MC7750 missing SIM until ModemManager restart

Wed Oct 10 07:40:56 UTC 2018

Hey,

> Having an odd issue where ModemManager has trouble reading SIM PIN status from Sierra MC7750 (Verizon US, LTE+CDMA, QMI interface) modules after a modem reset.
>
>
> At first system boot, MM has no issue detecting the modem and activating a connection. These are in mobile devices, so it's common to lose signal and later need to reconnect when back in a coverage area. These modems can be a little cranky, and sometimes at this point won't build a data connection after repeated attempts (known Qualcomm-level issue according to Sierra), so we have a separate process that watches for that and issues a Reset() via the MM DBus interface. Reset() on these does a "full power cycle", as if the modem was unplugged from USB and plugged back in.
>
>
> When the device turns back on, during detection NM says it doesn't have a SIM object:
>
> NetworkManager[6651]: <info>  [1539101206.9778] modem-broadband[cdc-wdm1]: failed to retrieve SIM object: No SIM object available
>
>
> MM reports this:
>
> ModemManager[8643]: <warn>  Couldn't load unlock retries: 'Couldn't get unlock retries: QMI protocol error (3): 'Internal''
> ModemManager[8643]: <warn>  couldn't load list of Own Numbers: 'Couldn't get MSISDN: QMI protocol error (25): 'DeviceUnsupported''
>
>
> Looking into MM debug logs, it's failing the "UIM Get PIN Status" step, the first time for IncorrectPin, then Internal QMI error for the rest of the retries. The SIMs don't have a PIN we're aware of.
>
> <debug> [1539101547.534249] [mm-iface-modem.c:3902] load_current_capabilities_ready(): Setting EPS network as supported
> <debug> [1539101547.538395] [mm-iface-modem.c:3928] load_current_capabilities_ready(): Checking if multimode device has a SIM...
> <debug> [1539101547.542528] [mm-broadband-modem-qmi.c:1845] load_unlock_required_context_step(): loading unlock required (DMS)...
> [/dev/cdc-wdm1] sent message...
> <<<<<< RAW:
> <<<<<<   length = 13
> <<<<<<   data   = 01:0C:00:00:02:01:00:02:00:2B:00:00:00
> [/dev/cdc-wdm1] sent generic request (translated)...
> <<<<<< QMUX:
> <<<<<<   length  = 12
> <<<<<<   flags   = 0x00
> <<<<<<   service = "dms"
> <<<<<<   client  = 1
> <<<<<< QMI:
> <<<<<<   flags       = "none"
> <<<<<<   transaction = 2
> <<<<<<   tlv_length  = 0
> <<<<<<   message     = "UIM Get PIN Status" (0x002B)
> [/dev/cdc-wdm1] received message...
> <<<<<< RAW:
> <<<<<<   length = 20
> <<<<<<   data   = 01:13:00:80:02:01:02:02:00:2B:00:07:00:02:04:00:01:00:0C:00
> [/dev/cdc-wdm1] received generic response (translated)...
> <<<<<< QMUX:
> <<<<<<   length  = 19
> <<<<<<   flags   = 0x80
> <<<<<<   service = "dms"
> <<<<<<   client  = 1
> <<<<<< QMI:
> <<<<<<   flags       = "response"
> <<<<<<   transaction = 2
> <<<<<<   tlv_length  = 7
> <<<<<<   message     = "UIM Get PIN Status" (0x002B)
> <<<<<< TLV:
> <<<<<<   type       = "Result" (0x02)
> <<<<<<   length     = 4
> <<<<<<   value      = 01:00:0C:00
> <<<<<<   translated = FAILURE: IncorrectPin
> <debug> [1539101547.550223] [mm-iface-modem.c:268] load_unlock_required_ready(): Couldn't check if unlock required: 'Couldn't get PIN status: QMI protocol error (12): 'IncorrectPin''
>
> (removed retries 1-5 here, they're identical)
>
>
> <debug> [1539101558.280189] [mm-iface-modem.c:292] load_unlock_required_ready(): Retrying (6) unlock required check
> <debug> [1539101560.270256] [mm-broadband-modem-qmi.c:1845] load_unlock_required_context_step(): loading unlock required (DMS)...
> [/dev/cdc-wdm1] sent message...
> <<<<<< RAW:
> <<<<<<   length = 13
> <<<<<<   data   = 01:0C:00:00:02:01:00:08:00:2B:00:00:00
> [/dev/cdc-wdm1] sent generic request (translated)...
> <<<<<< QMUX:
> <<<<<<   length  = 12
> <<<<<<   flags   = 0x00
> <<<<<<   service = "dms"
> <<<<<<   client  = 1
> <<<<<< QMI:
> <<<<<<   flags       = "none"
> <<<<<<   transaction = 8
> <<<<<<   tlv_length  = 0
> <<<<<<   message     = "UIM Get PIN Status" (0x002B)
> [/dev/cdc-wdm1] received message...
> <<<<<< RAW:
> <<<<<<   length = 20
> <<<<<<   data   = 01:13:00:80:02:01:02:08:00:2B:00:07:00:02:04:00:01:00:03:00
> [/dev/cdc-wdm1] received generic response (translated)...
> <<<<<< QMUX:
> <<<<<<   length  = 19
> <<<<<<   flags   = 0x80
> <<<<<<   service = "dms"
> <<<<<<   client  = 1
> <<<<<< QMI:
> <<<<<<   flags       = "response"
> <<<<<<   transaction = 8
> <<<<<<   tlv_length  = 7
> <<<<<<   message     = "UIM Get PIN Status" (0x002B)
> <<<<<< TLV:
> <<<<<<   type       = "Result" (0x02)
> <<<<<<   length     = 4
> <<<<<<   value      = 01:00:03:00
> <<<<<<   translated = FAILURE: Internal
> <debug> [1539101560.278384] [mm-iface-modem.c:268] load_unlock_required_ready(): Couldn't check if unlock required: 'Couldn't get PIN status (retry): QMI protocol error (3): 'Internal''
> <debug> [1539101560.282222] [mm-iface-modem.c:3864] current_capabilities_internal_load_unlock_required_ready(): Multimode device without SIM, no 3GPP capabilities
>
>
>
> Running (what I think is) the equivalent status command via qmicli directly, it looks like it works:
>
> [root at hostname ~]# qmicli -p -d /dev/cdc-wdm1 --dms-uim-get-pin-status
> [/dev/cdc-wdm1] PIN status retrieved successfully
> [/dev/cdc-wdm1] PIN1:
>         Status: disabled
>         Verify: 3
>         Unblock: 10
> [/dev/cdc-wdm1] PIN2:
>         Status: enabled-not-verified
>         Verify: 3
>         Unblock: 10
>
>
> Here's the odd part - this only happens if the modem is reset while MM is running. If I do a 'systemctl restart ModemManager' at this point, the modem+SIM are detected right away, and all is well.  That's my workaround right now, but I'd rather not be restarting services if I can help it: we have 2 modules in the system (second one is either a MC7700 or MC7354) and restarting MM disrupts the other data session. No detection issues from either one of those models.
>
>
> We're using the RHEL7 delivered MM build, 1.6.10, with libqmi 1.18.0.  Both appear unmodified according to the RPM specfile, no odd patches, etc.
>
>
> Any ideas where to look next? Thanks in advance!
>

This could be a timing issue of some sort, it doesnt' make sense that
you get a different reply when manually running the "DMS UIM Get Pin
Status" message. My assumption here is that we may need more retries,
or more time between retries, or something like that, but it will be
an ugly hack anyway as it's replying "IncorrectPin" for a while, then
"Internal" error and then finally that the PIN is disabled. Very
weird.

Could you try to manually run --uim-get-card-status as well during
your tests? Trying to see whether that will give us any better
indication of whether the sim info is still being loaded or fully
ready, before we query pin status.

-- 
Aleksander
https://aleksander.es