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

Failed to connect: org.bluez.Error.Failed

Open alembiq opened this issue 3 years ago • 3 comments

version: 5.55

I have a new audio receiver but cannot connect to it from Linux. There is no problem connecting from windows and android so I assume the device is fine. I'm turning the device to pairing mode, scanning for it on Linux, trying to connect, pairing looks good. However while it tries to connect it fails. I didn't noticed anything obvious in the logs :(

please help...

bluetoothctl scan on

Discovery started
[CHG] Controller 98:AF:65:F8:1C:12 Discovering: yes
[NEW] Device 00:09:B0:3A:E7:D0 Onkyo TX-NR6100
[CHG] Device 00:09:B0:3A:E7:D0 TxPower: 0
[CHG] Device 00:09:B0:3A:E7:D0 Modalias: usb:v1D6Bp0246d052B
[CHG] Device 00:09:B0:3A:E7:D0 UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Device 00:09:B0:3A:E7:D0 UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Device 00:09:B0:3A:E7:D0 UUIDs: 0000110e-0000-1000-8000-00805f9b34fb
[CHG] Device 00:09:B0:3A:E7:D0 UUIDs: 0000110b-0000-1000-8000-00805f9b34fb

bluetoothctl pair 00:09:B0:3A:E7:D0

Attempting to pair with 00:09:B0:3A:E7:D0
[CHG] Device 00:09:B0:3A:E7:D0 Connected: yes
[CHG] Device 00:09:B0:3A:E7:D0 UUIDs: 0000110b-0000-1000-8000-00805f9b34fb
[CHG] Device 00:09:B0:3A:E7:D0 UUIDs: 0000110e-0000-1000-8000-00805f9b34fb
[CHG] Device 00:09:B0:3A:E7:D0 UUIDs: 00001200-0000-1000-8000-00805f9b34fb
[CHG] Device 00:09:B0:3A:E7:D0 UUIDs: 00001800-0000-1000-8000-00805f9b34fb
[CHG] Device 00:09:B0:3A:E7:D0 UUIDs: 00001801-0000-1000-8000-00805f9b34fb
[CHG] Device 00:09:B0:3A:E7:D0 ServicesResolved: yes
[CHG] Device 00:09:B0:3A:E7:D0 Paired: yes
Pairing successful

bluetoothctl connect 00:09:B0:3A:E7:D0

Attempting to connect to 00:09:B0:3A:E7:D0
[CHG] Device 00:09:B0:3A:E7:D0 Connected: yes
Failed to connect: org.bluez.Error.Failed

/var/log/debug

Sep  6 14:50:23 verdandi bluetoothd[2707789]: src/device.c:btd_device_set_temporary() temporary 0
Sep  6 14:50:23 verdandi bluetoothd[2707789]: src/agent.c:agent_ref() 0x555fb9f64870: ref=2
Sep  6 14:50:23 verdandi bluetoothd[2707789]: src/device.c:bonding_request_new() Requesting bonding for 00:09:B0:3A:E7:D0
Sep  6 14:50:23 verdandi bluetoothd[2707789]: src/agent.c:agent_ref() 0x555fb9f64870: ref=3
Sep  6 14:50:23 verdandi bluetoothd[2707789]: src/agent.c:agent_unref() 0x555fb9f64870: ref=2
Sep  6 14:50:23 verdandi bluetoothd[2707789]: src/adapter.c:suspend_discovery() 
Sep  6 14:50:23 verdandi bluetoothd[2707789]: src/adapter.c:adapter_bonding_attempt() hci1 bdaddr 00:09:B0:3A:E7:D0 type 0 io_cap 0x04
Sep  6 14:50:23 verdandi bluetoothd[2707789]: src/adapter.c:add_whitelist_complete() 00:09:B0:3A:E7:D0 added to kernel whitelist
Sep  6 14:50:26 verdandi bluetoothd[2707789]: src/adapter.c:connected_callback() hci1 device 00:09:B0:3A:E7:D0 connected eir_len 22
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/adapter.c:new_link_key_callback() hci1 new key for 00:09:B0:3A:E7:D0 type 7 pin_len 0 store_hint 1
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/device.c:device_set_bonded() 
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/device.c:device_bonding_complete() bonding 0x555fb9f940e0 status 0x00
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/device.c:device_bonding_complete() Proceeding with service discovery
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/agent.c:agent_unref() 0x555fb9f64870: ref=1
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/adapter.c:resume_discovery() 
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/adapter.c:pair_device_complete() Success (0x00)
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/adapter.c:bonding_attempt_complete() hci1 bdaddr 00:09:B0:3A:E7:D0 type 0 status 0x0
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/device.c:device_bonding_complete() bonding (nil) status 0x00
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/adapter.c:resume_discovery() 
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/adapter.c:new_csrk_callback() hci1 new CSRK for 00:09:B0:3A:E7:D0 type 1
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/adapter.c:new_csrk_callback() hci1 new CSRK for 00:09:B0:3A:E7:D0 type 0
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/adapter.c:new_long_term_key_callback() hci1 new LTK for 00:09:B0:3A:E7:D0 type 2 enc_size 16
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/device.c:device_set_bonded() 
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/device.c:device_bonding_complete() bonding (nil) status 0x00
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/adapter.c:resume_discovery() 
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/device.c:device_probe_profiles() Probing profiles for device 00:09:B0:3A:E7:D0
Sep  6 14:50:27 verdandi bluetoothd[2707789]: profiles/gap/gas.c:gap_probe() GAP profile probe (00:09:B0:3A:E7:D0)
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/service.c:change_state() 0x555fb9f9b0d0: device 00:09:B0:3A:E7:D0 profile gap-profile state changed: unavailable -> disconnected (0)
Sep  6 14:50:27 verdandi bluetoothd[2707789]: profiles/audio/avrcp.c:avrcp_controller_probe() path /org/bluez/hci1/dev_00_09_B0_3A_E7_D0
Sep  6 14:50:27 verdandi bluetoothd[2707789]: profiles/audio/control.c:control_init() Registered interface org.bluez.MediaControl1 on path /org/bluez/hci1/dev_00_09_B0_3A_E7_D0
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/service.c:btd_service_ref() 0x555fb9fa7720: ref=2
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/service.c:change_state() 0x555fb9fa7720: device 00:09:B0:3A:E7:D0 profile avrcp-controller state changed: unavailable -> disconnected (0)
Sep  6 14:50:27 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:a2dp_sink_probe() path /org/bluez/hci1/dev_00_09_B0_3A_E7_D0
Sep  6 14:50:27 verdandi bluetoothd[2707789]: profiles/audio/sink.c:sink_init() /org/bluez/hci1/dev_00_09_B0_3A_E7_D0
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/service.c:btd_service_ref() 0x555fb9fa7a90: ref=2
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/service.c:change_state() 0x555fb9fa7a90: device 00:09:B0:3A:E7:D0 profile a2dp-sink state changed: unavailable -> disconnected (0)
Sep  6 14:50:27 verdandi bluetoothd[2707789]: src/device.c:device_svc_resolved() /org/bluez/hci1/dev_00_09_B0_3A_E7_D0 err 0
Sep  6 14:50:32 verdandi bluetoothd[2707789]: src/adapter.c:dev_disconnected() Device 00:09:B0:3A:E7:D0 disconnected, reason 2
Sep  6 14:50:32 verdandi bluetoothd[2707789]: src/adapter.c:adapter_remove_connection() 
Sep  6 14:50:32 verdandi bluetoothd[2707789]: plugins/policy.c:disconnect_cb() reason 2
Sep  6 14:50:32 verdandi bluetoothd[2707789]: src/adapter.c:bonding_attempt_complete() hci1 bdaddr 00:09:B0:3A:E7:D0 type 0 status 0xe
Sep  6 14:50:32 verdandi bluetoothd[2707789]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
Sep  6 14:50:32 verdandi bluetoothd[2707789]: src/device.c:device_bonding_failed() status 14
Sep  6 14:50:32 verdandi bluetoothd[2707789]: src/adapter.c:resume_discovery() 
Sep  6 14:50:42 verdandi bluetoothd[2707789]: src/device.c:device_remove() Removing device /org/bluez/hci1/dev_48_B0_2D_5D_60_8E
Sep  6 14:50:42 verdandi bluetoothd[2707789]: src/device.c:btd_device_unref() Freeing device /org/bluez/hci1/dev_48_B0_2D_5D_60_8E
Sep  6 14:50:42 verdandi bluetoothd[2707789]: src/device.c:device_free() 0x555fb9f9a070
Sep  6 14:50:43 verdandi bluetoothd[2707789]: src/device.c:device_remove() Removing device /org/bluez/hci1/dev_68_14_01_9B_15_E0
Sep  6 14:50:43 verdandi bluetoothd[2707789]: src/device.c:btd_device_unref() Freeing device /org/bluez/hci1/dev_68_14_01_9B_15_E0
Sep  6 14:50:43 verdandi bluetoothd[2707789]: src/device.c:device_free() 0x555fb9f67160
Sep  6 14:50:57 verdandi bluetoothd[2707789]: src/device.c:connect_profiles() /org/bluez/hci1/dev_00_09_B0_3A_E7_D0 (all), client :1.486779
Sep  6 14:50:57 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:a2dp_sink_connect() path /org/bluez/hci1/dev_00_09_B0_3A_E7_D0
Sep  6 14:50:57 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_ref() 0x555fb9fa3f00: ref=1
Sep  6 14:50:57 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_ref() 0x555fb9fa3f00: ref=2
Sep  6 14:50:57 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:setup_ref() 0x555fb9f7bd80: ref=1
Sep  6 14:50:57 verdandi bluetoothd[2707789]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci1/dev_00_09_B0_3A_E7_D0: SINK_STATE_DISCONNECTED -> SINK_STATE_CONNECTING
Sep  6 14:50:57 verdandi bluetoothd[2707789]: profiles/audio/sink.c:sink_connect() stream creation in progress
Sep  6 14:50:57 verdandi bluetoothd[2707789]: src/service.c:change_state() 0x555fb9fa7a90: device 00:09:B0:3A:E7:D0 profile a2dp-sink state changed: disconnected -> connecting (0)
Sep  6 14:50:58 verdandi bluetoothd[2707789]: src/adapter.c:connected_callback() hci1 device 00:09:B0:3A:E7:D0 connected eir_len 22
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP: connected signaling channel to 00:09:B0:3A:E7:D0
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_connect_cb() AVDTP imtu=672, omtu=1024
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_register_remote_sep() seid 1 type 0 media 0 delay_reporting true
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:register_remote_sep() Found remote SEP: /org/bluez/hci1/dev_00_09_B0_3A_E7_D0/sep1
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_register_remote_sep() seid 2 type 0 media 0 delay_reporting true
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:register_remote_sep() Found remote SEP: /org/bluez/hci1/dev_00_09_B0_3A_E7_D0/sep2
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_register_remote_sep() seid 3 type 1 media 0 delay_reporting true
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:register_remote_sep() Found remote SEP: /org/bluez/hci1/dev_00_09_B0_3A_E7_D0/sep3
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_register_remote_sep() seid 4 type 1 media 0 delay_reporting true
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:register_remote_sep() Found remote SEP: /org/bluez/hci1/dev_00_09_B0_3A_E7_D0/sep4
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_register_remote_sep() seid 5 type 1 media 0 delay_reporting true
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:register_remote_sep() Found remote SEP: /org/bluez/hci1/dev_00_09_B0_3A_E7_D0/sep5
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:session_cb() 
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_parse_resp() DISCOVER request succeeded
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 4 type 1 media 0 in use 0
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_discover_resp() seid 5 type 1 media 0 in use 0
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:discover_cb() version 0x0103 err (nil)
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/sink.c:discovery_complete() Discovery complete
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:setup_ref() 0x555fb9f7bd80: ref=2
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:setup_ref() 0x555fb9f7bd80: ref=3
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/media.c:media_endpoint_async_call() Calling SelectConfiguration: name = :1.486667 path = /MediaEndpoint/A2DPSource/sbc
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:setup_unref() 0x555fb9f7bd80: ref=2
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:a2dp_config() a2dp_config: selected SEP 0x555fb9fa2950
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:setup_ref() 0x555fb9f7bd80: ref=3
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_set_configuration() 0x555fb9fa3f00: int_seid=2, acp_seid=4
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:setup_unref() 0x555fb9f7bd80: ref=2
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:setup_unref() 0x555fb9f7bd80: ref=1
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:session_cb() 
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:setconf_cfm() Source 0x555fb9fa2950: Set_Configuration_Cfm
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:setup_ref() 0x555fb9f7bd80: ref=2
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_unref() 0x555fb9fa3f00: ref=1
Sep  6 14:50:59 verdandi bluetoothd[2707789]: src/service.c:change_state() 0x555fb9fa7a90: device 00:09:B0:3A:E7:D0 profile a2dp-sink state changed: connecting -> disconnected (-5)
Sep  6 14:50:59 verdandi bluetoothd[2707789]: src/device.c:device_profile_connected() a2dp-sink Input/output error (5)
Sep  6 14:50:59 verdandi bluetoothd[2707789]: src/device.c:device_profile_connected() returning response to :1.486779
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:setup_unref() 0x555fb9f7bd80: ref=1
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:setup_unref() 0x555fb9f7bd80: ref=0
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:setup_free() 0x555fb9f7bd80
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_unref() 0x555fb9fa3f00: ref=0
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_ref() 0x555fb9fa3f00: ref=1
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:set_disconnect_timer() timeout 0
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_ref() 0x555fb9fa3f00: ref=2
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:connection_lost() Disconnected from 00:09:B0:3A:E7:D0
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:abort_cfm() Source 0x555fb9fa2950: Abort_Cfm
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_sep_set_state() stream state change failed: Input/output error
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/sink.c:sink_set_state() State changed /org/bluez/hci1/dev_00_09_B0_3A_E7_D0: SINK_STATE_CONNECTING -> SINK_STATE_DISCONNECTED
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/a2dp.c:channel_remove() chan 0x555fb9f7e540
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_unref() 0x555fb9fa3f00: ref=1
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_unref() 0x555fb9fa3f00: ref=0
Sep  6 14:50:59 verdandi bluetoothd[2707789]: profiles/audio/avdtp.c:avdtp_free() 0x555fb9fa3f00
Sep  6 14:51:01 verdandi bluetoothd[2707789]: src/adapter.c:dev_disconnected() Device 00:09:B0:3A:E7:D0 disconnected, reason 2
Sep  6 14:51:01 verdandi bluetoothd[2707789]: src/adapter.c:adapter_remove_connection() 
Sep  6 14:51:01 verdandi bluetoothd[2707789]: plugins/policy.c:disconnect_cb() reason 2
Sep  6 14:51:01 verdandi bluetoothd[2707789]: src/adapter.c:bonding_attempt_complete() hci1 bdaddr 00:09:B0:3A:E7:D0 type 0 status 0xe
Sep  6 14:51:01 verdandi bluetoothd[2707789]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
Sep  6 14:51:01 verdandi bluetoothd[2707789]: src/device.c:device_bonding_failed() status 14
Sep  6 14:51:01 verdandi bluetoothd[2707789]: src/adapter.c:resume_discovery()

alembiq avatar Sep 06 '22 13:09 alembiq

@alembiq please add the HCI trace (use btmon -w)

Vudentz avatar Sep 06 '22 18:09 Vudentz

@Vudentz i hope it will help :) hcitrace.txt

alembiq avatar Sep 10 '22 19:09 alembiq

Somehow I've managed to connect to it and keep it connected. But I'm not sure what was the solution :(

I can select it as the prefered audio output, but I'm not hearing any sound :( when I'm using by bt headphones it works, but not with the receiver :(

Device 00:09:B0:3A:E7:D0 (public)
        Name: Onkyo TX-NR6100
        Alias: Onkyo TX-NR6100
        Class: 0x00240400
        Icon: audio-card
        Paired: yes
        Trusted: yes
        Blocked: no
        Connected: yes
        LegacyPairing: no
        UUID: Audio Sink                (0000110b-0000-1000-8000-00805f9b34fb)
        UUID: A/V Remote Control Target (0000110c-0000-1000-8000-00805f9b34fb)
        UUID: A/V Remote Control        (0000110e-0000-1000-8000-00805f9b34fb)
        UUID: PnP Information           (00001200-0000-1000-8000-00805f9b34fb)
        UUID: Generic Access Profile    (00001800-0000-1000-8000-00805f9b34fb)
        UUID: Generic Attribute Profile (00001801-0000-1000-8000-00805f9b34fb)
        Modalias: usb:v1D6Bp0246d052B

alembiq avatar Sep 15 '22 10:09 alembiq