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

[Matthew Starr]

> -----Original Message-----
> From: Matthew Starr
> Sent: Thursday, July 19, 2018 2:22 PM
> To: 'Aleksander Morgado'
> 
> > -----Original Message-----
> > From: Aleksander Morgado [mailto:aleksander at aleksander.es]
> > Sent: Thursday, July 19, 2018 2:16 PM
> >
> > Hey,
> >
> > On Thu, Jul 19, 2018 at 3:47 PM, Matthew Starr <mstarr at hedonline.com>
> > wrote:
> > > 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.
> > >
> >
> > These seem relevant, yes:
> >
> > > 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''
> > ...
> >
> > Any chance you can get a debug output of MM while reproducing this
> issue?
> 
> I will try to run with debug turned on, but it does not happen all the time.  I
> will send an update when and if I can get it to happen with debug turned on.
> 
Aleksander,

I have attached a log file that contains the serial port error I am seeing with debug turned on.  Below are a set of times from the log file and the interesting events that occurred during those times:

18:37:09 - Cell data connect with IP address
18:38:35 - No cell signal detected (AT+CSQ)
18:39:21 - Cell data connection terminated due to signal loss
18:39:59 - Cell data connection with IP address
18:40:53 - No cell signal detected (AT+CSQ)
18:43:02 - Cell data connection terminated due to signal loss
18:48:12 - Cell data connection with IP address
18:49:20 - No cell signal detected (AT+CSQ)
18:50:39 - Cell data connection terminated due to signal loss
18:50:50 - First instance of "Could not open serial device ttyACM0" and "Serial command timed out" messages

To me it appears what is happening is when the cell data connection is established and then the signal is lost for some amount of time, then when trying to reconnect the /dev/ttyACM0 port stops responding to AT commands.  Restarting ModemManager resolves the issue and ModemManager connects to the cell data connection again right away.  I am not sure if restarting ModemManager causes ModemManager to try and send reset commands to the modem to clean any bad state the serial port is in, or if ModemManager wasn't closing the serial port properly so exiting ModemManager when restarting ModemManager closes that serial port.

Best regards,
 
Matthew Starr
-------------- next part --------------
A non-text attachment was scrubbed...
Name: modemmanager_fails_to_reconnect_after_signal_loss.log
Type: application/octet-stream
Size: 273046 bytes
Desc: modemmanager_fails_to_reconnect_after_signal_loss.log
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20180806/482b3815/attachment-0001.obj>