Bug 92102 - cannot select a2dp profile
Summary: cannot select a2dp profile
Status: RESOLVED MOVED
Alias: None
Product: PulseAudio
Classification: Unclassified
Component: modules (show other bugs)
Version: unspecified
Hardware: Other All
: high normal
Assignee: pulseaudio-bugs
QA Contact: pulseaudio-bugs
URL:
Whiteboard:
Keywords: regression
Depends on:
Blocks:
 
Reported: 2015-09-24 12:27 UTC by Fabrice Bellet
Modified: 2018-07-30 10:36 UTC (History)
29 users (show)

See Also:
i915 platform:
i915 features:


Attachments
btmon log of attempt to connect and automatically use a2dp_sink profile. (76.00 KB, text/x-log)
2016-11-25 06:22 UTC, Elias E. del Real
Details
bluetoothd.log (50.20 KB, text/plain)
2017-03-21 12:25 UTC, crocket
Details
bluetooth-headset_head_unit.log (37.82 KB, text/x-log)
2017-03-21 13:27 UTC, crocket
Details
journalctl log of "automatic" headset connection (605 bytes, text/plain)
2017-11-20 17:29 UTC, Sergey
Details
pactl-subscribe log of "automatic" headset connection (934 bytes, text/x-log)
2017-11-20 17:29 UTC, Sergey
Details
btmon log of "automatic" headset connection (138.89 KB, text/plain)
2017-11-20 17:30 UTC, Sergey
Details
journalctl log of manual headset connection (416 bytes, text/x-log)
2017-11-20 17:31 UTC, Sergey
Details
pactl-subscribe log of manual headset connection (392 bytes, text/x-log)
2017-11-20 17:32 UTC, Sergey
Details
btmon log of manual headset connection (123.10 KB, text/x-log)
2017-11-20 17:32 UTC, Sergey
Details

Description Fabrice Bellet 2015-09-24 12:27:49 UTC
This bug is very similar to #87081, with the difference that the proposed commit doesn't work for me, and PA never sees the message "dbus: interface=org.bluez.MediaEndpoint1, path=/MediaEndpoint/A2DPSource, member=SelectConfiguration"

I'm running Fedora 22, with bluez-5.29, and pulseaudio from current git (tag v7.0) compiled from source. I'm using a Sony DR-BT21G headset.

The device is initially paired/trusted in bluetoothctl. I'm running bluetoothd with debug output enabled in a first terminal : /usr/libexec/bluetooth/bluetoothd -n -d. I'm running bluetoothctl in another term, and LD_LIBRARY_PATH=/tmp/install/lib LD_BIND_NOW=1  /tmp/install/bin/pulseaudio -vv in a 3rd term.

I compiled pulseaudio with the following configuration options, that pretty much matche those from the regular Fedora rpm package : ./configure --disable-silent-rules --disable-static --disable-rpath --with-system-user=pulse --with-system-group=pulse --with-access-group=pulse-access --disable-oss-output --disable-jack --disable-lirc --disable-bluez4 --enable-bluez5 --disable-systemd-daemon --prefix /tmp/install

* When powering on the headset on, bluetoothd logs:

bluetoothd[29282]: src/adapter.c:connected_callback() hci0 device 00:1A:80:91:72:05 connected eir_len 15
bluetoothd[29282]: src/profile.c:ext_confirm() incoming connect from 00:1A:80:91:72:05
bluetoothd[29282]: src/service.c:btd_service_ref() 0x55fe57a10240: ref=2
bluetoothd[29282]: src/profile.c:ext_confirm() Headset Voice gateway authorizing connection from 00:1A:80:91:72:05
bluetoothd[29282]: src/profile.c:ext_auth() 00:1A:80:91:72:05 authorized to connect to Headset Voice gateway
bluetoothd[29282]: src/profile.c:ext_connect() Headset Voice gateway connected to 00:1A:80:91:72:05
bluetoothd[29282]: src/service.c:change_state() 0x55fe57a10240: device 00:1A:80:91:72:05 profile Headset Voice gateway state changed: disconnected -> connected (0)
bluetoothd[29282]: src/service.c:btd_service_ref() 0x55fe57a10240: ref=3
bluetoothd[29282]: plugins/policy.c:service_cb() Added Headset Voice gateway reconnect 0


* in pulseaudio logs:

: [pulseaudio] bluez5-util.c: Properties changed in device /org/bluez/hci0/dev_00_1A_80_91_72_05
D: [pulseaudio] backend-native.c: dbus: path=/Profile/HSPAGProfile, interface=org.bluez.Profile1, member=NewConnection
D: [pulseaudio] backend-native.c: dbus: NewConnection path=/org/bluez/hci0/dev_00_1A_80_91_72_05, fd=20
D: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd20 state changed from disconnected to idle
D: [pulseaudio] module-bluez5-discover.c: Loading module-bluez5-device path=/org/bluez/hci0/dev_00_1A_80_91_72_05
I: [pulseaudio] module-card-restore.c: Restored profile 'a2dp_sink' for card bluez_card.00_1A_80_91_72_05.
I: [pulseaudio] module-card-restore.c: Restoring port latency offsets for card bluez_card.00_1A_80_91_72_05.
I: [pulseaudio] card.c: Created 1 "bluez_card.00_1A_80_91_72_05"
W: [pulseaudio] module-bluez5-device.c: Profile has no transport
D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
I: [pulseaudio] card.c: Changed profile of card 1 "bluez_card.00_1A_80_91_72_05" to off
I: [pulseaudio] module.c: Loaded "module-bluez5-device" (index: #25; argument: "path=/org/bluez/hci0/dev_00_1A_80_91_72_05").
D: [pulseaudio] backend-native.c: Transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd20 available for profile headset_head_unit

* in bluetoothctl:

[CHG] Device 00:1A:80:91:72:05 Connected: yes
[DR-BT21G]# info
Device 00:1A:80:91:72:05
	Name: DR-BT21G
	Alias: DR-BT21G
	Class: 0x240408
	Icon: audio-card
	Paired: yes
	Trusted: yes
	Blocked: no
	Connected: yes
	LegacyPairing: no
	UUID: Headset                   (00001108-0000-1000-8000-00805f9b34fb)
	UUID: Audio Sink                (0000110b-0000-1000-8000-00805f9b34fb)
	UUID: A/V Remote Control        (0000110e-0000-1000-8000-00805f9b34fb)
	UUID: Handsfree                 (0000111e-0000-1000-8000-00805f9b34fb)

* at this moment, the A2DP profile is _not_ available in pulseaudio, and cannot be switched to:

$ pactl list | grep -C2 A2D
	Profiles:
		headset_head_unit: Headset Head Unit (HSP/HFP) (sinks: 1, sources: 1, priority: 20, available: yes)
		a2dp_sink: High Fidelity Playback (A2DP Sink) (sinks: 1, sources: 0, priority: 10, available: no)
		off: Off (sinks: 0, sources: 0, priority: 0, available: yes)
	Active Profile: off

$ pacmd set-card-profile bluez_card.00_1A_80_91_72_05 a2dp_sink
Failed to set card profile to 'a2dp_sink'.

* to make profile A2DP available, I need to *connect* again to the device in bluetoothctl :

[DR-BT21G]# connect 00:1A:80:91:72:05
Attempting to connect to 00:1A:80:91:72:05
Connection successful

* in bluetoothd logs:

bluetoothd[29282]: src/device.c:connect_profiles() /org/bluez/hci0/dev_00_1A_80_91_72_05 (all), client :1.3792
bluetoothd[29282]: profiles/audio/a2dp.c:a2dp_sink_connect() path /org/bluez/hci0/dev_00_1A_80_91_72_05
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_ref() 0x55fe57a163e0: ref=1
bluetoothd[29282]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci0/dev_00_1A_80_91_72_05: SINK_STATE_DISCONNECTED -> SINK_STATE_CONNECTING
bluetoothd[29282]: profiles/audio/sink.c:sink_connect() stream creation in progress
bluetoothd[29282]: src/service.c:change_state() 0x55fe57a0b1c0: device 00:1A:80:91:72:05 profile a2dp-sink state changed: disconnected -> connecting (0)
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP: connected signaling channel to 00:1A:80:91:72:05
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP imtu=672, omtu=895
bluetoothd[29282]: profiles/audio/avdtp.c:session_cb() 
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_parse_resp() DISCOVER request succeeded
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 1 type 1 media 0 in use 0
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 2 type 1 media 0 in use 0
bluetoothd[29282]: profiles/audio/avdtp.c:session_cb() 
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 1 type 1 media 0
bluetoothd[29282]: profiles/audio/avdtp.c:session_cb() 
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 2 type 1 media 0
bluetoothd[29282]: profiles/audio/sink.c:discovery_complete() Discovery complete
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_ref() 0x55fe57a163e0: ref=2
bluetoothd[29282]: profiles/audio/a2dp.c:setup_ref() 0x55fe57a08890: ref=1
bluetoothd[29282]: profiles/audio/media.c:media_endpoint_async_call() Calling SelectConfiguration: name = :1.3793 path = /MediaEndpoint/A2DPSource
bluetoothd[29282]: profiles/audio/a2dp.c:a2dp_config() a2dp_config: selected SEP 0x55fe579f71b0
bluetoothd[29282]: profiles/audio/a2dp.c:setup_ref() 0x55fe57a08890: ref=2
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_set_configuration() 0x55fe57a163e0: int_seid=1, acp_seid=1
bluetoothd[29282]: profiles/audio/a2dp.c:setup_unref() 0x55fe57a08890: ref=1
bluetoothd[29282]: profiles/audio/avdtp.c:session_cb() 
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_parse_resp() SET_CONFIGURATION request succeeded
bluetoothd[29282]: profiles/audio/a2dp.c:setconf_cfm() Source 0x55fe579f71b0: Set_Configuration_Cfm
bluetoothd[29282]: profiles/audio/media.c:media_endpoint_async_call() Calling SetConfiguration: name = :1.3793 path = /MediaEndpoint/A2DPSource
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed: IDLE -> CONFIGURED
bluetoothd[29282]: profiles/audio/transport.c:media_owner_create() Owner created: sender=:1.3793
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_ref() 0x55fe57a163e0: ref=3
bluetoothd[29282]: profiles/audio/a2dp.c:a2dp_sep_lock() SEP 0x55fe579f71b0 locked
bluetoothd[29282]: profiles/audio/a2dp.c:setup_ref() 0x55fe57a08890: ref=2
bluetoothd[29282]: profiles/audio/transport.c:transport_set_state() State changed /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0: TRANSPORT_STATE_IDLE -> TRANSPORT_STATE_REQUESTING
bluetoothd[29282]: profiles/audio/transport.c:media_request_create() Request created: method=Acquire id=3
bluetoothd[29282]: profiles/audio/transport.c:media_owner_add() Owner :1.3793 Request Acquire
bluetoothd[29282]: profiles/audio/transport.c:media_transport_set_owner() Transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0 Owner :1.3793
bluetoothd[29282]: profiles/audio/avdtp.c:session_cb() 
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_parse_resp() OPEN request succeeded
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP: connected transport channel to 00:1A:80:91:72:05
bluetoothd[29282]: profiles/audio/avdtp.c:handle_transport_connect() Flushable packets enabled
bluetoothd[29282]: profiles/audio/avdtp.c:handle_transport_connect() sk 33, omtu 895, send buffer size 106496
bluetoothd[29282]: profiles/audio/a2dp.c:open_cfm() Source 0x55fe579f71b0: Open_Cfm
bluetoothd[29282]: profiles/audio/a2dp.c:setup_unref() 0x55fe57a08890: ref=1
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed: CONFIGURED -> OPEN
bluetoothd[29282]: src/service.c:change_state() 0x55fe57a0b1c0: device 00:1A:80:91:72:05 profile a2dp-sink state changed: connecting -> connected (0)
bluetoothd[29282]: src/device.c:device_profile_connected() a2dp-sink Success (0)
bluetoothd[29282]: src/device.c:device_profile_connected() returning response to :1.3792
bluetoothd[29282]: plugins/policy.c:policy_connect() /org/bluez/hci0/dev_00_1A_80_91_72_05 profile avrcp-controller
bluetoothd[29282]: profiles/audio/avrcp.c:avrcp_connect() path /org/bluez/hci0/dev_00_1A_80_91_72_05
bluetoothd[29282]: profiles/audio/avctp.c:avctp_set_state() AVCTP Connecting
bluetoothd[29282]: src/service.c:change_state() 0x55fe57a0c870: device 00:1A:80:91:72:05 profile avrcp-controller state changed: disconnected -> connecting (0)
bluetoothd[29282]: src/service.c:btd_service_ref() 0x55fe57a0b1c0: ref=3
bluetoothd[29282]: plugins/policy.c:service_cb() Added a2dp-sink reconnect 0
bluetoothd[29282]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci0/dev_00_1A_80_91_72_05: SINK_STATE_CONNECTING -> SINK_STATE_CONNECTED
bluetoothd[29282]: profiles/audio/transport.c:transport_update_playing() /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0 State=TRANSPORT_STATE_REQUESTING Playing=0
bluetoothd[29282]: src/device.c:search_cb() 00:1A:80:91:72:05: No service update
bluetoothd[29282]: src/device.c:device_svc_resolved() /org/bluez/hci0/dev_00_1A_80_91_72_05 err 0
bluetoothd[29282]: profiles/audio/avdtp.c:session_cb() 
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_parse_resp() START request succeeded
bluetoothd[29282]: profiles/audio/a2dp.c:start_cfm() Source 0x55fe579f71b0: Start_Cfm
bluetoothd[29282]: /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0: fd(33) ready
bluetoothd[29282]: profiles/audio/transport.c:media_owner_remove() Owner :1.3793 Request Acquire
bluetoothd[29282]: profiles/audio/transport.c:transport_set_state() State changed /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0: TRANSPORT_STATE_REQUESTING -> TRANSPORT_STATE_ACTIVE
bluetoothd[29282]: profiles/audio/a2dp.c:setup_unref() 0x55fe57a08890: ref=0
bluetoothd[29282]: profiles/audio/a2dp.c:setup_free() 0x55fe57a08890
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_unref() 0x55fe57a163e0: ref=2
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed: OPEN -> STREAMING
bluetoothd[29282]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci0/dev_00_1A_80_91_72_05: SINK_STATE_CONNECTED -> SINK_STATE_PLAYING
bluetoothd[29282]: profiles/audio/transport.c:transport_update_playing() /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0 State=TRANSPORT_STATE_ACTIVE Playing=1
bluetoothd[29282]: profiles/audio/avctp.c:avctp_connect_cb() AVCTP: connected to 00:1A:80:91:72:05
bluetoothd[29282]: profiles/audio/avctp.c:init_uinput() AVRCP: uinput initialized for 00:1A:80:91:72:05
bluetoothd[29282]: profiles/audio/avrcp.c:target_init() 0x55fe57a01e60 version 0x0100
bluetoothd[29282]: src/service.c:change_state() 0x55fe57a0c870: device 00:1A:80:91:72:05 profile avrcp-controller state changed: connecting -> connected (0)
bluetoothd[29282]: src/device.c:device_profile_connected() avrcp-controller Success (0)
bluetoothd[29282]: profiles/audio/avctp.c:avctp_set_state() AVCTP Connected
bluetoothd[29282]: profiles/audio/transport.c:transport_set_state() State changed /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0: TRANSPORT_STATE_ACTIVE -> TRANSPORT_STATE_SUSPENDING
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_ref() 0x55fe57a163e0: ref=3
bluetoothd[29282]: profiles/audio/a2dp.c:setup_ref() 0x55fe57a2a3d0: ref=1
bluetoothd[29282]: profiles/audio/transport.c:media_request_create() Request created: method=Release id=4
bluetoothd[29282]: profiles/audio/transport.c:media_owner_add() Owner :1.3793 Request Release
bluetoothd[29282]: profiles/audio/avdtp.c:session_cb() 
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_parse_resp() SUSPEND request succeeded
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed: STREAMING -> OPEN
bluetoothd[29282]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci0/dev_00_1A_80_91_72_05: SINK_STATE_PLAYING -> SINK_STATE_CONNECTED
bluetoothd[29282]: profiles/audio/transport.c:transport_update_playing() /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0 State=TRANSPORT_STATE_SUSPENDING Playing=0
bluetoothd[29282]: profiles/audio/a2dp.c:suspend_cfm() Source 0x55fe579f71b0: Suspend_Cfm
bluetoothd[29282]: profiles/audio/transport.c:media_request_reply() Request Release Reply Success
bluetoothd[29282]: profiles/audio/transport.c:media_owner_remove() Owner :1.3793 Request Release
bluetoothd[29282]: profiles/audio/a2dp.c:a2dp_sep_unlock() SEP 0x55fe579f71b0 unlocked
bluetoothd[29282]: profiles/audio/transport.c:transport_set_state() State changed /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0: TRANSPORT_STATE_SUSPENDING -> TRANSPORT_STATE_IDLE
bluetoothd[29282]: profiles/audio/transport.c:media_transport_remove_owner() Transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0 Owner :1.3793
bluetoothd[29282]: profiles/audio/transport.c:media_owner_free() Owner :1.3793
bluetoothd[29282]: profiles/audio/a2dp.c:setup_unref() 0x55fe57a2a3d0: ref=0
bluetoothd[29282]: profiles/audio/a2dp.c:setup_free() 0x55fe57a2a3d0
bluetoothd[29282]: profiles/audio/avdtp.c:avdtp_unref() 0x55fe57a163e0: ref=2

* in pulseaudio logs :

I: [pulseaudio] client.c: Created 5 "Login Session 847"
D: [pulseaudio] module-systemd-login.c: Added new session 847
D: [pulseaudio] module-systemd-login.c: Removing session 847
I: [pulseaudio] client.c: Freed 5 "Login Session 847"
D: [pulseaudio] bluez5-util.c: dbus: path=/MediaEndpoint/A2DPSource, interface=org.bluez.MediaEndpoint1, member=SelectConfiguration
D: [pulseaudio] bluez5-util.c: Unknown interface org.freedesktop.DBus.Introspectable found, skipping
D: [pulseaudio] bluez5-util.c: Unknown interface org.bluez.MediaTransport1 found, skipping
D: [pulseaudio] bluez5-util.c: Unknown interface org.freedesktop.DBus.Properties found, skipping
D: [pulseaudio] bluez5-util.c: dbus: path=/MediaEndpoint/A2DPSource, interface=org.bluez.MediaEndpoint1, member=SetConfiguration
D: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0 state changed from disconnected to idle
D: [pulseaudio] card.c: Setting card bluez_card.00_1A_80_91_72_05 profile a2dp_sink to availability status unknown
I: [pulseaudio] module-card-restore.c: Card bluez_card.00_1A_80_91_72_05 profile a2dp_sink became available, activating.
D: [pulseaudio] module-bluez5-device.c: Acquiring transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0
I: [pulseaudio] module-bluez5-device.c: Transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0 acquired: fd 27
I: [pulseaudio] module-bluez5-device.c: SBC parameters: allocation=0, subbands=1, blocks=3, bitpool=53
I: [pulseaudio] sink.c: Created sink 1 "bluez_sink.00_1A_80_91_72_05" with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: [pulseaudio] sink.c:     bluetooth.protocol = "a2dp_sink"
I: [pulseaudio] sink.c:     device.description = "DR-BT21G"
I: [pulseaudio] sink.c:     device.string = "00:1A:80:91:72:05"
I: [pulseaudio] sink.c:     device.api = "bluez"
I: [pulseaudio] sink.c:     device.class = "sound"
I: [pulseaudio] sink.c:     device.bus = "bluetooth"
I: [pulseaudio] sink.c:     device.form_factor = "hands-free"
I: [pulseaudio] sink.c:     bluez.path = "/org/bluez/hci0/dev_00_1A_80_91_72_05"
I: [pulseaudio] sink.c:     bluez.class = "0x240408"
I: [pulseaudio] sink.c:     bluez.alias = "DR-BT21G"
I: [pulseaudio] sink.c:     device.icon_name = "audio-handsfree-bluetooth"
I: [pulseaudio] sink.c:     device.intended_roles = "phone"
I: [pulseaudio] source.c: Created source 2 "bluez_sink.00_1A_80_91_72_05.monitor" with sample spec s16le 2ch 44100Hz and channel map front-left,front-right
I: [pulseaudio] source.c:     device.description = "Monitor of DR-BT21G"
I: [pulseaudio] source.c:     device.class = "monitor"
I: [pulseaudio] source.c:     device.string = "00:1A:80:91:72:05"
I: [pulseaudio] source.c:     device.api = "bluez"
I: [pulseaudio] source.c:     device.bus = "bluetooth"
I: [pulseaudio] source.c:     device.form_factor = "hands-free"
I: [pulseaudio] source.c:     bluez.path = "/org/bluez/hci0/dev_00_1A_80_91_72_05"
I: [pulseaudio] source.c:     bluez.class = "0x240408"
I: [pulseaudio] source.c:     bluez.alias = "DR-BT21G"
I: [pulseaudio] source.c:     device.icon_name = "audio-handsfree-bluetooth"
I: [pulseaudio] source.c:     device.intended_roles = "phone"
D: [bluetooth] module-bluez5-device.c: IO Thread starting up
D: [bluetooth] core-util.c: SCHED_RR|SCHED_RESET_ON_FORK worked.
I: [bluetooth] core-util.c: Successfully enabled SCHED_RR scheduling for thread, with priority 5.
I: [bluetooth] module-bluez5-device.c: Transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0 resuming
D: [bluetooth] module-bluez5-device.c: Stream properly set up, we're ready to roll!
D: [bluetooth] module-bluez5-device.c: Using SBC encoder implementation: MMX
D: [pulseaudio] module-device-restore.c: Could not set format on sink bluez_sink.00_1A_80_91_72_05
D: [pulseaudio] module-bluetooth-policy.c: Profile a2dp_sink cannot be selected for loopback
D: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.00_1A_80_91_72_05 becomes idle, timeout in 5 seconds.
D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
I: [pulseaudio] card.c: Changed profile of card 1 "bluez_card.00_1A_80_91_72_05" to a2dp_sink
I: [pulseaudio] module-card-restore.c: Storing card profile for card bluez_card.00_1A_80_91_72_05.
D: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0 available for profile a2dp_sink
D: [pulseaudio] bluez5-util.c: Properties changed in transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0
D: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0 state changed from idle to playing
D: [pulseaudio] card.c: Setting card bluez_card.00_1A_80_91_72_05 profile a2dp_sink to availability status yes
I: [pulseaudio] module-card-restore.c: Card bluez_card.00_1A_80_91_72_05 profile a2dp_sink became available, activating.
D: [pulseaudio] device-port.c: Setting port handsfree-output to status yes
D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
D: [pulseaudio] module-bluez5-device.c: Resuming sink bluez_sink.00_1A_80_91_72_05 because its transport state changed to playing
I: [pulseaudio] module-suspend-on-idle.c: Sink bluez_sink.00_1A_80_91_72_05 idle for too long, suspending ...
D: [pulseaudio] sink.c: Suspend cause of sink bluez_sink.00_1A_80_91_72_05 is 0x0004, suspending
D: [bluetooth] module-bluez5-device.c: Releasing transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0
I: [bluetooth] bluez5-util.c: Transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0 released
D: [bluetooth] module-bluez5-device.c: Audio stream torn down
D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.
D: [pulseaudio] bluez5-util.c: Properties changed in transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0
D: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_00_1A_80_91_72_05/fd0 state changed from playing to idle
D: [pulseaudio] card.c: Setting card bluez_card.00_1A_80_91_72_05 profile a2dp_sink to availability status unknown
I: [pulseaudio] module-card-restore.c: Card bluez_card.00_1A_80_91_72_05 profile a2dp_sink became available, activating.
D: [pulseaudio] device-port.c: Setting port handsfree-output to status unknown
D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
I: [pulseaudio] module-card-restore.c: Synced.

* from there, the A2DP sink is available and active in PulseAudio:

$ pactl list | grep -C2 A2D
	Profiles:
		headset_head_unit: Headset Head Unit (HSP/HFP) (sinks: 1, sources: 1, priority: 20, available: yes)
		a2dp_sink: High Fidelity Playback (A2DP Sink) (sinks: 1, sources: 0, priority: 10, available: yes)
		off: Off (sinks: 0, sources: 0, priority: 0, available: yes)
	Active Profile: a2dp_sink
Comment 1 Tanu Kaskinen 2015-09-24 20:28:11 UTC
Apparently the a2dp profile doesn't initially get connected. It's not PulseAudio's job to connect the profiles, but something is connecting the hsp profile, so I wonder why a2dp doesn't get connected at the same time... The same or similar problem was reported recently in IRC, but we didn't find the culprit at that time. Even though this doesn't appear to be a PulseAudio bug, I'd be very interested to know what the solution is, if you figure out one.

I'll add Luiz von Dentz to CC... Luiz, do you have any idea where to start debugging, if only the hsp profile gets connected when turning on a headset, but a2dp starts only working when an explicit "connect" command is given in bluetoothctl?
Comment 2 quequotion 2015-11-13 19:42:46 UTC
I had the same problem and can verify the same workaround with the following:

pulseaudio-git v7.0.34.g9d2b763-1

bluez 5.34-1

Device 00:1F:82:28:93:51
	Name: DR-BT101
	Alias: DR-BT101
	Class: 0x240408
	Icon: audio-card
	Paired: yes
	Trusted: yes
	Blocked: no
	Connected: yes
	LegacyPairing: no
	UUID: Headset                   (00001108-0000-1000-8000-00805f9b34fb)
	UUID: Audio Sink                (0000110b-0000-1000-8000-00805f9b34fb)
	UUID: A/V Remote Control        (0000110e-0000-1000-8000-00805f9b34fb)
	UUID: Handsfree                 (0000111e-0000-1000-8000-00805f9b34fb)

When the device connects automatically (by powering on after being paired) A2DP is "unavailable".

To enable--and subsequently activate--the profile the device must be connected by explicitly giving the "connect 00:1F:82:28:93:51" command to bluetoothctl.
Comment 3 crocket 2016-04-27 02:27:13 UTC
I reproduced the same bug with Sony MDR-1RBT. Why does it have the problem with Sony bluetooth products?
Comment 4 Nikola Šnele 2016-06-26 19:02:34 UTC
Can confirm the bug in Kubuntu 16.04 with JBL bluetooth speaker.
Comment 5 Luiz Augusto von Dentz 2016-06-26 20:21:29 UTC
It seems a similar problem was fixed upstream:

https://git.kernel.org/cgit/bluetooth/bluez.git/commit/src/service.c?id=2e2edc36a91d6a8f2c65d793273df28a166d6bed
Comment 6 Fabrice Bellet 2016-06-28 19:07:29 UTC
I just tested with this newer bluez, and the bug is still there.
Comment 7 Luiz Augusto von Dentz 2016-06-28 21:47:09 UTC
This is a headset bug actually, the policy of reconnecting profiles is from the initiator as it may or may not have disabled profiles, like cars normally do have options to have phone calls only or media only.

It is actually pretty strange coming from Sony, this used to work quite well with their devices in the past, maybe they have decided to move to another stack an now there is this sort of problem, please add the HCI trace maybe there is something preventing the L2CAP connection to A2DP.
Comment 8 crocket 2016-06-29 09:13:06 UTC
(In reply to Luiz Augusto von Dentz from comment #7)
> stack an now there is this sort of problem, please add the HCI trace maybe
> there is something preventing the L2CAP connection to A2DP.

Unfortunately, the sony headset was taken by someone else. I don't have it anymore.
Comment 9 Fabrice Bellet 2016-06-29 15:26:25 UTC
(In reply to Luiz Augusto von Dentz from comment #7)
> This is a headset bug actually, the policy of reconnecting profiles is from
> the initiator as it may or may not have disabled profiles, like cars
> normally do have options to have phone calls only or media only.
> 
> It is actually pretty strange coming from Sony, this used to work quite well
> with their devices in the past, maybe they have decided to move to another
> stack an now there is this sort of problem, please add the HCI trace maybe
> there is something preventing the L2CAP connection to A2DP.

oh yes, you're right, there's an action to be performed on the device (press on the play/pause jog switch), that makes the a2dp_sink profile available and active in pulseaudio.
Comment 10 Elias E. del Real 2016-11-25 06:02:23 UTC
I have a Sony MDR-ZX220BT bluetooth headset that encounters this problem.
I'm using Ubuntu 16.10, bluez "5.41-0ubuntu3", and pulseaudio "1:9.0-2ubuntu2.1".


From
https://bugs.launchpad.net/ubuntu/+source/bluez/+bug/1438510
https://bugs.launchpad.net/ubuntu/+source/indicator-sound/+bug/1577197
it looks like the sequence that works is:

1. Select the "off" profile in pulseaudio.
2.1 Disconnect the bluetooth earphones.
2.2 Reconnect the bluetooth earphones.
3. Select the "a2dp_sink" profile in pulseaudio.

Or for commands:
1. pactl set-card-profile bluez_card.00_18_09_62_4B_98 off
2. bluetoothctl
2.1    disconnect 00:18:09:62:4B:98
2.2    connect 00:18:09:62:4B:98
3. pactl set-card-profile bluez_card.00_18_09_62_4B_98 a2dp_sink

Bluetooth users are resorting to a scripted version of the above as a workaround:
https://gist.github.com/pylover/d68be364adac5f946887b85e6ed6e7ae#file-a2dp-py


What I'm seeing in /var/log/syslog if I select "a2dp_sink" as the profile, then disconnect, and reconnect:

Nov 25 00:47:50 fireflower pulseaudio[2178]: [pulseaudio] module-bluez5-device.c: Default profile not connected, selecting off profile
Nov 25 00:47:50 fireflower bluetoothd[970]: /org/bluez/hci0/dev_00_18_09_62_4B_98/fd17: fd(24) ready
Nov 25 00:47:50 fireflower pulseaudio[2178]: [pulseaudio] bluez5-util.c: Transport TryAcquire() failed for transport /org/bluez/hci0/dev_00_18_09_62_4B_98/fd17 (Operation Not Authorized)
Nov 25 00:47:50 fireflower kernel: [ 7852.918655] input: 00:18:09:62:4B:98 as /devices/virtual/input/input37


The message from bluetoothd "fd(24) ready" showing up then makes me wonder if this is a race between pulseaudio and the bluetooth connection?

If I then run:

pactl set-card-profile bluez_card.00_18_09_62_4B_98 a2dp_sink

I get nothing new in /var/log/syslog .

If I run:

pactl set-card-profile bluez_card.00_18_09_62_4B_98 off

I get nothing new in /var/log/syslog .


If I again run:

pactl set-card-profile bluez_card.00_18_09_62_4B_98 a2dp_sink

I get this output:

Failure: Input/Output error

and /var/log/syslog logs:

Nov 25 00:52:26 fireflower pulseaudio[2178]: [pulseaudio] bluez5-util.c: Transport Acquire() failed for transport /org/bluez/hci0/dev_00_18_09_62_4B_98/fd17 (Operation Not Authorized)


If I run

pactl list cards | tail -n 26

I see:

Card #18
	Name: bluez_card.00_18_09_62_4B_98
	Driver: module-bluez5-device.c
	Owner Module: 43
	Properties:
		device.description = "MDR-ZX220BT"
		device.string = "00:18:09:62:4B:98"
		device.api = "bluez"
		device.class = "sound"
		device.bus = "bluetooth"
		device.form_factor = "headset"
		bluez.path = "/org/bluez/hci0/dev_00_18_09_62_4B_98"
		bluez.class = "0x240404"
		bluez.alias = "MDR-ZX220BT"
		device.icon_name = "audio-headset-bluetooth"
		device.intended_roles = "phone"
	Profiles:
		headset_head_unit: Headset Head Unit (HSP/HFP) (sinks: 1, sources: 1, priority: 20, available: yes)
		a2dp_sink: High Fidelity Playback (A2DP Sink) (sinks: 1, sources: 0, priority: 10, available: yes)
		off: Off (sinks: 0, sources: 0, priority: 0, available: yes)
	Active Profile: off
	Ports:
		headset-output: Headset (priority: 0, latency offset: 0 usec, available)
			Part of profile(s): headset_head_unit, a2dp_sink
		headset-input: Headset (priority: 0, latency offset: 0 usec)
			Part of profile(s): headset_head_unit


If I disconnect and connect the device via bluetoothctl, /var/log/syslog logs:

Nov 25 00:55:38 fireflower acpid: input device has been disconnected, fd 15

and

Nov 25 00:57:02 fireflower kernel: [ 8404.425497] input: 00:18:09:62:4B:98 as /devices/virtual/input/input38


If in the "Sound" GUI (System Settings > Sound), I go to the Output tab, and select the headset, /var/log/syslog logs:

Nov 25 00:57:37 fireflower pulseaudio[2178]: [pulseaudio] backend-native.c: connect(): Function not implemented


If in the pulseaudio "Volume Control" UI I go to the Configuration tab, it shows the profile is "Off".

If there, I select "High Fidelity Playback (A2DP Sink), /var/log/syslog logs:

Nov 25 01:00:55 fireflower bluetoothd[970]: /org/bluez/hci0/dev_00_18_09_62_4B_98/fd18: fd(24) ready
Comment 11 Elias E. del Real 2016-11-25 06:22:56 UTC
Created attachment 128181 [details]
btmon log of attempt to connect and automatically use a2dp_sink profile.

Attached a btmon log of attempt to connect and automatically use a2dp_sink profile.
Comment 12 Luiz Augusto von Dentz 2016-11-25 11:29:22 UTC
Well the logs looks completely different from the original problem, perhaps the logs of bluetoothd can show if there is perhaps another client acquiring the transport which would explain the error:

Nov 25 00:47:50 fireflower pulseaudio[2178]: [pulseaudio] bluez5-util.c: Transport TryAcquire() failed for transport
/org/bluez/hci0/dev_00_18_09_62_4B_98/fd17 (Operation Not Authorized)
Comment 13 Tanu Kaskinen 2016-11-25 11:47:37 UTC
That another client could be gdm's pulseaudio instance. See comment 56 in bug 73325 for how to disable gdm's use of bluetooth: https://bugs.freedesktop.org/show_bug.cgi?id=73325#c56
Comment 14 Joshua Wong 2016-12-05 02:21:01 UTC
I faced a similar issue with a2dp_sink profile where it is "not available" and what I did prior to connecting the Bluetooth headset in bluetoothctl was to first run pulseaudio --check -v to check if the pulseaudio daemon is running. If it is not running, issue "pulseaudio -D" and then check if it is running. Once the pulseaudio daemon is running, then only perform pairing and connecting in bluetoothctl.
Comment 15 Slava Grig 2017-01-21 16:19:18 UTC
Hi,

The same bug for me. Ubuntu 16.04. Packets:

  * libbluetooth3:amd64                5.37-0ubuntu5
  * pulseaudio-module-bluetooth        1:8.0-0ubuntu3.1
  * bluez                              5.37-0ubuntu5
  * pulseaudio                         1:8.0-0ubuntu3.1

Speakers JBL Charge 2 can't return after disconnecting. The python script a2dp.py published above restores connection.


Is there any chance to solve this in 2017? How can I help with this? (I'm a programmer). Is is a bug of pulseaudio or blueZ?
Comment 16 Tanu Kaskinen 2017-01-26 05:29:44 UTC
(In reply to Slava Grig from comment #15)
> Is there any chance to solve this in 2017? How can I help with this? (I'm a
> programmer). Is is a bug of pulseaudio or blueZ?

If you're a programmer, you can dive into pulseaudio and bluez code and figure out why it's not working.

Have you disabled bluetooth for gdm, as hinted to in comment #13? Ruling out the gdm problem would be the first step.

If the a2dp profile in "pactl list cards" shows up as "available: no", then it's likely a bluez bug. An "unavailable" bluetooth profile in pulseaudio means that bluez tells pulseaudio that the profile isn't connected.
Comment 17 ipatrol6010 2017-02-08 01:32:54 UTC
Raising the priority due to downstream activity (affects a number of popular devices, directly impacts usability, leaves mainstream desktop Linux distros at a feature loss compared to non-free OSes, etc.). Also personally confirming that it affects the Bose Color SoundLink, and the workaround script is no help with it.

This bug should not have gone unresolved for two years.
Comment 18 Daniel 2017-02-10 13:02:00 UTC
A more or less vanilla Ubuntu 16.04 installation, this bug is triggered. Python script provided (a2dp.py) works like a charm and returns sound to device.
Comment 19 crocket 2017-03-21 07:29:38 UTC
(In reply to Daniel from comment #18)
> A more or less vanilla Ubuntu 16.04 installation, this bug is triggered.
> Python script provided (a2dp.py) works like a charm and returns sound to
> device.

Where can I download a2dp.py? I want to make MDR-1RBT work on my linux.
Comment 20 Daniel 2017-03-21 09:19:12 UTC
(In reply to crocket from comment #19)
> (In reply to Daniel from comment #18)
> > A more or less vanilla Ubuntu 16.04 installation, this bug is triggered.
> > Python script provided (a2dp.py) works like a charm and returns sound to
> > device.
> 
> Where can I download a2dp.py? I want to make MDR-1RBT work on my linux.


Link provided above in comment #10

https://gist.github.com/pylover/d68be364adac5f946887b85e6ed6e7ae#file-a2dp-py
Comment 21 crocket 2017-03-21 11:41:02 UTC
Unfortunately, with MDR-1RBT, a2dp_sink is not available. Thus, a2dp.py cannot work in my case.

The only real errors I see in journalctl are

E: [pulseaudio] backend-native.c: connect(): Function not implemented
W: [pulseaudio] module-bluez5-device.c: Refused to switch profile to a2dp_sink: Not connected
Comment 22 crocket 2017-03-21 11:49:47 UTC
Wait. The proposed workaround worked for MDR-1RBT.
I followed the steps below.

1. Turn on MDR-1RBT
2. Let it be paired and connected to automatically
3. Execute `connect 00:18:09:1F:C3:29` in bluetoothctl
4. Execute `pactl set-card-profile bluez_card.00_18_09_1F_C3_29 a2dp_sink` on a shell.
5. Select MDR-1RBT's A2DP in sound settings

If there was a workaround, people must have found the exact cause of the problem.
What is the problem? What is the cause? What is the solution?
Comment 23 Luiz Augusto von Dentz 2017-03-21 11:57:38 UTC
(In reply to crocket from comment #22)
> Wait. The proposed workaround worked for MDR-1RBT.
> I followed the steps below.
> 
> 1. Turn on MDR-1RBT
> 2. Let it be paired and connected to automatically
> 3. Execute `connect 00:18:09:1F:C3:29` in bluetoothctl
> 4. Execute `pactl set-card-profile bluez_card.00_18_09_1F_C3_29 a2dp_sink`
> on a shell.
> 5. Select MDR-1RBT's A2DP in sound settings
> 
> If there was a workaround, people must have found the exact cause of the
> problem.
> What is the problem? What is the cause? What is the solution?

If you could please add some logs when connecting, syslog of bluetoothd and pulseaudio, then we can figure out if it needs some special handling.
Comment 24 crocket 2017-03-21 12:25:15 UTC
Created attachment 130342 [details]
bluetoothd.log

I attached bluetooth.log as a file because it is somewhat long.
I paste journalctl log below because it is short.

journalctl.log:
----------------------------------------
I don't know what this is.

Mar 21 21:11:42 arch-server pulseaudio[16130]: W: [pulseaudio] module-bluez5-device.c: Profile has no transport

-----------------------------------------
When I tried to select MDR-1RBT in gnome sound settings while MDR-1RBT's active profile was off.

Mar 21 21:12:43 arch-server pulseaudio[16130]: E: [pulseaudio] backend-native.c: connect(): Function not implemented
Mar 21 21:12:47 arch-server pulseaudio[16130]: E: [pulseaudio] backend-native.c: connect(): Function not implemented
Comment 25 crocket 2017-03-21 13:27:28 UTC
Created attachment 130343 [details]
bluetooth-headset_head_unit.log

I haven't found a way to get verbose pulseaudio log output on gnome.
According to my test, A2DP works for MDR-1RBT after reconnection.
But, I can't set the active profile to headset_head_unit for MDR-1RBT.
Read the following errors I got when I tried headset_head_unit.

~> pactl set-card-profile bluez_card.00_18_09_1F_C3_29 headset_head_unit
Failure: Input/Output error
journalctl:
E: [pulseaudio] backend-native.c: connect(): Function not implemented

I attached bluetoothd log recorded when I tried headset_head_unit.
Comment 26 Luiz Augusto von Dentz 2017-03-21 14:35:04 UTC
bluetoothd[16274]: src/adapter.c:connected_callback() hci0 device 00:18:09:1F:C3:29 connected eir_len 5
bluetoothd[16274]: src/adapter.c:dev_disconnected() Device 00:18:09:1F:C3:29 disconnected, reason 3
bluetoothd[16274]: src/adapter.c:adapter_remove_connection() 
bluetoothd[16274]: plugins/policy.c:disconnect_cb() reason 3
bluetoothd[16274]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 00:18:09:1F:C3:29 type 0 status 0xe
bluetoothd[16274]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
bluetoothd[16274]: src/device.c:device_bonding_failed() status 14
bluetoothd[16274]: src/adapter.c:resume_discovery() 
bluetoothd[16274]: src/adapter.c:connected_callback() hci0 device 00:18:09:1F:C3:29 connected eir_len 5
bluetoothd[16274]: src/adapter.c:dev_disconnected() Device 00:18:09:1F:C3:29 disconnected, reason 3
bluetoothd[16274]: src/adapter.c:adapter_remove_connection() 
bluetoothd[16274]: plugins/policy.c:disconnect_cb() reason 3
bluetoothd[16274]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 00:18:09:1F:C3:29 type 0 status 0xe
bluetoothd[16274]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
bluetoothd[16274]: src/device.c:device_bonding_failed() status 14
bluetoothd[16274]: src/adapter.c:resume_discovery() 
bluetoothd[16274]: src/adapter.c:connected_callback() hci0 device 00:18:09:1F:C3:29 connected eir_len 5
bluetoothd[16274]: src/adapter.c:dev_disconnected() Device 00:18:09:1F:C3:29 disconnected, reason 3
bluetoothd[16274]: src/adapter.c:adapter_remove_connection() 
bluetoothd[16274]: plugins/policy.c:disconnect_cb() reason 3
bluetoothd[16274]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 00:18:09:1F:C3:29 type 0 status 0xe
bluetoothd[16274]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
bluetoothd[16274]: src/device.c:device_bonding_failed() status 14
bluetoothd[16274]: src/adapter.c:resume_discovery() 
bluetoothd[16274]: src/adapter.c:connected_callback() hci0 device 00:18:09:1F:C3:29 connected eir_len 5
bluetoothd[16274]: src/adapter.c:dev_disconnected() Device 00:18:09:1F:C3:29 disconnected, reason 3
bluetoothd[16274]: src/adapter.c:adapter_remove_connection() 
bluetoothd[16274]: plugins/policy.c:disconnect_cb() reason 3
bluetoothd[16274]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 00:18:09:1F:C3:29 type 0 status 0xe
bluetoothd[16274]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
bluetoothd[16274]: src/device.c:device_bonding_failed() status 14
bluetoothd[16274]: src/adapter.c:resume_discovery() 
bluetoothd[16274]: src/adapter.c:connected_callback() hci0 device 00:18:09:1F:C3:29 connected eir_len 5
bluetoothd[16274]: src/profile.c:ext_confirm() incoming connect from 00:18:09:1F:C3:29

This sounds strange, it is as if the connection is interrupted several times before it succeeds, anyway once past this line all looks fine:

bluetoothd[16274]: src/service.c:change_state() 0x250c1a0: device 00:18:09:1F:C3:29 profile Headset Voice gateway state changed: connecting -> connected (0)

bluetoothd[16274]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci0/dev_00_18_09_1F_C3_29: SINK_STATE_CONNECTING -> SINK_STATE_CONNECTED

And there is some client acquiring the transport:
bluetoothd[16274]: profiles/audio/transport.c:transport_set_state() State changed /org/bluez/hci0/dev_00_18_09_1F_C3_29/fd0: TRANSPORT_STATE_IDLE -> TRANSPORT_STATE_REQUESTING
bluetoothd[16274]: profiles/audio/transport.c:media_request_create() Request created: method=Acquire id=4
bluetoothd[16274]: profiles/audio/transport.c:media_owner_add() Owner :1.2679 Request Acquire
bluetoothd[16274]: profiles/audio/transport.c:media_transport_set_owner() Transport /org/bluez/hci0/dev_00_18_09_1F_C3_29/fd0 Owner :1.2679
bluetoothd[16274]: profiles/audio/avdtp.c:session_cb() 
bluetoothd[16274]: profiles/audio/avdtp.c:avdtp_parse_resp() START request succeeded
bluetoothd[16274]: profiles/audio/a2dp.c:start_cfm() Source 0x2503830: Start_Cfm
bluetoothd[16274]: /org/bluez/hci0/dev_00_18_09_1F_C3_29/fd0: fd(34) ready
bluetoothd[16274]: profiles/audio/transport.c:media_owner_remove() Owner :1.2679 Request Acquire
bluetoothd[16274]: profiles/audio/transport.c:transport_set_state() State changed /org/bluez/hci0/dev_00_18_09_1F_C3_29/fd0: TRANSPORT_STATE_REQUESTING -> TRANSPORT_STATE_ACTIVE
bluetoothd[16274]: profiles/audio/a2dp.c:setup_unref() 0x25222c0: ref=0
bluetoothd[16274]: profiles/audio/a2dp.c:setup_free() 0x25222c0
bluetoothd[16274]: profiles/audio/avdtp.c:avdtp_unref() 0x250d620: ref=2
bluetoothd[16274]: profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed: OPEN -> STREAMING
bluetoothd[16274]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci0/dev_00_18_09_1F_C3_29: SINK_STATE_CONNECTED -> SINK_STATE_PLAYING

Perhaps this is GDM instance taking over? Btw, have we make sure GDM instance disables its endpoints when it is no longer active?
Comment 27 crocket 2017-03-22 02:12:03 UTC
> This sounds strange, it is as if the connection is interrupted several times before it succeeds

When I turn on MDR-1RBT, the connection is severed by an unknown force several times before the connection succeeds.

> Perhaps this is GDM instance taking over? Btw, have we make sure GDM instance disables its endpoints when it is no longer active?

No, GDM is not running pulseaudio. I explicitly disabled pulseaudio in GDM.

~> ps -f (pgrep pulseaudio)
UID        PID  PPID  C STIME TTY      STAT   TIME CMD
crocket   2038  1936  0 10:52 ?        S<sl   0:04 /usr/bin/pulseaudio --daemonize=no

> there is some client acquiring the transport

I played music after A2DP became available to make sure A2DP actually worked.
Comment 28 Diego Fernandez 2017-08-30 03:53:15 UTC
I'm on Fedora 26, using PulseAudio 10.0 and I'm having the same issue with my Sony MDR100ABN headset. I've tried all sorts of things, and the only thing that consistently works is to:

1. Let it connect automatically when I turn on my headset
2. Disconnect through bluetoothctl
3. Reconnect through bluetoothctl
4. Use pacmd set-card-profile to set a2dp_sink

I've tried disabling the GDM pulseaudio, changing 'load-module module-bluetooth-discover headset=<mode>' in default.pa, adding 'load-module module-switch-on-connect' to default.pa, adding 'Disable=Headset' to '[General]' in bluetooth/main.conf, and pretty much any combination of those changes.
Comment 29 languitar 2017-11-10 13:02:05 UTC
(In reply to Diego Fernandez from comment #28)
> I'm on Fedora 26, using PulseAudio 10.0 and I'm having the same issue with
> my Sony MDR100ABN headset. I've tried all sorts of things, and the only
> thing that consistently works is to:
> 
> 1. Let it connect automatically when I turn on my headset
> 2. Disconnect through bluetoothctl
> 3. Reconnect through bluetoothctl
> 4. Use pacmd set-card-profile to set a2dp_sink

For me this is also the only thing that works, apart from the fact that I can enable A2DP within blueman after the explicit connection.

Archlinux, no GDM running.
Comment 30 Sergey 2017-11-19 20:56:21 UTC
My headset is Sony DR-BT50.
4.13.12-1-ARCH.

This is not gdm problem. I use lightdm + xfce. And have this bug. Nevertheless I was try to disable lightdm, reboot, startx - the bug still here.
Comment 31 Sergey 2017-11-20 17:29:00 UTC
Created attachment 135608 [details]
journalctl log of "automatic" headset connection
Comment 32 Sergey 2017-11-20 17:29:57 UTC
Created attachment 135609 [details]
pactl-subscribe log of "automatic" headset connection
Comment 33 Sergey 2017-11-20 17:30:47 UTC
Created attachment 135610 [details]
btmon log of "automatic" headset connection
Comment 34 Sergey 2017-11-20 17:31:33 UTC
Created attachment 135611 [details]
journalctl log of manual headset connection
Comment 35 Sergey 2017-11-20 17:32:00 UTC
Created attachment 135612 [details]
pactl-subscribe log of manual headset connection
Comment 36 Sergey 2017-11-20 17:32:21 UTC
Created attachment 135613 [details]
btmon log of manual headset connection
Comment 37 Sergey 2017-11-20 17:38:12 UTC
added some logs. Please check it

My system:
4.13.12-1-ARCH

BT:
local/blueberry 1.1.15-1
    Bluetooth configuration tool
local/bluez 5.47-2
    Daemons for the bluetooth protocol stack
local/bluez-libs 5.47-2
    Deprecated libraries for the bluetooth protocol stack
local/bluez-tools 0.2.0-1
    A set of tools to manage Bluetooth devices for Linux
local/bluez-utils 5.47-2
    Development and debugging utilities for the bluetooth protocol stack
local/gnome-bluetooth 3.26.0+1+g3875844-1
    The GNOME Bluetooth Subsystem
local/pulseaudio-bluetooth 11.1-1
    Bluetooth support for PulseAudio
local/sbc 1.3-1
    Bluetooth Subband Codec (SBC) library

Pulse:
local/libcanberra-pulse 0.30+2+gc0620e4-1
    PulseAudio plugin for libcanberra
local/libpulse 11.1-1
    A featureful, general-purpose sound server (client library)
local/pavucontrol 3.0-4
    PulseAudio Volume Control
local/pulseaudio 11.1-1
    A featureful, general-purpose sound server
local/pulseaudio-alsa 2-3
    ALSA Configuration for PulseAudio
local/pulseaudio-bluetooth 11.1-1
    Bluetooth support for PulseAudio
local/xfce4-pulseaudio-plugin 0.3.2-1 (xfce4-goodies)
    Pulseaudio plugin for Xfce4 panel
Comment 38 Sergey 2017-11-22 21:04:27 UTC
wrote this fully automated(you no need to manually run scripts or specify mac addresses) udev rule for temporary solve the problem. It work with already paired and new headsets.
https://gist.github.com/hxss/a3eadb0cc52e58ce7743dff71b92b297
Comment 39 Arch 2017-12-10 10:35:56 UTC
@Sergey: thanks for your udev script.

Would you add a comment to your script that bluez-tools package is a dependency (for bt-device)? (Standard dependency for bluetooth sound seems to be only bluez-utils.)
Comment 40 Sergey 2017-12-10 11:37:21 UTC
(In reply to Milan Knížek from comment #39)
> @Sergey: thanks for your udev script.
> 
> Would you add a comment to your script that bluez-tools package is a
> dependency (for bt-device)? (Standard dependency for bluetooth sound seems
> to be only bluez-utils.)

Dependencies list added.
Comment 41 Dominik 'Rathann' Mierzejewski 2018-02-02 20:10:29 UTC
Isn't this a duplicate of bug 73325?
Comment 42 Sergey 2018-02-02 20:27:50 UTC
Dominik, no. For me all protocols works fine. But only if I connect to headset manual from bluetoothctl. We need exactly AUTOMATIC connection, when headset trying to connect to PC.
Comment 44 GiH 2018-07-05 09:26:46 UTC
Just want to confirm this bug with SONY MDR-XB650BT on Kernel 4.14.52-1-MANJARO.

The script from Comment 38 helped me.
Comment 45 Dragoon Aethis 2018-07-12 12:49:49 UTC
Can also confirm the issue with Sony WH-H900N headphones, Arch with kernel 4.17.4, BlueZ 5.50, PulseAudio 12.0.
Comment 46 GitLab Migration User 2018-07-30 10:36:22 UTC
-- GitLab Migration Automatic Message --

This bug has been migrated to freedesktop.org's GitLab instance and has been closed from further activity.

You can subscribe and participate further through the new bug through this link to our GitLab instance: https://gitlab.freedesktop.org/pulseaudio/pulseaudio/issues/525.


Use of freedesktop.org services, including Bugzilla, is subject to our Code of Conduct. How we collect and use information is described in our Privacy Policy.