search

zephyrproject-rtos / zephyr

Primary Git Repository for the Zephyr Project. Zephyr is a new generation, scalable, optimized, secure RTOS for multiple hardware architectures.
https://docs.zephyrproject.org
Apache License 2.0
10.12k stars 6.21k forks source link

samples: net: cellular_modem: No PPP packets received when using esp32 async uart #72484

Closed vThibo closed 5 days ago

vThibo commented 2 months ago

Describe the bug

I managed to get the cellular_modem sample to work on my Walter board (ESP32-S3 + Sequans GM02SP modem) using UART_INTERRUPT_DRIVEN. However when using UART_ASYNC_API, all AT chat commands work, but no PPP frames can be received.

Requires #72453, or else the sample fails earlier.

To Reproduce

cellular_modem sample with:

devicetree (changes in comparison to the esp32s3-devkitc dts):

    aliases {
        modem = &modem;
        modem-uart = &uart1;
    };

&uart1 {
    status = "okay";
    current-speed = <115200>;
    hw-flow-control;

    dmas = <&dma 0
        &dma 1>;
    dma-names = "rx", "tx";

    pinctrl-0 = <&uart1_default>;
    pinctrl-names = "default";
    modem: modem {
        status = "okay";
        compatible = "sqn,gm02s";
            mdm-reset-gpios = <&gpio1 13 (GPIO_OPEN_DRAIN | GPIO_ACTIVE_LOW)>;
    };
};

&dma {
    status = "okay";
};

pinctrl:

    uart1_default: uart1_default {
        group1 {
            pinmux = <UART1_TX_GPIO48>;
            output-high;
        };
        group2 {
            pinmux = <UART1_RX_GPIO14>;
            bias-pull-up;
        };
        group3 {
            pinmux = <UART1_RTS_GPIO21>;
            output-high;
        };
        group4 {
            pinmux = <UART1_CTS_GPIO47>;
        };
    };

defconfig:

CONFIG_MAIN_STACK_SIZE=2048

CONFIG_CONSOLE=y
CONFIG_SERIAL=y
CONFIG_UART_CONSOLE=y
CONFIG_GPIO=y
CONFIG_CLOCK_CONTROL=y

CONFIG_DMA=y
CONFIG_UART_ASYNC_API=y

proj.conf:

CONFIG_POSIX_API=y

# Networking
CONFIG_NETWORKING=y
CONFIG_NET_NATIVE=y
CONFIG_NET_L2_PPP=y
CONFIG_NET_IPV4=y
CONFIG_NET_UDP=y
CONFIG_NET_SOCKETS=y
CONFIG_NET_CONTEXT_RCVTIMEO=y

# DNS
CONFIG_DNS_RESOLVER=y
CONFIG_NET_L2_PPP_OPTION_DNS_USE=y

# Network management
CONFIG_NET_MGMT=y
CONFIG_NET_MGMT_EVENT=y
CONFIG_NET_CONNECTION_MANAGER=y

# Modem driver
CONFIG_MODEM=y
CONFIG_PM_DEVICE=y
CONFIG_MODEM_CELLULAR=y

# Logging
CONFIG_LOG=y
CONFIG_LOG_BUFFER_SIZE=65536
CONFIG_MODEM_LOG_LEVEL_DBG=y
CONFIG_MODEM_MODULES_LOG_LEVEL_DBG=y
CONFIG_NET_LOG=y
CONFIG_NET_L2_PPP_LOG_LEVEL_DBG=y

Expected behavior PPP packets getting received, same as when using UART_INTERRUPT_DRIVEN.

Logs and console output

Functional UART_INTERRUPT_DRIVEN log:

[00:00:19.850,000] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from await registered to carrier on
[00:00:19.850,000] <dbg> modem_cellular: modem_cellular_log_event: event script success
[00:00:19.850,000] <dbg> net_l2_ppp: ppp_change_phase_debug: (0x3fca9e58): [0x3fcaa520] phase DEAD (0) => ESTABLISH (1) (ppp_open_async():202)
[00:00:19.850,000] <dbg> net_l2_ppp: ppp_open_async: (0x3fca9e58): Starting LCP
[00:00:19.850,000] <dbg> net_l2_ppp: ppp_fsm_lower_up: (0x3fca9e58): [LCP/0x3fcaa558] Current state INITIAL (0)
[00:00:19.850,000] <dbg> net_l2_ppp: ppp_change_state_debug: (0x3fca9e58): [LCP/0x3fcaa558] state INITIAL (0) => CLOSED (2) (ppp_fsm_lower_up():312)
[00:00:19.850,000] <dbg> net_l2_ppp: ppp_fsm_open: (0x3fca9e58): [LCP/0x3fcaa558] Current state CLOSED (2)
[00:00:19.850,000] <dbg> net_l2_ppp: ppp_change_state_debug: (0x3fca9e58): [LCP/0x3fcaa558] state CLOSED (2) => REQUEST_SENT (6) (ppp_fsm_open():335)
[00:00:19.850,000] <dbg> net_l2_ppp: fsm_send_configure_req: (0x3fca9e58): [LCP/0x3fcaa558] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[00:00:19.850,000] <dbg> net_l2_ppp: ppp_send_pkt: (0x3fca9e58): [LCP/0x3fcaa558] Sending 10 bytes pkt 0x3fc994c0 (options len 4)
[00:00:19.851,000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[00:00:19.851,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc994c0
                                     c0 21 01 01 00 08                                |.!....           
[00:00:19.851,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc994c0
                                     01 04 05 dc                                      |....             
[00:00:19.878,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:19.878,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 24)
[00:00:19.878,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:19.879,000] <dbg> net_l2_ppp: net_pkt_hexdump: recv L2
[00:00:19.879,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc995c0
                                     c0 21 01 01 00 14 02 06  00 00 00 00 05 06 44 f9 |.!...... ......D.
                                     b1 da 07 02 08 02                                |......           
[00:00:19.879,000] <dbg> net_l2_ppp: ppp_fsm_input: (0x3fcaa318): [LCP/0x3fcaa558] LCP Configure-Req (1) id 1 payload len 16
[00:00:19.879,000] <dbg> net_l2_ppp: fsm_recv_configure_req: (0x3fcaa318): [LCP/0x3fcaa558] Current state REQUEST_SENT (6)
[00:00:19.879,000] <dbg> net_l2_ppp: ppp_parse_options: (0x3fcaa318): [LCP/0x3fcaa558] option ASYNC_CTRL_CHAR_MAP (2) len 6
[00:00:19.879,000] <dbg> net_l2_ppp: ppp_parse_option_conf_req_unsupported: (0x3fcaa318): [LCP/0x3fcaa558] Check option ASYNC_CTRL_CHAR_MAP (2) len 4
[00:00:19.879,000] <dbg> net_l2_ppp: ppp_parse_options: (0x3fcaa318): [LCP/0x3fcaa558] option MAGIC_NUMBER (5) len 6
[00:00:19.879,000] <dbg> net_l2_ppp: ppp_parse_option_conf_req_unsupported: (0x3fcaa318): [LCP/0x3fcaa558] Check option MAGIC_NUMBER (5) len 4
[00:00:19.879,000] <dbg> net_l2_ppp: ppp_parse_options: (0x3fcaa318): [LCP/0x3fcaa558] option PROTO_COMPRESS (7) len 2
[00:00:19.879,000] <dbg> net_l2_ppp: ppp_parse_option_conf_req_unsupported: (0x3fcaa318): [LCP/0x3fcaa558] Check option PROTO_COMPRESS (7) len 0
[00:00:19.879,000] <dbg> net_l2_ppp: ppp_parse_options: (0x3fcaa318): [LCP/0x3fcaa558] option ADDR_CTRL_COMPRESS (8) len 2
[00:00:19.879,000] <dbg> net_l2_ppp: ppp_parse_option_conf_req_unsupported: (0x3fcaa318): [LCP/0x3fcaa558] Check option ADDR_CTRL_COMPRESS (8) len 0
[00:00:19.879,000] <dbg> net_l2_ppp: fsm_recv_configure_req: (0x3fcaa318): [LCP/0x3fcaa558] Sending Configure-Rej (4) id 1 to peer while in REQUEST_SENT (6)
[00:00:19.879,000] <dbg> net_l2_ppp: ppp_send_pkt: (0x3fcaa318): [LCP/0x3fcaa558] Sending 22 bytes pkt 0x3fc994c0 (options len 16)
[00:00:19.879,000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[00:00:19.879,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc994c0
                                     c0 21 04 01 00 14                                |.!....           
[00:00:19.879,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc994c0
                                     02 06 00 00 00 00 05 06  44 f9 b1 da 07 02 08 02 |........ D.......
[00:00:19.879,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 12)
[00:00:19.879,000] <dbg> net_l2_ppp: net_pkt_hexdump: recv L2
[00:00:19.879,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc99580
                                     c0 21 02 01 00 08 01 04  05 dc                   |.!...... ..

UART_ASYNC_API log:

[00:00:20.009,000] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from await registered to carrier on
[00:00:20.009,000] <dbg> modem_cellular: modem_cellular_log_event: event script success
[00:00:20.009,000] <dbg> net_l2_ppp: ppp_change_phase_debug: (0x3fcaa1a8): [0x3fcaa870] phase DEAD (0) => ESTABLISH (1) (ppp_open_async():202)
[00:00:20.009,000] <dbg> net_l2_ppp: ppp_open_async: (0x3fcaa1a8): Starting LCP
[00:00:20.009,000] <dbg> net_l2_ppp: ppp_fsm_lower_up: (0x3fcaa1a8): [LCP/0x3fcaa8a8] Current state INITIAL (0)
[00:00:20.010,000] <dbg> net_l2_ppp: ppp_change_state_debug: (0x3fcaa1a8): [LCP/0x3fcaa8a8] state INITIAL (0) => CLOSED (2) (ppp_fsm_lower_up():312)
[00:00:20.010,000] <dbg> net_l2_ppp: ppp_fsm_open: (0x3fcaa1a8): [LCP/0x3fcaa8a8] Current state CLOSED (2)
[00:00:20.010,000] <dbg> net_l2_ppp: ppp_change_state_debug: (0x3fcaa1a8): [LCP/0x3fcaa8a8] state CLOSED (2) => REQUEST_SENT (6) (ppp_fsm_open():335)
[00:00:20.010,000] <dbg> net_l2_ppp: fsm_send_configure_req: (0x3fcaa1a8): [LCP/0x3fcaa8a8] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[00:00:20.010,000] <dbg> net_l2_ppp: ppp_send_pkt: (0x3fcaa1a8): [LCP/0x3fcaa8a8] Sending 10 bytes pkt 0x3fc99810 (options len 4)
[00:00:20.010,000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[00:00:20.010,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc99810
                                     c0 21 01 01 00 08                                |.!....           
[00:00:20.010,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc99810
                                     01 04 05 dc                                      |....             
[00:00:22.009,000] <dbg> modem_cellular: modem_cellular_log_event: event timeout
[00:00:23.010,000] <dbg> net_l2_ppp: ppp_fsm_timeout: (0x3fcaad28): [LCP/0x3fcaa8a8] Current state REQUEST_SENT (6)
[00:00:23.010,000] <dbg> net_l2_ppp: fsm_send_configure_req: (0x3fcaad28): [LCP/0x3fcaa8a8] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[00:00:23.010,000] <dbg> net_l2_ppp: ppp_send_pkt: (0x3fcaad28): [LCP/0x3fcaa8a8] Sending 10 bytes pkt 0x3fc99810 (options len 4)
[00:00:23.010,000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[00:00:23.011,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc99810
                                     c0 21 01 01 00 08                                |.!....           
[00:00:23.011,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc99810
                                     01 04 05 dc                                      |....             
[00:00:26.010,000] <dbg> net_l2_ppp: ppp_fsm_timeout: (0x3fcaad28): [LCP/0x3fcaa8a8] Current state REQUEST_SENT (6)
[00:00:26.011,000] <dbg> net_l2_ppp: fsm_send_configure_req: (0x3fcaad28): [LCP/0x3fcaa8a8] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[00:00:26.011,000] <dbg> net_l2_ppp: ppp_send_pkt: (0x3fcaad28): [LCP/0x3fcaa8a8] Sending 10 bytes pkt 0x3fc99810 (options len 4)
[00:00:26.011,000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[00:00:26.011,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc99810
                                     c0 21 01 01 00 08                                |.!....           
[00:00:26.011,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc99810
                                     01 04 05 dc                                      |....             
[00:00:29.011,000] <dbg> net_l2_ppp: ppp_fsm_timeout: (0x3fcaad28): [LCP/0x3fcaa8a8] Current state REQUEST_SENT (6)
[00:00:29.011,000] <dbg> net_l2_ppp: fsm_send_configure_req: (0x3fcaad28): [LCP/0x3fcaa8a8] Sending Configure-Req (1) id 1 to peer while in REQUEST_SENT (6)
[00:00:29.011,000] <dbg> net_l2_ppp: ppp_send_pkt: (0x3fcaad28): [LCP/0x3fcaa8a8] Sending 10 bytes pkt 0x3fc99810 (options len 4)
[00:00:29.011,000] <dbg> net_l2_ppp: net_pkt_hexdump: send L2
[00:00:29.011,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc99810
                                     c0 21 01 01 00 08                                |.!....           
[00:00:29.011,000] <dbg> net_l2_ppp: net_pkt_hexdump: 0x3fc99810
                                     01 04 05 dc                                      |....

Environment:

github-actions[bot] commented 2 months ago

Hi @vThibo! We appreciate you submitting your first issue for our open-source project. 🌟

Even though I'm a bot, I can assure you that the whole community is genuinely grateful for your time and effort. 🤖💙

sylvioalves commented 5 days ago

Fixed by https://github.com/zephyrproject-rtos/zephyr/pull/72453