5.41 - Authentication Failed with kernel 4.2.0

5.41 - Authentication Failed with kernel 4.2.0

[Kropf Johannes]

Hi,

we had a problem when attempting to pair low energy devices on Ubuntu with kernel version 4.2.0-42-generic:
After scanning there always occured an "authentication failed" error. 
The devices we tried to pair were a A&D UC-352-BLE weighing scale and a A&D UA-651BLE blood pressure monitor. 
Both devices can be paired on the same machine with the same setup but with kernel version 3.13.0.92. 
Unfortunately the log doesn't give me an idea what the problem is.
 
Here is the output using bluetoothctl:
[bluetooth]# pair 5C:31:3E:5E:54:5E 
Attempting to pair with 5C:31:3E:5E:54:5E
[CHG] Device 5C:31:3E:5E:54:5E Connected: yes
Failed to pair: org.bluez.Error.AuthenticationFailed
[CHG] Device 5C:31:3E:5E:54:5E Connected: no

Bluetoothd debug messages:
bluetoothd[2386]: src/device.c:bonding_request_new() Requesting bonding for 5C:31:3E:5E:54:5E
bluetoothd[2386]: src/adapter.c:suspend_discovery() 
bluetoothd[2386]: src/adapter.c:adapter_bonding_attempt() hci0 bdaddr 5C:31:3E:5E:54:5E type 1 io_cap 0x03
bluetoothd[2386]: src/adapter.c:connected_callback() hci0 device 5C:31:3E:5E:54:5E connected eir_len 0
bluetoothd[2386]: src/gatt-database.c:connect_cb() New incoming LE ATT connection
bluetoothd[2386]: attrib/gattrib.c:g_attrib_ref() 0x1232f40: g_attrib_ref=1 
bluetoothd[2386]: src/gatt-client.c:btd_gatt_client_connected() Device connected.
bluetoothd[2386]: src/device.c:load_gatt_db() Restoring 5C:31:3E:5E:54:5E gatt database from file
bluetoothd[2386]: src/device.c:load_service() loading service: 0x0001, end: 0x000b, uuid: 00001800-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_service() loading service: 0x000c, end: 0x000f, uuid: 00001801-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_service() loading service: 0x0010, end: 0x0017, uuid: 0000181d-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_service() loading service: 0x0018, end: 0x0028, uuid: 0000180a-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_service() loading service: 0x0029, end: 0x002b, uuid: 0000180f-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_service() loading service: 0x002c, end: 0xffff, uuid: 233bf000-5a34-1b6d-975c-000d5690abe4
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x0002, value handle: 0x0003, properties 0x0002 uuid: 00002a00-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x0004, value handle: 0x0005, properties 0x0002 uuid: 00002a01-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x0006, value handle: 0x0007, properties 0x000a uuid: 00002a02-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x0008, value handle: 0x0009, properties 0x0008 uuid: 00002a03-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x000a, value handle: 0x000b, properties 0x0002 uuid: 00002a04-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x000d, value handle: 0x000e, properties 0x0020 uuid: 00002a05-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_desc() loading descriptor handle: 0x000f, value: 0x0000, uuid: 00002902-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x0011, value handle: 0x0012, properties 0x0020 uuid: 00002a9d-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_desc() loading descriptor handle: 0x0013, value: 0x0000, uuid: 00002902-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x0014, value handle: 0x0015, properties 0x0002 uuid: 00002a9e-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x0016, value handle: 0x0017, properties 0x000a uuid: 00002a08-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x0019, value handle: 0x001a, properties 0x0002 uuid: 00002a29-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x001b, value handle: 0x001c, properties 0x0002 uuid: 00002a24-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x001d, value handle: 0x001e, properties 0x0002 uuid: 00002a25-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x001f, value handle: 0x0020, properties 0x0002 uuid: 00002a27-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x0021, value handle: 0x0022, properties 0x0002 uuid: 00002a26-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x0023, value handle: 0x0024, properties 0x0002 uuid: 00002a28-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x0025, value handle: 0x0026, properties 0x0002 uuid: 00002a23-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x0027, value handle: 0x0028, properties 0x0002 uuid: 00002a2a-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x002a, value handle: 0x002b, properties 0x0002 uuid: 00002a19-0000-1000-8000-00805f9b34fb
bluetoothd[2386]: src/device.c:load_chrc() loading characteristic handle: 0x002d, value handle: 0x002e, properties 0x000a uuid: 233bf001-5a34-1b6d-975c-000d5690abe4
bluetoothd[2386]: src/device.c:gatt_debug() MTU exchange complete, with MTU: 23
bluetoothd[2386]: src/adapter.c:pair_device_complete() Authentication Failed (0x05)
bluetoothd[2386]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 5C:31:3E:5E:54:5E type 1 status 0x5
bluetoothd[2386]: src/device.c:device_bonding_complete() bonding 0x12344d0 status 0x05
bluetoothd[2386]: src/device.c:device_bonding_failed() status 5
bluetoothd[2386]: src/adapter.c:resume_discovery() 
bluetoothd[2386]: src/adapter.c:dev_disconnected() Device 5C:31:3E:5E:54:5E disconnected, reason 2
bluetoothd[2386]: src/adapter.c:adapter_remove_connection() 
bluetoothd[2386]: plugins/policy.c:disconnect_cb() reason 2
bluetoothd[2386]: src/adapter.c:bonding_attempt_complete() hci0 bdaddr 5C:31:3E:5E:54:5E type 1 status 0xe
bluetoothd[2386]: src/device.c:device_bonding_complete() bonding (nil) status 0x0e
bluetoothd[2386]: src/device.c:device_bonding_failed() status 14

Kind regards,
Johannes

Re: 5.41 - Authentication Failed with kernel 4.2.0

[Johan Hedberg]

Hi Johannes,

On Mon, Aug 08, 2016, Kropf Johannes wrote:
> we had a problem when attempting to pair low energy devices on Ubuntu with kernel version 4.2.0-42-generic:
> After scanning there always occured an "authentication failed" error. 
> The devices we tried to pair were a A&D UC-352-BLE weighing scale and a A&D UA-651BLE blood pressure monitor. 
> Both devices can be paired on the same machine with the same setup but with kernel version 3.13.0.92. 
> Unfortunately the log doesn't give me an idea what the problem is.
>  
> Here is the output using bluetoothctl:
> [bluetooth]# pair 5C:31:3E:5E:54:5E 
> Attempting to pair with 5C:31:3E:5E:54:5E
> [CHG] Device 5C:31:3E:5E:54:5E Connected: yes
> Failed to pair: org.bluez.Error.AuthenticationFailed
> [CHG] Device 5C:31:3E:5E:54:5E Connected: no

Did you also have an agent registered? (e.g. "agent KeyboardDisplay" in
bluetoothctl)

What would give an even better view of what's going on is the HCI logs.
You can get those with the btmon tool (found under monitor/ in the BlueZ
source tree).

Johan

Re: 5.41 - Authentication Failed with kernel 4.2.0

[Johan Hedberg]

Hi Johannes,

Please don't drop the mailing list from the thread (added it back now).

On Tue, Aug 09, 2016, Kropf Johannes wrote:
> > On Mon, Aug 08, 2016, Kropf Johannes wrote:
> > > we had a problem when attempting to pair low energy devices on Ubuntu
> > with kernel version 4.2.0-42-generic:
> > > After scanning there always occured an "authentication failed" error.
> > > The devices we tried to pair were a A&D UC-352-BLE weighing scale and a
> > A&D UA-651BLE blood pressure monitor.
> > > Both devices can be paired on the same machine with the same setup but
> > with kernel version 3.13.0.92.
> > > Unfortunately the log doesn't give me an idea what the problem is.
> > >
> > > Here is the output using bluetoothctl:
> > > [bluetooth]# pair 5C:31:3E:5E:54:5E
> > > Attempting to pair with 5C:31:3E:5E:54:5E [CHG] Device
> > > 5C:31:3E:5E:54:5E Connected: yes Failed to pair:
> > > org.bluez.Error.AuthenticationFailed
> > > [CHG] Device 5C:31:3E:5E:54:5E Connected: no
> > 
> > Did you also have an agent registered? (e.g. "agent KeyboardDisplay" in
> > bluetoothctl)
> Yes, an agent was registered in bluetoothctl with "agent on"

Ok, good. It shouldn't make a difference for pairings initiated from the
local side, but just in case, did you also issue "default-agent"?

> > What would give an even better view of what's going on is the HCI logs.
> > You can get those with the btmon tool (found under monitor/ in the BlueZ
> > source tree).
> Here is the output of btmon. Does it mean anything to you?
> ....
> < ACL Data TX: Handle 70 flags 0x00 dlen 11                    [hci0] 28.489379
>       ATT: Read By Group Type Request (0x10) len 6
>         Handle range: 0x0018-0xffff
>         Attribute group type: Primary Service (0x2800)
> > HCI Event: Number of Completed Packets (0x13) plen 5         [hci0] 28.559451
>         Num handles: 1
>         Handle: 70
>         Count: 1
> > HCI Event: Number of Completed Packets (0x13) plen 5         [hci0] 28.560451
>         Num handles: 1
>         Handle: 70
>         Count: 1
> > ACL Data RX: Handle 70 flags 0x02 dlen 6                     [hci0] 28.628456
>       SMP: Pairing Failed (0x05) len 1
>         Reason: Confirm value failed (0x04)
> < HCI Command: Disconnect (0x01|0x0006) plen 3                 [hci0] 28.628506
>         Handle: 70
>         Reason: Authentication Failure (0x05)

To me this looks like the remote either rejected the pairing, or
something else went wrong there. It'd help to see the full HCI log,
particularly from the beginning of the SMP session, i.e. including the
Pairing Request and Response PDUs.

Johan

AW: 5.41 - Authentication Failed with kernel 4.2.0

[Kropf Johannes]

Hi,

> -----Ursprüngliche Nachricht-----
> Von: Johan Hedberg [mailto:johan.hedberg@gmail.com]
> Gesendet: Dienstag, 9. August 2016 16:32
> An: Kropf Johannes
> Cc: linux-bluetooth@vger.kernel.org
> Betreff: Re: 5.41 - Authentication Failed with kernel 4.2.0
> 
> Hi Johannes,
> 
> Please don't drop the mailing list from the thread (added it back now).
> 
> On Tue, Aug 09, 2016, Kropf Johannes wrote:
> > > On Mon, Aug 08, 2016, Kropf Johannes wrote:
> > > > we had a problem when attempting to pair low energy devices on
> > > > Ubuntu
> > > with kernel version 4.2.0-42-generic:
> > > > After scanning there always occured an "authentication failed" error.
> > > > The devices we tried to pair were a A&D UC-352-BLE weighing scale
> > > > and a
> > > A&D UA-651BLE blood pressure monitor.
> > > > Both devices can be paired on the same machine with the same setup
> > > > but
> > > with kernel version 3.13.0.92.
> > > > Unfortunately the log doesn't give me an idea what the problem is.
> > > >
> > > > Here is the output using bluetoothctl:
> > > > [bluetooth]# pair 5C:31:3E:5E:54:5E Attempting to pair with
> > > > 5C:31:3E:5E:54:5E [CHG] Device 5C:31:3E:5E:54:5E Connected: yes
> > > > Failed to pair:
> > > > org.bluez.Error.AuthenticationFailed
> > > > [CHG] Device 5C:31:3E:5E:54:5E Connected: no
> > >
> > > Did you also have an agent registered? (e.g. "agent KeyboardDisplay"
> > > in
> > > bluetoothctl)
> > Yes, an agent was registered in bluetoothctl with "agent on"
> 
> Ok, good. It shouldn't make a difference for pairings initiated from the local
> side, but just in case, did you also issue "default-agent"?
> 
> > > What would give an even better view of what's going on is the HCI logs.
> > > You can get those with the btmon tool (found under monitor/ in the
> > > BlueZ source tree).
> > Here is the output of btmon. Does it mean anything to you?
> > ....
> > < ACL Data TX: Handle 70 flags 0x00 dlen 11                    [hci0] 28.489379
> >       ATT: Read By Group Type Request (0x10) len 6
> >         Handle range: 0x0018-0xffff
> >         Attribute group type: Primary Service (0x2800)
> > > HCI Event: Number of Completed Packets (0x13) plen 5         [hci0]
> 28.559451
> >         Num handles: 1
> >         Handle: 70
> >         Count: 1
> > > HCI Event: Number of Completed Packets (0x13) plen 5         [hci0]
> 28.560451
> >         Num handles: 1
> >         Handle: 70
> >         Count: 1
> > > ACL Data RX: Handle 70 flags 0x02 dlen 6                     [hci0] 28.628456
> >       SMP: Pairing Failed (0x05) len 1
> >         Reason: Confirm value failed (0x04)
> > < HCI Command: Disconnect (0x01|0x0006) plen 3                 [hci0] 28.628506
> >         Handle: 70
> >         Reason: Authentication Failure (0x05)
> 
> To me this looks like the remote either rejected the pairing, or something else
> went wrong there. It'd help to see the full HCI log, particularly from the
> beginning of the SMP session, i.e. including the Pairing Request and Response
> PDUs.
> 
> Johan

Here is the whole log:

> HCI Event: Command Status (0x0f) plen 4                      [hci0] 28.080411
      LE Create Connection (0x08|0x000d) ncmd 1
        Status: Success (0x00)
> HCI Event: LE Meta Event (0x3e) plen 19                      [hci0] 28.086410
      LE Connection Complete (0x01)
        Status: Success (0x00)
        Handle: 70
        Role: Master (0x00)
        Peer address type: Public (0x00)
        Peer address: 5C:31:3E:5E:54:5E (OUI 5C-31-3E)
        Connection interval: 70.00 msec (0x0038)
        Connection latency: 0.00 msec (0x0000)
        Supervision timeout: 420 msec (0x002a)
        Master clock accuracy: 0x00
< HCI Command: LE Read Remote Used Fea.. (0x08|0x0016) plen 2  [hci0] 28.086498
        Handle: 70
@ Device Connected: 5C:31:3E:5E:54:5E (1) flags 0x0000
        02 01 05 03 02 1d 18 05 12 40 00 50 00           .........@.P.   
> HCI Event: Command Status (0x0f) plen 4                      [hci0] 28.090427
      LE Read Remote Used Features (0x08|0x0016) ncmd 1
        Status: Success (0x00)
> ACL Data RX: Handle 70 flags 0x02 dlen 6                     [hci0] 28.145172
      SMP: Security Request (0x0b) len 1
        Authentication requirement: Bonding, No MITM, Legacy, No Keypresses (0x01)
> HCI Event: LE Meta Event (0x3e) plen 12                      [hci0] 28.209459
      LE Read Remote Used Features (0x04)
        Status: Success (0x00)
        Handle: 70
        Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
          LE Encryption
< ACL Data TX: Handle 70 flags 0x00 dlen 11                    [hci0] 28.209526
      SMP: Pairing Request (0x01) len 6
        IO capability: NoInputNoOutput (0x03)
        OOB data: Authentication data not present (0x00)
        Authentication requirement: Bonding, No MITM, SC, No Keypresses (0x09)
        Max encryption key size: 16
        Initiator key distribution: EncKey Sign LinkKey (0x0d)
        Responder key distribution: EncKey IdKey Sign LinkKey (0x0f)
< ACL Data TX: Handle 70 flags 0x00 dlen 7                     [hci0] 28.209934
      ATT: Exchange MTU Request (0x02) len 2
        Client RX MTU: 517
> HCI Event: Number of Completed Packets (0x13) plen 5         [hci0] 28.278449
        Num handles: 1
        Handle: 70
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5         [hci0] 28.279449
        Num handles: 1
        Handle: 70
        Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 11                    [hci0] 28.348460
      SMP: Pairing Response (0x02) len 6
        IO capability: NoInputNoOutput (0x03)
        OOB data: Authentication data not present (0x00)
        Authentication requirement: Bonding, No MITM, Legacy, No Keypresses (0x01)
        Max encryption key size: 16
        Initiator key distribution: EncKey Sign (0x05)
        Responder key distribution: EncKey IdKey Sign (0x07)
< ACL Data TX: Handle 70 flags 0x00 dlen 21                    [hci0] 28.348510
      SMP: Pairing Confirm (0x03) len 16
        Confim value: 12bd199ba4739a017395109cfa4621b3
> ACL Data RX: Handle 70 flags 0x02 dlen 7                     [hci0] 28.349000
      ATT: Exchange MTU Response (0x03) len 2
        Server RX MTU: 23
< ACL Data TX: Handle 70 flags 0x00 dlen 11                    [hci0] 28.349199
      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         [hci0] 28.419459
        Num handles: 1
        Handle: 70
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5         [hci0] 28.420450
        Num handles: 1
        Handle: 70
        Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 21                    [hci0] 28.488508
      SMP: Pairing Confirm (0x03) len 16
        Confim value: 41f5f7a6212356d0eefa268f7994844a
< ACL Data TX: Handle 70 flags 0x00 dlen 21                    [hci0] 28.488545
      SMP: Pairing Random (0x04) len 16
        Random value: 4e8d532caf34ab845ff243acf6a0a681
> ACL Data RX: Handle 70 flags 0x02 dlen 24                    [hci0] 28.489235
      ATT: Read By Group Type Response (0x11) len 19
        Attribute data length: 6
        Attribute group list: 3 entries
        Handle range: 0x0001-0x000b
        UUID: Generic Access Profile (0x1800)
        Handle range: 0x000c-0x000f
        UUID: Generic Attribute Profile (0x1801)
        Handle range: 0x0010-0x0017
        UUID: Weight Scale (0x181d)
< ACL Data TX: Handle 70 flags 0x00 dlen 11                    [hci0] 28.489379
      ATT: Read By Group Type Request (0x10) len 6
        Handle range: 0x0018-0xffff
        Attribute group type: Primary Service (0x2800)
> HCI Event: Number of Completed Packets (0x13) plen 5         [hci0] 28.559451
        Num handles: 1
        Handle: 70
        Count: 1
> HCI Event: Number of Completed Packets (0x13) plen 5         [hci0] 28.560451
        Num handles: 1
        Handle: 70
        Count: 1
> ACL Data RX: Handle 70 flags 0x02 dlen 6                     [hci0] 28.628456
      SMP: Pairing Failed (0x05) len 1
        Reason: Confirm value failed (0x04)
< HCI Command: Disconnect (0x01|0x0006) plen 3                 [hci0] 28.628506
        Handle: 70
        Reason: Authentication Failure (0x05)
@ Authentication Failed: 5C:31:3E:5E:54:5E (1) status 0x05
> ACL Data RX: Handle 70 flags 0x02 dlen 18                    [hci0] 28.635600
      ATT: Read By Group Type Response (0x11) len 13
        Attribute data length: 6
        Attribute group list: 2 entries
        Handle range: 0x0018-0x0028
        UUID: Device Information (0x180a)
        Handle range: 0x0029-0x002b
        UUID: Battery Service (0x180f)
> HCI Event: Command Status (0x0f) plen 4                      [hci0] 28.639427
      Disconnect (0x01|0x0006) ncmd 1
        Status: Success (0x00)
> HCI Event: Disconnect Complete (0x05) plen 4                 [hci0] 28.699449
        Status: Success (0x00)
        Handle: 70
        Reason: Connection Terminated By Local Host (0x16)
@ Device Disconnected: 5C:31:3E:5E:54:5E (1) reason 2

Re: 5.41 - Authentication Failed with kernel 4.2.0

[Johan Hedberg]

Hi Johannes,

On Wed, Aug 10, 2016, Kropf Johannes wrote:
> Here is the whole log:

Thanks. I'll filter it so only the relevant stuff (SMP) is present:

> > ACL Data RX: Handle 70 flags 0x02 dlen 6                     [hci0] 28.145172
>       SMP: Security Request (0x0b) len 1
>         Authentication requirement: Bonding, No MITM, Legacy, No Keypresses (0x01)
> < ACL Data TX: Handle 70 flags 0x00 dlen 11                    [hci0] 28.209526
>       SMP: Pairing Request (0x01) len 6
>         IO capability: NoInputNoOutput (0x03)
>         OOB data: Authentication data not present (0x00)
>         Authentication requirement: Bonding, No MITM, SC, No Keypresses (0x09)
>         Max encryption key size: 16
>         Initiator key distribution: EncKey Sign LinkKey (0x0d)
>         Responder key distribution: EncKey IdKey Sign LinkKey (0x0f)
> > ACL Data RX: Handle 70 flags 0x02 dlen 11                    [hci0] 28.348460
>       SMP: Pairing Response (0x02) len 6
>         IO capability: NoInputNoOutput (0x03)
>         OOB data: Authentication data not present (0x00)
>         Authentication requirement: Bonding, No MITM, Legacy, No Keypresses (0x01)
>         Max encryption key size: 16
>         Initiator key distribution: EncKey Sign (0x05)
>         Responder key distribution: EncKey IdKey Sign (0x07)
> < ACL Data TX: Handle 70 flags 0x00 dlen 21                    [hci0] 28.348510
>       SMP: Pairing Confirm (0x03) len 16
>         Confim value: 12bd199ba4739a017395109cfa4621b3
> > ACL Data RX: Handle 70 flags 0x02 dlen 21                    [hci0] 28.488508
>       SMP: Pairing Confirm (0x03) len 16
>         Confim value: 41f5f7a6212356d0eefa268f7994844a
> < ACL Data TX: Handle 70 flags 0x00 dlen 21                    [hci0] 28.488545
>       SMP: Pairing Random (0x04) len 16
>         Random value: 4e8d532caf34ab845ff243acf6a0a681
> > ACL Data RX: Handle 70 flags 0x02 dlen 6                     [hci0] 28.628456
>       SMP: Pairing Failed (0x05) len 1
>         Reason: Confirm value failed (0x04)
> < HCI Command: Disconnect (0x01|0x0006) plen 3                 [hci0] 28.628506
>         Handle: 70
>         Reason: Authentication Failure (0x05)
> @ Authentication Failed: 5C:31:3E:5E:54:5E (1) status 0x05

That "Confirm value failed" response still looks like something strange
is happening on the remote side - maybe a bug there. Unfortunately I
don't really have any other ideas except going for raw bisecting here if
you have a kernel version this did work with.

The inputs to the function that generates the confirm value are the
local and remote public keys and the random number that was sent over
the air, so there's not much that can go wrong there - also nothing I
can remember that would have changed on the Linux side regarding this
for a long time. This of course assumes that the remote device is using
this error code correctly and doesn't send it for some other condition.

Johan

Re: 5.41 - Authentication Failed with kernel 4.2.0

[Marcel Holtmann]

Hi Johan,

>> Here is the whole log:
> 
> Thanks. I'll filter it so only the relevant stuff (SMP) is present:
> 
>>> ACL Data RX: Handle 70 flags 0x02 dlen 6                     [hci0] 28.145172
>>      SMP: Security Request (0x0b) len 1
>>        Authentication requirement: Bonding, No MITM, Legacy, No Keypresses (0x01)
>> < ACL Data TX: Handle 70 flags 0x00 dlen 11                    [hci0] 28.209526
>>      SMP: Pairing Request (0x01) len 6
>>        IO capability: NoInputNoOutput (0x03)
>>        OOB data: Authentication data not present (0x00)
>>        Authentication requirement: Bonding, No MITM, SC, No Keypresses (0x09)
>>        Max encryption key size: 16
>>        Initiator key distribution: EncKey Sign LinkKey (0x0d)
>>        Responder key distribution: EncKey IdKey Sign LinkKey (0x0f)

actually this might be some fun that secure connection and cross-transport key derivation is causing because of RFU bits. Essentially the peripheral already told us that it does not support SC. So why do we try it and why do we try to use CT as well.

I think if we get a Security Request with legacy pairing auth requirements, we should treat the device as legacy. And not try to even negotiate secure connections in the first place.

>>> ACL Data RX: Handle 70 flags 0x02 dlen 11                    [hci0] 28.348460
>>      SMP: Pairing Response (0x02) len 6
>>        IO capability: NoInputNoOutput (0x03)
>>        OOB data: Authentication data not present (0x00)
>>        Authentication requirement: Bonding, No MITM, Legacy, No Keypresses (0x01)
>>        Max encryption key size: 16
>>        Initiator key distribution: EncKey Sign (0x05)
>>        Responder key distribution: EncKey IdKey Sign (0x07)
>> < ACL Data TX: Handle 70 flags 0x00 dlen 21                    [hci0] 28.348510
>>      SMP: Pairing Confirm (0x03) len 16
>>        Confim value: 12bd199ba4739a017395109cfa4621b3
>>> ACL Data RX: Handle 70 flags 0x02 dlen 21                    [hci0] 28.488508
>>      SMP: Pairing Confirm (0x03) len 16
>>        Confim value: 41f5f7a6212356d0eefa268f7994844a
>> < ACL Data TX: Handle 70 flags 0x00 dlen 21                    [hci0] 28.488545
>>      SMP: Pairing Random (0x04) len 16
>>        Random value: 4e8d532caf34ab845ff243acf6a0a681
>>> ACL Data RX: Handle 70 flags 0x02 dlen 6                     [hci0] 28.628456
>>      SMP: Pairing Failed (0x05) len 1
>>        Reason: Confirm value failed (0x04)
>> < HCI Command: Disconnect (0x01|0x0006) plen 3                 [hci0] 28.628506
>>        Handle: 70
>>        Reason: Authentication Failure (0x05)
>> @ Authentication Failed: 5C:31:3E:5E:54:5E (1) status 0x05
> 
> That "Confirm value failed" response still looks like something strange
> is happening on the remote side - maybe a bug there. Unfortunately I
> don't really have any other ideas except going for raw bisecting here if
> you have a kernel version this did work with.
> 
> The inputs to the function that generates the confirm value are the
> local and remote public keys and the random number that was sent over
> the air, so there's not much that can go wrong there - also nothing I
> can remember that would have changed on the Linux side regarding this
> for a long time. This of course assumes that the remote device is using
> this error code correctly and doesn't send it for some other condition.

I bet that the peripheral side wrongly clears some RFU bits. Which leads to wrong values for confirm values.

Regards

Marcel

Re: 5.41 - Authentication Failed with kernel 4.2.0

[Marcel Holtmann]

Hi Johannes,

>>>>> we had a problem when attempting to pair low energy devices on
>>>>> Ubuntu
>>>> with kernel version 4.2.0-42-generic:
>>>>> After scanning there always occured an "authentication failed" error.
>>>>> The devices we tried to pair were a A&D UC-352-BLE weighing scale
>>>>> and a
>>>> A&D UA-651BLE blood pressure monitor.
>>>>> Both devices can be paired on the same machine with the same setup
>>>>> but
>>>> with kernel version 3.13.0.92.
>>>>> Unfortunately the log doesn't give me an idea what the problem is.
>>>>> 
>>>>> Here is the output using bluetoothctl:
>>>>> [bluetooth]# pair 5C:31:3E:5E:54:5E Attempting to pair with
>>>>> 5C:31:3E:5E:54:5E [CHG] Device 5C:31:3E:5E:54:5E Connected: yes
>>>>> Failed to pair:
>>>>> org.bluez.Error.AuthenticationFailed
>>>>> [CHG] Device 5C:31:3E:5E:54:5E Connected: no
>>>> 
>>>> Did you also have an agent registered? (e.g. "agent KeyboardDisplay"
>>>> in
>>>> bluetoothctl)
>>> Yes, an agent was registered in bluetoothctl with "agent on"
>> 
>> Ok, good. It shouldn't make a difference for pairings initiated from the local
>> side, but just in case, did you also issue "default-agent"?
>> 
>>>> What would give an even better view of what's going on is the HCI logs.
>>>> You can get those with the btmon tool (found under monitor/ in the
>>>> BlueZ source tree).
>>> Here is the output of btmon. Does it mean anything to you?
>>> ....
>>> < ACL Data TX: Handle 70 flags 0x00 dlen 11                    [hci0] 28.489379
>>>      ATT: Read By Group Type Request (0x10) len 6
>>>        Handle range: 0x0018-0xffff
>>>        Attribute group type: Primary Service (0x2800)
>>>> HCI Event: Number of Completed Packets (0x13) plen 5         [hci0]
>> 28.559451
>>>        Num handles: 1
>>>        Handle: 70
>>>        Count: 1
>>>> HCI Event: Number of Completed Packets (0x13) plen 5         [hci0]
>> 28.560451
>>>        Num handles: 1
>>>        Handle: 70
>>>        Count: 1
>>>> ACL Data RX: Handle 70 flags 0x02 dlen 6                     [hci0] 28.628456
>>>      SMP: Pairing Failed (0x05) len 1
>>>        Reason: Confirm value failed (0x04)
>>> < HCI Command: Disconnect (0x01|0x0006) plen 3                 [hci0] 28.628506
>>>        Handle: 70
>>>        Reason: Authentication Failure (0x05)
>> 
>> To me this looks like the remote either rejected the pairing, or something else
>> went wrong there. It'd help to see the full HCI log, particularly from the
>> beginning of the SMP session, i.e. including the Pairing Request and Response
>> PDUs.
>> 
>> Johan
> 
> Here is the whole log:
> 
>> HCI Event: Command Status (0x0f) plen 4                      [hci0] 28.080411
>      LE Create Connection (0x08|0x000d) ncmd 1
>        Status: Success (0x00)
>> HCI Event: LE Meta Event (0x3e) plen 19                      [hci0] 28.086410
>      LE Connection Complete (0x01)
>        Status: Success (0x00)
>        Handle: 70
>        Role: Master (0x00)
>        Peer address type: Public (0x00)
>        Peer address: 5C:31:3E:5E:54:5E (OUI 5C-31-3E)
>        Connection interval: 70.00 msec (0x0038)
>        Connection latency: 0.00 msec (0x0000)
>        Supervision timeout: 420 msec (0x002a)
>        Master clock accuracy: 0x00
> < HCI Command: LE Read Remote Used Fea.. (0x08|0x0016) plen 2  [hci0] 28.086498
>        Handle: 70
> @ Device Connected: 5C:31:3E:5E:54:5E (1) flags 0x0000
>        02 01 05 03 02 1d 18 05 12 40 00 50 00           .........@.P.   
>> HCI Event: Command Status (0x0f) plen 4                      [hci0] 28.090427
>      LE Read Remote Used Features (0x08|0x0016) ncmd 1
>        Status: Success (0x00)
>> ACL Data RX: Handle 70 flags 0x02 dlen 6                     [hci0] 28.145172
>      SMP: Security Request (0x0b) len 1
>        Authentication requirement: Bonding, No MITM, Legacy, No Keypresses (0x01)

this is an odd event. So we are initiation the pairing, but the remote side is sending Security Request for no apparent reason. This means I am suspecting that we are just dropping this PDU and not acting on it.

This could be tested by adding a debug print in smp_sig_channel() for this statement

        if (smp && !test_and_clear_bit(code, &smp->allow_cmd))                   
                goto drop;

What we might need to do is allow SMP_CMD_SECURITY_REQ and then let it set SMP_FLAG_LEGACY_SLAVE in case SC is not set.

>> HCI Event: LE Meta Event (0x3e) plen 12                      [hci0] 28.209459
>      LE Read Remote Used Features (0x04)
>        Status: Success (0x00)
>        Handle: 70
>        Features: 0x01 0x00 0x00 0x00 0x00 0x00 0x00 0x00
>          LE Encryption
> < ACL Data TX: Handle 70 flags 0x00 dlen 11                    [hci0] 28.209526
>      SMP: Pairing Request (0x01) len 6
>        IO capability: NoInputNoOutput (0x03)
>        OOB data: Authentication data not present (0x00)
>        Authentication requirement: Bonding, No MITM, SC, No Keypresses (0x09)
>        Max encryption key size: 16
>        Initiator key distribution: EncKey Sign LinkKey (0x0d)
>        Responder key distribution: EncKey IdKey Sign LinkKey (0x0f)

If my suspicion is correct and we ignore Security Request above, that this Pairing Request is not a section based on Security Request. It is genuine new attempt to pair the device.

I would not be surprised if the auth requirement RFU bits or key distribution RFU bits are getting cleared by the peripheral and the raw PDU is used wrongly in confirm value calculation.

However that is easy to test and see if paring succeeds when manually doing "btmgmt sc off". Then the SC bit and LinkKey bits should not be set in the Pairing Request. If that succeeds then this is a broken peripheral.

Regards

Marcel

Re: 5.41 - Authentication Failed with kernel 4.2.0

[Johan Hedberg]

On Wed, Aug 10, 2016, Marcel Holtmann wrote:
> >>> ACL Data RX: Handle 70 flags 0x02 dlen 11                    [hci0] 28.348460
> >>      SMP: Pairing Response (0x02) len 6
> >>        IO capability: NoInputNoOutput (0x03)
> >>        OOB data: Authentication data not present (0x00)
> >>        Authentication requirement: Bonding, No MITM, Legacy, No Keypresses (0x01)
> >>        Max encryption key size: 16
> >>        Initiator key distribution: EncKey Sign (0x05)
> >>        Responder key distribution: EncKey IdKey Sign (0x07)
> >> < ACL Data TX: Handle 70 flags 0x00 dlen 21                    [hci0] 28.348510
> >>      SMP: Pairing Confirm (0x03) len 16
> >>        Confim value: 12bd199ba4739a017395109cfa4621b3
> >>> ACL Data RX: Handle 70 flags 0x02 dlen 21                    [hci0] 28.488508
> >>      SMP: Pairing Confirm (0x03) len 16
> >>        Confim value: 41f5f7a6212356d0eefa268f7994844a
> >> < ACL Data TX: Handle 70 flags 0x00 dlen 21                    [hci0] 28.488545
> >>      SMP: Pairing Random (0x04) len 16
> >>        Random value: 4e8d532caf34ab845ff243acf6a0a681
> >>> ACL Data RX: Handle 70 flags 0x02 dlen 6                     [hci0] 28.628456
> >>      SMP: Pairing Failed (0x05) len 1
> >>        Reason: Confirm value failed (0x04)
> >> < HCI Command: Disconnect (0x01|0x0006) plen 3                 [hci0] 28.628506
> >>        Handle: 70
> >>        Reason: Authentication Failure (0x05)
> >> @ Authentication Failed: 5C:31:3E:5E:54:5E (1) status 0x05
> > 
> > That "Confirm value failed" response still looks like something strange
> > is happening on the remote side - maybe a bug there. Unfortunately I
> > don't really have any other ideas except going for raw bisecting here if
> > you have a kernel version this did work with.
> > 
> > The inputs to the function that generates the confirm value are the
> > local and remote public keys and the random number that was sent over
> > the air, so there's not much that can go wrong there - also nothing I
> > can remember that would have changed on the Linux side regarding this
> > for a long time. This of course assumes that the remote device is using
> > this error code correctly and doesn't send it for some other condition.
> 
> I bet that the peripheral side wrongly clears some RFU bits. Which
> leads to wrong values for confirm values.

Johannes, could you try to experiment and see whether this is the issue?
You can temporarily disable Secure Connections support with the command
"btmgmt sc off"

Johan

Re: 5.41 - Authentication Failed with kernel 4.2.0

[Marcel Holtmann]

Hi Johan,

>>>>> ACL Data RX: Handle 70 flags 0x02 dlen 11                    [hci0] 28.348460
>>>>     SMP: Pairing Response (0x02) len 6
>>>>       IO capability: NoInputNoOutput (0x03)
>>>>       OOB data: Authentication data not present (0x00)
>>>>       Authentication requirement: Bonding, No MITM, Legacy, No Keypresses (0x01)
>>>>       Max encryption key size: 16
>>>>       Initiator key distribution: EncKey Sign (0x05)
>>>>       Responder key distribution: EncKey IdKey Sign (0x07)
>>>> < ACL Data TX: Handle 70 flags 0x00 dlen 21                    [hci0] 28.348510
>>>>     SMP: Pairing Confirm (0x03) len 16
>>>>       Confim value: 12bd199ba4739a017395109cfa4621b3
>>>>> ACL Data RX: Handle 70 flags 0x02 dlen 21                    [hci0] 28.488508
>>>>     SMP: Pairing Confirm (0x03) len 16
>>>>       Confim value: 41f5f7a6212356d0eefa268f7994844a
>>>> < ACL Data TX: Handle 70 flags 0x00 dlen 21                    [hci0] 28.488545
>>>>     SMP: Pairing Random (0x04) len 16
>>>>       Random value: 4e8d532caf34ab845ff243acf6a0a681
>>>>> ACL Data RX: Handle 70 flags 0x02 dlen 6                     [hci0] 28.628456
>>>>     SMP: Pairing Failed (0x05) len 1
>>>>       Reason: Confirm value failed (0x04)
>>>> < HCI Command: Disconnect (0x01|0x0006) plen 3                 [hci0] 28.628506
>>>>       Handle: 70
>>>>       Reason: Authentication Failure (0x05)
>>>> @ Authentication Failed: 5C:31:3E:5E:54:5E (1) status 0x05
>>> 
>>> That "Confirm value failed" response still looks like something strange
>>> is happening on the remote side - maybe a bug there. Unfortunately I
>>> don't really have any other ideas except going for raw bisecting here if
>>> you have a kernel version this did work with.
>>> 
>>> The inputs to the function that generates the confirm value are the
>>> local and remote public keys and the random number that was sent over
>>> the air, so there's not much that can go wrong there - also nothing I
>>> can remember that would have changed on the Linux side regarding this
>>> for a long time. This of course assumes that the remote device is using
>>> this error code correctly and doesn't send it for some other condition.
>> 
>> I bet that the peripheral side wrongly clears some RFU bits. Which
>> leads to wrong values for confirm values.
> 
> Johannes, could you try to experiment and see whether this is the issue?
> You can temporarily disable Secure Connections support with the command
> "btmgmt sc off"

I really wonder if we should start using HCI_MON_SYSTEM_NOTE / send_monitor_note to actually send these funky behaviors to the monitor channel once we detect it. At least that way, we would know why we trigger certain PDUs.

Or maybe we are doing something specific for SMP with a debugfs switch that allows us to enable to send SMP debug / tigers via monitor channel. An alternative would be to just be able to push the mgmt traffic via monitor channel so we actually have correct timing and can analyze these things together.

Regards

Marcel