Electrical Power Measurement Cluster Added via ZAP in SDK 3.2.0-preview Not Showing in Controllers (e.g., Home Assistant)

[sbehnam3]

Hello,

I recently migrated to SDK version 3.2.0-preview, which supports Matter 1.4.x.

When I use ZAP and add a new endpoint to the light_bulb example under the name Electrical Sensor, I include clusters from the Measurement & Sensing category, specifically the Electrical Power Measurement cluster. However, after building and flashing the device, no UI appears for this cluster in controllers such as the latest version of Home Assistant.

Interestingly, if I add other clusters, for example Air Quality, they are displayed correctly in the UI.

Could you please help me understand why the Electrical Power Measurement cluster is not displayed in the UI? Is there a known limitation or additional configuration required for this cluster to be recognized by controllers?

Thank you very much for your guidance.

[sbehnam3]

Hi Martte
Thank you for your respond and thank you for your suggestion regarding chip-tool testing. I haven’t tested the cluster using chip-tool yet, but I plan to do so soon and will share the results with you.

In the meantime, while observing the logs during Home Assistant’s attempt to interact with my development kit, I noticed repeated errors like:

Fail to retrieve data ... clusterId: 0x0090 / 0x0091, attributeId: ... err = 501 

These cluster IDs correspond to the Electrical Power Measurement cluster. Based on my understanding, the 0x501 status indicates Unsupported Cluster / Unsupported Attribute.

Could you please clarify whether these errors suggest that the issue is on our side (in the device implementation) or if they are originating from Home Assistant?

Thank you very much for your guidance.

[Marte Myrvold]

Hi,

Are these logs from the device or Home Assistant?

Can you share the complete log?

Best regards,
Marte

[sbehnam3]

Hi Marte,

When I built and flashed the Light Bulb example with an additional Electrical Sensor configured as endpoint 2 (generated using ZAP), the device started advertising successfully on the nRF52840 DK.

I'm connecting to it through Home Assistant Green, which acts as the border router with a Thread dongle connected via USB. The commissioning and control are done through the Home Assistant app.

The logs I previously shared are taken directly from the nRF52840 DK nrf serial terminal — they are not from Home Assistant.
Below, I’ve included the part of  log captured from the DK’s COM port for your reference.

D: 207208 [IN]UDP Message Received packet nb : 60 SrcAddr : fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2[47953] DestAddr : fd6c:c98b:e90b:1:5e69:660a:a976:1297[5540] Payload Length 42
I: 207224 [EM]>>> [E:14636r S:21075 M:176490579 (Ack:258267128)] (S) Msg RX from 2:000000000001B669 [DC11] to 0000000000000060 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 207239 [IM]Received status response, status is 0x00
I: 207269 [EM]<<< [E:14636r S:21075 M:258267129 (Ack:176490579)] (S) Msg TX from 0000000000000060 to 2:000000000001B669 [DC11] [UDP:[fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2]:47953] --- Type 0001:05 (IM:ReportData) (B:1203)
I: 207290 [EM]??1 [E:14636r S:21075 M:258267129] (S) Msg Retransmission to 2:000000000001B669 scheduled for 1904ms from now [State:Active II:500 AI:300 AT:4000]
D: 207415 [IN]UDP Message Received packet nb : 61 SrcAddr : fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2[47953] DestAddr : fd6c:c98b:e90b:1:5e69:660a:a976:1297[5540] Payload Length 42
I: 207432 [EM]>>> [E:14636r S:21075 M:176490580 (Ack:258267129)] (S) Msg RX from 2:000000000001B669 [DC11] to 0000000000000060 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 207447 [IM]Received status response, status is 0x00
I: 207473 [EM]<<< [E:14636r S:21075 M:258267130 (Ack:176490580)] (S) Msg TX from 0000000000000060 to 2:000000000001B669 [DC11] [UDP:[fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2]:47953] --- Type 0001:05 (IM:ReportData) (B:1199)
I: 207494 [EM]??1 [E:14636r S:21075 M:258267130] (S) Msg Retransmission to 2:000000000001B669 scheduled for 1833ms from now [State:Active II:500 AI:300 AT:4000]
D: 207620 [IN]UDP Message Received packet nb : 62 SrcAddr : fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2[47953] DestAddr : fd6c:c98b:e90b:1:5e69:660a:a976:1297[5540] Payload Length 42
I: 207636 [EM]>>> [E:14636r S:21075 M:176490581 (Ack:258267130)] (S) Msg RX from 2:000000000001B669 [DC11] to 0000000000000060 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 207651 [IM]Received status response, status is 0x00
E: 207658 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0090, attributeId: 0x0000_0000err = 501
E: 207670 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0090, attributeId: 0x0000_0001err = 501
E: 207682 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0090, attributeId: 0x0000_0002err = 501
E: 207693 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0090, attributeId: 0x0000_0008err = 501
E: 207707 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_0091, attributeId: 0x0000_0000err = 501
I: 207725 [EM]<<< [E:14636r S:21075 M:258267131 (Ack:176490581)] (S) Msg TX from 0000000000000060 to 2:000000000001B669 [DC11] [UDP:[fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2]:47953] --- Type 0001:05 (IM:ReportData) (B:777)
I: 207746 [EM]??1 [E:14636r S:21075 M:258267131] (S) Msg Retransmission to 2:000000000001B669 scheduled for 1908ms from now [State:Active II:500 AI:300 AT:4000]
D: 207834 [IN]UDP Message Received packet nb : 63 SrcAddr : fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2[47953] DestAddr : fd6c:c98b:e90b:1:5e69:660a:a976:1297[5540] Payload Length 34
I: 207851 [EM]>>> [E:14636r S:21075 M:176490582 (Ack:258267131)] (S) Msg RX from 2:000000000001B669 [DC11] to 0000000000000060 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
D: 208681 [IN]UDP Message Received packet nb : 64 SrcAddr : fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2[47953] DestAddr : fd6c:c98b:e90b:1:5e69:660a:a976:1297[5540] Payload Length 66
I: 208697 [EM]>>> [E:14637r S:21075 M:176490583] (S) Msg RX from 2:000000000001B669 [DC11] to 0000000000000060 --- Type 0001:08 (IM:InvokeCommandRequest) (B:66)
I: 208713 [ZCL]OpCreds: Received an UpdateFabricLabel command
I: 208745 [FP]Metadata for Fabric 0x2 persisted to storage.
I: 208752 [EM]<<< [E:14637r S:21075 M:258267132 (Ack:176490583)] (S) Msg TX from 0000000000000060 to 2:000000000001B669 [DC11] [UDP:[fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2]:47953] --- Type 0001:09 (IM:InvokeCommandResponse) (B:70)
I: 208773 [EM]??1 [E:14637r S:21075 M:258267132] (S) Msg Retransmission to 2:000000000001B669 scheduled for 1862ms from now [State:Active II:500 AI:300 AT:4000]
D: 208803 [IN]UDP Message Received packet nb : 65 SrcAddr : fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2[47953] DestAddr : fd6c:c98b:e90b:1:5e69:660a:a976:1297[5540] Payload Length 34
I: 208820 [EM]>>> [E:14637r S:21075 M:176490584 (Ack:258267132)] (S) Msg RX from 2:000000000001B669 [DC11] to 0000000000000060 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
D: 208954 [IN]UDP Message Received packet nb : 66 SrcAddr : fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2[47953] DestAddr : fd6c:c98b:e90b:1:5e69:660a:a976:1297[5540] Payload Length 57
I: 208970 [EM]>>> [E:14638r S:21075 M:176490585] (S) Msg RX from 2:000000000001B669 [DC11] to 0000000000000060 --- Type 0001:03 (IM:SubscribeRequest) (B:57)
D: 208984 [IM]Received Subscribe request
I: 209036 [DMG]Final negotiated min/max parameters: Min = 1s, Max = 60s
E: 209125 [DL]Long dispatch time: 156 ms, for event type 3
I: 209161 [EM]<<< [E:14638r S:21075 M:258267133 (Ack:176490585)] (S) Msg TX from 0000000000000060 to 2:000000000001B669 [DC11] [UDP:[fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2]:47953] --- Type 0001:05 (IM:ReportData) (B:1200)
I: 209182 [EM]??1 [E:14638r S:21075 M:258267133] (S) Msg Retransmission to 2:000000000001B669 scheduled for 1909ms from now [State:Active II:500 AI:300 AT:4000]
D: 209317 [IN]UDP Message Received packet nb : 67 SrcAddr : fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2[47953] DestAddr : fd6c:c98b:e90b:1:5e69:660a:a976:1297[5540] Payload Length 42
I: 209333 [EM]>>> [E:14638r S:21075 M:176490586 (Ack:258267133)] (S) Msg RX from 2:000000000001B669 [DC11] to 0000000000000060 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 209348 [IM]Received status response, status is 0x00
I: 209386 [EM]<<< [E:14638r S:21075 M:258267134 (Ack:176490586)] (S) Msg TX from 0000000000000060 to 2:000000000001B669 [DC11] [UDP:[fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2]:47953] --- Type 0001:05 (IM:ReportData) (B:1207)
I: 209407 [EM]??1 [E:14638r S:21075 M:258267134] (S) Msg Retransmission to 2:000000000001B669 scheduled for 1868ms from now [State:Active II:500 AI:300 AT:4000]
D: 209528 [IN]UDP Message Received packet nb : 68 SrcAddr : fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2[47953] DestAddr : fd6c:c98b:e90b:1:5e69:660a:a976:1297[5540] Payload Length 42
I: 209544 [EM]>>> [E:14638r S:21075 M:176490587 (Ack:258267134)] (S) Msg RX from 2:000000000001B669 [DC11] to 0000000000000060 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 209559 [IM]Received status response, status is 0x00
E: 209571 [DMG]Fail to retrieve data, roll back and encode status on clusterId: 0x0000_002B, attributeId: 0x0000_0001err = 501
I: 209606 [EM]<<< [E:14638r S:21075 M:258267135 (Ack:176490587)] (S) Msg TX from 0000000000000060 to 2:000000000001B669 [DC11] [UDP:[fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2]:47953] --- Type 0001:05 (IM:ReportData) (B:1191)
I: 209627 [EM]??1 [E:14638r S:21075 M:258267135] (S) Msg Retransmission to 2:000000000001B669 scheduled for 1870ms from now [State:Active II:500 AI:300 AT:4000]
D: 209785 [IN]UDP Message Received packet nb : 69 SrcAddr : fd6c:c98b:e90b:1:cccb:c9d1:7ea9:54c2[47953] DestAddr : fd6c:c98b:e90b:1:5e69:660a:a976:1297[5540] Payload Length 42
I: 209802 [EM]>>> [E:14638r S:21075 M:176490588 (Ack:258267135)] (S) Msg RX from 2:000000000001B669 [DC11] to 0000000000000060 --- Type 0001:01 (IM:StatusResponse) (B:42)
I: 209817 [IM]Received status response, status is 0x00
I: 209885 [EM]<<< [E:14638r S:21075 M:258267136 (Ack:176490588)] (S) Msg TX from 0000000000000060 to 2:000000000001B669 [DC11] 

[sbehnam3]

Hi Marte,

Regarding your question: “Are you able to interact with the cluster using chip-tool?”

I have set up the Matter environment and chip-tool on Linux and was able to connect to the nRF52840 DK development board via Bluetooth. I collected some logs, but these logs only cover the initial commissioning and connection phase.

Immediately after commissioning, the device switches to Thread for stable communication. Since my system does not have Thread connectivity, the connection drops, and I cannot use chip-tool to send requests or read the cluster data.

To interact reliably via chip-tool, I would need a device that supports both Bluetooth commissioning and Thread communication, so it can maintain a stable connection with the development board.

I’m wondering if there’s any alternative way to capture logs or interact with the board using chip-tool without needing an additional Thread-capable device?

[sbehnam3]

Dear Marte,

I have called the clusters through the chip tool, and it seems that the "Electrical Power Measurement" cluster is available. However, some attributes are failing.

I am waiting for your response.

vboxuser@Ubuntu-Thread:~/connectedhomeip$ ./out/debug/chip-tool descriptor read parts-list 1 0
[1761642942.106380][4870:4870] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1761642942.107036][4870:4870] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1761642942.107091][4870:4870] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1761642942.108723][4870:4870] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1761642942.108959][4870:4870] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1761642942.108983][4870:4870] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1761642942.109171][4870:4870] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-KAQBMx)
[1761642942.110023][4870:4870] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761642942.110038][4870:4870] CHIP:DL: NVS set: chip-counters/reboot-count = 4 (0x4)
[1761642942.110307][4870:4870] CHIP:DL: Got Ethernet interface: enp0s3
[1761642942.110658][4870:4870] CHIP:DL: Found the primary Ethernet interface:enp0s3
[1761642942.111303][4870:4870] CHIP:DL: Failed to get WiFi interface
[1761642942.111358][4870:4870] CHIP:DL: Failed to reset WiFi statistic counts
[1761642942.111579][4870:4870] CHIP:IN: UDP::Init bind&listen port=0
[1761642942.111661][4870:4870] CHIP:IN: UDP::Init bound to port=33325
[1761642942.111668][4870:4870] CHIP:IN: UDP::Init bind&listen port=0
[1761642942.111687][4870:4870] CHIP:IN: UDP::Init bound to port=57708
[1761642942.111690][4870:4870] CHIP:IN: BLEBase::Init - setting/overriding transport
[1761642942.111693][4870:4870] CHIP:IN: TransportMgr initialized
[1761642942.111714][4870:4870] CHIP:FP: Initializing FabricTable from persistent storage
[1761642942.111808][4870:4870] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761642942.112434][4870:4870] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xC0157AA7F5726A6C, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1761642942.115105][4870:4870] CHIP:ZCL: Using ZAP configuration...
[1761642942.116379][4870:4870] CHIP:CTL: System State Initialized...
[1761642942.116479][4870:4870] CHIP:CTL: Setting attestation nonce to random value
[1761642942.116500][4870:4870] CHIP:CTL: Setting CSR nonce to random value
[1761642942.116868][4870:4872] CHIP:DL: CHIP task running
[1761642942.116937][4870:4872] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1761642942.117030][4870:4872] CHIP:CTL: Setting attestation nonce to random value
[1761642942.117106][4870:4872] CHIP:CTL: Setting CSR nonce to random value
[1761642942.117343][4870:4872] CHIP:CTL: Generating NOC
[1761642942.117784][4870:4872] CHIP:FP: Validating NOC chain
[1761642942.118174][4870:4872] CHIP:FP: NOC chain validation successful
[1761642942.121502][4870:4872] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1761642942.121712][4870:4872] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761642942.121733][4870:4872] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1761642942.121747][4870:4872] CHIP:TS: Retaining current Last Known Good Time
[1761642942.129900][4870:4872] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1761642942.131712][4870:4872] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1761642942.133075][4870:4872] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: C0157AA7F5726A6C)
[1761642942.139990][4870:4872] CHIP:TOO: Sending command to node 0x1
[1761642942.140161][4870:4872] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1761642942.140167][4870:4872] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1761642942.140180][4870:4872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1761642942.141961][4870:4872] CHIP:DIS: Lookup clearing interface for non LL address
[1761642942.141993][4870:4872] CHIP:DIS: UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895%enp0s3]:5540: new best score: 5
[1761642942.141997][4870:4872] CHIP:DIS: Checking node lookup status after 1 ms
[1761642942.141999][4870:4872] CHIP:DIS: Keeping DNSSD lookup active
[1761642942.341374][4870:4872] CHIP:DIS: Checking node lookup status after 201 ms
[1761642942.341454][4870:4872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540 while in state 2
[1761642942.341462][4870:4872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1761642942.341546][4870:4872] CHIP:IN: SecureSession[0x79e42400da90]: Allocated Type:2 LSID:8844
[1761642942.341556][4870:4872] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1761642942.341837][4870:4872] CHIP:EM: <<< [E:12566i S:0 M:65294399] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1761642942.341919][4870:4872] CHIP:SC: Sent Sigma1 msg
[1761642942.341923][4870:4872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1761642942.450485][4870:4872] CHIP:EM: >>> [E:12566i S:0 M:78814383 (Ack:65294399)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761642942.450533][4870:4872] CHIP:EM: Found matching exchange: 12566i, Delegate: 0x79e42400d7e8
[1761642942.450554][4870:4872] CHIP:EM: Rxd Ack; Removing MessageCounter:65294399 from Retrans Table on exchange 12566i
[1761642942.628587][4870:4872] CHIP:EM: >>> [E:12566i S:0 M:78814384 (Ack:65294399)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1761642942.628650][4870:4872] CHIP:EM: Found matching exchange: 12566i, Delegate: 0x79e42400d7e8
[1761642942.628658][4870:4872] CHIP:EM: CHIP MessageCounter:65294399 not in RetransTable on exchange 12566i
[1761642942.628676][4870:4872] CHIP:SC: Received Sigma2 msg
[1761642942.628687][4870:4872] CHIP:SC: Peer assigned session session ID 29401
[1761642942.629542][4870:4872] CHIP:SC: Found MRP parameters in the message
[1761642942.629611][4870:4872] CHIP:SC: Sending Sigma3
[1761642942.629864][4870:4872] CHIP:EM: <<< [E:12566i S:0 M:65294400 (Ack:78814384)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1761642942.629979][4870:4872] CHIP:SC: Sent Sigma3 msg
[1761642942.785129][4870:4872] CHIP:EM: >>> [E:12566i S:0 M:78814385 (Ack:65294400)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761642942.785412][4870:4872] CHIP:EM: Found matching exchange: 12566i, Delegate: 0x79e42400d7e8
[1761642942.785426][4870:4872] CHIP:EM: Rxd Ack; Removing MessageCounter:65294400 from Retrans Table on exchange 12566i
[1761642943.106189][4870:4872] CHIP:EM: >>> [E:12566i S:0 M:78814386 (Ack:65294400)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1761642943.106383][4870:4872] CHIP:EM: Found matching exchange: 12566i, Delegate: 0x79e42400d7e8
[1761642943.106392][4870:4872] CHIP:EM: CHIP MessageCounter:65294400 not in RetransTable on exchange 12566i
[1761642943.106410][4870:4872] CHIP:SC: Success status report received. Session was established
[1761642943.108875][4870:4872] CHIP:SC: SecureSession[0x79e42400da90, LSID:8844]: State change 'kEstablishing' --> 'kActive'
[1761642943.108933][4870:4872] CHIP:IN: SecureSession[0x79e42400da90]: Activated - Type:2 LSID:8844
[1761642943.108939][4870:4872] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:8844 PSID:29401!
[1761642943.108946][4870:4872] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1761642943.108969][4870:4872] CHIP:TOO: Sending ReadAttribute to:
[1761642943.109003][4870:4872] CHIP:TOO: 	cluster 0x0000_001D, attribute: 0x0000_0003, endpoint 0
[1761642943.109066][4870:4872] CHIP:DMG: SendReadRequest ReadClient[0x79e42400a6c0]: Sending Read Request
[1761642943.109119][4870:4872] CHIP:EM: <<< [E:12567i S:8844 M:225392188] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0001:02 (IM:ReadRequest)
[1761642943.109361][4870:4872] CHIP:DMG: MoveToState ReadClient[0x79e42400a6c0]: Moving to [AwaitingIn]
[1761642943.109385][4870:4872] CHIP:EM: <<< [E:12566i S:0 M:65294401 (Ack:78814386)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761642943.109401][4870:4872] CHIP:EM: Flushed pending ack for MessageCounter:78814386 on exchange 12566i
[1761642943.259071][4870:4872] CHIP:EM: >>> [E:12567i S:8844 M:260732399 (Ack:225392188)] (S) Msg RX from 1:0000000000000001 [6A6C] --- Type 0001:05 (IM:ReportData)
[1761642943.259092][4870:4872] CHIP:EM: Found matching exchange: 12567i, Delegate: 0x79e42400a6d0
[1761642943.259101][4870:4872] CHIP:EM: Rxd Ack; Removing MessageCounter:225392188 from Retrans Table on exchange 12567i
[1761642943.259122][4870:4872] CHIP:DMG: ReportDataMessage =
[1761642943.259126][4870:4872] CHIP:DMG: {
[1761642943.259129][4870:4872] CHIP:DMG: 	AttributeReportIBs =
[1761642943.259134][4870:4872] CHIP:DMG: 	[
[1761642943.259137][4870:4872] CHIP:DMG: 		AttributeReportIB =
[1761642943.259142][4870:4872] CHIP:DMG: 		{
[1761642943.259145][4870:4872] CHIP:DMG: 			AttributeDataIB =
[1761642943.259150][4870:4872] CHIP:DMG: 			{
[1761642943.259154][4870:4872] CHIP:DMG: 				DataVersion = 0xad62f25a,
[1761642943.259158][4870:4872] CHIP:DMG: 				AttributePathIB =
[1761642943.259162][4870:4872] CHIP:DMG: 				{
[1761642943.259167][4870:4872] CHIP:DMG: 					Endpoint = 0x0,
[1761642943.259171][4870:4872] CHIP:DMG: 					Cluster = 0x1d,
[1761642943.259175][4870:4872] CHIP:DMG: 					Attribute = 0x0000_0003,
[1761642943.259179][4870:4872] CHIP:DMG: 				}
[1761642943.259183][4870:4872] CHIP:DMG: 					
[1761642943.259187][4870:4872] CHIP:DMG: 				Data = [
[1761642943.259192][4870:4872] CHIP:DMG: 						1 (unsigned), 2 (unsigned), 
[1761642943.259197][4870:4872] CHIP:DMG: 				],
[1761642943.259200][4870:4872] CHIP:DMG: 			},
[1761642943.259206][4870:4872] CHIP:DMG: 			
[1761642943.259209][4870:4872] CHIP:DMG: 		},
[1761642943.259214][4870:4872] CHIP:DMG: 		
[1761642943.259216][4870:4872] CHIP:DMG: 	],
[1761642943.259221][4870:4872] CHIP:DMG: 	
[1761642943.259224][4870:4872] CHIP:DMG: 	SuppressResponse = true, 
[1761642943.259227][4870:4872] CHIP:DMG: 	InteractionModelRevision = 12
[1761642943.259230][4870:4872] CHIP:DMG: }
[1761642943.259300][4870:4872] CHIP:TOO: Endpoint: 0 Cluster: 0x0000_001D Attribute 0x0000_0003 DataVersion: 2908942938
[1761642943.259334][4870:4872] CHIP:TOO:   PartsList: 2 entries
[1761642943.259339][4870:4872] CHIP:TOO:     [1]: 1
[1761642943.259342][4870:4872] CHIP:TOO:     [2]: 2
[1761642943.259387][4870:4872] CHIP:EM: <<< [E:12567i S:8844 M:225392189 (Ack:260732399)] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761642943.259987][4870:4872] CHIP:EM: Flushed pending ack for MessageCounter:260732399 on exchange 12567i
[1761642943.260601][4870:4870] CHIP:CTL: Shutting down the commissioner
[1761642943.260685][4870:4870] CHIP:CTL: Shutting down the controller
[1761642943.260718][4870:4870] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1761642943.260733][4870:4870] CHIP:IN: SecureSession[0x79e42400da90]: MarkForEviction Type:2 LSID:8844
[1761642943.260747][4870:4870] CHIP:SC: SecureSession[0x79e42400da90, LSID:8844]: State change 'kActive' --> 'kPendingEviction'
[1761642943.260813][4870:4870] CHIP:IN: SecureSession[0x79e42400da90]: Released - Type:2 LSID:8844
[1761642943.260822][4870:4870] CHIP:FP: Forgetting fabric 0x1
[1761642943.260828][4870:4870] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761642943.260869][4870:4870] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761642943.260872][4870:4870] CHIP:TS: Reverted Last Known Good Time to previous value
[1761642943.260885][4870:4870] CHIP:CTL: Shutting down the commissioner
[1761642943.260889][4870:4870] CHIP:CTL: Shutting down the controller
[1761642943.260892][4870:4870] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1761642943.260983][4870:4870] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1761642943.261005][4870:4870] CHIP:FP: Shutting down FabricTable
[1761642943.261009][4870:4870] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761642943.261025][4870:4870] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761642943.261027][4870:4870] CHIP:TS: Reverted Last Known Good Time to previous value
[1761642943.261128][4870:4870] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-7F5DSl)
[1761642943.261710][4870:4870] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761642943.261724][4870:4870] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1761642943.261727][4870:4870] CHIP:DL: Inet Layer shutdown
[1761642943.261730][4870:4870] CHIP:DL: BLE shutdown
[1761642943.262034][4870:4870] CHIP:DL: System Layer shutdown
vboxuser@Ubuntu-Thread:~/connectedhomeip$ ./out/debug/chip-tool descriptor read server-list 1 <EP>
bash: syntax error near unexpected token `newline'
vboxuser@Ubuntu-Thread:~/connectedhomeip$ ./out/debug/chip-tool descriptor read server-list 1 <EP>
bash: syntax error near unexpected token `newline'
vboxuser@Ubuntu-Thread:~/connectedhomeip$ ^C
vboxuser@Ubuntu-Thread:~/connectedhomeip$ ./out/debug/chip-tool descriptor read server-list 1 1
[1761643164.310884][4889:4889] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1761643164.311717][4889:4889] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1761643164.311725][4889:4889] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1761643164.313170][4889:4889] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1761643164.313205][4889:4889] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1761643164.313221][4889:4889] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1761643164.313338][4889:4889] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-fx6msX)
[1761643164.314312][4889:4889] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761643164.314329][4889:4889] CHIP:DL: NVS set: chip-counters/reboot-count = 5 (0x5)
[1761643164.314598][4889:4889] CHIP:DL: Got Ethernet interface: enp0s3
[1761643164.314821][4889:4889] CHIP:DL: Found the primary Ethernet interface:enp0s3
[1761643164.315473][4889:4889] CHIP:DL: Failed to get WiFi interface
[1761643164.315528][4889:4889] CHIP:DL: Failed to reset WiFi statistic counts
[1761643164.315694][4889:4889] CHIP:IN: UDP::Init bind&listen port=0
[1761643164.315742][4889:4889] CHIP:IN: UDP::Init bound to port=36438
[1761643164.315758][4889:4889] CHIP:IN: UDP::Init bind&listen port=0
[1761643164.315787][4889:4889] CHIP:IN: UDP::Init bound to port=39504
[1761643164.315838][4889:4889] CHIP:IN: BLEBase::Init - setting/overriding transport
[1761643164.315844][4889:4889] CHIP:IN: TransportMgr initialized
[1761643164.315856][4889:4889] CHIP:FP: Initializing FabricTable from persistent storage
[1761643164.315899][4889:4889] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761643164.316433][4889:4889] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xC0157AA7F5726A6C, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1761643164.318417][4889:4889] CHIP:ZCL: Using ZAP configuration...
[1761643164.319596][4889:4889] CHIP:CTL: System State Initialized...
[1761643164.319987][4889:4889] CHIP:CTL: Setting attestation nonce to random value
[1761643164.320012][4889:4889] CHIP:CTL: Setting CSR nonce to random value
[1761643164.320383][4889:4891] CHIP:DL: CHIP task running
[1761643164.320452][4889:4891] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1761643164.320551][4889:4891] CHIP:CTL: Setting attestation nonce to random value
[1761643164.320631][4889:4891] CHIP:CTL: Setting CSR nonce to random value
[1761643164.320873][4889:4891] CHIP:CTL: Generating NOC
[1761643164.327134][4889:4891] CHIP:FP: Validating NOC chain
[1761643164.327770][4889:4891] CHIP:FP: NOC chain validation successful
[1761643164.328019][4889:4891] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1761643164.328040][4889:4891] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761643164.328054][4889:4891] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1761643164.328068][4889:4891] CHIP:TS: Retaining current Last Known Good Time
[1761643164.332155][4889:4891] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1761643164.333858][4889:4891] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1761643164.334985][4889:4891] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: C0157AA7F5726A6C)
[1761643164.342373][4889:4891] CHIP:TOO: Sending command to node 0x1
[1761643164.342760][4889:4891] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1761643164.342815][4889:4891] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1761643164.342843][4889:4891] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1761643164.344785][4889:4891] CHIP:DIS: Lookup clearing interface for non LL address
[1761643164.344825][4889:4891] CHIP:DIS: UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895%enp0s3]:5540: new best score: 5
[1761643164.344829][4889:4891] CHIP:DIS: Checking node lookup status after 2 ms
[1761643164.344832][4889:4891] CHIP:DIS: Keeping DNSSD lookup active
[1761643164.543435][4889:4891] CHIP:DIS: Checking node lookup status after 201 ms
[1761643164.543538][4889:4891] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540 while in state 2
[1761643164.543546][4889:4891] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1761643164.543627][4889:4891] CHIP:IN: SecureSession[0x78ee4000da90]: Allocated Type:2 LSID:19362
[1761643164.543637][4889:4891] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1761643164.543916][4889:4891] CHIP:EM: <<< [E:23470i S:0 M:92824133] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1761643164.544052][4889:4891] CHIP:SC: Sent Sigma1 msg
[1761643164.544060][4889:4891] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1761643164.651502][4889:4891] CHIP:EM: >>> [E:23470i S:0 M:78814387 (Ack:92824133)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643164.651570][4889:4891] CHIP:EM: Found matching exchange: 23470i, Delegate: 0x78ee4000d7e8
[1761643164.651584][4889:4891] CHIP:EM: Rxd Ack; Removing MessageCounter:92824133 from Retrans Table on exchange 23470i
[1761643164.824510][4889:4891] CHIP:EM: >>> [E:23470i S:0 M:78814388 (Ack:92824133)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1761643164.824533][4889:4891] CHIP:EM: Found matching exchange: 23470i, Delegate: 0x78ee4000d7e8
[1761643164.824538][4889:4891] CHIP:EM: CHIP MessageCounter:92824133 not in RetransTable on exchange 23470i
[1761643164.824554][4889:4891] CHIP:SC: Received Sigma2 msg
[1761643164.824565][4889:4891] CHIP:SC: Peer assigned session session ID 29402
[1761643164.825451][4889:4891] CHIP:SC: Found MRP parameters in the message
[1761643164.825648][4889:4891] CHIP:SC: Sending Sigma3
[1761643164.825790][4889:4891] CHIP:EM: <<< [E:23470i S:0 M:92824134 (Ack:78814388)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1761643164.825908][4889:4891] CHIP:SC: Sent Sigma3 msg
[1761643164.983675][4889:4891] CHIP:EM: >>> [E:23470i S:0 M:78814389 (Ack:92824134)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643164.983697][4889:4891] CHIP:EM: Found matching exchange: 23470i, Delegate: 0x78ee4000d7e8
[1761643164.983706][4889:4891] CHIP:EM: Rxd Ack; Removing MessageCounter:92824134 from Retrans Table on exchange 23470i
[1761643165.305530][4889:4891] CHIP:EM: >>> [E:23470i S:0 M:78814390 (Ack:92824134)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1761643165.305600][4889:4891] CHIP:EM: Found matching exchange: 23470i, Delegate: 0x78ee4000d7e8
[1761643165.305609][4889:4891] CHIP:EM: CHIP MessageCounter:92824134 not in RetransTable on exchange 23470i
[1761643165.305626][4889:4891] CHIP:SC: Success status report received. Session was established
[1761643165.307434][4889:4891] CHIP:SC: SecureSession[0x78ee4000da90, LSID:19362]: State change 'kEstablishing' --> 'kActive'
[1761643165.307485][4889:4891] CHIP:IN: SecureSession[0x78ee4000da90]: Activated - Type:2 LSID:19362
[1761643165.307491][4889:4891] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:19362 PSID:29402!
[1761643165.307497][4889:4891] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1761643165.307519][4889:4891] CHIP:TOO: Sending ReadAttribute to:
[1761643165.307548][4889:4891] CHIP:TOO: 	cluster 0x0000_001D, attribute: 0x0000_0001, endpoint 1
[1761643165.307559][4889:4891] CHIP:DMG: SendReadRequest ReadClient[0x78ee4000a6c0]: Sending Read Request
[1761643165.307603][4889:4891] CHIP:EM: <<< [E:23471i S:19362 M:89598483] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0001:02 (IM:ReadRequest)
[1761643165.307663][4889:4891] CHIP:DMG: MoveToState ReadClient[0x78ee4000a6c0]: Moving to [AwaitingIn]
[1761643165.307675][4889:4891] CHIP:EM: <<< [E:23470i S:0 M:92824135 (Ack:78814390)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643165.307688][4889:4891] CHIP:EM: Flushed pending ack for MessageCounter:78814390 on exchange 23470i
[1761643165.462810][4889:4891] CHIP:EM: >>> [E:23471i S:19362 M:25620891 (Ack:89598483)] (S) Msg RX from 1:0000000000000001 [6A6C] --- Type 0001:05 (IM:ReportData)
[1761643165.462832][4889:4891] CHIP:EM: Found matching exchange: 23471i, Delegate: 0x78ee4000a6d0
[1761643165.462840][4889:4891] CHIP:EM: Rxd Ack; Removing MessageCounter:89598483 from Retrans Table on exchange 23471i
[1761643165.462862][4889:4891] CHIP:DMG: ReportDataMessage =
[1761643165.462865][4889:4891] CHIP:DMG: {
[1761643165.462868][4889:4891] CHIP:DMG: 	AttributeReportIBs =
[1761643165.462873][4889:4891] CHIP:DMG: 	[
[1761643165.462876][4889:4891] CHIP:DMG: 		AttributeReportIB =
[1761643165.462881][4889:4891] CHIP:DMG: 		{
[1761643165.462885][4889:4891] CHIP:DMG: 			AttributeDataIB =
[1761643165.462889][4889:4891] CHIP:DMG: 			{
[1761643165.462894][4889:4891] CHIP:DMG: 				DataVersion = 0x161c6ea4,
[1761643165.462898][4889:4891] CHIP:DMG: 				AttributePathIB =
[1761643165.462902][4889:4891] CHIP:DMG: 				{
[1761643165.462907][4889:4891] CHIP:DMG: 					Endpoint = 0x1,
[1761643165.462911][4889:4891] CHIP:DMG: 					Cluster = 0x1d,
[1761643165.462915][4889:4891] CHIP:DMG: 					Attribute = 0x0000_0001,
[1761643165.462919][4889:4891] CHIP:DMG: 				}
[1761643165.462923][4889:4891] CHIP:DMG: 					
[1761643165.462927][4889:4891] CHIP:DMG: 				Data = [
[1761643165.462933][4889:4891] CHIP:DMG: 						3 (unsigned), 4 (unsigned), 6 (unsigned), 8 (unsigned), 29 (unsigned), 98 (unsigned), 
[1761643165.462938][4889:4891] CHIP:DMG: 				],
[1761643165.462942][4889:4891] CHIP:DMG: 			},
[1761643165.462947][4889:4891] CHIP:DMG: 			
[1761643165.462950][4889:4891] CHIP:DMG: 		},
[1761643165.462955][4889:4891] CHIP:DMG: 		
[1761643165.462957][4889:4891] CHIP:DMG: 	],
[1761643165.462962][4889:4891] CHIP:DMG: 	
[1761643165.462966][4889:4891] CHIP:DMG: 	SuppressResponse = true, 
[1761643165.462969][4889:4891] CHIP:DMG: 	InteractionModelRevision = 12
[1761643165.462972][4889:4891] CHIP:DMG: }
[1761643165.463044][4889:4891] CHIP:TOO: Endpoint: 1 Cluster: 0x0000_001D Attribute 0x0000_0001 DataVersion: 370962084
[1761643165.463067][4889:4891] CHIP:TOO:   ServerList: 6 entries
[1761643165.463078][4889:4891] CHIP:TOO:     [1]: 3
[1761643165.463081][4889:4891] CHIP:TOO:     [2]: 4
[1761643165.463084][4889:4891] CHIP:TOO:     [3]: 6
[1761643165.463087][4889:4891] CHIP:TOO:     [4]: 8
[1761643165.463098][4889:4891] CHIP:TOO:     [5]: 29
[1761643165.463101][4889:4891] CHIP:TOO:     [6]: 98
[1761643165.463144][4889:4891] CHIP:EM: <<< [E:23471i S:19362 M:89598484 (Ack:25620891)] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643165.463184][4889:4891] CHIP:EM: Flushed pending ack for MessageCounter:25620891 on exchange 23471i
[1761643165.463976][4889:4889] CHIP:CTL: Shutting down the commissioner
[1761643165.464046][4889:4889] CHIP:CTL: Shutting down the controller
[1761643165.464112][4889:4889] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1761643165.464166][4889:4889] CHIP:IN: SecureSession[0x78ee4000da90]: MarkForEviction Type:2 LSID:19362
[1761643165.464232][4889:4889] CHIP:SC: SecureSession[0x78ee4000da90, LSID:19362]: State change 'kActive' --> 'kPendingEviction'
[1761643165.464249][4889:4889] CHIP:IN: SecureSession[0x78ee4000da90]: Released - Type:2 LSID:19362
[1761643165.464266][4889:4889] CHIP:FP: Forgetting fabric 0x1
[1761643165.464284][4889:4889] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761643165.464335][4889:4889] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761643165.464391][4889:4889] CHIP:TS: Reverted Last Known Good Time to previous value
[1761643165.464437][4889:4889] CHIP:CTL: Shutting down the commissioner
[1761643165.464489][4889:4889] CHIP:CTL: Shutting down the controller
[1761643165.464524][4889:4889] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1761643165.464647][4889:4889] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1761643165.464756][4889:4889] CHIP:FP: Shutting down FabricTable
[1761643165.464813][4889:4889] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761643165.464881][4889:4889] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761643165.464935][4889:4889] CHIP:TS: Reverted Last Known Good Time to previous value
[1761643165.465064][4889:4889] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-R9A5Rt)
[1761643165.465558][4889:4889] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761643165.465655][4889:4889] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1761643165.465693][4889:4889] CHIP:DL: Inet Layer shutdown
[1761643165.465874][4889:4889] CHIP:DL: BLE shutdown
[1761643165.471379][4889:4889] CHIP:DL: System Layer shutdown
vboxuser@Ubuntu-Thread:~/connectedhomeip$ ./out/debug/chip-tool descriptor read server-list 1 2
[1761643172.339194][4892:4892] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1761643172.339748][4892:4892] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1761643172.339977][4892:4892] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1761643172.341442][4892:4892] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1761643172.341735][4892:4892] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1761643172.341815][4892:4892] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1761643172.341975][4892:4892] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-ENFoqe)
[1761643172.342599][4892:4892] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761643172.342622][4892:4892] CHIP:DL: NVS set: chip-counters/reboot-count = 6 (0x6)
[1761643172.342901][4892:4892] CHIP:DL: Got Ethernet interface: enp0s3
[1761643172.343119][4892:4892] CHIP:DL: Found the primary Ethernet interface:enp0s3
[1761643172.343886][4892:4892] CHIP:DL: Failed to get WiFi interface
[1761643172.343941][4892:4892] CHIP:DL: Failed to reset WiFi statistic counts
[1761643172.343966][4892:4892] CHIP:IN: UDP::Init bind&listen port=0
[1761643172.343997][4892:4892] CHIP:IN: UDP::Init bound to port=52702
[1761643172.344052][4892:4892] CHIP:IN: UDP::Init bind&listen port=0
[1761643172.344080][4892:4892] CHIP:IN: UDP::Init bound to port=57232
[1761643172.344083][4892:4892] CHIP:IN: BLEBase::Init - setting/overriding transport
[1761643172.344086][4892:4892] CHIP:IN: TransportMgr initialized
[1761643172.344098][4892:4892] CHIP:FP: Initializing FabricTable from persistent storage
[1761643172.344149][4892:4892] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761643172.344695][4892:4892] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xC0157AA7F5726A6C, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1761643172.345952][4892:4892] CHIP:ZCL: Using ZAP configuration...
[1761643172.347205][4892:4892] CHIP:CTL: System State Initialized...
[1761643172.347447][4892:4892] CHIP:CTL: Setting attestation nonce to random value
[1761643172.347506][4892:4892] CHIP:CTL: Setting CSR nonce to random value
[1761643172.347651][4892:4894] CHIP:DL: CHIP task running
[1761643172.347719][4892:4894] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1761643172.347804][4892:4894] CHIP:CTL: Setting attestation nonce to random value
[1761643172.347879][4892:4894] CHIP:CTL: Setting CSR nonce to random value
[1761643172.348103][4892:4894] CHIP:CTL: Generating NOC
[1761643172.348483][4892:4894] CHIP:FP: Validating NOC chain
[1761643172.348877][4892:4894] CHIP:FP: NOC chain validation successful
[1761643172.348968][4892:4894] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1761643172.348976][4892:4894] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761643172.348979][4892:4894] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1761643172.348982][4892:4894] CHIP:TS: Retaining current Last Known Good Time
[1761643172.352400][4892:4894] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1761643172.357237][4892:4894] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1761643172.358460][4892:4894] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: C0157AA7F5726A6C)
[1761643172.374004][4892:4894] CHIP:TOO: Sending command to node 0x1
[1761643172.374242][4892:4894] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1761643172.374266][4892:4894] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1761643172.374291][4892:4894] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1761643172.376847][4892:4894] CHIP:DIS: Lookup clearing interface for non LL address
[1761643172.376890][4892:4894] CHIP:DIS: UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895%enp0s3]:5540: new best score: 5
[1761643172.376905][4892:4894] CHIP:DIS: Checking node lookup status after 2 ms
[1761643172.376919][4892:4894] CHIP:DIS: Keeping DNSSD lookup active
[1761643172.575417][4892:4894] CHIP:DIS: Checking node lookup status after 201 ms
[1761643172.575505][4892:4894] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540 while in state 2
[1761643172.575512][4892:4894] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1761643172.575591][4892:4894] CHIP:IN: SecureSession[0x7c291400da90]: Allocated Type:2 LSID:45927
[1761643172.575601][4892:4894] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1761643172.575904][4892:4894] CHIP:EM: <<< [E:1599i S:0 M:212535057] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1761643172.576057][4892:4894] CHIP:SC: Sent Sigma1 msg
[1761643172.576112][4892:4894] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1761643172.681207][4892:4894] CHIP:EM: >>> [E:1599i S:0 M:78814391 (Ack:212535057)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643172.681442][4892:4894] CHIP:EM: Found matching exchange: 1599i, Delegate: 0x7c291400d7e8
[1761643172.681473][4892:4894] CHIP:EM: Rxd Ack; Removing MessageCounter:212535057 from Retrans Table on exchange 1599i
[1761643172.859723][4892:4894] CHIP:EM: >>> [E:1599i S:0 M:78814392 (Ack:212535057)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1761643172.859797][4892:4894] CHIP:EM: Found matching exchange: 1599i, Delegate: 0x7c291400d7e8
[1761643172.859805][4892:4894] CHIP:EM: CHIP MessageCounter:212535057 not in RetransTable on exchange 1599i
[1761643172.859820][4892:4894] CHIP:SC: Received Sigma2 msg
[1761643172.859831][4892:4894] CHIP:SC: Peer assigned session session ID 29403
[1761643172.860676][4892:4894] CHIP:SC: Found MRP parameters in the message
[1761643172.860709][4892:4894] CHIP:SC: Sending Sigma3
[1761643172.860844][4892:4894] CHIP:EM: <<< [E:1599i S:0 M:212535058 (Ack:78814392)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1761643172.860919][4892:4894] CHIP:SC: Sent Sigma3 msg
[1761643173.016413][4892:4894] CHIP:EM: >>> [E:1599i S:0 M:78814393 (Ack:212535058)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643173.016482][4892:4894] CHIP:EM: Found matching exchange: 1599i, Delegate: 0x7c291400d7e8
[1761643173.016497][4892:4894] CHIP:EM: Rxd Ack; Removing MessageCounter:212535058 from Retrans Table on exchange 1599i
[1761643173.335322][4892:4894] CHIP:EM: >>> [E:1599i S:0 M:78814394 (Ack:212535058)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1761643173.335344][4892:4894] CHIP:EM: Found matching exchange: 1599i, Delegate: 0x7c291400d7e8
[1761643173.335349][4892:4894] CHIP:EM: CHIP MessageCounter:212535058 not in RetransTable on exchange 1599i
[1761643173.335364][4892:4894] CHIP:SC: Success status report received. Session was established
[1761643173.337483][4892:4894] CHIP:SC: SecureSession[0x7c291400da90, LSID:45927]: State change 'kEstablishing' --> 'kActive'
[1761643173.337683][4892:4894] CHIP:IN: SecureSession[0x7c291400da90]: Activated - Type:2 LSID:45927
[1761643173.337691][4892:4894] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:45927 PSID:29403!
[1761643173.337697][4892:4894] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1761643173.337719][4892:4894] CHIP:TOO: Sending ReadAttribute to:
[1761643173.337750][4892:4894] CHIP:TOO: 	cluster 0x0000_001D, attribute: 0x0000_0001, endpoint 2
[1761643173.337760][4892:4894] CHIP:DMG: SendReadRequest ReadClient[0x7c291400a6c0]: Sending Read Request
[1761643173.337808][4892:4894] CHIP:EM: <<< [E:1600i S:45927 M:159605889] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0001:02 (IM:ReadRequest)
[1761643173.338158][4892:4894] CHIP:DMG: MoveToState ReadClient[0x7c291400a6c0]: Moving to [AwaitingIn]
[1761643173.338194][4892:4894] CHIP:EM: <<< [E:1599i S:0 M:212535059 (Ack:78814394)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643173.338229][4892:4894] CHIP:EM: Flushed pending ack for MessageCounter:78814394 on exchange 1599i
[1761643173.487921][4892:4894] CHIP:EM: >>> [E:1600i S:45927 M:134764318 (Ack:159605889)] (S) Msg RX from 1:0000000000000001 [6A6C] --- Type 0001:05 (IM:ReportData)
[1761643173.487993][4892:4894] CHIP:EM: Found matching exchange: 1600i, Delegate: 0x7c291400a6d0
[1761643173.488007][4892:4894] CHIP:EM: Rxd Ack; Removing MessageCounter:159605889 from Retrans Table on exchange 1600i
[1761643173.488028][4892:4894] CHIP:DMG: ReportDataMessage =
[1761643173.488032][4892:4894] CHIP:DMG: {
[1761643173.488035][4892:4894] CHIP:DMG: 	AttributeReportIBs =
[1761643173.488040][4892:4894] CHIP:DMG: 	[
[1761643173.488043][4892:4894] CHIP:DMG: 		AttributeReportIB =
[1761643173.488048][4892:4894] CHIP:DMG: 		{
[1761643173.488051][4892:4894] CHIP:DMG: 			AttributeDataIB =
[1761643173.488056][4892:4894] CHIP:DMG: 			{
[1761643173.488060][4892:4894] CHIP:DMG: 				DataVersion = 0x9d701958,
[1761643173.488064][4892:4894] CHIP:DMG: 				AttributePathIB =
[1761643173.488068][4892:4894] CHIP:DMG: 				{
[1761643173.488073][4892:4894] CHIP:DMG: 					Endpoint = 0x2,
[1761643173.488077][4892:4894] CHIP:DMG: 					Cluster = 0x1d,
[1761643173.488081][4892:4894] CHIP:DMG: 					Attribute = 0x0000_0001,
[1761643173.488085][4892:4894] CHIP:DMG: 				}
[1761643173.488090][4892:4894] CHIP:DMG: 					
[1761643173.488094][4892:4894] CHIP:DMG: 				Data = [
[1761643173.488099][4892:4894] CHIP:DMG: 						29 (unsigned), 144 (unsigned), 145 (unsigned), 156 (unsigned), 
[1761643173.488104][4892:4894] CHIP:DMG: 				],
[1761643173.488108][4892:4894] CHIP:DMG: 			},
[1761643173.488113][4892:4894] CHIP:DMG: 			
[1761643173.488133][4892:4894] CHIP:DMG: 		},
[1761643173.488138][4892:4894] CHIP:DMG: 		
[1761643173.488141][4892:4894] CHIP:DMG: 	],
[1761643173.488146][4892:4894] CHIP:DMG: 	
[1761643173.488149][4892:4894] CHIP:DMG: 	SuppressResponse = true, 
[1761643173.488152][4892:4894] CHIP:DMG: 	InteractionModelRevision = 12
[1761643173.488155][4892:4894] CHIP:DMG: }
[1761643173.488227][4892:4894] CHIP:TOO: Endpoint: 2 Cluster: 0x0000_001D Attribute 0x0000_0001 DataVersion: 2641369432
[1761643173.488426][4892:4894] CHIP:TOO:   ServerList: 4 entries
[1761643173.488450][4892:4894] CHIP:TOO:     [1]: 29
[1761643173.488453][4892:4894] CHIP:TOO:     [2]: 144
[1761643173.488456][4892:4894] CHIP:TOO:     [3]: 145
[1761643173.488459][4892:4894] CHIP:TOO:     [4]: 156
[1761643173.488558][4892:4894] CHIP:EM: <<< [E:1600i S:45927 M:159605890 (Ack:134764318)] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643173.488636][4892:4894] CHIP:EM: Flushed pending ack for MessageCounter:134764318 on exchange 1600i
[1761643173.488762][4892:4892] CHIP:CTL: Shutting down the commissioner
[1761643173.488771][4892:4892] CHIP:CTL: Shutting down the controller
[1761643173.488788][4892:4892] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1761643173.488791][4892:4892] CHIP:IN: SecureSession[0x7c291400da90]: MarkForEviction Type:2 LSID:45927
[1761643173.488794][4892:4892] CHIP:SC: SecureSession[0x7c291400da90, LSID:45927]: State change 'kActive' --> 'kPendingEviction'
[1761643173.488797][4892:4892] CHIP:IN: SecureSession[0x7c291400da90]: Released - Type:2 LSID:45927
[1761643173.488802][4892:4892] CHIP:FP: Forgetting fabric 0x1
[1761643173.488808][4892:4892] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761643173.488847][4892:4892] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761643173.488850][4892:4892] CHIP:TS: Reverted Last Known Good Time to previous value
[1761643173.488862][4892:4892] CHIP:CTL: Shutting down the commissioner
[1761643173.488865][4892:4892] CHIP:CTL: Shutting down the controller
[1761643173.488868][4892:4892] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1761643173.488957][4892:4892] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1761643173.488981][4892:4892] CHIP:FP: Shutting down FabricTable
[1761643173.488984][4892:4892] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761643173.489000][4892:4892] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761643173.489002][4892:4892] CHIP:TS: Reverted Last Known Good Time to previous value
[1761643173.489096][4892:4892] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-jjQjPU)
[1761643173.489687][4892:4892] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761643173.489702][4892:4892] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1761643173.489705][4892:4892] CHIP:DL: Inet Layer shutdown
[1761643173.489708][4892:4892] CHIP:DL: BLE shutdown
[1761643173.490145][4892:4892] CHIP:DL: System Layer shutdown
vboxuser@Ubuntu-Thread:~/connectedhomeip$ ./out/debug/chip-tool electricalpowermeasurement read attribute-list 1 2
[1761643461.665516][4910:4910] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1761643461.666379][4910:4910] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1761643461.666597][4910:4910] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1761643461.668090][4910:4910] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1761643461.668364][4910:4910] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1761643461.668383][4910:4910] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1761643461.668507][4910:4910] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-dc2Ehg)
[1761643461.668836][4910:4910] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761643461.668896][4910:4910] CHIP:DL: NVS set: chip-counters/reboot-count = 7 (0x7)
[1761643461.669384][4910:4910] CHIP:DL: Got Ethernet interface: enp0s3
[1761643461.669605][4910:4910] CHIP:DL: Found the primary Ethernet interface:enp0s3
[1761643461.670415][4910:4910] CHIP:DL: Failed to get WiFi interface
[1761643461.670426][4910:4910] CHIP:DL: Failed to reset WiFi statistic counts
[1761643461.670441][4910:4910] CHIP:IN: UDP::Init bind&listen port=0
[1761643461.670471][4910:4910] CHIP:IN: UDP::Init bound to port=42216
[1761643461.670475][4910:4910] CHIP:IN: UDP::Init bind&listen port=0
[1761643461.670491][4910:4910] CHIP:IN: UDP::Init bound to port=50238
[1761643461.670543][4910:4910] CHIP:IN: BLEBase::Init - setting/overriding transport
[1761643461.670549][4910:4910] CHIP:IN: TransportMgr initialized
[1761643461.670572][4910:4910] CHIP:FP: Initializing FabricTable from persistent storage
[1761643461.670612][4910:4910] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761643461.670993][4910:4910] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xC0157AA7F5726A6C, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1761643461.672692][4910:4910] CHIP:ZCL: Using ZAP configuration...
[1761643461.674084][4910:4910] CHIP:CTL: System State Initialized...
[1761643461.674170][4910:4910] CHIP:CTL: Setting attestation nonce to random value
[1761643461.674178][4910:4910] CHIP:CTL: Setting CSR nonce to random value
[1761643461.674532][4910:4912] CHIP:DL: CHIP task running
[1761643461.674617][4910:4912] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1761643461.674737][4910:4912] CHIP:CTL: Setting attestation nonce to random value
[1761643461.677329][4910:4912] CHIP:CTL: Setting CSR nonce to random value
[1761643461.678011][4910:4912] CHIP:CTL: Generating NOC
[1761643461.678306][4910:4912] CHIP:FP: Validating NOC chain
[1761643461.679680][4910:4912] CHIP:FP: NOC chain validation successful
[1761643461.679746][4910:4912] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1761643461.679753][4910:4912] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761643461.679756][4910:4912] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1761643461.679759][4910:4912] CHIP:TS: Retaining current Last Known Good Time
[1761643461.684180][4910:4912] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1761643461.685538][4910:4912] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1761643461.686438][4910:4912] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: C0157AA7F5726A6C)
[1761643461.691587][4910:4912] CHIP:TOO: Sending command to node 0x1
[1761643461.691802][4910:4912] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1761643461.691809][4910:4912] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1761643461.691820][4910:4912] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1761643461.694439][4910:4912] CHIP:DIS: Lookup clearing interface for non LL address
[1761643461.694758][4910:4912] CHIP:DIS: UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895%enp0s3]:5540: new best score: 5
[1761643461.694764][4910:4912] CHIP:DIS: Checking node lookup status after 3 ms
[1761643461.694767][4910:4912] CHIP:DIS: Keeping DNSSD lookup active
[1761643461.892950][4910:4912] CHIP:DIS: Checking node lookup status after 201 ms
[1761643461.893036][4910:4912] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540 while in state 2
[1761643461.893043][4910:4912] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1761643461.893124][4910:4912] CHIP:IN: SecureSession[0x7f91e800da90]: Allocated Type:2 LSID:28933
[1761643461.893135][4910:4912] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1761643461.893578][4910:4912] CHIP:EM: <<< [E:8106i S:0 M:241010323] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1761643461.893718][4910:4912] CHIP:SC: Sent Sigma1 msg
[1761643461.893772][4910:4912] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1761643462.000549][4910:4912] CHIP:EM: >>> [E:8106i S:0 M:78814395 (Ack:241010323)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643462.000621][4910:4912] CHIP:EM: Found matching exchange: 8106i, Delegate: 0x7f91e800d7e8
[1761643462.000635][4910:4912] CHIP:EM: Rxd Ack; Removing MessageCounter:241010323 from Retrans Table on exchange 8106i
[1761643462.177942][4910:4912] CHIP:EM: >>> [E:8106i S:0 M:78814396 (Ack:241010323)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1761643462.177966][4910:4912] CHIP:EM: Found matching exchange: 8106i, Delegate: 0x7f91e800d7e8
[1761643462.177971][4910:4912] CHIP:EM: CHIP MessageCounter:241010323 not in RetransTable on exchange 8106i
[1761643462.177986][4910:4912] CHIP:SC: Received Sigma2 msg
[1761643462.178386][4910:4912] CHIP:SC: Peer assigned session session ID 29404
[1761643462.179264][4910:4912] CHIP:SC: Found MRP parameters in the message
[1761643462.179467][4910:4912] CHIP:SC: Sending Sigma3
[1761643462.179596][4910:4912] CHIP:EM: <<< [E:8106i S:0 M:241010324 (Ack:78814396)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1761643462.179712][4910:4912] CHIP:SC: Sent Sigma3 msg
[1761643462.339777][4910:4912] CHIP:EM: >>> [E:8106i S:0 M:78814397 (Ack:241010324)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643462.339799][4910:4912] CHIP:EM: Found matching exchange: 8106i, Delegate: 0x7f91e800d7e8
[1761643462.339810][4910:4912] CHIP:EM: Rxd Ack; Removing MessageCounter:241010324 from Retrans Table on exchange 8106i
[1761643462.662885][4910:4912] CHIP:EM: >>> [E:8106i S:0 M:78814398 (Ack:241010324)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1761643462.662954][4910:4912] CHIP:EM: Found matching exchange: 8106i, Delegate: 0x7f91e800d7e8
[1761643462.662962][4910:4912] CHIP:EM: CHIP MessageCounter:241010324 not in RetransTable on exchange 8106i
[1761643462.662979][4910:4912] CHIP:SC: Success status report received. Session was established
[1761643462.664562][4910:4912] CHIP:SC: SecureSession[0x7f91e800da90, LSID:28933]: State change 'kEstablishing' --> 'kActive'
[1761643462.664584][4910:4912] CHIP:IN: SecureSession[0x7f91e800da90]: Activated - Type:2 LSID:28933
[1761643462.664598][4910:4912] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:28933 PSID:29404!
[1761643462.664615][4910:4912] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1761643462.664647][4910:4912] CHIP:TOO: Sending ReadAttribute to:
[1761643462.664696][4910:4912] CHIP:TOO: 	cluster 0x0000_0090, attribute: 0x0000_FFFB, endpoint 2
[1761643462.664730][4910:4912] CHIP:DMG: SendReadRequest ReadClient[0x7f91e800a6c0]: Sending Read Request
[1761643462.664786][4910:4912] CHIP:EM: <<< [E:8107i S:28933 M:260624025] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0001:02 (IM:ReadRequest)
[1761643462.664856][4910:4912] CHIP:DMG: MoveToState ReadClient[0x7f91e800a6c0]: Moving to [AwaitingIn]
[1761643462.665115][4910:4912] CHIP:EM: <<< [E:8106i S:0 M:241010325 (Ack:78814398)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643462.665139][4910:4912] CHIP:EM: Flushed pending ack for MessageCounter:78814398 on exchange 8106i
[1761643462.819529][4910:4912] CHIP:EM: >>> [E:8107i S:28933 M:79169901 (Ack:260624025)] (S) Msg RX from 1:0000000000000001 [6A6C] --- Type 0001:05 (IM:ReportData)
[1761643462.819569][4910:4912] CHIP:EM: Found matching exchange: 8107i, Delegate: 0x7f91e800a6d0
[1761643462.819589][4910:4912] CHIP:EM: Rxd Ack; Removing MessageCounter:260624025 from Retrans Table on exchange 8107i
[1761643462.819624][4910:4912] CHIP:DMG: ReportDataMessage =
[1761643462.819640][4910:4912] CHIP:DMG: {
[1761643462.819654][4910:4912] CHIP:DMG: 	AttributeReportIBs =
[1761643462.819681][4910:4912] CHIP:DMG: 	[
[1761643462.819706][4910:4912] CHIP:DMG: 		AttributeReportIB =
[1761643462.819739][4910:4912] CHIP:DMG: 		{
[1761643462.819769][4910:4912] CHIP:DMG: 			AttributeDataIB =
[1761643462.819806][4910:4912] CHIP:DMG: 			{
[1761643462.819841][4910:4912] CHIP:DMG: 				DataVersion = 0xb9479069,
[1761643462.819867][4910:4912] CHIP:DMG: 				AttributePathIB =
[1761643462.819872][4910:4912] CHIP:DMG: 				{
[1761643462.819876][4910:4912] CHIP:DMG: 					Endpoint = 0x2,
[1761643462.819880][4910:4912] CHIP:DMG: 					Cluster = 0x90,
[1761643462.819885][4910:4912] CHIP:DMG: 					Attribute = 0x0000_FFFB,
[1761643462.819889][4910:4912] CHIP:DMG: 				}
[1761643462.819893][4910:4912] CHIP:DMG: 					
[1761643462.819897][4910:4912] CHIP:DMG: 				Data = [
[1761643462.819904][4910:4912] CHIP:DMG: 						0 (unsigned), 1 (unsigned), 2 (unsigned), 4 (unsigned), 5 (unsigned), 8 (unsigned), 65532 (unsigned), 65533 (unsigned), 65528 (unsigned), 65529 (unsigned), 65531 (unsigned), 
[1761643462.819910][4910:4912] CHIP:DMG: 				],
[1761643462.819914][4910:4912] CHIP:DMG: 			},
[1761643462.819919][4910:4912] CHIP:DMG: 			
[1761643462.819922][4910:4912] CHIP:DMG: 		},
[1761643462.819927][4910:4912] CHIP:DMG: 		
[1761643462.819930][4910:4912] CHIP:DMG: 	],
[1761643462.819936][4910:4912] CHIP:DMG: 	
[1761643462.819939][4910:4912] CHIP:DMG: 	SuppressResponse = true, 
[1761643462.819942][4910:4912] CHIP:DMG: 	InteractionModelRevision = 12
[1761643462.819945][4910:4912] CHIP:DMG: }
[1761643462.820037][4910:4912] CHIP:TOO: Endpoint: 2 Cluster: 0x0000_0090 Attribute 0x0000_FFFB DataVersion: 3108474985
[1761643462.822742][4910:4912] CHIP:TOO:   AttributeList: 11 entries
[1761643462.823598][4910:4912] CHIP:TOO:     [1]: 0
[1761643462.823679][4910:4912] CHIP:TOO:     [2]: 1
[1761643462.823717][4910:4912] CHIP:TOO:     [3]: 2
[1761643462.823752][4910:4912] CHIP:TOO:     [4]: 4
[1761643462.823785][4910:4912] CHIP:TOO:     [5]: 5
[1761643462.823801][4910:4912] CHIP:TOO:     [6]: 8
[1761643462.823834][4910:4912] CHIP:TOO:     [7]: 65532
[1761643462.823850][4910:4912] CHIP:TOO:     [8]: 65533
[1761643462.823883][4910:4912] CHIP:TOO:     [9]: 65528
[1761643462.823899][4910:4912] CHIP:TOO:     [10]: 65529
[1761643462.823932][4910:4912] CHIP:TOO:     [11]: 65531
[1761643462.824076][4910:4912] CHIP:EM: <<< [E:8107i S:28933 M:260624026 (Ack:79169901)] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643462.825623][4910:4912] CHIP:EM: Flushed pending ack for MessageCounter:79169901 on exchange 8107i
[1761643462.825751][4910:4910] CHIP:CTL: Shutting down the commissioner
[1761643462.825773][4910:4910] CHIP:CTL: Shutting down the controller
[1761643462.825798][4910:4910] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1761643462.825813][4910:4910] CHIP:IN: SecureSession[0x7f91e800da90]: MarkForEviction Type:2 LSID:28933
[1761643462.825828][4910:4910] CHIP:SC: SecureSession[0x7f91e800da90, LSID:28933]: State change 'kActive' --> 'kPendingEviction'
[1761643462.825842][4910:4910] CHIP:IN: SecureSession[0x7f91e800da90]: Released - Type:2 LSID:28933
[1761643462.825859][4910:4910] CHIP:FP: Forgetting fabric 0x1
[1761643462.825877][4910:4910] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761643462.825929][4910:4910] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761643462.825944][4910:4910] CHIP:TS: Reverted Last Known Good Time to previous value
[1761643462.825967][4910:4910] CHIP:CTL: Shutting down the commissioner
[1761643462.825981][4910:4910] CHIP:CTL: Shutting down the controller
[1761643462.825995][4910:4910] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1761643462.826101][4910:4910] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1761643462.826189][4910:4910] CHIP:FP: Shutting down FabricTable
[1761643462.826229][4910:4910] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761643462.826277][4910:4910] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761643462.826311][4910:4910] CHIP:TS: Reverted Last Known Good Time to previous value
[1761643462.826714][4910:4910] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-E7KMW1)
[1761643462.827079][4910:4910] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761643462.827164][4910:4910] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1761643462.827251][4910:4910] CHIP:DL: Inet Layer shutdown
[1761643462.827308][4910:4910] CHIP:DL: BLE shutdown
[1761643462.827642][4910:4910] CHIP:DL: System Layer shutdown
vboxuser@Ubuntu-Thread:~/connectedhomeip$ ./out/debug/chip-tool electricalpowermeasurement read cluster-revision 1 2
[1761643469.408463][4913:4913] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1761643469.409048][4913:4913] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1761643469.409104][4913:4913] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1761643469.410601][4913:4913] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1761643469.410915][4913:4913] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1761643469.410994][4913:4913] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1761643469.411143][4913:4913] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-tUHXOr)
[1761643469.411652][4913:4913] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761643469.411730][4913:4913] CHIP:DL: NVS set: chip-counters/reboot-count = 8 (0x8)
[1761643469.411993][4913:4913] CHIP:DL: Got Ethernet interface: enp0s3
[1761643469.412357][4913:4913] CHIP:DL: Found the primary Ethernet interface:enp0s3
[1761643469.412968][4913:4913] CHIP:DL: Failed to get WiFi interface
[1761643469.413025][4913:4913] CHIP:DL: Failed to reset WiFi statistic counts
[1761643469.413043][4913:4913] CHIP:IN: UDP::Init bind&listen port=0
[1761643469.413079][4913:4913] CHIP:IN: UDP::Init bound to port=45350
[1761643469.413082][4913:4913] CHIP:IN: UDP::Init bind&listen port=0
[1761643469.413304][4913:4913] CHIP:IN: UDP::Init bound to port=33719
[1761643469.413310][4913:4913] CHIP:IN: BLEBase::Init - setting/overriding transport
[1761643469.413313][4913:4913] CHIP:IN: TransportMgr initialized
[1761643469.413333][4913:4913] CHIP:FP: Initializing FabricTable from persistent storage
[1761643469.413371][4913:4913] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761643469.413822][4913:4913] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xC0157AA7F5726A6C, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1761643469.414743][4913:4913] CHIP:ZCL: Using ZAP configuration...
[1761643469.416038][4913:4913] CHIP:CTL: System State Initialized...
[1761643469.416160][4913:4913] CHIP:CTL: Setting attestation nonce to random value
[1761643469.416414][4913:4913] CHIP:CTL: Setting CSR nonce to random value
[1761643469.419285][4913:4915] CHIP:DL: CHIP task running
[1761643469.419332][4913:4915] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1761643469.419645][4913:4915] CHIP:CTL: Setting attestation nonce to random value
[1761643469.419818][4913:4915] CHIP:CTL: Setting CSR nonce to random value
[1761643469.420063][4913:4915] CHIP:CTL: Generating NOC
[1761643469.422549][4913:4915] CHIP:FP: Validating NOC chain
[1761643469.423026][4913:4915] CHIP:FP: NOC chain validation successful
[1761643469.423079][4913:4915] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1761643469.423098][4913:4915] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761643469.423113][4913:4915] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1761643469.423126][4913:4915] CHIP:TS: Retaining current Last Known Good Time
[1761643469.427293][4913:4915] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1761643469.428947][4913:4915] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1761643469.430209][4913:4915] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: C0157AA7F5726A6C)
[1761643469.440516][4913:4915] CHIP:TOO: Sending command to node 0x1
[1761643469.441096][4913:4915] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1761643469.441154][4913:4915] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1761643469.441183][4913:4915] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1761643469.443134][4913:4915] CHIP:DIS: Lookup clearing interface for non LL address
[1761643469.444141][4913:4915] CHIP:DIS: UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895%enp0s3]:5540: new best score: 5
[1761643469.444182][4913:4915] CHIP:DIS: Checking node lookup status after 3 ms
[1761643469.444198][4913:4915] CHIP:DIS: Keeping DNSSD lookup active
[1761643469.641583][4913:4915] CHIP:DIS: Checking node lookup status after 200 ms
[1761643469.641685][4913:4915] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540 while in state 2
[1761643469.641693][4913:4915] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1761643469.641771][4913:4915] CHIP:IN: SecureSession[0x785ee400da90]: Allocated Type:2 LSID:33572
[1761643469.641783][4913:4915] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1761643469.642094][4913:4915] CHIP:EM: <<< [E:7859i S:0 M:182313970] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1761643469.642379][4913:4915] CHIP:SC: Sent Sigma1 msg
[1761643469.642621][4913:4915] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1761643469.748786][4913:4915] CHIP:EM: >>> [E:7859i S:0 M:78814399 (Ack:182313970)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643469.748808][4913:4915] CHIP:EM: Found matching exchange: 7859i, Delegate: 0x785ee400d7e8
[1761643469.748819][4913:4915] CHIP:EM: Rxd Ack; Removing MessageCounter:182313970 from Retrans Table on exchange 7859i
[1761643469.923504][4913:4915] CHIP:EM: >>> [E:7859i S:0 M:78814400 (Ack:182313970)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1761643469.923574][4913:4915] CHIP:EM: Found matching exchange: 7859i, Delegate: 0x785ee400d7e8
[1761643469.923582][4913:4915] CHIP:EM: CHIP MessageCounter:182313970 not in RetransTable on exchange 7859i
[1761643469.923599][4913:4915] CHIP:SC: Received Sigma2 msg
[1761643469.923609][4913:4915] CHIP:SC: Peer assigned session session ID 29405
[1761643469.924451][4913:4915] CHIP:SC: Found MRP parameters in the message
[1761643469.924516][4913:4915] CHIP:SC: Sending Sigma3
[1761643469.924769][4913:4915] CHIP:EM: <<< [E:7859i S:0 M:182313971 (Ack:78814400)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1761643469.925114][4913:4915] CHIP:SC: Sent Sigma3 msg
[1761643470.083704][4913:4915] CHIP:EM: >>> [E:7859i S:0 M:78814401 (Ack:182313971)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643470.083774][4913:4915] CHIP:EM: Found matching exchange: 7859i, Delegate: 0x785ee400d7e8
[1761643470.083789][4913:4915] CHIP:EM: Rxd Ack; Removing MessageCounter:182313971 from Retrans Table on exchange 7859i
[1761643470.403430][4913:4915] CHIP:EM: >>> [E:7859i S:0 M:78814402 (Ack:182313971)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1761643470.403449][4913:4915] CHIP:EM: Found matching exchange: 7859i, Delegate: 0x785ee400d7e8
[1761643470.403454][4913:4915] CHIP:EM: CHIP MessageCounter:182313971 not in RetransTable on exchange 7859i
[1761643470.403470][4913:4915] CHIP:SC: Success status report received. Session was established
[1761643470.405442][4913:4915] CHIP:SC: SecureSession[0x785ee400da90, LSID:33572]: State change 'kEstablishing' --> 'kActive'
[1761643470.405494][4913:4915] CHIP:IN: SecureSession[0x785ee400da90]: Activated - Type:2 LSID:33572
[1761643470.405501][4913:4915] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:33572 PSID:29405!
[1761643470.405508][4913:4915] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1761643470.405545][4913:4915] CHIP:TOO: Sending ReadAttribute to:
[1761643470.405579][4913:4915] CHIP:TOO: 	cluster 0x0000_0090, attribute: 0x0000_FFFD, endpoint 2
[1761643470.405590][4913:4915] CHIP:DMG: SendReadRequest ReadClient[0x785ee400a6c0]: Sending Read Request
[1761643470.405636][4913:4915] CHIP:EM: <<< [E:7860i S:33572 M:251204743] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0001:02 (IM:ReadRequest)
[1761643470.406061][4913:4915] CHIP:DMG: MoveToState ReadClient[0x785ee400a6c0]: Moving to [AwaitingIn]
[1761643470.406133][4913:4915] CHIP:EM: <<< [E:7859i S:0 M:182313972 (Ack:78814402)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643470.406209][4913:4915] CHIP:EM: Flushed pending ack for MessageCounter:78814402 on exchange 7859i
[1761643470.555644][4913:4915] CHIP:EM: >>> [E:7860i S:33572 M:244966548 (Ack:251204743)] (S) Msg RX from 1:0000000000000001 [6A6C] --- Type 0001:05 (IM:ReportData)
[1761643470.555663][4913:4915] CHIP:EM: Found matching exchange: 7860i, Delegate: 0x785ee400a6d0
[1761643470.555672][4913:4915] CHIP:EM: Rxd Ack; Removing MessageCounter:251204743 from Retrans Table on exchange 7860i
[1761643470.555692][4913:4915] CHIP:DMG: ReportDataMessage =
[1761643470.555696][4913:4915] CHIP:DMG: {
[1761643470.555699][4913:4915] CHIP:DMG: 	AttributeReportIBs =
[1761643470.555704][4913:4915] CHIP:DMG: 	[
[1761643470.555707][4913:4915] CHIP:DMG: 		AttributeReportIB =
[1761643470.555711][4913:4915] CHIP:DMG: 		{
[1761643470.555715][4913:4915] CHIP:DMG: 			AttributeDataIB =
[1761643470.555817][4913:4915] CHIP:DMG: 			{
[1761643470.555857][4913:4915] CHIP:DMG: 				DataVersion = 0xb9479069,
[1761643470.555898][4913:4915] CHIP:DMG: 				AttributePathIB =
[1761643470.555985][4913:4915] CHIP:DMG: 				{
[1761643470.556034][4913:4915] CHIP:DMG: 					Endpoint = 0x2,
[1761643470.556081][4913:4915] CHIP:DMG: 					Cluster = 0x90,
[1761643470.556293][4913:4915] CHIP:DMG: 					Attribute = 0x0000_FFFD,
[1761643470.556346][4913:4915] CHIP:DMG: 				}
[1761643470.556389][4913:4915] CHIP:DMG: 					
[1761643470.556431][4913:4915] CHIP:DMG: 				Data = 3 (unsigned), 
[1761643470.556472][4913:4915] CHIP:DMG: 			},
[1761643470.556662][4913:4915] CHIP:DMG: 			
[1761643470.556694][4913:4915] CHIP:DMG: 		},
[1761643470.556724][4913:4915] CHIP:DMG: 		
[1761643470.556748][4913:4915] CHIP:DMG: 	],
[1761643470.556772][4913:4915] CHIP:DMG: 	
[1761643470.556810][4913:4915] CHIP:DMG: 	SuppressResponse = true, 
[1761643470.556818][4913:4915] CHIP:DMG: 	InteractionModelRevision = 12
[1761643470.556821][4913:4915] CHIP:DMG: }
[1761643470.556872][4913:4915] CHIP:TOO: Endpoint: 2 Cluster: 0x0000_0090 Attribute 0x0000_FFFD DataVersion: 3108474985
[1761643470.556899][4913:4915] CHIP:TOO:   ClusterRevision: 3
[1761643470.556949][4913:4915] CHIP:EM: <<< [E:7860i S:33572 M:251204744 (Ack:244966548)] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643470.557314][4913:4915] CHIP:EM: Flushed pending ack for MessageCounter:244966548 on exchange 7860i
[1761643470.557416][4913:4913] CHIP:CTL: Shutting down the commissioner
[1761643470.557435][4913:4913] CHIP:CTL: Shutting down the controller
[1761643470.557484][4913:4913] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1761643470.557500][4913:4913] CHIP:IN: SecureSession[0x785ee400da90]: MarkForEviction Type:2 LSID:33572
[1761643470.557514][4913:4913] CHIP:SC: SecureSession[0x785ee400da90, LSID:33572]: State change 'kActive' --> 'kPendingEviction'
[1761643470.557528][4913:4913] CHIP:IN: SecureSession[0x785ee400da90]: Released - Type:2 LSID:33572
[1761643470.557545][4913:4913] CHIP:FP: Forgetting fabric 0x1
[1761643470.557581][4913:4913] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761643470.557633][4913:4913] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761643470.557717][4913:4913] CHIP:TS: Reverted Last Known Good Time to previous value
[1761643470.557752][4913:4913] CHIP:CTL: Shutting down the commissioner
[1761643470.557800][4913:4913] CHIP:CTL: Shutting down the controller
[1761643470.557814][4913:4913] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1761643470.557915][4913:4913] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1761643470.557959][4913:4913] CHIP:FP: Shutting down FabricTable
[1761643470.557975][4913:4913] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761643470.558005][4913:4913] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761643470.558019][4913:4913] CHIP:TS: Reverted Last Known Good Time to previous value
[1761643470.558139][4913:4913] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-yCmyxX)
[1761643470.558655][4913:4913] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761643470.558687][4913:4913] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1761643470.558707][4913:4913] CHIP:DL: Inet Layer shutdown
[1761643470.558721][4913:4913] CHIP:DL: BLE shutdown
[1761643470.558771][4913:4913] CHIP:DL: System Layer shutdown
vboxuser@Ubuntu-Thread:~/connectedhomeip$ ./out/debug/chip-tool electricalpowermeasurement read active-power 1 2
[1761643482.190358][4916:4916] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1761643482.191139][4916:4916] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1761643482.191319][4916:4916] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1761643482.192813][4916:4916] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1761643482.193054][4916:4916] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1761643482.193135][4916:4916] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1761643482.193289][4916:4916] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-0YwvIJ)
[1761643482.193842][4916:4916] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761643482.193919][4916:4916] CHIP:DL: NVS set: chip-counters/reboot-count = 9 (0x9)
[1761643482.194355][4916:4916] CHIP:DL: Got Ethernet interface: enp0s3
[1761643482.194574][4916:4916] CHIP:DL: Found the primary Ethernet interface:enp0s3
[1761643482.195401][4916:4916] CHIP:DL: Failed to get WiFi interface
[1761643482.195455][4916:4916] CHIP:DL: Failed to reset WiFi statistic counts
[1761643482.195474][4916:4916] CHIP:IN: UDP::Init bind&listen port=0
[1761643482.195505][4916:4916] CHIP:IN: UDP::Init bound to port=36827
[1761643482.195509][4916:4916] CHIP:IN: UDP::Init bind&listen port=0
[1761643482.195525][4916:4916] CHIP:IN: UDP::Init bound to port=51665
[1761643482.195528][4916:4916] CHIP:IN: BLEBase::Init - setting/overriding transport
[1761643482.195582][4916:4916] CHIP:IN: TransportMgr initialized
[1761643482.195597][4916:4916] CHIP:FP: Initializing FabricTable from persistent storage
[1761643482.195646][4916:4916] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761643482.196039][4916:4916] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xC0157AA7F5726A6C, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1761643482.196920][4916:4916] CHIP:ZCL: Using ZAP configuration...
[1761643482.198261][4916:4916] CHIP:CTL: System State Initialized...
[1761643482.198600][4916:4916] CHIP:CTL: Setting attestation nonce to random value
[1761643482.204802][4916:4916] CHIP:CTL: Setting CSR nonce to random value
[1761643482.204962][4916:4918] CHIP:DL: CHIP task running
[1761643482.205256][4916:4918] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1761643482.205386][4916:4918] CHIP:CTL: Setting attestation nonce to random value
[1761643482.205808][4916:4918] CHIP:CTL: Setting CSR nonce to random value
[1761643482.206060][4916:4918] CHIP:CTL: Generating NOC
[1761643482.206351][4916:4918] CHIP:FP: Validating NOC chain
[1761643482.206706][4916:4918] CHIP:FP: NOC chain validation successful
[1761643482.206739][4916:4918] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1761643482.206744][4916:4918] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761643482.206747][4916:4918] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1761643482.206750][4916:4918] CHIP:TS: Retaining current Last Known Good Time
[1761643482.212277][4916:4918] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1761643482.213815][4916:4918] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1761643482.215113][4916:4918] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: C0157AA7F5726A6C)
[1761643482.232419][4916:4918] CHIP:TOO: Sending command to node 0x1
[1761643482.232684][4916:4918] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1761643482.232736][4916:4918] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1761643482.232761][4916:4918] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1761643482.235276][4916:4918] CHIP:DIS: Lookup clearing interface for non LL address
[1761643482.235366][4916:4918] CHIP:DIS: UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895%enp0s3]:5540: new best score: 5
[1761643482.235405][4916:4918] CHIP:DIS: Checking node lookup status after 3 ms
[1761643482.235439][4916:4918] CHIP:DIS: Keeping DNSSD lookup active
[1761643482.433330][4916:4918] CHIP:DIS: Checking node lookup status after 201 ms
[1761643482.433422][4916:4918] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540 while in state 2
[1761643482.433431][4916:4918] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1761643482.433511][4916:4918] CHIP:IN: SecureSession[0x72916c00da90]: Allocated Type:2 LSID:4391
[1761643482.433522][4916:4918] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1761643482.433813][4916:4918] CHIP:EM: <<< [E:11670i S:0 M:207834211] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1761643482.433941][4916:4918] CHIP:SC: Sent Sigma1 msg
[1761643482.433995][4916:4918] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1761643482.540613][4916:4918] CHIP:EM: >>> [E:11670i S:0 M:78814403 (Ack:207834211)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643482.540685][4916:4918] CHIP:EM: Found matching exchange: 11670i, Delegate: 0x72916c00d7e8
[1761643482.540698][4916:4918] CHIP:EM: Rxd Ack; Removing MessageCounter:207834211 from Retrans Table on exchange 11670i
[1761643482.716536][4916:4918] CHIP:EM: >>> [E:11670i S:0 M:78814404 (Ack:207834211)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1761643482.716602][4916:4918] CHIP:EM: Found matching exchange: 11670i, Delegate: 0x72916c00d7e8
[1761643482.716612][4916:4918] CHIP:EM: CHIP MessageCounter:207834211 not in RetransTable on exchange 11670i
[1761643482.716629][4916:4918] CHIP:SC: Received Sigma2 msg
[1761643482.716639][4916:4918] CHIP:SC: Peer assigned session session ID 29406
[1761643482.717699][4916:4918] CHIP:SC: Found MRP parameters in the message
[1761643482.717735][4916:4918] CHIP:SC: Sending Sigma3
[1761643482.717862][4916:4918] CHIP:EM: <<< [E:11670i S:0 M:207834212 (Ack:78814404)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1761643482.717936][4916:4918] CHIP:SC: Sent Sigma3 msg
[1761643482.882828][4916:4918] CHIP:EM: >>> [E:11670i S:0 M:78814405 (Ack:207834212)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643482.882848][4916:4918] CHIP:EM: Found matching exchange: 11670i, Delegate: 0x72916c00d7e8
[1761643482.882857][4916:4918] CHIP:EM: Rxd Ack; Removing MessageCounter:207834212 from Retrans Table on exchange 11670i
[1761643483.204820][4916:4918] CHIP:EM: >>> [E:11670i S:0 M:78814406 (Ack:207834212)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1761643483.204894][4916:4918] CHIP:EM: Found matching exchange: 11670i, Delegate: 0x72916c00d7e8
[1761643483.204904][4916:4918] CHIP:EM: CHIP MessageCounter:207834212 not in RetransTable on exchange 11670i
[1761643483.204922][4916:4918] CHIP:SC: Success status report received. Session was established
[1761643483.207528][4916:4918] CHIP:SC: SecureSession[0x72916c00da90, LSID:4391]: State change 'kEstablishing' --> 'kActive'
[1761643483.207586][4916:4918] CHIP:IN: SecureSession[0x72916c00da90]: Activated - Type:2 LSID:4391
[1761643483.207592][4916:4918] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:4391 PSID:29406!
[1761643483.207599][4916:4918] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1761643483.207621][4916:4918] CHIP:TOO: Sending ReadAttribute to:
[1761643483.207651][4916:4918] CHIP:TOO: 	cluster 0x0000_0090, attribute: 0x0000_0008, endpoint 2
[1761643483.207712][4916:4918] CHIP:DMG: SendReadRequest ReadClient[0x72916c00a6c0]: Sending Read Request
[1761643483.207764][4916:4918] CHIP:EM: <<< [E:11671i S:4391 M:209826636] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0001:02 (IM:ReadRequest)
[1761643483.207885][4916:4918] CHIP:DMG: MoveToState ReadClient[0x72916c00a6c0]: Moving to [AwaitingIn]
[1761643483.207954][4916:4918] CHIP:EM: <<< [E:11670i S:0 M:207834213 (Ack:78814406)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643483.207989][4916:4918] CHIP:EM: Flushed pending ack for MessageCounter:78814406 on exchange 11670i
[1761643483.370070][4916:4918] CHIP:EM: >>> [E:11671i S:4391 M:253691126 (Ack:209826636)] (S) Msg RX from 1:0000000000000001 [6A6C] --- Type 0001:05 (IM:ReportData)
[1761643483.370093][4916:4918] CHIP:EM: Found matching exchange: 11671i, Delegate: 0x72916c00a6d0
[1761643483.370101][4916:4918] CHIP:EM: Rxd Ack; Removing MessageCounter:209826636 from Retrans Table on exchange 11671i
[1761643483.370121][4916:4918] CHIP:DMG: ReportDataMessage =
[1761643483.370125][4916:4918] CHIP:DMG: {
[1761643483.370128][4916:4918] CHIP:DMG: 	AttributeReportIBs =
[1761643483.370334][4916:4918] CHIP:DMG: 	[
[1761643483.370340][4916:4918] CHIP:DMG: 		AttributeReportIB =
[1761643483.370345][4916:4918] CHIP:DMG: 		{
[1761643483.370348][4916:4918] CHIP:DMG: 			AttributeStatusIB =
[1761643483.370353][4916:4918] CHIP:DMG: 			{
[1761643483.370356][4916:4918] CHIP:DMG: 				AttributePathIB =
[1761643483.370361][4916:4918] CHIP:DMG: 				{
[1761643483.370366][4916:4918] CHIP:DMG: 					Endpoint = 0x2,
[1761643483.370370][4916:4918] CHIP:DMG: 					Cluster = 0x90,
[1761643483.370374][4916:4918] CHIP:DMG: 					Attribute = 0x0000_0008,
[1761643483.370378][4916:4918] CHIP:DMG: 				}
[1761643483.370384][4916:4918] CHIP:DMG: 					
[1761643483.370387][4916:4918] CHIP:DMG: 				StatusIB =
[1761643483.370392][4916:4918] CHIP:DMG: 				{
[1761643483.370396][4916:4918] CHIP:DMG: 					status = 0x01 (FAILURE),
[1761643483.370400][4916:4918] CHIP:DMG: 				},
[1761643483.370404][4916:4918] CHIP:DMG: 				
[1761643483.370408][4916:4918] CHIP:DMG: 			},
[1761643483.370413][4916:4918] CHIP:DMG: 			
[1761643483.370416][4916:4918] CHIP:DMG: 		},
[1761643483.370471][4916:4918] CHIP:DMG: 		
[1761643483.370477][4916:4918] CHIP:DMG: 	],
[1761643483.370481][4916:4918] CHIP:DMG: 	
[1761643483.370485][4916:4918] CHIP:DMG: 	SuppressResponse = true, 
[1761643483.370488][4916:4918] CHIP:DMG: 	InteractionModelRevision = 12
[1761643483.370491][4916:4918] CHIP:DMG: }
[1761643483.370668][4916:4918] CHIP:TOO: Response Failure: IM Error 0x00000501: General error: 0x01 (FAILURE)
[1761643483.370729][4916:4918] CHIP:EM: <<< [E:11671i S:4391 M:209826637 (Ack:253691126)] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643483.370779][4916:4918] CHIP:EM: Flushed pending ack for MessageCounter:253691126 on exchange 11671i
[1761643483.370905][4916:4916] CHIP:CTL: Shutting down the commissioner
[1761643483.370914][4916:4916] CHIP:CTL: Shutting down the controller
[1761643483.370926][4916:4916] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1761643483.370929][4916:4916] CHIP:IN: SecureSession[0x72916c00da90]: MarkForEviction Type:2 LSID:4391
[1761643483.370932][4916:4916] CHIP:SC: SecureSession[0x72916c00da90, LSID:4391]: State change 'kActive' --> 'kPendingEviction'
[1761643483.370935][4916:4916] CHIP:IN: SecureSession[0x72916c00da90]: Released - Type:2 LSID:4391
[1761643483.370941][4916:4916] CHIP:FP: Forgetting fabric 0x1
[1761643483.370947][4916:4916] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761643483.370987][4916:4916] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761643483.370990][4916:4916] CHIP:TS: Reverted Last Known Good Time to previous value
[1761643483.371002][4916:4916] CHIP:CTL: Shutting down the commissioner
[1761643483.371004][4916:4916] CHIP:CTL: Shutting down the controller
[1761643483.371007][4916:4916] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1761643483.371104][4916:4916] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1761643483.371133][4916:4916] CHIP:FP: Shutting down FabricTable
[1761643483.371136][4916:4916] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761643483.371152][4916:4916] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761643483.371155][4916:4916] CHIP:TS: Reverted Last Known Good Time to previous value
[1761643483.371263][4916:4916] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-WOY92H)
[1761643483.371846][4916:4916] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761643483.371860][4916:4916] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1761643483.371864][4916:4916] CHIP:DL: Inet Layer shutdown
[1761643483.371867][4916:4916] CHIP:DL: BLE shutdown
[1761643483.372441][4916:4916] CHIP:DL: System Layer shutdown
[1761643483.372535][4916:4916] CHIP:TOO: Run command failure: IM Error 0x00000501: General error: 0x01 (FAILURE)
vboxuser@Ubuntu-Thread:~/connectedhomeip$ ./out/debug/chip-tool electricalpowermeasurement read active-power 1 2
[1761643631.368618][4926:4926] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1761643631.369367][4926:4926] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1761643631.369425][4926:4926] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1761643631.371074][4926:4926] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1761643631.371329][4926:4926] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1761643631.371415][4926:4926] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1761643631.371578][4926:4926] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-1Iop85)
[1761643631.372469][4926:4926] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761643631.372493][4926:4926] CHIP:DL: NVS set: chip-counters/reboot-count = 10 (0xA)
[1761643631.372791][4926:4926] CHIP:DL: Got Ethernet interface: enp0s3
[1761643631.373011][4926:4926] CHIP:DL: Found the primary Ethernet interface:enp0s3
[1761643631.373975][4926:4926] CHIP:DL: Failed to get WiFi interface
[1761643631.374029][4926:4926] CHIP:DL: Failed to reset WiFi statistic counts
[1761643631.374051][4926:4926] CHIP:IN: UDP::Init bind&listen port=0
[1761643631.374336][4926:4926] CHIP:IN: UDP::Init bound to port=44065
[1761643631.374396][4926:4926] CHIP:IN: UDP::Init bind&listen port=0
[1761643631.374421][4926:4926] CHIP:IN: UDP::Init bound to port=44444
[1761643631.374425][4926:4926] CHIP:IN: BLEBase::Init - setting/overriding transport
[1761643631.374427][4926:4926] CHIP:IN: TransportMgr initialized
[1761643631.374449][4926:4926] CHIP:FP: Initializing FabricTable from persistent storage
[1761643631.374496][4926:4926] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761643631.374965][4926:4926] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xC0157AA7F5726A6C, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1761643631.376872][4926:4926] CHIP:ZCL: Using ZAP configuration...
[1761643631.378035][4926:4926] CHIP:CTL: System State Initialized...
[1761643631.378346][4926:4926] CHIP:CTL: Setting attestation nonce to random value
[1761643631.378432][4926:4926] CHIP:CTL: Setting CSR nonce to random value
[1761643631.379599][4926:4928] CHIP:DL: CHIP task running
[1761643631.379668][4926:4928] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1761643631.379779][4926:4928] CHIP:CTL: Setting attestation nonce to random value
[1761643631.379860][4926:4928] CHIP:CTL: Setting CSR nonce to random value
[1761643631.380092][4926:4928] CHIP:CTL: Generating NOC
[1761643631.382755][4926:4928] CHIP:FP: Validating NOC chain
[1761643631.385265][4926:4928] CHIP:FP: NOC chain validation successful
[1761643631.385517][4926:4928] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1761643631.385580][4926:4928] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761643631.385586][4926:4928] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1761643631.385589][4926:4928] CHIP:TS: Retaining current Last Known Good Time
[1761643631.389930][4926:4928] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1761643631.392034][4926:4928] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1761643631.393244][4926:4928] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: C0157AA7F5726A6C)
[1761643631.401390][4926:4928] CHIP:TOO: Sending command to node 0x1
[1761643631.401758][4926:4928] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1761643631.402123][4926:4928] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1761643631.402142][4926:4928] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1761643631.403787][4926:4928] CHIP:DIS: Lookup clearing interface for non LL address
[1761643631.403813][4926:4928] CHIP:DIS: UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895%enp0s3]:5540: new best score: 5
[1761643631.403817][4926:4928] CHIP:DIS: Checking node lookup status after 1 ms
[1761643631.403819][4926:4928] CHIP:DIS: Keeping DNSSD lookup active
[1761643631.604312][4926:4928] CHIP:DIS: Checking node lookup status after 202 ms
[1761643631.604417][4926:4928] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540 while in state 2
[1761643631.604425][4926:4928] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1761643631.604507][4926:4928] CHIP:IN: SecureSession[0x79872000da90]: Allocated Type:2 LSID:14038
[1761643631.604517][4926:4928] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1761643631.604804][4926:4928] CHIP:EM: <<< [E:30364i S:0 M:122457098] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1761643631.604891][4926:4928] CHIP:SC: Sent Sigma1 msg
[1761643631.604895][4926:4928] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1761643631.712098][4926:4928] CHIP:EM: >>> [E:30364i S:0 M:78814407 (Ack:122457098)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643631.712340][4926:4928] CHIP:EM: Found matching exchange: 30364i, Delegate: 0x79872000d7e8
[1761643631.712354][4926:4928] CHIP:EM: Rxd Ack; Removing MessageCounter:122457098 from Retrans Table on exchange 30364i
[1761643631.890161][4926:4928] CHIP:EM: >>> [E:30364i S:0 M:78814408 (Ack:122457098)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1761643631.890186][4926:4928] CHIP:EM: Found matching exchange: 30364i, Delegate: 0x79872000d7e8
[1761643631.890192][4926:4928] CHIP:EM: CHIP MessageCounter:122457098 not in RetransTable on exchange 30364i
[1761643631.890207][4926:4928] CHIP:SC: Received Sigma2 msg
[1761643631.890458][4926:4928] CHIP:SC: Peer assigned session session ID 29407
[1761643631.891294][4926:4928] CHIP:SC: Found MRP parameters in the message
[1761643631.891306][4926:4928] CHIP:SC: Sending Sigma3
[1761643631.891414][4926:4928] CHIP:EM: <<< [E:30364i S:0 M:122457099 (Ack:78814408)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1761643631.891677][4926:4928] CHIP:SC: Sent Sigma3 msg
[1761643632.054493][4926:4928] CHIP:EM: >>> [E:30364i S:0 M:78814409 (Ack:122457099)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643632.054565][4926:4928] CHIP:EM: Found matching exchange: 30364i, Delegate: 0x79872000d7e8
[1761643632.054580][4926:4928] CHIP:EM: Rxd Ack; Removing MessageCounter:122457099 from Retrans Table on exchange 30364i
[1761643632.376668][4926:4928] CHIP:EM: >>> [E:30364i S:0 M:78814410 (Ack:122457099)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1761643632.376739][4926:4928] CHIP:EM: Found matching exchange: 30364i, Delegate: 0x79872000d7e8
[1761643632.376747][4926:4928] CHIP:EM: CHIP MessageCounter:122457099 not in RetransTable on exchange 30364i
[1761643632.376764][4926:4928] CHIP:SC: Success status report received. Session was established
[1761643632.379228][4926:4928] CHIP:SC: SecureSession[0x79872000da90, LSID:14038]: State change 'kEstablishing' --> 'kActive'
[1761643632.379286][4926:4928] CHIP:IN: SecureSession[0x79872000da90]: Activated - Type:2 LSID:14038
[1761643632.379292][4926:4928] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:14038 PSID:29407!
[1761643632.379298][4926:4928] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1761643632.379438][4926:4928] CHIP:TOO: Sending ReadAttribute to:
[1761643632.379475][4926:4928] CHIP:TOO: 	cluster 0x0000_0090, attribute: 0x0000_0008, endpoint 2
[1761643632.379536][4926:4928] CHIP:DMG: SendReadRequest ReadClient[0x79872000a6c0]: Sending Read Request
[1761643632.379591][4926:4928] CHIP:EM: <<< [E:30365i S:14038 M:5495678] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0001:02 (IM:ReadRequest)
[1761643632.379711][4926:4928] CHIP:DMG: MoveToState ReadClient[0x79872000a6c0]: Moving to [AwaitingIn]
[1761643632.379781][4926:4928] CHIP:EM: <<< [E:30364i S:0 M:122457100 (Ack:78814410)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643632.379803][4926:4928] CHIP:EM: Flushed pending ack for MessageCounter:78814410 on exchange 30364i
[1761643632.538740][4926:4928] CHIP:EM: >>> [E:30365i S:14038 M:15014038 (Ack:5495678)] (S) Msg RX from 1:0000000000000001 [6A6C] --- Type 0001:05 (IM:ReportData)
[1761643632.538810][4926:4928] CHIP:EM: Found matching exchange: 30365i, Delegate: 0x79872000a6d0
[1761643632.538823][4926:4928] CHIP:EM: Rxd Ack; Removing MessageCounter:5495678 from Retrans Table on exchange 30365i
[1761643632.538845][4926:4928] CHIP:DMG: ReportDataMessage =
[1761643632.538849][4926:4928] CHIP:DMG: {
[1761643632.538851][4926:4928] CHIP:DMG: 	AttributeReportIBs =
[1761643632.538856][4926:4928] CHIP:DMG: 	[
[1761643632.538859][4926:4928] CHIP:DMG: 		AttributeReportIB =
[1761643632.538864][4926:4928] CHIP:DMG: 		{
[1761643632.538867][4926:4928] CHIP:DMG: 			AttributeStatusIB =
[1761643632.538871][4926:4928] CHIP:DMG: 			{
[1761643632.538875][4926:4928] CHIP:DMG: 				AttributePathIB =
[1761643632.538880][4926:4928] CHIP:DMG: 				{
[1761643632.538884][4926:4928] CHIP:DMG: 					Endpoint = 0x2,
[1761643632.538888][4926:4928] CHIP:DMG: 					Cluster = 0x90,
[1761643632.538893][4926:4928] CHIP:DMG: 					Attribute = 0x0000_0008,
[1761643632.538897][4926:4928] CHIP:DMG: 				}
[1761643632.538902][4926:4928] CHIP:DMG: 					
[1761643632.538911][4926:4928] CHIP:DMG: 				StatusIB =
[1761643632.538917][4926:4928] CHIP:DMG: 				{
[1761643632.538924][4926:4928] CHIP:DMG: 					status = 0x01 (FAILURE),
[1761643632.538928][4926:4928] CHIP:DMG: 				},
[1761643632.538932][4926:4928] CHIP:DMG: 				
[1761643632.538936][4926:4928] CHIP:DMG: 			},
[1761643632.538940][4926:4928] CHIP:DMG: 			
[1761643632.538943][4926:4928] CHIP:DMG: 		},
[1761643632.538947][4926:4928] CHIP:DMG: 		
[1761643632.538950][4926:4928] CHIP:DMG: 	],
[1761643632.538954][4926:4928] CHIP:DMG: 	
[1761643632.538957][4926:4928] CHIP:DMG: 	SuppressResponse = true, 
[1761643632.538960][4926:4928] CHIP:DMG: 	InteractionModelRevision = 12
[1761643632.538963][4926:4928] CHIP:DMG: }
[1761643632.538990][4926:4928] CHIP:TOO: Response Failure: IM Error 0x00000501: General error: 0x01 (FAILURE)
[1761643632.539236][4926:4928] CHIP:EM: <<< [E:30365i S:14038 M:5495679 (Ack:15014038)] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761643632.539312][4926:4928] CHIP:EM: Flushed pending ack for MessageCounter:15014038 on exchange 30365i
[1761643632.539419][4926:4926] CHIP:CTL: Shutting down the commissioner
[1761643632.539470][4926:4926] CHIP:CTL: Shutting down the controller
[1761643632.539497][4926:4926] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1761643632.539512][4926:4926] CHIP:IN: SecureSession[0x79872000da90]: MarkForEviction Type:2 LSID:14038
[1761643632.539526][4926:4926] CHIP:SC: SecureSession[0x79872000da90, LSID:14038]: State change 'kActive' --> 'kPendingEviction'
[1761643632.539541][4926:4926] CHIP:IN: SecureSession[0x79872000da90]: Released - Type:2 LSID:14038
[1761643632.539557][4926:4926] CHIP:FP: Forgetting fabric 0x1
[1761643632.539575][4926:4926] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761643632.539625][4926:4926] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761643632.539639][4926:4926] CHIP:TS: Reverted Last Known Good Time to previous value
[1761643632.539662][4926:4926] CHIP:CTL: Shutting down the commissioner
[1761643632.539676][4926:4926] CHIP:CTL: Shutting down the controller
[1761643632.539690][4926:4926] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1761643632.539799][4926:4926] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1761643632.539834][4926:4926] CHIP:FP: Shutting down FabricTable
[1761643632.539849][4926:4926] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761643632.539877][4926:4926] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761643632.539892][4926:4926] CHIP:TS: Reverted Last Known Good Time to previous value
[1761643632.540006][4926:4926] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-C0LuEG)
[1761643632.540762][4926:4926] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761643632.540798][4926:4926] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1761643632.540813][4926:4926] CHIP:DL: Inet Layer shutdown
[1761643632.540828][4926:4926] CHIP:DL: BLE shutdown
[1761643632.540876][4926:4926] CHIP:DL: System Layer shutdown
[1761643632.540967][4926:4926] CHIP:TOO: Run command failure: IM Error 0x00000501: General error: 0x01 (FAILURE)
vboxuser@Ubuntu-Thread:~/connectedhomeip$ ./out/debug/chip-tool electricalpowermeasurement read feature-map 1 2
[1761644467.851968][4952:4952] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1761644467.852673][4952:4952] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1761644467.852741][4952:4952] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1761644467.854391][4952:4952] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1761644467.854652][4952:4952] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1761644467.854676][4952:4952] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1761644467.854879][4952:4952] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-SQbsxT)
[1761644467.855589][4952:4952] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761644467.855792][4952:4952] CHIP:DL: NVS set: chip-counters/reboot-count = 11 (0xB)
[1761644467.856075][4952:4952] CHIP:DL: Got Ethernet interface: enp0s3
[1761644467.856446][4952:4952] CHIP:DL: Found the primary Ethernet interface:enp0s3
[1761644467.857252][4952:4952] CHIP:DL: Failed to get WiFi interface
[1761644467.857309][4952:4952] CHIP:DL: Failed to reset WiFi statistic counts
[1761644467.857333][4952:4952] CHIP:IN: UDP::Init bind&listen port=0
[1761644467.857367][4952:4952] CHIP:IN: UDP::Init bound to port=59151
[1761644467.857370][4952:4952] CHIP:IN: UDP::Init bind&listen port=0
[1761644467.857387][4952:4952] CHIP:IN: UDP::Init bound to port=52942
[1761644467.857391][4952:4952] CHIP:IN: BLEBase::Init - setting/overriding transport
[1761644467.857398][4952:4952] CHIP:IN: TransportMgr initialized
[1761644467.857411][4952:4952] CHIP:FP: Initializing FabricTable from persistent storage
[1761644467.857494][4952:4952] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761644467.857880][4952:4952] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xC0157AA7F5726A6C, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1761644467.859342][4952:4952] CHIP:ZCL: Using ZAP configuration...
[1761644467.860332][4952:4952] CHIP:CTL: System State Initialized...
[1761644467.860581][4952:4952] CHIP:CTL: Setting attestation nonce to random value
[1761644467.860640][4952:4952] CHIP:CTL: Setting CSR nonce to random value
[1761644467.863182][4952:4954] CHIP:DL: CHIP task running
[1761644467.863246][4952:4954] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1761644467.863373][4952:4954] CHIP:CTL: Setting attestation nonce to random value
[1761644467.863442][4952:4954] CHIP:CTL: Setting CSR nonce to random value
[1761644467.863714][4952:4954] CHIP:CTL: Generating NOC
[1761644467.863969][4952:4954] CHIP:FP: Validating NOC chain
[1761644467.866550][4952:4954] CHIP:FP: NOC chain validation successful
[1761644467.866885][4952:4954] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1761644467.866907][4952:4954] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761644467.866921][4952:4954] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1761644467.866978][4952:4954] CHIP:TS: Retaining current Last Known Good Time
[1761644467.870870][4952:4954] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1761644467.871735][4952:4954] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1761644467.873546][4952:4954] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: C0157AA7F5726A6C)
[1761644467.883581][4952:4954] CHIP:TOO: Sending command to node 0x1
[1761644467.883916][4952:4954] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1761644467.883972][4952:4954] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1761644467.883988][4952:4954] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1761644467.886989][4952:4954] CHIP:DIS: Lookup clearing interface for non LL address
[1761644467.887343][4952:4954] CHIP:DIS: UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895%enp0s3]:5540: new best score: 5
[1761644467.887352][4952:4954] CHIP:DIS: Checking node lookup status after 4 ms
[1761644467.887355][4952:4954] CHIP:DIS: Keeping DNSSD lookup active
[1761644468.083542][4952:4954] CHIP:DIS: Checking node lookup status after 200 ms
[1761644468.083631][4952:4954] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540 while in state 2
[1761644468.083638][4952:4954] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1761644468.083727][4952:4954] CHIP:IN: SecureSession[0x763f0000da90]: Allocated Type:2 LSID:39211
[1761644468.083738][4952:4954] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1761644468.084024][4952:4954] CHIP:EM: <<< [E:60346i S:0 M:151740471] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1761644468.084105][4952:4954] CHIP:SC: Sent Sigma1 msg
[1761644468.084109][4952:4954] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1761644468.191779][4952:4954] CHIP:EM: >>> [E:60346i S:0 M:78814411 (Ack:151740471)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761644468.191803][4952:4954] CHIP:EM: Found matching exchange: 60346i, Delegate: 0x763f0000d7e8
[1761644468.191813][4952:4954] CHIP:EM: Rxd Ack; Removing MessageCounter:151740471 from Retrans Table on exchange 60346i
[1761644468.370189][4952:4954] CHIP:EM: >>> [E:60346i S:0 M:78814412 (Ack:151740471)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1761644468.370211][4952:4954] CHIP:EM: Found matching exchange: 60346i, Delegate: 0x763f0000d7e8
[1761644468.370216][4952:4954] CHIP:EM: CHIP MessageCounter:151740471 not in RetransTable on exchange 60346i
[1761644468.370232][4952:4954] CHIP:SC: Received Sigma2 msg
[1761644468.370243][4952:4954] CHIP:SC: Peer assigned session session ID 29408
[1761644468.371308][4952:4954] CHIP:SC: Found MRP parameters in the message
[1761644468.371830][4952:4954] CHIP:SC: Sending Sigma3
[1761644468.372018][4952:4954] CHIP:EM: <<< [E:60346i S:0 M:151740472 (Ack:78814412)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1761644468.372461][4952:4954] CHIP:SC: Sent Sigma3 msg
[1761644468.532638][4952:4954] CHIP:EM: >>> [E:60346i S:0 M:78814413 (Ack:151740472)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761644468.532717][4952:4954] CHIP:EM: Found matching exchange: 60346i, Delegate: 0x763f0000d7e8
[1761644468.532732][4952:4954] CHIP:EM: Rxd Ack; Removing MessageCounter:151740472 from Retrans Table on exchange 60346i
[1761644468.851945][4952:4954] CHIP:EM: >>> [E:60346i S:0 M:78814414 (Ack:151740472)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1761644468.852010][4952:4954] CHIP:EM: Found matching exchange: 60346i, Delegate: 0x763f0000d7e8
[1761644468.852020][4952:4954] CHIP:EM: CHIP MessageCounter:151740472 not in RetransTable on exchange 60346i
[1761644468.852037][4952:4954] CHIP:SC: Success status report received. Session was established
[1761644468.853644][4952:4954] CHIP:SC: SecureSession[0x763f0000da90, LSID:39211]: State change 'kEstablishing' --> 'kActive'
[1761644468.853666][4952:4954] CHIP:IN: SecureSession[0x763f0000da90]: Activated - Type:2 LSID:39211
[1761644468.853680][4952:4954] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:39211 PSID:29408!
[1761644468.853697][4952:4954] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1761644468.853729][4952:4954] CHIP:TOO: Sending ReadAttribute to:
[1761644468.853901][4952:4954] CHIP:TOO: 	cluster 0x0000_0090, attribute: 0x0000_FFFC, endpoint 2
[1761644468.853936][4952:4954] CHIP:DMG: SendReadRequest ReadClient[0x763f0000a6c0]: Sending Read Request
[1761644468.853994][4952:4954] CHIP:EM: <<< [E:60347i S:39211 M:12868452] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0001:02 (IM:ReadRequest)
[1761644468.854066][4952:4954] CHIP:DMG: MoveToState ReadClient[0x763f0000a6c0]: Moving to [AwaitingIn]
[1761644468.854560][4952:4954] CHIP:EM: <<< [E:60346i S:0 M:151740473 (Ack:78814414)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761644468.854584][4952:4954] CHIP:EM: Flushed pending ack for MessageCounter:78814414 on exchange 60346i
[1761644469.015708][4952:4954] CHIP:EM: >>> [E:60347i S:39211 M:201925341 (Ack:12868452)] (S) Msg RX from 1:0000000000000001 [6A6C] --- Type 0001:05 (IM:ReportData)
[1761644469.015783][4952:4954] CHIP:EM: Found matching exchange: 60347i, Delegate: 0x763f0000a6d0
[1761644469.015797][4952:4954] CHIP:EM: Rxd Ack; Removing MessageCounter:12868452 from Retrans Table on exchange 60347i
[1761644469.015819][4952:4954] CHIP:DMG: ReportDataMessage =
[1761644469.015824][4952:4954] CHIP:DMG: {
[1761644469.015826][4952:4954] CHIP:DMG: 	AttributeReportIBs =
[1761644469.015831][4952:4954] CHIP:DMG: 	[
[1761644469.015834][4952:4954] CHIP:DMG: 		AttributeReportIB =
[1761644469.015839][4952:4954] CHIP:DMG: 		{
[1761644469.015843][4952:4954] CHIP:DMG: 			AttributeStatusIB =
[1761644469.015847][4952:4954] CHIP:DMG: 			{
[1761644469.015850][4952:4954] CHIP:DMG: 				AttributePathIB =
[1761644469.015855][4952:4954] CHIP:DMG: 				{
[1761644469.015860][4952:4954] CHIP:DMG: 					Endpoint = 0x2,
[1761644469.015864][4952:4954] CHIP:DMG: 					Cluster = 0x90,
[1761644469.015868][4952:4954] CHIP:DMG: 					Attribute = 0x0000_FFFC,
[1761644469.015872][4952:4954] CHIP:DMG: 				}
[1761644469.015878][4952:4954] CHIP:DMG: 					
[1761644469.015882][4952:4954] CHIP:DMG: 				StatusIB =
[1761644469.015886][4952:4954] CHIP:DMG: 				{
[1761644469.015890][4952:4954] CHIP:DMG: 					status = 0x01 (FAILURE),
[1761644469.015894][4952:4954] CHIP:DMG: 				},
[1761644469.015898][4952:4954] CHIP:DMG: 				
[1761644469.015902][4952:4954] CHIP:DMG: 			},
[1761644469.015906][4952:4954] CHIP:DMG: 			
[1761644469.015909][4952:4954] CHIP:DMG: 		},
[1761644469.015914][4952:4954] CHIP:DMG: 		
[1761644469.015917][4952:4954] CHIP:DMG: 	],
[1761644469.015921][4952:4954] CHIP:DMG: 	
[1761644469.015924][4952:4954] CHIP:DMG: 	SuppressResponse = true, 
[1761644469.015927][4952:4954] CHIP:DMG: 	InteractionModelRevision = 12
[1761644469.015930][4952:4954] CHIP:DMG: }
[1761644469.015957][4952:4954] CHIP:TOO: Response Failure: IM Error 0x00000501: General error: 0x01 (FAILURE)
[1761644469.016010][4952:4954] CHIP:EM: <<< [E:60347i S:39211 M:12868453 (Ack:201925341)] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761644469.016059][4952:4954] CHIP:EM: Flushed pending ack for MessageCounter:201925341 on exchange 60347i
[1761644469.016912][4952:4952] CHIP:CTL: Shutting down the commissioner
[1761644469.016940][4952:4952] CHIP:CTL: Shutting down the controller
[1761644469.016969][4952:4952] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1761644469.016983][4952:4952] CHIP:IN: SecureSession[0x763f0000da90]: MarkForEviction Type:2 LSID:39211
[1761644469.016998][4952:4952] CHIP:SC: SecureSession[0x763f0000da90, LSID:39211]: State change 'kActive' --> 'kPendingEviction'
[1761644469.017012][4952:4952] CHIP:IN: SecureSession[0x763f0000da90]: Released - Type:2 LSID:39211
[1761644469.017029][4952:4952] CHIP:FP: Forgetting fabric 0x1
[1761644469.017047][4952:4952] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761644469.017105][4952:4952] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761644469.017119][4952:4952] CHIP:TS: Reverted Last Known Good Time to previous value
[1761644469.017141][4952:4952] CHIP:CTL: Shutting down the commissioner
[1761644469.017156][4952:4952] CHIP:CTL: Shutting down the controller
[1761644469.017170][4952:4952] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1761644469.017266][4952:4952] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1761644469.017349][4952:4952] CHIP:FP: Shutting down FabricTable
[1761644469.017377][4952:4952] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761644469.017406][4952:4952] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761644469.017420][4952:4952] CHIP:TS: Reverted Last Known Good Time to previous value
[1761644469.017565][4952:4952] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-DLJoeX)
[1761644469.018004][4952:4952] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761644469.018035][4952:4952] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1761644469.018055][4952:4952] CHIP:DL: Inet Layer shutdown
[1761644469.018069][4952:4952] CHIP:DL: BLE shutdown
[1761644469.018573][4952:4952] CHIP:DL: System Layer shutdown
[1761644469.018870][4952:4952] CHIP:TOO: Run command failure: IM Error 0x00000501: General error: 0x01 (FAILURE)
boxuser@Ubuntu-Thread:~/connectedhomeip$ ./out/debug/chip-tool any read-by-id 0x0090 0x0000 1 2
[1761646274.184069][5329:5329] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1761646274.184669][5329:5329] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1761646274.184725][5329:5329] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1761646274.186537][5329:5329] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1761646274.186628][5329:5329] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1761646274.186647][5329:5329] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1761646274.186807][5329:5329] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-fu6GxH)
[1761646274.187756][5329:5329] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761646274.187770][5329:5329] CHIP:DL: NVS set: chip-counters/reboot-count = 18 (0x12)
[1761646274.188050][5329:5329] CHIP:DL: Got Ethernet interface: enp0s3
[1761646274.188391][5329:5329] CHIP:DL: Found the primary Ethernet interface:enp0s3
[1761646274.189043][5329:5329] CHIP:DL: Failed to get WiFi interface
[1761646274.189098][5329:5329] CHIP:DL: Failed to reset WiFi statistic counts
[1761646274.189124][5329:5329] CHIP:IN: UDP::Init bind&listen port=0
[1761646274.189276][5329:5329] CHIP:IN: UDP::Init bound to port=36281
[1761646274.189287][5329:5329] CHIP:IN: UDP::Init bind&listen port=0
[1761646274.189310][5329:5329] CHIP:IN: UDP::Init bound to port=48773
[1761646274.189360][5329:5329] CHIP:IN: BLEBase::Init - setting/overriding transport
[1761646274.189366][5329:5329] CHIP:IN: TransportMgr initialized
[1761646274.189379][5329:5329] CHIP:FP: Initializing FabricTable from persistent storage
[1761646274.189419][5329:5329] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761646274.189803][5329:5329] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xC0157AA7F5726A6C, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1761646274.191783][5329:5329] CHIP:ZCL: Using ZAP configuration...
[1761646274.192814][5329:5329] CHIP:CTL: System State Initialized...
[1761646274.193054][5329:5329] CHIP:CTL: Setting attestation nonce to random value
[1761646274.193115][5329:5329] CHIP:CTL: Setting CSR nonce to random value
[1761646274.193483][5329:5331] CHIP:DL: CHIP task running
[1761646274.193505][5329:5331] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
[1761646274.193589][5329:5331] CHIP:CTL: Setting attestation nonce to random value
[1761646274.193666][5329:5331] CHIP:CTL: Setting CSR nonce to random value
[1761646274.193891][5329:5331] CHIP:CTL: Generating NOC
[1761646274.194173][5329:5331] CHIP:FP: Validating NOC chain
[1761646274.194800][5329:5331] CHIP:FP: NOC chain validation successful
[1761646274.194892][5329:5331] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1761646274.194900][5329:5331] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1761646274.194903][5329:5331] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1761646274.194906][5329:5331] CHIP:TS: Retaining current Last Known Good Time
[1761646274.199440][5329:5331] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1761646274.201021][5329:5331] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1761646274.202586][5329:5331] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: C0157AA7F5726A6C)
[1761646274.213436][5329:5331] CHIP:TOO: Sending command to node 0x1
[1761646274.213615][5329:5331] CHIP:CSM: FindOrEstablishSession: PeerId = [1:0000000000000001]
[1761646274.213673][5329:5331] CHIP:CSM: FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1761646274.213689][5329:5331] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 1 --> 2
[1761646274.215420][5329:5331] CHIP:DIS: Lookup clearing interface for non LL address
[1761646274.215495][5329:5331] CHIP:DIS: UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895%enp0s3]:5540: new best score: 5
[1761646274.215500][5329:5331] CHIP:DIS: Checking node lookup status after 2 ms
[1761646274.215503][5329:5331] CHIP:DIS: Keeping DNSSD lookup active
[1761646274.414575][5329:5331] CHIP:DIS: Checking node lookup status after 201 ms
[1761646274.414673][5329:5331] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: Updating device address to UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540 while in state 2
[1761646274.414682][5329:5331] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 2 --> 3
[1761646274.414766][5329:5331] CHIP:IN: SecureSession[0x794b5000da90]: Allocated Type:2 LSID:47301
[1761646274.414777][5329:5331] CHIP:SC: Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000001
[1761646274.415077][5329:5331] CHIP:EM: <<< [E:59192i S:0 M:240876487] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[1761646274.415334][5329:5331] CHIP:SC: Sent Sigma1 msg
[1761646274.415344][5329:5331] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 3 --> 4
[1761646274.522548][5329:5331] CHIP:EM: >>> [E:59192i S:0 M:78814439 (Ack:240876487)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761646274.522621][5329:5331] CHIP:EM: Found matching exchange: 59192i, Delegate: 0x794b5000d7e8
[1761646274.522637][5329:5331] CHIP:EM: Rxd Ack; Removing MessageCounter:240876487 from Retrans Table on exchange 59192i
[1761646274.702653][5329:5331] CHIP:EM: >>> [E:59192i S:0 M:78814440 (Ack:240876487)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[1761646274.702674][5329:5331] CHIP:EM: Found matching exchange: 59192i, Delegate: 0x794b5000d7e8
[1761646274.702680][5329:5331] CHIP:EM: CHIP MessageCounter:240876487 not in RetransTable on exchange 59192i
[1761646274.702695][5329:5331] CHIP:SC: Received Sigma2 msg
[1761646274.702706][5329:5331] CHIP:SC: Peer assigned session session ID 29415
[1761646274.703554][5329:5331] CHIP:SC: Found MRP parameters in the message
[1761646274.703624][5329:5331] CHIP:SC: Sending Sigma3
[1761646274.703903][5329:5331] CHIP:EM: <<< [E:59192i S:0 M:240876488 (Ack:78814440)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[1761646274.704020][5329:5331] CHIP:SC: Sent Sigma3 msg
[1761646274.860546][5329:5331] CHIP:EM: >>> [E:59192i S:0 M:78814441 (Ack:240876488)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761646274.860615][5329:5331] CHIP:EM: Found matching exchange: 59192i, Delegate: 0x794b5000d7e8
[1761646274.860629][5329:5331] CHIP:EM: Rxd Ack; Removing MessageCounter:240876488 from Retrans Table on exchange 59192i
[1761646275.183872][5329:5331] CHIP:EM: >>> [E:59192i S:0 M:78814442 (Ack:240876488)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1761646275.184100][5329:5331] CHIP:EM: Found matching exchange: 59192i, Delegate: 0x794b5000d7e8
[1761646275.184108][5329:5331] CHIP:EM: CHIP MessageCounter:240876488 not in RetransTable on exchange 59192i
[1761646275.184129][5329:5331] CHIP:SC: Success status report received. Session was established
[1761646275.186746][5329:5331] CHIP:SC: SecureSession[0x794b5000da90, LSID:47301]: State change 'kEstablishing' --> 'kActive'
[1761646275.186807][5329:5331] CHIP:IN: SecureSession[0x794b5000da90]: Activated - Type:2 LSID:47301
[1761646275.186814][5329:5331] CHIP:IN: New secure session activated for device <0000000000000001, 1>, LSID:47301 PSID:29415!
[1761646275.186820][5329:5331] CHIP:DIS: OperationalSessionSetup[1:0000000000000001]: State change 4 --> 5
[1761646275.186846][5329:5331] CHIP:TOO: Sending ReadAttribute to:
[1761646275.187152][5329:5331] CHIP:TOO: 	cluster 0x0000_0090, attribute: 0x0000_0000, endpoint 2
[1761646275.187281][5329:5331] CHIP:DMG: SendReadRequest ReadClient[0x794b5000a6c0]: Sending Read Request
[1761646275.187510][5329:5331] CHIP:EM: <<< [E:59193i S:47301 M:172790302] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0001:02 (IM:ReadRequest)
[1761646275.187602][5329:5331] CHIP:DMG: MoveToState ReadClient[0x794b5000a6c0]: Moving to [AwaitingIn]
[1761646275.187666][5329:5331] CHIP:EM: <<< [E:59192i S:0 M:240876489 (Ack:78814442)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761646275.187716][5329:5331] CHIP:EM: Flushed pending ack for MessageCounter:78814442 on exchange 59192i
[1761646275.390973][5329:5331] CHIP:EM: >>> [E:59193i S:47301 M:102941012 (Ack:172790302)] (S) Msg RX from 1:0000000000000001 [6A6C] --- Type 0001:05 (IM:ReportData)
[1761646275.390992][5329:5331] CHIP:EM: Found matching exchange: 59193i, Delegate: 0x794b5000a6d0
[1761646275.390999][5329:5331] CHIP:EM: Rxd Ack; Removing MessageCounter:172790302 from Retrans Table on exchange 59193i
[1761646275.391018][5329:5331] CHIP:DMG: ReportDataMessage =
[1761646275.391021][5329:5331] CHIP:DMG: {
[1761646275.391024][5329:5331] CHIP:DMG: 	AttributeReportIBs =
[1761646275.391028][5329:5331] CHIP:DMG: 	[
[1761646275.391032][5329:5331] CHIP:DMG: 		AttributeReportIB =
[1761646275.391036][5329:5331] CHIP:DMG: 		{
[1761646275.391039][5329:5331] CHIP:DMG: 			AttributeStatusIB =
[1761646275.391044][5329:5331] CHIP:DMG: 			{
[1761646275.391047][5329:5331] CHIP:DMG: 				AttributePathIB =
[1761646275.391052][5329:5331] CHIP:DMG: 				{
[1761646275.391057][5329:5331] CHIP:DMG: 					Endpoint = 0x2,
[1761646275.391061][5329:5331] CHIP:DMG: 					Cluster = 0x90,
[1761646275.391065][5329:5331] CHIP:DMG: 					Attribute = 0x0000_0000,
[1761646275.391069][5329:5331] CHIP:DMG: 				}
[1761646275.391075][5329:5331] CHIP:DMG: 					
[1761646275.391079][5329:5331] CHIP:DMG: 				StatusIB =
[1761646275.391083][5329:5331] CHIP:DMG: 				{
[1761646275.391087][5329:5331] CHIP:DMG: 					status = 0x01 (FAILURE),
[1761646275.391091][5329:5331] CHIP:DMG: 				},
[1761646275.391095][5329:5331] CHIP:DMG: 				
[1761646275.391099][5329:5331] CHIP:DMG: 			},
[1761646275.391103][5329:5331] CHIP:DMG: 			
[1761646275.391106][5329:5331] CHIP:DMG: 		},
[1761646275.391110][5329:5331] CHIP:DMG: 		
[1761646275.391113][5329:5331] CHIP:DMG: 	],
[1761646275.391117][5329:5331] CHIP:DMG: 	
[1761646275.391120][5329:5331] CHIP:DMG: 	SuppressResponse = true, 
[1761646275.391124][5329:5331] CHIP:DMG: 	InteractionModelRevision = 12
[1761646275.391126][5329:5331] CHIP:DMG: }
[1761646275.391989][5329:5331] CHIP:TOO: Response Failure: IM Error 0x00000501: General error: 0x01 (FAILURE)
[1761646275.392057][5329:5331] CHIP:EM: <<< [E:59193i S:47301 M:172790303 (Ack:102941012)] (S) Msg TX to 1:0000000000000001 [6A6C] [UDP:[fdec:8fd8:7675:1:fd15:e00:bc62:5895]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1761646275.392174][5329:5331] CHIP:EM: Flushed pending ack for MessageCounter:102941012 on exchange 59193i
[1761646275.392406][5329:5329] CHIP:CTL: Shutting down the commissioner
[1761646275.392462][5329:5329] CHIP:CTL: Shutting down the controller
[1761646275.392494][5329:5329] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1761646275.392510][5329:5329] CHIP:IN: SecureSession[0x794b5000da90]: MarkForEviction Type:2 LSID:47301
[1761646275.392525][5329:5329] CHIP:SC: SecureSession[0x794b5000da90, LSID:47301]: State change 'kActive' --> 'kPendingEviction'
[1761646275.392539][5329:5329] CHIP:IN: SecureSession[0x794b5000da90]: Released - Type:2 LSID:47301
[1761646275.392556][5329:5329] CHIP:FP: Forgetting fabric 0x1
[1761646275.392574][5329:5329] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761646275.392628][5329:5329] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761646275.392638][5329:5329] CHIP:TS: Reverted Last Known Good Time to previous value
[1761646275.392650][5329:5329] CHIP:CTL: Shutting down the commissioner
[1761646275.392653][5329:5329] CHIP:CTL: Shutting down the controller
[1761646275.392656][5329:5329] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1761646275.393879][5329:5329] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1761646275.393923][5329:5329] CHIP:FP: Shutting down FabricTable
[1761646275.393939][5329:5329] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1761646275.393979][5329:5329] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1761646275.393994][5329:5329] CHIP:TS: Reverted Last Known Good Time to previous value
[1761646275.394144][5329:5329] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-zAOa1t)
[1761646275.395520][5329:5329] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1761646275.395569][5329:5329] CHIP:DL: NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1761646275.395585][5329:5329] CHIP:DL: Inet Layer shutdown
[1761646275.395599][5329:5329] CHIP:DL: BLE shutdown
[1761646275.395647][5329:5329] CHIP:DL: System Layer shutdown
[1761646275.395753][5329:5329] CHIP:TOO: Run command failure: IM Error 0x00000501: General error: 0x01 (FAILURE)
vboxuser@Ubuntu-Thread:~/connectedhomeip$ 

[Marte Myrvold]

Hi,

It seems like the attributes that fail are the ones that have the storage option set to external in ZAP tool. When an attribute is external, it means that it must be managed by the application, i.e. you are expected to provide the implementation for handling the attribute in the application.

To do this, you must implement the cluster initialization callback function, emberAfElectricalPowerMeasurementClusterInitCallback(), and set the value of the attribute on initialization. I recommend taking a look at how this is done in the all-clusters-app: https://github.com/nrfconnect/sdk-connectedhomeip/blob/master/examples/all-clusters-app/all-clusters-common/src/electrical-power-measurement-stub.cpp. You can find the API for the Electrical Power Measurement cluster here:

• https://github.com/nrfconnect/sdk-connectedhomeip/blob/master/src/app/clusters/electrical-power-measurement-server/electrical-power-measurement-server.h
• https://github.com/nrfconnect/sdk-connectedhomeip/blob/master/src/app/clusters/electrical-power-measurement-server/electrical-power-measurement-server.cpp 

Best regards,
Marte