hychao can take a look when he gets back.

Found a racing case which is very likely causing this problem:

Jenny: could you take a look at this fix to see if it's reasonable?
https://codereview.chromium.org/2385113002

It is a known issue that we need to take care of the timing of dbus response because it always has a delay.
Also I don't think the SetOutputNodeVolume request could lost by CRAS because CrasAudioHandler defers query until cras service becomes available(in CrasAudioHandler::InitializeAudioState()), so we can remove the check.

#3, even though SetOutputNodeVolume request won't be lost by CRAS because CrasAudioHandler defers query until cras service becomes available(in CrasAudioHandler::InitializeAudioState()), the code itself should not cause the problem. It is just unnecessary cautious. Remove it is ok, but I doubt it will make any difference. 

The fundamental issue is chrome needs to differentiate the OutputVolumeChanged signal generated by automatic code, or from user action to decide if the volume slider should pop up. derat@'s suggestion for adding an additional parameter "automatic_change" and having it passed by from OutputVolumeChanged signal sounds like a good approach.

Ok, I spent more time investigating this problem and agree this is more complicate then I thought.
It seems easy to reproduce on my Peppy running on battery(note: if I plug AC then cannot reproduce).
The cause is the timing of CrasAudioHandler initialization and CRAS server discovering audio nodes for the first time.
The sequence I am seeing:
0. CRAS dbus service ready.
1. CrasAudioHandler::InitializeAudioState() called for the 1st time
2. CrasAudioHandler::InitializeAudioState() called for the 2nd time
3. CRAS notifies NodesChanged() because a new node is discovered. (speaker probably)
4. as a result of (3), CrasAudioHandler calls GetNodes().
5. CRAS notifies NodesChanged() because a new node is discovered. (internal mic probably)
6. as a result of (5), CrasAudioHandler calls GetNodes().

For (1), (2), (4), (6) step from above, they all try to set active node and its initial volume. But only (1) and (2) are guarded by the 'initializing_audio_state_' flag to avoid volume bar popping up.

If CRAS finishes discovering nodes before CrasAudioHandler init, then we're good without seeing volume bar at boot.

Besides making changes in CRAS API to support more complicated communication. I think this is a challenge to accurately define the 'init' scenario from other user initiated event.
For example, when user hot-plugs a USB headset the volume bar is popped because its preference volume is set. But if the USB headset is hot-plugged right after system boot, should we include it in the 'init' stage? 

One solution I could think about is to NOT show volume bar at hotplug node/volume change, and only show it when user changes volume by keyboard or mouse.
Or, probably easier, can we use some other signal to know that UI init/loading is complete so user don't feel offended seeing volume bar notification? or maybe just use a 1 second timeout?

I think the desired UX here would be:

a) Always display the volume bar when the user hits the volume keys or changes the output device via the system tray.
b) Always display the volume bar when the volume or muting state is automatically changed due to an output device being plugged or unplugged.
c) Never show the volume bar at boot when the user hasn't hit the keys or changed the output device.

I understand that b) and c) might be hard to reconcile if we can't tell whether an output change right after boot was caused by the user plugging/unplugging headphones vs. already-connected headphones being discovered. If we can't tell the difference, I think it's okay to never display the bar in response to output changes for ~5 seconds (or some other short period of time) after boot. Note that we still need to display it if the user presses the volume keys during this period, though.

I still feel like the most reliable way to do this is by making CRAS include a field in its signals describing why the change was made. Solutions revolving around Chrome counting the number of requests that it's sent and disregarding a corresponding number of signals are race-prone.

I agree with derat on comment#6 for desired UX. It is more reliable to add a reason code parameter in cras command for setting output volume and mute, and have cras signal carries back the value of the reason code, than to have chrome use heuristic to count the signals resulting from initialization. 

The difficulty for differentiating a hotplug vs discovering an existing node during cras server starts up is hard to resolve on chrome side. If we put a delay for cras initialization, the proper length of delay may vary on hardware platform. Will it be possible for cras to make the guess on cras side and send back a signal indicating the discovering process is done? Is there anyway cras can tell the difference between discovering an existing node vs a hotplug?

+1 agree with the desired UX.

And no I don't think there is a way to differentiate initial discovering and 'very early' hot-plug. Every node CRAS discovered at init is essentially a hot-plug.
The best we could do is to check 'node_type' field of hotplug_nodes in UI, and handle by their nature.
 - AUDIO_TYPE_INTERNAL_SPEAKER and AUDIO_TYPE_INTERNAL_MIC can never be hot-plugged.
 - AUDIO_TYPE_BLUETOOTH is always hot-plugged
 - For AUDIO_TYPE_HEADPHONE/MIC/USB types, always treat them as hot-plugged.

Base on what we have, I propose we do this:

1. CRAS extends API to carry a reason code.
2. UI uses, for example, reason codes: 'init', 'hot-plug', 'by-user' with set volume/mute commands base on the context and node type.
3. UI should never show volume bar for reason code 'init'
4. UI use a short timeout at initialization, during this period volume bar is shown only for reason code 'by-user'.
5. After the init timeout, volume bar will be shown for volume/mute change made with reason 'hot-plug' or 'by-user'.

Thoughts?
 

re #8:

Looks about right.  However I don't think we should ever display volume because of "hot-plug".  Can we instead do it off of device switch?  Since Chrome initiates the device change, we should be able to isolate that case.

Chrome now has a preference storing the last set volume of each node using the stabld_id passed by CRAS as key.
When node hot-plug happens and causes active node change, Chrome UI fetches the preference volume and apply to the new node. So it's not only because of 'hot-plug' but Chrome making volume change so the volume bar is displayed.
I think it makes sense to show volume bar in this scenario because user always sees new volume when switching output device.

So what we want to do is not display this during start up?  But it is going through the exact same path device plugged, chrome alerted, chrome sets volume, volume displayed.  Is that right?

Yes that is right. The paths are identical so CRAS basically can not tell the difference.
Currently Chrome UI sets up a flag at initialization to block volume bar from showing and clear it when CRAS respond with volume changed event. This solution turns out not perfect because CRAS also initializes and cause active node change at the same time.

I would prefer the easiest solution to use a 3-5 seconds timeout to block volume bar. But if user hits volume -/+ really fast after boot we still need to show volume bar, and that's why CRAS is asked to carry additional info in volume/mute set APIs.

Can you spell out the proposed API change?

A new API for "Set volume with a reason"?

This is what I have in mind:

Before:
  Method:
    void SetOutputNodeVolume(uint64 node_id, int32 volume)
  Signal:
    OutputNodeVolumeChanged(uint64 node_id, int32 volume)

After:
  Method:
    void SetOutputNodeVolume(uint64 node_id, int32 volume, int32 reason)
  Signal:
    OutputNodeVolumeChanged(uint64 node_id, int32 volume, int32 reason)

note:
We don't have a per node mute on Chrome OS, so we don't need to worry the mute state change.

Seems OK to me as long as the reason doesn't clutter the internal implementation too much.

comment#8 and #14, hychao, the proposal looks good to me. But I think it would make sense to add a reason code for mute state change as well, because the mute change would invoke the volume bar to pop up too. It does not matter if the change is per node or not.

Just to mention it, I saw the volume slider again on boot, on a ToT cyan device this time. :-P

Re #17, got it.
I'll work on the CRAS side changes.

 Issue 625222  has been merged into this issue.

I'm seeing this frequently when booting stable-channel devices now. Any progress on the CRAS work?

That's my fault, I didn't like the tagged message plan as it propagated changes through a ton of code.

Jenny, hychao, did we schedule a meeting for this?  If not can we do it before thanksgiving?

What's the status of this? I'm happy to schedule a meeting if that's the main thing holding up a fix. :-P

Dylan, Jenny and I had a meeting a few months ago. The conclusion is that Jenny will look at how to revise Chrome side implementation to work with existing CRAS side API.