Help with LTE connection after loss of connection

We have noticed that several of our nRF9160 in production have problem with reconnecting to the LTE-M network after temporarily losing connection. We have tried reproducing this issue by deactivating the sim for about 10 seconds and then activating it again. After the default six retries it gives up and stop trying to reconnect to the network. the only way we can achieve a connection is if we do a sys_reboot() or a hard reboot with watchdog. Why is the reconnect attempts not enough? Why do we have to force a reboot? Attached are relevant logs.

0 Matias Marti 28 days ago in reply to lobaro-theo

Hello lobaro-theo ,

We have not used v2.5.0, only 2.3.0 and now 2.6.0. Thank you for sharing your findings on v2.5.0. My guess is that there might have been new config values that have been added to 2.6.0 that are discarded by 2.5.0 (that is, if you prj.conf looks the same).
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel

0 Matias Marti 28 days ago in reply to SeppoTakalo

Thank you @seppo . Here are some more interesing logs:

[1;32muart:~$ [m[8D[J[00:49:29.217,254] [0m<dbg> app_lwm2m_client: rd_client_event: Registration update complete[0m
[1;32muart:~$ [m[8D[J[00:49:29.217,285] [0m<dbg> app_lwm2m_client: watchdog_Kick: Watchdog feed ok![0m
[1;32muart:~$ [m[8D[J[00:49:29.217,376] [0m<inf> net_lwm2m_rd_client: Update Done[0m
[1;32muart:~$ [m[8D[J[00:49:29.217,559] [0m<dbg> net_lwm2m_message_handling: lwm2m_udp_receive: reply 0x2000d7c0 handled and removed[0m
[1;32muart:~$ [m[8D[J[00:49:29.217,620] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9[0m
[1;32muart:~$ [m[8D[J[00:49:29.252,838] [0m<dbg> at_monitor: at_monitor_task: AT notif: %CESQ: 39,1,17,2[0m
[1;32muart:~$ [m[8D[J[00:49:29.252,899] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x3bef9[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:49:34.666,595] [0m<dbg> at_monitor: at_monitor_task: AT notif: +CSCON: 0[0m
[1;32muart:~$ [m[8D[J[00:49:34.666,625] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x39a7d[0m
[1;32muart:~$ [m[8D[J[00:49:34.666,656] [0m<dbg> lte_lc: at_handler_cscon: +CSCON notification[0m
[1;32muart:~$ [m[8D[J[00:49:34.666,809] [0m<dbg> lte_lc: event_handler_list_dispatch: Dispatching event: type=3[0m
[1;32muart:~$ [m[8D[J[00:49:34.666,839] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0003C989[0m
[1;32muart:~$ [m[8D[J[00:49:34.666,839] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x00040D25[0m
[1;32muart:~$ [m[8D[J[00:49:34.666,870] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0001A8A5[0m
[1;32muart:~$ [m[8D[J[00:49:34.666,900] [0m<dbg> lte_lc: event_handler_list_dispatch: Done[0m
[1;32muart:~$ [m[8D[J[00:49:34.766,723] [0m<dbg> at_monitor: at_monitor_task: AT notif: %XT3412: 3239999[0m
[1;32muart:~$ [m[8D[J[00:49:34.766,754] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x3992d[0m
[1;32muart:~$ [m[8D[J[00:49:34.766,815] [0m<dbg> lte_lc: at_handler_xt3412: %XT3412 notification[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:49:35.249,389] [0m<dbg> at_monitor: at_monitor_task: AT notif: %CESQ: 37,1,12,1[0m
[1;32muart:~$ [m[8D[J[00:49:35.249,450] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x3bef9[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m*** Booting nRF Connect SDK v3.5.99-ncs1 ***
I: Starting bootloader
I: Primary image: magic=good, swap_type=0x2, copy_done=0x1, image_ok=0x1
I: Secondary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Boot source: none
I: Image index: 0, Swap type: none
I: Bootloader chainload address offset: 0x10000
I: Jumping to the first image slot
�[m

[1;32muart:~$ [m[8D[J[00:00:00.252,258] [0m<dbg> clock_control: clkstarted_handle: lfclk: Clock started[0m
[1;32muart:~$ [m[8D[J*** Booting nRF Connect SDK v3.5.99-ncs1 ***
[1;32muart:~$ [m[8D[J[00:00:00.253,814] [0m<dbg> net_lwm2m_obj_qlocx_manage: management_create: Create IPSO Management instance: 0[0m
[1;32muart:~$ [m[8D[J[00:00:00.253,845] [0m<dbg> net_lwm2m_obj_qlocx_barcode: barcode_create: Create IPSO Barcode instance: 0[0m
[1;32muart:~$ [m[8D[J[00:00:00.254,577] [0m<dbg> net_lwm2m_engine: lwm2m_engine_init: LWM2M engine socket receive thread started[0m
[1;32muart:~$ [m[8D[J[00:00:00.254,699] [0m<dbg> net_lwm2m_obj_security: security_create: Create LWM2M security instance: 0[0m
[1;32muart:~$ [m[8D[J[00:00:00.254,821] [0m<dbg> net_lwm2m_obj_device: device_create: Create LWM2M device instance: 0[0m
[1;32muart:~$ [m[8D[J[00:00:00.255,187] [0m<dbg> net_lwm2m_obj_conn_mon: connmon_create: Create LWM2M connectivity monitoring instance: 0[0m
[1;32muart:~$ [m[8D[J[00:00:00.255,249] [0m<dbg> net_lwm2m_obj_firmware: firmware_create: Create LWM2M firmware instance: 0[0m
[1;32muart:~$ [m[8D[J[00:00:00.255,798] [0m<inf> app_lwm2m_client: Run LWM2M client[0m
[1;32muart:~$ [m[8D[J[00:00:00.255,828] [0m<dbg> app_lwm2m_client: watchdog_Init: Watchdog started: 0[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:00:00.487,518] [0m<dbg> nrf_modem: nrf_modem_lib_init: Modem init callback: 0x3bdf9[0m
[1;32muart:~$ [m[8D[J[00:00:00.495,758] [0m<dbg> lte_lc: lte_lc_system_mode_set: System mode set to 1, preference 0[0m
[1;32muart:~$ [m[8D[J[00:00:00.495,819] [0m<dbg> lte_lc: lte_lc_psm_param_set: RPTAU set to 00000110[0m
[1;32muart:~$ [m[8D[J[00:00:00.495,849] [0m<dbg> lte_lc: lte_lc_psm_param_set: RAT set to 00001111[0m
[1;32muart:~$ [m[8D[J[00:00:00.495,910] [0m<dbg> lte_lc: on_modem_init: PSM configs set from string: tau=00000110, rat=00001111[0m
[1;32muart:~$ [m[8D[J[00:00:00.495,971] [0m<dbg> lte_lc: lte_lc_psm_req: enable=0, tau=00000110, rat=00001111[0m
[1;32muart:~$ [m[8D[J[00:00:00.503,906] [0m<inf> app_lwm2m_client: Clearing PSK[0m
[1;32muart:~$ [m[8D[J[00:00:00.533,843] [0m<dbg> app_lwm2m_client: watchdog_Kick: Watchdog feed ok![0m
[1;32muart:~$ [m[8D[J[00:00:00.533,905] [0m<dbg> app_lwm2m_client: watchdog_Kick: Watchdog feed ok![0m
[1;32muart:~$ [m[8D[J[00:00:00.534,606] [0m<inf> app_lwm2m_client: endpoint: <MY_ENDPOINT>[0m
[1;32muart:~$ [m[8D[J[00:00:00.534,637] [0m<dbg> app_lwm2m_client: watchdog_Kick: Watchdog feed ok![0m

We have noticed that the device keeps restarting every 49.5 minutes... Is there any value in prj.conf that might be causing this?

Another point:

It seems like disabling PSM mode prevents the device from disconnecting:

[1;32muart:~$ [m[8D[J[00:25:43.377,349] [0m<dbg> net_lwm2m_message_handling: lwm2m_parse_peerinfo: Parse url: coaps://<MY_URL>:5684[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:25:47.265,747] [0m<dbg> at_monitor: at_monitor_task: AT notif: +CSCON: 0[0m
[1;32muart:~$ [m[8D[J[00:25:47.265,808] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x39a7d[0m
[1;32muart:~$ [m[8D[J[00:25:47.265,808] [0m<dbg> lte_lc: at_handler_cscon: +CSCON notification[0m
[1;32muart:~$ [m[8D[J[00:25:47.265,960] [0m<dbg> lte_lc: event_handler_list_dispatch: Dispatching event: type=3[0m
[1;32muart:~$ [m[8D[J[00:25:47.265,991] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0003C989[0m
[1;32muart:~$ [m[8D[J[00:25:47.266,021] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x00040D25[0m
[1;32muart:~$ [m[8D[J[00:25:47.266,021] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0001A8A5[0m
[1;32muart:~$ [m[8D[J[00:25:47.266,052] [0m<dbg> lte_lc: event_handler_list_dispatch: Done[0m
[1;32muart:~$ [m[8D[J[00:25:47.365,875] [0m<dbg> at_monitor: at_monitor_task: AT notif: %XT3412: 3239999[0m
[1;32muart:~$ [m[8D[J[00:25:47.365,905] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x3992d[0m
[1;32muart:~$ [m[8D[J[00:25:47.365,966] [0m<dbg> lte_lc: at_handler_xt3412: %XT3412 notification[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:25:47.465,972] [0m<dbg> at_monitor: at_monitor_task: AT notif: %XT3412: 0[0m
[1;32muart:~$ [m[8D[J[00:25:47.466,003] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x3992d[0m
[1;32muart:~$ [m[8D[J[00:25:47.466,033] [0m<dbg> lte_lc: at_handler_xt3412: %XT3412 notification[0m
[1;32muart:~$ [m[8D[J[00:25:47.475,524] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:0/1/2/0, level 3, buf:0x20031fc3, buflen:1[0m
[1;32muart:~$ [m[8D[J[00:25:47.485,900] [0m<dbg> at_monitor: at_monitor_task: AT notif: +CSCON: 1[0m
[1;32muart:~$ [m[8D[J[00:25:47.485,931] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x39a7d[0m
[1;32muart:~$ [m[8D[J[00:25:47.485,961] [0m<dbg> lte_lc: at_handler_cscon: +CSCON notification[0m
[1;32muart:~$ [m[8D[J[00:25:47.486,083] [0m<dbg> lte_lc: event_handler_list_dispatch: Dispatching event: type=3[0m
[1;32muart:~$ [m[8D[J[00:25:47.486,114] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0003C989[0m
[1;32muart:~$ [m[8D[J[00:25:47.486,145] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x00040D25[0m
[1;32muart:~$ [m[8D[J[00:25:47.486,175] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0001A8A5[0m
[1;32muart:~$ [m[8D[J[00:25:47.486,206] [0m<dbg> lte_lc: event_handler_list_dispatch: Done[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:25:47.667,907] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:0/1/2/0, level 3, buf:0x20031f8b, buflen:1[0m
[1;32muart:~$ [m[8D[J[00:25:47.667,999] [0m<dbg> lwm2m_security: load_credentials_to_modem: Existing credentials found on modem[0m
[1;32muart:~$ [m[8D[J[00:25:47.668,548] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:0/1/2/0, level 3, buf:0x20031fcb, buflen:1[0m
[1;32muart:~$ [m[8D[J[00:25:47.840,270] [0m<inf> net_lwm2m_engine: Connected, sock id 2[0m
[1;32muart:~$ [m[8D[J[00:25:47.841,003] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x20031ff0, buflen:4[0m
[1;32muart:~$ [m[8D[J[00:25:47.842,407] [0m<dbg> net_lwm2m_rd_client: sm_send_registration: registration sent [<MY_IP>][0m
[1;32muart:~$ [m[8D[J[00:25:47.843,383] [0m<dbg> app_lwm2m_client: rd_client_event: Disconnected[0m
[1;32muart:~$ [m[8D[J[00:25:47.843,505] [0m<inf> net_lwm2m_rd_client: Stop LWM2M Client: <MY_ENDPOINT>[0m
[1;32muart:~$ [m[8D[J[00:25:47.845,031] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 17[0m
[1;32muart:~$ [m[8D[J[00:25:47.846,618] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 0[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:25:47.929,077] [0m<inf> app_lwm2m_client: Client connect to server[0m
[1;32muart:~$ [m[8D[J[00:25:47.929,168] [0m<inf> net_lwm2m_rd_client: Start LWM2M Client: <MY_ENDPOINT>[0m
[1;32muart:~$ [m[8D[J[00:25:47.929,443] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 1[0m
[1;32muart:~$ [m[8D[J[00:25:47.929,779] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 6[0m
[1;32muart:~$ [m[8D[J[00:25:47.929,809] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x20032020, buflen:4[0m
[1;32muart:~$ [m[8D[J[00:25:47.929,840] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/0/0, level 3, buf:0x20032040, buflen:2[0m
[1;32muart:~$ [m[8D[J[00:25:47.929,931] [0m<inf> net_lwm2m_rd_client: RD Client started with endpoint '<MY_ENDPOINT>' with client lifetime 86400 using server object 0[0m
[1;32muart:~$ [m[8D[J[00:25:47.929,992] [0m<dbg> net_lwm2m_message_handling: lwm2m_parse_peerinfo: Parse url: coaps://<MY_URL>:5684[0m
[1;32muart:~$ [m[8D[J[00:25:47.930,633] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:0/1/2/0, level 3, buf:0x20031fc3, buflen:1[0m
[1;32muart:~$ [m[8D[J[00:25:48.056,610] [0m<inf> app_lwm2m_client: LwM2M is connecting to server[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:25:48.096,557] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:0/1/2/0, level 3, buf:0x20031f8b, buflen:1[0m
[1;32muart:~$ [m[8D[J[00:25:48.096,649] [0m<dbg> lwm2m_security: load_credentials_to_modem: Existing credentials found on modem[0m
[1;32muart:~$ [m[8D[J[00:25:48.097,198] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:0/1/2/0, level 3, buf:0x20031fcb, buflen:1[0m
[1;32muart:~$ [m[8D[J[00:25:48.258,239] [0m<inf> net_lwm2m_engine: Connected, sock id 2[0m
[1;32muart:~$ [m[8D[J[00:25:48.258,819] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x20031ff0, buflen:4[0m
[1;32muart:~$ [m[8D[J[00:25:48.260,192] [0m<dbg> net_lwm2m_rd_client: sm_send_registration: registration sent [<MY_IP>][0m
[1;32muart:~$ [m[8D[J[00:25:48.262,390] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 8[0m
[1;32muart:~$ [m[8D[J[00:25:48.393,890] [0m<dbg> net_lwm2m_rd_client: do_registration_reply_cb: Registration callback (code:2.1)[0m
[1;32muart:~$ [m[8D[J[00:25:48.394,592] [0m<dbg> lte_lc: parse_psm: TAU: 3240 sec, active time: -1 sec[0m
[1;32muart:~$ [m[8D[J[00:25:48.394,622] [0m<dbg> lte_lc: lte_lc_psm_get: TAU: 3240 sec, active time: -1 sec[0m
[1;32muart:~$ [m[8D[J[00:25:48.394,653] [0m<dbg> lwm2m_sec_con_man: lwm2m_utils_update_rptau: PSM deactivated[0m
[1;32muart:~$ [m[8D[J[00:25:48.394,683] [0m<dbg> app_lwm2m_client: rd_client_event: Registration complete[0m
[1;32muart:~$ [m[8D[J[00:25:48.394,805] [0m<inf> net_lwm2m_rd_client: Registration Done (EP='XXXXXXX')[0m
[1;32muart:~$ [m[8D[J[00:25:48.394,989] [0m<dbg> net_lwm2m_message_handling: lwm2m_udp_receive: reply 0x2000d7c0 handled and removed[0m
[1;32muart:~$ [m[8D[J[00:25:48.395,050] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:25:48.477,661] [0m<inf> app_lwm2m_client: LwM2M is connected to server[0m
[1;32muart:~$ [m[8D[J[00:25:48.477,722] [0m<dbg> date_time: date_time_update_thread: Updating date time UTC...[0m
[1;32muart:~$ [m[8D[J[00:25:48.477,752] [0m<dbg> date_time: date_time_update_thread: Using previously obtained time[0m
[1;32muart:~$ [m[8D[J[00:25:48.477,783] [0m<inf> app_lwm2m_client: Obtained date-time from modem[0m
[1;32muart:~$ [m[8D[J[00:25:48.477,813] [0m<dbg> net_lwm2m_registry: lwm2m_engine_set: path:3/0/13, buf:0x2003275c, len:4[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:25:52.857,696] [0m<dbg> at_monitor: at_monitor_task: AT notif: +CSCON: 0[0m
[1;32muart:~$ [m[8D[J[00:25:52.857,727] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x39a7d[0m
[1;32muart:~$ [m[8D[J[00:25:52.857,757] [0m<dbg> lte_lc: at_handler_cscon: +CSCON notification[0m
[1;32muart:~$ [m[8D[J[00:25:52.857,910] [0m<dbg> lte_lc: event_handler_list_dispatch: Dispatching event: type=3[0m
[1;32muart:~$ [m[8D[J[00:25:52.857,910] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0003C989[0m
[1;32muart:~$ [m[8D[J[00:25:52.857,940] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x00040D25[0m
[1;32muart:~$ [m[8D[J[00:25:52.857,971] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0001A8A5[0m
[1;32muart:~$ [m[8D[J[00:25:52.857,971] [0m<dbg> lte_lc: event_handler_list_dispatch: Done[0m
[1;32muart:~$ [m[8D[J[00:25:52.957,794] [0m<dbg> at_monitor: at_monitor_task: AT notif: %XT3412: 3239999[0m
[1;32muart:~$ [m[8D[J[00:25:52.957,855] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x3992d[0m
[1;32muart:~$ [m[8D[J[00:25:52.957,885] [0m<dbg> lte_lc: at_handler_xt3412: %XT3412 notification[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:25:53.120,452] [0m<dbg> at_monitor: at_monitor_task: AT notif: %CESQ: 34,1,17,2[0m
[1;32muart:~$ [m[8D[J[00:25:53.120,513] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x3bef9[0m
[1;32muart:~$ [m[8D[J[00:25:53.120,727] [0m<dbg> net_lwm2m_registry: lwm2m_engine_set: path:4/0/2, buf:0x2003989e, len:2[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:26:02.080,841] [0m<dbg> at_monitor: at_monitor_task: AT notif: %CESQ: 33,1,12,1[0m
[1;32muart:~$ [m[8D[J[00:26:02.080,902] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x3bef9[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:26:07.393,768] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9[0m
[1;32muart:~$ [m[8D[J[00:26:07.393,829] [0m<dbg> app_lwm2m_client: rd_client_event: Registration update started[0m
[1;32muart:~$ [m[8D[J[00:26:07.493,347] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 11[0m
[1;32muart:~$ [m[8D[J[00:26:07.493,865] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x20031ff8, buflen:4[0m
[1;32muart:~$ [m[8D[J[00:26:07.494,018] [0m<dbg> net_lwm2m_rd_client: sm_send_registration: registration sent [<MY_IP>][0m
[1;32muart:~$ [m[8D[J[00:26:07.501,403] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 12[0m
[1;32muart:~$ [m[8D[J[00:26:07.604,492] [0m<dbg> at_monitor: at_monitor_task: AT notif: %XT3412: 0[0m
[1;32muart:~$ [m[8D[J[00:26:07.604,522] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x3992d[0m
[1;32muart:~$ [m[8D[J[00:26:07.604,553] [0m<dbg> lte_lc: at_handler_xt3412: %XT3412 notification[0m
[1;32muart:~$ [m[8D[J[00:26:07.704,925] [0m<dbg> at_monitor: at_monitor_task: AT notif: +CSCON: 1[0m
[1;32muart:~$ [m[8D[J[00:26:07.704,986] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x39a7d[0m
[1;32muart:~$ [m[8D[J[00:26:07.705,017] [0m<dbg> lte_lc: at_handler_cscon: +CSCON notification[0m
[1;32muart:~$ [m[8D[J[00:26:07.705,169] [0m<dbg> lte_lc: event_handler_list_dispatch: Dispatching event: type=3[0m
[1;32muart:~$ [m[8D[J[00:26:07.705,200] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0003C989[0m
[1;32muart:~$ [m[8D[J[00:26:07.705,200] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x00040D25[0m
[1;32muart:~$ [m[8D[J[00:26:07.705,230] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0001A8A5[0m
[1;32muart:~$ [m[8D[J[00:26:07.705,230] [0m<dbg> lte_lc: event_handler_list_dispatch: Done[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:26:08.495,117] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 12[0m
[1;32muart:~$ [m[8D[J[00:26:08.495,147] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State machine have timed out[0m
[1;32muart:~$ [m[8D[J[00:26:08.495,239] [0m<dbg> app_lwm2m_client: rd_client_event: Registration update failure![0m
[1;32muart:~$ [m[8D[J[00:26:08.495,300] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 1[0m
[1;32muart:~$ [m[8D[J[00:26:08.502,868] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 6[0m
[1;32muart:~$ [m[8D[J[00:26:08.502,899] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x20032020, buflen:4[0m
[1;32muart:~$ [m[8D[J[00:26:08.502,960] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/0/0, level 3, buf:0x20032040, buflen:2[0m
[1;32muart:~$ [m[8D[J[00:26:08.503,021] [0m<inf> net_lwm2m_rd_client: RD Client started with endpoint '<MY_ENDPOINT>' with client lifetime 86400 using server object 0[0m
[1;32muart:~$ [m[8D[J[00:26:08.503,112] [0m<dbg> net_lwm2m_message_handling: lwm2m_parse_peerinfo: Parse url: coaps://<MY_URL>:5684[0m
[1;32muart:~$ [m[8D[J[00:26:08.503,784] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:0/1/2/0, level 3, buf:0x20031fc3, buflen:1[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:26:08.641,876] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:0/1/2/0, level 3, buf:0x20031f8b, buflen:1[0m
[1;32muart:~$ [m[8D[J[00:26:08.641,998] [0m<dbg> lwm2m_security: load_credentials_to_modem: Existing credentials found on modem[0m
[1;32muart:~$ [m[8D[J[00:26:08.642,822] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:0/1/2/0, level 3, buf:0x20031fcb, buflen:1[0m
[1;32muart:~$ [m[8D[J[00:26:08.827,178] [0m<inf> net_lwm2m_engine: Connected, sock id 2[0m
[1;32muart:~$ [m[8D[J[00:26:08.827,911] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x20031ff0, buflen:4[0m
[1;32muart:~$ [m[8D[J[00:26:08.829,315] [0m<dbg> net_lwm2m_rd_client: sm_send_registration: registration sent [<MY_IP>][0m
[1;32muart:~$ [m[8D[J[00:26:08.830,291] [0m<dbg> app_lwm2m_client: rd_client_event: Disconnected[0m
[1;32muart:~$ [m[8D[J[00:26:08.830,413] [0m<inf> net_lwm2m_rd_client: Stop LWM2M Client: <MY_ENDPOINT>[0m
[1;32muart:~$ [m[8D[J[00:26:08.831,481] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 17[0m
[1;32muart:~$ [m[8D[J[00:26:08.833,190] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 0[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:26:08.916,229] [0m<inf> app_lwm2m_client: Client connect to server[0m
[1;32muart:~$ [m[8D[J[00:26:08.916,290] [0m<inf> net_lwm2m_rd_client: Start LWM2M Client: <MY_ENDPOINT>[0m
[1;32muart:~$ [m[8D[J[00:26:08.916,564] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 1[0m
[1;32muart:~$ [m[8D[J[00:26:08.916,900] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 6[0m
[1;32muart:~$ [m[8D[J[00:26:08.916,931] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x20032020, buflen:4[0m
[1;32muart:~$ [m[8D[J[00:26:08.916,992] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/0/0, level 3, buf:0x20032040, buflen:2[0m
[1;32muart:~$ [m[8D[J[00:26:08.917,053] [0m<inf> net_lwm2m_rd_client: RD Client started with endpoint '<MY_ENDPOINT>' with client lifetime 86400 using server object 0[0m
[1;32muart:~$ [m[8D[J[00:26:08.917,114] [0m<dbg> net_lwm2m_message_handling: lwm2m_parse_peerinfo: Parse url: coaps://<MY_URL>:5684[0m
[1;32muart:~$ [m[8D[J[00:26:08.917,999] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:0/1/2/0, level 3, buf:0x20031fc3, buflen:1[0m
[1;32muart:~$ [m[8D[J[00:26:09.040,771] [0m<inf> app_lwm2m_client: LwM2M is connecting to server[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:26:09.082,366] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:0/1/2/0, level 3, buf:0x20031f8b, buflen:1[0m
[1;32muart:~$ [m[8D[J[00:26:09.082,489] [0m<dbg> lwm2m_security: load_credentials_to_modem: Existing credentials found on modem[0m
[1;32muart:~$ [m[8D[J[00:26:09.083,099] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:0/1/2/0, level 3, buf:0x20031fcb, buflen:1[0m
[1;32muart:~$ [m[8D[J[00:26:09.207,244] [0m<inf> net_lwm2m_engine: Connected, sock id 2[0m
[1;32muart:~$ [m[8D[J[00:26:09.207,824] [0m<dbg> net_lwm2m_registry: lwm2m_engine_get: path:1/0/1/0, level 3, buf:0x20031ff0, buflen:4[0m
[1;32muart:~$ [m[8D[J[00:26:09.209,197] [0m<dbg> net_lwm2m_rd_client: sm_send_registration: registration sent [<MY_IP>][0m
[1;32muart:~$ [m[8D[J[00:26:09.211,395] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 8[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:26:13.028,656] [0m<dbg> at_monitor: at_monitor_task: AT notif: +CSCON: 0[0m
[1;32muart:~$ [m[8D[J[00:26:13.028,717] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x39a7d[0m
[1;32muart:~$ [m[8D[J[00:26:13.028,747] [0m<dbg> lte_lc: at_handler_cscon: +CSCON notification[0m
[1;32muart:~$ [m[8D[J[00:26:13.028,869] [0m<dbg> lte_lc: event_handler_list_dispatch: Dispatching event: type=3[0m
[1;32muart:~$ [m[8D[J[00:26:13.028,900] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0003C989[0m
[1;32muart:~$ [m[8D[J[00:26:13.028,930] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x00040D25[0m
[1;32muart:~$ [m[8D[J[00:26:13.028,930] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0001A8A5[0m
[1;32muart:~$ [m[8D[J[00:26:13.028,961] [0m<dbg> lte_lc: event_handler_list_dispatch: Done[0m
[1;32muart:~$ [m[8D[J[00:26:13.128,784] [0m<dbg> at_monitor: at_monitor_task: AT notif: %XT3412: 3239999[0m
[1;32muart:~$ [m[8D[J[00:26:13.128,814] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x3992d[0m
[1;32muart:~$ [m[8D[J[00:26:13.128,875] [0m<dbg> lte_lc: at_handler_xt3412: %XT3412 notification[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:26:15.004,791] [0m<dbg> at_monitor: at_monitor_task: AT notif: %XT3412: 0[0m
[1;32muart:~$ [m[8D[J[00:26:15.004,821] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x3992d[0m
[1;32muart:~$ [m[8D[J[00:26:15.004,852] [0m<dbg> lte_lc: at_handler_xt3412: %XT3412 notification[0m
[1;32muart:~$ [m[8D[J[00:26:15.105,010] [0m<dbg> at_monitor: at_monitor_task: AT notif: +CSCON: 1[0m
[1;32muart:~$ [m[8D[J[00:26:15.105,041] [0m<dbg> at_monitor: at_monitor_task: Dispatching to 0x39a7d[0m
[1;32muart:~$ [m[8D[J[00:26:15.105,072] [0m<dbg> lte_lc: at_handler_cscon: +CSCON notification[0m
[1;32muart:~$ [m[8D[J[00:26:15.105,224] [0m<dbg> lte_lc: event_handler_list_dispatch: Dispatching event: type=3[0m
[1;32muart:~$ [m[8D[J[00:26:15.105,224] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0003C989[0m
[1;32muart:~$ [m[8D[J[00:26:15.105,255] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x00040D25[0m
[1;32muart:~$ [m[8D[J[00:26:15.105,285] [0m<dbg> lte_lc: event_handler_list_dispatch:  - handler=0x0001A8A5[0m
[1;32muart:~$ [m[8D[J[00:26:15.105,316] [0m<dbg> lte_lc: event_handler_list_dispatch: Done[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:26:15.150,085] [0m<dbg> net_lwm2m_rd_client: do_registration_reply_cb: Registration callback (code:2.1)[0m
[1;32muart:~$ [m[8D[J[00:26:15.150,909] [0m<dbg> lte_lc: parse_psm: TAU: 3240 sec, active time: -1 sec[0m
[1;32muart:~$ [m[8D[J[00:26:15.150,970] [0m<dbg> lte_lc: lte_lc_psm_get: TAU: 3240 sec, active time: -1 sec[0m
[1;32muart:~$ [m[8D[J[00:26:15.151,000] [0m<dbg> lwm2m_sec_con_man: lwm2m_utils_update_rptau: PSM deactivated[0m
[1;32muart:~$ [m[8D[J[00:26:15.151,000] [0m<dbg> app_lwm2m_client: rd_client_event: Registration complete[0m
[1;32muart:~$ [m[8D[J[00:26:15.151,153] [0m<inf> net_lwm2m_rd_client: Registration Done (EP='XXXXXXX')[0m
[1;32muart:~$ [m[8D[J[00:26:15.151,336] [0m<dbg> net_lwm2m_message_handling: lwm2m_udp_receive: reply 0x2000d7c0 handled and removed[0m
[1;32muart:~$ [m[8D[J[00:26:15.151,397] [0m<dbg> net_lwm2m_rd_client: lwm2m_rd_client_service: State: 9[0m
[1;32muart:~$ [m[8D[J[00:26:15.236,083] [0m<inf> app_lwm2m_client: LwM2M is connected to server[0m
[1;32muart:~$ [m[8D[J[00:26:15.236,145] [0m<dbg> date_time: date_time_update_thread: Updating date time UTC...[0m
[1;32muart:~$ [m[8D[J[00:26:15.236,175] [0m<dbg> date_time: date_time_update_thread: Using previously obtained time[0m
[1;32muart:~$ [m[8D[J[00:26:15.236,206] [0m<inf> app_lwm2m_client: Obtained date-time from modem[0m
[1;32muart:~$ [m[8D[J[00:26:15.236,236] [0m<dbg> net_lwm2m_registry: lwm2m_engine_set: path:3/0/13, buf:0x2003275c, len:4[0m
[1;32muart:~$ [m[8D[J[1;32muart:~$ [m[8D[J[00:26:17.922,058] [0m<dbg> net_lwm2m_observation: engine_observe_node_init: OBSERVER ADDED 10351/0/50/0(3)[0m
[1;32muart:~$ [m[8D[J[00:26:17.922,149] [0m<dbg> net_lwm2m_observation: engine_observe_node_init: token:'afd3250c8d52644c' addr:<MY_IP>[0m
[1;32muart:~$ [m[8D[J[00:26:17.922,180] [0m<dbg> net_lwm2m_registry: lwm2m_engine_set: path:10351/0/50, buf:0x20031e9f, len:1[0m

After Registration update failure! we see lwm2m_utils_update_rptau: PSM deactivated. Our assumption is that in this situation the board previously went into LTE_OFFLINE and stayed offline.

It seems like we are making some progress here!

0 lobaro-theo 26 days ago in reply to Matias Marti

I opened a new private ticket. But before I discovered that there is no dependency for this problem to the nrf_modem. It does not matter.
Cancel
Vote Up 0 Vote Down

Sign in to reply

Verify Answer

Cancel

0 Matias Marti 11 hours ago in reply to dejans

dejans said:
Have you tried changing the value directly in the code?

dejans SeppoTakalo

We have now tried changing the value directly in the sdk, and this is how the logs look now:

[00:01:03.867,492] <inf> app_lwm2m_client: LwM2M is connected to server
[00:01:03.867,584] <inf> app_lwm2m_client: Obtained date-time from modem
[00:01:22.783,782] <dbg> app_lwm2m_client: rd_client_event: Registration update started
[00:01:27.884,124] <dbg> app_lwm2m_client: rd_client_event: Registration update failure!
[00:01:27.891,876] <inf> net_lwm2m_rd_client: RD Client started with endpoint '<MY_ENDPOINT>' with client lifetime 86400 using server object 0
[00:01:29.245,269] <inf> net_lwm2m_engine: Connected, sock id 2
[00:01:29.248,382] <dbg> app_lwm2m_client: rd_client_event: Disconnected
[00:01:29.248,504] <inf> net_lwm2m_rd_client: Stop LWM2M Client: <MY_ENDPOINT>
[00:01:29.334,838] <inf> app_lwm2m_client: Client connect to server
[00:01:29.334,869] <inf> net_lwm2m_rd_client: Start LWM2M Client: <MY_ENDPOINT>
[00:01:29.335,540] <inf> net_lwm2m_rd_client: RD Client started with endpoint '<MY_ENDPOINT>' with client lifetime 86400 using server object 0
[00:01:29.460,998] <inf> app_lwm2m_client: LwM2M is connecting to server
[00:01:29.632,720] <inf> net_lwm2m_engine: Connected, sock id 2
[00:01:29.785,278] <dbg> app_lwm2m_client: rd_client_event: Registration complete
[00:01:29.785,430] <inf> net_lwm2m_rd_client: Registration Done (EP='xxxx')
[00:01:29.868,164] <inf> app_lwm2m_client: LwM2M is connected to server
[00:01:29.868,225] <inf> app_lwm2m_client: Obtained date-time from modem
[00:01:48.784,393] <dbg> app_lwm2m_client: rd_client_event: Registration update started
[00:01:53.886,108] <dbg> app_lwm2m_client: rd_client_event: Registration update failure!
[00:01:53.893,859] <inf> net_lwm2m_rd_client: RD Client started with endpoint '<MY_ENDPOINT>' with client lifetime 86400 using server object 0
[00:01:55.007,781] <inf> net_lwm2m_engine: Connected, sock id 2
[00:01:55.010,894] <dbg> app_lwm2m_client: rd_client_event: Disconnected
[00:01:55.011,016] <inf> net_lwm2m_rd_client: Stop LWM2M Client: <MY_ENDPOINT>
[00:01:55.097,839] <inf> app_lwm2m_client: Client connect to server
[00:01:55.097,900] <inf> net_lwm2m_rd_client: Start LWM2M Client: <MY_ENDPOINT>
[00:01:55.098,541] <inf> net_lwm2m_rd_client: RD Client started with endpoint '<MY_ENDPOINT>' with client lifetime 86400 using server object 0
[00:01:55.223,052] <inf> app_lwm2m_client: LwM2M is connecting to server
[00:01:55.398,132] <inf> net_lwm2m_engine: Connected, sock id 2
[00:01:55.553,161] <dbg> app_lwm2m_client: rd_client_event: Registration complete
[00:01:55.553,314] <inf> net_lwm2m_rd_client: Registration Done (EP='xxxx')

We forced this error by making our Leshan server unresponsive. With the usual code, the failure log shows up 4min7s after the registration update starts. Now, by changing the exchange timeout for this specific message, the code behaves as we want to:

case ENGINE_UPDATE_SENT:
	/* wait update to be done or abort */
	timeout = EXCHANGE_LIFETIME;
	break;

We set the value to 5s, and the board starts to reregister after 5s instead of after 247s.

This is exactly how we want the board to behave. Is there any other way to declare the exchange timeouts? We do not want to fork the whole Github repo and make our customizations.

Should we create an issue and/or PR on Github for the sdk?

Again, thank you for you help.