cdc-wdm: unable to connect after suspend

cdc-wdm: unable to connect after suspend

[Florian Klink]

[-- Attachment #1: Type: text/plain, Size: 1003 bytes --]

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).

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.

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?

Florian

[-- Attachment #2: cdc-wdm_syslog.txt --]
[-- Type: text/plain, Size: 2893 bytes --]

Jun 10 09:44:18 notebook NetworkManager[321]: <info> Activation (cdc-wdm1) starting connection 'FONIC Vorgabe'
Jun 10 09:44:18 notebook NetworkManager[321]: <info> (cdc-wdm1): device state change: disconnected -> prepare (reason 'none') [30 40 0]
Jun 10 09:44:18 notebook NetworkManager[321]: <info> Activation (cdc-wdm1) Stage 1 of 5 (Device Prepare) scheduled...
Jun 10 09:44:18 notebook NetworkManager[321]: <info> Activation (cdc-wdm1) Stage 1 of 5 (Device Prepare) started...
Jun 10 09:44:18 notebook NetworkManager[321]: <info> (cdc-wdm1): device state change: prepare -> need-auth (reason 'none') [40 60 0]
Jun 10 09:44:18 notebook NetworkManager[321]: <info> Activation (cdc-wdm1) Stage 1 of 5 (Device Prepare) complete.
Jun 10 09:44:18 notebook NetworkManager[321]: <info> Activation (cdc-wdm1) Stage 1 of 5 (Device Prepare) scheduled...
Jun 10 09:44:18 notebook NetworkManager[321]: <info> Activation (cdc-wdm1) Stage 1 of 5 (Device Prepare) started...
Jun 10 09:44:18 notebook NetworkManager[321]: <info> (cdc-wdm1): device state change: need-auth -> prepare (reason 'none') [60 40 0]
Jun 10 09:44:18 notebook NetworkManager[321]: <info> Activation (cdc-wdm1) Stage 1 of 5 (Device Prepare) complete.
Jun 10 09:44:18 notebook ModemManager[332]: <info>  Simple connect started...
Jun 10 09:44:18 notebook ModemManager[332]: <info>  Simple connect state (3/8): Enable
Jun 10 09:44:18 notebook ModemManager[332]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disabled -> enabling)
Jun 10 09:44:18 notebook NetworkManager[321]: <info> (cdc-wdm1) modem state changed, 'disabled' --> 'enabling' (reason: user-requested)
Jun 10 09:44:28 notebook ModemManager[332]: Couldn't reload current power state: Transaction timed out
Jun 10 09:44:28 notebook ModemManager[332]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (unknown -> searching)
Jun 10 09:44:51 notebook ModemManager[332]: [/dev/cdc-wdm1] No transaction matched in received message
Jun 10 09:44:58 notebook ModemManager[332]: <info>  Modem /org/freedesktop/ModemManager1/Modem/0: state changed (enabling -> disabled)
Jun 10 09:44:58 notebook NetworkManager[321]: <info> (cdc-wdm1) modem state changed, 'enabling' --> 'disabled' (reason: unknown)
Jun 10 09:44:58 notebook NetworkManager[321]: <warn> (cdc-wdm1) failed to connect modem: Transaction timed out
Jun 10 09:44:58 notebook NetworkManager[321]: <info> (cdc-wdm1): device state change: prepare -> failed (reason 'unknown') [40 120 1]
Jun 10 09:44:58 notebook NetworkManager[321]: <warn> Activation (cdc-wdm1) failed for connection 'FONIC Vorgabe'
Jun 10 09:44:58 notebook NetworkManager[321]: <info> (cdc-wdm1): device state change: failed -> disconnected (reason 'none') [120 30 0]
Jun 10 09:44:58 notebook NetworkManager[321]: <info> (cdc-wdm1): deactivating device (reason 'none') [0]

Re: cdc-wdm: unable to connect after suspend

[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?

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.


> 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..

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?


Bjørn

Re: cdc-wdm: unable to connect after suspend

[Florian Klink]

[-- Attachment #1: Type: text/plain, Size: 5929 bytes --]

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...
.
> 
> 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 #2: OpenPGP digital signature --]
[-- Type: application/pgp-signature, Size: 819 bytes --]

Re: cdc-wdm: unable to connect after suspend

[Florian Klink]

[-- 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 --]

Re: cdc-wdm: unable to connect after suspend

[Bjørn Mork]

Florian Klink <flokli@flokli.de> writes:
> 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

Ah, OK.  Then I obviously guessed wrong.  MM and the firmware does not
agree on the current transaction sequence. I'm not sure why. The modem
is sending unexpected messages, and I assume MM doesn't get the answers
it is looking for.  This could be caused by the driver cancelling the
interrupt URB at an "inconvenient time" for the firmware.  But I haven't
seen issues like that with the Qualcomm based Sierra modems before.

And you get into this state consistently on every suspend+resume? 

It would be useful to know which unexpeced messages we receive (errors?
same message all over? older queued up messages being played back with
unexpected delay?)  Any chance you can enable libmbim + ModemManager
debugging to get the MBIM message dumps?


>>> 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.

Yes, my initial guess was wrong, so this is not the problem.

>> 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 ;-)

Thanks.  I wasn't expecting any errors there (I still don't think there
is any real error here from the drivers point of view), but I wanted to
see whether the modem is disconnected and rediscovered or just plainly
suspended.

But???  I cannot find anything related to the modem device in that log?
Not even anything mentioning the "1-6" USB port.



Bjørn

Re: cdc-wdm: unable to connect after suspend

[Florian Klink]

[-- Attachment #1: Type: text/plain, Size: 5091 bytes --]

Am 11.06.2014 10:01, schrieb Bjørn Mork:
> Florian Klink <flokli@flokli.de> writes:
>> 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
> 
> Ah, OK.  Then I obviously guessed wrong.  MM and the firmware does not
> agree on the current transaction sequence. I'm not sure why. The modem
> is sending unexpected messages, and I assume MM doesn't get the answers
> it is looking for.  This could be caused by the driver cancelling the
> interrupt URB at an "inconvenient time" for the firmware.  But I haven't
> seen issues like that with the Qualcomm based Sierra modems before.
> 
> And you get into this state consistently on every suspend+resume? 
> 
> It would be useful to know which unexpeced messages we receive (errors?
> same message all over? older queued up messages being played back with
> unexpected delay?)  Any chance you can enable libmbim + ModemManager
> debugging to get the MBIM message dumps?

Sure, I can provide the message dumps. Is it as simple as described in
here (http://www.freedesktop.org/wiki/Software/ModemManager/Debugging/),
or do I need to recompile libmbim + ModemManager with some additional (debug)
flags enabled?

> 
> 
>>>> 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.
> 
> Yes, my initial guess was wrong, so this is not the problem.
> 
>>> 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 ;-)
> 
> Thanks.  I wasn't expecting any errors there (I still don't think there
> is any real error here from the drivers point of view), but I wanted to
> see whether the modem is disconnected and rediscovered or just plainly
> suspended.
> 
> But???  I cannot find anything related to the modem device in that log?
> Not even anything mentioning the "1-6" USB port.

I just sent the part of dmesg where the suspend & resume cycle happened.

Of course, I see the device appearing on bootup:

[   11.537522] usb 1-6: new high-speed USB device number 11 using xhci_hcd
[   11.711214] usb 1-6: config 1 has an invalid interface number: 8 but max is 3
[   11.711217] usb 1-6: config 1 has no interface number 1
[   11.711432] usb 1-6: config 2 has an invalid interface number: 12 but max is 1
[   11.711434] usb 1-6: config 2 has an invalid interface number: 13 but max is 1
[   11.711435] usb 1-6: config 2 has an invalid interface number: 13 but max is 1
[   11.711437] usb 1-6: config 2 has no interface number 0
[   11.711439] usb 1-6: config 2 has no interface number 1

[...]

[   14.735330] usbcore: registered new interface driver cdc_ncm
[   14.736046] usbcore: registered new interface driver cdc_wdm
[   14.738273] cdc_mbim 1-6:2.12: cdc-wdm1: USB WDM device
[   14.738459] cdc_mbim 1-6:2.12 wwan0: register 'cdc_mbim' at usb-0000:00:14.0-6, CDC MBIM, 96:ba:xx:xx:xx:xx
[   14.738477] usbcore: registered new interface driver cdc_mbim
[   14.749795] systemd-udevd[248]: renamed network interface wwan0 to wwp0s20u6c2i12

... but you don't get any dmesg output about it during the suspend/resume cycle.

Florian


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

Re: cdc-wdm: unable to connect after suspend

[Aleksander Morgado]

On Wed, Jun 11, 2014 at 12:08 PM, Florian Klink <flokli@flokli.de> wrote:
> Sure, I can provide the message dumps. Is it as simple as described in
> here (http://www.freedesktop.org/wiki/Software/ModemManager/Debugging/),
> or do I need to recompile libmbim + ModemManager with some additional (debug)
> flags enabled?


It's just like that; once you run MM with --debug you'll also get
libmbim debug messages as well, including all transactions going to
and from the modem.

-- 
Aleksander
https://aleksander.es

Re: cdc-wdm: unable to connect after suspend

[Florian Klink]

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

Am 11.06.2014 12:17, schrieb Aleksander Morgado:
> On Wed, Jun 11, 2014 at 12:08 PM, Florian Klink <flokli@flokli.de> wrote:
>> Sure, I can provide the message dumps. Is it as simple as described in
>> here (http://www.freedesktop.org/wiki/Software/ModemManager/Debugging/),
>> or do I need to recompile libmbim + ModemManager with some additional (debug)
>> flags enabled?
> 
> 
> It's just like that; once you run MM with --debug you'll also get
> libmbim debug messages as well, including all transactions going to
> and from the modem.
> 

Nice! There you go, attached the outputs of ModemManager and
NetworkManager started in debug mode.


I wrote all "actions" (start,configure connection,suspend,resumed,
connectiong again) between 4 "="-signs, so you can easily recognize what
happened when.

Hope it sheds some light on the problem :-)


Florian

[-- Attachment #1.2: cdc-wdm_modemmanager_debug.txt.gz --]
[-- Type: application/gzip, Size: 20484 bytes --]

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

Re: cdc-wdm: unable to connect after suspend

[Bjørn Mork]

Florian Klink <flokli@flokli.de> writes:
> Am 11.06.2014 12:17, schrieb Aleksander Morgado:
>> On Wed, Jun 11, 2014 at 12:08 PM, Florian Klink <flokli@flokli.de> wrote:
>>> Sure, I can provide the message dumps. Is it as simple as described in
>>> here (http://www.freedesktop.org/wiki/Software/ModemManager/Debugging/),
>>> or do I need to recompile libmbim + ModemManager with some additional (debug)
>>> flags enabled?
>> 
>> 
>> It's just like that; once you run MM with --debug you'll also get
>> libmbim debug messages as well, including all transactions going to
>> and from the modem.
>> 
>
> Nice! There you go, attached the outputs of ModemManager and
> NetworkManager started in debug mode.
>
>
> I wrote all "actions" (start,configure connection,suspend,resumed,
> connectiong again) between 4 "="-signs, so you can easily recognize what
> happened when.
>
> Hope it sheds some light on the problem :-)

Thanks! Yes, I believe it does.  Or.. at least it confirms that
something strange is going on.  This part of the failed connection
attempt after resume look very odd to me:


ModemManager[1861]: <info>  [1402484694.481304] [mm-iface-modem-simple.c:469] connection_step(): Simple connect state (4/8): Wait to get fully enabled
ModemManager[1861]: <info>  [1402484694.481349] [mm-iface-modem-simple.c:478] connection_step(): Simple connect state (5/8): Register
ModemManager[1861]: <debug> [1402484694.481374] [mm-iface-modem-3gpp.c:395] mm_iface_modem_3gpp_register_in_network(): Launching automatic network registration...
ModemManager[1861]: [/dev/cdc-wdm1] Sent message...
<<<<<< RAW:
<<<<<<   length = 64
<<<<<<   data   = 03:00:00:00:40:00:00:00:17:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:09:00:00:00:01:00:00:00:10:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00:00
ModemManager[1861]: [/dev/cdc-wdm1] Sent message (translated)...
<<<<<< Header:
<<<<<<   length      = 64
<<<<<<   type        = command (0x00000003)
<<<<<<   transaction = 23
<<<<<< Fragment header:
<<<<<<   total   = 1
<<<<<<   current = 0
<<<<<< Contents:
<<<<<<   service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
<<<<<<   cid     = 'register-state' (0x00000009)
<<<<<<   type    = 'set' (0x00000001)
ModemManager[1861]: [/dev/cdc-wdm1] Received message...
>>>>>> RAW:
>>>>>>   length = 116
>>>>>>   data   = 07:00:00:80:74:00:00:00:00:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:09:00:00:00:48:00:00:00:00:00:00:00:03:00:00:00:01:00:00:00:1C:00:00:00:01:00:00:00:30:00:00:00:0A:00:00:00:3C:00:00:00:0A:00:00:00:00:00:00:00:00:00:00:00:02:00:00:00:32:00:36:00:32:00:30:00:37:00:00:00:46:00:4F:00:4E:00:49:00:43:00:00:00
ModemManager[1861]: [/dev/cdc-wdm1] Received message (translated)...
>>>>>> Header:
>>>>>>   length      = 116
>>>>>>   type        = indicate-status (0x80000007)
>>>>>>   transaction = 0
>>>>>> Fragment header:
>>>>>>   total   = 1
>>>>>>   current = 0
>>>>>> Contents:
>>>>>>   service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>>   cid     = 'register-state' (0x00000009)
ModemManager[1861]: <debug> [1402484694.508028] [mm-broadband-modem-mbim.c:1771] device_notification_cb(): Received notification (service 'basic-connect', command 'register-state')
ModemManager[1861]: <info>  [1402484694.508077] [mm-iface-modem-3gpp.c:1152] update_registration_state(): Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (searching -> registering)
ModemManager[1861]: <info>  [1402484694.508133] [mm-iface-modem.c:894] mm_iface_modem_update_access_technologies(): Modem /org/freedesktop/ModemManager1/Modem/0: access technology changed (unknown -> umts, hsdpa, hsupa)
ModemManager[1861]: <info>  [1402484694.508187] [mm-iface-modem-location.c:293] notify_3gpp_location_update(): Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '262', MNC: '7', Location area code: '0', Cell ID: '0')
ModemManager[1861]: <debug> [1402484694.508343] [mm-broadband-modem.c:3476] modem_3gpp_load_subscription_state(): Load subscription state: Marking the SIM as provisioned.
ModemManager[1861]: <info>  [1402484694.508479] [mm-iface-modem-3gpp.c:1077] update_registration_reload_current_registration_info_ready(): Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (registering -> home)
NetworkManager[1862]: <debug> [1402484701.903039] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 3 flags 0x1003
NetworkManager[1862]: <debug> [1402484744.894312] [nm-netlink-monitor.c:164] link_msg_handler(): netlink link message: iface idx 3 flags 0x1003
ModemManager[1861]: <debug> [1402484747.346282] [mm-iface-modem.c:1080] expire_signal_quality(): Signal quality value not updated in 60s, marking as not being recent



Here we send a 'register-state' command which the firmware never replies
to, but instead we get an unsolicited 'register-state' indication
showing that the modem is registered in the home network.  But where did
the reply to the command with transaction id 23 go?  That looks like a
firmware issue to me.  Which we probably just have to work around
somehow...

Then we continue with a 'signal-state' indication (which is expected),
followed by ModemManager concluding that the registration state is
changed to 'idle' and failing due to that:

ModemManager[1861]: [/dev/cdc-wdm1] Received message...
>>>>>> RAW:
>>>>>>   length = 64
>>>>>>   data   = 07:00:00:80:40:00:00:00:00:00:00:00:01:00:00:00:00:00:00:00:A2:89:CC:33:BC:BB:8B:4F:B6:B0:13:3E:C2:AA:E6:DF:0B:00:00:00:14:00:00:00:12:00:00:00:63:00:00:00:05:00:00:00:02:00:00:00:FF:FF:FF:FF
ModemManager[1861]: [/dev/cdc-wdm1] Received message (translated)...
>>>>>> Header:
>>>>>>   length      = 64
>>>>>>   type        = indicate-status (0x80000007)
>>>>>>   transaction = 0
>>>>>> Fragment header:
>>>>>>   total   = 1
>>>>>>   current = 0
>>>>>> Contents:
>>>>>>   service = 'basic-connect' (a289cc33-bcbb-8b4f-b6b0-133ec2aae6df)
>>>>>>   cid     = 'signal-state' (0x0000000b)
ModemManager[1861]: <debug> [1402484754.090164] [mm-broadband-modem-mbim.c:1771] device_notification_cb(): Received notification (service 'basic-connect', command 'signal-state')
ModemManager[1861]: <debug> [1402484754.090172] [mm-broadband-modem-mbim.c:1524] basic_connect_notification_signal_state(): Signal state indication: 18 --> 58%
ModemManager[1861]: <info>  [1402484754.090224] [mm-iface-modem.c:1144] update_signal_quality(): Modem /org/freedesktop/ModemManager1/Modem/0: signal quality updated (58)
ModemManager[1861]: <info>  [1402484754.484416] [mm-iface-modem-3gpp.c:1167] update_registration_state(): Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (home -> idle)
ModemManager[1861]: <info>  [1402484754.484496] [mm-iface-modem-location.c:293] notify_3gpp_location_update(): Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Cell ID: '0')
ModemManager[1861]: <debug> [1402484754.484540] [mm-bearer.c:261] modem_3gpp_registration_state_changed(): Bearer not allowed to connect, not registered in 3GPP network
ModemManager[1861]: <info>  [1402484754.484570] [mm-iface-modem.c:894] mm_iface_modem_update_access_technologies(): Modem /org/freedesktop/ModemManager1/Modem/0: access technology changed (umts, hsdpa, hsupa -> unknown)
NetworkManager[1862]: <warn> (cdc-wdm1) failed to connect modem: Network timeout
NetworkManager[1862]: <info> (cdc-wdm1): device state change: prepare -> failed (reason 'gsm-registration-timeout') [40 120 32]
NetworkManager[1862]: <info> NetworkManager state is now DISCONNECTED
NetworkManager[1862]: <debug> [1402484754.485784] [nm-manager.c:4165] policy_activating_device_changed(): ActivatingConnection now (none)
NetworkManager[1862]: <warn> Activation (cdc-wdm1) failed for connection 'FONIC Vorgabe'
NetworkManager[1862]: <debug> [1402484754.485885] [nm-device.c:5261] nm_device_queue_state(): (cdc-wdm1): queued state change to disconnected (id 431)
NetworkManager[1862]: <debug> [1402484754.486259] [nm-device.c:5219] queued_set_state(): (cdc-wdm1): running queued state change to disconnected (id 431)
NetworkManager[1862]: <info> (cdc-wdm1): device state change: failed -> disconnected (reason 'none') [120 30 0]
NetworkManager[1862]: <info> (cdc-wdm1): deactivating device (reason 'none') [0]
NetworkManager[1862]: <debug> [1402484754.486360] [nm-firewall-manager.c:166] nm_firewall_manager_remove_from_zone(): (cdc-wdm1) firewall zone remove skipped (not running)
NetworkManager[1862]: <debug> [1402484754.486649] [nm-dns-manager.c:995] nm_dns_manager_begin_updates(): (update_routing_and_dns): queueing DNS updates (1)
NetworkManager[1862]: <debug> [1402484754.486718] [nm-dns-manager.c:1013] nm_dns_manager_end_updates(): (nm_dns_manager_end_updates): DNS configuration did not change
NetworkManager[1862]: <debug> [1402484754.486745] [nm-dns-manager.c:1017] nm_dns_manager_end_updates(): (update_routing_and_dns): no DNS changes to commit (0)



But there are no MBIM messages explaining why MM sets the state to
'idle'.  Is this because of the missing reply, Alexander?  Why don't we
just trust the (more current) result from the indication?  We do know
that the modem is registered to the home network here, or?


Bjørn

Re: cdc-wdm: unable to connect after suspend

[Aleksander Morgado]

On Wed, Jun 11, 2014 at 1:53 PM, Bjørn Mork <bjorn@mork.no> wrote:
> ModemManager[1861]: <info>  [1402484754.484416] [mm-iface-modem-3gpp.c:1167] update_registration_state(): Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (home -> idle)
> ModemManager[1861]: <info>  [1402484754.484496] [mm-iface-modem-location.c:293] notify_3gpp_location_update(): Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Cell ID: '0')
> ModemManager[1861]: <debug> [1402484754.484540] [mm-bearer.c:261] modem_3gpp_registration_state_changed(): Bearer not allowed to connect, not registered in 3GPP network
> ModemManager[1861]: <info>  [1402484754.484570] [mm-iface-modem.c:894] mm_iface_modem_update_access_technologies(): Modem /org/freedesktop/ModemManager1/Modem/0: access technology changed (umts, hsdpa, hsupa -> unknown)
> NetworkManager[1862]: <warn> (cdc-wdm1) failed to connect modem: Network timeout
> NetworkManager[1862]: <info> (cdc-wdm1): device state change: prepare -> failed (reason 'gsm-registration-timeout') [40 120 32]
> NetworkManager[1862]: <info> NetworkManager state is now DISCONNECTED
> NetworkManager[1862]: <debug> [1402484754.485784] [nm-manager.c:4165] policy_activating_device_changed(): ActivatingConnection now (none)
> NetworkManager[1862]: <warn> Activation (cdc-wdm1) failed for connection 'FONIC Vorgabe'
> NetworkManager[1862]: <debug> [1402484754.485885] [nm-device.c:5261] nm_device_queue_state(): (cdc-wdm1): queued state change to disconnected (id 431)
> NetworkManager[1862]: <debug> [1402484754.486259] [nm-device.c:5219] queued_set_state(): (cdc-wdm1): running queued state change to disconnected (id 431)
> NetworkManager[1862]: <info> (cdc-wdm1): device state change: failed -> disconnected (reason 'none') [120 30 0]
> NetworkManager[1862]: <info> (cdc-wdm1): deactivating device (reason 'none') [0]
> NetworkManager[1862]: <debug> [1402484754.486360] [nm-firewall-manager.c:166] nm_firewall_manager_remove_from_zone(): (cdc-wdm1) firewall zone remove skipped (not running)
> NetworkManager[1862]: <debug> [1402484754.486649] [nm-dns-manager.c:995] nm_dns_manager_begin_updates(): (update_routing_and_dns): queueing DNS updates (1)
> NetworkManager[1862]: <debug> [1402484754.486718] [nm-dns-manager.c:1013] nm_dns_manager_end_updates(): (nm_dns_manager_end_updates): DNS configuration did not change
> NetworkManager[1862]: <debug> [1402484754.486745] [nm-dns-manager.c:1017] nm_dns_manager_end_updates(): (update_routing_and_dns): no DNS changes to commit (0)
>
>
>
> But there are no MBIM messages explaining why MM sets the state to
> 'idle'.  Is this because of the missing reply, Alexander?  Why don't we
> just trust the (more current) result from the indication?  We do know
> that the modem is registered to the home network here, or?

Gah....

Yeah, that's the thing:

static void
register_in_network_context_failed (RegisterInNetworkContext *ctx,
                                    GError *error)
{
    mm_iface_modem_3gpp_update_cs_registration_state (ctx->self,
MM_MODEM_3GPP_REGISTRATION_STATE_IDLE);
    mm_iface_modem_3gpp_update_ps_registration_state (ctx->self,
MM_MODEM_3GPP_REGISTRATION_STATE_IDLE);
    mm_iface_modem_3gpp_update_eps_registration_state (ctx->self,
MM_MODEM_3GPP_REGISTRATION_STATE_IDLE);
    mm_iface_modem_3gpp_update_access_technologies (ctx->self,
MM_MODEM_ACCESS_TECHNOLOGY_UNKNOWN);
    mm_iface_modem_3gpp_update_location (ctx->self, 0, 0);

    g_simple_async_result_take_error (ctx->result, error);
}

Well, I guess we should try to detect the indication and if so, use it
as 'reply' to the request we sent. Luckily both the indication and the
response will have the same info:

    imbim_message_register_state_notification_parse (
            notification,
            NULL, /* nw_error */
            &register_state,
            NULL, /* register_mode */
            &available_data_classes,
            NULL, /* current_cellular_class */
            &provider_id,
            &provider_name,
            NULL, /* roaming_text */
            NULL, /* registration_flag */
            NULL)

        mbim_message_register_state_response_parse (
            response,
            NULL, /* nw_error */
            &register_state,
            NULL, /* register_mode */
            &available_data_classes,
            NULL, /* current_cellular_class */
            &provider_id,
            &provider_name,
            NULL, /* roaming_text */
            NULL, /* registration_flag */
            NULL)

Ugly hack, but I guess there's no other way to handle this firmware issue?

Another option would be to avoid moving the state to IDLE when
registration check fails, but that's pretty generic in every flow for
every modem, not sure if we should touch that.

-- 
Aleksander
https://aleksander.es

Re: cdc-wdm: unable to connect after suspend

[Florian Klink]

[-- Attachment #1: Type: text/plain, Size: 5348 bytes --]

Am 11.06.2014 17:05, schrieb Aleksander Morgado:
> On Wed, Jun 11, 2014 at 1:53 PM, Bjørn Mork <bjorn@mork.no> wrote:
>> ModemManager[1861]: <info>  [1402484754.484416] [mm-iface-modem-3gpp.c:1167] update_registration_state(): Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (home -> idle)
>> ModemManager[1861]: <info>  [1402484754.484496] [mm-iface-modem-location.c:293] notify_3gpp_location_update(): Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP location updated (MCC: '0', MNC: '0', Location area code: '0', Cell ID: '0')
>> ModemManager[1861]: <debug> [1402484754.484540] [mm-bearer.c:261] modem_3gpp_registration_state_changed(): Bearer not allowed to connect, not registered in 3GPP network
>> ModemManager[1861]: <info>  [1402484754.484570] [mm-iface-modem.c:894] mm_iface_modem_update_access_technologies(): Modem /org/freedesktop/ModemManager1/Modem/0: access technology changed (umts, hsdpa, hsupa -> unknown)
>> NetworkManager[1862]: <warn> (cdc-wdm1) failed to connect modem: Network timeout
>> NetworkManager[1862]: <info> (cdc-wdm1): device state change: prepare -> failed (reason 'gsm-registration-timeout') [40 120 32]
>> NetworkManager[1862]: <info> NetworkManager state is now DISCONNECTED
>> NetworkManager[1862]: <debug> [1402484754.485784] [nm-manager.c:4165] policy_activating_device_changed(): ActivatingConnection now (none)
>> NetworkManager[1862]: <warn> Activation (cdc-wdm1) failed for connection 'FONIC Vorgabe'
>> NetworkManager[1862]: <debug> [1402484754.485885] [nm-device.c:5261] nm_device_queue_state(): (cdc-wdm1): queued state change to disconnected (id 431)
>> NetworkManager[1862]: <debug> [1402484754.486259] [nm-device.c:5219] queued_set_state(): (cdc-wdm1): running queued state change to disconnected (id 431)
>> NetworkManager[1862]: <info> (cdc-wdm1): device state change: failed -> disconnected (reason 'none') [120 30 0]
>> NetworkManager[1862]: <info> (cdc-wdm1): deactivating device (reason 'none') [0]
>> NetworkManager[1862]: <debug> [1402484754.486360] [nm-firewall-manager.c:166] nm_firewall_manager_remove_from_zone(): (cdc-wdm1) firewall zone remove skipped (not running)
>> NetworkManager[1862]: <debug> [1402484754.486649] [nm-dns-manager.c:995] nm_dns_manager_begin_updates(): (update_routing_and_dns): queueing DNS updates (1)
>> NetworkManager[1862]: <debug> [1402484754.486718] [nm-dns-manager.c:1013] nm_dns_manager_end_updates(): (nm_dns_manager_end_updates): DNS configuration did not change
>> NetworkManager[1862]: <debug> [1402484754.486745] [nm-dns-manager.c:1017] nm_dns_manager_end_updates(): (update_routing_and_dns): no DNS changes to commit (0)
>>
>>
>>
>> But there are no MBIM messages explaining why MM sets the state to
>> 'idle'.  Is this because of the missing reply, Alexander?  Why don't we
>> just trust the (more current) result from the indication?  We do know
>> that the modem is registered to the home network here, or?
> 
> Gah....
> 
> Yeah, that's the thing:
> 
> static void
> register_in_network_context_failed (RegisterInNetworkContext *ctx,
>                                     GError *error)
> {
>     mm_iface_modem_3gpp_update_cs_registration_state (ctx->self,
> MM_MODEM_3GPP_REGISTRATION_STATE_IDLE);
>     mm_iface_modem_3gpp_update_ps_registration_state (ctx->self,
> MM_MODEM_3GPP_REGISTRATION_STATE_IDLE);
>     mm_iface_modem_3gpp_update_eps_registration_state (ctx->self,
> MM_MODEM_3GPP_REGISTRATION_STATE_IDLE);
>     mm_iface_modem_3gpp_update_access_technologies (ctx->self,
> MM_MODEM_ACCESS_TECHNOLOGY_UNKNOWN);
>     mm_iface_modem_3gpp_update_location (ctx->self, 0, 0);
> 
>     g_simple_async_result_take_error (ctx->result, error);
> }
> 
> Well, I guess we should try to detect the indication and if so, use it
> as 'reply' to the request we sent. Luckily both the indication and the
> response will have the same info:
> 
>     imbim_message_register_state_notification_parse (
>             notification,
>             NULL, /* nw_error */
>             &register_state,
>             NULL, /* register_mode */
>             &available_data_classes,
>             NULL, /* current_cellular_class */
>             &provider_id,
>             &provider_name,
>             NULL, /* roaming_text */
>             NULL, /* registration_flag */
>             NULL)
> 
>         mbim_message_register_state_response_parse (
>             response,
>             NULL, /* nw_error */
>             &register_state,
>             NULL, /* register_mode */
>             &available_data_classes,
>             NULL, /* current_cellular_class */
>             &provider_id,
>             &provider_name,
>             NULL, /* roaming_text */
>             NULL, /* registration_flag */
>             NULL)
>
> Ugly hack, but I guess there's no other way to handle this firmware issue?


I'd think this approach at least seems to be less error-prone than the
one suggested below. Can you provide me a patch that treats the
indication as a reply?
I never touched libmbim, but I'd happily test a patch :-)


Florian


> Another option would be to avoid moving the state to IDLE when
> registration check fails, but that's pretty generic in every flow for
> every modem, not sure if we should touch that.
> 


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