On Fri, Aug 18, 2017 at 3:43 AM, Aleksander Morgado < [email protected]> wrote:
> Hey, > > > > > I'm looking into an issue with MM (built with udev) occasionally failing > to > > find the net port when doing the initial probing of a MBIM modem. Have > you > > seen something similar before? > > > > Thanks, > > Ben > > > > ### > > > > > > 2017-08-17T20:04:35.062308-07:00 INFO kernel: [ 4903.471298] usb 1-3: > new > > high-speed USB device number 14 using xhci-hcd > > 2017-08-17T20:04:35.082205-07:00 INFO kernel: [ 4903.495755] usb 1-3: > New > > USB device found, idVendor=12d1, idProduct=15bb > > 2017-08-17T20:04:35.082235-07:00 INFO kernel: [ 4903.495768] usb 1-3: > New > > USB device strings: Mfr=6, Product=5, SerialNumber=0 > > 2017-08-17T20:04:35.082242-07:00 INFO kernel: [ 4903.495776] usb 1-3: > > Product: HUAWEI Mobile Broadband Module > > 2017-08-17T20:04:35.082247-07:00 INFO kernel: [ 4903.495783] usb 1-3: > > Manufacturer: Huawei Technologies Co., Ltd. > > 2017-08-17T20:04:35.092179-07:00 INFO kernel: [ 4903.503156] usb 1-3: > > MAC-Address: xx:xx:xx:xx:xx:xx > > 2017-08-17T20:04:35.092208-07:00 INFO kernel: [ 4903.503542] cdc_ncm > 1-3:2.0 > > usb0: register 'cdc_ncm' at usb-xhci-hcd.0.auto-3, CDC NCM, > > xx:xx:xx:xx:xx:xx > > 2017-08-17T20:04:35.102279-07:00 INFO kernel: [ 4903.516219] cdc_ncm > 1-3:2.0 > > usb0: unregister 'cdc_ncm' usb-xhci-hcd.0.auto-3, CDC NCM > > > > # Switching from USB configuration 2 (NCM) -> USB configuration 3 (MBIM) > ... > > net/usb0 is removed and then net/wwan0 is added > > > > 2017-08-17T20:04:35.162402-07:00 INFO kernel: [ 4903.573001] cdc_mbim > > 1-3:3.0: cdc-wdm0: USB WDM device > > 2017-08-17T20:04:35.162432-07:00 INFO kernel: [ 4903.574327] cdc_mbim > > 1-3:3.0 wwan0: register 'cdc_mbim' at usb-xhci-hcd.0.auto-3, CDC MBIM, > > xx:xx:xx:xx:xx:xx > > 2017-08-17T20:04:35.191646-07:00 DEBUG ModemManager[26503]: <debug> > > (usbmisc/cdc-wdm0): adding device at sysfs path: > > /sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3/ > 1-3:3.0/usbmisc/cdc-wdm0 > > > > # cdc-wdm is considered the first port of > > /sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3 > > > > 2017-08-17T20:04:35.192518-07:00 DEBUG ModemManager[26503]: <debug> > > (usbmisc/cdc-wdm0): first port in device > > /sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3 > > 2017-08-17T20:04:35.192628-07:00 DEBUG ModemManager[26503]: <debug> > [plugin > > manager] task 2: new support task for device: > > /sys/devices/soc0/70090000.usb/xhci-hcd.0.auto/usb1/1-3 > > 2017-08-17T20:04:35.192895-07:00 DEBUG ModemManager[26503]: <debug> > [plugin > > manager] task 2: port grabbed: cdc-wdm0 > > 2017-08-17T20:04:35.192916-07:00 DEBUG ModemManager[26503]: <debug> > [plugin > > manager] task 2,cdc-wdm0: new support task for port > > 2017-08-17T20:04:35.192930-07:00 DEBUG ModemManager[26503]: <debug> > [plugin > > manager) task 2,cdc-wdm0: deferred until min wait time elapsed > > > > # This device removal looks suspicious ... I'm guessing it's related to > > net/usb0 > > > > 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 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 >
_______________________________________________ ModemManager-devel mailing list [email protected] https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
