981885 - [B2G][Bluetooth] No audio notification on "call waiting" call

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Bluetooth, defect)

Description

[sarsenyev]

Attachment: log31014.txt

Prerequisites:
FFOS is connected to Bluetooth headset 

Repro Steps:
1) Update a Buri to BuildID: 20140307040203
2) Receive a phone call to FFOS device and answer by tapping the headphone's call
3) When the call is establish make another call to the FFOS headset Bluetooth device

Actual:
A visual notification appears on the FFOS screen, but no audio incoming call sound can be heard on the "call waiting" call

Expected:
The devices receives audio and visual notification on the second incoming call

1.4 Environmental Variables:
Device: Buri 1.4 MOZ
BuildID: 20140307040203
Gaia: 04eb7996543f114133d1367f834a4d88b68c60ac
Gecko: b0e7f63c2138
Version: 30.0a1
Firmware Version: v1.2-device.cfg

Notes:
Audio can be heard on the first incoming call only

Repro frequency: 100%
https://moztrap.mozilla.org/manage/case/6697/
See attached: logcat

Comment 1

[sarsenyev]

The issue reproduces on 1.3 
No audio "notification" when the incoming call

1.3 Environmental Variables:
Device: Buri 1.3 MOZ
BuildID: 20140306004002
Gaia: 8aed4fafbaeb86d6884d31ce7d3cbeb87bcbf837
Gecko: 3d2d84d52141
Version: 28.0
Firmware Version: v1.2-device.cfg

Comment 2

[Jason Smith [:jsmith]]

Does this reproduce on 1.1?

Comment 3

[Ben Tian (inactive)]

The audio notification (a 'Du' sound) is heard without BT headset but not heard when BT headset is connected. ni? audio team Star.

Star, does audio driver mix the audio notification into bluetooth SCO audio path?

Comment 4

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

(In reply to Jason Smith [:jsmith] from comment #2)
> Does this reproduce on 1.1?
I don't think this bug has been handled before. It looks like audio HAL related.

Comment 5

[Jason Smith [:jsmith]]

(In reply to Shawn Huang [:shuang] [:shawnjohnjr] from comment #4)
> (In reply to Jason Smith [:jsmith] from comment #2)
> > Does this reproduce on 1.1?
> I don't think this bug has been handled before. It looks like audio HAL
> related.

ok - so that means this is not a regression.

Comment 6

[Star Cheng [:scheng]]

The waiting system tone is belong as "MEDIA" type. I am investigating weather the "MEDIA" stream  can be routed to SOC in audio policy HAL or not.

Comment 7

[Star Cheng [:scheng]]

In another device - Nexus4, I can duplicate it. But I am not sure weather the audio routing is correct or not.

Hi, Michael

I check the log, the call waiting tone is routed to "low-latency-playback bt-sco". It should be right. The log is below: Could you help me to check? 
Thanks

[1] ringtone 
I/AudioManager(  179): [star] SetPhoneState aState 1 -> [star] PHONE_STATE_RINGTONE
I/AudioStream( 1218): [star] AudioStream::Init stream type 2 -> [star] CUBEB_STREAM_TYPE_RING

D/audio_hw_primary(  173): out_set_parameters: enter: usecase(1: low-latency-playback) kvpairs: routing=2
D/audio_hw_primary(  173): out_set_parameters: exit: code(1)
D/audio_hw_primary(  173): start_output_stream: enter: usecase(1: low-latency-playback) devices(0x2)
D/audio_hw_primary(  173): select_devices: out_snd_device(2: speaker) in_snd_device(0: none)
D/audio_hw_primary(  173): enable_snd_device: sending audio calibration for snd_device(2) acdb_id(14)
E/audio_hw_primary(  173): [star] enable_snd_device: snd_device(2: speaker)
E/audio_hw_primary(  173): [star] enable_audio_route: enter: usecase(1)
E/audio_hw_primary(  173): [star]enable_audio_route: apply mixer path: low-latency-playback
E/audio_hw_primary(  173): [star] device id 14 sample rate 48000
D/audio_hw_primary(  173): start_output_stream: exit
D/audio_hw_primary(  173): adev_set_parameters: enter: bt_samplerate=8000
D/audio_hw_primary(  173): adev_set_parameters: exit with code(-2)
D/audio_hw_primary(  173): out_set_parameters: enter: usecase(1: low-latency-playback) kvpairs: routing=2
D/audio_hw_primary(  173): out_set_parameters: exit: code(1)

[2] in call
I/AudioManager(  179): [star] SetPhoneState aState 2 -> [star] PHONE_STATE_IN_CALL

D/audio_hw_primary(  173): out_set_parameters: enter: usecase(1: low-latency-playback) kvpairs: routing=32
D/audio_hw_primary(  173): select_devices: out_snd_device(10: bt-sco-headset) in_snd_device(0: none)
D/audio_hw_primary(  173): disable_audio_route: reset mixer path: low-latency-playback
D/audio_hw_primary(  173): disable_snd_device: snd_device(2: speaker)
D/audio_hw_primary(  173): enable_snd_device: sending audio calibration for snd_device(10) acdb_id(22)
E/audio_hw_primary(  173): [star] enable_snd_device: snd_device(10: bt-sco-headset)
E/audio_hw_primary(  173): [star] enable_audio_route: enter: usecase(1)
E/audio_hw_primary(  173): [star]enable_audio_route: apply mixer path: low-latency-playback bt-sco
D/audio_hw_primary(  173): start_voice_call: enter
D/audio_hw_primary(  173): select_devices: out_snd_device(10: bt-sco-headset) in_snd_device(24: bt-sco-mic)
D/audio_hw_primary(  173): enable_snd_device: snd_device(10: bt-sco-headset) is already active
D/audio_hw_primary(  173): enable_snd_device: sending audio calibration for snd_device(24) acdb_id(21)
E/audio_hw_primary(  173): [star] enable_snd_device: snd_device(24: bt-sco-mic)
E/audio_hw_primary(  173): [star] enable_audio_route: enter: usecase(5)
E/audio_hw_primary(  173): [star]enable_audio_route: apply mixer path: voice-call bt-sco
D/audio_hw_primary(  173): out_set_parameters: exit: code(2)
D/audio_hw_primary(  173): out_standby: enter: usecase(1: low-latency-playback)
D/audio_hw_primary(  173): stop_output_stream: enter: usecase(1: low-latency-playback)
D/audio_hw_primary(  173): disable_audio_route: reset mixer path: low-latency-playback bt-sco
D/audio_hw_primary(  173): stop_output_stream: exit: status(0)
D/audio_hw_primary(  173): out_standby: exit

[3] waiting call tone
I/AudioStream( 1218): [star] AudioStream::Init stream type 1 -> CUBEB_STREAM_TYPE_SYSTEM

D/audio_hw_primary(  173): out_set_parameters: enter: usecase(1: low-latency-playback) kvpairs: routing=32
D/audio_hw_primary(  173): out_set_parameters: exit: code(2)
D/audio_hw_primary(  173): start_output_stream: enter: usecase(1: low-latency-playback) devices(0x20)
D/audio_hw_primary(  173): select_devices: out_snd_device(10: bt-sco-headset) in_snd_device(0: none)
D/audio_hw_primary(  173): enable_snd_device: snd_device(10: bt-sco-headset) is already active
E/audio_hw_primary(  173): [star] enable_audio_route: enter: usecase(1)
E/audio_hw_primary(  173): [star]enable_audio_route: apply mixer path: low-latency-playback bt-sco
E/audio_hw_primary(  173): [star] device id 14 sample rate 48000
D/audio_hw_primary(  173): start_output_stream: exit

Comment 9

[Preeti Raghunath(:Preeti)]

Eric,

Can you please review the logs pasted? Please help with next steps.

Comment 10

[Inder]

Vasanth/Bhargav -- can you also please address Star's questions in comment 7.

Comment 11

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

(In reply to Preeti Raghunath(:Preeti) from comment #9)
> Eric,
> 
> Can you please review the logs pasted? Please help with next steps.

Preeti,

The logs star pasted were for Bhargav and we're still looking forward to his response.

Comment 12

[vasanth]

Got it. It's a mismatch between GeckoBluetooth and Bluedroid. 

From below adb logs during this scenario,
<<
I/GeckoBluetooth( 207): UpdatePhoneCIND: [2] state 10 => BTHF: active[1] held[0] state[5]
E/bt-btif ( 207): phone_state_change: Incorrect new ringing call state
>>

Here 5 in "state[5]" corresponds to BTHF_CALL_STATE_WAITING.
But I see the switch statement in phone_state_change(), btif_hf.c [1] never handles BTHF_CALL_STATE_WAITING. So this fails.

For same scenario (incoming call during live call), android framework sends BTHF_CALL_STATE_INCOMING again and bluedroid internally converts it to BTA_AG_CALL_WAIT_RES here [2]

Gecko should do similar to android framework, since we don't have control over bluedroid?

[1] https://www.codeaurora.org/cgit/quic/la/platform/external/bluetooth/bluedroid/tree/btif/src/btif_hf.c/?h=b2g_kk_3.5#n1007
[2] https://www.codeaurora.org/cgit/quic/la/platform/external/bluetooth/bluedroid/tree/btif/src/btif_hf.c/?h=b2g_kk_3.5#n940

Comment 13

[vasanth]

Sorry. Above link 2 is wrong.

New [2] https://www.codeaurora.org/cgit/quic/la/platform/external/bluetooth/bluedroid/tree/btif/src/btif_hf.c/?h=b2g_kk_3.5#n1042

Comment 14

[Preeti Raghunath(:Preeti)]

Star,

Do we need anything else from Vasanth?

Comment 15

[Jason Smith [:jsmith]]

CS blocker - so moving to 1.4+

Comment 16

[Star Cheng [:scheng]]

Hi, Shawn

Could you provide more information about Comment 12? 

Thanks

Comment 17

[Shawn Huang [:shawnjohnjr][:shuang] (as a happy gecko contributor)]

(In reply to vasanth from comment #12)
> Got it. It's a mismatch between GeckoBluetooth and Bluedroid. 
> 
> From below adb logs during this scenario,
> <<
> I/GeckoBluetooth( 207): UpdatePhoneCIND: [2] state 10 => BTHF: active[1]
> held[0] state[5]
> E/bt-btif ( 207): phone_state_change: Incorrect new ringing call state
> >>
> 
> Here 5 in "state[5]" corresponds to BTHF_CALL_STATE_WAITING.
> But I see the switch statement in phone_state_change(), btif_hf.c [1] never
> handles BTHF_CALL_STATE_WAITING. So this fails.
> 
> For same scenario (incoming call during live call), android framework sends
> BTHF_CALL_STATE_INCOMING again and bluedroid internally converts it to
> BTA_AG_CALL_WAIT_RES here [2]
> 
> Gecko should do similar to android framework, since we don't have control
> over bluedroid?
> 
> [1]
> https://www.codeaurora.org/cgit/quic/la/platform/external/bluetooth/
> bluedroid/tree/btif/src/btif_hf.c/?h=b2g_kk_3.5#n1007
> [2]
> https://www.codeaurora.org/cgit/quic/la/platform/external/bluetooth/
> bluedroid/tree/btif/src/btif_hf.c/?h=b2g_kk_3.5#n940

This had been fixed in Bug 993288. Star can you apply patches of Bug 993288? But i'm not sure why Comment 12 is related to this bug. Both buri and Nexus 4 can reproduce this bug, and Buri uses Bluez.
I don't understand even if audio path switches to BT_SCO and it's related to bluetooth? I think call waiting tone shall be mixed into SCO.

Comment 18

[vasanth]

(In reply to Shawn Huang [:shuang] [:shawnjohnjr] from comment #17)
> But i'm not sure why Comment 12 is related to this bug. 

Shawn, This are the only errors I see in my qrd 8x26 device during this scenario. Aren't you seeing these errors in a device with bluedroid?
I'm not sure about same issue with bluez though.

Comment 19

[Star Cheng [:scheng]]

The volume (after calling computeVolume() )is set as 0 besides voice & SCO. The log as below:

stream 0 -> VOICE_CALL
stream 6 -> BLUETOOTH_SCO

D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume stream 0 device 32 index 0 output 2 
D/AudioPolicyManagerBase( 1182): [star]checkAndSetVolume() cannot set stream 0 volume with force use = 3 for comm
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume stream 1 device 32 index 0 output 2
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume volume 0
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume stream 2 device 32 index 0 output 2
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume volume 0
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume stream 3 device 32 index 0 output 2
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume volume 0
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume stream 4 device 32 index 0 output 2
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume volume 0
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume stream 5 device 32 index 0 output 2
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume volume 0
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume stream 6 device 32 index 10 output 2 -> 
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume volume 1070596096
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume stream 7 device 32 index 0 output 2
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume volume 0
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume stream 8 device 32 index 0 output 2
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume volume 0
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume stream 9 device 32 index 0 output 2
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume volume 0
E/AudioPolicyManagerBase( 1182): [star] handleIncallSonification stream_strategy 0
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume stream 1 device 32 index 0 output 2
D/AudioPolicyManagerBase( 1182): [star] checkAndSetVolume volume 0


We should use "Telephony" audio channel type to ensure we can hear "waiting tone" with SCO device in call.

Comment 20

[Star Cheng [:scheng]]

We will plumb audiochannel type from AudioContext to mediastreamgraph (for audio back-end) in Bug 984498. After finishing it, we can use 'telephony' type for waiting tone. So I mark this bug depend on bug 984498.

Comment 21

[Star Cheng [:scheng]]

Depend on: Bug 997701

Because we need to use 'telephony' AudioChannelType for busy tone & waiting tone. After finishing solving Bug 997701, we can solve this issue (Bug 981885) as well.

Comment 22

[Jason Smith [:jsmith]]

Retriage - this is up for consideration to be punted, as this is a feature request.

mvines - can we consider removing this from the QC CS queue?

Comment 23

[Michael Vines [:m1] [:evilmachines]]

What is the LoE to fix this bug after bug 997701 (v1.3+) lands?

Comment 24

[Jason Smith [:jsmith]]

(In reply to Michael Vines [:m1] [:evilmachines] from comment #23)
> What is the LoE to fix this bug after bug 997701 (v1.3+) lands?

Star - Can you answer this?

Comment 25

[Star Cheng [:scheng]]

(In reply to Jason Smith [:jsmith] from comment #24)
> (In reply to Michael Vines [:m1] [:evilmachines] from comment #23)
> > What is the LoE to fix this bug after bug 997701 (v1.3+) lands?
> 
> Star - Can you answer this?


If the patches of bug 984498 & bug 997701 are both landed, it can solve this bug. I think the effort is low. And I am trying to resolve test case fail caused by my patch of bug 984498.

Comment 26

[Michael Vines [:m1] [:evilmachines]]

Thanks Star. I think we should aim to get this in to v1.4.  It'll make the product much better for BT users, and we all know how long the OTA upgrades take.

Comment 27

[bhavana bajaj [:bajaj]]

(In reply to Michael Vines [:m1] [:evilmachines] from comment #26)
> Thanks Star. I think we should aim to get this in to v1.4.  It'll make the
> product much better for BT users, and we all know how long the OTA upgrades
> take.

Looks like landings in bug 984498 & bug 997701 should take care of this bug. I'll mark the dependency here and not block on this issue.

Comment 28

[Preeti Raghunath(:Preeti)]

Inder,

Can we please have this issue tested once bug 984498 and bug 997701 have landed? 

We want to ensure that the issue is actually fixed with landing bug 984498 and bug 997701.

Comment 29

[Inder]

> 
> Can we please have this issue tested once bug 984498 and bug 997701 have
> landed? 
> 
> We want to ensure that the issue is actually fixed with landing bug 984498
> and bug 997701.

Moving the ni to Vasanth.
Preeti -- Just to confirm, this doesn't block our CS but i think Vasanth can help here.
Vasanth -- can you please verify once those fixes are uplifted to v1.4.

Comment 30

[vasanth]

(In reply to Preeti Raghunath(:Preeti) from comment #28)
> Can we please have this issue tested once bug 984498 and bug 997701 have
> landed? 

Sure Preeti. ni me again when they are landed in V1.4

Comment 31

[Preeti Raghunath(:Preeti)]

Backlog bug 981885. Banking on bug 984498 and bug 997701 to fix the issue.

Vasanth,

Bugs landed.

Comment 32

[vasanth]

(In reply to Preeti Raghunath(:Preeti) from comment #31)
> Backlog bug 981885. Banking on bug 984498 and bug 997701 to fix the issue.
> 
> Vasanth,
> 
> Bugs landed.

Preeti, I see bug 984498 is not landed in V1.4 yet (landed, backed out and not landed again)
Will monitor & test once that is landed.

Comment 33

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

Hi Vasanth,

(In reply to vasanth from comment #32)
> (In reply to Preeti Raghunath(:Preeti) from comment #31)
> > Backlog bug 981885. Banking on bug 984498 and bug 997701 to fix the issue.
> > 
> > Vasanth,
> > 
> > Bugs landed.
> 
> Preeti, I see bug 984498 is not landed in V1.4 yet (landed, backed out and
> not landed again)
> Will monitor & test once that is landed.

bug 984498 has landed for a few days. Please test again. Thank you.

Comment 34

[vasanth]

(In reply to Eric Chou [:ericchou] [:echou] from comment #33)
> bug 984498 has landed for a few days. Please test again. Thank you.

It's working as expected in V1.4. Able to hear busy/call waiting tone for new incoming call when another call is in progress. Thanks!

Comment 35

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

That's great. Thanks for testing, Vasanth.

Close as resolve fixed per comment 34 and add bug 984498 to the see also list.

Comment 36

[Roy|尚祚彦]

We have exactly the same issue.

Our modification is below:
AudioPolicyManagerBase::computeVolume

    //roy: modify for set BluetoothSCO volume max
    if (stream == AudioSystem::BLUETOOTH_SCO) {
        ALOGE("BT SCO use max value");
        return 1.0;
    }
and we found sometimes we will miss the BTA_AG_HF_CMD_CCWA cmd.
bta_ag_cmd.c
        case BTA_AG_CALL_WAIT_RES:
            //roy to support ccwa by default 
            //if (p_scb->ccwa_enabled)
            {
                bta_ag_send_result(p_scb, code, p_result->data.str, 0);
            }
            bta_ag_send_call_inds(p_scb, p_result->result);
            break;

Roy