<div dir="ltr"><div>I think I figured out why the `forced close` issue is happening to me! Short answer: network interface renaming. </div><div> </div><div><div>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).</div><div> </div></div><div>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. </div><div> </div><div>==== modem reset caused zombie modem ===</div> [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 <div> [8627]: <debug> [1700034569.147825] [modem0] completely disposed</div><div> </div><div>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.</div><div> </div><div>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. </div><div> </div><div>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 { ~</div><div> </div><div><div>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. </div><div> </div><div>Thanks for the support, </div><div>Jessy Diamond Exum </div><div> </div></div></div> <div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Tue, Nov 14, 2023 at 5:12 PM Jessy Exum <<a href="mailto:jessy.diamondman@gmail.com" target="_blank">jessy.diamondman@gmail.com</a>> wrote: </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div>This message was first sent November 1st, but something went wrong and I was asked to re-send it. </div><div> </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> 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: <div> </div>[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). ===================== =================================================================================== <div>====== ⠀⠀⠀⠀⠀⠀⠀⠀⢀⡠⠖⠊⠉⠉⠉⠉⢉⠝⠉⠓⠦⣄ =========</div><div>====== ⠀⠀⠀⠀⠀⠀⢀⡴⣋⠀⠀⣤⣒⡠⢀⠀⠐⠂⠀⠤⠤⠈⠓⢦⡀ ========</div><div></div>======⠀⠀ ⠀⠀⠀⣰⢋⢬⠀⡄⣀⠤⠄⠀⠓⢧⠐⠥⢃⣴⠤⣤⠀⢀⡙⣆ =========== ====== ⠀⠀⠀⠀⢠⡣⢨⠁⡘⠉⠀⢀⣤⡀⠀⢸⠀⢀⡏⠑⠢⣈⠦⠃⠦⡘⡆⠀⠀⠀ ========== ======⠀⠀ ⠀⠀⢸⡠⠊⠀⣇⠀⠀⢿⣿⠇⠀⡼⠀⢸⡀⠠⣶⡎⠳⣸⡠⠃⡇⠀⠀⠀ ========== ====== ⢀⠔⠒⠢⢜⡆⡆⠀⢿⢦⣤⠖⠒⢂⣽⢁⢀⠸⣿⣦⡀⢀⡼⠁⠀⠀⡇⠒⠑⡆ =========== ====== ⡇⠀⠐⠰⢦⠱⡤⠀⠈⠑⠪⢭⠩⠕⢁⣾⢸⣧⠙⡯⣿⠏⠠⡌⠁⡼⢣⠁⡜⠁ ========== ====== ⠈⠉⠻⡜⠚⢀⡏⠢⢆⠀⠀⢠⡆⠀⠀⣀⣀⣀⡀⠀⠀⠀⠀⣼⠾⢬⣹⡾⠀⠀ ========== ======⠀ ⠀⠀⠉⠀⠉⠀⠀⠈⣇⠀⠀⠀⣴⡟⢣⣀⡔⡭⣳⡈⠃⣼⠀⠀⠀⣼⣧⠀⠀ ========== ======⠀⠀⠀⠀⠀⠀⠀⠀ ⠀⢹⠀⠀⣸⣿⣿⣿⡿⣷⣿⣿⣷⠀⡇⠀⠀⠀⠙⠊⠀⠀ ========= ======⠀⠀⠀⠀⠀⠀⠀⠀ ⠀⢸⣠⠀⢻⠛⠭⢏⣑⣛⣙⣛⠏⠀⡇⠀⠀⠀⠀⠀⠀⠀ ========= ======⠀⠀⠀⠀⠀⠀⠀⠀⠀⠀ ⡏⠠⠜⠓⠉⠉⠀⠐⢒⡒⡍⠐⡇⠀⠀⠀⠀⠀⠀⠀ ========= ======⠀⠀⠀⠀⠀⠀⠀ ⠀⠀⠀⠙⠒⠢⠤⣀⣀⣀⣀⣘⠧⠤⠞⠁⠀ ========= =================================================================================== ====== 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' <div>[23573]: <info> [1697275311.060367] [base-manager] port usb0 released by device '/sys/devices/platform/soc/3100000.usb3/xhci-hcd.2.auto/usb5/5-1'</div><div>[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</div><div></div><div> </div><div> </div><div> </div><div>The full log file is attached.</div><div> </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). </div> <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> <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: </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">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 </blockquote></div></div> </blockquote></div>