Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

[BUG] Cannot pair with SetCheckForMatchingFabric(true) anymore after #29427 #30414

Closed
Emill opened this issue Nov 10, 2023 · 0 comments · Fixed by #30613
Closed

[BUG] Cannot pair with SetCheckForMatchingFabric(true) anymore after #29427 #30414

Emill opened this issue Nov 10, 2023 · 0 comments · Fixed by #30613
Assignees
@erjiaqing
Labels
bug Something isn't working linux needs triage

Comments

@Emill
Copy link

Emill commented Nov 10, 2023 •
edited
Loading

Reproduction steps

  1. In PairingCommand::GetCommissioningParameters() in the file examples/chip-tool/commands/pairing/PairingCommand.cpp, set params.SetCheckForMatchingFabric(true);.
  2. Compile chip-tool.
  3. Try to pair to some device using e.g. ./chip-tool pairing code 2 1596-874-0419 (in my case a Nanoleaf light strip).
  4. Watch it fail with Run command failure: src/app/ClusterStateCache.cpp:323: CHIP Error 0x00000010: Key not found.

Full log:

$ ./chip-tool pairing code 2 1596-874-0419
[1699624844.400245][101493:101493] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_tool_kvs
[1699624844.400532][101493:101493] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1699624844.400538][101493:101493] CHIP:DL: ChipLinuxStorage::Init: Attempt to re-initialize with KVS config file: /tmp/chip_kvs
[1699624844.403883][101493:101493] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1699624844.403912][101493:101493] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1699624844.403923][101493:101493] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1699624844.403965][101493:101493] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-khVe1a)
[1699624844.403991][101493:101493] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1699624844.403994][101493:101493] CHIP:DL: NVS set: chip-counters/reboot-count = 115 (0x73)
[1699624844.404213][101493:101493] CHIP:DL: Got Ethernet interface: enp0s31f6
[1699624844.404387][101493:101493] CHIP:DL: Found the primary Ethernet interface:enp0s31f6
[1699624844.404546][101493:101493] CHIP:DL: Got WiFi interface: wlp0s20f3
[1699624844.404552][101493:101493] CHIP:DL: Failed to reset WiFi statistic counts
[1699624844.404560][101493:101493] CHIP:IN: UDP::Init bind&listen port=0
[1699624844.404574][101493:101493] CHIP:IN: UDP::Init bound to port=53293
[1699624844.404579][101493:101493] CHIP:IN: UDP::Init bind&listen port=0
[1699624844.404586][101493:101493] CHIP:IN: UDP::Init bound to port=37717
[1699624844.404588][101493:101493] CHIP:IN: BLEBase::Init - setting/overriding transport
[1699624844.404590][101493:101493] CHIP:IN: TransportMgr initialized
[1699624844.404694][101493:101493] CHIP:FP: Initializing FabricTable from persistent storage
[1699624844.404872][101493:101493] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1699624844.405351][101493:101493] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0xA77ABB0AD2406C1A, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1
[1699624844.405451][101493:101493] CHIP:ZCL: Using ZAP configuration...
[1699624844.407741][101493:101493] CHIP:CTL: System State Initialized...
[1699624844.407943][101493:101493] CHIP:CTL: Setting attestation nonce to random value
[1699624844.407947][101493:101493] CHIP:CTL: Setting CSR nonce to random value
[1699624844.408003][101493:101495] CHIP:DL: CHIP task running
[1699624844.408020][101493:101495] CHIP:DL: HandlePlatformSpecificBLEEvent 32784
[1699624844.408073][101493:101495] CHIP:CTL: Setting attestation nonce to random value
[1699624844.408091][101493:101495] CHIP:CTL: Setting CSR nonce to random value
[1699624844.408814][101493:101495] CHIP:CTL: Generating NOC
[1699624844.409487][101493:101495] CHIP:FP: Validating NOC chain
[1699624844.409791][101493:101495] CHIP:FP: NOC chain validation successful
[1699624844.409814][101493:101495] CHIP:FP: Updated fabric at index: 0x1, Node ID: 0x000000000001B669
[1699624844.409817][101493:101495] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48
[1699624844.409819][101493:101495] CHIP:TS: New proposed Last Known Good Time: 2021-01-01T00:00:00
[1699624844.409821][101493:101495] CHIP:TS: Retaining current Last Known Good Time
[1699624844.410015][101493:101495] CHIP:FP: Metadata for Fabric 0x1 persisted to storage.
[1699624844.410075][101493:101495] CHIP:TS: Committing Last Known Good Time to storage: 2023-10-14T01:16:48
[1699624844.410130][101493:101495] CHIP:CTL: Joined the fabric at index 1. Fabric ID is 0x0000000000000001 (Compressed Fabric ID: A77ABB0AD2406C1A)
[1699624844.411302][101493:101495] CHIP:CTL: Setting attestation nonce to random value
[1699624844.411308][101493:101495] CHIP:CTL: Setting CSR nonce to random value
[1699624844.411322][101493:101495] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1699624844.411326][101493:101495] CHIP:CTL: Starting commissioning discovery over DNS-SD
[1699624844.724361][101493:101495] CHIP:CTL: Discovered device to be commissioned over DNS-SD
[1699624844.724419][101493:101495] CHIP:CTL: Attempting PASE connection to UDP:[fd5c:1682:6397:1:b7a7:483b:c913:984c]:5540
[1699624844.724816][101493:101495] CHIP:IN: SecureSession[0x7f04a000af20]: Allocated Type:1 LSID:46974
[1699624844.724849][101493:101495] CHIP:SC: Assigned local session key ID 46974
[1699624844.724919][101493:101495] CHIP:EM: <<< [E:51500i S:0 M:238279962] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd5c:1682:6397:1:b7a7:483b:c913:984c]:5540] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[1699624844.725025][101493:101495] CHIP:SC: Sent PBKDF param request
[1699624844.725036][101493:101495] CHIP:CTL: Commission called for node ID 0x0000000000000002
[1699624844.778978][101493:101495] CHIP:EM: >>> [E:51500i S:0 M:67754947 (Ack:238279962)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1699624844.779000][101493:101495] CHIP:EM: Found matching exchange: 51500i, Delegate: 0x7f04a000d100
[1699624844.779013][101493:101495] CHIP:EM: Rxd Ack; Removing MessageCounter:238279962 from Retrans Table on exchange 51500i
[1699624844.812110][101493:101495] CHIP:EM: >>> [E:51500i S:0 M:67754948 (Ack:238279962)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
[1699624844.812134][101493:101495] CHIP:EM: Found matching exchange: 51500i, Delegate: 0x7f04a000d100
[1699624844.812141][101493:101495] CHIP:EM: CHIP MessageCounter:238279962 not in RetransTable on exchange 51500i
[1699624844.812164][101493:101495] CHIP:SC: Received PBKDF param response
[1699624844.812181][101493:101495] CHIP:SC: Peer assigned session ID 60660
[1699624844.812190][101493:101495] CHIP:SC: Found MRP parameters in the message
[1699624844.823283][101493:101495] CHIP:EM: <<< [E:51500i S:0 M:238279963 (Ack:67754948)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd5c:1682:6397:1:b7a7:483b:c913:984c%br0]:5540] --- Type 0000:22 (SecureChannel:PASE_Pake1)
[1699624844.823318][101493:101495] CHIP:SC: Sent spake2p msg1
[1699624845.723290][101493:101495] CHIP:EM: Retransmitting MessageCounter:238279963 on exchange 51500i Send Cnt 1
[1699624846.634926][101493:101495] CHIP:EM: Retransmitting MessageCounter:238279963 on exchange 51500i Send Cnt 2
[1699624848.177821][101493:101495] CHIP:EM: Retransmitting MessageCounter:238279963 on exchange 51500i Send Cnt 3
[1699624848.914347][101493:101495] CHIP:EM: >>> [E:51500i S:0 M:67754949 (Ack:238279963)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1699624848.914387][101493:101495] CHIP:EM: Found matching exchange: 51500i, Delegate: 0x7f04a000d100
[1699624848.914404][101493:101495] CHIP:EM: Rxd Ack; Removing MessageCounter:238279963 from Retrans Table on exchange 51500i
[1699624848.922154][101493:101495] CHIP:EM: >>> [E:51500i S:0 M:67754950 (Ack:238279963)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
[1699624848.922195][101493:101495] CHIP:EM: Found matching exchange: 51500i, Delegate: 0x7f04a000d100
[1699624848.922205][101493:101495] CHIP:EM: CHIP MessageCounter:238279963 not in RetransTable on exchange 51500i
[1699624848.922230][101493:101495] CHIP:SC: Received spake2p msg2
[1699624848.923148][101493:101495] CHIP:EM: <<< [E:51500i S:0 M:238279964 (Ack:67754950)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd5c:1682:6397:1:b7a7:483b:c913:984c%br0]:5540] --- Type 0000:24 (SecureChannel:PASE_Pake3)
[1699624848.923247][101493:101495] CHIP:SC: Sent spake2p msg3
[1699624848.986108][101493:101495] CHIP:EM: >>> [E:51500i S:0 M:67754951 (Ack:238279964)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1699624848.986131][101493:101495] CHIP:EM: Found matching exchange: 51500i, Delegate: 0x7f04a000d100
[1699624848.986143][101493:101495] CHIP:EM: Rxd Ack; Removing MessageCounter:238279964 from Retrans Table on exchange 51500i
[1699624849.864955][101493:101495] CHIP:EM: >>> [E:51500i S:0 M:67754952 (Ack:238279964)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[1699624849.864975][101493:101495] CHIP:EM: Found matching exchange: 51500i, Delegate: 0x7f04a000d100
[1699624849.864981][101493:101495] CHIP:EM: CHIP MessageCounter:238279964 not in RetransTable on exchange 51500i
[1699624849.865068][101493:101495] CHIP:SC: SecureSession[0x7f04a000af20, LSID:46974]: State change 'kEstablishing' --> 'kActive'
[1699624849.865073][101493:101495] CHIP:IN: SecureSession[0x7f04a000af20]: Activated - Type:1 LSID:46974
[1699624849.865075][101493:101495] CHIP:IN: New secure session activated for device <FFFFFFFB00000000, 0>, LSID:46974 PSID:60660!
[1699624849.865081][101493:101495] CHIP:CTL: Remote device completed SPAKE2+ handshake
[1699624849.865085][101493:101495] CHIP:CTL: Pairing with commissionee successful, stopping discovery
[1699624849.865087][101493:101495] CHIP:CTL: Stopping commissioning discovery over DNS-SD
[1699624849.865093][101493:101495] CHIP:TOO: Pairing Success
[1699624849.865096][101493:101495] CHIP:TOO: PASE establishment successful
[1699624849.865100][101493:101495] CHIP:CTL: Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
[1699624849.865106][101493:101495] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo'
[1699624849.865108][101493:101495] CHIP:CTL: Sending read request for commissioning information
[1699624849.865143][101493:101495] CHIP:DMG: SendReadRequest ReadClient[0x7f04a000a210]: Sending Read Request
[1699624849.865227][101493:101495] CHIP:EM: <<< [E:51501i S:46974 M:135232398] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fd5c:1682:6397:1:b7a7:483b:c913:984c%br0]:5540] --- Type 0001:02 (IM:ReadRequest)
[1699624849.865290][101493:101495] CHIP:DMG: MoveToState ReadClient[0x7f04a000a210]: Moving to [AwaitingIn]
[1699624849.865310][101493:101495] CHIP:EM: <<< [E:51500i S:0 M:238279965 (Ack:67754952)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fd5c:1682:6397:1:b7a7:483b:c913:984c%br0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1699624849.865324][101493:101495] CHIP:EM: Flushed pending ack for MessageCounter:67754952 on exchange 51500i
[1699624850.102784][101493:101495] CHIP:DIS: SRV record already actively processed.
[1699624850.102885][101493:101495] CHIP:DIS: SRV record already actively processed.
[1699624850.102932][101493:101495] CHIP:DIS: SRV record already actively processed.
[1699624850.209303][101493:101495] CHIP:IN: Received unknown unsecure packet for initiator 0xFA8D36FB7B2CBF09
[1699624850.957849][101493:101495] CHIP:EM: Retransmitting MessageCounter:135232398 on exchange 51501i Send Cnt 1
[1699624851.208944][101493:101495] CHIP:EM: >>> [E:51501i S:46974 M:165831196 (Ack:135232398)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
[1699624851.208988][101493:101495] CHIP:EM: Found matching exchange: 51501i, Delegate: 0x7f04a000a220
[1699624851.209006][101493:101495] CHIP:EM: Rxd Ack; Removing MessageCounter:135232398 from Retrans Table on exchange 51501i
[1699624851.209072][101493:101495] CHIP:DMG: ReportDataMessage =
[1699624851.209081][101493:101495] CHIP:DMG: {
[1699624851.209089][101493:101495] CHIP:DMG:    AttributeReportIBs =
[1699624851.209103][101493:101495] CHIP:DMG:    [
[1699624851.209109][101493:101495] CHIP:DMG:            AttributeReportIB =
[1699624851.209121][101493:101495] CHIP:DMG:            {
[1699624851.209133][101493:101495] CHIP:DMG:                    AttributeDataIB =
[1699624851.209143][101493:101495] CHIP:DMG:                    {
[1699624851.209153][101493:101495] CHIP:DMG:                            DataVersion = 0x3024df61,
[1699624851.209168][101493:101495] CHIP:DMG:                            AttributePathIB =
[1699624851.209177][101493:101495] CHIP:DMG:                            {
[1699624851.209186][101493:101495] CHIP:DMG:                                    Endpoint = 0x0,
[1699624851.209196][101493:101495] CHIP:DMG:                                    Cluster = 0x31,
[1699624851.209206][101493:101495] CHIP:DMG:                                    Attribute = 0x0000_0003,
[1699624851.209214][101493:101495] CHIP:DMG:                            }
[1699624851.209225][101493:101495] CHIP:DMG: 
[1699624851.209235][101493:101495] CHIP:DMG:                            Data = 20, 
[1699624851.209243][101493:101495] CHIP:DMG:                    },
[1699624851.209254][101493:101495] CHIP:DMG: 
[1699624851.209261][101493:101495] CHIP:DMG:            },
[1699624851.209278][101493:101495] CHIP:DMG: 
[1699624851.209284][101493:101495] CHIP:DMG:            AttributeReportIB =
[1699624851.209298][101493:101495] CHIP:DMG:            {
[1699624851.209304][101493:101495] CHIP:DMG:                    AttributeDataIB =
[1699624851.209313][101493:101495] CHIP:DMG:                    {
[1699624851.209321][101493:101495] CHIP:DMG:                            DataVersion = 0x1438a7dd,
[1699624851.209328][101493:101495] CHIP:DMG:                            AttributePathIB =
[1699624851.209336][101493:101495] CHIP:DMG:                            {
[1699624851.209345][101493:101495] CHIP:DMG:                                    Endpoint = 0x0,
[1699624851.209353][101493:101495] CHIP:DMG:                                    Cluster = 0x28,
[1699624851.209362][101493:101495] CHIP:DMG:                                    Attribute = 0x0000_0004,
[1699624851.209369][101493:101495] CHIP:DMG:                            }
[1699624851.209380][101493:101495] CHIP:DMG: 
[1699624851.209388][101493:101495] CHIP:DMG:                            Data = 68, 
[1699624851.209395][101493:101495] CHIP:DMG:                    },
[1699624851.209406][101493:101495] CHIP:DMG: 
[1699624851.209412][101493:101495] CHIP:DMG:            },
[1699624851.209428][101493:101495] CHIP:DMG: 
[1699624851.209434][101493:101495] CHIP:DMG:            AttributeReportIB =
[1699624851.209446][101493:101495] CHIP:DMG:            {
[1699624851.209453][101493:101495] CHIP:DMG:                    AttributeDataIB =
[1699624851.209461][101493:101495] CHIP:DMG:                    {
[1699624851.209469][101493:101495] CHIP:DMG:                            DataVersion = 0x1438a7dd,
[1699624851.209476][101493:101495] CHIP:DMG:                            AttributePathIB =
[1699624851.209484][101493:101495] CHIP:DMG:                            {
[1699624851.209492][101493:101495] CHIP:DMG:                                    Endpoint = 0x0,
[1699624851.209500][101493:101495] CHIP:DMG:                                    Cluster = 0x28,
[1699624851.209509][101493:101495] CHIP:DMG:                                    Attribute = 0x0000_0002,
[1699624851.209516][101493:101495] CHIP:DMG:                            }
[1699624851.209526][101493:101495] CHIP:DMG: 
[1699624851.209535][101493:101495] CHIP:DMG:                            Data = 4442, 
[1699624851.209542][101493:101495] CHIP:DMG:                    },
[1699624851.209553][101493:101495] CHIP:DMG: 
[1699624851.209559][101493:101495] CHIP:DMG:            },
[1699624851.209574][101493:101495] CHIP:DMG: 
[1699624851.209580][101493:101495] CHIP:DMG:            AttributeReportIB =
[1699624851.209592][101493:101495] CHIP:DMG:            {
[1699624851.209598][101493:101495] CHIP:DMG:                    AttributeDataIB =
[1699624851.209606][101493:101495] CHIP:DMG:                    {
[1699624851.209614][101493:101495] CHIP:DMG:                            DataVersion = 0xd0b70867,
[1699624851.209621][101493:101495] CHIP:DMG:                            AttributePathIB =
[1699624851.209629][101493:101495] CHIP:DMG:                            {
[1699624851.209637][101493:101495] CHIP:DMG:                                    Endpoint = 0x0,
[1699624851.209646][101493:101495] CHIP:DMG:                                    Cluster = 0x30,
[1699624851.209654][101493:101495] CHIP:DMG:                                    Attribute = 0x0000_0003,
[1699624851.209662][101493:101495] CHIP:DMG:                            }
[1699624851.209672][101493:101495] CHIP:DMG: 
[1699624851.209681][101493:101495] CHIP:DMG:                            Data = 0, 
[1699624851.209688][101493:101495] CHIP:DMG:                    },
[1699624851.209698][101493:101495] CHIP:DMG: 
[1699624851.209705][101493:101495] CHIP:DMG:            },
[1699624851.209719][101493:101495] CHIP:DMG: 
[1699624851.209725][101493:101495] CHIP:DMG:            AttributeReportIB =
[1699624851.209737][101493:101495] CHIP:DMG:            {
[1699624851.209744][101493:101495] CHIP:DMG:                    AttributeDataIB =
[1699624851.209752][101493:101495] CHIP:DMG:                    {
[1699624851.209759][101493:101495] CHIP:DMG:                            DataVersion = 0xd0b70867,
[1699624851.209767][101493:101495] CHIP:DMG:                            AttributePathIB =
[1699624851.209774][101493:101495] CHIP:DMG:                            {
[1699624851.209783][101493:101495] CHIP:DMG:                                    Endpoint = 0x0,
[1699624851.209791][101493:101495] CHIP:DMG:                                    Cluster = 0x30,
[1699624851.209800][101493:101495] CHIP:DMG:                                    Attribute = 0x0000_0002,
[1699624851.209807][101493:101495] CHIP:DMG:                            }
[1699624851.209817][101493:101495] CHIP:DMG: 
[1699624851.209826][101493:101495] CHIP:DMG:                            Data = 0, 
[1699624851.209833][101493:101495] CHIP:DMG:                    },
[1699624851.209843][101493:101495] CHIP:DMG: 
[1699624851.209850][101493:101495] CHIP:DMG:            },
[1699624851.209865][101493:101495] CHIP:DMG: 
[1699624851.209871][101493:101495] CHIP:DMG:            AttributeReportIB =
[1699624851.209884][101493:101495] CHIP:DMG:            {
[1699624851.209891][101493:101495] CHIP:DMG:                    AttributeDataIB =
[1699624851.209898][101493:101495] CHIP:DMG:                    {
[1699624851.209906][101493:101495] CHIP:DMG:                            DataVersion = 0xd0b70867,
[1699624851.209913][101493:101495] CHIP:DMG:                            AttributePathIB =
[1699624851.209921][101493:101495] CHIP:DMG:                            {
[1699624851.209929][101493:101495] CHIP:DMG:                                    Endpoint = 0x0,
[1699624851.209937][101493:101495] CHIP:DMG:                                    Cluster = 0x30,
[1699624851.209945][101493:101495] CHIP:DMG:                                    Attribute = 0x0000_0001,
[1699624851.209953][101493:101495] CHIP:DMG:                            }
[1699624851.209963][101493:101495] CHIP:DMG: 
[1699624851.209970][101493:101495] CHIP:DMG:                            Data = 
[1699624851.209980][101493:101495] CHIP:DMG:                            {
[1699624851.209989][101493:101495] CHIP:DMG:                                    0x0 = 60, 
[1699624851.209998][101493:101495] CHIP:DMG:                                    0x1 = 900, 
[1699624851.210007][101493:101495] CHIP:DMG:                            },
[1699624851.210014][101493:101495] CHIP:DMG:                    },
[1699624851.210026][101493:101495] CHIP:DMG: 
[1699624851.210033][101493:101495] CHIP:DMG:            },
[1699624851.210048][101493:101495] CHIP:DMG: 
[1699624851.210054][101493:101495] CHIP:DMG:            AttributeReportIB =
[1699624851.210065][101493:101495] CHIP:DMG:            {
[1699624851.210072][101493:101495] CHIP:DMG:                    AttributeDataIB =
[1699624851.210079][101493:101495] CHIP:DMG:                    {
[1699624851.210087][101493:101495] CHIP:DMG:                            DataVersion = 0xd0b70867,
[1699624851.210094][101493:101495] CHIP:DMG:                            AttributePathIB =
[1699624851.210102][101493:101495] CHIP:DMG:                            {
[1699624851.210110][101493:101495] CHIP:DMG:                                    Endpoint = 0x0,
[1699624851.210118][101493:101495] CHIP:DMG:                                    Cluster = 0x30,
[1699624851.210126][101493:101495] CHIP:DMG:                                    Attribute = 0x0000_0000,
[1699624851.210134][101493:101495] CHIP:DMG:                            }
[1699624851.210143][101493:101495] CHIP:DMG: 
[1699624851.210152][101493:101495] CHIP:DMG:                            Data = 0, 
[1699624851.210159][101493:101495] CHIP:DMG:                    },
[1699624851.210169][101493:101495] CHIP:DMG: 
[1699624851.210176][101493:101495] CHIP:DMG:            },
[1699624851.210192][101493:101495] CHIP:DMG: 
[1699624851.210199][101493:101495] CHIP:DMG:            AttributeReportIB =
[1699624851.210209][101493:101495] CHIP:DMG:            {
[1699624851.210216][101493:101495] CHIP:DMG:                    AttributeDataIB =
[1699624851.210224][101493:101495] CHIP:DMG:                    {
[1699624851.210231][101493:101495] CHIP:DMG:                            DataVersion = 0x3024df61,
[1699624851.210238][101493:101495] CHIP:DMG:                            AttributePathIB =
[1699624851.210246][101493:101495] CHIP:DMG:                            {
[1699624851.210254][101493:101495] CHIP:DMG:                                    Endpoint = 0x0,
[1699624851.210262][101493:101495] CHIP:DMG:                                    Cluster = 0x31,
[1699624851.210271][101493:101495] CHIP:DMG:                                    Attribute = 0x0000_FFFC,
[1699624851.210278][101493:101495] CHIP:DMG:                            }
[1699624851.210288][101493:101495] CHIP:DMG: 
[1699624851.210297][101493:101495] CHIP:DMG:                            Data = 2, 
[1699624851.210303][101493:101495] CHIP:DMG:                    },
[1699624851.210314][101493:101495] CHIP:DMG: 
[1699624851.210321][101493:101495] CHIP:DMG:            },
[1699624851.210331][101493:101495] CHIP:DMG: 
[1699624851.210337][101493:101495] CHIP:DMG:    ],
[1699624851.210371][101493:101495] CHIP:DMG: 
[1699624851.210379][101493:101495] CHIP:DMG:    SuppressResponse = true, 
[1699624851.210387][101493:101495] CHIP:DMG:    InteractionModelRevision = 1
[1699624851.210393][101493:101495] CHIP:DMG: }
[1699624851.219430][101493:101495] CHIP:CTL: ----- NetworkCommissioning Features: has Thread. endpointid = 0
[1699624851.219500][101493:101495] CHIP:CTL: Successfully finished commissioning step 'ReadCommissioningInfo'
[1699624851.219513][101493:101495] CHIP:CTL: Commissioning stage next step: 'ReadCommissioningInfo' -> 'ReadCommissioningInfo2'
[1699624851.219532][101493:101495] CHIP:CTL: Performing next commissioning step 'ReadCommissioningInfo2'
[1699624851.219538][101493:101495] CHIP:CTL: Sending request for commissioning information -- Part 2
[1699624851.219556][101493:101495] CHIP:DMG: SendReadRequest ReadClient[0x7f04a000a210]: Sending Read Request
[1699624851.219712][101493:101495] CHIP:EM: <<< [E:51502i S:46974 M:135232399] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fd5c:1682:6397:1:b7a7:483b:c913:984c%br0]:5540] --- Type 0001:02 (IM:ReadRequest)
[1699624851.219822][101493:101495] CHIP:DMG: MoveToState ReadClient[0x7f04a000a210]: Moving to [AwaitingIn]
[1699624851.219870][101493:101495] CHIP:EM: <<< [E:51501i S:46974 M:135232400 (Ack:165831196)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fd5c:1682:6397:1:b7a7:483b:c913:984c%br0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1699624851.219895][101493:101495] CHIP:EM: Flushed pending ack for MessageCounter:165831196 on exchange 51501i
[1699624851.336738][101493:101495] CHIP:EM: >>> [E:51502i S:46974 M:165831197 (Ack:135232399)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
[1699624851.336758][101493:101495] CHIP:EM: Found matching exchange: 51502i, Delegate: 0x7f04a000a220
[1699624851.336771][101493:101495] CHIP:EM: Rxd Ack; Removing MessageCounter:135232399 from Retrans Table on exchange 51502i
[1699624851.336805][101493:101495] CHIP:DMG: ReportDataMessage =
[1699624851.336810][101493:101495] CHIP:DMG: {
[1699624851.336814][101493:101495] CHIP:DMG:    AttributeReportIBs =
[1699624851.336824][101493:101495] CHIP:DMG:    [
[1699624851.336828][101493:101495] CHIP:DMG:            AttributeReportIB =
[1699624851.336838][101493:101495] CHIP:DMG:            {
[1699624851.336842][101493:101495] CHIP:DMG:                    AttributeDataIB =
[1699624851.336848][101493:101495] CHIP:DMG:                    {
[1699624851.336853][101493:101495] CHIP:DMG:                            DataVersion = 0xc1a259e8,
[1699624851.336857][101493:101495] CHIP:DMG:                            AttributePathIB =
[1699624851.336862][101493:101495] CHIP:DMG:                            {
[1699624851.336868][101493:101495] CHIP:DMG:                                    Endpoint = 0x0,
[1699624851.336873][101493:101495] CHIP:DMG:                                    Cluster = 0x3e,
[1699624851.336878][101493:101495] CHIP:DMG:                                    Attribute = 0x0000_0001,
[1699624851.336882][101493:101495] CHIP:DMG:                            }
[1699624851.336888][101493:101495] CHIP:DMG: 
[1699624851.336893][101493:101495] CHIP:DMG:                            Data = [
[1699624851.336898][101493:101495] CHIP:DMG: 
[1699624851.336903][101493:101495] CHIP:DMG:                            ],
[1699624851.336907][101493:101495] CHIP:DMG:                    },
[1699624851.336913][101493:101495] CHIP:DMG: 
[1699624851.336917][101493:101495] CHIP:DMG:            },
[1699624851.336927][101493:101495] CHIP:DMG: 
[1699624851.336930][101493:101495] CHIP:DMG:            AttributeReportIB =
[1699624851.336938][101493:101495] CHIP:DMG:            {
[1699624851.336942][101493:101495] CHIP:DMG:                    AttributeDataIB =
[1699624851.336947][101493:101495] CHIP:DMG:                    {
[1699624851.336951][101493:101495] CHIP:DMG:                            DataVersion = 0xc1a259e8,
[1699624851.336955][101493:101495] CHIP:DMG:                            AttributePathIB =
[1699624851.336960][101493:101495] CHIP:DMG:                            {
[1699624851.336964][101493:101495] CHIP:DMG:                                    Endpoint = 0x0,
[1699624851.336970][101493:101495] CHIP:DMG:                                    Cluster = 0x3e,
[1699624851.336975][101493:101495] CHIP:DMG:                                    Attribute = 0x0000_0001,
[1699624851.336979][101493:101495] CHIP:DMG:                                    ListIndex = Null,
[1699624851.336983][101493:101495] CHIP:DMG:                            }
[1699624851.336989][101493:101495] CHIP:DMG: 
[1699624851.336993][101493:101495] CHIP:DMG:                            Data = 
[1699624851.336998][101493:101495] CHIP:DMG:                            {
[1699624851.337003][101493:101495] CHIP:DMG:                                    0x1 = [
[1699624851.337014][101493:101495] CHIP:DMG:                                                    0x04, 0x10, 0xd1, 0x8e, 0xe6, 0x6a, 0x35, 0xbb, 0x15, 0x1c, 0xa6, 0x98, 0x13, 0x95, 0xbb, 0x2b, 0x12, 0xd0, 0xb0, 0x07, 0x05, 0x43, 0x6f, 0x56, 0x5d, 0xe0, 0x56, 0x36, 0xc8, 0xaa, 0xe4, 0xa5, 0x10, 0xcc, 0x36, 0x32, 0x5f, 0x7c, 0x5b, 0x04, 0x28, 0x6b, 0xc9, 0x14, 0x80, 0x83, 0x14, 0xf1, 0x91, 0xd1, 0x98, 0x13, 0xda, 0x78, 0xa8, 0x84, 0xa9, 0xcc, 0xa0, 0xbf, 0x9e, 0x4e, 0xc0, 0x40, 0xdb, 
[1699624851.337023][101493:101495] CHIP:DMG:                                    ] (65 bytes)
[1699624851.337028][101493:101495] CHIP:DMG:                                    0x2 = 4362, 
[1699624851.337033][101493:101495] CHIP:DMG:                                    0x3 = 18189840129707104525, 
[1699624851.337038][101493:101495] CHIP:DMG:                                    0x4 = 12518788554772878593, 
[1699624851.337045][101493:101495] CHIP:DMG:                                    0x5 = "SmartThings Hub 8721" (20 chars), 
[1699624851.337050][101493:101495] CHIP:DMG:                                    0xfe = 1, 
[1699624851.337055][101493:101495] CHIP:DMG:                            },
[1699624851.337058][101493:101495] CHIP:DMG:                    },
[1699624851.337066][101493:101495] CHIP:DMG: 
[1699624851.337070][101493:101495] CHIP:DMG:            },
[1699624851.337081][101493:101495] CHIP:DMG: 
[1699624851.337085][101493:101495] CHIP:DMG:            AttributeReportIB =
[1699624851.337092][101493:101495] CHIP:DMG:            {
[1699624851.337096][101493:101495] CHIP:DMG:                    AttributeDataIB =
[1699624851.337100][101493:101495] CHIP:DMG:                    {
[1699624851.337105][101493:101495] CHIP:DMG:                            DataVersion = 0xc1a259e8,
[1699624851.337109][101493:101495] CHIP:DMG:                            AttributePathIB =
[1699624851.337113][101493:101495] CHIP:DMG:                            {
[1699624851.337118][101493:101495] CHIP:DMG:                                    Endpoint = 0x0,
[1699624851.337123][101493:101495] CHIP:DMG:                                    Cluster = 0x3e,
[1699624851.337127][101493:101495] CHIP:DMG:                                    Attribute = 0x0000_0001,
[1699624851.337131][101493:101495] CHIP:DMG:                                    ListIndex = Null,
[1699624851.337136][101493:101495] CHIP:DMG:                            }
[1699624851.337141][101493:101495] CHIP:DMG: 
[1699624851.337145][101493:101495] CHIP:DMG:                            Data = 
[1699624851.337150][101493:101495] CHIP:DMG:                            {
[1699624851.337154][101493:101495] CHIP:DMG:                                    0x1 = [
[1699624851.337165][101493:101495] CHIP:DMG:                                                    0x04, 0x9c, 0xcf, 0x34, 0x59, 0xc6, 0xf4, 0x1a, 0xca, 0xf7, 0x3b, 0x1a, 0x66, 0x00, 0xfc, 0x41, 0xde, 0xee, 0x3d, 0x6b, 0x2b, 0xac, 0xa3, 0xec, 0x60, 0x9d, 0x89, 0xea, 0xbc, 0xc3, 0xf2, 0x23, 0xdf, 0x4c, 0x0f, 0xbf, 0x41, 0x68, 0x46, 0xa1, 0x4e, 0x30, 0xe6, 0x2a, 0xbf, 0x8d, 0xf8, 0xaa, 0x54, 0x9c, 0x19, 0xfb, 0xf3, 0x6f, 0x29, 0xe3, 0xab, 0xf0, 0x3f, 0x6f, 0xe5, 0x58, 0xb9, 0x75, 0xfa, 
[1699624851.337173][101493:101495] CHIP:DMG:                                    ] (65 bytes)
[1699624851.337178][101493:101495] CHIP:DMG:                                    0x2 = 24582, 
[1699624851.337183][101493:101495] CHIP:DMG:                                    0x3 = 9528341463659338087, 
[1699624851.337188][101493:101495] CHIP:DMG:                                    0x4 = 12719008437906481207, 
[1699624851.337194][101493:101495] CHIP:DMG:                                    0x5 = "" (0 chars), 
[1699624851.337199][101493:101495] CHIP:DMG:                                    0xfe = 2, 
[1699624851.337203][101493:101495] CHIP:DMG:                            },
[1699624851.337207][101493:101495] CHIP:DMG:                    },
[1699624851.337214][101493:101495] CHIP:DMG: 
[1699624851.337218][101493:101495] CHIP:DMG:            },
[1699624851.337225][101493:101495] CHIP:DMG: 
[1699624851.337229][101493:101495] CHIP:DMG:    ],
[1699624851.337242][101493:101495] CHIP:DMG: 
[1699624851.337247][101493:101495] CHIP:DMG:    SuppressResponse = true, 
[1699624851.337251][101493:101495] CHIP:DMG:    InteractionModelRevision = 1
[1699624851.337254][101493:101495] CHIP:DMG: }
[1699624851.337462][101493:101495] CHIP:CTL: DeviceCommissioner::OnDone - fabric.vendorId=0x110A fabric.fabricId=0xFC6F4B395C56590D fabric.nodeId=0xADBBABDCF9769501
[1699624851.337473][101493:101495] CHIP:CTL: DeviceCommissioner::OnDone - fabric.vendorId=0x6006 fabric.fabricId=0x843B7813F00A5967 fabric.nodeId=0xB082FEC93C9CA037
[1699624851.338751][101493:101495] CHIP:CTL: Error on commissioning step 'ReadCommissioningInfo2': 'src/app/ClusterStateCache.cpp:323: CHIP Error 0x00000010: Key not found'
[1699624851.338757][101493:101495] CHIP:CTL: Failed to perform commissioning step 3
[1699624851.338762][101493:101495] CHIP:CTL: Going from commissioning step 'ReadCommissioningInfo2' with lastErr = 'src/app/ClusterStateCache.cpp:323: CHIP Error 0x00000010: Key not found' -> 'Cleanup'
[1699624851.338774][101493:101495] CHIP:CTL: Performing next commissioning step 'Cleanup' with completion status = 'src/app/ClusterStateCache.cpp:323: CHIP Error 0x00000010: Key not found'
[1699624851.338779][101493:101495] CHIP:CTL: Expiring failsafe on proxy 0x7f04a000d0b0
[1699624851.338817][101493:101495] CHIP:DMG: ICR moving to [AddingComm]
[1699624851.338830][101493:101495] CHIP:DMG: ICR moving to [AddedComma]
[1699624851.338887][101493:101495] CHIP:EM: <<< [E:51503i S:46974 M:135232401] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fd5c:1682:6397:1:b7a7:483b:c913:984c%br0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[1699624851.338955][101493:101495] CHIP:DMG: ICR moving to [CommandSen]
[1699624851.338983][101493:101495] CHIP:EM: <<< [E:51502i S:46974 M:135232402 (Ack:165831197)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fd5c:1682:6397:1:b7a7:483b:c913:984c%br0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[1699624851.339000][101493:101495] CHIP:EM: Flushed pending ack for MessageCounter:165831197 on exchange 51502i
[1699624851.416698][101493:101495] CHIP:EM: >>> [E:51503i S:46974 M:165831198 (Ack:135232401)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[1699624851.416730][101493:101495] CHIP:EM: Found matching exchange: 51503i, Delegate: 0x7f04a0009248
[1699624851.416743][101493:101495] CHIP:EM: Rxd Ack; Removing MessageCounter:135232401 from Retrans Table on exchange 51503i
[1699624851.416755][101493:101495] CHIP:DMG: ICR moving to [ResponseRe]
[1699624851.416776][101493:101495] CHIP:DMG: InvokeResponseMessage =
[1699624851.416781][101493:101495] CHIP:DMG: {
[1699624851.416785][101493:101495] CHIP:DMG:    suppressResponse = false, 
[1699624851.416788][101493:101495] CHIP:DMG:    InvokeResponseIBs =
[1699624851.416796][101493:101495] CHIP:DMG:    [
[1699624851.416802][101493:101495] CHIP:DMG:            InvokeResponseIB =
[1699624851.416810][101493:101495] CHIP:DMG:            {
[1699624851.416819][101493:101495] CHIP:DMG:                    CommandDataIB =
[1699624851.416825][101493:101495] CHIP:DMG:                    {
[1699624851.416829][101493:101495] CHIP:DMG:                            CommandPathIB =
[1699624851.416840][101493:101495] CHIP:DMG:                            {
[1699624851.416847][101493:101495] CHIP:DMG:                                    EndpointId = 0x0,
[1699624851.416853][101493:101495] CHIP:DMG:                                    ClusterId = 0x30,
[1699624851.416859][101493:101495] CHIP:DMG:                                    CommandId = 0x1,
[1699624851.416864][101493:101495] CHIP:DMG:                            },
[1699624851.416870][101493:101495] CHIP:DMG: 
[1699624851.416878][101493:101495] CHIP:DMG:                            CommandFields = 
[1699624851.416884][101493:101495] CHIP:DMG:                            {
[1699624851.416891][101493:101495] CHIP:DMG:                                    0x0 = 0, 
[1699624851.416898][101493:101495] CHIP:DMG:                                    0x1 = "" (0 chars), 
[1699624851.416904][101493:101495] CHIP:DMG:                            },
[1699624851.416909][101493:101495] CHIP:DMG:                    },
[1699624851.416917][101493:101495] CHIP:DMG: 
[1699624851.416921][101493:101495] CHIP:DMG:            },
[1699624851.416928][101493:101495] CHIP:DMG: 
[1699624851.416931][101493:101495] CHIP:DMG:    ],
[1699624851.416940][101493:101495] CHIP:DMG: 
[1699624851.416945][101493:101495] CHIP:DMG:    InteractionModelRevision = 1
[1699624851.416953][101493:101495] CHIP:DMG: },
[1699624851.416976][101493:101495] CHIP:DMG: Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[1699624851.416994][101493:101495] CHIP:CTL: Failsafe disarmed
[1699624851.417006][101493:101495] CHIP:CTL: Successfully finished commissioning step 'Cleanup'
[1699624851.417022][101493:101495] CHIP:TOO: Device commissioning Failure: src/app/ClusterStateCache.cpp:323: CHIP Error 0x00000010: Key not found
[1699624851.417042][101493:101495] CHIP:IN: SecureSession[0x7f04a000af20]: MarkForEviction Type:1 LSID:46974
[1699624851.417049][101493:101495] CHIP:SC: SecureSession[0x7f04a000af20, LSID:46974]: State change 'kActive' --> 'kPendingEviction'
[1699624851.417075][101493:101495] CHIP:EM: Failed to send Solitary ack for MessageCounter:165831198 on exchange 51503i:src/messaging/ExchangeContext.cpp:103: CHIP Error 0x00000002: Connection aborted
[1699624851.417092][101493:101495] CHIP:DMG: ICR moving to [AwaitingDe]
[1699624851.417101][101493:101495] CHIP:IN: SecureSession[0x7f04a000af20]: Released - Type:1 LSID:46974
[1699624851.417195][101493:101493] CHIP:CTL: Shutting down the commissioner
[1699624851.417215][101493:101493] CHIP:CTL: Shutting down the controller
[1699624851.417223][101493:101493] CHIP:IN: Expiring all sessions for fabric 0x1!!
[1699624851.417228][101493:101493] CHIP:FP: Forgetting fabric 0x1
[1699624851.417239][101493:101493] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1699624851.417303][101493:101493] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1699624851.417307][101493:101493] CHIP:TS: Reverted Last Known Good Time to previous value
[1699624851.417324][101493:101493] CHIP:CTL: Shutting down the commissioner
[1699624851.417327][101493:101493] CHIP:CTL: Shutting down the controller
[1699624851.417329][101493:101493] CHIP:CTL: Shutting down the System State, this will teardown the CHIP Stack
[1699624851.417402][101493:101493] CHIP:DMG: All ReadHandler-s are clean, clear GlobalDirtySet
[1699624851.417431][101493:101493] CHIP:FP: Shutting down FabricTable
[1699624851.417435][101493:101493] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1699624851.417465][101493:101493] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1699624851.417468][101493:101493] CHIP:TS: Reverted Last Known Good Time to previous value
[1699624851.417539][101493:101493] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-cGRMyV)
[1699624851.417613][101493:101493] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1699624851.417623][101493:101493] CHIP:DL: NVS set: chip-counters/total-operational-hours = 38 (0x26)
[1699624851.417628][101493:101493] CHIP:DL: Inet Layer shutdown
[1699624851.417632][101493:101493] CHIP:DL: BLE shutdown
[1699624851.417636][101493:101493] CHIP:DL: System Layer shutdown
[1699624851.417757][101493:101493] CHIP:TOO: Run command failure: src/app/ClusterStateCache.cpp:323: CHIP Error 0x00000010: Key not found

Bug prevalence

Always

GitHub hash of the SDK that was being used

6d9cb39

Platform

core

Platform Version(s)

No response

Anything else?

This bug was introduced in #29427.
There are some review comments that were published after it was merged. In particular, this step https://github.com/project-chip/connectedhomeip/pull/29427/files#r1381145851 is what is triggered. My analysis is that the situation happens because the read paths only contain the fabric attribute id and not the ICD feature map attribute path, because the strategy is ICDRegistrationStrategy::kIgnore (by default) and we requested params.SetCheckForMatchingFabric(true); . Therefore, when it later checks the attribute cache after the reply has been received, the ICD feature map attribute is obviously not present.
@Emill Emill added bug Something isn't working needs triage labels Nov 10, 2023
@github-actions github-actions bot added the linux label Nov 10, 2023
erjiaqing added a commit to erjiaqing/connectedhomeip that referenced this issue Nov 22, 2023
@erjiaqing
Should reset BUG if CHIP_ERROR_KEY_NOT_FOUND in ParseICDInfo
c53d96f 
Fixes project-chip#30604
Fixes project-chip#30414
erjiaqing added a commit to erjiaqing/connectedhomeip that referenced this issue Nov 22, 2023
@erjiaqing
Should reset err if CHIP_ERROR_KEY_NOT_FOUND in ParseICDInfo
aa73f9a 
Fixes project-chip#30604
Fixes project-chip#30414
@erjiaqing erjiaqing mentioned this issue Nov 22, 2023
Merged
erjiaqing added a commit to erjiaqing/connectedhomeip that referenced this issue Nov 22, 2023
@erjiaqing
Should reset err if CHIP_ERROR_KEY_NOT_FOUND in ParseICDInfo
af5669e 
Fixes project-chip#30604
Fixes project-chip#30414
@mergify mergify bot closed this as completed in #30613 Nov 22, 2023
mergify bot pushed a commit that referenced this issue Nov 22, 2023
@erjiaqing
Should reset err if CHIP_ERROR_KEY_NOT_FOUND in ParseICDInfo (#30613)
0c9c547 
Fixes #30604
Fixes #30414
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@erjiaqing erjiaqing

Labels
bug Something isn't working linux needs triage
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Should reset err if CHIP_ERROR_KEY_NOT_FOUND in ParseICDInfo erjiaqing/connectedhomeip
2 participants
@Emill @erjiaqing