Hi,
The RebootCount attribute of the GeneralDiagnosticsCluster is returning a FAILURE response.
This issue is causing failures in Matter test cases TC-ACE-2.1.
CONFIG_CHIP_LAST_FABRIC_REMOVED_ERASE_ONLY is required. What kind of response is possible?
- nRF5340DK
- NCS2.9.2
- Door Lock
- pri.conf: CONFIG_CHIP_LAST_FABRIC_REMOVED_ERASE_ONLY=y
Steps to Reproduce:
- Perform commissioning.
- Perform decommissioning (remove fabric).
- Perform re-commissioning.
- Attempt to read the RebootCount from the GeneralDiagnosticsCluster.
ubuntu@raspberrypi-obtr:~/th$ ~/connectedhomeip/out/host/chip-tool generaldiagnostics read reboot-count 2 0
[1769154746.645] [234597:234597] [DL] ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1769154746.647] [234597:234597] [DL] ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs, IGNORING.
[1769154746.652] [234597:234597] [DL] ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1769154746.652] [234597:234597] [DL] ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1769154746.653] [234597:234597] [DL] ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1769154746.659] [234597:234597] [DL] Wrote settings to /tmp/chip_counters.ini
[1769154746.659] [234597:234597] [DL] NVS set: chip-counters/reboot-count = 2 (0x2)
[1769154746.660] [234597:234597] [DL] Got Ethernet interface: eth0
[1769154746.660] [234597:234597] [DL] Found the primary Ethernet interface:eth0
[1769154746.661] [234597:234597] [DL] Got WiFi interface: wlan0
[1769154746.661] [234597:234597] [DL] Failed to reset WiFi statistic counts
[1769154746.661] [234597:234597] [PAF] WiFiPAF: WiFiPAFLayer::Init()
[1769154746.661] [234597:234597] [IN] UDP::Init bind&listen port=0
[1769154746.662] [234597:234597] [IN] UDP::Init bound to port=53750
[1769154746.662] [234597:234597] [IN] UDP::Init bind&listen port=0
[1769154746.662] [234597:234597] [IN] UDP::Init bound to port=38981
[1769154746.662] [234597:234597] [IN] BLEBase::Init - setting/overriding transport
[1769154746.662] [234597:234597] [IN] WiFiPAFBase::Init - setting/overriding transport
[1769154746.662] [234597:234597] [IN] TransportMgr initialized
[1769154746.662] [234597:234597] [FP] Initializing FabricTable from persistent storage
[1769154746.662] [234597:234597] [TS] Last Known Good Time: 2023-10-14T01:16:48
[1769154746.664] [234597:234597] [FP] Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x69C2586FB58E786E, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1769154746.667] [234597:234597] [DMG] Ember attribute persistence requires setting up
[1769154746.667] [234597:234597] [ZCL] Using ZAP configuration...
[1769154746.695] [234597:234597] [CTL] System State Initialized...
[1769154746.695] [234597:234597] [CTL] Setting attestation nonce to random value
[1769154746.695] [234597:234597] [CTL] Setting CSR nonce to random value
[1769154746.695] [234597:234599] [DL] CHIP task running
[1769154746.696] [234597:234599] [CTL] Setting attestation nonce to random value
[1769154746.696] [234597:234599] [CTL] Setting CSR nonce to random value
[1769154746.697] [234597:234599] [CTL] Generating NOC
[1769154746.698] [234597:234599] [FP] Validating NOC chain
[1769154746.700] [234597:234599] [FP] NOC chain validation successful
[1769154746.700] [234597:234599] [FP] Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1769154746.700] [234597:234599] [TS] Last Known Good Time: 2023-10-14T01:16:48
[1769154746.700] [234597:234599] [TS] New proposed Last Known Good Time: 2021-01-01T00:00:00
[1769154746.700] [234597:234599] [TS] Retaining current Last Known Good Time
[1769154746.704] [234597:234599] [FP] Metadata for Fabric 0x1 persisted to storage.
[1769154746.706] [234597:234599] [TS] Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1769154746.708] [234597:234599] [CTL] Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 69C2586FB58E786E)
[1769154746.723] [234597:234599] [TOO] Sending command to node 0x2
[1769154746.724] [234597:234599] [CSM] FindOrEstablishSession: PeerId = [1:0000000000000002]
[1769154746.724] [234597:234599] [CSM] FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1769154746.724] [234597:234599] [DIS] OperationalSessionSetup[1:0000000000000002]: State change 1 --> 2
[1769154746.726] [234597:234599] [DIS] Lookup started for 69C2586FB58E786E-0000000000000002
[1769154746.727] [234597:234599] [DIS] Lookup clearing interface for non LL address
[1769154746.727] [234597:234599] [DIS] UDP:[fd11:25::5318:efbe:829e:daf1%eth0]:5540: new best score: 5 (for 69C2586FB58E786E-0000000000000002)
[1769154746.727] [234597:234599] [DIS] Checking node lookup status for 69C2586FB58E786E-0000000000000002 after 3 ms
[1769154746.727] [234597:234599] [DIS] Keeping DNSSD lookup active
[1769154746.728] [234597:234599] [DIS] Lookup clearing interface for non LL address
[1769154746.728] [234597:234599] [DIS] UDP:[fd11:25::5318:efbe:829e:daf1%eth0]:5540: score has not improved: 5 (for 69C2586FB58E786E-0000000000000002)
[1769154746.728] [234597:234599] [DIS] Checking node lookup status for 69C2586FB58E786E-0000000000000002 after 4 ms
[1769154746.728] [234597:234599] [DIS] Keeping DNSSD lookup active
[1769154746.729] [234597:234599] [DIS] Lookup clearing interface for non LL address
[1769154746.729] [234597:234599] [DIS] UDP:[fd11:25::5318:efbe:829e:daf1%docker0]:5540: score has not improved: 5 (for 69C2586FB58E786E-0000000000000002)
[1769154746.729] [234597:234599] [DIS] Checking node lookup status for 69C2586FB58E786E-0000000000000002 after 5 ms
[1769154746.729] [234597:234599] [DIS] Keeping DNSSD lookup active
[1769154746.730] [234597:234599] [DIS] Lookup clearing interface for non LL address
[1769154746.730] [234597:234599] [DIS] UDP:[fd11:25::5318:efbe:829e:daf1%br-3ddb1bb9db70]:5540: score has not improved: 5 (for 69C2586FB58E786E-0000000000000002)
[1769154746.730] [234597:234599] [DIS] Checking node lookup status for 69C2586FB58E786E-0000000000000002 after 6 ms
[1769154746.730] [234597:234599] [DIS] Keeping DNSSD lookup active
[1769154746.730] [234597:234599] [DIS] Lookup clearing interface for non LL address
[1769154746.730] [234597:234599] [DIS] UDP:[fd11:25::5318:efbe:829e:daf1%br-3ddb1bb9db70]:5540: score has not improved: 5 (for 69C2586FB58E786E-0000000000000002)
[1769154746.730] [234597:234599] [DIS] Checking node lookup status for 69C2586FB58E786E-0000000000000002 after 6 ms
[1769154746.730] [234597:234599] [DIS] Keeping DNSSD lookup active
[1769154746.732] [234597:234599] [DIS] Lookup clearing interface for non LL address
[1769154746.732] [234597:234599] [DIS] UDP:[fd11:25::5318:efbe:829e:daf1%br-2a23e734cc28]:5540: score has not improved: 5 (for 69C2586FB58E786E-0000000000000002)
[1769154746.732] [234597:234599] [DIS] Checking node lookup status for 69C2586FB58E786E-0000000000000002 after 8 ms
[1769154746.732] [234597:234599] [DIS] Keeping DNSSD lookup active
[1769154746.732] [234597:234599] [DIS] Lookup clearing interface for non LL address
[1769154746.733] [234597:234599] [DIS] UDP:[fd11:25::5318:efbe:829e:daf1%br-2a23e734cc28]:5540: score has not improved: 5 (for 69C2586FB58E786E-0000000000000002)
[1769154746.733] [234597:234599] [DIS] Checking node lookup status for 69C2586FB58E786E-0000000000000002 after 8 ms
[1769154746.733] [234597:234599] [DIS] Keeping DNSSD lookup active
[1769154746.733] [234597:234599] [DIS] Lookup clearing interface for non LL address
[1769154746.733] [234597:234599] [DIS] UDP:[fd11:25::5318:efbe:829e:daf1%vethdaf5719]:5540: score has not improved: 5 (for 69C2586FB58E786E-0000000000000002)
[1769154746.733] [234597:234599] [DIS] Checking node lookup status for 69C2586FB58E786E-0000000000000002 after 9 ms
[1769154746.733] [234597:234599] [DIS] Keeping DNSSD lookup active
[1769154746.734] [234597:234599] [DIS] Lookup clearing interface for non LL address
[1769154746.734] [234597:234599] [DIS] UDP:[fd11:25::5318:efbe:829e:daf1%veth2b97f27]:5540: score has not improved: 5 (for 69C2586FB58E786E-0000000000000002)
[1769154746.734] [234597:234599] [DIS] Checking node lookup status for 69C2586FB58E786E-0000000000000002 after 10 ms
[1769154746.734] [234597:234599] [DIS] Keeping DNSSD lookup active
[1769154746.735] [234597:234599] [DIS] Lookup clearing interface for non LL address
[1769154746.735] [234597:234599] [DIS] UDP:[fd11:25::5318:efbe:829e:daf1%vethb213e12]:5540: score has not improved: 5 (for 69C2586FB58E786E-0000000000000002)
[1769154746.735] [234597:234599] [DIS] Checking node lookup status for 69C2586FB58E786E-0000000000000002 after 11 ms
[1769154746.735] [234597:234599] [DIS] Keeping DNSSD lookup active
[1769154746.736] [234597:234599] [DIS] Lookup clearing interface for non LL address
[1769154746.736] [234597:234599] [DIS] UDP:[fd11:25::5318:efbe:829e:daf1%veth5479bfb]:5540: score has not improved: 5 (for 69C2586FB58E786E-0000000000000002)
[1769154746.736] [234597:234599] [DIS] Checking node lookup status for 69C2586FB58E786E-0000000000000002 after 12 ms
[1769154746.736] [234597:234599] [DIS] Keeping DNSSD lookup active
[1769154746.736] [234597:234599] [DIS] Lookup clearing interface for non LL address
[1769154746.736] [234597:234599] [DIS] UDP:[fd11:25::5318:efbe:829e:daf1%vethd4182d3]:5540: score has not improved: 5 (for 69C2586FB58E786E-0000000000000002)
[1769154746.736] [234597:234599] [DIS] Checking node lookup status for 69C2586FB58E786E-0000000000000002 after 12 ms
[1769154746.736] [234597:234599] [DIS] Keeping DNSSD lookup active
[1769154746.924] [234597:234599] [DIS] Checking node lookup status for 69C2586FB58E786E-0000000000000002 after 200 ms
[1769154746.924] [234597:234599] [DIS] OperationalSessionSetup[1:0000000000000002]: Updating device address to UDP:[fd11:25::5318:efbe:829e:daf1]:5540 while in state 2
[1769154746.924] [234597:234599] [DIS] OperationalSessionSetup[1:0000000000000002]: State change 2 --> 3
[1769154746.925] [234597:234599] [IN] SecureSession[0xffff7c00c070]: Allocated Type:2 LSID:21621
[1769154746.925] [234597:234599] [SC] Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000002
[1769154746.927] [234597:234599] [EM] <<< [E:60840i S:0 M:196631889] (U) Msg TX from 7B2BFFA4C9058961 to 0:0000000000000000 [0000] [UDP:[fd11:25::5318:efbe:829e:daf1]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) (B:196)
[1769154746.928] [234597:234599] [EM] ??1 [E:60840i S:0 M:196631889] (U) Msg Retransmission to 0:0000000000000000 scheduled for 3336ms from now [State:Idle II:3000 AI:2200 AT:300]
[1769154746.928] [234597:234599] [SC] Sent Sigma1 msg to <0000000000000002, 1> [II:500ms AI:300ms AT:4000ms]
[1769154746.928] [234597:234599] [DIS] OperationalSessionSetup[1:0000000000000002]: State change 3 --> 4
[1769154747.030] [234597:234599] [EM] >>> [E:60840i S:0 M:259727808 (Ack:196631889)] (U) Msg RX from 0:0000000000000000 [0000] to 7B2BFFA4C9058961 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1769154747.030] [234597:234599] [EM] Found matching exchange: 60840i, Delegate: 0xffff7c00bd88
[1769154747.030] [234597:234599] [EM] Rxd Ack; Removing MessageCounter:196631889 from Retrans Table on exchange 60840i
[1769154747.225] [234597:234599] [EM] >>> [E:60840i S:0 M:259727809 (Ack:196631889)] (U) Msg RX from 0:0000000000000000 [0000] to 7B2BFFA4C9058961 --- Type 0000:31 (SecureChannel:CASE_Sigma2) (B:751)
[1769154747.226] [234597:234599] [EM] Found matching exchange: 60840i, Delegate: 0xffff7c00bd88
[1769154747.226] [234597:234599] [EM] CHIP MessageCounter:196631889 not in RetransTable on exchange 60840i
[1769154747.226] [234597:234599] [SC] Received Sigma2 msg
[1769154747.226] [234597:234599] [SC] Found MRP parameters in the message
[1769154747.231] [234597:234599] [SC] Peer <0000000000000002, 1> assigned session ID 11643
[1769154747.231] [234597:234599] [SC] Sending Sigma3
[1769154747.232] [234597:234599] [EM] <<< [E:60840i S:0 M:196631890 (Ack:259727809)] (U) Msg TX from 7B2BFFA4C9058961 to 0:0000000000000000 [0000] [UDP:[fd11:25::5318:efbe:829e:daf1]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) (B:598)
[1769154747.232] [234597:234599] [EM] ??1 [E:60840i S:0 M:196631890] (U) Msg Retransmission to 0:0000000000000000 scheduled for 2707ms from now [State:Active II:3000 AI:2200 AT:300]
[1769154747.232] [234597:234599] [SC] Sent Sigma3 msg
[1769154747.545] [234597:234599] [EM] >>> [E:60840i S:0 M:259727810 (Ack:196631890)] (U) Msg RX from 0:0000000000000000 [0000] to 7B2BFFA4C9058961 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1769154747.545] [234597:234599] [EM] Found matching exchange: 60840i, Delegate: 0xffff7c00bd88
[1769154747.545] [234597:234599] [EM] Rxd Ack; Removing MessageCounter:196631890 from Retrans Table on exchange 60840i
[1769154747.756] [234597:234599] [EM] >>> [E:60840i S:0 M:259727811 (Ack:196631890)] (U) Msg RX from 0:0000000000000000 [0000] to 7B2BFFA4C9058961 --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
[1769154747.756] [234597:234599] [EM] Found matching exchange: 60840i, Delegate: 0xffff7c00bd88
[1769154747.756] [234597:234599] [EM] CHIP MessageCounter:196631890 not in RetransTable on exchange 60840i
[1769154747.756] [234597:234599] [SC] Success status report received. Session was established
[1769154747.761] [234597:234599] [SC] SecureSession[0xffff7c00c070, LSID:21621]: State change 'kEstablishing' --> 'kActive'
[1769154747.761] [234597:234599] [IN] SecureSession[0xffff7c00c070]: Activated - Type:2 LSID:21621
[1769154747.761] [234597:234599] [IN] New secure session activated for device <0000000000000002, 1>, LSID:21621 PSID:11643!
[1769154747.761] [234597:234599] [DIS] OperationalSessionSetup[1:0000000000000002]: State change 4 --> 5
[1769154747.761] [234597:234599] [TOO] Sending ReadAttribute to:
[1769154747.761] [234597:234599] [TOO] cluster 0x0000_0033, attribute: 0x0000_0001, endpoint 0
[1769154747.761] [234597:234599] [DMG] SendReadRequest ReadClient[0xffff7c00ea20]: Sending Read Request
[1769154747.761] [234597:234599] [DMG] 0 data version filters provided, 0 not relevant, 0 encoded, 0 skipped due to lack of space
[1769154747.761] [234597:234599] [EM] <<< [E:60841i S:21621 M:149374553] (S) Msg TX from 000000000001B669 to 1:0000000000000002 [786E] [UDP:[fd11:25::5318:efbe:829e:daf1]:5540] --- Type 0001:02 (IM:ReadRequest) (B:51)
[1769154747.762] [234597:234599] [EM] ??1 [E:60841i S:21621 M:149374553] (S) Msg Retransmission to 1:0000000000000002 scheduled for 2699ms from now [State:Active II:3000 AI:2200 AT:300]
[1769154747.762] [234597:234599] [DMG] MoveToState ReadClient[0xffff7c00ea20]: Moving to [AwaitingIn]
[1769154747.762] [234597:234599] [EM] <<< [E:60840i S:0 M:196631891 (Ack:259727811)] (U) Msg TX from 7B2BFFA4C9058961 to 0:0000000000000000 [0000] [UDP:[fd11:25::5318:efbe:829e:daf1]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1769154747.762] [234597:234599] [EM] Flushed pending ack for MessageCounter:259727811 on exchange 60840i
[1769154747.965] [234597:234599] [EM] >>> [E:60841i S:21621 M:11254306 (Ack:149374553)] (S) Msg RX from 1:0000000000000002 [786E] to 000000000001B669 --- Type 0001:05 (IM:ReportData) (B:67)
[1769154747.965] [234597:234599] [EM] Found matching exchange: 60841i, Delegate: 0xffff7c00ea30
[1769154747.965] [234597:234599] [EM] Rxd Ack; Removing MessageCounter:149374553 from Retrans Table on exchange 60841i
[1769154747.966] [234597:234599] [DMG] ReportDataMessage =
[1769154747.966] [234597:234599] [DMG] {
[1769154747.966] [234597:234599] [DMG] AttributeReportIBs =
[1769154747.966] [234597:234599] [DMG] [
[1769154747.966] [234597:234599] [DMG] AttributeReportIB =
[1769154747.966] [234597:234599] [DMG] {
[1769154747.966] [234597:234599] [DMG] AttributeStatusIB =
[1769154747.966] [234597:234599] [DMG] {
[1769154747.966] [234597:234599] [DMG] AttributePathIB =
[1769154747.966] [234597:234599] [DMG] {
[1769154747.966] [234597:234599] [DMG] Endpoint = 0x0,
[1769154747.967] [234597:234599] [DMG] Cluster = 0x33,
[1769154747.967] [234597:234599] [DMG] Attribute = 0x0000_0001,
[1769154747.967] [234597:234599] [DMG] }
[1769154747.967] [234597:234599] [DMG]
[1769154747.967] [234597:234599] [DMG] StatusIB =
[1769154747.967] [234597:234599] [DMG] {
[1769154747.967] [234597:234599] [DMG] status = 0x01 (FAILURE),
[1769154747.967] [234597:234599] [DMG] },
[1769154747.967] [234597:234599] [DMG]
[1769154747.967] [234597:234599] [DMG] },
[1769154747.967] [234597:234599] [DMG]
[1769154747.968] [234597:234599] [DMG] },
[1769154747.968] [234597:234599] [DMG]
[1769154747.968] [234597:234599] [DMG] ],
[1769154747.968] [234597:234599] [DMG]
[1769154747.968] [234597:234599] [DMG] SuppressResponse = true,
[1769154747.968] [234597:234599] [DMG] InteractionModelRevision = 11
[1769154747.968] [234597:234599] [DMG] }
[1769154747.968] [234597:234599] [TOO] Response Failure: IM Error 0x00000501: General error: 0x01 (FAILURE) <--------------------------------------------------------------------------------
[1769154747.969] [234597:234599] [EM] <<< [E:60841i S:21621 M:149374554 (Ack:11254306)] (S) Msg TX from 000000000001B669 to 1:0000000000000002 [786E] [UDP:[fd11:25::5318:efbe:829e:daf1]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[1769154747.969] [234597:234599] [EM] Flushed pending ack for MessageCounter:11254306 on exchange 60841i
[1769154747.969] [234597:234597] [CTL] Shutting down the commissioner
[1769154747.969] [234597:234597] [PAF] WiFiPAF: Closing all WiFiPAF sessions to shutdown
[1769154747.969] [234597:234597] [CTL] Shutting down the controller
[1769154747.970] [234597:234597] [IN] Expiring all sessions for fabric 0x1!!
[1769154747.970] [234597:234597] [IN] SecureSession[0xffff7c00c070]: MarkForEviction Type:2 LSID:21621
[1769154747.970] [234597:234597] [SC] SecureSession[0xffff7c00c070, LSID:21621]: State change 'kActive' --> 'kPendingEviction'
[1769154747.970] [234597:234597] [IN] SecureSession[0xffff7c00c070]: Released - Type:2 LSID:21621
[1769154747.970] [234597:234597] [FP] Forgetting fabric 0x1
[1769154747.970] [234597:234597] [TS] Pending Last Known Good Time: 2023-10-14T01:16:48
[1769154747.970] [234597:234597] [TS] Previous Last Known Good Time: 2023-10-14T01:16:48
[1769154747.970] [234597:234597] [TS] Reverted Last Known Good Time to previous value
[1769154747.970] [234597:234597] [CTL] Shutting down the commissioner
[1769154747.970] [234597:234597] [PAF] WiFiPAF: Closing all WiFiPAF sessions to shutdown
[1769154747.970] [234597:234597] [CTL] Shutting down the controller
[1769154747.970] [234597:234597] [CTL] Shutting down the System State, this will teardown the CHIP Stack
[1769154747.972] [234597:234597] [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[1769154747.972] [234597:234597] [FP] Shutting down FabricTable
[1769154747.972] [234597:234597] [TS] Pending Last Known Good Time: 2023-10-14T01:16:48
[1769154747.973] [234597:234597] [TS] Previous Last Known Good Time: 2023-10-14T01:16:48
[1769154747.973] [234597:234597] [TS] Reverted Last Known Good Time to previous value
[1769154747.982] [234597:234597] [DL] Wrote settings to /tmp/chip_counters.ini
[1769154747.982] [234597:234597] [DL] NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1769154747.982] [234597:234597] [DL] Inet Layer shutdown
[1769154747.982] [234597:234597] [DL] BLE Layer shutdown
[1769154747.982] [234597:234597] [DL] WiFi-PAF Layer shutdown
[1769154747.982] [234597:234597] [PAF] WiFiPAF: Closing all WiFiPAF sessions to shutdown
[1769154747.982] [234597:234597] [DL] System Layer shutdown
[1769154747.982] [234597:234597] [TOO] Run command failure: IM Error 0x00000501: General error: 0x01 (FAILURE)
