Hello,
I am creating this Post to summarize all my findings regarding a problem with the SLM Application that multiple people are experiencing, in order to make it easier to keep track of the problem and eventually fix it.
The symptoms of the Problem are, that if the SLM application is used with the Zephyr Modem driver for the SLM, Deregistrations cause the device to never be able to reconnect again. This does not happen all the time and is hard to reproduce, because signal loss is most of the time needed to provoke it.
To my current knowledge this Problem consists of multiple Issues, one of them being that the cmux channels get swapped on start and ppp stoppage. the logic here is not failsafe, and in fact, fails more often than it works. This causes a mismatch of cmux channels between the Modem Driver and the SLM, causing the log message "chat_script_timed_out" to repeat indefinitely. Another Problem is, that sometimes it seems the Line termination (\r\n) is not received correctly by the nRF91, also causing problems.
I have logs that show all these Problems, that I will share here:
[02:06:42.626,007] <dbg> modem_chat: modem_chat_log_received_command: +CEREG: 1 5 00> [02:06:42.626,068] <dbg> modem_chat: modem_chat_log_received_command: OK 00> [02:06:42.626,098] <dbg> modem_chat: modem_chat_script_stop: nordic_nrf91_slm_periodic_chat_script: complete 00> [02:06:42.626,190] <dbg> modem_cellular: modem_cellular_log_event: event registered 00> [02:06:42.626,220] <dbg> modem_cellular: modem_cellular_log_event: event script success 00> [02:06:44.626,373] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:06:44.626,495] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:06:44.626,525] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:06:44.626,556] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:06:44.626,617] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:44.626,647] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:06:44.626,708] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:44.626,739] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:06:44.669,769] <dbg> modem_cmux: modem_cmux_log_received_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:44.669,799] <dbg> modem_cmux: modem_cmux_log_received_frame: data: 00> 0d 0a 2b 43 45 52 45 47 3a 20 31 2c 35 0d 0a 0d |..+CEREG : 1,5... 00> 0a 4f 4b 0d 0a |.OK.. 00> [02:06:44.669,982] <dbg> modem_chat: modem_chat_log_received_command: +CEREG: 1 5 00> [02:06:44.670,043] <dbg> modem_chat: modem_chat_log_received_command: OK 00> [02:06:44.670,074] <dbg> modem_chat: modem_chat_script_stop: nordic_nrf91_slm_periodic_chat_script: complete 00> [02:06:44.670,166] <dbg> modem_cellular: modem_cellular_log_event: event registered 00> [02:06:44.670,196] <dbg> modem_cellular: modem_cellular_log_event: event script success 00> [02:06:46.670,349] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:06:46.670,410] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:06:46.670,440] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:06:46.670,532] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:06:46.671,447] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:46.671,478] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:06:46.671,539] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:46.671,569] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:06:46.714,233] <dbg> modem_cmux: modem_cmux_log_received_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:46.714,233] <dbg> modem_cmux: modem_cmux_log_received_frame: data: 00> 0d 0a 2b 43 45 52 45 47 3a 20 31 2c 35 0d 0a 0d |..+CEREG : 1,5... 00> 0a 4f 4b 0d 0a |.OK.. 00> [02:06:46.714,416] <dbg> modem_chat: modem_chat_log_received_command: +CEREG: 1 5 00> [02:06:46.714,508] <dbg> modem_chat: modem_chat_log_received_command: OK 00> [02:06:46.714,508] <dbg> modem_chat: modem_chat_script_stop: nordic_nrf91_slm_periodic_chat_script: complete 00> [02:06:46.714,630] <dbg> modem_cellular: modem_cellular_log_event: event registered 00> [02:06:46.714,660] <dbg> modem_cellular: modem_cellular_log_event: event script success 00> [02:06:48.714,782] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:06:48.714,843] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:06:48.714,874] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:06:48.714,904] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:06:48.714,996] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:48.714,996] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:06:48.715,148] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:48.715,179] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:06:48.757,781] <dbg> modem_cmux: modem_cmux_log_received_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:48.757,812] <dbg> modem_cmux: modem_cmux_log_received_frame: data: 00> 0d 0a 2b 43 45 52 45 47 3a 20 31 2c 35 0d 0a 0d |..+CEREG : 1,5... 00> 0a 4f 4b 0d 0a |.OK.. 00> [02:06:48.757,995] <dbg> modem_chat: modem_chat_log_received_command: +CEREG: 1 5 00> [02:06:48.758,056] <dbg> modem_chat: modem_chat_log_received_command: OK 00> [02:06:48.758,087] <dbg> modem_chat: modem_chat_script_stop: nordic_nrf91_slm_periodic_chat_script: complete 00> [02:06:48.758,178] <dbg> modem_cellular: modem_cellular_log_event: event registered 00> [02:06:48.758,209] <dbg> modem_cellular: modem_cellular_log_event: event script success 00> [02:06:50.758,361] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:06:50.758,422] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:06:50.758,453] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:06:50.758,483] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:06:50.758,575] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:50.758,575] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:06:50.758,666] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:50.758,697] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:06:50.801,788] <dbg> modem_cmux: modem_cmux_log_received_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:50.801,818] <dbg> modem_cmux: modem_cmux_log_received_frame: data: 00> 0d 0a 2b 43 45 52 45 47 3a 20 31 2c 35 0d 0a 0d |..+CEREG : 1,5... 00> 0a 4f 4b 0d 0a |.OK.. 00> [02:06:50.802,062] <dbg> modem_chat: modem_chat_log_received_command: +CEREG: 1 5 00> [02:06:50.802,124] <dbg> modem_chat: modem_chat_log_received_command: OK 00> [02:06:50.802,154] <dbg> modem_chat: modem_chat_script_stop: nordic_nrf91_slm_periodic_chat_script: complete 00> [02:06:50.802,459] <dbg> modem_cellular: modem_cellular_log_event: event registered 00> [02:06:50.802,490] <dbg> modem_cellular: modem_cellular_log_event: event script success 00> [02:06:52.498,779] <dbg> modem_cmux: modem_cmux_log_received_frame: ch:1,cr:1,pf:0,type:UIH 00> [02:06:52.498,809] <dbg> modem_cmux: modem_cmux_log_received_frame: data: 00> 0d 0a |.. 00> [02:06:52.498,901] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0xff was expected. 00> [02:06:52.498,931] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0a because 0x7e was expected. 00> [02:06:52.500,274] <dbg> modem_cmux: modem_cmux_log_received_frame: ch:1,cr:1,pf:0,type:UIH 00> [02:06:52.500,305] <dbg> modem_cmux: modem_cmux_log_received_frame: data: 00> 2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2.. 00> [02:06:52.500,366] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2b because 0x7e was expected. 00> [02:06:52.500,396] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x43 because 0x7e was expected. 00> [02:06:52.500,396] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x45 because 0x7e was expected. 00> [02:06:52.500,427] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x52 because 0x7e was expected. 00> [02:06:52.500,457] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x45 because 0x7e was expected. 00> [02:06:52.500,457] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x47 because 0x7e was expected. 00> [02:06:52.500,457] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x3a because 0x7e was expected. 00> [02:06:52.500,488] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x20 because 0x7e was expected. 00> [02:06:52.500,488] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x32 because 0x7e was expected. 00> [02:06:52.500,518] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0x7e was expected. 00> [02:06:52.500,518] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0a because 0x7e was expected. 00> [02:06:52.802,642] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:06:52.802,703] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:06:52.802,734] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:06:52.802,764] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:06:52.802,856] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:52.802,856] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:06:52.802,947] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:52.802,978] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:06:54.653,167] <dbg> modem_cmux: modem_cmux_log_received_frame: ch:1,cr:1,pf:0,type:UIH 00> [02:06:54.653,228] <dbg> modem_cmux: modem_cmux_log_received_frame: data: 00> 0d 0a |.. 00> [02:06:54.653,320] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0x7e was expected. 00> [02:06:54.653,320] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0a because 0x7e was expected. 00> [02:06:54.655,212] <dbg> modem_cmux: modem_cmux_log_received_frame: ch:1,cr:1,pf:0,type:UIH 00> [02:06:54.655,242] <dbg> modem_cmux: modem_cmux_log_received_frame: data: 00> 2b 43 4e 45 43 5f 45 53 4d 3a 20 35 30 2c 30 0d |+CNEC_ES M: 50,0. 00> 0a |. 00> [02:06:54.655,303] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2b because 0x7e was expected. 00> [02:06:54.655,334] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x43 because 0x7e was expected. 00> [02:06:54.655,334] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x4e because 0x7e was expected. 00> [02:06:54.655,364] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x45 because 0x7e was expected. 00> [02:06:54.655,395] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x43 because 0x7e was expected. 00> [02:06:54.655,395] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x5f because 0x7e was expected. 00> [02:06:54.655,395] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x45 because 0x7e was expected. 00> [02:06:54.655,426] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x53 because 0x7e was expected. 00> [02:06:54.655,426] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x4d because 0x7e was expected. 00> [02:06:54.655,456] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x3a because 0x7e was expected. 00> [02:06:54.655,456] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x20 because 0x7e was expected. 00> [02:06:54.655,487] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x35 because 0x7e was expected. 00> [02:06:54.655,487] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x30 because 0x7e was expected. 00> [02:06:54.655,517] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2c because 0x7e was expected. 00> [02:06:54.655,517] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x30 because 0x7e was expected. 00> [02:06:54.655,548] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0x7e was expected. 00> [02:06:54.655,548] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0a because 0x7e was expected. 00> [02:06:54.753,814] <dbg> modem_cmux: modem_cmux_log_received_frame: ch:1,cr:1,pf:0,type:UIH 00> [02:06:54.753,875] <dbg> modem_cmux: modem_cmux_log_received_frame: data: 00> 0d 0a |.. 00> [02:06:54.753,967] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0x7e was expected. 00> [02:06:54.753,967] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0a because 0x7e was expected. 00> [02:06:54.755,310] <dbg> modem_cmux: modem_cmux_log_received_frame: ch:1,cr:1,pf:0,type:UIH 00> [02:06:54.755,340] <dbg> modem_cmux: modem_cmux_log_received_frame: data: 00> 2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5.. 00> [02:06:54.756,530] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2b because 0x7e was expected. 00> [02:06:54.756,561] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x43 because 0x7e was expected. 00> [02:06:54.756,561] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x45 because 0x7e was expected. 00> [02:06:54.756,591] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x52 because 0x7e was expected. 00> [02:06:54.756,622] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x45 because 0x7e was expected. 00> [02:06:54.756,622] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x47 because 0x7e was expected. 00> [02:06:54.756,652] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x3a because 0x7e was expected. 00> [02:06:54.756,652] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x20 because 0x7e was expected. 00> [02:06:54.756,683] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x35 because 0x7e was expected. 00> [02:06:54.756,713] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0x7e was expected. 00> [02:06:54.756,713] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0a because 0x7e was expected. 00> [02:06:54.756,805] <dbg> modem_cmux: modem_cmux_log_received_frame: ch:1,cr:1,pf:0,type:UIH 00> [02:06:54.756,866] <dbg> modem_cmux: modem_cmux_log_received_frame: data: 00> 0d 0a |.. 00> [02:06:54.756,958] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0x7e was expected. 00> [02:06:54.756,958] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0a because 0x7e was expected. 00> [02:06:54.759,704] <dbg> modem_cmux: modem_cmux_log_received_frame: ch:1,cr:1,pf:0,type:UIH 00> [02:06:54.759,735] <dbg> modem_cmux: modem_cmux_log_received_frame: data: 00> 25 58 54 49 4d 45 3a 20 22 38 30 22 2c 22 34 32 |%XTIME: "80","42 00> 39 30 35 30 32 32 31 30 32 35 38 30 22 2c 22 30 |90502210 2580","0 00> 31 22 0d 0a |1".. 00> [02:06:54.759,826] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x25 because 0x7e was expected. 00> [02:06:54.759,857] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x58 because 0x7e was expected. 00> [02:06:54.759,857] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x54 because 0x7e was expected. 00> [02:06:54.759,857] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x49 because 0x7e was expected. 00> [02:06:54.759,887] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x4d because 0x7e was expected. 00> [02:06:54.759,887] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x45 because 0x7e was expected. 00> [02:06:54.759,918] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x3a because 0x7e was expected. 00> [02:06:54.759,918] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x20 because 0x7e was expected. 00> [02:06:54.759,948] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x22 because 0x7e was expected. 00> [02:06:54.759,948] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x38 because 0x7e was expected. 00> [02:06:54.759,979] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x30 because 0x7e was expected. 00> [02:06:54.759,979] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x22 because 0x7e was expected. 00> [02:06:54.760,009] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2c because 0x7e was expected. 00> [02:06:54.760,009] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x22 because 0x7e was expected. 00> [02:06:54.760,040] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x34 because 0x7e was expected. 00> [02:06:54.760,040] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x32 because 0x7e was expected. 00> [02:06:54.760,040] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x39 because 0x7e was expected. 00> [02:06:54.760,070] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x30 because 0x7e was expected. 00> [02:06:54.760,070] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x35 because 0x7e was expected. 00> [02:06:54.760,101] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x30 because 0x7e was expected. 00> [02:06:54.760,101] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x32 because 0x7e was expected. 00> [02:06:54.760,131] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x32 because 0x7e was expected. 00> [02:06:54.760,131] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x31 because 0x7e was expected. 00> [02:06:54.760,162] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x30 because 0x7e was expected. 00> [02:06:54.760,162] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x32 because 0x7e was expected. 00> [02:06:54.760,192] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x35 because 0x7e was expected. 00> [02:06:54.760,192] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x38 because 0x7e was expected. 00> [02:06:54.760,192] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x30 because 0x7e was expected. 00> [02:06:54.760,223] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x22 because 0x7e was expected. 00> [02:06:54.760,223] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2c because 0x7e was expected. 00> [02:06:54.760,253] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x22 because 0x7e was expected. 00> [02:06:54.760,253] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x30 because 0x7e was expected. 00> [02:06:54.760,284] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x31 because 0x7e was expected. 00> [02:06:54.760,284] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x22 because 0x7e was expected. 00> [02:06:54.760,314] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0x7e was expected. 00> [02:06:54.760,314] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0a because 0x7e was expected. 00> [02:06:56.802,856] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:06:56.802,947] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:06:57.498,992] <dbg> modem_cmux: modem_cmux_log_received_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:57.499,023] <dbg> modem_cmux: modem_cmux_log_received_frame: data: 00> 7e ff 7d 23 c0 21 7d 25 7d 24 7d 20 7d 24 80 fe |~.}#.!}% }$} }$.. 00> 7e |~ 00> [02:06:58.803,070] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:06:58.803,131] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:06:58.803,161] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:06:58.803,192] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:06:58.803,283] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:58.803,283] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:06:58.803,375] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:06:58.803,405] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:07:02.803,283] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:07:02.803,375] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:07:04.803,497] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:07:04.803,558] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:07:04.803,588] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:07:04.803,619] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:07:04.803,710] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:04.803,710] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:07:04.803,802] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:04.803,833] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:07:08.803,710] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:07:08.803,863] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:07:10.803,985] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:07:10.804,046] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:07:10.804,077] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:07:10.804,107] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:07:10.804,199] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:10.804,199] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:07:10.804,290] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:10.804,321] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:07:14.804,199] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:07:14.804,290] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:07:16.804,412] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:07:16.804,473] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:07:16.804,504] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:07:16.804,534] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:07:16.804,626] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:16.804,626] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:07:16.804,718] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:16.804,748] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:07:20.804,626] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:07:20.804,718] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:07:22.804,840] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:07:22.804,901] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:07:22.804,931] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:07:22.804,962] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:07:22.805,053] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:22.805,053] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:07:22.805,145] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:22.805,175] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:07:26.805,053] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:07:26.805,145] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:07:28.805,999] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:07:28.806,060] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:07:28.806,091] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:07:28.806,121] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:07:28.806,213] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:28.806,243] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:07:28.806,304] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:28.806,335] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:07:32.806,213] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:07:32.806,304] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:07:34.806,427] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:07:34.806,488] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:07:34.806,518] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:07:34.806,549] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:07:34.806,640] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:34.806,640] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:07:34.806,732] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:34.806,762] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:07:38.806,640] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:07:38.806,732] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:07:40.806,854] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:07:40.806,915] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:07:40.806,945] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:07:40.806,976] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:07:40.807,067] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:40.807,067] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:07:40.807,159] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:40.807,189] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:07:44.807,067] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:07:44.807,159] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:07:46.807,281] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:07:46.807,434] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:07:46.807,464] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:07:46.807,495] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:07:46.807,556] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:46.807,586] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:07:46.807,647] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:46.807,678] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:07:50.807,556] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:07:50.807,647] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:07:52.807,769] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:07:52.807,830] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:07:52.807,861] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:07:52.807,891] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:07:52.807,983] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:52.807,983] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:07:52.808,074] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:52.808,105] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:07:56.807,983] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:07:56.808,074] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:07:58.808,197] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:07:58.808,319] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:07:58.808,349] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:07:58.808,380] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:07:58.809,326] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:58.809,417] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:07:58.809,478] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:07:58.809,509] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:08:02.808,471] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:08:02.808,563] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:08:04.809,020] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:08:04.809,082] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:08:04.809,112] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:08:04.809,143] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:08:04.809,234] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:04.809,265] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:08:04.809,326] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:04.809,356] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:08:08.809,234] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:08:08.809,356] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:08:10.809,509] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:08:10.809,570] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:08:10.809,600] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:08:10.809,631] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:08:10.809,722] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:10.809,753] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:08:10.809,814] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:10.809,844] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:08:14.809,722] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:08:14.809,814] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:08:16.809,936] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:08:16.809,997] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:08:16.810,028] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:08:16.810,058] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:08:16.810,150] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:16.810,180] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:08:16.810,241] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:16.810,272] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:08:20.810,150] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:08:20.810,241] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:08:22.810,363] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:08:22.810,424] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:08:22.810,455] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:08:22.810,485] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:08:22.810,577] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:22.810,607] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:08:22.810,668] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:22.810,699] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:08:26.810,577] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:08:26.810,668] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:08:28.810,791] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:08:28.810,852] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:08:28.810,882] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:08:28.810,913] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:08:28.811,004] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:28.811,035] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:08:28.811,096] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:28.811,126] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:08:32.811,004] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:08:32.811,096] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:08:34.811,218] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:08:34.811,279] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:08:34.811,309] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:08:34.811,340] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:08:34.811,431] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:34.811,431] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:08:34.811,523] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:34.811,553] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:08:38.811,431] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:08:38.811,523] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:08:40.811,645] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:08:40.811,706] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:08:40.811,737] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:08:40.811,767] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:08:40.811,859] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:40.811,859] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:08:40.811,950] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:40.811,981] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:08:44.811,859] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:08:44.811,950] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:08:46.812,072] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:08:46.812,133] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:08:46.812,164] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:08:46.812,194] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:08:46.812,286] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:46.812,286] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:08:46.812,377] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:46.812,408] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:08:50.812,347] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:08:50.812,438] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:08:52.812,561] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:08:52.812,622] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:08:52.812,652] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:08:52.812,683] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:08:52.812,805] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:52.812,835] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:08:52.812,896] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:52.812,927] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:08:56.812,805] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:08:56.812,866] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:08:58.812,988] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:08:58.813,049] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:08:58.813,079] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:08:58.813,110] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:08:58.813,201] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:58.813,201] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:08:58.813,293] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:08:58.813,323] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:09:02.813,385] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:09:02.813,476] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:09:04.813,598] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:09:04.813,659] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:09:04.813,690] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:09:04.813,720] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:09:04.813,812] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:09:04.813,842] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:09:04.813,903] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:09:04.813,934] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:09:08.813,812] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:09:08.813,903] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:09:10.814,025] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:09:10.814,086] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:09:10.814,117] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:09:10.814,147] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:09:10.814,239] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:09:10.814,239] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:09:10.814,331] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:09:10.814,361] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:09:14.814,239] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:09:14.814,331] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:09:16.814,453] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:09:16.814,514] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:09:16.814,544] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:09:16.814,575] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:09:16.814,666] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:09:16.814,697] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:09:16.814,758] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:09:16.814,788] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:09:20.815,460] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:09:20.815,551] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:09:22.815,673] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:09:22.815,734] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:09:22.815,765] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:09:22.815,795] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:09:22.815,887] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:09:22.815,887] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:09:22.815,979] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:09:22.816,009] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:09:26.815,887] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out 00> [02:09:26.815,979] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> [02:09:28.816,101] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> [02:09:28.816,162] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_periodic_chat_script 00> [02:09:28.816,192] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_periodic_chat_script: step: 0 00> [02:09:28.816,223] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG? 00> [02:09:28.816,314] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:09:28.816,345] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:09:28.816,406] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH 00> [02:09:28.816,436] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data: 00> 0d 0a |.. 00> [02:09:32.816,314] <wrn> modem_chat: nordic_nrf91_slm_periodic_chat_script: timed out
00> [02:06:31.484,130] <dbg> slm_at_host: cmd_send: RX 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:06:31.490,722] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a 2b 43 45 52 45 47 3a 20 31 2c 35 0d 0a 0d |..+CEREG : 1,5... 00> 0a 4f 4b 0d 0a |.OK.. 00> [02:06:33.528,198] <dbg> slm_at_host: cmd_send: RX 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:06:33.534,790] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a 2b 43 45 52 45 47 3a 20 31 2c 35 0d 0a 0d |..+CEREG : 1,5... 00> 0a 4f 4b 0d 0a |.OK.. 00> [02:06:35.572,265] <dbg> slm_at_host: cmd_send: RX 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:06:35.578,857] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a 2b 43 45 52 45 47 3a 20 31 2c 35 0d 0a 0d |..+CEREG : 1,5... 00> 0a 4f 4b 0d 0a |.OK.. 00> [02:06:37.616,333] <dbg> slm_at_host: cmd_send: RX 00> 41 54 2b 43 45 52 45 47 3f |AT+CEREG ? 00> [02:06:37.622,924] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a 2b 43 45 52 45 47 3a 20 31 2c 35 0d 0a 0d |..+CEREG : 1,5... 00> 0a 4f 4b 0d 0a |.OK.. 00> [02:06:39.263,275] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 5 received. 00> [02:06:39.320,098] <dbg> slm_ppp: ppp_stop: Stopping PPP... 00> [02:06:39.320,556] <inf> slm_ppp: PPP stopped. 00> [02:06:39.320,648] <dbg> slm_ppp: pdp_ctx_event_handler: Connection down. 00> [02:06:39.320,892] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [02:06:39.320,953] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2.. 00> [02:06:39.321,319] <dbg> slm_ppp: ppp_net_mgmt_event_handler: Peer not connected. 00> [02:06:39.660,308] <wrn> slm_cmux: Discarding 9 bytes received on non-AT DLCI 2. 00> [02:06:39.660,430] <wrn> slm_cmux: Discarding 2 bytes received on non-AT DLCI 2. 00> [02:06:41.475,524] <inf> slm_ppp: Connection up. Starting PPP. 00> [02:06:41.475,982] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [02:06:41.476,043] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 4e 45 43 5f 45 53 4d 3a 20 35 30 2c 30 0d |+CNEC_ES M: 50,0. 00> 0a |. 00> [02:06:41.476,074] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 0 received. 00> [02:06:41.576,110] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [02:06:41.576,141] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5.. 00> [02:06:41.576,568] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [02:06:41.576,629] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 25 58 54 49 4d 45 3a 20 22 38 30 22 2c 22 34 32 |%XTIME: "80","42 00> 39 30 35 30 32 32 31 30 32 35 38 30 22 2c 22 30 |90502210 2580","0 00> 31 22 0d 0a |1".. 00> [02:06:41.678,039] <dbg> slm_ppp: ppp_start: MTU set to 1430. 00> [02:06:41.678,466] <inf> slm_ppp: PPP started. 00> [02:06:49.320,617] <dbg> slm_ppp: ppp_net_mgmt_event_handler: Peer not connected. 00> [04:11:53.140,838] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 5 received. 00> [04:11:53.194,549] <dbg> slm_ppp: ppp_stop: Stopping PPP... 00> [04:11:53.194,885] <inf> slm_ppp: PPP stopped. 00> [04:11:53.195,068] <dbg> slm_ppp: pdp_ctx_event_handler: Connection down. 00> [04:11:53.295,135] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [04:11:53.295,196] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2.. 00> [04:11:56.710,174] <inf> slm_ppp: Connection up. Starting PPP. 00> [04:11:56.710,571] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [04:11:56.710,632] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 4e 45 43 5f 45 53 4d 3a 20 35 30 2c 30 0d |+CNEC_ES M: 50,0. 00> 0a |. 00> [04:11:56.710,693] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 0 received. 00> [04:11:56.810,729] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [04:11:56.810,791] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5.. 00> [04:11:56.811,187] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [04:11:56.811,248] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 25 58 54 49 4d 45 3a 20 22 38 30 22 2c 22 34 32 |%XTIME: "80","42 00> 39 30 36 30 30 30 37 30 37 30 38 30 22 2c 22 30 |90600070 7080","0 00> 31 22 0d 0a |1".. 00> [04:11:56.912,567] <dbg> slm_ppp: ppp_start: MTU set to 1430. 00> [04:11:56.913,543] <inf> slm_ppp: PPP started. 00> [04:13:36.916,290] <dbg> slm_ppp: ppp_net_mgmt_event_handler: Peer not connected. 00> [06:17:07.015,716] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 5 received. 00> [06:17:07.069,458] <dbg> slm_ppp: ppp_stop: Stopping PPP... 00> [06:17:07.069,763] <inf> slm_ppp: PPP stopped. 00> [06:17:07.069,976] <dbg> slm_ppp: pdp_ctx_event_handler: Connection down. 00> [06:17:07.170,013] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [06:17:07.170,074] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2.. 00> [06:17:11.065,063] <inf> slm_ppp: Connection up. Starting PPP. 00> [06:17:11.065,490] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [06:17:11.065,551] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 4e 45 43 5f 45 53 4d 3a 20 35 30 2c 30 0d |+CNEC_ES M: 50,0. 00> 0a |. 00> [06:17:11.065,612] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 0 received. 00> [06:17:11.165,649] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [06:17:11.165,710] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5.. 00> [06:17:11.166,107] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [06:17:11.166,168] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 25 58 54 49 4d 45 3a 20 22 38 30 22 2c 22 34 32 |%XTIME: "80","42 00> 39 30 36 30 32 30 32 31 31 32 38 30 22 2c 22 30 |90602021 1280","0 00> 31 22 0d 0a |1".. 00> [06:17:11.267,486] <dbg> slm_ppp: ppp_start: MTU set to 1430. 00> [06:17:11.268,463] <inf> slm_ppp: PPP started. 00> [06:18:51.271,179] <dbg> slm_ppp: ppp_net_mgmt_event_handler: Peer not connected. 00> [08:22:10.648,925] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 5 received. 00> [08:22:10.703,613] <dbg> slm_ppp: ppp_stop: Stopping PPP... 00> [08:22:10.703,948] <inf> slm_ppp: PPP stopped. 00> [08:22:10.704,132] <dbg> slm_ppp: pdp_ctx_event_handler: Connection down. 00> [08:22:10.804,199] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [08:22:10.804,260] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2.. 00> [08:22:12.136,199] <wrn> slm_cmux: Discarding 9 bytes received on non-AT DLCI 2. 00> [08:22:12.136,322] <wrn> slm_cmux: Discarding 2 bytes received on non-AT DLCI 2. 00> [08:22:13.268,280] <inf> slm_ppp: Connection up. Starting PPP. 00> [08:22:13.268,463] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [08:22:13.268,524] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 4e 45 43 5f 45 53 4d 3a 20 35 30 2c 30 0d |+CNEC_ES M: 50,0. 00> 0a |. 00> [08:22:13.268,585] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 0 received. 00> [08:22:13.269,073] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [08:22:13.269,134] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5.. 00> [08:22:13.270,843] <dbg> slm_ppp: ppp_start: MTU set to 1430. 00> [08:22:13.271,759] <inf> slm_ppp: PPP started. 00> [08:22:13.305,084] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [08:22:13.305,145] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 25 58 54 49 4d 45 3a 20 22 38 30 22 2c 22 34 32 |%XTIME: "80","42 00> 39 30 36 30 34 30 37 31 33 32 38 30 22 2c 22 30 |90604071 3280","0 00> 31 22 0d 0a |1".. 00> [08:23:53.274,383] <dbg> slm_ppp: ppp_net_mgmt_event_handler: Peer not connected. 00> [10:27:14.284,698] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 5 received. 00> [10:27:14.338,470] <dbg> slm_ppp: ppp_stop: Stopping PPP... 00> [10:27:14.338,775] <inf> slm_ppp: PPP stopped. 00> [10:27:14.338,989] <dbg> slm_ppp: pdp_ctx_event_handler: Connection down. 00> [10:27:14.439,056] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [10:27:14.439,117] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2.. 00> [10:27:16.414,001] <inf> slm_ppp: Connection up. Starting PPP. 00> [10:27:16.414,428] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [10:27:16.414,489] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 4e 45 43 5f 45 53 4d 3a 20 35 30 2c 30 0d |+CNEC_ES M: 50,0. 00> 0a |. 00> [10:27:16.414,520] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 0 received. 00> [10:27:16.514,617] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [10:27:16.514,678] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5.. 00> [10:27:16.515,075] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [10:27:16.515,136] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 25 58 54 49 4d 45 3a 20 22 38 30 22 2c 22 34 32 |%XTIME: "80","42 00> 39 30 36 30 36 30 32 32 36 32 38 30 22 2c 22 30 |90606022 6280","0 00> 31 22 0d 0a |1".. 00> [10:27:16.616,424] <dbg> slm_ppp: ppp_start: MTU set to 1430. 00> [10:27:16.617,431] <inf> slm_ppp: PPP started. 00> [10:28:56.620,056] <dbg> slm_ppp: ppp_net_mgmt_event_handler: Peer not connected. 00> [12:32:17.917,846] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 5 received. 00> [12:32:17.974,609] <dbg> slm_ppp: ppp_stop: Stopping PPP... 00> [12:32:17.974,914] <inf> slm_ppp: PPP stopped. 00> [12:32:17.975,097] <dbg> slm_ppp: pdp_ctx_event_handler: Connection down. 00> [12:32:18.075,164] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [12:32:18.075,225] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2.. 00> [12:32:19.774,108] <wrn> slm_cmux: Discarding 9 bytes received on non-AT DLCI 2. 00> [12:32:19.774,230] <wrn> slm_cmux: Discarding 2 bytes received on non-AT DLCI 2. 00> [12:32:20.690,124] <inf> slm_ppp: Connection up. Starting PPP. 00> [12:32:20.690,551] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [12:32:20.690,612] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 4e 45 43 5f 45 53 4d 3a 20 35 30 2c 30 0d |+CNEC_ES M: 50,0. 00> 0a |. 00> [12:32:20.690,643] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 0 received. 00> [12:32:20.790,679] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [12:32:20.790,771] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5.. 00> [12:32:20.791,168] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [12:32:20.791,229] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 25 58 54 49 4d 45 3a 20 22 38 30 22 2c 22 34 32 |%XTIME: "80","42 00> 39 30 36 30 38 30 37 32 30 33 38 30 22 2c 22 30 |90608072 0380","0 00> 31 22 0d 0a |1".. 00> [12:32:20.892,639] <dbg> slm_ppp: ppp_start: MTU set to 1430. 00> [12:32:20.893,463] <inf> slm_ppp: PPP started. 00> [12:34:00.896,118] <dbg> slm_ppp: ppp_net_mgmt_event_handler: Peer not connected. 00> [14:37:22.836,273] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 5 received. 00> [14:37:22.889,984] <dbg> slm_ppp: ppp_stop: Stopping PPP... 00> [14:37:22.890,472] <inf> slm_ppp: PPP stopped. 00> [14:37:22.890,563] <dbg> slm_ppp: pdp_ctx_event_handler: Connection down. 00> [14:37:22.990,570] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [14:37:22.990,631] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2.. 00> [14:37:26.599,822] <wrn> slm_cmux: Discarding 9 bytes received on non-AT DLCI 2. 00> [14:37:26.599,945] <wrn> slm_cmux: Discarding 2 bytes received on non-AT DLCI 2. 00> [14:37:26.886,230] <inf> slm_ppp: Connection up. Starting PPP. 00> [14:37:26.886,627] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [14:37:26.886,688] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 4e 45 43 5f 45 53 4d 3a 20 35 30 2c 30 0d |+CNEC_ES M: 50,0. 00> 0a |. 00> [14:37:26.886,749] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 0 received. 00> [14:37:26.986,724] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [14:37:26.986,785] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5.. 00> [14:37:26.987,426] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [14:37:26.987,487] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 25 58 54 49 4d 45 3a 20 22 38 30 22 2c 22 34 32 |%XTIME: "80","42 00> 39 30 36 30 30 31 32 33 36 33 38 30 22 2c 22 30 |90600123 6380","0 00> 31 22 0d 0a |1".. 00> [14:37:27.088,714] <dbg> slm_ppp: ppp_start: MTU set to 1430. 00> [14:37:27.089,569] <inf> slm_ppp: PPP started. 00> [14:39:07.092,285] <dbg> slm_ppp: ppp_net_mgmt_event_handler: Peer not connected. 00> [16:42:36.708,129] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 5 received. 00> [16:42:36.763,916] <dbg> slm_ppp: ppp_stop: Stopping PPP... 00> [16:42:36.764,221] <inf> slm_ppp: PPP stopped. 00> [16:42:36.764,434] <dbg> slm_ppp: pdp_ctx_event_handler: Connection down. 00> [16:42:36.864,501] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [16:42:36.864,562] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2.. 00> [16:42:39.079,071] <inf> slm_ppp: Connection up. Starting PPP. 00> [16:42:39.079,498] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [16:42:39.079,528] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 4e 45 43 5f 45 53 4d 3a 20 35 30 2c 30 0d |+CNEC_ES M: 50,0. 00> 0a |. 00> [16:42:39.079,589] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 0 received. 00> [16:42:39.179,565] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [16:42:39.179,626] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5.. 00> [16:42:39.180,297] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [16:42:39.180,358] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 25 58 54 49 4d 45 3a 20 22 38 30 22 2c 22 34 32 |%XTIME: "80","42 00> 39 30 36 30 32 31 37 33 38 34 38 30 22 2c 22 30 |90602173 8480","0 00> 31 22 0d 0a |1".. 00> [16:42:39.281,585] <dbg> slm_ppp: ppp_start: MTU set to 1430. 00> [16:42:39.282,440] <inf> slm_ppp: PPP started. 00> [16:44:19.285,064] <dbg> slm_ppp: ppp_net_mgmt_event_handler: Peer not connected. # Logging stopped @ 06 Sep 2024 14:50:09
These logs show the Problem, where the SLM falls back to cmux channel 1, before the CEREG message is sent, causing the nRF52 to drop the bytes and continue sending AT messages on channel 2, which is no longer an AT channel --> device is not usable until restarted.
If only the nRF91 is restarted, it can lead to this scenario:
nRF52:
[00:09:22.232,452] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data:
41 54 2b 43 45 52 45 47 3f |AT+CEREG ?
rtt:~$ [00:09:22.232,513] <dbg> modem_cmux: modem_cmux_log_transmit_frame: ch:2,cr:1,pf:0,type:UIH
rtt:~$ [00:09:22.232,543] <dbg> modem_cmux: modem_cmux_log_transmit_frame: data:
0d 0a |..
nRF91:
[00:00:07.583,984] <dbg> slm_at_host: cmd_send: RX
b7 f9 f9 0b ef 13 41 54 2b 43 45 52 45 47 3f 4f |......AT +CEREG?O
f9 f9 0b ef 05 |.....
[00:00:07.584,045] <err> slm_at_host: AT command syntax invalid: AT+CEREG?O��
�
[00:00:07.584,106] <dbg> slm_at_host: slm_at_send_indicate: TX
0d 0a 45 52 52 4f 52 0d 0a |..ERROR. .
It looks like a communication Problem, where the termination bytes are not correctly received. Only rebooting both devices results in a working state again.
Here another Problem, CEREG: 2 (Deregistration) is received without stopping ppp and without falling back to cmux channel 1, the driver does switch back to ch1 though as it thinks this is the correct behaviour for a deregistration:
nRF 52:
rtt:~$ [00:14:30.724,884] <dbg> modem_cmux: modem_cmux_log_frame: data:
0d 0a 2b 43 45 52 45 47 3a 20 31 2c 35 0d 0a 0d |..+CEREG : 1,5...
0a 4f 4b 0d 0a |.OK..
rtt:~$ [00:14:30.725,036] <dbg> modem_chat: modem_chat_log_received_command: +CEREG: 1 5
rtt:~$ [00:14:30.725,097] <dbg> modem_chat: modem_chat_log_received_command: OK
rtt:~$ [00:14:30.725,128] <dbg> modem_chat: modem_chat_script_stop: nordic_nrf91_slm_periodic_chat_script: complete
rtt:~$ [00:14:30.725,219] <dbg> modem_cellular: modem_cellular_log_event: event registered
rtt:~$ [00:14:30.725,250] <dbg> modem_cellular: modem_cellular_log_event: event script success
rtt:~$ rtt:~$ rtt:~$ [00:14:32.189,025] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:1 pf:0 type:UIH dlen:2
rtt:~$ [00:14:32.189,056] <dbg> modem_cmux: modem_cmux_log_frame: data:
0d 0a |..
rtt:~$ [00:14:32.189,117] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:1 pf:0 type:UIH dlen:11
rtt:~$ [00:14:32.189,147] <dbg> modem_cmux: modem_cmux_log_frame: data:
2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2..
rtt:~$ [00:14:32.189,270] <dbg> modem_chat: modem_chat_log_received_command: +CEREG: 2
rtt:~$ [00:14:32.189,361] <dbg> modem_cellular: modem_cellular_log_event: event deregistered
rtt:~$ [00:14:32.189,483] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from carrier on to run dial script
rtt:~$ [00:14:32.289,550] <dbg> modem_cellular: modem_cellular_log_event: event timeout
rtt:~$ [00:14:32.289,611] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_dial_chat_script
rtt:~$ [00:14:32.289,642] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_dial_chat_script: step: 0
rtt:~$ [00:14:32.289,672] <dbg> modem_chat: modem_chat_script_next: sending: AT+CFUN=4
rtt:~$ [00:14:32.289,764] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:9
rtt:~$ [00:14:32.289,764] <dbg> modem_cmux: modem_cmux_log_frame: data:
41 54 2b 43 46 55 4e 3d 34 |AT+CFUN= 4
rtt:~$ [00:14:32.289,855] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:2
rtt:~$ [00:14:32.289,886] <dbg> modem_cmux: modem_cmux_log_frame: data:
0d 0a |..
rtt:~$ rtt:~$ rtt:~$ [00:14:33.975,891] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:1 pf:0 type:UIH dlen:2
rtt:~$ [00:14:33.975,921] <dbg> modem_cmux: modem_cmux_log_frame: data:
0d 0a |..
rtt:~$ [00:14:33.975,982] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:1 pf:0 type:UIH dlen:11
rtt:~$ [00:14:33.976,013] <dbg> modem_cmux: modem_cmux_log_frame: data:
2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5..
rtt:~$ rtt:~$ [00:14:38.971,496] <inf> mqtthandler: MQTT client disconnected -115
rtt:~$ [00:14:38.971,527] <err> mqtthandler: MQTT Live failed [-115]
rtt:~$ [00:14:38.971,527] <inf> mqtthandler: test123
rtt:~$ rtt:~$ [00:14:42.072,265] <inf> mqtthandler: mqtt_connect -116
rtt:~$ [00:14:42.289,764] <wrn> modem_chat: nordic_nrf91_slm_dial_chat_script: timed out
rtt:~$ [00:14:42.289,855] <dbg> modem_cellular: modem_cellular_log_event: event script failed
nRF 91:
00:04:14.536,651] <dbg> slm_ppp: ppp_data_passing_thread: Forwarded 42 bytes to modem socket.
[00:04:14.777,038] <dbg> slm_ppp: ppp_data_passing_thread: Forwarded 42 bytes to modem socket.
[00:04:15.155,792] <dbg> slm_ppp: ppp_data_passing_thread: Forwarded 42 bytes to modem socket.
[00:04:15.738,983] <dbg> slm_ppp: ppp_data_passing_thread: Forwarded 42 bytes to modem socket.
[00:04:15.739,105] <dbg> slm_at_host: cmd_send: RX
41 54 2b 43 45 52 45 47 3f |AT+CEREG ?
[00:04:15.739,654] <dbg> slm_at_host: slm_at_send_indicate: TX
0d 0a 2b 43 45 52 45 47 3a 20 31 2c 35 0d 0a 0d |..+CEREG : 1,5...
0a 4f 4b 0d 0a |.OK..
[00:04:16.568,634] <dbg> slm_ppp: ppp_data_passing_thread: Forwarded 42 bytes to modem socket.
[00:04:17.516,967] <dbg> slm_at_host: slm_at_send_indicate: TX
0d 0a |..
[00:04:17.517,028] <dbg> slm_at_host: slm_at_send_indicate: TX
2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2..
[00:04:17.619,506] <dbg> slm_at_host: slm_at_send_indicate: TX
0d 0a |..
[00:04:17.619,567] <dbg> slm_at_host: slm_at_send_indicate: TX
2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5..
[00:04:18.949,584] <dbg> slm_ppp: ppp_data_passing_thread: Forwarded 40 bytes to Zephyr socket.
[00:04:19.072,937] <dbg> slm_ppp: ppp_data_passing_thread: Forwarded 42 bytes to Zephyr socket.
[00:04:19.313,079] <dbg> slm_ppp: ppp_data_passing_thread: Forwarded 40 bytes to Zephyr socket.
This also causes a channel mismatch and does not recover.
Tomi-Font over at discord was very helpful in diagnosing this and even said that "This may be a proof that only looking for PDN connection events in SLM is not enough. Monitoring the +CEREG notifications from the modem, and triggering the PPP stopping when it deregisters, might be better because it's aligned with how the driver works."
then lastly, I have one other Problem logged, where I had modified the SLM to delay the cmux channel switch on deregistration, so that the CEREG2 message would still be sent on ch2. This did work, however afterwards the CFUN=4 message from the nRF52 --> nRF91 is not received for unknown reasons, resulting again, in an unrecoverable state:
nRF52:
00> 0d 0a 2b 43 45 52 45 47 3a 20 31 2c 35 0d 0a 0d |..+CEREG : 1,5... 00> 0a 4f 4b 0d 0a |.OK.. 00> rtt:~$ [06:47:14.427,978] <dbg> modem_chat: modem_chat_log_received_command: +CEREG: 1 5 00> rtt:~$ [06:47:14.428,039] <dbg> modem_chat: modem_chat_log_received_command: OK 00> rtt:~$ [06:47:14.428,070] <dbg> modem_chat: modem_chat_script_stop: nordic_nrf91_slm_periodic_chat_script: complete 00> rtt:~$ [06:47:14.428,161] <dbg> modem_cellular: modem_cellular_log_event: event registered 00> rtt:~$ [06:47:14.428,192] <dbg> modem_cellular: modem_cellular_log_event: event script success 00> rtt:~$ rtt:~$ rtt:~$ [06:47:15.211,242] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:1 pf:0 type:UIH dlen:2 00> rtt:~$ [06:47:15.211,273] <dbg> modem_cmux: modem_cmux_log_frame: data: 00> 0d 0a |.. 00> rtt:~$ [06:47:15.211,334] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:1 pf:0 type:UIH dlen:11 00> rtt:~$ [06:47:15.211,364] <dbg> modem_cmux: modem_cmux_log_frame: data: 00> 2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2.. 00> rtt:~$ [06:47:15.211,486] <dbg> modem_chat: modem_chat_log_received_command: +CEREG: 2 00> rtt:~$ [06:47:15.211,578] <dbg> modem_cellular: modem_cellular_log_event: event deregistered 00> rtt:~$ [06:47:15.211,700] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from carrier on to run dial script 00> rtt:~$ [06:47:15.251,739] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:1 pf:0 type:UIH dlen:2 00> rtt:~$ [06:47:15.251,739] <dbg> modem_cmux: modem_cmux_log_frame: data: 00> 0d 0a |.. 00> rtt:~$ [06:47:15.251,831] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:1 pf:0 type:UIH dlen:11 00> rtt:~$ [06:47:15.251,861] <dbg> modem_cmux: modem_cmux_log_frame: data: 00> 2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5.. 00> rtt:~$ rtt:~$ rtt:~$ [06:47:15.311,767] <dbg> modem_cellular: modem_cellular_log_event: event timeout 00> rtt:~$ [06:47:15.311,828] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_dial_chat_script 00> rtt:~$ [06:47:15.311,859] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_dial_chat_script: step: 0 00> rtt:~$ [06:47:15.311,889] <dbg> modem_chat: modem_chat_script_next: sending: AT+CFUN=4 00> rtt:~$ [06:47:15.311,981] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:9 00> rtt:~$ [06:47:15.311,981] <dbg> modem_cmux: modem_cmux_log_frame: data: 00> 41 54 2b 43 46 55 4e 3d 34 |AT+CFUN= 4 00> rtt:~$ [06:47:15.312,072] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:2 00> rtt:~$ [06:47:15.312,103] <dbg> modem_cmux: modem_cmux_log_frame: data: 00> 0d 0a |.. 00> rtt:~$ rtt:~$ [06:47:25.311,981] <wrn> modem_chat: nordic_nrf91_slm_dial_chat_script: timed out 00> rtt:~$ [06:47:25.312,072] <dbg> modem_cellular: modem_cellular_log_event: event script failed 00> rtt:~$ rtt:~$ [06:47:53.111,358] <inf> mqtthandler: MQTT client disconnected -115 00> rtt:~$ [06:47:53.111,389] <err> mqtthandler: MQTT Live failed [-115]
nRF91:
00> [06:47:01.339,447] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a 2b 43 45 52 45 47 3a 20 31 2c 35 0d 0a 0d |..+CEREG : 1,5... 00> 0a 4f 4b 0d 0a |.OK.. 00> [06:47:02.122,375] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [06:47:02.122,436] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2.. 00> [06:47:02.163,208] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [06:47:02.163,269] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5.. 00> [08:51:54.830,505] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 5 received. 00> [08:51:54.884,368] <dbg> slm_ppp: ppp_stop: Stopping PPP... 00> [08:51:54.884,399] <wrn> slm_cmux: PPP fallback work start! 00> [08:51:54.884,826] <inf> slm_ppp: PPP stopped. 00> [08:51:54.884,918] <dbg> slm_ppp: pdp_ctx_event_handler: Connection down. 00> [08:51:54.885,162] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [08:51:54.885,192] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2.. 00> [08:51:54.885,559] <dbg> slm_ppp: ppp_net_mgmt_event_handler: Peer not connected. 00> [08:51:55.184,478] <wrn> slm_cmux: delayed PPP fallback! 00> [08:51:58.880,676] <inf> slm_ppp: Connection up. Starting PPP. 00> [08:51:58.880,767] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [08:51:58.880,828] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 4e 45 43 5f 45 53 4d 3a 20 35 30 2c 30 0d |+CNEC_ES M: 50,0. 00> 0a |. 00> [08:51:58.880,889] <dbg> slm_ppp: pdp_ctx_event_handler: Default PDN connection event 0 received. 00> [08:51:58.881,378] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [08:51:58.881,439] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5.. 00> [08:51:58.883,331] <dbg> slm_ppp: ppp_start: MTU set to 1430. 00> [08:51:58.883,972] <inf> slm_ppp: PPP started. 00> [08:51:58.914,672] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 0d 0a |.. 00> [08:51:58.914,733] <dbg> slm_at_host: slm_at_send_indicate: TX 00> 25 58 54 49 4d 45 3a 20 22 38 30 22 2c 22 34 32 |%XTIME: "80","42 00> 39 30 33 31 33 32 30 32 37 34 38 30 22 2c 22 30 |90313202 7480","0 00> 31 22 0d 0a |1".. 00> [08:52:04.885,009] <dbg> slm_ppp: ppp_net_mgmt_event_handler: Peer not connected.
as all these problems seem to originate from the cmux channel switching, I am wondering why that is even needed?
I hope all these logs make it easier to find the Problem. Reproducing is possible by triggering a signal loss by for example putting the device in a microwave, or submerging it in Water, or using a dummy load as antenna. I also observed this problem happening after hours to days of the device just sitting on my desk.
If anyone has experienced similiar Problems, please also share them here 
Kind regards,
Jonas
