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

Sun Nov 12 12:54:50 UTC 2017

Hello

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