Regarding commissioning a matter device

[Varun2103]

I'm getting the following error when I'm trying to commission my matter device using chip-tool downloaded from https://snapcraft.io/install/chip-tool/ubuntu, into the thread network formed by OTBR in docker.

"Failed in verifying 'Attestation Information' command received from the device: err 101. Look at AttestationVerificationResult enum to understand the errors".

Also OTBR and chip-tool are in linux x86 machine.

And I'm trying to commission Nanoleaf matter bulb.

Could anyone please help me to get rid of this error ?

[Varun2103]

Hey AHaug, Thanks for your help.

Can I ask you one more doubt ?

[AHaug]

Of course! : )

[Varun2103]

I'm trying to commission Tapo Mini Smart Wi-Fi Plug using chip-tool downloaded from https://github.com/nrfconnect/sdk-connectedhomeip/releases V2.4.0 chip-tool-linux_aarch64.zip , and my Linux machine is connected to local Wi-Fi.

The command I used is ./chip-tool-debug pairing code-wifi 0xA874 TP-Link_4722 77189462 MT:YZ7A00C-035AO14GV10

where TP-LINK_4722 is my Wi-Fi SSID, 77189462 is Password of my Wi-Fi and MT:YZ7A00C-035AO14GV10 is my smart plug payload

But I'm getting error as shown below

[1687270353.218157][18285:18285] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1687270353.218284][18285:18285] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1687270353.218312][18285:18285] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1687270353.218329][18285:18285] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1687270353.218415][18285:18285] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-HI4tsf)
[1687270353.218549][18285:18285] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1687270353.218559][18285:18285] CHIP:DL: NVS set: chip-counters/reboot-count = 9 (0x9)
[1687270353.218734][18285:18285] CHIP:DL: Got Ethernet interface: enp2s0
[1687270353.218840][18285:18285] CHIP:DL: Found the primary Ethernet interface:enp2s0
[1687270353.218933][18285:18285] CHIP:DL: Got WiFi interface: wlp3s0
[1687270353.219048][18285:18285] CHIP:DL: Found the primary WiFi interface:wlp3s0
[1687270353.219063][18285:18285] CHIP:IN: UDP::Init bind&listen port=0
[1687270353.219083][18285:18285] CHIP:IN: UDP::Init bound to port=51027
[1687270353.219087][18285:18285] CHIP:IN: UDP::Init bind&listen port=0
[1687270353.219101][18285:18285] CHIP:IN: UDP::Init bound to port=58610
[1687270353.219104][18285:18285] CHIP:IN: BLEBase::Init - setting/overriding transport
[1687270353.219107][18285:18285] CHIP:IN: TransportMgr initialized
[1687270353.219117][18285:18285] CHIP:FP: Initializing FabricTable from persistent storage
[1687270353.219161][18285:18285] CHIP:TS: Last Known Good Time: 2023-06-14T13:57:05
[1687270353.219268][18285:18285] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xBC18D1F1B58BDA4C, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1687270353.219652][18285:18285] CHIP:ZCL: Using ZAP configuration...
[1687270353.220892][18285:18285] CHIP:DL: Avahi client registered
[1687270353.221092][18285:18285] CHIP:CTL: System State Initialized...
[1687270353.221115][18285:18285] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687270353.221124][18285:18285] CHIP:CTL: Setting attestation nonce to random value
[1687270353.221128][18285:18285] CHIP:CTL: Setting CSR nonce to random value
[1687270353.221234][18285:18287] CHIP:DL: CHIP task running
[1687270353.221279][18285:18287] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1687270353.221350][18285:18287] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687270353.221357][18285:18287] CHIP:CTL: Setting attestation nonce to random value
[1687270353.221361][18285:18287] CHIP:CTL: Setting CSR nonce to random value
[1687270353.224120][18285:18287] CHIP:CTL: Generating NOC
[1687270353.227173][18285:18287] CHIP:FP: Validating NOC chain
[1687270353.238424][18285:18287] CHIP:FP: NOC chain validation successful
[1687270353.238435][18285:18287] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1687270353.238440][18285:18287] CHIP:TS: Last Known Good Time: 2023-06-14T13:57:05
[1687270353.238442][18285:18287] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1687270353.238444][18285:18287] CHIP:TS: Retaining current Last Known Good Time
[1687270353.239022][18285:18287] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1687270353.239322][18285:18287] CHIP:TS: Committing Last Known Good Time to storage: 2023-06-14T13:57:05
[1687270353.239622][18285:18287] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: BC18D1F1B58BDA4C)
[1687270353.241663][18285:18287] CHIP:CTL: Setting wifi credentials from parameters
[1687270353.241668][18285:18287] CHIP:CTL: Setting attestation nonce to random value
[1687270353.241673][18285:18287] CHIP:CTL: Setting CSR nonce to random value
[1687270353.241708][18285:18287] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687270353.241711][18285:18287] CHIP:CTL: Starting commissioning discovery over BLE
[1687270353.241719][18285:18287] CHIP:CTL: Starting commissioning discovery over DNS-SD
[1687270353.243006][18285:18286] CHIP:DL: TRACE: Bus acquired for name C-476d
[1687270353.244596][18285:18287] CHIP:DL: PlatformBlueZInit init success
[1687270353.245579][18285:18286] CHIP:BLE: BLE removing known devices.
[1687270353.245825][18285:18286] CHIP:BLE: BLE initiating scan.
[1687270353.362881][18285:18287] CHIP:DL: Long dispatch time: 121 ms, for event type 2
[1687270353.363042][18285:18287] CHIP:DL: Avahi browse: cache exhausted
[1687270353.377857][18285:18286] CHIP:BLE: Device 28:E6:38:3C:18:93 does not look like a CHIP device.
[1687270353.559761][18285:18286] CHIP:BLE: Device 7E:98:15:B0:D1:A8 does not look like a CHIP device.
[1687270353.561606][18285:18286] CHIP:BLE: Device 48:22:54:5F:2B:F3 does not look like a CHIP device.
[1687270354.245744][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270354.246605][18285:18286] CHIP:BLE: Device 09:23:E7:DB:26:0F does not look like a CHIP device.
[1687270354.253582][18285:18287] CHIP:DL: Avahi browse: all for now
[1687270354.601103][18285:18286] CHIP:BLE: Device 08:7C:85:05:34:4B does not look like a CHIP device.
[1687270354.766759][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270354.767085][18285:18286] CHIP:BLE: Device 09:23:E7:DB:26:0F does not look like a CHIP device.
[1687270355.492434][18285:18286] CHIP:BLE: Device 28:E6:38:3C:18:93 does not look like a CHIP device.
[1687270356.268395][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270359.929839][18285:18286] CHIP:BLE: Device D5:D0:B4:6C:40:03 does not look like a CHIP device.
[1687270360.034205][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270360.034383][18285:18286] CHIP:BLE: Device 09:23:E7:DB:26:0F does not look like a CHIP device.
[1687270363.368003][18285:18287] CHIP:BLE: BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout
[1687270363.485400][18285:18286] CHIP:BLE: Scan complete. No matching device found.
[1687270383.259484][18285:18287] CHIP:CTL: Discovery timed out
[1687270383.259514][18285:18287] CHIP:CTL: Stopping commissioning discovery over BLE
[1687270383.259519][18285:18287] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1687270383.259530][18285:18287] CHIP:-: src/platform/Linux/BLEManagerImpl.cpp:732: CHIP Error 0x0000002D: Not Implemented at src/controller/SetUpCodePairer.cpp:551
[1687270383.259535][18285:18287] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687270383.259543][18285:18287] CHIP:TOO: Secure Pairing Failed
[1687270383.259837][18285:18285] CHIP:CTL: Shutting down the commissioner
[1687270383.259862][18285:18285] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687270383.259870][18285:18285] CHIP:CTL: Shutting down the controller
[1687270383.259880][18285:18285] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1687270383.259888][18285:18285] CHIP:FP: Forgetting fabric 0x1
[1687270383.259903][18285:18285] CHIP:TS: Pending Last Known Good Time: 2023-06-14T13:57:05
[1687270383.260008][18285:18285] CHIP:TS: Previous Last Known Good Time: 2023-06-14T13:57:05
[1687270383.260019][18285:18285] CHIP:TS: Reverted Last Known Good Time to previous value
[1687270383.260037][18285:18285] CHIP:CTL: Shutting down the commissioner
[1687270383.260041][18285:18285] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687270383.260047][18285:18285] CHIP:CTL: Shutting down the controller
[1687270383.260052][18285:18285] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1687270383.260984][18285:18285] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1687270383.261035][18285:18285] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1687270383.261058][18285:18285] CHIP:FP: Shutting down FabricTable
[1687270383.261073][18285:18285] CHIP:TS: Pending Last Known Good Time: 2023-06-14T13:57:05
[1687270383.261166][18285:18285] CHIP:TS: Previous Last Known Good Time: 2023-06-14T13:57:05
[1687270383.261174][18285:18285] CHIP:TS: Reverted Last Known Good Time to previous value
[1687270383.261332][18285:18285] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-DBdfXb)
[1687270383.261752][18285:18285] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1687270383.261782][18285:18285] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1687270383.261790][18285:18285] CHIP:DL: Inet Layer shutdown
[1687270383.261794][18285:18285] CHIP:DL: BLE shutdown
[1687270383.262181][18285:18285] CHIP:DL: System Layer shutdown
[1687270383.262329][18285:18285] CHIP:TOO: Run command failure: examples/chip-tool/commands/pairing/PairingCommand.cpp:240: CHIP Error 0x00000003: Incorrect state

[AHaug]

Hi,

Based on the lines below it looks like your commissioner can not find any devices that are a Matter device while scanning for one. You should verify and check if the Matter device you want to commission actually is advertising

[1687270353.245825][18285:18286] CHIP:BLE: BLE initiating scan.
[1687270353.362881][18285:18287] CHIP:DL: Long dispatch time: 121 ms, for event type 2
[1687270353.363042][18285:18287] CHIP:DL: Avahi browse: cache exhausted
[1687270353.377857][18285:18286] CHIP:BLE: Device 28:E6:38:3C:18:93 does not look like a CHIP device.
[1687270353.559761][18285:18286] CHIP:BLE: Device 7E:98:15:B0:D1:A8 does not look like a CHIP device.
[1687270353.561606][18285:18286] CHIP:BLE: Device 48:22:54:5F:2B:F3 does not look like a CHIP device.
[1687270354.245744][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270354.246605][18285:18286] CHIP:BLE: Device 09:23:E7:DB:26:0F does not look like a CHIP device.
[1687270354.253582][18285:18287] CHIP:DL: Avahi browse: all for now
[1687270354.601103][18285:18286] CHIP:BLE: Device 08:7C:85:05:34:4B does not look like a CHIP device.
[1687270354.766759][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270354.767085][18285:18286] CHIP:BLE: Device 09:23:E7:DB:26:0F does not look like a CHIP device.
[1687270355.492434][18285:18286] CHIP:BLE: Device 28:E6:38:3C:18:93 does not look like a CHIP device.
[1687270356.268395][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270359.929839][18285:18286] CHIP:BLE: Device D5:D0:B4:6C:40:03 does not look like a CHIP device.
[1687270360.034205][18285:18286] CHIP:BLE: Device 24:FC:E5:99:C2:69 does not look like a CHIP device.
[1687270360.034383][18285:18286] CHIP:BLE: Device 09:23:E7:DB:26:0F does not look like a CHIP device.
[1687270363.368003][18285:18287] CHIP:BLE: BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:154: CHIP Error 0x00000032: Timeout
[1687270363.485400][18285:18286] CHIP:BLE: Scan complete. No matching device found.
[1687270383.259484][18285:18287] CHIP:CTL: Discovery timed out
[1687270383.259514][18285:18287] CHIP:CTL: Stopping commissioning discovery over BLE

Kind regards,
Andreas

[Varun2103]

Yeah it's advertising but now I'm getting error saying "Failed in verifying 'Attestation Information' command received from the device: err 101. Look at AttestationVerificationResult enum to understand the errors".

The output log of terminal is shown below

1687332180.797206][15779:15779] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /mnt/chip_kvs
[1687332180.798764][15779:15779] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /mnt/chip_factory.ini
[1687332180.798793][15779:15779] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /mnt/chip_config.ini
[1687332180.798805][15779:15779] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /mnt/chip_counters.ini
[1687332180.798998][15779:15779] CHIP:DL: writing settings to file (/mnt/chip_counters.ini-0SZGzF)
[1687332180.799323][15779:15779] CHIP:DL: renamed tmp file to file (/mnt/chip_counters.ini)
[1687332180.799330][15779:15779] CHIP:DL: NVS set: chip-counters/reboot-count = 41 (0x29)
[1687332180.799676][15779:15779] CHIP:DL: Got Ethernet interface: enp2s0
[1687332180.799807][15779:15779] CHIP:DL: Found the primary Ethernet interface:enp2s0
[1687332180.799909][15779:15779] CHIP:DL: Got WiFi interface: wlp3s0
[1687332180.800015][15779:15779] CHIP:DL: Found the primary WiFi interface:wlp3s0
[1687332180.800038][15779:15779] CHIP:IN: UDP::Init bind&listen port=0
[1687332180.800056][15779:15779] CHIP:IN: UDP::Init bound to port=46831
[1687332180.800060][15779:15779] CHIP:IN: UDP::Init bind&listen port=0
[1687332180.800073][15779:15779] CHIP:IN: UDP::Init bound to port=57258
[1687332180.800077][15779:15779] CHIP:IN: BLEBase::Init - setting/overriding transport
[1687332180.800080][15779:15779] CHIP:IN: TransportMgr initialized
[1687332180.800088][15779:15779] CHIP:FP: Initializing FabricTable from persistent storage
[1687332180.800123][15779:15779] CHIP:TS: Last Known Good Time: 2023-01-04T15:21:56
[1687332180.800483][15779:15779] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x8DA70BA28B057D3E, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1687332180.800753][15779:15779] CHIP:ZCL: Using ZAP configuration...
[1687332180.800971][15779:15779] CHIP:DL: MDNS failed to join multicast group on enp2s0 for address type IPv4: ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:764: Inet Error 0x00000110: Address not found
[1687332180.801288][15779:15779] CHIP:CTL: System State Initialized...
[1687332180.801301][15779:15779] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687332180.801316][15779:15779] CHIP:CTL: Setting attestation nonce to random value
[1687332180.801330][15779:15779] CHIP:CTL: Setting CSR nonce to random value
[1687332180.801342][15779:15779] CHIP:IN: UDP::Init bind&listen port=5550
[1687332180.801391][15779:15779] CHIP:IN: UDP::Init bound to port=5550
[1687332180.801395][15779:15779] CHIP:IN: UDP::Init bind&listen port=5550
[1687332180.801405][15779:15779] CHIP:IN: UDP::Init bound to port=5550
[1687332180.801408][15779:15779] CHIP:IN: TransportMgr initialized
[1687332180.801528][15779:15805] CHIP:DL: CHIP task running
[1687332180.801685][15779:15805] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687332180.801692][15779:15805] CHIP:CTL: Setting attestation nonce to random value
[1687332180.801710][15779:15805] CHIP:CTL: Setting CSR nonce to random value
[1687332180.801992][15779:15805] CHIP:CTL: Generating NOC
[1687332180.802256][15779:15805] CHIP:FP: Validating NOC chain
[1687332180.802694][15779:15805] CHIP:FP: NOC chain validation successful
[1687332180.802727][15779:15805] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1687332180.802731][15779:15805] CHIP:TS: Last Known Good Time: 2023-01-04T15:21:56
[1687332180.802735][15779:15805] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1687332180.802738][15779:15805] CHIP:TS: Retaining current Last Known Good Time
[1687332180.803039][15779:15805] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1687332180.803239][15779:15805] CHIP:TS: Committing Last Known Good Time to storage: 2023-01-04T15:21:56
[1687332180.803446][15779:15805] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 8DA70BA28B057D3E)
[1687332180.803454][15779:15805] CHIP:IN: UDP::Init bind&listen port=5550
[1687332180.803473][15779:15805] CHIP:IN: UDP::Init bound to port=5550
[1687332180.803476][15779:15805] CHIP:IN: UDP::Init bind&listen port=5550
[1687332180.803489][15779:15805] CHIP:IN: UDP::Init bound to port=5550
[1687332180.803492][15779:15805] CHIP:IN: TransportMgr initialized
[1687332180.804809][15779:15805] CHIP:CTL: Setting wifi credentials from parameters
[1687332180.804814][15779:15805] CHIP:CTL: Setting attestation nonce to random value
[1687332180.804821][15779:15805] CHIP:CTL: Setting CSR nonce to random value
[1687332180.804825][15779:15805] CHIP:CTL: Setting PASE-only commissioning from parameters
[1687332180.804847][15779:15805] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687332180.804850][15779:15805] CHIP:CTL: Starting commissioning discovery over BLE
[1687332180.804857][15779:15805] CHIP:CTL: Starting commissioning discovery over DNS-SD
[1687332180.804921][15779:15805] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp2s0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:411: OS Error 0x02000063: Cannot assign requested address
[1687332180.805021][15779:15805] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:411: OS Error 0x02000065: Network is unreachable
[1687332180.805026][15779:15805] CHIP:DIS: mDNS broadcast had only partial success: 4 successes and 2 failures.
[1687332180.806125][15779:15804] CHIP:DL: TRACE: Bus acquired for name C-3da3
[1687332180.807967][15779:15805] CHIP:DL: PlatformBlueZInit init success
[1687332180.809165][15779:15804] CHIP:BLE: BLE removing known devices.
[1687332180.809756][15779:15804] CHIP:BLE: BLE initiating scan.
[1687332180.929643][15779:15805] CHIP:DL: Long dispatch time: 124 ms, for event type 2
[1687332180.933627][15779:15804] CHIP:BLE: Device FD:43:F6:0B:17:56 does not look like a CHIP device.
[1687332180.939901][15779:15804] CHIP:BLE: Device 0F:30:69:85:1A:30 does not look like a CHIP device.
[1687332180.960228][15779:15804] CHIP:BLE: Device 90:38:0C:EE:5F:BA does not look like a CHIP device.
[1687332181.296349][15779:15804] CHIP:BLE: Device 28:DE:65:69:DA:69 does not look like a CHIP device.
[1687332181.296961][15779:15804] CHIP:BLE: Device 2B:E6:FE:EB:2E:75 does not look like a CHIP device.
[1687332181.297893][15779:15804] CHIP:BLE: Device 03:DB:05:38:1A:B8 does not look like a CHIP device.
[1687332181.298745][15779:15804] CHIP:BLE: New device scanned: 48:22:54:5F:2B:F3
[1687332181.298762][15779:15804] CHIP:BLE: Device discriminator match. Attempting to connect.
[1687332181.310504][15779:15804] CHIP:BLE: Scan complete notification without an active scan.
[1687332181.806871][15779:15805] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp2s0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:411: OS Error 0x02000063: Cannot assign requested address
[1687332181.807126][15779:15805] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:411: OS Error 0x02000065: Network is unreachable
[1687332181.807166][15779:15805] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 2 failures.
[1687332181.870917][15779:15804] CHIP:DL: ConnectDevice complete
[1687332182.694439][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687332182.694453][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694458][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687332182.694460][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694464][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687332182.694466][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694471][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0001
[1687332182.694474][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694477][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0001
[1687332182.694480][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694483][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0001
[1687332182.694486][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694491][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694494][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694498][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694500][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694508][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687332182.694511][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694515][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687332182.694517][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694521][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687332182.694524][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694532][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694536][15779:15804] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687332182.694542][15779:15804] CHIP:DL: New BLE connection 0x7f5948073de0, device 48:22:54:5F:2B:F3, path /org/bluez/hci0/dev_48_22_54_5F_2B_F3
[1687332182.694575][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1687332182.694583][15779:15805] CHIP:CTL: Discovered device to be commissioned over BLE
[1687332182.694592][15779:15805] CHIP:CTL: Attempting PASE connection to BLE
[1687332182.694603][15779:15805] CHIP:IN: BleConnectionComplete: endPoint 0x563852c5eb20
[1687332182.694646][15779:15805] CHIP:IN: SecureSession[0x7f594000ff10]: Allocated Type:1 LSID:19592
[1687332182.694651][15779:15805] CHIP:SC: Assigned local session key ID 19592
[1687332182.694672][15779:15805] CHIP:EM: <<< [E:64287i M:208376926] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[1687332182.694683][15779:15805] CHIP:IN: (U) Sending msg 208376926 to IP address 'BLE'
[1687332182.694689][15779:15805] CHIP:IN: Message appended to BLE send queue
[1687332182.694694][15779:15805] CHIP:SC: Sent PBKDF param request
[1687332182.694699][15779:15805] CHIP:CTL: Commission called for node ID 0x0000000000001548
[1687332183.504402][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332183.579966][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1687332183.579992][15779:15805] CHIP:BLE: subscribe complete, ep = 0x563852c5eb20
[1687332183.580017][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332183.580110][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332183.580128][15779:15805] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1687332183.580136][15779:15805] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1687332183.580142][15779:15805] CHIP:BLE: local and remote recv window size = 5
[1687332183.580188][15779:15805] CHIP:IN: BLE EndPoint 0x563852c5eb20 Connection Complete
[1687332183.669513][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332183.760194][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332183.760277][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332183.760351][15779:15805] CHIP:EM: >>> [E:64287i M:146526867] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
[1687332183.760366][15779:15805] CHIP:EM: Found matching exchange: 64287i, Delegate: 0x7f59400197d0
[1687332183.760384][15779:15805] CHIP:SC: Received PBKDF param response
[1687332183.760405][15779:15805] CHIP:SC: Peer assigned session ID 64722
[1687332183.760419][15779:15805] CHIP:SC: Found MRP parameters in the message
[1687332183.785073][15779:15805] CHIP:EM: <<< [E:64287i M:208376927] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
[1687332183.785092][15779:15805] CHIP:IN: (U) Sending msg 208376927 to IP address 'BLE'
[1687332183.785125][15779:15805] CHIP:SC: Sent spake2p msg1
[1687332183.806330][15779:15805] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on enp2s0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:411: OS Error 0x02000063: Cannot assign requested address
[1687332183.808861][15779:15805] CHIP:DIS: Warning: Attempt to mDNS broadcast failed on docker0:  ../examples/chip-tool/third_party/connectedhomeip/src/inet/UDPEndPointImplSockets.cpp:411: OS Error 0x02000065: Network is unreachable
[1687332183.808870][15779:15805] CHIP:DIS: mDNS broadcast had only partial success: 3 successes and 2 failures.
[1687332183.850412][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332184.795937][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332184.796032][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332184.796100][15779:15805] CHIP:EM: >>> [E:64287i M:146526868] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
[1687332184.796113][15779:15805] CHIP:EM: Found matching exchange: 64287i, Delegate: 0x7f59400197d0
[1687332184.796127][15779:15805] CHIP:SC: Received spake2p msg2
[1687332184.796876][15779:15805] CHIP:EM: <<< [E:64287i M:208376928] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
[1687332184.796895][15779:15805] CHIP:IN: (U) Sending msg 208376928 to IP address 'BLE'
[1687332184.796930][15779:15805] CHIP:SC: Sent spake2p msg3
[1687332184.885511][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332184.930866][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332184.931002][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332184.931097][15779:15805] CHIP:EM: >>> [E:64287i M:146526869] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1687332184.931117][15779:15805] CHIP:EM: Found matching exchange: 64287i, Delegate: 0x7f59400197d0
[1687332184.931230][15779:15805] CHIP:SC: SecureSession[0x7f594000ff10]: Moving from state 'kEstablishing' --> 'kActive'
[1687332184.931240][15779:15805] CHIP:IN: SecureSession[0x7f594000ff10]: Activated - Type:1 LSID:19592
[1687332184.931244][15779:15805] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:19592 PSID:64722!
[1687332184.931253][15779:15805] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1687332184.931261][15779:15805] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687332184.931266][15779:15805] CHIP:TOO: Pairing Success
[1687332184.931270][15779:15805] CHIP:TOO: PASE establishment successful
[1687332184.931276][15779:15805] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
[1687332184.931284][15779:15805] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'
[1687332184.931290][15779:15805] CHIP:CTL: Sending request for commissioning information
[1687332184.931310][15779:15805] CHIP:DMG: SendReadRequest ReadClient[0x7f594001b4c0]: Sending Read Request
[1687332184.931391][15779:15805] CHIP:EM: <<< [E:64288i M:43174472] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
[1687332184.931410][15779:15805] CHIP:IN: (S) Sending msg 43174472 on secure session with LSID: 19592
[1687332184.931460][15779:15805] CHIP:DMG: MoveToState ReadClient[0x7f594001b4c0]: Moving to [AwaitingIn]
[1687332185.020497][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332185.156144][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332185.156288][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332185.246137][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332185.246235][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332185.246335][15779:15805] CHIP:EM: >>> [E:64288i M:188327128] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
[1687332185.246350][15779:15805] CHIP:EM: Found matching exchange: 64288i, Delegate: 0x7f594001b4d0
[1687332185.246404][15779:15805] CHIP:DMG: ReportDataMessage =
[1687332185.246413][15779:15805] CHIP:DMG: {
[1687332185.246421][15779:15805] CHIP:DMG:     AttributeReportIBs =
[1687332185.246436][15779:15805] CHIP:DMG:     [
[1687332185.246443][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.246459][15779:15805] CHIP:DMG:         {
[1687332185.246466][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.246478][15779:15805] CHIP:DMG:             {
[1687332185.246488][15779:15805] CHIP:DMG:                 DataVersion = 0x4ff6d6f2,
[1687332185.246497][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.246510][15779:15805] CHIP:DMG:                 {
[1687332185.246522][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.246531][15779:15805] CHIP:DMG:                     Cluster = 0x31,
[1687332185.246542][15779:15805] CHIP:DMG:                     Attribute = 0x0000_0003,
[1687332185.246556][15779:15805] CHIP:DMG:                 }
[1687332185.246570][15779:15805] CHIP:DMG:                     
[1687332185.246582][15779:15805] CHIP:DMG:                 Data = 20,
[1687332185.246594][15779:15805] CHIP:DMG:             },
[1687332185.246608][15779:15805] CHIP:DMG:             
[1687332185.246616][15779:15805] CHIP:DMG:         },
[1687332185.246635][15779:15805] CHIP:DMG:         
[1687332185.246644][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.246657][15779:15805] CHIP:DMG:         {
[1687332185.246664][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.246675][15779:15805] CHIP:DMG:             {
[1687332185.246685][15779:15805] CHIP:DMG:                 DataVersion = 0x6b40079a,
[1687332185.246698][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.246710][15779:15805] CHIP:DMG:                 {
[1687332185.246718][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.246731][15779:15805] CHIP:DMG:                     Cluster = 0x28,
[1687332185.246743][15779:15805] CHIP:DMG:                     Attribute = 0x0000_0004,
[1687332185.246756][15779:15805] CHIP:DMG:                 }
[1687332185.246769][15779:15805] CHIP:DMG:                     
[1687332185.246780][15779:15805] CHIP:DMG:                 Data = 257,
[1687332185.246790][15779:15805] CHIP:DMG:             },
[1687332185.246805][15779:15805] CHIP:DMG:             
[1687332185.246811][15779:15805] CHIP:DMG:         },
[1687332185.246823][15779:15805] CHIP:DMG:         
[1687332185.246828][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.246843][15779:15805] CHIP:DMG:         {
[1687332185.246852][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.246862][15779:15805] CHIP:DMG:             {
[1687332185.246872][15779:15805] CHIP:DMG:                 DataVersion = 0x6b40079a,
[1687332185.246882][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.246892][15779:15805] CHIP:DMG:                 {
[1687332185.246903][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.246914][15779:15805] CHIP:DMG:                     Cluster = 0x28,
[1687332185.246925][15779:15805] CHIP:DMG:                     Attribute = 0x0000_0002,
[1687332185.246935][15779:15805] CHIP:DMG:                 }
[1687332185.246948][15779:15805] CHIP:DMG:                     
[1687332185.246959][15779:15805] CHIP:DMG:                 Data = 4488,
[1687332185.246968][15779:15805] CHIP:DMG:             },
[1687332185.246980][15779:15805] CHIP:DMG:             
[1687332185.246989][15779:15805] CHIP:DMG:         },
[1687332185.247006][15779:15805] CHIP:DMG:         
[1687332185.247012][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.247027][15779:15805] CHIP:DMG:         {
[1687332185.247033][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.247040][15779:15805] CHIP:DMG:             {
[1687332185.247055][15779:15805] CHIP:DMG:                 DataVersion = 0x80e5156d,
[1687332185.247064][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.247070][15779:15805] CHIP:DMG:                 {
[1687332185.247076][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.247082][15779:15805] CHIP:DMG:                     Cluster = 0x30,
[1687332185.247087][15779:15805] CHIP:DMG:                     Attribute = 0x0000_0003,
[1687332185.247092][15779:15805] CHIP:DMG:                 }
[1687332185.247101][15779:15805] CHIP:DMG:                     
[1687332185.247113][15779:15805] CHIP:DMG:                 Data = 0,
[1687332185.247123][15779:15805] CHIP:DMG:             },
[1687332185.247136][15779:15805] CHIP:DMG:             
[1687332185.247145][15779:15805] CHIP:DMG:         },
[1687332185.247157][15779:15805] CHIP:DMG:         
[1687332185.247163][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.247179][15779:15805] CHIP:DMG:         {
[1687332185.247188][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.247201][15779:15805] CHIP:DMG:             {
[1687332185.247209][15779:15805] CHIP:DMG:                 DataVersion = 0x80e5156d,
[1687332185.247218][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.247225][15779:15805] CHIP:DMG:                 {
[1687332185.247232][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.247245][15779:15805] CHIP:DMG:                     Cluster = 0x30,
[1687332185.247260][15779:15805] CHIP:DMG:                     Attribute = 0x0000_0002,
[1687332185.247269][15779:15805] CHIP:DMG:                 }
[1687332185.247281][15779:15805] CHIP:DMG:                     
[1687332185.247292][15779:15805] CHIP:DMG:                 Data = 0,
[1687332185.247302][15779:15805] CHIP:DMG:             },
[1687332185.247310][15779:15805] CHIP:DMG:             
[1687332185.247319][15779:15805] CHIP:DMG:         },
[1687332185.247338][15779:15805] CHIP:DMG:         
[1687332185.247344][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.247361][15779:15805] CHIP:DMG:         {
[1687332185.247369][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.247380][15779:15805] CHIP:DMG:             {
[1687332185.247391][15779:15805] CHIP:DMG:                 DataVersion = 0x80e5156d,
[1687332185.247401][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.247412][15779:15805] CHIP:DMG:                 {
[1687332185.247423][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.247439][15779:15805] CHIP:DMG:                     Cluster = 0x30,
[1687332185.247448][15779:15805] CHIP:DMG:                     Attribute = 0x0000_0001,
[1687332185.247458][15779:15805] CHIP:DMG:                 }
[1687332185.247475][15779:15805] CHIP:DMG:                     
[1687332185.247486][15779:15805] CHIP:DMG:                 Data =
[1687332185.247497][15779:15805] CHIP:DMG:                 {
[1687332185.247509][15779:15805] CHIP:DMG:                     0x0 = 60,
[1687332185.247519][15779:15805] CHIP:DMG:                     0x1 = 900,
[1687332185.247530][15779:15805] CHIP:DMG:                 },
[1687332185.247540][15779:15805] CHIP:DMG:             },
[1687332185.247554][15779:15805] CHIP:DMG:             
[1687332185.247563][15779:15805] CHIP:DMG:         },
[1687332185.247579][15779:15805] CHIP:DMG:         
[1687332185.247585][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.247602][15779:15805] CHIP:DMG:         {
[1687332185.247611][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.247622][15779:15805] CHIP:DMG:             {
[1687332185.247631][15779:15805] CHIP:DMG:                 DataVersion = 0x80e5156d,
[1687332185.247641][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.247650][15779:15805] CHIP:DMG:                 {
[1687332185.247661][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.247668][15779:15805] CHIP:DMG:                     Cluster = 0x30,
[1687332185.247680][15779:15805] CHIP:DMG:                     Attribute = 0x0000_0000,
[1687332185.247690][15779:15805] CHIP:DMG:                 }
[1687332185.247702][15779:15805] CHIP:DMG:                     
[1687332185.247712][15779:15805] CHIP:DMG:                 Data = 0,
[1687332185.247721][15779:15805] CHIP:DMG:             },
[1687332185.247734][15779:15805] CHIP:DMG:             
[1687332185.247742][15779:15805] CHIP:DMG:         },
[1687332185.247758][15779:15805] CHIP:DMG:         
[1687332185.247769][15779:15805] CHIP:DMG:         AttributeReportIB =
[1687332185.247781][15779:15805] CHIP:DMG:         {
[1687332185.247787][15779:15805] CHIP:DMG:             AttributeDataIB =
[1687332185.247798][15779:15805] CHIP:DMG:             {
[1687332185.247806][15779:15805] CHIP:DMG:                 DataVersion = 0x4ff6d6f2,
[1687332185.247816][15779:15805] CHIP:DMG:                 AttributePathIB =
[1687332185.247827][15779:15805] CHIP:DMG:                 {
[1687332185.247837][15779:15805] CHIP:DMG:                     Endpoint = 0x0,
[1687332185.247848][15779:15805] CHIP:DMG:                     Cluster = 0x31,
[1687332185.247858][15779:15805] CHIP:DMG:                     Attribute = 0x0000_FFFC,
[1687332185.247867][15779:15805] CHIP:DMG:                 }
[1687332185.247879][15779:15805] CHIP:DMG:                     
[1687332185.247887][15779:15805] CHIP:DMG:                 Data = 1,
[1687332185.247893][15779:15805] CHIP:DMG:             },
[1687332185.247903][15779:15805] CHIP:DMG:             
[1687332185.247911][15779:15805] CHIP:DMG:         },
[1687332185.247926][15779:15805] CHIP:DMG:         
[1687332185.247935][15779:15805] CHIP:DMG:     ],
[1687332185.247970][15779:15805] CHIP:DMG:     
[1687332185.247980][15779:15805] CHIP:DMG:     SuppressResponse = true,
[1687332185.247990][15779:15805] CHIP:DMG:     InteractionModelRevision = 1
[1687332185.247998][15779:15805] CHIP:DMG: }
[1687332185.248423][15779:15805] CHIP:CTL: ----- NetworkCommissioning Features: has WiFi. endpointid = 0
[1687332185.248462][15779:15805] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'
[1687332185.248473][15779:15805] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
[1687332185.248486][15779:15805] CHIP:CTL: Performing next commissioning step 'ArmFailSafe'
[1687332185.248495][15779:15805] CHIP:CTL: Arming failsafe (60 seconds)
[1687332185.248528][15779:15805] CHIP:DMG: ICR moving to [AddingComm]
[1687332185.248542][15779:15805] CHIP:DMG: ICR moving to [AddedComma]
[1687332185.248588][15779:15805] CHIP:EM: <<< [E:64289i M:43174473] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687332185.248601][15779:15805] CHIP:IN: (S) Sending msg 43174473 on secure session with LSID: 19592
[1687332185.248637][15779:15805] CHIP:DMG: ICR moving to [CommandSen]
[1687332185.335805][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332185.336694][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332185.336785][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332185.336893][15779:15805] CHIP:EM: >>> [E:64289i M:188327129] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687332185.336909][15779:15805] CHIP:EM: Found matching exchange: 64289i, Delegate: 0x7f59480472a8
[1687332185.336927][15779:15805] CHIP:DMG: ICR moving to [ResponseRe]
[1687332185.336961][15779:15805] CHIP:DMG: InvokeResponseMessage =
[1687332185.336973][15779:15805] CHIP:DMG: {
[1687332185.337001][15779:15805] CHIP:DMG:     suppressResponse = false,
[1687332185.337011][15779:15805] CHIP:DMG:     InvokeResponseIBs =
[1687332185.337274][15779:15805] CHIP:DMG:     [
[1687332185.337285][15779:15805] CHIP:DMG:         InvokeResponseIB =
[1687332185.337296][15779:15805] CHIP:DMG:         {
[1687332185.337303][15779:15805] CHIP:DMG:             CommandDataIB =
[1687332185.337314][15779:15805] CHIP:DMG:             {
[1687332185.337323][15779:15805] CHIP:DMG:                 CommandPathIB =
[1687332185.337336][15779:15805] CHIP:DMG:                 {
[1687332185.337347][15779:15805] CHIP:DMG:                     EndpointId = 0x0,
[1687332185.337465][15779:15805] CHIP:DMG:                     ClusterId = 0x30,
[1687332185.337478][15779:15805] CHIP:DMG:                     CommandId = 0x1,
[1687332185.337488][15779:15805] CHIP:DMG:                 },
[1687332185.337501][15779:15805] CHIP:DMG:                 
[1687332185.337513][15779:15805] CHIP:DMG:                 CommandFields =
[1687332185.337523][15779:15805] CHIP:DMG:                 {
[1687332185.337536][15779:15805] CHIP:DMG:                     0x0 = 0,
[1687332185.337548][15779:15805] CHIP:DMG:                     0x1 = "" (0 chars),
[1687332185.337561][15779:15805] CHIP:DMG:                 },
[1687332185.337570][15779:15805] CHIP:DMG:             },
[1687332185.337584][15779:15805] CHIP:DMG:             
[1687332185.337593][15779:15805] CHIP:DMG:         },
[1687332185.337609][15779:15805] CHIP:DMG:         
[1687332185.337617][15779:15805] CHIP:DMG:     ],
[1687332185.337633][15779:15805] CHIP:DMG:     
[1687332185.337642][15779:15805] CHIP:DMG:     InteractionModelRevision = 1
[1687332185.337652][15779:15805] CHIP:DMG: },
[1687332185.337695][15779:15805] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1687332185.337729][15779:15805] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1687332185.337744][15779:15805] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe'
[1687332185.337753][15779:15805] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
[1687332185.337765][15779:15805] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory'
[1687332185.337773][15779:15805] CHIP:CTL: Setting Regulatory Config
[1687332185.337781][15779:15805] CHIP:CTL: Device does not support configurable regulatory location
[1687332185.337816][15779:15805] CHIP:DMG: ICR moving to [AddingComm]
[1687332185.337831][15779:15805] CHIP:DMG: ICR moving to [AddedComma]
[1687332185.337884][15779:15805] CHIP:EM: <<< [E:64290i M:43174474] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687332185.337901][15779:15805] CHIP:IN: (S) Sending msg 43174474 on secure session with LSID: 19592
[1687332185.337945][15779:15805] CHIP:DMG: ICR moving to [CommandSen]
[1687332185.337981][15779:15805] CHIP:DMG: ICR moving to [AwaitingDe]
[1687332185.470705][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332185.516375][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332185.516487][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332185.516603][15779:15805] CHIP:EM: >>> [E:64290i M:188327130] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687332185.516618][15779:15805] CHIP:EM: Found matching exchange: 64290i, Delegate: 0x7f594000a4c8
[1687332185.516631][15779:15805] CHIP:DMG: ICR moving to [ResponseRe]
[1687332185.516654][15779:15805] CHIP:DMG: InvokeResponseMessage =
[1687332185.516662][15779:15805] CHIP:DMG: {
[1687332185.516672][15779:15805] CHIP:DMG:     suppressResponse = false,
[1687332185.516679][15779:15805] CHIP:DMG:     InvokeResponseIBs =
[1687332185.516690][15779:15805] CHIP:DMG:     [
[1687332185.516696][15779:15805] CHIP:DMG:         InvokeResponseIB =
[1687332185.516708][15779:15805] CHIP:DMG:         {
[1687332185.516713][15779:15805] CHIP:DMG:             CommandDataIB =
[1687332185.516725][15779:15805] CHIP:DMG:             {
[1687332185.516731][15779:15805] CHIP:DMG:                 CommandPathIB =
[1687332185.516741][15779:15805] CHIP:DMG:                 {
[1687332185.516749][15779:15805] CHIP:DMG:                     EndpointId = 0x0,
[1687332185.516766][15779:15805] CHIP:DMG:                     ClusterId = 0x30,
[1687332185.516774][15779:15805] CHIP:DMG:                     CommandId = 0x3,
[1687332185.516780][15779:15805] CHIP:DMG:                 },
[1687332185.516789][15779:15805] CHIP:DMG:                 
[1687332185.516796][15779:15805] CHIP:DMG:                 CommandFields =
[1687332185.516805][15779:15805] CHIP:DMG:                 {
[1687332185.516817][15779:15805] CHIP:DMG:                     0x0 = 0,
[1687332185.516826][15779:15805] CHIP:DMG:                     0x1 = "" (0 chars),
[1687332185.516834][15779:15805] CHIP:DMG:                 },
[1687332185.516841][15779:15805] CHIP:DMG:             },
[1687332185.516850][15779:15805] CHIP:DMG:             
[1687332185.516856][15779:15805] CHIP:DMG:         },
[1687332185.516867][15779:15805] CHIP:DMG:         
[1687332185.516872][15779:15805] CHIP:DMG:     ],
[1687332185.516883][15779:15805] CHIP:DMG:     
[1687332185.516890][15779:15805] CHIP:DMG:     InteractionModelRevision = 1
[1687332185.516895][15779:15805] CHIP:DMG: },
[1687332185.516921][15779:15805] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
[1687332185.516936][15779:15805] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0
[1687332185.516947][15779:15805] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory'
[1687332185.516954][15779:15805] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
[1687332185.516964][15779:15805] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest'
[1687332185.516969][15779:15805] CHIP:CTL: Sending request for PAI certificate
[1687332185.516974][15779:15805] CHIP:CTL: Sending Certificate Chain request to 0x7f5940019780 device
[1687332185.517014][15779:15805] CHIP:DMG: ICR moving to [AddingComm]
[1687332185.517037][15779:15805] CHIP:DMG: ICR moving to [AddedComma]
[1687332185.517075][15779:15805] CHIP:EM: <<< [E:64291i M:43174475] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687332185.517088][15779:15805] CHIP:IN: (S) Sending msg 43174475 on secure session with LSID: 19592
[1687332185.517127][15779:15805] CHIP:DMG: ICR moving to [CommandSen]
[1687332185.517151][15779:15805] CHIP:DMG: ICR moving to [AwaitingDe]
[1687332185.605674][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332185.741136][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332185.741249][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332185.921282][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332185.921402][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332186.011258][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332186.011405][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332186.011498][15779:15805] CHIP:EM: >>> [E:64291i M:188327131] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687332186.011513][15779:15805] CHIP:EM: Found matching exchange: 64291i, Delegate: 0x7f59480472a8
[1687332186.011531][15779:15805] CHIP:DMG: ICR moving to [ResponseRe]
[1687332186.011556][15779:15805] CHIP:DMG: InvokeResponseMessage =
[1687332186.011563][15779:15805] CHIP:DMG: {
[1687332186.011571][15779:15805] CHIP:DMG:     suppressResponse = false,
[1687332186.011578][15779:15805] CHIP:DMG:     InvokeResponseIBs =
[1687332186.011590][15779:15805] CHIP:DMG:     [
[1687332186.011596][15779:15805] CHIP:DMG:         InvokeResponseIB =
[1687332186.011613][15779:15805] CHIP:DMG:         {
[1687332186.011624][15779:15805] CHIP:DMG:             CommandDataIB =
[1687332186.011634][15779:15805] CHIP:DMG:             {
[1687332186.011646][15779:15805] CHIP:DMG:                 CommandPathIB =
[1687332186.011653][15779:15805] CHIP:DMG:                 {
[1687332186.011660][15779:15805] CHIP:DMG:                     EndpointId = 0x0,
[1687332186.011669][15779:15805] CHIP:DMG:                     ClusterId = 0x3e,
[1687332186.011682][15779:15805] CHIP:DMG:                     CommandId = 0x3,
[1687332186.011691][15779:15805] CHIP:DMG:                 },
[1687332186.011729][15779:15805] CHIP:DMG:                 
[1687332186.011739][15779:15805] CHIP:DMG:                 CommandFields =
[1687332186.011751][15779:15805] CHIP:DMG:                 {
[1687332186.011772][15779:15805] CHIP:DMG:                     0x0 = [
[1687332186.011847][15779:15805] CHIP:DMG:                             0x30, 0x82, 0x01, 0xda, 0x30, 0x82, 0x01, 0x80, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x4a, 0x55, 0x95, 0xca, 0xad, 0x8e, 0xcb, 0xd9, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x33, 0x31, 0x1b, 0x30, 0x19, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x12, 0x54, 0x50, 0x2d, 0x4c, 0x69, 0x6e, 0x6b, 0x20, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x31, 0x38, 0x38, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x31, 0x31, 0x30, 0x33, 0x31, 0x34, 0x32, 0x33, 0x34, 0x33, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x49, 0x31, 0x1b, 0x30, 0x19, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x12, 0x54, 0x50, 0x2d, 0x4c, 0x69, 0x6e, 0x6b, 0x20, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x50, 0x41, 0x49, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x31, 0x38, 0x38, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x30, 0x31, 0x30, 0x31, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x8e, 0x78, 0x82, 0x5a, 0x5a, 0xa7, 0xc4, 0xc8, 0x9e, 0xd6, 0xa8, 0x78, 0x08, 0x67, 0x32, 0x2e, 0x6a, 0xbb, 0xaa, 0x01, 0x1a, 0xee, 0xa4, 0xec, 0x26, 0xdb, 0x64, 0xd4, 0x47, 0xbe, 0xc7, 0xc3, 0x16, 0x7d, 0xb4, 0x19, 0x8a, 0x21, 0x15, 0x65, 0x7f, 0x63, 0x32, 0xc5, 0x38, 0x15, 0xc2, 0xbd, 0x8f, 0xa2, 0x52, 0x9d, 0x9e, 0xa0, 0xf8, 0xad, 0xb1, 0x42, 0xa2, 0x
[1687332186.011893][15779:15805] CHIP:DMG:                     ] (478 bytes)
[1687332186.011905][15779:15805] CHIP:DMG:                 },
[1687332186.011913][15779:15805] CHIP:DMG:             },
[1687332186.011923][15779:15805] CHIP:DMG:             
[1687332186.011936][15779:15805] CHIP:DMG:         },
[1687332186.011952][15779:15805] CHIP:DMG:         
[1687332186.011960][15779:15805] CHIP:DMG:     ],
[1687332186.011975][15779:15805] CHIP:DMG:     
[1687332186.011984][15779:15805] CHIP:DMG:     InteractionModelRevision = 1
[1687332186.011993][15779:15805] CHIP:DMG: },
[1687332186.012030][15779:15805] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1687332186.012045][15779:15805] CHIP:CTL: Received certificate chain from the device
[1687332186.012058][15779:15805] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest'
[1687332186.012071][15779:15805] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
[1687332186.012086][15779:15805] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest'
[1687332186.012095][15779:15805] CHIP:CTL: Sending request for DAC certificate
[1687332186.012101][15779:15805] CHIP:CTL: Sending Certificate Chain request to 0x7f5940019780 device
[1687332186.012133][15779:15805] CHIP:DMG: ICR moving to [AddingComm]
[1687332186.012146][15779:15805] CHIP:DMG: ICR moving to [AddedComma]
[1687332186.012196][15779:15805] CHIP:EM: <<< [E:64292i M:43174476] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687332186.012213][15779:15805] CHIP:IN: (S) Sending msg 43174476 on secure session with LSID: 19592
[1687332186.012260][15779:15805] CHIP:DMG: ICR moving to [CommandSen]
[1687332186.012286][15779:15805] CHIP:DMG: ICR moving to [AwaitingDe]
[1687332186.100647][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332186.236070][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332186.236203][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332186.461155][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332186.461288][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332186.551731][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332186.551898][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332186.552000][15779:15805] CHIP:EM: >>> [E:64292i M:188327132] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687332186.552017][15779:15805] CHIP:EM: Found matching exchange: 64292i, Delegate: 0x7f59480058a8
[1687332186.552038][15779:15805] CHIP:DMG: ICR moving to [ResponseRe]
[1687332186.552079][15779:15805] CHIP:DMG: InvokeResponseMessage =
[1687332186.552088][15779:15805] CHIP:DMG: {
[1687332186.552097][15779:15805] CHIP:DMG:     suppressResponse = false,
[1687332186.552106][15779:15805] CHIP:DMG:     InvokeResponseIBs =
[1687332186.552121][15779:15805] CHIP:DMG:     [
[1687332186.552131][15779:15805] CHIP:DMG:         InvokeResponseIB =
[1687332186.552145][15779:15805] CHIP:DMG:         {
[1687332186.552152][15779:15805] CHIP:DMG:             CommandDataIB =
[1687332186.552161][15779:15805] CHIP:DMG:             {
[1687332186.552170][15779:15805] CHIP:DMG:                 CommandPathIB =
[1687332186.552183][15779:15805] CHIP:DMG:                 {
[1687332186.552194][15779:15805] CHIP:DMG:                     EndpointId = 0x0,
[1687332186.552206][15779:15805] CHIP:DMG:                     ClusterId = 0x3e,
[1687332186.552217][15779:15805] CHIP:DMG:                     CommandId = 0x3,
[1687332186.552228][15779:15805] CHIP:DMG:                 },
[1687332186.552241][15779:15805] CHIP:DMG:                 
[1687332186.552248][15779:15805] CHIP:DMG:                 CommandFields =
[1687332186.552259][15779:15805] CHIP:DMG:                 {
[1687332186.552272][15779:15805] CHIP:DMG:                     0x0 = [
[1687332186.552345][15779:15805] CHIP:DMG:                             0x30, 0x82, 0x01, 0xeb, 0x30, 0x82, 0x01, 0x90, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x50, 0x04, 0xca, 0x35, 0x9a, 0x9e, 0x85, 0x27, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x49, 0x31, 0x1b, 0x30, 0x19, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x12, 0x54, 0x50, 0x2d, 0x4c, 0x69, 0x6e, 0x6b, 0x20, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x50, 0x41, 0x49, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x31, 0x38, 0x38, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x30, 0x31, 0x30, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x31, 0x31, 0x30, 0x33, 0x31, 0x34, 0x32, 0x33, 0x34, 0x33, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x49, 0x31, 0x1b, 0x30, 0x19, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x12, 0x54, 0x50, 0x2d, 0x4c, 0x69, 0x6e, 0x6b, 0x20, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x41, 0x43, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x31, 0x38, 0x38, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x30, 0x31, 0x30, 0x31, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x0c, 0x1d, 0xae, 0x80, 0x17, 0x17, 0xd1, 0x2f, 0xe3, 0xa6, 0x08, 0x50, 0xa2, 0x8b, 0x21, 0x03, 0xf6, 0xc2, 0x15, 0x6f, 0xe8, 0x9c, 0xa1, 0x9b, 0x59, 0xff, 0xf2, 0x2e, 0x42, 0xca, 0x25, 0x30, 0xe3, 0x10, 0xab, 0x72, 0x00, 0x
[1687332186.552375][15779:15805] CHIP:DMG:                     ] (495 bytes)
[1687332186.552389][15779:15805] CHIP:DMG:                 },
[1687332186.552406][15779:15805] CHIP:DMG:             },
[1687332186.552420][15779:15805] CHIP:DMG:             
[1687332186.552429][15779:15805] CHIP:DMG:         },
[1687332186.552441][15779:15805] CHIP:DMG:         
[1687332186.552450][15779:15805] CHIP:DMG:     ],
[1687332186.552466][15779:15805] CHIP:DMG:     
[1687332186.552474][15779:15805] CHIP:DMG:     InteractionModelRevision = 1
[1687332186.552486][15779:15805] CHIP:DMG: },
[1687332186.552526][15779:15805] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1687332186.552543][15779:15805] CHIP:CTL: Received certificate chain from the device
[1687332186.552558][15779:15805] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest'
[1687332186.552568][15779:15805] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
[1687332186.552581][15779:15805] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest'
[1687332186.552590][15779:15805] CHIP:CTL: Sending Attestation Request to the device.
[1687332186.552598][15779:15805] CHIP:CTL: Sending Attestation request to 0x7f5940019780 device
[1687332186.552628][15779:15805] CHIP:DMG: ICR moving to [AddingComm]
[1687332186.552639][15779:15805] CHIP:DMG: ICR moving to [AddedComma]
[1687332186.552680][15779:15805] CHIP:EM: <<< [E:64293i M:43174477] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687332186.552693][15779:15805] CHIP:IN: (S) Sending msg 43174477 on secure session with LSID: 19592
[1687332186.552732][15779:15805] CHIP:DMG: ICR moving to [CommandSen]
[1687332186.552742][15779:15805] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information
[1687332186.552763][15779:15805] CHIP:DMG: ICR moving to [AwaitingDe]
[1687332186.640430][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332186.911166][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332186.911258][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332187.046112][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332187.046244][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332187.046333][15779:15805] CHIP:EM: >>> [E:64293i M:188327133] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687332187.046348][15779:15805] CHIP:EM: Found matching exchange: 64293i, Delegate: 0x7f5948040458
[1687332187.046362][15779:15805] CHIP:DMG: ICR moving to [ResponseRe]
[1687332187.046393][15779:15805] CHIP:DMG: InvokeResponseMessage =
[1687332187.046399][15779:15805] CHIP:DMG: {
[1687332187.046404][15779:15805] CHIP:DMG:     suppressResponse = false,
[1687332187.046409][15779:15805] CHIP:DMG:     InvokeResponseIBs =
[1687332187.046419][15779:15805] CHIP:DMG:     [
[1687332187.046423][15779:15805] CHIP:DMG:         InvokeResponseIB =
[1687332187.046433][15779:15805] CHIP:DMG:         {
[1687332187.046440][15779:15805] CHIP:DMG:             CommandDataIB =
[1687332187.046448][15779:15805] CHIP:DMG:             {
[1687332187.046453][15779:15805] CHIP:DMG:                 CommandPathIB =
[1687332187.046464][15779:15805] CHIP:DMG:                 {
[1687332187.046472][15779:15805] CHIP:DMG:                     EndpointId = 0x0,
[1687332187.046483][15779:15805] CHIP:DMG:                     ClusterId = 0x3e,
[1687332187.046496][15779:15805] CHIP:DMG:                     CommandId = 0x1,
[1687332187.046503][15779:15805] CHIP:DMG:                 },
[1687332187.046513][15779:15805] CHIP:DMG:                 
[1687332187.046519][15779:15805] CHIP:DMG:                 CommandFields =
[1687332187.046527][15779:15805] CHIP:DMG:                 {
[1687332187.046535][15779:15805] CHIP:DMG:                     0x0 = [
[1687332187.046586][15779:15805] CHIP:DMG:                             0x15, 0x30, 0x01, 0xeb, 0x30, 0x81, 0xe8, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x02, 0xa0, 0x81, 0xda, 0x30, 0x81, 0xd7, 0x02, 0x01, 0x03, 0x31, 0x0d, 0x30, 0x0b, 0x06, 0x09, 0x60, 0x86, 0x48, 0x01, 0x65, 0x03, 0x04, 0x02, 0x01, 0x30, 0x44, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x01, 0xa0, 0x37, 0x04, 0x35, 0x15, 0x24, 0x00, 0x01, 0x25, 0x01, 0x88, 0x11, 0x36, 0x02, 0x05, 0x01, 0x01, 0x18, 0x25, 0x03, 0x0a, 0x01, 0x2c, 0x04, 0x13, 0x43, 0x53, 0x41, 0x32, 0x32, 0x31, 0x36, 0x35, 0x4d, 0x41, 0x54, 0x34, 0x30, 0x31, 0x36, 0x35, 0x2d, 0x32, 0x34, 0x24, 0x05, 0x00, 0x24, 0x06, 0x00, 0x24, 0x07, 0x01, 0x24, 0x08, 0x02, 0x18, 0x31, 0x7d, 0x30, 0x7b, 0x02, 0x01, 0x03, 0x80, 0x14, 0xfe, 0x34, 0x3f, 0x95, 0x99, 0x47, 0x76, 0x3b, 0x61, 0xee, 0x45, 0x39, 0x13, 0x13, 0x38, 0x49, 0x4f, 0xe6, 0x7d, 0x8e, 0x30, 0x0b, 0x06, 0x09, 0x60, 0x86, 0x48, 0x01, 0x65, 0x03, 0x04, 0x02, 0x01, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x04, 0x47, 0x30, 0x45, 0x02, 0x21, 0x00, 0x89, 0x38, 0x2b, 0xe2, 0x94, 0x74, 0x5a, 0xea, 0x8c, 0x45, 0xf0, 0x5c, 0xf5, 0x8d, 0xb8, 0x41, 0xa2, 0x3e, 0x07, 0x68, 0x43, 0xdc, 0x6e, 0x36, 0xe7, 0x93, 0x99, 0x5c, 0x8f, 0xbb, 0x3d, 0x2f, 0x02, 0x20, 0x7f, 0x86, 0x94, 0xc5, 0xe3, 0x33, 0x7a, 0x5b, 0x28, 0x8f, 0xe1, 0x5c, 0x8b, 0x69, 0x2d, 0x08, 0x45, 0xd0, 0x3b, 0x9a, 0x1b, 0xc5, 0x9a, 0x3d, 0xb5, 0xd8, 0x9f, 0xf9, 0x8d, 0xb1, 0x7e, 0x29, 0x30, 0x02, 0x20, 0xae, 0x90, 0x62, 0x85, 0xb0, 0x60, 0x5a, 0xf8, 0x4f, 0x09, 0xcd, 0x07, 0x08, 0xbd, 0x28, 0x96, 0x4a, 0x4f, 0x05, 0xd5, 0x08, 0x13, 0x11, 0x8a, 0x79, 0x0f, 0x16, 0x37, 0xa4, 0x16, 0xc3, 0x3e, 0x24, 0x03, 0x00, 0x18,
[1687332187.046615][15779:15805] CHIP:DMG:                     ] (278 bytes)
[1687332187.046622][15779:15805] CHIP:DMG:                     0x1 = [
[1687332187.046639][15779:15805] CHIP:DMG:                             0x74, 0xa1, 0xad, 0xe9, 0xf1, 0xae, 0xe3, 0x03, 0x15, 0xdb, 0x7d, 0x49, 0x67, 0x2f, 0x51, 0x74, 0xe9, 0xb8, 0xf2, 0x82, 0xfa, 0x31, 0x0c, 0x43, 0xc5, 0x0b, 0x5c, 0x5a, 0x64, 0x46, 0xa3, 0x30, 0x42, 0xfc, 0xb3, 0x0a, 0x3f, 0x7f, 0x68, 0xd1, 0xd6, 0xd6, 0x16, 0x89, 0xee, 0xeb, 0x7f, 0x69, 0x59, 0x1f, 0xd4, 0x47, 0x7a, 0x73, 0x80, 0x89, 0x6e, 0x10, 0xd4, 0xb6, 0x48, 0x3a, 0x96, 0x6b,
[1687332187.046651][15779:15805] CHIP:DMG:                     ] (64 bytes)
[1687332187.046658][15779:15805] CHIP:DMG:                 },
[1687332187.046664][15779:15805] CHIP:DMG:             },
[1687332187.046674][15779:15805] CHIP:DMG:             
[1687332187.046679][15779:15805] CHIP:DMG:         },
[1687332187.046689][15779:15805] CHIP:DMG:         
[1687332187.046695][15779:15805] CHIP:DMG:     ],
[1687332187.046705][15779:15805] CHIP:DMG:     
[1687332187.046712][15779:15805] CHIP:DMG:     InteractionModelRevision = 1
[1687332187.046737][15779:15805] CHIP:DMG: },
[1687332187.046783][15779:15805] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
[1687332187.046803][15779:15805] CHIP:CTL: Received Attestation Information from the device
[1687332187.046816][15779:15805] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest'
[1687332187.046828][15779:15805] CHIP:CTL: AutoCommissioner setting attestationElements buffer size 278/278
[1687332187.046850][15779:15805] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
[1687332187.046860][15779:15805] CHIP:CTL: Performing next commissioning step 'AttestationVerification'
[1687332187.046867][15779:15805] CHIP:CTL: Verifying attestation
[1687332187.061090][15779:15805] CHIP:CTL: Failed in verifying 'Attestation Information' command received from the device: err 101. Look at AttestationVerificationResult enum to understand the errors
[1687332187.061126][15779:15805] CHIP:CTL: Error on commissioning step 'AttestationVerification': '../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error'
[1687332187.061132][15779:15805] CHIP:CTL: Failed to perform commissioning step 8
[1687332187.061137][15779:15805] CHIP:CTL: Going from commissioning step 'AttestationVerification' with lastErr = '../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error' -> 'Cleanup'
[1687332187.061148][15779:15805] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = '../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error'
[1687332187.061153][15779:15805] CHIP:CTL: Expiring failsafe on proxy 0x7f5940019780
[1687332187.061181][15779:15805] CHIP:DMG: ICR moving to [AddingComm]
[1687332187.061189][15779:15805] CHIP:DMG: ICR moving to [AddedComma]
[1687332187.061246][15779:15805] CHIP:EM: <<< [E:64294i M:43174478] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687332187.061256][15779:15805] CHIP:IN: (S) Sending msg 43174478 on secure session with LSID: 19592
[1687332187.061301][15779:15805] CHIP:DMG: ICR moving to [CommandSen]
[1687332187.061321][15779:15805] CHIP:DMG: ICR moving to [AwaitingDe]
[1687332187.135649][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687332187.137969][15779:15804] CHIP:DL: Indication received, conn = 0x7f5948073de0
[1687332187.138091][15779:15805] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687332187.138199][15779:15805] CHIP:EM: >>> [E:64294i M:188327134] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687332187.138216][15779:15805] CHIP:EM: Found matching exchange: 64294i, Delegate: 0x7f59480405b8
[1687332187.138233][15779:15805] CHIP:DMG: ICR moving to [ResponseRe]
[1687332187.138258][15779:15805] CHIP:DMG: InvokeResponseMessage =
[1687332187.138265][15779:15805] CHIP:DMG: {
[1687332187.138275][15779:15805] CHIP:DMG:     suppressResponse = false,
[1687332187.138285][15779:15805] CHIP:DMG:     InvokeResponseIBs =
[1687332187.138302][15779:15805] CHIP:DMG:     [
[1687332187.138310][15779:15805] CHIP:DMG:         InvokeResponseIB =
[1687332187.138327][15779:15805] CHIP:DMG:         {
[1687332187.138336][15779:15805] CHIP:DMG:             CommandDataIB =
[1687332187.138347][15779:15805] CHIP:DMG:             {
[1687332187.138355][15779:15805] CHIP:DMG:                 CommandPathIB =
[1687332187.138369][15779:15805] CHIP:DMG:                 {
[1687332187.138383][15779:15805] CHIP:DMG:                     EndpointId = 0x0,
[1687332187.138394][15779:15805] CHIP:DMG:                     ClusterId = 0x30,
[1687332187.138414][15779:15805] CHIP:DMG:                     CommandId = 0x1,
[1687332187.138424][15779:15805] CHIP:DMG:                 },
[1687332187.138435][15779:15805] CHIP:DMG:                 
[1687332187.138445][15779:15805] CHIP:DMG:                 CommandFields =
[1687332187.138456][15779:15805] CHIP:DMG:                 {
[1687332187.138472][15779:15805] CHIP:DMG:                     0x0 = 0,
[1687332187.138486][15779:15805] CHIP:DMG:                     0x1 = "" (0 chars),
[1687332187.138495][15779:15805] CHIP:DMG:                 },
[1687332187.138505][15779:15805] CHIP:DMG:             },
[1687332187.138518][15779:15805] CHIP:DMG:             
[1687332187.138527][15779:15805] CHIP:DMG:         },
[1687332187.138544][15779:15805] CHIP:DMG:         
[1687332187.138551][15779:15805] CHIP:DMG:     ],
[1687332187.138566][15779:15805] CHIP:DMG:     
[1687332187.138574][15779:15805] CHIP:DMG:     InteractionModelRevision = 1
[1687332187.138581][15779:15805] CHIP:DMG: },
[1687332187.138616][15779:15805] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1687332187.138636][15779:15805] CHIP:CTL: Failsafe disarmed
[1687332187.138649][15779:15805] CHIP:CTL: Successfully finished commissioning step 'Cleanup'
[1687332187.138669][15779:15805] CHIP:TOO: Device commissioning Failure: ../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error
[1687332187.138685][15779:15805] CHIP:DIS: Closing all BLE connections
[1687332187.138692][15779:15805] CHIP:IN: Clearing BLE pending packets.
[1687332187.138718][15779:15805] CHIP:BLE: Auto-closing end point's BLE connection.
[1687332187.138724][15779:15805] CHIP:DL: Closing BLE GATT connection (con 0x7f5948073de0)
[1687332187.138759][15779:15805] CHIP:IN: SecureSession[0x7f594000ff10]: MarkForEviction Type:1 LSID:19592
[1687332187.138767][15779:15805] CHIP:SC: SecureSession[0x7f594000ff10]: Moving from state 'kActive' --> 'kPendingEviction'
[1687332187.138815][15779:15805] CHIP:DMG: ICR moving to [AwaitingDe]
[1687332187.138830][15779:15805] CHIP:IN: SecureSession[0x7f594000ff10]: Released - Type:1 LSID:19592
[1687332187.138858][15779:15804] CHIP:DL: BluezDisconnect peer=48:22:54:5F:2B:F3
[1687332187.138958][15779:15779] CHIP:CTL: Shutting down the commissioner
[1687332187.138983][15779:15779] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687332187.139034][15779:15779] CHIP:CTL: Shutting down the controller
[1687332187.139044][15779:15779] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1687332187.139055][15779:15779] CHIP:FP: Forgetting fabric 0x1
[1687332187.139071][15779:15779] CHIP:TS: Pending Last Known Good Time: 2023-01-04T15:21:56
[1687332187.139162][15779:15779] CHIP:TS: Previous Last Known Good Time: 2023-01-04T15:21:56
[1687332187.139170][15779:15779] CHIP:TS: Reverted Last Known Good Time to previous value
[1687332187.139193][15779:15779] CHIP:CTL: Shutting down the commissioner
[1687332187.139201][15779:15779] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687332187.139231][15779:15779] CHIP:CTL: Shutting down the controller
[1687332187.139240][15779:15779] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1687332187.139350][15779:15779] CHIP:DMG: IM WH moving to [Uninitialized]
[1687332187.139357][15779:15779] CHIP:DMG: IM WH moving to [Uninitialized]
[1687332187.139364][15779:15779] CHIP:DMG: IM WH moving to [Uninitialized]
[1687332187.139371][15779:15779] CHIP:DMG: IM WH moving to [Uninitialized]
[1687332187.139380][15779:15779] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1687332187.139409][15779:15779] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1687332187.139428][15779:15779] CHIP:FP: Shutting down FabricTable
[1687332187.139439][15779:15779] CHIP:TS: Pending Last Known Good Time: 2023-01-04T15:21:56
[1687332187.139494][15779:15779] CHIP:TS: Previous Last Known Good Time: 2023-01-04T15:21:56
[1687332187.139501][15779:15779] CHIP:TS: Reverted Last Known Good Time to previous value
[1687332187.139630][15779:15779] CHIP:DL: writing settings to file (/mnt/chip_counters.ini-SvHZOZ)
[1687332187.139859][15779:15779] CHIP:DL: renamed tmp file to file (/mnt/chip_counters.ini)
[1687332187.139883][15779:15779] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1687332187.139893][15779:15779] CHIP:DL: Inet Layer shutdown
[1687332187.139901][15779:15779] CHIP:DL: BLE shutdown
[1687332187.140579][15779:15779] CHIP:DL: System Layer shutdown
[1687332189.797401][15779:15779] CHIP:TOO: Run command failure: ../examples/chip-tool/third_party/connectedhomeip/src/controller/CHIPDeviceController.cpp:1075: CHIP Error 0x000000AC: Internal error

[AHaug]

Hi

Error 101, during AttestationInformation informs about unavailable PAA on the controller side, if the client use non-default DAC/PAI generated on non-default PAA in their sample (in FactoryData) then he/she needs to provider path to chip-tool where the PAA is stored.
./chip-tool pairing ble-thread <nodeid> hex:<thread_dataset> <setupcode> <discriminator> --paa-trust-store-path <path_to_paa>

https://github.com/nrfconnect/sdk-connectedhomeip/blob/master/src/credentials/attestation_verifier/DeviceAttestationVerifier.h#L35

Let me know if this solves the issue you're observing

Kind regards,
Andreas

[Varun2103]

Ok but what contains in the path to paa ?

[Varun2103]

Ok on mentioning the path to paa, It resolved attestation verification error Thank you so much.

But I got one more error(about operatioalsessionsetup) now could you please look into that.

The terminal output is as follows

1687452601.894221][124848:124848] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1687452601.898066][124848:124848] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1687452601.898141][124848:124848] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1687452601.898170][124848:124848] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1687452601.898355][124848:124848] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-ywQTl1)
[1687452601.898594][124848:124848] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1687452601.898617][124848:124848] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2)
[1687452601.898894][124848:124848] CHIP:DL: Got Ethernet interface: enp2s0
[1687452601.899028][124848:124848] CHIP:DL: Found the primary Ethernet interface:enp2s0
[1687452601.899230][124848:124848] CHIP:DL: Got WiFi interface: wlp3s0
[1687452601.899418][124848:124848] CHIP:DL: Found the primary WiFi interface:wlp3s0
[1687452601.899462][124848:124848] CHIP:IN: UDP::Init bind&listen port=0
[1687452601.899496][124848:124848] CHIP:IN: UDP::Init bound to port=33789
[1687452601.899504][124848:124848] CHIP:IN: UDP::Init bind&listen port=0
[1687452601.899526][124848:124848] CHIP:IN: UDP::Init bound to port=37925
[1687452601.899533][124848:124848] CHIP:IN: BLEBase::Init - setting/overriding transport
[1687452601.899541][124848:124848] CHIP:IN: TransportMgr initialized
[1687452601.899563][124848:124848] CHIP:FP: Initializing FabricTable from persistent storage
[1687452601.899642][124848:124848] CHIP:TS: Last Known Good Time: 2023-06-21T16:18:47
[1687452601.901028][124848:124848] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x10B023A18AE28C7A, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1687452601.902918][124848:124848] CHIP:ZCL: Using ZAP configuration...
[1687452601.906681][124848:124848] CHIP:CTL: System State Initialized...
[1687452601.916843][124848:124848] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687452601.916922][124848:124848] CHIP:CTL: Setting attestation nonce to random value
[1687452601.916988][124848:124848] CHIP:CTL: Setting CSR nonce to random value
[1687452601.917034][124848:124848] CHIP:IN: UDP::Init bind&listen port=5550
[1687452601.917099][124848:124848] CHIP:IN: UDP::Init bound to port=5550
[1687452601.917112][124848:124848] CHIP:IN: UDP::Init bind&listen port=5550
[1687452601.917156][124848:124848] CHIP:IN: UDP::Init bound to port=5550
[1687452601.917168][124848:124848] CHIP:IN: TransportMgr initialized
[1687452601.917412][124848:124851] CHIP:DL: CHIP task running
[1687452601.917481][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1687452601.917714][124848:124851] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687452601.917740][124848:124851] CHIP:CTL: Setting attestation nonce to random value
[1687452601.917824][124848:124851] CHIP:CTL: Setting CSR nonce to random value
[1687452601.918759][124848:124851] CHIP:CTL: Generating NOC
[1687452601.921097][124848:124851] CHIP:FP: Validating NOC chain
[1687452601.924594][124848:124851] CHIP:FP: NOC chain validation successful
[1687452601.924755][124848:124851] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1687452601.924772][124848:124851] CHIP:TS: Last Known Good Time: 2023-06-21T16:18:47
[1687452601.924781][124848:124851] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1687452601.924843][124848:124851] CHIP:TS: Retaining current Last Known Good Time
[1687452601.927284][124848:124851] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1687452601.929337][124848:124851] CHIP:TS: Committing Last Known Good Time to storage: 2023-06-21T16:18:47
[1687452601.930756][124848:124851] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 10B023A18AE28C7A)
[1687452601.930848][124848:124851] CHIP:IN: UDP::Init bind&listen port=5550
[1687452601.930952][124848:124851] CHIP:IN: UDP::Init bound to port=5550
[1687452601.930983][124848:124851] CHIP:IN: UDP::Init bind&listen port=5550
[1687452601.931052][124848:124851] CHIP:IN: UDP::Init bound to port=5550
[1687452601.931110][124848:124851] CHIP:IN: TransportMgr initialized
[1687452601.949223][124848:124851] CHIP:CTL: Setting wifi credentials from parameters
[1687452601.949247][124848:124851] CHIP:CTL: Setting attestation nonce to random value
[1687452601.949279][124848:124851] CHIP:CTL: Setting CSR nonce to random value
[1687452601.949334][124848:124851] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687452601.949344][124848:124851] CHIP:CTL: Starting commissioning discovery over BLE
[1687452601.949364][124848:124851] CHIP:CTL: Starting commissioning discovery over DNS-SD
[1687452601.957813][124848:124850] CHIP:DL: TRACE: Bus acquired for name C-e7b0
[1687452601.980398][124848:124851] CHIP:DL: PlatformBlueZInit init success
[1687452601.993381][124848:124850] CHIP:BLE: BLE removing known devices.
[1687452602.279460][124848:124850] CHIP:BLE: BLE initiating scan.
[1687452602.280717][124848:124851] CHIP:DL: Long dispatch time: 332 ms, for event type 2
[1687452602.349329][124848:124850] CHIP:BLE: Device 6C:E9:45:5C:64:BC does not look like a CHIP device.
[1687452602.416462][124848:124850] CHIP:BLE: New device scanned: 48:22:54:5F:2B:F3
[1687452602.416513][124848:124850] CHIP:BLE: Device discriminator match. Attempting to connect.
[1687452603.291685][124848:124850] CHIP:DL: ConnectDevice complete
[1687452604.046310][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687452604.046344][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046356][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687452604.046364][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046383][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687452604.046393][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046413][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0001
[1687452604.046421][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046430][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0001
[1687452604.046438][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046448][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0001
[1687452604.046457][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046481][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046488][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046505][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046515][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046538][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687452604.046546][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046561][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687452604.046570][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046585][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service000c
[1687452604.046595][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046616][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046624][124848:124850] CHIP:DL: Char1 /org/bluez/hci0/dev_48_22_54_5F_2B_F3/service0013
[1687452604.046644][124848:124850] CHIP:DL: New BLE connection 0x7f121c06fff0, device 48:22:54:5F:2B:F3, path /org/bluez/hci0/dev_48_22_54_5F_2B_F3
[1687452604.046742][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16385
[1687452604.046799][124848:124851] CHIP:CTL: Discovered device to be commissioned over BLE
[1687452604.046868][124848:124851] CHIP:CTL: Attempting PASE connection to BLE
[1687452604.046927][124848:124851] CHIP:IN: BleConnectionComplete: endPoint 0x55baaf17e4e0
[1687452604.047253][124848:124851] CHIP:IN: SecureSession[0x7f121400f400]: Allocated Type:1 LSID:44403
[1687452604.047273][124848:124851] CHIP:SC: Assigned local session key ID 44403
[1687452604.047348][124848:124851] CHIP:EM: <<< [E:17868i S:0 M:94851716] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[1687452604.047375][124848:124851] CHIP:IN: (U) Sending msg 94851716 to IP address 'BLE'
[1687452604.047389][124848:124851] CHIP:IN: Message appended to BLE send queue
[1687452604.047399][124848:124851] CHIP:SC: Sent PBKDF param request
[1687452604.047411][124848:124851] CHIP:CTL: Commission called for node ID 0x000000000000A219
[1687452604.438200][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452604.507030][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16388
[1687452604.507063][124848:124851] CHIP:BLE: subscribe complete, ep = 0x55baaf17e4e0
[1687452604.507552][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452604.507643][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452604.507679][124848:124851] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4
[1687452604.507692][124848:124851] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244.
[1687452604.507703][124848:124851] CHIP:BLE: local and remote recv window size = 5
[1687452604.508125][124848:124851] CHIP:IN: BLE EndPoint 0x55baaf17e4e0 Connection Complete
[1687452604.595850][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452604.688014][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452604.688153][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452604.688256][124848:124851] CHIP:EM: >>> [E:17868i S:0 M:218364218] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
[1687452604.688280][124848:124851] CHIP:EM: Found matching exchange: 17868i, Delegate: 0x7f1214012e60
[1687452604.688305][124848:124851] CHIP:SC: Received PBKDF param response
[1687452604.688383][124848:124851] CHIP:SC: Peer assigned session ID 42461
[1687452604.688437][124848:124851] CHIP:SC: Found MRP parameters in the message
[1687452604.765211][124848:124851] CHIP:EM: <<< [E:17868i S:0 M:94851717] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1)
[1687452604.765248][124848:124851] CHIP:IN: (U) Sending msg 94851717 to IP address 'BLE'
[1687452604.765797][124848:124851] CHIP:SC: Sent spake2p msg1
[1687452604.821203][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452605.766245][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452605.766398][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452605.766514][124848:124851] CHIP:EM: >>> [E:17868i S:0 M:218364219] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
[1687452605.766542][124848:124851] CHIP:EM: Found matching exchange: 17868i, Delegate: 0x7f1214012e60
[1687452605.766565][124848:124851] CHIP:SC: Received spake2p msg2
[1687452605.768598][124848:124851] CHIP:EM: <<< [E:17868i S:0 M:94851718] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3)
[1687452605.768705][124848:124851] CHIP:IN: (U) Sending msg 94851718 to IP address 'BLE'
[1687452605.769591][124848:124851] CHIP:SC: Sent spake2p msg3
[1687452605.900381][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452605.900908][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452605.901210][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452605.901384][124848:124851] CHIP:EM: >>> [E:17868i S:0 M:218364220] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1687452605.901432][124848:124851] CHIP:EM: Found matching exchange: 17868i, Delegate: 0x7f1214012e60
[1687452605.901849][124848:124851] CHIP:SC: SecureSession[0x7f121400f400, LSID:44403]: State change 'kEstablishing' --> 'kActive'
[1687452605.901880][124848:124851] CHIP:IN: SecureSession[0x7f121400f400]: Activated - Type:1 LSID:44403
[1687452605.901900][124848:124851] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:44403 PSID:42461!
[1687452605.901932][124848:124851] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1687452605.901969][124848:124851] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687452605.901987][124848:124851] CHIP:TOO: Pairing Success
[1687452605.902002][124848:124851] CHIP:TOO: PASE establishment successful
[1687452605.902017][124848:124851] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
[1687452605.902037][124848:124851] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'
[1687452605.902051][124848:124851] CHIP:CTL: Sending request for commissioning information
[1687452605.902090][124848:124851] CHIP:DMG: SendReadRequest ReadClient[0x7f1214015030]: Sending Read Request
[1687452605.902312][124848:124851] CHIP:EM: <<< [E:17869i S:44403 M:253297760] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest)
[1687452605.902346][124848:124851] CHIP:IN: (S) Sending msg 253297760 on secure session with LSID: 44403
[1687452605.903001][124848:124851] CHIP:DMG: MoveToState ReadClient[0x7f1214015030]: Moving to [AwaitingIn]
[1687452605.990716][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452606.126102][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452606.126213][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452606.261649][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452606.261771][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452606.261914][124848:124851] CHIP:EM: >>> [E:17869i S:44403 M:60129857] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
[1687452606.261933][124848:124851] CHIP:EM: Found matching exchange: 17869i, Delegate: 0x7f1214015040
[1687452606.262000][124848:124851] CHIP:DMG: ReportDataMessage =
[1687452606.262011][124848:124851] CHIP:DMG: {
[1687452606.262017][124848:124851] CHIP:DMG:     AttributeReportIBs =
[1687452606.262031][124848:124851] CHIP:DMG:     [
[1687452606.262039][124848:124851] CHIP:DMG:         AttributeReportIB =
[1687452606.262056][124848:124851] CHIP:DMG:         {
[1687452606.262070][124848:124851] CHIP:DMG:             AttributeDataIB =
[1687452606.262079][124848:124851] CHIP:DMG:             {
[1687452606.262088][124848:124851] CHIP:DMG:                 DataVersion = 0x7d966455,
[1687452606.262096][124848:124851] CHIP:DMG:                 AttributePathIB =
[1687452606.262105][124848:124851] CHIP:DMG:                 {
[1687452606.262113][124848:124851] CHIP:DMG:                     Endpoint = 0x0,
[1687452606.262122][124848:124851] CHIP:DMG:                     Cluster = 0x31,
[1687452606.262130][124848:124851] CHIP:DMG:                     Attribute = 0x0000_0003,
[1687452606.262140][124848:124851] CHIP:DMG:                 }
[1687452606.262157][124848:124851] CHIP:DMG:                     
[1687452606.262168][124848:124851] CHIP:DMG:                 Data = 20,
[1687452606.262177][124848:124851] CHIP:DMG:             },
[1687452606.262190][124848:124851] CHIP:DMG:             
[1687452606.262224][124848:124851] CHIP:DMG:         },
[1687452606.262241][124848:124851] CHIP:DMG:         
[1687452606.262249][124848:124851] CHIP:DMG:         AttributeReportIB =
[1687452606.262260][124848:124851] CHIP:DMG:         {
[1687452606.262269][124848:124851] CHIP:DMG:             AttributeDataIB =
[1687452606.262279][124848:124851] CHIP:DMG:             {
[1687452606.262288][124848:124851] CHIP:DMG:                 DataVersion = 0xdf9981e7,
[1687452606.262298][124848:124851] CHIP:DMG:                 AttributePathIB =
[1687452606.262305][124848:124851] CHIP:DMG:                 {
[1687452606.262314][124848:124851] CHIP:DMG:                     Endpoint = 0x0,
[1687452606.262323][124848:124851] CHIP:DMG:                     Cluster = 0x28,
[1687452606.262333][124848:124851] CHIP:DMG:                     Attribute = 0x0000_0004,
[1687452606.262345][124848:124851] CHIP:DMG:                 }
[1687452606.262356][124848:124851] CHIP:DMG:                     
[1687452606.262365][124848:124851] CHIP:DMG:                 Data = 257,
[1687452606.262373][124848:124851] CHIP:DMG:             },
[1687452606.262384][124848:124851] CHIP:DMG:             
[1687452606.262392][124848:124851] CHIP:DMG:         },
[1687452606.262408][124848:124851] CHIP:DMG:         
[1687452606.262415][124848:124851] CHIP:DMG:         AttributeReportIB =
[1687452606.262427][124848:124851] CHIP:DMG:         {
[1687452606.262435][124848:124851] CHIP:DMG:             AttributeDataIB =
[1687452606.262444][124848:124851] CHIP:DMG:             {
[1687452606.262453][124848:124851] CHIP:DMG:                 DataVersion = 0xdf9981e7,
[1687452606.262461][124848:124851] CHIP:DMG:                 AttributePathIB =
[1687452606.262476][124848:124851] CHIP:DMG:                 {
[1687452606.262485][124848:124851] CHIP:DMG:                     Endpoint = 0x0,
[1687452606.262494][124848:124851] CHIP:DMG:                     Cluster = 0x28,
[1687452606.262504][124848:124851] CHIP:DMG:                     Attribute = 0x0000_0002,
[1687452606.262512][124848:124851] CHIP:DMG:                 }
[1687452606.262522][124848:124851] CHIP:DMG:                     
[1687452606.262532][124848:124851] CHIP:DMG:                 Data = 4488,
[1687452606.262540][124848:124851] CHIP:DMG:             },
[1687452606.262551][124848:124851] CHIP:DMG:             
[1687452606.262559][124848:124851] CHIP:DMG:         },
[1687452606.262575][124848:124851] CHIP:DMG:         
[1687452606.262582][124848:124851] CHIP:DMG:         AttributeReportIB =
[1687452606.262598][124848:124851] CHIP:DMG:         {
[1687452606.262605][124848:124851] CHIP:DMG:             AttributeDataIB =
[1687452606.262617][124848:124851] CHIP:DMG:             {
[1687452606.262625][124848:124851] CHIP:DMG:                 DataVersion = 0xb7683cad,
[1687452606.262635][124848:124851] CHIP:DMG:                 AttributePathIB =
[1687452606.262646][124848:124851] CHIP:DMG:                 {
[1687452606.262655][124848:124851] CHIP:DMG:                     Endpoint = 0x0,
[1687452606.262665][124848:124851] CHIP:DMG:                     Cluster = 0x30,
[1687452606.262674][124848:124851] CHIP:DMG:                     Attribute = 0x0000_0003,
[1687452606.262698][124848:124851] CHIP:DMG:                 }
[1687452606.262709][124848:124851] CHIP:DMG:                     
[1687452606.262721][124848:124851] CHIP:DMG:                 Data = 0,
[1687452606.262730][124848:124851] CHIP:DMG:             },
[1687452606.262742][124848:124851] CHIP:DMG:             
[1687452606.262751][124848:124851] CHIP:DMG:         },
[1687452606.262769][124848:124851] CHIP:DMG:         
[1687452606.262777][124848:124851] CHIP:DMG:         AttributeReportIB =
[1687452606.262791][124848:124851] CHIP:DMG:         {
[1687452606.262799][124848:124851] CHIP:DMG:             AttributeDataIB =
[1687452606.262810][124848:124851] CHIP:DMG:             {
[1687452606.262820][124848:124851] CHIP:DMG:                 DataVersion = 0xb7683cad,
[1687452606.262832][124848:124851] CHIP:DMG:                 AttributePathIB =
[1687452606.262842][124848:124851] CHIP:DMG:                 {
[1687452606.262852][124848:124851] CHIP:DMG:                     Endpoint = 0x0,
[1687452606.262863][124848:124851] CHIP:DMG:                     Cluster = 0x30,
[1687452606.262873][124848:124851] CHIP:DMG:                     Attribute = 0x0000_0002,
[1687452606.262882][124848:124851] CHIP:DMG:                 }
[1687452606.262895][124848:124851] CHIP:DMG:                     
[1687452606.262905][124848:124851] CHIP:DMG:                 Data = 0,
[1687452606.262913][124848:124851] CHIP:DMG:             },
[1687452606.262927][124848:124851] CHIP:DMG:             
[1687452606.262935][124848:124851] CHIP:DMG:         },
[1687452606.262954][124848:124851] CHIP:DMG:         
[1687452606.262961][124848:124851] CHIP:DMG:         AttributeReportIB =
[1687452606.262977][124848:124851] CHIP:DMG:         {
[1687452606.262985][124848:124851] CHIP:DMG:             AttributeDataIB =
[1687452606.262996][124848:124851] CHIP:DMG:             {
[1687452606.263005][124848:124851] CHIP:DMG:                 DataVersion = 0xb7683cad,
[1687452606.263019][124848:124851] CHIP:DMG:                 AttributePathIB =
[1687452606.263030][124848:124851] CHIP:DMG:                 {
[1687452606.263040][124848:124851] CHIP:DMG:                     Endpoint = 0x0,
[1687452606.263050][124848:124851] CHIP:DMG:                     Cluster = 0x30,
[1687452606.263060][124848:124851] CHIP:DMG:                     Attribute = 0x0000_0001,
[1687452606.263069][124848:124851] CHIP:DMG:                 }
[1687452606.263081][124848:124851] CHIP:DMG:                     
[1687452606.263090][124848:124851] CHIP:DMG:                 Data =
[1687452606.263101][124848:124851] CHIP:DMG:                 {
[1687452606.263112][124848:124851] CHIP:DMG:                     0x0 = 60,
[1687452606.263123][124848:124851] CHIP:DMG:                     0x1 = 900,
[1687452606.263134][124848:124851] CHIP:DMG:                 },
[1687452606.263143][124848:124851] CHIP:DMG:             },
[1687452606.263158][124848:124851] CHIP:DMG:             
[1687452606.263167][124848:124851] CHIP:DMG:         },
[1687452606.263185][124848:124851] CHIP:DMG:         
[1687452606.263192][124848:124851] CHIP:DMG:         AttributeReportIB =
[1687452606.263207][124848:124851] CHIP:DMG:         {
[1687452606.263215][124848:124851] CHIP:DMG:             AttributeDataIB =
[1687452606.263224][124848:124851] CHIP:DMG:             {
[1687452606.263234][124848:124851] CHIP:DMG:                 DataVersion = 0xb7683cad,
[1687452606.263244][124848:124851] CHIP:DMG:                 AttributePathIB =
[1687452606.263255][124848:124851] CHIP:DMG:                 {
[1687452606.263267][124848:124851] CHIP:DMG:                     Endpoint = 0x0,
[1687452606.263276][124848:124851] CHIP:DMG:                     Cluster = 0x30,
[1687452606.263291][124848:124851] CHIP:DMG:                     Attribute = 0x0000_0000,
[1687452606.263300][124848:124851] CHIP:DMG:                 }
[1687452606.263311][124848:124851] CHIP:DMG:                     
[1687452606.263321][124848:124851] CHIP:DMG:                 Data = 0,
[1687452606.263330][124848:124851] CHIP:DMG:             },
[1687452606.263342][124848:124851] CHIP:DMG:             
[1687452606.263351][124848:124851] CHIP:DMG:         },
[1687452606.263368][124848:124851] CHIP:DMG:         
[1687452606.263376][124848:124851] CHIP:DMG:         AttributeReportIB =
[1687452606.263390][124848:124851] CHIP:DMG:         {
[1687452606.263398][124848:124851] CHIP:DMG:             AttributeDataIB =
[1687452606.263410][124848:124851] CHIP:DMG:             {
[1687452606.263419][124848:124851] CHIP:DMG:                 DataVersion = 0x7d966455,
[1687452606.263429][124848:124851] CHIP:DMG:                 AttributePathIB =
[1687452606.263438][124848:124851] CHIP:DMG:                 {
[1687452606.263448][124848:124851] CHIP:DMG:                     Endpoint = 0x0,
[1687452606.263468][124848:124851] CHIP:DMG:                     Cluster = 0x31,
[1687452606.263478][124848:124851] CHIP:DMG:                     Attribute = 0x0000_FFFC,
[1687452606.263486][124848:124851] CHIP:DMG:                 }
[1687452606.263497][124848:124851] CHIP:DMG:                     
[1687452606.263506][124848:124851] CHIP:DMG:                 Data = 1,
[1687452606.263514][124848:124851] CHIP:DMG:             },
[1687452606.263525][124848:124851] CHIP:DMG:             
[1687452606.263533][124848:124851] CHIP:DMG:         },
[1687452606.263544][124848:124851] CHIP:DMG:         
[1687452606.263553][124848:124851] CHIP:DMG:     ],
[1687452606.263587][124848:124851] CHIP:DMG:     
[1687452606.263596][124848:124851] CHIP:DMG:     SuppressResponse = true,
[1687452606.263604][124848:124851] CHIP:DMG:     InteractionModelRevision = 1
[1687452606.263610][124848:124851] CHIP:DMG: }
[1687452606.264216][124848:124851] CHIP:CTL: ----- NetworkCommissioning Features: has WiFi. endpointid = 0
[1687452606.264279][124848:124851] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'
[1687452606.265021][124848:124851] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe'
[1687452606.265052][124848:124851] CHIP:CTL: Performing next commissioning step 'ArmFailSafe'
[1687452606.265067][124848:124851] CHIP:CTL: Arming failsafe (60 seconds)
[1687452606.265130][124848:124851] CHIP:DMG: ICR moving to [AddingComm]
[1687452606.265481][124848:124851] CHIP:DMG: ICR moving to [AddedComma]
[1687452606.265622][124848:124851] CHIP:EM: <<< [E:17870i S:44403 M:253297761] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687452606.265647][124848:124851] CHIP:IN: (S) Sending msg 253297761 on secure session with LSID: 44403
[1687452606.265913][124848:124851] CHIP:DMG: ICR moving to [CommandSen]
[1687452606.350927][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452606.354711][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452606.354930][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452606.355295][124848:124851] CHIP:EM: >>> [E:17870i S:44403 M:60129858] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687452606.355321][124848:124851] CHIP:EM: Found matching exchange: 17870i, Delegate: 0x7f121c071398
[1687452606.355346][124848:124851] CHIP:DMG: ICR moving to [ResponseRe]
[1687452606.355391][124848:124851] CHIP:DMG: InvokeResponseMessage =
[1687452606.355403][124848:124851] CHIP:DMG: {
[1687452606.355455][124848:124851] CHIP:DMG:     suppressResponse = false,
[1687452606.355466][124848:124851] CHIP:DMG:     InvokeResponseIBs =
[1687452606.355493][124848:124851] CHIP:DMG:     [
[1687452606.355542][124848:124851] CHIP:DMG:         InvokeResponseIB =
[1687452606.355562][124848:124851] CHIP:DMG:         {
[1687452606.355571][124848:124851] CHIP:DMG:             CommandDataIB =
[1687452606.355581][124848:124851] CHIP:DMG:             {
[1687452606.355597][124848:124851] CHIP:DMG:                 CommandPathIB =
[1687452606.355614][124848:124851] CHIP:DMG:                 {
[1687452606.355632][124848:124851] CHIP:DMG:                     EndpointId = 0x0,
[1687452606.355650][124848:124851] CHIP:DMG:                     ClusterId = 0x30,
[1687452606.355670][124848:124851] CHIP:DMG:                     CommandId = 0x1,
[1687452606.355684][124848:124851] CHIP:DMG:                 },
[1687452606.355698][124848:124851] CHIP:DMG:                 
[1687452606.355708][124848:124851] CHIP:DMG:                 CommandFields =
[1687452606.355721][124848:124851] CHIP:DMG:                 {
[1687452606.355740][124848:124851] CHIP:DMG:                     0x0 = 0,
[1687452606.355757][124848:124851] CHIP:DMG:                     0x1 = "" (0 chars),
[1687452606.355776][124848:124851] CHIP:DMG:                 },
[1687452606.355790][124848:124851] CHIP:DMG:             },
[1687452606.355817][124848:124851] CHIP:DMG:             
[1687452606.355828][124848:124851] CHIP:DMG:         },
[1687452606.355851][124848:124851] CHIP:DMG:         
[1687452606.355880][124848:124851] CHIP:DMG:     ],
[1687452606.355906][124848:124851] CHIP:DMG:     
[1687452606.355917][124848:124851] CHIP:DMG:     InteractionModelRevision = 1
[1687452606.355929][124848:124851] CHIP:DMG: },
[1687452606.356084][124848:124851] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1687452606.356137][124848:124851] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1687452606.356177][124848:124851] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe'
[1687452606.356216][124848:124851] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
[1687452606.356256][124848:124851] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory'
[1687452606.356282][124848:124851] CHIP:CTL: Setting Regulatory Config
[1687452606.356305][124848:124851] CHIP:CTL: Device does not support configurable regulatory location
[1687452606.356402][124848:124851] CHIP:DMG: ICR moving to [AddingComm]
[1687452606.443640][124848:124851] CHIP:DMG: ICR moving to [AddedComma]
[1687452606.443755][124848:124851] CHIP:EM: <<< [E:17871i S:44403 M:253297762] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687452606.443784][124848:124851] CHIP:IN: (S) Sending msg 253297762 on secure session with LSID: 44403
[1687452606.444781][124848:124851] CHIP:DMG: ICR moving to [CommandSen]
[1687452606.444892][124848:124851] CHIP:DMG: ICR moving to [AwaitingDe]
[1687452606.530417][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452606.577938][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452606.578085][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452606.578258][124848:124851] CHIP:EM: >>> [E:17871i S:44403 M:60129859] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687452606.578290][124848:124851] CHIP:EM: Found matching exchange: 17871i, Delegate: 0x7f121400eaa8
[1687452606.578317][124848:124851] CHIP:DMG: ICR moving to [ResponseRe]
[1687452606.578373][124848:124851] CHIP:DMG: InvokeResponseMessage =
[1687452606.578389][124848:124851] CHIP:DMG: {
[1687452606.578405][124848:124851] CHIP:DMG:     suppressResponse = false,
[1687452606.578420][124848:124851] CHIP:DMG:     InvokeResponseIBs =
[1687452606.578449][124848:124851] CHIP:DMG:     [
[1687452606.578463][124848:124851] CHIP:DMG:         InvokeResponseIB =
[1687452606.578490][124848:124851] CHIP:DMG:         {
[1687452606.578505][124848:124851] CHIP:DMG:             CommandDataIB =
[1687452606.578526][124848:124851] CHIP:DMG:             {
[1687452606.578542][124848:124851] CHIP:DMG:                 CommandPathIB =
[1687452606.578560][124848:124851] CHIP:DMG:                 {
[1687452606.578578][124848:124851] CHIP:DMG:                     EndpointId = 0x0,
[1687452606.578597][124848:124851] CHIP:DMG:                     ClusterId = 0x30,
[1687452606.578617][124848:124851] CHIP:DMG:                     CommandId = 0x3,
[1687452606.578633][124848:124851] CHIP:DMG:                 },
[1687452606.578656][124848:124851] CHIP:DMG:                 
[1687452606.578674][124848:124851] CHIP:DMG:                 CommandFields =
[1687452606.578695][124848:124851] CHIP:DMG:                 {
[1687452606.578716][124848:124851] CHIP:DMG:                     0x0 = 0,
[1687452606.578739][124848:124851] CHIP:DMG:                     0x1 = "" (0 chars),
[1687452606.578759][124848:124851] CHIP:DMG:                 },
[1687452606.578776][124848:124851] CHIP:DMG:             },
[1687452606.578803][124848:124851] CHIP:DMG:             
[1687452606.578817][124848:124851] CHIP:DMG:         },
[1687452606.578844][124848:124851] CHIP:DMG:         
[1687452606.578855][124848:124851] CHIP:DMG:     ],
[1687452606.578877][124848:124851] CHIP:DMG:     
[1687452606.578888][124848:124851] CHIP:DMG:     InteractionModelRevision = 1
[1687452606.578899][124848:124851] CHIP:DMG: },
[1687452606.578951][124848:124851] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
[1687452606.579681][124848:124851] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0
[1687452606.579712][124848:124851] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory'
[1687452606.579727][124848:124851] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
[1687452606.579748][124848:124851] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest'
[1687452606.579761][124848:124851] CHIP:CTL: Sending request for PAI certificate
[1687452606.579772][124848:124851] CHIP:CTL: Sending Certificate Chain request to 0x7f1214012e10 device
[1687452606.579818][124848:124851] CHIP:DMG: ICR moving to [AddingComm]
[1687452606.580298][124848:124851] CHIP:DMG: ICR moving to [AddedComma]
[1687452606.580438][124848:124851] CHIP:EM: <<< [E:17872i S:44403 M:253297763] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687452606.580468][124848:124851] CHIP:IN: (S) Sending msg 253297763 on secure session with LSID: 44403
[1687452606.580909][124848:124851] CHIP:DMG: ICR moving to [CommandSen]
[1687452606.581016][124848:124851] CHIP:DMG: ICR moving to [AwaitingDe]
[1687452606.665704][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452606.802103][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452606.802374][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452607.026679][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452607.026824][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452607.116817][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452607.117056][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452607.117177][124848:124851] CHIP:EM: >>> [E:17872i S:44403 M:60129860] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687452607.117202][124848:124851] CHIP:EM: Found matching exchange: 17872i, Delegate: 0x7f121c071398
[1687452607.117225][124848:124851] CHIP:DMG: ICR moving to [ResponseRe]
[1687452607.117261][124848:124851] CHIP:DMG: InvokeResponseMessage =
[1687452607.117271][124848:124851] CHIP:DMG: {
[1687452607.117284][124848:124851] CHIP:DMG:     suppressResponse = false,
[1687452607.117297][124848:124851] CHIP:DMG:     InvokeResponseIBs =
[1687452607.117316][124848:124851] CHIP:DMG:     [
[1687452607.117324][124848:124851] CHIP:DMG:         InvokeResponseIB =
[1687452607.117341][124848:124851] CHIP:DMG:         {
[1687452607.117352][124848:124851] CHIP:DMG:             CommandDataIB =
[1687452607.117364][124848:124851] CHIP:DMG:             {
[1687452607.117375][124848:124851] CHIP:DMG:                 CommandPathIB =
[1687452607.117389][124848:124851] CHIP:DMG:                 {
[1687452607.117401][124848:124851] CHIP:DMG:                     EndpointId = 0x0,
[1687452607.117414][124848:124851] CHIP:DMG:                     ClusterId = 0x3e,
[1687452607.117426][124848:124851] CHIP:DMG:                     CommandId = 0x3,
[1687452607.117438][124848:124851] CHIP:DMG:                 },
[1687452607.117451][124848:124851] CHIP:DMG:        %C2%A0        
[1687452607.117462][124848:124851] CHIP:DMG:                 CommandFields =
[1687452607.117474][124848:124851] CHIP:DMG:                 {
[1687452607.117486][124848:124851] CHIP:DMG:                     0x0 = [
[1687452607.117732][124848:124851] CHIP:DMG:                             0x30, 0x82, 0x01, 0xda, 0x30, 0x82, 0x01, 0x80, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x4a, 0x55, 0x95, 0xca, 0xad, 0x8e, 0xcb, 0xd9, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x33, 0x31, 0x1b, 0x30, 0x19, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x12, 0x54, 0x50, 0x2d, 0x4c, 0x69, 0x6e, 0x6b, 0x20, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x31, 0x38, 0x38, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x31, 0x31, 0x30, 0x33, 0x31, 0x34, 0x32, 0x33, 0x34, 0x33, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x49, 0x31, 0x1b, 0x30, 0x19, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x12, 0x54, 0x50, 0x2d, 0x4c, 0x69, 0x6e, 0x6b, 0x20, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x50, 0x41, 0x49, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x31, 0x38, 0x38, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x30, 0x31, 0x30, 0x31, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x8e, 0x78, 0x82, 0x5a, 0x5a, 0xa7, 0xc4, 0xc8, 0x9e, 0xd6, 0xa8, 0x78, 0x08, 0x67, 0x32, 0x2e, 0x6a, 0xbb, 0xaa, 0x01, 0x1a, 0xee, 0xa4, 0xec, 0x26, 0xdb, 0x64, 0xd4, 0x47, 0xbe, 0xc7, 0xc3, 0x16, 0x7d, 0xb4, 0x19, 0x8a, 0x21, 0x15, 0x65, 0x7f, 0x63, 0x32, 0xc5, 0x38, 0x15, 0xc2, 0xbd, 0x8f, 0xa2, 0x52, 0x9d, 0x9e, 0xa0, 0xf8, 0xad, 0xb1, 0x42, 0xa2, 0x
[1687452607.117822][124848:124851] CHIP:DMG:                     ] (478 bytes)
[1687452607.117847][124848:124851] CHIP:DMG:                 },
[1687452607.117867][124848:124851] CHIP:DMG:             },
[1687452607.117898][124848:124851] CHIP:DMG:             
[1687452607.117916][124848:124851] CHIP:DMG:         },
[1687452607.117944][124848:124851] CHIP:DMG:         
[1687452607.117962][124848:124851] CHIP:DMG:     ],
[1687452607.117994][124848:124851] CHIP:DMG:     
[1687452607.118013][124848:124851] CHIP:DMG:     InteractionModelRevision = 1
[1687452607.118031][124848:124851] CHIP:DMG: },
[1687452607.118119][124848:124851] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1687452607.118158][124848:124851] CHIP:CTL: Received certificate chain from the device
[1687452607.118190][124848:124851] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest'
[1687452607.118230][124848:124851] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
[1687452607.118257][124848:124851] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest'
[1687452607.118275][124848:124851] CHIP:CTL: Sending request for DAC certificate
[1687452607.118330][124848:124851] CHIP:CTL: Sending Certificate Chain request to 0x7f1214012e10 device
[1687452607.118391][124848:124851] CHIP:DMG: ICR moving to [AddingComm]
[1687452607.118414][124848:124851] CHIP:DMG: ICR moving to [AddedComma]
[1687452607.118509][124848:124851] CHIP:EM: <<< [E:17873i S:44403 M:253297764] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687452607.118566][124848:124851] CHIP:IN: (S) Sending msg 253297764 on secure session with LSID: 44403
[1687452607.119252][124848:124851] CHIP:DMG: ICR moving to [CommandSen]
[1687452607.119426][124848:124851] CHIP:DMG: ICR moving to [AwaitingDe]
[1687452607.250729][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452607.431292][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452607.431527][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452607.611766][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452607.611893][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452607.703993][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452607.704145][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452607.704342][124848:124851] CHIP:EM: >>> [E:17873i S:44403 M:60129861] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687452607.704365][124848:124851] CHIP:EM: Found matching exchange: 17873i, Delegate: 0x7f121c071a18
[1687452607.704387][124848:124851] CHIP:DMG: ICR moving to [ResponseRe]
[1687452607.704424][124848:124851] CHIP:DMG: InvokeResponseMessage =
[1687452607.704440][124848:124851] CHIP:DMG: {
[1687452607.704457][124848:124851] CHIP:DMG:     suppressResponse = false,
[1687452607.704471][124848:124851] CHIP:DMG:     InvokeResponseIBs =
[1687452607.704500][124848:124851] CHIP:DMG:     [
[1687452607.704514][124848:124851] CHIP:DMG:         InvokeResponseIB =
[1687452607.704547][124848:124851] CHIP:DMG:         {
[1687452607.704566][124848:124851] CHIP:DMG:             CommandDataIB =
[1687452607.704586][124848:124851] CHIP:DMG:             {
[1687452607.704604][124848:124851] CHIP:DMG:                 CommandPathIB =
[1687452607.704624][124848:124851] CHIP:DMG:                 {
[1687452607.704644][124848:124851] CHIP:DMG:                     EndpointId = 0x0,
[1687452607.704666][124848:124851] CHIP:DMG:                     ClusterId = 0x3e,
[1687452607.704686][124848:124851] CHIP:DMG:                     CommandId = 0x3,
[1687452607.704704][124848:124851] CHIP:DMG:                 },
[1687452607.704727][124848:124851] CHIP:DMG:                 
[1687452607.704744][124848:124851] CHIP:DMG:                 CommandFields =
[1687452607.704766][124848:124851] CHIP:DMG:                 {
[1687452607.704785][124848:124851] CHIP:DMG:                     0x0 = [
[1687452607.704898][124848:124851] CHIP:DMG:                             0x30, 0x82, 0x01, 0xeb, 0x30, 0x82, 0x01, 0x90, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x50, 0x04, 0xca, 0x35, 0x9a, 0x9e, 0x85, 0x27, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x49, 0x31, 0x1b, 0x30, 0x19, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x12, 0x54, 0x50, 0x2d, 0x4c, 0x69, 0x6e, 0x6b, 0x20, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x50, 0x41, 0x49, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x31, 0x38, 0x38, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x30, 0x31, 0x30, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x31, 0x31, 0x30, 0x33, 0x31, 0x34, 0x32, 0x33, 0x34, 0x33, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x49, 0x31, 0x1b, 0x30, 0x19, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x12, 0x54, 0x50, 0x2d, 0x4c, 0x69, 0x6e, 0x6b, 0x20, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x41, 0x43, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x31, 0x31, 0x38, 0x38, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x30, 0x31, 0x30, 0x31, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x0c, 0x1d, 0xae, 0x80, 0x17, 0x17, 0xd1, 0x2f, 0xe3, 0xa6, 0x08, 0x50, 0xa2, 0x8b, 0x21, 0x03, 0xf6, 0xc2, 0x15, 0x6f, 0xe8, 0x9c, 0xa1, 0x9b, 0x59, 0xff, 0xf2, 0x2e, 0x42, 0xca, 0x25, 0x30, 0xe3, 0x10, 0xab, 0x72, 0x00, 0x
[1687452607.704958][124848:124851] CHIP:DMG:                     ] (495 bytes)
[1687452607.704976][124848:124851] CHIP:DMG:                 },
[1687452607.704994][124848:124851] CHIP:DMG:             },
[1687452607.705017][124848:124851] CHIP:DMG:             
[1687452607.705028][124848:124851] CHIP:DMG:         },
[1687452607.705054][124848:124851] CHIP:DMG:         
[1687452607.705064][124848:124851] CHIP:DMG:     ],
[1687452607.705088][124848:124851] CHIP:DMG:     
[1687452607.705100][124848:124851] CHIP:DMG:     InteractionModelRevision = 1
[1687452607.705112][124848:124851] CHIP:DMG: },
[1687452607.705166][124848:124851] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[1687452607.705190][124848:124851] CHIP:CTL: Received certificate chain from the device
[1687452607.705211][124848:124851] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest'
[1687452607.705226][124848:124851] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
[1687452607.705245][124848:124851] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest'
[1687452607.705257][124848:124851] CHIP:CTL: Sending Attestation Request to the device.
[1687452607.705270][124848:124851] CHIP:CTL: Sending Attestation request to 0x7f1214012e10 device
[1687452607.705317][124848:124851] CHIP:DMG: ICR moving to [AddingComm]
[1687452607.705332][124848:124851] CHIP:DMG: ICR moving to [AddedComma]
[1687452607.705413][124848:124851] CHIP:EM: <<< [E:17874i S:44403 M:253297765] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687452607.705434][124848:124851] CHIP:IN: (S) Sending msg 253297765 on secure session with LSID: 44403
[1687452607.705853][124848:124851] CHIP:DMG: ICR moving to [CommandSen]
[1687452607.705870][124848:124851] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information
[1687452607.705903][124848:124851] CHIP:DMG: ICR moving to [AwaitingDe]
[1687452607.790613][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452608.061527][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452608.061634][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452608.241597][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452608.241747][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452608.241886][124848:124851] CHIP:EM: >>> [E:17874i S:44403 M:60129862] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687452608.241908][124848:124851] CHIP:EM: Found matching exchange: 17874i, Delegate: 0x7f121c071f98
[1687452608.241939][124848:124851] CHIP:DMG: ICR moving to [ResponseRe]
[1687452608.241981][124848:124851] CHIP:DMG: InvokeResponseMessage =
[1687452608.241994][124848:124851] CHIP:DMG: {
[1687452608.242010][124848:124851] CHIP:DMG:     suppressResponse = false,
[1687452608.242022][124848:124851] CHIP:DMG:     InvokeResponseIBs =
[1687452608.242052][124848:124851] CHIP:DMG:     [
[1687452608.242064][124848:124851] CHIP:DMG:         InvokeResponseIB =
[1687452608.242091][124848:124851] CHIP:DMG:         {
[1687452608.242102][124848:124851] CHIP:DMG:             CommandDataIB =
[1687452608.242115][124848:124851] CHIP:DMG:             {
[1687452608.242135][124848:124851] CHIP:DMG:                 CommandPathIB =
[1687452608.242147][124848:124851] CHIP:DMG:                 {
[1687452608.242158][124848:124851] CHIP:DMG:                     EndpointId = 0x0,
[1687452608.242176][124848:124851] CHIP:DMG:                     ClusterId = 0x3e,
[1687452608.242192][124848:124851] CHIP:DMG:                     CommandId = 0x1,
[1687452608.242207][124848:124851] CHIP:DMG:                 },
[1687452608.242226][124848:124851] CHIP:DMG:                 
[1687452608.242238][124848:124851] CHIP:DMG:                 CommandFields =
[1687452608.242255][124848:124851] CHIP:DMG:                 {
[1687452608.242271][124848:124851] CHIP:DMG:                     0x0 = [
[1687452608.242355][124848:124851] CHIP:DMG:                             0x15, 0x30, 0x01, 0xeb, 0x30, 0x81, 0xe8, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x02, 0xa0, 0x81, 0xda, 0x30, 0x81, 0xd7, 0x02, 0x01, 0x03, 0x31, 0x0d, 0x30, 0x0b, 0x06, 0x09, 0x60, 0x86, 0x48, 0x01, 0x65, 0x03, 0x04, 0x02, 0x01, 0x30, 0x44, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x01, 0xa0, 0x37, 0x04, 0x35, 0x15, 0x24, 0x00, 0x01, 0x25, 0x01, 0x88, 0x11, 0x36, 0x02, 0x05, 0x01, 0x01, 0x18, 0x25, 0x03, 0x0a, 0x01, 0x2c, 0x04, 0x13, 0x43, 0x53, 0x41, 0x32, 0x32, 0x31, 0x36, 0x35, 0x4d, 0x41, 0x54, 0x34, 0x30, 0x31, 0x36, 0x35, 0x2d, 0x32, 0x34, 0x24, 0x05, 0x00, 0x24, 0x06, 0x00, 0x24, 0x07, 0x01, 0x24, 0x08, 0x02, 0x18, 0x31, 0x7d, 0x30, 0x7b, 0x02, 0x01, 0x03, 0x80, 0x14, 0xfe, 0x34, 0x3f, 0x95, 0x99, 0x47, 0x76, 0x3b, 0x61, 0xee, 0x45, 0x39, 0x13, 0x13, 0x38, 0x49, 0x4f, 0xe6, 0x7d, 0x8e, 0x30, 0x0b, 0x06, 0x09, 0x60, 0x86, 0x48, 0x01, 0x65, 0x03, 0x04, 0x02, 0x01, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x04, 0x47, 0x30, 0x45, 0x02, 0x21, 0x00, 0x89, 0x38, 0x2b, 0xe2, 0x94, 0x74, 0x5a, 0xea, 0x8c, 0x45, 0xf0, 0x5c, 0xf5, 0x8d, 0xb8, 0x41, 0xa2, 0x3e, 0x07, 0x68, 0x43, 0xdc, 0x6e, 0x36, 0xe7, 0x93, 0x99, 0x5c, 0x8f, 0xbb, 0x3d, 0x2f, 0x02, 0x20, 0x7f, 0x86, 0x94, 0xc5, 0xe3, 0x33, 0x7a, 0x5b, 0x28, 0x8f, 0xe1, 0x5c, 0x8b, 0x69, 0x2d, 0x08, 0x45, 0xd0, 0x3b, 0x9a, 0x1b, 0xc5, 0x9a, 0x3d, 0xb5, 0xd8, 0x9f, 0xf9, 0x8d, 0xb1, 0x7e, 0x29, 0x30, 0x02, 0x20, 0x25, 0x86, 0x64, 0x0e, 0x7e, 0x68, 0x0b, 0x9d, 0x5b, 0xa4, 0x60, 0x79, 0x87, 0x16, 0x35, 0x84, 0x97, 0xa8, 0xcc, 0x78, 0x86, 0x86, 0xaa, 0x41, 0xca, 0xde, 0xfc, 0xde, 0x85, 0x30, 0x7d, 0x71, 0x24, 0x03, 0x00, 0x18,
[1687452608.242395][124848:124851] CHIP:DMG:                     ] (278 bytes)
[1687452608.242405][124848:124851] CHIP:DMG:                     0x1 = [
[1687452608.242429][124848:124851] CHIP:DMG:                             0xc9, 0xed, 0x56, 0xb1, 0x00, 0x14, 0xcf, 0xe1, 0x80, 0x54, 0x23, 0xf7, 0x75, 0x14, 0xc4, 0xe9, 0xef, 0x6c, 0x0c, 0xaa, 0x5b, 0x21, 0x5b, 0x28, 0x1e, 0x9e, 0x88, 0xa6, 0xd8, 0x24, 0x2a, 0xc9, 0x3c, 0xae, 0x02, 0x5a, 0x38, 0xcc, 0xba, 0x2b, 0x13, 0x07, 0xf9, 0x1f, 0x5d, 0x5d, 0x01, 0x5b, 0xd6, 0xd0, 0x56, 0x95, 0x4d, 0x8e, 0x0e, 0x5e, 0xc9, 0x44, 0xe7, 0xc5, 0x42, 0x12, 0x1d, 0x23,
[1687452608.242447][124848:124851] CHIP:DMG:                     ] (64 bytes)
[1687452608.242455][124848:124851] CHIP:DMG:                 },
[1687452608.242465][124848:124851] CHIP:DMG:             },
[1687452608.242479][124848:124851] CHIP:DMG:             
[1687452608.242487][124848:124851] CHIP:DMG:         },
[1687452608.242501][124848:124851] CHIP:DMG:         
[1687452608.242509][124848:124851] CHIP:DMG:     ],
[1687452608.242527][124848:124851] CHIP:DMG:     
[1687452608.242535][124848:124851] CHIP:DMG:     InteractionModelRevision = 1
[1687452608.242543][124848:124851] CHIP:DMG: },
[1687452608.242582][124848:124851] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
[1687452608.242601][124848:124851] CHIP:CTL: Received Attestation Information from the device
[1687452608.242618][124848:124851] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest'
[1687452608.242629][124848:124851] CHIP:CTL: AutoCommissioner setting attestationElements buffer size 278/278
[1687452608.242656][124848:124851] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
[1687452608.242670][124848:124851] CHIP:CTL: Performing next commissioning step 'AttestationVerification'
[1687452608.242678][124848:124851] CHIP:CTL: Verifying attestation
[1687452608.289841][124848:124851] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device.
[1687452608.289921][124848:124851] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification'
[1687452608.289936][124848:124851] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest'
[1687452608.289961][124848:124851] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest'
[1687452608.289975][124848:124851] CHIP:CTL: Sending CSR request to 0x7f1214012e10 device
[1687452608.290080][124848:124851] CHIP:DMG: ICR moving to [AddingComm]
[1687452608.290115][124848:124851] CHIP:DMG: ICR moving to [AddedComma]
[1687452608.290302][124848:124851] CHIP:EM: <<< [E:17875i S:44403 M:253297766] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687452608.290360][124848:124851] CHIP:IN: (S) Sending msg 253297766 on secure session with LSID: 44403
[1687452608.291105][124848:124851] CHIP:DMG: ICR moving to [CommandSen]
[1687452608.291178][124848:124851] CHIP:CTL: Sent CSR request, waiting for the CSR
[1687452608.291281][124848:124851] CHIP:DMG: ICR moving to [AwaitingDe]
[1687452608.375209][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452609.006156][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452609.006367][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452609.231165][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452609.231292][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452609.231433][124848:124851] CHIP:EM: >>> [E:17875i S:44403 M:60129863] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687452609.231457][124848:124851] CHIP:EM: Found matching exchange: 17875i, Delegate: 0x7f121c071a18
[1687452609.231477][124848:124851] CHIP:DMG: ICR moving to [ResponseRe]
[1687452609.231524][124848:124851] CHIP:DMG: InvokeResponseMessage =
[1687452609.231532][124848:124851] CHIP:DMG: {
[1687452609.231539][124848:124851] CHIP:DMG:     suppressResponse = false,
[1687452609.231546][124848:124851] CHIP:DMG:     InvokeResponseIBs =
[1687452609.231562][124848:124851] CHIP:DMG:     [
[1687452609.231570][124848:124851] CHIP:DMG:         InvokeResponseIB =
[1687452609.231586][124848:124851] CHIP:DMG:         {
[1687452609.231595][124848:124851] CHIP:DMG:             CommandDataIB =
[1687452609.231607][124848:124851] CHIP:DMG:             {
[1687452609.231616][124848:124851] CHIP:DMG:                 CommandPathIB =
[1687452609.231631][124848:124851] CHIP:DMG:                 {
[1687452609.231642][124848:124851] CHIP:DMG:                     EndpointId = 0x0,
[1687452609.231653][124848:124851] CHIP:DMG:                     ClusterId = 0x3e,
[1687452609.231664][124848:124851] CHIP:DMG:                     CommandId = 0x5,
[1687452609.231673][124848:124851] CHIP:DMG:                 },
[1687452609.231686][124848:124851] CHIP:DMG:                 
[1687452609.231696][124848:124851] CHIP:DMG:                 CommandFields =
[1687452609.231707][124848:124851] CHIP:DMG:                 {
[1687452609.231719][124848:124851] CHIP:DMG:                     0x0 = [
[1687452609.231787][124848:124851] CHIP:DMG:                             0x15, 0x30, 0x01, 0xce, 0x30, 0x81, 0xcb, 0x30, 0x70, 0x02, 0x01, 0x00, 0x30, 0x0e, 0x31, 0x0c, 0x30, 0x0a, 0x06, 0x03, 0x55, 0x04, 0x0a, 0x0c, 0x03, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x01, 0x80, 0xae, 0x4f, 0x36, 0x64, 0x52, 0x7a, 0x15, 0x0a, 0x07, 0x01, 0xbc, 0x74, 0x92, 0xbf, 0x75, 0x6d, 0x2a, 0x39, 0xbc, 0xcb, 0x9f, 0x32, 0x73, 0x0a, 0x26, 0xd4, 0xe3, 0xbe, 0x6f, 0x92, 0x1b, 0x67, 0x66, 0x18, 0x86, 0xf5, 0x11, 0x21, 0xcb, 0xcc, 0x10, 0x05, 0xef, 0x81, 0xb8, 0xef, 0xc2, 0x51, 0xed, 0x89, 0x22, 0x7d, 0x83, 0xa6, 0xe7, 0x40, 0x63, 0x1f, 0x9c, 0xc0, 0xfb, 0xe3, 0xa0, 0x00, 0x30, 0x0c, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x05, 0x00, 0x03, 0x49, 0x00, 0x30, 0x46, 0x02, 0x21, 0x00, 0xf6, 0xb1, 0x6d, 0x87, 0xa6, 0xb7, 0x59, 0xdf, 0x93, 0x04, 0x13, 0x3a, 0x2e, 0x51, 0x01, 0xb4, 0x0e, 0xeb, 0x24, 0xca, 0x0d, 0xa2, 0x8f, 0xd7, 0x26, 0x1e, 0xeb, 0x5f, 0x33, 0x14, 0x37, 0xb6, 0x02, 0x21, 0x00, 0xf3, 0x23, 0x48, 0x23, 0xa4, 0x08, 0xeb, 0x68, 0x26, 0x7b, 0x25, 0x27, 0xa0, 0xf7, 0xc1, 0x9f, 0x96, 0x74, 0xa2, 0x91, 0x73, 0x28, 0x40, 0x99, 0xcd, 0x87, 0xff, 0xad, 0x5b, 0xad, 0x32, 0xff, 0x30, 0x02, 0x20, 0xc4, 0x53, 0xe4, 0x80, 0x93, 0xd0, 0x93, 0x3b, 0x3e, 0xf7, 0xdd, 0xc8, 0x00, 0xde, 0x48, 0x35, 0x94, 0x51, 0x0d, 0x7c, 0xcc, 0x66, 0xd1, 0xc3, 0xc6, 0x64, 0xd6, 0x17, 0x82, 0x77, 0x4e, 0xfb, 0x18,
[1687452609.231824][124848:124851] CHIP:DMG:                     ] (246 bytes)
[1687452609.231833][124848:124851] CHIP:DMG:                     0x1 = [
[1687452609.231876][124848:124851] CHIP:DMG:                             0x4d, 0xf4, 0x88, 0x4b, 0x7f, 0xba, 0x85, 0x5d, 0xb8, 0x3b, 0xd8, 0x80, 0xbb, 0x4a, 0x3b, 0xf8, 0x09, 0xbd, 0x2a, 0x4c, 0x26, 0xf0, 0xeb, 0xd2, 0x41, 0x0b, 0x90, 0xde, 0x15, 0x31, 0x6d, 0x56, 0x32, 0x58, 0xcd, 0xf2, 0x04, 0x4d, 0xfe, 0xe6, 0xe1, 0x8a, 0xef, 0xa8, 0x2f, 0x2b, 0x63, 0xc7, 0xba, 0x1d, 0x63, 0xfc, 0x3c, 0xd4, 0x16, 0xdf, 0x9e, 0xbe, 0xc3, 0x1b, 0xea, 0x99, 0xcf, 0x69,
[1687452609.231900][124848:124851] CHIP:DMG:                     ] (64 bytes)
[1687452609.231916][124848:124851] CHIP:DMG:                 },
[1687452609.231951][124848:124851] CHIP:DMG:             },
[1687452609.231965][124848:124851] CHIP:DMG:             
[1687452609.231973][124848:124851] CHIP:DMG:         },
[1687452609.231988][124848:124851] CHIP:DMG:         
[1687452609.231996][124848:124851] CHIP:DMG:     ],
[1687452609.232012][124848:124851] CHIP:DMG:     
[1687452609.232021][124848:124851] CHIP:DMG:     InteractionModelRevision = 1
[1687452609.232028][124848:124851] CHIP:DMG: },
[1687452609.232070][124848:124851] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005
[1687452609.232090][124848:124851] CHIP:CTL: Received certificate signing request from the device
[1687452609.232107][124848:124851] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest'
[1687452609.232117][124848:124851] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR'
[1687452609.232130][124848:124851] CHIP:CTL: Performing next commissioning step 'ValidateCSR'
[1687452609.239406][124848:124851] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR'
[1687452609.239429][124848:124851] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain'
[1687452609.239437][124848:124851] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain'
[1687452609.239445][124848:124851] CHIP:CTL: Getting certificate chain for the device from the issuer
[1687452609.243630][124848:124851] CHIP:CTL: Verifying Certificate Signing Request
[1687452609.245995][124848:124851] CHIP:CTL: Generating NOC
[1687452609.246334][124848:124851] CHIP:CTL: Providing certificate chain to the commissioner
[1687452609.246364][124848:124851] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status src/controller/ExampleOperationalCredentialsIssuer.cpp:396: Success
[1687452609.246388][124848:124851] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain'
[1687452609.246517][124848:124851] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert'
[1687452609.246529][124848:124851] CHIP:CTL: Sending root certificate to the device
[1687452609.246583][124848:124851] CHIP:DMG: ICR moving to [AddingComm]
[1687452609.246600][124848:124851] CHIP:DMG: ICR moving to [AddedComma]
[1687452609.246703][124848:124851] CHIP:EM: <<< [E:17876i S:44403 M:253297767] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687452609.246739][124848:124851] CHIP:IN: (S) Sending msg 253297767 on secure session with LSID: 44403
[1687452609.247555][124848:124851] CHIP:DMG: ICR moving to [CommandSen]
[1687452609.247678][124848:124851] CHIP:CTL: Sent root certificate to the device
[1687452609.248271][124848:124851] CHIP:DMG: ICR moving to [AwaitingDe]
[1687452609.321031][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452609.410599][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452609.771333][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452609.771536][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452609.771701][124848:124851] CHIP:EM: >>> [E:17876i S:44403 M:60129864] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687452609.771725][124848:124851] CHIP:EM: Found matching exchange: 17876i, Delegate: 0x7f121c071f98
[1687452609.771745][124848:124851] CHIP:DMG: ICR moving to [ResponseRe]
[1687452609.771778][124848:124851] CHIP:DMG: InvokeResponseMessage =
[1687452609.771788][124848:124851] CHIP:DMG: {
[1687452609.771799][124848:124851] CHIP:DMG:     suppressResponse = false,
[1687452609.771809][124848:124851] CHIP:DMG:     InvokeResponseIBs =
[1687452609.771826][124848:124851] CHIP:DMG:     [
[1687452609.771835][124848:124851] CHIP:DMG:         InvokeResponseIB =
[1687452609.771852][124848:124851] CHIP:DMG:         {
[1687452609.771964][124848:124851] CHIP:DMG:             CommandStatusIB =
[1687452609.772051][124848:124851] CHIP:DMG:             {
[1687452609.772072][124848:124851] CHIP:DMG:                 CommandPathIB =
[1687452609.772123][124848:124851] CHIP:DMG:                 {
[1687452609.772171][124848:124851] CHIP:DMG:                     EndpointId = 0x0,
[1687452609.772196][124848:124851] CHIP:DMG:                     ClusterId = 0x3e,
[1687452609.772230][124848:124851] CHIP:DMG:                     CommandId = 0xb,
[1687452609.772275][124848:124851] CHIP:DMG:                 },
[1687452609.772308][124848:124851] CHIP:DMG:                 
[1687452609.772452][124848:124851] CHIP:DMG:                 StatusIB =
[1687452609.772474][124848:124851] CHIP:DMG:                 {
[1687452609.772493][124848:124851] CHIP:DMG:                     status = 0x00 (SUCCESS),
[1687452609.772511][124848:124851] CHIP:DMG:                 },
[1687452609.772537][124848:124851] CHIP:DMG:                 
[1687452609.772553][124848:124851] CHIP:DMG:             },
[1687452609.772579][124848:124851] CHIP:DMG:             
[1687452609.772594][124848:124851] CHIP:DMG:         },
[1687452609.772621][124848:124851] CHIP:DMG:         
[1687452609.772635][124848:124851] CHIP:DMG:     ],
[1687452609.772659][124848:124851] CHIP:DMG:     
[1687452609.772674][124848:124851] CHIP:DMG:     InteractionModelRevision = 1
[1687452609.772687][124848:124851] CHIP:DMG: },
[1687452609.772754][124848:124851] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0
[1687452609.772779][124848:124851] CHIP:CTL: Device confirmed that it has received the root certificate
[1687452609.772804][124848:124851] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert'
[1687452609.772819][124848:124851] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC'
[1687452609.772840][124848:124851] CHIP:CTL: Performing next commissioning step 'SendNOC'
[1687452609.772926][124848:124851] CHIP:DMG: ICR moving to [AddingComm]
[1687452609.772946][124848:124851] CHIP:DMG: ICR moving to [AddedComma]
[1687452609.773014][124848:124851] CHIP:EM: <<< [E:17877i S:44403 M:253297768] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687452609.773034][124848:124851] CHIP:IN: (S) Sending msg 253297768 on secure session with LSID: 44403
[1687452609.773541][124848:124851] CHIP:DMG: ICR moving to [CommandSen]
[1687452609.773593][124848:124851] CHIP:CTL: Sent operational certificate to the device
[1687452609.773650][124848:124851] CHIP:DMG: ICR moving to [AwaitingDe]
[1687452609.951173][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452610.130522][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452610.220512][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452611.211192][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452611.211290][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452611.211422][124848:124851] CHIP:EM: >>> [E:17877i S:44403 M:60129865] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687452611.211442][124848:124851] CHIP:EM: Found matching exchange: 17877i, Delegate: 0x7f121c071a18
[1687452611.211459][124848:124851] CHIP:DMG: ICR moving to [ResponseRe]
[1687452611.211490][124848:124851] CHIP:DMG: InvokeResponseMessage =
[1687452611.211500][124848:124851] CHIP:DMG: {
[1687452611.211510][124848:124851] CHIP:DMG:     suppressResponse = false,
[1687452611.211518][124848:124851] CHIP:DMG:     InvokeResponseIBs =
[1687452611.211535][124848:124851] CHIP:DMG:     [
[1687452611.211543][124848:124851] CHIP:DMG:         InvokeResponseIB =
[1687452611.211562][124848:124851] CHIP:DMG:         {
[1687452611.211570][124848:124851] CHIP:DMG:             CommandDataIB =
[1687452611.211582][124848:124851] CHIP:DMG:             {
[1687452611.211593][124848:124851] CHIP:DMG:                 CommandPathIB =
[1687452611.211604][124848:124851] CHIP:DMG:                 {
[1687452611.211616][124848:124851] CHIP:DMG:                     EndpointId = 0x0,
[1687452611.211627][124848:124851] CHIP:DMG:                     ClusterId = 0x3e,
[1687452611.211637][124848:124851] CHIP:DMG:                     CommandId = 0x8,
[1687452611.211646][124848:124851] CHIP:DMG:                 },
[1687452611.211658][124848:124851] CHIP:DMG:                 
[1687452611.211667][124848:124851] CHIP:DMG:                 CommandFields =
[1687452611.211681][124848:124851] CHIP:DMG:                 {
[1687452611.211693][124848:124851] CHIP:DMG:                     0x0 = 0,
[1687452611.211704][124848:124851] CHIP:DMG:                     0x1 = 1,
[1687452611.211714][124848:124851] CHIP:DMG:                 },
[1687452611.211724][124848:124851] CHIP:DMG:             },
[1687452611.211737][124848:124851] CHIP:DMG:             
[1687452611.211746][124848:124851] CHIP:DMG:         },
[1687452611.211760][124848:124851] CHIP:DMG:         
[1687452611.211768][124848:124851] CHIP:DMG:     ],
[1687452611.211783][124848:124851] CHIP:DMG:     
[1687452611.211792][124848:124851] CHIP:DMG:     InteractionModelRevision = 1
[1687452611.211800][124848:124851] CHIP:DMG: },
[1687452611.211839][124848:124851] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
[1687452611.211881][124848:124851] CHIP:CTL: Device returned status 0 on receiving the NOC
[1687452611.211895][124848:124851] CHIP:CTL: Operational credentials provisioned on device 0x7f1214012e10
[1687452611.211904][124848:124851] CHIP:TOO: Secure Pairing Success
[1687452611.211911][124848:124851] CHIP:TOO: CASE establishment successful
[1687452611.211926][124848:124851] CHIP:CTL: Successfully finished commissioning step 'SendNOC'
[1687452611.211936][124848:124851] CHIP:CTL: No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks
[1687452611.211945][124848:124851] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'WiFiNetworkSetup'
[1687452611.211958][124848:124851] CHIP:CTL: Performing next commissioning step 'WiFiNetworkSetup'
[1687452611.211998][124848:124851] CHIP:DMG: ICR moving to [AddingComm]
[1687452611.212013][124848:124851] CHIP:DMG: ICR moving to [AddedComma]
[1687452611.212069][124848:124851] CHIP:EM: <<< [E:17878i S:44403 M:253297769] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687452611.212088][124848:124851] CHIP:IN: (S) Sending msg 253297769 on secure session with LSID: 44403
[1687452611.212455][124848:124851] CHIP:DMG: ICR moving to [CommandSen]
[1687452611.212577][124848:124851] CHIP:DMG: ICR moving to [AwaitingDe]
[1687452611.301524][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452611.303744][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452611.303826][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452611.303982][124848:124851] CHIP:EM: >>> [E:17878i S:44403 M:60129866] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687452611.304008][124848:124851] CHIP:EM: Found matching exchange: 17878i, Delegate: 0x7f121c071f98
[1687452611.304032][124848:124851] CHIP:DMG: ICR moving to [ResponseRe]
[1687452611.304072][124848:124851] CHIP:DMG: InvokeResponseMessage =
[1687452611.304084][124848:124851] CHIP:DMG: {
[1687452611.304099][124848:124851] CHIP:DMG:     suppressResponse = false,
[1687452611.304114][124848:124851] CHIP:DMG:     InvokeResponseIBs =
[1687452611.304144][124848:124851] CHIP:DMG:     [
[1687452611.304154][124848:124851] CHIP:DMG:         InvokeResponseIB =
[1687452611.304178][124848:124851] CHIP:DMG:         {
[1687452611.304188][124848:124851] CHIP:DMG:             CommandDataIB =
[1687452611.304202][124848:124851] CHIP:DMG:             {
[1687452611.304215][124848:124851] CHIP:DMG:                 CommandPathIB =
[1687452611.304230][124848:124851] CHIP:DMG:                 {
[1687452611.304242][124848:124851] CHIP:DMG:                     EndpointId = 0x0,
[1687452611.304253][124848:124851] CHIP:DMG:                     ClusterId = 0x31,
[1687452611.304264][124848:124851] CHIP:DMG:                     CommandId = 0x5,
[1687452611.304273][124848:124851] CHIP:DMG:                 },
[1687452611.304285][124848:124851] CHIP:DMG:                 
[1687452611.304295][124848:124851] CHIP:DMG:                 CommandFields =
[1687452611.304306][124848:124851] CHIP:DMG:                 {
[1687452611.304323][124848:124851] CHIP:DMG:                     0x0 = 0,
[1687452611.304340][124848:124851] CHIP:DMG:                     0x2 = 0,
[1687452611.304355][124848:124851] CHIP:DMG:                 },
[1687452611.304367][124848:124851] CHIP:DMG:             },
[1687452611.304388][124848:124851] CHIP:DMG:             
[1687452611.304399][124848:124851] CHIP:DMG:         },
[1687452611.304420][124848:124851] CHIP:DMG:         
[1687452611.304431][124848:124851] CHIP:DMG:     ],
[1687452611.304455][124848:124851] CHIP:DMG:     
[1687452611.304465][124848:124851] CHIP:DMG:     InteractionModelRevision = 1
[1687452611.304476][124848:124851] CHIP:DMG: },
[1687452611.304523][124848:124851] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
[1687452611.305367][124848:124851] CHIP:CTL: Received NetworkConfig response, networkingStatus=0
[1687452611.305393][124848:124851] CHIP:CTL: Successfully finished commissioning step 'WiFiNetworkSetup'
[1687452611.305403][124848:124851] CHIP:CTL: Commissioning stage next step: 'WiFiNetworkSetup' -> 'FailsafeBeforeWiFiEnable'
[1687452611.305416][124848:124851] CHIP:CTL: Performing next commissioning step 'FailsafeBeforeWiFiEnable'
[1687452611.305432][124848:124851] CHIP:CTL: Arming failsafe (132 seconds)
[1687452611.305462][124848:124851] CHIP:DMG: ICR moving to [AddingComm]
[1687452611.305473][124848:124851] CHIP:DMG: ICR moving to [AddedComma]
[1687452611.305521][124848:124851] CHIP:EM: <<< [E:17879i S:44403 M:253297770] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687452611.305536][124848:124851] CHIP:IN: (S) Sending msg 253297770 on secure session with LSID: 44403
[1687452611.305991][124848:124851] CHIP:DMG: ICR moving to [CommandSen]
[1687452611.306030][124848:124851] CHIP:DMG: ICR moving to [AwaitingDe]
[1687452611.390404][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452611.392744][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452611.392963][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452611.393084][124848:124851] CHIP:EM: >>> [E:17879i S:44403 M:60129867] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687452611.393104][124848:124851] CHIP:EM: Found matching exchange: 17879i, Delegate: 0x7f121c071a18
[1687452611.393119][124848:124851] CHIP:DMG: ICR moving to [ResponseRe]
[1687452611.393151][124848:124851] CHIP:DMG: InvokeResponseMessage =
[1687452611.393158][124848:124851] CHIP:DMG: {
[1687452611.393165][124848:124851] CHIP:DMG:     suppressResponse = false,
[1687452611.393172][124848:124851] CHIP:DMG:     InvokeResponseIBs =
[1687452611.393186][124848:124851] CHIP:DMG:     [
[1687452611.393198][124848:124851] CHIP:DMG:         InvokeResponseIB =
[1687452611.393214][124848:124851] CHIP:DMG:         {
[1687452611.393227][124848:124851] CHIP:DMG:             CommandDataIB =
[1687452611.393243][124848:124851] CHIP:DMG:             {
[1687452611.393258][124848:124851] CHIP:DMG:                 CommandPathIB =
[1687452611.393274][124848:124851] CHIP:DMG:                 {
[1687452611.393290][124848:124851] CHIP:DMG:                     EndpointId = 0x0,
[1687452611.393307][124848:124851] CHIP:DMG:                     ClusterId = 0x30,
[1687452611.393322][124848:124851] CHIP:DMG:                     CommandId = 0x1,
[1687452611.393336][124848:124851] CHIP:DMG:                 },
[1687452611.393352][124848:124851] CHIP:DMG:                 
[1687452611.393366][124848:124851] CHIP:DMG:                 CommandFields =
[1687452611.393381][124848:124851] CHIP:DMG:                 {
[1687452611.393397][124848:124851] CHIP:DMG:                     0x0 = 0,
[1687452611.393415][124848:124851] CHIP:DMG:                     0x1 = "" (0 chars),
[1687452611.393431][124848:124851] CHIP:DMG:                 },
[1687452611.393443][124848:124851] CHIP:DMG:             },
[1687452611.393464][124848:124851] CHIP:DMG:             
[1687452611.393474][124848:124851] CHIP:DMG:         },
[1687452611.393492][124848:124851] CHIP:DMG:         
[1687452611.393500][124848:124851] CHIP:DMG:     ],
[1687452611.393527][124848:124851] CHIP:DMG:     
[1687452611.393537][124848:124851] CHIP:DMG:     InteractionModelRevision = 1
[1687452611.393547][124848:124851] CHIP:DMG: },
[1687452611.393596][124848:124851] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1687452611.393621][124848:124851] CHIP:CTL: Received ArmFailSafe response errorCode=0
[1687452611.393639][124848:124851] CHIP:CTL: Successfully finished commissioning step 'FailsafeBeforeWiFiEnable'
[1687452611.393650][124848:124851] CHIP:CTL: Commissioning stage next step: 'FailsafeBeforeWiFiEnable' -> 'WiFiNetworkEnable'
[1687452611.393664][124848:124851] CHIP:CTL: Setting wifi connection time min = 20
[1687452611.393679][124848:124851] CHIP:CTL: Performing next commissioning step 'WiFiNetworkEnable'
[1687452611.393726][124848:124851] CHIP:DMG: ICR moving to [AddingComm]
[1687452611.393743][124848:124851] CHIP:DMG: ICR moving to [AddedComma]
[1687452611.393804][124848:124851] CHIP:EM: <<< [E:17880i S:44403 M:253297771] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687452611.393826][124848:124851] CHIP:IN: (S) Sending msg 253297771 on secure session with LSID: 44403
[1687452611.394073][124848:124851] CHIP:DMG: ICR moving to [CommandSen]
[1687452611.394122][124848:124851] CHIP:DMG: ICR moving to [AwaitingDe]
[1687452611.479303][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452612.282310][124848:124851] CHIP:CTL: Commissioning discovery over BLE failed: src/platform/Linux/bluez/ChipDeviceScanner.cpp:175: CHIP Error 0x00000032: Timeout
[1687452612.282387][124848:124851] CHIP:-: src/platform/Linux/bluez/ChipDeviceScanner.cpp:175: CHIP Error 0x00000032: Timeout at src/controller/SetUpCodePairer.cpp:323
[1687452612.282442][124848:124851] CHIP:BLE: BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:175: CHIP Error 0x00000032: Timeout
[1687452613.955670][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452613.955786][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452616.520570][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452616.568147][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452616.568958][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452616.569246][124848:124851] CHIP:EM: >>> [E:17880i S:44403 M:60129868] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687452616.569301][124848:124851] CHIP:EM: Found matching exchange: 17880i, Delegate: 0x7f121c071f98
[1687452616.569345][124848:124851] CHIP:DMG: ICR moving to [ResponseRe]
[1687452616.569424][124848:124851] CHIP:DMG: InvokeResponseMessage =
[1687452616.569446][124848:124851] CHIP:DMG: {
[1687452616.569478][124848:124851] CHIP:DMG:     suppressResponse = false,
[1687452616.569499][124848:124851] CHIP:DMG:     InvokeResponseIBs =
[1687452616.569541][124848:124851] CHIP:DMG:     [
[1687452616.569566][124848:124851] CHIP:DMG:         InvokeResponseIB =
[1687452616.569614][124848:124851] CHIP:DMG:         {
[1687452616.569638][124848:124851] CHIP:DMG:             CommandDataIB =
[1687452616.569664][124848:124851] CHIP:DMG:             {
[1687452616.569686][124848:124851] CHIP:DMG:                 CommandPathIB =
[1687452616.569715][124848:124851] CHIP:DMG:                 {
[1687452616.569753][124848:124851] CHIP:DMG:                     EndpointId = 0x0,
[1687452616.569781][124848:124851] CHIP:DMG:                     ClusterId = 0x31,
[1687452616.569814][124848:124851] CHIP:DMG:                     CommandId = 0x7,
[1687452616.569840][124848:124851] CHIP:DMG:                 },
[1687452616.569872][124848:124851] CHIP:DMG:                 
[1687452616.569900][124848:124851] CHIP:DMG:                 CommandFields =
[1687452616.569923][124848:124851] CHIP:DMG:                 {
[1687452616.569946][124848:124851] CHIP:DMG:                     0x0 = 0,
[1687452616.569997][124848:124851] CHIP:DMG:                     0x2 = NULL
[1687452616.570035][124848:124851] CHIP:DMG:                 },
[1687452616.570057][124848:124851] CHIP:DMG:             },
[1687452616.570094][124848:124851] CHIP:DMG:             
[1687452616.570114][124848:124851] CHIP:DMG:         },
[1687452616.570140][124848:124851] CHIP:DMG:         
[1687452616.570154][124848:124851] CHIP:DMG:     ],
[1687452616.570184][124848:124851] CHIP:DMG:     
[1687452616.570200][124848:124851] CHIP:DMG:     InteractionModelRevision = 1
[1687452616.570215][124848:124851] CHIP:DMG: },
[1687452616.570306][124848:124851] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007
[1687452616.570357][124848:124851] CHIP:CTL: Received ConnectNetwork response, networkingStatus=0
[1687452616.570396][124848:124851] CHIP:CTL: Successfully finished commissioning step 'WiFiNetworkEnable'
[1687452616.570425][124848:124851] CHIP:CTL: Commissioning stage next step: 'WiFiNetworkEnable' -> 'FindOperational'
[1687452616.570459][124848:124851] CHIP:CTL: Performing next commissioning step 'FindOperational'
[1687452616.570475][124848:124851] CHIP:CSM: FindOrEstablishSession: PeerId = [1:000000000000A219]
[1687452616.570495][124848:124851] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1687452616.570538][124848:124851] CHIP:DIS: OperationalSessionSetup[1:000000000000A219]: State change 1 --> 2
[1687452616.571152][124848:124851] CHIP:DMG: ICR moving to [AwaitingDe]
[1687452616.770875][124848:124851] CHIP:DIS: Checking node lookup status after 201 ms
[1687452619.265913][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452621.741998][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452621.742248][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452624.440940][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452626.917726][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452626.917846][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452629.616637][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452632.092342][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452632.092493][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452632.951991][124848:124851] CHIP:DIS: Timeout waiting for mDNS resolution.
[1687452634.657278][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452637.179756][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452637.179964][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452639.743137][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452642.218824][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452642.218979][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452644.782981][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452647.259407][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452647.259530][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452647.575946][124848:124851] CHIP:DIS: Timeout waiting for mDNS resolution.
[1687452649.824605][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452652.300762][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452652.300904][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452654.910774][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452657.385939][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452657.386187][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452659.950321][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452661.572108][124848:124851] CHIP:DIS: Checking node lookup status after 45002 ms
[1687452661.572166][124848:124851] CHIP:DIS: OperationalSessionSetup[1:000000000000A219]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
[1687452661.572174][124848:124851] CHIP:DIS: Retrying operational DNS-SD discovery. Attempts remaining: 2
[1687452661.572580][124848:124851] CHIP:CTL: Session establishment failed for <000000000000A219, 1>, error: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout.  Next retry expected to get a response to Sigma1 or fail within 60 seconds
[1687452661.572616][124848:124851] CHIP:CTL: Arming failsafe (120 seconds)
[1687452661.572704][124848:124851] CHIP:DMG: ICR moving to [AddingComm]
[1687452661.572720][124848:124851] CHIP:DMG: ICR moving to [AddedComma]
[1687452661.572835][124848:124851] CHIP:EM: <<< [E:17881i S:44403 M:253297772] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687452661.572874][124848:124851] CHIP:IN: (S) Sending msg 253297772 on secure session with LSID: 44403
[1687452661.573430][124848:124851] CHIP:DMG: ICR moving to [CommandSen]
[1687452661.661895][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452661.663849][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452661.664045][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452661.664367][124848:124851] CHIP:EM: >>> [E:17881i S:44403 M:60129869] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687452661.664405][124848:124851] CHIP:EM: Found matching exchange: 17881i, Delegate: 0x7f121c071a18
[1687452661.664444][124848:124851] CHIP:DMG: ICR moving to [ResponseRe]
[1687452661.664538][124848:124851] CHIP:DMG: InvokeResponseMessage =
[1687452661.664561][124848:124851] CHIP:DMG: {
[1687452661.664585][124848:124851] CHIP:DMG:     suppressResponse = false,
[1687452661.664610][124848:124851] CHIP:DMG:     InvokeResponseIBs =
[1687452661.664654][124848:124851] CHIP:DMG:     [
[1687452661.664671][124848:124851] CHIP:DMG:         InvokeResponseIB =
[1687452661.664715][124848:124851] CHIP:DMG:         {
[1687452661.664734][124848:124851] CHIP:DMG:             CommandDataIB =
[1687452661.664761][124848:124851] CHIP:DMG:             {
[1687452661.664785][124848:124851] CHIP:DMG:                 CommandPathIB =
[1687452661.664816][124848:124851] CHIP:DMG:                 {
[1687452661.664842][124848:124851] CHIP:DMG:                     EndpointId = 0x0,
[1687452661.664867][124848:124851] CHIP:DMG:                     ClusterId = 0x30,
[1687452661.664891][124848:124851] CHIP:DMG:                     CommandId = 0x1,
[1687452661.664914][124848:124851] CHIP:DMG:                 },
[1687452661.664941][124848:124851] CHIP:DMG:                 
[1687452661.664963][124848:124851] CHIP:DMG:                 CommandFields =
[1687452661.664989][124848:124851] CHIP:DMG:                 {
[1687452661.665019][124848:124851] CHIP:DMG:                     0x0 = 0,
[1687452661.665049][124848:124851] CHIP:DMG:                     0x1 = "" (0 chars),
[1687452661.665100][124848:124851] CHIP:DMG:                 },
[1687452661.665113][124848:124851] CHIP:DMG:             },
[1687452661.665135][124848:124851] CHIP:DMG:             
[1687452661.665146][124848:124851] CHIP:DMG:         },
[1687452661.665168][124848:124851] CHIP:DMG:         
[1687452661.665179][124848:124851] CHIP:DMG:     ],
[1687452661.665202][124848:124851] CHIP:DMG:     
[1687452661.665213][124848:124851] CHIP:DMG:     InteractionModelRevision = 1
[1687452661.665226][124848:124851] CHIP:DMG: },
[1687452661.665305][124848:124851] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1687452661.665330][124848:124851] CHIP:CTL: Status of extending fail-safe for CASE retry: 0
[1687452661.665363][124848:124851] CHIP:DMG: ICR moving to [AwaitingDe]
[1687452661.772628][124848:124851] CHIP:DIS: Checking node lookup status after 200 ms
[1687452664.227600][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452666.702503][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452666.702616][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452669.267403][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452671.744272][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452671.744380][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452674.308755][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452676.784292][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452676.784495][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452679.348665][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452681.825275][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452681.825496][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452684.390052][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452686.865185][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452686.865383][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452689.429427][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452691.907434][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452691.907665][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452692.576205][124848:124851] CHIP:DIS: Timeout waiting for mDNS resolution.
[1687452694.471086][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452696.946584][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452696.946696][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452699.510715][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452702.031830][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452702.032022][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452704.596406][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452706.574555][124848:124851] CHIP:DIS: Checking node lookup status after 45002 ms
[1687452706.574604][124848:124851] CHIP:DIS: OperationalSessionSetup[1:000000000000A219]: operational discovery failed: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout
[1687452706.574612][124848:124851] CHIP:DIS: Retrying operational DNS-SD discovery. Attempts remaining: 1
[1687452706.574808][124848:124851] CHIP:CTL: Session establishment failed for <000000000000A219, 1>, error: src/lib/address_resolve/AddressResolve_DefaultImpl.cpp:119: CHIP Error 0x00000032: Timeout.  Next retry expected to get a response to Sigma1 or fail within 60 seconds
[1687452706.574825][124848:124851] CHIP:CTL: Arming failsafe (120 seconds)
[1687452706.574868][124848:124851] CHIP:DMG: ICR moving to [AddingComm]
[1687452706.574882][124848:124851] CHIP:DMG: ICR moving to [AddedComma]
[1687452706.574958][124848:124851] CHIP:EM: <<< [E:17882i S:44403 M:253297773] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest)
[1687452706.574979][124848:124851] CHIP:IN: (S) Sending msg 253297773 on secure session with LSID: 44403
[1687452706.575309][124848:124851] CHIP:DMG: ICR moving to [CommandSen]
[1687452706.666098][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452706.670371][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452706.670718][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452706.670986][124848:124851] CHIP:EM: >>> [E:17882i S:44403 M:60129870] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1687452706.671025][124848:124851] CHIP:EM: Found matching exchange: 17882i, Delegate: 0x7f121c071a18
[1687452706.671064][124848:124851] CHIP:DMG: ICR moving to [ResponseRe]
[1687452706.671130][124848:124851] CHIP:DMG: InvokeResponseMessage =
[1687452706.671149][124848:124851] CHIP:DMG: {
[1687452706.671173][124848:124851] CHIP:DMG:     suppressResponse = false,
[1687452706.671195][124848:124851] CHIP:DMG:     InvokeResponseIBs =
[1687452706.671236][124848:124851] CHIP:DMG:     [
[1687452706.671261][124848:124851] CHIP:DMG:         InvokeResponseIB =
[1687452706.671312][124848:124851] CHIP:DMG:         {
[1687452706.671331][124848:124851] CHIP:DMG:             CommandDataIB =
[1687452706.671360][124848:124851] CHIP:DMG:             {
[1687452706.671395][124848:124851] CHIP:DMG:                 CommandPathIB =
[1687452706.671460][124848:124851] CHIP:DMG:                 {
[1687452706.671484][124848:124851] CHIP:DMG:                     EndpointId = 0x0,
[1687452706.671512][124848:124851] CHIP:DMG:                     ClusterId = 0x30,
[1687452706.671532][124848:124851] CHIP:DMG:                     CommandId = 0x1,
[1687452706.671549][124848:124851] CHIP:DMG:                 },
[1687452706.671577][124848:124851] CHIP:DMG:                 
[1687452706.671599][124848:124851] CHIP:DMG:                 CommandFields =
[1687452706.671626][124848:124851] CHIP:DMG:                 {
[1687452706.671656][124848:124851] CHIP:DMG:                     0x0 = 0,
[1687452706.671688][124848:124851] CHIP:DMG:                     0x1 = "" (0 chars),
[1687452706.671715][124848:124851] CHIP:DMG:                 },
[1687452706.671745][124848:124851] CHIP:DMG:             },
[1687452706.671787][124848:124851] CHIP:DMG:             
[1687452706.671804][124848:124851] CHIP:DMG:         },
[1687452706.671850][124848:124851] CHIP:DMG:         
[1687452706.671905][124848:124851] CHIP:DMG:     ],
[1687452706.671947][124848:124851] CHIP:DMG:     
[1687452706.671972][124848:124851] CHIP:DMG:     InteractionModelRevision = 1
[1687452706.671990][124848:124851] CHIP:DMG: },
[1687452706.672078][124848:124851] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1687452706.672152][124848:124851] CHIP:CTL: Status of extending fail-safe for CASE retry: 0
[1687452706.672217][124848:124851] CHIP:DMG: ICR moving to [AwaitingDe]
[1687452706.774521][124848:124851] CHIP:DIS: Checking node lookup status after 200 ms
[1687452709.231716][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452711.707681][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452711.707803][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452714.272973][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452716.748325][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452716.748437][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452719.312930][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16387
[1687452721.790439][124848:124850] CHIP:DL: Indication received, conn = 0x7f121c06fff0
[1687452721.790644][124848:124851] CHIP:DL: HandlePlatformSpecificBLEEvent 16389
[1687452721.918195][124848:124848] CHIP:CTL: Shutting down the commissioner
[1687452721.918268][124848:124848] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687452721.918398][124848:124848] CHIP:DIS: Closing all BLE connections
[1687452721.918423][124848:124848] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1687452721.918462][124848:124848] CHIP:BLE: CancelBleIncompleteConnection() failed, err = src/platform/Linux/BLEManagerImpl.cpp:732: CHIP Error 0x0000002D: Not Implemented
[1687452721.918493][124848:124848] CHIP:IN: Clearing BLE pending packets.
[1687452721.918976][124848:124848] CHIP:BLE: Auto-closing end point's BLE connection.
[1687452721.919001][124848:124848] CHIP:DL: Closing BLE GATT connection (con 0x7f121c06fff0)
[1687452721.919083][124848:124850] CHIP:DL: BluezDisconnect peer=48:22:54:5F:2B:F3
[1687452723.821825][124848:124848] CHIP:IN: SecureSession[0x7f121400f400]: MarkForEviction Type:1 LSID:44403
[1687452723.821861][124848:124848] CHIP:SC: SecureSession[0x7f121400f400, LSID:44403]: State change 'kActive' --> 'kPendingEviction'
[1687452723.821904][124848:124848] CHIP:IN: SecureSession[0x7f121400f400]: Released - Type:1 LSID:44403
[1687452723.821926][124848:124848] CHIP:CTL: Shutting down the controller
[1687452723.821946][124848:124848] CHIP:DIS: OperationalSessionSetup[1:000000000000A219]: Cancelling incomplete address resolution as device is being deleted.
[1687452723.821988][124848:124848] CHIP:CTL: Device connection failed. Error src/app/OperationalSessionSetup.cpp:450: CHIP Error 0x00000074: The operation has been cancelled
[1687452723.822007][124848:124848] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1687452723.822026][124848:124848] CHIP:FP: Forgetting fabric 0x1
[1687452723.822045][124848:124848] CHIP:TS: Pending Last Known Good Time: 2023-06-21T16:18:47
[1687452723.822204][124848:124848] CHIP:TS: Previous Last Known Good Time: 2023-06-21T16:18:47
[1687452723.822294][124848:124848] CHIP:TS: Reverted Last Known Good Time to previous value
[1687452723.822366][124848:124848] CHIP:CTL: Shutting down the commissioner
[1687452723.822382][124848:124848] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1687452723.822454][124848:124848] CHIP:CTL: Shutting down the controller
[1687452723.822472][124848:124848] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1687452723.822554][124848:124850] CHIP:DL: Bluez disconnected
[1687452723.822572][124848:124850] CHIP:DL: Bluez notify CHIPoBluez connection disconnected
[1687452723.822573][124848:124848] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1687452723.822640][124848:124848] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented.
[1687452723.822736][124848:124848] CHIP:FP: Shutting down FabricTable
[1687452723.822770][124848:124848] CHIP:TS: Pending Last Known Good Time: 2023-06-21T16:18:47
[1687452723.822915][124848:124848] CHIP:TS: Previous Last Known Good Time: 2023-06-21T16:18:47
[1687452723.822927][124848:124848] CHIP:TS: Reverted Last Known Good Time to previous value
[1687452723.823131][124848:124848] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-hSvwT1)
[1687452723.823511][124848:124848] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1687452723.823553][124848:124848] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1687452723.823568][124848:124848] CHIP:DL: Inet Layer shutdown
[1687452723.823580][124848:124848] CHIP:DL: BLE shutdown
[1687452723.823601][124848:124848] CHIP:BLE: CancelBleIncompleteConnection() failed, err = src/ble/BleLayer.cpp:372: CHIP Error 0x00000003: Incorrect state
[1687452723.825022][124848:124848] CHIP:DL: System Layer shutdown
[1687452723.825324][124848:124848] CHIP:TOO: Run command failure: ../examples/chip-tool/commands/common/CHIPCommand.cpp:550: CHIP Error 0x00000032: Timeout