LoRaWAN: Incorrect Handling of Repeated Calls of 'send' and 'cancel_sending'

[mattbrown015]

Description

We managed to generate the following assertion from the LoRaWAN stack:

mbed assertation failed: obj.timer_id != 0, file: .\mbed-os\features\lorawan\system\LoRaWANTimer.cpp, line 57þ

We use a sensor to trigger samples and a small problem with a sensor resulted in many events occurring in quick succession. While I appreciate we probably should guard against this in our app I feel the LoRaWAN stack should have handled it better.

We call LoRaWANInterface::send at regular intervals or after an event. Most of the time the interval or events should be easily handled by LoRaWAN and just sent.

We've tried to anticipate what might happen if LoRaWANInterface::send is called while the previous sample is still being sent and we may call LoRaWANInterface::cancel_sending if LoRaWANInterface::send returns LORAWAN_STATUS_WOULD_BLOCK. In other words, attempt to cancel the previous sample so that the latest can be sent.

My feeling is that LoRaWANInterface::send and LoRaWANInterface::cancel_sending is not robust in the face of all possible situations. I think perhaps calling LoRaWANInterface::cancel_sending at just the wrong time allows another TX to be scheduled while waiting for the receive window to expire.

I believe the following debug shows shows something incorrect happening i.e. multiple Opening RX1 Window:

[2018-10-01 09:27:57.718] [INFO][LMAC]: RTS = 10 bytes, PEND = 0, Port: 15
[2018-10-01 09:27:57.718] [DBG ][LMAC]: Frame prepared to send at port 15
[2018-10-01 09:27:57.718] [DBG ][LMAC]: TX: Channel=1, TX DR=5, RX1 DR=5
[2018-10-01 09:27:57.718] [DBG ][asrv]: immediate send
[2018-10-01 09:27:57.718] [WARN][asrv]: LoRaWANInterface::send returned LORAWAN_STATUS_WOULD_BLOCK
[2018-10-01 09:27:57.718] [DBG ][asrv]: try to cancel message
[2018-10-01 09:27:57.718] [INFO][LMAC]: RTS = 10 bytes, PEND = 0, Port: 15
[2018-10-01 09:27:57.718] [DBG ][LMAC]: Frame prepared to send at port 15
[2018-10-01 09:27:57.718] [DBG ][LMAC]: TX: Channel=6, TX DR=5, RX1 DR=5
[2018-10-01 09:27:57.742] [DBG ][asrv]: immediate send
[2018-10-01 09:27:57.742] [WARN][asrv]: LoRaWANInterface::send returned LORAWAN_STATUS_WOULD_BLOCK
[2018-10-01 09:27:57.742] [DBG ][asrv]: try to cancel message
[2018-10-01 09:27:57.742] [INFO][LMAC]: RTS = 10 bytes, PEND = 0, Port: 15
[2018-10-01 09:27:57.742] [DBG ][LMAC]: Frame prepared to send at port 15
[2018-10-01 09:27:57.742] [DBG ][LMAC]: TX: Channel=3, TX DR=5, RX1 DR=5
[2018-10-01 09:27:57.742] [DBG ][asrv]: immediate send
[2018-10-01 09:27:57.742] [WARN][asrv]: LoRaWANInterface::send returned LORAWAN_STATUS_WOULD_BLOCK
[2018-10-01 09:27:57.742] [DBG ][asrv]: try to cancel message
[2018-10-01 09:27:57.742] [INFO][LMAC]: RTS = 10 bytes, PEND = 0, Port: 15
[2018-10-01 09:27:57.742] [DBG ][LMAC]: Frame prepared to send at port 15
[2018-10-01 09:27:57.742] [DBG ][LMAC]: TX: Channel=7, TX DR=5, RX1 DR=5
[2018-10-01 09:27:57.742] [DBG ][asrv]: immediate send
[2018-10-01 09:27:57.742] [WARN][asrv]: LoRaWANInterface::send returned LORAWAN_STATUS_WOULD_BLOCK
[2018-10-01 09:27:57.754] [DBG ][asrv]: try to cancel message
[2018-10-01 09:27:57.754] [INFO][LMAC]: RTS = 10 bytes, PEND = 0, Port: 15
[2018-10-01 09:27:57.754] [DBG ][LMAC]: Frame prepared to send at port 15
[2018-10-01 09:27:57.754] [DBG ][LMAC]: TX: Channel=3, TX DR=5, RX1 DR=5
[2018-10-01 09:27:57.754] [DBG ][asrv]: immediate send
[2018-10-01 09:27:57.754] [DBG ][LSTK]: Transmission completed
[2018-10-01 09:27:57.754] [DBG ][LSTK]: Transmission completed
[2018-10-01 09:27:57.754] [DBG ][LSTK]: Transmission completed
[2018-10-01 09:27:58.636] [DBG ][LMAC]: Opening RX1 Window
[2018-10-01 09:27:58.650] [DBG ][LMAC]: Opening RX1 Window
[2018-10-01 09:27:59.637] [DBG ][LMAC]: Opening RX2 Window, Frequency = 869525000
[2018-10-01 09:27:59.663] [DBG ][LMAC]: Opening RX2 Window, Frequency = 869525000

I think the problem might be in LoRaWANStack::stop_sending and LoRaMac::clear_tx_pipe. LoRaMac::clear_tx_pipe will return LORAWAN_STATUS_OK if there is no message queued but I think it can also return LORAWAN_STATUS_OK if we're waiting for the RX windows to expire.

SHA 37654e5
cc @hasnainvirk

Issue request type

[ ] Question
[ ] Enhancement
[X] Bug

[hasnainvirk]

@mattbrown015 Let me have a look at it. I will try to reproduce it and get back at you.
[Mirrored to Jira]

[hasnainvirk]

@mattbrown015 Meanwhile, could you please rebase your work with this on top #8183 ? I am not entirely positive that it would solve your issue, but this does try to eliminate a few inconsistencies. Please let me know if you can still reproduce the issue.
[Mirrored to Jira]

[mattbrown015]

I've just updated to the latest master but it didn't help.

To reproduce the problem I created a loop around our normal 'send' code which I believe means I'm effectively doing this:

for (int debug_loop = 0; debug_loop < 4; ++debug_loop) {
    int16_t bytes_sent = lorawan.send(MBED_CONF_LORA_APP_PORT, buf, buf_len, MSG_UNCONFIRMED_FLAG);
    if (bytes_sent >= LORAWAN_STATUS_WOULD_BLOCK) {
         lorawan.cancel_sending();
    }
 }

Making the loop repeat 32 times causes the assert because 32 is the size of the event queue.
[Mirrored to Jira]

[hasnainvirk]

@mattbrown015 I am unable to reproduce the issue. Please note that I am using Mbed OS master with #8183 on top of it. Here is the output with the loop you mentioned in the previous comment :

[DBG ][LSTK]: Initializing MAC layer

 Mbed LoRaWANStack initialized 

 CONFIRMED message retries : 3 

 Adaptive data  rate (ADR) - Enabled 
[DBG ][LSTK]: Initiating OTAA
[DBG ][LSTK]: Sending Join Request ...
[DBG ][LMAC]: Frame prepared to send at port 0
[DBG ][LMAC]: TX: Channel=0, TX DR=5, RX1 DR=5

 Connection - In Progress ...
[DBG ][LSTK]: Transmission completed
[DBG ][LMAC]: RX1 slot open, Freq = 868100000
[DBG ][LSTK]: OTAA Connection OK!

 Connection - Successful 

 Dummy Sensor Value = 2.1 
[INFO][LMAC]: RTS = 25 bytes, PEND = 0, Port: 15
[DBG ][LMAC]: Frame prepared to send at port 15
[DBG ][LMAC]: TX: Channel=6, TX DR=5, RX1 DR=5
[INFO][LMAC]: RTS = 25 bytes, PEND = 0, Port: 15
[DBG ][LMAC]: Frame prepared to send at port 15
[DBG ][LMAC]: TX: Channel=6, TX DR=5, RX1 DR=5
[INFO][LMAC]: RTS = 25 bytes, PEND = 0, Port: 15
[DBG ][LMAC]: Frame prepared to send at port 15
[DBG ][LMAC]: TX: Channel=3, TX DR=5, RX1 DR=5
[INFO][LMAC]: RTS = 25 bytes, PEND = 0, Port: 15
[DBG ][LMAC]: Frame prepared to send at port 15
[DBG ][LMAC]: TX: Channel=6, TX DR=5, RX1 DR=5

 0 bytes scheduled for transmission 

[Mirrored to Jira]

[hasnainvirk]

@mattbrown015 One more thing, your loop actually spins and blocks your main thread. Please note:

Lock lock(*this)

in LoRaWANInterface class. All the user facing APIs are scope locked. The fact that our stack and application run in the same thread gives us great flexibility and minimal footprint in terms of RAM but it does have some inherent limitations. Nothing should sit around and keep the thread occupied. This is the ideal situation. If you need more advanced handling, I would request you to rethink your app-design and may be have a separate Queue specific to your application. Please contact me on Skype if you need more information. You are partially correct about an ambiguous return code in the clear_tx_pipe() and I am looking at it as we speak.
[Mirrored to Jira]

[mattbrown015]

Hi @hasnainvirk,

The real app doesn't loop like my example and the example is simplified in comparison to what I actually did. The real app uses a InterruptIn which offloads to an event queue before eventually ending up in the layer that calls LoRaWANInterface::send. I started looking at this when we accidentally fired the InterruptIn too much.

I think what I'm describing is heavily timing dependant, I think it could be important to attempt the cancel while the RX window timers are running.

I could also easily believe there's a thread race. I did think about adding some critical sections!!

I shall try and think of another example.

But, don't you think LoRaMac::clear_tx_pipe looks odd? It checks the backoff timer but there's a long time between the expiry of the backoff timer and the closing of RX window 2. AFAICT, LoRaWANStack::stop_sending will mark the TX as no longer on going while the RX window timers are running.
[Mirrored to Jira]

[hasnainvirk]

@mattbrown015 If the id of the back_off timer is zero, it means transmission may have already taken place or there was nothing in the queue to start with. Here the error code was ambiguous which you rightly pointed out. I changed the return code from LORAWAN_STATUS_OK to LORAWAN_STATUS_NO_OP. This would stop it from marking the ongoing_tx as false. No-op would mean I can't complete operation at the moment. But, if you start retrying at that moment, you would block the thread and that will definitely meddle the state machine. Let me have a closer look and I will update you soon.
[Mirrored to Jira]

[mattbrown015]

@hasnainvirk Ah, sorry, I've just realised that #8183 hasn't been merged yet; I wasn't paying attention yesterday! I'll try and have another look at this today but I'm pretty sure you and me are in the same boat as regards having a number of issues to work on all at the same time! Thanks. :-)
[Mirrored to Jira]

[hasnainvirk]

:) @mattbrown015 It's my pleasure fixing issues with you :)
[Mirrored to Jira]

[hasnainvirk]

@mattbrown015 Could you please try this out #8299 ?
[Mirrored to Jira]