Android App failed to commission lighting app - Connect hands hake timed out #8774

fengli · 2021-08-04T01:17:19Z

Problem

On test-event-4 branch, I was testing android example app to commission lighting app and it failed with BLE : connect handshake timed out, closing ep 0x7a059745f0.

Setup:

Tested with test-event-4 branch.
Android example app was deployed to Pixel XL with Android 8.1.0.
Lighting app was built and ran on Raspberry-PI with ubuntu server.
QR code (to scan with chip android app):

./out/host/obj/src/qrcodetool/bin/qrcodetool generate-qr-code -f a.txt
CHIP:TOO: Executing cmd generate-qr-code

CHIP:TOO: setup_payload_operation_generate_qr_code

CHIP:SPL: Loaded vendorID: 9050
CHIP:SPL: Loaded productID: 65279
CHIP:SPL: Loaded discriminator: 3840
CHIP:SPL: Loaded setupPinCode: 20202021
CHIP:TOO: QR Code: MT:YNJV7PF100KA0648G00

Relevant output from Android example app:
Full log see: device_log.txt

08-03 17:34:40.412   956   956 D CTL     : newDeviceController() called
08-03 17:34:40.412   956   956 D TOO     : KVS: Getting key ExampleOpCredsCAKey
08-03 17:34:40.412   956   956 D TOO     : KVS: Getting key afeng ExampleOpCredsCAKey
08-03 17:34:40.412   956   956 D TOO     : KVS: Getting key error 0
08-03 17:34:40.412   956   956 D TOO     : KVS: Getting key ExampleOpCredsICAKey
08-03 17:34:40.412   956   956 D TOO     : KVS: Getting key afeng ExampleOpCredsICAKey
08-03 17:34:40.412   956   956 D TOO     : KVS: Getting key error 0
08-03 17:34:40.413   956   956 D IN      : TransportMgr initialized
08-03 17:34:40.413   956   956 D DIS     : Init admin pairing table with server storage
08-03 17:34:40.413   956   956 D TOO     : KVS: Getting key CHIPAdmin0
08-03 17:34:40.413   956   956 D TOO     : KVS: Getting key afeng CHIPAdmin0
08-03 17:34:40.413   956   956 D TOO     : KVS: Getting key error 0
08-03 17:34:40.413   956   956 D IN      : Loading certs from KVS
08-03 17:34:40.413   956   956 D IN      : local node id is 0x000000000001B669
08-03 17:34:40.413   956   956 D ZCL     : Using ZAP configuration...
08-03 17:34:40.413   956   956 D ZCL     : deactivate report event
08-03 17:34:40.413   956   956 D CTL     : Getting operational keys
08-03 17:34:40.413   956   956 D CTL     : Generating credentials
08-03 17:34:40.413   956   956 D CTL     : Loaded credentials successfully
08-03 17:34:40.413   956   956 D TOO     : KVS: Getting key StartKeyID
08-03 17:34:40.413   956   956 D TOO     : KVS: Getting key afeng StartKeyID
08-03 17:34:40.413   956   956 D TOO     : KVS: Getting key error 0

...

08-03 17:34:44.337   956  1024 D BluetoothGatt: onClientConnectionState() - status=0 clientIf=8 device=DC:A6:32:EC:31:F1
08-03 17:34:44.338   956  1024 I chip.BluetoothManager|onConnectionStateChange: Discovering Services...
08-03 17:34:44.338   956  1024 D BluetoothGatt: discoverServices() - device: DC:A6:32:EC:31:F1

...

08-03 17:34:45.800   956  1024 D BluetoothGatt: onConfigureMTU() - Device=DC:A6:32:EC:31:F1 mtu=131 status=0
08-03 17:34:45.800   956  1024 D chip.BluetoothManager: MTU changed: connecting to CHIP device
08-03 17:34:45.819   956   956 D ChipDeviceController: Bluetooth connection added with ID: 1
08-03 17:34:45.820   956   956 D ChipDeviceController: Pairing device with ID: 2
08-03 17:34:45.820   956   956 D CTL     : pairDevice() called with device ID, connection object, and pincode
08-03 17:34:45.820   956   956 D TOO     : KVS: Getting key ListPairedDevices0
08-03 17:34:45.820   956   956 D TOO     : KVS: Getting key afeng ListPairedDevices0
08-03 17:34:45.820   956   956 D KeyValueStoreManager: Key 'ListPairedDevices0' not found in shared preferences
08-03 17:34:45.820   956   956 D TOO     : KVS: Getting key error 4016
08-03 17:34:45.822   956   956 D IN      : BleConnectionComplete: endPoint 0x7a059745f0
08-03 17:34:45.822   956   956 D CTL     : Received GetMTU
08-03 17:34:45.822   956   956 D CTL     : Calling Java onGetMTU
08-03 17:34:45.822   956   956 D AndroidChipStack: Android Manufacturer: (Google)
08-03 17:34:45.822   956   956 D AndroidChipStack: Android Model: (Pixel XL)
08-03 17:34:45.822   956   956 D CTL     : Received SendCharacteristic
08-03 17:34:45.822   956   956 D CTL     : Calling Java SendCharacteristic
08-03 17:34:45.824   956   956 D SC      : Assigned local session key ID 3
08-03 17:34:45.824   956   956 D IN      : Message appended to BLE send queue
08-03 17:34:45.824   956   956 D SC      : Sent PBKDF param request
08-03 17:34:45.824   956   956 D TOO     : KVS: Setting key StartKeyID
08-03 17:34:45.846   956  1024 D chip.BluetoothManager: MATTER-3840.onCharacteristicWrite: 18ee2ef5-263d-4559-959f-4f9c429f9d11 -> 0
08-03 17:34:45.846   956  1024 D CTL     : Received SubscribeCharacteristic
08-03 17:34:45.846   956  1024 D CTL     : Calling Java SubscribeCharacteristic
08-03 17:34:45.846   956  1024 D BluetoothGatt: setCharacteristicNotification() - uuid: 18ee2ef5-263d-4559-959f-4f9c429f9d12 enable: true
08-03 17:34:45.875   956   986 D chip.BluetoothManager: MATTER-3840.onDescriptorWrite: 00002902-0000-1000-8000-00805f9b34fb -> 253
08-03 17:34:45.876   956   986 E AndroidChipStack: onDescriptorWrite for 00002902-0000-1000-8000-00805f9b34fb failed with status: 253
08-03 17:34:45.876   956   986 D BLE     : subscribe complete, ep = 0x7a059745f0

08-03 17:35:00.823   956  1019 E BLE     : connect handshake timed out, closing ep 0x7a059745f0
08-03 17:35:00.823   956  1019 E IN      : Failed to establish BLE connection: Ble Error 6021 (0x00001785): Connect handshake timed out
08-03 17:35:00.823   956  1019 D IN      : Clearing BLE pending packets.
08-03 17:35:00.823   956  1019 D CTL     : Received UnsubscribeCharacteristic
08-03 17:35:00.824   956  1019 D CTL     : Calling Java UnsubscribeCharacteristic
08-03 17:35:00.826   956  1019 D BluetoothGatt: setCharacteristicNotification() - uuid: 18ee2ef5-263d-4559-959f-4f9c429f9d12 enable: false
08-03 17:35:00.914   671   865 I nanohub : osLog: [AR_CHRE] still: 49
08-03 17:35:00.915   671   865 I nanohub : osLog: [AR_CHRE] ON => IDLE
08-03 17:35:00.920   671   865 I nanohub : osLog: [AR_CHRE] IDLE => ON
08-03 17:35:01.070   956   986 D chip.BluetoothManager: MATTER-3840.onDescriptorWrite: 00002902-0000-1000-8000-00805f9b34fb -> 0
08-03 17:35:01.070   956   986 D BLE     : Auto-closing end point's BLE connection.
08-03 17:35:01.071   956   986 D CTL     : Received CloseConnection
08-03 17:35:01.071   956   986 D CTL     : Calling Java CloseConnection
08-03 17:35:01.071   956   986 D ChipDeviceController: Closing GATT and removing connection for 1
08-03 17:35:01.071   956   986 D BluetoothGatt: close()
08-03 17:35:01.071   956   986 D BluetoothGatt: unregisterApp() - mClientIf=8
08-03 17:35:01.075   956   986 D ChipDeviceController: Calling onCloseBleComplete()

Relevant output from lighting app

[1628028783.418380][107509:107512] CHIP:DL: Device 7C:A2:E7:D1:DA:A8 (Path: /org/bluez/hci0/dev_7C_A2_E7_D1_DA_A8) Connected
[1628028785.956335][107509:107512] CHIP:DL: BluezCharacteristicAcquireWrite is called, conn: 0xffff8002fb90
[1628028785.958532][107509:107512] CHIP:DL: c1 BluezCharacteristicWriteFD mtu, 517
[1628028785.958747][107509:107512] CHIP:BLE: Write request received debug 0xffff8002fb90
[1628028785.958990][107509:107509] CHIP:BLE: local and remote recv window sizes = 3
[1628028785.959062][107509:107509] CHIP:BLE: selected BTP version 3
[1628028785.959107][107509:107509] CHIP:BLE: using BTP fragment sizes rx 128 / tx 20.
[1628028800.961313][107509:107509] CHIP:BLE: receive handshake timed out, closing ep 0xaaaacf09a318
[1628028800.961407][107509:107509] CHIP:IN: Clearing BLE pending packets.
[1628028800.961458][107509:107509] CHIP:BLE: Releasing end point's BLE connection back to application.
[1628028800.961510][107509:107509] CHIP:BLE: Got notification regarding chip connection closure
[1628028802.336948][107509:107512] CHIP:DL: Bluez disconnected
[1628028802.337035][107509:107512] CHIP:DL: Bluez notify CHIPoBluez connection disconnected

Notes

Tested also with chip-tool running on macbook and lighting-app on Raspberry-PI, the commission succeeded.

Proposed Solution

N/A

The text was updated successfully, but these errors were encountered:

austinh0 · 2021-08-04T02:50:20Z

This is the same as #7078, but for Linux (Bluez).

08-03 17:34:45.875   956   986 D chip.BluetoothManager: MATTER-3840.onDescriptorWrite: 00002902-0000-1000-8000-00805f9b34fb -> 253
08-03 17:34:45.876   956   986 E AndroidChipStack: onDescriptorWrite for 00002902-0000-1000-8000-00805f9b34fb failed with status: 253

253 = 0xFD. In the bluedroid source we can see that this represents Client Characteristic Configuration Descriptor Improperly Configured. I guess we need some Linux platform changes?

jmartinez-silabs · 2021-08-04T17:56:54Z

Android chip-tool was not working with efr32 at the time of TE4 branch.
#8666 fixed it on master. For TE4 use python controller or chip-tool on your computer

fengli · 2021-08-04T18:51:19Z

@jmartinez-silabs will the fix for EFR32 also fix lighting-app on Linux? I saw there's some platform specific change for EFR32 in the fix for #8666

jmartinez-silabs · 2021-08-05T02:48:12Z

@fengli the fix i linked only applies to efr32. I do not know if it is the same issue with linux app

austinh0 · 2021-08-05T22:50:21Z

Looking at the code now. Unfortunately I don't have a Linux machine to test on; I ordered a raspberry pi but it will take a couple days to arrive.

TE-N-ElvenWang · 2021-08-30T03:12:10Z

Hi, is there any progress with this issue?
I see this still not fixed on Aug 30's master tree.

Thanks.

austinh0 · 2021-08-30T18:27:31Z

@Damian-Nordic Do you have any update here?

xylophone21 · 2021-09-06T08:45:02Z

I meet the same issue, any update on this?

Damian-Nordic · 2021-09-07T06:35:48Z

Hi, I tried the following changes yesterday to support BLE notifications on the Linux peripheral side:

diff --git a/src/platform/Linux/bluez/Helper.cpp b/src/platform/Linux/bluez/Helper.cpp
index f784eb56c..8929f12b7 100644
--- a/src/platform/Linux/bluez/Helper.cpp
+++ b/src/platform/Linux/bluez/Helper.cpp
@@ -1227,8 +1227,8 @@ exit:
 static void BluezPeripheralObjectsSetup(gpointer apClosure)
 {
 
-    static const char * const c1_flags[] = { "write", nullptr };
-    static const char * const c2_flags[] = { "read", "indicate", nullptr };
+    static const char * const c1_flags[] = { "write", "write-without-response", nullptr };
+    static const char * const c2_flags[] = { "read", "indicate", "notify", nullptr };
     static const char * const c3_flags[] = { "read", nullptr };
 
     BluezEndpoint * endpoint = static_cast<BluezEndpoint *>(apClosure);

Unfortunately, it's not enough and although the processing goes a little bit further, Bluez somehow doesn't deliver the second message to the app. I'm afraid I won't have time to investigate it further this week, but I'm pasting the diff in case someone else has spare time to take a look into that.

TE-N-ElvenWang · 2021-09-08T02:31:22Z

Get the application work if revert below change.
Tested on Linux and K32W Lock.

commit bc3d6bf
Author: Robert Farnum [email protected]
Date: Tue Apr 6 21:52:32 2021 -0500

Android: use ENABLE_NOTIFICATION_VALUE instead of ENABLE_INDICATION_VALUE (#5784)

* Fix Issue#5593

* Fix Issue#5593

* Merge with master

* issue#5593 merge with master

* issue#5593 do not reformat code

* issue#5593 apply patch failure on second part

* Restyled by whitespace

Co-authored-by: Restyled.io <[email protected]>

TE-N-ElvenWang · 2021-09-28T00:35:22Z

Hi everyone,
Looks there is still no formal fix of this issue. The indication and notification in BLE seems still not align in every platforms.

stale · 2022-12-11T19:38:02Z

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs.

stale · 2023-06-09T21:19:03Z

This issue has been automatically marked as stale because it has not had recent activity. It will be closed if no further activity occurs.

yunhanw-google · 2023-08-09T03:14:52Z

not reproduced

This was referenced Aug 4, 2021

Android app failed to commission EFR32 Light App(CHIP over Thread device) #8502

Closed

BLE connection failure between Android chip tool and EFR32 Lock App #7078

Closed

austinh0 mentioned this issue Aug 5, 2021

Android CHIPTool pairing fail during "PROVISION CHIP DEVICE WITH WI-FI" #8655

Closed

austinh0 self-assigned this Aug 5, 2021

Damian-Nordic self-assigned this Aug 6, 2021

woody-apple added android V1.0 labels Jan 26, 2022

andy31415 added v1_triage_split_6 android V1.0 and removed android V1.0 v1_triage_split_6 labels Jan 30, 2022

woody-apple added the deferral candidate label Jun 7, 2022

woody-apple added v1.1 and removed V1.0 deferral candidate labels Jun 14, 2022

stale bot added the stale Stale issue or PR label Jun 9, 2023

yunhanw-google closed this as completed Aug 9, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Android App failed to commission lighting app - Connect hands hake timed out #8774

Android App failed to commission lighting app - Connect hands hake timed out #8774

fengli commented Aug 4, 2021 •

edited

Loading

austinh0 commented Aug 4, 2021

jmartinez-silabs commented Aug 4, 2021

fengli commented Aug 4, 2021

jmartinez-silabs commented Aug 5, 2021

austinh0 commented Aug 5, 2021

TE-N-ElvenWang commented Aug 30, 2021

austinh0 commented Aug 30, 2021

xylophone21 commented Sep 6, 2021

Damian-Nordic commented Sep 7, 2021

TE-N-ElvenWang commented Sep 8, 2021

TE-N-ElvenWang commented Sep 28, 2021

stale bot commented Dec 11, 2022

stale bot commented Jun 9, 2023

yunhanw-google commented Aug 9, 2023

Android App failed to commission lighting app - Connect hands hake timed out #8774

Android App failed to commission lighting app - Connect hands hake timed out #8774

Comments

fengli commented Aug 4, 2021 • edited Loading

Problem

Proposed Solution

austinh0 commented Aug 4, 2021

jmartinez-silabs commented Aug 4, 2021

fengli commented Aug 4, 2021

jmartinez-silabs commented Aug 5, 2021

austinh0 commented Aug 5, 2021

TE-N-ElvenWang commented Aug 30, 2021

austinh0 commented Aug 30, 2021

xylophone21 commented Sep 6, 2021

Damian-Nordic commented Sep 7, 2021

TE-N-ElvenWang commented Sep 8, 2021

TE-N-ElvenWang commented Sep 28, 2021

stale bot commented Dec 11, 2022

stale bot commented Jun 9, 2023

yunhanw-google commented Aug 9, 2023

fengli commented Aug 4, 2021 •

edited

Loading