modem timeouts in ModemManager (+ old audio being transmitted)
Just ran into a timing out modem (see calls#178)
which after some more poking lead to the following weird situation (copy of the post in calls#178):
Just had the same thing happening and I'm adding some more information from the logs (including the hickups from the modem).
Mar 29 15:26:49 poseidon ModemManager[528]: Cannot read from istream: connection broken
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] QMI endpoint hangup: removed
Mar 29 15:26:49 poseidon ModemManager[528]: <info> [modem0] connection to qmi-proxy for /dev/cdc-wdm0 lost, reprobing
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'voice' client with flags 'release-cid'...
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'voice' client with ID '1'
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'pdc' client with flags 'release-cid'...
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'pdc' client with ID '1'
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'loc' client with flags 'release-cid'...
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'loc' client with ID '1'
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'uim' client with flags 'release-cid'...
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'uim' client with ID '1'
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'wms' client with flags 'release-cid'...
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'wms' client with ID '1'
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'nas' client with flags 'release-cid'...
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'nas' client with ID '1'
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'dms' client with flags 'release-cid'...
Mar 29 15:26:49 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'dms' client with ID '1'
Mar 29 15:26:49 poseidon ModemManager[528]: <info> [base-manager] port ttyUSB1 released by device '/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4>
Mar 29 15:26:49 poseidon ModemManager[528]: <info> [base-manager] port ttyUSB2 released by device '/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4>
Mar 29 15:26:49 poseidon ModemManager[528]: <info> [base-manager] port ttyUSB3 released by device '/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4>
Mar 29 15:26:49 poseidon ModemManager[528]: <info> [base-manager] port ttyUSB0 released by device '/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4>
Mar 29 15:26:49 poseidon ModemManager[528]: <info> [base-manager] port cdc-wdm0 released by device '/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.>
Mar 29 15:26:49 poseidon ModemManager[528]: <info> [base-manager] port wwx2e37c7b2b333 released by device '/sys/devices/platform/soc@0/38200000.usb/xh>
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] Opening device with flags 'version-info, proxy'...
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] created endpoint
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] Checking version info (25 retries)...
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] QMI Device supports 30 services:
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] ctl (1.5)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] wds (1.67)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] dms (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] nas (1.25)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] qos (1.12)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] wms (1.10)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] auth (1.3)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] at (1.4)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] voice (2.1)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] cat2 (2.24)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] uim (1.46)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] pbm (1.4)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] test (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] loc (2.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] sar (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] ims (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] csd (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] ts (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] tmd (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] wda (1.16)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] csvt (1.1)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] imsp (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] imsa (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] coex (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] pdc (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] rfrpe (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] dsd (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] unknown [0x2d] (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] unknown [0x30] (1.0)
Mar 29 15:26:51 poseidon ModemManager[528]: [/dev/cdc-wdm0] unknown [0x36] (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: <info> [device /sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/1-1.2] creating modem wit>
Mar 29 15:26:52 poseidon ModemManager[528]: <info> [base-manager] modem for device '/sys/devices/platform/soc@0/38200000.usb/xhci-hcd.4.auto/usb1/1-1/>
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Opening device with flags 'version-info, proxy'...
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] created endpoint
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Checking version info (25 retries)...
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] QMI Device supports 30 services:
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] ctl (1.5)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] wds (1.67)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] dms (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] nas (1.25)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] qos (1.12)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] wms (1.10)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] auth (1.3)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] at (1.4)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] voice (2.1)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] cat2 (2.24)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] uim (1.46)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] pbm (1.4)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] test (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] loc (2.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] sar (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] ims (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] csd (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] ts (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] tmd (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] wda (1.16)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] csvt (1.1)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] imsp (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] imsa (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] coex (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] pdc (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] rfrpe (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] dsd (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] unknown [0x2d] (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] unknown [0x30] (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] unknown [0x36] (1.0)
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Reading expected data format from: /sys/class/net/wwx2e37c7b2b333/qmi/raw_ip
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Allocating new client ID...
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Registered 'wda' (version 1.16) client with ID '1'
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Writing expected data format to: /sys/class/net/wwx2e37c7b2b333/qmi/raw_ip
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Reading expected data format from: /sys/class/net/wwx2e37c7b2b333/qmi/raw_ip
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Allocating new client ID...
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'wda' client with flags 'release-cid'...
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'wda' client with ID '1'
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Registered 'dms' (version 1.0) client with ID '1'
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Allocating new client ID...
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Registered 'nas' (version 1.25) client with ID '1'
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Allocating new client ID...
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Registered 'wms' (version 1.10) client with ID '1'
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Allocating new client ID...
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Registered 'uim' (version 1.46) client with ID '1'
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Allocating new client ID...
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Registered 'loc' (version 2.0) client with ID '1'
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Allocating new client ID...
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Registered 'pdc' (version 1.0) client with ID '1'
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Allocating new client ID...
Mar 29 15:26:52 poseidon ModemManager[528]: [/dev/cdc-wdm0] Registered 'voice' (version 2.1) client with ID '1'
Mar 29 15:26:52 poseidon ModemManager[528]: <warn> [modem1/sim1] couldn't load list of emergency numbers: uninitialized emergency numbers list
Mar 29 15:26:52 poseidon ModemManager[528]: <warn> [modem1] couldn't load facility locks: QMI protocol error (94): 'NotSupported'
Mar 29 15:26:53 poseidon ModemManager[528]: <info> [modem1] state changed (unknown -> disabled)
Mar 29 15:26:53 poseidon ModemManager[528]: <info> [modem1] state changed (disabled -> enabling)
Mar 29 15:26:53 poseidon ModemManager[528]: [/dev/cdc-wdm0] Allocating new client ID...
Mar 29 15:26:53 poseidon ModemManager[528]: [/dev/cdc-wdm0] Registered 'wds' (version 1.67) client with ID '1'
Mar 29 15:26:53 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'wds' client with flags 'release-cid'...
Mar 29 15:26:53 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'wds' client with ID '1'
Mar 29 15:26:53 poseidon ModemManager[528]: <info> [modem1] state changed (enabling -> enabled)
Mar 29 15:26:53 poseidon ModemManager[528]: <info> [modem1] 3GPP registration state changed (unknown -> registering)
Mar 29 15:26:53 poseidon ModemManager[528]: <info> [modem1] 3GPP registration state changed (registering -> home)
Mar 29 15:26:53 poseidon ModemManager[528]: <info> [modem1] state changed (enabled -> registered)
Mar 29 15:27:01 poseidon ModemManager[528]: <warn> [modem1] couldn't load network timezone from the current network
Mar 29 15:28:48 poseidon ModemManager[528]: <info> [modem1/call3] user request to start call
Mar 29 15:28:48 poseidon ModemManager[528]: <info> [modem1/call3] call state changed: unknown -> dialing (outgoing-started)
Mar 29 15:29:47 poseidon ModemManager[528]: <info> [modem1/call3] user request to hangup call
Mar 29 15:29:53 poseidon ModemManager[528]: <info> [modem1/call3] user request to hangup call
Mar 29 15:30:19 poseidon ModemManager[528]: <warn> [modem1/call3] couldn't start call: Serial command timed out
Mar 29 15:30:19 poseidon ModemManager[528]: <info> [modem1/call3] call state changed: dialing -> terminated (unknown)
Mar 29 15:30:19 poseidon ModemManager[528]: <warn> [modem1] port ttyUSB1 timed out 2 consecutive times
Mar 29 15:30:24 poseidon ModemManager[528]: <warn> [modem1] couldn't load call list: Serial command timed out
Mar 29 15:30:24 poseidon ModemManager[528]: <warn> [modem1] port ttyUSB1 timed out 3 consecutive times
Mar 29 15:30:26 poseidon ModemManager[528]: <warn> [modem1] port ttyUSB1 timed out 4 consecutive times
Trying again to place a call:
Mar 29 15:30:28 poseidon ModemManager[528]: <warn> [modem1] port ttyUSB1 timed out 5 consecutive times
Mar 29 15:34:33 poseidon ModemManager[528]: <info> [modem1/call4] user request to start call
Mar 29 15:34:33 poseidon ModemManager[528]: <info> [modem1/call4] call state changed: unknown -> dialing (outgoing-started)
Mar 29 15:35:34 poseidon ModemManager[528]: <info> [modem1/call4] user request to hangup call
Mar 29 15:35:38 poseidon ModemManager[528]: <info> [modem1/call4] user request to hangup call
Mar 29 15:35:41 poseidon ModemManager[528]: <info> [modem1/call4] user request to hangup call
Mar 29 15:35:53 poseidon ModemManager[528]: <info> [modem1/call4] user request to hangup call
Mar 29 15:36:00 poseidon ModemManager[528]: <info> [modem1/call4] user request to hangup call
Mar 29 15:36:04 poseidon ModemManager[528]: <warn> [modem1/call4] couldn't start call: Serial command timed out
Mar 29 15:36:04 poseidon ModemManager[528]: <info> [modem1/call4] call state changed: dialing -> terminated (unknown)
Mar 29 15:36:04 poseidon ModemManager[528]: <warn> [modem1] port ttyUSB1 timed out 6 consecutive times
Mar 29 15:36:09 poseidon ModemManager[528]: <warn> [modem1] couldn't load call list: Serial command timed out
Mar 29 15:36:09 poseidon ModemManager[528]: <warn> [modem1] port ttyUSB1 timed out 7 consecutive times
Mar 29 15:36:11 poseidon ModemManager[528]: <warn> [modem1] port ttyUSB1 timed out 8 consecutive times
Mar 29 15:36:13 poseidon ModemManager[528]: <warn> [modem1] port ttyUSB1 timed out 9 consecutive times
Mar 29 15:36:15 poseidon ModemManager[528]: <error> [modem1] port ttyUSB1 timed out 10 consecutive times, marking modem as invalid
Mar 29 15:36:15 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'voice' client with flags 'release-cid'...
Mar 29 15:36:15 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'voice' client with ID '1'
Mar 29 15:36:15 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'pdc' client with flags 'release-cid'...
Mar 29 15:36:15 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'pdc' client with ID '1'
Mar 29 15:36:15 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'loc' client with flags 'release-cid'...
Mar 29 15:36:15 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'loc' client with ID '1'
Mar 29 15:36:15 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'uim' client with flags 'release-cid'...
Mar 29 15:36:15 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'uim' client with ID '1'
Mar 29 15:36:15 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'wms' client with flags 'release-cid'...
Mar 29 15:36:15 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'wms' client with ID '1'
Mar 29 15:36:15 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'nas' client with flags 'release-cid'...
Mar 29 15:36:15 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'nas' client with ID '1'
Mar 29 15:36:15 poseidon ModemManager[528]: [/dev/cdc-wdm0] Releasing 'dms' client with flags 'release-cid'...
Mar 29 15:36:15 poseidon ModemManager[528]: [/dev/cdc-wdm0] Unregistered 'dms' client with ID '1'
Mar 29 15:36:18 poseidon ModemManager[528]: transaction 0xe aborted, but message is not abortable
Mar 29 15:36:18 poseidon ModemManager[528]: transaction 0xf aborted, but message is not abortable
Mar 29 15:36:18 poseidon ModemManager[528]: transaction 0x10 aborted, but message is not abortable
Mar 29 15:36:18 poseidon ModemManager[528]: transaction 0x11 aborted, but message is not abortable
Mar 29 15:36:18 poseidon ModemManager[528]: transaction 0x12 aborted, but message is not abortable
Mar 29 15:36:18 poseidon ModemManager[528]: transaction 0x13 aborted, but message is not abortable
Mar 29 15:36:18 poseidon ModemManager[528]: transaction 0x14 aborted, but message is not abortable
And the modem is gone :'(
After enganging and disengaging the killswitch the modem comes back online.
I did try placing a call which did work. But interestingly that transmitted audio is NOT current. I noticed this because I could hear myself typing, while I was not actually typing :? Also I could hear some music (which according to my playlist I listened to more about half an hour ago). what the ...?