How to recover from serial device being force closed.
Jessy Exum
jessy.diamondman at gmail.com
Wed Nov 15 01:13:04 UTC 2023
This message was first sent November 1st, but something went wrong and I
was asked to re-send it.
Hello again ModemManager developers, I finally come with logs that show
this 'forced close' issue appearing on version 1.20.6 with full --debug
logging!
There have been several odd situations that devices have gotten stuck in
where the modem could not be reconnected, or the modem was labeled as
connected but all AT commands fail. I was able to trace several of these
seemingly unrelated problems to the serial connection to the modem being
marked as 'forced close'. Sometimes when this happens, the modem itself has
crashed and needs a hard reset. But most of the time (that I have seen),
the modem will still respond to AT commands if you send them directly down
the serial device or if you restart ModemManager, In this state, any AT
command that is sent from ModemManager will receive this error:
GDBus.Error:org.freedesktop.ModemManager1.Error.Core.Connected: Cannot
run sequence: 'Could not open serial device ttyACM1: it has been forced
close'
When a Modem in ModemManager is stuck in this 'forced close' state, there
is no way to communicate with the modem until the modem is removed from
ModemManager and re-added (it may be able to work if it were reloaded like
when a SIM card is inserted or removed, but in this state we will not be
able to receive notifications about SIM events because the AT channel is
down), or by restarting ModemManager (which technically tears down the
MMModem objects). A 'soft reset' is not an option when the AT channels are
down, and even weirder (as we will see) this appears to be triggered by
removing the modem and ModemManager somehow failing to respond to udev
events or otherwise not processing them correctly (that is my guess).
This problem is very inconsistent in weird ways. Of thousands of devices,
some never encounter the problem, some see it only once, some see it every
few months, and some see them consistently in a customer's hands but not at
all when sent in for testing. It was quite difficult to trigger this
problem with verbose debugging, let alone to get something that misbehaved
consistently so it could be studied.
But luckily, I recently added the ability to hard reset the modem (using
GPIOs) to every device that uses ModemManager, and experimenting with that
helped us locate a device in the testbed that consistently exhibited this
problem when the modem was hard reset. What is strange is that when you let
the modem come up normally and then do a hard reset, the Modem is not
removed in ModemManager, but ModemManager still detects the serial lines
have been forced closed (because of the device removal). When the modem
comes back up, ModemManager appears to notice the new modem, but thinks it
is the first modem that should have been destroyed so ModemManager re-adds
the ports to the same MMModem. The modem in ModemManager will stay in this
state until a hard reset is done again, in which case ModemManager will
correctly detect the modem has been removed, clean up the old modem, and
when the modem comes back up ModemManager will reinitialize the modem and
resume communication. Remember that this device behaving like this
consistently is an anomaly, and most devices only seem to fall into this
state very rarely.
Also note that we use eudev. I also upgraded eudev and libgudev to the
versions that come with yocto kirkstone, but the issue still happened in
each case (but the frequency/pattern of the failures was a bit different
than before the upgrade).
Here are the log highlights:
[23573]: <debug> [1697275284.571998] [ttyACM1/at] <-- '<CR><LF>^SMONI:
4G,900,2,10,10,FDD,001,01,0001,1A2D001,1,-150,-98,-6,1,CONN,1<CR><LF><CR><LF>OK<CR><LF>'
[23573]: <debug> [1697275284.572479] [ttyACM1/at] device open count is 2
(close)
[23573]: <debug> [1697275286.069421] [ttyACM1/at] device open count is 3
(open)
[23573]: <debug> [1697275286.069546] [ttyACM1/at] --> 'AT^SMONI<CR>'
=================== Modem reset is triggered by `reset_modem 0`
========================
========= at this point in time, ModemManager realizes something is wrong.
=============
[23573]: <debug> [1697275286.255622] [ttyACM1/at] unexpected port hangup!
[23573]: <debug> [1697275286.255698] [ttyACM1/at] forced to close port
[23573]: <debug> [1697275286.255732] [ttyACM1/at] device open count is 0
(close)
[23573]: <debug> [1697275286.255779] [ttyACM1/at] closing serial port...
[23573]: <debug> [1697275286.258383] [ttyACM1/at] serial port closed
[23573]: <warn> [1697275286.258564] [modem0] couldn't reload extended
signal information: Serial port is now closed
[23573]: <info> [1697275286.262682] [base-manager] port ttyACM0 released
by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[23573]: <info> [1697275286.269022] [base-manager] port ttyACM4 released
by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[23573]: <info> [1697275286.270508] [base-manager] port ttyACM3 released
by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[23573]: <info> [1697275286.270765] [base-manager] port ttyACM2 released
by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[23573]: <info> [1697275286.288052] [base-manager] port ttyACM1 released
by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[23573]: <info> [1697275286.352196] [base-manager] port usb1 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
============== At this point, I believe the modem has been detected by
============
========== udev, and udev has told ModemManager about the 'new' device.
===========
[23573]: <debug> [1697275293.112972] [ttyACM0] port contents loaded:
[23573]: <debug> [1697275293.113037] [ttyACM0] bus: usb
[23573]: <debug> [1697275293.113072] [ttyACM0] interface:
/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1/5-1:1.0
[23573]: <debug> [1697275293.113107] [ttyACM0] device:
/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1
[23573]: <debug> [1697275293.113141] [ttyACM0] driver: cdc_acm
[23573]: <debug> [1697275293.113175] [ttyACM0] vendor: 1e2d
[23573]: <debug> [1697275293.113206] [ttyACM0] product: 0061
[23573]: <debug> [1697275293.113239] [ttyACM0] revision: 0232
[23573]: <debug> [1697275293.113273] [base-manager] adding port ttyACM0 at
sysfs path:
/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1/5-1:1.0/tty/ttyACM0
[23573]: <debug> [1697275293.113400] [filter] (tty/ttyACM0) port allowed:
device is allowlisted by plugin (vid)
[...... Repeated structure for other 'ports' ......]
[23573]: <debug> [1697275293.540659] [base-manager] adding port usb0 at
sysfs path:
/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1/5-1:1.10/net/usb0
[23573]: <debug> [1697275293.540788] [filter] (net/usb0) port allowed:
device is allowlisted by plugin (vid)
[23573]: <debug> [1697275293.540879] [base-manager] port usb0 already added
=========== The Modem has become a "ZOMBIE MODEM", and will stick around
==========
====================== until a reset can clear it (or never).
=====================
===================================================================================
====== ⠀⠀⠀⠀⠀⠀⠀⠀⢀⡠⠖⠊⠉⠉⠉⠉⢉⠝⠉⠓⠦⣄ =========
====== ⠀⠀⠀⠀⠀⠀⢀⡴⣋⠀⠀⣤⣒⡠⢀⠀⠐⠂⠀⠤⠤⠈⠓⢦⡀ ========
======⠀⠀ ⠀⠀⠀⣰⢋⢬⠀⡄⣀⠤⠄⠀⠓⢧⠐⠥⢃⣴⠤⣤⠀⢀⡙⣆ ===========
====== ⠀⠀⠀⠀⢠⡣⢨⠁⡘⠉⠀⢀⣤⡀⠀⢸⠀⢀⡏⠑⠢⣈⠦⠃⠦⡘⡆⠀⠀⠀ ==========
======⠀⠀ ⠀⠀⢸⡠⠊⠀⣇⠀⠀⢿⣿⠇⠀⡼⠀⢸⡀⠠⣶⡎⠳⣸⡠⠃⡇⠀⠀⠀ ==========
====== ⢀⠔⠒⠢⢜⡆⡆⠀⢿⢦⣤⠖⠒⢂⣽⢁⢀⠸⣿⣦⡀⢀⡼⠁⠀⠀⡇⠒⠑⡆ ===========
====== ⡇⠀⠐⠰⢦⠱⡤⠀⠈⠑⠪⢭⠩⠕⢁⣾⢸⣧⠙⡯⣿⠏⠠⡌⠁⡼⢣⠁⡜⠁ ==========
====== ⠈⠉⠻⡜⠚⢀⡏⠢⢆⠀⠀⢠⡆⠀⠀⣀⣀⣀⡀⠀⠀⠀⠀⣼⠾⢬⣹⡾⠀⠀ ==========
======⠀ ⠀⠀⠉⠀⠉⠀⠀⠈⣇⠀⠀⠀⣴⡟⢣⣀⡔⡭⣳⡈⠃⣼⠀⠀⠀⣼⣧⠀⠀ ==========
======⠀⠀⠀⠀⠀⠀⠀⠀ ⠀⢹⠀⠀⣸⣿⣿⣿⡿⣷⣿⣿⣷⠀⡇⠀⠀⠀⠙⠊⠀⠀ =========
======⠀⠀⠀⠀⠀⠀⠀⠀ ⠀⢸⣠⠀⢻⠛⠭⢏⣑⣛⣙⣛⠏⠀⡇⠀⠀⠀⠀⠀⠀⠀ =========
======⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀ ⡏⠠⠜⠓⠉⠉⠀⠐⢒⡒⡍⠐⡇⠀⠀⠀⠀⠀⠀⠀ =========
======⠀⠀⠀⠀⠀⠀⠀ ⠀⠀⠀⠙⠒⠢⠤⣀⣀⣀⣀⣘⠧⠤⠞⠁⠀ =========
===================================================================================
====== ModemManager does not appear to do anything when receiving this
event ======
========== while the zombie modem still stalks these halls (spo~~oky)
=============
==== _/_
========
==== _._ _,-'""`-._ _/_ /~,~\
========
==== (,-.`._,'( |\`-/| /~,~\ \\_//
========
==== `-.-' \ )-`( , o o) \\_// _/_
========
==== `- \`_`"'- /~,~\
========
==== \\_//
========
===================================================================================
======= We then encounter our error =======
[23573]: <warn> [1697275296.068908] [modem0] couldn't reload extended
signal information: Cannot run sequence: 'Could not open serial device
ttyACM1: it has been forced close'
[23573]: <debug> [1697275297.068957] [modem0] loading signal quality...
[23573]: <debug> [1697275297.069153] [modem0] couldn't refresh signal
quality: Cannot run sequence: 'Could not open serial device ttyACM1: it has
been forced close'
[23573]: <debug> [1697275297.069195] [modem0] periodic signal quality and
access technology checks scheduled
[23573]: <warn> [1697275298.070029] [modem0/bearer1] checking if connected
failed: Cannot run sequence: 'Could not open serial device ttyACM1: it has
been forced close'
[23573]: <warn> [1697275303.068878] [modem0/bearer1] checking if connected
failed: Cannot run sequence: 'Could not open serial device ttyACM1: it has
been forced close'
[23573]: <warn> [1697275306.069145] [modem0] couldn't reload extended
signal information: Cannot run sequence: 'Could not open serial device
ttyACM1: it has been forced close'
[23573]: <warn> [1697275308.068776] [modem0/bearer1] checking if connected
failed: Cannot run sequence: 'Could not open serial device ttyACM1: it has
been forced close'
=============== If a reset (soft or hard) correctly clears out the issue,
the Zombie will be defeated =====================
[23573]: <info> [1697275311.022694] [base-manager] port ttyACM0 released
by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[23573]: <info> [1697275311.034934] [base-manager] port ttyACM3 released
by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[23573]: <info> [1697275311.035306] [base-manager] port ttyACM2 released
by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[23573]: <info> [1697275311.035598] [base-manager] port ttyACM4 released
by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[23573]: <info> [1697275311.036694] [base-manager] port ttyACM1 released
by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[23573]: <info> [1697275311.060367] [base-manager] port usb0 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[23573]: <info> [1697275311.096341] [base-manager] port usb1 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[23573]: <debug> [1697275311.096533] [base-manager] removing empty device
'/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[23573]: <debug> [1697275311.097054] [modem0/bearer0] removing from bus
[23573]: <debug> [1697275311.097120] [modem0/bearer1] removing from bus
[23573]: <debug> [1697275311.097172] [device
/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1] unexported
modem from path '/org/freedesktop/ModemManager1/Modem/0'
[23573]: <debug> [1697275311.097224] [modem0] periodic signal checks
disabled
[23573]: <debug> [1697275311.097262] [modem0] releasing serial ports
context for SIM hot swap
[23573]: <debug> [1697275311.098219] [modem0/usb0/net] port now disconnected
[23573]: <debug> [1697275311.098548] [modem0] cleaning up port
'tty/ttyACM1'...
[23573]: <debug> [1697275311.098598] [modem0] cleaning up port
'unknown/ttyACM3'...
[23573]: <debug> [1697275311.098636] [modem0] cleaning up port
'tty/ttyACM0'...
[23573]: <debug> [1697275311.098680] [modem0] cleaning up port 'net/usb1'...
[23573]: <debug> [1697275311.098715] [modem0] cleaning up port
'tty/ttyACM2'...
[23573]: <debug> [1697275311.098750] [modem0] cleaning up port
'unknown/ttyACM4'...
[23573]: <debug> [1697275311.098789] [modem0] cleaning up port 'net/usb0'...
[23573]: <debug> [1697275311.099011] [ttyACM0/at] forced to close port
[23573]: <debug> [1697275311.099213] [modem0/ttyACM2/gps] forced to close
port
[23573]: <debug> [1697275311.099660] [modem0] completely disposed
The full log file is attached.
I am currently working on fixing this issue and am happy to be the one to
code up a fix if the solution is not obvious to the community. Right now I
am digging around in how udev device events are detected/propagated and
other core parts of ModemManager, so any hints or assistance is greatly
appreciated. Even if someone else comes up with the solution, I am able to
provide thorough testing across multiple devices (all with Cinterion PLS8
or PALS9 modems).
I look forward to working with you all so we can help make ModemManager
even better. Happy Halloween!
Jessy Diamond Exum
On Wed, May 3, 2023 at 6:32 AM Aleksander Morgado <aleksandermj at chromium.org>
wrote:
> Hey,
>
> >
> > it would be great if you could verify the behavior on the main branch
> > (at least on the last stable 1.20.6), and give us some logs, so we can
> > have a better idea of the issue and how proceed, whether in a general
> > manner, or with some specific fixes.
> >
>
> Yes, especially since several bugfixes were done that could help solve
> the problem (although not sure if they were done in 1.20 or earlier
> really)
>
> > >
> > > I have encountered an issue while running ModemManager (version
> 1.18.4) on a Cinterion PLAS8 modem. Sometimes, the serial device used for
> AT communication with the modem is force closed (due to G_IO_HUP) without
> any obvious reason.
> > >
>
> Also, are you using NetworkManager along with ModemManager? Or are you
> running pppd yourself? You must ensure that MM only touches the port
> once pppd has exited, otherwise they'll use mismatched CLOCAL flags
> and MM may get a HUP when the modem got disconnected from the network
> (as opposed to getting a HUP only when the port goes away from the
> system)
>
> --
> Aleksander
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20231115/640cee46/attachment.htm>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: zombie.log
Type: text/x-log
Size: 532123 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20231115/640cee46/attachment.bin>
More information about the ModemManager-devel
mailing list