Hi all,
I trying to use test-harness v2.6 raspi and nRF52840dk to test commissioning.The result is always failure, and the error is timeout
The firmware DK flash is build from matter V1.0.0 Release，connectedhomeip/examples/lock-app/nrfconnect.
I have tried to test-harness v2.4 with DK flashed the same firmware commissioning successfully. But both test-harness v2.4 and test-harness v2.5 fail to time out.
Has anyone tested this? why V2.6 can't be commissioning successfully?
Below are the logs of chiptool and DK.
ubuntu@ubuntu:~/apps$ ./chip-tool pairing ble-thread 66 hex:0e080000000000010000000300001935060004001fffe002085b35dead5b35beef0708fd2c6fd19ad8db3f051000112233445566778899aabbccddeeff03043562333501025b350410eff65884a3c56f18b1d6204fec9432060c0402a0f7f8 20202021 4004
[1667898591.850033][3796:3796] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1667898591.855532][3796:3796] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1667898591.855844][3796:3796] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1667898591.855968][3796:3796] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1667898591.856293][3796:3796] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-RQtTxi)
[1667898591.856896][3796:3796] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1667898591.856948][3796:3796] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2)
[1667898591.857859][3796:3796] CHIP:DL: Got Ethernet interface: eth0
[1667898591.858535][3796:3796] CHIP:DL: Found the primary Ethernet interface:eth0
[1667898591.859136][3796:3796] CHIP:DL: Got WiFi interface: wlan0
[1667898591.859199][3796:3796] CHIP:DL: Failed to reset WiFi statistic counts
[1667898591.859249][3796:3796] CHIP:IN: UDP::Init bind&listen port=0
[1667898591.859363][3796:3796] CHIP:IN: UDP::Init bound to port=41818
[1667898591.859387][3796:3796] CHIP:IN: BLEBase::Init - setting/overriding transport
[1667898591.859408][3796:3796] CHIP:IN: TransportMgr initialized
[1667898591.859443][3796:3796] CHIP:FP: Initializing FabricTable from persistent storage
[1667898591.859573][3796:3796] CHIP:TS: Last Known Good Time: 2022-10-21T23:13:11
[1667898591.861073][3796:3796] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x289D5D313AA5011B, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1667898591.863124][3796:3796] CHIP:ZCL: Using ZAP configuration...
[1667898591.866958][3796:3796] CHIP:DL: Avahi client registered
[1667898591.868044][3796:3796] CHIP:CTL: System State Initialized...
[1667898591.868140][3796:3796] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1667898591.868179][3796:3796] CHIP:CTL: Setting attestation nonce to random value
[1667898591.868214][3796:3796] CHIP:CTL: Setting CSR nonce to random value
[1667898591.868482][3796:3801] CHIP:DL: CHIP task running
[1667898591.868654][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1667898591.868716][3796:3801] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1667898591.868746][3796:3801] CHIP:CTL: Setting attestation nonce to random value
[1667898591.868902][3796:3801] CHIP:CTL: Setting CSR nonce to random value
[1667898591.869964][3796:3801] CHIP:CTL: Generating NOC
[1667898591.871105][3796:3801] CHIP:FP: Validating NOC chain
[1667898591.873192][3796:3801] CHIP:FP: NOC chain validation successful
[1667898591.873369][3796:3801] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1667898591.873407][3796:3801] CHIP:TS: Last Known Good Time: 2022-10-21T23:13:11
[1667898591.873434][3796:3801] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1667898591.873459][3796:3801] CHIP:TS: Retaining current Last Known Good Time
[1667898591.877553][3796:3801] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1667898591.879500][3796:3801] CHIP:TS: Committing Last Known Good Time to storage: 2022-10-21T23:13:11
[1667898591.881251][3796:3801] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000
[1667898591.892944][3796:3801] CHIP:IN: SecureSession[0xffff8c009d20]: Allocated Type:1 LSID:64643
[1667898591.893004][3796:3801] CHIP:SC: Assigned local session key ID 64643
[1667898591.893083][3796:3801] CHIP:SC: Including MRP parameters in PBKDF param request
[1667898591.893157][3796:3801] CHIP:IN: Prepared unauthenticated message 0xffffa0a2dc58 to 0x0000000000000000 (0) of type 0x20 and protocolId (0, 0) on exchange 47590i with MessageCounter:76027510.
[1667898591.893203][3796:3801] CHIP:IN: Sending unauthenticated msg 0xffffa0a2dc58 with MessageCounter:76027510 to 0x0000000000000000 at monotonic time: 00000000003A0647 msec
[1667898591.893259][3796:3801] CHIP:IN: Message appended to BLE send queue
[1667898591.893285][3796:3801] CHIP:SC: Sent PBKDF param request
[1667898591.893316][3796:3801] CHIP:CTL: Setting thread operational dataset from parameters
[1667898591.893349][3796:3801] CHIP:CTL: Setting attempt thread scan from parameters
[1667898591.893373][3796:3801] CHIP:CTL: Setting attestation nonce to random value
[1667898591.893409][3796:3801] CHIP:CTL: Setting CSR nonce to random value
[1667898591.893457][3796:3801] CHIP:CTL: Commission called for node ID 0x0000000000000042
[1667898591.893809][3796:3802] CHIP:DL: TRACE: Bluez mainloop starting Thread
[1667898591.893988][3796:3799] CHIP:DL: TRACE: Bus acquired for name C-0ed4
[1667898591.901969][3796:3801] CHIP:DL: PlatformBlueZInit init success
[1667898591.908023][3796:3799] CHIP:BLE: BLE removing known devices.
[1667898591.909702][3796:3799] CHIP:BLE: BLE initiating scan.
[1667898591.916952][3796:3799] CHIP:BLE: Device 30:B5:30:25:0B:DE does not look like a CHIP device.
[1667898591.928004][3796:3799] CHIP:BLE: New device scanned: F0:65:2E:2F:C1:D0
[1667898591.928087][3796:3799] CHIP:BLE: Device discriminator match. Attempting to connect.
[1667898591.932084][3796:3799] CHIP:BLE: Scan complete notification without an active scan.
[1667898592.087033][3796:3799] CHIP:DL: ConnectDevice complete
[1667898593.591129][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0001
[1667898593.591181][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591216][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0001
[1667898593.591237][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591260][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0001
[1667898593.591279][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591307][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0001
[1667898593.591326][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591348][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0001
[1667898593.591367][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591389][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0001
[1667898593.591408][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591434][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591453][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591477][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591496][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591522][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0001
[1667898593.591541][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591563][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0001
[1667898593.591583][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591604][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0001
[1667898593.591623][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591650][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591669][3796:3799] CHIP:DL: Char1 /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0/service0010
[1667898593.591695][3796:3799] CHIP:DL: New BLE connection 0xffff980351e0, device F0:65:2E:2F:C1:D0, path /org/bluez/hci0/dev_F0_65_2E_2F_C1_D0
[1667898593.591802][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1667898593.591836][3796:3801] CHIP:IN: BleConnectionComplete: endPoint 0xaaaacdad00d8
[1667898594.036347][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1667898594.134120][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1667898594.134202][3796:3801] CHIP:BLE: subscribe complete, ep = 0xaaaacdad00d8
[1667898594.134555][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898594.134741][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898594.134805][3796:3801] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1667898594.134855][3796:3801] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1667898594.134899][3796:3801] CHIP:BLE: local and remote recv window size = 5
[1667898594.135080][3796:3801] CHIP:IN: BLE EndPoint 0xaaaacdad00d8 Connection Complete
[1667898594.279429][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1667898594.282063][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898594.282315][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898594.282539][3796:3801] CHIP:EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:63814348 on exchange 47590i
[1667898594.282617][3796:3801] CHIP:EM: Found matching exchange: 47590i, Delegate: 0xffff8c00ae30
[1667898594.282707][3796:3801] CHIP:SC: Received PBKDF param response
[1667898594.282800][3796:3801] CHIP:SC: Peer assigned session ID 58142
[1667898594.282877][3796:3801] CHIP:SC: Found MRP parameters in the message
[1667898594.294712][3796:3801] CHIP:IN: Prepared unauthenticated message 0xffffa0a2d7e8 to 0x0000000000000000 (0) of type 0x22 and protocolId (0, 0) on exchange 47590i with MessageCounter:76027511.
[1667898594.294768][3796:3801] CHIP:IN: Sending unauthenticated msg 0xffffa0a2d7e8 with MessageCounter:76027511 to 0x0000000000000000 at monotonic time: 00000000003A0FA9 msec
[1667898594.294865][3796:3801] CHIP:SC: Sent spake2p msg1
[1667898594.377033][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1667898596.377928][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898596.378219][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898596.378446][3796:3801] CHIP:EM: Received message of type 0x23 with protocolId (0, 0) and MessageCounter:63814349 on exchange 47590i
[1667898596.378564][3796:3801] CHIP:EM: Found matching exchange: 47590i, Delegate: 0xffff8c00ae30
[1667898596.378754][3796:3801] CHIP:SC: Received spake2p msg2
[1667898596.382067][3796:3801] CHIP:IN: Prepared unauthenticated message 0xffffa0a2d928 to 0x0000000000000000 (0) of type 0x24 and protocolId (0, 0) on exchange 47590i with MessageCounter:76027512.
[1667898596.382179][3796:3801] CHIP:IN: Sending unauthenticated msg 0xffffa0a2d928 with MessageCounter:76027512 to 0x0000000000000000 at monotonic time: 00000000003A17D0 msec
[1667898596.382376][3796:3801] CHIP:SC: Sent spake2p msg3
[1667898596.472969][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1667898596.522416][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898596.522597][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898596.522755][3796:3801] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:63814350 on exchange 47590i
[1667898596.522832][3796:3801] CHIP:EM: Found matching exchange: 47590i, Delegate: 0xffff8c00ae30
[1667898596.523132][3796:3801] CHIP:SC: SecureSession[0xffff8c009d20]: Moving from state 'kEstablishing' --> 'kActive'
[1667898596.523180][3796:3801] CHIP:IN: SecureSession[0xffff8c009d20]: Activated - Type:1 LSID:64643
[1667898596.523214][3796:3801] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:64643 PSID:58142!
[1667898596.523257][3796:3801] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1667898596.523291][3796:3801] CHIP:TOO: Pairing Success
[1667898596.523321][3796:3801] CHIP:TOO: PASE establishment successful
[1667898596.523356][3796:3801] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
[1667898596.523394][3796:3801] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'
[1667898596.523443][3796:3801] CHIP:CTL: Sending request for commissioning information
[1667898596.523562][3796:3801] CHIP:DMG: SendReadRequest ReadClient[0xffff8c016a20]: Sending Read Request
[1667898596.523781][3796:3801] CHIP:IN: Prepared secure message 0xffffa0a2d138 to 0xFFFFFFFB00000000 (0) of type 0x2 and protocolId (0, 1) on exchange 47591i with MessageCounter:19450924.
[1667898596.523857][3796:3801] CHIP:IN: Sending encrypted msg 0xffffa0a2d138 with MessageCounter:19450924 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000003A185E msec
[1667898596.523989][3796:3801] CHIP:DMG: MoveToState ReadClient[0xffff8c016a20]: Moving to [AwaitingIn]
[1667898596.619488][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1667898596.866579][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898596.866853][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898597.010597][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898597.011005][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898597.011165][3796:3801] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:172714638 on exchange 47591i
[1667898597.011200][3796:3801] CHIP:EM: Found matching exchange: 47591i, Delegate: 0xffff8c016a30
[1667898597.011289][3796:3801] CHIP:DMG: ReportDataMessage =
[1667898597.011315][3796:3801] CHIP:DMG: {
[1667898597.011335][3796:3801] CHIP:DMG: AttributeReportIBs =
[1667898597.011363][3796:3801] CHIP:DMG: [
[1667898597.011384][3796:3801] CHIP:DMG: AttributeReportIB =
[1667898597.011418][3796:3801] CHIP:DMG: {
[1667898597.011442][3796:3801] CHIP:DMG: AttributeDataIB =
[1667898597.011469][3796:3801] CHIP:DMG: {
[1667898597.011496][3796:3801] CHIP:DMG: DataVersion = 0xeac7ff90,
[1667898597.011522][3796:3801] CHIP:DMG: AttributePathIB =
[1667898597.011550][3796:3801] CHIP:DMG: {
[1667898597.011578][3796:3801] CHIP:DMG: Endpoint = 0x0,
[1667898597.011607][3796:3801] CHIP:DMG: Cluster = 0x31,
[1667898597.011637][3796:3801] CHIP:DMG: Attribute = 0x0000_0003,
[1667898597.011664][3796:3801] CHIP:DMG: }
[1667898597.011693][3796:3801] CHIP:DMG:
[1667898597.011721][3796:3801] CHIP:DMG: Data = 20,
[1667898597.011746][3796:3801] CHIP:DMG: },
[1667898597.011774][3796:3801] CHIP:DMG:
[1667898597.011796][3796:3801] CHIP:DMG: },
[1667898597.011827][3796:3801] CHIP:DMG:
[1667898597.011848][3796:3801] CHIP:DMG: AttributeReportIB =
[1667898597.011875][3796:3801] CHIP:DMG: {
[1667898597.011899][3796:3801] CHIP:DMG: AttributeDataIB =
[1667898597.011924][3796:3801] CHIP:DMG: {
[1667898597.011949][3796:3801] CHIP:DMG: DataVersion = 0xd87b2cdb,
[1667898597.011975][3796:3801] CHIP:DMG: AttributePathIB =
[1667898597.012001][3796:3801] CHIP:DMG: {
[1667898597.012028][3796:3801] CHIP:DMG: Endpoint = 0x0,
[1667898597.012058][3796:3801] CHIP:DMG: Cluster = 0x28,
[1667898597.012087][3796:3801] CHIP:DMG: Attribute = 0x0000_0004,
[1667898597.012114][3796:3801] CHIP:DMG: }
[1667898597.012142][3796:3801] CHIP:DMG:
[1667898597.012169][3796:3801] CHIP:DMG: Data = 32774,
[1667898597.012194][3796:3801] CHIP:DMG: },
[1667898597.012221][3796:3801] CHIP:DMG:
[1667898597.012243][3796:3801] CHIP:DMG: },
[1667898597.012275][3796:3801] CHIP:DMG:
[1667898597.012296][3796:3801] CHIP:DMG: AttributeReportIB =
[1667898597.012323][3796:3801] CHIP:DMG: {
[1667898597.012345][3796:3801] CHIP:DMG: AttributeDataIB =
[1667898597.012371][3796:3801] CHIP:DMG: {
[1667898597.012397][3796:3801] CHIP:DMG: DataVersion = 0xd87b2cdb,
[1667898597.012422][3796:3801] CHIP:DMG: AttributePathIB =
[1667898597.012449][3796:3801] CHIP:DMG: {
[1667898597.012476][3796:3801] CHIP:DMG: Endpoint = 0x0,
[1667898597.012505][3796:3801] CHIP:DMG: Cluster = 0x28,
[1667898597.012533][3796:3801] CHIP:DMG: Attribute = 0x0000_0002,
[1667898597.012560][3796:3801] CHIP:DMG: }
[1667898597.012588][3796:3801] CHIP:DMG:
[1667898597.012615][3796:3801] CHIP:DMG: Data = 65521,
[1667898597.012640][3796:3801] CHIP:DMG: },
[1667898597.012668][3796:3801] CHIP:DMG:
[1667898597.012690][3796:3801] CHIP:DMG: },
[1667898597.012720][3796:3801] CHIP:DMG:
[1667898597.012741][3796:3801] CHIP:DMG: AttributeReportIB =
[1667898597.012768][3796:3801] CHIP:DMG: {
[1667898597.012791][3796:3801] CHIP:DMG: AttributeDataIB =
[1667898597.012816][3796:3801] CHIP:DMG: {
[1667898597.012842][3796:3801] CHIP:DMG: DataVersion = 0xcca4d571,
[1667898597.012867][3796:3801] CHIP:DMG: AttributePathIB =
[1667898597.012893][3796:3801] CHIP:DMG: {
[1667898597.012920][3796:3801] CHIP:DMG: Endpoint = 0x0,
[1667898597.012950][3796:3801] CHIP:DMG: Cluster = 0x30,
[1667898597.012978][3796:3801] CHIP:DMG: Attribute = 0x0000_0003,
[1667898597.013005][3796:3801] CHIP:DMG: }
[1667898597.013033][3796:3801] CHIP:DMG:
[1667898597.013060][3796:3801] CHIP:DMG: Data = 0,
[1667898597.013085][3796:3801] CHIP:DMG: },
[1667898597.013112][3796:3801] CHIP:DMG:
[1667898597.013134][3796:3801] CHIP:DMG: },
[1667898597.013164][3796:3801] CHIP:DMG:
[1667898597.013185][3796:3801] CHIP:DMG: AttributeReportIB =
[1667898597.013212][3796:3801] CHIP:DMG: {
[1667898597.013235][3796:3801] CHIP:DMG: AttributeDataIB =
[1667898597.013260][3796:3801] CHIP:DMG: {
[1667898597.013285][3796:3801] CHIP:DMG: DataVersion = 0xcca4d571,
[1667898597.013311][3796:3801] CHIP:DMG: AttributePathIB =
[1667898597.013338][3796:3801] CHIP:DMG: {
[1667898597.013365][3796:3801] CHIP:DMG: Endpoint = 0x0,
[1667898597.013394][3796:3801] CHIP:DMG: Cluster = 0x30,
[1667898597.013423][3796:3801] CHIP:DMG: Attribute = 0x0000_0002,
[1667898597.013449][3796:3801] CHIP:DMG: }
[1667898597.013477][3796:3801] CHIP:DMG:
[1667898597.013504][3796:3801] CHIP:DMG: Data = 0,
[1667898597.013528][3796:3801] CHIP:DMG: },
[1667898597.013555][3796:3801] CHIP:DMG:
[1667898597.013578][3796:3801] CHIP:DMG: },
[1667898597.013609][3796:3801] CHIP:DMG:
[1667898597.013629][3796:3801] CHIP:DMG: AttributeReportIB =
[1667898597.013658][3796:3801] CHIP:DMG: {
[1667898597.013709][3796:3801] CHIP:DMG: AttributeDataIB =
[1667898597.013738][3796:3801] CHIP:DMG: {
[1667898597.013763][3796:3801] CHIP:DMG: DataVersion = 0xcca4d571,
[1667898597.013789][3796:3801] CHIP:DMG: AttributePathIB =
[1667898597.013815][3796:3801] CHIP:DMG: {
[1667898597.013843][3796:3801] CHIP:DMG: Endpoint = 0x0,
[1667898597.013871][3796:3801] CHIP:DMG: Cluster = 0x30,
[1667898597.013900][3796:3801] CHIP:DMG: Attribute = 0x0000_0001,
[1667898597.013926][3796:3801] CHIP:DMG: }
[1667898597.013953][3796:3801] CHIP:DMG:
[1667898597.013979][3796:3801] CHIP:DMG: Data =
[1667898597.014005][3796:3801] CHIP:DMG: {
[1667898597.014064][3796:3801] CHIP:DMG: 0x0 = 60,
[1667898597.014092][3796:3801] CHIP:DMG: 0x1 = 900,
[1667898597.014121][3796:3801] CHIP:DMG: },
[1667898597.014146][3796:3801] CHIP:DMG: },
[1667898597.014174][3796:3801] CHIP:DMG:
[1667898597.014196][3796:3801] CHIP:DMG: },
[1667898597.014227][3796:3801] CHIP:DMG:
[1667898597.014248][3796:3801] CHIP:DMG: AttributeReportIB =
[1667898597.014275][3796:3801] CHIP:DMG: {
[1667898597.014297][3796:3801] CHIP:DMG: AttributeDataIB =
[1667898597.014322][3796:3801] CHIP:DMG: {
[1667898597.014348][3796:3801] CHIP:DMG: DataVersion = 0xcca4d571,
[1667898597.014373][3796:3801] CHIP:DMG: AttributePathIB =
[1667898597.014400][3796:3801] CHIP:DMG: {
[1667898597.014427][3796:3801] CHIP:DMG: Endpoint = 0x0,
[1667898597.014456][3796:3801] CHIP:DMG: Cluster = 0x30,
[1667898597.014484][3796:3801] CHIP:DMG: Attribute = 0x0000_0000,
[1667898597.014510][3796:3801] CHIP:DMG: }
[1667898597.014538][3796:3801] CHIP:DMG:
[1667898597.014565][3796:3801] CHIP:DMG: Data = 0,
[1667898597.014590][3796:3801] CHIP:DMG: },
[1667898597.014617][3796:3801] CHIP:DMG:
[1667898597.014639][3796:3801] CHIP:DMG: },
[1667898597.014669][3796:3801] CHIP:DMG:
[1667898597.014690][3796:3801] CHIP:DMG: AttributeReportIB =
[1667898597.014717][3796:3801] CHIP:DMG: {
[1667898597.014739][3796:3801] CHIP:DMG: AttributeDataIB =
[1667898597.014764][3796:3801] CHIP:DMG: {
[1667898597.014790][3796:3801] CHIP:DMG: DataVersion = 0xeac7ff90,
[1667898597.014815][3796:3801] CHIP:DMG: AttributePathIB =
[1667898597.014842][3796:3801] CHIP:DMG: {
[1667898597.014869][3796:3801] CHIP:DMG: Endpoint = 0x0,
[1667898597.014898][3796:3801] CHIP:DMG: Cluster = 0x31,
[1667898597.014927][3796:3801] CHIP:DMG: Attribute = 0x0000_FFFC,
[1667898597.014953][3796:3801] CHIP:DMG: }
[1667898597.014981][3796:3801] CHIP:DMG:
[1667898597.015008][3796:3801] CHIP:DMG: Data = 2,
[1667898597.015033][3796:3801] CHIP:DMG: },
[1667898597.015060][3796:3801] CHIP:DMG:
[1667898597.015082][3796:3801] CHIP:DMG: },
[1667898597.015108][3796:3801] CHIP:DMG:
[1667898597.015128][3796:3801] CHIP:DMG: ],
[1667898597.015175][3796:3801] CHIP:DMG:
[1667898597.015198][3796:3801] CHIP:DMG: SuppressResponse = true,
[1667898597.015221][3796:3801] CHIP:DMG: InteractionModelRevision = 1
[1667898597.015240][3796:3801] CHIP:DMG: }
[1667898597.015889][3796:3801] CHIP:CTL: ----- NetworkCommissioning Features: has Thread. endpointid = 0
[1667898597.015981][3796:3801] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'
[1667898597.016011][3796:3801] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
[1667898597.016039][3796:3801] CHIP:CTL: Performing next commissioning step 'ArmFailSafe'
[1667898597.016057][3796:3801] CHIP:CTL: Arming failsafe (60 seconds)
[1667898597.016118][3796:3801] CHIP:DMG: ICR moving to [AddingComm]
[1667898597.016144][3796:3801] CHIP:DMG: ICR moving to [AddedComma]
[1667898597.016255][3796:3801] CHIP:IN: Prepared secure message 0xffffa0a2cdf8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 47592i with MessageCounter:19450925.
[1667898597.016292][3796:3801] CHIP:IN: Sending encrypted msg 0xffffa0a2cdf8 with MessageCounter:19450925 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000003A1A4A msec
[1667898597.016394][3796:3801] CHIP:DMG: ICR moving to [CommandSen]
[1667898597.204758][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1667898597.254290][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898597.254526][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898597.254806][3796:3801] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:172714639 on exchange 47592i
[1667898597.254878][3796:3801] CHIP:EM: Found matching exchange: 47592i, Delegate: 0xffff9800d608
[1667898597.254954][3796:3801] CHIP:DMG: ICR moving to [ResponseRe]
[1667898597.255044][3796:3801] CHIP:DMG: InvokeResponseMessage =
[1667898597.255099][3796:3801] CHIP:DMG: {
[1667898597.255150][3796:3801] CHIP:DMG: suppressResponse = false,
[1667898597.255203][3796:3801] CHIP:DMG: InvokeResponseIBs =
[1667898597.255272][3796:3801] CHIP:DMG: [
[1667898597.255326][3796:3801] CHIP:DMG: InvokeResponseIB =
[1667898597.255408][3796:3801] CHIP:DMG: {
[1667898597.255465][3796:3801] CHIP:DMG: CommandDataIB =
[1667898597.255534][3796:3801] CHIP:DMG: {
[1667898597.255607][3796:3801] CHIP:DMG: CommandPathIB =
[1667898597.255689][3796:3801] CHIP:DMG: {
[1667898597.255772][3796:3801] CHIP:DMG: EndpointId = 0x0,
[1667898597.255850][3796:3801] CHIP:DMG: ClusterId = 0x30,
[1667898597.255928][3796:3801] CHIP:DMG: CommandId = 0x1,
[1667898597.256001][3796:3801] CHIP:DMG: },
[1667898597.256084][3796:3801] CHIP:DMG:
[1667898597.256145][3796:3801] CHIP:DMG: CommandFields =
[1667898597.256224][3796:3801] CHIP:DMG: {
[1667898597.256300][3796:3801] CHIP:DMG: 0x0 = 0,
[1667898597.256382][3796:3801] CHIP:DMG: 0x1 = "" (0 chars),
[1667898597.256465][3796:3801] CHIP:DMG: },
[1667898597.256533][3796:3801] CHIP:DMG: },
[1667898597.256610][3796:3801] CHIP:DMG:
[1667898597.256670][3796:3801] CHIP:DMG: },
[1667898597.256743][3796:3801] CHIP:DMG:
[1667898597.256796][3796:3801] CHIP:DMG: ],
[1667898597.256863][3796:3801] CHIP:DMG:
[1667898597.256917][3796:3801] CHIP:DMG: InteractionModelRevision = 1
[1667898597.256968][3796:3801] CHIP:DMG: },
[1667898597.257094][3796:3801] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1667898597.257169][3796:3801] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1667898597.257229][3796:3801] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe'
[1667898597.257279][3796:3801] CHIP:CTL: No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks
[1667898597.257324][3796:3801] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
[1667898597.257381][3796:3801] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory'
[1667898597.257426][3796:3801] CHIP:CTL: Setting Regulatory Config
[1667898597.257470][3796:3801] CHIP:CTL: Device does not support configurable regulatory location
[1667898597.257581][3796:3801] CHIP:DMG: ICR moving to [AddingComm]
[1667898597.257645][3796:3801] CHIP:DMG: ICR moving to [AddedComma]
[1667898597.257991][3796:3801] CHIP:IN: Prepared secure message 0xffffa0a2c898 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 47593i with MessageCounter:19450926.
[1667898597.258077][3796:3801] CHIP:IN: Sending encrypted msg 0xffffa0a2c898 with MessageCounter:19450926 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000003A1B3C msec
[1667898597.258253][3796:3801] CHIP:DMG: ICR moving to [CommandSen]
[1667898597.258364][3796:3801] CHIP:DMG: ICR moving to [AwaitingDe]
[1667898597.448362][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1667898597.662666][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898597.662941][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898597.663252][3796:3801] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:172714640 on exchange 47593i
[1667898597.663333][3796:3801] CHIP:EM: Found matching exchange: 47593i, Delegate: 0xffff8c009588
[1667898597.663424][3796:3801] CHIP:DMG: ICR moving to [ResponseRe]
[1667898597.663530][3796:3801] CHIP:DMG: InvokeResponseMessage =
[1667898597.663595][3796:3801] CHIP:DMG: {
[1667898597.663655][3796:3801] CHIP:DMG: suppressResponse = false,
[1667898597.663717][3796:3801] CHIP:DMG: InvokeResponseIBs =
[1667898597.663798][3796:3801] CHIP:DMG: [
[1667898597.663861][3796:3801] CHIP:DMG: InvokeResponseIB =
[1667898597.663959][3796:3801] CHIP:DMG: {
[1667898597.664026][3796:3801] CHIP:DMG: CommandDataIB =
[1667898597.664109][3796:3801] CHIP:DMG: {
[1667898597.664194][3796:3801] CHIP:DMG: CommandPathIB =
[1667898597.664289][3796:3801] CHIP:DMG: {
[1667898597.664369][3796:3801] CHIP:DMG: EndpointId = 0x0,
[1667898597.664468][3796:3801] CHIP:DMG: ClusterId = 0x30,
[1667898597.664564][3796:3801] CHIP:DMG: CommandId = 0x3,
[1667898597.664656][3796:3801] CHIP:DMG: },
[1667898597.664745][3796:3801] CHIP:DMG:
[1667898597.664823][3796:3801] CHIP:DMG: CommandFields =
[1667898597.664910][3796:3801] CHIP:DMG: {
[1667898597.664999][3796:3801] CHIP:DMG: 0x0 = 0,
[1667898597.665102][3796:3801] CHIP:DMG: 0x1 = "" (0 chars),
[1667898597.665191][3796:3801] CHIP:DMG: },
[1667898597.665272][3796:3801] CHIP:DMG: },
[1667898597.665354][3796:3801] CHIP:DMG:
[1667898597.665424][3796:3801] CHIP:DMG: },
[1667898597.665508][3796:3801] CHIP:DMG:
[1667898597.665569][3796:3801] CHIP:DMG: ],
[1667898597.665646][3796:3801] CHIP:DMG:
[1667898597.665755][3796:3801] CHIP:DMG: InteractionModelRevision = 1
[1667898597.665816][3796:3801] CHIP:DMG: },
[1667898597.665961][3796:3801] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
[1667898597.671670][3796:3801] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0
[1667898597.671763][3796:3801] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory'
[1667898597.671824][3796:3801] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
[1667898597.671893][3796:3801] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest'
[1667898597.671948][3796:3801] CHIP:CTL: Sending request for PAI certificate
[1667898597.671999][3796:3801] CHIP:CTL: Sending Certificate Chain request to 0xffff8c00ade0 device
[1667898597.672208][3796:3801] CHIP:DMG: ICR moving to [AddingComm]
[1667898597.674504][3796:3801] CHIP:DMG: ICR moving to [AddedComma]
[1667898597.674656][3796:3801] CHIP:IN: Prepared secure message 0xffffa0a2c7d8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 47594i with MessageCounter:19450927.
[1667898597.674714][3796:3801] CHIP:IN: Sending encrypted msg 0xffffa0a2c7d8 with MessageCounter:19450927 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000003A1CDD msec
[1667898597.674864][3796:3801] CHIP:DMG: ICR moving to [CommandSen]
[1667898597.674964][3796:3801] CHIP:DMG: ICR moving to [AwaitingDe]
[1667898597.750850][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1667898597.889058][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898597.889334][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898597.979133][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898597.979405][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898598.066944][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898598.067442][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898598.067744][3796:3801] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:172714641 on exchange 47594i
[1667898598.067823][3796:3801] CHIP:EM: Found matching exchange: 47594i, Delegate: 0xffff9800d608
[1667898598.067919][3796:3801] CHIP:DMG: ICR moving to [ResponseRe]
[1667898598.068025][3796:3801] CHIP:DMG: InvokeResponseMessage =
[1667898598.068252][3796:3801] CHIP:DMG: {
[1667898598.068318][3796:3801] CHIP:DMG: suppressResponse = false,
[1667898598.068381][3796:3801] CHIP:DMG: InvokeResponseIBs =
[1667898598.068461][3796:3801] CHIP:DMG: [
[1667898598.068524][3796:3801] CHIP:DMG: InvokeResponseIB =
[1667898598.068667][3796:3801] CHIP:DMG: {
[1667898598.068794][3796:3801] CHIP:DMG: CommandDataIB =
[1667898598.068927][3796:3801] CHIP:DMG: {
[1667898598.069058][3796:3801] CHIP:DMG: CommandPathIB =
[1667898598.069197][3796:3801] CHIP:DMG: {
[1667898598.069335][3796:3801] CHIP:DMG: EndpointId = 0x0,
[1667898598.069475][3796:3801] CHIP:DMG: ClusterId = 0x3e,
[1667898598.069614][3796:3801] CHIP:DMG: CommandId = 0x3,
[1667898598.069750][3796:3801] CHIP:DMG: },
[1667898598.069881][3796:3801] CHIP:DMG:
[1667898598.070057][3796:3801] CHIP:DMG: CommandFields =
[1667898598.070159][3796:3801] CHIP:DMG: {
[1667898598.070258][3796:3801] CHIP:DMG: 0x0 = [
[1667898598.070518][3796:3801] CHIP:DMG: 0x30, 0x82, 0x1, 0xcb, 0x30, 0x82, 0x1, 0x71, 0xa0, 0x3, 0x2, 0x1, 0x2, 0x2, 0x8, 0x56, 0xad, 0x82, 0x22, 0xad, 0x94, 0x5b, 0x64, 0x30, 0xa, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0xf, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0xd, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0xf, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0x41, 0x9a, 0x93, 0x15, 0xc2, 0x17, 0x3e, 0xc, 0x8c, 0x87, 0x6d, 0x3, 0xcc, 0xfc, 0x94, 0x48, 0x52, 0x64, 0x7f, 0x7f, 0xec, 0x5e, 0x50, 0x82, 0xf4, 0x5, 0x99, 0x28, 0xec, 0xa8, 0x94, 0xc5, 0x94, 0x15, 0x13, 0x9, 0xac, 0x63, 0x1e, 0x4c, 0xb0, 0x33, 0x92, 0xaf, 0x68, 0x4b, 0xb, 0xaf, 0xb7, 0xe6, 0x5b, 0x3b, 0x81, 0x62, 0xc2, 0xf5, 0x2b, 0xf9, 0x31, 0xb8, 0xe7, 0x7a, 0xaa, 0x82, 0xa3, 0x66, 0x30, 0x64, 0x30, 0x12, 0x6, 0x3, 0x55, 0x1d, 0x13, 0x1, 0x1, 0xff, 0x4, 0x8, 0x30, 0x6, 0x1, 0x1, 0xff, 0x2, 0x1,
[1667898598.070686][3796:3801] CHIP:DMG: ] (463 bytes)
[1667898598.070785][3796:3801] CHIP:DMG: },
[1667898598.070880][3796:3801] CHIP:DMG: },
[1667898598.070976][3796:3801] CHIP:DMG:
[1667898598.071029][3796:3801] CHIP:DMG: },
[1667898598.071115][3796:3801] CHIP:DMG:
[1667898598.071159][3796:3801] CHIP:DMG: ],
[1667898598.071213][3796:3801] CHIP:DMG:
[1667898598.071257][3796:3801] CHIP:DMG: InteractionModelRevision = 1
[1667898598.071298][3796:3801] CHIP:DMG: },
[1667898598.071396][3796:3801] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1667898598.071451][3796:3801] CHIP:CTL: Received certificate chain from the device
[1667898598.071501][3796:3801] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest'
[1667898598.071545][3796:3801] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
[1667898598.071594][3796:3801] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest'
[1667898598.071631][3796:3801] CHIP:CTL: Sending request for DAC certificate
[1667898598.071665][3796:3801] CHIP:CTL: Sending Certificate Chain request to 0xffff8c00ade0 device
[1667898598.071762][3796:3801] CHIP:DMG: ICR moving to [AddingComm]
[1667898598.071813][3796:3801] CHIP:DMG: ICR moving to [AddedComma]
[1667898598.071972][3796:3801] CHIP:IN: Prepared secure message 0xffffa0a2c7e8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 47595i with MessageCounter:19450928.
[1667898598.072043][3796:3801] CHIP:IN: Sending encrypted msg 0xffffa0a2c7e8 with MessageCounter:19450928 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000003A1E6A msec
[1667898598.072205][3796:3801] CHIP:DMG: ICR moving to [CommandSen]
[1667898598.072362][3796:3801] CHIP:DMG: ICR moving to [AwaitingDe]
[1667898598.246880][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1667898598.250755][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898598.250968][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898598.384194][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898598.384470][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898598.472119][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898598.472402][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898598.472715][3796:3801] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:172714642 on exchange 47595i
[1667898598.472795][3796:3801] CHIP:EM: Found matching exchange: 47595i, Delegate: 0xffff9800a4a8
[1667898598.472891][3796:3801] CHIP:DMG: ICR moving to [ResponseRe]
[1667898598.472997][3796:3801] CHIP:DMG: InvokeResponseMessage =
[1667898598.473062][3796:3801] CHIP:DMG: {
[1667898598.473122][3796:3801] CHIP:DMG: suppressResponse = false,
[1667898598.473185][3796:3801] CHIP:DMG: InvokeResponseIBs =
[1667898598.473267][3796:3801] CHIP:DMG: [
[1667898598.473330][3796:3801] CHIP:DMG: InvokeResponseIB =
[1667898598.473428][3796:3801] CHIP:DMG: {
[1667898598.473501][3796:3801] CHIP:DMG: CommandDataIB =
[1667898598.473590][3796:3801] CHIP:DMG: {
[1667898598.473737][3796:3801] CHIP:DMG: CommandPathIB =
[1667898598.473839][3796:3801] CHIP:DMG: {
[1667898598.473935][3796:3801] CHIP:DMG: EndpointId = 0x0,
[1667898598.474035][3796:3801] CHIP:DMG: ClusterId = 0x3e,
[1667898598.474133][3796:3801] CHIP:DMG: CommandId = 0x3,
[1667898598.474226][3796:3801] CHIP:DMG: },
[1667898598.474318][3796:3801] CHIP:DMG:
[1667898598.474396][3796:3801] CHIP:DMG: CommandFields =
[1667898598.474481][3796:3801] CHIP:DMG: {
[1667898598.474575][3796:3801] CHIP:DMG: 0x0 = [
[1667898598.474919][3796:3801] CHIP:DMG: 0x30, 0x82, 0x1, 0xe7, 0x30, 0x82, 0x1, 0x8d, 0xa0, 0x3, 0x2, 0x1, 0x2, 0x2, 0x7, 0x21, 0xf6, 0x6d, 0xf5, 0x1d, 0x72, 0x58, 0x30, 0xa, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0xd, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0xf, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x53, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x44, 0x41, 0x43, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x2f, 0x30, 0x78, 0x38, 0x30, 0x30, 0x36, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x2, 0xc, 0x4, 0x38, 0x30, 0x30, 0x36, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0x5e, 0x91, 0xed, 0x92, 0x50, 0x16, 0xcc, 0x82, 0x67, 0x19, 0x7a, 0x9, 0xb, 0x75, 0x33, 0xe5, 0x54, 0xe2, 0x5c, 0x8b, 0x9, 0x3c, 0xdd, 0xca, 0x9e, 0xaf, 0xcb, 0xa7, 0x47, 0xfe, 0xb8, 0xb5, 0xb8, 0xdc, 0x78, 0x9f, 0xf, 0x9d, 0xb0, 0xd8, 0xfc, 0xae, 0xac, 0x6c, 0xfd, 0x83, 0x9c, 0x51, 0xb3, 0xbd, 0xe, 0x4b, 0xc
[1667898598.475107][3796:3801] CHIP:DMG: ] (491 bytes)
[1667898598.475205][3796:3801] CHIP:DMG: },
[1667898598.475294][3796:3801] CHIP:DMG: },
[1667898598.475391][3796:3801] CHIP:DMG:
[1667898598.475463][3796:3801] CHIP:DMG: },
[1667898598.475546][3796:3801] CHIP:DMG:
[1667898598.475607][3796:3801] CHIP:DMG: ],
[1667898598.475684][3796:3801] CHIP:DMG:
[1667898598.475749][3796:3801] CHIP:DMG: InteractionModelRevision = 1
[1667898598.475809][3796:3801] CHIP:DMG: },
[1667898598.475952][3796:3801] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1667898598.476033][3796:3801] CHIP:CTL: Received certificate chain from the device
[1667898598.476103][3796:3801] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest'
[1667898598.476170][3796:3801] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
[1667898598.476237][3796:3801] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest'
[1667898598.476291][3796:3801] CHIP:CTL: Sending Attestation Request to the device.
[1667898598.476496][3796:3801] CHIP:CTL: Sending Attestation request to 0xffff8c00ade0 device
[1667898598.476626][3796:3801] CHIP:DMG: ICR moving to [AddingComm]
[1667898598.476699][3796:3801] CHIP:DMG: ICR moving to [AddedComma]
[1667898598.476893][3796:3801] CHIP:IN: Prepared secure message 0xffffa0a2c7a8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 47596i with MessageCounter:19450929.
[1667898598.476987][3796:3801] CHIP:IN: Sending encrypted msg 0xffffa0a2c7a8 with MessageCounter:19450929 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000003A1FFF msec
[1667898598.477192][3796:3801] CHIP:DMG: ICR moving to [CommandSen]
[1667898598.477266][3796:3801] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information
[1667898598.477372][3796:3801] CHIP:DMG: ICR moving to [AwaitingDe]
[1667898598.605978][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1667898598.654122][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898598.654409][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898598.879169][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898598.879672][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898598.968984][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898598.969259][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898598.969587][3796:3801] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:172714643 on exchange 47596i
[1667898598.969720][3796:3801] CHIP:EM: Found matching exchange: 47596i, Delegate: 0xffff98036d18
[1667898598.969825][3796:3801] CHIP:DMG: ICR moving to [ResponseRe]
[1667898598.969937][3796:3801] CHIP:DMG: InvokeResponseMessage =
[1667898598.970003][3796:3801] CHIP:DMG: {
[1667898598.970064][3796:3801] CHIP:DMG: suppressResponse = false,
[1667898598.970127][3796:3801] CHIP:DMG: InvokeResponseIBs =
[1667898598.970208][3796:3801] CHIP:DMG: [
[1667898598.970271][3796:3801] CHIP:DMG: InvokeResponseIB =
[1667898598.970365][3796:3801] CHIP:DMG: {
[1667898598.970433][3796:3801] CHIP:DMG: CommandDataIB =
[1667898598.970514][3796:3801] CHIP:DMG: {
[1667898598.970589][3796:3801] CHIP:DMG: CommandPathIB =
[1667898598.970675][3796:3801] CHIP:DMG: {
[1667898598.970770][3796:3801] CHIP:DMG: EndpointId = 0x0,
[1667898598.970869][3796:3801] CHIP:DMG: ClusterId = 0x3e,
[1667898598.970966][3796:3801] CHIP:DMG: CommandId = 0x1,
[1667898598.971058][3796:3801] CHIP:DMG: },
[1667898598.971147][3796:3801] CHIP:DMG:
[1667898598.971232][3796:3801] CHIP:DMG: CommandFields =
[1667898598.971318][3796:3801] CHIP:DMG: {
[1667898598.971404][3796:3801] CHIP:DMG: 0x0 = [
[1667898598.971754][3796:3801] CHIP:DMG: 0x15, 0x31, 0x1, 0x1c, 0x2, 0x30, 0x82, 0x2, 0x18, 0x6, 0x9, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0xd, 0x1, 0x7, 0x2, 0xa0, 0x82, 0x2, 0x9, 0x30, 0x82, 0x2, 0x5, 0x2, 0x1, 0x3, 0x31, 0xd, 0x30, 0xb, 0x6, 0x9, 0x60, 0x86, 0x48, 0x1, 0x65, 0x3, 0x4, 0x2, 0x1, 0x30, 0x82, 0x1, 0x70, 0x6, 0x9, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0xd, 0x1, 0x7, 0x1, 0xa0, 0x82, 0x1, 0x61, 0x4, 0x82, 0x1, 0x5d, 0x15, 0x24, 0x0, 0x1, 0x25, 0x1, 0xf1, 0xff, 0x36, 0x2, 0x5, 0x0, 0x80, 0x5, 0x1, 0x80, 0x5, 0x2, 0x80, 0x5, 0x3, 0x80, 0x5, 0x4, 0x80, 0x5, 0x5, 0x80, 0x5, 0x6, 0x80, 0x5, 0x7, 0x80, 0x5, 0x8, 0x80, 0x5, 0x9, 0x80, 0x5, 0xa, 0x80, 0x5, 0xb, 0x80, 0x5, 0xc, 0x80, 0x5, 0xd, 0x80, 0x5, 0xe, 0x80, 0x5, 0xf, 0x80, 0x5, 0x10, 0x80, 0x5, 0x11, 0x80, 0x5, 0x12, 0x80, 0x5, 0x13, 0x80, 0x5, 0x14, 0x80, 0x5, 0x15, 0x80, 0x5, 0x16, 0x80, 0x5, 0x17, 0x80, 0x5, 0x18, 0x80, 0x5, 0x19, 0x80, 0x5, 0x1a, 0x80, 0x5, 0x1b, 0x80, 0x5, 0x1c, 0x80, 0x5, 0x1d, 0x80, 0x5, 0x1e, 0x80, 0x5, 0x1f, 0x80, 0x5, 0x20, 0x80, 0x5, 0x21, 0x80, 0x5, 0x22, 0x80, 0x5, 0x23, 0x80, 0x5, 0x24, 0x80, 0x5, 0x25, 0x80, 0x5, 0x26, 0x80, 0x5, 0x27, 0x80, 0x5, 0x28, 0x80, 0x5, 0x29, 0x80, 0x5, 0x2a, 0x80, 0x5, 0x2b, 0x80, 0x5, 0x2c, 0x80, 0x5, 0x2d, 0x80, 0x5, 0x2e, 0x80, 0x5, 0x2f, 0x80, 0x5, 0x30, 0x80, 0x5, 0x31, 0x80, 0x5, 0x32, 0x80, 0x5, 0x33, 0x80, 0x5, 0x34, 0x80, 0x5, 0x35, 0x80, 0x5, 0x36, 0x80, 0x5, 0x37, 0x80, 0x5, 0x38, 0x80, 0x5, 0x39, 0x80, 0x5, 0x3a, 0x80, 0x5, 0x3b, 0x80, 0x5, 0x3c, 0x80, 0x5, 0x3d, 0x80, 0x5, 0x3e, 0x80, 0x5, 0x3f, 0x80, 0x5, 0x40, 0x80, 0x5, 0x41, 0x80, 0x5, 0x42, 0x80, 0x5, 0x43, 0x80, 0x5, 0x44, 0x80, 0x5, 0x45, 0x80, 0x5, 0x46, 0x80, 0x5, 0x47, 0x80, 0x5, 0x48, 0x80, 0x5, 0x49, 0x80, 0x5, 0x4a, 0x80, 0x5, 0
[1667898598.971952][3796:3801] CHIP:DMG: ] (584 bytes)
[1667898598.972050][3796:3801] CHIP:DMG: 0x1 = [
[1667898598.972185][3796:3801] CHIP:DMG: 0x7d, 0xa7, 0x58, 0xc6, 0x74, 0xb5, 0xfc, 0x3f, 0xee, 0x1c, 0x2a, 0x54, 0xcc, 0xfa, 0x80, 0xb2, 0x3a, 0x46, 0xee, 0xf8, 0xb, 0xc7, 0xdb, 0xd2, 0xf0, 0x7b, 0x0, 0xd3, 0x21, 0x65, 0x65, 0xb8, 0x47, 0x93, 0xae, 0xfa, 0xf2, 0x41, 0xac, 0x79, 0x5f, 0xe, 0xe2, 0x38, 0x1a, 0xac, 0xe7, 0x60, 0x9c, 0x66, 0xf9, 0xf3, 0xe7, 0x68, 0x21, 0xf1, 0xcf, 0x3, 0x3e, 0x70, 0x5b, 0xcc, 0x77, 0xe5,
[1667898598.972295][3796:3801] CHIP:DMG: ] (64 bytes)
[1667898598.972394][3796:3801] CHIP:DMG: },
[1667898598.972480][3796:3801] CHIP:DMG: },
[1667898598.972569][3796:3801] CHIP:DMG:
[1667898598.972640][3796:3801] CHIP:DMG: },
[1667898598.972724][3796:3801] CHIP:DMG:
[1667898598.972785][3796:3801] CHIP:DMG: ],
[1667898598.972863][3796:3801] CHIP:DMG:
[1667898598.972925][3796:3801] CHIP:DMG: InteractionModelRevision = 1
[1667898598.972985][3796:3801] CHIP:DMG: },
[1667898598.973134][3796:3801] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
[1667898598.973217][3796:3801] CHIP:CTL: Received Attestation Information from the device
[1667898598.973288][3796:3801] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest'
[1667898598.973404][3796:3801] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
[1667898598.973479][3796:3801] CHIP:CTL: Performing next commissioning step 'AttestationVerification'
[1667898598.973536][3796:3801] CHIP:CTL: Verifying attestation
[1667898598.998303][3796:3801] CHIP:CTL: Failed in verifying 'Attestation Information' command received from the device: err 601. Look at AttestationVerificationResult enum to understand the errors
[1667898598.998391][3796:3801] CHIP:CTL: Error on commissioning step 'AttestationVerification': '../../src/controller/CHIPDeviceController.cpp:1027: CHIP Error 0x000000AC: Internal error'
[1667898598.998413][3796:3801] CHIP:CTL: Failed to perform commissioning step 8
[1667898598.998436][3796:3801] CHIP:CTL: Going from commissioning step 'AttestationVerification' with lastErr = '../../src/controller/CHIPDeviceController.cpp:1027: CHIP Error 0x000000AC: Internal error' -> 'Cleanup'
[1667898598.998469][3796:3801] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../../src/controller/CHIPDeviceController.cpp:1027: CHIP Error 0x000000AC: Internal error'
[1667898598.998490][3796:3801] CHIP:CTL: Expiring failsafe on proxy 0xffff8c00ade0
[1667898598.998560][3796:3801] CHIP:DMG: ICR moving to [AddingComm]
[1667898598.998589][3796:3801] CHIP:DMG: ICR moving to [AddedComma]
[1667898598.998703][3796:3801] CHIP:IN: Prepared secure message 0xffffa0a2bd48 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 47597i with MessageCounter:19450930.
[1667898598.998741][3796:3801] CHIP:IN: Sending encrypted msg 0xffffa0a2bd48 with MessageCounter:19450930 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000003A2209 msec
[1667898598.998847][3796:3801] CHIP:DMG: ICR moving to [CommandSen]
[1667898598.998907][3796:3801] CHIP:DMG: ICR moving to [AwaitingDe]
[1667898599.145988][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1667898599.236759][3796:3799] CHIP:DL: Indication received, conn = 0xffff980351e0
[1667898599.237010][3796:3801] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1667898599.237296][3796:3801] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:172714644 on exchange 47597i
[1667898599.237369][3796:3801] CHIP:EM: Found matching exchange: 47597i, Delegate: 0xffff98036e78
[1667898599.237447][3796:3801] CHIP:DMG: ICR moving to [ResponseRe]
[1667898599.237539][3796:3801] CHIP:DMG: InvokeResponseMessage =
[1667898599.237594][3796:3801] CHIP:DMG: {
[1667898599.237645][3796:3801] CHIP:DMG: suppressResponse = false,
[1667898599.237750][3796:3801] CHIP:DMG: InvokeResponseIBs =
[1667898599.237822][3796:3801] CHIP:DMG: [
[1667898599.237876][3796:3801] CHIP:DMG: InvokeResponseIB =
[1667898599.237958][3796:3801] CHIP:DMG: {
[1667898599.238015][3796:3801] CHIP:DMG: CommandDataIB =
[1667898599.238091][3796:3801] CHIP:DMG: {
[1667898599.238164][3796:3801] CHIP:DMG: CommandPathIB =
[1667898599.238239][3796:3801] CHIP:DMG: {
[1667898599.238321][3796:3801] CHIP:DMG: EndpointId = 0x0,
[1667898599.238399][3796:3801] CHIP:DMG: ClusterId = 0x30,
[1667898599.238476][3796:3801] CHIP:DMG: CommandId = 0x1,
[1667898599.238555][3796:3801] CHIP:DMG: },
[1667898599.238631][3796:3801] CHIP:DMG:
[1667898599.238705][3796:3801] CHIP:DMG: CommandFields =
[1667898599.238777][3796:3801] CHIP:DMG: {
[1667898599.238853][3796:3801] CHIP:DMG: 0x0 = 0,
[1667898599.238943][3796:3801] CHIP:DMG: 0x1 = "" (0 chars),
[1667898599.239027][3796:3801] CHIP:DMG: },
[1667898599.239101][3796:3801] CHIP:DMG: },
[1667898599.239183][3796:3801] CHIP:DMG:
[1667898599.239243][3796:3801] CHIP:DMG: },
[1667898599.239316][3796:3801] CHIP:DMG:
[1667898599.239368][3796:3801] CHIP:DMG: ],
[1667898599.239436][3796:3801] CHIP:DMG:
[1667898599.239489][3796:3801] CHIP:DMG: InteractionModelRevision = 1
[1667898599.239540][3796:3801] CHIP:DMG: },
[1667898599.239666][3796:3801] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1667898599.239740][3796:3801] CHIP:CTL: Failsafe disarmed
[1667898599.239800][3796:3801] CHIP:CTL: Successfully finished commissioning step 'Cleanup'
[1667898599.239875][3796:3801] CHIP:TOO: Device commissioning Failure: ../../src/controller/CHIPDeviceController.cpp:1027: CHIP Error 0x000000AC: Internal error
[1667898599.239967][3796:3801] CHIP:DIS: Closing all BLE connections
[1667898599.240020][3796:3801] CHIP:IN: Clearing BLE pending packets.
[1667898599.240140][3796:3801] CHIP:BLE: Auto-closing end point's BLE connection.
[1667898599.240192][3796:3801] CHIP:DL: Closing BLE GATT connection (con 0xffff980351e0)
[1667898599.240360][3796:3801] CHIP:DMG: ICR moving to [AwaitingDe]
[1667898599.240531][3796:3799] CHIP:DL: BluezDisconnect peer=F0:65:2E:2F:C1:D0
[1667898599.240806][3796:3796] CHIP:CTL: Shutting down the commissioner
[1667898599.240874][3796:3796] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1667898599.240920][3796:3796] CHIP:CTL: Shutting down the controller
[1667898599.240982][3796:3796] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1667898599.241034][3796:3796] CHIP:FP: Forgetting fabric 0x1
[1667898599.241096][3796:3796] CHIP:TS: Pending Last Known Good Time: 2022-10-21T23:13:11
[1667898599.241349][3796:3796] CHIP:TS: Previous Last Known Good Time: 2022-10-21T23:13:11
[1667898599.241406][3796:3796] CHIP:TS: Reverted Last Known Good Time to previous value
[1667898599.241491][3796:3796] CHIP:CTL: Shutting down the commissioner
[1667898599.241534][3796:3796] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1667898599.241572][3796:3796] CHIP:CTL: Shutting down the controller
[1667898599.241608][3796:3796] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1667898599.243671][3796:3796] CHIP:DMG: IM WH moving to [Uninitialized]
[1667898599.243753][3796:3796] CHIP:DMG: IM WH moving to [Uninitialized]
[1667898599.243798][3796:3796] CHIP:DMG: IM WH moving to [Uninitialized]
[1667898599.243924][3796:3796] CHIP:DMG: IM WH moving to [Uninitialized]
[1667898599.243982][3796:3796] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1667898599.244140][3796:3796] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1667898599.244589][3796:3796] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-EGimzo)
[1667898599.245876][3796:3796] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1667898599.246052][3796:3796] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1667898599.246110][3796:3796] CHIP:DL: Inet Layer shutdown
[1667898599.246158][3796:3796] CHIP:DL: BLE shutdown
[1667898599.247695][3796:3796] CHIP:DL: System Layer shutdown
[1667898599.247807][3796:3796] CHIP:IN: SecureSession[0xffff8c009d20]: MarkForEviction Type:1 LSID:64643
[1667898599.247835][3796:3796] CHIP:SC: SecureSession[0xffff8c009d20]: Moving from state 'kActive' --> 'kPendingEviction'
[1667898599.247858][3796:3796] CHIP:IN: SecureSession[0xffff8c009d20]: Released - Type:1 LSID:64643
[1667898599.247924][3796:3796] CHIP:TOO: Run command failure: ../../src/controller/CHIPDeviceController.cpp:1027: CHIP Error 0x000000AC: Internal error
uart:~$
uart:~$ D: 7407 [IN]SecureSession[0x200030f0]: Allocated Type:1 LSID:58142
D: 7413 [SC]Assigned local session key ID 58142
D: 7417 [SC]Waiting for PBKDF param request
D: 7421 [DL]CHIPoBLE advertising set to on
I: 7425 [DIS]Updating services using commissioning mode 1
D: 7430 [DL]Using Thread extended MAC for hostname.
D: 7435 [DL]Using Thread extended MAC for hostname.
I: 7441 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=4004/15 cm=1
E: 7450 [DIS]Failed to advertise commissionable node: 3
E: 7455 [DIS]Failed to finalize service update: 1c
I: 7462 [DL]CHIPoBLE advertising started
I: 7467 [DL]NFC Tag emulation started
I: 14876 [DL]BLE connection established (ConnId: 0x00)
I: 14881 [DL]Current number of connections: 1/1
I: 14885 [DL]CHIPoBLE advertising stopped
I: 14889 [DL]NFC Tag emulation stopped
D: 16830 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 16837 [BLE]local and remote recv window sizes = 5
I: 16841 [BLE]selected BTP version 4
I: 16845 [BLE]using BTP fragment sizes rx 244 / tx 244.
D: 16927 [DL]ConnId: 0x00, New CCCD value: 0x0002
D: 16932 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 6)
D: 16939 [IN]BLE EndPoint 0x20011d00 Connection Complete
I: 16944 [DL]CHIPoBLE connection established (ConnId: 0x00, GATT MTU: 247)
D: 17024 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 17033 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 17040 [EM]>>> [E:47590r M:76027510] (U) Msg RX from 0:F7C620AF8D6897A3 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
D: 17052 [EM]Handling via exchange: 47590r, Delegate: 0x2000521c
D: 17057 [SC]Received PBKDF param request
D: 17061 [SC]Peer assigned session ID 64643
D: 17065 [SC]Found MRP parameters in the message
D: 17070 [SC]Including MRP parameters in PBKDF param response
I: 17076 [EM]<<< [E:47590r M:63814348] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
I: 17087 [IN](U) Sending msg 63814348 to IP address 'BLE'
D: 17093 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 140)
D: 17100 [SC]Sent PBKDF param response
D: 17171 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 17179 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 17186 [EM]>>> [E:47590r M:76027511] (U) Msg RX from 0:F7C620AF8D6897A3 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
D: 17197 [EM]Found matching exchange: 47590r, Delegate: 0x2000521c
D: 17203 [SC]Received spake2p msg1
I: 19080 [EM]<<< [E:47590r M:63814349] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
I: 19091 [IN](U) Sending msg 63814349 to IP address 'BLE'
D: 19096 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 132)
D: 19104 [SC]Sent spake2p msg2
E: 19107 [DL]Long dispatch time: 1928 ms, for event type 16388
D: 19267 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19275 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 19283 [EM]>>> [E:47590r M:76027512] (U) Msg RX from 0:F7C620AF8D6897A3 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
D: 19294 [EM]Found matching exchange: 47590r, Delegate: 0x2000521c
D: 19300 [SC]Received spake2p msg3
D: 19303 [SC]Sending status report. Protocol code 0, exchange 47590
I: 19309 [EM]<<< [E:47590r M:63814350] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
I: 19321 [IN](U) Sending msg 63814350 to IP address 'BLE'
D: 19326 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 35)
I: 19334 [SC]SecureSession[0x200030f0]: Moving from state 'kEstablishing' --> 'kActive'
D: 19342 [IN]SecureSession[0x200030f0]: Activated - Type:1 LSID:58142
D: 19348 [IN]New secure session activated for device <FFFFFFFB00000000, 0>, LSID:58142 PSID:64643!
I: 19357 [SVR]Commissioning completed session establishment step
I: 19363 [DIS]Updating services using commissioning mode 0
D: 19369 [DL]Using Thread extended MAC for hostname.
D: 19374 [DL]Using Thread extended MAC for hostname.
I: 19379 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=4004/15 cm=0
E: 19388 [DIS]Failed to advertise extended commissionable node: 3
D: 19394 [DIS]Scheduling extended discovery timeout in 900s
E: 19399 [DIS]Failed to finalize service update: 1c
D: 19404 [DL]CHIPoBLE advertising set to off
I: 19408 [SVR]Device completed Rendezvous process
E: 19413 [DL]Long dispatch time: 138 ms, for event type 16388
D: 19419 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19427 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 19435 [EM]>>> [E:47591r M:19450924] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
D: 19446 [EM]Handling via exchange: 47591r, Delegate: 0x2000f6cc
D: 19451 [IM]Received Read request
D: 19458 [DMG]IM RH moving to [GeneratingReports]
D: 19462 [DMG]Building Reports for ReadHandler with LastReportGeneration = 0 DirtyGeneration = 0
D: 19471 [DMG]<RE:Run> Cluster 31, Attribute 3 is dirty
D: 19476 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_0003 (expanded=1)
D: 19485 [DMG]<RE:Run> Cluster 28, Attribute 4 is dirty
D: 19490 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0004 (expanded=0)
D: 19499 [DMG]<RE:Run> Cluster 28, Attribute 2 is dirty
D: 19504 [DMG]Reading attribute: Cluster=0x0000_0028 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 19513 [DMG]<RE:Run> Cluster 30, Attribute 3 is dirty
D: 19518 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0003 (expanded=0)
D: 19527 [DMG]<RE:Run> Cluster 30, Attribute 2 is dirty
D: 19532 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0002 (expanded=0)
D: 19541 [DMG]<RE:Run> Cluster 30, Attribute 1 is dirty
D: 19546 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0001 (expanded=0)
D: 19555 [DMG]<RE:Run> Cluster 30, Attribute 0 is dirty
D: 19560 [DMG]Reading attribute: Cluster=0x0000_0030 Endpoint=0 AttributeId=0x0000_0000 (expanded=0)
D: 19569 [DMG]<RE:Run> Cluster 31, Attribute fffc is dirty
D: 19575 [DMG]Reading attribute: Cluster=0x0000_0031 Endpoint=0 AttributeId=0x0000_FFFC (expanded=1)
D: 19584 [DMG]<RE> Sending report (payload has 228 bytes)...
I: 19591 [EM]<<< [E:47591r M:172714638] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
I: 19601 [IN](S) Sending msg 172714638 on secure session with LSID: 58142
D: 19607 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 19615 [DMG]<RE> OnReportConfirm: NumReports = 0
D: 19620 [DMG]<RE> ReportsInFlight = 0 with readHandler 0, RE has no more messages
D: 19627 [DMG]IM RH moving to [AwaitingDestruction]
D: 19632 [DMG]All ReadHandler-s are clean, clear GlobalDirtySet
D: 19754 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19762 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 21)
D: 19949 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 19958 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 19966 [EM]>>> [E:47592r M:19450925] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 19977 [EM]Handling via exchange: 47592r, Delegate: 0x2000f6cc
D: 19983 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I: 19990 [FS]GeneralCommissioning: Received ArmFailSafe (60s)
D: 19996 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to cca4d572
D: 20003 [DMG]Command handler moving to [ Preparing]
D: 20008 [DMG]Command handler moving to [AddingComm]
D: 20012 [DMG]Command handler moving to [AddedComma]
D: 20017 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 20025 [EM]<<< [E:47592r M:172714639] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 20035 [IN](S) Sending msg 172714639 on secure session with LSID: 58142
D: 20042 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 20050 [DMG]Command handler moving to [CommandSen]
D: 20054 [DMG]Command handler moving to [AwaitingDe]
E: 20059 [DL]Long dispatch time: 101 ms, for event type 16388
D: 20144 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20243 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 20251 [EM]>>> [E:47593r M:19450926] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 20261 [EM]Handling via exchange: 47593r, Delegate: 0x2000f6cc
D: 20268 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0002
D: 20440 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to cca4d573
D: 20446 [DMG]Command handler moving to [ Preparing]
D: 20451 [DMG]Command handler moving to [AddingComm]
D: 20456 [DMG]Command handler moving to [AddedComma]
D: 20461 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 20468 [EM]<<< [E:47593r M:172714640] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 20479 [IN](S) Sending msg 172714640 on secure session with LSID: 58142
D: 20485 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 20493 [DMG]Command handler moving to [CommandSen]
D: 20498 [DMG]Command handler moving to [AwaitingDe]
E: 20502 [DL]Long dispatch time: 260 ms, for event type 16388
D: 20548 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20556 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 20564 [EM]>>> [E:47594r M:19450927] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 20575 [EM]Handling via exchange: 47594r, Delegate: 0x2000f6cc
D: 20582 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 20589 [ZCL]OpCreds: Certificate Chain request received for PAI
D: 20595 [DMG]Command handler moving to [ Preparing]
D: 20600 [DMG]Command handler moving to [AddingComm]
D: 20605 [DMG]Command handler moving to [AddedComma]
D: 20609 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 20619 [EM]<<< [E:47594r M:172714641] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 20630 [IN](S) Sending msg 172714641 on secure session with LSID: 58142
D: 20636 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 20644 [DMG]Command handler moving to [CommandSen]
D: 20649 [DMG]Command handler moving to [AwaitingDe]
D: 20773 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20781 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 20863 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20871 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 48)
D: 20953 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 20961 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 20969 [EM]>>> [E:47595r M:19450928] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 20980 [EM]Handling via exchange: 47595r, Delegate: 0x2000f6cc
D: 20987 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0002
I: 20994 [ZCL]OpCreds: Certificate Chain request received for DAC
D: 21000 [DMG]Command handler moving to [ Preparing]
D: 21005 [DMG]Command handler moving to [AddingComm]
D: 21010 [DMG]Command handler moving to [AddedComma]
D: 21015 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 21024 [EM]<<< [E:47595r M:172714642] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 21035 [IN](S) Sending msg 172714642 on secure session with LSID: 58142
D: 21041 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 21049 [DMG]Command handler moving to [CommandSen]
D: 21054 [DMG]Command handler moving to [AwaitingDe]
D: 21133 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21141 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 21268 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21276 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 76)
D: 21358 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21366 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 21375 [EM]>>> [E:47596r M:19450929] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 21385 [EM]Handling via exchange: 47596r, Delegate: 0x2000f6cc
D: 21392 [DMG]Received command for Endpoint=0 Cluster=0x0000_003E Command=0x0000_0000
I: 21399 [ZCL]OpCreds: Received an AttestationRequest command
I: 21435 [ZCL]OpCreds: AttestationRequest successful.
D: 21440 [DMG]Command handler moving to [ Preparing]
D: 21445 [DMG]Command handler moving to [AddingComm]
D: 21450 [DMG]Command handler moving to [AddedComma]
D: 21455 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 21465 [EM]<<< [E:47596r M:172714643] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 21476 [IN](S) Sending msg 172714643 on secure session with LSID: 58142
D: 21482 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 21490 [DMG]Command handler moving to [CommandSen]
D: 21495 [DMG]Command handler moving to [AwaitingDe]
E: 21500 [DL]Long dispatch time: 134 ms, for event type 16388
D: 21538 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21546 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 244)
D: 21763 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21771 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 236)
D: 21853 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
D: 21944 [DL]Write request received for CHIPoBLE RX characteristic (ConnId 0x00)
I: 21952 [EM]>>> [E:47597r M:19450930] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
D: 21963 [EM]Handling via exchange: 47597r, Delegate: 0x2000f6cc
D: 21970 [DMG]Received command for Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0000
I: 21977 [FS]GeneralCommissioning: Received ArmFailSafe (0s)
I: 21983 [FS]Fail-safe timer expired
D: 21986 [DMG]Command handler moving to [ Preparing]
D: 21991 [DMG]Command handler moving to [AddingComm]
D: 21995 [DMG]Command handler moving to [AddedComma]
D: 22000 [DMG]Decreasing reference count for CommandHandler, remaining 0
I: 22007 [EM]<<< [E:47597r M:172714644] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
I: 22018 [IN](S) Sending msg 172714644 on secure session with LSID: 58142
D: 22025 [DL]Sending indication for CHIPoBLE TX characteristic (ConnId 00, len 71)
D: 22033 [DMG]Command handler moving to [CommandSen]
D: 22038 [DMG]Command handler moving to [AwaitingDe]
E: 22042 [SVR]Failsafe timer expired
D: 22046 [IN]SecureSession[0x200030f0]: MarkForEviction Type:1 LSID:58142
I: 22052 [SC]SecureSession[0x200030f0]: Moving from state 'kActive' --> 'kPendingEviction'
D: 22060 [IN]SecureSession[0x200030f0]: Released - Type:1 LSID:58142
E: 22066 [SVR]Commissioning failed (attempt 1): 32
D: 22071 [IN]Clearing BLE pending packets.
I: 22075 [BLE]Releasing end point's BLE connection back to application.
I: 22081 [DL]Closing BLE GATT connection (ConnId 00)
D: 22089 [IN]SecureSession[0x200030f0]: Allocated Type:1 LSID:58143
D: 22095 [SC]Assigned local session key ID 58143
D: 22099 [SC]Waiting for PBKDF param request
D: 22103 [DL]CHIPoBLE advertising set to on
I: 22107 [DIS]Updating services using commissioning mode 1
D: 22112 [DL]Using Thread extended MAC for hostname.
D: 22117 [DL]Using Thread extended MAC for hostname.
I: 22123 [DIS]Advertise commission parameter vendorID=65521 productID=32774 discriminator=4004/15 cm=1
E: 22132 [DIS]Failed to advertise commissionable node: 3
E: 22137 [DIS]Failed to finalize service update: 1c
E: 22142 [ZCL]OpCreds: Got FailSafeTimerExpired
E: 22146 [ZCL]OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
I: 22153 [TS]Pending Last Known Good Time: 2022-11-02T14:54:43
I: 22159 [TS]Previous Last Known Good Time: 2022-11-02T14:54:43
I: 22165 [TS]Reverted Last Known Good Time to previous value
E: not connected!
D: 22173 [DMG]Endpoint 0, Cluster 0x0000_0030 update version to cca4d574
D: 22179 [ZCL]Failsafe timeout, tell platform driver to revert network credentials.
E: 22188 [DL]Long dispatch time: 145 ms, for event type 32782
I: 22193 [FS]Fail-safe cleanly disarmed
D: 22197 [DL]Indication for CHIPoBLE TX characteristic done (ConnId 0x00, result 0x00)
E: 22204 [BLE]no endpoint for BLE sent data ack
D: 22209 [DL]ConnId: 0x00, New CCCD value: 0x0000
E: 22213 [BLE]no endpoint for unsub recvd
I: 22528 [DL]BLE GAP connection terminated (reason 0x22)
I: 22533 [DL]Current number of connections: 0/1
I: 22540 [DL]CHIPoBLE advertising started
I: 22545 [DL]NFC Tag emulation started
I: 52544 [DL]CHIPoBLE advertising mode changed to slow
