nRF9160 SLM with Zephyr native_sim on linux

[Pafka]

Hi,

We develop functionalities on native_sim before moving to embedded, therefore I am trying to have nRF9160 modem connected to Zephyr "cellular_modem" sample on linux native_sim.

I compiled "serial_lte_modem" with "west build -b nrf9160dk/nrf9160/ns -p -- -DEXTRA_CONF_FILE=overlay-ppp-cmux-linux.conf && west flash" (v3.0.2). I had to remove "hw-flow-control" on uart0 to have the communication. The modem is connected to developer's PC with USB (nRF9160 DK board). It answers communication, connects to APN - all OK.

The "cellular_modem" sample is from Zephyr source (not nrf, although diff does not show differences related to the issue). This native_sim app, uses DTS uart_1 as "zephyr,native-pty-uart" with modem on it and uart_1 is showing as PTY on linux.

/ {
	aliases {
		modem = &modem;
	};

	chosen {
		zephyr,console = &uart0;
		zephyr,shell-uart = &uart0;
	};

	uart_1: uart_1 {
		compatible = "zephyr,native-pty-uart";
		current-speed = <115200>;
		status = "okay";

		modem: modem {
			compatible = "nordic,nrf91-slm";
			status = "okay";
		};
	};
};

The uart_1 where the app is run is then connected with socat to /dev/ACM0. Communication starts, I get AT commands running, but just when CMUX is enabled with AT#XCMUX=1 it stops. No output from app nor from the SLM modem. 

Log from console of the cellular_modem app:

uart connected to pseudotty: /dev/pts/6
uart_1 connected to pseudotty: /dev/pts/7
*** Booting Zephyr OS build v4.1.0-5405-ge571f8bab428 ***
Powering on modem
[00:00:05.010,000] <dbg> modem_cellular: modem_cellular_log_event: event resume
[00:00:05.010,000] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from idle to run init script
[00:00:05.010,000] <dbg> modem_cellular: modem_cellular_log_event: event bus opened
[00:00:05.010,000] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_init_chat_script
[00:00:05.010,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 0
[00:00:05.010,000] <dbg> modem_chat: modem_chat_script_next: sending: AT
Bring up network interface
Waiting for L4 connected
[00:00:05.070,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:05.070,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 1
[00:00:05.070,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CFUN=0
[00:00:05.150,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:05.150,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 2
[00:00:05.150,000] <dbg> modem_chat: modem_chat_script_next: sending: AT%XSYSTEMMODE=1,0,0,0
[00:00:05.210,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:05.210,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 3
[00:00:05.210,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CFUN=0
[00:00:05.450,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:05.450,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 4
[00:00:05.450,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG=1
[00:00:05.510,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:05.510,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 5
[00:00:05.510,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CFUN=1
[00:00:05.610,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:05.610,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 6
[00:00:05.610,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CMEE=1
[00:00:05.670,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:05.670,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 7
[00:00:05.670,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG=1
[00:00:05.730,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:05.730,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 8
[00:00:05.730,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG?
[00:00:05.790,000] <dbg> modem_chat: modem_chat_log_received_command: +CEREG:  1 4
[00:00:05.790,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:05.790,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 9
[00:00:05.790,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGSN
[00:00:05.790,000] <dbg> modem_cellular: modem_cellular_log_event: event deregistered
[00:00:05.850,000] <dbg> modem_chat: modem_chat_log_received_command:  351516172759573
[00:00:05.850,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 10
[00:00:05.850,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:05.850,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 11
[00:00:05.850,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGMM
[00:00:05.910,000] <dbg> modem_chat: modem_chat_log_received_command:  nRF9160-SICA
[00:00:05.910,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 12
[00:00:05.910,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:05.910,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 13
[00:00:05.910,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGMI
[00:00:05.970,000] <dbg> modem_chat: modem_chat_log_received_command:  Nordic Semiconductor ASA
[00:00:05.970,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 14
[00:00:05.970,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:05.970,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 15
[00:00:05.970,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGMR
[00:00:06.030,000] <dbg> modem_chat: modem_chat_log_received_command:  mfw_nrf9160_1.3.5
[00:00:06.030,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 16
[00:00:06.030,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:06.030,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 17
[00:00:06.030,000] <dbg> modem_chat: modem_chat_script_next: sending: AT#XCMUX=1
[00:00:06.090,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:06.090,000] <dbg> modem_chat: modem_chat_script_stop: nordic_nrf91_slm_init_chat_script: complete
[00:00:06.090,000] <dbg> modem_cellular: modem_cellular_log_event: event script success

(there is 5s delay on start, to allow me to run socat on other terminal)

socat starts with:

socat -v /dev/ttyACM0,raw,echo=0,b115200 /dev/pts/7,raw,echo=0

and shows AT commands and responses (no issues spotted).

Would be grateful for any idea.

Regards

[Håkon Alseth]

Hi,

 

If I understand your setup correct, you are running SLM on the nRF9160, and cellular_modem on the linux side (native target).

The issue occurs when you issue AT#XCMUX=1: 

Communication starts, I get AT commands running, but just when CMUX is enabled with AT#XCMUX=1 it stops. No output from app nor from the SLM modem. 

From the docs here:

https://docs.nordicsemi.com/bundle/ncs-2.9.0/page/nrf/applications/serial_lte_modem/doc/nRF91_as_Zephyr_modem.html#flashing_and_running 

It states:

The cellular modem driver will start sending AT commands to SLM. 
It will enable the network status notifications, gather some information from the modem, enable CMUX, and set the modem to normal mode (with an AT+CFUN=1 command). 
This will result in SLM’s PPP starting automatically when the network registration is complete.

Have you checked if it works with "AT#XCMUX=2"?

 

Kind regards,

Håkon

[Pafka]

Hi Håkon,

Thank you for your response!

You get my setup correct.

I have checked also with "AT#XCMUX=2" - the same result.

It looks like the modem is not sending nor responding at all after "AT#XCMUX" command - the connected UART is then silent.

I made following tests:
1. Manual: when manually entering commands in UART terminal, I am able to get to AT#XCMUX step, before modem registers to the network. Without yet entering AT#XCMUX mode, I can still see unsolicited +CEREG: 1 and #XPPP: 1,0 being sent by the modem.
When I repeat this test but then issue "AT#XCMUX=1" before those unsolicited are sent, I would expect to get them using CMUX channel and see any activity on the socat/console - but it is silent then.

2. With python script: I made an python script that sends the AT commands and CMUX command directly to /dev/ttyACM0 (without socat) followed by "AT\r\n" codded on command channel as described in 0710 GSM spec (multiplexing protocol). The result is the same as with manual, after AT#XCMUX=1 (or AT#XCMUX=1 or AT#XCMUX) there is totally no activity from SLM modem; no response to the coded message.

Kind regards,

Pafka

[Pafka]

It might be related - I am not able to get SLM compiled from sources and working at all when uart0 has hw-flow-control enabled (despite enabling HW flow on terminal no responses on AT commands). When hw-flow-control is removed and SLM is compiled then it works on terminal with no flow control (but CMUX is not working).

On the other hand if I flash SLM with nRF Connect on Windows (no compilation, but SW bundled with it), the SLM works with HW flow control on my terminals (but sadly CMUX is not enabled there, AT#XCMUX=1 responds with ERROR).

[Håkon Alseth]

Hi,

 

Pafka said:

With python script: I made an python script that sends the AT commands and CMUX command directly to /dev/ttyACM0 (without socat) followed by "AT\r\n" codded on command channel as described in 0710 GSM spec (multiplexing protocol). The result is the same as with manual, after AT#XCMUX=1 (or AT#XCMUX=1 or AT#XCMUX) there is totally no activity from SLM modem; no

Please note that there are differences between AT#XCMUX and the specified AT+CMUX.
SLM does not implement +CMUX as described in the docs:

Pafka said:

I am not able to get SLM compiled from sources and working at all when uart0 has hw-flow-control enabled

Try this build cmd:

west build -b nrf9160dk/nrf9160/ns -- -DEXTRA_CONF_FILE="overlay-ppp.conf;overlay-cmux.conf;overlay-ppp-cmux-linux.conf"

Enabling CMUX will require UIH frames, as described here:

https://docs.nordicsemi.com/bundle/ncs-2.6.1/page/nrf/applications/serial_lte_modem/doc/CMUX_AT_commands.html

Although not very well documented, it is shown in the example that UIH frames are required and can only be disabled by a reset after its been enabled:

 

You could have a look at the scripts to see how the chat functions are setup there:

https://github.com/nrfconnect/sdk-nrf/tree/main/applications/serial_lte_modem/scripts 

 

Example to print XMONITOR output:

chat $CHATOPT -t$TIMEOUT "" "AT%XMONITOR" "OK" >$AT_CMUX <$AT_CMUX

 

Kind regards,

Håkon

 

[Pafka]

Hi Håkon,

Thank you for your insights!

Indeed when compiled as you advised - but still without  hw-flow-control - when using script: ./slm_start_ppp.sh I got:

+ MODEM=/dev/ttyACM0
+ BAUD=115200
+ PPP_CMUX=/dev/gsmtty2
+ AT_CMUX=/dev/gsmtty1
+ CHATOPT=-vs
+ TIMEOUT=60
+ getopts s:b:t:h flag
+ trap cleanup ERR
+ [[ ! -c /dev/ttyACM0 ]]
+ stty -F /dev/ttyACM0 115200 pass8 raw crtscts clocal
+ echo 'Wait modem to boot'
Wait modem to boot
+ chat -t5 '' AT OK
+ echo 'Attach CMUX channel to modem...'
Attach CMUX channel to modem...
+ ldattach -c $'AT#XCMUX=1\r' GSM0710 /dev/ttyACM0
+ sleep 1
+ stty -F /dev/gsmtty1 clocal
+ echo 'Connect and wait for PPP link...'
Connect and wait for PPP link...
+ test -c /dev/gsmtty1
+ chat -vs -t60 '' AT+CFUN=1 OK '\c' '#XPPP: 1,0'
send (AT+CFUN=1^M)
expect (OK)


OK
 -- got it

send ()
expect (#XPPP: 1,0)




+CNEC_ESM: 50,0



#XPPP: 1,0
 -- got it

+ pppd /dev/gsmtty2 noauth novj nodeflate nobsdcomp debug noipdefault passive +ipv6 noremoteip local linkname nrf91 defaultroute defaultroute-metric -1

That shows the slm modem can "speak" cmux.

I have adapted the cellular_modem of zephyr to have the connection setup with CMUX, however there the slm modem is not responding when cmux is on. I got the following log:

[00:00:10.510,000] <inf> modem_cellular: modem_cellular_chat_on_cxreg registered
[00:00:10.510,000] <inf> modem_cellular: modem_cellular_delegate_event
[00:00:10.510,000] <inf> modem_cellular: modem_cellular_event_dispatch_handler
[00:00:10.510,000] <inf> modem_cellular: event registered
[00:00:10.510,000] <inf> modem_cellular: modem_cellular_run_init_script_event_handler
[00:00:10.510,000] <dbg> modem_chat: modem_chat_log_received_command: #XPPP:  1,0
[00:00:10.510,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_init_chat_script: step: 16
[00:00:10.510,000] <dbg> modem_chat: modem_chat_script_next: sending: AT#XCMUX=1
[00:00:10.570,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:10.570,000] <dbg> modem_chat: modem_chat_script_stop: nordic_nrf91_slm_init_chat_script: complete
..... CUT ....
[00:00:10.790,000] <inf> modem_cellular: modem_cellular_event_dispatch_handler
[00:00:10.790,000] <inf> modem_cellular: event timeout
[00:00:10.790,000] <dbg> modem_chat: modem_chat_script_start: running script: nordic_nrf91_slm_dial_chat_script
[00:00:10.790,000] <dbg> modem_chat: modem_chat_script_next: nordic_nrf91_slm_dial_chat_script: step: 0
[00:00:10.790,000] <dbg> modem_chat: modem_chat_script_next: sending: AT
[00:00:10.790,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:2
[00:00:10.790,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54                                            |AT               
[00:00:10.790,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:2
[00:00:10.790,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d 0a                                            |..               
[00:00:10.790,000] <dbg> modem_cmux: modem_cmux_transmit_handler: About to transmit to UART:
                                     f9 07 ef 05 41 54 30 f9  f9 07 ef 05 0d 0a 30 f9 |....AT0. ......0.
[00:00:11.200,000] <inf> modem_cmux: UART transmit returned: 16, expected: 16

I looks like the cellular_modem is transmitting UIH framed data (I can also see the frames being send out with socat), but get's no response ... 

Regards,

Pafka

PS. Does the Zephyr cellular_modem works with SLM as described here: https://docs.nordicsemi.com/bundle/ncs-2.6.1/page/nrf/applications/serial_lte_modem/doc/nRF91_as_Zephyr_modem.html#slm-as-zephyr-modem "out of the box"?

Since to have the modem achieve the dlci connected state it required some changes in code ...

[Håkon Alseth]

Hi,

 

What is your current slm build configuration? Note that linux vs. zephyr modem compliant differs in terms of .conf files:

https://docs.nordicsemi.com/bundle/ncs-latest/page/nrf/applications/serial_lte_modem/doc/nRF91_as_Zephyr_modem.html#nrf91_series_sip_running_slm

 

Based on the log, it seems to run, but not answer.

Is the problem that it is encoding your line-ending in addition to the "AT"?

[00:00:10.790,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     41 54                                            |AT               
[00:00:10.790,000] <dbg> modem_cmux: modem_cmux_log_frame: tx ch:1 cr:1 pf:0 type:UIH dlen:2
[00:00:10.790,000] <dbg> modem_cmux: modem_cmux_log_frame: data:
                                     0d 0a                                            |..               
[00:00:10.790,000] <dbg> modem_cmux: modem_cmux_transmit_handler: About to transmit to UART:
                                     f9 07 ef 05 41 54 30 f9  f9 07 ef 05 0d 0a 30 f9 |....AT0. ......0.

Pafka said:

PS. Does the Zephyr cellular_modem works with SLM as described here: https://docs.nordicsemi.com/bundle/ncs-2.6.1/page/nrf/applications/serial_lte_modem/doc/nRF91_as_Zephyr_modem.html#slm-as-zephyr-modem "out of the box"?

With additional configuration(s), yes, that is the intention.

 

Kind regards,

Håkon