1030550 - [Dialer][Bluetooth] Callscreen app sometimes calls BT command "CHLD=3" twice when it only receive one system message.

Status: RESOLVED FIXED

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

Description

[Jamin Liu [:jaliu][:Jamin]]

=== Steps to reproduce ===
1. Connect to a BT hand-free device which support "merge conference call" command.
2. Place a call from a external line to the testing device and answer it.
3. Place a second call from a external line to the testing device.
4. Answer the second call and put the first call on hold.
5. Use BT hand-free to merge two calls into a conference call.
6. Hang up the conference call.
7. Repeat steps 1 ~ 5.
 
=== Expect result ===
The two calls were merged into a conference call.

=== Actual result ===
The calls can't be merged.
P.S. The calls would be merged correctly at step 5, however, it would fail at the second time.

=== Environment ===
B2G master and B2G v2.0 with bluez stack.

=== Detail Description ===
I put few logs to related code section.

Gecko would broadcast a system message "bluetooth-dialer-command" with string "CHLD=3" when BT hand-free device send "merge conference call" command.
And Gaia would handle it in handleBTCommand at calls_handler.js.

However, Gaia would call handleBTCommand twice by following the STR in this bug when it only receive one system message.
It means Callscreen app call telephony.conferenceGroup.add(,); twice in a short time. Sometime it leads to Telephony::NotifyConferenceError(), in this case, the toast "Unable to merge calls" would appear.

Comment 1

[Eric Chou [:ericchou] [:echou]]

Nominate as a 2.0+ blocker since it blocks Bluetooth certification. See bug 1027508 for more information.

Comment 2

[Preeti Raghunath(:Preeti)]

Blocking for BT cert

Comment 3

[howie [:howie]]

Hi Wesley, need you help to find someone to own this, thanks.

Comment 4

[Wesley Huang [:wesley_huang] (EPM) (NI me)]

Dialer team is aware of this and will be high priority task for sprint6. 
Will update right after sprint planning on July/8.

Comment 5

[Anthony Ricaud (:rik)]

I'm seeing an error in Gecko when reproducing this, just when I press the BT button:

E/GeckoConsole(  709): [JavaScript Error: "this._dispatchers is null" {file: "jar:file:///system/b2g/omni.ja!/components/SystemMessageManager.js" line: 225}]
E/GeckoConsole(  709): Content JS LOG at app://callscreen.gaiamobile.org/js/calls_handler.js:375 in handleBTCommand: add two individual calls
E/GeckoConsole(  709): Content JS LOG at app://callscreen.gaiamobile.org/js/calls_handler.js:375 in handleBTCommand: add two individual calls

So I'm inclined to say this is a mozSetMessageHandler issue. Needinfo-ing Gene to take a look, since he is the top contributor to that file.

Comment 6

[Anthony Ricaud (:rik)]

To reproduce the problem without a bluetooth device that supports this command, I just did this in apps/callscreen/js/calls_handler.js:

   function handleBTCommand(message) {
     var command = message.command;
+    var command = 'CHLD=3';

Comment 7

[Gene Lian (I already quit Mozilla)]

(In reply to Anthony Ricaud (:rik) from comment #5)
> I'm seeing an error in Gecko when reproducing this, just when I press the BT
> button:
> 
> E/GeckoConsole(  709): [JavaScript Error: "this._dispatchers is null" {file:
> "jar:file:///system/b2g/omni.ja!/components/SystemMessageManager.js" line:
> 225}]

Thanks Anthony for the investigation!

The only possibility of nullify this._dispatchers is at [1], which only happens when the app's window is closed. However, it's reasonable to stop handling system messages when the app is no longer living. I cannot figure out how this case happens.

I'm not very familiar with the control of the BT device. Hi Jamin, could you please elaborate on how comment #0 and comment #6 work together? That would be extremely helpful if you can come by to demo it face-to-face. Thank you!

Looping Sean as well who is going to take over most of the system message tasks.

[1] http://mxr.mozilla.org/mozilla-central/source/dom/messages/SystemMessageManager.js#174

Comment 8

[Jamin Liu [:jaliu][:Jamin]]

(In reply to Gene Lian [:gene] (business trip Jun. 16 ~ Jun. 20) from comment #7)
> The only possibility of nullify this._dispatchers is at [1], which only
> happens when the app's window is closed. However, it's reasonable to stop
> handling system messages when the app is no longer living. I cannot figure
> out how this case happens.
> 
> I'm not very familiar with the control of the BT device. Hi Jamin, could you
> please elaborate on how comment #0 and comment #6 work together? That would
> be extremely helpful if you can come by to demo it face-to-face. Thank you!
> 
> Looping Sean as well who is going to take over most of the system message
> tasks.
> 
> [1]
> http://mxr.mozilla.org/mozilla-central/source/dom/messages/
> SystemMessageManager.js#174

Hi Gene,
Thank you for your time.
I'm glad to demo the STRs at #Description face-to-face, I will try to reach you this afternoon.
A Bluetooth hand-free device is required to reproduce this bug, if you don't want to simulate the BT command by modifying the code.

However, it's easy to reproduce the symptom which was mentioned at #Comment 7. 

=== Steps to reproduce ===
(It's OK to keep Bluetooth switch off.)
1. Make a phone call. (Do not answer it.)
2. Hang up.
3. Make a phone call again.
4. Hang up.
> E/GeckoConsole(  288): [JavaScript Error: "this._dispatchers is null" {file: "jar:file:///system/b2g/omni.ja!/components/SystemMessageManager.js" line: 225}]
> E/GeckoConsole(  288): [JavaScript Error: "this._dispatchers is null" {file: "jar:file:///system/b2g/omni.ja!/components/SystemMessageManager.js" line: 225}]

If you make a phone call and hang up again.
You will see these messages through adb logcat.
> E/GeckoConsole(  288): [JavaScript Error: "this._dispatchers is null" {file: "jar:file:///system/b2g/omni.ja!/components/SystemMessageManager.js" line: 225}]
> E/GeckoConsole(  288): [JavaScript Error: "this._dispatchers is null" {file: "jar:file:///system/b2g/omni.ja!/components/SystemMessageManager.js" line: 225}]
> E/GeckoConsole(  288): [JavaScript Error: "this._dispatchers is null" {file: "jar:file:///system/b2g/omni.ja!/components/SystemMessageManager.js" line: 225}]
> E/GeckoConsole(  288): [JavaScript Error: "this._dispatchers is null" {file: "jar:file:///system/b2g/omni.ja!/components/SystemMessageManager.js" line: 225}]

Comment 9

[Tamara Hills [:thills]]

I tried out the preliminary patch in 1035074 and that fixed the this._dispatchers error for me.  However, I can still repro this bug *with* the patch. So, perhaps there is something else going on here.

Comment 10

[Jamin Liu [:jaliu][:Jamin]]

I got the same result as Tamara did.

There are many different cases with current codebase would trigger the JavaScript Error "this._dispatchers is null".  e.g. [Hang up a phone], [Answer a call by BT hand-free], [Hang up a call by BT hand-free]...
However, these operations work fine even when they got the JavaScript Error "this._dispatchers is null".

Comment 11

[Henry Chang [:hchang]]

I believe bug 1035074 has nothing to do with this bug. The cause of this 
bug is that multiple CallScreen  [1] are present to receive the system 
message. (You can observe the |onload| of callscreen app is called more 
than once.) The reason that call screen app is loaded multiple times is [2]. 
There might be bugs or surprising behavior around doing this:

var src = iframe.src.split('#')[0];
iframe.src = ''; // cocotte
setTimeout(function nextTick() {
  iframe.src = src;
});

What I observed is only one 'inner-window-destroyed' event is thrown. 
If SystemMessageManager could receive 'inner-window-destroyed' for 
every unloaded callscreen app, then only the latest callscreen app
would receive the system message.

Attached a gaia patch which has been verified by Jamin but I am not
saying this is a gaia bug... The bug may be a rooted object in every
single re-loaded callscreen app since only the first callscreen app
died.

[1] https://github.com/mozilla-b2g/gaia/blob/master/apps/callscreen/js/index.js#L7
[2] https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/attention_screen.js#L241

Comment 12

[Henry Chang [:hchang]]

Attachment: Bug1030550.patch

Comment 13

[Anthony Ricaud (:rik)]

Thanks for the investigation Henry! I'll move this forward.

Comment 14

[Anthony Ricaud (:rik)]

Henry: We kill the callscreen app when all the current calls are finished and reopen it just afterwards. That's what the attention_screen code you linked to does.

I'm only seeing one call to the load listener, each time we re-spawn the callscreen app. So this is as expected.

I'm seeing a strange thing though. Every time I run the STR, I get one more "this._dispatchers is null" error. But I'm only seeing maximum two calls to handleBTCommand. So after running the STRs five times, I get 5 dispatcher errors but only 2 handleBTCommand calls. I would have expected the same amount of dispatcher errors and handleBTCommand calls.

Comment 15

[Anthony Ricaud (:rik)]

I tried re-spawning the callscreen app after a 5 second delay but it has no effect.

Henry: I'm gonna assign this to you as it looks like a SystemMessage issue. We can chat tomorrow morning Europe time if you want (Rik in #gaia).

Comment 16

[Anthony Ricaud (:rik)]

We investigated a bit with Henry earlier today. We suspected that we might have 2 running callscreen app or something like this. I continued a bit and here is a branch with some logging:

https://github.com/Rik/gaia/tree/bluetooth-exploration-1036378

When running this branch, I'm seeing the following. The numbers are assigned random but generated once per callscreen instance. My comments in brackets:

[In call]
E/GeckoConsole( 4339): Content JS LOG at app://callscreen.gaiamobile.org/js/index.js:5 in anonymous: XXXXX I AM STILL ALIVE !!!! 0.29644786460608763
[We hang up all calls, the callscreen app will re-spawn]
E/GeckoConsole( 4339): Content JS LOG at app://callscreen.gaiamobile.org/js/index.js:11 in callSetup: XXXXXX load 0.14472809783713758
E/GeckoConsole( 4339): Content JS LOG at app://callscreen.gaiamobile.org/js/index.js:5 in anonymous: XXXXX I AM STILL ALIVE !!!! 0.14472809783713758
[This goes on every second]
E/GeckoConsole( 4339): Content JS LOG at app://callscreen.gaiamobile.org/js/index.js:5 in anonymous: XXXXX I AM STILL ALIVE !!!! 0.14472809783713758
[Now pressing a bluetooth command]
E/GeckoConsole( 4339): Content JS LOG at app://callscreen.gaiamobile.org/js/calls_handler.js:345 in handleBTCommand: XXXX WESH Bluetooth! 0.29644786460608763
E/GeckoConsole( 4339): Content JS WARN at app://callscreen.gaiamobile.org/js/calls_handler.js:386 in handleBTCommand: Cannot join conference call.
E/GeckoConsole( 4339): Content JS LOG at app://callscreen.gaiamobile.org/js/calls_handler.js:345 in handleBTCommand: XXXX WESH Bluetooth! 0.14472809783713758
E/GeckoConsole( 4339): Content JS WARN at app://callscreen.gaiamobile.org/js/calls_handler.js:386 in handleBTCommand: Cannot join conference call.

As you can see, the previous callscreen app is not running anymore (no 0.29644786460608763 logs) but the message handler for it is still getting called.

Comment 17

[Henry Chang [:hchang]]

I got new findings!
The cause is the bfcache [1][2].

When you do:

iframe.src = ''; // cocotte
setTimeout(function nextTick() {
  iframe.src = src;
});

The DOM created by the original iframe will not be released:

"In the bfcache case, freezing the window just marks it as frozen; the DOM is preserved, as are compiled script objects."

So the old SystemMessageManager will still be there to handle BT system messages.
Listening for a unload event would turn the bfcache off and it works.
I also tried "cache-control: no-store" approach mentioned in [1] but failed.

[1] https://developer.mozilla.org/en-US/docs/Using_Firefox_1.5_caching
[2] https://developer.mozilla.org/en-US/docs/Working_with_BFCache


(In reply to Anthony Ricaud (:rik) from comment #16)
> We investigated a bit with Henry earlier today. We suspected that we might
> have 2 running callscreen app or something like this. I continued a bit and
> here is a branch with some logging:
> 
> https://github.com/Rik/gaia/tree/bluetooth-exploration-1036378
> 
> When running this branch, I'm seeing the following. The numbers are assigned
> random but generated once per callscreen instance. My comments in brackets:
> 
> [In call]
> E/GeckoConsole( 4339): Content JS LOG at
> app://callscreen.gaiamobile.org/js/index.js:5 in anonymous: XXXXX I AM STILL
> ALIVE !!!! 0.29644786460608763
> [We hang up all calls, the callscreen app will re-spawn]
> E/GeckoConsole( 4339): Content JS LOG at
> app://callscreen.gaiamobile.org/js/index.js:11 in callSetup: XXXXXX load
> 0.14472809783713758
> E/GeckoConsole( 4339): Content JS LOG at
> app://callscreen.gaiamobile.org/js/index.js:5 in anonymous: XXXXX I AM STILL
> ALIVE !!!! 0.14472809783713758
> [This goes on every second]
> E/GeckoConsole( 4339): Content JS LOG at
> app://callscreen.gaiamobile.org/js/index.js:5 in anonymous: XXXXX I AM STILL
> ALIVE !!!! 0.14472809783713758
> [Now pressing a bluetooth command]
> E/GeckoConsole( 4339): Content JS LOG at
> app://callscreen.gaiamobile.org/js/calls_handler.js:345 in handleBTCommand:
> XXXX WESH Bluetooth! 0.29644786460608763
> E/GeckoConsole( 4339): Content JS WARN at
> app://callscreen.gaiamobile.org/js/calls_handler.js:386 in handleBTCommand:
> Cannot join conference call.
> E/GeckoConsole( 4339): Content JS LOG at
> app://callscreen.gaiamobile.org/js/calls_handler.js:345 in handleBTCommand:
> XXXX WESH Bluetooth! 0.14472809783713758
> E/GeckoConsole( 4339): Content JS WARN at
> app://callscreen.gaiamobile.org/js/calls_handler.js:386 in handleBTCommand:
> Cannot join conference call.
> 
> As you can see, the previous callscreen app is not running anymore (no
> 0.29644786460608763 logs) but the message handler for it is still getting
> called.

Comment 18

[Henry Chang [:hchang]]

Attachment: PR to turn off bfcache

Comment 19

[Henry Chang [:hchang]]

Comment on attachment 8456675 [details]
PR to turn off bfcache

https://github.com/mozilla-b2g/gaia/pull/21794

Comment 20

[Henry Chang [:hchang]]

Comment on attachment 8456675 [details]
PR to turn off bfcache

https://github.com/mozilla-b2g/gaia/pull/21794

Comment 21

[Henry Chang [:hchang]]

Attachment: PR to turn off bfcache

Comment 22

[Anthony Ricaud (:rik)]

Comment on attachment 8456677 [details] [review]
PR to turn off bfcache

Wow, thanks for the investigation! I guess we can disable the bfcache because this is a 2.0 blocker. But I think long term, we should fix this in the platform.

I'm putting feedback+ because I'd prefer the comment to mention when we can remove this hack and point to a new platform bug.

Comment 23

[Henry Chang [:hchang]]

(In reply to Anthony Ricaud (:rik) from comment #22)
> Comment on attachment 8456677 [details] [review]
> PR to turn off bfcache
> 
> Wow, thanks for the investigation! I guess we can disable the bfcache
> because this is a 2.0 blocker. But I think long term, we should fix this in
> the platform.
> 
> I'm putting feedback+ because I'd prefer the comment to mention when we can
> remove this hack and point to a new platform bug.

Thanks for your review!

Actually, I think there is no bug but some undefined behaviour in the platform:

1) For system message, if there are two instances of one app in different window,
   which one or both should receive the system message.

2) For a cached/frozen app, what the DOM object should behave. (setTimeout is known 
   to stop working when a page is frozen.)

So, I would not consider turning off bfcache is a hack since it just avoids the ambiguity.
Other than turning off bfcache, we may be able to listen to onpageshow/onpagehide
event to set/invalidate the system message handler.

Comment 24

[Henry Chang [:hchang]]

:fabrice, :bz,

Do you have any thought regarding the above two questions?

1) For system message, if there are two instances of one app in different window,
   which one or both should receive the system message.

2) For a cached/frozen app, what the DOM object should behave. (setTimeout is known 
   to stop working when a page is frozen.)

Comment 25

[[:fabrice] Fabrice Desré]

(In reply to Henry Chang [:henry] from comment #24)
> :fabrice, :bz,
> 
> Do you have any thought regarding the above two questions?
> 
> 1) For system message, if there are two instances of one app in different
> window,
>    which one or both should receive the system message.

That's not well defined currently. I believe that the last one to call mozSetMessageHandler() will get the message but that needs to be verified.

Comment 26

[Henry Chang [:hchang]]

(In reply to Fabrice Desré [:fabrice] from comment #25)
> (In reply to Henry Chang [:henry] from comment #24)
> > :fabrice, :bz,
> > 
> > Do you have any thought regarding the above two questions?
> > 
> > 1) For system message, if there are two instances of one app in different
> > window,
> >    which one or both should receive the system message.
> 
> That's not well defined currently. I believe that the last one to call
> mozSetMessageHandler() will get the message but that needs to be verified.

It's been verified and is explainable that both of them would receive.
(because each system message could match the manifest/pageurl.)
The point is if it's the behavior that the app desires.

In the callscreen case, callscreen app will be reloaded for each call cycle.
Because of bfcache, the SystemMessageManager for the frozen callscreen
would still be active to dispatch the registered handler.

Comment 27

[Henry Chang [:hchang]]

Since this bug is no longer blocking 2.0+ issues, it should not be 2.0+ any more.

Comment 28

[Jamin Liu [:jaliu][:Jamin]]

(In reply to Henry Chang [:henry] from comment #27)
> Since this bug is no longer blocking 2.0+ issues, it should not be 2.0+ any
> more.

Agree with Henry.
This bug is no longer blocking Bluetooth certification.

The symptom of this bug has changed slightly.
Gaia still call handleBTCommand twice by following the STR, however, the it could merge the conference call successfully with current codebase.

=== Steps to reproduce ===
...

=== Expect result ===
The two calls were merged into a conference call.

=== Actual result ===
The calls were merged into a conference call, but the incorrect toast "Unable to merge calls" would appear at the same time.

Since it become a UI issue, the Bluetooth certification wouldn't be blocked by it.
Thank Henry and Anthony for their efforts.

Comment 29

[Anthony Ricaud (:rik)]

1) is not really the issue here, is it? We never have two callscreen launched at the same time. We really want to figure out 2) 

Also, this is still a 2.0+ blocker to me. Especially given the simple fix Henry provided.

Comment 30

[Boris Zbarsky [:bzbarsky]]

> For a cached/frozen app, what the DOM object should behave.

Which DOM object?

In general, random DOM objects from a cached/frozen page should act more or less like they would in an unloaded page.  The existence of the caching should transparent, as much as possible.

Some DOM objects actually implement this behavior by dropping a page from the cache if used in a cached page.

Comment 31

[Henry Chang [:hchang]]

(In reply to Boris Zbarsky [:bz] from comment #30)
> > For a cached/frozen app, what the DOM object should behave.
> 
> Which DOM object?
> 

Take system message as example. callscreen page will 
create a DOM object "SystemMessageManager", which will
be listening to certain ppmm messages from 
"SystemMessageInternal" running in chrome.
In other words, SystemMessageManager is driven by
ppmm messages.

When a page is frozen, SystemMessageManager seems to
still receive messages from ppmm. Is this an expected
behavior?

> In general, random DOM objects from a cached/frozen page should act more or
> less like they would in an unloaded page.  The existence of the caching
> should transparent, as much as possible.
> 
> Some DOM objects actually implement this behavior by dropping a page from
> the cache if used in a cached page.

So, the existence of caching is not transparent to DOM objects since
the DOM objects should be aware of the caching. Could you tell me what
DOM objects you're referring to? Thanks!

Comment 32

[Boris Zbarsky [:bzbarsky]]

> create a DOM object "SystemMessageManager"

That's not a "DOM object" in the sense of "something we expose to web pages".  That's some sort of internal object right? 

How it behaves is then presumably entirely up to us.  If it wants to check for the document being in bfcache, it can.

> Is this an expected behavior?

I expect so, but I'm not an expert on the message manager bits.  Olli, do you know?

> So, the existence of caching is not transparent to DOM objects

It's not transparent to our implementation, sure!

> Could you tell me what DOM objects you're referring to?

Where? For the "dropping a page" thing?  For example, mutations to the Node tree will do that.

Comment 33

[Henry Chang [:hchang]]

(In reply to Boris Zbarsky [:bz] from comment #32)
> > create a DOM object "SystemMessageManager"
> 
> That's not a "DOM object" in the sense of "something we expose to web
> pages".  That's some sort of internal object right? 
> 
> How it behaves is then presumably entirely up to us.  If it wants to check
> for the document being in bfcache, it can.
> 
> > Is this an expected behavior?
> 
> I expect so, but I'm not an expert on the message manager bits.  Olli, do
> you know?
> 
> > So, the existence of caching is not transparent to DOM objects
> 
> It's not transparent to our implementation, sure!
> 
> > Could you tell me what DOM objects you're referring to?
> 
> Where? For the "dropping a page" thing?  For example, mutations to the Node
> tree will do that.

Thanks for your reply and correction! I should say it a "DOM-facing object".
I think our internal object (SystemMessageManager) has to check if a window 
is frozen or not. However, SystemMessageManager is implemented in javascript
so not able to call nsGlobalWindow::IsFrozen() directly. I will find other ways
to get this information in SystemMessageManager. 

Rik: I filed a bug to address this (Bug 1040565) and mention it in the comment.
Please review again. I also attach PR for 2.0. Thanks!

Comment 34

[Henry Chang [:hchang]]

Attachment: PR for 2.0

Comment 35

[Boris Zbarsky [:bzbarsky]]

> so not able to call nsGlobalWindow::IsFrozen() directly.

Yeah, indeed.  Worse yet, since it only has access to the _outer_ window, even if we exposed an API for this it would see the window as not-frozen.

We could expose some object on window that you can grab that later keeps exposing the frozen state for the inner that was current when you grabbed it...

Comment 36

[Anthony Ricaud (:rik)]

Comment on attachment 8458428 [details] [review]
PR for 2.0

Thanks Henry!

Comment 37

[Olli Pettay [:smaug][[e-mail]]]

(In reply to Henry Chang [:henry] from comment #31)

> When a page is frozen, SystemMessageManager seems to
> still receive messages from ppmm. Is this an expected
> behavior?
ppmm, a (parent?) process message manager, will receive messages as long as the other side sends such.

Comment 38

[Henry Chang [:hchang]]

(In reply to Anthony Ricaud (:rik) from comment #36)
> Comment on attachment 8458428 [details] [review]
> PR for 2.0
> 
> Thanks Henry!

Thanks Rik! Flagged checkin-needed to gaia 2.0. Thanks!

Comment 39

[Henry Chang [:hchang]]

(In reply to Henry Chang [:henry] from comment #38)
> (In reply to Anthony Ricaud (:rik) from comment #36)
> > Comment on attachment 8458428 [details] [review]
> > PR for 2.0
> > 
> > Thanks Henry!
> 
> Thanks Rik! Flagged checkin-needed to gaia 2.0. Thanks!

Hi Rik, I don't know if 'checkin-needed' flag effective for gaia PR.
Could you please help merge the PR? Thanks!

Comment 40

[Carsten Book [:Tomcat]]

also travis is failing https://travis-ci.org/mozilla-b2g/gaia/builds/30234767 so i guess this need to be checked if this failures are related.

Comment 41

[Anthony Ricaud (:rik)]

Henry: checkin-needed usually works with a green Travis (as Tomcat explained).

It was unrelated failures so I merged in https://github.com/mozilla-b2g/gaia/commit/2ab20b365bbbaebdd01f34246a2d05ee068fbc76

Comment 42

[Preeti Raghunath(:Preeti)]

Rik

Given BT cert is not an issue here why is this still needed?

Comment 43

[Anthony Ricaud (:rik)]

I think this is still needed because we're displaying an erroneous message that we couldn't create a conference call, even though we did. This is a regression of bug 990003 (so 1.4 and 1.3t are probably also affected although I didn't verify it).