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

chip-device-ctrl connected error #7390

Closed
ChengqiangShe opened this issue Jun 4, 2021 · 4 comments · Fixed by #7727
Closed

chip-device-ctrl connected error #7390

ChengqiangShe opened this issue Jun 4, 2021 · 4 comments · Fixed by #7727

Comments

@ChengqiangShe
Copy link

When I use chip-device-ctrl to configure a device, an error is displayed

chip-device-ctrl and device commit：test_event_3_2021_06_03

bb8a6ef

@jmartinez-silabs
Can you help me find out what caused it, how do I need to solve this problem here?

chip-device-ctrl logs：

(python_env) chengqiang@chengqiang-desktop:~/Desktop/connectedhomeip$ chip-device-ctrl 
[1622792402.317171][8360] CHIP:IN: local node id is 0x000000000001B669
[1622792402.318456][8360] CHIP:DL: MDNS failed to join multicast group on eth0 for address type IPv4: Inet Error 1016 (0x000003F8): Address not found
[1622792402.319958][8360] CHIP:DL: MDNS failed to join multicast group on wpan0 for address type IPv4: Inet Error 1016 (0x000003F8): Address not found
[1622792402.320735][8360] CHIP:ZCL: Using ZAP configuration...
[1622792402.320837][8360] CHIP:ZCL: deactivate report event
[1622792402.320885][8360] CHIP:CTL: Getting operational keys
[1622792402.322067][8360] CHIP:CTL: Generating operational certificate for the controller
[1622792402.323233][8360] CHIP:CTL: Getting root certificate for the controller from the issuer
[1622792402.323720][8360] CHIP:CTL: Generating credentials
[1622792402.324034][8360] CHIP:CTL: Loaded credentials successfully
[1622792402.337505][8369] CHIP:DL: Platform main loop started.
Chip Device Controller Shell

chip-device-ctrl > 
chip-device-ctrl > connect -ble 3840 73141520 1232
Device is assigned with nodeid = 1232
[1622792446.882316][8364] CHIP:BLE: BLE removing known devices.
[1622792446.882395][8364] CHIP:BLE: BLE initiating scan.
[1622792447.368815][8364] CHIP:BLE: New device scanned: 4E:A7:F9:B4:3C:7A
[1622792447.369012][8364] CHIP:BLE: Device discriminator match. Attempting to connect.
[1622792447.373847][8364] CHIP:BLE: Scan complete notification without an active scan.
[1622792448.460473][8364] CHIP:DL: FAIL: ConnectDevice : GDBus.Error:org.bluez.Error.Failed: Software caused connection abort
Failed to establish secure session to device: 4050
CHIP Error 4050 (0x00000FD2): Timeout
[1622792476.864653][8368] CHIP:SC: PASESession timed out while waiting for a response from the peer. Expected message type was 33
Failed to establish secure session to device: 4050
chip-device-ctrl > 
chip-device-ctrl > connect -ble 3840 73141520 1232
Device is assigned with nodeid = 1232
[1622792520.528054][8364] CHIP:BLE: BLE removing known devices.
[1622792520.528139][8364] CHIP:BLE: BLE initiating scan.
[1622792521.280073][8364] CHIP:BLE: New device scanned: 4E:A7:F9:B4:3C:7A
[1622792521.280139][8364] CHIP:BLE: Device discriminator match. Attempting to connect.
[1622792521.283768][8364] CHIP:BLE: Scan complete notification without an active scan.
[1622792523.696654][8369] CHIP:BLE: subscribe complete, ep = 0xffffbbb24f40
[1622792523.696742][8369] CHIP:BLE: peripheral chose BTP version 3; central expected between 2 and 3
[1622792523.696766][8369] CHIP:BLE: using BTP fragment sizes rx 20 / tx 128.
[1622792523.696782][8369] CHIP:BLE: local and remote recv window size = 3
[1622792525.646112][8368] CHIP:EM: Received message of type 33 and protocolId 0 on exchange 39018
[1622792531.790033][8369] CHIP:EM: Received message of type 35 and protocolId 0 on exchange 39018
[1622792531.795485][8369] CHIP:IN: Sending msg from 0x000000000001B669 to 0x00000000000004D0 at utc time: 1066608 msec
[1622792531.795556][8369] CHIP:IN: Sending secure msg on generic transport
[1622792531.795602][8369] CHIP:IN: Secure msg send status No Error
[1622792537.006475][8368] CHIP:IN: Secure transport received message destined to fabric 0, node 0x000000000001B669. Key ID 1
[1622792537.006740][8368] CHIP:IN: Setting fabricID 4D0 on admin.
[1622792537.006804][8368] CHIP:IN: Since admin was modified, persisting changes to KVS
[1622792537.006951][8368] CHIP:EM: Received message of type 9 and protocolId 327680 on exchange 39019
[1622792537.007316][8368] CHIP:ZCL: OpCSRResponse:
[1622792537.007435][8368] CHIP:ZCL:   CSR: 204
[1622792537.007473][8368] CHIP:ZCL:   CSRNonce: 32
[1622792537.007506][8368] CHIP:ZCL:   VendorReserved1: 0
[1622792537.007651][8368] CHIP:ZCL:   VendorReserved2: 0
[1622792537.007755][8368] CHIP:ZCL:   VendorReserved3: 0
[1622792537.007854][8368] CHIP:ZCL:   Signature: 0
[1622792537.007960][8368] CHIP:CTL: Received certificate signing request from the device
[1622792537.008100][8368] CHIP:CTL: Generating operational certificate for device 4d0
[1622792537.010550][8368] CHIP:CTL: Getting intermediate CA certificate from the issuer
[1622792537.010625][8368] CHIP:CTL: GetIntermediateCACertificate returned 4190
[1622792537.010662][8368] CHIP:CTL: Intermediate CA is not needed
[1622792537.010838][8368] CHIP:CTL: Sending operational certificate to the device. Op Cert Len 255, ICA Cert Len 0
[1622792537.011162][8368] CHIP:IN: Sending msg from 0x000000000001B669 to 0x00000000000004D0 at utc time: 1071823 msec
[1622792537.011208][8368] CHIP:IN: Sending secure msg on generic transport
[1622792537.011391][8368] CHIP:IN: Secure msg send status No Error
[1622792537.011441][8368] CHIP:CTL: Sent operational certificate to the device
[1622792537.011630][8368] CHIP:ZCL: DefaultResponse:
[1622792537.011677][8368] CHIP:ZCL:   Transaction: 0xffffbbb236e0
[1622792537.011712][8368] CHIP:ZCL:   status: EMBER_ZCL_STATUS_SUCCESS (0x00)
[1622792537.834525][8369] CHIP:IN: Secure transport received message destined to fabric 0, node 0x000000000001B669. Key ID 1
[1622792537.834725][8369] CHIP:EM: Received message of type 9 and protocolId 327680 on exchange 39020
SetCommandIndexStatus commandHandle=1 commandIndex=1
[1622792537.835773][8369] CHIP:ZCL: DefaultResponse:
[1622792537.835837][8369] CHIP:ZCL:   Transaction: 0xffffbbb237f8
[1622792537.835899][8369] CHIP:ZCL:   status: EMBER_ZCL_STATUS_FAILURE (0x01)
[1622792537.835938][8369] CHIP:CTL: Device failed to receive the operational certificate Response: 0x01
Failed to establish secure session to device: 4172
CHIP Error 4172 (0x0000104C): Internal error
chip-device-ctrl > [1622792537.836916][8369] CHIP:ZCL: DefaultResponse:
[1622792537.837014][8369] CHIP:ZCL:   Transaction: 0xffffbbb237f8
[1622792537.837051][8369] CHIP:ZCL:   status: EMBER_ZCL_STATUS_SUCCESS (0x00)

chip-device-ctrl > zcl NetworkCommissioning AddThreadNetwork 1239 1 0 operationalDataset=hex:0e080000000000000000000300000b35060004001fffe00208dead00beef00cafe0708fddead00beef0000051079e9df9c1d1d215308b7b6baefb36a41030a4f70656e54687265616401029b620410e051260fb7d7fed12d5fc30f872f4abe0c0402a0fff8 breadcrumb=0 timeoutMs=1000
An exception occurred during process ZCL command:
CHIP Error 4072 (0x00000FE8): Not connected
chip-device-ctrl > 
chip-device-ctrl > zcl NetworkCommissioning EnableNetwork 1234 1 0 networkID=hex:dead00beef00cafe breadcrumb=0 timeoutMs=1000
An exception occurred during process ZCL command:
CHIP Error 4072 (0x00000FE8): Not connected
chip-device-ctrl > 
chip-device-ctrl > zcl OnOff Toggle 1232 1 0  
An exception occurred during process ZCL command:
CHIP Error 4072 (0x00000FE8): Not connected
chip-device-ctrl > 
chip-device-ctrl > zcl NetworkCommissioning AddThreadNetwork 1232 1 0 operationalDataset=hex:0e080000000000000000000300000b35060004001fffe00208dead00beef00cafe0708fddead00beef0000051079e9df9c1d1d215308b7b6baefb36a41030a4f70656e54687265616401029b620410e051260fb7d7fed12d5fc30f872f4abe0c0402a0fff8 breadcrumb=0 timeoutMs=1000 
An exception occurred during process ZCL command:
CHIP Error 4072 (0x00000FE8): Not connected
chip-device-ctrl > 
chip-device-ctrl >

device logs （efr32mg21A020F1024）：

00> <efr32 > ==================================================
00> <efr32 > chip-efr32-lighting-example starting
00> <efr32 > ==================================================
00> <efr32 > Init CHIP Stack
00> <detail> [-] Initializing key value store
00> <detail> [-] KeyValueStore init complete: active keys 4, deleted keys 0, sectors 4, logical sector size 8192 bytes
00> <info  > [DL] Setting device name to : "EFR32_LIGHT"
00> <efr32 > Initializing OpenThread stack
00> <info  > [DL] OpenThread started: OK
00> <info  > [DL] Setting OpenThread device type to ROUTER
00> <efr32 > Starting Platform Manager Event Loop
00> <efr32 > Starting OpenThread task
00> <efr32 > Starting App Task
00> <efr32 > Starting FreeRTOS scheduler
00> <info  > [DL] Bluetooth stack booted: v3.1.1-b214
00> 
00> <detail> [DL] Thread task running
00> <info  > [ZCL] Using ZAP configuration...
00> <detail> [DL] CHIP task running
00> <detail> [DL] Start BLE advertissement
00> <info  > [ZCL] deactivate report event
00> <info  > [ZCL] OpCreds: Initiating OpCreds cluster by writing fabrics list from admin pairing table.
00> <detail> [DIS] Set the admin pairing table delegate
00> <info  > [ZCL] OpCreds: Call to writeAdminsIntoFabricsListAttribute
00> <info  > [ZCL] OpCreds: Stored 0 admins in fabrics list attribute.
00> <efr32 > Unknown cluster ID: 40
00> <efr32 > Unknown cluster ID: 40
00> <efr32 > Unknown cluster ID: 40
00> <efr32 > Unknown cluster ID: 40
00> <efr32 > Unknown cluster ID: 40
00> <efr32 > Unknown cluster ID: 40
00> <efr32 > Unknown cluster ID: 40
00> <efr32 > Unknown cluster ID: 40
00> <efr32 > Unknown cluster ID: 40
00> <detail> [DIS] Init admin pairing table with server storage
00> <info  > [DL] _OnPlatformEvent default:  event->Type = 32778
00> <detail> [DL] OpenThread State Changed (Flags: 0x00038200)
00> <detail> [DL]    Network Name: OpenThread
00> <detail> [DL]    PAN Id: 0xFFFF
00> <detail> [IN] TransportMgr initialized
00> <detail> [DL]    Extended PAN Id: 0xDEAD00BEEF00CAFE
00> <detail> [DL]    Channel: 11
00> <detail> [DL]    Mesh Prefix: FDDE:AD00:BEEF::/64
00> <info  > [IN] local node id is 0x0000000000BC5C01
00> <detail> [SC] Assigned local session key ID 0
00> <detail> [SC] Waiting for PBKDF param request
00> <info  > [DIS] Start dns-sd server
00> <info  > [SVR] Server Listening...
00> <efr32 > Current Firmware Version: 0.1ALPHA
00> <info  > [DL] Device Configuration:
00> <info  > [DL]   Serial Number: TEST_SN
00> <info  > [DL]   Vendor Id: 9050 (0x235A)
00> <info  > [DL]   Product Id: 21324 (0x534C)
00> <info  > [DL]   Product Revision: 1
00> <info  > [DL]   Setup Pin Code: 73141520
00> <info  > [DL]   Setup Discriminator: 3840 (0xF00)
00> <info  > [DL]   Manufacturing Date: (not set)
00> <info  > [DL]   Device Type: 65535 (0xFFFF)
00> <info  > [SVR] SetupQRCode: [CH:Y3.1345600C0NF0ET00]
00> <info  > [SVR] Copy/paste the below URL in a browser to see the QR Code:
00> <info  > [SVR] https://dhrishi.github.io/connectedhomeip/qrcode.html?data=CH%3AY3.1345600C0NF0ET00
00> <info  > [SVR] Manual pairing code: [35249644644]
00> <efr32 > App Task started
00> <detail> [DL] bleAdv Timeout : Start slow advertissment
00> <info  > [DL] Connect Event for handle : 1
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 9)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [BLE] local and remote recv window sizes = 3
00> <info  > [BLE] selected BTP version 3
00> <info  > [BLE] using BTP fragment sizes rx 128 / tx 20.
00> <info  > [DL] CHIPoBLE subscribe received
00> <info  > [DL] _OnPlatformEvent kCHIPoBLESubscribe
00> <detail> [IN] BLE EndPoint 0x2000fa28 Connection Complete
00> <info  > [DL] _OnPlatformEvent default:  event->Type = 32777
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 51)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [EM] Received message of type 32 and protocolId 0 on exchange 39018
00> <detail> [EM] ec id: 39018, Delegate: 0x20011c70
00> <detail> [SC] Received PBKDF param request
00> <detail> [SC] Sent PBKDF param response
00> <error > [DL] Long dispatch time: 1276 ms
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 86)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [EM] Received message of type 34 and protocolId 0 on exchange 39018
00> <detail> [SC] Received spake2p msg1
00> <detail> [SC] Peer assigned session key ID 1
00> <detail> [SC] Sent spake2p msg2
00> <error > [DL] Long dispatch time: 5460 ms
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 51)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [EM] Received message of type 36 and protocolId 0 on exchange 39018
00> <detail> [SC] Received spake2p msg3
00> <detail> [IN] New pairing for device 0x0000000000000000, key 1!!
00> <info  > [SVR] Device completed SPAKE2+ handshake
00> <info  > [SVR] Persisting admin ID 0, next available 1
00> <info  > [SVR] Stored value in server storage
00> <info  > [DIS] Admin (0) persisted to storage. Calling OnAdminPersistedToStorage
00> <info  > [ZCL] OpCreds: Admin 0 was persisted to storage. FabricId 00000000000000000, NodeId 00000000020011758, VendorId 0x628D
00> <info  > [ZCL] OpCreds: Call to writeAdminsIntoFabricsListAttribute
00> <info  > [ZCL] OpCreds: Skipping over unitialized admin with fabricId 0x0000000000000000, nodeId 0x0000000000000000 vendorId 0x0000
00> <info  > [ZCL] OpCreds: Stored 0 admins in fabrics list attribute.
00> <info  > [SVR] Persisting admin ID successfully
00> <info  > [SVR] Device completed Rendezvous process
00> <info  > [SVR] Stored value in server storage
00> <info  > [SVR] Stored value in server storage
00> <error > [DL] Long dispatch time: 1071 ms
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 107)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [IN] Secure transport received message destined to fabric 0, node 0x00000000000004D0. Key ID 0
00> <info  > [IN] Setting nodeID lX on admin.
00> <info  > [IN] Setting fabricID lX on admin.
00> <info  > [IN] Since admin was modified, persisting changes to KVS
00> <info  > [SVR] Stored value in server storage
00> <info  > [DIS] Admin (0) persisted to storage. Calling OnAdminPersistedToStorage
00> <info  > [ZCL] OpCreds: Admin 0 was persisted to storage. FabricId 00001B66900000000, NodeId 4d00000000020011758, VendorId 0x628D
00> <info  > [ZCL] OpCreds: Call to writeAdminsIntoFabricsListAttribute
00> <info  > [ZCL] OpCreds: Skipping over unitialized admin with fabricId 0x000000000001B669, nodeId 0x00000000000004D0 vendorId 0x0000
00> <info  > [ZCL] OpCreds: Stored 0 admins in fabrics list attribute.
00> <info  > [EM] Received message of type 8 and protocolId 327680 on exchange 39019
00> <detail> [EM] ec id: 39019, Delegate: 0x20013b58
00> <detail> [DMG] ICR moving to [Initialize]
00> <detail> [ZCL] Received Cluster Command: Cluster=3e Command=hx Endpoint=hx
00> <info  > [ZCL] OpCreds: commissioner has requested an OpCSR
00> <info  > [ZCL] OpCreds: Finding admin with fabricId 0x000000000001B669.
00> <info  > [DIS] Checking ind:0 [fabricId 0x000000000001B669 nodeId 0x00000000000004D0 vendorId 0] vs [fabricId 0x000000000001B669 nodeId 0x0000000000000000 vendorId 0]
00> <info  > [DIS] Found a match!
00> <info  > [ZCL] OpCreds: NewCertificateSigningRequest returned 0
00> <detail> [DMG] ICR moving to [AddCommand]
00> <detail> [IN] Secure message was encrypted: Msg ID 1
00> <info  > [IN] Sending msg from 0x00000000000004D0 to 0x000000000001B669 at utc time: ld msec
00> <info  > [IN] Sending secure msg on generic transport
00> <info  > [IN] Secure msg send status No Error
00> <detail> [DMG] ICR moving to [   Sending]
00> <detail> [DMG] ICR moving to [Uninitiali]
00> <error > [DL] Long dispatch time: 2161 ms
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 128)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 128)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 95)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [IN] Secure transport received message destined to fabric 0, node 0x00000000000004D0. Key ID 0
00> <info  > [EM] Received message of type 8 and protocolId 327680 on exchange 39020
00> <detail> [EM] ec id: 39020, Delegate: 0x20013b58
00> <detail> [DMG] ICR moving to [Initialize]
00> <detail> [ZCL] Received Cluster Command: Cluster=3e Command=hx Endpoint=hx
00> <info  > [ZCL] OpCreds: commissioner has added an Op Cert
00> <info  > [ZCL] OpCreds: Finding admin with fabricId 0x000000000001B669.
00> <info  > [DIS] Checking ind:0 [fabricId 0x000000000001B669 nodeId 0x00000000000004D0 vendorId 0] vs [fabricId 0x000000000001B669 nodeId 0x0000000000000000 vendorId 0]
00> <info  > [DIS] Found a match!
00> <detail> [DMG] ICR moving to [AddCommand]
00> <info  > [ZCL] OpCreds: Failed AddOpCert request.
00> <detail> [IN] Secure message was encrypted: Msg ID 2
00> <info  > [IN] Sending msg from 0x00000000000004D0 to 0x000000000001B669 at utc time: ld msec
00> <info  > [IN] Sending secure msg on generic transport
00> <info  > [IN] Secure msg send status No Error
00> <detail> [DMG] ICR moving to [   Sending]
00> <detail> [DMG] ICR moving to [Uninitiali]
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
00> <info  > [DL] Tx Confirmation received
00> <info  > [DL]  stop soft timer
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEIndicateConfirm
00> <info  > [DL] Char Write Req, char : 26
00> <detail> [DL] Write request/command received for CHIPoBLE RX characteristic (con 1, len 3)
00> <info  > [DL] _OnPlatformEvent kCHIPoBLEWriteReceived
(Connection lost)
@jmartinez-silabs
Copy link
Member

Hi @ChengqiangShe

The secure session failed so you cannot send the zcl commands for the provissioning. Now I am not sure why it failed.

I see you are using mg21, I think it is a Heap issue, we had that happend on the lock app. RAM on MG21 is getting really slim and we have almost no room. You can try to bump the heap by 1k. I will try it and do a PR for that

Like this PR #7241

I also what to point out that you are using the wrong endpoints for the commissioning zcl commands.

Here is the flow of commands you should be using

connect -ble 3840 73141520 1234

zcl NetworkCommissioning AddThreadNetwork 1234 **0** 0 operationalDataset=hex:0e080000000000000000000300000f35060004001fffe0020811111111222222220708fdc68a163468d333051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f01021234041061e1206d2c2b46e079eb775f41fc72190c0402a0fff8 breadcrumb=0 timeoutMs=1000

zcl NetworkCommissioning EnableNetwork 1234 **0** 0 networkID=hex:1111111122222222 breadcrumb=0 timeoutMs=1000

close-ble

resolve 0 1234

zcl OnOff Toggle 1234 **1** 0

As you see except the OnOff command that use enpoint 1, the others are on endpoint 0

@568760310
Copy link

568760310 commented Jun 15, 2021 •
edited
Loading

@jmartinez-silabs

I meet the same issue on MG12 while pairing lock-app. Is the same reason failed ? and how to fix this issue?

@568760310
Copy link

568760310 commented Jun 15, 2021 •
edited
Loading

@LuDuda ,
I also test the lock-app on nrf52840, the same issue happened.
Would you like to help me fix this issue?

ubuntu@ubuntuservercontroller:~$ chip-device-ctrl 
[1623756311.603052][11055] CHIP:CTL: SyncSetKeyValue on ExampleOpCredsCAKey
[1623756311.608230][11055] CHIP:IN: TransportMgr initialized
[1623756311.608277][11055] CHIP:DIS: Init admin pairing table with server storage
[1623756311.608327][11055] CHIP:IN: local node id is 0x000000000001B669
[1623756311.612231][11055] CHIP:DL: Avahi client registered
[1623756311.613888][11055] CHIP:ZCL: Using ZAP configuration...
[1623756311.613994][11055] CHIP:ZCL: deactivate report event
[1623756311.614037][11055] CHIP:CTL: Getting operational keys
[1623756311.615050][11055] CHIP:CTL: Generating operational certificate for the controller
[1623756311.616059][11055] CHIP:CTL: Getting root certificate for the controller from the issuer
[1623756311.616458][11055] CHIP:CTL: SyncSetKeyValue on CHIPAdmin0
[1623756311.616531][11055] CHIP:CTL: Generating credentials
[1623756311.616809][11055] CHIP:CTL: Loaded credentials successfully
[1623756311.617077][11063] CHIP:DL: CHIP task running
[1623756311.631259][11064] CHIP:DL: Platform main loop started.
Chip Device Controller Shell

chip-device-ctrl > connect -ble 3840 20202021  1
Device is assigned with nodeid = 1
[1623756364.280122][11055] CHIP:SC: Assigned local session key ID 0
[1623756364.280373][11055] CHIP:IN: Message appended to BLE send queue
[1623756364.280453][11055] CHIP:SC: Sent PBKDF param request
[1623756364.280395][11583] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1623756364.280672][11055] CHIP:CTL: SyncSetKeyValue on StartKeyID
[1623756364.280913][11059] CHIP:DL: TRACE: Bus acquired for name C-2b2f
[1623756364.292317][11064] CHIP:DL: PlatformBlueZInit init success
[1623756364.298864][11059] CHIP:BLE: BLE removing known devices.
[1623756364.298937][11059] CHIP:BLE: BLE initiating scan.
[1623756364.408275][11059] CHIP:BLE: Device 54:EF:44:26:58:0E does not look like a CHIP device.
[1623756364.429334][11059] CHIP:BLE: Device 7F:96:72:77:9C:17 does not look like a CHIP device.
[1623756364.431541][11059] CHIP:BLE: Device 65:EC:84:E4:D9:1B does not look like a CHIP device.
[1623756364.440751][11059] CHIP:BLE: Device 72:26:66:33:16:49 does not look like a CHIP device.
[1623756364.455182][11059] CHIP:BLE: Device 28:D1:27:29:8B:6B does not look like a CHIP device.
[1623756364.469305][11059] CHIP:BLE: Device 5C:E6:52:56:A1:8C does not look like a CHIP device.
[1623756364.492072][11059] CHIP:BLE: Device 28:D1:27:29:67:B9 does not look like a CHIP device.
[1623756364.494284][11059] CHIP:BLE: Device 5D:FD:FF:63:EE:A5 does not look like a CHIP device.
[1623756364.495993][11059] CHIP:BLE: Device 5B:95:BC:7A:46:32 does not look like a CHIP device.
[1623756364.497776][11059] CHIP:BLE: Device 84:2E:14:28:45:61 does not look like a CHIP device.
[1623756364.513851][11059] CHIP:BLE: Device CC:CC:CC:DB:FC:AC does not look like a CHIP device.
[1623756364.523375][11059] CHIP:BLE: Device 4A:72:3D:42:65:78 does not look like a CHIP device.
[1623756364.543388][11059] CHIP:BLE: Device 8C:85:90:C2:19:3B does not look like a CHIP device.
[1623756364.547021][11059] CHIP:BLE: Device 28:D1:27:29:2F:3E does not look like a CHIP device.
[1623756364.552294][11059] CHIP:BLE: Device 84:2E:14:78:C1:D0 does not look like a CHIP device.
[1623756364.555625][11059] CHIP:BLE: Device 28:D1:27:28:F0:4E does not look like a CHIP device.
[1623756364.557459][11059] CHIP:BLE: Device 7C:57:89:F5:A8:58 does not look like a CHIP device.
[1623756364.580314][11059] CHIP:BLE: Device 28:D1:27:29:83:5F does not look like a CHIP device.
[1623756364.583966][11059] CHIP:BLE: Device 74:9C:E7:45:22:1B does not look like a CHIP device.
[1623756364.586976][11059] CHIP:BLE: Device F9:9F:BE:EC:AA:7C does not look like a CHIP device.
[1623756364.588992][11059] CHIP:BLE: Device 74:10:04:9C:C3:1F does not look like a CHIP device.
[1623756364.619268][11059] CHIP:BLE: Device 54:EF:44:CC:D7:AE does not look like a CHIP device.
[1623756364.628333][11059] CHIP:BLE: Device 1F:CD:6D:81:DC:EF does not look like a CHIP device.
[1623756364.636453][11059] CHIP:BLE: New device scanned: F7:D8:C8:B3:46:53
[1623756364.636574][11059] CHIP:BLE: Device discriminator match. Attempting to connect.
[1623756364.654584][11059] CHIP:BLE: Scan complete notification without an active scan.
[1623756364.771029][11059] CHIP:DL: ConnectDevice complete
[1623756366.558490][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0001
[1623756366.558655][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0001
[1623756366.558696][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0001
[1623756366.558724][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0001
[1623756366.558762][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0007
[1623756366.558788][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0001
[1623756366.558817][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0007
[1623756366.558838][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0001
[1623756366.558863][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0007
[1623756366.558887][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0001
[1623756366.558926][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0007
[1623756366.558948][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0001
[1623756366.558979][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0007
[1623756366.558999][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0001
[1623756366.559028][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0007
[1623756366.559053][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0001
[1623756366.559096][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0001
[1623756366.559117][11059] CHIP:DL: Char1 /org/bluez/hci0/dev_F7_D8_C8_B3_46_53/service0001
[1623756366.559158][11059] CHIP:DL: New BLE connection 0xffff90064340, device F7:D8:C8:B3:46:53, path /org/bluez/hci0/dev_F7_D8_C8_B3_46_53
[1623756366.559321][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1623756366.559361][11064] CHIP:IN: BleConnectionComplete: endPoint 0xffff9b48cff8
[1623756367.070148][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756367.170808][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1623756367.170897][11064] CHIP:BLE: subscribe complete, ep = 0xffff9b48cff8
[1623756367.171145][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756367.171378][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756367.171577][11064] CHIP:BLE: peripheral chose BTP version 3; central expected between 2 and 3
[1623756367.171631][11064] CHIP:BLE: using BTP fragment sizes rx 20 / tx 20.
[1623756367.171669][11064] CHIP:BLE: local and remote recv window size = 3
[1623756367.171961][11064] CHIP:IN: BLE EndPoint 0xffff9b48cff8 Connection Complete
[1623756367.319548][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756367.419488][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756367.420007][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756367.420220][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756367.520146][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756367.719582][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756367.719806][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756367.969567][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756367.970324][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756367.970524][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756368.070412][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756368.070700][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756368.170226][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756368.270012][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756368.270306][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756368.369957][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756368.370244][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756368.370524][11064] CHIP:EM: Received message of type 33 and protocolId 0 on exchange 39017
[1623756368.370616][11064] CHIP:SC: Received PBKDF param response
[1623756368.373897][11064] CHIP:SC: Sent spake2p msg1
[1623756368.469612][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756368.619281][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756368.619587][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756368.619801][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756368.719898][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756368.920083][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756368.969930][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756368.970209][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756369.119526][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756369.219521][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756369.469794][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756369.470070][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756369.669641][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756369.669871][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756369.769653][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756369.819907][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756369.820149][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756369.920424][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756369.920755][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756370.219570][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756370.220096][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756370.220328][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756370.370421][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756370.370698][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756370.469343][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756370.469923][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756370.470263][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756370.619488][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756370.619712][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756370.619932][11064] CHIP:EM: Received message of type 35 and protocolId 0 on exchange 39017
[1623756370.620003][11064] CHIP:SC: Received spake2p msg2
[1623756370.620083][11064] CHIP:SC: Peer assigned session key ID 0
[1623756370.622405][11064] CHIP:SC: Sent spake2p msg3
[1623756370.622543][11064] CHIP:IN: New pairing for device 0x0000000000000001, key 0!!
[1623756370.622656][11064] CHIP:CTL: Remote device completed SPAKE2+ handshake

[1623756370.622863][11064] CHIP:CTL: Sending OpCSR request to 0x34a4e908 device
[1623756370.623084][11064] CHIP:DMG: ICR moving to [Initialize]
[1623756370.623141][11064] CHIP:DMG: ICR moving to [AddCommand]
[1623756370.623319][11064] CHIP:IN: Secure message was encrypted: Msg ID 0
[1623756370.623367][11064] CHIP:IN: Sending msg from 0x000000000001B669 to 0x0000000000000001 at utc time: 4677406 msec
[1623756370.623406][11064] CHIP:IN: Sending secure msg on generic transport
[1623756370.623447][11064] CHIP:IN: Secure msg send status No Error
[1623756370.623482][11064] CHIP:DMG: ICR moving to [   Sending]
[1623756370.623515][11064] CHIP:CTL: Sent OpCSR request, waiting for the CSR
[1623756370.719546][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756370.869628][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756370.870031][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756370.870351][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756371.019551][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756371.119576][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756371.169872][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756371.170141][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756371.276166][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756371.369548][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756371.370068][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756371.370286][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756371.519222][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756371.619207][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756371.669440][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756371.669686][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756371.819517][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756372.120216][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756372.169809][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756372.170085][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756372.469663][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756372.469932][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756372.669566][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756372.670023][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756372.670213][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756372.870070][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756372.870353][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756373.019559][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756373.020088][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756373.020308][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756373.170006][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756373.170285][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756373.269577][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756373.270125][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756373.270350][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756373.369987][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756373.370267][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756373.469175][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756373.569633][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756373.569859][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756373.669950][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756373.670189][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756373.769169][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756373.769871][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756373.770031][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756373.970051][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756373.970332][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756374.069625][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756374.070199][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756374.070479][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756374.170005][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756374.170282][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756374.369659][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756374.370326][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756374.370580][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756374.519573][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756374.519799][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756374.769656][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756374.770010][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756374.770184][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756374.870119][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756374.870430][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756374.969574][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756374.970088][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756374.970308][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756375.069514][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756375.069748][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756375.069975][11064] CHIP:IN: Secure transport received message destined to fabric 0, node 0x000000000001B669. Key ID 0
[1623756375.070178][11064] CHIP:IN: Setting fabricID 1 on admin.
[1623756375.070223][11064] CHIP:IN: Since admin was modified, persisting changes to KVS
[1623756375.070335][11064] CHIP:CTL: SyncSetKeyValue on CHIPAdmin0
[1623756375.070384][11064] CHIP:EM: Received message of type 9 and protocolId 327680 on exchange 39018
[1623756375.070473][11064] CHIP:DMG: InvokeCommand =
[1623756375.070518][11064] CHIP:DMG: {
[1623756375.070554][11064] CHIP:DMG: 	CommandList =
[1623756375.070592][11064] CHIP:DMG: 	[
[1623756375.070638][11064] CHIP:DMG: 		CommandDataElement =
[1623756375.070705][11064] CHIP:DMG: 		{
[1623756375.070751][11064] CHIP:DMG: 			CommandPath =
[1623756375.070798][11064] CHIP:DMG: 			{
[1623756375.070839][11064] CHIP:DMG: 				EndpointId = 0x0,
[1623756375.070883][11064] CHIP:DMG: 				ClusterId = 0x3e,
[1623756375.070926][11064] CHIP:DMG: 				CommandId = 0x5,
[1623756375.070969][11064] CHIP:DMG: 			},
[1623756375.071027][11064] CHIP:DMG: 			
[1623756375.071072][11064] CHIP:DMG: 			CommandData = 
[1623756375.071121][11064] CHIP:DMG: 			{
[1623756375.071171][11064] CHIP:DMG: 				0x0 = [
[1623756375.071257][11064] CHIP:DMG: 					0x30, 0x81, 0xca, 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, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3,
[1623756375.071319][11064] CHIP:DMG: 			]
[1623756375.071370][11064] CHIP:DMG: 				0x1 = [
[1623756375.071448][11064] CHIP:DMG: 					0xc7, 0xa9, 0x15, 0xf6, 0xde, 0xf4, 0x35, 0x64, 0xa4, 0x31, 0x95, 0x83, 0xc2, 0x8c, 0xd0, 0x30, 0x2c, 0x5e, 0x7a, 0x19, 0xfc, 0x9d, 0x41, 0x2a, 0x59, 0x6d, 0x9f, 0x30, 0x2, 0x1, 0xbb, 0x1a, 
[1623756375.071510][11064] CHIP:DMG: 			]
[1623756375.071566][11064] CHIP:DMG: 				0x2 = [
[1623756375.071623][11064] CHIP:DMG: 					
[1623756375.071682][11064] CHIP:DMG: 			]
[1623756375.071738][11064] CHIP:DMG: 				0x3 = [
[1623756375.071794][11064] CHIP:DMG: 					
[1623756375.071855][11064] CHIP:DMG: 			]
[1623756375.071908][11064] CHIP:DMG: 				0x4 = [
[1623756375.071959][11064] CHIP:DMG: 					
[1623756375.072018][11064] CHIP:DMG: 			]
[1623756375.072071][11064] CHIP:DMG: 				0x5 = [
[1623756375.072121][11064] CHIP:DMG: 					
[1623756375.072177][11064] CHIP:DMG: 			]
[1623756375.072228][11064] CHIP:DMG: 			},
[1623756375.072279][11064] CHIP:DMG: 		},
[1623756375.072333][11064] CHIP:DMG: 		
[1623756375.072370][11064] CHIP:DMG: 	],
[1623756375.072418][11064] CHIP:DMG: 	
[1623756375.072453][11064] CHIP:DMG: }
[1623756375.072651][11064] CHIP:ZCL: Received Cluster Command: Cluster=3e Command=5 Endpoint=0
[1623756375.072708][11064] CHIP:ZCL: OpCSRResponse:
[1623756375.072742][11064] CHIP:ZCL:   CSR: 205
[1623756375.072773][11064] CHIP:ZCL:   CSRNonce: 32
[1623756375.072803][11064] CHIP:ZCL:   VendorReserved1: 0
[1623756375.072833][11064] CHIP:ZCL:   VendorReserved2: 0
[1623756375.072863][11064] CHIP:ZCL:   VendorReserved3: 0
[1623756375.072893][11064] CHIP:ZCL:   Signature: 0
[1623756375.072929][11064] CHIP:CTL: Received certificate signing request from the device
[1623756375.072972][11064] CHIP:CTL: Generating operational certificate for device 1
[1623756375.074698][11064] CHIP:CTL: Getting intermediate CA certificate from the issuer
[1623756375.074758][11064] CHIP:CTL: GetIntermediateCACertificate returned 4190
[1623756375.074792][11064] CHIP:CTL: Intermediate CA is not needed
[1623756375.074952][11064] CHIP:CTL: Sending operational certificate to the device. Op Cert Len 253, ICA Cert Len 0
[1623756375.075040][11064] CHIP:DMG: ICR moving to [Initialize]
[1623756375.075103][11064] CHIP:DMG: ICR moving to [AddCommand]
[1623756375.075317][11064] CHIP:IN: Secure message was encrypted: Msg ID 1
[1623756375.075366][11064] CHIP:IN: Sending msg from 0x000000000001B669 to 0x0000000000000001 at utc time: 4681858 msec
[1623756375.075403][11064] CHIP:IN: Sending secure msg on generic transport
[1623756375.075449][11064] CHIP:IN: Secure msg send status No Error
[1623756375.075483][11064] CHIP:DMG: ICR moving to [   Sending]
[1623756375.075516][11064] CHIP:CTL: Sent operational certificate to the device
[1623756375.075675][11064] CHIP:ZCL: DefaultResponse:
[1623756375.075718][11064] CHIP:ZCL:   Transaction: 0xffff9b48b3b8
[1623756375.075751][11064] CHIP:ZCL:   status: EMBER_ZCL_STATUS_SUCCESS (0x00)
[1623756375.075785][11064] CHIP:ZCL: emberAfDefaultResponseCallback: Missing success callback
[1623756375.075817][11064] CHIP:ZCL: emberAfDefaultResponseCallback: Missing failure callback
[1623756375.075852][11064] CHIP:DMG: ICR moving to [Uninitiali]
[1623756375.170254][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756375.269647][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756375.270170][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756375.270401][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756375.369273][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756375.519243][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756375.519637][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756375.519805][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756375.669659][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756375.819604][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756375.820362][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756375.821134][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756375.919610][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756376.020228][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756376.020834][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756376.021065][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756376.126817][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756376.270023][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756376.270520][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756376.270798][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756376.370031][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756376.469843][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756376.569493][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756376.569723][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756376.669253][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756376.770179][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756376.777587][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756376.777818][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756376.869650][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756377.069605][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756377.070123][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756377.070339][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756377.169417][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756377.269162][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756377.276895][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756377.277149][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756377.369270][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756377.519531][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756377.520082][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756377.520244][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756377.619549][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756377.676563][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756377.676772][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756377.769640][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756377.770307][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756377.770518][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389

[1623756377.870031][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756377.870329][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756377.969529][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756377.976962][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756377.977209][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756378.069486][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756378.069713][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756378.069946][11064] CHIP:IN: Secure transport received message destined to fabric 0, node 0x000000000001B669. Key ID 0
[1623756378.070124][11064] CHIP:EM: Received message of type 9 and protocolId 327680 on exchange 39019
[1623756378.070210][11064] CHIP:DMG: InvokeCommand =
[1623756378.070248][11064] CHIP:DMG: {
[1623756378.070287][11064] CHIP:DMG: 	CommandList =
[1623756378.070332][11064] CHIP:DMG: 	[
[1623756378.070375][11064] CHIP:DMG: 		CommandDataElement =
[1623756378.070417][11064] CHIP:DMG: 		{
[1623756378.070452][11064] CHIP:DMG: 			CommandPath =
[1623756378.070493][11064] CHIP:DMG: 			{
[1623756378.070534][11064] CHIP:DMG: 				EndpointId = 0x0,
[1623756378.070577][11064] CHIP:DMG: 				ClusterId = 0x3e,
[1623756378.070619][11064] CHIP:DMG: 				CommandId = 0x6,
[1623756378.070658][11064] CHIP:DMG: 			},
[1623756378.070704][11064] CHIP:DMG: 			
[1623756378.070740][11064] CHIP:DMG: 			StatusElement =
[1623756378.070780][11064] CHIP:DMG: 			{
[1623756378.070832][11064] CHIP:DMG: 				GeneralCode = 0x4,
[1623756378.070888][11064] CHIP:DMG: 				ProtocolId = 0x0,
[1623756378.070943][11064] CHIP:DMG: 				protocolCode = 0xffff,
[1623756378.070995][11064] CHIP:DMG: 			},
[1623756378.071059][11064] CHIP:DMG: 			
[1623756378.071096][11064] CHIP:DMG: 		},
[1623756378.071149][11064] CHIP:DMG: 		
[1623756378.071184][11064] CHIP:DMG: 	],
[1623756378.071232][11064] CHIP:DMG: 	
[1623756378.071267][11064] CHIP:DMG: }
SetCommandIndexStatus commandHandle=1 commandIndex=1
[1623756378.071837][11064] CHIP:ZCL: DefaultResponse:
[1623756378.071881][11064] CHIP:ZCL:   Transaction: 0xffff9b48b4d0
[1623756378.071914][11064] CHIP:ZCL:   status: EMBER_ZCL_STATUS_FAILURE (0x01)
[1623756378.071950][11064] CHIP:CTL: Device failed to receive the operational certificate Response: 0x01
[1623756378.072015][11064] CHIP:CTL: SyncSetKeyValue on StartKeyID
[1623756378.072114][11064] CHIP:CTL: SyncSetKeyValue on PairedDevice1
Failed to establish secure session to device: 4172
CHIP Error 4172 (0x0000104C): Internal error
[1623756378.072587][11064] CHIP:ZCL: DefaultResponse:
[1623756378.072635][11064] CHIP:ZCL:   Transaction: 0xffff9b48b4d0
[1623756378.072669][11064] CHIP:ZCL:   status: EMBER_ZCL_STATUS_SUCCESS (0x00)
[1623756378.072703][11064] CHIP:ZCL: emberAfDefaultResponseCallback: Missing success callback
[1623756378.072735][11064] CHIP:ZCL: emberAfDefaultResponseCallback: Missing failure callback
[1623756378.072773][11064] CHIP:DMG: ICR moving to [Uninitiali]
chip-device-ctrl > 
chip-device-ctrl > [1623756378.169663][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

chip-device-ctrl > 
chip-device-ctrl > 
chip-device-ctrl > [1623756380.741675][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756380.741952][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756383.369472][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1623756386.117232][11059] CHIP:DL: Indication received, conn = 0xffff90064340
[1623756386.117461][11063] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1623756388.769677][11064] CHIP:DL: HandlePlatformSpecificBLEEvent 16387

Logs of Lock-app

I: 86398 [DL]NFC Tag emulation started
D: 86401 [DL]SetAdvertisingEnabled(true)
D: 86405 [SC]Assigned local session key ID 0
D: 86409 [SC]Waiting for PBKDF param request
I: Enabled BLE Advertisement
D: 86416 [DL]In DriveBLEState
I: 86420 [DL]CHIPoBLE advertising started
<1>
I: 98046 [DL]BLE connection established (ConnId: 0x00)
I: 98050 [DL]Current number of connections: 1/1
D: 98055 [DL]In DriveBLEState
I: 98057 [DL]CHIPoBLE advertising stopped
I: 98061 [DL]NFC Tag emulation stopped
<2>
D: 100321 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 100327 [BLE]local and remote recv window sizes = 3
I: 100331 [BLE]selected BTP version 3
I: 100335 [BLE]using BTP fragment sizes rx 20 / tx 20.
<3>
D: 100471 [DL]ConnId: 0x00, New CCCD value: 0x0001
D: 100475 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 6)
D: 100481 [IN]BLE EndPoint 0x20007d88 Connection Complete
I: 100487 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 23)
D: 100571 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 100576 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
<4>
D: 100721 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 100727 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 100821 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 100826 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 100832 [EM]Received message of type 32 and protocolId 0 on exchange 39017
D: 100839 [EM]ec id: 39017, Delegate: 0x0x20003ed8
D: 100844 [SC]Received PBKDF param request
<5>
D: 101014 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 101021 [SC]Sent PBKDF param response
E: 101024 [DL]Long dispatch time: 197 ms
<6>
D: 101170 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 101221 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 101227 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<7>
D: 101370 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 101376 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 101471 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 101476 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 101482 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<8>
D: 101670 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 101676 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 9)
D: 101771 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 101776 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 101871 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 101877 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
<9>
D: 102021 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 102026 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 102121 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 102127 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
<10>
D: 102371 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 102376 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
<11>
D: 102521 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 102527 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
I: 102533 [EM]Received message of type 34 and protocolId 0 on exchange 39017
D: 102540 [SC]Received spake2p msg1
D: 102595 [SC]Peer assigned session key ID 0
D: 102671 [SC]Sent spake2p msg2
E: 102673 [DL]Long dispatch time: 152 ms
<12>
D: 102870 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 102876 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<13>
D: 103071 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 103076 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 103082 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<14>
D: 103220 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 103226 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 103321 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 103326 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 103332 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<15>
D: 103620 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 103626 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<16>
D: 103771 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 103776 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 103782 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 103870 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 103876 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 12)
<17>
D: 104021 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 104026 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 104121 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 104127 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
<18>
D: 104271 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 104276 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
<19>
D: 104421 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 104427 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
I: 104433 [EM]Received message of type 36 and protocolId 0 on exchange 39017
D: 104440 [SC]Received spake2p msg3
D: 104443 [IN]New pairing for device 0x0000000000000000, key 0!!
I: 104450 [SVR]Device completed SPAKE2+ handshake
D: 104454 [DL]SetAdvertisingEnabled(false)
I: 104458 [SVR]Persisting admin ID 0, next available 1
I: 104479 [SVR]Stored value in server storage
I: 104525 [DIS]Admin (0) persisted to storage. Calling OnAdminPersistedToStorage
I: 104532 [ZCL]OpCreds: Admin 0 was persisted to storage. FabricId 00000000000000000, NodeId 00000000000000000, VendorId 0x62F9
I: 104543 [ZCL]OpCreds: Call to writeAdminsIntoFabricsListAttribute
I: 104549 [ZCL]OpCreds: Skipping over unitialized admin with fabricId 0x0000000000000000, nodeId 0x0000000000000000 vendorId 0x0000
I: 104561 [ZCL]OpCreds: Stored 0 admins in fabrics list attribute.
I: 104576 [SVR]Persisting admin ID successfully
I: 104581 [SVR]Device completed Rendezvous process
I: 104585 [SVR]Stored value in server storage
I: 104598 [SVR]Stored value in server storage
E: 104610 [DL]Long dispatch time: 189 ms
D: 104614 [DL]In DriveBLEState
D: 104617 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 104623 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 104671 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 104677 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 104771 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 104776 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
<20>
D: 104921 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 104927 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
<21>
D: 105071 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 105076 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
<22>
D: 105221 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 105227 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
I: 105233 [IN]Secure transport received message destined to fabric 0, node 0x0000000000000001. Key ID 0
I: 105242 [IN]Setting nodeID 1 on admin.
I: 105246 [IN]Setting fabricID 1B669 on admin.
I: 105250 [IN]Since admin was modified, persisting changes to KVS
I: 105272 [SVR]Stored value in server storage
<23>
I: 105487 [DIS]Admin (0) persisted to storage. Calling OnAdminPersistedToStorage
I: 105495 [ZCL]OpCreds: Admin 0 was persisted to storage. FabricId 00001B66900000000, NodeId 10000000000000000, VendorId 0x62F9
I: 105506 [ZCL]OpCreds: Call to writeAdminsIntoFabricsListAttribute
I: 105512 [ZCL]OpCreds: Skipping over unitialized admin with fabricId 0x000000000001B669, nodeId 0x0000000000000001 vendorId 0x0000
I: 105524 [ZCL]OpCreds: Stored 0 admins in fabrics list attribute.
I: 105530 [EM]Received message of type 8 and protocolId 5 on exchange 39018
D: 105537 [EM]ec id: 39018, Delegate: 0x0x20005d78
D: 105541 [DMG]ICR moving to [Initialize]
D: 105545 [ZCL]Received Cluster Command: Cluster=3e Command=4 Endpoint=0
I: 105552 [ZCL]OpCreds: commissioner has requested an OpCSR
I: 105557 [ZCL]OpCreds: Finding admin with fabricId 0x000000000001B669.
I: 105563 [DIS]Checking ind:0 [fabricId 0x000000000001B669 nodeId 0x0000000000000001 vendorId 0] vs [fabricId 0x000000000001B669 nodeId 0x0000000000000000 vendorId 0]
I: 105578 [DIS]Found a match!
I: 105616 [ZCL]OpCreds: NewCertificateSigningRequest returned 0
D: 105622 [DMG]ICR moving to [AddCommand]
D: 105626 [IN]Secure message was encrypted: Msg ID 1
I: 105631 [IN]Sending msg from 0x0000000000000001 to 0x000000000001B669 at utc time: 105631 msec
I: 105640 [IN]Sending secure msg on generic transport
I: 105644 [IN]Secure msg send status No Error
D: 105649 [DMG]ICR moving to [   Sending]
D: 105652 [DMG]ICR moving to [Uninitiali]
E: 105656 [DL]Long dispatch time: 435 ms
D: 105661 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 105667 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<24>
D: 105871 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 105876 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 105882 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<25>
D: 106071 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 106076 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<26>
D: 106271 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 106276 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 106282 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<27>
D: 106420 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 106426 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<28>
D: 106571 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 106576 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 106582 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 106670 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 106676 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 106771 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 106776 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 106782 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<29>
D: 106971 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 106976 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 107071 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 107076 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 107082 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 107170 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 107176 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<30>
D: 107371 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 107376 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 107382 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 107470 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 107476 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 107571 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 107576 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 107582 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<31>
D: 107771 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 107776 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<32>
D: 107921 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 107926 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 107932 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
<33>
D: 108170 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 108176 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 108270 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 108276 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 108282 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 108370 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 108376 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 12)
D: 108471 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 108476 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 108571 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 108577 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 108671 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 108676 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 108771 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 108777 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
<34>
D: 108921 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 108926 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
<35>
D: 109071 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 109077 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
<36>
D: 109221 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 109226 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 109321 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 109327 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 109421 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 109426 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 109521 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 109527 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
<37>
D: 109671 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 109676 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 109771 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 109777 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
<38>
D: 109971 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 109976 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 110071 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 110077 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 110171 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 110176 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
<39>
D: 110371 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 110377 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 110471 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 110476 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 110571 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 110577 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
D: 110671 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 110676 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 110771 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 110777 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 3)
<40>
D: 110921 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 110926 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
I: 110932 [IN]Secure transport received message destined to fabric 0, node 0x0000000000000001. Key ID 0
I: 110942 [EM]Received message of type 8 and protocolId 5 on exchange 39019
D: 110948 [EM]ec id: 39019, Delegate: 0x0x20005d78
D: 110953 [DMG]ICR moving to [Initialize]
D: 110957 [ZCL]Received Cluster Command: Cluster=3e Command=6 Endpoint=0
D: 110963 [DMG]ICR moving to [AddCommand]
I: 110967 [ZCL]Failed to dispatch command, 3/4 arguments parsed, TLVError=0, UnpackError=4038 (last decoded tag = 2
D: 110978 [IN]Secure message was encrypted: Msg ID 2
I: 110983 [IN]Sending msg from 0x0000000000000001 to 0x000000000001B669 at utc time: 110983 msec
I: 110991 [IN]Sending secure msg on generic transport
D: 110996 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
I: 111002 [IN]Secure msg send status No Error
D: 111007 [DMG]ICR moving to [   Sending]
D: 111010 [DMG]ICR moving to [Uninitiali]
D: 111070 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 111076 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 111082 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 111170 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 111176 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 111270 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 111276 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
D: 111282 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 20)
D: 111370 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 111376 [DL]Sending notification for CHIPoBLE TX (ConnId 00, len 10)
D: 111470 [DL]Notification for CHIPoBLE TX done (ConnId 0x00)
D: 111476 [DL]Write request received for CHIPoBLE RX (ConnId 0x00)
<41>

the version of nrf

*** Booting Zephyr OS build v2.4.99-ncs1-4959-g4e63ea417176  ***

commit of CHIP:

b0eeffc345840f84a25a69b77c996d9e7fe1b915

@jmartinez-silabs
Copy link
Member

I am looking into this thank you. I will link to this issue when there is a fix

@jmartinez-silabs jmartinez-silabs mentioned this issue Jun 17, 2021
Merged
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

Successfully merging a pull request may close this issue.

[EFR32] Heap fragmentation issue cause AddOpCert request to fail jmartinez-silabs/connectedhomeip
3 participants
@jmartinez-silabs @568760310 @ChengqiangShe