976497 - SIM Slot manager seems to be racy regarding SIM card state on boot (Peak, Nexus S)

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: RIL, defect, P3)

Description

[:gerard-majax]

On a fresh boot, device might show "No SIM card" while there is really one. 100% reproductibility at least on Nexus S and Peak. After stop b2g/start b2g, SIM card is detected. Looking at Gecko RIL logs, the SIM card status detected is fine on my Nexus S (pinRequired), but debug in SIM Slot shows no event coming at all, only:
E/GeckoConsole(   77): Content JS LOG at app://system.gaiamobile.org/js/simslot.js:116 in SIMSlot.prototype.debug: [SIMSLOT][0][-1391929871338.441] publish: created

STR:
 0. Device powered, with SIM card inserted and visible
 1. Long press power, select "Power off"
 2. Wait a couple of seconds, then power on.
 3. Let B2G boot

Expected:
 SIM card detected, either registering on network or asking PIN code.

Actual:
 No SIM card detected.

Having a PIN code set or not has no impact.

Comment 1

[:gerard-majax]

Logcat when the SIM is detected, after a stop/start of b2g:
alex@portable-alex:~/codaz/Mozilla/b2g/gaia$ adb logcat | egrep -i simslot
E/GeckoConsole(  403): Content JS DEBUG at app://system.gaiamobile.org/js/simslot_manager.js:26 in ssm_init: SIMSlotManager: init
E/GeckoConsole(  403): Content JS DEBUG at app://system.gaiamobile.org/js/simslot_manager.js:31 in ssm_init: SIMSlotManager: has IccManager
E/GeckoConsole(  403): Content JS DEBUG at app://system.gaiamobile.org/js/simslot_manager.js:35 in ssm_init: SIMSlotManager: conns: 1
E/GeckoConsole(  403): Content JS DEBUG at app://system.gaiamobile.org/js/simslot_manager.js:40 in ssm_init: SIMSlotManager: iterating conns
E/GeckoConsole(  403): Content JS DEBUG at app://system.gaiamobile.org/js/simslot_manager.js:42 in iterator: SIMSlotManager: conn: [object MozMobileConnection] -- index: 0
E/GeckoConsole(  403): Content JS LOG at app://system.gaiamobile.org/js/simslot.js:116 in SIMSlot.prototype.debug: [SIMSLOT][0][-1391930550831.263] publish: created
E/GeckoConsole(  403): Content JS DEBUG at app://system.gaiamobile.org/js/simslot_manager.js:47 in ssm_init: SIMSlotManager: add iccdetected
E/GeckoConsole(  403): Content JS LOG at app://system.gaiamobile.org/js/simslot.js:116 in SIMSlot.prototype.debug: [SIMSLOT][0][-1391930550828.553] publish: updated
E/GeckoConsole(  403): Content JS LOG at app://system.gaiamobile.org/js/simslot.js:116 in SIMSlot.prototype.debug: [SIMSLOT][0][-1391930550828.532] publish: iccinfochange
E/GeckoConsole(  403): Content JS LOG at app://system.gaiamobile.org/js/simslot.js:116 in SIMSlot.prototype.debug: [SIMSLOT][0][-1391930550828.517]pinRequired


Logcat after a frehs boot:
alex@portable-alex:~/codaz/Mozilla/b2g/gaia$ adb logcat | egrep -i simslot
- waiting for device -



E/GeckoConsole(   77): Content JS DEBUG at app://system.gaiamobile.org/js/simslot_manager.js:26 in ssm_init: SIMSlotManager: init
E/GeckoConsole(   77): Content JS DEBUG at app://system.gaiamobile.org/js/simslot_manager.js:31 in ssm_init: SIMSlotManager: has IccManager
E/GeckoConsole(   77): Content JS DEBUG at app://system.gaiamobile.org/js/simslot_manager.js:35 in ssm_init: SIMSlotManager: conns: 1
E/GeckoConsole(   77): Content JS DEBUG at app://system.gaiamobile.org/js/simslot_manager.js:40 in ssm_init: SIMSlotManager: iterating conns
E/GeckoConsole(   77): Content JS DEBUG at app://system.gaiamobile.org/js/simslot_manager.js:42 in iterator: SIMSlotManager: conn: [object MozMobileConnection] -- index: 0
E/GeckoConsole(   77): Content JS LOG at app://system.gaiamobile.org/js/simslot.js:116 in SIMSlot.prototype.debug: [SIMSLOT][0][-1391930680659.305] publish: created
E/GeckoConsole(   77): Content JS DEBUG at app://system.gaiamobile.org/js/simslot_manager.js:47 in ssm_init: SIMSlotManager: add iccdetected

Comment 2

[:gerard-majax]

Hsin-Yi, Szu-Yu, I'm wondering if this is not a regression from bug 963054.

As far as I tested, I don't reproduce this issue anymore when applying those changes:

> diff --git a/dom/system/gonk/ril_worker.js b/dom/system/gonk/ril_worker.js
> index f9ef93d..76f8084 100644
> --- a/dom/system/gonk/ril_worker.js
> +++ b/dom/system/gonk/ril_worker.js
> @@ -3105,9 +3105,7 @@ RilObject.prototype = {
>      this.appType = app.app_type;
>      this.iccInfo.iccType = GECKO_CARD_TYPE[this.appType];
>      // Try to get iccId only when cardState left GECKO_CARDSTATE_UNDETECTED.
> -    if (iccStatus.cardState === CARD_STATE_PRESENT &&
> -        (this.cardState === GECKO_CARDSTATE_UNINITIALIZED ||
> -         this.cardState === GECKO_CARDSTATE_UNDETECTED)) {
> +    if (iccStatus.cardState === CARD_STATE_PRESENT) {
>        ICCRecordHelper.readICCID();
>      }

Comment 3

[Zac C (:zac)]

I don't self-build so I'm no help here, sorry :)

Comment 4

[Hsin-Yi Tsai (she/her) [:hsinyi]]

(In reply to Alexandre LISSY :gerard-majax from comment #2)
> Hsin-Yi, Szu-Yu, I'm wondering if this is not a regression from bug 963054.
> 
> As far as I tested, I don't reproduce this issue anymore when applying those
> changes:
> 

Hmm, interesting try...

Before bug 963054 we had only one const GECKO_CARDSTATE_UNDETECTED which covered the definitions of "GECKO_CARDSTATE_UNINITIALIZED" and "GECKO_CARDSTATE_UNDETECTED" afterwards. We introduced GECKO_CARDSTATE_UNINITIALIZED to make things clearer and the logic before and after bug 963054 is the same. So it's not obvious to me this is a regression from that.

We call readICCID() only when card state changes from uninitialized/undetected to present. Wondering if Peak or Nexus S sends another cardstate X between those so that we never get the chance to readICCID(). Maybe you could help provide RIL log.

> > diff --git a/dom/system/gonk/ril_worker.js b/dom/system/gonk/ril_worker.js
> > index f9ef93d..76f8084 100644
> > --- a/dom/system/gonk/ril_worker.js
> > +++ b/dom/system/gonk/ril_worker.js
> > @@ -3105,9 +3105,7 @@ RilObject.prototype = {
> >      this.appType = app.app_type;
> >      this.iccInfo.iccType = GECKO_CARD_TYPE[this.appType];
> >      // Try to get iccId only when cardState left GECKO_CARDSTATE_UNDETECTED.
> > -    if (iccStatus.cardState === CARD_STATE_PRESENT &&
> > -        (this.cardState === GECKO_CARDSTATE_UNINITIALIZED ||
> > -         this.cardState === GECKO_CARDSTATE_UNDETECTED)) {
> > +    if (iccStatus.cardState === CARD_STATE_PRESENT) {
> >        ICCRecordHelper.readICCID();
> >      }

Comment 5

[Szu-Yu Chen [:aknow] (inactive)]

Alexandre,

The following lines are the original code before bug 963054 and I think the patch didn't change any logic for this part.

if (this.cardState === GECKO_CARDSTATE_UNDETECTED &&
    iccStatus.cardState === CARD_STATE_PRESENT) {
 ICCRecordHelper.readICCID();
}

This is the fix you do in Comment 2. The logic is actually different from the above one.

if (iccStatus.cardState === CARD_STATE_PRESENT) {
  ICCRecordHelper.readICCID();
}	

Could you build a gecko with version prior than bug 963054. I am wondering whether it was OK before and we just broke something in bug 963054. Otherwise, it might be another issue, which is not related to bug 963054.

Comment 6

[:gerard-majax]

(In reply to Hsin-Yi Tsai  [:hsinyi] from comment #4)
> (In reply to Alexandre LISSY :gerard-majax from comment #2)
> > Hsin-Yi, Szu-Yu, I'm wondering if this is not a regression from bug 963054.
> > 
> > As far as I tested, I don't reproduce this issue anymore when applying those
> > changes:
> > 
> 
> Hmm, interesting try...
> 
> Before bug 963054 we had only one const GECKO_CARDSTATE_UNDETECTED which
> covered the definitions of "GECKO_CARDSTATE_UNINITIALIZED" and
> "GECKO_CARDSTATE_UNDETECTED" afterwards. We introduced
> GECKO_CARDSTATE_UNINITIALIZED to make things clearer and the logic before
> and after bug 963054 is the same. So it's not obvious to me this is a
> regression from that.
> 
> We call readICCID() only when card state changes from
> uninitialized/undetected to present. Wondering if Peak or Nexus S sends
> another cardstate X between those so that we never get the chance to
> readICCID(). Maybe you could help provide RIL log.
> 
> > > diff --git a/dom/system/gonk/ril_worker.js b/dom/system/gonk/ril_worker.js
> > > index f9ef93d..76f8084 100644
> > > --- a/dom/system/gonk/ril_worker.js
> > > +++ b/dom/system/gonk/ril_worker.js
> > > @@ -3105,9 +3105,7 @@ RilObject.prototype = {
> > >      this.appType = app.app_type;
> > >      this.iccInfo.iccType = GECKO_CARD_TYPE[this.appType];
> > >      // Try to get iccId only when cardState left GECKO_CARDSTATE_UNDETECTED.
> > > -    if (iccStatus.cardState === CARD_STATE_PRESENT &&
> > > -        (this.cardState === GECKO_CARDSTATE_UNINITIALIZED ||
> > > -         this.cardState === GECKO_CARDSTATE_UNDETECTED)) {
> > > +    if (iccStatus.cardState === CARD_STATE_PRESENT) {
> > >        ICCRecordHelper.readICCID();
> > >      }

I have the logs from the gecko RIL, but they were not helpful.

Comment 7

[:gerard-majax]

(In reply to Szu-Yu Chen [:aknow] from comment #5)
> Alexandre,
> 
> The following lines are the original code before bug 963054 and I think the
> patch didn't change any logic for this part.
> 
> if (this.cardState === GECKO_CARDSTATE_UNDETECTED &&
>     iccStatus.cardState === CARD_STATE_PRESENT) {
>  ICCRecordHelper.readICCID();
> }
> 
> This is the fix you do in Comment 2. The logic is actually different from
> the above one.
> 
> if (iccStatus.cardState === CARD_STATE_PRESENT) {
>   ICCRecordHelper.readICCID();
> }	
> 
> Could you build a gecko with version prior than bug 963054. I am wondering
> whether it was OK before and we just broke something in bug 963054.
> Otherwise, it might be another issue, which is not related to bug 963054.

It has changes from: (this.cardState === GECKO_CARDSTATE_UNDETECTED && iccStatus.cardState === CARD_STATE_PRESENT) to : (iccStatus.cardState === CARD_STATE_PRESENT && (this.cardState === GECKO_CARDSTATE_UNINITIALIZED || this.cardState === GECKO_CARDSTATE_UNDETECTED)).

I reverted to (this.cardState === GECKO_CARDSTATE_UNDETECTED && iccStatus.cardState === CARD_STATE_PRESENT) and I reproduce the issue, so probably you are right and we are just exposing a long standing issue.

Comment 8

[:gerard-majax]

I reverted my hack, and added some debug prior the if so the code looks like this:
>    3107     // Try to get iccId only when cardState left GECKO_CARDSTATE_UNDETECTED.
> +  3108     debug("About to call ICCRecordHelper.readICCID :: this.cardState=" + this.cardState);
> +  3109     debug("About to call ICCRecordHelper.readICCID :: iccStatus.cardState=" + iccStatus.cardState);
>    3110     if (iccStatus.cardState === CARD_STATE_PRESENT &&
>    3111         (this.cardState === GECKO_CARDSTATE_UNINITIALIZED ||
> .  3112          this.cardState === GECKO_CARDSTATE_UNDETECTED)) {
>    3113       ICCRecordHelper.readICCID();
>    3114     }
> 

This is what I get:
$ grep readICCID icc.nexus.log 
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: this.cardState=uninitialized
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: iccStatus.cardState=1
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: this.cardState=pinRequired
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: iccStatus.cardState=1
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: this.cardState=pinRequired
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: iccStatus.cardState=1
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: this.cardState=pinRequired
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: iccStatus.cardState=1
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: this.cardState=pinRequired
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: iccStatus.cardState=1
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: this.cardState=pinRequired
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: iccStatus.cardState=1
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: this.cardState=pinRequired
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: iccStatus.cardState=1
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: this.cardState=pinRequired
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: iccStatus.cardState=1
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: this.cardState=pinRequired
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: iccStatus.cardState=1
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: this.cardState=pinRequired
I/Gecko   (   77): RIL Worker: About to call ICCRecordHelper.readICCID :: iccStatus.cardState=1

Comment 9

[:gerard-majax]

Attachment: ril.cardState.patch

I get correct behavior if I add handling for pin required and puk required states.

Comment 10

[Hsin-Yi Tsai (she/her) [:hsinyi]]

(In reply to Alexandre LISSY :gerard-majax from comment #9)
> Created attachment 8382036 [details] [diff] [review]
> ril.cardState.patch
> 
> I get correct behavior if I add handling for pin required and puk required
> states.
Thanks for the patch. I am working on urgent 2/28 bugs and won't have bandwidth until then, sorry. I'll get back to you afterwards.

Comment 11

[:gerard-majax]

(In reply to Hsin-Yi Tsai  [:hsinyi] from comment #10)
> (In reply to Alexandre LISSY :gerard-majax from comment #9)
> > Created attachment 8382036 [details] [diff] [review]
> > ril.cardState.patch
> > 
> > I get correct behavior if I add handling for pin required and puk required
> > states.
> Thanks for the patch. I am working on urgent 2/28 bugs and won't have
> bandwidth until then, sorry. I'll get back to you afterwards.

No problem, we are all in the same ship :). I can live for some time with this small local change.

Comment 12

[Hsin-Yi Tsai (she/her) [:hsinyi]]

Comment on attachment 8382036 [details] [diff] [review]
ril.cardState.patch

Review of attachment 8382036 [details] [diff] [review]:
-----------------------------------------------------------------

Sorry for being late.

::: dom/system/gonk/ril_worker.js
@@ +3108,5 @@
>      if (iccStatus.cardState === CARD_STATE_PRESENT &&
>          (this.cardState === GECKO_CARDSTATE_UNINITIALIZED ||
> +         this.cardState === GECKO_CARDSTATE_UNDETECTED ||
> +         this.cardState === GECKO_CARDSTATE_PIN_REQUIRED ||
> +         this.cardState === GECKO_CARDSTATE_PUK_REQUIRED)) {

Per your investigation on comment 8, there's indeed a transition from "this.cardState=uninitialized" to "iccStatus.cardState=1". So at that time, readICCID() should be called, I don't see obvious reasons why we need to have GECKO_CARDSTATE_PIN_REQUIRED and GECKO_CARDSTATE_PUK_REQUIRED. Could you explain more? Otherwise, I doubt this patch doesn't point to the root cause. Thank you.

Comment 13

[:gerard-majax]

(In reply to Hsin-Yi Tsai  [:hsinyi] from comment #12)
> Comment on attachment 8382036 [details] [diff] [review]
> ril.cardState.patch
> 
> Review of attachment 8382036 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> Sorry for being late.
> 
> ::: dom/system/gonk/ril_worker.js
> @@ +3108,5 @@
> >      if (iccStatus.cardState === CARD_STATE_PRESENT &&
> >          (this.cardState === GECKO_CARDSTATE_UNINITIALIZED ||
> > +         this.cardState === GECKO_CARDSTATE_UNDETECTED ||
> > +         this.cardState === GECKO_CARDSTATE_PIN_REQUIRED ||
> > +         this.cardState === GECKO_CARDSTATE_PUK_REQUIRED)) {
> 
> Per your investigation on comment 8, there's indeed a transition from
> "this.cardState=uninitialized" to "iccStatus.cardState=1". So at that time,
> readICCID() should be called, I don't see obvious reasons why we need to
> have GECKO_CARDSTATE_PIN_REQUIRED and GECKO_CARDSTATE_PUK_REQUIRED. Could
> you explain more? Otherwise, I doubt this patch doesn't point to the root
> cause. Thank you.

I re-did a debug log. You are right, we are doing the call:

  129 I/Gecko   (   77): RIL Worker: iccStatus.cardState=1 -- this.cardState=uninitialized
  130 I/Gecko   (   77): RIL Worker: Calling ICCRecordHelper.readICCID()
  131 I/Gecko   (   77): RIL Worker: readICCID: perform ICCIO

But,

  212 I/Gecko   (   77): RIL Worker: REQUEST_SIM_IO: length=0
  213 I/Gecko   (   77): RIL Worker: REQUEST_SIM_IO: options={"fileId":12258,"type":0,"command":192,"pathId":"3f00","p1":0,"p2":0,"p3":15,"rilRequestType":28,"rilRequestError":1}
  214 I/Gecko   (   77): RIL Worker: [0] ICC I/O Error code RadioNotAvailable EF id = 2fe2 command = c0

fileId 12258 is 2fe2, which is the id of icc record.

So this is the root of the race condition.

Comment 14

[:gerard-majax]

Attachment: ril.cardState.patch

So after debugging a bit again, checking the radio state helps a lot :)

Comment 15

[Hsin-Yi Tsai (she/her) [:hsinyi]]

(In reply to Alexandre LISSY :gerard-majax from comment #14)
> Created attachment 8384510 [details] [diff] [review]
> ril.cardState.patch
> 
> So after debugging a bit again, checking the radio state helps a lot :)

Hey Alexandre,

Adding check on radio_state gives a useful hint. Thanks for the information. :) 

However, I am not sure if this is the right solution. An interesting thing is that typically cardState becomes present after radio is available. Then how come an error "RadioNotAvailable" appears when we try to readICCID() with cardState present? I need more context before providing any further feedback.

As I don't have nexus S on hand, please help provide me the log with RIL debugger enabled, i.e. "adb logcat -b radio -b main -v time". Hope we get more ideas then. Thank you!

Comment 16

[:gerard-majax]

(In reply to Hsin-Yi Tsai  [:hsinyi] from comment #15)
> (In reply to Alexandre LISSY :gerard-majax from comment #14)
> > Created attachment 8384510 [details] [diff] [review]
> > ril.cardState.patch
> > 
> > So after debugging a bit again, checking the radio state helps a lot :)
> 
> Hey Alexandre,
> 
> Adding check on radio_state gives a useful hint. Thanks for the information.
> :) 
> 
> However, I am not sure if this is the right solution. An interesting thing
> is that typically cardState becomes present after radio is available. Then
> how come an error "RadioNotAvailable" appears when we try to readICCID()
> with cardState present? I need more context before providing any further
> feedback.
> 
> As I don't have nexus S on hand, please help provide me the log with RIL
> debugger enabled, i.e. "adb logcat -b radio -b main -v time". Hope we get
> more ideas then. Thank you!

Well I already have the log, just lacks timestamps.

Comment 17

[:gerard-majax]

Attachment: ril.log

RIL|RadioInterface log

Comment 18

[Hsin-Yi Tsai (she/her) [:hsinyi]]

(In reply to Alexandre LISSY :gerard-majax from comment #17)
> Created attachment 8384549 [details]
> ril.log
> 
> RIL|RadioInterface log

Thanks for the log!

I discussed this issue with Edgar. We conjecture [1] seems the line triggering the problem. IMO we shouldn't expect retrieving correct ICCStatus upon an unsolicited event for voice network state. I'd like to think about the possibility of removing the line. Could you mark the line and give it a try to see if that helps resolve the problem? Thank you.

[1] http://hg.mozilla.org//mozilla-central/annotate/cfc63f40409d/dom/system/gonk/ril_worker.js#l6410

Comment 19

[Hsin-Yi Tsai (she/her) [:hsinyi]]

Comment on attachment 8384510 [details] [diff] [review]
ril.cardState.patch

Review of attachment 8384510 [details] [diff] [review]:
-----------------------------------------------------------------

I don't think we should do this. It could affect fugu. Please see comment 18 and give it a try.

Comment 20

[:gerard-majax]

(In reply to Hsin-Yi Tsai  [:hsinyi] from comment #18)
> (In reply to Alexandre LISSY :gerard-majax from comment #17)
> > Created attachment 8384549 [details]
> > ril.log
> > 
> > RIL|RadioInterface log
> 
> Thanks for the log!
> 
> I discussed this issue with Edgar. We conjecture [1] seems the line
> triggering the problem. IMO we shouldn't expect retrieving correct ICCStatus
> upon an unsolicited event for voice network state. I'd like to think about
> the possibility of removing the line. Could you mark the line and give it a
> try to see if that helps resolve the problem? Thank you.
> 
> [1]
> http://hg.mozilla.org//mozilla-central/annotate/cfc63f40409d/dom/system/gonk/
> ril_worker.js#l6410

Of course. Your bet is to revert my workaround and comment this line then ?

I'll try it asap.

Comment 21

[Hsin-Yi Tsai (she/her) [:hsinyi]]

(In reply to Alexandre LISSY :gerard-majax from comment #20)
> (In reply to Hsin-Yi Tsai  [:hsinyi] from comment #18)
> > (In reply to Alexandre LISSY :gerard-majax from comment #17)
> > > Created attachment 8384549 [details]
> > > ril.log
> > > 
> > > RIL|RadioInterface log
> > 
> > Thanks for the log!
> > 
> > I discussed this issue with Edgar. We conjecture [1] seems the line
> > triggering the problem. IMO we shouldn't expect retrieving correct ICCStatus
> > upon an unsolicited event for voice network state. I'd like to think about
> > the possibility of removing the line. Could you mark the line and give it a
> > try to see if that helps resolve the problem? Thank you.
> > 
> > [1]
> > http://hg.mozilla.org//mozilla-central/annotate/cfc63f40409d/dom/system/gonk/
> > ril_worker.js#l6410
> 
> Of course. Your bet is to revert my workaround and comment this line then ?

Yes, you got my point.

> 
> I'll try it asap.

Waiting for your response!

Comment 22

[:gerard-majax]

So, after reverting my changes and commenting this line, I do see the SIM card being detected, asking for PIN, but somehow it stays in this status: SIM PIN is correctly unlocked (I can make and receive calls), but the system (settings app, dialer) still see it as being pin locked.

Comment 23

[:gerard-majax]

Attachment: ril.cardState.patch

So, as documented in the previous comment, the suggested change helps but I then get into a state where the new SIM card status, after unlocking with PIN code, is not updated.

If I force query an ICC status update in the SIM PIN/PUK handler code, it gets correctly updated.

Comment 24

[:gerard-majax]

Attachment: ril.suggested.log

RIL log with your suggested changes.

Comment 25

[Hsin-Yi Tsai (she/her) [:hsinyi]]

(In reply to Alexandre LISSY :gerard-majax from comment #23)
> Created attachment 8385284 [details] [diff] [review]
> ril.cardState.patch
> 
> So, as documented in the previous comment, the suggested change helps but I
> then get into a state where the new SIM card status, after unlocking with
> PIN code, is not updated.
> 
> If I force query an ICC status update in the SIM PIN/PUK handler code, it
> gets correctly updated.

Oh... looks like the hardware solution of nexus s is different from other devices. I talked with Edgar again :) Currently we map radio_state into rough categories that leads to lack of details. We need to distinguish radio_state_sim_*. I'll provide a test patch later. Hopefully this issue is able to be solved.

Comment 26

[Hsin-Yi Tsai (she/her) [:hsinyi]]

Attachment: WIP

Not map radioState into rough categories

Comment 27

[Hsin-Yi Tsai (she/her) [:hsinyi]]

Comment on attachment 8385938 [details] [diff] [review]
WIP

Review of attachment 8385938 [details] [diff] [review]:
-----------------------------------------------------------------

Hi Alexandre, please help verify this patch, seeing if it resolves this issue. Thanks!!!

Comment 28

[:gerard-majax]

(In reply to Hsin-Yi Tsai  [:hsinyi] from comment #25)
> (In reply to Alexandre LISSY :gerard-majax from comment #23)
> > Created attachment 8385284 [details] [diff] [review]
> > ril.cardState.patch
> > 
> > So, as documented in the previous comment, the suggested change helps but I
> > then get into a state where the new SIM card status, after unlocking with
> > PIN code, is not updated.
> > 
> > If I force query an ICC status update in the SIM PIN/PUK handler code, it
> > gets correctly updated.
> 
> Oh... looks like the hardware solution of nexus s is different from other
> devices. I talked with Edgar again :) Currently we map radio_state into
> rough categories that leads to lack of details. We need to distinguish
> radio_state_sim_*. I'll provide a test patch later. Hopefully this issue is
> able to be solved.

That would make sense at least. I'll test it asap !

Comment 29

[:gerard-majax]

So your WIP does not work, but combining WIP that adds those new states, AND removing the previously suggested line as in comment 18, I get everything working as expected:
 - sim card detected
 - pin code asked
 - sim card status updated after entering pin code

Comment 30

[:gerard-majax]

Attachment: ril.wip.log

Attached is the RIL log with WIP only applied. As documented, it is not enough. Adding changes from comment 18 makes everything working correctly.

Comment 31

[Hsin-Yi Tsai (she/her) [:hsinyi]]

(In reply to Alexandre LISSY :gerard-majax from comment #29)
> So your WIP does not work, but combining WIP that adds those new states, AND
> removing the previously suggested line as in comment 18, I get everything
> working as expected:
>  - sim card detected
>  - pin code asked
>  - sim card status updated after entering pin code

Oh... yes, I forgot to add comment 18 in WIP. We must have it! Thanks for reminding :)

Comment 32

[Hsin-Yi Tsai (she/her) [:hsinyi]]

Attachment: WIP - v2

Addressed comment 18.

Comment 33

[Hsin-Yi Tsai (she/her) [:hsinyi]]

(In reply to Hsin-Yi Tsai  [:hsinyi] from comment #32)
> Created attachment 8386055 [details] [diff] [review]
> WIP - v2
> 
> Addressed comment 18.

I think this patch is quite ready for review. 

Alexandre, not sure if I should file another gecko bug for the patch?

Comment 34

[:gerard-majax]

(In reply to Hsin-Yi Tsai  [:hsinyi] from comment #33)
> (In reply to Hsin-Yi Tsai  [:hsinyi] from comment #32)
> > Created attachment 8386055 [details] [diff] [review]
> > WIP - v2
> > 
> > Addressed comment 18.
> 
> I think this patch is quite ready for review. 
> 
> Alexandre, not sure if I should file another gecko bug for the patch?

No, I think that we are still working on the same issue, it's just that I first thought it was a SIM slot manager issue :)

Comment 35

[Hsin-Yi Tsai (she/her) [:hsinyi]]

(In reply to Alexandre LISSY :gerard-majax from comment #34)
> (In reply to Hsin-Yi Tsai  [:hsinyi] from comment #33)
> > (In reply to Hsin-Yi Tsai  [:hsinyi] from comment #32)
> > > Created attachment 8386055 [details] [diff] [review]
> > > WIP - v2
> > > 
> > > Addressed comment 18.
> > 
> > I think this patch is quite ready for review. 
> > 
> > Alexandre, not sure if I should file another gecko bug for the patch?
> 
> No, I think that we are still working on the same issue, it's just that I
> first thought it was a SIM slot manager issue :)

Cool~ so change the component from Gaia::System to RIL?

Comment 36

[Hsin-Yi Tsai (she/her) [:hsinyi]]

Attachment: WIP - part1

In summary:
1) not getICCStatus() in the handler of UNSOLICITED_RESPONSE_VOICE_NETWORK_STATE_CHANGED
2) not map radioState into rough categories, should keep distinct details instead
3) getICCStatus() when radio is available or when radio is turned off (so that we can get card_undetected in some devices)

Comment 37

[Hsin-Yi Tsai (she/her) [:hsinyi]]

Attachment: WIP - part2 - test case

Comment 38

[Hsin-Yi Tsai (she/her) [:hsinyi]]

Attachment: WIP - part2 - test case v2

Remove self debug log in v1.

Comment 39

[Hsin-Yi Tsai (she/her) [:hsinyi]]

Comment on attachment 8386713 [details] [diff] [review]
WIP - part1

Review of attachment 8386713 [details] [diff] [review]:
-----------------------------------------------------------------

Hi Edgar and Yoshi,

The symptom of this issue is: we query iccStatus when radio is not ready. It's okay to get iccStatus and get cardstate updated. However, request_sim_io fails at [1] due to radio not ready. With more debug, [2] calling getICCStatus() leads to the issue. IMO we shouldn't query iccStatus when voice changes. We should, instead, query it when radio changes or icc changes. Also, our code currently maps radioState reported from modem into a rough category that makes us miss details and distinctions. For example, in the case of Nexus S, modem sends out radio state of RADIO_STATE_SIM_READY, RADIO_STATE_SIM_NOT_READY or RADIO_STATE_SIM_LOCKED_OR_ABSENT but our code [3] abstracts the differences.

In summary, the patch does the followings:
1) not getICCStatus() in the handler of UNSOLICITED_RESPONSE_VOICE_NETWORK_STATE_CHANGED
2) not map radioState into rough categories, should keep distinct details instead
3) getICCStatus() when radio is available or when radio is turned off (so that we can get card_undetected in some devices)

Please help review it, thanks!

[1] http://hg.mozilla.org//mozilla-central/annotate/d2dac18d0562/dom/system/gonk/ril_worker.js#l3174
[2] http://hg.mozilla.org//mozilla-central/annotate/d2dac18d0562/dom/system/gonk/ril_worker.js#l6411
[3] http://hg.mozilla.org//mozilla-central/annotate/d2dac18d0562/dom/system/gonk/ril_worker.js#l6331

Comment 40

[Hsin-Yi Tsai (she/her) [:hsinyi]]

Comment on attachment 8386713 [details] [diff] [review]
WIP - part1

Review of attachment 8386713 [details] [diff] [review]:
-----------------------------------------------------------------

Hi Alexandra, 

Minor changes after WIP (v1). It would be better to have your help on testing nexus S again. :)

Comment 41

[Yoshi Cheng-Hao Huang [:allstars.chh][:allstarschh][:yoshi]]

Comment on attachment 8386713 [details] [diff] [review]
WIP - part1

Review of attachment 8386713 [details] [diff] [review]:
-----------------------------------------------------------------

When card is unlocked, the SIM_STATUS_CHANGED unsolicited should be called, not RADIO_STATE_CHANGED,
Also the RADIO_STATE_SIM_NOT_READY, ...etc constants are deprecated now, 
the patch here is likely going back to the older version of RIL.

I think we should check why SIM_STATUS_CHANGED won't be called first.

Comment 42

[Hsin-Yi Tsai (she/her) [:hsinyi]]

(In reply to Yoshi Huang[:allstars.chh] from comment #41)
> Comment on attachment 8386713 [details] [diff] [review]
> WIP - part1
> 
> Review of attachment 8386713 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> When card is unlocked, the SIM_STATUS_CHANGED unsolicited should be called,
> not RADIO_STATE_CHANGED,
> Also the RADIO_STATE_SIM_NOT_READY, ...etc constants are deprecated now, 
> the patch here is likely going back to the older version of RIL.
> 
> I think we should check why SIM_STATUS_CHANGED won't be called first.

I don't see 'RIL_UNSOL_RESPONSE_SIM_STATUS_CHANGED'  in the previous log Alexandra provided. Let's look into "-b radio" then.

Hi Alexnadre, please help provide the log with "-b radio -b main" parameters for the cases:
1) reboot
2) reboot with sim pin enabled
3) unlock sim pin
4) turn on airplane mode and turn off

Thank you!

Comment 43

[Hsin-Yi Tsai (she/her) [:hsinyi]]

Comment on attachment 8386713 [details] [diff] [review]
WIP - part1

Try to answer yoshi's question first ...

Comment 44

[Hsin-Yi Tsai (she/her) [:hsinyi]]

(In reply to Hsin-Yi Tsai  [:hsinyi] from comment #42)
> (In reply to Yoshi Huang[:allstars.chh] from comment #41)
> > Comment on attachment 8386713 [details] [diff] [review]
> > WIP - part1
> > 
> > Review of attachment 8386713 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > When card is unlocked, the SIM_STATUS_CHANGED unsolicited should be called,
> > not RADIO_STATE_CHANGED,
> > Also the RADIO_STATE_SIM_NOT_READY, ...etc constants are deprecated now, 
> > the patch here is likely going back to the older version of RIL.
> > 
> > I think we should check why SIM_STATUS_CHANGED won't be called first.
> 
> I don't see 'RIL_UNSOL_RESPONSE_SIM_STATUS_CHANGED'  in the previous log
> Alexandra provided. Let's look into "-b radio" then.
> 
> Hi Alexnadre, please help provide the log with "-b radio -b main" parameters
> for the cases:
> 1) reboot
> 2) reboot with sim pin enabled
> 3) unlock sim pin
> 4) turn on airplane mode and turn off
> 
> Thank you!

More, it would be great help to find out when "RIL_UNSOL_RESPONSE_SIM_STATUS_CHANGED" is called.

Comment 45

[aniellob]

Please, what's the actual patch to apply in order to test the solution? thank you in advance

Comment 46

[:gerard-majax]

(In reply to Hsin-Yi Tsai  [:hsinyi] from comment #42)
> (In reply to Yoshi Huang[:allstars.chh] from comment #41)
> > Comment on attachment 8386713 [details] [diff] [review]
> > WIP - part1
> > 
> > Review of attachment 8386713 [details] [diff] [review]:
> > -----------------------------------------------------------------
> > 
> > When card is unlocked, the SIM_STATUS_CHANGED unsolicited should be called,
> > not RADIO_STATE_CHANGED,
> > Also the RADIO_STATE_SIM_NOT_READY, ...etc constants are deprecated now, 
> > the patch here is likely going back to the older version of RIL.
> > 
> > I think we should check why SIM_STATUS_CHANGED won't be called first.
> 
> I don't see 'RIL_UNSOL_RESPONSE_SIM_STATUS_CHANGED'  in the previous log
> Alexandra provided. Let's look into "-b radio" then.
> 
> Hi Alexnadre, please help provide the log with "-b radio -b main" parameters
> for the cases:
> 1) reboot
> 2) reboot with sim pin enabled
> 3) unlock sim pin
> 4) turn on airplane mode and turn off
> 
> Thank you!

The logs I provided already covers 1 to 3.

Comment 47

[:gerard-majax]

But it's not radio log :)

Comment 48

[:gerard-majax]

Attachment: radio-crespo-without-patch_nosimdetected.log

adb logcat -b radio -b main

without patch applied, sim card not detected

Comment 49

[:gerard-majax]

Attachment: radio-crespo-without-patch_airplaneonoff.log

adb logcat -b radio -b main

without patch, enabling/disabling airplane mode

Comment 50

[:gerard-majax]

Attachment: radio-crespo-with-patch_pinasked.log

adb logcat -b radio -b main

with patch, pin asked

Comment 51

[:gerard-majax]

Attachment: radio-crespo-with-patch_pinunlocking.log

adb logcat -b radio -b main

with patch, entering pin and unlocking sim

Comment 52

[:gerard-majax]

Attachment: radio-crespo-with-patch_airplaneonoff.log

adb logcat -b radio -b main

with patch, enabling/disabling airplane mode

Comment 53

[David Lawrence [:dkl]]

Verifying that this issue is still present in the latest v1.3 builds available from Geeksphone on my Peak. Switching airplane mode on/off fixes the issue til the next reboot. Let me know if I can help with anything.

dkl

Comment 54

[Sandip Kamat]

PM Triage: Can QA confirm the latest on if this is happening on any of our portfolio devices? (besides Nexus and Peak)

Comment 55

[Jason Smith [:jsmith]]

QA Wanted for comment 54 - try reproducing this on Buri.

Comment 56

[Peter Bylenga [:PBylenga]]

I don't reproduce this issue on latest Buri v1.4, The SIM is detected immediately upon reboots.

v1.4 Environmental Variables:
Device: Buri v1.4 MOZ
BuildID: 20140307040203
Gaia: 04eb7996543f114133d1367f834a4d88b68c60ac
Gecko: b0e7f63c2138
Version: 30.0a1
Firmware Version: v1.2-device.cfg

Same results on latest Buri v1.3

v1.3 Environmental Variables:
Device: Buri v1.3 MOZ
BuildID: 20140307004004
Gaia: e8bf7326ce5ed63bc8ef8b2cff1eba094887b9bf
Gecko: 4efa30fe00e7
Version: 28.0
Firmware Version: v1.2-device.cfg

Comment 57

[Jason Smith [:jsmith]]

Bumping to backlog for not being reproducible on a production device.

Comment 58

[Gabriele Svelto [:gsvelto]]

I hit this issue while dogfooding the latest nightly build on my Peak in the last few days; I must it's quite annoying as it's 100% reproducible.

Comment 59

[:gerard-majax]

Hsin-Yi, please note that one contributor helping on Nexus S (shadeimi in needinfo?) is experiencing this on his device. He also noticed that the current patch works but only with one of its SIM card, not with the other.

Shadeimi, it would be very helpful if you could provide logcat with RIL debug enabled in both cases.

Comment 60

[Hsin-Yi Tsai (she/her) [:hsinyi]]

Sorry for late response. I was occupied by a workweek last week.

I checked with the log again and didn't see expected parcel "RIL_UNSOL_RESPONSE_SIM_STATUS_CHANGED" being sent when card state changes. This behaviour seems not follow latest AOSP ril.h. To meet Nexus S *old* implementation, my patch is turning our moz implementation back to older RIL version (some constants are even deprecated), but this is not what we really want as Yoshi commented. I don't have better ideas of how to deal with this old vendor implementation. I am even wondering whether we could and we should fix this on gecko. 

Since this is not 1.4+ I'd need to work on other issues with higher priority. I am sorry about that.

Comment 61

[aniellob]

Hi,

this is the RIL logfile for my H3G sim card -> http://pastebin.com/qLgR8AQ0

Comment 62

[Ken Chang[:kenkai]]

It is neither a 1.4 target feature nor a 1.4+ bug. I don't think we need to set a target for this bug. But if I am wrong, please feel free to correct it. Thanks.

Comment 63

[Antonio Manuel Amaya Calvo (:amac)]

(In reply to Jason Smith [:jsmith] from comment #57)
> Bumping to backlog for not being reproducible on a production device.

We're getting this same error on Buri devices. The symptoms are: At boot time the SIM isn't recognized, enabling and disabling the airplane mode makes the device see the SIM. The thing is that there are devices that work correctly always, and other that fail always, both with the same build. Oh, and the devices that fail always work correctly when brought back to the stock 1.1.

Comment 64

[Jason Smith [:jsmith]]

(In reply to Antonio Manuel Amaya Calvo (:amac) from comment #63)
> (In reply to Jason Smith [:jsmith] from comment #57)
> > Bumping to backlog for not being reproducible on a production device.
> 
> We're getting this same error on Buri devices. The symptoms are: At boot
> time the SIM isn't recognized, enabling and disabling the airplane mode
> makes the device see the SIM. The thing is that there are devices that work
> correctly always, and other that fail always, both with the same build. Oh,
> and the devices that fail always work correctly when brought back to the
> stock 1.1.

The Buri-specific issue is a recent regression on trunk - see bug 988979. This issue targets the non-production device issue present.

Comment 65

[Antonio Manuel Amaya Calvo (:amac)]

(In reply to Jason Smith [:jsmith] from comment #64)
> (In reply to Antonio Manuel Amaya Calvo (:amac) from comment #63)
> > (In reply to Jason Smith [:jsmith] from comment #57)
> > > Bumping to backlog for not being reproducible on a production device.
> > 
> > We're getting this same error on Buri devices. The symptoms are: At boot
> > time the SIM isn't recognized, enabling and disabling the airplane mode
> > makes the device see the SIM. The thing is that there are devices that work
> > correctly always, and other that fail always, both with the same build. Oh,
> > and the devices that fail always work correctly when brought back to the
> > stock 1.1.
> 
> The Buri-specific issue is a recent regression on trunk - see bug 988979.
> This issue targets the non-production device issue present.

Hmm no, I don't think we're seeing the same problem then. We've been getting this problem on several of our development Buris since... at least one month ago. Strangely enough, the same build works on some devices and fails to work on another ones (which work correctly with the stock 1.1).

Comment 66

[Hsin-Yi Tsai (she/her) [:hsinyi]]

(In reply to aniellob from comment #61)
> Hi,
> 
> this is the RIL logfile for my H3G sim card -> http://pastebin.com/qLgR8AQ0

No RIL_UNSOL_RESPONSE_SIM_STATUS_CHANGED delivered to gecko by modem. Seems an old RIL issue.

Comment 67

[Paul Adenot (:padenot)]

(In reply to Jason Smith [:jsmith] from comment #64)
> (In reply to Antonio Manuel Amaya Calvo (:amac) from comment #63)
> > (In reply to Jason Smith [:jsmith] from comment #57)
> > > Bumping to backlog for not being reproducible on a production device.
> > 
> > We're getting this same error on Buri devices. The symptoms are: At boot
> > time the SIM isn't recognized, enabling and disabling the airplane mode
> > makes the device see the SIM. The thing is that there are devices that work
> > correctly always, and other that fail always, both with the same build. Oh,
> > and the devices that fail always work correctly when brought back to the
> > stock 1.1.
> 
> The Buri-specific issue is a recent regression on trunk - see bug 988979.
> This issue targets the non-production device issue present.

I can repro this 100% of the time on a buri that has the patches from bug 988979 and deps (today's gaia master/gecko master). :amac's description of the problem, re. airplane mode is what happens to me.

In light of this, I think we should reconsider the priority or open a new bug that is buri-specific (although if we are seeing a race, as it seems implied in a couple comments, it might very well happen everywhere if we are unlucky).

Let me know if I can be of any help (logs/patches testing/etc.), I can repro _very_ easily on my buri.

Comment 68

[Jason Smith [:jsmith]]

That's strange - I'm not seeing this on the latest master. What base image are you running for Buri?

Comment 69

[Paul Adenot (:padenot)]

OTA updates, updated every day, I can still repro.

Comment 70

[:gerard-majax]

The FOTA updates are only touching Gecko and Gaia. I have no idea what base version Paul is running.

Comment 71

[:gerard-majax]

Attachment: ril.patch

My current workaround.

Comment 72

[Paul Adenot (:padenot)]

Can we just land this? Dogfooding is painful with this bug.

Comment 73

[Julien Wajsberg [:julienw]]

Is it still current?

Comment 74

[Gabriele Svelto [:gsvelto]]

(In reply to Julien Wajsberg [:julienw] (PTO 08/20 -> 09/15; contact schung instead) from comment #73)
> Is it still current?

I haven't experienced this issue on my Peak for a while but due to the nature of the bug it could be just by luck.

Comment 75

[:gerard-majax]

(In reply to Julien Wajsberg [:julienw] (PTO 08/20 -> 09/15; contact schung instead) from comment #73)
> Is it still current?

I have a local hack for my Nexus S so I can't tell precisely.

Comment 76

[:gerard-majax]

(In reply to Gabriele Svelto [:gsvelto] from comment #74)
> (In reply to Julien Wajsberg [:julienw] (PTO 08/20 -> 09/15; contact schung
> instead) from comment #73)
> > Is it still current?
> 
> I haven't experienced this issue on my Peak for a while but due to the
> nature of the bug it could be just by luck.

I can confirm I have not seen this for a while on my Peak, however:
 - I'm using Geeksphone's updates, so maybe they have a local hack
 - Removing the hack from my Nexus S, I still have the issue

Comment 77

[Gregor Wagner [:gwagner]]

Alex, are you still working on this? Can we close it?

Comment 78

[:gerard-majax]

(In reply to Gregor Wagner [:gwagner] from comment #77)
> Alex, are you still working on this? Can we close it?

Well I think we should keep it opened, I'm still having a look at this, but this may just be limited to some devices.

Comment 79

[:gerard-majax]

Unassigning as I'm stopping dogfooding Nexus S.

Comment 80

[:gerard-majax]

Attachment: Make sure we always read ICCID

Comment 81

[Hsin-Yi Tsai (she/her) [:hsinyi]]

This bug results from that our gecko doesn't support old deprecated AOSP ril version (RIL v6, ICS based), and as we've moved to AOSP-L (RIL v11) we don't go back to support the deprecated version.

Going to close as WONTFIX.