Fail to load SIM information during modem initialization when modem in CFUN 4 state

[Aleksander Morgado]

Hey Ben,

> 
> I've observed an issue on some modems. If the modem is initially in the
> CFUN 4 state, the SIM interface isn't fully functional (e.g. +CIMI and
> +CRSM would fail). When ModemManager initializes the modem in such
> state, it fails to read ICCID, IMSI, etc, and would never load the
> information again. Have you observed similar issues on your modems? I
> wonder if ModemManager should reload SIM information after the modem is
> enabled (after setting CFUN=1)?
> 

I'm not sure I've seen this with other modems, but it really does seem
unfortunate. Reading this information so late just makes useless any
attempt to e.g. try to match connection settings to IMSI (which would be
useful to decide which SIM-PIN to automatically send). But anyway, if
possible, I think we should probably try to implement this and provide
proper values whenever we can get them.

Reading SIM-related read-only properties is attempted twice now: during
the initialization phase, even if SIM-PIN is required; and also when
re-running the initialization phase after sending SIM-PIN. We could
definitely add a third try after going into full functionality mode
(e.g. CFUN=1), but if so I'd suggest to do it in such a way that we let
plugins decide when they want to do it. Some plugins will never load
e.g. IMSI well even in the two attempts that we currently do, so we
shouldn't retry it a third time just to see it fail. A boolean property
in the MMIfaceModem interface could help, stating whether
mm_sim_initialize() should be called as an additional step after
ENABLING_STEP_SET_POWER_STATE.

In which modem(s) have you seen this?


> Thanks,
> Ben
> 
> 2013-10-09T18:04:24.860375-07:00 localhost ModemManager[2033]: <debug>
> loading power state...
> 2013-10-09T18:04:24.860451-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): --> 'AT+CFUN?<CR><LF>'
> 2013-10-09T18:04:24.976094-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): <-- '<CR><LF>+CFUN: 4<CR><LF><CR><LF>OK<CR><LF>'
> 2013-10-09T18:04:24.976169-07:00 localhost ModemManager[2033]: <debug>
> checking if unlock required...
> 2013-10-09T18:04:24.976219-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): --> 'AT+CPIN?<CR><LF>'
> 2013-10-09T18:04:24.984225-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): <-- '<CR><LF>+CPIN: READY<CR><LF><CR><LF>OK<CR><LF>'
> 2013-10-09T18:04:24.992881-07:00 localhost ModemManager[2033]: <debug>
> SIM is ready, and no need for the after SIM unlock step...
> 2013-10-09T18:04:24.992963-07:00 localhost ModemManager[2033]: <debug>
> loading SIM identifier...
> 2013-10-09T18:04:24.993000-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): --> 'AT+CRSM=176,12258,0,0,10<CR><LF>'
> 2013-10-09T18:04:25.000186-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): <-- '<CR><LF>+CRSM: 144,0<CR><LF><CR><LF>OK<CR><LF>'
> 2013-10-09T18:04:25.000228-07:00 localhost ModemManager[2033]: <debug>
> loading SIM identifier...
> 2013-10-09T18:04:25.000276-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): --> 'AT+CRSM=176,12258,0,0,10<CR><LF>'
> 2013-10-09T18:04:25.008353-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): <-- '<CR><LF>+CRSM: 144,0<CR><LF><CR><LF>OK<CR><LF>'
> 2013-10-09T18:04:25.008436-07:00 localhost ModemManager[2033]: <warn>
>  couldn't load SIM identifier: 'Could not parse the CRSM response'
> 2013-10-09T18:04:25.008459-07:00 localhost ModemManager[2033]: <debug>
> loading IMSI...
> 2013-10-09T18:04:25.008516-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): --> 'AT+CIMI<CR><LF>'
> 2013-10-09T18:04:25.016233-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): <-- '<CR><LF>+CME ERROR: 13<CR><LF>'
> 2013-10-09T18:04:25.016317-07:00 localhost ModemManager[2033]: <debug>
> Got failure code 13: SIM failure
> 2013-10-09T18:04:25.016338-07:00 localhost ModemManager[2033]: <warn>
>  couldn't load IMSI: 'SIM failure'
> 2013-10-09T18:04:25.016355-07:00 localhost ModemManager[2033]: <debug>
> loading Operator ID...
> 2013-10-09T18:04:25.016407-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): --> 'AT+CRSM=176,28589,0,0,4<CR><LF>'
> 2013-10-09T18:04:25.024497-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): <-- '<CR><LF>+CRSM: 144,0<CR><LF><CR><LF>OK<CR><LF>'
> 2013-10-09T18:04:25.024547-07:00 localhost ModemManager[2033]: <warn>
>  couldn't load Operator identifier: 'Cannot load Operator ID without IMSI'
> 2013-10-09T18:04:25.024568-07:00 localhost ModemManager[2033]: <debug>
> loading Operator Name...
> 2013-10-09T18:04:25.024622-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): --> 'AT+CRSM=176,28486,0,0,17<CR><LF>'
> 2013-10-09T18:04:25.032573-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): <-- '<CR><LF>+CRSM: 144,0<CR><LF><CR><LF>OK<CR><LF>'
> 2013-10-09T18:04:25.032620-07:00 localhost ModemManager[2033]: <warn>
>  couldn't load Operator name: 'Could not parse the CRSM response'
> 2013-10-09T18:04:25.032658-07:00 localhost ModemManager[2033]: <debug>
> loading own numbers...
> 2013-10-09T18:04:25.032693-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): --> 'AT+CNUM<CR><LF>'
> 2013-10-09T18:04:25.040195-07:00 localhost ModemManager[2033]: <debug>
> (ttyACM0): <-- '<CR><LF>OK<CR><LF>'


-- 
Aleksander