New issue
Advanced search Search tips

Issue 914140 link

Starred by 1 user

Issue metadata

Status: Assigned
Owner:
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: Chrome
Pri: 1
Type: Bug



Sign in to add a comment

Bluetooth headphones reset to 50% volume every time they are (re-)connected

Project Member Reported by w...@chromium.org, Dec 11

Issue description

Chrome Version: 72.0.3609.3
OS: ChromeOS Fizz

What steps will reproduce the problem?
(1) Connect bluetooth headphones (mine are V-MODA Crossfade 2).
(2) Reduce volume to ~10%.
(3) Disconnect headphones.
(4) Reconnect them and check volume slider.

What is the expected result?

Expect that when re-connected, the volume slider is at 10% again.

What happens instead?

Volume slider always resets to 50% when the headphones re-connect, so if you forget and start audio playing, it is painfully loud!

This used to work; not sure when it regressed though, since I've not used Bluetooth headphones for some time with this system.
 
Owner: hychao@chromium.org
Status: Assigned (was: Untriaged)
Maybe an issue with the unique ID generated for the device causing the UI to think that it's a new device each time.
Looking in file://var/log/messages I notice:

2018-12-11T13:27:43.526150-08:00 ERR cras_server[1335]: AT command AT+BTRH? not supported
2018-12-11T13:27:43.588552-08:00 ERR cras_server[1335]: AT command AT+XAPL=0000-0000-0100,7 not supported
2018-12-11T13:27:43.681057-08:00 ERR cras_server[1335]: AT command AT+IPHONEACCEV=2,1,5,2,0 not supported
2018-12-11T13:27:43.791036-08:00 ERR cras_server[1335]: AT command AT+CSRSF=0,0,0,1,0,0,0 not supported
2018-12-11T13:27:44.103323-08:00 ERR bluetoothd[1683]: a2dp-sink profile connect failed for 20:9B:A5:5B:E2:56: Device or resource busy
2018-12-11T13:27:44.104132-08:00 ERR cras_server[1335]: Connect profile message replied error: org.bluez.Error.Failed
2018-12-11T13:27:45.855372-08:00 INFO kernel: [140722.711040] input: 20:9B:A5:5B:E2:56 as /devices/virtual/input/input12
2018-12-11T13:27:48.117249-08:00 ERR cras_server[1335]: Set absolute volume returned error: org.freedesktop.DBus.Error.UnknownProperty
2018-12-11T13:27:54.814388-08:00 ERR chapsd[734]: Attribute does not exist: 297
2018-12-11T13:27:57.903429-08:00 NOTICE kernel: [140734.757251] audit: type=1401 audit(1544563677.898:2385): op=setxattr invalid_context="u:object_r:cros_shm:s0"
2018-12-11T13:27:54.862671-08:00 ERR chapsd[734]: message repeated 5 times: [ Attribute does not exist: 297]
2018-12-11T13:27:59.749893-08:00 INFO bluetoothd[1683]: /org/bluez/hci0/dev_20_9B_A5_5B_E2_56/fd4: fd(26) ready
2018-12-11T13:27:59.759907-08:00 ERR cras_server[1335]: Set absolute volume returned error: org.freedesktop.DBus.Error.UnknownProperty
2018-12-11T13:28:05.018271-08:00 NOTICE kernel: [140741.874117] audit: type=1401 audit(1544563685.015:2386): op=setxattr invalid_context="u:object_r:cros_shm:s0"

in particular the "set absolute volume returned error" suggests that we're trying to use some protocol property that these headphones don't support..?
Ah, I also notice that this device (same MAC) appears as /devices/virtual/input/input{11,12,13} on successive re-connects - I'd expect that the /device/... path not be relevant to looking up the settings, though?
The "set absolute volume returned error" is due to the timing that two profiles A2DP and AVRCP setup in bluez.

AVRCP take cares the volume up/down and media play/pause buttons event.
And I guess the log you're seeing is due to headset didn't synchronize volume state immediate enough, so bluez thought the "volume" property wasn't ready.

I'd suspect your headset sends an volume=50% event to CRAS with a delay every time it re-connects.

Are you sure this is a regression? We changed nothing related to AVRCP on CRAS side for a long while, not sure if Bluez has uprev'ed recently.
Labels: -Type-Bug-Regression Type-Bug
Re #4: This is a different set of Bluetooth headphones to what I've used previously with these devices, so yes, it may be that it has different behaviour to the ones I've used before.

If I start music playing, then connect the headphones then I do see the volume UI show up, and the volume sets itself to the previously-set volume, before then setting itself to 50% after a short delay.

Is this strictly a bug in the headset firmware, or something that ChromeOS can/should work-around by e.g. ignoring set-absolute-volume for some brief period after connection?
Re #4: Actually, I've realised that the 50% volume change only happens shortly after I hit "play" in e.g. Play Music.  Immediately after re-connecting the headphones the volume is set correctly to the previously-configured volume.  Only after I actually start playing does it get forced to 50%
Good to know the finding per #6
Can you try below steps:

1. Reconnect BT headset (this should trigger volume bar show up)
2. Use keyboard vol up/down (F9/F10) to modify volume. 
3. Hit play button on BT headset, verify if the 50% force still occurs.

The purpose of (2) above is to make CRAS sends absolute volume changed event through AVRCP back to headset. I have a guess that BT headset has a cached volume value there.
Re #7: Tried the steps that you suggested:

1. Volume bar showed up as expected.
2. Volume bar showed F9/F10 affecting volume, as expected.
3. None of the headset buttons have any effect (neither the multifunction play/pause/skip button nor the volume buttons). /var/log/messages didn't show anything from my pressing them.

After #3 I did the following additional steps:

4. Hit the play button in Google Play Music. The volume immediately jumped to 50%.  I set the volume down to something bearable.
5. Stopped Google Play Music and waited for the playback hiss to stop, indicating that the audio pipeline was idle.
6. Pressed play again. This time the volume stayed where I'd set it.

Sign in to add a comment