0

Device

  • Hardware: Raspberry Pi 3
  • OS: Raspbian GNU/Linux 10 (buster)
  • NetworkManager: 1.14.6
  • ModemManager: 1.10.0
  • Modem: Simcom SIM5320A connected via UART to the port ttyAMA0

Problem

I don't think I fully understand what is causing the modem to disconnect, I've been told it might go into a binary state where it stops responding and that might conflict with Network Manager trying to check the signal via the now missing AT port. I have a feeling this might just be a configuration issue due to inexperience.

I tried to bring the connection up using nmcli c up, but it fails and the modem is put no some sort of hold state. (Not really off) From what I understand reading the logs, the connection seems to be failing due to 2 reasons

1) ModemManager fails after a

Couldn't refresh signal quality: 'No AT port available to run command'

2) NetworkManager shows a warning and then fails

[1572423930.3650] device (ttyAMA0): interface ttyAMA0 not up for IP configuration

...

[1572423950.1289] ppp-manager: pppd timed out or didn't initialize our dbus module

You will find more details ahead including the full NetworkManager and ModemManager logs

Setup

First I had to modify my Rpi3 to be able to use the serial port, so I had to remove console=serial0,115200 from /boot/cmdline.txt, and add the following to /boot/config.txt:

#dtoverlay=vc4-fkms-v3d #This was enabled by default
dtparam=i2c_arm=on
dtparam=i2c1=on
dtoverlay=pi3-miniuart-bt
enable_uart=1

In order to get the modem detected by ModemManager I had to specify the following udev rule:

ACTION=="add|change|move", KERNEL=="ttyAMA0", ENV{ID_MM_TTY_FLOW_CONTROL}="none", ENV{ID_MM_TTY_BAUDRATE}="115200", ENV{ID_MM_CANDIDATE}="1", ENV{ID_MM_PLATFORM_DRIVER_PROBE}="1"

So the device then looks like this:

$ udevadm info /dev/ttyAMA0

P: /devices/platform/soc/3f201000.serial/tty/ttyAMA0
N: ttyAMA0
L: 0
S: serial0
E: DEVPATH=/devices/platform/soc/3f201000.serial/tty/ttyAMA0
E: DEVNAME=/dev/ttyAMA0
E: MAJOR=204
E: MINOR=64
E: SUBSYSTEM=tty
E: USEC_INITIALIZED=4926482
E: ID_MM_CANDIDATE=1
E: ID_MM_TTY_FLOW_CONTROL=none
E: ID_MM_TTY_BAUDRATE=115200
E: ID_MM_PLATFORM_DRIVER_PROBE=1
E: DEVLINKS=/dev/serial0
E: TAGS=:systemd:

I have been able to send AT commands to my modem using minicom with no flow control and 115200 8N1 for /dev/ttyAMA0

Once I turn the modem on with:

echo 22 > /sys/class/gpio/unexport 2>/dev/null
echo 22 > /sys/class/gpio/export
echo out > /sys/class/gpio/gpio22/direction
echo 1 > /sys/class/gpio/gpio22/value
sleep 6

I am able to trigger a modem scan (sudo mmcli -S) and it will be detected as:

/org/freedesktop/ModemManager1/Modem/0 [SIMCOM INCORPORATED] SIMCOM_SIM5320A

$ mmcli -m 0

  --------------------------
  General  |      dbus path: /org/freedesktop/ModemManager1/Modem/0
           |      device id: 23b798cdd09c78be14e231127c48d70f5307a48e
  --------------------------
  Hardware |   manufacturer: SIMCOM INCORPORATED
           |          model: SIMCOM_SIM5320A
           |       revision: 1575B13SIM5320A
           |      supported: gsm-umts
           |        current: gsm-umts
           |   equipment id: 012813008537617
  --------------------------
  System   |         device: /sys/devices/platform/soc
           |        drivers: uart-pl011
           |         plugin: Generic
           |   primary port: ttyAMA0
           |          ports: ttyAMA0 (at)
  --------------------------
  Numbers  |            own: +573176760667
  --------------------------
  Status   | unlock retries: sim-pin (3), sim-pin2 (3), sim-puk (10), sim-puk2 (10)
           |          state: registered
           |    power state: on
           | signal quality: 80% (recent)
  --------------------------
  Modes    |      supported: allowed: 2g, 3g; preferred: none
           |        current: allowed: 2g, 3g; preferred: none
  --------------------------
  IP       |      supported: ipv4, ipv6
  --------------------------
  3GPP     |           imei: 012813008537617
           |    operator id: 732123
           |  operator name: movistar
           |   registration: home
  --------------------------
  SIM      |      dbus path: /org/freedesktop/ModemManager1/SIM/0

I created a connection with nmcli Specifying the following:

connection.id:                          Movistar
connection.uuid:                        acab2207-347a-424c-b366-b2c4ef4e4c75
connection.stable-id:                   --
connection.type:                        gsm
connection.interface-name:              ttyAMA0
connection.autoconnect:                 no
connection.autoconnect-priority:        0
connection.autoconnect-retries:         -1 (default)
connection.multi-connect:               0 (default)
connection.auth-retries:                -1
connection.timestamp:                   0
connection.read-only:                   no
connection.permissions:                 --
connection.zone:                        --
connection.master:                      --
connection.slave-type:                  --
connection.autoconnect-slaves:          -1 (default)
connection.secondaries:                 --
connection.gateway-ping-timeout:        0
connection.metered:                     unknown
connection.lldp:                        default
connection.mdns:                        -1 (default)
connection.llmnr:                       -1 (default)
ipv4.method:                            auto
ipv4.dns:                               --
ipv4.dns-search:                        --
ipv4.dns-options:                       ""
ipv4.dns-priority:                      0
ipv4.addresses:                         --
ipv4.gateway:                           --
ipv4.routes:                            --
ipv4.route-metric:                      -1
ipv4.route-table:                       0 (unspec)
ipv4.ignore-auto-routes:                no
ipv4.ignore-auto-dns:                   no
ipv4.dhcp-client-id:                    --
ipv4.dhcp-timeout:                      0 (default)
ipv4.dhcp-send-hostname:                yes
ipv4.dhcp-hostname:                     --
ipv4.dhcp-fqdn:                         --
ipv4.never-default:                     no
ipv4.may-fail:                          yes
ipv4.dad-timeout:                       -1 (default)
ipv6.method:                            auto
ipv6.dns:                               --
ipv6.dns-search:                        --
ipv6.dns-options:                       ""
ipv6.dns-priority:                      0
ipv6.addresses:                         --
ipv6.gateway:                           --
ipv6.routes:                            --
ipv6.route-metric:                      -1
ipv6.route-table:                       0 (unspec)
ipv6.ignore-auto-routes:                no
ipv6.ignore-auto-dns:                   no
ipv6.never-default:                     no
ipv6.may-fail:                          yes
ipv6.ip6-privacy:                       -1 (unknown)
ipv6.addr-gen-mode:                     stable-privacy
ipv6.dhcp-duid:                         --
ipv6.dhcp-send-hostname:                yes
ipv6.dhcp-hostname:                     --
ipv6.token:                             --
serial.baud:                            115200
serial.bits:                            8
serial.parity:                          none
serial.stopbits:                        1
serial.send-delay:                      0
ppp.noauth:                             yes
ppp.refuse-eap:                         no
ppp.refuse-pap:                         no
ppp.refuse-chap:                        no
ppp.refuse-mschap:                      no
ppp.refuse-mschapv2:                    no
ppp.nobsdcomp:                          no
ppp.nodeflate:                          no
ppp.no-vj-comp:                         no
ppp.require-mppe:                       no
ppp.require-mppe-128:                   no
ppp.mppe-stateful:                      no
ppp.crtscts:                            no
ppp.baud:                               115200
ppp.mru:                                0
ppp.mtu:                                auto
ppp.lcp-echo-failure:                   0
ppp.lcp-echo-interval:                  0
gsm.number:                             *99#
gsm.username:                           --
gsm.password:                           <hidden>
gsm.password-flags:                     0 (none)
gsm.apn:                                internet.movistar.com.co
gsm.network-id:                         --
gsm.pin:                                <hidden>
gsm.pin-flags:                          0 (none)
gsm.home-only:                          no
gsm.device-id:                          --
gsm.sim-id:                             --
gsm.sim-operator-id:                    --
gsm.mtu:                                auto
proxy.method:                           none
proxy.browser-only:                     no
proxy.pac-url:                          --
proxy.pac-script:                       --

Full logs

NetworkManager

Oct 30 08:25:30 modemRPI NetworkManager[337]: <info>  [1572423930.2650] agent-manager: req[0x7fcb70, :1.29674/nmcli-connect/0]: agent registered
Oct 30 08:25:30 modemRPI NetworkManager[337]: <info>  [1572423930.2739] device (ttyAMA0): Activation: starting connection 'Movistar' (acab2207-347a-424c-b366-b2c4ef4e4c75)
Oct 30 08:25:30 modemRPI NetworkManager[337]: <info>  [1572423930.2742] audit: op="connection-activate" uuid="acab2207-347a-424c-b366-b2c4ef4e4c75" name="Movistar" pid=25443 uid=0 result="success"
Oct 30 08:25:30 modemRPI NetworkManager[337]: <info>  [1572423930.2747] device (ttyAMA0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Oct 30 08:25:30 modemRPI NetworkManager[337]: <info>  [1572423930.2952] modem["ttyAMA0"]: modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Oct 30 08:25:30 modemRPI NetworkManager[337]: <info>  [1572423930.3556] modem["ttyAMA0"]: modem state changed, 'connecting' --> 'connected' (reason: user-requested)
Oct 30 08:25:30 modemRPI NetworkManager[337]: <info>  [1572423930.3622] device (ttyAMA0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Oct 30 08:25:30 modemRPI NetworkManager[337]: <info>  [1572423930.3640] device (ttyAMA0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Oct 30 08:25:30 modemRPI NetworkManager[337]: <warn>  [1572423930.3650] device (ttyAMA0): interface ttyAMA0 not up for IP configuration
Oct 30 08:25:30 modemRPI NetworkManager[337]: <info>  [1572423930.3652] modem["ttyAMA0"]: using modem-specified IP timeout: 20 seconds
Oct 30 08:25:30 modemRPI NetworkManager[337]: <info>  [1572423930.3657] ppp-manager: starting PPP connection
Oct 30 08:25:30 modemRPI NetworkManager[337]: <info>  [1572423930.3712] ppp-manager: pppd started with pid 25450
Oct 30 08:25:30 modemRPI NetworkManager[337]: <info>  [1572423930.3716] modem["ttyAMA0"]: IPv6 configuration disabled
Oct 30 08:25:30 modemRPI pppd[25450]: Plugin /usr/lib/pppd/2.4.7/nm-pppd-plugin.so loaded.
Oct 30 08:25:30 modemRPI NetworkManager[337]: Plugin /usr/lib/pppd/2.4.7/nm-pppd-plugin.so loaded.
Oct 30 08:25:30 modemRPI pppd[25450]: nm-ppp-plugin: (plugin_init): initializing
Oct 30 08:25:30 modemRPI pppd[25450]: pppd 2.4.7 started by root, uid 0
Oct 30 08:25:30 modemRPI pppd[25450]: nm-ppp-plugin: (nm_phasechange): status 3 / phase 'serial connection'
Oct 30 08:25:50 modemRPI NetworkManager[337]: <warn>  [1572423950.1289] ppp-manager: pppd timed out or didn't initialize our dbus module
Oct 30 08:25:50 modemRPI pppd[25450]: nm-ppp-plugin: (nm_phasechange): status 1 / phase 'dead'
Oct 30 08:25:50 modemRPI NetworkManager[337]: <info>  [1572423950.1333] device (ttyAMA0): state change: ip-config -> failed (reason 'ip-config-unavailable', sys-iface-state: 'managed')
Oct 30 08:25:50 modemRPI NetworkManager[337]: <warn>  [1572423950.1410] device (ttyAMA0): Activation: failed for connection 'Movistar'
Oct 30 08:25:50 modemRPI NetworkManager[337]: <info>  [1572423950.1480] device (ttyAMA0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
Oct 30 08:25:50 modemRPI NetworkManager[337]: <info>  [1572423950.1739] modem["ttyAMA0"]: modem state changed, 'connected' --> 'disconnecting' (reason: user-requested)
Oct 30 08:25:51 modemRPI pppd[25450]: nm-ppp-plugin: (nm_exit_notify): cleaning up
Oct 30 08:25:51 modemRPI pppd[25450]: Exit.
Oct 30 08:26:17 modemRPI NetworkManager[337]: <info>  [1572423977.1334] modem["ttyAMA0"]: modem state changed, 'disconnecting' --> 'registered' (reason: user-requested)
Oct 30 08:26:31 modemRPI NetworkManager[337]: <info>  [1572423991.1315] device (ttyAMA0): state change: disconnected -> unmanaged (reason 'removed', sys-iface-state: 'removed')
Oct 30 08:29:10 modemRPI NetworkManager[337]: <info>  [1572424150.6750] device (wlan0): set-hw-addr: set MAC address to 5E:7D:B3:EC:65:8D (scanning)
Oct 30 08:29:10 modemRPI NetworkManager[337]: <info>  [1572424150.7625] device (wlan0): supplicant interface state: inactive -> disabled
Oct 30 08:29:10 modemRPI NetworkManager[337]: <info>  [1572424150.7633] device (wlan0): supplicant interface state: disabled -> inactive

ModemManager --debug

ModemManager[22535]: <info>  [1572423930.286880] Simple connect started...
ModemManager[22535]: <debug> [1572423930.287041]    PIN: unspecified
ModemManager[22535]: <debug> [1572423930.287087]    Operator ID: unspecified
ModemManager[22535]: <debug> [1572423930.287124]    Allowed roaming: yes
ModemManager[22535]: <debug> [1572423930.287161]    APN: internet.movistar.com.co
ModemManager[22535]: <debug> [1572423930.287249]    IP family: ipv4
ModemManager[22535]: <debug> [1572423930.287466]    Allowed authentication: none, pap, chap, mschap, mschapv2, eap
ModemManager[22535]: <debug> [1572423930.287521]    User: unspecified
ModemManager[22535]: <debug> [1572423930.287599]    Password: unspecified
ModemManager[22535]: <info>  [1572423930.287651] Simple connect state (4/8): Wait to get fully enabled
ModemManager[22535]: <info>  [1572423930.288158] Simple connect state (5/8): Register
ModemManager[22535]: <debug> [1572423930.288412] Already registered in network '732123', automatic registration not launched...
ModemManager[22535]: <info>  [1572423930.288556] Simple connect state (6/8): Bearer
ModemManager[22535]: <debug> [1572423930.288614] Creating new bearer...
ModemManager[22535]: <debug> [1572423930.288685] Creating Broadband bearer in broadband modem
ModemManager[22535]: <debug> [1572423930.290250] (ttyAMA0) device open count is 2 (open)
ModemManager[22535]: <info>  [1572423930.291072] Simple connect state (7/8): Connect
ModemManager[22535]: <debug> [1572423930.291395] Connecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
ModemManager[22535]: <info>  [1572423930.291502] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
ModemManager[22535]: <debug> [1572423930.293413] Launching 3GPP connection attempt with APN 'internet.movistar.com.co'
ModemManager[22535]: <debug> [1572423930.293566] Looking for best CID...
ModemManager[22535]: <debug> [1572423930.293642] (ttyAMA0) device open count is 3 (open)
ModemManager[22535]: <debug> [1572423930.293799] (ttyAMA0) device open count is 2 (close)
ModemManager[22535]: <debug> [1572423930.295300] (ttyAMA0): --> 'AT+CGDCONT?<CR>'
ModemManager[22535]: <debug> [1572423930.312533] (ttyAMA0): <-- '<CR><LF>+CGDCO'
ModemManager[22535]: <debug> [1572423930.313240] (ttyAMA0): <-- 'NT: 1,"I'
ModemManager[22535]: <debug> [1572423930.313920] (ttyAMA0): <-- 'P","inte'
ModemManager[22535]: <debug> [1572423930.314720] (ttyAMA0): <-- 'rnet.mov'
ModemManager[22535]: <debug> [1572423930.315314] (ttyAMA0): <-- 'istar.co'
ModemManager[22535]: <debug> [1572423930.315994] (ttyAMA0): <-- 'm.co","0'
ModemManager[22535]: <debug> [1572423930.316690] (ttyAMA0): <-- '.0.0.0",'
ModemManager[22535]: <debug> [1572423930.317506] (ttyAMA0): <-- '0,0<CR><LF>+CG'
ModemManager[22535]: <debug> [1572423930.318080] (ttyAMA0): <-- 'DCONT: 2'
ModemManager[22535]: <debug> [1572423930.318854] (ttyAMA0): <-- ',"IP","w'
ModemManager[22535]: <debug> [1572423930.319464] (ttyAMA0): <-- 'eb.colom'
ModemManager[22535]: <debug> [1572423930.320252] (ttyAMA0): <-- 'biamovil'
ModemManager[22535]: <debug> [1572423930.320849] (ttyAMA0): <-- '.com.co"'
ModemManager[22535]: <debug> [1572423930.321549] (ttyAMA0): <-- ',"0.0.0.'
ModemManager[22535]: <debug> [1572423930.322253] (ttyAMA0): <-- '0",0,0<CR><LF>'
ModemManager[22535]: <debug> [1572423930.322937] (ttyAMA0): <-- '+CGDCONT'
ModemManager[22535]: <debug> [1572423930.323633] (ttyAMA0): <-- ': 3,"IP"'
ModemManager[22535]: <debug> [1572423930.324337] (ttyAMA0): <-- ',"intern'
ModemManager[22535]: <debug> [1572423930.325538] (ttyAMA0): <-- 'et.movis'
ModemManager[22535]: <debug> [1572423930.325915] (ttyAMA0): <-- 'tar.com.'
ModemManager[22535]: <debug> [1572423930.326426] (ttyAMA0): <-- 'co","0.0'
ModemManager[22535]: <debug> [1572423930.327151] (ttyAMA0): <-- '.0.0",0,'
ModemManager[22535]: <debug> [1572423930.327806] (ttyAMA0): <-- '0<CR><LF><CR><LF>OK<CR>'
ModemManager[22535]: <debug> [1572423930.328244] (ttyAMA0): <-- '<LF>'
ModemManager[22535]: <debug> [1572423930.328767] Found '3' PDP contexts
ModemManager[22535]: <debug> [1572423930.328868]   PDP context [cid=1] [type='ipv4'] [apn='internet.movistar.com.co']
ModemManager[22535]: <debug> [1572423930.328986]   PDP context [cid=2] [type='ipv4'] [apn='web.colombiamovil.com.co']
ModemManager[22535]: <debug> [1572423930.329049]   PDP context [cid=3] [type='ipv4'] [apn='internet.movistar.com.co']
ModemManager[22535]: <debug> [1572423930.329109] Found PDP context with CID 1 and PDP type ipv4 for APN 'internet.movistar.com.co'
ModemManager[22535]: <debug> [1572423930.329244] (ttyAMA0) device open count is 3 (open)
ModemManager[22535]: <debug> [1572423930.329337] Connection through a plain serial AT port (ttyAMA0)
ModemManager[22535]: <debug> [1572423930.329423] (ttyAMA0) device open count is 4 (open)
ModemManager[22535]: <debug> [1572423930.329655] (ttyAMA0) device open count is 3 (close)
ModemManager[22535]: <debug> [1572423930.329848] (ttyAMA0): --> 'ATD*99***1#<CR>'
ModemManager[22535]: <debug> [1572423930.348373] (ttyAMA0): <-- '<CR><LF>CONNEC'
ModemManager[22535]: <debug> [1572423930.349415] (ttyAMA0): <-- 'T 115200'
ModemManager[22535]: <debug> [1572423930.350245] (ttyAMA0): <-- '<CR><LF>'
ModemManager[22535]: <debug> [1572423930.350770] (ttyAMA0): port now connected
ModemManager[22535]: <debug> [1572423930.351098] Connected bearer '/org/freedesktop/ModemManager1/Bearer/0'
ModemManager[22535]: <info>  [1572423930.352101] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
ModemManager[22535]: <info>  [1572423930.353475] Simple connect state (8/8): All done
ModemManager[22535]: <debug> [1572423930.353994] (ttyAMA0) device open count is 2 (close)
ModemManager[22535]: <debug> [1572423932.129424] loading signal quality...
ModemManager[22535]: <debug> [1572423932.129804] Couldn't refresh signal quality: 'No AT port available to run command'
ModemManager[22535]: <debug> [1572423932.129900] Periodic signal quality checks scheduled in 30s
ModemManager[22535]: <debug> [1572423950.166703] Disconnecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
ModemManager[22535]: <info>  [1572423950.168686] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> disconnecting)
ModemManager[22535]: <debug> [1572423950.169906] Reopening data port (ttyAMA0)...
ModemManager[22535]: <debug> [1572423950.170068] (ttyAMA0) reopening port (2)
ModemManager[22535]: <debug> [1572423950.170184] (ttyAMA0) device open count is 1 (close)
ModemManager[22535]: <debug> [1572423950.170250] (ttyAMA0) device open count is 0 (close)
ModemManager[22535]: <debug> [1572423950.170326] (ttyAMA0) closing serial port...
ModemManager[22535]: <debug> [1572423950.170398] (ttyAMA0): port now disconnected
ModemManager[22535]: <debug> [1572423950.170528] (ttyAMA0) serial port closed
ModemManager[22535]: <debug> [1572423951.171077] (ttyAMA0) opening serial port...
ModemManager[22535]: <debug> [1572423951.171653] (ttyAMA0): setting up baudrate: 115200
ModemManager[22535]: <debug> [1572423951.171768] (ttyAMA0): flow control explicitly requested for device is: none
ModemManager[22535]: <debug> [1572423951.171953] (ttyAMA0) device open count is 1 (open)
ModemManager[22535]: <debug> [1572423951.172029] (ttyAMA0) device open count is 2 (open)
ModemManager[22535]: <debug> [1572423951.172156] Flashing data port (ttyAMA0)...
ModemManager[22535]: <debug> [1572423951.172280] (ttyAMA0): port attributes not fully set
ModemManager[22535]: <debug> [1572423952.173624] (ttyAMA0) device open count is 1 (close)
ModemManager[22535]: <debug> [1572423952.173799] (ttyAMA0): running init sequence...
ModemManager[22535]: <debug> [1572423952.173992] Sending PDP context deactivation in primary/data port...
ModemManager[22535]: <debug> [1572423952.174130] (ttyAMA0) device open count is 2 (open)
ModemManager[22535]: <debug> [1572423952.174333] (ttyAMA0): --> 'ATE0<CR>'
ModemManager[22535]: <debug> [1572423955.130028] (ttyAMA0): --> 'ATV1<CR>'
ModemManager[22535]: <warn>  [1572423958.129183] (tty/ttyAMA0) at port timed out 2 consecutive times
ModemManager[22535]: <debug> [1572423958.129517] (ttyAMA0): --> 'AT+CMEE=1<CR>'
ModemManager[22535]: <debug> [1572423960.129040] (ttyAMA0) device open count is 3 (open)
ModemManager[22535]: <warn>  [1572423961.128839] (tty/ttyAMA0) at port timed out 3 consecutive times
ModemManager[22535]: <debug> [1572423961.129092] (ttyAMA0): --> 'ATX4<CR>'
ModemManager[22535]: <debug> [1572423962.128279] Signal quality value not updated in 60s, marking as not being recent
ModemManager[22535]: <debug> [1572423962.128626] loading signal quality...
ModemManager[22535]: <debug> [1572423962.128753] (ttyAMA0) device open count is 4 (open)
ModemManager[22535]: <warn>  [1572423964.128134] (tty/ttyAMA0) at port timed out 4 consecutive times
ModemManager[22535]: <debug> [1572423964.128357] (ttyAMA0): --> 'AT&C1<CR>'
ModemManager[22535]: <debug> [1572423965.129208] (ttyAMA0) device open count is 5 (open)
ModemManager[22535]: <warn>  [1572423967.129153] (tty/ttyAMA0) at port timed out 5 consecutive times
ModemManager[22535]: <debug> [1572423967.129499] (ttyAMA0): --> 'AT+CGACT=0,1<CR>'
ModemManager[22535]: <debug> [1572423970.128816] (ttyAMA0) device open count is 6 (open)
ModemManager[22535]: <debug> [1572423975.129416] (ttyAMA0) device open count is 7 (open)
ModemManager[22535]: <debug> [1572423977.128688] PDP context deactivation failed (not fatal): Serial command timed out
ModemManager[22535]: <debug> [1572423977.128859] Disconnected bearer '/org/freedesktop/ModemManager1/Bearer/0'
ModemManager[22535]: <info>  [1572423977.128962] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disconnecting -> registered)
ModemManager[22535]: <debug> [1572423977.129904] (ttyAMA0) device open count is 6 (close)
ModemManager[22535]: <warn>  [1572423977.130014] (tty/ttyAMA0) at port timed out 6 consecutive times
ModemManager[22535]: <debug> [1572423977.130365] (ttyAMA0): --> 'AT+CGACT?<CR>'
ModemManager[22535]: <warn>  [1572423980.130340] checking if connected failed: Couldn't check current list of active PDP contexts: Serial command timed out
ModemManager[22535]: <debug> [1572423980.130653] (ttyAMA0) device open count is 5 (close)
ModemManager[22535]: <warn>  [1572423980.130817] (tty/ttyAMA0) at port timed out 7 consecutive times
ModemManager[22535]: <debug> [1572423980.130955] (ttyAMA0): --> 'AT+CIND?<CR>'
ModemManager[22535]: <debug> [1572423985.128479] (ttyAMA0) device open count is 6 (open)
ModemManager[22535]: <debug> [1572423985.128812] (ttyAMA0) device open count is 5 (close)
ModemManager[22535]: <warn>  [1572423985.128974] (tty/ttyAMA0) at port timed out 8 consecutive times
ModemManager[22535]: <debug> [1572423985.129111] (ttyAMA0): --> 'AT+CGACT?<CR>'
ModemManager[22535]: <warn>  [1572423988.129484] checking if connected failed: Couldn't check current list of active PDP contexts: Serial command timed out
ModemManager[22535]: <debug> [1572423988.129684] (ttyAMA0) device open count is 4 (close)
ModemManager[22535]: <warn>  [1572423988.129793] (tty/ttyAMA0) at port timed out 9 consecutive times
ModemManager[22535]: <debug> [1572423988.129891] (ttyAMA0): --> 'AT+CGACT?<CR>'
ModemManager[22535]: <warn>  [1572423991.128715] checking if connected failed: Couldn't check current list of active PDP contexts: Serial command timed out
ModemManager[22535]: <debug> [1572423991.128910] (ttyAMA0) device open count is 3 (close)
ModemManager[22535]: <error> [1572423991.129022] (tty/ttyAMA0) at port timed out 10 consecutive times, marking modem '/org/freedesktop/ModemManager1/Modem/0' as invalid
ModemManager[22535]: <debug> [1572423991.129160] (ttyAMA0): --> 'AT+CGACT?<CR>'
ModemManager[22535]: <debug> [1572423991.130259] Removing from DBus bearer at '/org/freedesktop/ModemManager1/Bearer/0'
ModemManager[22535]: <debug> [1572423991.130449] [device /sys/devices/platform/soc] unexported modem from path '/org/freedesktop/ModemManager1/Modem/0'
ModemManager[22535]: <debug> [1572423991.130539] Periodic signal checks disabled
ModemManager[22535]: <warn>  [1572423991.140824] checking if connected failed: Couldn't check current list of active PDP contexts: AT command was cancelled
ModemManager[22535]: <debug> [1572423991.141068] (ttyAMA0) device open count is 2 (close)
ModemManager[22535]: <debug> [1572423991.141166] (ttyAMA0): --> 'AT+CSQ<CR>'
ModemManager[22535]: <debug> [1572423991.148071] Couldn't refresh signal quality: 'AT sequence was cancelled'
ModemManager[22535]: <debug> [1572423991.148162] Periodic signal checks not rescheduled: disabled
ModemManager[22535]: <debug> [1572423991.148231] (ttyAMA0) device open count is 1 (close)
ModemManager[22535]: <debug> [1572423991.148285] (ttyAMA0) device open count is 0 (close)
ModemManager[22535]: <debug> [1572423991.148356] (ttyAMA0) closing serial port...
ModemManager[22535]: <debug> [1572423991.148505] (ttyAMA0) serial port closed
ModemManager[22535]: <debug> [1572423991.148589] Modem (Generic) '/sys/devices/platform/soc' completely disposed
ModemManager[22535]: <debug> [1572423991.148782] (ttyAMA0) forced to close port

After this connection attempt, the modem is left in a weird state where I have to turn it off and on again for it to actually react

Hardware check

In order to discard faulty hardware or incorrect provider settings, I managed to test by connecting from this device using ppp, my successful attempt involved running the command:

/usr/sbin/pppd defaultroute usepeerdns debug connect "/usr/sbin/chat -V -f /home/pi/conScript" noauth /dev/ttyAMA0 nodetach 115200

and the script was:

ABORT           BUSY
ABORT           VOICE
ABORT           "NO CARRIER"
ABORT           "NO DIALTONE"
ABORT           "NO DIAL TONE"
ABORT           "NO ANSWER"
ABORT           "DELAYED"
ABORT           "ERROR"
ABORT           "+CGATT: 0"

""              AT
TIMEOUT         12
OK              ATH
OK              ATE1

OK              AT+CGDCONT=1,"IP","internet.movistar.com.co","",0,0
OK              ATD*99#
TIMEOUT         22
CONNECT         ""

Next Steps

Any suggestions are more than welcome, I can't really seem to find a way to configure this and I've done my research. Search engines aren't being really helpful so far. The PDP context doesn't seem to be the problem. I believe ModemManager is unable to check the signal because the AT port is already used for the connection, or maybe the device is freezing?

Dien
  • 9
  • 5
  • you are using the "virtual" uart port instead of the full uart port, you might want to read about the details of those two, for our usecase the mini-uart did not work stable enough and we opted for an external device. – Dennis Nolte Feb 18 '20 at 10:21

2 Answers2

0

I've been running into a similar issue. How to maintain and manage a cellular connection to a serial modem? I tired using modemmanager but but didn't get far, it looks like you got way further than I did. The issue that I also ran into is that once a PPP connection is made, you cannot use the same serial port for AT commands to the modem (which I think is the issue you ran into as well).

What I ended up doing was writing a program in C that would run as a service and that would call the pon and poff commands to open the ppp connection manually. In between connections it sends AT commands to get information about the modem status, connectivity, and to also set configurations if needed. It works to maintain an internet connection but it gets buggy when the modem moves in an out of cellular range.

I used the following provider script:

#serial port
/dev/serial0

#baudrate
115200

#chat script
connect "/usr/sbin/chat -v -f /etc/ppp/peers/vzw-chat"

#no username or password required
noauth

#create a default route
defaultroute

#override existing default route with ppp0
replacedefaultroute

#obtain DNS server addresses from peer
usepeerdns

#do not use modem control lines
local

#verbose mode
debug

#output stdout to terminal until connection is established
updetach

#lock serial device so no other process can use it
lock

#no hardware flow control
nocrtscts

#attempt to reconnect if failure or disconnect
persist

#attempt to connect 3 times before quit
maxfail 3

My next step is to use the /etc/ppp/ip-pre-up, /etc/ppp/ip-up, /etc/ppp/ip-down scripts to replace my service and to handle loss of connection.

I hope this helps. I'd definitely be interested if you're able to get the modemmanager to work with a serial modem properly.

Dave M
  • 4,494
  • 21
  • 30
  • 30
0

I ran into the same issue using a SimCom SIM5300-E.

In my case ModemManager initialized the device as "Generic" but the PPPd died by timeout.

I still don't know why, but seems that the only way to Start the PPP daemon was to set the baud frequency in /etc/ppp/option to 56700

This is my option file:

auth noipdefault 56700 nocrtscts local nodeflate noccp usepeerdns +chap

Dave M
  • 4,494
  • 21
  • 30
  • 30