<div dir="ltr"> <div class="gmail_extra"> <div class="gmail_quote">On Fri, Aug 18, 2017 at 12:08 PM, Aleksander Morgado <<a href="mailto:aleksander@aleksander.es" target="_blank">aleksander@aleksander.es</a>> wrote: <blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div class="gmail-HOEnZb"><div class="gmail-h5">>> > 2017-08-17T20:04:<a href="tel:35.193998-07" value="+13519399807">35.193998-07</a>:00 DEBUG ModemManager[26503]: <debug> >> > Removing >> > device '/sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3' >> >> Yes, this is definitely the issue here, looks like we're getting a >> "removed" udev event for the usb device AFTER we got the "add" event >> for the "cdc-wdm" port, or a least that is how I interpret it. So, >> when we got the cdc-wdm port we create a MMDevice and start probing >> it, and we track it in the internal tables; then we get the usb >> removal event and we end up removing that new MMDevice from the >> tracking table, and then we get the add event for wwan0 and we end up >> creating yet another MMDevice for that one. None of the MMDevices end >> up creating a modem because both lack something (the first one lacks >> the net port, the second one lacks the control port). >> >> Could you update mm-base-manager.c:device_removed() to log the subsys >> and name of all events received? that will give us more info. >> >> The logic that does that MMDevice removal is documented like this: >> >> /* This case is designed to handle the case where, at least with >> kernel 2.6.31, unplugging >> * an in-use ttyACMx device results in udev generating remove >> events for the usb, but the >> * ttyACMx device (subsystem tty) is not removed, since it was >> in-use. So if we have not >> * found a modem for the port (above), we're going to look here to >> see if we have a modem >> * associated with the newly removed device. If so, we'll remove >> the modem, since the >> * device has been removed. That way, if the device is reinserted >> later, we'll go through >> * the process of exporting it. >> */ >> >> That means that if we get a remove event for the parent USB device and >> there is still a MMDevice around, we remove the MMDevice. This is a >> special case. >> The normal flow is to get remove events per-port and when the last >> port is removed, we remove the empty MMDevice. >> >> From my point of view, the order of events received from udev isn't >> the expected one, and we should confirm that. Actually, it may very >> well just be that the removal event we get isn't a removal event for >> the whole USB device, and it's just the removal event for the "usb0" >> interface, which for some reason isn't flagged as "net" subsystem and >> it's flagged as "usb" subsystem... Again, printing subsys/name in that >> method will give us more details. >> >> > > It looks like when the USB configuration is switch from 2 to 3. The udev > events of the removal of interfaces associated with config 2 and the > addition of interfaces associated with config 3 could be interleaved. Here's > an example that the removal event of 1-3:2.2 and 1-3:2.4 are issued after > the addition of 1-3:3.0/usbmisc/cdc-wdm0 but before the addition of > 1-3:3.0/net/wwan0. All of them are associated with the same device > "/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3". > > > UDEV [60231.057732] add > /devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3/1-3:3.0/usbmisc/cdc-wdm0 > (usbmisc) > ACTION=add > DEVNAME=/dev/cdc-wdm0 > DEVPATH=/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3/1-3:3.0/usbmisc/cdc-wdm0 > ID_MM_CANDIDATE=1 > ID_MM_DEVICE_IS_MODEM=1 > MAJOR=180 > MINOR=176 > SEQNUM=2029 > SUBSYSTEM=usbmisc > USEC_INITIALIZED=60231057407 > > UDEV [60231.060390] remove > /devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3/1-3:2.2 (usb) > ACTION=remove > DEVPATH=/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3/1-3:2.2 > DEVTYPE=usb_interface > ID_USB_CLASS_FROM_DATABASE=Miscellaneous Device > ID_USB_PROTOCOL_FROM_DATABASE=Interface Association > INTERFACE=255/5/16 > MODALIAS=usb:v12D1p15BBd0001dcEFdsc02dp01icFFisc05ip10in02 > PRODUCT=12d1/15bb/1 > SEQNUM=2023 > SUBSYSTEM=usb > TYPE=239/2/1 > USEC_INITIALIZED=60231049203 > </div></div>Here's the problem. We're taking the usb_interface DEVTYPE removal event as if it were a full usb_device removal event. The special codeblock that does the full device removal should make sure we're not removing just a usb_interface. </blockquote><div> </div><div>I can prepare a patch to do additional checks in this special code block.</div><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> But now I wonder, maybe we could just remove the whole block? Is there any case nowadays were we don't get port event removals? If this was a hack for a bug in kernel 2.6.31, maybe we could consider it already obsoleted? </blockquote><div> </div><div> </div><div>Yeah, this comes from an old commit 53af144f49b0d81bd4dc1f5ee9eea6d61ccae992 (udev: handle removal of parent usb devices) dated back to 2009, which seems to imply that the kernel doesn't remove the tty when the usb device is removed. I guess it's probably not hard to reproduce the steps, but I'm not sure if the original fix was related to a particular kernel version or a particular devices or a combination of both. </div><div> </div><div> </div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"> <div class="gmail-HOEnZb"><div class="gmail-h5"> > UDEV [60231.061816] remove > /devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3/1-3:2.4 (usb) > ACTION=remove > DEVPATH=/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3/1-3:2.4 > DEVTYPE=usb_interface > ID_USB_CLASS_FROM_DATABASE=Miscellaneous Device > ID_USB_PROTOCOL_FROM_DATABASE=Interface Association > INTERFACE=255/5/18 > MODALIAS=usb:v12D1p15BBd0001dcEFdsc02dp01icFFisc05ip12in04 > PRODUCT=12d1/15bb/1 > SEQNUM=2025 > SUBSYSTEM=usb > TYPE=239/2/1 > USEC_INITIALIZED=60231053657 > > UDEV [60231.065329] add > /devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3/1-3:3.0/net/wwan0 (net) > ACTION=add > DEVPATH=/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3/1-3:3.0/net/wwan0 > DEVTYPE=wwan > ID_BUS=usb > ID_MM_CANDIDATE=1 > ID_MODEL=HUAWEI_Mobile_Broadband_Module > ID_MODEL_ENC=HUAWEI\x20Mobile\x20Broadband\x20Module > ID_MODEL_ID=15bb > ID_NET_DRIVER=cdc_mbim > ID_NET_NAME_MAC=wwx5ae7c1ec981c > ID_PATH=platform-xhci-hcd.0.auto-usb-0:3:3.0 > ID_PATH_TAG=platform-xhci-hcd_0_auto-usb-0_3_3_0 > ID_REVISION=0001 > ID_SERIAL=Huawei_Technologies_Co.__Ltd._HUAWEI_Mobile_Broadband_Module > ID_TYPE=generic > ID_USB_CLASS_FROM_DATABASE=Miscellaneous Device > ID_USB_DRIVER=cdc_mbim > ID_USB_INTERFACES=:ff0512:ff0513:ff0510:ff0516:ff0514:020d00:0a0000:020e00:0a0002: > ID_USB_INTERFACE_NUM=00 > ID_USB_PROTOCOL_FROM_DATABASE=Interface Association > ID_VENDOR=Huawei_Technologies_Co.__Ltd. > ID_VENDOR_ENC=Huawei\x20Technologies\x20Co.\x2c\x20Ltd. > ID_VENDOR_ID=12d1 > IFINDEX=42 > INTERFACE=wwan0 > SEQNUM=2030 > SUBSYSTEM=net > USEC_INITIALIZED=60231063661 > > > > >> >> >> > 2017-08-17T20:04:35.196198-07:00 DEBUG ModemManager[26503]: <debug> >> > (net/wwan0): adding device at sysfs path: >> > >> > /sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3/1-3:3.0/net/wwan0 >> > >> > # wwan0 should be considered as an additional port of the same device, >> > but >> > considered the first port.. perhaps related to the device removal above >> > >> > 2017-08-17T20:04:35.197025-07:00 DEBUG ModemManager[26503]: <debug> >> > (net/wwan0): first port in device >> > /sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3 >> > >> > # The following error also looks kind of weird >> > >> > 2017-08-17T20:04:35.197660-07:00 INFO ModemManager[26503]: <info> >> > Couldn't >> > check support for device >> > '/sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3': Device >> > support >> > check task already available for device >> > '/sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3' >> > >> > 2017-08-17T20:04:35.199626-07:00 DEBUG ModemManager[26503]: <debug> >> > (net/usb0): adding device at sysfs path: >> > /sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3/1-3:2.0/net/usb0 >> > 2017-08-17T20:04:35.200104-07:00 DEBUG ModemManager[26503]: <debug> >> > (net/usb0): first port in device >> > /sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3 >> > 2017-08-17T20:04:35.200446-07:00 DEBUG ModemManager[26503]: <debug> >> > (net/usb0) could not get vendor/product id >> > 2017-08-17T20:04:35.200540-07:00 DEBUG ModemManager[26503]: <debug> >> > (net/usb0) could not get vendor/product id >> > 2017-08-17T20:04:35.200912-07:00 INFO ModemManager[26503]: <info> >> > Couldn't >> > check support for device >> > '/sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3': Device >> > support >> > check task already available for device >> > '/sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3' >> > 2017-08-17T20:04:36.694918-07:00 DEBUG ModemManager[26503]: <debug> >> > [plugin >> > manager] task 2: min wait time elapsed >> > 2017-08-17T20:04:36.694963-07:00 DEBUG ModemManager[26503]: <debug> >> > (Novatel >> > LTE) [cdc-wdm0] filtered by subsystem >> > 2017-08-17T20:04:36.694993-07:00 DEBUG ModemManager[26503]: <debug> >> > (Telit) >> > [cdc-wdm0] filtered by vendor/product IDs >> > 2017-08-17T20:04:36.695019-07:00 DEBUG ModemManager[26503]: <debug> >> > (Samsung) [cdc-wdm0] filtered by subsystem >> > 2017-08-17T20:04:36.695045-07:00 DEBUG ModemManager[26503]: <debug> >> > (ZTE) >> > [cdc-wdm0] filtered by vendor/product IDs >> > 2017-08-17T20:04:36.695069-07:00 DEBUG ModemManager[26503]: <debug> >> > (Longcheer) [cdc-wdm0] filtered by subsystem >> > 2017-08-17T20:04:36.695094-07:00 DEBUG ModemManager[26503]: <debug> >> > (Altair >> > LTE) [cdc-wdm0] filtered by subsystem >> > 2017-08-17T20:04:36.695128-07:00 DEBUG ModemManager[26503]: <debug> >> > [plugin >> > manager] task 2,cdc-wdm0: found '2' plugins to try >> > 2017-08-17T20:04:36.695151-07:00 DEBUG ModemManager[26503]: <debug> >> > [plugin >> > manager] task 2,cdc-wdm0: will try with plugin 'Huawei' >> > 2017-08-17T20:04:36.695174-07:00 DEBUG ModemManager[26503]: <debug> >> > [plugin >> > manager] task 2,cdc-wdm0: will try with plugin 'Generic' >> > 2017-08-17T20:04:36.695216-07:00 DEBUG ModemManager[26503]: <debug> >> > [plugin >> > manager) task 2,cdc-wdm0: started >> > 2017-08-17T20:04:36.695867-07:00 DEBUG ModemManager[26503]: <debug> >> > [plugin >> > manager] task 2,cdc-wdm0: checking with plugin 'Huawei' >> > 2017-08-17T20:04:36.696037-07:00 DEBUG ModemManager[26503]: <debug> >> > (Huawei) >> > [cdc-wdm0] probe required: 'mbim' >> > 2017-08-17T20:04:36.696086-07:00 DEBUG ModemManager[26503]: <debug> >> > (usbmisc/cdc-wdm0) launching port probing: 'mbim' >> > 2017-08-17T20:04:36.696142-07:00 DEBUG ModemManager[26503]: <debug> >> > (usbmisc/cdc-wdm0) probing MBIM... >> > 2017-08-17T20:04:36.697733-07:00 DEBUG ModemManager[26503]: opening >> > device... >> > 2017-08-17T20:04:36.698239-07:00 DEBUG ModemManager[26503]: cannot >> > connect >> > to proxy: Could not connect: Connection refused >> > 2017-08-17T20:04:36.698275-07:00 DEBUG ModemManager[26503]: spawning new >> > mbim-proxy (try 1)... >> > 2017-08-17T20:04:36.807686-07:00 DEBUG ModemManager[26503]: >> > [/dev/cdc-wdm0] >> > Read max control message size from descriptors file: 1024 >> > 2017-08-17T20:04:36.808578-07:00 DEBUG ModemManager[26503]: >> > [/dev/cdc-wdm0] >> > Sent message...#012<<<<<< RAW:#012<<<<<< length = 88#012<<<<<< data >> > = >> > >> > 03:00:00:00:58:00:00:00:01:00:00:00:01:00:00:00:00:00:00:00:83:8C:F7:FB:8D:0D:4D:7F:87:1E:D7:1D:BE:FB:B3:9B:01:00:00:00:01:00:00:00:28:00:00:00:0C:00:00:00:1A:00:00:00:1E:00:00:00:2F:00:64:00:65:00:76:00:2F:00:63:00:64:00:63:00:2D:00:77:00:64:00:6D:00:30:00:00:00 >> > 2017-08-17T20:04:36.809129-07:00 DEBUG ModemManager[26503]: >> > [/dev/cdc-wdm0] >> > Sent message (translated)...#012<<<<<< Header:#012<<<<<< length = >> > 88#012<<<<<< type = command (0x00000003)#012<<<<<< >> > transaction = >> > 1#012<<<<<< Fragment header:#012<<<<<< total = 1#012<<<<<< current >> > = >> > 0#012<<<<<< Contents:#012<<<<<< service = 'proxy-control' >> > (838cf7fb-8d0d-4d7f-871e-d71dbefbb39b)#012<<<<<< cid = >> > 'configuration' >> > (0x00000001)#012<<<<<< type = 'set' (0x00000001) >> > 2017-08-17T20:04:37.027805-07:00 DEBUG ModemManager[26503]: >> > [/dev/cdc-wdm0] >> > Received message...#012>>>>>> RAW:#012>>>>>> length = 48#012>>>>>> >> > data >> > = >> > >> > 03:00:00:80:30:00:00:00:01:00:00:00:01:00:00:00:00:00:00:00:83:8C:F7:FB:8D:0D:4D:7F:87:1E:D7:1D:BE:FB:B3:9B:01:00:00:00:00:00:00:00:00:00:00:00 >> > 2017-08-17T20:04:37.027952-07:00 DEBUG ModemManager[26503]: >> > [/dev/cdc-wdm0] >> > Received message (translated)...#012>>>>>> Header:#012>>>>>> length >> > = >> > 48#012>>>>>> type = command-done (0x80000003)#012>>>>>> >> > transaction = 1#012>>>>>> Fragment header:#012>>>>>> total = >> > 1#012>>>>>> >> > current = 0#012>>>>>> Contents:#012>>>>>> status error = 'None' >> > (0x00000000)#012>>>>>> service = 'proxy-control' >> > (838cf7fb-8d0d-4d7f-871e-d71dbefbb39b)#012>>>>>> cid = >> > 'configuration' (0x00000001) >> > 2017-08-17T20:04:37.028108-07:00 DEBUG ModemManager[26503]: >> > [/dev/cdc-wdm0] >> > Sent message...#012<<<<<< RAW:#012<<<<<< length = 16#012<<<<<< data >> > = >> > 01:00:00:00:10:00:00:00:02:00:00:00:00:04:00:00 >> > 2017-08-17T20:04:37.028178-07:00 DEBUG ModemManager[26503]: >> > [/dev/cdc-wdm0] >> > Sent message (translated)...#012<<<<<< Header:#012<<<<<< length = >> > 16#012<<<<<< type = open (0x00000001)#012<<<<<< transaction = >> > 2#012<<<<<< Contents:#012<<<<<< max_control_transfer = 1024 >> > 2017-08-17T20:04:37.029093-07:00 DEBUG ModemManager[26503]: >> > [/dev/cdc-wdm0] >> > Received message...#012>>>>>> RAW:#012>>>>>> length = 16#012>>>>>> >> > data >> > = 01:00:00:80:10:00:00:00:02:00:00:00:00:00:00:00 >> > 2017-08-17T20:04:37.029324-07:00 DEBUG ModemManager[26503]: <debug> >> > (usbmisc/cdc-wdm0) port is MBIM-capable >> > 2017-08-17T20:04:37.029426-07:00 DEBUG ModemManager[26503]: >> > [/dev/cdc-wdm0] >> > Sent message...#012<<<<<< RAW:#012<<<<<< length = 12#012<<<<<< data >> > = >> > 02:00:00:00:0C:00:00:00:03:00:00:00 >> > 2017-08-17T20:04:37.029492-07:00 DEBUG ModemManager[26503]: >> > [/dev/cdc-wdm0] >> > Sent message (translated)...#012<<<<<< Header:#012<<<<<< length = >> > 12#012<<<<<< type = close (0x00000002)#012<<<<<< transaction >> > = 3 >> > 2017-08-17T20:04:37.030365-07:00 DEBUG ModemManager[26503]: >> > [/dev/cdc-wdm0] >> > Received message...#012>>>>>> RAW:#012>>>>>> length = 16#012>>>>>> >> > data >> > = 02:00:00:80:10:00:00:00:03:00:00:00:00:00:00:00 >> > 2017-08-17T20:04:37.030483-07:00 DEBUG ModemManager[26503]: >> > [/dev/cdc-wdm0] >> > channel destroyed >> > 2017-08-17T20:04:37.030891-07:00 DEBUG ModemManager[26503]: <debug> >> > [plugin >> > manager] task 2,cdc-wdm0: found best plugin for port (Huawei) >> > 2017-08-17T20:04:37.030961-07:00 DEBUG ModemManager[26503]: <debug> >> > [plugin >> > manager] task 2,cdc-wdm0: finished in '1.838009' seconds >> > 2017-08-17T20:04:37.031016-07:00 DEBUG ModemManager[26503]: <debug> >> > [plugin >> > manager] task 2,cdc-wdm0: found best plugin: Huawei >> > 2017-08-17T20:04:37.031066-07:00 DEBUG ModemManager[26503]: <debug> >> > [plugin >> > manager] task 2: no more ports to probe >> > 2017-08-17T20:04:37.031115-07:00 DEBUG ModemManager[26503]: <debug> >> > [plugin >> > manager] task 2: finished in '1.838466' seconds >> > 2017-08-17T20:04:37.031244-07:00 INFO ModemManager[26503]: <info> >> > [device >> > /sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3] creating modem >> > with >> > plugin 'Huawei' and '1' ports >> > 2017-08-17T20:04:37.031338-07:00 DEBUG ModemManager[26503]: <debug> >> > MBIM-powered Huawei modem found... >> > 2017-08-17T20:04:37.037442-07:00 DEBUG ModemManager[26503]: <debug> >> > (usbmisc/cdc-wdm0) Port will have AT flags 'none' >> > 2017-08-17T20:04:37.037618-07:00 DEBUG ModemManager[26503]: <debug> >> > (cdc-wdm0) type 'mbim' claimed by >> > /sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3 >> > 2017-08-17T20:04:37.037892-07:00 DEBUG ModemManager[26503]: <debug> >> > Modem >> > (Huawei) '/sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3' >> > completely disposed >> > >> > # Seems like wwan0 wasn't probed along with cdc-wdm0, so no net port was >> > found >> > >> > 2017-08-17T20:04:37.037971-07:00 WARNING ModemManager[26503]: <warn> >> > Couldn't create modem for device >> > '/sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3': Failed to >> > find a >> > net port in the MBIM modem >> > >> >> >> >> -- >> Aleksander >> <a href="https://aleksander.es" rel="noreferrer" target="_blank">https://aleksander.es</a> > > </div></div>-- Aleksander <a href="https://aleksander.es" rel="noreferrer" target="_blank">https://aleksander.es</a> </blockquote></div> </div></div>