SIM hot swap with SIM locked

Fri Mar 17 10:15:38 UTC 2017

Hi,

I'm working on a fix for the problem observed in "[PATCH] telit:
lock/unlock CSIM operations by default" thread:

> when SIM is locked and then unlocked, with SIM hot swap enabled, we
receive an unsolicited "#QSS: 1", which is not related to any physical SIM
insertion, and release the modem:
>
>
> mar 16 09:55:00 d2092 ModemManager[542]: <debug> (ttyACM0): -->
'AT+CSQ<CR>'
> mar 16 09:55:00 d2092 ModemManager[542]: <debug> (ttyACM0): <-- '<CR><LF>'
> mar 16 09:55:00 d2092 ModemManager[542]: <debug> (ttyACM0): <-- '+CSQ:
9,4<CR><LF><CR><LF>OK<CR><LF>'
> mar 16 09:55:00 d2092 ModemManager[542]: <debug> (ttyACM0) device open
count is 3 (close)
> mar 16 09:55:00 d2092 ModemManager[542]: <debug> Modem
/org/freedesktop/ModemManager1/Modem/0: signal quality updated (29)
> mar 16 09:55:00 d2092 ModemManager[542]: <debug> Periodic signal quality
checks rescheduled (interval = 30s)
> mar 16 09:55:02 d2092 ModemManager[542]: <debug> (ttyACM3): <--
'<CR><LF>+CIEV: service,1<CR><LF>'
> mar 16 09:55:02 d2092 ModemManager[542]: <debug> (ttyACM3): <--
'<CR><LF>+CIEV: roam,0<CR><LF>'
> mar 16 09:55:05 d2092 ModemManager[542]: <debug> (ttyACM0) device open
count is 4 (open)
> mar 16 09:55:05 d2092 ModemManager[542]: <debug> (ttyACM0): -->
'AT+CCLK?<CR>'
> mar 16 09:55:05 d2092 ModemManager[542]: <debug> (ttyACM0): <-- '<CR><LF>'
> mar 16 09:55:05 d2092 ModemManager[542]: <debug> (ttyACM0): <-- '+CCLK:
"17/03/16,09:55:05+04"<CR><LF><CR><LF>OK<CR><LF>'
> mar 16 09:55:05 d2092 ModemManager[542]: <debug> (ttyACM0) device open
count is 3 (close)
> mar 16 09:55:09 d2092 ModemManager[542]: <debug> (ttyACM3): <--
'<CR><LF>#QSS: 1<CR><LF>'
> mar 16 09:55:09 d2092 ModemManager[542]: <info>  QSS: SIM inserted
> mar 16 09:55:09 d2092 ModemManager[542]: <debug> Releasing SIM hot swap
ports context

Working on a solution, I borrowed the Aleksander's proposal patch to trace
QSS values and to start SIM hot swap only on specific transitions (#QSS: 0
=> #QSS: [1|2|3] and vice versa), but I observed a different behavior when
the SIM is locked and when it's not, which I don't really understand.

This is the test sequence:

1. Modem attached with SIM locked
2. Unlock SIM
3. SIM removed (wait for the modem manager to reprobe)
4. SIM inserted back (wait for the modem manager to reprobe)

Here is the output of mmcli -M

> $ mmcli -M
>
> Found 1 modems:
>         /org/freedesktop/ModemManager1/Modem/0 [Telit] HE910-EUR
> Removed modem:
>         /org/freedesktop/ModemManager1/Modem/0 [Telit] HE910-EUR
> Added modem:
>         /org/freedesktop/ModemManager1/Modem/1 [unknown] unknown
> Removed modem:
>         /org/freedesktop/ModemManager1/Modem/1 [unknown] unknown
> Added modem:
>         /org/freedesktop/ModemManager1/Modem/0 [Telit] HE910-EUR

First of all, after SIM removal, the ModemManager seems unable to recognize
the modem again.
Moreover, when the sim is inserted back there is a crash (this is why the
modem id is 0 again in the last attach), very likely due to the incomplete
modem recognition:

> mar 17 09:13:38 D2040 ModemManager[24536]: mm_base_modem_set_reprobe:
assertion 'MM_IS_BASE_MODEM (self)' failed
> mar 17 09:13:38 D2040 systemd[1]: ModemManager.service: Main process
exited, code=dumped, status=11/SEGV
> mar 17 09:13:38 D2040 systemd[1]: ModemManager.service: Unit entered
failed state.
> mar 17 09:13:38 D2040 systemd[1]: ModemManager.service: Failed with
result 'core-dump'.

Comparing the logs with and without SIM locked (attached to this email), it
seems that after the SIM removal, the ModemManager skips several AT
commands (between AT+GCAP and AT+CPIN) while loading modem capabilities:

With SIM LOCKED

> mar 17 09:12:36 D2040 ModemManager[24536]: <debug> (ttyACM0): -->
'AT+GCAP<CR>'
> mar 17 09:12:36 D2040 ModemManager[24536]: <debug> (ttyACM0): <--
'<CR><LF>'
> mar 17 09:12:36 D2040 ModemManager[24536]: <debug> (ttyACM0): <-- '+GCAP:
+CGSM,+DS,+FCLASS,+MS,+ES<CR><LF><CR><LF>OK<CR><LF>'
> mar 17 09:12:38 D2040 ModemManager[24536]: <debug> (ttyACM0): -->
'ATI<CR>'
> mar 17 09:12:38 D2040 ModemManager[24536]: <debug> (ttyACM0): <--
'<CR><LF>'
> mar 17 09:12:38 D2040 ModemManager[24536]: <debug> (ttyACM0): <--
'332<CR><LF><CR><LF>OK<CR><LF>'
> mar 17 09:12:39 D2040 ModemManager[24536]: <debug> (ttyACM0): -->
'AT+CPIN?<CR>'
> mar 17 09:12:39 D2040 ModemManager[24536]: <debug> (ttyACM0): <--
'<CR><LF>+CME ERROR: 10<CR><LF>'
> mar 17 09:12:39 D2040 ModemManager[24536]: <debug> Got failure code 10:
SIM not inserted
> mar 17 09:12:40 D2040 ModemManager[24536]: <debug> (ttyACM0): -->
'AT+CGMM<CR>'
> mar 17 09:12:40 D2040 ModemManager[24536]: <debug> (ttyACM0): <--
'<CR><LF>'
> mar 17 09:12:40 D2040 ModemManager[24536]: <debug> (ttyACM0): <--
'HE910-EUR<CR><LF><CR><LF>OK<CR><LF>'
> mar 17 09:12:41 D2040 ModemManager[24536]: <debug> (ttyACM0) device open
count is 1 (close)
> mar 17 09:12:41 D2040 ModemManager[24536]: <warn>  Modem couldn't be
initialized: couldn't load current capabilities: Failed to determine modem
capabilities.
> mar 17 09:12:41 D2040 ModemManager[24536]: <debug> Couldn't initialize
interface: 'Firmware interface not available'
> mar 17 09:12:41 D2040 ModemManager[24536]: <debug> Creating PortsContext
for SIM hot swap.
> mar 17 09:12:41 D2040 ModemManager[24536]: <debug> (ttyACM0) device open
count is 2 (open)
> mar 17 09:12:41 D2040 ModemManager[24536]: <debug> (ttyACM3) opening
serial port...
> mar 17 09:12:41 D2040 ModemManager[24536]: <debug> (ttyACM3) device open
count is 1 (open)
> mar 17 09:12:41 D2040 ModemManager[24536]: <debug> (ttyACM3): running
init sequence...
> mar 17 09:12:41 D2040 ModemManager[24536]: <debug> (ttyACM0) device open
count is 1 (close)
> mar 17 09:12:41 D2040 ModemManager[24536]: <debug> modem properly
initialized

With SIM UNLOCKED

> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): -->
'AT+GCAP<CR>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <-- '+GCAP:
+CGSM,+DS,+FCLASS,+MS,+ES<CR><LF><CR><LF>OK<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 3 (open)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 2 (close)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): -->
'AT+WS46=?<CR>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <-- '+WS46:
(12,22,25)<CR><LF><CR><LF>OK<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> loaded current
capabilities: gsm-umts
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> Modem allows up to 1
bearers
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> Creating bearer list
(max: 1, max active: 1)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> loading manufacturer...
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 3 (open)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 2 (close)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): -->
'AT+CGMI<CR>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'Telit<CR><LF><CR><LF>OK<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> loaded manufacturer:
Telit
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> loading model...
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 3 (open)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 2 (close)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): -->
'AT+CGMM<CR>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'HE910-EUR<CR><LF><CR><LF>OK<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> loaded model: HE910-EUR
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> loading revision...
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 3 (open)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 2 (close)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): -->
'AT+CGMR<CR>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'12.00.208<CR><LF><CR><LF>OK<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> loaded revision:
12.00.208
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> loading equipment
identifier...
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 3 (open)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 2 (close)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): -->
'AT+CGSN<CR>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'359658044004697<CR><LF><CR><LF>OK<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> loaded equipment
identifier: 359658044004697
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> loading device
identifier...
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 3 (open)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 2 (close)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): -->
'ATI<CR>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'332<CR><LF><CR><LF>OK<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> Device ID source
'00001bc70000002133235965804400469712.00.208HE910-EURTelit'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> Device ID
'ba190479f4a2cb0455d08efa6a0de6940afb9192'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> loaded device
identifier: ba190479f4a2cb0455d08efa6a0de6940afb9192
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> loading supported
modes...
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 3 (open)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 2 (close)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): -->
'AT*CNTI=2<CR>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'<CR><LF>ERROR<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> Got failure code 100:
Unknown error
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> Generic query of
supported 3GPP networks with *CNTI failed: 'Unknown error'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 3 (open)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 2 (close)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> Device allows (3GPP)
2G-only network mode
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> Device allows (3GPP)
3G-only network mode
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> Device allows every
supported 3GPP network mode (2G/3G)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 3 (open)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 2 (close)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): -->
'AT#BND=?<CR>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <-- '#BND:
(0-3),(0,2,5,6)<CR><LF><CR><LF>OK<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> loading supported IP
families...
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 3 (open)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 2 (close)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): -->
'AT+CGDCONT=?<CR>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'<CR><LF>+CME ERROR: 10<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> Got failure code 10:
SIM not inserted
> mar 17 09:08:17 D2040 ModemManager[23597]: <warn>  couldn't load
Supported IP families: 'SIM not inserted'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> loading power state...
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 3 (open)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 2 (close)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): -->
'AT+CFUN?<CR>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <-- '+CFUN:
1<CR><LF><CR><LF>OK<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> Telit SIM hot swap:
Enable QSS
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM3) opening
serial port...
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM3) device open
count is 1 (open)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 1 (close)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM3): -->
'AT#QSS=2<CR>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM3): <--
'<CR><LF>OK<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> Iface modem: SIM hot
swap setup succeded
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> checking if unlock
required...
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0) device open
count is 2 (open)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM3) device open
count is 0 (close)
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM3) closing
serial port...
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM3) serial port
closed
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): -->
'AT+CPIN?<CR>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> (ttyACM0): <--
'<CR><LF>+CME ERROR: 10<CR><LF>'
> mar 17 09:08:17 D2040 ModemManager[23597]: <debug> Got failure code 10:
SIM not inserted

I'll keep working on it, but any hint is most welcome :)
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20170317/fa29ca1b/attachment-0001.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: mm-qss-sim-locked-pin-off.log
Type: text/x-log
Size: 217318 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20170317/fa29ca1b/attachment-0002.bin>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: mm-qss-sim-locked-pin-on.log
Type: text/x-log
Size: 122728 bytes
Desc: not available
URL: <https://lists.freedesktop.org/archives/modemmanager-devel/attachments/20170317/fa29ca1b/attachment-0003.bin>