ubuntu@ManognaTHpi:~/apps$ rm -rf /tmp/chip_* ubuntu@ManognaTHpi:~/apps$ ./chip-tool pairing ble-wifi 1 Manogna_2G Silabs@2022 20202021 3840 [1685486577.660474][4882:4882] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1685486577.660687][4882:4882] CHIP:DL: writing settings to file (/tmp/chip_kvs-GGzbQT) [1685486577.660850][4882:4882] CHIP:DL: renamed tmp file to file (/tmp/chip_kvs) [1685486577.666478][4882:4882] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1685486577.666744][4882:4882] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-gfhQCx) [1685486577.666932][4882:4882] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1685486577.667039][4882:4882] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1685486577.667138][4882:4882] CHIP:DL: writing settings to file (/tmp/chip_config.ini-OsZ4ih) [1685486577.667247][4882:4882] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1685486577.667330][4882:4882] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1685486577.667427][4882:4882] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-RLCANR) [1685486577.667533][4882:4882] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486577.667783][4882:4882] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-SyD2qH) [1685486577.668271][4882:4882] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1685486577.668323][4882:4882] CHIP:DL: NVS set: chip-factory/unique-id = "E957DD14AE585A41" [1685486577.668455][4882:4882] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-4kUgYo) [1685486577.669128][4882:4882] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1685486577.669180][4882:4882] CHIP:DL: NVS set: chip-factory/vendor-id = 65521 (0xFFF1) [1685486577.669312][4882:4882] CHIP:DL: writing settings to file (/tmp/chip_factory.ini-TM0WJZ) [1685486577.669880][4882:4882] CHIP:DL: renamed tmp file to file (/tmp/chip_factory.ini) [1685486577.669927][4882:4882] CHIP:DL: NVS set: chip-factory/product-id = 32769 (0x8001) [1685486577.670046][4882:4882] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-qPVUnp) [1685486577.670377][4882:4882] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486577.670420][4882:4882] CHIP:DL: NVS set: chip-counters/reboot-count = 1 (0x1) [1685486577.670620][4882:4882] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-ieLgzT) [1685486577.671399][4882:4882] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486577.671446][4882:4882] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1685486577.671564][4882:4882] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-j16UTt) [1685486577.672152][4882:4882] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486577.672202][4882:4882] CHIP:DL: NVS set: chip-counters/boot-reason = 0 (0x0) [1685486577.672327][4882:4882] CHIP:DL: writing settings to file (/tmp/chip_config.ini-1Hw6eS) [1685486577.672666][4882:4882] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1685486577.672711][4882:4882] CHIP:DL: NVS set: chip-config/regulatory-location = 0 (0x0) [1685486577.672941][4882:4882] CHIP:DL: writing settings to file (/tmp/chip_config.ini-WJSdti) [1685486577.673618][4882:4882] CHIP:DL: renamed tmp file to file (/tmp/chip_config.ini) [1685486577.673666][4882:4882] CHIP:DL: NVS set: chip-config/location-capability = 2 (0x2) [1685486577.674721][4882:4882] CHIP:DL: Got Ethernet interface: eth0 [1685486577.675257][4882:4882] CHIP:DL: Found the primary Ethernet interface:eth0 [1685486577.675846][4882:4882] CHIP:DL: Got WiFi interface: wlan0 [1685486577.675909][4882:4882] CHIP:DL: Failed to reset WiFi statistic counts [1685486577.675969][4882:4882] CHIP:IN: UDP::Init bind&listen port=0 [1685486577.676073][4882:4882] CHIP:IN: UDP::Init bound to port=52126 [1685486577.676093][4882:4882] CHIP:IN: BLEBase::Init - setting/overriding transport [1685486577.676110][4882:4882] CHIP:IN: TransportMgr initialized [1685486577.676141][4882:4882] CHIP:FP: Initializing FabricTable from persistent storage [1685486577.676185][4882:4882] CHIP:TS: Last Known Good Time: [unknown] [1685486577.676209][4882:4882] CHIP:TS: Setting Last Known Good Time to firmware build time 2023-05-26T15:09:49 [1685486577.678359][4882:4882] CHIP:ZCL: Using ZAP configuration... [1685486577.682040][4882:4882] CHIP:DL: Avahi client registered [1685486577.683160][4882:4882] CHIP:CTL: System State Initialized... [1685486577.683292][4882:4882] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486577.683334][4882:4882] CHIP:CTL: Setting attestation nonce to random value [1685486577.683369][4882:4882] CHIP:CTL: Setting CSR nonce to random value [1685486577.683660][4882:4884] CHIP:DL: CHIP task running [1685486577.683869][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1685486577.684316][4882:4884] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486577.684370][4882:4884] CHIP:CTL: Setting attestation nonce to random value [1685486577.684537][4882:4884] CHIP:CTL: Setting CSR nonce to random value [1685486577.684691][4882:4884] CHIP:CTL: Couldn't get ExampleOpCredsCAKey from storage: src/controller/ExamplePersistentStorage.cpp:99: CHIP Error 0x000000A0: Value not found in the persisted storage [1685486577.685700][4882:4884] CHIP:CTL: Couldn't get ExampleOpCredsICAKey from storage: src/controller/ExamplePersistentStorage.cpp:99: CHIP Error 0x000000A0: Value not found in the persisted storage [1685486577.686982][4882:4884] CHIP:CTL: Generating RCAC [1685486577.688925][4882:4884] CHIP:CTL: Generating ICAC [1685486577.690178][4882:4884] CHIP:CTL: Generating NOC [1685486577.691130][4882:4884] CHIP:FP: Validating NOC chain [1685486577.694085][4882:4884] CHIP:FP: NOC chain validation successful [1685486577.694360][4882:4884] CHIP:FP: Added new fabric at index: 0x1 [1685486577.694389][4882:4884] CHIP:FP: Assigned compressed fabric ID: 0xE0B91AD5E051DD6E, node ID: 0x000000000001B669 [1685486577.694423][4882:4884] CHIP:TS: Last Known Good Time: 2023-05-26T15:09:49 [1685486577.694448][4882:4884] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1685486577.694470][4882:4884] CHIP:TS: Retaining current Last Known Good Time [1685486577.696341][4882:4884] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1685486577.698640][4882:4884] CHIP:TS: Committing Last Known Good Time to storage: 2023-05-26T15:09:49 [1685486577.700878][4882:4884] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: E0B91AD5E051DD6E) [1685486577.729332][4882:4884] CHIP:CTL: Setting wifi credentials from parameters [1685486577.729374][4882:4884] CHIP:CTL: Setting attestation nonce to random value [1685486577.729426][4882:4884] CHIP:CTL: Setting CSR nonce to random value [1685486577.729456][4882:4884] CHIP:CTL: Commission called for node ID 0x0000000000000001 [1685486577.733638][4882:4883] CHIP:DL: TRACE: Bus acquired for name C-1312 [1685486577.739588][4882:4884] CHIP:DL: PlatformBlueZInit init success [1685486577.746215][4882:4883] CHIP:BLE: BLE removing known devices. [1685486577.748152][4882:4883] CHIP:BLE: BLE initiating scan. [1685486577.760898][4882:4883] CHIP:BLE: Device 27:FE:4A:1F:69:26 does not look like a CHIP device. [1685486577.770285][4882:4883] CHIP:BLE: Device B8:27:EB:BB:4F:5B does not look like a CHIP device. [1685486577.777529][4882:4883] CHIP:BLE: Device 05:63:E6:B3:E8:0D does not look like a CHIP device. [1685486577.779452][4882:4883] CHIP:BLE: Device 24:18:D0:79:20:C9 does not look like a CHIP device. [1685486577.799182][4882:4883] CHIP:BLE: Device 0F:CF:0F:AE:12:6D does not look like a CHIP device. [1685486577.801579][4882:4883] CHIP:BLE: Device 13:D1:2A:86:47:27 does not look like a CHIP device. [1685486577.806322][4882:4883] CHIP:BLE: Device 1C:5F:CB:AB:AE:29 does not look like a CHIP device. [1685486577.808377][4882:4883] CHIP:BLE: Device 0E:8F:E3:56:26:F0 does not look like a CHIP device. [1685486577.815360][4882:4883] CHIP:BLE: New device scanned: 1C:34:F1:DE:2A:FB [1685486577.818565][4882:4883] CHIP:BLE: Device 32:F7:09:39:09:8B does not look like a CHIP device. [1685486577.823843][4882:4883] CHIP:BLE: Device 28:4C:4E:F9:EA:3C does not look like a CHIP device. [1685486577.839259][4882:4883] CHIP:BLE: New device scanned: 94:1E:65:D1:68:27 [1685486577.839326][4882:4883] CHIP:BLE: Device discriminator match. Attempting to connect. [1685486578.277866][4882:4883] CHIP:DL: ConnectDevice complete [1685486579.378950][4882:4883] CHIP:DL: Char1 /org/bluez/hci0/dev_94_1E_65_D1_68_27/service000a [1685486579.379010][4882:4883] CHIP:DL: Char1 /org/bluez/hci0/dev_94_1E_65_D1_68_27/service000a [1685486579.379059][4882:4883] CHIP:DL: Char1 /org/bluez/hci0/dev_94_1E_65_D1_68_27/service000a [1685486579.379088][4882:4883] CHIP:DL: Char1 /org/bluez/hci0/dev_94_1E_65_D1_68_27/service000a [1685486579.379122][4882:4883] CHIP:DL: Char1 /org/bluez/hci0/dev_94_1E_65_D1_68_27/service000a [1685486579.379150][4882:4883] CHIP:DL: Char1 /org/bluez/hci0/dev_94_1E_65_D1_68_27/service000a [1685486579.379186][4882:4883] CHIP:DL: New BLE connection 0xffffa403fdc0, device 94:1E:65:D1:68:27, path /org/bluez/hci0/dev_94_1E_65_D1_68_27 [1685486579.379325][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16385 [1685486579.379370][4882:4884] CHIP:DIS: Closing all BLE connections [1685486579.379472][4882:4884] CHIP:IN: BleConnectionComplete: endPoint 0xaaaaea525630 [1685486579.380121][4882:4884] CHIP:IN: SecureSession[0xffff9c038b00]: Allocated Type:1 LSID:10964 [1685486579.380189][4882:4884] CHIP:SC: Assigned local session key ID 10964 [1685486579.380334][4882:4884] CHIP:EM: <<< [E:1855i S:0 M:171016409] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) [1685486579.380406][4882:4884] CHIP:IN: (U) Sending msg 171016409 to IP address 'BLE' [1685486579.380445][4882:4884] CHIP:IN: Message appended to BLE send queue [1685486579.380476][4882:4884] CHIP:SC: Sent PBKDF param request [1685486580.081650][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486580.532520][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16388 [1685486580.532609][4882:4884] CHIP:BLE: subscribe complete, ep = 0xaaaaea525630 [1685486580.533469][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486580.533682][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486580.533751][4882:4884] CHIP:BLE: peripheral chose BTP version 4; central expected between 4 and 4 [1685486580.533801][4882:4884] CHIP:BLE: using BTP fragment sizes rx 229 / tx 229. [1685486580.533847][4882:4884] CHIP:BLE: local and remote recv window size = 5 [1685486580.534565][4882:4884] CHIP:IN: BLE EndPoint 0xaaaaea525630 Connection Complete [1685486581.037925][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486581.040588][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486581.040844][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486581.041083][4882:4884] CHIP:EM: >>> [E:1855i S:0 M:245487188] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) [1685486581.041158][4882:4884] CHIP:EM: Found matching exchange: 1855i, Delegate: 0xffff9c034450 [1685486581.041286][4882:4884] CHIP:SC: Received PBKDF param response [1685486581.041374][4882:4884] CHIP:SC: Peer assigned session ID 35477 [1685486581.041448][4882:4884] CHIP:SC: Found MRP parameters in the message [1685486581.053340][4882:4884] CHIP:EM: <<< [E:1855i S:0 M:171016410] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:22 (SecureChannel:PASE_Pake1) [1685486581.053399][4882:4884] CHIP:IN: (U) Sending msg 171016410 to IP address 'BLE' [1685486581.053768][4882:4884] CHIP:SC: Sent spake2p msg1 [1685486581.150072][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486582.727429][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486582.727701][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486582.728013][4882:4884] CHIP:EM: >>> [E:1855i S:0 M:245487189] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) [1685486582.728091][4882:4884] CHIP:EM: Found matching exchange: 1855i, Delegate: 0xffff9c034450 [1685486582.728184][4882:4884] CHIP:SC: Received spake2p msg2 [1685486582.731402][4882:4884] CHIP:EM: <<< [E:1855i S:0 M:171016411] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:24 (SecureChannel:PASE_Pake3) [1685486582.731516][4882:4884] CHIP:IN: (U) Sending msg 171016411 to IP address 'BLE' [1685486582.732276][4882:4884] CHIP:SC: Sent spake2p msg3 [1685486582.837242][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486582.838652][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486582.838801][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486582.838957][4882:4884] CHIP:EM: >>> [E:1855i S:0 M:245487190] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685486582.839001][4882:4884] CHIP:EM: Found matching exchange: 1855i, Delegate: 0xffff9c034450 [1685486582.839254][4882:4884] CHIP:SC: SecureSession[0xffff9c038b00, LSID:10964]: State change 'kEstablishing' --> 'kActive' [1685486582.839294][4882:4884] CHIP:IN: SecureSession[0xffff9c038b00]: Activated - Type:1 LSID:10964 [1685486582.839322][4882:4884] CHIP:IN: New secure session activated for device , LSID:10964 PSID:35477! [1685486582.839359][4882:4884] CHIP:CTL: Remote device completed SPAKE2+ handshake [1685486582.839387][4882:4884] CHIP:TOO: Pairing Success [1685486582.839411][4882:4884] CHIP:TOO: PASE establishment successful [1685486582.839439][4882:4884] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' [1685486582.839476][4882:4884] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo' [1685486582.839511][4882:4884] CHIP:CTL: Sending request for commissioning information [1685486582.839588][4882:4884] CHIP:DMG: SendReadRequest ReadClient[0xffff9c037a70]: Sending Read Request [1685486582.839988][4882:4884] CHIP:EM: <<< [E:1856i S:10964 M:266588920] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:02 (IM:ReadRequest) [1685486582.840066][4882:4884] CHIP:IN: (S) Sending msg 266588920 on secure session with LSID: 10964 [1685486582.840658][4882:4884] CHIP:DMG: MoveToState ReadClient[0xffff9c037a70]: Moving to [AwaitingIn] [1685486583.062934][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486583.122196][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486583.122480][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486583.570224][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486583.570490][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486583.570778][4882:4884] CHIP:EM: >>> [E:1856i S:10964 M:62833418] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [1685486583.570913][4882:4884] CHIP:EM: Found matching exchange: 1856i, Delegate: 0xffff9c037a80 [1685486583.571132][4882:4884] CHIP:DMG: ReportDataMessage = [1685486583.571218][4882:4884] CHIP:DMG: { [1685486583.571269][4882:4884] CHIP:DMG: AttributeReportIBs = [1685486583.571343][4882:4884] CHIP:DMG: [ [1685486583.571399][4882:4884] CHIP:DMG: AttributeReportIB = [1685486583.571475][4882:4884] CHIP:DMG: { [1685486583.571558][4882:4884] CHIP:DMG: AttributeDataIB = [1685486583.571643][4882:4884] CHIP:DMG: { [1685486583.571721][4882:4884] CHIP:DMG: DataVersion = 0xf1170222, [1685486583.571998][4882:4884] CHIP:DMG: AttributePathIB = [1685486583.572081][4882:4884] CHIP:DMG: { [1685486583.572262][4882:4884] CHIP:DMG: Endpoint = 0x0, [1685486583.572355][4882:4884] CHIP:DMG: Cluster = 0x31, [1685486583.572469][4882:4884] CHIP:DMG: Attribute = 0x0000_0003, [1685486583.572544][4882:4884] CHIP:DMG: } [1685486583.572621][4882:4884] CHIP:DMG: [1685486583.572781][4882:4884] CHIP:DMG: Data = 20, [1685486583.572853][4882:4884] CHIP:DMG: }, [1685486583.572929][4882:4884] CHIP:DMG: [1685486583.573014][4882:4884] CHIP:DMG: }, [1685486583.573103][4882:4884] CHIP:DMG: [1685486583.573159][4882:4884] CHIP:DMG: AttributeReportIB = [1685486583.573257][4882:4884] CHIP:DMG: { [1685486583.573379][4882:4884] CHIP:DMG: AttributeDataIB = [1685486583.573452][4882:4884] CHIP:DMG: { [1685486583.573548][4882:4884] CHIP:DMG: DataVersion = 0xf34ceab6, [1685486583.573617][4882:4884] CHIP:DMG: AttributePathIB = [1685486583.573688][4882:4884] CHIP:DMG: { [1685486583.573846][4882:4884] CHIP:DMG: Endpoint = 0x0, [1685486583.573929][4882:4884] CHIP:DMG: Cluster = 0x28, [1685486583.574031][4882:4884] CHIP:DMG: Attribute = 0x0000_0004, [1685486583.574104][4882:4884] CHIP:DMG: } [1685486583.574180][4882:4884] CHIP:DMG: [1685486583.574278][4882:4884] CHIP:DMG: Data = 32773, [1685486583.574346][4882:4884] CHIP:DMG: }, [1685486583.574419][4882:4884] CHIP:DMG: [1685486583.574477][4882:4884] CHIP:DMG: }, [1685486583.574641][4882:4884] CHIP:DMG: [1685486583.574698][4882:4884] CHIP:DMG: AttributeReportIB = [1685486583.574854][4882:4884] CHIP:DMG: { [1685486583.574917][4882:4884] CHIP:DMG: AttributeDataIB = [1685486583.575006][4882:4884] CHIP:DMG: { [1685486583.575077][4882:4884] CHIP:DMG: DataVersion = 0xf34ceab6, [1685486583.575147][4882:4884] CHIP:DMG: AttributePathIB = [1685486583.575237][4882:4884] CHIP:DMG: { [1685486583.575377][4882:4884] CHIP:DMG: Endpoint = 0x0, [1685486583.575481][4882:4884] CHIP:DMG: Cluster = 0x28, [1685486583.575560][4882:4884] CHIP:DMG: Attribute = 0x0000_0002, [1685486583.575631][4882:4884] CHIP:DMG: } [1685486583.575729][4882:4884] CHIP:DMG: [1685486583.575892][4882:4884] CHIP:DMG: Data = 65521, [1685486583.575981][4882:4884] CHIP:DMG: }, [1685486583.576058][4882:4884] CHIP:DMG: [1685486583.576117][4882:4884] CHIP:DMG: }, [1685486583.576222][4882:4884] CHIP:DMG: [1685486583.576280][4882:4884] CHIP:DMG: AttributeReportIB = [1685486583.576354][4882:4884] CHIP:DMG: { [1685486583.576413][4882:4884] CHIP:DMG: AttributeDataIB = [1685486583.576560][4882:4884] CHIP:DMG: { [1685486583.576639][4882:4884] CHIP:DMG: DataVersion = 0xaa58d9fc, [1685486583.576732][4882:4884] CHIP:DMG: AttributePathIB = [1685486583.576868][4882:4884] CHIP:DMG: { [1685486583.576965][4882:4884] CHIP:DMG: Endpoint = 0x0, [1685486583.577011][4882:4884] CHIP:DMG: Cluster = 0x30, [1685486583.577046][4882:4884] CHIP:DMG: Attribute = 0x0000_0003, [1685486583.577090][4882:4884] CHIP:DMG: } [1685486583.577126][4882:4884] CHIP:DMG: [1685486583.577160][4882:4884] CHIP:DMG: Data = 0, [1685486583.577204][4882:4884] CHIP:DMG: }, [1685486583.577240][4882:4884] CHIP:DMG: [1685486583.577300][4882:4884] CHIP:DMG: }, [1685486583.577343][4882:4884] CHIP:DMG: [1685486583.577369][4882:4884] CHIP:DMG: AttributeReportIB = [1685486583.577440][4882:4884] CHIP:DMG: { [1685486583.577469][4882:4884] CHIP:DMG: AttributeDataIB = [1685486583.577501][4882:4884] CHIP:DMG: { [1685486583.577534][4882:4884] CHIP:DMG: DataVersion = 0xaa58d9fc, [1685486583.577579][4882:4884] CHIP:DMG: AttributePathIB = [1685486583.577614][4882:4884] CHIP:DMG: { [1685486583.577685][4882:4884] CHIP:DMG: Endpoint = 0x0, [1685486583.577723][4882:4884] CHIP:DMG: Cluster = 0x30, [1685486583.577760][4882:4884] CHIP:DMG: Attribute = 0x0000_0002, [1685486583.577807][4882:4884] CHIP:DMG: } [1685486583.577843][4882:4884] CHIP:DMG: [1685486583.577889][4882:4884] CHIP:DMG: Data = 0, [1685486583.577922][4882:4884] CHIP:DMG: }, [1685486583.577957][4882:4884] CHIP:DMG: [1685486583.578015][4882:4884] CHIP:DMG: }, [1685486583.578058][4882:4884] CHIP:DMG: [1685486583.578084][4882:4884] CHIP:DMG: AttributeReportIB = [1685486583.578131][4882:4884] CHIP:DMG: { [1685486583.578159][4882:4884] CHIP:DMG: AttributeDataIB = [1685486583.578191][4882:4884] CHIP:DMG: { [1685486583.578261][4882:4884] CHIP:DMG: DataVersion = 0xaa58d9fc, [1685486583.578323][4882:4884] CHIP:DMG: AttributePathIB = [1685486583.578371][4882:4884] CHIP:DMG: { [1685486583.578406][4882:4884] CHIP:DMG: Endpoint = 0x0, [1685486583.578454][4882:4884] CHIP:DMG: Cluster = 0x30, [1685486583.578492][4882:4884] CHIP:DMG: Attribute = 0x0000_0001, [1685486583.578529][4882:4884] CHIP:DMG: } [1685486583.578574][4882:4884] CHIP:DMG: [1685486583.578608][4882:4884] CHIP:DMG: Data = [1685486583.578642][4882:4884] CHIP:DMG: { [1685486583.578721][4882:4884] CHIP:DMG: 0x0 = 60, [1685486583.578791][4882:4884] CHIP:DMG: 0x1 = 900, [1685486583.578841][4882:4884] CHIP:DMG: }, [1685486583.578893][4882:4884] CHIP:DMG: }, [1685486583.578943][4882:4884] CHIP:DMG: [1685486583.578970][4882:4884] CHIP:DMG: }, [1685486583.579011][4882:4884] CHIP:DMG: [1685486583.579048][4882:4884] CHIP:DMG: AttributeReportIB = [1685486583.579083][4882:4884] CHIP:DMG: { [1685486583.579135][4882:4884] CHIP:DMG: AttributeDataIB = [1685486583.579181][4882:4884] CHIP:DMG: { [1685486583.579214][4882:4884] CHIP:DMG: DataVersion = 0xaa58d9fc, [1685486583.579275][4882:4884] CHIP:DMG: AttributePathIB = [1685486583.579311][4882:4884] CHIP:DMG: { [1685486583.579346][4882:4884] CHIP:DMG: Endpoint = 0x0, [1685486583.579393][4882:4884] CHIP:DMG: Cluster = 0x30, [1685486583.579431][4882:4884] CHIP:DMG: Attribute = 0x0000_0000, [1685486583.579501][4882:4884] CHIP:DMG: } [1685486583.579540][4882:4884] CHIP:DMG: [1685486583.579576][4882:4884] CHIP:DMG: Data = 0, [1685486583.579618][4882:4884] CHIP:DMG: }, [1685486583.579653][4882:4884] CHIP:DMG: [1685486583.579681][4882:4884] CHIP:DMG: }, [1685486583.579729][4882:4884] CHIP:DMG: [1685486583.579772][4882:4884] CHIP:DMG: AttributeReportIB = [1685486583.579808][4882:4884] CHIP:DMG: { [1685486583.579836][4882:4884] CHIP:DMG: AttributeDataIB = [1685486583.579878][4882:4884] CHIP:DMG: { [1685486583.579975][4882:4884] CHIP:DMG: DataVersion = 0xf1170222, [1685486583.580008][4882:4884] CHIP:DMG: AttributePathIB = [1685486583.580042][4882:4884] CHIP:DMG: { [1685486583.580086][4882:4884] CHIP:DMG: Endpoint = 0x0, [1685486583.580124][4882:4884] CHIP:DMG: Cluster = 0x31, [1685486583.580160][4882:4884] CHIP:DMG: Attribute = 0x0000_FFFC, [1685486583.580203][4882:4884] CHIP:DMG: } [1685486583.580240][4882:4884] CHIP:DMG: [1685486583.580315][4882:4884] CHIP:DMG: Data = 1, [1685486583.580349][4882:4884] CHIP:DMG: }, [1685486583.580408][4882:4884] CHIP:DMG: [1685486583.580448][4882:4884] CHIP:DMG: }, [1685486583.580481][4882:4884] CHIP:DMG: [1685486583.580506][4882:4884] CHIP:DMG: ], [1685486583.580580][4882:4884] CHIP:DMG: [1685486583.580626][4882:4884] CHIP:DMG: SuppressResponse = true, [1685486583.580666][4882:4884] CHIP:DMG: InteractionModelRevision = 1 [1685486583.580691][4882:4884] CHIP:DMG: } [1685486583.581619][4882:4884] CHIP:CTL: ----- NetworkCommissioning Features: has WiFi. endpointid = 0 [1685486583.581694][4882:4884] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo' [1685486583.581728][4882:4884] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ArmFailSafe' [1685486583.581761][4882:4884] CHIP:CTL: Performing next commissioning step 'ArmFailSafe' [1685486583.581788][4882:4884] CHIP:CTL: Arming failsafe (60 seconds) [1685486583.581860][4882:4884] CHIP:DMG: ICR moving to [AddingComm] [1685486583.581925][4882:4884] CHIP:DMG: ICR moving to [AddedComma] [1685486583.582077][4882:4884] CHIP:EM: <<< [E:1857i S:10964 M:266588921] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685486583.582123][4882:4884] CHIP:IN: (S) Sending msg 266588921 on secure session with LSID: 10964 [1685486583.582609][4882:4884] CHIP:DMG: ICR moving to [CommandSen] [1685486583.905868][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486583.908240][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486583.908493][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486583.908819][4882:4884] CHIP:EM: >>> [E:1857i S:10964 M:62833419] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685486583.908937][4882:4884] CHIP:EM: Found matching exchange: 1857i, Delegate: 0xffff9c039208 [1685486583.909020][4882:4884] CHIP:DMG: ICR moving to [ResponseRe] [1685486583.909144][4882:4884] CHIP:DMG: InvokeResponseMessage = [1685486583.909320][4882:4884] CHIP:DMG: { [1685486583.909383][4882:4884] CHIP:DMG: suppressResponse = false, [1685486583.909467][4882:4884] CHIP:DMG: InvokeResponseIBs = [1685486583.909544][4882:4884] CHIP:DMG: [ [1685486583.909599][4882:4884] CHIP:DMG: InvokeResponseIB = [1685486583.909676][4882:4884] CHIP:DMG: { [1685486583.909821][4882:4884] CHIP:DMG: CommandDataIB = [1685486583.909895][4882:4884] CHIP:DMG: { [1685486583.909960][4882:4884] CHIP:DMG: CommandPathIB = [1685486583.910058][4882:4884] CHIP:DMG: { [1685486583.910136][4882:4884] CHIP:DMG: EndpointId = 0x0, [1685486583.910216][4882:4884] CHIP:DMG: ClusterId = 0x30, [1685486583.910377][4882:4884] CHIP:DMG: CommandId = 0x1, [1685486583.910458][4882:4884] CHIP:DMG: }, [1685486583.910560][4882:4884] CHIP:DMG: [1685486583.910628][4882:4884] CHIP:DMG: CommandFields = [1685486583.910702][4882:4884] CHIP:DMG: { [1685486583.910814][4882:4884] CHIP:DMG: 0x0 = 0, [1685486583.910963][4882:4884] CHIP:DMG: 0x1 = "" (0 chars), [1685486583.911065][4882:4884] CHIP:DMG: }, [1685486583.911135][4882:4884] CHIP:DMG: }, [1685486583.911213][4882:4884] CHIP:DMG: [1685486583.911296][4882:4884] CHIP:DMG: }, [1685486583.911430][4882:4884] CHIP:DMG: [1685486583.911489][4882:4884] CHIP:DMG: ], [1685486583.911586][4882:4884] CHIP:DMG: [1685486583.911642][4882:4884] CHIP:DMG: InteractionModelRevision = 1 [1685486583.911695][4882:4884] CHIP:DMG: }, [1685486583.911904][4882:4884] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1685486583.911984][4882:4884] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1685486583.912047][4882:4884] CHIP:CTL: Successfully finished commissioning step 'ArmFailSafe' [1685486583.912177][4882:4884] CHIP:CTL: Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory' [1685486583.912247][4882:4884] CHIP:CTL: Performing next commissioning step 'ConfigRegulatory' [1685486583.912362][4882:4884] CHIP:CTL: Setting Regulatory Config [1685486583.912436][4882:4884] CHIP:CTL: Device does not support configurable regulatory location [1685486583.912562][4882:4884] CHIP:DMG: ICR moving to [AddingComm] [1685486583.912702][4882:4884] CHIP:DMG: ICR moving to [AddedComma] [1685486583.912933][4882:4884] CHIP:EM: <<< [E:1858i S:10964 M:266588922] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685486583.913024][4882:4884] CHIP:IN: (S) Sending msg 266588922 on secure session with LSID: 10964 [1685486583.913866][4882:4884] CHIP:DMG: ICR moving to [CommandSen] [1685486583.914008][4882:4884] CHIP:DMG: ICR moving to [AwaitingDe] [1685486584.244133][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486584.245783][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486584.246032][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486584.246358][4882:4884] CHIP:EM: >>> [E:1858i S:10964 M:62833420] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685486584.246441][4882:4884] CHIP:EM: Found matching exchange: 1858i, Delegate: 0xffff9c0382a8 [1685486584.246525][4882:4884] CHIP:DMG: ICR moving to [ResponseRe] [1685486584.246626][4882:4884] CHIP:DMG: InvokeResponseMessage = [1685486584.246681][4882:4884] CHIP:DMG: { [1685486584.246733][4882:4884] CHIP:DMG: suppressResponse = false, [1685486584.246790][4882:4884] CHIP:DMG: InvokeResponseIBs = [1685486584.246866][4882:4884] CHIP:DMG: [ [1685486584.246922][4882:4884] CHIP:DMG: InvokeResponseIB = [1685486584.246999][4882:4884] CHIP:DMG: { [1685486584.247059][4882:4884] CHIP:DMG: CommandDataIB = [1685486584.247131][4882:4884] CHIP:DMG: { [1685486584.247195][4882:4884] CHIP:DMG: CommandPathIB = [1685486584.247270][4882:4884] CHIP:DMG: { [1685486584.247345][4882:4884] CHIP:DMG: EndpointId = 0x0, [1685486584.247425][4882:4884] CHIP:DMG: ClusterId = 0x30, [1685486584.247503][4882:4884] CHIP:DMG: CommandId = 0x3, [1685486584.247578][4882:4884] CHIP:DMG: }, [1685486584.247655][4882:4884] CHIP:DMG: [1685486584.247722][4882:4884] CHIP:DMG: CommandFields = [1685486584.247855][4882:4884] CHIP:DMG: { [1685486584.247936][4882:4884] CHIP:DMG: 0x0 = 0, [1685486584.248022][4882:4884] CHIP:DMG: 0x1 = "" (0 chars), [1685486584.248107][4882:4884] CHIP:DMG: }, [1685486584.248177][4882:4884] CHIP:DMG: }, [1685486584.248254][4882:4884] CHIP:DMG: [1685486584.248314][4882:4884] CHIP:DMG: }, [1685486584.248387][4882:4884] CHIP:DMG: [1685486584.248441][4882:4884] CHIP:DMG: ], [1685486584.248512][4882:4884] CHIP:DMG: [1685486584.248565][4882:4884] CHIP:DMG: InteractionModelRevision = 1 [1685486584.248619][4882:4884] CHIP:DMG: }, [1685486584.248760][4882:4884] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [1685486584.248882][4882:4884] CHIP:CTL: Received SetRegulatoryConfig response errorCode=0 [1685486584.248950][4882:4884] CHIP:CTL: Successfully finished commissioning step 'ConfigRegulatory' [1685486584.248999][4882:4884] CHIP:CTL: Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest' [1685486584.249060][4882:4884] CHIP:CTL: Performing next commissioning step 'SendPAICertificateRequest' [1685486584.249109][4882:4884] CHIP:CTL: Sending request for PAI certificate [1685486584.249154][4882:4884] CHIP:CTL: Sending Certificate Chain request to 0xffff9c034400 device [1685486584.249276][4882:4884] CHIP:DMG: ICR moving to [AddingComm] [1685486584.249373][4882:4884] CHIP:DMG: ICR moving to [AddedComma] [1685486584.249574][4882:4884] CHIP:EM: <<< [E:1859i S:10964 M:266588923] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685486584.249665][4882:4884] CHIP:IN: (S) Sending msg 266588923 on secure session with LSID: 10964 [1685486584.250403][4882:4884] CHIP:DMG: ICR moving to [CommandSen] [1685486584.250546][4882:4884] CHIP:DMG: ICR moving to [AwaitingDe] [1685486584.469300][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486584.472654][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486584.472902][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486584.640933][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486584.641179][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486584.751696][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486584.752291][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486584.752610][4882:4884] CHIP:EM: >>> [E:1859i S:10964 M:62833421] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685486584.752691][4882:4884] CHIP:EM: Found matching exchange: 1859i, Delegate: 0xffff9c039208 [1685486584.752781][4882:4884] CHIP:DMG: ICR moving to [ResponseRe] [1685486584.752882][4882:4884] CHIP:DMG: InvokeResponseMessage = [1685486584.752938][4882:4884] CHIP:DMG: { [1685486584.752991][4882:4884] CHIP:DMG: suppressResponse = false, [1685486584.753047][4882:4884] CHIP:DMG: InvokeResponseIBs = [1685486584.753123][4882:4884] CHIP:DMG: [ [1685486584.753179][4882:4884] CHIP:DMG: InvokeResponseIB = [1685486584.753257][4882:4884] CHIP:DMG: { [1685486584.753317][4882:4884] CHIP:DMG: CommandDataIB = [1685486584.753387][4882:4884] CHIP:DMG: { [1685486584.753451][4882:4884] CHIP:DMG: CommandPathIB = [1685486584.753525][4882:4884] CHIP:DMG: { [1685486584.753599][4882:4884] CHIP:DMG: EndpointId = 0x0, [1685486584.753703][4882:4884] CHIP:DMG: ClusterId = 0x3e, [1685486584.753779][4882:4884] CHIP:DMG: CommandId = 0x3, [1685486584.753860][4882:4884] CHIP:DMG: }, [1685486584.753937][4882:4884] CHIP:DMG: [1685486584.754004][4882:4884] CHIP:DMG: CommandFields = [1685486584.754074][4882:4884] CHIP:DMG: { [1685486584.754150][4882:4884] CHIP:DMG: 0x0 = [ [1685486584.754479][4882:4884] 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 [1685486584.754651][4882:4884] CHIP:DMG: ] (463 bytes) [1685486584.754731][4882:4884] CHIP:DMG: }, [1685486584.754800][4882:4884] CHIP:DMG: }, [1685486584.754876][4882:4884] CHIP:DMG: [1685486584.754935][4882:4884] CHIP:DMG: }, [1685486584.755007][4882:4884] CHIP:DMG: [1685486584.755061][4882:4884] CHIP:DMG: ], [1685486584.755132][4882:4884] CHIP:DMG: [1685486584.755187][4882:4884] CHIP:DMG: InteractionModelRevision = 1 [1685486584.755241][4882:4884] CHIP:DMG: }, [1685486584.755381][4882:4884] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1685486584.755453][4882:4884] CHIP:CTL: Received certificate chain from the device [1685486584.755515][4882:4884] CHIP:CTL: Successfully finished commissioning step 'SendPAICertificateRequest' [1685486584.755574][4882:4884] CHIP:CTL: Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest' [1685486584.755636][4882:4884] CHIP:CTL: Performing next commissioning step 'SendDACCertificateRequest' [1685486584.755685][4882:4884] CHIP:CTL: Sending request for DAC certificate [1685486584.755730][4882:4884] CHIP:CTL: Sending Certificate Chain request to 0xffff9c034400 device [1685486584.755909][4882:4884] CHIP:DMG: ICR moving to [AddingComm] [1685486584.755977][4882:4884] CHIP:DMG: ICR moving to [AddedComma] [1685486584.756174][4882:4884] CHIP:EM: <<< [E:1860i S:10964 M:266588924] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685486584.756267][4882:4884] CHIP:IN: (S) Sending msg 266588924 on secure session with LSID: 10964 [1685486584.757020][4882:4884] CHIP:DMG: ICR moving to [CommandSen] [1685486584.757161][4882:4884] CHIP:DMG: ICR moving to [AwaitingDe] [1685486584.919260][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486585.034752][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486585.035024][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486585.203469][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486585.203732][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486585.483652][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486585.483994][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486585.484418][4882:4884] CHIP:EM: >>> [E:1860i S:10964 M:62833422] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685486585.484508][4882:4884] CHIP:EM: Found matching exchange: 1860i, Delegate: 0xffff9c0382a8 [1685486585.484602][4882:4884] CHIP:DMG: ICR moving to [ResponseRe] [1685486585.484704][4882:4884] CHIP:DMG: InvokeResponseMessage = [1685486585.484760][4882:4884] CHIP:DMG: { [1685486585.484815][4882:4884] CHIP:DMG: suppressResponse = false, [1685486585.484871][4882:4884] CHIP:DMG: InvokeResponseIBs = [1685486585.484946][4882:4884] CHIP:DMG: [ [1685486585.485003][4882:4884] CHIP:DMG: InvokeResponseIB = [1685486585.485078][4882:4884] CHIP:DMG: { [1685486585.485134][4882:4884] CHIP:DMG: CommandDataIB = [1685486585.485201][4882:4884] CHIP:DMG: { [1685486585.485328][4882:4884] CHIP:DMG: CommandPathIB = [1685486585.485421][4882:4884] CHIP:DMG: { [1685486585.485517][4882:4884] CHIP:DMG: EndpointId = 0x0, [1685486585.485615][4882:4884] CHIP:DMG: ClusterId = 0x3e, [1685486585.485710][4882:4884] CHIP:DMG: CommandId = 0x3, [1685486585.485789][4882:4884] CHIP:DMG: }, [1685486585.485864][4882:4884] CHIP:DMG: [1685486585.485930][4882:4884] CHIP:DMG: CommandFields = [1685486585.486019][4882:4884] CHIP:DMG: { [1685486585.486111][4882:4884] CHIP:DMG: 0x0 = [ [1685486585.486442][4882:4884] CHIP:DMG: 0x30, 0x82, 0x01, 0xe8, 0x30, 0x82, 0x01, 0x8e, 0xa0, 0x03, 0x02, 0x01, 0x02, 0x02, 0x08, 0x6f, 0xdc, 0xb6, 0xed, 0x06, 0xf3, 0x58, 0xf9, 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, 0x35, 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, 0x35, 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, 0x7e, 0xf2, 0xf1, 0x08, 0x2b, 0x2a, 0x56, 0x4a, 0x05, 0x44, 0xc0, 0xa6, 0x13, 0xd2, 0x1b, 0x15, 0x75, 0x00, 0x55, 0x2d, 0x03, 0x5f, 0x23, 0x02, 0x25, 0x2f, 0xce, 0xe8, 0x1d, 0x6e, 0xc6, 0x74, 0x17, 0x34, 0x18, 0xa9, 0x4a, 0x88, 0xdb, 0x [1685486585.486622][4882:4884] CHIP:DMG: ] (492 bytes) [1685486585.486718][4882:4884] CHIP:DMG: }, [1685486585.486792][4882:4884] CHIP:DMG: }, [1685486585.486870][4882:4884] CHIP:DMG: [1685486585.486930][4882:4884] CHIP:DMG: }, [1685486585.487002][4882:4884] CHIP:DMG: [1685486585.487057][4882:4884] CHIP:DMG: ], [1685486585.487128][4882:4884] CHIP:DMG: [1685486585.487184][4882:4884] CHIP:DMG: InteractionModelRevision = 1 [1685486585.487237][4882:4884] CHIP:DMG: }, [1685486585.487378][4882:4884] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [1685486585.487452][4882:4884] CHIP:CTL: Received certificate chain from the device [1685486585.487517][4882:4884] CHIP:CTL: Successfully finished commissioning step 'SendDACCertificateRequest' [1685486585.487580][4882:4884] CHIP:CTL: Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest' [1685486585.487644][4882:4884] CHIP:CTL: Performing next commissioning step 'SendAttestationRequest' [1685486585.487692][4882:4884] CHIP:CTL: Sending Attestation Request to the device. [1685486585.487789][4882:4884] CHIP:CTL: Sending Attestation request to 0xffff9c034400 device [1685486585.487929][4882:4884] CHIP:DMG: ICR moving to [AddingComm] [1685486585.488006][4882:4884] CHIP:DMG: ICR moving to [AddedComma] [1685486585.488232][4882:4884] CHIP:EM: <<< [E:1861i S:10964 M:266588925] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685486585.488332][4882:4884] CHIP:IN: (S) Sending msg 266588925 on secure session with LSID: 10964 [1685486585.489274][4882:4884] CHIP:DMG: ICR moving to [CommandSen] [1685486585.489377][4882:4884] CHIP:CTL: Sent Attestation request, waiting for the Attestation Information [1685486585.489486][4882:4884] CHIP:DMG: ICR moving to [AwaitingDe] [1685486585.875590][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486586.159732][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486586.160065][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486586.385015][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486586.385950][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486587.172425][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486587.172698][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486587.507900][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486587.508161][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486587.509214][4882:4884] CHIP:EM: >>> [E:1861i S:10964 M:62833423] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685486587.509326][4882:4884] CHIP:EM: Found matching exchange: 1861i, Delegate: 0xffff9c039208 [1685486587.509427][4882:4884] CHIP:DMG: ICR moving to [ResponseRe] [1685486587.509547][4882:4884] CHIP:DMG: InvokeResponseMessage = [1685486587.509611][4882:4884] CHIP:DMG: { [1685486587.509666][4882:4884] CHIP:DMG: suppressResponse = false, [1685486587.509723][4882:4884] CHIP:DMG: InvokeResponseIBs = [1685486587.509801][4882:4884] CHIP:DMG: [ [1685486587.509859][4882:4884] CHIP:DMG: InvokeResponseIB = [1685486587.509940][4882:4884] CHIP:DMG: { [1685486587.510002][4882:4884] CHIP:DMG: CommandDataIB = [1685486587.510087][4882:4884] CHIP:DMG: { [1685486587.510157][4882:4884] CHIP:DMG: CommandPathIB = [1685486587.510230][4882:4884] CHIP:DMG: { [1685486587.510304][4882:4884] CHIP:DMG: EndpointId = 0x0, [1685486587.510391][4882:4884] CHIP:DMG: ClusterId = 0x3e, [1685486587.510463][4882:4884] CHIP:DMG: CommandId = 0x1, [1685486587.510528][4882:4884] CHIP:DMG: }, [1685486587.510599][4882:4884] CHIP:DMG: [1685486587.510659][4882:4884] CHIP:DMG: CommandFields = [1685486587.510724][4882:4884] CHIP:DMG: { [1685486587.510800][4882:4884] CHIP:DMG: 0x0 = [ [1685486587.511068][4882:4884] 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 [1685486587.511185][4882:4884] CHIP:DMG: ] (583 bytes) [1685486587.511239][4882:4884] CHIP:DMG: 0x1 = [ [1685486587.511326][4882:4884] CHIP:DMG: 0xba, 0xe5, 0x29, 0x48, 0x94, 0xd6, 0xe6, 0x67, 0x7f, 0xaf, 0xf5, 0x57, 0x3b, 0xfe, 0xc4, 0x5a, 0xb9, 0xa0, 0x3d, 0xff, 0x35, 0x83, 0xf4, 0x20, 0x30, 0x34, 0x8a, 0xc9, 0x9a, 0x59, 0x33, 0xd6, 0xbb, 0x7b, 0x6e, 0x60, 0x8c, 0x10, 0x8b, 0xf5, 0x20, 0x35, 0xf6, 0xe0, 0x9e, 0x8c, 0xd0, 0x38, 0x52, 0x80, 0xd2, 0xde, 0xa8, 0xe0, 0x38, 0x2d, 0x42, 0xba, 0xbb, 0x92, 0x92, 0x48, 0x96, 0x69, [1685486587.511392][4882:4884] CHIP:DMG: ] (64 bytes) [1685486587.511445][4882:4884] CHIP:DMG: }, [1685486587.511492][4882:4884] CHIP:DMG: }, [1685486587.511545][4882:4884] CHIP:DMG: [1685486587.511584][4882:4884] CHIP:DMG: }, [1685486587.511633][4882:4884] CHIP:DMG: [1685486587.511669][4882:4884] CHIP:DMG: ], [1685486587.511718][4882:4884] CHIP:DMG: [1685486587.511785][4882:4884] CHIP:DMG: InteractionModelRevision = 1 [1685486587.511824][4882:4884] CHIP:DMG: }, [1685486587.511925][4882:4884] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 [1685486587.511979][4882:4884] CHIP:CTL: Received Attestation Information from the device [1685486587.512025][4882:4884] CHIP:CTL: Successfully finished commissioning step 'SendAttestationRequest' [1685486587.512062][4882:4884] CHIP:CTL: AutoCommissioner setting attestationElements buffer size 583/583 [1685486587.512146][4882:4884] CHIP:CTL: Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification' [1685486587.512194][4882:4884] CHIP:CTL: Performing next commissioning step 'AttestationVerification' [1685486587.512228][4882:4884] CHIP:CTL: Verifying attestation [1685486587.546296][4882:4884] CHIP:CTL: Successfully validated 'Attestation Information' command received from the device. [1685486587.546374][4882:4884] CHIP:CTL: Successfully finished commissioning step 'AttestationVerification' [1685486587.546395][4882:4884] CHIP:CTL: Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest' [1685486587.546423][4882:4884] CHIP:CTL: Performing next commissioning step 'SendOpCertSigningRequest' [1685486587.546443][4882:4884] CHIP:CTL: Sending CSR request to 0xffff9c034400 device [1685486587.546522][4882:4884] CHIP:DMG: ICR moving to [AddingComm] [1685486587.546552][4882:4884] CHIP:DMG: ICR moving to [AddedComma] [1685486587.546674][4882:4884] CHIP:EM: <<< [E:1862i S:10964 M:266588926] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685486587.546713][4882:4884] CHIP:IN: (S) Sending msg 266588926 on secure session with LSID: 10964 [1685486587.546765][4882:4884] CHIP:DMG: ICR moving to [CommandSen] [1685486587.546789][4882:4884] CHIP:CTL: Sent CSR request, waiting for the CSR [1685486587.546833][4882:4884] CHIP:DMG: ICR moving to [AwaitingDe] [1685486587.751307][4882:4884] CHIP:BLE: BLE scan error: src/platform/Linux/bluez/ChipDeviceScanner.cpp:174: CHIP Error 0x00000032: Timeout [1685486587.956965][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486588.350623][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486588.972199][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486588.972655][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486589.251591][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486589.251714][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486589.251951][4882:4884] CHIP:EM: >>> [E:1862i S:10964 M:62833424] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685486589.251992][4882:4884] CHIP:EM: Found matching exchange: 1862i, Delegate: 0xffff9c04c1b8 [1685486589.252034][4882:4884] CHIP:DMG: ICR moving to [ResponseRe] [1685486589.252079][4882:4884] CHIP:DMG: InvokeResponseMessage = [1685486589.252099][4882:4884] CHIP:DMG: { [1685486589.252117][4882:4884] CHIP:DMG: suppressResponse = false, [1685486589.252137][4882:4884] CHIP:DMG: InvokeResponseIBs = [1685486589.252185][4882:4884] CHIP:DMG: [ [1685486589.252204][4882:4884] CHIP:DMG: InvokeResponseIB = [1685486589.252231][4882:4884] CHIP:DMG: { [1685486589.252251][4882:4884] CHIP:DMG: CommandDataIB = [1685486589.252284][4882:4884] CHIP:DMG: { [1685486589.252318][4882:4884] CHIP:DMG: CommandPathIB = [1685486589.252351][4882:4884] CHIP:DMG: { [1685486589.252383][4882:4884] CHIP:DMG: EndpointId = 0x0, [1685486589.252425][4882:4884] CHIP:DMG: ClusterId = 0x3e, [1685486589.252459][4882:4884] CHIP:DMG: CommandId = 0x5, [1685486589.252489][4882:4884] CHIP:DMG: }, [1685486589.252526][4882:4884] CHIP:DMG: [1685486589.252553][4882:4884] CHIP:DMG: CommandFields = [1685486589.252583][4882:4884] CHIP:DMG: { [1685486589.252693][4882:4884] CHIP:DMG: 0x0 = [ [1685486589.252840][4882:4884] 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, 0x8f, 0xf5, 0xf2, 0x00, 0x2b, 0x22, 0x8a, 0x6e, 0x36, 0xed, 0x86, 0x94, 0x3b, 0x63, 0x80, 0x85, 0xdb, 0xc4, 0x0e, 0xd0, 0xdd, 0x42, 0xed, 0x1f, 0xc0, 0x2f, 0x65, 0xb9, 0x15, 0x88, 0xfb, 0x41, 0xda, 0x73, 0xf7, 0x88, 0x29, 0xb9, 0xf3, 0xb3, 0x74, 0xfb, 0xe9, 0x4f, 0xfb, 0xff, 0xa4, 0x35, 0xde, 0x73, 0xc0, 0x37, 0xca, 0xf7, 0x9f, 0xe5, 0xd2, 0x6e, 0xf3, 0x23, 0x1d, 0x13, 0x9b, 0x7b, 0xa0, 0x00, 0x30, 0x0c, 0x06, 0x08, 0x2a, 0x86, 0x48, 0xce, 0x3d, 0x04, 0x03, 0x02, 0x05, 0x00, 0x03, 0x48, 0x00, 0x30, 0x45, 0x02, 0x21, 0x00, 0xe8, 0x91, 0xc3, 0x0c, 0xf8, 0x06, 0xfb, 0x96, 0x8f, 0x61, 0xe0, 0xe4, 0x5c, 0x67, 0x4e, 0x06, 0x61, 0xf1, 0x12, 0x8e, 0x07, 0x93, 0xe1, 0xb5, 0x2e, 0x0a, 0x7d, 0x8e, 0x86, 0xac, 0x8e, 0xf2, 0x02, 0x20, 0x04, 0xfb, 0xae, 0x69, 0xd3, 0x08, 0x46, 0xb3, 0x69, 0x04, 0xf1, 0x19, 0xf0, 0x1c, 0x42, 0xa5, 0x4a, 0xdf, 0x6e, 0x66, 0xfd, 0x2b, 0xc8, 0x44, 0x3f, 0x8b, 0x4a, 0xf0, 0xe2, 0xfe, 0x13, 0x74, 0x30, 0x02, 0x20, 0x55, 0x7e, 0xff, 0xb9, 0x11, 0xae, 0xe4, 0xd2, 0x84, 0x44, 0xc0, 0x13, 0xca, 0xb5, 0x6e, 0x2e, 0x92, 0x23, 0x28, 0x0d, 0xb7, 0xb3, 0xa8, 0xac, 0x39, 0x22, 0xa3, 0x38, 0x24, 0x9d, 0xd9, 0xb6, 0x18, [1685486589.252937][4882:4884] CHIP:DMG: ] (245 bytes) [1685486589.252971][4882:4884] CHIP:DMG: 0x1 = [ [1685486589.253019][4882:4884] CHIP:DMG: 0x70, 0xe6, 0x07, 0xef, 0x52, 0x49, 0x11, 0x6b, 0x47, 0x99, 0x9e, 0x00, 0xf0, 0x4a, 0x85, 0xc8, 0xd1, 0x1d, 0xe5, 0x84, 0x15, 0x25, 0x38, 0xf3, 0xee, 0x8c, 0xc5, 0x6b, 0xb4, 0x2a, 0x96, 0x0b, 0x11, 0x4b, 0x39, 0xb5, 0x00, 0xb5, 0x76, 0x01, 0x9b, 0x27, 0x3a, 0x8c, 0xb0, 0x67, 0x3a, 0xc5, 0xbd, 0x1e, 0x4b, 0x4d, 0xa9, 0x1b, 0x0b, 0x5e, 0x66, 0x0a, 0xdd, 0x88, 0x32, 0xc9, 0xe3, 0x86, [1685486589.253082][4882:4884] CHIP:DMG: ] (64 bytes) [1685486589.253114][4882:4884] CHIP:DMG: }, [1685486589.253143][4882:4884] CHIP:DMG: }, [1685486589.253172][4882:4884] CHIP:DMG: [1685486589.253203][4882:4884] CHIP:DMG: }, [1685486589.253229][4882:4884] CHIP:DMG: [1685486589.253247][4882:4884] CHIP:DMG: ], [1685486589.253272][4882:4884] CHIP:DMG: [1685486589.253291][4882:4884] CHIP:DMG: InteractionModelRevision = 1 [1685486589.253309][4882:4884] CHIP:DMG: }, [1685486589.253365][4882:4884] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 [1685486589.253396][4882:4884] CHIP:CTL: Received certificate signing request from the device [1685486589.253423][4882:4884] CHIP:CTL: Successfully finished commissioning step 'SendOpCertSigningRequest' [1685486589.253442][4882:4884] CHIP:CTL: Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR' [1685486589.253467][4882:4884] CHIP:CTL: Performing next commissioning step 'ValidateCSR' [1685486589.258055][4882:4884] CHIP:CTL: Successfully finished commissioning step 'ValidateCSR' [1685486589.258115][4882:4884] CHIP:CTL: Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain' [1685486589.258138][4882:4884] CHIP:CTL: Performing next commissioning step 'GenerateNOCChain' [1685486589.258163][4882:4884] CHIP:CTL: Getting certificate chain for the device from the issuer [1685486589.262105][4882:4884] CHIP:CTL: Verifying Certificate Signing Request [1685486589.264743][4882:4884] CHIP:CTL: Generating NOC [1685486589.265138][4882:4884] CHIP:CTL: Providing certificate chain to the commissioner [1685486589.265177][4882:4884] CHIP:CTL: Received callback from the CA for NOC Chain generation. Status src/controller/ExampleOperationalCredentialsIssuer.cpp:396: Success [1685486589.265210][4882:4884] CHIP:CTL: Successfully finished commissioning step 'GenerateNOCChain' [1685486589.265384][4882:4884] CHIP:CTL: Performing next commissioning step 'SendTrustedRootCert' [1685486589.265424][4882:4884] CHIP:CTL: Sending root certificate to the device [1685486589.265508][4882:4884] CHIP:DMG: ICR moving to [AddingComm] [1685486589.265551][4882:4884] CHIP:DMG: ICR moving to [AddedComma] [1685486589.265749][4882:4884] CHIP:EM: <<< [E:1863i S:10964 M:266588927] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685486589.265795][4882:4884] CHIP:IN: (S) Sending msg 266588927 on secure session with LSID: 10964 [1685486589.266269][4882:4884] CHIP:DMG: ICR moving to [CommandSen] [1685486589.266318][4882:4884] CHIP:CTL: Sent root certificate to the device [1685486589.266833][4882:4884] CHIP:DMG: ICR moving to [AwaitingDe] [1685486589.419125][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486589.700650][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486589.926711][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486589.926978][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486589.927309][4882:4884] CHIP:EM: >>> [E:1863i S:10964 M:62833425] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685486589.927430][4882:4884] CHIP:EM: Found matching exchange: 1863i, Delegate: 0xffff9c039208 [1685486589.927517][4882:4884] CHIP:DMG: ICR moving to [ResponseRe] [1685486589.927618][4882:4884] CHIP:DMG: InvokeResponseMessage = [1685486589.927700][4882:4884] CHIP:DMG: { [1685486589.927829][4882:4884] CHIP:DMG: suppressResponse = false, [1685486589.927889][4882:4884] CHIP:DMG: InvokeResponseIBs = [1685486589.928101][4882:4884] CHIP:DMG: [ [1685486589.928162][4882:4884] CHIP:DMG: InvokeResponseIB = [1685486589.928240][4882:4884] CHIP:DMG: { [1685486589.928324][4882:4884] CHIP:DMG: CommandStatusIB = [1685486589.928395][4882:4884] CHIP:DMG: { [1685486589.928461][4882:4884] CHIP:DMG: CommandPathIB = [1685486589.928618][4882:4884] CHIP:DMG: { [1685486589.928701][4882:4884] CHIP:DMG: EndpointId = 0x0, [1685486589.928781][4882:4884] CHIP:DMG: ClusterId = 0x3e, [1685486589.928886][4882:4884] CHIP:DMG: CommandId = 0xb, [1685486589.928961][4882:4884] CHIP:DMG: }, [1685486589.929066][4882:4884] CHIP:DMG: [1685486589.929201][4882:4884] CHIP:DMG: StatusIB = [1685486589.929304][4882:4884] CHIP:DMG: { [1685486589.929386][4882:4884] CHIP:DMG: status = 0x00 (SUCCESS), [1685486589.929462][4882:4884] CHIP:DMG: }, [1685486589.929622][4882:4884] CHIP:DMG: [1685486589.929695][4882:4884] CHIP:DMG: }, [1685486589.929773][4882:4884] CHIP:DMG: [1685486589.929857][4882:4884] CHIP:DMG: }, [1685486589.929930][4882:4884] CHIP:DMG: [1685486589.929985][4882:4884] CHIP:DMG: ], [1685486589.930056][4882:4884] CHIP:DMG: [1685486589.930134][4882:4884] CHIP:DMG: InteractionModelRevision = 1 [1685486589.930188][4882:4884] CHIP:DMG: }, [1685486589.930385][4882:4884] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 [1685486589.930454][4882:4884] CHIP:CTL: Device confirmed that it has received the root certificate [1685486589.930515][4882:4884] CHIP:CTL: Successfully finished commissioning step 'SendTrustedRootCert' [1685486589.930566][4882:4884] CHIP:CTL: Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC' [1685486589.930703][4882:4884] CHIP:CTL: Performing next commissioning step 'SendNOC' [1685486589.930844][4882:4884] CHIP:DMG: ICR moving to [AddingComm] [1685486589.930949][4882:4884] CHIP:DMG: ICR moving to [AddedComma] [1685486589.931240][4882:4884] CHIP:EM: <<< [E:1864i S:10964 M:266588928] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685486589.931404][4882:4884] CHIP:IN: (S) Sending msg 266588928 on secure session with LSID: 10964 [1685486589.932007][4882:4884] CHIP:DMG: ICR moving to [CommandSen] [1685486589.932062][4882:4884] CHIP:CTL: Sent operational certificate to the device [1685486589.932129][4882:4884] CHIP:DMG: ICR moving to [AwaitingDe] [1685486590.150685][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486590.375439][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486590.488177][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486591.107876][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486591.108314][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486591.108610][4882:4884] CHIP:EM: >>> [E:1864i S:10964 M:62833426] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685486591.108681][4882:4884] CHIP:EM: Found matching exchange: 1864i, Delegate: 0xffff9c04c1b8 [1685486591.108754][4882:4884] CHIP:DMG: ICR moving to [ResponseRe] [1685486591.108842][4882:4884] CHIP:DMG: InvokeResponseMessage = [1685486591.108890][4882:4884] CHIP:DMG: { [1685486591.108933][4882:4884] CHIP:DMG: suppressResponse = false, [1685486591.108981][4882:4884] CHIP:DMG: InvokeResponseIBs = [1685486591.109044][4882:4884] CHIP:DMG: [ [1685486591.109093][4882:4884] CHIP:DMG: InvokeResponseIB = [1685486591.109159][4882:4884] CHIP:DMG: { [1685486591.109211][4882:4884] CHIP:DMG: CommandDataIB = [1685486591.109270][4882:4884] CHIP:DMG: { [1685486591.109322][4882:4884] CHIP:DMG: CommandPathIB = [1685486591.109392][4882:4884] CHIP:DMG: { [1685486591.109456][4882:4884] CHIP:DMG: EndpointId = 0x0, [1685486591.109525][4882:4884] CHIP:DMG: ClusterId = 0x3e, [1685486591.109592][4882:4884] CHIP:DMG: CommandId = 0x8, [1685486591.109655][4882:4884] CHIP:DMG: }, [1685486591.109722][4882:4884] CHIP:DMG: [1685486591.109781][4882:4884] CHIP:DMG: CommandFields = [1685486591.109844][4882:4884] CHIP:DMG: { [1685486591.109910][4882:4884] CHIP:DMG: 0x0 = 0, [1685486591.109979][4882:4884] CHIP:DMG: 0x1 = 1, [1685486591.110045][4882:4884] CHIP:DMG: }, [1685486591.110105][4882:4884] CHIP:DMG: }, [1685486591.110176][4882:4884] CHIP:DMG: [1685486591.110227][4882:4884] CHIP:DMG: }, [1685486591.110295][4882:4884] CHIP:DMG: [1685486591.110342][4882:4884] CHIP:DMG: ], [1685486591.110403][4882:4884] CHIP:DMG: [1685486591.110450][4882:4884] CHIP:DMG: InteractionModelRevision = 1 [1685486591.110497][4882:4884] CHIP:DMG: }, [1685486591.110618][4882:4884] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 [1685486591.110687][4882:4884] CHIP:CTL: Device returned status 0 on receiving the NOC [1685486591.110733][4882:4884] CHIP:CTL: Operational credentials provisioned on device 0xffff9c034400 [1685486591.110775][4882:4884] CHIP:TOO: Secure Pairing Success [1685486591.110813][4882:4884] CHIP:TOO: CASE establishment successful [1685486591.110862][4882:4884] CHIP:CTL: Successfully finished commissioning step 'SendNOC' [1685486591.110907][4882:4884] CHIP:CTL: No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks [1685486591.110946][4882:4884] CHIP:CTL: Commissioning stage next step: 'SendNOC' -> 'WiFiNetworkSetup' [1685486591.110994][4882:4884] CHIP:CTL: Performing next commissioning step 'WiFiNetworkSetup' [1685486591.111111][4882:4884] CHIP:DMG: ICR moving to [AddingComm] [1685486591.111178][4882:4884] CHIP:DMG: ICR moving to [AddedComma] [1685486591.111368][4882:4884] CHIP:EM: <<< [E:1865i S:10964 M:266588929] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685486591.111450][4882:4884] CHIP:IN: (S) Sending msg 266588929 on secure session with LSID: 10964 [1685486591.112237][4882:4884] CHIP:DMG: ICR moving to [CommandSen] [1685486591.112374][4882:4884] CHIP:DMG: ICR moving to [AwaitingDe] [1685486591.219263][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486591.220844][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486591.221282][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486591.221574][4882:4884] CHIP:EM: >>> [E:1865i S:10964 M:62833427] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685486591.221643][4882:4884] CHIP:EM: Found matching exchange: 1865i, Delegate: 0xffff9c039208 [1685486591.221717][4882:4884] CHIP:DMG: ICR moving to [ResponseRe] [1685486591.221804][4882:4884] CHIP:DMG: InvokeResponseMessage = [1685486591.221851][4882:4884] CHIP:DMG: { [1685486591.221896][4882:4884] CHIP:DMG: suppressResponse = false, [1685486591.221944][4882:4884] CHIP:DMG: InvokeResponseIBs = [1685486591.222007][4882:4884] CHIP:DMG: [ [1685486591.222055][4882:4884] CHIP:DMG: InvokeResponseIB = [1685486591.222122][4882:4884] CHIP:DMG: { [1685486591.222173][4882:4884] CHIP:DMG: CommandDataIB = [1685486591.222239][4882:4884] CHIP:DMG: { [1685486591.222294][4882:4884] CHIP:DMG: CommandPathIB = [1685486591.222355][4882:4884] CHIP:DMG: { [1685486591.222413][4882:4884] CHIP:DMG: EndpointId = 0x0, [1685486591.222486][4882:4884] CHIP:DMG: ClusterId = 0x31, [1685486591.222550][4882:4884] CHIP:DMG: CommandId = 0x5, [1685486591.222613][4882:4884] CHIP:DMG: }, [1685486591.222680][4882:4884] CHIP:DMG: [1685486591.222737][4882:4884] CHIP:DMG: CommandFields = [1685486591.222800][4882:4884] CHIP:DMG: { [1685486591.222863][4882:4884] CHIP:DMG: 0x0 = 0, [1685486591.222930][4882:4884] CHIP:DMG: 0x2 = 0, [1685486591.222997][4882:4884] CHIP:DMG: }, [1685486591.223056][4882:4884] CHIP:DMG: }, [1685486591.223122][4882:4884] CHIP:DMG: [1685486591.223172][4882:4884] CHIP:DMG: }, [1685486591.223234][4882:4884] CHIP:DMG: [1685486591.223278][4882:4884] CHIP:DMG: ], [1685486591.223339][4882:4884] CHIP:DMG: [1685486591.223386][4882:4884] CHIP:DMG: InteractionModelRevision = 1 [1685486591.223431][4882:4884] CHIP:DMG: }, [1685486591.223552][4882:4884] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005 [1685486591.223703][4882:4884] CHIP:CTL: Received NetworkConfig response, networkingStatus=0 [1685486591.223829][4882:4884] CHIP:CTL: Successfully finished commissioning step 'WiFiNetworkSetup' [1685486591.223881][4882:4884] CHIP:CTL: Commissioning stage next step: 'WiFiNetworkSetup' -> 'FailsafeBeforeWiFiEnable' [1685486591.223935][4882:4884] CHIP:CTL: Performing next commissioning step 'FailsafeBeforeWiFiEnable' [1685486591.223997][4882:4884] CHIP:CTL: Arming failsafe (66 seconds) [1685486591.224114][4882:4884] CHIP:DMG: ICR moving to [AddingComm] [1685486591.224173][4882:4884] CHIP:DMG: ICR moving to [AddedComma] [1685486591.224354][4882:4884] CHIP:EM: <<< [E:1866i S:10964 M:266588930] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685486591.224434][4882:4884] CHIP:IN: (S) Sending msg 266588930 on secure session with LSID: 10964 [1685486591.225111][4882:4884] CHIP:DMG: ICR moving to [CommandSen] [1685486591.225235][4882:4884] CHIP:DMG: ICR moving to [AwaitingDe] [1685486591.331886][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486591.333591][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486591.333836][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486591.334164][4882:4884] CHIP:EM: >>> [E:1866i S:10964 M:62833428] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685486591.334246][4882:4884] CHIP:EM: Found matching exchange: 1866i, Delegate: 0xffff9c04c1b8 [1685486591.334332][4882:4884] CHIP:DMG: ICR moving to [ResponseRe] [1685486591.334434][4882:4884] CHIP:DMG: InvokeResponseMessage = [1685486591.334490][4882:4884] CHIP:DMG: { [1685486591.334543][4882:4884] CHIP:DMG: suppressResponse = false, [1685486591.334601][4882:4884] CHIP:DMG: InvokeResponseIBs = [1685486591.334676][4882:4884] CHIP:DMG: [ [1685486591.334732][4882:4884] CHIP:DMG: InvokeResponseIB = [1685486591.334810][4882:4884] CHIP:DMG: { [1685486591.334870][4882:4884] CHIP:DMG: CommandDataIB = [1685486591.334941][4882:4884] CHIP:DMG: { [1685486591.335006][4882:4884] CHIP:DMG: CommandPathIB = [1685486591.335081][4882:4884] CHIP:DMG: { [1685486591.335156][4882:4884] CHIP:DMG: EndpointId = 0x0, [1685486591.335236][4882:4884] CHIP:DMG: ClusterId = 0x30, [1685486591.335321][4882:4884] CHIP:DMG: CommandId = 0x1, [1685486591.335401][4882:4884] CHIP:DMG: }, [1685486591.335482][4882:4884] CHIP:DMG: [1685486591.335550][4882:4884] CHIP:DMG: CommandFields = [1685486591.335625][4882:4884] CHIP:DMG: { [1685486591.335704][4882:4884] CHIP:DMG: 0x0 = 0, [1685486591.335862][4882:4884] CHIP:DMG: 0x1 = "" (0 chars), [1685486591.335944][4882:4884] CHIP:DMG: }, [1685486591.336016][4882:4884] CHIP:DMG: }, [1685486591.336095][4882:4884] CHIP:DMG: [1685486591.336154][4882:4884] CHIP:DMG: }, [1685486591.336226][4882:4884] CHIP:DMG: [1685486591.336281][4882:4884] CHIP:DMG: ], [1685486591.336353][4882:4884] CHIP:DMG: [1685486591.336408][4882:4884] CHIP:DMG: InteractionModelRevision = 1 [1685486591.336461][4882:4884] CHIP:DMG: }, [1685486591.336599][4882:4884] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [1685486591.336676][4882:4884] CHIP:CTL: Received ArmFailSafe response errorCode=0 [1685486591.336739][4882:4884] CHIP:CTL: Successfully finished commissioning step 'FailsafeBeforeWiFiEnable' [1685486591.336789][4882:4884] CHIP:CTL: Commissioning stage next step: 'FailsafeBeforeWiFiEnable' -> 'WiFiNetworkEnable' [1685486591.336840][4882:4884] CHIP:CTL: Setting wifi connection time min = 20 [1685486591.336895][4882:4884] CHIP:CTL: Performing next commissioning step 'WiFiNetworkEnable' [1685486591.337023][4882:4884] CHIP:DMG: ICR moving to [AddingComm] [1685486591.337095][4882:4884] CHIP:DMG: ICR moving to [AddedComma] [1685486591.337295][4882:4884] CHIP:EM: <<< [E:1867i S:10964 M:266588931] (S) Msg TX to 0:FFFFFFFB00000000 [0000] --- Type 0001:08 (IM:InvokeCommandRequest) [1685486591.337386][4882:4884] CHIP:IN: (S) Sending msg 266588931 on secure session with LSID: 10964 [1685486591.338227][4882:4884] CHIP:DMG: ICR moving to [CommandSen] [1685486591.338374][4882:4884] CHIP:DMG: ICR moving to [AwaitingDe] [1685486591.725728][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486594.257436][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486594.257712][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486596.057942][4882:4883] CHIP:DL: Indication received, conn = 0xffffa403fdc0 [1685486596.058182][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16389 [1685486596.058433][4882:4884] CHIP:EM: >>> [E:1867i S:10964 M:62833429] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [1685486596.058506][4882:4884] CHIP:EM: Found matching exchange: 1867i, Delegate: 0xffff9c039208 [1685486596.058588][4882:4884] CHIP:DMG: ICR moving to [ResponseRe] [1685486596.058677][4882:4884] CHIP:DMG: InvokeResponseMessage = [1685486596.058725][4882:4884] CHIP:DMG: { [1685486596.058772][4882:4884] CHIP:DMG: suppressResponse = false, [1685486596.058822][4882:4884] CHIP:DMG: InvokeResponseIBs = [1685486596.058886][4882:4884] CHIP:DMG: [ [1685486596.058934][4882:4884] CHIP:DMG: InvokeResponseIB = [1685486596.059002][4882:4884] CHIP:DMG: { [1685486596.059053][4882:4884] CHIP:DMG: CommandDataIB = [1685486596.059112][4882:4884] CHIP:DMG: { [1685486596.059164][4882:4884] CHIP:DMG: CommandPathIB = [1685486596.059221][4882:4884] CHIP:DMG: { [1685486596.059287][4882:4884] CHIP:DMG: EndpointId = 0x0, [1685486596.059359][4882:4884] CHIP:DMG: ClusterId = 0x31, [1685486596.059442][4882:4884] CHIP:DMG: CommandId = 0x7, [1685486596.059507][4882:4884] CHIP:DMG: }, [1685486596.059573][4882:4884] CHIP:DMG: [1685486596.059629][4882:4884] CHIP:DMG: CommandFields = [1685486596.059686][4882:4884] CHIP:DMG: { [1685486596.059808][4882:4884] CHIP:DMG: 0x0 = 0, [1685486596.059882][4882:4884] CHIP:DMG: 0x2 = NULL [1685486596.059951][4882:4884] CHIP:DMG: }, [1685486596.060011][4882:4884] CHIP:DMG: }, [1685486596.060078][4882:4884] CHIP:DMG: [1685486596.060129][4882:4884] CHIP:DMG: }, [1685486596.060192][4882:4884] CHIP:DMG: [1685486596.060239][4882:4884] CHIP:DMG: ], [1685486596.060303][4882:4884] CHIP:DMG: [1685486596.060351][4882:4884] CHIP:DMG: InteractionModelRevision = 1 [1685486596.060399][4882:4884] CHIP:DMG: }, [1685486596.060521][4882:4884] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007 [1685486596.060590][4882:4884] CHIP:CTL: Received ConnectNetwork response, networkingStatus=0 [1685486596.060646][4882:4884] CHIP:CTL: Successfully finished commissioning step 'WiFiNetworkEnable' [1685486596.060695][4882:4884] CHIP:CTL: Commissioning stage next step: 'WiFiNetworkEnable' -> 'FindOperational' [1685486596.060749][4882:4884] CHIP:CTL: Performing next commissioning step 'FindOperational' [1685486596.060784][4882:4884] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1685486596.060819][4882:4884] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1685486596.060885][4882:4884] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1685486596.060931][4882:4884] CHIP:DIS: Resolving E0B91AD5E051DD6E:0000000000000001 ... [1685486596.062557][4882:4884] CHIP:DMG: ICR moving to [AwaitingDe] [1685486596.063701][4882:4884] CHIP:DL: Avahi resolve found [1685486596.063842][4882:4884] CHIP:DIS: Node ID resolved for E0B91AD5E051DD6E:0000000000000001 [1685486596.063883][4882:4884] CHIP:DIS: Hostname: 287681CAAD58 [1685486596.063927][4882:4884] CHIP:DIS: IP Address #1: fe80::2a76:81ff:feca:ad58 [1685486596.063965][4882:4884] CHIP:DIS: Port: 5540 [1685486596.064000][4882:4884] CHIP:DIS: Mrp Interval idle: 300 ms [1685486596.064035][4882:4884] CHIP:DIS: Mrp Interval active: 2000 ms [1685486596.064070][4882:4884] CHIP:DIS: TCP Supported: 1 [1685486596.064266][4882:4884] CHIP:DIS: UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540: new best score: 3 [1685486596.064308][4882:4884] CHIP:DIS: Checking node lookup status after 3 ms [1685486596.064340][4882:4884] CHIP:DIS: Keeping DNSSD lookup active [1685486596.261423][4882:4884] CHIP:DIS: Checking node lookup status after 200 ms [1685486596.261713][4882:4884] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540 while in state 2 [1685486596.261778][4882:4884] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1685486596.261992][4882:4884] CHIP:IN: SecureSession[0xffff940212c0]: Allocated Type:2 LSID:10965 [1685486596.262083][4882:4884] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1685486596.264081][4882:4884] CHIP:EM: <<< [E:1868i S:0 M:171016412] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1685486596.264374][4882:4884] CHIP:IN: (U) Sending msg 171016412 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486596.264695][4882:4884] CHIP:SC: Sent Sigma1 msg [1685486596.264763][4882:4884] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1685486596.449823][4882:4884] CHIP:EM: >>> [E:1868i S:0 M:245487191 (Ack:171016412)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486596.449915][4882:4884] CHIP:EM: Found matching exchange: 1868i, Delegate: 0xffff9c064d68 [1685486596.449988][4882:4884] CHIP:EM: Rxd Ack; Removing MessageCounter:171016412 from Retrans Table on exchange 1868i [1685486597.013399][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16387 [1685486597.214128][4882:4884] CHIP:EM: >>> [E:1868i S:0 M:245487192 (Ack:171016412)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1685486597.214229][4882:4884] CHIP:EM: Found matching exchange: 1868i, Delegate: 0xffff9c064d68 [1685486597.214291][4882:4884] CHIP:EM: CHIP MessageCounter:171016412 not in RetransTable on exchange 1868i [1685486597.214389][4882:4884] CHIP:SC: Received Sigma2 msg [1685486597.214471][4882:4884] CHIP:SC: Peer assigned session session ID 35478 [1685486597.224352][4882:4884] CHIP:SC: Found MRP parameters in the message [1685486597.224469][4882:4884] CHIP:SC: Sending Sigma3 [1685486597.225713][4882:4884] CHIP:EM: <<< [E:1868i S:0 M:171016413 (Ack:245487192)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1685486597.226033][4882:4884] CHIP:IN: (U) Sending msg 171016413 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486597.226354][4882:4884] CHIP:SC: Sent Sigma3 msg [1685486597.412035][4882:4884] CHIP:EM: >>> [E:1868i S:0 M:245487193 (Ack:171016413)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486597.412137][4882:4884] CHIP:EM: Found matching exchange: 1868i, Delegate: 0xffff9c064d68 [1685486597.412221][4882:4884] CHIP:EM: Rxd Ack; Removing MessageCounter:171016413 from Retrans Table on exchange 1868i [1685486598.302690][4882:4884] CHIP:EM: >>> [E:1868i S:0 M:245487194 (Ack:171016413)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685486598.302795][4882:4884] CHIP:EM: Found matching exchange: 1868i, Delegate: 0xffff9c064d68 [1685486598.302855][4882:4884] CHIP:EM: CHIP MessageCounter:171016413 not in RetransTable on exchange 1868i [1685486598.302957][4882:4884] CHIP:SC: Success status report received. Session was established [1685486598.309355][4882:4884] CHIP:SC: SecureSession[0xffff940212c0, LSID:10965]: State change 'kEstablishing' --> 'kActive' [1685486598.309459][4882:4884] CHIP:IN: SecureSession[0xffff940212c0]: Activated - Type:2 LSID:10965 [1685486598.309515][4882:4884] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:10965 PSID:35478! [1685486598.309578][4882:4884] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1685486598.309706][4882:4884] CHIP:CTL: Successfully finished commissioning step 'FindOperational' [1685486598.309768][4882:4884] CHIP:CTL: Commissioning stage next step: 'FindOperational' -> 'SendComplete' [1685486598.309842][4882:4884] CHIP:CTL: Performing next commissioning step 'SendComplete' [1685486598.309976][4882:4884] CHIP:DMG: ICR moving to [AddingComm] [1685486598.310043][4882:4884] CHIP:DMG: ICR moving to [AddedComma] [1685486598.310269][4882:4884] CHIP:EM: <<< [E:1869i S:10965 M:229453271] (S) Msg TX to 1:0000000000000001 [DD6E] --- Type 0001:08 (IM:InvokeCommandRequest) [1685486598.310367][4882:4884] CHIP:IN: (S) Sending msg 229453271 on secure session with LSID: 10965 [1685486598.310672][4882:4884] CHIP:DMG: ICR moving to [CommandSen] [1685486598.310809][4882:4884] CHIP:EM: <<< [E:1868i S:0 M:171016414 (Ack:245487194)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486598.311069][4882:4884] CHIP:IN: (U) Sending msg 171016414 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486598.311249][4882:4884] CHIP:EM: Flushed pending ack for MessageCounter:245487194 on exchange 1868i [1685486598.428425][4882:4884] CHIP:EM: >>> [E:1869i S:10965 M:62562869 (Ack:229453271)] (S) Msg RX from 1:0000000000000001 [DD6E] --- Type 0001:09 (IM:InvokeCommandResponse) [1685486598.428516][4882:4884] CHIP:EM: Found matching exchange: 1869i, Delegate: 0xffff9c04c1b8 [1685486598.428589][4882:4884] CHIP:EM: Rxd Ack; Removing MessageCounter:229453271 from Retrans Table on exchange 1869i [1685486598.428662][4882:4884] CHIP:DMG: ICR moving to [ResponseRe] [1685486598.428755][4882:4884] CHIP:DMG: InvokeResponseMessage = [1685486598.428803][4882:4884] CHIP:DMG: { [1685486598.428848][4882:4884] CHIP:DMG: suppressResponse = false, [1685486598.428896][4882:4884] CHIP:DMG: InvokeResponseIBs = [1685486598.428959][4882:4884] CHIP:DMG: [ [1685486598.429006][4882:4884] CHIP:DMG: InvokeResponseIB = [1685486598.429074][4882:4884] CHIP:DMG: { [1685486598.429126][4882:4884] CHIP:DMG: CommandDataIB = [1685486598.429187][4882:4884] CHIP:DMG: { [1685486598.429242][4882:4884] CHIP:DMG: CommandPathIB = [1685486598.429306][4882:4884] CHIP:DMG: { [1685486598.429370][4882:4884] CHIP:DMG: EndpointId = 0x0, [1685486598.429434][4882:4884] CHIP:DMG: ClusterId = 0x30, [1685486598.429512][4882:4884] CHIP:DMG: CommandId = 0x5, [1685486598.429591][4882:4884] CHIP:DMG: }, [1685486598.429671][4882:4884] CHIP:DMG: [1685486598.429736][4882:4884] CHIP:DMG: CommandFields = [1685486598.429803][4882:4884] CHIP:DMG: { [1685486598.430003][4882:4884] CHIP:DMG: 0x0 = 0, [1685486598.430088][4882:4884] CHIP:DMG: 0x1 = "" (0 chars), [1685486598.430169][4882:4884] CHIP:DMG: }, [1685486598.430239][4882:4884] CHIP:DMG: }, [1685486598.430318][4882:4884] CHIP:DMG: [1685486598.430377][4882:4884] CHIP:DMG: }, [1685486598.430451][4882:4884] CHIP:DMG: [1685486598.430505][4882:4884] CHIP:DMG: ], [1685486598.430577][4882:4884] CHIP:DMG: [1685486598.430632][4882:4884] CHIP:DMG: InteractionModelRevision = 1 [1685486598.430685][4882:4884] CHIP:DMG: }, [1685486598.430826][4882:4884] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005 [1685486598.430902][4882:4884] CHIP:CTL: Received CommissioningComplete response, errorCode=0 [1685486598.430966][4882:4884] CHIP:CTL: Successfully finished commissioning step 'SendComplete' [1685486598.431015][4882:4884] CHIP:CTL: Commissioning stage next step: 'SendComplete' -> 'Cleanup' [1685486598.431084][4882:4884] CHIP:CTL: Performing next commissioning step 'Cleanup' [1685486598.431138][4882:4884] CHIP:DIS: Closing all BLE connections [1685486598.431193][4882:4884] CHIP:IN: Clearing BLE pending packets. [1685486598.431973][4882:4884] CHIP:BLE: Auto-closing end point's BLE connection. [1685486598.432051][4882:4884] CHIP:DL: Closing BLE GATT connection (con 0xffffa403fdc0) [1685486598.432259][4882:4883] CHIP:DL: BluezDisconnect peer=94:1E:65:D1:68:27 [1685486600.615327][4882:4884] CHIP:IN: SecureSession[0xffff9c038b00]: MarkForEviction Type:1 LSID:10964 [1685486600.615415][4882:4884] CHIP:SC: SecureSession[0xffff9c038b00, LSID:10964]: State change 'kActive' --> 'kPendingEviction' [1685486600.615526][4882:4884] CHIP:IN: SecureSession[0xffff9c038b00]: Released - Type:1 LSID:10964 [1685486600.615610][4882:4884] CHIP:CTL: Successfully finished commissioning step 'Cleanup' [1685486600.615675][4882:4884] CHIP:TOO: Device commissioning completed with success [1685486600.615888][4882:4884] CHIP:DMG: ICR moving to [AwaitingDe] [1685486600.616105][4882:4884] CHIP:EM: <<< [E:1869i S:10965 M:229453272 (Ack:62562869)] (S) Msg TX to 1:0000000000000001 [DD6E] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486600.616141][4882:4883] CHIP:DL: Bluez disconnected [1685486600.616304][4882:4883] CHIP:DL: Bluez notify CHIPoBluez connection disconnected [1685486600.616632][4882:4884] CHIP:IN: (S) Sending msg 229453272 on secure session with LSID: 10965 [1685486600.616863][4882:4884] CHIP:EM: Flushed pending ack for MessageCounter:62562869 on exchange 1869i [1685486600.616970][4882:4884] CHIP:DL: HandlePlatformSpecificBLEEvent 16388 [1685486600.617019][4882:4884] CHIP:BLE: no endpoint for unsub complete [1685486600.617598][4882:4882] CHIP:CTL: Shutting down the commissioner [1685486600.617666][4882:4882] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486600.617714][4882:4882] CHIP:CTL: Shutting down the controller [1685486600.617760][4882:4882] CHIP:IN: Expiring all sessions for fabric 0x1!! [1685486600.617804][4882:4882] CHIP:IN: SecureSession[0xffff940212c0]: MarkForEviction Type:2 LSID:10965 [1685486600.617847][4882:4882] CHIP:SC: SecureSession[0xffff940212c0, LSID:10965]: State change 'kActive' --> 'kPendingEviction' [1685486600.617892][4882:4882] CHIP:IN: SecureSession[0xffff940212c0]: Released - Type:2 LSID:10965 [1685486600.617943][4882:4882] CHIP:FP: Forgetting fabric 0x1 [1685486600.618003][4882:4882] CHIP:TS: Pending Last Known Good Time: 2023-05-26T15:09:49 [1685486600.618292][4882:4882] CHIP:TS: Previous Last Known Good Time: 2023-05-26T15:09:49 [1685486600.618344][4882:4882] CHIP:TS: Reverted Last Known Good Time to previous value [1685486600.618418][4882:4882] CHIP:CTL: Shutting down the commissioner [1685486600.618461][4882:4882] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486600.618503][4882:4882] CHIP:CTL: Shutting down the controller [1685486600.618542][4882:4882] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1685486600.620383][4882:4882] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1685486600.620556][4882:4882] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1685486600.620660][4882:4882] CHIP:FP: Shutting down FabricTable [1685486600.620726][4882:4882] CHIP:TS: Pending Last Known Good Time: 2023-05-26T15:09:49 [1685486600.620954][4882:4882] CHIP:TS: Previous Last Known Good Time: 2023-05-26T15:09:49 [1685486600.621094][4882:4882] CHIP:TS: Reverted Last Known Good Time to previous value [1685486600.621619][4882:4882] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-Qv5wgV) [1685486600.622766][4882:4882] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486600.622886][4882:4882] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1685486600.622938][4882:4882] CHIP:DL: Inet Layer shutdown [1685486600.622981][4882:4882] CHIP:DL: BLE shutdown [1685486600.624593][4882:4882] CHIP:DL: System Layer shutdown ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ./chip-tool scenes read cluster-revision 1 1 [1685486606.271008][4893:4893] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1685486606.276618][4893:4893] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1685486606.276921][4893:4893] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1685486606.277070][4893:4893] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1685486606.277406][4893:4893] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-wcFgRr) [1685486606.278081][4893:4893] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486606.278136][4893:4893] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2) [1685486606.279016][4893:4893] CHIP:DL: Got Ethernet interface: eth0 [1685486606.279575][4893:4893] CHIP:DL: Found the primary Ethernet interface:eth0 [1685486606.280208][4893:4893] CHIP:DL: Got WiFi interface: wlan0 [1685486606.280275][4893:4893] CHIP:DL: Failed to reset WiFi statistic counts [1685486606.280330][4893:4893] CHIP:IN: UDP::Init bind&listen port=0 [1685486606.280444][4893:4893] CHIP:IN: UDP::Init bound to port=47269 [1685486606.280466][4893:4893] CHIP:IN: BLEBase::Init - setting/overriding transport [1685486606.280483][4893:4893] CHIP:IN: TransportMgr initialized [1685486606.280514][4893:4893] CHIP:FP: Initializing FabricTable from persistent storage [1685486606.280680][4893:4893] CHIP:TS: Last Known Good Time: 2023-05-26T15:09:49 [1685486606.282206][4893:4893] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xE0B91AD5E051DD6E, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1685486606.284149][4893:4893] CHIP:ZCL: Using ZAP configuration... [1685486606.287769][4893:4893] CHIP:DL: Avahi client registered [1685486606.288959][4893:4893] CHIP:CTL: System State Initialized... [1685486606.289065][4893:4893] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486606.289108][4893:4893] CHIP:CTL: Setting attestation nonce to random value [1685486606.289141][4893:4893] CHIP:CTL: Setting CSR nonce to random value [1685486606.289409][4893:4895] CHIP:DL: CHIP task running [1685486606.289604][4893:4895] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1685486606.289992][4893:4895] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486606.290041][4893:4895] CHIP:CTL: Setting attestation nonce to random value [1685486606.290205][4893:4895] CHIP:CTL: Setting CSR nonce to random value [1685486606.291062][4893:4895] CHIP:CTL: Generating NOC [1685486606.292064][4893:4895] CHIP:FP: Validating NOC chain [1685486606.293703][4893:4895] CHIP:FP: NOC chain validation successful [1685486606.293857][4893:4895] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1685486606.293888][4893:4895] CHIP:TS: Last Known Good Time: 2023-05-26T15:09:49 [1685486606.293906][4893:4895] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1685486606.293923][4893:4895] CHIP:TS: Retaining current Last Known Good Time [1685486606.298455][4893:4895] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1685486606.300554][4893:4895] CHIP:TS: Committing Last Known Good Time to storage: 2023-05-26T15:09:49 [1685486606.302263][4893:4895] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: E0B91AD5E051DD6E) [1685486606.314644][4893:4895] CHIP:TOO: Sending command to node 0x1 [1685486606.315074][4893:4895] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1685486606.315104][4893:4895] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1685486606.315137][4893:4895] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1685486606.315165][4893:4895] CHIP:DIS: Resolving E0B91AD5E051DD6E:0000000000000001 ... [1685486606.316790][4893:4895] CHIP:DL: Avahi resolve found [1685486606.316862][4893:4895] CHIP:DIS: Node ID resolved for E0B91AD5E051DD6E:0000000000000001 [1685486606.316883][4893:4895] CHIP:DIS: Hostname: 287681CAAD58 [1685486606.316905][4893:4895] CHIP:DIS: IP Address #1: fe80::2a76:81ff:feca:ad58 [1685486606.316925][4893:4895] CHIP:DIS: Port: 5540 [1685486606.316942][4893:4895] CHIP:DIS: Mrp Interval idle: 300 ms [1685486606.316960][4893:4895] CHIP:DIS: Mrp Interval active: 2000 ms [1685486606.316978][4893:4895] CHIP:DIS: TCP Supported: 1 [1685486606.317100][4893:4895] CHIP:DIS: UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540: new best score: 3 [1685486606.317125][4893:4895] CHIP:DIS: Checking node lookup status after 2 ms [1685486606.317142][4893:4895] CHIP:DIS: Keeping DNSSD lookup active [1685486606.515342][4893:4895] CHIP:DIS: Checking node lookup status after 200 ms [1685486606.515653][4893:4895] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540 while in state 2 [1685486606.515719][4893:4895] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1685486606.516007][4893:4895] CHIP:IN: SecureSession[0xffff8c00ae60]: Allocated Type:2 LSID:49604 [1685486606.516105][4893:4895] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1685486606.518074][4893:4895] CHIP:EM: <<< [E:29923i S:0 M:55336019] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1685486606.518374][4893:4895] CHIP:IN: (U) Sending msg 55336019 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486606.518724][4893:4895] CHIP:SC: Sent Sigma1 msg [1685486606.518794][4893:4895] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1685486606.614047][4893:4895] CHIP:EM: >>> [E:29923i S:0 M:245487195 (Ack:55336019)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486606.614136][4893:4895] CHIP:EM: Found matching exchange: 29923i, Delegate: 0xffff8c00d2d8 [1685486606.614208][4893:4895] CHIP:EM: Rxd Ack; Removing MessageCounter:55336019 from Retrans Table on exchange 29923i [1685486607.481428][4893:4895] CHIP:EM: >>> [E:29923i S:0 M:245487196 (Ack:55336019)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1685486607.481537][4893:4895] CHIP:EM: Found matching exchange: 29923i, Delegate: 0xffff8c00d2d8 [1685486607.481599][4893:4895] CHIP:EM: CHIP MessageCounter:55336019 not in RetransTable on exchange 29923i [1685486607.481700][4893:4895] CHIP:SC: Received Sigma2 msg [1685486607.481785][4893:4895] CHIP:SC: Peer assigned session session ID 35479 [1685486607.492408][4893:4895] CHIP:SC: Found MRP parameters in the message [1685486607.492531][4893:4895] CHIP:SC: Sending Sigma3 [1685486607.493907][4893:4895] CHIP:EM: <<< [E:29923i S:0 M:55336020 (Ack:245487196)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1685486607.494220][4893:4895] CHIP:IN: (U) Sending msg 55336020 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486607.494554][4893:4895] CHIP:SC: Sent Sigma3 msg [1685486607.634515][4893:4895] CHIP:EM: >>> [E:29923i S:0 M:245487197 (Ack:55336020)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486607.634620][4893:4895] CHIP:EM: Found matching exchange: 29923i, Delegate: 0xffff8c00d2d8 [1685486607.634703][4893:4895] CHIP:EM: Rxd Ack; Removing MessageCounter:55336020 from Retrans Table on exchange 29923i [1685486608.511654][4893:4895] CHIP:EM: >>> [E:29923i S:0 M:245487198 (Ack:55336020)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685486608.511784][4893:4895] CHIP:EM: Found matching exchange: 29923i, Delegate: 0xffff8c00d2d8 [1685486608.511842][4893:4895] CHIP:EM: CHIP MessageCounter:55336020 not in RetransTable on exchange 29923i [1685486608.511933][4893:4895] CHIP:SC: Success status report received. Session was established [1685486608.517765][4893:4895] CHIP:SC: SecureSession[0xffff8c00ae60, LSID:49604]: State change 'kEstablishing' --> 'kActive' [1685486608.517853][4893:4895] CHIP:IN: SecureSession[0xffff8c00ae60]: Activated - Type:2 LSID:49604 [1685486608.517899][4893:4895] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:49604 PSID:35479! [1685486608.517954][4893:4895] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1685486608.518137][4893:4895] CHIP:TOO: cluster 0x0000_0005, attribute: 0x0000_FFFD, endpoint 1 [1685486608.518203][4893:4895] CHIP:TOO: Sending ReadAttribute to: [1685486608.518267][4893:4895] CHIP:DMG: SendReadRequest ReadClient[0xffff8c0101a0]: Sending Read Request [1685486608.518520][4893:4895] CHIP:EM: <<< [E:29924i S:49604 M:106835747] (S) Msg TX to 1:0000000000000001 [DD6E] --- Type 0001:02 (IM:ReadRequest) [1685486608.518643][4893:4895] CHIP:IN: (S) Sending msg 106835747 on secure session with LSID: 49604 [1685486608.518936][4893:4895] CHIP:DMG: MoveToState ReadClient[0xffff8c0101a0]: Moving to [AwaitingIn] [1685486608.519076][4893:4895] CHIP:EM: <<< [E:29923i S:0 M:55336021 (Ack:245487198)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486608.519329][4893:4895] CHIP:IN: (U) Sending msg 55336021 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486608.519508][4893:4895] CHIP:EM: Flushed pending ack for MessageCounter:245487198 on exchange 29923i [1685486608.584999][4893:4895] CHIP:EM: >>> [E:29924i S:49604 M:1039903 (Ack:106835747)] (S) Msg RX from 1:0000000000000001 [DD6E] --- Type 0001:05 (IM:ReportData) [1685486608.585051][4893:4895] CHIP:EM: Found matching exchange: 29924i, Delegate: 0xffff8c0101b0 [1685486608.585087][4893:4895] CHIP:EM: Rxd Ack; Removing MessageCounter:106835747 from Retrans Table on exchange 29924i [1685486608.585147][4893:4895] CHIP:DMG: ReportDataMessage = [1685486608.585175][4893:4895] CHIP:DMG: { [1685486608.585200][4893:4895] CHIP:DMG: AttributeReportIBs = [1685486608.585247][4893:4895] CHIP:DMG: [ [1685486608.585290][4893:4895] CHIP:DMG: AttributeReportIB = [1685486608.585351][4893:4895] CHIP:DMG: { [1685486608.585398][4893:4895] CHIP:DMG: AttributeDataIB = [1685486608.585452][4893:4895] CHIP:DMG: { [1685486608.585533][4893:4895] CHIP:DMG: DataVersion = 0xa51ec1e3, [1685486608.585594][4893:4895] CHIP:DMG: AttributePathIB = [1685486608.585651][4893:4895] CHIP:DMG: { [1685486608.585708][4893:4895] CHIP:DMG: Endpoint = 0x1, [1685486608.585788][4893:4895] CHIP:DMG: Cluster = 0x5, [1685486608.585853][4893:4895] CHIP:DMG: Attribute = 0x0000_FFFD, [1685486608.585912][4893:4895] CHIP:DMG: } [1685486608.585971][4893:4895] CHIP:DMG: [1685486608.586133][4893:4895] CHIP:DMG: Data = 4, [1685486608.586190][4893:4895] CHIP:DMG: }, [1685486608.586250][4893:4895] CHIP:DMG: [1685486608.586314][4893:4895] CHIP:DMG: }, [1685486608.586372][4893:4895] CHIP:DMG: [1685486608.586413][4893:4895] CHIP:DMG: ], [1685486608.586466][4893:4895] CHIP:DMG: [1685486608.586528][4893:4895] CHIP:DMG: SuppressResponse = true, [1685486608.586629][4893:4895] CHIP:DMG: InteractionModelRevision = 1 [1685486608.586671][4893:4895] CHIP:DMG: } [1685486608.586984][4893:4895] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0005 Attribute 0x0000_FFFD DataVersion: 2770256355 [1685486608.587923][4893:4895] CHIP:TOO: ClusterRevision: 4 [1685486608.588184][4893:4895] CHIP:EM: <<< [E:29924i S:49604 M:106835748 (Ack:1039903)] (S) Msg TX to 1:0000000000000001 [DD6E] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486608.588258][4893:4895] CHIP:IN: (S) Sending msg 106835748 on secure session with LSID: 49604 [1685486608.588461][4893:4895] CHIP:EM: Flushed pending ack for MessageCounter:1039903 on exchange 29924i [1685486608.588853][4893:4893] CHIP:CTL: Shutting down the commissioner [1685486608.588907][4893:4893] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486608.588949][4893:4893] CHIP:CTL: Shutting down the controller [1685486608.588989][4893:4893] CHIP:IN: Expiring all sessions for fabric 0x1!! [1685486608.589027][4893:4893] CHIP:IN: SecureSession[0xffff8c00ae60]: MarkForEviction Type:2 LSID:49604 [1685486608.589066][4893:4893] CHIP:SC: SecureSession[0xffff8c00ae60, LSID:49604]: State change 'kActive' --> 'kPendingEviction' [1685486608.589104][4893:4893] CHIP:IN: SecureSession[0xffff8c00ae60]: Released - Type:2 LSID:49604 [1685486608.589149][4893:4893] CHIP:FP: Forgetting fabric 0x1 [1685486608.589202][4893:4893] CHIP:TS: Pending Last Known Good Time: 2023-05-26T15:09:49 [1685486608.589479][4893:4893] CHIP:TS: Previous Last Known Good Time: 2023-05-26T15:09:49 [1685486608.589525][4893:4893] CHIP:TS: Reverted Last Known Good Time to previous value [1685486608.589590][4893:4893] CHIP:CTL: Shutting down the commissioner [1685486608.589631][4893:4893] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486608.589669][4893:4893] CHIP:CTL: Shutting down the controller [1685486608.589705][4893:4893] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1685486608.591238][4893:4893] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1685486608.591390][4893:4893] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1685486608.591481][4893:4893] CHIP:FP: Shutting down FabricTable [1685486608.591536][4893:4893] CHIP:TS: Pending Last Known Good Time: 2023-05-26T15:09:49 [1685486608.591892][4893:4893] CHIP:TS: Previous Last Known Good Time: 2023-05-26T15:09:49 [1685486608.591954][4893:4893] CHIP:TS: Reverted Last Known Good Time to previous value [1685486608.592354][4893:4893] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-A05HST) [1685486608.593414][4893:4893] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486608.593524][4893:4893] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1685486608.593569][4893:4893] CHIP:DL: Inet Layer shutdown [1685486608.593606][4893:4893] CHIP:DL: BLE shutdown [1685486608.593645][4893:4893] CHIP:DL: System Layer shutdown ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ./chip-tool scenes read feature-map 1 1 [1685486618.329937][4896:4896] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1685486618.335413][4896:4896] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1685486618.335677][4896:4896] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1685486618.335867][4896:4896] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1685486618.336228][4896:4896] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-qlbUEv) [1685486618.336920][4896:4896] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486618.336978][4896:4896] CHIP:DL: NVS set: chip-counters/reboot-count = 3 (0x3) [1685486618.337808][4896:4896] CHIP:DL: Got Ethernet interface: eth0 [1685486618.338361][4896:4896] CHIP:DL: Found the primary Ethernet interface:eth0 [1685486618.338983][4896:4896] CHIP:DL: Got WiFi interface: wlan0 [1685486618.339044][4896:4896] CHIP:DL: Failed to reset WiFi statistic counts [1685486618.339096][4896:4896] CHIP:IN: UDP::Init bind&listen port=0 [1685486618.339207][4896:4896] CHIP:IN: UDP::Init bound to port=47824 [1685486618.339227][4896:4896] CHIP:IN: BLEBase::Init - setting/overriding transport [1685486618.339244][4896:4896] CHIP:IN: TransportMgr initialized [1685486618.339283][4896:4896] CHIP:FP: Initializing FabricTable from persistent storage [1685486618.339447][4896:4896] CHIP:TS: Last Known Good Time: 2023-05-26T15:09:49 [1685486618.340922][4896:4896] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xE0B91AD5E051DD6E, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1685486618.342870][4896:4896] CHIP:ZCL: Using ZAP configuration... [1685486618.346444][4896:4896] CHIP:DL: Avahi client registered [1685486618.347605][4896:4896] CHIP:CTL: System State Initialized... [1685486618.347717][4896:4896] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486618.347786][4896:4896] CHIP:CTL: Setting attestation nonce to random value [1685486618.347827][4896:4896] CHIP:CTL: Setting CSR nonce to random value [1685486618.348184][4896:4898] CHIP:DL: CHIP task running [1685486618.348393][4896:4898] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1685486618.348692][4896:4898] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486618.348745][4896:4898] CHIP:CTL: Setting attestation nonce to random value [1685486618.348912][4896:4898] CHIP:CTL: Setting CSR nonce to random value [1685486618.349793][4896:4898] CHIP:CTL: Generating NOC [1685486618.350702][4896:4898] CHIP:FP: Validating NOC chain [1685486618.352489][4896:4898] CHIP:FP: NOC chain validation successful [1685486618.352649][4896:4898] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1685486618.352680][4896:4898] CHIP:TS: Last Known Good Time: 2023-05-26T15:09:49 [1685486618.352700][4896:4898] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1685486618.352719][4896:4898] CHIP:TS: Retaining current Last Known Good Time [1685486618.356957][4896:4898] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1685486618.358654][4896:4898] CHIP:TS: Committing Last Known Good Time to storage: 2023-05-26T15:09:49 [1685486618.360214][4896:4898] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: E0B91AD5E051DD6E) [1685486618.372391][4896:4898] CHIP:TOO: Sending command to node 0x1 [1685486618.372797][4896:4898] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1685486618.372827][4896:4898] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1685486618.372860][4896:4898] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1685486618.372888][4896:4898] CHIP:DIS: Resolving E0B91AD5E051DD6E:0000000000000001 ... [1685486618.374427][4896:4898] CHIP:DL: Avahi resolve found [1685486618.374495][4896:4898] CHIP:DIS: Node ID resolved for E0B91AD5E051DD6E:0000000000000001 [1685486618.374515][4896:4898] CHIP:DIS: Hostname: 287681CAAD58 [1685486618.374537][4896:4898] CHIP:DIS: IP Address #1: fe80::2a76:81ff:feca:ad58 [1685486618.374556][4896:4898] CHIP:DIS: Port: 5540 [1685486618.374573][4896:4898] CHIP:DIS: Mrp Interval idle: 300 ms [1685486618.374591][4896:4898] CHIP:DIS: Mrp Interval active: 2000 ms [1685486618.374608][4896:4898] CHIP:DIS: TCP Supported: 1 [1685486618.374727][4896:4898] CHIP:DIS: UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540: new best score: 3 [1685486618.374750][4896:4898] CHIP:DIS: Checking node lookup status after 2 ms [1685486618.374767][4896:4898] CHIP:DIS: Keeping DNSSD lookup active [1685486618.574075][4896:4898] CHIP:DIS: Checking node lookup status after 201 ms [1685486618.574388][4896:4898] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540 while in state 2 [1685486618.574452][4896:4898] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1685486618.574671][4896:4898] CHIP:IN: SecureSession[0xffff9800ae60]: Allocated Type:2 LSID:41608 [1685486618.574767][4896:4898] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1685486618.576823][4896:4898] CHIP:EM: <<< [E:57867i S:0 M:29217307] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1685486618.577123][4896:4898] CHIP:IN: (U) Sending msg 29217307 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486618.577440][4896:4898] CHIP:SC: Sent Sigma1 msg [1685486618.577507][4896:4898] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1685486618.695834][4896:4898] CHIP:EM: >>> [E:57867i S:0 M:245487199 (Ack:29217307)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486618.695933][4896:4898] CHIP:EM: Found matching exchange: 57867i, Delegate: 0xffff9800d2d8 [1685486618.696015][4896:4898] CHIP:EM: Rxd Ack; Removing MessageCounter:29217307 from Retrans Table on exchange 57867i [1685486619.443291][4896:4898] CHIP:EM: >>> [E:57867i S:0 M:245487200 (Ack:29217307)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1685486619.443397][4896:4898] CHIP:EM: Found matching exchange: 57867i, Delegate: 0xffff9800d2d8 [1685486619.443458][4896:4898] CHIP:EM: CHIP MessageCounter:29217307 not in RetransTable on exchange 57867i [1685486619.443557][4896:4898] CHIP:SC: Received Sigma2 msg [1685486619.443642][4896:4898] CHIP:SC: Peer assigned session session ID 35480 [1685486619.453622][4896:4898] CHIP:SC: Found MRP parameters in the message [1685486619.453736][4896:4898] CHIP:SC: Sending Sigma3 [1685486619.454968][4896:4898] CHIP:EM: <<< [E:57867i S:0 M:29217308 (Ack:245487200)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1685486619.455282][4896:4898] CHIP:IN: (U) Sending msg 29217308 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486619.455602][4896:4898] CHIP:SC: Sent Sigma3 msg [1685486619.493630][4896:4898] CHIP:EM: >>> [E:57867i S:0 M:245487201 (Ack:29217308)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486619.493708][4896:4898] CHIP:EM: Found matching exchange: 57867i, Delegate: 0xffff9800d2d8 [1685486619.493776][4896:4898] CHIP:EM: Rxd Ack; Removing MessageCounter:29217308 from Retrans Table on exchange 57867i [1685486620.317314][4896:4898] CHIP:EM: >>> [E:57867i S:0 M:245487202 (Ack:29217308)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685486620.317420][4896:4898] CHIP:EM: Found matching exchange: 57867i, Delegate: 0xffff9800d2d8 [1685486620.317481][4896:4898] CHIP:EM: CHIP MessageCounter:29217308 not in RetransTable on exchange 57867i [1685486620.317584][4896:4898] CHIP:SC: Success status report received. Session was established [1685486620.324016][4896:4898] CHIP:SC: SecureSession[0xffff9800ae60, LSID:41608]: State change 'kEstablishing' --> 'kActive' [1685486620.324115][4896:4898] CHIP:IN: SecureSession[0xffff9800ae60]: Activated - Type:2 LSID:41608 [1685486620.324166][4896:4898] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:41608 PSID:35480! [1685486620.324228][4896:4898] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1685486620.324428][4896:4898] CHIP:TOO: cluster 0x0000_0005, attribute: 0x0000_FFFC, endpoint 1 [1685486620.324498][4896:4898] CHIP:TOO: Sending ReadAttribute to: [1685486620.324563][4896:4898] CHIP:DMG: SendReadRequest ReadClient[0xffff980101a0]: Sending Read Request [1685486620.324844][4896:4898] CHIP:EM: <<< [E:57868i S:41608 M:169965174] (S) Msg TX to 1:0000000000000001 [DD6E] --- Type 0001:02 (IM:ReadRequest) [1685486620.324947][4896:4898] CHIP:IN: (S) Sending msg 169965174 on secure session with LSID: 41608 [1685486620.325265][4896:4898] CHIP:DMG: MoveToState ReadClient[0xffff980101a0]: Moving to [AwaitingIn] [1685486620.325427][4896:4898] CHIP:EM: <<< [E:57867i S:0 M:29217309 (Ack:245487202)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486620.325692][4896:4898] CHIP:IN: (U) Sending msg 29217309 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486620.325866][4896:4898] CHIP:EM: Flushed pending ack for MessageCounter:245487202 on exchange 57867i [1685486620.411512][4896:4898] CHIP:EM: >>> [E:57868i S:41608 M:139347766 (Ack:169965174)] (S) Msg RX from 1:0000000000000001 [DD6E] --- Type 0001:05 (IM:ReportData) [1685486620.411608][4896:4898] CHIP:EM: Found matching exchange: 57868i, Delegate: 0xffff980101b0 [1685486620.411681][4896:4898] CHIP:EM: Rxd Ack; Removing MessageCounter:169965174 from Retrans Table on exchange 57868i [1685486620.411835][4896:4898] CHIP:DMG: ReportDataMessage = [1685486620.411894][4896:4898] CHIP:DMG: { [1685486620.411937][4896:4898] CHIP:DMG: AttributeReportIBs = [1685486620.412000][4896:4898] CHIP:DMG: [ [1685486620.412049][4896:4898] CHIP:DMG: AttributeReportIB = [1685486620.412114][4896:4898] CHIP:DMG: { [1685486620.412167][4896:4898] CHIP:DMG: AttributeDataIB = [1685486620.412228][4896:4898] CHIP:DMG: { [1685486620.412292][4896:4898] CHIP:DMG: DataVersion = 0xa51ec1e3, [1685486620.412353][4896:4898] CHIP:DMG: AttributePathIB = [1685486620.412417][4896:4898] CHIP:DMG: { [1685486620.412481][4896:4898] CHIP:DMG: Endpoint = 0x1, [1685486620.412545][4896:4898] CHIP:DMG: Cluster = 0x5, [1685486620.412614][4896:4898] CHIP:DMG: Attribute = 0x0000_FFFC, [1685486620.412678][4896:4898] CHIP:DMG: } [1685486620.412745][4896:4898] CHIP:DMG: [1685486620.412811][4896:4898] CHIP:DMG: Data = 1, [1685486620.412870][4896:4898] CHIP:DMG: }, [1685486620.412933][4896:4898] CHIP:DMG: [1685486620.412984][4896:4898] CHIP:DMG: }, [1685486620.413044][4896:4898] CHIP:DMG: [1685486620.413092][4896:4898] CHIP:DMG: ], [1685486620.413151][4896:4898] CHIP:DMG: [1685486620.413200][4896:4898] CHIP:DMG: SuppressResponse = true, [1685486620.413250][4896:4898] CHIP:DMG: InteractionModelRevision = 1 [1685486620.413295][4896:4898] CHIP:DMG: } [1685486620.413556][4896:4898] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0005 Attribute 0x0000_FFFC DataVersion: 2770256355 [1685486620.413659][4896:4898] CHIP:TOO: FeatureMap: 1 [1685486620.413904][4896:4898] CHIP:EM: <<< [E:57868i S:41608 M:169965175 (Ack:139347766)] (S) Msg TX to 1:0000000000000001 [DD6E] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486620.413984][4896:4898] CHIP:IN: (S) Sending msg 169965175 on secure session with LSID: 41608 [1685486620.414178][4896:4898] CHIP:EM: Flushed pending ack for MessageCounter:139347766 on exchange 57868i [1685486620.414502][4896:4896] CHIP:CTL: Shutting down the commissioner [1685486620.414565][4896:4896] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486620.414614][4896:4896] CHIP:CTL: Shutting down the controller [1685486620.414660][4896:4896] CHIP:IN: Expiring all sessions for fabric 0x1!! [1685486620.414702][4896:4896] CHIP:IN: SecureSession[0xffff9800ae60]: MarkForEviction Type:2 LSID:41608 [1685486620.414748][4896:4896] CHIP:SC: SecureSession[0xffff9800ae60, LSID:41608]: State change 'kActive' --> 'kPendingEviction' [1685486620.414790][4896:4896] CHIP:IN: SecureSession[0xffff9800ae60]: Released - Type:2 LSID:41608 [1685486620.414841][4896:4896] CHIP:FP: Forgetting fabric 0x1 [1685486620.414903][4896:4896] CHIP:TS: Pending Last Known Good Time: 2023-05-26T15:09:49 [1685486620.415180][4896:4896] CHIP:TS: Previous Last Known Good Time: 2023-05-26T15:09:49 [1685486620.415231][4896:4896] CHIP:TS: Reverted Last Known Good Time to previous value [1685486620.415309][4896:4896] CHIP:CTL: Shutting down the commissioner [1685486620.415356][4896:4896] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486620.415401][4896:4896] CHIP:CTL: Shutting down the controller [1685486620.415432][4896:4896] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1685486620.417043][4896:4896] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1685486620.417181][4896:4896] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1685486620.417265][4896:4896] CHIP:FP: Shutting down FabricTable [1685486620.417317][4896:4896] CHIP:TS: Pending Last Known Good Time: 2023-05-26T15:09:49 [1685486620.417508][4896:4896] CHIP:TS: Previous Last Known Good Time: 2023-05-26T15:09:49 [1685486620.417564][4896:4896] CHIP:TS: Reverted Last Known Good Time to previous value [1685486620.417921][4896:4896] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-Okmk5C) [1685486620.418901][4896:4896] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486620.419004][4896:4896] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1685486620.419044][4896:4896] CHIP:DL: Inet Layer shutdown [1685486620.419077][4896:4896] CHIP:DL: BLE shutdown [1685486620.419111][4896:4896] CHIP:DL: System Layer shutdown ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ./chip-tool scenes read attribute-list 1 1 [1685486633.218233][4901:4901] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1685486633.223856][4901:4901] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1685486633.224113][4901:4901] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1685486633.224218][4901:4901] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1685486633.224552][4901:4901] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-MqTeIP) [1685486633.225165][4901:4901] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486633.225238][4901:4901] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4) [1685486633.226184][4901:4901] CHIP:DL: Got Ethernet interface: eth0 [1685486633.226713][4901:4901] CHIP:DL: Found the primary Ethernet interface:eth0 [1685486633.227260][4901:4901] CHIP:DL: Got WiFi interface: wlan0 [1685486633.227319][4901:4901] CHIP:DL: Failed to reset WiFi statistic counts [1685486633.227374][4901:4901] CHIP:IN: UDP::Init bind&listen port=0 [1685486633.227475][4901:4901] CHIP:IN: UDP::Init bound to port=46507 [1685486633.227495][4901:4901] CHIP:IN: BLEBase::Init - setting/overriding transport [1685486633.227511][4901:4901] CHIP:IN: TransportMgr initialized [1685486633.227542][4901:4901] CHIP:FP: Initializing FabricTable from persistent storage [1685486633.227689][4901:4901] CHIP:TS: Last Known Good Time: 2023-05-26T15:09:49 [1685486633.229170][4901:4901] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xE0B91AD5E051DD6E, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1685486633.231042][4901:4901] CHIP:ZCL: Using ZAP configuration... [1685486633.234656][4901:4901] CHIP:DL: Avahi client registered [1685486633.235795][4901:4901] CHIP:CTL: System State Initialized... [1685486633.235919][4901:4901] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486633.235965][4901:4901] CHIP:CTL: Setting attestation nonce to random value [1685486633.236004][4901:4901] CHIP:CTL: Setting CSR nonce to random value [1685486633.236305][4901:4903] CHIP:DL: CHIP task running [1685486633.236510][4901:4903] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1685486633.236809][4901:4903] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486633.236862][4901:4903] CHIP:CTL: Setting attestation nonce to random value [1685486633.237027][4901:4903] CHIP:CTL: Setting CSR nonce to random value [1685486633.237913][4901:4903] CHIP:CTL: Generating NOC [1685486633.238814][4901:4903] CHIP:FP: Validating NOC chain [1685486633.240603][4901:4903] CHIP:FP: NOC chain validation successful [1685486633.240766][4901:4903] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1685486633.240797][4901:4903] CHIP:TS: Last Known Good Time: 2023-05-26T15:09:49 [1685486633.240818][4901:4903] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1685486633.240836][4901:4903] CHIP:TS: Retaining current Last Known Good Time [1685486633.245193][4901:4903] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1685486633.246905][4901:4903] CHIP:TS: Committing Last Known Good Time to storage: 2023-05-26T15:09:49 [1685486633.248550][4901:4903] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: E0B91AD5E051DD6E) [1685486633.285110][4901:4903] CHIP:TOO: Sending command to node 0x1 [1685486633.285732][4901:4903] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1685486633.285778][4901:4903] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1685486633.285823][4901:4903] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1685486633.285865][4901:4903] CHIP:DIS: Resolving E0B91AD5E051DD6E:0000000000000001 ... [1685486633.288196][4901:4903] CHIP:DL: Avahi resolve found [1685486633.288289][4901:4903] CHIP:DIS: Node ID resolved for E0B91AD5E051DD6E:0000000000000001 [1685486633.288321][4901:4903] CHIP:DIS: Hostname: 287681CAAD58 [1685486633.288357][4901:4903] CHIP:DIS: IP Address #1: fe80::2a76:81ff:feca:ad58 [1685486633.288387][4901:4903] CHIP:DIS: Port: 5540 [1685486633.288417][4901:4903] CHIP:DIS: Mrp Interval idle: 300 ms [1685486633.288446][4901:4903] CHIP:DIS: Mrp Interval active: 2000 ms [1685486633.288474][4901:4903] CHIP:DIS: TCP Supported: 1 [1685486633.288636][4901:4903] CHIP:DIS: UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540: new best score: 3 [1685486633.288671][4901:4903] CHIP:DIS: Checking node lookup status after 2 ms [1685486633.288697][4901:4903] CHIP:DIS: Keeping DNSSD lookup active [1685486633.486427][4901:4903] CHIP:DIS: Checking node lookup status after 200 ms [1685486633.486727][4901:4903] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540 while in state 2 [1685486633.486791][4901:4903] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1685486633.487008][4901:4903] CHIP:IN: SecureSession[0xffff7c00ae60]: Allocated Type:2 LSID:12059 [1685486633.487103][4901:4903] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1685486633.489137][4901:4903] CHIP:EM: <<< [E:55739i S:0 M:89904338] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1685486633.489439][4901:4903] CHIP:IN: (U) Sending msg 89904338 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486633.489760][4901:4903] CHIP:SC: Sent Sigma1 msg [1685486633.489829][4901:4903] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1685486633.620699][4901:4903] CHIP:EM: >>> [E:55739i S:0 M:245487203 (Ack:89904338)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486633.620786][4901:4903] CHIP:EM: Found matching exchange: 55739i, Delegate: 0xffff7c00d2d8 [1685486633.620859][4901:4903] CHIP:EM: Rxd Ack; Removing MessageCounter:89904338 from Retrans Table on exchange 55739i [1685486634.419973][4901:4903] CHIP:EM: >>> [E:55739i S:0 M:245487204 (Ack:89904338)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1685486634.420076][4901:4903] CHIP:EM: Found matching exchange: 55739i, Delegate: 0xffff7c00d2d8 [1685486634.420138][4901:4903] CHIP:EM: CHIP MessageCounter:89904338 not in RetransTable on exchange 55739i [1685486634.420237][4901:4903] CHIP:SC: Received Sigma2 msg [1685486634.420320][4901:4903] CHIP:SC: Peer assigned session session ID 35481 [1685486634.430238][4901:4903] CHIP:SC: Found MRP parameters in the message [1685486634.430355][4901:4903] CHIP:SC: Sending Sigma3 [1685486634.431605][4901:4903] CHIP:EM: <<< [E:55739i S:0 M:89904339 (Ack:245487204)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1685486634.431960][4901:4903] CHIP:IN: (U) Sending msg 89904339 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486634.432288][4901:4903] CHIP:SC: Sent Sigma3 msg [1685486634.479863][4901:4903] CHIP:EM: >>> [E:55739i S:0 M:245487205 (Ack:89904339)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486634.479958][4901:4903] CHIP:EM: Found matching exchange: 55739i, Delegate: 0xffff7c00d2d8 [1685486634.480039][4901:4903] CHIP:EM: Rxd Ack; Removing MessageCounter:89904339 from Retrans Table on exchange 55739i [1685486635.285609][4901:4903] CHIP:EM: >>> [E:55739i S:0 M:245487206 (Ack:89904339)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685486635.285714][4901:4903] CHIP:EM: Found matching exchange: 55739i, Delegate: 0xffff7c00d2d8 [1685486635.285774][4901:4903] CHIP:EM: CHIP MessageCounter:89904339 not in RetransTable on exchange 55739i [1685486635.285874][4901:4903] CHIP:SC: Success status report received. Session was established [1685486635.292681][4901:4903] CHIP:SC: SecureSession[0xffff7c00ae60, LSID:12059]: State change 'kEstablishing' --> 'kActive' [1685486635.292780][4901:4903] CHIP:IN: SecureSession[0xffff7c00ae60]: Activated - Type:2 LSID:12059 [1685486635.293005][4901:4903] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:12059 PSID:35481! [1685486635.293073][4901:4903] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1685486635.293282][4901:4903] CHIP:TOO: cluster 0x0000_0005, attribute: 0x0000_FFFB, endpoint 1 [1685486635.293359][4901:4903] CHIP:TOO: Sending ReadAttribute to: [1685486635.293429][4901:4903] CHIP:DMG: SendReadRequest ReadClient[0xffff7c0101a0]: Sending Read Request [1685486635.293712][4901:4903] CHIP:EM: <<< [E:55740i S:12059 M:139370815] (S) Msg TX to 1:0000000000000001 [DD6E] --- Type 0001:02 (IM:ReadRequest) [1685486635.293811][4901:4903] CHIP:IN: (S) Sending msg 139370815 on secure session with LSID: 12059 [1685486635.294111][4901:4903] CHIP:DMG: MoveToState ReadClient[0xffff7c0101a0]: Moving to [AwaitingIn] [1685486635.294267][4901:4903] CHIP:EM: <<< [E:55739i S:0 M:89904340 (Ack:245487206)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486635.294532][4901:4903] CHIP:IN: (U) Sending msg 89904340 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486635.294711][4901:4903] CHIP:EM: Flushed pending ack for MessageCounter:245487206 on exchange 55739i [1685486635.381338][4901:4903] CHIP:EM: >>> [E:55740i S:12059 M:225645842 (Ack:139370815)] (S) Msg RX from 1:0000000000000001 [DD6E] --- Type 0001:05 (IM:ReportData) [1685486635.381438][4901:4903] CHIP:EM: Found matching exchange: 55740i, Delegate: 0xffff7c0101b0 [1685486635.381523][4901:4903] CHIP:EM: Rxd Ack; Removing MessageCounter:139370815 from Retrans Table on exchange 55740i [1685486635.381666][4901:4903] CHIP:DMG: ReportDataMessage = [1685486635.381732][4901:4903] CHIP:DMG: { [1685486635.381782][4901:4903] CHIP:DMG: AttributeReportIBs = [1685486635.381869][4901:4903] CHIP:DMG: [ [1685486635.381926][4901:4903] CHIP:DMG: AttributeReportIB = [1685486635.382017][4901:4903] CHIP:DMG: { [1685486635.382078][4901:4903] CHIP:DMG: AttributeDataIB = [1685486635.382167][4901:4903] CHIP:DMG: { [1685486635.382245][4901:4903] CHIP:DMG: DataVersion = 0xa51ec1e3, [1685486635.382337][4901:4903] CHIP:DMG: AttributePathIB = [1685486635.382431][4901:4903] CHIP:DMG: { [1685486635.382525][4901:4903] CHIP:DMG: Endpoint = 0x1, [1685486635.382624][4901:4903] CHIP:DMG: Cluster = 0x5, [1685486635.382722][4901:4903] CHIP:DMG: Attribute = 0x0000_FFFB, [1685486635.382814][4901:4903] CHIP:DMG: } [1685486635.382909][4901:4903] CHIP:DMG: [1685486635.382999][4901:4903] CHIP:DMG: Data = [ [1685486635.383175][4901:4903] CHIP:DMG: 0, 1, 2, 3, 4, 5, 6, 7, 65528, 65529, 65530, 65531, 65532, 65533, [1685486635.383286][4901:4903] CHIP:DMG: ], [1685486635.383375][4901:4903] CHIP:DMG: }, [1685486635.383472][4901:4903] CHIP:DMG: [1685486635.383533][4901:4903] CHIP:DMG: }, [1685486635.383617][4901:4903] CHIP:DMG: [1685486635.383671][4901:4903] CHIP:DMG: ], [1685486635.383809][4901:4903] CHIP:DMG: [1685486635.383875][4901:4903] CHIP:DMG: SuppressResponse = true, [1685486635.383933][4901:4903] CHIP:DMG: InteractionModelRevision = 1 [1685486635.383987][4901:4903] CHIP:DMG: } [1685486635.384640][4901:4903] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0005 Attribute 0x0000_FFFB DataVersion: 2770256355 [1685486635.384815][4901:4903] CHIP:TOO: AttributeList: 14 entries [1685486635.384941][4901:4903] CHIP:TOO: [1]: 0 [1685486635.385007][4901:4903] CHIP:TOO: [2]: 1 [1685486635.385063][4901:4903] CHIP:TOO: [3]: 2 [1685486635.385118][4901:4903] CHIP:TOO: [4]: 3 [1685486635.385173][4901:4903] CHIP:TOO: [5]: 4 [1685486635.385228][4901:4903] CHIP:TOO: [6]: 5 [1685486635.385283][4901:4903] CHIP:TOO: [7]: 6 [1685486635.385338][4901:4903] CHIP:TOO: [8]: 7 [1685486635.385394][4901:4903] CHIP:TOO: [9]: 65528 [1685486635.385451][4901:4903] CHIP:TOO: [10]: 65529 [1685486635.385507][4901:4903] CHIP:TOO: [11]: 65530 [1685486635.385563][4901:4903] CHIP:TOO: [12]: 65531 [1685486635.385618][4901:4903] CHIP:TOO: [13]: 65532 [1685486635.385673][4901:4903] CHIP:TOO: [14]: 65533 [1685486635.385974][4901:4903] CHIP:EM: <<< [E:55740i S:12059 M:139370816 (Ack:225645842)] (S) Msg TX to 1:0000000000000001 [DD6E] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486635.386070][4901:4903] CHIP:IN: (S) Sending msg 139370816 on secure session with LSID: 12059 [1685486635.386295][4901:4903] CHIP:EM: Flushed pending ack for MessageCounter:225645842 on exchange 55740i [1685486635.386684][4901:4901] CHIP:CTL: Shutting down the commissioner [1685486635.386764][4901:4901] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486635.386820][4901:4901] CHIP:CTL: Shutting down the controller [1685486635.386875][4901:4901] CHIP:IN: Expiring all sessions for fabric 0x1!! [1685486635.386925][4901:4901] CHIP:IN: SecureSession[0xffff7c00ae60]: MarkForEviction Type:2 LSID:12059 [1685486635.386977][4901:4901] CHIP:SC: SecureSession[0xffff7c00ae60, LSID:12059]: State change 'kActive' --> 'kPendingEviction' [1685486635.387028][4901:4901] CHIP:IN: SecureSession[0xffff7c00ae60]: Released - Type:2 LSID:12059 [1685486635.387087][4901:4901] CHIP:FP: Forgetting fabric 0x1 [1685486635.387156][4901:4901] CHIP:TS: Pending Last Known Good Time: 2023-05-26T15:09:49 [1685486635.387480][4901:4901] CHIP:TS: Previous Last Known Good Time: 2023-05-26T15:09:49 [1685486635.387542][4901:4901] CHIP:TS: Reverted Last Known Good Time to previous value [1685486635.387632][4901:4901] CHIP:CTL: Shutting down the commissioner [1685486635.387682][4901:4901] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486635.387733][4901:4901] CHIP:CTL: Shutting down the controller [1685486635.387831][4901:4901] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1685486635.389904][4901:4901] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1685486635.390109][4901:4901] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1685486635.390238][4901:4901] CHIP:FP: Shutting down FabricTable [1685486635.390310][4901:4901] CHIP:TS: Pending Last Known Good Time: 2023-05-26T15:09:49 [1685486635.390570][4901:4901] CHIP:TS: Previous Last Known Good Time: 2023-05-26T15:09:49 [1685486635.390642][4901:4901] CHIP:TS: Reverted Last Known Good Time to previous value [1685486635.391048][4901:4901] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-rZPKfJ) [1685486635.392012][4901:4901] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486635.392095][4901:4901] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1685486635.392120][4901:4901] CHIP:DL: Inet Layer shutdown [1685486635.392140][4901:4901] CHIP:DL: BLE shutdown [1685486635.392160][4901:4901] CHIP:DL: System Layer shutdown ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ./chip-tool scenes read event-list 1 1 [1685486640.957387][4904:4904] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1685486640.962869][4904:4904] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1685486640.963138][4904:4904] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1685486640.963245][4904:4904] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1685486640.963561][4904:4904] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-C6ltEY) [1685486640.964195][4904:4904] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486640.964253][4904:4904] CHIP:DL: NVS set: chip-counters/reboot-count = 5 (0x5) [1685486640.965166][4904:4904] CHIP:DL: Got Ethernet interface: eth0 [1685486640.965696][4904:4904] CHIP:DL: Found the primary Ethernet interface:eth0 [1685486640.966250][4904:4904] CHIP:DL: Got WiFi interface: wlan0 [1685486640.966313][4904:4904] CHIP:DL: Failed to reset WiFi statistic counts [1685486640.966365][4904:4904] CHIP:IN: UDP::Init bind&listen port=0 [1685486640.966465][4904:4904] CHIP:IN: UDP::Init bound to port=51765 [1685486640.966486][4904:4904] CHIP:IN: BLEBase::Init - setting/overriding transport [1685486640.966502][4904:4904] CHIP:IN: TransportMgr initialized [1685486640.966533][4904:4904] CHIP:FP: Initializing FabricTable from persistent storage [1685486640.966680][4904:4904] CHIP:TS: Last Known Good Time: 2023-05-26T15:09:49 [1685486640.968152][4904:4904] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xE0B91AD5E051DD6E, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1685486640.970083][4904:4904] CHIP:ZCL: Using ZAP configuration... [1685486640.973795][4904:4904] CHIP:DL: Avahi client registered [1685486640.974852][4904:4904] CHIP:CTL: System State Initialized... [1685486640.974964][4904:4904] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486640.975012][4904:4904] CHIP:CTL: Setting attestation nonce to random value [1685486640.975052][4904:4904] CHIP:CTL: Setting CSR nonce to random value [1685486640.975387][4904:4906] CHIP:DL: CHIP task running [1685486640.975592][4904:4906] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1685486640.975934][4904:4906] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486640.975993][4904:4906] CHIP:CTL: Setting attestation nonce to random value [1685486640.976168][4904:4906] CHIP:CTL: Setting CSR nonce to random value [1685486640.977116][4904:4906] CHIP:CTL: Generating NOC [1685486640.978064][4904:4906] CHIP:FP: Validating NOC chain [1685486640.979968][4904:4906] CHIP:FP: NOC chain validation successful [1685486640.980134][4904:4906] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1685486640.980167][4904:4906] CHIP:TS: Last Known Good Time: 2023-05-26T15:09:49 [1685486640.980189][4904:4906] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1685486640.980209][4904:4906] CHIP:TS: Retaining current Last Known Good Time [1685486640.984802][4904:4906] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1685486640.986500][4904:4906] CHIP:TS: Committing Last Known Good Time to storage: 2023-05-26T15:09:49 [1685486640.988053][4904:4906] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: E0B91AD5E051DD6E) [1685486641.000182][4904:4906] CHIP:TOO: Sending command to node 0x1 [1685486641.000594][4904:4906] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1685486641.000625][4904:4906] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1685486641.000658][4904:4906] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1685486641.000686][4904:4906] CHIP:DIS: Resolving E0B91AD5E051DD6E:0000000000000001 ... [1685486641.002291][4904:4906] CHIP:DL: Avahi resolve found [1685486641.002361][4904:4906] CHIP:DIS: Node ID resolved for E0B91AD5E051DD6E:0000000000000001 [1685486641.002381][4904:4906] CHIP:DIS: Hostname: 287681CAAD58 [1685486641.002403][4904:4906] CHIP:DIS: IP Address #1: fe80::2a76:81ff:feca:ad58 [1685486641.002422][4904:4906] CHIP:DIS: Port: 5540 [1685486641.002440][4904:4906] CHIP:DIS: Mrp Interval idle: 300 ms [1685486641.002458][4904:4906] CHIP:DIS: Mrp Interval active: 2000 ms [1685486641.002475][4904:4906] CHIP:DIS: TCP Supported: 1 [1685486641.002596][4904:4906] CHIP:DIS: UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540: new best score: 3 [1685486641.002619][4904:4906] CHIP:DIS: Checking node lookup status after 2 ms [1685486641.002635][4904:4906] CHIP:DIS: Keeping DNSSD lookup active [1685486641.200891][4904:4906] CHIP:DIS: Checking node lookup status after 201 ms [1685486641.201203][4904:4906] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540 while in state 2 [1685486641.201267][4904:4906] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1685486641.201486][4904:4906] CHIP:IN: SecureSession[0xffffa800ae60]: Allocated Type:2 LSID:21067 [1685486641.201581][4904:4906] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1685486641.203530][4904:4906] CHIP:EM: <<< [E:60030i S:0 M:206522841] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1685486641.203912][4904:4906] CHIP:IN: (U) Sending msg 206522841 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486641.204237][4904:4906] CHIP:SC: Sent Sigma1 msg [1685486641.204302][4904:4906] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1685486641.446434][4904:4906] CHIP:EM: >>> [E:60030i S:0 M:245487207 (Ack:206522841)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486641.446527][4904:4906] CHIP:EM: Found matching exchange: 60030i, Delegate: 0xffffa800d2d8 [1685486641.446602][4904:4906] CHIP:EM: Rxd Ack; Removing MessageCounter:206522841 from Retrans Table on exchange 60030i [1685486642.266536][4904:4906] CHIP:EM: >>> [E:60030i S:0 M:245487208 (Ack:206522841)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1685486642.266641][4904:4906] CHIP:EM: Found matching exchange: 60030i, Delegate: 0xffffa800d2d8 [1685486642.266703][4904:4906] CHIP:EM: CHIP MessageCounter:206522841 not in RetransTable on exchange 60030i [1685486642.266803][4904:4906] CHIP:SC: Received Sigma2 msg [1685486642.266886][4904:4906] CHIP:SC: Peer assigned session session ID 35482 [1685486642.275372][4904:4906] CHIP:SC: Found MRP parameters in the message [1685486642.275447][4904:4906] CHIP:SC: Sending Sigma3 [1685486642.276232][4904:4906] CHIP:EM: <<< [E:60030i S:0 M:206522842 (Ack:245487208)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1685486642.276431][4904:4906] CHIP:IN: (U) Sending msg 206522842 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486642.276632][4904:4906] CHIP:SC: Sent Sigma3 msg [1685486642.446295][4904:4906] CHIP:EM: >>> [E:60030i S:0 M:245487209 (Ack:206522842)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486642.446399][4904:4906] CHIP:EM: Found matching exchange: 60030i, Delegate: 0xffffa800d2d8 [1685486642.446482][4904:4906] CHIP:EM: Rxd Ack; Removing MessageCounter:206522842 from Retrans Table on exchange 60030i [1685486643.279173][4904:4906] CHIP:EM: >>> [E:60030i S:0 M:245487210 (Ack:206522842)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685486643.279280][4904:4906] CHIP:EM: Found matching exchange: 60030i, Delegate: 0xffffa800d2d8 [1685486643.279342][4904:4906] CHIP:EM: CHIP MessageCounter:206522842 not in RetransTable on exchange 60030i [1685486643.279444][4904:4906] CHIP:SC: Success status report received. Session was established [1685486643.288358][4904:4906] CHIP:SC: SecureSession[0xffffa800ae60, LSID:21067]: State change 'kEstablishing' --> 'kActive' [1685486643.288441][4904:4906] CHIP:IN: SecureSession[0xffffa800ae60]: Activated - Type:2 LSID:21067 [1685486643.288482][4904:4906] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:21067 PSID:35482! [1685486643.288531][4904:4906] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1685486643.288706][4904:4906] CHIP:TOO: cluster 0x0000_0005, attribute: 0x0000_FFFA, endpoint 1 [1685486643.288764][4904:4906] CHIP:TOO: Sending ReadAttribute to: [1685486643.288818][4904:4906] CHIP:DMG: SendReadRequest ReadClient[0xffffa80101a0]: Sending Read Request [1685486643.289057][4904:4906] CHIP:EM: <<< [E:60031i S:21067 M:8808714] (S) Msg TX to 1:0000000000000001 [DD6E] --- Type 0001:02 (IM:ReadRequest) [1685486643.289134][4904:4906] CHIP:IN: (S) Sending msg 8808714 on secure session with LSID: 21067 [1685486643.289378][4904:4906] CHIP:DMG: MoveToState ReadClient[0xffffa80101a0]: Moving to [AwaitingIn] [1685486643.289505][4904:4906] CHIP:EM: <<< [E:60030i S:0 M:206522843 (Ack:245487210)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486643.289718][4904:4906] CHIP:IN: (U) Sending msg 206522843 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486643.289866][4904:4906] CHIP:EM: Flushed pending ack for MessageCounter:245487210 on exchange 60030i [1685486643.415314][4904:4906] CHIP:EM: >>> [E:60031i S:21067 M:134772543 (Ack:8808714)] (S) Msg RX from 1:0000000000000001 [DD6E] --- Type 0001:05 (IM:ReportData) [1685486643.415414][4904:4906] CHIP:EM: Found matching exchange: 60031i, Delegate: 0xffffa80101b0 [1685486643.415495][4904:4906] CHIP:EM: Rxd Ack; Removing MessageCounter:8808714 from Retrans Table on exchange 60031i [1685486643.415627][4904:4906] CHIP:DMG: ReportDataMessage = [1685486643.415701][4904:4906] CHIP:DMG: { [1685486643.415801][4904:4906] CHIP:DMG: AttributeReportIBs = [1685486643.415883][4904:4906] CHIP:DMG: [ [1685486643.415941][4904:4906] CHIP:DMG: AttributeReportIB = [1685486643.416019][4904:4906] CHIP:DMG: { [1685486643.416081][4904:4906] CHIP:DMG: AttributeDataIB = [1685486643.416171][4904:4906] CHIP:DMG: { [1685486643.416259][4904:4906] CHIP:DMG: DataVersion = 0xa51ec1e3, [1685486643.416349][4904:4906] CHIP:DMG: AttributePathIB = [1685486643.416443][4904:4906] CHIP:DMG: { [1685486643.416530][4904:4906] CHIP:DMG: Endpoint = 0x1, [1685486643.416629][4904:4906] CHIP:DMG: Cluster = 0x5, [1685486643.416720][4904:4906] CHIP:DMG: Attribute = 0x0000_FFFA, [1685486643.416796][4904:4906] CHIP:DMG: } [1685486643.416875][4904:4906] CHIP:DMG: [1685486643.416950][4904:4906] CHIP:DMG: Data = [ [1685486643.417023][4904:4906] CHIP:DMG: [1685486643.417104][4904:4906] CHIP:DMG: ], [1685486643.417175][4904:4906] CHIP:DMG: }, [1685486643.417251][4904:4906] CHIP:DMG: [1685486643.417311][4904:4906] CHIP:DMG: }, [1685486643.417382][4904:4906] CHIP:DMG: [1685486643.417437][4904:4906] CHIP:DMG: ], [1685486643.417508][4904:4906] CHIP:DMG: [1685486643.417566][4904:4906] CHIP:DMG: SuppressResponse = true, [1685486643.417624][4904:4906] CHIP:DMG: InteractionModelRevision = 1 [1685486643.417677][4904:4906] CHIP:DMG: } [1685486643.418022][4904:4906] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0005 Attribute 0x0000_FFFA DataVersion: 2770256355 [1685486643.418161][4904:4906] CHIP:TOO: EventList: 0 entries [1685486643.418449][4904:4906] CHIP:EM: <<< [E:60031i S:21067 M:8808715 (Ack:134772543)] (S) Msg TX to 1:0000000000000001 [DD6E] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486643.418544][4904:4906] CHIP:IN: (S) Sending msg 8808715 on secure session with LSID: 21067 [1685486643.418760][4904:4906] CHIP:EM: Flushed pending ack for MessageCounter:134772543 on exchange 60031i [1685486643.419156][4904:4904] CHIP:CTL: Shutting down the commissioner [1685486643.419228][4904:4904] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486643.419395][4904:4904] CHIP:CTL: Shutting down the controller [1685486643.419515][4904:4904] CHIP:IN: Expiring all sessions for fabric 0x1!! [1685486643.419573][4904:4904] CHIP:IN: SecureSession[0xffffa800ae60]: MarkForEviction Type:2 LSID:21067 [1685486643.419626][4904:4904] CHIP:SC: SecureSession[0xffffa800ae60, LSID:21067]: State change 'kActive' --> 'kPendingEviction' [1685486643.419704][4904:4904] CHIP:IN: SecureSession[0xffffa800ae60]: Released - Type:2 LSID:21067 [1685486643.419809][4904:4904] CHIP:FP: Forgetting fabric 0x1 [1685486643.419882][4904:4904] CHIP:TS: Pending Last Known Good Time: 2023-05-26T15:09:49 [1685486643.420227][4904:4904] CHIP:TS: Previous Last Known Good Time: 2023-05-26T15:09:49 [1685486643.420380][4904:4904] CHIP:TS: Reverted Last Known Good Time to previous value [1685486643.420473][4904:4904] CHIP:CTL: Shutting down the commissioner [1685486643.420547][4904:4904] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486643.420600][4904:4904] CHIP:CTL: Shutting down the controller [1685486643.420646][4904:4904] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1685486643.422700][4904:4904] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1685486643.422883][4904:4904] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1685486643.422993][4904:4904] CHIP:FP: Shutting down FabricTable [1685486643.423065][4904:4904] CHIP:TS: Pending Last Known Good Time: 2023-05-26T15:09:49 [1685486643.423356][4904:4904] CHIP:TS: Previous Last Known Good Time: 2023-05-26T15:09:49 [1685486643.423435][4904:4904] CHIP:TS: Reverted Last Known Good Time to previous value [1685486643.423938][4904:4904] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-wwtT1q) [1685486643.425564][4904:4904] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486643.425703][4904:4904] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1685486643.425762][4904:4904] CHIP:DL: Inet Layer shutdown [1685486643.425812][4904:4904] CHIP:DL: BLE shutdown [1685486643.425863][4904:4904] CHIP:DL: System Layer shutdown ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ubuntu@ManognaTHpi:~/apps$ ./chip-tool scenes read accepted-command-list 1 1 [1685486647.309073][4909:4909] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1685486647.314555][4909:4909] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1685486647.314816][4909:4909] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1685486647.314927][4909:4909] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1685486647.315251][4909:4909] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-tzYxsb) [1685486647.315876][4909:4909] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486647.315931][4909:4909] CHIP:DL: NVS set: chip-counters/reboot-count = 6 (0x6) [1685486647.316754][4909:4909] CHIP:DL: Got Ethernet interface: eth0 [1685486647.317284][4909:4909] CHIP:DL: Found the primary Ethernet interface:eth0 [1685486647.317820][4909:4909] CHIP:DL: Got WiFi interface: wlan0 [1685486647.317886][4909:4909] CHIP:DL: Failed to reset WiFi statistic counts [1685486647.317942][4909:4909] CHIP:IN: UDP::Init bind&listen port=0 [1685486647.318045][4909:4909] CHIP:IN: UDP::Init bound to port=58878 [1685486647.318066][4909:4909] CHIP:IN: BLEBase::Init - setting/overriding transport [1685486647.318082][4909:4909] CHIP:IN: TransportMgr initialized [1685486647.318113][4909:4909] CHIP:FP: Initializing FabricTable from persistent storage [1685486647.318256][4909:4909] CHIP:TS: Last Known Good Time: 2023-05-26T15:09:49 [1685486647.319687][4909:4909] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xE0B91AD5E051DD6E, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1685486647.321668][4909:4909] CHIP:ZCL: Using ZAP configuration... [1685486647.325243][4909:4909] CHIP:DL: Avahi client registered [1685486647.326373][4909:4909] CHIP:CTL: System State Initialized... [1685486647.326482][4909:4909] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486647.326524][4909:4909] CHIP:CTL: Setting attestation nonce to random value [1685486647.326557][4909:4909] CHIP:CTL: Setting CSR nonce to random value [1685486647.326860][4909:4911] CHIP:DL: CHIP task running [1685486647.327045][4909:4911] CHIP:DL: HandlePlatformSpecificBLEEvent 32784 [1685486647.327328][4909:4911] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486647.327377][4909:4911] CHIP:CTL: Setting attestation nonce to random value [1685486647.327527][4909:4911] CHIP:CTL: Setting CSR nonce to random value [1685486647.328378][4909:4911] CHIP:CTL: Generating NOC [1685486647.329218][4909:4911] CHIP:FP: Validating NOC chain [1685486647.331304][4909:4911] CHIP:FP: NOC chain validation successful [1685486647.331538][4909:4911] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1685486647.331580][4909:4911] CHIP:TS: Last Known Good Time: 2023-05-26T15:09:49 [1685486647.331608][4909:4911] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1685486647.331634][4909:4911] CHIP:TS: Retaining current Last Known Good Time [1685486647.337196][4909:4911] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1685486647.339462][4909:4911] CHIP:TS: Committing Last Known Good Time to storage: 2023-05-26T15:09:49 [1685486647.341530][4909:4911] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: E0B91AD5E051DD6E) [1685486647.353689][4909:4911] CHIP:TOO: Sending command to node 0x1 [1685486647.354098][4909:4911] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1685486647.354127][4909:4911] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1685486647.354160][4909:4911] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1685486647.354190][4909:4911] CHIP:DIS: Resolving E0B91AD5E051DD6E:0000000000000001 ... [1685486647.355802][4909:4911] CHIP:DL: Avahi resolve found [1685486647.355873][4909:4911] CHIP:DIS: Node ID resolved for E0B91AD5E051DD6E:0000000000000001 [1685486647.355893][4909:4911] CHIP:DIS: Hostname: 287681CAAD58 [1685486647.355916][4909:4911] CHIP:DIS: IP Address #1: fe80::2a76:81ff:feca:ad58 [1685486647.355935][4909:4911] CHIP:DIS: Port: 5540 [1685486647.355953][4909:4911] CHIP:DIS: Mrp Interval idle: 300 ms [1685486647.355971][4909:4911] CHIP:DIS: Mrp Interval active: 2000 ms [1685486647.355988][4909:4911] CHIP:DIS: TCP Supported: 1 [1685486647.356125][4909:4911] CHIP:DIS: UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540: new best score: 3 [1685486647.356150][4909:4911] CHIP:DIS: Checking node lookup status after 2 ms [1685486647.356166][4909:4911] CHIP:DIS: Keeping DNSSD lookup active [1685486647.554410][4909:4911] CHIP:DIS: Checking node lookup status after 200 ms [1685486647.554688][4909:4911] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540 while in state 2 [1685486647.554744][4909:4911] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1685486647.554940][4909:4911] CHIP:IN: SecureSession[0xffff8000ae60]: Allocated Type:2 LSID:45839 [1685486647.555057][4909:4911] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1685486647.557026][4909:4911] CHIP:EM: <<< [E:17725i S:0 M:19308804] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1685486647.557297][4909:4911] CHIP:IN: (U) Sending msg 19308804 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486647.557607][4909:4911] CHIP:SC: Sent Sigma1 msg [1685486647.557668][4909:4911] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1685486647.622533][4909:4911] CHIP:EM: >>> [E:17725i S:0 M:245487211 (Ack:19308804)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486647.622631][4909:4911] CHIP:EM: Found matching exchange: 17725i, Delegate: 0xffff8000d2d8 [1685486647.622712][4909:4911] CHIP:EM: Rxd Ack; Removing MessageCounter:19308804 from Retrans Table on exchange 17725i [1685486648.808642][4909:4911] CHIP:EM: >>> [E:17725i S:0 M:245487212 (Ack:19308804)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1685486648.808695][4909:4911] CHIP:EM: Found matching exchange: 17725i, Delegate: 0xffff8000d2d8 [1685486648.808719][4909:4911] CHIP:EM: CHIP MessageCounter:19308804 not in RetransTable on exchange 17725i [1685486648.808765][4909:4911] CHIP:SC: Received Sigma2 msg [1685486648.808802][4909:4911] CHIP:SC: Peer assigned session session ID 35483 [1685486648.813381][4909:4911] CHIP:SC: Found MRP parameters in the message [1685486648.813446][4909:4911] CHIP:SC: Sending Sigma3 [1685486648.814093][4909:4911] CHIP:EM: <<< [E:17725i S:0 M:19308805 (Ack:245487212)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1685486648.814277][4909:4911] CHIP:IN: (U) Sending msg 19308805 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486648.814470][4909:4911] CHIP:SC: Sent Sigma3 msg [1685486648.844963][4909:4911] CHIP:EM: >>> [E:17725i S:0 M:245487213 (Ack:19308805)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486648.845060][4909:4911] CHIP:EM: Found matching exchange: 17725i, Delegate: 0xffff8000d2d8 [1685486648.845141][4909:4911] CHIP:EM: Rxd Ack; Removing MessageCounter:19308805 from Retrans Table on exchange 17725i [1685486649.663299][4909:4911] CHIP:EM: >>> [E:17725i S:0 M:245487214 (Ack:19308805)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1685486649.663406][4909:4911] CHIP:EM: Found matching exchange: 17725i, Delegate: 0xffff8000d2d8 [1685486649.663468][4909:4911] CHIP:EM: CHIP MessageCounter:19308805 not in RetransTable on exchange 17725i [1685486649.663570][4909:4911] CHIP:SC: Success status report received. Session was established [1685486649.670241][4909:4911] CHIP:SC: SecureSession[0xffff8000ae60, LSID:45839]: State change 'kEstablishing' --> 'kActive' [1685486649.670344][4909:4911] CHIP:IN: SecureSession[0xffff8000ae60]: Activated - Type:2 LSID:45839 [1685486649.670409][4909:4911] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:45839 PSID:35483! [1685486649.670470][4909:4911] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1685486649.670681][4909:4911] CHIP:TOO: cluster 0x0000_0005, attribute: 0x0000_FFF9, endpoint 1 [1685486649.670752][4909:4911] CHIP:TOO: Sending ReadAttribute to: [1685486649.670821][4909:4911] CHIP:DMG: SendReadRequest ReadClient[0xffff800101a0]: Sending Read Request [1685486649.671156][4909:4911] CHIP:EM: <<< [E:17726i S:45839 M:1935049] (S) Msg TX to 1:0000000000000001 [DD6E] --- Type 0001:02 (IM:ReadRequest) [1685486649.671259][4909:4911] CHIP:IN: (S) Sending msg 1935049 on secure session with LSID: 45839 [1685486649.671593][4909:4911] CHIP:DMG: MoveToState ReadClient[0xffff800101a0]: Moving to [AwaitingIn] [1685486649.671886][4909:4911] CHIP:EM: <<< [E:17725i S:0 M:19308806 (Ack:245487214)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486649.672049][4909:4911] CHIP:IN: (U) Sending msg 19308806 to IP address 'UDP:[fe80::2a76:81ff:feca:ad58%eth0]:5540' [1685486649.672152][4909:4911] CHIP:EM: Flushed pending ack for MessageCounter:245487214 on exchange 17725i [1685486649.759547][4909:4911] CHIP:EM: >>> [E:17726i S:45839 M:88782904 (Ack:1935049)] (S) Msg RX from 1:0000000000000001 [DD6E] --- Type 0001:05 (IM:ReportData) [1685486649.759649][4909:4911] CHIP:EM: Found matching exchange: 17726i, Delegate: 0xffff800101b0 [1685486649.759732][4909:4911] CHIP:EM: Rxd Ack; Removing MessageCounter:1935049 from Retrans Table on exchange 17726i [1685486649.759926][4909:4911] CHIP:DMG: ReportDataMessage = [1685486649.759992][4909:4911] CHIP:DMG: { [1685486649.760041][4909:4911] CHIP:DMG: AttributeReportIBs = [1685486649.760124][4909:4911] CHIP:DMG: [ [1685486649.760181][4909:4911] CHIP:DMG: AttributeReportIB = [1685486649.760268][4909:4911] CHIP:DMG: { [1685486649.760357][4909:4911] CHIP:DMG: AttributeDataIB = [1685486649.760440][4909:4911] CHIP:DMG: { [1685486649.760512][4909:4911] CHIP:DMG: DataVersion = 0xa51ec1e3, [1685486649.760584][4909:4911] CHIP:DMG: AttributePathIB = [1685486649.760678][4909:4911] CHIP:DMG: { [1685486649.760755][4909:4911] CHIP:DMG: Endpoint = 0x1, [1685486649.760834][4909:4911] CHIP:DMG: Cluster = 0x5, [1685486649.760936][4909:4911] CHIP:DMG: Attribute = 0x0000_FFF9, [1685486649.761012][4909:4911] CHIP:DMG: } [1685486649.761090][4909:4911] CHIP:DMG: [1685486649.761163][4909:4911] CHIP:DMG: Data = [ [1685486649.761429][4909:4911] CHIP:DMG: 0, 1, 2, 3, 4, 5, 6, 64, 65, 66, [1685486649.761604][4909:4911] CHIP:DMG: ], [1685486649.761681][4909:4911] CHIP:DMG: }, [1685486649.761794][4909:4911] CHIP:DMG: [1685486649.761855][4909:4911] CHIP:DMG: }, [1685486649.761934][4909:4911] CHIP:DMG: [1685486649.762011][4909:4911] CHIP:DMG: ], [1685486649.762157][4909:4911] CHIP:DMG: [1685486649.762237][4909:4911] CHIP:DMG: SuppressResponse = true, [1685486649.762298][4909:4911] CHIP:DMG: InteractionModelRevision = 1 [1685486649.762353][4909:4911] CHIP:DMG: } [1685486649.763028][4909:4911] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_0005 Attribute 0x0000_FFF9 DataVersion: 2770256355 [1685486649.763252][4909:4911] CHIP:TOO: AcceptedCommandList: 10 entries [1685486649.763323][4909:4911] CHIP:TOO: [1]: 0 [1685486649.763381][4909:4911] CHIP:TOO: [2]: 1 [1685486649.763437][4909:4911] CHIP:TOO: [3]: 2 [1685486649.763492][4909:4911] CHIP:TOO: [4]: 3 [1685486649.763571][4909:4911] CHIP:TOO: [5]: 4 [1685486649.763629][4909:4911] CHIP:TOO: [6]: 5 [1685486649.763685][4909:4911] CHIP:TOO: [7]: 6 [1685486649.763784][4909:4911] CHIP:TOO: [8]: 64 [1685486649.763886][4909:4911] CHIP:TOO: [9]: 65 [1685486649.763947][4909:4911] CHIP:TOO: [10]: 66 [1685486649.764319][4909:4911] CHIP:EM: <<< [E:17726i S:45839 M:1935050 (Ack:88782904)] (S) Msg TX to 1:0000000000000001 [DD6E] --- Type 0000:10 (SecureChannel:StandaloneAck) [1685486649.764440][4909:4911] CHIP:IN: (S) Sending msg 1935050 on secure session with LSID: 45839 [1685486649.764667][4909:4911] CHIP:EM: Flushed pending ack for MessageCounter:88782904 on exchange 17726i [1685486649.765137][4909:4909] CHIP:CTL: Shutting down the commissioner [1685486649.765207][4909:4909] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486649.765261][4909:4909] CHIP:CTL: Shutting down the controller [1685486649.765314][4909:4909] CHIP:IN: Expiring all sessions for fabric 0x1!! [1685486649.765365][4909:4909] CHIP:IN: SecureSession[0xffff8000ae60]: MarkForEviction Type:2 LSID:45839 [1685486649.765418][4909:4909] CHIP:SC: SecureSession[0xffff8000ae60, LSID:45839]: State change 'kActive' --> 'kPendingEviction' [1685486649.765470][4909:4909] CHIP:IN: SecureSession[0xffff8000ae60]: Released - Type:2 LSID:45839 [1685486649.765529][4909:4909] CHIP:FP: Forgetting fabric 0x1 [1685486649.765597][4909:4909] CHIP:TS: Pending Last Known Good Time: 2023-05-26T15:09:49 [1685486649.765913][4909:4909] CHIP:TS: Previous Last Known Good Time: 2023-05-26T15:09:49 [1685486649.765972][4909:4909] CHIP:TS: Reverted Last Known Good Time to previous value [1685486649.766056][4909:4909] CHIP:CTL: Shutting down the commissioner [1685486649.766109][4909:4909] CHIP:CTL: Stopping commissioning discovery over DNS-SD [1685486649.766158][4909:4909] CHIP:CTL: Shutting down the controller [1685486649.766206][4909:4909] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1685486649.768411][4909:4909] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1685486649.768607][4909:4909] CHIP:BLE: BleConnectionDelegate::CancelConnection is not implemented. [1685486649.768724][4909:4909] CHIP:FP: Shutting down FabricTable [1685486649.768795][4909:4909] CHIP:TS: Pending Last Known Good Time: 2023-05-26T15:09:49 [1685486649.769054][4909:4909] CHIP:TS: Previous Last Known Good Time: 2023-05-26T15:09:49 [1685486649.769136][4909:4909] CHIP:TS: Reverted Last Known Good Time to previous value [1685486649.769577][4909:4909] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-QHSGk2) [1685486649.770873][4909:4909] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1685486649.771009][4909:4909] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1685486649.771070][4909:4909] CHIP:DL: Inet Layer shutdown [1685486649.771119][4909:4909] CHIP:DL: BLE shutdown [1685486649.771170][4909:4909] CHIP:DL: System Layer shutdown ubuntu@ManognaTHpi:~/apps$