bluetoothd Permission denied (13) when connecting A2DP headset

[Murz]

I have a Nokia BH-504 bluetooth headset and Ubuntu Karmic.
Via blueman-applet (I try 1.10 and 1.20 versions) I can successfully add and pair the bluetooth headset, but can't connect A2DP sink profile (and Headset Service too).
When I try to connect, it tries, but show the error "Connection Failed: Stream setup failed".
In /var/log/daemon.log I see the record at same time:
Sep 27 17:09:33 kit bluetoothd[1940]: Permission denied (13)

This record shows each time when I try to connect.

I try to pair and connect via priveleged users, via kdesudo, via root user and always see the permission error.
On Windows I have succesfully connected this headset and computer.

At now I have:
bluez 4.51-0ubuntu2
blueman 1.20+r496+200909251843~karmic

Which permissions does bluetoothd needs? How I can give him this permissions?

[Murz (murznn)]

Updating to blueman release (1.20-1~ppa1k) didn't help. I try to remove all and reconnect again but no good news. The device added succesfully, but can't connect.
I have try two devices - Nokia BH-504 and Motorola S705 (password is 0000) and both can't connect.

I have found a hcidump tool and attach an output of "sudo hcidump -X -V" as attachment. In the dump I see the "Authentication Failure" error. But in pairing there are no errors.

Where can I look which password is used for connect?

[Murz (murznn)]

Same problem on another 2 computers with Ubuntu Karmic:
Dec 14 09:50:44 axe bluetoothd[2971]: Permission denied (13)
Dec 14 10:31:24 boss bluetoothd[1897]: Permission denied (13)

Bluez version is 4.51-0ubuntu2
Bluetooth dongle:
Bus 003 Device 004: ID 1131:1004 Integrated System Solution Corp. Bluetooth Device

[Murz (murznn)]

Updating to bluez 4.57-0ubuntu1 and blueman 1.21-1~ppa1k didn't solve the problem.

[Murz (murznn)]

Problem still here after upgrading to bluez 4.60-0ubuntu1
Can anybody tell me how I can look some debug output of this error? Which permissions are denied?

[Murz (murznn)]

Output of bluetoothd -d -n on connect process:

bluetoothd[22040]: avdtp_ref(0x7f6b42f9e750): ref=2
bluetoothd[22040]: stream creation in progress
bluetoothd[22040]: adapter_get_device(00:22:FC:74:AA:3C)
bluetoothd[22040]: Permission denied (13)
bluetoothd[22040]: Disconnected from 00:22:FC:74:AA:3C
bluetoothd[22040]: avdtp_unref(0x7f6b42f9e750): ref=1
bluetoothd[22040]: connect:connect XCASE detected
bluetoothd[22040]: avdtp_unref(0x7f6b42f9e750): ref=0
bluetoothd[22040]: avdtp_unref(0x7f6b42f9e750): freeing session and removing from list
bluetoothd[22040]: Stream setup failed, after XCASE connect:connect

[Murz (murznn)]

I try upgrade to lucid but this isn't help, same error!

[Murz (murznn)]

I try to load livecd Ubuntu Karmic & Fedora 12 livecd, and got this error too.

[Murz (murznn)]

Here is hcidump of a2dp connect process:

< HCI Command: Create Connection (0x01|0x0005) plen 13
> HCI Event: Command Status (0x0f) plen 4
> HCI Event: Connect Complete (0x03) plen 11
< HCI Command: Read Remote Supported Features (0x01|0x001b) plen 2
> HCI Event: Command Status (0x0f) plen 4
> HCI Event: Page Scan Repetition Mode Change (0x20) plen 7
< HCI Command: Read RSSI (0x05|0x0005) plen 2
> HCI Event: Max Slots Change (0x1b) plen 3
> HCI Event: Command Complete (0x0e) plen 7
< HCI Command: Read Link Quality (0x05|0x0003) plen 2
> HCI Event: Command Complete (0x0e) plen 7
< HCI Command: Read Transmit Power Level (0x03|0x002d) plen 3
> HCI Event: Command Complete (0x0e) plen 7
> HCI Event: Connection Packet Type Changed (0x1d) plen 5
> HCI Event: Read Remote Supported Features (0x0b) plen 11
< ACL data: handle 1 flags 0x02 dlen 10
    L2CAP(s): Info req: type 2
> HCI Event: Number of Completed Packets (0x13) plen 5
< HCI Command: Remote Name Request (0x01|0x0019) plen 10
> ACL data: handle 1 flags 0x02 dlen 16
    L2CAP(s): Info rsp: type 2 result 0
      Extended feature mask 0x0000
< ACL data: handle 1 flags 0x02 dlen 12
    L2CAP(s): Connect req: psm 25 scid 0x0040
> HCI Event: Command Status (0x0f) plen 4
> HCI Event: Number of Completed Packets (0x13) plen 5
> ACL data: handle 1 flags 0x02 dlen 16
    L2CAP(s): Connect rsp: dcid 0x0041 scid 0x0040 result 1 status 2
      Connection pending - Authorization pending
> HCI Event: Remote Name Req Complete (0x07) plen 255
< HCI Command: Read RSSI (0x05|0x0005) plen 2
> HCI Event: Command Complete (0x0e) plen 7
< HCI Command: Read Link Quality (0x05|0x0003) plen 2
> HCI Event: Command Complete (0x0e) plen 7
< HCI Command: Read Transmit Power Level (0x03|0x002d) plen 3
> HCI Event: Command Complete (0x0e) plen 7
< HCI Command: Read RSSI (0x05|0x0005) plen 2
> HCI Event: Command Complete (0x0e) plen 7
< HCI Command: Read Link Quality (0x05|0x0003) plen 2
> HCI Event: Command Complete (0x0e) plen 7
< HCI Command: Read Transmit Power Level (0x03|0x002d) plen 3
> HCI Event: Command Complete (0x0e) plen 7
> HCI Event: Disconn Complete (0x05) plen 4

[schaze (schaze)]

Hi,

I have this problem too. But interestingly it has been working once. The only related change I did since then was to uninstall the "linux-backports-modules-alsa-karmic-generic" package (due to a problem with my avermedia DVD EZmake USB gold)
Maybe someone can try installing the alsa backports to see if it fixes the problem (I can' t at the moment because of the prob with my avermedia).

/schaze

[Baptiste Mille-Mathias (bmillemathias)]

Hello,

did someone tried to strace the process ?
perhaps contacting the bluez developers might help?

[Murz (murznn)]

Baptiste Mille-Mathias, please tell me how I can strace this process, i'll try this.

I have wrote about this problem in bluez user mailing list - http://marc.info/?l=linux-bluetooth&m=126391643201558&w=2 but give no answer :(
Upgrading to lucid and latest blueman, bluez didn't solve the problem.

[Murz (murznn)]

schaze, installing linux-backports-modules-alsa-lucid-generic (I use lucid) didn't solve the problem for me, see the same error when trying to connect:
Apr 13 08:48:05 axe bluetoothd[1266]: Permission denied (13)

[Murz (murznn)]

I'll try to run bluetoothd daemon via strace but got nothing.
I got a backtrace via 'strace -p' command attached to bluetoothd pid, the result is attached.

[Murz (murznn)]

schaze, please add your strace too for additional info.
Can I give more information for detecting the source of the bug?

[Murz (murznn)]

Baptiste Mille-Mathias, upgrading bluez to 4.63-0ubuntu4 from your ppa didn't help too.
strace of connection process is attached.

[[e-mail] (watchingman)]

I add workround in http://blueman-project.org/forum/viewtopic.php?f=5&t=286.

and It may result from bluez' API CreateDevice.

there is just fine if use CreatePairedDevice in action "Add" like as the script "simple-agent" packed up in bluez sourcecode.

you may test.

[Murz (murznn)]

Seems that this fixed in bluez, I have successfully pair with Ubuntu Lucid and bluez version 4.70-0ubuntu2

[Bernie Innocenti (codewiz)]

I'm still experiencing this bug on oneiric with bluez_4.96-0ubuntu4 and jWin bluetooth headphones. The only way I have to reconnect the headphones is deleting the device and repairing it.

Any suggestion on how to debug this?

[Bernie Innocenti (codewiz)]

Output of bluetoothd -d -n:

bluetoothd[7378]: audio/headset.c:headset_set_state() State changed /org/bluez/7378/hci0/dev_00_1A_7D_E0_7B_27: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECTING
bluetoothd[7378]: plugins/hciops.c:conn_complete() status 0x00
bluetoothd[7378]: src/adapter.c:adapter_get_device() 00:1A:7D:E0:7B:27
bluetoothd[7378]: plugins/hciops.c:remote_features_information() hci0 status 0
bluetoothd[7378]: plugins/hciops.c:remote_name_information() hci0 status 0
bluetoothd[7378]: audio/headset.c:headset_set_channel() Discovered Handsfree service on channel 1
bluetoothd[7378]: audio/headset.c:rfcomm_connect() /org/bluez/7378/hci0/dev_00_1A_7D_E0_7B_27: Connecting to 00:1A:7D:E0:7B:27 channel 1
bluetoothd[7378]: plugins/hciops.c:link_key_request() hci0 dba 00:1A:7D:E0:7B:27
bluetoothd[7378]: plugins/hciops.c:get_auth_info() hci0 dba 00:1A:7D:E0:7B:27
bluetoothd[7378]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x04
bluetoothd[7378]: plugins/hciops.c:link_key_request() Matching key found
bluetoothd[7378]: plugins/hciops.c:link_key_request() link key type 0x04
bluetoothd[7378]: plugins/hciops.c:auth_complete() hci0 status 0
bluetoothd[7378]: plugins/hciops.c:bonding_complete() status 0x00
bluetoothd[7378]: src/event.c:btd_event_bonding_complete() status 0x00
bluetoothd[7378]: src/adapter.c:adapter_get_device() 00:1A:7D:E0:7B:27
bluetoothd[7378]: src/device.c:device_bonding_complete() bonding (nil) status 0x00
bluetoothd[7378]: Permission denied (13)
bluetoothd[7378]: audio/headset.c:headset_set_state() State changed /org/bluez/7378/hci0/dev_00_1A_7D_E0_7B_27: HEADSET_STATE_CONNECTING -> HEADSET_STATE_DISCONNECTED
bluetoothd[7378]: plugins/hciops.c:disconn_complete() handle 11 status 0x00
bluetoothd[7378]: src/event.c:btd_event_disconn_complete()
bluetoothd[7378]: src/adapter.c:adapter_remove_connection()

[Murz (murznn)]

I solve this problem for me via editing dbus rules: in file /etc/dbus-1/system.d/bluetooth.conf I add:
  <policy user="pulse">
    <allow send_destination="org.bluez"/>
  </policy>

Maybe this helps you too.
I use pulseaudio as system daemon, so maybe you must add not pulse but your user to policy.

[Bernie Innocenti (codewiz)]

Thanks Murz. Your proposed workaround did not solve the issue for me. I can now reproduce both on lucid and on oneiric, using the same headset.

This is the log from a session in which I successfully coupled the adapter:

Dec 28 22:58:04 giskard bluetoothd[21144]: Discovery session 0x555555813e50 with :1.1088 activated
Dec 28 22:58:51 giskard bluetoothd[21144]: Stopping discovery
Dec 28 22:59:02 giskard bluetoothd[21144]: Badly formated or unrecognized command: AT+CSRSF=0,0,0,0,0,7
Dec 28 22:59:04 giskard kernel: [268697.152101] input: 00:1A:7D:E0:7B:27 as /devices/virtual/input/input22
Dec 29 03:59:04 giskard rtkit-daemon[1920]: Successfully made thread 21926 of process 2092 (n/a) owned by '1000' RT at priority 5.
Dec 29 03:59:04 giskard rtkit-daemon[1920]: Supervising 3 threads of 1 processes of 1 users.

Now I disconnect it:

Dec 28 22:59:53 giskard bluetoothd[21144]: Disconnected from 00:1A:7D:E0:7B:27, /org/bluez/21144/hci0/dev_00_1A_7D_E0_7B_27

And this is gnome-control-center trying to reconnect it:

Dec 28 23:00:15 giskard bluetoothd[21144]: Permission denied (13)
Dec 28 23:00:15 giskard bluetoothd[21144]: Unable to get service record: Permission denied (13)
Dec 28 23:00:21 giskard bluetoothd[21144]: Permission denied (13)
Dec 28 23:00:27 giskard bluetoothd[21144]: Permission denied (13)
Dec 28 23:00:27 giskard bluetoothd[21144]: Unable to get service record: Permission denied (13)

I've also found this interesting error in the logs from a previous session:

Dec 28 22:51:38 giskard bluetoothd[21144]: HCI dev 0 registered
Dec 28 22:51:38 giskard bluetoothd[21144]: Listening for HCI events on hci0
Dec 28 22:51:38 giskard bluetoothd[21144]: HCI dev 0 up
Dec 28 22:51:38 giskard bluetoothd[21144]: Adapter /org/bluez/21144/hci0 has been enabled
Dec 28 22:51:38 giskard pulseaudio[2092]: [pulseaudio] bluetooth-util.c: Error from RegisterEndpoint reply: org.freedesktop.DBus.Error.UnknownMethod
Dec 28 22:52:06 pulseaudio[2092]: last message repeated 2 times
Dec 28 22:52:06 giskard bluetoothd[21144]: Permission denied (13)

[Trevor Joynson (trevorjay)]

This happens every time I reconnect my Nokia BH-505 headset as well.

It always works for me the first time I pair it, but after that it never reconnects.

I have to unpair, then repair, and it will work until a disconnect happens.

[Trevor Joynson (trevorjay)]

This is an *awfully* descriptive permissions denied error... </sarcasm>

bluetoothd[16555]: audio/headset.c:headset_set_state() State changed /org/bluez/16555/hci0/dev_00_1E_DE_28_4E_00: HEADSET_STATE_DISCONNECTED -> HEADSET_STATE_CONNECTING
bluetoothd[16555]: plugins/hciops.c:conn_complete() status 0x00
bluetoothd[16555]: src/adapter.c:adapter_get_device() 00:1E:DE:28:4E:00
bluetoothd[16555]: plugins/hciops.c:remote_features_information() hci0 status 0
bluetoothd[16555]: plugins/hciops.c:remote_name_information() hci0 status 0
bluetoothd[16555]: audio/headset.c:headset_set_channel() Discovered Handsfree service on channel 1
bluetoothd[16555]: audio/headset.c:rfcomm_connect() /org/bluez/16555/hci0/dev_00_1E_DE_28_4E_00: Connecting to 00:1E:DE:28:4E:00 channel 1
bluetoothd[16555]: plugins/hciops.c:link_key_request() hci0 dba 00:1E:DE:28:4E:00
bluetoothd[16555]: plugins/hciops.c:get_auth_info() hci0 dba 00:1E:DE:28:4E:00
bluetoothd[16555]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x04
bluetoothd[16555]: plugins/hciops.c:link_key_request() Matching key found
bluetoothd[16555]: plugins/hciops.c:link_key_request() link key type 0x04
bluetoothd[16555]: plugins/hciops.c:auth_complete() hci0 status 0
bluetoothd[16555]: plugins/hciops.c:bonding_complete() status 0x00
bluetoothd[16555]: src/event.c:btd_event_bonding_complete() status 0x00
bluetoothd[16555]: src/adapter.c:adapter_get_device() 00:1E:DE:28:4E:00
bluetoothd[16555]: src/device.c:device_bonding_complete() bonding (nil) status 0x00
bluetoothd[16555]: Permission denied (13)
bluetoothd[16555]: audio/headset.c:headset_set_state() State changed /org/bluez/16555/hci0/dev_00_1E_DE_28_4E_00: HEADSET_STATE_CONNECTING -> HEADSET_STATE_DISCONNECTED
bluetoothd[16555]: plugins/hciops.c:disconn_complete() handle 12 status 0x00
bluetoothd[16555]: src/event.c:btd_event_disconn_complete()
bluetoothd[16555]: src/adapter.c:adapter_remove_connection()

[Trevor Joynson (trevorjay)]

strace bluetooth -d -n:

<snip>

sendto(3, "<31>Jan 27 18:00:26 bluetoothd[1"..., 158, MSG_NOSIGNAL, NULL, 0) = 158
socket(PF_BLUETOOTH, SOCK_STREAM, 3) = 26
bind(26, {sa_family=AF_BLUETOOTH, sa_data="\211\224/G\370\340\0\0\377\377\377\377\377\377"}, 10) = 0
setsockopt(26, 0x112 /* SOL_?? */, 4, "\2", 1) = 0
fstat(26, {st_mode=S_IFSOCK|0777, st_size=0, ...}) = 0
fcntl(26, F_GETFL) = 0x2 (flags O_RDWR)
fcntl(26, F_SETFL, O_RDONLY|O_NONBLOCK) = 0
connect(26, {sa_family=AF_BLUETOOTH, sa_data="\0N(\336\36\0\1\0\0\0\0\0\0\0"}, 10) = -1 EINPROGRESS (Operation now in progress)
poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=8, events=POLLIN}, {fd=9, events=POLLIN}, {fd=10, events=POLLIN}, {fd=14, events=POLLIN}, {fd=11, events=POLLIN}, {fd=16, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, events=POLLIN}, {fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}, {fd=22, events=POLLIN}, {fd=23, events=POLLIN}, {fd=13, events=POLLIN}, {fd=4, events=POLLIN}, {fd=26, events=POLLOUT}, {fd=15, events=POLLIN}], 19, 1976) = 1 ([{fd=15, revents=POLLIN}])
read(15, "\4\17\4\0\1\21\4", 260) = 7
socket(PF_BLUETOOTH, SOCK_RAW, 1) = 27
ioctl(27, 0x800448d3, 0x7fffaa266ac0) = 0
close(27) = 0
poll([{fd=5, events=POLLIN}, {fd=6, events=POLLIN}, {fd=8, events=POLLIN}, {fd=9, events=POLLIN}, {fd=10, events=POLLIN}, {fd=14, events=POLLIN}, {fd=11, events=POLLIN}, {fd=16, events=POLLIN}, {fd=17, events=POLLIN}, {fd=18, events=POLLIN}, {fd=19, events=POLLIN}, {fd=20, events=POLLIN}, {fd=21, events=POLLIN}, {fd=22, events=POLLIN}, {fd=23, events=POLLIN}, {fd=13, events=POLLIN}, {fd=4, events=POLLIN}, {fd=26, events=POLLOUT}, {fd=15, events=POLLIN}], 19, 1974) = 1 ([{fd=15, revents=POLLIN}])
read(15, "\4\27\6\0N(\336\36\0", 260) = 9
socket(PF_BLUETOOTH, SOCK_RAW, 1) = 27
ioctl(27, 0x800448d3, 0x7fffaa266ac0) = 0
close(27) = 0
writev(2, [{"bluetoothd[16631]: plugins/hciop"..., 81}, {"\n", 1}], 2bluetoothd[16631]: plugins/hciops.c:link_key_request() hci0 dba 00:1E:DE:28:4E:00
) = 82
sendto(3, "<31>Jan 27 18:00:26 bluetoothd[1"..., 101, MSG_NOSIGNAL, NULL, 0) = 101
writev(2, [{"bluetoothd[16631]: plugins/hciop"..., 78}, {"\n", 1}], 2bluetoothd[16631]: plugins/hciops.c:get_auth_info() hci0 dba 00:1E:DE:28:4E:00
) = 79
sendto(3, "<31>Jan 27 18:00:26 bluetoothd[1"..., 98, MSG_NOSIGNAL, NULL, 0) = 98
ioctl(15, 0x800448d7, 0x7fffaa265950) = 0
writev(2, [{"bluetoothd[16631]: plugins/hciop"..., 86}, {"\n", 1}], 2bluetoothd[16631]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x04
) = 87
sendto(3, "<31>Jan 27 18:00:26 bluetoothd[1"..., 106, MSG_NOSIGNAL, NULL, 0) = 106
writev(2, [{"bluetoothd[16631]: plugins/hciop"..., 73}, {"\n", 1}], 2bluetoothd[16631]: plugins/hciops.c:link_key_request() Matching key found
) = 74
sendto(3, "<31>Jan 27 18:00:26 bluetoothd[1"..., 93, MSG_NOSIGNAL, NULL, 0) = 93
writev(2, [{"bluetoothd[16631]: plugins/hciop"..., 73}, {"\n", 1}], 2bluetoothd[16631]: plugins/hciops.c:link_key_request() link key type 0x04
) = 74
sendto(3, "<31>Jan 27 18:00:26 bluetoothd[1"..., 93, MSG_NOSIGNAL, NULL, 0) = 93
writev(15, [{...

[RickB (rick-777)]

I have a new Novatech laptop with Ubuntu 11.10, and a new Plantronic BB903+.

When I enable BT and then attempt to connect the headset service using the system-tray applet, syslog gets the following:

Jan 31 17:39:53 krum bluetoothd[1251]: HCI dev 0 up
Jan 31 17:39:53 krum bluetoothd[1251]: Adapter /org/bluez/1251/hci0 has been enabled
Jan 31 17:39:53 krum bluetoothd[1251]: Adapter /org/bluez/1251/hci0 has been enabled
Jan 31 17:40:08 krum bluetoothd[1251]: Permission denied (13)

So I installed Blueman and this works a bit better: for A2DP I get a successful link:

Jan 31 17:45:47 krum kernel: [ 2640.281203] input: FF:66:DD:22:FF:11 as /devices/virtual/input/input16
Jan 31 17:45:47 krum rtkit-daemon[1590]: Successfully made thread 2937 of process 2062 (n/a) owned by '1000' RT at priority 5.
Jan 31 17:45:47 krum rtkit-daemon[1590]: Supervising 4 threads of 1 processes of 1 users.

But even with Blueman, the permission error arises everytime I try instead to use the headset service or the input service:

Jan 31 17:47:50 krum bluetoothd[1251]: Permission denied (13)

Only A2DP works.

Any suggestions?