On Fri, Aug 18, 2017 at 12:08 PM, Aleksander Morgado < [email protected]> wrote:
> >> > 2017-08-17T20:04:35.193998-07: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 > > > > 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. > I can prepare a patch to do additional checks in this special code block. > > 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? > 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. > > > > 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 > >> https://aleksander.es > > > > > > > > -- > Aleksander > https://aleksander.es >
_______________________________________________ ModemManager-devel mailing list [email protected] https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
