ModemManager fails to reinitialize a Sierra modem on repeated suspend/resume
Description of the bug
When a laptop with internal Sierra Wireless EM7455 modem (configured for fast enumeration) is rapidly repeatedly suspended and resumed, on second resume ModemManager fails to acquire and initialize the modem.
Expected behavior I didn't see
- ModemManager detects, initializes and exports the internal modem when it reappears after resume
Unexpected behavior I saw
- ModemManager does not re-detect and re-initialize the modem
Steps to reproduce
- Get a EM7455 or (I suspect) any similar MBIM modem
- Configure it for fast enumeration on warm boot (
AT!CUSTOM="FASTENUMEN",2
) - Suspend and resume the host
- Just after ModemManager detects the modem and spawns mbim-proxy, suspend and resume the host again
- Observe that ModemManager does not reinitialize the modem
Logs
$ journalctl -f -u ModemManager
-- Logs begin at Fri 2019-03-08 10:46:21 MSK. --
Apr 01 02:49:39 able systemd[1]: Starting Modem Manager...
Apr 01 02:49:39 able ModemManager[2404]: <info> ModemManager (version 1.10.0) starting in system bus...
Apr 01 02:49:39 able systemd[1]: Started Modem Manager.
Apr 01 02:49:41 able ModemManager[2404]: opening device...
Apr 01 02:49:41 able ModemManager[2404]: cannot connect to proxy: Could not connect: Connection refused
Apr 01 02:49:41 able ModemManager[2404]: spawning new mbim-proxy (try 1)...
Apr 01 02:49:41 able ModemManager[2404]: [/dev/cdc-wdm0] Read max control message size from descriptors file: 4096
Apr 01 02:49:42 able ModemManager[2404]: <info> Couldn't check support for device '/sys/devices/pci0000:00/0000:00:1c.0/0000:02:00.0': not supported by any plugin
Apr 01 02:49:42 able ModemManager[2404]: <info> Couldn't check support for device '/sys/devices/pci0000:00/0000:00:1f.6': not supported by any plugin
Apr 01 02:49:44 able ModemManager[2404]: [/dev/cdc-wdm0] channel destroyed
Apr 01 02:49:57 able ModemManager[2404]: <info> [device /sys/devices/pci0000:00/0000:00:14.0/usb1/1-6] creating modem with plugin 'Sierra' and '5' ports
Apr 01 02:49:57 able ModemManager[2404]: <warn> Could not grab port (tty/ttyUSB2): 'Cannot add port 'tty/ttyUSB2', unhandled serial type'
Apr 01 02:49:57 able ModemManager[2404]: <warn> Could not grab port (tty/ttyUSB1): 'Cannot add port 'tty/ttyUSB1', unhandled serial type'
Apr 01 02:49:57 able ModemManager[2404]: <info> Modem for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6' successfully created
Apr 01 02:49:57 able ModemManager[2404]: opening device...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Read max control message size from descriptors file: 4096
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Opening device with flags 'version-info, proxy, mbim, expect-indications'...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] loaded driver of cdc-wdm port: cdc_mbim
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] creating MBIM device...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] MBIM device created
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] opening MBIM device...
Apr 01 02:49:57 able ModemManager[2404]: opening device...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Read max control message size from descriptors file: 4096
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] MBIM device open
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Checking version info (15 retries)...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] sending message as MBIM...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Received MBIM message
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] QMI Device supports 34 services:
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] ctl (1.5)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] wds (1.67)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] dms (1.14)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] nas (1.25)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] qos (1.6)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] wms (1.10)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] auth (1.3)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] at (1.2)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] voice (2.1)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] cat2 (2.24)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] uim (1.45)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] pbm (1.4)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] test (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] loc (2.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] sar (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] ts (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] tmd (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] wda (1.16)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] csvt (1.1)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] coex (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] pdc (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] rfrpe (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] dsd (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] ssctl (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] unknown [0x2e] (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] unknown [0x30] (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] unknown [0x31] (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] unknown [0x36] (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] rms (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] unknown [0xf0] (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] unknown [0xf3] (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] unknown [0xf5] (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] unknown [0xf6] (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] unknown [0xfc] (1.0)
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Enabling QMI indications via MBIM...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] enabled QMI indications via MBIM
Apr 01 02:49:57 able ModemManager[2404]: <info> [cdc-wdm0] MBIM device is QMI capable
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Allocating new client ID...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] sending message as MBIM...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Received MBIM message
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Registered 'dms' (version 1.14) client with ID '3'
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Allocating new client ID...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] sending message as MBIM...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Received MBIM message
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Registered 'nas' (version 1.25) client with ID '4'
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Allocating new client ID...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] sending message as MBIM...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Received MBIM message
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Registered 'loc' (version 2.0) client with ID '1'
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] sending message as MBIM...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Received MBIM message
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] sending message as MBIM...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Received MBIM message
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] sending message as MBIM...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Received MBIM message
Apr 01 02:49:57 able ModemManager[2404]: <info> QMI-based capability and mode switching support enabled
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] sending message as MBIM...
Apr 01 02:49:57 able ModemManager[2404]: [/dev/cdc-wdm0] Received MBIM message
Apr 01 02:49:58 able ModemManager[2404]: [/dev/cdc-wdm0] sending message as MBIM...
Apr 01 02:49:58 able ModemManager[2404]: [/dev/cdc-wdm0] Received MBIM message
Apr 01 02:49:58 able ModemManager[2404]: [/dev/cdc-wdm0] sending message as MBIM...
Apr 01 02:49:58 able ModemManager[2404]: [/dev/cdc-wdm0] Received MBIM message
Apr 01 02:49:58 able ModemManager[2404]: <warn> couldn't load UE mode of operation for EPS: 'No AT port available to run command'
Apr 01 02:49:58 able ModemManager[2404]: <warn> couldn't load initial EPS bearer settings: 'NoDeviceSupport'
Apr 01 02:49:58 able ModemManager[2404]: [/dev/cdc-wdm0] sending message as MBIM...
Apr 01 02:49:58 able ModemManager[2404]: [/dev/cdc-wdm0] Received MBIM message
Apr 01 02:49:58 able ModemManager[2404]: [/dev/cdc-wdm0] sending message as MBIM...
Apr 01 02:49:58 able ModemManager[2404]: [/dev/cdc-wdm0] Received MBIM message
Apr 01 02:49:58 able ModemManager[2404]: <warn> Couldn't open ports during Modem SIM hot swap enabling: Couldn't get primary port
Apr 01 02:49:58 able ModemManager[2404]: <info> Modem: state changed (unknown -> disabled)
Apr 01 02:49:58 able ModemManager[2404]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (disabled -> enabling)
Apr 01 02:49:58 able ModemManager[2404]: <info> Simple connect started...
Apr 01 02:49:58 able ModemManager[2404]: <info> Simple connect state (4/8): Wait to get fully enabled
Apr 01 02:49:59 able ModemManager[2404]: <warn> Failure
Apr 01 02:49:59 able ModemManager[2404]: [/dev/cdc-wdm0] sending message as MBIM...
Apr 01 02:49:59 able ModemManager[2404]: [/dev/cdc-wdm0] Received MBIM message
Apr 01 02:49:59 able ModemManager[2404]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (unknown -> searching)
Apr 01 02:49:59 able ModemManager[2404]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (enabling -> searching)
Apr 01 02:49:59 able ModemManager[2404]: <info> Simple connect state (5/8): Register
Apr 01 02:49:59 able ModemManager[2404]: [/dev/cdc-wdm0] sending message as MBIM...
Apr 01 02:49:59 able ModemManager[2404]: [/dev/cdc-wdm0] Received MBIM message
Apr 01 02:50:33 able ModemManager[2404]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (searching -> registering)
Apr 01 02:50:33 able ModemManager[2404]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: 3GPP Registration state changed (registering -> home)
Apr 01 02:50:33 able ModemManager[2404]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (searching -> registered)
Apr 01 02:50:33 able ModemManager[2404]: <info> Simple connect state (6/8): Bearer
Apr 01 02:50:33 able ModemManager[2404]: <info> Simple connect state (7/8): Connect
Apr 01 02:50:33 able ModemManager[2404]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (registered -> connecting)
Apr 01 02:50:34 able ModemManager[2404]: <info> Modem /org/freedesktop/ModemManager1/Modem/0: state changed (connecting -> connected)
Apr 01 02:50:34 able ModemManager[2404]: <info> Simple connect state (8/8): All done
<first suspend/resume cycle>
Apr 01 02:50:51 able ModemManager[2404]: [/dev/cdc-wdm0] channel destroyed
Apr 01 02:50:51 able ModemManager[2404]: [/dev/cdc-wdm0] channel destroyed
Apr 01 02:50:51 able ModemManager[2404]: [/dev/cdc-wdm0] QMI client for service 'dms' with CID '3' wasn't released
Apr 01 02:50:51 able ModemManager[2404]: [/dev/cdc-wdm0] QMI client for service 'nas' with CID '4' wasn't released
Apr 01 02:50:51 able ModemManager[2404]: [/dev/cdc-wdm0] QMI client for service 'loc' with CID '1' wasn't released
Apr 01 02:51:03 able ModemManager[2404]: <info> Couldn't check support for device '/sys/devices/pci0000:00/0000:00:1c.0/0000:02:00.0': not supported by any plugin
Apr 01 02:51:03 able ModemManager[2404]: <info> Couldn't check support for device '/sys/devices/pci0000:00/0000:00:1f.6': not supported by any plugin
Apr 01 02:51:05 able ModemManager[2404]: opening device...
Apr 01 02:51:05 able ModemManager[2404]: [/dev/cdc-wdm0] Read max control message size from descriptors file: 4096
<second suspend/resume cycle>
Apr 01 02:51:21 able ModemManager[2404]: <warn> (ttyUSB0) could not open serial device (2)
Apr 01 02:51:21 able ModemManager[2404]: <warn> [plugin manager] task 5,ttyUSB0: error when checking support with plugin 'Generic': '(tty/ttyUSB0) failed to open port: Could not open serial device ttyUSB0: No such file or directory'
Apr 01 02:51:21 able ModemManager[2404]: [/dev/cdc-wdm0] unexpected port hangup!
Apr 01 02:51:21 able ModemManager[2404]: [/dev/cdc-wdm0] channel destroyed
Apr 01 02:51:24 able ModemManager[2404]: <info> Couldn't check support for device '/sys/devices/pci0000:00/0000:00:1c.0/0000:02:00.0': not supported by any plugin
Apr 01 02:51:24 able ModemManager[2404]: <info> Couldn't check support for device '/sys/devices/pci0000:00/0000:00:1f.6': not supported by any plugin
Apr 01 02:51:26 able ModemManager[2404]: <info> Couldn't check support for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6': Device support check task already available for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6'
Apr 01 02:51:26 able ModemManager[2404]: <info> Couldn't check support for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6': Device support check task already available for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6'
Apr 01 02:51:26 able ModemManager[2404]: <info> Couldn't check support for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6': Device support check task already available for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6'
Apr 01 02:51:26 able ModemManager[2404]: <info> Couldn't check support for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6': Device support check task already available for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6'
Apr 01 02:51:26 able ModemManager[2404]: <info> Couldn't check support for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6': Device support check task already available for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6'
Apr 01 02:51:42 able ModemManager[2404]: proxy configuration failed: closed
Apr 01 02:51:42 able ModemManager[2404]: <info> [device /sys/devices/pci0000:00/0000:00:14.0/usb1/1-6] creating modem with plugin 'Sierra' and '2' ports
Apr 01 02:51:42 able ModemManager[2404]: <warn> Could not grab port (usbmisc/cdc-wdm0): 'Cannot add port 'usbmisc/cdc-wdm0', unsupported'
Apr 01 02:51:42 able ModemManager[2404]: <warn> Couldn't create modem for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6': Failed to find primary AT port
Sometimes the final messages are different:
<some time after second suspend/resume cycle>
Apr 01 02:44:12 able ModemManager[763]: proxy configuration failed: closed
Apr 01 02:44:12 able ModemManager[763]: <info> [device /sys/devices/pci0000:00/0000:00:14.0/usb1/1-6] creating modem with plugin 'Sierra' and '5' ports
Apr 01 02:44:12 able ModemManager[763]: <warn> Could not grab port (tty/ttyUSB1): 'Cannot add port 'tty/ttyUSB1', unhandled serial type'
Apr 01 02:44:12 able ModemManager[763]: <warn> Could not grab port (usbmisc/cdc-wdm0): 'Cannot add port 'usbmisc/cdc-wdm0', unsupported'
Apr 01 02:44:12 able ModemManager[763]: <info> Modem for device '/sys/devices/pci0000:00/0000:00:14.0/usb1/1-6' successfully created
Apr 01 02:44:12 able ModemManager[763]: <warn> couldn't initialize the modem: 'Operation was cancelled'