CMUX never connected using cellular_modem samples [nRF54L15 + Quectel EG21]

[krisnaresi89]

Hi there,

I have a plan to have cellular connectivity for my project. My project will consist of nRF54L15 custom board with Quectel EG21 cellular module. I understand that there is no dts bindings for this specific cellular module, but I assume quectel,eg25-g binding will do just fine. Here is my setup:

OS: Host: Linux Ubuntu 18.04, Docker: zephyrprojectrtos/v0.26.12
Toolchain: Zephyr SDK v0.16.6
Zephyr RTOS v4.2.0

Here is the dts for handling cellular modem

&uart20 {
	status= "okay";
	current-speed = <115200>;
	pinctrl-0 = <&uart20_default>;
	pinctrl-1 = <&uart20_sleep>;
	pinctrl-names = "default", "sleep";
	hw-flow-control;

	modem: modem {
		status= "okay";
		compatible = "quectel,eg25-g";
		mdm-reset-gpios = <&tca9554 4 GPIO_ACTIVE_HIGH>;
		mdm-power-gpios = <&tca9554 5 GPIO_ACTIVE_HIGH>;
	};
};

&i2c21 {
    status = "okay";
    compatible = "nordic,nrf-twim";
    clock-frequency = <I2C_BITRATE_FAST>;  // 100kHz standard clock frequency
    pinctrl-0 = <&i2c21_default>;
    pinctrl-1 = <&i2c21_sleep>;
    pinctrl-names = "default","sleep";

    tca9554: tca9554@20 {
        status = "okay";
        compatible = "nxp,pca9554";
        reg = <0x20>;
        gpio-controller;
        #gpio-cells = <2>;
        ngpios = <8>;
        label = "tca9554";
    };
};

&pinctrl {
        /omit-if-no-ref/ uart20_default: uart20_default {
		group1 {
			psels = <NRF_PSEL(UART_TX, 1, 13)>, <NRF_PSEL(UART_RTS, 2, 10)>;
		};
		group2 {
			psels = <NRF_PSEL(UART_RX, 1, 14)>, <NRF_PSEL(UART_CTS, 1, 7)>;
			bias-pull-up;
		};
	};

	/omit-if-no-ref/ uart20_sleep: uart20_sleep {
		group1 {
			psels = <NRF_PSEL(UART_TX, 1, 13)>,
				<NRF_PSEL(UART_RX, 1, 14)>,
				<NRF_PSEL(UART_RTS, 2, 10)>,
				<NRF_PSEL(UART_CTS, 1, 7)>;
			low-power-enable;
		};
	};
};

I need to modify dts binding on zephyr/dts/bindings/modem/quectel,eg25-g.yaml so it can use mdm-power-gpios for powerkey control

description: Quectel EG25-G modem

compatible: "quectel,eg25-g"

include: uart-device.yaml

properties:
  mdm-reset-gpios:
    type: phandle-array
    required: true

  mdm-power-gpios:
    type: phandle-array

  mdm-dtr-gpios:
    type: phandle-array

  mdm-wdisable-gpios:
    type: phandle-array

I'm pretty much using default samples from zephyr/samples/net/cellular_modem, with overlay conf:

CONFIG_MODEM_CMUX_LOG_LEVEL_DBG=y
CONFIG_LOG_BUFFER_SIZE=65536

CONFIG_GPIO=y
CONFIG_I2C=y

CONFIG_MODEM_CELLULAR_APN="internet"
CONFIG_MODEM_LOG_LEVEL_DBG=y

CONFIG_NRFX_UARTE20=y
CONFIG_UART_ASYNC_API=y
CONFIG_UART_20_ASYNC=y
CONFIG_UART_20_INTERRUPT_DRIVEN=n

CONFIG_MODEM_CMUX_WORK_BUFFER_SIZE=1500
CONFIG_MODEM_CELLULAR_UART_BUFFER_SIZES=6000
CONFIG_MODEM_CMUX_MTU=127
CONFIG_MODEM_CMUX_WORK_BUFFER_SIZE=134

Modem chat success to transmit all required AT command to the end. But, when modem driver trying to connect to cmux, it never success to do so, and the same cmux log keep spawn until the end. I expect to find event cmux connected log somewhere along the line. Here is the log:

*** Booting Zephyr OS build v4.2.0 ***
Powering on modem
[00:00:30.195,554] <dbg> modem_cellular: modem_cellular_log_event: event resume
Bring up network interface
Waiting for L4 connected
[00:00:30.195,838] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from idle to power pulse
[00:00:31.695,904] <dbg> modem_cellular: modem_cellular_log_event: event timeout
[00:00:31.696,084] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from power pulse to await power on
[00:00:46.696,160] <dbg> modem_cellular: modem_cellular_log_event: event timeout
[00:00:46.696,223] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from await power on to run init script
[00:00:46.696,245] <dbg> modem_cellular: modem_cellular_log_event: event bus opened
[00:00:46.696,274] <wrn> modem_backend_uart_async: Receive stopped for reasons: 4
[00:00:46.696,285] <wrn> modem_backend_uart_async: Receive stopped for reasons: 8
[00:00:46.696,303] <dbg> modem_chat: modem_chat_script_start: running script: quectel_eg25_g_init_chat_script
[00:00:46.696,313] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 0
[00:00:46.696,325] <dbg> modem_chat: modem_chat_script_next: sending: ATE0
[00:00:46.696,367] <wrn> modem_backend_uart_async: Receive stopped for reasons: 4
[00:00:46.696,378] <wrn> modem_backend_uart_async: Receive stopped for reasons: 8
[00:00:46.696,458] <wrn> modem_backend_uart_async: Receive stopped for reasons: 4
[00:00:46.696,470] <wrn> modem_backend_uart_async: Receive stopped for reasons: 8
[00:00:46.696,549] <wrn> modem_backend_uart_async: Receive stopped for reasons: 4
[00:00:46.696,560] <wrn> modem_backend_uart_async: Receive stopped for reasons: 8
[00:00:46.696,642] <wrn> modem_backend_uart_async: Receive stopped for reasons: 4
[00:00:46.696,657] <wrn> modem_backend_uart_async: Receive stopped for reasons: 8
[00:00:46.696,733] <wrn> modem_backend_uart_async: Receive stopped for reasons: 4
[00:00:46.696,744] <wrn> modem_backend_uart_async: Receive stopped for reasons: 8
[00:00:56.696,399] <wrn> modem_chat: quectel_eg25_g_init_chat_script: timed out
[00:00:56.696,444] <dbg> modem_cellular: modem_cellular_log_event: event script failed
[00:00:56.696,613] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from run init script to power pulse
[00:00:58.196,672] <dbg> modem_cellular: modem_cellular_log_event: event timeout
[00:00:58.196,852] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from power pulse to await power on
[00:01:13.196,896] <dbg> modem_cellular: modem_cellular_log_event: event timeout
[00:01:13.196,959] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from await power on to run init script
[00:01:13.196,981] <dbg> modem_cellular: modem_cellular_log_event: event bus opened
[00:01:13.197,016] <dbg> modem_chat: modem_chat_script_start: running script: quectel_eg25_g_init_chat_script
[00:01:13.197,026] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 0
[00:01:13.197,039] <dbg> modem_chat: modem_chat_script_next: sending: ATE0
[00:01:13.210,157] <dbg> modem_chat: modem_chat_on_unknown_command_received: ATE0
[00:01:13.210,180] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:01:13.210,192] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 1
[00:01:13.210,204] <dbg> modem_chat: modem_chat_script_next: sending: AT+CFUN=4
[00:01:13.469,919] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:01:13.469,942] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 2
[00:01:13.469,955] <dbg> modem_chat: modem_chat_script_next: sending: AT+CMEE=1
[00:01:13.482,117] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:01:13.482,129] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 3
[00:01:13.482,142] <dbg> modem_chat: modem_chat_script_next: sending: AT+CREG=1
[00:01:13.493,645] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:01:13.493,656] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 4
[00:01:13.493,669] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGREG=1
[00:01:13.505,070] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:01:13.505,094] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 5
[00:01:13.505,106] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG=1
[00:01:13.516,517] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:01:13.516,540] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 6
[00:01:13.516,553] <dbg> modem_chat: modem_chat_script_next: sending: AT+CREG?
[00:01:13.529,137] <dbg> modem_chat: modem_chat_log_received_command: +CREG:  1 0
[00:01:13.529,173] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:01:13.529,184] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 7
[00:01:13.529,197] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG?
[00:01:13.529,222] <dbg> modem_cellular: modem_cellular_log_event: event deregistered
[00:01:13.541,906] <dbg> modem_chat: modem_chat_log_received_command: +CEREG:  1 0
[00:01:13.541,942] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:01:13.541,966] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 8
[00:01:13.541,978] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGREG?
[00:01:13.542,006] <dbg> modem_cellular: modem_cellular_log_event: event deregistered
[00:01:13.554,655] <dbg> modem_chat: modem_chat_log_received_command: +CGREG:  1 0
[00:01:13.554,711] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:01:13.554,723] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 9
[00:01:13.554,735] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGSN
[00:01:13.554,763] <dbg> modem_cellular: modem_cellular_log_event: event deregistered
[00:01:13.568,135] <dbg> modem_chat: modem_chat_log_received_command:  862079072143343
[00:01:13.568,149] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 10
[00:01:13.568,171] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:01:13.568,181] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 11
[00:01:13.568,194] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGMM
[00:01:13.580,105] <dbg> modem_chat: modem_chat_log_received_command:  EG21
[00:01:13.580,122] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 12
[00:01:13.580,144] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:01:13.580,154] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 13
[00:01:13.580,167] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGMI
[00:01:13.592,277] <dbg> modem_chat: modem_chat_log_received_command:  Quectel
[00:01:13.592,294] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 14
[00:01:13.592,316] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:01:13.592,326] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 15
[00:01:13.592,339] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGMR
[00:01:13.605,268] <dbg> modem_chat: modem_chat_log_received_command:  EG21GGBR07A21M1G
[00:01:13.605,285] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 16
[00:01:13.605,307] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:01:13.605,317] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 17
[00:01:13.605,330] <dbg> modem_chat: modem_chat_script_next: sending: AT+CIMI
[00:01:13.618,138] <dbg> modem_chat: modem_chat_log_received_command:  510107790121492
[00:01:13.618,153] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 18
[00:01:13.618,175] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:01:13.618,185] <dbg> modem_chat: modem_chat_script_next: quectel_eg25_g_init_chat_script: step: 19
[00:01:13.618,198] <dbg> modem_chat: modem_chat_script_next: sending: AT+CMUX=0,0,5,127,10,3,30,10,2
[00:01:13.631,604] <dbg> modem_chat: modem_chat_on_unknown_command_received: OK
[00:01:13.720,945] <dbg> modem_chat: modem_chat_script_stop: quectel_eg25_g_init_chat_script: complete
[00:01:13.720,981] <dbg> modem_cellular: modem_cellular_log_event: event script success
[00:01:13.721,569] <dbg> modem_cellular: modem_cellular_log_event: event bus closed
[00:01:13.721,597] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from run init script to connect cmux
[00:01:13.821,664] <dbg> modem_cellular: modem_cellular_log_event: event timeout
[00:01:13.821,716] <dbg> modem_cellular: modem_cellular_log_event: event bus opened
[00:01:13.821,764] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:13.821,775] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:14.151,866] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:14.151,887] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:14.481,978] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:14.481,989] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:14.812,086] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:14.812,098] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:15.142,198] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:15.142,209] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:15.472,314] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:15.472,334] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:15.802,422] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:15.802,433] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:16.132,535] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:16.132,546] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:16.462,647] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:16.462,658] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:16.792,793] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:16.792,814] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:17.122,902] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:17.122,914] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:17.453,014] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:17.453,026] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:17.783,126] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:17.783,138] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:18.113,241] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:18.113,262] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:18.443,350] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:18.443,361] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:18.773,462] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:18.773,473] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:19.103,574] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:19.103,586] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:19.433,689] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:19.433,710] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:19.763,798] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:19.763,809] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:20.093,910] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:20.093,922] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:20.424,022] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:20.424,034] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:20.754,137] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:20.754,158] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:21.084,246] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:21.084,257] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:21.084,312] <dbg> modem_cmux: modem_cmux_transmit_handler: Transmitted only 0 out of 4 bytes at once.
[00:01:21.414,358] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:21.414,369] <dbg> modem_cmux: modem_cmux_log_frame: data:
[00:01:21.744,470] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0
[00:01:21.744,481] <dbg> modem_cmux: modem_cmux_log_frame: data:
...

There might be some similarity with this issue: #63410, but I already increase CMUX timeout to 2000ms, still with no luck.

I've been stuck for several days and doesn't have any idea how to troubleshot this any further. Any help, pointer and suggestion is pretty much appreciated. Thank you for your time.

Krisna