On nrf-sdk 3.0.1, we were running nrf54 (main app) with Zephyr's PPP modem for nrf91 SLM. Everything was working fine. After upgrading to nrf-sdk 3.1.0, I am now getting this error on nrf54 while trying to switch cmux channels:
[00:00:14.997,584] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 10[00:00:14.997,601] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGMR[00:00:15.038,367] <dbg> modem_chat: modem_chat_log_received_command: mfw_nrf91x1_2.0.1[00:00:15.038,397] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 11[00:00:15.038,426] <dbg> modem_chat: modem_chat_log_received_command: OK[00:00:15.038,441] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 12[00:00:15.038,458] <dbg> modem_chat: modem_chat_script_next: sending: AT#XCMUX=1[00:00:15.073,334] <dbg> modem_chat: modem_chat_log_received_command: OK[00:00:15.073,352] <dbg> modem_chat: modem_chat_script_stop: nordic_nrf91_slm_init_chat_script: complete[00:00:15.478,126] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_dial_chat_script[00:00:15.478,151] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_dial_chat_script: step: 0[00:00:15.478,169] <dbg> modem_chat: modem_chat_script_next: sending: AT+CFUN=4[00:00:15.547,396] <dbg> modem_chat: modem_chat_log_received_command: OK[00:00:15.547,414] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_dial_chat_script: step: 1[00:00:15.547,431] <dbg> modem_chat: modem_chat_script_next: sending: AT+CFUN=1[00:00:15.656,959] <dbg> modem_chat: modem_chat_log_received_command: OK[00:00:15.656,985] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_dial_chat_script: step: 2[00:00:15.657,003] <dbg> modem_chat: modem_chat_script_next: sending: AT#XCMUX=2[00:00:25.478,261] <wrn> modem_chat: nordic_nrf91_slm_dial_chat_script: timed out
However, it appears that nrf91 SLM, at least, is sending the OK
[00:00:02.355,316] <dbg> slm_at_host: cmd_send: RX 41 54 2b 43 46 55 4e 3d 31 |AT+CFUN= 1 [00:00:02.355,529] <dbg> slm_util: slm_util_at_cmd_no_intercept: Forwarding "AT+CFUN=1" to the modem.[00:00:02.402,099] <dbg> slm_util: slm_util_at_cmd_no_intercept: Forwarding "AT+CGEREP=1" to the modem.[00:00:02.402,679] <dbg> slm_at_host: slm_at_send_indicate: TX 0d 0a 4f 4b 0d 0a |..OK.. [00:00:02.464,660] <dbg> slm_cmux: dlci_pipe_event_handler: DLCI 1 (AT) receive ready.[00:00:02.464,752] <dbg> slm_cmux: dlci_pipe_event_handler: DLCI 1 (AT) receive ready.[00:00:02.464,904] <dbg> slm_cmux: rx_work_fn: DLCI 1 (AT) received 12 bytes of data.[00:00:02.464,935] <dbg> slm_at_host: cmd_send: RX 41 54 23 58 43 4d 55 58 3d 32 |AT#XCMUX =2 [00:00:02.465,209] <dbg> slm_at_host: slm_at_send_indicate: TX 0d 0a 4f 4b 0d 0a |..OK.. [00:00:03.492,492] <dbg> slm_at_host: slm_at_send_indicate: TX 0d 0a |.. [00:00:03.492,553] <dbg> slm_at_host: slm_at_send_indicate: TX 2b 43 45 52 45 47 3a 20 32 0d 0a |+CEREG: 2.. [00:00:10.881,530] <inf> slm_ppp: PPP PDN (0) activated.[00:00:10.881,591] <dbg> slm_ppp: delegate_ppp_event: PPP start, reason: 0[00:00:10.881,866] <dbg> slm_at_host: slm_at_send_indicate: TX 0d 0a |.. [00:00:10.881,896] <dbg> slm_at_host: slm_at_send_indicate: TX 2b 43 4e 45 43 5f 45 53 4d 3a 20 35 30 2c 30 0d |+CNEC_ES M: 50,0. 0a |. [00:00:10.882,019] <dbg> slm_at_host: slm_at_send_indicate: TX 0d 0a |.. [00:00:10.882,049] <dbg> slm_at_host: slm_at_send_indicate: TX 2b 43 45 52 45 47 3a 20 35 0d 0a |+CEREG: 5.. [00:00:10.882,171] <inf> slm_ppp: PPP start, reason: 0[00:00:10.885,375] <dbg> slm_ppp: ppp_retrieve_pdn_info: MTU set to 1360.[00:00:10.886,108] <inf> slm_ppp: PPP socket bound to PDN 0[00:00:10.887,451] <dbg> slm_at_host: slm_at_send_indicate: TX 0d 0a 23 58 50 50 50 3a 20 31 2c 30 2c 30 0d 0a |..#XPPP: 1,0,0..[00:00:10.887,512] <inf> slm_ppp: PPP start succeeded.[00:00:14.286,468] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x41 because 0x7e was expected.[00:00:14.286,529] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x54 because 0x7e was expected.[00:00:14.286,529] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2b because 0x7e was expected.
What are we missing?
