InfiniTime icon indicating copy to clipboard operation
InfiniTime copied to clipboard

Published 20 hours ago • verified publisher icon InfiniTimeOrg

Secure pairing is lost after watchdog reset

Open AndreySV opened this issue 2 years ago • 1 comments

Verification

  • [X] I searched for similar bug reports and found none was relevant.

What happened?

PineTime doesn't connect to a phone after reset and pairing has to be manually removed and reinitiated

What should happen instead?

PineTime is connected to a phone after reset

Reproduction steps

  1. Manually pair using sspmode using bluetoothctl.
  2. Check that notifications are working using Amazfish
  3. Trust device
Agent registered
[InfiniTime]# info
Device E2:C8:1A:2B:48:34 (random)
	Name: InfiniTime
	Alias: InfiniTime
	Appearance: 0x00c2
	Paired: yes
	Bonded: yes
	Trusted: yes
	Blocked: no
	Connected: yes
	LegacyPairing: no
  1. Reset PineTime using power button or https://github.com/InfiniTimeOrg/InfiniTime/issues/1260
  2. Device can't connect to the phone
mobian@mobian:~/.config/systemd/user $ bluetoothctl
Agent registered
[bluetooth]# connect E2:C8:1A:2B:48:34
Attempting to connect to E2:C8:1A:2B:48:34
[CHG] Device E2:C8:1A:2B:48:34 RSSI: -50
[CHG] Device E2:C8:1A:2B:48:34 Connected: yes
Connection successful
[CHG] Device E2:C8:1A:2B:48:34 RSSI: -48
[CHG] Device E2:C8:1A:2B:48:34 Connected: no

mobian@mobian:~/.config/systemd/user $ sudo btmon
...
< HCI Command: LE Start Encryption (0x08|0x0019) plen 28                                                                                                                                                                                                              #37 [hci0] 9.862167
        Handle: 16 Address: E2:C8:1A:2B:48:34 (Static)
        Random number: 0x0000000000000000
        Encrypted diversifier: 0x0000
        Long term key: c510eaa2e3d76d9371b4596b68e247b6
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                                                                                             #38 [hci0] 9.863460
      LE Start Encryption (0x08|0x0019) ncmd 2
        Status: Success (0x00)
> ACL Data RX: Handle 16 flags 0x02 dlen 13                                                                                                                                                                                                                          #39 [hci0] 10.310960
      ATT: Find By Type Value Request (0x06) len 8
        Handle range: 0x0001-0xffff
        Attribute type: Primary Service (0x2800)
          UUID: Current Time Service (0x1805)
> HCI Event: Encryption Change (0x08) plen 4                                                                                                                                                                                                                         #40 [hci0] 10.581018
        Status: PIN or Key Missing (0x06)
        Handle: 16 Address: E2:C8:1A:2B:48:34 (Static)
        Encryption: Disabled (0x00)
< HCI Command: Disconnect (0x01|0x0006) plen 3                                                                                                                                                                                                                       #41 [hci0] 10.581422
        Handle: 16 Address: E2:C8:1A:2B:48:34 (Static)
        Reason: Authentication Failure (0x05)
> HCI Event: Command Status (0x0f) plen 4                                                                                                                                                                                                                            #42 [hci0] 10.582421
      Disconnect (0x01|0x0006) ncmd 2
        Status: Success (0x00)
> HCI Event: Disconnect Complete (0x05) plen 4                                                                                                                                                                                                                       #43 [hci0] 10.625995
        Status: Success (0x00)
        Handle: 16 Address: E2:C8:1A:2B:48:34 (Static)
        Reason: Connection Terminated By Local Host (0x16)

More details?

PinePhone with Mobian running kernel 5.15.44 and Amazfish 2.0.3 with PineTime

Version

v1.10.0

Companion app

Amazfish

AndreySV avatar Aug 14 '22 22:08 AndreySV

Have a similar problem with Pinetime connected to Amazfish on Sailfish OS. https://github.com/piggz/harbour-amazfish/issues/203

dvidebaek avatar Aug 15 '22 00:08 dvidebaek

If you trigger BLE_GAP_EVENT_ENC_CHANGE (https://github.com/InfiniTimeOrg/InfiniTime/blob/7f45538eb53235ab4015fcf13533796c8759c7bc/src/components/ble/NimbleController.cpp#L249) then the bond gets persisted properly. As this seems to be only happening on Amazfish, I'd say it's a shortfall in its bonding process.

Avamander avatar Oct 04 '22 10:10 Avamander

I've paired using bluetoothctl, not Amazfish.

mobian@mobian:~ $ bluetoothctl
Agent registered
[CHG] Controller 00:E0:XX:XX:XX:XX Pairable: yes
[InfiniTime]# info
Device E2:C8:XX:XX:XX:XX (random)
	Name: InfiniTime
	Alias: InfiniTime
	Appearance: 0x00c2
	Paired: no
	Bonded: no
	Trusted: yes
	Blocked: no
	Connected: yes
	LegacyPairing: no
	UUID: Vendor specific           (00000000-78fc-48fe-8e23-433b3a1942d0)
	UUID: Vendor specific           (00001530-1212-efde-1523-785feabcd123)
	UUID: Generic Access Profile    (00001800-0000-1000-8000-00805f9b34fb)
	UUID: Generic Attribute Profile (00001801-0000-1000-8000-00805f9b34fb)
	UUID: Immediate Alert           (00001802-0000-1000-8000-00805f9b34fb)
	UUID: Current Time Service      (00001805-0000-1000-8000-00805f9b34fb)
	UUID: Device Information        (0000180a-0000-1000-8000-00805f9b34fb)
	UUID: Heart Rate                (0000180d-0000-1000-8000-00805f9b34fb)
	UUID: Battery Service           (0000180f-0000-1000-8000-00805f9b34fb)
	UUID: Alert Notification Serv.. (00001811-0000-1000-8000-00805f9b34fb)
	UUID: adafruit industries       (0000febb-0000-1000-8000-00805f9b34fb)
	UUID: Vendor specific           (00010000-78fc-48fe-8e23-433b3a1942d0)
	UUID: Vendor specific           (00030000-78fc-48fe-8e23-433b3a1942d0)
	UUID: Vendor specific           (00040000-78fc-48fe-8e23-433b3a1942d0)
	Battery Percentage: 0x24 (36)
[InfiniTime]# pair
Attempting to pair with E2:C8:XX:XX:XX:XX
Request passkey
[agent] Enter passkey (number in 0-999999): 801998
[CHG] Device E2:C8:XX:XX:XX:XX Bonded: yes
[CHG] Device E2:C8:XX:XX:XX:XX Paired: yes
Pairing successful
[InfiniTime]# trust
Changing E2:C8:XX:XX:XX:XX trust succeeded
[InfiniTime]# info
Device E2:C8:XX:XX:XX:XX (random)
	Name: InfiniTime
	Alias: InfiniTime
	Appearance: 0x00c2
	Paired: yes
	Bonded: yes
	Trusted: yes
	Blocked: no
	Connected: yes
	LegacyPairing: no
	UUID: Vendor specific           (00000000-78fc-48fe-8e23-433b3a1942d0)
	UUID: Vendor specific           (00001530-1212-efde-1523-785feabcd123)
	UUID: Generic Access Profile    (00001800-0000-1000-8000-00805f9b34fb)
	UUID: Generic Attribute Profile (00001801-0000-1000-8000-00805f9b34fb)
	UUID: Immediate Alert           (00001802-0000-1000-8000-00805f9b34fb)
	UUID: Current Time Service      (00001805-0000-1000-8000-00805f9b34fb)
	UUID: Device Information        (0000180a-0000-1000-8000-00805f9b34fb)
	UUID: Heart Rate                (0000180d-0000-1000-8000-00805f9b34fb)
	UUID: Battery Service           (0000180f-0000-1000-8000-00805f9b34fb)
	UUID: Alert Notification Serv.. (00001811-0000-1000-8000-00805f9b34fb)
	UUID: adafruit industries       (0000febb-0000-1000-8000-00805f9b34fb)
	UUID: Vendor specific           (00010000-78fc-48fe-8e23-433b3a1942d0)
	UUID: Vendor specific           (00030000-78fc-48fe-8e23-433b3a1942d0)
	UUID: Vendor specific           (00040000-78fc-48fe-8e23-433b3a1942d0)
	Battery Percentage: 0x24 (36)
[InfiniTime]#

if I try connect after watchdog reset, I get following

[bluetooth]# connect E2:C8:XX:XX:XX:XX
Attempting to connect to E2:C8:XX:XX:XX:XX
[CHG] Device E2:C8:XX:XX:XX:XX Connected: yes
Connection successful
[CHG] Device E2:C8:XX:XX:XX:XX Connected: no

< HCI Command: LE Create Connection (0x08|0x000d) plen 25
    bdaddr E2:C8:XX:XX:XX:XX type 1
    interval 96 window 96 initiator_filter 0
    own_bdaddr_type 0 min_interval 24 max_interval 40
    latency 0 supervision_to 42 min_ce 0 max_ce 0
> HCI Event: Command Status (0x0f) plen 4
    LE Create Connection (0x08|0x000d) status 0x00 ncmd 2
> HCI Event: LE Meta Event (0x3e) plen 19
    LE Connection Complete
      status 0x00 handle 16, role central
      bdaddr E2:C8:XX:XX:XX:XX (Random)
< HCI Command: LE Read Remote Used Features (0x08|0x0016) plen 2
> HCI Event: Command Status (0x0f) plen 4
    LE Read Remote Used Features (0x08|0x0016) status 0x00 ncmd 2
< HCI Command: LE Set Scan Parameters (0x08|0x000b) plen 7
    type 0x00 (passive)
    interval 60.000ms window 30.000ms
    own address: 0x00 (Public) policy: All
> HCI Event: Command Complete (0x0e) plen 4
    LE Set Scan Parameters (0x08|0x000b) ncmd 2
    status 0x00
< HCI Command: LE Set Scan Enable (0x08|0x000c) plen 2
    value 0x01 (scanning enabled)
    filter duplicates 0x01 (enabled)
> HCI Event: Command Complete (0x0e) plen 4
    LE Set Scan Enable (0x08|0x000c) ncmd 2
    status 0x00
> HCI Event: LE Meta Event (0x3e) plen 12
    LE Read Remote Used Features Complete
      status 0x00 handle 16
      Features: 0x01 0x40 0x00 0x00 0x00 0x00 0x00 0x00
< HCI Command: LE Start Encryption (0x08|0x0019) plen 28
> HCI Event: Command Status (0x0f) plen 4
    LE Start Encryption (0x08|0x0019) status 0x00 ncmd 2
> ACL data: handle 16 flags 0x02 dlen 13
    ATT: Find By Type req (0x06)
      start 0x0001, end 0xffff, uuid 0x2800
      value 0x05 0x18
> HCI Event: Encrypt Change (0x08) plen 4
    status 0x06 handle 16 encrypt 0x00
    Error: PIN or Key Missing
< HCI Command: Disconnect (0x01|0x0006) plen 3
    handle 16 reason 0x05
    Reason: Authentication Failure
> HCI Event: Command Status (0x0f) plen 4
    Disconnect (0x01|0x0006) status 0x00 ncmd 2
> HCI Event: Disconn Complete (0x05) plen 4
    status 0x00 handle 16 reason 0x16
    Reason: Connection Terminated by Local Host
> HCI Event: LE Meta Event (0x3e) plen 33
    LE Advertising Report
      ADV_IND - Connectable undirected advertising (0)
      bdaddr E2:C8:XX:XX:XX:XX (Random)
      Flags: 0x06
      Unknown type 0x07 with 16 bytes data
      RSSI: -84

AndreySV avatar Oct 04 '22 18:10 AndreySV

Please also establish a GATT connection where encryption is used.

Avamander avatar Oct 04 '22 19:10 Avamander

Please also establish a GATT connection where encryption is used.

root@mobian:/home/mobian# gatttool --sec-level=high -b E2:C8:XX:XX:XX:XX -t random -I
[E2:C8:XX:XX:XX:XX][LE]> connect
Attempting to connect to E2:C8:XX:XX:XX:XX
Connection successful
[E2:C8:XX:XX:XX:XX][LE]> primary
attr handle: 0x0001, end grp handle: 0x0005 uuid: 00001800-0000-1000-8000-00805f9b34fb
attr handle: 0x0006, end grp handle: 0x0009 uuid: 00001801-0000-1000-8000-00805f9b34fb
attr handle: 0x000a, end grp handle: 0x0016 uuid: 0000180a-0000-1000-8000-00805f9b34fb
attr handle: 0x0017, end grp handle: 0x0019 uuid: 00001805-0000-1000-8000-00805f9b34fb
attr handle: 0x001a, end grp handle: 0x0035 uuid: 00000000-78fc-48fe-8e23-433b3a1942d0
attr handle: 0x0036, end grp handle: 0x003a uuid: 00040000-78fc-48fe-8e23-433b3a1942d0
attr handle: 0x003b, end grp handle: 0x0043 uuid: 00010000-78fc-48fe-8e23-433b3a1942d0
attr handle: 0x0044, end grp handle: 0x0049 uuid: 00001811-0000-1000-8000-00805f9b34fb
attr handle: 0x004a, end grp handle: 0x0051 uuid: 00001530-1212-efde-1523-785feabcd123
attr handle: 0x0052, end grp handle: 0x0055 uuid: 0000180f-0000-1000-8000-00805f9b34fb
attr handle: 0x0056, end grp handle: 0x0058 uuid: 00001802-0000-1000-8000-00805f9b34fb
attr handle: 0x0059, end grp handle: 0x005c uuid: 0000180d-0000-1000-8000-00805f9b34fb
attr handle: 0x005d, end grp handle: 0x0063 uuid: 00030000-78fc-48fe-8e23-433b3a1942d0
attr handle: 0x0064, end grp handle: 0xffff uuid: 0000febb-0000-1000-8000-00805f9b34fb
[E2:C8:XX:XX:XX:XX][LE]> sec-level
sec-level: low
[E2:C8:XX:XX:XX:XX][LE]> sec-level high
[E2:C8:XX:XX:XX:XX][LE]> sec-level
sec-level: high
[E2:C8:XX:XX:XX:XX][LE]> char-read-hnd 0x000b
Characteristic value/descriptor: 02 0c 00 29 2a 
[E2:C8:XX:XX:XX:XX][LE]> disconnect
(gatttool:39602): GLib-WARNING **: 00:48:54.037: Invalid file descriptor.
[E2:C8:XX:XX:XX:XX][LE]> connect
Attempting to connect to E2:C8:XX:XX:XX:XX
Connection successful
[E2:C8:XX:XX:XX:XX][LE]> char-read-hnd 0x0019
Characteristic value/descriptor: e6 07 0a 05 00 3b 11 00 7c 
[E2:C8:XX:XX:XX:XX][LE]> sec-level
sec-level: high
[E2:C8:XX:XX:XX:XX][LE]> disconnect

Would be that enough to do after pairing?

AndreySV avatar Oct 04 '22 22:10 AndreySV

@Avamander IMHO, it doesn't help.

I've paired with pinetime and after setting sec-level to high see enabled encryption in btmon.

< HCI Command: LE Start Encryption (0x08|0x0019) plen 28   #24 [hci0] 13.125540
        Handle: 16 Address: E2:C8:1A:2B:48:34 (Static)
        Random number: 0x0000000000000000
        Encrypted diversifier: 0x0000
        Long term key: b0a276f252db2bf18b6fbeead087e64d
> HCI Event: Command Status (0x0f) plen 4                  #25 [hci0] 13.126807
      LE Start Encryption (0x08|0x0019) ncmd 2
        Status: Success (0x00)
> ACL Data RX: Handle 16 flags 0x02 dlen 13                #26 [hci0] 13.574570
      ATT: Find By Type Value Request (0x06) len 8
        Handle range: 0x0001-0xffff
        Attribute type: Primary Service (0x2800)
          UUID: Current Time Service (0x1805)
< ACL Data TX: Handle 16 flags 0x00 dlen 9                 #27 [hci0] 13.586694
      ATT: Error Response (0x01) len 4
        Find By Type Value Request (0x06)
        Handle: 0x0000
        Error: Request Not Supported (0x06)
> HCI Event: Number of Completed Packets (0x13) plen 5     #28 [hci0] 13.634512
        Num handles: 1
        Handle: 16 Address: E2:C8:1A:2B:48:34 (Static)
        Count: 1
> HCI Event: Encryption Change (0x08) plen 4               #29 [hci0] 13.904646
        Status: Success (0x00)
        Handle: 16 Address: E2:C8:1A:2B:48:34 (Static)
        Encryption: Enabled with AES-CCM (0x01)

But after long power button press or after watchdog reset, I can't connect to pinetime anymore.

< HCI Command: LE Start Encrypt.. (0x08|0x0019) plen 28  #341 [hci0] 447.717763
        Handle: 16 Address: E2:C8:1A:2B:48:34 (Static)
        Random number: 0x0000000000000000
        Encrypted diversifier: 0x0000
        Long term key: b0a276f252db2bf18b6fbeead087e64d
> HCI Event: Command Status (0x0f) plen 4                #342 [hci0] 447.719151
      LE Start Encryption (0x08|0x0019) ncmd 2
        Status: Success (0x00)
> HCI Event: Encryption Change (0x08) plen 4             #343 [hci0] 447.897046
        Status: PIN or Key Missing (0x06)
        Handle: 16 Address: E2:C8:1A:2B:48:34 (Static)
        Encryption: Disabled (0x00)
< HCI Command: Disconnect (0x01|0x0006) plen 3           #344 [hci0] 447.897384
        Handle: 16 Address: E2:C8:1A:2B:48:34 (Static)
        Reason: Authentication Failure (0x05)

So this happens not only with Amazfish, but with bluetoothctl and gattool as well.

AndreySV avatar Oct 16 '22 18:10 AndreySV

Because it's happening not only with Amazfish, do we need to reopen this issue?

AndreySV avatar Nov 07 '22 10:11 AndreySV

If you can prove it's not a bug in bluez or both companions. iOS and Android do not encounter this and those BLE stacks are significantly more correct.

Avamander avatar Nov 07 '22 15:11 Avamander

I haven't personally experienced that issue. Do you have the opportunity to debug the code running on the pinetime? If it's the case, you can check if the bond info are correctly written to the file (https://github.com/InfiniTimeOrg/InfiniTime/blob/develop/src/components/ble/NimbleController.cpp#L422) and restored after the reboot (https://github.com/InfiniTimeOrg/InfiniTime/blob/develop/src/components/ble/NimbleController.cpp#L476).

JF002 avatar Nov 14 '22 20:11 JF002