Zephyr & PPP GSM Modem without RTS/CTS

Hi, I have a problem configuring the PPP Modem correctly and I'm not quite sure what i'm missing here.

I'm running the code on a custom board. We are using nRF52832 to talk to Telit ML865G1 modem over UART and we don't have any HW control pins implemented so it's pretty much just RX&TX.

Everything seems to be functioning correctly but the response from modem is not being received by nRF52.

  • modem is powered and activated.
  • UART get correctly initialized
  • modem list (shell) lists the modem on the correct UART Iface
  • I scoped the UART lines and the AT command that's called by gsm_ppp_start->gsm_configure gets sent correctly with correct baud rate
  • The correct AT OK response is also generated by the modem and is detected both by a scope & a USB to serial converter
  • we also have an NRF5 sdk based solution that is able to successfully comunicate with the modem on the same board

however, with net_dbg logging enabled the modem generates the following error:

modem_gsm.gsm_configure: modem not ready -116

My suspicion is that the configurations i'm trying to run this in doesn't work unless RTS/CTS pins are implemented. Could you suggest something to troubleshoot this further or some other configuration combo that i'm missing here.

Code, board definitions and configuration provided below.

Here's a snippet of our custom board.dts:

 &uart0 {
	 status = "okay";
	 compatible = "nordic,nrf-uarte";
	 current-speed = <9600>;
	 tx-pin = <6>;
	 rx-pin = <8>;
	 label = "HTS_UART_0";
	 rts-pin = <0xFFFFFFFF>;
	 cts-pin = <0xFFFFFFFF>;
 };

I'm also using an additional overlay file with the following contents:

&uart0 {
	status = "okay";
	current-speed = <115200>;
	/delete-property/ rts-pin;
	/delete-property/ cts-pin;
	gsm: gsm-modem {
		compatible = "zephyr,gsm-ppp";
		label = "gsm_ppp";
		status = "okay";
	};
};

Here's the relevant bits of prj.conf:

CONFIG_UART_ASYNC_API=y

CONFIG_UART_0_ASYNC=y
CONFIG_UART_0_INTERRUPT_DRIVEN=n

CONFIG_MODEM=y
CONFIG_MODEM_GSM_PPP=y

CONFIG_NET_DRIVERS=y
CONFIG_NET_PPP=y
CONFIG_NET_L2_PPP=y
CONFIG_NET_NATIVE=y
CONFIG_NETWORKING=y

CONFIG_GSM_PPP_AUTOSTART=n

CONFIG_NET_PPP_ASYNC_UART=y

Here's the code itself:

const struct device *uart_dev = DEVICE_DT_GET(DT_BUS(DT_INST(0, zephyr_gsm_ppp)));
	gsm_dev = DEVICE_DT_GET(DT_INST(0, zephyr_gsm_ppp));

	LOG_INF("Board '%s' APN '%s' UART '%s' device %p (%s)",
		CONFIG_BOARD, CONFIG_MODEM_GSM_APN,
		DT_BUS_LABEL(DT_INST(0, zephyr_gsm_ppp)), uart_dev,
		gsm_dev->name);

	net_mgmt_init_event_callback(&mgmt_cb, event_handler,
				     NET_EVENT_L4_CONNECTED |
				     NET_EVENT_L4_DISCONNECTED);
	net_mgmt_add_event_callback(&mgmt_cb);

	LOG_INF("Modem Device INIT");

	gsm_ppp_start(gsm_dev);

It's pretty much a verbatim copy of net/gsm_modem example.

Parents
  • Hello Nikolozka,

    Thanks a lot for your detailed input.

    Could you suggest something to troubleshoot this further or some other configuration combo that i'm missing here.

    A little bit hard to tell what could be the problem here. But I assume you are using the nRF5 SDK based solution without flow control as well?

    My suspicion is that the configurations i'm trying to run this in doesn't work unless RTS/CTS pins are implemented.

    I’m not sure if flow control actually is the problem here, but just to double-check you could call the uart_config_get() function and check if flow control is disabled.

    Otherwise, it might be a good idea to check ../<build_folder>/zephyr/zephyr.dts to confirm that all overlay settings have been taken into account.

    Regards,

    Markus

Reply
  • Hello Nikolozka,

    Thanks a lot for your detailed input.

    Could you suggest something to troubleshoot this further or some other configuration combo that i'm missing here.

    A little bit hard to tell what could be the problem here. But I assume you are using the nRF5 SDK based solution without flow control as well?

    My suspicion is that the configurations i'm trying to run this in doesn't work unless RTS/CTS pins are implemented.

    I’m not sure if flow control actually is the problem here, but just to double-check you could call the uart_config_get() function and check if flow control is disabled.

    Otherwise, it might be a good idea to check ../<build_folder>/zephyr/zephyr.dts to confirm that all overlay settings have been taken into account.

    Regards,

    Markus

Children
  • Hi, Thanks for the response. I've narrowed things down a little bit.

    after working through zephyr files and enabling a ton of logging options i figured out the following:

    there a function driver/net/ppp/ppp_async_uart_rx_enable() that is part of ppp.c file. now this is the function that actually enables RX on the UART. This function is in turn being called by driver/net/ppp/ppp_start() (this function is exposed through (struct ppp_api->start)

    The modem example calls driver/modme/gsm_ppp_start() (defined in gsm_ppp.c) which is in turn supposed to call the abovementioned ppp_start() however it seems like to reach ppp_api->start() it already has to have received a response on to AT on UART. 

    I'm not sure if i'm doing something rather wrong or if this is indeed a bug? maybe some problem with init order?

    In any case by manually getting the reference to ppp driver:

    	
    	gsm_dev = DEVICE_DT_GET(DT_INST(0, zephyr_gsm_ppp));
    	const struct device *ppp_dev = device_get_binding(CONFIG_NET_PPP_DRV_NAME);
    	const struct ppp_api *api = (const struct ppp_api *)ppp_dev->api;
    
    	int ret;
    
    	ret = api->start(ppp_dev);
    		if (ret) {
    			LOG_ERR("ppp start returned %d", ret);
    	}
    	
    	/////////////////////////////
    	
    	gsm_ppp_start(gsm_dev);
    

    I'm able to catch a "Network Connected" state with the net_mgmt callback.

    This generates more log output than i'm able to allocate ram for (64kb on nRF52832)

    The problem that i'm now facing though is that none of the modem info get's populated & net ping times out.

    I haven't had much time to investigate this past this point, but i'll update this thread as i make more progress....

    In the meantime could you tell me if i'm doing something wrong by manualy calling pp_api->start() ?

    another question:

    Am i expected to significantly extend the modem code and implement the modem myself or am I supposed to rely on the gsm_ppp implementation (assuming my modem supports ppp) - this is a bit ambiguous.

    !!!EDIT: 

    I spoke too soon.

    In my attempts to get this runing i' hade the call to gsm_ppp_start commented out.

    Here's th actual code:

    	const struct device *uart_dev = DEVICE_DT_GET(DT_BUS(DT_INST(0, zephyr_gsm_ppp)));
    	gsm_dev = DEVICE_DT_GET(DT_INST(0, zephyr_gsm_ppp));
    
    	const struct device *ppp_dev = device_get_binding(CONFIG_NET_PPP_DRV_NAME);
    	const struct ppp_api *api = (const struct ppp_api *)ppp_dev->api;
    
    	int ret;
    
    	ret = api->start(ppp_dev);
    		if (ret) {
    			LOG_ERR("ppp start returned %d", ret);
    	}
    
    
    	LOG_INF("Board '%s' APN '%s' UART '%s' device %p (%s)",
    		CONFIG_BOARD, CONFIG_MODEM_GSM_APN,
    		DT_BUS_LABEL(DT_INST(0, zephyr_gsm_ppp)), uart_dev,
    		gsm_dev->name);
    
    	net_mgmt_init_event_callback(&mgmt_cb, event_handler,
    				     NET_EVENT_L4_CONNECTED |
    				     NET_EVENT_L4_DISCONNECTED);
    	net_mgmt_add_event_callback(&mgmt_cb);
    
    	LOG_INF("Modem Device INIT");
    
    	//gsm_ppp_start(gsm_dev);

    In addition to that 

    CONFIG_GSM_PPP_AUTOSTART=n
    Here's the massive log this generates - i'm not sure how to interpret this especially since a lot of logs are dropped
    00> 
    00> 
    00> rtt:~$ [00:00:00.000,854] <dbg> net_ppp.ppp_driver_init: [0x20002a90] dev 0x1ef14
    00> rtt:~$ [00:00:00.001,251] <dbg> modem_gsm.gsm_init: Generic GSM modem (0x20001100)
    00> rtt:~$ [00:00:00.001,281] <dbg> modem_gsm.gsm_init: iface->read 0x1d035 iface->write 0x1d06b
    00> rtt:~$ [00:00:00.001,342] <dbg> modem_gsm.gsm_rx: starting
    00> rtt:~$ [00:00:00.001,556] <inf> regulator_fixed: V3V3_PWR onoff: 0
    00> rtt:~$ 
    00> rtt:~$ [00:00:00.015,838] <dbg> net_mgmt.net_mgmt_event_init: (main): Net MGMT initialized: queue of 2 entries, stack size of 768
    00> rtt:~$ [00:00:00.015,869] <dbg> net_ppp.ppp_iface_init: [0x20002a90] iface 0x20000a00
    00> rtt:~$ [00:00:00.015,899] <dbg> net_l2_ppp.net_ppp_init: (main): Initializing PPP L2 0x20002860 for iface 0x20000a00
    00> rtt:~$ [00:00:00.015,991] <dbg> net_l2_ppp.ppp_startup: (sysworkq): PPP 0x20002860 startup for interface 0x20000a00
    00> rtt:~$ [00:00:00.016,021] <dbg> net_l2_ppp.ipcp_init: (sysworkq): proto IPCP (0x8021) fsm 0x20002978
    00> rtt:~$ 
    00> rtt:~$ --- 36 messages dropped ---
    00> rtt:~$ [00:00:00.016,082] <dbg> net_l2_ppp.lcp_init: (sysworkq): proto LCP (0xc021) fsm 0x200028a8
    00> rtt:~$ [00:00:05.665,130] <dbg> net_ppp.ppp_input_byte: Address byte (0xff) start
    00> rtt:~$ [00:00:05.665,161] <dbg> net_ppp.ppp_change_state: (<log_strdup alloc failed>): [0x20002a90] state ADDRESS (1) => DATA (2)
    00> rtt:~$ [00:00:05.665,252] <dbg> net_ppp.ppp_input_byte: End of pkt (0x7e)
    00> rtt:~$ [00:00:05.665,252] <dbg> net_ppp.ppp_change_state: (<log_strdup alloc failed>): [0x20002a90] state DATA (2) => ADDRESS (1)
    00> rtt:~$ [00:00:05.665,283] <dbg> net_ppp.net_pkt_hexdump: recv ppp
    00> rtt:~$ [00:00:05.665,313] <dbg> net_ppp: <log_strdup alloc failed>
    00>                                   ff 03 c0 21 01 01 00 04  d1 b5                   |...!.... ..      
    00> rtt:~$ [00:00:05.665,344] <dbg> net_ppp.ppp_consume_ringbuf: Ringbuf 0x200033e4 is empty!
    00> rtt:~$ [00:00:05.665,374] <dbg> net_l2_ppp.net_pkt_hexdump: recv L2
    00> rtt:~$ [00:00:05.665,405] <dbg> net_l2_ppp: <log_strdup alloc failed>
    00>                                      c0 21 01 01 00 04                                |.!....           
    00> rtt:~$ 
    00> rtt:~$ [00:00:05.665,435] <dbg> net_l2_ppp.ppp_fsm_input: (<log_strdup alloc failed>): [LCP/0x200028a8] LCP Configure-Req (1) id 1 payload len 0
    00> rtt:~$ 
    00> rtt:~$ [00:00:05.665,466] <dbg> net_l2_ppp.fsm_recv_configure_req: (<log_strdup alloc failed>): [LCP/0x200028a8] Current state REQUEST_SENT (6)
    00> rtt:~$ [00:00:05.665,527] <dbg> net_l2_ppp.fsm_recv_configure_req: (<log_strdup alloc failed>): [LCP/0x200028a8] Sending Configure-Ack (2) id 1 to peer while in REQUEST_SENT (6)
    00> rtt:~$ [00:00:05.665,557] <dbg> net_l2_ppp.ppp_send_pkt: (<log_strdup alloc failed>): [LCP/0x200028a8] Sending 6 bytes pkt 0x2000d4a4 (options len 0)
    00> rtt:~$ [00:00:05.665,588] <dbg> net_l2_ppp.ppp_change_state_debug: (<log_strdup alloc failed>): [LCP/0x200028a8] state REQUEST_SENT (6) => ACK_SENT (8) (fsm_recv_configure_req():651)
    00> rtt:~$ [00:00:05.665,618] <dbg> net_l2_ppp.net_pkt_hexdump: send L2
    00> rtt:~$ [00:00:05.665,679] <dbg> net_l2_ppp: <log_strdup alloc failed>
    00>                                      c0 21 02 01 00 04                                |.!....           
    00> rtt:~$ [00:00:05.665,679] <dbg> net_ppp.net_pkt_hexdump: send ppp
    00> rtt:~$ [00:00:05.665,740] <dbg> net_ppp: <log_strdup alloc failed>
    00>                                   c0 21 02 01 00 04                                |.!....           
    00> rtt:~$ [00:00:05.667,327] <dbg> net_ppp.uart_callback: UART_TX_DONE: sent 18 bytes
    00> rtt:~$ [00:00:05.785,186] <dbg> net_ppp.uart_callback: Received data 18 bytes
    00> rtt:~$ 
    00> rtt:~$ [00:00:05.785,247] <dbg> net_ppp.ppp_input_byte: Address byte (0xff) start
    00> rtt:~$ 
    00> rtt:~$ [00:00:05.785,247] <dbg> net_ppp.ppp_change_state: (<log_strdup alloc failed>): [0x20002a90] state ADDRESS (1) => DATA (2)
    00> rtt:~$ [00:00:05.785,339] <dbg> net_ppp.ppp_input_byte: End of pkt (0x7e)
    00> rtt:~$ [00:00:05.785,369] <dbg> net_ppp.ppp_change_state: (<log_strdup alloc failed>): [0x20002a90] state DATA (2) => ADDRESS (1)
    00> rtt:~$ [00:00:05.785,369] <dbg> net_ppp.net_pkt_hexdump: recv ppp
    00> rtt:~$ [00:00:05.785,430] <dbg> net_ppp: <log_strdup alloc failed>
    00>                                   ff 03 c0 21 02 01 00 04  1c 90                   |...!.... ..      
    00> rtt:~$ [00:00:05.785,430] <dbg> net_ppp.ppp_consume_ringbuf: Ringbuf 0x200033e4 is empty!
    00> rtt:~$ [00:00:05.785,461] <dbg> net_l2_ppp.net_pkt_hexdump: recv L2
    00> rtt:~$ [00:00:05.785,522] <dbg> net_l2_ppp: <log_strdup alloc failed>
    00>                                      c0 21 02 01 00 04                                |.!....           
    00> rtt:~$ [00:00:05.785,552] <dbg> net_l2_ppp.ppp_fsm_input: (<log_strdup alloc failed>): [LCP/0x200028a8] LCP Configure-Ack (2) id 1 payload len 0
    00> rtt:~$ [00:00:05.785,552] <dbg> net_l2_ppp.fsm_recv_configure_ack: (<log_strdup alloc failed>): [LCP/0x200028a8] Current state ACK_SENT (8)
    00> rtt:~$ 
    00> rtt:~$ [00:00:05.785,583] <dbg> net_l2_ppp.ppp_change_state_debug: (<log_strdup alloc failed>): [LCP/0x200028a8] state ACK_SENT (8) => OPENED (9) (fsm_recv_configure_ack():705)
    00> rtt:~$ [00:00:05.785,583] <dbg> net_l2_ppp.ppp_link_established: (<log_strdup alloc failed>): [0x20002860] Link established
    00> rtt:~$ [00:00:05.785,614] <dbg> net_l2_ppp.ppp_change_phase_debug: (<log_strdup alloc failed>): [0x20002860] phase ESTABLISH (1) => AUTH (2) (do_auth():74)
    00> rtt:~$ [00:00:05.785,614] <dbg> net_l2_ppp.ppp_link_authenticated: (<log_strdup alloc failed>): [0x20002860] Link authenticated
    00> rtt:~$ [00:00:05.785,644] <dbg> net_l2_ppp.ppp_change_phase_debug: (<log_strdup alloc failed>): [0x20002860] phase AUTH (2) => NETWORK (3) (do_network():34)
    00> rtt:~$ [00:00:05.785,644] <dbg> net_l2_ppp.ppp_fsm_open: (<log_strdup alloc failed>): [IPCP/0x20002978] Current state INITIAL (0)
    00> rtt:~$ [00:00:05.785,675] <dbg> net_l2_ppp.ppp_change_state_debug: (<log_strdup alloc failed>): [IPCP/0x20002978] state INITIAL (0) => STARTING (1) (ppp_fsm_open():348)
    00> rtt:~$ [00:00:05.785,675] <dbg> net_l2_ppp.ppp_fsm_lower_up: (<log_strdup alloc failed>): [IPCP/0x20002978] Current state STARTING (1)
    00> rtt:~$ 
    00> rtt:~$ [00:00:05.785,797] <dbg> net_l2_ppp.fsm_send_configure_req: (<log_strdup alloc failed>): [IPCP/0x20002978] Sending Configure-Req (1) id 1 to peer while in STARTING (1)
    00> rtt:~$ [00:00:05.785,827] <dbg> net_l2_ppp.ppp_send_pkt: (<log_strdup alloc failed>): [IPCP/0x20002978] Sending 24 bytes pkt 0x2000d4a4 (options len 18)
    00> rtt:~$ [00:00:05.785,858] <dbg> net_l2_ppp.ppp_change_state_debug: (<log_strdup alloc failed>): [IPCP/0x20002978] state STARTING (1) => REQUEST_SENT (6) (ppp_fsm_lower_up():316)
    00> rtt:~$ 
    00> rtt:~$ [00:00:05.785,888] <dbg> net_l2_ppp.net_pkt_hexdump: send L2
    00> rtt:~$ [00:00:05.785,949] <dbg> net_l2_ppp: <log_strdup alloc failed>
    00>                                      80 21 01 01 00 16                                |.!....           
    00> rtt:~$ [00:00:05.785,949] <dbg> net_l2_ppp: <log_strdup alloc failed>
    00>                                      03 06 00 00 00 00 81 06  00 00 00 00 83 06 00 00 |........ ........
    00>                                      00 00                                            |..               
    00> rtt:~$ [00:00:05.785,980] <dbg> net_ppp.net_pkt_hexdump: send ppp
    00> rtt:~$ [00:00:05.786,010] <dbg> net_ppp: <log_strdup alloc failed>
    00>                                   80 21 01 01 00 16                                |.!....           
    00> rtt:~$ [00:00:05.786,041] <dbg> net_ppp: <log_strdup alloc failed>
    00>                                   03 06 00 00 00 00 81 06  00 00 00 00 83 06 00 00 |........ ........
    00>                                   00 00                                            |..               
    00> rtt:~$ [00:00:05.790,527] <dbg> net_ppp.uart_callback: UART_TX_DONE: sent 51 bytes
    00> rtt:~$ [00:00:05.905,303] <dbg> net_ppp.uart_callback: Received data 51 bytes
    00> rtt:~$ rtt:~$ [00:00:05.905,364] <dbg> net_ppp.ppp_input_byte: Address byte (0xff) start
    00> rtt:~$ [00:00:05.905,364] <dbg> net_ppp.ppp_change_state: (<log_strdup alloc failed>): [0x20002a90] state ADDRESS (1) => DATA (2)
    00> rtt:~$ [00:00:05.905,578] <dbg> net_ppp.ppp_input_byte: End of pkt (0x7e)
    00> rtt:~$ 
    00> rtt:~$ [00:00:05.905,609] <dbg> net_ppp.ppp_change_state: (<log_strdup alloc failed>): [0x20002a90] state DATA (2) => ADDRESS (1)
    00> rtt:~$ [00:00:05.905,609] <dbg> net_ppp.net_pkt_hexdump: recv ppp
    00> rtt:~$ [00:00:05.905,639] <dbg> net_ppp: <log_strdup alloc failed>
    00>                                   ff 03 80 21 01 01 00 16  03 06 00 00 00 00 81 06 |...!.... ........
    00>                                   00 00 00 00 83 06 00 00  00 00 6e db             |........ ..n.    
    00> rtt:~$ [00:00:05.905,670] <dbg> net_ppp.ppp_consume_ringbuf: Ringbuf 0x200033e4 is empty!
    00> rtt:~$ [00:00:05.905,700] <dbg> net_l2_ppp.net_pkt_hexdump: recv L2
    00> rtt:~$ [00:00:05.905,761] <dbg> net_l2_ppp: <log_strdup alloc failed>
    00>                                      80 21 01 01 00 16 03 06  00 00 00 00 81 06 00 00 |.!...... ........
    00>                                      00 00 83 06 00 00 00 00                          |........         
    00> rtt:~$ [00:00:05.905,792] <dbg> net_l2_ppp.ppp_fsm_input: (<log_strdup alloc failed>): [IPCP/0x20002978] IPCP Configure-Req (1) id 1 payload len 18
    00> rtt:~$ [00:00:05.905,822] <dbg> net_l2_ppp.fsm_recv_configure_req: (<log_strdup alloc failed>): [IPCP/0x20002978] Current state REQUEST_SENT (6)
    00> rtt:~$ 
    00> rtt:~$ [00:00:05.905,883] <dbg> net_l2_ppp.ppp_parse_options: (<log_strdup alloc failed>): [IPCP/0x20002978] option IP_ADDRESS (3) len 6
    00> rtt:~$ [00:00:05.905,883] <dbg> net_l2_ppp.ppp_parse_option_conf_req_unsupported: (<log_strdup alloc failed>): [IPCP/0x20002978] Check option IP_ADDRESS (3) len 4
    00> rtt:~$ [00:00:05.905,914] <dbg> net_l2_ppp.ppp_parse_options: (<log_strdup alloc failed>): [IPCP/0x20002978] option DNS1 (129) len 6
    00> rtt:~$ 
    00> rtt:~$ [00:00:05.905,944] <dbg> net_l2_ppp.ppp_parse_option_conf_req_unsupported: (<log_strdup alloc failed>): [IPCP/0x20002978] Check option DNS1 (129) len 4
    00> rtt:~$ [00:00:05.905,975] <dbg> net_l2_ppp.ppp_parse_options: (<log_strdup alloc failed>): [IPCP/0x20002978] option DNS2 (131) len 6
    00> rtt:~$ [00:00:05.905,975] <dbg> net_l2_ppp.ppp_parse_option_conf_req_unsupported: (<log_strdup alloc failed>): [IPCP/0x20002978] Check option DNS2 (131) len 4
    00> rtt:~$ [00:00:05.906,036] <dbg> net_l2_ppp.fsm_recv_configure_req: (<log_strdup alloc failed>): [IPCP/0x20002978] Sending Configure-Rej (4) id 1 to peer while in REQUEST_SENT (6)
    00> rtt:~$ [00:00:05.906,066] <dbg> net_l2_ppp.ppp_send_pkt: (<log_strdup alloc failed>): [IPCP/0x20002978] Sending 18 bytes pkt 0x2000d4a4 (options len 12)
    00> rtt:~$ [00:00:05.906,097] <dbg> net_l2_ppp.net_pkt_hexdump: send L2
    00> rtt:~$ [00:00:05.906,158] <dbg> net_l2_ppp: <log_strdup alloc failed>
    00>                                      80 21 04 01 00 10                                |.!....           
    00> rtt:~$ [00:00:05.906,158] <dbg> net_l2_ppp: <log_strdup alloc failed>
    00>                                      81 06 00 00 00 00 83 06  00 00 00 00             |........ ....    
    00> rtt:~$ [00:00:05.906,188] <dbg> net_ppp.net_pkt_hexdump: send ppp
    00> rtt:~$ 
    00> rtt:~$ [00:00:05.906,219] <dbg> net_ppp: <log_strdup alloc failed>
    00>                                   80 21 04 01 00 10                                |.!....           
    00> rtt:~$ [00:00:05.906,219] <dbg> net_ppp: <log_strdup alloc failed>
    00>                                   81 06 00 00 00 00 83 06  00 00 00 00             |........ ....    
    00> rtt:~$ 
    00> rtt:~$ [00:00:05.909,667] <dbg> net_ppp.uart_callback: UART_TX_DONE: sent 39 bytes
    00> rtt:~$ [00:00:06.025,421] <dbg> net_ppp.uart_callback: Received data 39 bytes
    00> rtt:~$ [00:00:06.025,482] <dbg> net_ppp.ppp_input_byte: Address byte (0xff) start
    00> rtt:~$ [00:00:06.025,482] <dbg> net_ppp.ppp_change_state: (<log_strdup alloc failed>): [0x20002a90] state ADDRESS (1) => DATA (2)
    00> rtt:~$ [00:00:06.025,665] <dbg> net_ppp.ppp_input_byte: End of pkt (0x7e)
    00> rtt:~$ [00:00:06.025,665] <dbg> net_ppp.ppp_change_state: (<log_strdup alloc failed>): [0x20002a90] state DATA (2) => ADDRESS (1)
    00> rtt:~$ [00:00:06.025,665] <dbg> net_ppp.net_pkt_hexdump: recv ppp
    00> rtt:~$ [00:00:06.025,726] <dbg> net_ppp: <log_strdup alloc failed>
    00>                                   ff 03 80 21 04 01 00 10  81 06 00 00 00 00 83 06 |...!.... ........
    00>                                   00 00 00 00 5f c7                                |...._.           
    00> rtt:~$ [00:00:06.025,756] <dbg> net_ppp.ppp_consume_ringbuf: Ringbuf 0x200033e4 is empty!
    00> rtt:~$ 
    00> rtt:~$ [00:00:06.025,787] <dbg> net_l2_ppp.net_pkt_hexdump: recv L2
    00> rtt:~$ [00:00:06.025,817] <dbg> net_l2_ppp: <log_strdup alloc failed>
    00>                                      80 21 04 01 00 10 81 06  00 00 00 00 83 06 00 00 |.!...... ........
    00>                                      00 00                                            |..               
    00> rtt:~$ [00:00:06.025,878] <dbg> net_l2_ppp.ppp_fsm_input: (<log_strdup alloc failed>): [IPCP/0x20002978] IPCP Configure-Rej (4) id 1 payload len 12
    00> rtt:~$ [00:00:06.025,878] <dbg> net_l2_ppp.fsm_recv_configure_nack_rej: (<log_strdup alloc failed>): [IPCP/0x20002978] Current state REQUEST_SENT (6)
    00> rtt:~$ [00:00:06.025,909] <dbg> net_l2_ppp.ppp_parse_options: (<log_strdup alloc failed>): [IPCP/0x20002978] option DNS1 (129) len 6
    00> rtt:~$ 
    00> rtt:~$ [00:00:06.025,939] <dbg> net_l2_ppp.ppp_parse_options: (<log_strdup alloc failed>): [IPCP/0x20002978] option DNS2 (131) len 6
    00> rtt:~$ [00:00:06.026,031] <dbg> net_l2_ppp.fsm_send_configure_req: (<log_strdup alloc failed>): [IPCP/0x20002978] Sending Configure-Req (1) id 2 to peer while in REQUEST_SENT (6)
    00> rtt:~$ [00:00:06.026,062] <dbg> net_l2_ppp.ppp_send_pkt: (<log_strdup alloc failed>): [IPCP/0x20002978] Sending 12 bytes pkt 0x2000d4a4 (options len 6)
    00> rtt:~$ [00:00:06.026,123] <dbg> net_l2_ppp.net_pkt_hexdump: send L2
    00> rtt:~$ [00:00:06.026,153] <dbg> net_l2_ppp: <log_strdup alloc failed>
    00>                                      80 21 01 02 00 0a                                |.!....           
    00> rtt:~$ [00:00:06.026,153] <dbg> net_l2_ppp: <log_strdup alloc failed>
    00>                                      03 06 00 00 00 00                                |......           
    00> rtt:~$ 
    00> rtt:~$ [00:00:06.026,184] <dbg> net_ppp.net_pkt_hexdump: send ppp
    00> rtt:~$ [00:00:06.026,214] <dbg> net_ppp: <log_strdup alloc failed>
    00>                                   80 21 01 02 00 0a                                |.!....           
    00> rtt:~$ [00:00:06.026,245] <dbg> net_ppp: <log_strdup alloc failed>
    00>                                   03 06 00 00 00 00                                |......           
    00> rtt:~$ [00:00:06.028,869] <dbg> net_ppp.uart_callback: UART_TX_DONE: sent 30 bytes
    00> rtt:~$ [00:00:06.031,036] <dbg> net_ppp.uart_callback: Received data 3 bytes
    00> rtt:~$ 
    00> rtt:~$ [00:00:06.031,066] <dbg> net_ppp.uart_callback: UART_RX_BUF_RELEASED: buf 0x20002aa0
    00> rtt:~$ [00:00:06.031,066] <dbg> net_ppp.uart_callback: UART_RX_BUF_REQUEST: buf 0x20002aa0
    00> rtt:~$ [00:00:06.031,097] <dbg> net_ppp.ppp_input_byte: Address byte (0xff) start
    00> rtt:~$ [00:00:06.031,097] <dbg> net_ppp.ppp_change_state: (<log_strdup alloc failed>): [0x20002a90] state ADDRESS (1) => DATA (2)
    00> rtt:~$ [00:00:06.031,158] <dbg> net_ppp.ppp_consume_ringbuf: Ringbuf 0x200033e4 is empty!
    00> rtt:~$ [00:00:06.151,184] <dbg> net_ppp.uart_callback: Received data 27 bytes
    00> rtt:~$ [00:00:06.151,336] <dbg> net_ppp.ppp_input_byte: End of pkt (0x7e)
    00> rtt:~$ [00:00:06.151,336] <dbg> net_ppp.ppp_change_state: (<log_strdup alloc failed>): [0x20002a90] state DATA (2) => ADDRESS (1)
    00> rtt:~$ 
    00> rtt:~$ [00:00:06.151,336] <dbg> net_ppp.net_pkt_hexdump: recv ppp
    00> rtt:~$ [00:00:06.151,397] <dbg> net_ppp: <log_strdup alloc failed>
    00>                                   ff 03 80 21 01 02 00 0a  03 06 00 00 00 00 14 fe |...!.... ........
    00> rtt:~$ [00:00:06.151,428] <dbg> net_ppp.ppp_consume_ringbuf: Ringbuf 0x200033e4 is empty!
    00> rtt:~$ 
    00> rtt:~$ [00:00:06.151,458] <dbg> net_l2_ppp.net_pkt_hexdump: recv L2
    00> rtt:~$ [00:00:06.151,489] <dbg> net_l2_ppp: <log_strdup alloc failed>
    00>                                      80 21 01 02 00 0a 03 06  00 00 00 00             |.!...... ....    
    00> rtt:~$ [00:00:06.151,519] <dbg> net_l2_ppp.ppp_fsm_input: (<log_strdup alloc failed>): [IPCP/0x20002978] IPCP Configure-Req (1) id 2 payload len 6
    00> rtt:~$ [00:00:06.151,550] <dbg> net_l2_ppp.fsm_recv_configure_req: (<log_strdup alloc failed>): [IPCP/0x20002978] Current state REQUEST_SENT (6)
    00> rtt:~$ [00:00:06.151,611] <dbg> net_l2_ppp.ppp_parse_options: (<log_strdup alloc failed>): [IPCP/0x20002978] option IP_ADDRESS (3) len 6
    00> rtt:~$ [00:00:06.151,641] <dbg> net_l2_ppp.ppp_parse_option_conf_req_unsupported: (<log_strdup alloc failed>): [IPCP/0x20002978] Check option IP_ADDRESS (3) len 4
    00> rtt:~$ [00:00:06.151,672] <dbg> net_l2_ppp.ppp_parse_options: (<log_strdup alloc failed>): [IPCP/0x20002978] option IP_ADDRESS (3) len 6
    00> rtt:~$ [00:00:06.151,672] <dbg> net_l2_ppp.ipcp_ip_address_parse: (<log_strdup alloc failed>): [IPCP] Received peer address <log_strdup alloc failed>
    00> rtt:~$ 
    00> rtt:~$ [00:00:06.151,702] <dbg> net_l2_ppp.fsm_recv_configure_req: (<log_strdup alloc failed>): [IPCP/0x20002978] Sending Configure-Ack (2) id 2 to peer while in REQUEST_SENT (6)
    00> rtt:~$ [00:00:06.151,733] <dbg> net_l2_ppp.ppp_send_pkt: (<log_strdup alloc failed>): [IPCP/0x20002978] Sending 12 bytes pkt 0x2000d4a4 (options len 6)
    00> rtt:~$ [00:00:06.151,763] <dbg> net_l2_ppp.ppp_change_state_debug: (<log_strdup alloc failed>): [IPCP/0x20002978] state REQUEST_SENT (6) => ACK_SENT (8) (fsm_recv_configure_req():651)
    00> rtt:~$ [00:00:06.151,794] <dbg> net_l2_ppp.net_pkt_hexdump: send L2
    00> rtt:~$ [00:00:06.151,855] <dbg> net_l2_ppp: <log_strdup alloc failed>
    00>                                      80 21 02 02 00 0a                                |.!....           
    00> rtt:~$ [00:00:06.151,855] <dbg> net_l2_ppp: <log_strdup alloc failed>
    00>                                      03 06 00 00 00 00                                |......           
    00> rtt:~$ [00:00:06.151,885] <dbg> net_ppp.net_pkt_hexdump: send ppp
    00> rtt:~$ 
    00> rtt:~$ [00:00:06.151,916] <dbg> net_ppp: <log_strdup alloc failed>
    00>                                   80 21 02 02 00 0a                                |.!....           
    00> rtt:~$ [00:00:06.151,947] <dbg> net_ppp: <log_strdup alloc failed>
    00>                                   03 06 00 00 00 00                                |......           
    00> rtt:~$ [00:00:06.154,632] <dbg> net_ppp.uart_callback: UART_TX_DONE: sent 30 bytes
    00> rtt:~$ [00:00:06.271,331] <dbg> net_ppp.uart_callback: Received data 30 bytes
    00> rtt:~$ 
    00> rtt:~$ [00:00:06.271,362] <dbg> net_ppp.ppp_input_byte: Address byte (0xff) start
    00> rtt:~$ [00:00:06.271,423] <dbg> net_ppp.ppp_change_state: (ppp_workq): [0x20002a90] state ADDRESS (1) => DATA (2)
    00> rtt:~$ [00:00:06.271,545] <dbg> net_ppp.ppp_input_byte: End of pkt (0x7e)
    00> rtt:~$ [00:00:06.271,606] <dbg> net_ppp.ppp_change_state: (ppp_workq): [0x20002a90] state DATA (2) => ADDRESS (1)
    00> rtt:~$ [00:00:06.271,636] <dbg> net_ppp.net_pkt_hexdump: recv ppp
    00> rtt:~$ [00:00:06.271,697] <dbg> net_ppp: 0x2000d3b4
    00>                                   ff 03 80 21 02 02 00 0a  03 06 00 00 00 00 7d 8a |...!.... ......}.
    00> rtt:~$ [00:00:06.271,728] <dbg> net_ppp.ppp_consume_ringbuf: Ringbuf 0x200033e4 is empty!
    00> rtt:~$ 
    00> rtt:~$ [00:00:06.271,789] <dbg> net_l2_ppp.net_pkt_hexdump: recv L2
    00> rtt:~$ [00:00:06.271,850] <dbg> net_l2_ppp: 0x2000d3b4
    00>                                      80 21 02 02 00 0a 03 06  00 00 00 00             |.!...... ....    
    00> rtt:~$ [00:00:06.271,911] <dbg> net_l2_ppp.ppp_fsm_input: (rx_q[0]): [IPCP/0x20002978] IPCP Configure-Ack (2) id 2 payload len 6
    00> rtt:~$ [00:00:06.271,942] <dbg> net_l2_ppp.fsm_recv_configure_ack: (rx_q[0]): [IPCP/0x20002978] Current state ACK_SENT (8)
    00> rtt:~$ [00:00:06.272,033] <dbg> net_l2_ppp.ppp_change_state_debug: (rx_q[0]): [IPCP/0x20002978] state ACK_SENT (8) => OPENED (9) (fsm_recv_configure_ack():705)
    00> rtt:~$ [00:00:06.272,094] <dbg> net_mgmt.net_mgmt_event_notify_with_info: (rx_q[0]): Notifying Event layer 2 code 4 type 1
    00> rtt:~$ 
    00> rtt:~$ [00:00:06.272,155] <dbg> net_l2_ppp.ipcp_up: (rx_q[0]): PPP up with address 0.0.0.0
    00> rtt:~$ [00:00:06.272,216] <dbg> net_l2_ppp.ppp_change_phase_debug: (rx_q[0]): [0x20002860] phase NETWORK (3) => RUNNING (4) (ppp_network_up():22)
    00> rtt:~$ [00:00:06.272,277] <dbg> net_l2_ppp.ppp_network_up: (rx_q[0]): [0x20002860] Proto IPv4 (0x0021) up (1)
    00> rtt:~$ [00:00:06.272,308] <dbg> net_l2_ppp.ipcp_up: (rx_q[0]): [IPCP/0x20002978] Current state OPENED (9)
    00> rtt:~$ [00:00:06.272,338] <dbg> net_mgmt.mgmt_thread: (net_mgmt): Handling events, forwarding it relevantly
    00> rtt:~$ 
    00> rtt:~$ [00:00:06.272,369] <dbg> net_mgmt.mgmt_run_callbacks: (<log_strdup alloc failed>): Event layer 2 code 4 cmd 1
    00> rtt:~$ [00:00:06.272,399] <dbg> net_mgmt.mgmt_run_callbacks: (<log_strdup alloc failed>): Running callback 0x20004570 : 0xe5d1
    00> rtt:~$ [00:00:06.272,430] <dbg> conn_mgr.conn_mgr_ipv4_events_handler: (<log_strdup alloc failed>): IPv4 event 3758358529 received on iface 1 (0x20000a00)
    00> rtt:~$ [00:00:06.272,430] <dbg> conn_mgr.conn_mgr_ipv4_events_handler: (<log_strdup alloc failed>): Iface index 0
    00> rtt:~$ [00:00:06.272,460] <dbg> conn_mgr.conn_mgr_ipv4_status: (<log_strdup alloc failed>): IPv4 connected on iface index 1
    00> rtt:~$ [00:00:06.272,491] <dbg> conn_mgr.conn_mgr_notify_status: (<log_strdup alloc failed>): Iface 1 (0x20000a00) connected
    00> rtt:~$ 
    00> rtt:~$ [00:00:06.272,521] <dbg> net_mgmt.net_mgmt_event_notify_with_info: (<log_strdup alloc failed>): Notifying Event layer 3 code 276 type 1
    00> rtt:~$ [00:00:06.272,552] <dbg> net_mgmt.mgmt_thread: (<log_strdup alloc failed>): Handling events, forwarding it relevantly
    00> rtt:~$ [00:00:06.272,583] <dbg> net_mgmt.mgmt_run_callbacks: (<log_strdup alloc failed>): Event layer 3 code 276 cmd 1
    00> rtt:~$ [00:00:06.272,613] <dbg> net_mgmt.mgmt_run_callbacks: (<log_strdup alloc failed>): Running callback 0x20003a88 : 0x2b21
    00> rtt:~$ [00:00:06.272,613] <inf> app: Network connected
    00> rtt:~$ 
    00> rtt:~$ 
    in any case, If i'm using gsm_ppp_start, async_uart_rx_enable doesn't seem to get called.
    the execution waits for AT OK and communication times out BEFORE uart_rx gets enabled...
Related