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.

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.

Reproduced on Flame.

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.

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.

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?

(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).

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 ...

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?

Yes, this is a cert blocker

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 :)

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?

http://mxr.mozilla.org/mozilla-central/source/dom/audiochannel/AudioChannelService.cpp#567 http://mxr.mozilla.org/mozilla-central/source/dom/audiochannel/AudioChannelService.cpp#583

Comment on attachment 8419456 [details] 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+.

(In reply to Alive Kuo [:alive][NEEDINFO!] from comment #30) > Comment on attachment 8419456 [details] > 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.

(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.

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.

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 :/

Etienne, why was the visibilitychange handler added ?

302 baku on this one, since he wrote the code. What are your thougts on comment 38 ?

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.

(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().

Hacking to make mDeferTelChannelTimer not used does not help.

(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.

(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.

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.

(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.

Hey is this helping?

Comment on attachment 8421295 [details] [diff] [review] Test patch It does not seems to be helping :(

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 ?

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.

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?

(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));

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.

(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 :(

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.

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] Link to Github https://github.com/mozilla-b2g/gaia/pull/19070 Updated PR with a much better fix.

(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.

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] Link to Github https://github.com/mozilla-b2g/gaia/pull/19070 Etienne, please find attached a PR that fixes the issue.

Comment on attachment 8419456 [details] Link to Github https://github.com/mozilla-b2g/gaia/pull/19070 Comments on github but kudos on the tests!

bug 984498 cause this issue.

Thanks Etienne, comments addressed. New Travis at https://travis-ci.org/mozilla-b2g/gaia/builds/25312792.

Comment on attachment 8419456 [details] 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 :)

It's OK in hamachi

(In reply to Dafeng Xu from comment #94) > It's OK in hamachi What is okay exactly ?

Travis is green. https://travis-ci.org/mozilla-b2g/gaia/builds/25312792

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 :)

(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] link to Github https://github.com/mozilla-b2g/gaia/pull/19070. I just test it in hamachi, It's OK

We need land it to 1.3t

(In reply to James Zhang from comment #100) > We need land it to 1.3t

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.

(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.

(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 ?

(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.

That should fix the test failure reported by julien.

Travis is green: https://travis-ci.org/mozilla-b2g/gaia/builds/25508424

(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.

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.

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.