Issue with finding net port for a MBIM modem

Fri Aug 18 10:43:04 UTC 2017

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.

> 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