Bug: bluetoothd dies when connecting device

Hi,

I tried to work on the oFono HFP patches for PulseAudio, but I couldn't really do anything, because BlueZ is basically not working at all on my machine. When I try to connect my Nokia BH-505 headset, bluetoothd sort of dies. The process doesn't terminate, but it disconnects from D-Bus.

I'm on Fedora 20, PulseAudio and BlueZ are compiled from current git master. oFono is not involved here in any way. I have attached an annotated log of the headset connecting process, in case someone wants to investigate this. The starting scenario in the log is that pulseaudio and bluetoothd are not running, and I have previously removed the headset from the BlueZ database. First I start pulseaudio with verbose logging and timestamps in the background, then in the same terminal I start bluetoothd with -d -n options in the background, and then still in the same terminal I start bluetoothctl to issue the commands for connecting the headset, so pulseuadio, bluetoothd and bluetoothctl output are all interleaved. Connecting the device appears to work at first, but when PulseAudio tries to start streaming to the headset, things fall apart.

Tanu

tanu@TKKASKIN_MOBL3_GER_CORP_INTEL_COM ~> ( 0.000| 0.000) I: [pulseaudio] main.c: setrlimit(RLIMIT_NICE, (31, 31)) failed: Operation not permitted

*** Removed about 1500 lines of irrelevant pulseaudio startup log.

(   0.175|   0.000) D: [pulseaudio] module.c: Checking for existence of '/usr/local/lib/pulse-5.0/modules/module-bluetooth-policy.so': success
(   0.175|   0.000) I: [pulseaudio] module.c: Loaded "module-bluetooth-policy" (index: #7; argument: "").
(   0.175|   0.000) D: [pulseaudio] module.c: Checking for existence of '/usr/local/lib/pulse-5.0/modules/module-bluetooth-discover.so': success
(   0.176|   0.000) D: [pulseaudio] module.c: Checking for existence of '/usr/local/lib/pulse-5.0/modules/module-bluez5-discover.so': success
(   0.177|   0.001) D: [pulseaudio] dbus-util.c: Successfully connected to D-Bus system bus 103c6c2f6f65f03fccdb8d6e53e8792b as :1.335
(   0.178|   0.001) I: [pulseaudio] module.c: Loaded "module-bluez5-discover" (index: #9; argument: "").
(   0.178|   0.000) D: [pulseaudio] module.c: Checking for existence of '/usr/local/lib/pulse-5.0/modules/module-bluez4-discover.so': success
(   0.180|   0.002) I: [pulseaudio] module.c: Loaded "module-bluez4-discover" (index: #10; argument: "").
(   0.180|   0.000) I: [pulseaudio] module.c: Loaded "module-bluetooth-discover" (index: #8; argument: "").
(   0.180|   0.000) D: [pulseaudio] module.c: Checking for existence of '/usr/local/lib/pulse-5.0/modules/module-esound-protocol-unix.so': success
(   0.181|   0.000) I: [pulseaudio] module.c: Loaded "module-esound-protocol-unix" (index: #11; argument: "").
(   0.183|   0.001) I: [pulseaudio] module.c: Loaded "module-native-protocol-unix" (index: #12; argument: "").
(   0.183|   0.000) D: [pulseaudio] module.c: Checking for existence of '/usr/local/lib/pulse-5.0/modules/module-gconf.so': failure
(   0.183|   0.000) D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
(   0.183|   0.000) I: [pulseaudio] module-default-device-restore.c: Restored default sink 'alsa_output.pci-0000_00_1b.0.analog-stereo'.
(   0.196|   0.012) D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
(   0.196|   0.000) I: [pulseaudio] module-default-device-restore.c: Restored default source 'alsa_input.pci-0000_00_1b.0.analog-stereo'.
(   0.196|   0.000) I: [pulseaudio] module.c: Loaded "module-default-device-restore" (index: #13; argument: "").
(   0.196|   0.000) I: [pulseaudio] module.c: Loaded "module-rescue-streams" (index: #14; argument: "").
(   0.196|   0.000) I: [pulseaudio] module.c: Loaded "module-always-sink" (index: #15; argument: "").
(   0.197|   0.000) I: [pulseaudio] module.c: Loaded "module-intended-roles" (index: #16; argument: "").
(   0.197|   0.000) D: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_1b.0.analog-stereo becomes idle, timeout in 5 seconds.
(   0.197|   0.000) D: [pulseaudio] module-suspend-on-idle.c: Source alsa_input.pci-0000_00_1b.0.analog-stereo becomes idle, timeout in 5 seconds.
(   0.197|   0.000) I: [pulseaudio] module.c: Loaded "module-suspend-on-idle" (index: #17; argument: "").
(   0.197|   0.000) D: [pulseaudio] module.c: Checking for existence of '/usr/local/lib/pulse-5.0/modules/module-console-kit.so': success
(   0.198|   0.000) I: [pulseaudio] module.c: Loaded "module-console-kit" (index: #18; argument: "").
(   0.198|   0.000) D: [pulseaudio] module.c: Checking for existence of '/usr/local/lib/pulse-5.0/modules/module-systemd-login.so': success
(   0.199|   0.000) I: [pulseaudio] client.c: Created 0 "Login Session 1"
(   0.199|   0.000) D: [pulseaudio] module-systemd-login.c: Added new session 1
(   0.199|   0.000) I: [pulseaudio] module.c: Loaded "module-systemd-login" (index: #19; argument: "").
(   0.199|   0.000) I: [pulseaudio] module.c: Loaded "module-position-event-sounds" (index: #20; argument: "").
(   0.200|   0.000) D: [pulseaudio] module-role-cork.c: Using role 'phone' as trigger role.
(   0.200|   0.000) D: [pulseaudio] module-role-cork.c: Using roles 'music' and 'video' as cork roles.
(   0.200|   0.000) I: [pulseaudio] module.c: Loaded "module-role-cork" (index: #21; argument: "").
(   0.200|   0.000) I: [pulseaudio] module.c: Loaded "module-filter-heuristics" (index: #22; argument: "").
(   0.201|   0.000) I: [pulseaudio] module.c: Loaded "module-filter-apply" (index: #23; argument: "").
(   0.201|   0.000) D: [pulseaudio] main.c: Got org.PulseAudio1!
(   0.201|   0.000) D: [pulseaudio] main.c: Got org.pulseaudio.Server!
(   0.201|   0.000) I: [pulseaudio] main.c: Daemon startup complete.
(   0.201|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus, path=/org/freedesktop/DBus, member=NameAcquired
(   0.202|   0.000) E: [pulseaudio] hfaudioagent-ofono.c: Failed to register as a handsfree audio agent with ofono: org.freedesktop.DBus.Error.ServiceUnknown: The name org.ofono was not provided by any .service files
(   0.202|   0.000) E: [pulseaudio] bluez5-util.c: GetManagedObjects() failed: org.freedesktop.systemd1.LoadFailed: Unit dbus-org.bluez.service failed to load: No such file or directory.
(   0.202|   0.000) I: [pulseaudio] client.c: Created 1 "Native client (UNIX socket client)"
(   0.202|   0.000) D: [pulseaudio] module-udev-detect.c: /dev/snd/controlC0 is accessible: yes
(   0.202|   0.000) D: [pulseaudio] module-udev-detect.c: Resuming all sinks and sources of card alsa_card.pci-0000_00_1b.0.
(   0.202|   0.000) E: [pulseaudio] bluez4-util.c: org.bluez.Manager.GetProperties() failed: org.freedesktop.systemd1.LoadFailed: Unit dbus-org.bluez.service failed to load: No such file or directory.
(   0.202|   0.000) D: [pulseaudio] protocol-native.c: Protocol version: remote 29, local 30
(   0.202|   0.000) I: [pulseaudio] protocol-native.c: Got credentials: uid=1000 gid=1000 success=1
(   0.202|   0.000) D: [pulseaudio] protocol-native.c: SHM possible: yes
(   0.202|   0.000) D: [pulseaudio] protocol-native.c: Negotiated SHM: yes
(   0.202|   0.000) D: [pulseaudio] protocol-native.c: Disabling srbchannel, reason: Protocol too old
(   0.203|   0.000) D: [pulseaudio] module-augment-properties.c: Looking for .desktop file for gnome-settings-daemon
(   0.211|   0.008) I: [pulseaudio] client.c: Created 2 "Native client (UNIX socket client)"
(   0.212|   0.000) D: [pulseaudio] protocol-native.c: Protocol version: remote 29, local 30
(   0.212|   0.000) I: [pulseaudio] protocol-native.c: Got credentials: uid=1000 gid=1000 success=1
(   0.212|   0.000) D: [pulseaudio] protocol-native.c: SHM possible: yes
(   0.212|   0.000) D: [pulseaudio] protocol-native.c: Negotiated SHM: yes
(   0.212|   0.000) D: [pulseaudio] protocol-native.c: Disabling srbchannel, reason: Protocol too old
(   0.212|   0.000) D: [pulseaudio] module-augment-properties.c: Looking for .desktop file for gnome-shell
(   0.212|   0.000) D: [pulseaudio] module-augment-properties.c: Found /usr/share/applications/gnome-shell.desktop.
(   5.204|   4.991) I: [pulseaudio] module-suspend-on-idle.c: Source alsa_input.pci-0000_00_1b.0.analog-stereo idle for too long, suspending ...
(   5.204|   0.000) D: [pulseaudio] source.c: Suspend cause of source alsa_input.pci-0000_00_1b.0.analog-stereo is 0x0004, suspending
(   5.204|   0.000) I: [alsa-source-ALC269VC Analog] alsa-source.c: Device suspended...
(   5.204|   0.000) D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.
(   5.205|   0.000) I: [pulseaudio] module-suspend-on-idle.c: Sink alsa_output.pci-0000_00_1b.0.analog-stereo idle for too long, suspending ...
(   5.205|   0.000) D: [pulseaudio] sink.c: Suspend cause of sink alsa_output.pci-0000_00_1b.0.analog-stereo is 0x0004, suspending
(   5.207|   0.001) I: [alsa-sink-ALC269VC Analog] alsa-sink.c: Device suspended...
(   5.207|   0.000) D: [pulseaudio] core.c: Hmm, no streams around, trying to vacuum.
(   5.208|   0.001) D: [pulseaudio] module-udev-detect.c: /dev/snd/controlC0 is accessible: yes
(   5.208|   0.000) D: [pulseaudio] module-udev-detect.c: Resuming all sinks and sources of card alsa_card.pci-0000_00_1b.0.

*** pulseaudio startup complete, let's start bluetoothd.

tanu@TKKASKIN_MOBL3_GER_CORP_INTEL_COM ~> sudo /usr/local/libexec/bluetooth/bluetoothd -n -d &
[2] 9534
tanu@TKKASKIN_MOBL3_GER_CORP_INTEL_COM ~> bluetoothd[9537]: Bluetooth daemon 5.22 bluetoothd[9537]: src/gatt.c:gatt_init() Starting GATT server

(  27.568|  22.359) D: [pulseaudio] bluez5-util.c: Bluetooth daemon appeared
(  27.568|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus, path=/org/freedesktop/DBus, member=NameOwnerChanged

bluetoothd[9537]: src/adapter.c:adapter_init() sending read version command
( 27.568| 0.000) D: [pulseaudio] bluez4-util.c: Bluetooth daemon appeared.
bluetoothd[9537]: Starting SDP server
bluetoothd[9537]: src/sdpd-service.c:register_device_id() Adding device id record for 0002:1d6b:0246:0516 bluetoothd[9537]: src/plugin.c:plugin_init() Loading builtin plugins
bluetoothd[9537]: src/plugin.c:add_plugin() Loading hostname plugin
bluetoothd[9537]: src/plugin.c:add_plugin() Loading wiimote plugin
bluetoothd[9537]: src/plugin.c:add_plugin() Loading autopair plugin
bluetoothd[9537]: src/plugin.c:add_plugin() Loading policy plugin
bluetoothd[9537]: src/plugin.c:add_plugin() Loading a2dp plugin
bluetoothd[9537]: src/plugin.c:add_plugin() Loading avrcp plugin
bluetoothd[9537]: src/plugin.c:add_plugin() Loading network plugin
bluetoothd[9537]: src/plugin.c:add_plugin() Loading input plugin
bluetoothd[9537]: src/plugin.c:add_plugin() Loading hog plugin
bluetoothd[9537]: src/plugin.c:add_plugin() Loading gatt plugin
bluetoothd[9537]: src/plugin.c:add_plugin() Loading scanparam plugin
bluetoothd[9537]: src/plugin.c:add_plugin() Loading deviceinfo plugin
bluetoothd[9537]: src/plugin.c:plugin_init() Loading plugins /usr/local/lib/bluetooth/plugins bluetoothd[9537]: profiles/input/suspend-dummy.c:suspend_init()
bluetoothd[9537]: profiles/input/suspend-dummy.c:suspend_init() Created suspend-dummy FIFO on /tmp/hogsuspend bluetoothd[9537]: profiles/network/manager.c:read_config() Config options: Security=true
bluetoothd[9537]: plugins/hostname.c:read_dmi_fallback() chassis: laptop
bluetoothd[9537]: plugins/hostname.c:read_dmi_fallback() major: 0x01 minor: 0x03
( 27.574| 0.005) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.ObjectManager, path=/, member=InterfacesAdded
bluetoothd[9537]: src/main.c:main() Entering main loop
bluetoothd[9537]: src/rfkill.c:rfkill_event() RFKILL event idx 0 type 2 op 0 soft 0 hard 0
bluetoothd[9537]: Bluetooth management interface 1.5 initialized
bluetoothd[9537]: src/adapter.c:read_version_complete() sending read supported commands command bluetoothd[9537]: src/adapter.c:read_version_complete() sending read index list command
bluetoothd[9537]: src/rfkill.c:rfkill_event() RFKILL event idx 1 type 5 op 0 soft 0 hard 0
bluetoothd[9537]: src/rfkill.c:rfkill_event() RFKILL event idx 3 type 1 op 0 soft 0 hard 0
bluetoothd[9537]: src/adapter.c:read_commands_complete() Number of commands: 46
bluetoothd[9537]: src/adapter.c:read_commands_complete() Number of events: 23
bluetoothd[9537]: src/rfkill.c:rfkill_event() RFKILL event idx 6 type 2 op 0 soft 0 hard 0
bluetoothd[9537]: src/adapter.c:read_index_list_complete() Number of controllers: 1
bluetoothd[9537]: src/adapter.c:read_index_list_complete() Found index 0
bluetoothd[9537]: src/adapter.c:index_added() index 0
bluetoothd[9537]: src/adapter.c:btd_adapter_new() System name: BlueZ 5.22
bluetoothd[9537]: src/adapter.c:btd_adapter_new() Major class: 0
bluetoothd[9537]: src/adapter.c:btd_adapter_new() Minor class: 0
bluetoothd[9537]: src/adapter.c:btd_adapter_new() Modalias: usb:v1D6Bp0246d0516
bluetoothd[9537]: src/adapter.c:btd_adapter_new() Discoverable timeout: 180 seconds
bluetoothd[9537]: src/adapter.c:btd_adapter_new() Pairable timeout: 0 seconds
bluetoothd[9537]: src/adapter.c:index_added() sending read info command for index 0
bluetoothd[9537]: src/adapter.c:read_info_complete() index 0 status 0x00
bluetoothd[9537]: src/adapter.c:clear_uuids() sending clear uuids command for index 0
bluetoothd[9537]: src/attrib-server.c:btd_adapter_gatt_server_start() Start GATT server in hci0 bluetoothd[9537]: src/attrib-server.c:attrib_db_add_new() handle=0x0001
bluetoothd[9537]: src/attrib-server.c:attrib_db_add_new() handle=0x0004
bluetoothd[9537]: src/attrib-server.c:attrib_db_add_new() handle=0x0006
bluetoothd[9537]: src/attrib-server.c:attrib_db_add_new() handle=0x0007
bluetoothd[9537]: src/attrib-server.c:attrib_db_add_new() handle=0x0008
bluetoothd[9537]: src/adapter.c:adapter_service_add() /org/bluez/hci0
bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Adding record with handle 0x10001 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000007-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001800-0000-1000-8000-00805f9 bluetoothd[9537]: src/adapter.c:adapter_service_insert() /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:add_uuid() sending add uuid command for index 0
bluetoothd[9537]: src/attrib-server.c:attrib_db_add_new() handle=0x0010
bluetoothd[9537]: src/adapter.c:adapter_service_add() /org/bluez/hci0
bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Adding record with handle 0x10002 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000007-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001801-0000-1000-8000-00805f9 bluetoothd[9537]: src/adapter.c:adapter_service_insert() /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:add_uuid() sending add uuid command for index 0
bluetoothd[9537]: profiles/audio/a2dp.c:media_server_probe() path /org/bluez/hci0
bluetoothd[9537]: plugins/hostname.c:hostname_probe()
bluetoothd[9537]: plugins/hostname.c:update_class() major: 0x01 minor: 0x03
bluetoothd[9537]: src/adapter.c:btd_adapter_set_class() class: major 1 minor 3
bluetoothd[9537]: src/adapter.c:set_dev_class() sending set device class command for index 0
bluetoothd[9537]: profiles/network/manager.c:panu_server_probe() path /org/bluez/hci0
bluetoothd[9537]: profiles/network/server.c:server_register() Registered interface org.bluez.NetworkServer1 on path /org/bluez/hci0 bluetoothd[9537]: profiles/network/manager.c:gn_server_probe() path /org/bluez/hci0
bluetoothd[9537]: profiles/network/manager.c:nap_server_probe() path /org/bluez/hci0
bluetoothd[9537]: profiles/audio/avrcp.c:avrcp_controller_server_probe() path /org/bluez/hci0 bluetoothd[9537]: src/adapter.c:adapter_service_add() /org/bluez/hci0
bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Adding record with handle 0x10003 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000017-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 0000110e-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 0000110f-0000-1000-8000-00805f9 bluetoothd[9537]: src/adapter.c:adapter_service_insert() /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:add_uuid() sending add uuid command for index 0
bluetoothd[9537]: profiles/audio/avrcp.c:avrcp_target_server_probe() path /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:adapter_service_add() /org/bluez/hci0
bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Adding record with handle 0x10004 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000017-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 0000110c-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 0000110e-0000-1000-8000-00805f9 bluetoothd[9537]: src/adapter.c:adapter_service_insert() /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:add_uuid() sending add uuid command for index 0
bluetoothd[9537]: profiles/audio/a2dp.c:a2dp_sink_server_probe() path /org/bluez/hci0
bluetoothd[9537]: profiles/audio/a2dp.c:a2dp_source_server_probe() path /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:btd_adapter_unblock_address() hci0 00:00:00:00:00:00
bluetoothd[9537]: src/adapter.c:load_link_keys() hci0 keys 0 debug_keys 0
bluetoothd[9537]: src/adapter.c:load_ltks() hci0 keys 0
bluetoothd[9537]: src/adapter.c:load_irks() hci0 irks 0
bluetoothd[9537]: src/adapter.c:load_conn_params() hci0 conn params 0
bluetoothd[9537]: src/adapter.c:adapter_service_insert() /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:add_uuid() sending add uuid command for index 0
bluetoothd[9537]: src/adapter.c:set_did() hci0 source 2 vendor 1d6b product 246 version 516
bluetoothd[9537]: src/adapter.c:adapter_register() Adapter /org/bluez/hci0 registered
bluetoothd[9537]: src/adapter.c:set_dev_class() sending set device class command for index 0
bluetoothd[9537]: src/adapter.c:set_name() sending set local name command for index 0
bluetoothd[9537]: src/adapter.c:set_mode() sending set mode command for index 0
bluetoothd[9537]: src/adapter.c:load_link_keys_complete() link keys loaded for hci0
bluetoothd[9537]: src/adapter.c:load_ltks_complete() LTKs loaded for hci0
bluetoothd[9537]: src/adapter.c:load_irks_complete() IRKs loaded for hci0
bluetoothd[9537]: hci0 Load Connection Parameters failed: Unknown Command (0x01)
bluetoothd[9537]: src/adapter.c:local_name_changed_callback() Name: BlueZ 5.22
bluetoothd[9537]: src/adapter.c:local_name_changed_callback() Short name:
bluetoothd[9537]: src/adapter.c:local_name_changed_callback() Current alias: BlueZ 5.22
bluetoothd[9537]: src/attrib-server.c:attrib_db_update() handle=0x0006
bluetoothd[9537]: src/profile.c:register_profile() sender :1.73
bluetoothd[9537]: src/profile.c:create_ext() Created "Message Notification"
bluetoothd[9537]: src/profile.c:ext_adapter_probe() "Message Notification" probed
bluetoothd[9537]: src/profile.c:ext_start_servers() Message Notification listening on PSM 4097 bluetoothd[9537]: src/profile.c:ext_start_servers() Message Notification listening on chan 17 bluetoothd[9537]: src/adapter.c:adapter_service_add() /org/bluez/hci0
bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Adding record with handle 0x10005 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000003-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000008-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001133-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001134-0000-1000-8000-00805f9 bluetoothd[9537]: src/adapter.c:adapter_service_insert() /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:add_uuid() sending add uuid command for index 0
bluetoothd[9537]: src/profile.c:register_profile() sender :1.73
bluetoothd[9537]: src/profile.c:create_ext() Created "Message Access"
( 27.600| 0.026) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.ObjectManager, path=/, member=InterfacesAdded
bluetoothd[9537]: src/profile.c:ext_adapter_probe() "Message Access" probed
bluetoothd[9537]: src/profile.c:ext_start_servers() Message Access listening on chan 16
bluetoothd[9537]: src/adapter.c:adapter_service_add() /org/bluez/hci0
bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Adding record with handle 0x10006 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000003-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000008-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001132-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001134-0000-1000-8000-00805f9 bluetoothd[9537]: src/adapter.c:adapter_service_insert() /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:add_uuid() sending add uuid command for index 0
bluetoothd[9537]: src/profile.c:register_profile() sender :1.73
bluetoothd[9537]: src/profile.c:create_ext() Created "Phone Book Access"
bluetoothd[9537]: src/profile.c:ext_adapter_probe() "Phone Book Access" probed
bluetoothd[9537]: src/profile.c:ext_start_servers() Phone Book Access listening on chan 15
bluetoothd[9537]: src/adapter.c:adapter_service_add() /org/bluez/hci0
bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Adding record with handle 0x10007 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000003-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000008-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 0000112f-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001130-0000-1000-8000-00805f9 bluetoothd[9537]: src/adapter.c:adapter_service_insert() /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:add_uuid() sending add uuid command for index 0
bluetoothd[9537]: src/profile.c:register_profile() sender :1.73
bluetoothd[9537]: src/profile.c:create_ext() Created "Synchronization"
bluetoothd[9537]: src/profile.c:ext_adapter_probe() "Synchronization" probed
bluetoothd[9537]: src/profile.c:ext_start_servers() Synchronization listening on chan 14
bluetoothd[9537]: src/adapter.c:adapter_service_add() /org/bluez/hci0
bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Adding record with handle 0x10008 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000003-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000008-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001104-0000-1000-8000-00805f9 bluetoothd[9537]: src/adapter.c:adapter_service_insert() /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:add_uuid() sending add uuid command for index 0
bluetoothd[9537]: src/profile.c:register_profile() sender :1.73
bluetoothd[9537]: src/profile.c:create_ext() Created "File Transfer"
bluetoothd[9537]: src/profile.c:ext_adapter_probe() "File Transfer" probed
bluetoothd[9537]: src/profile.c:ext_start_servers() File Transfer listening on PSM 4099
bluetoothd[9537]: src/profile.c:ext_start_servers() File Transfer listening on chan 10
bluetoothd[9537]: src/adapter.c:adapter_service_add() /org/bluez/hci0
bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Adding record with handle 0x10009 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000003-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000008-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001106-0000-1000-8000-00805f9 bluetoothd[9537]: src/adapter.c:adapter_service_insert() /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:add_uuid() sending add uuid command for index 0
bluetoothd[9537]: src/profile.c:register_profile() sender :1.73
bluetoothd[9537]: src/profile.c:create_ext() Created "Object Push"
bluetoothd[9537]: src/profile.c:ext_adapter_probe() "Object Push" probed
bluetoothd[9537]: src/profile.c:ext_start_servers() Object Push listening on PSM 4101
bluetoothd[9537]: src/profile.c:ext_start_servers() Object Push listening on chan 9
bluetoothd[9537]: src/adapter.c:adapter_service_add() /org/bluez/hci0
bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Adding record with handle 0x1000a bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000003-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000008-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001105-0000-1000-8000-00805f9 bluetoothd[9537]: src/adapter.c:adapter_service_insert() /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:add_uuid() sending add uuid command for index 0
bluetoothd[9537]: plugins/hostname.c:property_changed() static hostname: tkkaskin-mobl3.ger.corp.intel.com bluetoothd[9537]: plugins/hostname.c:property_changed() pretty hostname:

(  27.620|   0.019) D: [pulseaudio] bluez5-util.c: Unknown interface org.freedesktop.DBus.Introspectable found, skipping
(  27.620|   0.000) D: [pulseaudio] bluez5-util.c: Unknown interface org.bluez.AgentManager1 found, skipping
(  27.620|   0.000) D: [pulseaudio] bluez5-util.c: Unknown interface org.bluez.ProfileManager1 found, skipping
(  27.620|   0.000) D: [pulseaudio] bluez5-util.c: Unknown interface org.freedesktop.DBus.Introspectable found, skipping
(  27.620|   0.000) D: [pulseaudio] bluez5-util.c: Adapter /org/bluez/hci0 found
(  27.620|   0.000) D: [pulseaudio] bluez5-util.c: Registering /MediaEndpoint/A2DPSource on adapter /org/bluez/hci0
bluetoothd[9537]: plugins/hostname.c:update_name() name: tkkaskin-mobl3.ger.corp.intel.com
(  27.620|   0.000) D: [pulseaudio] bluez5-util.c: Registering /MediaEndpoint/A2DPSink on adapter /org/bluez/hci0
(  27.620|   0.000) D: [pulseaudio] bluez5-util.c: Unknown interface org.freedesktop.DBus.Properties found, skipping
(  27.620|   0.000) D: [pulseaudio] bluez5-util.c: Unknown interface org.bluez.Media1 found, skipping
(  27.620|   0.000) D: [pulseaudio] bluez5-util.c: Unknown interface org.bluez.NetworkServer1 found, skipping
(  27.621|   0.000) E: [pulseaudio] bluez4-util.c: org.bluez.Manager.GetProperties() failed: org.freedesktop.DBus.Error.UnknownMethod: Method "GetProperties" with signature "" on interface "org.bluez.Manager" doesn't exist

bluetoothd[9537]: src/adapter.c:adapter_set_name() name: tkkaskin-mobl3.ger.corp.intel.com bluetoothd[9537]: src/adapter.c:adapter_set_name() alias: tkkaskin-mobl3.ger.corp.intel.com bluetoothd[9537]: src/adapter.c:set_name() sending set local name command for index 0 bluetoothd[9537]: plugins/hostname.c:property_changed() chassis: laptop
bluetoothd[9537]: plugins/hostname.c:update_class() major: 0x01 minor: 0x03 bluetoothd[9537]: src/adapter.c:local_name_changed_callback() Name: tkkaskin-mobl3.ger.corp.intel.com bluetoothd[9537]: src/adapter.c:local_name_changed_callback() Short name:
bluetoothd[9537]: src/adapter.c:local_name_changed_callback() Current alias: tkkaskin-mobl3.ger.corp.intel.com bluetoothd[9537]: src/attrib-server.c:attrib_db_update() handle=0x0006

(  27.623|   0.002) D: [pulseaudio] bluez5-util.c: Properties changed in adapter /org/bluez/hci0
(  27.623|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.Properties, path=/org/bluez/hci0, member=PropertiesChanged

bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_register_sep() SEP 0xe4e1d0 registered: type:0 codec:0 seid:1 bluetoothd[9537]: src/adapter.c:adapter_service_add() /org/bluez/hci0
bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Adding record with handle 0x1000b bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000019-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 0000110a-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 0000110d-0000-1000-8000-00805f9 bluetoothd[9537]: src/adapter.c:adapter_service_insert() /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:add_uuid() sending add uuid command for index 0 bluetoothd[9537]: Endpoint registered: sender=:1.335 path=/MediaEndpoint/A2DPSource bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_register_sep() SEP 0xe491c0 registered: type:1 codec:0 seid:2

(  27.626|   0.003) D: [pulseaudio] bluez5-util.c: Properties changed in adapter /org/bluez/hci0
(  27.626|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.Properties, path=/org/bluez/hci0, member=PropertiesChanged

bluetoothd[9537]: src/adapter.c:adapter_service_add() /org/bluez/hci0
bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Adding record with handle 0x1000c bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000019-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 0000110b-0000-1000-8000-00805f9 bluetoothd[9537]: src/sdpd-service.c:add_record_to_server() Record pattern UUID 0000110d-0000-1000-8000-00805f9 bluetoothd[9537]: src/adapter.c:adapter_service_insert() /org/bluez/hci0
bluetoothd[9537]: src/adapter.c:add_uuid() sending add uuid command for index 0 bluetoothd[9537]: Endpoint registered: sender=:1.335 path=/MediaEndpoint/A2DPSink

(  27.629|   0.002) D: [pulseaudio] bluez5-util.c: Properties changed in adapter /org/bluez/hci0
(  27.629|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.Properties, path=/org/bluez/hci0, member=PropertiesChanged
bluetoothd[9537]: src/adapter.c:property_set_mode() sending Set Powered command for index 0
bluetoothd[9537]: src/adapter.c:dev_class_changed_callback() Class: 0x1c010c
bluetoothd[9537]: src/attrib-server.c:attrib_db_update() handle=0x0008
(  27.749|   0.119) D: [pulseaudio] bluez5-util.c: Properties changed in adapter /org/bluez/hci0
(  27.749|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.Properties, path=/org/bluez/hci0, member=PropertiesChanged

bluetoothd[9537]: src/adapter.c:property_set_mode_complete() Success (0x00) bluetoothd[9537]: src/adapter.c:new_settings_callback() Settings: 0x000002d3 bluetoothd[9537]: src/adapter.c:settings_changed() Changed settings: 0x00000001 bluetoothd[9537]: src/adapter.c:adapter_start() adapter /org/bluez/hci0 has been enabled bluetoothd[9537]: src/adapter.c:trigger_passive_scanning()

(  27.753|   0.003) D: [pulseaudio] bluez5-util.c: Properties changed in adapter /org/bluez/hci0
(  27.753|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.Properties, path=/org/bluez/hci0, member=PropertiesChanged

bluetoothd[9537]: src/agent.c:agent_ref() 0xe3f880: ref=1
bluetoothd[9537]: src/agent.c:register_agent() agent :1.67
bluetoothd[9537]: src/agent.c:add_default_agent() Default agent set to :1.67 /org/bluez/agent/gnome bluetoothd[9537]: src/agent.c:unregister_agent() agent :1.67
bluetoothd[9537]: src/agent.c:agent_disconnect() Agent :1.67 disconnected bluetoothd[9537]: src/agent.c:remove_default_agent() Default agent cleared bluetoothd[9537]: src/agent.c:agent_destroy() agent :1.67
bluetoothd[9537]: src/agent.c:agent_unref() 0xe3f880: ref=0
bluetoothd[9537]: src/agent.c:agent_ref() 0xe426f0: ref=1
bluetoothd[9537]: src/agent.c:register_agent() agent :1.67
bluetoothd[9537]: src/agent.c:add_default_agent() Default agent set to :1.67 /org/bluez/agent/gnome

*** bluetoothd startup complete, let's start bluetoothctl.

tanu@TKKASKIN_MOBL3_GER_CORP_INTEL_COM ~> bluetoothctl
[NEW] Controller 7C:E9:D3:EA:69:B2 tkkaskin-mobl3.ger.corp.intel.com [default]

*** Turn on the headset in discovery mode.

[bluetooth]# scan on
[bluetooth]# bluetoothd[9537]: src/adapter.c:start_discovery() sender :1.337 bluetoothd[9537]: src/adapter.c:trigger_start_discovery() bluetoothd[9537]: src/adapter.c:cancel_passive_scanning()
Discovery started
[bluetooth]# bluetoothd[9537]: src/adapter.c:start_discovery_timeout() bluetoothd[9537]: src/adapter.c:start_discovery_complete() status 0x00 bluetoothd[9537]: src/adapter.c:discovering_callback() hci0 type 7 discovering 1

(  61.290|  33.537) D: [pulseaudio] bluez5-util.c: Properties changed in adapter /org/bluez/hci0
(  61.290|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.Properties, path=/org/bluez/hci0, member=PropertiesChanged

[CHG] Controller 7C:E9:D3:EA:69:B2 Discovering: yes
[bluetooth]# bluetoothd[9537]: src/adapter.c:device_found_callback() hci0 addr 00:1E:DE:29:B7:3B, rssi -48 flags 0x0001 eir_len 31 bluetoothd[9537]: src/device.c:device_create() dst 00:1E:DE:29:B7:3B
bluetoothd[9537]: src/device.c:device_new() address 00:1E:DE:29:B7:3B
bluetoothd[9537]: src/device.c:device_new() Creating device /org/bluez/hci0/dev_00_1E_DE_29_B7_3B bluetoothd[9537]: src/device.c:device_set_legacy() legacy 0
bluetoothd[9537]: src/device.c:device_set_rssi() rssi -48
bluetoothd[9537]: src/device.c:device_set_class() /org/bluez/hci0/dev_00_1E_DE_29_B7_3B 0x240404 bluetoothd[9537]: src/adapter.c:confirm_name() hci0 bdaddr 00:1E:DE:29:B7:3B name_known 1
bluetoothd[9537]: src/adapter.c:confirm_name_complete() Confirm name complete for hci0

(  71.238|   9.947) D: [pulseaudio] bluez5-util.c: Unknown interface org.freedesktop.DBus.Introspectable found, skipping
(  71.238|   0.000) D: [pulseaudio] bluez5-util.c: Device /org/bluez/hci0/dev_00_1E_DE_29_B7_3B found
(  71.238|   0.000) D: [pulseaudio] bluez5-util.c: Address: 00:1E:DE:29:B7:3B
(  71.238|   0.000) D: [pulseaudio] bluez5-util.c: Alias: Nokia BH-505
(  71.238|   0.000) D: [pulseaudio] bluez5-util.c: Class: 2360324
(  71.238|   0.000) D: [pulseaudio] bluez5-util.c: UUIDs: 0000111e-0000-1000-8000-00805f9b34fb
(  71.238|   0.000) D: [pulseaudio] bluez5-util.c: UUIDs: 00001108-0000-1000-8000-00805f9b34fb
(  71.238|   0.000) D: [pulseaudio] bluez5-util.c: UUIDs: 0000110b-0000-1000-8000-00805f9b34fb
(  71.238|   0.000) D: [pulseaudio] bluez5-util.c: UUIDs: 0000110d-0000-1000-8000-00805f9b34fb
(  71.238|   0.000) D: [pulseaudio] bluez5-util.c: UUIDs: 0000110e-0000-1000-8000-00805f9b34fb
(  71.238|   0.000) D: [pulseaudio] bluez5-util.c: Adapter: /org/bluez/hci0
(  71.238|   0.000) D: [pulseaudio] bluez5-util.c: Unknown interface org.freedesktop.DBus.Properties found, skipping
(  71.239|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.ObjectManager, path=/, member=InterfacesAdded

[NEW] Device 00:1E:DE:29:B7:3B Nokia BH-505
[bluetooth]# bluetoothd[9537]: src/adapter.c:discovering_callback() hci0 type 7 discovering 0 bluetoothd[9537]: src/adapter.c:trigger_start_discovery()
bluetoothd[9537]: src/adapter.c:cancel_passive_scanning()

*** Headset found, let's turn off scanning.

[bluetooth]# scan off
[bluetooth]# bluetoothd[9537]: src/adapter.c:stop_discovery() sender :1.337 bluetoothd[9537]: src/adapter.c:discovery_destroy() owner :1.337 bluetoothd[9537]: src/device.c:device_set_rssi() rssi 0 bluetoothd[9537]: src/adapter.c:trigger_passive_scanning()

(  75.870|   4.631) D: [pulseaudio] bluez5-util.c: Properties changed in device /org/bluez/hci0/dev_00_1E_DE_29_B7_3B
(  75.870|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.Properties, path=/org/bluez/hci0/dev_00_1E_DE_29_B7_3B, member=PropertiesChanged
(  75.870|   0.000) D: [pulseaudio] bluez5-util.c: Properties changed in adapter /org/bluez/hci0
(  75.871|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.Properties, path=/org/bluez/hci0, member=PropertiesChanged

[CHG] Device 00:1E:DE:29:B7:3B RSSI is nil [CHG] Controller 7C:E9:D3:EA:69:B2 Discovering: no Discovery stopped

*** I was supposed to pair the device at this point, but I forgot that and went straight to connecting, which appeared to work anyway without explicit pairing step.

[bluetooth]# connect 00:1E:DE:29:B7:3B
Attempting to connect to 00:1E:DE:29:B7:3B
[bluetooth]# bluetoothd[9537]: src/device.c:connect_profiles() /org/bluez/hci0/dev_00_1E_DE_29_B7_3B (all), client :1.337 bluetoothd[9537]: src/device.c:btd_device_set_temporary() temporary 0
bluetoothd[9537]: src/device.c:connect_profiles() Resolving services for /org/bluez/hci0/dev_00_1E_DE_29_B7_3B
[bluetooth]# bluetoothd[9537]: src/adapter.c:connected_callback() hci0 device 00:1E:DE:29:B7:3B connected eir_len 19
( 97.389| 21.518) D: [pulseaudio] bluez5-util.c: Properties changed in device /org/bluez/hci0/dev_00_1E_DE_29_B7_3B
[CHG] Device 00:1E:DE:29:B7:3B Connected: yes
[bluetooth]# ( 97.389| 0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.Properties, path=/org/bluez/hci0/dev_00_1E_DE_29_B7_3B, member=PropertiesChanged
bluetoothd[9537]: src/device.c:device_probe_profiles() Probing profiles for device 00:1E:DE:29:B7:3B
bluetoothd[9537]: profiles/audio/avrcp.c:avrcp_controller_probe() path /org/bluez/hci0/dev_00_1E_DE_29_B7_3B
bluetoothd[9537]: profiles/audio/control.c:control_init() Registered interface org.bluez.MediaControl1 on path /org/bluez/hci0/dev_00_1E_DE_29_B7_3B bluetoothd[9537]: src/service.c:btd_service_ref() 0xe63670: ref=2
bluetoothd[9537]: src/service.c:change_state() 0xe63670: device 00:1E:DE:29:B7:3B profile avrcp-controller state changed: unavailable -> disconnected (0) bluetoothd[9537]: profiles/audio/avrcp.c:avrcp_target_probe() path /org/bluez/hci0/dev_00_1E_DE_29_B7_3B
bluetoothd[9537]: src/service.c:btd_service_ref() 0xe636f0: ref=2
bluetoothd[9537]: src/service.c:change_state() 0xe636f0: device 00:1E:DE:29:B7:3B profile audio-avrcp-target state changed: unavailable -> disconnected (0) bluetoothd[9537]: profiles/audio/a2dp.c:a2dp_sink_probe() path /org/bluez/hci0/dev_00_1E_DE_29_B7_3B
bluetoothd[9537]: profiles/audio/sink.c:sink_init() /org/bluez/hci0/dev_00_1E_DE_29_B7_3B
bluetoothd[9537]: src/service.c:btd_service_ref() 0xe63720: ref=2
bluetoothd[9537]: src/service.c:change_state() 0xe63720: device 00:1E:DE:29:B7:3B profile a2dp-sink state changed: unavailable -> disconnected (0) bluetoothd[9537]: src/device.c:device_svc_resolved() /org/bluez/hci0/dev_00_1E_DE_29_B7_3B err 0
bluetoothd[9537]: src/device.c:connect_profiles() /org/bluez/hci0/dev_00_1E_DE_29_B7_3B (all), client :1.337
bluetoothd[9537]: profiles/audio/a2dp.c:a2dp_sink_connect() path /org/bluez/hci0/dev_00_1E_DE_29_B7_3B
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_ref() 0xe61030: ref=1
bluetoothd[9537]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci0/dev_00_1E_DE_29_B7_3B: SINK_STATE_DISCONNECTED -> SINK_STATE_CONNECTING bluetoothd[9537]: profiles/audio/sink.c:sink_connect() stream creation in progress
bluetoothd[9537]: src/service.c:change_state() 0xe63720: device 00:1E:DE:29:B7:3B profile a2dp-sink state changed: disconnected -> connecting (0)

(  97.502|   0.113) D: [pulseaudio] bluez5-util.c: Unknown interface org.bluez.MediaControl1 found, skipping
(  97.503|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.ObjectManager, path=/, member=InterfacesAdded
(  97.503|   0.000) D: [pulseaudio] bluez5-util.c: Properties changed in device /org/bluez/hci0/dev_00_1E_DE_29_B7_3B
(  97.503|   0.000) D: [pulseaudio] bluez5-util.c: UUIDs: 0000110c-0000-1000-8000-00805f9b34fb
(  97.503|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.Properties, path=/org/bluez/hci0/dev_00_1E_DE_29_B7_3B, member=PropertiesChanged
[CHG] Device 00:1E:DE:29:B7:3B UUIDs:
	00001108-0000-1000-8000-00805f9b34fb
	0000110b-0000-1000-8000-00805f9b34fb
	0000110c-0000-1000-8000-00805f9b34fb
	0000110e-0000-1000-8000-00805f9b34fb
	0000111e-0000-1000-8000-00805f9b34fb

[bluetooth]# bluetoothd[9537]: src/adapter.c:new_link_key_callback() hci0 new key for 00:1E:DE:29:B7:3B type 4 pin_len 0 bluetoothd[9537]: src/device.c:device_set_bonded()
bluetoothd[9537]: src/device.c:device_bonding_complete() bonding (nil) status 0x00
bluetoothd[9537]: src/adapter.c:resume_discovery()

(  98.998|   1.495) D: [pulseaudio] bluez5-util.c: Properties changed in device /org/bluez/hci0/dev_00_1E_DE_29_B7_3B
(  98.998|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.Properties, path=/org/bluez/hci0/dev_00_1E_DE_29_B7_3B, member=PropertiesChanged

[CHG] Device 00:1E:DE:29:B7:3B Paired: yes
[bluetooth]# bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP: connected signaling channel to 00:1E:DE:29:B7:3B bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP imtu=672, omtu=895
bluetoothd[9537]: profiles/audio/avdtp.c:session_cb()
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_parse_resp() DISCOVER request succeeded
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 1 type 1 media 0 in use 0
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 2 type 1 media 0 in use 0
bluetoothd[9537]: profiles/audio/avdtp.c:session_cb()
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 1 type 1 media 0
bluetoothd[9537]: profiles/audio/avdtp.c:session_cb()
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_parse_resp() GET_CAPABILITIES request succeeded
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_get_capabilities_resp() seid 2 type 1 media 0
bluetoothd[9537]: profiles/audio/sink.c:discovery_complete() Discovery complete
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_ref() 0xe61030: ref=2
bluetoothd[9537]: profiles/audio/a2dp.c:setup_ref() 0xe42e00: ref=1
bluetoothd[9537]: profiles/audio/media.c:media_endpoint_async_call() Calling SelectConfiguration: name = :1.335 path = /MediaEndpoint/A2DPSource

( 101.778|   2.779) D: [pulseaudio] bluez4-util.c: dbus: interface=org.bluez.MediaEndpoint1, path=/MediaEndpoint/A2DPSource, member=SelectConfiguration
( 101.778|   0.000) D: [pulseaudio] bluez5-util.c: dbus: path=/MediaEndpoint/A2DPSource, interface=org.bluez.MediaEndpoint1, member=SelectConfiguration

bluetoothd[9537]: profiles/audio/a2dp.c:a2dp_config() a2dp_config: selected SEP 0xe4e1d0
bluetoothd[9537]: profiles/audio/a2dp.c:setup_ref() 0xe42e00: ref=2
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_set_configuration() 0xe61030: int_seid=1, acp_seid=1
bluetoothd[9537]: profiles/audio/a2dp.c:setup_unref() 0xe42e00: ref=1
bluetoothd[9537]: profiles/audio/avdtp.c:session_cb()
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_parse_resp() SET_CONFIGURATION request succeeded
bluetoothd[9537]: profiles/audio/a2dp.c:setconf_cfm() Source 0xe4e1d0: Set_Configuration_Cfm
bluetoothd[9537]: profiles/audio/media.c:media_endpoint_async_call() Calling SetConfiguration: name = :1.335 path = /MediaEndpoint/A2DPSource bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed: IDLE -> CONFIGURED

( 101.811|   0.032) D: [pulseaudio] bluez5-util.c: Unknown interface org.freedesktop.DBus.Introspectable found, skipping
( 101.811|   0.000) D: [pulseaudio] bluez5-util.c: Unknown interface org.bluez.MediaTransport1 found, skipping
( 101.811|   0.000) D: [pulseaudio] bluez5-util.c: Unknown interface org.freedesktop.DBus.Properties found, skipping
( 101.811|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus.ObjectManager, path=/, member=InterfacesAdded
( 101.811|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.bluez.MediaEndpoint1, path=/MediaEndpoint/A2DPSource, member=SetConfiguration
( 101.811|   0.000) D: [pulseaudio] bluez5-util.c: dbus: path=/MediaEndpoint/A2DPSource, interface=org.bluez.MediaEndpoint1, member=SetConfiguration
( 101.811|   0.000) D: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_00_1E_DE_29_B7_3B/fd0 state changed from disconnected to idle
( 101.811|   0.000) D: [pulseaudio] module-bluez5-discover.c: Loading module-bluez5-device path=/org/bluez/hci0/dev_00_1E_DE_29_B7_3B
( 101.813|   0.001) I: [pulseaudio] module-card-restore.c: Restored profile 'a2dp' for card bluez_card.00_1E_DE_29_B7_3B.
( 101.813|   0.000) I: [pulseaudio] module-card-restore.c: Restoring port latency offsets for card bluez_card.00_1E_DE_29_B7_3B.
( 101.813|   0.000) I: [pulseaudio] card.c: Created 1 "bluez_card.00_1E_DE_29_B7_3B"
( 101.813|   0.000) D: [pulseaudio] module-bluez5-device.c: Acquiring transport /org/bluez/hci0/dev_00_1E_DE_29_B7_3B/fd0

bluetoothd[9537]: profiles/audio/transport.c:media_owner_create() Owner created: sender=:1.335
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_ref() 0xe61030: ref=3
bluetoothd[9537]: profiles/audio/a2dp.c:a2dp_sep_lock() SEP 0xe4e1d0 locked
bluetoothd[9537]: profiles/audio/a2dp.c:setup_ref() 0xe42e00: ref=2
bluetoothd[9537]: profiles/audio/transport.c:transport_set_state() State changed /org/bluez/hci0/dev_00_1E_DE_29_B7_3B/fd0: TRANSPORT_STATE_IDLE -> TRANSPORT_STATE_REQUESTING bluetoothd[9537]: profiles/audio/transport.c:media_request_create() Request created: method=Acquire id=3
bluetoothd[9537]: profiles/audio/transport.c:media_owner_add() Owner :1.335 Request Acquire
bluetoothd[9537]: profiles/audio/transport.c:media_transport_set_owner() Transport /org/bluez/hci0/dev_00_1E_DE_29_B7_3B/fd0 Owner :1.335 bluetoothd[9537]: profiles/audio/avdtp.c:session_cb()
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_parse_resp() OPEN request succeeded
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP: connected transport channel to 00:1E:DE:29:B7:3B
bluetoothd[9537]: profiles/audio/avdtp.c:handle_transport_connect() Flushable packets enabled
bluetoothd[9537]: profiles/audio/avdtp.c:handle_transport_connect() sk 29, omtu 895, send buffer size 106496
bluetoothd[9537]: profiles/audio/a2dp.c:open_cfm() Source 0xe4e1d0: Open_Cfm
bluetoothd[9537]: profiles/audio/a2dp.c:setup_unref() 0xe42e00: ref=1
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed: CONFIGURED -> OPEN
bluetoothd[9537]: src/service.c:change_state() 0xe63720: device 00:1E:DE:29:B7:3B profile a2dp-sink state changed: connecting -> connected (0) bluetoothd[9537]: src/device.c:device_profile_connected() a2dp-sink Success (0)
bluetoothd[9537]: src/device.c:device_profile_connected() returning response to :1.337
bluetoothd[9537]: plugins/policy.c:policy_connect() /org/bluez/hci0/dev_00_1E_DE_29_B7_3B profile avrcp-controller
bluetoothd[9537]: profiles/audio/avrcp.c:avrcp_connect() path /org/bluez/hci0/dev_00_1E_DE_29_B7_3B
bluetoothd[9537]: profiles/audio/avctp.c:avctp_set_state() AVCTP Connecting
bluetoothd[9537]: src/service.c:change_state() 0xe63670: device 00:1E:DE:29:B7:3B profile avrcp-controller state changed: disconnected -> connecting (0) Connection successful
[bluetooth]# bluetoothd[9537]: src/service.c:btd_service_ref() 0xe63720: ref=3
bluetoothd[9537]: plugins/policy.c:service_cb() Added a2dp-sink reconnect 0
bluetoothd[9537]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci0/dev_00_1E_DE_29_B7_3B: SINK_STATE_CONNECTING -> SINK_STATE_CONNECTED bluetoothd[9537]: profiles/audio/transport.c:transport_update_playing() /org/bluez/hci0/dev_00_1E_DE_29_B7_3B/fd0 State=TRANSPORT_STATE_REQUESTING Playing=0 bluetoothd[9537]: profiles/audio/avdtp.c:session_cb()
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_parse_resp() START request succeeded
bluetoothd[9537]: profiles/audio/a2dp.c:start_cfm() Source 0xe4e1d0: Start_Cfm
bluetoothd[9537]: /org/bluez/hci0/dev_00_1E_DE_29_B7_3B/fd0: fd(29) ready
bluetoothd[9537]: profiles/audio/transport.c:media_owner_remove() Owner :1.335 Request Acquire
bluetoothd[9537]: profiles/audio/transport.c:transport_set_state() State changed /org/bluez/hci0/dev_00_1E_DE_29_B7_3B/fd0: TRANSPORT_STATE_REQUESTING -> TRANSPORT_STATE_ACTIVE bluetoothd[9537]: profiles/audio/a2dp.c:setup_unref() 0xe42e00: ref=0
bluetoothd[9537]: profiles/audio/a2dp.c:setup_free() 0xe42e00
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_unref() 0xe61030: ref=2
bluetoothd[9537]: profiles/audio/avdtp.c:avdtp_sep_set_state() stream state changed: OPEN -> STREAMING
bluetoothd[9537]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci0/dev_00_1E_DE_29_B7_3B: SINK_STATE_CONNECTED -> SINK_STATE_PLAYING bluetoothd[9537]: profiles/audio/transport.c:transport_update_playing() /org/bluez/hci0/dev_00_1E_DE_29_B7_3B/fd0 State=TRANSPORT_STATE_ACTIVE Playing=1

( 102.747|   0.934) E: [pulseaudio] bluez5-util.c: Transport Acquire() failed for transport /org/bluez/hci0/dev_00_1E_DE_29_B7_3B/fd0 (Message did not receive a reply (timeout by message bus))
( 102.747|   0.000) D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
( 102.747|   0.000) I: [pulseaudio] card.c: Changed profile of card 1 "bluez_card.00_1E_DE_29_B7_3B" to off
( 102.747|   0.000) I: [pulseaudio] module.c: Loaded "module-bluez5-device" (index: #24; argument: "path=/org/bluez/hci0/dev_00_1E_DE_29_B7_3B").
( 102.748|   0.000) D: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_00_1E_DE_29_B7_3B/fd0 available for profile a2dp_sink
( 102.748|   0.000) D: [pulseaudio] bluez5-util.c: Bluetooth daemon disappeared

*** Note the above message, apparently bluetoothd disconnected from D-Bus. I suppose that should never happen.

( 102.748|   0.000) D: [pulseaudio] bluez5-util.c: Transport /org/bluez/hci0/dev_00_1E_DE_29_B7_3B/fd0 state changed from idle to disconnected
( 102.748|   0.000) D: [pulseaudio] card.c: Setting card bluez_card.00_1E_DE_29_B7_3B profile a2dp_sink to availability status no
( 102.748|   0.000) D: [pulseaudio] device-port.c: Setting port headset-output to status no
( 102.748|   0.000) D: [pulseaudio] core-subscribe.c: Dropped redundant event due to change event.
( 102.748|   0.000) D: [pulseaudio] module-bluez5-discover.c: Unregistering module for /org/bluez/hci0/dev_00_1E_DE_29_B7_3B
( 102.748|   0.000) D: [pulseaudio] module-bluez5-device.c: Unloading module for device /org/bluez/hci0/dev_00_1E_DE_29_B7_3B
[DEL] Controller 7C:E9:D3:EA:69:B2 tkkaskin-mobl3.ger.corp.intel.com [default]
( 102.748|   0.000) I: [pulseaudio] module.c: Unloading "module-bluez5-device" (index: #24).
[bluetooth]# ( 102.748|   0.000) I: [pulseaudio] card.c: Freed 1 "bluez_card.00_1E_DE_29_B7_3B"
( 102.748|   0.000) D: [pulseaudio] core-subscribe.c: Dropped redundant event due to remove event.
( 102.748|   0.000) I: [pulseaudio] module.c: Unloaded "module-bluez5-device" (index: #24).
( 102.749|   0.000) D: [pulseaudio] bluez4-util.c: dbus: interface=org.freedesktop.DBus, path=/org/freedesktop/DBus, member=NameOwnerChanged
( 102.749|   0.000) D: [pulseaudio] bluez4-util.c: Bluetooth daemon disappeared.

[bluetooth]# bluetoothd[9537]: profiles/audio/avctp.c:avctp_confirm_cb() AVCTP: incoming connect from 00:1E:DE:29:B7:3B bluetoothd[9537]: Control: Refusing unexpected connect
bluetoothd[9537]: profiles/audio/avctp.c:avctp_set_state() AVCTP Disconnected
bluetoothd[9537]: connect error: Connection refused (111)

Hi Tanu,

It is very likely a problem with SELinux (either set it to disabled or permissive should make it work) blocking fd passing and making us disconnect, also note that I have also start working on porting the patches here:

https://gitorious.org/pulseaudio/vudentzs-mainline/commits/fceee2a876110186f8fdc87743e3ee7f7bf8c1ae

I did not went through the comments you did so perhaps you can ignore them for now, but I do include some on top that makes it work with oFono.

Luiz Augusto von Dentz

Thanks for the tip, disabling SELinux seemed to do at least something. I can't test the use case, because now pulseaudio complains that "properties changed in unknown adapter", i.e. somehow pulseaudio doesn't find /org/bluez/hci0 during initialization and then is very confused when changes happen in that adapter. I'll have to debug this later.

Tanu