1155022 - [RIL] Intermittent script timed out in test_outgoing_radio_off.js due to emulator command, `gsm cancel`, doesn't trigger UNSOLICITED_RESPONSE_CALL_STATE_CHANGED.

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Emulator, defect)

Description

[Edgar Chen [:edgar] (OOO ~ 04/02)]

I though the intermittent failure in test_outgoing_radio_off.js is caused by the same reason as bug 1152272. But after applying the solution of bug 1152272, intermittent failure still show in try: https://treeherder.mozilla.org/logviewer.html#?job_id=6575653&repo=try.

I capture the log from radio buffer, and found something interesting,
- Normal case (https://treeherder.mozilla.org/logviewer.html#?job_id=6579106&repo=try):
> 04-15 15:46:38.262    44    44 I Gecko   : 1429112798268	Marionette	DEBUG	conn108 emulator <- ({"emulator_cmd":"gsm cancel 112","id":3})
> 04-15 15:46:38.312    44   142 I Gecko   : RIL Worker: [0] New outgoing parcel of type 28
> 04-15 15:46:38.322    44   142 I Gecko   : RIL Worker: Outgoing parcel: 0,0,0,64,28,0,0,0,139,5,0,0,178,0,0,0,198,111,0,0,8,0,0,0,51,0,102,0,48,0,48,0,55,0,102,0,50,0,48,0,0,0,0,0,7,0,0,0,4,0,0,0,24,0,0,0,255,255,255,255,255,255,255,255,255,255,255,255
> 04-15 15:46:38.372    38    83 D AT      : AT< NO CARRIER
> 04-15 15:46:38.392    38    79 D RIL     : onRequest: SIM_IO
> 04-15 15:46:38.392    38    79 D AT      : AT> AT+CRSM=178,28614,7,4,24
> 04-15 15:46:38.392    38    83 D AT      : AT< +CRSM: 144,0,00d1dd0000fffe07ffffffffffffffffffffffffffffffff
> 04-15 15:46:38.392    38    83 D AT      : AT< OK

- Failure case (https://treeherder.mozilla.org/logviewer.html#?job_id=6575653&repo=try):
> 04-15 13:10:05.886    44    44 I Gecko   : 1429103405894	Marionette	DEBUG	conn108 emulator <- ({"emulator_cmd":"gsm cancel 112","id":3})
> 04-15 13:10:05.907    44   141 I Gecko   : RIL Worker: [0] New outgoing parcel of type 28
> 04-15 13:10:05.907    44   141 I Gecko   : RIL Worker: Outgoing parcel: 0,0,0,64,28,0,0,0,139,5,0,0,178,0,0,0,198,111,0,0,8,0,0,0,51,0,102,0,48,0,48,0,55,0,102,0,50,0,48,0,0,0,0,0,10,0,0,0,4,0,0,0,24,0,0,0,255,255,255,255,255,255,255,255,255,255,255,255
> 04-15 13:10:05.957    38    83 D RIL     : onRequest: SIM_IO
> 04-15 13:10:05.957    38    83 D AT      : AT> AT+CRSM=178,28614,10,4,24
> 04-15 13:10:05.957    38    87 D AT      : AT< NO CARRIER
> 04-15 13:10:05.957    38    87 D AT      : AT< +CRSM: 144,0,ffffffffffffffffffffffffffffffffffffffffffffffff
> 04-15 13:10:05.957    38    87 D AT      : AT< OK

No AT command lost, but the command sequence are different.

Comment 1

[Edgar Chen [:edgar] (OOO ~ 04/02)]

According to the spec, TS 127.007, 'NO CARRIER` could be: (See Annex E, F and G)
- An unsolicited message to notify remote hangup call.
- A final response for a request.

Rild decide the "NO CARRIER" is an unsolicited message or a final response by checking is there any pending request [1]. 

For the failed case mentioned in comment #0, the AT command sequence is like:
> AT> AT+CRSM=178,28614,10,4,24
> AT< NO CARRIER
> AT< +CRSM: 144,0,ffffffffffffffffffffffffffffffffffffffffffffffff
> AT< OK
The "NO CARRIER" was treated as the final response of "AT+CRSM .." request.

The ideal solution is having some way to ensure the sequence of AT response, but it is not easy to do that. Besides, current qemu doesn't support replying "NO CARRIER" as final response for now actually, we could just let rild always treat "NO CARRIER" as an unsolicited message, which is a much easier way to solve this issue.

[1] https://github.com/EdgarChen/platform_hardware_ril/blob/09b65d623026b7fdaa6be53c53b0e99d8130a134/reference-ril/atchannel.c#L245-L253

Comment 2

[Edgar Chen [:edgar] (OOO ~ 04/02)]

Working branch: https://github.com/EdgarChen/platform_hardware_ril/commits/bug_1155022/NO_CARRIER

Try looks good, https://treeherder.mozilla.org/logviewer.html#?job_id=6640616&repo=try, even having same sequence as failure case in comment #0, but it works perfect with the patch.
> 04-16 15:45:54.521 D/AT      (   38): AT> AT+CRSM=178,28613,7,4,24
> 04-16 15:45:54.531 D/AT      (   38): AT< NO CARRIER
> 04-16 15:45:54.531 D/AT      (   38): AT< +CRSM: 144,0,430685d4f29c7e03ffffffffffffffffffffffffffffffff
> 04-16 15:45:54.531 D/AT      (   38): AT< OK
> 04-16 15:45:54.551 I/Gecko   (   44): RIL Worker: [0] Handling parcel as UNSOLICITED_RESPONSE_CALL_STATE_CHANGED

Comment 3

[Edgar Chen [:edgar] (OOO ~ 04/02)]

Attachment: [platform_hardware_ril:master] PR #50

PR for platform_hardware_ril:master

Comment 4

[Edgar Chen [:edgar] (OOO ~ 04/02)]

Attachment: [platform_hardware_ril:b2g-ril_v7] PR #51

PR for platform_hardware_ril:b2g-ril_v7.

Comment 5

[Edgar Chen [:edgar] (OOO ~ 04/02)]

Comment on attachment 8593783 [details] [review]
[platform_hardware_ril:master] PR #50

Hi Hsinyi, may I have your review (Please see comment #1 and comment #2 for more details)? Thank you.

Comment 6

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

Comment on attachment 8593783 [details] [review]
[platform_hardware_ril:master] PR #50

The explanation is fair enough. Thank you for catching this.

Comment 7

[Edgar Chen [:edgar] (OOO ~ 04/02)]

Thank you, Hsinyi.

master: 
https://github.com/mozilla-b2g/platform_hardware_ril/commit/0c2ffe181ca64a6cad9c5f93ddea623f080c6434

b2g-ril_v7: 
https://github.com/mozilla-b2g/platform_hardware_ril/commit/9a9797062c6001d6346504161c51187a2968466b