ModemManager floods log and cannot reconnect after sudden disconnect

Bug #1856332 reported by Jalink
8
This bug affects 1 person
Affects Status Importance Assigned to Milestone
Raspbian
New
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)
description: updated
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.