SIM900 CMUX does work, only echoes data #76894

davidalo · 2024-08-09T14:42:51Z

davidalo
Aug 9, 2024

Hello,

Running Zephyr 3.7.0 and trying to use SIM900 module with it. As recommended in docs, I'm using Cellular Modem module but I can not get it working.

Steps I've done so far:

Using cellular_modem sample
Took sim7080 as reference, I've modified the chat scripts to the following status. Moved commands from dial_chat_script because I can not get proper answer from CMUX. Removed CEREG messages as module has no LTE. Using AT and ATI in dial_chat_scripts and periodic_chat_scripts as dummy commands to get it up and running.

MODEM_CHAT_SCRIPT_CMDS_DEFINE(simcom_sim7080_init_chat_script_cmds,
			      MODEM_CHAT_SCRIPT_CMD_RESP_NONE("AT", 100),
			      MODEM_CHAT_SCRIPT_CMD_RESP_NONE("AT", 100),
			      MODEM_CHAT_SCRIPT_CMD_RESP_NONE("AT", 100),
			      MODEM_CHAT_SCRIPT_CMD_RESP_NONE("AT", 100),
			      MODEM_CHAT_SCRIPT_CMD_RESP("ATE0", ok_match),
				//   MODEM_CHAT_SCRIPT_CMD_RESP("AT+IPR=9600", ok_match),
			      MODEM_CHAT_SCRIPT_CMD_RESP("AT+CFUN=4", ok_match),
			      MODEM_CHAT_SCRIPT_CMD_RESP("AT+CMEE=1", ok_match),
			      MODEM_CHAT_SCRIPT_CMD_RESP("AT+CREG=1", ok_match),
			      MODEM_CHAT_SCRIPT_CMD_RESP("AT+CGREG=1", ok_match),
			    //   MODEM_CHAT_SCRIPT_CMD_RESP("AT+CEREG=1", ok_match),
			      MODEM_CHAT_SCRIPT_CMD_RESP("AT+CREG?", ok_match),
			    //   MODEM_CHAT_SCRIPT_CMD_RESP("AT+CEREG?", ok_match),
			      MODEM_CHAT_SCRIPT_CMD_RESP("AT+CGREG?", ok_match),
			      MODEM_CHAT_SCRIPT_CMD_RESP("AT+CGSN", imei_match),
			      MODEM_CHAT_SCRIPT_CMD_RESP("", ok_match),
			      MODEM_CHAT_SCRIPT_CMD_RESP("AT+CGMM", cgmm_match),
			      MODEM_CHAT_SCRIPT_CMD_RESP("", ok_match),
			      MODEM_CHAT_SCRIPT_CMD_RESP_MULT("AT+CGACT=0,1", allow_match),
			      MODEM_CHAT_SCRIPT_CMD_RESP("AT+CGDCONT=1,\"IP\","
							 "\""CONFIG_MODEM_CELLULAR_APN"\"",
							 ok_match),
			      MODEM_CHAT_SCRIPT_CMD_RESP("AT+CFUN=1", ok_match),
			      MODEM_CHAT_SCRIPT_CMD_RESP_NONE("AT+CMUX=0,0,5,127", 300));

MODEM_CHAT_SCRIPT_DEFINE(simcom_sim7080_init_chat_script, simcom_sim7080_init_chat_script_cmds,
			 abort_matches, modem_cellular_chat_callback_handler, 10);

MODEM_CHAT_SCRIPT_CMDS_DEFINE(simcom_sim7080_dial_chat_script_cmds,
				MODEM_CHAT_SCRIPT_CMD_RESP_NONE("AT", 100),
					//   MODEM_CHAT_SCRIPT_CMD_RESP("ATE0", ok_match),
			    //   MODEM_CHAT_SCRIPT_CMD_RESP("AT+CREG=1", ok_match),
			    //   MODEM_CHAT_SCRIPT_CMD_RESP("AT+CGREG=1", ok_match),
			    //   MODEM_CHAT_SCRIPT_CMD_RESP_MULT("AT+CGACT=0,1", allow_match),
			    //   MODEM_CHAT_SCRIPT_CMD_RESP("AT+CGDCONT=1,\"IP\","
				// 			 "\""CONFIG_MODEM_CELLULAR_APN"\"",
				// 			 ok_match),
			    //   MODEM_CHAT_SCRIPT_CMD_RESP("AT+CFUN=1", ok_match),
			    //   MODEM_CHAT_SCRIPT_CMD_RESP_NONE("ATD*99***1#", 0),
				  );

MODEM_CHAT_SCRIPT_DEFINE(simcom_sim7080_dial_chat_script, simcom_sim7080_dial_chat_script_cmds,
			 dial_abort_matches, modem_cellular_chat_callback_handler, 10);

MODEM_CHAT_SCRIPT_CMDS_DEFINE(simcom_sim7080_periodic_chat_script_cmds,
					MODEM_CHAT_SCRIPT_CMD_RESP("ATI", ok_match),
			    //   MODEM_CHAT_SCRIPT_CMD_RESP("AT+CREG?", ok_match),
			    //   MODEM_CHAT_SCRIPT_CMD_RESP("AT+CEREG?", ok_match),
			    //   MODEM_CHAT_SCRIPT_CMD_RESP("AT+CGREG?", ok_match)
				  );

MODEM_CHAT_SCRIPT_DEFINE(simcom_sim7080_periodic_chat_script,
			 simcom_sim7080_periodic_chat_script_cmds, abort_matches,
			 modem_cellular_chat_callback_handler, 4);

I've made some modifications to modem_cmux.c to avoid considering SABM frames as ACK (in SIM900 docs it says ACK is UA frame):

static void modem_cmux_on_dlci_frame_sabm(struct modem_cmux_dlci *dlci)
{
	struct modem_cmux *cmux = dlci->cmux;

	modem_cmux_connect_response_transmit(cmux);

	if (dlci->state == MODEM_CMUX_DLCI_STATE_OPEN) {
		LOG_DBG("Unexpected SABM frame. dlci->state: %d", dlci->state);
		return;
	}

	if (dlci->state == MODEM_CMUX_DLCI_STATE_OPENING) {
		LOG_DBG("Unexpected SABM frame. dlci->state: %d", dlci->state);
		return;
	}
....

static void modem_cmux_on_control_frame_sabm(struct modem_cmux *cmux)
{
	modem_cmux_connect_response_transmit(cmux);

	if ((cmux->state == MODEM_CMUX_STATE_CONNECTED) ||
	    (cmux->state == MODEM_CMUX_STATE_DISCONNECTING)) {
		LOG_DBG("Connect request not accepted");
		return;
	}

	if (cmux->state == MODEM_CMUX_STATE_CONNECTING) {
		LOG_DBG("Unexpected SABM frame. cmux->state: %d", cmux->state);
		return;
	}

A few more small changes to debug and so.

The current status and problem is the following:

Module gets up and running.
Init chat scripts are run as expected
CMUX is configured. DLCI1 and DLCI2 channels are configured as expected.
When I send a command over DLCI1 (dial chat script) or DLCI2 (periodic chat script) I only receive echo from the module. Sending ATE0 via DLCI2 seems not to help.

[00:00:13.732,000] <dbg> modem_chat: modem_chat_script_next: simcom_sim7080_init_chat_script: step: 17
[00:00:13.732,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CFUN=1
[00:00:13.888,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CFUN=1
[00:00:13.888,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:13.888,000] <dbg> modem_chat: modem_chat_script_next: simcom_sim7080_init_chat_script: step: 18
[00:00:13.888,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CMUX=0,0,5,127
[00:00:14.036,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CMUX=0,0,5,127
[00:00:14.056,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: OK
[00:00:14.188,000] <dbg> modem_chat: modem_chat_script_stop: simcom_sim7080_init_chat_script: complete
[00:00:14.188,000] <inf> modem_cellular: switch from run init script to connect cmux
[00:00:14.289,000] <dbg> modem_cmux: modem_cmux_connect_handler: cmux state: 1
[00:00:14.289,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0 type: 
[00:00:14.619,000] <dbg> modem_cmux: modem_cmux_connect_handler: cmux state: 1
[00:00:14.619,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0 type: 
[00:00:14.949,000] <dbg> modem_cmux: modem_cmux_connect_handler: cmux state: 1
[00:00:14.949,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0 type: 
[00:00:15.279,000] <dbg> modem_cmux: modem_cmux_connect_handler: cmux state: 1
[00:00:15.279,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0 type: 
[00:00:15.609,000] <dbg> modem_cmux: modem_cmux_connect_handler: cmux state: 1
[00:00:15.609,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0 type: 
[00:00:15.940,000] <dbg> modem_cmux: modem_cmux_connect_handler: cmux state: 1
[00:00:15.940,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0 type: 
[00:00:16.270,000] <dbg> modem_cmux: modem_cmux_connect_handler: cmux state: 1
[00:00:16.270,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0 type: 
[00:00:16.600,000] <dbg> modem_cmux: modem_cmux_connect_handler: cmux state: 1
[00:00:16.600,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0 type: 
[00:00:16.930,000] <dbg> modem_cmux: modem_cmux_connect_handler: cmux state: 1
[00:00:16.930,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0 type: 
[00:00:17.260,000] <dbg> modem_cmux: modem_cmux_connect_handler: cmux state: 1
[00:00:17.260,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:SABM dlen:0 type: 
[00:00:17.396,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:0 cr:1 pf:1 type:SABM dlen:0 type: control
[00:00:17.396,000] <dbg> modem_cmux: modem_cmux_connect_response_transmit: SABM/DISC request state send ack
[00:00:17.396,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:0 cr:1 pf:1 type:UA dlen:0 type: 
[00:00:17.396,000] <dbg> modem_cmux: modem_cmux_on_control_frame_sabm: Unexpected SABM frame. cmux->state: 1
[00:00:17.531,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:0 cr:1 pf:1 type:UA dlen:0 type: control
[00:00:17.531,000] <inf> modem_cellular: switch from connect cmux to open dlci1
[00:00:17.531,000] <dbg> modem_cmux: modem_cmux_dlci_open_handler: DLCI 1 state 1
[00:00:17.531,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:1 type:SABM dlen:0 type: 
[00:00:17.667,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:1 cr:1 pf:1 type:SABM dlen:0 type: dlci
[00:00:17.667,000] <dbg> modem_cmux: modem_cmux_connect_response_transmit: SABM/DISC request state send ack
[00:00:17.667,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:1 type:UA dlen:0 type: 
[00:00:17.667,000] <dbg> modem_cmux: modem_cmux_on_dlci_frame_sabm: Unexpected SABM frame. dlci->state: 1
[00:00:17.802,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:1 cr:1 pf:1 type:UA dlen:0 type: dlci
[00:00:17.802,000] <inf> modem_cellular: switch from open dlci1 to open dlci2
[00:00:17.802,000] <dbg> modem_cmux: modem_cmux_dlci_open_handler: DLCI 2 state 1
[00:00:17.802,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:2 cr:1 pf:1 type:SABM dlen:0 type: 
[00:00:17.939,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:1 pf:1 type:SABM dlen:0 type: dlci
[00:00:17.939,000] <dbg> modem_cmux: modem_cmux_connect_response_transmit: SABM/DISC request state send ack
[00:00:17.939,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:2 cr:1 pf:1 type:UA dlen:0 type: 
[00:00:17.939,000] <dbg> modem_cmux: modem_cmux_on_dlci_frame_sabm: Unexpected SABM frame. dlci->state: 1
[00:00:18.074,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:1 pf:1 type:UA dlen:0 type: dlci
[00:00:18.074,000] <inf> modem_cellular: switch from open dlci2 to run dial script
[00:00:18.175,000] <inf> modem_cellular: event 7
[00:00:18.175,000] <dbg> modem_chat: modem_chat_script_start: running script: simcom_sim7080_dial_chat_script
[00:00:18.175,000] <dbg> modem_chat: modem_chat_script_next: simcom_sim7080_dial_chat_script: step: 0
[00:00:18.175,000] <dbg> modem_chat: modem_chat_script_next: sending: AT
[00:00:18.175,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:2 type: 
[00:00:18.175,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54                                            |AT               
[00:00:18.175,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:1 type: 
[00:00:18.175,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d                                               |.                
[00:00:18.275,000] <dbg> modem_chat: modem_chat_script_stop: simcom_sim7080_dial_chat_script: complete
[00:00:18.275,000] <inf> modem_cellular: event 2
[00:00:18.275,000] <inf> modem_cellular: switch from run dial script to await registered
[00:00:18.320,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:1 cr:1 pf:0 type:UIH dlen:2 type: dlci
[00:00:18.320,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54                                            |AT               
[00:00:18.320,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:1 cr:1 pf:0 type:UIH dlen:1 type: dlci
[00:00:18.320,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d                                               |.                
[00:00:18.320,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x41 because 0x7e was expected.
[00:00:18.320,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x54 because 0x7e was expected.
[00:00:18.320,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0x7e was expected.
[00:00:20.275,000] <dbg> modem_chat: modem_chat_script_start: running script: simcom_sim7080_periodic_chat_script
[00:00:20.275,000] <dbg> modem_chat: modem_chat_script_next: simcom_sim7080_periodic_chat_script: step: 0
[00:00:20.275,000] <dbg> modem_chat: modem_chat_script_next: sending: ATI
[00:00:20.275,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:2 cr:1 pf:0 type:UIH dlen:3 type: 
[00:00:20.275,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54 49                                         |ATI              
[00:00:20.275,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:2 cr:1 pf:0 type:UIH dlen:1 type: 
[00:00:20.275,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d                                               |.                
[00:00:20.422,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:1 pf:0 type:UIH dlen:3 type: dlci
[00:00:20.422,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54 49                                         |ATI              
[00:00:20.422,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:1 pf:0 type:UIH dlen:1 type: dlci
[00:00:20.422,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d                                               |.                
[00:00:20.422,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: ATI
[00:00:24.275,000] <wrn> modem_chat: simcom_sim7080_periodic_chat_script: timed out
[00:00:26.275,000] <dbg> modem_chat: modem_chat_script_start: running script: simcom_sim7080_periodic_chat_script
[00:00:26.276,000] <dbg> modem_chat: modem_chat_script_next: simcom_sim7080_periodic_chat_script: step: 0
[00:00:26.276,000] <dbg> modem_chat: modem_chat_script_next: sending: ATI
[00:00:26.276,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:2 cr:1 pf:0 type:UIH dlen:3 type: 
[00:00:26.276,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54 49                                         |ATI              
[00:00:26.276,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:2 cr:1 pf:0 type:UIH dlen:1 type: 
[00:00:26.276,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d                                               |.                
[00:00:26.421,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:1 pf:0 type:UIH dlen:3 type: dlci
[00:00:26.421,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54 49                                         |ATI              
[00:00:26.422,000] <dbg> modem_cmux: modem_cmux_log_frame: rcvd ch:2 cr:1 pf:0 type:UIH dlen:1 type: dlci
[00:00:26.422,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d                                               |.                
[00:00:26.422,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: ATI

Tasosgi · 2024-11-27T08:47:57Z

Tasosgi
Nov 27, 2024

Could you please provide an update on the progress of this issue? I'm experiencing the same issue and would appreciate any insight.

1 reply

davidalo Nov 30, 2024
Author

I couldn't make it work. I upgraded the module but it didn't work either.

Tasosgi · 2024-11-30T16:33:58Z

Tasosgi
Nov 30, 2024

In my case the AT+CMUX=0,0,5,127 returns CME ERROR: 100

0 replies

jukkar · 2024-12-02T08:13:57Z

jukkar
Dec 2, 2024
Collaborator

It does not look like CMUX is enabled

[00:00:18.320,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x41 because 0x7e was expected.

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

SIM900 CMUX does work, only echoes data #76894

Uh oh!

{{title}}

Uh oh!

Replies: 3 comments 1 reply

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Uh oh!

{{title}}

Uh oh!

Select a reply

Uh oh!

SIM900 CMUX does work, only echoes data #76894

Uh oh!

davidalo Aug 9, 2024

Replies: 3 comments · 1 reply

Uh oh!

Tasosgi Nov 27, 2024

Uh oh!

davidalo Nov 30, 2024 Author

Uh oh!

Tasosgi Nov 30, 2024

Uh oh!

jukkar Dec 2, 2024 Collaborator

davidalo
Aug 9, 2024

Replies: 3 comments 1 reply

Tasosgi
Nov 27, 2024

davidalo Nov 30, 2024
Author

Tasosgi
Nov 30, 2024

jukkar
Dec 2, 2024
Collaborator