SIM900 CMUX does work, only echoes data

[davidalo]

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:

1. Using cellular_modem sample
2. 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);

3. 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;
	}
	

4. 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]

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

[davidalo]

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

[Tasosgi]

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

[jukkar]

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.