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

RESOLVED FIXED in 1.1 QE4 (15jul)

Status

P1
major
RESOLVED FIXED
6 years ago
5 years ago

People

(Reporter: leo.bugzilla.gecko, Assigned: arthurcc)

Tracking

unspecified
1.1 QE4 (15jul)
All
Gonk (Firefox OS)

Firefox Tracking Flags

(blocking-b2g:leo+, b2g18 fixed, b2g-v1.1hd fixed)

Details

(Whiteboard: [mozilla-triage], [LeoVB+])

Attachments

(8 attachments)

(Reporter)

Description

6 years ago
GAIA : f2d6ed54a236e6e3b94f0abad9f0dacb8a1cc7b3
GECKO : be276cf55ce160bca09f36d9ca679a2ae20ea7cc


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

Comment 1

6 years ago
Created attachment 766971 [details]
duplicated ringtone log
(Reporter)

Comment 2

6 years ago
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).
Flags: needinfo?(htsai)
(Reporter)

Updated

6 years ago
Assignee: nobody → htsai
Hardware: x86 → All
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.
Flags: needinfo?(leo.bugzilla.gecko)
Flags: needinfo?(htsai)
(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.
(Reporter)

Comment 5

6 years ago
<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]
Attachment #766971 - Attachment mime type: text/x-log → text/plain
(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.
(Reporter)

Comment 7

6 years ago
Created attachment 770033 [details]
video file
Flags: needinfo?(leo.bugzilla.gecko)
(Reporter)

Comment 8

6 years ago
This is not about busy tone.
Please check the video file.
(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.
Summary: [B2G] overwrapped ringtone → [B2G] Duplicate missed call notifications show up
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.
Assignee: htsai → nobody
(Reporter)

Comment 11

6 years ago
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.
Flags: needinfo?(htsai)
(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.
Flags: needinfo?(htsai)
Keywords: qawanted
(Reporter)

Comment 13

6 years ago
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();
  },
(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?
(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?
Flags: needinfo?(etienne)
(Reporter)

Comment 16

6 years ago
Mozilla-b2g18 (Leo)

Build ID = 20130616070209
gaia revision="f2d6ed54a236e6e3b94f0abad9f0dacb8a1cc7b3"
gecko revision="be276cf55ce160bca09f36d9ca679a2ae20ea7cc"
(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
Flags: needinfo?(etienne)
(Reporter)

Updated

6 years ago
blocking-b2g: --- → leo?
(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
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

6 years ago
Created attachment 772825 [details]
Screenshot

Comment 21

6 years ago
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.
Keywords: qawanted
(Reporter)

Comment 22

6 years ago
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();
Flags: needinfo?(htsai)
(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.
Flags: needinfo?(htsai)
(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?
Created attachment 774424 [details] [diff] [review]
Gaia - debug patch

Adding some debug messages in dialer.js and oncall.js.
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 :)
Flags: needinfo?(pyang)
Use leo base image v08h and reproducible.
Try phone call before lock screen is ready.
Flags: needinfo?(pyang)
(Reporter)

Comment 28

6 years ago
Created attachment 774458 [details]
duplicated ringtone log 0712
(Reporter)

Comment 29

6 years ago
I uploaded the reproduced log with your debugging messages.
You can see the duplicated messages in attachment 774458 [details].
(In reply to Paul Yang: pyang: pyang@mozilla.com 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.
Created attachment 774470 [details] [diff] [review]
Gaia debug patch (2)
Created attachment 774472 [details]
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
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
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.
Flags: needinfo?(etienne)
(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
Component: DOM: Device Interfaces → Gaia::Dialer
Product: Core → Boot2Gecko
Summary: [B2G] Duplicate missed call notifications show up → [B2G] [Dialer] Duplicate missed call notifications show up due to more than one callscreen being opened
Found the root cause in comment #35. Clearing ni.
Flags: needinfo?(etienne)
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.
Whiteboard: [mozilla-triage]

Updated

6 years ago
blocking-b2g: leo? → leo+
Priority: -- → P1
Target Milestone: --- → 1.1 QE4 (15jul)
Created attachment 776208 [details]
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!
Attachment #776208 - Flags: review?(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)
Attachment #776208 - Flags: review?(etienne) → review+
Assignee: nobody → arthur.chen
Merged with the comment addressed. Thanks Etienne!

master: https://github.com/mozilla-b2g/gaia/commit/3411f0b09f1643e7d95766593cbbc3eff7cdd7e6
Status: NEW → RESOLVED
Last Resolved: 6 years ago
status-b2g18: --- → affected
Resolution: --- → FIXED

Updated

6 years ago
Whiteboard: [mozilla-triage] → [mozilla-triage], [LeoVB+]
Uplifted 3411f0b09f1643e7d95766593cbbc3eff7cdd7e6 to:
v1-train: 0a272bc04e7a16e0f12ba2fe0932d1f2613c9c6b
status-b2g18: affected → fixed
v1.1.0hd: 0a272bc04e7a16e0f12ba2fe0932d1f2613c9c6b
status-b2g-v1.1hd: --- → fixed
Duplicate of this bug: 894735
You need to log in before you can comment on or make changes to this bug.