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

Mon Aug 20 23:04:55 UTC 2018

Hey,

+thaller

>> > I did some further testing and while ModemManager is continually
>> reporting the serial port can't be opened, I was able to connect to the port
>> and send AT commands to the modem and the modem responded.  This
>> means there is something in ModemManager that is triggering these
>> messages and not the modem itself
>> >
>> > I have also been able to regularly reproduce this issue with
>> ModemManager 1.8.0 by just connecting a data connection, disconnecting
>> my antennas for about 5-10 minutes (simulates loss of signal in a poor signal
>> area), and reconnecting the antennas (simulates moving into a good signal
>> area).  ModemManager never recovers until the ModemManager process is
>> restarted.
>> >
>> > I see that ModemManager is reporting "(ttyACM0) unexpected port
>> hangup!" and then "(ttyACM0) forced to close port".  After that
>> ModemManager is unable to connect again to ttyACM0.  It looks like the
>> issue may be in the serial port force close code or whatever caused the force
>> close to occur.
>> >
>>
>> This look like a modem crash actually. When this previous issue
>> happens, do you see the ttyACM0 port going away from the system? (e.g.
>> in dmesg output)
>>
>
> The /dev/ttyACM0 interface does not go away, nor do any of the other ttyACM interfaces for the modem.  The problem will persist until ModemManager is restarted.  While ModemManager cannot communicate with the modem over /dev/ttyACM0, I am able to use minicom or picocom to talk to the modem using /dev/ttyACM0. Immediately on restarting ModemManager there is no longer an issue until the next time there is a long period of no signal while a data connection is established.
>
> I did some digging through the code and added some of my own debug statements to track down what was going on.  I found that in src/mm-port-serial.c when the port_serial_close_force() function is called and self->priv->forced_close is set to TRUE, that is when the port stops working in ModemManager.  At that point the forced_close value is never reset to FALSE.

Ok, I see.

I believe the problem here is that we're getting a HUP in the serial
port, and when that happens (remote end closes) we explicitly force
close the TTY. Now, this usually happens only when the tty goes away,
which is why I suggested that option. The other case where this could
happen is if modem control lines are in effect once pppd has exited;
IIRC no modem control lines should be in effect when MM recovers the
TTY after pppd is no longer using it, otherwise this kind of HUP may
happen. This could be a race condition between MM re-using the port
before pppd has fully exited, which reminds me of this one:
https://github.com/NetworkManager/NetworkManager/commit/fe090c34b7247116a1424d956148548cd0237c4b

Maybe the issue has been brought back?

The key point here is that NM cannot notify the disconnection to MM
before pppd has fully exited, and I believe this is not happening,
according to these logs you sent:

Aug  2 18:39:21 canect2 daemon.info pppd[310]: LCP terminated by peer
(User request)
Aug  2 18:39:21 canect2 daemon.info pppd[310]: Connect time 2.2 minutes.
Aug  2 18:39:21 canect2 daemon.info pppd[310]: Sent 1598 bytes,
received 1254 bytes.
Aug  2 18:39:22 canect2 daemon.notice pppd[310]: Modem hangup
Aug  2 18:39:22 canect2 daemon.notice pppd[310]: Connection terminated.
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.558492] (ttyACM1): <-- '<CR><LF>+COPS:
0,2,"310260",2<CR><LF><CR><LF>OK<CR><LF>'
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.559345] loaded Operator Code: 310260
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.559753] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP
location updated (MCC: '310', MNC: '260', Location area code: '55C2',
Cell ID: '2BFA65F')
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.559898] loading Operator Name...
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.560066] (ttyACM1) device open count is 3 (open)
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.560341] (ttyACM1) device open count is 2 (close)
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.568693] (ttyACM1): --> 'AT+COPS=3,0;+COPS?<CR>'
Aug  2 18:39:22 canect2 daemon.info NetworkManager[259]: <info>
(ttyACM0): device state change: activated -> failed (reason
'ip-config-unavailable') [100 120 5]
Aug  2 18:39:22 canect2 daemon.info NetworkManager[259]: <info>
NetworkManager state is now DISCONNECTED
Aug  2 18:39:22 canect2 daemon.warn NetworkManager[259]: <warn>
(ttyACM0): Activation: failed for connection 'ATT'
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.621958] Disconnecting bearer
'/org/freedesktop/ModemManager1/Bearer/0'
Aug  2 18:39:22 canect2 daemon.info ModemManager[253]: <info>
[1533235162.622294] Modem /org/freedesktop/ModemManager1/Modem/0:
state changed (connected -> disconnecting)
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.623518] Sending PDP context deactivation in secondary
port...
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.623710] (ttyACM1) device open count is 3 (open)
Aug  2 18:39:22 canect2 daemon.notice dbus[200]: [system] Activating
service name='org.freedesktop.nm_dispatcher' (using servicehelper)
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.747149] (ttyACM1): <-- '<CR><LF>+COPS:
0,0,"AT&T",2<CR><LF><CR><LF>OK<CR><LF>'
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.747921] loaded Operator Name: AT&T
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.748295] (ttyACM1) device open count is 2 (close)
Aug  2 18:39:22 canect2 daemon.info ModemManager[253]: <info>
[1533235162.751496] Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP
Registration state changed (registering -> home)
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.758517] (ttyACM1): --> 'AT+CGACT=0,2<CR>'
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.764292] (ttyACM1): <-- '<CR><LF>OK<CR><LF>'
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.765073] Reopening data port (ttyACM0)...
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.766013] (ttyACM0) reopening port (2)
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.767152] (ttyACM0) device open count is 1 (close)
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.768230] (ttyACM0) device open count is 0 (close)
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.769402] (ttyACM0) closing serial port...
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.770540] (ttyACM0): port now disconnected
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.771870] (ttyACM0) serial port closed
Aug  2 18:39:22 canect2 daemon.debug ModemManager[253]: <debug>
[1533235162.773374] (ttyACM1) device open count is 1 (close)
Aug  2 18:39:22 canect2 daemon.info pppd[310]: Exit.

By the time pppd exit notification happens, we have already started
the disconnection process in MM, and that's not right I think. The
logs should show first the Exit notification, and only then the
"Disconnecting bearer..." message in MM.

Thomas, Dan, any comment about this issue?

-- 
Aleksander
https://aleksander.es