Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[K32W] Failure during the BLE Rendezvous session #7320

Closed
doru91 opened this issue Jun 2, 2021 · 10 comments
Closed

[K32W] Failure during the BLE Rendezvous session #7320

doru91 opened this issue Jun 2, 2021 · 10 comments

Comments

@doru91
Copy link
Contributor

doru91 commented Jun 2, 2021 •
edited
Loading

SPAKE2+ session is successful. Then the commissioner sends a CSR Request to the DUT, it looks like the DUT replies with a CSR Request Response but the chip-device-ctrl looks to timeout the message.

Head is at

commit f6af7b9c9d86174f2e894d54e90dbf9cef250ad0 (upstream/master, upstream/master)
Author: Song Guo <[email protected]>
Date:   Wed Jun 2 13:15:21 2021 +0800

[python] Add flag to disable BLE for controller (#7179)

I checked with other vendors and everything is ok on their side. I expect that there is a problem on the DUT side. Any help on how to debug this would be appreciated.

Logs on the device side:

[Info]Welcome to NXP ELock Demo App
[Info]OpenThread started: OK
[Info]Setting OpenThread device type to SLEEPY END DEVICE
[Info]OpenThread polling interval set to 1000ms
[Info]Using ZAP configuration...
[Info]deactivate report event
[Info]OpCreds: Initiating OpCreds cluster by writing fabrics list from admin pairing table.
[Info]Set the admin pairing table delegate
[Info]OpCreds: Call to writeAdminsIntoFabricsListAttribute
[Info]OpCreds: Stored 0 admins in fabrics list attribute.
[Info]Unknown cluster ID: 40
[Info]Unknown cluster ID: 40
[Info]Unknown cluster ID: 40
[Info]Unknown cluster ID: 40
[Info]Unknown cluster ID: 40
[Info]Unknown cluster ID: 40
[Info]Unknown cluster ID: 40
[Info]Unknown cluster ID: 40
[Info]Unknown cluster ID: 40
[Info]Init admin pairing table with server storage
[Info]TransportMgr initialized
[Info]local node id is 0x0000000000BC5C01
[Info]Start dns-sd server
[Info]Server Listening...
[Info]SetupQRCode: [CH:Y3.13G3600A50324800]
[Info]Copy/paste the below URL in a browser to see the QR Code:
[Info]https://dhrishi.github.io/connectedhomeip/qrcode.html?data=CH%3AY3.13G3600A50324800
[Info]Manual pairing code: [34970112332]
[Info]Current Firmware Version: 04-2020-te2
[Info]Thread task running
[Info]CHIP task running
[Info]OpenThread State Changed (Flags: 0x00038200)
[Info]   Network Name: OpenThread
[Info]   PAN Id: 0xFFFF
[Info]   Extended PAN Id: 0xDEAD00BEEF00CAFE
[Info]   Channel: 11
[Info]   Mesh Prefix: FDDE:AD00:BEEF::/64
[Info]   Master Key: 4D69D05232A8447494BA06C0AF1F0F5D
[Info]Assigned local session key ID 0
[Info]Waiting for PBKDF param request
[Info]Started BLE Advertising!
[Info]Started Advertising.
[Info]Started NFC Tag Emulation!
[Info]BLE is connected with device: 0.

[Info]Started Advertising.
[Info]NFC Tag emulation is already started!
[Info]BLE MTU size has been changed to 247.
[Info]local and remote recv window sizes = 3
[Info]selected BTP version 3
[Info]using BTP fragment sizes rx 128 / tx 20.
[Info]BLE EndPoint 0x400ea50 Connection Complete
[Info]Long dispatch time: 300 ms
[Info]Received message of type 32 and protocolId 0 on exchange 39017
[Info]ec id: 39017, Delegate: 0x4010420
[Info]Received PBKDF param request
[Info]Sent PBKDF param response
[Info]Long dispatch time: 20760 ms
[Info]Long dispatch time: 140 ms
[Info]Long dispatch time: 210 ms
[Info]Long dispatch time: 150 ms
[Info]Long dispatch time: 290 ms
[Info]Received message of type 34 and protocolId 0 on exchange 39017
[Info]Received spake2p msg1
[Info]Using Object Id --> 28

[Info]Peer assigned session key ID 0
[Info]Sent spake2p msg2
[Info]Long dispatch time: 2380 ms
[Info]Long dispatch time: 210 ms
[Info]Long dispatch time: 140 ms
[Info]Long dispatch time: 210 ms
[Info]Long dispatch time: 210 ms
[Info]Long dispatch time: 210 ms
[Info]Long dispatch time: 210 ms
[Info]Received message of type 36 and protocolId 0 on exchange 39017
[Info]Received spake2p msg3
[Info]New pairing for device 0x0000000000000000, key 0!!
[Info]Device completed SPAKE2+ handshake
[Info]Persisting admin ID 0, next available 1
[Info]Stored value in server storage
[Info]KVS, put key id:: 150
[Info]Admin (0) persisted to storage. Calling OnAdminPersistedToStorage
[Info]OpCreds: Admin 0 was persisted to storage. FabricId 00000000000000000, NodeId 00000000000000000, VendorId 0x0EC9
[Info]OpCreds: Call to writeAdminsIntoFabricsListAttribute
[Info]OpCreds: Skipping over unitialized admin with fabricId 0x0000000000000000, nodeId 0x0000000000000000 vendorId 0x0000
[Info]OpCreds: Stored 0 admins in fabrics list attribute.
[Info]KVS, put key id:: 170
[Info]Persisting admin ID successfully
[Info]Device completed Rendezvous process
[Info]Stored value in server storage
[Info]KVS, put key id:: 241
[Info]Stored value in server storage
[Info]KVS, put key id:: 3
[Info]Long dispatch time: 2660 ms
[Info]Stopped Advertising
[Info]Stopped NFC Tag Emulation!
[Info]Secure transport received message destined to fabric 0, node 0x0000000000097ED1. Key ID 0
[Info]Setting nodeID lX on admin.
[Info]Setting fabricID lX on admin.
[Info]Since admin was modified, persisting changes to KVS
[Info]Stored value in server storage
[Info]KVS, put key id:: 150
[Info]Admin (0) persisted to storage. Calling OnAdminPersistedToStorage
[Info]OpCreds: Admin 0 was persisted to storage. FabricId 00001B66900000000, NodeId 97ed10000000000000000, VendorId 0x0EC9
[Info]OpCreds: Call to writeAdminsIntoFabricsListAttribute
[Info]OpCreds: Skipping over unitialized admin with fabricId 0x000000000001B669, nodeId 0x0000000000097ED1 vendorId 0x0000
[Info]OpCreds: Stored 0 admins in fabrics list attribute.
[Info]Received message of type 8 and protocolId 327680 on exchange 39018
[Info]ec id: 39018, Delegate: 0x4013f08
[Info]ICR moving to [Initialize]
[Info]Received Cluster Command: Cluster=3e Command=hx Endpoint=hx
[Info]OpCreds: commissioner has requested an OpCSR
[Info]OpCreds: Finding admin with fabricId 0x000000000001B669.
[Info]Checking ind:0 [fabricId 0x000000000001B669 nodeId 0x0000000000097ED1 vendorId 0] vs [fabricId 0x000000000001B669 nodeId 0x0000000000000000 vendorId 0]
**[Info]Found a match!
[Info]OpCreds: NewCertificateSigningRequest returned 0
[Info]ICR moving to [AddCommand]
[Info]Secure message was encrypted: Msg ID 1
[Info]Sending msg from 0x0000000000097ED1 to 0x000000000001B669 at utc time: ld msec
[Info]Sending secure msg on generic transport
[Info]Secure msg send status No Error**
[Info]ICR moving to [   Sending]
[Info]ICR moving to [Uninitiali]
[Info]Long dispatch time: 5070 ms
[Info]Long dispatch time: 210 ms
[Info]Long dispatch time: 140 ms
[Info]Long dispatch time: 210 ms
[Info]Long dispatch time: 140 ms
[Info]Long dispatch time: 220 ms
[Info]Long dispatch time: 150 ms
[Info]Long dispatch time: 290 ms
[Info]Long dispatch time: 220 ms
[Info]Long dispatch time: 220 ms
[Info]Long dispatch time: 150 ms
[Info]Long dispatch time: 220 ms
[Info]Long dispatch time: 140 ms
[Info]Long dispatch time: 210 ms
[Info]Long dispatch time: 140 ms
[Info]Long dispatch time: 220 ms
[Info]Long dispatch time: 150 ms
[Info]Long dispatch time: 220 ms
[Info]Long dispatch time: 140 ms
[Info]Clearing BLE pending packets.
[Info]Releasing end point's BLE connection back to application.
[Info]BLE connection timeout: Forcing disconnection.
[Info]Stopped connectionTimeout timer.
[Info]BLE is disconnected with device: 0.

Logs on the chip-device-ctrl side:

chip-device-ctrl > connect -ble 3840 020202021
Device is assigned with nodeid = 622289
CHIP:SC: Assigned local session key ID 0
CHIP:IN: Message appended to BLE send queue
CHIP:SC: Sent PBKDF param request
CHIP:DL: TRACE: Bluez mainloop starting Thread
CHIP:DL: TRACE: Bus acquired for name C-50b1
CHIP:CTL: SyncSetKeyValue on StartKeyID
CHIP:DL: PlatformBlueZInit init success
CHIP:BLE: BLE removing known devices.
CHIP:BLE: BLE initiating scan.
CHIP:BLE: New device scanned: 00:60:37:53:24:DC
CHIP:BLE: Device discriminator match. Attempting to connect.
CHIP:BLE: Scan complete notification without an active scan.
CHIP:DL: ConnectDevice complete
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0013
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0013
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0013
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0013
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0013
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0013
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0013
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0013
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0013
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0013
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0013
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0013
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0001
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0001
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service0001
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: Char1 /org/bluez/hci0/dev_00_60_37_53_24_DC/service000c
CHIP:DL: New BLE connection 0xffff8c038140, device 00:60:37:53:24:DC, path /org/bluez/hci0/dev_00_60_37_53_24_DC
CHIP:DL: HandlePlatformSpecificBLEEvent 16385
CHIP:IN: BleConnectionComplete: endPoint 0xffff972d2fb8
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: HandlePlatformSpecificBLEEvent 16388
CHIP:BLE: subscribe complete, ep = 0xffff972d2fb8
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:BLE: peripheral chose BTP version 3; central expected between 2 and 3
CHIP:BLE: using BTP fragment sizes rx 20 / tx 128.
CHIP:BLE: local and remote recv window size = 3
CHIP:IN: BLE EndPoint 0xffff972d2fb8 Connection Complete
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:EM: Received message of type 33 and protocolId 0 on exchange 39017
CHIP:SC: Received PBKDF param response
CHIP:SC: Sent spake2p msg1
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:EM: Received message of type 35 and protocolId 0 on exchange 39017
CHIP:SC: Received spake2p msg2
CHIP:SC: Peer assigned session key ID 0
CHIP:SC: Sent spake2p msg3
CHIP:IN: New pairing for device 0x0000000000097ed1, key 0!!
CHIP:CTL: Remote device completed SPAKE2+ handshake

CHIP:CTL: Sending OpCSR request to 0x3e5932c8 device
CHIP:DMG: ICR moving to [Initialize]
CHIP:DMG: ICR moving to [AddCommand]
CHIP:IN: Secure message was encrypted: Msg ID 0
CHIP:IN: Sending msg from 0x000000000001B669 to 0x0000000000097ED1 at utc time: 791969033 msec
CHIP:IN: Sending secure msg on generic transport
CHIP:IN: Secure msg send status No Error
CHIP:DMG: ICR moving to [   Sending]
CHIP:CTL: Sent OpCSR request, waiting for the CSR
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:CTL: SyncSetKeyValue on StartKeyID
CHIP:CTL: SyncSetKeyValue on PairedDevice97ed1
Failed to establish secure session to device: 4050
CHIP Error 4050 (0x00000FD2): Timeout
chip-device-ctrl > CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
**CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 39018
CHIP:ZCL: DefaultResponse:
CHIP:ZCL:   Transaction: 0xffff972d1378
CHIP:ZCL:   status: EMBER_ZCL_STATUS_FAILURE (0x01)**
CHIP:CTL: Device failed to receive the CSR request Response: 0x01
CHIP:CTL: SyncSetKeyValue on StartKeyID
Failed to establish secure session to device: 4172
CHIP:DMG: ICR moving to [Uninitiali]
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff8c038140
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:IN: Secure transport received message destined to fabric 0, node 0x000000000001B669. Key ID 0

cc @pan-apple
@pan-apple
Copy link
Contributor

It doesn’t seem that the controller is getting the OpCSR response from the DUT. I can see the DUT did send a message. Can you add more logs in this function to make sure that it did the correct response?

emberAfOperationalCredentialsClusterOpCSRRequestCallback()

The function has logs for error scenarios, but not sure if those are not getting printed for some reason.

For reference, we should see some of the following logs on the controller side when it receives the OpCSR.

[1622647452470] [0x1701a3] CHIP: [EM] Received message of type 9 and protocolId 327680 on exchange 44250
[1622647452470] [0x1701a3] CHIP: [DMG] InvokeCommand =
[1622647452470] [0x1701a3] CHIP: [DMG] {
[1622647452470] [0x1701a3] CHIP: [DMG]  CommandList =
[1622647452470] [0x1701a3] CHIP: [DMG]  [
[1622647452470] [0x1701a3] CHIP: [DMG]          CommandDataElement =
[1622647452470] [0x1701a3] CHIP: [DMG]          {
[1622647452470] [0x1701a3] CHIP: [DMG]                  CommandPath =
[1622647452470] [0x1701a3] CHIP: [DMG]                  {
[1622647452470] [0x1701a3] CHIP: [DMG]                          EndpointId = 0x0,
[1622647452470] [0x1701a3] CHIP: [DMG]                          ClusterId = 0x3e,
[1622647452470] [0x1701a3] CHIP: [DMG]                          CommandId = 0x5,
[1622647452470] [0x1701a3] CHIP: [DMG]                  },
[1622647452470] [0x1701a3] CHIP: [DMG] 
[1622647452470] [0x1701a3] CHIP: [DMG]                  CommandData = 
[1622647452470] [0x1701a3] CHIP: [DMG]                  {
[1622647452470] [0x1701a3] CHIP: [DMG]                          0x0 = [
[1622647452470] [0x1701a3] CHIP: [DMG]                                  0x30, 0x81, 0xcb, 0x30, 0x70, 0x2, 0x1, 0x0, 0x30, 0xe, 0x31, 0xc, 0x30, 0xa, 0x6, 0x3, 0x55, 0x4, 0xa, 0xc, 0x3, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 
[1622647452470] [0x1701a3] CHIP: [DMG]                  ]
[1622647452470] [0x1701a3] CHIP: [DMG]                          0x1 = [
[1622647452470] [0x1701a3] CHIP: [DMG]                                  0x14, 0x5c, 0xbd, 0xd, 0xce, 0xc0, 0xa8, 0x91, 0x9b, 0xd6, 0x73, 0xc4, 0x84, 0xc, 0x2a, 0x57, 0x23, 0xda, 0xa, 0x4, 0xd6, 0x18, 0x1c, 0x10, 0x9e, 0x19, 0xa7, 0xee, 0x60, 0xbd, 0x3e, 0x11, 
[1622647452470] [0x1701a3] CHIP: [DMG]                  ]
[1622647452470] [0x1701a3] CHIP: [DMG]                          0x2 = [
[1622647452470] [0x1701a3] CHIP: [DMG] 
[1622647452470] [0x1701a3] CHIP: [DMG]                  ]
[1622647452470] [0x1701a3] CHIP: [DMG]                          0x3 = [
[1622647452470] [0x1701a3] CHIP: [DMG] 
[1622647452470] [0x1701a3] CHIP: [DMG]                  ]
[1622647452470] [0x1701a3] CHIP: [DMG]                          0x4 = [
[1622647452470] [0x1701a3] CHIP: [DMG] 
[1622647452470] [0x1701a3] CHIP: [DMG]                  ]
[1622647452470] [0x1701a3] CHIP: [DMG]                          0x5 = [
[1622647452470] [0x1701a3] CHIP: [DMG] 
[1622647452470] [0x1701a3] CHIP: [DMG]                  ]
[1622647452470] [0x1701a3] CHIP: [DMG]                  },
[1622647452470] [0x1701a3] CHIP: [DMG]          },
[1622647452470] [0x1701a3] CHIP: [DMG] 
[1622647452470] [0x1701a3] CHIP: [DMG]  ],
[1622647452470] [0x1701a3] CHIP: [DMG] 
[1622647452470] [0x1701a3] CHIP: [DMG] }
[1622647452470] [0x1701a3] CHIP: [ZCL] Received Cluster Command: Cluster=3e Command=5 Endpoint=0
[1622647452470] [0x1701a3] CHIP: [ZCL] OpCSRResponse:
[1622647452470] [0x1701a3] CHIP: [ZCL]   CSR: 206
[1622647452470] [0x1701a3] CHIP: [ZCL]   CSRNonce: 32
[1622647452470] [0x1701a3] CHIP: [ZCL]   VendorReserved1: 0
[1622647452470] [0x1701a3] CHIP: [ZCL]   VendorReserved2: 0
[1622647452470] [0x1701a3] CHIP: [ZCL]   VendorReserved3: 0
[1622647452470] [0x1701a3] CHIP: [ZCL]   Signature: 0
[1622647452470] [0x1701a3] CHIP: [CTL] Received certificate signing request from the device

@doru91
Copy link
Contributor Author

doru91 commented Jun 3, 2021

Thanks @pan-apple for helping me.

I step into emberAfOperationalCredentialsClusterOpCSRRequestCallback and it returns with success.

Then I took a closer look at the logs on the chip-device-ctrl-side:

CHIP:CTL: Sending OpCSR request to 0x2eeabb08 device
CHIP:DMG: ICR moving to [Initialize]
CHIP:DMG: ICR moving to [AddCommand]
CHIP:IN: Secure message was encrypted: Msg ID 0
CHIP:IN: Sending msg from 0x000000000001B669 to 0x0000000000000001 at utc time: 857971535 msec
CHIP:IN: Sending secure msg on generic transport
CHIP:IN: Secure msg send status No Error
CHIP:DMG: ICR moving to [ Sending]
CHIP:CTL: Sent OpCSR request, waiting for the CSR
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff80038120
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff80038120
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff80038120
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff80038120
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DL: Indication received, conn = 0xffff80038120
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: Indication received, conn = 0xffff80038120
CHIP:DL: HandlePlatformSpecificBLEEvent 16389
CHIP:DL: HandlePlatformSpecificBLEEvent 16387
CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 39018
CHIP:ZCL: DefaultResponse:
CHIP:ZCL: Transaction: 0xffff91977378
CHIP:ZCL: status: EMBER_ZCL_STATUS_FAILURE (0x01)
CHIP:CTL: Device failed to receive the CSR request Response: 0x01

So there are some indications that are being received from the device side. Then I looked into the device side, and these indications are being sent immediately after the CSR Op Rsp is generated, so they should contain DER bytes. As long as the SPAKE2+ session was successful, I don't expect that BLE transport lost any byte. Here are the relevant logs on the device side (first I print the DER bytes inside emberAfOperationalCredentialsClusterOpCSRRequestCallback then I print the BLE bytes in BLEManagerImpl.cpp):

[Info]Received message of type 8 and protocolId 327680 on exchange 39018
[Info]ec id: 39018, eived Cluster Command: Cluster=3e Command=hx Endpoint=hx
[Info]OpCreds: commissioner has requested an OpCSR
[Info]OpCreds: Finding admin with fabricId 0x000000000001B669.
[Info]Checking ind:0 [fabricId 0x000000000001B669 deId 0x000000000 0]
[Info]Found a match!
[Info]OpCreds: NewCertificateSigningRequest returned 0
[Info]ICR moving to [AddCommand]
[Info]csr[0]=30
[Info]csr[1]=81
[Info]csr[2]=ca
[Info]csr[3]=30
[Info]csr[4]=70
[Info]csr[5]=2
[Info]csr[6]=1
[Info]csr[7]=0
[Info]csr[8]=30
[Info]csr[9]=e
[Info]csr[10]=31
[Info]csr[11]=c
[Info]csr[12]=30
[Info]csr[13]=a
[Info]csr[14]=6
[Info]csr[15]=3
[Info]csr[16]=55
[Info]csr[17]=4
[Info]csr[18]=a
[Info]csr[19]=c
[Info]csr[20]=3
[Info]csr[21]=43
[Info]csr[22]=53
[Info]csr[23]=52
[Info]csr[24]=30
[Info]csr[25]=59
[Info]csr[26]=30
[Info]csr[27]=13
[Info]csr[28]=6
[Info]csr[29]=7
[Info]csr[30]=2a
[Info]csr[31]=86
[Info]csr[32]=48
[Info]csr[33]=ce
[Info]csr[34]=3d
[Info]csr[35]=2
[Info]csr[36]=1
[Info]csr[37]=6
[Info]csr[38]=8
[Info]csr[39]=2a
[Info]csr[40]=86
[Info]csr[41]=48
[Info]csr[42]=ce
[Info]csr[43]=3d
[Info]csr[44]=3
[Info]csr[45]=1
[Info]csr[46]=7
[Info]csr[47]=3
[Info]csr[48]=42
[Info]csr[49]=0
[Info]csr[50]=4
[Info]csr[51]=f9
[Info]csr[52]=3b
[Info]csr[53]=fd
[Info]csr[54]=b3
[Info]csr[55]=5e
[Info]csr[56]=f
[Info]csr[57]=46
[Info]csr[58]=66
[Info]csr[59]=fa
[Info]csr[60]=d3
[Info]csr[61]=ba
[Info]csr[62]=ab
[Info]csr[63]=f7
[Info]csr[64]=7f
[Info]csr[65]=9b
[Info]csr[66]=da
[Info]csr[67]=49
[Info]csr[68]=25
[Info]csr[69]=12
[Info]csr[70]=55
[Info]csr[71]=28
[Info]csr[72]=be
[Info]csr[73]=d4
[Info]csr[74]=bf
[Info]csr[75]=2b
[Info]csr[76]=a6
[Info]csr[77]=5f
[Info]csr[78]=a4
[Info]csr[79]=52
[Info]csr[80]=61
[Info]csr[81]=f0
[Info]csr[82]=d6
[Info]csr[83]=ec
[Info]csr[84]=14
[Info]csr[85]=b0
[Info]csr[86]=1b
[Info]csr[87]=5e
[Info]csr[88]=8
[Info]csr[89]=d3
[Info]csr[90]=38
[Info]csr[91]=fe
[Info]csr[92]=63
[Info]csr[93]=a6
[Info]csr[94]=65
[Info]csr[95]=fb
[Info]csr[96]=1e
[Info]csr[97]=8f
[Info]csr[98]=37
[Info]csr[99]=e5
[Info]csr[100]=be
[Info]csr[101]=a5
[Info]csr[102]=1a
[Info]csr[103]=17
[Info]csr[104]=86
[Info]csr[105]=ee
[Info]csr[106]=93
[Info]csr[107]=13
[Info]csr[108]=b1
[Info]csr[109]=2e
[Info]csr[110]=62
[Info]csr[111]=40
[Info]csr[112]=3d
[Info]csr[113]=6b
[Info]csr[114]=66
[Info]csr[115]=a0
[Info]csr[116]=0
[Info]csr[117]=30
[Info]csr[118]=c
[Info]csr[119]=6
[Info]csr[120]=8
[Info]csr[121]=2a
[Info]csr[122]=86
[Info]csr[123]=48
[Info]csr[124]=ce
[Info]csr[125]=3d
[Info]csr[126]=4
[Info]csr[127]=3
[Info]csr[128]=2
[Info]csr[129]=5
[Info]csr[130]=0
[Info]csr[131]=3
[Info]csr[132]=48
[Info]csr[133]=0
[Info]csr[134]=30
[Info]csr[135]=45
[Info]csr[136]=2
[Info]csr[137]=20
[Info]csr[138]=a
[Info]csr[139]=ce
[Info]csr[140]=28
[Info]csr[141]=24
[Info]csr[142]=2d
[Info]csr[143]=e1
[Info]csr[144]=94
[Info]csr[145]=e8
[Info]csr[146]=1b
[Info]csr[147]=c0
[Info]csr[148]=9d
[Info]csr[149]=dc
[Info]csr[150]=70
[Info]csr[151]=e0
[Info]csr[152]=2
[Info]csr[153]=45
[Info]csr[154]=b3
[Info]csr[155]=bd
[Info]csr[156]=6f
[Info]csr[157]=40
[Info]csr[158]=27
[Info]csr[159]=a2
[Info]csr[160]=c9
[Info]csr[161]=a4
[Info]csr[162]=be
[Info]csr[163]=67
[Info]csr[164]=6a
[Info]csr[165]=65
[Info]csr[166]=44
[Info]csr[167]=e
[Info]csr[168]=36
[Info]csr[169]=4c
[Info]csr[170]=2
[Info]csr[171]=21
[Info]csr[172]=0
[Info]csr[173]=b9
[Info]csr[174]=6a
[Info]csr[175]=67
[Info]csr[176]=c0
[Info]csr[177]=40
[Info]csr[178]=9c
[Info]csr[179]=e0
[Info]csr[180]=33
[Info]csr[181]=79
[Info]csr[182]=39
[Info]csr[183]=c8
[Info]csr[184]=bc
[Info]csr[185]=c5
[Info]csr[186]=b4
[Info]csr[187]=c2
[Info]csr[188]=14
[Info]csr[189]=7
[Info]csr[190]=8
[Info]csr[191]=96
[Info]csr[192]=67
[Info]csr[193]=a6
[Info]csr[194]=20
[Info]csr[195]=f1
[Info]csr[196]=bf
[Info]csr[197]=3e
[Info]csr[198]=9f
[Info]csr[199]=d0
[Info]csr[200]=35
[Info]csr[201]=d2
[Info]csr[202]=41
[Info]csr[203]=c1
[Info]csr[204]=5d
[Info]Secure message was encrypted: Msg ID 1
[Info]Sending msg from 0x0000000000000001 to 0x000000000001B669 at utc time: ld msec
[Info]Sending secure msg on generic transport
[Info]Trying to send indication. Len: 20
[Info]data[0]=9
[Info]data[1]=9
[Info]data[2]=f
[Info]data[3]=43
[Info]data[4]=1
[Info]data[5]=21
[Info]data[6]=23
[Info]data[7]=1
[Info]data[8]=0
[Info]data[9]=0
[Info]data[10]=0
[Info]data[11]=1
[Info]data[12]=0
[Info]data[13]=0
[Info]data[14]=0
[Info]data[15]=0
[Info]data[16]=0
[Info]data[17]=0
[Info]data[18]=0
[Info]data[19]=69
[Info]BLE Event - Sent :-)
[Info]Secure msg send status No Error
[Info]ICR moving to [   Sending]
[Info]ICR moving to [Uninitiali]
[Info]Long dispatch time: 5250 ms
[Info]Attribute write request(device: 0,handle: 14).
[Info]Write request/command received forCHIPoBLE RX characteristic (con 0, len 3)
[Info]Trying to send indication. Len: 20
[Info]data[0]=2
[Info]data[1]=10
[Info]data[2]=b6
[Info]data[3]=1
[Info]data[4]=0
[Info]data[5]=0
[Info]data[6]=0
[Info]data[7]=0
[Info]data[8]=0
[Info]data[9]=0
[Info]data[10]=0
[Info]data[11]=80
[Info]data[12]=ab
[Info]data[13]=94
[Info]data[14]=91
[Info]data[15]=37
[Info]data[16]=64
[Info]data[17]=e4
[Info]data[18]=64
[Info]data[19]=34
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 180 ms
[Info]Trying to send indication. Len: 20
[Info]data[0]=a
[Info]data[1]=a
[Info]data[2]=11
[Info]data[3]=67
[Info]data[4]=4b
[Info]data[5]=78
[Info]data[6]=1b
[Info]data[7]=8e
[Info]data[8]=4c
[Info]data[9]=6b
[Info]data[10]=f0
[Info]data[11]=c5
[Info]data[12]=9b
[Info]data[13]=c7
[Info]data[14]=38
[Info]data[15]=f0
[Info]data[16]=73
[Info]data[17]=99
[Info]data[18]=a1
[Info]data[19]=39
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 210 ms
[Info]Attribute write request(device: 0,handle: 14).
[Info]Write request/command received forCHIPoBLE RX characteristic (con 0, len 3)
[Info]Trying to send indication. Len: 20
[Info]data[0]=2
[Info]data[1]=12
[Info]data[2]=91
[Info]data[3]=d7
[Info]data[4]=87
[Info]data[5]=fa
[Info]data[6]=49
[Info]data[7]=83
[Info]data[8]=36
[Info]data[9]=98
[Info]data[10]=61
[Info]data[11]=81
[Info]data[12]=d
[Info]data[13]=55
[Info]data[14]=4
[Info]data[15]=e1
[Info]data[16]=f
[Info]data[17]=a9
[Info]data[18]=e8
[Info]data[19]=70
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 200 ms
[Info]Trying to send indication. Len: 20
[Info]data[0]=a
[Info]data[1]=b
[Info]data[2]=13
[Info]data[3]=3f
[Info]data[4]=5d
[Info]data[5]=2b
[Info]data[6]=a
[Info]data[7]=13
[Info]data[8]=b8
[Info]data[9]=4c
[Info]data[10]=cb
[Info]data[11]=e0
[Info]data[12]=21
[Info]data[13]=2e
[Info]data[14]=e4
[Info]data[15]=6f
[Info]data[16]=f7
[Info]data[17]=b0
[Info]data[18]=cb
[Info]data[19]=1b
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 140 ms
[Info]Attribute write request(device: 0,handle: 14).
[Info]Write request/command received forCHIPoBLE RX characteristic (con 0, len 3)
[Info]Trying to send indication. Len: 20
[Info]data[0]=2
[Info]data[1]=14
[Info]data[2]=67
[Info]data[3]=e9
[Info]data[4]=99
[Info]data[5]=d4
[Info]data[6]=e6
[Info]data[7]=e6
[Info]data[8]=bc
[Info]data[9]=a0
[Info]data[10]=6a
[Info]data[11]=83
[Info]data[12]=c2
[Info]data[13]=78
[Info]data[14]=51
[Info]data[15]=6e
[Info]data[16]=6b
[Info]data[17]=e3
[Info]data[18]=a5
[Info]data[19]=fd
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 490 ms
[Info]Trying to send indication. Len: 20
[Info]data[0]=a
[Info]data[1]=c
[Info]data[2]=15
[Info]data[3]=64
[Info]data[4]=1
[Info]data[5]=6e
[Info]data[6]=28
[Info]data[7]=a8
[Info]data[8]=41
[Info]data[9]=6d
[Info]data[10]=2e
[Info]data[11]=9c
[Info]data[12]=15
[Info]data[13]=a7
[Info]data[14]=70
[Info]data[15]=29
[Info]data[16]=62
[Info]data[17]=cc
[Info]data[18]=76
[Info]data[19]=af
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 140 ms
[Info]Attribute write request(device: 0,handle: 14).
[Info]Write request/command received forCHIPoBLE RX characteristic (con 0, len 3)
[Info]Trying to send indication. Len: 20
[Info]data[0]=2
[Info]data[1]=16
[Info]data[2]=51
[Info]data[3]=57
[Info]data[4]=94
[Info]data[5]=a9
[Info]data[6]=e4
[Info]data[7]=37
[Info]data[8]=90
[Info]data[9]=2e
[Info]data[10]=b8
[Info]data[11]=e3
[Info]data[12]=e8
[Info]data[13]=2a
[Info]data[14]=f8
[Info]data[15]=72
[Info]data[16]=2b
[Info]data[17]=68
[Info]data[18]=34
[Info]data[19]=f2
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 200 ms
[Info]Trying to send indication. Len: 20
[Info]data[0]=a
[Info]data[1]=d
[Info]data[2]=17
[Info]data[3]=92
[Info]data[4]=75
[Info]data[5]=41
[Info]data[6]=bf
[Info]data[7]=d6
[Info]data[8]=ea
[Info]data[9]=98
[Info]data[10]=ba
[Info]data[11]=80
[Info]data[12]=4b
[Info]data[13]=fc
[Info]data[14]=57
[Info]data[15]=7c
[Info]data[16]=f9
[Info]data[17]=44
[Info]data[18]=33
[Info]data[19]=e7
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 150 ms
[Info]Attribute write request(device: 0,handle: 14).
[Info]Write request/command received forCHIPoBLE RX characteristic (con 0, len 3)
[Info]Trying to send indication. Len: 20
[Info]data[0]=2
[Info]data[1]=18
[Info]data[2]=70
[Info]data[3]=c
[Info]data[4]=31
[Info]data[5]=8a
[Info]data[6]=c5
[Info]data[7]=48
[Info]data[8]=bd
[Info]data[9]=e7
[Info]data[10]=44
[Info]data[11]=ba
[Info]data[12]=b
[Info]data[13]=bf
[Info]data[14]=c4
[Info]data[15]=d6
[Info]data[16]=4c
[Info]data[17]=ab
[Info]data[18]=7f
[Info]data[19]=b
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 200 ms
[Info]Trying to send indication. Len: 20
[Info]data[0]=a
[Info]data[1]=e
[Info]data[2]=19
[Info]data[3]=a3
[Info]data[4]=85
[Info]data[5]=a8
[Info]data[6]=2e
[Info]data[7]=c
[Info]data[8]=21
[Info]data[9]=66
[Info]data[10]=92
[Info]data[11]=1c
[Info]data[12]=97
[Info]data[13]=ff
[Info]data[14]=8b
[Info]data[15]=c7
[Info]data[16]=32
[Info]data[17]=7
[Info]data[18]=e8
[Info]data[19]=25
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 140 ms
[Info]Attribute write request(device: 0,handle: 14).
[Info]Write request/command received forCHIPoBLE RX characteristic (con 0, len 3)
[Info]Trying to send indication. Len: 20
[Info]data[0]=2
[Info]data[1]=1a
[Info]data[2]=35
[Info]data[3]=5d
[Info]data[4]=63
[Info]data[5]=cc
[Info]data[6]=53
[Info]data[7]=75
[Info]data[8]=d2
[Info]data[9]=78
[Info]data[10]=a2
[Info]data[11]=18
[Info]data[12]=6c
[Info]data[13]=d6
[Info]data[14]=f1
[Info]data[15]=bb
[Info]data[16]=b1
[Info]data[17]=4a
[Info]data[18]=43
[Info]data[19]=16
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 190 ms
[Info]Trying to send indication. Len: 20
[Info]data[0]=a
[Info]data[1]=f
[Info]data[2]=1b
[Info]data[3]=71
[Info]data[4]=c4
[Info]data[5]=40
[Info]data[6]=6c
[Info]data[7]=80
[Info]data[8]=df
[Info]data[9]=c4
[Info]data[10]=67
[Info]data[11]=29
[Info]data[12]=d2
[Info]data[13]=5f
[Info]data[14]=6d
[Info]data[15]=ec
[Info]data[16]=e5
[Info]data[17]=75
[Info]data[18]=58
[Info]data[19]=f7
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 140 ms
[Info]Attribute write request(device: 0,handle: 14).
[Info]Write request/command received forCHIPoBLE RX characteristic (con 0, len 3)
[Info]Trying to send indication. Len: 20
[Info]data[0]=2
[Info]data[1]=1c
[Info]data[2]=a4
[Info]data[3]=72
[Info]data[4]=63
[Info]data[5]=a7
[Info]data[6]=20
[Info]data[7]=74
[Info]data[8]=85
[Info]data[9]=8f
[Info]data[10]=27
[Info]data[11]=fc
[Info]data[12]=5
[Info]data[13]=7d
[Info]data[14]=9e
[Info]data[15]=f9
[Info]data[16]=2
[Info]data[17]=2c
[Info]data[18]=ae
[Info]data[19]=b7
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 200 ms
[Info]Trying to send indication. Len: 20
[Info]data[0]=a
[Info]data[1]=10
[Info]data[2]=1d
[Info]data[3]=5
[Info]data[4]=56
[Info]data[5]=87
[Info]data[6]=fb
[Info]data[7]=78
[Info]data[8]=d2
[Info]data[9]=78
[Info]data[10]=74
[Info]data[11]=df
[Info]data[12]=ee
[Info]data[13]=27
[Info]data[14]=7c
[Info]data[15]=65
[Info]data[16]=2d
[Info]data[17]=b3
[Info]data[18]=c1
[Info]data[19]=a5
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 290 ms
[Info]Attribute write request(device: 0,handle: 14).
[Info]Write request/command received forCHIPoBLE RX characteristic (con 0, len 3)
[Info]Trying to send indication. Len: 20
[Info]data[0]=2
[Info]data[1]=1e
[Info]data[2]=70
[Info]data[3]=f4
[Info]data[4]=38
[Info]data[5]=19
[Info]data[6]=61
[Info]data[7]=d5
[Info]data[8]=89
[Info]data[9]=17
[Info]data[10]=d1
[Info]data[11]=dc
[Info]data[12]=1d
[Info]data[13]=5b
[Info]data[14]=66
[Info]data[15]=6b
[Info]data[16]=92
[Info]data[17]=fb
[Info]data[18]=9c
[Info]data[19]=fc
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 190 ms
[Info]Trying to send indication. Len: 20
[Info]data[0]=a
[Info]data[1]=11
[Info]data[2]=1f
[Info]data[3]=e4
[Info]data[4]=86
[Info]data[5]=13
[Info]data[6]=7c
[Info]data[7]=31
[Info]data[8]=f1
[Info]data[9]=ec
[Info]data[10]=14
[Info]data[11]=98
[Info]data[12]=46
[Info]data[13]=fa
[Info]data[14]=4
[Info]data[15]=f9
[Info]data[16]=27
[Info]data[17]=95
[Info]data[18]=92
[Info]data[19]=3c
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 210 ms
[Info]Attribute write request(device: 0,handle: 14).
[Info]Write request/command received forCHIPoBLE RX characteristic (con 0, len 3)
[Info]Trying to send indication. Len: 20
[Info]data[0]=2
[Info]data[1]=20
[Info]data[2]=5c
[Info]data[3]=bf
[Info]data[4]=9d
[Info]data[5]=30
[Info]data[6]=81
[Info]data[7]=cf
[Info]data[8]=b9
[Info]data[9]=c1
[Info]data[10]=4b
[Info]data[11]=94
[Info]data[12]=89
[Info]data[13]=f5
[Info]data[14]=19
[Info]data[15]=9b
[Info]data[16]=da
[Info]data[17]=12
[Info]data[18]=b8
[Info]data[19]=9b
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 410 ms
[Info]Trying to send indication. Len: 13
[Info]data[0]=e
[Info]data[1]=12
[Info]data[2]=21
[Info]data[3]=52
[Info]data[4]=0
[Info]data[5]=40
[Info]data[6]=92
[Info]data[7]=85
[Info]data[8]=87
[Info]data[9]=ec
[Info]data[10]=25
[Info]data[11]=8
[Info]data[12]=a8
[Info]BLE Event - Sent :-)
[Info]Long dispatch time: 210 ms
[Info]Attribute write request(device: 0,handle: 14).
[Info]Write request/command received forCHIPoBLE RX characteristic (con 0, len 3)
[Info]Trying to send indication. Len: 3
[Info]data[0]=8
[Info]data[1]=14
[Info]data[2]=23
[Info]BLE Event - Sent :-)

@doru91
Copy link
Contributor Author

doru91 commented Jun 3, 2021 •
edited
Loading

After several hours of debugging I found an workaround:

diff --git a/src/messaging/ExchangeContext.cpp b/src/messaging/ExchangeContext.cpp
index 5aa546cda69..ae54556138f 100644
--- a/src/messaging/ExchangeContext.cpp
+++ b/src/messaging/ExchangeContext.cpp
@@ -73,7 +73,9 @@ void ExchangeContext::SetResponseExpected(bool inResponseExpected)

 void ExchangeContext::SetResponseTimeout(Timeout timeout)
 {
-    mResponseTimeout = timeout;
+    ChipLogError(ExchangeManager, "Set timeout %d", timeout);
+
+    mResponseTimeout = timeout * 2;
 }

The initial value for the mResponseTimeout is 30000 (30s?), but the timeout error occurs after 20s - I don't understand why. @pan-apple any idea?
Doubling the value fixed the Rendezvous session.

@pan-apple
Copy link
Contributor

That's really weird. Does doubling it change it to 40s? It would indicate some issue with the timer itself.
Also, 20s should have been long enough to receive the CSR response.

@doru91
Copy link
Contributor Author

doru91 commented Jun 4, 2021

With the default value, the timer always expires in the middle of the CSR response reception - this happens after ~16-17s after the "connect -ble" is issued. However, it's unclear to me if the timer is armed for the whole rendezvous session or only for the CSR response.

@doru91
Copy link
Contributor Author

doru91 commented Jun 8, 2021 •
edited
Loading

This timer issue seems to be related to #7005: the embedded device sent the required packets but the chip-device-ctrl times out.

@pan-apple could you please help me with adding some debug code? I was thinking to print a timestamp when the timer is armed then a timstamp when the timer expires. It's unclear to me when the timer is armed.

@pan-apple
Copy link
Contributor

@doru91 , I think this function is setting up the response timer

CHIP_ERROR CommandSender::SendCommandRequest(NodeId aNodeId, Transport::AdminId aAdminId, SecureSessionHandle * secureSession)

specifically, here

    mpExchangeCtx->SetResponseTimeout(kImMessageTimeoutMsec);

Looks like the default timeout is 6 seconds.

uint32_t kImMessageTimeoutMsec  = 6000;

@pan-apple
Copy link
Contributor

@doru91, I have submitted this issue (#7489) to have a proper fix for the timeouts. For time being, you could probably increase kImMessageTimeoutMsec to 12 seconds. If you plan to go that route, please mention the issue 7489 in the code comment as a TODO.

@doru91 doru91 mentioned this issue Jun 9, 2021
Merged
@doru91
Copy link
Contributor Author

doru91 commented Jun 9, 2021

Perfect, @pan-apple . Submitted #7490

@woody-apple
Copy link
Contributor

Is this resolved?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@doru91 @woody-apple @pan-apple