Note: This is a public test instance of Red Hat Bugzilla. The data contained within is a snapshot of the live data so any changes you make will not be reflected in the production Bugzilla. Email is disabled so feel free to test any aspect of the site that you want. File any problems you find or give feedback at bugzilla.redhat.com.
Bug 1259827 - Failed to obtain handles for "Service Changed" characteristic
Summary: Failed to obtain handles for "Service Changed" characteristic
Keywords:
Status: CLOSED ERRATA
Alias: None
Product: Fedora
Classification: Fedora
Component: bluez
Version: 25
Hardware: x86_64
OS: Unspecified
unspecified
medium
Target Milestone: ---
Assignee: Don Zickus
QA Contact: Fedora Extras Quality Assurance
URL:
Whiteboard:
: 1347935 1405752 (view as bug list)
Depends On:
Blocks:
TreeView+ depends on / blocked
 
Reported: 2015-09-03 15:01 UTC by Christian Stadelmann
Modified: 2017-02-08 01:51 UTC (History)
19 users (show)

Fixed In Version: bluez-5.43-2.fc25
Doc Type: Bug Fix
Doc Text:
Clone Of:
Environment:
Last Closed: 2017-02-08 01:51:57 UTC
Type: Bug
Embargoed:

Attachments (Terms of Use)


Links
System ID Private Priority Status Summary Last Updated
Red Hat Bugzilla 1336963 0 unspecified CLOSED [abrt] blueman: Device.py:33:err:blueman.bluez.errors.DBusAuthenticationFailedError: Authentication Failed 2021-02-22 00:41:40 UTC

Internal Links: 1336963

Description Christian Stadelmann 2015-09-03 15:01:20 UTC 
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
Comment 1 Edward O'Callaghan 2015-11-08 11:55:16 UTC 
I had this problem happen to me also but not at boot.
Comment 2 Dominic Robinson 2015-11-23 15:52:54 UTC 
I also have this problem on every boot with F23.
Comment 3 Krystian 2016-01-23 14:27:49 UTC 
Me too problem in fedora 23 xfce
Comment 4 Raphael Groner 2016-05-18 13:19:29 UTC 
Possible duplication in Fedora 24.
Comment 5 Don Zickus 2016-06-30 21:16:45 UTC 
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
Comment 6 Aleksandar Kostadinov 2016-08-01 18:41:13 UTC 
I still see it on fedora 24 with bluez-5.40-2.fc24.x86_64
Comment 7 Rubén 2016-09-09 18:37:24 UTC 
*** Bug 1347935 has been marked as a duplicate of this bug. ***
Comment 8 Christian Stadelmann 2016-09-22 18:08:56 UTC 
Still present on F25 with bluez-5.41-1.fc25
Comment 9 Janvitus 2016-12-01 11:08:42 UTC 
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.
Comment 10 Don Zickus 2016-12-19 16:58:25 UTC 
*** Bug 1405752 has been marked as a duplicate of this bug. ***
Comment 11 gopal krishna tiwari 2016-12-29 09:21:00 UTC 
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...
Comment 13 JW71 2017-01-18 19:47:00 UTC 
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)
Comment 14 JW71 2017-01-18 20:04:53 UTC 
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
Comment 15 Fedora Update System 2017-02-06 15:07:13 UTC 
bluez-5.43-2.fc25 has been submitted as an update to Fedora 25. https://bodhi.fedoraproject.org/updates/FEDORA-2017-43a77d126b
Comment 16 Fedora Update System 2017-02-07 02:49:32 UTC 
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
Comment 17 Fedora Update System 2017-02-08 01:51:57 UTC 
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.
Note You need to log in before you can comment on or make changes to this bug.