[LoRaWAN] timer & callbacks issues #97
Description
Please include the following information when submitting a bug report:
- board/firmware version:
(sysname='LoPy', nodename='LoPy', release='1.10.1.b1', version='d8e32ac-dirty on 2017-11-16', machine='LoPy with ESP32', lorawan='1.0.0')
note: I applied the fix described in #96.
-
Exact steps to cause this issue:
- First I applied the fix described in [LoRaWAN] Error in LoRaMacChannelManualAdd #96, allowing to force the LoRaWAN stack to use SF12.
- Then, I ran this program:
from machine import Timer
from network import LoRa
from socket import socket, AF_LORA, SOCK_RAW, SOL_LORA, SO_CONFIRMED, SO_DR
from time import sleep, ticks_ms, ticks_diff
from sys import exit
from binascii import unhexlify, hexlify
from json import load
class OTAAEndDevice(object):
TX_PENDING = 0x000
TX_FAIL = 0x100
TX_OK = 0x001
RX_OK = 0x010
ACTION_NONE = 0x00
ACTION_UPLINK = 0x01
def __init__(self, dev_eui, app_eui, app_key, uplink_period):
self.dev_eui = dev_eui
self.app_eui = app_eui
self.app_key = app_key
self.uplink_period = uplink_period
self.mac = LoRa()
self.mac.init(mode=LoRa.LORAWAN, device_class=LoRa.CLASS_A, adr=False, tx_retries=0)
self.mac.add_channel(index=0, frequency=868100000, dr_min=0, dr_max=0)
self.mac.add_channel(index=1, frequency=868100000, dr_min=0, dr_max=0)
self.mac.add_channel(index=2, frequency=868100000, dr_min=0, dr_max=0)
self.mac.remove_channel(3)
self.mac.remove_channel(4)
self.mac.remove_channel(5)
self.mac.remove_channel(6)
self.mac.remove_channel(7)
self.mac.sf(12)
self.socket = socket(AF_LORA, SOCK_RAW)
self.socket.setsockopt(SOL_LORA, SO_CONFIRMED, True)
self.socket.setsockopt(SOL_LORA, SO_DR, 0)
self.socket.setblocking(False)
self.mac.callback(
trigger=LoRa.RX_PACKET_EVENT | LoRa.TX_PACKET_EVENT | LoRa.TX_FAILED_EVENT,
handler=self.event_handler
)
self.port = None
self.payload = None
self.uplink_timer = None
self.ticks_uplink = None
self.ticks_timer = None
self.status = None
self.pending = False
self.action = OTAAEndDevice.ACTION_NONE
def event_handler(self, mac):
print('event_handler called')
self.pending = False
events = mac.events()
if events & LoRa.RX_PACKET_EVENT:
(payload, port) = self.socket.recvfrom(256)
self.port = port
self.payload = payload
self.status |= OTAAEndDevice.RX_OK
print('rx ok')
if events & LoRa.TX_PACKET_EVENT:
self.status |= OTAAEndDevice.TX_OK
print('tx ok')
if events & LoRa.TX_FAILED_EVENT:
self.status |= OTAAEndDevice.TX_FAIL
print('tx fail')
def trigger_uplink(self, _):
print('timer: {0}ms elapsed'.format(ticks_diff(self.ticks_timer, ticks_ms())))
self.action = OTAAEndDevice.ACTION_UPLINK
self.ticks_timer = ticks_ms()
def join(self):
self.mac.join(
activation=LoRa.OTAA,
auth=(self.dev_eui, self.app_eui, self.app_key),
timeout=0
)
while not self.mac.has_joined():
sleep(1)
def uplink(self):
self.pending = True
self.status = OTAAEndDevice.TX_PENDING
self.ticks_uplink = ticks_ms()
self.socket.send('long dummy payload that fits in 40 bytes')
while(self.pending):
sleep(1)
print('...')
if self.status & OTAAEndDevice.TX_OK:
print('tx ok')
if self.status & OTAAEndDevice.RX_OK:
print('rx downlink: {0} on port {1}'.format(hexlify(self.payload, ':'), self.port ))
if self.status & OTAAEndDevice.TX_FAIL:
print('tx failed')
print('uplink: {0}ms elapsed'.format(ticks_diff(self.ticks_uplink, ticks_ms())))
self.action = OTAAEndDevice.ACTION_NONE
def run(self):
print('joining')
self.join()
print('joined')
self.uplink_timer = Timer.Alarm(self.trigger_uplink, self.uplink_period, periodic=True)
self.ticks_timer = ticks_ms()
try:
while True:
if self.action is OTAAEndDevice.ACTION_UPLINK:
print('uplink')
self.uplink()
print('uplink done, status: {0}'.format(self.status))
else:
pass
except KeyboardInterrupt:
print('action: {0}'.format(self.action))
print('pending: {0}'.format(self.pending))
print('status: {0}'.format(self.status))
exit()
def main():
dev_eui = unhexlify("<dev_eui>".replace(':', ''))
app_eui = unhexlify("<app_eui>".replace(':', ''))
app_key = unhexlify("<app_key>".replace(':', ''))
uplink_period = 20
otaa_device = OTAAEndDevice(dev_eui, app_eui, app_key, uplink_period)
otaa_device.run()
main()
- what's happening:
After several (read lost of) trials, I've identified two types of behaviours:
behaviour 1:
joining
joined
timer: 20000ms elapsed
uplink
event_handler called
tx fail
...
tx failed
uplink: 1000ms elapsed
uplink done, status: 256
timer: 19999ms elapsed
uplink
event_handler called
tx fail
...
tx failed
uplink: 1000ms elapsed
uplink done, status: 256
timer: 19999ms elapsed
uplink
event_handler called
tx fail
...
tx failed
uplink: 1000ms elapsed
uplink done, status: 256
behaviour 2:
joining
joined
timer: 20001ms elapsed
uplink
timer: 19999ms elapsed
timer: 19999ms elapsed
timer: 19999ms elapsed
timer: 19999ms elapsed
timer: 19999ms elapsed
timer: 19999ms elapsed
timer: 19999ms elapsed
timer: 19999ms elapsed
In the first case (behaviour 1), the timer is called in time (20 000ms after its initialisation). The execution goes through all the steps I'm expecting BUT the time it spent in the uplink function means there is something very bad happening: 1s is not enough for a 40-bytes payload to be sent using SF12 + 2 RX windows. I strongly suspect that this 1s is the time the code spent sleeping ( which is set to 1s).
In the second case (behaviour 2), the timer is called late (20 0001ms after its initialisation). The execution is stuck in the while loop (print), and event_handler is never called.
Both cases strongly hints toward a bad port of the timer librairie used in LoRaMac.
I will investigate this further.