How to recover from serial device being force closed.
Jessy Exum
jessy.diamondman at gmail.com
Wed Nov 15 11:00:49 UTC 2023
I think I figured out why the `forced close` issue is happening to me!
Short answer: network interface renaming.
In my application, I use ModemManager to connect the modem, and then I
rename the network interface to a special name that is required by another
part of my system (and change the name back if the modem disconnects).
I added some additional logging to ModemManager's hardware detection code
and was watching the udev events as the modem was rebooted (comparing when
the modem is properly torn down and when it is not). I noticed that when a
network device is removed (like the CDC interfaces on the modem) the
interface's current name is listed in the remove event (which makes sense),
but ModemManager does not update the name of the network interfaces
internally, so when a remove uevent comes through with the renamed
interface name, ModemManager does not realize it is one of the port that is
associated with the modem. And because in this situation there is always
one 'port' on the modem (even though it has actually been removed), the
modem is not disposed of.
==== modem reset caused zombie modem ===
[8627]: <debug> [1700034180.178810] [ttyACM1/at] unexpected port hangup!
[8627]: <debug> [1700034180.178885] [ttyACM1/at] forced to close port
[8627]: <debug> [1700034180.178923] [ttyACM1/at] device open count is 0
(close)
[8627]: <debug> [1700034180.178969] [ttyACM1/at] closing serial port...
[8627]: <debug> [1700034180.183019] [ttyACM1/at] serial port closed
[8627]: <warn> [1700034180.183358] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(remove) "tty", "ttyACM0"
[8627]: <warn> [1700034180.183411] [base-manager] EXTRALOG
MMBaseManager::device_removed("tty", "ttyACM0"
[8627]: <info> [1700034180.183468] [base-manager] port ttyACM0 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[8627]: <warn> [1700034180.185135] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(remove) "tty", "ttyACM1"
[8627]: <warn> [1700034180.185214] [base-manager] EXTRALOG
MMBaseManager::device_removed("tty", "ttyACM1"
[8627]: <info> [1700034180.185271] [base-manager] port ttyACM1 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[8627]: <warn> [1700034180.190975] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(remove) "tty", "ttyACM2"
[8627]: <warn> [1700034180.191056] [base-manager] EXTRALOG
MMBaseManager::device_removed("tty", "ttyACM2"
[8627]: <info> [1700034180.191111] [base-manager] port ttyACM2 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[8627]: <warn> [1700034180.193025] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(remove) "tty", "ttyACM4"
[8627]: <warn> [1700034180.193099] [base-manager] EXTRALOG
MMBaseManager::device_removed("tty", "ttyACM4"
[8627]: <info> [1700034180.193150] [base-manager] port ttyACM4 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[8627]: <warn> [1700034180.197629] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(remove) "tty", "ttyACM3"
[8627]: <warn> [1700034180.197713] [base-manager] EXTRALOG
MMBaseManager::device_removed("tty", "ttyACM3"
[8627]: <info> [1700034180.197768] [base-manager] port ttyACM3 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[8627]: <warn> [1700034180.224472] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(remove) "net", "cell_cdc"
[8627]: <warn> [1700034180.224667] [base-manager] EXTRALOG
MMBaseManager::device_removed("net", "cell_cdc"
[8627]: <warn> [1700034180.253334] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(remove) "net", "usb1"
[8627]: <warn> [1700034180.253410] [base-manager] EXTRALOG
MMBaseManager::device_removed("net", "usb1"
[8627]: <info> [1700034180.253462] [base-manager] port usb1 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
=== modem boot ==
[8627]: <warn> [1700034187.060079] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(add) "tty", "ttyACM1"
[8627]: <debug> [1700034187.060497] [ttyACM1] port contents loaded (EXTRALOG
DEVICE UDEV):
[8627]: <debug> [1700034187.060540] [ttyACM1] bus: usb
[8627]: <debug> [1700034187.060594] [ttyACM1] interface:
/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1/5-1:1.2
[8627]: <debug> [1700034187.060631] [ttyACM1] device:
/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1
[8627]: <debug> [1700034187.060667] [ttyACM1] driver: cdc_acm
[8627]: <debug> [1700034187.060700] [ttyACM1] vendor: 1e2d
[8627]: <debug> [1700034187.060733] [ttyACM1] product: 0061
[8627]: <debug> [1700034187.060767] [ttyACM1] revision: 0232
[8627]: <warn> [1700034187.060802] [base-manager] EXTRALOG
MMBaseManager::device_added("ttyACM1", 1, 0)
[8627]: <debug> [1700034187.060841] [base-manager] adding port ttyACM1 at
sysfs path:
/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1/5-1:1.2/tty/ttyACM1
[8627]: <debug> [1700034187.060978] [filter] (tty/ttyACM1) port allowed:
device is allowlisted by plugin (vid)
[8627]: <debug> [1700034187.061032] [base-manager] additional port ttyACM1
in device /sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1
[8627]: <warn> [1700034187.135987] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(add) "net", "usb1"
[8627]: <debug> [1700034187.136429] [usb1] port contents loaded (EXTRALOG
DEVICE UDEV):
[8627]: <debug> [1700034187.136471] [usb1] bus: usb
[8627]: <debug> [1700034187.136504] [usb1] interface:
/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1/5-1:1.12
[8627]: <debug> [1700034187.136538] [usb1] device:
/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1
[8627]: <debug> [1700034187.136586] [usb1] driver: cdc_ether
[8627]: <debug> [1700034187.136618] [usb1] vendor: 1e2d
[8627]: <debug> [1700034187.136649] [usb1] product: 0061
[8627]: <debug> [1700034187.136680] [usb1] revision: 0232
[8627]: <warn> [1700034187.136714] [base-manager] EXTRALOG
MMBaseManager::device_added("usb1", 1, 0)
[8627]: <debug> [1700034187.136751] [base-manager] adding port usb1 at
sysfs path:
/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1/5-1:1.12/net/usb1
[8627]: <debug> [1700034187.136881] [filter] (net/usb1) port allowed:
device is allowlisted by plugin (vid)
=== modem reset again ===
[8627]: <warn> [1700034569.075509] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(remove) "tty", "ttyACM2"
[8627]: <warn> [1700034569.075598] [base-manager] EXTRALOG
MMBaseManager::device_removed("tty", "ttyACM2"
[8627]: <info> [1700034569.075662] [base-manager] port ttyACM2 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[8627]: <warn> [1700034569.078437] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(remove) "tty", "ttyACM1"
[8627]: <warn> [1700034569.078520] [base-manager] EXTRALOG
MMBaseManager::device_removed("tty", "ttyACM1"
[8627]: <info> [1700034569.078579] [base-manager] port ttyACM1 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[8627]: <warn> [1700034569.080608] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(remove) "tty", "ttyACM3"
[8627]: <warn> [1700034569.080687] [base-manager] EXTRALOG
MMBaseManager::device_removed("tty", "ttyACM3"
[8627]: <info> [1700034569.080743] [base-manager] port ttyACM3 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[8627]: <warn> [1700034569.083641] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(remove) "tty", "ttyACM0"
[8627]: <warn> [1700034569.083723] [base-manager] EXTRALOG
MMBaseManager::device_removed("tty", "ttyACM0"
[8627]: <info> [1700034569.083773] [base-manager] port ttyACM0 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[8627]: <warn> [1700034569.089682] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(remove) "tty", "ttyACM4"
[8627]: <warn> [1700034569.089767] [base-manager] EXTRALOG
MMBaseManager::device_removed("tty", "ttyACM4"
[8627]: <info> [1700034569.089817] [base-manager] port ttyACM4 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[8627]: <warn> [1700034569.117972] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(remove) "net", "usb0"
[8627]: <warn> [1700034569.118050] [base-manager] EXTRALOG
MMBaseManager::device_removed("net", "usb0"
[8627]: <info> [1700034569.118102] [base-manager] port usb0 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[8627]: <warn> [1700034569.144932] [base-manager] EXTRALOG
MMBaseManager::handle_uevent(remove) "net", "usb1"
[8627]: <warn> [1700034569.145007] [base-manager] EXTRALOG
MMBaseManager::device_removed("net", "usb1"
[8627]: <info> [1700034569.145058] [base-manager] port usb1 released by
device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[8627]: <debug> [1700034569.145197] [base-manager] removing empty device
'/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'
[8627]: <debug> [1700034569.145752] [device
/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1] unexported
modem from path '/org/freedesktop/ModemManager1/Modem/0'
[8627]: <debug> [1700034569.145816] [modem0] releasing serial ports context
for SIM hot swap
[8627]: <debug> [1700034569.146738] [modem0] cleaning up port
'tty/ttyACM1'...
[8627]: <debug> [1700034569.146800] [modem0] cleaning up port
'unknown/ttyACM3'...
[8627]: <debug> [1700034569.146838] [modem0] cleaning up port
'tty/ttyACM0'...
[8627]: <debug> [1700034569.146882] [modem0] cleaning up port 'net/usb1'...
[8627]: <debug> [1700034569.146918] [modem0] cleaning up port
'tty/ttyACM2'...
[8627]: <debug> [1700034569.146951] [modem0] cleaning up port
'unknown/ttyACM4'...
[8627]: <debug> [1700034569.146986] [modem0] cleaning up port 'net/usb0'...
[8627]: <debug> [1700034569.147364] [ttyACM0/at] forced to close port
[8627]: <debug> [1700034569.147561] [modem0/ttyACM2/gps] forced to close
port
[8627]: <debug> [1700034569.147825] [modem0] completely disposed
I can try to alter my application to not rename the interface, but I think
it would be more reliable to have ModemManager track change events and
change out the port.
Here is a preview of a patch for my attempt to have ModemManager handle
moving the network interfaces. It has some unnecessary logging and does not
yet comply with the ModemManager style, but hopefully there is enough here
for someone to let me know if I am on the right track. This patch handles
`move` uevents by removing the old device and then adding the new name.
diff --git a/src/mm-base-manager.c b/src/mm-base-manager.c
index 13c4fe26..fe2b934c 100644
--- a/src/mm-base-manager.c
+++ b/src/mm-base-manager.c
@@ -491,18 +506,56 @@ handle_uevent (MMBaseManager *self,
if (!subsystem || !name)
return;
- if (g_str_equal (action, "add") || g_str_equal (action, "move")
|| g_str_equal (action, "change")) {
- g_autoptr(MMKernelDevice) kernel_device = NULL;
-
- kernel_device = mm_kernel_device_udev_new (self->priv->udev,
device);
- device_added (self, kernel_device, TRUE, FALSE);
- return;
- }
-
if (g_str_equal (action, "remove")) {
device_removed (self, subsystem, name);
return;
}
+
+ if (g_str_equal (subsystem, "net") && g_str_equal (action, "move")) {
+ const gchar *property_devpath_old = NULL;
+ const gchar *property_interface = NULL;
+ gchar **parts = NULL;
+ gchar *last_part = NULL;
+ gchar **iter = NULL;
+ g_autoptr(MMKernelDevice) kernel_device = NULL;
+
+ property_devpath_old = g_udev_device_get_property (device,
"DEVPATH_OLD");
+ property_interface = g_udev_device_get_property (device,
"INTERFACE");
+ mm_obj_warn (self, "EXTRALOG MOVE EVENT; OLD_PATH: %s; INTERFACE:
%s; name: %s",
+ property_devpath_old,
+ property_interface,
+ name);
+ if ((property_devpath_old == NULL) || (property_interface == NULL))
+ return;
+
+ // Find the last non-empty part
+ parts = g_strsplit(property_devpath_old, "/", -1);
+ for (iter = parts; *iter != NULL; ++iter) {
+ if (**iter != '\0') {
+ last_part = *iter;
+ }
+ }
+
+ g_printf("Result: %s\n", last_part);
+ if (last_part != NULL) {
+ device_removed (self, subsystem, last_part);
+ }
+
+ // Free the memory allocated by g_strsplit
+ g_strfreev(parts);
+
+ kernel_device = mm_kernel_device_udev_new (self->priv->udev,
device);
+ device_added (self, kernel_device, TRUE, FALSE);
+ return;
+ }
+
+ if (g_str_equal (action, "add") || g_str_equal (action, "move") ||
g_str_equal (action, "change")) {
+ g_autoptr(MMKernelDevice) kernel_device = NULL;
+
+ kernel_device = mm_kernel_device_udev_new (self->priv->udev,
device);
+ device_added (self, kernel_device, TRUE, FALSE);
+ return;
+ }
}
typedef struct {
~
This change seems to prevent the `forced close` error for me (I have not
done thorough testing yet), but it does not update the network interface
name in mmcli. I do not think my patch is valid until it updates the
interface names everywhere. I do not know the best way to do this, and I
welcome any input even if it is to say this is a bad idea.
Thanks for the support,
Jessy Diamond Exum
On Tue, Nov 14, 2023 at 5:12 PM Jessy Exum <jessy.diamondman at gmail.com>
wrote:
> 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/f178fa10/attachment-0001.htm>
More information about the ModemManager-devel
mailing list