952386 - [wasabi][CDMA] UIM card can only be detected after flashing build and once reboot device, UIM can't be detected.

Status: VERIFIED FIXED

(Firefox OS Graveyard :: RIL, defect)

Description

[Enpei]

Attachment: wasabi-nosim.txt

After flash build, UIM card can be detected. But once reboot device, it will always fail to detect the UIM.

* Build Number     
Wasabi -           
Gaia      a9b942c98a09eed626104e6509a4ba4f50842231
Gecko     bdc10edc8a2d48bba8a2ff011974309a4158bba4
BuildID   20131220100118
Version   29.0a1

* Reproduce Steps
1. Flash build.
2. Reboot device.

* Expected Result
UIM can still be detected.

* Actual Result
UIM cannot be detected.

* Occurrence rate
100%

Comment 1

[Enpei]

Wasabi v1.2 has no such bug. It is found from v1.3.

Gaia      5772ee76645417b96b0b168f2f0845716be4bff2
Gecko     ba8ed3a7473b95eb988c8c0565b193131901e6b7
BuildID   20131220131837
Version   28.0a2

Nominate as 1.3 blocker first.

Comment 2

[Arthur Chen [:arthurcc][inactive after 6/30]]

I found that the device could detect the UIM card after enabling and the disabling the airplane mode.

Comment 3

[Edgar Chen [:edgar]]

(In reply to Enpei from comment #0)
> Created attachment 8350459 [details]
> wasabi-nosim.txt

Hmm, from the log, radio becomes to 'off', that is why device can not detect UIM card.

01-24 09:59:35.870 I/Gecko   (  200): RIL Worker[0]: Handling parcel as UNSOLICITED_RESPONSE_RADIO_STATE_CHANGED
01-24 09:59:35.870 I/Gecko   (  200): RIL Worker[0]: Radio state changed from 'ready' to 'off'
01-24 09:59:35.870 I/Gecko   (  200): -*- RadioInterface[0]: Received message from worker: {"rilMessageType":"radiostatechange","radioState":"off"}
01-24 09:59:35.870 I/Gecko   (  200): -*- RILContentHelper: Received message 'RIL:RadioStateChanged': {"clientId":0,"data":"disabled"}

Comment 4

[Edgar Chen [:edgar]]

(In reply to Edgar Chen [:edgar][:echen] from comment #3)
> (In reply to Enpei from comment #0)
> > Created attachment 8350459 [details]
> > wasabi-nosim.txt

I think we have a racing issue between handling radio state and processing radio enable/disable request.

1). After receiving system-message-listener-ready, RadioInterface will enable radio by default. [1]
------------
01-24 09:59:28.803 I/Gecko   (  200): RIL Worker[0]: Received chrome message {"enabled":true,"rilMessageToken":6,"rilMessageType":"setRadioEnabled"}
01-24 09:59:28.803 I/Gecko   (  200): RIL Worker[0]: New outgoing parcel of type 23
01-24 09:59:28.803 I/Gecko   (  200): RIL Worker[0]: Outgoing parcel: 0,0,0,16,23,0,0,0,3,0,0,0,1,0,0,0,1,0,0,0


2). Received UNSOLICITED_RESPONSE_RADIO_STATE_CHANGED, ril_woker will disable radio if the |_isInitialRadioState| is true [2].
------------
01-24 09:59:30.665 I/Gecko   (  200): RIL Worker[0]: Handling parcel as UNSOLICITED_RESPONSE_RADIO_STATE_CHANGED
01-24 09:59:30.665 I/Gecko   (  200): RIL Worker[0]: New outgoing parcel of type 23
01-24 09:59:30.665 I/Gecko   (  200): RIL Worker[0]: Outgoing parcel: 0,0,0,16,23,0,0,0,5,0,0,0,1,0,0,0,0,0,0,0
01-24 09:59:30.665 I/Gecko   (  200): RIL Worker[0]: Radio state changed from 'null' to 'off'


3). Received UNSOLICITED_RESPONSE_RADIO_STATE_CHANGED with 'ready' state (I guess it is from 1)).
----------
01-24 09:59:30.975 I/Gecko   (  200): RIL Worker[0]: Handling parcel as UNSOLICITED_RESPONSE_RADIO_STATE_CHANGED
01-24 09:59:30.975 I/Gecko   (  200): -*- RadioInterface[0]: Ignore orphan token: 6
01-24 09:59:30.975 I/Gecko   (  200): RIL Worker[0]: New outgoing parcel of type 23
01-24 09:59:30.985 I/Gecko   (  200): RIL Worker[0]: Outgoing parcel: 0,0,0,16,23,0,0,0,6,0,0,0,1,0,0,0,0,0,0,0
01-24 09:59:30.985 I/Gecko   (  200): RIL Worker[0]: Radio state changed from 'off' to 'ready'

4). Received enable request from content, but this request will not be performed due to the |detailedRadioState| is 'enabled' at that time. [3]
--------
01-24 09:59:31.045 I/Gecko   (  200): -*- RadioInterfaceLayer: Received 'RIL:SetRadioEnabled' message from content process
01-24 09:59:31.045 I/Gecko   (  200): -*- RadioInterfaceLayer: setRadioEnabled: receiveMessage: {"target":{},"name":"RIL:SetRadioEnabled","sync":false,"json":{"clientId":0,"data":{"requestId":"id{767362ed-d8de-44b2-af72-a3705c5b3bd9}","enabled":true}},"data":{"clientId":0,"data":{"requestId":"id{767362ed-d8de-44b2-af72-a3705c5b3bd9}","enabled":true}},"objects":{}}
01-24 09:59:31.045 I/Gecko   (  200): -*- RadioInterfaceLayer: setRadioEnabled: handleMessage: {"target":{},"name":"RIL:SetRadioEnabled","sync":false,"json":{"clientId":0,"data":{"requestId":"id{767362ed-d8de-44b2-af72-a3705c5b3bd9}","enabled":true}},"data":{"clientId":0,"data":{"requestId":"id{767362ed-d8de-44b2-af72-a3705c5b3bd9}","enabled":true}},"objects":{}}

So that finally radio is disabled.

[1] http://goo.gl/DgqqKX
[2] http://goo.gl/Ncx8Yt
[3] http://goo.gl/ujEEhz

Comment 5

[Edgar Chen [:edgar]]

(In reply to Edgar Chen [:edgar][:echen] from comment #4)
> 
> 2). Received UNSOLICITED_RESPONSE_RADIO_STATE_CHANGED, ril_woker will
> disable radio if the |_isInitialRadioState| is true [2].
|_isInitialRadioState| was introduced in bug 775375 to reset radio after B2G restart.
Currently most of logic to control/maintain radio state is in RadioInterfaceLayer/gRadioEnabledController, maybe we should consider to integrate |_isInitialRadioState| things into RadioInterfaceLayer/gRadioEnabledController as well.

* Note: We need to be careful about the timing between initialization and sending request. (Please see bug 849758 comment #14)

> 
> 4). Received enable request from content, but this request will not be
> performed due to the |detailedRadioState| is 'enabled' at that time. [3]
>
It seems if we drop the request in above situation, we may have synchronization issue.
To me, there are two possible solution for this:
1). Process all request instead.
2). Keep the last enabled/disabled request, and make sure the radio status will match with the last request. something like |_ensureRadioState()|[1] that we had before.

[1] http://hg.mozilla.org/mozilla-central/annotate/657afaa2c756/dom/system/gonk/RadioInterfaceLayer.js#l1497

Comment 6

[Sandip Kamat]

PM assessment: Need to block for 1.3.

Comment 7

[Edgar Chen [:edgar]]

After did more analysis, I found the key of the issue was caused by the initialization process of ril_worker and gRadioEnabledController.
1). ril_worker will try to disable radio power if |_isInitialRadioState| is true.
2). gRadioEnabledController will try to enable radio power by default.

Above two actions cause some timing problems (please see comment #4) and seems only happened in wasabi.
(I have tested with other device, but I did not encounter this issue)

Here is the solution I proposed:
1). Remove the initialization process of radio power in ril_worker.
2). Disable radio power by default in gRadioEnabledController.

With above solution, we can remove some redundant radio control to avoid timing issue caused by two different module and also can reset radio after b2g restart same as we have now.

Comment 8

[Edgar Chen [:edgar]]

(In reply to Edgar Chen [:edgar][:echen] from comment #7)
> After did more analysis, I found the key of the issue was caused by the
> initialization process of ril_worker and gRadioEnabledController.
> 1). ril_worker will try to disable radio power if |_isInitialRadioState| is
> true.
> 2). gRadioEnabledController will try to enable radio power by default.
> 
> Above two actions cause some timing problems (please see comment #4) and
> seems only happened in wasabi.
> (I have tested with other device, but I did not encounter this issue)
> 
> Here is the solution I proposed:
> 1). Remove the initialization process of radio power in ril_worker.
> 2). Disable radio power by default in gRadioEnabledController.
After offline discuss with Hsinyi, it seems better to handle radio power initialization right after received UNSOLICITED_RIL_CONNECTED rather than handle it in gRadioEnabledController.
I will try this first.
Thank you.

> 
> With above solution, we can remove some redundant radio control to avoid
> timing issue caused by two different module and also can reset radio after
> b2g restart same as we have now.

Comment 9

[Edgar Chen [:edgar]]

Attachment: Patch, v1

Comment 10

[Edgar Chen [:edgar]]

Comment on attachment 8362841 [details] [diff] [review]
Patch, v1

I tested this patch with unagi, wasabi and fugu. All of them work well. Thank you.

Comment 11

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

Comment on attachment 8362841 [details] [diff] [review]
Patch, v1

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

Good to see we remove more redundant code! Thank you.

I also test with Buri and it works well. :)

Comment 12

[Edgar Chen [:edgar]]

Try result: https://tbpl.mozilla.org/?tree=Try&rev=0d1ee587bf72

Comment 13

[Edgar Chen [:edgar]]

https://hg.mozilla.org/integration/b2g-inbound/rev/9e318ecba7e7

Comment 14

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/mozilla-central/rev/9e318ecba7e7

Comment 15

[Ryan VanderMeulen [:RyanVM]]

https://hg.mozilla.org/releases/mozilla-aurora/rev/bc7764b0d190

Comment 17

[Enpei]

The original bug is fixed, yet there is another bug that after reboot device, there is about 10 seconds, device will still show no UIM card before detect it and camp on network. This is not found on v1.2 before, I will file another bug for it.

Verified on Wasabi:
Gaia      6fbeac2415f07f10de181f0877ddf67ee299b885
Gecko     086e69971516130ad297c7f950dfb42a995217e9
BuildID   20140123182629
Version   28.0a2