1066961 - Construct a STK call first and then try to make another STK call via the same steps, FFOS still send CALLSETUP to modem after modem reports "STK_SESSION_END" because ME is busy on the first active call

Status: RESOLVED WORKSFORME

(Firefox OS Graveyard :: Vendcom, defect)

Description

[helloarvin]

Steps to reproduce:
a)open stk menu
b)go to music
c)go to caller tune
d)go to toll free number 123
e)again follow step a-d
f)fail to disconnect the call.

Comment 1

[helloarvin]

Attachment: slog.rar

Dear Shawn,

The reason is that we don't make a right response for the session-end from modem and still send cmd to setup call. Modem don't handle the wrong cmd for a long time so that the hangup cmd triggered by user is blocked.

Our android device works well, so could you please help check the issue?

Thanks a lot.

-------------------------------------------------------------------

// Construct 1st call
09-09 18:42:23.920   107   107 I Gecko   : -*- RadioInterface[1]: Received message from worker: {"commandNumber":11,"typeOfCommand":16,"commandQualifier":0,"rilMessageType":"stkcommand","options":{"address":"123"},"rilMessageClientId":1}
09-09 18:42:23.930   107   107 I Gecko   : -*- RadioInterface[1]: handleStkProactiveCommand {"commandNumber":11,"typeOfCommand":16,"commandQualifier":0,"rilMessageType":"stkcommand","options":{"address":"123"},"rilMessageClientId":1}

09-09 18:42:23.940   711   711 I Gecko   : -*- RILContentHelper: Received message 'RIL:StkCommand': {"clientId":1,"data":{"commandNumber":11,"typeOfCommand":16,"commandQualifier":0,"rilMessageType":"stkcommand","options":{"address":"123"},"rilMessageClientId":1}}
09-09 18:42:23.950   549   549 I Gecko   : -*- RILContentHelper: Received message 'RIL:StkCommand': {"clientId":1,"data":{"commandNumber":11,"typeOfCommand":16,"commandQualifier":0,"rilMessageType":"stkcommand","options":{"address":"123"},"rilMessageClientId":1}}
09-09 18:42:23.950   107   107 I Gecko   : -*- RILContentHelper: Received message 'RIL:StkCommand': {"clientId":1,"data":{"commandNumber":11,"typeOfCommand":16,"commandQualifier":0,"rilMessageType":"stkcommand","options":{"address":"123"},"rilMessageClientId":1}}

09-09 18:42:25.250   107   107 I Gecko   : -*- RadioInterfaceLayer: Received 'RIL:SendStkResponse' message from content process
09-09 18:42:25.250   107   524 I Gecko   : RIL Worker: [1] Received chrome message {"hasConfirmed":true,"resultCode":0,"command":{"commandNumber":11,"typeOfCommand":16,"commandQualifier":0,"rilMessageType":"stkcommand","options":{"address":"123","confirmMessage":"Call 123?"},"rilMessageClientId":1},"rilMessageClientId":1,"rilMessageToken":44,"rilMessageType":"sendStkTerminalResponse"}

09-09 18:42:25.380   107   107 I Gecko   : -*- RadioInterface[1]: Received message from worker: {"rilMessageType":"callStateChange","call":{"state":2,"callIndex":1,"toa":129,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"123","numberPresentation":0,"name":null,"namePresentation":0,"uusInfo":null,"isOutgoing":true,"isConference":false},"rilMessageClientId":1}
09-09 18:42:25.390   107   107 I Gecko   : TelephonyProvider: handleCallStateChange: {"state":2,"callIndex":1,"toa":129,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"123","numberPresentation":0,"name":null,"namePresentation":0,"uusInfo":null,"isOutgoing":true,"isConference":false}
// Call connected
09-09 18:42:42.540   107   107 I Gecko   : -*- RadioInterface[1]: Received message from worker: {"rilMessageType":"callStateChange","call":{"state":0,"callIndex":1,"toa":129,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"123","numberPresentation":0,"name":null,"namePresentation":0,"uusInfo":null,"isOutgoing":true,"isConference":false,"started":1410268362546},"rilMessageClientId":1}
09-09 18:42:42.540   107   107 I Gecko   : TelephonyProvider: handleCallStateChange: {"state":0,"callIndex":1,"toa":129,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"123","numberPresentation":0,"name":null,"namePresentation":0,"uusInfo":null,"isOutgoing":true,"isConference":false,"started":1410268362546}


// Try to construct 2nd call
09-09 18:42:46.650   107   107 I Gecko   : -*- RadioInterface[1]: Received message from worker: {"commandNumber":14,"typeOfCommand":16,"commandQualifier":0,"rilMessageType":"stkcommand","options":{"address":"123"},"rilMessageClientId":1}
09-09 18:42:46.650   107   107 I Gecko   : -*- RadioInterface[1]: handleStkProactiveCommand {"commandNumber":14,"typeOfCommand":16,"commandQualifier":0,"rilMessageType":"stkcommand","options":{"address":"123"},"rilMessageClientId":1}
09-09 18:42:46.660   549   549 I Gecko   : -*- RILContentHelper: Received message 'RIL:StkCommand': {"clientId":1,"data":{"commandNumber":14,"typeOfCommand":16,"commandQualifier":0,"rilMessageType":"stkcommand","options":{"address":"123"},"rilMessageClientId":1}}
09-09 18:42:46.660   711   711 I Gecko   : -*- RILContentHelper: Received message 'RIL:StkCommand': {"clientId":1,"data":{"commandNumber":14,"typeOfCommand":16,"commandQualifier":0,"rilMessageType":"stkcommand","options":{"address":"123"},"rilMessageClientId":1}}

09-09 18:42:46.650   135   188 D use-Rlog/RLOG-AT: [w] Channel3: AT< +SPUSATSETUPCALL:D00E81030E10008202818386038121F3
09-09 18:42:46.650   135   188 D use-Rlog/RLOG-RIL: [w] [stk unsl]RIL_UNSOL_STK_CALL_SETUP
09-09 18:42:46.650   135   188 D use-Rlog/RLOG-RILC: [w] [UNSL]< UNSOL_STK_PROACTIVE_COMMAND {D00E81030E10008202818386038121F3}
09-09 18:42:46.650   135   188 D use-Rlog/RLOG-RILC: [w] [UNSL]< UNSOL_STK_CALL_SETUP {D00E81030E10008202818386038121F3}

// modem reject the command and report a session-end
09-09 18:42:46.660   135   188 D use-Rlog/RLOG-AT: [w] Channel3: AT< +SPUSATENDSESSIONIND
09-09 18:42:46.660   135   188 D use-Rlog/RLOG-RIL: [w] [stk unsl]RIL_UNSOL_STK_SESSION_END
09-09 18:42:46.660   135   188 D use-Rlog/RLOG-RILC: [w] [UNSL]< UNSOL_STK_SESSION_END 

// FFOS still send cmd to dial
09-09 18:42:47.850   135   172 I use-Rlog/RLOG-RILC: [w] enter processCommandsCallback
09-09 18:42:47.850   135   172 I use-Rlog/RLOG-RILC: [w] PCC  alloc one command p_record
09-09 18:42:47.850   135   560 D use-Rlog/RLOG-RILC: [w] PCB request code 71 token 137
09-09 18:42:47.850   135   560 D use-Rlog/RLOG-RILC: [w] [0137]> STK_HANDLE_CALL_SETUP_REQUESTED_FROM_SIM (1)
09-09 18:42:47.850   135   560 D use-Rlog/RLOG-RIL: [w] onRequest: STK_HANDLE_CALL_SETUP_REQUESTED_FROM_SIM sState=4

// Click to hangUp 1st call
09-09 18:42:53.590   107   524 I Gecko   : RIL Worker: [1] Received chrome message {"callIndex":1,"rilMessageClientId":1,"rilMessageToken":50,"rilMessageType":"hangUp"}



09-09 18:43:37.310   107   107 I Gecko   : -*- RadioInterface[1]: Received message from worker: {"rilMessageType":"callDisconnected","call":{"state":0,"callIndex":1,"toa":129,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"123","numberPresentation":0,"name":null,"namePresentation":0,"uusInfo":null,"isOutgoing":true,"isConference":false,"started":1410268362546,"failCause":"NormalCallClearingError"},"rilMessageClientId":1}
09-09 18:43:37.310   107   107 I Gecko   : TelephonyProvider: handleCallDisconnected: {"state":0,"callIndex":1,"toa":129,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"123","numberPresentation":0,"name":null,"namePresentation":0,"uusInfo":null,"isOutgoing":true,"isConference":false,"started":1410268362546,"failCause":"NormalCallClearingError"}

Comment 2

[helloarvin]

Dear Hsin-Yi,

Could you please help check the issue for Shawn is OOO till Sep.19?
Thanks a lot.

Comment 3

[helloarvin]

Attachment: 7715_android_logs.rar

Comment 4

[helloarvin]

Dear echen & tzu-lin,

As mentioned in email, could you please help check the root-cause of the issue?

Thanks a lot.

Comment 5

[Edgar Chen [:edgar]]

(In reply to helloarvin from comment #4)
> Dear echen & tzu-lin,
> 
> As mentioned in email, could you please help check the root-cause of the
> issue?
> 
> Thanks a lot.

I will update later.
Keeps ni? to me for tracking.
Thank you.

Comment 6

[Edgar Chen [:edgar]]

Hi helloarvin:

According to ril.h [1] and as my best understanding, it seems gecko should only receive stk call setup command when the call is already been initialized. And gecko will send message to gaia to ask user confirmation, then pass the user confirmation back to modem.

Therefore, if the second call can not be initialized successfully (ME is busy on first call), why modem still send stk call setup message to ask user confirmation? IMO, in such case, modem should reply TR by itself and should not propagate stk call setup to gecko. How do you think? Please let me know if I misunderstand anything.

Thank you.

[1] https://github.com/mozilla-b2g/platform_hardware_ril/blob/master/include/telephony/ril.h#L2562-L2565

Comment 7

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

I seconded Edgar's view, which is also how I interpret the spec TS 102.223.

Quote of TS 102.223, clause 6.4.13:

"
if the command is rejected because the terminal is busy on another call, the terminal informs the UICC using
TERMINAL RESPONSE (terminal unable to process command - currently busy on call). " 
 If the terminal is able to set up the call on the serving network, the terminal shall: alert the user...
 -- if the user accepts the call, the terminal shall then set up a call to the destination address given in the response data ... ...
 -- if the user does not accept the call, or rejects the call ... ...
"

Comment 8

[helloarvin]

Dear Edgar & Hsin-Yi,

The feedback of modem team is:
1\ TERMINAL RESPONSE (terminal unable to process command - currently busy on call) has been sent to UICC;
2\ The purpose of reporting 'SPUSATSETUPCALL' to AP is to help inform user cannot dial currently in UI with the next command 'session-end'. That's to say, modem should tell AP which command had been terminated automatically via 'cmd_name + session_end'.

How do you think about?
Thanks:)

Comment 9

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

(In reply to helloarvin from comment #8)
> Dear Edgar & Hsin-Yi,
> 
> The feedback of modem team is:
> 1\ TERMINAL RESPONSE (terminal unable to process command - currently busy on
> call) has been sent to UICC;
> 2\ The purpose of reporting 'SPUSATSETUPCALL' to AP is to help inform user
> cannot dial currently in UI with the next command 'session-end'. That's to
> say, modem should tell AP which command had been terminated automatically
> via 'cmd_name + session_end'.
> 
> How do you think about?
> Thanks:)

Thanks for the explanation. I understand the design now :) However, I would say it's not a reliable design, because from gecko/gaia perspective, we will never know *in advance* if session_end will come. How long should we wait in this case? So, no matter what the magic number we choose to wait, it's still likely that UI shows confirmation dialogue and user confirms just before session_end arrives... As modem knows the 2nd STK call isn't able to make, and as the 2nd proactive command isn't really helpful for user, I still think then that 2nd proactive command shouldn't be sent to gecko.

Comment 10

[helloarvin]

Dear Hsin-Yi,
Thank you very much.
I'll discuss the issue with modem team and update the progress in time.

Comment 11

[helloarvin]

Resolve the issue via changing the component to SPRD.

Thank you all for your help.