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?
