Description of problem: Bluetoothd prints some error messages to syslog: $ systemctl status bluetooth.service -l ● bluetooth.service - Bluetooth service Loaded: loaded (/usr/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled) Active: active (running) since Do 2015-09-03 16:46:12 CEST; 12min ago Docs: man:bluetoothd(8) Main PID: 1141 (bluetoothd) Status: "Running" CGroup: /system.slice/bluetooth.service └─1141 /usr/libexec/bluetooth/bluetoothd Sep 03 16:46:12 hostname bluetoothd[1141]: Bluetooth daemon 5.33 Sep 03 16:46:12 hostname systemd[1]: Starting Bluetooth service... Sep 03 16:46:12 hostname systemd[1]: Started Bluetooth service. Sep 03 16:46:12 hostname bluetoothd[1141]: Starting SDP server Sep 03 16:46:12 hostname bluetoothd[1141]: Bluetooth management interface 1.10 initialized Sep 03 16:46:12 hostname bluetoothd[1141]: Failed to obtain handles for "Service Changed" characteristic Sep 03 16:46:15 hostname bluetoothd[1141]: Failed to set mode: Blocked through rfkill (0x12) Sep 03 16:46:20 hostname bluetoothd[1141]: Endpoint registered: sender=:1.42 path=/MediaEndpoint/A2DPSource Sep 03 16:46:20 hostname bluetoothd[1141]: Endpoint registered: sender=:1.42 path=/MediaEndpoint/A2DPSink Sep 03 16:46:21 hostname bluetoothd[1141]: Failed to set mode: Blocked through rfkill (0x12) Version-Release number of selected component (if applicable): bluez-5.33-1.fc23.x86_64 How reproducible: on every boot
I had this problem happen to me also but not at boot.
I also have this problem on every boot with F23.
Me too problem in fedora 23 xfce
Possible duplication in Fedora 24.
Hi, This is a harmless warning that does not seem to impact bluetoothd from doing its job. I will try to get upstream to fix/remove this warning to not confuse users. Cheers, Don
I still see it on fedora 24 with bluez-5.40-2.fc24.x86_64
*** Bug 1347935 has been marked as a duplicate of this bug. ***
Still present on F25 with bluez-5.41-1.fc25
Same bug here: systemctl status bluetooth.service -l ● bluetooth.service - Bluetooth service Loaded: loaded (/usr/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled) Active: active (running) since gio 2016-12-01 11:31:53 CET; 35min ago Docs: man:bluetoothd(8) Main PID: 670 (bluetoothd) Status: "Running" Tasks: 1 (limit: 4915) CGroup: /system.slice/bluetooth.service └─670 /usr/libexec/bluetooth/bluetoothd dic 01 11:31:53 fedorabox systemd[1]: Starting Bluetooth service... dic 01 11:31:53 fedorabox bluetoothd[670]: Bluetooth daemon 5.43 dic 01 11:31:53 fedorabox bluetoothd[670]: Starting SDP server dic 01 11:31:53 fedorabox systemd[1]: Started Bluetooth service. dic 01 11:31:53 fedorabox bluetoothd[670]: Bluetooth management interface 1.13 initialized dic 01 11:31:53 fedorabox bluetoothd[670]: Failed to obtain handles for "Service Changed" characteristic dic 01 11:32:04 fedorabox bluetoothd[670]: Endpoint registered: sender=:1.49 path=/MediaEndpoint/A2DPSource dic 01 11:32:04 fedorabox bluetoothd[670]: Endpoint registered: sender=:1.49 path=/MediaEndpoint/A2DPSink The bug still persist from Fedora 24 and now on 25.
*** Bug 1405752 has been marked as a duplicate of this bug. ***
I think I understood the issue a bit bluetoothd[30656]: Bluetooth daemon 5.29 bluetoothd[30656]: ../src/adapter.c:adapter_init() sending read version command bluetoothd[30656]: Starting SDP server bluetoothd[32055]: ../src/adapter.c:adapter_service_insert() /org/bluez/hci0 bluetoothd[32055]: ../src/adapter.c:add_uuid() sending add uuid command for index 0 bluetoothd[32055]: ../src/gatt-database.c:gatt_db_service_added() GATT Service added to local database bluetoothd[32055]: ../src/gatt-database.c:send_service_changed() GKT: Debug start (nil) (nil) <<------------------------ bluetoothd[32055]: Failed to obtain handles for "Service Changed" characteristic <<----------- error we are getting bluetoothd[32055]: ../src/adapter.c:adapter_service_add() /org/bluez/hci0 bluetoothd[32055]: ../src/sdpd-service.c:add_record_to_server() Adding record with handle 0x10002 bluetoothd[32055]: ../src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000007-0000-1000-8000-00805f9 bluetoothd[32055]: ../src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[32055]: ../src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[32055]: ../src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001801-0000-1000-8000-00805f9 bluetoothd[32055]: ../src/adapter.c:adapter_service_insert() /org/bluez/hci0 bluetoothd[32055]: ../src/adapter.c:add_uuid() sending add uuid command for index 0 bluetoothd[32055]: ../src/gatt-database.c:gatt_db_service_added() GATT Service added to local database bluetoothd[32055]: ../src/gatt-database.c:send_service_changed() GKT: Debug start 0x8 0x9 <<---------------- No error as we have the handles bluetoothd[32055]: ../profiles/audio/a2dp.c:media_server_probe() path /org/bluez/hci0 bluetoothd[32055]: ../plugins/hostname.c:hostname_probe() bluetoothd[32055]: ../plugins/hostname.c:update_class() major: 0x01 minor: 0x03 bluetoothd[32055]: ../src/adapter.c:btd_adapter_set_class() class: major 1 minor 3 bluetoothd[32055]: ../src/adapter.c:set_dev_class() sending set device class command for index 0 bluetoothd[32055]: ../profiles/network/manager.c:panu_server_probe() path /org/bluez/hci0 bluetoothd[32055]: ../profiles/network/server.c:server_register() Registered interface org.bluez.NetworkServer1 on path /org/bluez/hci0 bluetoothd[32055]: ../profiles/network/manager.c:gn_server_probe() path /org/bluez/hci0 bluetoothd[32055]: ../profiles/network/manager.c:nap_server_probe() path /org/bluez/hci0 I again tried with the latest 5.43 latest pull with the same debug prints bluetoothd[15532]: Bluetooth daemon 5.43 bluetoothd[15532]: ../src/adapter.c:adapter_init() sending read version command bluetoothd[15532]: Starting SDP server bluetoothd[15532]: ../src/adapter.c:clear_devices() sending clear devices command for index 0 bluetoothd[15532]: ../src/adapter.c:set_privacy() sending set privacy command for index 0 bluetoothd[15532]: ../src/adapter.c:set_privacy() setting privacy mode 0x00 for index 0 bluetoothd[15532]: ../src/gatt-database.c:btd_gatt_database_new() GATT Manager registered for adapter: /org/bluez/hci0 bluetoothd[15532]: ../src/adapter.c:adapter_service_add() /org/bluez/hci0 bluetoothd[15532]: ../src/sdpd-service.c:add_record_to_server() Adding record with handle 0x10001 bluetoothd[15532]: ../src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000007-0000-1000-8000-00805f9 bluetoothd[15532]: ../src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[15532]: ../src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[15532]: ../src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001800-0000-1000-8000-00805f9 bluetoothd[15532]: ../src/adapter.c:adapter_service_insert() /org/bluez/hci0 bluetoothd[15532]: ../src/adapter.c:add_uuid() sending add uuid command for index 0 bluetoothd[15532]: ../src/adapter.c:adapter_service_add() /org/bluez/hci0 bluetoothd[15532]: ../src/sdpd-service.c:add_record_to_server() Adding record with handle 0x10002 bluetoothd[15532]: ../src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000007-0000-1000-8000-00805f9 bluetoothd[15532]: ../src/sdpd-service.c:add_record_to_server() Record pattern UUID 00000100-0000-1000-8000-00805f9 bluetoothd[15532]: ../src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001002-0000-1000-8000-00805f9 bluetoothd[15532]: ../src/sdpd-service.c:add_record_to_server() Record pattern UUID 00001801-0000-1000-8000-00805f9 bluetoothd[15532]: ../src/adapter.c:adapter_service_insert() /org/bluez/hci0 bluetoothd[15532]: ../src/adapter.c:add_uuid() sending add uuid command for index 0 bluetoothd[15532]: ../profiles/audio/a2dp.c:media_server_probe() path /org/bluez/hci0 bluetoothd[15532]: ../plugins/hostname.c:hostname_probe() Above problem is not there. As per my understanding it looks like the following issue with 5.29 gatt_db_register, which is registering the notification, is called before register_core_services, is for the device probing , which is generating the change event notification even if the device haven't got the handler yet. I think this problem is solved with 5.43 latest release is having following patch commit f558fca8d64e3795b0654a90d343af1dd1d8b33c Author: Luiz Augusto von Dentz <luiz.von.dentz> Date: Tue Nov 8 10:38:43 2016 +0200 core/gatt: Don't register attribute handler until core service are registered Wait until GAP and GATT service are registered to register attribute handlers otherwise it may attempt to generate service changed without having service changed registered which leads to print errors: bluetoothd[2376]: Failed to obtain handles for "Service Changed" characteristic diff --git a/src/gatt-database.c b/src/gatt-database.c index 0877b25..d4bf5ad 100644 --- a/src/gatt-database.c +++ b/src/gatt-database.c @@ -2600,12 +2600,6 @@ struct btd_gatt_database *btd_gatt_database_new(struct btd_adapter *adapter) database->profiles = queue_new(); database->ccc_callbacks = queue_new(); - database->db_id = gatt_db_register(database->db, gatt_db_service_added, - gatt_db_service_removed, - database, NULL); - if (!database->db_id) - goto fail; - addr = btd_adapter_get_address(adapter); database->le_io = bt_io_listen(connect_cb, NULL, NULL, NULL, &gerr, BT_IO_OPT_SOURCE_BDADDR, addr, @@ -2641,6 +2635,13 @@ struct btd_gatt_database *btd_gatt_database_new(struct btd_adapter *adapter) register_core_services(database); Gopal...
I have also the same problem with F25: uname -a Linux spectre 4.9.3-200.fc25.x86_64 #1 SMP Fri Jan 13 01:01:13 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux bluez-5.43-1.fc25.x86_64 sudo systemctl status bluetooth.service -l ● bluetooth.service - Bluetooth service Loaded: loaded (/usr/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled) Active: active (running) since Mi 2017-01-18 20:15:47 CET; 21min ago Docs: man:bluetoothd(8) Main PID: 792 (bluetoothd) Status: "Running" Tasks: 1 (limit: 4915) CGroup: /system.slice/bluetooth.service └─792 /usr/libexec/bluetooth/bluetoothd Jan 18 20:16:10 spectre bluetoothd[792]: Failed to set mode: Blocked through rfkill (0x12) Jan 18 20:16:11 spectre bluetoothd[792]: Failed to set mode: Failed (0x03) Jan 18 20:16:13 spectre bluetoothd[792]: Failed to set mode: Failed (0x03) Jan 18 20:16:14 spectre bluetoothd[792]: Failed to set mode: Failed (0x03) Jan 18 20:16:51 spectre bluetoothd[792]: Failed to set mode: Failed (0x03) Jan 18 20:17:08 spectre bluetoothd[792]: Failed to set mode: Failed (0x03) Jan 18 20:24:47 spectre bluetoothd[792]: Failed to set mode: Failed (0x03) Jan 18 20:29:58 spectre bluetoothd[792]: Failed to set mode: Failed (0x03) Jan 18 20:33:01 spectre bluetoothd[792]: Failed to set mode: Failed (0x03) Jan 18 20:33:16 spectre bluetoothd[792]: Failed to set mode: Failed (0x03)
It works as expected with the previous kernel version: [18.01.2017 20:59:57](pts/0 from local) ~ juergen@spectre(Fedora 25)> uname -a Linux spectre 4.8.16-300.fc25.x86_64 #1 SMP Fri Jan 6 18:11:49 UTC 2017 x86_64 x86_64 x86_64 GNU/Linux [18.01.2017 21:00:17](pts/0 from local) ~ juergen@spectre(Fedora 25)> sudo systemctl status bluetooth.service -l [sudo] Passwort für juergen: ● bluetooth.service - Bluetooth service Loaded: loaded (/usr/lib/systemd/system/bluetooth.service; enabled; vendor preset: enabled) Active: active (running) since Mi 2017-01-18 20:58:09 CET; 2min 27s ago Docs: man:bluetoothd(8) Main PID: 805 (bluetoothd) Status: "Running" Tasks: 1 (limit: 4915) CGroup: /system.slice/bluetooth.service └─805 /usr/libexec/bluetooth/bluetoothd Jan 18 20:58:09 spectre systemd[1]: Started Bluetooth service. Jan 18 20:58:09 spectre bluetoothd[805]: Bluetooth management interface 1.13 initialized Jan 18 20:58:09 spectre bluetoothd[805]: Failed to obtain handles for "Service Changed" characteristic Jan 18 20:58:19 spectre bluetoothd[805]: Endpoint registered: sender=:1.49 path=/MediaEndpoint/A2DPSource Jan 18 20:58:19 spectre bluetoothd[805]: Endpoint registered: sender=:1.49 path=/MediaEndpoint/A2DPSink Jan 18 20:58:25 spectre bluetoothd[805]: Failed to set mode: Failed (0x03) Jan 18 20:58:26 spectre bluetoothd[805]: Failed to set mode: Failed (0x03) Jan 18 20:58:28 spectre bluetoothd[805]: Failed to set mode: Failed (0x03) Jan 18 20:58:29 spectre bluetoothd[805]: Failed to set mode: Failed (0x03) Jan 18 20:59:23 spectre bluetoothd[805]: /org/bluez/hci0/dev_A0_E9_DB_00_ED_04/fd0: fd(24) ready
bluez-5.43-2.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2017-43a77d126b
bluez-5.43-2.fc25 has been pushed to the Fedora 25 testing repository. If problems still persist, please make note of it in this bug report. See https://fedoraproject.org/wiki/QA:Updates_Testing for instructions on how to install test updates. You can provide feedback for this update here: https://bodhi.fedoraproject.org/updates/FEDORA-2017-43a77d126b
bluez-5.43-2.fc25 has been pushed to the Fedora 25 stable repository. If problems still persist, please make note of it in this bug report.