Hi,
In some cases, the UniqueID attribute of the Basic Information Cluster is empty (no value is set).
CONFIG_CHIP_LAST_FABRIC_REMOVED_ERASE_ONLY is enabled.
Environment:
- Board: nRF5340 DK
- SDK: NCS v2.9.2
- Sample: Door Lock
- prj.conf: CONFIG_CHIP_LAST_FABRIC_REMOVED_ERASE_ONLY=y
Steps to Reproduce:
1. Perform commissioning.
2. Perform decommissioning (remove the fabric).
3. Perform re-commissioning.
4. Read the UniqueID attribute from the Basic Information Cluster.
$ chip-tool basicinformation read unique-id 2 0
[1790241304.713] [467304:467304] [DL] ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1790241304.715] [467304:467304] [DL] ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs, IGNORING.
[1790241304.720] [467304:467304] [DL] ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1790241304.720] [467304:467304] [DL] ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1790241304.720] [467304:467304] [DL] ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1790241304.726] [467304:467304] [DL] Wrote settings to /tmp/chip_counters.ini
[1790241304.726] [467304:467304] [DL] NVS set: chip-counters/reboot-count = 3 (0x3)
[1790241304.727] [467304:467304] [DL] Got Ethernet interface: eth0
[1790241304.727] [467304:467304] [DL] Found the primary Ethernet interface:eth0
[1790241304.728] [467304:467304] [DL] Got WiFi interface: wlan0
[1790241304.731] [467304:467304] [DL] Found the primary WiFi interface:wlan0
[1790241304.731] [467304:467304] [PAF] WiFiPAF: WiFiPAFLayer::Init()
[1790241304.731] [467304:467304] [IN] UDP::Init bind&listen port=0
[1790241304.731] [467304:467304] [IN] UDP::Init bound to port=51880
[1790241304.731] [467304:467304] [IN] BLEBase::Init - setting/overriding transport
[1790241304.731] [467304:467304] [IN] WiFiPAFBase::Init - setting/overriding transport
[1790241304.731] [467304:467304] [IN] TransportMgr initialized
[1790241304.731] [467304:467304] [FP] Initializing FabricTable from persistent storage
[1790241304.732] [467304:467304] [TS] Last Known Good Time: 2023-10-14T01:16:48
[1790241304.734] [467304:467304] [FP] Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x4FC239DB662DA104, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1790241304.737] [467304:467304] [DMG] Ember attribute persistence requires setting up
[1790241304.737] [467304:467304] [ZCL] Using ZAP configuration...
[1790241304.743] [467304:467304] [DL] Avahi client registered
[1790241304.743] [467304:467304] [CTL] System State Initialized...
[1790241304.743] [467304:467304] [CTL] Setting attestation nonce to random value
[1790241304.743] [467304:467304] [CTL] Setting CSR nonce to random value
[1790241304.743] [467304:467304] [IN] UDP::Init bind&listen port=5550
[1790241304.743] [467304:467304] [IN] UDP::Init bound to port=5550
[1790241304.743] [467304:467304] [IN] TransportMgr initialized
[1790241304.744] [467304:467306] [DL] CHIP task running
[1790241304.744] [467304:467306] [DL] HandlePlatformSpecificBLEEvent 32786
[1790241304.745] [467304:467306] [CTL] Setting attestation nonce to random value
[1790241304.745] [467304:467306] [CTL] Setting CSR nonce to random value
[1790241304.746] [467304:467306] [CTL] Generating NOC
[1790241304.747] [467304:467306] [FP] Validating NOC chain
[1790241304.749] [467304:467306] [FP] NOC chain validation successful
[1790241304.750] [467304:467306] [FP] Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1790241304.750] [467304:467306] [TS] Last Known Good Time: 2023-10-14T01:16:48
[1790241304.750] [467304:467306] [TS] New proposed Last Known Good Time: 2021-01-01T00:00:00
[1790241304.750] [467304:467306] [TS] Retaining current Last Known Good Time
[1790241304.758] [467304:467306] [FP] Metadata for Fabric 0x1 persisted to storage.
[1790241304.762] [467304:467306] [TS] Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1790241304.764] [467304:467306] [CTL] Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: 4FC239DB662DA104)
[1790241304.764] [467304:467306] [IN] UDP::Init bind&listen port=5551
[1790241304.764] [467304:467306] [IN] UDP::Init bound to port=5551
[1790241304.764] [467304:467306] [IN] TransportMgr initialized
[1790241304.780] [467304:467306] [TOO] Sending command to node 0x2
[1790241304.781] [467304:467306] [CSM] FindOrEstablishSession: PeerId = [1:0000000000000002]
[1790241304.781] [467304:467306] [CSM] FindOrEstablishSession: No existing OperationalSessionSetup instance found
[1790241304.781] [467304:467306] [DIS] OperationalSessionSetup[1:0000000000000002]: State change 1 --> 2
[1790241304.781] [467304:467306] [DIS] Resolving 4FC239DB662DA104:0000000000000002 ...
[1790241304.782] [467304:467306] [DIS] Lookup started for 4FC239DB662DA104-0000000000000002
[1790241304.783] [467304:467306] [DL] Avahi resolve found
[1790241304.783] [467304:467306] [DIS] Node ID resolved for 4FC239DB662DA104-0000000000000002
[1790241304.783] [467304:467306] [DIS] Hostname: F691A7A78058A837
[1790241304.783] [467304:467306] [DIS] IP Address #1: fd11:25::fcbb:fd84:b83f:2815
[1790241304.783] [467304:467306] [DIS] Port: 5540
[1790241304.784] [467304:467306] [DIS] Mrp Interval idle: 3000 ms
[1790241304.784] [467304:467306] [DIS] Mrp Interval active: 2200 ms
[1790241304.784] [467304:467306] [DIS] Mrp Active Threshold: 300 ms
[1790241304.784] [467304:467306] [DIS] TCP Client Supported: 0
[1790241304.784] [467304:467306] [DIS] TCP Server Supported: 0
[1790241304.784] [467304:467306] [DIS] ICD: not present
[1790241304.784] [467304:467306] [DIS] Lookup clearing interface for non LL address
[1790241304.785] [467304:467306] [DIS] UDP:[fd11:25::fcbb:fd84:b83f:2815%veth5875779]:5540: new best score: 5 (for 4FC239DB662DA104-0000000000000002)
[1790241304.785] [467304:467306] [DIS] Checking node lookup status for 4FC239DB662DA104-0000000000000002 after 3 ms
[1790241304.785] [467304:467306] [DIS] Keeping DNSSD lookup active
[1790241304.982] [467304:467306] [DIS] Checking node lookup status for 4FC239DB662DA104-0000000000000002 after 201 ms
[1790241304.982] [467304:467306] [DIS] OperationalSessionSetup[1:0000000000000002]: Updating device address to UDP:[fd11:25::fcbb:fd84:b83f:2815]:5540 while in state 2
[1790241304.983] [467304:467306] [DIS] OperationalSessionSetup[1:0000000000000002]: State change 2 --> 3
[1790241304.983] [467304:467306] [IN] SecureSession[0xffff8c00bb30]: Allocated Type:2 LSID:33639
[1790241304.983] [467304:467306] [SC] Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000000000002
[1790241304.985] [467304:467306] [EM] <<< [E:8739i S:0 M:92132059] (U) Msg TX from 1179AA5E57D2C7F0 to 0:0000000000000000 [0000] [UDP:[fd11:25::fcbb:fd84:b83f:2815]:5540] --- Type 0000:30 (SecureChannel:CASE_
[1790241304.986] [467304:467306] [EM] ??1 [E:8739i S:0 M:92132059] (U) Msg Retransmission to 0:0000000000000000 scheduled for 3359ms from now [State:Idle II:3000 AI:2200 AT:300]
[1790241304.986] [467304:467306] [SC] Sent Sigma1 msg to <0000000000000002, 1> [II:500ms AI:300ms AT:4000ms]
[1790241304.986] [467304:467306] [DIS] OperationalSessionSetup[1:0000000000000002]: State change 3 --> 4
[1790241305.536] [467304:467306] [EM] >>> [E:8739i S:0 M:47193904 (Ack:92132059)] (U) Msg RX from 0:0000000000000000 [0000] to 1179AA5E57D2C7F0 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1790241305.536] [467304:467306] [EM] Found matching exchange: 8739i, Delegate: 0xffff8c00b848
[1790241305.536] [467304:467306] [EM] Rxd Ack; Removing MessageCounter:92132059 from Retrans Table on exchange 8739i
[1790241305.758] [467304:467306] [EM] >>> [E:8739i S:0 M:47193905 (Ack:92132059)] (U) Msg RX from 0:0000000000000000 [0000] to 1179AA5E57D2C7F0 --- Type 0000:31 (SecureChannel:CASE_Sigma2) (B:751)
[1790241305.758] [467304:467306] [EM] Found matching exchange: 8739i, Delegate: 0xffff8c00b848
[1790241305.758] [467304:467306] [EM] CHIP MessageCounter:92132059 not in RetransTable on exchange 8739i
[1790241305.758] [467304:467306] [SC] Received Sigma2 msg
[1790241305.758] [467304:467306] [SC] Found MRP parameters in the message
[1790241305.769] [467304:467306] [SC] Peer <0000000000000002, 1> assigned session ID 6213
[1790241305.769] [467304:467306] [SC] Sending Sigma3
[1790241305.770] [467304:467306] [EM] <<< [E:8739i S:0 M:92132060 (Ack:47193905)] (U) Msg TX from 1179AA5E57D2C7F0 to 0:0000000000000000 [0000] [UDP:[fd11:25::fcbb:fd84:b83f:2815]:5540] --- Type 0000:32 (Secu
[1790241305.770] [467304:467306] [EM] ??1 [E:8739i S:0 M:92132060] (U) Msg Retransmission to 0:0000000000000000 scheduled for 2614ms from now [State:Active II:3000 AI:2200 AT:300]
[1790241305.770] [467304:467306] [SC] Sent Sigma3 msg
[1790241306.236] [467304:467306] [EM] >>> [E:8739i S:0 M:47193906 (Ack:92132060)] (U) Msg RX from 0:0000000000000000 [0000] to 1179AA5E57D2C7F0 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:26)
[1790241306.237] [467304:467306] [EM] Found matching exchange: 8739i, Delegate: 0xffff8c00b848
[1790241306.237] [467304:467306] [EM] Rxd Ack; Removing MessageCounter:92132060 from Retrans Table on exchange 8739i
[1790241306.448] [467304:467306] [EM] >>> [E:8739i S:0 M:47193907 (Ack:92132060)] (U) Msg RX from 0:0000000000000000 [0000] to 1179AA5E57D2C7F0 --- Type 0000:40 (SecureChannel:StatusReport) (B:34)
[1790241306.448] [467304:467306] [EM] Found matching exchange: 8739i, Delegate: 0xffff8c00b848
[1790241306.449] [467304:467306] [EM] CHIP MessageCounter:92132060 not in RetransTable on exchange 8739i
[1790241306.449] [467304:467306] [SC] Success status report received. Session was established
[1790241306.456] [467304:467306] [SC] SecureSession[0xffff8c00bb30, LSID:33639]: State change 'kEstablishing' --> 'kActive'
[1790241306.456] [467304:467306] [IN] SecureSession[0xffff8c00bb30]: Activated - Type:2 LSID:33639
[1790241306.456] [467304:467306] [IN] New secure session activated for device <0000000000000002, 1>, LSID:33639 PSID:6213!
[1790241306.457] [467304:467306] [DIS] OperationalSessionSetup[1:0000000000000002]: State change 4 --> 5
[1790241306.457] [467304:467306] [TOO] Sending ReadAttribute to:
[1790241306.457] [467304:467306] [TOO] cluster 0x0000_0028, attribute: 0x0000_0012, endpoint 0
[1790241306.457] [467304:467306] [DMG] SendReadRequest ReadClient[0xffff8c00eaf0]: Sending Read Request
[1790241306.457] [467304:467306] [DMG] 0 data version filters provided, 0 not relevant, 0 encoded, 0 skipped due to lack of space
[1790241306.457] [467304:467306] [EM] <<< [E:8740i S:33639 M:106557212] (S) Msg TX from 000000000001B669 to 1:0000000000000002 [A104] [UDP:[fd11:25::fcbb:fd84:b83f:2815]:5540] --- Type 0001:02 (IM:ReadRequest
[1790241306.458] [467304:467306] [EM] ??1 [E:8740i S:33639 M:106557212] (S) Msg Retransmission to 1:0000000000000002 scheduled for 2645ms from now [State:Active II:3000 AI:2200 AT:300]
[1790241306.458] [467304:467306] [DMG] MoveToState ReadClient[0xffff8c00eaf0]: Moving to [AwaitingIn]
[1790241306.458] [467304:467306] [EM] <<< [E:8739i S:0 M:92132061 (Ack:47193907)] (U) Msg TX from 1179AA5E57D2C7F0 to 0:0000000000000000 [0000] [UDP:[fd11:25::fcbb:fd84:b83f:2815]:5540] --- Type 0000:10 (Secu
[1790241306.458] [467304:467306] [EM] Flushed pending ack for MessageCounter:47193907 on exchange 8739i
[1790241306.458] [467304:467306] [DL] HandlePlatformSpecificBLEEvent 32792
[1790241306.752] [467304:467306] [EM] >>> [E:8740i S:33639 M:191114545 (Ack:106557212)] (S) Msg RX from 1:0000000000000002 [A104] to 000000000001B669 --- Type 0001:05 (IM:ReportData) (B:70)
[1790241306.752] [467304:467306] [EM] Found matching exchange: 8740i, Delegate: 0xffff8c00eb00
[1790241306.752] [467304:467306] [EM] Rxd Ack; Removing MessageCounter:106557212 from Retrans Table on exchange 8740i
[1790241306.753] [467304:467306] [DMG] ReportDataMessage =
[1790241306.753] [467304:467306] [DMG] {
[1790241306.753] [467304:467306] [DMG] AttributeReportIBs =
[1790241306.753] [467304:467306] [DMG] [
[1790241306.753] [467304:467306] [DMG] AttributeReportIB =
[1790241306.753] [467304:467306] [DMG] {
[1790241306.753] [467304:467306] [DMG] AttributeDataIB =
[1790241306.753] [467304:467306] [DMG] {
[1790241306.753] [467304:467306] [DMG] DataVersion = 0x29433f05,
[1790241306.753] [467304:467306] [DMG] AttributePathIB =
[1790241306.753] [467304:467306] [DMG] {
[1790241306.753] [467304:467306] [DMG] Endpoint = 0x0,
[1790241306.753] [467304:467306] [DMG] Cluster = 0x28,
[1790241306.754] [467304:467306] [DMG] Attribute = 0x0000_0012,
[1790241306.754] [467304:467306] [DMG] }
[1790241306.754] [467304:467306] [DMG]
[1790241306.754] [467304:467306] [DMG] Data = "" (0 chars), <---------------------------------------------------- empty
[1790241306.754] [467304:467306] [DMG] },
[1790241306.754] [467304:467306] [DMG]
[1790241306.754] [467304:467306] [DMG] },
[1790241306.754] [467304:467306] [DMG]
[1790241306.754] [467304:467306] [DMG] ],
[1790241306.754] [467304:467306] [DMG]
[1790241306.754] [467304:467306] [DMG] SuppressResponse = true,
[1790241306.754] [467304:467306] [DMG] InteractionModelRevision = 11
[1790241306.754] [467304:467306] [DMG] }
[1790241306.755] [467304:467306] [TOO] Endpoint: 0 Cluster: 0x0000_0028 Attribute 0x0000_0012 DataVersion: 692272901
[1790241306.755] [467304:467306] [TOO] UniqueID:
[1790241306.755] [467304:467306] [EM] <<< [E:8740i S:33639 M:106557213 (Ack:191114545)] (S) Msg TX from 000000000001B669 to 1:0000000000000002 [A104] [UDP:[fd11:25::fcbb:fd84:b83f:2815]:5540] --- Type 0000:10
[1790241306.755] [467304:467306] [EM] Flushed pending ack for MessageCounter:191114545 on exchange 8740i
[1790241306.756] [467304:467304] [CTL] Shutting down the commissioner
[1790241306.756] [467304:467304] [PAF] WiFiPAF: Closing all WiFiPAF sessions to shutdown
[1790241306.756] [467304:467304] [CTL] Shutting down the controller
[1790241306.756] [467304:467304] [IN] Expiring all sessions for fabric 0x1!!
[1790241306.756] [467304:467304] [IN] SecureSession[0xffff8c00bb30]: MarkForEviction Type:2 LSID:33639
[1790241306.756] [467304:467304] [SC] SecureSession[0xffff8c00bb30, LSID:33639]: State change 'kActive' --> 'kPendingEviction'
[1790241306.756] [467304:467304] [IN] SecureSession[0xffff8c00bb30]: Released - Type:2 LSID:33639
[1790241306.756] [467304:467304] [FP] Forgetting fabric 0x1
[1790241306.756] [467304:467304] [TS] Pending Last Known Good Time: 2023-10-14T01:16:48
[1790241306.757] [467304:467304] [TS] Previous Last Known Good Time: 2023-10-14T01:16:48
[1790241306.757] [467304:467304] [TS] Reverted Last Known Good Time to previous value
[1790241306.757] [467304:467304] [CTL] Shutting down the commissioner
[1790241306.757] [467304:467304] [PAF] WiFiPAF: Closing all WiFiPAF sessions to shutdown
[1790241306.757] [467304:467304] [CTL] Shutting down the controller
[1790241306.757] [467304:467304] [CTL] Shutting down the System State, this will teardown the CHIP Stack
[1790241306.758] [467304:467304] [DMG] All ReadHandler-s are clean, clear GlobalDirtySet
[1790241306.758] [467304:467304] [FP] Shutting down FabricTable
[1790241306.758] [467304:467304] [TS] Pending Last Known Good Time: 2023-10-14T01:16:48
[1790241306.758] [467304:467304] [TS] Previous Last Known Good Time: 2023-10-14T01:16:48
[1790241306.758] [467304:467304] [TS] Reverted Last Known Good Time to previous value
[1790241306.765] [467304:467304] [DL] Wrote settings to /tmp/chip_counters.ini
[1790241306.766] [467304:467304] [DL] NVS set: chip-counters/total-operational-hours = 0 (0x0)
[1790241306.766] [467304:467304] [DL] Inet Layer shutdown
[1790241306.766] [467304:467304] [DL] BLE Layer shutdown
[1790241306.766] [467304:467304] [DL] WiFi-PAF Layer shutdown
[1790241306.766] [467304:467304] [PAF] WiFiPAF: Closing all WiFiPAF sessions to shutdown
[1790241306.766] [467304:467304] [DL] System Layer shutdown
