<div dir="ltr"><div dir="ltr" class="gmail_msg"><div class="gmail_msg">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)' </div>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; </div><div class="gmail_msg">However, still not a clue about why a use case with SIM locked should work differently that one with SIM unlocked. </div><div class="gmail_quote gmail_msg"><div dir="ltr" class="gmail_msg">On Fri, 17 Mar 2017 at 11:15 Carlo Lobrano <<a href="mailto:c.lobrano@gmail.com" class="gmail_msg" target="_blank">c.lobrano@gmail.com</a>> wrote: </div><blockquote class="gmail_quote gmail_msg" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr" class="gmail_msg">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 :) </div></blockquote></div></div>