bluez icon indicating copy to clipboard operation
bluez copied to clipboard
verified publisher icon bluez

[5.61] volume synchronisation failed

Open baybal opened this issue 4 years ago • 17 comments

I installed 5.60, and my volume sync stopped working with the pipewire. I have following in logs:

Aug 16 18:39:36 xps bluetoothd[16960]: profiles/audio/avctp.c:avctp_control_confirm() Control: Refusing unexpected connect
Aug 16 18:39:37 xps bluetoothd[16960]: profiles/audio/avctp.c:uinput_create() Can't open input device: No such file or directory (2)
Aug 16 18:39:37 xps bluetoothd[16960]: profiles/audio/avctp.c:init_uinput() AVRCP: failed to init uinput for GS

baybal avatar Aug 17 '21 09:08 baybal

Hi @baybal could you please check if you have CONFIG_INPUT_UINPUT=m in kernel?

i-garrison avatar Aug 17 '21 21:08 i-garrison

Not set! Is this the cause? Can we add a hint for this in the error output?

baybal avatar Aug 18 '21 03:08 baybal

It now registers button presses, but still no volume sync

Aug 18 13:03:27 xps dbus-daemon[5524]: [session uid=1000 pid=5522] Activating service name='org.blueman.Manager' requested by ':1.77' (uid=1000 pid=5813 comm="/usr/bin/python3.9 /usr/bin/blueman-applet ")
Aug 18 13:03:28 xps dbus-daemon[5524]: [session uid=1000 pid=5522] Successfully activated service 'org.blueman.Manager'
Aug 18 13:03:43 xps bluetoothd[2695]: profiles/audio/avctp.c:avctp_control_confirm() Control: Refusing unexpected connect
Aug 18 13:03:44 xps kernel: input: GS (AVRCP) as /devices/virtual/input/input24
Aug 18 13:03:44 xps elogind-daemon[2727]: Watching system buttons on /dev/input/event20 (GS (AVRCP))
Aug 18 13:03:58 xps bluetoothd[2695]: /org/bluez/hci0/dev_FC_58_FA_B0_4A_D2/sep1/fd2: fd(42) ready
^@^@^@^@^@^@^@^@^@^@^@^@

baybal avatar Aug 18 '21 04:08 baybal

I also recently updated to 5.13. Maybe it's because of that? I do remember it was working before.

baybal avatar Aug 18 '21 04:08 baybal 

static void avctp_control_confirm(struct avctp *session, GIOChannel *chan,
						struct btd_device *dev)
{
	const bdaddr_t *src;
	const bdaddr_t *dst;

	if (session->control != NULL) {
		error("Control: Refusing unexpected connect");
		g_io_channel_shutdown(chan, TRUE, NULL);

		/*
		 * Close AVCTP channel if remote tried connect
		 * at the same time
		 * AVRCP SPEC V1.5 4.1.1 Connection Establishment
		 */
		avctp_set_state(session, AVCTP_STATE_DISCONNECTED, -EAGAIN);
		return;
	}

	avctp_set_state(session, AVCTP_STATE_CONNECTING, 0);
	session->control = avctp_channel_create(session, chan, 2, NULL);

	src = btd_adapter_get_address(device_get_adapter(dev));
	dst = device_get_address(dev);

	session->auth_id = btd_request_authorization(src, dst,
							AVRCP_REMOTE_UUID,
							auth_cb, session);
	if (session->auth_id == 0)
		goto drop;

	session->control->watch = g_io_add_watch(chan, G_IO_ERR | G_IO_HUP |
						G_IO_NVAL, session_cb, session);
	return;

drop:
	avctp_set_state(session, AVCTP_STATE_DISCONNECTED, -EIO);
}

From where does that session->control comes from?

baybal avatar Aug 18 '21 04:08 baybal

@baybal there have been some fixes pushed for the volume sync:

https://git.kernel.org/pub/scm/bluetooth/bluez.git/commit/profiles/audio?id=44e1bcffcd491ae1e7d5904e44c9bc6d296d0093

Also check if there is any traffic ongoing, btw is this with PulseAudio or Pipewire?

Vudentz avatar Aug 19 '21 21:08 Vudentz

Pipewire

baybal avatar Aug 20 '21 11:08 baybal

@Vudentz still the same issue with A2DP volume on linux 5.14, pipewire 0.3.34, bluez 5.61. HFP volume sync works fine.

Still same avctp.c:avctp_control_confirm() Control: Refusing unexpected connect

baybal avatar Sep 05 '21 12:09 baybal

Update. I found out that this doesn't happen with my bluetooth stereo. Only the BT handsfree.

Maintainers please provide suggestions how to debug this.

Can it be that it's mSBC volume sync somehow conflicts with its A2DP volume sync?

baybal avatar Oct 06 '21 21:10 baybal

The Audio/Video Remote Control Profile (AVRCP) is often used in conjunction with A2DP for remote control on devices such as headphones, car audio systems, or stand-alone speaker units.

qiurui144 avatar Oct 09 '21 02:10 qiurui144

BTsnoop log dump.btsnoop.log

baybal avatar Oct 24 '21 01:10 baybal

in this log , volumechanged is fine when avrcp gets capabilities. can you get some input log by using "sudo libinput debug-events"

qiurui144 avatar Oct 25 '21 01:10 qiurui144 

-event21  DEVICE_ADDED     GS (AVRCP)                        seat0 default group13 cap:k
-event5   KEYBOARD_KEY     +33.252s	*** (-1) pressed
 event5   KEYBOARD_KEY     +33.416s	*** (-1) released
 event5   KEYBOARD_KEY     +33.434s	*** (-1) released
-event21  KEYBOARD_KEY     +36.214s	KEY_PREVIOUSSONG (165) pressed
 event21  KEYBOARD_KEY     +36.279s	KEY_PREVIOUSSONG (165) released
 event21  KEYBOARD_KEY     +36.782s	KEY_PREVIOUSSONG (165) pressed
 event21  KEYBOARD_KEY     +36.852s	KEY_PREVIOUSSONG (165) released
 event21  KEYBOARD_KEY     +38.322s	KEY_NEXTSONG (163) pressed
 event21  KEYBOARD_KEY     +38.345s	KEY_NEXTSONG (163) released
 event21  KEYBOARD_KEY     +39.039s	KEY_NEXTSONG (163) pressed
 event21  KEYBOARD_KEY     +39.099s	KEY_NEXTSONG (163) released
 event21  KEYBOARD_KEY     +42.687s	KEY_PLAYCD (200) pressed
 event21  KEYBOARD_KEY     +42.724s	KEY_PLAYCD (200) released
 event21  KEYBOARD_KEY     +43.792s	KEY_PAUSECD (201) pressed
 event21  KEYBOARD_KEY     +43.843s	KEY_PAUSECD (201) released
 event21  KEYBOARD_KEY     +45.647s	KEY_PLAYCD (200) pressed
 event21  KEYBOARD_KEY     +45.654s	KEY_PLAYCD (200) released
 event21  KEYBOARD_KEY     +46.895s	KEY_PAUSECD (201) pressed
 event21  KEYBOARD_KEY     +46.903s	KEY_PAUSECD (201) released
 event21  KEYBOARD_KEY     +48.395s	KEY_PREVIOUSSONG (165) pressed
 event21  KEYBOARD_KEY     +48.403s	KEY_PREVIOUSSONG (165) released
 event21  KEYBOARD_KEY     +51.887s	KEY_NEXTSONG (163) pressed
 event21  KEYBOARD_KEY     +51.925s	KEY_NEXTSONG (163) released
-event5   KEYBOARD_KEY     +62.431s	*** (-1) pressed
 event5   KEYBOARD_KEY     +62.566s	*** (-1) pressed

@qiurui144 why do you think the debug output avctp.c:avctp_control_confirm() Control: Refusing unexpected connect comes out?

baybal avatar Nov 01 '21 23:11 baybal

1635816109(1)

qiurui144 avatar Nov 02 '21 01:11 qiurui144

i think the logs of btsnoop\libpinput\kernel that are at the same time are neccessary

qiurui144 avatar Nov 02 '21 01:11 qiurui144

I hava a similar log on headset init:

May  2 22:50:03 node-calculate2 bluetoothd[4279]: profiles/audio/avctp.c:uinput_create() Can't open input device: No such file or directory (2)
May  2 22:50:03 node-calculate2 bluetoothd[4279]: profiles/audio/avctp.c:init_uinput() AVRCP: failed to init uinput for MAJOR IV
May  2 22:50:03 node-calculate2 bluetoothd[4279]: sdp_extract_attr: Unknown data descriptor : 0x6 terminating

kuraga avatar May 02 '22 19:05 kuraga

Edit: My issue is solved after updating (which upgraded kernel-firmware-bluetooth 20220509-1.1 -> 20220516-1.1) and then restarting bluetoothd. See https://forums.opensuse.org/showthread.php/570146-Bluetooth-speaker-connects-but-no-longer-appears-as-audio-device

Original post:

Similarly here:

❯ journalctl -b -t bluetoothd                                                                                                                                                                                                                                                                   0.75  74%  866.7 Mbps ─╯
Mai 19 15:32:27 felicity bluetoothd[1547]: Bluetooth daemon 5.64
Mai 19 15:32:27 felicity bluetoothd[1547]: Starting SDP server
Mai 19 15:32:27 felicity bluetoothd[1547]: Bluetooth management interface 1.21 initialized
Mai 19 15:32:29 felicity bluetoothd[1547]: Admin Policy Set interface registered
Mai 19 15:32:29 felicity bluetoothd[1547]: Admin Policy Status interface registered
Mai 19 15:33:33 felicity bluetoothd[1547]: Failed to set mode: Failed (0x03)
Mai 19 15:33:35 felicity bluetoothd[1547]: src/profile.c:ext_start_servers() RFCOMM server failed for Headset unit: rfcomm_bind: Address already in use (98)
Mai 19 15:33:35 felicity bluetoothd[1547]: src/profile.c:ext_start_servers() RFCOMM server failed for Hands-Free Voice gateway: rfcomm_bind: Address already in use (98)
Mai 19 15:33:35 felicity bluetoothd[1547]: Player registered: sender=:1.88 path=/media_player0
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.88 path=/MediaEndpoint/A2DPSource/ldac
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.88 path=/MediaEndpoint/A2DPSource/aac
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.88 path=/MediaEndpoint/A2DPSink/sbc
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.88 path=/MediaEndpoint/A2DPSource/sbc
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.88 path=/MediaEndpoint/A2DPSink/sbc_xq
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.88 path=/MediaEndpoint/A2DPSource/sbc_xq
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.88 path=/MediaEndpoint/A2DPSource/faststream
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.88 path=/MediaEndpoint/A2DPSource/faststream_duplex
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.85 path=/MediaEndpoint/A2DPSource/ldac_hq
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.85 path=/MediaEndpoint/A2DPSource/ldac_sq
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.85 path=/MediaEndpoint/A2DPSource/ldac_mq
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.85 path=/MediaEndpoint/A2DPSink/sbc
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.85 path=/MediaEndpoint/A2DPSource/sbc
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.85 path=/MediaEndpoint/A2DPSink/sbc_xq_453
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.85 path=/MediaEndpoint/A2DPSource/sbc_xq_453
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.85 path=/MediaEndpoint/A2DPSink/sbc_xq_512
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.85 path=/MediaEndpoint/A2DPSource/sbc_xq_512
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.85 path=/MediaEndpoint/A2DPSink/sbc_xq_552
Mai 19 15:33:35 felicity bluetoothd[1547]: Endpoint registered: sender=:1.85 path=/MediaEndpoint/A2DPSource/sbc_xq_552
Mai 19 15:45:13 felicity bluetoothd[1547]: profiles/audio/avctp.c:uinput_create() Can't open input device: No such file or directory (2)
Mai 19 15:45:13 felicity bluetoothd[1547]: profiles/audio/avctp.c:init_uinput() AVRCP: failed to init uinput for  wm CUBE mini
Mai 19 15:55:32 felicity bluetoothd[1547]: profiles/audio/avctp.c:uinput_create() Can't open input device: No such file or directory (2)
Mai 19 15:55:32 felicity bluetoothd[1547]: profiles/audio/avctp.c:init_uinput() AVRCP: failed to init uinput for  wm CUBE mini
Mai 19 15:55:42 felicity bluetoothd[1547]: No matching connection for device
Mai 19 15:55:54 felicity bluetoothd[1547]: profiles/audio/avctp.c:uinput_create() Can't open input device: No such file or directory (2)
Mai 19 15:55:54 felicity bluetoothd[1547]: profiles/audio/avctp.c:init_uinput() AVRCP: failed to init uinput for  wm CUBE mini
Mai 19 15:56:22 felicity bluetoothd[1547]: profiles/audio/avctp.c:uinput_create() Can't open input device: No such file or directory (2)
Mai 19 15:56:22 felicity bluetoothd[1547]: profiles/audio/avctp.c:init_uinput() AVRCP: failed to init uinput for  wm CUBE mini
Mai 19 16:50:46 felicity bluetoothd[1547]: profiles/audio/avctp.c:uinput_create() Can't open input device: No such file or directory (2)
Mai 19 16:50:46 felicity bluetoothd[1547]: profiles/audio/avctp.c:init_uinput() AVRCP: failed to init uinput for  wm CUBE mini

OpenSUSE tumbleweed snapshot 20220322-1.2

❯ zypper se -si bluetooth                                                                                                                                                                                                                                                                       0.84  75%  433.3 Mbps ─╯
Repository-Daten werden geladen...
Installierte Pakete werden gelesen...

S  | Name                        | Type  | Version         | Arch   | Repository
---+-----------------------------+-------+-----------------+--------+----------------------
i+ | kernel-firmware-bluetooth   | Paket | 20220509-1.1    | noarch | Main Repository (OSS)
i+ | kernel-firmware-bluetooth   | Paket | 20220509-1.1    | noarch | openSUSE:Tumbleweed
i+ | libQt5Bluetooth5            | Paket | 5.15.2+kde5-1.3 | x86_64 | Main Repository (OSS)
i+ | libQt5Bluetooth5            | Paket | 5.15.2+kde5-1.3 | x86_64 | openSUSE:Tumbleweed
i+ | libQt5Bluetooth5-imports    | Paket | 5.15.2+kde5-1.3 | x86_64 | Main Repository (OSS)
i+ | libQt5Bluetooth5-imports    | Paket | 5.15.2+kde5-1.3 | x86_64 | openSUSE:Tumbleweed
i+ | libbluetooth3               | Paket | 5.64-2.3        | x86_64 | Main Repository (OSS)
i+ | libbluetooth3               | Paket | 5.64-2.3        | x86_64 | openSUSE:Tumbleweed
i  | libbluetooth3-32bit         | Paket | 5.64-2.3        | x86_64 | Main Repository (OSS)
i  | libbluetooth3-32bit         | Paket | 5.64-2.3        | x86_64 | openSUSE:Tumbleweed
i+ | pulseaudio-module-bluetooth | Paket | 15.0-10.3       | x86_64 | Main Repository (OSS)
i+ | pulseaudio-module-bluetooth | Paket | 15.0-10.3       | x86_64 | openSUSE:Tumbleweed

❯ zypper se -si bluez                                                                                                                                                                                                                                                                           0.81  75%  433.3 Mbps ─╯
Repository-Daten werden geladen...
Installierte Pakete werden gelesen...

S  | Name             | Type  | Version    | Arch   | Repository
---+------------------+-------+------------+--------+----------------------
i+ | bluez            | Paket | 5.64-2.3   | x86_64 | Main Repository (OSS)
i+ | bluez            | Paket | 5.64-2.3   | x86_64 | openSUSE:Tumbleweed
i+ | bluez-qt-imports | Paket | 5.94.0-1.1 | x86_64 | Main Repository (OSS)
i+ | bluez-qt-imports | Paket | 5.94.0-1.1 | x86_64 | openSUSE:Tumbleweed
i+ | bluez-qt-udev    | Paket | 5.94.0-1.1 | x86_64 | Main Repository (OSS)
i+ | bluez-qt-udev    | Paket | 5.94.0-1.1 | x86_64 | openSUSE:Tumbleweed
i+ | libKF5BluezQt6   | Paket | 5.94.0-1.1 | x86_64 | Main Repository (OSS)
i+ | libKF5BluezQt6   | Paket | 5.94.0-1.1 | x86_64 | openSUSE:Tumbleweed

LeoniePhiline avatar May 19 '22 16:05 LeoniePhiline