835637 - Dialer does not show call made by STK proactive command SET_UP_CALL

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Gaia::Dialer, defect)

Description

[Carol Yang [:cyang]]

In GCF TC 27.22.4.13.1.5, the test is ran as follows:

- After device boots up and is connected to the network simulator, make a call to "321"
- Once call is connected to "321", the GCF test will send a proactive command for SET_UP_CALL to "+012340123456" (via a display text which asks for user confirmation)
- Upon user confirmation by pressing OK button, the active call to "321" is disconnected and the call to "+012340123456" is connected
- At the end, the test will prompt for user to disconnect the call to "+012340123456"

At this point, the dialer does not show any active calls even though the call is still active.

This shows that call from 321 was disconnected:
RILContentHelper: Received message 'RIL:CallStateChanged': {"state":10,"callIndex":1,"toa":129,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"321","numberPresentation":1,"name":"","namePresentation":1,"uusInfo":null,"isActive":false}

This shows that call to +012340123456 was connected:
RILContentHelper: Received message 'RIL:CallStateChanged': {"state":1,"callIndex":1,"toa":145,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"+012340123456","numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,"isActive":true}

I never saw a message that showed the call to +012340123456 was not active so the assumption is the call is still active but there is no way to disconnect it.

This is quite hard to reproduce outside of running via GCF. If there is any way I can collect more logs with certain logging enabled, I can do so.

Comment 1

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

(In reply to Carol Yang from comment #0)
> In GCF TC 27.22.4.13.1.5, the test is ran as follows:
> 
> - After device boots up and is connected to the network simulator, make a
> call to "321"
> - Once call is connected to "321", the GCF test will send a proactive
> command for SET_UP_CALL to "+012340123456" (via a display text which asks
> for user confirmation)
> - Upon user confirmation by pressing OK button, the active call to "321" is
> disconnected and the call to "+012340123456" is connected
> - At the end, the test will prompt for user to disconnect the call to
> "+012340123456"
> 
> At this point, the dialer does not show any active calls even though the
> call is still active.
> 
> This shows that call from 321 was disconnected:
> RILContentHelper: Received message 'RIL:CallStateChanged':
> {"state":10,"callIndex":1,"toa":129,"isMpty":false,"isMT":false,"als":0,
> "isVoice":true,"isVoicePrivacy":false,"number":"321","numberPresentation":1,
> "name":"","namePresentation":1,"uusInfo":null,"isActive":false}
> 
> This shows that call to +012340123456 was connected:
> RILContentHelper: Received message 'RIL:CallStateChanged':
> {"state":1,"callIndex":1,"toa":145,"isMpty":false,"isMT":false,"als":0,
> "isVoice":true,"isVoicePrivacy":false,"number":"+012340123456",
> "numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,
> "isActive":true}
> 

No, this wasn't 'call is connected.' State 1 here meant 'call_state_dialing.'

> I never saw a message that showed the call to +012340123456 was not active
> so the assumption is the call is still active but there is no way to
> disconnect it.
> 

Maybe you can try to find 'RIL:CallError' message in the log. If you see this, then the call has been released as well.

> This is quite hard to reproduce outside of running via GCF. If there is any
> way I can collect more logs with certain logging enabled, I can do so.

Comment 2

[Carol Yang [:cyang]]

(In reply to Hsin-Yi Tsai [:hsinyi] from comment #1)
> (In reply to Carol Yang from comment #0)
> > This shows that call to +012340123456 was connected:
> > RILContentHelper: Received message 'RIL:CallStateChanged':
> > {"state":1,"callIndex":1,"toa":145,"isMpty":false,"isMT":false,"als":0,
> > "isVoice":true,"isVoicePrivacy":false,"number":"+012340123456",
> > "numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,
> > "isActive":true}
> > 
> 
> No, this wasn't 'call is connected.' State 1 here meant 'call_state_dialing.'

Sorry, I had copied the first one of all the 'RIL:CallStateChanged'. Later, I see State 5:
RILContentHelper: Received message 'RIL:CallStateChanged': {"state":5,"callIndex":1,"toa":145,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"+012340123456","numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,"isActive":true}


> > I never saw a message that showed the call to +012340123456 was not active
> > so the assumption is the call is still active but there is no way to
> > disconnect it.
> > 
> 
> Maybe you can try to find 'RIL:CallError' message in the log. If you see
> this, then the call has been released as well.

I never saw 'RIL:CallError' in the logs these logs. One more thing I forgot to mention was that from the IT3 logs, I usually find logs that tell me the call has been connected or disconnected. In this case, I do not see a call disconnect from IT3 logs.

> 
> > This is quite hard to reproduce outside of running via GCF. If there is any
> > way I can collect more logs with certain logging enabled, I can do so.

Comment 3

[Fernando R. Sela (no CC, needinfo please) [:frsela]]

(In reply to Carol Yang from comment #0)
> In GCF TC 27.22.4.13.1.5, the test is ran as follows:
> 
> - After device boots up and is connected to the network simulator, make a
> call to "321"
> - Once call is connected to "321", the GCF test will send a proactive
> command for SET_UP_CALL to "+012340123456" (via a display text which asks
> for user confirmation)
> - Upon user confirmation by pressing OK button, the active call to "321" is
> disconnected and the call to "+012340123456" is connected
> - At the end, the test will prompt for user to disconnect the call to
> "+012340123456"
> 
> At this point, the dialer does not show any active calls even though the
> call is still active.
> 

If the call is active, is probably cause the STK command was correctly responded and the Modem started the call. So if no visual feedback is provided is because the System Message is not well managed by dialer app.

But before move the bug to dialer, I want to be sure that the STK part is working correctly.

> 
> I never saw a message that showed the call to +012340123456 was not active
> so the assumption is the call is still active but there is no way to
> disconnect it.
> 
> This is quite hard to reproduce outside of running via GCF. If there is any
> way I can collect more logs with certain logging enabled, I can do so.

Can you provide STKUI debug traces? (enabling DEBUG flag in apps/settings/js/utils.js and apps/system/js/icc_cache.js GAIA files)

Thanks

Comment 4

[Carol Yang [:cyang]]

Attachment: STKUI debug trace

Logs when GCF TC 27.22.4.13.1.5 is ran. The same result as seen before where the second call dialed via STK is still active but does not show up in dialer.

Comment 5

[Carol Yang [:cyang]]

(In reply to Fernando R. Sela [:frsela] from comment #3)
> (In reply to Carol Yang from comment #0)
> Can you provide STKUI debug traces? (enabling DEBUG flag in
> apps/settings/js/utils.js and apps/system/js/icc_cache.js GAIA files)
> 
> Thanks

Something I did notice was that while in this state where the active call does not show up in the dialer, when I attempted to dial another number, I then see '+012340123456' as the active call but hitting the End button did nothing.

Comment 6

[Fernando R. Sela (no CC, needinfo please) [:frsela]]

(In reply to Carol Yang from comment #5)
> (In reply to Fernando R. Sela [:frsela] from comment #3)
> Something I did notice was that while in this state where the active call
> does not show up in the dialer, when I attempted to dial another number, I
> then see '+012340123456' as the active call but hitting the End button did
> nothing.

My two cents:

 * Carol, can you test this again with this patch?: https://bug836135.bugzilla.mozilla.org/attachment.cgi?id=709609
   Looking to the logcat you provided, I see that the STK menu is empty which produces a Javascript error which stops the correct execution of icc.js. The patch I made for bug 836135 fix this ;)

 * After PHONE CALL command response (2639:02-01 17:37:44.029   439   439 E GeckoConsole: Content JS LOG at app://settings.example.com/js/utils.js:20 in debug: [DEBUG # Settings] sendStkResponse -- # response = {"hasConfirmed":true,"resultCode":0}) 
   The call is stablished as showed after this comment.
   I suppose the dialer app is on foreground. Isn't it?

When you tell "hitting the End button did nothing": Do you mean the Dialer app finish call button?

--8<----8<----8<----8<----8<----8<----8<----8<----8<----8<----8<----8<----8<----8<----8<----8<----8<----8<----8<--

LOG After PHONE CALL STK Command response (call established)

2759:02-01 17:37:44.609   126   126 I Gecko   : -*- QCContentHelper_QC_B2G: Notify system message manager of incoming or dialing call
2761:02-01 17:37:44.649   439   439 I Gecko   : -*- RILContentHelper: Received message 'RIL:CallStateChanged': {"state":1,"callIndex":1,"toa":145,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"+012340123456","numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,"isActive":true}
2765:02-01 17:37:44.669   126   126 I Gecko   : -*- RILContentHelper: Received message 'RIL:CallStateChanged': {"state":1,"callIndex":1,"toa":145,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"+012340123456","numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,"isActive":true}
2766:02-01 17:37:44.749   413   413 I Gecko   : -*- RILContentHelper: Received message 'RIL:CallStateChanged': {"state":1,"callIndex":1,"toa":145,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"+012340123456","numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,"isActive":true}
2772:02-01 17:37:44.939   413   413 E GeckoConsole: Content JS WARN at app://communications.example.com/shared/js/l10n.js:52 in consoleWarn: [l10n] #connecting is undefined.
2780:02-01 17:37:45.309   413   413 I Gecko   : -*- RILContentHelper: Stopping Tone
2781:02-01 17:37:45.379   413   413 E GeckoConsole: [JavaScript Warning: "HTTP "Content-Type" of "text/html" is not supported. Load of media resource app://communications.example.com/dialer/oncall.html failed." {file: "app://communications.example.com/dialer/oncall.html#unlocked" line: 0}]
2782:02-01 17:37:45.629   126   126 I Gecko   : -*- QCContentHelper_QC_B2G: receiveMessage: 'RIL:StopTone' arrived from content process
2792:02-01 17:37:45.929   466   466 E GeckoConsole: [JavaScript Warning: "Unknown property '-moz-align-self'.  Declaration dropped." {file: "resource://gre-resources/ua.css" line: 44}]
2793:02-01 17:37:46.359   413   413 I Gecko   : -*- RILContentHelper: Unregistered telephony callback: [xpconnect wrapped nsIRILVoicemailCallback]
2794:02-01 17:37:46.509   413   413 I Gecko   : -*- RILContentHelper: Unregistered telephony callback: [xpconnect wrapped nsIRILTelephonyCallback]
2890:02-01 17:37:53.709   126   126 I Gecko   : -*- QCContentHelper_QC_B2G: sendMessage to content process: RIL:CallStateChanged{  state : 5,callIndex : 1,toa : 145,isMpty : false, isMT : false, als : 0, isVoice: true, isVoicePrivacy: false, number : '+012340123456',numberPresentation : 0,name: '', namePresentation : 0, uusInfo: null, isActive : true}
2893:02-01 17:37:53.729   439   439 I Gecko   : -*- RILContentHelper: Received message 'RIL:CallStateChanged': {"state":5,"callIndex":1,"toa":145,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"+012340123456","numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,"isActive":true}
2895:02-01 17:37:53.739   126   126 I Gecko   : -*- RILContentHelper: Received message 'RIL:CallStateChanged': {"state":5,"callIndex":1,"toa":145,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"+012340123456","numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,"isActive":true}
2897:02-01 17:37:53.739   413   413 I Gecko   : -*- RILContentHelper: Received message 'RIL:CallStateChanged': {"state":5,"callIndex":1,"toa":145,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"+012340123456","numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,"isActive":true}
2903:02-01 17:37:53.839   126   126 I Gecko   : -*- QCContentHelper_QC_B2G: sendMessage to content process: RIL:StkSessionEndnull
2904:02-01 17:37:53.849   439   439 I Gecko   : -*- RILContentHelper: Received message 'RIL:StkSessionEnd': null
2905:02-01 17:37:53.859   413   413 I Gecko   : -*- RILContentHelper: Received message 'RIL:StkSessionEnd': null
2906:02-01 17:37:53.859   126   126 I Gecko   : -*- RILContentHelper: Received message 'RIL:StkSessionEnd': null

Comment 7

[Carol Yang [:cyang]]

(In reply to Fernando R. Sela [:frsela] from comment #6)
> (In reply to Carol Yang from comment #5)
> > (In reply to Fernando R. Sela [:frsela] from comment #3)
> 
> My two cents:
> 
>  * Carol, can you test this again with this patch?:
> https://bug836135.bugzilla.mozilla.org/attachment.cgi?id=709609
>    Looking to the logcat you provided, I see that the STK menu is empty
> which produces a Javascript error which stops the correct execution of
> icc.js. The patch I made for bug 836135 fix this ;)

I'll need to get back in the lab for this. Will provide logs tomorrow.

> 
>  * After PHONE CALL command response (2639:02-01 17:37:44.029   439   439 E
> GeckoConsole: Content JS LOG at app://settings.example.com/js/utils.js:20 in
> debug: [DEBUG # Settings] sendStkResponse -- # response =
> {"hasConfirmed":true,"resultCode":0}) 
>    The call is stablished as showed after this comment.
>    I suppose the dialer app is on foreground. Isn't it?

No. At this point, we're at the empty SIM Toolkit menu. To get to the dialer app, I pressed the Home button and then launch the dialer app.

> 
> When you tell "hitting the End button did nothing": Do you mean the Dialer
> app finish call button?

When I said "hitting the End button did nothing", I mean from UI perspective, looks like nothing happened (the dialer app is still up with the "End call" button still available. And from the IT3 logs, looks like a call disconnect was not received (which would be if the call was actually being hung up).

Comment 8

[Andrew Overholt [:overholt]]

Fernando, please un-assign yourself if you can't take this.

Comment 9

[Carol Yang [:cyang]]

Attachment: STKUI debug trace part 2

Fernando,

This contains logcat running GCF TC 27.22.4.13.1.5 after pulling in the patch from https://bug836135.bugzilla.mozilla.org/attachment.cgi?id=709609. The same result is seen as before.

Comment 10

[Lukas Blakk [:lsblakk] use ?needinfo]

What are the next steps here?  The deadline for landing blocker bugs is rapidly approaching (2/15) and getting this landed sooner rather than later to shake out any possible regressions would be ideal.

Comment 11

[Fernando R. Sela (no CC, needinfo please) [:frsela]]

(In reply to Lukas Blakk [:lsblakk] from comment #10)
> What are the next steps here?  The deadline for landing blocker bugs is
> rapidly approaching (2/15) and getting this landed sooner rather than later
> to shake out any possible regressions would be ideal.

We're investigating, I think the issue is in the dialer app. Theorically a system message is sent when the modem establish the call and the dialer should catch it.

By the Carol's descriptions, I assume that this system message is not correctly managed.

Looking at the end logcat:

2665:02-22 18:13:50.889   405   405 E GeckoConsole: [JavaScript Warning: "HTTP "Content-Type" of "text/html" is not supported. Load of media resource app://communications.example.com/dialer/oncall.html failed." {file: "app://communications.example.com/dialer/oncall.html#unlocked" line: 0}]


The call is established and the dialer is opened but not moved to foreground.

I think the issue is in the dialer app and not STK one, anyway I'll investigate this today.

Comment 12

[Fernando R. Sela (no CC, needinfo please) [:frsela]]

Hi Carol,

Regarding the bug 835637 I want to clarify:

 * Is the call automatically done? (looking to the logcat you provided I think that this is true)
 * Is the Dialer opened (in background)? Or it isn't opened . . . (I think this is the real issue)

I think the cause is that the dialer is not automatically opened couse the telephony-new-call system message is sent only on receiving calls . . . but I would like to be sure about this.


Could you also activate systemmessage debug traces? (in order to verify the system messages is correctly sent:

File: dom/messages/SystemMessageInternal.js
(uncomment the debug method (dump line):

function debug(aMsg) {
  dump("-- SystemMessageInternal " + Date.now() + " : " + aMsg + "\n");
}

You can see the two methods which launch this system message. In the gecko file: system/gonk/RadioInterfaceLayer.js

  /**

   * Handle an incoming call.
   *
   * Not much is known about this call at this point, but it's enough
   * to start bringing up the Phone app already.
   */
  handleCallRing: function handleCallRing() {
    if (!this._callRingWakeLock) {
      this._callRingWakeLock = gPowerManagerService.newWakeLock("cpu");
    }
    if (!this._callRingWakeLockTimer) {
      this._callRingWakeLockTimer =
        Cc["@mozilla.org/timer;1"].createInstance(Ci.nsITimer);
    }
    this._callRingWakeLockTimer
        .initWithCallback(this._cancelCallRingWakeLockTimer.bind(this),
                          CALL_WAKELOCK_TIMEOUT, Ci.nsITimer.TYPE_ONE_SHOT);

    gSystemMessenger.broadcastMessage("telephony-new-call", {});
  },

  /**
   * Handle call state changes by updating our current state and the audio
   * system.
   */
  handleCallStateChange: function handleCallStateChange(call) {
    debug("handleCallStateChange: " + JSON.stringify(call));
    call.state = convertRILCallState(call.state);

    if (call.state == nsIRadioInterfaceLayer.CALL_STATE_DIALING) {
      gSystemMessenger.broadcastMessage("telephony-new-call", {});
    }
    this.updateCallAudioState(call);
    this._sendTargetMessage("telephony", "RIL:CallStateChanged", call);
  },

Comment 13

[Carol Yang [:cyang]]

(In reply to Fernando R. Sela [:frsela] from comment #12)
> Hi Carol,
> 
> Regarding the bug 835637 I want to clarify:
> 
>  * Is the call automatically done? (looking to the logcat you provided I
> think that this is true)

Yes. The call is automatically made by the System Simulator.

>  * Is the Dialer opened (in background)? Or it isn't opened . . . (I think
> this is the real issue)

Prior to the STK proactive command coming, I had launched the dialer to dial '321'. Once the STK command comes, it seems to have been put in the background.

> 
> I think the cause is that the dialer is not automatically opened couse the
> telephony-new-call system message is sent only on receiving calls . . . but
> I would like to be sure about this.

I did see this after enabling system message debug traces:

2476:02-28 20:35:05.519   125   125 I Gecko   : -- SystemMessageInternal 320618105522 : Broadcasting telephony-new-call {"number":"+012340123456","state":1}

For full logs, please see new attachement.

Comment 14

[Carol Yang [:cyang]]

Attachment: STKUI debug trace part 3

Hi Fernando,

This contains logcat running GCF TC 27.22.4.13.1.5 after enabling STKUI and system message debug trace.

Comment 15

[Fernando R. Sela (no CC, needinfo please) [:frsela]]

(In reply to Carol Yang from comment #13)

Thank you Carol, this confirms me that the bug is in the dialer app (we should move it to foreground when the call is received.

I'll updload a patch asap.

Comment 16

[Fernando R. Sela (no CC, needinfo please) [:frsela]]

Attachment: Move communications to foreground on new calls

Carol, this patch fix the issue?

Comment 17

[Etienne Segonzac (:etienne)]

Comment on attachment 712822 [details]
Move communications to foreground on new calls

The dialer uses an attention screen [1] to show the call screen, we specifically don't want to put the dialer app frame in foreground with a getSelf().launch().

The attention screen is a second window that basically gets on top of everything else (including the lockscreen), this is how we can get the incoming calls to work properly.

We need to understand the real issue here (we confirmed in Comment 13 that the system message is sent correctly so I think the next step would be to add logs in communications/dialer/js/oncall.js).

[1] https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/attention_screen.js

Comment 18

[Carol Yang [:cyang]]

(In reply to Fernando R. Sela [:frsela] from comment #16)
> Created attachment 712822 [details]
> Move communications to foreground on new calls
> 
> Carol, this patch fix the issue?

Hi Fernando, this patch did not fix the issue. Once the second call was being automatically dialed, the STK empty menu is still shown. When I go to the dialer manually, it just shows the numpad as if I am ready to make a call. New logs collected with your patch is attached.

Comment 19

[Carol Yang [:cyang]]

Attachment: STKUI debug trace part 4

Logs collected with patch from attachment 712822 [details]. The behavior is still the same where the dialer app does not show any connecting calls.

Comment 20

[Fernando R. Sela (no CC, needinfo please) [:frsela]]

Reassigned to German which knows better dialer app.

Comment 21

[Germán Toro del Valle (:gtorodelvalle)]

Attachment: Inclusion of logs in the front end to track the problem down.

Comment 22

[Germán Toro del Valle (:gtorodelvalle)]

Hi Carol, I have made a pull request including some logs (attachment 713839 [details]) to try to shed some light on the problem. Is this OK or should I provide you with these updates some other way? Thanks!

Comment 23

[Etienne Segonzac (:etienne)]

(In reply to Carol Yang from comment #18)
> Hi Fernando, this patch did not fix the issue. Once the second call was
> being automatically dialed, the STK empty menu is still shown. When I go to
> the dialer manually, it just shows the numpad as if I am ready to make a
> call. New logs collected with your patch is attached.

Mmmhh... are we dialing an outgoing call while there is already an active call?
The dialer does not handle that, so it's very likely the issue comes from here :)

See: https://github.com/mozilla-b2g/gaia/blob/master/apps/communications/dialer/js/oncall.js#L246-248

Comment 24

[Carol Yang [:cyang]]

(In reply to gtorodelvalle from comment #22)
> Hi Carol, I have made a pull request including some logs (attachment 713839 [details]
> [details]) to try to shed some light on the problem. Is this OK or should I
> provide you with these updates some other way? Thanks!

No prob. I can pull in your patch manually and re-run the test this way. Will provide logs when I get a chance to get back into the lab.

Comment 25

[Alex Keybl [:akeybl]]

Michael confirmed that this remains a hard blocker for v1.0

Comment 26

[Carol Yang [:cyang]]

(In reply to Etienne Segonzac (:etienne) from comment #23)
> (In reply to Carol Yang from comment #18)
> > Hi Fernando, this patch did not fix the issue. Once the second call was
> > being automatically dialed, the STK empty menu is still shown. When I go to
> > the dialer manually, it just shows the numpad as if I am ready to make a
> > call. New logs collected with your patch is attached.
> 
> Mmmhh... are we dialing an outgoing call while there is already an active
> call?
> The dialer does not handle that, so it's very likely the issue comes from
> here :)

The active call (321) should have already been disconnected by the network simulator. When I go to the dialer, it shows the number pad (instead of the new call to +012340123456 that was being setup) so I was able to click on the Call log tab. There, I see 321 listed as if it was hung up.

> 
> See:
> https://github.com/mozilla-b2g/gaia/blob/master/apps/communications/dialer/
> js/oncall.js#L246-248

Comment 27

[Carol Yang [:cyang]]

(In reply to Carol Yang from comment #24)
> (In reply to gtorodelvalle from comment #22)
> > Hi Carol, I have made a pull request including some logs (attachment 713839 [details]
> > [details]) to try to shed some light on the problem. Is this OK or should I
> > provide you with these updates some other way? Thanks!
> 
> No prob. I can pull in your patch manually and re-run the test this way.
> Will provide logs when I get a chance to get back into the lab.

Hi German, I had some issues after pulling in your logging:

1) After dialing from the numpad, hitting Call button does nothing to the UI (doesn't show the connected call and duration). It just stays on the same numpad UI as if nothing was pressed even though call is connected (I can tell via IT3 logs)
2) STK command UI does pop up and asks for confirmation. After pressing Ok, via the IT3 logs, I can tell that the old call from #1 is disconnected and a new call is connected but now, the screen is completely white
3) Pressing home button and then Dialer app, takes me to the numpad screen for a second and then I see white screen again

Because I only had a limited time in the lab, I couldn't debug until I left there and found that this particular line in oncall.js is causing the dialer issue:

+    console.log("********** callscreen: " + callscreen);

When I removed this line, the dialer part acted normal as it was before. I'm not sure if other parts of your new logging would cause the remaining UI issues I saw but since I can't return to the lab until tomorrow, can you please have a look at your logging and see if anything else needs to be changed? I have collected logs but since I encountered more than the original issue, not sure if that's of any help to you.

Comment 28

[Germán Toro del Valle (:gtorodelvalle)]

Indeed it helped a lot! In fact, I am really sorry for the mistake but in my testing I did not realized of the typo :-( I have pushed a minor update to the the pull request (https://github.com/mozilla-b2g/gaia/pull/8097) So, please, pull it again and try it out :-) I have rechecked all the logging and there should be no more typos... ;-999 Thank you very much!

Comment 29

[Carol Yang [:cyang]]

Attachment: STKUI debug trace part 5

Pulled in https://github.com/mozilla-b2g/gaia/pull/8097 and also enabled other STK UI debug trace. Test is ran as follows:

1) User launches Dialer app to dial to '321'
2) After call connects, STK command comes in to setup a call to '012340123456'
3) After user confirms the call, call to '321' will disconnect (green bar disappears and IT3 logs show call is disconnected) and call to +012340123456 is setup by the system simulator
4) After call is connected to +012340123456 (via IT3 logs), UI stays on the empty STK menu
5) User presses Home button and launches Dialer app again which now shows the numpad and not the existing call to +012340123456 so there is no way to hang up the call

Comment 30

[Carol Yang [:cyang]]

(In reply to gtorodelvalle from comment #28)
> Indeed it helped a lot! In fact, I am really sorry for the mistake but in my
> testing I did not realized of the typo :-( I have pushed a minor update to
> the the pull request (https://github.com/mozilla-b2g/gaia/pull/8097) So,
> please, pull it again and try it out :-) I have rechecked all the logging
> and there should be no more typos... ;-999 Thank you very much!

Thanks! This new pull request worked out. Please checkout attachment 714479 [details] for latest logs.

Comment 31

[Germán Toro del Valle (:gtorodelvalle)]

(In reply to Carol Yang from comment #30)
> (In reply to gtorodelvalle from comment #28)
> > Indeed it helped a lot! In fact, I am really sorry for the mistake but in my
> > testing I did not realized of the typo :-( I have pushed a minor update to
> > the the pull request (https://github.com/mozilla-b2g/gaia/pull/8097) So,
> > please, pull it again and try it out :-) I have rechecked all the logging
> > and there should be no more typos... ;-999 Thank you very much!
> 
> Thanks! This new pull request worked out. Please checkout attachment 714479 [details]
> [details] for latest logs.

Hi Carol ;) After going nuts checking the logs :-p I do not know if I am going to be of great help but something "I do not like" about the logs is this:

3149:02-03 19:31:28.859   437   437 I Gecko   : -*- RILContentHelper: Received message 'RIL:CallStateChanged': {"state":1,"callIndex":1,"toa":145,"isMpty":false,"isMT":false,"als":0,"isVoice":true,"isVoicePrivacy":false,"number":"+012340123456","numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,"isActive":true}
3162:02-03 19:31:29.099   437   437 E GeckoConsole: Content JS LOG at app://communications.gaiamobile.org/dialer/js/dialer.js:103 in newCall: ********** In new call...
3163:02-03 19:31:29.109   437   437 E GeckoConsole: Content JS LOG at app://communications.gaiamobile.org/dialer/js/dialer.js:107 in newCall: ********** telephony: [object Telephony]
3164:02-03 19:31:29.109   437   437 E GeckoConsole: Content JS LOG at app://communications.gaiamobile.org/dialer/js/dialer.js:220 in openCallScreen: ********** In openCallScreen...
3165:02-03 19:31:29.109   437   437 E GeckoConsole: Content JS LOG at app://communications.gaiamobile.org/dialer/js/dialer.js:221 in openCallScreen: ********** callScreenWindow: [object Window]
3166:02-03 19:31:29.119   437   437 E GeckoConsole: Content JS LOG at app://communications.gaiamobile.org/dialer/js/dialer.js:247 in anonymous: ********** In telephony.oncallschanged...
3167:02-03 19:31:29.139   437   437 E GeckoConsole: Content JS LOG at app://communications.gaiamobile.org/dialer/js/oncall.js:404 in trWait: ********** In call screen transitionend handler...
3168:02-03 19:31:29.149   437   437 E GeckoConsole: Content JS LOG at app://communications.gaiamobile.org/dialer/js/dialer.js:292 in handleCallScreenClosing: ********** In handleCallScreenClosing...

As you can see this is regarding the second call made to "+012340123456".

Let's put it this way: "something" is provoking the notification of the callschanged event which if you have a look at the code closes the outgoing call attention screen, when I guess it shouldn't.

Does this behavior make any sense to you?

Comment 32

[Carol Yang [:cyang]]

(In reply to gtorodelvalle from comment #31)
> (In reply to Carol Yang from comment #30)
> > (In reply to gtorodelvalle from comment #28)
> > > Indeed it helped a lot! In fact, I am really sorry for the mistake but in my
> > > testing I did not realized of the typo :-( I have pushed a minor update to
> > > the the pull request (https://github.com/mozilla-b2g/gaia/pull/8097) So,
> > > please, pull it again and try it out :-) I have rechecked all the logging
> > > and there should be no more typos... ;-999 Thank you very much!
> > 
> > Thanks! This new pull request worked out. Please checkout attachment 714479 [details]
> > [details] for latest logs.
> 
> Hi Carol ;) After going nuts checking the logs :-p I do not know if I am
> going to be of great help but something "I do not like" about the logs is
> this:
> 
> 3149:02-03 19:31:28.859   437   437 I Gecko   : -*- RILContentHelper:
> Received message 'RIL:CallStateChanged':
> {"state":1,"callIndex":1,"toa":145,"isMpty":false,"isMT":false,"als":0,
> "isVoice":true,"isVoicePrivacy":false,"number":"+012340123456",
> "numberPresentation":0,"name":"","namePresentation":0,"uusInfo":null,
> "isActive":true}
> 3162:02-03 19:31:29.099   437   437 E GeckoConsole: Content JS LOG at
> app://communications.gaiamobile.org/dialer/js/dialer.js:103 in newCall:
> ********** In new call...
> 3163:02-03 19:31:29.109   437   437 E GeckoConsole: Content JS LOG at
> app://communications.gaiamobile.org/dialer/js/dialer.js:107 in newCall:
> ********** telephony: [object Telephony]
> 3164:02-03 19:31:29.109   437   437 E GeckoConsole: Content JS LOG at
> app://communications.gaiamobile.org/dialer/js/dialer.js:220 in
> openCallScreen: ********** In openCallScreen...
> 3165:02-03 19:31:29.109   437   437 E GeckoConsole: Content JS LOG at
> app://communications.gaiamobile.org/dialer/js/dialer.js:221 in
> openCallScreen: ********** callScreenWindow: [object Window]
> 3166:02-03 19:31:29.119   437   437 E GeckoConsole: Content JS LOG at
> app://communications.gaiamobile.org/dialer/js/dialer.js:247 in anonymous:
> ********** In telephony.oncallschanged...
> 3167:02-03 19:31:29.139   437   437 E GeckoConsole: Content JS LOG at
> app://communications.gaiamobile.org/dialer/js/oncall.js:404 in trWait:
> ********** In call screen transitionend handler...
> 3168:02-03 19:31:29.149   437   437 E GeckoConsole: Content JS LOG at
> app://communications.gaiamobile.org/dialer/js/dialer.js:292 in
> handleCallScreenClosing: ********** In handleCallScreenClosing...
> 
> As you can see this is regarding the second call made to "+012340123456".
> 
> Let's put it this way: "something" is provoking the notification of the
> callschanged event which if you have a look at the code closes the outgoing
> call attention screen, when I guess it shouldn't.
> 
> Does this behavior make any sense to you?

Something we noticed here is that the time between the last call disconnect (for 321) and the new call being dialed (+012340123456) is only 200ms from each other:

02-03 19:31:28.409   124   124 I Gecko   : -*- QCContentHelper_QC_B2G: sendMessage to content process: RIL:CallStateChanged{  state : 10,callIndex : 1,toa : 129,isMpty : false, isMT : false, als : 0, isVoice: true, isVoicePrivacy: false, number : '321',numberPresentation : 1,name: '', namePresentation : 1, uusInfo: null, isActive : false}

02-03 19:31:28.609   124   124 I Gecko   : -*- QCContentHelper_QC_B2G: sendMessage to content process: RIL:CallStateChanged{  state : 1,callIndex : 1,toa : 145,isMpty : false, isMT : false, als : 0, isVoice: true, isVoicePrivacy: false, number : '+012340123456',numberPresentation : 0,name: '', namePresentation : 0, uusInfo: null, isActive : true}

Is UI handling this properly when the two call state changes are so closely sent?

Comment 33

[Etienne Segonzac (:etienne)]

Attachment: Fix?

Hi Carol, can you make a run with this patch?

I think the issue with the UI and the delay between the 2 calls is a good lead.

This is a quick patch to make the dialer app able to receive a new call faster once the previous one is disconnected.

Comment 34

[Andrew Overholt [:overholt]]

Clarifying ownership

Comment 35

[Fernando R. Sela (no CC, needinfo please) [:frsela]]

Looking the log traces, I think if the destination number exists or not (is very strange, isn't it?)

Could be that the connection is closed by the network for non-existent target?

Could be useful to increase the ril log level. WDYT?

Comment 36

[Germán Toro del Valle (:gtorodelvalle)]

+1

Comment 37

[Carol Yang [:cyang]]

Attachment: STKUI debug trace part 6

Contains debug trace as well as patch from Etienne in attachment 715939 [details] [diff] [review]. Patch did not fix the issue. Behavior is still the same as before.

Comment 38

[Carol Yang [:cyang]]

(In reply to Etienne Segonzac (:etienne) from comment #33)
> Created attachment 715939 [details] [diff] [review]
> Fix?
> 
> Hi Carol, can you make a run with this patch?
> 
> I think the issue with the UI and the delay between the 2 calls is a good
> lead.
> 
> This is a quick patch to make the dialer app able to receive a new call
> faster once the previous one is disconnected.

Hi Etienne, unfortunately, the patch from attachment 715939 [details] [diff] [review] did not fix the issue. I am still seeing the same behavior as before.

Aside from making sure that the new call can be received, I think the UI is also inconsistent with the other SET_UP_CALL behavior. For example, if there are no existing/active calls and a SET_UP_CALL STK command comes, user would be prompted to confirm the call. When user presses Ok, the dialer app is brought to the foreground and user can see that the new call is now connected.

However, in the current case where there is an existing call and STK command comes, we remain on the empty SIM Toolkit menu once user presses Ok. So the fix would not only need to be able to handle receiving the new call faster, but also show the new call, as is the case stated above (when there are no existing/active calls) by possibly bringing the dialer app to the foreground?

New logs provided in attachment 716676 [details] (I added extra debug to show that postToMainWindow is called).

Comment 39

[Etienne Segonzac (:etienne)]

Attachment: New patch - instantly closing the call screen

I spent some quality time with the various logs and grep, and here is a new try: the previous patch did the postToMainWindow(closing) in time (before the telephony-new-call sys message) but the window itself was still open for about half a second after that.

It shouldn't cause an issue but this new patch will tell us for sure: we're doing the postToMainWindow and closing the window directly. I also added some logs at the gaia system app level to further validate this hunch.

I can't wait for the results with this one!
Thanks again Carol, it's a lot of back and forth but we're getting somewhere.

PS: please also keep German's log patch applied, it's really helpful.

Comment 40

[Carol Yang [:cyang]]

Attachment: Logs when TC passes with attachment 717160

Hi Etienne,

Your latest patch in attachment 717160 [details] [diff] [review] seems to have worked! After user confirms the call setup, the dialer is eventually brought forward and I was able to terminate the second call to '+012340123456'. Attached the logs in case you wanted to confirm anything else. Thanks so much for your help!

FYI, there's a similar bug to this but instead of disconnecting, it puts the first call on hold: https://bugzilla.mozilla.org/show_bug.cgi?id=843734

Comment 41

[Etienne Segonzac (:etienne)]

Attachment: Patch proposal

Now that we have nailed down the issue, here is a patch fixing the bug without sacrificing the nice animation.

Fingers crossed, the STK test should pass with only this patch applied.

But I'm confident enough to ask Francisco for review right away, this way we can land it as soon as we get the GO from Carol.

Comment 42

[Francisco Jordano [:arcturus] [:francisco]]

Comment on attachment 717880 [details] [diff] [review]
Patch proposal

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

::: apps/communications/dialer/js/dialer.js
@@ +261,4 @@
>      var highPriorityWakeLock = navigator.requestWakeLock('high-priority');
>      var openWindow = function dialer_openCallScreen(state) {
>        callScreenWindow = window.open(urlBase + '#' + state,
> +                  ('call_screen' + callScreenId++), 'attention');

Here we are missing the pointer to any previous call screen opened before.

If I can remember correctly we will need that reference, not for closing the window in a normal call, but in some cases we were closing the window via sending a postMessage (cannot remember the message), in cases where the call finishes before we are able to open completely the call.

Will we have the case of a zombi call screen cause of that special case and this patch?

Comment 43

[Etienne Segonzac (:etienne)]

(In reply to Francisco Jordano [:arcturus] from comment #42)
> Comment on attachment 717880 [details] [diff] [review]
> Patch proposal
> 
> Review of attachment 717880 [details] [diff] [review]:
> -----------------------------------------------------------------
> 
> ::: apps/communications/dialer/js/dialer.js
> @@ +261,4 @@
> >      var highPriorityWakeLock = navigator.requestWakeLock('high-priority');
> >      var openWindow = function dialer_openCallScreen(state) {
> >        callScreenWindow = window.open(urlBase + '#' + state,
> > +                  ('call_screen' + callScreenId++), 'attention');
> 
> Here we are missing the pointer to any previous call screen opened before.
> 
> If I can remember correctly we will need that reference, not for closing the
> window in a normal call, but in some cases we were closing the window via
> sending a postMessage (cannot remember the message), in cases where the call
> finishes before we are able to open completely the call.

Yep, we use the |callScreenWindow| variable for that.

> 
> Will we have the case of a zombi call screen cause of that special case and
> this patch?

There is no other reference to the "call_screen" name anywhere else in the communications app directory, so I'm pretty sure it's safe :)

Comment 44

[Francisco Jordano [:arcturus] [:francisco]]

Comment on attachment 717880 [details] [diff] [review]
Patch proposal

Tried on the phone, working well :)

Comment 45

[Carol Yang [:cyang]]

(In reply to Etienne Segonzac (:etienne) from comment #41)
> Created attachment 717880 [details] [diff] [review]
> Patch proposal
> 
> Now that we have nailed down the issue, here is a patch fixing the bug
> without sacrificing the nice animation.
> 
> Fingers crossed, the STK test should pass with only this patch applied.
> 
> But I'm confident enough to ask Francisco for review right away, this way we
> can land it as soon as we get the GO from Carol.

Hi Etienne, I tried this patch and things look good!

Comment 46

[Etienne Segonzac (:etienne)]

https://github.com/mozilla-b2g/gaia/commit/3f69c326ec7d7318829a39afe9ca8c0a45ef0996

Comment 47

[John Ford [:jhford] CET/CEST Berlin Time]

Uplifting commit 3f69c326ec7d7318829a39afe9ca8c0a45ef0996:
v1-train: aa18b270b6d15a983f5c00e27a8bcebf7b7aa6d9
v1.0.1: 3e9edb0781aee0e74dd3ed9749ecfccabb0bdab8

Comment 48

[Cody Roesch [:croesch]]

Can you please provide steps to verify this fix - as we will blackbox test from the UI?

Somehow I doubt we can do this over here but I thought i'd check anyway.

Comment 49

[Germán Toro del Valle (:gtorodelvalle)]

He, he... You are mostly right, croesch ;-)

BTW, I would suggest you to set the "Need more information from" flag to the assigned person :-) You may probably get quicker replies this way :-)

Comment 50

[Carol Yang [:cyang]]

This was found while running GCF TC 27.22.4.13.1.5. If you don't have a setup for that, not sure how you can test without hacking some code :\

Comment 51

[Etienne Segonzac (:etienne)]

This is only testable with a STK test bench, that's why it was so hard to fix :)

Comment 52

[Cody Roesch [:croesch]]

Understood.
Tagging as QARegressExclude.