1032761 - [FFOS2.1] [Audio]ringtone keeps playing for 1s after user answer the phone when there is headphone plugged in

Status: RESOLVED WONTFIX

(Firefox OS Graveyard :: AudioChannel, defect)

Description

[Peipei Cheng (needinfo if you need my action)]

Steps to reproduce
----------------------------------------------------------------------
0. Plug in a wired headphone
1. Set a music as ringtone
2. Make a MT call to test device
3. After ringtone rings, answer the call
   --> You will notice the ringtone still plays for about 1s.

Note: without wired headphone cannot get this issue reproduced.


Test build:
Gaia      3c896abb05d95ebe3d66634d014dac03a05f4caf
Gecko     https://hg.mozilla.org/releases/mozilla-b2g28_v1_3t/rev/f8a929882cb0
BuildID   20140630014001
Version   28.1
ro.build.version.incremental=eng.cltbld.20140630.045332
ro.build.date=Mon Jun 30 04:53:41 EDT 2014

Comment 1

[Joe Cheng [:jcheng] (please needinfo)]

this does not put the phone in unusable state, adding this to backlog.

Comment 2

[Star Cheng [:scheng]]

I can't duplicate in flame / nexus4 device with latest SW.

Comment 3

[Xinhe Yan]

in Android
stopOutput is called before connect a call.

08-05 19:57:54.707 D/AudioPolicyManagerSPRD(  101): stopOutput() output 2, stream 2, session 12
08-05 19:57:54.707 D/AudioPolicyManagerSPRD(  101): stopOutput() is_voip_set 0,stream 2,output size 1
08-05 19:57:54.727 W/audio_hw_primary(  101): voice:VBC_CMD_HAL_get_cmd try vbc_lock, pipe_name:/dev/spipe_w6, ret:12.
08-05 19:57:54.727 W/audio_hw_primary(  101): vocie:VBC_CMD_HAL_OPEN IN.
08-05 19:57:54.727 W/audio_hw_primary(  101): vocie:VBC_CMD_HAL_OPEN, try lock
08-05 19:57:54.727 W/audio_hw_primary(  101): voice:VBC_CMD_HAL_OPEN, got lock
08-05 19:57:55.277 W/audio_hw_primary(  101): voice:VBC_CMD_HAL_OPEN OUT, vbpipe_name:/dev/spipe_w6.
08-05 19:57:55.277 W/audio_hw_primary(  101): voice:VBC_CMD_HAL_get_cmd release vbc_lock.
08-05 19:57:55.277 W/audio_hw_primary(  101): voice:VBC_CMD_HAL_get_cmd try vbc_lock, pipe_name:/dev/spipe_w6, ret:12.
08-05 19:57:55.277 W/audio_hw_primary(  101): voice:VBC_CMD_DEVICE_CTRL IN.
08-05 19:57:55.407 W/audio_hw_primary(  101): voice:VBC_CMD_DEVICE_CTRL OUT.
08-05 19:57:55.407 W/audio_hw_primary(  101): voice:VBC_CMD_HAL_get_cmd release vbc_lock.
08-05 19:57:55.417 W/audio_hw_primary(  101): voice:VBC_CMD_HAL_get_cmd try vbc_lock, pipe_name:/dev/spipe_w6, ret:12.
08-05 19:57:55.417 W/audio_hw_primary(  101): voice:VBC_CMD_SWITCH_CTRL IN.
08-05 19:57:55.417 W/audio_hw_primary(  101): voice:VBC_CMD_SWITCH_CTRL OUT.
08-05 19:57:55.417 W/audio_hw_primary(  101): voice:VBC_CMD_HAL_get_cmd release vbc_lock.
08-05 19:57:55.517 W/audio_hw_primary(  101): voice:VBC_CMD_HAL_get_cmd try vbc_lock, pipe_name:/dev/spipe_w6, ret:12.
08-05 19:57:55.517 W/audio_hw_primary(  101): voice:VBC_CMD_SET_GAIN IN.
08-05 19:57:55.527 W/audio_hw_primary(  101): voice:VBC_CMD_SET_GAIN OUT.
08-05 19:57:55.527 W/audio_hw_primary(  101): voice:VBC_CMD_HAL_get_cmd release vbc_lock.
08-05 19:57:55.787 D/AudioPolicyManagerSPRD(  101): stopOutput() output 2, stream 1, session 13
08-05 19:57:55.787 D/AudioPolicyManagerSPRD(  101): stopOutput() is_voip_set 0,stream 1,output size 1

in ffos 
stopOutput called after connect call.

08-04 00:14:30.900 W/audio_hw_primary(  104): voice:VBC_CMD_HAL_get_cmd try vbc_lock, pipe_name:/dev/spipe_w6, ret:12.
08-04 00:14:30.900 W/audio_hw_primary(  104): vocie:VBC_CMD_HAL_OPEN IN.                   
08-04 00:14:30.900 W/audio_hw_primary(  104): vocie:VBC_CMD_HAL_OPEN, try lock
08-04 00:14:30.900 W/audio_hw_primary(  104): voice:VBC_CMD_HAL_OPEN, got lock
08-04 00:14:31.460 W/audio_hw_primary(  104): voice:VBC_CMD_HAL_OPEN OUT, vbpipe_name:/dev/spipe_w6.
08-04 00:14:31.460 W/audio_hw_primary(  104): voice:VBC_CMD_HAL_get_cmd release vbc_lock.
08-04 00:14:31.470 W/audio_hw_primary(  104): voice:VBC_CMD_HAL_get_cmd try vbc_lock, pipe_name:/dev/spipe_w6, ret:12.
08-04 00:14:31.470 W/audio_hw_primary(  104): voice:VBC_CMD_DEVICE_CTRL IN.
08-04 00:14:31.620 W/audio_hw_primary(  104): voice:VBC_CMD_DEVICE_CTRL OUT.
08-04 00:14:31.620 W/audio_hw_primary(  104): voice:VBC_CMD_HAL_get_cmd release vbc_lock.
08-04 00:14:31.640 W/audio_hw_primary(  104): voice:VBC_CMD_HAL_get_cmd try vbc_lock, pipe_name:/dev/spipe_w6, ret:12.
08-04 00:14:31.640 W/audio_hw_primary(  104): voice:VBC_CMD_SWITCH_CTRL IN.
08-04 00:14:31.640 W/audio_hw_primary(  104): voice:VBC_CMD_SWITCH_CTRL OUT.                     
08-04 00:14:31.640 W/audio_hw_primary(  104): voice:VBC_CMD_HAL_get_cmd release vbc_lock.
08-04 00:14:32.000 W/audio_hw_primary(  104): voice:VBC_CMD_HAL_get_cmd try vbc_lock, pipe_name:/dev/spipe_w6, ret:12.
08-04 00:14:32.000 W/audio_hw_primary(  104): voice:VBC_CMD_SET_GAIN IN.
08-04 00:14:32.000 W/audio_hw_primary(  104): voice:VBC_CMD_SET_GAIN OUT.
08-04 00:14:32.000 W/audio_hw_primary(  104): voice:VBC_CMD_HAL_get_cmd release vbc_lock.
08-04 00:14:32.340 D/AudioPolicyManagerSPRD(  104): stopOutput() output 2, stream 2, session 13           
08-04 00:14:32.340 D/AudioPolicyManagerSPRD(  104): stopOutput() is_voip_set 0,stream 2,output size 1

Comment 4

[Xinhe Yan]

Audio hal will throw data during estimate call. 
But after call connected, audio data will not be throw. 

If stopOutput called after call connected, the audio data will send to cp and mix .

Wayne, can you check log in gecko/gaia?

Comment 5

[Wayne Chen [:xwaynec]]

From log, I think app should stop music first then pick up phone. Maybe they can change the scenario?

1. pick up phone
08-06 11:06:43.690 V/AudioPolicyManagerBase(  102): setPhoneState() state 2

2. stop music
08-06 11:06:44.040 D/AudioPolicyManagerSPRD(  102): stopOutput() output 2, stream 2, session 25

Comment 6

[Wayne Chang [:wchang]]

[Blocking Requested - why for this release]:

Sounds pretty fundamental we should have this corrected as early as possible.

- Stopping ringtone before call is connected.

Comment 7

[jingmei.zhang]

(In reply to Wayne Chang [:wchang] from comment #6)
> [Blocking Requested - why for this release]:
> 
> Sounds pretty fundamental we should have this corrected as early as possible.
> 
> - Stopping ringtone before call is connected.

hi wchang:

  I have checked the 'pause' action in gaia.it sees from the log that before we call the pause function,the ringtone has been stopped.

08-23 12:33:19.870    89   185 E audio_hw_primary: VBC_CMD_SWITCH_CTRL OUT.//establish the Conversation

08-23 12:33:19.920    85    85 I Gecko   : -*- RadioInterface[0]: Received

08-23 12:33:20.130    89   190 W audio_hw_primary: vplayback write over result is 0,frame_size is 4 in frames 1600, out frames 290
08-23 12:33:20.130    89   190 W audio_hw_primary: vplayback out_write call_start(1) call_connected(1) ...in....
08-23 12:33:20.130    89   431 V AudioPolicyManagerBase: stopOutput() output 1, stream 2, session 2 //stop the ringtone 

08-23 12:33:20.170    85    85 E GeckoConsole: Content JS LOG at app://system.gaiamobile.org/js/dialer_agent.js:167 in da_stopAlerting: zjm-_stopAler//call the pause function in gaia.
    
the pause function in gaia is used to stop the ringtone after the Conversation is stopped.

Comment 8

[jingmei.zhang]

hi Wayne Chen:
   
  As described in comment7,there is a pause function in system/js/dialer_agent.js,if it is called before the conversation is connected,the issue might be solved.But I do not know if it is feasible,what do you think of it?

Comment 9

[Wayne Chen [:xwaynec]]

(In reply to jingmei.zhang from comment #8)
> hi Wayne Chen:
>    
>   As described in comment7,there is a pause function in
> system/js/dialer_agent.js,if it is called before the conversation is
> connected,the issue might be solved.But I do not know if it is feasible,what
> do you think of it?

Hello jingmei,

your method needs gaia's owner to confirm.

Sincerely,
Wayne

Comment 10

[jingmei.zhang]

hi Wayne Chen:

   I don't know who might be the owner of gaia here.

   so would you please tell me the owner in gaia?

Comment 11

[Wayne Chang [:wchang]]

Someone will check this once it is triaged

Comment 12

[Dietrich Ayala (:dietrich)]

Triage reviewed, and can't block on an issue that hasn't actually been experienced.

Once 2.1 is running on this device and you can confirm the issue occurs still, re-nominate to block at that point.

Comment 13

[helloarvin]

[Blocking Requested - why for this release]:
As comment#12, mark as block for the issue still occurs on the branch v2.1 and v2.1s.

Comment 14

[Vance Chen [:vchen][skype:vance.lucida][[e-mail]]]

Hi Alastor -

Any workaround we can have for this issue?

Thanks

Comment 15

[Alastor Wu [:alwu]]

Sorry for my late reply,
I will check it later. 
Keep ni for tracking.

Comment 16

[Alastor Wu [:alwu]]

In short : Have not fix it yet, Still looking for more details.

---

After I checked, I found that the behavior of the audio channel is correct,

> Get incoming call
> 05-04 16:00:30.932  1491  1491 I Gecko   : DD | Agent, register  , type  = 5    <-- start ringtone
> 05-04 16:00:30.932  1491  1491 I Gecko   : DD | Am, SetPhoneState, state = 0
> 05-04 16:00:31.122  1491  1491 I Gecko   : DD | Am, SetPhoneState, state = 1
> 
> Answer the call
> 05-04 16:00:35.882  1491  1491 I Gecko   : DD | Agent, unregister, type  = 5    <-- stop ringtone
> 05-04 16:00:35.922  1491  1491 I Gecko   : DD | Am, SetPhoneState, state = 2
> 05-04 16:00:35.962  1491  1491 I Gecko   : DD | Agent, register  , type  = 4    <-- start telephony

According to the previous discussion, the stopOutput() would be called after the setPhoneState(). 
If the command order in Gecko is correct, I guessed that the setPhoneState() was triggered first may resulted from needing more process time for the stopOutput().

Therefore, I used the AudioSystem::isStreamActive() to check whether the ringtone stream is ended by stopOutput(). If so, we set the phone state, or wait for its completion.

However, the issue still exist, even the setPhoneState() was called after the stopOutput().

Comment 17

[Alastor Wu [:alwu]]

Hi, all,
I think this issue might not be solved in Gecko, must be modified in the Vendor.
In my observation, the issue might be caused by "the hw voice call module be active too early".

---

As I known, the telephony should be started after the AudioManager::SetPhoneState(). In this fucntion, we will modify the call state. After that, the the voice call module starts and the AudioPolicyManager can decide the audio output device from the call state.

However, in Dolphin, the voice call would be started before the AudioManager::SetPhoneState(). The voice call would be active too early, and it also changed the audio output device. 

> Voice call module be start 
> 05-05 11:25:27.080   103   316 W audio_hw_primary: voice:START CALL,open pcm device...
> 05-05 11:25:27.080   103   316 W audio_hw_primary: SetParas_OpenHal_Incall successfully,sim card number(0)
> 
> Change the output device, 0x4 = headset
> 05-05 11:25:27.280   103   316 W audio_hw_primary: SetCall_ModePara successfully, device: earpice(Close),
>   headphone(Open), speaker(Close), Main_Mic(Close), Back_Mic(Close), hp_mic(Open)
> 05-05 11:25:27.280   103   316 W audio_hw_primary: SetVoice_gain_by_devices out, out_devices:0x4, 
>   in_devices:0x80000010
> 
> Stop ringtone
> 05-05 11:25:27.520  6128  6128 I GeckoDump: DD | Gaia, _stopAlerting
> 05-05 11:25:27.520  6128  6128 I Gecko   : DD | HTMLMediaElement, pause
> 05-05 11:25:27.520  6128  6128 I Gecko   : DD | AudioChannelService, unregister agent, type = 5
> 
> Set phone state
> 05-05 11:25:27.550  6128  6128 I Gecko   : DD | Am, SetPhoneState, state = 2

---

In Flame, the voice call module would be active after the AudioManager::SetPhoneState().
Therefore, I think we need the modifications in vendor's part, or ask someone familiar with the telephony to verify my assumption.

Comment 18

[Alastor Wu [:alwu]]

Here is the log in Flame.

> Voice call module is not active
> 05-05 11:39:23.136 30590 30590 D voice_extn: update_call_states is_call_active:0 in_call:0, mode:1
> 
> Stop ringtone 
> 05-05 11:39:23.236 32005 32005 I GeckoDump: DD | Gaia, _stopAlerting
> 05-05 11:39:23.236 32005 32005 I Gecko   : DD | AudioChannelService, unregister agent, type = 5
> 
> Set phone state
> 05-05 11:39:23.256 32005 32005 I Gecko   : DD | AudioManager::SetPhoneState, state = 2
> 
> Start voice call module
> 05-05 11:39:23.556 30590 30600 D voice_extn: update_calls: enter:
> 05-05 11:39:23.566 30590 30600 D voice_extn: update_calls: cur_state=1 new_state=2 vsid=10c01000
> 05-05 11:39:23.566 30590 30600 D voice_extn: update_calls: INACTIVE -> ACTIVE vsid:10c01000

Comment 19

[Vance Chen [:vchen][skype:vance.lucida][[e-mail]]]

ni Siiaceon

Comment 20

[jingmei.zhang]

Hi  Alastor,

I can get from my side that we should first to active voice call module or go to SetPhoneState is controled by platform side,not in vender.

So can you help to find someone who should be familiar with this part in gecko to check if we have stopped music first?

Comment 21

[Alastor Wu [:alwu]]

Hi, JingMei,
Sorry I don't understand what you mentioned.

My thought is, this behavior should not happen before we set the phone state, and it seems not controlled by Gecko. (maybe the modem?)
> Change the output device, 0x4 = headset
> 05-05 11:25:27.280   103   316 W audio_hw_primary: SetCall_ModePara successfully, device: earpice(Close),
>   headphone(Open), speaker(Close), Main_Mic(Close), Back_Mic(Close), hp_mic(Open)
> 05-05 11:25:27.280   103   316 W audio_hw_primary: SetVoice_gain_by_devices out, out_devices:0x4, 
>   in_devices:0x80000010

Comment 22

[Josh Cheng [:josh]]

Hi Vance,
Do we still care this bug? It seems to be POVB per comment 17.
Thanks!

Comment 23

[Vance Chen [:vchen][skype:vance.lucida][[e-mail]]]

No, partner already find some ways to workaround this at their end. Also now we have a Audio re-factoring, so this kind of problems should happened on 2.5 anymore