ModemManager Delayed Signal Lost Disconnect on u-blox TOBY-R200
Matthew Starr
mstarr at hedonline.com
Tue May 7 22:22:15 UTC 2019
> -----Original Message-----
> From: Aleksander Morgado [mailto:aleksander at aleksander.es]
> Sent: Tuesday, May 07, 2019 1:32 PM
>
> >
> > > It's the modem firmware itself handling that, MM will just report
> > > whatever the modem is reporting.
> > >
> > > E.g. if the modem is registered and connected in LTE, and the LTE
> > > network disappears (e.g. low signal quality, out of coverage) then the
> > > modem will try to handover to 3G or 2G transparently if there is any
> > > 3G or 2G around. While this is happening, the modem will definitely
> > > report that it's no longer registered in LTE (e.g. the CEREG:4 and
> > > CEREG:0 you see in the logs), it will also probably say that it's
> > > searching for some other non-LTE network via CREG/CGREG URCs, and
> > > while all that is happening, the modem will still keep saying that
> > > it's connected (the response to the periodic CGACT? states that the
> > > PDP context / EPS bearer is still connected). ModemManager will say
> > > that the modem is disconnected only when the CGACT? response reports
> > > that our specific CID isn't active.
> >
> > What about the case I had in the original email where CREG, CGREG, and
> CEREG are all reporting 0 (idle) or 3 (registration denied). At this point the
> modem is not searching anymore on 2G, 3G, or 4G. Could this condition
> combined with a CSQ showing 0 signal strength be used to force a disconnect
> even though CGACT is still showing an active bearer?
> >
>
> I have a lot of mixed feelings about that; I don't think we should be
> triggering any implicit disconnection ourselves if the modem didn't do
> it itself. The connection stack inside the modem has much more info
> than we do, and I would definitely prefer to just rely on the modem
> doing the disconnection if one is needed.
>
> > May 6 18:21:04 canect2 daemon.debug ModemManager[304]: <debug>
> [1557166864.178195] Modem
> /org/freedesktop/ModemManager1/Modem/0: signal quality updated (0)
> > 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>'
> >
> > This change would make ModemManager more aggressive about
> disconnecting, but if NetworkManager has a profile configured for
> autoconnect, then the connection would reconnect as soon as the modem
> can reestablish registration on a valid network.
> >
>
> If that is your concern, leaving the modem to disconnect itself when
> it thinks it should is probably going to give you the same
> reconnection speed, if you think about it. If we trigger a
> disconnection manually ourselves, we could even be doing things
> *worse*, as we would ask the modem to disconnect a context with
> CGACT=0 and the modem may end up taking a very long time to do that,
> especially under low signal conditions. From my point of view, MM
> shouldn't try to do anything on top of whatever the internal PS/EPS
> stack is doing inside the modem.
>
> > If this isn't something that you would want globally throughout
> ModemManager, then is this something that could be implemented in the u-
> blox plugin since it is u-blox's firmware that holds onto the bearer for a long
> time after loss of registration with the network? If so, how would one
> modify that logic? I would be willing to attempt to implement it but would
> like some ideas on where to properly implement the logic.
> >
>
> If you believe this is the u-blox firmware behaving incorrectly, then
> we can definitely bring it to u-blox engineers.
> Are you able to reproduce this issue easily with the TOBY-R200?
> How much time have you seen the modem needing to report the context as
> disconnected after all CREG/CGREG/CEREG keep saying 0? Are we talking
> about seconds, minutes?
What I have seen is eventually all three registration status values will show idle, but eventually it starts cycling through them again searching for a network to register with again. I currently have an email out to u-blox support about this.
Usually in a true no signal environment the modem will disconnect in 10-20 minutes, but I will see a registration status of idle on the registration status commands within 1-2 minutes after loss of signal.
What I think might be happening in some cases is the modem sees a valid network for a brief moment and restarts whatever countdown to when the modem eventually disconnects the PDP context. This is causing the modem to sometimes take a really long time to disconnect (over an hour has been seen).
>
> I'm not sure we want this in the u-blox plugin per se, again, not sure
> if MM should try to be smarter than the modem with less information.
>
> > I guess another approach would be to have an external application that
> uses the ModemManager library interface to monitor signal strength and
> registration status. When the registration is lost and signal strength 0, then
> the external application could tell NetworkManager to stop the GSM
> connection profile. In this case would the registration status be properly
> updated in the library as the connection is active?
>
> That is totally up to you to do, yes, this would be totally doable and
> it could be easy to do. BUT, consider again the case that trying to
> disconnect cleanly involves CGACT=0 and that could end up taking a
> very long time under low signal conditions...
You are right about the issues with trying to control the modem. I had more issues when trying to stop the connection then just letting the modem handle it. I think the only solution that is reliable here is to try and get u-blox to update the firmware or see if there are settings that might change the behavior to speed up disconnects.
I tried a simple test of establishing a connection, removing the antenna, and then running nmcli to down the cellular connection profile. After 10 seconds nmcli timed out, but eventually after the timeout pppd was terminated and ModemManager disconnected the bearer. The issue is this actually triggered the serial port issue where the port that was used for the data connection now can't be opened for AT commands. See below:
May 7 20:13:36 canect2 daemon.debug ModemManager[304]: <debug> [1557260016.869789] loading signal quality...
May 7 20:13:36 canect2 daemon.debug ModemManager[304]: <debug> [1557260016.870163] (ttyACM1) device open count is 2 (open)
May 7 20:13:36 canect2 daemon.debug ModemManager[304]: <debug> [1557260016.870476] (ttyACM1): --> 'AT+CIND?<CR>'
May 7 20:13:36 canect2 daemon.debug ModemManager[304]: <debug> [1557260016.874309] (ttyACM1): <-- '<CR><LF>+CIND: 5,0,0,0,0,0,0,0,0,0,0,0<CR><LF><CR><LF>OK<CR><LF>'
May 7 20:13:36 canect2 daemon.debug ModemManager[304]: <debug> [1557260016.875133] (ttyACM1) device open count is 3 (open)
May 7 20:13:36 canect2 daemon.debug ModemManager[304]: <debug> [1557260016.875401] (ttyACM1) device open count is 2 (close)
May 7 20:13:36 canect2 daemon.debug ModemManager[304]: <debug> [1557260016.875634] (ttyACM1): --> 'AT+CSQ<CR>'
May 7 20:13:36 canect2 daemon.debug ModemManager[304]: <debug> [1557260016.878974] (ttyACM1): <-- '<CR><LF>+CSQ: 99,99<CR><LF><CR><LF>OK<CR><LF>'
May 7 20:13:36 canect2 daemon.debug ModemManager[304]: <debug> [1557260016.880090] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (0)
May 7 20:13:36 canect2 daemon.debug ModemManager[304]: <debug> [1557260016.880869] Periodic signal quality checks scheduled in 30s
May 7 20:13:36 canect2 daemon.debug ModemManager[304]: <debug> [1557260016.881443] (ttyACM1) device open count is 1 (close)
May 7 20:13:40 canect2 daemon.debug ModemManager[304]: <debug> [1557260020.869313] (ttyACM1) device open count is 2 (open)
May 7 20:13:40 canect2 daemon.debug ModemManager[304]: <debug> [1557260020.869699] (ttyACM1): --> 'AT+CGACT?<CR>'
May 7 20:13:40 canect2 daemon.debug ModemManager[304]: <debug> [1557260020.874946] (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 7 20:13:40 canect2 daemon.debug ModemManager[304]: <debug> [1557260020.876049] connection status loaded: connected
May 7 20:13:40 canect2 daemon.debug ModemManager[304]: <debug> [1557260020.876247] (ttyACM1) device open count is 1 (close)
May 7 20:13:45 canect2 daemon.debug ModemManager[304]: <debug> [1557260025.874689] (ttyACM1) device open count is 2 (open)
May 7 20:13:45 canect2 daemon.debug ModemManager[304]: <debug> [1557260025.875078] (ttyACM1): --> 'AT+CGACT?<CR>'
May 7 20:13:45 canect2 daemon.debug ModemManager[304]: <debug> [1557260025.880205] (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 7 20:13:45 canect2 daemon.debug ModemManager[304]: <debug> [1557260025.881295] connection status loaded: connected
May 7 20:13:45 canect2 daemon.debug ModemManager[304]: <debug> [1557260025.881495] (ttyACM1) device open count is 1 (close)
May 7 20:13:48 canect2 daemon.debug ModemManager[304]: <debug> [1557260028.662030] (ttyACM1): <-- '<CR><LF>+CREG: 0<CR><LF><CR><LF>+CGREG: 0<CR><LF><CR><LF>+CEREG: 0<CR><LF>'
May 7 20:13:48 canect2 daemon.info ModemManager[304]: <info> [1557260028.662757] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (searching -> idle)
May 7 20:13:48 canect2 daemon.debug ModemManager[304]: <debug> [1557260028.663342] Connected bearer not registered in 3GPP network
May 7 20:13:50 canect2 daemon.debug ModemManager[304]: <debug> [1557260030.869499] (ttyACM1) device open count is 2 (open)
May 7 20:13:50 canect2 daemon.debug ModemManager[304]: <debug> [1557260030.873975] (ttyACM1): --> 'AT+CGACT?<CR>'
May 7 20:13:50 canect2 daemon.debug ModemManager[304]: <debug> [1557260030.878919] (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 7 20:13:50 canect2 daemon.debug ModemManager[304]: <debug> [1557260030.880280] connection status loaded: connected
May 7 20:13:50 canect2 daemon.debug ModemManager[304]: <debug> [1557260030.880779] (ttyACM1) device open count is 1 (close)
May 7 20:13:53 canect2 daemon.debug ModemManager[304]: <debug> [1557260033.662875] (ttyACM1): <-- '<CR><LF>+CREG: 2<CR><LF><CR><LF>+CGREG: 2<CR><LF><CR><LF>+CEREG: 4<CR><LF>'
May 7 20:13:53 canect2 daemon.info ModemManager[304]: <info> [1557260033.663471] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (idle -> searching)
May 7 20:13:54 canect2 daemon.debug ModemManager[304]: <debug> [1557260034.498535] (ttyACM1): <-- '<CR><LF>+CREG: 2<CR><LF><CR><LF>+CEREG: 4<CR><LF>'
May 7 20:13:55 canect2 daemon.debug ModemManager[304]: <debug> [1557260035.871007] (ttyACM1) device open count is 2 (open)
May 7 20:13:55 canect2 daemon.debug ModemManager[304]: <debug> [1557260035.871392] (ttyACM1): --> 'AT+CGACT?<CR>'
May 7 20:13:55 canect2 daemon.debug ModemManager[304]: <debug> [1557260035.876185] (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 7 20:13:55 canect2 daemon.debug ModemManager[304]: <debug> [1557260035.877271] connection status loaded: connected
May 7 20:13:55 canect2 daemon.debug ModemManager[304]: <debug> [1557260035.877467] (ttyACM1) device open count is 1 (close)
May 7 20:13:57 canect2 daemon.info NetworkManager[311]: <info> [1557260037.4230] device (ttyACM0): state change: activated -> deactivating (reason 'user-requested', sys-iface-state: 'managed')
May 7 20:13:57 canect2 daemon.warn NetworkManager[311]: <warn> [1557260037.4280] settings-connection[0x1aa10d8,83187ceb-ad3a-4af8-92d8-7a255d9c5e3f]: error saving timestamp to file '/var/lib/NetworkManager/timestamps': Failed to create file “/var/lib/NetworkManager/t
May 7 20:13:57 canect2 daemon.info NetworkManager[311]: <info> [1557260037.4596] manager: NetworkManager state is now CONNECTED_LOCAL
May 7 20:13:57 canect2 daemon.notice dbus[232]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
May 7 20:13:57 canect2 daemon.info NetworkManager[311]: <info> [1557260037.4833] audit: op="connection-deactivate" uuid="83187ceb-ad3a-4af8-92d8-7a255d9c5e3f" name="Aeris" pid=642 uid=0 result="success"
May 7 20:13:57 canect2 daemon.info pppd[537]: Terminating on signal 15
May 7 20:13:57 canect2 auth.notice dbus[232]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.1" (uid=0 pid=311 comm="/usr/sbin/NetworkManager ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" request
May 7 20:13:57 canect2 auth.notice dbus[232]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.1" (uid=0 pid=311 comm="/usr/sbin/NetworkManager ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" request
May 7 20:13:57 canect2 daemon.info pppd[537]: Connect time 2.6 minutes.
May 7 20:13:57 canect2 daemon.info pppd[537]: Sent 112 bytes, received 32 bytes.
May 7 20:13:57 canect2 daemon.notice pppd[537]: Connection terminated.
May 7 20:13:57 canect2 daemon.debug ModemManager[304]: <debug> [1557260037.545305] Disconnecting bearer '/org/freedesktop/ModemManager1/Bearer/0'
May 7 20:13:57 canect2 daemon.info ModemManager[304]: <info> [1557260037.545575] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connected -> disconnecting)
May 7 20:13:57 canect2 daemon.debug ModemManager[304]: <debug> [1557260037.547127] Sending PDP context deactivation in secondary port...
May 7 20:13:57 canect2 daemon.debug ModemManager[304]: <debug> [1557260037.547340] (ttyACM1) device open count is 2 (open)
May 7 20:13:57 canect2 daemon.debug ModemManager[304]: <debug> [1557260037.547746] (ttyACM1): --> 'AT+CGACT=0,2<CR>'
May 7 20:13:57 canect2 daemon.info NetworkManager[311]: <info> [1557260037.5616] device (ppp0): state change: disconnected -> unmanaged (reason 'connection-assumed', sys-iface-state: 'external')
May 7 20:13:57 canect2 auth.notice dbus[232]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.1" (uid=0 pid=311 comm="/usr/sbin/NetworkManager ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" request
May 7 20:13:57 canect2 auth.notice dbus[232]: [system] Rejected send message, 0 matched rules; type="error", sender=":1.1" (uid=0 pid=311 comm="/usr/sbin/NetworkManager ") interface="(unset)" member="(unset)" error name="org.freedesktop.DBus.Error.UnknownMethod" request
May 7 20:13:57 canect2 daemon.info NetworkManager[311]: <info> [1557260037.6185] modem["ttyACM0"]: modem state changed, 'connected' --> 'disconnecting' (reason: user-requested)
May 7 20:13:57 canect2 daemon.notice dbus[232]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
May 7 20:13:57 canect2 daemon.info nm-dispatcher: req:1 'connectivity-change': new request (2 scripts)
May 7 20:13:57 canect2 daemon.info nm-dispatcher: req:1 'connectivity-change': start running ordered scripts...
May 7 20:13:58 canect2 daemon.info pppd[537]: Exit.
May 7 20:14:00 canect2 daemon.debug ModemManager[304]: <debug> [1557260040.870017] (ttyACM1) device open count is 3 (open)
May 7 20:14:05 canect2 daemon.debug ModemManager[304]: <debug> [1557260045.874634] (ttyACM1) device open count is 4 (open)
May 7 20:14:06 canect2 daemon.debug ModemManager[304]: <debug> [1557260046.869136] loading signal quality...
May 7 20:14:06 canect2 daemon.debug ModemManager[304]: <debug> [1557260046.869447] (ttyACM1) device open count is 5 (open)
May 7 20:14:07 canect2 daemon.debug ModemManager[304]: <debug> [1557260047.871006] PDP context deactivation failed (not fatal): Serial command timed out
May 7 20:14:07 canect2 daemon.debug ModemManager[304]: <debug> [1557260047.871266] Reopening data port (ttyACM0)...
May 7 20:14:07 canect2 daemon.debug ModemManager[304]: <debug> [1557260047.871385] (ttyACM0) reopening port (2)
May 7 20:14:07 canect2 daemon.debug ModemManager[304]: <debug> [1557260047.871465] (ttyACM0) device open count is 1 (close)
May 7 20:14:07 canect2 daemon.debug ModemManager[304]: <debug> [1557260047.871537] (ttyACM0) device open count is 0 (close)
May 7 20:14:07 canect2 daemon.debug ModemManager[304]: <debug> [1557260047.871619] (ttyACM0) closing serial port...
May 7 20:14:07 canect2 daemon.debug ModemManager[304]: <debug> [1557260047.871707] (ttyACM0): port now disconnected
May 7 20:14:07 canect2 daemon.debug ModemManager[304]: <debug> [1557260047.879824] (ttyACM0) serial port closed
May 7 20:14:07 canect2 daemon.debug ModemManager[304]: <debug> [1557260047.880047] (ttyACM1) device open count is 4 (close)
May 7 20:14:07 canect2 daemon.debug ModemManager[304]: <debug> [1557260047.880335] (ttyACM1): --> 'AT+CGACT?<CR>'
May 7 20:14:08 canect2 daemon.debug ModemManager[304]: <debug> [1557260048.880335] (ttyACM0) opening serial port...
May 7 20:14:08 canect2 daemon.debug ModemManager[304]: <debug> [1557260048.882216] (ttyACM0): setting up baudrate: 57600
May 7 20:14:08 canect2 daemon.debug ModemManager[304]: <debug> [1557260048.882533] (ttyACM0) device open count is 1 (open)
May 7 20:14:08 canect2 daemon.debug ModemManager[304]: <debug> [1557260048.882645] (ttyACM0) device open count is 2 (open)
May 7 20:14:08 canect2 daemon.debug ModemManager[304]: <debug> [1557260048.883001] Flashing data port (ttyACM0)...
May 7 20:14:08 canect2 daemon.debug ModemManager[304]: <debug> [1557260048.884047] (ttyACM0): port attributes not fully set
May 7 20:14:09 canect2 daemon.debug ModemManager[304]: <debug> [1557260049.886989] (ttyACM0) device open count is 1 (close)
May 7 20:14:09 canect2 daemon.debug ModemManager[304]: <debug> [1557260049.887169] (ttyACM0): running init sequence...
May 7 20:14:09 canect2 daemon.debug ModemManager[304]: <debug> [1557260049.887385] Sending PDP context deactivation in primary/data port...
May 7 20:14:09 canect2 daemon.debug ModemManager[304]: <debug> [1557260049.887566] (ttyACM0) device open count is 2 (open)
May 7 20:14:09 canect2 daemon.debug ModemManager[304]: <debug> [1557260049.887928] (ttyACM0): --> 'ATE0<CR>'
May 7 20:14:10 canect2 daemon.debug ModemManager[304]: <debug> [1557260050.869479] (ttyACM0) device open count is 3 (open)
May 7 20:14:10 canect2 daemon.warn ModemManager[304]: <warn> [1557260050.869941] checking if connected failed: Couldn't check current list of active PDP contexts: Serial command timed out
May 7 20:14:10 canect2 daemon.debug ModemManager[304]: <debug> [1557260050.870125] (ttyACM1) device open count is 3 (close)
May 7 20:14:10 canect2 daemon.debug ModemManager[304]: <debug> [1557260050.870386] (ttyACM1): --> 'AT+CGACT?<CR>'
May 7 20:14:12 canect2 daemon.debug ModemManager[304]: <debug> [1557260052.869782] (ttyACM0): --> 'ATV1<CR>'
May 7 20:14:13 canect2 daemon.warn ModemManager[304]: <warn> [1557260053.870302] checking if connected failed: Couldn't check current list of active PDP contexts: Serial command timed out
May 7 20:14:13 canect2 daemon.debug ModemManager[304]: <debug> [1557260053.870546] (ttyACM1) device open count is 2 (close)
May 7 20:14:13 canect2 daemon.debug ModemManager[304]: <debug> [1557260053.870815] (ttyACM1): --> 'AT+CIND?<CR>'
May 7 20:14:15 canect2 daemon.debug ModemManager[304]: <debug> [1557260055.870264] (ttyACM0) device open count is 4 (open)
May 7 20:14:15 canect2 daemon.debug ModemManager[304]: <debug> [1557260055.870742] (ttyACM0): --> 'AT+CMEE=1<CR>'
May 7 20:14:18 canect2 daemon.debug ModemManager[304]: <debug> [1557260058.869476] (ttyACM1) device open count is 3 (open)
May 7 20:14:18 canect2 daemon.debug ModemManager[304]: <debug> [1557260058.869794] (ttyACM1) device open count is 2 (close)
May 7 20:14:18 canect2 daemon.debug ModemManager[304]: <debug> [1557260058.870122] (ttyACM1): --> 'AT+CSQ<CR>'
May 7 20:14:18 canect2 daemon.debug ModemManager[304]: <debug> [1557260058.871145] (ttyACM0): --> 'ATX4<CR>'
May 7 20:14:20 canect2 daemon.debug ModemManager[304]: <debug> [1557260060.869607] (ttyACM0) device open count is 5 (open)
May 7 20:14:21 canect2 daemon.debug ModemManager[304]: <debug> [1557260061.870340] Couldn't refresh signal quality: 'Serial command timed out'
May 7 20:14:21 canect2 daemon.debug ModemManager[304]: <debug> [1557260061.870538] Periodic signal quality checks scheduled in 30s
May 7 20:14:21 canect2 daemon.debug ModemManager[304]: <debug> [1557260061.870721] (ttyACM1) device open count is 1 (close)
May 7 20:14:21 canect2 daemon.debug ModemManager[304]: <debug> [1557260061.871021] (ttyACM0): --> 'AT&C1<CR>'
May 7 20:14:24 canect2 daemon.debug ModemManager[304]: <debug> [1557260064.869402] (ttyACM0): --> 'AT+CGACT=0,2<CR>'
May 7 20:14:25 canect2 daemon.debug ModemManager[304]: <debug> [1557260065.870072] (ttyACM0) device open count is 6 (open)
May 7 20:14:30 canect2 daemon.debug ModemManager[304]: <debug> [1557260070.869712] (ttyACM0) device open count is 7 (open)
May 7 20:14:34 canect2 daemon.debug ModemManager[304]: <debug> [1557260074.869379] PDP context deactivation failed (not fatal): Serial command timed out
May 7 20:14:34 canect2 daemon.debug ModemManager[304]: <debug> [1557260074.869577] Disconnected bearer '/org/freedesktop/ModemManager1/Bearer/0'
May 7 20:14:34 canect2 daemon.info ModemManager[304]: <info> [1557260074.869807] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disconnecting -> searching)
May 7 20:14:34 canect2 daemon.info NetworkManager[311]: <info> [1557260074.8767] modem["ttyACM0"]: modem state changed, 'disconnecting' --> 'searching' (reason: user-requested)
May 7 20:14:34 canect2 daemon.debug ModemManager[304]: <debug> [1557260074.878295] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (0)
May 7 20:14:34 canect2 daemon.debug ModemManager[304]: <debug> [1557260074.878871] Periodic signal checks disabled
May 7 20:14:34 canect2 daemon.info NetworkManager[311]: <info> [1557260074.8826] device (ttyACM0): state change: deactivating -> disconnected (reason 'user-requested', sys-iface-state: 'managed')
May 7 20:14:34 canect2 daemon.debug ModemManager[304]: <debug> [1557260074.889225] (ttyACM0) device open count is 6 (close)
May 7 20:14:34 canect2 daemon.debug ModemManager[304]: <debug> [1557260074.894383] (ttyACM0): --> 'AT+CGACT?<CR>'
May 7 20:14:34 canect2 daemon.notice dbus[232]: [system] Activating service name='org.freedesktop.nm_dispatcher' (using servicehelper)
May 7 20:14:35 canect2 daemon.notice dbus[232]: [system] Successfully activated service 'org.freedesktop.nm_dispatcher'
May 7 20:14:35 canect2 daemon.info nm-dispatcher: req:1 'down' [ttyACM0]: new request (2 scripts)
May 7 20:14:35 canect2 daemon.info nm-dispatcher: req:1 'down' [ttyACM0]: start running ordered scripts...
May 7 20:14:37 canect2 daemon.debug ModemManager[304]: <debug> [1557260077.551225] (ttyACM1): <-- '<CR><LF>OK<CR><LF><CR><LF>+CREG: 2<CR><LF><CR><LF>+CEREG: 4<CR><LF><CR><LF>+CREG: 0<CR><LF><CR><LF>+CGREG: 0<CR><LF><CR><LF>+CEREG: 0<CR><LF><CR><LF>+CREG: 2<CR><LF><CR><LF
May 7 20:14:37 canect2 daemon.info ModemManager[304]: <info> [1557260077.553046] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (searching -> idle)
May 7 20:14:37 canect2 daemon.debug ModemManager[304]: <debug> [1557260077.553637] Bearer not allowed to connect, not registered in 3GPP network
May 7 20:14:37 canect2 daemon.info ModemManager[304]: <info> [1557260077.554029] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (idle -> searching)
May 7 20:14:37 canect2 daemon.warn ModemManager[304]: <warn> [1557260077.870103] checking if connected failed: Couldn't check current list of active PDP contexts: Serial command timed out
May 7 20:14:37 canect2 daemon.debug ModemManager[304]: <debug> [1557260077.870659] (ttyACM0) device open count is 5 (close)
May 7 20:14:37 canect2 daemon.debug ModemManager[304]: <debug> [1557260077.871196] (ttyACM0): --> 'AT+CGACT?<CR>'
May 7 20:14:40 canect2 daemon.warn ModemManager[304]: <warn> [1557260080.869070] checking if connected failed: Couldn't check current list of active PDP contexts: Serial command timed out
May 7 20:14:40 canect2 daemon.debug ModemManager[304]: <debug> [1557260080.869307] (ttyACM0) device open count is 4 (close)
May 7 20:14:40 canect2 daemon.debug ModemManager[304]: <debug> [1557260080.869558] (ttyACM0): --> 'AT+CGACT?<CR>'
May 7 20:14:43 canect2 daemon.warn ModemManager[304]: <warn> [1557260083.872039] checking if connected failed: Couldn't check current list of active PDP contexts: Serial command timed out
May 7 20:14:43 canect2 daemon.debug ModemManager[304]: <debug> [1557260083.872278] (ttyACM0) device open count is 3 (close)
May 7 20:14:43 canect2 daemon.debug ModemManager[304]: <debug> [1557260083.872536] (ttyACM0): --> 'AT+CGACT?<CR>'
May 7 20:14:46 canect2 daemon.warn ModemManager[304]: <warn> [1557260086.869031] checking if connected failed: Couldn't check current list of active PDP contexts: Serial command timed out
May 7 20:14:46 canect2 daemon.debug ModemManager[304]: <debug> [1557260086.869274] (ttyACM0) device open count is 2 (close)
May 7 20:14:46 canect2 daemon.debug ModemManager[304]: <debug> [1557260086.869524] (ttyACM0): --> 'AT+CGACT?<CR>'
May 7 20:14:49 canect2 daemon.warn ModemManager[304]: <warn> [1557260089.872097] checking if connected failed: Couldn't check current list of active PDP contexts: Serial command timed out
May 7 20:14:49 canect2 daemon.debug ModemManager[304]: <debug> [1557260089.872334] (ttyACM0) device open count is 1 (close)
May 7 20:15:19 canect2 daemon.info NetworkManager[311]: <info> [1557260119.9380] audit: op="connection-add-activate" pid=734 uid=0 result="fail" reason="A 'wireless' setting is required if no AP path was given."
May 7 20:15:26 canect2 daemon.debug ModemManager[304]: <debug> [1557260126.695512] (ttyACM1): <-- '<CR><LF>+CIEV: 2,2<CR><LF>'
May 7 20:15:26 canect2 daemon.debug ModemManager[304]: <debug> [1557260126.696181] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (40)
May 7 20:15:28 canect2 daemon.debug ModemManager[304]: <debug> [1557260128.294191] (ttyACM1): <-- '<CR><LF>+CREG: 3<CR><LF><CR><LF>+CGREG: 3<CR><LF><CR><LF>+CIEV: 9,1<CR><LF><CR><LF>+CEREG: 3<CR><LF>'
May 7 20:15:28 canect2 daemon.info ModemManager[304]: <info> [1557260128.295066] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (searching -> unknown)
May 7 20:15:28 canect2 daemon.debug ModemManager[304]: <debug> [1557260128.295662] Bearer not allowed to connect, not registered in 3GPP network
May 7 20:15:36 canect2 daemon.debug ModemManager[304]: <debug> [1557260136.324109] (ttyACM1): <-- '<CR><LF>+CEREG: 3<CR><LF><CR><LF>+CEREG: 3<CR><LF>'
May 7 20:15:39 canect2 daemon.debug ModemManager[304]: <debug> [1557260139.887071] (ttyACM1): <-- '<CR><LF>+CIEV: 2,3<CR><LF>'
May 7 20:15:39 canect2 daemon.debug ModemManager[304]: <debug> [1557260139.887747] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (60)
May 7 20:15:40 canect2 daemon.debug ModemManager[304]: <debug> [1557260140.311183] (ttyACM1): <-- '<CR><LF>+CIEV: 2,2<CR><LF>'
May 7 20:15:40 canect2 daemon.debug ModemManager[304]: <debug> [1557260140.312245] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (40)
May 7 20:15:41 canect2 daemon.debug ModemManager[304]: <debug> [1557260141.324385] (ttyACM1): <-- '<CR><LF>+CIEV: 9,0<CR><LF><CR><LF>+CEREG: 3<CR><LF>'
May 7 20:15:41 canect2 daemon.debug ModemManager[304]: <debug> [1557260141.764202] (ttyACM1): <-- '<CR><LF>+CIEV: 2,3<CR><LF>'
May 7 20:15:41 canect2 daemon.debug ModemManager[304]: <debug> [1557260141.764869] Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (60)
May 7 20:15:44 canect2 daemon.debug ModemManager[304]: <debug> [1557260144.951453] (ttyACM1): <-- '<CR><LF>+CREG: 1,"7910","051C085F",6<CR><LF><CR><LF>+CIEV: 3,1<CR><LF><CR><LF>+CIEV: 9,1<CR><LF><CR><LF>+CEREG: 3<CR><LF>'
May 7 20:15:44 canect2 daemon.info ModemManager[304]: <info> [1557260144.952140] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (unknown -> registering)
May 7 20:15:44 canect2 daemon.debug ModemManager[304]: <debug> [1557260144.952345] loading Operator Code...
May 7 20:15:44 canect2 daemon.debug ModemManager[304]: <debug> [1557260144.952502] (ttyACM0) device open count is 2 (open)
May 7 20:15:44 canect2 daemon.debug ModemManager[304]: <debug> [1557260144.952927] Modem /org/freedesktop/ModemManager1/Modem/0: access technology changed (unknown -> hspa)
May 7 20:15:44 canect2 daemon.debug ModemManager[304]: <debug> [1557260144.953105] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '7910', Cell ID: '51C085F')
May 7 20:15:44 canect2 daemon.debug ModemManager[304]: <debug> [1557260144.957989] (ttyACM0): --> 'AT+COPS=3,2;+COPS?<CR>'
May 7 20:15:45 canect2 daemon.debug ModemManager[304]: <debug> [1557260145.015527] (ttyACM1): <-- '<CR><LF>+CGREG: 1,"7910","051C085F",6,"6C"<CR><LF><CR><LF>+CIEV: 9,2<CR><LF><CR><LF>+CEREG: 4<CR><LF>'
May 7 20:15:47 canect2 daemon.warn ModemManager[304]: <warn> [1557260147.872553] Couldn't load Operator Code: 'Serial command timed out'
May 7 20:15:47 canect2 daemon.debug ModemManager[304]: <debug> [1557260147.872915] loading Operator Name...
May 7 20:15:47 canect2 daemon.debug ModemManager[304]: <debug> [1557260147.873088] (ttyACM0) device open count is 3 (open)
May 7 20:15:47 canect2 daemon.debug ModemManager[304]: <debug> [1557260147.873304] (ttyACM0) device open count is 2 (close)
May 7 20:15:47 canect2 daemon.debug ModemManager[304]: <debug> [1557260147.873544] (ttyACM0): --> 'AT+COPS=3,0;+COPS?<CR>'
May 7 20:15:50 canect2 daemon.warn ModemManager[304]: <warn> [1557260150.871993] Couldn't load Operator Name: 'Serial command timed out'
May 7 20:15:50 canect2 daemon.debug ModemManager[304]: <debug> [1557260150.872428] (ttyACM0) device open count is 1 (close)
May 7 20:15:50 canect2 daemon.info ModemManager[304]: <info> [1557260150.872843] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (registering -> home)
May 7 20:15:50 canect2 daemon.info ModemManager[304]: <info> [1557260150.873246] Modem /org/freedesktop/ModemManager1/Modem/0: state changed (searching -> registered)
May 7 20:15:50 canect2 daemon.debug ModemManager[304]: <debug> [1557260150.873572] Network timezone polling started
May 7 20:15:50 canect2 daemon.info NetworkManager[311]: <info> [1557260150.8805] modem["ttyACM0"]: modem state changed, 'searching' --> 'registered' (reason: unknown)
May 7 20:15:50 canect2 daemon.debug ModemManager[304]: <debug> [1557260150.881811] Periodic signal checks enabled
May 7 20:15:50 canect2 daemon.debug ModemManager[304]: <debug> [1557260150.882236] Periodic signal check refresh requested
May 7 20:15:50 canect2 daemon.debug ModemManager[304]: <debug> [1557260150.882545] loading signal quality...
May 7 20:15:50 canect2 daemon.debug ModemManager[304]: <debug> [1557260150.882947] (ttyACM0) device open count is 2 (open)
May 7 20:15:50 canect2 daemon.debug ModemManager[304]: <debug> [1557260150.887033] (ttyACM0): --> 'AT+CIND?<CR>'
May 7 20:15:55 canect2 daemon.debug ModemManager[304]: <debug> [1557260155.873960] (ttyACM0) device open count is 3 (open)
May 7 20:15:55 canect2 daemon.debug ModemManager[304]: <debug> [1557260155.874799] (ttyACM0) device open count is 4 (open)
May 7 20:15:55 canect2 daemon.debug ModemManager[304]: <debug> [1557260155.875312] (ttyACM0) device open count is 3 (close)
May 7 20:15:55 canect2 daemon.debug ModemManager[304]: <debug> [1557260155.875927] (ttyACM0): --> 'AT+CCLK?<CR>'
May 7 20:15:58 canect2 daemon.debug ModemManager[304]: <debug> [1557260158.869680] Couldn't load network timezone: Serial command timed out
May 7 20:15:58 canect2 daemon.warn ModemManager[304]: <warn> [1557260158.869873] Couldn't load network timezone from the current network
May 7 20:15:58 canect2 daemon.debug ModemManager[304]: <debug> [1557260158.869967] (ttyACM0) device open count is 2 (close)
May 7 20:15:58 canect2 daemon.debug ModemManager[304]: <debug> [1557260158.870222] (ttyACM0): --> 'AT+CSQ<CR>'
May 7 20:16:01 canect2 daemon.debug ModemManager[304]: <debug> [1557260161.872353] Couldn't refresh signal quality: 'Serial command timed out'
May 7 20:16:01 canect2 daemon.debug ModemManager[304]: <debug> [1557260161.872541] Periodic signal quality checks scheduled in 3s
May 7 20:16:01 canect2 daemon.debug ModemManager[304]: <debug> [1557260161.872723] (ttyACM0) device open count is 1 (close)
May 7 20:16:04 canect2 daemon.debug ModemManager[304]: <debug> [1557260164.872194] loading signal quality...
May 7 20:16:04 canect2 daemon.debug ModemManager[304]: <debug> [1557260164.872516] (ttyACM0) device open count is 2 (open)
May 7 20:16:04 canect2 daemon.debug ModemManager[304]: <debug> [1557260164.872821] (ttyACM0): --> 'AT+CIND?<CR>'
May 7 20:16:09 canect2 daemon.debug ModemManager[304]: <debug> [1557260169.869415] (ttyACM0) device open count is 3 (open)
May 7 20:16:09 canect2 daemon.debug ModemManager[304]: <debug> [1557260169.869741] (ttyACM0) device open count is 2 (close)
May 7 20:16:09 canect2 daemon.debug ModemManager[304]: <debug> [1557260169.869992] (ttyACM0): --> 'AT+CSQ<CR>'
May 7 20:16:12 canect2 daemon.debug ModemManager[304]: <debug> [1557260172.872177] Couldn't refresh signal quality: 'Serial command timed out'
May 7 20:16:12 canect2 daemon.debug ModemManager[304]: <debug> [1557260172.872359] Periodic signal quality checks scheduled in 3s
May 7 20:16:12 canect2 daemon.debug ModemManager[304]: <debug> [1557260172.872537] (ttyACM0) device open count is 1 (close)
>
> >
> > >
> > > There's a thing here, though. For this kind of modems where PPP is
> > > used, maybe we shouldn't be doing the periodic CGACT? checks through
> > > the secondary TTY. This is an open point I have in mind to review,
> > > because if we end up reporting the disconnection via MM (because
> CGACT
> > > reports no active CIDs) then the pppd shutdown process may not be
> > > happening properly in NM and the connected TTY may not go well back to
> > > command mode. I think there was some open issue about this.
> >
> > I have reported a past issue where ModemManager is unable to reopen a
> port after a dropped cellular connection like this. I am not sure it is the port
> that is the problem since just restarting ModemManager fixes the issue, so
> maybe it is something with the way ModemManager is keeping the state of
> the port. If I remember correctly when ModemManager forced closed a
> port, it was not clearing its forced closed flag so ModemManager would
> always fail to open the port. I think I only reported it in the mailing list but
> never filed a bug report in GitLab. I could grab the old logs I have or possibly
> recreate the condition and file a new issue in GitLab if that would help track
> it.
>
> That was the issue I believe.
It looks like I am able to reproduce this issue two different ways. One is to request the NetworkManager profile down when there is no signal as seen above. The other way is to wait for the connection to eventually be dropped when there is no signal and sometimes the port is then unavailable.
>
> --
> Aleksander
> https://aleksander.es
Best regards,
Matthew Starr
More information about the ModemManager-devel
mailing list