[BLE] When pairing with Android device (Android 10) the pairing request has to be confirmed twice

[kalle16lab]

Description of defect

When running the example provided Here and attempting to pair the device using nRF Connect app the pairing request confirmation dialog appears twice in a row. The vendor provided Cordio based BLE examples successfully pair on first try.

Target(s) affected by this defect ?

Sparkfun Artemis has been tested but issue does not seem to be Ambiq MCU specific.

Toolchain(s) (name and version) displaying this defect ?

GNU Arm Embedded Toolchain 9-2020-q2-update 9.3.1 20200408 (release)

What version of Mbed-os are you using (tag or sha) ?

mbed commit sha: 26c6b75

What version(s) of tools are you using. List all that apply (E.g. mbed-cli)

Mbed Studio 1.4.1

How is this defect reproduced ?

Compile the example and attempt to pair device to an Android phone using nRF Connect app.

[ciarmcom]

Thank you for raising this detailed GitHub issue. I am now notifying our internal issue triagers.
Internal Jira reference: https://jira.arm.com/browse/IOTOSM-3961

[idea--list]

I find the same with the BLE_Advertising example found here.

The original example is non-connectable, however modifying line 69 like ble::advertising_type_t::CONNECTABLE_UNDIRECTED,
we can convert it to a connectable example.

After doing so we have to connect twice in nRF Connect app in order to find any data under the CLIENT tab.
So it seems the bug might have its roots somewhere else than just the SecurityManager API.

UPDATE: nRF Connect logs Error 133 (0x85): GATT ERROR

[paul-szczepanek-arm]

I'm having trouble reproducing this problem. In the BLE_SecurityAndPrivacy demo I connect and pair (and bond) once. After that the other device will disconnect automatically. When I reconnect again the bond is found and link is encrypted successfully without pairing. I'll try with the advertising example and more boards.

@kalle16lab when you run the example with two boards, do you get a normal log (pair once, and then uses bond information from then on)?

[kalle16lab]

I had not attempted to reconnect to device after pairing but I discovered that reconnecting fails.

The following trace contains boot of device, a pairing event (confirmation dialog on android device appears twice an I accepted twice) and afterwards I attempted to reconnect and this does not succeed.

Also from the main loop the following code has been removed and privacy has been disabled since the controller doesn't support random addresses.

/*
printf("\r\n * Device is a central *\r\n\r\n");
SecurityCentral central(ble, queue);
central.run();
*/

[INFO][BLCO]: WSF Cordio tracing enabled
[INFO][BLE ]: Allocated 9000 bytes for Cordio
[INFO][BLE ]: BLE features enabled: EXTENDED_ADVERTISING GATT_CLIENT GATT_SERVER PERIODIC_ADVERTISING PHY_MANAGEMENT PRIVACY SECURE_CONNECTIONS SECURITY SIGNING WHITELIST
[INFO][BLE ]: BLE roles enabled: PERIPHERAL CENTRAL
[INFO][BLE ]: Initialising Cordio host stack

 * Device is a peripheral *

[INFO][BLPR]: Initialize privacy PAL
[INFO][BLE ]: Initialising BLE instance
[INFO][BLHC]: CordioHCIDriver initializing
[INFO][BLE ]: Reset sequence complete. Controller supported features:
[INFO][BLE ]: 21:00:00:00
[INFO][BLE ]: Initialising extended features
[INFO][BLGS]: Initialize GattServer
[INFO][BLGS]: Add Generic Access Service to the Gatt Server: handle=1
[INFO][BLGS]: Add Device Name characteristic: handle=3
[INFO][BLGS]: Add Appearance characteristic: handle=5
[INFO][BLGS]: Add Peripheral Preferred Connection characteristic: handle=7
[INFO][BLGS]: Add Generic Attribute Service to the Gatt Server: handle=8
[INFO][BLGS]: Add Service Changed characteristic: handle=10
[INFO][BLGP]: Get address - type=PUBLIC, address=00:00:00:00:00:00
Device address: 66:77:88:23:bb:ef
[INFO][BLSM]: SM init: bondable=true, mitm=false, iocaps=IO_CAPS_NONE, passkey=0, signing=false, db_path=0x35984
[INFO][BLSM]: Initialize PAL SM
[INFO][BLSM]: Initialize database. Path = /fs/bt_sec_db
[WARN][BLDB]: Security DB didn't exist, creating new one
[ERR ][BLDB]: Failed to create security DB
[INFO][BLDB]: Using memory security DB (capacity 5 entries) - no persistence across reset
[INFO][BLSM]: Set stack I/O capabilities: NO_INPUT_NO_OUTPUT
[INFO][BLSM]: Set stack display passkey: 30:30:30:30:30:30
[INFO][BLSM]: Initialize resolving list
[INFO][BLSM]: Identity list retrieved: 0 entries to add to the resolving list
[INFO][BLSM]: Clear resolving list
[INFO][BLSM]: Init identity
[INFO][BLSM]: Stack generated random data: af:8e:7a:05:d6:51:e5:17
[INFO][BLSM]: Stack generated random data: 3a:24:17:2d:05:58:a3:1f
[INFO][BLSM]: Random data generated: af:8e:7a:05:d6:51:e5:17:3a:24:17:2d:05:58:a3:1f
[INFO][BLSM]: Set stack local IRK: af:8e:7a:05:d6:51:e5:17:3a:24:17:2d:05:58:a3:1f
[INFO][BLSM]: Set local irk: af:8e:7a:05:d6:51:e5:17:3a:24:17:2d:05:58:a3:1f
[INFO][BLPR]: PAL start generation of RPA from local irk: af:8e:7a:05:d6:51:e5:17:3a:24:17:2d:05:58:a3:1f
[INFO][BLSM]: Set stack local identity address: address = 00:00:00:00:00:00, public = false
[INFO][BLSM]: Set manual handling of pairing request: true
[INFO][BLSM]: Set role reversal hint: true
[INFO][BLGP]: Set peripheral privacy configuration - use_non_resolvable_random_address=false, resolution_strategy=PERFORM_PAIRING_PROCEDURE
[INFO][BLGP]: Advertising set 0: set advertising data - payload=02:01:06:0d:09:53:65:63:75:72:69:74:79:44:65:6d:6f, minimiseFragmentation=true, scan_response=false
[INFO][BLGP]: Advertising set 0: set extended advertising parameters - _advType=CONNECTABLE_UNDIRECTED, _minInterval=640ms, _maxInterval=1280ms, _peerAddressType=PUBLIC, _ownAddressType=RANDOM, _policy=NO_FILTER, _primaryPhy=LE_1M, _secondaryPhy=LE_1M, _peerAddress=00:00:00:00:00:00, _txPower=127, _maxSkip=0, _channel37=true, _channel38=true, _channel39=true, _anonymous=false, _notifyOnScan=false, _legacyPDU=true, _includeHeaderTxPower=false
[INFO][BLDM]: Legacy PDU w/undirected advertising event
[INFO][BLDM]: Advertising set 0: update direct advertising parameters - advertising_type=0, peer_address=00:00:00:00:00:00, peer_address_type=PUBLIC
[INFO][BLGP]: Advertising set 0: set advertising parameters - _advType=CONNECTABLE_UNDIRECTED, _minInterval=640ms, _maxInterval=1280ms, _peerAddressType=PUBLIC, _ownAddressType=PUBLIC, _policy=NO_FILTER, _primaryPhy=LE_1M, _secondaryPhy=LE_1M, _peerAddress=00:00:00:00:00:00, _txPower=127, _maxSkip=0, _channel37=true, _channel38=true, _channel39=true, _anonymous=false, _notifyOnScan=false, _legacyPDU=true, _includeHeaderTxPower=false
[INFO][BLDM]: Advertising set 0: update direct advertising parameters - advertising_type=0, peer_address=00:00:00:00:00:00, peer_address_type=PUBLIC
[INFO][BLGP]: Advertising set 0: start advertising - maxDuration=10000ms, maxEvents=0
[INFO][BLDM]: Set random address - address=00:00:00:00:00:00
[INFO][BLDM]: Advertising enable - enable=true
Advertising...
[INFO][BLPR]: Privacy handling: DM_PRIV_GENERATE_ADDR_IND
[INFO][BLSM]: Resolvable private address generated: 0c:87:c5:3d:18:7c
[INFO][BLGP]: Private address generated - connectable=true
[ERR ][BLGP]: privacy enabled, not passing to event handler
[INFO][BLGP]: Legacy advertising started
[INFO][BLGP]: Connection 1 successfully completed - role=PERIPHERAL, peer_address_type=RANDOM peer_address=ec:19:ad:2f:3a:5a, connection_interval=36, connection_latency=0, supervision_timeout=500, local_resolvable_private_address=00:00:00:00:00:00, peer_resolvable_private_address=00:00:00:00:00:00
[INFO][BLDM]: Advertising enable - enable=false
[INFO][BLSM]: Connection 1 - Open: ltk=false, csrk=false, irk=false
Connected to peer: 5a:3a:2f:ad:19:ec
[INFO][BLSM]: Connection 1 - Set link security: SECURITY_MODE_ENCRYPTION_NO_MITM
[INFO][BLSM]: Connection 1 - Set encryption: ENCRYPTED
[INFO][BLSM]: Connection 1 - Enable encryption
[INFO][BLSM]: Connection 1 - Ltk not available, send slave security request
[INFO][BLSM]: Connection 1 - Initiate security request
[INFO][BLSM]: Connection 1 - Pass slave security to the stack: authentication = 11
[INFO][BLSM]: Connection 1 - Request authentication
[INFO][BLSM]: Connection 1 - ltk not mitm protected, issue slave security request
[INFO][BLSM]: Connection 1 - Initiate security request
[INFO][BLSM]: Connection 1 - Pass slave security to the stack: authentication = 15
[INFO][BLGP]: Connection 1 update successfully completed - connection_interval=6, connection_latency=0,supervision_timeout=500,
[INFO][BLGP]: Connection 1 update successfully completed - connection_interval=36, connection_latency=0,supervision_timeout=500,
[INFO][BLSM]: Handling event DM_SEC_PAIR_IND
[INFO][BLSM]: Connection 1 - pairing request received: use_oob = false, authentication = 0D, initiator_dist = 0F, responder_dist = 0F
[INFO][BLSM]: Connection 1 - Forwarding pairing request to user handler
Pairing requested - authorising
[INFO][BLSM]: Connection 1 - Accept pairing request
[INFO][BLSM]: Connection 1 - Update OOB presence: false
[INFO][BLSM]: Connection 1 - Send pairing response: oob = false, auth = 15, initiator dist = 03, responder dist = 03
[INFO][BLSM]: Handling event DM_SEC_ENCRYPT_IND
[INFO][BLSM]: Connection 1 - Link encryption: updated = ENCRYPTED
Link ENCRYPTED
[INFO][BLSM]: Handling event DM_SEC_KEY_IND
[INFO][BLSM]: Connection 1 - Local LTK distributed: 96:08:1a:73:31:9b:9a:4b:f9:19:03:45:58:2c:b5:44
[INFO][BLDB]: Write DB entry 0: local ltk 96:08:1a:73:31:9b:9a:4b:f9:19:03:45:58:2c:b5:44
[INFO][BLSM]: Connection 1 - Local EDIV/RAND distributed: EDIV = 78:fb, RAND = 13:21:6b:e1:d3:43:ab:ac
[INFO][BLDB]: Write DB entry 0: local ediv 78:fb rand 13:21:6b:e1:d3:43:ab:ac
[INFO][BLSM]: Handling event DM_SEC_KEY_IND
[INFO][BLSM]: Connection 1 - LTK distributed: 3a:bf:c0:18:38:59:7e:39:02:22:fa:06:63:d6:2a:d4
[INFO][BLDB]: Write DB entry 0: peer ltk 3a:bf:c0:18:38:59:7e:39:02:22:fa:06:63:d6:2a:d4
[INFO][BLSM]: Connection 1 - EDIV and RAND distributed: ediv = be:54, rand = df:4e:75:e7:1a:db:37:80
[INFO][BLDB]: Write DB entry 0: peer ediv be:54 rand df:4e:75:e7:1a:db:37:80
[INFO][BLSM]: Handling event DM_SEC_KEY_IND
[INFO][BLSM]: Connection 1 - Peer identity distributed: address = cd:3f:60:2e:b7:dc, public = true
[INFO][BLDB]: Write DB entry 0: public peer address cd:3f:60:2e:b7:dc
[INFO][BLSM]: Connection 1 - IRK distributed: 90:7e:eb:76:4a:f8:9f:d5:c4:73:1b:f9:2b:49:c6:e1
[INFO][BLDB]: Write DB entry 0: peer irk 90:7e:eb:76:4a:f8:9f:d5:c4:73:1b:f9:2b:49:c6:e1
[INFO][BLSM]: Handling event DM_SEC_PAIR_CMPL_IND
[INFO][BLSM]: Connection 1 - Pairing successfully completed
[INFO][BLSM]: Connection 1 - Retrieve identity address to register it into resolving list
[INFO][BLSM]: Security identity retrieved for entry 0x100086A0: address: cd:3f:60:2e:b7:dc, public: true, irk: 90:7e:eb:76:4a:f8:9f:d5:c4:73:1b:f9:2b:49:c6:e1
[INFO][BLSM]: Add device to resolving list: peer address=cd:3f:60:2e:b7:dc, type=PUBLIC, peer irk=90:7e:eb:76:4a:f8:9f:d5:c4:73:1b:f9:2b:49:c6:e1
Pairing successful
[INFO][BLGP]: Connection 1: disconnect - reason=USER_TERMINATION
[INFO][BLGP]: Disconnection 1 successfully completed - reason=22
[INFO][BLSM]: Connection 1 - Process disconnection
[INFO][BLSM]: Connection 1 - Remove stack peer CSRK
Disconnected.

We are bonded, we will only accept known devices
[INFO][BLGP]: Set peripheral privacy configuration - use_non_resolvable_random_address=false, resolution_strategy=REJECT_NON_RESOLVED_ADDRESS
[INFO][BLGP]: Advertising set 0: set advertising data - payload=02:01:06:0d:09:53:65:63:75:72:69:74:79:44:65:6d:6f, minimiseFragmentation=true, scan_response=false
[INFO][BLGP]: Advertising set 0: set advertising parameters - _advType=CONNECTABLE_UNDIRECTED, _minInterval=640ms, _maxInterval=1280ms, _peerAddressType=PUBLIC, _ownAddressType=PUBLIC, _policy=NO_FILTER, _primaryPhy=LE_1M, _secondaryPhy=LE_1M, _peerAddress=00:00:00:00:00:00, _txPower=127, _maxSkip=0, _channel37=true, _channel38=true, _channel39=true, _anonymous=false, _notifyOnScan=false, _legacyPDU=true, _includeHeaderTxPower=false
[INFO][BLDM]: Advertising set 0: update direct advertising parameters - advertising_type=0, peer_address=00:00:00:00:00:00, peer_address_type=PUBLIC
[INFO][BLGP]: Advertising set 0: start advertising - maxDuration=0ms, maxEvents=0
[INFO][BLDM]: Set random address - address=00:00:00:00:00:00
[INFO][BLDM]: Advertising enable - enable=true
Advertising...
[INFO][BLGP]: Legacy advertising started
[INFO][BLGP]: Connection 1 successfully completed - role=PERIPHERAL, peer_address_type=RANDOM peer_address=ec:19:ad:2f:3a:5a, connection_interval=36, connection_latency=0, supervision_timeout=500, local_resolvable_private_address=00:00:00:00:00:00, peer_resolvable_private_address=00:00:00:00:00:00
[INFO][BLDM]: Advertising enable - enable=false
[INFO][BLGP]: Connection 1: disconnecting - reason=AUTHENTICATION_FAILURE
[INFO][BLGP]: Disconnection 1 successfully completed - reason=5
[INFO][BLSM]: Connection 1 - Process disconnection
[ERR ][BLSM]: Connection 1 - Error, control block not available
Disconnected.

Sidenote: tracing on BLE is quite buggy and broken. Intermittently I get file accessed in ISR crashes or other seg-fault crashes.

Advertising...
[INFO][BLPR]: Privacy handling: DM_PRIV_GENERATE_ADDR_IND
[INFO][BLSM]: Resolvable private address generated: 16:2d:46:05:d8:5e
[INFO][BLGP]: Private address generated - connectable=true
[ERR ][BLGP]: privacy enabled, not passing to event handler
[INFO][BLGP]: Legacy advertising started


++ MbedOS Error Info ++
Error Status: 0x8001012F Code: 303 Module: 1
Error Message: Error - writing to a file in an ISR or critical section

Location: 0x2EDA1
Error Value: 0x1
Current Thread: rtx_idle Id: 0x10001708 Entry: 0xFAB5 StackSize: 0x200 StackMem: 0x10001A50 SP: 0x1005FD4C
For more info, visit: https://mbed.com/s/error?error=0x8001012F&tgt=AMBIQ_EVK

@kalle16lab Thanks for reporting the issue with BLE traces. I suspect it's related to #14574. Unfortunately, that PR got blocked by #14426 and other CI-related issues. I removed the blocking commits, so we should be able to merge the fix ASAP.

[AGlass0fMilk]

I will preface this with the information that I'm working on the latest Mbed-OS master (14e5d30) with the fixes from #14574 and #14673

I am seeing a similar issue with Android (Samsung Galaxy S10 Lite, Model #: SM-G770U1, Android version 10).

I do not enable privacy at runtime (I have not disabled privacy at the configuration level yet) and I have a file system set up to store the bonding credentials. When I connect with the above Android phone (using PunchThrough LightBlue), the pairing screen shows up twice. Attempting to reconnect fails the first time. The second reconnection attempt shows the two pairing popups again. I assume the credentials are being purged by the Anrdoid phone after the first failed reconnection attempt.

I also tried to pair/bond with nRF Connect Desktop using an nRF52840 dongle as the interface. In this setup, the pairing goes fine the first time (no double pairing popup). A subsequent reconnection fails with the following log output in nRF Connect:

Here are the corresponding BLE traces on the Mbed device side (not sure if I can enable even more traces, let me know if I can):

nrf-connect-hci-different-transaction-collision.log

Traces for the Android connection:
android-pairing-trace.log
(Note: when I collected these logs, the first reconnection attempt just performed pairing twice again...)

@noonfom @pan- @paul-szczepanek-arm

I have several customer projects that require BLE pairing. This is one of the last outstanding issues for most of them. I am willing to work closely with you to get this fixed as quickly as possible...

I think Mbed-OS really needs some automated testing infrastructure to ensure compatibility with major operating systems over BLE...

[AGlass0fMilk]

This is related to the defect I reported in #14611 @paul-szczepanek-arm

[pan-]

@AGlass0fMilk @kalle16lab I made some progress and observed the following things:

• The issue does not affect all android versions. It is visible on Android 10 but not on Android 8 for example.
• The issue is visible when the device issue a slave security request.
• The issue doesn't seems to be related to timing, sending the slave security request 5 seconds after the connection has been established displays the pairing pop up twice.
• The issue is visible when privacy is not enabled.

The workaround at the moment is to keep privacy disabled and set the peripheral privacy strategy to DO_NOT_RESOLVE.

@paul-szczepanek-arm Can you make sure that Gap::apply_peripheral_privacy_connection_policy is only applied when privacy is enabled ? Slave security request is issued according to the privacy strategy even if the privacy is not enabled.

[AGlass0fMilk]

@pan-

Thanks for the update. I did notice that when I configured ble.ble-feature-privacy to false the issue did not happen.

Any idea what might be causing the BLE_HCI_DIFFERENT_TRANSACTION_COLLISION error when reconnecting with nRF connect? Not that this needs to be a supported peer, but we shouldn't have problems with any peer. I still see this issue even when I disable privacy at the configuration level.

I will do some more testing and see if there are still pairing/bonding issues with iOS/Android.

Did my sniffer logs help at all? I can collect more of them if so. I'm apprehensive to share them publicly on GH because they may contain some customer details.

[AGlass0fMilk]

Also, what do you think about the automated integration testing with iOS/Android/desktop operating systems...?

I would target mobile OS's first. Write a simple native app for iOS and Android that performs various common use cases (eg: unpaired connection, paired connection, reading/writing characteristics, etc). For Android the automation is simple, you can probably accomplish everything through the android debug bridge (adb).

For iOS, it's obviously a bit more complicated. You need a Mac to build. I haven't done iOS development before, but from my research Xcode has support for (on-device?) unit testing and "UI testing". UI testing seems to allow you to automate interacting with UI elements (eg: pressing buttons to pair, etc). So perhaps that's a path forward...

I know there's a lot on the roadmap already, but I really think this would help find bugs before they become issues. Otherwise, we're using our userbase as "automated testing" 😁