Lora JOIN request fails & RX TIMEOUT

[zafersn]

I’ve ported the Semtech LoRa Basic Modem library to Zephyr for my project. It works fine unless I enable CONFIG_PM. Does anyone have any insight into what might be causing this issue? I understand that the LoRa Basic Modem library isn’t officially part of Zephyr yet, but perhaps someone has encountered a similar problem and has a solution or idea.

I can see that the join request from the chip successfully reaches the gateway, and the gateway accepts it, but the LoRa device immediately generates a fail event due to modem returns RX Timeout flags. There is no problem with dev eui and app_key. if I disable the configuration. a join request will will be ok.

Here are the gateway LoRaWAN frames:

zephyr version: v3.6-branch
sdk version: zephyr-sdk-0.16.6
MCU: STM32U575ZIQ
SHIELD: semtech_lr1121mb1xxs
Any workaround ideas? Can anyone shed some light on how to debug at least?

SUCCESFULL JOIN LOGS

INFO: Use soft secure element for cryptographic functionalities
[00:00:36.403,000] <dbg> lora_mac_layer: lr1_stack_mac_region_config: smtc_real_init done

[00:00:36.403,000] <dbg> lr1mac_core: lr1mac_core_init: stack_id 0

[00:00:36.403,000] <dbg> lr1mac_core: lr1mac_core_init:  DevNonce = 708

[00:00:36.403,000] <dbg> lr1mac_core: lr1mac_core_init:  JoinNonce = 0x0d 02 00, NetID = 0x00 00 00

[00:00:36.403,000] <dbg> lr1mac_core: lr1mac_core_init:  Region = CN470_RP_1_0

[00:00:36.404,000] <dbg> lora_radio_planner: rp_task_abort: RP: rp_task_abort #1

[00:00:36.404,000] <dbg> lora_mac_layer: lr1_stack_mac_region_config: smtc_real_init done

[00:00:36.404,000] <dbg> lora_certification: lorawan_certification_services_init: LoRaWAN Certification is disabled on stack 0

[00:00:36.404,000] <inf> lora_periodic: Modem event callback

[00:00:36.404,000] <inf> lora_periodic: Event received: RESET

2
[00:00:36.404,000] <dbg> lora_mac_layer: lr1_stack_mac_region_config: smtc_real_init done

INFO: smtc_modem_join_network
 Start a new join sequence now on stack 0
[00:00:36.404,000] <dbg> lora_module: lora_callback_handler: SMTC_MODEM_EVENT_RESET
[00:00:36.404,000] <inf> lora_periodic: Join is starting 

[00:00:36.405,000] <dbg> lora_mac_layer: lr1_stack_mac_region_config: smtc_real_init done

[00:00:36.405,000] <dbg> lora_radio_planner: rp_task_enqueue: RP: Task #2 enqueue with #7 priority

[00:00:36.405,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: Arbiter has been called by rp_task_enqueue and priority-task #2, timer hook #0, delay 2448, now 36405
                        
[00:00:36.405,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: High priority task is in the future

[00:00:36.413,000] <inf> modem_hl7812: RTC string: '"00/00/00,00:00:00-00"'
[00:00:38.846,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: Arbiter has been called by rp_timer_irq and priority-task #2, timer hook #2, delay 7, now 38846
                  
[00:00:38.846,000] <dbg> lora_radio_planner: rp_task_launch_current:  RP: Launch task #2 and start radio state 2, type 12

[00:00:38.846,000] <dbg> lora_radio_planner: rp_task_print: 
                                                            RP- INFO - Radio task #2  running - Timer task #2 running  - Hook ID #2 -
[00:00:38.846,000] <dbg> lora_radio_planner: rp_task_print:  TASK_ERROR 
[00:00:38.846,000] <dbg> lora_radio_planner: rp_task_print:  - start time @38853 - priority #7

[00:00:38.855,000] <dbg> lora_radio_planner: rp_callback:  RP: INFO - Radio IRQ received for hook #2

DevEUI - (8 bytes):
 66 30 31 34 63 33 65 39
JoinEUI - (8 bytes):
 00 00 00 00 00 00 00 00
[00:00:38.855,000] <dbg> lora_mac_layer: lr1_stack_mac_join_request_build: DevNonce 0x2c5, stack_id 0

[00:00:38.856,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: No more active tasks

[00:00:38.856,000] <dbg> lr1mac_core: lr1mac_core_process: Send Payload  for stack_id = 0

[00:00:38.856,000] <dbg> lr1mac_core: lr1mac_core_process:   Tx  LoRa at 38855 ms: freq:487500000, SF8, BW125, len 23 bytes 14 dBm, fcnt_up 0, toa = 114

[00:00:38.856,000] <dbg> lora_radio_planner: rp_task_enqueue: RP: Task #1 enqueue with #6 priority

[00:00:38.856,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: Arbiter has been called by rp_task_enqueue and priority-task #1, timer hook #2, delay 7, now 38856
                     
[00:00:38.856,000] <dbg> lora_radio_planner: rp_task_launch_current:  RP: Launch task #1 and start radio state 2, type 2

[00:00:38.856,000] <dbg> lora_radio_planner: rp_task_print: 
                                                            RP- INFO - Radio task #1  running - Timer task #2 running  - Hook ID #1 -
[00:00:38.856,000] <dbg> lora_radio_planner: rp_task_print:  TASK_TX_LORA 
[00:00:38.856,000] <dbg> lora_radio_planner: rp_task_print:  - start time @38866 - priority #6

[00:00:38.979,000] <dbg> lora_app_common: radio_on_dio_irq: 1446 lr11_apps_common.c

[00:00:38.980,000] <dbg> lora_radio_planner: rp_callback:  RP: INFO - Radio IRQ received for hook #1

[00:00:38.981,000] <dbg> lora_app_common: radio_on_dio_irq: 1446 lr11_apps_common.c

[00:00:38.981,000] <dbg> lora_mac_layer: lr1_stack_mac_rp_callback: 662 lr1_stack_mac_layer.c update: 3

[00:00:38.981,000] <dbg> lora_mac_layer: lr1_stack_mac_rp_callback: 749 lr1_stack_mac_layer.c update: 2

[00:00:38.981,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: No more active tasks

[00:00:38.981,000] <dbg> lr1mac_core: lr1mac_core_process:  TX DONE

[00:00:38.981,000] <dbg> lr1mac_core: lr1mac_core_process: radio_timestamp: 38979 time_off_ms: 0 jn stat:1

[00:00:38.983,000] <dbg> lr1mac_core: lr1mac_core_process: 297 lr1mac_core.c wnds: 0 1

[00:00:38.983,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_timer_configure: delay_ms 5000

[00:00:38.983,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_timer_configure: rx_offset_ms:-2, rx_timeout_symb_in_ms:16, rx_window_symb: 8, board_delay_ms:2

[00:00:38.983,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_radio_start: freq rx1: 507900000

[00:00:38.983,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_radio_start: timeout prm: 3000

[00:00:38.983,000] <dbg> lora_radio_planner: rp_task_enqueue: RP: Task #1 enqueue with #1 priority

[00:00:38.983,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: Arbiter has been called by rp_task_enqueue and priority-task #1, timer hook #2, delay 4994, now 38983
                        
[00:00:38.983,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: High priority task is in the future

[00:00:38.983,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_radio_start:   RX1 LoRa at 43977 ms: freq:507900000, SF8, BW125, sync word = 0x34

[00:00:38.983,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_timer_configure:   Timer will expire in 4994 ms

[00:00:38.983,000] <dbg> lr1mac_core: lr1mac_core_process: 301 lr1mac_core.c past: 0 

[00:00:43.970,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: Arbiter has been called by rp_timer_irq and priority-task #1, timer hook #1, delay 7, now 43970
                  
[00:00:43.970,000] <dbg> lora_radio_planner: rp_task_launch_current:  RP: Launch task #1 and start radio state 2, type 0

[00:00:43.970,000] <dbg> lora_radio_planner: rp_task_print: 
                                                            RP- INFO - Radio task #1  running - Timer task #1 running  - Hook ID #1 -
[00:00:43.970,000] <dbg> lora_radio_planner: rp_task_print:  TASK_RX_LORA 
[00:00:43.970,000] <dbg> lora_radio_planner: rp_task_print:  - start time @43977 - priority #1

[00:00:44.068,000] <dbg> lora_app_common: radio_on_dio_irq: 1446 lr11_apps_common.c

[00:00:44.068,000] <dbg> lora_radio_planner: rp_callback:  RP: INFO - Radio IRQ received for hook #1

[00:00:44.069,000] <dbg> lora_app_common: radio_on_dio_irq: 1446 lr11_apps_common.c

[00:00:44.070,000] <dbg> lora_mac_layer: lr1_stack_mac_rp_callback: 662 lr1_stack_mac_layer.c update: 4

[00:00:44.070,000] <dbg> lora_mac_layer: lr1_stack_mac_rp_callback: payload size receive = 17, snr = 12 , rssi = -72

[00:00:44.070,000] <dbg> lora_mac_layer: lr1_stack_mac_rp_callback: 749 lr1_stack_mac_layer.c update: 4

[00:00:44.070,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: No more active tasks

[00:00:44.070,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_frame_decode:  rx_packet_type = 4

[00:00:44.070,000] <dbg> lr1mac_core: lr1mac_core_process: 1Receive a Valid downlink RX1 for stack_id = 0
[00:00:44.070,000] <dbg> lr1mac_core: lr1mac_mac_update:  update join procedure

[00:00:44.070,000] <dbg> lora_mac_layer: lr1_stack_mac_join_accept:  DevAddr= 1e11adc

[00:00:44.070,000] <dbg> lora_mac_layer: lr1_stack_mac_join_accept:  MacRx1DataRateOffset= 0

[00:00:44.070,000] <dbg> lora_mac_layer: lr1_stack_mac_join_accept:  MacRx2DataRate= 0

[00:00:44.070,000] <dbg> lora_mac_layer: lr1_stack_mac_join_accept:  MacRx1Delay= 1

[00:00:44.072,000] <inf> lora_periodic: Modem event callback

[00:00:44.072,000] <inf> lora_periodic: Event received: JOINED

[00:00:44.072,000] <inf> lora_periodic: Modem is now joined

JOIN REQUEST FAILS LOG

INFO: Use soft secure element for cryptographic functionalities
[00:00:37.762,000] <dbg> lora_mac_layer: lr1_stack_mac_region_config: smtc_real_init done

[00:00:37.762,000] <dbg> lr1mac_core: lr1mac_core_init: stack_id 0

[00:00:37.762,000] <dbg> lr1mac_core: lr1mac_core_init:  DevNonce = 709

[00:00:37.762,000] <dbg> lr1mac_core: lr1mac_core_init:  JoinNonce = 0x0e 02 00, NetID = 0x00 00 00

[00:00:37.762,000] <dbg> lr1mac_core: lr1mac_core_init:  Region = CN470_RP_1_0

[00:00:37.764,000] <dbg> lora_radio_planner: rp_task_abort: RP: rp_task_abort #1

[00:00:37.764,000] <dbg> lora_mac_layer: lr1_stack_mac_region_config: smtc_real_init done

[00:00:37.764,000] <dbg> lora_certification: lorawan_certification_services_init: LoRaWAN Certification is disabled on stack 0

[00:00:37.764,000] <inf> lora_periodic: Modem event callback

[00:00:37.764,000] <inf> lora_periodic: Event received: RESET

2
[00:00:37.764,000] <dbg> lora_mac_layer: lr1_stack_mac_region_config: smtc_real_init done

INFO: smtc_modem_join_network
 Start a new join sequence now on stack 0
[00:00:37.764,000] <dbg> lora_module: lora_callback_handler: SMTC_MODEM_EVENT_RESET
[00:00:37.764,000] <inf> lora_periodic: Join is starting 

[00:00:37.765,000] <dbg> lora_mac_layer: lr1_stack_mac_region_config: smtc_real_init done

[00:00:37.765,000] <dbg> lora_radio_planner: rp_task_enqueue: RP: Task #2 enqueue with #7 priority

[00:00:37.765,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: Arbiter has been called by rp_task_enqueue and priority-task #2, timer hook #0, delay 2944, now 37765
                        
[00:00:37.765,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: High priority task is in the future
[00:00:40.702,000] <dbg> lora_radio_planner: rp_task_launch_current:  RP: Launch task #2 and start radio state 2, type 12

[00:00:40.702,000] <dbg> lora_radio_planner: rp_task_print: 
                                                            RP- INFO - Radio task #2  running - Timer task #2 running  - Hook ID #2 -
[00:00:40.702,000] <dbg> lora_radio_planner: rp_task_print:  TASK_ERROR 
[00:00:40.702,000] <dbg> lora_radio_planner: rp_task_print:  - start time @40709 - priority #7

[00:00:40.712,000] <dbg> lora_radio_planner: rp_callback:  RP: INFO - Radio IRQ received for hook #2

DevEUI - (8 bytes):
 66 30 31 34 63 33 65 39
JoinEUI - (8 bytes):
 00 00 00 00 00 00 00 00
[00:00:40.713,000] <dbg> lora_mac_layer: lr1_stack_mac_join_request_build: DevNonce 0x2c6, stack_id 0

[00:00:40.713,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: No more active tasks

[00:00:40.713,000] <dbg> lr1mac_core: lr1mac_core_process: Send Payload  for stack_id = 0

[00:00:40.713,000] <dbg> lr1mac_core: lr1mac_core_process:   Tx  LoRa at 40713 ms: freq:487500000, SF8, BW125, len 23 bytes 14 dBm, fcnt_up 0, toa = 114

[00:00:40.713,000] <dbg> lora_radio_planner: rp_task_enqueue: RP: Task #1 enqueue with #6 priority

[00:00:40.713,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: Arbiter has been called by rp_task_enqueue and priority-task #1, timer hook #2, delay 7, now 40713
                     
[00:00:40.713,000] <dbg> lora_radio_planner: rp_task_launch_current:  RP: Launch task #1 and start radio state 2, type 2

[00:00:40.713,000] <dbg> lora_radio_planner: rp_task_print: 
                                                            RP- INFO - Radio task #1  running - Timer task #2 running  - Hook ID #1 -
[00:00:40.713,000] <dbg> lora_radio_planner: rp_task_print:  TASK_TX_LORA 
[00:00:40.713,000] <dbg> lora_radio_planner: rp_task_print:  - start time @40713 - priority #6

[00:00:40.807,000] <dbg> lora_app_common: radio_on_dio_irq: 1446 lr11_apps_common.c

[00:00:40.807,000] <dbg> lora_radio_planner: rp_callback:  RP: INFO - Radio IRQ received for hook #1

[00:00:40.807,000] <dbg> lora_app_common: radio_on_dio_irq: 1446 lr11_apps_common.c

[00:00:40.808,000] <dbg> lora_mac_layer: lr1_stack_mac_rp_callback: 662 lr1_stack_mac_layer.c update: 3

[00:00:40.808,000] <dbg> lora_mac_layer: lr1_stack_mac_rp_callback: 749 lr1_stack_mac_layer.c update: 2

[00:00:40.808,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: No more active tasks

[00:00:40.808,000] <dbg> lr1mac_core: lr1mac_core_process:  TX DONE

[00:00:40.808,000] <dbg> lr1mac_core: lr1mac_core_process: radio_timestamp: 40807 time_off_ms: 0 jn stat:1

[00:00:40.810,000] <dbg> lr1mac_core: lr1mac_core_process: 297 lr1mac_core.c wnds: 0 1

[00:00:40.810,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_timer_configure: delay_ms 5000

[00:00:40.810,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_timer_configure: rx_offset_ms:-2, rx_timeout_symb_in_ms:16, rx_window_symb: 8, board_delay_ms:2

[00:00:40.810,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_radio_start: freq rx1: 507900000

[00:00:40.810,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_radio_start: timeout prm: 3000

[00:00:40.810,000] <dbg> lora_radio_planner: rp_task_enqueue: RP: Task #1 enqueue with #1 priority

[00:00:40.810,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: Arbiter has been called by rp_task_enqueue and priority-task #1, timer hook #2, delay 4995, now 40810
                        
[00:00:40.810,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: High priority task is in the future

[00:00:40.810,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_radio_start:   RX1 LoRa at 45805 ms: freq:507900000, SF8, BW125, sync word = 0x34

[00:00:40.810,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_timer_configure:   Timer will expire in 4995 ms

[00:00:40.810,000] <dbg> lr1mac_core: lr1mac_core_process: 301 lr1mac_core.c past: 0 

[00:00:45.798,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: Arbiter has been called by rp_timer_irq and priority-task #1, timer hook #1, delay 7, now 45798
                  
[00:00:45.798,000] <dbg> lora_radio_planner: rp_task_launch_current:  RP: Launch task #1 and start radio state 2, type 0

[00:00:45.798,000] <dbg> lora_radio_planner: rp_task_print: 
                                                            RP- INFO - Radio task #1  running - Timer task #1 running  - Hook ID #1 -
[00:00:45.798,000] <dbg> lora_radio_planner: rp_task_print:  TASK_RX_LORA 
[00:00:45.798,000] <dbg> lora_radio_planner: rp_task_print:  - start time @45805 - priority #1

[00:00:45.818,000] <dbg> lora_app_common: radio_on_dio_irq: 1446 lr11_apps_common.c

[00:00:45.820,000] <dbg> lora_radio_planner: rp_callback:  RP: INFO - Radio IRQ received for hook #1

[00:00:45.820,000] <dbg> lora_app_common: radio_on_dio_irq: 1446 lr11_apps_common.c

[00:00:45.821,000] <dbg> lora_mac_layer: lr1_stack_mac_rp_callback: 662 lr1_stack_mac_layer.c update: 5

[00:00:45.821,000] <dbg> lora_mac_layer: lr1_stack_mac_rp_callback: DR4 Fine tune correction (ms) = 0, error fine tune (ms) = -5, lr1_mac->rx_offset_ms = -2

[00:00:45.821,000] <dbg> lora_mac_layer: lr1_stack_mac_rp_callback: 749 lr1_stack_mac_layer.c update: 4

[00:00:45.821,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: No more active tasks

[00:00:45.821,000] <dbg> lr1mac_core: lr1mac_core_process: 1RX1 Timeout for stack_id = 0


[00:00:45.821,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_timer_configure: delay_ms 6000

[00:00:45.821,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_timer_configure: rx_offset_ms:-2, rx_timeout_symb_in_ms:16, rx_window_symb: 8, board_delay_ms:2

[00:00:45.821,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_radio_start: freq rx2: 505300000

[00:00:45.821,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_radio_start: timeout prm: 3000

[00:00:45.821,000] <dbg> lora_radio_planner: rp_task_enqueue: RP: Task #1 enqueue with #1 priority

[00:00:45.821,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: Arbiter has been called by rp_task_enqueue and priority-task #1, timer hook #1, delay 984, now 45821
                       
[00:00:45.821,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: High priority task is in the future

[00:00:45.821,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_radio_start:   RX2 LoRa at 46805 ms: freq:505300000, SF8, BW125, sync word = 0x34

[00:00:45.821,000] <dbg> lora_mac_layer: lr1_stack_mac_rx_timer_configure:   Timer will expire in 984 ms

[00:00:46.798,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: Arbiter has been called by rp_timer_irq and priority-task #1, timer hook #1, delay 7, now 46798
                  
[00:00:46.798,000] <dbg> lora_radio_planner: rp_task_launch_current:  RP: Launch task #1 and start radio state 2, type 0

[00:00:46.798,000] <dbg> lora_radio_planner: rp_task_print: 
                                                            RP- INFO - Radio task #1  running - Timer task #1 running  - Hook ID #1 -
[00:00:46.798,000] <dbg> lora_radio_planner: rp_task_print:  TASK_RX_LORA 
[00:00:46.798,000] <dbg> lora_radio_planner: rp_task_print:  - start time @46805 - priority #1

[00:00:46.818,000] <dbg> lora_app_common: radio_on_dio_irq: 1446 lr11_apps_common.c

[00:00:46.820,000] <dbg> lora_radio_planner: rp_callback:  RP: INFO - Radio IRQ received for hook #1

[00:00:46.820,000] <dbg> lora_app_common: radio_on_dio_irq: 1446 lr11_apps_common.c

[00:00:46.821,000] <dbg> lora_mac_layer: lr1_stack_mac_rp_callback: 662 lr1_stack_mac_layer.c update: 5

[00:00:46.821,000] <dbg> lora_mac_layer: lr1_stack_mac_rp_callback: DR0 Fine tune correction (ms) = 0, error fine tune (ms) = -5, lr1_mac->rx_offset_ms = -2

[00:00:46.821,000] <dbg> lora_mac_layer: lr1_stack_mac_rp_callback: 749 lr1_stack_mac_layer.c update: 4

[00:00:46.821,000] <dbg> lora_radio_planner: rp_task_arbiter:  RP: No more active tasks

[00:00:46.821,000] <dbg> lr1mac_core: lr1mac_core_process: RX2 Timeout for stack_id = 0
 Start a new join sequence in 14 seconds on stack 0
[00:00:46.821,000] <inf> lora_periodic: Modem event callback

[00:00:46.821,000] <inf> lora_periodic: Event received: JOINFAIL

[00:00:46.821,000] <dbg> lora_module: lora_callback_handler: SMTC_MODEM_EVENT_JOINFAIL

I created the same issue here too:

https://www.thethingsnetwork.org/forum/t/lora-join-request-fails-rx-timeout/69045/8

[opeyrard]

Hi,
A porting of LBM on Zephyr OS is now available as a feature branch here.
Many thanks,
Best regards,

[jakeru]

Hi,
I have been playing a bit with the LBM Zephyr port from Semtech on a RAK4631 module. My node is able to join also when I enable Zephyr Power Management for the kernel (CONFIG_PM=y) as well as for devices (CONFIG_PM_DEVICE=y).
Note that the CONFIG_PM_DEVICE option is actually not implemented for the LoRa radio drivers. The sx1262 is put into sleep mode by the driver regardless of that option.

[Salamandar]

Hi @jakeru , indeed, the device is put in sleep mode by the LBM stack and not by the zephyr-side driver. This can be open to discussion, but IMHO the current behaviour is "sane" enough.