mobile broadband is slow to start in wake from suspend (or system startup)

[Erno Kuusela]

On a ThinkPad 470s it takes ~ 40 seconds to gain connectivity on wake or startup.

The log seems to incidate that there is first a 10 second delay in the kernel recognising the USB device and assigning a serial port to it, and then it takes ModemManager 20 seconds to open the device, and a further 13 seconds to go from unlocking the SIM ("locked" state) to getting an ip address.

Apparently it starts in 10 seconds in Windows (see https://forums.lenovo.com/t5/ThinkPad-X-Series-Laptops/SierraWireless-EM7455-in-X1c5-is-Lenovo-going-to-fix-its-poor/td-p/3716748) so the 40+ seconds it's not a hardware property.

The log goes like this:

Jun 28 15:06:35 myhostname NetworkManager[1302]: <info> [1530187595.7935] manager: sleep: wake requested (sleeping: yes enabled: yes)
Jun 28 15:06:35 myhostname NetworkManager[1302]: <info> [1530187595.7936] device (enp0s31f6): state change: unavailable -> unmanaged (reason 'sleeping', sys-iface-state: 'managed')
Jun 28 15:06:35 myhostname NetworkManager[1302]: <info> [1530187595.8780] device (enp0s31f6): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
Jun 28 15:06:36 myhostname kernel: [127229.483041] usb 1-6: config 1 interface 0 altsetting 0 bulk endpoint 0x1 has invalid maxpacket 64
Jun 28 15:06:36 myhostname kernel: [127229.483051] usb 1-6: config 1 interface 0 altsetting 0 bulk endpoint 0x81 has invalid maxpacket 64
Jun 28 15:06:36 myhostname kernel: [127229.483720] usb 1-6: New USB device found, idVendor=1199, idProduct=9078
Jun 28 15:06:36 myhostname kernel: [127229.483728] usb 1-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jun 28 15:06:36 myhostname kernel: [127229.483734] usb 1-6: Product: Sierra Wireless EM7455 Qualcomm
Jun 28 15:06:36 myhostname kernel: [127229.483741] usb 1-6: Manufacturer: Sierra Wireless, Incorporated
Jun 28 15:06:36 myhostname kernel: [127229.483747] usb 1-6: SerialNumber: LF80875274011022
Jun 28 15:06:36 myhostname kernel: [127229.502644] usb 1-6: USB disconnect, device number 14

Jun 28 15:06:36 myhostname NetworkManager[1302]: <info> [1530187596.0722] device (wlp58s0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'managed')
Jun 28 15:06:36 myhostname NetworkManager[1302]: <info> [1530187596.0744] manager: NetworkManager state is now CONNECTED_LOCAL
Jun 28 15:06:36 myhostname upowerd[1509]: unhandled action 'bind' on /sys/devices/pci0000:00/0000:00:14.0/usb1/1-6
Jun 28 15:06:36 myhostname upowerd[1509]: unhandled action 'unbind' on /sys/devices/pci0000:00/0000:00:14.0/usb1/1-6
Jun 28 15:06:36 myhostname upowerd[1509]: unhandled action 'bind' on /sys/devices/pci0000:00/0000:00:14.0/usb2/2-3/2-3:1.0
Jun 28 15:06:36 myhostname upowerd[1509]: unhandled action 'bind' on /sys/devices/pci0000:00/0000:00:14.0/usb2/2-3

Jun 28 15:06:38 myhostname ModemManager[1312]: <info> Couldn't check support for device at '/sys/devices/pci0000:00/0000:00:1c.2/0000:3a:00.0': not supported by any plu
gin
Jun 28 15:06:38 myhostname ModemManager[1312]: <info> Couldn't check support for device at '/sys/devices/pci0000:00/0000:00:1f.6': not supported by any plugin

Jun 28 15:06:45 myhostname kernel: [127238.486536] usb 1-6: new high-speed USB device number 15 using xhci_hcd
Jun 28 15:06:45 myhostname kernel: [127238.642917] usb 1-6: config 1 has an invalid interface number: 12 but max is 4
Jun 28 15:06:45 myhostname kernel: [127238.642920] usb 1-6: config 1 has an invalid interface number: 13 but max is 4
Jun 28 15:06:45 myhostname kernel: [127238.642921] usb 1-6: config 1 has an invalid interface number: 13 but max is 4
Jun 28 15:06:45 myhostname kernel: [127238.642923] usb 1-6: config 1 has no interface number 1
Jun 28 15:06:45 myhostname kernel: [127238.642925] usb 1-6: config 1 has no interface number 4
Jun 28 15:06:45 myhostname kernel: [127238.643533] usb 1-6: New USB device found, idVendor=1199, idProduct=9079
Jun 28 15:06:45 myhostname kernel: [127238.643535] usb 1-6: New USB device strings: Mfr=1, Product=2, SerialNumber=3
Jun 28 15:06:45 myhostname kernel: [127238.643537] usb 1-6: Product: Sierra Wireless EM7455 Qualcomm Snapdragon X7 LTE-A
Jun 28 15:06:45 myhostname kernel: [127238.643539] usb 1-6: Manufacturer: Sierra Wireless, Incorporated
Jun 28 15:06:45 myhostname kernel: [127238.646888] qcserial 1-6:1.0: Qualcomm USB modem converter detected
Jun 28 15:06:45 myhostname kernel: [127238.647053] usb 1-6: Qualcomm USB modem converter now attached to ttyUSB0
Jun 28 15:06:45 myhostname kernel: [127238.647590] qcserial 1-6:1.2: Qualcomm USB modem converter detected
Jun 28 15:06:45 myhostname kernel: [127238.647791] usb 1-6: Qualcomm USB modem converter now attached to ttyUSB1
Jun 28 15:06:45 myhostname kernel: [127238.648344] qcserial 1-6:1.3: Qualcomm USB modem converter detected
Jun 28 15:06:45 myhostname kernel: [127238.648541] usb 1-6: Qualcomm USB modem converter now attached to ttyUSB2

Jun 28 15:06:45 myhostname NetworkManager[1302]: <info> [1530187605.2736] devices added (path: /sys/devices/pci0000:00/0000:00:14.0/usb1/1-6/1-6:1.12/net/wwp0s20f0u6i12, iface: wwp0s20f0u6i12)
Jun 28 15:06:45 myhostname NetworkManager[1302]: <info> [1530187605.2737] device added (path: /sys/devices/pci0000:00/0000:00:14.0/usb1/1-6/1-6:1.12/net/wwp0s20f0u6i12, iface: wwp0s20f0u6i12): no ifupdown configuration found.
Jun 28 15:06:46 myhostname ModemManager[1312]: <warn> (ttyUSB0): port attributes not fully set
Jun 28 15:06:46 myhostname ModemManager[1312]: <warn> (ttyUSB1): port attributes not fully set
Jun 28 15:06:46 myhostname ModemManager[1312]: <warn> (ttyUSB2): port attributes not fully set
Jun 28 15:06:46 myhostname ModemManager[1312]: opening device...
Jun 28 15:06:46 myhostname ModemManager[1312]: [/dev/cdc-wdm0] Read max control message size from descriptors file: 4096
Jun 28 15:06:57 myhostname ModemManager[1312]: <info> Creating modem with plugin 'Generic' and '1' ports
Jun 28 15:06:57 myhostname ModemManager[1312]: <warn> Could not grab port (tty/ttyS4): 'Cannot add port 'tty/ttyS4', unhandled serial type'
Jun 28 15:06:57 myhostname ModemManager[1312]: <warn> Couldn't create modem for device at '/sys/devices/pci0000:00/0000:00:16.3': Failed to find primary AT port
Jun 28 15:07:05 myhostname ModemManager[1312]: <info> Creating modem with plugin 'Sierra' and '5' ports
Jun 28 15:07:05 myhostname ModemManager[1312]: <warn> Could not grab port (tty/ttyUSB1): 'Cannot add port 'tty/ttyUSB1', unhandled serial type'
Jun 28 15:07:05 myhostname ModemManager[1312]: <info> Modem for device at '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6' successfully created
Jun 28 15:07:05 myhostname ModemManager[1312]: opening device...
Jun 28 15:07:05 myhostname ModemManager[1312]: [/dev/cdc-wdm0] Read max control message size from descriptors file: 4096
Jun 28 15:07:05 myhostname ModemManager[1312]: <warn> (ttyUSB2): port attributes not fully set
Jun 28 15:07:05 myhostname ModemManager[1312]: <info> Modem: state changed (unknown -> locked)
Jun 28 15:07:05 myhostname ModemManager[1312]: <warn> couldn't load Operator identifier: 'PinRequired'
Jun 28 15:07:05 myhostname ModemManager[1312]: <warn> couldn't load Operator name: 'PinRequired'

Jun 28 15:07:05 myhostname NetworkManager[1302]: <warn> [1530187625.7846] modem["cdc-wdm0"]: cannot enable/disable modem: locked
Jun 28 15:07:05 myhostname NetworkManager[1302]: <info> [1530187625.7881] manager: (cdc-wdm0): new Broadband device (/org/freedesktop/NetworkManager/Devices/10)
Jun 28 15:07:05 myhostname NetworkManager[1302]: <info> [1530187625.7894] device (cdc-wdm0): state change: unmanaged -> unavailable (reason 'managed', sys-iface-state: 'external')
Jun 28 15:07:05 myhostname NetworkManager[1302]: <info> [1530187625.7909] device (cdc-wdm0): modem state 'locked'
Jun 28 15:07:05 myhostname NetworkManager[1302]: <info> [1530187625.7950] device (cdc-wdm0): state change: unavailable -> disconnected (reason 'none', sys-iface-state: 'managed')
Jun 28 15:07:05 myhostname NetworkManager[1302]: <info> [1530187625.7970] policy: auto-activating connection 'Elisa Default'
Jun 28 15:07:05 myhostname NetworkManager[1302]: <info> [1530187625.8017] device (cdc-wdm0): Activation: starting connection 'Elisa Default' (e69a2599-2e3d-4e31-b2dc-9d808c3e6b4a)
Jun 28 15:07:05 myhostname NetworkManager[1302]: <info> [1530187625.8027] device (cdc-wdm0): state change: disconnected -> prepare (reason 'none', sys-iface-state: 'managed')
Jun 28 15:07:05 myhostname NetworkManager[1302]: <info> [1530187625.8048] manager: NetworkManager state is now CONNECTING
Jun 28 15:07:05 myhostname NetworkManager[1302]: <info> [1530187625.8534] device (cdc-wdm0): state change: prepare -> need-auth (reason 'none', sys-iface-state: 'managed')
Jun 28 15:07:05 myhostname NetworkManager[1302]: <info> [1530187625.8624] device (cdc-wdm0): state change: need-auth -> prepare (reason 'none', sys-iface-state: 'managed')
Jun 28 15:07:08 myhostname NetworkManager[1302]: <info> [1530187628.6915] modem["cdc-wdm0"]: modem state changed, 'locked' --> 'disabled' (reason: unknown)
Jun 28 15:07:08 myhostname NetworkManager[1302]: <info> [1530187628.6917] modem["cdc-wdm0"]: modem state changed, 'disabled' --> 'enabling' (reason: user preference)
Jun 28 15:07:09 myhostname NetworkManager[1302]: <info> [1530187629.6208] modem["cdc-wdm0"]: modem state changed, 'enabling' --> 'searching' (reason: user-requested)
Jun 28 15:07:13 myhostname NetworkManager[1302]: <info> [1530187633.1831] modem["cdc-wdm0"]: modem state changed, 'searching' --> 'registered' (reason: unknown)
Jun 28 15:07:13 myhostname NetworkManager[1302]: <info> [1530187633.3033] modem["cdc-wdm0"]: modem state changed, 'registered' --> 'connecting' (reason: user-requested)
Jun 28 15:07:18 myhostname NetworkManager[1302]: <info> [1530187638.3588] modem["cdc-wdm0"]: modem state changed, 'connecting' --> 'connected' (reason: user-requested)
Jun 28 15:07:18 myhostname NetworkManager[1302]: <info> [1530187638.3710] device (cdc-wdm0): state change: prepare -> config (reason 'none', sys-iface-state: 'managed')
Jun 28 15:07:18 myhostname NetworkManager[1302]: <info> [1530187638.3739] device (cdc-wdm0): state change: config -> ip-config (reason 'none', sys-iface-state: 'managed')
Jun 28 15:07:18 myhostname NetworkManager[1302]: <info> [1530187638.3757] modem-broadband[cdc-wdm0]: IPv4 static configuration:
Jun 28 15:07:18 myhostname NetworkManager[1302]: <info> [1530187638.3759] modem-broadband[cdc-wdm0]: address 123.123.123.127/30
Jun 28 15:07:18 myhostname NetworkManager[1302]: <info> [1530187638.3760] modem-broadband[cdc-wdm0]: gateway 123.123.123.128

ProblemType: Bug
DistroRelease: Ubuntu 18.04
Package: network-manager 1.10.6-2ubuntu1
ProcVersionSignature: Ubuntu 4.15.0-23.25-generic 4.15.18
Uname: Linux 4.15.0-23-generic x86_64
ApportVersion: 2.20.9-0ubuntu7.2
Architecture: amd64
CurrentDesktop: ubuntu:GNOME
Date: Thu Jun 28 15:08:56 2018
IfupdownConfig:
 # interfaces(5) file used by ifup(8) and ifdown(8)
 auto lo
 iface lo inet loopback
InstallationDate: Installed on 2018-04-25 (63 days ago)
InstallationMedia: Ubuntu 18.04 LTS "Bionic Beaver" - Beta amd64 (20180404)
IpRoute:
 default via 100.120.136.158 dev wwp0s20f0u6i12 proto static metric 700
 10.134.178.0/24 dev lxdbr0 proto kernel scope link src 10.134.178.1
 100.120.136.156/30 dev wwp0s20f0u6i12 proto kernel scope link src 100.120.136.157 metric 700
 169.254.0.0/16 dev lxdbr0 scope link metric 1000
NetworkManager.state:
 [main]
 NetworkingEnabled=true
 WirelessEnabled=false
 WWANEnabled=true
SourcePackage: network-manager
UpgradeStatus: No upgrade log present (probably fresh install)
nmcli-nm:
 RUNNING VERSION STATE STARTUP CONNECTIVITY NETWORKING WIFI-HW WIFI WWAN-HW WWAN
 running 1.10.6 connected started full enabled enabled disabled enabled enabled

[tho (treeshateorcs)]

have you found a workaround for this? I'm having the same issue with T450s and EM7345