#639640 network-manager: Cannot connect to bluez/bluetoothd

Package:
network-manager
Source:
network-manager
Description:
network management framework (daemon and userspace tools)
Submitter:
Olivier Berger
Date:
2011-08-29 05:27:03 UTC
Severity:
normal
#639640#5
Date:
2011-08-28 22:03:18 UTC
From:
To:
I've setup a DUN connection over bluetooth, with gnome's bluetooth wizard, which appears in NetworkManager.

However, when I try to connect it, it will fail.

Excerpts of syslog (with bluetoothd running with -d option) :
Aug 28 23:39:45 inf-8657 NetworkManager[5441]: <info> Activation (0C:DD:EF:FC:14:07) starting connection 'Orange No Contract / Mobicarte'
Aug 28 23:39:45 inf-8657 NetworkManager[5441]: <info> (0C:DD:EF:FC:14:07): device state change: 3 -> 4 (reason 0)
Aug 28 23:39:45 inf-8657 NetworkManager[5441]: <info> Activation (0C:DD:EF:FC:14:07) Stage 1 of 5 (Device Prepare) scheduled...
Aug 28 23:39:45 inf-8657 NetworkManager[5441]: <info> Activation (0C:DD:EF:FC:14:07) Stage 1 of 5 (Device Prepare) started...
Aug 28 23:39:45 inf-8657 NetworkManager[5441]: <info> Activation (0C:DD:EF:FC:14:07) Stage 2 of 5 (Device Configure) scheduled...
Aug 28 23:39:45 inf-8657 NetworkManager[5441]: <info> Activation (0C:DD:EF:FC:14:07) Stage 1 of 5 (Device Prepare) complete.
Aug 28 23:39:45 inf-8657 NetworkManager[5441]: <info> Activation (0C:DD:EF:FC:14:07) Stage 2 of 5 (Device Configure) starting...
Aug 28 23:39:45 inf-8657 NetworkManager[5441]: <info> (0C:DD:EF:FC:14:07): device state change: 4 -> 5 (reason 0)
Aug 28 23:39:45 inf-8657 NetworkManager[5441]: <info> Activation (0C:DD:EF:FC:14:07) Stage 2 of 5 (Device Configure) complete.
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: plugins/hciops.c:conn_complete() status 0x00
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: src/adapter.c:adapter_get_device() 0C:DD:EF:FC:14:07
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: plugins/hciops.c:remote_features_information() hci0 status 0
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: plugins/hciops.c:remote_name_information() hci0 status 0
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: plugins/hciops.c:link_key_request() hci0 dba 0C:DD:EF:FC:14:07
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: plugins/hciops.c:get_auth_info() hci0 dba 0C:DD:EF:FC:14:07
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x04
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: plugins/hciops.c:link_key_request() Matching key found
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: plugins/hciops.c:link_key_request() link key type 0x05
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: plugins/hciops.c:auth_complete() hci0 status 0
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: plugins/hciops.c:bonding_complete() status 0x00
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: src/event.c:btd_event_bonding_complete() status 0x00
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: src/adapter.c:adapter_get_device() 0C:DD:EF:FC:14:07
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: src/device.c:device_bonding_complete() bonding (nil) status 0x00
Aug 28 23:39:46 inf-8657 bluetoothd[5730]: Connection refused (111)
Aug 28 23:39:46 inf-8657 NetworkManager[5441]: <warn> Error connecting with bluez: Connection refused (111)
Aug 28 23:39:46 inf-8657 NetworkManager[5441]: <info> (0C:DD:EF:FC:14:07): device state change: 5 -> 9 (reason 44)
Aug 28 23:39:46 inf-8657 NetworkManager[5441]: <info> Marking connection 'Orange No Contract / Mobicarte' invalid.
Aug 28 23:39:46 inf-8657 NetworkManager[5441]: <warn> Activation (0C:DD:EF:FC:14:07) failed.
Aug 28 23:39:46 inf-8657 NetworkManager[5441]: <info> (0C:DD:EF:FC:14:07): device state change: 9 -> 3 (reason 0)
Aug 28 23:39:46 inf-8657 NetworkManager[5441]: <info> (0C:DD:EF:FC:14:07): deactivating device (reason: 0).
Aug 28 23:39:50 inf-8657 bluetoothd[5730]: plugins/hciops.c:disconn_complete() handle 43 status 0x00
Aug 28 23:39:50 inf-8657 bluetoothd[5730]: src/event.c:btd_event_disconn_complete()
Aug 28 23:39:50 inf-8657 bluetoothd[5730]: src/adapter.c:adapter_remove_connection()


Whereas, when using rfcomm to initialize rfcomm0, and wvdial to connect, it succeeds. FYI, in such case, bluetoothd reports :

Aug 28 23:51:57 inf-8657 bluetoothd[5730]: plugins/hciops.c:conn_complete() status 0x00
Aug 28 23:51:57 inf-8657 bluetoothd[5730]: src/adapter.c:adapter_get_device() 0C:DD:EF:FC:14:07
Aug 28 23:51:57 inf-8657 bluetoothd[5730]: plugins/hciops.c:remote_features_information() hci0 status 0
Aug 28 23:51:57 inf-8657 bluetoothd[5730]: plugins/hciops.c:remote_name_information() hci0 status 0
Aug 28 23:51:57 inf-8657 bluetoothd[5730]: plugins/hciops.c:link_key_request() hci0 dba 0C:DD:EF:FC:14:07
Aug 28 23:51:57 inf-8657 bluetoothd[5730]: plugins/hciops.c:get_auth_info() hci0 dba 0C:DD:EF:FC:14:07
Aug 28 23:51:57 inf-8657 bluetoothd[5730]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x00
Aug 28 23:51:57 inf-8657 bluetoothd[5730]: plugins/hciops.c:link_key_request() Matching key found
Aug 28 23:51:57 inf-8657 bluetoothd[5730]: plugins/hciops.c:link_key_request() link key type 0x05
Aug 28 23:51:57 inf-8657 bluetoothd[5730]: plugins/hciops.c:auth_complete() hci0 status 0
Aug 28 23:51:57 inf-8657 bluetoothd[5730]: plugins/hciops.c:bonding_complete() status 0x00
Aug 28 23:51:57 inf-8657 bluetoothd[5730]: src/event.c:btd_event_bonding_complete() status 0x00
Aug 28 23:51:57 inf-8657 bluetoothd[5730]: src/adapter.c:adapter_get_device() 0C:DD:EF:FC:14:07
Aug 28 23:51:57 inf-8657 bluetoothd[5730]: src/device.c:device_bonding_complete() bonding (nil) status 0x00
Aug 28 23:52:13 inf-8657 bluetoothd[5730]: plugins/hciops.c:disconn_complete() handle 43 status 0x00
Aug 28 23:52:13 inf-8657 bluetoothd[5730]: src/event.c:btd_event_disconn_complete()
Aug 28 23:52:13 inf-8657 bluetoothd[5730]: src/adapter.c:adapter_remove_connection()
Aug 28 23:52:18 inf-8657 bluetoothd[5730]: plugins/hciops.c:conn_complete() status 0x00
Aug 28 23:52:18 inf-8657 bluetoothd[5730]: src/adapter.c:adapter_get_device() 0C:DD:EF:FC:14:07
Aug 28 23:52:18 inf-8657 bluetoothd[5730]: plugins/hciops.c:remote_features_information() hci0 status 0
Aug 28 23:52:19 inf-8657 bluetoothd[5730]: plugins/hciops.c:remote_name_information() hci0 status 0
Aug 28 23:52:19 inf-8657 bluetoothd[5730]: plugins/hciops.c:link_key_request() hci0 dba 0C:DD:EF:FC:14:07
Aug 28 23:52:19 inf-8657 bluetoothd[5730]: plugins/hciops.c:get_auth_info() hci0 dba 0C:DD:EF:FC:14:07
Aug 28 23:52:19 inf-8657 bluetoothd[5730]: plugins/hciops.c:link_key_request() kernel auth requirements = 0x00
Aug 28 23:52:19 inf-8657 bluetoothd[5730]: plugins/hciops.c:link_key_request() Matching key found
Aug 28 23:52:19 inf-8657 bluetoothd[5730]: plugins/hciops.c:link_key_request() link key type 0x05
Aug 28 23:52:19 inf-8657 bluetoothd[5730]: plugins/hciops.c:auth_complete() hci0 status 0
Aug 28 23:52:19 inf-8657 bluetoothd[5730]: plugins/hciops.c:bonding_complete() status 0x00
Aug 28 23:52:19 inf-8657 bluetoothd[5730]: src/event.c:btd_event_bonding_complete() status 0x00
Aug 28 23:52:19 inf-8657 bluetoothd[5730]: src/adapter.c:adapter_get_device() 0C:DD:EF:FC:14:07
Aug 28 23:52:19 inf-8657 bluetoothd[5730]: src/device.c:device_bonding_complete() bonding (nil) status 0x00
Aug 28 23:52:54 inf-8657 kernel: [ 6647.509488] rfcomm_tty_ioctl: TIOCGSERIAL is not supported
Aug 28 23:52:57 inf-8657 pppd[6040]: pppd 2.4.5 started by root, uid 0
Aug 28 23:52:57 inf-8657 kernel: [ 6651.236066] PPP generic driver version 2.4.2
Aug 28 23:52:57 inf-8657 pppd[6040]: Using interface ppp0
Aug 28 23:52:57 inf-8657 pppd[6040]: Connect: ppp0 <--> /dev/rfcomm0
Aug 28 23:52:58 inf-8657 pppd[6040]: PAP authentication succeeded
Aug 28 23:52:58 inf-8657 kernel: [ 6651.484322] PPP BSD Compression module registered
Aug 28 23:52:58 inf-8657 kernel: [ 6651.492200] PPP Deflate Compression module registered
Aug 28 23:53:00 inf-8657 dnsmasq[2297]: no servers found in /etc/resolv.conf, will retry
Aug 28 23:53:00 inf-8657 pppd[6040]: local  IP address 10.97.160.236
Aug 28 23:53:00 inf-8657 pppd[6040]: remote IP address 10.6.6.6
etc.


I hence think there's something wrong in the way NM tries to connect to bluetoothd (if it's what's identified by "bluez").

Thanks in advance.

Hope this helps.

Best regards,
#639640#10
Date:
2011-08-28 22:22:38 UTC
From:
To:
Am 29.08.2011 00:03, schrieb Olivier Berger:

This looks suspicious.
Might be related to [1]. What permissions does the device have?
Could you get the permissions of /dev/rfkill and hci0 with getfacl.
Maybe there is a race between hci0 being ready and NM trying to access it.


[1] http://bugs.debian.org/cgi-bin/bugreport.cgi?bug=582188
#639640#15
Date:
2011-08-29 05:25:04 UTC
From:
To:
Le lundi 29 août 2011 à 00:22 +0200, Michael Biebl a écrit :

# ls -al /dev/rfkill
crw-rw-r--+ 1 root root 10, 59 Aug 29 02:11 /dev/rfkill
# getfacl /dev/rfkill
getfacl: Removing leading '/' from absolute path names
# file: dev/rfkill
# owner: root
# group: root
user::rw-
user:olivier:rw-
group::r--
mask::rw-
other::r--

Uh... hci0 ?

Hope this helps.

Thanks in advance.