ModemManager floods log and cannot reconnect after sudden disconnect

Bug #1856332 reported by Jalink on 2019-12-13
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Raspbian
Undecided
Unassigned

Bug Description

To configure my RaspberryPi 4 to use a UBlox SARA-U201 4G USB Modem I used nmcli and mmcli. It connects after a minute after each boot now:
:~ $ mmcli -m 0
  --------------------------
  General | dbus path: /org/freedesktop/ModemManager1/Modem/0
           | device id: xxxx
  --------------------------
  Hardware | manufacturer: u-blox
           | model: SARA-U201
           | revision: 23.60
           | supported: gsm-umts
           | current: gsm-umts
           | equipment id: 358887095191472
  --------------------------
  System | device: /sys/devices/platform/scb/fd500000.pcie/pci0000:00/0000:00:00.0/0000:01:00.0/usb1/1-1/1-1.4
           | drivers: cdc_acm
           | plugin: u-blox
           | primary port: ttyACM0
           | ports: ttyACM3 (unknown), ttyACM4 (unknown), ttyACM5 (unknown),
           | ttyACM6 (unknown), ttyACM0 (at), ttyACM1 (at), ttyACM2 (at)
  --------------------------
  Status | unlock retries: sim-pin (3), sim-pin2 (3), sim-puk (10), sim-puk2 (10)
           | state: connected
           | power state: on
           | access tech: umts
           | signal quality: 20% (recent)
  --------------------------
  Modes | supported: allowed: 2g; preferred: none
           | allowed: 2g, 3g; preferred: none
           | allowed: 2g, 3g; preferred: 2g
           | allowed: 2g, 3g; preferred: 3g
           | allowed: 3g; preferred: none
           | current: allowed: 2g, 3g; preferred: 3g
  --------------------------
  Bands | supported: egsm, dcs, pcs, g850, utran-1, utran-3, utran-4, utran-6,
           | utran-5, utran-8, utran-2, utran-7, utran-11
           | current: egsm, pcs, g850, utran-1, utran-6, utran-5, utran-8, utran-2
  --------------------------
  IP | supported: ipv4, ipv6, ipv4v6
  --------------------------
  3GPP | imei: xxxx
           | operator id: xxxx
           | operator name: vodafone NL
           | registration: roaming
  --------------------------
  SIM | dbus path: /org/freedesktop/ModemManager1/SIM/0
  --------------------------
  Bearer | dbus path: /org/freedesktop/ModemManager1/Bearer/0

But randomly it disconnects and starts flooding the log, not willing to connect again. The reason it cannot reconnect again is:
NetworkManager[387]: <warn> [1576251985.8713] modem-broadband[ttyACM0]: failed to connect modem: Could not open serial device ttyACM0: it has been forced close
Of which I think the issue is addressed here: https://lists.freedesktop.org/archives/modemmanager-devel/2018-August/006593.html

Below is the output of a part of journalctl --boot -1

Dec 13 16:46:23 447452017112 run.sh[362]: wal
Dec 13 16:46:24 447452017112 run.sh[362]: wal
Dec 13 16:46:24 447452017112 pppd[2394]: LCP terminated by peer
Dec 13 16:46:24 447452017112 pppd[2394]: nm-ppp-plugin: (nm_phasechange): status 8 / phase 'network'
Dec 13 16:46:24 447452017112 NetworkManager[387]: LCP terminated by peer
Dec 13 16:46:24 447452017112 NetworkManager[387]: Connect time 6.1 minutes.
Dec 13 16:46:24 447452017112 NetworkManager[387]: Sent 7957670 bytes, received 2555477 bytes.
Dec 13 16:46:24 447452017112 pppd[2394]: Connect time 6.1 minutes.
Dec 13 16:46:24 447452017112 NetworkManager[387]: <info> [1576251984.6522] device (ppp0): state change: disconnected -> unmanaged (reason 'connection-assumed', sys-iface-state: 'external')
Dec 13 16:46:24 447452017112 pppd[2394]: Sent 7957670 bytes, received 2555477 bytes.
Dec 13 16:46:24 447452017112 pppd[2394]: nm-ppp-plugin: (nm_phasechange): status 5 / phase 'establish'
Dec 13 16:46:24 447452017112 run.sh[362]: wal
Dec 13 16:46:25 447452017112 run.sh[362]: wal
Dec 13 16:46:25 447452017112 pppd[2394]: Modem hangup
Dec 13 16:46:25 447452017112 NetworkManager[387]: Modem hangup
Dec 13 16:46:25 447452017112 NetworkManager[387]: Connection terminated.
Dec 13 16:46:25 447452017112 pppd[2394]: nm-ppp-plugin: (nm_phasechange): status 11 / phase 'disconnect'
Dec 13 16:46:25 447452017112 pppd[2394]: Connection terminated.
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.7740] device (ttyACM0): state change: activated -> failed (reason 'ip-config-unavailable', sys-iface-state: 'managed')
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> network request to deactivate context (type IP, address 172.33.70.239, cid 5)
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Bearer /org/freedesktop/ModemManager1/Bearer/0: explicitly disconnected
Dec 13 16:46:25 447452017112 ModemManager[395]: <warn> (ttyACM0): could not re-acquire serial port lock: (5) Input/output error
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> registered)
Dec 13 16:46:25 447452017112 NetworkManager[387]: <warn> [1576251985.7977] device (ttyACM0): Activation: failed for connection 'mymodem'
Dec 13 16:46:25 447452017112 dbus-daemon[369]: [system] Activating via systemd: service name='org.freedesktop.nm_dispatcher' unit='dbus-org.freedesktop.nm-dispatcher.service' requested by ':1.7' (uid=0
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8072] modem["ttyACM0"]: modem state changed, 'connected' --> 'registered' (reason: user-requested)
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8080] device (ttyACM0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
Dec 13 16:46:25 447452017112 systemd[1]: Starting Network Manager Script Dispatcher Service...
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8133] policy: auto-activating connection 'mymodem' (209621ae-13a5-49de-9009-23cb00fc52d7)
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8172] device (ttyACM0): Activation: starting connection 'mymodem' (209621ae-13a5-49de-9009-23cb00fc52d7)
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8178] device (ttyACM0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect started...
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (4/8): Wait to get fully enabled
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (5/8): Register
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (6/8): Bearer
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect started...
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (4/8): Wait to get fully enabled
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (5/8): Register
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (6/8): Bearer
Dec 13 16:46:25 447452017112 dbus-daemon[369]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Dec 13 16:46:25 447452017112 systemd[1]: Started Network Manager Script Dispatcher Service.
Dec 13 16:46:25 447452017112 nm-dispatcher[6134]: req:1 'down' [ppp0]: new request (1 scripts)
Dec 13 16:46:25 447452017112 nm-dispatcher[6134]: req:1 'down' [ppp0]: start running ordered scripts...
Dec 13 16:46:25 447452017112 nm-dispatcher[6134]: req:2 'connectivity-change': new request (1 scripts)
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect started...
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (4/8): Wait to get fully enabled
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (5/8): Register
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (6/8): Bearer
Dec 13 16:46:25 447452017112 NetworkManager[387]: <warn> [1576251985.8409] modem-broadband[ttyACM0]: failed to connect modem: Could not open serial device ttyACM0: it has been forced close
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8409] device (ttyACM0): state change: prepare -> failed (reason 'unknown', sys-iface-state: 'managed')
Dec 13 16:46:25 447452017112 NetworkManager[387]: <warn> [1576251985.8430] device (ttyACM0): Activation: failed for connection 'mymodem'
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8436] device (ttyACM0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8480] policy: auto-activating connection 'mymodem' (209621ae-13a5-49de-9009-23cb00fc52d7)
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8515] device (ttyACM0): Activation: starting connection 'mymodem' (209621ae-13a5-49de-9009-23cb00fc52d7)
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8520] device (ttyACM0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect started...
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (4/8): Wait to get fully enabled
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (5/8): Register
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (6/8): Bearer
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect started...
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (4/8): Wait to get fully enabled
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (5/8): Register
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (6/8): Bearer
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect started...
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (4/8): Wait to get fully enabled
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (5/8): Register
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (6/8): Bearer
Dec 13 16:46:25 447452017112 NetworkManager[387]: <warn> [1576251985.8713] modem-broadband[ttyACM0]: failed to connect modem: Could not open serial device ttyACM0: it has been forced close
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8714] device (ttyACM0): state change: prepare -> failed (reason 'unknown', sys-iface-state: 'managed')
Dec 13 16:46:25 447452017112 NetworkManager[387]: <warn> [1576251985.8732] device (ttyACM0): Activation: failed for connection 'mymodem'
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8739] device (ttyACM0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8762] policy: auto-activating connection 'mymodem' (209621ae-13a5-49de-9009-23cb00fc52d7)
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8797] device (ttyACM0): Activation: starting connection 'mymodem' (209621ae-13a5-49de-9009-23cb00fc52d7)
Dec 13 16:46:25 447452017112 NetworkManager[387]: <info> [1576251985.8805] device (ttyACM0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect started...
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (4/8): Wait to get fully enabled
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (5/8): Register
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (6/8): Bearer
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect started...
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (4/8): Wait to get fully enabled
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (5/8): Register
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (6/8): Bearer
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect started...
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (4/8): Wait to get fully enabled
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (5/8): Register
Dec 13 16:46:25 447452017112 ModemManager[395]: <info> Simple connect state (6/8): Bearer
Dec 13 16:46:25 447452017112 NetworkManager[387]: <warn> [1576251985.8984] modem-broadband[ttyACM0]: failed to connect modem: Could not open serial device ttyACM0: it has been forced close

Jalink (fantasyzer) on 2019-12-16
description: updated
To post a comment you must log in.
This report contains Public information  Edit
Everyone can see this information.

Other bug subscribers