ubuntu@ubuntu:~/apps$ ./chip-tool pairing open-commissioning-window 1 1 901 2000 3423 [1747181689.846912][3900:3900] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs [1747181689.848043][3900:3900] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1747181689.848086][3900:3900] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs [1747181689.853309][3900:3900] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1747181689.853626][3900:3900] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1747181689.853768][3900:3900] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1747181689.854087][3900:3900] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-Fhy44B) [1747181689.854726][3900:3900] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1747181689.854783][3900:3900] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2) [1747181689.855719][3900:3900] CHIP:DL: Got Ethernet interface: eth0 [1747181689.856365][3900:3900] CHIP:DL: Found the primary Ethernet interface:eth0 [1747181689.857046][3900:3900] CHIP:DL: Got WiFi interface: wlan0 [1747181689.857119][3900:3900] CHIP:DL: Failed to reset WiFi statistic counts [1747181689.857175][3900:3900] CHIP:IN: UDP::Init bind&listen port=0 [1747181689.857302][3900:3900] CHIP:IN: UDP::Init bound to port=59696 [1747181689.857326][3900:3900] CHIP:IN: BLEBase::Init - setting/overriding transport [1747181689.857355][3900:3900] CHIP:IN: TransportMgr initialized [1747181689.857408][3900:3900] CHIP:FP: Initializing FabricTable from persistent storage [1747181689.857581][3900:3900] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1747181689.859159][3900:3900] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x9FF6358D4C9156A9, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1747181689.861352][3900:3900] CHIP:ZCL: Using ZAP configuration... [1747181689.865075][3900:3900] CHIP:DL: Avahi client registered [1747181689.865194][3900:3900] CHIP:CTL: System State Initialized... [1747181689.865376][3900:3900] CHIP:CTL: Setting attestation nonce to random value [1747181689.865436][3900:3900] CHIP:CTL: Setting CSR nonce to random value [1747181689.865521][3900:3900] CHIP:IN: UDP::Init bind&listen port=5550 [1747181689.865673][3900:3900] CHIP:IN: UDP::Init bound to port=5550 [1747181689.865697][3900:3900] CHIP:IN: TransportMgr initialized [1747181689.866013][3900:3902] CHIP:DL: CHIP task running [1747181689.866248][3900:3902] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 [1747181689.866625][3900:3902] CHIP:CTL: Setting attestation nonce to random value [1747181689.866852][3900:3902] CHIP:CTL: Setting CSR nonce to random value [1747181689.867895][3900:3902] CHIP:CTL: Generating NOC [1747181689.868860][3900:3902] CHIP:FP: Validating NOC chain [1747181689.870827][3900:3902] CHIP:FP: NOC chain validation successful [1747181689.870996][3900:3902] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669 [1747181689.871030][3900:3902] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1747181689.871054][3900:3902] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00 [1747181689.871074][3900:3902] CHIP:TS: Retaining current Last Known Good Time [1747181689.876098][3900:3902] CHIP:FP: Metadata for Fabric 0x1 persisted to storage. [1747181689.877930][3900:3902] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48 [1747181689.879560][3900:3902] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 9FF6358D4C9156A9) [1747181689.879612][3900:3902] CHIP:IN: UDP::Init bind&listen port=5550 [1747181689.879722][3900:3902] CHIP:IN: UDP::Init bound to port=5550 [1747181689.879744][3900:3902] CHIP:IN: TransportMgr initialized [1747181689.902398][3900:3902] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1747181689.902450][3900:3902] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1747181689.902484][3900:3902] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2 [1747181689.902516][3900:3902] CHIP:DIS: Resolving 9FF6358D4C9156A9:0000000000000001 ... [1747181689.904085][3900:3902] CHIP:DL: Avahi resolve found [1747181689.904153][3900:3902] CHIP:DIS: Node ID resolved for 9FF6358D4C9156A9:0000000000000001 [1747181689.904174][3900:3902] CHIP:DIS: Hostname: 7E09CFA3BB2EF4F3 [1747181689.904198][3900:3902] CHIP:DIS: IP Address #1: fd11:22::3982:2271:515d:4a83 [1747181689.904218][3900:3902] CHIP:DIS: Port: 5540 [1747181689.904237][3900:3902] CHIP:DIS: Mrp Interval idle: 5000 ms [1747181689.904255][3900:3902] CHIP:DIS: Mrp Interval active: 2500 ms [1747181689.904274][3900:3902] CHIP:DIS: Mrp Active Threshold: 500 ms [1747181689.904292][3900:3902] CHIP:DIS: TCP Supported: 0 [1747181689.904309][3900:3902] CHIP:DIS: ICD: not present [1747181689.905098][3900:3902] CHIP:DIS: Lookup clearing interface for non LL address [1747181689.905188][3900:3902] CHIP:DIS: UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540: new best score: 3 [1747181689.905211][3900:3902] CHIP:DIS: Checking node lookup status after 2 ms [1747181689.905229][3900:3902] CHIP:DIS: Keeping DNSSD lookup active [1747181690.103565][3900:3902] CHIP:DIS: Checking node lookup status after 201 ms [1747181690.103705][3900:3902] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:22::3982:2271:515d:4a83]:5540 while in state 2 [1747181690.103768][3900:3902] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3 [1747181690.104088][3900:3902] CHIP:IN: SecureSession[0xffff7000edd0]: Allocated Type:2 LSID:4449 [1747181690.104191][3900:3902] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001 [1747181690.106396][3900:3902] CHIP:EM: <<< [E:37782i S:0 M:215371205] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::3982:2271:515d:4a83]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [1747181690.106973][3900:3902] CHIP:SC: Sent Sigma1 msg [1747181690.107053][3900:3902] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4 [1747181690.475051][3900:3902] CHIP:EM: >>> [E:37782i S:0 M:157386237 (Ack:215371205)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747181690.475153][3900:3902] CHIP:EM: Found matching exchange: 37782i, Delegate: 0xffff7000eb28 [1747181690.475234][3900:3902] CHIP:EM: Rxd Ack; Removing MessageCounter:215371205 from Retrans Table on exchange 37782i [1747181690.622962][3900:3902] CHIP:EM: >>> [E:37782i S:0 M:157386238 (Ack:215371205)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [1747181690.623068][3900:3902] CHIP:EM: Found matching exchange: 37782i, Delegate: 0xffff7000eb28 [1747181690.623132][3900:3902] CHIP:EM: CHIP MessageCounter:215371205 not in RetransTable on exchange 37782i [1747181690.623240][3900:3902] CHIP:SC: Received Sigma2 msg [1747181690.623327][3900:3902] CHIP:SC: Peer assigned session session ID 6268 [1747181690.632020][3900:3902] CHIP:SC: Found MRP parameters in the message [1747181690.632143][3900:3902] CHIP:SC: Sending Sigma3 [1747181690.633433][3900:3902] CHIP:EM: <<< [E:37782i S:0 M:215371206 (Ack:157386238)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [1747181690.633884][3900:3902] CHIP:SC: Sent Sigma3 msg [1747181691.060155][3900:3902] CHIP:EM: >>> [E:37782i S:0 M:157386239 (Ack:215371206)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747181691.060216][3900:3902] CHIP:EM: Found matching exchange: 37782i, Delegate: 0xffff7000eb28 [1747181691.060264][3900:3902] CHIP:EM: Rxd Ack; Removing MessageCounter:215371206 from Retrans Table on exchange 37782i [1747181691.247417][3900:3902] CHIP:EM: >>> [E:37782i S:0 M:157386240 (Ack:215371206)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [1747181691.247518][3900:3902] CHIP:EM: Found matching exchange: 37782i, Delegate: 0xffff7000eb28 [1747181691.247582][3900:3902] CHIP:EM: CHIP MessageCounter:215371206 not in RetransTable on exchange 37782i [1747181691.247688][3900:3902] CHIP:SC: Success status report received. Session was established [1747181691.254415][3900:3902] CHIP:SC: SecureSession[0xffff7000edd0, LSID:4449]: State change 'kEstablishing' --> 'kActive' [1747181691.254514][3900:3902] CHIP:IN: SecureSession[0xffff7000edd0]: Activated - Type:2 LSID:4449 [1747181691.254568][3900:3902] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:4449 PSID:6268! [1747181691.254634][3900:3902] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5 [1747181691.254876][3900:3902] CHIP:DMG: SendReadRequest ReadClient[0xffff7000a4c0]: Sending Read Request [1747181691.255413][3900:3902] CHIP:EM: <<< [E:37783i S:4449 M:120802994] (S) Msg TX to 1:0000000000000001 [56A9] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0001:02 (IM:ReadRequest) [1747181691.256003][3900:3902] CHIP:DMG: MoveToState ReadClient[0xffff7000a4c0]: Moving to [AwaitingIn] [1747181691.256339][3900:3902] CHIP:EM: <<< [E:37782i S:0 M:215371207 (Ack:157386240)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747181691.256652][3900:3902] CHIP:EM: Flushed pending ack for MessageCounter:157386240 on exchange 37782i [1747181691.580238][3900:3902] CHIP:EM: >>> [E:37783i S:4449 M:99251886 (Ack:120802994)] (S) Msg RX from 1:0000000000000001 [56A9] --- Type 0001:05 (IM:ReportData) [1747181691.580305][3900:3902] CHIP:EM: Found matching exchange: 37783i, Delegate: 0xffff7000a4d0 [1747181691.580358][3900:3902] CHIP:EM: Rxd Ack; Removing MessageCounter:120802994 from Retrans Table on exchange 37783i [1747181691.580439][3900:3902] CHIP:DMG: ReportDataMessage = [1747181691.580473][3900:3902] CHIP:DMG: { [1747181691.580501][3900:3902] CHIP:DMG: AttributeReportIBs = [1747181691.580541][3900:3902] CHIP:DMG: [ [1747181691.580570][3900:3902] CHIP:DMG: AttributeReportIB = [1747181691.580636][3900:3902] CHIP:DMG: { [1747181691.580669][3900:3902] CHIP:DMG: AttributeDataIB = [1747181691.580705][3900:3902] CHIP:DMG: { [1747181691.580758][3900:3902] CHIP:DMG: DataVersion = 0xfd1b1703, [1747181691.580805][3900:3902] CHIP:DMG: AttributePathIB = [1747181691.580856][3900:3902] CHIP:DMG: { [1747181691.580895][3900:3902] CHIP:DMG: Endpoint = 0x0, [1747181691.580949][3900:3902] CHIP:DMG: Cluster = 0x28, [1747181691.580990][3900:3902] CHIP:DMG: Attribute = 0x0000_0002, [1747181691.581039][3900:3902] CHIP:DMG: } [1747181691.581081][3900:3902] CHIP:DMG: [1747181691.581122][3900:3902] CHIP:DMG: Data = 5547, [1747181691.581171][3900:3902] CHIP:DMG: }, [1747181691.581211][3900:3902] CHIP:DMG: [1747181691.581254][3900:3902] CHIP:DMG: }, [1747181691.581291][3900:3902] CHIP:DMG: [1747181691.581332][3900:3902] CHIP:DMG: ], [1747181691.581372][3900:3902] CHIP:DMG: [1747181691.581403][3900:3902] CHIP:DMG: SuppressResponse = true, [1747181691.581447][3900:3902] CHIP:DMG: InteractionModelRevision = 11 [1747181691.581476][3900:3902] CHIP:DMG: } [1747181691.581691][3900:3902] CHIP:CTL: Received VID for the device. Value 5547 [1747181691.581726][3900:3902] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1747181691.581755][3900:3902] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1747181691.581799][3900:3902] CHIP:DIS: Found an existing secure session to [1:0000000000000001]! [1747181691.581835][3900:3902] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5 [1747181691.581926][3900:3902] CHIP:DMG: SendReadRequest ReadClient[0xffff700092c0]: Sending Read Request [1747181691.582215][3900:3902] CHIP:EM: <<< [E:37784i S:4449 M:120802995] (S) Msg TX to 1:0000000000000001 [56A9] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0001:02 (IM:ReadRequest) [1747181691.582509][3900:3902] CHIP:DMG: MoveToState ReadClient[0xffff700092c0]: Moving to [AwaitingIn] [1747181691.582769][3900:3902] CHIP:EM: <<< [E:37783i S:4449 M:120802996 (Ack:99251886)] (S) Msg TX to 1:0000000000000001 [56A9] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747181691.582926][3900:3902] CHIP:EM: Flushed pending ack for MessageCounter:99251886 on exchange 37783i [1747181692.091910][3900:3902] CHIP:EM: >>> [E:37784i S:4449 M:99251887 (Ack:120802995)] (S) Msg RX from 1:0000000000000001 [56A9] --- Type 0001:05 (IM:ReportData) [1747181692.091996][3900:3902] CHIP:EM: Found matching exchange: 37784i, Delegate: 0xffff700092d0 [1747181692.092065][3900:3902] CHIP:EM: Rxd Ack; Removing MessageCounter:120802995 from Retrans Table on exchange 37784i [1747181692.092173][3900:3902] CHIP:DMG: ReportDataMessage = [1747181692.092222][3900:3902] CHIP:DMG: { [1747181692.092269][3900:3902] CHIP:DMG: AttributeReportIBs = [1747181692.092337][3900:3902] CHIP:DMG: [ [1747181692.092389][3900:3902] CHIP:DMG: AttributeReportIB = [1747181692.092457][3900:3902] CHIP:DMG: { [1747181692.092512][3900:3902] CHIP:DMG: AttributeDataIB = [1747181692.092582][3900:3902] CHIP:DMG: { [1747181692.092645][3900:3902] CHIP:DMG: DataVersion = 0xfd1b1703, [1747181692.092708][3900:3902] CHIP:DMG: AttributePathIB = [1747181692.092775][3900:3902] CHIP:DMG: { [1747181692.092955][3900:3902] CHIP:DMG: Endpoint = 0x0, [1747181692.093029][3900:3902] CHIP:DMG: Cluster = 0x28, [1747181692.093099][3900:3902] CHIP:DMG: Attribute = 0x0000_0004, [1747181692.093221][3900:3902] CHIP:DMG: } [1747181692.093297][3900:3902] CHIP:DMG: [1747181692.093365][3900:3902] CHIP:DMG: Data = 1, [1747181692.093427][3900:3902] CHIP:DMG: }, [1747181692.093497][3900:3902] CHIP:DMG: [1747181692.093610][3900:3902] CHIP:DMG: }, [1747181692.093676][3900:3902] CHIP:DMG: [1747181692.093726][3900:3902] CHIP:DMG: ], [1747181692.093789][3900:3902] CHIP:DMG: [1747181692.093840][3900:3902] CHIP:DMG: SuppressResponse = true, [1747181692.093892][3900:3902] CHIP:DMG: InteractionModelRevision = 11 [1747181692.093940][3900:3902] CHIP:DMG: } [1747181692.094148][3900:3902] CHIP:CTL: Received PID for the device. Value 1 [1747181692.094200][3900:3902] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001] [1747181692.094246][3900:3902] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found [1747181692.094451][3900:3902] CHIP:DIS: Found an existing secure session to [1:0000000000000001]! [1747181692.094512][3900:3902] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 5 [1747181692.094576][3900:3902] CHIP:CTL: OpenCommissioningWindow for device ID 0x0000000000000001 [1747181692.094740][3900:3902] CHIP:DMG: ICR moving to [AddingComm] [1747181692.094860][3900:3902] CHIP:DMG: ICR moving to [AddedComma] [1747181692.095249][3900:3902] CHIP:EM: <<< [E:37785i S:4449 M:120802997] (S) Msg TX to 1:0000000000000001 [56A9] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0001:0A (IM:TimedRequest) [1747181692.095580][3900:3902] CHIP:DMG: ICR moving to [AwaitingTi] [1747181692.095920][3900:3902] CHIP:EM: <<< [E:37784i S:4449 M:120802998 (Ack:99251887)] (S) Msg TX to 1:0000000000000001 [56A9] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747181692.096117][3900:3902] CHIP:EM: Flushed pending ack for MessageCounter:99251887 on exchange 37784i [1747181692.606218][3900:3902] CHIP:EM: >>> [E:37785i S:4449 M:99251888 (Ack:120802997)] (S) Msg RX from 1:0000000000000001 [56A9] --- Type 0001:01 (IM:StatusResponse) [1747181692.606342][3900:3902] CHIP:EM: Found matching exchange: 37785i, Delegate: 0xffff70008628 [1747181692.606415][3900:3902] CHIP:EM: Rxd Ack; Removing MessageCounter:120802997 from Retrans Table on exchange 37785i [1747181692.606512][3900:3902] CHIP:DMG: StatusResponseMessage = [1747181692.606574][3900:3902] CHIP:DMG: { [1747181692.606625][3900:3902] CHIP:DMG: Status = 0x00 (SUCCESS), [1747181692.606678][3900:3902] CHIP:DMG: InteractionModelRevision = 11 [1747181692.606727][3900:3902] CHIP:DMG: } [1747181692.606778][3900:3902] CHIP:IM: Received status response, status is 0x00 (SUCCESS) [1747181692.607127][3900:3902] CHIP:EM: <<< [E:37785i S:4449 M:120802999 (Ack:99251888)] (S) Msg TX to 1:0000000000000001 [56A9] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) [1747181692.607533][3900:3902] CHIP:DMG: ICR moving to [AwaitingRe] [1747181693.136297][3900:3902] CHIP:EM: >>> [E:37785i S:4449 M:99251889 (Ack:120802999)] (S) Msg RX from 1:0000000000000001 [56A9] --- Type 0001:09 (IM:InvokeCommandResponse) [1747181693.136390][3900:3902] CHIP:EM: Found matching exchange: 37785i, Delegate: 0xffff70008628 [1747181693.136468][3900:3902] CHIP:EM: Rxd Ack; Removing MessageCounter:120802999 from Retrans Table on exchange 37785i [1747181693.136544][3900:3902] CHIP:DMG: ICR moving to [ResponseRe] [1747181693.136640][3900:3902] CHIP:DMG: InvokeResponseMessage = [1747181693.136693][3900:3902] CHIP:DMG: { [1747181693.136741][3900:3902] CHIP:DMG: suppressResponse = false, [1747181693.136791][3900:3902] CHIP:DMG: InvokeResponseIBs = [1747181693.136858][3900:3902] CHIP:DMG: [ [1747181693.136907][3900:3902] CHIP:DMG: InvokeResponseIB = [1747181693.136976][3900:3902] CHIP:DMG: { [1747181693.137029][3900:3902] CHIP:DMG: CommandStatusIB = [1747181693.137090][3900:3902] CHIP:DMG: { [1747181693.137145][3900:3902] CHIP:DMG: CommandPathIB = [1747181693.137218][3900:3902] CHIP:DMG: { [1747181693.137288][3900:3902] CHIP:DMG: EndpointId = 0x0, [1747181693.137357][3900:3902] CHIP:DMG: ClusterId = 0x3c, [1747181693.137428][3900:3902] CHIP:DMG: CommandId = 0x0, [1747181693.137495][3900:3902] CHIP:DMG: }, [1747181693.137571][3900:3902] CHIP:DMG: [1747181693.137628][3900:3902] CHIP:DMG: StatusIB = [1747181693.137694][3900:3902] CHIP:DMG: { [1747181693.137763][3900:3902] CHIP:DMG: status = 0x00 (SUCCESS), [1747181693.137831][3900:3902] CHIP:DMG: }, [1747181693.137898][3900:3902] CHIP:DMG: [1747181693.137956][3900:3902] CHIP:DMG: }, [1747181693.138022][3900:3902] CHIP:DMG: [1747181693.138083][3900:3902] CHIP:DMG: }, [1747181693.138148][3900:3902] CHIP:DMG: [1747181693.138196][3900:3902] CHIP:DMG: ], [1747181693.138260][3900:3902] CHIP:DMG: [1747181693.138387][3900:3902] CHIP:DMG: InteractionModelRevision = 11 [1747181693.138437][3900:3902] CHIP:DMG: }, [1747181693.138571][3900:3902] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003C Command=0x0000_0000 Status=0x0 [1747181693.138629][3900:3902] CHIP:CTL: Successfully opened pairing window on the device [1747181693.138733][3900:3902] CHIP:CTL: Manual pairing code: [31711002791] [1747181693.138793][3900:3902] CHIP:CTL: SetupQRCode: [MT:WUDA0UZ427..O74P300] [1747181693.138931][3900:3902] CHIP:DMG: ICR moving to [AwaitingDe] [1747181693.139283][3900:3902] CHIP:EM: <<< [E:37785i S:4449 M:120803000 (Ack:99251889)] (S) Msg TX to 1:0000000000000001 [56A9] [UDP:[fd11:22::3982:2271:515d:4a83%otbr0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [1747181693.139611][3900:3902] CHIP:EM: Flushed pending ack for MessageCounter:99251889 on exchange 37785i [1747181693.140008][3900:3900] CHIP:CTL: Shutting down the commissioner [1747181693.140185][3900:3900] CHIP:CTL: Shutting down the controller [1747181693.140239][3900:3900] CHIP:IN: Expiring all sessions for fabric 0x1!! [1747181693.140284][3900:3900] CHIP:IN: SecureSession[0xffff7000edd0]: MarkForEviction Type:2 LSID:4449 [1747181693.140331][3900:3900] CHIP:SC: SecureSession[0xffff7000edd0, LSID:4449]: State change 'kActive' --> 'kPendingEviction' [1747181693.140378][3900:3900] CHIP:IN: SecureSession[0xffff7000edd0]: Released - Type:2 LSID:4449 [1747181693.140489][3900:3900] CHIP:FP: Forgetting fabric 0x1 [1747181693.140555][3900:3900] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1747181693.140863][3900:3900] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1747181693.140932][3900:3900] CHIP:TS: Reverted Last Known Good Time to previous value [1747181693.141024][3900:3900] CHIP:CTL: Shutting down the commissioner [1747181693.141198][3900:3900] CHIP:CTL: Shutting down the controller [1747181693.141253][3900:3900] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack [1747181693.141546][3900:3900] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet [1747181693.141731][3900:3900] CHIP:FP: Shutting down FabricTable [1747181693.141800][3900:3900] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48 [1747181693.142031][3900:3900] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48 [1747181693.142096][3900:3900] CHIP:TS: Reverted Last Known Good Time to previous value [1747181693.142544][3900:3900] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-xkR8xQ) [1747181693.143676][3900:3900] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1747181693.143792][3900:3900] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0) [1747181693.143843][3900:3900] CHIP:DL: Inet Layer shutdown [1747181693.143886][3900:3900] CHIP:DL: BLE shutdown [1747181693.143934][3900:3900] CHIP:DL: System Layer shutdown