ModemManager Delayed Signal Lost Disconnect on u-blox TOBY-R200

Mon May 6 18:36:20 UTC 2019

I am using a u-blox TOBY-R200 with an embedded Linux device that runs ModemManager 1.8.0, NetworkManager 1.12.0, and pppd 2.4.7.  When I disconnect the cellular antenna from the device, it can take 10 minutes or sometimes much longer before ModemManager/NetworkManager drops the data connection.  I would like it to disconnect closer to 1 minute of no signal.  Below I provide data on what I see that would make me think something should stop the cell data connection, but it keeps running.  What I am really looking for is a way to force the cell data connection to stop after around a minute of no signal and lack of network registration.

I have run ModemManager in debug mode and see that ModemManager detects the antenna being disconnected within 1 second based on the reported signal quality being 0.  I also see that the cell connection does not disconnect until I see pppd report "Modem hangup".

First what are the conditions where a cellular data connection will be automatically disconnected due to bad signal/loss of network?  Also what program handles the disconnect (NetworkManager, ModemManager, pppd)?

Based on the debug information from ModemManager:
- The signal quality of 0 is seen:
        May  6 18:21:04 canect2 daemon.debug ModemManager[304]: <debug> [1557166864.178195] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (0)
- The network registration is no longer valid and the modem is reporting idle, so it isn't even searching anymore:
        May  6 18:22:26 canect2 daemon.debug ModemManager[304]: <debug> [1557166946.511289] (ttyACM1): <-- '<CR><LF>+CREG: 0<CR><LF><CR><LF>+CGREG: 0<CR><LF><CR><LF>+CEREG: 0<CR><LF>'
- ModemManager keeps reporting that the connection is connected when it really isn't:
        May  6 18:31:00 canect2 daemon.debug ModemManager[304]: <debug> [1557167460.882025] connection status loaded: connected
- The bearer status was always showing connected as yes in the output of "mmcli -b 0", yet the debug output from ModemManager shows the bearer is not registered:
        May  6 18:21:52 canect2 daemon.debug ModemManager[304]: <debug> [1557166912.849992] Connected bearer not registered in 3GPP network

With the information listed above, why isn't ModemManager considering the bearer disconnected or forcing it to disconnect?  Is this NetworkManager that should be monitoring these states and isn't so the connection is never stopped?  Where could I configure or modify how soon the connection is dropped after loss of signal and registration?

Here is what I see when the connection finally does stop on its own after a while with no antenna connected:

May  6 18:31:10 canect2 daemon.debug ModemManager[304]: <debug> [1557167470.873088] (ttyACM1) device open count is 2 (open)
May  6 18:31:10 canect2 daemon.debug ModemManager[304]: <debug> [1557167470.873469] (ttyACM1): --> 'AT+CGACT?<CR>'
May  6 18:31:10 canect2 daemon.debug ModemManager[304]: <debug> [1557167470.878780] (ttyACM1): <-- '<CR><LF>+CGACT: 1,0<CR><LF><CR><LF>+CGACT: 2,1<CR><LF><CR><LF>+CGACT: 3,0<CR><LF><CR><LF>+CGACT: 4,0<CR><LF><CR><LF>+CGACT: 5,0<CR><LF><CR><LF>+CGACT: 6,0<CR><LF><CR><LF>+C
May  6 18:31:10 canect2 daemon.debug ModemManager[304]: <debug> [1557167470.880110] connection status loaded: connected
May  6 18:31:10 canect2 daemon.debug ModemManager[304]: <debug> [1557167470.880683] (ttyACM1) device open count is 1 (close)
May  6 18:31:13 canect2 daemon.debug ModemManager[304]: <debug> [1557167473.593700] (ttyACM1): <-- '<CR><LF>+CREG: 2<CR><LF><CR><LF>+CEREG: 4<CR><LF>'
May  6 18:31:15 canect2 daemon.debug ModemManager[304]: <debug> [1557167475.872996] (ttyACM1) device open count is 2 (open)
May  6 18:31:15 canect2 daemon.debug ModemManager[304]: <debug> [1557167475.873385] (ttyACM1): --> 'AT+CGACT?<CR>'
May  6 18:31:15 canect2 daemon.debug ModemManager[304]: <debug> [1557167475.878784] (ttyACM1): <-- '<CR><LF>+CGACT: 1,0<CR><LF><CR><LF>+CGACT: 2,1<CR><LF><CR><LF>+CGACT: 3,0<CR><LF><CR><LF>+CGACT: 4,0<CR><LF><CR><LF>+CGACT: 5,0<CR><LF><CR><LF>+CGACT: 6,0<CR><LF><CR><LF>+C
May  6 18:31:15 canect2 daemon.debug ModemManager[304]: <debug> [1557167475.879858] connection status loaded: connected
May  6 18:31:15 canect2 daemon.debug ModemManager[304]: <debug> [1557167475.880056] (ttyACM1) device open count is 1 (close)
May  6 18:31:20 canect2 daemon.debug ModemManager[304]: <debug> [1557167480.875650] (ttyACM1) device open count is 2 (open)
May  6 18:31:20 canect2 daemon.debug ModemManager[304]: <debug> [1557167480.876037] (ttyACM1): --> 'AT+CGACT?<CR>'
May  6 18:31:20 canect2 daemon.debug ModemManager[304]: <debug> [1557167480.882306] (ttyACM1): <-- '<CR><LF>+CGACT: 1,0<CR><LF><CR><LF>+CGACT: 2,1<CR><LF><CR><LF>+CGACT: 3,0<CR><LF><CR><LF>+CGACT: 4,0<CR><LF><CR><LF>+CGACT: 5,0<CR><LF><CR><LF>+CGACT: 6,0<CR><LF><CR><LF>+C
May  6 18:31:20 canect2 daemon.debug ModemManager[304]: <debug> [1557167480.883459] connection status loaded: connected
May  6 18:31:20 canect2 daemon.debug ModemManager[304]: <debug> [1557167480.883663] (ttyACM1) device open count is 1 (close)
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.876448] (ttyACM1) device open count is 2 (open)
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.876769] loading signal quality...
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.876957] (ttyACM1) device open count is 3 (open)
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.881612] (ttyACM1): --> 'AT+CGACT?<CR>'
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.888000] (ttyACM1): <-- '<CR><LF>+CGACT: 1,0<CR><LF><CR><LF>+CGACT: 2,1<CR><LF><CR><LF>+CGACT: 3,0<CR><LF><CR><LF>+CGACT: 4,0<CR><LF><CR><LF>+CGACT: 5,0<CR><LF><CR><LF>+CGACT: 6,0<CR><LF><CR><LF>+C
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.889407] connection status loaded: connected
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.889881] (ttyACM1) device open count is 2 (close)
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.890380] (ttyACM1): --> 'AT+CIND?<CR>'
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.893977] (ttyACM1): <-- '<CR><LF>+CIND: 5,0,0,0,0,0,0,0,0,0,0,0<CR><LF><CR><LF>OK<CR><LF>'
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.894989] (ttyACM1) device open count is 3 (open)
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.895556] (ttyACM1) device open count is 2 (close)
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.896059] (ttyACM1): --> 'AT+CSQ<CR>'
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.899223] (ttyACM1): <-- '<CR><LF>+CSQ: 99,99<CR><LF><CR><LF>OK<CR><LF>'
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.900293] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (0)
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.900837] Periodic signal quality checks scheduled in 30s
May  6 18:31:25 canect2 daemon.debug ModemManager[304]: <debug> [1557167485.901271] (ttyACM1) device open count is 1 (close)
May  6 18:31:26 canect2 user.alert kernel: [  801.008093] wlan: mlan0 START SCAN
May  6 18:31:28 canect2 user.warn kernel: [  802.620129] wlan: SCAN COMPLETED: scanned AP count=10
May  6 18:31:30 canect2 daemon.debug ModemManager[304]: <debug> [1557167490.875920] (ttyACM1) device open count is 2 (open)
May  6 18:31:30 canect2 daemon.debug ModemManager[304]: <debug> [1557167490.876303] (ttyACM1): --> 'AT+CGACT?<CR>'
May  6 18:31:30 canect2 daemon.debug ModemManager[304]: <debug> [1557167490.882310] (ttyACM1): <-- '<CR><LF>+CGACT: 1,0<CR><LF><CR><LF>+CGACT: 2,1<CR><LF><CR><LF>+CGACT: 3,0<CR><LF><CR><LF>+CGACT: 4,0<CR><LF><CR><LF>+CGACT: 5,0<CR><LF><CR><LF>+CGACT: 6,0<CR><LF><CR><LF>+C
May  6 18:31:30 canect2 daemon.debug ModemManager[304]: <debug> [1557167490.883392] connection status loaded: connected
May  6 18:31:30 canect2 daemon.debug ModemManager[304]: <debug> [1557167490.883648] (ttyACM1) device open count is 1 (close)
May  6 18:31:34 canect2 daemon.info NetworkManager[311]: <info>  [1557167494.0571] audit: op="connection-add-activate" pid=785 uid=0 result="fail" reason="A 'wireless' setting is required if no AP path was given."
May  6 18:31:35 canect2 daemon.debug ModemManager[304]: <debug> [1557167495.876110] (ttyACM1) device open count is 2 (open)
May  6 18:31:35 canect2 daemon.debug ModemManager[304]: <debug> [1557167495.876486] (ttyACM1): --> 'AT+CGACT?<CR>'
May  6 18:31:35 canect2 daemon.debug ModemManager[304]: <debug> [1557167495.882438] (ttyACM1): <-- '<CR><LF>+CGACT: 1,0<CR><LF><CR><LF>+CGACT: 2,1<CR><LF><CR><LF>+CGACT: 3,0<CR><LF><CR><LF>+CGACT: 4,0<CR><LF><CR><LF>+CGACT: 5,0<CR><LF><CR><LF>+CGACT: 6,0<CR><LF><CR><LF>+C
May  6 18:31:35 canect2 daemon.debug ModemManager[304]: <debug> [1557167495.883521] connection status loaded: connected
May  6 18:31:35 canect2 daemon.debug ModemManager[304]: <debug> [1557167495.883774] (ttyACM1) device open count is 1 (close)
May  6 18:31:40 canect2 daemon.debug ModemManager[304]: <debug> [1557167500.875017] (ttyACM1) device open count is 2 (open)
May  6 18:31:40 canect2 daemon.debug ModemManager[304]: <debug> [1557167500.875398] (ttyACM1): --> 'AT+CGACT?<CR>'
May  6 18:31:40 canect2 daemon.debug ModemManager[304]: <debug> [1557167500.881307] (ttyACM1): <-- '<CR><LF>+CGACT: 1,0<CR><LF><CR><LF>+CGACT: 2,1<CR><LF><CR><LF>+CGACT: 3,0<CR><LF><CR><LF>+CGACT: 4,0<CR><LF><CR><LF>+CGACT: 5,0<CR><LF><CR><LF>+CGACT: 6,0<CR><LF><CR><LF>+C
May  6 18:31:40 canect2 daemon.debug ModemManager[304]: <debug> [1557167500.882388] connection status loaded: connected
May  6 18:31:40 canect2 daemon.debug ModemManager[304]: <debug> [1557167500.882585] (ttyACM1) device open count is 1 (close)
May  6 18:31:45 canect2 daemon.debug ModemManager[304]: <debug> [1557167505.876087] (ttyACM1) device open count is 2 (open)
May  6 18:31:45 canect2 daemon.debug ModemManager[304]: <debug> [1557167505.876474] (ttyACM1): --> 'AT+CGACT?<CR>'
May  6 18:31:45 canect2 daemon.debug ModemManager[304]: <debug> [1557167505.882433] (ttyACM1): <-- '<CR><LF>+CGACT: 1,0<CR><LF><CR><LF>+CGACT: 2,1<CR><LF><CR><LF>+CGACT: 3,0<CR><LF><CR><LF>+CGACT: 4,0<CR><LF><CR><LF>+CGACT: 5,0<CR><LF><CR><LF>+CGACT: 6,0<CR><LF><CR><LF>+C
May  6 18:31:45 canect2 daemon.debug ModemManager[304]: <debug> [1557167505.883515] connection status loaded: connected
May  6 18:31:45 canect2 daemon.debug ModemManager[304]: <debug> [1557167505.883772] (ttyACM1) device open count is 1 (close)
May  6 18:31:48 canect2 daemon.debug ModemManager[304]: <debug> [1557167508.347425] (ttyACM1): <-- '<CR><LF>+CIEV: 2,1<CR><LF>'
May  6 18:31:48 canect2 daemon.debug ModemManager[304]: <debug> [1557167508.348063] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (20)
May  6 18:31:48 canect2 daemon.debug ModemManager[304]: <debug> [1557167508.641702] (ttyACM1): <-- '<CR><LF>+CREG: 1,"0000","0331E70C",7<CR><LF><CR><LF>+CGREG: 4<CR><LF><CR><LF>+CIEV: 3,1<CR><LF><CR><LF>+CEREG: 0<CR><LF>'
May  6 18:31:48 canect2 daemon.info ModemManager[304]: <info>  [1557167508.642347] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (searching -> registering)
May  6 18:31:48 canect2 daemon.debug ModemManager[304]: <debug> [1557167508.642554] loading Operator Code...
May  6 18:31:48 canect2 daemon.debug ModemManager[304]: <debug> [1557167508.642722] (ttyACM1) device open count is 2 (open)
May  6 18:31:48 canect2 daemon.debug ModemManager[304]: <debug> [1557167508.643131] Modem /org/freedesktop/ModemManager1/Modem/0: access technology changed (unknown -> lte)
May  6 18:31:48 canect2 daemon.debug ModemManager[304]: <debug> [1557167508.647791] (ttyACM1): --> 'AT+COPS=3,2;+COPS?<CR>'
May  6 18:31:48 canect2 daemon.notice pppd[540]: Modem hangup
May  6 18:31:48 canect2 daemon.debug ModemManager[304]: <debug> [1557167508.782893] (ttyACM1): <-- '<CR><LF>+COPS: 0,2,"311480",7<CR><LF><CR><LF>OK<CR><LF>'
May  6 18:31:48 canect2 daemon.warn NetworkManager[311]: <warn>  [1557167508.7835] ppp-manager: can't change the ifindex from 8 to 8
May  6 18:31:48 canect2 daemon.debug ModemManager[304]: <debug> [1557167508.785014] loaded Operator Code: 311480
May  6 18:31:48 canect2 daemon.debug ModemManager[304]: <debug> [1557167508.785746] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '311', MNC: '480', Location area code: '0', Cell ID: '0')
May  6 18:31:48 canect2 daemon.debug ModemManager[304]: <debug> [1557167508.786218] loading Operator Name...
May  6 18:31:48 canect2 daemon.debug ModemManager[304]: <debug> [1557167508.786627] (ttyACM1) device open count is 3 (open)
May  6 18:31:48 canect2 daemon.debug ModemManager[304]: <debug> [1557167508.787089] (ttyACM1) device open count is 2 (close)
May  6 18:31:48 canect2 daemon.debug ModemManager[304]: <debug> [1557167508.791127] (ttyACM1): --> 'AT+COPS=3,0;+COPS?<CR>'
May  6 18:31:49 canect2 daemon.debug ModemManager[304]: <debug> [1557167509.373307] (ttyACM1): <-- '<CR><LF>ERROR<CR><LF><CR><LF>+CREG: 3<CR><LF><CR><LF>+CGREG: 3<CR><LF><CR><LF>+CEREG: 3<CR><LF><CR><LF>+CEREG: 3<CR><LF><CR><LF>+CIEV: 3,0<CR><LF>'
May  6 18:31:49 canect2 daemon.info ModemManager[304]: <info>  [1557167509.374479] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (searching -> idle)
May  6 18:31:49 canect2 daemon.debug ModemManager[304]: <debug> [1557167509.375239] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Cell ID: '0')
May  6 18:31:49 canect2 daemon.debug ModemManager[304]: <debug> [1557167509.375902] Connected bearer not registered in 3GPP network
May  6 18:31:49 canect2 daemon.info ModemManager[304]: <info>  [1557167509.376545] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (idle -> unknown)
May  6 18:31:49 canect2 daemon.debug ModemManager[304]: <debug> [1557167509.377619] Got failure code 100: Unknown error
May  6 18:31:49 canect2 daemon.warn ModemManager[304]: <warn>  [1557167509.378117] Couldn't load Operator Name: 'Unknown error'
May  6 18:31:49 canect2 daemon.debug ModemManager[304]: <debug> [1557167509.378687] (ttyACM1) device open count is 1 (close)
May  6 18:31:49 canect2 daemon.info ModemManager[304]: <info>  [1557167509.382972] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (registering -> home)
May  6 18:31:50 canect2 daemon.debug ModemManager[304]: <debug> [1557167510.872975] (ttyACM1) device open count is 2 (open)
May  6 18:31:50 canect2 daemon.debug ModemManager[304]: <debug> [1557167510.873812] (ttyACM1): --> 'AT+CGACT?<CR>'
May  6 18:31:50 canect2 daemon.debug ModemManager[304]: <debug> [1557167510.880002] (ttyACM1): <-- '<CR><LF>+CGACT: 1,0<CR><LF><CR><LF>+CGACT: 2,0<CR><LF><CR><LF>+CGACT: 3,0<CR><LF><CR><LF>+CGACT: 4,0<CR><LF><CR><LF>+CGACT: 5,0<CR><LF><CR><LF>+CGACT: 6,0<CR><LF><CR><LF>+C
May  6 18:31:50 canect2 daemon.debug ModemManager[304]: <debug> [1557167510.881410] connection status loaded: disconnected
May  6 18:31:50 canect2 daemon.warn ModemManager[304]: <warn>  [1557167510.882008] (ttyACM0): could not re-acquire serial port lock: (5) Input/output error
May  6 18:31:50 canect2 daemon.debug ModemManager[304]: <debug> [1557167510.882435] (ttyACM0): port now disconnected
May  6 18:31:50 canect2 daemon.info ModemManager[304]: <info>  [1557167510.882875] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> registered)
May  6 18:31:50 canect2 daemon.info NetworkManager[311]: <info>  [1557167510.8894] modem["ttyACM0"]: modem state changed, 'connected' --> 'registered' (reason: user-requested)
May  6 18:31:50 canect2 daemon.info NetworkManager[311]: <info>  [1557167510.8897] device (ttyACM0): state change: activated -> failed (reason 'modem-no-carrier', sys-iface-state: 'managed')
May  6 18:31:50 canect2 daemon.warn NetworkManager[311]: <warn>  [1557167510.8958] settings-connection[0x12950d8,83187ceb-ad3a-4af8-92d8-7a255d9c5e3f]: error saving timestamp to file '/var/lib/NetworkManager/timestamps': Failed to create file "/var/lib/NetworkManager/t
May  6 18:31:50 canect2 daemon.debug ModemManager[304]: <debug> [1557167510.901996] (ttyACM1) device open count is 1 (close)
May  6 18:31:50 canect2 daemon.debug ModemManager[304]: <debug> [1557167510.902603] (ttyACM0) unexpected port hangup!
May  6 18:31:50 canect2 daemon.debug ModemManager[304]: <debug> [1557167510.902952] (ttyACM0) forced to close port
May  6 18:31:50 canect2 daemon.debug ModemManager[304]: <debug> [1557167510.903237] (ttyACM0) device open count is 0 (close)
May  6 18:31:50 canect2 daemon.debug ModemManager[304]: <debug> [1557167510.903522] (ttyACM0) closing serial port...
May  6 18:31:50 canect2 daemon.debug ModemManager[304]: <debug> [1557167510.903842] (ttyACM0) serial port closed
May  6 18:31:50 canect2 daemon.warn NetworkManager[311]: <warn>  [1557167510.9206] device (ttyACM0): Activation: failed for connection 'Aeris'
May  6 18:31:50 canect2 daemon.notice dbus[232]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
May  6 18:31:50 canect2 daemon.info NetworkManager[311]: <info>  [1557167510.9628] manager: NetworkManager state is now CONNECTED_LOCAL
May  6 18:31:50 canect2 daemon.info NetworkManager[311]: <info>  [1557167510.9858] device (ttyACM0): state change: failed -> disconnected (reason 'none', sys-iface-state: 'managed')

Best regards,

Matthew Starr