* BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect
@ 2016-11-09 19:39 Petri Gynther
2016-11-10 14:17 ` Luiz Augusto von Dentz
0 siblings, 1 reply; 16+ messages in thread
From: Petri Gynther @ 2016-11-09 19:39 UTC (permalink / raw)
To: linux-bluetooth
Hi linux-bluetooth:
I'm seeing the following issue with BlueZ 5.43 and Linux 4.4.30.
When a previously bonded HoG remote control reconnects to BlueZ 5.43
host, BlueZ goes ahead and re-discovers the primary services of the
bonded remote again and again on every reconnect.
Why is this necessary? Shouldn't this information be cached on the
initial pairing/bonding, and a reconnect can get this information from
the relevant persistent file, rather than wasting BLE airtime and
delaying the reconnect?
Here is the log:
15,148349,14484016000,-;btmon: < HCI Command: LE Set Scan Enable
(0x08|0x000c) plen 2 [hci0] 16:45:13.144717
15,148350,14484016000,-;btmon: Scanning: Disabled (0x00)
15,148351,14484016000,-;btmon: Filter duplicates: Disabled (0x00)
15,148352,14484024000,-;btmon: > HCI Event: Command Complete (0x0e)
plen 4 [hci0] 16:45:13.151431
15,148353,14484024000,-;btmon: LE Set Scan Enable (0x08|0x000c) ncmd 1
15,148354,14484024000,-;btmon: Status: Success (0x00)
15,148355,14484024000,-;btmon: < HCI Command: LE Create Connec..
(0x08|0x000d) plen 25 [hci0] 16:45:13.151696
15,148356,14484024000,-;btmon: Scan interval: 60.000 msec (0x0060)
15,148357,14484026000,-;btmon: Scan window: 60.000 msec (0x0060)
15,148358,14484026000,-;btmon: Filter policy: White list is
not used (0x00)
15,148359,14484026000,-;btmon: Peer address type: Public (0x00)
15,148360,14484026000,-;btmon: Peer address: D4:F5:13:xx:xx:xx
(OUI D4-F5-13)
15,148361,14484026000,-;btmon: Own address type: Public (0x00)
15,148362,14484026000,-;btmon: Min connection interval: 10.00
msec (0x0008)
15,148363,14484026000,-;btmon: Max connection interval: 10.00
msec (0x0008)
15,148364,14484026000,-;btmon: Connection latency: 0x0032
15,148365,14484026000,-;btmon: Supervision timeout: 5000 msec (0x01f4)
15,148366,14484026000,-;btmon: Min connection length: 0.000
msec (0x0000)
15,148367,14484026000,-;btmon: Max connection length: 0.000
msec (0x0000)
15,148368,14484035000,-;btmon: > HCI Event: Command Status (0x0f) plen
4 [hci0] 16:45:13.163738
15,148369,14484036000,-;btmon: LE Create Connection (0x08|0x000d) ncmd 1
15,148370,14484036000,-;btmon: Status: Success (0x00)
15,148371,14484042000,-;bluez: bluetoothd[1985]:
src/adapter.c:connected_callback() hci0 device D4:F5:13:xx:xx:xx
connected eir_len 0
15,148372,14484042000,-;bluez: bluetoothd[1985]:
src/adapter.c:connected_callback() device 0x56c520 paired 1 bonded 1
bonding 0
15,148373,14484048000,-;btmon: > HCI Event: LE Meta Event (0x3e) plen
19 [hci0] 16:45:13.166525
15,148374,14484048000,-;btmon: LE Connection Complete (0x01)
15,148375,14484048000,-;btmon: Status: Success (0x00)
15,148376,14484048000,-;btmon: Handle: 128
15,148377,14484048000,-;btmon: Role: Master (0x00)
15,148378,14484048000,-;btmon: Peer address type: Public (0x00)
15,148379,14484048000,-;btmon: Peer address: D4:F5:13:xx:xx:xx
(OUI D4-F5-13)
15,148380,14484048000,-;btmon: Connection interval: 10.00 msec (0x0008)
15,148381,14484048000,-;btmon: Connection latency: 62.50 msec (0x0032)
15,148382,14484048000,-;btmon: Supervision timeout: 5000 msec (0x01f4)
15,148383,14484048000,-;btmon: Master clock accuracy: 0x01
15,148384,14484054000,-;btmon: < HCI Command: LE Read Remote Us..
(0x08|0x0016) plen 2 [hci0] 16:45:13.167102
15,148385,14484057000,-;btmon: Handle: 128
15,148386,14484057000,-;btmon: @ Device Connected: D4:F5:13:xx:xx:xx
(1) flags 0x0000
15,148387,14484060000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 6 [hci0] 16:45:13.186288
15,148388,14484060000,-;btmon: SMP: Security Request (0x0b) len 1
15,148389,14484060000,-;btmon: Authentication requirement:
Bonding, MITM, Legacy, No Keypresses (0x05)
15,148390,14484060000,-;btmon: > HCI Event: Command Status (0x0f) plen
4 [hci0] 16:45:13.187449
15,148391,14484060000,-;btmon: LE Read Remote Used Features
(0x08|0x0016) ncmd 1
15,148392,14484060000,-;btmon: Status: Success (0x00)
15,148393,14484083000,-;btmon: > HCI Event: LE Meta Event (0x3e) plen
12 [hci0] 16:45:13.204567
15,148394,14484083000,-;btmon: LE Read Remote Used Features (0x04)
15,148395,14484083000,-;btmon: Status: Success (0x00)
15,148396,14484083000,-;btmon: Handle: 128
15,148397,14484083000,-;btmon: Features: 0x01 0x00 0x00 0x00
0x00 0x00 0x00 0x00
15,148398,14484083000,-;btmon: LE Encryption
15,148399,14484084000,-;bluez: bluetoothd[1985]:
src/gatt-database.c:connect_cb() New incoming LE ATT connection
15,148400,14484084000,-;bluez: bluetoothd[1985]:
src/device.c:device_attach_att() Elevating security level since LTK is
available
15,148401,14484090000,-;btmon: < HCI Command: LE Start Encrypt..
(0x08|0x0019) plen 28 [hci0] 16:45:13.204768
15,148402,14484092000,-;btmon: Handle: 128
15,148403,14484092000,-;btmon: Random number: 0x2f1ece959be98720
15,148404,14484092000,-;btmon: Encrypted diversifier: 0xf64c
15,148405,14484092000,-;btmon: Long term key:
81f83ba06c91dd2e8a19cbe65fd5123a
15,148406,14484095000,-;btmon: > HCI Event: Command Status (0x0f) plen
4 [hci0] 16:45:13.219246
15,148407,14484097000,-;btmon: LE Start Encryption (0x08|0x0019) ncmd 1
15,148408,14484098000,-;btmon: Status: Success (0x00)
15,148409,14484101000,-;bluez: bluetoothd[1985]:
attrib/gattrib.c:g_attrib_ref() 0x51aab8: g_attrib_ref=1
15,148410,14484101000,-;bluez: bluetoothd[1985]:
profiles/gap/gas.c:gap_accept() GAP profile accept (D4:F5:13:xx:xx:xx)
15,148411,14484103000,-;bluez: bluetoothd[1985]:
profiles/gap/gas.c:handle_characteristic() Unsupported characteristic:
00002a02-0000-1000-8000-00805f9b34fb
15,148412,14484104000,-;bluez: bluetoothd[1985]:
profiles/gap/gas.c:handle_characteristic() Unsupported characteristic:
00002a03-0000-1000-8000-00805f9b34fb
15,148413,14484112000,-;bluez: bluetoothd[1985]:
profiles/gap/gas.c:handle_characteristic() Unsupported characteristic:
00002a04-0000-1000-8000-00805f9b34fb
15,148414,14484119000,-;bluez: bluetoothd[1985]:
src/service.c:change_state() 0x56ae98: device D4:F5:13:xx:xx:xx
profile gap-profile state changed: disconnected -> connected (0)
15,148415,14484121000,-;bluez: bluetoothd[1985]:
profiles/deviceinfo/deviceinfo.c:deviceinfo_accept() deviceinfo
profile accept (D4:F5:13:xx:xx:xx)
15,148416,14484121000,-;bluez: bluetoothd[1985]:
profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported
characteristic: 00002a23-0000-1000-8000-00805f9b34fb
15,148417,14484123000,-;bluez: bluetoothd[1985]:
profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported
characteristic: 00002a24-0000-1000-8000-00805f9b34fb
15,148418,14484124000,-;bluez: bluetoothd[1985]:
profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported
characteristic: 00002a25-0000-1000-8000-00805f9b34fb
15,148419,14484125000,-;bluez: bluetoothd[1985]:
profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported
characteristic: 00002a26-0000-1000-8000-00805f9b34fb
15,148420,14484127000,-;bluez: bluetoothd[1985]:
profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported
characteristic: 00002a27-0000-1000-8000-00805f9b34fb
15,148421,14484127000,-;bluez: bluetoothd[1985]:
profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported
characteristic: 00002a28-0000-1000-8000-00805f9b34fb
15,148422,14484132000,-;bluez: bluetoothd[1985]:
profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported
characteristic: 00002a29-0000-1000-8000-00805f9b34fb
15,148423,14484133000,-;bluez: bluetoothd[1985]:
profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported
characteristic: 00002a2a-0000-1000-8000-00805f9b34fb
15,148424,14484136000,-;bluez: bluetoothd[1985]:
src/service.c:change_state() 0x512ff0: device D4:F5:13:xx:xx:xx
profile deviceinfo state changed: disconnected -> connected (0)
15,148425,14484139000,-;bluez: bluetoothd[1985]:
profiles/battery/battery.c:batt_accept() BATT connected
15,148426,14484139000,-;bluez: bluetoothd[1985]:
src/service.c:change_state() 0x517cf0: device D4:F5:13:xx:xx:xx
profile Battery state changed: disconnected -> connected (0)
15,148427,14484141000,-;bluez: bluetoothd[1985]:
plugins/policy.c:service_cb() Added Battery reconnect 0
15,148428,14484142000,-;bluez: bluetoothd[1985]:
profiles/scanparam/scan.c:scan_param_accept() Scan Parameters Client
Driver profile accept (D4:F5:13:xx:xx:xx)
15,148429,14484147000,-;bluez: bluetoothd[1985]:
profiles/scanparam/scan.c:handle_iwin() Scan Interval Window handle:
0x002b
15,148430,14484150000,-;bluez: bluetoothd[1985]:
profiles/scanparam/scan.c:handle_refresh() Scan Refresh handle: 0x002d
15,148431,14484151000,-;bluez: bluetoothd[1985]:
src/service.c:change_state() 0x563e48: device D4:F5:13:xx:xx:xx
profile Scan Parameters Client Driver state changed: disconnected ->
connected (0)
15,148434,14484159000,-;bluez: bluetoothd[1985]:
src/service.c:change_state() 0x517cd0: device D4:F5:13:xx:xx:xx
profile input-hog state changed: disconnected -> connected (0)
15,148435,14484159000,-;bluez: bluetoothd[1985]:
plugins/policy.c:service_cb() Added input-hog reconnect 0
15,148436,14484162000,-;bluez: bluetoothd[1985]:
profiles/oad/oad.c:oad_accept() OAD connected
15,148437,14484164000,-;bluez: bluetoothd[1985]:
src/service.c:change_state() 0x56aa90: device D4:F5:13:xx:xx:xx
profile OAD state changed: disconnected -> connected (0)
15,148438,14484167000,-;bluez: bluetoothd[1985]:
plugins/policy.c:service_cb() Added OAD reconnect 0
15,148439,14484168000,-;bluez: bluetoothd[1985]:
profiles/oad/oad.c:oad_is_time_for_upgrade_check() OAD not time for
upgrade check yet (27717 seconds left)
15,148440,14484172000,-;bluez: bluetoothd[1985]:
src/gatt-client.c:btd_gatt_client_connected() Device connected.
15,148444,14484647000,-;btmon: > HCI Event: Encryption Change (0x08)
plen 4 [hci0] 16:45:13.772757
15,148445,14484648000,-;btmon: Status: Success (0x00)
15,148446,14484650000,-;btmon: Handle: 128
15,148447,14484650000,-;btmon: Encryption: Enabled with AES-CCM (0x01)
15,148448,14484650000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 11 [hci0] 16:45:13.773623
15,148449,14484650000,-;btmon: ATT: Write Command (0x52) len 6
15,148450,14484650000,-;btmon: Handle: 0x002b
15,148451,14484650000,-;btmon: Data: 60003000
15,148452,14484650000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 7 [hci0] 16:45:13.776191
15,148453,14484650000,-;btmon: ATT: Exchange MTU Request (0x02) len 2
15,148454,14484650000,-;btmon: Client RX MTU: 517
15,148455,14484653000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:13.781800
15,148456,14484654000,-;btmon: Num handles: 1
15,148457,14484654000,-;btmon: Handle: 128
15,148458,14484654000,-;btmon: Count: 1
15,148459,14484656000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 8 [hci0] 16:45:13.783776
15,148460,14484656000,-;btmon: ATT: Handle Value Notification (0x1b) len 3
15,148461,14484656000,-;btmon: Handle: 0x002e
15,148462,14484656000,-;btmon: Data: 00
15,148463,14484658000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:13.785586
15,148464,14484658000,-;btmon: Num handles: 1
15,148465,14484658000,-;btmon: Handle: 128
15,148466,14484658000,-;btmon: Count: 1
15,148467,14484676000,-;bluez: bluetoothd[1985]:
src/device.c:gatt_debug() MTU exchange complete, with MTU: 23
15,148468,14484676000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 7 [hci0] 16:45:13.803216
15,148469,14484676000,-;btmon: ATT: Exchange MTU Response (0x03) len 2
15,148470,14484676000,-;btmon: Server RX MTU: 23
15,148471,14484680000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 7 [hci0] 16:45:13.805360
15,148472,14484680000,-;btmon: ATT: Read Request (0x0a) len 2
15,148473,14484680000,-;btmon: Handle: 0x0003
15,148476,14485197000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:14.323660
15,148477,14485197000,-;btmon: Num handles: 1
15,148478,14485197000,-;btmon: Handle: 128
15,148479,14485197000,-;btmon: Count: 1
15,148480,14485215000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 12 [hci0] 16:45:14.343324
15,148481,14485215000,-;btmon: ATT: Read Response (0x0b) len 7
15,148482,14485215000,-;btmon: Value: xxxxxxxx
15,148483,14485216000,-;bluez: bluetoothd[1985]:
profiles/gap/gas.c:read_device_name_cb() GAP Device Name: xxxxxxxx
15,148484,14485218000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 7 [hci0] 16:45:14.345190
15,148485,14485218000,-;btmon: ATT: Read Request (0x0a) len 2
15,148486,14485218000,-;btmon: Handle: 0x0005
15,148487,14485280000,-;btmon: > HCI Event: Vendor (0xff) plen 5
[hci0] 16:45:14.408751
15,148488,14485280000,-;btmon: 05 80 00 09 00
.....
15,148497,14485736000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:14.864603
15,148498,14485736000,-;btmon: Num handles: 1
15,148499,14485736000,-;btmon: Handle: 128
15,148500,14485736000,-;btmon: Count: 1
15,148501,14485744000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 7 [hci0] 16:45:14.871746
15,148502,14485744000,-;btmon: ATT: Read Response (0x0b) len 2
15,148503,14485744000,-;btmon: Value: c003
15,148504,14485744000,-;bluez: bluetoothd[1985]:
profiles/gap/gas.c:read_appearance_cb() GAP Appearance: 0x03c0
15,148505,14485746000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 7 [hci0] 16:45:14.873179
15,148506,14485746000,-;btmon: ATT: Read Request (0x0a) len 214487
15,148507,14485746000,-;btmon: Handle: 0x0022
15,148508,14485754000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:14.881837
15,148509,14485754000,-;btmon: Num handles: 1
15,148510,14485754000,-;btmon: Handle: 128
15,148511,14485754000,-;btmon: Count: 1
15,148512,14485769000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 12 [hci0] 16:45:14.895082
15,148513,14485769000,-;btmon: ATT: Read Response (0x0b) len 7
15,148514,14485771000,-;btmon: Value: 010d0001f01600
15,148515,14485771000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 7 [hci0] 16:45:14.895711
15,148516,14485771000,-;btmon: ATT: Read Request (0x0a) len 2
15,148517,14485772000,-;btmon: Handle: 0x0
15,148518,14485775000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:14.903381
15,148519,14485775000,-;btmon: Num handles: 1
15,148520,14485775000,-;btmon: Handle: 128
15,148521,14485775000,-;btmon: Count: 1
15,148522,14485786000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 6 [hci0] 16:45:14.913585
15,148523,14485786000,-;btmon: ATT: Read Response (0x0b) len 1
15,148524,14485788000,-;bluez: bluetoothd[1985]:
profiles/battery/battery.c:level_read_char_cb() BATT level=100
15,148525,14485788000,-;btmon: Value: 64
15,148526,14485790000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 9 [hci0] 16:45:14.918396
15,148527,14485790000,-;btmon: ATT: Write Request (0x12) len 4
15,148528,14485790000,-;btmon: Handle: 0x002e
15,148529,14485790000,-;btmon: Data: 0100
15,148531,14486306000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:15.434853
15,148532,14486306000,-;btmon: Num handles: 1
15,148533,14486306000,-;btmon: Handle: 128
15,148534,14486306000,-;btmon: Count: 1
15,148535,14486316000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 5 [hci0] 16:45:15.443551
15,148536,14486316000,-;btmon: ATT: Write Response (0x13) len 0
15,148537,14486317000,-;bluez: bluetoothd[1985]:
profiles/scanparam/scan.c:refresh_ccc_written_cb() Scan Refresh:
notification enabled
15,148538,14486317000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 11 [hci0] 16:45:15.444853
15,148539,14486317000,-;btmon: ATT: Read By Type Request (0x08) len 6
15,148540,14486317000,-;btmon: Handle range: 0x002f-0x0037
15,148541,14486318000,-;btmon: Attribute type: Characteristic (0x2803)
15,148542,14486326000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:15.454609
15,148543,14486326000,-;btmon: Num handles: 1
15,148544,14486326000,-;btmon: Handle: 128
15,148545,14486326000,-;btmon: Count: 1
15,148546,14486356000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 27 [hci0] 16:45:15.484547
15,148547,14486356000,-;btmon: ATT: Read By Type Response (0x09) len 22
15,148548,14486356000,-;btmon: Attribute data length: 7
15,148549,14486356000,-;btmon: Attribute data list: 3 entries
15,148550,14486357000,-;btmon: Handle: 0x0030
15,148551,14486357000,-;btmon: Value: 1e3100f1ff
15,148552,14486357000,-;btmon: Handle: 0x0033
15,148553,14486357000,-;btmon: Value: 0a3400f2ff
15,148554,14486357000,-;btmon: Handle: 0x0035
15,148555,14486357000,-;btmon: Value: 123600f4ff
BlueZ request to re-discover peripheral's Primary Service starts below:
15,148556,14486357000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 11 [hci0] 16:45:15.485545
15,148557,14486357000,-;btmon: ATT: Read By Group Type Request
(0x10) len 6
15,148558,14486358000,-;btmon: Handle range: 0x0001-0xffff
15,148559,14486358000,-;btmon: Attribute group type: Primary
Service (0x2800)
15,148560,14486364000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:15.491805
15,148561,14486364000,-;btmon: Num handles: 1
15,148562,14486364000,-;btmon: Handle: 128
15,148563,14486364000,-;btmon: Count: 1
15,148564,14486384000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 24 [hci0] 16:45:15.511935
15,148565,14486384000,-;btmon: ATT: Read By Group Type Response
(0x11) len 19
15,148566,14486384000,-;btmon: Attribute data length: 6
15,148567,14486384000,-;btmon: Attribute group list: 3 entries
15,148568,14486384000,-;btmon: Handle range: 0x0001-0x000b
15,148569,14486384000,-;btmon: UUID: Generic Access Profile (0x1800)
15,148570,14486385000,-;btmon: Handle range: 0x000c-0x000f
15,148571,14486385000,-;btmon: UUID: Generic Attribute Profile (0x1801)
15,148572,14486385000,-;btmon: Handle range: 0x0010-0x0022
15,148573,14486386000,-;btmon: UUID: Device Information (0x180a)
15,148574,14486386000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 11 [hci0] 16:45:15.512563
15,148575,14486386000,-;btmon: ATT: Read By Type Request (0x08) len 6
15,148576,14486386000,-;btmon: Handle range: 0x0036-0x0037
15,148577,14486386000,-;btmon: Attribute type: Characteristic (0x2803)
15,148578,14486395000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:15.521844
15,148579,14486395000,-;btmon: Num handles: 1
15,148580,14486395000,-;btmon: Handle: 128
15,148581,14486400000,-;btmon: Count: 1
15,148582,14486404000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 9 [hci0] 16:45:15.532197
15,148583,14486404000,-;btmon: ATT: Error Response (0x01) len 4
15,148584,14486404000,-;btmon: Read By Type Request (0x08)
15,148585,14486404000,-;btmon: Handle: 0x0036
15,148586,14486404000,-;btmon: Error: Attribute Not Found (0x0a)
15,148587,14486405000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 11 [hci0] 16:45:15.533289
15,148588,14486405000,-;btmon: ATT: Read By Group Type Request
(0x10) len 6
15,148589,14486405000,-;btmon: Handle range: 0x0023-0xffff
15,148590,14486405000,-;btmon: Attribute group type: Primary
Service (0x2800)
15,148591,14486414000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:15.541821
15,148592,14486414000,-;btmon: Num handles: 1
15,148593,14486414000,-;btmon: Handle: 128
15,148594,14486414000,-;btmon: Count: 1
15,148595,14486448000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 24 [hci0] 16:45:15.574739
15,148596,14486449000,-;btmon: ATT: Read By Group Type Response
(0x11) len 19
15,148597,14486449000,-;btmon: Attribute data length: 6
15,148598,14486450000,-;btmon: Attribute group list: 3 entries
15,148599,14486450000,-;btmon: Handle range: 0x0023-0x0028
15,148600,14486450000,-;btmon: UUID: Battery Service (0x180f)
15,148601,14486450000,-;btmon: Handle range: 0x0029-0x002e
15,148602,14486450000,-;btmon: UUID: Scan Parameters (0x1813)
15,148603,14486450000,-;btmon: Handle range: 0x002f-0x0037
15,148604,14486450000,-;btmon: UUID: Unknown (0xfff0)
15,148605,14486450000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 9 [hci0] 16:45:15.575704
15,148606,14486450000,-;btmon: ATT: Find Information Request (0x04) len 4
15,148607,14486450000,-;btmon: Handle range: 0x0036-0x0037
15,148608,14486454000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:15.581832
15,148609,14486454000,-;btmon: Num handles: 1
15,148610,14486454000,-;btmon: Handle: 128
15,148611,14486454000,-;btmon: Count: 1
15,148614,14486476000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 14 [hci0] 16:45:15.603418
15,148615,14486476000,-;btmon: ATT: Find Information Response (0x05) len 9
15,148616,14486476000,-;btmon: Format: UUID-16 (0x01)
15,148617,14486476000,-;btmon: Handle: 0x0036
15,148618,14486476000,-;btmon: UUID: Unknown (0xfff4)
15,148619,14486477000,-;btmon: Handle: 0x0037
15,148620,14486477000,-;btmon: UUID: Client Characteristic
Configuration (0x2902)
15,148621,14486477000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 10 [hci0] 16:45:15.604557
15,148622,14486477000,-;btmon: ATT: Write Request (0x12) len 5
15,148623,14486477000,-;btmon: Handle: 0x0034
15,148624,14486477000,-;btmon: Data: 030000
15,148625,14486485000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:15.613570
15,148626,14486485000,-;btmon: Num handles: 1
15,148627,14486485000,-;btmon: Handle: 128
15,148628,14486485000,-;btmon: Count: 1
15,148629,14486496000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 5 [hci0] 16:45:15.623625
15,148630,14486496000,-;btmon: ATT: Write Response (0x13) len 0
15,148631,14486496000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 11 [hci0] 16:45:15.624699
15,148632,14486496000,-;btmon: ATT: Read By Group Type Request
(0x10) len 6
15,148633,14486496000,-;btmon: Handle range: 0x0038-0xffff
15,148634,14486496000,-;btmon: Attribute group type: Primary
Service (0x2800)
15,148635,14486509000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:15.637188
15,148636,14486509000,-;btmon: Num handles: 1
15,148637,14486509000,-;btmon: Handle: 128
15,148638,14486509000,-;btmon: Count: 1
15,148639,14486525000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 12 [hci0] 16:45:15.652267
15,148640,14486525000,-;btmon: ATT: Read By Group Type Response
(0x11) len 7
15,148641,14486525000,-;btmon: Attribute data length: 6
15,148642,14486525000,-;btmon: Attribute group list: 1 entry
15,148643,14486525000,-;btmon: Handle range: 0x0038-0x005c
15,148644,14486525000,-;btmon: UUID: Human Interface Device (0x1812)
15,148645,14486526000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 9 [hci0] 16:45:15.654189
15,148646,14486526000,-;btmon: ATT: Write Request (0x12) len 4
15,148647,14486526000,-;btmon: Handle: 0x0037
15,148648,14486526000,-;btmon: Data: 0100
15,148650,14486543000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:15.671923
15,148651,14486543000,-;btmon: Num handles: 1
15,148652,14486543000,-;btmon: Handle: 128
15,148653,14486544000,-;btmon: Count: 1
15,148654,14486574000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 5 [hci0] 16:45:15.702603
15,148655,14486574000,-;btmon: ATT: Write Response (0x13) len 0
15,148656,14486575000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 11 [hci0] 16:45:15.703208
15,148657,14486575000,-;btmon: ATT: Read By Group Type Request
(0x10) len 6
15,148658,14486575000,-;btmon: Handle range: 0x005d-0xffff
15,148659,14486575000,-;btmon: Attribute group type: Primary
Service (0x2800)
15,148660,14486586000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:15.714715
15,148661,14486586000,-;btmon: Num handles: 1
15,148662,14486586000,-;btmon: Handle: 128
15,148663,14486586000,-;btmon: Count: 1
15,148664,14486617000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 26 [hci0] 16:45:15.744781
15,148665,14486617000,-;btmon: ATT: Read By Group Type Response
(0x11) len 21
15,148666,14486617000,-;btmon: Attribute data length: 20
15,148667,14486617000,-;btmon: Attribute group list: 1 entry
15,148668,14486617000,-;btmon: Handle range: 0x005d-0x0070
15,148669,14486617000,-;btmon: UUID: Vendor specific
(f000fef0-0451-4000-b000-000000000000)
15,148670,14486618000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 11 [hci0] 16:45:15.746142
15,148671,14486619000,-;btmon: ATT: Read By Group Type Request
(0x10) len 6
15,148672,14486619000,-;btmon: Handle range: 0x0071-0xffff
15,148673,14486620000,-;btmon: Attribute group type: Primary
Service (0x2800)
15,148675,14487139000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:16.267193
15,148676,14487139000,-;btmon: Num handles: 1
15,148677,14487139000,-;btmon: Handle: 128
15,148678,14487139000,-;btmon: Count: 1
15,148679,14487156000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 26 [hci0] 16:45:16.284511
15,148680,14487156000,-;btmon: ATT: Read By Group Type Response
(0x11) len 21
15,148681,14487156000,-;btmon: Attribute data length: 20
15,148682,14487156000,-;btmon: Attribute group list: 1 entry
15,148683,14487157000,-;btmon: Handle range: 0x0071-0xffff
15,148684,14487157000,-;btmon: UUID: Vendor specific
(f000ffc0-0451-4000-b000-000000000000)
15,148685,14487157000,-;bluez: bluetoothd[1985]:
src/device.c:gatt_debug() Primary services found: 9
15,148686,14487157000,-;bluez: bluetoothd[1985]:
src/device.c:gatt_debug() start: 0x0001, end: 0x000b, uuid:
00001800-0000-1000-8000-00805f9b34fb
15,148687,14487157000,-;bluez: bluetoothd[1985]:
src/device.c:gatt_debug() start: 0x000c, end: 0x000f, uuid:
00001801-0000-1000-8000-00805f9b34fb
15,148688,14487158000,-;bluez: bluetoothd[1985]:
src/device.c:gatt_debug() start: 0x0010, end: 0x0022, uuid:
0000180a-0000-1000-8000-00805f9b34fb
15,148689,14487158000,-;bluez: bluetoothd[1985]:
src/device.c:gatt_debug() start: 0x0023, end: 0x0028, uuid:
0000180f-0000-1000-8000-00805f9b34fb
15,148690,14487160000,-;bluez: bluetoothd[1985]:
src/device.c:gatt_debug() start: 0x0029, end: 0x002e, uuid:
00001813-0000-1000-8000-00805f9b34fb
15,148691,14487160000,-;bluez: bluetoothd[1985]:
src/device.c:gatt_debug() start: 0x002f, end: 0x0037, uuid:
0000fff0-0000-1000-8000-00805f9b34fb
15,148692,14487160000,-;bluez: bluetoothd[1985]:
src/device.c:gatt_debug() start: 0x0038, end: 0x005c, uuid:
00001812-0000-1000-8000-00805f9b34fb
15,148693,14487161000,-;bluez: bluetoothd[1985]:
src/device.c:gatt_debug() start: 0x005d, end: 0x0070, uuid:
f000fef0-0451-4000-b000-000000000000
15,148694,14487163000,-;bluez: bluetoothd[1985]:
src/device.c:gatt_debug() start: 0x0071, end: 0xffff, uuid:
f000ffc0-0451-4000-b000-000000000000
15,148695,14487166000,-;bluez: bluetoothd[1985]:
src/device.c:gatt_client_ready_cb() status: success, error: 0
15,148696,14487169000,-;bluez: bluetoothd[1985]:
src/gatt-client.c:btd_gatt_client_ready() GATT client ready
15,148697,14487169000,-;bluez: bluetoothd[1985]:
src/gatt-client.c:create_services() Exporting objects for GATT
services: D4:F5:13:xx:xx:xx
15,148698,14487169000,-;bluez: bluetoothd[1985]:
src/device.c:device_svc_resolved()
/org/bluez/hci0/dev_D4_F5_13_xx_xx_xx err 0
15,148700,14487208000,-;btmon: < ACL Data TX: Handle 128 flags 0x00
dlen 9 [hci0] 16:45:16.336263
15,148701,14487208000,-;btmon: ATT: Write Request (0x12) len 4
15,148702,14487208000,-;btmon: Handle: 0x000f
15,148703,14487208000,-;btmon: Data: 0200
15,148713,14487675000,-;btmon: > HCI Event: Number of Completed
Packets (0x13) plen 5 [hci0] 16:45:16.803794
15,148714,14487675000,-;btmon: Num handles: 1
15,148715,14487676000,-;btmon: Handle: 128
15,148716,14487676000,-;btmon: Count: 1
15,148717,14487705000,-;btmon: > ACL Data RX: Handle 128 flags 0x02
dlen 5 [hci0] 16:45:16.833390
15,148718,14487705000,-;btmon: ATT: Write Response (0x13) len 0
15,148719,14487706000,-;bluez: bluetoothd[1985]:
src/device.c:gatt_debug() Registered handler for "Service Changed": 2
In the above log, I see that MTU exchange takes place:
15,148467,14484676000,-;bluez: bluetoothd[1985]:
src/device.c:gatt_debug() MTU exchange complete, with MTU: 23
Looking at the relevant code in src/shared/gatt-client.c, function
exchange_mtu_cb():
util_debug(client->debug_callback, client->debug_data,
"MTU exchange complete, with MTU: %u",
bt_att_get_mtu(client->att));
discover:
client->discovery_req = bt_gatt_discover_all_primary_services(
client->att, NULL,
discover_primary_cb,
discovery_op_ref(op),
discovery_op_unref);
The call to bt_gatt_discover_all_primary_services() is unconditional,
whether the device was previously bonded or not.
-- Petri
^ permalink raw reply [flat|nested] 16+ messages in thread* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect 2016-11-09 19:39 BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect Petri Gynther @ 2016-11-10 14:17 ` Luiz Augusto von Dentz 2016-11-11 2:42 ` Petri Gynther 0 siblings, 1 reply; 16+ messages in thread From: Luiz Augusto von Dentz @ 2016-11-10 14:17 UTC (permalink / raw) To: Petri Gynther; +Cc: linux-bluetooth Hi Petri, On Wed, Nov 9, 2016 at 9:39 PM, Petri Gynther <pgynther@google.com> wrote: > Hi linux-bluetooth: > > I'm seeing the following issue with BlueZ 5.43 and Linux 4.4.30. > > When a previously bonded HoG remote control reconnects to BlueZ 5.43 > host, BlueZ goes ahead and re-discovers the primary services of the > bonded remote again and again on every reconnect. > > Why is this necessary? Shouldn't this information be cached on the > initial pairing/bonding, and a reconnect can get this information from > the relevant persistent file, rather than wasting BLE airtime and > delaying the reconnect? > IF, and only if, the cache is restored properly then yes it will work as you said, but bt_hog is not yet using the gatt_db so it might rediscover the handles anyway, this happens only once though. > > > In the above log, I see that MTU exchange takes place: > 15,148467,14484676000,-;bluez: bluetoothd[1985]: > src/device.c:gatt_debug() MTU exchange complete, with MTU: 23 > > Looking at the relevant code in src/shared/gatt-client.c, function > exchange_mtu_cb(): > > util_debug(client->debug_callback, client->debug_data, > "MTU exchange complete, with MTU: %u", > bt_att_get_mtu(client->att)); > > discover: > client->discovery_req = bt_gatt_discover_all_primary_services( > client->att, NULL, > discover_primary_cb, > discovery_op_ref(op), > discovery_op_unref); > > > The call to bt_gatt_discover_all_primary_services() is unconditional, > whether the device was previously bonded or not. This does range validation in case service changed is not properly implemented this will attempt to figure out if there are any changes in the database, but note that it will stop in here: attr = gatt_db_insert_service(client->db, start, &uuid, true, end - start + 1); if (!attr) { So if the database already contain all the services it will no do more than one Read By Group Type. -- Luiz Augusto von Dentz ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect 2016-11-10 14:17 ` Luiz Augusto von Dentz @ 2016-11-11 2:42 ` Petri Gynther 2016-11-11 9:07 ` Luiz Augusto von Dentz 0 siblings, 1 reply; 16+ messages in thread From: Petri Gynther @ 2016-11-11 2:42 UTC (permalink / raw) To: Luiz Augusto von Dentz; +Cc: linux-bluetooth Hi Luiz, On Thu, Nov 10, 2016 at 6:17 AM, Luiz Augusto von Dentz <luiz.dentz@gmail.com> wrote: > Hi Petri, > > On Wed, Nov 9, 2016 at 9:39 PM, Petri Gynther <pgynther@google.com> wrote: >> Hi linux-bluetooth: >> >> I'm seeing the following issue with BlueZ 5.43 and Linux 4.4.30. >> >> When a previously bonded HoG remote control reconnects to BlueZ 5.43 >> host, BlueZ goes ahead and re-discovers the primary services of the >> bonded remote again and again on every reconnect. >> >> Why is this necessary? Shouldn't this information be cached on the >> initial pairing/bonding, and a reconnect can get this information from >> the relevant persistent file, rather than wasting BLE airtime and >> delaying the reconnect? >> > > IF, and only if, the cache is restored properly then yes it will work > as you said, but bt_hog is not yet using the gatt_db so it might > rediscover the handles anyway, this happens only once though. > >> >> >> In the above log, I see that MTU exchange takes place: >> 15,148467,14484676000,-;bluez: bluetoothd[1985]: >> src/device.c:gatt_debug() MTU exchange complete, with MTU: 23 >> >> Looking at the relevant code in src/shared/gatt-client.c, function >> exchange_mtu_cb(): >> >> util_debug(client->debug_callback, client->debug_data, >> "MTU exchange complete, with MTU: %u", >> bt_att_get_mtu(client->att)); >> >> discover: >> client->discovery_req = bt_gatt_discover_all_primary_services( >> client->att, NULL, >> discover_primary_cb, >> discovery_op_ref(op), >> discovery_op_unref); >> >> >> The call to bt_gatt_discover_all_primary_services() is unconditional, >> whether the device was previously bonded or not. > > This does range validation in case service changed is not properly > implemented this will attempt to figure out if there are any changes > in the database, but note that it will stop in here: > > attr = gatt_db_insert_service(client->db, start, &uuid, true, > end - start + 1); > if (!attr) { > > So if the database already contain all the services it will no do more > than one Read By Group Type. > > -- > Luiz Augusto von Dentz I'm observing primary services re-discovery on every reconnect, even on the first reconnect after the initial pairing. Multiple Read By Group Type messages are sent to the remote, until all primary services have been re-discovered. The files D4:F5:13:xx:xx:xx/attributes and cache/D4:F5:13:xx:xx:xx exist and contain valid data. Here is the log for the initial pairing: 15,15255,744664000,-;bluez: bluetoothd[2346]: src/device.c:bonding_request_new() Requesting bonding for D4:F5:13:xx:xx:xx 15,15256,744664000,-;bluez: bluetoothd[2346]: src/agent.c:agent_ref() 0x51c600: ref=3 15,15257,744664000,-;bluez: bluetoothd[2346]: src/agent.c:agent_unref() 0x51c600: ref=2 15,15258,744664000,-;bluez: bluetoothd[2346]: src/adapter.c:suspend_discovery() 15,15259,744667000,-;bluez: bluetoothd[2346]: src/adapter.c:adapter_bonding_attempt() hci0 bdaddr D4:F5:13:xx:xx:xx type 1 io_cap 0x03 15,15306,744819000,-;bluez: bluetoothd[2346]: src/adapter.c:connected_callback() hci0 device D4:F5:13:xx:xx:xx connected eir_len 30 15,15313,744822000,-;bluez: bluetoothd[2346]: src/adapter.c:connected_callback() device 0x518440 paired 0 bonded 0 bonding 1 15,15314,744822000,-;bluez: bluetoothd[2346]: src/device.c:device_set_class() /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx 0x20050C 15,15387,744928000,-;bluez: bluetoothd[2346]: src/gatt-database.c:connect_cb() New incoming LE ATT connection 15,15388,744947000,-;bluez: bluetoothd[2346]: attrib/gattrib.c:g_attrib_ref() 0x5159d8: g_attrib_ref=1 15,15389,744947000,-;bluez: bluetoothd[2346]: src/device.c:load_gatt_db() Restoring D4:F5:13:xx:xx:xx gatt database from file 15,15390,744948000,-;bluez: bluetoothd[2346]: No cache for D4:F5:13:xx:xx:xx 15,15394,744951000,-;bluez: bluetoothd[2346]: src/gatt-client.c:btd_gatt_client_connected() Device connected. 15,15413,745068000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() MTU exchange complete, with MTU: 23 15,15442,745101000,-;bluez: bluetoothd[2346]: src/adapter.c:new_irk_callback() hci0 new IRK for D4:F5:13:xx:xx:xx RPA 00:00:00:00:00:00 15,15466,745120000,-;bluez: bluetoothd[2346]: src/adapter.c:new_csrk_callback() hci0 new CSRK for D4:F5:13:xx:xx:xx type 1 15,15489,745161000,-;bluez: bluetoothd[2346]: src/adapter.c:new_csrk_callback() hci0 new CSRK for D4:F5:13:xx:xx:xx type 0 15,15490,745177000,-;bluez: bluetoothd[2346]: src/adapter.c:new_long_term_key_callback() hci0 new LTK for D4:F5:13:xx:xx:xx type 0 enc_size 16 15,15491,745193000,-;bluez: bluetoothd[2346]: src/device.c:device_set_bonded() 15,15492,745193000,-;bluez: bluetoothd[2346]: src/device.c:device_bonding_complete() bonding 0x51a458 status 0x00 15,15493,745194000,-;bluez: bluetoothd[2346]: src/device.c:device_bonding_complete() Proceeding with service discovery 15,15494,745194000,-;bluez: bluetoothd[2346]: src/agent.c:agent_unref() 0x51c600: ref=1 15,15496,745196000,-;bluez: bluetoothd[2346]: src/adapter.c:resume_discovery() 15,15500,745198000,-;bluez: bluetoothd[2346]: src/adapter.c:new_long_term_key_callback() hci0 new LTK for D4:F5:13:xx:xx:xx type 0 enc_size 16 15,15505,745216000,-;bluez: bluetoothd[2346]: src/device.c:device_set_bonded() 15,15506,745216000,-;bluez: bluetoothd[2346]: src/device.c:device_bonding_complete() bonding (nil) status 0x00 15,15507,745217000,-;bluez: bluetoothd[2346]: src/adapter.c:resume_discovery() 15,15514,745230000,-;bluez: bluetoothd[2346]: src/adapter.c:pair_device_complete() Success (0x00) 15,15515,745230000,-;bluez: bluetoothd[2346]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr D4:F5:13:xx:xx:xx type 1 status 0x0 15,15516,745233000,-;bluez: bluetoothd[2346]: src/device.c:device_bonding_complete() bonding (nil) status 0x00 15,15517,745233000,-;bluez: bluetoothd[2346]: src/adapter.c:resume_discovery() 15,15548,745375000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Primary services found: 9 15,15549,745375000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0001, end: 0x000b, uuid: 00001800-0000-1000-8000-00805f9b34fb 15,15550,745376000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x000c, end: 0x000f, uuid: 00001801-0000-1000-8000-00805f9b34fb 15,15551,745377000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0010, end: 0x0022, uuid: 0000180a-0000-1000-8000-00805f9b34fb 15,15552,745380000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0023, end: 0x0028, uuid: 0000180f-0000-1000-8000-00805f9b34fb 15,15553,745380000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0029, end: 0x002e, uuid: 00001813-0000-1000-8000-00805f9b34fb 15,15554,745381000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x002f, end: 0x0037, uuid: 0000fff0-0000-1000-8000-00805f9b34fb 15,15555,745384000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0038, end: 0x005c, uuid: 00001812-0000-1000-8000-00805f9b34fb 15,15556,745384000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x005d, end: 0x0070, uuid: f000fef0-0451-4000-b000-000000000000 15,15557,745384000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0071, end: 0xffff, uuid: f000ffc0-0451-4000-b000-000000000000 15,15571,745472000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Secondary service discovery failed. ATT ECODE: 0x10 15,15672,745685000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Included services found: 1 15,15673,745685000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0039, start: 0x0023, end: 0x0028,uuid: 0000180f-0000-1000-8000-0080 15,15753,745903000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Characteristics found: 5 15,15754,745904000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0002, end: 0x0003, value: 0x0003, props: 0x02, uuid: 00002a00-0000-1 15,15755,745905000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0004, end: 0x0005, value: 0x0005, props: 0x02, uuid: 00002a01-0000-1 15,15756,745906000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0006, end: 0x0007, value: 0x0007, props: 0x0a, uuid: 00002a02-0000-1 15,15757,745907000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0008, end: 0x0009, value: 0x0009, props: 0x08, uuid: 00002a03-0000-1 15,15758,745912000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x000a, end: 0x000b, value: 0x000b, props: 0x02, uuid: 00002a04-0000-1 15,15789,746112000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Characteristics found: 1 15,15790,746113000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x000d, end: 0x000f, value: 0x000e, props: 0x20, uuid: 00002a05-0000-1 15,15798,746134000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 1 15,15804,746134000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x000f, uuid: 00002902-0000-1000-8000-00805f9b34fb 15,15875,746292000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Characteristics found: 9 15,15876,746294000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0011, end: 0x0012, value: 0x0012, props: 0x02, uuid: 00002a23-0000-1 15,15877,746294000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0013, end: 0x0014, value: 0x0014, props: 0x02, uuid: 00002a24-0000-1 15,15878,746296000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0015, end: 0x0016, value: 0x0016, props: 0x02, uuid: 00002a25-0000-1 15,15879,746296000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0017, end: 0x0018, value: 0x0018, props: 0x02, uuid: 00002a26-0000-1 15,15880,746300000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0019, end: 0x001a, value: 0x001a, props: 0x02, uuid: 00002a27-0000-1 15,15883,746304000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x001b, end: 0x001c, value: 0x001c, props: 0x02, uuid: 00002a28-0000-1 15,15884,746307000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x001d, end: 0x001e, value: 0x001e, props: 0x02, uuid: 00002a29-0000-1 15,15885,746307000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x001f, end: 0x0020, value: 0x0020, props: 0x02, uuid: 00002a2a-0000-1 15,15886,746308000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0021, end: 0x0022, value: 0x0022, props: 0x02, uuid: 00002a50-0000-1 15,15914,746423000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Characteristics found: 1 15,15915,746424000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0024, end: 0x0028, value: 0x0025, props: 0x12, uuid: 00002a19-0000-1 15,15932,746453000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 3 15,15933,746453000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0026, uuid: 00002902-0000-1000-8000-00805f9b34fb 15,15934,746453000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0027, uuid: 00002908-0000-1000-8000-00805f9b34fb 15,15935,746455000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0028, uuid: 00002904-0000-1000-8000-00805f9b34fb 15,15960,746513000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Characteristics found: 2 15,15962,746514000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x002a, end: 0x002b, value: 0x002b, props: 0x04, uuid: 00002a4f-0000-1 15,15964,746515000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x002c, end: 0x002e, value: 0x002d, props: 0x10, uuid: 00002a31-0000-1 15,15980,746535000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 1 15,15981,746536000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x002e, uuid: 00002902-0000-1000-8000-00805f9b34fb 15,16014,746904000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Characteristics found: 3 15,16015,746904000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0030, end: 0x0032, value: 0x0031, props: 0x1e, uuid: 0000fff1-0000-1 15,16016,746905000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0033, end: 0x0034, value: 0x0034, props: 0x0a, uuid: 0000fff2-0000-1 15,16017,746909000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0035, end: 0x0037, value: 0x0036, props: 0x12, uuid: 0000fff4-0000-1 15,16029,747004000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 1 15,16031,747005000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0032, uuid: 00002902-0000-1000-8000-00805f9b34fb 15,16044,747124000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 1 15,16045,747124000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0037, uuid: 00002902-0000-1000-8000-00805f9b34fb 15,16128,747343000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Characteristics found: 12 15,16130,747343000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x003a, end: 0x003b, value: 0x003b, props: 0x02, uuid: 00002a4a-0000-1 15,16132,747344000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x003c, end: 0x003d, value: 0x003d, props: 0x04, uuid: 00002a4c-0000-1 15,16135,747345000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x003e, end: 0x003f, value: 0x003f, props: 0x06, uuid: 00002a4e-0000-1 15,16137,747346000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0040, end: 0x0042, value: 0x0041, props: 0x02, uuid: 00002a4b-0000-1 15,16139,747347000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0043, end: 0x0046, value: 0x0044, props: 0x12, uuid: 00002a4d-0000-1 15,16141,747350000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0047, end: 0x004a, value: 0x0048, props: 0x12, uuid: 00002a4d-0000-1 15,16142,747351000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x004b, end: 0x004e, value: 0x004c, props: 0x12, uuid: 00002a4d-0000-1 15,16143,747355000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x004f, end: 0x0051, value: 0x0050, props: 0x0e, uuid: 00002a4d-0000-1 15,16144,747356000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0052, end: 0x0054, value: 0x0053, props: 0x12, uuid: 00002a22-0000-1 15,16145,747359000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0055, end: 0x0056, value: 0x0056, props: 0x0e, uuid: 00002a32-0000-1 15,16146,747361000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0057, end: 0x0059, value: 0x0058, props: 0x12, uuid: 00002a33-0000-1 15,16147,747363000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x005a, end: 0x005c, value: 0x005b, props: 0x0a, uuid: 00002a4d-0000-1 15,16156,747526000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 1 15,16157,747526000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0042, uuid: 00002907-0000-1000-8000-00805f9b34fb 15,16177,747635000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 2 15,16178,747638000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0045, uuid: 00002902-0000-1000-8000-00805f9b34fb 15,16179,747638000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0046, uuid: 00002908-0000-1000-8000-00805f9b34fb 15,16195,747744000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 2 15,16196,747744000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0049, uuid: 00002902-0000-1000-8000-00805f9b34fb 15,16197,747744000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x004a, uuid: 00002908-0000-1000-8000-00805f9b34fb 15,16213,747776000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 2 15,16214,747776000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x004d, uuid: 00002902-0000-1000-8000-00805f9b34fb 15,16215,747776000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x004e, uuid: 00002908-0000-1000-8000-00805f9b34fb 15,16225,747873000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 1 15,16231,747874000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0051, uuid: 00002908-0000-1000-8000-00805f9b34fb 15,16244,747894000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 1 15,16245,747894000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0054, uuid: 00002902-0000-1000-8000-00805f9b34fb 15,16258,747913000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 1 15,16259,747913000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0059, uuid: 00002902-0000-1000-8000-00805f9b34fb 15,16272,747936000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 1 15,16273,747936000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x005c, uuid: 00002908-0000-1000-8000-00805f9b34fb 15,16416,748556000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Characteristics found: 9 15,16422,748563000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x005e, end: 0x005f, value: 0x005f, props: 0x0a, uuid: f000fef1-0451-4 15,16423,748563000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0060, end: 0x0061, value: 0x0061, props: 0x0a, uuid: f000fef2-0451-4 15,16424,748563000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0062, end: 0x0063, value: 0x0063, props: 0x0a, uuid: f000fef3-0451-4 15,16425,748563000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0064, end: 0x0065, value: 0x0065, props: 0x0a, uuid: f000fef4-0451-4 15,16426,748563000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0066, end: 0x0068, value: 0x0067, props: 0x08, uuid: f000fef5-0451-4 15,16427,748565000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0069, end: 0x006a, value: 0x006a, props: 0x0a, uuid: f000fef6-0451-4 15,16428,748565000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x006b, end: 0x006c, value: 0x006c, props: 0x0a, uuid: f000fef7-0451-4 15,16429,748567000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x006d, end: 0x006e, value: 0x006e, props: 0x0a, uuid: f000fef8-0451-4 15,16430,748572000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x006f, end: 0x0070, value: 0x0070, props: 0x08, uuid: f000fef9-0451-4 15,16443,748665000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 1 15,16444,748665000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0068, uuid: 00002902-0000-1000-8000-00805f9b34fb 15,16488,748827000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Characteristics found: 2 15,16489,748827000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0072, end: 0x0074, value: 0x0073, props: 0x1c, uuid: f000ffc1-0451-4 15,16490,748827000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0075, end: 0xffff, value: 0x0076, props: 0x1c, uuid: f000ffc2-0451-4 15,16505,748849000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 1 15,16506,748849000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0074, uuid: 00002902-0000-1000-8000-00805f9b34fb 15,16534,748968000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Descriptors found: 1 15,16535,748968000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() handle: 0x0077, uuid: 00002902-0000-1000-8000-00805f9b34fb 15,16536,748968000,-;bluez: bluetoothd[2346]: src/device.c:gatt_client_ready_cb() status: success, error: 10 15,16537,748973000,-;bluez: bluetoothd[2346]: src/device.c:update_gatt_uuids() UUID Added: 00001800-0000-1000-8000-00805f9b34fb 15,16538,748975000,-;bluez: bluetoothd[2346]: src/device.c:update_gatt_uuids() UUID Added: 00001801-0000-1000-8000-00805f9b34fb 15,16539,748975000,-;bluez: bluetoothd[2346]: src/device.c:update_gatt_uuids() UUID Added: 0000180a-0000-1000-8000-00805f9b34fb 15,16540,748978000,-;bluez: bluetoothd[2346]: src/device.c:update_gatt_uuids() UUID Added: 0000180f-0000-1000-8000-00805f9b34fb 15,16541,748978000,-;bluez: bluetoothd[2346]: src/device.c:update_gatt_uuids() UUID Added: 00001813-0000-1000-8000-00805f9b34fb 15,16542,748979000,-;bluez: bluetoothd[2346]: src/device.c:update_gatt_uuids() UUID Added: 0000fff0-0000-1000-8000-00805f9b34fb 15,16543,748981000,-;bluez: bluetoothd[2346]: src/device.c:update_gatt_uuids() UUID Added: 00001812-0000-1000-8000-00805f9b34fb 15,16544,748981000,-;bluez: bluetoothd[2346]: src/device.c:update_gatt_uuids() UUID Added: f000fef0-0451-4000-b000-000000000000 15,16545,748983000,-;bluez: bluetoothd[2346]: src/device.c:update_gatt_uuids() UUID Added: f000ffc0-0451-4000-b000-000000000000 15,16546,748987000,-;bluez: bluetoothd[2346]: src/device.c:device_probe_profiles() Probing profiles for device D4:F5:13:xx:xx:xx 15,16554,748989000,-;bluez: bluetoothd[2346]: profiles/gap/gas.c:gap_probe() GAP profile probe (D4:F5:13:xx:xx:xx) 15,16555,748991000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x563210: device D4:F5:13:xx:xx:xx profile gap-profile state changed: unavailable -> disconnected (0) 15,16556,748993000,-;bluez: bluetoothd[2346]: profiles/gap/gas.c:gap_accept() GAP profile accept (D4:F5:13:xx:xx:xx) 15,16558,748998000,-;bluez: bluetoothd[2346]: profiles/gap/gas.c:handle_characteristic() Unsupported characteristic: 00002a02-0000-1000-8000-00805f9b34fb 15,16559,749000000,-;bluez: bluetoothd[2346]: profiles/gap/gas.c:handle_characteristic() Unsupported characteristic: 00002a03-0000-1000-8000-00805f9b34fb 15,16560,749000000,-;bluez: bluetoothd[2346]: profiles/gap/gas.c:handle_characteristic() Unsupported characteristic: 00002a04-0000-1000-8000-00805f9b34fb 15,16561,749002000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x563210: device D4:F5:13:xx:xx:xx profile gap-profile state changed: disconnected -> connected (0) 15,16563,749003000,-;bluez: bluetoothd[2346]: src/device.c:device_probe_profiles() Probing profiles for device D4:F5:13:xx:xx:xx 15,16564,749006000,-;bluez: bluetoothd[2346]: src/device.c:device_probe_profiles() Probing profiles for device D4:F5:13:xx:xx:xx 15,16567,749011000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564370: device D4:F5:13:xx:xx:xx profile deviceinfo state changed: unavailable -> disconnected (0) 15,16568,749015000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:deviceinfo_accept() deviceinfo profile accept (D4:F5:13:xx:xx:xx) 15,16569,749018000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a23-0000-1000-8000-00805f9b34fb 15,16570,749019000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a24-0000-1000-8000-00805f9b34fb 15,16571,749021000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a25-0000-1000-8000-00805f9b34fb 15,16572,749023000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a26-0000-1000-8000-00805f9b34fb 15,16573,749024000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a27-0000-1000-8000-00805f9b34fb 15,16574,749024000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a28-0000-1000-8000-00805f9b34fb 15,16575,749026000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a29-0000-1000-8000-00805f9b34fb 15,16576,749027000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a2a-0000-1000-8000-00805f9b34fb 15,16577,749028000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564370: device D4:F5:13:xx:xx:xx profile deviceinfo state changed: disconnected -> connected (0) 15,16578,749030000,-;bluez: bluetoothd[2346]: src/device.c:device_probe_profiles() Probing profiles for device D4:F5:13:xx:xx:xx 15,16579,749031000,-;bluez: bluetoothd[2346]: profiles/battery/battery.c:batt_probe() BATT path /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx 15,16580,749032000,-;bluez: bluetoothd[2346]: profiles/battery/battery.c:batt_probe() BATT matched BATT_UUID 0000180f-0000-1000-8000-00805f9b34fb 15,16581,749037000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564408: device D4:F5:13:xx:xx:xx profile Battery state changed: unavailable -> disconnected (0) 15,16582,749038000,-;bluez: bluetoothd[2346]: src/device.c:device_set_auto_connect() D4:F5:13:xx:xx:xx auto connect: 1 15,16583,749041000,-;bluez: bluetoothd[2346]: src/device.c:device_set_auto_connect() Already connected 15,16584,749043000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564408: device D4:F5:13:xx:xx:xx profile Battery state changed: disconnected -> connected (0) 15,16585,749045000,-;bluez: bluetoothd[2346]: src/service.c:btd_service_ref() 0x564408: ref=2 15,16586,749047000,-;bluez: bluetoothd[2346]: plugins/policy.c:service_cb() Added Battery reconnect 0 15,16591,749062000,-;bluez: bluetoothd[2346]: profiles/battery/battery.c:batt_accept() BATT discovering characteristics 15,16593,749066000,-;bluez: bluetoothd[2346]: src/device.c:device_probe_profiles() Probing profiles for device D4:F5:13:xx:xx:xx 15,16595,749068000,-;bluez: bluetoothd[2346]: profiles/scanparam/scan.c:scan_param_probe() Scan Parameters Client Driver profile probe (D4:F5:13:xx:xx:xx) 15,16596,749068000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564808: device D4:F5:13:xx:xx:xx profile Scan Parameters Client Driver state changed: unavailable -> disconnected (0) 15,16598,749075000,-;bluez: bluetoothd[2346]: profiles/scanparam/scan.c:scan_param_accept() Scan Parameters Client Driver profile accept (D4:F5:13:xx:xx:xx) 15,16600,749077000,-;bluez: bluetoothd[2346]: profiles/scanparam/scan.c:handle_iwin() Scan Interval Window handle: 0x002b 15,16601,749079000,-;bluez: bluetoothd[2346]: profiles/scanparam/scan.c:handle_refresh() Scan Refresh handle: 0x002d 15,16602,749081000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564808: device D4:F5:13:xx:xx:xx profile Scan Parameters Client Driver state changed: disconnected -> connected (0) 15,16610,749141000,-;bluez: bluetoothd[2346]: src/device.c:device_probe_profiles() Probing profiles for device D4:F5:13:xx:xx:xx 15,16612,749148000,-;bluez: bluetoothd[2346]: profiles/input/hog.c:hog_probe() path /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx 15,16613,749149000,-;bluez: bluetoothd[2346]: profiles/input/hog.c:hog_device_new() name=xxxxxx vendor=0x471, product=0x2210, version=0x0 15,16614,749167000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564ba0: device D4:F5:13:xx:xx:xx profile input-hog state changed: unavailable -> disconnected (0) 15,16615,749167000,-;bluez: bluetoothd[2346]: src/device.c:device_set_auto_connect() D4:F5:13:xx:xx:xx auto connect: 1 15,16616,749171000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:bt_hog_attach() HoG discovering characteristics 15,16617,749173000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564ba0: device D4:F5:13:xx:xx:xx profile input-hog state changed: disconnected -> connected (0) 15,16618,749180000,-;bluez: bluetoothd[2346]: src/service.c:btd_service_ref() 0x564ba0: ref=2 15,16619,749181000,-;bluez: bluetoothd[2346]: plugins/policy.c:service_cb() Added input-hog reconnect 0 15,16620,749183000,-;bluez: bluetoothd[2346]: src/device.c:device_probe_profiles() Probing profiles for device D4:F5:13:xx:xx:xx 15,16621,749189000,-;bluez: bluetoothd[2346]: src/device.c:device_probe_profiles() Probing profiles for device D4:F5:13:xx:xx:xx 15,16622,749196000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_probe() OAD path /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx 15,16623,749198000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_probe() OAD matched OAD_UUID f000ffc0-0451-4000-b000-000000000000 15,16624,749198000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564f60: device D4:F5:13:xx:xx:xx profile OAD state changed: unavailable -> disconnected (0) 15,16625,749199000,-;bluez: bluetoothd[2346]: src/device.c:device_set_auto_connect() D4:F5:13:xx:xx:xx auto connect: 1 15,16626,749201000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564f60: device D4:F5:13:xx:xx:xx profile OAD state changed: disconnected -> connected (0) 15,16627,749202000,-;bluez: bluetoothd[2346]: src/service.c:btd_service_ref() 0x564f60: ref=2 15,16628,749206000,-;bluez: bluetoothd[2346]: plugins/policy.c:service_cb() Added OAD reconnect 0 15,16629,749208000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_accept() OAD discovering characteristics 15,16630,749210000,-;bluez: bluetoothd[2346]: src/gatt-client.c:btd_gatt_client_ready() GATT client ready 15,16631,749212000,-;bluez: bluetoothd[2346]: src/gatt-client.c:create_services() Exporting objects for GATT services: D4:F5:13:xx:xx:xx 15,16632,749212000,-;bluez: bluetoothd[2346]: src/gatt-client.c:service_create() Exported GATT service: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service000c 15,16633,749214000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service000c/char000d 15,16635,749221000,-;bluez: bluetoothd[2346]: src/gatt-client.c:descriptor_create() Exported GATT characteristic descriptor: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service000c/char000d/desc000f 15,16636,749225000,-;bluez: bluetoothd[2346]: src/gatt-client.c:service_create() Exported GATT service: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service0010 15,16637,749226000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service0010/char0011 15,16638,749227000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service0010/char0013 15,16639,749228000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service0010/char0015 15,16640,749229000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service0010/char0017 15,16641,749233000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service0010/char0019 15,16642,749237000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service0010/char001b 15,16643,749240000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service0010/char001d 15,16644,749247000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service0010/char001f 15,16645,749249000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service0010/char0021 15,16646,749250000,-;bluez: bluetoothd[2346]: src/gatt-client.c:service_create() Exported GATT service: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service005d 15,16647,749252000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service005d/char005e 15,16648,749257000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service005d/char0060 15,16649,749259000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service005d/char0062 15,16650,749262000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service005d/char0064 15,16651,749265000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service005d/char0066 15,16652,749268000,-;bluez: bluetoothd[2346]: src/gatt-client.c:descriptor_create() Exported GATT characteristic descriptor: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service005d/char0066/desc0068 15,16653,749273000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service005d/char0069 15,16654,749275000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service005d/char006b 15,16655,749277000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service005d/char006d 15,16656,749281000,-;bluez: bluetoothd[2346]: src/gatt-client.c:characteristic_create() Exported GATT characteristic: /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx/service005d/char006f 15,16657,749283000,-;bluez: bluetoothd[2346]: src/device.c:device_svc_resolved() /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx err 0 15,16669,749406000,-;bluez: bluetoothd[2346]: src/adapter.c:add_device_complete() D4:F5:13:xx:xx:xx (1) added to kernel connect list 15,16685,749474000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Registered handler for "Service Changed": 1 15,16697,749493000,-;bluez: bluetoothd[2346]: profiles/gap/gas.c:read_device_name_cb() GAP Device Name: xxxxxx 15,16698,749494000,-;bluez: bluetoothd[2346]: src/device.c:btd_device_device_set_name() /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx xxxxxx 15,16709,749512000,-;bluez: bluetoothd[2346]: profiles/gap/gas.c:read_appearance_cb() GAP Appearance: 0x03c0 15,16726,749565000,-;bluez: bluetoothd[2346]: src/device.c:btd_device_set_trusted() trusted 1 15,16750,749663000,-;bluez: bluetoothd[2346]: profiles/scanparam/scan.c:refresh_ccc_written_cb() Scan Refresh: notification enabled 15,16817,749945000,-;bluez: bluetoothd[2346]: profiles/battery/battery.c:char_discovered_cb() BATT inspecting characteristics 15,16818,749945000,-;bluez: bluetoothd[2346]: profiles/battery/battery.c:char_discovered_cb() BATT found BATT_LEVEL_UUID value_handle=0x0025 15,16872,750055000,-;bluez: bluetoothd[2346]: profiles/battery/battery.c:level_read_char_cb() BATT level=100 15,16932,750307000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_char_discovered_cb() OAD inspecting characteristics 15,16933,750307000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_char_discovered_cb() OAD found OAD_IMG_IDENTITY_UUID value_handle=0x0073 15,16934,750309000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_discover_desc() OAD discovering descriptors start=0x0074 end=0x0074 15,16935,750310000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_char_discovered_cb() OAD found OAD_IMG_BLOCK_UUID value_handle=0x0076 15,16936,750312000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_discover_desc() OAD discovering descriptors start=0x0077 end=0xffff 15,16972,750473000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_desc_discovered_cb() OAD found OAD_IMG_IDENTITY_UUID ccc_handle=0x0074 15,16999,750524000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:char_discovered_cb() HoG inspecting characteristics 15,17000,750524000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:char_discovered_cb() 0x003a UUID: 00002a4a-0000-1000-8000-00805f9b34fb properties: 02 15,17001,750527000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:char_discovered_cb() 0x003c UUID: 00002a4c-0000-1000-8000-00805f9b34fb properties: 04 15,17002,750527000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:char_discovered_cb() 0x003e UUID: 00002a4e-0000-1000-8000-00805f9b34fb properties: 06 15,17003,750527000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:char_discovered_cb() 0x0040 UUID: 00002a4b-0000-1000-8000-00805f9b34fb properties: 02 15,17009,750529000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:char_discovered_cb() HoG discovering report map 15,17010,750530000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:char_discovered_cb() 0x0043 UUID: 00002a4d-0000-1000-8000-00805f9b34fb properties: 12 15,17011,750531000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:char_discovered_cb() 0x0047 UUID: 00002a4d-0000-1000-8000-00805f9b34fb properties: 12 15,17012,750532000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:char_discovered_cb() 0x004b UUID: 00002a4d-0000-1000-8000-00805f9b34fb properties: 12 15,17013,750533000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:char_discovered_cb() 0x004f UUID: 00002a4d-0000-1000-8000-00805f9b34fb properties: 0e 15,17014,750534000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:char_discovered_cb() 0x0052 UUID: 00002a22-0000-1000-8000-00805f9b34fb properties: 12 15,17015,750535000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:char_discovered_cb() 0x0055 UUID: 00002a32-0000-1000-8000-00805f9b34fb properties: 0e 15,17016,750536000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:char_discovered_cb() 0x0057 UUID: 00002a33-0000-1000-8000-00805f9b34fb properties: 12 15,17017,750537000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:char_discovered_cb() 0x005a UUID: 00002a4d-0000-1000-8000-00805f9b34fb properties: 0a 15,17018,750542000,-;bluez: bluetoothd[2346]: attrib/gattrib.c:g_attrib_ref() 0x5159d8: g_attrib_ref=21 15,17030,750633000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_desc_discovered_cb() OAD found OAD_IMG_BLOCK_UUID ccc_handle=0x0077 15,17181,751092000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:proto_mode_read_cb() HoG is operating in Report Protocol Mode 15,17195,751113000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:info_read_cb() bcdHID: 0x0111 bCountryCode: 0x00 Flags: 0x01 15,17216,751164000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:external_report_reference_cb() External report reference read, external report characteristic UUID: 0x2a19 15,17226,751184000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_reference_cb() Report 0x0044: id 0x01 type input 15,17237,751204000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_reference_cb() Report 0x0048: id 0x02 type input 15,17251,751224000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_reference_cb() Report 0x004c: id 0x03 type input 15,17262,751244000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_reference_cb() Report 0x0050: id 0x00 type output 15,17270,751262000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_reference_cb() Report 0x005b: id 0x00 type feature 15,17338,751382000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_ccc_written_cb() Report characteristic descriptor written: notifications enabled 15,17349,751404000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_ccc_written_cb() Report characteristic descriptor written: notifications enabled 15,17360,751423000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_ccc_written_cb() Report characteristic descriptor written: notifications enabled 15,17386,751547000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() HoG inspecting report map 15,17387,751547000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() Report MAP: 15,17388,751547000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 05 01 15,17389,751547000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 09 06 15,17390,751548000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() a1 01 15,17391,751549000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 85 02 15,17392,751549000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 05 07 15,17393,751550000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 19 e0 15,17394,751551000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 29 e7 15,17395,751554000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 15 00 15,17396,751554000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 25 01 15,17397,751558000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 75 01 15,17398,751560000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 95 08 15,17399,751561000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 81 02 15,17400,751566000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 95 01 15,17401,751566000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 75 08 15,17402,751567000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 81 01 15,17403,751568000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 95 05 15,17404,751569000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 75 01 15,17405,751570000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 05 08 15,17406,751571000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 19 01 15,17408,751574000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 29 05 15,17409,751578000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 91 02 15,17410,751579000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 95 01 15,17411,751581000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 75 03 15,17412,751585000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 91 01 15,17413,751586000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 95 06 15,17414,751589000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 75 08 15,17415,751590000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 15 00 15,17416,751591000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 25 73 15,17417,751596000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 05 07 15,17418,751596000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 19 00 15,17419,751598000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 29 73 15,17420,751600000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 81 00 15,17421,751602000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() c0 15,17422,751603000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 05 0c 15,17423,751607000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 09 01 15,17424,751609000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() a1 01 15,17425,751613000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 85 03 15,17426,751613000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 05 0c 15,17427,751615000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() a1 02 15,17428,751615000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 19 00 15,17429,751617000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 2a 3c 02 15,17430,751617000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 15 00 15,17431,751620000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 26 3c 02 15,17432,751620000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 95 01 15,17433,751622000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 75 10 15,17434,751623000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 81 00 15,17435,751625000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() c0 15,17436,751626000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() c0 15,17437,751628000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 06 00 ff 15,17438,751629000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 09 07 15,17439,751631000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() a1 01 15,17440,751633000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 85 81 15,17441,751635000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 19 00 15,17442,751638000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 2a ff 00 15,17443,751647000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 15 00 15,17444,751647000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 26 ff 00 15,17445,751649000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 75 08 15,17446,751651000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 95 01 15,17447,751652000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() 81 02 15,17448,751652000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() c0 15,17451,751664000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_map_read_cb() HoG created uHID device 15,17465,752003000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_upgrade_timer() OAD timer fired 15,17466,752003000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_enable_notify() OAD enabling notify for OAD_IMG_IDENTITY_UUID 15,17467,752003000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_enable_notify() OAD enabling notify for OAD_IMG_BLOCK_UUID 15,17488,752062000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_check_fwversion() OAD sending fw version request 15,17509,752104000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_check_for_upgrade() OAD TI firmware is up to date 15,17510,752107000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_check_for_upgrade() OAD GP firmware is up to date 15,17511,752109000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_check_for_upgrade() OAD next check is in 28800 seconds 15,17548,755028000,-;bluez: bluetoothd[2346]: src/adapter.c:new_conn_param() hci0 D4:F5:13:xx:xx:xx (1) min 0x0008 max 0x0008 latency 0x0032 timeout 0x01f4 15,17565,755036000,-;bluez: bluetoothd[2346]: src/adapter.c:store_conn_param() 15,17581,755058000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_value_cb() HoG report (3 bytes) 15,17594,755145000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_value_cb() HoG report (3 bytes) 15,17610,755375000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_value_cb() HoG report (3 bytes) 15,17619,755483000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_value_cb() HoG report (3 bytes) Then, the remote disconnects to save battery: 15,18130,815801000,-;bluez: bluetoothd[2346]: src/adapter.c:dev_disconnected() Device D4:F5:13:xx:xx:xx disconnected, reason 3 15,18131,815801000,-;bluez: bluetoothd[2346]: src/adapter.c:dev_disconnected() device 0x518440 paired 1 bonded 1 bonding 0 15,18132,815802000,-;bluez: bluetoothd[2346]: src/adapter.c:adapter_remove_connection() 15,18133,815802000,-;bluez: bluetoothd[2346]: plugins/policy.c:disconnect_cb() reason 3 15,18134,815804000,-;bluez: bluetoothd[2346]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr D4:F5:13:xx:xx:xx type 1 status 0xe 15,18135,815804000,-;bluez: bluetoothd[2346]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e 15,18136,815804000,-;bluez: bluetoothd[2346]: src/device.c:device_bonding_failed() status 14 15,18137,815805000,-;bluez: bluetoothd[2346]: src/adapter.c:resume_discovery() 15,18138,815807000,-;bluez: bluetoothd[2346]: src/device.c:att_disconnected_cb() 15,18139,815808000,-;bluez: bluetoothd[2346]: src/device.c:att_disconnected_cb() Connection reset by peer (131) 15,18140,815808000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x563210: device D4:F5:13:xx:xx:xx profile gap-profile state changed: connected -> disconnecting (0) 15,18141,815810000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x563210: device D4:F5:13:xx:xx:xx profile gap-profile state changed: disconnecting -> disconnected (0) 15,18142,815810000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564370: device D4:F5:13:xx:xx:xx profile deviceinfo state changed: connected -> disconnecting (0) 15,18149,815810000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564370: device D4:F5:13:xx:xx:xx profile deviceinfo state changed: disconnecting -> disconnected (0) 15,18150,815811000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564408: device D4:F5:13:xx:xx:xx profile Battery state changed: connected -> disconnecting (0) 15,18151,815811000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564408: device D4:F5:13:xx:xx:xx profile Battery state changed: disconnecting -> disconnected (0) 15,18152,815813000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564808: device D4:F5:13:xx:xx:xx profile Scan Parameters Client Driver state changed: connected -> disconnecting (0) 15,18153,815814000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564808: device D4:F5:13:xx:xx:xx profile Scan Parameters Client Driver state changed: disconnecting -> disconnected (0) 15,18156,815816000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564ba0: device D4:F5:13:xx:xx:xx profile input-hog state changed: connected -> disconnecting (0) 15,18157,815817000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564ba0: device D4:F5:13:xx:xx:xx profile input-hog state changed: disconnecting -> disconnected (0) 15,18158,815818000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564f60: device D4:F5:13:xx:xx:xx profile OAD state changed: connected -> disconnecting (0) 15,18159,815819000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564f60: device D4:F5:13:xx:xx:xx profile OAD state changed: disconnecting -> disconnected (0) 15,18169,815827000,-;bluez: bluetoothd[2346]: src/gatt-client.c:btd_gatt_client_disconnected() Device disconnected. Cleaning up. 15,18170,815828000,-;bluez: bluetoothd[2346]: attrib/gattrib.c:g_attrib_unref() 0x5159d8: g_attrib_unref=0 And here is the first reconnect: 15,18345,832482000,-;bluez: bluetoothd[2346]: src/adapter.c:connected_callback() hci0 device D4:F5:13:xx:xx:xx connected eir_len 0 15,18352,832483000,-;bluez: bluetoothd[2346]: src/adapter.c:connected_callback() device 0x518440 paired 1 bonded 1 bonding 0 15,18369,832511000,-;bluez: bluetoothd[2346]: src/gatt-database.c:connect_cb() New incoming LE ATT connection 15,18370,832511000,-;bluez: bluetoothd[2346]: src/device.c:device_attach_att() Elevating security level since LTK is available 15,18384,832524000,-;bluez: bluetoothd[2346]: attrib/gattrib.c:g_attrib_ref() 0x5159d8: g_attrib_ref=1 15,18385,832525000,-;bluez: bluetoothd[2346]: profiles/gap/gas.c:gap_accept() GAP profile accept (D4:F5:13:xx:xx:xx) 15,18386,832526000,-;bluez: bluetoothd[2346]: profiles/gap/gas.c:handle_characteristic() Unsupported characteristic: 00002a02-0000-1000-8000-00805f9b34fb 15,18387,832527000,-;bluez: bluetoothd[2346]: profiles/gap/gas.c:handle_characteristic() Unsupported characteristic: 00002a03-0000-1000-8000-00805f9b34fb 15,18388,832527000,-;bluez: bluetoothd[2346]: profiles/gap/gas.c:handle_characteristic() Unsupported characteristic: 00002a04-0000-1000-8000-00805f9b34fb 15,18389,832528000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x563210: device D4:F5:13:xx:xx:xx profile gap-profile state changed: disconnected -> connected (0) 15,18391,832543000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:deviceinfo_accept() deviceinfo profile accept (D4:F5:13:xx:xx:xx) 15,18392,832544000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a23-0000-1000-8000-00805f9b34fb 15,18393,832545000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a24-0000-1000-8000-00805f9b34fb 15,18394,832546000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a25-0000-1000-8000-00805f9b34fb 15,18395,832546000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a26-0000-1000-8000-00805f9b34fb 15,18396,832547000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a27-0000-1000-8000-00805f9b34fb 15,18397,832549000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a28-0000-1000-8000-00805f9b34fb 15,18398,832549000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a29-0000-1000-8000-00805f9b34fb 15,18399,832552000,-;bluez: bluetoothd[2346]: profiles/deviceinfo/deviceinfo.c:handle_characteristic() Unsupported characteristic: 00002a2a-0000-1000-8000-00805f9b34fb 15,18400,832557000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564370: device D4:F5:13:xx:xx:xx profile deviceinfo state changed: disconnected -> connected (0) 15,18401,832558000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564408: device D4:F5:13:xx:xx:xx profile Battery state changed: disconnected -> connected (0) 15,18402,832559000,-;bluez: bluetoothd[2346]: plugins/policy.c:service_cb() Added Battery reconnect 0 15,18403,832563000,-;bluez: bluetoothd[2346]: profiles/scanparam/scan.c:scan_param_accept() Scan Parameters Client Driver profile accept (D4:F5:13:xx:xx:xx) 15,18404,832563000,-;bluez: bluetoothd[2346]: profiles/scanparam/scan.c:handle_iwin() Scan Interval Window handle: 0x002b 15,18405,832565000,-;bluez: bluetoothd[2346]: profiles/scanparam/scan.c:handle_refresh() Scan Refresh handle: 0x002d 15,18406,832567000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564808: device D4:F5:13:xx:xx:xx profile Scan Parameters Client Driver state changed: disconnected -> connected (0) 15,18413,832579000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564ba0: device D4:F5:13:xx:xx:xx profile input-hog state changed: disconnected -> connected (0) 15,18414,832579000,-;bluez: bluetoothd[2346]: plugins/policy.c:service_cb() Added input-hog reconnect 0 15,18415,832579000,-;bluez: bluetoothd[2346]: src/service.c:change_state() 0x564f60: device D4:F5:13:xx:xx:xx profile OAD state changed: disconnected -> connected (0) 15,18416,832579000,-;bluez: bluetoothd[2346]: plugins/policy.c:service_cb() Added OAD reconnect 0 15,18417,832579000,-;bluez: bluetoothd[2346]: profiles/oad/oad.c:oad_is_time_for_upgrade_check() OAD not time for upgrade check yet (28720 seconds left) 15,18418,832579000,-;bluez: bluetoothd[2346]: src/gatt-client.c:btd_gatt_client_connected() Device connected. 15,18441,832622000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() MTU exchange complete, with MTU: 23 15,18447,832642000,-;bluez: bluetoothd[2346]: profiles/gap/gas.c:read_device_name_cb() GAP Device Name: xxxxxxxx 15,18463,832664000,-;bluez: bluetoothd[2346]: profiles/gap/gas.c:read_appearance_cb() GAP Appearance: 0x03c0 15,18481,832702000,-;bluez: bluetoothd[2346]: profiles/battery/battery.c:level_read_char_cb() BATT level=100 ==== 15,18491,832722000,-;bluez: bluetoothd[2346]: profiles/scanparam/scan.c:refresh_ccc_written_cb() Scan Refresh: notification enabled 15,18649,834042000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Primary services found: 9 15,18650,834043000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0001, end: 0x000b, uuid: 00001800-0000-1000-8000-00805f9b34fb 15,18651,834043000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x000c, end: 0x000f, uuid: 00001801-0000-1000-8000-00805f9b34fb 15,18652,834043000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0010, end: 0x0022, uuid: 0000180a-0000-1000-8000-00805f9b34fb 15,18653,834045000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0023, end: 0x0028, uuid: 0000180f-0000-1000-8000-00805f9b34fb 15,18654,834046000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0029, end: 0x002e, uuid: 00001813-0000-1000-8000-00805f9b34fb 15,18655,834046000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x002f, end: 0x0037, uuid: 0000fff0-0000-1000-8000-00805f9b34fb 15,18656,834047000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0038, end: 0x005c, uuid: 00001812-0000-1000-8000-00805f9b34fb 15,18657,834049000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x005d, end: 0x0070, uuid: f000fef0-0451-4000-b000-000000000000 15,18658,834050000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0071, end: 0xffff, uuid: f000ffc0-0451-4000-b000-000000000000 15,18659,834053000,-;bluez: bluetoothd[2346]: src/device.c:gatt_client_ready_cb() status: success, error: 0 15,18660,834064000,-;bluez: bluetoothd[2346]: src/gatt-client.c:btd_gatt_client_ready() GATT client ready 15,18661,834066000,-;bluez: bluetoothd[2346]: src/gatt-client.c:create_services() Exporting objects for GATT services: D4:F5:13:xx:xx:xx 15,18662,834066000,-;bluez: bluetoothd[2346]: src/device.c:device_svc_resolved() /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx err 0 15,18673,834571000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Registered handler for "Service Changed": 2 15,18702,837932000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_value_cb() HoG report (3 bytes) 15,18721,838033000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_value_cb() HoG report (3 bytes) 15,18737,838262000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_value_cb() HoG report (3 bytes) 15,18753,838353000,-;bluez: bluetoothd[2346]: profiles/input/hog-lib.c:report_value_cb() HoG report (3 bytes) Looking into btmon details after the line marked ====: 15,18491,832722000,-;bluez: bluetoothd[2346]: profiles/scanparam/scan.c:refresh_ccc_written_cb() Scan Refresh: notification enabled We can see that BlueZ issues a bunch of ATT: Read By Group Type Requests to re-discover all primary services (0x2800): 15,18491,832722000,-;bluez: bluetoothd[2346]: profiles/scanparam/scan.c:refresh_ccc_written_cb() Scan Refresh: notification enabled 15,18492,832723000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen 11 [hci0] 17:26:51.730522 15,18493,832725000,-;btmon: ATT: Read By Type Request (0x08) len 6 15,18494,832725000,-;btmon: Handle range: 0x002f-0x0037 15,18495,832725000,-;btmon: Attribute type: Characteristic (0x2803) 15,18496,832725000,-;btmon: > HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 17:26:51.731128 15,18497,832726000,-;btmon: Num handles: 1 15,18498,832726000,-;btmon: Handle: 128 15,18499,832726000,-;btmon: Count: 1 15,18500,832733000,-;btmon: > HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 17:26:51.739362 15,18501,832733000,-;btmon: Num handles: 1 15,18502,832733000,-;btmon: Handle: 128 15,18503,832733000,-;btmon: Count: 1 15,18504,832752000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen 27 [hci0] 17:26:51.759357 15,18505,832753000,-;btmon: ATT: Read By Type Response (0x09) len 22 15,18506,832753000,-;btmon: Attribute data length: 7 15,18507,832753000,-;btmon: Attribute data list: 3 entries 15,18508,832753000,-;btmon: Handle: 0x0030 15,18509,832753000,-;btmon: Value: 1e3100f1ff 15,18510,832753000,-;btmon: Handle: 0x0033 15,18511,832753000,-;btmon: Value: 0a3400f2ff 15,18512,832753000,-;btmon: Handle: 0x0035 15,18513,832753000,-;btmon: Value: 123600f4ff 15,18514,832754000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen 11 [hci0] 17:26:51.760043 15,18515,832754000,-;btmon: ATT: Read By Group Type Request (0x10) len 6 15,18516,832754000,-;btmon: Handle range: 0x0001-0xffff 15,18517,832754000,-;btmon: Attribute group type: Primary Service (0x2800) 15,18518,832762000,-;btmon: > HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 17:26:51.769346 15,18519,832762000,-;btmon: Num handles: 1 15,18520,832762000,-;btmon: Handle: 128 15,18521,832762000,-;btmon: Count: 1 15,18522,832782000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen 24 [hci0] 17:26:51.789303 15,18523,832782000,-;btmon: ATT: Read By Group Type Response (0x11) len 19 15,18524,832782000,-;btmon: Attribute data length: 6 15,18525,832782000,-;btmon: Attribute group list: 3 entries 15,18526,832784000,-;btmon: Handle range: 0x0001-0x000b 15,18527,832784000,-;btmon: UUID: Generic Access Profile (0x1800) 15,18528,832784000,-;btmon: Handle range: 0x000c-0x000f 15,18529,832784000,-;btmon: UUID: Generic Attribute Profile (0x1801) 15,18530,832784000,-;btmon: Handle range: 0x0010-0x0022 15,18531,832784000,-;btmon: UUID: Device Information (0x180a) 15,18532,832784000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen 11 [hci0] 17:26:51.790028 15,18533,832784000,-;btmon: ATT: Read By Type Request (0x08) len 6 15,18534,832784000,-;btmon: Handle range: 0x0036-0x0037 15,18535,832784000,-;btmon: Attribute type: Characteristic (0x2803) 15,18536,832792000,-;btmon: > HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 17:26:51.799354 15,18537,832792000,-;btmon: Num handles: 1 15,18538,832792000,-;btmon: Handle: 128 15,18539,832792000,-;btmon: Count: 1 15,18540,832809000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen 9 [hci0] 17:26:51.808179 15,18541,832809000,-;btmon: ATT: Error Response (0x01) len 4 15,18542,832809000,-;btmon: Read By Type Request (0x08) 15,18543,832809000,-;btmon: Handle: 0x0036 15,18544,832809000,-;btmon: Error: Attribute Not Found (0x0a) 15,18546,832811000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen 11 [hci0] 17:26:51.810774 15,18547,832812000,-;btmon: ATT: Read By Group Type Request (0x10) len 6 15,18548,832812000,-;btmon: Handle range: 0x0023-0xffff 15,18549,832812000,-;btmon: Attribute group type: Primary Service (0x2800) 15,18553,833321000,-;btmon: > HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 17:26:52.328191 15,18554,833321000,-;btmon: Num handles: 1 15,18555,833321000,-;btmon: Handle: 128 15,18556,833321000,-;btmon: Count: 1 15,18558,833334000,-;btmon: > HCI Event: Vendor (0xff) plen 5 [hci0] 17:26:52.339515 15,18559,833334000,-;btmon: 05 80 00 09 00 ..... 15,18560,833362000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen 24 [hci0] 17:26:52.369478 15,18561,833363000,-;btmon: ATT: Read By Group Type Response (0x11) len 19 15,18562,833363000,-;btmon: Attribute data length: 6 15,18563,833363000,-;btmon: Attribute group list: 3 entries 15,18564,833364000,-;btmon: Handle range: 0x0023-0x0028 15,18565,833364000,-;btmon: UUID: Battery Service (0x180f) 15,18566,833364000,-;btmon: Handle range: 0x0029-0x002e 15,18567,833364000,-;btmon: UUID: Scan Parameters (0x1813) 15,18568,833364000,-;btmon: Handle range: 0x002f-0x0037 15,18569,833364000,-;btmon: UUID: Unknown (0xfff0) 15,18570,833364000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen 9 [hci0] 17:26:52.370138 15,18571,833364000,-;btmon: ATT: Find Information Request (0x04) len 4 15,18572,833364000,-;btmon: Handle range: 0x0036-0x0037 15,18574,833371000,-;btmon: > HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 17:26:52.378203 15,18575,833371000,-;btmon: Num handles: 1 15,18576,833371000,-;btmon: Handle: 128 15,18577,833371000,-;btmon: Count: 1 15,18578,833391000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen 14 [hci0] 17:26:52.398166 15,18579,833391000,-;btmon: ATT: Find Information Response (0x05) len 9 15,18580,833392000,-;btmon: Format: UUID-16 (0x01) 15,18582,833394000,-;btmon: Handle: 0x0036 15,18583,833394000,-;btmon: UUID: Unknown (0xfff4) 15,18584,833394000,-;btmon: Handle: 0x0037 15,18585,833394000,-;btmon: UUID: Client Characteristic Configuration (0x2902) 15,18586,833394000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen 10 [hci0] 17:26:52.400735 15,18587,833394000,-;btmon: ATT: Write Request (0x12) len 5 15,18588,833394000,-;btmon: Handle: 0x0034 15,18589,833394000,-;btmon: Data: 030000 15,18591,833912000,-;btmon: > HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 17:26:52.919397 15,18592,833912000,-;btmon: Num handles: 1 15,18593,833912000,-;btmon: Handle: 128 15,18594,833912000,-;btmon: Count: 1 15,18595,833931000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen 5 [hci0] 17:26:52.938157 15,18596,833931000,-;btmon: ATT: Write Response (0x13) len 0 15,18597,833932000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen 11 [hci0] 17:26:52.939032 15,18598,833932000,-;btmon: ATT: Read By Group Type Request (0x10) len 6 15,18599,833932000,-;btmon: Handle range: 0x0038-0xffff 15,18600,833932000,-;btmon: Attribute group type: Primary Service (0x2800) 15,18601,833944000,-;btmon: > HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 17:26:52.951628 15,18602,833944000,-;btmon: Num handles: 1 15,18603,833944000,-;btmon: Handle: 128 15,18604,833944000,-;btmon: Count: 1 15,18605,833959000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen 12 [hci0] 17:26:52.966479 15,18606,833959000,-;btmon: ATT: Read By Group Type Response (0x11) len 7 15,18607,833960000,-;btmon: Attribute data length: 6 15,18608,833960000,-;btmon: Attribute group list: 1 entry 15,18609,833960000,-;btmon: Handle range: 0x0038-0x005c 15,18610,833960000,-;btmon: UUID: Human Interface Device (0x1812) 15,18611,833960000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen 9 [hci0] 17:26:52.967113 15,18612,833960000,-;btmon: ATT: Write Request (0x12) len 4 15,18613,833960000,-;btmon: Handle: 0x0037 15,18614,833960000,-;btmon: Data: 0100 15,18615,833971000,-;btmon: > HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 17:26:52.976999 15,18616,833971000,-;btmon: Num handles: 1 15,18617,833972000,-;btmon: Handle: 128 15,18618,833972000,-;btmon: Count: 1 15,18619,833979000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen 5 [hci0] 17:26:52.986355 15,18620,833980000,-;btmon: ATT: Write Response (0x13) len 0 15,18621,833980000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen 11 [hci0] 17:26:52.986894 15,18622,833980000,-;btmon: ATT: Read By Group Type Request (0x10) len 6 15,18623,833980000,-;btmon: Handle range: 0x005d-0xffff 15,18624,833980000,-;btmon: Attribute group type: Primary Service (0x2800) 15,18625,833990000,-;btmon: > HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 17:26:52.996610 15,18626,833990000,-;btmon: Num handles: 1 15,18627,833991000,-;btmon: Handle: 128 15,18628,833991000,-;btmon: Count: 1 15,18629,834013000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen 26 [hci0] 17:26:53.019401 15,18630,834013000,-;btmon: ATT: Read By Group Type Response (0x11) len 21 15,18631,834013000,-;btmon: Attribute data length: 20 15,18632,834013000,-;btmon: Attribute group list: 1 entry 15,18633,834013000,-;btmon: Handle range: 0x005d-0x0070 15,18634,834013000,-;btmon: UUID: Vendor specific (f000fef0-0451-4000-b000-000000000000) 15,18635,834013000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen 11 [hci0] 17:26:53.020026 15,18636,834013000,-;btmon: ATT: Read By Group Type Request (0x10) len 6 15,18637,834013000,-;btmon: Handle range: 0x0071-0xffff 15,18638,834013000,-;btmon: Attribute group type: Primary Service (0x2800) 15,18639,834022000,-;btmon: > HCI Event: Number of Completed Packets (0x13) plen 5 [hci0] 17:26:53.029922 15,18640,834022000,-;btmon: Num handles: 1 15,18641,834022000,-;btmon: Handle: 128 15,18642,834023000,-;btmon: Count: 1 15,18643,834042000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen 26 [hci0] 17:26:53.049348 15,18644,834042000,-;btmon: ATT: Read By Group Type Response (0x11) len 21 15,18645,834042000,-;btmon: Attribute data length: 20 15,18646,834042000,-;btmon: Attribute group list: 1 entry 15,18647,834042000,-;btmon: Handle range: 0x0071-0xffff 15,18648,834042000,-;btmon: UUID: Vendor specific (f000ffc0-0451-4000-b000-000000000000) 15,18649,834042000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() Primary services found: 9 15,18650,834043000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0001, end: 0x000b, uuid: 00001800-0000-1000-8000-00805f9b34fb 15,18651,834043000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x000c, end: 0x000f, uuid: 00001801-0000-1000-8000-00805f9b34fb 15,18652,834043000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0010, end: 0x0022, uuid: 0000180a-0000-1000-8000-00805f9b34fb 15,18653,834045000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0023, end: 0x0028, uuid: 0000180f-0000-1000-8000-00805f9b34fb 15,18654,834046000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0029, end: 0x002e, uuid: 00001813-0000-1000-8000-00805f9b34fb 15,18655,834046000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x002f, end: 0x0037, uuid: 0000fff0-0000-1000-8000-00805f9b34fb 15,18656,834047000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0038, end: 0x005c, uuid: 00001812-0000-1000-8000-00805f9b34fb 15,18657,834049000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x005d, end: 0x0070, uuid: f000fef0-0451-4000-b000-000000000000 15,18658,834050000,-;bluez: bluetoothd[2346]: src/device.c:gatt_debug() start: 0x0071, end: 0xffff, uuid: f000ffc0-0451-4000-b000-000000000000 15,18659,834053000,-;bluez: bluetoothd[2346]: src/device.c:gatt_client_ready_cb() status: success, error: 0 15,18660,834064000,-;bluez: bluetoothd[2346]: src/gatt-client.c:btd_gatt_client_ready() GATT client ready 15,18661,834066000,-;bluez: bluetoothd[2346]: src/gatt-client.c:create_services() Exporting objects for GATT services: D4:F5:13:xx:xx:xx 15,18662,834066000,-;bluez: bluetoothd[2346]: src/device.c:device_svc_resolved() /org/bluez/hci0/dev_D4_F5_13_xx_xx_xx err 0 The file "D4:F5:13:xx:xx:xx/attributes" exists and contains: [1] UUID=00002800-0000-1000-8000-00805f9b34fb Value=1800 EndGroupHandle=11 [12] UUID=00002800-0000-1000-8000-00805f9b34fb Value=1801 EndGroupHandle=15 [16] UUID=00002800-0000-1000-8000-00805f9b34fb Value=180A EndGroupHandle=34 [35] UUID=00002800-0000-1000-8000-00805f9b34fb Value=180F EndGroupHandle=40 [41] UUID=00002800-0000-1000-8000-00805f9b34fb Value=1813 EndGroupHandle=46 [47] UUID=00002800-0000-1000-8000-00805f9b34fb Value=FFF0 EndGroupHandle=55 [56] UUID=00002800-0000-1000-8000-00805f9b34fb Value=1812 EndGroupHandle=92 [93] UUID=00002800-0000-1000-8000-00805f9b34fb Value=F000FEF004514000B000000000000000 EndGroupHandle=112 [113] UUID=00002800-0000-1000-8000-00805f9b34fb Value=F000FFC004514000B000000000000000 EndGroupHandle=65535 And, the file "cache/D4:F5:13:xx:xx:xx" exists and contains: [Attributes] 0001=2800:000b:00001800-0000-1000-8000-00805f9b34fb 0002=2803:0003:02:00002a00-0000-1000-8000-00805f9b34fb 0004=2803:0005:02:00002a01-0000-1000-8000-00805f9b34fb 0006=2803:0007:0a:00002a02-0000-1000-8000-00805f9b34fb 0008=2803:0009:08:00002a03-0000-1000-8000-00805f9b34fb 000a=2803:000b:02:00002a04-0000-1000-8000-00805f9b34fb 000c=2800:000f:00001801-0000-1000-8000-00805f9b34fb 000d=2803:000e:20:00002a05-0000-1000-8000-00805f9b34fb 000f=00002902-0000-1000-8000-00805f9b34fb 0010=2800:0022:0000180a-0000-1000-8000-00805f9b34fb 0011=2803:0012:02:00002a23-0000-1000-8000-00805f9b34fb 0013=2803:0014:02:00002a24-0000-1000-8000-00805f9b34fb 0015=2803:0016:02:00002a25-0000-1000-8000-00805f9b34fb 0017=2803:0018:02:00002a26-0000-1000-8000-00805f9b34fb 0019=2803:001a:02:00002a27-0000-1000-8000-00805f9b34fb 001b=2803:001c:02:00002a28-0000-1000-8000-00805f9b34fb 001d=2803:001e:02:00002a29-0000-1000-8000-00805f9b34fb 001f=2803:0020:02:00002a2a-0000-1000-8000-00805f9b34fb 0021=2803:0022:02:00002a50-0000-1000-8000-00805f9b34fb 0023=2800:0028:0000180f-0000-1000-8000-00805f9b34fb 0024=2803:0025:12:00002a19-0000-1000-8000-00805f9b34fb 0026=00002902-0000-1000-8000-00805f9b34fb 0027=00002908-0000-1000-8000-00805f9b34fb 0028=00002904-0000-1000-8000-00805f9b34fb 0029=2800:002e:00001813-0000-1000-8000-00805f9b34fb 002a=2803:002b:04:00002a4f-0000-1000-8000-00805f9b34fb 002c=2803:002d:10:00002a31-0000-1000-8000-00805f9b34fb 002e=00002902-0000-1000-8000-00805f9b34fb 002f=2800:0037:0000fff0-0000-1000-8000-00805f9b34fb 0030=2803:0031:1e:0000fff1-0000-1000-8000-00805f9b34fb 0032=00002902-0000-1000-8000-00805f9b34fb 0033=2803:0034:0a:0000fff2-0000-1000-8000-00805f9b34fb 0035=2803:0036:12:0000fff4-0000-1000-8000-00805f9b34fb 0037=00002902-0000-1000-8000-00805f9b34fb 0038=2800:005c:00001812-0000-1000-8000-00805f9b34fb 0039=2802:0023:0028:0000180f-0000-1000-8000-00805f9b34fb 003a=2803:003b:02:00002a4a-0000-1000-8000-00805f9b34fb 003c=2803:003d:04:00002a4c-0000-1000-8000-00805f9b34fb 003e=2803:003f:06:00002a4e-0000-1000-8000-00805f9b34fb 0040=2803:0041:02:00002a4b-0000-1000-8000-00805f9b34fb 0042=00002907-0000-1000-8000-00805f9b34fb 0043=2803:0044:12:00002a4d-0000-1000-8000-00805f9b34fb 0045=00002902-0000-1000-8000-00805f9b34fb 0046=00002908-0000-1000-8000-00805f9b34fb 0047=2803:0048:12:00002a4d-0000-1000-8000-00805f9b34fb 0049=00002902-0000-1000-8000-00805f9b34fb 004a=00002908-0000-1000-8000-00805f9b34fb 004b=2803:004c:12:00002a4d-0000-1000-8000-00805f9b34fb 004d=00002902-0000-1000-8000-00805f9b34fb 004e=00002908-0000-1000-8000-00805f9b34fb 004f=2803:0050:0e:00002a4d-0000-1000-8000-00805f9b34fb 0051=00002908-0000-1000-8000-00805f9b34fb 0052=2803:0053:12:00002a22-0000-1000-8000-00805f9b34fb 0054=00002902-0000-1000-8000-00805f9b34fb 0055=2803:0056:0e:00002a32-0000-1000-8000-00805f9b34fb 0057=2803:0058:12:00002a33-0000-1000-8000-00805f9b34fb 0059=00002902-0000-1000-8000-00805f9b34fb 005a=2803:005b:0a:00002a4d-0000-1000-8000-00805f9b34fb 005c=00002908-0000-1000-8000-00805f9b34fb 005d=2800:0070:f000fef0-0451-4000-b000-000000000000 005e=2803:005f:0a:f000fef1-0451-4000-b000-000000000000 0060=2803:0061:0a:f000fef2-0451-4000-b000-000000000000 0062=2803:0063:0a:f000fef3-0451-4000-b000-000000000000 0064=2803:0065:0a:f000fef4-0451-4000-b000-000000000000 0066=2803:0067:08:f000fef5-0451-4000-b000-000000000000 0068=00002902-0000-1000-8000-00805f9b34fb 0069=2803:006a:0a:f000fef6-0451-4000-b000-000000000000 006b=2803:006c:0a:f000fef7-0451-4000-b000-000000000000 006d=2803:006e:0a:f000fef8-0451-4000-b000-000000000000 006f=2803:0070:08:f000fef9-0451-4000-b000-000000000000 0071=2800:ffff:f000ffc0-0451-4000-b000-000000000000 0072=2803:0073:1c:f000ffc1-0451-4000-b000-000000000000 0074=00002902-0000-1000-8000-00805f9b34fb 0075=2803:0076:1c:f000ffc2-0451-4000-b000-000000000000 0077=00002902-0000-1000-8000-00805f9b34fb ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect 2016-11-11 2:42 ` Petri Gynther @ 2016-11-11 9:07 ` Luiz Augusto von Dentz [not found] ` <CAGXr9JET_-mB1qtOryXpUMhQPTe_ecw84f4kFH+Wv9_WYp3iog@mail.gmail.com> 0 siblings, 1 reply; 16+ messages in thread From: Luiz Augusto von Dentz @ 2016-11-11 9:07 UTC (permalink / raw) To: Petri Gynther; +Cc: linux-bluetooth Hi Petri, On Fri, Nov 11, 2016 at 4:42 AM, Petri Gynther <pgynther@google.com> wrote: > Hi Luiz, > > On Thu, Nov 10, 2016 at 6:17 AM, Luiz Augusto von Dentz > <luiz.dentz@gmail.com> wrote: >> Hi Petri, >> >> On Wed, Nov 9, 2016 at 9:39 PM, Petri Gynther <pgynther@google.com> wrote: >>> Hi linux-bluetooth: >>> >>> I'm seeing the following issue with BlueZ 5.43 and Linux 4.4.30. >>> >>> When a previously bonded HoG remote control reconnects to BlueZ 5.43 >>> host, BlueZ goes ahead and re-discovers the primary services of the >>> bonded remote again and again on every reconnect. >>> >>> Why is this necessary? Shouldn't this information be cached on the >>> initial pairing/bonding, and a reconnect can get this information from >>> the relevant persistent file, rather than wasting BLE airtime and >>> delaying the reconnect? >>> >> >> IF, and only if, the cache is restored properly then yes it will work >> as you said, but bt_hog is not yet using the gatt_db so it might >> rediscover the handles anyway, this happens only once though. >> >>> >>> >>> In the above log, I see that MTU exchange takes place: >>> 15,148467,14484676000,-;bluez: bluetoothd[1985]: >>> src/device.c:gatt_debug() MTU exchange complete, with MTU: 23 >>> >>> Looking at the relevant code in src/shared/gatt-client.c, function >>> exchange_mtu_cb(): >>> >>> util_debug(client->debug_callback, client->debug_data, >>> "MTU exchange complete, with MTU: %u", >>> bt_att_get_mtu(client->att)); >>> >>> discover: >>> client->discovery_req = bt_gatt_discover_all_primary_services( >>> client->att, NULL, >>> discover_primary_cb, >>> discovery_op_ref(op), >>> discovery_op_unref); >>> >>> >>> The call to bt_gatt_discover_all_primary_services() is unconditional, >>> whether the device was previously bonded or not. >> >> This does range validation in case service changed is not properly >> implemented this will attempt to figure out if there are any changes >> in the database, but note that it will stop in here: >> >> attr = gatt_db_insert_service(client->db, start, &uuid, true, >> end - start + 1); >> if (!attr) { >> >> So if the database already contain all the services it will no do more >> than one Read By Group Type. Looking into btmon details after the line marked ====: > 15,18491,832722000,-;bluez: bluetoothd[2346]: > profiles/scanparam/scan.c:refresh_ccc_written_cb() Scan Refresh: > notification enabled > > We can see that BlueZ issues a bunch of ATT: Read By Group Type > Requests to re-discover all primary services (0x2800): This is what I said, we will issue Read By Group Type to validate the cached data since service changed is not mandatory and way too many devices don't implement it correctly. > 15,18491,832722000,-;bluez: bluetoothd[2346]: > profiles/scanparam/scan.c:refresh_ccc_written_cb() Scan Refresh: > notification enabled > 15,18492,832723000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen > 11 [hci0] 17:26:51.730522 > 15,18493,832725000,-;btmon: ATT: Read By Type Request (0x08) len 6 > 15,18494,832725000,-;btmon: Handle range: 0x002f-0x0037 > 15,18495,832725000,-;btmon: Attribute type: Characteristic (0x2803) > 15,18496,832725000,-;btmon: > HCI Event: Number of Completed Packets > (0x13) plen 5 [hci0] 17:26:51.731128 > 15,18497,832726000,-;btmon: Num handles: 1 > 15,18498,832726000,-;btmon: Handle: 128 > 15,18499,832726000,-;btmon: Count: 1 > 15,18500,832733000,-;btmon: > HCI Event: Number of Completed Packets > (0x13) plen 5 [hci0] 17:26:51.739362 > 15,18501,832733000,-;btmon: Num handles: 1 > 15,18502,832733000,-;btmon: Handle: 128 > 15,18503,832733000,-;btmon: Count: 1 > 15,18504,832752000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen > 27 [hci0] 17:26:51.759357 > 15,18505,832753000,-;btmon: ATT: Read By Type Response (0x09) len 22 > 15,18506,832753000,-;btmon: Attribute data length: 7 > 15,18507,832753000,-;btmon: Attribute data list: 3 entries > 15,18508,832753000,-;btmon: Handle: 0x0030 > 15,18509,832753000,-;btmon: Value: 1e3100f1ff > 15,18510,832753000,-;btmon: Handle: 0x0033 > 15,18511,832753000,-;btmon: Value: 0a3400f2ff > 15,18512,832753000,-;btmon: Handle: 0x0035 > 15,18513,832753000,-;btmon: Value: 123600f4ff > 15,18514,832754000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen > 11 [hci0] 17:26:51.760043 > 15,18515,832754000,-;btmon: ATT: Read By Group Type Request (0x10) len 6 > 15,18516,832754000,-;btmon: Handle range: 0x0001-0xffff > 15,18517,832754000,-;btmon: Attribute group type: Primary > Service (0x2800) > 15,18518,832762000,-;btmon: > HCI Event: Number of Completed Packets > (0x13) plen 5 [hci0] 17:26:51.769346 > 15,18519,832762000,-;btmon: Num handles: 1 > 15,18520,832762000,-;btmon: Handle: 128 > 15,18521,832762000,-;btmon: Count: 1 > 15,18522,832782000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen > 24 [hci0] 17:26:51.789303 > 15,18523,832782000,-;btmon: ATT: Read By Group Type Response (0x11) len 19 > 15,18524,832782000,-;btmon: Attribute data length: 6 > 15,18525,832782000,-;btmon: Attribute group list: 3 entries > 15,18526,832784000,-;btmon: Handle range: 0x0001-0x000b > 15,18527,832784000,-;btmon: UUID: Generic Access Profile (0x1800) > 15,18528,832784000,-;btmon: Handle range: 0x000c-0x000f > 15,18529,832784000,-;btmon: UUID: Generic Attribute Profile (0x1801) > 15,18530,832784000,-;btmon: Handle range: 0x0010-0x0022 > 15,18531,832784000,-;btmon: UUID: Device Information (0x180a) > 15,18532,832784000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen > 11 [hci0] 17:26:51.790028 > 15,18533,832784000,-;btmon: ATT: Read By Type Request (0x08) len 6 > 15,18534,832784000,-;btmon: Handle range: 0x0036-0x0037 > 15,18535,832784000,-;btmon: Attribute type: Characteristic (0x2803) > 15,18536,832792000,-;btmon: > HCI Event: Number of Completed Packets > (0x13) plen 5 [hci0] 17:26:51.799354 > 15,18537,832792000,-;btmon: Num handles: 1 > 15,18538,832792000,-;btmon: Handle: 128 > 15,18539,832792000,-;btmon: Count: 1 > 15,18540,832809000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen > 9 [hci0] 17:26:51.808179 > 15,18541,832809000,-;btmon: ATT: Error Response (0x01) len 4 > 15,18542,832809000,-;btmon: Read By Type Request (0x08) > 15,18543,832809000,-;btmon: Handle: 0x0036 > 15,18544,832809000,-;btmon: Error: Attribute Not Found (0x0a) > 15,18546,832811000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen > 11 [hci0] 17:26:51.810774 > 15,18547,832812000,-;btmon: ATT: Read By Group Type Request (0x10) len 6 > 15,18548,832812000,-;btmon: Handle range: 0x0023-0xffff > 15,18549,832812000,-;btmon: Attribute group type: Primary > Service (0x2800) > 15,18553,833321000,-;btmon: > HCI Event: Number of Completed Packets > (0x13) plen 5 [hci0] 17:26:52.328191 > 15,18554,833321000,-;btmon: Num handles: 1 > 15,18555,833321000,-;btmon: Handle: 128 > 15,18556,833321000,-;btmon: Count: 1 > 15,18558,833334000,-;btmon: > HCI Event: Vendor (0xff) plen 5 > [hci0] 17:26:52.339515 > 15,18559,833334000,-;btmon: 05 80 00 09 00 > ..... > 15,18560,833362000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen > 24 [hci0] 17:26:52.369478 > 15,18561,833363000,-;btmon: ATT: Read By Group Type Response (0x11) len 19 > 15,18562,833363000,-;btmon: Attribute data length: 6 > 15,18563,833363000,-;btmon: Attribute group list: 3 entries > 15,18564,833364000,-;btmon: Handle range: 0x0023-0x0028 > 15,18565,833364000,-;btmon: UUID: Battery Service (0x180f) > 15,18566,833364000,-;btmon: Handle range: 0x0029-0x002e > 15,18567,833364000,-;btmon: UUID: Scan Parameters (0x1813) > 15,18568,833364000,-;btmon: Handle range: 0x002f-0x0037 > 15,18569,833364000,-;btmon: UUID: Unknown (0xfff0) > 15,18570,833364000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen > 9 [hci0] 17:26:52.370138 I have to check but these command bellow seems to be unrelated to the discover. > 15,18571,833364000,-;btmon: ATT: Find Information Request (0x04) len 4 > 15,18572,833364000,-;btmon: Handle range: 0x0036-0x0037 > 15,18574,833371000,-;btmon: > HCI Event: Number of Completed Packets > (0x13) plen 5 [hci0] 17:26:52.378203 > 15,18575,833371000,-;btmon: Num handles: 1 > 15,18576,833371000,-;btmon: Handle: 128 > 15,18577,833371000,-;btmon: Count: 1 > 15,18578,833391000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen > 14 [hci0] 17:26:52.398166 > 15,18579,833391000,-;btmon: ATT: Find Information Response (0x05) len 9 > 15,18580,833392000,-;btmon: Format: UUID-16 (0x01) > 15,18582,833394000,-;btmon: Handle: 0x0036 > 15,18583,833394000,-;btmon: UUID: Unknown (0xfff4) > 15,18584,833394000,-;btmon: Handle: 0x0037 > 15,18585,833394000,-;btmon: UUID: Client Characteristic > Configuration (0x2902) > 15,18586,833394000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen > 10 [hci0] 17:26:52.400735 > 15,18587,833394000,-;btmon: ATT: Write Request (0x12) len 5 > 15,18588,833394000,-;btmon: Handle: 0x0034 > 15,18589,833394000,-;btmon: Data: 030000 > 15,18591,833912000,-;btmon: > HCI Event: Number of Completed Packets > (0x13) plen 5 [hci0] 17:26:52.919397 > 15,18592,833912000,-;btmon: Num handles: 1 > 15,18593,833912000,-;btmon: Handle: 128 > 15,18594,833912000,-;btmon: Count: 1 > 15,18595,833931000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen > 5 [hci0] 17:26:52.938157 > 15,18596,833931000,-;btmon: ATT: Write Response (0x13) len 0 > 15,18597,833932000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen > 11 [hci0] 17:26:52.939032 Were we just continue with the primary discovery. > 15,18598,833932000,-;btmon: ATT: Read By Group Type Request (0x10) len 6 > 15,18599,833932000,-;btmon: Handle range: 0x0038-0xffff > 15,18600,833932000,-;btmon: Attribute group type: Primary > Service (0x2800) > 15,18601,833944000,-;btmon: > HCI Event: Number of Completed Packets > (0x13) plen 5 [hci0] 17:26:52.951628 > 15,18602,833944000,-;btmon: Num handles: 1 > 15,18603,833944000,-;btmon: Handle: 128 > 15,18604,833944000,-;btmon: Count: 1 > 15,18605,833959000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen > 12 [hci0] 17:26:52.966479 > 15,18606,833959000,-;btmon: ATT: Read By Group Type Response (0x11) len 7 > 15,18607,833960000,-;btmon: Attribute data length: 6 > 15,18608,833960000,-;btmon: Attribute group list: 1 entry > 15,18609,833960000,-;btmon: Handle range: 0x0038-0x005c > 15,18610,833960000,-;btmon: UUID: Human Interface Device (0x1812) > 15,18611,833960000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen > 9 [hci0] 17:26:52.967113 > 15,18612,833960000,-;btmon: ATT: Write Request (0x12) len 4 > 15,18613,833960000,-;btmon: Handle: 0x0037 > 15,18614,833960000,-;btmon: Data: 0100 > 15,18615,833971000,-;btmon: > HCI Event: Number of Completed Packets > (0x13) plen 5 [hci0] 17:26:52.976999 > 15,18616,833971000,-;btmon: Num handles: 1 > 15,18617,833972000,-;btmon: Handle: 128 > 15,18618,833972000,-;btmon: Count: 1 > 15,18619,833979000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen > 5 [hci0] 17:26:52.986355 > 15,18620,833980000,-;btmon: ATT: Write Response (0x13) len 0 > 15,18621,833980000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen > 11 [hci0] 17:26:52.986894 > 15,18622,833980000,-;btmon: ATT: Read By Group Type Request (0x10) len 6 > 15,18623,833980000,-;btmon: Handle range: 0x005d-0xffff > 15,18624,833980000,-;btmon: Attribute group type: Primary > Service (0x2800) > 15,18625,833990000,-;btmon: > HCI Event: Number of Completed Packets > (0x13) plen 5 [hci0] 17:26:52.996610 > 15,18626,833990000,-;btmon: Num handles: 1 > 15,18627,833991000,-;btmon: Handle: 128 > 15,18628,833991000,-;btmon: Count: 1 > 15,18629,834013000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen > 26 [hci0] 17:26:53.019401 > 15,18630,834013000,-;btmon: ATT: Read By Group Type Response (0x11) len 21 > 15,18631,834013000,-;btmon: Attribute data length: 20 > 15,18632,834013000,-;btmon: Attribute group list: 1 entry > 15,18633,834013000,-;btmon: Handle range: 0x005d-0x0070 > 15,18634,834013000,-;btmon: UUID: Vendor specific > (f000fef0-0451-4000-b000-000000000000) > 15,18635,834013000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen > 11 [hci0] 17:26:53.020026 > 15,18636,834013000,-;btmon: ATT: Read By Group Type Request (0x10) len 6 > 15,18637,834013000,-;btmon: Handle range: 0x0071-0xffff > 15,18638,834013000,-;btmon: Attribute group type: Primary > Service (0x2800) > 15,18639,834022000,-;btmon: > HCI Event: Number of Completed Packets > (0x13) plen 5 [hci0] 17:26:53.029922 > 15,18640,834022000,-;btmon: Num handles: 1 > 15,18641,834022000,-;btmon: Handle: 128 > 15,18642,834023000,-;btmon: Count: 1 > 15,18643,834042000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen > 26 [hci0] 17:26:53.049348 > 15,18644,834042000,-;btmon: ATT: Read By Group Type Response (0x11) len 21 > 15,18645,834042000,-;btmon: Attribute data length: 20 > 15,18646,834042000,-;btmon: Attribute group list: 1 entry > 15,18647,834042000,-;btmon: Handle range: 0x0071-0xffff > 15,18648,834042000,-;btmon: UUID: Vendor specific So there is nothing new in the behavior, it does recheck the if the services are in place but it doesn't check if anything about characteristics and descriptors, also in the meantime you can issue command as we see above, so it doesn't introduce extra delays so I wonder why this is bothering you? -- Luiz Augusto von Dentz ^ permalink raw reply [flat|nested] 16+ messages in thread
[parent not found: <CAGXr9JET_-mB1qtOryXpUMhQPTe_ecw84f4kFH+Wv9_WYp3iog@mail.gmail.com>]
* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect [not found] ` <CAGXr9JET_-mB1qtOryXpUMhQPTe_ecw84f4kFH+Wv9_WYp3iog@mail.gmail.com> @ 2016-11-29 23:15 ` Petri Gynther 2016-11-30 8:36 ` Luiz Augusto von Dentz 0 siblings, 1 reply; 16+ messages in thread From: Petri Gynther @ 2016-11-29 23:15 UTC (permalink / raw) To: Luiz Augusto von Dentz; +Cc: linux-bluetooth Hi Luiz, On Wed, Nov 16, 2016 at 1:45 PM, Petri Gynther <pgynther@google.com> wrote: > Hi Luiz, > > On Fri, Nov 11, 2016 at 1:07 AM, Luiz Augusto von Dentz > <luiz.dentz@gmail.com> wrote: >> >> Hi Petri, >> >> On Fri, Nov 11, 2016 at 4:42 AM, Petri Gynther <pgynther@google.com> >> wrote: >> > Hi Luiz, >> > >> > On Thu, Nov 10, 2016 at 6:17 AM, Luiz Augusto von Dentz >> > <luiz.dentz@gmail.com> wrote: >> >> Hi Petri, >> >> >> >> On Wed, Nov 9, 2016 at 9:39 PM, Petri Gynther <pgynther@google.com> >> >> wrote: >> >>> Hi linux-bluetooth: >> >>> >> >>> I'm seeing the following issue with BlueZ 5.43 and Linux 4.4.30. >> >>> >> >>> When a previously bonded HoG remote control reconnects to BlueZ 5.43 >> >>> host, BlueZ goes ahead and re-discovers the primary services of the >> >>> bonded remote again and again on every reconnect. >> >>> >> >>> Why is this necessary? Shouldn't this information be cached on the >> >>> initial pairing/bonding, and a reconnect can get this information from >> >>> the relevant persistent file, rather than wasting BLE airtime and >> >>> delaying the reconnect? >> >>> >> >> >> >> IF, and only if, the cache is restored properly then yes it will work >> >> as you said, but bt_hog is not yet using the gatt_db so it might >> >> rediscover the handles anyway, this happens only once though. >> >> >> >>> >> >>> >> >>> In the above log, I see that MTU exchange takes place: >> >>> 15,148467,14484676000,-;bluez: bluetoothd[1985]: >> >>> src/device.c:gatt_debug() MTU exchange complete, with MTU: 23 >> >>> >> >>> Looking at the relevant code in src/shared/gatt-client.c, function >> >>> exchange_mtu_cb(): >> >>> >> >>> util_debug(client->debug_callback, client->debug_data, >> >>> "MTU exchange complete, with >> >>> MTU: %u", >> >>> bt_att_get_mtu(client->att)); >> >>> >> >>> discover: >> >>> client->discovery_req = bt_gatt_discover_all_primary_services( >> >>> client->att, >> >>> NULL, >> >>> >> >>> discover_primary_cb, >> >>> >> >>> discovery_op_ref(op), >> >>> >> >>> discovery_op_unref); >> >>> >> >>> >> >>> The call to bt_gatt_discover_all_primary_services() is unconditional, >> >>> whether the device was previously bonded or not. >> >> >> >> This does range validation in case service changed is not properly >> >> implemented this will attempt to figure out if there are any changes >> >> in the database, but note that it will stop in here: >> >> >> >> attr = gatt_db_insert_service(client->db, start, &uuid, true, >> >> end - start + 1); >> >> if (!attr) { >> >> >> >> So if the database already contain all the services it will no do more >> >> than one Read By Group Type. >> Looking into btmon details after the line marked ====: >> > 15,18491,832722000,-;bluez: bluetoothd[2346]: >> > profiles/scanparam/scan.c:refresh_ccc_written_cb() Scan Refresh: >> > notification enabled >> > >> > We can see that BlueZ issues a bunch of ATT: Read By Group Type >> > Requests to re-discover all primary services (0x2800): >> >> >> This is what I said, we will issue Read By Group Type to validate the >> cached data since service changed is not mandatory and way too many >> devices don't implement it correctly. >> >> > 15,18491,832722000,-;bluez: bluetoothd[2346]: >> > profiles/scanparam/scan.c:refresh_ccc_written_cb() Scan Refresh: >> > notification enabled >> > 15,18492,832723000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen >> > 11 [hci0] 17:26:51.730522 >> > 15,18493,832725000,-;btmon: ATT: Read By Type Request (0x08) len 6 >> > 15,18494,832725000,-;btmon: Handle range: 0x002f-0x0037 >> > 15,18495,832725000,-;btmon: Attribute type: Characteristic >> > (0x2803) >> > 15,18496,832725000,-;btmon: > HCI Event: Number of Completed Packets >> > (0x13) plen 5 [hci0] 17:26:51.731128 >> > 15,18497,832726000,-;btmon: Num handles: 1 >> > 15,18498,832726000,-;btmon: Handle: 128 >> > 15,18499,832726000,-;btmon: Count: 1 >> > 15,18500,832733000,-;btmon: > HCI Event: Number of Completed Packets >> > (0x13) plen 5 [hci0] 17:26:51.739362 >> > 15,18501,832733000,-;btmon: Num handles: 1 >> > 15,18502,832733000,-;btmon: Handle: 128 >> > 15,18503,832733000,-;btmon: Count: 1 >> > 15,18504,832752000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen >> > 27 [hci0] 17:26:51.759357 >> > 15,18505,832753000,-;btmon: ATT: Read By Type Response (0x09) len >> > 22 >> > 15,18506,832753000,-;btmon: Attribute data length: 7 >> > 15,18507,832753000,-;btmon: Attribute data list: 3 entries >> > 15,18508,832753000,-;btmon: Handle: 0x0030 >> > 15,18509,832753000,-;btmon: Value: 1e3100f1ff >> > 15,18510,832753000,-;btmon: Handle: 0x0033 >> > 15,18511,832753000,-;btmon: Value: 0a3400f2ff >> > 15,18512,832753000,-;btmon: Handle: 0x0035 >> > 15,18513,832753000,-;btmon: Value: 123600f4ff >> > 15,18514,832754000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen >> > 11 [hci0] 17:26:51.760043 >> > 15,18515,832754000,-;btmon: ATT: Read By Group Type Request (0x10) >> > len 6 >> > 15,18516,832754000,-;btmon: Handle range: 0x0001-0xffff >> > 15,18517,832754000,-;btmon: Attribute group type: Primary >> > Service (0x2800) >> > 15,18518,832762000,-;btmon: > HCI Event: Number of Completed Packets >> > (0x13) plen 5 [hci0] 17:26:51.769346 >> > 15,18519,832762000,-;btmon: Num handles: 1 >> > 15,18520,832762000,-;btmon: Handle: 128 >> > 15,18521,832762000,-;btmon: Count: 1 >> > 15,18522,832782000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen >> > 24 [hci0] 17:26:51.789303 >> > 15,18523,832782000,-;btmon: ATT: Read By Group Type Response >> > (0x11) len 19 >> > 15,18524,832782000,-;btmon: Attribute data length: 6 >> > 15,18525,832782000,-;btmon: Attribute group list: 3 entries >> > 15,18526,832784000,-;btmon: Handle range: 0x0001-0x000b >> > 15,18527,832784000,-;btmon: UUID: Generic Access Profile >> > (0x1800) >> > 15,18528,832784000,-;btmon: Handle range: 0x000c-0x000f >> > 15,18529,832784000,-;btmon: UUID: Generic Attribute Profile >> > (0x1801) >> > 15,18530,832784000,-;btmon: Handle range: 0x0010-0x0022 >> > 15,18531,832784000,-;btmon: UUID: Device Information (0x180a) >> > 15,18532,832784000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen >> > 11 [hci0] 17:26:51.790028 >> > 15,18533,832784000,-;btmon: ATT: Read By Type Request (0x08) len 6 >> > 15,18534,832784000,-;btmon: Handle range: 0x0036-0x0037 >> > 15,18535,832784000,-;btmon: Attribute type: Characteristic >> > (0x2803) >> > 15,18536,832792000,-;btmon: > HCI Event: Number of Completed Packets >> > (0x13) plen 5 [hci0] 17:26:51.799354 >> > 15,18537,832792000,-;btmon: Num handles: 1 >> > 15,18538,832792000,-;btmon: Handle: 128 >> > 15,18539,832792000,-;btmon: Count: 1 >> > 15,18540,832809000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen >> > 9 [hci0] 17:26:51.808179 >> > 15,18541,832809000,-;btmon: ATT: Error Response (0x01) len 4 >> > 15,18542,832809000,-;btmon: Read By Type Request (0x08) >> > 15,18543,832809000,-;btmon: Handle: 0x0036 >> > 15,18544,832809000,-;btmon: Error: Attribute Not Found (0x0a) >> > 15,18546,832811000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen >> > 11 [hci0] 17:26:51.810774 >> > 15,18547,832812000,-;btmon: ATT: Read By Group Type Request (0x10) >> > len 6 >> > 15,18548,832812000,-;btmon: Handle range: 0x0023-0xffff >> > 15,18549,832812000,-;btmon: Attribute group type: Primary >> > Service (0x2800) >> > 15,18553,833321000,-;btmon: > HCI Event: Number of Completed Packets >> > (0x13) plen 5 [hci0] 17:26:52.328191 >> > 15,18554,833321000,-;btmon: Num handles: 1 >> > 15,18555,833321000,-;btmon: Handle: 128 >> > 15,18556,833321000,-;btmon: Count: 1 >> > 15,18558,833334000,-;btmon: > HCI Event: Vendor (0xff) plen 5 >> > [hci0] 17:26:52.339515 >> > 15,18559,833334000,-;btmon: 05 80 00 09 00 >> > ..... >> > 15,18560,833362000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen >> > 24 [hci0] 17:26:52.369478 >> > 15,18561,833363000,-;btmon: ATT: Read By Group Type Response >> > (0x11) len 19 >> > 15,18562,833363000,-;btmon: Attribute data length: 6 >> > 15,18563,833363000,-;btmon: Attribute group list: 3 entries >> > 15,18564,833364000,-;btmon: Handle range: 0x0023-0x0028 >> > 15,18565,833364000,-;btmon: UUID: Battery Service (0x180f) >> > 15,18566,833364000,-;btmon: Handle range: 0x0029-0x002e >> > 15,18567,833364000,-;btmon: UUID: Scan Parameters (0x1813) >> > 15,18568,833364000,-;btmon: Handle range: 0x002f-0x0037 >> > 15,18569,833364000,-;btmon: UUID: Unknown (0xfff0) >> > 15,18570,833364000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen >> > 9 [hci0] 17:26:52.370138 >> >> I have to check but these command bellow seems to be unrelated to the >> discover. >> >> > 15,18571,833364000,-;btmon: ATT: Find Information Request (0x04) >> > len 4 >> > 15,18572,833364000,-;btmon: Handle range: 0x0036-0x0037 >> > 15,18574,833371000,-;btmon: > HCI Event: Number of Completed Packets >> > (0x13) plen 5 [hci0] 17:26:52.378203 >> > 15,18575,833371000,-;btmon: Num handles: 1 >> > 15,18576,833371000,-;btmon: Handle: 128 >> > 15,18577,833371000,-;btmon: Count: 1 >> > 15,18578,833391000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen >> > 14 [hci0] 17:26:52.398166 >> > 15,18579,833391000,-;btmon: ATT: Find Information Response (0x05) >> > len 9 >> > 15,18580,833392000,-;btmon: Format: UUID-16 (0x01) >> > 15,18582,833394000,-;btmon: Handle: 0x0036 >> > 15,18583,833394000,-;btmon: UUID: Unknown (0xfff4) >> > 15,18584,833394000,-;btmon: Handle: 0x0037 >> > 15,18585,833394000,-;btmon: UUID: Client Characteristic >> > Configuration (0x2902) >> > 15,18586,833394000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen >> > 10 [hci0] 17:26:52.400735 >> > 15,18587,833394000,-;btmon: ATT: Write Request (0x12) len 5 >> > 15,18588,833394000,-;btmon: Handle: 0x0034 >> > 15,18589,833394000,-;btmon: Data: 030000 >> > 15,18591,833912000,-;btmon: > HCI Event: Number of Completed Packets >> > (0x13) plen 5 [hci0] 17:26:52.919397 >> > 15,18592,833912000,-;btmon: Num handles: 1 >> > 15,18593,833912000,-;btmon: Handle: 128 >> > 15,18594,833912000,-;btmon: Count: 1 >> > 15,18595,833931000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen >> > 5 [hci0] 17:26:52.938157 >> > 15,18596,833931000,-;btmon: ATT: Write Response (0x13) len 0 >> > 15,18597,833932000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen >> > 11 [hci0] 17:26:52.939032 >> >> >> Were we just continue with the primary discovery. >> >> > 15,18598,833932000,-;btmon: ATT: Read By Group Type Request (0x10) >> > len 6 >> > 15,18599,833932000,-;btmon: Handle range: 0x0038-0xffff >> > 15,18600,833932000,-;btmon: Attribute group type: Primary >> > Service (0x2800) >> > 15,18601,833944000,-;btmon: > HCI Event: Number of Completed Packets >> > (0x13) plen 5 [hci0] 17:26:52.951628 >> > 15,18602,833944000,-;btmon: Num handles: 1 >> > 15,18603,833944000,-;btmon: Handle: 128 >> > 15,18604,833944000,-;btmon: Count: 1 >> > 15,18605,833959000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen >> > 12 [hci0] 17:26:52.966479 >> > 15,18606,833959000,-;btmon: ATT: Read By Group Type Response >> > (0x11) len 7 >> > 15,18607,833960000,-;btmon: Attribute data length: 6 >> > 15,18608,833960000,-;btmon: Attribute group list: 1 entry >> > 15,18609,833960000,-;btmon: Handle range: 0x0038-0x005c >> > 15,18610,833960000,-;btmon: UUID: Human Interface Device >> > (0x1812) >> > 15,18611,833960000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen >> > 9 [hci0] 17:26:52.967113 >> > 15,18612,833960000,-;btmon: ATT: Write Request (0x12) len 4 >> > 15,18613,833960000,-;btmon: Handle: 0x0037 >> > 15,18614,833960000,-;btmon: Data: 0100 >> > 15,18615,833971000,-;btmon: > HCI Event: Number of Completed Packets >> > (0x13) plen 5 [hci0] 17:26:52.976999 >> > 15,18616,833971000,-;btmon: Num handles: 1 >> > 15,18617,833972000,-;btmon: Handle: 128 >> > 15,18618,833972000,-;btmon: Count: 1 >> > 15,18619,833979000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen >> > 5 [hci0] 17:26:52.986355 >> > 15,18620,833980000,-;btmon: ATT: Write Response (0x13) len 0 >> > 15,18621,833980000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen >> > 11 [hci0] 17:26:52.986894 >> > 15,18622,833980000,-;btmon: ATT: Read By Group Type Request (0x10) >> > len 6 >> > 15,18623,833980000,-;btmon: Handle range: 0x005d-0xffff >> > 15,18624,833980000,-;btmon: Attribute group type: Primary >> > Service (0x2800) >> > 15,18625,833990000,-;btmon: > HCI Event: Number of Completed Packets >> > (0x13) plen 5 [hci0] 17:26:52.996610 >> > 15,18626,833990000,-;btmon: Num handles: 1 >> > 15,18627,833991000,-;btmon: Handle: 128 >> > 15,18628,833991000,-;btmon: Count: 1 >> > 15,18629,834013000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen >> > 26 [hci0] 17:26:53.019401 >> > 15,18630,834013000,-;btmon: ATT: Read By Group Type Response >> > (0x11) len 21 >> > 15,18631,834013000,-;btmon: Attribute data length: 20 >> > 15,18632,834013000,-;btmon: Attribute group list: 1 entry >> > 15,18633,834013000,-;btmon: Handle range: 0x005d-0x0070 >> > 15,18634,834013000,-;btmon: UUID: Vendor specific >> > (f000fef0-0451-4000-b000-000000000000) >> > 15,18635,834013000,-;btmon: < ACL Data TX: Handle 128 flags 0x00 dlen >> > 11 [hci0] 17:26:53.020026 >> > 15,18636,834013000,-;btmon: ATT: Read By Group Type Request (0x10) >> > len 6 >> > 15,18637,834013000,-;btmon: Handle range: 0x0071-0xffff >> > 15,18638,834013000,-;btmon: Attribute group type: Primary >> > Service (0x2800) >> > 15,18639,834022000,-;btmon: > HCI Event: Number of Completed Packets >> > (0x13) plen 5 [hci0] 17:26:53.029922 >> > 15,18640,834022000,-;btmon: Num handles: 1 >> > 15,18641,834022000,-;btmon: Handle: 128 >> > 15,18642,834023000,-;btmon: Count: 1 >> > 15,18643,834042000,-;btmon: > ACL Data RX: Handle 128 flags 0x02 dlen >> > 26 [hci0] 17:26:53.049348 >> > 15,18644,834042000,-;btmon: ATT: Read By Group Type Response >> > (0x11) len 21 >> > 15,18645,834042000,-;btmon: Attribute data length: 20 >> > 15,18646,834042000,-;btmon: Attribute group list: 1 entry >> > 15,18647,834042000,-;btmon: Handle range: 0x0071-0xffff >> > 15,18648,834042000,-;btmon: UUID: Vendor specific >> >> So there is nothing new in the behavior, it does recheck the if the >> services are in place but it doesn't check if anything about >> characteristics and descriptors, also in the meantime you can issue >> command as we see above, so it doesn't introduce extra delays so I >> wonder why this is bothering you? > > > I'm just interested in optimizing the HoG reconnect, so that only the > absolutely necessary reads/writes are done over the air. > > So, since I know that the primary services on my HoG device won't change, is > there a way to avoid this re-discovery of primary services on every > reconnect? > This primary services re-discovery on every reconnect is actually now causing a problem for us. Basically, this is what happens: 1. HoG remote control reconnects to BlueZ host for firmware update check. 2. BlueZ starts re-discovering the services of the remote, but doesn't yet complete it. 3. The remote disconnects after being connected for 2 seconds (no firmware update was available, so quickly disconnect to save battery). 4. BlueZ declares the HoG remote "bad" since it couldn't complete step (2). And then, BlueZ ends up removing the HoG remote services from its GATT database completely. 5. On the next reconnect attempt, the remote does not work. Re-pairing is required. Obviously, this is bad for user experience. Therefore, I'm asking: 1. Is there a way to avoid services re-discovery on every reconnect? 2. If the remote control is successfully bonded previously, and BlueZ experiences a problem during reconnect (services re-discovery), can we avoid destroying the bonding and GATT info on BlueZ side? A failed reconnect should not be a reason to remove a bonded device. >> >> >> -- >> Luiz Augusto von Dentz > > ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect 2016-11-29 23:15 ` Petri Gynther @ 2016-11-30 8:36 ` Luiz Augusto von Dentz 2016-11-30 9:37 ` Luiz Augusto von Dentz 0 siblings, 1 reply; 16+ messages in thread From: Luiz Augusto von Dentz @ 2016-11-30 8:36 UTC (permalink / raw) To: Petri Gynther; +Cc: linux-bluetooth Hi Petri, > > This primary services re-discovery on every reconnect is actually now > causing a problem for us. > > Basically, this is what happens: > 1. HoG remote control reconnects to BlueZ host for firmware update check. > 2. BlueZ starts re-discovering the services of the remote, but doesn't > yet complete it. > 3. The remote disconnects after being connected for 2 seconds (no > firmware update was available, so quickly disconnect to save battery). > 4. BlueZ declares the HoG remote "bad" since it couldn't complete step > (2). And then, BlueZ ends up removing the HoG remote services from its > GATT database completely. > 5. On the next reconnect attempt, the remote does not work. Re-pairing > is required. > > Obviously, this is bad for user experience. Therefore, I'm asking: > 1. Is there a way to avoid services re-discovery on every reconnect? > 2. If the remote control is successfully bonded previously, and BlueZ > experiences a problem during reconnect (services re-discovery), can we > avoid destroying the bonding and GATT info on BlueZ side? A failed > reconnect should not be a reason to remove a bonded device. The second point should definitely be fixed, but I wonder how the firmware update check does actually detects if the host is not doing something important before it decides it has to save power. Also if I recall this correctly dfu was exactly why some devices needed the database check, they boot in dfu mode which has a different database but they completely lost the state of service changed subscriptions so basically nothing works since all handles are invalid and even if service changed would work it would cause a rediscover anyway. -- Luiz Augusto von Dentz ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect 2016-11-30 8:36 ` Luiz Augusto von Dentz @ 2016-11-30 9:37 ` Luiz Augusto von Dentz 2016-11-30 22:15 ` Petri Gynther 0 siblings, 1 reply; 16+ messages in thread From: Luiz Augusto von Dentz @ 2016-11-30 9:37 UTC (permalink / raw) To: Petri Gynther; +Cc: linux-bluetooth Hi Petri, On Wed, Nov 30, 2016 at 10:36 AM, Luiz Augusto von Dentz <luiz.dentz@gmail.com> wrote: > Hi Petri, >> >> This primary services re-discovery on every reconnect is actually now >> causing a problem for us. >> >> Basically, this is what happens: >> 1. HoG remote control reconnects to BlueZ host for firmware update check. >> 2. BlueZ starts re-discovering the services of the remote, but doesn't >> yet complete it. >> 3. The remote disconnects after being connected for 2 seconds (no >> firmware update was available, so quickly disconnect to save battery). >> 4. BlueZ declares the HoG remote "bad" since it couldn't complete step >> (2). And then, BlueZ ends up removing the HoG remote services from its >> GATT database completely. >> 5. On the next reconnect attempt, the remote does not work. Re-pairing >> is required. >> >> Obviously, this is bad for user experience. Therefore, I'm asking: >> 1. Is there a way to avoid services re-discovery on every reconnect? >> 2. If the remote control is successfully bonded previously, and BlueZ >> experiences a problem during reconnect (services re-discovery), can we >> avoid destroying the bonding and GATT info on BlueZ side? A failed >> reconnect should not be a reason to remove a bonded device. > > The second point should definitely be fixed, but I wonder how the > firmware update check does actually detects if the host is not doing > something important before it decides it has to save power. Also if I > recall this correctly dfu was exactly why some devices needed the > database check, they boot in dfu mode which has a different database > but they completely lost the state of service changed subscriptions so > basically nothing works since all handles are invalid and even if > service changed would work it would cause a rediscover anyway. Checking the code I did not find anything that could have break the remote services, or perhaps it is the passive scanning/reconnection logic that gets broken if we failed to discover the services? -- Luiz Augusto von Dentz ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect 2016-11-30 9:37 ` Luiz Augusto von Dentz @ 2016-11-30 22:15 ` Petri Gynther 2016-11-30 22:55 ` Petri Gynther 2016-12-01 8:21 ` Luiz Augusto von Dentz 0 siblings, 2 replies; 16+ messages in thread From: Petri Gynther @ 2016-11-30 22:15 UTC (permalink / raw) To: Luiz Augusto von Dentz; +Cc: linux-bluetooth Hi Luiz, On Wed, Nov 30, 2016 at 1:37 AM, Luiz Augusto von Dentz <luiz.dentz@gmail.com> wrote: > Hi Petri, > > On Wed, Nov 30, 2016 at 10:36 AM, Luiz Augusto von Dentz > <luiz.dentz@gmail.com> wrote: >> Hi Petri, >>> >>> This primary services re-discovery on every reconnect is actually now >>> causing a problem for us. >>> >>> Basically, this is what happens: >>> 1. HoG remote control reconnects to BlueZ host for firmware update check. >>> 2. BlueZ starts re-discovering the services of the remote, but doesn't >>> yet complete it. >>> 3. The remote disconnects after being connected for 2 seconds (no >>> firmware update was available, so quickly disconnect to save battery). >>> 4. BlueZ declares the HoG remote "bad" since it couldn't complete step >>> (2). And then, BlueZ ends up removing the HoG remote services from its >>> GATT database completely. >>> 5. On the next reconnect attempt, the remote does not work. Re-pairing >>> is required. >>> >>> Obviously, this is bad for user experience. Therefore, I'm asking: >>> 1. Is there a way to avoid services re-discovery on every reconnect? >>> 2. If the remote control is successfully bonded previously, and BlueZ >>> experiences a problem during reconnect (services re-discovery), can we >>> avoid destroying the bonding and GATT info on BlueZ side? A failed >>> reconnect should not be a reason to remove a bonded device. >> >> The second point should definitely be fixed, but I wonder how the >> firmware update check does actually detects if the host is not doing >> something important before it decides it has to save power. Also if I >> recall this correctly dfu was exactly why some devices needed the >> database check, they boot in dfu mode which has a different database >> but they completely lost the state of service changed subscriptions so >> basically nothing works since all handles are invalid and even if >> service changed would work it would cause a rediscover anyway. > > Checking the code I did not find anything that could have break the > remote services, or perhaps it is the passive scanning/reconnection > logic that gets broken if we failed to discover the services? > > -- > Luiz Augusto von Dentz Here is a sample BlueZ log that shows HoG remote reconnect, quick disconnect, primary services re-discovery failure, and subsequent removal of all GATT services of the remote: 11/12,060338.676 bluez: bluetoothd[3980]: src/gatt-database.c:connect_cb() New incoming LE ATT connection 11/12,060338.677 bluez: bluetoothd[3980]: src/device.c:device_attach_att() Elevating security level since LTK is available 11/12,060338.700 bluez: bluetoothd[3980]: attrib/gattrib.c:g_attrib_ref() 0x50b138: g_attrib_ref=1 11/12,060338.700 bluez: bluetoothd[3980]: src/device.c:attio_connected() 11/12,060338.701 bluez: bluetoothd[3980]: profiles/input/hog.c:attio_connected_cb() HoG connected 11/12,060338.701 bluez: bluetoothd[3980]: src/device.c:attio_connected() 11/12,060338.702 bluez: bluetoothd[3980]: src/device.c:attio_connected() 11/12,060338.702 bluez: bluetoothd[3980]: profiles/battery/battery.c:attio_connected_cb() BATT connected 11/12,060338.703 bluez: bluetoothd[3980]: src/device.c:attio_connected() 11/12,060338.703 bluez: bluetoothd[3980]: profiles/oad/oad.c:oad_attio_connected_cb() OAD connected 11/12,060338.704 bluez: bluetoothd[3980]: profiles/oad/oad.c:oad_is_time_for_upgrade_check() OAD not time for upgrade check yet (15164 seconds left) 11/12,060338.704 bluez: bluetoothd[3980]: src/gatt-client.c:btd_gatt_client_connected() Device connected. 11/12,060343.426 bluez: bluetoothd[3980]: src/device.c:gatt_debug() MTU exchange complete, with MTU: 23 11/12,060343.476 bluez: bluetoothd[3980]: profiles/battery/battery.c:level_read_char_cb() BATT level=78 ==== HoG remote disconnects below; primary services re-discovery was still in progress ==== 11/12,060343.691 bluez: bluetoothd[3980]: src/adapter.c:dev_disconnected() Device LEFQAU disconnected, reason 3 11/12,060343.692 bluez: bluetoothd[3980]: src/adapter.c:dev_disconnected() device 0x522c18 paired 1 bonded 1 bonding 0 11/12,060343.694 bluez: bluetoothd[3980]: src/adapter.c:adapter_remove_connection() 11/12,060343.694 bluez: bluetoothd[3980]: plugins/policy.c:disconnect_cb() reason 3 11/12,060343.695 bluez: bluetoothd[3980]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr LEFQAU type 1 status 0xe 11/12,060343.695 bluez: bluetoothd[3980]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e 11/12,060343.696 bluez: bluetoothd[3980]: src/device.c:device_bonding_failed() status 14 11/12,060343.696 bluez: bluetoothd[3980]: src/adapter.c:resume_discovery() ==== primary services discovery failure noted below; all GATT services of the remote are then removed and become unavailable ==== 11/12,060343.698 bluez: bluetoothd[3980]: src/device.c:gatt_debug() Primary service discovery failed. ATT ECODE: 0x00 11/12,060343.698 bluez: bluetoothd[3980]: src/device.c:gatt_service_removed() start: 0x0001, end: 0x000b 11/12,060343.702 bluez: bluetoothd[3980]: src/service.c:change_state() 0x53dd48: device LEFQAU profile gap-profile state changed: connecting -> disconnected (-130) 11/12,060343.707 bluez: bluetoothd[3980]: src/device.c:device_profile_connected() gap-profile Software caused connection abort (130) 11/12,060343.707 bluez: bluetoothd[3980]: src/service.c:change_state() 0x53dd48: device LEFQAU profile gap-profile state changed: disconnected -> unavailable (0) 11/12,060343.711 bluez: bluetoothd[3980]: profiles/gap/gas.c:gap_driver_remove() GAP profile remove (LEFQAU) 11/12,060343.712 bluez: bluetoothd[3980]: src/service.c:btd_service_unref() 0x53dd48: ref=0 11/12,060343.723 bluez: bluetoothd[3980]: src/gatt-client.c:btd_gatt_client_service_removed() GATT Services Removed - start: 0x0001, end: 0x000b 11/12,060343.837 bluez: bluetoothd[3980]: src/device.c:gatt_service_removed() start: 0x000c, end: 0x000f 11/12,060343.838 bluez: bluetoothd[3980]: src/gatt-client.c:btd_gatt_client_service_removed() GATT Services Removed - start: 0x000c, end: 0x000f 11/12,060343.838 bluez: bluetoothd[3980]: src/gatt-client.c:unregister_service() Removing GATT service: /org/bluez/hci0/dev_LEFQAU/service000c 11/12,060343.839 bluez: bluetoothd[3980]: src/gatt-client.c:unregister_characteristic() Removing GATT characteristic: /org/bluez/hci0/dev_LEFQAU/service000c/char000d 11/12,060343.840 bluez: bluetoothd[3980]: src/gatt-client.c:unregister_descriptor() Removing GATT descriptor: /org/bluez/hci0/dev_LEFQAU/service000c/char000d/desc000f 11/12,060343.893 bluez: bluetoothd[3980]: src/device.c:gatt_service_removed() start: 0x0010, end: 0x0022 11/12,060343.894 bluez: bluetoothd[3980]: src/service.c:change_state() 0x53dce8: device LEFQAU profile deviceinfo state changed: connecting -> disconnected (-130) 11/12,060343.895 bluez: bluetoothd[3980]: src/device.c:device_profile_connected() deviceinfo Software caused connection abort (130) 11/12,060343.898 bluez: bluetoothd[3980]: src/service.c:change_state() 0x53dce8: device LEFQAU profile deviceinfo state changed: disconnected -> unavailable (0) 11/12,060343.898 bluez: bluetoothd[3980]: src/service.c:btd_service_unref() 0x53dce8: ref=0 11/12,060343.902 bluez: bluetoothd[3980]: src/gatt-client.c:btd_gatt_client_service_removed() GATT Services Removed - start: 0x0010, end: 0x0022 11/12,060343.905 bluez: bluetoothd[3980]: src/gatt-client.c:unregister_service() Removing GATT service: /org/bluez/hci0/dev_LEFQAU/service0010 11/12,060343.906 bluez: bluetoothd[3980]: src/gatt-client.c:unregister_characteristic() Removing GATT characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0011 11/12,060343.910 bluez: bluetoothd[3980]: src/gatt-client.c:unregister_characteristic() Removing GATT characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0013 11/12,060343.914 bluez: bluetoothd[3980]: src/gatt-client.c:unregister_characteristic() Removing GATT characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0015 11/12,060343.920 bluez: bluetoothd[3980]: src/gatt-client.c:unregister_characteristic() Removing GATT characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0017 11/12,060343.922 bluez: bluetoothd[3980]: src/gatt-client.c:unregister_characteristic() Removing GATT characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0019 11/12,060343.926 bluez: bluetoothd[3980]: src/gatt-client.c:unregister_characteristic() Removing GATT characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char001b 11/12,060343.940 bluez: bluetoothd[3980]: src/gatt-client.c:unregister_characteristic() Removing GATT characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char001d 11/12,060343.941 bluez: bluetoothd[3980]: src/gatt-client.c:unregister_characteris 11/12,061849.049 bluez: bluetoothd[3980]: src/gatt-client.c:btd_gatt_client_disconnected() Device disconnected. Cleaning up. 11/12,061849.056 bluez: bluetoothd[3980]: attrib/gattrib.c:g_attrib_unref() 0x51c360: g_attrib_unref=0tic() Removing GATT characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char001f 11/12,060343.942 bluez: bluetoothd[3980]: src/gatt-client.c:unregister_characteristic() Removing GATT characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0021 11/12,060344.021 bluez: bluetoothd[3980]: src/device.c:gatt_service_removed() start: 0x0023, end: 0x0028 11/12,060344.022 bluez: bluetoothd[3980]: src/service.c:change_state() 0x53dd80: device LEFQAU profile Battery state changed: connecting -> disconnected (-130) 11/12,060344.023 bluez: bluetoothd[3980]: src/device.c:device_profile_connected() Battery Software caused connection abort (130) 11/12,060344.025 bluez: bluetoothd[3980]: src/service.c:change_state() 0x53dd80: device LEFQAU profile Battery state changed: disconnected -> unavailable (0) 11/12,060344.033 bluez: bluetoothd[3980]: profiles/battery/battery.c:batt_remove() BATT path /org/bluez/hci0/dev_LEFQAU 11/12,060344.036 bluez: bluetoothd[3980]: src/service.c:btd_service_unref() 0x53dd80: ref=0 11/12,060344.037 bluez: bluetoothd[3980]: src/gatt-client.c:btd_gatt_client_service_removed() GATT Services Removed - start: 0x0023, end: 0x0028 11/12,060344.046 bluez: bluetoothd[3980]: Error storing included service - can't find it 11/12,060344.128 bluez: bluetoothd[3980]: src/device.c:gatt_service_removed() start: 0x0029, end: 0x002e 11/12,060344.129 bluez: bluetoothd[3980]: src/service.c:change_state() 0x53dd08: device LEFQAU profile Scan Parameters Client Driver state changed: connecting -> disconnected (-130) 11/12,060344.129 bluez: bluetoothd[3980]: src/device.c:device_profile_connected() Scan Parameters Client Driver Software caused connection abort (130) 11/12,060344.133 bluez: bluetoothd[3980]: src/service.c:change_state() 0x53dd08: device LEFQAU profile Scan Parameters Client Driver state changed: disconnected -> unavailable (0) 11/12,060344.141 bluez: bluetoothd[3980]: profiles/scanparam/scan.c:scan_param_remove() GAP profile remove (LEFQAU) 11/12,060344.145 bluez: bluetoothd[3980]: src/service.c:btd_service_unref() 0x53dd08: ref=0 11/12,060344.226 bluez: bluetoothd[3980]: src/service.c:btd_service_unref() 0x53dc38: ref=0 11/12,060344.239 bluez: bluetoothd[3980]: src/gatt-client.c:btd_gatt_client_service_removed() GATT Services Removed - start: 0x002f, end: 0x0037 11/12,060344.247 bluez: bluetoothd[3980]: Error storing included service - can't find it 11/12,060344.291 bluez: bluetoothd[3980]: src/device.c:gatt_service_removed() start: 0x0038, end: 0x005c 11/12,060344.292 bluez: bluetoothd[3980]: src/service.c:change_state() 0x53d3a0: device LEFQAU profile input-hog state changed: connecting -> disconnected (-130) 11/12,060344.293 bluez: bluetoothd[3980]: src/device.c:device_profile_connected() input-hog Software caused connection abort (130) 11/12,060344.293 bluez: bluetoothd[3980]: src/service.c:change_state() 0x53d3a0: device LEFQAU profile input-hog state changed: disconnected -> unavailable (0) 11/12,060344.296 bluez: bluetoothd[3980]: profiles/input/hog.c:hog_remove() path /org/bluez/hci0/dev_LEFQAU 11/12,060344.313 bluez: bluetoothd[3980]: src/service.c:btd_service_unref() 0x53d3a0: ref=0 11/12,060344.313 bluez: bluetoothd[3980]: src/gatt-client.c:btd_gatt_client_service_removed() GATT Services Removed - start: 0x0038, end: 0x005c 11/12,060344.382 bluez: bluetoothd[3980]: src/device.c:gatt_service_removed() start: 0x005d, end: 0x0070 11/12,060344.383 bluez: bluetoothd[3980]: src/gatt-client.c:btd_gatt_client_service_removed() GATT Services Removed - start: 0x005d, end: 0x0070 11/12,060344.575 bluez: bluetoothd[3980]: src/device.c:device_svc_resolved() /org/bluez/hci0/dev_LEFQAU err 0 11/12,060344.584 bluez: bluetoothd[3980]: src/device.c:att_disconnected_cb() 11/12,060344.591 bluez: bluetoothd[3980]: src/device.c:att_disconnected_cb() Connection reset by peer (131) So, if we can somehow avoid removing the GATT services of the remote in this scenario, it would be a big usability win. Next reconnect attempt would just work, since the services would be left in disconnected state. -- Petri ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect 2016-11-30 22:15 ` Petri Gynther @ 2016-11-30 22:55 ` Petri Gynther 2016-12-01 7:54 ` Luiz Augusto von Dentz 2016-12-01 8:21 ` Luiz Augusto von Dentz 1 sibling, 1 reply; 16+ messages in thread From: Petri Gynther @ 2016-11-30 22:55 UTC (permalink / raw) To: Luiz Augusto von Dentz; +Cc: linux-bluetooth Hi Luiz, On Wed, Nov 30, 2016 at 2:15 PM, Petri Gynther <pgynther@google.com> wrote: > Hi Luiz, > > On Wed, Nov 30, 2016 at 1:37 AM, Luiz Augusto von Dentz > <luiz.dentz@gmail.com> wrote: >> Hi Petri, >> >> On Wed, Nov 30, 2016 at 10:36 AM, Luiz Augusto von Dentz >> <luiz.dentz@gmail.com> wrote: >>> Hi Petri, >>>> >>>> This primary services re-discovery on every reconnect is actually now >>>> causing a problem for us. >>>> >>>> Basically, this is what happens: >>>> 1. HoG remote control reconnects to BlueZ host for firmware update check. >>>> 2. BlueZ starts re-discovering the services of the remote, but doesn't >>>> yet complete it. >>>> 3. The remote disconnects after being connected for 2 seconds (no >>>> firmware update was available, so quickly disconnect to save battery). >>>> 4. BlueZ declares the HoG remote "bad" since it couldn't complete step >>>> (2). And then, BlueZ ends up removing the HoG remote services from its >>>> GATT database completely. >>>> 5. On the next reconnect attempt, the remote does not work. Re-pairing >>>> is required. >>>> >>>> Obviously, this is bad for user experience. Therefore, I'm asking: >>>> 1. Is there a way to avoid services re-discovery on every reconnect? >>>> 2. If the remote control is successfully bonded previously, and BlueZ >>>> experiences a problem during reconnect (services re-discovery), can we >>>> avoid destroying the bonding and GATT info on BlueZ side? A failed >>>> reconnect should not be a reason to remove a bonded device. >>> >>> The second point should definitely be fixed, but I wonder how the >>> firmware update check does actually detects if the host is not doing >>> something important before it decides it has to save power. Also if I >>> recall this correctly dfu was exactly why some devices needed the >>> database check, they boot in dfu mode which has a different database >>> but they completely lost the state of service changed subscriptions so >>> basically nothing works since all handles are invalid and even if >>> service changed would work it would cause a rediscover anyway. >> >> Checking the code I did not find anything that could have break the >> remote services, or perhaps it is the passive scanning/reconnection >> logic that gets broken if we failed to discover the services? >> >> -- >> Luiz Augusto von Dentz > > Here is a sample BlueZ log that shows HoG remote reconnect, quick > disconnect, primary services re-discovery failure, and subsequent > removal of all GATT services of the remote: > > 11/12,060338.676 bluez: bluetoothd[3980]: > src/gatt-database.c:connect_cb() New incoming LE ATT connection > 11/12,060338.677 bluez: bluetoothd[3980]: > src/device.c:device_attach_att() Elevating security level since LTK is > available > 11/12,060338.700 bluez: bluetoothd[3980]: > attrib/gattrib.c:g_attrib_ref() 0x50b138: g_attrib_ref=1 > 11/12,060338.700 bluez: bluetoothd[3980]: src/device.c:attio_connected() > 11/12,060338.701 bluez: bluetoothd[3980]: > profiles/input/hog.c:attio_connected_cb() HoG connected > 11/12,060338.701 bluez: bluetoothd[3980]: src/device.c:attio_connected() > 11/12,060338.702 bluez: bluetoothd[3980]: src/device.c:attio_connected() > 11/12,060338.702 bluez: bluetoothd[3980]: > profiles/battery/battery.c:attio_connected_cb() BATT connected > 11/12,060338.703 bluez: bluetoothd[3980]: src/device.c:attio_connected() > 11/12,060338.703 bluez: bluetoothd[3980]: > profiles/oad/oad.c:oad_attio_connected_cb() OAD connected > 11/12,060338.704 bluez: bluetoothd[3980]: > profiles/oad/oad.c:oad_is_time_for_upgrade_check() OAD not time for > upgrade check yet (15164 seconds left) > 11/12,060338.704 bluez: bluetoothd[3980]: > src/gatt-client.c:btd_gatt_client_connected() Device connected. > 11/12,060343.426 bluez: bluetoothd[3980]: src/device.c:gatt_debug() > MTU exchange complete, with MTU: 23 > 11/12,060343.476 bluez: bluetoothd[3980]: > profiles/battery/battery.c:level_read_char_cb() BATT level=78 > > ==== HoG remote disconnects below; primary services re-discovery was > still in progress ==== > 11/12,060343.691 bluez: bluetoothd[3980]: > src/adapter.c:dev_disconnected() Device LEFQAU disconnected, reason 3 > 11/12,060343.692 bluez: bluetoothd[3980]: > src/adapter.c:dev_disconnected() device 0x522c18 paired 1 bonded 1 > bonding 0 > 11/12,060343.694 bluez: bluetoothd[3980]: > src/adapter.c:adapter_remove_connection() > 11/12,060343.694 bluez: bluetoothd[3980]: > plugins/policy.c:disconnect_cb() reason 3 > 11/12,060343.695 bluez: bluetoothd[3980]: > src/adapter.c:bonding_attempt_complete() hci0 bdaddr LEFQAU type 1 > status 0xe > 11/12,060343.695 bluez: bluetoothd[3980]: > src/device.c:device_bonding_complete() bonding (nil) status 0x0e > 11/12,060343.696 bluez: bluetoothd[3980]: > src/device.c:device_bonding_failed() status 14 > 11/12,060343.696 bluez: bluetoothd[3980]: src/adapter.c:resume_discovery() > > ==== primary services discovery failure noted below; all GATT services > of the remote are then removed and become unavailable ==== > 11/12,060343.698 bluez: bluetoothd[3980]: src/device.c:gatt_debug() > Primary service discovery failed. ATT ECODE: 0x00 > 11/12,060343.698 bluez: bluetoothd[3980]: > src/device.c:gatt_service_removed() start: 0x0001, end: 0x000b > 11/12,060343.702 bluez: bluetoothd[3980]: > src/service.c:change_state() 0x53dd48: device LEFQAU profile > gap-profile state changed: connecting -> disconnected (-130) > 11/12,060343.707 bluez: bluetoothd[3980]: > src/device.c:device_profile_connected() gap-profile Software caused > connection abort (130) > 11/12,060343.707 bluez: bluetoothd[3980]: > src/service.c:change_state() 0x53dd48: device LEFQAU profile > gap-profile state changed: disconnected -> unavailable (0) > 11/12,060343.711 bluez: bluetoothd[3980]: > profiles/gap/gas.c:gap_driver_remove() GAP profile remove (LEFQAU) > 11/12,060343.712 bluez: bluetoothd[3980]: > src/service.c:btd_service_unref() 0x53dd48: ref=0 > 11/12,060343.723 bluez: bluetoothd[3980]: > src/gatt-client.c:btd_gatt_client_service_removed() GATT Services > Removed - start: 0x0001, end: 0x000b > 11/12,060343.837 bluez: bluetoothd[3980]: > src/device.c:gatt_service_removed() start: 0x000c, end: 0x000f > 11/12,060343.838 bluez: bluetoothd[3980]: > src/gatt-client.c:btd_gatt_client_service_removed() GATT Services > Removed - start: 0x000c, end: 0x000f > 11/12,060343.838 bluez: bluetoothd[3980]: > src/gatt-client.c:unregister_service() Removing GATT service: > /org/bluez/hci0/dev_LEFQAU/service000c > 11/12,060343.839 bluez: bluetoothd[3980]: > src/gatt-client.c:unregister_characteristic() Removing GATT > characteristic: /org/bluez/hci0/dev_LEFQAU/service000c/char000d > 11/12,060343.840 bluez: bluetoothd[3980]: > src/gatt-client.c:unregister_descriptor() Removing GATT descriptor: > /org/bluez/hci0/dev_LEFQAU/service000c/char000d/desc000f > 11/12,060343.893 bluez: bluetoothd[3980]: > src/device.c:gatt_service_removed() start: 0x0010, end: 0x0022 > 11/12,060343.894 bluez: bluetoothd[3980]: > src/service.c:change_state() 0x53dce8: device LEFQAU profile > deviceinfo state changed: connecting -> disconnected (-130) > 11/12,060343.895 bluez: bluetoothd[3980]: > src/device.c:device_profile_connected() deviceinfo Software caused > connection abort (130) > 11/12,060343.898 bluez: bluetoothd[3980]: > src/service.c:change_state() 0x53dce8: device LEFQAU profile > deviceinfo state changed: disconnected -> unavailable (0) > 11/12,060343.898 bluez: bluetoothd[3980]: > src/service.c:btd_service_unref() 0x53dce8: ref=0 > 11/12,060343.902 bluez: bluetoothd[3980]: > src/gatt-client.c:btd_gatt_client_service_removed() GATT Services > Removed - start: 0x0010, end: 0x0022 > 11/12,060343.905 bluez: bluetoothd[3980]: > src/gatt-client.c:unregister_service() Removing GATT service: > /org/bluez/hci0/dev_LEFQAU/service0010 > 11/12,060343.906 bluez: bluetoothd[3980]: > src/gatt-client.c:unregister_characteristic() Removing GATT > characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0011 > 11/12,060343.910 bluez: bluetoothd[3980]: > src/gatt-client.c:unregister_characteristic() Removing GATT > characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0013 > 11/12,060343.914 bluez: bluetoothd[3980]: > src/gatt-client.c:unregister_characteristic() Removing GATT > characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0015 > 11/12,060343.920 bluez: bluetoothd[3980]: > src/gatt-client.c:unregister_characteristic() Removing GATT > characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0017 > 11/12,060343.922 bluez: bluetoothd[3980]: > src/gatt-client.c:unregister_characteristic() Removing GATT > characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0019 > 11/12,060343.926 bluez: bluetoothd[3980]: > src/gatt-client.c:unregister_characteristic() Removing GATT > characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char001b > 11/12,060343.940 bluez: bluetoothd[3980]: > src/gatt-client.c:unregister_characteristic() Removing GATT > characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char001d > 11/12,060343.941 bluez: bluetoothd[3980]: > src/gatt-client.c:unregister_characteris > > 11/12,061849.049 bluez: bluetoothd[3980]: > src/gatt-client.c:btd_gatt_client_disconnected() Device disconnected. > Cleaning up. > 11/12,061849.056 bluez: bluetoothd[3980]: > attrib/gattrib.c:g_attrib_unref() 0x51c360: g_attrib_unref=0tic() > Removing GATT characteristic: > /org/bluez/hci0/dev_LEFQAU/service0010/char001f > 11/12,060343.942 bluez: bluetoothd[3980]: > src/gatt-client.c:unregister_characteristic() Removing GATT > characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0021 > 11/12,060344.021 bluez: bluetoothd[3980]: > src/device.c:gatt_service_removed() start: 0x0023, end: 0x0028 > 11/12,060344.022 bluez: bluetoothd[3980]: > src/service.c:change_state() 0x53dd80: device LEFQAU profile Battery > state changed: connecting -> disconnected (-130) > 11/12,060344.023 bluez: bluetoothd[3980]: > src/device.c:device_profile_connected() Battery Software caused > connection abort (130) > 11/12,060344.025 bluez: bluetoothd[3980]: > src/service.c:change_state() 0x53dd80: device LEFQAU profile Battery > state changed: disconnected -> unavailable (0) > 11/12,060344.033 bluez: bluetoothd[3980]: > profiles/battery/battery.c:batt_remove() BATT path > /org/bluez/hci0/dev_LEFQAU > 11/12,060344.036 bluez: bluetoothd[3980]: > src/service.c:btd_service_unref() 0x53dd80: ref=0 > 11/12,060344.037 bluez: bluetoothd[3980]: > src/gatt-client.c:btd_gatt_client_service_removed() GATT Services > Removed - start: 0x0023, end: 0x0028 > 11/12,060344.046 bluez: bluetoothd[3980]: Error storing included > service - can't find it > 11/12,060344.128 bluez: bluetoothd[3980]: > src/device.c:gatt_service_removed() start: 0x0029, end: 0x002e > 11/12,060344.129 bluez: bluetoothd[3980]: > src/service.c:change_state() 0x53dd08: device LEFQAU profile Scan > Parameters Client Driver state changed: connecting -> disconnected > (-130) > 11/12,060344.129 bluez: bluetoothd[3980]: > src/device.c:device_profile_connected() Scan Parameters Client Driver > Software caused connection abort (130) > 11/12,060344.133 bluez: bluetoothd[3980]: > src/service.c:change_state() 0x53dd08: device LEFQAU profile Scan > Parameters Client Driver state changed: disconnected -> unavailable > (0) > 11/12,060344.141 bluez: bluetoothd[3980]: > profiles/scanparam/scan.c:scan_param_remove() GAP profile remove > (LEFQAU) > 11/12,060344.145 bluez: bluetoothd[3980]: > src/service.c:btd_service_unref() 0x53dd08: ref=0 > 11/12,060344.226 bluez: bluetoothd[3980]: > src/service.c:btd_service_unref() 0x53dc38: ref=0 > 11/12,060344.239 bluez: bluetoothd[3980]: > src/gatt-client.c:btd_gatt_client_service_removed() GATT Services > Removed - start: 0x002f, end: 0x0037 > 11/12,060344.247 bluez: bluetoothd[3980]: Error storing included > service - can't find it > 11/12,060344.291 bluez: bluetoothd[3980]: > src/device.c:gatt_service_removed() start: 0x0038, end: 0x005c > 11/12,060344.292 bluez: bluetoothd[3980]: > src/service.c:change_state() 0x53d3a0: device LEFQAU profile input-hog > state changed: connecting -> disconnected (-130) > 11/12,060344.293 bluez: bluetoothd[3980]: > src/device.c:device_profile_connected() input-hog Software caused > connection abort (130) > 11/12,060344.293 bluez: bluetoothd[3980]: > src/service.c:change_state() 0x53d3a0: device LEFQAU profile input-hog > state changed: disconnected -> unavailable (0) > 11/12,060344.296 bluez: bluetoothd[3980]: > profiles/input/hog.c:hog_remove() path /org/bluez/hci0/dev_LEFQAU > 11/12,060344.313 bluez: bluetoothd[3980]: > src/service.c:btd_service_unref() 0x53d3a0: ref=0 > 11/12,060344.313 bluez: bluetoothd[3980]: > src/gatt-client.c:btd_gatt_client_service_removed() GATT Services > Removed - start: 0x0038, end: 0x005c > 11/12,060344.382 bluez: bluetoothd[3980]: > src/device.c:gatt_service_removed() start: 0x005d, end: 0x0070 > 11/12,060344.383 bluez: bluetoothd[3980]: > src/gatt-client.c:btd_gatt_client_service_removed() GATT Services > Removed - start: 0x005d, end: 0x0070 > 11/12,060344.575 bluez: bluetoothd[3980]: > src/device.c:device_svc_resolved() /org/bluez/hci0/dev_LEFQAU err 0 > 11/12,060344.584 bluez: bluetoothd[3980]: src/device.c:att_disconnected_cb() > 11/12,060344.591 bluez: bluetoothd[3980]: > src/device.c:att_disconnected_cb() Connection reset by peer (131) > > So, if we can somehow avoid removing the GATT services of the remote > in this scenario, it would be a big usability win. Next reconnect > attempt would just work, since the services would be left in > disconnected state. > > -- Petri Just found a bug in src/shared/gatt-client.c: discover_primary_cb() if (!success) { util_debug(client->debug_callback, client->debug_data, "Primary service discovery failed." " ATT ECODE: 0x%02x", att_ecode); /* Reset error in case of not found */ if (BT_ATT_ERROR_ATTRIBUTE_NOT_FOUND) { success = true; att_ecode = 0; } goto secondary; } The second if-statement: if (BT_ATT_ERROR_ATTRIBUTE_NOT_FOUND) should be: if (att_ecode == BT_ATT_ERROR_ATTRIBUTE_NOT_FOUND) Furthermore, looking at my own failure log: bluez: bluetoothd[3980]: src/device.c:gatt_debug() Primary service discovery failed. ATT ECODE: 0x00 Perhaps the if-statement should be: if (att_ecode == 0 || att_ecode == BT_ATT_ERROR_ATTRIBUTE_NOT_FOUND) { success = true; att_ecode = 0; goto secondary; } else { goto done; } Similar adjustment for att_ecode == 0 might be needed for discover_secondary_cb(). ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect 2016-11-30 22:55 ` Petri Gynther @ 2016-12-01 7:54 ` Luiz Augusto von Dentz 0 siblings, 0 replies; 16+ messages in thread From: Luiz Augusto von Dentz @ 2016-12-01 7:54 UTC (permalink / raw) To: Petri Gynther; +Cc: linux-bluetooth Hi Petri, On Thu, Dec 1, 2016 at 12:55 AM, Petri Gynther <pgynther@google.com> wrote: > Hi Luiz, > > On Wed, Nov 30, 2016 at 2:15 PM, Petri Gynther <pgynther@google.com> wrote: >> Hi Luiz, >> >> On Wed, Nov 30, 2016 at 1:37 AM, Luiz Augusto von Dentz >> <luiz.dentz@gmail.com> wrote: >>> Hi Petri, >>> >>> On Wed, Nov 30, 2016 at 10:36 AM, Luiz Augusto von Dentz >>> <luiz.dentz@gmail.com> wrote: >>>> Hi Petri, >>>>> >>>>> This primary services re-discovery on every reconnect is actually now >>>>> causing a problem for us. >>>>> >>>>> Basically, this is what happens: >>>>> 1. HoG remote control reconnects to BlueZ host for firmware update check. >>>>> 2. BlueZ starts re-discovering the services of the remote, but doesn't >>>>> yet complete it. >>>>> 3. The remote disconnects after being connected for 2 seconds (no >>>>> firmware update was available, so quickly disconnect to save battery). >>>>> 4. BlueZ declares the HoG remote "bad" since it couldn't complete step >>>>> (2). And then, BlueZ ends up removing the HoG remote services from its >>>>> GATT database completely. >>>>> 5. On the next reconnect attempt, the remote does not work. Re-pairing >>>>> is required. >>>>> >>>>> Obviously, this is bad for user experience. Therefore, I'm asking: >>>>> 1. Is there a way to avoid services re-discovery on every reconnect? >>>>> 2. If the remote control is successfully bonded previously, and BlueZ >>>>> experiences a problem during reconnect (services re-discovery), can we >>>>> avoid destroying the bonding and GATT info on BlueZ side? A failed >>>>> reconnect should not be a reason to remove a bonded device. >>>> >>>> The second point should definitely be fixed, but I wonder how the >>>> firmware update check does actually detects if the host is not doing >>>> something important before it decides it has to save power. Also if I >>>> recall this correctly dfu was exactly why some devices needed the >>>> database check, they boot in dfu mode which has a different database >>>> but they completely lost the state of service changed subscriptions so >>>> basically nothing works since all handles are invalid and even if >>>> service changed would work it would cause a rediscover anyway. >>> >>> Checking the code I did not find anything that could have break the >>> remote services, or perhaps it is the passive scanning/reconnection >>> logic that gets broken if we failed to discover the services? >>> >>> -- >>> Luiz Augusto von Dentz >> >> Here is a sample BlueZ log that shows HoG remote reconnect, quick >> disconnect, primary services re-discovery failure, and subsequent >> removal of all GATT services of the remote: >> >> 11/12,060338.676 bluez: bluetoothd[3980]: >> src/gatt-database.c:connect_cb() New incoming LE ATT connection >> 11/12,060338.677 bluez: bluetoothd[3980]: >> src/device.c:device_attach_att() Elevating security level since LTK is >> available >> 11/12,060338.700 bluez: bluetoothd[3980]: >> attrib/gattrib.c:g_attrib_ref() 0x50b138: g_attrib_ref=1 >> 11/12,060338.700 bluez: bluetoothd[3980]: src/device.c:attio_connected() >> 11/12,060338.701 bluez: bluetoothd[3980]: >> profiles/input/hog.c:attio_connected_cb() HoG connected >> 11/12,060338.701 bluez: bluetoothd[3980]: src/device.c:attio_connected() >> 11/12,060338.702 bluez: bluetoothd[3980]: src/device.c:attio_connected() >> 11/12,060338.702 bluez: bluetoothd[3980]: >> profiles/battery/battery.c:attio_connected_cb() BATT connected >> 11/12,060338.703 bluez: bluetoothd[3980]: src/device.c:attio_connected() >> 11/12,060338.703 bluez: bluetoothd[3980]: >> profiles/oad/oad.c:oad_attio_connected_cb() OAD connected >> 11/12,060338.704 bluez: bluetoothd[3980]: >> profiles/oad/oad.c:oad_is_time_for_upgrade_check() OAD not time for >> upgrade check yet (15164 seconds left) >> 11/12,060338.704 bluez: bluetoothd[3980]: >> src/gatt-client.c:btd_gatt_client_connected() Device connected. >> 11/12,060343.426 bluez: bluetoothd[3980]: src/device.c:gatt_debug() >> MTU exchange complete, with MTU: 23 >> 11/12,060343.476 bluez: bluetoothd[3980]: >> profiles/battery/battery.c:level_read_char_cb() BATT level=78 >> >> ==== HoG remote disconnects below; primary services re-discovery was >> still in progress ==== >> 11/12,060343.691 bluez: bluetoothd[3980]: >> src/adapter.c:dev_disconnected() Device LEFQAU disconnected, reason 3 >> 11/12,060343.692 bluez: bluetoothd[3980]: >> src/adapter.c:dev_disconnected() device 0x522c18 paired 1 bonded 1 >> bonding 0 >> 11/12,060343.694 bluez: bluetoothd[3980]: >> src/adapter.c:adapter_remove_connection() >> 11/12,060343.694 bluez: bluetoothd[3980]: >> plugins/policy.c:disconnect_cb() reason 3 >> 11/12,060343.695 bluez: bluetoothd[3980]: >> src/adapter.c:bonding_attempt_complete() hci0 bdaddr LEFQAU type 1 >> status 0xe >> 11/12,060343.695 bluez: bluetoothd[3980]: >> src/device.c:device_bonding_complete() bonding (nil) status 0x0e >> 11/12,060343.696 bluez: bluetoothd[3980]: >> src/device.c:device_bonding_failed() status 14 >> 11/12,060343.696 bluez: bluetoothd[3980]: src/adapter.c:resume_discovery() >> >> ==== primary services discovery failure noted below; all GATT services >> of the remote are then removed and become unavailable ==== >> 11/12,060343.698 bluez: bluetoothd[3980]: src/device.c:gatt_debug() >> Primary service discovery failed. ATT ECODE: 0x00 >> 11/12,060343.698 bluez: bluetoothd[3980]: >> src/device.c:gatt_service_removed() start: 0x0001, end: 0x000b >> 11/12,060343.702 bluez: bluetoothd[3980]: >> src/service.c:change_state() 0x53dd48: device LEFQAU profile >> gap-profile state changed: connecting -> disconnected (-130) >> 11/12,060343.707 bluez: bluetoothd[3980]: >> src/device.c:device_profile_connected() gap-profile Software caused >> connection abort (130) >> 11/12,060343.707 bluez: bluetoothd[3980]: >> src/service.c:change_state() 0x53dd48: device LEFQAU profile >> gap-profile state changed: disconnected -> unavailable (0) >> 11/12,060343.711 bluez: bluetoothd[3980]: >> profiles/gap/gas.c:gap_driver_remove() GAP profile remove (LEFQAU) >> 11/12,060343.712 bluez: bluetoothd[3980]: >> src/service.c:btd_service_unref() 0x53dd48: ref=0 >> 11/12,060343.723 bluez: bluetoothd[3980]: >> src/gatt-client.c:btd_gatt_client_service_removed() GATT Services >> Removed - start: 0x0001, end: 0x000b >> 11/12,060343.837 bluez: bluetoothd[3980]: >> src/device.c:gatt_service_removed() start: 0x000c, end: 0x000f >> 11/12,060343.838 bluez: bluetoothd[3980]: >> src/gatt-client.c:btd_gatt_client_service_removed() GATT Services >> Removed - start: 0x000c, end: 0x000f >> 11/12,060343.838 bluez: bluetoothd[3980]: >> src/gatt-client.c:unregister_service() Removing GATT service: >> /org/bluez/hci0/dev_LEFQAU/service000c >> 11/12,060343.839 bluez: bluetoothd[3980]: >> src/gatt-client.c:unregister_characteristic() Removing GATT >> characteristic: /org/bluez/hci0/dev_LEFQAU/service000c/char000d >> 11/12,060343.840 bluez: bluetoothd[3980]: >> src/gatt-client.c:unregister_descriptor() Removing GATT descriptor: >> /org/bluez/hci0/dev_LEFQAU/service000c/char000d/desc000f >> 11/12,060343.893 bluez: bluetoothd[3980]: >> src/device.c:gatt_service_removed() start: 0x0010, end: 0x0022 >> 11/12,060343.894 bluez: bluetoothd[3980]: >> src/service.c:change_state() 0x53dce8: device LEFQAU profile >> deviceinfo state changed: connecting -> disconnected (-130) >> 11/12,060343.895 bluez: bluetoothd[3980]: >> src/device.c:device_profile_connected() deviceinfo Software caused >> connection abort (130) >> 11/12,060343.898 bluez: bluetoothd[3980]: >> src/service.c:change_state() 0x53dce8: device LEFQAU profile >> deviceinfo state changed: disconnected -> unavailable (0) >> 11/12,060343.898 bluez: bluetoothd[3980]: >> src/service.c:btd_service_unref() 0x53dce8: ref=0 >> 11/12,060343.902 bluez: bluetoothd[3980]: >> src/gatt-client.c:btd_gatt_client_service_removed() GATT Services >> Removed - start: 0x0010, end: 0x0022 >> 11/12,060343.905 bluez: bluetoothd[3980]: >> src/gatt-client.c:unregister_service() Removing GATT service: >> /org/bluez/hci0/dev_LEFQAU/service0010 >> 11/12,060343.906 bluez: bluetoothd[3980]: >> src/gatt-client.c:unregister_characteristic() Removing GATT >> characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0011 >> 11/12,060343.910 bluez: bluetoothd[3980]: >> src/gatt-client.c:unregister_characteristic() Removing GATT >> characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0013 >> 11/12,060343.914 bluez: bluetoothd[3980]: >> src/gatt-client.c:unregister_characteristic() Removing GATT >> characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0015 >> 11/12,060343.920 bluez: bluetoothd[3980]: >> src/gatt-client.c:unregister_characteristic() Removing GATT >> characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0017 >> 11/12,060343.922 bluez: bluetoothd[3980]: >> src/gatt-client.c:unregister_characteristic() Removing GATT >> characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0019 >> 11/12,060343.926 bluez: bluetoothd[3980]: >> src/gatt-client.c:unregister_characteristic() Removing GATT >> characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char001b >> 11/12,060343.940 bluez: bluetoothd[3980]: >> src/gatt-client.c:unregister_characteristic() Removing GATT >> characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char001d >> 11/12,060343.941 bluez: bluetoothd[3980]: >> src/gatt-client.c:unregister_characteris >> >> 11/12,061849.049 bluez: bluetoothd[3980]: >> src/gatt-client.c:btd_gatt_client_disconnected() Device disconnected. >> Cleaning up. >> 11/12,061849.056 bluez: bluetoothd[3980]: >> attrib/gattrib.c:g_attrib_unref() 0x51c360: g_attrib_unref=0tic() >> Removing GATT characteristic: >> /org/bluez/hci0/dev_LEFQAU/service0010/char001f >> 11/12,060343.942 bluez: bluetoothd[3980]: >> src/gatt-client.c:unregister_characteristic() Removing GATT >> characteristic: /org/bluez/hci0/dev_LEFQAU/service0010/char0021 >> 11/12,060344.021 bluez: bluetoothd[3980]: >> src/device.c:gatt_service_removed() start: 0x0023, end: 0x0028 >> 11/12,060344.022 bluez: bluetoothd[3980]: >> src/service.c:change_state() 0x53dd80: device LEFQAU profile Battery >> state changed: connecting -> disconnected (-130) >> 11/12,060344.023 bluez: bluetoothd[3980]: >> src/device.c:device_profile_connected() Battery Software caused >> connection abort (130) >> 11/12,060344.025 bluez: bluetoothd[3980]: >> src/service.c:change_state() 0x53dd80: device LEFQAU profile Battery >> state changed: disconnected -> unavailable (0) >> 11/12,060344.033 bluez: bluetoothd[3980]: >> profiles/battery/battery.c:batt_remove() BATT path >> /org/bluez/hci0/dev_LEFQAU >> 11/12,060344.036 bluez: bluetoothd[3980]: >> src/service.c:btd_service_unref() 0x53dd80: ref=0 >> 11/12,060344.037 bluez: bluetoothd[3980]: >> src/gatt-client.c:btd_gatt_client_service_removed() GATT Services >> Removed - start: 0x0023, end: 0x0028 >> 11/12,060344.046 bluez: bluetoothd[3980]: Error storing included >> service - can't find it >> 11/12,060344.128 bluez: bluetoothd[3980]: >> src/device.c:gatt_service_removed() start: 0x0029, end: 0x002e >> 11/12,060344.129 bluez: bluetoothd[3980]: >> src/service.c:change_state() 0x53dd08: device LEFQAU profile Scan >> Parameters Client Driver state changed: connecting -> disconnected >> (-130) >> 11/12,060344.129 bluez: bluetoothd[3980]: >> src/device.c:device_profile_connected() Scan Parameters Client Driver >> Software caused connection abort (130) >> 11/12,060344.133 bluez: bluetoothd[3980]: >> src/service.c:change_state() 0x53dd08: device LEFQAU profile Scan >> Parameters Client Driver state changed: disconnected -> unavailable >> (0) >> 11/12,060344.141 bluez: bluetoothd[3980]: >> profiles/scanparam/scan.c:scan_param_remove() GAP profile remove >> (LEFQAU) >> 11/12,060344.145 bluez: bluetoothd[3980]: >> src/service.c:btd_service_unref() 0x53dd08: ref=0 >> 11/12,060344.226 bluez: bluetoothd[3980]: >> src/service.c:btd_service_unref() 0x53dc38: ref=0 >> 11/12,060344.239 bluez: bluetoothd[3980]: >> src/gatt-client.c:btd_gatt_client_service_removed() GATT Services >> Removed - start: 0x002f, end: 0x0037 >> 11/12,060344.247 bluez: bluetoothd[3980]: Error storing included >> service - can't find it >> 11/12,060344.291 bluez: bluetoothd[3980]: >> src/device.c:gatt_service_removed() start: 0x0038, end: 0x005c >> 11/12,060344.292 bluez: bluetoothd[3980]: >> src/service.c:change_state() 0x53d3a0: device LEFQAU profile input-hog >> state changed: connecting -> disconnected (-130) >> 11/12,060344.293 bluez: bluetoothd[3980]: >> src/device.c:device_profile_connected() input-hog Software caused >> connection abort (130) >> 11/12,060344.293 bluez: bluetoothd[3980]: >> src/service.c:change_state() 0x53d3a0: device LEFQAU profile input-hog >> state changed: disconnected -> unavailable (0) >> 11/12,060344.296 bluez: bluetoothd[3980]: >> profiles/input/hog.c:hog_remove() path /org/bluez/hci0/dev_LEFQAU >> 11/12,060344.313 bluez: bluetoothd[3980]: >> src/service.c:btd_service_unref() 0x53d3a0: ref=0 >> 11/12,060344.313 bluez: bluetoothd[3980]: >> src/gatt-client.c:btd_gatt_client_service_removed() GATT Services >> Removed - start: 0x0038, end: 0x005c >> 11/12,060344.382 bluez: bluetoothd[3980]: >> src/device.c:gatt_service_removed() start: 0x005d, end: 0x0070 >> 11/12,060344.383 bluez: bluetoothd[3980]: >> src/gatt-client.c:btd_gatt_client_service_removed() GATT Services >> Removed - start: 0x005d, end: 0x0070 >> 11/12,060344.575 bluez: bluetoothd[3980]: >> src/device.c:device_svc_resolved() /org/bluez/hci0/dev_LEFQAU err 0 >> 11/12,060344.584 bluez: bluetoothd[3980]: src/device.c:att_disconnected_cb() >> 11/12,060344.591 bluez: bluetoothd[3980]: >> src/device.c:att_disconnected_cb() Connection reset by peer (131) >> >> So, if we can somehow avoid removing the GATT services of the remote >> in this scenario, it would be a big usability win. Next reconnect >> attempt would just work, since the services would be left in >> disconnected state. >> >> -- Petri > > Just found a bug in src/shared/gatt-client.c: discover_primary_cb() > > if (!success) { > util_debug(client->debug_callback, client->debug_data, > "Primary service discovery failed." > " ATT ECODE: 0x%02x", att_ecode); > /* Reset error in case of not found */ > if (BT_ATT_ERROR_ATTRIBUTE_NOT_FOUND) { > success = true; > att_ecode = 0; > } > goto secondary; > } > > The second if-statement: > if (BT_ATT_ERROR_ATTRIBUTE_NOT_FOUND) Yep, this needs fixing. > should be: > if (att_ecode == BT_ATT_ERROR_ATTRIBUTE_NOT_FOUND) > > Furthermore, looking at my own failure log: > bluez: bluetoothd[3980]: src/device.c:gatt_debug() Primary service > discovery failed. ATT ECODE: 0x00 This is own purpose since it was a local failure it shouldn't set the att_ecode. > Perhaps the if-statement should be: > if (att_ecode == 0 || att_ecode == BT_ATT_ERROR_ATTRIBUTE_NOT_FOUND) { > success = true; > att_ecode = 0; > goto secondary; > } else { > goto done; > } > > Similar adjustment for att_ecode == 0 might be needed for > discover_secondary_cb(). -- Luiz Augusto von Dentz ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect 2016-11-30 22:15 ` Petri Gynther 2016-11-30 22:55 ` Petri Gynther @ 2016-12-01 8:21 ` Luiz Augusto von Dentz 2016-12-01 21:12 ` Petri Gynther 1 sibling, 1 reply; 16+ messages in thread From: Luiz Augusto von Dentz @ 2016-12-01 8:21 UTC (permalink / raw) To: Petri Gynther; +Cc: linux-bluetooth Hi Petri, On Thu, Dec 1, 2016 at 12:15 AM, Petri Gynther <pgynther@google.com> wrote: > Hi Luiz, > > On Wed, Nov 30, 2016 at 1:37 AM, Luiz Augusto von Dentz > <luiz.dentz@gmail.com> wrote: >> Hi Petri, >> >> On Wed, Nov 30, 2016 at 10:36 AM, Luiz Augusto von Dentz >> <luiz.dentz@gmail.com> wrote: >>> Hi Petri, >>>> >>>> This primary services re-discovery on every reconnect is actually now >>>> causing a problem for us. >>>> >>>> Basically, this is what happens: >>>> 1. HoG remote control reconnects to BlueZ host for firmware update check. >>>> 2. BlueZ starts re-discovering the services of the remote, but doesn't >>>> yet complete it. >>>> 3. The remote disconnects after being connected for 2 seconds (no >>>> firmware update was available, so quickly disconnect to save battery). >>>> 4. BlueZ declares the HoG remote "bad" since it couldn't complete step >>>> (2). And then, BlueZ ends up removing the HoG remote services from its >>>> GATT database completely. >>>> 5. On the next reconnect attempt, the remote does not work. Re-pairing >>>> is required. >>>> >>>> Obviously, this is bad for user experience. Therefore, I'm asking: >>>> 1. Is there a way to avoid services re-discovery on every reconnect? >>>> 2. If the remote control is successfully bonded previously, and BlueZ >>>> experiences a problem during reconnect (services re-discovery), can we >>>> avoid destroying the bonding and GATT info on BlueZ side? A failed >>>> reconnect should not be a reason to remove a bonded device. >>> >>> The second point should definitely be fixed, but I wonder how the >>> firmware update check does actually detects if the host is not doing >>> something important before it decides it has to save power. Also if I >>> recall this correctly dfu was exactly why some devices needed the >>> database check, they boot in dfu mode which has a different database >>> but they completely lost the state of service changed subscriptions so >>> basically nothing works since all handles are invalid and even if >>> service changed would work it would cause a rediscover anyway. >> >> Checking the code I did not find anything that could have break the >> remote services, or perhaps it is the passive scanning/reconnection >> logic that gets broken if we failed to discover the services? >> > 11/12,060343.698 bluez: bluetoothd[3980]: src/device.c:gatt_debug() > Primary service discovery failed. ATT ECODE: 0x00 There is something wrong with your setup then, here it reconnect just fine: https://paste.fedoraproject.org/494521/58036114/ But I do agree that we should not reset the db if that was populated already, so I will try to fix that. ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect 2016-12-01 8:21 ` Luiz Augusto von Dentz @ 2016-12-01 21:12 ` Petri Gynther 2016-12-02 11:56 ` Luiz Augusto von Dentz 0 siblings, 1 reply; 16+ messages in thread From: Petri Gynther @ 2016-12-01 21:12 UTC (permalink / raw) To: Luiz Augusto von Dentz; +Cc: linux-bluetooth Hi Luiz, On Thu, Dec 1, 2016 at 12:21 AM, Luiz Augusto von Dentz <luiz.dentz@gmail.com> wrote: > Hi Petri, > > On Thu, Dec 1, 2016 at 12:15 AM, Petri Gynther <pgynther@google.com> wrote: >> Hi Luiz, >> >> On Wed, Nov 30, 2016 at 1:37 AM, Luiz Augusto von Dentz >> <luiz.dentz@gmail.com> wrote: >>> Hi Petri, >>> >>> On Wed, Nov 30, 2016 at 10:36 AM, Luiz Augusto von Dentz >>> <luiz.dentz@gmail.com> wrote: >>>> Hi Petri, >>>>> >>>>> This primary services re-discovery on every reconnect is actually now >>>>> causing a problem for us. >>>>> >>>>> Basically, this is what happens: >>>>> 1. HoG remote control reconnects to BlueZ host for firmware update check. >>>>> 2. BlueZ starts re-discovering the services of the remote, but doesn't >>>>> yet complete it. >>>>> 3. The remote disconnects after being connected for 2 seconds (no >>>>> firmware update was available, so quickly disconnect to save battery). >>>>> 4. BlueZ declares the HoG remote "bad" since it couldn't complete step >>>>> (2). And then, BlueZ ends up removing the HoG remote services from its >>>>> GATT database completely. >>>>> 5. On the next reconnect attempt, the remote does not work. Re-pairing >>>>> is required. >>>>> >>>>> Obviously, this is bad for user experience. Therefore, I'm asking: >>>>> 1. Is there a way to avoid services re-discovery on every reconnect? >>>>> 2. If the remote control is successfully bonded previously, and BlueZ >>>>> experiences a problem during reconnect (services re-discovery), can we >>>>> avoid destroying the bonding and GATT info on BlueZ side? A failed >>>>> reconnect should not be a reason to remove a bonded device. >>>> >>>> The second point should definitely be fixed, but I wonder how the >>>> firmware update check does actually detects if the host is not doing >>>> something important before it decides it has to save power. Also if I >>>> recall this correctly dfu was exactly why some devices needed the >>>> database check, they boot in dfu mode which has a different database >>>> but they completely lost the state of service changed subscriptions so >>>> basically nothing works since all handles are invalid and even if >>>> service changed would work it would cause a rediscover anyway. >>> >>> Checking the code I did not find anything that could have break the >>> remote services, or perhaps it is the passive scanning/reconnection >>> logic that gets broken if we failed to discover the services? >>> >> 11/12,060343.698 bluez: bluetoothd[3980]: src/device.c:gatt_debug() >> Primary service discovery failed. ATT ECODE: 0x00 > > There is something wrong with your setup then, here it reconnect just fine: > > https://paste.fedoraproject.org/494521/58036114/ > Thanks for sharing the above. Here is the first reconnect attempt from our remote after the services had been removed on previous failure: 11/12,061843.757 bluez: bluetoothd[3980]: src/gatt-database.c:connect_cb() New incoming LE ATT connection 11/12,061843.757 bluez: bluetoothd[3980]: src/device.c:device_attach_att() Elevating security level since LTK is available 11/12,061843.780 bluez: bluetoothd[3980]: attrib/gattrib.c:g_attrib_ref() 0x51c360: g_attrib_ref=1 11/12,061843.780 bluez: bluetoothd[3980]: src/gatt-client.c:btd_gatt_client_connected() Device connected. 11/12,061843.780 bluez: bluetoothd[3980]: src/device.c:load_gatt_db() Restoring LEFQAU gatt database from file 11/12,061843.783 bluez: bluetoothd[3980]: No cache for LEFQAU 11/12,061843.944 bluez: bluetoothd[3980]: src/device.c:gatt_debug() MTU exchange complete, with MTU: 23 11/12,061846.226 bluez: bluetoothd[3980]: src/device.c:gatt_debug() Primary services found: 9 11/12,061846.226 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0001, end: 0x000b, uuid: 00001800-0000-1000-8000-00805f9b34fb 11/12,061846.227 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x000c, end: 0x000f, uuid: 00001801-0000-1000-8000-00805f9b34fb 11/12,061846.227 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0010, end: 0x0022, uuid: 0000180a-0000-1000-8000-00805f9b34fb 11/12,061846.230 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0023, end: 0x0028, uuid: 0000180f-0000-1000-8000-00805f9b34fb 11/12,061846.230 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0029, end: 0x002e, uuid: 00001813-0000-1000-8000-00805f9b34fb 11/12,061846.230 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x002f, end: 0x0037, uuid: 0000fff0-0000-1000-8000-00805f9b34fb 11/12,061846.230 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0038, end: 0x005c, uuid: 00001812-0000-1000-8000-00805f9b34fb 11/12,061846.230 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x005d, end: 0x0070, uuid: f000fef0-0451-4000-b000-000000000000 11/12,061846.232 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0071, end: 0xffff, uuid: f000ffc0-0451-4000-b000-000000000000 11/12,061846.757 bluez: bluetoothd[3980]: src/device.c:gatt_debug() Secondary service discovery failed. ATT ECODE: 0x10 11/12,061847.497 bluez: bluetoothd[3980]: src/device.c:gatt_debug() Included services found: 1 11/12,061847.497 bluez: bluetoothd[3980]: src/device.c:gatt_debug() handle: 0x0039, start: 0x0023, end: 0x0028,uuid: 0000180f-0000-1000-8000-0080 11/12,061847.644 bluez: bluetoothd[3980]: src/device.c:gatt_debug() Characteristics found: 5 11/12,061847.644 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0002, end: 0x0003, value: 0x0003, props: 0x02, uuid: 00002a00-0000-1 11/12,061847.646 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0004, end: 0x0005, value: 0x0005, props: 0x02, uuid: 00002a01-0000-1 11/12,061847.646 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0006, end: 0x0007, value: 0x0007, props: 0x0a, uuid: 00002a02-0000-1 11/12,061847.648 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0008, end: 0x0009, value: 0x0009, props: 0x08, uuid: 00002a03-0000-1 11/12,061847.648 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x000a, end: 0x000b, value: 0x000b, props: 0x02, uuid: 00002a04-0000-1 11/12,061847.715 bluez: bluetoothd[3980]: src/device.c:gatt_debug() Characteristics found: 1 11/12,061847.715 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x000d, end: 0x000f, value: 0x000e, props: 0x20, uuid: 00002a05-0000-1 11/12,061847.735 bluez: bluetoothd[3980]: src/device.c:gatt_debug() Descriptors found: 1 11/12,061847.735 bluez: bluetoothd[3980]: src/device.c:gatt_debug() handle: 0x000f, uuid: 00002902-0000-1000-8000-00805f9b34fb 11/12,061847.871 bluez: bluetoothd[3980]: src/device.c:gatt_debug() Characteristics found: 9 11/12,061847.871 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0011, end: 0x0012, value: 0x0012, props: 0x02, uuid: 00002a23-0000-1 11/12,061847.871 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0013, end: 0x0014, value: 0x0014, props: 0x02, uuid: 00002a24-0000-1 11/12,061847.874 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0015, end: 0x0016, value: 0x0016, props: 0x02, uuid: 00002a25-0000-1 11/12,061847.874 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0017, end: 0x0018, value: 0x0018, props: 0x02, uuid: 00002a26-0000-1 11/12,061847.878 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0019, end: 0x001a, value: 0x001a, props: 0x02, uuid: 00002a27-0000-1 11/12,061847.886 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x001b, end: 0x001c, value: 0x001c, props: 0x02, uuid: 00002a28-0000-1 11/12,061847.887 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x001d, end: 0x001e, value: 0x001e, props: 0x02, uuid: 00002a29-0000-1 11/12,061847.888 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x001f, end: 0x0020, value: 0x0020, props: 0x02, uuid: 00002a2a-0000-1 11/12,061847.890 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0021, end: 0x0022, value: 0x0022, props: 0x02, uuid: 00002a50-0000-1 11/12,061848.426 bluez: bluetoothd[3980]: src/device.c:gatt_debug() Characteristics found: 1 11/12,061848.426 bluez: bluetoothd[3980]: src/device.c:gatt_debug() start: 0x0024, end: 0x0028, value: 0x0025, props: 0x12, uuid: 00002a19-0000-1 ==== again here, early disconnect from remote side ==== 11/12,061848.999 bluez: bluetoothd[3980]: src/adapter.c:dev_disconnected() Device LEFQAU disconnected, reason 3 11/12,061848.999 bluez: bluetoothd[3980]: src/adapter.c:dev_disconnected() device 0x522c18 paired 1 bonded 1 bonding 0 11/12,061848.999 bluez: bluetoothd[3980]: src/adapter.c:adapter_remove_connection() 11/12,061848.999 bluez: bluetoothd[3980]: plugins/policy.c:disconnect_cb() reason 3 11/12,061848.999 bluez: bluetoothd[3980]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr LEFQAU type 1 status 0xe 11/12,061849.000 bluez: bluetoothd[3980]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e 11/12,061849.000 bluez: bluetoothd[3980]: src/device.c:device_bonding_failed() status 14 11/12,061849.001 bluez: bluetoothd[3980]: src/adapter.c:resume_discovery() ==== and again, since the re-discovery of services didn't complete fully, GATT DB gets cleaned ==== 11/12,061849.002 bluez: bluetoothd[3980]: src/device.c:gatt_service_removed() start: 0x0001, end: 0x000b 11/12,061849.003 bluez: bluetoothd[3980]: src/device.c:gatt_service_removed() start: 0x000c, end: 0x000f 11/12,061849.004 bluez: bluetoothd[3980]: src/device.c:gatt_service_removed() start: 0x0010, end: 0x0022 11/12,061849.020 bluez: bluetoothd[3980]: src/device.c:gatt_debug() Failed to initialize gatt-client 11/12,061849.021 bluez: bluetoothd[3980]: src/device.c:gatt_client_ready_cb() status: failed, error: 0 11/12,061849.021 bluez: bluetoothd[3980]: src/device.c:device_svc_resolved() /org/bluez/hci0/dev_LEFQAU err -5 11/12,061849.027 bluez: bluetoothd[3980]: src/device.c:att_disconnected_cb() 11/12,061849.032 bluez: bluetoothd[3980]: src/device.c:att_disconnected_cb() Connection reset by peer (131) 11/12,061849.049 bluez: bluetoothd[3980]: src/gatt-client.c:btd_gatt_client_disconnected() Device disconnected. Cleaning up. 11/12,061849.056 bluez: bluetoothd[3980]: attrib/gattrib.c:g_attrib_unref() 0x51c360: g_attrib_unref=0 However, in this case, I think this handling is correct. load_gatt_db() showed "No cache for LEFQAU", so BlueZ has to re-discover everything from the device over BLE. But, since the device disconnected in the middle of discovery, BlueZ couldn't fully populate the GATT DB and has to clean it. If the device didn't disconnect so quickly, this would have most likely worked. > But I do agree that we should not reset the db if that was populated > already, so I will try to fix that. Yes, once BlueZ does not reset the GATT DB on failed reconnects, this problem will be solved. ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect 2016-12-01 21:12 ` Petri Gynther @ 2016-12-02 11:56 ` Luiz Augusto von Dentz 2016-12-08 21:52 ` Petri Gynther 0 siblings, 1 reply; 16+ messages in thread From: Luiz Augusto von Dentz @ 2016-12-02 11:56 UTC (permalink / raw) To: Petri Gynther; +Cc: linux-bluetooth Hi Petri, On Thu, Dec 1, 2016 at 11:12 PM, Petri Gynther <pgynther@google.com> wrote: > However, in this case, I think this handling is correct. > load_gatt_db() showed "No cache for LEFQAU", so BlueZ has to > re-discover everything from the device over BLE. > But, since the device disconnected in the middle of discovery, BlueZ > couldn't fully populate the GATT DB and has to clean it. > If the device didn't disconnect so quickly, this would have most likely worked. > >> But I do agree that we should not reset the db if that was populated >> already, so I will try to fix that. > > Yes, once BlueZ does not reset the GATT DB on failed reconnects, this > problem will be solved. Please check if everything is alright when using upstream, it should clear the database anymore if we get an early disconnect. -- Luiz Augusto von Dentz ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect 2016-12-02 11:56 ` Luiz Augusto von Dentz @ 2016-12-08 21:52 ` Petri Gynther 2016-12-09 8:43 ` José Bollo 0 siblings, 1 reply; 16+ messages in thread From: Petri Gynther @ 2016-12-08 21:52 UTC (permalink / raw) To: Luiz Augusto von Dentz; +Cc: linux-bluetooth Hi Luiz, On Fri, Dec 2, 2016 at 3:56 AM, Luiz Augusto von Dentz <luiz.dentz@gmail.com> wrote: > Hi Petri, > > On Thu, Dec 1, 2016 at 11:12 PM, Petri Gynther <pgynther@google.com> wrote: >> However, in this case, I think this handling is correct. >> load_gatt_db() showed "No cache for LEFQAU", so BlueZ has to >> re-discover everything from the device over BLE. >> But, since the device disconnected in the middle of discovery, BlueZ >> couldn't fully populate the GATT DB and has to clean it. >> If the device didn't disconnect so quickly, this would have most likely worked. >> >>> But I do agree that we should not reset the db if that was populated >>> already, so I will try to fix that. >> >> Yes, once BlueZ does not reset the GATT DB on failed reconnects, this >> problem will be solved. > > Please check if everything is alright when using upstream, it should > clear the database anymore if we get an early disconnect. I applied my 2 patches and your 2 patches on top of 5.43. GATT DB is no longer destroyed on reconnection errors, so that's excellent. However, we are still seeing reconnect problems, but not GATT DB related: bluez: bluetoothd[17780]: src/gatt-client.c:btd_gatt_client_connected() Device connected. bluez: bluetoothd[17780]: profiles/gap/gas.c:read_device_name_cb() Reading device name failed with ATT error: 0 bluez: bluetoothd[17780]: profiles/gap/gas.c:read_appearance_cb() Reading appearance failed with ATT error: 0 bluez: bluetoothd[17780]: Error reading PNP_ID value: Unexpected error code bluez: bluetoothd[17780]: BATT level_read_char_cb failed: Request attribute has encountered an unlikely error We are still investigating this. Likely a firmware issue on the remote. > > > -- > Luiz Augusto von Dentz ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect 2016-12-08 21:52 ` Petri Gynther @ 2016-12-09 8:43 ` José Bollo 2016-12-09 17:38 ` Petri Gynther 0 siblings, 1 reply; 16+ messages in thread From: José Bollo @ 2016-12-09 8:43 UTC (permalink / raw) To: Petri Gynther; +Cc: Luiz Augusto von Dentz, linux-bluetooth Hi Petri, This is perhaps related to the question I asked yesterday. Where can I find your 4 patches? Best regards Jos=C3=A9 Bollo Jos=C3=A9 Bollo - Senior Software Engineer www.iot.bzh 2016-12-08 22:52 GMT+01:00 Petri Gynther <pgynther@google.com>: > Hi Luiz, > > On Fri, Dec 2, 2016 at 3:56 AM, Luiz Augusto von Dentz > <luiz.dentz@gmail.com> wrote: >> Hi Petri, >> >> On Thu, Dec 1, 2016 at 11:12 PM, Petri Gynther <pgynther@google.com> wro= te: >>> However, in this case, I think this handling is correct. >>> load_gatt_db() showed "No cache for LEFQAU", so BlueZ has to >>> re-discover everything from the device over BLE. >>> But, since the device disconnected in the middle of discovery, BlueZ >>> couldn't fully populate the GATT DB and has to clean it. >>> If the device didn't disconnect so quickly, this would have most likely= worked. >>> >>>> But I do agree that we should not reset the db if that was populated >>>> already, so I will try to fix that. >>> >>> Yes, once BlueZ does not reset the GATT DB on failed reconnects, this >>> problem will be solved. >> >> Please check if everything is alright when using upstream, it should >> clear the database anymore if we get an early disconnect. > > I applied my 2 patches and your 2 patches on top of 5.43. > > GATT DB is no longer destroyed on reconnection errors, so that's excellen= t. > > However, we are still seeing reconnect problems, but not GATT DB related: > bluez: bluetoothd[17780]: > src/gatt-client.c:btd_gatt_client_connected() Device connected. > bluez: bluetoothd[17780]: profiles/gap/gas.c:read_device_name_cb() > Reading device name failed with ATT error: 0 > bluez: bluetoothd[17780]: profiles/gap/gas.c:read_appearance_cb() > Reading appearance failed with ATT error: 0 > bluez: bluetoothd[17780]: Error reading PNP_ID value: Unexpected error co= de > bluez: bluetoothd[17780]: BATT level_read_char_cb failed: Request > attribute has encountered an unlikely error > > We are still investigating this. Likely a firmware issue on the remote. > >> >> >> -- >> Luiz Augusto von Dentz > -- > To unsubscribe from this list: send the line "unsubscribe linux-bluetooth= " in > the body of a message to majordomo@vger.kernel.org > More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply [flat|nested] 16+ messages in thread
* Re: BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect 2016-12-09 8:43 ` José Bollo @ 2016-12-09 17:38 ` Petri Gynther 0 siblings, 0 replies; 16+ messages in thread From: Petri Gynther @ 2016-12-09 17:38 UTC (permalink / raw) To: jose.bollo; +Cc: Luiz Augusto von Dentz, linux-bluetooth Hi Jos=C3=A9, On Fri, Dec 9, 2016 at 12:43 AM, Jos=C3=A9 Bollo <jose.bollo@iot.bzh> wrote= : > Hi Petri, > > This is perhaps related to the question I asked yesterday. > Where can I find your 4 patches? > The patches are already applied on upstream BlueZ: shared/gatt-client: Fix discover_primary_cb() shared/gatt-client: Fix discover_secondary_cb() shared/gatt-db: Make gatt_db_clear call gatt_db_clear_range shared/gatt-client: Don't clear db in case of errors > Best regards > Jos=C3=A9 Bollo > Jos=C3=A9 Bollo - Senior Software Engineer > www.iot.bzh > > > > 2016-12-08 22:52 GMT+01:00 Petri Gynther <pgynther@google.com>: >> Hi Luiz, >> >> On Fri, Dec 2, 2016 at 3:56 AM, Luiz Augusto von Dentz >> <luiz.dentz@gmail.com> wrote: >>> Hi Petri, >>> >>> On Thu, Dec 1, 2016 at 11:12 PM, Petri Gynther <pgynther@google.com> wr= ote: >>>> However, in this case, I think this handling is correct. >>>> load_gatt_db() showed "No cache for LEFQAU", so BlueZ has to >>>> re-discover everything from the device over BLE. >>>> But, since the device disconnected in the middle of discovery, BlueZ >>>> couldn't fully populate the GATT DB and has to clean it. >>>> If the device didn't disconnect so quickly, this would have most likel= y worked. >>>> >>>>> But I do agree that we should not reset the db if that was populated >>>>> already, so I will try to fix that. >>>> >>>> Yes, once BlueZ does not reset the GATT DB on failed reconnects, this >>>> problem will be solved. >>> >>> Please check if everything is alright when using upstream, it should >>> clear the database anymore if we get an early disconnect. >> >> I applied my 2 patches and your 2 patches on top of 5.43. >> >> GATT DB is no longer destroyed on reconnection errors, so that's excelle= nt. >> >> However, we are still seeing reconnect problems, but not GATT DB related= : >> bluez: bluetoothd[17780]: >> src/gatt-client.c:btd_gatt_client_connected() Device connected. >> bluez: bluetoothd[17780]: profiles/gap/gas.c:read_device_name_cb() >> Reading device name failed with ATT error: 0 >> bluez: bluetoothd[17780]: profiles/gap/gas.c:read_appearance_cb() >> Reading appearance failed with ATT error: 0 >> bluez: bluetoothd[17780]: Error reading PNP_ID value: Unexpected error c= ode >> bluez: bluetoothd[17780]: BATT level_read_char_cb failed: Request >> attribute has encountered an unlikely error >> >> We are still investigating this. Likely a firmware issue on the remote. >> >>> >>> >>> -- >>> Luiz Augusto von Dentz >> -- >> To unsubscribe from this list: send the line "unsubscribe linux-bluetoot= h" in >> the body of a message to majordomo@vger.kernel.org >> More majordomo info at http://vger.kernel.org/majordomo-info.html ^ permalink raw reply [flat|nested] 16+ messages in thread
end of thread, other threads:[~2016-12-09 17:38 UTC | newest]
Thread overview: 16+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2016-11-09 19:39 BlueZ 5.43: HoG peripheral services re-discovered again and again on every reconnect Petri Gynther
2016-11-10 14:17 ` Luiz Augusto von Dentz
2016-11-11 2:42 ` Petri Gynther
2016-11-11 9:07 ` Luiz Augusto von Dentz
[not found] ` <CAGXr9JET_-mB1qtOryXpUMhQPTe_ecw84f4kFH+Wv9_WYp3iog@mail.gmail.com>
2016-11-29 23:15 ` Petri Gynther
2016-11-30 8:36 ` Luiz Augusto von Dentz
2016-11-30 9:37 ` Luiz Augusto von Dentz
2016-11-30 22:15 ` Petri Gynther
2016-11-30 22:55 ` Petri Gynther
2016-12-01 7:54 ` Luiz Augusto von Dentz
2016-12-01 8:21 ` Luiz Augusto von Dentz
2016-12-01 21:12 ` Petri Gynther
2016-12-02 11:56 ` Luiz Augusto von Dentz
2016-12-08 21:52 ` Petri Gynther
2016-12-09 8:43 ` José Bollo
2016-12-09 17:38 ` Petri Gynther
This is a public inbox, see mirroring instructions for how to clone and mirror all data and code used for this inbox; as well as URLs for NNTP newsgroup(s).