Closed Bug 1006356 Opened 8 years ago Closed 8 years ago

[hamachi][2.0]Not possible to change volume level after voice call

Categories

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

ARM
Gonk (Firefox OS)
defect
Not set
normal

Tracking

(blocking-b2g:1.3T+, b2g-v1.3 unaffected, b2g-v1.3T fixed, b2g-v1.4 fixed, b2g-v2.0 fixed)

RESOLVED FIXED
2.0 S2 (23may)
blocking-b2g 1.3T+
Tracking Status
b2g-v1.3 --- unaffected
b2g-v1.3T --- fixed
b2g-v1.4 --- fixed
b2g-v2.0 --- fixed

People

(Reporter: zrzut01, Assigned: gerard-majax)

References

Details

(Keywords: regression, Whiteboard: [systemsfe][partner-blocker][sprd311363][sprd311363])

Attachments

(4 files)

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:29.0) Gecko/20100101 Firefox/29.0 (Beta/Release)
Build ID: 20140421221237

Steps to reproduce:

1. Set some volume levels for ringtones and etc.
2. Make a voice call.
3. Finish voice call. 


Actual results:

From now it is impossible to change volume control i.e. for ringtones or FM Radio when every time volume buttons are pressed the voice call volume control appears.


Expected results:

It should be possible to change volume control for other types of sound after finish a voice call.
Found on:

Alcatel One Touch Fire (T-mobile Poland)
B2G version: 2.0.0.0-prerelease master
Platform version: 32.0a1
Build Identifier: 20140505160203
Git commit info: 2014-05-05 09:01:02 e8a08a3f
I'm reproducing this on Nexus S and Desire Z at least.
Component: Gaia → Gaia::Dialer
I'm reproducing this on Geeksphone Peak (nightly build image from http://downloads.geeksphone.com/peak/master/latest_master.html)

And I can add that when I'm listening music after this issues, when I lock my phone music stop. Don't know if this is related, but it occured at the same time.
(In reply to romain from comment #3)
> I'm reproducing this on Geeksphone Peak (nightly build image from
> http://downloads.geeksphone.com/peak/master/latest_master.html)
> 
> And I can add that when I'm listening music after this issues, when I lock
> my phone music stop. Don't know if this is related, but it occured at the
> same time.

Same on hamachi, I think that it is related problem.
OS: All → Gonk (Firefox OS)
Hardware: All → ARM
Reproduced on Flame.
Status: UNCONFIRMED → NEW
blocking-b2g: --- → 2.0?
Component: Gaia::Dialer → RIL
Ever confirmed: true
Keywords: regression
Recently we found some weird call audio behaviour (e.g. bug 1005498 and bug 1002538) which is triggered by bug 999334. We provided a patch on bug 1005498 that resolves bug 1005498 and bug 1002538. 

When I noticed this issue, I first thought that this issue could be the same one as above. However, even I applied the patch on 1005498, the issue is still. Also, RIL code doesn't touch volume control, so it's not obvious to me that it's a RIL issue. I guess we would need to check recent changes on volume control or audio management.
QA Contact: ckreinbring
B2G-Inbound regression window from Buri 2.0

No repro
Build ID: 20140429020207
Gecko: https://hg.mozilla.org/integration/b2g-inbound/rev/be5b6fda11f9
Gaia: d9cb98243113558e4581c6bfcb6515ae6b088620
Platform Version: 32.0a1
Firmware Version: V1.2-device.cfg

Repro
Build ID: 20140429023207
Gecko: https://hg.mozilla.org/integration/b2g-inbound/rev/2607b6b60561
Gaia: 08cdbbbf5c35f7002388b920d4fb75570f2ae0d1
Platform Version: 32.0a1
Firmware Version: V1.2-device.cfg

Old Gaia / New Gecko - OK
New Gaia / Old Gecko - Fail
https://github.com/mozilla-b2g/gaia/compare/d9cb98243113558e4581c6bfcb6515ae6b088620...08cdbbbf5c35f7002388b920d4fb75570f2ae0d1
The window above can't be right. The patch called out here is dealing with contacts import, which has nothing to do with this bug.
Tinderbox regression window on Buri 2.0 mozilla RIL

No repro
Build ID: 20140429044712
Gecko: https://hg.mozilla.org/mozilla-central/rev/400a31da59a9
Gaia: 725a23802708eb70e3d7e8a2ce7179adbac806e4
Platform Version: 32.0a1
Firmware Version: V1.2-device.cfg

Repro
Build ID: 20140429093609
Gecko: https://hg.mozilla.org/mozilla-central/rev/34a7215c5d85
Gaia: 1892ba3a857f7e9cd1d2a0cf1c87481f3dcaca2c
Platform Version: 32.0a1
Firmware Version: V1.2-device.cfg

Gaia push log: https://github.com/mozilla-b2g/gaia/compare/725a23802708eb70e3d7e8a2ce7179adbac806e4...1892ba3a857f7e9cd1d2a0cf1c87481f3dcaca2c
comment 10 isn't really answering my question on the request in comment 9 - did you check to see if the window there was correct or not?
(In reply to Hsin-Yi Tsai  [:hsinyi] from comment #6)
> Recently we found some weird call audio behaviour (e.g. bug 1005498 and bug
> 1002538) which is triggered by bug 999334. We provided a patch on bug
> 1005498 that resolves bug 1005498 and bug 1002538. 
> 
> When I noticed this issue, I first thought that this issue could be the same
> one as above. However, even I applied the patch on 1005498, the issue is
> still. Also, RIL code doesn't touch volume control, so it's not obvious to
> me that it's a RIL issue. I guess we would need to check recent changes on
> volume control or audio management.

Thanks, then it may be a gaia system bug. Taking.
Assignee: nobody → lissyx+mozillians
Status: NEW → ASSIGNED
Component: RIL → Gaia::System
Target Milestone: --- → 2.0 S1 (9may)
Duplicate of this bug: 1007047
Whiteboard: [systemsfe]
blocking-b2g: 2.0? → 2.0+
I retested the b2g-inbound window, the Tinderbox window provided previously is correct. The new b2g-inbound window is:

    Last working
B2G-Inbound Environmental Variables:
Device: Buri Master MOZ
BuildID: 20140429014311
Gaia: 5e09ffe399cce7575011408fea4b7b43b3dcc148
Gecko: 5f256979dacc
Version: 32.0a1
Firmware Version: v1.2-device.cfg

    First Broken
B2G-Inbound Environmental Variables:
BuildID: 20140429020207
Gaia: d9cb98243113558e4581c6bfcb6515ae6b088620
Gecko: be5b6fda11f9
Version: 32.0a1
Firmware Version: v1.2-device.cfg

    Gecko/Gaia Swap Test
First Broken Gecko / Last Working Gaia: Issue does not reproduce
Gaia: 5e09ffe399cce7575011408fea4b7b43b3dcc148
Gecko: be5b6fda11f9

First Broken Gaia / Last Working Gecko: Issue Reproduces
Gaia: d9cb98243113558e4581c6bfcb6515ae6b088620
Gecko: 5f256979dacc

    Gaia Pushlog:
https://github.com/mozilla-b2g/gaia/compare/5e09ffe399cce7575011408fea4b7b43b3dcc148...d9cb98243113558e4581c6bfcb6515ae6b088620
This is either caused by bug 997701 or bug 1000047.

Etienne - Which bug caused this regression?
Flags: needinfo?(etienne)
(In reply to Jason Smith [:jsmith] from comment #15)
> This is either caused by bug 997701 or bug 1000047.
> 
> Etienne - Which bug caused this regression?

I'll check both.
I cannot reproduce anymore once I locally revert merge commit 3617fa6b6e5e2e3c7a198227d27a12bca830ff0a (bug 997701).
Depends on: 997701
I don't think that the gaia patch in bug 997701 is causing the issue seen here, I think it's more likely that it's caused by the new Gecko functionality that patch uses (namely creating an AudioContext with a specific channel). I think it's more likely that the issue originated from bug 984498 where that functionality was introduced in Gecko.
(In reply to Gabriele Svelto [:gsvelto] from comment #18)
> I don't think that the gaia patch in bug 997701 is causing the issue seen
> here, I think it's more likely that it's caused by the new Gecko
> functionality that patch uses (namely creating an AudioContext with a
> specific channel). I think it's more likely that the issue originated from
> bug 984498 where that functionality was introduced in Gecko.

It seems you are right: I added some debug to TonePlayer, and it seems to correctly switch from normal to telephony channel and then back to normal.
$ adb logcat -v threadtime | egrep TonePlayer
05-08 13:12:13.382  3399  3399 E GeckoConsole: Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:243 in tp_setChannel: TonePlayer: setChannel(normal => telephony) from: tp_setChannel@app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:243:5
05-08 13:12:13.382  3399  3399 E GeckoConsole: Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:48 in tp_trashAudio: TonePlayer: trashAudio(normal)
05-08 13:12:13.392  3399  3399 E GeckoConsole: Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:43 in tp_ensureAudio: TonePlayer: ensureAudio: new AudioContext(telephony)
05-08 13:12:21.042  3399  3399 E GeckoConsole: Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:243 in tp_setChannel: TonePlayer: setChannel(telephony => normal) from: tp_setChannel@app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:243:5
05-08 13:12:21.042  3399  3399 E GeckoConsole: Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:48 in tp_trashAudio: TonePlayer: trashAudio(telephony)
05-08 13:12:21.042  3399  3399 E GeckoConsole: Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:43 in tp_ensureAudio: TonePlayer: ensureAudio: new AudioContext(normal)
05-08 13:12:21.092  3399  3399 E GeckoConsole: Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:48 in tp_trashAudio: TonePlayer: trashAudio(normal)
05-08 13:12:21.102  3399  3399 E GeckoConsole: Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:243 in tp_setChannel: TonePlayer: setChannel(null => normal) from: tp_setChannel@app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:243:5
05-08 13:12:21.102  3399  3399 E GeckoConsole: Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:48 in tp_trashAudio: TonePlayer: trashAudio(null)
05-08 13:12:21.102  3399  3399 E GeckoConsole: Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:43 in tp_ensureAudio: TonePlayer: ensureAudio: new AudioContext(normal)
05-08 13:12:21.542  3399  3399 E GeckoConsole: Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:243 in tp_setChannel: TonePlayer: setChannel(null => normal) from: tp_setChannel@app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:243:5
05-08 13:12:21.542  3399  3399 E GeckoConsole: Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:48 in tp_trashAudio: TonePlayer: trashAudio(null)
05-08 13:12:21.542  3399  3399 E GeckoConsole: Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:43 in tp_ensureAudio: TonePlayer: ensureAudio: new AudioContext(normal)
SoundManager in the system app is getting locked into 'telephony' channel.
At https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/sound_manager.js#L306, we find a comment stating:

>    // XXX: This work should be removed
>    // once we could get telephony channel change event
>    // https://bugzilla.mozilla.org/show_bug.cgi?id=819858

So it may be related ...
Depends on: 819858
currentChannel in SoundManager is not getting updated when call is finished: we are waiting for a mozChromeEvent named 'audio-channel-changed', but we are only getting three 'visible-audio-channel-changed'. When the call is first placed, we get one 'audio-channel-changed'.
Re-checked, with and without bug 997701:
 - with, we get audio-channel-changed and visible-audio-channel-changed when we hang up
 - without, we get three visible-audio-channel-changed when we hang up.
Bouncing into 1.4? triage since the regressing cause is going to be present on 1.3, 1.4, & 2.0 (although bug 984498 hasn't been uplifted yet).

Vance - This bug is a regression from a cert blocker in bug 984498. Can you find out if the followup here to the cert blocker is also a cert blocker?
blocking-b2g: 2.0+ → 1.4?
Flags: needinfo?(etienne) → needinfo?(vchen)
Yes, this is a cert blocker
Flags: needinfo?(vchen)
blocking-b2g: 1.4? → 1.3+
Whiteboard: [systemsfe] → [systemsfe][cert]
Alive, please review this. It fixes the exposed bug, but:
 - I have no idea of the consequences of this change
 - I'm not sure if it's normal that we do not get audio-channel-changed but rather visible-audio-channel-changed
 - Writing unit tests for this sound_manager seems far from possible, but if you see a way to test this, I'm happy to hear from you :)
Attachment #8419456 - Flags: review?(alive)
Thanks for investigating.
But I'd rather to think this is a gecko bug.
Gecko should send audio-channel-changed when the busy tone which is telephony channel terminates any way.

Star, could you confirm?
Flags: needinfo?(scheng)
Comment on attachment 8419456 [details] [review]
Link to Github https://github.com/mozilla-b2g/gaia/pull/19070

I tend to grant for v1.3 because it's already too late to fix this in gecko but I'd like gecko guy to fix it in 1.4+.
Attachment #8419456 - Flags: review?(alive) → review+
(In reply to Alive Kuo [:alive][NEEDINFO!] from comment #30)
> Comment on attachment 8419456 [details] [review]
> Link to Github https://github.com/mozilla-b2g/gaia/pull/19070
> 
> I tend to grant for v1.3 because it's already too late to fix this in gecko
> but I'd like gecko guy to fix it in 1.4+.

Thanks. However, I have not tested whether we have this on v1.3. I'll check as soon as I'm in the office :)
(In reply to Alive Kuo [:alive][NEEDINFO!] from comment #28)
> Thanks for investigating.
> But I'd rather to think this is a gecko bug.
> Gecko should send audio-channel-changed when the busy tone which is
> telephony channel terminates any way.
> 
> Star, could you confirm?

I will investigate it.
Flags: needinfo?(scheng)
(In reply to Star Cheng [:scheng] from comment #32)
> (In reply to Alive Kuo [:alive][NEEDINFO!] from comment #28)
> > Thanks for investigating.
> > But I'd rather to think this is a gecko bug.
> > Gecko should send audio-channel-changed when the busy tone which is
> > telephony channel terminates any way.
> > 
> > Star, could you confirm?
> 
> I will investigate it.

I have a guess: tone player holds the telephony channel even after call end.
(In reply to Alive Kuo [:alive][NEEDINFO!] from comment #33)
> (In reply to Star Cheng [:scheng] from comment #32)
> > (In reply to Alive Kuo [:alive][NEEDINFO!] from comment #28)
> > > Thanks for investigating.
> > > But I'd rather to think this is a gecko bug.
> > > Gecko should send audio-channel-changed when the busy tone which is
> > > telephony channel terminates any way.
> > > 
> > > Star, could you confirm?
> > 
> > I will investigate it.
> 
> I have a guess: tone player holds the telephony channel even after call end.

Alive, I'm not sure this is what TonePlayer does, as exposed in comment 20: it seems to switch back to normal channel correctly. Maybe you mean there is a race condition then ?
(In reply to Alexandre LISSY :gerard-majax from comment #34)
> (In reply to Alive Kuo [:alive][NEEDINFO!] from comment #33)
> > (In reply to Star Cheng [:scheng] from comment #32)
> > > (In reply to Alive Kuo [:alive][NEEDINFO!] from comment #28)
> > > > Thanks for investigating.
> > > > But I'd rather to think this is a gecko bug.
> > > > Gecko should send audio-channel-changed when the busy tone which is
> > > > telephony channel terminates any way.
> > > > 
> > > > Star, could you confirm?
> > > 
> > > I will investigate it.
> > 
> > I have a guess: tone player holds the telephony channel even after call end.
> 
> Alive, I'm not sure this is what TonePlayer does, as exposed in comment 20:
> it seems to switch back to normal channel correctly. Maybe you mean there is
> a race condition then ?

I mean system should know the switch back to normal by audio-channel-changed event, but as you described we don't get it. Am I misunderstanding you?
Digging this up again, I noticed that there was multiple calls to TonePlayer.setChannel():
 (1) one from https://github.com/mozilla-b2g/gaia/blob/master/apps/callscreen/js/calls_handler.js#L311
 (2) one from https://github.com/mozilla-b2g/gaia/blob/master/shared/js/dialer/keypad.js#L237

The call from (1) is done when the call screen window is closing, while the call (2) is performed when hiding the keypad.

Now, what I'm seeing is that (2) comes before (1), and that this makes Gecko thinking that the channel is still visible. Removing call (2) fixes the issue.
Flags: needinfo?(etienne)
In Gecko, mCurrentHigherChannel is correctly switched first, but then never switched back:

I/Gecko   (12746): [-----] AudioChannel: new mCurrentHigherChannel=0
I/Gecko   (12746): [-----] AudioChannel: new mCurrentVisibleHigherChannel=0
I/Gecko   (12746): [-----] AudioChannel: new mCurrentHigherChannel=4
I/Gecko   (12746): [-----] AudioChannel: new mCurrentVisibleHigherChannel=4
I/Gecko   (12746): [-----] AudioChannel: new mCurrentVisibleHigherChannel=0
I/Gecko   (12746): [-----] AudioChannel: new mCurrentVisibleHigherChannel=-1
I/Gecko   (12746): [-----] AudioChannel: new mCurrentVisibleHigherChannel=0
In AudioChannelService, I noticed that when we hang up, the invalid higher value which is stuck to AudioChannel::Telephony comes from: http://dxr.mozilla.org/mozilla-central/source/dom/audiochannel/AudioChannelService.cpp#550

Hacking the indexes from [*2+1] to only [*2] makes the higher value not being changed and "fixing" the issue. I'm wondering whether those indexes are right, or if the issue is that !IsEmpty() is valid.
Flags: needinfo?(paul)
Some more logs at hangup time. This excerpt comes from logcat, and is generated by a call at the very begining of TonePlayer.setChannel():
> console.debug("TonePlayer: AudioChannel setChannel([" + (typeof this._channel) + "]" + this._channel + " => [" + (typeof channel) + "]" + channel + "). Request from: " + (new Error()).stack);

We see a first TonePlayer.setChannel("normal") that comes from keypad.js' visibilitychange handler:

>  E/GeckoConsole(20185): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:249 in tp_setChannel: TonePlayer: AudioChannel setChannel([object]null => [string]normal). Request from: tp_setChannel@app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:249:119
>  E/GeckoConsole(20185): kh_init/<@app://callscreen.gaiamobile.org/shared/js/dialer/keypad.js:237:7
>  E/GeckoConsole(20185): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:255 in tp_setChannel: TonePlayer: AudioChannel set to: normal. Request from: tp_setChannel@app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:255:5
>  E/GeckoConsole(20185): kh_init/<@app://callscreen.gaiamobile.org/shared/js/dialer/keypad.js:237:7
>  E/GeckoConsole(20185): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:49 in tp_ensureAudio: TonePlayer: AudioContext: ensureAudio(normal) [{"normal":1,"telephony":0}] FROM:tp_ensureAudio@app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:49:5
>  E/GeckoConsole(20185): tp_setChannel@app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:259:5
>  E/GeckoConsole(20185): kh_init/<@app://callscreen.gaiamobile.org/shared/js/dialer/keypad.js:237:7

Then a second call to TonePlayer.setChannel("normal") coming from calls_handler.js' window closing:

>  E/GeckoConsole(20185): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:249 in tp_setChannel: TonePlayer: AudioChannel setChannel([object]null => [string]normal). Request from: tp_setChannel@app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:249:119
>  E/GeckoConsole(20185): closeWindow@app://callscreen.gaiamobile.org/js/calls_handler.js:311:5
>  E/GeckoConsole(20185): exitCallScreen@app://callscreen.gaiamobile.org/js/calls_handler.js:305:7
>  E/GeckoConsole(20185): onCallsChanged@app://callscreen.gaiamobile.org/js/calls_handler.js:117:7
>  E/GeckoConsole(20185): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:255 in tp_setChannel: TonePlayer: AudioChannel set to: normal. Request from: tp_setChannel@app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:255:5
>  E/GeckoConsole(20185): closeWindow@app://callscreen.gaiamobile.org/js/calls_handler.js:311:5
>  E/GeckoConsole(20185): exitCallScreen@app://callscreen.gaiamobile.org/js/calls_handler.js:305:7
>  E/GeckoConsole(20185): onCallsChanged@app://callscreen.gaiamobile.org/js/calls_handler.js:117:7
>  E/GeckoConsole(20185): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:49 in tp_ensureAudio: TonePlayer: AudioContext: ensureAudio(normal) [{"normal":1,"telephony":0}] FROM:tp_ensureAudio@app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:49:5
>  E/GeckoConsole(20185): tp_setChannel@app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:259:5
>  E/GeckoConsole(20185): closeWindow@app://callscreen.gaiamobile.org/js/calls_handler.js:311:5
>  E/GeckoConsole(20185): exitCallScreen@app://callscreen.gaiamobile.org/js/calls_handler.js:305:7
>  E/GeckoConsole(20185): onCallsChanged@app://callscreen.gaiamobile.org/js/calls_handler.js:117:7

One should notice that in both cases, we see "setChannel([object]null => [string]normal)", meaning that this._channel has not been changed.
Prior to landing the callscreen app, the keypad.js was not using a visibilitychange handler as we can check in https://github.com/mozilla-b2g/gaia/blob/e151331f5688d933fad4b9da067ffdd57653b733/apps/communications/dialer/js/keypad.js#L234:

> TonePlayer.init(this._onCall ? 'telephony' : 'normal');
Hey, nice digging. Not sure what information is needed from me though :/
Flags: needinfo?(etienne)
Etienne, why was the visibilitychange handler added ?
Flags: needinfo?(etienne)
302 baku on this one, since he wrote the code. What are your thougts on comment 38 ?
Flags: needinfo?(paul) → needinfo?(amarchesini)
I had a closer look at the mChannelCounters behavior. The following log only focuses on the index [9], which seems to be the one triggering the issue.

> I/Gecko   (  287): AudioChannelService::RegisterType: mChannelCounters[9].AppendElement(0);       +1
> I/Gecko   (  287): [XXXXX] [IsEmpty] AudioChannel: higher=4, index=4, mChannelCounters[9]
> I/Gecko   (  287): AudioChannelService::UpdateChannelType: mChannelCounters[9].RemoveElement(0);  -1
> I/Gecko   (  287): AudioChannelService::RegisterType: mChannelCounters[9].AppendElement(0);       +1
> I/Gecko   (  287): AudioChannelService::UpdateChannelType: mChannelCounters[9].RemoveElement(0);  -1
> I/Gecko   (  287): AudioChannelService::UpdateChannelType: mChannelCounters[9].AppendElement(0);  +1
> I/Gecko   (  287): [XXXXX] [IsEmpty] AudioChannel: higher=4, index=4, mChannelCounters[9]
The latest AppendElement is triggered from http://dxr.mozilla.org/mozilla-central/source/dom/audiochannel/AudioChannelService.cpp#295

The fact that there is no subsequent RemoveElement call displayed means we probably hit the assert.
So I can confirm we can do both call, this is not a problem of maybe leaking something. By hacking with some setTimeout(), I can show that if keypad.js calls setChannel() first, it's NOT triggering the issue.
> Hacking the indexes from [*2+1] to only [*2] makes the higher value not
> being changed and "fixing" the issue. I'm wondering whether those indexes
> are right, or if the issue is that !IsEmpty() is valid.

No. This seems correct because the index goes from AudioChannel::Normal (0) to 
AudioChannel::Publicnotification. We want to have a value from AudioChannelInternalType enum where any audiochannel is foreground and background. Doing index * 2 you obtain a value from AudioChannelInternalType enum. +1 gives you the index for the background channel.

I'm debugging it with a real device. gerard-majax, have you checked if mDeferTelChannelTimer is used?
Telephony channel is not released immediately: there is a timer of 1500ms.
Flags: needinfo?(amarchesini)
(In reply to Andrea Marchesini (:baku) from comment #47)
> > Hacking the indexes from [*2+1] to only [*2] makes the higher value not
> > being changed and "fixing" the issue. I'm wondering whether those indexes
> > are right, or if the issue is that !IsEmpty() is valid.
> 
> No. This seems correct because the index goes from AudioChannel::Normal (0)
> to 
> AudioChannel::Publicnotification. We want to have a value from
> AudioChannelInternalType enum where any audiochannel is foreground and
> background. Doing index * 2 you obtain a value from AudioChannelInternalType
> enum. +1 gives you the index for the background channel.
> 
> I'm debugging it with a real device. gerard-majax, have you checked if
> mDeferTelChannelTimer is used?
> Telephony channel is not released immediately: there is a timer of 1500ms.

I'm checking ths right now. While hacking on the Gaia side, I noticed that sending a setChannel("normal") or setChannel("telephony") from keypad.js did not seems to have an impact: what is important is doing a setChannel, not the payload.
Indeed, mDeferTelChannelTimer is being used and it goes upto the Notify().
Flags: needinfo?(amarchesini)
Hacking to make mDeferTelChannelTimer not used does not help.
Duplicate of this bug: 1008801
(gdb) print *(script.ptr->scriptSource())
$8 = {refs = 1, dataType = js::ScriptSource::DataMissing, data = {uncompressed = {chars = 0x5a5a5a5a <Address 0x5a5a5a5a out of bounds>, ownsChars = 90}, compressed = {raw = 0x5a5a5a5a, 
      nbytes = 1515870810}}, length_ = 0, filename_ = 0xb0e37080 "app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js", displayURL_ = 0x0, sourceMapURL_ = 0x0, 
  originPrincipals_ = 0xb0e81904, introductionOffset_ = 0, introducerFilename_ = 0xb0e37080 "app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js", 
  introductionType_ = 0xb5f9bc5d "scriptElement", sourceRetrievable_ = false, argumentsNotIncluded_ = false, hasIntroductionOffset_ = true}
gdb backtrace shows this is triggering the creation of a new AudioContext:

(gdb) bt
#0  mozilla::dom::AudioChannelService::RegisterType (this=0xab5ab100, aChannel=mozilla::dom::Telephony, aChildID=41856205516, aWithVideo=false)
    at ../../../gecko/dom/audiochannel/AudioChannelService.cpp:154
#1  0xb54a2cb0 in RegisterAudioChannelAgent (aWithVideo=false, aChannel=mozilla::dom::Telephony, aAgent=0xabdbc220, this=0xab5ab100) at ../../../gecko/dom/audiochannel/AudioChannelService.cpp:127
#2  mozilla::dom::AudioChannelService::RegisterAudioChannelAgent (this=0xab5ab100, aAgent=0xabdbc220, aChannel=mozilla::dom::Telephony, aWithVideo=<optimized out>)
    at ../../../gecko/dom/audiochannel/AudioChannelService.cpp:114
#3  0xb54a187e in mozilla::dom::AudioChannelAgent::StartPlaying (this=0xabdbc220, _retval=0xbed30360) at ../../../gecko/dom/audiochannel/AudioChannelAgent.cpp:127
#4  0xb55ea3d0 in mozilla::dom::AudioDestinationNode::CreateAudioChannelAgent (this=0xadb3cd70) at ../../../../gecko/content/media/webaudio/AudioDestinationNode.cpp:527
#5  0xb55ead42 in mozilla::dom::AudioDestinationNode::AudioDestinationNode (this=0xadb3cd70, aContext=<optimized out>, aIsOffline=<optimized out>, aChannel=mozilla::dom::Telephony, 
    aNumberOfChannels=0, aLength=0, aSampleRate=0) at ../../../../gecko/content/media/webaudio/AudioDestinationNode.cpp:274
#6  0xb55e9bde in mozilla::dom::AudioContext::AudioContext (this=0xab5b4a10, aWindow=0xae3a08c0, aIsOffline=<optimized out>, aChannel=mozilla::dom::Telephony, aNumberOfChannels=0, aLength=0, 
    aSampleRate=0) at ../../../../gecko/content/media/webaudio/AudioContext.cpp:97
#7  0xb55e9d32 in mozilla::dom::AudioContext::Constructor (aGlobal=<optimized out>, aChannel=mozilla::dom::Telephony, aRv=<optimized out>)
    at ../../../../gecko/content/media/webaudio/AudioContext.cpp:152
#8  0xb5116836 in mozilla::dom::AudioContextBinding::_constructor (cx=0xb06fba20, argc=<optimized out>, vp=0xb2dda130) at AudioContextBinding.cpp:1194

The breakpoint was added in RegisterType. Logging shows that |GetInternalType(aChannel, true);| returned a type of 9 which, to my understanding, matches a telephony channel that is hidden.
Target Milestone: 2.0 S1 (9may) → 2.0 S2 (23may)
(In reply to Alexandre LISSY :gerard-majax from comment #42)
> Etienne, why was the visibilitychange handler added ?

Since the callscreen is preloaded and hidden, we don't want it to keep and audio channel open when not displayed.
Flags: needinfo?(etienne)
Makes sense. I hacked a bit in the train. For some reason that I have no idea, it seems that using document.hidden I'm not able to reproduce being stuck on the telephony channel: after 1.5sec (like the timer in AudioChannelService?) it switches back correctly to normal channel.
Flags: needinfo?(etienne)
Duplicate of this bug: 1008482
(In reply to Alexandre LISSY :gerard-majax from comment #55)
> Makes sense. I hacked a bit in the train. For some reason that I have no
> idea, it seems that using document.hidden I'm not able to reproduce being
> stuck on the telephony channel: after 1.5sec (like the timer in
> AudioChannelService?) it switches back correctly to normal channel.

It seems like a false positive ; there is something else at play, with document.hidden I'm reproducing the issue again at some point.
Attached patch Test patchSplinter Review
Hey is this helping?
Flags: needinfo?(etienne)
Comment on attachment 8421295 [details] [diff] [review]
Test patch

It does not seems to be helping :(
Attachment #8421295 - Flags: feedback-
Duplicate of this bug: 1008836
So far, my understanding of the issue is the following:
 (1) the channel is blocked on telephony because gaia's SoundManager never received any audio-channel-changed event, but rather a visible-audio-channel-changed
 (2) AudioChannelService is sending the wrong event because we don't match the condition |(higher != mCurrentHigherChannel)|
 (3) this condition is not not matched because |higher| is being reset because we match |!mChannelCounters[index * 2 + 1].IsEmpty()|
 (4) we match this !IsEmpty() condition because at some point, TonePlayer is creating a AudioContext as documented by the backtrace provided by comment 53
 (5) Hacking [index * 2 + 1] works around the issue, and using gdb we see that the RegisterType() call deduce a |type = 9|, which matches (index=4)*2+1, i.e., a background telephony channel

Andrea, can you backup that the behavior is the one we want ?
Flags: needinfo?(amarchesini)
When the telephony channel is involved, I see two transitions from type 9 to type 8, i.e. telephony hidden to visible:
> I/Gecko   ( 4899): AudioChannelService::UpdateChannelType(aChannel=4) :::==> (newType=8 != oldType=9) ?= 1;
> I/Gecko   ( 4899): AudioChannelService::UpdateChannelType(aChannel=4) [8].AppendElement();
> I/Gecko   ( 4899): AudioChannelService::UpdateChannelType(aChannel=4) [9].RemoveElement();
> I/Gecko   ( 4899): AudioChannelService: higher=4 mCurrentHigherChannel=4

Then at the end, one transition is done from type 8 to 9, telephony visible to hidden:
> I/Gecko   ( 4899): AudioChannelService::UpdateChannelType(aChannel=4) :::==> (newType=9 != oldType=8) ?= 1;
> I/Gecko   ( 4899): AudioChannelService::UpdateChannelType(aChannel=4) [9].AppendElement();
> I/Gecko   ( 4899): AudioChannelService::UpdateChannelType(aChannel=4) [8].RemoveElement();
> I/Gecko   ( 4899): AudioChannelService: oldHigher=0 higher=4 index=4 (9) users=1
> I/Gecko   ( 4899): AudioChannelService: higher=4 mCurrentHigherChannel=4

This is when things are starting to mess up.
Placing a call, then hanging up:

First, with the TonePlayer.setChannel() call in visibilitychange handler in keypad.js:
> I/Gecko   ( 8523): AudioChannelService: higher != mCurrentHigherChannel, mCurrentHigherChannel=0 try to notify observer
> I/Gecko   ( 8523): AudioChannelService[5]: higher != mCurrentHigherChannel, mCurrentHigherChannel=0 WILL notify observer
> I/Gecko   ( 8523): AudioChannelService[5]: visibleHigher != mCurrentVisibleHigherChannel, mCurrentVisibleHigherChannel=0 WILL notify observer
> I/Gecko   ( 8523): AudioChannelService: higher != mCurrentHigherChannel, mCurrentHigherChannel=4 try to notify observer
> I/Gecko   ( 8523): AudioChannelService[0]: higher != mCurrentHigherChannel, mCurrentHigherChannel=4 WILL notify observer
> I/Gecko   ( 8523): AudioChannelService[0]: visibleHigher != mCurrentVisibleHigherChannel, mCurrentVisibleHigherChannel=4 WILL notify observer
> I/Gecko   ( 8523): AudioChannelService[0]: visibleHigher != mCurrentVisibleHigherChannel, mCurrentVisibleHigherChannel=0 WILL notify observer
> I/Gecko   ( 8523): AudioChannelService[0]: visibleHigher != mCurrentVisibleHigherChannel, mCurrentVisibleHigherChannel=-1 WILL notify observer
> I/Gecko   ( 8523): AudioChannelService[5]: visibleHigher != mCurrentVisibleHigherChannel, mCurrentVisibleHigherChannel=0 WILL notify observer

Then, without this call:
> I/Gecko   ( 9065): AudioChannelService: higher != mCurrentHigherChannel, mCurrentHigherChannel=0 try to notify observer
> I/Gecko   ( 9065): AudioChannelService[5]: higher != mCurrentHigherChannel, mCurrentHigherChannel=0 WILL notify observer
> I/Gecko   ( 9065): AudioChannelService[5]: visibleHigher != mCurrentVisibleHigherChannel, mCurrentVisibleHigherChannel=0 WILL notify observer
> I/Gecko   ( 9065): AudioChannelService: higher != mCurrentHigherChannel, mCurrentHigherChannel=4 try to notify observer
> I/Gecko   ( 9065): AudioChannelService[0]: higher != mCurrentHigherChannel, mCurrentHigherChannel=4 WILL notify observer
> I/Gecko   ( 9065): AudioChannelService[0]: visibleHigher != mCurrentVisibleHigherChannel, mCurrentVisibleHigherChannel=4 WILL notify observer
> I/Gecko   ( 9065): AudioChannelService: higher != mCurrentHigherChannel, mCurrentHigherChannel=0 try to notify observer
> I/Gecko   ( 9065): AudioChannelService[0]: higher != mCurrentHigherChannel, mCurrentHigherChannel=0 WILL notify observer
> I/Gecko   ( 9065): AudioChannelService[0]: visibleHigher != mCurrentVisibleHigherChannel, mCurrentVisibleHigherChannel=0 WILL notify observer
> I/Gecko   ( 9065): AudioChannelService: higher != mCurrentHigherChannel, mCurrentHigherChannel=-1 try to notify observer
> I/Gecko   ( 9065): AudioChannelService[0]: higher != mCurrentHigherChannel, mCurrentHigherChannel=-1 WILL notify observer
> I/Gecko   ( 9065): AudioChannelService[0]: visibleHigher != mCurrentVisibleHigherChannel, mCurrentVisibleHigherChannel=-1 WILL notify observer
> I/Gecko   ( 9065): AudioChannelService: higher != mCurrentHigherChannel, mCurrentHigherChannel=0 try to notify observer
> I/Gecko   ( 9065): AudioChannelService[5]: higher != mCurrentHigherChannel, mCurrentHigherChannel=0 WILL notify observer
> I/Gecko   ( 9065): AudioChannelService[5]: visibleHigher != mCurrentVisibleHigherChannel, mCurrentVisibleHigherChannel=0 WILL notify observer
It seems, but I'd need to confirm it further, that NOT doing the TonePlayer.setChannel() FROM keypad.js call WHEN document.hidden is true, then I don't reproduce the issue.

But I still don't understand whatever happens. My latest backtrace shows a visibilitychange with |this=0xab72d340, aChannel=mozilla::dom::Telephony, aChildID=0, aElementHidden=true, aElementWasHidden=false|, which justifies the |!mChannelCounters[index*2+1].IsEmpty()| being true.
Flags: needinfo?(etienne)
Flags: needinfo?(amarchesini)
I did some more testing in the train. In the following,
 - ACS stands for AudioChannelService,
   - R means RegisterType
   - C means UpdateChannelType
   - U means UnregisterTypeInterval
 - the first digit is the aChildID
 - channel is the aChannel value
 - type is the result of GetTypeInternal

Then we can check the chain of events when hanging up.

Case where the channel is correctly reset:
> acs.log:05-13 19:38:42.808 16516 16516 I Gecko   : [0] ACS:R [channel=4] [type=9]
> acs.log:05-13 19:38:42.808 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 8]
> acs.log:05-13 19:38:43.188 16516 16516 I Gecko   : [0] ACS:R [channel=4] [type=9]
> acs.log:05-13 19:38:43.188 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 8]
> acs.log:05-13 19:38:52.968 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 9]
> acs.log:05-13 19:38:58.378 16516 16516 I Gecko   : [0] ACS:U [channel=4] [type=9]

Case where it is not:
> acs2.log:05-13 19:40:20.018 16516 16516 I Gecko   : [0] ACS:R [channel=4] [type=9]
> acs2.log:05-13 19:40:20.028 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 8]
> acs2.log:05-13 19:40:20.448 16516 16516 I Gecko   : [0] ACS:R [channel=4] [type=9]
> acs2.log:05-13 19:40:20.448 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 8]
> acs2.log:05-13 19:40:29.668 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 9]
> acs2.log:05-13 19:40:32.778 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 9]
> acs2.log:05-13 19:40:47.028 16516 16516 I Gecko   : [0] ACS:R [channel=4] [type=9]
> acs2.log:05-13 19:40:47.038 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 9]
> acs2.log:05-13 19:40:47.038 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 8]
> acs2.log:05-13 19:40:47.398 16516 16516 I Gecko   : [0] ACS:R [channel=4] [type=9]
> acs2.log:05-13 19:40:47.398 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 9]
> acs2.log:05-13 19:40:47.398 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 8]
> acs2.log:05-13 19:40:49.898 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 9]
> acs2.log:05-13 19:40:53.728 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 9]
> acs2.log:05-13 19:40:55.198 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 9]
> acs2.log:05-13 19:40:55.698 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 9]
> acs2.log:05-13 19:40:55.838 16516 16516 I Gecko   : [0] ACS:C [channel=4] [type: 9 -> 9]

So what it tells us is that in the correct case, we do the UnregisterTypeInternal, while we seems to never be doing it in the bogus case.
Hi Star,

Alex has done several analysis and has already had some log here. Could you help with taking a look based on his observation?
Flags: needinfo?(scheng)
(In reply to Eric Chou [:ericchou] [:echou] from comment #66)
> Hi Star,
> 
> Alex has done several analysis and has already had some log here. Could you
> help with taking a look based on his observation?

Thanks Alex's Digging, you provide more information to this issue.

I found there is another telephony audio channel is registered before SetPhoneState aState as 2 (IN_Call mode). And add some log to trace it. It should be registered in keypad.js. Please see below log:
(telephony audio channel type should be registered in AudioManager::setPhoneSteate())

I/GeckoDump(  177): [star] visibilitychange channel:telephony
I/GeckoDump(  177): [star] tone palyer setChannel - channel:telephony
I/GeckoDump(  177): [star] tone player trashAudio
I/AudioChannelAgent(  177): [star] AudioChannelAgent::StartPlaying

I try to disable the init flow of toneplayer because it should be created while pressing the touch screen of number key of keypad. 

https://github.com/mozilla-b2g/gaia/blob/master/shared/js/dialer/keypad.js#L234
comment line 234 ~ line 238

    //TonePlayer.init('normal');
    //var channel = this._onCall ? 'telephony' : 'normal';
    //window.addEventListener('visibilitychange', (function() {
    //  TonePlayer.setChannel(document.mozHidden ? 'normal' : channel);
    //}).bind(this));
Flags: needinfo?(scheng)
I have a question about this:
https://github.com/mozilla-b2g/gaia/blob/master/apps/callscreen/js/calls_handler.js#L311

I have no idea what the closeWindow() should do. If the function want to close the toneplayer, it seems to use toneplayer.trashAudio() instead of set the audio channel as 'normal'.
There is another strange point - there are 2 'ringer' audio channel are registered. Please see below. We should only need either. 

https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/dialer_agent.js#L46
http://dxr.mozilla.org/mozilla-central/source/dom/system/gonk/AudioManager.cpp#539

I try to disable the AudioManager part, and it works normally. I will investigate it and check weather the AudioManager part is necessary or not.
Marco, can you take a look? Thanks.
Flags: needinfo?(amarchesini) → needinfo?(mchen)
(In reply to Star Cheng [:scheng] from comment #69)
> There is another strange point - there are 2 'ringer' audio channel are
> registered. Please see below. We should only need either. 
> 
> https://github.com/mozilla-b2g/gaia/blob/master/apps/system/js/dialer_agent.
> js#L46
> http://dxr.mozilla.org/mozilla-central/source/dom/system/gonk/AudioManager.
> cpp#539
> 
> I try to disable the AudioManager part, and it works normally. I will
> investigate it and check weather the AudioManager part is necessary or not.

Thanks !

I'll check those other points.
(In reply to Star Cheng [:scheng] from comment #67)
> I found there is another telephony audio channel is registered before
> SetPhoneState aState as 2 (IN_Call mode). And add some log to trace it. It
> should be registered in keypad.js. Please see below log:
> (telephony audio channel type should be registered in
> AudioManager::setPhoneSteate())


I'm not able to find any evidence of two AudioContext('telephony') being created by TonePlayer.
> 05-14 14:27:00.140  5875  5875 I Gecko   : AudioManager::SetPhoneState(-1 => 2)
> 05-14 14:27:02.820  5875  5875 I Gecko   : AudioManager::SetPhoneState(2 => 2)
> 05-14 14:27:06.460  5875  5875 I Gecko   : AudioManager::SetPhoneState(2 => 0)

I only see one new IN_CALL state :(
Flags: needinfo?(scheng)
This issue also reproduces when using the fake libril in JS of bug 989926.
Some fun with mulet+libril:

Starting Gaia:
> AudioChannelService::UnregisterAudioChannelAgent(0)
> AudioChannelService::RegisterType: 0

Then starting dialer :
> AudioChannelService::UnregisterAudioChannelAgent(0)
> AudioChannelService::RegisterType: 0

Placing a call :
> AudioChannelService::UnregisterAudioChannelAgent(4)
> AudioChannelService::RegisterType: 4

Hanging up:
> AudioChannelService::UnregisterAudioChannelAgent(0)
> AudioChannelService::RegisterType: 0
> AudioChannelService::UnregisterAudioChannelAgent(0)
> AudioChannelService::RegisterType: 0
> AudioChannelService::UnregisterAudioChannelAgent(0)
> AudioChannelService::RegisterType: 0
> AudioChannelService::UnregisterAudioChannelAgent(0)
> AudioChannelService::RegisterType: 0

More fun is that since it's a Mulet, I can open a tab. So I'm opening a second tab on |about:| then closing the |shell.html| tab. At which point, log shows that we FINALLY call unregister against the telephony channel. Then loading |chrome://b2g/content/shell.html| in the tab that I used to open |about:|, channel is okay again.
On device:
I/Gecko   ( 3139): AudioChannelService::RegisterAudioChannelAgent(0)
I/Gecko   ( 3139): AudioChannelService::RegisterType: 0
E/GeckoConsole( 3139): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:49 in tp_trashAudio: TonePlayer: trashAudio(): delete AudioContext(null)
E/GeckoConsole( 3139): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:43 in tp_ensureAudio: TonePlayer: ensureAudio(): new AudioContext(normal)
I/Gecko   ( 3439): AudioChannelService::RegisterAudioChannelAgent(0)
I/Gecko   ( 3439): AudioChannelService::RegisterType: 0
I/Gecko   ( 3139): AudioChannelService::RegisterType: 0
I/Gecko   ( 3139): AudioChannelService::RegisterAudioChannelAgent(4)
I/Gecko   ( 3139): AudioChannelService::RegisterType: 4
E/GeckoConsole( 3139): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:49 in tp_trashAudio: TonePlayer: trashAudio(): delete AudioContext(normal)
E/GeckoConsole( 3139): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:43 in tp_ensureAudio: TonePlayer: ensureAudio(): new AudioContext(telephony)
I/Gecko   ( 3139): AudioChannelService::RegisterAudioChannelAgent(4)
I/Gecko   ( 3139): AudioChannelService::RegisterType: 4
I/Gecko   ( 3439): AudioChannelService::RegisterAudioChannelAgent(0)
I/Gecko   ( 3439): AudioChannelService::RegisterType: 0
I/Gecko   ( 3139): AudioChannelService::RegisterType: 0
I/Gecko   ( 3139): AudioChannelService::UnregisterAudioChannelAgent(4)
I/Gecko   ( 3139): AudioChannelService::UnregisterType: 4
I/Gecko   ( 3139): AudioChannelService::RegisterAudioChannelAgent(0)
I/Gecko   ( 3139): AudioChannelService::RegisterType: 0
E/GeckoConsole( 3139): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:49 in tp_trashAudio: TonePlayer: trashAudio(): delete AudioContext(telephony)
E/GeckoConsole( 3139): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:43 in tp_ensureAudio: TonePlayer: ensureAudio(): new AudioContext(normal)
I/Gecko   ( 3139): AudioChannelService::RegisterAudioChannelAgent(0)
I/Gecko   ( 3139): AudioChannelService::RegisterType: 0
E/GeckoConsole( 3139): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:49 in tp_trashAudio: TonePlayer: trashAudio(): delete AudioContext(normal)
E/GeckoConsole( 3139): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:49 in tp_trashAudio: TonePlayer: trashAudio(): delete AudioContext(null)
E/GeckoConsole( 3139): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:43 in tp_ensureAudio: TonePlayer: ensureAudio(): new AudioContext(normal)
I/Gecko   ( 3139): AudioChannelService::RegisterAudioChannelAgent(0)
I/Gecko   ( 3139): AudioChannelService::RegisterType: 0
E/GeckoConsole( 3139): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:49 in tp_trashAudio: TonePlayer: trashAudio(): delete AudioContext(null)
E/GeckoConsole( 3139): Content JS DEBUG at app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js:43 in tp_ensureAudio: TonePlayer: ensureAudio(): new AudioContext(normal)

So there is clearly TWO telephony channels created, but only one seems to be created by TonePlayer's code.
So, thanks to gdb:
 - the first telephony channel registered is because of TonePlayer
 - the second one is because of this backtrace:

gdb) bt
#0  mozilla::dom::AudioChannelService::RegisterAudioChannelAgent (this=0xae022e80, aAgent=0xaddd4300, aChannel=mozilla::dom::Telephony, aWithVideo=<optimized out>)
    at ../../../gecko/dom/audiochannel/AudioChannelService.cpp:121
#1  0xb54a7dd6 in mozilla::dom::AudioChannelAgent::StartPlaying (this=0xaddd4300, _retval=0xbed893b4) at ../../../gecko/dom/audiochannel/AudioChannelAgent.cpp:127
#2  0xb547d1a4 in SetPhoneState (aState=<optimized out>, this=0xb25f0d30) at ../../../../gecko/dom/system/gonk/AudioManager.cpp:544
#3  mozilla::dom::gonk::AudioManager::SetPhoneState (this=0xb25f0d30, aState=<optimized out>) at ../../../../gecko/dom/system/gonk/AudioManager.cpp:504
#4  0xb4d85c1e in NS_InvokeByIndex (that=<optimized out>, methodIndex=<optimized out>, paramCount=<optimized out>, params=<optimized out>)
    at ../../../../../../../gecko/xpcom/reflect/xptcall/src/md/unix/xptcinvoke_arm.cpp:164
#5  0xb5373546 in Invoke (this=0xbed894c0) at ../../../../gecko/js/xpconnect/src/XPCWrappedNative.cpp:2397
#6  Call (this=0xbed894c0) at ../../../../gecko/js/xpconnect/src/XPCWrappedNative.cpp:1738
#7  XPCWrappedNative::CallMethod (ccx=<optimized out>, mode=<optimized out>) at ../../../../gecko/js/xpconnect/src/XPCWrappedNative.cpp:1705
#8  0xb537615a in SetAttribute (ccx=...) at ../../../../gecko/js/xpconnect/src/xpcprivate.h:2081
#9  XPC_WN_GetterSetter (cx=0xb6b10840, argc=1, vp=0xbed89990) at ../../../../gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:1301
#10 0xb5d076ac in CallJSNative (args=..., native=0xb537603d <XPC_WN_GetterSetter(JSContext*, unsigned int, JS::Value*)>, cx=0xb6b10840) at ../../../gecko/js/src/jscntxtinlines.h:239
#11 js::Invoke (cx=0xb6b10840, args=..., construct=js::NO_CONSTRUCT) at ../../../gecko/js/src/vm/Interpreter.cpp:475
#12 0xb5d08072 in js::Invoke (cx=0xb6b10840, thisv=<optimized out>, fval=..., argc=1, argv=0xbed89d60, rval=...) at ../../../gecko/js/src/vm/Interpreter.cpp:531
#13 0xb5d0814c in js::InvokeGetterOrSetter (cx=<optimized out>, obj=0xacf4b180, fval=..., argc=1, argv=0xbed89d60, rval=...) at ../../../gecko/js/src/vm/Interpreter.cpp:603
#14 0xb5c9d9fe in set (vp=..., strict=true, receiver=<optimized out>, obj=..., cx=0xb6b10840, this=0xaf658088) at ../../../gecko/js/src/vm/Shape-inl.h:95
#15 js::NativeSet<(js::ExecutionMode)0> (cxArg=<optimized out>, obj=..., receiver=<optimized out>, shape=..., strict=true, vp=...) at ../../../gecko/js/src/jsobj.cpp:4365
#16 0xb5ca08e8 in js::baseops::SetPropertyHelper<(js::ExecutionMode)0> (cxArg=0xb6b10840, obj=..., receiver=..., id=..., qualified=js::baseops::Qualified, vp=..., strict=true)
    at ../../../gecko/js/src/jsobj.cpp:5062
#17 0xb5d0281c in SetPropertyOperation (rval=<optimized out>, lval=<optimized out>, pc=<optimized out>, script=..., cx=<optimized out>) at ../../../gecko/js/src/vm/Interpreter.cpp:335
#18 Interpret (cx=<optimized out>, state=...) at ../../../gecko/js/src/vm/Interpreter.cpp:2456
#19 0xb5d07494 in js::RunScript (cx=0xb6b10840, state=...) at ../../../gecko/js/src/vm/Interpreter.cpp:422
#20 0xb5d0763a in RunScript (state=..., cx=0xb6b10840) at ../../../gecko/js/src/vm/Interpreter.cpp:389
#21 js::Invoke (cx=0xb6b10840, args=..., construct=js::NO_CONSTRUCT) at ../../../gecko/js/src/vm/Interpreter.cpp:494
#22 0xb5d08072 in js::Invoke (cx=0xb6b10840, thisv=<optimized out>, fval=..., argc=3, argv=0xbed8a4b0, rval=...) at ../../../gecko/js/src/vm/Interpreter.cpp:531
#23 0xb5c59e2c in JS_CallFunctionValue (cx=0xb6b10840, obj=<optimized out>, fval=<optimized out>, args=<optimized out>, rval=...) at ../../../gecko/js/src/jsapi.cpp:5194
#24 0xb53705b6 in nsXPCWrappedJSClass::CallMethod (this=0xade50ca0, wrapper=<optimized out>, methodIndex=<optimized out>, info_=0xb2f6fdb8, nativeParams=0xbed8a550)
    at ../../../../gecko/js/xpconnect/src/XPCWrappedJSClass.cpp:1272
#25 0xb536e338 in CallMethod (params=<optimized out>, info=0xb2f6fdb8, methodIndex=25, this=0xadb4b0c0) at ../../../../gecko/js/xpconnect/src/XPCWrappedJS.cpp:517
#26 nsXPCWrappedJS::CallMethod (this=0xadb4b0c0, methodIndex=<optimized out>, info=0xb2f6fdb8, params=<optimized out>) at ../../../../gecko/js/xpconnect/src/XPCWrappedJS.cpp:507
#27 0xb4d864a6 in PrepareAndDispatch (self=0xaddfacf0, methodIndex=<optimized out>, args=<optimized out>) at ../../../../../../../gecko/xpcom/reflect/xptcall/src/md/unix/xptcstubs_arm.cpp:93
#28 0xb4d85c68 in SharedStub () from /home/alex/codaz/Mozilla/b2g/devices/Flame/B2G/objdir-gecko/dist/bin/libxul.so
#29 0xb4d85c1e in NS_InvokeByIndex (that=<optimized out>, methodIndex=<optimized out>, paramCount=<optimized out>, params=<optimized out>)
    at ../../../../../../../gecko/xpcom/reflect/xptcall/src/md/unix/xptcinvoke_arm.cpp:164
#30 0xb5373546 in Invoke (this=0xbed8a6f0) at ../../../../gecko/js/xpconnect/src/XPCWrappedNative.cpp:2397
#31 Call (this=0xbed8a6f0) at ../../../../gecko/js/xpconnect/src/XPCWrappedNative.cpp:1738
#32 XPCWrappedNative::CallMethod (ccx=<optimized out>, mode=<optimized out>) at ../../../../gecko/js/xpconnect/src/XPCWrappedNative.cpp:1705
#33 0xb5375cca in XPC_WN_CallMethod (cx=0xb6b10840, argc=2, vp=0xbed8a8b0) at ../../../../gecko/js/xpconnect/src/XPCWrappedNativeJSOps.cpp:1273
#34 0xb3dcc6c0 in ?? ()
#35 0xb3dcc6c0 in ?? ()
(In reply to Alexandre LISSY :gerard-majax from comment #77)
> So, thanks to gdb:
>  - the first telephony channel registered is because of TonePlayer
>  - the second one is because of this backtrace:

Have you tried invoking 'call DumpJSStack()' to see what JS methods are present on the stack when you hit that point? If you're testing this on a device you have to redirect the main process' stdout to see the output of that command.
(In reply to Gabriele Svelto [:gsvelto] from comment #78)
> (In reply to Alexandre LISSY :gerard-majax from comment #77)
> > So, thanks to gdb:
> >  - the first telephony channel registered is because of TonePlayer
> >  - the second one is because of this backtrace:
> 
> Have you tried invoking 'call DumpJSStack()' to see what JS methods are
> present on the stack when you hit that point? If you're testing this on a
> device you have to redirect the main process' stdout to see the output of
> that command.

Nice trick :)
So I had a look at what happens regarding the registered channels. I found two calls to RegisterAudioChannelAgent, each one with a different agent, followed by a subsequent call to UnregisterAudioChannelAgent with only the second agent, when we hang up:

> I/Gecko   ( 2216): AudioChannelService::RegisterAudioChannelAgent(aAgent=0xae121420)      << Placing call
> I/Gecko   ( 2216): AudioChannelService::RegisterAudioChannelAgent(aAgent=0xae0f9840)      << Placing call
> I/Gecko   ( 2216): AudioChannelService::UnregisterAudioChannelAgent(0xae0f9840)           << Hanging call

This ordering is always constant.

With the help of gdb, I checked where did both agent came from:
 - 0xae121420 is linked to the TonePlayer code in Gaia
 - 0xae0f9840 is triggered by the gAudioManager lazy getter in TelephonyProvider in dom/telephony/gonk

So from this we clearly see that it is the audio agent from Gaia that is missing its unregister call and thus bugs us.

Thanks to DumpJSStack(), let's see what code triggers the registration of the gaia-side agent:
> 0 tp_ensureAudio() ["app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js":44]
>     this = [object Object]
> 1 tp_setChannel(channel = "telephony") ["app://callscreen.gaiamobile.org/shared/js/dialer/tone_player.js":245]
>     this = [object Object]
> 2 anonymous(e = [object Event]) ["app://callscreen.gaiamobile.org/shared/js/dialer/keypad.js":237]
>     this = [object Object]

This is from the visibilitychange event handler.
Flags: needinfo?(scheng)
Flags: needinfo?(mchen)
Flags: needinfo?(etienne)
Duplicate of this bug: 1010152
Whiteboard: [systemsfe][cert] → [systemsfe][cert][partner-blocker][sprd311363]
Duplicate of this bug: 1008836
Duplicate of this bug: 1010656
I know have an explanation.

The root of the issue is that we still have a 'telephony' channel registered. Debugging this, I came to the conclusion that:
 (1) this is the channel created by TonePlayer() when creating an AudioContext('telephony')
 (2) while we null the property holding the AudioContext, the effective release of the AudioContext happens when the window is closed
 (3) when we trashAudio() we do not touch the mozAudioChannelType
 (4) setChannel() in TonePlayer will always perform a trash/ensure step

Because of (4) and (2), we end up with a couple of AudioContext created that will be held until the window is closed, or ressources are collected. This explains (1).

I have a patch that fixes the issue in a more proper way than the first proposal:
 - make setChannel() NOT call trashAudio() to avoid recreating unnecessary AudioContext(). This helps for (2)
 - make setChannel() change the mozAudioChannelType to the new channel. This helps for ensuring we do not retain unnecessary telephony channel
 - make trashAudio() force mozAudioChannelType to be null, for the same reason.

With those changes applied, I'm not able to reproduce anymore.
(In reply to Alexandre LISSY :gerard-majax from comment #84)
>  (2) while we null the property holding the AudioContext, the effective
> release of the AudioContext happens when the window is closed

Yuck, is this because the AudioContext is wiped out only when the GC run? Or is it tied to the window's lifetime?

> With those changes applied, I'm not able to reproduce anymore.

+1000
Comment on attachment 8419456 [details] [review]
Link to Github https://github.com/mozilla-b2g/gaia/pull/19070

Updated PR with a much better fix.
Attachment #8419456 - Flags: review+
(In reply to Alexandre LISSY :gerard-majax from comment #86)
> Updated PR with a much better fix.

I've left a couple of comments on GitHub, except for fixing up the unit-tests this LGTM.
Blocks: 1011000
So far I have unit tests, but writing device gaia ui test is way too risky for now. Bug 1011000 has been filed to make reliable tests when SoundManager refactoring is landed: it's much more stable than using events.
Comment on attachment 8419456 [details] [review]
Link to Github https://github.com/mozilla-b2g/gaia/pull/19070

Etienne, please find attached a PR that fixes the issue.
Attachment #8419456 - Flags: review?(etienne)
Comment on attachment 8419456 [details] [review]
Link to Github https://github.com/mozilla-b2g/gaia/pull/19070

Comments on github but kudos on the tests!
Attachment #8419456 - Flags: review?(etienne) → review+
bug 984498 cause this issue.
Whiteboard: [systemsfe][cert][partner-blocker][sprd311363] → [systemsfe][cert][partner-blocker][sprd311363][sprd311363]
Thanks Etienne, comments addressed. New Travis at https://travis-ci.org/mozilla-b2g/gaia/builds/25312792.
Comment on attachment 8419456 [details] [review]
Link to Github https://github.com/mozilla-b2g/gaia/pull/19070

Anthony, do you mind to put your eyes on the changes ? That's the removal of the setChannel() call part :)
Attachment #8419456 - Flags: review?(anthony)
It's OK in hamachi
(In reply to Dafeng Xu from comment #94)
> It's OK in hamachi

What is okay exactly ?
Flags: needinfo?(Dafeng.Xu)
Attachment #8419456 - Flags: review?(anthony) → review+
https://github.com/mozilla-b2g/gaia/commit/78a31887c15d26f38df0e86c3f799c0c08d4b81b
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
Looks like this is going to need branch-specific patches for uplift. Don't forget to request approval-gaia-v1.3 on the 1.3 patch :)
Flags: needinfo?(lissyx+mozillians)
(In reply to Alexandre LISSY :gerard-majax from comment #95)
> (In reply to Dafeng Xu from comment #94)
> > It's OK in hamachi
> 
> What is okay exactly ?
The attachment 8419456 [details] [review] link to Github https://github.com/mozilla-b2g/gaia/pull/19070.
I just test it in hamachi, It's OK
Flags: needinfo?(Dafeng.Xu)
We need land it to 1.3t
(In reply to James Zhang from comment #100)
> We need land it to 1.3t
Flags: needinfo?(fabrice)
1.3t: https://github.com/mozilla-b2g/gaia/commit/917174ee3812a43758bf43f7ba5f9416dcdb2ca8

Note: this still needs to go through the normal approval/uplift process for 1.3 as well.
Flags: needinfo?(fabrice)
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #98)
> Looks like this is going to need branch-specific patches for uplift. Don't
> forget to request approval-gaia-v1.3 on the 1.3 patch :)

I'm sorry, but I don't see the callscreen app on v1.3. Hence, I don't think we need to uplift this on 1.3.
Flags: needinfo?(lissyx+mozillians)
(In reply to Ryan VanderMeulen [:RyanVM UTC-4] from comment #98)
> Looks like this is going to need branch-specific patches for uplift. Don't
> forget to request approval-gaia-v1.3 on the 1.3 patch :)

Can QA cross check whether this issue reproduces on v1.3 ?
Keywords: qawanted
(In reply to Dafeng Xu from comment #94)
> It's OK in hamachi

We have verified this patch on tarako, not hamachi.
v1.3t is permared because of the uplift: https://travis-ci.org/mozilla-b2g/gaia/jobs/25441555

Could someone please fix the "mock is undefined" error? Probably only needs to require the correct file.
Flags: needinfo?(lissyx+mozillians)
That should fix the test failure reported by julien.
Attachment #8424770 - Flags: review?(etienne)
Flags: needinfo?(lissyx+mozillians)
Attachment #8424770 - Flags: review?(etienne) → review+
(In reply to Alexandre LISSY :gerard-majax from comment #103)
> I'm sorry, but I don't see the callscreen app on v1.3. Hence, I don't think
> we need to uplift this on 1.3.

What about v1.4? Also, a 1.3+ blocking status on a bug that doesn't affect 1.3 doesn't make a whole lot of sense.
Flags: needinfo?(lissyx+mozillians)
This issue does not reproduce on 1.3 Buri.

1.3 Environmental Variables:
Device: Buri 1.3 MOZ
BuildID: 20140521062818
Gaia: 0ce948e378cab7ed3db20231281dd7ca2eb99779
Gecko: fce835f24818
Version: 28.0
Firmware Version: v1.2-device.cfg

Volume change does not get stuck on call volume.
Adding qawanted to check 1.4 as well.
blocking-b2g: 1.3+ → 1.3T+
Keywords: qawanted
Whiteboard: [systemsfe][cert][partner-blocker][sprd311363][sprd311363] → [systemsfe][partner-blocker][sprd311363][sprd311363]
This issue does not occur on today's Buri 1.4 build.

1.4 Environmental Variables:
Device: Buri 1.4 MOZ
BuildID: 20140521070720
Gaia: 5cf90f2bc058c8a8f9353ee7381f546791d27405
Gecko: 8dae6f96a13a
Version: 30.0
Firmware Version: v1.2-device.cfg

Volume change does not get stuck on call volume.
Clearing branch-patch-needed since this only needs to land on 1.3T & 2.0.
Flags: needinfo?(lissyx+mozillians)
See Also: → 1195191
You need to log in before you can comment on or make changes to this bug.