Re: [MM] [PATCH] sim: retry SIM operations during initialization

[Ben Chan <benchan chromium org>]

On Fri, Aug 24, 2012 at 8:21 AM, Ben Chan <benchan chromium org> wrote:
> On Thu, Aug 23, 2012 at 11:51 PM, Aleksander Morgado
> <aleksander lanedo com> wrote:
>>
>>> The timeout + retries really tries to address flaky SIM operations on
>>> some modems. We could limit the retries to certain error codes, but
>>> that won't address flakiness, unfortunately :(
>>>
>>> We could let individual plugins to configure whether it should retry
>>> on failed SIM operations. For a modem that does not support reading
>>> IMSI (AT+CIMI), the plugin would set load_imsi / load_imsi_finish to
>>> NULL to skip INITIALIZATION_STEP_IMSI altogether.
>>>
>>
>> That is not the only reason in this case. We try to load IMSI and other
>> SIM-related stuff before and after PIN unlocking. Loading IMSI may fail
>> before SIM unlock, and succeed after SIM unlock (got that case here with
>> a Gobi modem) [*]. So, before unlocking the PIN, we're sending AT+CIMI
>> three times and in all we get an error. It is probably a good idea to
>> retry these commands under certain circumstances, but not sure if they
>> should be retried always, for every error. I fear that if we add those
>> unconditional retries now they'll end up being there forever and we'll
>> never know if they were always needed or not. Can we initially retry
>> only if we get some expected error, and add more cases as we see them?
>>
>> Also, setting load_imsi/load_imsi_finish to NULL should only be done if
>> all modems handled by the given plugin are known to have IMSI loading
>> unsupported.
>>
>> [*] Probably we shouldn't try to load IMSI before PIN unlocking.
>>
>> --
>> Aleksander
>
> Let me see if there are certain error codes that may suggest a retry
> is needed. My concern is that some modems may provide a flaky
> response, which may not even include a valid error code when it fails
> to read IMSI. But that should be handled in the modem plugins instead.
> I think the MMSim interface should still validate the IMSI value
> reported by +CIMI, so I've submitted a smaller patch just for that.

After the +CPIN: READY response, there is a period of time where SIM
operations are not reliable on some modems. I've observed issues with
reading ICCID and IMSI. The following example shows that the modem
reports bogus values of ICCID. The first reply of
"AT+CRSM=176,12258,0,0,10" is IMSI instead of ICCID, which is
surprisingly odd. Retrying after 1s, it replies "+CRSM: 110,0,"".
Retrying one more time after 1s, it finally replies the expected ICCID
value.

I can see two issues here: (1) +CPIN: READY doesn't necessarily
guarantee the SIM is ready, (2) it may not be reliable to determine if
we should retry a SIM operation based on the modem response (the modem
could just be flaky or give bogus replies). There is a chance that if
we address (1), (2) may not be an issue anymore.

2012-08-25T11:59:17.610405-07:00 (ttyUSB0): --> 'AT+CNUM<CR>'
2012-08-25T11:59:17.620878-07:00 (ttyUSB0): <-- '<CR><LF>ERROR<CR><LF>'
2012-08-25T11:59:17.621400-07:00 (ttyUSB0): --> 'AT+CPIN?<CR>'
2012-08-25T11:59:17.632196-07:00 (ttyUSB0): <-- '<CR><LF>+CME ERROR: 14<CR><LF>'
2012-08-25T11:59:19.909769-07:00 (ttyUSB0): --> 'AT+CPIN?<CR>'
2012-08-25T11:59:19.919917-07:00 (ttyUSB0): <-- '<CR><LF>+CME ERROR: 14<CR><LF>'
2012-08-25T11:59:21.910338-07:00 (ttyUSB0): --> 'AT+CPIN?<CR>'
2012-08-25T11:59:21.934265-07:00 (ttyUSB0): <-- '<CR><LF>+CME ERROR: 14<CR><LF>'
2012-08-25T11:59:23.910089-07:00 (ttyUSB0): --> 'AT+CPIN?<CR>'
2012-08-25T11:59:23.927366-07:00 (ttyUSB0): <-- '<CR><LF>+CPIN:
READY<CR><LF><CR><LF>OK<CR><LF>'
2012-08-25T11:59:23.927405-07:00 (ttyUSB0): --> 'AT+CRSM=176,12258,0,0,10<CR>'
2012-08-25T11:59:27.706575-07:00 (ttyUSB0): <--
'<CR><LF>311480000348263<CR><LF><CR><LF>OK<CR><LF>'
2012-08-25T11:59:28.910415-07:00 (ttyUSB0): --> 'AT+CRSM=176,12258,0,0,10<CR>'
2012-08-25T11:59:28.935351-07:00 (ttyUSB0): <-- 'AT+CRSM=176,12258,0,0'
2012-08-25T11:59:28.941294-07:00 (ttyUSB0): <-- ',10<CR>'
2012-08-25T11:59:29.111180-07:00 (ttyUSB0): <-- '<CR><LF>+CRSM:
110,0,""<CR><LF><CR><LF>OK<CR><LF>'
2012-08-25T11:59:29.910411-07:00 (ttyUSB0): --> 'AT+CRSM=176,12258,0,0,10<CR>'
2012-08-25T11:59:29.934756-07:00 (ttyUSB0): <-- 'AT+CRSM=176,12258,0,'
2012-08-25T11:59:29.939838-07:00 (ttyUSB0): <-- '0,10<CR>'
2012-08-25T11:59:30.188479-07:00 (ttyUSB0): <-- '<CR><LF>+CRSM:
144,0,"98410800000030267965"<CR><LF><CR><LF>OK<CR><LF>'
2012-08-25T11:59:30.188636-07:00 (ttyUSB0): --> 'AT+CIMI<CR>'
2012-08-25T11:59:30.196241-07:00 (ttyUSB0): <-- 'AT+'
2012-08-25T11:59:30.200727-07:00 (ttyUSB0): <-- 'CIMI<CR>'
2012-08-25T11:59:30.597451-07:00 (ttyUSB0): <--
'<CR><LF>311480000348263<CR><LF><CR><LF>OK<CR><LF>'