Issue with finding net port for a MBIM modem

Fri Aug 18 18:42:09 UTC 2017

On Fri, Aug 18, 2017 at 3:43 AM, Aleksander Morgado <
aleksander at aleksander.es> 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
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20170818/102eecaa/attachment-0001.html>