PPP + GSM MUX doesn't work with Thales PLS83-W modem

[ivonalo]

I am trying to get my Thales PLS83-W to have PPP data and AT commands simultaneously. The modem datasheet and vendor are claim muxing should work in general.
Is there anyone here experienced with the GSM MUX who can advise on how to debug this issue?
As I understood it should be possible with enabling the CONFIG_GSM_MUX .

When just using MODEM_GSM_PPP=y the PPP works fine.

I: Jumping to the first image slot
[    0.000000] <dbg> net_ppp: ppp_driver_init: [0x20003250] dev 0x8069544
[    0.000000] <dbg> net_mgmt: net_mgmt_add_event_callback: (main): Adding event callback 0x20002fc8
[    0.005000] <dbg> net_mgmt: net_mgmt_event_init: (main): Net MGMT initialized: queue of 2 entries, stack size of 2056
[    0.005000] <dbg> net_if: net_if_init: (main): 
[    0.005000] <dbg> net_if: init_iface: (main): On iface 0x20000aec
[    0.005000] <dbg> net_ppp: ppp_iface_init: [0x20003250] iface 0x20000aec
[    0.005000] <dbg> net_l2_ppp: net_ppp_init: (main): Initializing PPP L2 0x20003020 for iface 0x20000aec
[    0.005000] <dbg> net_l2_ppp: ppp_startup: (sysworkq): PPP 0x20003020 startup for interface 0x20000aec
[    0.005000] <dbg> net_l2_ppp: ipcp_init: (sysworkq): proto IPCP (0x8021) fsm 0x20003138
[    0.005000] <dbg> net_l2_ppp: lcp_init: (sysworkq): proto LCP (0xc021) fsm 0x20003068
[    0.005000] <dbg> net_if: net_if_post_init: (main): 
*** Booting Zephyr OS build 53987830411a  ***
[    0.870000] <dbg> net_mgmt: net_mgmt_add_event_callback: (conn_mgr): Adding event callback 0x20004b04
[    0.870000] <dbg> net_mgmt: net_mgmt_add_event_callback: (conn_mgr): Adding event callback 0x20004b18
[    0.871000] <dbg> conn_mgr: conn_mgr_handler: (conn_mgr): Connection Manager started
[    0.871000] <dbg> net_l2_ppp: tx_handler: (tx_handler_thread): PPP TX started
[    1.126000] <dbg> net_mgmt: net_mgmt_add_event_callback: (main): Adding event callback 0x20003b98
[   14.905000] <err> modem_gsm: gsm_setup_mccmno returned -5, retrying...
[   16.461000] <dbg> net_l2_ppp: ppp_fsm_lower_up: (sysworkq): [LCP/0x20003068] Current state INITIAL (0)
--- 155 messages dropped ---
[   16.488000] <dbg> net_ppp: ppp_consume_ringbuf: Ringbuf 0x20003284 is empty!
--- 36 messages dropped ---
e_ringbuf: Ringbuf 0x20003284 is empty!
--- 142 messages dropped ---
[   16.513000] <dbg> net_if: net_if_ipv4_addr_add: (rx_q[0]): [0] interface 0x20000aec address 10.25.85.68 type MANUAL added
[   16.513000] <dbg> net_mgmt: net_mgmt_event_notify_with_info: (rx_q[0]): Notifying Event layer 2 code 4 type 1
[   16.513000] <dbg> net_l2_ppp: ipcp_up: (rx_q[0]): PPP up with address 10.25.85.68
[   16.514000] <dbg> net_l2_ppp: ppp_change_phase_debug: (rx_q[0]): [0x20003020] phase NETWORK (3) => RUNNING (4) (ppp_network_up():22)
[   16.514000] <dbg> net_l2_ppp: ppp_network_up: (rx_q[0]): [0x20003020] Proto IPv4 (0x0021) up (1)
[   16.514000] <dbg> net_l2_ppp: ipcp_up: (rx_q[0]): [IPCP/0x20003138] Current state OPENED (9)
[   16.514000] <dbg> net_mgmt: mgmt_thread: (net_mgmt): Handling events, forwarding it relevantly
[   16.514000] <dbg> net_mgmt: mgmt_run_callbacks: (net_mgmt): Event layer 2 code 4 cmd 1
[   16.514000] <dbg> net_mgmt: mgmt_run_callbacks: (net_mgmt): Running callback 0x20004b18 : 0x8032689
[   16.514000] <dbg> conn_mgr: conn_mgr_ipv4_events_handler: (net_mgmt): IPv4 event 3758358529 received on iface 1 (0x20000aec)
[   16.514000] <dbg> conn_mgr: conn_mgr_ipv4_events_handler: (net_mgmt): Iface index 0
[   16.514000] <dbg> conn_mgr: conn_mgr_ipv4_status: (conn_mgr): IPv4 connected on iface index 1
[   16.514000] <dbg> conn_mgr: conn_mgr_notify_status: (conn_mgr): Iface 1 (0x20000aec) connected

But, when adding the CONFIG_GSM_MUX = y I can't get PPP to work and I am also not able to send AT commands. I don't receive any response from the modem, I get the -116 error code, which is timeout.

I: Jumping to the first image slot
[    0.000000] <dbg> net_ppp: ppp_driver_init: [0x20003688] dev 0x806ad44
[    0.000000] <dbg> net_mgmt: net_mgmt_add_event_callback: (main): Adding event callback 0x20003400
[    0.005000] <dbg> net_mgmt: net_mgmt_event_init: (main): Net MGMT initialized: queue of 2 entries, stack size of 2056
[    0.005000] <dbg> net_if: net_if_init: (main): 
[    0.005000] <dbg> net_if: init_iface: (main): On iface 0x20000d54
[    0.005000] <dbg> net_ppp: ppp_iface_init: [0x20003688] iface 0x20000d54
[    0.005000] <dbg> net_l2_ppp: net_ppp_init: (main): Initializing PPP L2 0x20003458 for iface 0x20000d54
[    0.005000] <dbg> net_l2_ppp: ppp_startup: (sysworkq): PPP 0x20003458 startup for interface 0x20000d54
[    0.005000] <dbg> net_l2_ppp: ipcp_init: (sysworkq): proto IPCP (0x8021) fsm 0x20003570
[    0.005000] <dbg> net_l2_ppp: lcp_init: (sysworkq): proto LCP (0xc021) fsm 0x200034a0
[    0.005000] <dbg> net_if: net_if_post_init: (main): 
*** Booting Zephyr OS build 53987830411a  ***
[    0.260000] <dbg> net_mgmt: net_mgmt_add_event_callback: (conn_mgr): Adding event callback 0x20004f3c
[    0.260000] <dbg> net_mgmt: net_mgmt_add_event_callback: (conn_mgr): Adding event callback 0x20004f50
[    0.260000] <dbg> conn_mgr: conn_mgr_handler: (conn_mgr): Connection Manager started
[    0.260000] <dbg> net_l2_ppp: tx_handler: (tx_handler_thread): PPP TX started
[    0.516000] <dbg> net_mgmt: net_mgmt_add_event_callback: (main): Adding event callback 0x20003fd0
[   12.019000] <inf> modem_gsm: PPP channel 2 connected to GSM_1
[   14.283000] <err> modem_gsm: gsm_setup_mccmno returned -5, retrying...
[   17.284000] <err> modem_gsm: AT returned -116, retrying...
[   20.285000] <err> modem_gsm: AT returned -116, retrying...
[   23.287000] <err> modem_gsm: AT returned -116, retrying...
[   26.288000] <err> modem_gsm: AT returned -116, retrying...
[   29.289000] <err> modem_gsm: AT returned -116, retrying...
[   32.290000] <err> modem_gsm: AT returned -116, retrying...
[   35.292000] <err> modem_gsm: AT returned -116, retrying...
[   38.293000] <err> modem_gsm: AT returned -116, retrying...
[   41.294000] <err> modem_gsm: AT returned -116, retrying...
[   44.296000] <err> modem_gsm: AT returned -116, retrying...

This is how my prj.conf file looks like:

CONFIG_NET_TCP=y
CONFIG_NET_UDP=y
CONFIG_NET_IPV6=n
CONFIG_NET_IPV4=y
CONFIG_NET_ARP=y
CONFIG_NET_DHCPV4=n

CONFIG_SOCKS=y
CONFIG_NET_SOCKETS=y
CONFIG_NET_SOCKETS_PACKET=y

# Network drivers buffers
CONFIG_NET_PKT_RX_COUNT=640
CONFIG_NET_PKT_TX_COUNT=640
CONFIG_NET_BUF_RX_COUNT=640
CONFIG_NET_BUF_TX_COUNT=640
CONFIG_NET_BUF_DATA_SIZE=256

# IP Address ranges
CONFIG_NET_IF_UNICAST_IPV4_ADDR_COUNT=10
CONFIG_NET_IF_MCAST_IPV4_ADDR_COUNT=0
CONFIG_NET_MAX_CONTEXTS=10
CONFIG_NET_CONFIG_NEED_IPV4=y
CONFIG_NET_STATISTICS=y

CONFIG_NET_L2_ETHERNET=n
# Enable MQTT Lib support
CONFIG_MQTT_LIB=y
CONFIG_MQTT_KEEPALIVE=30

# # Network configuration
CONFIG_NET_CONFIG_SETTINGS=n
# Configure static addresses
CONFIG_TEST_RANDOM_GENERATOR=y

# Network management events
CONFIG_NET_CONNECTION_MANAGER=y
CONFIG_NET_MGMT_EVENT_STACK_SIZE=2056
CONFIG_NET_MGMT_EVENT_LOG_LEVEL_DBG=y

# Enable Logging support
CONFIG_DEBUG_INFO=y
CONFIG_NET_LOG=y
CONFIG_NET_SOCKETS_LOG_LEVEL_DBG=y
CONFIG_MQTT_LOG_LEVEL_DBG=y
CONFIG_NET_IF_LOG_LEVEL_DBG=y
CONFIG_NET_CONFIG_LOG_LEVEL_DBG=y
CONFIG_NET_CONNECTION_MANAGER_LOG_LEVEL_DBG=y
CONFIG_NET_MGMT_EVENT_INFO=y
CONFIG_DNS_RESOLVER_LOG_LEVEL_DBG=y
CONFIG_NET_CONTEXT_LOG_LEVEL_DBG=y
CONFIG_NET_PPP_LOG_LEVEL_DBG=y
CONFIG_NET_L2_PPP_LOG_LEVEL_DBG=y
CONFIG_UART_CONSOLE_LOG_LEVEL_DBG=y

# UART support
CONFIG_SERIAL=y

# GSM modem support
CONFIG_MODEM=y
CONFIG_MODEM_GSM_PPP=y
CONFIG_MODEM_GSM_APN="internet.m2mportal.de"
CONFIG_MODEM_SHELL=y

# PPP networking support
CONFIG_NET_DRIVERS=y
CONFIG_NET_PPP=y
CONFIG_NET_L2_PPP=y
CONFIG_NET_NATIVE=y
CONFIG_NETWORKING=y
CONFIG_GSM_PPP_AUTOSTART=y
CONFIG_NET_DEFAULT_IF_PPP=y
CONFIG_NET_L2_PPP_TIMEOUT=10000

CONFIG_GSM_MUX_LOG_LEVEL_ERR=y
CONFIG_GSM_MUX=y
CONFIG_UART_MUX=y
# CONFIG_NET_SHELL=y
# CONFIG_MODEM_SHELL=y
 

[ivonalo]

After I increased the GSM_CMD_AT_TIMEOUT from 2 to 5 seconds I don't get the AT command timeout anymore. But also never get the PPP to interface up. It gets stuck in REQUEST_SENT phase
This is my console output:

I: Jumping to the first image slot
[    0.000000] <dbg> net_ppp: ppp_driver_init: [0x20003688] dev 0x806ad64
[    0.000000] <dbg> net_mgmt: net_mgmt_add_event_callback: (main): Adding event callback 0x20003400
[    0.005000] <dbg> net_mgmt: net_mgmt_event_init: (main): Net MGMT initialized: queue of 2 entries, stack size of 2056
[    0.005000] <dbg> net_if: net_if_init: (main): 
[    0.005000] <dbg> net_if: init_iface: (main): On iface 0x20000d54
[    0.005000] <dbg> net_ppp: ppp_iface_init: [0x20003688] iface 0x20000d54
[    0.005000] <dbg> net_l2_ppp: net_ppp_init: (main): Initializing PPP L2 0x20003458 for iface 0x20000d54
[    0.005000] <dbg> net_if: net_if_post_init: (main): 
[    5.005000] <dbg> net_l2_ppp: ppp_startup: (sysworkq): PPP 0x20003458 startup for interface 0x20000d54
[    5.005000] <dbg> net_l2_ppp: ipcp_init: (sysworkq): proto IPCP (0x8021) fsm 0x20003570
[    5.005000] <dbg> net_l2_ppp: lcp_init: (sysworkq): proto LCP (0xc021) fsm 0x200034a0
*** Booting Zephyr OS build 53987830411a  ***

[   14.613000] <dbg> net_mgmt: net_mgmt_add_event_callback: (conn_mgr): Adding event callback 0x20004f3c
[   14.613000] <dbg> net_mgmt: net_mgmt_add_event_callback: (conn_mgr): Adding event callback 0x20004f50
[   14.614000] <dbg> conn_mgr: conn_mgr_handler: (conn_mgr): Connection Manager started
[   14.614000] <dbg> net_l2_ppp: tx_handler: (tx_handler_thread): PPP TX started
[   14.869000] <dbg> net_mgmt: net_mgmt_add_event_callback: (main): Adding event callback 0x20003fd0
[   30.004000] <dbg> modem_gsm: AT+CMUX generic
[   30.020000] <inf> modem_gsm: PPP channel 2 connected to GSM_1
[   31.962000] <dbg> net_l2_ppp: ppp_fsm_lower_up: (sysworkq): [LCP/0x200034a0] Current state INITIAL (0)
--- 12 messages dropped ---
[   31.962000] <dbg> net_l2_ppp: ppp_change_state_debug: (sysworkq): [LCP/0x200034a0] state INITIAL (0) => CLOSED (2) (ppp_fsm_lower_up():312)
[   31.962000] <dbg> net_l2_ppp: start_ppp: (sysworkq): Starting LCP
[   31.962000] <dbg> net_l2_ppp: ppp_fsm_open: (sysworkq): [LCP/0x200034a0] Current state CLOSED (2)
[   31.962000] <dbg> net_l2_ppp: ppp_change_state_debug: (sysworkq): [LCP/0x200034a0] state CLOSED (2) => REQUEST_SENT (6) (ppp_fsm_open():335)
[   31.962000] <dbg> net_l2_ppp: fsm_send_configure_req: (sysworkq): [LCP/0x200034a0] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[   31.962000] <dbg> net_l2_ppp: ppp_send_pkt: (sysworkq): [LCP/0x200034a0] Sending 6 bytes pkt 0x2002dc20 (options len 0)
[   31.963000] <dbg> net_mgmt: net_mgmt_event_notify_with_info: (sysworkq): Notifying Event layer 1 code 1 type 2
[   31.963000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dc20, prio 1) network packet iface 0x20000d54/1
[   31.963000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[   31.963000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x2002dc20
                                 c0 21 01 01 00 04                                |.!....           
[   31.963000] <dbg> net_ppp: net_pkt_hexdump: send ppp
[   31.963000] <dbg> net_ppp: net_pkt_hexdump: 0x2002dc20
                              c0 21 01 01 00 04                                |.!....           
[   31.966000] <inf> modem_gsm: AT channel 1 connected to GSM_2
[   31.966000] <dbg> net_mgmt: mgmt_thread: (net_mgmt): Handling events, forwarding it relevantly
[   31.966000] <dbg> net_mgmt: mgmt_run_callbacks: (net_mgmt): Event layer 1 code 1 cmd 2
[   31.966000] <dbg> net_mgmt: mgmt_run_callbacks: (net_mgmt): Running callback 0x20004f3c : 0x8032605
[   31.966000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface event 3489726466 received on iface 1 (0x20000d54)
[   31.966000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface index 0
[   41.963000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x200034a0] Current state REQUEST_SENT (6)
[   41.963000] <dbg> net_l2_ppp: fsm_send_configure_req: (sysworkq): [LCP/0x200034a0] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[   41.963000] <dbg> net_l2_ppp: ppp_send_pkt: (sysworkq): [LCP/0x200034a0] Sending 6 bytes pkt 0x2002dc20 (options len 0)
[   41.963000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dc20, prio 1) network packet iface 0x20000d54/1
[   41.963000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[   41.963000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x2002dc20
                                 c0 21 01 01 00 04                                |.!....           
[   41.963000] <dbg> net_ppp: net_pkt_hexdump: send ppp
[   41.963000] <dbg> net_ppp: net_pkt_hexdump: 0x2002dc20
                              c0 21 01 01 00 04                                |.!....           
[   51.963000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x200034a0] Current state REQUEST_SENT (6)
[   51.963000] <dbg> net_l2_ppp: fsm_send_configure_req: (sysworkq): [LCP/0x200034a0] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[   51.963000] <dbg> net_l2_ppp: ppp_send_pkt: (sysworkq): [LCP/0x200034a0] Sending 6 bytes pkt 0x2002dc20 (options len 0)
[   51.963000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dc20, prio 1) network packet iface 0x20000d54/1
[   51.963000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[   51.963000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x2002dc20
                                 c0 21 01 01 00 04                                |.!....           
[   51.963000] <dbg> net_ppp: net_pkt_hexdump: send ppp
[   51.963000] <dbg> net_ppp: net_pkt_hexdump: 0x2002dc20
                              c0 21 01 01 00 04                                |.!....           
[   61.963000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x200034a0] Current state REQUEST_SENT (6)
[   61.963000] <dbg> net_l2_ppp: fsm_send_configure_req: (sysworkq): [LCP/0x200034a0] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[   61.963000] <dbg> net_l2_ppp: ppp_send_pkt: (sysworkq): [LCP/0x200034a0] Sending 6 bytes pkt 0x2002dc20 (options len 0)
[   61.963000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dc20, prio 1) network packet iface 0x20000d54/1
[   61.963000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[   61.963000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x2002dc20
                                 c0 21 01 01 00 04                                |.!....           
[   61.963000] <dbg> net_ppp: net_pkt_hexdump: send ppp
[   61.963000] <dbg> net_ppp: net_pkt_hexdump: 0x2002dc20
                              c0 21 01 01 00 04                                |.!....           
[   71.963000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x200034a0] Current state REQUEST_SENT (6)
[   71.963000] <dbg> net_l2_ppp: fsm_send_configure_req: (sysworkq): [LCP/0x200034a0] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[   71.963000] <dbg> net_l2_ppp: ppp_send_pkt: (sysworkq): [LCP/0x200034a0] Sending 6 bytes pkt 0x2002dc20 (options len 0)
[   71.963000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dc20, prio 1) network packet iface 0x20000d54/1
[   71.963000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[   71.963000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x2002dc20
                                 c0 21 01 01 00 04                                |.!....           
[   71.964000] <dbg> net_ppp: net_pkt_hexdump: send ppp
[   71.964000] <dbg> net_ppp: net_pkt_hexdump: 0x2002dc20
                              c0 21 01 01 00 04                                |.!....           
[   81.963000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x200034a0] Current state REQUEST_SENT (6)
[   81.963000] <dbg> net_l2_ppp: fsm_send_configure_req: (sysworkq): [LCP/0x200034a0] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[   81.964000] <dbg> net_l2_ppp: ppp_send_pkt: (sysworkq): [LCP/0x200034a0] Sending 6 bytes pkt 0x2002dc20 (options len 0)
[   81.964000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dc20, prio 1) network packet iface 0x20000d54/1
[   81.964000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[   81.964000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x2002dc20
                                 c0 21 01 01 00 04                                |.!....           
[   81.964000] <dbg> net_ppp: net_pkt_hexdump: send ppp
[   81.964000] <dbg> net_ppp: net_pkt_hexdump: 0x2002dc20
                              c0 21 01 01 00 04                                |.!....           
[   91.964000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x200034a0] Current state REQUEST_SENT (6)
[   91.964000] <dbg> net_l2_ppp: fsm_send_configure_req: (sysworkq): [LCP/0x200034a0] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[   91.964000] <dbg> net_l2_ppp: ppp_send_pkt: (sysworkq): [LCP/0x200034a0] Sending 6 bytes pkt 0x2002dc20 (options len 0)
[   91.964000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dc20, prio 1) network packet iface 0x20000d54/1
[   91.964000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[   91.964000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x2002dc20
                                 c0 21 01 01 00 04                                |.!....           
[   91.964000] <dbg> net_ppp: net_pkt_hexdump: send ppp
[   91.964000] <dbg> net_ppp: net_pkt_hexdump: 0x2002dc20
                              c0 21 01 01 00 04                                |.!....           
[  101.964000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x200034a0] Current state REQUEST_SENT (6)
[  101.964000] <dbg> net_l2_ppp: fsm_send_configure_req: (sysworkq): [LCP/0x200034a0] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[  101.964000] <dbg> net_l2_ppp: ppp_send_pkt: (sysworkq): [LCP/0x200034a0] Sending 6 bytes pkt 0x2002dc20 (options len 0)
[  101.964000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dc20, prio 1) network packet iface 0x20000d54/1
[  101.964000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[  101.964000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x2002dc20
                                 c0 21 01 01 00 04                                |.!....           
[  101.964000] <dbg> net_ppp: net_pkt_hexdump: send ppp
[  101.964000] <dbg> net_ppp: net_pkt_hexdump: 0x2002dc20
                              c0 21 01 01 00 04                                |.!....           
[  111.964000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x200034a0] Current state REQUEST_SENT (6)
[  111.964000] <dbg> net_l2_ppp: fsm_send_configure_req: (sysworkq): [LCP/0x200034a0] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[  111.964000] <dbg> net_l2_ppp: ppp_send_pkt: (sysworkq): [LCP/0x200034a0] Sending 6 bytes pkt 0x2002dc20 (options len 0)
[  111.964000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dc20, prio 1) network packet iface 0x20000d54/1
[  111.964000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[  111.964000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x2002dc20
                                 c0 21 01 01 00 04                                |.!....           
[  111.964000] <dbg> net_ppp: net_pkt_hexdump: send ppp
[  111.964000] <dbg> net_ppp: net_pkt_hexdump: 0x2002dc20
                              c0 21 01 01 00 04                                |.!....           
[  121.964000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x200034a0] Current state REQUEST_SENT (6)
[  121.964000] <dbg> net_l2_ppp: fsm_send_configure_req: (sysworkq): [LCP/0x200034a0] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[  121.964000] <dbg> net_l2_ppp: ppp_send_pkt: (sysworkq): [LCP/0x200034a0] Sending 6 bytes pkt 0x2002dc20 (options len 0)
[  121.964000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dc20, prio 1) network packet iface 0x20000d54/1
[  121.964000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[  121.964000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x2002dc20
                                 c0 21 01 01 00 04                                |.!....           
[  121.965000] <dbg> net_ppp: net_pkt_hexdump: send ppp
[  121.965000] <dbg> net_ppp: net_pkt_hexdump: 0x2002dc20
                              c0 21 01 01 00 04                                |.!....           
[  131.964000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x200034a0] Current state REQUEST_SENT (6)
[  131.964000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x200034a0] Configure-Req retransmit limit 0 reached
[  131.965000] <dbg> net_l2_ppp: ppp_change_state_debug: (sysworkq): [LCP/0x200034a0] state REQUEST_SENT (6) => STOPPED (3) (ppp_fsm_timeout():114)
[  131.965000] <dbg> net_l2_ppp: ppp_change_phase_debug: (sysworkq): [0x20003458] phase ESTABLISH (1) => DEAD (0) (ppp_link_terminated():123)
[  131.965000] <dbg> net_l2_ppp: ppp_link_terminated: (sysworkq): [0x20003458] Link terminated
[  131.965000] <dbg> net_if: net_if_carrier_down: (sysworkq): iface 0x20000d54
[  131.965000] <dbg> net_mgmt: net_mgmt_event_notify_with_info: (sysworkq): Notifying Event layer 1 code 1 type 1
[  131.965000] <dbg> net_mgmt: mgmt_thread: (net_mgmt): Handling events, forwarding it relevantly
[  131.965000] <dbg> net_mgmt: mgmt_run_callbacks: (net_mgmt): Event layer 1 code 1 cmd 1
[  131.965000] <dbg> net_mgmt: mgmt_run_callbacks: (net_mgmt): Running callback 0x20004f3c : 0x8032605
[  131.965000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface event 3489726465 received on iface 1 (0x20000d54)
[  131.965000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface index 0
[  131.965000] <dbg> net_mgmt: mgmt_run_callbacks: (net_mgmt): Running callback 0x20003400 : 0x8035fe9
[  131.965000] <inf> modem_gsm: GSM network interface down

[jukkar]

If I recall correctly, you will get IP address only after muxing has been setup correctly if the modem supports muxing. So this means that if you get PPP up and running and muxing is disabled in Zephyr, that means that muxing in modem is not enabled.
This would further explain the issue if you enable muxing in Zephyr and do not get PPP running, which could be explained if your modem either does not support muxing or it needs some special tweaks etc to enable muxing. Note that I am just guessing here, I am not familiar with your modem. Could be of course some totally different issue, but I hope this helps you further in debugging.

[ivonalo]

From these logs I would conclude that muxing is successfully configured.
And the problem is that the modem is stuck on the AT+CSQ command

[00:00:15.001,000] <dbg> modem_gsm: gsm_configure: Starting modem 0x200059d0 configuration
[00:00:15.004,000] <dbg> modem_cmd_handler: cmd_handler_process_rx_buf: match cmd [OK] (len:2)
[00:00:15.004,000] <dbg> modem_gsm: gsm_cmd_ok: ok
[00:00:15.011,000] <dbg> modem_cmd_handler: cmd_handler_process_rx_buf: match cmd [OK] (len:2)
[00:00:15.011,000] <dbg> modem_gsm: gsm_cmd_ok: ok
**[00:00:15.011,000] <dbg> modem_gsm: gsm_configure: GSM muxing enabled
[00:00:15.013,000] <dbg> modem_gsm: mux_attach_cb: DLCI 0 to GSM_0 connected
[00:00:15.016,000] <dbg> modem_gsm: mux_attach_cb: DLCI 2 to GSM_1 connected
[00:00:15.019,000] <dbg> modem_gsm: mux_attach_cb: DLCI 1 to GSM_2 connected
[00:00:15.020,000] <inf> modem_gsm: PPP channel 2 connected to GSM_1**
[00:00:16.283,000] <dbg> modem_cmd_handler: cmd_handler_process_rx_buf: match cmd [+COPS:] (len:20)
[00:00:16.284,000] <dbg> modem_gsm: gsm_cmd_ok: ok
[00:00:16.538,000] <inf> modem_gsm: Manufacturer: Cinterion
[00:00:16.598,000] <inf> modem_gsm: Model: PLS83-W
[00:00:16.657,000] <inf> modem_gsm: Revision: REVISION 01.006
[00:00:16.718,000] <inf> modem_gsm: IMEI: 351072640170126
[00:00:16.775,000] <inf> modem_gsm: IMSI: 901405001929674
[00:00:16.834,000] <inf> modem_gsm: ICCID: 89882280000013669359
[00:00:16.840,000] <dbg> modem_cmd_handler: cmd_handler_process_rx_buf: match cmd [+CREG: ] (len:10)
[00:00:16.840,000] <inf> modem_gsm: Network registered, roaming.
[00:00:16.841,000] <dbg> modem_gsm: gsm_cmd_ok: ok
[00:00:16.847,000] <dbg> modem_cmd_handler: cmd_handler_process_rx_buf: match cmd [+CGATT:] (len:9)
[00:00:16.847,000] <inf> modem_gsm: Attached to packet service!
[00:00:16.848,000] <dbg> modem_gsm: gsm_cmd_ok: ok
[00:00:16.848,000] <dbg> modem_gsm: gsm_finalize_connection: modem attach returned 0, read RSSI
[00:00:16.848,000] <dbg> modem_gsm: gsm_finalize_connection: modem RSSI: 0, enable PPP
[00:00:16.870,000] <dbg> modem_cmd_handler: cmd_handler_process_rx_buf: match cmd [CONNECT] (len:7)
[00:00:16.870,000] <dbg> modem_gsm: gsm_cmd_ok: ok
**[00:00:16.870,000] <inf> net_ppp: Initializing PPP to use GSM_1**
[00:00:16.871,000] <dbg> net_l2_ppp: carrier_on_off: (sysworkq): Carrier ON for interface 0x20000d54
[00:00:16.871,000] <dbg> net_if: net_if_up: (sysworkq): iface 0x20000d54
[00:00:16.871,000] <dbg> net_l2_ppp: ppp_change_phase_debug: (sysworkq): [0x20007058] phase DEAD (0) => ESTABLISH (1) (start_ppp():209)
[00:00:16.871,000] <dbg> net_l2_ppp: ppp_fsm_lower_up: (sysworkq): [LCP/0x200070a0] Current state INITIAL (0)
[00:00:16.872,000] <dbg> net_l2_ppp: ppp_change_state_debug: (sysworkq): [LCP/0x200070a0] state INITIAL (0) => CLOSED (2) (ppp_fsm_lower_up():312)
[00:00:16.872,000] <dbg> net_l2_ppp: start_ppp: (sysworkq): Starting LCP
[00:00:16.872,000] <dbg> net_l2_ppp: ppp_fsm_open: (sysworkq): [LCP/0x200070a0] Current state CLOSED (2)
[00:00:16.872,000] <dbg> net_l2_ppp: ppp_change_state_debug: (sysworkq): [LCP/0x200070a0] state CLOSED (2) => REQUEST_SENT (6) (ppp_fsm_open():335)
[00:00:16.872,000] <dbg> net_l2_ppp: fsm_send_configure_req: (sysworkq): [LCP/0x200070a0] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[00:00:16.872,000] <dbg> net_l2_ppp: ppp_send_pkt: (sysworkq): [LCP/0x200070a0] Sending 6 bytes pkt 0x20031a60 (options len 0)
[00:00:16.872,000] <dbg> net_mgmt: net_mgmt_event_notify_with_info: (sysworkq): Notifying Event layer 1 code 1 type 2
[00:00:16.872,000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x20031a60, prio 1) network packet iface 0x20000d54/1
[00:00:16.872,000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[00:00:16.872,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x20031a60
                                     c0 21 01 01 00 04                                |.!....           
[00:00:16.872,000] <dbg> net_ppp: net_pkt_hexdump: send ppp
[00:00:16.872,000] <dbg> net_ppp: net_pkt_hexdump: 0x20031a60
                                  c0 21 01 01 00 04                                |.!....           
[00:00:16.875,000] <dbg> modem_cmd_handler: cmd_handler_process_rx_buf: match cmd [OK] (len:2)
[00:00:16.875,000] <dbg> modem_gsm: gsm_cmd_ok: ok
**[00:00:16.875,000] <inf> modem_gsm: AT channel 1 connected to GSM_2**

[00:00:16.875,000] <dbg> net_mgmt: mgmt_thread: (net_mgmt): Handling events, forwarding it relevantly
[00:00:16.875,000] <dbg> net_mgmt: mgmt_run_callbacks: (net_mgmt): Event layer 1 code 1 cmd 2
[00:00:16.876,000] <dbg> net_mgmt: mgmt_run_callbacks: (net_mgmt): Running callback 0x20008b48 : 0x8034a51
[00:00:16.876,000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface event 3489726466 received on iface 1 (0x20000d54)
[00:00:16.876,000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface index 0
[00:00:26.872,000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x200070a0] Current state REQUEST_SENT (6)
[00:00:26.872,000] <dbg> net_l2_ppp: fsm_send_configure_req: (sysworkq): [LCP/0x200070a0] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[00:00:26.872,000] <dbg> net_l2_ppp: ppp_send_pkt: (sysworkq): [LCP/0x200070a0] Sending 6 bytes pkt 0x20031a60 (options len 0)
[00:00:26.872,000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x20031a60, prio 1) network packet iface 0x20000d54/1
[00:00:26.872,000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[00:00:26.872,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x20031a60
                                     c0 21 01 01 00 04                                |.!....           
[00:00:26.872,000] <dbg> net_ppp: net_pkt_hexdump: send ppp
[00:00:26.872,000] <dbg> net_ppp: net_pkt_hexdump: 0x20031a60
                                  c0 21 01 01 00 04                                |.!....           
[00:00:36.872,000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x200070a0] Current state REQUEST_SENT (6)
[00:00:36.872,000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x200070a0] Configure-Req retransmit limit 0 reached
[00:00:36.872,000] <dbg> net_l2_ppp: ppp_change_state_debug: (sysworkq): [LCP/0x200070a0] state REQUEST_SENT (6) => STOPPED (3) (ppp_fsm_timeout():114)
[00:00:36.872,000] <dbg> net_l2_ppp: ppp_change_phase_debug: (sysworkq): [0x20007058] phase ESTABLISH (1) => DEAD (0) (ppp_link_terminated():123)
[00:00:36.872,000] <dbg> net_l2_ppp: ppp_link_terminated: (sysworkq): [0x20007058] Link terminated
[00:00:36.872,000] <dbg> net_if: net_if_carrier_down: (sysworkq): iface 0x20000d54
[00:00:36.872,000] <dbg> net_mgmt: net_mgmt_event_notify_with_info: (sysworkq): Notifying Event layer 1 code 1 type 1
[00:00:36.872,000] <dbg> net_mgmt: mgmt_thread: (net_mgmt): Handling events, forwarding it relevantly
[00:00:36.872,000] <dbg> net_mgmt: mgmt_run_callbacks: (net_mgmt): Event layer 1 code 1 cmd 1
[00:00:36.872,000] <dbg> net_mgmt: mgmt_run_callbacks: (net_mgmt): Running callback 0x20008b48 : 0x8034a51
[00:00:36.872,000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface event 3489726465 received on iface 1 (0x20000d54)
[00:00:36.872,000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface index 0
[00:00:36.872,000] <dbg> net_mgmt: mgmt_run_callbacks: (net_mgmt): Running callback 0x20007000 : 0x80389ed
[00:00:36.872,000] <inf> modem_gsm: GSM network interface down
050762 [INFO] pls8_handler.cpp:99:[Initialize] | Opened modem serial port
050869 [INFO] pls8_handler.cpp:210:[SendGPSCommand] | Disable echo
[00:00:52.877,000] <dbg> modem_gsm: rssi_handler: No answer to RSSI readout, ignoring...
083879 [INFO] pls8_handler.cpp:217:[SendGPSCommand] | ATE0 Response ascii: [ 249 5 239 13 65 84 43 ]
083889 [INFO] pls8_handler.cpp:219:[SendGPSCommand] | ATE0 Response char: [ �  � A T + ]
083997 [INFO] pls8_handler.cpp:225:[SendGPSCommand] | Sending AT^SQPORT?
[00:01:28.879,000] <dbg> modem_gsm: rssi_handler: No answer to RSSI readout, ignoring...
118940 [INFO] pls8_handler.cpp:231:[SendGPSCommand] | Response to AT^SQPORT ascii[ 249 5 239 13 65 84 43 67 83 81 95 249 249 5 239 3 13 181 ]
118953 [INFO] pls8_handler.cpp:233:[SendGPSCommand] | Response to AT^SQPORT char[ �  � A T + C S Q _ � �  �  � ]

[jukkar]

Indeed, the muxing seems to be working ok. Perhaps the PPP and AT channels need to be swapped like in Simcom modem.
You could try to change and see if it helps.

CONFIG_GSM_MUX_DLCI_PPP=1
CONFIG_GSM_MUX_DLCI_AT=2

[ivonalo]

Indeed, the muxing seems to be working ok. Perhaps the PPP and AT channels need to be swapped like in Simcom modem. You could try to change and see if it helps.

CONFIG_GSM_MUX_DLCI_PPP=1
CONFIG_GSM_MUX_DLCI_AT=2

Has zephyr implemented HW flow control while communicating with the modem, can I enable it somehow?

[ivonalo]

Indeed, the muxing seems to be working ok. Perhaps the PPP and AT channels need to be swapped like in Simcom modem. You could try to change and see if it helps.

CONFIG_GSM_MUX_DLCI_PPP=1
CONFIG_GSM_MUX_DLCI_AT=2

I have tried that change, but unfortunately, the behaviour is the same

[ycsin]

Don't know what's going on, but maybe try disable the GPS part first if it shares the same serial port to keep things simple?

[ivonalo]

Don't know what's going on, but maybe try disable the GPS part first if it shares the same serial port to keep things simple?

Yes, I have tried that too. But the problem is still present. Muxing is successful but I don't get the IP address and can't get PPP interface up. This is how my logs look like

*** Booting Zephyr OS build 53987830411a  ***
I: Starting bootloader
I: Primary image: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Scratch: magic=unset, swap_type=0x1, copy_done=0x3, image_ok=0x3
I: Boot source: primary slot
I: Swap type: none
I: Bootloader chainload address offset: 0x10000
I: Jumping to the first image slot
[00:00:00.005,000] <dbg> net_if: net_if_init: (main): 
[00:00:00.005,000] <dbg> net_if: init_iface: (main): On iface 0x20000d54
[00:00:00.005,000] <dbg> net_if: net_if_post_init: (main): 
*** Booting Zephyr OS build 7e22bfaff313  ***
[00:00:00.360,000] <dbg> conn_mgr: conn_mgr_handler: (conn_mgr): Connection Manager started
[00:00:15.019,000] <inf> modem_gsm: PPP channel 1 connected to GSM_1
[00:00:16.671,000] <inf> modem_gsm: Manufacturer: Cinterion
[00:00:16.731,000] <inf> modem_gsm: Model: PLS83-W
[00:00:16.789,000] <inf> modem_gsm: Revision: REVISION 01.006
[00:00:16.850,000] <inf> modem_gsm: IMEI: 351072640170126
[00:00:16.908,000] <inf> modem_gsm: IMSI: 901405001929674
[00:00:16.966,000] <inf> modem_gsm: ICCID: 89882280000013669359
[00:00:16.973,000] <inf> modem_gsm: Network registered, roaming.
[00:00:16.980,000] <inf> modem_gsm: Attached to packet service!
[00:00:17.001,000] <inf> net_ppp: Initializing PPP to use GSM_1
[00:00:17.002,000] <dbg> net_if: net_if_up: (sysworkq): iface 0x20000d54
[00:00:17.003,000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dba0, prio 1) network packet iface 0x20000d54/1
[00:00:17.005,000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface event 3489726466 received on iface 1 (0x20000d54)
[00:00:17.005,000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface index 0
[00:00:17.010,000] <inf> modem_gsm: AT channel 2 connected to GSM_2
[00:00:20.003,000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dba0, prio 1) network packet iface 0x20000d54/1
[00:00:23.003,000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dba0, prio 1) network packet iface 0x20000d54/1
[00:00:26.003,000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dba0, prio 1) network packet iface 0x20000d54/1
[00:00:29.003,000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dba0, prio 1) network packet iface 0x20000d54/1
[00:00:32.003,000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dba0, prio 1) network packet iface 0x20000d54/1
[00:00:35.003,000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dba0, prio 1) network packet iface 0x20000d54/1
[00:00:38.003,000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dba0, prio 1) network packet iface 0x20000d54/1
[00:00:41.003,000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dba0, prio 1) network packet iface 0x20000d54/1
[00:00:44.003,000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x2002dba0, prio 1) network packet iface 0x20000d54/1
[00:00:47.003,000] <dbg> net_if: net_if_carrier_down: (sysworkq): iface 0x20000d54
[00:00:47.004,000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface event 3489726465 received on iface 1 (0x20000d54)
[00:00:47.004,000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface index 0
[00:00:47.004,000] <inf> modem_gsm: GSM network interface down

[ycsin]

@ivonalo unfortunately I have no clue as well
cc @mniestroj @rlubos @bbilas @endian-benjamin

[ivonalo]

@ivonalo unfortunately I have no clue as well cc @mniestroj @rlubos @bbilas @endian-benjamin

Thank you for your reply! I have described the current problem on this link: #47995

[ivonalo]

After enabling and increasing the MRU length to the max one, PPP is now successfully up, together with CONFIG_GSM_MUX
CONFIG_NET_L2_PPP_OPTION_MRU=y
CONFIG_GSM_MUX_MRU_DEFAULT_LEN=128

[ycsin]

Thats great, maybe you can send a patch for this particular modem

[ivonalo]

Now, while the PPP interface is up I want to send periodically an AT command to the modem, to ask for the GPS coordinates, but I am not sure how to do that. Can I do it from my user code or I must edit the gsm_ppp.c file directly and add my AT commands?

[ycsin]

There is a location API current WIP #46660

You can also refer to https://github.com/G-Technologies-Sdn-Bhd/zephyr/blob/develop_v2.7/drivers/modem/gsm_ppp.c#L721