886245 - [B2G] [Dialer] Duplicate missed call notifications show up due to more than one callscreen being opened

Status: RESOLVED FIXED

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

Description

[leo.bugzilla.gecko]

GAIA : f2d6ed54a236e6e3b94f0abad9f0dacb8a1cc7b3
GECKO : be276cf55ce160bca09f36d9ca679a2ae20ea7cc


Ringtone is overwrapped occasionally.
It reproduced well right after the device is booted.

Comment 1

[leo.bugzilla.gecko]

Attachment: duplicated ringtone log

Comment 2

[leo.bugzilla.gecko]

I think the below patches of #823958 are related with this phenomenon.
https://hg.mozilla.org/releases/mozilla-b2g18_v1_1_0_hd/rev/dd63ed7329f6
https://hg.mozilla.org/releases/mozilla-b2g18_v1_1_0_hd/rev/c958c525d075

I uploaded the log and please check the log (Especially, RIL:EnumerateCalls event).

Comment 3

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

Sorry, I don't get this issue. RIL:EnumerateCalls messages are not directly related to any ringtone operation. Bug 823958, either. 

Could you please clarify what's the expected behaviour and what's actual behaviour right now? Thank you.

Comment 4

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

(In reply to Hsin-Yi Tsai [:hsinyi] from comment #3)
> Sorry, I don't get this issue. RIL:EnumerateCalls messages are not directly
> related to any ringtone operation. Bug 823958, either. 
> 
> Could you please clarify what's the expected behaviour and what's actual
> behaviour right now? Thank you.

Detailed STR always helps. Thanks.

I'll also cc Anshul since it seems it's using commercial RIL per log attached.

Comment 5

[leo.bugzilla.gecko]

<Testcase>
1. After booting, A calls to the device. (MT call)
2. Ringtone is overwrapped occasionally in device. (It is reproduced 50%)
3. Before answering, A ends the call.
When this is reproduced, the 2 missed calls are updated in call log.

=> The ringtone should be generated only once in a time.

In log, the 'RIL:EnumerateCalls' events are printed duplicate.
06-20 22:27:30.419 I/Gecko   (  384): -*- RILContentHelper: Requesting enumeration of calls for callback: [xpconnect wrapped nsIRILTelephonyCallback]

06-20 22:27:31.759 I/Gecko   (  384): -*- RILContentHelper: Requesting enumeration of calls for callback: [xpconnect wrapped nsIRILTelephonyCallback]

06-20 22:27:32.139 I/Gecko   (  384): -*- RILContentHelper: Requesting enumeration of calls for callback: [xpconnect wrapped nsIRILTelephonyCallback]

Comment 6

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

(In reply to leo.bugzilla.gecko from comment #5)
> <Testcase>
> 1. After booting, A calls to the device. (MT call)
> 2. Ringtone is overwrapped occasionally in device. (It is reproduced 50%)
> 3. Before answering, A ends the call.
> When this is reproduced, the 2 missed calls are updated in call log.
> 
> => The ringtone should be generated only once in a time.

I can imagine in some cases you would hear duplicated busy tone, and that's because of bug 857951. After step 3, carrier might send out some specific busy tone. Then, once gaia gets busy state, it will play busy tone again (see bug 857951). If that's the case, we shall see |'RIL:CallStateChanged': {"state":3,"...| but I see nothing related in the log.

> 
> In log, the 'RIL:EnumerateCalls' events are printed duplicate.
> 06-20 22:27:30.419 I/Gecko   (  384): -*- RILContentHelper: Requesting
> enumeration of calls for callback: [xpconnect wrapped
> nsIRILTelephonyCallback]
> 
> 06-20 22:27:31.759 I/Gecko   (  384): -*- RILContentHelper: Requesting
> enumeration of calls for callback: [xpconnect wrapped
> nsIRILTelephonyCallback]
> 
> 06-20 22:27:32.139 I/Gecko   (  384): -*- RILContentHelper: Requesting
> enumeration of calls for callback: [xpconnect wrapped
> nsIRILTelephonyCallback]

More than one 'RIL:EnumerateCalls' message might appear, but it doesn't imply they are duplicated. That's because more than one telephonyListeners might request enumeration even in the same process, so it's expected to see several 'RIL:EnumerateCalls.' Further, this message has nothing to do with ringtone operation. 

Also, update of audio phone state looks right to me in the log.

Comment 7

[leo.bugzilla.gecko]

Attachment: video file

Comment 8

[leo.bugzilla.gecko]

This is not about busy tone.
Please check the video file.

Comment 9

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

(In reply to leo.bugzilla.gecko from comment #8)
> This is not about busy tone.
> Please check the video file.
Thanks for the video. It helps.
I would like to change to bug description to make it clear.

Comment 10

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

I cannot reproduce this issue even after rebooting and powering off the device. 
Reproducing rate: 0/10

The device and build version I used: Leo with Moz RIL
Gecko: git mozillaorg/gecko-18, 96c693c47c9afcb603fd4ded1cc87d998e08331b
Gaia: git mozillaorg/v1-train, 0d5a9a7577f16b6a72a982148c6f509ee1714ea2


Note: The above version contains the commits in comment #0.

Comment 11

[leo.bugzilla.gecko]

Would you refer to Comment #26 of Bug 882841?
We use commercial ril. It might be caused by use of reference ril, not commercial ril.
It is still reproduced.

Comment 12

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

(In reply to leo.bugzilla.gecko from comment #11)
> Would you refer to Comment #26 of Bug 882841?
> We use commercial ril. It might be caused by use of reference ril, not
> commercial ril.
> It is still reproduced.

Hi Leo,

Sorry that I am not sure what information you would like me to provide.

I tested with the latest code, with Moz RIL, again and still cannot reproduce this issue.

gecko: github, mozillaorg/gecko-18, e7708d494f8be46fe602e4c0264d5861bb6ac13a
gaia: github, mozillaorg/v1-train, 5d7a0da528dce626b563abafc135eb828599d3c0
      github, mozillaorg/master, 4834511b24e5640ab096204434a614a8b8e61c20

As you are using commercial RIL and I cannot reproduce it with moz RIL, I'd like to ask for qa's help to verify this issue. Thank you.

Comment 13

[leo.bugzilla.gecko]

Hm. If I block the below code, this is not reproduced.
It needs more debugging but please check the one more about callschanged event.

// RILContentHelper.js
handleEnumerateCalls: function handleEnumerateCalls(calls) {
...
      if (!keepGoing) {
        break;
      }
    }
    //callback.enumerateCallStateComplete();
  },

Comment 14

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

(In reply to leo.bugzilla.gecko from comment #13)
> Hm. If I block the below code, this is not reproduced.
> It needs more debugging but please check the one more about callschanged
> event.
> 
> // RILContentHelper.js
> handleEnumerateCalls: function handleEnumerateCalls(calls) {
> ...
>       if (!keepGoing) {
>         break;
>       }
>     }
>     //callback.enumerateCallStateComplete();
>   },

Thanks for the info. 
Would you please tell which branch and which version/commit you are testing with, as I do have trouble reproducing this?

Comment 15

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

(In reply to Hsin-Yi Tsai [:hsinyi] from comment #14)
> (In reply to leo.bugzilla.gecko from comment #13)
> > Hm. If I block the below code, this is not reproduced.
> > It needs more debugging but please check the one more about callschanged
> > event.
> > 
> > // RILContentHelper.js
> > handleEnumerateCalls: function handleEnumerateCalls(calls) {
> > ...
> >       if (!keepGoing) {
> >         break;
> >       }
> >     }
> >     //callback.enumerateCallStateComplete();
> >   },
> 
> Thanks for the info. 
> Would you please tell which branch and which version/commit you are testing
> with, as I do have trouble reproducing this?

Hi Etienne,

Do you think any possibility that one more callschanged event (without carrying a call object) could lead to this issue?

Comment 16

[leo.bugzilla.gecko]

Mozilla-b2g18 (Leo)

Build ID = 20130616070209
gaia revision="f2d6ed54a236e6e3b94f0abad9f0dacb8a1cc7b3"
gecko revision="be276cf55ce160bca09f36d9ca679a2ae20ea7cc"

Comment 17

[Etienne Segonzac (:etienne)]

(In reply to Hsin-Yi Tsai [:hsinyi] from comment #15)
> (In reply to Hsin-Yi Tsai [:hsinyi] from comment #14)
> > (In reply to leo.bugzilla.gecko from comment #13)
> > > Hm. If I block the below code, this is not reproduced.
> > > It needs more debugging but please check the one more about callschanged
> > > event.
> > > 
> > > // RILContentHelper.js
> > > handleEnumerateCalls: function handleEnumerateCalls(calls) {
> > > ...
> > >       if (!keepGoing) {
> > >         break;
> > >       }
> > >     }
> > >     //callback.enumerateCallStateComplete();
> > >   },
> > 
> > Thanks for the info. 
> > Would you please tell which branch and which version/commit you are testing
> > with, as I do have trouble reproducing this?
> 
> Hi Etienne,
> 
> Do you think any possibility that one more callschanged event (without
> carrying a call object) could lead to this issue?

In the code path that triggers the notification we remove the event listener right away [1]. So having 2 statechange triggered on 1 call object wouldn't cause this bug.

Looks like somehow we added 2 calls, which shouldn't be possible, the code preventing this from happening can be found here [2].

[1] https://github.com/mozilla-b2g/gaia/blob/master/apps/communications/dialer/js/oncall.js#L322
[2] https://github.com/mozilla-b2g/gaia/blob/master/apps/communications/dialer/js/oncall.js#L261-L269

Comment 18

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

(In reply to Etienne Segonzac (:etienne) from comment #17)
> (In reply to Hsin-Yi Tsai [:hsinyi] from comment #15)
> > (In reply to Hsin-Yi Tsai [:hsinyi] from comment #14)
> > > (In reply to leo.bugzilla.gecko from comment #13)
> > > > Hm. If I block the below code, this is not reproduced.
> > > > It needs more debugging but please check the one more about callschanged
> > > > event.
> > > > 
> > > > // RILContentHelper.js
> > > > handleEnumerateCalls: function handleEnumerateCalls(calls) {
> > > > ...
> > > >       if (!keepGoing) {
> > > >         break;
> > > >       }
> > > >     }
> > > >     //callback.enumerateCallStateComplete();
> > > >   },
> > > 

Hi Leo,

Indeed, the line you marked triggers one more 'callschanged' event without carrying a call object, and this is the expected behaviour and improvement that we would like to have. However, since the telephony API behaviour changes, the api users (some Apps) should change accordingly otherwise something unexpected might happen. 

Thank for Etienne's feedback. We checked how dialer app deals with missed call notifications (see comment #17). According to the code, the dialer app have already handled the multiple/duplicate events which shouldn't cause this issue. 

However, as [1], [2] and [3] are the exact points triggering missed call notification, would you please help add debug messages there to gather more information once you are reproducing the issue, to help us understand whether the code somehow added duplicate calls accidentally? Thank you.

[1]
https://github.com/mozilla-b2g/gaia/blob/master/apps/communications/dialer/js/oncall.js#L322
[2]
https://github.com/mozilla-b2g/gaia/blob/master/apps/communications/dialer/js/oncall.js#L261-L269
[3]
https://github.com/mozilla-b2g/gaia/blob/master/apps/communications/dialer/js/oncall.js#L324

Comment 19

[Natalya Kot [:nkot]]

have not been able to reproduce this issue on 7/08 Leo build, COM_RIL 

Build  20130708070214
Gecko  http://hg.mozilla.org/releases/mozilla-b2g18/rev/8c0127cc7be3
Gaia   7c40bdaeaffae708342fc773926dcfac5389348e
RIL    01.01.00.019.152

leaving "qawanted" for someone else to try reproduce it

Comment 20

[Mila Davydova]

Attachment: Screenshot

Comment 21

[Mila Davydova]

I was able to reproduce this issue on Leo build ID: 20130709070206, COM RIL

Gecko: http://hg.mozilla.org/releases/mozilla-b2g18/rev/f917f3fb17ab
Gaia: e251ee6bdab13d8620afa8f9c2d5f14e5e6a4f99
Platform Version: 18.1
RIL Version: 01.01.00.019.152 

When user receives a missed call right after device was rebooted, the missed call notification is duplicated on the device. 
Screenshot is attached.

Comment 22

[leo.bugzilla.gecko]

Hsin-Yi,

Any update on this?
(In reply to Hsin-Yi Tsai [:hsinyi] from comment #18)
Indeed, the line you marked triggers one more 'callschanged' event
> without carrying a call object, and this is the expected behaviour and
> improvement that we would like to have. However, since the telephony API
> behaviour changes, the api users (some Apps) should change accordingly
> otherwise something unexpected might happen. 

If the below line in RILContentHelper.js file is blocked, what is the kind of problem occured?
>     //callback.enumerateCallStateComplete();

Comment 23

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

(In reply to leo.bugzilla.gecko from comment #22)
> Hsin-Yi,
> 
> Any update on this?

I still cannot reproduce this. As my previous comment #18, it's worth adding more debug messages in gaia and starting tracing from there. Would you please help add debug messages there to gather more information once you are reproducing the issue?

> (In reply to Hsin-Yi Tsai [:hsinyi] from comment #18)
> Indeed, the line you marked triggers one more 'callschanged' event
> > without carrying a call object, and this is the expected behaviour and
> > improvement that we would like to have. However, since the telephony API
> > behaviour changes, the api users (some Apps) should change accordingly
> > otherwise something unexpected might happen. 
> 
> If the below line in RILContentHelper.js file is blocked, what is the kind
> of problem occured?
> >     //callback.enumerateCallStateComplete();

This is what we added in bug 823958. If we mark this line, then its dependent bugs, such as bug 837344 and bug 860614, happen.

Comment 24

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

(In reply to Mila Davydova from comment #21)
> I was able to reproduce this issue on Leo build ID: 20130709070206, COM RIL
> 
> Gecko: http://hg.mozilla.org/releases/mozilla-b2g18/rev/f917f3fb17ab
> Gaia: e251ee6bdab13d8620afa8f9c2d5f14e5e6a4f99
> Platform Version: 18.1
> RIL Version: 01.01.00.019.152 
> 
> When user receives a missed call right after device was rebooted, the missed
> call notification is duplicated on the device. 
> Screenshot is attached.

How's the reproducing rate? I saw there were 2 missed calls in the status bar in the screenshot. Did the issue happen on the 2nd missed call?

Comment 25

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

Attachment: Gaia - debug patch

Adding some debug messages in dialer.js and oncall.js.

Comment 26

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

I was trying to use QC RIL to reproduce this, but still in vain ... According to the bug report, I realize the issue happens right after the device is booted. But anything specific for reproducing? Some steps missed?

Also, I am requesting help from Taipei QA team to help reproduce the issue and to gather more information. Attachment 774424 [details] [diff] is for adding debug messages in gaia. Please apply that patch. Hopefully we can capture hints with that when the issue occurs. Thanks for QA's assistance in advance :)

Comment 27

[Paul Yang [:pyang] (away)]

Use leo base image v08h and reproducible.
Try phone call before lock screen is ready.

Comment 28

[leo.bugzilla.gecko]

Attachment: duplicated ringtone log 0712

Comment 29

[leo.bugzilla.gecko]

I uploaded the reproduced log with your debugging messages.
You can see the duplicated messages in attachment 774458 [details].

Comment 30

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

(In reply to Paul Yang: pyang: [e-mail] from comment #27)
> Use leo base image v08h and reproducible.
> Try phone call before lock screen is ready.

Thanks for the clue. I saw this issue eventually.

Comment 31

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

Attachment: Gaia debug patch (2)

Comment 32

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

Attachment: Log with gaia debug patch (2)

According to the log, Dialer received duplicate callschanged event, then added duplicate calls (see below).

07-12 13:49:02.669 I/GeckoDump(  494): XXX oncall - oncallschanged - evt: [object CallEvent]
07-12 13:49:02.669 I/GeckoDump(  494): XXX oncall - oncallschanged - evt.call.number: 0972995796
07-12 13:49:02.669 I/GeckoDump(  494): XXX oncall - telephony calls.length : 1
07-12 13:49:02.669 I/GeckoDump(  494): XXX oncall.js - addCall - call.number: 0972995796
07-12 13:49:02.749 I/GeckoDump(  494): XXX oncall - oncallschanged - evt: [object CallEvent]
07-12 13:49:03.199 I/GeckoDump(  494): XXX oncall - oncallschanged - evt: [object CallEvent]
07-12 13:49:03.199 I/GeckoDump(  494): XXX oncall - oncallschanged - evt.call.number: 0972995796
07-12 13:49:03.209 I/GeckoDump(  494): XXX oncall - telephony calls.length : 1
07-12 13:49:03.209 I/GeckoDump(  494): XXX oncall.js - addCall - call.number: 0972995796
07-12 13:49:03.259 I/GeckoDump(  494): XXX oncall - oncallschanged - evt: [object CallEvent]
07-12 13:49:10.389 I/GeckoDump(  494): XXX oncall - oncallschanged - evt: [object CallEvent]
07-12 13:49:10.389 I/GeckoDump(  494): XXX oncall - oncallschanged - evt.call.number: 0972995796
07-12 13:49:10.389 I/GeckoDump(  494): XXX oncall - telephony calls.length : 0
07-12 13:49:10.409 I/GeckoDump(  494): XXX oncall.js - notification: call.number: 0972995796
07-12 13:49:10.409 I/GeckoDump(  494): XXX oncall - oncallschanged - evt: [object CallEvent]
07-12 13:49:10.409 I/GeckoDump(  494): XXX oncall - oncallschanged - evt.call.number: 0972995796
07-12 13:49:10.419 I/GeckoDump(  494): XXX oncall - telephony calls.length : 0
07-12 13:49:10.429 I/GeckoDump(  494): XXX oncall.js - notification: call.number: 0972995796
07-12 13:49:10.669 I/GeckoDump(  494): XXX dialer.js - missed call: 0972995796

Comment 33

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

Sorry some line missed in the previous comment. Summary of the log again.

According to the log, Dialer received duplicate callschanged event, then added duplicate calls (see below).
==============================================================================
07-12 13:49:02.669 I/GeckoDump(  494): XXX oncall - oncallschanged - evt: [object CallEvent]
07-12 13:49:02.669 I/GeckoDump(  494): XXX oncall - oncallschanged - evt.call.number: 0972995796
07-12 13:49:02.669 I/GeckoDump(  494): XXX oncall - telephony calls.length : 1
07-12 13:49:02.669 I/GeckoDump(  494): XXX oncall.js - addCall - call.number: 0972995796
07-12 13:49:02.749 I/GeckoDump(  494): XXX oncall - oncallschanged - evt: [object CallEvent]
07-12 13:49:03.199 I/GeckoDump(  494): XXX oncall - oncallschanged - evt: [object CallEvent]
07-12 13:49:03.199 I/GeckoDump(  494): XXX oncall - oncallschanged - evt.call.number: 0972995796
07-12 13:49:03.209 I/GeckoDump(  494): XXX oncall - telephony calls.length : 1
07-12 13:49:03.209 I/GeckoDump(  494): XXX oncall.js - addCall - call.number: 0972995796
07-12 13:49:03.259 I/GeckoDump(  494): XXX oncall - oncallschanged - evt: [object CallEvent]
07-12 13:49:10.389 I/GeckoDump(  494): XXX oncall - oncallschanged - evt: [object CallEvent]
07-12 13:49:10.389 I/GeckoDump(  494): XXX oncall - oncallschanged - evt.call.number: 0972995796
07-12 13:49:10.389 I/GeckoDump(  494): XXX oncall - telephony calls.length : 0
07-12 13:49:10.409 I/GeckoDump(  494): XXX oncall.js - notification: call.number: 0972995796
07-12 13:49:10.409 I/GeckoDump(  494): XXX oncall - oncallschanged - evt: [object CallEvent]
07-12 13:49:10.409 I/GeckoDump(  494): XXX oncall - oncallschanged - evt.call.number: 0972995796
07-12 13:49:10.419 I/GeckoDump(  494): XXX oncall - telephony calls.length : 0
07-12 13:49:10.429 I/GeckoDump(  494): XXX oncall.js - notification: call.number: 0972995796
07-12 13:49:10.669 I/GeckoDump(  494): XXX dialer.js - missed call: 0972995796
07-12 13:49:10.689 I/GeckoDump(  494): XXX dialer.js - missed call: 0972995796

Comment 34

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

In gecko, we shall have more investigation on duplicate callschanged event with a call object. In the meanwhile, in gaia, we shall see how adding duplicate calls happen. 

Etienne, could you help examine the gaia side? Please see attachment 774472 [details] for the full log. Thank you.

Comment 35

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

(In reply to Hsin-Yi Tsai [:hsinyi] from comment #34)
> In gecko, we shall have more investigation on duplicate callschanged event
> with a call object. In the meanwhile, in gaia, we shall see how adding
> duplicate calls happen. 
> 
> Etienne, could you help examine the gaia side? Please see attachment 774472 [details]
> [details] for the full log. Thank you.

Okay, I guess I got the root cause. dialer.js somehow open 2 callscreens that is unexpected. dialer.js will receive two "callschanged" events, one carrying a call object and one not. We check [1] to avoid opening more callscreens, but seems the condition isn't strong enough. So I see the code pass that leads to 2 callscreens. Each callscreen will send a missed call notification to dialer.js. That's why this issue occurs...

[1] https://github.com/mozilla-b2g/gaia/blob/master/apps/communications/dialer/js/dialer.js#L303

Comment 36

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

Found the root cause in comment #35. Clearing ni.

Comment 37

[Lukas Blakk [:lsblakk] use ?needinfo]

Given comment 36, leaving it up to leo triage to decide on taking a fix at this stage - this has no milestone or assignee so it looks like it might be a miss for v1.1 without a champion.

Comment 38

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

Attachment: link to https://github.com/mozilla-b2g/gaia/pull/10995

Based on the observation from Hsinyi, `openCallScreen` gets called twice when there is an incoming call. And if `screenState` is not ready, it tries to get it asynchronously. It leads to the problem when `openCallScreen` gets called again before the asynchronous call returns.

This patch adds a simple flag to avoid the problem. Etienne, could you help to review it? Thanks!

Comment 39

[Etienne Segonzac (:etienne)]

Comment on attachment 776208 [details]
link to https://github.com/mozilla-b2g/gaia/pull/10995

Sweet and simple :)

r=me with the naming nit addressed (see github)

Comment 40

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

Merged with the comment addressed. Thanks Etienne!

master: https://github.com/mozilla-b2g/gaia/commit/3411f0b09f1643e7d95766593cbbc3eff7cdd7e6

Comment 41

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

Uplifted 3411f0b09f1643e7d95766593cbbc3eff7cdd7e6 to:
v1-train: 0a272bc04e7a16e0f12ba2fe0932d1f2613c9c6b

Comment 42

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

v1.1.0hd: 0a272bc04e7a16e0f12ba2fe0932d1f2613c9c6b