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

Tue Aug 14 21:45:24 UTC 2018

> -----Original Message-----
> From: Matthew Starr
> Sent: Monday, August 06, 2018 11:36 AM
> 
> > -----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.
> 

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.

I thought the following commit (https://cgit.freedesktop.org/ModemManager/ModemManager/commit/src/mm-port-serial.c?id=bb9e9a92a325b955ee839565618f13a2a0bf4cf0) might fix the issue, but it seems to still present itself with the following messages:
modem-broadband[ttyACM0]: failed to connect modem: Could not open serial device ttyACM0: it has been forced close
Couldn't refresh signal quality: 'Cannot run sequence: 'Could not open serial device ttyACM0: it has been forced close''

Does anyone have any suggestions of where to look in the source code for where this issue may be occurring?

Best regards,
Matthew Starr