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
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
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
quoted
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.
quoted
quoted
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 ;-)
.
quoted
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.
quoted
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?
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.
quoted
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.
quoted
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?
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?
quoted
quoted
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.
quoted
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
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.
quoted
quoted
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
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
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
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...
quoted
quoted
quoted
quoted
quoted
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)...
quoted
quoted
quoted
quoted
quoted
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...
quoted
quoted
quoted
quoted
quoted
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)...
quoted
quoted
quoted
quoted
quoted
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
From: Aleksander Morgado <hidden> Date: 2014-06-11 15:05:04
On Wed, Jun 11, 2014 at 1:53 PM, Bjørn Mork [off-list ref] 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 */
®ister_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 */
®ister_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
On Wed, Jun 11, 2014 at 1:53 PM, Bjørn Mork [off-list ref] wrote:
quoted
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 */
®ister_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 */
®ister_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.