960507 - Follow up to bug 948975 Multi-party call frozen when receiving and finishing a new incoming call

Status: VERIFIED FIXED

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

Description

[isabelrios]

Attachment: Call ended label with the call ongoing

Reproduced on both, 1.2 and 1.3 buri builds
-1.2 01/16 build:
Gecko-4ab7427
Gaia-539a25e
-1.3 01/16 build:
Gecko-0f53789
Gaia-423326d

STR: 
1. Start a multicall (2 parties involved)
2. Join all the calls
3. Receive a new call. Previous multicall is on hold
4. Finish the latest incoming call received 

ACTUAL
Different behaviour depending on the build:

1.2:
After step 4, the multi-call seems to be frozen as in the attached, but tapping on 'Gruop call' it is recovered correctly.

1.3:
After step 3, the device shows 'Call ended' although the call is stablished ok (see new screenshot attached) The screen is frozen, also the dialer app itself, it is necessary to power the device off and on to get it working back.

EXPECTED
The managment of the calls should work fine.

Comment 1

[Preeti Raghunath(:Preeti)]

potential cert blocker hence 1.3+

Comment 2

[Joe Cheng [:jcheng] (please needinfo)]

Rik, do you think you can take this bug? thanks

Comment 3

[Joe Cheng [:jcheng] (please needinfo)]

assuming 1.3+ is the top priority in this sprint, i am adding target milestone here. please correct the target milestone directly if you feel it does not reflect your work. Thanks

Comment 4

[Sarah Parsons]

We can repro this issue but only on older base images. After updating to either the 20131209 or the v1.2-deivce.cfg the issue no longer reproduces. NI Isabel to find out what base she was using to get the issue to occur. 

See bug 946168 and bug 948982, similar issues that were report in the past that were fixed using a newer base.

Comment 5

[Anthony Ricaud (:rik)]

I can reproduce with a newer base image. But the reproduction is not 100%. I think we have a timing issue with the "Call ended" messages but that's just a gut feeling.

Comment 6

[isabelrios]

Hi Sarah, 

When I filed this bug I was already using that base image: v1.2-deivce.cfg

Thanks

Comment 7

[Anthony Ricaud (:rik)]

Do you have a 100% repro on this? Can you make a video so I can see if the timing of those STRs matches mine?

Comment 8

[isabelrios]

Hi Anthony,
With today's 1.3 build:
Gecko-6840e8c
Gaia-744fb69
Attached a video file reproducing the problem.

Comment 9

[isabelrios]

Attachment: VID_0004.3gp

Comment 10

[Anthony Ricaud (:rik)]

I cannot reproduce anymore :( It's really weird.

Isabel: I see on your video that we have a "Unable to merge calls" banner showing up. Is that happening all the time or was it just because you tapped several times on the merge button?

Sidenote: The first call is cropped under the status bar, that's bug 959660. bug 960056 is for the + button misbehaving.

Comment 11

[Matthew Vaughan]

This issue reproduces for me on the 01/23/14 1.3 build.

This issue appears to have started reproducing on the 11/28/13 1.3 build. On builds before 11/29, there is no freezing and the user can end calls. The only issue is that the user cannot resume the group call so they have to end the call and start it again.

- Works -
Device: Buri v1.3 MOZ RIL
BuildID: 20131128040201
Gaia: 0d57ec2801ae125ec855a19cf956ab118660d694
Gecko: a5e7f611546f
Version: 28.0a1
Firmware Version: V1.2-device.cfg

- Broken -
Device: Buri v1.3 MOZ RIL
BuildID: 20131129053350
Gaia: 09d1f63762aaf645b5b6642d218b40f069b77562
Gecko: e9337081c744
Version: 28.0a1
Firmware Version: V1.2-device.cfg

Comment 12

[isabelrios]

(In reply to Anthony Ricaud (:rik) from comment #10)
> I cannot reproduce anymore :( It's really weird.
> 
> Isabel: I see on your video that we have a "Unable to merge calls" banner
> showing up. Is that happening all the time or was it just because you tapped
> several times on the merge button?
> 
> Sidenote: The first call is cropped under the status bar, that's bug 959660.
> bug 960056 is for the + button misbehaving.

Hi Anthony,
The call is correctly merged, it should had appeared because I had to tap several times to get the calls merged.
Sometimes, instead of the 'Call ended' message, I also reproduce the screen seen on the new attachment. It happens just when receiving the incoming call (Step 3). The management of that new incoming call is not working and make the conference call to stop working.

Comment 13

[isabelrios]

Attachment: New incoming call error causes wrong managment of it and the conference call stablished

Comment 14

[Anthony Ricaud (:rik)]

I was doing a git bisect to find the problematic commit but I just lost adb on a version with a broken settings app. I need to flash it again from scratch. I'll do that on Monday.

Comment 15

[Anthony Ricaud (:rik)]

My bisection is saying that a2e63ba7d798eb935392a5976dd2ff3f2b9d9337 is the commit that introduced the regression. Bug 933153.

Comment 16

[Anthony Ricaud (:rik)]

So I think this is a TelephonyAPI issue.

Since bug 933153, we hold the active call before calling the second one. In that case, when we answer the 3rd call, we get an extra onCallsChanged event. That's unexpected but our Gaia code shouldn't mind.

On top of that unexpected event, in the event handler, we have a comparison that fails. We compare each call known by Gaia with each call in the TelephonyAPI [1]. And for the second call, we have hc.call.number == call.number but hc.call != call.

We can solve this bug by changing the Gaia logic to be more robust but I believe this should be solved in the TelephonyAPI.

[1] https://github.com/mozilla-b2g/gaia/blob/61866f17977a440a3297aa8ade8f410c68d2cdd7/apps/communications/dialer/js/calls_handler.js#L146

Comment 17

[Anthony Ricaud (:rik)]

Thomas: I'm reassigning to you because Taipei is on holidays and David told me you'd be the one taking a look. Feel free to ask me for more details if my explanation is not clear.

Comment 18

[Thomas Zimmermann [:tzimmermann] [:tdz]]

Hi Anthony,

I haven't worked on ril for a while, so I'm not up to speed with this. But I'll prioritize this bug and work on it at least until the people in Taipeh are back from vacation.

Comment 19

[Anthony Ricaud (:rik)]

Attachment: Gaia diff to exhibit the issue

You can use this patch to exhibit the issue I explained in comment 16.

Comment 20

[Thomas Zimmermann [:tzimmermann] [:tdz]]

I cannot reproduce the issue, because my SIMs don't support multiparty calls. When I try to do call #2 I see the error message below.

> Hold non-connected call ignored! mNumber=+xxxxxxxxx mSecondNumber= mState=holding mCallState=5 mCallIndex=1: file /home/mozilla/Projects/mozilla/src/mozilla-central/dom/telephony/TelephonyCall.cpp, line 260

I think the phone tries to hold the first call, which is also not supported by the SIM.

Comment 21

[Gabriele Svelto [:gsvelto]]

Taking this. I've just tried reproducing it on my phone and I get a slightly different behavior. When the third call comes in if I tap to accept it then it seems that the call is accepted correctly. Once I try to finish the call the second call stays in the dialer as if it were still connected; I'm sure it's not because I've hanged it from the other side but there's no way to close the dialer then. No amount of hanging up seems to fix it; in the logcat I end up with this:

E/GeckoConsole(  136): [JavaScript Error: "Error: Unknown rilSuppSvcNotification: null" {file: "jar:file:///system/b2g/omni.ja!/components/TelephonyProvider.js" line: 318}]
E/GeckoConsole(  136): [JavaScript Error: "NS_ERROR_XPC_JS_THREW_JS_OBJECT: Error: Unknown rilSuppSvcNotification: null'Error: Unknown rilSuppSvcNotification: null' when calling method: [nsIGonkTelephonyProvider::notifySupplementaryService]" {file: "jar:file:///system/b2g/omni.ja!/components/RadioInterfaceLayer.js" line: 1484}]
E/GeckoConsole(  136): Content JS WARN at app://system.gaiamobile.org/js/app_window_manager.js:85 in awm_display: the app has been displayed.
E/GeckoConsole(  136): [JavaScript Error: "Error: Unknown rilSuppSvcNotification: null" {file: "jar:file:///system/b2g/omni.ja!/components/TelephonyProvider.js" line: 318}]
E/GeckoConsole(  136): [JavaScript Error: "NS_ERROR_XPC_JS_THREW_JS_OBJECT: Error: Unknown rilSuppSvcNotification: null'Error: Unknown rilSuppSvcNotification: null' when calling method: [nsIGonkTelephonyProvider::notifySupplementaryService]" {file: "jar:file:///system/b2g/omni.ja!/components/RadioInterfaceLayer.js" line: 1484}]

I'm not sure if this is the same problem or maybe just related. I've tested on my hamachi with a build that is a few days old; I'm rebuilding master right now to see what happens there.

Comment 22

[Gabriele Svelto [:gsvelto]]

OK, scratch my previous comment, I've managed to reproduce exactly the same issue, the RIL error messages I had found in the log are apparently unrelated.

Comment 23

[Anthony Ricaud (:rik)]

Also, if you want to see the behaviour without the issue, you can comment https://github.com/mozilla-b2g/gaia/blob/d8bdd6e84ccbb9027f811e42373cbdd53977980a/apps/communications/dialer/js/telephony_helper.js#L32-L42 except line 33-34. It will not hold the first call before making the second one.

Comment 24

[Gabriele Svelto [:gsvelto]]

OK, looking at the sequence of oncallschanged events there's something weird happening that Anthony diagnosed correctly in comment 16. Here's the sequence of oncallschanged events with the state of telephony.calls being trackerd:

* Dialing the first call

onCallsChanged() telephony.calls.length = 1
call[0] = {
    serviceId = 0
    number = 11111111
    state = dialing
    group = null
}

* First call answered

onCallsChanged() telephony.calls.length = 1
call[0] = {
    serviceId = 0
    number = 11111111
    state = dialing
    group = null
}

* Dialing the second call

onCallsChanged() telephony.calls.length = 2
call[0] = {
    serviceId = 0
    number = 11111111
    state = connected
    group = null
}
call[1] = {
    serviceId = 0
    number = 22222222
    state = dialing
    group = null
}

* Second call answered

onCallsChanged() telephony.calls.length = 1
call[0] = {
    serviceId = 0
    number = 22222222
    state = connected
    group = null
}

* Grouped calls

onCallsChanged() telephony.calls.length = 1
call[0] = {
    serviceId = 0
    number = 22222222
    state = connected
    group = [object TelephonyCallGroup]
}

* Third call comes in, telephony.calls appears empty (is the grouped call held?)

onCallsChanged() telephony.calls.length = 0

* Here's the incoming third call

onCallsChanged() telephony.calls.length = 1
call[0] = {
    serviceId = 0
    number = 33333333
    state = incoming
    group = null
}

* The original grouped call reappears, but it's a different object, its 'group' field is not set and it's in the dialing state (huh?)

onCallsChanged() telephony.calls.length = 2
call[0] = {
    serviceId = 0
    number = 33333333
    state = incoming
    group = null
}
call[1] = {
    serviceId = 0
    number = 22222222
    state = dialing
    group = null
}

* Finally it disappears again, the third call seems to be answered correctly (I can see it on the phone I used to make it) but that's not reflected by the oncallschanged event, the call state remains 'incoming'

onCallsChanged() telephony.calls.length = 1
call[0] = {
    serviceId = 0
    number = 33333333
    state = incoming
    group = null
}

I'll have to look at our telephony code because either we're interpreting incorrectly what we get within the oncallschanged events or we're just getting weird events we cannot possibly deal with.

Comment 25

[Gabriele Svelto [:gsvelto]]

I've figured out another detail. When the third call is answered the first two calls go into the 'held' state; this is expected because we're calling hold on the group call. However when the group call comes back (the mysterious fourth call appearing in telephony.calls) it's in the 'dialing' state while the two calls which should be tied to it are still on hold ('held' state). At this stage everything goes *boom*. Now digging in Gecko's telephony code to figure out where it's coming from.

Comment 26

[Gabriele Svelto [:gsvelto]]

I found an interesting bit while investigating the issue in the telephony code: when we accept the incoming third call we also try to dial the first number we called; this seems to point to an issue in Gaia rather than in the telephony code. Stay tuned for more telephony fun.

Comment 27

[Gabriele Svelto [:gsvelto]]

OK, I think I've nailed it, it seems that this line is not removing the onheld handler from the active call:

https://github.com/mozilla-b2g/gaia/blob/03f51ed669f2561e6348c1e862890569ddecf881/apps/communications/dialer/js/telephony_helper.js#L38

So it's invoked again when we accept the third incoming call and starts to dial the first number once again. I'm testing a one line patch that changes it from 'delete activeCall.onheld' to 'activeCall.onheld = null'. There's one thing that surprises me however and it's that I haven't seen Gecko complaining about us deleting the property of a DOM object. I always assumed you couldn't do that but maybe I haven't looked hard enough in the ginormous log I get when testing this.

Comment 28

[Gabriele Svelto [:gsvelto]]

Attachment: [PATCH] Properly remove the onheld event handler when doing a second call

I've verified a couple of different scenarios and it works fine. Can't believe it was this easy :-)

Comment 29

[Gabriele Svelto [:gsvelto]]

Attachment: [PULL REQUEST] Properly remove the onheld event handler when doing a second call

Here's the pull request, the travis run is here:

https://travis-ci.org/mozilla-b2g/gaia/builds/17986368

Comment 30

[Etienne Segonzac (:etienne)]

Comment on attachment 8368609 [details] [diff] [review]
[PATCH] Properly remove the onheld event handler when doing a second call

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

Stealing, because I can see Rik hard at work on another bug.

r=me with the isUndefined changed to isNull in the telephony_helper_test.js file.

(otherwise the build won't be green anyway :))

Comment 31

[Gabriele Svelto [:gsvelto]]

Attachment: [PATCH v2] Properly remove the onheld event handler when doing a second call r=etienne

Fixed the unit tests and squashed all jshint warnings for that file, carrying over the r+ flag. I've also updated the PR and the new Travis run is here:

https://travis-ci.org/mozilla-b2g/gaia/builds/17988461

Comment 32

[Etienne Segonzac (:etienne)]

https://github.com/mozilla-b2g/gaia/commit/905a2aa679f6d2ed075d9414ed8f6b35f22153ee

Comment 33

[Gabriele Svelto [:gsvelto]]

Cherry-picked and pushed to gaia/v1.3 9f1387a6f9d6ced1c170872fd5b209864b8cf859

Comment 34

[Loli (:lolimartinezcr)]

Tested (02/03/2014) and working
1.3
Gecko e01ea79
Gaia f9a37c7

master
Gecko e392563
Gaia f192815

Comment 35

[Loli (:lolimartinezcr)]

Call waiting is inactive. Open a new bug

Comment 36

[Loli (:lolimartinezcr)]

"Group Call"  is inactive when received call is hung up. Still happen this (reported in description):

"1.2:
After step 4, the multi-call seems to be frozen as in the attached, but tapping on 'Gruop call' it is recovered correctly."

So, i open a new bug

Comment 37

[Gabriele Svelto [:gsvelto]]

(In reply to Loli from comment #36)
> "1.2:
> After step 4, the multi-call seems to be frozen as in the attached, but
> tapping on 'Gruop call' it is recovered correctly."

You mean that you're unable to switch between the grouped call and the new call? I am not sure if this is a bug or intended behavior, I'm unsure if switching between calls is possible once you're in conference mode.

Comment 38

[Loli (:lolimartinezcr)]

(In reply to Gabriele Svelto [:gsvelto] from comment #37)
> (In reply to Loli from comment #36)
> > "1.2:
> > After step 4, the multi-call seems to be frozen as in the attached, but
> > tapping on 'Gruop call' it is recovered correctly."
> 
> You mean that you're unable to switch between the grouped call and the new
> call? I am not sure if this is a bug or intended behavior, I'm unsure if
> switching between calls is possible once you're in conference mode.

I can switch between the grouped call, the problem is when received call is hung up, the group call isn't active and is necesary press in "group call". New bug open bug 966951