Matter test failure about TC-DESC-2.3

Hi Nordic Support Team,

I have created an issue on GitHub regarding the device type ID error we encountered during testing. Here is the link to the issue:

github.com/.../838

Since I am unsure how long it will take to get a response, I would like to discuss this matter with your team as well.

Looking forward to your assistance.

Best regards,
Xiongwei Wang

Parents
  • Hi,

    UL has also identified an issue with [TC-IDM-6.2] (step 17) during our testing. I have reproduced this issue using the nRF52840DK with the light switch example.

    Here are the steps:
    Firstly, using the following command to pairing the device:

    ./chip-tool pairing ble-thread 1  hex:0e08000000000001000035060004001fffe00708fdb7e5dc719dbfef0410d45354fc6eefbee082acc76262c4dd2c0c0402a0f7f8000300001901025b3702085b37dead5b37beef030435623337051000112233445566778899aabbccddeeff 20202021 3840  --paa-trust-store-path /var/paa-root-certs/ --trace_decode 1
     And using ./chip-tool interactive start to enter the interactive mode. Then, executing accesscontrol subscribe-event access-control-entry-changed  20 30 1 0, Wait for the subscription response (first event number varies — sometimes 65538, sometimes 3).:

    [1767693565.629] [22611:22613] [DMG] 	],
    [1767693565.629] [22611:22613] [DMG] 	
    [1767693565.629] [22611:22613] [DMG] 	InteractionModelRevision = 12
    [1767693565.629] [22611:22613] [DMG] }
    [1767693565.629] [22611:22613] [TOO] Endpoint: 0 Cluster: 0x0000_001F Event 0x0000_0000
    [1767693565.629] [22611:22613] [TOO]   Event number: 65538
    [1767693565.629] [22611:22613] [TOO]   Priority: Info
    [1767693565.629] [22611:22613] [TOO]   Timestamp: 45519
    [1767693565.629] [22611:22613] [TOO]   AccessControlEntryChanged: {
    [1767693565.629] [22611:22613] [TOO]     AdminNodeID: null
    [1767693565.629] [22611:22613] [TOO]     AdminPasscodeID: 0
    [1767693565.629] [22611:22613] [TOO]     ChangeType: 1
    [1767693565.629] [22611:22613] [TOO]     LatestValue: {
    [1767693565.629] [22611:22613] [TOO]       Privilege: 5
    [1767693565.629] [22611:22613] [TOO]       AuthMode: 2
    [1767693565.629] [22611:22613] [TOO]       Subjects: 1 entries
    [1767693565.629] [22611:22613] [TOO]         [1]: 112233
    [1767693565.629] [22611:22613] [TOO]       Targets: null
    [1767693565.629] [22611:22613] [TOO]       FabricIndex: 1
    [1767693565.629] [22611:22613] [TOO]      }
    [1767693565.629] [22611:22613] [TOO]     FabricIndex: 1
    [1767693565.629] [22611:22613] [TOO]    }
    [1767693565.629] [22611:22613] [DMG] MoveToState ReadClient[0xffffac0117c0]: Moving to [AwaitingSu]
    [1767693565.629] [22611:22613] [EM] <<< [E:25769i S:52386 M:9137062 (Ack:119546972)] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [30B3] [UDP:[fd11:37::837e:acd0:586e:1582]:5540] --- Type 0001:01 (IM:StatusResponse) (B:42)
    [1767693565.629] [22611:22613] [EM] ??1 [E:25769i S:52386 M:9137062] (S) Msg Retransmission to 1:0000000000000001 scheduled for 2753ms from now [State:Idle II:4500 AI:2500 AT:0]
    [1767693566.182] [22611:22613] [EM] >>> [E:25769i S:52386 M:119546973 (Ack:9137062)] (S) Msg RX from 1:0000000000000001 [30B3] to 000000000001B669 --- Type 0001:04 (IM:SubscribeResponse) (B:48)
    [1767693566.182] [22611:22613] [EM] Found matching exchange: 25769i, Delegate: 0xffffac0117d0
    [1767693566.182] [22611:22613] [EM] Rxd Ack; Removing MessageCounter:9137062 from Retrans Table on exchange 25769i
    [1767693566.182] [22611:22613] [DMG] SubscribeResponse is received
    [1767693566.182] [22611:22613] [DMG] SubscribeResponseMessage =
    [1767693566.182] [22611:22613] [DMG] {
    [1767693566.182] [22611:22613] [DMG] 	SubscriptionId = 0xf142fae6,
    [1767693566.182] [22611:22613] [DMG] 	MaxInterval = 0x78,
    [1767693566.182] [22611:22613] [DMG] 	InteractionModelRevision = 12
    [1767693566.182] [22611:22613] [DMG] }
    [1767693566.182] [22611:22613] [DMG] Subscription established in 968ms with SubscriptionID = 0xf142fae6 MinInterval = 20s MaxInterval = 120s Peer = 01:0000000000000001
    [1767693566.182] [22611:22613] [DMG] MoveToState ReadClient[0xffffac0117c0]: Moving to [Subscripti]
    [1767693566.182] [22611:22613] [DMG] Refresh LivenessCheckTime for 164277 milliseconds with SubscriptionId = 0xf142fae6 Peer = 01:0000000000000001
    [1767693566.182] [22611:22613] [EM] <<< [E:25769i S:52386 M:9137063 (Ack:119546973)] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [30B3] [UDP:[fd11:37::837e:acd0:586e:1582]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
    [1767693566.182] [22611:22613] [EM] Flushed pending ack for MessageCounter:119546973 on exchange 25769i
    


    Anyway, then, we need to execute
    accesscontrol write acl '[{"fabricIndex": 1, "privilege": 5, "authMode": 2, "subjects": [112233], "targets": null}, {"fabricIndex": 1, "privilege": 1, "authMode": 3, "subjects": [111,222,333,444], "targets": [{"cluster":11 , "endpoint":22, "deviceType": null}]}, {"fabricIndex": 1, "privilege": 3, "authMode": 3, "subjects": [555,666,777,888], "targets": [{"cluster": 55, "endpoint": 66, "deviceType":null }]}]' 1 0

    Wating about 2 minutes or short, I receive the message this:

    [1767693686.247] [22611:22613] [TOO] Endpoint: 0 Cluster: 0x0000_001F Event 0x0000_0000
    [1767693686.247] [22611:22613] [TOO]   Event number: 65540
    [1767693686.247] [22611:22613] [TOO]   Priority: Info
    [1767693686.247] [22611:22613] [TOO]   Timestamp: 147847
    [1767693686.247] [22611:22613] [TOO]   AccessControlEntryChanged: {
    [1767693686.247] [22611:22613] [TOO]     AdminNodeID: 112233
    [1767693686.247] [22611:22613] [TOO]     AdminPasscodeID: null
    [1767693686.247] [22611:22613] [TOO]     ChangeType: 0
    [1767693686.247] [22611:22613] [TOO]     LatestValue: {
    [1767693686.247] [22611:22613] [TOO]       Privilege: 5
    [1767693686.247] [22611:22613] [TOO]       AuthMode: 2
    [1767693686.247] [22611:22613] [TOO]       Subjects: 1 entries
    [1767693686.247] [22611:22613] [TOO]         [1]: 112233
    [1767693686.247] [22611:22613] [TOO]       Targets: null
    [1767693686.247] [22611:22613] [TOO]       FabricIndex: 1
    [1767693686.247] [22611:22613] [TOO]      }
    [1767693686.247] [22611:22613] [TOO]     FabricIndex: 1
    [1767693686.247] [22611:22613] [TOO]    }
    [1767693686.247] [22611:22613] [TOO] Endpoint: 0 Cluster: 0x0000_001F Event 0x0000_0000
    [1767693686.247] [22611:22613] [TOO]   Event number: 65541
    [1767693686.247] [22611:22613] [TOO]   Priority: Info
    [1767693686.247] [22611:22613] [TOO]   Timestamp: 147859
    [1767693686.247] [22611:22613] [TOO]   AccessControlEntryChanged: {
    [1767693686.247] [22611:22613] [TOO]     AdminNodeID: 112233
    [1767693686.247] [22611:22613] [TOO]     AdminPasscodeID: null
    [1767693686.247] [22611:22613] [TOO]     ChangeType: 1
    [1767693686.247] [22611:22613] [TOO]     LatestValue: {
    [1767693686.247] [22611:22613] [TOO]       Privilege: 1
    [1767693686.247] [22611:22613] [TOO]       AuthMode: 3
    [1767693686.247] [22611:22613] [TOO]       Subjects: 4 entries
    [1767693686.247] [22611:22613] [TOO]         [1]: 111
    [1767693686.247] [22611:22613] [TOO]         [2]: 222
    [1767693686.247] [22611:22613] [TOO]         [3]: 333
    [1767693686.247] [22611:22613] [TOO]         [4]: 444
    [1767693686.247] [22611:22613] [TOO]       Targets: 1 entries
    [1767693686.247] [22611:22613] [TOO]         [1]: {
    [1767693686.247] [22611:22613] [TOO]           Cluster: 11
    [1767693686.247] [22611:22613] [TOO]           Endpoint: 22
    [1767693686.247] [22611:22613] [TOO]           DeviceType: null
    [1767693686.247] [22611:22613] [TOO]          }
    [1767693686.247] [22611:22613] [TOO]       FabricIndex: 1
    [1767693686.247] [22611:22613] [TOO]      }
    [1767693686.247] [22611:22613] [TOO]     FabricIndex: 1
    [1767693686.247] [22611:22613] [TOO]    }
    [1767693686.248] [22611:22613] [TOO] Endpoint: 0 Cluster: 0x0000_001F Event 0x0000_0000
    [1767693686.248] [22611:22613] [TOO]   Event number: 65542
    [1767693686.248] [22611:22613] [TOO]   Priority: Info
    [1767693686.248] [22611:22613] [TOO]   Timestamp: 147873
    [1767693686.248] [22611:22613] [TOO]   AccessControlEntryChanged: {
    [1767693686.248] [22611:22613] [TOO]     AdminNodeID: 112233
    [1767693686.248] [22611:22613] [TOO]     AdminPasscodeID: null
    [1767693686.248] [22611:22613] [TOO]     ChangeType: 1
    [1767693686.248] [22611:22613] [TOO]     LatestValue: {
    [1767693686.248] [22611:22613] [TOO]       Privilege: 3
    [1767693686.248] [22611:22613] [TOO]       AuthMode: 3
    [1767693686.248] [22611:22613] [TOO]       Subjects: 4 entries
    [1767693686.248] [22611:22613] [TOO]         [1]: 555
    [1767693686.248] [22611:22613] [TOO]         [2]: 666
    [1767693686.248] [22611:22613] [TOO]         [3]: 777
    [1767693686.248] [22611:22613] [TOO]         [4]: 888
    [1767693686.248] [22611:22613] [TOO]       Targets: 1 entries
    [1767693686.248] [22611:22613] [TOO]         [1]: {
    [1767693686.248] [22611:22613] [TOO]           Cluster: 55
    [1767693686.248] [22611:22613] [TOO]           Endpoint: 66
    [1767693686.248] [22611:22613] [TOO]           DeviceType: null
    [1767693686.248] [22611:22613] [TOO]          }
    [1767693686.248] [22611:22613] [TOO]       FabricIndex: 1
    [1767693686.248] [22611:22613] [TOO]      }
    [1767693686.248] [22611:22613] [TOO]     FabricIndex: 1
    [1767693686.248] [22611:22613] [TOO]    }
    [1767693686.248] [22611:22613] [DMG] Refresh LivenessCheckTime for 164277 milliseconds with SubscriptionId = 0xf142fae6 Peer = 01:0000000000000001
    [1767693686.248] [22611:22613] [EM] <<< [E:38016r S:52386 M:9137066 (Ack:119546975)] (S) Msg TX from 000000000001B669 to 1:0000000000000001 [30B3] [UDP:[fd11:37::837e:acd0:586e:1582]:5540] --- Type 0001:01 (IM:StatusResponse) (B:42)
    [1767693686.248] [22611:22613] [EM] ??1 [E:38016r S:52386 M:9137066] (S) Msg Retransmission to 1:0000000000000001 scheduled for 3019ms from now [State:Idle II:4500 AI:2500 AT:0]
    [1767693686.891] [22611:22613] [EM] >>> [E:38016r S:52386 M:119546976 (Ack:9137066)] (S) Msg RX from 1:0000000000000001 [30B3] to 000000000001B669 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
    

    The event sequence is inconsistent. Starting from event number 65538, the next expected event should be 65539, but I receive 65540 directly. This indicates a skipped event number.

    Here is the log which UL provided.

    TC-IDM-6.2_Step17.txt

    For comparison, I tested the same scenario with an ESP32-H2 running the light example, and the event numbers were sequential (no skipping).

    Best regards.
    Xiongwei.Wang

  • Hi,

    I think I may have found some relevant threads about this issue (TC-IDM-6.2), so you don't need to investigate it further.

    Best regards,
    Xiongwei.Wang

  • Thanks for the update Wang and Happy New year. Can you point this thread to those relevant threads, so that this thread can feel complete?

Reply Children
  • Hi,

    Happy New Year! I almost forgot about it, haha. Sorry to bother you at the start of the new year.

    I've now verified the issue I mentioned yesterday.

    After adding some debug prints, I found that all events share the same variable. It's normal for the event number to jump if other events are emitted in the middle of the monitored sequence.

    Here’s what happens in TC-IDM-6.2:

    1. The test expects to receive about 4 consecutive events of Event A.

    2. The first Event A is emitted right after device boot.(Saved in the buffer)

    3. However, when pairing with the Matter controller, the Thread Diagnostics Cluster emits an Event B.

    4. This Event B increments the event counter, so the subsequent Event A instances no longer follow the expected consecutive numbering, causing the test to fail.

    UL (the certification body) suggested I could temporarily remove the Thread Diagnostics Cluster and retest.

    In esp-matter, their examples don’t include this cluster, which is why their tests pass.

    Here is the issue:
    https://github.com/project-chip/connectedhomeip/issues/42559

    However, there’s still another issue to resolve: I'm not sure how to proceed with test case TC-DESC-2.3.

    Also, UL reported another problem, but I need to organize the details before sharing.

    Best regards,
    Xiongwei.Wang

Related