Possible Bug: PPP gets stuck after net_if_down(ppp_iface)

[ljdevdev]

Hi everyone,

I have a curious observation, and I am not quite sure, if I am using the driver wrong, or I encountered a bug. The LCP-Statemachine gets stuck after calling net_if_down on the PPP interface. Do I need to reset the driver somehow?

Obeserved behaviour
I am running a custom AT-Command modem driver that hands over to the Zephyr-PPP driver after successfully establishing a mobile link.

When the modem unilaterally terminates the PPP link (see log below) the PPP-driver switches to phase "DEAD".

The AT-Command driver then takes over, calls net_if_down , reestablishes the mobile connection and calls net_if_up on the ppp-interface.

The LCP-Statemachine then gets stuck in state "PPP_STOPPED".

Solution
The problem goes away if I reset lcp.fsm.state to "PPP_INITIAL" in ppp_link_terminated (https://github.com/zephyrproject-rtos/zephyr/blob/main/subsys/net/l2/ppp/link.c#L115):

void ppp_link_terminated(struct ppp_context *ctx)
{
        k_sem_give(&ctx->wait_ppp_link_terminated);

        if (ctx->phase == PPP_DEAD) {
                return;
        }

        /* TODO: cleanup things etc here if needed */

        ppp_change_phase(ctx, PPP_DEAD);
/*+*/   ppp_change_state(&ctx->lcp.fsm, PPP_INITIAL);

        NET_DBG("[%p] Link terminated", ctx);
}

To Reproduce
Unfortuantely I have no easy way to reproduce this without a modem that terminates the connection. If someone points me to a testsuite where I could add this as a test, I would be happy to do so.

Expected behavior
The statemachine should start from the same initial state each time ppp_start is called.

Impact
This bug makes the PPP driver unusable in a commercial product.

Logs and console output

[00:05:13.538,000] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20205e88, pkt=0x20274270, st=0, user_data=(nil)
[00:05:14.261,000] <dbg> net_ppp: ppp_input_byte: Address byte (0xff) start
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_fsm_input: (rx_q[0]): [LCP/0x20207350] LCP Terminate-Req (5) id 3 payload len 28
[00:05:14.265,000] <dbg> net_l2_ppp: fsm_recv_terminate_req: (rx_q[0]): [LCP/0x20207350] Current state OPENED (9)
[00:05:14.265,000] <dbg> net_l2_ppp: fsm_recv_terminate_req: (rx_q[0]): [LCP/0x20207350] Terminated by peer (No network protocols running)
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_change_state_debug: (rx_q[0]): [LCP/0x20207350] state OPENED (9) => STOPPING (5) (fsm_recv_terminate_req():877)
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_fsm_lower_down: (rx_q[0]): [IPCP/0x20207420] Current state OPENED (9)
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_change_state_debug: (rx_q[0]): [IPCP/0x20207420] state OPENED (9) => STARTING (1) (ppp_fsm_lower_down():282)
[00:05:14.265,000] <dbg> net_if: net_if_ipv4_addr_rm: (rx_q[0]): [0] interface 0x202030e8 address 100.84.56.8 removed
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_change_phase_debug: (rx_q[0]): [0x20207318] phase RUNNING (4) => TERMINATE (5) (ppp_network_down():37)
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_network_down: (rx_q[0]): [0x20207318] Proto IPv4 (0x0021) down (0)
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_fsm_close: (rx_q[0]): [IPCP/0x20207420] Current state STARTING (1)
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_change_state_debug: (rx_q[0]): [IPCP/0x20207420] state STARTING (1) => INITIAL (0) (ppp_fsm_close():240)
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_fsm_lower_down: (rx_q[0]): [IPV6CP/0x202074f8] Current state ACK_RECEIVED (7)
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_change_state_debug: (rx_q[0]): [IPV6CP/0x202074f8] state ACK_RECEIVED (7) => STARTING (1) (ppp_fsm_lower_down():268)
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_fsm_close: (rx_q[0]): [IPV6CP/0x202074f8] Current state STARTING (1)
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_change_state_debug: (rx_q[0]): [IPV6CP/0x202074f8] state STARTING (1) => INITIAL (0) (ppp_fsm_close():240)
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_fsm_lower_down: (rx_q[0]): [PAP/0x202075c0] Current state CLOSED (2)
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_change_state_debug: (rx_q[0]): [PAP/0x202075c0] state CLOSED (2) => INITIAL (0) (ppp_fsm_lower_down():273)
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_change_phase_debug: (rx_q[0]): [0x20207318] phase TERMINATE (5) => DEAD (0) (ppp_link_down():133)
[00:05:14.265,000] <dbg> net_l2_ppp: ppp_change_phase_debug: (rx_q[0]): [0x20207318] phase DEAD (0) => ESTABLISH (1) (lcp_down():163)
[00:05:14.266,000] <dbg> net_l2_ppp: ppp_send_pkt: (rx_q[0]): [LCP/0x20207350] Sending 6 bytes pkt 0x20273390 (options len 0)
[00:05:14.266,000] <dbg> net_if: net_if_tx: (ppp_tx): Processing (pkt 0x20273390, prio 1) network packet iface 0x202030e8/2
[00:05:14.266,000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[00:05:14.266,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x20273390
                                     c0 21 06 03 00 04                                |.!....           
[00:05:14.266,000] <dbg> net_ppp: net_pkt_hexdump: send ppp
[00:05:14.266,000] <dbg> net_ppp: net_pkt_hexdump: 0x20273390
                                  c0 21 06 03 00 04                                |.!....           
[00:05:14.267,000] <dbg> conn_mgr: conn_mgr_ipv4_events_handler: (net_mgmt): IPv4 event 0xe0040002 received on iface 2 (0x202030e8)
[00:05:14.267,000] <dbg> conn_mgr: conn_mgr_ipv4_events_handler: (net_mgmt): Iface index 1
[00:05:14.268,000] <dbg> net_ppp: ppp_input_byte: Address byte (0xff) start
[00:05:14.268,000] <dbg> net_ppp: ppp_change_state: (ppp_workq): [0x202076f8] state ADDRESS (1) => DATA (2)
[00:05:14.273,000] <dbg> net_ppp: ppp_input_byte: End of pkt (0x7e)
[00:05:14.273,000] <dbg> net_ppp: ppp_change_state: (ppp_workq): [0x202076f8] state DATA (2) => ADDRESS (1)
[00:05:14.273,000] <dbg> net_ppp: net_pkt_hexdump: recv ppp
[00:05:14.273,000] <dbg> net_ppp: net_pkt_hexdump: 0x20274270
                                  ff 03 c0 21 01 04 00 18  01 04 05 94 02 06 00 00 |...!.... ........
                                  00 00 05 06 50 cb e4 1e  07 02 08 02 7a 5c       |....P... ....z\  
[00:05:14.273,000] <dbg> net_ppp: ppp_consume_ringbuf: Ringbuf 0x20207f1c is empty!
[00:05:14.273,000] <dbg> net_l2_ppp: net_pkt_hexdump: recv L2
[00:05:14.273,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x20274270
                                     c0 21 01 04 00 18 01 04  05 94 02 06 00 00 00 00 |.!...... ........
                                     05 06 50 cb e4 1e 07 02  08 02                   |..P..... ..      
[00:05:14.273,000] <dbg> net_l2_ppp: ppp_fsm_input: (rx_q[0]): [LCP/0x20207350] LCP Configure-Req (1) id 4 payload len 20
[00:05:14.273,000] <dbg> net_l2_ppp: fsm_recv_configure_req: (rx_q[0]): [LCP/0x20207350] Current state STOPPING (5)
[00:05:15.267,000] <dbg> net_ppp: ppp_consume_ringbuf: Ringbuf 0x20207f1c is empty!
[00:05:15.267,000] <dbg> net_ppp: ppp_input_byte: Address byte (0xff) start
[00:05:15.267,000] <dbg> net_ppp: ppp_change_state: (ppp_workq): [0x202076f8] state ADDRESS (1) => DATA (2)
[00:05:15.269,000] <dbg> net_ppp: ppp_input_byte: End of pkt (0x7e)
[00:05:15.270,000] <dbg> net_ppp: ppp_change_state: (ppp_workq): [0x202076f8] state DATA (2) => ADDRESS (1)
[00:05:15.270,000] <dbg> net_ppp: net_pkt_hexdump: recv ppp
[00:05:15.270,000] <dbg> net_ppp: net_pkt_hexdump: 0x2027455c
                                  ff 03 c0 21 05 05 00 10  55 73 65 72 20 72 65 71 |...!.... User req
                                  75 65 73 74 94 c3                                |uest..           
[00:05:15.270,000] <dbg> net_ppp: ppp_consume_ringbuf: Ringbuf 0x20207f1c is empty!
[00:05:15.270,000] <dbg> net_l2_ppp: net_pkt_hexdump: recv L2
[00:05:15.270,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x2027455c
                                     c0 21 05 05 00 10 55 73  65 72 20 72 65 71 75 65 |.!....Us er reque
                                     73 74                                            |st               
[00:05:15.270,000] <dbg> net_l2_ppp: ppp_fsm_input: (rx_q[0]): [LCP/0x20207350] LCP Terminate-Req (5) id 5 payload len 12
[00:05:15.270,000] <dbg> net_l2_ppp: fsm_recv_terminate_req: (rx_q[0]): [LCP/0x20207350] Current state STOPPING (5)
[00:05:15.270,000] <dbg> net_l2_ppp: fsm_recv_terminate_req: (rx_q[0]): [LCP/0x20207350] Invalid state STOPPING (5)
[00:05:15.277,000] <dbg> net_ppp: ppp_input_byte: Invalid (0x0d) byte, expecting Address
[00:05:15.277,000] <dbg> net_ppp: ppp_change_state: (ppp_workq): [0x202076f8] state ADDRESS (1) => START (0)
[00:05:16.538,000] <dbg> net_if: net_if_tx: (rx_q[0]): Processing (pkt 0x20273390, prio 0) network packet iface 0x20203068/1
[00:05:16.538,000] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20205e88, pkt=0x2027455c, st=0, user_data=(nil)
[00:05:16.750,000] <dbg> net_if: net_if_tx: (tcp_work): Processing (pkt 0x202733d4, prio 0) network packet iface 0x20203068/1
[00:05:19.266,000] <dbg> net_l2_ppp: ppp_fsm_timeout: (sysworkq): [LCP/0x20207350] Current state STOPPING (5)
[00:05:19.266,000] <dbg> net_l2_ppp: ppp_change_state_debug: (sysworkq): [LCP/0x20207350] state STOPPING (5) => STOPPED (3) (ppp_fsm_timeout():136)
[00:05:19.266,000] <dbg> net_l2_ppp: ppp_change_phase_debug: (sysworkq): [0x20207318] phase ESTABLISH (1) => DEAD (0) (ppp_link_terminated():119)
[00:05:19.266,000] <dbg> net_l2_ppp: ppp_link_terminated: (sysworkq): [0x20207318] Link terminated
[00:05:19.391,000] <dbg> net_if: net_if_down: (seModemDriverAppRun): iface 0x202030e8
[00:05:19.391,000] <dbg> net_if: net_if_tx: (seModemDriverAppRun): Processing (pkt 0x20273390, prio 1) network packet iface 0x202030e8/2
[00:05:19.391,000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[00:05:19.391,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x20273390
                                     46 00 00 20 00 00 00 00  01 02 44 d6 00 00 00 00 |F.. .... ..D.....
                                     e0 00 00 02 94 04 00 00  17 00 08 fe e0 00 00 01 |........ ........
[00:05:19.391,000] <dbg> net_if: net_if_ipv4_maddr_rm: (seModemDriverAppRun): interface 0x202030e8 address 224.0.0.1 removed
[00:05:19.392,000] <dbg> conn_mgr: conn_mgr_ipv4_events_handler: (net_mgmt): IPv4 event 0xe004000b received on iface 2 (0x202030e8)
[00:05:19.392,000] <dbg> net_if: update_operational_state: (seModemDriverAppRun): iface 0x202030e8, oper state DOWN admin UP carrier OFF dormant OFF
[00:05:19.392,000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface event 0xd0010001 received on iface 2 (0x202030e8)
[00:05:19.392,000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface index 1
[00:05:19.392,000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface event 0xd0010003 received on iface 2 (0x202030e8)
[00:05:19.392,000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface index 1
[00:05:19.392,000] <dbg> net_if: update_operational_state: (seModemDriverAppRun): iface 0x202030e8, oper state DOWN admin DOWN carrier OFF dormant OFF
[00:05:19.538,000] <dbg> net_if: net_if_tx: (rx_q[0]): Processing (pkt 0x20273390, prio 0) network packet iface 0x20203068/1
[00:05:19.539,000] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20205e88, pkt=0x202742b4, st=0, user_data=(nil)
[00:05:20.662,000] <dbg> net_sock: zsock_socket_internal: (seModemTestAppRun): socket: ctx=0x20205f40, fd=23
[00:05:20.663,000] <dbg> net_ctx: net_context_unref: (seModemTestAppRun): Context 0x20205f40 released
[00:05:22.538,000] <dbg> net_if: net_if_tx: (rx_q[0]): Processing (pkt 0x20273390, prio 0) network packet iface 0x20203068/1
[00:05:22.538,000] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20205e88, pkt=0x202740d8, st=0, user_data=(nil)
[00:05:25.100,000] <dbg> net_sock: zsock_socket_internal: (seModemTestAppRun): socket: ctx=0x20205f40, fd=23
[00:05:25.101,000] <dbg> net_ctx: net_context_unref: (seModemTestAppRun): Context 0x20205f40 released
[00:05:25.537,000] <dbg> net_if: net_if_tx: (rx_q[0]): Processing (pkt 0x20273390, prio 0) network packet iface 0x20203068/1
[00:05:25.537,000] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20205e88, pkt=0x2027411c, st=0, user_data=(nil)
[00:05:25.782,000] <dbg> net_if: net_if_tx: (tcp_work): Processing (pkt 0x202733d4, prio 0) network packet iface 0x20203068/1
[00:05:27.109,000] modem                   DEBUG: --> AT+CEREG?
[00:05:28.538,000] <dbg> net_if: net_if_tx: (rx_q[0]): Processing (pkt 0x20273390, prio 0) network packet iface 0x20203068/1
[00:05:28.538,000] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20205e88, pkt=0x202740d8, st=0, user_data=(nil)
[00:05:29.110,000] modem                   DEBUG: <--  
[00:05:29.161,000] modem                   DEBUG: CEREG Command failed.
[00:05:30.102,000] <dbg> net_sock: zsock_socket_internal: (seModemTestAppRun): socket: ctx=0x20205f40, fd=23
[00:05:30.102,000] <dbg> net_ctx: net_context_unref: (seModemTestAppRun): Context 0x20205f40 released
[00:05:30.172,000] modem                   DEBUG: --> AT+CEREG?
[00:05:30.191,000] modem                   DEBUG: <-- AT+CEREG?  /+CEREG: 0,0 / /OK /
[00:05:31.252,000] modem                   DEBUG: --> AT+CEREG?
[00:05:31.257,000] modem                   DEBUG: <-- AT+CEREG?  /+CEREG: 0,0 / /OK /
[00:05:31.537,000] <dbg> net_if: net_if_tx: (rx_q[0]): Processing (pkt 0x20273390, prio 0) network packet iface 0x20203068/1
[00:05:31.538,000] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20205e88, pkt=0x202740d8, st=0, user_data=(nil)
[00:05:32.308,000] modem                   DEBUG: Buffer was not empty before command.
[00:05:32.308,000] modem                   DEBUG: <--  /RDY / /+CFUN: 1 / /+CPIN: READY / /+QUSIM: 1 /
[00:05:32.310,000] modem                   DEBUG: --> AT+CEREG?
[00:05:32.316,000] modem                   DEBUG: <-- AT+CEREG?  /+CEREG: 0,2 / /OK /
[00:05:33.367,000] modem                   DEBUG: Buffer was not empty before command.
[00:05:33.368,000] modem                   DEBUG: <--  /+QIND: SMS DONE /
[00:05:33.369,000] modem                   DEBUG: --> AT+CEREG?
[00:05:33.378,000] modem                   DEBUG: <-- AT+CEREG?  /+CEREG: 0,5 / /OK /
[00:05:33.428,000] modem                    INFO: Registered, roaming.
[00:05:33.439,000] modem                   DEBUG: --> AT+QENG="servingcell"
[00:05:33.459,000] modem                   DEBUG: <-- AT+QENG="servingcell"  /+QENG: "servingcell","CONNECT","eMTC","FDD",262,01,19C3804,214,1444,3,3,3,5D3,-99,-13,-84,23, / /OK /
[00:05:34.535,000] <dbg> net_if: net_if_tx: (rx_q[0]): Processing (pkt 0x20273390, prio 0) network packet iface 0x20203068/1
[00:05:34.535,000] <dbg> net_sock: zsock_received_cb: (rx_q[0]): ctx=0x20205e88, pkt=0x202740d8, st=0, user_data=(nil)
[00:05:35.103,000] <dbg> net_sock: zsock_socket_internal: (seModemTestAppRun): socket: ctx=0x20205f40, fd=23
[00:05:35.104,000] <dbg> net_ctx: net_context_unref: (seModemTestAppRun): Context 0x20205f40 released
[00:05:36.510,000] modem                   DEBUG: Buffer was not empty before command.
[00:05:36.511,000] modem                   DEBUG: <--  /APP RDY /
[00:05:36.511,000] modem                   DEBUG: --> AT+QCSQ
[00:05:36.519,000] modem                   DEBUG: <-- AT+QCSQ  /+QCSQ: "eMTC",-87,-100,210,-12 / /OK /
[00:05:36.580,000] modem                   DEBUG: --> AT+CGACT?
[00:05:36.589,000] modem                   DEBUG: <-- AT+CGACT?  /+CGACT: 1,1 /+CGACT: 2,0 /+CGACT: 3,0 /+CGACT: 4,0 /+CGACT: 5,0 / /OK /
[00:05:36.650,000] modem                   DEBUG: --> AT+CGDCONT=1,"IP","iot.1nce.net"
[00:05:36.657,000] modem                   DEBUG: <-- AT+CGDCONT=1,"IP","iot.1nce.net"  /OK /
[00:05:36.718,000] modem                   DEBUG: --> AT+CGPADDR
[00:05:36.729,000] modem                   DEBUG: <-- AT+CGPADDR  /+CGPADDR: 1,"100.84.56.8" / /+CGPADDR: 2 / /+CGPADDR: 3 / /+CGPADDR: 4 / /+CGPADDR: 5 / /OK /
[00:05:36.790,000] modem                   DEBUG: --> ATD*99#;
[00:05:36.794,000] modem                   DEBUG: <-- ATD*99#;  /CONNECT / /OK /
[00:05:36.844,000] <dbg> net_if: net_if_up: (seModemDriverAppRun): iface 0x202030e8
[00:05:36.844,000] <dbg> net_ppp: ppp_start: Initializing PPP to use uart@4018c000
[00:05:36.844,000] <dbg> net_if: update_operational_state: (seModemDriverAppRun): iface 0x202030e8, oper state DOWN admin DOWN carrier ON dormant OFF
[00:05:36.845,000] <dbg> net_if: net_if_ipv4_maddr_add: (seModemDriverAppRun): interface 0x202030e8 address 224.0.0.1 added
[00:05:36.845,000] <dbg> conn_mgr: conn_mgr_ipv4_events_handler: (net_mgmt): IPv4 event 0xe0040003 received on iface 2 (0x202030e8)
[00:05:36.845,000] <dbg> conn_mgr: conn_mgr_ipv4_events_handler: (net_mgmt): Iface index 1
[00:05:36.845,000] <dbg> net_if: update_operational_state: (seModemDriverAppRun): iface 0x202030e8, oper state UP admin UP carrier ON dormant OFF
[00:05:36.845,000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface event 0xd0010002 received on iface 2 (0x202030e8)
[00:05:36.845,000] <dbg> conn_mgr: conn_mgr_iface_events_handler: (net_mgmt): Iface index 1
[00:05:36.845,000] <dbg> net_l2_ppp: ppp_change_phase_debug: (net_mgmt): [0x20207318] phase DEAD (0) => ESTABLISH (1) (ppp_open_async():202)
[00:05:36.845,000] <dbg> net_l2_ppp: ppp_open_async: (net_mgmt): Starting LCP
[00:05:36.845,000] <dbg> net_l2_ppp: ppp_fsm_lower_up: (net_mgmt): [LCP/0x20207350] Current state STOPPED (3)
[00:05:36.845,000] <dbg> net_l2_ppp: ppp_fsm_lower_up: (net_mgmt): [LCP/0x20207350] Invalid state STOPPED (3)
[00:05:36.845,000] <dbg> net_l2_ppp: ppp_fsm_open: (net_mgmt): [LCP/0x20207350] Current state STOPPED (3)
uart:~$ net ppp
PPP phase           : ESTABLISH (1)
LCP state           : STOPPED (3)
LCP retransmits     : 0
LCP NACK loops      : 0
LCP NACKs recv      : 0
LCP current id      : 1
LCP ACK received    : yes
IPCP state          : INITIAL (0)
IPCP retransmits    : 10
IPCP NACK loops     : 0
IPCP NACKs recv     : 0
IPCP current id     : 2
IPCP ACK received   : yes
IPv6CP state        : INITIAL (0)
IPv6CP retransmits  : 10
IPv6CP NACK loops   : 0
IPv6CP NACKs recv   : 0
IPv6CP current id   : 1
IPv6CP ACK received : yes
PAP state           : INITIAL (0)
PAP retransmits     : 0
PAP NACK loops      : 0
PAP NACKs recv      : 0
PAP current id      : 0
PAP ACK received    : no

Environment (please complete the following information):

• OS: Linux
• Toolchain Zephyr SDK 16.1
• Zephyr 3.6

[jukkar]

Please create a proper issue of this, no need to waste time in discussions.

[ljdevdev]

Ok, will do.