ModemManager can't open serial port after previously opening it successfully

Thu Jul 19 13:47:53 UTC 2018

I am running ModemManager 1.8.0 and NetworkManager 1.8.0 on an embedded device with the Linux OS built by buildroot.  I am using a u-blox TOBY-R200 cell modem connected over USB with virtual serial interfaces /dev/ttyACM0 through /dev/ttyACM5.

Sometimes while connected to the cellular network for a longer period of time (sometimes around 200 minutes, other times I have reached over 800 minutes), ModemManager will report a modem hangup that was not initiated by user action or loss of signal since this is a stationary device that is being tested.  Usually ModemManager will reconnect with NetworkManager prompting for the associated cell profile to be reconnected.  My issue is that sometimes no matter how many times I try or auto reconnects are tried, ModemManager cannot reestablish a data connection.  ModemManager just keeps reporting that it can't open /dev/ttyACM0 which is was using just fine before.  The interesting thing is that if I restart ModemManager, it is able to open the /dev/ttyACM0 port right away and make a data connection again, so it doesn't look to be an issue with the modem causing serial port issues.  This looks to be some sort of serial port handling issue in ModemManager, maybe just related to u-blox but I am not sure.  I looked at the state of the /dev/ttyACM0 device using lsof and it is not reporting that any other process has that device file open or locked. 

Here is the log output of ModemManager and NetworkManager when this occurs:

Jul 19 12:52:06 canect2 daemon.notice pppd[5047]: Modem hangup
Jul 19 12:52:06 canect2 daemon.info ModemManager[302]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (home -> searching)
Jul 19 12:52:06 canect2 daemon.info pppd[5047]: Connect time 841.7 minutes.
Jul 19 12:52:06 canect2 daemon.info pppd[5047]: Sent 3398 bytes, received 10548 bytes.
Jul 19 12:52:06 canect2 daemon.notice pppd[5047]: Connection terminated.
Jul 19 12:52:06 canect2 daemon.err NetworkManager[309]: <error> [1532004726.0732] platform-linux: do-add-ip4-address[8: 10.167.240.23/32]: failure 19 (No such device)
Jul 19 12:52:06 canect2 daemon.err NetworkManager[309]: <error> [1532004726.0776] platform-linux: do-add-ip4-route[8: 0.0.0.0/0 1000]: failure 19 (No such device)
Jul 19 12:52:06 canect2 daemon.warn NetworkManager[309]: <warn>  [1532004726.0788] default-route: failed to add default route 0.0.0.0/0 via 0.0.0.0 dev 8 metric 1000 mss 0 rt-src user with effective metric 1000
Jul 19 12:52:06 canect2 daemon.err NetworkManager[309]: <error> [1532004726.1012] platform-linux: do-add-ip4-address[8: 10.167.240.23/32]: failure 19 (No such device)
Jul 19 12:52:06 canect2 daemon.err NetworkManager[309]: <error> [1532004726.1041] platform-linux: do-add-ip4-route[8: 0.0.0.0/0 1000]: failure 19 (No such device)
Jul 19 12:52:06 canect2 daemon.warn NetworkManager[309]: <warn>  [1532004726.1057] default-route: failed to add default route 0.0.0.0/0 via 0.0.0.0 dev 8 metric 1000 mss 0 rt-src user with effective metric 1000
Jul 19 12:52:06 canect2 daemon.warn ModemManager[302]: <warn>  (ttyACM0): could not re-acquire serial port lock: (5) Input/output error
Jul 19 12:52:06 canect2 daemon.info ModemManager[302]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> searching)
Jul 19 12:52:06 canect2 daemon.info NetworkManager[309]: <info>  [1532004726.2975] (ttyACM0): modem state changed, 'connected' --> 'searching' (reason: user-requested)
Jul 19 12:52:06 canect2 daemon.info NetworkManager[309]: <info>  [1532004726.3007] device (ttyACM0): state change: activated -> failed (reason 'modem-no-carrier') [100 120 25]
Jul 19 12:52:06 canect2 daemon.warn NetworkManager[309]: <warn>  [1532004726.3315] settings-connection[0x143e0b0,83187ceb-ad3a-4af8-92d8-7a255d9c5e3f]: error saving timestamp to file '/var/lib/NetworkManager/timestamps': Failed to create file "/var/lib/NetworkManager/t
Jul 19 12:52:06 canect2 daemon.info ModemManager[302]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (searching -> registering)
Jul 19 12:52:06 canect2 daemon.warn ModemManager[302]: <warn>  Couldn't load Operator Code: 'Cannot run sequence: 'Could not open serial device ttyACM0: it has been forced close''
Jul 19 12:52:06 canect2 daemon.warn ModemManager[302]: <warn>  Couldn't load Operator Name: 'Cannot run sequence: 'Could not open serial device ttyACM0: it has been forced close''
Jul 19 12:52:06 canect2 daemon.info ModemManager[302]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (registering -> home)
Jul 19 12:52:06 canect2 daemon.info ModemManager[302]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (searching -> registered)
Jul 19 12:52:06 canect2 daemon.warn NetworkManager[309]: <warn>  [1532004726.4199] device (ttyACM0): Activation: failed for connection 'Aeris'
Jul 19 12:52:06 canect2 daemon.notice dbus[235]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Jul 19 12:52:06 canect2 daemon.info NetworkManager[309]: <info>  [1532004726.5093] (ttyACM0): modem state changed, 'searching' --> 'registered' (reason: unknown)
Jul 19 12:52:06 canect2 daemon.info NetworkManager[309]: <info>  [1532004726.5304] device (ttyACM0): state change: failed -> disconnected (reason 'none') [120 30 0]
Jul 19 12:52:06 canect2 daemon.notice dbus[235]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
Jul 19 12:52:06 canect2 daemon.info nm-dispatcher: req:1 'down' [ppp0]: new request (1 scripts)
Jul 19 12:52:06 canect2 daemon.info nm-dispatcher: req:1 'down' [ppp0]: start running ordered scripts...
Jul 19 12:52:07 canect2 daemon.warn NetworkManager[309]: <warn>  [1532004727.0918] ppp-manager: pppd pid 5047 exited with error: A modem hung up the phone
Jul 19 12:52:11 canect2 daemon.warn ModemManager[302]: <warn>  Couldn't load network timezone from the current network
Jul 19 12:52:27 canect2 daemon.info ModemManager[302]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (home -> unknown)
Jul 19 12:52:31 canect2 daemon.info ModemManager[302]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (unknown -> registering)
Jul 19 12:52:31 canect2 daemon.warn ModemManager[302]: <warn>  Couldn't load Operator Code: 'Cannot run sequence: 'Could not open serial device ttyACM0: it has been forced close''
Jul 19 12:52:31 canect2 daemon.warn ModemManager[302]: <warn>  Couldn't load Operator Name: 'Cannot run sequence: 'Could not open serial device ttyACM0: it has been forced close''
Jul 19 12:52:31 canect2 daemon.info ModemManager[302]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (registering -> home)
Jul 19 13:04:37 canect2 daemon.info ModemManager[302]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (home -> unknown)
Jul 19 13:05:09 canect2 daemon.info ModemManager[302]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (unknown -> registering)
Jul 19 13:05:09 canect2 daemon.warn ModemManager[302]: <warn>  Couldn't load Operator Code: 'Cannot run sequence: 'Could not open serial device ttyACM0: it has been forced close''
Jul 19 13:05:09 canect2 daemon.warn ModemManager[302]: <warn>  Couldn't load Operator Name: 'Cannot run sequence: 'Could not open serial device ttyACM0: it has been forced close''
Jul 19 13:05:09 canect2 daemon.info ModemManager[302]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (registering -> home)

Later when trying to load the cell profile (named Aeris) from NetworkManager after the issue with opening the serial port has occurred, I get the following:

Jul 19 13:18:06 canect2 daemon.info NetworkManager[309]: <info>  [1532006286.1655] keyfile: update /etc/NetworkManager/system-connections/Aeris (83187ceb-ad3a-4af8-92d8-7a255d9c5e3f,"Aeris")
Jul 19 13:18:06 canect2 daemon.info NetworkManager[309]: <info>  [1532006286.1826] audit: op="connection-update" uuid="83187ceb-ad3a-4af8-92d8-7a255d9c5e3f" name="Aeris" args="connection.autoconnect,connection.timestamp" pid=23674 uid=0 result="success"
Jul 19 13:18:06 canect2 daemon.info NetworkManager[309]: <info>  [1532006286.3195] policy: auto-activating connection 'Aeris'
Jul 19 13:18:06 canect2 daemon.info NetworkManager[309]: <info>  [1532006286.4401] device (ttyACM0): Activation: starting connection 'Aeris' (83187ceb-ad3a-4af8-92d8-7a255d9c5e3f)
Jul 19 13:18:06 canect2 daemon.info NetworkManager[309]: <info>  [1532006286.4644] device (ttyACM0): state change: disconnected -> prepare (reason 'none') [30 40 0]
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Simple connect started...
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Simple connect state (4/8): Wait to get fully enabled
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Simple connect state (5/8): Register
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Simple connect state (6/8): Bearer
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Simple connect state (7/8): Connect
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Jul 19 13:18:06 canect2 daemon.info NetworkManager[309]: <info>  [1532006286.5197] (ttyACM0): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Jul 19 13:18:06 canect2 daemon.warn ModemManager[302]: <warn>  Couldn't find best CID to use: 'Cannot run sequence: 'Could not open serial device ttyACM0: it has been forced close''
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> registered)
Jul 19 13:18:06 canect2 daemon.info NetworkManager[309]: <info>  [1532006286.5493] (ttyACM0): modem state changed, 'connecting' --> 'registered' (reason: user-requested)
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Simple connect started...
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Simple connect state (4/8): Wait to get fully enabled
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Simple connect state (5/8): Register
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Simple connect state (6/8): Bearer
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Simple connect started...
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Simple connect state (4/8): Wait to get fully enabled
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Simple connect state (5/8): Register
Jul 19 13:18:06 canect2 daemon.info ModemManager[302]: <info>  Simple connect state (6/8): Bearer
Jul 19 13:18:06 canect2 daemon.warn NetworkManager[309]: <warn>  [1532006286.6025] modem-broadband[ttyACM0]: failed to connect modem: Cannot run sequence: 'Could not open serial device ttyACM0: it has been forced close'
Jul 19 13:18:06 canect2 daemon.info NetworkManager[309]: <info>  [1532006286.6028] device (ttyACM0): state change: prepare -> failed (reason 'unknown') [40 120 1]
Jul 19 13:18:06 canect2 daemon.warn NetworkManager[309]: <warn>  [1532006286.6295] device (ttyACM0): Activation: failed for connection 'Aeris'
Jul 19 13:18:06 canect2 daemon.info NetworkManager[309]: <info>  [1532006286.6679] device (ttyACM0): state change: failed -> disconnected (reason 'none') [120 30 0]

Best regards,

Matthew Starr