Random MM and/or qmi-proxy hang?

[Bowden, Brendan]

Hello,

Not sure if this is actually MM or libqmi related, so trying here first; let me know if I need to take this to libqmi-devel instead.

Having an odd issue that seems to be tied to MM’s interaction with qmi-proxy. We’d been noticing that ModemManager will occasionally stop responding to DBus interaction on some machines at (what seems to be) random intervals. Both direct-to-DBus calls and `mmcli -L` on these will hang and eventually time out after ~30 seconds:

[root at host ~]#  mmcli -L
error: couldn't create manager: Timeout was reached

Restarting ModemManager does get it responding again, but not a great solution. These are mobile devices where we’re trying to keep cell connection active as much as possible. Checking further on another affected unit showed qmicli doesn’t respond either when this happens – each response is after a similar delay:

[root at host ~]# qmicli -d /dev/cdc-wdm0 -p --dms-get-model
error: couldn't open the QmiDevice: Couldn't spawn the qmi-proxy
[root at host ~]# qmicli -d /dev/cdc-wdm1 -p --dms-get-model
error: couldn't open the QmiDevice: Couldn't spawn the qmi-proxy

Killing qmi-proxy results in this sequence in MM debug logs, and it appears to respawn and start sending QMI commands again. We do see that “No way to load extended signal” error occasionally but it doesn’t seem to hurt anything in normal conditions.

ModemManager[2352]: <warn>  Couldn't load extended signal information: No way to load extended signal information
ModemManager[2352]: <warn>  Couldn't load extended signal information: No way to load extended signal information
ModemManager[2352]: <warn>  Couldn't load extended signal information: No way to load extended signal information
ModemManager[2352]: <warn>  Couldn't load extended signal information: No way to load extended signal information
ModemManager[2352]: <warn>  Couldn't load extended signal information: No way to load extended signal information
ModemManager[2352]: <warn>  Couldn't load extended signal information: No way to load extended signal information
(qmi-proxy killed here)
ModemManager[2352]: <debug> Couldn't refresh CDMA registration status: 'QMI operation failed: Transaction timed out'
ModemManager[2352]: <warn>  Reloading stats failed: QMI operation failed: Device must be open to send commands
ModemManager[2352]: <debug> Couldn't refresh signal quality: 'Device must be open to send commands'
ModemManager[2352]: <warn>  Reloading stats failed: QMI operation failed: Device must be open to send commands
ModemManager[2352]: <debug> Couldn't refresh signal quality: 'Device must be open to send commands'
ModemManager[2352]: <warn>  Couldn't load extended signal information: No way to load extended signal information
ModemManager[2352]: <warn>  Reloading stats failed: QMI operation failed: Cannot write message: Error sending data: Broken pipe
ModemManager[2352]: <debug> Couldn't refresh signal quality: 'Cannot write message: Error sending data: Broken pipe'
ModemManager[2352]: <debug> loading signal quality...
ModemManager[2352]: <debug> loading extended signal information...
ModemManager[2352]: Error reading from istream: Error receiving data: Connection reset by peer
ModemManager[2352]: <debug> loading signal quality...
ModemManager[2352]: <debug> loading extended signal information...
ModemManager[2352]: Error reading from istream: Error receiving data: Connection reset by peer
C0:00:00:00#010<<<<<<   translated = tx-bytes-ok, rx-bytes-ok
ModemManager[2352]: [/dev/cdc-wdm1] sent message...#010<<<<<< RAW:#010<<<<<<   length = 20#010<<<<<<   data   = 01:13:00:00:01:01:00:F4:01:24:00:07:00:01:04:00:C0:00:00:00
= "none"#010<<<<<<   transaction = 4094#010<<<<<<   tlv_length  = 0#010<<<<<<   message     = "Get Signal Strength" (0x0020)
ModemManager[2352]: [/dev/cdc-wdm1] sent message...#010<<<<<< RAW:#010<<<<<<   length = 13#010<<<<<<   data   = 01:0C:00:00:03:01:00:FE:0F:20:00:00:00
ModemManager[2352]: <debug> loading signal quality...
= "none"#010<<<<<<   transaction = 4093#010<<<<<<   tlv_length  = 0#010<<<<<<   message     = "Get Signal Info" (0x004F)
ModemManager[2352]: [/dev/cdc-wdm1] sent message...#010<<<<<< RAW:#010<<<<<<   length = 13#010<<<<<<   data   = 01:0C:00:00:03:01:00:FD:0F:4F:00:00:00
ModemManager[2352]: <debug> loading extended signal information...
ModemManager[2352]: <warn>  Couldn't load extended signal information: No way to load extended signal information
     = EF:00#010<<<<<<   translated = rssi, ecio, io, sinr, rsrq, lte-snr, lte-rsrp
ModemManager[2352]: [/dev/cdc-wdm0] sent message...#010<<<<<< RAW:#010<<<<<<   length = 18#010<<<<<<   data   = 01:11:00:00:03:01:00:0E:0E:20:00:05:00:10:02:00:EF:00
= "none"#010<<<<<<   transaction = 3597#010<<<<<<   tlv_length  = 0#010<<<<<<   message     = "Get Signal Info" (0x004F)
                (and so on)

This is RHEL7 so I’m using the 1.6 branch of MM and 1.18.0 libqmi; for MM I tried building our own 1.16.4 when we suspected MM being the core issue, with no change in behavior.

Any thoughts? Wanted to see about putting qmi-proxy in debug mode but I’m not sure how to do that when it’s already running (spawned by MM). Out of ~200 units I’ve got MM debug logging enabled on, 3-4 would get into this state after 24 hours, so reproducibility is a problem; haven’t found a way to trigger this condition on cue yet. As background info, each unit (3500 out there) has two Sierra modems, could be any combination of MC7700, MC7750, MC7354 talking to AT&T or Verizon, both LTE and 3G.

Thanks,

-- Brendan Bowden


This message w/attachments (message) is intended solely for the use of the intended recipient(s) and may contain information that is privileged, confidential or proprietary. If you are not an intended recipient, please notify the sender, and then please delete and destroy all copies and attachments. Please be advised that any review or dissemination of, or the taking of any action in reliance on, the information contained in or attached to this message is prohibited.
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20190312/924cc287/attachment-0001.html>