SIM hot swap with SIM locked

Fri Mar 17 15:55:11 UTC 2017

Sorry, I made a mistake copying the log in the previous email

mar 17 16:45:15 D2040 ModemManager[3946]: <debug> (ttyACM0): -->
'AT+GCAP<CR>'
mar 17 16:45:15 D2040 ModemManager[3946]: <debug> (ttyACM0): <-- '<CR><LF>'
mar 17 16:45:15 D2040 ModemManager[3946]: <debug> (ttyACM0): <-- '+GCAP:
+CGSM,+DS,+FCLASS,+MS,+ES<CR><LF><CR><LF>OK<CR><LF>'
mar 17 16:45:16 D2040 ModemManager[3946]: <debug> parse_caps_gcap on
'(null)'
mar 17 16:45:16 D2040 ModemManager[3946]: <debug> (ttyACM0): --> 'ATI<CR>'
mar 17 16:45:16 D2040 ModemManager[3946]: <debug> (ttyACM0): <-- '<CR><LF>'
mar 17 16:45:16 D2040 ModemManager[3946]: <debug> (ttyACM0): <--
'332<CR><LF><CR><LF>OK<CR><LF>'
mar 17 16:45:17 D2040 ModemManager[3946]: <debug> parse_caps_gcap on
'(null)'
mar 17 16:45:17 D2040 ModemManager[3946]: <debug> (ttyACM0): -->
'AT+CPIN?<CR>'
mar 17 16:45:17 D2040 ModemManager[3946]: <debug> (ttyACM0): <--
'<CR><LF>+CME ERROR: 10<CR><LF>'
mar 17 16:45:17 D2040 ModemManager[3946]: <debug> Got failure code 10: SIM
not inserted

On Fri, 17 Mar 2017 at 14:16 Carlo Lobrano <c.lobrano at gmail.com> wrote:

> Short update that might highlight better the problem. When the Modem is
> re-probed after SIM is removed, the "parse_caps_gcap" receives NULL
> strings, even if we can see the reply on the logs
>
> mar 17 14:08:40 D2040 ModemManager[7410]: (ttyACM0): --> 'AT+GCAP'
> mar 17 14:08:40 D2040 ModemManager[7410]: (ttyACM0): <-- ''
> mar 17 14:08:40 D2040 ModemManager[7410]: (ttyACM0): <-- '+GCAP:
> +CGSM,+DS,+FCLASS,+MS,+ESOK'
> mar 17 14:08:42 D2040 ModemManager[7410]: parse_caps_gcap on '(null)'
>
> this is the origin of that print:
>
> static gboolean
> parse_caps_gcap (MMBaseModem *self,
>                  gpointer none,
>                  const gchar *command,
>                  const gchar *response,
>                  gboolean last_command,
>                  const GError *error,
>                  GVariant **variant,
>                  GError **result_error)
> {
>     const ModemCaps *cap = modem_caps;
>     guint32 ret = 0;
>
>     mm_dbg ("parse_caps_gcap on '%s'", response);
>     if (!response)
>         return FALSE;
>
> However, still not a clue about why a use case with SIM locked should work
> differently that one with SIM unlocked.
> On Fri, 17 Mar 2017 at 11:15 Carlo Lobrano <c.lobrano at gmail.com> wrote:
>
> 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/e8d82cc2/attachment-0001.html>