LTE Cat 1bis on STM32U565 with Simcom A7683E and Zephyr

2024-04-06 14:05

Detlev Zundel

Tags:

Trying to understand the new cellular modem subsystem in Zephyr, I realized that building a working demo system should be the best way forward. Having an evaluation board of the A7683E available, the first step was to pick a well suited eval board to match the module.

As it turns out, the Simcom module runs at 1.8V and even on the evaluation board there are no level shifters. So that quickly gave me the first hard requirement, namely that the UART needs to be run at 1.8V.

Looking at my collection of recent MPU eval kits, I realized that the NUCLEO-U575ZI-Q could run completely on 1.8V by a simple jumper setting. On the other boards it would have been more involved to define the UART pins to run on 1.8V, so I decided to use this eval board for the MPU part.

So the aim of this blog post is to document how I implemented the demo on this hardware combination:

Simcom EVB

For evaluating their modules, Simcom uses a common evaluation board (EVB) and individual "TE modules" per specific modems. For the A7683E, the assembled setup looks like this:

As can be seen on the picture, there are two USB micro connectors which can be attached to a USB host:

on TE A7683E module
on EVB baseboard

Let's look at those connections in turn.

USB Device on A7683E

Next to plain old UART, the module has also USB device support. Connecting this to a PC gives us this lsusb information:

Bus 005 Device 123: ID 1e0e:9011 Qualcomm / Option A76XX Series LTE Module
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               2.00
  bDeviceClass          239 Miscellaneous Device
  bDeviceSubClass         2 [unknown]
  bDeviceProtocol         1 Interface Association
  bMaxPacketSize0        64
  idVendor           0x1e0e Qualcomm / Option
  idProduct          0x9011 A76XX Series LTE Module
  bcdDevice            1.00
  iManufacturer           1 SIMCom Wireless Solution
  iProduct                2 A76XX Series LTE Module
  iSerial                 3 200806006809080000
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength       0x00c4
    bNumInterfaces          5
    bConfigurationValue     1
    iConfiguration          0
    bmAttributes         0xc0
      Self Powered
    MaxPower              500mA
    Interface Association:
      bLength                 8
      bDescriptorType        11
      bFirstInterface         0
      bInterfaceCount         2
      bFunctionClass        224 Wireless
      bFunctionSubClass       1 Radio Frequency
      bFunctionProtocol       3 RNDIS
      iFunction               5 Mobile RNDIS Network Adapter
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           1
      bInterfaceClass       224 Wireless
      bInterfaceSubClass      1 Radio Frequency
      bInterfaceProtocol      3 RNDIS
      iInterface              5 Mobile RNDIS Network Adapter
      ** UNRECOGNIZED:  05 24 00 10 01
      ** UNRECOGNIZED:  05 24 01 00 01
      ** UNRECOGNIZED:  04 24 02 00
      ** UNRECOGNIZED:  05 24 06 00 01
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x87  EP 7 IN
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0040  1x 64 bytes
        bInterval              16
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        1
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass        10 CDC Data
      bInterfaceSubClass      0 [unknown]
      bInterfaceProtocol      0
      iInterface              5 Mobile RNDIS Network Adapter
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x83  EP 3 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x0c  EP 12 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        2
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass       255 Vendor Specific Class
      bInterfaceSubClass      0 [unknown]
      bInterfaceProtocol      0
      iInterface              8 Mobile Diag Interface
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x82  EP 2 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x0b  EP 11 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        4
      bAlternateSetting       0
      bNumEndpoints           3
      bInterfaceClass       255 Vendor Specific Class
      bInterfaceSubClass      0 [unknown]
      bInterfaceProtocol      0
      iInterface             11 Mobile AT Interface
      ** UNRECOGNIZED:  05 24 00 10 01
      ** UNRECOGNIZED:  05 24 01 00 00
      ** UNRECOGNIZED:  04 24 02 02
      ** UNRECOGNIZED:  05 24 06 00 00
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x89  EP 9 IN
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0040  1x 64 bytes
        bInterval              16
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x86  EP 6 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x0f  EP 15 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        5
      bAlternateSetting       0
      bNumEndpoints           3
      bInterfaceClass       255 Vendor Specific Class
      bInterfaceSubClass      0 [unknown]
      bInterfaceProtocol      0
      iInterface             11 Mobile AT Interface
      ** UNRECOGNIZED:  05 24 00 10 01
      ** UNRECOGNIZED:  05 24 01 00 00
      ** UNRECOGNIZED:  04 24 02 02
      ** UNRECOGNIZED:  05 24 06 00 00
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x88  EP 8 IN
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0040  1x 64 bytes
        bInterval              16
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x0a  EP 10 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0200  1x 512 bytes
        bInterval               0
Device Qualifier (for other device speed):
  bLength                10
  bDescriptorType         6
  bcdUSB               2.00
  bDeviceClass            0 [unknown]
  bDeviceSubClass         0 [unknown]
  bDeviceProtocol         0
  bMaxPacketSize0        16
  bNumConfigurations      1
Device Status:     0x0001
  Self Powered

This is a pretty complex composite device, but effectively we get one USB RNDIS network adapter and three UART endpoints (ttyUSB). The last two of those serial endpoints allow controlling the module via standard AT commands. When connected, the RNDIS interface will be used to transfer data. It will show up as a regular network interface on the GNU/Linux host.

For our demonstrator, we aim to use plain UART communications and thus we will not use this USB connection. So let's see what the USB connector on the EVB exposes.

USB Device on EVB

Plugging the EVB into my GNU/Linux host, yields this device:

Bus 005 Device 125: ID 1a86:55d2 QinHeng Electronics USB Dual_Serial
Device Descriptor:
  bLength                18
  bDescriptorType         1
  bcdUSB               1.10
  bDeviceClass          239 Miscellaneous Device
  bDeviceSubClass         2 [unknown]
  bDeviceProtocol         1 Interface Association
  bMaxPacketSize0         8
  idVendor           0x1a86 QinHeng Electronics
  idProduct          0x55d2 USB Dual_Serial
  bcdDevice            4.45
  iManufacturer           0
  iProduct                2 USB Dual_Serial
  iSerial                 3 5510046696
  bNumConfigurations      1
  Configuration Descriptor:
    bLength                 9
    bDescriptorType         2
    wTotalLength       0x008d
    bNumInterfaces          4
    bConfigurationValue     1
    iConfiguration          0
    bmAttributes         0x80
      (Bus Powered)
    MaxPower              138mA
    Interface Association:
      bLength                 8
      bDescriptorType        11
      bFirstInterface         0
      bInterfaceCount         2
      bFunctionClass          2 Communications
      bFunctionSubClass       2 Abstract (modem)
      bFunctionProtocol       1 AT-commands (v.25ter)
      iFunction               0
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        0
      bAlternateSetting       0
      bNumEndpoints           1
      bInterfaceClass         2 Communications
      bInterfaceSubClass      2 Abstract (modem)
      bInterfaceProtocol      1 AT-commands (v.25ter)
      iInterface              0
      CDC Header:
        bcdCDC               1.10
      CDC Call Management:
        bmCapabilities       0x00
        bDataInterface          1
      CDC ACM:
        bmCapabilities       0x02
          line coding and serial state
      CDC Union:
        bMasterInterface        0
        bSlaveInterface         1
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x81  EP 1 IN
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0008  1x 8 bytes
        bInterval               1
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        1
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass        10 CDC Data
      bInterfaceSubClass      0 [unknown]
      bInterfaceProtocol      0
      iInterface              0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x02  EP 2 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0020  1x 32 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x82  EP 2 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0040  1x 64 bytes
        bInterval               0
    Interface Association:
      bLength                 8
      bDescriptorType        11
      bFirstInterface         2
      bInterfaceCount         2
      bFunctionClass          2 Communications
      bFunctionSubClass       2 Abstract (modem)
      bFunctionProtocol       1 AT-commands (v.25ter)
      iFunction               0
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        2
      bAlternateSetting       0
      bNumEndpoints           1
      bInterfaceClass         2 Communications
      bInterfaceSubClass      2 Abstract (modem)
      bInterfaceProtocol      1 AT-commands (v.25ter)
      iInterface              0
      CDC Header:
        bcdCDC               1.10
      CDC Call Management:
        bmCapabilities       0x00
        bDataInterface          1
      CDC ACM:
        bmCapabilities       0x02
          line coding and serial state
      CDC Union:
        bMasterInterface        2
        bSlaveInterface         3
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x84  EP 4 IN
        bmAttributes            3
          Transfer Type            Interrupt
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0008  1x 8 bytes
        bInterval               1
    Interface Descriptor:
      bLength                 9
      bDescriptorType         4
      bInterfaceNumber        3
      bAlternateSetting       0
      bNumEndpoints           2
      bInterfaceClass        10 CDC Data
      bInterfaceSubClass      0 [unknown]
      bInterfaceProtocol      0
      iInterface              0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x03  EP 3 OUT
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0020  1x 32 bytes
        bInterval               0
      Endpoint Descriptor:
        bLength                 7
        bDescriptorType         5
        bEndpointAddress     0x83  EP 3 IN
        bmAttributes            2
          Transfer Type            Bulk
          Synch Type               None
          Usage Type               Data
        wMaxPacketSize     0x0040  1x 64 bytes
        bInterval               0
Device Status:     0x0000
  (Bus Powered)

This composite device will show up simply as two serial ports (ttyACM). Reading the documentation, we find that the first one is a continuous stream of debug information and the second one is the actual UART interface that can be used to control the modem and connect via the ppp protocol to the internet.

Using my usb-console script, it is easy to connect to both ports in one tmux session. This way it is very easy to keep an eye on all of the ports during the experiments. Connecting to the second port, it is easy to get some rudimentary information:

AT+CPSI?
+CPSI: LTE,Online,262-01,0x63A7,31085319,393,EUTRAN-BAND8,3749,3,0,0,27,26,-9

OK

Cool, the Simcard that I plugged into the SIM1 slot does not require a pin and "just works". All we need to do is to set an APN and then we can connect to the internet:

AT+CGDCONT=1,"IP","iot.1nce.net"
OK
ATDT*99#
CONNECT 115200

Ok, at this point the modem is ready to talk ppp and we thus start pppd manually on our GNU/Linux host:

sudo /usr/sbin/pppd /dev/ttyACM1 noauth nodetach debug

On an otherwise unconnected machine, this will bring up the ppp0 interface and we can do some basic tests. As I do not care about DNS, all I want to see is some ping answers from Googles DNS servers:

sudo ip route add default dev ppp0

dzu@krikkit:~$ ping 8.8.8.8
PING 8.8.8.8 (8.8.8.8) 56(84) bytes of data.
64 bytes from 8.8.8.8: icmp_seq=10 ttl=57 time=7365 ms
64 bytes from 8.8.8.8: icmp_seq=11 ttl=57 time=6383 ms
64 bytes from 8.8.8.8: icmp_seq=12 ttl=57 time=5371 ms
64 bytes from 8.8.8.8: icmp_seq=13 ttl=57 time=4358 ms
64 bytes from 8.8.8.8: icmp_seq=14 ttl=57 time=3333 ms
64 bytes from 8.8.8.8: icmp_seq=15 ttl=57 time=2319 ms
64 bytes from 8.8.8.8: icmp_seq=16 ttl=57 time=1310 ms
64 bytes from 8.8.8.8: icmp_seq=17 ttl=57 time=287 ms
64 bytes from 8.8.8.8: icmp_seq=18 ttl=57 time=98.9 ms
64 bytes from 8.8.8.8: icmp_seq=19 ttl=57 time=105 ms
64 bytes from 8.8.8.8: icmp_seq=20 ttl=57 time=96.7 ms
64 bytes from 8.8.8.8: icmp_seq=21 ttl=57 time=89.2 ms
64 bytes from 8.8.8.8: icmp_seq=22 ttl=57 time=90.7 ms
64 bytes from 8.8.8.8: icmp_seq=23 ttl=57 time=84.4 ms
64 bytes from 8.8.8.8: icmp_seq=24 ttl=57 time=91.2 ms
64 bytes from 8.8.8.8: icmp_seq=25 ttl=57 time=101 ms
64 bytes from 8.8.8.8: icmp_seq=26 ttl=57 time=94.5 ms
64 bytes from 8.8.8.8: icmp_seq=27 ttl=57 time=118 ms
64 bytes from 8.8.8.8: icmp_seq=28 ttl=57 time=79.9 ms
64 bytes from 8.8.8.8: icmp_seq=29 ttl=57 time=82.8 ms
64 bytes from 8.8.8.8: icmp_seq=30 ttl=57 time=76.9 ms
64 bytes from 8.8.8.8: icmp_seq=31 ttl=57 time=77.8 ms
64 bytes from 8.8.8.8: icmp_seq=32 ttl=57 time=119 ms
64 bytes from 8.8.8.8: icmp_seq=33 ttl=57 time=80.9 ms
64 bytes from 8.8.8.8: icmp_seq=34 ttl=57 time=156 ms

As can be seen, the connection took some time to come up properly but then the ping times are actually pretty good.

So at this stage I am confident that the Simcom module works as expected with the SIM card of my choice. The fact that I can manually start a ppp connectino through the serial interface gives me confidence that one the connectino is setup correctly, the ST board should be able to do the same.

nucleo_u575zi_q

Finding A Serial Port

So let's look at the other end of our intended UART communication. Reading the the User Manual of the Nucleo board, we find that UART1 is connected to the STLink debug adapter, but UART2 is available on the Arduino header CN9:

Pin	Function	FTDI Pin
4	USART_B_RX	TX
6	USART_B_TX	RX
8	USART_B_RTS	RTS
10	USART_B_CTS
12	GND	GND

Nice! To test this, we simply hook up an FTDI serial to USB adapter to pin 4,6 and 12:

In order to test this, we use the plain shell_module example, but override the chosen entries in the device tree to route input and output to USART2:

dzu@zarniwoop:zephyr$ pwd
/home/dzu/src/zephyr
dzu@zarniwoop:zephyr$ cp -ar /opt/src/git/zephyrproject/zephyr/samples/subsys/shell/shell_module .
dzu@zarniwoop:zephyr$ cd shell_module
dzu@zarniwoop:shell_module$ cat <<EOF > nucleo_u575zi_q.overlay
/ {
        chosen {
                zephyr,console = &usart2;
                zephyr,shell-uart = &usart2;
        };
};
EOF
dzu@zarniwoop:shell_module$

With this in place, building the application is trivial:

dzu@zarniwoop:shell_module$ west build -b nucleo_u575zi_q
-- west build: generating a build system
Loading Zephyr default modules (Zephyr base).
-- Application: /home/dzu/src/zephyr/shell_module
-- CMake version: 3.22.1
-- Found Python3: /usr/bin/python3 (found suitable version "3.10.12", minimum required is "3.8") found components: Interpreter
-- Cache files will be written to: /home/dzu/.cache/zephyr
-- Zephyr version: 3.6.99 (/opt/src/git/zephyrproject/zephyr)
-- Found west (found suitable version "1.2.0", minimum required is "0.14.0")
-- Board: nucleo_u575zi_q, qualifiers: stm32u575xx
-- Found host-tools: zephyr 0.16.4 (/opt/zephyr-sdk-0.16.4)
-- Found toolchain: zephyr 0.16.4 (/opt/zephyr-sdk-0.16.4)
-- Found Dtc: /opt/zephyr-sdk-0.16.4/sysroots/x86_64-pokysdk-linux/usr/bin/dtc (found suitable version "1.6.0", minimum required is "1.4.6")
-- Found BOARD.dts: /opt/src/git/zephyrproject/zephyr/boards/st/nucleo_u575zi_q/nucleo_u575zi_q.dts
-- Found devicetree overlay: /home/dzu/src/zephyr/shell_module/nucleo_u575zi_q.overlay
-- Generated zephyr.dts: /home/dzu/src/zephyr/shell_module/build/nucleo_u575zi_q/zephyr/zephyr.dts
-- Generated devicetree_generated.h: /home/dzu/src/zephyr/shell_module/build/nucleo_u575zi_q/zephyr/include/generated/devicetree_generated.h
-- Including generated dts.cmake file: /home/dzu/src/zephyr/shell_module/build/nucleo_u575zi_q/zephyr/dts.cmake
Parsing /home/dzu/src/zephyr/shell_module/Kconfig
Loaded configuration '/opt/src/git/zephyrproject/zephyr/boards/st/nucleo_u575zi_q/nucleo_u575zi_q_defconfig'
Merged configuration '/home/dzu/src/zephyr/shell_module/prj.conf'
Configuration saved to '/home/dzu/src/zephyr/shell_module/build/nucleo_u575zi_q/zephyr/.config'
Kconfig header saved to '/home/dzu/src/zephyr/shell_module/build/nucleo_u575zi_q/zephyr/include/generated/autoconf.h'
-- Found GnuLd: /opt/zephyr-sdk-0.16.4/arm-zephyr-eabi/bin/../lib/gcc/arm-zephyr-eabi/12.2.0/../../../../arm-zephyr-eabi/bin/ld.bfd (found version "2.38")
-- The C compiler identification is GNU 12.2.0
-- The CXX compiler identification is GNU 12.2.0
-- The ASM compiler identification is GNU
-- Found assembler: /opt/zephyr-sdk-0.16.4/arm-zephyr-eabi/bin/arm-zephyr-eabi-gcc
-- Using ccache: /usr/bin/ccache
-- Configuring done
-- Generating done
-- Build files have been written to: /home/dzu/src/zephyr/shell_module/build/nucleo_u575zi_q
-- west build: building application
[1/171] Preparing syscall dependency handling

[2/171] Generating include/generated/version.h
-- Zephyr version: 3.6.99 (/opt/src/git/zephyrproject/zephyr), build: v3.6.0-1761-gdd0923d7ad8a
[171/171] Linking C executable zephyr/zephyr.elf
Memory region         Used Size  Region Size  %age Used
           FLASH:       64952 B         2 MB      3.10%
             RAM:       13232 B       768 KB      1.68%
        IDT_LIST:          0 GB        32 KB      0.00%
Generating files from /home/dzu/src/zephyr/shell_module/build/nucleo_u575zi_q/zephyr/zephyr.elf for board: nucleo_u575zi_q
dzu@zarniwoop:shell_module$

Flashing is also easy. Note that I use the openocd runner as this does not need the STM32CubeProgrammer software:

dzu@zarniwoop:shell_module$ west flash -d build/nucleo_u575zi_q/ -r openocd
-- west flash: rebuilding
ninja: no work to do.
-- west flash: using runner openocd
-- runners.openocd: Flashing file: build/nucleo_u575zi_q/zephyr/zephyr.hex
Open On-Chip Debugger 0.11.0+dev-00726-ge2b6f5655 (2023-11-15-11:07)
Licensed under GNU GPL v2
For bug reports, read
        http://openocd.org/doc/doxygen/bugs.html
Info : DEPRECATED target event trace-config; use TPIU events {pre,post}-{enable,disable}
Info : STLINK V3J10M3 (API v3) VID:PID 0483:374E
Info : Target voltage: 3.283455
Info : Unable to match requested speed 500 kHz, using 200 kHz
Info : Unable to match requested speed 500 kHz, using 200 kHz
Info : clock speed 200 kHz
Info : stlink_dap_op_connect(connect)
Info : SWD DPIDR 0x0be12477
Info : [STM32U575ZITxQ.cpu] Cortex-M33 r0p4 processor detected
Info : [STM32U575ZITxQ.cpu] target has 8 breakpoints, 4 watchpoints
Info : [STM32U575ZITxQ.cpu] external reset detected
Info : starting gdb server for STM32U575ZITxQ.cpu on 3333
Info : Listening on port 3333 for gdb connections
    TargetName         Type       Endian TapName            State
--  ------------------ ---------- ------ ------------------ ------------
 0* STM32U575ZITxQ.cpu cortex_m   little STM32U575ZITxQ.cpu reset

Info : Unable to match requested speed 480 kHz, using 200 kHz
Info : Unable to match requested speed 480 kHz, using 200 kHz
CPU in Non-Secure state
target halted due to debug-request, current mode: Thread
xPSR: 0xf9000000 pc: 0x0800090c msp: 0x20001088
Info : Unable to match requested speed 4000 kHz, using 3300 kHz
Info : Unable to match requested speed 4000 kHz, using 3300 kHz
Info : device idcode = 0x10016482 (STM32U57/U58xx - Rev Z : 0x1001)
Info : TZEN = 0 : TrustZone disabled by option bytes
Info : RDP level 0 (0xAA)
Info : flash size = 2048kbytes
Info : flash mode : dual-bank
Info : Padding image section 0 at 0x0800fdb8 with 8 bytes (bank write end alignment)
Warn : Adding extra erase range, 0x0800fdc0 .. 0x0800ffff
auto erase enabled
wrote 64960 bytes from file build/nucleo_u575zi_q/zephyr/zephyr.hex in 0.588708s (107.757 KiB/s)

Info : Unable to match requested speed 480 kHz, using 200 kHz
Info : Unable to match requested speed 480 kHz, using 200 kHz
shutdown command invoked
dzu@zarniwoop:shell_module$

After flashing, the board now reacts to commands over USART2:

uart:~$ version
Zephyr version 3.6.99
uart:~$ demo board
nucleo_u575zi_q
uart:~$

As a final check, the device tree overlay can be removed again and after recompilation, the shell should show up on the STLink port rather than the external USB to serial channel.

Emulating The Modem

Before we finally put together the hardware, let's use the current setup to verify that our Zephyr App tries to talk to the modem on USART2. So without attaching the modem, we expect to see the chatscript for the generic modem being sent to the port. We should also be able to "play the modem" and send answers to see progress on the Zephyr side.

For this, we start by copying the respective example from the upstream Zephyr tree:

dzu@zarniwoop:zephyr$ pwd
/home/dzu/src/zephyr
dzu@zarniwoop:zephyr$ cp -ar /opt/src/git/zephyrproject/zephyr/samples/net/cellular_modem/ .
dzu@zarniwoop:zephyr$ cd cellular_modem/
dzu@zarniwoop:cellular_modem$

In this case I also need to adjust the configuration, so I went with the upstream example and put my "extensions" into the board subdirectory:

dzu@zarniwoop:cellular_modem$ cat boards/nucleo_u575zi_q.conf
# Copyright (c) 2024, Detlev Zundel
# SPDX-License-Identifier: Apache-2.0

CONFIG_UART_ASYNC_API=y
CONFIG_MODEM_CELLULAR_APN="iot.1nce.net"
dzu@zarniwoop:cellular_modem$ cat boards/nucleo_u575zi_q.overlay
/ {
        aliases {
                modem-uart = &usart2;
                modem = &modem;
        };
};

&usart2 {
        status = "okay";

        modem: modem {
                compatible = "zephyr,gsm";
                status = "okay";
        };
};
dzu@zarniwoop:cellular_modem$

With this preparation, it is easy to build and flash the project:

west build -b nucleo_u575zi_q
west flash -d build/nucleao_u575zi_q

But testing it out, we see some output on the console, but no output on the modem end. Here is what the console says:

  *** Booting Zephyr OS build v3.6.0-1832-gd34351d99454 ***
  Powering on modem
  [00:00:00.005,000] <wrn> modem_cellular: failed to enter state error: -19
  Bring up network interface
  Waiting for L4 connected

After a timeout, this string is appended:

L4 was not connected in time

So it seems we are stuck and need to dive in deeper to find why we do not ee any output on USART2, although we know that we can use the port just fine with the shell example application. Because we did this additional step in our preparation, we now know that the problem is not really in the serial driver but somewhere in the usage of the serial port in the cellular_modem stack.

Debugging The Problem

It is easy to fire up standard gdb on our application like this

dzu@krikkit:~/src/zephyr/cellular_modem$ west debug -d build/nucleo_u575zi_q/
-- west debug: rebuilding
ninja: no work to do.
-- west debug: using runner openocd
-- runners.openocd: OpenOCD GDB server running on port 3333; no thread info available
Open On-Chip Debugger 0.11.0+dev-00728-gb6f95a16c (2024-02-17-23:51)
Licensed under GNU GPL v2
For bug reports, read
	http://openocd.org/doc/doxygen/bugs.html
Info : DEPRECATED target event trace-config; use TPIU events {pre,post}-{enable,disable}
Info : STLINK V3J10M3 (API v3) VID:PID 0483:374E
Info : Target voltage: 3.285050
Info : Unable to match requested speed 500 kHz, using 200 kHz
Info : Unable to match requested speed 500 kHz, using 200 kHz
Info : clock speed 200 kHz
Info : stlink_dap_op_connect(connect)
Info : SWD DPIDR 0x0be12477
GNU gdb (Zephyr SDK 0.16.5-1) 12.1
Copyright (C) 2022 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "--host=x86_64-build_pc-linux-gnu --target=arm-zephyr-eabi".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://github.com/zephyrproject-rtos/sdk-ng/issues>.
Find the GDB manual and other documentation resources online at:
    <http://www.gnu.org/software/gdb/documentation/>.

For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from build/nucleo_u575zi_q/zephyr/zephyr.elf...
Info : [STM32U575ZITxQ.cpu] Cortex-M33 r0p4 processor detected
Info : [STM32U575ZITxQ.cpu] target has 8 breakpoints, 4 watchpoints
Info : [STM32U575ZITxQ.cpu] external reset detected
Info : starting gdb server for STM32U575ZITxQ.cpu on 3333
Info : Listening on port 3333 for gdb connections
    TargetName         Type       Endian TapName            State       
--  ------------------ ---------- ------ ------------------ ------------
 0* STM32U575ZITxQ.cpu cortex_m   little STM32U575ZITxQ.cpu reset

Info : Listening on port 6666 for tcl connections
Info : Listening on port 4444 for telnet connections
Remote debugging using :3333
Info : accepting 'gdb' connection on tcp/3333
Debugger attaching: halting execution
Info : Unable to match requested speed 480 kHz, using 200 kHz
Info : Unable to match requested speed 480 kHz, using 200 kHz
CPU in Non-Secure state
target halted due to debug-request, current mode: Thread 
xPSR: 0xf9000000 pc: 0x080025e8 msp: 0x20006b10
force hard breakpoints
Info : device idcode = 0x10016482 (STM32U57/U58xx - Rev Z : 0x1001)
Info : TZEN = 0 : TrustZone disabled by option bytes
Info : RDP level 0 (0xAA)
Info : flash size = 2048kbytes
Info : flash mode : dual-bank
Info : device idcode = 0x10016482 (STM32U57/U58xx - Rev Z : 0x1001)
Info : TZEN = 0 : TrustZone disabled by option bytes
Info : RDP level 0 (0xAA)
Info : flash size = 2048kbytes
Info : flash mode : dual-bank
Info : device idcode = 0x10016482 (STM32U57/U58xx - Rev Z : 0x1001)
Info : TZEN = 0 : TrustZone disabled by option bytes
Info : RDP level 0 (0xAA)
Info : OTP size is 512 bytes, base address is 0x0bfa0000
z_arm_reset () at /opt/src/git/zephyrproject/zephyr/arch/arm/core/cortex_m/reset.S:119
119	    movs.n r0, #_EXC_IRQ_DEFAULT_PRIO
TZEN option bit disabled
workarea_addr 536870912
Loading section rom_start, size 0x234 lma 0x8000000
Loading section text, size 0x198c8 lma 0x8000234
Loading section .ARM.exidx, size 0x8 lma 0x8019afc
Loading section initlevel, size 0x110 lma 0x8019b04
Loading section device_area, size 0x1c8 lma 0x8019c14
Loading section sw_isr_table, size 0x3e8 lma 0x8019ddc
Loading section _static_thread_data_area, size 0x30 lma 0x801a1c8
Loading section net_socket_register_area, size 0x10 lma 0x801a1f8
Loading section ppp_protocol_handler_area, size 0x70 lma 0x801a208
Loading section log_const_area, size 0xd0 lma 0x801a278
Loading section log_backend_area, size 0x10 lma 0x801a348
Loading section rodata, size 0x2328 lma 0x801a358
Loading section datas, size 0x1d70 lma 0x801c680
Loading section device_states, size 0x26 lma 0x801e3f0
Loading section log_mpsc_pbuf_area, size 0x40 lma 0x801e418
--Type <RET> for more, q to quit, c to continue without paging--c
Loading section log_msg_ptr_area, size 0x4 lma 0x801e458
Loading section k_mem_slab_area, size 0x38 lma 0x801e45c
Loading section k_heap_area, size 0x14 lma 0x801e494
Loading section k_mutex_area, size 0xa0 lma 0x801e4a8
Loading section k_msgq_area, size 0x30 lma 0x801e548
Loading section k_sem_area, size 0x48 lma 0x801e578
Loading section k_fifo_area, size 0x18 lma 0x801e5c0
Loading section net_buf_pool_area, size 0xb0 lma 0x801e5d8
Loading section net_if_area, size 0x40 lma 0x801e688
Loading section net_if_dev_area, size 0x1c lma 0x801e6c8
Loading section net_l2_area, size 0x10 lma 0x801e6e4
Loading section .last_section, size 0x4 lma 0x801e6f4
Info : Padding image section 0 at 0x0801a1c4 with 4 bytes
Info : Padding image section 1 at 0x0801e416 with 2 bytes
Info : Padding image section 2 at 0x0801e6f8 with 8 bytes (bank write end alignment)
Info : Unable to match requested speed 480 kHz, using 200 kHz
Info : Unable to match requested speed 480 kHz, using 200 kHz
target halted due to debug-request, current mode: Thread 
xPSR: 0xf9000000 pc: 0x080025e8 msp: 0x20006b10
Start address 0x080025e8, load size 124658
Transfer rate: 17 KB/sec, 3777 bytes/write.
(gdb)

Note that while the debugger starts up, it will pause in a paged output ("–Type <RET> for more …" in the output). Do not quit the pager with the key q or you will not correctly initialize the target. Be sure to press 'c' or 'Enter' and let gdb continue. After initialization, we can set a breakpoint in main, run until the breakpoint is reached and enable tui mode:

(gdb) b main
Breakpoint 1 at 0x8000804: file /home/dzu/src/zephyr/cellular_modem/src/main.c, line 280.
Note: automatically using hardware breakpoints for read-only addresses.
(gdb) c
Continuing.

Breakpoint 1, main () at /home/dzu/src/zephyr/cellular_modem/src/main.c:280
280		struct net_if *const iface = net_if_get_first_by_type(&NET_L2_GET_NAME(PPP));
(gdb) tui enable

From here on we can debug easily into all the relevant code stages. The architecture of cellular_modem is event driven and so stepping through the code is not a particular good way to follow the structure as we will step through all the scheduling of Zephyr when synchronization is used. With little learnings after the first round I decided to increase the logging of the program itself. Zephyr has a lot of compile time options, so I fired up menuconfig on the build:

dzu@krikkit:~/src/zephyr/cellular_modem$ west build -t menuconfig -b nucleo_u575zi_q

In Kconfig, you can search for options, read their documentation and check dependencies. One of the first options I increased was to set CONFIG_MODEM_LOG_LEVEL_DBG to 'y'. This is what we get:

  ** Booting Zephyr OS build v3.6.0-1832-gd34351d99454 ***
  Powering on modem
  [00:00:00.005,000] <dbg> modem_cellular: modem_cellular_log_event: event resume
  [00:00:00.005,000] <wrn> modem_cellular: failed to enter state error: -19
  [00:00:00.005,000] <dbg> modem_cellular: modem_cellular_log_state_changed: switch from idle to run init script
  Bring up network interface
  Waiting for L4 connected

So it seems the cellular_mode stack wants to run the init script but that is not really happening. Ok. Now that we know that the init script should run, we can look for functions implementing this. Studying the code in modem_cellular.c, we find that modem_cellular_on_run_init_script_state_enter is called when the FSM enters this state. So let's put a breakpoint on that location:

(gdb) b modem_cellular_on_run_init_script_state_enter
Breakpoint 1 at 0x800d756: file /opt/src/git/zephyrproject/zephyr/drivers/modem/modem_cellular.c, line 692.
Note: automatically using hardware breakpoints for read-only addresses.
(gdb)

Resetting the target for another run through the program is easy to do:

(gdb) mon reset halt

If breakpoints are still set, simply 'c' ontinue until the first one is hit. This time around, we will stop in main(), but continuing to the next breakpoint will break in modem_cellular_on_run_init_script_state_enter. Stepping from here, we can see that we progress through modem_pip_open_async and into pipe->api->open(). This brings us to modem_backend_uart_async_open() and ultimately into uart_rx_enable. Stepping into this, we will finally run into stm32_async_rx_enable() in drivers/serial/uart_stm32.c. The very first statement here checks for dma_rx.dma_dev and finds this to be null. This bails out very early with -ENODEV (-19). Hm, hm, hm. So the error message tells us that UART2 could not be enabled with the ASYNC_UART API. So the STM32 UART driver seems not to support the ASYNC interface?

Hm, ok, so do we need the ASYNC interface? We started with the config option CONFIG_UART_ASYNC_API set to 'y' but that was copied from the example. Unsetting this option will not even compile the project with this error message:

warning: MODEM_BACKEND_UART (defined at subsys/modem/backends/Kconfig:9) has direct dependencies (UART_INTERRUPT_DRIVEN || UART_ASYNC_API) && MODEM_MODULES with value n, but is currently being y-selected by the following symbols:
 - MODEM_CELLULAR (defined at drivers/modem/Kconfig.cellular:4), with value y, direct dependencies (DT_HAS_QUECTEL_BG95_ENABLED || DT_HAS_ZEPHYR_GSM_PPP_ENABLED || DT_HAS_SIMCOM_SIM7080_ENABLED || DT_HAS_U_BLOX_SARA_R4_ENABLED || DT_HAS_U_BLOX_SARA_R5_ENABLED || DT_HAS_SWIR_HL7800_ENABLED || DT_HAS_TELIT_ME910G1_ENABLED || DT_HAS_QUECTEL_EG25_G_ENABLED || DT_HAS_NORDIC_NRF91_SLM_ENABLED) && MODEM (value: y), and select condition (DT_HAS_QUECTEL_BG95_ENABLED || DT_HAS_ZEPHYR_GSM_PPP_ENABLED || DT_HAS_SIMCOM_SIM7080_ENABLED || DT_HAS_U_BLOX_SARA_R4_ENABLED || DT_HAS_U_BLOX_SARA_R5_ENABLED || DT_HAS_SWIR_HL7800_ENABLED || DT_HAS_TELIT_ME910G1_ENABLED || DT_HAS_QUECTEL_EG25_G_ENABLED || DT_HAS_NORDIC_NRF91_SLM_ENABLED) && MODEM (value: y)
Parsing /opt/src/git/zephyrproject/zephyr/Kconfig
Loaded configuration '/home/dzu/src/zephyr/cellular_modem/build/nucleo_u575zi_q/zephyr/.config'

error: Aborting due to Kconfig warnings

Ok, so the cellular_modem stack needs UART_ASYNC_API but the STM32 drivers do not use DMA for the serial ports? Ugh. This is a very much unanticipated problem in the project. Having used USART2 with the shell example made me think that it is supported. But it turns out, the port is not using DMA and cellular_modem requires this out of the box.

Checking the sample sources again, I see that another board, i.e. b_u585i_iot02a includes an overlay which enables DMA on the serial port. Copying this, I amend the nucleu_u575zi_q.overlay to end up like this:

/ {
        aliases {
                modem-uart = &usart2;
                modem = &modem;
        };
};

&usart2 {
        status = "okay";

        dmas = <&gpdma1 0 27 STM32_DMA_PERIPH_TX
                &gpdma1 1 26 STM32_DMA_PERIPH_RX>;
        dma-names = "tx", "rx";

        modem: modem {
                compatible = "zephyr,gsm-ppp";
                status = "okay";
        };
};

Recompiling the sample and checking the serial port, I now see that the stack is talking to the modem on USART2:

ATE0FUN=4

If we are quick enough, we can enter "OK" and enter several times to see Zephyr executing its modem script playbook. Now this seems good enough to connect to the modem itself.

Attaching the modem

Now we detach the FTDI adapter and connect the STM32 Nucleo Kit directly to the Simcom modem. Here are the connections:

Pin	Nucleo_u575zi_q	Pin	Simcom EVB
4	USART_B_RX	A11	TXD
6	USART_B_TX	A8	RXD
8	USART_B_RTS	A10	RTX
10	USART_B_CTS	A9	CTS
12	GND	C10	GND

And lo and behold we see communication happening between cellular_modem and the modem itself:

 *** Booting Zephyr OS build v3.6.0-1832-gd34351d99454 ***
Powering on modem
[00:00:00.005,000] <dbg> modem_chat: modem_chat_script_start: running script: zephyr_gsm_ppp_init_chat_script
[00:00:00.005,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 0
[00:00:00.005,000] <dbg> modem_chat: modem_chat_script_next: sending: AT
Bring up network interface
Waiting for L4 connected
[00:00:00.043,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT
[00:00:00.043,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: OK
[00:00:00.106,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 1
[00:00:00.106,000] <dbg> modem_chat: modem_chat_script_next: sending: AT
[00:00:00.143,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT
[00:00:00.143,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: OK
[00:00:00.206,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 2
[00:00:00.206,000] <dbg> modem_chat: modem_chat_script_next: sending: AT
[00:00:00.243,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT
[00:00:00.243,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: OK
[00:00:00.306,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 3
[00:00:00.306,000] <dbg> modem_chat: modem_chat_script_next: sending: AT
[00:00:00.343,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT
[00:00:00.343,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: OK
[00:00:00.407,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 4
[00:00:00.407,000] <dbg> modem_chat: modem_chat_script_next: sending: ATE0
[00:00:00.444,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: ATE0
[00:00:00.444,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:00.444,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 5
[00:00:00.444,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CFUN=4
[00:00:00.688,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: +CGEV: ME DETACH
[00:00:00.816,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:00.816,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 6
[00:00:00.816,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CMEE=1
[00:00:00.850,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:00.850,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 7
[00:00:00.850,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CREG=1
[00:00:00.888,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:00.888,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 8
[00:00:00.888,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGREG=1
[00:00:00.926,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:00.926,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 9
[00:00:00.926,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG=1
[00:00:00.963,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:00.963,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 10
[00:00:00.963,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CREG?
[00:00:01.002,000] <dbg> modem_chat: modem_chat_log_received_command: +CREG:  1 0
[00:00:01.002,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:01.002,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 11
[00:00:01.003,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG?
[00:00:01.042,000] <dbg> modem_chat: modem_chat_log_received_command: +CEREG:  1 0
[00:00:01.042,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:01.042,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 12
[00:00:01.042,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGREG?
[00:00:01.081,000] <dbg> modem_chat: modem_chat_log_received_command: +CGREG:  1 0
[00:00:01.081,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:01.081,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 13
[00:00:01.081,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGSN
[00:00:01.123,000] <dbg> modem_chat: modem_chat_log_received_command:  862095060003511
[00:00:01.123,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 14
[00:00:01.123,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:01.123,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 15
[00:00:01.123,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGMM
[00:00:01.162,000] <dbg> modem_chat: modem_chat_log_received_command:  A7683E-LAXS
[00:00:01.162,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 16
[00:00:01.162,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:01.162,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_init_chat_script: step: 17
[00:00:01.162,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CMUX=0,0,5,127
[00:00:01.200,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: OK
[00:00:01.463,000] <dbg> modem_chat: modem_chat_script_stop: zephyr_gsm_ppp_init_chat_script: complete
[00:00:01.759,000] <dbg> modem_chat: modem_chat_script_start: running script: zephyr_gsm_ppp_dial_chat_script
[00:00:01.759,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_dial_chat_script: step: 0
[00:00:01.759,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGACT=0,1
[00:00:01.800,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CGACT=0,1
[00:00:01.800,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:01.800,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_dial_chat_script: step: 1
[00:00:01.800,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGDCONT=1,"IP","iot.1nce.net"
[00:00:01.844,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CGDCONT=1,"IP","iot.1nce.net"
[00:00:01.844,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:01.844,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_dial_chat_script: step: 2
[00:00:01.844,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CFUN=1
[00:00:01.946,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CFUN=1
[00:00:02.142,000] <dbg> modem_chat: modem_chat_script_next: sending: ATD*99***1#
--- 2 messages dropped ---
[00:00:02.142,000] <dbg> modem_chat: modem_chat_script_stop: zephyr_gsm_ppp_dial_chat_script: complete
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x41 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x54 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x44 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2a because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x39 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x39 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2a because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2a because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2a because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x31 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x23 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0a because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x43 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x4f because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x4e because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x4e because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x45 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x43 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x54 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0a because 0x7e was expected.
[00:00:04.142,000] <dbg> modem_chat: modem_chat_script_start: running script: zephyr_gsm_ppp_periodic_chat_script
[00:00:04.142,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 0
[00:00:04.142,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CREG?
[00:00:04.185,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CREG?
[00:00:04.185,000] <dbg> modem_chat: modem_chat_log_received_command: +CREG:  1 0
[00:00:04.185,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:04.185,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 1
[00:00:04.185,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG?
[00:00:04.227,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CEREG?
[00:00:04.228,000] <dbg> modem_chat: modem_chat_log_received_command: +CEREG:  1 0
[00:00:04.228,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:04.228,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 2
[00:00:04.228,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGREG?
[00:00:04.270,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CGREG?
[00:00:04.270,000] <dbg> modem_chat: modem_chat_log_received_command: +CGREG:  1 0
[00:00:04.270,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:04.270,000] <dbg> modem_chat: modem_chat_script_stop: zephyr_gsm_ppp_periodic_chat_script: complete
[00:00:06.270,000] <dbg> modem_chat: modem_chat_script_start: running script: zephyr_gsm_ppp_periodic_chat_script
[00:00:06.270,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 0
[00:00:06.270,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CREG?
[00:00:06.279,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CREG?
[00:00:06.311,000] <dbg> modem_chat: modem_chat_log_received_command: +CREG:  1 0
[00:00:06.311,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:06.311,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 1
[00:00:06.311,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG?
[00:00:06.350,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CEREG?
[00:00:06.350,000] <dbg> modem_chat: modem_chat_log_received_command: +CEREG:  1 0
[00:00:06.350,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:06.350,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 2
[00:00:06.350,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGREG?
[00:00:06.360,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CGREG?
[00:00:06.360,000] <dbg> modem_chat: modem_chat_log_received_command: +CGREG:  1 0
[00:00:06.390,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:06.390,000] <dbg> modem_chat: modem_chat_script_stop: zephyr_gsm_ppp_periodic_chat_script: complete
[00:00:08.391,000] <dbg> modem_chat: modem_chat_script_start: running script: zephyr_gsm_ppp_periodic_chat_script
[00:00:08.391,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 0
[00:00:08.391,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CREG?
[00:00:08.433,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CREG?
[00:00:08.433,000] <dbg> modem_chat: modem_chat_log_received_command: +CREG:  1 0
[00:00:08.433,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:08.433,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 1
[00:00:08.433,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG?
[00:00:08.474,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CEREG?
[00:00:08.475,000] <dbg> modem_chat: modem_chat_log_received_command: +CEREG:  1 0
[00:00:08.475,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:08.475,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 2
[00:00:08.475,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGREG?
[00:00:08.517,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CGREG?
[00:00:08.517,000] <dbg> modem_chat: modem_chat_log_received_command: +CGREG:  1 0
[00:00:08.517,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:08.517,000] <dbg> modem_chat: modem_chat_script_stop: zephyr_gsm_ppp_periodic_chat_script: complete
[00:00:10.517,000] <dbg> modem_chat: modem_chat_script_start: running script: zephyr_gsm_ppp_periodic_chat_script
[00:00:10.517,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 0
[00:00:10.517,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CREG?
[00:00:10.642,000] <dbg> modem_chat: modem_chat_log_received_command: +CEREG:  11
[00:00:10.642,000] <dbg> modem_chat: modem_chat_log_received_command: +CGREG:  11
[00:00:10.642,000] <dbg> modem_chat: modem_chat_log_received_command: +CREG:  11
[00:00:10.642,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CREG?
[00:00:10.673,000] <dbg> modem_chat: modem_chat_log_received_command: +CREG:  1 11
[00:00:10.674,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:10.674,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 1
[00:00:10.674,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG?
[00:00:10.719,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CEREG?
[00:00:10.719,000] <dbg> modem_chat: modem_chat_log_received_command: +CEREG:  1 11
[00:00:10.719,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:10.719,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 2
[00:00:10.719,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGREG?
[00:00:10.731,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CGREG?
[00:00:10.731,000] <dbg> modem_chat: modem_chat_log_received_command: +CGREG:  1 11
[00:00:10.762,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:10.762,000] <dbg> modem_chat: modem_chat_script_stop: zephyr_gsm_ppp_periodic_chat_script: complete
[00:00:11.764,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: +CGEV: EPS PDN ACT 1
[00:00:11.764,000] <dbg> modem_chat: modem_chat_log_received_command: +CEREG:  5
[00:00:11.796,000] <dbg> modem_chat: modem_chat_log_received_command: +CGREG:  5
[00:00:11.797,000] <dbg> modem_chat: modem_chat_log_received_command: +CREG:  5
[00:00:12.201,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:12.201,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 28)
[00:00:12.201,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:12.201,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 12)
[00:00:12.240,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Receiving PPP frame
[00:00:12.240,000] <dbg> modem_ppp: modem_ppp_process_received_byte: Received PPP frame (len 12)
[00:00:12.431,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x03 because 0x7d was expected.
[00:00:12.431,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xc0 because 0x7e was expected.
[00:00:12.431,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x23 because 0x7e was expected.
[00:00:12.431,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x02 because 0x7e was expected.
[00:00:12.431,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x01 because 0x7e was expected.
[00:00:12.431,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x00 because 0x7e was expected.
[00:00:12.431,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x06 because 0x7e was expected.
[00:00:12.431,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x00 because 0x7e was expected.
[00:00:12.431,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x00 because 0x7e was expected.
[00:00:12.431,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xfc because 0x7e was expected.
[00:00:12.431,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x25 because 0x7e was expected.
[00:00:13.764,000] <dbg> modem_chat: modem_chat_script_start: running script: zephyr_gsm_ppp_periodic_chat_script
[00:00:13.764,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 0
[00:00:13.764,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CREG?
[00:00:13.806,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CREG?
[00:00:13.806,000] <dbg> modem_chat: modem_chat_log_received_command: +CREG:  1 5
[00:00:13.806,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:13.806,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 1
[00:00:13.806,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG?
[00:00:13.846,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CEREG?
[00:00:13.846,000] <dbg> modem_chat: modem_chat_log_received_command: +CEREG:  1 5
[00:00:13.846,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:13.846,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 2
[00:00:13.846,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGREG?
[00:00:13.853,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CGREG?
[00:00:13.886,000] <dbg> modem_chat: modem_chat_log_received_command: +CGREG:  1 5
[00:00:13.886,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:13.886,000] <dbg> modem_chat: modem_chat_script_stop: zephyr_gsm_ppp_periodic_chat_script: complete
[00:00:15.394,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x03 because 0x7d was expected.
[00:00:15.394,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xc0 because 0x7e was expected.
[00:00:15.394,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x23 because 0x7e was expected.
[00:00:15.394,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x02 because 0x7e was expected.
[00:00:15.394,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x01 because 0x7e was expected.
[00:00:15.394,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x00 because 0x7e was expected.
[00:00:15.394,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x06 because 0x7e was expected.
[00:00:15.394,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x00 because 0x7e was expected.
[00:00:15.394,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x00 because 0x7e was expected.
[00:00:15.394,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xfc because 0x7e was expected.
[00:00:15.394,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x25 because 0x7e was expected.
[00:00:15.886,000] <dbg> modem_chat: modem_chat_script_start: running script: zephyr_gsm_ppp_periodic_chat_script
[00:00:15.886,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 0
[00:00:15.886,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CREG?
[00:00:15.925,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CREG?
[00:00:15.925,000] <dbg> modem_chat: modem_chat_log_received_command: +CREG:  1 5
[00:00:15.925,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:15.925,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 1
[00:00:15.925,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG?
[00:00:15.932,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CEREG?
[00:00:15.965,000] <dbg> modem_chat: modem_chat_log_received_command: +CEREG:  1 5
[00:00:15.965,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:15.965,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 2
[00:00:15.965,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGREG?
[00:00:16.005,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CGREG?
[00:00:16.005,000] <dbg> modem_chat: modem_chat_log_received_command: +CGREG:  1 5
[00:00:16.005,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:16.005,000] <dbg> modem_chat: modem_chat_script_stop: zephyr_gsm_ppp_periodic_chat_script: complete
[00:00:18.005,000] <dbg> modem_chat: modem_chat_script_start: running script: zephyr_gsm_ppp_periodic_chat_script
[00:00:18.005,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 0
[00:00:18.005,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CREG?
[00:00:18.013,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CREG?
[00:00:18.013,000] <dbg> modem_chat: modem_chat_log_received_command: +CREG:  1 5
[00:00:18.044,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:18.044,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 1
[00:00:18.044,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG?
[00:00:18.083,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CEREG?
[00:00:18.083,000] <dbg> modem_chat: modem_chat_log_received_command: +CEREG:  1 5
[00:00:18.083,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:18.083,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 2
[00:00:18.083,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGREG?
[00:00:18.123,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CGREG?
[00:00:18.123,000] <dbg> modem_chat: modem_chat_log_received_command: +CGREG:  1 5
[00:00:18.123,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:18.123,000] <dbg> modem_chat: modem_chat_script_stop: zephyr_gsm_ppp_periodic_chat_script: complete
[00:00:18.401,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x03 because 0x7d was expected.
[00:00:18.401,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xc0 because 0x7e was expected.
[00:00:18.401,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x23 because 0x7e was expected.
[00:00:18.401,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x02 because 0x7e was expected.
[00:00:18.401,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x01 because 0x7e was expected.
[00:00:18.401,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x00 because 0x7e was expected.
[00:00:18.401,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x06 because 0x7e was expected.
[00:00:18.401,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x00 because 0x7e was expected.
[00:00:18.401,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x00 because 0x7e was expected.
[00:00:18.401,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0xfc because 0x7e was expected.
[00:00:18.401,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x25 because 0x7e was expected.
[00:00:20.123,000] <dbg> modem_chat: modem_chat_script_start: running script: zephyr_gsm_ppp_periodic_chat_script
[00:00:20.123,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 0
[00:00:20.123,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CREG?
[00:00:20.162,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CREG?
[00:00:20.162,000] <dbg> modem_chat: modem_chat_log_received_command: +CREG:  1 5
[00:00:20.162,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:20.162,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 1
[00:00:20.162,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CEREG?
[00:00:20.202,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CEREG?
[00:00:20.202,000] <dbg> modem_chat: modem_chat_log_received_command: +CEREG:  1 5
[00:00:20.202,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:20.202,000] <dbg> modem_chat: modem_chat_script_next: zephyr_gsm_ppp_periodic_chat_script: step: 2
[00:00:20.202,000] <dbg> modem_chat: modem_chat_script_next: sending: AT+CGREG?
[00:00:20.242,000] <dbg> modem_chat: modem_chat_on_unknown_command_received: AT+CGREG?
[00:00:20.242,000] <dbg> modem_chat: modem_chat_log_received_command: +CGREG:  1 5
[00:00:20.242,000] <dbg> modem_chat: modem_chat_log_received_command: OK
[00:00:20.242,000] <dbg> modem_chat: modem_chat_script_stop: zephyr_gsm_ppp_periodic_chat_script: complete

Unfortunately, there are a lot of errors and the network interface does not come up in the end. But as I tested the modem with pppd under Debian, I now suspect the ppp/cmux stack from Zephyr to be the problem and start looking into how I can gain more information during the phase when ppp should come up.

But first I looked at the first batch of problems again - it seems the modem sends a string that is totally unexpected by cellular_modem:

[00:00:02.142,000] <dbg> modem_chat: modem_chat_script_stop: zephyr_gsm_ppp_dial_chat_script: complete
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x41 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x54 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x44 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2a because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x39 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x39 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2a because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2a because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x2a because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x31 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x23 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0a because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x43 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x4f because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x4e because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x4e because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x45 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x43 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x54 because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0d because 0x7e was expected.
[00:00:02.184,000] <dbg> modem_ppp: modem_ppp_is_byte_expected: Dropping byte 0x0a because 0x7e was expected.
[00:00:04.142,000] <dbg> modem_chat: modem_chat_script_start: running script: zephyr_gsm_ppp_periodic_chat_script

And indeed looking at the bytes, I see this is the response for the final command from the ppp_dial_chat_script, i.e. 'ATD*99***1#' plus the string "CONNECTED\r\n". Checking the source code again, it becomes obvious that our ppp chat script does not wait for any response to the ATDT command. To proceed in debugging, I inserted waiting for CONNECT also into the "zephyr,gsm-ppp" case. Indeed, this gets rid of the first batch of errors. Still the others remain.

Patching the connect script for proof of concept

To remove the first problem, we need to wait for the "CONNECT" answer from the modem. Some chat scripts implement such a wait, but "zephyr,gsm-ppp" currently does not. Eventually this should be solved by introducing our own chat scripts for this modem family, but for now, let's patch "zephyr,gsm-ppp". The chat script framework makes this basically a no-brainer. The only problem is that connect_match is protected by a modem using this functionality. Let's remove that barrier and change the last entry in the chat script. Here's the diff:

diff --git a/drivers/modem/modem_cellular.c b/drivers/modem/modem_cellular.c
index c66264d349f..7744f9eeeda 100644
--- a/drivers/modem/modem_cellular.c
+++ b/drivers/modem/modem_cellular.c
@@ -458,9 +458,7 @@ MODEM_CHAT_MATCHES_DEFINE(dial_abort_matches,
                          MODEM_CHAT_MATCH("NO CARRIER", "", NULL),
                          MODEM_CHAT_MATCH("NO DIALTONE", "", NULL));

-#if DT_HAS_COMPAT_STATUS_OKAY(swir_hl7800)
 MODEM_CHAT_MATCH_DEFINE(connect_match, "CONNECT", "", NULL);
-#endif

 static void modem_cellular_log_state_changed(enum modem_cellular_state last_state,
                                             enum modem_cellular_state new_state)
@@ -1734,7 +1732,7 @@ MODEM_CHAT_SCRIPT_CMDS_DEFINE(zephyr_gsm_ppp_dial_chat_script_cmds,
                                                         "\""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_CMD_RESP("ATD*99***1#", connect_match));

 MODEM_CHAT_SCRIPT_DEFINE(zephyr_gsm_ppp_dial_chat_script, zephyr_gsm_ppp_dial_chat_script_cmds,
                         dial_abort_matches, modem_cellular_chat_callback_handler, 10);

With this change, we remove the first block of errors, but the others still remain. There's some more debugging left to find the root cause why ppp does not start up.

Summary

It took some time, but we were finally able to connect our microcontroller to the simcom modem.