How are NewChannelReq handled

[Thomas Schaefer]

Hi all!
Today I tried to join via OTAA with a LoPy1 to a LoRaWAN-Network here in my local area.
At the first moment, everything looks fine. The Lopy sends the JoinRequest and gets his JoinAccept. But afterwards not only one packet reached my dashboard. Despite this, a ReJoin worked well.
After some investigations, I found that the provider uses a different frequency plan. Different in terms of "Not the TTN plan".
So I observed the frequencies used after the join, and the LoPy does not use the frequencies from the providers frequency plan.
After I realized the problem, I set the channel frequencies manually, and everything work like a charm.
So far, so good. But this is not the way, the things should be done, isn't it?

How can I manage this problem?

Cheers,
Thomas

[Gijs]

Let us know. Im not familiar with the NewChannelReq and how it works, but I've been diving deep in the Loramac stack for the adaptive datarate over the past few days, so i'll take a look here as well.

[Thomas Schaefer]

Hi!
So, takes a while, to collect all the information.
I'm running the latest firmware:

(sysname='LoPy', nodename='LoPy', release='1.20.2.r4', version='v1.11-ffb0e1c on 2021-01-12', machine='LoPy with ESP32', lorawan='1.0.2', pybytes='1.6.1')

Intentionally I only use light sleep (machine.sleep()) between the tasks, but I save LoRaWAN state to nvram after every LoRaWAN action.
Unfortunately I have no access to the LNS but I asked to get the logs.

While I'm investigating, I found something weird. I had some Guru Meditation Errors, after sending the Lopy to light sleep, but clearly before it comes back to normal operation:

2782286522: INFO - >>>>>>Packed Sensor Data (14 Bytes) send at 2021-02-15 14:17:02
2782286535: DEBUG - Next transmission in 270 seconds
2782286545: DEBUG - Go to light sleep for 30 Seconds
Guru Meditation Error: Core  0 panic'ed (StoreProhibited). Exception was unhandled.
Core 0 register dump:
PC      : 0x40095f3b  PS      : 0x00060c33  A0      : 0x80088f54  A1      : 0x3ffb7130
A2      : 0x00000000  A3      : 0x00060c20  A4      : 0x00000001  A5      : 0x0000cdcd
A6      : 0xb33fffff  A7      : 0x3ffaff34  A8      : 0x0000abab  A9      : 0x3ffb7130
A10     : 0x00000003  A11     : 0x0000cdcd  A12     : 0x00060c20  A13     : 0x00038214
A14     : 0x3fbc1030  A15     : 0x3fbc1771  SAR     : 0x00000000  EXCCAUSE: 0x0000001d
EXCVADDR: 0x00000000  LBEG    : 0x40093a40  LEND    : 0x40093a6e  LCOUNT  : 0xffffffff

ELF file SHA256: 0000000000000000000000000000000000000000000000000000000000000000

Backtrace: 0x40095f3b:0x3ffb7130 0x40088f51:0x3ffb7160 0x40086d29:0x3ffb7180 0x40145196:0x3ffb71c0 0x400d2418:0x3ffb71e0

Never seen something like that before with FW 1.20.2.rc6 or 1.20.2.rc6-0.10.1-vanilla-squirrel, what I used before. The coredump tells me:

==================== THREAD 1 (TCB: 0x3ffb727c, name: 'esp_timer') =====================
#0  0x40095f3b in uxPortCompareSet (set=<synthetic pointer>, compare=3007315967, addr=0x0) at /home/peter/docs/pycom-esp-idf/components/freertos/include/freertos/portmacro.h:355
#1  vPortCPUAcquireMutexIntsDisabledInternal (timeout_cycles=-1, mux=0x0) at /home/peter/docs/pycom-esp-idf/components/freertos/portmux_impl.inc.h:86
#2  vPortCPUAcquireMutexIntsDisabled (timeout_cycles=-1, mux=0x0) at /home/peter/docs/pycom-esp-idf/components/freertos/portmux_impl.h:98
#3  vTaskEnterCritical (mux=0x0) at /home/peter/docs/pycom-esp-idf/components/freertos/tasks.c:4201
#4  0x40088f54 in wifi_int_disable_wrapper (wifi_int_mux=0x0) at /home/peter/docs/pycom-esp-idf/components/esp32/esp_adapter.c:192
#5  0x40086d2c in pp_post ()
#6  0x40145199 in cnx_coexist_timeout ()
#7  0x400d241b in timer_process_alarm (dispatch_method=ESP_TIMER_TASK) at /home/peter/docs/pycom-esp-idf/components/esp32/esp_timer.c:305
#8  timer_task (arg=<optimized out>) at /home/peter/docs/pycom-esp-idf/components/esp32/esp_timer.c:326

ERROR: GDB/MI command failed (error / msg="Cannot access memory at address 0x1")!
WARNING: Unable to switch to thread 2

Possibly the core crashed, because the 'resume_wifi_ble' option was set to True with disabled WiFi. I need to have a deeper look into my sources.
If this happens (frequently), possibly something went wrong with the recovery of the LoRaWAN state from nvram. I don't know yet...

Cheers,
Thomas

[jcaron]

@Thomas-Schaefer What firmware version are toi using and which region are you in? Do you keep the LoPy running without rebooting it or having it go to deep sleep during all your tests?

If you reboot or deep sleep, you need to save and restore the LoRaWAN state to keep the channel assignments given by the network.

Can you share logs of the MAC commands sent to the LoPy and the channels used for uplinks?