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.lobr...@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.lobr...@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 :) > >
_______________________________________________ ModemManager-devel mailing list ModemManager-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel