Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

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

Open
vThibo opened this issue May 8, 2024 · 1 comment
Open

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

vThibo opened this issue May 8, 2024 · 1 comment
Assignees
@sylvioalves
Labels
bug The issue is a bug, or the PR is fixing a bug platform: ESP32 Espressif ESP32 priority: low Low impact/importance bug

Comments

@vThibo
Copy link

vThibo commented May 8, 2024

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:

  • OS: Ubuntu 22.04
  • Toolchain: Zephyr SDK
  • Version used: 3.6.99
@vThibo vThibo added the bug The issue is a bug, or the PR is fixing a bug label May 8, 2024
@github-actions GitHub Actions
Copy link

github-actions bot commented May 8, 2024

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. 🤖💙

@henrikbrixandersen henrikbrixandersen added the platform: ESP32 Espressif ESP32 label May 10, 2024
@aescolar aescolar added the priority: low Low impact/importance bug label May 14, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@sylvioalves sylvioalves

Labels
bug The issue is a bug, or the PR is fixing a bug platform: ESP32 Espressif ESP32 priority: low Low impact/importance bug
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
4 participants
@henrikbrixandersen @sylvioalves @aescolar @vThibo