ubuntu@ubuntu:~/apps$ ./chip-tool pairing open-commissioning-window 0xC57022EBC6624A46 1 900 1000 3423 [1747224035.635485][19133:19133] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs [1747224035.636632][19133:19133] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1747224035.636673][19133:19133] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1747224035.641954][19133:19133] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1747224035.642275][19133:19133] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1747224035.642387][19133:19133] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1747224035.642710][19133:19133] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-LNMvWl) [1747224035.643216][19133:19133] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1747224035.643263][19133:19133] CHIP:DL: NVS set: chip-counters/reboot-count = 11 (0xB) [1747224035.644146][19133:19133] CHIP:DL: Got Ethernet interface: eth0 [1747224035.644680][19133:19133] CHIP:DL: Found the primary Ethernet interface:eth0 [1747224035.645233][19133:19133] CHIP:DL: Got WiFi interface: wlan0 [1747224035.645295][19133:19133] CHIP:DL: Failed to reset WiFi statistic counts [1747224035.645345][19133:19133] CHIP:IN: UDP::Init bind&listen port=0 [1747224035.645451][19133:19133] CHIP:IN: UDP::Init bound to port=59505 [1747224035.645471][19133:19133] CHIP:IN: BLEBase::Init - setting/overriding transport [1747224035.645489][19133:19133] CHIP:IN: TransportMgr initialized [1747224035.645537][19133:19133] CHIP:FP: Initializing FabricTable from persistent storage [1747224035.645672][19133:19133] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1747224035.647145][19133:19133] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xE62A29F0B52B7236, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1747224035.650956][19133:19133] CHIP:ZCL: Using ZAP configuration... [1747224035.654915][19133:19133] CHIP:DL: Avahi client registered [1747224035.655054][19133:19133] CHIP:CTL: System State Initialized... [1747224035.655260][19133:19133] CHIP:CTL: Setting attestation nonce to random value [1747224035.655314][19133:19133] CHIP:CTL: Setting CSR nonce to random value [1747224035.655391][19133:19133] CHIP:IN: UDP::Init bind&listen port=5550 [1747224035.655545][19133:19133] CHIP:IN: UDP::Init bound to port=5550 [1747224035.655570][19133:19133] CHIP:IN: TransportMgr initialized [1747224035.655889][19133:19135] CHIP:DL: CHIP task running [1747224035.656085][19133:19135] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1747224035.656419][19133:19135] CHIP:CTL: Setting attestation nonce to random value [1747224035.656599][19133:19135] CHIP:CTL: Setting CSR nonce to random value [1747224035.657505][19133:19135] CHIP:CTL: Generating NOC [1747224035.658483][19133:19135] CHIP:FP: Validating NOC chain [1747224035.660341][19133:19135] CHIP:FP: NOC chain validation successful [1747224035.660507][19133:19135] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1747224035.660539][19133:19135] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1747224035.660562][19133:19135] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1747224035.660583][19133:19135] CHIP:TS: Retaining current Last Known Good Time [1747224035.665461][19133:19135] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1747224035.667122][19133:19135] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48 [1747224035.669024][19133:19135] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: E62A29F0B52B7236) [1747224035.669075][19133:19135] CHIP:IN: UDP::Init bind&listen port=5550 [1747224035.669190][19133:19135] CHIP:IN: UDP::Init bound to port=5550 [1747224035.669212][19133:19135] CHIP:IN: TransportMgr initialized [1747224035.689849][19133:19135] CHIP:CSM: FindOrEstablishSession: PeerId = [1:C57022EBC6624A46] [1747224035.689904][19133:19135] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1747224035.689941][19133:19135] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 1 --> 2 [1747224035.689975][19133:19135] CHIP:DIS: Resolving E62A29F0B52B7236:C57022EBC6624A46 ... [1747224035.691836][19133:19135] CHIP:DL: Avahi resolve found [1747224035.691921][19133:19135] CHIP:DIS: Node ID resolved for E62A29F0B52B7236:C57022EBC6624A46 [1747224035.691945][19133:19135] CHIP:DIS: Hostname: 3E60856AC9F1A6F8 [1747224035.691971][19133:19135] CHIP:DIS: IP Address #1: fd11:35::d92:331a:246b:35c8 [1747224035.691993][19133:19135] CHIP:DIS: Port: 5540 [1747224035.692014][19133:19135] CHIP:DIS: Mrp Interval idle: 5000 ms [1747224035.692034][19133:19135] CHIP:DIS: Mrp Interval active: 2500 ms [1747224035.692055][19133:19135] CHIP:DIS: Mrp Active Threshold: 500 ms [1747224035.692076][19133:19135] CHIP:DIS: TCP Supported: 0 [1747224035.692097][19133:19135] CHIP:DIS: ICD: not present [1747224035.692880][19133:19135] CHIP:DIS: Lookup clearing interface for non LL address [1747224035.692972][19133:19135] CHIP:DIS: UDP:[fd11:35::d92:331a:246b:35c8%vethb57ca26]:5540: new best score: 5 [1747224035.692998][19133:19135] CHIP:DIS: Checking node lookup status after 3 ms [1747224035.693018][19133:19135] CHIP:DIS: Keeping DNSSD lookup active [1747224035.890294][19133:19135] CHIP:DIS: Checking node lookup status after 201 ms [1747224035.890436][19133:19135] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: Updating device address to UDP:[fd11:35::d92:331a:246b:35c8]:5540 while in state 2 [1747224035.890498][19133:19135] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 2 --> 3 [1747224035.890811][19133:19135] CHIP:IN: SecureSession[0xffffa800edd0]: Allocated Type:2 LSID:59316 [1747224035.890914][19133:19135] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0xC57022EBC6624A46 [1747224035.892936][19133:19135] CHIP:EM: <<< [E:1479i S:0 M:187229172] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1747224035.893490][19133:19135] CHIP:SC: Sent Sigma1 msg [1747224035.893591][19133:19135] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 3 --> 4 [1747224036.143124][19133:19135] CHIP:EM: >>> [E:1479i S:0 M:160472342 (Ack:187229172)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747224036.143207][19133:19135] CHIP:EM: Found matching exchange: 1479i, Delegate: 0xffffa800eb28 [1747224036.143275][19133:19135] CHIP:EM: Rxd Ack; Removing MessageCounter:187229172 from Retrans Table on exchange 1479i [1747224036.314810][19133:19135] CHIP:EM: >>> [E:1479i S:0 M:160472343 (Ack:187229172)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1747224036.314901][19133:19135] CHIP:EM: Found matching exchange: 1479i, Delegate: 0xffffa800eb28 [1747224036.314956][19133:19135] CHIP:EM: CHIP MessageCounter:187229172 not in RetransTable on exchange 1479i [1747224036.315053][19133:19135] CHIP:SC: Received Sigma2 msg [1747224036.315128][19133:19135] CHIP:SC: Peer assigned session session ID 28363 [1747224036.322720][19133:19135] CHIP:SC: Found MRP parameters in the message [1747224036.322819][19133:19135] CHIP:SC: Sending Sigma3 [1747224036.323805][19133:19135] CHIP:EM: <<< [E:1479i S:0 M:187229173 (Ack:160472343)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1747224036.324091][19133:19135] CHIP:SC: Sent Sigma3 msg [1747224036.717443][19133:19135] CHIP:EM: >>> [E:1479i S:0 M:160472344 (Ack:187229173)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747224036.717494][19133:19135] CHIP:EM: Found matching exchange: 1479i, Delegate: 0xffffa800eb28 [1747224036.717532][19133:19135] CHIP:EM: Rxd Ack; Removing MessageCounter:187229173 from Retrans Table on exchange 1479i [1747224036.937647][19133:19135] CHIP:EM: >>> [E:1479i S:0 M:160472345 (Ack:187229173)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1747224036.937752][19133:19135] CHIP:EM: Found matching exchange: 1479i, Delegate: 0xffffa800eb28 [1747224036.937815][19133:19135] CHIP:EM: CHIP MessageCounter:187229173 not in RetransTable on exchange 1479i [1747224036.937925][19133:19135] CHIP:SC: Success status report received. Session was established [1747224036.945040][19133:19135] CHIP:SC: SecureSession[0xffffa800edd0, LSID:59316]: State change 'kEstablishing' --> 'kActive' [1747224036.945148][19133:19135] CHIP:IN: SecureSession[0xffffa800edd0]: Activated - Type:2 LSID:59316 [1747224036.945218][19133:19135] CHIP:IN: New secure session activated for device , LSID:59316 PSID:28363! [1747224036.945279][19133:19135] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 4 --> 5 [1747224036.945456][19133:19135] CHIP:DMG: SendReadRequest ReadClient[0xffffa800a4c0]: Sending Read Request [1747224036.946036][19133:19135] CHIP:EM: <<< [E:1480i S:59316 M:241695939] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0001:02 (IM:ReadRequest) [1747224036.946425][19133:19135] CHIP:DMG: MoveToState ReadClient[0xffffa800a4c0]: Moving to [AwaitingIn] [1747224036.946628][19133:19135] CHIP:EM: <<< [E:1479i S:0 M:187229174 (Ack:160472345)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747224036.946757][19133:19135] CHIP:EM: Flushed pending ack for MessageCounter:160472345 on exchange 1479i [1747224037.223219][19133:19135] CHIP:EM: >>> [E:1480i S:59316 M:24121245 (Ack:241695939)] (S) Msg RX from 1:C57022EBC6624A46 [7236] --- Type 0001:05 (IM:ReportData) [1747224037.223310][19133:19135] CHIP:EM: Found matching exchange: 1480i, Delegate: 0xffffa800a4d0 [1747224037.223386][19133:19135] CHIP:EM: Rxd Ack; Removing MessageCounter:241695939 from Retrans Table on exchange 1480i [1747224037.223505][19133:19135] CHIP:DMG: ReportDataMessage = [1747224037.223561][19133:19135] CHIP:DMG: { [1747224037.223606][19133:19135] CHIP:DMG: AttributeReportIBs = [1747224037.223672][19133:19135] CHIP:DMG: [ [1747224037.223722][19133:19135] CHIP:DMG: AttributeReportIB = [1747224037.223790][19133:19135] CHIP:DMG: { [1747224037.223844][19133:19135] CHIP:DMG: AttributeDataIB = [1747224037.223907][19133:19135] CHIP:DMG: { [1747224037.223970][19133:19135] CHIP:DMG: DataVersion = 0x7215b6c9, [1747224037.224033][19133:19135] CHIP:DMG: AttributePathIB = [1747224037.224099][19133:19135] CHIP:DMG: { [1747224037.224165][19133:19135] CHIP:DMG: Endpoint = 0x0, [1747224037.224237][19133:19135] CHIP:DMG: Cluster = 0x28, [1747224037.224307][19133:19135] CHIP:DMG: Attribute = 0x0000_0002, [1747224037.224371][19133:19135] CHIP:DMG: } [1747224037.224438][19133:19135] CHIP:DMG: [1747224037.224566][19133:19135] CHIP:DMG: Data = 5547, [1747224037.224630][19133:19135] CHIP:DMG: }, [1747224037.224699][19133:19135] CHIP:DMG: [1747224037.224752][19133:19135] CHIP:DMG: }, [1747224037.224816][19133:19135] CHIP:DMG: [1747224037.224864][19133:19135] CHIP:DMG: ], [1747224037.224927][19133:19135] CHIP:DMG: [1747224037.224979][19133:19135] CHIP:DMG: SuppressResponse = true, [1747224037.225032][19133:19135] CHIP:DMG: InteractionModelRevision = 11 [1747224037.225080][19133:19135] CHIP:DMG: } [1747224037.225355][19133:19135] CHIP:CTL: Received VID for the device. Value 5547 [1747224037.225407][19133:19135] CHIP:CSM: FindOrEstablishSession: PeerId = [1:C57022EBC6624A46] [1747224037.225453][19133:19135] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1747224037.225518][19133:19135] CHIP:DIS: Found an existing secure session to [1:C57022EBC6624A46]! [1747224037.225573][19133:19135] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 1 --> 5 [1747224037.225688][19133:19135] CHIP:DMG: SendReadRequest ReadClient[0xffffa80092c0]: Sending Read Request [1747224037.226106][19133:19135] CHIP:EM: <<< [E:1481i S:59316 M:241695940] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0001:02 (IM:ReadRequest) [1747224037.226512][19133:19135] CHIP:DMG: MoveToState ReadClient[0xffffa80092c0]: Moving to [AwaitingIn] [1747224037.226914][19133:19135] CHIP:EM: <<< [E:1480i S:59316 M:241695941 (Ack:24121245)] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747224037.227150][19133:19135] CHIP:EM: Flushed pending ack for MessageCounter:24121245 on exchange 1480i [1747224037.735697][19133:19135] CHIP:EM: >>> [E:1481i S:59316 M:24121246 (Ack:241695940)] (S) Msg RX from 1:C57022EBC6624A46 [7236] --- Type 0001:05 (IM:ReportData) [1747224037.735793][19133:19135] CHIP:EM: Found matching exchange: 1481i, Delegate: 0xffffa80092d0 [1747224037.735871][19133:19135] CHIP:EM: Rxd Ack; Removing MessageCounter:241695940 from Retrans Table on exchange 1481i [1747224037.735991][19133:19135] CHIP:DMG: ReportDataMessage = [1747224037.736048][19133:19135] CHIP:DMG: { [1747224037.736095][19133:19135] CHIP:DMG: AttributeReportIBs = [1747224037.736162][19133:19135] CHIP:DMG: [ [1747224037.736212][19133:19135] CHIP:DMG: AttributeReportIB = [1747224037.736280][19133:19135] CHIP:DMG: { [1747224037.736334][19133:19135] CHIP:DMG: AttributeDataIB = [1747224037.736398][19133:19135] CHIP:DMG: { [1747224037.736464][19133:19135] CHIP:DMG: DataVersion = 0x7215b6c9, [1747224037.736528][19133:19135] CHIP:DMG: AttributePathIB = [1747224037.736593][19133:19135] CHIP:DMG: { [1747224037.736659][19133:19135] CHIP:DMG: Endpoint = 0x0, [1747224037.736732][19133:19135] CHIP:DMG: Cluster = 0x28, [1747224037.736801][19133:19135] CHIP:DMG: Attribute = 0x0000_0004, [1747224037.736868][19133:19135] CHIP:DMG: } [1747224037.736939][19133:19135] CHIP:DMG: [1747224037.737008][19133:19135] CHIP:DMG: Data = 1, [1747224037.737066][19133:19135] CHIP:DMG: }, [1747224037.737134][19133:19135] CHIP:DMG: [1747224037.737187][19133:19135] CHIP:DMG: }, [1747224037.737250][19133:19135] CHIP:DMG: [1747224037.737298][19133:19135] CHIP:DMG: ], [1747224037.737361][19133:19135] CHIP:DMG: [1747224037.737412][19133:19135] CHIP:DMG: SuppressResponse = true, [1747224037.737465][19133:19135] CHIP:DMG: InteractionModelRevision = 11 [1747224037.737513][19133:19135] CHIP:DMG: } [1747224037.737719][19133:19135] CHIP:CTL: Received PID for the device. Value 1 [1747224037.737768][19133:19135] CHIP:CSM: FindOrEstablishSession: PeerId = [1:C57022EBC6624A46] [1747224037.737814][19133:19135] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1747224037.737877][19133:19135] CHIP:DIS: Found an existing secure session to [1:C57022EBC6624A46]! [1747224037.737931][19133:19135] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 1 --> 5 [1747224037.737992][19133:19135] CHIP:CTL: OpenCommissioningWindow for device ID 0xC57022EBC6624A46 [1747224037.738206][19133:19135] CHIP:DMG: ICR moving to [AddingComm] [1747224037.738330][19133:19135] CHIP:DMG: ICR moving to [AddedComma] [1747224037.738719][19133:19135] CHIP:EM: <<< [E:1482i S:59316 M:241695942] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0001:0A (IM:TimedRequest) [1747224037.739054][19133:19135] CHIP:DMG: ICR moving to [AwaitingTi] [1747224037.739623][19133:19135] CHIP:EM: <<< [E:1481i S:59316 M:241695943 (Ack:24121246)] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747224037.739859][19133:19135] CHIP:EM: Flushed pending ack for MessageCounter:24121246 on exchange 1481i [1747224038.243630][19133:19135] CHIP:EM: >>> [E:1482i S:59316 M:24121247 (Ack:241695942)] (S) Msg RX from 1:C57022EBC6624A46 [7236] --- Type 0001:01 (IM:StatusResponse) [1747224038.243712][19133:19135] CHIP:EM: Found matching exchange: 1482i, Delegate: 0xffffa8008628 [1747224038.243779][19133:19135] CHIP:EM: Rxd Ack; Removing MessageCounter:241695942 from Retrans Table on exchange 1482i [1747224038.243873][19133:19135] CHIP:DMG: StatusResponseMessage = [1747224038.243923][19133:19135] CHIP:DMG: { [1747224038.243969][19133:19135] CHIP:DMG: Status = 0x00 (SUCCESS), [1747224038.244016][19133:19135] CHIP:DMG: InteractionModelRevision = 11 [1747224038.244059][19133:19135] CHIP:DMG: } [1747224038.244103][19133:19135] CHIP:IM: Received status response, status is 0x00 (SUCCESS) [1747224038.244424][19133:19135] CHIP:EM: <<< [E:1482i S:59316 M:241695944 (Ack:24121247)] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) [1747224038.244719][19133:19135] CHIP:DMG: ICR moving to [AwaitingRe] [1747224038.825526][19133:19135] CHIP:EM: >>> [E:1482i S:59316 M:24121248 (Ack:241695944)] (S) Msg RX from 1:C57022EBC6624A46 [7236] --- Type 0001:09 (IM:InvokeCommandResponse) [1747224038.825632][19133:19135] CHIP:EM: Found matching exchange: 1482i, Delegate: 0xffffa8008628 [1747224038.825720][19133:19135] CHIP:EM: Rxd Ack; Removing MessageCounter:241695944 from Retrans Table on exchange 1482i [1747224038.825806][19133:19135] CHIP:DMG: ICR moving to [ResponseRe] [1747224038.825915][19133:19135] CHIP:DMG: InvokeResponseMessage = [1747224038.825976][19133:19135] CHIP:DMG: { [1747224038.826032][19133:19135] CHIP:DMG: suppressResponse = false, [1747224038.826090][19133:19135] CHIP:DMG: InvokeResponseIBs = [1747224038.826220][19133:19135] CHIP:DMG: [ [1747224038.826282][19133:19135] CHIP:DMG: InvokeResponseIB = [1747224038.826360][19133:19135] CHIP:DMG: { [1747224038.826422][19133:19135] CHIP:DMG: CommandStatusIB = [1747224038.826491][19133:19135] CHIP:DMG: { [1747224038.826566][19133:19135] CHIP:DMG: CommandPathIB = [1747224038.826639][19133:19135] CHIP:DMG: { [1747224038.826716][19133:19135] CHIP:DMG: EndpointId = 0x0, [1747224038.826797][19133:19135] CHIP:DMG: ClusterId = 0x3c, [1747224038.826875][19133:19135] CHIP:DMG: CommandId = 0x0, [1747224038.826952][19133:19135] CHIP:DMG: }, [1747224038.827037][19133:19135] CHIP:DMG: [1747224038.827107][19133:19135] CHIP:DMG: StatusIB = [1747224038.827184][19133:19135] CHIP:DMG: { [1747224038.827263][19133:19135] CHIP:DMG: status = 0x00 (SUCCESS), [1747224038.827339][19133:19135] CHIP:DMG: }, [1747224038.827417][19133:19135] CHIP:DMG: [1747224038.827485][19133:19135] CHIP:DMG: }, [1747224038.827559][19133:19135] CHIP:DMG: [1747224038.827620][19133:19135] CHIP:DMG: }, [1747224038.827694][19133:19135] CHIP:DMG: [1747224038.827749][19133:19135] CHIP:DMG: ], [1747224038.827823][19133:19135] CHIP:DMG: [1747224038.827880][19133:19135] CHIP:DMG: InteractionModelRevision = 11 [1747224038.827936][19133:19135] CHIP:DMG: }, [1747224038.828092][19133:19135] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0000 Status=0x0 [1747224038.828158][19133:19135] CHIP:CTL: Successfully opened pairing window on the device [1747224038.828277][19133:19135] CHIP:CTL: Manual pairing code: [31928450031] [1747224038.828346][19133:19135] CHIP:CTL: SetupQRCode: [MT:WUDA0UZ427TVZR4VR10] [1747224038.828502][19133:19135] CHIP:DMG: ICR moving to [AwaitingDe] [1747224038.828902][19133:19135] CHIP:EM: <<< [E:1482i S:59316 M:241695945 (Ack:24121248)] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747224038.829189][19133:19135] CHIP:EM: Flushed pending ack for MessageCounter:24121248 on exchange 1482i [1747224038.829573][19133:19133] CHIP:CTL: Shutting down the commissioner [1747224038.829775][19133:19133] CHIP:CTL: Shutting down the controller [1747224038.829850][19133:19133] CHIP:IN: Expiring all sessions for fabric 0x1!! [1747224038.829930][19133:19133] CHIP:IN: SecureSession[0xffffa800edd0]: MarkForEviction Type:2 LSID:59316 [1747224038.829987][19133:19133] CHIP:SC: SecureSession[0xffffa800edd0, LSID:59316]: State change 'kActive' --> 'kPendingEviction' [1747224038.830044][19133:19133] CHIP:IN: SecureSession[0xffffa800edd0]: Released - Type:2 LSID:59316 [1747224038.830106][19133:19133] CHIP:FP: Forgetting fabric 0x1 [1747224038.830267][19133:19133] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1747224038.830642][19133:19133] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1747224038.830707][19133:19133] CHIP:TS: Reverted Last Known Good Time to previous value [1747224038.830803][19133:19133] CHIP:CTL: Shutting down the commissioner [1747224038.830985][19133:19133] CHIP:CTL: Shutting down the controller [1747224038.831040][19133:19133] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1747224038.831351][19133:19133] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1747224038.831478][19133:19133] CHIP:FP: Shutting down FabricTable [1747224038.831524][19133:19133] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1747224038.831675][19133:19133] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1747224038.831709][19133:19133] CHIP:TS: Reverted Last Known Good Time to previous value [1747224038.832016][19133:19133] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-X0YOF9) [1747224038.832861][19133:19133] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1747224038.832946][19133:19133] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1747224038.832980][19133:19133] CHIP:DL: Inet Layer shutdown [1747224038.833008][19133:19133] CHIP:DL: BLE shutdown [1747224038.833041][19133:19133] CHIP:DL: System Layer shutdown ubuntu@ubuntu:~/apps$ ./chip-tool administratorcommissioning read window-status 0xC57022EBC6624A46 0 [1747224053.162033][19140:19140] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs [1747224053.163207][19140:19140] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1747224053.163250][19140:19140] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1747224053.168461][19140:19140] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1747224053.168721][19140:19140] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1747224053.168828][19140:19140] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1747224053.169174][19140:19140] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-Usefab) [1747224053.169766][19140:19140] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1747224053.169817][19140:19140] CHIP:DL: NVS set: chip-counters/reboot-count = 12 (0xC) [1747224053.170697][19140:19140] CHIP:DL: Got Ethernet interface: eth0 [1747224053.171255][19140:19140] CHIP:DL: Found the primary Ethernet interface:eth0 [1747224053.171813][19140:19140] CHIP:DL: Got WiFi interface: wlan0 [1747224053.171881][19140:19140] CHIP:DL: Failed to reset WiFi statistic counts [1747224053.171934][19140:19140] CHIP:IN: UDP::Init bind&listen port=0 [1747224053.172041][19140:19140] CHIP:IN: UDP::Init bound to port=43204 [1747224053.172062][19140:19140] CHIP:IN: BLEBase::Init - setting/overriding transport [1747224053.172081][19140:19140] CHIP:IN: TransportMgr initialized [1747224053.172129][19140:19140] CHIP:FP: Initializing FabricTable from persistent storage [1747224053.172270][19140:19140] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1747224053.173636][19140:19140] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xE62A29F0B52B7236, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1747224053.175672][19140:19140] CHIP:ZCL: Using ZAP configuration... [1747224053.179356][19140:19140] CHIP:DL: Avahi client registered [1747224053.179484][19140:19140] CHIP:CTL: System State Initialized... [1747224053.179662][19140:19140] CHIP:CTL: Setting attestation nonce to random value [1747224053.179698][19140:19140] CHIP:CTL: Setting CSR nonce to random value [1747224053.179768][19140:19140] CHIP:IN: UDP::Init bind&listen port=5550 [1747224053.179889][19140:19140] CHIP:IN: UDP::Init bound to port=5550 [1747224053.179909][19140:19140] CHIP:IN: TransportMgr initialized [1747224053.180157][19140:19142] CHIP:DL: CHIP task running [1747224053.180325][19140:19142] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1747224053.180626][19140:19142] CHIP:CTL: Setting attestation nonce to random value [1747224053.180778][19140:19142] CHIP:CTL: Setting CSR nonce to random value [1747224053.181549][19140:19142] CHIP:CTL: Generating NOC [1747224053.182401][19140:19142] CHIP:FP: Validating NOC chain [1747224053.183983][19140:19142] CHIP:FP: NOC chain validation successful [1747224053.184152][19140:19142] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1747224053.184186][19140:19142] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1747224053.184211][19140:19142] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1747224053.184234][19140:19142] CHIP:TS: Retaining current Last Known Good Time [1747224053.189234][19140:19142] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1747224053.191725][19140:19142] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48 [1747224053.194358][19140:19142] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: E62A29F0B52B7236) [1747224053.194418][19140:19142] CHIP:IN: UDP::Init bind&listen port=5550 [1747224053.194549][19140:19142] CHIP:IN: UDP::Init bound to port=5550 [1747224053.194575][19140:19142] CHIP:IN: TransportMgr initialized [1747224053.209668][19140:19142] CHIP:TOO: Sending command to node 0xc57022ebc6624a46 [1747224053.210497][19140:19142] CHIP:CSM: FindOrEstablishSession: PeerId = [1:C57022EBC6624A46] [1747224053.210533][19140:19142] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1747224053.210567][19140:19142] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 1 --> 2 [1747224053.210601][19140:19142] CHIP:DIS: Resolving E62A29F0B52B7236:C57022EBC6624A46 ... [1747224053.212284][19140:19142] CHIP:DL: Avahi resolve found [1747224053.212360][19140:19142] CHIP:DIS: Node ID resolved for E62A29F0B52B7236:C57022EBC6624A46 [1747224053.212383][19140:19142] CHIP:DIS: Hostname: 3E60856AC9F1A6F8 [1747224053.212408][19140:19142] CHIP:DIS: IP Address #1: fd11:35::d92:331a:246b:35c8 [1747224053.212430][19140:19142] CHIP:DIS: Port: 5540 [1747224053.212450][19140:19142] CHIP:DIS: Mrp Interval idle: 5000 ms [1747224053.212471][19140:19142] CHIP:DIS: Mrp Interval active: 2500 ms [1747224053.212492][19140:19142] CHIP:DIS: Mrp Active Threshold: 500 ms [1747224053.212514][19140:19142] CHIP:DIS: TCP Supported: 0 [1747224053.212538][19140:19142] CHIP:DIS: ICD: not present [1747224053.213273][19140:19142] CHIP:DIS: Lookup clearing interface for non LL address [1747224053.213366][19140:19142] CHIP:DIS: UDP:[fd11:35::d92:331a:246b:35c8%vethb57ca26]:5540: new best score: 5 [1747224053.213391][19140:19142] CHIP:DIS: Checking node lookup status after 3 ms [1747224053.213411][19140:19142] CHIP:DIS: Keeping DNSSD lookup active [1747224053.410778][19140:19142] CHIP:DIS: Checking node lookup status after 200 ms [1747224053.410913][19140:19142] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: Updating device address to UDP:[fd11:35::d92:331a:246b:35c8]:5540 while in state 2 [1747224053.410974][19140:19142] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 2 --> 3 [1747224053.411285][19140:19142] CHIP:IN: SecureSession[0xffff840107e0]: Allocated Type:2 LSID:57686 [1747224053.411386][19140:19142] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0xC57022EBC6624A46 [1747224053.413290][19140:19142] CHIP:EM: <<< [E:38331i S:0 M:26264687] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1747224053.413728][19140:19142] CHIP:SC: Sent Sigma1 msg [1747224053.413806][19140:19142] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 3 --> 4 [1747224053.755607][19140:19142] CHIP:EM: >>> [E:38331i S:0 M:160472346 (Ack:26264687)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747224053.755700][19140:19142] CHIP:EM: Found matching exchange: 38331i, Delegate: 0xffff84010538 [1747224053.755777][19140:19142] CHIP:EM: Rxd Ack; Removing MessageCounter:26264687 from Retrans Table on exchange 38331i [1747224053.926562][19140:19142] CHIP:EM: >>> [E:38331i S:0 M:160472347 (Ack:26264687)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1747224053.926651][19140:19142] CHIP:EM: Found matching exchange: 38331i, Delegate: 0xffff84010538 [1747224053.926708][19140:19142] CHIP:EM: CHIP MessageCounter:26264687 not in RetransTable on exchange 38331i [1747224053.926803][19140:19142] CHIP:SC: Received Sigma2 msg [1747224053.926879][19140:19142] CHIP:SC: Peer assigned session session ID 28364 [1747224053.935689][19140:19142] CHIP:SC: Found MRP parameters in the message [1747224053.935834][19140:19142] CHIP:SC: Sending Sigma3 [1747224053.936685][19140:19142] CHIP:EM: <<< [E:38331i S:0 M:26264688 (Ack:160472347)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1747224053.936957][19140:19142] CHIP:SC: Sent Sigma3 msg [1747224054.337358][19140:19142] CHIP:EM: >>> [E:38331i S:0 M:160472348 (Ack:26264688)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747224054.337462][19140:19142] CHIP:EM: Found matching exchange: 38331i, Delegate: 0xffff84010538 [1747224054.337551][19140:19142] CHIP:EM: Rxd Ack; Removing MessageCounter:26264688 from Retrans Table on exchange 38331i [1747224054.547547][19140:19142] CHIP:EM: >>> [E:38331i S:0 M:160472349 (Ack:26264688)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1747224054.547647][19140:19142] CHIP:EM: Found matching exchange: 38331i, Delegate: 0xffff84010538 [1747224054.547712][19140:19142] CHIP:EM: CHIP MessageCounter:26264688 not in RetransTable on exchange 38331i [1747224054.547822][19140:19142] CHIP:SC: Success status report received. Session was established [1747224054.554473][19140:19142] CHIP:SC: SecureSession[0xffff840107e0, LSID:57686]: State change 'kEstablishing' --> 'kActive' [1747224054.554576][19140:19142] CHIP:IN: SecureSession[0xffff840107e0]: Activated - Type:2 LSID:57686 [1747224054.554630][19140:19142] CHIP:IN: New secure session activated for device , LSID:57686 PSID:28364! [1747224054.554695][19140:19142] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 4 --> 5 [1747224054.554842][19140:19142] CHIP:TOO: Sending ReadAttribute to: [1747224054.554998][19140:19142] CHIP:TOO: cluster 0x0000_003C, attribute: 0x0000_0000, endpoint 0 [1747224054.555089][19140:19142] CHIP:DMG: SendReadRequest ReadClient[0xffff8400a4c0]: Sending Read Request [1747224054.555683][19140:19142] CHIP:EM: <<< [E:38332i S:57686 M:204414440] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0001:02 (IM:ReadRequest) [1747224054.556057][19140:19142] CHIP:DMG: MoveToState ReadClient[0xffff8400a4c0]: Moving to [AwaitingIn] [1747224054.556408][19140:19142] CHIP:EM: <<< [E:38331i S:0 M:26264689 (Ack:160472349)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747224054.556675][19140:19142] CHIP:EM: Flushed pending ack for MessageCounter:160472349 on exchange 38331i [1747224054.834195][19140:19142] CHIP:EM: >>> [E:38332i S:57686 M:222795199 (Ack:204414440)] (S) Msg RX from 1:C57022EBC6624A46 [7236] --- Type 0001:05 (IM:ReportData) [1747224054.834278][19140:19142] CHIP:EM: Found matching exchange: 38332i, Delegate: 0xffff8400a4d0 [1747224054.834348][19140:19142] CHIP:EM: Rxd Ack; Removing MessageCounter:204414440 from Retrans Table on exchange 38332i [1747224054.834455][19140:19142] CHIP:DMG: ReportDataMessage = [1747224054.834504][19140:19142] CHIP:DMG: { [1747224054.834545][19140:19142] CHIP:DMG: AttributeReportIBs = [1747224054.834603][19140:19142] CHIP:DMG: [ [1747224054.834649][19140:19142] CHIP:DMG: AttributeReportIB = [1747224054.834708][19140:19142] CHIP:DMG: { [1747224054.834755][19140:19142] CHIP:DMG: AttributeDataIB = [1747224054.834814][19140:19142] CHIP:DMG: { [1747224054.834868][19140:19142] CHIP:DMG: DataVersion = 0x7fdd0008, [1747224054.834922][19140:19142] CHIP:DMG: AttributePathIB = [1747224054.834979][19140:19142] CHIP:DMG: { [1747224054.835036][19140:19142] CHIP:DMG: Endpoint = 0x0, [1747224054.835097][19140:19142] CHIP:DMG: Cluster = 0x3c, [1747224054.835158][19140:19142] CHIP:DMG: Attribute = 0x0000_0000, [1747224054.835216][19140:19142] CHIP:DMG: } [1747224054.835279][19140:19142] CHIP:DMG: [1747224054.835339][19140:19142] CHIP:DMG: Data = 1, [1747224054.835392][19140:19142] CHIP:DMG: }, [1747224054.835451][19140:19142] CHIP:DMG: [1747224054.835497][19140:19142] CHIP:DMG: }, [1747224054.835552][19140:19142] CHIP:DMG: [1747224054.835594][19140:19142] CHIP:DMG: ], [1747224054.835648][19140:19142] CHIP:DMG: [1747224054.835692][19140:19142] CHIP:DMG: SuppressResponse = true, [1747224054.835739][19140:19142] CHIP:DMG: InteractionModelRevision = 11 [1747224054.835781][19140:19142] CHIP:DMG: } [1747224054.836022][19140:19142] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_003C Attribute 0x0000_0000 DataVersion: 2145189896 [1747224054.836145][19140:19142] CHIP:TOO: WindowStatus: 1 [1747224054.836551][19140:19142] CHIP:EM: <<< [E:38332i S:57686 M:204414441 (Ack:222795199)] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747224054.836793][19140:19142] CHIP:EM: Flushed pending ack for MessageCounter:222795199 on exchange 38332i [1747224054.837111][19140:19140] CHIP:CTL: Shutting down the commissioner [1747224054.837269][19140:19140] CHIP:CTL: Shutting down the controller [1747224054.837354][19140:19140] CHIP:IN: Expiring all sessions for fabric 0x1!! [1747224054.837398][19140:19140] CHIP:IN: SecureSession[0xffff840107e0]: MarkForEviction Type:2 LSID:57686 [1747224054.837440][19140:19140] CHIP:SC: SecureSession[0xffff840107e0, LSID:57686]: State change 'kActive' --> 'kPendingEviction' [1747224054.837484][19140:19140] CHIP:IN: SecureSession[0xffff840107e0]: Released - Type:2 LSID:57686 [1747224054.837533][19140:19140] CHIP:FP: Forgetting fabric 0x1 [1747224054.837596][19140:19140] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1747224054.837851][19140:19140] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1747224054.837891][19140:19140] CHIP:TS: Reverted Last Known Good Time to previous value [1747224054.837954][19140:19140] CHIP:CTL: Shutting down the commissioner [1747224054.838063][19140:19140] CHIP:CTL: Shutting down the controller [1747224054.838096][19140:19140] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1747224054.838355][19140:19140] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1747224054.838481][19140:19140] CHIP:FP: Shutting down FabricTable [1747224054.838527][19140:19140] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1747224054.838690][19140:19140] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1747224054.838726][19140:19140] CHIP:TS: Reverted Last Known Good Time to previous value [1747224054.839024][19140:19140] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-w4XBI0) [1747224054.839882][19140:19140] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1747224054.839969][19140:19140] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1747224054.840005][19140:19140] CHIP:DL: Inet Layer shutdown [1747224054.840034][19140:19140] CHIP:DL: BLE shutdown [1747224054.840067][19140:19140] CHIP:DL: System Layer shutdown ubuntu@ubuntu:~/apps$ ./chip-tool administratorcommissioning read window-status 0xC57022EBC6624A46 0 [1747225582.841311][19574:19574] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs [1747225582.842404][19574:19574] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1747225582.842440][19574:19574] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1747225582.847761][19574:19574] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1747225582.848031][19574:19574] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1747225582.848136][19574:19574] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1747225582.848488][19574:19574] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-kMnUCb) [1747225582.849090][19574:19574] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1747225582.849141][19574:19574] CHIP:DL: NVS set: chip-counters/reboot-count = 13 (0xD) [1747225582.849985][19574:19574] CHIP:DL: Got Ethernet interface: eth0 [1747225582.850592][19574:19574] CHIP:DL: Found the primary Ethernet interface:eth0 [1747225582.851237][19574:19574] CHIP:DL: Got WiFi interface: wlan0 [1747225582.851303][19574:19574] CHIP:DL: Failed to reset WiFi statistic counts [1747225582.851357][19574:19574] CHIP:IN: UDP::Init bind&listen port=0 [1747225582.851465][19574:19574] CHIP:IN: UDP::Init bound to port=60019 [1747225582.851486][19574:19574] CHIP:IN: BLEBase::Init - setting/overriding transport [1747225582.851503][19574:19574] CHIP:IN: TransportMgr initialized [1747225582.851586][19574:19574] CHIP:FP: Initializing FabricTable from persistent storage [1747225582.851732][19574:19574] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1747225582.853124][19574:19574] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xE62A29F0B52B7236, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1747225582.855116][19574:19574] CHIP:ZCL: Using ZAP configuration... [1747225582.858806][19574:19574] CHIP:DL: Avahi client registered [1747225582.858930][19574:19574] CHIP:CTL: System State Initialized... [1747225582.859102][19574:19574] CHIP:CTL: Setting attestation nonce to random value [1747225582.859142][19574:19574] CHIP:CTL: Setting CSR nonce to random value [1747225582.859209][19574:19574] CHIP:IN: UDP::Init bind&listen port=5550 [1747225582.859331][19574:19574] CHIP:IN: UDP::Init bound to port=5550 [1747225582.859351][19574:19574] CHIP:IN: TransportMgr initialized [1747225582.859635][19574:19576] CHIP:DL: CHIP task running [1747225582.859824][19574:19576] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1747225582.860129][19574:19576] CHIP:CTL: Setting attestation nonce to random value [1747225582.860285][19574:19576] CHIP:CTL: Setting CSR nonce to random value [1747225582.861071][19574:19576] CHIP:CTL: Generating NOC [1747225582.861913][19574:19576] CHIP:FP: Validating NOC chain [1747225582.863550][19574:19576] CHIP:FP: NOC chain validation successful [1747225582.863731][19574:19576] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1747225582.863768][19574:19576] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1747225582.863793][19574:19576] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1747225582.863815][19574:19576] CHIP:TS: Retaining current Last Known Good Time [1747225582.868923][19574:19576] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1747225582.870869][19574:19576] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48 [1747225582.872800][19574:19576] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: E62A29F0B52B7236) [1747225582.872859][19574:19576] CHIP:IN: UDP::Init bind&listen port=5550 [1747225582.872991][19574:19576] CHIP:IN: UDP::Init bound to port=5550 [1747225582.873017][19574:19576] CHIP:IN: TransportMgr initialized [1747225582.888118][19574:19576] CHIP:TOO: Sending command to node 0xc57022ebc6624a46 [1747225582.888864][19574:19576] CHIP:CSM: FindOrEstablishSession: PeerId = [1:C57022EBC6624A46] [1747225582.888893][19574:19576] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1747225582.888925][19574:19576] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 1 --> 2 [1747225582.888956][19574:19576] CHIP:DIS: Resolving E62A29F0B52B7236:C57022EBC6624A46 ... [1747225583.089215][19574:19576] CHIP:DIS: Checking node lookup status after 201 ms [1747225583.297925][19574:19576] CHIP:DL: Avahi resolve found [1747225583.298079][19574:19576] CHIP:DIS: Node ID resolved for E62A29F0B52B7236:C57022EBC6624A46 [1747225583.298183][19574:19576] CHIP:DIS: Hostname: 3E60856AC9F1A6F8 [1747225583.298254][19574:19576] CHIP:DIS: IP Address #1: fd11:35::d92:331a:246b:35c8 [1747225583.298312][19574:19576] CHIP:DIS: Port: 5540 [1747225583.298366][19574:19576] CHIP:DIS: Mrp Interval idle: 5000 ms [1747225583.298421][19574:19576] CHIP:DIS: Mrp Interval active: 2500 ms [1747225583.298476][19574:19576] CHIP:DIS: Mrp Active Threshold: 500 ms [1747225583.298530][19574:19576] CHIP:DIS: TCP Supported: 0 [1747225583.298584][19574:19576] CHIP:DIS: ICD: not present [1747225583.300195][19574:19576] CHIP:DIS: Lookup clearing interface for non LL address [1747225583.300400][19574:19576] CHIP:DIS: UDP:[fd11:35::d92:331a:246b:35c8%vethb57ca26]:5540: new best score: 5 [1747225583.300462][19574:19576] CHIP:DIS: Checking node lookup status after 412 ms [1747225583.302227][19574:19576] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: Updating device address to UDP:[fd11:35::d92:331a:246b:35c8]:5540 while in state 2 [1747225583.302304][19574:19576] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 2 --> 3 [1747225583.302613][19574:19576] CHIP:IN: SecureSession[0xffff8c0107e0]: Allocated Type:2 LSID:39702 [1747225583.302714][19574:19576] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0xC57022EBC6624A46 [1747225583.304626][19574:19576] CHIP:EM: <<< [E:53150i S:0 M:237549501] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1747225583.305063][19574:19576] CHIP:SC: Sent Sigma1 msg [1747225583.305143][19574:19576] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 3 --> 4 [1747225583.432769][19574:19576] CHIP:EM: >>> [E:53150i S:0 M:160472350 (Ack:237549501)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747225583.432875][19574:19576] CHIP:EM: Found matching exchange: 53150i, Delegate: 0xffff8c010538 [1747225583.432965][19574:19576] CHIP:EM: Rxd Ack; Removing MessageCounter:237549501 from Retrans Table on exchange 53150i [1747225583.609481][19574:19576] CHIP:EM: >>> [E:53150i S:0 M:160472351 (Ack:237549501)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1747225583.609530][19574:19576] CHIP:EM: Found matching exchange: 53150i, Delegate: 0xffff8c010538 [1747225583.609555][19574:19576] CHIP:EM: CHIP MessageCounter:237549501 not in RetransTable on exchange 53150i [1747225583.609605][19574:19576] CHIP:SC: Received Sigma2 msg [1747225583.609644][19574:19576] CHIP:SC: Peer assigned session session ID 28366 [1747225583.613226][19574:19576] CHIP:SC: Found MRP parameters in the message [1747225583.613296][19574:19576] CHIP:SC: Sending Sigma3 [1747225583.613957][19574:19576] CHIP:EM: <<< [E:53150i S:0 M:237549502 (Ack:160472351)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1747225583.614203][19574:19576] CHIP:SC: Sent Sigma3 msg [1747225584.004817][19574:19576] CHIP:EM: >>> [E:53150i S:0 M:160472352 (Ack:237549502)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747225584.004923][19574:19576] CHIP:EM: Found matching exchange: 53150i, Delegate: 0xffff8c010538 [1747225584.005012][19574:19576] CHIP:EM: Rxd Ack; Removing MessageCounter:237549502 from Retrans Table on exchange 53150i [1747225584.311382][19574:19576] CHIP:EM: >>> [E:53150i S:0 M:160472353 (Ack:237549502)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1747225584.311485][19574:19576] CHIP:EM: Found matching exchange: 53150i, Delegate: 0xffff8c010538 [1747225584.311551][19574:19576] CHIP:EM: CHIP MessageCounter:237549502 not in RetransTable on exchange 53150i [1747225584.311658][19574:19576] CHIP:SC: Success status report received. Session was established [1747225584.318298][19574:19576] CHIP:SC: SecureSession[0xffff8c0107e0, LSID:39702]: State change 'kEstablishing' --> 'kActive' [1747225584.318401][19574:19576] CHIP:IN: SecureSession[0xffff8c0107e0]: Activated - Type:2 LSID:39702 [1747225584.318462][19574:19576] CHIP:IN: New secure session activated for device , LSID:39702 PSID:28366! [1747225584.318527][19574:19576] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 4 --> 5 [1747225584.318674][19574:19576] CHIP:TOO: Sending ReadAttribute to: [1747225584.318827][19574:19576] CHIP:TOO: cluster 0x0000_003C, attribute: 0x0000_0000, endpoint 0 [1747225584.318916][19574:19576] CHIP:DMG: SendReadRequest ReadClient[0xffff8c00a4c0]: Sending Read Request [1747225584.319518][19574:19576] CHIP:EM: <<< [E:53151i S:39702 M:20707361] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0001:02 (IM:ReadRequest) [1747225584.319898][19574:19576] CHIP:DMG: MoveToState ReadClient[0xffff8c00a4c0]: Moving to [AwaitingIn] [1747225584.320265][19574:19576] CHIP:EM: <<< [E:53150i S:0 M:237549503 (Ack:160472353)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747225584.320511][19574:19576] CHIP:EM: Flushed pending ack for MessageCounter:160472353 on exchange 53150i [1747225584.510025][19574:19576] CHIP:EM: >>> [E:53151i S:39702 M:208337151 (Ack:20707361)] (S) Msg RX from 1:C57022EBC6624A46 [7236] --- Type 0001:05 (IM:ReportData) [1747225584.510107][19574:19576] CHIP:EM: Found matching exchange: 53151i, Delegate: 0xffff8c00a4d0 [1747225584.510210][19574:19576] CHIP:EM: Rxd Ack; Removing MessageCounter:20707361 from Retrans Table on exchange 53151i [1747225584.510317][19574:19576] CHIP:DMG: ReportDataMessage = [1747225584.510364][19574:19576] CHIP:DMG: { [1747225584.510402][19574:19576] CHIP:DMG: AttributeReportIBs = [1747225584.510460][19574:19576] CHIP:DMG: [ [1747225584.510504][19574:19576] CHIP:DMG: AttributeReportIB = [1747225584.510563][19574:19576] CHIP:DMG: { [1747225584.510609][19574:19576] CHIP:DMG: AttributeDataIB = [1747225584.510662][19574:19576] CHIP:DMG: { [1747225584.510717][19574:19576] CHIP:DMG: DataVersion = 0x7fdd000b, [1747225584.510775][19574:19576] CHIP:DMG: AttributePathIB = [1747225584.510833][19574:19576] CHIP:DMG: { [1747225584.510892][19574:19576] CHIP:DMG: Endpoint = 0x0, [1747225584.510950][19574:19576] CHIP:DMG: Cluster = 0x3c, [1747225584.511010][19574:19576] CHIP:DMG: Attribute = 0x0000_0000, [1747225584.511068][19574:19576] CHIP:DMG: } [1747225584.511126][19574:19576] CHIP:DMG: [1747225584.511187][19574:19576] CHIP:DMG: Data = 0, [1747225584.511240][19574:19576] CHIP:DMG: }, [1747225584.511300][19574:19576] CHIP:DMG: [1747225584.511345][19574:19576] CHIP:DMG: }, [1747225584.511401][19574:19576] CHIP:DMG: [1747225584.511443][19574:19576] CHIP:DMG: ], [1747225584.511498][19574:19576] CHIP:DMG: [1747225584.511543][19574:19576] CHIP:DMG: SuppressResponse = true, [1747225584.511588][19574:19576] CHIP:DMG: InteractionModelRevision = 11 [1747225584.511629][19574:19576] CHIP:DMG: } [1747225584.511874][19574:19576] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_003C Attribute 0x0000_0000 DataVersion: 2145189899 [1747225584.511996][19574:19576] CHIP:TOO: WindowStatus: 0 [1747225584.512401][19574:19576] CHIP:EM: <<< [E:53151i S:39702 M:20707362 (Ack:208337151)] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747225584.512636][19574:19576] CHIP:EM: Flushed pending ack for MessageCounter:208337151 on exchange 53151i [1747225584.512953][19574:19574] CHIP:CTL: Shutting down the commissioner [1747225584.513110][19574:19574] CHIP:CTL: Shutting down the controller [1747225584.513195][19574:19574] CHIP:IN: Expiring all sessions for fabric 0x1!! [1747225584.513239][19574:19574] CHIP:IN: SecureSession[0xffff8c0107e0]: MarkForEviction Type:2 LSID:39702 [1747225584.513281][19574:19574] CHIP:SC: SecureSession[0xffff8c0107e0, LSID:39702]: State change 'kActive' --> 'kPendingEviction' [1747225584.513323][19574:19574] CHIP:IN: SecureSession[0xffff8c0107e0]: Released - Type:2 LSID:39702 [1747225584.513371][19574:19574] CHIP:FP: Forgetting fabric 0x1 [1747225584.513502][19574:19574] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1747225584.513841][19574:19574] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1747225584.513889][19574:19574] CHIP:TS: Reverted Last Known Good Time to previous value [1747225584.513966][19574:19574] CHIP:CTL: Shutting down the commissioner [1747225584.514104][19574:19574] CHIP:CTL: Shutting down the controller [1747225584.514196][19574:19574] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1747225584.514452][19574:19574] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1747225584.514612][19574:19574] CHIP:FP: Shutting down FabricTable [1747225584.514670][19574:19574] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1747225584.514863][19574:19574] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1747225584.514909][19574:19574] CHIP:TS: Reverted Last Known Good Time to previous value [1747225584.515335][19574:19574] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-yStw7P) [1747225584.516341][19574:19574] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1747225584.516448][19574:19574] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1747225584.516494][19574:19574] CHIP:DL: Inet Layer shutdown [1747225584.516532][19574:19574] CHIP:DL: BLE shutdown [1747225584.516574][19574:19574] CHIP:DL: System Layer shutdown ubuntu@ubuntu:~/apps$ ./chip-tool pairing open-commissioning-window 0xC57022EBC6624A46 1 901 2000 3423 [1747225604.789831][19585:19585] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs [1747225604.790945][19585:19585] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1747225604.790990][19585:19585] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1747225604.796269][19585:19585] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1747225604.796526][19585:19585] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1747225604.796658][19585:19585] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1747225604.797005][19585:19585] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-NOo5TI) [1747225604.797623][19585:19585] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1747225604.797683][19585:19585] CHIP:DL: NVS set: chip-counters/reboot-count = 14 (0xE) [1747225604.798655][19585:19585] CHIP:DL: Got Ethernet interface: eth0 [1747225604.799292][19585:19585] CHIP:DL: Found the primary Ethernet interface:eth0 [1747225604.799927][19585:19585] CHIP:DL: Got WiFi interface: wlan0 [1747225604.800000][19585:19585] CHIP:DL: Failed to reset WiFi statistic counts [1747225604.800059][19585:19585] CHIP:IN: UDP::Init bind&listen port=0 [1747225604.800180][19585:19585] CHIP:IN: UDP::Init bound to port=54910 [1747225604.800211][19585:19585] CHIP:IN: BLEBase::Init - setting/overriding transport [1747225604.800229][19585:19585] CHIP:IN: TransportMgr initialized [1747225604.800288][19585:19585] CHIP:FP: Initializing FabricTable from persistent storage [1747225604.800434][19585:19585] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1747225604.801891][19585:19585] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xE62A29F0B52B7236, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1747225604.804210][19585:19585] CHIP:ZCL: Using ZAP configuration... [1747225604.807856][19585:19585] CHIP:DL: Avahi client registered [1747225604.807997][19585:19585] CHIP:CTL: System State Initialized... [1747225604.808184][19585:19585] CHIP:CTL: Setting attestation nonce to random value [1747225604.808240][19585:19585] CHIP:CTL: Setting CSR nonce to random value [1747225604.808320][19585:19585] CHIP:IN: UDP::Init bind&listen port=5550 [1747225604.808457][19585:19585] CHIP:IN: UDP::Init bound to port=5550 [1747225604.808479][19585:19585] CHIP:IN: TransportMgr initialized [1747225604.808765][19585:19587] CHIP:DL: CHIP task running [1747225604.808957][19585:19587] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1747225604.809263][19585:19587] CHIP:CTL: Setting attestation nonce to random value [1747225604.809420][19585:19587] CHIP:CTL: Setting CSR nonce to random value [1747225604.810373][19585:19587] CHIP:CTL: Generating NOC [1747225604.811239][19585:19587] CHIP:FP: Validating NOC chain [1747225604.813122][19585:19587] CHIP:FP: NOC chain validation successful [1747225604.813289][19585:19587] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1747225604.813323][19585:19587] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1747225604.813346][19585:19587] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1747225604.813367][19585:19587] CHIP:TS: Retaining current Last Known Good Time [1747225604.818141][19585:19587] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1747225604.819984][19585:19587] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48 [1747225604.821666][19585:19587] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: E62A29F0B52B7236) [1747225604.821719][19585:19587] CHIP:IN: UDP::Init bind&listen port=5550 [1747225604.821841][19585:19587] CHIP:IN: UDP::Init bound to port=5550 [1747225604.821865][19585:19587] CHIP:IN: TransportMgr initialized [1747225604.847891][19585:19587] CHIP:CSM: FindOrEstablishSession: PeerId = [1:C57022EBC6624A46] [1747225604.847944][19585:19587] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1747225604.847979][19585:19587] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 1 --> 2 [1747225604.848013][19585:19587] CHIP:DIS: Resolving E62A29F0B52B7236:C57022EBC6624A46 ... [1747225604.849628][19585:19587] CHIP:DL: Avahi resolve found [1747225604.849697][19585:19587] CHIP:DIS: Node ID resolved for E62A29F0B52B7236:C57022EBC6624A46 [1747225604.849719][19585:19587] CHIP:DIS: Hostname: 3E60856AC9F1A6F8 [1747225604.849744][19585:19587] CHIP:DIS: IP Address #1: fd11:35::d92:331a:246b:35c8 [1747225604.849764][19585:19587] CHIP:DIS: Port: 5540 [1747225604.849783][19585:19587] CHIP:DIS: Mrp Interval idle: 5000 ms [1747225604.849802][19585:19587] CHIP:DIS: Mrp Interval active: 2500 ms [1747225604.849823][19585:19587] CHIP:DIS: Mrp Active Threshold: 500 ms [1747225604.849843][19585:19587] CHIP:DIS: TCP Supported: 0 [1747225604.849862][19585:19587] CHIP:DIS: ICD: not present [1747225604.850688][19585:19587] CHIP:DIS: Lookup clearing interface for non LL address [1747225604.850781][19585:19587] CHIP:DIS: UDP:[fd11:35::d92:331a:246b:35c8%vethb57ca26]:5540: new best score: 5 [1747225604.850804][19585:19587] CHIP:DIS: Checking node lookup status after 3 ms [1747225604.850823][19585:19587] CHIP:DIS: Keeping DNSSD lookup active [1747225605.048138][19585:19587] CHIP:DIS: Checking node lookup status after 201 ms [1747225605.048274][19585:19587] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: Updating device address to UDP:[fd11:35::d92:331a:246b:35c8]:5540 while in state 2 [1747225605.048334][19585:19587] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 2 --> 3 [1747225605.048651][19585:19587] CHIP:IN: SecureSession[0xffffac00edd0]: Allocated Type:2 LSID:46012 [1747225605.048753][19585:19587] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0xC57022EBC6624A46 [1747225605.050757][19585:19587] CHIP:EM: <<< [E:1259i S:0 M:27417373] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1747225605.051243][19585:19587] CHIP:SC: Sent Sigma1 msg [1747225605.051319][19585:19587] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 3 --> 4 [1747225606.050669][19585:19587] CHIP:EM: >>> [E:1259i S:0 M:160472354 (Ack:27417373)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747225606.050761][19585:19587] CHIP:EM: Found matching exchange: 1259i, Delegate: 0xffffac00eb28 [1747225606.050838][19585:19587] CHIP:EM: Rxd Ack; Removing MessageCounter:27417373 from Retrans Table on exchange 1259i [1747225606.223852][19585:19587] CHIP:EM: >>> [E:1259i S:0 M:160472355 (Ack:27417373)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1747225606.223945][19585:19587] CHIP:EM: Found matching exchange: 1259i, Delegate: 0xffffac00eb28 [1747225606.223999][19585:19587] CHIP:EM: CHIP MessageCounter:27417373 not in RetransTable on exchange 1259i [1747225606.224095][19585:19587] CHIP:SC: Received Sigma2 msg [1747225606.224171][19585:19587] CHIP:SC: Peer assigned session session ID 28367 [1747225606.232718][19585:19587] CHIP:SC: Found MRP parameters in the message [1747225606.232840][19585:19587] CHIP:SC: Sending Sigma3 [1747225606.234209][19585:19587] CHIP:EM: <<< [E:1259i S:0 M:27417374 (Ack:160472355)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1747225606.234581][19585:19587] CHIP:SC: Sent Sigma3 msg [1747225606.619892][19585:19587] CHIP:EM: >>> [E:1259i S:0 M:160472356 (Ack:27417374)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747225606.619992][19585:19587] CHIP:EM: Found matching exchange: 1259i, Delegate: 0xffffac00eb28 [1747225606.620073][19585:19587] CHIP:EM: Rxd Ack; Removing MessageCounter:27417374 from Retrans Table on exchange 1259i [1747225606.839771][19585:19587] CHIP:EM: >>> [E:1259i S:0 M:160472357 (Ack:27417374)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1747225606.839859][19585:19587] CHIP:EM: Found matching exchange: 1259i, Delegate: 0xffffac00eb28 [1747225606.839914][19585:19587] CHIP:EM: CHIP MessageCounter:27417374 not in RetransTable on exchange 1259i [1747225606.840009][19585:19587] CHIP:SC: Success status report received. Session was established [1747225606.845690][19585:19587] CHIP:SC: SecureSession[0xffffac00edd0, LSID:46012]: State change 'kEstablishing' --> 'kActive' [1747225606.845785][19585:19587] CHIP:IN: SecureSession[0xffffac00edd0]: Activated - Type:2 LSID:46012 [1747225606.845832][19585:19587] CHIP:IN: New secure session activated for device , LSID:46012 PSID:28367! [1747225606.845889][19585:19587] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 4 --> 5 [1747225606.846043][19585:19587] CHIP:DMG: SendReadRequest ReadClient[0xffffac00a4c0]: Sending Read Request [1747225606.846696][19585:19587] CHIP:EM: <<< [E:1260i S:46012 M:214171360] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0001:02 (IM:ReadRequest) [1747225606.847041][19585:19587] CHIP:DMG: MoveToState ReadClient[0xffffac00a4c0]: Moving to [AwaitingIn] [1747225606.847316][19585:19587] CHIP:EM: <<< [E:1259i S:0 M:27417375 (Ack:160472357)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747225606.847590][19585:19587] CHIP:EM: Flushed pending ack for MessageCounter:160472357 on exchange 1259i [1747225607.130829][19585:19587] CHIP:EM: >>> [E:1260i S:46012 M:176753862 (Ack:214171360)] (S) Msg RX from 1:C57022EBC6624A46 [7236] --- Type 0001:05 (IM:ReportData) [1747225607.130912][19585:19587] CHIP:EM: Found matching exchange: 1260i, Delegate: 0xffffac00a4d0 [1747225607.130980][19585:19587] CHIP:EM: Rxd Ack; Removing MessageCounter:214171360 from Retrans Table on exchange 1260i [1747225607.131085][19585:19587] CHIP:DMG: ReportDataMessage = [1747225607.131133][19585:19587] CHIP:DMG: { [1747225607.131174][19585:19587] CHIP:DMG: AttributeReportIBs = [1747225607.131232][19585:19587] CHIP:DMG: [ [1747225607.131276][19585:19587] CHIP:DMG: AttributeReportIB = [1747225607.131335][19585:19587] CHIP:DMG: { [1747225607.131382][19585:19587] CHIP:DMG: AttributeDataIB = [1747225607.131441][19585:19587] CHIP:DMG: { [1747225607.131499][19585:19587] CHIP:DMG: DataVersion = 0x7215b6c9, [1747225607.131556][19585:19587] CHIP:DMG: AttributePathIB = [1747225607.131614][19585:19587] CHIP:DMG: { [1747225607.131672][19585:19587] CHIP:DMG: Endpoint = 0x0, [1747225607.131739][19585:19587] CHIP:DMG: Cluster = 0x28, [1747225607.131800][19585:19587] CHIP:DMG: Attribute = 0x0000_0002, [1747225607.131858][19585:19587] CHIP:DMG: } [1747225607.131919][19585:19587] CHIP:DMG: [1747225607.131979][19585:19587] CHIP:DMG: Data = 5547, [1747225607.132034][19585:19587] CHIP:DMG: }, [1747225607.132093][19585:19587] CHIP:DMG: [1747225607.132139][19585:19587] CHIP:DMG: }, [1747225607.132193][19585:19587] CHIP:DMG: [1747225607.132236][19585:19587] CHIP:DMG: ], [1747225607.132291][19585:19587] CHIP:DMG: [1747225607.132336][19585:19587] CHIP:DMG: SuppressResponse = true, [1747225607.132381][19585:19587] CHIP:DMG: InteractionModelRevision = 11 [1747225607.132423][19585:19587] CHIP:DMG: } [1747225607.132667][19585:19587] CHIP:CTL: Received VID for the device. Value 5547 [1747225607.132712][19585:19587] CHIP:CSM: FindOrEstablishSession: PeerId = [1:C57022EBC6624A46] [1747225607.132753][19585:19587] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1747225607.132815][19585:19587] CHIP:DIS: Found an existing secure session to [1:C57022EBC6624A46]! [1747225607.132863][19585:19587] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 1 --> 5 [1747225607.132963][19585:19587] CHIP:DMG: SendReadRequest ReadClient[0xffffac0092c0]: Sending Read Request [1747225607.133321][19585:19587] CHIP:EM: <<< [E:1261i S:46012 M:214171361] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0001:02 (IM:ReadRequest) [1747225607.133621][19585:19587] CHIP:DMG: MoveToState ReadClient[0xffffac0092c0]: Moving to [AwaitingIn] [1747225607.133960][19585:19587] CHIP:EM: <<< [E:1260i S:46012 M:214171362 (Ack:176753862)] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747225607.134195][19585:19587] CHIP:EM: Flushed pending ack for MessageCounter:176753862 on exchange 1260i [1747225607.640457][19585:19587] CHIP:EM: >>> [E:1261i S:46012 M:176753863 (Ack:214171361)] (S) Msg RX from 1:C57022EBC6624A46 [7236] --- Type 0001:05 (IM:ReportData) [1747225607.640540][19585:19587] CHIP:EM: Found matching exchange: 1261i, Delegate: 0xffffac0092d0 [1747225607.640609][19585:19587] CHIP:EM: Rxd Ack; Removing MessageCounter:214171361 from Retrans Table on exchange 1261i [1747225607.640714][19585:19587] CHIP:DMG: ReportDataMessage = [1747225607.640763][19585:19587] CHIP:DMG: { [1747225607.640809][19585:19587] CHIP:DMG: AttributeReportIBs = [1747225607.640875][19585:19587] CHIP:DMG: [ [1747225607.640925][19585:19587] CHIP:DMG: AttributeReportIB = [1747225607.640994][19585:19587] CHIP:DMG: { [1747225607.641048][19585:19587] CHIP:DMG: AttributeDataIB = [1747225607.641112][19585:19587] CHIP:DMG: { [1747225607.641175][19585:19587] CHIP:DMG: DataVersion = 0x7215b6c9, [1747225607.641251][19585:19587] CHIP:DMG: AttributePathIB = [1747225607.641324][19585:19587] CHIP:DMG: { [1747225607.641397][19585:19587] CHIP:DMG: Endpoint = 0x0, [1747225607.641482][19585:19587] CHIP:DMG: Cluster = 0x28, [1747225607.641565][19585:19587] CHIP:DMG: Attribute = 0x0000_0004, [1747225607.641644][19585:19587] CHIP:DMG: } [1747225607.641716][19585:19587] CHIP:DMG: [1747225607.641784][19585:19587] CHIP:DMG: Data = 1, [1747225607.641844][19585:19587] CHIP:DMG: }, [1747225607.641909][19585:19587] CHIP:DMG: [1747225607.641962][19585:19587] CHIP:DMG: }, [1747225607.642023][19585:19587] CHIP:DMG: [1747225607.642072][19585:19587] CHIP:DMG: ], [1747225607.642177][19585:19587] CHIP:DMG: [1747225607.642233][19585:19587] CHIP:DMG: SuppressResponse = true, [1747225607.642285][19585:19587] CHIP:DMG: InteractionModelRevision = 11 [1747225607.642333][19585:19587] CHIP:DMG: } [1747225607.642541][19585:19587] CHIP:CTL: Received PID for the device. Value 1 [1747225607.642592][19585:19587] CHIP:CSM: FindOrEstablishSession: PeerId = [1:C57022EBC6624A46] [1747225607.642638][19585:19587] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1747225607.642703][19585:19587] CHIP:DIS: Found an existing secure session to [1:C57022EBC6624A46]! [1747225607.642757][19585:19587] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 1 --> 5 [1747225607.642819][19585:19587] CHIP:CTL: OpenCommissioningWindow for device ID 0xC57022EBC6624A46 [1747225607.642986][19585:19587] CHIP:DMG: ICR moving to [AddingComm] [1747225607.643103][19585:19587] CHIP:DMG: ICR moving to [AddedComma] [1747225607.643513][19585:19587] CHIP:EM: <<< [E:1262i S:46012 M:214171363] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0001:0A (IM:TimedRequest) [1747225607.643847][19585:19587] CHIP:DMG: ICR moving to [AwaitingTi] [1747225607.644209][19585:19587] CHIP:EM: <<< [E:1261i S:46012 M:214171364 (Ack:176753863)] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747225607.644415][19585:19587] CHIP:EM: Flushed pending ack for MessageCounter:176753863 on exchange 1261i [1747225608.152763][19585:19587] CHIP:EM: >>> [E:1262i S:46012 M:176753864 (Ack:214171363)] (S) Msg RX from 1:C57022EBC6624A46 [7236] --- Type 0001:01 (IM:StatusResponse) [1747225608.152856][19585:19587] CHIP:EM: Found matching exchange: 1262i, Delegate: 0xffffac008628 [1747225608.152933][19585:19587] CHIP:EM: Rxd Ack; Removing MessageCounter:214171363 from Retrans Table on exchange 1262i [1747225608.153036][19585:19587] CHIP:DMG: StatusResponseMessage = [1747225608.153092][19585:19587] CHIP:DMG: { [1747225608.153141][19585:19587] CHIP:DMG: Status = 0x00 (SUCCESS), [1747225608.153195][19585:19587] CHIP:DMG: InteractionModelRevision = 11 [1747225608.153244][19585:19587] CHIP:DMG: } [1747225608.153292][19585:19587] CHIP:IM: Received status response, status is 0x00 (SUCCESS) [1747225608.153651][19585:19587] CHIP:EM: <<< [E:1262i S:46012 M:214171365 (Ack:176753864)] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) [1747225608.153973][19585:19587] CHIP:DMG: ICR moving to [AwaitingRe] [1747225608.725696][19585:19587] CHIP:EM: >>> [E:1262i S:46012 M:176753865 (Ack:214171365)] (S) Msg RX from 1:C57022EBC6624A46 [7236] --- Type 0001:09 (IM:InvokeCommandResponse) [1747225608.725789][19585:19587] CHIP:EM: Found matching exchange: 1262i, Delegate: 0xffffac008628 [1747225608.725866][19585:19587] CHIP:EM: Rxd Ack; Removing MessageCounter:214171365 from Retrans Table on exchange 1262i [1747225608.725938][19585:19587] CHIP:DMG: ICR moving to [ResponseRe] [1747225608.726032][19585:19587] CHIP:DMG: InvokeResponseMessage = [1747225608.726082][19585:19587] CHIP:DMG: { [1747225608.726190][19585:19587] CHIP:DMG: suppressResponse = false, [1747225608.726243][19585:19587] CHIP:DMG: InvokeResponseIBs = [1747225608.726310][19585:19587] CHIP:DMG: [ [1747225608.726359][19585:19587] CHIP:DMG: InvokeResponseIB = [1747225608.726427][19585:19587] CHIP:DMG: { [1747225608.726481][19585:19587] CHIP:DMG: CommandStatusIB = [1747225608.726540][19585:19587] CHIP:DMG: { [1747225608.726597][19585:19587] CHIP:DMG: CommandPathIB = [1747225608.726666][19585:19587] CHIP:DMG: { [1747225608.726733][19585:19587] CHIP:DMG: EndpointId = 0x0, [1747225608.726805][19585:19587] CHIP:DMG: ClusterId = 0x3c, [1747225608.726874][19585:19587] CHIP:DMG: CommandId = 0x0, [1747225608.726939][19585:19587] CHIP:DMG: }, [1747225608.727012][19585:19587] CHIP:DMG: [1747225608.727071][19585:19587] CHIP:DMG: StatusIB = [1747225608.727136][19585:19587] CHIP:DMG: { [1747225608.727202][19585:19587] CHIP:DMG: status = 0x00 (SUCCESS), [1747225608.727267][19585:19587] CHIP:DMG: }, [1747225608.727333][19585:19587] CHIP:DMG: [1747225608.727390][19585:19587] CHIP:DMG: }, [1747225608.727454][19585:19587] CHIP:DMG: [1747225608.727505][19585:19587] CHIP:DMG: }, [1747225608.727567][19585:19587] CHIP:DMG: [1747225608.727615][19585:19587] CHIP:DMG: ], [1747225608.727677][19585:19587] CHIP:DMG: [1747225608.727725][19585:19587] CHIP:DMG: InteractionModelRevision = 11 [1747225608.727773][19585:19587] CHIP:DMG: }, [1747225608.727903][19585:19587] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0000 Status=0x0 [1747225608.727960][19585:19587] CHIP:CTL: Successfully opened pairing window on the device [1747225608.728065][19585:19587] CHIP:CTL: Manual pairing code: [31650857689] [1747225608.728125][19585:19587] CHIP:CTL: SetupQRCode: [MT:WUDA0UZ427.9610Y.10] [1747225608.728263][19585:19587] CHIP:DMG: ICR moving to [AwaitingDe] [1747225608.728609][19585:19587] CHIP:EM: <<< [E:1262i S:46012 M:214171366 (Ack:176753865)] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747225608.728871][19585:19587] CHIP:EM: Flushed pending ack for MessageCounter:176753865 on exchange 1262i [1747225608.729274][19585:19585] CHIP:CTL: Shutting down the commissioner [1747225608.729520][19585:19585] CHIP:CTL: Shutting down the controller [1747225608.729598][19585:19585] CHIP:IN: Expiring all sessions for fabric 0x1!! [1747225608.729642][19585:19585] CHIP:IN: SecureSession[0xffffac00edd0]: MarkForEviction Type:2 LSID:46012 [1747225608.729686][19585:19585] CHIP:SC: SecureSession[0xffffac00edd0, LSID:46012]: State change 'kActive' --> 'kPendingEviction' [1747225608.729729][19585:19585] CHIP:IN: SecureSession[0xffffac00edd0]: Released - Type:2 LSID:46012 [1747225608.729793][19585:19585] CHIP:FP: Forgetting fabric 0x1 [1747225608.729869][19585:19585] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1747225608.730255][19585:19585] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1747225608.730330][19585:19585] CHIP:TS: Reverted Last Known Good Time to previous value [1747225608.730422][19585:19585] CHIP:CTL: Shutting down the commissioner [1747225608.730589][19585:19585] CHIP:CTL: Shutting down the controller [1747225608.730642][19585:19585] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1747225608.730933][19585:19585] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1747225608.731122][19585:19585] CHIP:FP: Shutting down FabricTable [1747225608.731191][19585:19585] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1747225608.731426][19585:19585] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1747225608.731493][19585:19585] CHIP:TS: Reverted Last Known Good Time to previous value [1747225608.731878][19585:19585] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-wngLbn) [1747225608.733051][19585:19585] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1747225608.733171][19585:19585] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1747225608.733223][19585:19585] CHIP:DL: Inet Layer shutdown [1747225608.733268][19585:19585] CHIP:DL: BLE shutdown [1747225608.733316][19585:19585] CHIP:DL: System Layer shutdown ubuntu@ubuntu:~/apps$ ./chip-tool administratorcommissioning read window-status 0xC57022EBC6624A46 0 [1747225695.829523][19615:19615] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs [1747225695.830670][19615:19615] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1747225695.830710][19615:19615] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1747225695.836707][19615:19615] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1747225695.836988][19615:19615] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1747225695.837118][19615:19615] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1747225695.837492][19615:19615] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-dqkZO1) [1747225695.838096][19615:19615] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1747225695.838181][19615:19615] CHIP:DL: NVS set: chip-counters/reboot-count = 15 (0xF) [1747225695.839042][19615:19615] CHIP:DL: Got Ethernet interface: eth0 [1747225695.839609][19615:19615] CHIP:DL: Found the primary Ethernet interface:eth0 [1747225695.840174][19615:19615] CHIP:DL: Got WiFi interface: wlan0 [1747225695.840241][19615:19615] CHIP:DL: Failed to reset WiFi statistic counts [1747225695.840297][19615:19615] CHIP:IN: UDP::Init bind&listen port=0 [1747225695.840424][19615:19615] CHIP:IN: UDP::Init bound to port=59689 [1747225695.840447][19615:19615] CHIP:IN: BLEBase::Init - setting/overriding transport [1747225695.840474][19615:19615] CHIP:IN: TransportMgr initialized [1747225695.840540][19615:19615] CHIP:FP: Initializing FabricTable from persistent storage [1747225695.840698][19615:19615] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1747225695.842200][19615:19615] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xE62A29F0B52B7236, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1747225695.844464][19615:19615] CHIP:ZCL: Using ZAP configuration... [1747225695.848201][19615:19615] CHIP:DL: Avahi client registered [1747225695.848328][19615:19615] CHIP:CTL: System State Initialized... [1747225695.848499][19615:19615] CHIP:CTL: Setting attestation nonce to random value [1747225695.848538][19615:19615] CHIP:CTL: Setting CSR nonce to random value [1747225695.848607][19615:19615] CHIP:IN: UDP::Init bind&listen port=5550 [1747225695.848728][19615:19615] CHIP:IN: UDP::Init bound to port=5550 [1747225695.848748][19615:19615] CHIP:IN: TransportMgr initialized [1747225695.849014][19615:19617] CHIP:DL: CHIP task running [1747225695.849188][19615:19617] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1747225695.849489][19615:19617] CHIP:CTL: Setting attestation nonce to random value [1747225695.849646][19615:19617] CHIP:CTL: Setting CSR nonce to random value [1747225695.850568][19615:19617] CHIP:CTL: Generating NOC [1747225695.851514][19615:19617] CHIP:FP: Validating NOC chain [1747225695.853636][19615:19617] CHIP:FP: NOC chain validation successful [1747225695.853913][19615:19617] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1747225695.853955][19615:19617] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1747225695.853981][19615:19617] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1747225695.854056][19615:19617] CHIP:TS: Retaining current Last Known Good Time [1747225695.859381][19615:19617] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1747225695.861269][19615:19617] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48 [1747225695.862922][19615:19617] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: E62A29F0B52B7236) [1747225695.862975][19615:19617] CHIP:IN: UDP::Init bind&listen port=5550 [1747225695.863151][19615:19617] CHIP:IN: UDP::Init bound to port=5550 [1747225695.863176][19615:19617] CHIP:IN: TransportMgr initialized [1747225695.877620][19615:19617] CHIP:TOO: Sending command to node 0xc57022ebc6624a46 [1747225695.878538][19615:19617] CHIP:CSM: FindOrEstablishSession: PeerId = [1:C57022EBC6624A46] [1747225695.878571][19615:19617] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1747225695.878605][19615:19617] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 1 --> 2 [1747225695.878637][19615:19617] CHIP:DIS: Resolving E62A29F0B52B7236:C57022EBC6624A46 ... [1747225695.880315][19615:19617] CHIP:DL: Avahi resolve found [1747225695.880386][19615:19617] CHIP:DIS: Node ID resolved for E62A29F0B52B7236:C57022EBC6624A46 [1747225695.880408][19615:19617] CHIP:DIS: Hostname: 3E60856AC9F1A6F8 [1747225695.880433][19615:19617] CHIP:DIS: IP Address #1: fd11:35::d92:331a:246b:35c8 [1747225695.880454][19615:19617] CHIP:DIS: Port: 5540 [1747225695.880473][19615:19617] CHIP:DIS: Mrp Interval idle: 5000 ms [1747225695.880490][19615:19617] CHIP:DIS: Mrp Interval active: 2500 ms [1747225695.880508][19615:19617] CHIP:DIS: Mrp Active Threshold: 500 ms [1747225695.880527][19615:19617] CHIP:DIS: TCP Supported: 0 [1747225695.880561][19615:19617] CHIP:DIS: ICD: not present [1747225695.881271][19615:19617] CHIP:DIS: Lookup clearing interface for non LL address [1747225695.881359][19615:19617] CHIP:DIS: UDP:[fd11:35::d92:331a:246b:35c8%vethb57ca26]:5540: new best score: 5 [1747225695.881383][19615:19617] CHIP:DIS: Checking node lookup status after 3 ms [1747225695.881402][19615:19617] CHIP:DIS: Keeping DNSSD lookup active [1747225696.078763][19615:19617] CHIP:DIS: Checking node lookup status after 200 ms [1747225696.078902][19615:19617] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: Updating device address to UDP:[fd11:35::d92:331a:246b:35c8]:5540 while in state 2 [1747225696.078963][19615:19617] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 2 --> 3 [1747225696.079283][19615:19617] CHIP:IN: SecureSession[0xffff900107e0]: Allocated Type:2 LSID:61562 [1747225696.079418][19615:19617] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0xC57022EBC6624A46 [1747225696.081363][19615:19617] CHIP:EM: <<< [E:11439i S:0 M:200125685] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1747225696.081812][19615:19617] CHIP:SC: Sent Sigma1 msg [1747225696.081920][19615:19617] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 3 --> 4 [1747225696.417395][19615:19617] CHIP:EM: >>> [E:11439i S:0 M:160472358 (Ack:200125685)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747225696.417483][19615:19617] CHIP:EM: Found matching exchange: 11439i, Delegate: 0xffff90010538 [1747225696.417559][19615:19617] CHIP:EM: Rxd Ack; Removing MessageCounter:200125685 from Retrans Table on exchange 11439i [1747225696.588498][19615:19617] CHIP:EM: >>> [E:11439i S:0 M:160472359 (Ack:200125685)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1747225696.588589][19615:19617] CHIP:EM: Found matching exchange: 11439i, Delegate: 0xffff90010538 [1747225696.588645][19615:19617] CHIP:EM: CHIP MessageCounter:200125685 not in RetransTable on exchange 11439i [1747225696.588740][19615:19617] CHIP:SC: Received Sigma2 msg [1747225696.588816][19615:19617] CHIP:SC: Peer assigned session session ID 28368 [1747225696.597535][19615:19617] CHIP:SC: Found MRP parameters in the message [1747225696.597659][19615:19617] CHIP:SC: Sending Sigma3 [1747225696.598991][19615:19617] CHIP:EM: <<< [E:11439i S:0 M:200125686 (Ack:160472359)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1747225696.599262][19615:19617] CHIP:SC: Sent Sigma3 msg [1747225696.994730][19615:19617] CHIP:EM: >>> [E:11439i S:0 M:160472360 (Ack:200125686)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747225696.994818][19615:19617] CHIP:EM: Found matching exchange: 11439i, Delegate: 0xffff90010538 [1747225696.994895][19615:19617] CHIP:EM: Rxd Ack; Removing MessageCounter:200125686 from Retrans Table on exchange 11439i [1747225697.216384][19615:19617] CHIP:EM: >>> [E:11439i S:0 M:160472361 (Ack:200125686)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1747225697.216483][19615:19617] CHIP:EM: Found matching exchange: 11439i, Delegate: 0xffff90010538 [1747225697.216546][19615:19617] CHIP:EM: CHIP MessageCounter:200125686 not in RetransTable on exchange 11439i [1747225697.216655][19615:19617] CHIP:SC: Success status report received. Session was established [1747225697.223305][19615:19617] CHIP:SC: SecureSession[0xffff900107e0, LSID:61562]: State change 'kEstablishing' --> 'kActive' [1747225697.223409][19615:19617] CHIP:IN: SecureSession[0xffff900107e0]: Activated - Type:2 LSID:61562 [1747225697.223464][19615:19617] CHIP:IN: New secure session activated for device , LSID:61562 PSID:28368! [1747225697.223529][19615:19617] CHIP:DIS: OperationalSessionSetup[1:C57022EBC6624A46]: State change 4 --> 5 [1747225697.223669][19615:19617] CHIP:TOO: Sending ReadAttribute to: [1747225697.223831][19615:19617] CHIP:TOO: cluster 0x0000_003C, attribute: 0x0000_0000, endpoint 0 [1747225697.223922][19615:19617] CHIP:DMG: SendReadRequest ReadClient[0xffff9000a4c0]: Sending Read Request [1747225697.224526][19615:19617] CHIP:EM: <<< [E:11440i S:61562 M:79681768] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0001:02 (IM:ReadRequest) [1747225697.224910][19615:19617] CHIP:DMG: MoveToState ReadClient[0xffff9000a4c0]: Moving to [AwaitingIn] [1747225697.225260][19615:19617] CHIP:EM: <<< [E:11439i S:0 M:200125687 (Ack:160472361)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747225697.225499][19615:19617] CHIP:EM: Flushed pending ack for MessageCounter:160472361 on exchange 11439i [1747225697.493081][19615:19617] CHIP:EM: >>> [E:11440i S:61562 M:225803355 (Ack:79681768)] (S) Msg RX from 1:C57022EBC6624A46 [7236] --- Type 0001:05 (IM:ReportData) [1747225697.493173][19615:19617] CHIP:EM: Found matching exchange: 11440i, Delegate: 0xffff9000a4d0 [1747225697.493250][19615:19617] CHIP:EM: Rxd Ack; Removing MessageCounter:79681768 from Retrans Table on exchange 11440i [1747225697.493367][19615:19617] CHIP:DMG: ReportDataMessage = [1747225697.493424][19615:19617] CHIP:DMG: { [1747225697.493468][19615:19617] CHIP:DMG: AttributeReportIBs = [1747225697.493533][19615:19617] CHIP:DMG: [ [1747225697.493583][19615:19617] CHIP:DMG: AttributeReportIB = [1747225697.493650][19615:19617] CHIP:DMG: { [1747225697.493704][19615:19617] CHIP:DMG: AttributeDataIB = [1747225697.493777][19615:19617] CHIP:DMG: { [1747225697.493844][19615:19617] CHIP:DMG: DataVersion = 0x7fdd000e, [1747225697.493907][19615:19617] CHIP:DMG: AttributePathIB = [1747225697.493972][19615:19617] CHIP:DMG: { [1747225697.494038][19615:19617] CHIP:DMG: Endpoint = 0x0, [1747225697.494163][19615:19617] CHIP:DMG: Cluster = 0x3c, [1747225697.494236][19615:19617] CHIP:DMG: Attribute = 0x0000_0000, [1747225697.494302][19615:19617] CHIP:DMG: } [1747225697.494372][19615:19617] CHIP:DMG: [1747225697.494439][19615:19617] CHIP:DMG: Data = 1, [1747225697.494500][19615:19617] CHIP:DMG: }, [1747225697.494566][19615:19617] CHIP:DMG: [1747225697.494618][19615:19617] CHIP:DMG: }, [1747225697.494681][19615:19617] CHIP:DMG: [1747225697.494728][19615:19617] CHIP:DMG: ], [1747225697.494791][19615:19617] CHIP:DMG: [1747225697.494840][19615:19617] CHIP:DMG: SuppressResponse = true, [1747225697.494890][19615:19617] CHIP:DMG: InteractionModelRevision = 11 [1747225697.494937][19615:19617] CHIP:DMG: } [1747225697.495210][19615:19617] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_003C Attribute 0x0000_0000 DataVersion: 2145189902 [1747225697.495349][19615:19617] CHIP:TOO: WindowStatus: 1 [1747225697.495794][19615:19617] CHIP:EM: <<< [E:11440i S:61562 M:79681769 (Ack:225803355)] (S) Msg TX to 1:C57022EBC6624A46 [7236] [UDP:[fd11:35::d92:331a:246b:35c8%wpan0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747225697.496052][19615:19617] CHIP:EM: Flushed pending ack for MessageCounter:225803355 on exchange 11440i [1747225697.496399][19615:19615] CHIP:CTL: Shutting down the commissioner [1747225697.496672][19615:19615] CHIP:CTL: Shutting down the controller [1747225697.496771][19615:19615] CHIP:IN: Expiring all sessions for fabric 0x1!! [1747225697.496820][19615:19615] CHIP:IN: SecureSession[0xffff900107e0]: MarkForEviction Type:2 LSID:61562 [1747225697.496868][19615:19615] CHIP:SC: SecureSession[0xffff900107e0, LSID:61562]: State change 'kActive' --> 'kPendingEviction' [1747225697.497021][19615:19615] CHIP:IN: SecureSession[0xffff900107e0]: Released - Type:2 LSID:61562 [1747225697.497367][19615:19615] CHIP:FP: Forgetting fabric 0x1 [1747225697.497444][19615:19615] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1747225697.497763][19615:19615] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1747225697.497835][19615:19615] CHIP:TS: Reverted Last Known Good Time to previous value [1747225697.497920][19615:19615] CHIP:CTL: Shutting down the commissioner [1747225697.498096][19615:19615] CHIP:CTL: Shutting down the controller [1747225697.498214][19615:19615] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1747225697.498545][19615:19615] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1747225697.498732][19615:19615] CHIP:FP: Shutting down FabricTable [1747225697.498801][19615:19615] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1747225697.499048][19615:19615] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1747225697.499112][19615:19615] CHIP:TS: Reverted Last Known Good Time to previous value [1747225697.499512][19615:19615] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-r8nzNa) [1747225697.500655][19615:19615] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1747225697.500778][19615:19615] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1747225697.500827][19615:19615] CHIP:DL: Inet Layer shutdown [1747225697.500871][19615:19615] CHIP:DL: BLE shutdown [1747225697.500920][19615:19615] CHIP:DL: System Layer shutdown ubuntu@ubuntu:~/apps$