[LoRaWAN] timer & callbacks issues

[quentin-ol]

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:

  1. First I applied the fix described in #96, allowing to force the LoRaWAN stack to use SF12.
  2. 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.

[quentin-ol]

Extra info: Those behaviours appeared with version 1.10.0b1

[quentin-ol]

@danicampora Any idea ? Btw, is there any documentation on how to attach a debugger to the PyCom, that would help immensely.

[quentin-ol]

Well, reverting to 1.9.2.b2, the code above works flawlessly.

Something fishy happened in the commit 54e3269474bd0952a5137a79ec27056460c455b2

Without help, nor any documentation on how to attach a debugger to the LoPy, I'm stuck with debugging with printf which, I'm sure, is one way to create weird timing issues...

I'd appreciated if the PyCom staff could dedicate a bit more time to answering/helping on issues posted here. Right now, this place feels like a desert.

BTW, don't get my wrong, I'm not expecting every issue to be answered/solved by PyCom and I'd be more than happy to help/contribute. Just give me a nudge into the right direction, tell me where to look at.

[jmarcelino]

Hi @quentin-ol sorry you felt your questions aren't being answered, we do see all these issues and when possible aim to offer a fast reply however please understand your question is quite complex and - as you found- it is to do with the recently released firmware we're currently reviewing.

Also at the moment - for a number of reasons - there is a reliable way to use a JTAG debugger to debug the MicroPython stack, that is something still being worked on and when available it'll be documented.

[quentin-ol]

@jmarcelino you make me happy. This, an honest answer, is all I was looking for. Even if it doesn't solve the issue.

As said above, I'd be happy to help. Don't hesitate to ping me if there is anything I can help you with.