Locator Tag example fails at Fast Pair Validator App test "Provisioning"

Question

We are using SDK 3.1.1 and nrf52DK with our own Model ID and anti-spoofing key from Google. When flashing the Locator Tag example to the board, a half sheet notification is shown on the phone (Google Pixel 6 with Android 16) and provisioning is successful. The device is shown in the Google Find Hub app. However, when we try the "Provisioning" test in the Eddystone test set of the Google Fast Pair Validator app, the test fails. The test was started both with the device unprovisioned via the Find Hub app and reset (turned off then on), as well as with the device freshly flashed. The tester app was running on Google Pixel 6 with Android 16 and OnePlus 3 with Android. We also tried with the ADB command for locator tags that do not create a bond during pairing activated and deactivated, but there was no difference in the output. Honestly not sure which of the two applies to the Locator Tag example. The log output for the Fast Pair validator app (failing) case: [00:00:11.506,286] fast_pair_adv_manager: Fast Pair Adv Manager: connected to 74:69:53:98:2A:4D (random) [00:00:11.781,860] fast_pair: Notify name not supported (KBP request) [00:00:11.782,287] fast_pair: write_key_based_pairing: Key-based Pairing write: res=80 conn=0x20002810 [00:00:12.340,545] fast_pair: send_auth_confirm: Confirmed passkey [00:00:12.341,064] fast_pair: write_passkey: Passkey write: res=16 conn=0x20002810 [00:00:12.792,541] fp_fmdn: FMDN: connection authenticated using the Bluetooth bond: 0x20002810 [00:00:12.792,663] fast_pair_adv_manager: Fast Pair Adv Manager: security changed: 74:69:53:98:2A:4D (random) level 4 [00:00:12.943,145] fast_pair: pairing_complete: Bonding complete [00:00:22.943,298] fast_pair: Key discarded (timeout) [00:00:26.964,752] fp_fmdn: DIS Firmware Revision characteristic is being read [00:00:27.054,962] fast_pair: Decrypt failed: err=-13 (Account Key) [00:00:27.054,992] fast_pair: write_account_key: Account Key write: res=-14 conn=0x20002810 [00:00:29.169,830] fast_pair: Decrypt failed: err=-13 (Account Key) [00:00:29.169,860] fast_pair: write_account_key: Account Key write: res=-14 conn=0x20002810 [00:00:31.284,759] fast_pair: Decrypt failed: err=-13 (Account Key) [00:00:31.284,790] fast_pair: write_account_key: Account Key write: res=-14 conn=0x20002810 [00:00:31.375,061] fast_pair_adv_manager: Fast Pair Adv Manager: disconnected from D4:3A:2C:8B:12:03 (public) (reason 19) [00:00:31.376,068] fast_pair_adv_manager: Fast Pair Adv Manager: advertising in the discoverable mode And a screenshot of the validator app: The log output for when provisioning via half-sheet notification (successful): [00:00:17.649,902] fast_pair_adv_manager: Fast Pair Adv Manager: connected to 74:69:53:98:2A:4D (random) [00:00:17.958,679] fast_pair: write_key_based_pairing: Key-based Pairing write: res=80 conn=0x20002810 [00:00:18.113,403] fp_fmdn: DIS Firmware Revision characteristic is being read [00:00:18.255,920] fast_pair: fp_keys_store_account_key: Account Key stored [00:00:18.255,981] fast_pair_adv_manager: Fast Pair Adv Manager: advertising request from trigger "fmdn_provisioning": enable [00:00:18.256,011] fp_fmdn: Fast Pair: Account Key write [00:00:18.256,072] fast_pair_adv_manager: Fast Pair Adv Manager: advertising request from trigger "pairing_mode": disable [00:00:18.256,103] fast_pair_adv_manager: fp_adv_request_bm_pairing_mode_set: Fast Pair Adv Manager: set pairing mode to false [00:00:18.256,134] fast_pair: write_account_key: Account Key write: res=16 conn=0x20002810 [00:00:18.383,300] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_read: Beacon Actions GATT Read Request [00:00:18.383,575] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_read: Beacon Actions: challenge-response enabled for the next write: b5 9e dc 3e 1f 6d c4 88 |...>.m.. [00:00:18.383,605] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_read: Beacon Actions read: res=9 conn=0x20002810 [00:00:18.473,419] fp_fmdn_beacon_actions: Beacon Actions CCCD write, handle: 0, value: 0x0001 [00:00:18.563,568] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_write: Beacon Actions GATT Write Request: 01 08 c9 b8 9e 6b 08 61 e9 f6 |.....k.a .. [00:00:18.563,598] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_write: Beacon Actions: consuming random nonce read operation [00:00:18.564,025] fp_fmdn_beacon_actions: beacon_response_send: Beacon Actions response: 01 09 bf 05 31 91 76 f0 ef a0 02 |....1.v. ... [00:00:18.564,117] fp_fmdn: FMDN: connection authenticated using Beacon Actions command: 0x20002810 [00:00:18.564,147] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_write: Beacon Actions write: res=10 conn=0x20002810 [00:00:18.698,394] fp_fmdn_beacon_actions: Beacon Actions CCCD write, handle: 0, value: 0x0000 [00:00:19.778,625] fast_pair_adv_manager: Fast Pair Adv Manager: disconnected from 74:69:53:98:2A:4D (random) (reason 19) [00:00:19.779,663] fast_pair_adv_manager: Fast Pair Adv Manager: advertising in the not-discoverable mode [00:00:29.657,379] fast_pair_adv_manager: Fast Pair Adv Manager: connected to 74:69:53:98:2A:4D (random) [00:00:29.992,950] fp_fmdn_beacon_actions: Beacon Actions CCCD write, handle: 0, value: 0x0001 [00:00:30.127,868] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_read: Beacon Actions GATT Read Request [00:00:30.128,173] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_read: Beacon Actions: challenge-response enabled for the next write: 08 e7 01 7c b9 9b bf 7a |...|...z [00:00:30.128,173] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_read: Beacon Actions read: res=9 conn=0x20002810 [00:00:30.307,891] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_write: Beacon Actions GATT Write Request: 01 08 e7 bb 87 9b 08 24 31 8e |.......$ 1. [00:00:30.307,891] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_write: Beacon Actions: consuming random nonce read operation [00:00:30.308,319] fp_fmdn_beacon_actions: beacon_response_send: Beacon Actions response: 01 09 6d 48 db e1 f0 33 32 24 02 |..mH...3 2$. [00:00:30.308,441] fp_fmdn: FMDN: connection authenticated using Beacon Actions command: 0x20002810 [00:00:30.308,441] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_write: Beacon Actions write: res=10 conn=0x20002810 [00:00:30.397,888] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_read: Beacon Actions GATT Read Request [00:00:30.398,132] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_read: Beacon Actions: challenge-response enabled for the next write: 3f e0 4e af 3d 40 1d 58 |?.N.=@.X [00:00:30.398,162] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_read: Beacon Actions read: res=9 conn=0x20002810 [00:00:30.488,037] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_write: Beacon Actions GATT Write Request: 00 08 6f 30 09 be 8d be 50 2b |..o0.... P+ [00:00:30.488,067] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_write: Beacon Actions: consuming random nonce read operation [00:00:30.488,281] fp_fmdn_beacon_actions: beacon_parameters_read_handle: Beacon Actions: Beacon Parameters Read request: setting response TX power to 4 [dBm] encoded as 0x04 [00:00:30.488,311] fp_fmdn_clock: fp_fmdn_clock_read: FMDN Clock: reading the last value: 30 [s] [00:00:30.488,586] fp_fmdn_beacon_actions: beacon_response_send: Beacon Actions response: 00 18 03 19 34 ff e6 c3 7f 29 24 d3 44 e7 c8 1c |....4... .)$.D... 26 5c 02 b6 af 1d d7 ff 9e a3 |&\...... .. [00:00:30.488,708] fp_fmdn: FMDN: clock information synchronized with the authenticated Bluetooth peer [00:00:30.488,708] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_write: Beacon Actions write: res=10 conn=0x20002810 [00:00:34.852,844] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_read: Beacon Actions: challenge-response enabled for the next write: ef 54 48 65 47 74 b7 fc |.THeGt.. --- 6 messages dropped --- [00:00:34.950,103] fast_pair_adv_manager: Fast Pair Adv Manager: triggers state change to: inactive [00:00:34.950,134] fp_fmdn: FMDN: state changed to provisioned [00:00:34.950,195] fp_fmdn_state: fmdn_adv_rpa_expired: FMDN State: RPA expired [00:00:34.950,225] fp_fmdn_clock: fp_fmdn_clock_read: FMDN Clock: reading the last value: 34 [s] [00:00:34.950,256] fp_fmdn_state: fmdn_adv_rpa_timeout_calculate: FMDN State: calculating new rotation time: 990 s + 168 s [00:00:34.950,286] fp_fmdn_clock: fp_fmdn_clock_read: FMDN Clock: reading the last value: 34 [s] [00:00:34.950,317] fp_fmdn_state: eid_encode: EID seed data: ff ff ff ff ff ff ff ff ff ff ff 0a 00 00 00 00 |........ ........ 00 00 00 00 00 00 00 00 00 00 00 0a 00 00 00 00 |........ ........ [00:00:34.950,347] fp_fmdn_state: eid_encode: EIK: a0 85 9a 5c e9 fe 88 f1 59 c1 82 1a 40 ee b7 fd |...\.... Y...@... 32 bc 81 bf 9e 1c bb b4 0c a4 f0 37 0d 13 19 a3 |2....... ...7.... [00:00:34.950,500] fp_fmdn_state: eid_encode: Encrypted EID seed data: 44 6f 46 01 51 e1 b0 2a 54 05 72 90 10 81 8f 51 |DoF.Q..* T.r....Q 22 dc 03 e2 a2 9e dd a4 be 2e 78 c0 8c a1 14 b1 |"....... ..x..... [00:00:34.957,611] fp_fmdn_state: eid_encode: EID: 12 01 52 6c 2b 12 a6 d7 66 82 70 e4 86 22 b9 82 |..Rl+... f.p..".. fb 6b f7 4c |.k.L [00:00:34.957,672] fp_fmdn_state: hashed_flags_encode: FMDN State: Hashed Flags byte: [00:00:34.957,702] fp_fmdn_state: hashed_flags_encode: Bitmask: 0x02 [00:00:34.957,702] fp_fmdn_state: hashed_flags_encode: Hash: 0x28 [00:00:34.957,733] fp_fmdn_state: hashed_flags_encode: Final value: 0x2A [00:00:34.957,733] fp_fmdn_state: frame_type_encode: FMDN State: FMDN Frame type: 0x40 [00:00:34.958,190] fp_fmdn_state: fmdn_adv_rpa_expired: FMDN State: rotating advertising payload [00:00:34.958,190] fp_fmdn_state: fmdn_adv_rpa_expired: FMDN State: next rotation in 1158 [s] [00:00:34.958,221] fast_pair_adv_manager: Fast Pair Adv Manager: RPA expired [00:00:34.958,221] fast_pair_adv_manager: Fast Pair Adv Manager: RPA rotation in the inactive advertising state [00:00:34.958,251] fast_pair_adv_manager: Fast Pair Adv Manager: the last timeout has occurred 34 [s] ago [00:00:34.959,777] fp_fmdn_state: fmdn_adv_set_rotate: FMDN State: forcing advertising payload rotation [00:00:34.960,418] fp_fmdn_state: fmdn_adv_start: FMDN State: advertising started [00:00:34.960,418] fp_fmdn_state: fmdn_new_provision: FMDN State: Successful provisioning of the EIK [00:00:34.960,662] fp_fmdn_beacon_actions: beacon_response_send: Beacon Actions response: 02 08 23 3f e0 af b9 0a ff 3a |..#?.... .: [00:00:34.960,784] fp_fmdn_beacon_actions: fp_fmdn_beacon_actions_write: Beacon Actions write: res=42 conn=0x20002810 [00:00:36.292,785] fp_fmdn_beacon_actions: Beacon Actions CCCD write, handle: 0, value: 0x0000 [00:00:36.292,938] fast_pair_adv_manager: Fast Pair Adv Manager: disconnected from 74:69:53:98:2A:4D (random) (reason 19) Line 9 in the upper log seems suspicious, where the Key is timing out right before the decrypt fails. However when searching the code base I was not able to pin point where that Log message is produced. Plus the two log outputs differ quite vastly, which I know no answer to (e.g. in the Validator App log is "Bonding complete", even when configuring the Eddystone test set for locator tags than don't create a bonding during pairing, as specified in the google docs).

Hung Bui · Accepted Answer

Hi Luca,
Please find the following feedback:
============

The logs from the FPV app test indicate that the smartphone does not write the Account Key to the Fast Pair Provider (nRF52 DK). The Fast Pair procedure is always concluded with the Account Key write operation, which then starts the FHN provisioning (required for the FHN extension and locator tag use case).

Our implementation expects the Account Key to be provided within 10 seconds. If the operation does not appear on time, we invalidate the temporary session key (public key) and the overall Fast Pair procedure needs to be started from scratch.

[00:00:12.943,145] <dbg> fast_pair: pairing_complete: Bonding complete
[00:00:22.943,298] <inf> fast_pair: Key discarded (timeout)

<- 10 second gap between these two logs (the write passkey operation restarts the timeout)

This is clearly what happens in the customer case. For some reason, the independent operation to read the DIS characteristic is scheduled by the Android OS, which delays the Fast Pair procedure and breaks the assumption that the Account Key write happens within 10 seconds.

It actually happens after 15 seconds, but it is rejected by our DK as the session key and the ongoing FP procedure is already marked as invalid.

[00:00:27.054,962] <wrn> fast_pair: Decrypt failed: err=-13 (Account Key)
[00:00:27.054,992] <dbg> fast_pair: write_account_key: Account Key write: res=-14 conn=0x20002810

To test this hypothesis, you can extend the Fast Pair Key timeout in the following file and line:

https://github.com/nrfconnect/sdk-nrf/blob/main/subsys/bluetooth/services/fast_pair/fp_keys.c#L28

K_SECONDS(10) -> K_SECONDS(20)

Locator Tag example fails at Fast Pair Validator App test "Provisioning"

Top Replies