./chip-tool pairing ble-wifi 0x7283 Chhatrapati 1234567890 20202021 3840 [1685988536.043785][834669:834669] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1685988536.045601][834669:834669] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1685988536.045642][834669:834669] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1685988536.045662][834669:834669] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1685988536.045851][834669:834669] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-8GTlgH) [1685988536.046217][834669:834669] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685988536.046225][834669:834669] CHIP:DL: NVS set: chip-counters/reboot-count = 67 (0x43) [1685988536.047658][834669:834669] CHIP:DL: Got Ethernet interface: enp2s0f0 [1685988536.047808][834669:834669] CHIP:DL: Found the primary Ethernet interface:enp2s0f0 [1685988536.047980][834669:834669] CHIP:DL: Got WiFi interface: wlp3s0 [1685988536.049773][834669:834669] CHIP:DL: Found the primary WiFi interface:wlp3s0 [1685988536.049803][834669:834669] CHIP:IN: UDP::Init bind&listen port=0 [1685988536.049822][834669:834669] CHIP:IN: UDP::Init bound to port=32846 [1685988536.049825][834669:834669] CHIP:IN: UDP::Init bind&listen port=0 [1685988536.049834][834669:834669] CHIP:IN: UDP::Init bound to port=41545 [1685988536.049837][834669:834669] CHIP:IN: BLEBase::Init - setting/overriding transport [1685988536.049838][834669:834669] CHIP:IN: TransportMgr initialized [1685988536.049846][834669:834669] CHIP:FP: Initializing FabricTable from persistent storage [1685988536.049885][834669:834669] CHIP:TS: Last Known Good Time: 2023-06-05T15:07:23 [1685988536.050240][834669:834669] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x7DFDC0CC2967173B, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1685988536.073793][834669:834669] CHIP:ZCL: Using ZAP configuration... [1685988536.075610][834669:834669] CHIP:CTL: System State Initialized... [1685988536.075634][834669:834669] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988536.075655][834669:834669] CHIP:CTL: Setting attestation nonce to random value [1685988536.075660][834669:834669] CHIP:CTL: Setting CSR nonce to random value [1685988536.075688][834669:834669] CHIP:IN: UDP::Init bind&listen port=5550 [1685988536.075698][834669:834669] CHIP:IN: UDP::Init bound to port=5550 [1685988536.075701][834669:834669] CHIP:IN: UDP::Init bind&listen port=5550 [1685988536.075714][834669:834669] CHIP:IN: UDP::Init bound to port=5550 [1685988536.075715][834669:834669] CHIP:IN: TransportMgr initialized [1685988536.075826][834669:834671] CHIP:DL: CHIP task running [1685988536.075863][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1685988536.075965][834669:834671] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988536.075971][834669:834671] CHIP:CTL: Setting attestation nonce to random value [1685988536.075993][834669:834671] CHIP:CTL: Setting CSR nonce to random value [1685988536.076330][834669:834671] CHIP:CTL: Generating NOC [1685988536.076620][834669:834671] CHIP:FP: Validating NOC chain [1685988536.077012][834669:834671] CHIP:FP: NOC chain validation successful [1685988536.077048][834669:834671] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1685988536.077053][834669:834671] CHIP:TS: Last Known Good Time: 2023-06-05T15:07:23 [1685988536.077055][834669:834671] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1685988536.077058][834669:834671] CHIP:TS: Retaining current Last Known Good Time [1685988536.077377][834669:834671] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1685988536.077669][834669:834671] CHIP:TS: Committing Last Known Good Time to storage: 2023-06-05T15:07:23 [1685988536.077945][834669:834671] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 7DFDC0CC2967173B) [1685988536.077954][834669:834671] CHIP:IN: UDP::Init bind&listen port=5550 [1685988536.077988][834669:834671] CHIP:IN: UDP::Init bound to port=5550 [1685988536.077993][834669:834671] CHIP:IN: UDP::Init bind&listen port=5550 [1685988536.078007][834669:834671] CHIP:IN: UDP::Init bound to port=5550 [1685988536.078011][834669:834671] CHIP:IN: TransportMgr initialized [1685988536.080103][834669:834671] CHIP:CTL: Setting wifi credentials from parameters [1685988536.080107][834669:834671] CHIP:CTL: Setting attestation nonce to random value [1685988536.080112][834669:834671] CHIP:CTL: Setting CSR nonce to random value [1685988536.080116][834669:834671] CHIP:CTL: Commission called for node ID 0x0000000000007283 [1685988536.081919][834669:834670] CHIP:DL: TRACE: Bus acquired for name C-bc6d [1685988536.083703][834669:834671] CHIP:DL: PlatformBlueZInit init success [1685988536.085014][834669:834670] CHIP:BLE: BLE removing known devices. [1685988538.371086][834669:834670] CHIP:BLE: BLE initiating scan. [1685988538.426224][834669:834671] CHIP:DL: Long dispatch time: 2346 ms, for event type 2 [1685988538.426301][834669:834670] CHIP:BLE: New device scanned: F2:E4:E2:24:9E:41 [1685988538.426327][834669:834670] CHIP:BLE: Device discriminator match. Attempting to connect. [1685988538.684537][834669:834670] CHIP:DL: ConnectDevice complete [1685988539.548233][834669:834670] CHIP:DL: Char1 /org/bluez/hci0/dev_F2_E4_E2_24_9E_41/service0006 [1685988539.548256][834669:834670] CHIP:DL: Char1 /org/bluez/hci0/dev_F2_E4_E2_24_9E_41/service000a [1685988539.548261][834669:834670] CHIP:DL: Char1 /org/bluez/hci0/dev_F2_E4_E2_24_9E_41/service0006 [1685988539.548264][834669:834670] CHIP:DL: Char1 /org/bluez/hci0/dev_F2_E4_E2_24_9E_41/service000a [1685988539.548268][834669:834670] CHIP:DL: Char1 /org/bluez/hci0/dev_F2_E4_E2_24_9E_41/service0006 [1685988539.548271][834669:834670] CHIP:DL: Char1 /org/bluez/hci0/dev_F2_E4_E2_24_9E_41/service000a [1685988539.548276][834669:834670] CHIP:DL: Char1 /org/bluez/hci0/dev_F2_E4_E2_24_9E_41/service000a [1685988539.548279][834669:834670] CHIP:DL: Char1 /org/bluez/hci0/dev_F2_E4_E2_24_9E_41/service000a [1685988539.548288][834669:834670] CHIP:DL: Char1 /org/bluez/hci0/dev_F2_E4_E2_24_9E_41/service000a [1685988539.548296][834669:834670] CHIP:DL: Char1 /org/bluez/hci0/dev_F2_E4_E2_24_9E_41/service000a [1685988539.548309][834669:834670] CHIP:DL: Char1 /org/bluez/hci0/dev_F2_E4_E2_24_9E_41/service000a [1685988539.548316][834669:834670] CHIP:DL: Char1 /org/bluez/hci0/dev_F2_E4_E2_24_9E_41/service000a [1685988539.548329][834669:834670] CHIP:DL: New BLE connection 0x7fbe9003bce0, device F2:E4:E2:24:9E:41, path /org/bluez/hci0/dev_F2_E4_E2_24_9E_41 [1685988539.548442][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16385 [1685988539.548463][834669:834671] CHIP:DIS: Closing all BLE connections [1685988539.548495][834669:834671] CHIP:IN: BleConnectionComplete: endPoint 0x561a0cc15da0 [1685988539.548778][834669:834671] CHIP:IN: SecureSession[0x7fbe88012b00]: Allocated Type:1 LSID:49793 [1685988539.548798][834669:834671] CHIP:SC: Assigned local session key ID 49793 [1685988539.548866][834669:834671] CHIP:EM: <<< [E:16292i S:0 M:13186440] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) [1685988539.548887][834669:834671] CHIP:IN: (U) Sending msg 13186440 to IP address 'BLE' [1685988539.548898][834669:834671] CHIP:IN: Message appended to BLE send queue [1685988539.548904][834669:834671] CHIP:SC: Sent PBKDF param request [1685988539.944248][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988540.034482][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988540.034549][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16388 [1685988540.034578][834669:834671] CHIP:BLE: subscribe complete, ep = 0x561a0cc15da0 [1685988540.034598][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988540.034613][834669:834671] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4 [1685988540.034625][834669:834671] CHIP:BLE: using BTP fragment sizes rx 244 / tx 244. [1685988540.034631][834669:834671] CHIP:BLE: local and remote recv window size = 5 [1685988540.034803][834669:834671] CHIP:IN: BLE EndPoint 0x561a0cc15da0 Connection Complete [1685988540.123811][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988540.216134][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988540.216308][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988540.216418][834669:834671] CHIP:EM: >>> [E:16292i S:0 M:125335175] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) [1685988540.216433][834669:834671] CHIP:EM: Found matching exchange: 16292i, Delegate: 0x7fbe8800dad0 [1685988540.216447][834669:834671] CHIP:SC: Received PBKDF param response [1685988540.216468][834669:834671] CHIP:SC: Peer assigned session ID 17165 [1685988540.218106][834669:834671] CHIP:EM: <<< [E:16292i S:0 M:13186441] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) [1685988540.218115][834669:834671] CHIP:IN: (U) Sending msg 13186441 to IP address 'BLE' [1685988540.218236][834669:834671] CHIP:SC: Sent spake2p msg1 [1685988540.303541][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988540.982611][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988540.982809][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988540.982933][834669:834671] CHIP:EM: >>> [E:16292i S:0 M:125335176] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) [1685988540.982950][834669:834671] CHIP:EM: Found matching exchange: 16292i, Delegate: 0x7fbe8800dad0 [1685988540.982964][834669:834671] CHIP:SC: Received spake2p msg2 [1685988540.983662][834669:834671] CHIP:EM: <<< [E:16292i S:0 M:13186442] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) [1685988540.983679][834669:834671] CHIP:IN: (U) Sending msg 13186442 to IP address 'BLE' [1685988540.983978][834669:834671] CHIP:SC: Sent spake2p msg3 [1685988541.068930][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988541.114935][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988541.115019][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988541.115080][834669:834671] CHIP:EM: >>> [E:16292i S:0 M:125335177] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685988541.115092][834669:834671] CHIP:EM: Found matching exchange: 16292i, Delegate: 0x7fbe8800dad0 [1685988541.115198][834669:834671] CHIP:SC: SecureSession[0x7fbe88012b00, LSID:49793]: State change 'kEstablishing' --> 'kActive' [1685988541.115201][834669:834671] CHIP:IN: SecureSession[0x7fbe88012b00]: Activated - Type:1 LSID:49793 [1685988541.115202][834669:834671] CHIP:IN: New secure session activated for device , LSID:49793 PSID:17165! [1685988541.115208][834669:834671] CHIP:CTL: Remote device completed SPAKE2+ handshake [1685988541.115210][834669:834671] CHIP:TOO: Pairing Success [1685988541.115211][834669:834671] CHIP:TOO: PASE establishment successful [1685988541.115214][834669:834671] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' [1685988541.115217][834669:834671] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' [1685988541.115219][834669:834671] CHIP:CTL: Sending request for commissioning information [1685988541.115231][834669:834671] CHIP:DMG: SendReadRequest ReadClient[0x7fbe88011e70]: Sending Read Request [1685988541.115283][834669:834671] CHIP:EM: <<< [E:16293i S:49793 M:12672778] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) [1685988541.115288][834669:834671] CHIP:IN: (S) Sending msg 12672778 on secure session with LSID: 49793 [1685988541.115418][834669:834671] CHIP:DMG: MoveToState ReadClient[0x7fbe88011e70]: Moving to [AwaitingIn] [1685988541.203033][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988541.255678][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988541.255852][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988541.340399][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988541.340568][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988541.340879][834669:834671] CHIP:EM: >>> [E:16293i S:49793 M:92440513] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [1685988541.340909][834669:834671] CHIP:EM: Found matching exchange: 16293i, Delegate: 0x7fbe88011e80 [1685988541.341002][834669:834671] CHIP:DMG: ReportDataMessage = [1685988541.341015][834669:834671] CHIP:DMG: { [1685988541.341023][834669:834671] CHIP:DMG: AttributeReportIBs = [1685988541.341035][834669:834671] CHIP:DMG: [ [1685988541.341041][834669:834671] CHIP:DMG: AttributeReportIB = [1685988541.341054][834669:834671] CHIP:DMG: { [1685988541.341067][834669:834671] CHIP:DMG: AttributeDataIB = [1685988541.341076][834669:834671] CHIP:DMG: { [1685988541.341088][834669:834671] CHIP:DMG: DataVersion = 0x1b3bbbb6, [1685988541.341096][834669:834671] CHIP:DMG: AttributePathIB = [1685988541.341105][834669:834671] CHIP:DMG: { [1685988541.341113][834669:834671] CHIP:DMG: Endpoint = 0x0, [1685988541.341121][834669:834671] CHIP:DMG: Cluster = 0x31, [1685988541.341129][834669:834671] CHIP:DMG: Attribute = 0x0000_0003, [1685988541.341136][834669:834671] CHIP:DMG: } [1685988541.341152][834669:834671] CHIP:DMG: [1685988541.341162][834669:834671] CHIP:DMG: Data = 30, [1685988541.341167][834669:834671] CHIP:DMG: }, [1685988541.341175][834669:834671] CHIP:DMG: [1685988541.341178][834669:834671] CHIP:DMG: }, [1685988541.341184][834669:834671] CHIP:DMG: [1685988541.341186][834669:834671] CHIP:DMG: AttributeReportIB = [1685988541.341191][834669:834671] CHIP:DMG: { [1685988541.341194][834669:834671] CHIP:DMG: AttributeDataIB = [1685988541.341197][834669:834671] CHIP:DMG: { [1685988541.341199][834669:834671] CHIP:DMG: DataVersion = 0x88ccc67e, [1685988541.341202][834669:834671] CHIP:DMG: AttributePathIB = [1685988541.341206][834669:834671] CHIP:DMG: { [1685988541.341208][834669:834671] CHIP:DMG: Endpoint = 0x0, [1685988541.341212][834669:834671] CHIP:DMG: Cluster = 0x28, [1685988541.341214][834669:834671] CHIP:DMG: Attribute = 0x0000_0004, [1685988541.341217][834669:834671] CHIP:DMG: } [1685988541.341221][834669:834671] CHIP:DMG: [1685988541.341224][834669:834671] CHIP:DMG: Data = 32768, [1685988541.341226][834669:834671] CHIP:DMG: }, [1685988541.341230][834669:834671] CHIP:DMG: [1685988541.341233][834669:834671] CHIP:DMG: }, [1685988541.341239][834669:834671] CHIP:DMG: [1685988541.341242][834669:834671] CHIP:DMG: AttributeReportIB = [1685988541.341246][834669:834671] CHIP:DMG: { [1685988541.341249][834669:834671] CHIP:DMG: AttributeDataIB = [1685988541.341253][834669:834671] CHIP:DMG: { [1685988541.341255][834669:834671] CHIP:DMG: DataVersion = 0x88ccc67e, [1685988541.341258][834669:834671] CHIP:DMG: AttributePathIB = [1685988541.341261][834669:834671] CHIP:DMG: { [1685988541.341264][834669:834671] CHIP:DMG: Endpoint = 0x0, [1685988541.341267][834669:834671] CHIP:DMG: Cluster = 0x28, [1685988541.341270][834669:834671] CHIP:DMG: Attribute = 0x0000_0002, [1685988541.341273][834669:834671] CHIP:DMG: } [1685988541.341277][834669:834671] CHIP:DMG: [1685988541.341280][834669:834671] CHIP:DMG: Data = 65521, [1685988541.341282][834669:834671] CHIP:DMG: }, [1685988541.341286][834669:834671] CHIP:DMG: [1685988541.341288][834669:834671] CHIP:DMG: }, [1685988541.341293][834669:834671] CHIP:DMG: [1685988541.341295][834669:834671] CHIP:DMG: AttributeReportIB = [1685988541.341300][834669:834671] CHIP:DMG: { [1685988541.341302][834669:834671] CHIP:DMG: AttributeDataIB = [1685988541.341305][834669:834671] CHIP:DMG: { [1685988541.341308][834669:834671] CHIP:DMG: DataVersion = 0xe885b772, [1685988541.341310][834669:834671] CHIP:DMG: AttributePathIB = [1685988541.341313][834669:834671] CHIP:DMG: { [1685988541.341316][834669:834671] CHIP:DMG: Endpoint = 0x0, [1685988541.341319][834669:834671] CHIP:DMG: Cluster = 0x30, [1685988541.341322][834669:834671] CHIP:DMG: Attribute = 0x0000_0003, [1685988541.341326][834669:834671] CHIP:DMG: } [1685988541.341330][834669:834671] CHIP:DMG: [1685988541.341333][834669:834671] CHIP:DMG: Data = 0, [1685988541.341335][834669:834671] CHIP:DMG: }, [1685988541.341339][834669:834671] CHIP:DMG: [1685988541.341341][834669:834671] CHIP:DMG: }, [1685988541.341347][834669:834671] CHIP:DMG: [1685988541.341349][834669:834671] CHIP:DMG: AttributeReportIB = [1685988541.341353][834669:834671] CHIP:DMG: { [1685988541.341355][834669:834671] CHIP:DMG: AttributeDataIB = [1685988541.341358][834669:834671] CHIP:DMG: { [1685988541.341361][834669:834671] CHIP:DMG: DataVersion = 0xe885b772, [1685988541.341363][834669:834671] CHIP:DMG: AttributePathIB = [1685988541.341366][834669:834671] CHIP:DMG: { [1685988541.341369][834669:834671] CHIP:DMG: Endpoint = 0x0, [1685988541.341372][834669:834671] CHIP:DMG: Cluster = 0x30, [1685988541.341374][834669:834671] CHIP:DMG: Attribute = 0x0000_0002, [1685988541.341377][834669:834671] CHIP:DMG: } [1685988541.341381][834669:834671] CHIP:DMG: [1685988541.341384][834669:834671] CHIP:DMG: Data = 0, [1685988541.341387][834669:834671] CHIP:DMG: }, [1685988541.341390][834669:834671] CHIP:DMG: [1685988541.341392][834669:834671] CHIP:DMG: }, [1685988541.341399][834669:834671] CHIP:DMG: [1685988541.341401][834669:834671] CHIP:DMG: AttributeReportIB = [1685988541.341406][834669:834671] CHIP:DMG: { [1685988541.341408][834669:834671] CHIP:DMG: AttributeDataIB = [1685988541.341411][834669:834671] CHIP:DMG: { [1685988541.341414][834669:834671] CHIP:DMG: DataVersion = 0xe885b772, [1685988541.341417][834669:834671] CHIP:DMG: AttributePathIB = [1685988541.341420][834669:834671] CHIP:DMG: { [1685988541.341422][834669:834671] CHIP:DMG: Endpoint = 0x0, [1685988541.341426][834669:834671] CHIP:DMG: Cluster = 0x30, [1685988541.341429][834669:834671] CHIP:DMG: Attribute = 0x0000_0001, [1685988541.341432][834669:834671] CHIP:DMG: } [1685988541.341436][834669:834671] CHIP:DMG: [1685988541.341438][834669:834671] CHIP:DMG: Data = [1685988541.341441][834669:834671] CHIP:DMG: { [1685988541.341445][834669:834671] CHIP:DMG: 0x0 = 60, [1685988541.341448][834669:834671] CHIP:DMG: 0x1 = 900, [1685988541.341451][834669:834671] CHIP:DMG: }, [1685988541.341454][834669:834671] CHIP:DMG: }, [1685988541.341458][834669:834671] CHIP:DMG: [1685988541.341461][834669:834671] CHIP:DMG: }, [1685988541.341467][834669:834671] CHIP:DMG: [1685988541.341469][834669:834671] CHIP:DMG: AttributeReportIB = [1685988541.341473][834669:834671] CHIP:DMG: { [1685988541.341475][834669:834671] CHIP:DMG: AttributeDataIB = [1685988541.341479][834669:834671] CHIP:DMG: { [1685988541.341481][834669:834671] CHIP:DMG: DataVersion = 0xe885b772, [1685988541.341484][834669:834671] CHIP:DMG: AttributePathIB = [1685988541.341487][834669:834671] CHIP:DMG: { [1685988541.341489][834669:834671] CHIP:DMG: Endpoint = 0x0, [1685988541.341493][834669:834671] CHIP:DMG: Cluster = 0x30, [1685988541.341496][834669:834671] CHIP:DMG: Attribute = 0x0000_0000, [1685988541.341499][834669:834671] CHIP:DMG: } [1685988541.341502][834669:834671] CHIP:DMG: [1685988541.341505][834669:834671] CHIP:DMG: Data = 0, [1685988541.341507][834669:834671] CHIP:DMG: }, [1685988541.341511][834669:834671] CHIP:DMG: [1685988541.341513][834669:834671] CHIP:DMG: }, [1685988541.341519][834669:834671] CHIP:DMG: [1685988541.341521][834669:834671] CHIP:DMG: AttributeReportIB = [1685988541.341526][834669:834671] CHIP:DMG: { [1685988541.341528][834669:834671] CHIP:DMG: AttributeDataIB = [1685988541.341532][834669:834671] CHIP:DMG: { [1685988541.341535][834669:834671] CHIP:DMG: DataVersion = 0x1b3bbbb6, [1685988541.341538][834669:834671] CHIP:DMG: AttributePathIB = [1685988541.341540][834669:834671] CHIP:DMG: { [1685988541.341543][834669:834671] CHIP:DMG: Endpoint = 0x0, [1685988541.341546][834669:834671] CHIP:DMG: Cluster = 0x31, [1685988541.341552][834669:834671] CHIP:DMG: Attribute = 0x0000_FFFC, [1685988541.341556][834669:834671] CHIP:DMG: } [1685988541.341560][834669:834671] CHIP:DMG: [1685988541.341563][834669:834671] CHIP:DMG: Data = 1, [1685988541.341565][834669:834671] CHIP:DMG: }, [1685988541.341569][834669:834671] CHIP:DMG: [1685988541.341571][834669:834671] CHIP:DMG: }, [1685988541.341575][834669:834671] CHIP:DMG: [1685988541.341577][834669:834671] CHIP:DMG: ], [1685988541.341593][834669:834671] CHIP:DMG: [1685988541.341596][834669:834671] CHIP:DMG: SuppressResponse = true, [1685988541.341600][834669:834671] CHIP:DMG: InteractionModelRevision = 1 [1685988541.341602][834669:834671] CHIP:DMG: } [1685988541.342076][834669:834671] CHIP:CTL: ----- NetworkCommissioning Features: has WiFi. endpointid = 0 [1685988541.342151][834669:834671] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo' [1685988541.342172][834669:834671] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe' [1685988541.342187][834669:834671] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' [1685988541.342200][834669:834671] CHIP:CTL: Arming failsafe (60 seconds) [1685988541.342270][834669:834671] CHIP:DMG: ICR moving to [AddingComm] [1685988541.342288][834669:834671] CHIP:DMG: ICR moving to [AddedComma] [1685988541.342378][834669:834671] CHIP:EM: <<< [E:16294i S:49793 M:12672779] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685988541.342391][834669:834671] CHIP:IN: (S) Sending msg 12672779 on secure session with LSID: 49793 [1685988541.342642][834669:834671] CHIP:DMG: ICR moving to [CommandSen] [1685988541.429111][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988541.476143][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988541.476416][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988541.476793][834669:834671] CHIP:EM: >>> [E:16294i S:49793 M:92440514] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685988541.476814][834669:834671] CHIP:EM: Found matching exchange: 16294i, Delegate: 0x7fbe90049578 [1685988541.476833][834669:834671] CHIP:DMG: ICR moving to [ResponseRe] [1685988541.476870][834669:834671] CHIP:DMG: InvokeResponseMessage = [1685988541.476874][834669:834671] CHIP:DMG: { [1685988541.476880][834669:834671] CHIP:DMG: suppressResponse = false, [1685988541.476885][834669:834671] CHIP:DMG: InvokeResponseIBs = [1685988541.476891][834669:834671] CHIP:DMG: [ [1685988541.476896][834669:834671] CHIP:DMG: InvokeResponseIB = [1685988541.476903][834669:834671] CHIP:DMG: { [1685988541.476906][834669:834671] CHIP:DMG: CommandDataIB = [1685988541.476911][834669:834671] CHIP:DMG: { [1685988541.476915][834669:834671] CHIP:DMG: CommandPathIB = [1685988541.476928][834669:834671] CHIP:DMG: { [1685988541.476933][834669:834671] CHIP:DMG: EndpointId = 0x0, [1685988541.476938][834669:834671] CHIP:DMG: ClusterId = 0x30, [1685988541.476944][834669:834671] CHIP:DMG: CommandId = 0x1, [1685988541.476950][834669:834671] CHIP:DMG: }, [1685988541.476955][834669:834671] CHIP:DMG: [1685988541.476963][834669:834671] CHIP:DMG: CommandFields = [1685988541.476969][834669:834671] CHIP:DMG: { [1685988541.476975][834669:834671] CHIP:DMG: 0x0 = 0, [1685988541.476982][834669:834671] CHIP:DMG: 0x1 = "" (0 chars), [1685988541.476987][834669:834671] CHIP:DMG: }, [1685988541.476990][834669:834671] CHIP:DMG: }, [1685988541.476996][834669:834671] CHIP:DMG: [1685988541.476998][834669:834671] CHIP:DMG: }, [1685988541.477005][834669:834671] CHIP:DMG: [1685988541.477007][834669:834671] CHIP:DMG: ], [1685988541.477015][834669:834671] CHIP:DMG: [1685988541.477018][834669:834671] CHIP:DMG: InteractionModelRevision = 1 [1685988541.477021][834669:834671] CHIP:DMG: }, [1685988541.477042][834669:834671] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1685988541.477056][834669:834671] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1685988541.477070][834669:834671] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe' [1685988541.477075][834669:834671] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory' [1685988541.477083][834669:834671] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' [1685988541.477085][834669:834671] CHIP:CTL: Setting Regulatory Config [1685988541.477089][834669:834671] CHIP:CTL: Device does not support configurable regulatory location [1685988541.477135][834669:834671] CHIP:DMG: ICR moving to [AddingComm] [1685988541.477170][834669:834671] CHIP:DMG: ICR moving to [AddedComma] [1685988541.477204][834669:834671] CHIP:EM: <<< [E:16295i S:49793 M:12672780] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685988541.477213][834669:834671] CHIP:IN: (S) Sending msg 12672780 on secure session with LSID: 49793 [1685988541.477335][834669:834671] CHIP:DMG: ICR moving to [CommandSen] [1685988541.477354][834669:834671] CHIP:DMG: ICR moving to [AwaitingDe] [1685988541.563579][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988541.610950][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988541.611042][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988541.611164][834669:834671] CHIP:EM: >>> [E:16295i S:49793 M:92440515] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685988541.611178][834669:834671] CHIP:EM: Found matching exchange: 16295i, Delegate: 0x7fbe88013208 [1685988541.611187][834669:834671] CHIP:DMG: ICR moving to [ResponseRe] [1685988541.611202][834669:834671] CHIP:DMG: InvokeResponseMessage = [1685988541.611206][834669:834671] CHIP:DMG: { [1685988541.611210][834669:834671] CHIP:DMG: suppressResponse = false, [1685988541.611215][834669:834671] CHIP:DMG: InvokeResponseIBs = [1685988541.611221][834669:834671] CHIP:DMG: [ [1685988541.611226][834669:834671] CHIP:DMG: InvokeResponseIB = [1685988541.611232][834669:834671] CHIP:DMG: { [1685988541.611236][834669:834671] CHIP:DMG: CommandDataIB = [1685988541.611240][834669:834671] CHIP:DMG: { [1685988541.611244][834669:834671] CHIP:DMG: CommandPathIB = [1685988541.611251][834669:834671] CHIP:DMG: { [1685988541.611255][834669:834671] CHIP:DMG: EndpointId = 0x0, [1685988541.611258][834669:834671] CHIP:DMG: ClusterId = 0x30, [1685988541.611262][834669:834671] CHIP:DMG: CommandId = 0x3, [1685988541.611265][834669:834671] CHIP:DMG: }, [1685988541.611269][834669:834671] CHIP:DMG: [1685988541.611273][834669:834671] CHIP:DMG: CommandFields = [1685988541.611277][834669:834671] CHIP:DMG: { [1685988541.611281][834669:834671] CHIP:DMG: 0x0 = 0, [1685988541.611286][834669:834671] CHIP:DMG: 0x1 = "" (0 chars), [1685988541.611291][834669:834671] CHIP:DMG: }, [1685988541.611293][834669:834671] CHIP:DMG: }, [1685988541.611299][834669:834671] CHIP:DMG: [1685988541.611302][834669:834671] CHIP:DMG: }, [1685988541.611307][834669:834671] CHIP:DMG: [1685988541.611310][834669:834671] CHIP:DMG: ], [1685988541.611315][834669:834671] CHIP:DMG: [1685988541.611318][834669:834671] CHIP:DMG: InteractionModelRevision = 1 [1685988541.611321][834669:834671] CHIP:DMG: }, [1685988541.611340][834669:834671] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1685988541.611364][834669:834671] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0 [1685988541.611375][834669:834671] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory' [1685988541.611379][834669:834671] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest' [1685988541.611386][834669:834671] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' [1685988541.611389][834669:834671] CHIP:CTL: Sending request for PAI certificate [1685988541.611391][834669:834671] CHIP:CTL: Sending Certificate Chain request to 0x7fbe8800da80 device [1685988541.611411][834669:834671] CHIP:DMG: ICR moving to [AddingComm] [1685988541.611421][834669:834671] CHIP:DMG: ICR moving to [AddedComma] [1685988541.611443][834669:834671] CHIP:EM: <<< [E:16296i S:49793 M:12672781] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685988541.611450][834669:834671] CHIP:IN: (S) Sending msg 12672781 on secure session with LSID: 49793 [1685988541.611585][834669:834671] CHIP:DMG: ICR moving to [CommandSen] [1685988541.611605][834669:834671] CHIP:DMG: ICR moving to [AwaitingDe] [1685988541.698987][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988541.750928][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988541.751100][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988541.840228][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988541.840324][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988541.926252][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988541.926498][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988541.926848][834669:834671] CHIP:EM: >>> [E:16296i S:49793 M:92440516] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685988541.926874][834669:834671] CHIP:EM: Found matching exchange: 16296i, Delegate: 0x7fbe90049578 [1685988541.926907][834669:834671] CHIP:DMG: ICR moving to [ResponseRe] [1685988541.926954][834669:834671] CHIP:DMG: InvokeResponseMessage = [1685988541.926963][834669:834671] CHIP:DMG: { [1685988541.926970][834669:834671] CHIP:DMG: suppressResponse = false, [1685988541.926975][834669:834671] CHIP:DMG: InvokeResponseIBs = [1685988541.926986][834669:834671] CHIP:DMG: [ [1685988541.926999][834669:834671] CHIP:DMG: InvokeResponseIB = [1685988541.927011][834669:834671] CHIP:DMG: { [1685988541.927017][834669:834671] CHIP:DMG: CommandDataIB = [1685988541.927024][834669:834671] CHIP:DMG: { [1685988541.927030][834669:834671] CHIP:DMG: CommandPathIB = [1685988541.927040][834669:834671] CHIP:DMG: { [1685988541.927046][834669:834671] CHIP:DMG: EndpointId = 0x0, [1685988541.927052][834669:834671] CHIP:DMG: ClusterId = 0x3e, [1685988541.927057][834669:834671] CHIP:DMG: CommandId = 0x3, [1685988541.927062][834669:834671] CHIP:DMG: }, [1685988541.927069][834669:834671] CHIP:DMG: [1685988541.927077][834669:834671] CHIP:DMG: CommandFields = [1685988541.927083][834669:834671] CHIP:DMG: { [1685988541.927094][834669:834671] CHIP:DMG: 0x0 = [ [1685988541.927136][834669:834671] CHIP:DMG: 0x30, 0x82, 0x01, 0xcb, 0x30, 0x82, 0x01, 0x71, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x56, 0xad, 0x82, 0x22, 0xad, 0x94, 0x5b, 0x64, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x30, 0x31, 0x18, 0x30, 0x16, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 0x0f, 0x4d, 0x61, 0x74, 0x74, 0x65, 0x72, 0x20, 0x54, 0x65, 0x73, 0x74, 0x20, 0x50, 0x41, 0x41, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 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, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x41, 0x9a, 0x93, 0x15, 0xc2, 0x17, 0x3e, 0x0c, 0x8c, 0x87, 0x6d, 0x03, 0xcc, 0xfc, 0x94, 0x48, 0x52, 0x64, 0x7f, 0x7f, 0xec, 0x5e, 0x50, 0x82, 0xf4, 0x05, 0x99, 0x28, 0xec, 0xa8, 0x94, 0xc5, 0x94, 0x15, 0x13, 0x09, 0xac, 0x63, 0x1e, 0x4c, 0xb0, 0x33, 0x92, 0xaf, 0x68, 0x4b, 0x0b, 0xaf, 0xb7, 0xe6, 0x5b, 0x3b, 0x81, 0x62, 0xc2, 0xf5, 0x2b, 0xf9, 0x31, 0xb8, 0xe7, 0x7a, 0xaa, 0x82, 0xa3, 0x66, 0x30, 0x64, 0x30, 0x12, 0x06, 0x03, 0x55, 0x1d, 0x [1685988541.927162][834669:834671] CHIP:DMG: ] (463 bytes) [1685988541.927169][834669:834671] CHIP:DMG: }, [1685988541.927175][834669:834671] CHIP:DMG: }, [1685988541.927183][834669:834671] CHIP:DMG: [1685988541.927188][834669:834671] CHIP:DMG: }, [1685988541.927196][834669:834671] CHIP:DMG: [1685988541.927200][834669:834671] CHIP:DMG: ], [1685988541.927210][834669:834671] CHIP:DMG: [1685988541.927215][834669:834671] CHIP:DMG: InteractionModelRevision = 1 [1685988541.927220][834669:834671] CHIP:DMG: }, [1685988541.927256][834669:834671] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1685988541.927277][834669:834671] CHIP:CTL: Received certificate chain from the device [1685988541.927304][834669:834671] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest' [1685988541.927335][834669:834671] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest' [1685988541.927347][834669:834671] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest' [1685988541.927352][834669:834671] CHIP:CTL: Sending request for DAC certificate [1685988541.927356][834669:834671] CHIP:CTL: Sending Certificate Chain request to 0x7fbe8800da80 device [1685988541.927392][834669:834671] CHIP:DMG: ICR moving to [AddingComm] [1685988541.927398][834669:834671] CHIP:DMG: ICR moving to [AddedComma] [1685988541.927431][834669:834671] CHIP:EM: <<< [E:16297i S:49793 M:12672782] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685988541.927439][834669:834671] CHIP:IN: (S) Sending msg 12672782 on secure session with LSID: 49793 [1685988541.927588][834669:834671] CHIP:DMG: ICR moving to [CommandSen] [1685988541.927609][834669:834671] CHIP:DMG: ICR moving to [AwaitingDe] [1685988542.014320][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988542.065722][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988542.066096][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988542.156044][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988542.156288][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988542.242099][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988542.242315][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988542.242652][834669:834671] CHIP:EM: >>> [E:16297i S:49793 M:92440517] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685988542.242674][834669:834671] CHIP:EM: Found matching exchange: 16297i, Delegate: 0x7fbe9004a898 [1685988542.242718][834669:834671] CHIP:DMG: ICR moving to [ResponseRe] [1685988542.242779][834669:834671] CHIP:DMG: InvokeResponseMessage = [1685988542.242788][834669:834671] CHIP:DMG: { [1685988542.242794][834669:834671] CHIP:DMG: suppressResponse = false, [1685988542.242799][834669:834671] CHIP:DMG: InvokeResponseIBs = [1685988542.242806][834669:834671] CHIP:DMG: [ [1685988542.242810][834669:834671] CHIP:DMG: InvokeResponseIB = [1685988542.242819][834669:834671] CHIP:DMG: { [1685988542.242822][834669:834671] CHIP:DMG: CommandDataIB = [1685988542.242826][834669:834671] CHIP:DMG: { [1685988542.242830][834669:834671] CHIP:DMG: CommandPathIB = [1685988542.242836][834669:834671] CHIP:DMG: { [1685988542.242839][834669:834671] CHIP:DMG: EndpointId = 0x0, [1685988542.242842][834669:834671] CHIP:DMG: ClusterId = 0x3e, [1685988542.242845][834669:834671] CHIP:DMG: CommandId = 0x3, [1685988542.242847][834669:834671] CHIP:DMG: }, [1685988542.242851][834669:834671] CHIP:DMG: [1685988542.242857][834669:834671] CHIP:DMG: CommandFields = [1685988542.242861][834669:834671] CHIP:DMG: { [1685988542.242874][834669:834671] CHIP:DMG: 0x0 = [ [1685988542.242896][834669:834671] CHIP:DMG: 0x30, 0x82, 0x01, 0xe9, 0x30, 0x82, 0x01, 0x8e, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x23, 0x8a, 0x64, 0x7b, 0xbc, 0x4c, 0x30, 0xdd, 0x30, 0x0a, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x30, 0x3d, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 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, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x30, 0x20, 0x17, 0x0d, 0x32, 0x32, 0x30, 0x32, 0x30, 0x35, 0x30, 0x30, 0x30, 0x30, 0x30, 0x30, 0x5a, 0x18, 0x0f, 0x39, 0x39, 0x39, 0x39, 0x31, 0x32, 0x33, 0x31, 0x32, 0x33, 0x35, 0x39, 0x35, 0x39, 0x5a, 0x30, 0x53, 0x31, 0x25, 0x30, 0x23, 0x06, 0x03, 0x55, 0x04, 0x03, 0x0c, 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, 0x30, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x01, 0x0c, 0x04, 0x46, 0x46, 0x46, 0x31, 0x31, 0x14, 0x30, 0x12, 0x06, 0x0a, 0x2b, 0x06, 0x01, 0x04, 0x01, 0x82, 0xa2, 0x7c, 0x02, 0x02, 0x0c, 0x04, 0x38, 0x30, 0x30, 0x30, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x62, 0xdb, 0x16, 0xba, 0xde, 0xa3, 0x26, 0xa6, 0xdb, 0x84, 0x81, 0x4a, 0x06, 0x3f, 0xc6, 0xc7, 0xe9, 0xe2, 0xb1, 0x01, 0xb7, 0x21, 0x64, 0x8e, 0xba, 0x4e, 0x5a, 0xc8, 0x40, 0xf5, 0xda, 0x30, 0x1e, 0xe6, 0x18, 0x12, 0x4e, 0xb4, 0x18, 0x [1685988542.242934][834669:834671] CHIP:DMG: ] (493 bytes) [1685988542.242938][834669:834671] CHIP:DMG: }, [1685988542.242941][834669:834671] CHIP:DMG: }, [1685988542.242945][834669:834671] CHIP:DMG: [1685988542.242948][834669:834671] CHIP:DMG: }, [1685988542.242953][834669:834671] CHIP:DMG: [1685988542.242955][834669:834671] CHIP:DMG: ], [1685988542.242963][834669:834671] CHIP:DMG: [1685988542.242966][834669:834671] CHIP:DMG: InteractionModelRevision = 1 [1685988542.242968][834669:834671] CHIP:DMG: }, [1685988542.243014][834669:834671] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1685988542.243058][834669:834671] CHIP:CTL: Received certificate chain from the device [1685988542.243115][834669:834671] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest' [1685988542.243150][834669:834671] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest' [1685988542.243167][834669:834671] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest' [1685988542.243170][834669:834671] CHIP:CTL: Sending Attestation Request to the device. [1685988542.243180][834669:834671] CHIP:CTL: Sending Attestation request to 0x7fbe8800da80 device [1685988542.243294][834669:834671] CHIP:DMG: ICR moving to [AddingComm] [1685988542.243309][834669:834671] CHIP:DMG: ICR moving to [AddedComma] [1685988542.243390][834669:834671] CHIP:EM: <<< [E:16298i S:49793 M:12672783] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685988542.243402][834669:834671] CHIP:IN: (S) Sending msg 12672783 on secure session with LSID: 49793 [1685988542.243620][834669:834671] CHIP:DMG: ICR moving to [CommandSen] [1685988542.243629][834669:834671] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information [1685988542.243641][834669:834671] CHIP:DMG: ICR moving to [AwaitingDe] [1685988542.328972][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988542.466286][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988542.466445][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988542.560994][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988542.561174][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988542.649691][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988542.649796][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988542.649884][834669:834671] CHIP:EM: >>> [E:16298i S:49793 M:92440518] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685988542.649900][834669:834671] CHIP:EM: Found matching exchange: 16298i, Delegate: 0x7fbe9004a9f8 [1685988542.649910][834669:834671] CHIP:DMG: ICR moving to [ResponseRe] [1685988542.649934][834669:834671] CHIP:DMG: InvokeResponseMessage = [1685988542.649937][834669:834671] CHIP:DMG: { [1685988542.649940][834669:834671] CHIP:DMG: suppressResponse = false, [1685988542.649942][834669:834671] CHIP:DMG: InvokeResponseIBs = [1685988542.649948][834669:834671] CHIP:DMG: [ [1685988542.649950][834669:834671] CHIP:DMG: InvokeResponseIB = [1685988542.649955][834669:834671] CHIP:DMG: { [1685988542.649958][834669:834671] CHIP:DMG: CommandDataIB = [1685988542.649961][834669:834671] CHIP:DMG: { [1685988542.649963][834669:834671] CHIP:DMG: CommandPathIB = [1685988542.649967][834669:834671] CHIP:DMG: { [1685988542.649969][834669:834671] CHIP:DMG: EndpointId = 0x0, [1685988542.649981][834669:834671] CHIP:DMG: ClusterId = 0x3e, [1685988542.649983][834669:834671] CHIP:DMG: CommandId = 0x1, [1685988542.649986][834669:834671] CHIP:DMG: }, [1685988542.649989][834669:834671] CHIP:DMG: [1685988542.649992][834669:834671] CHIP:DMG: CommandFields = [1685988542.649996][834669:834671] CHIP:DMG: { [1685988542.649999][834669:834671] CHIP:DMG: 0x0 = [ [1685988542.650020][834669:834671] CHIP:DMG: 0x15, 0x31, 0x01, 0x1b, 0x02, 0x30, 0x82, 0x02, 0x17, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x02, 0xa0, 0x82, 0x02, 0x08, 0x30, 0x82, 0x02, 0x04, 0x02, 0x01, 0x03, 0x31, 0x0d, 0x30, 0x0b, 0x06, 0x09, 0x60, 0x86, 0x48, 0x01, 0x65, 0x03, 0x04, 0x02, 0x01, 0x30, 0x82, 0x01, 0x70, 0x06, 0x09, 0x2a, 0x86, 0x48, 0x86, 0xf7, 0x0d, 0x01, 0x07, 0x01, 0xa0, 0x82, 0x01, 0x61, 0x04, 0x82, 0x01, 0x5d, 0x15, 0x24, 0x00, 0x01, 0x25, 0x01, 0xf1, 0xff, 0x36, 0x02, 0x05, 0x00, 0x80, 0x05, 0x01, 0x80, 0x05, 0x02, 0x80, 0x05, 0x03, 0x80, 0x05, 0x04, 0x80, 0x05, 0x05, 0x80, 0x05, 0x06, 0x80, 0x05, 0x07, 0x80, 0x05, 0x08, 0x80, 0x05, 0x09, 0x80, 0x05, 0x0a, 0x80, 0x05, 0x0b, 0x80, 0x05, 0x0c, 0x80, 0x05, 0x0d, 0x80, 0x05, 0x0e, 0x80, 0x05, 0x0f, 0x80, 0x05, 0x10, 0x80, 0x05, 0x11, 0x80, 0x05, 0x12, 0x80, 0x05, 0x13, 0x80, 0x05, 0x14, 0x80, 0x05, 0x15, 0x80, 0x05, 0x16, 0x80, 0x05, 0x17, 0x80, 0x05, 0x18, 0x80, 0x05, 0x19, 0x80, 0x05, 0x1a, 0x80, 0x05, 0x1b, 0x80, 0x05, 0x1c, 0x80, 0x05, 0x1d, 0x80, 0x05, 0x1e, 0x80, 0x05, 0x1f, 0x80, 0x05, 0x20, 0x80, 0x05, 0x21, 0x80, 0x05, 0x22, 0x80, 0x05, 0x23, 0x80, 0x05, 0x24, 0x80, 0x05, 0x25, 0x80, 0x05, 0x26, 0x80, 0x05, 0x27, 0x80, 0x05, 0x28, 0x80, 0x05, 0x29, 0x80, 0x05, 0x2a, 0x80, 0x05, 0x2b, 0x80, 0x05, 0x2c, 0x80, 0x05, 0x2d, 0x80, 0x05, 0x2e, 0x80, 0x05, 0x2f, 0x80, 0x05, 0x30, 0x80, 0x05, 0x31, 0x80, 0x05, 0x32, 0x80, 0x05, 0x33, 0x80, 0x05, 0x34, 0x80, 0x05, 0x35, 0x80, 0x05, 0x36, 0x80, 0x05, 0x37, 0x80, 0x05, 0x38, 0x80, 0x05, 0x39, 0x80, 0x05, 0x3a, 0x80, 0x05, 0x3b, 0x80, 0x05, 0x3c, 0x80, 0x05, 0x3d, 0x80, 0x05, 0x3e, 0x80, 0x05, 0x3f, 0x80, 0x05, 0x40, 0x80, 0x05, 0x41, 0x80, 0x05, 0x42, 0x80, 0x05, 0x43, 0x80, 0x [1685988542.650033][834669:834671] CHIP:DMG: ] (583 bytes) [1685988542.650036][834669:834671] CHIP:DMG: 0x1 = [ [1685988542.650043][834669:834671] CHIP:DMG: 0x97, 0xdb, 0xcc, 0xa5, 0x17, 0x14, 0x86, 0xf0, 0x5c, 0x16, 0xfc, 0xa7, 0x0e, 0x3f, 0xe3, 0xfd, 0x59, 0x32, 0x17, 0xdc, 0x4a, 0x6c, 0xeb, 0xfa, 0x82, 0x0f, 0x88, 0xa4, 0x3b, 0xb0, 0xbf, 0x4a, 0xa0, 0xbe, 0x03, 0x13, 0xc9, 0x25, 0x21, 0x61, 0x72, 0xcf, 0x92, 0x02, 0xfc, 0xbc, 0x84, 0xd3, 0xe1, 0xf6, 0x59, 0x4a, 0x4a, 0x3e, 0x9b, 0x64, 0xd4, 0x55, 0xfe, 0x35, 0xe9, 0x69, 0x74, 0x57, [1685988542.650049][834669:834671] CHIP:DMG: ] (64 bytes) [1685988542.650052][834669:834671] CHIP:DMG: }, [1685988542.650053][834669:834671] CHIP:DMG: }, [1685988542.650058][834669:834671] CHIP:DMG: [1685988542.650060][834669:834671] CHIP:DMG: }, [1685988542.650065][834669:834671] CHIP:DMG: [1685988542.650067][834669:834671] CHIP:DMG: ], [1685988542.650072][834669:834671] CHIP:DMG: [1685988542.650074][834669:834671] CHIP:DMG: InteractionModelRevision = 1 [1685988542.650076][834669:834671] CHIP:DMG: }, [1685988542.650091][834669:834671] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 [1685988542.650100][834669:834671] CHIP:CTL: Received Attestation Information from the device [1685988542.650110][834669:834671] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest' [1685988542.650116][834669:834671] CHIP:CTL: AutoCommissioner setting attestationElements buffer size 583/583 [1685988542.650131][834669:834671] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification' [1685988542.650136][834669:834671] CHIP:CTL: Performing next commissioning step 'AttestationVerification' [1685988542.650138][834669:834671] CHIP:CTL: Verifying attestation [1685988542.661221][834669:834671] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device. [1685988542.661238][834669:834671] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification' [1685988542.661243][834669:834671] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest' [1685988542.661249][834669:834671] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest' [1685988542.661252][834669:834671] CHIP:CTL: Sending CSR request to 0x7fbe8800da80 device [1685988542.661285][834669:834671] CHIP:DMG: ICR moving to [AddingComm] [1685988542.661296][834669:834671] CHIP:DMG: ICR moving to [AddedComma] [1685988542.661337][834669:834671] CHIP:EM: <<< [E:16299i S:49793 M:12672784] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685988542.661357][834669:834671] CHIP:IN: (S) Sending msg 12672784 on secure session with LSID: 49793 [1685988542.661619][834669:834671] CHIP:DMG: ICR moving to [CommandSen] [1685988542.661647][834669:834671] CHIP:CTL: Sent CSR request, waiting for the CSR [1685988542.661690][834669:834671] CHIP:DMG: ICR moving to [AwaitingDe] [1685988542.734109][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988542.965128][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988542.965231][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988543.052752][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988543.052950][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988543.053170][834669:834671] CHIP:EM: >>> [E:16299i S:49793 M:92440519] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685988543.053196][834669:834671] CHIP:EM: Found matching exchange: 16299i, Delegate: 0x7fbe9004a898 [1685988543.053218][834669:834671] CHIP:DMG: ICR moving to [ResponseRe] [1685988543.053243][834669:834671] CHIP:DMG: InvokeResponseMessage = [1685988543.053247][834669:834671] CHIP:DMG: { [1685988543.053253][834669:834671] CHIP:DMG: suppressResponse = false, [1685988543.053256][834669:834671] CHIP:DMG: InvokeResponseIBs = [1685988543.053259][834669:834671] CHIP:DMG: [ [1685988543.053262][834669:834671] CHIP:DMG: InvokeResponseIB = [1685988543.053266][834669:834671] CHIP:DMG: { [1685988543.053268][834669:834671] CHIP:DMG: CommandDataIB = [1685988543.053272][834669:834671] CHIP:DMG: { [1685988543.053276][834669:834671] CHIP:DMG: CommandPathIB = [1685988543.053280][834669:834671] CHIP:DMG: { [1685988543.053283][834669:834671] CHIP:DMG: EndpointId = 0x0, [1685988543.053286][834669:834671] CHIP:DMG: ClusterId = 0x3e, [1685988543.053289][834669:834671] CHIP:DMG: CommandId = 0x5, [1685988543.053291][834669:834671] CHIP:DMG: }, [1685988543.053294][834669:834671] CHIP:DMG: [1685988543.053298][834669:834671] CHIP:DMG: CommandFields = [1685988543.053300][834669:834671] CHIP:DMG: { [1685988543.053305][834669:834671] CHIP:DMG: 0x0 = [ [1685988543.053319][834669:834671] CHIP:DMG: 0x15, 0x30, 0x01, 0xcd, 0x30, 0x81, 0xca, 0x30, 0x70, 0x02, 0x01, 0x00, 0x30, 0x0e, 0x31, 0x0c, 0x30, 0x0a, 0x06, 0x03, 0x55, 0x04, 0x0a, 0x0c, 0x03, 0x43, 0x53, 0x52, 0x30, 0x59, 0x30, 0x13, 0x06, 0x07, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x02, 0x01, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x03, 0x01, 0x07, 0x03, 0x42, 0x00, 0x04, 0x44, 0xc1, 0xe0, 0x0e, 0x71, 0xfe, 0x1c, 0x53, 0xac, 0x5b, 0xf4, 0x6d, 0x99, 0xfd, 0x97, 0x20, 0xbe, 0x36, 0x4e, 0x39, 0x81, 0xb6, 0xf0, 0xcd, 0x3c, 0x08, 0x0f, 0xa1, 0x58, 0x74, 0x67, 0xc2, 0xb6, 0xfb, 0x67, 0xd3, 0x3d, 0xbb, 0x5b, 0x74, 0x38, 0x83, 0x12, 0x09, 0x0e, 0x4a, 0x8a, 0x02, 0x74, 0x58, 0x33, 0x05, 0xcf, 0x72, 0x4c, 0x5e, 0x83, 0x60, 0xa3, 0xb6, 0x36, 0x60, 0x05, 0x94, 0xa0, 0x00, 0x30, 0x0c, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x05, 0x00, 0x03, 0x48, 0x00, 0x30, 0x45, 0x02, 0x20, 0x26, 0x67, 0x23, 0x55, 0x4c, 0xf9, 0x29, 0x7f, 0xc4, 0x27, 0xdf, 0xb0, 0x48, 0xfd, 0xfd, 0x53, 0x52, 0xe4, 0x12, 0xe8, 0x6d, 0xf8, 0x9e, 0xef, 0x8a, 0xa9, 0x07, 0xc9, 0x08, 0x94, 0xea, 0x20, 0x02, 0x21, 0x00, 0x88, 0x9d, 0xda, 0xf0, 0xfb, 0xb3, 0x86, 0x5b, 0x1d, 0x10, 0x8b, 0x42, 0xcd, 0xc0, 0x5d, 0x00, 0x6e, 0x3a, 0x6a, 0xd9, 0xf9, 0xb3, 0x39, 0x53, 0x29, 0xea, 0xae, 0x31, 0x68, 0xbb, 0xe6, 0x6d, 0x30, 0x02, 0x20, 0x8e, 0xd7, 0x01, 0xdd, 0x01, 0x9b, 0xaf, 0xc4, 0x34, 0xc7, 0xd9, 0xa4, 0xd3, 0x9a, 0x4d, 0x35, 0xf4, 0x95, 0x14, 0x1f, 0xa3, 0x05, 0xe2, 0xe0, 0x4c, 0xbe, 0x73, 0xe6, 0x6d, 0x91, 0x11, 0x05, 0x18, [1685988543.053333][834669:834671] CHIP:DMG: ] (245 bytes) [1685988543.053336][834669:834671] CHIP:DMG: 0x1 = [ [1685988543.053341][834669:834671] CHIP:DMG: 0x17, 0xb7, 0x20, 0xd4, 0x97, 0x49, 0x08, 0x75, 0x41, 0x74, 0x6a, 0x94, 0x4b, 0xe6, 0x48, 0xee, 0x56, 0x3c, 0x71, 0x5c, 0x5f, 0x39, 0xd0, 0x88, 0xde, 0x71, 0xd1, 0x60, 0x6e, 0xf5, 0xb2, 0x9c, 0x47, 0xea, 0x6d, 0x2b, 0xbc, 0x3a, 0x4e, 0xe1, 0xb0, 0x55, 0x24, 0xa4, 0x5b, 0xa0, 0x89, 0x43, 0x00, 0xb0, 0x1d, 0x03, 0x5b, 0x9b, 0xfd, 0x2f, 0x42, 0x27, 0x0e, 0x95, 0x53, 0xba, 0x22, 0x5d, [1685988543.053344][834669:834671] CHIP:DMG: ] (64 bytes) [1685988543.053346][834669:834671] CHIP:DMG: }, [1685988543.053348][834669:834671] CHIP:DMG: }, [1685988543.053351][834669:834671] CHIP:DMG: [1685988543.053356][834669:834671] CHIP:DMG: }, [1685988543.053359][834669:834671] CHIP:DMG: [1685988543.053360][834669:834671] CHIP:DMG: ], [1685988543.053365][834669:834671] CHIP:DMG: [1685988543.053367][834669:834671] CHIP:DMG: InteractionModelRevision = 1 [1685988543.053368][834669:834671] CHIP:DMG: }, [1685988543.053387][834669:834671] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 [1685988543.053407][834669:834671] CHIP:CTL: Received certificate signing request from the device [1685988543.053437][834669:834671] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest' [1685988543.053444][834669:834671] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR' [1685988543.053454][834669:834671] CHIP:CTL: Performing next commissioning step 'ValidateCSR' [1685988543.055260][834669:834671] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR' [1685988543.055269][834669:834671] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain' [1685988543.055271][834669:834671] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain' [1685988543.055274][834669:834671] CHIP:CTL: Getting certificate chain for the device from the issuer [1685988543.055955][834669:834671] CHIP:CTL: Verifying Certificate Signing Request [1685988543.056522][834669:834671] CHIP:CTL: Generating NOC [1685988543.056673][834669:834671] CHIP:CTL: Providing certificate chain to the commissioner [1685988543.056679][834669:834671] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status src/controller/ExampleOperationalCredentialsIssuer.cpp:396: Success [1685988543.056684][834669:834671] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain' [1685988543.056742][834669:834671] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert' [1685988543.056745][834669:834671] CHIP:CTL: Sending root certificate to the device [1685988543.056792][834669:834671] CHIP:DMG: ICR moving to [AddingComm] [1685988543.056801][834669:834671] CHIP:DMG: ICR moving to [AddedComma] [1685988543.056877][834669:834671] CHIP:EM: <<< [E:16300i S:49793 M:12672785] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685988543.056887][834669:834671] CHIP:IN: (S) Sending msg 12672785 on secure session with LSID: 49793 [1685988543.057081][834669:834671] CHIP:DMG: ICR moving to [CommandSen] [1685988543.057089][834669:834671] CHIP:CTL: Sent root certificate to the device [1685988543.057247][834669:834671] CHIP:DMG: ICR moving to [AwaitingDe] [1685988543.139133][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988543.228758][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988543.456195][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988543.456443][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988543.456762][834669:834671] CHIP:EM: >>> [E:16300i S:49793 M:92440520] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685988543.456787][834669:834671] CHIP:EM: Found matching exchange: 16300i, Delegate: 0x7fbe9004a9f8 [1685988543.456808][834669:834671] CHIP:DMG: ICR moving to [ResponseRe] [1685988543.456851][834669:834671] CHIP:DMG: InvokeResponseMessage = [1685988543.456859][834669:834671] CHIP:DMG: { [1685988543.456867][834669:834671] CHIP:DMG: suppressResponse = false, [1685988543.456874][834669:834671] CHIP:DMG: InvokeResponseIBs = [1685988543.456890][834669:834671] CHIP:DMG: [ [1685988543.456896][834669:834671] CHIP:DMG: InvokeResponseIB = [1685988543.456908][834669:834671] CHIP:DMG: { [1685988543.456913][834669:834671] CHIP:DMG: CommandStatusIB = [1685988543.456922][834669:834671] CHIP:DMG: { [1685988543.456928][834669:834671] CHIP:DMG: CommandPathIB = [1685988543.456939][834669:834671] CHIP:DMG: { [1685988543.456943][834669:834671] CHIP:DMG: EndpointId = 0x0, [1685988543.456945][834669:834671] CHIP:DMG: ClusterId = 0x3e, [1685988543.456949][834669:834671] CHIP:DMG: CommandId = 0xb, [1685988543.456952][834669:834671] CHIP:DMG: }, [1685988543.456958][834669:834671] CHIP:DMG: [1685988543.456961][834669:834671] CHIP:DMG: StatusIB = [1685988543.456966][834669:834671] CHIP:DMG: { [1685988543.456968][834669:834671] CHIP:DMG: status = 0x00 (SUCCESS), [1685988543.456971][834669:834671] CHIP:DMG: }, [1685988543.456973][834669:834671] CHIP:DMG: [1685988543.456976][834669:834671] CHIP:DMG: }, [1685988543.456979][834669:834671] CHIP:DMG: [1685988543.456981][834669:834671] CHIP:DMG: }, [1685988543.456985][834669:834671] CHIP:DMG: [1685988543.456987][834669:834671] CHIP:DMG: ], [1685988543.456991][834669:834671] CHIP:DMG: [1685988543.456993][834669:834671] CHIP:DMG: InteractionModelRevision = 1 [1685988543.456995][834669:834671] CHIP:DMG: }, [1685988543.457016][834669:834671] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 [1685988543.457030][834669:834671] CHIP:CTL: Device confirmed that it has received the root certificate [1685988543.457052][834669:834671] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert' [1685988543.457060][834669:834671] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC' [1685988543.457071][834669:834671] CHIP:CTL: Performing next commissioning step 'SendNOC' [1685988543.457155][834669:834671] CHIP:DMG: ICR moving to [AddingComm] [1685988543.457176][834669:834671] CHIP:DMG: ICR moving to [AddedComma] [1685988543.457238][834669:834671] CHIP:EM: <<< [E:16301i S:49793 M:12672786] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685988543.457248][834669:834671] CHIP:IN: (S) Sending msg 12672786 on secure session with LSID: 49793 [1685988543.457423][834669:834671] CHIP:DMG: ICR moving to [CommandSen] [1685988543.457431][834669:834671] CHIP:CTL: Sent operational certificate to the device [1685988543.457447][834669:834671] CHIP:DMG: ICR moving to [AwaitingDe] [1685988543.543661][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988543.634437][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988543.723982][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988544.265826][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988544.266007][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988544.266189][834669:834671] CHIP:EM: >>> [E:16301i S:49793 M:92440521] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685988544.266220][834669:834671] CHIP:EM: Found matching exchange: 16301i, Delegate: 0x7fbe9004a898 [1685988544.266233][834669:834671] CHIP:DMG: ICR moving to [ResponseRe] [1685988544.266257][834669:834671] CHIP:DMG: InvokeResponseMessage = [1685988544.266264][834669:834671] CHIP:DMG: { [1685988544.266269][834669:834671] CHIP:DMG: suppressResponse = false, [1685988544.266276][834669:834671] CHIP:DMG: InvokeResponseIBs = [1685988544.266286][834669:834671] CHIP:DMG: [ [1685988544.266292][834669:834671] CHIP:DMG: InvokeResponseIB = [1685988544.266307][834669:834671] CHIP:DMG: { [1685988544.266313][834669:834671] CHIP:DMG: CommandDataIB = [1685988544.266320][834669:834671] CHIP:DMG: { [1685988544.266328][834669:834671] CHIP:DMG: CommandPathIB = [1685988544.266336][834669:834671] CHIP:DMG: { [1685988544.266343][834669:834671] CHIP:DMG: EndpointId = 0x0, [1685988544.266350][834669:834671] CHIP:DMG: ClusterId = 0x3e, [1685988544.266357][834669:834671] CHIP:DMG: CommandId = 0x8, [1685988544.266363][834669:834671] CHIP:DMG: }, [1685988544.266372][834669:834671] CHIP:DMG: [1685988544.266378][834669:834671] CHIP:DMG: CommandFields = [1685988544.266385][834669:834671] CHIP:DMG: { [1685988544.266393][834669:834671] CHIP:DMG: 0x0 = 0, [1685988544.266400][834669:834671] CHIP:DMG: 0x1 = 1, [1685988544.266407][834669:834671] CHIP:DMG: }, [1685988544.266413][834669:834671] CHIP:DMG: }, [1685988544.266428][834669:834671] CHIP:DMG: [1685988544.266434][834669:834671] CHIP:DMG: }, [1685988544.266444][834669:834671] CHIP:DMG: [1685988544.266450][834669:834671] CHIP:DMG: ], [1685988544.266462][834669:834671] CHIP:DMG: [1685988544.266468][834669:834671] CHIP:DMG: InteractionModelRevision = 1 [1685988544.266473][834669:834671] CHIP:DMG: }, [1685988544.266509][834669:834671] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 [1685988544.266528][834669:834671] CHIP:CTL: Device returned status 0 on receiving the NOC [1685988544.266534][834669:834671] CHIP:CTL: Operational credentials provisioned on device 0x7fbe8800da80 [1685988544.266541][834669:834671] CHIP:TOO: Secure Pairing Success [1685988544.266545][834669:834671] CHIP:TOO: CASE establishment successful [1685988544.266555][834669:834671] CHIP:CTL: Successfully finished commissioning step 'SendNOC' [1685988544.266563][834669:834671] CHIP:CTL: No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks [1685988544.266568][834669:834671] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'WiFiNetworkSetup' [1685988544.266577][834669:834671] CHIP:CTL: Performing next commissioning step 'WiFiNetworkSetup' [1685988544.266610][834669:834671] CHIP:DMG: ICR moving to [AddingComm] [1685988544.266621][834669:834671] CHIP:DMG: ICR moving to [AddedComma] [1685988544.266657][834669:834671] CHIP:EM: <<< [E:16302i S:49793 M:12672787] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685988544.266670][834669:834671] CHIP:IN: (S) Sending msg 12672787 on secure session with LSID: 49793 [1685988544.266917][834669:834671] CHIP:DMG: ICR moving to [CommandSen] [1685988544.266954][834669:834671] CHIP:DMG: ICR moving to [AwaitingDe] [1685988544.354190][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988544.400927][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988544.401029][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988544.401139][834669:834671] CHIP:EM: >>> [E:16302i S:49793 M:92440522] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685988544.401149][834669:834671] CHIP:EM: Found matching exchange: 16302i, Delegate: 0x7fbe9004a9f8 [1685988544.401156][834669:834671] CHIP:DMG: ICR moving to [ResponseRe] [1685988544.401173][834669:834671] CHIP:DMG: InvokeResponseMessage = [1685988544.401177][834669:834671] CHIP:DMG: { [1685988544.401181][834669:834671] CHIP:DMG: suppressResponse = false, [1685988544.401185][834669:834671] CHIP:DMG: InvokeResponseIBs = [1685988544.401191][834669:834671] CHIP:DMG: [ [1685988544.401196][834669:834671] CHIP:DMG: InvokeResponseIB = [1685988544.401204][834669:834671] CHIP:DMG: { [1685988544.401209][834669:834671] CHIP:DMG: CommandDataIB = [1685988544.401213][834669:834671] CHIP:DMG: { [1685988544.401217][834669:834671] CHIP:DMG: CommandPathIB = [1685988544.401222][834669:834671] CHIP:DMG: { [1685988544.401227][834669:834671] CHIP:DMG: EndpointId = 0x0, [1685988544.401231][834669:834671] CHIP:DMG: ClusterId = 0x31, [1685988544.401235][834669:834671] CHIP:DMG: CommandId = 0x5, [1685988544.401238][834669:834671] CHIP:DMG: }, [1685988544.401242][834669:834671] CHIP:DMG: [1685988544.401246][834669:834671] CHIP:DMG: CommandFields = [1685988544.401250][834669:834671] CHIP:DMG: { [1685988544.401256][834669:834671] CHIP:DMG: 0x0 = 0, [1685988544.401260][834669:834671] CHIP:DMG: 0x2 = 0, [1685988544.401263][834669:834671] CHIP:DMG: }, [1685988544.401266][834669:834671] CHIP:DMG: }, [1685988544.401271][834669:834671] CHIP:DMG: [1685988544.401274][834669:834671] CHIP:DMG: }, [1685988544.401279][834669:834671] CHIP:DMG: [1685988544.401281][834669:834671] CHIP:DMG: ], [1685988544.401287][834669:834671] CHIP:DMG: [1685988544.401290][834669:834671] CHIP:DMG: InteractionModelRevision = 1 [1685988544.401293][834669:834671] CHIP:DMG: }, [1685988544.401313][834669:834671] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005 [1685988544.401342][834669:834671] CHIP:CTL: Received NetworkConfig response, networkingStatus=0 [1685988544.401355][834669:834671] CHIP:CTL: Successfully finished commissioning step 'WiFiNetworkSetup' [1685988544.401363][834669:834671] CHIP:CTL: Commissioning stage next step: 'WiFiNetworkSetup' -> 'FailsafeBeforeWiFiEnable' [1685988544.401373][834669:834671] CHIP:CTL: Performing next commissioning step 'FailsafeBeforeWiFiEnable' [1685988544.401382][834669:834671] CHIP:CTL: Arming failsafe (66 seconds) [1685988544.401401][834669:834671] CHIP:DMG: ICR moving to [AddingComm] [1685988544.401406][834669:834671] CHIP:DMG: ICR moving to [AddedComma] [1685988544.401428][834669:834671] CHIP:EM: <<< [E:16303i S:49793 M:12672788] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685988544.401434][834669:834671] CHIP:IN: (S) Sending msg 12672788 on secure session with LSID: 49793 [1685988544.401594][834669:834671] CHIP:DMG: ICR moving to [CommandSen] [1685988544.401628][834669:834671] CHIP:DMG: ICR moving to [AwaitingDe] [1685988544.488677][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988544.535997][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988544.536139][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988544.536387][834669:834671] CHIP:EM: >>> [E:16303i S:49793 M:92440523] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685988544.536404][834669:834671] CHIP:EM: Found matching exchange: 16303i, Delegate: 0x7fbe9004a898 [1685988544.536420][834669:834671] CHIP:DMG: ICR moving to [ResponseRe] [1685988544.536452][834669:834671] CHIP:DMG: InvokeResponseMessage = [1685988544.536459][834669:834671] CHIP:DMG: { [1685988544.536463][834669:834671] CHIP:DMG: suppressResponse = false, [1685988544.536466][834669:834671] CHIP:DMG: InvokeResponseIBs = [1685988544.536472][834669:834671] CHIP:DMG: [ [1685988544.536475][834669:834671] CHIP:DMG: InvokeResponseIB = [1685988544.536480][834669:834671] CHIP:DMG: { [1685988544.536484][834669:834671] CHIP:DMG: CommandDataIB = [1685988544.536491][834669:834671] CHIP:DMG: { [1685988544.536495][834669:834671] CHIP:DMG: CommandPathIB = [1685988544.536500][834669:834671] CHIP:DMG: { [1685988544.536505][834669:834671] CHIP:DMG: EndpointId = 0x0, [1685988544.536509][834669:834671] CHIP:DMG: ClusterId = 0x30, [1685988544.536513][834669:834671] CHIP:DMG: CommandId = 0x1, [1685988544.536516][834669:834671] CHIP:DMG: }, [1685988544.536520][834669:834671] CHIP:DMG: [1685988544.536525][834669:834671] CHIP:DMG: CommandFields = [1685988544.536529][834669:834671] CHIP:DMG: { [1685988544.536534][834669:834671] CHIP:DMG: 0x0 = 0, [1685988544.536540][834669:834671] CHIP:DMG: 0x1 = "" (0 chars), [1685988544.536543][834669:834671] CHIP:DMG: }, [1685988544.536546][834669:834671] CHIP:DMG: }, [1685988544.536550][834669:834671] CHIP:DMG: [1685988544.536552][834669:834671] CHIP:DMG: }, [1685988544.536557][834669:834671] CHIP:DMG: [1685988544.536559][834669:834671] CHIP:DMG: ], [1685988544.536565][834669:834671] CHIP:DMG: [1685988544.536568][834669:834671] CHIP:DMG: InteractionModelRevision = 1 [1685988544.536570][834669:834671] CHIP:DMG: }, [1685988544.536597][834669:834671] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1685988544.536622][834669:834671] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1685988544.536646][834669:834671] CHIP:CTL: Successfully finished commissioning step 'FailsafeBeforeWiFiEnable' [1685988544.536653][834669:834671] CHIP:CTL: Commissioning stage next step: 'FailsafeBeforeWiFiEnable' -> 'WiFiNetworkEnable' [1685988544.536660][834669:834671] CHIP:CTL: Setting wifi connection time min = 30 [1685988544.536669][834669:834671] CHIP:CTL: Performing next commissioning step 'WiFiNetworkEnable' [1685988544.536747][834669:834671] CHIP:DMG: ICR moving to [AddingComm] [1685988544.536763][834669:834671] CHIP:DMG: ICR moving to [AddedComma] [1685988544.536827][834669:834671] CHIP:EM: <<< [E:16304i S:49793 M:12672789] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685988544.536837][834669:834671] CHIP:IN: (S) Sending msg 12672789 on secure session with LSID: 49793 [1685988544.537119][834669:834671] CHIP:DMG: ICR moving to [CommandSen] [1685988544.537146][834669:834671] CHIP:DMG: ICR moving to [AwaitingDe] [1685988544.623903][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988547.183695][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988547.183847][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988548.315589][834669:834670] CHIP:DL: Indication received, conn = 0x7fbe9003bce0 [1685988548.315709][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685988548.315910][834669:834671] CHIP:EM: >>> [E:16304i S:49793 M:92440524] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685988548.315932][834669:834671] CHIP:EM: Found matching exchange: 16304i, Delegate: 0x7fbe9004a9f8 [1685988548.315951][834669:834671] CHIP:DMG: ICR moving to [ResponseRe] [1685988548.315977][834669:834671] CHIP:DMG: InvokeResponseMessage = [1685988548.315980][834669:834671] CHIP:DMG: { [1685988548.315988][834669:834671] CHIP:DMG: suppressResponse = false, [1685988548.315992][834669:834671] CHIP:DMG: InvokeResponseIBs = [1685988548.315998][834669:834671] CHIP:DMG: [ [1685988548.316000][834669:834671] CHIP:DMG: InvokeResponseIB = [1685988548.316008][834669:834671] CHIP:DMG: { [1685988548.316012][834669:834671] CHIP:DMG: CommandDataIB = [1685988548.316017][834669:834671] CHIP:DMG: { [1685988548.316020][834669:834671] CHIP:DMG: CommandPathIB = [1685988548.316024][834669:834671] CHIP:DMG: { [1685988548.316027][834669:834671] CHIP:DMG: EndpointId = 0x0, [1685988548.316031][834669:834671] CHIP:DMG: ClusterId = 0x31, [1685988548.316034][834669:834671] CHIP:DMG: CommandId = 0x7, [1685988548.316037][834669:834671] CHIP:DMG: }, [1685988548.316041][834669:834671] CHIP:DMG: [1685988548.316045][834669:834671] CHIP:DMG: CommandFields = [1685988548.316048][834669:834671] CHIP:DMG: { [1685988548.316054][834669:834671] CHIP:DMG: 0x0 = 0, [1685988548.316057][834669:834671] CHIP:DMG: 0x2 = NULL [1685988548.316060][834669:834671] CHIP:DMG: }, [1685988548.316062][834669:834671] CHIP:DMG: }, [1685988548.316066][834669:834671] CHIP:DMG: [1685988548.316069][834669:834671] CHIP:DMG: }, [1685988548.316072][834669:834671] CHIP:DMG: [1685988548.316074][834669:834671] CHIP:DMG: ], [1685988548.316080][834669:834671] CHIP:DMG: [1685988548.316083][834669:834671] CHIP:DMG: InteractionModelRevision = 1 [1685988548.316086][834669:834671] CHIP:DMG: }, [1685988548.316105][834669:834671] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007 [1685988548.316128][834669:834671] CHIP:CTL: Received ConnectNetwork response, networkingStatus=0 [1685988548.316144][834669:834671] CHIP:CTL: Successfully finished commissioning step 'WiFiNetworkEnable' [1685988548.316153][834669:834671] CHIP:CTL: Commissioning stage next step: 'WiFiNetworkEnable' -> 'FindOperational' [1685988548.316160][834669:834671] CHIP:CTL: Performing next commissioning step 'FindOperational' [1685988548.316164][834669:834671] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000007283] [1685988548.316169][834669:834671] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1685988548.316185][834669:834671] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 1 --> 2 [1685988548.316486][834669:834671] CHIP:DMG: ICR moving to [AwaitingDe] [1685988548.426779][834669:834671] CHIP:BLE: BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:174: CHIP Error 0x00000032: Timeout [1685988548.516276][834669:834671] CHIP:DIS: Checking node lookup status after 200 ms [1685988549.613084][834669:834671] CHIP:DIS: UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540: new best score: 3 [1685988549.613125][834669:834671] CHIP:DIS: UDP:192.168.202.40%wlp3s0:5540: score has not improved: 2 [1685988549.613131][834669:834671] CHIP:DIS: Checking node lookup status after 1297 ms [1685988549.613149][834669:834671] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: Updating device address to UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540 while in state 2 [1685988549.613158][834669:834671] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 2 --> 3 [1685988549.613248][834669:834671] CHIP:IN: SecureSession[0x7fbe88014520]: Allocated Type:2 LSID:49794 [1685988549.613267][834669:834671] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000007283 [1685988549.613874][834669:834671] CHIP:EM: <<< [E:16305i S:0 M:13186443] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1685988549.613923][834669:834671] CHIP:IN: (U) Sending msg 13186443 to IP address 'UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540' [1685988549.614083][834669:834671] CHIP:SC: Sent Sigma1 msg [1685988549.614092][834669:834671] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 3 --> 4 [1685988549.843902][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685988549.969229][834669:834671] CHIP:EM: Retransmitting MessageCounter:13186443 on exchange 16305i Send Cnt 1 [1685988549.969428][834669:834671] CHIP:IN: (U) Sending msg 13186443 to IP address 'UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540' [1685988550.008937][834669:834671] CHIP:EM: >>> [E:16305i S:0 M:125335178 (Ack:13186443)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988550.008980][834669:834671] CHIP:EM: Found matching exchange: 16305i, Delegate: 0x7fbe88014298 [1685988550.008998][834669:834671] CHIP:EM: Rxd Ack; Removing MessageCounter:13186443 from Retrans Table on exchange 16305i [1685988550.311281][834669:834671] CHIP:EM: >>> [E:16305i S:0 M:125335179 (Ack:13186443)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1685988550.311326][834669:834671] CHIP:EM: Found matching exchange: 16305i, Delegate: 0x7fbe88014298 [1685988550.311337][834669:834671] CHIP:EM: CHIP MessageCounter:13186443 not in RetransTable on exchange 16305i [1685988550.311360][834669:834671] CHIP:SC: Received Sigma2 msg [1685988550.311380][834669:834671] CHIP:SC: Peer assigned session session ID 17166 [1685988550.313620][834669:834671] CHIP:SC: Sending Sigma3 [1685988550.313952][834669:834671] CHIP:EM: <<< [E:16305i S:0 M:13186444 (Ack:125335179)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1685988550.314117][834669:834671] CHIP:IN: (U) Sending msg 13186444 to IP address 'UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540' [1685988550.314375][834669:834671] CHIP:SC: Sent Sigma3 msg [1685988550.314432][834669:834671] CHIP:EM: >>> [E:16305i S:0 M:125335180 (Ack:13186443)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988550.314449][834669:834671] CHIP:EM: Found matching exchange: 16305i, Delegate: 0x7fbe88014298 [1685988550.314470][834669:834671] CHIP:EM: CHIP MessageCounter:13186443 not in RetransTable on exchange 16305i [1685988550.514859][834669:834671] CHIP:EM: >>> [E:16305i S:0 M:125335181 (Ack:13186444)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988550.514899][834669:834671] CHIP:EM: Found matching exchange: 16305i, Delegate: 0x7fbe88014298 [1685988550.514917][834669:834671] CHIP:EM: Rxd Ack; Removing MessageCounter:13186444 from Retrans Table on exchange 16305i [1685988551.129455][834669:834671] CHIP:EM: >>> [E:16305i S:0 M:125335182 (Ack:13186444)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685988551.129500][834669:834671] CHIP:EM: Found matching exchange: 16305i, Delegate: 0x7fbe88014298 [1685988551.129513][834669:834671] CHIP:EM: CHIP MessageCounter:13186444 not in RetransTable on exchange 16305i [1685988551.129544][834669:834671] CHIP:SC: Success status report received. Session was established [1685988551.133162][834669:834671] CHIP:SC: SecureSession[0x7fbe88014520, LSID:49794]: State change 'kEstablishing' --> 'kActive' [1685988551.133172][834669:834671] CHIP:IN: SecureSession[0x7fbe88014520]: Activated - Type:2 LSID:49794 [1685988551.133175][834669:834671] CHIP:IN: New secure session activated for device <0000000000007283, 1>, LSID:49794 PSID:17166! [1685988551.133183][834669:834671] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 4 --> 5 [1685988551.133252][834669:834671] CHIP:CTL: Successfully finished commissioning step 'FindOperational' [1685988551.133265][834669:834671] CHIP:CTL: Commissioning stage next step: 'FindOperational' -> 'SendComplete' [1685988551.133273][834669:834671] CHIP:CTL: Performing next commissioning step 'SendComplete' [1685988551.133317][834669:834671] CHIP:DMG: ICR moving to [AddingComm] [1685988551.133326][834669:834671] CHIP:DMG: ICR moving to [AddedComma] [1685988551.133399][834669:834671] CHIP:EM: <<< [E:16306i S:49794 M:228453597] (S) Msg TX to 1:0000000000007283 [173B] --- Type 0001:08 (IM:InvokeCommandRequest) [1685988551.133408][834669:834671] CHIP:IN: (S) Sending msg 228453597 on secure session with LSID: 49794 [1685988551.133558][834669:834671] CHIP:DMG: ICR moving to [CommandSen] [1685988551.133575][834669:834671] CHIP:EM: <<< [E:16305i S:0 M:13186445 (Ack:125335182)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988551.133627][834669:834671] CHIP:IN: (U) Sending msg 13186445 to IP address 'UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540' [1685988551.133645][834669:834671] CHIP:EM: Flushed pending ack for MessageCounter:125335182 on exchange 16305i [1685988551.336242][834669:834671] CHIP:EM: >>> [E:16306i S:49794 M:215940403 (Ack:228453597)] (S) Msg RX from 1:0000000000007283 [173B] --- Type 0001:09 (IM:InvokeCommandResponse) [1685988551.336293][834669:834671] CHIP:EM: Found matching exchange: 16306i, Delegate: 0x7fbe9004a898 [1685988551.336315][834669:834671] CHIP:EM: Rxd Ack; Removing MessageCounter:228453597 from Retrans Table on exchange 16306i [1685988551.336332][834669:834671] CHIP:DMG: ICR moving to [ResponseRe] [1685988551.336360][834669:834671] CHIP:DMG: InvokeResponseMessage = [1685988551.336367][834669:834671] CHIP:DMG: { [1685988551.336383][834669:834671] CHIP:DMG: suppressResponse = false, [1685988551.336393][834669:834671] CHIP:DMG: InvokeResponseIBs = [1685988551.336410][834669:834671] CHIP:DMG: [ [1685988551.336420][834669:834671] CHIP:DMG: InvokeResponseIB = [1685988551.336440][834669:834671] CHIP:DMG: { [1685988551.336452][834669:834671] CHIP:DMG: CommandDataIB = [1685988551.336464][834669:834671] CHIP:DMG: { [1685988551.336475][834669:834671] CHIP:DMG: CommandPathIB = [1685988551.336488][834669:834671] CHIP:DMG: { [1685988551.336498][834669:834671] CHIP:DMG: EndpointId = 0x0, [1685988551.336509][834669:834671] CHIP:DMG: ClusterId = 0x30, [1685988551.336521][834669:834671] CHIP:DMG: CommandId = 0x5, [1685988551.336530][834669:834671] CHIP:DMG: }, [1685988551.336542][834669:834671] CHIP:DMG: [1685988551.336552][834669:834671] CHIP:DMG: CommandFields = [1685988551.336567][834669:834671] CHIP:DMG: { [1685988551.336576][834669:834671] CHIP:DMG: 0x0 = 0, [1685988551.336591][834669:834671] CHIP:DMG: 0x1 = "" (0 chars), [1685988551.336601][834669:834671] CHIP:DMG: }, [1685988551.336610][834669:834671] CHIP:DMG: }, [1685988551.336624][834669:834671] CHIP:DMG: [1685988551.336631][834669:834671] CHIP:DMG: }, [1685988551.336645][834669:834671] CHIP:DMG: [1685988551.336651][834669:834671] CHIP:DMG: ], [1685988551.336667][834669:834671] CHIP:DMG: [1685988551.336674][834669:834671] CHIP:DMG: InteractionModelRevision = 1 [1685988551.336683][834669:834671] CHIP:DMG: }, [1685988551.336724][834669:834671] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005 [1685988551.336741][834669:834671] CHIP:CTL: Received CommissioningComplete response, errorCode=0 [1685988551.336754][834669:834671] CHIP:CTL: Successfully finished commissioning step 'SendComplete' [1685988551.336761][834669:834671] CHIP:CTL: Commissioning stage next step: 'SendComplete' -> 'Cleanup' [1685988551.336774][834669:834671] CHIP:CTL: Performing next commissioning step 'Cleanup' [1685988551.336781][834669:834671] CHIP:DIS: Closing all BLE connections [1685988551.336789][834669:834671] CHIP:IN: Clearing BLE pending packets. [1685988551.337050][834669:834671] CHIP:BLE: Auto-closing end point's BLE connection. [1685988551.337058][834669:834671] CHIP:DL: Closing BLE GATT connection (con 0x7fbe9003bce0) [1685988551.337105][834669:834670] CHIP:DL: BluezDisconnect peer=F2:E4:E2:24:9E:41 [1685988553.220607][834669:834671] CHIP:IN: SecureSession[0x7fbe88012b00]: MarkForEviction Type:1 LSID:49793 [1685988553.220640][834669:834671] CHIP:SC: SecureSession[0x7fbe88012b00, LSID:49793]: State change 'kActive' --> 'kPendingEviction' [1685988553.220684][834669:834671] CHIP:IN: SecureSession[0x7fbe88012b00]: Released - Type:1 LSID:49793 [1685988553.220711][834669:834671] CHIP:CTL: Successfully finished commissioning step 'Cleanup' [1685988553.220734][834669:834671] CHIP:TOO: Device commissioning completed with success [1685988553.220820][834669:834671] CHIP:DMG: ICR moving to [AwaitingDe] [1685988553.220922][834669:834671] CHIP:EM: <<< [E:16306i S:49794 M:228453598 (Ack:215940403)] (S) Msg TX to 1:0000000000007283 [173B] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988553.220963][834669:834671] CHIP:IN: (S) Sending msg 228453598 on secure session with LSID: 49794 [1685988553.221045][834669:834670] CHIP:DL: Bluez disconnected [1685988553.221070][834669:834670] CHIP:DL: Bluez notify CHIPoBluez connection disconnected [1685988553.221058][834669:834671] CHIP:EM: Flushed pending ack for MessageCounter:215940403 on exchange 16306i [1685988553.221120][834669:834671] CHIP:DL: HandlePlatformSpecificBLEEvent 16388 [1685988553.221142][834669:834671] CHIP:BLE: no endpoint for unsub complete [1685988553.221407][834669:834669] CHIP:CTL: Shutting down the commissioner [1685988553.221443][834669:834669] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988553.221504][834669:834669] CHIP:CTL: Shutting down the controller [1685988553.221516][834669:834669] CHIP:IN: Expiring all sessions for fabric 0x1!! [1685988553.221522][834669:834669] CHIP:IN: SecureSession[0x7fbe88014520]: MarkForEviction Type:2 LSID:49794 [1685988553.221529][834669:834669] CHIP:SC: SecureSession[0x7fbe88014520, LSID:49794]: State change 'kActive' --> 'kPendingEviction' [1685988553.221535][834669:834669] CHIP:IN: SecureSession[0x7fbe88014520]: Released - Type:2 LSID:49794 [1685988553.221544][834669:834669] CHIP:FP: Forgetting fabric 0x1 [1685988553.221558][834669:834669] CHIP:TS: Pending Last Known Good Time: 2023-06-05T15:07:23 [1685988553.221667][834669:834669] CHIP:TS: Previous Last Known Good Time: 2023-06-05T15:07:23 [1685988553.221689][834669:834669] CHIP:TS: Reverted Last Known Good Time to previous value [1685988553.221710][834669:834669] CHIP:CTL: Shutting down the commissioner [1685988553.221715][834669:834669] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988553.221735][834669:834669] CHIP:CTL: Shutting down the controller [1685988553.221739][834669:834669] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1685988553.221788][834669:834669] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1685988553.221809][834669:834669] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1685988553.221842][834669:834669] CHIP:FP: Shutting down FabricTable [1685988553.221849][834669:834669] CHIP:TS: Pending Last Known Good Time: 2023-06-05T15:07:23 [1685988553.221892][834669:834669] CHIP:TS: Previous Last Known Good Time: 2023-06-05T15:07:23 [1685988553.221897][834669:834669] CHIP:TS: Reverted Last Known Good Time to previous value [1685988553.222130][834669:834669] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-WBuDdT) [1685988553.222386][834669:834669] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685988553.222395][834669:834669] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1685988553.222398][834669:834669] CHIP:DL: Inet Layer shutdown [1685988553.222400][834669:834669] CHIP:DL: BLE shutdown [1685988553.222630][834669:834669] CHIP:DL: System Layer shutdown vaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool scenes read cluster-revision 0x7283 1 [1685988611.441939][835736:835736] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1685988611.444873][835736:835736] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1685988611.444921][835736:835736] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1685988611.444935][835736:835736] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1685988611.445085][835736:835736] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-PEq39C) [1685988611.445339][835736:835736] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685988611.445347][835736:835736] CHIP:DL: NVS set: chip-counters/reboot-count = 68 (0x44) [1685988611.446701][835736:835736] CHIP:DL: Got Ethernet interface: enp2s0f0 [1685988611.446835][835736:835736] CHIP:DL: Found the primary Ethernet interface:enp2s0f0 [1685988611.446984][835736:835736] CHIP:DL: Got WiFi interface: wlp3s0 [1685988611.448581][835736:835736] CHIP:DL: Found the primary WiFi interface:wlp3s0 [1685988611.448658][835736:835736] CHIP:IN: UDP::Init bind&listen port=0 [1685988611.448710][835736:835736] CHIP:IN: UDP::Init bound to port=36482 [1685988611.448721][835736:835736] CHIP:IN: UDP::Init bind&listen port=0 [1685988611.448747][835736:835736] CHIP:IN: UDP::Init bound to port=47072 [1685988611.448754][835736:835736] CHIP:IN: BLEBase::Init - setting/overriding transport [1685988611.448759][835736:835736] CHIP:IN: TransportMgr initialized [1685988611.448781][835736:835736] CHIP:FP: Initializing FabricTable from persistent storage [1685988611.448908][835736:835736] CHIP:TS: Last Known Good Time: 2023-06-05T15:07:23 [1685988611.449745][835736:835736] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x7DFDC0CC2967173B, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1685988611.450073][835736:835736] CHIP:ZCL: Using ZAP configuration... [1685988611.451249][835736:835736] CHIP:CTL: System State Initialized... [1685988611.451261][835736:835736] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988611.451269][835736:835736] CHIP:CTL: Setting attestation nonce to random value [1685988611.451274][835736:835736] CHIP:CTL: Setting CSR nonce to random value [1685988611.451284][835736:835736] CHIP:IN: UDP::Init bind&listen port=5550 [1685988611.451291][835736:835736] CHIP:IN: UDP::Init bound to port=5550 [1685988611.451294][835736:835736] CHIP:IN: UDP::Init bind&listen port=5550 [1685988611.451299][835736:835736] CHIP:IN: UDP::Init bound to port=5550 [1685988611.451301][835736:835736] CHIP:IN: TransportMgr initialized [1685988611.451365][835736:835738] CHIP:DL: CHIP task running [1685988611.451387][835736:835738] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1685988611.451465][835736:835738] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988611.451472][835736:835738] CHIP:CTL: Setting attestation nonce to random value [1685988611.451490][835736:835738] CHIP:CTL: Setting CSR nonce to random value [1685988611.451710][835736:835738] CHIP:CTL: Generating NOC [1685988611.451928][835736:835738] CHIP:FP: Validating NOC chain [1685988611.452290][835736:835738] CHIP:FP: NOC chain validation successful [1685988611.452319][835736:835738] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1685988611.452325][835736:835738] CHIP:TS: Last Known Good Time: 2023-06-05T15:07:23 [1685988611.452327][835736:835738] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1685988611.452330][835736:835738] CHIP:TS: Retaining current Last Known Good Time [1685988611.452977][835736:835738] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1685988611.453216][835736:835738] CHIP:TS: Committing Last Known Good Time to storage: 2023-06-05T15:07:23 [1685988611.453437][835736:835738] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 7DFDC0CC2967173B) [1685988611.453444][835736:835738] CHIP:IN: UDP::Init bind&listen port=5550 [1685988611.453456][835736:835738] CHIP:IN: UDP::Init bound to port=5550 [1685988611.453458][835736:835738] CHIP:IN: UDP::Init bind&listen port=5550 [1685988611.453469][835736:835738] CHIP:IN: UDP::Init bound to port=5550 [1685988611.453471][835736:835738] CHIP:IN: TransportMgr initialized [1685988611.455355][835736:835738] CHIP:TOO: Sending command to node 0x7283 [1685988611.455412][835736:835738] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000007283] [1685988611.455423][835736:835738] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1685988611.455428][835736:835738] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 1 --> 2 [1685988611.655375][835736:835738] CHIP:DIS: Checking node lookup status after 200 ms [1685988611.655607][835736:835738] CHIP:DIS: UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540: new best score: 3 [1685988611.655935][835736:835738] CHIP:DIS: Lookup clearing interface for non LL address [1685988611.655954][835736:835738] CHIP:DIS: UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540: new best score: 7 [1685988611.656178][835736:835738] CHIP:DIS: UDP:192.168.202.40%wlp3s0:5540: score has not improved: 2 [1685988611.656185][835736:835738] CHIP:DIS: Checking node lookup status after 201 ms [1685988611.656195][835736:835738] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: Updating device address to UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c]:5540 while in state 2 [1685988611.656206][835736:835738] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 2 --> 3 [1685988611.656305][835736:835738] CHIP:IN: SecureSession[0x7f63a400b070]: Allocated Type:2 LSID:48221 [1685988611.656324][835736:835738] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000007283 [1685988611.656962][835736:835738] CHIP:EM: <<< [E:12788i S:0 M:239444711] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1685988611.656990][835736:835738] CHIP:IN: (U) Sending msg 239444711 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c]:5540' [1685988611.657111][835736:835738] CHIP:SC: Sent Sigma1 msg [1685988611.657120][835736:835738] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 3 --> 4 [1685988611.937354][835736:835738] CHIP:EM: >>> [E:12788i S:0 M:125335183 (Ack:239444711)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988611.937377][835736:835738] CHIP:EM: Found matching exchange: 12788i, Delegate: 0x7f63a400e1b8 [1685988611.937389][835736:835738] CHIP:EM: Rxd Ack; Removing MessageCounter:239444711 from Retrans Table on exchange 12788i [1685988612.263069][835736:835738] CHIP:EM: >>> [E:12788i S:0 M:125335184 (Ack:239444711)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1685988612.263112][835736:835738] CHIP:EM: Found matching exchange: 12788i, Delegate: 0x7f63a400e1b8 [1685988612.263122][835736:835738] CHIP:EM: CHIP MessageCounter:239444711 not in RetransTable on exchange 12788i [1685988612.263145][835736:835738] CHIP:SC: Received Sigma2 msg [1685988612.263161][835736:835738] CHIP:SC: Peer assigned session session ID 17167 [1685988612.264616][835736:835738] CHIP:SC: Sending Sigma3 [1685988612.264747][835736:835738] CHIP:EM: <<< [E:12788i S:0 M:239444712 (Ack:125335184)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1685988612.264797][835736:835738] CHIP:IN: (U) Sending msg 239444712 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540' [1685988612.264857][835736:835738] CHIP:SC: Sent Sigma3 msg [1685988612.308032][835736:835738] CHIP:EM: >>> [E:12788i S:0 M:125335185 (Ack:239444712)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988612.308066][835736:835738] CHIP:EM: Found matching exchange: 12788i, Delegate: 0x7f63a400e1b8 [1685988612.308085][835736:835738] CHIP:EM: Rxd Ack; Removing MessageCounter:239444712 from Retrans Table on exchange 12788i [1685988613.082009][835736:835738] CHIP:EM: >>> [E:12788i S:0 M:125335186 (Ack:239444712)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685988613.082048][835736:835738] CHIP:EM: Found matching exchange: 12788i, Delegate: 0x7f63a400e1b8 [1685988613.082072][835736:835738] CHIP:EM: CHIP MessageCounter:239444712 not in RetransTable on exchange 12788i [1685988613.082110][835736:835738] CHIP:SC: Success status report received. Session was established [1685988613.085938][835736:835738] CHIP:SC: SecureSession[0x7f63a400b070, LSID:48221]: State change 'kEstablishing' --> 'kActive' [1685988613.085958][835736:835738] CHIP:IN: SecureSession[0x7f63a400b070]: Activated - Type:2 LSID:48221 [1685988613.085969][835736:835738] CHIP:IN: New secure session activated for device <0000000000007283, 1>, LSID:48221 PSID:17167! [1685988613.086015][835736:835738] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 4 --> 5 [1685988613.086083][835736:835738] CHIP:TOO: cluster 0x0000_0005, attribute: 0x0000_FFFD, endpoint 1 [1685988613.086095][835736:835738] CHIP:TOO: Sending ReadAttribute to: [1685988613.086113][835736:835738] CHIP:DMG: SendReadRequest ReadClient[0x7f63a400f3f0]: Sending Read Request [1685988613.086200][835736:835738] CHIP:EM: <<< [E:12789i S:48221 M:234170900] (S) Msg TX to 1:0000000000007283 [173B] --- Type 0001:02 (IM:ReadRequest) [1685988613.086243][835736:835738] CHIP:IN: (S) Sending msg 234170900 on secure session with LSID: 48221 [1685988613.086373][835736:835738] CHIP:DMG: MoveToState ReadClient[0x7f63a400f3f0]: Moving to [AwaitingIn] [1685988613.086407][835736:835738] CHIP:EM: <<< [E:12788i S:0 M:239444713 (Ack:125335186)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988613.086466][835736:835738] CHIP:IN: (U) Sending msg 239444713 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540' [1685988613.086543][835736:835738] CHIP:EM: Flushed pending ack for MessageCounter:125335186 on exchange 12788i [1685988613.389216][835736:835738] CHIP:EM: >>> [E:12789i S:48221 M:198841692 (Ack:234170900)] (S) Msg RX from 1:0000000000007283 [173B] --- Type 0001:05 (IM:ReportData) [1685988613.389281][835736:835738] CHIP:EM: Found matching exchange: 12789i, Delegate: 0x7f63a400f400 [1685988613.389298][835736:835738] CHIP:EM: Rxd Ack; Removing MessageCounter:234170900 from Retrans Table on exchange 12789i [1685988613.389335][835736:835738] CHIP:DMG: ReportDataMessage = [1685988613.389344][835736:835738] CHIP:DMG: { [1685988613.389349][835736:835738] CHIP:DMG: AttributeReportIBs = [1685988613.389359][835736:835738] CHIP:DMG: [ [1685988613.389365][835736:835738] CHIP:DMG: AttributeReportIB = [1685988613.389378][835736:835738] CHIP:DMG: { [1685988613.389385][835736:835738] CHIP:DMG: AttributeDataIB = [1685988613.389393][835736:835738] CHIP:DMG: { [1685988613.389402][835736:835738] CHIP:DMG: DataVersion = 0x29cd3c9a, [1685988613.389408][835736:835738] CHIP:DMG: AttributePathIB = [1685988613.389419][835736:835738] CHIP:DMG: { [1685988613.389427][835736:835738] CHIP:DMG: Endpoint = 0x1, [1685988613.389434][835736:835738] CHIP:DMG: Cluster = 0x5, [1685988613.389440][835736:835738] CHIP:DMG: Attribute = 0x0000_FFFD, [1685988613.389447][835736:835738] CHIP:DMG: } [1685988613.389462][835736:835738] CHIP:DMG: [1685988613.389471][835736:835738] CHIP:DMG: Data = 4, [1685988613.389477][835736:835738] CHIP:DMG: }, [1685988613.389486][835736:835738] CHIP:DMG: [1685988613.389491][835736:835738] CHIP:DMG: }, [1685988613.389501][835736:835738] CHIP:DMG: [1685988613.389508][835736:835738] CHIP:DMG: ], [1685988613.389517][835736:835738] CHIP:DMG: [1685988613.389528][835736:835738] CHIP:DMG: SuppressResponse = true, [1685988613.389535][835736:835738] CHIP:DMG: InteractionModelRevision = 1 [1685988613.389541][835736:835738] CHIP:DMG: } [1685988613.394387][835736:835738] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0005 Attribute 0x0000_FFFD DataVersion: 701316250 [1685988613.394803][835736:835738] CHIP:TOO: ClusterRevision: 4 [1685988613.395026][835736:835738] CHIP:EM: <<< [E:12789i S:48221 M:234170901 (Ack:198841692)] (S) Msg TX to 1:0000000000007283 [173B] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988613.395045][835736:835738] CHIP:IN: (S) Sending msg 234170901 on secure session with LSID: 48221 [1685988613.395180][835736:835738] CHIP:EM: Flushed pending ack for MessageCounter:198841692 on exchange 12789i [1685988613.395384][835736:835736] CHIP:CTL: Shutting down the commissioner [1685988613.395418][835736:835736] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988613.395488][835736:835736] CHIP:CTL: Shutting down the controller [1685988613.395498][835736:835736] CHIP:IN: Expiring all sessions for fabric 0x1!! [1685988613.395504][835736:835736] CHIP:IN: SecureSession[0x7f63a400b070]: MarkForEviction Type:2 LSID:48221 [1685988613.395511][835736:835736] CHIP:SC: SecureSession[0x7f63a400b070, LSID:48221]: State change 'kActive' --> 'kPendingEviction' [1685988613.395519][835736:835736] CHIP:IN: SecureSession[0x7f63a400b070]: Released - Type:2 LSID:48221 [1685988613.395527][835736:835736] CHIP:FP: Forgetting fabric 0x1 [1685988613.395541][835736:835736] CHIP:TS: Pending Last Known Good Time: 2023-06-05T15:07:23 [1685988613.395629][835736:835736] CHIP:TS: Previous Last Known Good Time: 2023-06-05T15:07:23 [1685988613.395635][835736:835736] CHIP:TS: Reverted Last Known Good Time to previous value [1685988613.395656][835736:835736] CHIP:CTL: Shutting down the commissioner [1685988613.395660][835736:835736] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988613.395681][835736:835736] CHIP:CTL: Shutting down the controller [1685988613.395686][835736:835736] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1685988613.395745][835736:835736] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1685988613.395765][835736:835736] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1685988613.395779][835736:835736] CHIP:FP: Shutting down FabricTable [1685988613.395786][835736:835736] CHIP:TS: Pending Last Known Good Time: 2023-06-05T15:07:23 [1685988613.395824][835736:835736] CHIP:TS: Previous Last Known Good Time: 2023-06-05T15:07:23 [1685988613.395829][835736:835736] CHIP:TS: Reverted Last Known Good Time to previous value [1685988613.396039][835736:835736] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-toXCzS) [1685988613.396443][835736:835736] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685988613.396454][835736:835736] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1685988613.396457][835736:835736] CHIP:DL: Inet Layer shutdown [1685988613.396458][835736:835736] CHIP:DL: BLE shutdown [1685988613.396464][835736:835736] CHIP:DL: System Layer shutdown vaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool scenes read feature-map 0x7283 1 [1685988682.812062][835905:835905] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1685988682.814485][835905:835905] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1685988682.814533][835905:835905] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1685988682.814549][835905:835905] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1685988682.814845][835905:835905] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-yHpLqk) [1685988682.815332][835905:835905] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685988682.815343][835905:835905] CHIP:DL: NVS set: chip-counters/reboot-count = 69 (0x45) [1685988682.816794][835905:835905] CHIP:DL: Got Ethernet interface: enp2s0f0 [1685988682.816969][835905:835905] CHIP:DL: Found the primary Ethernet interface:enp2s0f0 [1685988682.817136][835905:835905] CHIP:DL: Got WiFi interface: wlp3s0 [1685988682.820051][835905:835905] CHIP:DL: Found the primary WiFi interface:wlp3s0 [1685988682.820149][835905:835905] CHIP:IN: UDP::Init bind&listen port=0 [1685988682.820187][835905:835905] CHIP:IN: UDP::Init bound to port=45467 [1685988682.820194][835905:835905] CHIP:IN: UDP::Init bind&listen port=0 [1685988682.820215][835905:835905] CHIP:IN: UDP::Init bound to port=39314 [1685988682.820221][835905:835905] CHIP:IN: BLEBase::Init - setting/overriding transport [1685988682.820225][835905:835905] CHIP:IN: TransportMgr initialized [1685988682.820240][835905:835905] CHIP:FP: Initializing FabricTable from persistent storage [1685988682.820370][835905:835905] CHIP:TS: Last Known Good Time: 2023-06-05T15:07:23 [1685988682.821042][835905:835905] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x7DFDC0CC2967173B, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1685988682.821496][835905:835905] CHIP:ZCL: Using ZAP configuration... [1685988682.822679][835905:835905] CHIP:CTL: System State Initialized... [1685988682.822693][835905:835905] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988682.822702][835905:835905] CHIP:CTL: Setting attestation nonce to random value [1685988682.822707][835905:835905] CHIP:CTL: Setting CSR nonce to random value [1685988682.822717][835905:835905] CHIP:IN: UDP::Init bind&listen port=5550 [1685988682.822725][835905:835905] CHIP:IN: UDP::Init bound to port=5550 [1685988682.822727][835905:835905] CHIP:IN: UDP::Init bind&listen port=5550 [1685988682.822733][835905:835905] CHIP:IN: UDP::Init bound to port=5550 [1685988682.822734][835905:835905] CHIP:IN: TransportMgr initialized [1685988682.822848][835905:835907] CHIP:DL: CHIP task running [1685988682.822879][835905:835907] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1685988682.822961][835905:835907] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988682.822975][835905:835907] CHIP:CTL: Setting attestation nonce to random value [1685988682.822999][835905:835907] CHIP:CTL: Setting CSR nonce to random value [1685988682.823227][835905:835907] CHIP:CTL: Generating NOC [1685988682.823469][835905:835907] CHIP:FP: Validating NOC chain [1685988682.823843][835905:835907] CHIP:FP: NOC chain validation successful [1685988682.823873][835905:835907] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1685988682.823877][835905:835907] CHIP:TS: Last Known Good Time: 2023-06-05T15:07:23 [1685988682.823880][835905:835907] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1685988682.823882][835905:835907] CHIP:TS: Retaining current Last Known Good Time [1685988682.824565][835905:835907] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1685988682.825156][835905:835907] CHIP:TS: Committing Last Known Good Time to storage: 2023-06-05T15:07:23 [1685988682.825701][835905:835907] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 7DFDC0CC2967173B) [1685988682.825728][835905:835907] CHIP:IN: UDP::Init bind&listen port=5550 [1685988682.825755][835905:835907] CHIP:IN: UDP::Init bound to port=5550 [1685988682.825761][835905:835907] CHIP:IN: UDP::Init bind&listen port=5550 [1685988682.825776][835905:835907] CHIP:IN: UDP::Init bound to port=5550 [1685988682.825781][835905:835907] CHIP:IN: TransportMgr initialized [1685988682.828377][835905:835907] CHIP:TOO: Sending command to node 0x7283 [1685988682.828438][835905:835907] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000007283] [1685988682.828452][835905:835907] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1685988682.828463][835905:835907] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 1 --> 2 [1685988682.925434][835905:835907] CHIP:DIS: UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540: new best score: 3 [1685988682.925739][835905:835907] CHIP:DIS: Lookup clearing interface for non LL address [1685988682.925760][835905:835907] CHIP:DIS: UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540: new best score: 7 [1685988682.926011][835905:835907] CHIP:DIS: UDP:192.168.202.40%wlp3s0:5540: score has not improved: 2 [1685988682.926019][835905:835907] CHIP:DIS: Checking node lookup status after 98 ms [1685988682.926023][835905:835907] CHIP:DIS: Keeping DNSSD lookup active [1685988682.926324][835905:835907] CHIP:DIS: UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540: score has not improved: 3 [1685988682.926691][835905:835907] CHIP:DIS: UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540: score has not improved: 7 [1685988682.926871][835905:835907] CHIP:DIS: UDP:192.168.202.40%wlp3s0:5540: score has not improved: 2 [1685988682.926877][835905:835907] CHIP:DIS: Checking node lookup status after 99 ms [1685988682.926881][835905:835907] CHIP:DIS: Keeping DNSSD lookup active [1685988683.028139][835905:835907] CHIP:DIS: Checking node lookup status after 200 ms [1685988683.028200][835905:835907] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: Updating device address to UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c]:5540 while in state 2 [1685988683.028211][835905:835907] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 2 --> 3 [1685988683.028309][835905:835907] CHIP:IN: SecureSession[0x7fc32000b070]: Allocated Type:2 LSID:41927 [1685988683.028348][835905:835907] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000007283 [1685988683.028920][835905:835907] CHIP:EM: <<< [E:65290i S:0 M:243162531] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1685988683.028947][835905:835907] CHIP:IN: (U) Sending msg 243162531 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c]:5540' [1685988683.029067][835905:835907] CHIP:SC: Sent Sigma1 msg [1685988683.029076][835905:835907] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 3 --> 4 [1685988683.226603][835905:835907] CHIP:EM: >>> [E:65290i S:0 M:125335187 (Ack:243162531)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988683.226646][835905:835907] CHIP:EM: Found matching exchange: 65290i, Delegate: 0x7fc32000e1b8 [1685988683.226664][835905:835907] CHIP:EM: Rxd Ack; Removing MessageCounter:243162531 from Retrans Table on exchange 65290i [1685988683.534090][835905:835907] CHIP:EM: >>> [E:65290i S:0 M:125335188 (Ack:243162531)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1685988683.534157][835905:835907] CHIP:EM: Found matching exchange: 65290i, Delegate: 0x7fc32000e1b8 [1685988683.534167][835905:835907] CHIP:EM: CHIP MessageCounter:243162531 not in RetransTable on exchange 65290i [1685988683.534190][835905:835907] CHIP:SC: Received Sigma2 msg [1685988683.534214][835905:835907] CHIP:SC: Peer assigned session session ID 17168 [1685988683.535663][835905:835907] CHIP:SC: Sending Sigma3 [1685988683.535922][835905:835907] CHIP:EM: <<< [E:65290i S:0 M:243162532 (Ack:125335188)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1685988683.536025][835905:835907] CHIP:IN: (U) Sending msg 243162532 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540' [1685988683.536130][835905:835907] CHIP:SC: Sent Sigma3 msg [1685988683.841255][835905:835907] CHIP:EM: >>> [E:65290i S:0 M:125335189 (Ack:243162532)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988683.841298][835905:835907] CHIP:EM: Found matching exchange: 65290i, Delegate: 0x7fc32000e1b8 [1685988683.841316][835905:835907] CHIP:EM: Rxd Ack; Removing MessageCounter:243162532 from Retrans Table on exchange 65290i [1685988684.558144][835905:835907] CHIP:EM: >>> [E:65290i S:0 M:125335190 (Ack:243162532)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685988684.558184][835905:835907] CHIP:EM: Found matching exchange: 65290i, Delegate: 0x7fc32000e1b8 [1685988684.558194][835905:835907] CHIP:EM: CHIP MessageCounter:243162532 not in RetransTable on exchange 65290i [1685988684.558218][835905:835907] CHIP:SC: Success status report received. Session was established [1685988684.561994][835905:835907] CHIP:SC: SecureSession[0x7fc32000b070, LSID:41927]: State change 'kEstablishing' --> 'kActive' [1685988684.562010][835905:835907] CHIP:IN: SecureSession[0x7fc32000b070]: Activated - Type:2 LSID:41927 [1685988684.562018][835905:835907] CHIP:IN: New secure session activated for device <0000000000007283, 1>, LSID:41927 PSID:17168! [1685988684.562031][835905:835907] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 4 --> 5 [1685988684.562104][835905:835907] CHIP:TOO: cluster 0x0000_0005, attribute: 0x0000_FFFC, endpoint 1 [1685988684.562114][835905:835907] CHIP:TOO: Sending ReadAttribute to: [1685988684.562129][835905:835907] CHIP:DMG: SendReadRequest ReadClient[0x7fc320010f40]: Sending Read Request [1685988684.562231][835905:835907] CHIP:EM: <<< [E:65291i S:41927 M:198705546] (S) Msg TX to 1:0000000000007283 [173B] --- Type 0001:02 (IM:ReadRequest) [1685988684.562264][835905:835907] CHIP:IN: (S) Sending msg 198705546 on secure session with LSID: 41927 [1685988684.562382][835905:835907] CHIP:DMG: MoveToState ReadClient[0x7fc320010f40]: Moving to [AwaitingIn] [1685988684.562414][835905:835907] CHIP:EM: <<< [E:65290i S:0 M:243162533 (Ack:125335190)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988684.562466][835905:835907] CHIP:IN: (U) Sending msg 243162533 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540' [1685988684.562500][835905:835907] CHIP:EM: Flushed pending ack for MessageCounter:125335190 on exchange 65290i [1685988684.865119][835905:835907] CHIP:EM: >>> [E:65291i S:41927 M:55163709 (Ack:198705546)] (S) Msg RX from 1:0000000000007283 [173B] --- Type 0001:05 (IM:ReportData) [1685988684.865163][835905:835907] CHIP:EM: Found matching exchange: 65291i, Delegate: 0x7fc320010f50 [1685988684.865179][835905:835907] CHIP:EM: Rxd Ack; Removing MessageCounter:198705546 from Retrans Table on exchange 65291i [1685988684.865213][835905:835907] CHIP:DMG: ReportDataMessage = [1685988684.865223][835905:835907] CHIP:DMG: { [1685988684.865227][835905:835907] CHIP:DMG: AttributeReportIBs = [1685988684.865236][835905:835907] CHIP:DMG: [ [1685988684.865242][835905:835907] CHIP:DMG: AttributeReportIB = [1685988684.865252][835905:835907] CHIP:DMG: { [1685988684.865259][835905:835907] CHIP:DMG: AttributeDataIB = [1685988684.865268][835905:835907] CHIP:DMG: { [1685988684.865277][835905:835907] CHIP:DMG: DataVersion = 0x29cd3c9a, [1685988684.865282][835905:835907] CHIP:DMG: AttributePathIB = [1685988684.865289][835905:835907] CHIP:DMG: { [1685988684.865297][835905:835907] CHIP:DMG: Endpoint = 0x1, [1685988684.865305][835905:835907] CHIP:DMG: Cluster = 0x5, [1685988684.865314][835905:835907] CHIP:DMG: Attribute = 0x0000_FFFC, [1685988684.865320][835905:835907] CHIP:DMG: } [1685988684.865328][835905:835907] CHIP:DMG: [1685988684.865336][835905:835907] CHIP:DMG: Data = 0, [1685988684.865343][835905:835907] CHIP:DMG: }, [1685988684.865352][835905:835907] CHIP:DMG: [1685988684.865357][835905:835907] CHIP:DMG: }, [1685988684.865366][835905:835907] CHIP:DMG: [1685988684.865372][835905:835907] CHIP:DMG: ], [1685988684.865383][835905:835907] CHIP:DMG: [1685988684.865389][835905:835907] CHIP:DMG: SuppressResponse = true, [1685988684.865394][835905:835907] CHIP:DMG: InteractionModelRevision = 1 [1685988684.865399][835905:835907] CHIP:DMG: } [1685988684.865515][835905:835907] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0005 Attribute 0x0000_FFFC DataVersion: 701316250 [1685988684.865552][835905:835907] CHIP:TOO: FeatureMap: 0 [1685988684.865632][835905:835907] CHIP:EM: <<< [E:65291i S:41927 M:198705547 (Ack:55163709)] (S) Msg TX to 1:0000000000007283 [173B] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988684.865652][835905:835907] CHIP:IN: (S) Sending msg 198705547 on secure session with LSID: 41927 [1685988684.865737][835905:835907] CHIP:EM: Flushed pending ack for MessageCounter:55163709 on exchange 65291i [1685988684.865909][835905:835905] CHIP:CTL: Shutting down the commissioner [1685988684.865928][835905:835905] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988684.865995][835905:835905] CHIP:CTL: Shutting down the controller [1685988684.866007][835905:835905] CHIP:IN: Expiring all sessions for fabric 0x1!! [1685988684.866013][835905:835905] CHIP:IN: SecureSession[0x7fc32000b070]: MarkForEviction Type:2 LSID:41927 [1685988684.866020][835905:835905] CHIP:SC: SecureSession[0x7fc32000b070, LSID:41927]: State change 'kActive' --> 'kPendingEviction' [1685988684.866027][835905:835905] CHIP:IN: SecureSession[0x7fc32000b070]: Released - Type:2 LSID:41927 [1685988684.866043][835905:835905] CHIP:FP: Forgetting fabric 0x1 [1685988684.866074][835905:835905] CHIP:TS: Pending Last Known Good Time: 2023-06-05T15:07:23 [1685988684.866202][835905:835905] CHIP:TS: Previous Last Known Good Time: 2023-06-05T15:07:23 [1685988684.866216][835905:835905] CHIP:TS: Reverted Last Known Good Time to previous value [1685988684.866242][835905:835905] CHIP:CTL: Shutting down the commissioner [1685988684.866247][835905:835905] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988684.866266][835905:835905] CHIP:CTL: Shutting down the controller [1685988684.866271][835905:835905] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1685988684.866318][835905:835905] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1685988684.866338][835905:835905] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1685988684.866352][835905:835905] CHIP:FP: Shutting down FabricTable [1685988684.866358][835905:835905] CHIP:TS: Pending Last Known Good Time: 2023-06-05T15:07:23 [1685988684.866398][835905:835905] CHIP:TS: Previous Last Known Good Time: 2023-06-05T15:07:23 [1685988684.866403][835905:835905] CHIP:TS: Reverted Last Known Good Time to previous value [1685988684.866576][835905:835905] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-2JCYiA) [1685988684.866889][835905:835905] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685988684.866911][835905:835905] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1685988684.866917][835905:835905] CHIP:DL: Inet Layer shutdown [1685988684.866921][835905:835905] CHIP:DL: BLE shutdown [1685988684.866927][835905:835905] CHIP:DL: System Layer shutdown vaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool scenes read attribute-list 0x7283 1 [1685988807.785731][836084:836084] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1685988807.787539][836084:836084] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1685988807.787569][836084:836084] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1685988807.787581][836084:836084] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1685988807.787690][836084:836084] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-tjlTbT) [1685988807.787859][836084:836084] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685988807.787866][836084:836084] CHIP:DL: NVS set: chip-counters/reboot-count = 70 (0x46) [1685988807.789222][836084:836084] CHIP:DL: Got Ethernet interface: enp2s0f0 [1685988807.789360][836084:836084] CHIP:DL: Found the primary Ethernet interface:enp2s0f0 [1685988807.789503][836084:836084] CHIP:DL: Got WiFi interface: wlp3s0 [1685988807.791708][836084:836084] CHIP:DL: Found the primary WiFi interface:wlp3s0 [1685988807.791774][836084:836084] CHIP:IN: UDP::Init bind&listen port=0 [1685988807.791795][836084:836084] CHIP:IN: UDP::Init bound to port=35220 [1685988807.791799][836084:836084] CHIP:IN: UDP::Init bind&listen port=0 [1685988807.791808][836084:836084] CHIP:IN: UDP::Init bound to port=43874 [1685988807.791811][836084:836084] CHIP:IN: BLEBase::Init - setting/overriding transport [1685988807.791813][836084:836084] CHIP:IN: TransportMgr initialized [1685988807.791823][836084:836084] CHIP:FP: Initializing FabricTable from persistent storage [1685988807.791892][836084:836084] CHIP:TS: Last Known Good Time: 2023-06-05T15:07:23 [1685988807.792340][836084:836084] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x7DFDC0CC2967173B, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1685988807.815501][836084:836084] CHIP:ZCL: Using ZAP configuration... [1685988807.817588][836084:836084] CHIP:CTL: System State Initialized... [1685988807.817613][836084:836084] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988807.817635][836084:836084] CHIP:CTL: Setting attestation nonce to random value [1685988807.817641][836084:836084] CHIP:CTL: Setting CSR nonce to random value [1685988807.817664][836084:836084] CHIP:IN: UDP::Init bind&listen port=5550 [1685988807.817676][836084:836084] CHIP:IN: UDP::Init bound to port=5550 [1685988807.817678][836084:836084] CHIP:IN: UDP::Init bind&listen port=5550 [1685988807.817687][836084:836084] CHIP:IN: UDP::Init bound to port=5550 [1685988807.817689][836084:836084] CHIP:IN: TransportMgr initialized [1685988807.817858][836084:836086] CHIP:DL: CHIP task running [1685988807.817892][836084:836086] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1685988807.817985][836084:836086] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988807.817991][836084:836086] CHIP:CTL: Setting attestation nonce to random value [1685988807.818018][836084:836086] CHIP:CTL: Setting CSR nonce to random value [1685988807.818335][836084:836086] CHIP:CTL: Generating NOC [1685988807.818642][836084:836086] CHIP:FP: Validating NOC chain [1685988807.819058][836084:836086] CHIP:FP: NOC chain validation successful [1685988807.819097][836084:836086] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1685988807.819102][836084:836086] CHIP:TS: Last Known Good Time: 2023-06-05T15:07:23 [1685988807.819105][836084:836086] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1685988807.819108][836084:836086] CHIP:TS: Retaining current Last Known Good Time [1685988807.820680][836084:836086] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1685988807.820907][836084:836086] CHIP:TS: Committing Last Known Good Time to storage: 2023-06-05T15:07:23 [1685988807.821119][836084:836086] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 7DFDC0CC2967173B) [1685988807.821126][836084:836086] CHIP:IN: UDP::Init bind&listen port=5550 [1685988807.821139][836084:836086] CHIP:IN: UDP::Init bound to port=5550 [1685988807.821141][836084:836086] CHIP:IN: UDP::Init bind&listen port=5550 [1685988807.821147][836084:836086] CHIP:IN: UDP::Init bound to port=5550 [1685988807.821148][836084:836086] CHIP:IN: TransportMgr initialized [1685988807.823042][836084:836086] CHIP:TOO: Sending command to node 0x7283 [1685988807.823100][836084:836086] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000007283] [1685988807.823112][836084:836086] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1685988807.823118][836084:836086] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 1 --> 2 [1685988807.854223][836084:836086] CHIP:DIS: UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540: new best score: 3 [1685988807.854664][836084:836086] CHIP:DIS: Lookup clearing interface for non LL address [1685988807.854721][836084:836086] CHIP:DIS: UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540: new best score: 7 [1685988807.854935][836084:836086] CHIP:DIS: UDP:192.168.202.40%wlp3s0:5540: score has not improved: 2 [1685988807.854942][836084:836086] CHIP:DIS: Checking node lookup status after 32 ms [1685988807.854946][836084:836086] CHIP:DIS: Keeping DNSSD lookup active [1685988807.855220][836084:836086] CHIP:DIS: UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540: score has not improved: 3 [1685988807.855574][836084:836086] CHIP:DIS: UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540: score has not improved: 7 [1685988807.855769][836084:836086] CHIP:DIS: UDP:192.168.202.40%wlp3s0:5540: score has not improved: 2 [1685988807.855774][836084:836086] CHIP:DIS: Checking node lookup status after 33 ms [1685988807.855777][836084:836086] CHIP:DIS: Keeping DNSSD lookup active [1685988808.023272][836084:836086] CHIP:DIS: Checking node lookup status after 200 ms [1685988808.023332][836084:836086] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: Updating device address to UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c]:5540 while in state 2 [1685988808.023341][836084:836086] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 2 --> 3 [1685988808.023423][836084:836086] CHIP:IN: SecureSession[0x7f4d3c00b070]: Allocated Type:2 LSID:56168 [1685988808.023443][836084:836086] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000007283 [1685988808.024064][836084:836086] CHIP:EM: <<< [E:62497i S:0 M:104134448] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1685988808.024092][836084:836086] CHIP:IN: (U) Sending msg 104134448 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c]:5540' [1685988808.024217][836084:836086] CHIP:SC: Sent Sigma1 msg [1685988808.024226][836084:836086] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 3 --> 4 [1685988808.112702][836084:836086] CHIP:EM: >>> [E:62497i S:0 M:125335191 (Ack:104134448)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988808.112731][836084:836086] CHIP:EM: Found matching exchange: 62497i, Delegate: 0x7f4d3c00e1b8 [1685988808.112747][836084:836086] CHIP:EM: Rxd Ack; Removing MessageCounter:104134448 from Retrans Table on exchange 62497i [1685988808.409446][836084:836086] CHIP:EM: >>> [E:62497i S:0 M:125335192 (Ack:104134448)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1685988808.409479][836084:836086] CHIP:EM: Found matching exchange: 62497i, Delegate: 0x7f4d3c00e1b8 [1685988808.409505][836084:836086] CHIP:EM: CHIP MessageCounter:104134448 not in RetransTable on exchange 62497i [1685988808.409527][836084:836086] CHIP:SC: Received Sigma2 msg [1685988808.409544][836084:836086] CHIP:SC: Peer assigned session session ID 17169 [1685988808.410971][836084:836086] CHIP:SC: Sending Sigma3 [1685988808.411106][836084:836086] CHIP:EM: <<< [E:62497i S:0 M:104134449 (Ack:125335192)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1685988808.411153][836084:836086] CHIP:IN: (U) Sending msg 104134449 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540' [1685988808.411239][836084:836086] CHIP:SC: Sent Sigma3 msg [1685988808.457174][836084:836086] CHIP:EM: >>> [E:62497i S:0 M:125335193 (Ack:104134449)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988808.457194][836084:836086] CHIP:EM: Found matching exchange: 62497i, Delegate: 0x7f4d3c00e1b8 [1685988808.457204][836084:836086] CHIP:EM: Rxd Ack; Removing MessageCounter:104134449 from Retrans Table on exchange 62497i [1685988809.287560][836084:836086] CHIP:EM: >>> [E:62497i S:0 M:125335194 (Ack:104134449)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685988809.287601][836084:836086] CHIP:EM: Found matching exchange: 62497i, Delegate: 0x7f4d3c00e1b8 [1685988809.287612][836084:836086] CHIP:EM: CHIP MessageCounter:104134449 not in RetransTable on exchange 62497i [1685988809.287636][836084:836086] CHIP:SC: Success status report received. Session was established [1685988809.289191][836084:836086] CHIP:SC: SecureSession[0x7f4d3c00b070, LSID:56168]: State change 'kEstablishing' --> 'kActive' [1685988809.289204][836084:836086] CHIP:IN: SecureSession[0x7f4d3c00b070]: Activated - Type:2 LSID:56168 [1685988809.289208][836084:836086] CHIP:IN: New secure session activated for device <0000000000007283, 1>, LSID:56168 PSID:17169! [1685988809.289218][836084:836086] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 4 --> 5 [1685988809.289274][836084:836086] CHIP:TOO: cluster 0x0000_0005, attribute: 0x0000_FFFB, endpoint 1 [1685988809.289283][836084:836086] CHIP:TOO: Sending ReadAttribute to: [1685988809.289293][836084:836086] CHIP:DMG: SendReadRequest ReadClient[0x7f4d3c010f40]: Sending Read Request [1685988809.289384][836084:836086] CHIP:EM: <<< [E:62498i S:56168 M:46384307] (S) Msg TX to 1:0000000000007283 [173B] --- Type 0001:02 (IM:ReadRequest) [1685988809.289397][836084:836086] CHIP:IN: (S) Sending msg 46384307 on secure session with LSID: 56168 [1685988809.289486][836084:836086] CHIP:DMG: MoveToState ReadClient[0x7f4d3c010f40]: Moving to [AwaitingIn] [1685988809.289535][836084:836086] CHIP:EM: <<< [E:62497i S:0 M:104134450 (Ack:125335194)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988809.289604][836084:836086] CHIP:IN: (U) Sending msg 104134450 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540' [1685988809.289644][836084:836086] CHIP:EM: Flushed pending ack for MessageCounter:125335194 on exchange 62497i [1685988809.486704][836084:836086] CHIP:IN: Received a duplicate message with MessageCounter:125335194 on exchange 62497i [1685988809.486738][836084:836086] CHIP:EM: >>> [E:62497i S:0 M:125335194 (Ack:104134449)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685988809.486751][836084:836086] CHIP:EM: Generating StandaloneAck via exchange: 62497i [1685988809.486757][836084:836086] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:125335194 on exchange 62497i [1685988809.486769][836084:836086] CHIP:EM: <<< [E:62497i S:0 M:104134451 (Ack:125335194)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988809.486824][836084:836086] CHIP:IN: (U) Sending msg 104134451 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540' [1685988809.508942][836084:836086] CHIP:EM: >>> [E:62498i S:56168 M:45007605 (Ack:46384307)] (S) Msg RX from 1:0000000000007283 [173B] --- Type 0001:05 (IM:ReportData) [1685988809.508961][836084:836086] CHIP:EM: Found matching exchange: 62498i, Delegate: 0x7f4d3c010f50 [1685988809.508970][836084:836086] CHIP:EM: Rxd Ack; Removing MessageCounter:46384307 from Retrans Table on exchange 62498i [1685988809.508992][836084:836086] CHIP:DMG: ReportDataMessage = [1685988809.508996][836084:836086] CHIP:DMG: { [1685988809.508998][836084:836086] CHIP:DMG: AttributeReportIBs = [1685988809.509004][836084:836086] CHIP:DMG: [ [1685988809.509007][836084:836086] CHIP:DMG: AttributeReportIB = [1685988809.509014][836084:836086] CHIP:DMG: { [1685988809.509016][836084:836086] CHIP:DMG: AttributeDataIB = [1685988809.509019][836084:836086] CHIP:DMG: { [1685988809.509023][836084:836086] CHIP:DMG: DataVersion = 0x29cd3c9a, [1685988809.509026][836084:836086] CHIP:DMG: AttributePathIB = [1685988809.509030][836084:836086] CHIP:DMG: { [1685988809.509033][836084:836086] CHIP:DMG: Endpoint = 0x1, [1685988809.509036][836084:836086] CHIP:DMG: Cluster = 0x5, [1685988809.509039][836084:836086] CHIP:DMG: Attribute = 0x0000_FFFB, [1685988809.509042][836084:836086] CHIP:DMG: } [1685988809.509045][836084:836086] CHIP:DMG: [1685988809.509048][836084:836086] CHIP:DMG: Data = [ [1685988809.509056][836084:836086] CHIP:DMG: 65528, 65529, 65530, 65531, 65532, 65533, 0, 1, 2, 3, 4, [1685988809.509059][836084:836086] CHIP:DMG: ], [1685988809.509061][836084:836086] CHIP:DMG: }, [1685988809.509066][836084:836086] CHIP:DMG: [1685988809.509068][836084:836086] CHIP:DMG: }, [1685988809.509073][836084:836086] CHIP:DMG: [1685988809.509075][836084:836086] CHIP:DMG: ], [1685988809.509080][836084:836086] CHIP:DMG: [1685988809.509083][836084:836086] CHIP:DMG: SuppressResponse = true, [1685988809.509085][836084:836086] CHIP:DMG: InteractionModelRevision = 1 [1685988809.509087][836084:836086] CHIP:DMG: } [1685988809.509178][836084:836086] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0005 Attribute 0x0000_FFFB DataVersion: 701316250 [1685988809.509213][836084:836086] CHIP:TOO: AttributeList: 11 entries [1685988809.509218][836084:836086] CHIP:TOO: [1]: 65528 [1685988809.509220][836084:836086] CHIP:TOO: [2]: 65529 [1685988809.509223][836084:836086] CHIP:TOO: [3]: 65530 [1685988809.509225][836084:836086] CHIP:TOO: [4]: 65531 [1685988809.509227][836084:836086] CHIP:TOO: [5]: 65532 [1685988809.509229][836084:836086] CHIP:TOO: [6]: 65533 [1685988809.509231][836084:836086] CHIP:TOO: [7]: 0 [1685988809.509233][836084:836086] CHIP:TOO: [8]: 1 [1685988809.509235][836084:836086] CHIP:TOO: [9]: 2 [1685988809.509237][836084:836086] CHIP:TOO: [10]: 3 [1685988809.509239][836084:836086] CHIP:TOO: [11]: 4 [1685988809.509277][836084:836086] CHIP:EM: <<< [E:62498i S:56168 M:46384308 (Ack:45007605)] (S) Msg TX to 1:0000000000007283 [173B] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685988809.509283][836084:836086] CHIP:IN: (S) Sending msg 46384308 on secure session with LSID: 56168 [1685988809.509332][836084:836086] CHIP:EM: Flushed pending ack for MessageCounter:45007605 on exchange 62498i [1685988809.509393][836084:836084] CHIP:CTL: Shutting down the commissioner [1685988809.509400][836084:836084] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988809.509452][836084:836084] CHIP:CTL: Shutting down the controller [1685988809.509457][836084:836084] CHIP:IN: Expiring all sessions for fabric 0x1!! [1685988809.509459][836084:836084] CHIP:IN: SecureSession[0x7f4d3c00b070]: MarkForEviction Type:2 LSID:56168 [1685988809.509461][836084:836084] CHIP:SC: SecureSession[0x7f4d3c00b070, LSID:56168]: State change 'kActive' --> 'kPendingEviction' [1685988809.509464][836084:836084] CHIP:IN: SecureSession[0x7f4d3c00b070]: Released - Type:2 LSID:56168 [1685988809.509467][836084:836084] CHIP:FP: Forgetting fabric 0x1 [1685988809.509476][836084:836084] CHIP:TS: Pending Last Known Good Time: 2023-06-05T15:07:23 [1685988809.509525][836084:836084] CHIP:TS: Previous Last Known Good Time: 2023-06-05T15:07:23 [1685988809.509527][836084:836084] CHIP:TS: Reverted Last Known Good Time to previous value [1685988809.509542][836084:836084] CHIP:CTL: Shutting down the commissioner [1685988809.509545][836084:836084] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685988809.509563][836084:836084] CHIP:CTL: Shutting down the controller [1685988809.509567][836084:836084] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1685988809.509603][836084:836084] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1685988809.509619][836084:836084] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1685988809.509628][836084:836084] CHIP:FP: Shutting down FabricTable [1685988809.509633][836084:836084] CHIP:TS: Pending Last Known Good Time: 2023-06-05T15:07:23 [1685988809.509662][836084:836084] CHIP:TS: Previous Last Known Good Time: 2023-06-05T15:07:23 [1685988809.509665][836084:836084] CHIP:TS: Reverted Last Known Good Time to previous value [1685988809.509787][836084:836084] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-zUsA5X) [1685988809.513100][836084:836084] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685988809.513147][836084:836084] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1685988809.513159][836084:836084] CHIP:DL: Inet Layer shutdown [1685988809.513169][836084:836084] CHIP:DL: BLE shutdown [1685988809.513190][836084:836084] CHIP:DL: System Layer shutdown vaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/covaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeivaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connecvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-mattervaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/examples/chip-tool/out/debvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/examples/chip-tool/out/debugvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/examples/chip-tool/out/dvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectevaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/evaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/examples/chvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectevaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/exvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/examples/chip-tool/outvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/examples/chip-tool/out/debvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connecvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectevaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connecvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/vaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/exvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/examvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/examplvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/vaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connvaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool scenes read event-list 0x7283 1 [1685989172.222684][836368:836368] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1685989172.224679][836368:836368] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1685989172.224719][836368:836368] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1685989172.224736][836368:836368] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1685989172.224945][836368:836368] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-kWE3m4) [1685989172.225447][836368:836368] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685989172.225456][836368:836368] CHIP:DL: NVS set: chip-counters/reboot-count = 71 (0x47) [1685989172.226793][836368:836368] CHIP:DL: Got Ethernet interface: enp2s0f0 [1685989172.226937][836368:836368] CHIP:DL: Found the primary Ethernet interface:enp2s0f0 [1685989172.227084][836368:836368] CHIP:DL: Got WiFi interface: wlp3s0 [1685989172.228667][836368:836368] CHIP:DL: Found the primary WiFi interface:wlp3s0 [1685989172.228740][836368:836368] CHIP:IN: UDP::Init bind&listen port=0 [1685989172.228777][836368:836368] CHIP:IN: UDP::Init bound to port=33180 [1685989172.228784][836368:836368] CHIP:IN: UDP::Init bind&listen port=0 [1685989172.228805][836368:836368] CHIP:IN: UDP::Init bound to port=34682 [1685989172.228811][836368:836368] CHIP:IN: BLEBase::Init - setting/overriding transport [1685989172.228815][836368:836368] CHIP:IN: TransportMgr initialized [1685989172.228830][836368:836368] CHIP:FP: Initializing FabricTable from persistent storage [1685989172.228946][836368:836368] CHIP:TS: Last Known Good Time: 2023-06-05T15:07:23 [1685989172.229705][836368:836368] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x7DFDC0CC2967173B, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1685989172.252842][836368:836368] CHIP:ZCL: Using ZAP configuration... [1685989172.254134][836368:836368] CHIP:CTL: System State Initialized... [1685989172.254200][836368:836368] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685989172.254231][836368:836368] CHIP:CTL: Setting attestation nonce to random value [1685989172.254247][836368:836368] CHIP:CTL: Setting CSR nonce to random value [1685989172.254277][836368:836368] CHIP:IN: UDP::Init bind&listen port=5550 [1685989172.254329][836368:836368] CHIP:IN: UDP::Init bound to port=5550 [1685989172.254340][836368:836368] CHIP:IN: UDP::Init bind&listen port=5550 [1685989172.254356][836368:836368] CHIP:IN: UDP::Init bound to port=5550 [1685989172.254361][836368:836368] CHIP:IN: TransportMgr initialized [1685989172.254601][836368:836370] CHIP:DL: CHIP task running [1685989172.254690][836368:836370] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1685989172.254916][836368:836370] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685989172.254939][836368:836370] CHIP:CTL: Setting attestation nonce to random value [1685989172.255024][836368:836370] CHIP:CTL: Setting CSR nonce to random value [1685989172.255608][836368:836370] CHIP:CTL: Generating NOC [1685989172.255978][836368:836370] CHIP:FP: Validating NOC chain [1685989172.256400][836368:836370] CHIP:FP: NOC chain validation successful [1685989172.256427][836368:836370] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1685989172.256431][836368:836370] CHIP:TS: Last Known Good Time: 2023-06-05T15:07:23 [1685989172.256433][836368:836370] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1685989172.256434][836368:836370] CHIP:TS: Retaining current Last Known Good Time [1685989172.257058][836368:836370] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1685989172.257282][836368:836370] CHIP:TS: Committing Last Known Good Time to storage: 2023-06-05T15:07:23 [1685989172.257502][836368:836370] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 7DFDC0CC2967173B) [1685989172.257508][836368:836370] CHIP:IN: UDP::Init bind&listen port=5550 [1685989172.257523][836368:836370] CHIP:IN: UDP::Init bound to port=5550 [1685989172.257525][836368:836370] CHIP:IN: UDP::Init bind&listen port=5550 [1685989172.257533][836368:836370] CHIP:IN: UDP::Init bound to port=5550 [1685989172.257535][836368:836370] CHIP:IN: TransportMgr initialized [1685989172.259522][836368:836370] CHIP:TOO: Sending command to node 0x7283 [1685989172.259582][836368:836370] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000007283] [1685989172.259589][836368:836370] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1685989172.259601][836368:836370] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 1 --> 2 [1685989172.460443][836368:836370] CHIP:DIS: Checking node lookup status after 200 ms [1685989172.504254][836368:836370] CHIP:DIS: UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540: new best score: 3 [1685989172.504701][836368:836370] CHIP:DIS: Lookup clearing interface for non LL address [1685989172.504724][836368:836370] CHIP:DIS: UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540: new best score: 7 [1685989172.504941][836368:836370] CHIP:DIS: UDP:192.168.202.40%wlp3s0:5540: score has not improved: 2 [1685989172.504948][836368:836370] CHIP:DIS: Checking node lookup status after 245 ms [1685989172.504960][836368:836370] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: Updating device address to UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c]:5540 while in state 2 [1685989172.504970][836368:836370] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 2 --> 3 [1685989172.505122][836368:836370] CHIP:IN: SecureSession[0x7f13d800b070]: Allocated Type:2 LSID:50596 [1685989172.505141][836368:836370] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000007283 [1685989172.505716][836368:836370] CHIP:EM: <<< [E:27507i S:0 M:7234254] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1685989172.505728][836368:836370] CHIP:IN: (U) Sending msg 7234254 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c]:5540' [1685989172.505784][836368:836370] CHIP:SC: Sent Sigma1 msg [1685989172.505789][836368:836370] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 3 --> 4 [1685989172.664380][836368:836370] CHIP:EM: >>> [E:27507i S:0 M:125335195 (Ack:7234254)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685989172.664400][836368:836370] CHIP:EM: Found matching exchange: 27507i, Delegate: 0x7f13d800e1b8 [1685989172.664411][836368:836370] CHIP:EM: Rxd Ack; Removing MessageCounter:7234254 from Retrans Table on exchange 27507i [1685989173.009950][836368:836370] CHIP:EM: >>> [E:27507i S:0 M:125335196 (Ack:7234254)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1685989173.010008][836368:836370] CHIP:EM: Found matching exchange: 27507i, Delegate: 0x7f13d800e1b8 [1685989173.010019][836368:836370] CHIP:EM: CHIP MessageCounter:7234254 not in RetransTable on exchange 27507i [1685989173.010046][836368:836370] CHIP:SC: Received Sigma2 msg [1685989173.010068][836368:836370] CHIP:SC: Peer assigned session session ID 17170 [1685989173.012271][836368:836370] CHIP:SC: Sending Sigma3 [1685989173.012517][836368:836370] CHIP:EM: <<< [E:27507i S:0 M:7234255 (Ack:125335196)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1685989173.012587][836368:836370] CHIP:IN: (U) Sending msg 7234255 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540' [1685989173.012737][836368:836370] CHIP:SC: Sent Sigma3 msg [1685989173.317217][836368:836370] CHIP:EM: >>> [E:27507i S:0 M:125335197 (Ack:7234255)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685989173.317251][836368:836370] CHIP:EM: Found matching exchange: 27507i, Delegate: 0x7f13d800e1b8 [1685989173.317269][836368:836370] CHIP:EM: Rxd Ack; Removing MessageCounter:7234255 from Retrans Table on exchange 27507i [1685989173.907403][836368:836370] CHIP:EM: >>> [E:27507i S:0 M:125335198 (Ack:7234255)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685989173.907459][836368:836370] CHIP:EM: Found matching exchange: 27507i, Delegate: 0x7f13d800e1b8 [1685989173.907471][836368:836370] CHIP:EM: CHIP MessageCounter:7234255 not in RetransTable on exchange 27507i [1685989173.907498][836368:836370] CHIP:SC: Success status report received. Session was established [1685989173.911600][836368:836370] CHIP:SC: SecureSession[0x7f13d800b070, LSID:50596]: State change 'kEstablishing' --> 'kActive' [1685989173.911628][836368:836370] CHIP:IN: SecureSession[0x7f13d800b070]: Activated - Type:2 LSID:50596 [1685989173.911634][836368:836370] CHIP:IN: New secure session activated for device <0000000000007283, 1>, LSID:50596 PSID:17170! [1685989173.911648][836368:836370] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 4 --> 5 [1685989173.911783][836368:836370] CHIP:TOO: cluster 0x0000_0005, attribute: 0x0000_FFFA, endpoint 1 [1685989173.911788][836368:836370] CHIP:TOO: Sending ReadAttribute to: [1685989173.911803][836368:836370] CHIP:DMG: SendReadRequest ReadClient[0x7f13d800f3f0]: Sending Read Request [1685989173.911890][836368:836370] CHIP:EM: <<< [E:27508i S:50596 M:51571272] (S) Msg TX to 1:0000000000007283 [173B] --- Type 0001:02 (IM:ReadRequest) [1685989173.911897][836368:836370] CHIP:IN: (S) Sending msg 51571272 on secure session with LSID: 50596 [1685989173.912037][836368:836370] CHIP:DMG: MoveToState ReadClient[0x7f13d800f3f0]: Moving to [AwaitingIn] [1685989173.912054][836368:836370] CHIP:EM: <<< [E:27507i S:0 M:7234256 (Ack:125335198)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685989173.912108][836368:836370] CHIP:IN: (U) Sending msg 7234256 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540' [1685989173.912120][836368:836370] CHIP:EM: Flushed pending ack for MessageCounter:125335198 on exchange 27507i [1685989173.975573][836368:836370] CHIP:EM: >>> [E:27508i S:50596 M:148421450 (Ack:51571272)] (S) Msg RX from 1:0000000000007283 [173B] --- Type 0001:05 (IM:ReportData) [1685989173.975617][836368:836370] CHIP:EM: Found matching exchange: 27508i, Delegate: 0x7f13d800f400 [1685989173.975634][836368:836370] CHIP:EM: Rxd Ack; Removing MessageCounter:51571272 from Retrans Table on exchange 27508i [1685989173.975668][836368:836370] CHIP:DMG: ReportDataMessage = [1685989173.975678][836368:836370] CHIP:DMG: { [1685989173.975688][836368:836370] CHIP:DMG: AttributeReportIBs = [1685989173.975699][836368:836370] CHIP:DMG: [ [1685989173.975705][836368:836370] CHIP:DMG: AttributeReportIB = [1685989173.975716][836368:836370] CHIP:DMG: { [1685989173.975722][836368:836370] CHIP:DMG: AttributeDataIB = [1685989173.975737][836368:836370] CHIP:DMG: { [1685989173.975745][836368:836370] CHIP:DMG: DataVersion = 0x29cd3c9a, [1685989173.975751][836368:836370] CHIP:DMG: AttributePathIB = [1685989173.975758][836368:836370] CHIP:DMG: { [1685989173.975765][836368:836370] CHIP:DMG: Endpoint = 0x1, [1685989173.975772][836368:836370] CHIP:DMG: Cluster = 0x5, [1685989173.975779][836368:836370] CHIP:DMG: Attribute = 0x0000_FFFA, [1685989173.975785][836368:836370] CHIP:DMG: } [1685989173.975799][836368:836370] CHIP:DMG: [1685989173.975806][836368:836370] CHIP:DMG: Data = [ [1685989173.975812][836368:836370] CHIP:DMG: [1685989173.975824][836368:836370] CHIP:DMG: ], [1685989173.975830][836368:836370] CHIP:DMG: }, [1685989173.975838][836368:836370] CHIP:DMG: [1685989173.975843][836368:836370] CHIP:DMG: }, [1685989173.975852][836368:836370] CHIP:DMG: [1685989173.975858][836368:836370] CHIP:DMG: ], [1685989173.975866][836368:836370] CHIP:DMG: [1685989173.975873][836368:836370] CHIP:DMG: SuppressResponse = true, [1685989173.975879][836368:836370] CHIP:DMG: InteractionModelRevision = 1 [1685989173.975884][836368:836370] CHIP:DMG: } [1685989173.976022][836368:836370] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0005 Attribute 0x0000_FFFA DataVersion: 701316250 [1685989173.976055][836368:836370] CHIP:TOO: EventList: 0 entries [1685989173.976127][836368:836370] CHIP:EM: <<< [E:27508i S:50596 M:51571273 (Ack:148421450)] (S) Msg TX to 1:0000000000007283 [173B] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685989173.976140][836368:836370] CHIP:IN: (S) Sending msg 51571273 on secure session with LSID: 50596 [1685989173.976243][836368:836370] CHIP:EM: Flushed pending ack for MessageCounter:148421450 on exchange 27508i [1685989173.976396][836368:836368] CHIP:CTL: Shutting down the commissioner [1685989173.976414][836368:836368] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685989173.976473][836368:836368] CHIP:CTL: Shutting down the controller [1685989173.976500][836368:836368] CHIP:IN: Expiring all sessions for fabric 0x1!! [1685989173.976516][836368:836368] CHIP:IN: SecureSession[0x7f13d800b070]: MarkForEviction Type:2 LSID:50596 [1685989173.976523][836368:836368] CHIP:SC: SecureSession[0x7f13d800b070, LSID:50596]: State change 'kActive' --> 'kPendingEviction' [1685989173.976529][836368:836368] CHIP:IN: SecureSession[0x7f13d800b070]: Released - Type:2 LSID:50596 [1685989173.976539][836368:836368] CHIP:FP: Forgetting fabric 0x1 [1685989173.976553][836368:836368] CHIP:TS: Pending Last Known Good Time: 2023-06-05T15:07:23 [1685989173.976638][836368:836368] CHIP:TS: Previous Last Known Good Time: 2023-06-05T15:07:23 [1685989173.976644][836368:836368] CHIP:TS: Reverted Last Known Good Time to previous value [1685989173.976664][836368:836368] CHIP:CTL: Shutting down the commissioner [1685989173.976669][836368:836368] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685989173.976687][836368:836368] CHIP:CTL: Shutting down the controller [1685989173.976692][836368:836368] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1685989173.976739][836368:836368] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1685989173.976760][836368:836368] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1685989173.976774][836368:836368] CHIP:FP: Shutting down FabricTable [1685989173.976780][836368:836368] CHIP:TS: Pending Last Known Good Time: 2023-06-05T15:07:23 [1685989173.976821][836368:836368] CHIP:TS: Previous Last Known Good Time: 2023-06-05T15:07:23 [1685989173.976825][836368:836368] CHIP:TS: Reverted Last Known Good Time to previous value [1685989173.976942][836368:836368] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-YeeXFT) [1685989173.977112][836368:836368] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685989173.977121][836368:836368] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1685989173.977125][836368:836368] CHIP:DL: Inet Layer shutdown [1685989173.977127][836368:836368] CHIP:DL: BLE shutdown [1685989173.977130][836368:836368] CHIP:DL: System Layer shutdown vaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool scenes read accepted-command-list 0x7283 1 [1685989244.308661][836506:836506] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1685989244.310528][836506:836506] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1685989244.310568][836506:836506] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1685989244.310582][836506:836506] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1685989244.310781][836506:836506] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-kXUme3) [1685989244.311118][836506:836506] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685989244.311127][836506:836506] CHIP:DL: NVS set: chip-counters/reboot-count = 72 (0x48) [1685989244.312618][836506:836506] CHIP:DL: Got Ethernet interface: enp2s0f0 [1685989244.312788][836506:836506] CHIP:DL: Found the primary Ethernet interface:enp2s0f0 [1685989244.312966][836506:836506] CHIP:DL: Got WiFi interface: wlp3s0 [1685989244.314507][836506:836506] CHIP:DL: Found the primary WiFi interface:wlp3s0 [1685989244.314565][836506:836506] CHIP:IN: UDP::Init bind&listen port=0 [1685989244.314602][836506:836506] CHIP:IN: UDP::Init bound to port=44030 [1685989244.314607][836506:836506] CHIP:IN: UDP::Init bind&listen port=0 [1685989244.314628][836506:836506] CHIP:IN: UDP::Init bound to port=48320 [1685989244.314631][836506:836506] CHIP:IN: BLEBase::Init - setting/overriding transport [1685989244.314633][836506:836506] CHIP:IN: TransportMgr initialized [1685989244.314649][836506:836506] CHIP:FP: Initializing FabricTable from persistent storage [1685989244.314703][836506:836506] CHIP:TS: Last Known Good Time: 2023-06-05T15:07:23 [1685989244.315392][836506:836506] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x7DFDC0CC2967173B, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1685989244.338820][836506:836506] CHIP:ZCL: Using ZAP configuration... [1685989244.340563][836506:836506] CHIP:CTL: System State Initialized... [1685989244.340577][836506:836506] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685989244.340588][836506:836506] CHIP:CTL: Setting attestation nonce to random value [1685989244.340593][836506:836506] CHIP:CTL: Setting CSR nonce to random value [1685989244.340623][836506:836506] CHIP:IN: UDP::Init bind&listen port=5550 [1685989244.340632][836506:836506] CHIP:IN: UDP::Init bound to port=5550 [1685989244.340635][836506:836506] CHIP:IN: UDP::Init bind&listen port=5550 [1685989244.340641][836506:836506] CHIP:IN: UDP::Init bound to port=5550 [1685989244.340643][836506:836506] CHIP:IN: TransportMgr initialized [1685989244.340716][836506:836508] CHIP:DL: CHIP task running [1685989244.340736][836506:836508] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1685989244.340849][836506:836508] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685989244.340860][836506:836508] CHIP:CTL: Setting attestation nonce to random value [1685989244.340892][836506:836508] CHIP:CTL: Setting CSR nonce to random value [1685989244.341152][836506:836508] CHIP:CTL: Generating NOC [1685989244.341426][836506:836508] CHIP:FP: Validating NOC chain [1685989244.341825][836506:836508] CHIP:FP: NOC chain validation successful [1685989244.341858][836506:836508] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1685989244.341863][836506:836508] CHIP:TS: Last Known Good Time: 2023-06-05T15:07:23 [1685989244.341866][836506:836508] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1685989244.341868][836506:836508] CHIP:TS: Retaining current Last Known Good Time [1685989244.342610][836506:836508] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1685989244.342828][836506:836508] CHIP:TS: Committing Last Known Good Time to storage: 2023-06-05T15:07:23 [1685989244.343039][836506:836508] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 7DFDC0CC2967173B) [1685989244.343048][836506:836508] CHIP:IN: UDP::Init bind&listen port=5550 [1685989244.343059][836506:836508] CHIP:IN: UDP::Init bound to port=5550 [1685989244.343061][836506:836508] CHIP:IN: UDP::Init bind&listen port=5550 [1685989244.343070][836506:836508] CHIP:IN: UDP::Init bound to port=5550 [1685989244.343072][836506:836508] CHIP:IN: TransportMgr initialized [1685989244.345014][836506:836508] CHIP:TOO: Sending command to node 0x7283 [1685989244.345072][836506:836508] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000007283] [1685989244.345077][836506:836508] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1685989244.345093][836506:836508] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 1 --> 2 [1685989244.546007][836506:836508] CHIP:DIS: Checking node lookup status after 201 ms [1685989244.591480][836506:836508] CHIP:DIS: UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540: new best score: 3 [1685989244.591786][836506:836508] CHIP:DIS: Lookup clearing interface for non LL address [1685989244.591811][836506:836508] CHIP:DIS: UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540: new best score: 7 [1685989244.592047][836506:836508] CHIP:DIS: UDP:192.168.202.40%wlp3s0:5540: score has not improved: 2 [1685989244.592056][836506:836508] CHIP:DIS: Checking node lookup status after 247 ms [1685989244.592066][836506:836508] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: Updating device address to UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c]:5540 while in state 2 [1685989244.592073][836506:836508] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 2 --> 3 [1685989244.592151][836506:836508] CHIP:IN: SecureSession[0x7f66d400b070]: Allocated Type:2 LSID:59550 [1685989244.592177][836506:836508] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000007283 [1685989244.592761][836506:836508] CHIP:EM: <<< [E:56268i S:0 M:123329451] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1685989244.592788][836506:836508] CHIP:IN: (U) Sending msg 123329451 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c]:5540' [1685989244.592896][836506:836508] CHIP:SC: Sent Sigma1 msg [1685989244.592905][836506:836508] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 3 --> 4 [1685989244.895932][836506:836508] CHIP:EM: >>> [E:56268i S:0 M:125335199 (Ack:123329451)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685989244.896008][836506:836508] CHIP:EM: Found matching exchange: 56268i, Delegate: 0x7f66d400e1b8 [1685989244.896035][836506:836508] CHIP:EM: Rxd Ack; Removing MessageCounter:123329451 from Retrans Table on exchange 56268i [1685989245.100110][836506:836508] CHIP:EM: >>> [E:56268i S:0 M:125335200 (Ack:123329451)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1685989245.100152][836506:836508] CHIP:EM: Found matching exchange: 56268i, Delegate: 0x7f66d400e1b8 [1685989245.100163][836506:836508] CHIP:EM: CHIP MessageCounter:123329451 not in RetransTable on exchange 56268i [1685989245.100188][836506:836508] CHIP:SC: Received Sigma2 msg [1685989245.100207][836506:836508] CHIP:SC: Peer assigned session session ID 17171 [1685989245.102167][836506:836508] CHIP:SC: Sending Sigma3 [1685989245.102262][836506:836508] CHIP:EM: <<< [E:56268i S:0 M:123329452 (Ack:125335200)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1685989245.102311][836506:836508] CHIP:IN: (U) Sending msg 123329452 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540' [1685989245.102394][836506:836508] CHIP:SC: Sent Sigma3 msg [1685989245.408020][836506:836508] CHIP:EM: >>> [E:56268i S:0 M:125335201 (Ack:123329452)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685989245.408061][836506:836508] CHIP:EM: Found matching exchange: 56268i, Delegate: 0x7f66d400e1b8 [1685989245.408078][836506:836508] CHIP:EM: Rxd Ack; Removing MessageCounter:123329452 from Retrans Table on exchange 56268i [1685989246.124326][836506:836508] CHIP:EM: >>> [E:56268i S:0 M:125335202 (Ack:123329452)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685989246.124365][836506:836508] CHIP:EM: Found matching exchange: 56268i, Delegate: 0x7f66d400e1b8 [1685989246.124375][836506:836508] CHIP:EM: CHIP MessageCounter:123329452 not in RetransTable on exchange 56268i [1685989246.124398][836506:836508] CHIP:SC: Success status report received. Session was established [1685989246.128119][836506:836508] CHIP:SC: SecureSession[0x7f66d400b070, LSID:59550]: State change 'kEstablishing' --> 'kActive' [1685989246.128160][836506:836508] CHIP:IN: SecureSession[0x7f66d400b070]: Activated - Type:2 LSID:59550 [1685989246.128166][836506:836508] CHIP:IN: New secure session activated for device <0000000000007283, 1>, LSID:59550 PSID:17171! [1685989246.128180][836506:836508] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 4 --> 5 [1685989246.128241][836506:836508] CHIP:TOO: cluster 0x0000_0005, attribute: 0x0000_FFF9, endpoint 1 [1685989246.128252][836506:836508] CHIP:TOO: Sending ReadAttribute to: [1685989246.128264][836506:836508] CHIP:DMG: SendReadRequest ReadClient[0x7f66d400f3f0]: Sending Read Request [1685989246.128356][836506:836508] CHIP:EM: <<< [E:56269i S:59550 M:226850882] (S) Msg TX to 1:0000000000007283 [173B] --- Type 0001:02 (IM:ReadRequest) [1685989246.128388][836506:836508] CHIP:IN: (S) Sending msg 226850882 on secure session with LSID: 59550 [1685989246.128502][836506:836508] CHIP:DMG: MoveToState ReadClient[0x7f66d400f3f0]: Moving to [AwaitingIn] [1685989246.128533][836506:836508] CHIP:EM: <<< [E:56268i S:0 M:123329453 (Ack:125335202)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685989246.128586][836506:836508] CHIP:IN: (U) Sending msg 123329453 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540' [1685989246.128619][836506:836508] CHIP:EM: Flushed pending ack for MessageCounter:125335202 on exchange 56268i [1685989246.376456][836506:836508] CHIP:EM: >>> [E:56269i S:59550 M:116248551 (Ack:226850882)] (S) Msg RX from 1:0000000000007283 [173B] --- Type 0001:05 (IM:ReportData) [1685989246.376498][836506:836508] CHIP:EM: Found matching exchange: 56269i, Delegate: 0x7f66d400f400 [1685989246.376521][836506:836508] CHIP:EM: Rxd Ack; Removing MessageCounter:226850882 from Retrans Table on exchange 56269i [1685989246.376566][836506:836508] CHIP:DMG: ReportDataMessage = [1685989246.376574][836506:836508] CHIP:DMG: { [1685989246.376576][836506:836508] CHIP:DMG: AttributeReportIBs = [1685989246.376584][836506:836508] CHIP:DMG: [ [1685989246.376587][836506:836508] CHIP:DMG: AttributeReportIB = [1685989246.376594][836506:836508] CHIP:DMG: { [1685989246.376596][836506:836508] CHIP:DMG: AttributeDataIB = [1685989246.376600][836506:836508] CHIP:DMG: { [1685989246.376605][836506:836508] CHIP:DMG: DataVersion = 0x29cd3c9a, [1685989246.376611][836506:836508] CHIP:DMG: AttributePathIB = [1685989246.376615][836506:836508] CHIP:DMG: { [1685989246.376619][836506:836508] CHIP:DMG: Endpoint = 0x1, [1685989246.376622][836506:836508] CHIP:DMG: Cluster = 0x5, [1685989246.376625][836506:836508] CHIP:DMG: Attribute = 0x0000_FFF9, [1685989246.376632][836506:836508] CHIP:DMG: } [1685989246.376639][836506:836508] CHIP:DMG: [1685989246.376642][836506:836508] CHIP:DMG: Data = [ [1685989246.376655][836506:836508] CHIP:DMG: 0, 1, 2, 3, 4, 5, 6, [1685989246.376659][836506:836508] CHIP:DMG: ], [1685989246.376661][836506:836508] CHIP:DMG: }, [1685989246.376668][836506:836508] CHIP:DMG: [1685989246.376671][836506:836508] CHIP:DMG: }, [1685989246.376676][836506:836508] CHIP:DMG: [1685989246.376679][836506:836508] CHIP:DMG: ], [1685989246.376685][836506:836508] CHIP:DMG: [1685989246.376692][836506:836508] CHIP:DMG: SuppressResponse = true, [1685989246.376695][836506:836508] CHIP:DMG: InteractionModelRevision = 1 [1685989246.376697][836506:836508] CHIP:DMG: } [1685989246.376824][836506:836508] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0005 Attribute 0x0000_FFF9 DataVersion: 701316250 [1685989246.376893][836506:836508] CHIP:TOO: AcceptedCommandList: 7 entries [1685989246.376910][836506:836508] CHIP:TOO: [1]: 0 [1685989246.376913][836506:836508] CHIP:TOO: [2]: 1 [1685989246.376915][836506:836508] CHIP:TOO: [3]: 2 [1685989246.376917][836506:836508] CHIP:TOO: [4]: 3 [1685989246.376920][836506:836508] CHIP:TOO: [5]: 4 [1685989246.376922][836506:836508] CHIP:TOO: [6]: 5 [1685989246.376926][836506:836508] CHIP:TOO: [7]: 6 [1685989246.376976][836506:836508] CHIP:EM: <<< [E:56269i S:59550 M:226850883 (Ack:116248551)] (S) Msg TX to 1:0000000000007283 [173B] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685989246.376996][836506:836508] CHIP:IN: (S) Sending msg 226850883 on secure session with LSID: 59550 [1685989246.377142][836506:836508] CHIP:EM: Flushed pending ack for MessageCounter:116248551 on exchange 56269i [1685989246.377290][836506:836506] CHIP:CTL: Shutting down the commissioner [1685989246.377301][836506:836506] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685989246.377403][836506:836506] CHIP:CTL: Shutting down the controller [1685989246.377425][836506:836506] CHIP:IN: Expiring all sessions for fabric 0x1!! [1685989246.377430][836506:836506] CHIP:IN: SecureSession[0x7f66d400b070]: MarkForEviction Type:2 LSID:59550 [1685989246.377434][836506:836506] CHIP:SC: SecureSession[0x7f66d400b070, LSID:59550]: State change 'kActive' --> 'kPendingEviction' [1685989246.377440][836506:836506] CHIP:IN: SecureSession[0x7f66d400b070]: Released - Type:2 LSID:59550 [1685989246.377449][836506:836506] CHIP:FP: Forgetting fabric 0x1 [1685989246.377466][836506:836506] CHIP:TS: Pending Last Known Good Time: 2023-06-05T15:07:23 [1685989246.377574][836506:836506] CHIP:TS: Previous Last Known Good Time: 2023-06-05T15:07:23 [1685989246.377577][836506:836506] CHIP:TS: Reverted Last Known Good Time to previous value [1685989246.377623][836506:836506] CHIP:CTL: Shutting down the commissioner [1685989246.377628][836506:836506] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685989246.377657][836506:836506] CHIP:CTL: Shutting down the controller [1685989246.377660][836506:836506] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1685989246.377745][836506:836506] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1685989246.377771][836506:836506] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1685989246.377784][836506:836506] CHIP:FP: Shutting down FabricTable [1685989246.377787][836506:836506] CHIP:TS: Pending Last Known Good Time: 2023-06-05T15:07:23 [1685989246.377808][836506:836506] CHIP:TS: Previous Last Known Good Time: 2023-06-05T15:07:23 [1685989246.377811][836506:836506] CHIP:TS: Reverted Last Known Good Time to previous value [1685989246.378257][836506:836506] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-CPbXGJ) [1685989246.378921][836506:836506] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685989246.378950][836506:836506] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1685989246.378956][836506:836506] CHIP:DL: Inet Layer shutdown [1685989246.378964][836506:836506] CHIP:DL: BLE shutdown [1685989246.378973][836506:836506] CHIP:DL: System Layer shutdown vaishali@vaishali-ThinkPad-P14s-Gen-2a:~/esp/esp-matter/connectedhomeip/connectedhomeip/examples/chip-tool/out/debug$ ./chip-tool scenes read generated-command-list 0x7283 1 [1685989293.186788][836663:836663] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1685989293.188442][836663:836663] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1685989293.188493][836663:836663] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1685989293.188508][836663:836663] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1685989293.188696][836663:836663] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-T6Uf3m) [1685989293.189106][836663:836663] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685989293.189117][836663:836663] CHIP:DL: NVS set: chip-counters/reboot-count = 73 (0x49) [1685989293.189600][836663:836663] CHIP:DL: Got Ethernet interface: enp2s0f0 [1685989293.189772][836663:836663] CHIP:DL: Found the primary Ethernet interface:enp2s0f0 [1685989293.189944][836663:836663] CHIP:DL: Got WiFi interface: wlp3s0 [1685989293.192477][836663:836663] CHIP:DL: Found the primary WiFi interface:wlp3s0 [1685989293.192599][836663:836663] CHIP:IN: UDP::Init bind&listen port=0 [1685989293.192645][836663:836663] CHIP:IN: UDP::Init bound to port=35925 [1685989293.192653][836663:836663] CHIP:IN: UDP::Init bind&listen port=0 [1685989293.192674][836663:836663] CHIP:IN: UDP::Init bound to port=42577 [1685989293.192679][836663:836663] CHIP:IN: BLEBase::Init - setting/overriding transport [1685989293.192684][836663:836663] CHIP:IN: TransportMgr initialized [1685989293.192703][836663:836663] CHIP:FP: Initializing FabricTable from persistent storage [1685989293.192889][836663:836663] CHIP:TS: Last Known Good Time: 2023-06-05T15:07:23 [1685989293.193499][836663:836663] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x7DFDC0CC2967173B, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1685989293.194353][836663:836663] CHIP:ZCL: Using ZAP configuration... [1685989293.195681][836663:836663] CHIP:CTL: System State Initialized... [1685989293.195712][836663:836663] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685989293.195740][836663:836663] CHIP:CTL: Setting attestation nonce to random value [1685989293.195746][836663:836663] CHIP:CTL: Setting CSR nonce to random value [1685989293.195770][836663:836663] CHIP:IN: UDP::Init bind&listen port=5550 [1685989293.195783][836663:836663] CHIP:IN: UDP::Init bound to port=5550 [1685989293.195786][836663:836663] CHIP:IN: UDP::Init bind&listen port=5550 [1685989293.195794][836663:836663] CHIP:IN: UDP::Init bound to port=5550 [1685989293.195796][836663:836663] CHIP:IN: TransportMgr initialized [1685989293.196254][836663:836665] CHIP:DL: CHIP task running [1685989293.196276][836663:836665] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1685989293.196367][836663:836665] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685989293.196374][836663:836665] CHIP:CTL: Setting attestation nonce to random value [1685989293.196399][836663:836665] CHIP:CTL: Setting CSR nonce to random value [1685989293.196675][836663:836665] CHIP:CTL: Generating NOC [1685989293.196931][836663:836665] CHIP:FP: Validating NOC chain [1685989293.197317][836663:836665] CHIP:FP: NOC chain validation successful [1685989293.197352][836663:836665] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1685989293.197356][836663:836665] CHIP:TS: Last Known Good Time: 2023-06-05T15:07:23 [1685989293.197358][836663:836665] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1685989293.197361][836663:836665] CHIP:TS: Retaining current Last Known Good Time [1685989293.198166][836663:836665] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1685989293.198734][836663:836665] CHIP:TS: Committing Last Known Good Time to storage: 2023-06-05T15:07:23 [1685989293.199261][836663:836665] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 7DFDC0CC2967173B) [1685989293.199269][836663:836665] CHIP:IN: UDP::Init bind&listen port=5550 [1685989293.199279][836663:836665] CHIP:IN: UDP::Init bound to port=5550 [1685989293.199280][836663:836665] CHIP:IN: UDP::Init bind&listen port=5550 [1685989293.199286][836663:836665] CHIP:IN: UDP::Init bound to port=5550 [1685989293.199287][836663:836665] CHIP:IN: TransportMgr initialized [1685989293.201354][836663:836665] CHIP:TOO: Sending command to node 0x7283 [1685989293.201410][836663:836665] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000007283] [1685989293.201415][836663:836665] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1685989293.201420][836663:836665] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 1 --> 2 [1685989293.235115][836663:836665] CHIP:DIS: UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540: new best score: 3 [1685989293.235417][836663:836665] CHIP:DIS: Lookup clearing interface for non LL address [1685989293.235437][836663:836665] CHIP:DIS: UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540: new best score: 7 [1685989293.235633][836663:836665] CHIP:DIS: UDP:192.168.202.40%wlp3s0:5540: score has not improved: 2 [1685989293.235654][836663:836665] CHIP:DIS: Checking node lookup status after 35 ms [1685989293.235660][836663:836665] CHIP:DIS: Keeping DNSSD lookup active [1685989293.235926][836663:836665] CHIP:DIS: UDP:[fe80::7204:1dff:fe14:f78c%wlp3s0]:5540: score has not improved: 3 [1685989293.236299][836663:836665] CHIP:DIS: UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540: score has not improved: 7 [1685989293.236516][836663:836665] CHIP:DIS: UDP:192.168.202.40%wlp3s0:5540: score has not improved: 2 [1685989293.236522][836663:836665] CHIP:DIS: Checking node lookup status after 35 ms [1685989293.236526][836663:836665] CHIP:DIS: Keeping DNSSD lookup active [1685989293.402050][836663:836665] CHIP:DIS: Checking node lookup status after 201 ms [1685989293.402108][836663:836665] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: Updating device address to UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c]:5540 while in state 2 [1685989293.402117][836663:836665] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 2 --> 3 [1685989293.402194][836663:836665] CHIP:IN: SecureSession[0x7f6be800b070]: Allocated Type:2 LSID:39029 [1685989293.402214][836663:836665] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000007283 [1685989293.402814][836663:836665] CHIP:EM: <<< [E:41086i S:0 M:256352013] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1685989293.402842][836663:836665] CHIP:IN: (U) Sending msg 256352013 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c]:5540' [1685989293.402962][836663:836665] CHIP:SC: Sent Sigma1 msg [1685989293.402971][836663:836665] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 3 --> 4 [1685989293.492900][836663:836665] CHIP:EM: >>> [E:41086i S:0 M:125335203 (Ack:256352013)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685989293.492917][836663:836665] CHIP:EM: Found matching exchange: 41086i, Delegate: 0x7f6be800e1b8 [1685989293.492927][836663:836665] CHIP:EM: Rxd Ack; Removing MessageCounter:256352013 from Retrans Table on exchange 41086i [1685989293.788285][836663:836665] CHIP:EM: >>> [E:41086i S:0 M:125335204 (Ack:256352013)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1685989293.788319][836663:836665] CHIP:EM: Found matching exchange: 41086i, Delegate: 0x7f6be800e1b8 [1685989293.788330][836663:836665] CHIP:EM: CHIP MessageCounter:256352013 not in RetransTable on exchange 41086i [1685989293.788353][836663:836665] CHIP:SC: Received Sigma2 msg [1685989293.788371][836663:836665] CHIP:SC: Peer assigned session session ID 17172 [1685989293.789691][836663:836665] CHIP:SC: Sending Sigma3 [1685989293.789785][836663:836665] CHIP:EM: <<< [E:41086i S:0 M:256352014 (Ack:125335204)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1685989293.789827][836663:836665] CHIP:IN: (U) Sending msg 256352014 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540' [1685989293.789888][836663:836665] CHIP:SC: Sent Sigma3 msg [1685989293.834999][836663:836665] CHIP:EM: >>> [E:41086i S:0 M:125335205 (Ack:256352014)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685989293.835028][836663:836665] CHIP:EM: Found matching exchange: 41086i, Delegate: 0x7f6be800e1b8 [1685989293.835038][836663:836665] CHIP:EM: Rxd Ack; Removing MessageCounter:256352014 from Retrans Table on exchange 41086i [1685989294.662320][836663:836665] CHIP:EM: >>> [E:41086i S:0 M:125335206 (Ack:256352014)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685989294.662354][836663:836665] CHIP:EM: Found matching exchange: 41086i, Delegate: 0x7f6be800e1b8 [1685989294.662370][836663:836665] CHIP:EM: CHIP MessageCounter:256352014 not in RetransTable on exchange 41086i [1685989294.662409][836663:836665] CHIP:SC: Success status report received. Session was established [1685989294.663039][836663:836665] CHIP:SC: SecureSession[0x7f6be800b070, LSID:39029]: State change 'kEstablishing' --> 'kActive' [1685989294.663045][836663:836665] CHIP:IN: SecureSession[0x7f6be800b070]: Activated - Type:2 LSID:39029 [1685989294.663048][836663:836665] CHIP:IN: New secure session activated for device <0000000000007283, 1>, LSID:39029 PSID:17172! [1685989294.663054][836663:836665] CHIP:DIS: OperationalSessionSetup[1:0000000000007283]: State change 4 --> 5 [1685989294.663092][836663:836665] CHIP:TOO: cluster 0x0000_0005, attribute: 0x0000_FFF8, endpoint 1 [1685989294.663097][836663:836665] CHIP:TOO: Sending ReadAttribute to: [1685989294.663104][836663:836665] CHIP:DMG: SendReadRequest ReadClient[0x7f6be8010f40]: Sending Read Request [1685989294.663146][836663:836665] CHIP:EM: <<< [E:41087i S:39029 M:111460936] (S) Msg TX to 1:0000000000007283 [173B] --- Type 0001:02 (IM:ReadRequest) [1685989294.663151][836663:836665] CHIP:IN: (S) Sending msg 111460936 on secure session with LSID: 39029 [1685989294.663220][836663:836665] CHIP:DMG: MoveToState ReadClient[0x7f6be8010f40]: Moving to [AwaitingIn] [1685989294.663232][836663:836665] CHIP:EM: <<< [E:41086i S:0 M:256352015 (Ack:125335206)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685989294.663252][836663:836665] CHIP:IN: (U) Sending msg 256352015 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540' [1685989294.663263][836663:836665] CHIP:EM: Flushed pending ack for MessageCounter:125335206 on exchange 41086i [1685989294.866702][836663:836665] CHIP:IN: Received a duplicate message with MessageCounter:125335206 on exchange 41086i [1685989294.866733][836663:836665] CHIP:EM: >>> [E:41086i S:0 M:125335206 (Ack:256352014)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685989294.866750][836663:836665] CHIP:EM: Generating StandaloneAck via exchange: 41086i [1685989294.866757][836663:836665] CHIP:EM: Forcing tx of solitary ack for duplicate MessageCounter:125335206 on exchange 41086i [1685989294.866777][836663:836665] CHIP:EM: <<< [E:41086i S:0 M:256352016 (Ack:125335206)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685989294.866890][836663:836665] CHIP:IN: (U) Sending msg 256352016 to IP address 'UDP:[2409:4042:4e98:f444:7204:1dff:fe14:f78c%wlp3s0]:5540' [1685989294.882072][836663:836665] CHIP:EM: >>> [E:41087i S:39029 M:151838911 (Ack:111460936)] (S) Msg RX from 1:0000000000007283 [173B] --- Type 0001:05 (IM:ReportData) [1685989294.882105][836663:836665] CHIP:EM: Found matching exchange: 41087i, Delegate: 0x7f6be8010f50 [1685989294.882121][836663:836665] CHIP:EM: Rxd Ack; Removing MessageCounter:111460936 from Retrans Table on exchange 41087i [1685989294.882161][836663:836665] CHIP:DMG: ReportDataMessage = [1685989294.882170][836663:836665] CHIP:DMG: { [1685989294.882177][836663:836665] CHIP:DMG: AttributeReportIBs = [1685989294.882193][836663:836665] CHIP:DMG: [ [1685989294.882198][836663:836665] CHIP:DMG: AttributeReportIB = [1685989294.882212][836663:836665] CHIP:DMG: { [1685989294.882218][836663:836665] CHIP:DMG: AttributeDataIB = [1685989294.882226][836663:836665] CHIP:DMG: { [1685989294.882238][836663:836665] CHIP:DMG: DataVersion = 0x29cd3c9a, [1685989294.882244][836663:836665] CHIP:DMG: AttributePathIB = [1685989294.882257][836663:836665] CHIP:DMG: { [1685989294.882265][836663:836665] CHIP:DMG: Endpoint = 0x1, [1685989294.882274][836663:836665] CHIP:DMG: Cluster = 0x5, [1685989294.882282][836663:836665] CHIP:DMG: Attribute = 0x0000_FFF8, [1685989294.882289][836663:836665] CHIP:DMG: } [1685989294.882299][836663:836665] CHIP:DMG: [1685989294.882309][836663:836665] CHIP:DMG: Data = [ [1685989294.882325][836663:836665] CHIP:DMG: 0, 1, 2, 3, 4, 6, [1685989294.882334][836663:836665] CHIP:DMG: ], [1685989294.882340][836663:836665] CHIP:DMG: }, [1685989294.882351][836663:836665] CHIP:DMG: [1685989294.882356][836663:836665] CHIP:DMG: }, [1685989294.882369][836663:836665] CHIP:DMG: [1685989294.882374][836663:836665] CHIP:DMG: ], [1685989294.882387][836663:836665] CHIP:DMG: [1685989294.882394][836663:836665] CHIP:DMG: SuppressResponse = true, [1685989294.882400][836663:836665] CHIP:DMG: InteractionModelRevision = 1 [1685989294.882405][836663:836665] CHIP:DMG: } [1685989294.882581][836663:836665] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0005 Attribute 0x0000_FFF8 DataVersion: 701316250 [1685989294.882620][836663:836665] CHIP:TOO: GeneratedCommandList: 6 entries [1685989294.882630][836663:836665] CHIP:TOO: [1]: 0 [1685989294.882636][836663:836665] CHIP:TOO: [2]: 1 [1685989294.882642][836663:836665] CHIP:TOO: [3]: 2 [1685989294.882648][836663:836665] CHIP:TOO: [4]: 3 [1685989294.882654][836663:836665] CHIP:TOO: [5]: 4 [1685989294.882660][836663:836665] CHIP:TOO: [6]: 6 [1685989294.882732][836663:836665] CHIP:EM: <<< [E:41087i S:39029 M:111460937 (Ack:151838911)] (S) Msg TX to 1:0000000000007283 [173B] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685989294.882746][836663:836665] CHIP:IN: (S) Sending msg 111460937 on secure session with LSID: 39029 [1685989294.882864][836663:836665] CHIP:EM: Flushed pending ack for MessageCounter:151838911 on exchange 41087i [1685989294.882989][836663:836663] CHIP:CTL: Shutting down the commissioner [1685989294.883005][836663:836663] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685989294.883092][836663:836663] CHIP:CTL: Shutting down the controller [1685989294.883103][836663:836663] CHIP:IN: Expiring all sessions for fabric 0x1!! [1685989294.883109][836663:836663] CHIP:IN: SecureSession[0x7f6be800b070]: MarkForEviction Type:2 LSID:39029 [1685989294.883115][836663:836663] CHIP:SC: SecureSession[0x7f6be800b070, LSID:39029]: State change 'kActive' --> 'kPendingEviction' [1685989294.883123][836663:836663] CHIP:IN: SecureSession[0x7f6be800b070]: Released - Type:2 LSID:39029 [1685989294.883132][836663:836663] CHIP:FP: Forgetting fabric 0x1 [1685989294.883147][836663:836663] CHIP:TS: Pending Last Known Good Time: 2023-06-05T15:07:23 [1685989294.883249][836663:836663] CHIP:TS: Previous Last Known Good Time: 2023-06-05T15:07:23 [1685989294.883266][836663:836663] CHIP:TS: Reverted Last Known Good Time to previous value [1685989294.883285][836663:836663] CHIP:CTL: Shutting down the commissioner [1685989294.883290][836663:836663] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685989294.883310][836663:836663] CHIP:CTL: Shutting down the controller [1685989294.883315][836663:836663] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1685989294.883360][836663:836663] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1685989294.883381][836663:836663] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1685989294.883395][836663:836663] CHIP:FP: Shutting down FabricTable [1685989294.883401][836663:836663] CHIP:TS: Pending Last Known Good Time: 2023-06-05T15:07:23 [1685989294.883443][836663:836663] CHIP:TS: Previous Last Known Good Time: 2023-06-05T15:07:23 [1685989294.883448][836663:836663] CHIP:TS: Reverted Last Known Good Time to previous value [1685989294.883613][836663:836663] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-to3Tum) [1685989294.883912][836663:836663] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685989294.883936][836663:836663] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1685989294.883943][836663:836663] CHIP:DL: Inet Layer shutdown [1685989294.883949][836663:836663] CHIP:DL: BLE shutdown [1685989294.883955][836663:836663] CHIP:DL: System Layer shutdown