hcitrace-dory-asteroidossync-20-Nov-2017-nightly-build

hcitrace.txt

@ New Settings: 0x0a11
            powered bondable le secure-conn 
> HCI Event: LE Meta Event (0x3e) plen 19                  #73 [hci0] 77.819918
      LE Connection Complete (0x01)
        Status: Success (0x00)
        Handle: 64
        Role: Slave (0x01)
        Peer address type: Random (0x01)
        Peer address: 56:51:59:36:F3:53 (Resolvable)
        Connection interval: 50.00 msec (0x0028)
        Connection latency: 0.00 msec (0x0000)
        Supervision timeout: 20010 msec (0x07d1)
        Master clock accuracy: 0x01
@ Device Connected: 56:51:59:36:F3:53 (2) flags 0x0000
< ACL Data TX: Handle 64 flags 0x00 dlen 7                 #74 [hci0] 77.821696
      ATT: Exchange MTU Request (0x02) len 2
        Client RX MTU: 517
> ACL Data RX: Handle 64 flags 0x02 dlen 11                #75 [hci0] 77.980894
      SMP: Pairing Request (0x01) len 6
        IO capability: KeyboardDisplay (0x04)
        OOB data: Authentication data not present (0x00)
        Authentication requirement: Bonding, MITM, SC, No Keypresses (0x0d)
        Max encryption key size: 16
        Initiator key distribution: EncKey IdKey Sign LinkKey (0x0f)
        Responder key distribution: EncKey IdKey Sign LinkKey (0x0f)
< ACL Data TX: Handle 64 flags 0x00 dlen 11                #76 [hci0] 77.981110
      SMP: Pairing Response (0x02) len 6
        IO capability: DisplayYesNo (0x01)
        OOB data: Authentication data not present (0x00)
        Authentication requirement: Bonding, MITM, SC, No Keypresses (0x0d)
        Max encryption key size: 16
        Initiator key distribution: EncKey IdKey Sign (0x07)
        Responder key distribution: EncKey Sign (0x05)
> ACL Data RX: Handle 64 flags 0x02 dlen 7                 #77 [hci0] 78.030212
      ATT: Exchange MTU Response (0x03) len 2
        Server RX MTU: 517
< ACL Data TX: Handle 64 flags 0x00 dlen 11                #78 [hci0] 78.030842
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0001-0xffff
        Attribute group type: Primary Service (0x2800)
> HCI Event: Number of Completed Packets (0x13) plen 5     #79 [hci0] 78.175498
        Num handles: 1
        Handle: 64
        Count: 1
> ACL Data RX: Handle 64 flags 0x02 dlen 24                #80 [hci0] 78.182006
> ACL Data RX: Handle 64 flags 0x01 dlen 24                #81 [hci0] 78.231959
> ACL Data RX: Handle 64 flags 0x01 dlen 21                #82 [hci0] 78.282582
      SMP: Pairing Public Key (0x0c) len 64
        X: 15bcdb2f8ec14cd5509116208b84c207db0e81687f36d4e8f05d002caafc39d1
        Y: 6c54c855ce5652078bcd9e95366135445635bd3ed996f3b25afb2f7b728107d4
> HCI Event: Number of Completed Packets (0x13) plen 5     #83 [hci0] 78.282596
        Num handles: 1
        Handle: 64
        Count: 2
< ACL Data TX: Handle 64 flags 0x00 dlen 27                #84 [hci0] 78.302083
< ACL Data TX: Handle 64 flags 0x01 dlen 27                #85 [hci0] 78.302108
< ACL Data TX: Handle 64 flags 0x01 dlen 15                #86 [hci0] 78.302128
      SMP: Pairing Public Key (0x0c) len 64
        X: 439e430c170d442e8a65cf719800b91a1eed8a388a379e8e8bb50a125ed285e4
        Y: f864ac9813d9de96bdcb119ea922854dd84eb668e43ff1736d1408d1945a64fa
< ACL Data TX: Handle 64 flags 0x00 dlen 21                #87 [hci0] 78.302137
      SMP: Pairing Confirm (0x03) len 16
        Confim value: b509ee1203f6db107442d99a9eecdf7b
> ACL Data RX: Handle 64 flags 0x02 dlen 18                #88 [hci0] 78.331436
      ATT: Read By Group Type Response (0x11) len 13
        Attribute data length: 6
        Attribute group list: 2 entries
        Handle range: 0x0001-0x0005
        UUID: Generic Attribute Profile (0x1801)
        Handle range: 0x0014-0xffff
        UUID: Generic Access Profile (0x1800)
< ACL Data TX: Handle 64 flags 0x00 dlen 11                #89 [hci0] 78.332507
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0001-0xffff
        Attribute group type: Secondary Service (0x2801)
> HCI Event: Number of Completed Packets (0x13) plen 5     #90 [hci0] 78.434438
        Num handles: 1
        Handle: 64
        Count: 2
> HCI Event: Number of Completed Packets (0x13) plen 5     #91 [hci0] 78.434452
        Num handles: 1
        Handle: 64
        Count: 2
> HCI Event: LE Meta Event (0x3e) plen 10                  #92 [hci0] 78.434454
      LE Connection Update Complete (0x03)
        Status: Success (0x00)
        Handle: 64
        Connection interval: 7.50 msec (0x0006)
        Connection latency: 0.00 msec (0x0000)
        Supervision timeout: 20010 msec (0x07d1)
> HCI Event: Number of Completed Packets (0x13) plen 5     #93 [hci0] 81.545287
        Num handles: 1
        Handle: 64
        Count: 1
> ACL Data RX: Handle 64 flags 0x02 dlen 9                 #94 [hci0] 86.882368
      ATT: Error Response (0x01) len 4
        Read By Group Type Request (0x10)
        Handle: 0x0001
        Error: Unsupported Group Type (0x10)
< ACL Data TX: Handle 64 flags 0x00 dlen 11                #95 [hci0] 86.882940
      ATT: Read By Type Request (0x08) len 6
        Handle range: 0x0001-0xffff
        Attribute type: Include (0x2802)
> ACL Data RX: Handle 64 flags 0x02 dlen 11                #96 [hci0] 92.432064
      ATT: Read By Type Request (0x08) len 6
        Handle range: 0x0001-0xffff
        Attribute type: Device Name (0x2a00)
< ACL Data TX: Handle 64 flags 0x00 dlen 12                #97 [hci0] 92.432780
      ATT: Read By Type Response (0x09) len 7
        Attribute data length: 6
        Attribute data list: 1 entry
        Handle: 0x0003
        Value: 446f7279
> ACL Data RX: Handle 64 flags 0x02 dlen 21                #98 [hci0] 97.982793
      SMP: Pairing Random (0x04) len 16
        Random value: 46829845a554201cdebf9170b05617cf
< ACL Data TX: Handle 64 flags 0x00 dlen 21                #99 [hci0] 97.983162
      SMP: Pairing Random (0x04) len 16
        Random value: bd18d6b3824abd91ce47efd4d40a2cf1
@ User Confirmation Request: 56:51:59:36:F3:53 (2) hint 0 value 97704
> HCI Event: Number of Completed Packets (0x13) plen 5    #100 [hci0] 98.169334
        Num handles: 1
        Handle: 64
        Count: 1
> ACL Data RX: Handle 64 flags 0x02 dlen 9               #101 [hci0] 103.530988
      ATT: Error Response (0x01) len 4
        Read By Type Request (0x08)
        Handle: 0x0001
        Error: Attribute Not Found (0x0a)
< ACL Data TX: Handle 64 flags 0x00 dlen 11              #102 [hci0] 103.531698
      ATT: Read By Type Request (0x08) len 6
        Handle range: 0x0001-0xffff
        Attribute type: Characteristic (0x2803)
> HCI Event: Number of Completed Packets (0x13) plen 5   #103 [hci0] 103.669673
        Num handles: 1
        Handle: 64
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5   #104 [hci0] 109.289254
        Num handles: 1
        Handle: 64
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5   #105 [hci0] 114.782457
        Num handles: 1
        Handle: 64
 

journalctl-debug-bluetoothd.log

Nov 21 16:11:56 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:property_set_mode() sending Set Powered command for index 0
Nov 21 16:11:56 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:property_set_mode_complete() Success (0x00)
Nov 21 16:11:56 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:new_settings_callback() Settings: 0x00000a10
Nov 21 16:11:56 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:settings_changed() Changed settings: 0x00000001
Nov 21 16:11:56 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:cancel_passive_scanning()
Nov 21 16:11:56 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:adapter_stop() adapter /org/bluez/hci0 has been disabled
Nov 21 16:12:00 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:property_set_mode() sending Set Powered command for index 0
Nov 21 16:12:01 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:property_set_mode_complete() Success (0x00)
Nov 21 16:12:01 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:new_settings_callback() Settings: 0x00000a11
Nov 21 16:12:01 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:settings_changed() Changed settings: 0x00000001
Nov 21 16:12:01 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:adapter_start() adapter /org/bluez/hci0 has been enabled
Nov 21 16:12:01 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:trigger_passive_scanning()
Nov 21 16:12:53 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:connected_callback() hci0 device 56:51:59:36:F3:53 connected eir_len 0
Nov 21 16:12:53 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:device_create() dst 56:51:59:36:F3:53
Nov 21 16:12:53 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:device_new() address 56:51:59:36:F3:53
Nov 21 16:12:53 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:device_new() Creating device /org/bluez/hci0/dev_56_51_59_36_F3_53
Nov 21 16:12:53 dory bluetoothd[1109]: ../bluez-5.46/src/gatt-database.c:connect_cb() New incoming LE ATT connection
Nov 21 16:12:53 dory bluetoothd[1109]: ../bluez-5.46/attrib/gattrib.c:g_attrib_ref() 0xe03fa0: g_attrib_ref=1
Nov 21 16:12:53 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:load_gatt_db() Restoring 56:51:59:36:F3:53 gatt database from file
Nov 21 16:12:53 dory bluetoothd[1109]: No cache for 56:51:59:36:F3:53
Nov 21 16:12:53 dory bluetoothd[1109]: ../bluez-5.46/src/gatt-client.c:btd_gatt_client_connected() Device connected.
Nov 21 16:12:54 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:gatt_debug() MTU exchange complete, with MTU: 517
Nov 21 16:12:54 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:gatt_debug() Primary services found: 2
Nov 21 16:12:54 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:gatt_debug() start: 0x0001, end: 0x0005, uuid: 00001801-0000-1000-8000-00805f9b34fb
Nov 21 16:12:54 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:gatt_debug() start: 0x0014, end: 0xffff, uuid: 00001800-0000-1000-8000-00805f9b34fb
Nov 21 16:13:02 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:gatt_debug() Secondary service discovery failed. ATT ECODE: 0x10
Nov 21 16:13:08 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:gatt_debug() Read By Type - start: 0x0001 end: 0xffff
Nov 21 16:13:08 dory bluetoothd[1109]: ../bluez-5.46/src/gatt-database.c:gap_device_name_read_cb() GAP Device Name read request
Nov 21 16:13:13 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:user_confirm_request_callback() hci0 56:51:59:36:F3:53 confirm_hint 0
Nov 21 16:13:13 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:new_auth() Requesting agent authentication for 56:51:59:36:F3:53
Nov 21 16:13:13 dory bluetoothd[1109]: ../bluez-5.46/src/agent.c:agent_ref() 0xe19518: ref=2
Nov 21 16:13:13 dory bluetoothd[1109]: ../bluez-5.46/src/agent.c:agent_request_confirmation() Calling Agent.RequestConfirmation: name=:1.38, path=/org/asteroidos/launcher/agent, passkey=097704
Nov 21 16:13:49 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:att_disconnected_cb()
Nov 21 16:13:49 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:att_disconnected_cb() Success (0)
Nov 21 16:13:49 dory bluetoothd[1109]: ../bluez-5.46/src/gatt-client.c:btd_gatt_client_disconnected() Device disconnected. Cleaning up.
Nov 21 16:13:49 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:att_disconnected_cb() Automatic connection disabled
Nov 21 16:13:49 dory bluetoothd[1109]: ../bluez-5.46/attrib/gattrib.c:g_attrib_unref() 0xe03fa0: g_attrib_unref=0
Nov 21 16:13:53 dory bluetoothd[1109]: ../bluez-5.46/src/agent.c:agent_ref() 0xe19518: ref=3
Nov 21 16:13:53 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:btd_adapter_confirm_reply() hci0 addr 56:51:59:36:F3:53 success 1
Nov 21 16:13:53 dory bluetoothd[1109]: ../bluez-5.46/src/agent.c:agent_unref() 0xe19518: ref=2
Nov 21 16:13:53 dory bluetoothd[1109]: ../bluez-5.46/src/agent.c:agent_unref() 0xe19518: ref=1
Nov 21 16:14:01 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:dev_disconnected() Device 56:51:59:36:F3:53 disconnected, reason 0
Nov 21 16:14:01 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:adapter_remove_connection()
Nov 21 16:14:01 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:device_cancel_authentication() Canceling authentication request for 56:51:59:36:F3:53
Nov 21 16:14:01 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:adapter_remove_connection() Removing temporary device /org/bluez/hci0/dev_56_51_59_36_F3_53
Nov 21 16:14:01 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:device_remove() Removing device /org/bluez/hci0/dev_56_51_59_36_F3_53
Nov 21 16:14:01 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:btd_device_unref() Freeing device /org/bluez/hci0/dev_56_51_59_36_F3_53
Nov 21 16:14:01 dory bluetoothd[1109]: ../bluez-5.46/src/device.c:device_free() 0xe1a0b0
Nov 21 16:14:01 dory bluetoothd[1109]: ../bluez-5.46/plugins/policy.c:disconnect_cb() reason 0
Nov 21 16:14:01 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:bonding_attempt_complete() hci0 bdaddr 56:51:59:36:F3:53 type 2 status 0xe
Nov 21 16:14:01 dory bluetoothd[1109]: ../bluez-5.46/src/adapter.c:resume_discovery()

Wireshark capture file:
https://s3-eu-west-1.amazonaws.com/wireshark-bucket/journalctl-debug-bluetoothd-74-105.log

Thank you for your logs! I'll try to give it a look as soon as I'll have some time.