<div dir="ltr"><div>This message was first sent November 1st, but something went wrong and I was asked to re-send it.<br></div><div><br></div><div>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! </div><br>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:<span><br><br>     <span style="font-family:monospace">GDBus.Error:org.freedesktop.ModemManager1.Error.Core.Connected: Cannot run sequence: 'Could not open serial device ttyACM1: it has been forced close'</span><br><br></span>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).<br><br>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.<br><br>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.<br><br>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).<br><br>Here are the log highlights:<br><div><br></div><span style="font-family:monospace">[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>'<br>[23573]: <debug> [1697275284.572479] [ttyACM1/at] device open count is 2 (close)<br>[23573]: <debug> [1697275286.069421] [ttyACM1/at] device open count is 3 (open)<br>[23573]: <debug> [1697275286.069546] [ttyACM1/at] --> 'AT^SMONI<CR>'<br><br>=================== Modem reset is triggered by `reset_modem 0` ========================<br>========= at this point in time, ModemManager realizes something is wrong. =============<br><br>[23573]: <debug> [1697275286.255622] [ttyACM1/at] unexpected port hangup!<br>[23573]: <debug> [1697275286.255698] [ttyACM1/at] forced to close port<br>[23573]: <debug> [1697275286.255732] [ttyACM1/at] device open count is 0 (close)<br>[23573]: <debug> [1697275286.255779] [ttyACM1/at] closing serial port...<br>[23573]: <debug> [1697275286.258383] [ttyACM1/at] serial port closed<br>[23573]: <warn>  [1697275286.258564] [modem0] couldn't reload extended signal information: Serial port is now closed<br>[23573]: <info>  [1697275286.262682] [base-manager] port ttyACM0 released by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'<br>[23573]: <info>  [1697275286.269022] [base-manager] port ttyACM4 released by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'<br>[23573]: <info>  [1697275286.270508] [base-manager] port ttyACM3 released by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'<br>[23573]: <info>  [1697275286.270765] [base-manager] port ttyACM2 released by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'<br>[23573]: <info>  [1697275286.288052] [base-manager] port ttyACM1 released by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'<br>[23573]: <info>  [1697275286.352196] [base-manager] port usb1 released by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'<br><br>============== At this point, I believe the modem has been detected by ============<br>========== udev, and udev has told ModemManager about the 'new' device. ===========<br><br>[23573]: <debug> [1697275293.112972] [ttyACM0] port contents loaded:<br>[23573]: <debug> [1697275293.113037] [ttyACM0]   bus: usb<br>[23573]: <debug> [1697275293.113072] [ttyACM0]   interface: /sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1/5-1:1.0<br>[23573]: <debug> [1697275293.113107] [ttyACM0]   device: /sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1<br>[23573]: <debug> [1697275293.113141] [ttyACM0]   driver: cdc_acm<br>[23573]: <debug> [1697275293.113175] [ttyACM0]   vendor: 1e2d<br>[23573]: <debug> [1697275293.113206] [ttyACM0]   product: 0061<br>[23573]: <debug> [1697275293.113239] [ttyACM0]   revision: 0232<br>[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<br>[23573]: <debug> [1697275293.113400] [filter] (tty/ttyACM0) port allowed: device is allowlisted by plugin (vid)<br><br>[...... Repeated structure for other 'ports' ......]<br><br>[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<br>[23573]: <debug> [1697275293.540788] [filter] (net/usb0) port allowed: device is allowlisted by plugin (vid)<br>[23573]: <debug> [1697275293.540879] [base-manager] port usb0 already added<br><br><br>=========== The Modem has become a "ZOMBIE MODEM", and will stick around ==========<br>====================== until a reset can clear it (or never). =====================<br>===================================================================================<br></span><div><span style="font-family:monospace">======                ⠀⠀⠀⠀⠀⠀⠀⠀⢀⡠⠖⠊⠉⠉⠉⠉⢉⠝⠉⠓⠦⣄                       =========</span></div><div><span style="font-family:monospace">======               ⠀⠀⠀⠀⠀⠀⢀⡴⣋⠀⠀⣤⣒⡠⢀⠀⠐⠂⠀⠤⠤⠈⠓⢦⡀                     ========</span></div><div><span style="font-family:monospace"></span></div><span style="font-family:monospace">======⠀⠀               ⠀⠀⠀⣰⢋⢬⠀⡄⣀⠤⠄⠀⠓⢧⠐⠥⢃⣴⠤⣤⠀⢀⡙⣆                ===========<br>======               ⠀⠀⠀⠀⢠⡣⢨⠁⡘⠉⠀⢀⣤⡀⠀⢸⠀⢀⡏⠑⠢⣈⠦⠃⠦⡘⡆⠀⠀⠀             ==========<br>======⠀⠀                ⠀⠀⢸⡠⠊⠀⣇⠀⠀⢿⣿⠇⠀⡼⠀⢸⡀⠠⣶⡎⠳⣸⡠⠃⡇⠀⠀⠀            ==========<br>======               ⢀⠔⠒⠢⢜⡆⡆⠀⢿⢦⣤⠖⠒⢂⣽⢁⢀⠸⣿⣦⡀⢀⡼⠁⠀⠀⡇⠒⠑⡆           ===========<br>======               ⡇⠀⠐⠰⢦⠱⡤⠀⠈⠑⠪⢭⠩⠕⢁⣾⢸⣧⠙⡯⣿⠏⠠⡌⠁⡼⢣⠁⡜⠁           ==========<br>======               ⠈⠉⠻⡜⠚⢀⡏⠢⢆⠀⠀⢠⡆⠀⠀⣀⣀⣀⡀⠀⠀⠀⠀⣼⠾⢬⣹⡾⠀⠀             ==========<br>======⠀               ⠀⠀⠉⠀⠉⠀⠀⠈⣇⠀⠀⠀⣴⡟⢣⣀⡔⡭⣳⡈⠃⣼⠀⠀⠀⣼⣧⠀⠀              ==========<br>======⠀⠀⠀⠀⠀⠀⠀⠀               ⠀⢹⠀⠀⣸⣿⣿⣿⡿⣷⣿⣿⣷⠀⡇⠀⠀⠀⠙⠊⠀⠀               =========<br>======⠀⠀⠀⠀⠀⠀⠀⠀               ⠀⢸⣠⠀⢻⠛⠭⢏⣑⣛⣙⣛⠏⠀⡇⠀⠀⠀⠀⠀⠀⠀               =========<br>======⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀               ⡏⠠⠜⠓⠉⠉⠀⠐⢒⡒⡍⠐⡇⠀⠀⠀⠀⠀⠀⠀               =========<br>======⠀⠀⠀⠀⠀⠀⠀               ⠀⠀⠀⠙⠒⠢⠤⣀⣀⣀⣀⣘⠧⠤⠞⠁⠀                      =========<br>===================================================================================<br>====== ModemManager does not appear to do anything when receiving this event ======<br>========== while the zombie modem still stalks these halls (spo~~oky) =============<br>====                                           _/_                         ========<br>====  _._     _,-'""`-._               _/_    /~,~\                        ========<br>==== (,-.`._,'(       |\`-/|          /~,~\   \\_//                        ========<br>====     `-.-' \ )-`( , o o)          \\_//  _/_                           ========<br>====           `-    \`_`"'-                /~,~\                          ========<br>====                                        \\_//                          ========<br>===================================================================================<br><br>======= We then encounter our error =======<br><br>[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'<br>[23573]: <debug> [1697275297.068957] [modem0] loading signal quality...<br>[23573]:
 <debug> [1697275297.069153] [modem0] couldn't refresh signal 
quality: Cannot run sequence: 'Could not open serial device ttyACM1: it 
has been forced close'<br>[23573]: <debug> [1697275297.069195] [modem0] periodic signal quality and access technology checks scheduled<br>[23573]:
 <warn>  [1697275298.070029] [modem0/bearer1] checking if 
connected failed: Cannot run sequence: 'Could not open serial device 
ttyACM1: it has been forced close'<br>[23573]: <warn> 
 [1697275303.068878] [modem0/bearer1] checking if connected failed: 
Cannot run sequence: 'Could not open serial device ttyACM1: it has been 
forced close'<br>[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'<br>[23573]: 
<warn>  [1697275308.068776] [modem0/bearer1] checking if connected
 failed: Cannot run sequence: 'Could not open serial device ttyACM1: it 
has been forced close'<br><br>=============== If a reset (soft or hard) correctly clears out the issue, the Zombie will be defeated =====================<br><br>[23573]: <info>  [1697275311.022694] [base-manager] port ttyACM0 released by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'<br>[23573]: <info>  [1697275311.034934] [base-manager] port ttyACM3 released by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'<br>[23573]: <info>  [1697275311.035306] [base-manager] port ttyACM2 released by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'<br>[23573]: <info>  [1697275311.035598] [base-manager] port ttyACM4 released by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'<br>[23573]: <info>  [1697275311.036694] [base-manager] port ttyACM1 released by device '/sys/devices/platform/soc/</span><span style="font-family:monospace">3100000.usb3/xhci-hcd.2.auto/</span><span style="font-family:monospace">usb5/5-1'<br></span><div><span style="font-family:monospace">[23573]: <info>  [1697275311.060367] [base-manager] port usb0 released by device '/sys/devices/platform/soc/</span><span style="font-family:monospace">3100000.usb3/xhci-hcd.2.auto/</span><span style="font-family:monospace">usb5/5-1'</span></div><div><span style="font-family:monospace">[23573]: <info>  [1697275311.096341] [base-manager] port usb1 released by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'<br>[23573]: <debug> [1697275311.096533] [base-manager] removing empty device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'<br>[23573]: <debug> [1697275311.097054] [modem0/bearer0] removing from bus<br>[23573]: <debug> [1697275311.097120] [modem0/bearer1] removing from bus<br>[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'<br>[23573]: <debug> [1697275311.097224] [modem0] periodic signal checks disabled<br>[23573]: <debug> [1697275311.097262] [modem0] releasing serial ports context for SIM hot swap<br>[23573]: <debug> [1697275311.098219] [modem0/usb0/net] port now disconnected<br>[23573]: <debug> [1697275311.098548] [modem0] cleaning up port 'tty/ttyACM1'...<br>[23573]: <debug> [1697275311.098598] [modem0] cleaning up port 'unknown/ttyACM3'...<br>[23573]: <debug> [1697275311.098636] [modem0] cleaning up port 'tty/ttyACM0'...<br>[23573]: <debug> [1697275311.098680] [modem0] cleaning up port 'net/usb1'...<br>[23573]: <debug> [1697275311.098715] [modem0] cleaning up port 'tty/ttyACM2'...<br>[23573]: <debug> [1697275311.098750] [modem0] cleaning up port 'unknown/ttyACM4'...<br>[23573]: <debug> [1697275311.098789] [modem0] cleaning up port 'net/usb0'...<br>[23573]: <debug> [1697275311.099011] [ttyACM0/at] forced to close port<br>[23573]: <debug> [1697275311.099213] [modem0/ttyACM2/gps] forced to close port<br>[23573]: <debug> [1697275311.099660] [modem0] completely disposed</span></div><div></div><div><br></div><div><br></div><div><br></div><div>The full log file is attached.</div><div><br></div><div>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).<br></div><br><div>I look forward to working with you all so we can help make ModemManager even better. Happy Halloween!</div><div>Jessy Diamond Exum</div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Wed, May 3, 2023 at 6:32 AM Aleksander Morgado <<a href="mailto:aleksandermj@chromium.org" target="_blank">aleksandermj@chromium.org</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">Hey,<br>
<br>
><br>
> it would be great if you could verify the behavior on the main branch<br>
> (at least on the last stable 1.20.6), and give us some logs, so we can<br>
> have a better idea of the issue and how proceed, whether in a general<br>
> manner, or with some specific fixes.<br>
><br>
<br>
Yes, especially since several bugfixes were done that could help solve<br>
the problem (although not sure if they were done in 1.20 or earlier<br>
really)<br>
<br>
> ><br>
> > 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.<br>
> ><br>
<br>
Also, are you using NetworkManager along with ModemManager? Or are you<br>
running pppd yourself? You must ensure that MM only touches the port<br>
once pppd has exited, otherwise they'll use mismatched CLOCAL flags<br>
and MM may get a HUP when the modem got disconnected from the network<br>
(as opposed to getting a HUP only when the port goes away from the<br>
system)<br>
<br>
-- <br>
Aleksander<br>
</blockquote></div></div>