TC-CNET-4.10 Test step 11 timeout.

[hoorii-zzy]

Hi,

      Our product is about to undergo Matter certification. However, in the testing of TC-CNET-4.10, during the 11th step " ./chip-tool generalcommissioning arm-fail-safe 0 0 1 0", there is a timeout error indicating that the command is not responding. However, when executing it immediately for the second time, it succeeds. This phenomenon is consistently reproducible. Can you provide any guidance on how to resolve this issue? We are anxious to proceed with the product testing.

      I'm urgently looking forward to your reply.

      Jerry.

      22/8/2023

[Charlie]

Hi Jerry,

I just checked with your development team. The deeper investigation will take time.

The current solution that we suggest is using the interactive chip-tool to pass the test.

Best regards,

Charlie

[hoorii-zzy]

Charlie said:

The current solution that we suggest is using the interactive chip-tool to pass the test

Do you mead use chip-tool with ./chip-tool interactive start? And what is the next step?

Jerry

[Charlie]

Hi Jerry,

What Test Harness has been used to certify the device and to what version of Matter is it? Matter 1.0 or Matter 1.1?

Best regards,

Charlie

[hoorii-zzy]

Hi Charlie,

The version of the Test Harness is 2.8.1, and the version of Matter is tag: SVE_23_03_rc2.

Jerry.

[Charlie]

Hi Jerry,

We prepared a fix for such issue, can you check if this solution is sufficient?

https://github.com/nrfconnect/sdk-connectedhomeip/pull/324/files

Best regards,

Charlie

[hoorii-zzy]

Hi Charlie,
No problem, I'll verify it immediately.
Also, can you reveal the specific reason that caused it? And why does enabling CONFIG_LOG help to pass through?
BR,
Jerry

[Charlie]

Hi Jerry,

You can refer to the comments from the developer.
 [nrf noup] Enhance/Optimize attach to thread network by doublemis1 · Pull Request #324 · nrfconnect/sdk-connectedhomeip (github.com)

Best regards,
Charlie

[hoorii-zzy]

Hi Charlie,
Thanks for this refer. BTW, it doesn't mention why enabling CONFIG_LOG leads to success here. I'm curious about this reason. Can you provide some clues?
BR,
Jerry

[Charlie]

Hi Jerry,

Here is more explanation:

Moreover, it is a corner case for SED with disabled CONFIG_LOG (tested on NCS 2.4.0 MED Template disabled CONFIG_LOG and it passed). The logging backend utilized by our samples led to slow down the processing next instructions. This may impact some race conditions which cannot be observed using samples with disabled CONFIG_LOG.

We use logger configured in a minimal mode, which results in printing messages in a blocking way (not scheduling the print action to the other thread). After disabling CONFIG_LOG some time relations may change (the actions will typically be done faster).

Best regards,

Charlie

[Charlie]

Hi Jerry,

Here is more explanation:

Moreover, it is a corner case for SED with disabled CONFIG_LOG (tested on NCS 2.4.0 MED Template disabled CONFIG_LOG and it passed). The logging backend utilized by our samples led to slow down the processing next instructions. This may impact some race conditions which cannot be observed using samples with disabled CONFIG_LOG.

We use logger configured in a minimal mode, which results in printing messages in a blocking way (not scheduling the print action to the other thread). After disabling CONFIG_LOG some time relations may change (the actions will typically be done faster).

Best regards,

Charlie

[hoorii-zzy]

Hi Charlie,
I tested your fix strategy for the issue and found that the situation has become worse. Originally, after the first failure, the second attempt would be successful. However, now, after the first failure, subsequent attempts timeout at sigma1, performing even worse than before. Have you tested this on NCS2.2.0? Here is the log from my chip-tool:

ubuntu@ubuntu:~/apps$ ./chip-tool generalcommissioning arm-fail-safe 900 1 1 0
[1694846954.079581][22373:22373] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1694846954.084975][22373:22373] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1694846954.085257][22373:22373] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1694846954.085378][22373:22373] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1694846954.085691][22373:22373] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-D5ODy0)
[1694846954.086260][22373:22373] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694846954.086310][22373:22373] CHIP:DL: NVS set: chip-counters/reboot-count = 2 (0x2)
[1694846954.087306][22373:22373] CHIP:DL: Got Ethernet interface: eth0
[1694846954.087905][22373:22373] CHIP:DL: Found the primary Ethernet interface:eth0
[1694846954.088494][22373:22373] CHIP:DL: Got WiFi interface: wlan0
[1694846954.088554][22373:22373] CHIP:DL: Failed to reset WiFi statistic counts
[1694846954.088640][22373:22373] CHIP:IN: UDP::Init bind&listen port=0
[1694846954.088743][22373:22373] CHIP:IN: UDP::Init bound to port=46490
[1694846954.088763][22373:22373] CHIP:IN: BLEBase::Init - setting/overriding transport
[1694846954.088780][22373:22373] CHIP:IN: TransportMgr initialized
[1694846954.088810][22373:22373] CHIP:FP: Initializing FabricTable from persistent storage
[1694846954.088951][22373:22373] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694846954.090326][22373:22373] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x531C5E1335241DE8, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1694846954.093675][22373:22373] CHIP:ZCL: Using ZAP configuration...
[1694846954.097154][22373:22373] CHIP:DL: Avahi client registered
[1694846954.097276][22373:22373] CHIP:CTL: System State Initialized...
[1694846954.097353][22373:22373] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694846954.097394][22373:22373] CHIP:CTL: Setting attestation nonce to random value
[1694846954.097425][22373:22373] CHIP:CTL: Setting CSR nonce to random value
[1694846954.097480][22373:22373] CHIP:IN: UDP::Init bind&listen port=5550
[1694846954.097596][22373:22373] CHIP:IN: UDP::Init bound to port=5550
[1694846954.097616][22373:22373] CHIP:IN: TransportMgr initialized
[1694846954.097882][22373:22375] CHIP:DL: CHIP task running
[1694846954.098050][22373:22375] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1694846954.098316][22373:22375] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694846954.098363][22373:22375] CHIP:CTL: Setting attestation nonce to random value
[1694846954.098509][22373:22375] CHIP:CTL: Setting CSR nonce to random value
[1694846954.099354][22373:22375] CHIP:CTL: Generating NOC
[1694846954.100185][22373:22375] CHIP:FP: Validating NOC chain
[1694846954.102179][22373:22375] CHIP:FP: NOC chain validation successful
[1694846954.102378][22373:22375] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1694846954.102416][22373:22375] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694846954.102443][22373:22375] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1694846954.102468][22373:22375] CHIP:TS: Retaining current Last Known Good Time
[1694846954.115005][22373:22375] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1694846954.120095][22373:22375] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-25T18:22:45
[1694846954.124849][22373:22375] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 531C5E1335241DE8)
[1694846954.124916][22373:22375] CHIP:IN: UDP::Init bind&listen port=5550
[1694846954.125066][22373:22375] CHIP:IN: UDP::Init bound to port=5550
[1694846954.125098][22373:22375] CHIP:IN: TransportMgr initialized
[1694846954.150404][22373:22375] CHIP:TOO: Sending command to node 0x1
[1694846954.150855][22373:22375] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1694846954.150886][22373:22375] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1694846954.150920][22373:22375] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1694846954.150952][22373:22375] CHIP:DIS: Resolving 531C5E1335241DE8:0000000000000001 ...
[1694846954.152641][22373:22375] CHIP:DL: Avahi resolve found
[1694846954.152713][22373:22375] CHIP:DIS: Node ID resolved for 531C5E1335241DE8:0000000000000001
[1694846954.152736][22373:22375] CHIP:DIS:      Hostname: 1A214799925ACE94
[1694846954.152760][22373:22375] CHIP:DIS:      IP Address #1: fd11:35::e119:c9a1:75db:8d1e
[1694846954.152780][22373:22375] CHIP:DIS:      Port: 5540
[1694846954.152799][22373:22375] CHIP:DIS:      Mrp Interval idle: 2800 ms
[1694846954.152818][22373:22375] CHIP:DIS:      Mrp Interval active: 1000 ms
[1694846954.152837][22373:22375] CHIP:DIS:      TCP Supported: 0
[1694846954.153745][22373:22375] CHIP:DIS: Lookup clearing interface for non LL address
[1694846954.153871][22373:22375] CHIP:DIS: UDP:[fd11:35::e119:c9a1:75db:8d1e%veth10eedd1]:5540: new best score: 5
[1694846954.153905][22373:22375] CHIP:DIS: Checking node lookup status after 3 ms
[1694846954.153932][22373:22375] CHIP:DIS: Keeping DNSSD lookup active
[1694846954.351756][22373:22375] CHIP:DIS: Checking node lookup status after 201 ms
[1694846954.351887][22373:22375] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540 while in state 2
[1694846954.351947][22373:22375] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1694846954.352270][22373:22375] CHIP:IN: SecureSession[0xffff9400aef0]: Allocated Type:2 LSID:16795
[1694846954.352365][22373:22375] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1694846954.354243][22373:22375] CHIP:EM: <<< [E:57500i S:0 M:241104530] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1694846954.354382][22373:22375] CHIP:IN: (U) Sending msg 241104530 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694846954.354797][22373:22375] CHIP:SC: Sent Sigma1 msg
[1694846954.354877][22373:22375] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1694846954.537115][22373:22375] CHIP:EM: >>> [E:57500i S:0 M:56493077 (Ack:241104530)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694846954.537195][22373:22375] CHIP:EM: Found matching exchange: 57500i, Delegate: 0xffff9400dd98
[1694846954.537261][22373:22375] CHIP:EM: Rxd Ack; Removing MessageCounter:241104530 from Retrans Table on exchange 57500i
[1694846954.830568][22373:22375] CHIP:EM: >>> [E:57500i S:0 M:56493078 (Ack:241104530)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1694846954.830668][22373:22375] CHIP:EM: Found matching exchange: 57500i, Delegate: 0xffff9400dd98
[1694846954.830779][22373:22375] CHIP:EM: CHIP MessageCounter:241104530 not in RetransTable on exchange 57500i
[1694846954.830886][22373:22375] CHIP:SC: Received Sigma2 msg
[1694846954.830972][22373:22375] CHIP:SC: Peer assigned session session ID 51785
[1694846954.839032][22373:22375] CHIP:SC: Found MRP parameters in the message
[1694846954.839107][22373:22375] CHIP:SC: Sending Sigma3
[1694846954.839844][22373:22375] CHIP:EM: <<< [E:57500i S:0 M:241104531 (Ack:56493078)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1694846954.840044][22373:22375] CHIP:IN: (U) Sending msg 241104531 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694846954.840270][22373:22375] CHIP:SC: Sent Sigma3 msg
[1694846955.177928][22373:22375] CHIP:EM: >>> [E:57500i S:0 M:56493079 (Ack:241104531)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694846955.178013][22373:22375] CHIP:EM: Found matching exchange: 57500i, Delegate: 0xffff9400dd98
[1694846955.178088][22373:22375] CHIP:EM: Rxd Ack; Removing MessageCounter:241104531 from Retrans Table on exchange 57500i
[1694846955.377282][22373:22375] CHIP:EM: >>> [E:57500i S:0 M:56493080 (Ack:241104531)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1694846955.377382][22373:22375] CHIP:EM: Found matching exchange: 57500i, Delegate: 0xffff9400dd98
[1694846955.377445][22373:22375] CHIP:EM: CHIP MessageCounter:241104531 not in RetransTable on exchange 57500i
[1694846955.377549][22373:22375] CHIP:SC: Success status report received. Session was established
[1694846955.385276][22373:22375] CHIP:SC: SecureSession[0xffff9400aef0, LSID:16795]: State change 'kEstablishing' --> 'kActive'
[1694846955.385368][22373:22375] CHIP:IN: SecureSession[0xffff9400aef0]: Activated - Type:2 LSID:16795
[1694846955.385413][22373:22375] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:16795 PSID:51785!
[1694846955.385467][22373:22375] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1694846955.385578][22373:22375] CHIP:TOO: Sending cluster (0x00000030) command (0x00000000) on endpoint 0
[1694846955.385673][22373:22375] CHIP:DMG: ICR moving to [AddingComm]
[1694846955.385796][22373:22375] CHIP:DMG: ICR moving to [AddedComma]
[1694846955.386009][22373:22375] CHIP:EM: <<< [E:57501i S:16795 M:67629403] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0001:08 (IM:InvokeCommandRequest)
[1694846955.386093][22373:22375] CHIP:IN: (S) Sending msg 67629403 on secure session with LSID: 16795
[1694846955.386392][22373:22375] CHIP:DMG: ICR moving to [CommandSen]
[1694846955.386514][22373:22375] CHIP:EM: <<< [E:57500i S:0 M:241104532 (Ack:56493080)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694846955.386920][22373:22375] CHIP:IN: (U) Sending msg 241104532 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694846955.387117][22373:22375] CHIP:EM: Flushed pending ack for MessageCounter:56493080 on exchange 57500i
[1694846955.592939][22373:22375] CHIP:EM: >>> [E:57501i S:16795 M:95663835 (Ack:67629403)] (S) Msg RX from 1:0000000000000001 [1DE8] --- Type 0001:09 (IM:InvokeCommandResponse)
[1694846955.593031][22373:22375] CHIP:EM: Found matching exchange: 57501i, Delegate: 0xffff9400a178
[1694846955.593103][22373:22375] CHIP:EM: Rxd Ack; Removing MessageCounter:67629403 from Retrans Table on exchange 57501i
[1694846955.593173][22373:22375] CHIP:DMG: ICR moving to [ResponseRe]
[1694846955.593265][22373:22375] CHIP:DMG: InvokeResponseMessage =
[1694846955.593315][22373:22375] CHIP:DMG: {
[1694846955.593362][22373:22375] CHIP:DMG:      suppressResponse = false,
[1694846955.593411][22373:22375] CHIP:DMG:      InvokeResponseIBs =
[1694846955.593476][22373:22375] CHIP:DMG:      [
[1694846955.593525][22373:22375] CHIP:DMG:              InvokeResponseIB =
[1694846955.593592][22373:22375] CHIP:DMG:              {
[1694846955.593644][22373:22375] CHIP:DMG:                      CommandDataIB =
[1694846955.593710][22373:22375] CHIP:DMG:                      {
[1694846955.593766][22373:22375] CHIP:DMG:                              CommandPathIB =
[1694846955.593830][22373:22375] CHIP:DMG:                              {
[1694846955.593896][22373:22375] CHIP:DMG:                                      EndpointId = 0x0,
[1694846955.593965][22373:22375] CHIP:DMG:                                      ClusterId = 0x30,
[1694846955.594035][22373:22375] CHIP:DMG:                                      CommandId = 0x1,
[1694846955.594096][22373:22375] CHIP:DMG:                              },
[1694846955.594162][22373:22375] CHIP:DMG:
[1694846955.594222][22373:22375] CHIP:DMG:                              CommandFields =
[1694846955.594288][22373:22375] CHIP:DMG:                              {
[1694846955.594396][22373:22375] CHIP:DMG:                                      0x0 = 0,
[1694846955.594468][22373:22375] CHIP:DMG:                                      0x1 = "" (0 chars),
[1694846955.594537][22373:22375] CHIP:DMG:                              },
[1694846955.594597][22373:22375] CHIP:DMG:                      },
[1694846955.594665][22373:22375] CHIP:DMG:
[1694846955.594769][22373:22375] CHIP:DMG:              },
[1694846955.594833][22373:22375] CHIP:DMG:
[1694846955.594882][22373:22375] CHIP:DMG:      ],
[1694846955.594944][22373:22375] CHIP:DMG:
[1694846955.594991][22373:22375] CHIP:DMG:      InteractionModelRevision = 1
[1694846955.595039][22373:22375] CHIP:DMG: },
[1694846955.595162][22373:22375] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1694846955.595248][22373:22375] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0030 Command 0x0000_0001
[1694846955.595425][22373:22375] CHIP:TOO:   ArmFailSafeResponse: {
[1694846955.595527][22373:22375] CHIP:TOO:     errorCode: 0
[1694846955.595575][22373:22375] CHIP:TOO:     debugText:
[1694846955.595620][22373:22375] CHIP:TOO:    }
[1694846955.595693][22373:22375] CHIP:DMG: ICR moving to [AwaitingDe]
[1694846955.595893][22373:22375] CHIP:EM: <<< [E:57501i S:16795 M:67629404 (Ack:95663835)] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694846955.595971][22373:22375] CHIP:IN: (S) Sending msg 67629404 on secure session with LSID: 16795
[1694846955.596189][22373:22375] CHIP:EM: Flushed pending ack for MessageCounter:95663835 on exchange 57501i
[1694846955.596539][22373:22373] CHIP:CTL: Shutting down the commissioner
[1694846955.596604][22373:22373] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694846955.596760][22373:22373] CHIP:CTL: Shutting down the controller
[1694846955.596812][22373:22373] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1694846955.596857][22373:22373] CHIP:IN: SecureSession[0xffff9400aef0]: MarkForEviction Type:2 LSID:16795
[1694846955.596901][22373:22373] CHIP:SC: SecureSession[0xffff9400aef0, LSID:16795]: State change 'kActive' --> 'kPendingEviction'
[1694846955.596947][22373:22373] CHIP:IN: SecureSession[0xffff9400aef0]: Released - Type:2 LSID:16795
[1694846955.596996][22373:22373] CHIP:FP: Forgetting fabric 0x1
[1694846955.597055][22373:22373] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694846955.597335][22373:22373] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694846955.597386][22373:22373] CHIP:TS: Reverted Last Known Good Time to previous value
[1694846955.597464][22373:22373] CHIP:CTL: Shutting down the commissioner
[1694846955.597510][22373:22373] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694846955.597642][22373:22373] CHIP:CTL: Shutting down the controller
[1694846955.597776][22373:22373] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1694846955.598058][22373:22373] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1694846955.598251][22373:22373] CHIP:FP: Shutting down FabricTable
[1694846955.598316][22373:22373] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694846955.598534][22373:22373] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694846955.598667][22373:22373] CHIP:TS: Reverted Last Known Good Time to previous value
[1694846955.599269][22373:22373] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-QQJHfK)
[1694846955.600367][22373:22373] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694846955.600483][22373:22373] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1694846955.600533][22373:22373] CHIP:DL: Inet Layer shutdown
[1694846955.600574][22373:22373] CHIP:DL: BLE shutdown
[1694846955.600617][22373:22373] CHIP:DL: System Layer shutdown
ubuntu@ubuntu:~/apps$ ./chip-tool generalcommissioning arm-fail-safe 900 1 1 0
[1694846974.067163][22376:22376] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1694846974.072530][22376:22376] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1694846974.072779][22376:22376] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1694846974.072884][22376:22376] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1694846974.073220][22376:22376] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-JPUEc5)
[1694846974.073804][22376:22376] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694846974.073855][22376:22376] CHIP:DL: NVS set: chip-counters/reboot-count = 3 (0x3)
[1694846974.074805][22376:22376] CHIP:DL: Got Ethernet interface: eth0
[1694846974.075378][22376:22376] CHIP:DL: Found the primary Ethernet interface:eth0
[1694846974.075967][22376:22376] CHIP:DL: Got WiFi interface: wlan0
[1694846974.076028][22376:22376] CHIP:DL: Failed to reset WiFi statistic counts
[1694846974.076108][22376:22376] CHIP:IN: UDP::Init bind&listen port=0
[1694846974.076210][22376:22376] CHIP:IN: UDP::Init bound to port=36841
[1694846974.076230][22376:22376] CHIP:IN: BLEBase::Init - setting/overriding transport
[1694846974.076247][22376:22376] CHIP:IN: TransportMgr initialized
[1694846974.076277][22376:22376] CHIP:FP: Initializing FabricTable from persistent storage
[1694846974.076413][22376:22376] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694846974.077913][22376:22376] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x531C5E1335241DE8, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1694846974.081712][22376:22376] CHIP:ZCL: Using ZAP configuration...
[1694846974.085598][22376:22376] CHIP:DL: Avahi client registered
[1694846974.085729][22376:22376] CHIP:CTL: System State Initialized...
[1694846974.085819][22376:22376] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694846974.085865][22376:22376] CHIP:CTL: Setting attestation nonce to random value
[1694846974.085899][22376:22376] CHIP:CTL: Setting CSR nonce to random value
[1694846974.085957][22376:22376] CHIP:IN: UDP::Init bind&listen port=5550
[1694846974.086075][22376:22376] CHIP:IN: UDP::Init bound to port=5550
[1694846974.086094][22376:22376] CHIP:IN: TransportMgr initialized
[1694846974.086347][22376:22378] CHIP:DL: CHIP task running
[1694846974.086544][22376:22378] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1694846974.086861][22376:22378] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694846974.086918][22376:22378] CHIP:CTL: Setting attestation nonce to random value
[1694846974.087072][22376:22378] CHIP:CTL: Setting CSR nonce to random value
[1694846974.087918][22376:22378] CHIP:CTL: Generating NOC
[1694846974.088799][22376:22378] CHIP:FP: Validating NOC chain
[1694846974.090929][22376:22378] CHIP:FP: NOC chain validation successful
[1694846974.091154][22376:22378] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1694846974.091194][22376:22378] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694846974.091223][22376:22378] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1694846974.091245][22376:22378] CHIP:TS: Retaining current Last Known Good Time
[1694846974.104723][22376:22378] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1694846974.109633][22376:22378] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-25T18:22:45
[1694846974.115006][22376:22378] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 531C5E1335241DE8)
[1694846974.115083][22376:22378] CHIP:IN: UDP::Init bind&listen port=5550
[1694846974.115244][22376:22378] CHIP:IN: UDP::Init bound to port=5550
[1694846974.115279][22376:22378] CHIP:IN: TransportMgr initialized
[1694846974.171784][22376:22378] CHIP:TOO: Sending command to node 0x1
[1694846974.172516][22376:22378] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1694846974.172567][22376:22378] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1694846974.172620][22376:22378] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1694846974.172671][22376:22378] CHIP:DIS: Resolving 531C5E1335241DE8:0000000000000001 ...
[1694846974.175553][22376:22378] CHIP:DL: Avahi resolve found
[1694846974.175660][22376:22378] CHIP:DIS: Node ID resolved for 531C5E1335241DE8:0000000000000001
[1694846974.175701][22376:22378] CHIP:DIS:      Hostname: 1A214799925ACE94
[1694846974.175746][22376:22378] CHIP:DIS:      IP Address #1: fd11:35::e119:c9a1:75db:8d1e
[1694846974.175783][22376:22378] CHIP:DIS:      Port: 5540
[1694846974.175819][22376:22378] CHIP:DIS:      Mrp Interval idle: 2800 ms
[1694846974.175855][22376:22378] CHIP:DIS:      Mrp Interval active: 1000 ms
[1694846974.175891][22376:22378] CHIP:DIS:      TCP Supported: 0
[1694846974.177119][22376:22378] CHIP:DIS: Lookup clearing interface for non LL address
[1694846974.177261][22376:22378] CHIP:DIS: UDP:[fd11:35::e119:c9a1:75db:8d1e%veth10eedd1]:5540: new best score: 5
[1694846974.177303][22376:22378] CHIP:DIS: Checking node lookup status after 5 ms
[1694846974.177336][22376:22378] CHIP:DIS: Keeping DNSSD lookup active
[1694846974.372163][22376:22378] CHIP:DIS: Checking node lookup status after 200 ms
[1694846974.372232][22376:22378] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540 while in state 2
[1694846974.372254][22376:22378] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1694846974.372421][22376:22378] CHIP:IN: SecureSession[0xffff7800aee0]: Allocated Type:2 LSID:44689
[1694846974.372462][22376:22378] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1694846974.373298][22376:22378] CHIP:EM: <<< [E:45618i S:0 M:15950907] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1694846974.373364][22376:22378] CHIP:IN: (U) Sending msg 15950907 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694846974.373535][22376:22378] CHIP:SC: Sent Sigma1 msg
[1694846974.373565][22376:22378] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1694846975.809794][22376:22378] CHIP:EM: >>> [E:45618i S:0 M:56493081 (Ack:15950907)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694846975.809888][22376:22378] CHIP:EM: Found matching exchange: 45618i, Delegate: 0xffff7800dfe8
[1694846975.809964][22376:22378] CHIP:EM: Rxd Ack; Removing MessageCounter:15950907 from Retrans Table on exchange 45618i
[1694846976.088356][22376:22378] CHIP:EM: >>> [E:45618i S:0 M:56493082 (Ack:15950907)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1694846976.088461][22376:22378] CHIP:EM: Found matching exchange: 45618i, Delegate: 0xffff7800dfe8
[1694846976.088522][22376:22378] CHIP:EM: CHIP MessageCounter:15950907 not in RetransTable on exchange 45618i
[1694846976.088627][22376:22378] CHIP:SC: Received Sigma2 msg
[1694846976.088714][22376:22378] CHIP:SC: Peer assigned session session ID 51786
[1694846976.097743][22376:22378] CHIP:SC: Found MRP parameters in the message
[1694846976.097815][22376:22378] CHIP:SC: Sending Sigma3
[1694846976.098507][22376:22378] CHIP:EM: <<< [E:45618i S:0 M:15950908 (Ack:56493082)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1694846976.098727][22376:22378] CHIP:IN: (U) Sending msg 15950908 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694846976.098944][22376:22378] CHIP:SC: Sent Sigma3 msg
[1694846976.474840][22376:22378] CHIP:EM: >>> [E:45618i S:0 M:56493083 (Ack:15950908)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694846976.474921][22376:22378] CHIP:EM: Found matching exchange: 45618i, Delegate: 0xffff7800dfe8
[1694846976.474987][22376:22378] CHIP:EM: Rxd Ack; Removing MessageCounter:15950908 from Retrans Table on exchange 45618i
[1694846976.662783][22376:22378] CHIP:EM: >>> [E:45618i S:0 M:56493084 (Ack:15950908)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1694846976.662858][22376:22378] CHIP:EM: Found matching exchange: 45618i, Delegate: 0xffff7800dfe8
[1694846976.662902][22376:22378] CHIP:EM: CHIP MessageCounter:15950908 not in RetransTable on exchange 45618i
[1694846976.662978][22376:22378] CHIP:SC: Success status report received. Session was established
[1694846976.672589][22376:22378] CHIP:SC: SecureSession[0xffff7800aee0, LSID:44689]: State change 'kEstablishing' --> 'kActive'
[1694846976.672691][22376:22378] CHIP:IN: SecureSession[0xffff7800aee0]: Activated - Type:2 LSID:44689
[1694846976.672744][22376:22378] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:44689 PSID:51786!
[1694846976.672807][22376:22378] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1694846976.672933][22376:22378] CHIP:TOO: Sending cluster (0x00000030) command (0x00000000) on endpoint 0
[1694846976.673043][22376:22378] CHIP:DMG: ICR moving to [AddingComm]
[1694846976.673183][22376:22378] CHIP:DMG: ICR moving to [AddedComma]
[1694846976.673422][22376:22378] CHIP:EM: <<< [E:45619i S:44689 M:207365076] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0001:08 (IM:InvokeCommandRequest)
[1694846976.673519][22376:22378] CHIP:IN: (S) Sending msg 207365076 on secure session with LSID: 44689
[1694846976.673819][22376:22378] CHIP:DMG: ICR moving to [CommandSen]
[1694846976.673890][22376:22378] CHIP:EM: <<< [E:45618i S:0 M:15950909 (Ack:56493084)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694846976.674111][22376:22378] CHIP:IN: (U) Sending msg 15950909 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694846976.674216][22376:22378] CHIP:EM: Flushed pending ack for MessageCounter:56493084 on exchange 45618i
[1694846976.874127][22376:22378] CHIP:EM: >>> [E:45619i S:44689 M:6483841 (Ack:207365076)] (S) Msg RX from 1:0000000000000001 [1DE8] --- Type 0001:09 (IM:InvokeCommandResponse)
[1694846976.874212][22376:22378] CHIP:EM: Found matching exchange: 45619i, Delegate: 0xffff7800a168
[1694846976.874279][22376:22378] CHIP:EM: Rxd Ack; Removing MessageCounter:207365076 from Retrans Table on exchange 45619i
[1694846976.874342][22376:22378] CHIP:DMG: ICR moving to [ResponseRe]
[1694846976.874426][22376:22378] CHIP:DMG: InvokeResponseMessage =
[1694846976.874468][22376:22378] CHIP:DMG: {
[1694846976.874509][22376:22378] CHIP:DMG:      suppressResponse = false,
[1694846976.874552][22376:22378] CHIP:DMG:      InvokeResponseIBs =
[1694846976.874609][22376:22378] CHIP:DMG:      [
[1694846976.874652][22376:22378] CHIP:DMG:              InvokeResponseIB =
[1694846976.874740][22376:22378] CHIP:DMG:              {
[1694846976.874788][22376:22378] CHIP:DMG:                      CommandDataIB =
[1694846976.874842][22376:22378] CHIP:DMG:                      {
[1694846976.874891][22376:22378] CHIP:DMG:                              CommandPathIB =
[1694846976.874948][22376:22378] CHIP:DMG:                              {
[1694846976.875007][22376:22378] CHIP:DMG:                                      EndpointId = 0x0,
[1694846976.875082][22376:22378] CHIP:DMG:                                      ClusterId = 0x30,
[1694846976.875149][22376:22378] CHIP:DMG:                                      CommandId = 0x1,
[1694846976.875228][22376:22378] CHIP:DMG:                              },
[1694846976.875297][22376:22378] CHIP:DMG:
[1694846976.875355][22376:22378] CHIP:DMG:                              CommandFields =
[1694846976.875419][22376:22378] CHIP:DMG:                              {
[1694846976.875531][22376:22378] CHIP:DMG:                                      0x0 = 0,
[1694846976.875605][22376:22378] CHIP:DMG:                                      0x1 = "" (0 chars),
[1694846976.875675][22376:22378] CHIP:DMG:                              },
[1694846976.875735][22376:22378] CHIP:DMG:                      },
[1694846976.875801][22376:22378] CHIP:DMG:
[1694846976.875853][22376:22378] CHIP:DMG:              },
[1694846976.875915][22376:22378] CHIP:DMG:
[1694846976.875962][22376:22378] CHIP:DMG:      ],
[1694846976.876023][22376:22378] CHIP:DMG:
[1694846976.876071][22376:22378] CHIP:DMG:      InteractionModelRevision = 1
[1694846976.876118][22376:22378] CHIP:DMG: },
[1694846976.876240][22376:22378] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1694846976.876330][22376:22378] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0030 Command 0x0000_0001
[1694846976.876466][22376:22378] CHIP:TOO:   ArmFailSafeResponse: {
[1694846976.876537][22376:22378] CHIP:TOO:     errorCode: 0
[1694846976.876584][22376:22378] CHIP:TOO:     debugText:
[1694846976.876628][22376:22378] CHIP:TOO:    }
[1694846976.876702][22376:22378] CHIP:DMG: ICR moving to [AwaitingDe]
[1694846976.876894][22376:22378] CHIP:EM: <<< [E:45619i S:44689 M:207365077 (Ack:6483841)] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694846976.876973][22376:22378] CHIP:IN: (S) Sending msg 207365077 on secure session with LSID: 44689
[1694846976.877197][22376:22378] CHIP:EM: Flushed pending ack for MessageCounter:6483841 on exchange 45619i
[1694846976.877604][22376:22376] CHIP:CTL: Shutting down the commissioner
[1694846976.877669][22376:22376] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694846976.877829][22376:22376] CHIP:CTL: Shutting down the controller
[1694846976.877883][22376:22376] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1694846976.877929][22376:22376] CHIP:IN: SecureSession[0xffff7800aee0]: MarkForEviction Type:2 LSID:44689
[1694846976.877975][22376:22376] CHIP:SC: SecureSession[0xffff7800aee0, LSID:44689]: State change 'kActive' --> 'kPendingEviction'
[1694846976.878021][22376:22376] CHIP:IN: SecureSession[0xffff7800aee0]: Released - Type:2 LSID:44689
[1694846976.878071][22376:22376] CHIP:FP: Forgetting fabric 0x1
[1694846976.878132][22376:22376] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694846976.878467][22376:22376] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694846976.878525][22376:22376] CHIP:TS: Reverted Last Known Good Time to previous value
[1694846976.878626][22376:22376] CHIP:CTL: Shutting down the commissioner
[1694846976.878718][22376:22376] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694846976.878868][22376:22376] CHIP:CTL: Shutting down the controller
[1694846976.878916][22376:22376] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1694846976.879182][22376:22376] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1694846976.879364][22376:22376] CHIP:FP: Shutting down FabricTable
[1694846976.879426][22376:22376] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694846976.879641][22376:22376] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694846976.879693][22376:22376] CHIP:TS: Reverted Last Known Good Time to previous value
[1694846976.880083][22376:22376] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-ufGv49)
[1694846976.881259][22376:22376] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694846976.881380][22376:22376] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1694846976.881431][22376:22376] CHIP:DL: Inet Layer shutdown
[1694846976.881472][22376:22376] CHIP:DL: BLE shutdown
[1694846976.881516][22376:22376] CHIP:DL: System Layer shutdown
ubuntu@ubuntu:~/apps$ ./chip-tool networkcommissioning read networks 1 0
[1694846991.227386][22381:22381] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1694846991.232850][22381:22381] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1694846991.233099][22381:22381] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1694846991.233208][22381:22381] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1694846991.233543][22381:22381] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-xh0Cn9)
[1694846991.234122][22381:22381] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694846991.234175][22381:22381] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4)
[1694846991.235136][22381:22381] CHIP:DL: Got Ethernet interface: eth0
[1694846991.235703][22381:22381] CHIP:DL: Found the primary Ethernet interface:eth0
[1694846991.236279][22381:22381] CHIP:DL: Got WiFi interface: wlan0
[1694846991.236338][22381:22381] CHIP:DL: Failed to reset WiFi statistic counts
[1694846991.236419][22381:22381] CHIP:IN: UDP::Init bind&listen port=0
[1694846991.236518][22381:22381] CHIP:IN: UDP::Init bound to port=48489
[1694846991.236538][22381:22381] CHIP:IN: BLEBase::Init - setting/overriding transport
[1694846991.236555][22381:22381] CHIP:IN: TransportMgr initialized
[1694846991.236585][22381:22381] CHIP:FP: Initializing FabricTable from persistent storage
[1694846991.236723][22381:22381] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694846991.238093][22381:22381] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x531C5E1335241DE8, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1694846991.242211][22381:22381] CHIP:ZCL: Using ZAP configuration...
[1694846991.245865][22381:22381] CHIP:DL: Avahi client registered
[1694846991.246001][22381:22381] CHIP:CTL: System State Initialized...
[1694846991.246093][22381:22381] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694846991.246141][22381:22381] CHIP:CTL: Setting attestation nonce to random value
[1694846991.246179][22381:22381] CHIP:CTL: Setting CSR nonce to random value
[1694846991.246241][22381:22381] CHIP:IN: UDP::Init bind&listen port=5550
[1694846991.246374][22381:22381] CHIP:IN: UDP::Init bound to port=5550
[1694846991.246397][22381:22381] CHIP:IN: TransportMgr initialized
[1694846991.246657][22381:22383] CHIP:DL: CHIP task running
[1694846991.246872][22381:22383] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1694846991.247174][22381:22383] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694846991.247227][22381:22383] CHIP:CTL: Setting attestation nonce to random value
[1694846991.247395][22381:22383] CHIP:CTL: Setting CSR nonce to random value
[1694846991.248313][22381:22383] CHIP:CTL: Generating NOC
[1694846991.249236][22381:22383] CHIP:FP: Validating NOC chain
[1694846991.251159][22381:22383] CHIP:FP: NOC chain validation successful
[1694846991.251321][22381:22383] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1694846991.251354][22381:22383] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694846991.251375][22381:22383] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1694846991.251395][22381:22383] CHIP:TS: Retaining current Last Known Good Time
[1694846991.262995][22381:22383] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1694846991.267972][22381:22383] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-25T18:22:45
[1694846991.273510][22381:22383] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 531C5E1335241DE8)
[1694846991.273587][22381:22383] CHIP:IN: UDP::Init bind&listen port=5550
[1694846991.273748][22381:22383] CHIP:IN: UDP::Init bound to port=5550
[1694846991.273782][22381:22383] CHIP:IN: TransportMgr initialized
[1694846991.300089][22381:22383] CHIP:TOO: Sending command to node 0x1
[1694846991.300667][22381:22383] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1694846991.300708][22381:22383] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1694846991.300752][22381:22383] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1694846991.300792][22381:22383] CHIP:DIS: Resolving 531C5E1335241DE8:0000000000000001 ...
[1694846991.303111][22381:22383] CHIP:DL: Avahi resolve found
[1694846991.303201][22381:22383] CHIP:DIS: Node ID resolved for 531C5E1335241DE8:0000000000000001
[1694846991.303231][22381:22383] CHIP:DIS:      Hostname: 1A214799925ACE94
[1694846991.303265][22381:22383] CHIP:DIS:      IP Address #1: fd11:35::e119:c9a1:75db:8d1e
[1694846991.303294][22381:22383] CHIP:DIS:      Port: 5540
[1694846991.303320][22381:22383] CHIP:DIS:      Mrp Interval idle: 2800 ms
[1694846991.303348][22381:22383] CHIP:DIS:      Mrp Interval active: 1000 ms
[1694846991.303374][22381:22383] CHIP:DIS:      TCP Supported: 0
[1694846991.304337][22381:22383] CHIP:DIS: Lookup clearing interface for non LL address
[1694846991.304455][22381:22383] CHIP:DIS: UDP:[fd11:35::e119:c9a1:75db:8d1e%veth10eedd1]:5540: new best score: 5
[1694846991.304487][22381:22383] CHIP:DIS: Checking node lookup status after 3 ms
[1694846991.304512][22381:22383] CHIP:DIS: Keeping DNSSD lookup active
[1694846991.501197][22381:22383] CHIP:DIS: Checking node lookup status after 200 ms
[1694846991.501326][22381:22383] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540 while in state 2
[1694846991.501385][22381:22383] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1694846991.501713][22381:22383] CHIP:IN: SecureSession[0xffff8800aef0]: Allocated Type:2 LSID:1972
[1694846991.501810][22381:22383] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1694846991.503744][22381:22383] CHIP:EM: <<< [E:57613i S:0 M:42494554] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1694846991.503882][22381:22383] CHIP:IN: (U) Sending msg 42494554 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694846991.504211][22381:22383] CHIP:SC: Sent Sigma1 msg
[1694846991.504286][22381:22383] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1694846993.093053][22381:22383] CHIP:EM: >>> [E:57613i S:0 M:56493085 (Ack:42494554)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694846993.093144][22381:22383] CHIP:EM: Found matching exchange: 57613i, Delegate: 0xffff8800dd98
[1694846993.093219][22381:22383] CHIP:EM: Rxd Ack; Removing MessageCounter:42494554 from Retrans Table on exchange 57613i
[1694846993.379544][22381:22383] CHIP:EM: >>> [E:57613i S:0 M:56493086 (Ack:42494554)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1694846993.379634][22381:22383] CHIP:EM: Found matching exchange: 57613i, Delegate: 0xffff8800dd98
[1694846993.379687][22381:22383] CHIP:EM: CHIP MessageCounter:42494554 not in RetransTable on exchange 57613i
[1694846993.379778][22381:22383] CHIP:SC: Received Sigma2 msg
[1694846993.379854][22381:22383] CHIP:SC: Peer assigned session session ID 51787
[1694846993.387450][22381:22383] CHIP:SC: Found MRP parameters in the message
[1694846993.387536][22381:22383] CHIP:SC: Sending Sigma3
[1694846993.388345][22381:22383] CHIP:EM: <<< [E:57613i S:0 M:42494555 (Ack:56493086)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1694846993.388573][22381:22383] CHIP:IN: (U) Sending msg 42494555 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694846993.388811][22381:22383] CHIP:SC: Sent Sigma3 msg
[1694846993.752413][22381:22383] CHIP:EM: >>> [E:57613i S:0 M:56493087 (Ack:42494555)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694846993.752499][22381:22383] CHIP:EM: Found matching exchange: 57613i, Delegate: 0xffff8800dd98
[1694846993.752565][22381:22383] CHIP:EM: Rxd Ack; Removing MessageCounter:42494555 from Retrans Table on exchange 57613i
[1694846993.944433][22381:22383] CHIP:EM: >>> [E:57613i S:0 M:56493088 (Ack:42494555)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1694846993.944532][22381:22383] CHIP:EM: Found matching exchange: 57613i, Delegate: 0xffff8800dd98
[1694846993.944592][22381:22383] CHIP:EM: CHIP MessageCounter:42494555 not in RetransTable on exchange 57613i
[1694846993.944695][22381:22383] CHIP:SC: Success status report received. Session was established
[1694846993.954354][22381:22383] CHIP:SC: SecureSession[0xffff8800aef0, LSID:1972]: State change 'kEstablishing' --> 'kActive'
[1694846993.954434][22381:22383] CHIP:IN: SecureSession[0xffff8800aef0]: Activated - Type:2 LSID:1972
[1694846993.954469][22381:22383] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:1972 PSID:51787!
[1694846993.954514][22381:22383] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1694846993.954619][22381:22383] CHIP:TOO: Sending ReadAttribute to:
[1694846993.961118][22381:22383] CHIP:TOO:      cluster 0x0000_0031, attribute: 0x0000_0001, endpoint 0
[1694846993.961205][22381:22383] CHIP:DMG: SendReadRequest ReadClient[0xffff880110a0]: Sending Read Request
[1694846993.961452][22381:22383] CHIP:EM: <<< [E:57614i S:1972 M:28592983] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0001:02 (IM:ReadRequest)
[1694846993.961512][22381:22383] CHIP:IN: (S) Sending msg 28592983 on secure session with LSID: 1972
[1694846993.961754][22381:22383] CHIP:DMG: MoveToState ReadClient[0xffff880110a0]: Moving to [AwaitingIn]
[1694846993.961861][22381:22383] CHIP:EM: <<< [E:57613i S:0 M:42494556 (Ack:56493088)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694846993.962050][22381:22383] CHIP:IN: (U) Sending msg 42494556 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694846993.962196][22381:22383] CHIP:EM: Flushed pending ack for MessageCounter:56493088 on exchange 57613i
[1694846994.172010][22381:22383] CHIP:EM: >>> [E:57614i S:1972 M:13598520 (Ack:28592983)] (S) Msg RX from 1:0000000000000001 [1DE8] --- Type 0001:05 (IM:ReportData)
[1694846994.172095][22381:22383] CHIP:EM: Found matching exchange: 57614i, Delegate: 0xffff880110b0
[1694846994.172160][22381:22383] CHIP:EM: Rxd Ack; Removing MessageCounter:28592983 from Retrans Table on exchange 57614i
[1694846994.172277][22381:22383] CHIP:DMG: ReportDataMessage =
[1694846994.172327][22381:22383] CHIP:DMG: {
[1694846994.172366][22381:22383] CHIP:DMG:      AttributeReportIBs =
[1694846994.172425][22381:22383] CHIP:DMG:      [
[1694846994.172469][22381:22383] CHIP:DMG:              AttributeReportIB =
[1694846994.172527][22381:22383] CHIP:DMG:              {
[1694846994.172574][22381:22383] CHIP:DMG:                      AttributeDataIB =
[1694846994.172629][22381:22383] CHIP:DMG:                      {
[1694846994.172685][22381:22383] CHIP:DMG:                              DataVersion = 0x8cef20fc,
[1694846994.172740][22381:22383] CHIP:DMG:                              AttributePathIB =
[1694846994.172796][22381:22383] CHIP:DMG:                              {
[1694846994.172854][22381:22383] CHIP:DMG:                                      Endpoint = 0x0,
[1694846994.172916][22381:22383] CHIP:DMG:                                      Cluster = 0x31,
[1694846994.172977][22381:22383] CHIP:DMG:                                      Attribute = 0x0000_0001,
[1694846994.173035][22381:22383] CHIP:DMG:                              }
[1694846994.173095][22381:22383] CHIP:DMG:
[1694846994.173152][22381:22383] CHIP:DMG:                              Data = [
[1694846994.173208][22381:22383] CHIP:DMG:
[1694846994.173265][22381:22383] CHIP:DMG:                              ],
[1694846994.173319][22381:22383] CHIP:DMG:                      },
[1694846994.173377][22381:22383] CHIP:DMG:
[1694846994.173423][22381:22383] CHIP:DMG:              },
[1694846994.173490][22381:22383] CHIP:DMG:
[1694846994.173533][22381:22383] CHIP:DMG:              AttributeReportIB =
[1694846994.173593][22381:22383] CHIP:DMG:              {
[1694846994.173639][22381:22383] CHIP:DMG:                      AttributeDataIB =
[1694846994.173690][22381:22383] CHIP:DMG:                      {
[1694846994.173744][22381:22383] CHIP:DMG:                              DataVersion = 0x8cef20fc,
[1694846994.173798][22381:22383] CHIP:DMG:                              AttributePathIB =
[1694846994.173854][22381:22383] CHIP:DMG:                              {
[1694846994.173911][22381:22383] CHIP:DMG:                                      Endpoint = 0x0,
[1694846994.173971][22381:22383] CHIP:DMG:                                      Cluster = 0x31,
[1694846994.174031][22381:22383] CHIP:DMG:                                      Attribute = 0x0000_0001,
[1694846994.174091][22381:22383] CHIP:DMG:                                      ListIndex = Null,
[1694846994.174148][22381:22383] CHIP:DMG:                              }
[1694846994.174207][22381:22383] CHIP:DMG:
[1694846994.174262][22381:22383] CHIP:DMG:                              Data =
[1694846994.174317][22381:22383] CHIP:DMG:                              {
[1694846994.174413][22381:22383] CHIP:DMG:                                      0x0 = [
[1694846994.174477][22381:22383] CHIP:DMG:                                                      0x18, 0xb1, 0xa8, 0xd8, 0xfc, 0x4c, 0x18, 0x70,
[1694846994.174545][22381:22383] CHIP:DMG:                                      ] (8 bytes)
[1694846994.174608][22381:22383] CHIP:DMG:                                      0x1 = true,
[1694846994.174667][22381:22383] CHIP:DMG:                              },
[1694846994.174778][22381:22383] CHIP:DMG:                      },
[1694846994.174842][22381:22383] CHIP:DMG:
[1694846994.174889][22381:22383] CHIP:DMG:              },
[1694846994.174945][22381:22383] CHIP:DMG:
[1694846994.174988][22381:22383] CHIP:DMG:      ],
[1694846994.175051][22381:22383] CHIP:DMG:
[1694846994.175094][22381:22383] CHIP:DMG:      SuppressResponse = true,
[1694846994.175139][22381:22383] CHIP:DMG:      InteractionModelRevision = 1
[1694846994.175180][22381:22383] CHIP:DMG: }
[1694846994.177172][22381:22383] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0031 Attribute 0x0000_0001 DataVersion: 2364481788
[1694846994.180275][22381:22383] CHIP:TOO:   Networks: 1 entries
[1694846994.180341][22381:22383] CHIP:TOO:     [1]: {
[1694846994.180381][22381:22383] CHIP:TOO:       NetworkID: 18B1A8D8FC4C1870
[1694846994.180412][22381:22383] CHIP:TOO:       Connected: TRUE
[1694846994.180441][22381:22383] CHIP:TOO:      }
[1694846994.180673][22381:22383] CHIP:EM: <<< [E:57614i S:1972 M:28592984 (Ack:13598520)] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694846994.180729][22381:22383] CHIP:IN: (S) Sending msg 28592984 on secure session with LSID: 1972
[1694846994.180906][22381:22383] CHIP:EM: Flushed pending ack for MessageCounter:13598520 on exchange 57614i
[1694846994.181147][22381:22381] CHIP:CTL: Shutting down the commissioner
[1694846994.181236][22381:22381] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694846994.181348][22381:22381] CHIP:CTL: Shutting down the controller
[1694846994.181411][22381:22381] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1694846994.181442][22381:22381] CHIP:IN: SecureSession[0xffff8800aef0]: MarkForEviction Type:2 LSID:1972
[1694846994.181472][22381:22381] CHIP:SC: SecureSession[0xffff8800aef0, LSID:1972]: State change 'kActive' --> 'kPendingEviction'
[1694846994.181502][22381:22381] CHIP:IN: SecureSession[0xffff8800aef0]: Released - Type:2 LSID:1972
[1694846994.181535][22381:22381] CHIP:FP: Forgetting fabric 0x1
[1694846994.181576][22381:22381] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694846994.181819][22381:22381] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694846994.181851][22381:22381] CHIP:TS: Reverted Last Known Good Time to previous value
[1694846994.181906][22381:22381] CHIP:CTL: Shutting down the commissioner
[1694846994.181937][22381:22381] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694846994.182035][22381:22381] CHIP:CTL: Shutting down the controller
[1694846994.182074][22381:22381] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1694846994.182295][22381:22381] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1694846994.182440][22381:22381] CHIP:FP: Shutting down FabricTable
[1694846994.182484][22381:22381] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694846994.182646][22381:22381] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694846994.182717][22381:22381] CHIP:TS: Reverted Last Known Good Time to previous value
[1694846994.183044][22381:22381] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-JITb80)
[1694846994.183918][22381:22381] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694846994.184005][22381:22381] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1694846994.184040][22381:22381] CHIP:DL: Inet Layer shutdown
[1694846994.184067][22381:22381] CHIP:DL: BLE shutdown
[1694846994.184095][22381:22381] CHIP:DL: System Layer shutdown
ubuntu@ubuntu:~/apps$ ./chip-tool networkcommissioning  remove-network hex:18B1A8D8FC4C1870 1 0
[1694847016.585037][22389:22389] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1694847016.590549][22389:22389] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1694847016.590841][22389:22389] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1694847016.590970][22389:22389] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1694847016.591317][22389:22389] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-2wqKZk)
[1694847016.591909][22389:22389] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847016.591959][22389:22389] CHIP:DL: NVS set: chip-counters/reboot-count = 5 (0x5)
[1694847016.592885][22389:22389] CHIP:DL: Got Ethernet interface: eth0
[1694847016.593467][22389:22389] CHIP:DL: Found the primary Ethernet interface:eth0
[1694847016.594058][22389:22389] CHIP:DL: Got WiFi interface: wlan0
[1694847016.594118][22389:22389] CHIP:DL: Failed to reset WiFi statistic counts
[1694847016.594207][22389:22389] CHIP:IN: UDP::Init bind&listen port=0
[1694847016.594319][22389:22389] CHIP:IN: UDP::Init bound to port=53531
[1694847016.594339][22389:22389] CHIP:IN: BLEBase::Init - setting/overriding transport
[1694847016.594357][22389:22389] CHIP:IN: TransportMgr initialized
[1694847016.594386][22389:22389] CHIP:FP: Initializing FabricTable from persistent storage
[1694847016.594526][22389:22389] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847016.595953][22389:22389] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x531C5E1335241DE8, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1694847016.599476][22389:22389] CHIP:ZCL: Using ZAP configuration...
[1694847016.603047][22389:22389] CHIP:DL: Avahi client registered
[1694847016.603172][22389:22389] CHIP:CTL: System State Initialized...
[1694847016.603255][22389:22389] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847016.603298][22389:22389] CHIP:CTL: Setting attestation nonce to random value
[1694847016.603330][22389:22389] CHIP:CTL: Setting CSR nonce to random value
[1694847016.603433][22389:22389] CHIP:IN: UDP::Init bind&listen port=5550
[1694847016.603554][22389:22389] CHIP:IN: UDP::Init bound to port=5550
[1694847016.603574][22389:22389] CHIP:IN: TransportMgr initialized
[1694847016.603848][22389:22391] CHIP:DL: CHIP task running
[1694847016.604040][22389:22391] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1694847016.604319][22389:22391] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847016.604373][22389:22391] CHIP:CTL: Setting attestation nonce to random value
[1694847016.604565][22389:22391] CHIP:CTL: Setting CSR nonce to random value
[1694847016.605632][22389:22391] CHIP:CTL: Generating NOC
[1694847016.606638][22389:22391] CHIP:FP: Validating NOC chain
[1694847016.608651][22389:22391] CHIP:FP: NOC chain validation successful
[1694847016.608819][22389:22391] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1694847016.608868][22389:22391] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847016.608892][22389:22391] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1694847016.608913][22389:22391] CHIP:TS: Retaining current Last Known Good Time
[1694847016.621413][22389:22391] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1694847016.627452][22389:22391] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-25T18:22:45
[1694847016.632259][22389:22391] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 531C5E1335241DE8)
[1694847016.632331][22389:22391] CHIP:IN: UDP::Init bind&listen port=5550
[1694847016.632495][22389:22391] CHIP:IN: UDP::Init bound to port=5550
[1694847016.632531][22389:22391] CHIP:IN: TransportMgr initialized
[1694847016.661871][22389:22391] CHIP:TOO: Sending command to node 0x1
[1694847016.662654][22389:22391] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1694847016.662791][22389:22391] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1694847016.662847][22389:22391] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1694847016.662899][22389:22391] CHIP:DIS: Resolving 531C5E1335241DE8:0000000000000001 ...
[1694847016.665813][22389:22391] CHIP:DL: Avahi resolve found
[1694847016.665924][22389:22391] CHIP:DIS: Node ID resolved for 531C5E1335241DE8:0000000000000001
[1694847016.665964][22389:22391] CHIP:DIS:      Hostname: 1A214799925ACE94
[1694847016.666009][22389:22391] CHIP:DIS:      IP Address #1: fd11:35::e119:c9a1:75db:8d1e
[1694847016.666047][22389:22391] CHIP:DIS:      Port: 5540
[1694847016.666082][22389:22391] CHIP:DIS:      Mrp Interval idle: 2800 ms
[1694847016.666119][22389:22391] CHIP:DIS:      Mrp Interval active: 1000 ms
[1694847016.666155][22389:22391] CHIP:DIS:      TCP Supported: 0
[1694847016.667523][22389:22391] CHIP:DIS: Lookup clearing interface for non LL address
[1694847016.667672][22389:22391] CHIP:DIS: UDP:[fd11:35::e119:c9a1:75db:8d1e%veth10eedd1]:5540: new best score: 5
[1694847016.667713][22389:22391] CHIP:DIS: Checking node lookup status after 5 ms
[1694847016.667747][22389:22391] CHIP:DIS: Keeping DNSSD lookup active
[1694847016.863321][22389:22391] CHIP:DIS: Checking node lookup status after 200 ms
[1694847016.863453][22389:22391] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540 while in state 2
[1694847016.863512][22389:22391] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1694847016.863846][22389:22391] CHIP:IN: SecureSession[0xffff7c00aef0]: Allocated Type:2 LSID:18990
[1694847016.863943][22389:22391] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1694847016.865811][22389:22391] CHIP:EM: <<< [E:12483i S:0 M:194337713] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1694847016.865972][22389:22391] CHIP:IN: (U) Sending msg 194337713 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847016.866332][22389:22391] CHIP:SC: Sent Sigma1 msg
[1694847016.866412][22389:22391] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1694847018.383230][22389:22391] CHIP:EM: >>> [E:12483i S:0 M:56493089 (Ack:194337713)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847018.383322][22389:22391] CHIP:EM: Found matching exchange: 12483i, Delegate: 0xffff7c00dd98
[1694847018.383396][22389:22391] CHIP:EM: Rxd Ack; Removing MessageCounter:194337713 from Retrans Table on exchange 12483i
[1694847018.661799][22389:22391] CHIP:EM: >>> [E:12483i S:0 M:56493090 (Ack:194337713)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1694847018.661896][22389:22391] CHIP:EM: Found matching exchange: 12483i, Delegate: 0xffff7c00dd98
[1694847018.661953][22389:22391] CHIP:EM: CHIP MessageCounter:194337713 not in RetransTable on exchange 12483i
[1694847018.662046][22389:22391] CHIP:SC: Received Sigma2 msg
[1694847018.662123][22389:22391] CHIP:SC: Peer assigned session session ID 51788
[1694847018.669911][22389:22391] CHIP:SC: Found MRP parameters in the message
[1694847018.669979][22389:22391] CHIP:SC: Sending Sigma3
[1694847018.670598][22389:22391] CHIP:EM: <<< [E:12483i S:0 M:194337714 (Ack:56493090)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1694847018.670783][22389:22391] CHIP:IN: (U) Sending msg 194337714 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847018.671002][22389:22391] CHIP:SC: Sent Sigma3 msg
[1694847019.021547][22389:22391] CHIP:EM: >>> [E:12483i S:0 M:56493091 (Ack:194337714)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847019.021638][22389:22391] CHIP:EM: Found matching exchange: 12483i, Delegate: 0xffff7c00dd98
[1694847019.021712][22389:22391] CHIP:EM: Rxd Ack; Removing MessageCounter:194337714 from Retrans Table on exchange 12483i
[1694847019.212321][22389:22391] CHIP:EM: >>> [E:12483i S:0 M:56493092 (Ack:194337714)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1694847019.212370][22389:22391] CHIP:EM: Found matching exchange: 12483i, Delegate: 0xffff7c00dd98
[1694847019.212394][22389:22391] CHIP:EM: CHIP MessageCounter:194337714 not in RetransTable on exchange 12483i
[1694847019.212441][22389:22391] CHIP:SC: Success status report received. Session was established
[1694847019.220579][22389:22391] CHIP:SC: SecureSession[0xffff7c00aef0, LSID:18990]: State change 'kEstablishing' --> 'kActive'
[1694847019.220634][22389:22391] CHIP:IN: SecureSession[0xffff7c00aef0]: Activated - Type:2 LSID:18990
[1694847019.220653][22389:22391] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:18990 PSID:51788!
[1694847019.220680][22389:22391] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1694847019.220744][22389:22391] CHIP:TOO: Sending cluster (0x00000031) command (0x00000004) on endpoint 0
[1694847019.220798][22389:22391] CHIP:DMG: ICR moving to [AddingComm]
[1694847019.220865][22389:22391] CHIP:DMG: ICR moving to [AddedComma]
[1694847019.220999][22389:22391] CHIP:EM: <<< [E:12484i S:18990 M:207048944] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0001:08 (IM:InvokeCommandRequest)
[1694847019.221042][22389:22391] CHIP:IN: (S) Sending msg 207048944 on secure session with LSID: 18990
[1694847019.221219][22389:22391] CHIP:DMG: ICR moving to [CommandSen]
[1694847019.221290][22389:22391] CHIP:EM: <<< [E:12483i S:0 M:194337715 (Ack:56493092)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847019.221429][22389:22391] CHIP:IN: (U) Sending msg 194337715 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847019.221523][22389:22391] CHIP:EM: Flushed pending ack for MessageCounter:56493092 on exchange 12483i
[1694847019.452302][22389:22391] CHIP:EM: >>> [E:12484i S:18990 M:116581298 (Ack:207048944)] (S) Msg RX from 1:0000000000000001 [1DE8] --- Type 0001:09 (IM:InvokeCommandResponse)
[1694847019.452394][22389:22391] CHIP:EM: Found matching exchange: 12484i, Delegate: 0xffff7c00a178
[1694847019.452466][22389:22391] CHIP:EM: Rxd Ack; Removing MessageCounter:207048944 from Retrans Table on exchange 12484i
[1694847019.452535][22389:22391] CHIP:DMG: ICR moving to [ResponseRe]
[1694847019.452628][22389:22391] CHIP:DMG: InvokeResponseMessage =
[1694847019.452676][22389:22391] CHIP:DMG: {
[1694847019.452722][22389:22391] CHIP:DMG:      suppressResponse = false,
[1694847019.452771][22389:22391] CHIP:DMG:      InvokeResponseIBs =
[1694847019.452835][22389:22391] CHIP:DMG:      [
[1694847019.452884][22389:22391] CHIP:DMG:              InvokeResponseIB =
[1694847019.452950][22389:22391] CHIP:DMG:              {
[1694847019.453002][22389:22391] CHIP:DMG:                      CommandDataIB =
[1694847019.453067][22389:22391] CHIP:DMG:                      {
[1694847019.453123][22389:22391] CHIP:DMG:                              CommandPathIB =
[1694847019.453187][22389:22391] CHIP:DMG:                              {
[1694847019.453253][22389:22391] CHIP:DMG:                                      EndpointId = 0x0,
[1694847019.453322][22389:22391] CHIP:DMG:                                      ClusterId = 0x31,
[1694847019.453390][22389:22391] CHIP:DMG:                                      CommandId = 0x5,
[1694847019.453455][22389:22391] CHIP:DMG:                              },
[1694847019.453522][22389:22391] CHIP:DMG:
[1694847019.453581][22389:22391] CHIP:DMG:                              CommandFields =
[1694847019.453644][22389:22391] CHIP:DMG:                              {
[1694847019.453752][22389:22391] CHIP:DMG:                                      0x0 = 0,
[1694847019.453821][22389:22391] CHIP:DMG:                                      0x2 = 0,
[1694847019.453890][22389:22391] CHIP:DMG:                              },
[1694847019.453950][22389:22391] CHIP:DMG:                      },
[1694847019.454017][22389:22391] CHIP:DMG:
[1694847019.454069][22389:22391] CHIP:DMG:              },
[1694847019.454131][22389:22391] CHIP:DMG:
[1694847019.454179][22389:22391] CHIP:DMG:      ],
[1694847019.454241][22389:22391] CHIP:DMG:
[1694847019.454289][22389:22391] CHIP:DMG:      InteractionModelRevision = 1
[1694847019.454336][22389:22391] CHIP:DMG: },
[1694847019.454457][22389:22391] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005
[1694847019.454543][22389:22391] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0031 Command 0x0000_0005
[1694847019.454724][22389:22391] CHIP:TOO:   NetworkConfigResponse: {
[1694847019.454804][22389:22391] CHIP:TOO:     networkingStatus: 0
[1694847019.454857][22389:22391] CHIP:TOO:     networkIndex: 0
[1694847019.454903][22389:22391] CHIP:TOO:    }
[1694847019.454978][22389:22391] CHIP:DMG: ICR moving to [AwaitingDe]
[1694847019.455166][22389:22391] CHIP:EM: <<< [E:12484i S:18990 M:207048945 (Ack:116581298)] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847019.455246][22389:22391] CHIP:IN: (S) Sending msg 207048945 on secure session with LSID: 18990
[1694847019.455465][22389:22391] CHIP:EM: Flushed pending ack for MessageCounter:116581298 on exchange 12484i
[1694847019.455788][22389:22389] CHIP:CTL: Shutting down the commissioner
[1694847019.455852][22389:22389] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847019.456009][22389:22389] CHIP:CTL: Shutting down the controller
[1694847019.456063][22389:22389] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1694847019.456107][22389:22389] CHIP:IN: SecureSession[0xffff7c00aef0]: MarkForEviction Type:2 LSID:18990
[1694847019.456153][22389:22389] CHIP:SC: SecureSession[0xffff7c00aef0, LSID:18990]: State change 'kActive' --> 'kPendingEviction'
[1694847019.456199][22389:22389] CHIP:IN: SecureSession[0xffff7c00aef0]: Released - Type:2 LSID:18990
[1694847019.456248][22389:22389] CHIP:FP: Forgetting fabric 0x1
[1694847019.456307][22389:22389] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847019.456584][22389:22389] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847019.456637][22389:22389] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847019.456716][22389:22389] CHIP:CTL: Shutting down the commissioner
[1694847019.456776][22389:22389] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847019.456921][22389:22389] CHIP:CTL: Shutting down the controller
[1694847019.456970][22389:22389] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1694847019.457236][22389:22389] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1694847019.457417][22389:22389] CHIP:FP: Shutting down FabricTable
[1694847019.457479][22389:22389] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847019.457694][22389:22389] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847019.457746][22389:22389] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847019.458205][22389:22389] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-2dIOUK)
[1694847019.459694][22389:22389] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847019.459820][22389:22389] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1694847019.459872][22389:22389] CHIP:DL: Inet Layer shutdown
[1694847019.459914][22389:22389] CHIP:DL: BLE shutdown
[1694847019.459957][22389:22389] CHIP:DL: System Layer shutdown
ubuntu@ubuntu:~/apps$ ./chip-tool networkcommissioning read networks 1 0
[1694847031.651700][22392:22392] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1694847031.657194][22392:22392] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1694847031.657458][22392:22392] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1694847031.657567][22392:22392] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1694847031.657896][22392:22392] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-qrN2TE)
[1694847031.658475][22392:22392] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847031.658526][22392:22392] CHIP:DL: NVS set: chip-counters/reboot-count = 6 (0x6)
[1694847031.659478][22392:22392] CHIP:DL: Got Ethernet interface: eth0
[1694847031.660033][22392:22392] CHIP:DL: Found the primary Ethernet interface:eth0
[1694847031.660617][22392:22392] CHIP:DL: Got WiFi interface: wlan0
[1694847031.660682][22392:22392] CHIP:DL: Failed to reset WiFi statistic counts
[1694847031.660763][22392:22392] CHIP:IN: UDP::Init bind&listen port=0
[1694847031.660865][22392:22392] CHIP:IN: UDP::Init bound to port=43627
[1694847031.660885][22392:22392] CHIP:IN: BLEBase::Init - setting/overriding transport
[1694847031.660902][22392:22392] CHIP:IN: TransportMgr initialized
[1694847031.660931][22392:22392] CHIP:FP: Initializing FabricTable from persistent storage
[1694847031.661072][22392:22392] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847031.662447][22392:22392] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x531C5E1335241DE8, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1694847031.666251][22392:22392] CHIP:ZCL: Using ZAP configuration...
[1694847031.670059][22392:22392] CHIP:DL: Avahi client registered
[1694847031.670194][22392:22392] CHIP:CTL: System State Initialized...
[1694847031.670285][22392:22392] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847031.670335][22392:22392] CHIP:CTL: Setting attestation nonce to random value
[1694847031.670372][22392:22392] CHIP:CTL: Setting CSR nonce to random value
[1694847031.670437][22392:22392] CHIP:IN: UDP::Init bind&listen port=5550
[1694847031.670574][22392:22392] CHIP:IN: UDP::Init bound to port=5550
[1694847031.670599][22392:22392] CHIP:IN: TransportMgr initialized
[1694847031.670891][22392:22394] CHIP:DL: CHIP task running
[1694847031.671093][22392:22394] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1694847031.671396][22392:22394] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847031.671450][22392:22394] CHIP:CTL: Setting attestation nonce to random value
[1694847031.671623][22392:22394] CHIP:CTL: Setting CSR nonce to random value
[1694847031.672544][22392:22394] CHIP:CTL: Generating NOC
[1694847031.673477][22392:22394] CHIP:FP: Validating NOC chain
[1694847031.675344][22392:22394] CHIP:FP: NOC chain validation successful
[1694847031.675506][22392:22394] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1694847031.675538][22392:22394] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847031.675559][22392:22394] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1694847031.675579][22392:22394] CHIP:TS: Retaining current Last Known Good Time
[1694847031.688875][22392:22394] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1694847031.693973][22392:22394] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-25T18:22:45
[1694847031.699170][22392:22394] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 531C5E1335241DE8)
[1694847031.699246][22392:22394] CHIP:IN: UDP::Init bind&listen port=5550
[1694847031.699426][22392:22394] CHIP:IN: UDP::Init bound to port=5550
[1694847031.699465][22392:22394] CHIP:IN: TransportMgr initialized
[1694847031.725214][22392:22394] CHIP:TOO: Sending command to node 0x1
[1694847031.725721][22392:22394] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1694847031.725756][22392:22394] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1694847031.725795][22392:22394] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1694847031.725830][22392:22394] CHIP:DIS: Resolving 531C5E1335241DE8:0000000000000001 ...
[1694847031.727815][22392:22394] CHIP:DL: Avahi resolve found
[1694847031.727892][22392:22394] CHIP:DIS: Node ID resolved for 531C5E1335241DE8:0000000000000001
[1694847031.727918][22392:22394] CHIP:DIS:      Hostname: 1A214799925ACE94
[1694847031.727948][22392:22394] CHIP:DIS:      IP Address #1: fd11:35::e119:c9a1:75db:8d1e
[1694847031.727973][22392:22394] CHIP:DIS:      Port: 5540
[1694847031.727996][22392:22394] CHIP:DIS:      Mrp Interval idle: 2800 ms
[1694847031.728019][22392:22394] CHIP:DIS:      Mrp Interval active: 1000 ms
[1694847031.728042][22392:22394] CHIP:DIS:      TCP Supported: 0
[1694847031.728899][22392:22394] CHIP:DIS: Lookup clearing interface for non LL address
[1694847031.729002][22392:22394] CHIP:DIS: UDP:[fd11:35::e119:c9a1:75db:8d1e%veth10eedd1]:5540: new best score: 5
[1694847031.729030][22392:22394] CHIP:DIS: Checking node lookup status after 3 ms
[1694847031.729051][22392:22394] CHIP:DIS: Keeping DNSSD lookup active
[1694847031.926655][22392:22394] CHIP:DIS: Checking node lookup status after 200 ms
[1694847031.926844][22392:22394] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540 while in state 2
[1694847031.926903][22392:22394] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1694847031.927226][22392:22394] CHIP:IN: SecureSession[0xffff7800aef0]: Allocated Type:2 LSID:14147
[1694847031.927321][22392:22394] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1694847031.929180][22392:22394] CHIP:EM: <<< [E:39671i S:0 M:96665082] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1694847031.929319][22392:22394] CHIP:IN: (U) Sending msg 96665082 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847031.929638][22392:22394] CHIP:SC: Sent Sigma1 msg
[1694847031.929712][22392:22394] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1694847033.652605][22392:22394] CHIP:EM: >>> [E:39671i S:0 M:56493093 (Ack:96665082)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847033.652697][22392:22394] CHIP:EM: Found matching exchange: 39671i, Delegate: 0xffff7800dd98
[1694847033.652771][22392:22394] CHIP:EM: Rxd Ack; Removing MessageCounter:96665082 from Retrans Table on exchange 39671i
[1694847033.970009][22392:22394] CHIP:EM: >>> [E:39671i S:0 M:56493094 (Ack:96665082)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1694847033.970069][22392:22394] CHIP:EM: Found matching exchange: 39671i, Delegate: 0xffff7800dd98
[1694847033.970100][22392:22394] CHIP:EM: CHIP MessageCounter:96665082 not in RetransTable on exchange 39671i
[1694847033.970158][22392:22394] CHIP:SC: Received Sigma2 msg
[1694847033.970205][22392:22394] CHIP:SC: Peer assigned session session ID 51789
[1694847033.974059][22392:22394] CHIP:SC: Found MRP parameters in the message
[1694847033.974119][22392:22394] CHIP:SC: Sending Sigma3
[1694847033.974620][22392:22394] CHIP:EM: <<< [E:39671i S:0 M:96665083 (Ack:56493094)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1694847033.974812][22392:22394] CHIP:IN: (U) Sending msg 96665083 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847033.974991][22392:22394] CHIP:SC: Sent Sigma3 msg
[1694847034.191560][22392:22394] CHIP:EM: >>> [E:39671i S:0 M:56493095 (Ack:96665083)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847034.191650][22392:22394] CHIP:EM: Found matching exchange: 39671i, Delegate: 0xffff7800dd98
[1694847034.191723][22392:22394] CHIP:EM: Rxd Ack; Removing MessageCounter:96665083 from Retrans Table on exchange 39671i
[1694847034.383738][22392:22394] CHIP:EM: >>> [E:39671i S:0 M:56493096 (Ack:96665083)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1694847034.383839][22392:22394] CHIP:EM: Found matching exchange: 39671i, Delegate: 0xffff7800dd98
[1694847034.383900][22392:22394] CHIP:EM: CHIP MessageCounter:96665083 not in RetransTable on exchange 39671i
[1694847034.384003][22392:22394] CHIP:SC: Success status report received. Session was established
[1694847034.392825][22392:22394] CHIP:SC: SecureSession[0xffff7800aef0, LSID:14147]: State change 'kEstablishing' --> 'kActive'
[1694847034.392904][22392:22394] CHIP:IN: SecureSession[0xffff7800aef0]: Activated - Type:2 LSID:14147
[1694847034.392938][22392:22394] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:14147 PSID:51789!
[1694847034.392983][22392:22394] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1694847034.393081][22392:22394] CHIP:TOO: Sending ReadAttribute to:
[1694847034.393187][22392:22394] CHIP:TOO:      cluster 0x0000_0031, attribute: 0x0000_0001, endpoint 0
[1694847034.393249][22392:22394] CHIP:DMG: SendReadRequest ReadClient[0xffff780110a0]: Sending Read Request
[1694847034.393463][22392:22394] CHIP:EM: <<< [E:39672i S:14147 M:95690121] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0001:02 (IM:ReadRequest)
[1694847034.393532][22392:22394] CHIP:IN: (S) Sending msg 95690121 on secure session with LSID: 14147
[1694847034.393782][22392:22394] CHIP:DMG: MoveToState ReadClient[0xffff780110a0]: Moving to [AwaitingIn]
[1694847034.393888][22392:22394] CHIP:EM: <<< [E:39671i S:0 M:96665084 (Ack:56493096)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847034.394083][22392:22394] CHIP:IN: (U) Sending msg 96665084 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847034.394226][22392:22394] CHIP:EM: Flushed pending ack for MessageCounter:56493096 on exchange 39671i
[1694847034.605688][22392:22394] CHIP:EM: >>> [E:39672i S:14147 M:267589899 (Ack:95690121)] (S) Msg RX from 1:0000000000000001 [1DE8] --- Type 0001:05 (IM:ReportData)
[1694847034.605780][22392:22394] CHIP:EM: Found matching exchange: 39672i, Delegate: 0xffff780110b0
[1694847034.605852][22392:22394] CHIP:EM: Rxd Ack; Removing MessageCounter:95690121 from Retrans Table on exchange 39672i
[1694847034.605967][22392:22394] CHIP:DMG: ReportDataMessage =
[1694847034.606021][22392:22394] CHIP:DMG: {
[1694847034.606064][22392:22394] CHIP:DMG:      AttributeReportIBs =
[1694847034.606129][22392:22394] CHIP:DMG:      [
[1694847034.606178][22392:22394] CHIP:DMG:              AttributeReportIB =
[1694847034.606246][22392:22394] CHIP:DMG:              {
[1694847034.606299][22392:22394] CHIP:DMG:                      AttributeDataIB =
[1694847034.606366][22392:22394] CHIP:DMG:                      {
[1694847034.606427][22392:22394] CHIP:DMG:                              DataVersion = 0x8cef20fc,
[1694847034.606490][22392:22394] CHIP:DMG:                              AttributePathIB =
[1694847034.606555][22392:22394] CHIP:DMG:                              {
[1694847034.606620][22392:22394] CHIP:DMG:                                      Endpoint = 0x0,
[1694847034.606735][22392:22394] CHIP:DMG:                                      Cluster = 0x31,
[1694847034.606807][22392:22394] CHIP:DMG:                                      Attribute = 0x0000_0001,
[1694847034.606873][22392:22394] CHIP:DMG:                              }
[1694847034.606941][22392:22394] CHIP:DMG:
[1694847034.607004][22392:22394] CHIP:DMG:                              Data = [
[1694847034.607067][22392:22394] CHIP:DMG:
[1694847034.607136][22392:22394] CHIP:DMG:                              ],
[1694847034.607196][22392:22394] CHIP:DMG:                      },
[1694847034.607263][22392:22394] CHIP:DMG:
[1694847034.607315][22392:22394] CHIP:DMG:              },
[1694847034.607376][22392:22394] CHIP:DMG:
[1694847034.607425][22392:22394] CHIP:DMG:      ],
[1694847034.607486][22392:22394] CHIP:DMG:
[1694847034.607535][22392:22394] CHIP:DMG:      SuppressResponse = true,
[1694847034.607585][22392:22394] CHIP:DMG:      InteractionModelRevision = 1
[1694847034.607633][22392:22394] CHIP:DMG: }
[1694847034.607936][22392:22394] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0031 Attribute 0x0000_0001 DataVersion: 2364481788
[1694847034.608076][22392:22394] CHIP:TOO:   Networks: 0 entries
[1694847034.608355][22392:22394] CHIP:EM: <<< [E:39672i S:14147 M:95690122 (Ack:267589899)] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847034.608435][22392:22394] CHIP:IN: (S) Sending msg 95690122 on secure session with LSID: 14147
[1694847034.608663][22392:22394] CHIP:EM: Flushed pending ack for MessageCounter:267589899 on exchange 39672i
[1694847034.609050][22392:22392] CHIP:CTL: Shutting down the commissioner
[1694847034.609113][22392:22392] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847034.609275][22392:22392] CHIP:CTL: Shutting down the controller
[1694847034.609366][22392:22392] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1694847034.609412][22392:22392] CHIP:IN: SecureSession[0xffff7800aef0]: MarkForEviction Type:2 LSID:14147
[1694847034.609458][22392:22392] CHIP:SC: SecureSession[0xffff7800aef0, LSID:14147]: State change 'kActive' --> 'kPendingEviction'
[1694847034.609503][22392:22392] CHIP:IN: SecureSession[0xffff7800aef0]: Released - Type:2 LSID:14147
[1694847034.609552][22392:22392] CHIP:FP: Forgetting fabric 0x1
[1694847034.609659][22392:22392] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847034.609945][22392:22392] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847034.610011][22392:22392] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847034.610099][22392:22392] CHIP:CTL: Shutting down the commissioner
[1694847034.610153][22392:22392] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847034.610303][22392:22392] CHIP:CTL: Shutting down the controller
[1694847034.610351][22392:22392] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1694847034.610632][22392:22392] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1694847034.610873][22392:22392] CHIP:FP: Shutting down FabricTable
[1694847034.610939][22392:22392] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847034.611156][22392:22392] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847034.611209][22392:22392] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847034.611627][22392:22392] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-n918vf)
[1694847034.612813][22392:22392] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847034.612932][22392:22392] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1694847034.612983][22392:22392] CHIP:DL: Inet Layer shutdown
[1694847034.613024][22392:22392] CHIP:DL: BLE shutdown
[1694847034.613067][22392:22392] CHIP:DL: System Layer shutdown
ubuntu@ubuntu:~/apps$ ./chip-tool networkcommissioning read last-networking-status 1 0
[1694847043.821514][22397:22397] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1694847043.826918][22397:22397] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1694847043.827189][22397:22397] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1694847043.827299][22397:22397] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1694847043.827647][22397:22397] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-GtBItT)
[1694847043.828232][22397:22397] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847043.828282][22397:22397] CHIP:DL: NVS set: chip-counters/reboot-count = 7 (0x7)
[1694847043.829213][22397:22397] CHIP:DL: Got Ethernet interface: eth0
[1694847043.829785][22397:22397] CHIP:DL: Found the primary Ethernet interface:eth0
[1694847043.830374][22397:22397] CHIP:DL: Got WiFi interface: wlan0
[1694847043.830434][22397:22397] CHIP:DL: Failed to reset WiFi statistic counts
[1694847043.830525][22397:22397] CHIP:IN: UDP::Init bind&listen port=0
[1694847043.830639][22397:22397] CHIP:IN: UDP::Init bound to port=51585
[1694847043.830660][22397:22397] CHIP:IN: BLEBase::Init - setting/overriding transport
[1694847043.830701][22397:22397] CHIP:IN: TransportMgr initialized
[1694847043.830733][22397:22397] CHIP:FP: Initializing FabricTable from persistent storage
[1694847043.830871][22397:22397] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847043.832243][22397:22397] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x531C5E1335241DE8, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1694847043.835849][22397:22397] CHIP:ZCL: Using ZAP configuration...
[1694847043.839428][22397:22397] CHIP:DL: Avahi client registered
[1694847043.839553][22397:22397] CHIP:CTL: System State Initialized...
[1694847043.839635][22397:22397] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847043.839698][22397:22397] CHIP:CTL: Setting attestation nonce to random value
[1694847043.839730][22397:22397] CHIP:CTL: Setting CSR nonce to random value
[1694847043.839793][22397:22397] CHIP:IN: UDP::Init bind&listen port=5550
[1694847043.839931][22397:22397] CHIP:IN: UDP::Init bound to port=5550
[1694847043.839959][22397:22397] CHIP:IN: TransportMgr initialized
[1694847043.840210][22397:22399] CHIP:DL: CHIP task running
[1694847043.840381][22397:22399] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1694847043.840648][22397:22399] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847043.840695][22397:22399] CHIP:CTL: Setting attestation nonce to random value
[1694847043.840840][22397:22399] CHIP:CTL: Setting CSR nonce to random value
[1694847043.841632][22397:22399] CHIP:CTL: Generating NOC
[1694847043.842442][22397:22399] CHIP:FP: Validating NOC chain
[1694847043.844061][22397:22399] CHIP:FP: NOC chain validation successful
[1694847043.844279][22397:22399] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1694847043.844321][22397:22399] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847043.844351][22397:22399] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1694847043.844378][22397:22399] CHIP:TS: Retaining current Last Known Good Time
[1694847043.857776][22397:22399] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1694847043.862402][22397:22399] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-25T18:22:45
[1694847043.867805][22397:22399] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 531C5E1335241DE8)
[1694847043.867874][22397:22399] CHIP:IN: UDP::Init bind&listen port=5550
[1694847043.868022][22397:22399] CHIP:IN: UDP::Init bound to port=5550
[1694847043.868054][22397:22399] CHIP:IN: TransportMgr initialized
[1694847043.894160][22397:22399] CHIP:TOO: Sending command to node 0x1
[1694847043.894666][22397:22399] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1694847043.894819][22397:22399] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1694847043.894857][22397:22399] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1694847043.894892][22397:22399] CHIP:DIS: Resolving 531C5E1335241DE8:0000000000000001 ...
[1694847043.896705][22397:22399] CHIP:DL: Avahi resolve found
[1694847043.896779][22397:22399] CHIP:DIS: Node ID resolved for 531C5E1335241DE8:0000000000000001
[1694847043.896802][22397:22399] CHIP:DIS:      Hostname: 1A214799925ACE94
[1694847043.896828][22397:22399] CHIP:DIS:      IP Address #1: fd11:35::e119:c9a1:75db:8d1e
[1694847043.896860][22397:22399] CHIP:DIS:      Port: 5540
[1694847043.896891][22397:22399] CHIP:DIS:      Mrp Interval idle: 2800 ms
[1694847043.896917][22397:22399] CHIP:DIS:      Mrp Interval active: 1000 ms
[1694847043.896939][22397:22399] CHIP:DIS:      TCP Supported: 0
[1694847043.897662][22397:22399] CHIP:DIS: Lookup clearing interface for non LL address
[1694847043.897751][22397:22399] CHIP:DIS: UDP:[fd11:35::e119:c9a1:75db:8d1e%veth10eedd1]:5540: new best score: 5
[1694847043.897772][22397:22399] CHIP:DIS: Checking node lookup status after 3 ms
[1694847043.897789][22397:22399] CHIP:DIS: Keeping DNSSD lookup active
[1694847044.095133][22397:22399] CHIP:DIS: Checking node lookup status after 200 ms
[1694847044.095262][22397:22399] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540 while in state 2
[1694847044.095319][22397:22399] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1694847044.095652][22397:22399] CHIP:IN: SecureSession[0xffff7c00aef0]: Allocated Type:2 LSID:46028
[1694847044.095750][22397:22399] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1694847044.097631][22397:22399] CHIP:EM: <<< [E:62984i S:0 M:124143657] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1694847044.097770][22397:22399] CHIP:IN: (U) Sending msg 124143657 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847044.098091][22397:22399] CHIP:SC: Sent Sigma1 msg
[1694847044.098162][22397:22399] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1694847044.931202][22397:22399] CHIP:EM: >>> [E:62984i S:0 M:56493097 (Ack:124143657)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847044.931294][22397:22399] CHIP:EM: Found matching exchange: 62984i, Delegate: 0xffff7c00dd98
[1694847044.931370][22397:22399] CHIP:EM: Rxd Ack; Removing MessageCounter:124143657 from Retrans Table on exchange 62984i
[1694847045.209139][22397:22399] CHIP:EM: >>> [E:62984i S:0 M:56493098 (Ack:124143657)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1694847045.209231][22397:22399] CHIP:EM: Found matching exchange: 62984i, Delegate: 0xffff7c00dd98
[1694847045.209384][22397:22399] CHIP:EM: CHIP MessageCounter:124143657 not in RetransTable on exchange 62984i
[1694847045.209485][22397:22399] CHIP:SC: Received Sigma2 msg
[1694847045.209562][22397:22399] CHIP:SC: Peer assigned session session ID 51790
[1694847045.217528][22397:22399] CHIP:SC: Found MRP parameters in the message
[1694847045.217627][22397:22399] CHIP:SC: Sending Sigma3
[1694847045.218600][22397:22399] CHIP:EM: <<< [E:62984i S:0 M:124143658 (Ack:56493098)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1694847045.218889][22397:22399] CHIP:IN: (U) Sending msg 124143658 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847045.219172][22397:22399] CHIP:SC: Sent Sigma3 msg
[1694847045.464091][22397:22399] CHIP:EM: >>> [E:62984i S:0 M:56493099 (Ack:124143658)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847045.464183][22397:22399] CHIP:EM: Found matching exchange: 62984i, Delegate: 0xffff7c00dd98
[1694847045.464258][22397:22399] CHIP:EM: Rxd Ack; Removing MessageCounter:124143658 from Retrans Table on exchange 62984i
[1694847045.657465][22397:22399] CHIP:EM: >>> [E:62984i S:0 M:56493100 (Ack:124143658)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1694847045.657576][22397:22399] CHIP:EM: Found matching exchange: 62984i, Delegate: 0xffff7c00dd98
[1694847045.657639][22397:22399] CHIP:EM: CHIP MessageCounter:124143658 not in RetransTable on exchange 62984i
[1694847045.657760][22397:22399] CHIP:SC: Success status report received. Session was established
[1694847045.667324][22397:22399] CHIP:SC: SecureSession[0xffff7c00aef0, LSID:46028]: State change 'kEstablishing' --> 'kActive'
[1694847045.667433][22397:22399] CHIP:IN: SecureSession[0xffff7c00aef0]: Activated - Type:2 LSID:46028
[1694847045.667487][22397:22399] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:46028 PSID:51790!
[1694847045.667550][22397:22399] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1694847045.667685][22397:22399] CHIP:TOO: Sending ReadAttribute to:
[1694847045.667835][22397:22399] CHIP:TOO:      cluster 0x0000_0031, attribute: 0x0000_0005, endpoint 0
[1694847045.667927][22397:22399] CHIP:DMG: SendReadRequest ReadClient[0xffff7c0110a0]: Sending Read Request
[1694847045.668281][22397:22399] CHIP:EM: <<< [E:62985i S:46028 M:252836071] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0001:02 (IM:ReadRequest)
[1694847045.668402][22397:22399] CHIP:IN: (S) Sending msg 252836071 on secure session with LSID: 46028
[1694847045.668634][22397:22399] CHIP:DMG: MoveToState ReadClient[0xffff7c0110a0]: Moving to [AwaitingIn]
[1694847045.668712][22397:22399] CHIP:EM: <<< [E:62984i S:0 M:124143659 (Ack:56493100)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847045.668881][22397:22399] CHIP:IN: (U) Sending msg 124143659 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847045.669001][22397:22399] CHIP:EM: Flushed pending ack for MessageCounter:56493100 on exchange 62984i
[1694847045.703129][22397:22399] CHIP:EM: >>> [E:62985i S:46028 M:263667777 (Ack:252836071)] (S) Msg RX from 1:0000000000000001 [1DE8] --- Type 0001:05 (IM:ReportData)
[1694847045.703220][22397:22399] CHIP:EM: Found matching exchange: 62985i, Delegate: 0xffff7c0110b0
[1694847045.703293][22397:22399] CHIP:EM: Rxd Ack; Removing MessageCounter:252836071 from Retrans Table on exchange 62985i
[1694847045.703410][22397:22399] CHIP:DMG: ReportDataMessage =
[1694847045.703464][22397:22399] CHIP:DMG: {
[1694847045.703506][22397:22399] CHIP:DMG:      AttributeReportIBs =
[1694847045.703569][22397:22399] CHIP:DMG:      [
[1694847045.703617][22397:22399] CHIP:DMG:              AttributeReportIB =
[1694847045.703716][22397:22399] CHIP:DMG:              {
[1694847045.703770][22397:22399] CHIP:DMG:                      AttributeDataIB =
[1694847045.703855][22397:22399] CHIP:DMG:                      {
[1694847045.703918][22397:22399] CHIP:DMG:                              DataVersion = 0x8cef20fc,
[1694847045.703998][22397:22399] CHIP:DMG:                              AttributePathIB =
[1694847045.704066][22397:22399] CHIP:DMG:                              {
[1694847045.704130][22397:22399] CHIP:DMG:                                      Endpoint = 0x0,
[1694847045.704219][22397:22399] CHIP:DMG:                                      Cluster = 0x31,
[1694847045.704306][22397:22399] CHIP:DMG:                                      Attribute = 0x0000_0005,
[1694847045.704372][22397:22399] CHIP:DMG:                              }
[1694847045.704458][22397:22399] CHIP:DMG:
[1694847045.704528][22397:22399] CHIP:DMG:                              Data = 0,
[1694847045.704606][22397:22399] CHIP:DMG:                      },
[1694847045.704674][22397:22399] CHIP:DMG:
[1694847045.704743][22397:22399] CHIP:DMG:              },
[1694847045.704808][22397:22399] CHIP:DMG:
[1694847045.704856][22397:22399] CHIP:DMG:      ],
[1694847045.704936][22397:22399] CHIP:DMG:
[1694847045.704986][22397:22399] CHIP:DMG:      SuppressResponse = true,
[1694847045.705055][22397:22399] CHIP:DMG:      InteractionModelRevision = 1
[1694847045.705105][22397:22399] CHIP:DMG: }
[1694847045.705401][22397:22399] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0031 Attribute 0x0000_0005 DataVersion: 2364481788
[1694847045.709918][22397:22399] CHIP:TOO:   LastNetworkingStatus: 0
[1694847045.710209][22397:22399] CHIP:EM: <<< [E:62985i S:46028 M:252836072 (Ack:263667777)] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847045.710316][22397:22399] CHIP:IN: (S) Sending msg 252836072 on secure session with LSID: 46028
[1694847045.710534][22397:22399] CHIP:EM: Flushed pending ack for MessageCounter:263667777 on exchange 62985i
[1694847045.710939][22397:22397] CHIP:CTL: Shutting down the commissioner
[1694847045.711004][22397:22397] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847045.711157][22397:22397] CHIP:CTL: Shutting down the controller
[1694847045.711247][22397:22397] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1694847045.711294][22397:22397] CHIP:IN: SecureSession[0xffff7c00aef0]: MarkForEviction Type:2 LSID:46028
[1694847045.711339][22397:22397] CHIP:SC: SecureSession[0xffff7c00aef0, LSID:46028]: State change 'kActive' --> 'kPendingEviction'
[1694847045.711383][22397:22397] CHIP:IN: SecureSession[0xffff7c00aef0]: Released - Type:2 LSID:46028
[1694847045.711432][22397:22397] CHIP:FP: Forgetting fabric 0x1
[1694847045.711492][22397:22397] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847045.711774][22397:22397] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847045.711831][22397:22397] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847045.711927][22397:22397] CHIP:CTL: Shutting down the commissioner
[1694847045.711972][22397:22397] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847045.712117][22397:22397] CHIP:CTL: Shutting down the controller
[1694847045.712170][22397:22397] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1694847045.712445][22397:22397] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1694847045.712628][22397:22397] CHIP:FP: Shutting down FabricTable
[1694847045.712691][22397:22397] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847045.712904][22397:22397] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847045.712958][22397:22397] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847045.713339][22397:22397] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-41tAWP)
[1694847045.714208][22397:22397] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847045.714289][22397:22397] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1694847045.714320][22397:22397] CHIP:DL: Inet Layer shutdown
[1694847045.714346][22397:22397] CHIP:DL: BLE shutdown
[1694847045.714371][22397:22397] CHIP:DL: System Layer shutdown
ubuntu@ubuntu:~/apps$ ./chip-tool networkcommissioning read last-network-id 1 0
[1694847057.946508][22400:22400] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1694847057.951922][22400:22400] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1694847057.952166][22400:22400] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1694847057.952301][22400:22400] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1694847057.952659][22400:22400] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-MYUliB)
[1694847057.953245][22400:22400] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847057.953296][22400:22400] CHIP:DL: NVS set: chip-counters/reboot-count = 8 (0x8)
[1694847057.954224][22400:22400] CHIP:DL: Got Ethernet interface: eth0
[1694847057.954824][22400:22400] CHIP:DL: Found the primary Ethernet interface:eth0
[1694847057.955423][22400:22400] CHIP:DL: Got WiFi interface: wlan0
[1694847057.955483][22400:22400] CHIP:DL: Failed to reset WiFi statistic counts
[1694847057.955578][22400:22400] CHIP:IN: UDP::Init bind&listen port=0
[1694847057.955689][22400:22400] CHIP:IN: UDP::Init bound to port=45732
[1694847057.955709][22400:22400] CHIP:IN: BLEBase::Init - setting/overriding transport
[1694847057.955726][22400:22400] CHIP:IN: TransportMgr initialized
[1694847057.955756][22400:22400] CHIP:FP: Initializing FabricTable from persistent storage
[1694847057.955893][22400:22400] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847057.957283][22400:22400] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x531C5E1335241DE8, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1694847057.961656][22400:22400] CHIP:ZCL: Using ZAP configuration...
[1694847057.965180][22400:22400] CHIP:DL: Avahi client registered
[1694847057.965301][22400:22400] CHIP:CTL: System State Initialized...
[1694847057.965380][22400:22400] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847057.965442][22400:22400] CHIP:CTL: Setting attestation nonce to random value
[1694847057.965476][22400:22400] CHIP:CTL: Setting CSR nonce to random value
[1694847057.965541][22400:22400] CHIP:IN: UDP::Init bind&listen port=5550
[1694847057.965677][22400:22400] CHIP:IN: UDP::Init bound to port=5550
[1694847057.965706][22400:22400] CHIP:IN: TransportMgr initialized
[1694847057.965952][22400:22402] CHIP:DL: CHIP task running
[1694847057.966126][22400:22402] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1694847057.966392][22400:22402] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847057.966440][22400:22402] CHIP:CTL: Setting attestation nonce to random value
[1694847057.966587][22400:22402] CHIP:CTL: Setting CSR nonce to random value
[1694847057.967413][22400:22402] CHIP:CTL: Generating NOC
[1694847057.968248][22400:22402] CHIP:FP: Validating NOC chain
[1694847057.970163][22400:22402] CHIP:FP: NOC chain validation successful
[1694847057.970363][22400:22402] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1694847057.970402][22400:22402] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847057.970429][22400:22402] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1694847057.970453][22400:22402] CHIP:TS: Retaining current Last Known Good Time
[1694847057.984089][22400:22402] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1694847057.988959][22400:22402] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-25T18:22:45
[1694847057.994610][22400:22402] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 531C5E1335241DE8)
[1694847057.994747][22400:22402] CHIP:IN: UDP::Init bind&listen port=5550
[1694847057.994901][22400:22402] CHIP:IN: UDP::Init bound to port=5550
[1694847057.994933][22400:22402] CHIP:IN: TransportMgr initialized
[1694847058.021135][22400:22402] CHIP:TOO: Sending command to node 0x1
[1694847058.021592][22400:22402] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1694847058.021622][22400:22402] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1694847058.021658][22400:22402] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1694847058.021691][22400:22402] CHIP:DIS: Resolving 531C5E1335241DE8:0000000000000001 ...
[1694847058.129811][22400:22402] CHIP:DL: Avahi resolve found
[1694847058.129933][22400:22402] CHIP:DIS: Node ID resolved for 531C5E1335241DE8:0000000000000001
[1694847058.129979][22400:22402] CHIP:DIS:      Hostname: 1A214799925ACE94
[1694847058.130023][22400:22402] CHIP:DIS:      IP Address #1: fd11:35::e119:c9a1:75db:8d1e
[1694847058.130058][22400:22402] CHIP:DIS:      Port: 5540
[1694847058.130091][22400:22402] CHIP:DIS:      Mrp Interval idle: 2800 ms
[1694847058.130128][22400:22402] CHIP:DIS:      Mrp Interval active: 1000 ms
[1694847058.130164][22400:22402] CHIP:DIS:      TCP Supported: 0
[1694847058.131478][22400:22402] CHIP:DIS: Lookup clearing interface for non LL address
[1694847058.131637][22400:22402] CHIP:DIS: UDP:[fd11:35::e119:c9a1:75db:8d1e%veth10eedd1]:5540: new best score: 5
[1694847058.131681][22400:22402] CHIP:DIS: Checking node lookup status after 110 ms
[1694847058.131721][22400:22402] CHIP:DIS: Keeping DNSSD lookup active
[1694847058.222260][22400:22402] CHIP:DIS: Checking node lookup status after 200 ms
[1694847058.222375][22400:22402] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540 while in state 2
[1694847058.222433][22400:22402] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1694847058.222825][22400:22402] CHIP:IN: SecureSession[0xffff8800aef0]: Allocated Type:2 LSID:15639
[1694847058.222926][22400:22402] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1694847058.224829][22400:22402] CHIP:EM: <<< [E:45501i S:0 M:80296439] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1694847058.224972][22400:22402] CHIP:IN: (U) Sending msg 80296439 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847058.225299][22400:22402] CHIP:SC: Sent Sigma1 msg
[1694847058.225422][22400:22402] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1694847059.919658][22400:22402] CHIP:EM: >>> [E:45501i S:0 M:56493101 (Ack:80296439)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847059.919752][22400:22402] CHIP:EM: Found matching exchange: 45501i, Delegate: 0xffff8800dd98
[1694847059.919828][22400:22402] CHIP:EM: Rxd Ack; Removing MessageCounter:80296439 from Retrans Table on exchange 45501i
[1694847060.219378][22400:22402] CHIP:EM: >>> [E:45501i S:0 M:56493102 (Ack:80296439)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1694847060.219466][22400:22402] CHIP:EM: Found matching exchange: 45501i, Delegate: 0xffff8800dd98
[1694847060.219518][22400:22402] CHIP:EM: CHIP MessageCounter:80296439 not in RetransTable on exchange 45501i
[1694847060.219611][22400:22402] CHIP:SC: Received Sigma2 msg
[1694847060.219688][22400:22402] CHIP:SC: Peer assigned session session ID 51791
[1694847060.228214][22400:22402] CHIP:SC: Found MRP parameters in the message
[1694847060.228318][22400:22402] CHIP:SC: Sending Sigma3
[1694847060.229378][22400:22402] CHIP:EM: <<< [E:45501i S:0 M:80296440 (Ack:56493102)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1694847060.229666][22400:22402] CHIP:IN: (U) Sending msg 80296440 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847060.229971][22400:22402] CHIP:SC: Sent Sigma3 msg
[1694847060.445048][22400:22402] CHIP:EM: >>> [E:45501i S:0 M:56493103 (Ack:80296440)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847060.445135][22400:22402] CHIP:EM: Found matching exchange: 45501i, Delegate: 0xffff8800dd98
[1694847060.445209][22400:22402] CHIP:EM: Rxd Ack; Removing MessageCounter:80296440 from Retrans Table on exchange 45501i
[1694847060.634898][22400:22402] CHIP:EM: >>> [E:45501i S:0 M:56493104 (Ack:80296440)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1694847060.634998][22400:22402] CHIP:EM: Found matching exchange: 45501i, Delegate: 0xffff8800dd98
[1694847060.635058][22400:22402] CHIP:EM: CHIP MessageCounter:80296440 not in RetransTable on exchange 45501i
[1694847060.635162][22400:22402] CHIP:SC: Success status report received. Session was established
[1694847060.644543][22400:22402] CHIP:SC: SecureSession[0xffff8800aef0, LSID:15639]: State change 'kEstablishing' --> 'kActive'
[1694847060.644608][22400:22402] CHIP:IN: SecureSession[0xffff8800aef0]: Activated - Type:2 LSID:15639
[1694847060.644637][22400:22402] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:15639 PSID:51791!
[1694847060.644674][22400:22402] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1694847060.644759][22400:22402] CHIP:TOO: Sending ReadAttribute to:
[1694847060.644851][22400:22402] CHIP:TOO:      cluster 0x0000_0031, attribute: 0x0000_0006, endpoint 0
[1694847060.644905][22400:22402] CHIP:DMG: SendReadRequest ReadClient[0xffff880110a0]: Sending Read Request
[1694847060.645098][22400:22402] CHIP:EM: <<< [E:45502i S:15639 M:97210167] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0001:02 (IM:ReadRequest)
[1694847060.645155][22400:22402] CHIP:IN: (S) Sending msg 97210167 on secure session with LSID: 15639
[1694847060.645378][22400:22402] CHIP:DMG: MoveToState ReadClient[0xffff880110a0]: Moving to [AwaitingIn]
[1694847060.645467][22400:22402] CHIP:EM: <<< [E:45501i S:0 M:80296441 (Ack:56493104)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847060.645641][22400:22402] CHIP:IN: (U) Sending msg 80296441 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847060.645764][22400:22402] CHIP:EM: Flushed pending ack for MessageCounter:56493104 on exchange 45501i
[1694847060.856844][22400:22402] CHIP:EM: >>> [E:45502i S:15639 M:122340649 (Ack:97210167)] (S) Msg RX from 1:0000000000000001 [1DE8] --- Type 0001:05 (IM:ReportData)
[1694847060.856928][22400:22402] CHIP:EM: Found matching exchange: 45502i, Delegate: 0xffff880110b0
[1694847060.856993][22400:22402] CHIP:EM: Rxd Ack; Removing MessageCounter:97210167 from Retrans Table on exchange 45502i
[1694847060.857098][22400:22402] CHIP:DMG: ReportDataMessage =
[1694847060.857146][22400:22402] CHIP:DMG: {
[1694847060.857183][22400:22402] CHIP:DMG:      AttributeReportIBs =
[1694847060.857239][22400:22402] CHIP:DMG:      [
[1694847060.857282][22400:22402] CHIP:DMG:              AttributeReportIB =
[1694847060.857353][22400:22402] CHIP:DMG:              {
[1694847060.857405][22400:22402] CHIP:DMG:                      AttributeDataIB =
[1694847060.857586][22400:22402] CHIP:DMG:                      {
[1694847060.857652][22400:22402] CHIP:DMG:                              DataVersion = 0x8cef20fc,
[1694847060.857713][22400:22402] CHIP:DMG:                              AttributePathIB =
[1694847060.857779][22400:22402] CHIP:DMG:                              {
[1694847060.857843][22400:22402] CHIP:DMG:                                      Endpoint = 0x0,
[1694847060.857912][22400:22402] CHIP:DMG:                                      Cluster = 0x31,
[1694847060.857978][22400:22402] CHIP:DMG:                                      Attribute = 0x0000_0006,
[1694847060.858042][22400:22402] CHIP:DMG:                              }
[1694847060.858110][22400:22402] CHIP:DMG:
[1694847060.858176][22400:22402] CHIP:DMG:                              Data = [
[1694847060.858243][22400:22402] CHIP:DMG:                                              0x18, 0xb1, 0xa8, 0xd8, 0xfc, 0x4c, 0x18, 0x70,
[1694847060.858311][22400:22402] CHIP:DMG:                              ] (8 bytes)
[1694847060.858371][22400:22402] CHIP:DMG:                      },
[1694847060.858437][22400:22402] CHIP:DMG:
[1694847060.858489][22400:22402] CHIP:DMG:              },
[1694847060.858551][22400:22402] CHIP:DMG:
[1694847060.858599][22400:22402] CHIP:DMG:      ],
[1694847060.858660][22400:22402] CHIP:DMG:
[1694847060.858751][22400:22402] CHIP:DMG:      SuppressResponse = true,
[1694847060.858804][22400:22402] CHIP:DMG:      InteractionModelRevision = 1
[1694847060.858851][22400:22402] CHIP:DMG: }
[1694847060.859123][22400:22402] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0031 Attribute 0x0000_0006 DataVersion: 2364481788
[1694847060.859227][22400:22402] CHIP:TOO:   LastNetworkID: 18B1A8D8FC4C1870
[1694847060.859495][22400:22402] CHIP:EM: <<< [E:45502i S:15639 M:97210168 (Ack:122340649)] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847060.859576][22400:22402] CHIP:IN: (S) Sending msg 97210168 on secure session with LSID: 15639
[1694847060.859799][22400:22402] CHIP:EM: Flushed pending ack for MessageCounter:122340649 on exchange 45502i
[1694847060.860191][22400:22400] CHIP:CTL: Shutting down the commissioner
[1694847060.860255][22400:22400] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847060.860412][22400:22400] CHIP:CTL: Shutting down the controller
[1694847060.860504][22400:22400] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1694847060.860550][22400:22400] CHIP:IN: SecureSession[0xffff8800aef0]: MarkForEviction Type:2 LSID:15639
[1694847060.860596][22400:22400] CHIP:SC: SecureSession[0xffff8800aef0, LSID:15639]: State change 'kActive' --> 'kPendingEviction'
[1694847060.860641][22400:22400] CHIP:IN: SecureSession[0xffff8800aef0]: Released - Type:2 LSID:15639
[1694847060.860690][22400:22400] CHIP:FP: Forgetting fabric 0x1
[1694847060.860794][22400:22400] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847060.861079][22400:22400] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847060.861142][22400:22400] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847060.861233][22400:22400] CHIP:CTL: Shutting down the commissioner
[1694847060.861287][22400:22400] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847060.861435][22400:22400] CHIP:CTL: Shutting down the controller
[1694847060.861484][22400:22400] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1694847060.861788][22400:22400] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1694847060.861983][22400:22400] CHIP:FP: Shutting down FabricTable
[1694847060.862056][22400:22400] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847060.862279][22400:22400] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847060.862341][22400:22400] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847060.862777][22400:22400] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-pN6tDw)
[1694847060.863925][22400:22400] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847060.864046][22400:22400] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1694847060.864098][22400:22400] CHIP:DL: Inet Layer shutdown
[1694847060.864140][22400:22400] CHIP:DL: BLE shutdown
[1694847060.864183][22400:22400] CHIP:DL: System Layer shutdown
ubuntu@ubuntu:~/apps$ ./chip-tool generalcommissioning read breadcrumb 1 0
[1694847071.383439][22404:22404] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1694847071.388832][22404:22404] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1694847071.389075][22404:22404] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1694847071.389186][22404:22404] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1694847071.389519][22404:22404] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-yaZjKn)
[1694847071.390100][22404:22404] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847071.390151][22404:22404] CHIP:DL: NVS set: chip-counters/reboot-count = 9 (0x9)
[1694847071.391104][22404:22404] CHIP:DL: Got Ethernet interface: eth0
[1694847071.391678][22404:22404] CHIP:DL: Found the primary Ethernet interface:eth0
[1694847071.392260][22404:22404] CHIP:DL: Got WiFi interface: wlan0
[1694847071.392321][22404:22404] CHIP:DL: Failed to reset WiFi statistic counts
[1694847071.392403][22404:22404] CHIP:IN: UDP::Init bind&listen port=0
[1694847071.392510][22404:22404] CHIP:IN: UDP::Init bound to port=33588
[1694847071.392530][22404:22404] CHIP:IN: BLEBase::Init - setting/overriding transport
[1694847071.392547][22404:22404] CHIP:IN: TransportMgr initialized
[1694847071.392577][22404:22404] CHIP:FP: Initializing FabricTable from persistent storage
[1694847071.392717][22404:22404] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847071.394219][22404:22404] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x531C5E1335241DE8, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1694847071.398034][22404:22404] CHIP:ZCL: Using ZAP configuration...
[1694847071.401600][22404:22404] CHIP:DL: Avahi client registered
[1694847071.401724][22404:22404] CHIP:CTL: System State Initialized...
[1694847071.401807][22404:22404] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847071.401851][22404:22404] CHIP:CTL: Setting attestation nonce to random value
[1694847071.401883][22404:22404] CHIP:CTL: Setting CSR nonce to random value
[1694847071.401942][22404:22404] CHIP:IN: UDP::Init bind&listen port=5550
[1694847071.402066][22404:22404] CHIP:IN: UDP::Init bound to port=5550
[1694847071.402086][22404:22404] CHIP:IN: TransportMgr initialized
[1694847071.402351][22404:22406] CHIP:DL: CHIP task running
[1694847071.402523][22404:22406] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1694847071.402813][22404:22406] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847071.402865][22404:22406] CHIP:CTL: Setting attestation nonce to random value
[1694847071.403014][22404:22406] CHIP:CTL: Setting CSR nonce to random value
[1694847071.403964][22404:22406] CHIP:CTL: Generating NOC
[1694847071.405023][22404:22406] CHIP:FP: Validating NOC chain
[1694847071.407227][22404:22406] CHIP:FP: NOC chain validation successful
[1694847071.407412][22404:22406] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1694847071.407447][22404:22406] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847071.407472][22404:22406] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1694847071.407495][22404:22406] CHIP:TS: Retaining current Last Known Good Time
[1694847071.419074][22404:22406] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1694847071.423960][22404:22406] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-25T18:22:45
[1694847071.429695][22404:22406] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 531C5E1335241DE8)
[1694847071.429764][22404:22406] CHIP:IN: UDP::Init bind&listen port=5550
[1694847071.429917][22404:22406] CHIP:IN: UDP::Init bound to port=5550
[1694847071.429951][22404:22406] CHIP:IN: TransportMgr initialized
[1694847071.455702][22404:22406] CHIP:TOO: Sending command to node 0x1
[1694847071.456144][22404:22406] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1694847071.456175][22404:22406] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1694847071.456210][22404:22406] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1694847071.456242][22404:22406] CHIP:DIS: Resolving 531C5E1335241DE8:0000000000000001 ...
[1694847071.458364][22404:22406] CHIP:DL: Avahi resolve found
[1694847071.458454][22404:22406] CHIP:DIS: Node ID resolved for 531C5E1335241DE8:0000000000000001
[1694847071.458487][22404:22406] CHIP:DIS:      Hostname: 1A214799925ACE94
[1694847071.458524][22404:22406] CHIP:DIS:      IP Address #1: fd11:35::e119:c9a1:75db:8d1e
[1694847071.458554][22404:22406] CHIP:DIS:      Port: 5540
[1694847071.458584][22404:22406] CHIP:DIS:      Mrp Interval idle: 2800 ms
[1694847071.458613][22404:22406] CHIP:DIS:      Mrp Interval active: 1000 ms
[1694847071.458642][22404:22406] CHIP:DIS:      TCP Supported: 0
[1694847071.459724][22404:22406] CHIP:DIS: Lookup clearing interface for non LL address
[1694847071.459848][22404:22406] CHIP:DIS: UDP:[fd11:35::e119:c9a1:75db:8d1e%veth10eedd1]:5540: new best score: 5
[1694847071.459882][22404:22406] CHIP:DIS: Checking node lookup status after 4 ms
[1694847071.459909][22404:22406] CHIP:DIS: Keeping DNSSD lookup active
[1694847071.656671][22404:22406] CHIP:DIS: Checking node lookup status after 200 ms
[1694847071.656799][22404:22406] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540 while in state 2
[1694847071.656858][22404:22406] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1694847071.657194][22404:22406] CHIP:IN: SecureSession[0xffff9000aef0]: Allocated Type:2 LSID:46213
[1694847071.657294][22404:22406] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1694847071.659247][22404:22406] CHIP:EM: <<< [E:35476i S:0 M:37330579] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1694847071.659383][22404:22406] CHIP:IN: (U) Sending msg 37330579 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847071.659710][22404:22406] CHIP:SC: Sent Sigma1 msg
[1694847071.659785][22404:22406] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1694847073.180895][22404:22406] CHIP:EM: >>> [E:35476i S:0 M:56493105 (Ack:37330579)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847073.180988][22404:22406] CHIP:EM: Found matching exchange: 35476i, Delegate: 0xffff9000dd98
[1694847073.181061][22404:22406] CHIP:EM: Rxd Ack; Removing MessageCounter:37330579 from Retrans Table on exchange 35476i
[1694847073.468015][22404:22406] CHIP:EM: >>> [E:35476i S:0 M:56493106 (Ack:37330579)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1694847073.468120][22404:22406] CHIP:EM: Found matching exchange: 35476i, Delegate: 0xffff9000dd98
[1694847073.468182][22404:22406] CHIP:EM: CHIP MessageCounter:37330579 not in RetransTable on exchange 35476i
[1694847073.468286][22404:22406] CHIP:SC: Received Sigma2 msg
[1694847073.468374][22404:22406] CHIP:SC: Peer assigned session session ID 51792
[1694847073.476904][22404:22406] CHIP:SC: Found MRP parameters in the message
[1694847073.477005][22404:22406] CHIP:SC: Sending Sigma3
[1694847073.478076][22404:22406] CHIP:EM: <<< [E:35476i S:0 M:37330580 (Ack:56493106)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1694847073.478368][22404:22406] CHIP:IN: (U) Sending msg 37330580 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847073.478731][22404:22406] CHIP:SC: Sent Sigma3 msg
[1694847073.721177][22404:22406] CHIP:EM: >>> [E:35476i S:0 M:56493107 (Ack:37330580)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847073.721268][22404:22406] CHIP:EM: Found matching exchange: 35476i, Delegate: 0xffff9000dd98
[1694847073.721342][22404:22406] CHIP:EM: Rxd Ack; Removing MessageCounter:37330580 from Retrans Table on exchange 35476i
[1694847073.999243][22404:22406] CHIP:EM: >>> [E:35476i S:0 M:56493108 (Ack:37330580)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1694847073.999348][22404:22406] CHIP:EM: Found matching exchange: 35476i, Delegate: 0xffff9000dd98
[1694847073.999409][22404:22406] CHIP:EM: CHIP MessageCounter:37330580 not in RetransTable on exchange 35476i
[1694847073.999514][22404:22406] CHIP:SC: Success status report received. Session was established
[1694847074.009033][22404:22406] CHIP:SC: SecureSession[0xffff9000aef0, LSID:46213]: State change 'kEstablishing' --> 'kActive'
[1694847074.009137][22404:22406] CHIP:IN: SecureSession[0xffff9000aef0]: Activated - Type:2 LSID:46213
[1694847074.009190][22404:22406] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:46213 PSID:51792!
[1694847074.009253][22404:22406] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1694847074.009389][22404:22406] CHIP:TOO: Sending ReadAttribute to:
[1694847074.009538][22404:22406] CHIP:TOO:      cluster 0x0000_0030, attribute: 0x0000_0000, endpoint 0
[1694847074.009666][22404:22406] CHIP:DMG: SendReadRequest ReadClient[0xffff900110a0]: Sending Read Request
[1694847074.010009][22404:22406] CHIP:EM: <<< [E:35477i S:46213 M:122011128] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0001:02 (IM:ReadRequest)
[1694847074.010108][22404:22406] CHIP:IN: (S) Sending msg 122011128 on secure session with LSID: 46213
[1694847074.010340][22404:22406] CHIP:DMG: MoveToState ReadClient[0xffff900110a0]: Moving to [AwaitingIn]
[1694847074.010423][22404:22406] CHIP:EM: <<< [E:35476i S:0 M:37330581 (Ack:56493108)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847074.010593][22404:22406] CHIP:IN: (U) Sending msg 37330581 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847074.010749][22404:22406] CHIP:EM: Flushed pending ack for MessageCounter:56493108 on exchange 35476i
[1694847074.211076][22404:22406] CHIP:EM: >>> [E:35477i S:46213 M:212825513 (Ack:122011128)] (S) Msg RX from 1:0000000000000001 [1DE8] --- Type 0001:05 (IM:ReportData)
[1694847074.211135][22404:22406] CHIP:EM: Found matching exchange: 35477i, Delegate: 0xffff900110b0
[1694847074.211176][22404:22406] CHIP:EM: Rxd Ack; Removing MessageCounter:122011128 from Retrans Table on exchange 35477i
[1694847074.211243][22404:22406] CHIP:DMG: ReportDataMessage =
[1694847074.211270][22404:22406] CHIP:DMG: {
[1694847074.211292][22404:22406] CHIP:DMG:      AttributeReportIBs =
[1694847074.211324][22404:22406] CHIP:DMG:      [
[1694847074.211349][22404:22406] CHIP:DMG:              AttributeReportIB =
[1694847074.211382][22404:22406] CHIP:DMG:              {
[1694847074.211408][22404:22406] CHIP:DMG:                      AttributeDataIB =
[1694847074.211444][22404:22406] CHIP:DMG:                      {
[1694847074.211475][22404:22406] CHIP:DMG:                              DataVersion = 0x44dee692,
[1694847074.211506][22404:22406] CHIP:DMG:                              AttributePathIB =
[1694847074.211539][22404:22406] CHIP:DMG:                              {
[1694847074.211572][22404:22406] CHIP:DMG:                                      Endpoint = 0x0,
[1694847074.211607][22404:22406] CHIP:DMG:                                      Cluster = 0x30,
[1694847074.211642][22404:22406] CHIP:DMG:                                      Attribute = 0x0000_0000,
[1694847074.211675][22404:22406] CHIP:DMG:                              }
[1694847074.211709][22404:22406] CHIP:DMG:
[1694847074.211743][22404:22406] CHIP:DMG:                              Data = 1,
[1694847074.211773][22404:22406] CHIP:DMG:                      },
[1694847074.211807][22404:22406] CHIP:DMG:
[1694847074.211832][22404:22406] CHIP:DMG:              },
[1694847074.211863][22404:22406] CHIP:DMG:
[1694847074.211887][22404:22406] CHIP:DMG:      ],
[1694847074.211918][22404:22406] CHIP:DMG:
[1694847074.211943][22404:22406] CHIP:DMG:      SuppressResponse = true,
[1694847074.211968][22404:22406] CHIP:DMG:      InteractionModelRevision = 1
[1694847074.211991][22404:22406] CHIP:DMG: }
[1694847074.212142][22404:22406] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0030 Attribute 0x0000_0000 DataVersion: 1155458706
[1694847074.212192][22404:22406] CHIP:TOO:   Breadcrumb: 1
[1694847074.212345][22404:22406] CHIP:EM: <<< [E:35477i S:46213 M:122011129 (Ack:212825513)] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847074.212388][22404:22406] CHIP:IN: (S) Sending msg 122011129 on secure session with LSID: 46213
[1694847074.212532][22404:22406] CHIP:EM: Flushed pending ack for MessageCounter:212825513 on exchange 35477i
[1694847074.212727][22404:22404] CHIP:CTL: Shutting down the commissioner
[1694847074.212760][22404:22404] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847074.212854][22404:22404] CHIP:CTL: Shutting down the controller
[1694847074.212909][22404:22404] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1694847074.212934][22404:22404] CHIP:IN: SecureSession[0xffff9000aef0]: MarkForEviction Type:2 LSID:46213
[1694847074.212958][22404:22404] CHIP:SC: SecureSession[0xffff9000aef0, LSID:46213]: State change 'kActive' --> 'kPendingEviction'
[1694847074.212981][22404:22404] CHIP:IN: SecureSession[0xffff9000aef0]: Released - Type:2 LSID:46213
[1694847074.213006][22404:22404] CHIP:FP: Forgetting fabric 0x1
[1694847074.213040][22404:22404] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847074.213207][22404:22404] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847074.213235][22404:22404] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847074.213281][22404:22404] CHIP:CTL: Shutting down the commissioner
[1694847074.213305][22404:22404] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847074.213379][22404:22404] CHIP:CTL: Shutting down the controller
[1694847074.213402][22404:22404] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1694847074.213572][22404:22404] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1694847074.213672][22404:22404] CHIP:FP: Shutting down FabricTable
[1694847074.213704][22404:22404] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847074.213849][22404:22404] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847074.213876][22404:22404] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847074.214202][22404:22404] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-nUAwjT)
[1694847074.215281][22404:22404] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847074.215387][22404:22404] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1694847074.215428][22404:22404] CHIP:DL: Inet Layer shutdown
[1694847074.215461][22404:22404] CHIP:DL: BLE shutdown
[1694847074.215494][22404:22404] CHIP:DL: System Layer shutdown
ubuntu@ubuntu:~/apps$ ./chip-tool networkcommissioning connect-network hex:18B1A8D8FC4C1870 1 0 --Breadcrumb 2
[1694847130.317732][22410:22410] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1694847130.323394][22410:22410] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1694847130.323642][22410:22410] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1694847130.323745][22410:22410] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1694847130.324080][22410:22410] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-7Jzw3y)
[1694847130.324650][22410:22410] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847130.324700][22410:22410] CHIP:DL: NVS set: chip-counters/reboot-count = 10 (0xA)
[1694847130.325610][22410:22410] CHIP:DL: Got Ethernet interface: eth0
[1694847130.326167][22410:22410] CHIP:DL: Found the primary Ethernet interface:eth0
[1694847130.326782][22410:22410] CHIP:DL: Got WiFi interface: wlan0
[1694847130.326844][22410:22410] CHIP:DL: Failed to reset WiFi statistic counts
[1694847130.326925][22410:22410] CHIP:IN: UDP::Init bind&listen port=0
[1694847130.327030][22410:22410] CHIP:IN: UDP::Init bound to port=37200
[1694847130.327050][22410:22410] CHIP:IN: BLEBase::Init - setting/overriding transport
[1694847130.327067][22410:22410] CHIP:IN: TransportMgr initialized
[1694847130.327097][22410:22410] CHIP:FP: Initializing FabricTable from persistent storage
[1694847130.327239][22410:22410] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847130.328726][22410:22410] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x531C5E1335241DE8, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1694847130.332398][22410:22410] CHIP:ZCL: Using ZAP configuration...
[1694847130.336173][22410:22410] CHIP:DL: Avahi client registered
[1694847130.336307][22410:22410] CHIP:CTL: System State Initialized...
[1694847130.336394][22410:22410] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847130.336441][22410:22410] CHIP:CTL: Setting attestation nonce to random value
[1694847130.336478][22410:22410] CHIP:CTL: Setting CSR nonce to random value
[1694847130.336539][22410:22410] CHIP:IN: UDP::Init bind&listen port=5550
[1694847130.336666][22410:22410] CHIP:IN: UDP::Init bound to port=5550
[1694847130.336689][22410:22410] CHIP:IN: TransportMgr initialized
[1694847130.336972][22410:22412] CHIP:DL: CHIP task running
[1694847130.337164][22410:22412] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1694847130.337553][22410:22412] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847130.337607][22410:22412] CHIP:CTL: Setting attestation nonce to random value
[1694847130.337771][22410:22412] CHIP:CTL: Setting CSR nonce to random value
[1694847130.338647][22410:22412] CHIP:CTL: Generating NOC
[1694847130.339570][22410:22412] CHIP:FP: Validating NOC chain
[1694847130.341297][22410:22412] CHIP:FP: NOC chain validation successful
[1694847130.341447][22410:22412] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1694847130.341476][22410:22412] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847130.341496][22410:22412] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1694847130.341515][22410:22412] CHIP:TS: Retaining current Last Known Good Time
[1694847130.354764][22410:22412] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1694847130.359839][22410:22412] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-25T18:22:45
[1694847130.364882][22410:22412] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 531C5E1335241DE8)
[1694847130.364933][22410:22412] CHIP:IN: UDP::Init bind&listen port=5550
[1694847130.365043][22410:22412] CHIP:IN: UDP::Init bound to port=5550
[1694847130.365063][22410:22412] CHIP:IN: TransportMgr initialized
[1694847130.393949][22410:22412] CHIP:TOO: Sending command to node 0x1
[1694847130.394461][22410:22412] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1694847130.394495][22410:22412] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1694847130.394534][22410:22412] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1694847130.394570][22410:22412] CHIP:DIS: Resolving 531C5E1335241DE8:0000000000000001 ...
[1694847130.396666][22410:22412] CHIP:DL: Avahi resolve found
[1694847130.396743][22410:22412] CHIP:DIS: Node ID resolved for 531C5E1335241DE8:0000000000000001
[1694847130.396770][22410:22412] CHIP:DIS:      Hostname: 1A214799925ACE94
[1694847130.396798][22410:22412] CHIP:DIS:      IP Address #1: fd11:35::e119:c9a1:75db:8d1e
[1694847130.396823][22410:22412] CHIP:DIS:      Port: 5540
[1694847130.396845][22410:22412] CHIP:DIS:      Mrp Interval idle: 2800 ms
[1694847130.396869][22410:22412] CHIP:DIS:      Mrp Interval active: 1000 ms
[1694847130.396892][22410:22412] CHIP:DIS:      TCP Supported: 0
[1694847130.397752][22410:22412] CHIP:DIS: Lookup clearing interface for non LL address
[1694847130.397857][22410:22412] CHIP:DIS: UDP:[fd11:35::e119:c9a1:75db:8d1e%veth10eedd1]:5540: new best score: 5
[1694847130.397883][22410:22412] CHIP:DIS: Checking node lookup status after 4 ms
[1694847130.397905][22410:22412] CHIP:DIS: Keeping DNSSD lookup active
[1694847130.594777][22410:22412] CHIP:DIS: Checking node lookup status after 201 ms
[1694847130.594914][22410:22412] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540 while in state 2
[1694847130.594973][22410:22412] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1694847130.595303][22410:22412] CHIP:IN: SecureSession[0xffff8000aef0]: Allocated Type:2 LSID:20908
[1694847130.595403][22410:22412] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1694847130.597301][22410:22412] CHIP:EM: <<< [E:33015i S:0 M:120577016] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1694847130.597445][22410:22412] CHIP:IN: (U) Sending msg 120577016 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847130.597780][22410:22412] CHIP:SC: Sent Sigma1 msg
[1694847130.597853][22410:22412] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1694847132.431034][22410:22412] CHIP:EM: >>> [E:33015i S:0 M:56493109 (Ack:120577016)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847132.431125][22410:22412] CHIP:EM: Found matching exchange: 33015i, Delegate: 0xffff8000dd98
[1694847132.431201][22410:22412] CHIP:EM: Rxd Ack; Removing MessageCounter:120577016 from Retrans Table on exchange 33015i
[1694847132.708012][22410:22412] CHIP:EM: >>> [E:33015i S:0 M:56493110 (Ack:120577016)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1694847132.708102][22410:22412] CHIP:EM: Found matching exchange: 33015i, Delegate: 0xffff8000dd98
[1694847132.708156][22410:22412] CHIP:EM: CHIP MessageCounter:120577016 not in RetransTable on exchange 33015i
[1694847132.708250][22410:22412] CHIP:SC: Received Sigma2 msg
[1694847132.708328][22410:22412] CHIP:SC: Peer assigned session session ID 51793
[1694847132.716786][22410:22412] CHIP:SC: Found MRP parameters in the message
[1694847132.716861][22410:22412] CHIP:SC: Sending Sigma3
[1694847132.717586][22410:22412] CHIP:EM: <<< [E:33015i S:0 M:120577017 (Ack:56493110)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1694847132.717791][22410:22412] CHIP:IN: (U) Sending msg 120577017 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847132.718038][22410:22412] CHIP:SC: Sent Sigma3 msg
[1694847133.065886][22410:22412] CHIP:EM: >>> [E:33015i S:0 M:56493111 (Ack:120577017)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847133.065977][22410:22412] CHIP:EM: Found matching exchange: 33015i, Delegate: 0xffff8000dd98
[1694847133.066051][22410:22412] CHIP:EM: Rxd Ack; Removing MessageCounter:120577017 from Retrans Table on exchange 33015i
[1694847133.258226][22410:22412] CHIP:EM: >>> [E:33015i S:0 M:56493112 (Ack:120577017)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1694847133.258309][22410:22412] CHIP:EM: Found matching exchange: 33015i, Delegate: 0xffff8000dd98
[1694847133.258360][22410:22412] CHIP:EM: CHIP MessageCounter:120577017 not in RetransTable on exchange 33015i
[1694847133.258452][22410:22412] CHIP:SC: Success status report received. Session was established
[1694847133.266469][22410:22412] CHIP:SC: SecureSession[0xffff8000aef0, LSID:20908]: State change 'kEstablishing' --> 'kActive'
[1694847133.266535][22410:22412] CHIP:IN: SecureSession[0xffff8000aef0]: Activated - Type:2 LSID:20908
[1694847133.266559][22410:22412] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:20908 PSID:51793!
[1694847133.266655][22410:22412] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1694847133.266755][22410:22412] CHIP:TOO: Sending cluster (0x00000031) command (0x00000006) on endpoint 0
[1694847133.266819][22410:22412] CHIP:DMG: ICR moving to [AddingComm]
[1694847133.266897][22410:22412] CHIP:DMG: ICR moving to [AddedComma]
[1694847133.267045][22410:22412] CHIP:EM: <<< [E:33016i S:20908 M:195585805] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0001:08 (IM:InvokeCommandRequest)
[1694847133.267097][22410:22412] CHIP:IN: (S) Sending msg 195585805 on secure session with LSID: 20908
[1694847133.267300][22410:22412] CHIP:DMG: ICR moving to [CommandSen]
[1694847133.267376][22410:22412] CHIP:EM: <<< [E:33015i S:0 M:120577018 (Ack:56493112)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847133.267541][22410:22412] CHIP:IN: (U) Sending msg 120577018 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847133.267649][22410:22412] CHIP:EM: Flushed pending ack for MessageCounter:56493112 on exchange 33015i
[1694847133.475202][22410:22412] CHIP:EM: >>> [E:33016i S:20908 M:227614345 (Ack:195585805)] (S) Msg RX from 1:0000000000000001 [1DE8] --- Type 0001:09 (IM:InvokeCommandResponse)
[1694847133.475285][22410:22412] CHIP:EM: Found matching exchange: 33016i, Delegate: 0xffff8000a178
[1694847133.475349][22410:22412] CHIP:EM: Rxd Ack; Removing MessageCounter:195585805 from Retrans Table on exchange 33016i
[1694847133.475411][22410:22412] CHIP:DMG: ICR moving to [ResponseRe]
[1694847133.475493][22410:22412] CHIP:DMG: InvokeResponseMessage =
[1694847133.475536][22410:22412] CHIP:DMG: {
[1694847133.475577][22410:22412] CHIP:DMG:      suppressResponse = false,
[1694847133.475620][22410:22412] CHIP:DMG:      InvokeResponseIBs =
[1694847133.475676][22410:22412] CHIP:DMG:      [
[1694847133.475719][22410:22412] CHIP:DMG:              InvokeResponseIB =
[1694847133.475779][22410:22412] CHIP:DMG:              {
[1694847133.475825][22410:22412] CHIP:DMG:                      CommandDataIB =
[1694847133.475885][22410:22412] CHIP:DMG:                      {
[1694847133.475936][22410:22412] CHIP:DMG:                              CommandPathIB =
[1694847133.476010][22410:22412] CHIP:DMG:                              {
[1694847133.476068][22410:22412] CHIP:DMG:                                      EndpointId = 0x0,
[1694847133.476129][22410:22412] CHIP:DMG:                                      ClusterId = 0x31,
[1694847133.476188][22410:22412] CHIP:DMG:                                      CommandId = 0x7,
[1694847133.476246][22410:22412] CHIP:DMG:                              },
[1694847133.476306][22410:22412] CHIP:DMG:
[1694847133.476357][22410:22412] CHIP:DMG:                              CommandFields =
[1694847133.476413][22410:22412] CHIP:DMG:                              {
[1694847133.476519][22410:22412] CHIP:DMG:                                      0x0 = 3,
[1694847133.476582][22410:22412] CHIP:DMG:                                      0x2 = 0,
[1694847133.476642][22410:22412] CHIP:DMG:                              },
[1694847133.476695][22410:22412] CHIP:DMG:                      },
[1694847133.476753][22410:22412] CHIP:DMG:
[1694847133.476799][22410:22412] CHIP:DMG:              },
[1694847133.476853][22410:22412] CHIP:DMG:
[1694847133.476895][22410:22412] CHIP:DMG:      ],
[1694847133.476950][22410:22412] CHIP:DMG:
[1694847133.476991][22410:22412] CHIP:DMG:      InteractionModelRevision = 1
[1694847133.477033][22410:22412] CHIP:DMG: },
[1694847133.477140][22410:22412] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007
[1694847133.477218][22410:22412] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0031 Command 0x0000_0007
[1694847133.477355][22410:22412] CHIP:TOO:   ConnectNetworkResponse: {
[1694847133.477433][22410:22412] CHIP:TOO:     networkingStatus: 3
[1694847133.477488][22410:22412] CHIP:TOO:     errorValue: 0
[1694847133.477534][22410:22412] CHIP:TOO:    }
[1694847133.477609][22410:22412] CHIP:DMG: ICR moving to [AwaitingDe]
[1694847133.477806][22410:22412] CHIP:EM: <<< [E:33016i S:20908 M:195585806 (Ack:227614345)] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847133.477885][22410:22412] CHIP:IN: (S) Sending msg 195585806 on secure session with LSID: 20908
[1694847133.478107][22410:22412] CHIP:EM: Flushed pending ack for MessageCounter:227614345 on exchange 33016i
[1694847133.478446][22410:22410] CHIP:CTL: Shutting down the commissioner
[1694847133.478514][22410:22410] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847133.478713][22410:22410] CHIP:CTL: Shutting down the controller
[1694847133.478769][22410:22410] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1694847133.478814][22410:22410] CHIP:IN: SecureSession[0xffff8000aef0]: MarkForEviction Type:2 LSID:20908
[1694847133.478860][22410:22410] CHIP:SC: SecureSession[0xffff8000aef0, LSID:20908]: State change 'kActive' --> 'kPendingEviction'
[1694847133.478906][22410:22410] CHIP:IN: SecureSession[0xffff8000aef0]: Released - Type:2 LSID:20908
[1694847133.478956][22410:22410] CHIP:FP: Forgetting fabric 0x1
[1694847133.479016][22410:22410] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847133.479304][22410:22410] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847133.479368][22410:22410] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847133.479448][22410:22410] CHIP:CTL: Shutting down the commissioner
[1694847133.479495][22410:22410] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847133.479647][22410:22410] CHIP:CTL: Shutting down the controller
[1694847133.479700][22410:22410] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1694847133.479976][22410:22410] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1694847133.480161][22410:22410] CHIP:FP: Shutting down FabricTable
[1694847133.480223][22410:22410] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847133.480444][22410:22410] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847133.480501][22410:22410] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847133.480900][22410:22410] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-gy1g4X)
[1694847133.482027][22410:22410] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847133.482147][22410:22410] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1694847133.482198][22410:22410] CHIP:DL: Inet Layer shutdown
[1694847133.482239][22410:22410] CHIP:DL: BLE shutdown
[1694847133.482282][22410:22410] CHIP:DL: System Layer shutdown
ubuntu@ubuntu:~/apps$ ./chip-tool generalcommissioning read breadcrumb 1 0
[1694847145.251508][22415:22415] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1694847145.256966][22415:22415] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1694847145.257206][22415:22415] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1694847145.257312][22415:22415] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1694847145.257640][22415:22415] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-1ShiWq)
[1694847145.258215][22415:22415] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847145.258266][22415:22415] CHIP:DL: NVS set: chip-counters/reboot-count = 11 (0xB)
[1694847145.259214][22415:22415] CHIP:DL: Got Ethernet interface: eth0
[1694847145.259779][22415:22415] CHIP:DL: Found the primary Ethernet interface:eth0
[1694847145.260481][22415:22415] CHIP:DL: Got WiFi interface: wlan0
[1694847145.260548][22415:22415] CHIP:DL: Failed to reset WiFi statistic counts
[1694847145.260631][22415:22415] CHIP:IN: UDP::Init bind&listen port=0
[1694847145.260737][22415:22415] CHIP:IN: UDP::Init bound to port=35122
[1694847145.260756][22415:22415] CHIP:IN: BLEBase::Init - setting/overriding transport
[1694847145.260773][22415:22415] CHIP:IN: TransportMgr initialized
[1694847145.260803][22415:22415] CHIP:FP: Initializing FabricTable from persistent storage
[1694847145.260943][22415:22415] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847145.262297][22415:22415] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x531C5E1335241DE8, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1694847145.264310][22415:22415] CHIP:ZCL: Using ZAP configuration...
[1694847145.267875][22415:22415] CHIP:DL: Avahi client registered
[1694847145.268000][22415:22415] CHIP:CTL: System State Initialized...
[1694847145.268082][22415:22415] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847145.268125][22415:22415] CHIP:CTL: Setting attestation nonce to random value
[1694847145.268155][22415:22415] CHIP:CTL: Setting CSR nonce to random value
[1694847145.268210][22415:22415] CHIP:IN: UDP::Init bind&listen port=5550
[1694847145.268329][22415:22415] CHIP:IN: UDP::Init bound to port=5550
[1694847145.268349][22415:22415] CHIP:IN: TransportMgr initialized
[1694847145.268618][22415:22417] CHIP:DL: CHIP task running
[1694847145.268800][22415:22417] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1694847145.269068][22415:22417] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847145.269115][22415:22417] CHIP:CTL: Setting attestation nonce to random value
[1694847145.269264][22415:22417] CHIP:CTL: Setting CSR nonce to random value
[1694847145.270053][22415:22417] CHIP:CTL: Generating NOC
[1694847145.270890][22415:22417] CHIP:FP: Validating NOC chain
[1694847145.272570][22415:22417] CHIP:FP: NOC chain validation successful
[1694847145.272711][22415:22417] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1694847145.272739][22415:22417] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847145.272757][22415:22417] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1694847145.272773][22415:22417] CHIP:TS: Retaining current Last Known Good Time
[1694847145.279310][22415:22417] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1694847145.281191][22415:22417] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-25T18:22:45
[1694847145.283065][22415:22417] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 531C5E1335241DE8)
[1694847145.283126][22415:22417] CHIP:IN: UDP::Init bind&listen port=5550
[1694847145.283262][22415:22417] CHIP:IN: UDP::Init bound to port=5550
[1694847145.283289][22415:22417] CHIP:IN: TransportMgr initialized
[1694847145.296833][22415:22417] CHIP:TOO: Sending command to node 0x1
[1694847145.297247][22415:22417] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1694847145.297276][22415:22417] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1694847145.297308][22415:22417] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1694847145.297338][22415:22417] CHIP:DIS: Resolving 531C5E1335241DE8:0000000000000001 ...
[1694847145.298960][22415:22417] CHIP:DL: Avahi resolve found
[1694847145.299030][22415:22417] CHIP:DIS: Node ID resolved for 531C5E1335241DE8:0000000000000001
[1694847145.299050][22415:22417] CHIP:DIS:      Hostname: 1A214799925ACE94
[1694847145.299073][22415:22417] CHIP:DIS:      IP Address #1: fd11:35::e119:c9a1:75db:8d1e
[1694847145.299093][22415:22417] CHIP:DIS:      Port: 5540
[1694847145.299111][22415:22417] CHIP:DIS:      Mrp Interval idle: 2800 ms
[1694847145.299129][22415:22417] CHIP:DIS:      Mrp Interval active: 1000 ms
[1694847145.299147][22415:22417] CHIP:DIS:      TCP Supported: 0
[1694847145.299864][22415:22417] CHIP:DIS: Lookup clearing interface for non LL address
[1694847145.299952][22415:22417] CHIP:DIS: UDP:[fd11:35::e119:c9a1:75db:8d1e%veth10eedd1]:5540: new best score: 5
[1694847145.299975][22415:22417] CHIP:DIS: Checking node lookup status after 3 ms
[1694847145.299992][22415:22417] CHIP:DIS: Keeping DNSSD lookup active
[1694847145.497250][22415:22417] CHIP:DIS: Checking node lookup status after 200 ms
[1694847145.497379][22415:22417] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540 while in state 2
[1694847145.497439][22415:22417] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1694847145.497768][22415:22417] CHIP:IN: SecureSession[0xffff8000aef0]: Allocated Type:2 LSID:438
[1694847145.497865][22415:22417] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1694847145.499781][22415:22417] CHIP:EM: <<< [E:20852i S:0 M:138859938] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1694847145.499918][22415:22417] CHIP:IN: (U) Sending msg 138859938 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847145.500242][22415:22417] CHIP:SC: Sent Sigma1 msg
[1694847145.500318][22415:22417] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1694847145.693705][22415:22417] CHIP:EM: >>> [E:20852i S:0 M:56493113 (Ack:138859938)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847145.693799][22415:22417] CHIP:EM: Found matching exchange: 20852i, Delegate: 0xffff8000dd98
[1694847145.693873][22415:22417] CHIP:EM: Rxd Ack; Removing MessageCounter:138859938 from Retrans Table on exchange 20852i
[1694847145.981162][22415:22417] CHIP:EM: >>> [E:20852i S:0 M:56493114 (Ack:138859938)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1694847145.981255][22415:22417] CHIP:EM: Found matching exchange: 20852i, Delegate: 0xffff8000dd98
[1694847145.981309][22415:22417] CHIP:EM: CHIP MessageCounter:138859938 not in RetransTable on exchange 20852i
[1694847145.981401][22415:22417] CHIP:SC: Received Sigma2 msg
[1694847145.981476][22415:22417] CHIP:SC: Peer assigned session session ID 51794
[1694847145.990105][22415:22417] CHIP:SC: Found MRP parameters in the message
[1694847145.990218][22415:22417] CHIP:SC: Sending Sigma3
[1694847145.991386][22415:22417] CHIP:EM: <<< [E:20852i S:0 M:138859939 (Ack:56493114)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1694847145.991674][22415:22417] CHIP:IN: (U) Sending msg 138859939 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847145.991899][22415:22417] CHIP:SC: Sent Sigma3 msg
[1694847146.244033][22415:22417] CHIP:EM: >>> [E:20852i S:0 M:56493115 (Ack:138859939)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847146.244138][22415:22417] CHIP:EM: Found matching exchange: 20852i, Delegate: 0xffff8000dd98
[1694847146.244223][22415:22417] CHIP:EM: Rxd Ack; Removing MessageCounter:138859939 from Retrans Table on exchange 20852i
[1694847146.432958][22415:22417] CHIP:EM: >>> [E:20852i S:0 M:56493116 (Ack:138859939)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1694847146.433052][22415:22417] CHIP:EM: Found matching exchange: 20852i, Delegate: 0xffff8000dd98
[1694847146.433112][22415:22417] CHIP:EM: CHIP MessageCounter:138859939 not in RetransTable on exchange 20852i
[1694847146.433214][22415:22417] CHIP:SC: Success status report received. Session was established
[1694847146.439141][22415:22417] CHIP:SC: SecureSession[0xffff8000aef0, LSID:438]: State change 'kEstablishing' --> 'kActive'
[1694847146.439226][22415:22417] CHIP:IN: SecureSession[0xffff8000aef0]: Activated - Type:2 LSID:438
[1694847146.439265][22415:22417] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:438 PSID:51794!
[1694847146.439313][22415:22417] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1694847146.439421][22415:22417] CHIP:TOO: Sending ReadAttribute to:
[1694847146.439539][22415:22417] CHIP:TOO:      cluster 0x0000_0030, attribute: 0x0000_0000, endpoint 0
[1694847146.439614][22415:22417] CHIP:DMG: SendReadRequest ReadClient[0xffff800110a0]: Sending Read Request
[1694847146.439852][22415:22417] CHIP:EM: <<< [E:20853i S:438 M:98738084] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0001:02 (IM:ReadRequest)
[1694847146.439929][22415:22417] CHIP:IN: (S) Sending msg 98738084 on secure session with LSID: 438
[1694847146.440203][22415:22417] CHIP:DMG: MoveToState ReadClient[0xffff800110a0]: Moving to [AwaitingIn]
[1694847146.440321][22415:22417] CHIP:EM: <<< [E:20852i S:0 M:138859940 (Ack:56493116)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847146.440547][22415:22417] CHIP:IN: (U) Sending msg 138859940 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847146.440707][22415:22417] CHIP:EM: Flushed pending ack for MessageCounter:56493116 on exchange 20852i
[1694847146.650241][22415:22417] CHIP:EM: >>> [E:20853i S:438 M:19653449 (Ack:98738084)] (S) Msg RX from 1:0000000000000001 [1DE8] --- Type 0001:05 (IM:ReportData)
[1694847146.650334][22415:22417] CHIP:EM: Found matching exchange: 20853i, Delegate: 0xffff800110b0
[1694847146.650408][22415:22417] CHIP:EM: Rxd Ack; Removing MessageCounter:98738084 from Retrans Table on exchange 20853i
[1694847146.650522][22415:22417] CHIP:DMG: ReportDataMessage =
[1694847146.650577][22415:22417] CHIP:DMG: {
[1694847146.650621][22415:22417] CHIP:DMG:      AttributeReportIBs =
[1694847146.650725][22415:22417] CHIP:DMG:      [
[1694847146.650780][22415:22417] CHIP:DMG:              AttributeReportIB =
[1694847146.650845][22415:22417] CHIP:DMG:              {
[1694847146.650898][22415:22417] CHIP:DMG:                      AttributeDataIB =
[1694847146.650964][22415:22417] CHIP:DMG:                      {
[1694847146.651027][22415:22417] CHIP:DMG:                              DataVersion = 0x44dee692,
[1694847146.651089][22415:22417] CHIP:DMG:                              AttributePathIB =
[1694847146.651153][22415:22417] CHIP:DMG:                              {
[1694847146.651220][22415:22417] CHIP:DMG:                                      Endpoint = 0x0,
[1694847146.651289][22415:22417] CHIP:DMG:                                      Cluster = 0x30,
[1694847146.651359][22415:22417] CHIP:DMG:                                      Attribute = 0x0000_0000,
[1694847146.651425][22415:22417] CHIP:DMG:                              }
[1694847146.651492][22415:22417] CHIP:DMG:
[1694847146.651560][22415:22417] CHIP:DMG:                              Data = 1,
[1694847146.651620][22415:22417] CHIP:DMG:                      },
[1694847146.651686][22415:22417] CHIP:DMG:
[1694847146.651738][22415:22417] CHIP:DMG:              },
[1694847146.651800][22415:22417] CHIP:DMG:
[1694847146.651848][22415:22417] CHIP:DMG:      ],
[1694847146.651909][22415:22417] CHIP:DMG:
[1694847146.651958][22415:22417] CHIP:DMG:      SuppressResponse = true,
[1694847146.652009][22415:22417] CHIP:DMG:      InteractionModelRevision = 1
[1694847146.652056][22415:22417] CHIP:DMG: }
[1694847146.652322][22415:22417] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_0030 Attribute 0x0000_0000 DataVersion: 1155458706
[1694847146.652411][22415:22417] CHIP:TOO:   Breadcrumb: 1
[1694847146.652670][22415:22417] CHIP:EM: <<< [E:20853i S:438 M:98738085 (Ack:19653449)] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847146.652749][22415:22417] CHIP:IN: (S) Sending msg 98738085 on secure session with LSID: 438
[1694847146.652971][22415:22417] CHIP:EM: Flushed pending ack for MessageCounter:19653449 on exchange 20853i
[1694847146.653350][22415:22415] CHIP:CTL: Shutting down the commissioner
[1694847146.653418][22415:22415] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847146.653577][22415:22415] CHIP:CTL: Shutting down the controller
[1694847146.653670][22415:22415] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1694847146.653717][22415:22415] CHIP:IN: SecureSession[0xffff8000aef0]: MarkForEviction Type:2 LSID:438
[1694847146.653762][22415:22415] CHIP:SC: SecureSession[0xffff8000aef0, LSID:438]: State change 'kActive' --> 'kPendingEviction'
[1694847146.653806][22415:22415] CHIP:IN: SecureSession[0xffff8000aef0]: Released - Type:2 LSID:438
[1694847146.653852][22415:22415] CHIP:FP: Forgetting fabric 0x1
[1694847146.653962][22415:22415] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847146.654250][22415:22415] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847146.654316][22415:22415] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847146.654397][22415:22415] CHIP:CTL: Shutting down the commissioner
[1694847146.654441][22415:22415] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847146.654598][22415:22415] CHIP:CTL: Shutting down the controller
[1694847146.654649][22415:22415] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1694847146.654973][22415:22415] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1694847146.655163][22415:22415] CHIP:FP: Shutting down FabricTable
[1694847146.655213][22415:22415] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847146.655387][22415:22415] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847146.655423][22415:22415] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847146.655720][22415:22415] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-p8NQVY)
[1694847146.656575][22415:22415] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847146.656660][22415:22415] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1694847146.656693][22415:22415] CHIP:DL: Inet Layer shutdown
[1694847146.656720][22415:22415] CHIP:DL: BLE shutdown
[1694847146.656748][22415:22415] CHIP:DL: System Layer shutdown
ubuntu@ubuntu:~/apps$ ./chip-tool generalcommissioning arm-fail-safe 0 0 1 0
[1694847153.258459][22418:22418] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1694847153.263872][22418:22418] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1694847153.264120][22418:22418] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1694847153.264224][22418:22418] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1694847153.264554][22418:22418] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-jo5H8h)
[1694847153.265135][22418:22418] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847153.265187][22418:22418] CHIP:DL: NVS set: chip-counters/reboot-count = 12 (0xC)
[1694847153.266117][22418:22418] CHIP:DL: Got Ethernet interface: eth0
[1694847153.266700][22418:22418] CHIP:DL: Found the primary Ethernet interface:eth0
[1694847153.267418][22418:22418] CHIP:DL: Got WiFi interface: wlan0
[1694847153.267484][22418:22418] CHIP:DL: Failed to reset WiFi statistic counts
[1694847153.267568][22418:22418] CHIP:IN: UDP::Init bind&listen port=0
[1694847153.267671][22418:22418] CHIP:IN: UDP::Init bound to port=33784
[1694847153.267691][22418:22418] CHIP:IN: BLEBase::Init - setting/overriding transport
[1694847153.267709][22418:22418] CHIP:IN: TransportMgr initialized
[1694847153.267739][22418:22418] CHIP:FP: Initializing FabricTable from persistent storage
[1694847153.267881][22418:22418] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847153.269243][22418:22418] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x531C5E1335241DE8, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1694847153.271219][22418:22418] CHIP:ZCL: Using ZAP configuration...
[1694847153.274763][22418:22418] CHIP:DL: Avahi client registered
[1694847153.274890][22418:22418] CHIP:CTL: System State Initialized...
[1694847153.274973][22418:22418] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847153.275016][22418:22418] CHIP:CTL: Setting attestation nonce to random value
[1694847153.275049][22418:22418] CHIP:CTL: Setting CSR nonce to random value
[1694847153.275105][22418:22418] CHIP:IN: UDP::Init bind&listen port=5550
[1694847153.275227][22418:22418] CHIP:IN: UDP::Init bound to port=5550
[1694847153.275247][22418:22418] CHIP:IN: TransportMgr initialized
[1694847153.275509][22418:22420] CHIP:DL: CHIP task running
[1694847153.275689][22418:22420] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1694847153.275968][22418:22420] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847153.276016][22418:22420] CHIP:CTL: Setting attestation nonce to random value
[1694847153.276181][22418:22420] CHIP:CTL: Setting CSR nonce to random value
[1694847153.276987][22418:22420] CHIP:CTL: Generating NOC
[1694847153.277810][22418:22420] CHIP:FP: Validating NOC chain
[1694847153.279399][22418:22420] CHIP:FP: NOC chain validation successful
[1694847153.279538][22418:22420] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1694847153.279579][22418:22420] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847153.279598][22418:22420] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1694847153.279615][22418:22420] CHIP:TS: Retaining current Last Known Good Time
[1694847153.286164][22418:22420] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1694847153.288472][22418:22420] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-25T18:22:45
[1694847153.290838][22418:22420] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 531C5E1335241DE8)
[1694847153.290909][22418:22420] CHIP:IN: UDP::Init bind&listen port=5550
[1694847153.291058][22418:22420] CHIP:IN: UDP::Init bound to port=5550
[1694847153.291090][22418:22420] CHIP:IN: TransportMgr initialized
[1694847153.304926][22418:22420] CHIP:TOO: Sending command to node 0x1
[1694847153.305373][22418:22420] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1694847153.305401][22418:22420] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1694847153.305434][22418:22420] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1694847153.305464][22418:22420] CHIP:DIS: Resolving 531C5E1335241DE8:0000000000000001 ...
[1694847153.307120][22418:22420] CHIP:DL: Avahi resolve found
[1694847153.307188][22418:22420] CHIP:DIS: Node ID resolved for 531C5E1335241DE8:0000000000000001
[1694847153.307208][22418:22420] CHIP:DIS:      Hostname: 1A214799925ACE94
[1694847153.307231][22418:22420] CHIP:DIS:      IP Address #1: fd11:35::e119:c9a1:75db:8d1e
[1694847153.307250][22418:22420] CHIP:DIS:      Port: 5540
[1694847153.307268][22418:22420] CHIP:DIS:      Mrp Interval idle: 2800 ms
[1694847153.307286][22418:22420] CHIP:DIS:      Mrp Interval active: 1000 ms
[1694847153.307304][22418:22420] CHIP:DIS:      TCP Supported: 0
[1694847153.308049][22418:22420] CHIP:DIS: Lookup clearing interface for non LL address
[1694847153.308139][22418:22420] CHIP:DIS: UDP:[fd11:35::e119:c9a1:75db:8d1e%veth10eedd1]:5540: new best score: 5
[1694847153.308161][22418:22420] CHIP:DIS: Checking node lookup status after 3 ms
[1694847153.308178][22418:22420] CHIP:DIS: Keeping DNSSD lookup active
[1694847153.505501][22418:22420] CHIP:DIS: Checking node lookup status after 200 ms
[1694847153.505634][22418:22420] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540 while in state 2
[1694847153.505692][22418:22420] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1694847153.506014][22418:22420] CHIP:IN: SecureSession[0xffff7000aef0]: Allocated Type:2 LSID:43446
[1694847153.506148][22418:22420] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1694847153.508128][22418:22420] CHIP:EM: <<< [E:42829i S:0 M:233752633] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1694847153.508265][22418:22420] CHIP:IN: (U) Sending msg 233752633 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847153.508624][22418:22420] CHIP:SC: Sent Sigma1 msg
[1694847153.508703][22418:22420] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1694847154.872200][22418:22420] CHIP:EM: >>> [E:42829i S:0 M:56493117 (Ack:233752633)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847154.872291][22418:22420] CHIP:EM: Found matching exchange: 42829i, Delegate: 0xffff7000dd98
[1694847154.872365][22418:22420] CHIP:EM: Rxd Ack; Removing MessageCounter:233752633 from Retrans Table on exchange 42829i
[1694847155.150228][22418:22420] CHIP:EM: >>> [E:42829i S:0 M:56493118 (Ack:233752633)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1694847155.150318][22418:22420] CHIP:EM: Found matching exchange: 42829i, Delegate: 0xffff7000dd98
[1694847155.150373][22418:22420] CHIP:EM: CHIP MessageCounter:233752633 not in RetransTable on exchange 42829i
[1694847155.150464][22418:22420] CHIP:SC: Received Sigma2 msg
[1694847155.150539][22418:22420] CHIP:SC: Peer assigned session session ID 51795
[1694847155.159192][22418:22420] CHIP:SC: Found MRP parameters in the message
[1694847155.159297][22418:22420] CHIP:SC: Sending Sigma3
[1694847155.160374][22418:22420] CHIP:EM: <<< [E:42829i S:0 M:233752634 (Ack:56493118)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1694847155.160667][22418:22420] CHIP:IN: (U) Sending msg 233752634 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847155.160972][22418:22420] CHIP:SC: Sent Sigma3 msg
[1694847155.503705][22418:22420] CHIP:EM: >>> [E:42829i S:0 M:56493119 (Ack:233752634)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847155.503796][22418:22420] CHIP:EM: Found matching exchange: 42829i, Delegate: 0xffff7000dd98
[1694847155.503870][22418:22420] CHIP:EM: Rxd Ack; Removing MessageCounter:233752634 from Retrans Table on exchange 42829i
[1694847155.693817][22418:22420] CHIP:EM: >>> [E:42829i S:0 M:56493120 (Ack:233752634)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1694847155.693878][22418:22420] CHIP:EM: Found matching exchange: 42829i, Delegate: 0xffff7000dd98
[1694847155.693909][22418:22420] CHIP:EM: CHIP MessageCounter:233752634 not in RetransTable on exchange 42829i
[1694847155.693968][22418:22420] CHIP:SC: Success status report received. Session was established
[1694847155.699447][22418:22420] CHIP:SC: SecureSession[0xffff7000aef0, LSID:43446]: State change 'kEstablishing' --> 'kActive'
[1694847155.699518][22418:22420] CHIP:IN: SecureSession[0xffff7000aef0]: Activated - Type:2 LSID:43446
[1694847155.699546][22418:22420] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:43446 PSID:51795!
[1694847155.699584][22418:22420] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1694847155.699664][22418:22420] CHIP:TOO: Sending cluster (0x00000030) command (0x00000000) on endpoint 0
[1694847155.699734][22418:22420] CHIP:DMG: ICR moving to [AddingComm]
[1694847155.699821][22418:22420] CHIP:DMG: ICR moving to [AddedComma]
[1694847155.699989][22418:22420] CHIP:EM: <<< [E:42830i S:43446 M:264534210] (S) Msg TX to 1:0000000000000001 [1DE8] --- Type 0001:08 (IM:InvokeCommandRequest)
[1694847155.700047][22418:22420] CHIP:IN: (S) Sending msg 264534210 on secure session with LSID: 43446
[1694847155.700436][22418:22420] CHIP:DMG: ICR moving to [CommandSen]
[1694847155.700539][22418:22420] CHIP:EM: <<< [E:42829i S:0 M:233752635 (Ack:56493120)] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1694847155.700727][22418:22420] CHIP:IN: (U) Sending msg 233752635 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e%wpan0]:5540'
[1694847155.701038][22418:22420] CHIP:EM: Flushed pending ack for MessageCounter:56493120 on exchange 42829i
[1694847156.971689][22418:22420] CHIP:EM: Retransmitting MessageCounter:264534210 on exchange 42830i Send Cnt 1
[1694847156.971824][22418:22420] CHIP:IN: (S) Sending msg 264534210 on secure session with LSID: 43446
[1694847158.293495][22418:22420] CHIP:EM: Retransmitting MessageCounter:264534210 on exchange 42830i Send Cnt 2
[1694847158.293636][22418:22420] CHIP:IN: (S) Sending msg 264534210 on secure session with LSID: 43446
[1694847160.136883][22418:22420] CHIP:EM: Retransmitting MessageCounter:264534210 on exchange 42830i Send Cnt 3
[1694847160.137081][22418:22420] CHIP:IN: (S) Sending msg 264534210 on secure session with LSID: 43446
[1694847168.124515][22418:22420] CHIP:EM: Retransmitting MessageCounter:264534210 on exchange 42830i Send Cnt 4
[1694847168.124640][22418:22420] CHIP:IN: (S) Sending msg 264534210 on secure session with LSID: 43446
[1694847173.276117][22418:22418] CHIP:CTL: Shutting down the commissioner
[1694847173.276213][22418:22418] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847173.276400][22418:22418] CHIP:CTL: Shutting down the controller
[1694847173.276465][22418:22418] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1694847173.276516][22418:22418] CHIP:IN: SecureSession[0xffff7000aef0]: MarkForEviction Type:2 LSID:43446
[1694847173.276571][22418:22418] CHIP:SC: SecureSession[0xffff7000aef0, LSID:43446]: State change 'kActive' --> 'kPendingEviction'
[1694847173.276661][22418:22418] CHIP:DMG: Time out! failed to receive invoke command response from Exchange: 42830i
[1694847173.276733][22418:22418] CHIP:TOO: Error: src/app/CommandSender.cpp:263: CHIP Error 0x00000032: Timeout
[1694847173.276783][22418:22418] CHIP:DMG: ICR moving to [AwaitingDe]
[1694847173.276908][22418:22418] CHIP:IN: SecureSession[0xffff7000aef0]: Released - Type:2 LSID:43446
[1694847173.276973][22418:22418] CHIP:FP: Forgetting fabric 0x1
[1694847173.277040][22418:22418] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847173.277356][22418:22418] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847173.277415][22418:22418] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847173.277502][22418:22418] CHIP:CTL: Shutting down the commissioner
[1694847173.277555][22418:22418] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847173.277703][22418:22418] CHIP:CTL: Shutting down the controller
[1694847173.277756][22418:22418] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1694847173.278053][22418:22418] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1694847173.278241][22418:22418] CHIP:FP: Shutting down FabricTable
[1694847173.278311][22418:22418] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847173.278555][22418:22418] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847173.278616][22418:22418] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847173.279163][22418:22418] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-TQHNIG)
[1694847173.280497][22418:22418] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847173.280633][22418:22418] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1694847173.280692][22418:22418] CHIP:DL: Inet Layer shutdown
[1694847173.280741][22418:22418] CHIP:DL: BLE shutdown
[1694847173.280791][22418:22418] CHIP:DL: System Layer shutdown
[1694847173.281468][22418:22418] CHIP:TOO: Run command failure: ../../examples/chip-tool/commands/common/CHIPCommand.cpp:549: CHIP Error 0x00000032: Timeout
ubuntu@ubuntu:~/apps$ ./chip-tool generalcommissioning arm-fail-safe 0 0 1 0
[1694847179.161449][22423:22423] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1694847179.166912][22423:22423] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1694847179.167162][22423:22423] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1694847179.167270][22423:22423] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1694847179.167605][22423:22423] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-e1fesd)
[1694847179.168184][22423:22423] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847179.168235][22423:22423] CHIP:DL: NVS set: chip-counters/reboot-count = 13 (0xD)
[1694847179.169143][22423:22423] CHIP:DL: Got Ethernet interface: eth0
[1694847179.169704][22423:22423] CHIP:DL: Found the primary Ethernet interface:eth0
[1694847179.170380][22423:22423] CHIP:DL: Got WiFi interface: wlan0
[1694847179.170447][22423:22423] CHIP:DL: Failed to reset WiFi statistic counts
[1694847179.170531][22423:22423] CHIP:IN: UDP::Init bind&listen port=0
[1694847179.170636][22423:22423] CHIP:IN: UDP::Init bound to port=44723
[1694847179.170656][22423:22423] CHIP:IN: BLEBase::Init - setting/overriding transport
[1694847179.170695][22423:22423] CHIP:IN: TransportMgr initialized
[1694847179.170728][22423:22423] CHIP:FP: Initializing FabricTable from persistent storage
[1694847179.170872][22423:22423] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847179.172250][22423:22423] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x531C5E1335241DE8, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1694847179.174246][22423:22423] CHIP:ZCL: Using ZAP configuration...
[1694847179.177851][22423:22423] CHIP:DL: Avahi client registered
[1694847179.177976][22423:22423] CHIP:CTL: System State Initialized...
[1694847179.178058][22423:22423] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847179.178102][22423:22423] CHIP:CTL: Setting attestation nonce to random value
[1694847179.178133][22423:22423] CHIP:CTL: Setting CSR nonce to random value
[1694847179.178188][22423:22423] CHIP:IN: UDP::Init bind&listen port=5550
[1694847179.178373][22423:22423] CHIP:IN: UDP::Init bound to port=5550
[1694847179.178396][22423:22423] CHIP:IN: TransportMgr initialized
[1694847179.178640][22423:22425] CHIP:DL: CHIP task running
[1694847179.178860][22423:22425] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1694847179.179141][22423:22425] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847179.179189][22423:22425] CHIP:CTL: Setting attestation nonce to random value
[1694847179.179351][22423:22425] CHIP:CTL: Setting CSR nonce to random value
[1694847179.180166][22423:22425] CHIP:CTL: Generating NOC
[1694847179.180996][22423:22425] CHIP:FP: Validating NOC chain
[1694847179.182571][22423:22425] CHIP:FP: NOC chain validation successful
[1694847179.182737][22423:22425] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1694847179.182765][22423:22425] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847179.182783][22423:22425] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1694847179.182800][22423:22425] CHIP:TS: Retaining current Last Known Good Time
[1694847179.189237][22423:22425] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1694847179.192496][22423:22425] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-25T18:22:45
[1694847179.194648][22423:22425] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 531C5E1335241DE8)
[1694847179.194745][22423:22425] CHIP:IN: UDP::Init bind&listen port=5550
[1694847179.194873][22423:22425] CHIP:IN: UDP::Init bound to port=5550
[1694847179.194898][22423:22425] CHIP:IN: TransportMgr initialized
[1694847179.208809][22423:22425] CHIP:TOO: Sending command to node 0x1
[1694847179.209249][22423:22425] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1694847179.209279][22423:22425] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1694847179.209313][22423:22425] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1694847179.209343][22423:22425] CHIP:DIS: Resolving 531C5E1335241DE8:0000000000000001 ...
[1694847179.210986][22423:22425] CHIP:DL: Avahi resolve found
[1694847179.211055][22423:22425] CHIP:DIS: Node ID resolved for 531C5E1335241DE8:0000000000000001
[1694847179.211077][22423:22425] CHIP:DIS:      Hostname: 1A214799925ACE94
[1694847179.211100][22423:22425] CHIP:DIS:      IP Address #1: fd11:35::e119:c9a1:75db:8d1e
[1694847179.211119][22423:22425] CHIP:DIS:      Port: 5540
[1694847179.211137][22423:22425] CHIP:DIS:      Mrp Interval idle: 2800 ms
[1694847179.211155][22423:22425] CHIP:DIS:      Mrp Interval active: 1000 ms
[1694847179.211173][22423:22425] CHIP:DIS:      TCP Supported: 0
[1694847179.211928][22423:22425] CHIP:DIS: Lookup clearing interface for non LL address
[1694847179.212024][22423:22425] CHIP:DIS: UDP:[fd11:35::e119:c9a1:75db:8d1e%veth10eedd1]:5540: new best score: 5
[1694847179.212047][22423:22425] CHIP:DIS: Checking node lookup status after 3 ms
[1694847179.212065][22423:22425] CHIP:DIS: Keeping DNSSD lookup active
[1694847179.409475][22423:22425] CHIP:DIS: Checking node lookup status after 200 ms
[1694847179.409607][22423:22425] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540 while in state 2
[1694847179.409665][22423:22425] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1694847179.410001][22423:22425] CHIP:IN: SecureSession[0xffff9400aef0]: Allocated Type:2 LSID:61642
[1694847179.410138][22423:22425] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1694847179.412090][22423:22425] CHIP:EM: <<< [E:12531i S:0 M:64344774] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1694847179.412229][22423:22425] CHIP:IN: (U) Sending msg 64344774 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847179.412598][22423:22425] CHIP:SC: Sent Sigma1 msg
[1694847179.412674][22423:22425] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1694847182.787314][22423:22425] CHIP:EM: Retransmitting MessageCounter:64344774 on exchange 12531i Send Cnt 1
[1694847182.787472][22423:22425] CHIP:IN: (U) Sending msg 64344774 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847186.508578][22423:22425] CHIP:EM: Retransmitting MessageCounter:64344774 on exchange 12531i Send Cnt 2
[1694847186.508724][22423:22425] CHIP:IN: (U) Sending msg 64344774 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847192.045610][22423:22425] CHIP:EM: Retransmitting MessageCounter:64344774 on exchange 12531i Send Cnt 3
[1694847192.045828][22423:22425] CHIP:IN: (U) Sending msg 64344774 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847199.179262][22423:22423] CHIP:CTL: Shutting down the commissioner
[1694847199.179356][22423:22423] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847199.179543][22423:22423] CHIP:CTL: Shutting down the controller
[1694847199.179734][22423:22423] CHIP:IN: SecureSession[0xffff9400aef0]: Released - Type:2 LSID:61642
[1694847199.179847][22423:22423] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1694847199.179906][22423:22423] CHIP:FP: Forgetting fabric 0x1
[1694847199.179975][22423:22423] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847199.180279][22423:22423] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847199.180339][22423:22423] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847199.180418][22423:22423] CHIP:CTL: Shutting down the commissioner
[1694847199.180471][22423:22423] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847199.180621][22423:22423] CHIP:CTL: Shutting down the controller
[1694847199.180676][22423:22423] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1694847199.180974][22423:22423] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1694847199.181160][22423:22423] CHIP:FP: Shutting down FabricTable
[1694847199.181229][22423:22423] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847199.181441][22423:22423] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847199.181500][22423:22423] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847199.181965][22423:22423] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-3UdspP)
[1694847199.183351][22423:22423] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847199.183489][22423:22423] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1694847199.183548][22423:22423] CHIP:DL: Inet Layer shutdown
[1694847199.183596][22423:22423] CHIP:DL: BLE shutdown
[1694847199.183646][22423:22423] CHIP:DL: System Layer shutdown
[1694847199.184350][22423:22423] CHIP:TOO: Run command failure: ../../examples/chip-tool/commands/common/CHIPCommand.cpp:549: CHIP Error 0x00000032: Timeout
ubuntu@ubuntu:~/apps$ ./chip-tool generalcommissioning arm-fail-safe 0 0 1 0
[1694847206.382977][22427:22427] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1694847206.388374][22427:22427] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1694847206.388622][22427:22427] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1694847206.388738][22427:22427] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1694847206.389083][22427:22427] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-dkljdh)
[1694847206.389661][22427:22427] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847206.389712][22427:22427] CHIP:DL: NVS set: chip-counters/reboot-count = 14 (0xE)
[1694847206.390629][22427:22427] CHIP:DL: Got Ethernet interface: eth0
[1694847206.391230][22427:22427] CHIP:DL: Found the primary Ethernet interface:eth0
[1694847206.391833][22427:22427] CHIP:DL: Got WiFi interface: wlan0
[1694847206.391904][22427:22427] CHIP:DL: Failed to reset WiFi statistic counts
[1694847206.391989][22427:22427] CHIP:IN: UDP::Init bind&listen port=0
[1694847206.392092][22427:22427] CHIP:IN: UDP::Init bound to port=33094
[1694847206.392112][22427:22427] CHIP:IN: BLEBase::Init - setting/overriding transport
[1694847206.392130][22427:22427] CHIP:IN: TransportMgr initialized
[1694847206.392161][22427:22427] CHIP:FP: Initializing FabricTable from persistent storage
[1694847206.392299][22427:22427] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847206.393640][22427:22427] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x531C5E1335241DE8, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1694847206.395623][22427:22427] CHIP:ZCL: Using ZAP configuration...
[1694847206.399148][22427:22427] CHIP:DL: Avahi client registered
[1694847206.399277][22427:22427] CHIP:CTL: System State Initialized...
[1694847206.399356][22427:22427] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847206.399401][22427:22427] CHIP:CTL: Setting attestation nonce to random value
[1694847206.399433][22427:22427] CHIP:CTL: Setting CSR nonce to random value
[1694847206.399490][22427:22427] CHIP:IN: UDP::Init bind&listen port=5550
[1694847206.399608][22427:22427] CHIP:IN: UDP::Init bound to port=5550
[1694847206.399628][22427:22427] CHIP:IN: TransportMgr initialized
[1694847206.399865][22427:22429] CHIP:DL: CHIP task running
[1694847206.400036][22427:22429] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1694847206.400300][22427:22429] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847206.400347][22427:22429] CHIP:CTL: Setting attestation nonce to random value
[1694847206.400493][22427:22429] CHIP:CTL: Setting CSR nonce to random value
[1694847206.401289][22427:22429] CHIP:CTL: Generating NOC
[1694847206.402102][22427:22429] CHIP:FP: Validating NOC chain
[1694847206.403900][22427:22429] CHIP:FP: NOC chain validation successful
[1694847206.404054][22427:22429] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1694847206.404085][22427:22429] CHIP:TS: Last Known Good Time: 2023-07-25T18:22:45
[1694847206.404104][22427:22429] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1694847206.404121][22427:22429] CHIP:TS: Retaining current Last Known Good Time
[1694847206.406296][22427:22429] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1694847206.408217][22427:22429] CHIP:TS: Committing Last Known Good Time to storage: 2023-07-25T18:22:45
[1694847206.410033][22427:22429] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 531C5E1335241DE8)
[1694847206.410085][22427:22429] CHIP:IN: UDP::Init bind&listen port=5550
[1694847206.410209][22427:22429] CHIP:IN: UDP::Init bound to port=5550
[1694847206.410232][22427:22429] CHIP:IN: TransportMgr initialized
[1694847206.423208][22427:22429] CHIP:TOO: Sending command to node 0x1
[1694847206.423607][22427:22429] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1694847206.423634][22427:22429] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1694847206.423667][22427:22429] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1694847206.423697][22427:22429] CHIP:DIS: Resolving 531C5E1335241DE8:0000000000000001 ...
[1694847206.531501][22427:22429] CHIP:DL: Avahi resolve found
[1694847206.531654][22427:22429] CHIP:DIS: Node ID resolved for 531C5E1335241DE8:0000000000000001
[1694847206.531722][22427:22429] CHIP:DIS:      Hostname: 1A214799925ACE94
[1694847206.531784][22427:22429] CHIP:DIS:      IP Address #1: fd11:35::e119:c9a1:75db:8d1e
[1694847206.531837][22427:22429] CHIP:DIS:      Port: 5540
[1694847206.531885][22427:22429] CHIP:DIS:      Mrp Interval idle: 2800 ms
[1694847206.531945][22427:22429] CHIP:DIS:      Mrp Interval active: 1000 ms
[1694847206.531996][22427:22429] CHIP:DIS:      TCP Supported: 0
[1694847206.533750][22427:22429] CHIP:DIS: Lookup clearing interface for non LL address
[1694847206.533974][22427:22429] CHIP:DIS: UDP:[fd11:35::e119:c9a1:75db:8d1e%veth10eedd1]:5540: new best score: 5
[1694847206.534036][22427:22429] CHIP:DIS: Checking node lookup status after 110 ms
[1694847206.534087][22427:22429] CHIP:DIS: Keeping DNSSD lookup active
[1694847206.624406][22427:22429] CHIP:DIS: Checking node lookup status after 200 ms
[1694847206.624541][22427:22429] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540 while in state 2
[1694847206.624600][22427:22429] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1694847206.624930][22427:22429] CHIP:IN: SecureSession[0xffff8400ac50]: Allocated Type:2 LSID:22369
[1694847206.625035][22427:22429] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1694847206.626585][22427:22429] CHIP:EM: <<< [E:540i S:0 M:226751894] (U) Msg TX to 0:0000000000000000 [0000] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1694847206.626669][22427:22429] CHIP:IN: (U) Sending msg 226751894 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847206.626912][22427:22429] CHIP:SC: Sent Sigma1 msg
[1694847206.626952][22427:22429] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1694847209.909497][22427:22429] CHIP:EM: Retransmitting MessageCounter:226751894 on exchange 540i Send Cnt 1
[1694847209.909714][22427:22429] CHIP:IN: (U) Sending msg 226751894 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847213.661983][22427:22429] CHIP:EM: Retransmitting MessageCounter:226751894 on exchange 540i Send Cnt 2
[1694847213.662200][22427:22429] CHIP:IN: (U) Sending msg 226751894 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847219.790817][22427:22429] CHIP:EM: Retransmitting MessageCounter:226751894 on exchange 540i Send Cnt 3
[1694847219.791035][22427:22429] CHIP:IN: (U) Sending msg 226751894 to IP address 'UDP:[fd11:35::e119:c9a1:75db:8d1e]:5540'
[1694847226.400480][22427:22427] CHIP:CTL: Shutting down the commissioner
[1694847226.400573][22427:22427] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847226.400755][22427:22427] CHIP:CTL: Shutting down the controller
[1694847226.400945][22427:22427] CHIP:IN: SecureSession[0xffff8400ac50]: Released - Type:2 LSID:22369
[1694847226.401056][22427:22427] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1694847226.401116][22427:22427] CHIP:FP: Forgetting fabric 0x1
[1694847226.401185][22427:22427] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847226.401492][22427:22427] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847226.401552][22427:22427] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847226.401632][22427:22427] CHIP:CTL: Shutting down the commissioner
[1694847226.401686][22427:22427] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1694847226.401834][22427:22427] CHIP:CTL: Shutting down the controller
[1694847226.401891][22427:22427] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1694847226.402192][22427:22427] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1694847226.402380][22427:22427] CHIP:FP: Shutting down FabricTable
[1694847226.402452][22427:22427] CHIP:TS: Pending Last Known Good Time: 2023-07-25T18:22:45
[1694847226.402665][22427:22427] CHIP:TS: Previous Last Known Good Time: 2023-07-25T18:22:45
[1694847226.402828][22427:22427] CHIP:TS: Reverted Last Known Good Time to previous value
[1694847226.403306][22427:22427] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-fTA6Am)
[1694847226.404653][22427:22427] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1694847226.404796][22427:22427] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1694847226.404857][22427:22427] CHIP:DL: Inet Layer shutdown
[1694847226.404905][22427:22427] CHIP:DL: BLE shutdown
[1694847226.404955][22427:22427] CHIP:DL: System Layer shutdown
[1694847226.405641][22427:22427] CHIP:TOO: Run command failure: ../../examples/chip-tool/commands/common/CHIPCommand.cpp:549: CHIP Error 0x00000032: Timeout

I look forward to your response.
BR,
Jerry

[Charlie]

Hi Jerry,

Here is the feedback from our development team:

1) About the firmware:

I tested it once again on NCS 2.2.0 based on already merged known issue:

KRKNWK-17594: Application does not always respond when forcing fail-safe cleanup.

This can happen because of the Thread interface being unnecessarily reset and can result in the TC-CNET-4.10 Matter Certification test failing.

Workaround: Manually cherry-pick and apply the commit with the fix to sdk-connectedhomeip (commit hash: 3b2d8e1367d9055a78d72365323cfbf60e054975).

Previously I test it on NCS 2.4.0

I've built lock sample on NCS 2.2.0 + above fix and performed the test, but I was not able to reproduce it.
Can you verify if the fix was applied based on current state?

During PR review there could be a change in the implementation.

2) About the log:

I am not sure if this is possible but based only on the logs provided the DUT might crash, because communication failed at every next zcl command. If it is true, then helpful will be to debug by the GDB.

Best regards,

Charlie