ubuntu@ubuntu:~/connectedhomeip_sve/out/debug$ sudo ./chip-tool pairing ble-thread 20 hex:0e080000000000010000000300000f35060004001fffe0020811111111222222220708fd2e2f57f702e16e051000112233445566778899aabbccddeeff030e4f70656e54687265616444656d6f010212340410445f2b5ca6f2a93a55ce570a70efeecb0c0402a0fff8 20202021 3840 [1657181038.514223][45452:45452] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1657181038.514766][45452:45452] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1657181038.514920][45452:45452] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1657181038.515027][45452:45452] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1657181038.515501][45452:45452] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-8yq2yc) [1657181038.516113][45452:45452] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1657181038.516165][45452:45452] CHIP:DL: NVS set: chip-counters/reboot-count = 208 (0xD0) [1657181038.516970][45452:45452] CHIP:DL: Got Ethernet interface: eth0 [1657181038.517505][45452:45452] CHIP:DL: Found the primary Ethernet interface:eth0 [1657181038.517999][45452:45452] CHIP:DL: Got WiFi interface: wlan0 [1657181038.518070][45452:45452] CHIP:DL: Failed to reset WiFi statistic counts [1657181038.518125][45452:45452] CHIP:IN: UDP::Init bind&listen port=0 [1657181038.518264][45452:45452] CHIP:IN: UDP::Init bound to port=44406 [1657181038.518289][45452:45452] CHIP:IN: BLEBase::Init - setting/overriding transport [1657181038.518353][45452:45452] CHIP:IN: TransportMgr initialized [1657181038.518393][45452:45452] CHIP:FP: Initializing FabricTable from persistent storage [1657181038.519043][45452:45452] CHIP:TS: Last Known Good Time: 2022-07-06T07:34:20 [1657181038.520644][45452:45452] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xA4A2E578C9A5C677, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1657181038.521831][45452:45452] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0xCA1F06D394A42031, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1 [1657181038.523116][45452:45452] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0xAD94C792A6262B1B, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1 [1657181038.531761][45452:45452] CHIP:ZCL: Using ZAP configuration... [1657181038.535925][45452:45452] CHIP:DL: Avahi client registered [1657181038.537260][45452:45452] CHIP:CTL: System State Initialized... [1657181038.537370][45452:45452] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1657181038.537407][45452:45452] CHIP:CTL: Setting attestation nonce to random value [1657181038.537457][45452:45452] CHIP:CTL: Setting CSR nonce to random value [1657181038.537592][45452:45452] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1657181038.537621][45452:45452] CHIP:CTL: Setting attestation nonce to random value [1657181038.537666][45452:45452] CHIP:CTL: Setting CSR nonce to random value [1657181038.540354][45452:45452] CHIP:CTL: Generating NOC [1657181038.542611][45452:45452] CHIP:FP: Validating NOC chain [1657181038.544570][45452:45452] CHIP:FP: NOC chain validation successful [1657181038.544768][45452:45452] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1657181038.544808][45452:45452] CHIP:TS: Last Known Good Time: 2022-07-06T07:34:20 [1657181038.544837][45452:45452] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1657181038.544864][45452:45452] CHIP:TS: Retaining current Last Known Good Time [1657181038.546042][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to load node state: ../../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.546474][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to load node state: ../../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.546893][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to load node state: ../../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.547304][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to load node state: ../../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.548162][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.549005][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.549828][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.550653][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.551473][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.552293][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.553221][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.554056][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.554823][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.555486][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.556144][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.556806][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.557495][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.558158][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.558818][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.559480][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.560134][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.560793][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.561466][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.562126][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.562781][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.563445][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.564104][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.564760][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.565435][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.566095][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.566759][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.567420][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.568078][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.568737][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.569408][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.570072][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.570729][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.571387][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.572046][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.572705][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.573376][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.574064][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.574724][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.575387][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.576048][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.576707][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.577382][45452:45452] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.588471][45452:45452] CHIP:CTL: Warning, failed to delete session resumption state for fabric index 0x1: ../../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181038.595341][45452:45452] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1657181038.602591][45452:45452] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-06T07:34:20 [1657181038.609627][45452:45452] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000 [1657181038.609770][45452:45452] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1657181038.609810][45452:45452] CHIP:CTL: Setting attestation nonce to random value [1657181038.609873][45452:45452] CHIP:CTL: Setting CSR nonce to random value [1657181038.610760][45452:45452] CHIP:CTL: Generating NOC [1657181038.612831][45452:45452] CHIP:FP: Validating NOC chain [1657181038.614607][45452:45452] CHIP:FP: NOC chain validation successful [1657181038.614767][45452:45452] CHIP:FP: Updated fabric at index: 0x2, Node ID: 0x000000000001B669 [1657181038.614800][45452:45452] CHIP:TS: Last Known Good Time: 2022-07-06T07:34:20 [1657181038.614824][45452:45452] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1657181038.614845][45452:45452] CHIP:TS: Retaining current Last Known Good Time [1657181038.622456][45452:45452] CHIP:FP: Metadata for Fabric 0x2 persisted to storage. [1657181038.629710][45452:45452] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-06T07:34:20 [1657181038.636732][45452:45452] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000 [1657181038.636871][45452:45452] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1657181038.636930][45452:45452] CHIP:CTL: Setting attestation nonce to random value [1657181038.636992][45452:45452] CHIP:CTL: Setting CSR nonce to random value [1657181038.637873][45452:45452] CHIP:CTL: Generating NOC [1657181038.639958][45452:45452] CHIP:FP: Validating NOC chain [1657181038.641709][45452:45452] CHIP:FP: NOC chain validation successful [1657181038.641870][45452:45452] CHIP:FP: Updated fabric at index: 0x3, Node ID: 0x000000000001B669 [1657181038.641902][45452:45452] CHIP:TS: Last Known Good Time: 2022-07-06T07:34:20 [1657181038.641926][45452:45452] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1657181038.641948][45452:45452] CHIP:TS: Retaining current Last Known Good Time [1657181038.649542][45452:45452] CHIP:FP: Metadata for Fabric 0x3 persisted to storage. [1657181038.656746][45452:45452] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-06T07:34:20 [1657181038.663829][45452:45452] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000 [1657181038.766368][45452:45457] CHIP:DL: CHIP task running [1657181038.766562][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1657181038.766800][45452:45457] CHIP:IN: SecureSession[0xffffa8001b30]: Allocated Type:1 LSID:20324 [1657181038.766835][45452:45457] CHIP:SC: Assigned local session key ID 20324 [1657181038.766903][45452:45457] CHIP:SC: Including MRP parameters in PBKDF param request [1657181038.767050][45452:45457] CHIP:IN: Prepared unauthenticated message 0xffffb27cdd08 to 0x0000000000000000 (0) of type 0x20 and protocolId (0, 0) on exchange 20330i with MessageCounter:220996869. [1657181038.767102][45452:45457] CHIP:IN: Sending unauthenticated msg 0xffffb27cdd08 with MessageCounter:220996869 to 0x0000000000000000 at monotonic time: 00000000227D5A86 msec [1657181038.767135][45452:45457] CHIP:IN: Message appended to BLE send queue [1657181038.767173][45452:45457] CHIP:SC: Sent PBKDF param request [1657181038.767203][45452:45457] CHIP:CTL: Setting thread operational dataset from parameters [1657181038.767226][45452:45457] CHIP:CTL: Setting attestation nonce to random value [1657181038.767276][45452:45457] CHIP:CTL: Setting CSR nonce to random value [1657181038.767324][45452:45457] CHIP:CTL: Commission called for node ID 0x0000000000000014 [1657181038.767643][45452:45458] CHIP:DL: TRACE: Bluez mainloop starting Thread [1657181038.767841][45452:45455] CHIP:DL: TRACE: Bus acquired for name C-b18c [1657181038.774884][45452:45457] CHIP:DL: PlatformBlueZInit init success [1657181038.780761][45452:45455] CHIP:BLE: BLE removing known devices. [1657181038.782613][45452:45455] CHIP:BLE: BLE initiating scan. [1657181038.817738][45452:45455] CHIP:BLE: New device scanned: 46:6F:A7:1E:0A:95 [1657181038.817829][45452:45455] CHIP:BLE: Device discriminator match. Attempting to connect. [1657181038.822577][45452:45455] CHIP:BLE: Scan complete notification without an active scan. [1657181039.185184][45452:45455] CHIP:DL: ConnectDevice complete [1657181040.756033][45452:45455] CHIP:DL: Char1 /org/bluez/hci0/dev_46_6F_A7_1E_0A_95/service0007 [1657181040.756087][45452:45455] CHIP:DL: Char1 /org/bluez/hci0/dev_46_6F_A7_1E_0A_95/service0007 [1657181040.756128][45452:45455] CHIP:DL: Char1 /org/bluez/hci0/dev_46_6F_A7_1E_0A_95/service0007 [1657181040.756151][45452:45455] CHIP:DL: Char1 /org/bluez/hci0/dev_46_6F_A7_1E_0A_95/service0007 [1657181040.756179][45452:45455] CHIP:DL: Char1 /org/bluez/hci0/dev_46_6F_A7_1E_0A_95/service0007 [1657181040.756201][45452:45455] CHIP:DL: Char1 /org/bluez/hci0/dev_46_6F_A7_1E_0A_95/service0007 [1657181040.756228][45452:45455] CHIP:DL: New BLE connection 0xffffa402d680, device 46:6F:A7:1E:0A:95, path /org/bluez/hci0/dev_46_6F_A7_1E_0A_95 [1657181040.756332][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16385 [1657181040.756390][45452:45457] CHIP:IN: BleConnectionComplete: endPoint 0xaaaad92a8c78 [1657181041.134080][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181041.281084][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16388 [1657181041.281176][45452:45457] CHIP:BLE: subscribe complete, ep = 0xaaaad92a8c78 [1657181041.281483][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181041.281665][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181041.281739][45452:45457] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4 [1657181041.281796][45452:45457] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244. [1657181041.281851][45452:45457] CHIP:BLE: local and remote recv window size = 6 [1657181041.282164][45452:45457] CHIP:IN: BLE EndPoint 0xaaaad92a8c78 Connection Complete [1657181041.426372][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181041.429076][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181041.429295][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181041.429507][45452:45457] CHIP:EM: Received message of type 0x21 with protocolId (0, 0) and MessageCounter:227768852 on exchange 20330i [1657181041.429584][45452:45457] CHIP:EM: Found matching exchange: 20330i, Delegate: 0xffffa8000bb0 [1657181041.429671][45452:45457] CHIP:SC: Received PBKDF param response [1657181041.429867][45452:45457] CHIP:SC: Peer assigned session ID 30627 [1657181041.429950][45452:45457] CHIP:SC: Found MRP parameters in the message [1657181041.440414][45452:45457] CHIP:IN: Prepared unauthenticated message 0xffffb27cd868 to 0x0000000000000000 (0) of type 0x22 and protocolId (0, 0) on exchange 20330i with MessageCounter:220996870. [1657181041.440482][45452:45457] CHIP:IN: Sending unauthenticated msg 0xffffb27cd868 with MessageCounter:220996870 to 0x0000000000000000 at monotonic time: 00000000227D64F7 msec [1657181041.440611][45452:45457] CHIP:SC: Sent spake2p msg1 [1657181041.572594][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181043.378655][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181043.378909][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181043.379128][45452:45457] CHIP:EM: Received message of type 0x23 with protocolId (0, 0) and MessageCounter:227768853 on exchange 20330i [1657181043.379206][45452:45457] CHIP:EM: Found matching exchange: 20330i, Delegate: 0xffffa8000bb0 [1657181043.379289][45452:45457] CHIP:SC: Received spake2p msg2 [1657181043.382541][45452:45457] CHIP:IN: Prepared unauthenticated message 0xffffb27cd9a8 to 0x0000000000000000 (0) of type 0x24 and protocolId (0, 0) on exchange 20330i with MessageCounter:220996871. [1657181043.382646][45452:45457] CHIP:IN: Sending unauthenticated msg 0xffffb27cd9a8 with MessageCounter:220996871 to 0x0000000000000000 at monotonic time: 00000000227D6C8D msec [1657181043.382839][45452:45457] CHIP:SC: Sent spake2p msg3 [1657181043.522747][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181043.524382][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181043.524611][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181043.524829][45452:45457] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:227768854 on exchange 20330i [1657181043.524955][45452:45457] CHIP:EM: Found matching exchange: 20330i, Delegate: 0xffffa8000bb0 [1657181043.525131][45452:45457] CHIP:SC: SecureSession[0xffffa8001b30]: Moving from state 'kEstablishing' --> 'kActive' [1657181043.525195][45452:45457] CHIP:IN: SecureSession[0xffffa8001b30]: Activated - Type:1 LSID:20324 [1657181043.525249][45452:45457] CHIP:IN: New secure session activated for device , LSID:20324 PSID:30627! [1657181043.525314][45452:45457] CHIP:CTL: Remote device completed SPAKE2+ handshake [1657181043.525367][45452:45457] CHIP:TOO: Pairing Success [1657181043.525415][45452:45457] CHIP:TOO: PASE establishment successful [1657181043.525469][45452:45457] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' [1657181043.525529][45452:45457] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' [1657181043.525582][45452:45457] CHIP:CTL: Sending request for commissioning information [1657181043.525652][45452:45457] CHIP:DMG: SendReadRequest ReadClient[0xffffa4016910]: Sending Read Request [1657181043.525890][45452:45457] CHIP:IN: Prepared secure message 0xffffb27cd1b8 to 0xFFFFFFFB00000000 (0) of type 0x2 and protocolId (0, 1) on exchange 20331i with MessageCounter:81080689. [1657181043.525981][45452:45457] CHIP:IN: Sending encrypted msg 0xffffb27cd1b8 with MessageCounter:81080689 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000227D6D1D msec [1657181043.526177][45452:45457] CHIP:DMG: MoveToState ReadClient[0xffffa4016910]: Moving to [AwaitingIn] [1657181043.719074][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181043.818451][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181043.818663][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181043.913741][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181043.913951][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181043.914172][45452:45457] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:104862476 on exchange 20331i [1657181043.914247][45452:45457] CHIP:EM: Found matching exchange: 20331i, Delegate: 0xffffa4016910 [1657181043.914450][45452:45457] CHIP:DMG: ReportDataMessage = [1657181043.914514][45452:45457] CHIP:DMG: { [1657181043.914569][45452:45457] CHIP:DMG: AttributeReportIBs = [1657181043.914644][45452:45457] CHIP:DMG: [ [1657181043.914701][45452:45457] CHIP:DMG: AttributeReportIB = [1657181043.914783][45452:45457] CHIP:DMG: { [1657181043.914847][45452:45457] CHIP:DMG: AttributeDataIB = [1657181043.914922][45452:45457] CHIP:DMG: { [1657181043.915003][45452:45457] CHIP:DMG: DataVersion = 0x326b41b2, [1657181043.915084][45452:45457] CHIP:DMG: AttributePathIB = [1657181043.915164][45452:45457] CHIP:DMG: { [1657181043.915246][45452:45457] CHIP:DMG: Endpoint = 0x0, [1657181043.915323][45452:45457] CHIP:DMG: Cluster = 0x31, [1657181043.915408][45452:45457] CHIP:DMG: Attribute = 0x0000_0003, [1657181043.915494][45452:45457] CHIP:DMG: } [1657181043.915585][45452:45457] CHIP:DMG: [1657181043.915669][45452:45457] CHIP:DMG: Data = 20, [1657181043.915744][45452:45457] CHIP:DMG: }, [1657181043.915826][45452:45457] CHIP:DMG: [1657181043.915889][45452:45457] CHIP:DMG: }, [1657181043.915977][45452:45457] CHIP:DMG: [1657181043.916037][45452:45457] CHIP:DMG: AttributeReportIB = [1657181043.916113][45452:45457] CHIP:DMG: { [1657181043.916176][45452:45457] CHIP:DMG: AttributeDataIB = [1657181043.916244][45452:45457] CHIP:DMG: { [1657181043.916318][45452:45457] CHIP:DMG: DataVersion = 0xe1ecefb5, [1657181043.916394][45452:45457] CHIP:DMG: AttributePathIB = [1657181043.916473][45452:45457] CHIP:DMG: { [1657181043.916553][45452:45457] CHIP:DMG: Endpoint = 0x0, [1657181043.916638][45452:45457] CHIP:DMG: Cluster = 0x28, [1657181043.916730][45452:45457] CHIP:DMG: Attribute = 0x0000_0004, [1657181043.916816][45452:45457] CHIP:DMG: } [1657181043.916928][45452:45457] CHIP:DMG: [1657181043.917013][45452:45457] CHIP:DMG: Data = 32773, [1657181043.917088][45452:45457] CHIP:DMG: }, [1657181043.917169][45452:45457] CHIP:DMG: [1657181043.917231][45452:45457] CHIP:DMG: }, [1657181043.917317][45452:45457] CHIP:DMG: [1657181043.917376][45452:45457] CHIP:DMG: AttributeReportIB = [1657181043.917451][45452:45457] CHIP:DMG: { [1657181043.917513][45452:45457] CHIP:DMG: AttributeDataIB = [1657181043.917586][45452:45457] CHIP:DMG: { [1657181043.917659][45452:45457] CHIP:DMG: DataVersion = 0xe1ecefb5, [1657181043.917736][45452:45457] CHIP:DMG: AttributePathIB = [1657181043.917817][45452:45457] CHIP:DMG: { [1657181043.917898][45452:45457] CHIP:DMG: Endpoint = 0x0, [1657181043.917988][45452:45457] CHIP:DMG: Cluster = 0x28, [1657181043.918073][45452:45457] CHIP:DMG: Attribute = 0x0000_0002, [1657181043.918159][45452:45457] CHIP:DMG: } [1657181043.918243][45452:45457] CHIP:DMG: [1657181043.918318][45452:45457] CHIP:DMG: Data = 65521, [1657181043.918396][45452:45457] CHIP:DMG: }, [1657181043.918476][45452:45457] CHIP:DMG: [1657181043.918539][45452:45457] CHIP:DMG: }, [1657181043.918623][45452:45457] CHIP:DMG: [1657181043.918682][45452:45457] CHIP:DMG: AttributeReportIB = [1657181043.918757][45452:45457] CHIP:DMG: { [1657181043.918819][45452:45457] CHIP:DMG: AttributeDataIB = [1657181043.918892][45452:45457] CHIP:DMG: { [1657181043.918971][45452:45457] CHIP:DMG: DataVersion = 0x38b78231, [1657181043.919055][45452:45457] CHIP:DMG: AttributePathIB = [1657181043.919134][45452:45457] CHIP:DMG: { [1657181043.919214][45452:45457] CHIP:DMG: Endpoint = 0x0, [1657181043.919299][45452:45457] CHIP:DMG: Cluster = 0x30, [1657181043.919383][45452:45457] CHIP:DMG: Attribute = 0x0000_0003, [1657181043.919462][45452:45457] CHIP:DMG: } [1657181043.919550][45452:45457] CHIP:DMG: [1657181043.919638][45452:45457] CHIP:DMG: Data = 0, [1657181043.919712][45452:45457] CHIP:DMG: }, [1657181043.919793][45452:45457] CHIP:DMG: [1657181043.919854][45452:45457] CHIP:DMG: }, [1657181043.919940][45452:45457] CHIP:DMG: [1657181043.919999][45452:45457] CHIP:DMG: AttributeReportIB = [1657181043.920076][45452:45457] CHIP:DMG: { [1657181043.920138][45452:45457] CHIP:DMG: AttributeDataIB = [1657181043.920212][45452:45457] CHIP:DMG: { [1657181043.920287][45452:45457] CHIP:DMG: DataVersion = 0x38b78231, [1657181043.920362][45452:45457] CHIP:DMG: AttributePathIB = [1657181043.920440][45452:45457] CHIP:DMG: { [1657181043.920519][45452:45457] CHIP:DMG: Endpoint = 0x0, [1657181043.920602][45452:45457] CHIP:DMG: Cluster = 0x30, [1657181043.920693][45452:45457] CHIP:DMG: Attribute = 0x0000_0002, [1657181043.920777][45452:45457] CHIP:DMG: } [1657181043.920859][45452:45457] CHIP:DMG: [1657181043.920984][45452:45457] CHIP:DMG: Data = 0, [1657181043.921060][45452:45457] CHIP:DMG: }, [1657181043.921137][45452:45457] CHIP:DMG: [1657181043.921198][45452:45457] CHIP:DMG: }, [1657181043.921286][45452:45457] CHIP:DMG: [1657181043.921346][45452:45457] CHIP:DMG: AttributeReportIB = [1657181043.921424][45452:45457] CHIP:DMG: { [1657181043.921482][45452:45457] CHIP:DMG: AttributeDataIB = [1657181043.921553][45452:45457] CHIP:DMG: { [1657181043.921630][45452:45457] CHIP:DMG: DataVersion = 0x38b78231, [1657181043.921712][45452:45457] CHIP:DMG: AttributePathIB = [1657181043.921785][45452:45457] CHIP:DMG: { [1657181043.921864][45452:45457] CHIP:DMG: Endpoint = 0x0, [1657181043.921955][45452:45457] CHIP:DMG: Cluster = 0x30, [1657181043.922057][45452:45457] CHIP:DMG: Attribute = 0x0000_0001, [1657181043.922129][45452:45457] CHIP:DMG: } [1657181043.922222][45452:45457] CHIP:DMG: [1657181043.922305][45452:45457] CHIP:DMG: Data = [1657181043.922383][45452:45457] CHIP:DMG: { [1657181043.922507][45452:45457] CHIP:DMG: 0x0 = 60, [1657181043.922592][45452:45457] CHIP:DMG: 0x1 = 900, [1657181043.922675][45452:45457] CHIP:DMG: }, [1657181043.922743][45452:45457] CHIP:DMG: }, [1657181043.922834][45452:45457] CHIP:DMG: [1657181043.922896][45452:45457] CHIP:DMG: }, [1657181043.922985][45452:45457] CHIP:DMG: [1657181043.923045][45452:45457] CHIP:DMG: AttributeReportIB = [1657181043.923121][45452:45457] CHIP:DMG: { [1657181043.923184][45452:45457] CHIP:DMG: AttributeDataIB = [1657181043.923255][45452:45457] CHIP:DMG: { [1657181043.923330][45452:45457] CHIP:DMG: DataVersion = 0x38b78231, [1657181043.923405][45452:45457] CHIP:DMG: AttributePathIB = [1657181043.923485][45452:45457] CHIP:DMG: { [1657181043.923564][45452:45457] CHIP:DMG: Endpoint = 0x0, [1657181043.923647][45452:45457] CHIP:DMG: Cluster = 0x30, [1657181043.923725][45452:45457] CHIP:DMG: Attribute = 0x0000_0000, [1657181043.923759][45452:45457] CHIP:DMG: } [1657181043.923795][45452:45457] CHIP:DMG: [1657181043.923836][45452:45457] CHIP:DMG: Data = 0, [1657181043.923873][45452:45457] CHIP:DMG: }, [1657181043.923908][45452:45457] CHIP:DMG: [1657181043.923935][45452:45457] CHIP:DMG: }, [1657181043.923972][45452:45457] CHIP:DMG: [1657181043.923997][45452:45457] CHIP:DMG: AttributeReportIB = [1657181043.924029][45452:45457] CHIP:DMG: { [1657181043.924057][45452:45457] CHIP:DMG: AttributeDataIB = [1657181043.924088][45452:45457] CHIP:DMG: { [1657181043.924119][45452:45457] CHIP:DMG: DataVersion = 0x326b41b2, [1657181043.924155][45452:45457] CHIP:DMG: AttributePathIB = [1657181043.924188][45452:45457] CHIP:DMG: { [1657181043.924222][45452:45457] CHIP:DMG: Endpoint = 0x0, [1657181043.924261][45452:45457] CHIP:DMG: Cluster = 0x31, [1657181043.924297][45452:45457] CHIP:DMG: Attribute = 0x0000_FFFC, [1657181043.924331][45452:45457] CHIP:DMG: } [1657181043.924365][45452:45457] CHIP:DMG: [1657181043.924397][45452:45457] CHIP:DMG: Data = 2, [1657181043.924429][45452:45457] CHIP:DMG: }, [1657181043.924462][45452:45457] CHIP:DMG: [1657181043.924489][45452:45457] CHIP:DMG: }, [1657181043.924520][45452:45457] CHIP:DMG: [1657181043.924544][45452:45457] CHIP:DMG: ], [1657181043.924604][45452:45457] CHIP:DMG: [1657181043.924631][45452:45457] CHIP:DMG: SuppressResponse = true, [1657181043.924657][45452:45457] CHIP:DMG: InteractionModelRevision = 1 [1657181043.924682][45452:45457] CHIP:DMG: } [1657181043.925491][45452:45457] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo' [1657181043.925531][45452:45457] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe' [1657181043.925562][45452:45457] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' [1657181043.925585][45452:45457] CHIP:CTL: Arming failsafe (60 seconds) [1657181043.925647][45452:45457] CHIP:DMG: ICR moving to [AddingComm] [1657181043.925680][45452:45457] CHIP:DMG: ICR moving to [AddedComma] [1657181043.925779][45452:45457] CHIP:IN: Prepared secure message 0xffffb27ccfa8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 20332i with MessageCounter:81080690. [1657181043.925823][45452:45457] CHIP:IN: Sending encrypted msg 0xffffb27ccfa8 with MessageCounter:81080690 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000227D6EAC msec [1657181043.925930][45452:45457] CHIP:DMG: ICR moving to [CommandSen] [1657181044.011110][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181044.013299][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181044.013513][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181044.013778][45452:45457] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:104862477 on exchange 20332i [1657181044.013856][45452:45457] CHIP:EM: Found matching exchange: 20332i, Delegate: 0xffffa800efc0 [1657181044.014049][45452:45457] CHIP:DMG: ICR moving to [ResponseRe] [1657181044.014156][45452:45457] CHIP:DMG: InvokeResponseMessage = [1657181044.014216][45452:45457] CHIP:DMG: { [1657181044.014275][45452:45457] CHIP:DMG: suppressResponse = false, [1657181044.014334][45452:45457] CHIP:DMG: InvokeResponseIBs = [1657181044.014470][45452:45457] CHIP:DMG: [ [1657181044.014532][45452:45457] CHIP:DMG: InvokeResponseIB = [1657181044.014614][45452:45457] CHIP:DMG: { [1657181044.014677][45452:45457] CHIP:DMG: CommandDataIB = [1657181044.014830][45452:45457] CHIP:DMG: { [1657181044.014899][45452:45457] CHIP:DMG: CommandPathIB = [1657181044.015005][45452:45457] CHIP:DMG: { [1657181044.015148][45452:45457] CHIP:DMG: EndpointId = 0x0, [1657181044.015237][45452:45457] CHIP:DMG: ClusterId = 0x30, [1657181044.015320][45452:45457] CHIP:DMG: CommandId = 0x1, [1657181044.015459][45452:45457] CHIP:DMG: }, [1657181044.015544][45452:45457] CHIP:DMG: [1657181044.015616][45452:45457] CHIP:DMG: CommandFields = [1657181044.015760][45452:45457] CHIP:DMG: { [1657181044.015842][45452:45457] CHIP:DMG: 0x0 = 0, [1657181044.015992][45452:45457] CHIP:DMG: 0x1 = "", [1657181044.016074][45452:45457] CHIP:DMG: }, [1657181044.016151][45452:45457] CHIP:DMG: }, [1657181044.016292][45452:45457] CHIP:DMG: [1657181044.016357][45452:45457] CHIP:DMG: }, [1657181044.016433][45452:45457] CHIP:DMG: [1657181044.016492][45452:45457] CHIP:DMG: ], [1657181044.016632][45452:45457] CHIP:DMG: [1657181044.016694][45452:45457] CHIP:DMG: InteractionModelRevision = 1 [1657181044.016752][45452:45457] CHIP:DMG: }, [1657181044.016992][45452:45457] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1657181044.017080][45452:45457] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1657181044.017145][45452:45457] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe' [1657181044.017270][45452:45457] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory' [1657181044.017331][45452:45457] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' [1657181044.017386][45452:45457] CHIP:CTL: Setting Regulatory Config [1657181044.017435][45452:45457] CHIP:CTL: Device does not support configurable regulatory location [1657181044.017557][45452:45457] CHIP:DMG: ICR moving to [AddingComm] [1657181044.017632][45452:45457] CHIP:DMG: ICR moving to [AddedComma] [1657181044.017844][45452:45457] CHIP:IN: Prepared secure message 0xffffb27cca88 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 20333i with MessageCounter:81080691. [1657181044.017938][45452:45457] CHIP:IN: Sending encrypted msg 0xffffb27cca88 with MessageCounter:81080691 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000227D6F09 msec [1657181044.018201][45452:45457] CHIP:DMG: ICR moving to [CommandSen] [1657181044.018319][45452:45457] CHIP:DMG: ICR moving to [AwaitingDe] [1657181044.107664][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181044.109466][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181044.109673][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181044.109927][45452:45457] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:104862478 on exchange 20333i [1657181044.110003][45452:45457] CHIP:EM: Found matching exchange: 20333i, Delegate: 0xffffa800f760 [1657181044.110189][45452:45457] CHIP:DMG: ICR moving to [ResponseRe] [1657181044.110294][45452:45457] CHIP:DMG: InvokeResponseMessage = [1657181044.110353][45452:45457] CHIP:DMG: { [1657181044.110409][45452:45457] CHIP:DMG: suppressResponse = false, [1657181044.110469][45452:45457] CHIP:DMG: InvokeResponseIBs = [1657181044.110545][45452:45457] CHIP:DMG: [ [1657181044.110672][45452:45457] CHIP:DMG: InvokeResponseIB = [1657181044.110762][45452:45457] CHIP:DMG: { [1657181044.110826][45452:45457] CHIP:DMG: CommandDataIB = [1657181044.110909][45452:45457] CHIP:DMG: { [1657181044.111049][45452:45457] CHIP:DMG: CommandPathIB = [1657181044.111134][45452:45457] CHIP:DMG: { [1657181044.111216][45452:45457] CHIP:DMG: EndpointId = 0x0, [1657181044.111364][45452:45457] CHIP:DMG: ClusterId = 0x30, [1657181044.111456][45452:45457] CHIP:DMG: CommandId = 0x3, [1657181044.111537][45452:45457] CHIP:DMG: }, [1657181044.111662][45452:45457] CHIP:DMG: [1657181044.111738][45452:45457] CHIP:DMG: CommandFields = [1657181044.111818][45452:45457] CHIP:DMG: { [1657181044.111903][45452:45457] CHIP:DMG: 0x0 = 0, [1657181044.112057][45452:45457] CHIP:DMG: 0x1 = "", [1657181044.112143][45452:45457] CHIP:DMG: }, [1657181044.112217][45452:45457] CHIP:DMG: }, [1657181044.112298][45452:45457] CHIP:DMG: [1657181044.112432][45452:45457] CHIP:DMG: }, [1657181044.112509][45452:45457] CHIP:DMG: [1657181044.112567][45452:45457] CHIP:DMG: ], [1657181044.112705][45452:45457] CHIP:DMG: [1657181044.112773][45452:45457] CHIP:DMG: InteractionModelRevision = 1 [1657181044.112831][45452:45457] CHIP:DMG: }, [1657181044.113066][45452:45457] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1657181044.113199][45452:45457] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0 [1657181044.113268][45452:45457] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory' [1657181044.113322][45452:45457] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest' [1657181044.113384][45452:45457] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' [1657181044.113487][45452:45457] CHIP:CTL: Sending request for PAI certificate [1657181044.113538][45452:45457] CHIP:CTL: Sending Certificate Chain request to 0xffffa8000b60 device [1657181044.113648][45452:45457] CHIP:DMG: ICR moving to [AddingComm] [1657181044.113716][45452:45457] CHIP:DMG: ICR moving to [AddedComma] [1657181044.113882][45452:45457] CHIP:IN: Prepared secure message 0xffffb27cc9c8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 20334i with MessageCounter:81080692. [1657181044.114023][45452:45457] CHIP:IN: Sending encrypted msg 0xffffb27cc9c8 with MessageCounter:81080692 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000227D6F69 msec [1657181044.114281][45452:45457] CHIP:DMG: ICR moving to [CommandSen] [1657181044.114398][45452:45457] CHIP:DMG: ICR moving to [AwaitingDe] [1657181044.204973][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181044.208571][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181044.208762][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181044.355093][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181044.355325][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181044.498711][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181044.498936][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181044.499195][45452:45457] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:104862479 on exchange 20334i [1657181044.499276][45452:45457] CHIP:EM: Found matching exchange: 20334i, Delegate: 0xffffa800efc0 [1657181044.499365][45452:45457] CHIP:DMG: ICR moving to [ResponseRe] [1657181044.499466][45452:45457] CHIP:DMG: InvokeResponseMessage = [1657181044.499524][45452:45457] CHIP:DMG: { [1657181044.499581][45452:45457] CHIP:DMG: suppressResponse = false, [1657181044.499641][45452:45457] CHIP:DMG: InvokeResponseIBs = [1657181044.499831][45452:45457] CHIP:DMG: [ [1657181044.499894][45452:45457] CHIP:DMG: InvokeResponseIB = [1657181044.499973][45452:45457] CHIP:DMG: { [1657181044.500098][45452:45457] CHIP:DMG: CommandDataIB = [1657181044.500191][45452:45457] CHIP:DMG: { [1657181044.500262][45452:45457] CHIP:DMG: CommandPathIB = [1657181044.500406][45452:45457] CHIP:DMG: { [1657181044.500489][45452:45457] CHIP:DMG: EndpointId = 0x0, [1657181044.500575][45452:45457] CHIP:DMG: ClusterId = 0x3e, [1657181044.500729][45452:45457] CHIP:DMG: CommandId = 0x3, [1657181044.500811][45452:45457] CHIP:DMG: }, [1657181044.500990][45452:45457] CHIP:DMG: [1657181044.501070][45452:45457] CHIP:DMG: CommandFields = [1657181044.501149][45452:45457] CHIP:DMG: { [1657181044.501294][45452:45457] CHIP:DMG: 0x0 = [ [1657181044.501688][45452:45457] CHIP:DMG: 0x30, 0x82, 0x1, 0xcb, 0x30, 0x82, 0x1, 0x71, 0xa0, 0x3, 0x2, 0x1, 0x2, 0x2, 0x8, 0x56, 0xad, 0x82, 0x22, 0xad, 0x94, 0x5b, 0x64, 0x30, 0xa, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0xf, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0xd, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0xf, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0x41, 0x9a, 0x93, 0x15, 0xc2, 0x17, 0x3e, 0xc, 0x8c, 0x87, 0x6d, 0x3, 0xcc, 0xfc, 0x94, 0x48, 0x52, 0x64, 0x7f, 0x7f, 0xec, 0x5e, 0x50, 0x82, 0xf4, 0x5, 0x99, 0x28, 0xec, 0xa8, 0x94, 0xc5, 0x94, 0x15, 0x13, 0x9, 0xac, 0x63, 0x1e, 0x4c, 0xb0, 0x33, 0x92, 0xaf, 0x68, 0x4b, 0xb, 0xaf, 0xb7, 0xe6, 0x5b, 0x3b, 0x81, 0x62, 0xc2, 0xf5, 0x2b, 0xf9, 0x31, 0xb8, 0xe7, 0x7a, 0xaa, 0x82, 0xa3, 0x66, 0x30, 0x64, 0x30, 0x12, 0x6, 0x3, 0x55, 0x1d, 0x13, 0x1, 0x1, 0xff, 0x4, 0x8, 0x30, 0x6, 0x1, 0x1, 0xff, 0x2, 0x1, [1657181044.501937][45452:45457] CHIP:DMG: ] [1657181044.502022][45452:45457] CHIP:DMG: }, [1657181044.502096][45452:45457] CHIP:DMG: }, [1657181044.502181][45452:45457] CHIP:DMG: [1657181044.502242][45452:45457] CHIP:DMG: }, [1657181044.502316][45452:45457] CHIP:DMG: [1657181044.502374][45452:45457] CHIP:DMG: ], [1657181044.502448][45452:45457] CHIP:DMG: [1657181044.502510][45452:45457] CHIP:DMG: InteractionModelRevision = 1 [1657181044.502566][45452:45457] CHIP:DMG: }, [1657181044.502705][45452:45457] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1657181044.502900][45452:45457] CHIP:CTL: Received certificate chain from the device [1657181044.503032][45452:45457] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest' [1657181044.503092][45452:45457] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest' [1657181044.503157][45452:45457] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest' [1657181044.503210][45452:45457] CHIP:CTL: Sending request for DAC certificate [1657181044.503260][45452:45457] CHIP:CTL: Sending Certificate Chain request to 0xffffa8000b60 device [1657181044.503439][45452:45457] CHIP:DMG: ICR moving to [AddingComm] [1657181044.503511][45452:45457] CHIP:DMG: ICR moving to [AddedComma] [1657181044.503750][45452:45457] CHIP:IN: Prepared secure message 0xffffb27cc9d8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 20335i with MessageCounter:81080693. [1657181044.503845][45452:45457] CHIP:IN: Sending encrypted msg 0xffffb27cc9d8 with MessageCounter:81080693 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000227D70EE msec [1657181044.504106][45452:45457] CHIP:DMG: ICR moving to [CommandSen] [1657181044.504224][45452:45457] CHIP:DMG: ICR moving to [AwaitingDe] [1657181044.692638][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181044.696292][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181044.696510][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181044.890909][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181044.891138][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181044.986442][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181044.986668][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181044.986930][45452:45457] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:104862480 on exchange 20335i [1657181044.987006][45452:45457] CHIP:EM: Found matching exchange: 20335i, Delegate: 0xffffa800f760 [1657181044.987095][45452:45457] CHIP:DMG: ICR moving to [ResponseRe] [1657181044.987195][45452:45457] CHIP:DMG: InvokeResponseMessage = [1657181044.987254][45452:45457] CHIP:DMG: { [1657181044.987312][45452:45457] CHIP:DMG: suppressResponse = false, [1657181044.987484][45452:45457] CHIP:DMG: InvokeResponseIBs = [1657181044.987565][45452:45457] CHIP:DMG: [ [1657181044.987625][45452:45457] CHIP:DMG: InvokeResponseIB = [1657181044.987704][45452:45457] CHIP:DMG: { [1657181044.987767][45452:45457] CHIP:DMG: CommandDataIB = [1657181044.987905][45452:45457] CHIP:DMG: { [1657181044.987987][45452:45457] CHIP:DMG: CommandPathIB = [1657181044.988068][45452:45457] CHIP:DMG: { [1657181044.988219][45452:45457] CHIP:DMG: EndpointId = 0x0, [1657181044.988318][45452:45457] CHIP:DMG: ClusterId = 0x3e, [1657181044.988402][45452:45457] CHIP:DMG: CommandId = 0x3, [1657181044.988543][45452:45457] CHIP:DMG: }, [1657181044.988628][45452:45457] CHIP:DMG: [1657181044.988701][45452:45457] CHIP:DMG: CommandFields = [1657181044.988844][45452:45457] CHIP:DMG: { [1657181044.988979][45452:45457] CHIP:DMG: 0x0 = [ [1657181044.989436][45452:45457] CHIP:DMG: 0x30, 0x82, 0x1, 0xe8, 0x30, 0x82, 0x1, 0x8e, 0xa0, 0x3, 0x2, 0x1, 0x2, 0x2, 0x8, 0x6f, 0xdc, 0xb6, 0xed, 0x6, 0xf3, 0x58, 0xf9, 0x30, 0xa, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x50, 0x41, 0x49, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x20, 0x6e, 0x6f, 0x20, 0x50, 0x49, 0x44, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0xd, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0xf, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x53, 0x31, 0x25, 0x30, 0x23, 0x6, 0x3, 0x55, 0x4, 0x3, 0xc, 0x1c, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x44, 0x65, 0x76, 0x20, 0x44, 0x41, 0x43, 0x20, 0x30, 0x78, 0x46, 0x46, 0x46, 0x31, 0x2f, 0x30, 0x78, 0x38, 0x30, 0x30, 0x35, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x1, 0xc, 0x4, 0x46, 0x46, 0x46, 0x31, 0x31, 0x14, 0x30, 0x12, 0x6, 0xa, 0x2b, 0x6, 0x1, 0x4, 0x1, 0x82, 0xa2, 0x7c, 0x2, 0x2, 0xc, 0x4, 0x38, 0x30, 0x30, 0x35, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0x7e, 0xf2, 0xf1, 0x8, 0x2b, 0x2a, 0x56, 0x4a, 0x5, 0x44, 0xc0, 0xa6, 0x13, 0xd2, 0x1b, 0x15, 0x75, 0x0, 0x55, 0x2d, 0x3, 0x5f, 0x23, 0x2, 0x25, 0x2f, 0xce, 0xe8, 0x1d, 0x6e, 0xc6, 0x74, 0x17, 0x34, 0x18, 0xa9, 0x4a, 0x88, 0xdb, 0x73, 0x74, 0x15, 0x58, 0xc9, 0xfc, 0x8a, 0xc9, 0x34, 0x9e, 0xf6, 0x7e, 0x3e [1657181044.989680][45452:45457] CHIP:DMG: ] [1657181044.989766][45452:45457] CHIP:DMG: }, [1657181044.989841][45452:45457] CHIP:DMG: }, [1657181044.989922][45452:45457] CHIP:DMG: [1657181044.989983][45452:45457] CHIP:DMG: }, [1657181044.990057][45452:45457] CHIP:DMG: [1657181044.990115][45452:45457] CHIP:DMG: ], [1657181044.990191][45452:45457] CHIP:DMG: [1657181044.990250][45452:45457] CHIP:DMG: InteractionModelRevision = 1 [1657181044.990306][45452:45457] CHIP:DMG: }, [1657181044.990550][45452:45457] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1657181044.990635][45452:45457] CHIP:CTL: Received certificate chain from the device [1657181044.990702][45452:45457] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest' [1657181044.990765][45452:45457] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest' [1657181044.990898][45452:45457] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest' [1657181044.990953][45452:45457] CHIP:CTL: Sending Attestation Request to the device. [1657181044.991004][45452:45457] CHIP:CTL: Sending Attestation request to 0xffffa8000b60 device [1657181044.991116][45452:45457] CHIP:DMG: ICR moving to [AddingComm] [1657181044.991187][45452:45457] CHIP:DMG: ICR moving to [AddedComma] [1657181044.991426][45452:45457] CHIP:IN: Prepared secure message 0xffffb27cc998 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 20336i with MessageCounter:81080694. [1657181044.991518][45452:45457] CHIP:IN: Sending encrypted msg 0xffffb27cc998 with MessageCounter:81080694 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000227D72D6 msec [1657181044.991784][45452:45457] CHIP:DMG: ICR moving to [CommandSen] [1657181044.991917][45452:45457] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information [1657181044.992024][45452:45457] CHIP:DMG: ICR moving to [AwaitingDe] [1657181045.082100][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181045.427215][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181045.427452][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181045.622165][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181045.622391][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181045.768391][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181045.768625][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181045.768952][45452:45457] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:104862481 on exchange 20336i [1657181045.769029][45452:45457] CHIP:EM: Found matching exchange: 20336i, Delegate: 0xffffa800efc0 [1657181045.769119][45452:45457] CHIP:DMG: ICR moving to [ResponseRe] [1657181045.769223][45452:45457] CHIP:DMG: InvokeResponseMessage = [1657181045.769284][45452:45457] CHIP:DMG: { [1657181045.769342][45452:45457] CHIP:DMG: suppressResponse = false, [1657181045.769401][45452:45457] CHIP:DMG: InvokeResponseIBs = [1657181045.769479][45452:45457] CHIP:DMG: [ [1657181045.769540][45452:45457] CHIP:DMG: InvokeResponseIB = [1657181045.769632][45452:45457] CHIP:DMG: { [1657181045.769696][45452:45457] CHIP:DMG: CommandDataIB = [1657181045.769771][45452:45457] CHIP:DMG: { [1657181045.769845][45452:45457] CHIP:DMG: CommandPathIB = [1657181045.769926][45452:45457] CHIP:DMG: { [1657181045.770007][45452:45457] CHIP:DMG: EndpointId = 0x0, [1657181045.770092][45452:45457] CHIP:DMG: ClusterId = 0x3e, [1657181045.770167][45452:45457] CHIP:DMG: CommandId = 0x1, [1657181045.770245][45452:45457] CHIP:DMG: }, [1657181045.770327][45452:45457] CHIP:DMG: [1657181045.770399][45452:45457] CHIP:DMG: CommandFields = [1657181045.770478][45452:45457] CHIP:DMG: { [1657181045.770567][45452:45457] CHIP:DMG: 0x0 = [ [1657181045.770919][45452:45457] CHIP:DMG: 0x15, 0x31, 0x1, 0x1d, 0x2, 0x30, 0x82, 0x2, 0x19, 0x6, 0x9, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0xd, 0x1, 0x7, 0x2, 0xa0, 0x82, 0x2, 0xa, 0x30, 0x82, 0x2, 0x6, 0x2, 0x1, 0x3, 0x31, 0xd, 0x30, 0xb, 0x6, 0x9, 0x60, 0x86, 0x48, 0x1, 0x65, 0x3, 0x4, 0x2, 0x1, 0x30, 0x82, 0x1, 0x71, 0x6, 0x9, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0xd, 0x1, 0x7, 0x1, 0xa0, 0x82, 0x1, 0x62, 0x4, 0x82, 0x1, 0x5e, 0x15, 0x24, 0x0, 0x1, 0x25, 0x1, 0xf1, 0xff, 0x36, 0x2, 0x5, 0x0, 0x80, 0x5, 0x1, 0x80, 0x5, 0x2, 0x80, 0x5, 0x3, 0x80, 0x5, 0x4, 0x80, 0x5, 0x5, 0x80, 0x5, 0x6, 0x80, 0x5, 0x7, 0x80, 0x5, 0x8, 0x80, 0x5, 0x9, 0x80, 0x5, 0xa, 0x80, 0x5, 0xb, 0x80, 0x5, 0xc, 0x80, 0x5, 0xd, 0x80, 0x5, 0xe, 0x80, 0x5, 0xf, 0x80, 0x5, 0x10, 0x80, 0x5, 0x11, 0x80, 0x5, 0x12, 0x80, 0x5, 0x13, 0x80, 0x5, 0x14, 0x80, 0x5, 0x15, 0x80, 0x5, 0x16, 0x80, 0x5, 0x17, 0x80, 0x5, 0x18, 0x80, 0x5, 0x19, 0x80, 0x5, 0x1a, 0x80, 0x5, 0x1b, 0x80, 0x5, 0x1c, 0x80, 0x5, 0x1d, 0x80, 0x5, 0x1e, 0x80, 0x5, 0x1f, 0x80, 0x5, 0x20, 0x80, 0x5, 0x21, 0x80, 0x5, 0x22, 0x80, 0x5, 0x23, 0x80, 0x5, 0x24, 0x80, 0x5, 0x25, 0x80, 0x5, 0x26, 0x80, 0x5, 0x27, 0x80, 0x5, 0x28, 0x80, 0x5, 0x29, 0x80, 0x5, 0x2a, 0x80, 0x5, 0x2b, 0x80, 0x5, 0x2c, 0x80, 0x5, 0x2d, 0x80, 0x5, 0x2e, 0x80, 0x5, 0x2f, 0x80, 0x5, 0x30, 0x80, 0x5, 0x31, 0x80, 0x5, 0x32, 0x80, 0x5, 0x33, 0x80, 0x5, 0x34, 0x80, 0x5, 0x35, 0x80, 0x5, 0x36, 0x80, 0x5, 0x37, 0x80, 0x5, 0x38, 0x80, 0x5, 0x39, 0x80, 0x5, 0x3a, 0x80, 0x5, 0x3b, 0x80, 0x5, 0x3c, 0x80, 0x5, 0x3d, 0x80, 0x5, 0x3e, 0x80, 0x5, 0x3f, 0x80, 0x5, 0x40, 0x80, 0x5, 0x41, 0x80, 0x5, 0x42, 0x80, 0x5, 0x43, 0x80, 0x5, 0x44, 0x80, 0x5, 0x45, 0x80, 0x5, 0x46, 0x80, 0x5, 0x47, 0x80, 0x5, 0x48, 0x80, 0x5, 0x49, 0x80, 0x5, 0x4a, 0x80, 0x5, 0 [1657181045.771095][45452:45457] CHIP:DMG: ] [1657181045.771179][45452:45457] CHIP:DMG: 0x1 = [ [1657181045.771312][45452:45457] CHIP:DMG: 0x36, 0xee, 0x8c, 0x21, 0x52, 0x99, 0xcd, 0x6a, 0xaa, 0x9, 0x2f, 0x33, 0xd7, 0x84, 0x59, 0x2f, 0x7e, 0xcc, 0xed, 0xe8, 0x55, 0x6a, 0x67, 0x53, 0x22, 0x17, 0xe3, 0xcc, 0xa2, 0xd7, 0xd2, 0x6f, 0x5a, 0x94, 0x84, 0x2c, 0x90, 0xfb, 0xab, 0x6a, 0x14, 0x1a, 0xef, 0xb, 0xdf, 0xdd, 0xc2, 0xe6, 0x55, 0xde, 0x18, 0x6d, 0xea, 0x3b, 0x0, 0x5f, 0xa2, 0x93, 0x4e, 0x98, 0x2a, 0xd8, 0x3f, 0x7d, [1657181045.771414][45452:45457] CHIP:DMG: ] [1657181045.771497][45452:45457] CHIP:DMG: }, [1657181045.771571][45452:45457] CHIP:DMG: }, [1657181045.771655][45452:45457] CHIP:DMG: [1657181045.771717][45452:45457] CHIP:DMG: }, [1657181045.771793][45452:45457] CHIP:DMG: [1657181045.771851][45452:45457] CHIP:DMG: ], [1657181045.771926][45452:45457] CHIP:DMG: [1657181045.771984][45452:45457] CHIP:DMG: InteractionModelRevision = 1 [1657181045.772041][45452:45457] CHIP:DMG: }, [1657181045.772181][45452:45457] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 [1657181045.772260][45452:45457] CHIP:CTL: Received Attestation Information from the device [1657181045.772325][45452:45457] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest' [1657181045.772464][45452:45457] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification' [1657181045.772532][45452:45457] CHIP:CTL: Performing next commissioning step 'AttestationVerification' [1657181045.772585][45452:45457] CHIP:CTL: Verifying attestation [1657181045.781688][45452:45457] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device. [1657181045.781749][45452:45457] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification' [1657181045.781776][45452:45457] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest' [1657181045.781809][45452:45457] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest' [1657181045.781835][45452:45457] CHIP:CTL: Sending CSR request to 0xffffa8000b60 device [1657181045.781910][45452:45457] CHIP:DMG: ICR moving to [AddingComm] [1657181045.781948][45452:45457] CHIP:DMG: ICR moving to [AddedComma] [1657181045.782064][45452:45457] CHIP:IN: Prepared secure message 0xffffb27cc068 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 20337i with MessageCounter:81080695. [1657181045.782113][45452:45457] CHIP:IN: Sending encrypted msg 0xffffb27cc068 with MessageCounter:81080695 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000227D75ED msec [1657181045.782233][45452:45457] CHIP:DMG: ICR moving to [CommandSen] [1657181045.782265][45452:45457] CHIP:CTL: Sent CSR request, waiting for the CSR [1657181045.782323][45452:45457] CHIP:DMG: ICR moving to [AwaitingDe] [1657181045.862655][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181046.939056][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181046.939299][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181047.132319][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181047.132549][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181047.132789][45452:45457] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:104862482 on exchange 20337i [1657181047.132868][45452:45457] CHIP:EM: Found matching exchange: 20337i, Delegate: 0xaaab0d2ded40 [1657181047.133015][45452:45457] CHIP:DMG: ICR moving to [ResponseRe] [1657181047.133120][45452:45457] CHIP:DMG: InvokeResponseMessage = [1657181047.133180][45452:45457] CHIP:DMG: { [1657181047.133238][45452:45457] CHIP:DMG: suppressResponse = false, [1657181047.133298][45452:45457] CHIP:DMG: InvokeResponseIBs = [1657181047.133377][45452:45457] CHIP:DMG: [ [1657181047.133438][45452:45457] CHIP:DMG: InvokeResponseIB = [1657181047.133520][45452:45457] CHIP:DMG: { [1657181047.133584][45452:45457] CHIP:DMG: CommandDataIB = [1657181047.133660][45452:45457] CHIP:DMG: { [1657181047.133728][45452:45457] CHIP:DMG: CommandPathIB = [1657181047.133809][45452:45457] CHIP:DMG: { [1657181047.133891][45452:45457] CHIP:DMG: EndpointId = 0x0, [1657181047.133978][45452:45457] CHIP:DMG: ClusterId = 0x3e, [1657181047.134060][45452:45457] CHIP:DMG: CommandId = 0x5, [1657181047.134138][45452:45457] CHIP:DMG: }, [1657181047.134221][45452:45457] CHIP:DMG: [1657181047.134293][45452:45457] CHIP:DMG: CommandFields = [1657181047.134372][45452:45457] CHIP:DMG: { [1657181047.134452][45452:45457] CHIP:DMG: 0x0 = [ [1657181047.134735][45452:45457] CHIP:DMG: 0x15, 0x30, 0x1, 0xce, 0x30, 0x81, 0xcb, 0x30, 0x70, 0x2, 0x1, 0x0, 0x30, 0xe, 0x31, 0xc, 0x30, 0xa, 0x6, 0x3, 0x55, 0x4, 0xa, 0xc, 0x3, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x6, 0x7, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x2, 0x1, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x3, 0x1, 0x7, 0x3, 0x42, 0x0, 0x4, 0xc9, 0x9a, 0xd2, 0x50, 0x3a, 0xd8, 0xad, 0x77, 0x8c, 0x74, 0x10, 0xe8, 0x6c, 0xb3, 0x91, 0x3e, 0x9a, 0x73, 0x87, 0x6b, 0x1a, 0x3a, 0xf3, 0x48, 0x6c, 0x94, 0x19, 0x4, 0x9d, 0x92, 0x1b, 0xc9, 0x8, 0x39, 0x9e, 0xda, 0x48, 0xd5, 0x68, 0xca, 0xb, 0x99, 0xd2, 0xbc, 0xb5, 0xd8, 0x21, 0x11, 0xf3, 0x9, 0x21, 0xfe, 0xe1, 0xd3, 0x99, 0x38, 0x83, 0x82, 0xf7, 0x6b, 0x85, 0xf6, 0xd0, 0x34, 0xa0, 0x0, 0x30, 0xc, 0x6, 0x8, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x4, 0x3, 0x2, 0x5, 0x0, 0x3, 0x49, 0x0, 0x30, 0x46, 0x2, 0x21, 0x0, 0xaf, 0x7c, 0xbb, 0x3, 0xf2, 0xcf, 0x88, 0x72, 0x96, 0xc, 0x8e, 0x56, 0x13, 0x11, 0xf4, 0x3e, 0xf3, 0x39, 0x74, 0xa4, 0x3d, 0xb9, 0x17, 0xc0, 0xb2, 0xb4, 0x29, 0x5d, 0x96, 0xde, 0xca, 0x62, 0x2, 0x21, 0x0, 0xa4, 0x88, 0xed, 0x7b, 0x9c, 0x6c, 0x7f, 0xdc, 0x40, 0xf7, 0xa3, 0x61, 0x6c, 0x8a, 0x10, 0x24, 0xb6, 0x7a, 0xda, 0x25, 0x39, 0x81, 0x50, 0x97, 0x7a, 0xc7, 0xba, 0x82, 0x40, 0x12, 0x1b, 0x4e, 0x30, 0x2, 0x20, 0x27, 0x32, 0x5, 0xd8, 0xd8, 0xc7, 0x3f, 0xc, 0x19, 0x1a, 0x40, 0x40, 0x0, 0x3b, 0xc, 0xd4, 0x84, 0xf8, 0xc5, 0xe4, 0x8f, 0x8f, 0x61, 0x6a, 0xf5, 0xb1, 0x1f, 0xf9, 0x8e, 0x16, 0x8d, 0x6e, 0x18, [1657181047.134906][45452:45457] CHIP:DMG: ] [1657181047.134988][45452:45457] CHIP:DMG: 0x1 = [ [1657181047.135128][45452:45457] CHIP:DMG: 0x2a, 0xd4, 0x9c, 0xa8, 0xe9, 0xc5, 0xe8, 0x2d, 0xe9, 0x90, 0xa9, 0xf6, 0xa5, 0x3a, 0x81, 0x2b, 0x48, 0x21, 0xad, 0x49, 0x25, 0xf8, 0xb2, 0x20, 0x20, 0x94, 0xc1, 0xda, 0x8a, 0x93, 0xf5, 0x15, 0x2a, 0x2f, 0x63, 0xe6, 0x86, 0x94, 0x4b, 0x15, 0x86, 0xa1, 0x3b, 0x1e, 0x82, 0x8f, 0xe5, 0x62, 0xa3, 0x3a, 0x49, 0x87, 0xd6, 0xbf, 0x78, 0x5f, 0xa0, 0xd9, 0x43, 0xa8, 0x5c, 0x2, 0x14, 0xd9, [1657181047.135230][45452:45457] CHIP:DMG: ] [1657181047.135312][45452:45457] CHIP:DMG: }, [1657181047.135387][45452:45457] CHIP:DMG: }, [1657181047.135470][45452:45457] CHIP:DMG: [1657181047.135532][45452:45457] CHIP:DMG: }, [1657181047.135606][45452:45457] CHIP:DMG: [1657181047.135665][45452:45457] CHIP:DMG: ], [1657181047.135740][45452:45457] CHIP:DMG: [1657181047.135798][45452:45457] CHIP:DMG: InteractionModelRevision = 1 [1657181047.135855][45452:45457] CHIP:DMG: }, [1657181047.135995][45452:45457] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 [1657181047.136079][45452:45457] CHIP:CTL: Received certificate signing request from the device [1657181047.136148][45452:45457] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest' [1657181047.136203][45452:45457] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR' [1657181047.136264][45452:45457] CHIP:CTL: Performing next commissioning step 'ValidateCSR' [1657181047.138767][45452:45457] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR' [1657181047.138847][45452:45457] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain' [1657181047.138906][45452:45457] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain' [1657181047.138961][45452:45457] CHIP:CTL: Getting certificate chain for the device from the issuer [1657181047.139418][45452:45457] CHIP:CTL: Verifying Certificate Signing Request [1657181047.141271][45452:45457] CHIP:CTL: Generating NOC [1657181047.141931][45452:45457] CHIP:CTL: Providing certificate chain to the commissioner [1657181047.142008][45452:45457] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status ../../src/controller/ExampleOperationalCredentialsIssuer.cpp:261: Success [1657181047.142076][45452:45457] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain' [1657181047.142409][45452:45457] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert' [1657181047.142477][45452:45457] CHIP:CTL: Sending root certificate to the device [1657181047.142604][45452:45457] CHIP:DMG: ICR moving to [AddingComm] [1657181047.142675][45452:45457] CHIP:DMG: ICR moving to [AddedComma] [1657181047.142859][45452:45457] CHIP:IN: Prepared secure message 0xffffb27cb8f8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 20338i with MessageCounter:81080696. [1657181047.142935][45452:45457] CHIP:IN: Sending encrypted msg 0xffffb27cb8f8 with MessageCounter:81080696 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000227D7B3E msec [1657181047.143052][45452:45457] CHIP:DMG: ICR moving to [CommandSen] [1657181047.143089][45452:45457] CHIP:CTL: Sent root certificate to the device [1657181047.143402][45452:45457] CHIP:DMG: ICR moving to [AwaitingDe] [1657181047.327670][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181047.568976][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181047.570757][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181047.570983][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181047.571234][45452:45457] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:104862483 on exchange 20338i [1657181047.571313][45452:45457] CHIP:EM: Found matching exchange: 20338i, Delegate: 0xffffa800efc0 [1657181047.571396][45452:45457] CHIP:DMG: ICR moving to [ResponseRe] [1657181047.571495][45452:45457] CHIP:DMG: InvokeResponseMessage = [1657181047.571556][45452:45457] CHIP:DMG: { [1657181047.571613][45452:45457] CHIP:DMG: suppressResponse = false, [1657181047.571672][45452:45457] CHIP:DMG: InvokeResponseIBs = [1657181047.571749][45452:45457] CHIP:DMG: [ [1657181047.571809][45452:45457] CHIP:DMG: InvokeResponseIB = [1657181047.571889][45452:45457] CHIP:DMG: { [1657181047.571951][45452:45457] CHIP:DMG: CommandStatusIB = [1657181047.572032][45452:45457] CHIP:DMG: { [1657181047.572103][45452:45457] CHIP:DMG: CommandPathIB = [1657181047.572183][45452:45457] CHIP:DMG: { [1657181047.572263][45452:45457] CHIP:DMG: EndpointId = 0x0, [1657181047.572349][45452:45457] CHIP:DMG: ClusterId = 0x3e, [1657181047.572433][45452:45457] CHIP:DMG: CommandId = 0xb, [1657181047.572504][45452:45457] CHIP:DMG: }, [1657181047.572592][45452:45457] CHIP:DMG: [1657181047.572663][45452:45457] CHIP:DMG: StatusIB = [1657181047.572743][45452:45457] CHIP:DMG: { [1657181047.572825][45452:45457] CHIP:DMG: status = 0x00 (SUCCESS), [1657181047.572943][45452:45457] CHIP:DMG: }, [1657181047.573027][45452:45457] CHIP:DMG: [1657181047.573093][45452:45457] CHIP:DMG: }, [1657181047.573169][45452:45457] CHIP:DMG: [1657181047.573235][45452:45457] CHIP:DMG: }, [1657181047.573308][45452:45457] CHIP:DMG: [1657181047.573366][45452:45457] CHIP:DMG: ], [1657181047.573438][45452:45457] CHIP:DMG: [1657181047.573497][45452:45457] CHIP:DMG: InteractionModelRevision = 1 [1657181047.573565][45452:45457] CHIP:DMG: }, [1657181047.573696][45452:45457] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 [1657181047.573764][45452:45457] CHIP:CTL: Device confirmed that it has received the root certificate [1657181047.573826][45452:45457] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert' [1657181047.573880][45452:45457] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC' [1657181047.573941][45452:45457] CHIP:CTL: Performing next commissioning step 'SendNOC' [1657181047.574063][45452:45457] CHIP:DMG: ICR moving to [AddingComm] [1657181047.574145][45452:45457] CHIP:DMG: ICR moving to [AddedComma] [1657181047.574367][45452:45457] CHIP:IN: Prepared secure message 0xffffb27cc9c8 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 20339i with MessageCounter:81080697. [1657181047.574458][45452:45457] CHIP:IN: Sending encrypted msg 0xffffb27cc9c8 with MessageCounter:81080697 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000227D7CED msec [1657181047.574652][45452:45457] CHIP:DMG: ICR moving to [CommandSen] [1657181047.574724][45452:45457] CHIP:CTL: Sent operational certificate to the device [1657181047.574828][45452:45457] CHIP:DMG: ICR moving to [AwaitingDe] [1657181047.666163][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181047.763730][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181047.861454][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181049.374074][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181049.374301][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181049.374570][45452:45457] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:104862484 on exchange 20339i [1657181049.374647][45452:45457] CHIP:EM: Found matching exchange: 20339i, Delegate: 0xaaab0d2ded40 [1657181049.374730][45452:45457] CHIP:DMG: ICR moving to [ResponseRe] [1657181049.374828][45452:45457] CHIP:DMG: InvokeResponseMessage = [1657181049.374885][45452:45457] CHIP:DMG: { [1657181049.374942][45452:45457] CHIP:DMG: suppressResponse = false, [1657181049.375002][45452:45457] CHIP:DMG: InvokeResponseIBs = [1657181049.375078][45452:45457] CHIP:DMG: [ [1657181049.375137][45452:45457] CHIP:DMG: InvokeResponseIB = [1657181049.375218][45452:45457] CHIP:DMG: { [1657181049.375280][45452:45457] CHIP:DMG: CommandDataIB = [1657181049.375361][45452:45457] CHIP:DMG: { [1657181049.375432][45452:45457] CHIP:DMG: CommandPathIB = [1657181049.375520][45452:45457] CHIP:DMG: { [1657181049.375603][45452:45457] CHIP:DMG: EndpointId = 0x0, [1657181049.375687][45452:45457] CHIP:DMG: ClusterId = 0x3e, [1657181049.375776][45452:45457] CHIP:DMG: CommandId = 0x8, [1657181049.375851][45452:45457] CHIP:DMG: }, [1657181049.375932][45452:45457] CHIP:DMG: [1657181049.376004][45452:45457] CHIP:DMG: CommandFields = [1657181049.376076][45452:45457] CHIP:DMG: { [1657181049.376158][45452:45457] CHIP:DMG: 0x0 = 0, [1657181049.376241][45452:45457] CHIP:DMG: 0x1 = 1, [1657181049.376323][45452:45457] CHIP:DMG: }, [1657181049.376397][45452:45457] CHIP:DMG: }, [1657181049.376478][45452:45457] CHIP:DMG: [1657181049.376545][45452:45457] CHIP:DMG: }, [1657181049.376619][45452:45457] CHIP:DMG: [1657181049.376676][45452:45457] CHIP:DMG: ], [1657181049.376751][45452:45457] CHIP:DMG: [1657181049.376810][45452:45457] CHIP:DMG: InteractionModelRevision = 1 [1657181049.376867][45452:45457] CHIP:DMG: }, [1657181049.377095][45452:45457] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 [1657181049.377177][45452:45457] CHIP:CTL: Device returned status 0 on receiving the NOC [1657181049.377233][45452:45457] CHIP:CTL: Operational credentials provisioned on device 0xffffa8000b60 [1657181049.377307][45452:45457] CHIP:TOO: Secure Pairing Success [1657181049.377356][45452:45457] CHIP:TOO: CASE establishment successful [1657181049.377414][45452:45457] CHIP:CTL: Successfully finished commissioning step 'SendNOC' [1657181049.377469][45452:45457] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'ThreadNetworkSetup' [1657181049.377531][45452:45457] CHIP:CTL: Performing next commissioning step 'ThreadNetworkSetup' [1657181049.377645][45452:45457] CHIP:DMG: ICR moving to [AddingComm] [1657181049.377719][45452:45457] CHIP:DMG: ICR moving to [AddedComma] [1657181049.377891][45452:45457] CHIP:IN: Prepared secure message 0xffffb27cca08 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 20340i with MessageCounter:81080698. [1657181049.377983][45452:45457] CHIP:IN: Sending encrypted msg 0xffffb27cca08 with MessageCounter:81080698 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000227D83F9 msec [1657181049.378181][45452:45457] CHIP:DMG: ICR moving to [CommandSen] [1657181049.378302][45452:45457] CHIP:DMG: ICR moving to [AwaitingDe] [1657181049.470200][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181049.471947][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181049.472165][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181049.472420][45452:45457] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:104862485 on exchange 20340i [1657181049.472496][45452:45457] CHIP:EM: Found matching exchange: 20340i, Delegate: 0xffffa800efc0 [1657181049.472578][45452:45457] CHIP:DMG: ICR moving to [ResponseRe] [1657181049.472676][45452:45457] CHIP:DMG: InvokeResponseMessage = [1657181049.472727][45452:45457] CHIP:DMG: { [1657181049.472786][45452:45457] CHIP:DMG: suppressResponse = false, [1657181049.472845][45452:45457] CHIP:DMG: InvokeResponseIBs = [1657181049.472976][45452:45457] CHIP:DMG: [ [1657181049.473039][45452:45457] CHIP:DMG: InvokeResponseIB = [1657181049.473118][45452:45457] CHIP:DMG: { [1657181049.473180][45452:45457] CHIP:DMG: CommandDataIB = [1657181049.473255][45452:45457] CHIP:DMG: { [1657181049.473335][45452:45457] CHIP:DMG: CommandPathIB = [1657181049.473414][45452:45457] CHIP:DMG: { [1657181049.473496][45452:45457] CHIP:DMG: EndpointId = 0x0, [1657181049.473580][45452:45457] CHIP:DMG: ClusterId = 0x31, [1657181049.473670][45452:45457] CHIP:DMG: CommandId = 0x5, [1657181049.473749][45452:45457] CHIP:DMG: }, [1657181049.473824][45452:45457] CHIP:DMG: [1657181049.473898][45452:45457] CHIP:DMG: CommandFields = [1657181049.473978][45452:45457] CHIP:DMG: { [1657181049.474061][45452:45457] CHIP:DMG: 0x0 = 0, [1657181049.474144][45452:45457] CHIP:DMG: 0x2 = 0, [1657181049.474226][45452:45457] CHIP:DMG: }, [1657181049.474299][45452:45457] CHIP:DMG: }, [1657181049.474381][45452:45457] CHIP:DMG: [1657181049.474442][45452:45457] CHIP:DMG: }, [1657181049.474515][45452:45457] CHIP:DMG: [1657181049.474574][45452:45457] CHIP:DMG: ], [1657181049.474647][45452:45457] CHIP:DMG: [1657181049.474705][45452:45457] CHIP:DMG: InteractionModelRevision = 1 [1657181049.474761][45452:45457] CHIP:DMG: }, [1657181049.474898][45452:45457] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005 [1657181049.475029][45452:45457] CHIP:CTL: Received NetworkConfig response, networkingStatus=0 [1657181049.475100][45452:45457] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkSetup' [1657181049.475156][45452:45457] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkSetup' -> 'ThreadNetworkEnable' [1657181049.475218][45452:45457] CHIP:CTL: Performing next commissioning step 'ThreadNetworkEnable' [1657181049.475340][45452:45457] CHIP:DMG: ICR moving to [AddingComm] [1657181049.475414][45452:45457] CHIP:DMG: ICR moving to [AddedComma] [1657181049.475578][45452:45457] CHIP:IN: Prepared secure message 0xffffb27cca78 to 0xFFFFFFFB00000000 (0) of type 0x8 and protocolId (0, 1) on exchange 20341i with MessageCounter:81080699. [1657181049.475669][45452:45457] CHIP:IN: Sending encrypted msg 0xffffb27cca78 with MessageCounter:81080699 to 0xFFFFFFFB00000000 (0) at monotonic time: 00000000227D845A msec [1657181049.475882][45452:45457] CHIP:DMG: ICR moving to [CommandSen] [1657181049.476002][45452:45457] CHIP:DMG: ICR moving to [AwaitingDe] [1657181049.567279][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181051.713447][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181051.713603][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181051.713785][45452:45457] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:104862486 on exchange 20341i [1657181051.713830][45452:45457] CHIP:EM: Found matching exchange: 20341i, Delegate: 0xaaab0d2ded40 [1657181051.713878][45452:45457] CHIP:DMG: ICR moving to [ResponseRe] [1657181051.713940][45452:45457] CHIP:DMG: InvokeResponseMessage = [1657181051.713973][45452:45457] CHIP:DMG: { [1657181051.714005][45452:45457] CHIP:DMG: suppressResponse = false, [1657181051.714037][45452:45457] CHIP:DMG: InvokeResponseIBs = [1657181051.714075][45452:45457] CHIP:DMG: [ [1657181051.714107][45452:45457] CHIP:DMG: InvokeResponseIB = [1657181051.714157][45452:45457] CHIP:DMG: { [1657181051.714192][45452:45457] CHIP:DMG: CommandDataIB = [1657181051.714233][45452:45457] CHIP:DMG: { [1657181051.714276][45452:45457] CHIP:DMG: CommandPathIB = [1657181051.714321][45452:45457] CHIP:DMG: { [1657181051.714366][45452:45457] CHIP:DMG: EndpointId = 0x0, [1657181051.714412][45452:45457] CHIP:DMG: ClusterId = 0x31, [1657181051.714454][45452:45457] CHIP:DMG: CommandId = 0x7, [1657181051.714496][45452:45457] CHIP:DMG: }, [1657181051.714542][45452:45457] CHIP:DMG: [1657181051.714582][45452:45457] CHIP:DMG: CommandFields = [1657181051.714621][45452:45457] CHIP:DMG: { [1657181051.714665][45452:45457] CHIP:DMG: 0x0 = 0, [1657181051.714707][45452:45457] CHIP:DMG: 0x2 = NULL [1657181051.714752][45452:45457] CHIP:DMG: }, [1657181051.714794][45452:45457] CHIP:DMG: }, [1657181051.714838][45452:45457] CHIP:DMG: [1657181051.714872][45452:45457] CHIP:DMG: }, [1657181051.714915][45452:45457] CHIP:DMG: [1657181051.714947][45452:45457] CHIP:DMG: ], [1657181051.714988][45452:45457] CHIP:DMG: [1657181051.715021][45452:45457] CHIP:DMG: InteractionModelRevision = 1 [1657181051.715052][45452:45457] CHIP:DMG: }, [1657181051.715131][45452:45457] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007 [1657181051.715180][45452:45457] CHIP:CTL: Received ConnectNetwork response, networkingStatus=0 [1657181051.715219][45452:45457] CHIP:CTL: Successfully finished commissioning step 'ThreadNetworkEnable' [1657181051.715250][45452:45457] CHIP:CTL: Commissioning stage next step: 'ThreadNetworkEnable' -> 'FindOperational' [1657181051.715286][45452:45457] CHIP:CTL: Performing next commissioning step 'FindOperational' [1657181051.715317][45452:45457] CHIP:CSM: FindOrEstablishSession: PeerId = A4A2E578C9A5C677:0000000000000014 [1657181051.715348][45452:45457] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1657181051.715396][45452:45457] CHIP:CTL: OperationalDeviceProxy[A4A2E578C9A5C677:0000000000000014]: State change 1 --> 2 [1657181051.715436][45452:45457] CHIP:DIS: Resolving A4A2E578C9A5C677:0000000000000014 ... [1657181051.716699][45452:45457] CHIP:DIS: Operational node lookup already in progress. Will NOT start a new one. [1657181051.716782][45452:45457] CHIP:DMG: ICR moving to [AwaitingDe] [1657181051.915261][45452:45457] CHIP:DIS: Checking node lookup status after 200 ms [1657181053.906026][45452:45457] CHIP:DL: Avahi resolve found [1657181053.906175][45452:45457] CHIP:DIS: Node ID resolved for A4A2E578C9A5C677:0000000000000014 [1657181053.906240][45452:45457] CHIP:DIS: Hostname: 4612FAB3B85DE883 [1657181053.906309][45452:45457] CHIP:DIS: IP Address #1: fd11:22::d8d5:666c:2d87:2fd1 [1657181053.906367][45452:45457] CHIP:DIS: Port: 5540 [1657181053.906424][45452:45457] CHIP:DIS: Mrp Interval idle: 5000 ms [1657181053.906480][45452:45457] CHIP:DIS: Mrp Interval active: 300 ms [1657181053.907982][45452:45457] CHIP:DIS: Lookup clearing interface for non LL address [1657181053.908054][45452:45457] CHIP:DIS: UDP:[fd11:22::d8d5:666c:2d87:2fd1%docker0]:5540: new best score: 4 [1657181053.908112][45452:45457] CHIP:DIS: Checking node lookup status after 2193 ms [1657181053.908181][45452:45457] CHIP:CTL: Updating device address to UDP:[fd11:22::d8d5:666c:2d87:2fd1]:5540 while in state 2 [1657181053.908237][45452:45457] CHIP:CTL: OperationalDeviceProxy[A4A2E578C9A5C677:0000000000000014]: State change 2 --> 3 [1657181053.908484][45452:45457] CHIP:IN: SecureSession[0xffffa800d180]: Allocated Type:2 LSID:20325 [1657181053.908565][45452:45457] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000014 [1657181053.912420][45452:45457] CHIP:SC: Including MRP parameters [1657181053.913421][45452:45457] CHIP:IN: Prepared unauthenticated message 0xffffa8020fa8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 20342i with MessageCounter:220996872. [1657181053.913648][45452:45457] CHIP:IN: Sending unauthenticated msg 0xffffa8020fa8 with MessageCounter:220996872 to 0x0000000000000000 at monotonic time: 00000000227D95B0 msec [1657181053.914102][45452:45457] CHIP:SC: Sent Sigma1 msg [1657181053.914180][45452:45457] CHIP:CTL: OperationalDeviceProxy[A4A2E578C9A5C677:0000000000000014]: State change 3 --> 4 [1657181054.062777][45452:45457] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:227768855 on exchange 20342i [1657181054.062879][45452:45457] CHIP:EM: Found matching exchange: 20342i, Delegate: 0xffffa80140c0 [1657181054.062963][45452:45457] CHIP:EM: Rxd Ack; Removing MessageCounter:220996872 from Retrans Table on exchange 20342i [1657181054.063024][45452:45457] CHIP:EM: Removed CHIP MessageCounter:220996872 from RetransTable on exchange 20342i [1657181054.345417][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1657181055.633295][45452:45457] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:227768856 on exchange 20342i [1657181055.633400][45452:45457] CHIP:EM: Found matching exchange: 20342i, Delegate: 0xffffa80140c0 [1657181055.633464][45452:45457] CHIP:EM: CHIP MessageCounter:220996872 not in RetransTable on exchange 20342i [1657181055.633547][45452:45457] CHIP:SC: Received Sigma2 msg [1657181055.633616][45452:45457] CHIP:SC: Peer assigned session session ID 30628 [1657181055.642193][45452:45457] CHIP:SC: Found MRP parameters in the message [1657181055.642431][45452:45457] CHIP:SC: Sending Sigma3 [1657181055.644549][45452:45457] CHIP:EM: Piggybacking Ack for MessageCounter:227768856 on exchange: 20342i [1657181055.644613][45452:45457] CHIP:IN: Prepared unauthenticated message 0xffffa8014918 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 20342i with MessageCounter:220996873. [1657181055.644660][45452:45457] CHIP:IN: Sending unauthenticated msg 0xffffa8014918 with MessageCounter:220996873 to 0x0000000000000000 at monotonic time: 00000000227D9C73 msec [1657181055.644931][45452:45457] CHIP:SC: Sent Sigma3 msg [1657181055.973452][45452:45457] CHIP:EM: Retransmitting MessageCounter:220996873 on exchange 20342i Send Cnt 1 [1657181055.973653][45452:45457] CHIP:IN: Sending unauthenticated msg 0xffffa8014918 with MessageCounter:220996873 to 0x0000000000000000 at monotonic time: 00000000227D9DBC msec [1657181055.998619][45452:45457] CHIP:IN: Received a duplicate message with MessageCounter:227768856 on exchange 20342i [1657181055.998783][45452:45457] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:227768856 on exchange 20342i [1657181055.998839][45452:45457] CHIP:EM: Found matching exchange: 20342i, Delegate: 0xffffa80140c0 [1657181055.998886][45452:45457] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:227768856 on exchange 20342i [1657181055.998932][45452:45457] CHIP:EM: Sending Standalone Ack for MessageCounter:227768856 on exchange 20342i [1657181055.998999][45452:45457] CHIP:IN: Prepared unauthenticated message 0xffffb27cda18 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 20342i with MessageCounter:220996874. [1657181055.999066][45452:45457] CHIP:IN: Sending unauthenticated msg 0xffffb27cda18 with MessageCounter:220996874 to 0x0000000000000000 at monotonic time: 00000000227D9DD6 msec [1657181056.038363][45452:45457] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:227768857 on exchange 20342i [1657181056.038455][45452:45457] CHIP:EM: Found matching exchange: 20342i, Delegate: 0xffffa80140c0 [1657181056.038531][45452:45457] CHIP:EM: Rxd Ack; Removing MessageCounter:220996873 from Retrans Table on exchange 20342i [1657181056.038584][45452:45457] CHIP:EM: Removed CHIP MessageCounter:220996873 from RetransTable on exchange 20342i [1657181058.153617][45452:45457] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:227768858 on exchange 20342i [1657181058.153724][45452:45457] CHIP:EM: Found matching exchange: 20342i, Delegate: 0xffffa80140c0 [1657181058.153797][45452:45457] CHIP:EM: CHIP MessageCounter:220996873 not in RetransTable on exchange 20342i [1657181058.153888][45452:45457] CHIP:SC: Success status report received. Session was established [1657181058.172021][45452:45457] CHIP:SC: SecureSession[0xffffa800d180]: Moving from state 'kEstablishing' --> 'kActive' [1657181058.172076][45452:45457] CHIP:IN: SecureSession[0xffffa800d180]: Activated - Type:2 LSID:20325 [1657181058.172100][45452:45457] CHIP:IN: New secure session activated for device <0000000000000014, 1>, LSID:20325 PSID:30628! [1657181058.172131][45452:45457] CHIP:CTL: OperationalDeviceProxy[A4A2E578C9A5C677:0000000000000014]: State change 4 --> 5 [1657181058.172194][45452:45457] CHIP:CTL: Successfully finished commissioning step 'FindOperational' [1657181058.172223][45452:45457] CHIP:CTL: Commissioning stage next step: 'FindOperational' -> 'SendComplete' [1657181058.172252][45452:45457] CHIP:CTL: Performing next commissioning step 'SendComplete' [1657181058.172325][45452:45457] CHIP:DMG: ICR moving to [AddingComm] [1657181058.172358][45452:45457] CHIP:DMG: ICR moving to [AddedComma] [1657181058.172478][45452:45457] CHIP:IN: Prepared secure message 0xffffa801bf08 to 0x0000000000000014 (1) of type 0x8 and protocolId (0, 1) on exchange 20343i with MessageCounter:75635293. [1657181058.172525][45452:45457] CHIP:IN: Sending encrypted msg 0xffffa801bf08 with MessageCounter:75635293 to 0x0000000000000014 (1) at monotonic time: 00000000227DA653 msec [1657181058.172788][45452:45457] CHIP:DMG: ICR moving to [CommandSen] [1657181058.172836][45452:45457] CHIP:EM: Sending Standalone Ack for MessageCounter:227768858 on exchange 20342i [1657181058.172907][45452:45457] CHIP:IN: Prepared unauthenticated message 0xffffb27cd9c8 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 20342i with MessageCounter:220996875. [1657181058.172956][45452:45457] CHIP:IN: Sending unauthenticated msg 0xffffb27cd9c8 with MessageCounter:220996875 to 0x0000000000000000 at monotonic time: 00000000227DA654 msec [1657181058.173110][45452:45457] CHIP:EM: Flushed pending ack for MessageCounter:227768858 on exchange 20342i [1657181058.205482][45452:45457] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:227768859 on exchange 20342i [1657181058.205683][45452:45457] CHIP:EM: OnMessageReceived failed, err = ../../src/messaging/ExchangeMgr.cpp:274: CHIP Error 0x00000070: Unsolicited msg with originator bit clear [1657181058.294704][45452:45455] CHIP:DL: Indication received, conn = 0xffffa402d680 [1657181058.294935][45452:45457] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1657181058.365879][45452:45457] CHIP:EM: Received message of type 0x9 with protocolId (0, 1) and MessageCounter:166448080 on exchange 20343i [1657181058.365979][45452:45457] CHIP:EM: Found matching exchange: 20343i, Delegate: 0xaaab0d2ded40 [1657181058.366074][45452:45457] CHIP:EM: Rxd Ack; Removing MessageCounter:75635293 from Retrans Table on exchange 20343i [1657181058.366139][45452:45457] CHIP:EM: Removed CHIP MessageCounter:75635293 from RetransTable on exchange 20343i [1657181058.366216][45452:45457] CHIP:DMG: ICR moving to [ResponseRe] [1657181058.366321][45452:45457] CHIP:DMG: InvokeResponseMessage = [1657181058.366382][45452:45457] CHIP:DMG: { [1657181058.366439][45452:45457] CHIP:DMG: suppressResponse = false, [1657181058.366500][45452:45457] CHIP:DMG: InvokeResponseIBs = [1657181058.366577][45452:45457] CHIP:DMG: [ [1657181058.366637][45452:45457] CHIP:DMG: InvokeResponseIB = [1657181058.366718][45452:45457] CHIP:DMG: { [1657181058.366782][45452:45457] CHIP:DMG: CommandDataIB = [1657181058.366861][45452:45457] CHIP:DMG: { [1657181058.366934][45452:45457] CHIP:DMG: CommandPathIB = [1657181058.367017][45452:45457] CHIP:DMG: { [1657181058.367099][45452:45457] CHIP:DMG: EndpointId = 0x0, [1657181058.367187][45452:45457] CHIP:DMG: ClusterId = 0x30, [1657181058.367278][45452:45457] CHIP:DMG: CommandId = 0x5, [1657181058.367350][45452:45457] CHIP:DMG: }, [1657181058.367433][45452:45457] CHIP:DMG: [1657181058.367506][45452:45457] CHIP:DMG: CommandFields = [1657181058.367585][45452:45457] CHIP:DMG: { [1657181058.367669][45452:45457] CHIP:DMG: 0x0 = 0, [1657181058.367758][45452:45457] CHIP:DMG: 0x1 = "", [1657181058.367849][45452:45457] CHIP:DMG: }, [1657181058.367925][45452:45457] CHIP:DMG: }, [1657181058.368008][45452:45457] CHIP:DMG: [1657181058.368071][45452:45457] CHIP:DMG: }, [1657181058.368145][45452:45457] CHIP:DMG: [1657181058.368204][45452:45457] CHIP:DMG: ], [1657181058.368280][45452:45457] CHIP:DMG: [1657181058.368339][45452:45457] CHIP:DMG: InteractionModelRevision = 1 [1657181058.368396][45452:45457] CHIP:DMG: }, [1657181058.368535][45452:45457] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005 [1657181058.368618][45452:45457] CHIP:CTL: Received CommissioningComplete response, errorCode=0 [1657181058.368684][45452:45457] CHIP:CTL: Successfully finished commissioning step 'SendComplete' [1657181058.368739][45452:45457] CHIP:CTL: Commissioning stage next step: 'SendComplete' -> 'Cleanup' [1657181058.368799][45452:45457] CHIP:CTL: Performing next commissioning step 'Cleanup' [1657181058.368855][45452:45457] CHIP:DIS: Closing all BLE connections [1657181058.368956][45452:45457] CHIP:IN: Clearing BLE pending packets. [1657181058.369085][45452:45457] CHIP:BLE: Auto-closing end point's BLE connection. [1657181058.369148][45452:45457] CHIP:DL: Closing BLE GATT connection (con 0xffffa402d680) [1657181058.369290][45452:45457] CHIP:CTL: Successfully finished commissioning step 'Cleanup' [1657181058.369359][45452:45457] CHIP:TOO: Device commissioning completed with success [1657181058.369511][45452:45457] CHIP:DMG: ICR moving to [AwaitingDe] [1657181058.369587][45452:45457] CHIP:EM: Sending Standalone Ack for MessageCounter:166448080 on exchange 20343i [1657181058.369734][45452:45457] CHIP:IN: Prepared secure message 0xffffb27cd9d8 to 0x0000000000000014 (1) of type 0x10 and protocolId (0, 0) on exchange 20343i with MessageCounter:75635294. [1657181058.369828][45452:45457] CHIP:IN: Sending encrypted msg 0xffffb27cd9d8 with MessageCounter:75635294 to 0x0000000000000014 (1) at monotonic time: 00000000227DA718 msec [1657181058.369881][45452:45455] CHIP:DL: BluezDisconnect peer=46:6F:A7:1E:0A:95 [1657181058.370188][45452:45457] CHIP:EM: Flushed pending ack for MessageCounter:166448080 on exchange 20343i [1657181058.370683][45452:45452] CHIP:CTL: Shutting down the commissioner [1657181058.370760][45452:45452] CHIP:CTL: Shutting down the controller [1657181058.370853][45452:45452] CHIP:CTL: Shutting down the commissioner [1657181058.370906][45452:45452] CHIP:CTL: Shutting down the controller [1657181058.370972][45452:45452] CHIP:IN: Expiring all connections for fabric 1!! [1657181058.371029][45452:45452] CHIP:IN: SecureSession[0xffffa800d180]: MarkForEviction Type:2 LSID:20325 [1657181058.371086][45452:45452] CHIP:SC: SecureSession[0xffffa800d180]: Moving from state 'kActive' --> 'kPendingEviction' [1657181058.371166][45452:45452] CHIP:IN: SecureSession[0xffffa800d180]: Released - Type:2 LSID:20325 [1657181058.371227][45452:45452] CHIP:FP: Forgetting fabric 0x1 [1657181058.371320][45452:45452] CHIP:TS: Pending Last Known Good Time: 2022-07-06T07:34:20 [1657181058.372566][45452:45452] CHIP:TS: Previous Last Known Good Time: 2022-07-06T07:34:20 [1657181058.372654][45452:45452] CHIP:TS: Reverted Last Known Good Time to previous value [1657181058.372748][45452:45452] CHIP:CTL: Shutting down the commissioner [1657181058.372813][45452:45452] CHIP:CTL: Shutting down the controller [1657181058.372857][45452:45452] CHIP:IN: Expiring all connections for fabric 2!! [1657181058.372958][45452:45452] CHIP:FP: Forgetting fabric 0x2 [1657181058.373019][45452:45452] CHIP:TS: Pending Last Known Good Time: 2022-07-06T07:34:20 [1657181058.374129][45452:45452] CHIP:TS: Previous Last Known Good Time: 2022-07-06T07:34:20 [1657181058.374207][45452:45452] CHIP:TS: Reverted Last Known Good Time to previous value [1657181058.374299][45452:45452] CHIP:CTL: Shutting down the commissioner [1657181058.374354][45452:45452] CHIP:CTL: Shutting down the controller [1657181058.374407][45452:45452] CHIP:IN: Expiring all connections for fabric 3!! [1657181058.374460][45452:45452] CHIP:FP: Forgetting fabric 0x3 [1657181058.374523][45452:45452] CHIP:TS: Pending Last Known Good Time: 2022-07-06T07:34:20 [1657181058.375506][45452:45452] CHIP:TS: Previous Last Known Good Time: 2022-07-06T07:34:20 [1657181058.375571][45452:45452] CHIP:TS: Reverted Last Known Good Time to previous value [1657181058.375639][45452:45452] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1657181058.376599][45452:45452] CHIP:DMG: IM WH moving to [Uninitialized] [1657181058.376638][45452:45452] CHIP:DMG: IM WH moving to [Uninitialized] [1657181058.376659][45452:45452] CHIP:DMG: IM WH moving to [Uninitialized] [1657181058.376679][45452:45452] CHIP:DMG: IM WH moving to [Uninitialized] [1657181058.376701][45452:45452] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1657181058.376773][45452:45452] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1657181058.377158][45452:45452] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-exWxPt) [1657181058.377967][45452:45452] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1657181058.378034][45452:45452] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1657181058.378061][45452:45452] CHIP:DL: Inet Layer shutdown [1657181058.378082][45452:45452] CHIP:DL: BLE shutdown [1657181058.378782][45452:45452] CHIP:DL: System Layer shutdown [1657181058.378915][45452:45452] CHIP:IN: SecureSession[0xffffa8001b30]: Released - Type:1 LSID:20324 ubuntu@ubuntu:~/connectedhomeip_sve/out/debug$ sudo ./chip-tool generaldiagnostics read-event boot-reason 20 0 [1657181063.943732][45466:45466] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1657181063.944293][45466:45466] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1657181063.944453][45466:45466] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1657181063.944567][45466:45466] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1657181063.945051][45466:45466] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-sOOzj7) [1657181063.945695][45466:45466] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1657181063.945750][45466:45466] CHIP:DL: NVS set: chip-counters/reboot-count = 209 (0xD1) [1657181063.946618][45466:45466] CHIP:DL: Got Ethernet interface: eth0 [1657181063.947142][45466:45466] CHIP:DL: Found the primary Ethernet interface:eth0 [1657181063.947661][45466:45466] CHIP:DL: Got WiFi interface: wlan0 [1657181063.947740][45466:45466] CHIP:DL: Failed to reset WiFi statistic counts [1657181063.947796][45466:45466] CHIP:IN: UDP::Init bind&listen port=0 [1657181063.947939][45466:45466] CHIP:IN: UDP::Init bound to port=53214 [1657181063.947966][45466:45466] CHIP:IN: BLEBase::Init - setting/overriding transport [1657181063.947989][45466:45466] CHIP:IN: TransportMgr initialized [1657181063.948028][45466:45466] CHIP:FP: Initializing FabricTable from persistent storage [1657181063.948649][45466:45466] CHIP:TS: Last Known Good Time: 2022-07-06T07:34:20 [1657181063.950375][45466:45466] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xA4A2E578C9A5C677, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1657181063.951616][45466:45466] CHIP:FP: Fabric index 0x2 was retrieved from storage. Compressed FabricId 0xCA1F06D394A42031, FabricId 0x0000000000000002, NodeId 0x000000000001B669, VendorId 0xFFF1 [1657181063.952864][45466:45466] CHIP:FP: Fabric index 0x3 was retrieved from storage. Compressed FabricId 0xAD94C792A6262B1B, FabricId 0x0000000000000003, NodeId 0x000000000001B669, VendorId 0xFFF1 [1657181063.961609][45466:45466] CHIP:ZCL: Using ZAP configuration... [1657181063.965675][45466:45466] CHIP:DL: Avahi client registered [1657181063.966864][45466:45466] CHIP:CTL: System State Initialized... [1657181063.966970][45466:45466] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1657181063.967008][45466:45466] CHIP:CTL: Setting attestation nonce to random value [1657181063.967058][45466:45466] CHIP:CTL: Setting CSR nonce to random value [1657181063.967150][45466:45466] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1657181063.967178][45466:45466] CHIP:CTL: Setting attestation nonce to random value [1657181063.967223][45466:45466] CHIP:CTL: Setting CSR nonce to random value [1657181063.970405][45466:45466] CHIP:CTL: Generating NOC [1657181063.973209][45466:45466] CHIP:FP: Validating NOC chain [1657181063.975344][45466:45466] CHIP:FP: NOC chain validation successful [1657181063.975542][45466:45466] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1657181063.975582][45466:45466] CHIP:TS: Last Known Good Time: 2022-07-06T07:34:20 [1657181063.975612][45466:45466] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1657181063.975638][45466:45466] CHIP:TS: Retaining current Last Known Good Time [1657181063.976743][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to load node state: ../../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.977213][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to load node state: ../../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.977644][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to load node state: ../../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.978070][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to load node state: ../../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.978848][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.979519][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.980182][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.980850][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.981531][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.982199][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.982870][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.983537][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.984204][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.984876][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.985557][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.986228][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.986900][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.987569][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.988277][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.988964][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.989633][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.990303][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.990975][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.991647][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.992316][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.993004][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.993677][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.994347][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.995015][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.995685][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.996356][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.997060][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.997732][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.998430][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.999102][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181063.999773][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181064.000443][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181064.001130][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181064.001798][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181064.002470][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181064.003138][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181064.003806][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181064.004475][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181064.005160][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181064.005832][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181064.006498][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181064.007167][45466:45466] CHIP:SC: Session resumption cache deletion partially failed for fabric index 1, unable to delete node link: ../../examples/chip-tool/config/PersistentStorage.cpp:127: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181064.020300][45466:45466] CHIP:CTL: Warning, failed to delete session resumption state for fabric index 0x1: ../../examples/chip-tool/config/PersistentStorage.cpp:85: CHIP Error 0x000000A0: Value not found in the persisted storage [1657181064.028224][45466:45466] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1657181064.036429][45466:45466] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-06T07:34:20 [1657181064.043579][45466:45466] CHIP:CTL: Joined the fabric at index 1. Compressed fabric ID is: 0x0000000000000000 [1657181064.043702][45466:45466] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1657181064.043742][45466:45466] CHIP:CTL: Setting attestation nonce to random value [1657181064.043803][45466:45466] CHIP:CTL: Setting CSR nonce to random value [1657181064.044786][45466:45466] CHIP:CTL: Generating NOC [1657181064.046963][45466:45466] CHIP:FP: Validating NOC chain [1657181064.048684][45466:45466] CHIP:FP: NOC chain validation successful [1657181064.048841][45466:45466] CHIP:FP: Updated fabric at index: 0x2, Node ID: 0x000000000001B669 [1657181064.048872][45466:45466] CHIP:TS: Last Known Good Time: 2022-07-06T07:34:20 [1657181064.048949][45466:45466] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1657181064.048971][45466:45466] CHIP:TS: Retaining current Last Known Good Time [1657181064.056541][45466:45466] CHIP:FP: Metadata for Fabric 0x2 persisted to storage. [1657181064.063836][45466:45466] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-06T07:34:20 [1657181064.071044][45466:45466] CHIP:CTL: Joined the fabric at index 2. Compressed fabric ID is: 0x0000000000000000 [1657181064.071188][45466:45466] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1657181064.071227][45466:45466] CHIP:CTL: Setting attestation nonce to random value [1657181064.071289][45466:45466] CHIP:CTL: Setting CSR nonce to random value [1657181064.072275][45466:45466] CHIP:CTL: Generating NOC [1657181064.074422][45466:45466] CHIP:FP: Validating NOC chain [1657181064.076135][45466:45466] CHIP:FP: NOC chain validation successful [1657181064.076329][45466:45466] CHIP:FP: Updated fabric at index: 0x3, Node ID: 0x000000000001B669 [1657181064.076361][45466:45466] CHIP:TS: Last Known Good Time: 2022-07-06T07:34:20 [1657181064.076385][45466:45466] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1657181064.076407][45466:45466] CHIP:TS: Retaining current Last Known Good Time [1657181064.084005][45466:45466] CHIP:FP: Metadata for Fabric 0x3 persisted to storage. [1657181064.091410][45466:45466] CHIP:TS: Committing Last Known Good Time to storage: 2022-07-06T07:34:20 [1657181064.098569][45466:45466] CHIP:CTL: Joined the fabric at index 3. Compressed fabric ID is: 0x0000000000000000 [1657181064.202722][45466:45471] CHIP:DL: CHIP task running [1657181064.202951][45466:45471] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1657181064.202985][45466:45471] CHIP:TOO: Sending command to node 0x14 [1657181064.203021][45466:45471] CHIP:CSM: FindOrEstablishSession: PeerId = A4A2E578C9A5C677:0000000000000014 [1657181064.203047][45466:45471] CHIP:CSM: FindOrEstablishSession: No existing OperationalDeviceProxy instance found [1657181064.203085][45466:45471] CHIP:CTL: OperationalDeviceProxy[A4A2E578C9A5C677:0000000000000014]: State change 1 --> 2 [1657181064.203115][45466:45471] CHIP:DIS: Resolving A4A2E578C9A5C677:0000000000000014 ... [1657181064.204819][45466:45471] CHIP:DL: Avahi resolve found [1657181064.204920][45466:45471] CHIP:DIS: Node ID resolved for A4A2E578C9A5C677:0000000000000014 [1657181064.204948][45466:45471] CHIP:DIS: Hostname: 4612FAB3B85DE883 [1657181064.204976][45466:45471] CHIP:DIS: IP Address #1: fd11:22::d8d5:666c:2d87:2fd1 [1657181064.205000][45466:45471] CHIP:DIS: Port: 5540 [1657181064.205022][45466:45471] CHIP:DIS: Mrp Interval idle: 5000 ms [1657181064.205044][45466:45471] CHIP:DIS: Mrp Interval active: 300 ms [1657181064.205777][45466:45471] CHIP:DIS: Lookup clearing interface for non LL address [1657181064.205810][45466:45471] CHIP:DIS: UDP:[fd11:22::d8d5:666c:2d87:2fd1%docker0]:5540: new best score: 4 [1657181064.205835][45466:45471] CHIP:DIS: Checking node lookup status after 2 ms [1657181064.205857][45466:45471] CHIP:DIS: Keeping DNSSD lookup active [1657181064.404151][45466:45471] CHIP:DIS: Checking node lookup status after 201 ms [1657181064.404255][45466:45471] CHIP:CTL: Updating device address to UDP:[fd11:22::d8d5:666c:2d87:2fd1]:5540 while in state 2 [1657181064.404311][45466:45471] CHIP:CTL: OperationalDeviceProxy[A4A2E578C9A5C677:0000000000000014]: State change 2 --> 3 [1657181064.404684][45466:45471] CHIP:IN: SecureSession[0xffff88001930]: Allocated Type:2 LSID:32306 [1657181064.404772][45466:45471] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000014 [1657181064.408603][45466:45471] CHIP:SC: Including MRP parameters [1657181064.409599][45466:45471] CHIP:IN: Prepared unauthenticated message 0xffff88002fd8 to 0x0000000000000000 (0) of type 0x30 and protocolId (0, 0) on exchange 58773i with MessageCounter:241426311. [1657181064.409704][45466:45471] CHIP:IN: Sending unauthenticated msg 0xffff88002fd8 with MessageCounter:241426311 to 0x0000000000000000 at monotonic time: 00000000227DBEB0 msec [1657181064.410136][45466:45471] CHIP:SC: Sent Sigma1 msg [1657181064.410209][45466:45471] CHIP:CTL: OperationalDeviceProxy[A4A2E578C9A5C677:0000000000000014]: State change 3 --> 4 [1657181064.586039][45466:45471] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:227768860 on exchange 58773i [1657181064.586124][45466:45471] CHIP:EM: Found matching exchange: 58773i, Delegate: 0xffff880011a0 [1657181064.586192][45466:45471] CHIP:EM: Rxd Ack; Removing MessageCounter:241426311 from Retrans Table on exchange 58773i [1657181064.586237][45466:45471] CHIP:EM: Removed CHIP MessageCounter:241426311 from RetransTable on exchange 58773i [1657181066.111069][45466:45471] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:227768861 on exchange 58773i [1657181066.111166][45466:45471] CHIP:EM: Found matching exchange: 58773i, Delegate: 0xffff880011a0 [1657181066.111268][45466:45471] CHIP:EM: CHIP MessageCounter:241426311 not in RetransTable on exchange 58773i [1657181066.111351][45466:45471] CHIP:SC: Received Sigma2 msg [1657181066.111420][45466:45471] CHIP:SC: Peer assigned session session ID 30629 [1657181066.118939][45466:45471] CHIP:SC: Found MRP parameters in the message [1657181066.119032][45466:45471] CHIP:SC: Sending Sigma3 [1657181066.121413][45466:45471] CHIP:EM: Piggybacking Ack for MessageCounter:227768861 on exchange: 58773i [1657181066.121519][45466:45471] CHIP:IN: Prepared unauthenticated message 0xffff88000ec8 to 0x0000000000000000 (0) of type 0x32 and protocolId (0, 0) on exchange 58773i with MessageCounter:241426312. [1657181066.121600][45466:45471] CHIP:IN: Sending unauthenticated msg 0xffff88000ec8 with MessageCounter:241426312 to 0x0000000000000000 at monotonic time: 00000000227DC560 msec [1657181066.122046][45466:45471] CHIP:SC: Sent Sigma3 msg [1657181066.394644][45466:45471] CHIP:IN: Received a duplicate message with MessageCounter:227768861 on exchange 58773i [1657181066.394751][45466:45471] CHIP:EM: Received message of type 0x31 with protocolId (0, 0) and MessageCounter:227768861 on exchange 58773i [1657181066.394822][45466:45471] CHIP:EM: Found matching exchange: 58773i, Delegate: 0xffff880011a0 [1657181066.394874][45466:45471] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:227768861 on exchange 58773i [1657181066.394931][45466:45471] CHIP:EM: Sending Standalone Ack for MessageCounter:227768861 on exchange 58773i [1657181066.395035][45466:45471] CHIP:IN: Prepared unauthenticated message 0xffff9c9b8a18 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 58773i with MessageCounter:241426313. [1657181066.395123][45466:45471] CHIP:IN: Sending unauthenticated msg 0xffff9c9b8a18 with MessageCounter:241426313 to 0x0000000000000000 at monotonic time: 00000000227DC672 msec [1657181066.413081][45466:45471] CHIP:EM: Received message of type 0x10 with protocolId (0, 0) and MessageCounter:227768862 on exchange 58773i [1657181066.413175][45466:45471] CHIP:EM: Found matching exchange: 58773i, Delegate: 0xffff880011a0 [1657181066.413243][45466:45471] CHIP:EM: Rxd Ack; Removing MessageCounter:241426312 from Retrans Table on exchange 58773i [1657181066.413288][45466:45471] CHIP:EM: Removed CHIP MessageCounter:241426312 from RetransTable on exchange 58773i [1657181068.619506][45466:45471] CHIP:EM: Received message of type 0x40 with protocolId (0, 0) and MessageCounter:227768863 on exchange 58773i [1657181068.619614][45466:45471] CHIP:EM: Found matching exchange: 58773i, Delegate: 0xffff880011a0 [1657181068.619682][45466:45471] CHIP:EM: CHIP MessageCounter:241426312 not in RetransTable on exchange 58773i [1657181068.619777][45466:45471] CHIP:SC: Success status report received. Session was established [1657181068.648905][45466:45471] CHIP:SC: SecureSession[0xffff88001930]: Moving from state 'kEstablishing' --> 'kActive' [1657181068.648965][45466:45471] CHIP:IN: SecureSession[0xffff88001930]: Activated - Type:2 LSID:32306 [1657181068.648996][45466:45471] CHIP:IN: New secure session activated for device <0000000000000014, 1>, LSID:32306 PSID:30629! [1657181068.649035][45466:45471] CHIP:CTL: OperationalDeviceProxy[A4A2E578C9A5C677:0000000000000014]: State change 4 --> 5 [1657181068.649112][45466:45471] CHIP:TOO: Sending ReadEvent to: [1657181068.649177][45466:45471] CHIP:TOO: cluster 0x0000_0033, event: 0x0000_0003, endpoint 0 [1657181068.649234][45466:45471] CHIP:DMG: SendReadRequest ReadClient[0xffff880151d0]: Sending Read Request [1657181068.649397][45466:45471] CHIP:IN: Prepared secure message 0xffff88013868 to 0x0000000000000014 (1) of type 0x2 and protocolId (0, 1) on exchange 58774i with MessageCounter:65544630. [1657181068.649455][45466:45471] CHIP:IN: Sending encrypted msg 0xffff88013868 with MessageCounter:65544630 to 0x0000000000000014 (1) at monotonic time: 00000000227DCF40 msec [1657181068.649756][45466:45471] CHIP:DMG: MoveToState ReadClient[0xffff880151d0]: Moving to [AwaitingIn] [1657181068.649827][45466:45471] CHIP:EM: Sending Standalone Ack for MessageCounter:227768863 on exchange 58773i [1657181068.649885][45466:45471] CHIP:IN: Prepared unauthenticated message 0xffff9c9b89c8 to 0x0000000000000000 (0) of type 0x10 and protocolId (0, 0) on exchange 58773i with MessageCounter:241426314. [1657181068.649935][45466:45471] CHIP:IN: Sending unauthenticated msg 0xffff9c9b89c8 with MessageCounter:241426314 to 0x0000000000000000 at monotonic time: 00000000227DCF41 msec [1657181068.650095][45466:45471] CHIP:EM: Flushed pending ack for MessageCounter:227768863 on exchange 58773i [1657181068.825955][45466:45471] CHIP:EM: Received message of type 0x5 with protocolId (0, 1) and MessageCounter:212214313 on exchange 58774i [1657181068.826058][45466:45471] CHIP:EM: Found matching exchange: 58774i, Delegate: 0xffff880151d0 [1657181068.826141][45466:45471] CHIP:EM: Rxd Ack; Removing MessageCounter:65544630 from Retrans Table on exchange 58774i [1657181068.826201][45466:45471] CHIP:EM: Removed CHIP MessageCounter:65544630 from RetransTable on exchange 58774i [1657181068.826307][45466:45471] CHIP:DMG: ReportDataMessage = [1657181068.826372][45466:45471] CHIP:DMG: { [1657181068.826430][45466:45471] CHIP:DMG: SuppressResponse = true, [1657181068.826489][45466:45471] CHIP:DMG: InteractionModelRevision = 1 [1657181068.826547][45466:45471] CHIP:DMG: } [1657181068.826701][45466:45471] CHIP:EM: Sending Standalone Ack for MessageCounter:212214313 on exchange 58774i [1657181068.826831][45466:45471] CHIP:IN: Prepared secure message 0xffff9c9b89d8 to 0x0000000000000014 (1) of type 0x10 and protocolId (0, 0) on exchange 58774i with MessageCounter:65544631. [1657181068.826917][45466:45471] CHIP:IN: Sending encrypted msg 0xffff9c9b89d8 with MessageCounter:65544631 to 0x0000000000000014 (1) at monotonic time: 00000000227DCFF2 msec [1657181068.827229][45466:45471] CHIP:EM: Flushed pending ack for MessageCounter:212214313 on exchange 58774i [1657181068.827616][45466:45466] CHIP:CTL: Shutting down the commissioner [1657181068.827698][45466:45466] CHIP:CTL: Shutting down the controller [1657181068.827764][45466:45466] CHIP:CTL: Shutting down the commissioner [1657181068.827819][45466:45466] CHIP:CTL: Shutting down the controller [1657181068.827884][45466:45466] CHIP:IN: Expiring all connections for fabric 1!! [1657181068.827939][45466:45466] CHIP:IN: SecureSession[0xffff88001930]: MarkForEviction Type:2 LSID:32306 [1657181068.827994][45466:45466] CHIP:SC: SecureSession[0xffff88001930]: Moving from state 'kActive' --> 'kPendingEviction' [1657181068.828113][45466:45466] CHIP:IN: SecureSession[0xffff88001930]: Released - Type:2 LSID:32306 [1657181068.828176][45466:45466] CHIP:FP: Forgetting fabric 0x1 [1657181068.828247][45466:45466] CHIP:TS: Pending Last Known Good Time: 2022-07-06T07:34:20 [1657181068.829352][45466:45466] CHIP:TS: Previous Last Known Good Time: 2022-07-06T07:34:20 [1657181068.829429][45466:45466] CHIP:TS: Reverted Last Known Good Time to previous value [1657181068.829520][45466:45466] CHIP:CTL: Shutting down the commissioner [1657181068.829577][45466:45466] CHIP:CTL: Shutting down the controller [1657181068.829628][45466:45466] CHIP:IN: Expiring all connections for fabric 2!! [1657181068.829680][45466:45466] CHIP:FP: Forgetting fabric 0x2 [1657181068.829740][45466:45466] CHIP:TS: Pending Last Known Good Time: 2022-07-06T07:34:20 [1657181068.830634][45466:45466] CHIP:TS: Previous Last Known Good Time: 2022-07-06T07:34:20 [1657181068.830695][45466:45466] CHIP:TS: Reverted Last Known Good Time to previous value [1657181068.830769][45466:45466] CHIP:CTL: Shutting down the commissioner [1657181068.830822][45466:45466] CHIP:CTL: Shutting down the controller [1657181068.830872][45466:45466] CHIP:IN: Expiring all connections for fabric 3!! [1657181068.830922][45466:45466] CHIP:FP: Forgetting fabric 0x3 [1657181068.830980][45466:45466] CHIP:TS: Pending Last Known Good Time: 2022-07-06T07:34:20 [1657181068.831857][45466:45466] CHIP:TS: Previous Last Known Good Time: 2022-07-06T07:34:20 [1657181068.831916][45466:45466] CHIP:TS: Reverted Last Known Good Time to previous value [1657181068.831984][45466:45466] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1657181068.834024][45466:45466] CHIP:DMG: IM WH moving to [Uninitialized] [1657181068.834102][45466:45466] CHIP:DMG: IM WH moving to [Uninitialized] [1657181068.834128][45466:45466] CHIP:DMG: IM WH moving to [Uninitialized] [1657181068.834152][45466:45466] CHIP:DMG: IM WH moving to [Uninitialized] [1657181068.834179][45466:45466] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1657181068.834367][45466:45466] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1657181068.834708][45466:45466] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-tqGzki) [1657181068.835703][45466:45466] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1657181068.835799][45466:45466] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1657181068.835838][45466:45466] CHIP:DL: Inet Layer shutdown [1657181068.835870][45466:45466] CHIP:DL: BLE shutdown [1657181068.835903][45466:45466] CHIP:DL: System Layer shutdown ubuntu@ubuntu:~/connectedhomeip_sve/out/debug$