Re: cdc-wdm: unable to connect after suspend

[Florian Klink <flokli@flokli.de>]

[-- Attachment #1.1: Type: text/plain, Size: 6261 bytes --]

Am 10.06.2014 16:08, schrieb Florian Klink:
> Am 10.06.2014 14:09, schrieb BjÞrn Mork:
>> Florian Klink <flokli@flokli.de> writes:
>>
>>> Hi,
>>>
>>> I recently bought a notebook (Fujitsu Lifebook T904) with integrated
>>> 3G/4G modem (Sierra Wireless EM7305) thats powered by the cdc-wdm driver.
>>>
>>> It works without any problems on a fresh bootup using Networkmanager.
>>>
>>> However, after putting the notebook into standby and waking up again,
>>> I'm unable to get a connection (always reproducible, not signal quality
>>> related).
>>
>> Does it work again if you restart NetworkManager and ModemManager at
>> this point?
> 
> Nope. ModemManager gets confused completely and drops the modem out of
> the list of connections:
> 
> ModemManager[3067]: <warn>  Couldn't find support for device at
> '/sys/devices/pci0000:00/0000:00:19.0': not supported by any plugin
> ModemManager[3067]: <warn>  Couldn't find support for device at
> '/sys/devices/pci0000:00/0000:00:1c.3/0000:03:00.0': not supported by
> any plugin
> ModemManager[3067]: [/dev/cdc-wdm1] Queried max control message size: 4096
> ModemManager[3067]: [/dev/cdc-wdm1] No transaction matched in received
> message
> ModemManager[3067]: [/dev/cdc-wdm1] No transaction matched in received
> message
> ModemManager[3067]: [/dev/cdc-wdm1] No transaction matched in received
> message
> ModemManager[3067]: [/dev/cdc-wdm1] No transaction matched in received
> message
> ModemManager[3067]: [/dev/cdc-wdm1] No transaction matched in received
> message
> ModemManager[3067]: [/dev/cdc-wdm1] No transaction matched in received
> message
> ModemManager[3067]: [/dev/cdc-wdm1] No transaction matched in received
> message
> ModemManager[3067]: [/dev/cdc-wdm1] No transaction matched in received
> message
> ModemManager[3067]: [/dev/cdc-wdm1] No transaction matched in received
> message
> ModemManager[3067]: [/dev/cdc-wdm1] No transaction matched in received
> message
> ModemManager[3067]: <info>  Creating modem with plugin 'Generic' and '2'
> ports
> ModemManager[3067]: <warn>  Could not grab port (usbmisc/cdc-wdm1):
> 'Cannot add port 'usbmisc/cdc-wdm1', unsupported'
> ModemManager[3067]: <warn>  Couldn't create modem for device at
> '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6': Failed to find primary
> AT port
> ModemManager[3067]: <info>  Creating modem with plugin 'Generic' and '1'
> ports
> ModemManager[3067]: <warn>  Could not grab port (tty/ttyS0): 'Cannot add
> port 'tty/ttyS0', unhandled serial type'
> ModemManager[3067]: <warn>  Couldn't create modem for device at
> '/sys/devices/pci0000:00/0000:00:16.3': Failed to find primary AT port
> 
>>
>> Does it help to do
>>
>>  echo  0 >/sys/bus/usb/devices/x-y/power/persist
>>
>> prior to suspending the notebook?  You'll have to replace "x-y" with the
>> correct USB bus and port number.  You can find this in e.g. the dmesg
>> output.  For example, if your log shows:
>>
>>   qmi_wwan 2-4:1.8: cdc-wdm0: USB WDM device
>>
>> then x-y = 2-4.
> 
> dmesg shows "cdc_mbim 1-6:2.12: cdc-wdm1: USB WDM device", so I did echo
> 0 > /sys/bus/usb/devices/1-6/power/persist.
> 
> However, after a suspend/resume cycle, connecting didnt work either.
> Errors were the same as without persist = 0.
> 
>>
>>
>>> I see the following error messages:
>>>
>>>
>>> Couldn't reload current power state: Transaction timed out
>>> [/dev/cdc-wdm1] No transaction matched in received message
>>> <warn> (cdc-wdm1) failed to connect modem: Transaction timed out
>>> <info> (cdc-wdm1): device state change: prepare -> failed (reason
>>> 'unknown') [40 120 1]
>>> modem_prepare_result: assertion 'state == NM_DEVICE_STATE_PREPARE' failed
>>>
>>>
>>> It looks like a driver bug for me, like the device not woken up
>>> correctly. I attached the syslog.
>>
>> It is certainly bad interaction between userspace and the driver.  We'll
>> have to fight about where the bug is :-)
>>
>> I believe the problem is that the modem is powered down when the
>> notebook is suspended, combined with the "USB device persistence"
>> feature and bad handling of "unexpected" states in ModemManager.
>> The result is that MM and the device/driver ends up with different views
>> of the current modem state. But I might be completely wrong here.
>> Seeing kernel logs would have helped.
> 
> dmesg doesn't really show an error message from the modem. Seems like it
> also has an issue resuming "Bus 001 Device 006: ID 0483:91d1
> STMicroelectronics", but this shouldn't cause the problems with the modem...

I attached the dmesg output, probably there's till something interesting
inside ;-)
> .
>>
>> Initially I'd like to claim that this is a userspace problem.  But I'm
>> open to reconsider that view, given convincing arguments. It's not my
>> intention to reject this as "someone elses problem".
>>
>> A short explanation of what's going on: The "USB device persistence"
>> feature just cannot work with 3G/LTE modem devices because they lose
>> necessary internal state on any power loss.  The persist feature makes
>> the modem reappear as exact the same device after resume, but with a
>> case of severe amnesia.  So why don't we just disable the feature when
>> it cannot work? The reason is that modems often are composite devices,
>> and many of them include card reader functions. USB device persistences
>> is critical for such devices. Consider suspending a card reader with a
>> mounted file system...
>>
>> For this reason I really do not want to disable the persist feature,
>> even if it is pointless from a standalone modem point of view.  Instead
>> userspace should be able to cope with modems "suddendly" entering
>> unexpected states.
>>
>>> I'm running Arch Linux amd64 with an 3.15.0-rc8 kernel, and
>>> NetworkManager 0.9.8.10.
>>>
>>> Is there anybody else who observed this behaviour?
>>
>> Yes, I must admit I've seen similar behaviour.  The interaction between
>> system suspend and drivers/MM/NM is not good.
>>
>> Could you please bring this up on the ModemManager list?
> 
> I added modemmanager-devel to CC as suggested :-)
>>
>>
>> Bjørn
>>
> Florian
> 
> 
> 
> 
> 
> 


[-- Attachment #1.2: cdc-wdm_dmesg.txt --]
[-- Type: text/plain, Size: 11119 bytes --]

[  260.792757] PM: Syncing filesystems ... done.
[  260.802407] PM: Preparing system for mem sleep
[  260.802669] Freezing user space processes ... (elapsed 0.272 seconds) done.
[  261.074849] Freezing remaining freezable tasks ... (elapsed 0.001 seconds) done.
[  261.075996] PM: Entering mem sleep
[  261.076084] Suspending console(s) (use no_console_suspend to debug)
[  261.076458] sd 0:0:0:0: [sda] Synchronizing SCSI cache
[  261.077394] sd 0:0:0:0: [sda] Stopping disk
[  261.306570] PM: suspend of devices complete after 230.462 msecs
[  261.319899] PM: late suspend of devices complete after 13.331 msecs
[  261.320808] xhci_hcd 0000:00:14.0: System wakeup enabled by ACPI
[  261.333439] PM: noirq suspend of devices complete after 13.541 msecs
[  261.333813] ACPI: Preparing to enter system sleep state S3
[  261.334192] PM: Saving platform NVS memory
[  261.335170] Disabling non-boot CPUs ...
[  261.335210] intel_pstate CPU 1 exiting
[  261.336402] kvm: disabling virtualization on CPU1
[  261.436483] smpboot: CPU 1 is now offline
[  261.436770] intel_pstate CPU 2 exiting
[  261.437926] kvm: disabling virtualization on CPU2
[  261.539788] smpboot: CPU 2 is now offline
[  261.540083] intel_pstate CPU 3 exiting
[  261.541403] kvm: disabling virtualization on CPU3
[  261.643088] smpboot: CPU 3 is now offline
[  261.645894] ACPI: Low-level resume complete
[  261.645959] PM: Restoring platform NVS memory
[  261.646552] Enabling non-boot CPUs ...
[  261.646588] x86: Booting SMP configuration:
[  261.646589] smpboot: Booting Node 0 Processor 1 APIC 0x1
[  261.658866] kvm: enabling virtualization on CPU1
[  261.661080] Intel pstate controlling: cpu 1
[  261.661136] CPU1 is up
[  261.661153] smpboot: Booting Node 0 Processor 2 APIC 0x2
[  261.673229] kvm: enabling virtualization on CPU2
[  261.675385] Intel pstate controlling: cpu 2
[  261.675432] CPU2 is up
[  261.675445] smpboot: Booting Node 0 Processor 3 APIC 0x3
[  261.687462] kvm: enabling virtualization on CPU3
[  261.689684] Intel pstate controlling: cpu 3
[  261.689731] CPU3 is up
[  261.693932] ACPI: Waking up from system sleep state S3
[  261.710391] xhci_hcd 0000:00:14.0: System wakeup disabled by ACPI
[  261.710484] PM: noirq resume of devices complete after 11.794 msecs
[  261.710711] PM: early resume of devices complete after 0.205 msecs
[  261.710817] snd_hda_intel 0000:00:03.0: irq 61 for MSI/MSI-X
[  261.711031] mei_me 0000:00:16.0: irq 62 for MSI/MSI-X
[  261.711155] snd_hda_intel 0000:00:1b.0: irq 63 for MSI/MSI-X
[  261.722633] sd 0:0:0:0: [sda] Starting disk
[  261.815946] tpm_tis 00:08: TPM is disabled/deactivated (0x7)
[  262.025752] e1000e 0000:00:19.0: irq 66 for MSI/MSI-X
[  262.215995] usb 1-7: reset full-speed USB device number 5 using xhci_hcd
[  262.216060] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 4.
[  262.216062] usb 1-7: hub failed to enable device, error -22
[  262.375750] usb 1-7: reset full-speed USB device number 5 using xhci_hcd
[  262.375831] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 4.
[  262.375832] usb 1-7: hub failed to enable device, error -22
[  262.535692] usb 1-7: reset full-speed USB device number 5 using xhci_hcd
[  262.549700] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff880037940000
[  262.549701] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff880037940048
[  262.549702] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff880037940090
[  262.549703] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff880211151780
[  262.549704] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff8802111517c8
[  262.709160] usb 1-5: reset high-speed USB device number 4 using xhci_hcd
[  262.709238] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 3.
[  262.709240] usb 1-5: hub failed to enable device, error -22
[  262.868948] usb 1-5: reset high-speed USB device number 4 using xhci_hcd
[  262.869047] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 3.
[  262.869061] usb 1-5: hub failed to enable device, error -22
[  263.028875] usb 1-5: reset high-speed USB device number 4 using xhci_hcd
[  263.042861] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff8802115eaa20
[  263.185459] [drm] Enabling RC6 states: RC6 on, RC6p off, RC6pp off
[  263.202259] usb 1-4: reset full-speed USB device number 3 using xhci_hcd
[  263.202266] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 2.
[  263.202266] usb 1-4: hub failed to enable device, error -22
[  263.362099] usb 1-4: reset full-speed USB device number 3 using xhci_hcd
[  263.362146] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 2.
[  263.362147] usb 1-4: hub failed to enable device, error -22
[  263.518687] ata1: SATA link up 6.0 Gbps (SStatus 133 SControl 300)
[  263.518973] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[  263.518974] ata1.00: ACPI cmd b1/c1:00:00:00:00:a0 (DEVICE CONFIGURATION OVERLAY) filtered out
[  263.519149] ata1.00: ACPI cmd ef/10:09:00:00:00:b0 (SET FEATURES) succeeded
[  263.520027] ata1.00: ACPI cmd f5/00:00:00:00:00:a0 (SECURITY FREEZE LOCK) filtered out
[  263.520029] ata1.00: ACPI cmd b1/c1:00:00:00:00:a0 (DEVICE CONFIGURATION OVERLAY) filtered out
[  263.520158] ata1.00: ACPI cmd ef/10:09:00:00:00:b0 (SET FEATURES) succeeded
[  263.520549] ata1.00: configured for UDMA/100
[  263.525319] usb 1-4: reset full-speed USB device number 3 using xhci_hcd
[  263.531955] ahci 0000:00:1f.2: port does not support device sleep
[  263.539471] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff8802115ea960
[  263.539473] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff8802115ea9c0
[  263.698876] usb 1-8: reset full-speed USB device number 6 using xhci_hcd
[  263.698910] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 5.
[  263.698920] usb 1-8: hub failed to enable device, error -22
[  263.858645] usb 1-8: reset full-speed USB device number 6 using xhci_hcd
[  263.858666] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 5.
[  263.858666] usb 1-8: hub failed to enable device, error -22
[  264.018686] usb 1-8: reset full-speed USB device number 6 using xhci_hcd
[  264.032645] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff8802115eaae0
[  264.098984] usb 1-5.1: reset high-speed USB device number 7 using xhci_hcd
[  264.098996] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 6.
[  264.098998] usb 1-5.1: hub failed to enable device, error -22
[  264.165488] usb 1-5.1: reset high-speed USB device number 7 using xhci_hcd
[  264.165505] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 6.
[  264.165507] usb 1-5.1: hub failed to enable device, error -22
[  264.232145] usb 1-5.1: reset high-speed USB device number 7 using xhci_hcd
[  264.312289] usb 1-5.3: reset full-speed USB device number 9 using xhci_hcd
[  264.312305] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 8.
[  264.312306] usb 1-5.3: hub failed to enable device, error -22
[  264.320021] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff8802115eaa80
[  264.378667] usb 1-5.3: reset full-speed USB device number 9 using xhci_hcd
[  264.378681] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 8.
[  264.378683] usb 1-5.3: hub failed to enable device, error -22
[  264.445417] usb 1-5.3: reset full-speed USB device number 9 using xhci_hcd
[  264.459207] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff8802115eade0
[  264.459226] usb 1-5.3: ep 0x81 - rounding interval to 1024 microframes, ep desc says 2040 microframes
[  264.525621] usb 1-5.2: reset full-speed USB device number 8 using xhci_hcd
[  264.525644] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 7.
[  264.525647] usb 1-5.2: hub failed to enable device, error -22
[  264.591958] usb 1-5.2: reset full-speed USB device number 8 using xhci_hcd
[  264.591973] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 7.
[  264.591975] usb 1-5.2: hub failed to enable device, error -22
[  264.658604] usb 1-5.2: reset full-speed USB device number 8 using xhci_hcd
[  264.672682] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff88021171be00
[  264.672685] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff88021171be48
[  264.672687] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff88021171be90
[  264.672689] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff88021171bed8
[  264.738669] usb 1-5.3.2: reset full-speed USB device number 10 using xhci_hcd
[  264.738689] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 9.
[  264.738692] usb 1-5.3.2: hub failed to enable device, error -22
[  264.805057] usb 1-5.3.2: reset full-speed USB device number 10 using xhci_hcd
[  264.805077] xhci_hcd 0000:00:14.0: Setup ERROR: setup context command for slot 9.
[  264.805081] usb 1-5.3.2: hub failed to enable device, error -22
[  264.871685] usb 1-5.3.2: reset full-speed USB device number 10 using xhci_hcd
[  264.885578] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff880037940390
[  264.885581] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff880037940348
[  264.885584] xhci_hcd 0000:00:14.0: xHCI xhci_drop_endpoint called with disabled ep ffff880037940300
[  264.885607] usb 1-5.3.2: ep 0x81 - rounding interval to 1024 microframes, ep desc says 2040 microframes
[  264.886405] PM: resume of devices complete after 3176.834 msecs
[  264.887529] PM: Finishing wakeup.
[  264.887531] Restarting tasks ... done.
[  264.894184] video LNXVIDEO:00: Restoring backlight state
[  264.899913] Bluetooth: hci0: read Intel version: 370710018002030d00
[  264.901309] Bluetooth: hci0: Intel Bluetooth firmware file: intel/ibt-hw-37.7.10-fw-1.80.2.3.d.bseq
[  265.004901] e1000e 0000:00:19.0: irq 66 for MSI/MSI-X
[  265.008951] Bluetooth: hci0: Intel Bluetooth firmware patch completed and activated
[  265.108097] e1000e 0000:00:19.0: irq 66 for MSI/MSI-X
[  265.108218] IPv6: ADDRCONF(NETDEV_UP): enp0s25: link is not ready
[  265.108957] IPv6: ADDRCONF(NETDEV_UP): br0: link is not ready
[  366.046593] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
[  366.046830] iwlwifi 0000:03:00.0: L1 Enabled; Disabling L0S
[  366.058024] IPv6: ADDRCONF(NETDEV_UP): wlp3s0: link is not ready
[  369.847867] wlp3s0: authenticate with xx:xx:xx:xx:xx:xx
[  369.850057] wlp3s0: send auth to yy:yy:yy:yy:yy:yy (try 1/3)
[  369.851829] wlp3s0: authenticated
[  369.852933] wlp3s0: associate with yy:yy:yy:yy:yy:yy (try 1/3)
[  369.862472] wlp3s0: RX AssocResp from xx:xx:xx:xx:xx:xx (capab=0x431 status=0 aid=59)
[  369.866686] wlp3s0: associated
[  369.866706] IPv6: ADDRCONF(NETDEV_CHANGE): wlp3s0: link becomes ready

[-- Attachment #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 819 bytes --]