Sierra EM7455 takes 3+ minutes to connect after suspend/resume

Sun Nov 12 13:02:35 UTC 2017

Hey,

>
> I have a Sierra EM7455 that takes 3+ minutes to connect to my mobile broadband provider after suspend/resume.
> *This behaviour only occures after suspend/resume.
> *With a cold boot I can connecty nearly right after the desktop comes up.
> *If I disable ModemManager and connect via my own script I can connect approximately 5 seconds after the system has resumed.
>
> Below are the logs. Suspend at 18:51:05 and resume 15 seconds later. It took ModemManager more than 3,5minutes to connect me to the internet.

Looks like it timed out waiting to get registered in the network
before launching teh explicit connection attempt.
Could you gather debug logs?

https://www.freedesktop.org/wiki/Software/ModemManager/Debugging/

> # journalctl -f -u ModemManager -u NetworkManager
> Nov 11 18:51:05 470s NetworkManager[484]: <info>  [1510422665.3000] manager: sleeping...
> Nov 11 18:51:05 470s NetworkManager[484]: <info>  [1510422665.3001] device (w0): state change: unavailable -> unmanaged (reason 'sleeping', internal state 'managed')
> Nov 11 18:51:05 470s NetworkManager[484]: <info>  [1510422665.3003] device (w0): set-hw-addr: reset MAC address to 34:F6:XX:XX:XX:XX (unmanage)
> Nov 11 18:51:05 470s NetworkManager[484]: <info>  [1510422665.3007] manager: NetworkManager state is now ASLEEP
> Nov 11 18:51:05 470s NetworkManager[484]: <info>  [1510422665.3012] device (cdc-wdm0): state change: activated -> unmanaged (reason 'removed', internal state 'removed')
> Nov 11 18:51:05 470s NetworkManager[484]: <info>  [1510422665.3065] dns-mgr: Removing DNS information from /usr/bin/resolvconf
> Nov 11 18:51:05 470s NetworkManager[484]: <warn>  [1510422665.3773] modem-broadband[cdc-wdm0]: failed to disconnect modem: GDBus.Error:org.freedesktop.DBus.Error.UnknownMethod: No such interface 'org.freedesktop.ModemManager1.Modem.Simple' on object at path /org/freedesktop/ModemManager1/Modem/2
> Nov 11 18:51:20 470s ModemManager[5298]: [/dev/cdc-wdm0] unexpected port hangup!
> Nov 11 18:51:20 470s NetworkManager[484]: <info>  [1510422680.6509] manager: wake requested (sleeping: yes  enabled: yes)
> Nov 11 18:51:20 470s NetworkManager[484]: <info>  [1510422680.6509] manager: waking up...
> Nov 11 18:51:20 470s NetworkManager[484]: <info>  [1510422680.6510] device (e0): state change: unavailable -> unmanaged (reason 'sleeping', internal state 'managed')
> Nov 11 18:51:20 470s NetworkManager[484]: <info>  [1510422680.7763] device (e0.5): state change: unavailable -> unmanaged (reason 'sleeping', internal state 'managed')
> Nov 11 18:51:20 470s NetworkManager[484]: <info>  [1510422680.7788] device (e0.4): state change: unavailable -> unmanaged (reason 'sleeping', internal state 'managed')
> Nov 11 18:51:20 470s NetworkManager[484]: <info>  [1510422680.7854] device (e0): state change: unmanaged -> unavailable (reason 'managed', internal state 'managed')
> Nov 11 18:51:20 470s NetworkManager[484]: <info>  [1510422680.9989] device (e0.5): state change: unmanaged -> unavailable (reason 'managed', internal state 'managed')
> Nov 11 18:51:20 470s NetworkManager[484]: <info>  [1510422680.9994] device (e0.4): state change: unmanaged -> unavailable (reason 'managed', internal state 'managed')
> Nov 11 18:51:20 470s NetworkManager[484]: <info>  [1510422680.9998] device (w0): state change: unmanaged -> unavailable (reason 'managed', internal state 'managed')
> Nov 11 18:51:21 470s NetworkManager[484]: <info>  [1510422681.0003] manager: NetworkManager state is now DISCONNECTED
> Nov 11 18:51:23 470s ModemManager[5298]: <info>  Couldn't check support for device at '/sys/devices/pci0000:00/0000:00:1c.2/0000:3a:00.0': not supported by any plugin
> Nov 11 18:51:23 470s ModemManager[5298]: <info>  Couldn't check support for device at '/sys/devices/pci0000:00/0000:00:1f.6': not supported by any plugin
> Nov 11 18:51:29 470s ModemManager[5298]: opening device...
> Nov 11 18:51:29 470s ModemManager[5298]: [/dev/cdc-wdm0] Read max control message size from descriptors file: 4096
> Nov 11 18:51:42 470s ModemManager[5298]: <info>  Creating modem with plugin 'Sierra' and '2' ports
> Nov 11 18:51:42 470s ModemManager[5298]: <info>  Modem for device at '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6' successfully created
> Nov 11 18:51:42 470s ModemManager[5298]: opening device...
> Nov 11 18:51:42 470s ModemManager[5298]: [/dev/cdc-wdm0] Read max control message size from descriptors file: 4096
> Nov 11 18:51:43 470s ModemManager[5298]: <info>  Modem: state changed (unknown -> disabled)
> Nov 11 18:51:43 470s NetworkManager[484]: <info>  [1510422703.4223] (cdc-wdm0): modem state changed, 'disabled' --> 'enabling' (reason: user preference)
> Nov 11 18:51:43 470s NetworkManager[484]: <info>  [1510422703.4231] manager: (cdc-wdm0): new Broadband device (/org/freedesktop/NetworkManager/Devices/15)
> Nov 11 18:51:43 470s NetworkManager[484]: <info>  [1510422703.4234] device (cdc-wdm0): state change: unmanaged -> unavailable (reason 'managed', internal state 'external')
> Nov 11 18:51:43 470s NetworkManager[484]: <info>  [1510422703.4236] device (cdc-wdm0): modem state 'enabling'
> Nov 11 18:51:43 470s NetworkManager[484]: <info>  [1510422703.4239] device (cdc-wdm0): state change: unavailable -> disconnected (reason 'none', internal state 'managed')
> Nov 11 18:51:43 470s NetworkManager[484]: <info>  [1510422703.4244] policy: auto-activating connection 'Mobile'
> Nov 11 18:51:43 470s ModemManager[5298]: <info>  Modem /org/freedesktop/ModemManager1/Modem/3: state changed (disabled -> enabling)
> Nov 11 18:51:43 470s NetworkManager[484]: <info>  [1510422703.4258] device (cdc-wdm0): Activation: starting connection 'Mobile' (24c07b0c-6974-48dd-bb29-13eaeb12596e)
> Nov 11 18:51:43 470s NetworkManager[484]: <info>  [1510422703.4262] device (cdc-wdm0): state change: disconnected -> prepare (reason 'none', internal state 'managed')
> Nov 11 18:51:43 470s NetworkManager[484]: <info>  [1510422703.4263] manager: NetworkManager state is now CONNECTING
> Nov 11 18:51:43 470s ModemManager[5298]: <info>  Simple connect started...
> Nov 11 18:51:43 470s ModemManager[5298]: <info>  Simple connect state (4/8): Wait to get fully enabled
> Nov 11 18:51:43 470s ModemManager[5298]: <warn>  Failure
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] Opening device with flags 'proxy, mbim'...
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] loaded driver of cdc-wdm port: cdc_mbim
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] creating MBIM device...
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] MBIM device created
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] opening MBIM device...
> Nov 11 18:51:43 470s ModemManager[5298]: opening device...
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] Read max control message size from descriptors file: 4096
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] MBIM device open
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] Assuming service 'dms' is supported...
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] Allocating new client ID...
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] sending message as MBIM...
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] Received MBIM message
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] Registered 'dms' (version unknown) client with ID '3'
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] sending message as MBIM...
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] Received MBIM message
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] Releasing 'dms' client with flags 'release-cid'...
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] Unregistered 'dms' client with ID '3'
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] sending message as MBIM...
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] Received MBIM message
> Nov 11 18:51:43 470s ModemManager[5298]: [/dev/cdc-wdm0] Releasing '(null)' client with flags 'release-cid'...
> Nov 11 18:51:44 470s ModemManager[5298]: <info>  Modem /org/freedesktop/ModemManager1/Modem/3: 3GPP Registration state changed (unknown -> searching)
> Nov 11 18:51:44 470s ModemManager[5298]: <info>  Modem /org/freedesktop/ModemManager1/Modem/3: state changed (enabling -> searching)
> Nov 11 18:51:44 470s ModemManager[5298]: <info>  Simple connect state (5/8): Register
> Nov 11 18:51:44 470s NetworkManager[484]: <info>  [1510422704.1281] (cdc-wdm0): modem state changed, 'enabling' --> 'searching' (reason: user-requested)
> Nov 11 18:52:44 470s ModemManager[5298]: <info>  Modem /org/freedesktop/ModemManager1/Modem/3: 3GPP Registration state changed (searching -> idle)
> Nov 11 18:52:44 470s ModemManager[5298]: <info>  Simple connect started...
> Nov 11 18:52:44 470s ModemManager[5298]: <info>  Simple connect state (4/8): Wait to get fully enabled
> Nov 11 18:52:44 470s ModemManager[5298]: <info>  Simple connect state (5/8): Register
> Nov 11 18:52:47 470s ModemManager[5298]: <info>  Modem /org/freedesktop/ModemManager1/Modem/3: 3GPP Registration state changed (idle -> searching)
> Nov 11 18:53:47 470s ModemManager[5298]: <info>  Modem /org/freedesktop/ModemManager1/Modem/3: 3GPP Registration state changed (searching -> idle)
> Nov 11 18:53:47 470s ModemManager[5298]: <info>  Simple connect started...
> Nov 11 18:53:47 470s ModemManager[5298]: <info>  Simple connect state (4/8): Wait to get fully enabled
> Nov 11 18:53:47 470s ModemManager[5298]: <info>  Simple connect state (5/8): Register
> Nov 11 18:54:35 470s ModemManager[5298]: <info>  Modem /org/freedesktop/ModemManager1/Modem/3: 3GPP Registration state changed (idle -> searching)
> Nov 11 18:54:50 470s ModemManager[5298]: <info>  Modem /org/freedesktop/ModemManager1/Modem/3: 3GPP Registration state changed (searching -> idle)
> Nov 11 18:54:50 470s NetworkManager[484]: <warn>  [1510422890.2087] modem-broadband[cdc-wdm0]: failed to connect modem: Network timeout
> Nov 11 18:54:50 470s NetworkManager[484]: <info>  [1510422890.2087] device (cdc-wdm0): state change: prepare -> failed (reason 'gsm-registration-timeout', internal state 'managed')
> Nov 11 18:54:50 470s NetworkManager[484]: <info>  [1510422890.2092] manager: NetworkManager state is now DISCONNECTED
> Nov 11 18:54:50 470s NetworkManager[484]: <warn>  [1510422890.2104] device (cdc-wdm0): Activation: failed for connection 'Mobile'
> Nov 11 18:54:50 470s NetworkManager[484]: <info>  [1510422890.2121] device (cdc-wdm0): state change: failed -> disconnected (reason 'none', internal state 'managed')
> Nov 11 18:54:50 470s NetworkManager[484]: <info>  [1510422890.2140] policy: auto-activating connection 'Mobile'
> Nov 11 18:54:50 470s NetworkManager[484]: <info>  [1510422890.2171] device (cdc-wdm0): Activation: starting connection 'Mobile' (24c07b0c-6974-48dd-bb29-13eaeb12596e)
> Nov 11 18:54:50 470s NetworkManager[484]: <info>  [1510422890.2224] device (cdc-wdm0): state change: disconnected -> prepare (reason 'none', internal state 'managed')
> Nov 11 18:54:50 470s NetworkManager[484]: <info>  [1510422890.2229] manager: NetworkManager state is now CONNECTING
> Nov 11 18:54:50 470s ModemManager[5298]: <info>  Simple connect started...
> Nov 11 18:54:50 470s ModemManager[5298]: <info>  Simple connect state (4/8): Wait to get fully enabled
> Nov 11 18:54:50 470s ModemManager[5298]: <info>  Simple connect state (5/8): Register
> Nov 11 18:54:52 470s ModemManager[5298]: <info>  Modem /org/freedesktop/ModemManager1/Modem/3: 3GPP Registration state changed (idle -> registering)
> Nov 11 18:54:52 470s ModemManager[5298]: <info>  Modem /org/freedesktop/ModemManager1/Modem/3: 3GPP Registration state changed (registering -> roaming)
> Nov 11 18:54:52 470s ModemManager[5298]: <info>  Modem /org/freedesktop/ModemManager1/Modem/3: state changed (searching -> registered)
> Nov 11 18:54:52 470s NetworkManager[484]: <info>  [1510422892.6754] (cdc-wdm0): modem state changed, 'searching' --> 'registered' (reason: unknown)
> Nov 11 18:54:52 470s ModemManager[5298]: <info>  Simple connect state (6/8): Bearer
> Nov 11 18:54:52 470s ModemManager[5298]: <info>  Simple connect state (7/8): Connect
> Nov 11 18:54:52 470s ModemManager[5298]: <info>  Modem /org/freedesktop/ModemManager1/Modem/3: state changed (registered -> connecting)
> Nov 11 18:54:52 470s NetworkManager[484]: <info>  [1510422892.8661] (cdc-wdm0): modem state changed, 'registered' --> 'connecting' (reason: user-requested)
> Nov 11 18:54:53 470s ModemManager[5298]: <info>  Modem /org/freedesktop/ModemManager1/Modem/3: state changed (connecting -> connected)
> Nov 11 18:54:53 470s ModemManager[5298]: <info>  Simple connect state (8/8): All done
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2495] (cdc-wdm0): modem state changed, 'connecting' --> 'connected' (reason: user-requested)
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2543] device (cdc-wdm0): state change: prepare -> config (reason 'none', internal state 'managed')
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2568] device (cdc-wdm0): state change: config -> ip-config (reason 'none', internal state 'managed')
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2608] modem-broadband[cdc-wdm0]: IPv4 static configuration:
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2638] modem-broadband[cdc-wdm0]:   address 10.74.86.60/29
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2643] modem-broadband[cdc-wdm0]:   gateway 10.74.86.61
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2646] modem-broadband[cdc-wdm0]:   DNS XXX.XX.XXX.XXX
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2649] modem-broadband[cdc-wdm0]:   DNS XXX.XX.XXX.XXX
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2731] device (cdc-wdm0): state change: ip-config -> ip-check (reason 'none', internal state 'managed')
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2778] device (cdc-wdm0): state change: ip-check -> secondaries (reason 'none', internal state 'managed')
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2791] device (cdc-wdm0): state change: secondaries -> activated (reason 'none', internal state 'managed')
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2797] manager: NetworkManager state is now CONNECTED_LOCAL
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2867] manager: NetworkManager state is now CONNECTED_GLOBAL
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2869] policy: set 'Mobile' (wwp0s20f0u6i12) as default for IPv4 routing and DNS
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.2870] dns-mgr: Writing DNS information to /usr/bin/resolvconf
> Nov 11 18:54:53 470s NetworkManager[484]: <info>  [1510422893.3435] device (cdc-wdm0): Activation: successful, device activated.
>
> This is the script/workaround which can connect me a few seconds after resume:
> #!/bin/bash -x
> qmicli --device-open-mbim -d /dev/cdc-wdm0 --dms-set-fcc-authentication && \
> mbim-network /dev/cdc-wdm0 start && \
> ip l s up dev wwp0s20f0u6i12 && \
> ip a a $(mbimcli -d /dev/cdc-wdm0 -p  --query-ip-configuration | grep 'IP \[0\]' | egrep -o "[0-9]{1,3}.[0-9]{1,3}.[0-9]{1,3}.[0-9]{1,3}/[0-9][0-9]") dev wwp0s20f0u6i12 &&\
> ip r a default via $(mbimcli -d /dev/cdc-wdm0 -p  --query-ip-configuration  | grep Gateway | egrep -o "[0-9]{1,3}.[0-9]{1,3}.[0-9]{1,3}.[0-9]{1,3}") metric 3000
>
> I would prefer to connect via ModemManager than via my own hacky script.
>
> Regards
> Karl
> _______________________________________________
> ModemManager-devel mailing list
> ModemManager-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel

-- 
Aleksander
https://aleksander.es