LoRaWAN Stack Lockup

[Swap-File]

Description of defect

Under certain conditions the LoRaWAN stack can lock up. Specifically it appears to happen when when late (or close to late) acks are received and create interrupts near the dispatch of other events.

Target(s) affected by this defect ?

Specifically experienced under FF1705_L151CC & XDOT_L151CC, but likely all targets that use the LoRaWAN stack.

Toolchain(s) (name and version) displaying this defect ?

Online compiler (https://ide.mbed.com/compiler/)
mbed-cli's GCC

What version of Mbed-os are you using (tag or sha) ?

mbed 5.15.6 b114a9c
mbed 5.11

What version(s) of tools are you using. List all that apply (E.g. mbed-cli)

mbed-cli 1.8.3
Online compiler (https://ide.mbed.com/compiler/)

How is this defect reproduced ?

Take the mbed-os-example-lorawan program and import it into the online compiler, select mbedos 5.15.6 and add the default semtech drivers.:
https://os.mbed.com/teams/mbed-os-examples/code/mbed-os-example-lorawan/
https://github.com/ARMmbed/mbed-semtech-lora-rf-drivers

Change it to uplink in confirmed mode by replacing MSG_UNCONFIRMED_FLAG with MSG_CONFIRMED_FLAG

And replace ev_queue.dispatch_forever(); with:

while(1){
     ev_queue.dispatch(0);
}

Then let the device send uplinks in a high latency (late ack) network server environment.

Eventually (a few hours later) you will see this happen:

[27/01/21 - 08:16:35:456] [DBG ][LSTK]: Transmission completed
[27/01/21 - 08:16:35:471] [DBG ][LSTK]: Awaiting ACK
[27/01/21 - 08:16:36:456] [DBG ][LMAC]: RX1 slot open, Freq = 925700000
[27/01/21 - 08:16:36:471] ++ MbedOS Error Info ++
[27/01/21 - 08:16:36:471] Error Status: 0x80FF0144 Code: 324 Module: 255
[27/01/21 - 08:16:36:487] Error Message: Assertion failed: ret != 0
[27/01/21 - 08:16:36:503] Location: 0x801029B
[27/01/21 - 08:16:36:503] File: /extras/mbed-os.lib/features/lorawan/LoRaWANStack.cpp+531
[27/01/21 - 08:16:36:503] Error Value: 0x0
[27/01/21 - 08:16:36:503] Current Thread: LR-SX1272 Id: 0x20003658 Entry: 0x800A58D StackSize: 0x400 StackMem: 0x200038C8 SP: 0x
[27/01/21 - 08:16:36:518] 20003C0C 
[27/01/21 - 08:16:36:518] For more info, visit: https://mbed.com/s/error?error=0x80FF0144&tgt=XDOT_L151CC
[27/01/21 - 08:16:36:518] -- MbedOS Error Info --

Alternatively, take the mbed-os-example-lorawan program, change it to uplink in confirmed mode like above, and add the following code:

replace ev_queue.dispatch_forever(); with

ev_queue.call_every(20, led_blink_func);
ev_queue.dispatch_forever();

And add the code:

DigitalOut led1(GPIO0);
void led_blink_func(void){
     led1 = !led1;
}

Then let the device send uplinks in a high latency (late acks) network server environment. The same crash will happen.

It feels like something isn't quite interrupt safe, but I can't pinpoint it. Ideas?

[ciarmcom]

Thank you for raising this detailed GitHub issue. I am now notifying our internal issue triagers.
Internal Jira reference: https://jira.arm.com/browse/IOTOSM-3364

[0xc0170]

cc @ARMmbed/mbed-os-pan

[Swap-File]

So far I've traced this back to a problem in the event queue system.

In mbed 5.11, not having this commit causes additional problems, so let's ignore 5.11 and focus on 5.15.

In mbed 5.15 there appears to be a problem when dispatch fires an LoRaWAN event that then tries to cancel itself. Unfortunately, much of the LoRaWAN stack uses this pattern.

When dispatch returns it tries to deallocate the same event again, and sometimes the entire queue becomes corrupted, failing in a variety of ways.

I did a quick hack fix by saving the event id before dispatching and then not canceling events if the requested ID matches what is being dispatched. This appears to have fixed my stability problems, but there is probably a better way to fix it.

Anyone more familiar with the queue subsystem care to comment?

static int current_dispatch_id = 0;
bool equeue_cancel(equeue_t *q, int id)
{
    if (!id || current_dispatch_id == id) {
        return false;
    }

Inside of equeue_dispatch

...
            // actually dispatch the callbacks
            current_dispatch_id = equeue_event_id(q, e);
            void (*cb)(void *) = e->cb;
            if (cb) {
                cb(e + 1);
            }
            current_dispatch_id = 0;
...

[pan-]

Thanks for the details @Swap-File .

How did you came to the conclusion that the issue was in the cancel function of the event queue ? The first thing dispatch does is to dequeue the events that will be executed. Preventing an event being run to be dequeued should not have an effect.
Am I correct @geky ?
Obviously if it reproducible, something and sensitive to slight changes to the use of the event queue, the issue might be related to it.

According to the stack trace, it seems that the rx_interrupt_handler is not able to push a new event in the queue.

mbed-os/features/lorawan/LoRaWANStack.cpp

Lines 519 to 533 in b114a9c

	void LoRaWANStack::rx_interrupt_handler(const uint8_t *payload, uint16_t size,
	int16_t rssi, int8_t snr)
	{
	if (size > sizeof _rx_payload || core_util_atomic_flag_test_and_set(&_rx_payload_in_use)) {
	return;
	}
	memcpy(_rx_payload, payload, size);
	const uint8_t *ptr = _rx_payload;
	const int ret = _queue->call(this, &LoRaWANStack::process_reception,
	ptr, size, rssi, snr);
	MBED_ASSERT(ret != 0);
	(void)ret;
	}

If the controller generates events at a faster rate than the processing rate then it can saturate the event queue.
It would be interesting to add instrumentation to the code to count how many of these interrupts events are pending when the assert is triggered.
A static counter that is incremented after the assertion in LoRaWANStack::rx_interrupt_handler and decremented at the entry of LoRaWANStack::process_reception should be sufficient.

Have you tried to increase the event queue size ? Why do you replace dispatch_forever into a while(1) { dispatch(0); } ?

[Swap-File]

I believe the core problem is:

1. A function dispatched from the event queue cancels itself (the LoRa Stack does this a lot), calling equeue_dealloc()
2. Before that function returns, more changes are made to the event queue (either through interrupts or the function itself making more calls), and the same memory that was just freed up could be reused.
3. When execution returns to the event queue, equeue_dealloc() is called again. If memory was reused (or maybe it's an event queue ID collision?), this could remove a "new" event.

From what I can tell the queue running out of space is a symptom, I've also observed this pattern to cause events to get "unhooked" from the main event queue linked list, the behavior seems to change if you use GCC or the ARM compiler.

while(1) { dispatch(0); } is a fast way to demonstrate the problem since it makes it more likely for an interrupt to land in the critical "Bad" spot. Otherwise with dispatch_forever(); it is less likely to happen (unless you have more background event queue activity, like blinking a LED).

I observed this happening by altering the event queue to display a list of all events and IDs on every call, dispatch, and cancel.

[pan-]

There is no cancel possible in the code I pointed above and that causes the crash, the event id is not captured by the class and therefore the event can't be cancelled. There is only one event that the lora stack cancels:

mbed-os/features/lorawan/system/LoRaWANTimer.cpp

Lines 60 to 64 in b114a9c

	void LoRaWANTimeHandler::stop(timer_event_t &obj)
	{
	_queue->cancel(obj.timer_id);
	obj.timer_id = 0;
	}

It cancels the timer event but such processing is not present for events scheduled through the IRQs. They are never canceled.

That's why I'm surprised altering the code to cancel the event queue would have an effect.

From what I can tell the queue running out of space is a symptom, I've also observed this pattern to cause events to get "unhooked" from the main event queue linked list, the behavior seems to change if you use GCC or the ARM compiler.

What were the differences between GCC and ARM ?

I observed this happening by altering the event queue to display a list of all events and IDs on every call, dispatch, and cancel.

The strategy of displaying stats of the event queue at each call can be provoke more issues because traces takes a significant amount of time to be printed. Compared to posting an event it is several order of magnitude slower. When events are posted in IRQ this can have a significant impact on the system behaviour.

Thanks for completing the description, that is very useful. I will try to reproduce it with the dispatch(0).

[Swap-File]

I have only observed the problem in late ack, high retry environments. I generally would capture it happening once or twice per day, per device, when uplinking at a rate of once per minute. When it happens in my program I would see a WDT reset.

The fix I posted above has reduced this lockup rate to zero, across 17 devices for the last ~4 days.

Under GCC I generally see a stack lockup with no error, the stack would just never return from an event being canceled that shouldn't be canceled. Under the online ARM compiler I see the error posted above.

Here is what I believe the chain of events are, but I have seen it happen with both the opening of rx1, and rx2, and the ack timer:

Example:

1. open_rx2_window() fires from the event queue.
2. _lora_time.stop(_params.timers.rx_window2_timer); is called, calling equeue_dealloc().
3. Before the function open_rx2_window() completes, more changes are made to the event queue.
4. Execution returns to the event queue, and equeue_dealloc() is called again, and it has a chance of stopping something it shouldn't (or sometimes causing corruption / hanging events, I think it depends on the size of events being called).

[geky]

I've been pinged! Unfortunately it's been a while since I've looked at this code and I've become rusty, so I'm not sure how much my memory would help vs go the wrong direction.

I did a quick hack fix by saving the event id before dispatching and then not canceling events if the requested ID matches what is being dispatched. This appears to have fixed my stability problems, but there is probably a better way to fix it.

That's really strange. In theory that's precisely what this line does:

mbed-os/events/source/equeue.c

Line 334 in aa561ee

if (e->id != (unsigned)id >> q->npw2) {

Unless the id in the event is getting overwritten by a buffer overflow?

[Swap-File]

Could be, I am not familiar with the inner workings of the event queue system, only that I observed the problem in "mbed-os-example-lorawan" (as well as in my own application), that I only see it under ack loss & retry conditions, that the issue was coming from the event queue not behaving as it should, and preventing duplicate cancels fixed it.

Here is an additional serial port log, from my local copy of mbed-os with additional debug statements in the LoRa stack and event queue (GCC compiled).

It shows how many outstanding events there are by walking the queue's linked list and counting how many items are in it ( "Outstanding Events X") and printing it whenever it changes. It prints "dispatch event call complete" each time a single event firing is complete.

It also shows the queue ID and time left for RX1, RX2, and the ACK timer.

Confirmed uplink is in progress, we are about to open the RX2 window:

[03/02/21 - 00:54:03:727] Outstanding Events 2
[03/02/21 - 00:54:03:852] IDs 0 59392 88284 timeleft  0 855 3764
[03/02/21 - 00:54:03:852] IDs 0 59392 88284 timeleft  0 852 3761
[03/02/21 - 00:54:04:055] IDs 0 59392 88284 timeleft  0 648 3557
[03/02/21 - 00:54:04:070] IDs 0 59392 88284 timeleft  0 645 3554
[03/02/21 - 00:54:04:273] IDs 0 59392 88284 timeleft  0 441 3350
[03/02/21 - 00:54:04:273] IDs 0 59392 88284 timeleft  0 438 3347
[03/02/21 - 00:54:04:477] IDs 0 59392 88284 timeleft  0 234 3143
[03/02/21 - 00:54:04:477] IDs 0 59392 88284 timeleft  0 230 3139
[03/02/21 - 00:54:04:680] IDs 0 59392 88284 timeleft  0 26 2935
[03/02/21 - 00:54:04:695] IDs 0 59392 88284 timeleft  0 23 2932
[03/02/21 - 00:54:04:711] [WARN][LMAC]: open_rx2_window
[03/02/21 - 00:54:04:727] LoRaWANtimeleftHandler stopped 59392
[03/02/21 - 00:54:04:727] [DBG ][LMAC]: RX2 slot open, Freq = 923300000
[03/02/21 - 00:54:04:727] dispatch event call complete
[03/02/21 - 00:54:04:727] Outstanding Events 0

Where did the ack timer (88284) go?  We should not have zero outstanding events here.
We had 2 events in the queue before this, and "dispatch event call complete" only happened once.

[03/02/21 - 00:54:04:773] [WARN][LSTK]: rx_t  <- RX Timeout interrupt
[03/02/21 - 00:54:04:773] Outstanding Events 1
[03/02/21 - 00:54:04:773] [WARN][LSTK]: continue_sending
[03/02/21 - 00:54:04:773] dispatch event call complete
[03/02/21 - 00:54:04:773] Outstanding Events 0
[03/02/21 - 00:54:04:883] IDs 0 0 88284 timeleft  0 0 2728

Ack timer still shows up if we know the ID, but it's no longer in the queue's linked list, so it never gets dispatched.

[03/02/21 - 00:54:04:898] IDs 0 0 88284 timeleft  0 0 2726
[03/02/21 - 00:54:05:102] IDs 0 0 88284 timeleft  0 0 2522
[03/02/21 - 00:54:05:102] IDs 0 0 88284 timeleft  0 0 2520
[03/02/21 - 00:54:05:305] IDs 0 0 88284 timeleft  0 0 2316
[03/02/21 - 00:54:05:305] IDs 0 0 88284 timeleft  0 0 2313
[03/02/21 - 00:54:05:508] IDs 0 0 88284 timeleft  0 0 2110
[03/02/21 - 00:54:05:508] IDs 0 0 88284 timeleft  0 0 2107
[03/02/21 - 00:54:05:711] IDs 0 0 88284 timeleft  0 0 1904
[03/02/21 - 00:54:05:727] IDs 0 0 88284 timeleft  0 0 1901
[03/02/21 - 00:54:05:914] IDs 0 0 88284 timeleft  0 0 1697
[03/02/21 - 00:54:05:930] IDs 0 0 88284 timeleft  0 0 1695
[03/02/21 - 00:54:06:133] IDs 0 0 88284 timeleft  0 0 1491
[03/02/21 - 00:54:06:133] IDs 0 0 88284 timeleft  0 0 1489
[03/02/21 - 00:54:06:336] IDs 0 0 88284 timeleft  0 0 1285
[03/02/21 - 00:54:06:336] IDs 0 0 88284 timeleft  0 0 1283
[03/02/21 - 00:54:06:539] IDs 0 0 88284 timeleft  0 0 1079
[03/02/21 - 00:54:06:539] IDs 0 0 88284 timeleft  0 0 1076
[03/02/21 - 00:54:06:742] IDs 0 0 88284 timeleft  0 0 873
[03/02/21 - 00:54:06:742] IDs 0 0 88284 timeleft  0 0 870
[03/02/21 - 00:54:06:945] IDs 0 0 88284 timeleft  0 0 667
[03/02/21 - 00:54:06:961] IDs 0 0 88284 timeleft  0 0 664
[03/02/21 - 00:54:07:164] IDs 0 0 88284 timeleft  0 0 461
[03/02/21 - 00:54:07:164] IDs 0 0 88284 timeleft  0 0 458
[03/02/21 - 00:54:07:367] IDs 0 0 88284 timeleft  0 0 255
[03/02/21 - 00:54:07:367] IDs 0 0 88284 timeleft  0 0 252
[03/02/21 - 00:54:07:570] IDs 0 0 88284 timeleft  0 0 49
[03/02/21 - 00:54:07:570] IDs 0 0 88284 timeleft  0 0 46
[03/02/21 - 00:54:07:773] IDs 0 0 88284 timeleft  0 0 0
[03/02/21 - 00:54:07:773] IDs 0 0 88284 timeleft  0 0 0
[03/02/21 - 00:54:07:977] IDs 0 0 88284 timeleft  0 0 0

Stack is now locked up.

[Swap-File]

I set aside a few boards, added more debug messages, and let a test run overnight. Here are the results:

Under normal operation, when rx1 or rx2 calls stop/cancel on itself, equeue_cancel takes no action.

This time, when rx2 called stop/cancel on itself, equeue_cancel did try to cancel something, and succeeded, breaking the stack.

Transmission complete, counting down to open RX1:

[10/02/21 - 15:37:32:623] [DBG ][LSTK]: Transmission completed
[10/02/21 - 15:37:32:655] IDs 75776 61544 37084 time  969 1993 4245
[10/02/21 - 15:37:32:655] called 67636
[10/02/21 - 15:37:32:655] in equeue_dispatch before calling equeue_incid
[10/02/21 - 15:37:32:655] Outstanding Events 3
[10/02/21 - 15:37:32:655] in equeue_dispatch before calling equeue_dealloc
[10/02/21 - 15:37:32:655] in equeue_dispatch after calling equeue_dealloc
[10/02/21 - 15:37:32:780] IDs 75776 61544 37084 time  835 1859 4111
[10/02/21 - 15:37:32:780] IDs 75776 61544 37084 time  831 1855 4107
[10/02/21 - 15:37:32:998] IDs 75776 61544 37084 time  622 1646 3898
[10/02/21 - 15:37:32:998] IDs 75776 61544 37084 time  618 1642 3894
[10/02/21 - 15:37:33:202] IDs 75776 61544 37084 time  413 1437 3689
[10/02/21 - 15:37:33:202] IDs 75776 61544 37084 time  410 1434 3686
[10/02/21 - 15:37:33:405] IDs 75776 61544 37084 time  205 1229 3481
[10/02/21 - 15:37:33:420] IDs 75776 61544 37084 time  201 1225 3477

RX1 Opening:

[10/02/21 - 15:37:33:623] [WARN][LMAC]: open_rx1_window
[10/02/21 - 15:37:33:623] equeue_cancel called while dispatching 75776
[10/02/21 - 15:37:33:623] equeue_cancel taking no action
[10/02/21 - 15:37:33:623] Outstanding Events 2
[10/02/21 - 15:37:33:623] LoRaWANTimeHandler stopped 75776
[10/02/21 - 15:37:33:639] [DBG ][LMAC]: RX1 slot open, Freq = 926900000
[10/02/21 - 15:37:33:639] equeue_dispatch fired 75776
[10/02/21 - 15:37:33:639] in equeue_dispatch before calling equeue_incid
[10/02/21 - 15:37:33:639] in equeue_dispatch before calling equeue_dealloc
[10/02/21 - 15:37:33:639] in equeue_dispatch after calling equeue_dealloc
[10/02/21 - 15:37:33:655] IDs 0 61544 37084 time  0 1002 3254
[10/02/21 - 15:37:33:655] IDs 0 61544 37084 time  0 999 3251

RX Timeout Interrupt:

[10/02/21 - 15:37:33:670] [WARN][LSTK]: rx_t
[10/02/21 - 15:37:33:670] Outstanding Events 3
[10/02/21 - 15:37:33:670] equeue_dispatch fired 77824
[10/02/21 - 15:37:33:670] in equeue_dispatch before calling equeue_incid
[10/02/21 - 15:37:33:670] Outstanding Events 2
[10/02/21 - 15:37:33:670] in equeue_dispatch before calling equeue_dealloc
[10/02/21 - 15:37:33:686] in equeue_dispatch after calling equeue_dealloc
[10/02/21 - 15:37:33:842] IDs 0 61544 37084 time  0 790 3042
[10/02/21 - 15:37:33:858] IDs 0 61544 37084 time  0 787 3039
[10/02/21 - 15:37:34:061] IDs 0 61544 37084 time  0 578 2830
[10/02/21 - 15:37:34:061] IDs 0 61544 37084 time  0 575 2827
[10/02/21 - 15:37:34:264] IDs 0 61544 37084 time  0 371 2623
[10/02/21 - 15:37:34:264] IDs 0 61544 37084 time  0 368 2620
[10/02/21 - 15:37:34:467] IDs 0 61544 37084 time  0 164 2416
[10/02/21 - 15:37:34:483] IDs 0 61544 37084 time  0 161 2413

RX2 Opening:

[10/02/21 - 15:37:34:639] [WARN][LMAC]: open_rx2_window
[10/02/21 - 15:37:34:655] equeue_cancel called while dispatching 61544
[10/02/21 - 15:37:34:655] in equeue_cancel before calling equeue_dealloc
[10/02/21 - 15:37:34:655] Outstanding Events 0
[10/02/21 - 15:37:34:655] in equeue_cancel after calling equeue_dealloc
[10/02/21 - 15:37:34:655] LoRaWANTimeHandler stopped 61544

Outstanding Events 0 should not be zero here.

[10/02/21 - 15:37:34:655] [DBG ][LMAC]: RX2 slot open, Freq = 923300000
[10/02/21 - 15:37:34:670] equeue_dispatch fired 61544
[10/02/21 - 15:37:34:670] in equeue_dispatch before calling equeue_incid
[10/02/21 - 15:37:34:686] in equeue_dispatch before calling equeue_dealloc
[10/02/21 - 15:37:34:686] in equeue_dispatch after calling equeue_dealloc
[10/02/21 - 15:37:34:686] IDs 0 0 37084 time  0 0 2209
[10/02/21 - 15:37:34:686] IDs 0 0 37084 time  0 0 2206
[10/02/21 - 15:37:34:701] [WARN][LSTK]: rx_t  <- RX Timeout interrupt
[10/02/21 - 15:37:34:701] Outstanding Events 1
[10/02/21 - 15:37:34:701] [WARN][LSTK]: continue_sending
[10/02/21 - 15:37:34:701] equeue_dispatch fired 65640
[10/02/21 - 15:37:34:701] in equeue_dispatch before calling equeue_incid
[10/02/21 - 15:37:34:717] Outstanding Events 0
[10/02/21 - 15:37:34:717] in equeue_dispatch before calling equeue_dealloc
[10/02/21 - 15:37:34:717] in equeue_dispatch after calling equeue_dealloc


Ack timer still shows up if we know the ID (37084), but it's no longer in the queue's linked list, so it never gets dispatched.


[10/02/21 - 15:37:34:889] IDs 0 0 37084 time  0 0 1998
[10/02/21 - 15:37:34:889] IDs 0 0 37084 time  0 0 1995
[10/02/21 - 15:37:35:092] IDs 0 0 37084 time  0 0 1787
[10/02/21 - 15:37:35:108] IDs 0 0 37084 time  0 0 1785
[10/02/21 - 15:37:35:311] IDs 0 0 37084 time  0 0 1581
[10/02/21 - 15:37:35:311] IDs 0 0 37084 time  0 0 1579
[10/02/21 - 15:37:35:514] IDs 0 0 37084 time  0 0 1375
[10/02/21 - 15:37:35:514] IDs 0 0 37084 time  0 0 1372
[10/02/21 - 15:37:35:717] IDs 0 0 37084 time  0 0 1169
[10/02/21 - 15:37:35:717] IDs 0 0 37084 time  0 0 1166
[10/02/21 - 15:37:35:920] IDs 0 0 37084 time  0 0 963
[10/02/21 - 15:37:35:920] IDs 0 0 37084 time  0 0 960
[10/02/21 - 15:37:36:123] IDs 0 0 37084 time  0 0 757
[10/02/21 - 15:37:36:139] IDs 0 0 37084 time  0 0 754
[10/02/21 - 15:37:36:342] IDs 0 0 37084 time  0 0 551
[10/02/21 - 15:37:36:342] IDs 0 0 37084 time  0 0 548
[10/02/21 - 15:37:36:545] IDs 0 0 37084 time  0 0 345
[10/02/21 - 15:37:36:545] IDs 0 0 37084 time  0 0 342
[10/02/21 - 15:37:36:748] IDs 0 0 37084 time  0 0 139
[10/02/21 - 15:37:36:748] IDs 0 0 37084 time  0 0 136
[10/02/21 - 15:37:36:951] IDs 0 0 37084 time  0 0 0
[10/02/21 - 15:37:36:951] IDs 0 0 37084 time  0 0 0
[10/02/21 - 15:37:37:154] IDs 0 0 37084 time  0 0 0


Stack is now locked up.

[Swap-File]

Here's a capture from last night's logging, due to the limited bandwidth of serial logging I reduced what is logged.

I set it up to print out the memory addresses as it went, Looks like both dispatch and cancel are equeue_dealloc()ing the same event (same memory address and same id).

Would this point to equeue_dequeue in dispatch not correctly dequeue-ing the event, therefore allowing the dequeue to happen again inside of cancel, and both deallocations to happen, breaking the ack timer event?

Formatting of the debug string is: printf("id:%d e:%u npw2:%u \n",id,e,((unsigned)lookup_id >> q->npw2));

[11/02/21 - 21:13:31:879] [DBG ][LSTK]: Transmission completed

RX1: ID: 364596 Timeleft: 986
RX2: ID: 372736 Timeleft: 2009
ACK: ID: 53468 Timeleft: 5038

[11/02/21 - 21:13:31:879] dispatch unqueued id:372840 e:536883872 npw2:182 

RX1 Opening (start of 364596):

Data from inside of Cancel:
[11/02/21 - 21:13:32:864] id:364596 e:536883820 npw2:178 
[11/02/21 - 21:13:32:864] cancel unqueued nothing

[11/02/21 - 21:13:32:879] [DBG ][LMAC]: RX1 slot open, Freq = 926900000
[11/02/21 - 21:13:32:879] dispatch complete id:364596 e:536883820 npw2:178   <- inside of dispatch, before equeue_dealloc


RX Timeout Interrupt:
[11/02/21 - 21:13:32:879] dispatch complete id:22684 e:536883924 npw2:11    <- inside of dispatch, before equeue_dealloc

RX2 Opening (start of 372736):

Data from inside of Cancel
[11/02/21 - 21:13:33:879] id:372736 e:536883768 npw2:182 
[11/02/21 - 21:13:33:895] cancel unqueued id:372736 e:536883768 npw2:182  <- This is incorrect

[11/02/21 - 21:13:33:895] [DBG ][LMAC]: RX2 slot open, Freq = 923300000
[11/02/21 - 21:13:33:910] dispatch complete id:372736 e:536883768 npw2:182    <- inside of dispatch, before equeue_dealloc

RX Timeout Interrupt:
[11/02/21 - 21:13:33:942] dispatch complete id:24732 e:536883924 npw2:12    <- inside of dispatch, before equeue_dealloc

Stack is locked up.

Note: The batch of devices with the quick fix I posted above continue to work with zero stack lockups / WDT resets since implementation.