[Bug] TC-ACE-1.5 failing on TH2 steps

[PhLuReh]

Describe the bug

When running all automated tests on a DUT, TC-ACE-1.5 fails over and over again, but all other tests succeed. Commissioning window get's opened by the DUT (as seen by the logs). The error was also filed in other repos, but never found the way to CHIP.

Steps to reproduce the behavior

1. Start Matter TH in Version: v2.8.1-official Sha: 1446f09
2. Run TC-ACE-1.5
3. Commissioning from TH1 works
4. Commissioning from TH2 fails

Expected behavior

As I'm using Espressif's default implementation relying on CHIP's mDNS, I would expect the testcase to run without failure.

Log files

• DUT log: dut.txt
• TH log: TC-ACE-1_5_2023_11_30_17_18_34.zip

PICS file

No response

Screenshots

Environment

• Matther TH Version: v2.8.1-official Sha: 1446f09
• ESP-Matter: dd4f34ec98ee1d5467bcfa8f6c885d53de58e50e (release/v1.1)
• ESP-IDF: e088c3766ba440e72268b458a68f27b6e7d63986 (v5.1.1)
• connectedhomeip: 8f66f4215bc0708efc8cc73bda80620e67d8955f (v1.1.0.1)

Additional Information

I already added additional forced advertisements, but this also didn't solve the problem:

chip[DIS]: Advertise operational node 8A399D0EB828898F-4340514E6DFC35BD
I (94739) chip[DIS]: CHIP minimal mDNS configured as 'Operational device'; instance name: 8A399D0EB828898F-4340514E6DFC35BD.
I (94769) chip[DIS]: mDNS service published: _matter._tcp
I (94769) app_main: advertise operational done

But avahi seems to know the device.

ubuntu@ubuntu:~/apps$ avahi-browse -a
+   eth0 IPv6 00DE5CDDEF0323B1                              _matterc._udp        local
+   eth0 IPv4 00DE5CDDEF0323B1                              _matterc._udp        local
+   eth0 IPv6 8A399D0EB828898F-4340514E6DFC35BD             _matter._tcp         local
+   eth0 IPv4 8A399D0EB828898F-4340514E6DFC35BD             _matter._tcp         local
+   eth0 IPv6 18A1E134D0BBD480                              _matterc._udp        local
+   eth0 IPv4 18A1E134D0BBD480                              _matterc._udp        local

[cecille]

This looks more like a real failure than a dns-sd problem:

CHIPTOOL   | 2023-11-30 16:20:28.976352 | [1701361228.939912][24:32] CHIP:TOO:  ***** Test Step 16 : TH1 sends RemoveFabric command for TH2
CHIPTOOL   | 2023-11-30 16:20:28.977756 | 
CHIPTOOL   | 2023-11-30 16:20:28.979215 | [1701361228.940095][24:32] CHIP:DMG: ICR moving to [AddingComm]
CHIPTOOL   | 2023-11-30 16:20:28.980964 | [1701361228.940151][24:32] CHIP:DMG: ICR moving to [AddedComma]
CHIPTOOL   | 2023-11-30 16:20:28.992817 | [1701361228.940994][24:32] CHIP:DMG: >> to UDP:[fd61:3599:e3a1:0:32c6:f7ff:feaa:7c2c%eth0]:5540 | 223347496 | [Interaction Model  (1) / InvokeCommandRequest (0x08) / Session = 13895 / Exchange = 50301]
CHIPTOOL   | 2023-11-30 16:20:28.994231 | [1701361228.941082][24:32] CHIP:DMG: Header Flags =
CHIPTOOL   | 2023-11-30 16:20:28.995431 | [1701361228.941117][24:32] CHIP:DMG: {
CHIPTOOL   | 2023-11-30 16:20:28.996466 | [1701361228.941181][24:32] CHIP:DMG:     Exchange (0x05) =
CHIPTOOL   | 2023-11-30 16:20:28.997500 | [1701361228.941216][24:32] CHIP:DMG:     {
CHIPTOOL   | 2023-11-30 16:20:28.998561 | [1701361228.941245][24:32] CHIP:DMG:         Initiator = true
CHIPTOOL   | 2023-11-30 16:20:29.000032 | [1701361228.941276][24:32] CHIP:DMG:         NeedsAck = true
CHIPTOOL   | 2023-11-30 16:20:29.001366 | [1701361228.941307][24:32] CHIP:DMG:     }
CHIPTOOL   | 2023-11-30 16:20:29.002639 | [1701361228.941355][24:32] CHIP:DMG: }
CHIPTOOL   | 2023-11-30 16:20:29.004050 | [1701361228.941388][24:32] CHIP:DMG:  
CHIPTOOL   | 2023-11-30 16:20:29.005353 | [1701361228.941434][24:32] CHIP:DMG: Encrypted Payload (32 bytes) =
CHIPTOOL   | 2023-11-30 16:20:29.006636 | [1701361228.941467][24:32] CHIP:DMG: {
CHIPTOOL   | 2023-11-30 16:20:29.008029 | [1701361228.941497][24:32] CHIP:DMG:     data = 1528002801360215370024000024013e24020a18350124000018181824ff0118
CHIPTOOL   | 2023-11-30 16:20:29.009365 | [1701361228.941528][24:32] CHIP:DMG:     buffer_ptr = 281473366230496
CHIPTOOL   | 2023-11-30 16:20:29.010341 | [1701361228.941558][24:32] CHIP:DMG: }
CHIPTOOL   | 2023-11-30 16:20:29.011290 | [1701361228.941587][24:32] CHIP:DMG:  
CHIPTOOL   | 2023-11-30 16:20:29.012186 | [1701361228.941639][24:32] CHIP:DMG: Decrypted Payload (34 bytes) =
CHIPTOOL   | 2023-11-30 16:20:29.013084 | [1701361228.941672][24:32] CHIP:DMG: {
CHIPTOOL   | 2023-11-30 16:20:29.013967 | [1701361228.941711][24:32] CHIP:DMG:     data = 004736002703500d51e9af8aae6cfe641fe8d89c32e55479723bb33d576f9fc0ddad
CHIPTOOL   | 2023-11-30 16:20:29.014890 | [1701361228.941741][24:32] CHIP:DMG: }
CHIPTOOL   | 2023-11-30 16:20:29.015800 | [1701361228.941771][24:32] CHIP:DMG:  
CHIPTOOL   | 2023-11-30 16:20:29.016700 | [1701361228.941854][24:32] CHIP:DMG: Error: src/lib/core/TLVReader.cpp:532: CHIP Error 0x00000003: Incorrect state
CHIPTOOL   | 2023-11-30 16:20:29.027074 | 0x02, tag[Anonymous]: 0x100, type: Signed Fixed Point (0x00), value: 71
CHIPTOOL   | 2023-11-30 16:20:29.028391 | [1701361228.942093][24:32] CHIP:EM: <<< [E:50301i S:33483 M:223347496] (S) Msg TX to 1:4340514E6DFC35BD [898F] --- Type 0001:08 (IM:InvokeCommandRequest)
CHIPTOOL   | 2023-11-30 16:20:29.029437 | [1701361228.942198][24:32] CHIP:IN: (S) Sending msg 223347496 on secure session with LSID: 33483
CHIPTOOL   | 2023-11-30 16:20:29.041399 | [1701361228.943289][24:32] CHIP:DMG: ICR moving to [CommandSen]
CHIPTOOL   | 2023-11-30 16:20:29.200573 | [1701361229.198939][24:32] CHIP:EM: >>> [E:50301i S:33483 M:193874070 (Ack:223347496)] (S) Msg RX from 1:4340514E6DFC35BD [898F] --- Type 0001:09 (IM:InvokeCommandResponse)
CHIPTOOL   | 2023-11-30 16:20:29.203584 | [1701361229.199007][24:32] CHIP:EM: Found matching exchange: 50301i, Delegate: 0xffffa000a808
CHIPTOOL   | 2023-11-30 16:20:29.207204 | [1701361229.199065][24:32] CHIP:EM: Rxd Ack; Removing MessageCounter:223347496 from Retrans Table on exchange 50301i
CHIPTOOL   | 2023-11-30 16:20:29.211383 | [1701361229.199124][24:32] CHIP:DMG: ICR moving to [ResponseRe]
CHIPTOOL   | 2023-11-30 16:20:29.224414 | [1701361229.199191][24:32] CHIP:DMG: InvokeResponseMessage =
CHIPTOOL   | 2023-11-30 16:20:29.226194 | [1701361229.199245][24:32] CHIP:DMG: {
CHIPTOOL   | 2023-11-30 16:20:29.227686 | [1701361229.199272][24:32] CHIP:DMG: 	suppressResponse = false, 
CHIPTOOL   | 2023-11-30 16:20:29.229383 | [1701361229.199296][24:32] CHIP:DMG: 	InvokeResponseIBs =
CHIPTOOL   | 2023-11-30 16:20:29.231324 | [1701361229.199332][24:32] CHIP:DMG: 	[
CHIPTOOL   | 2023-11-30 16:20:29.234410 | [1701361229.199357][24:32] CHIP:DMG: 		InvokeResponseIB =
CHIPTOOL   | 2023-11-30 16:20:29.509409 | [1701361229.199397][24:32] CHIP:DMG: 		{
CHIPTOOL   | 2023-11-30 16:20:29.510846 | [1701361229.199422][24:32] CHIP:DMG: 			CommandStatusIB =
CHIPTOOL   | 2023-11-30 16:20:29.522266 | [1701361229.199449][24:32] CHIP:DMG: 			{
CHIPTOOL   | 2023-11-30 16:20:29.524050 | [1701361229.199473][24:32] CHIP:DMG: 				CommandPathIB =
CHIPTOOL   | 2023-11-30 16:20:29.525421 | [1701361229.199501][24:32] CHIP:DMG: 				{
CHIPTOOL   | 2023-11-30 16:20:29.537321 | [1701361229.199530][24:32] CHIP:DMG: 					EndpointId = 0x0,
CHIPTOOL   | 2023-11-30 16:20:29.539067 | [1701361229.199558][24:32] CHIP:DMG: 					ClusterId = 0x3e,
CHIPTOOL   | 2023-11-30 16:20:29.551103 | [1701361229.199584][24:32] CHIP:DMG: 					CommandId = 0xa,
CHIPTOOL   | 2023-11-30 16:20:29.553003 | [1701361229.199612][24:32] CHIP:DMG: 				},
CHIPTOOL   | 2023-11-30 16:20:29.555280 | [1701361229.199646][24:32] CHIP:DMG:
CHIPTOOL   | 2023-11-30 16:20:29.567931 | [1701361229.199670][24:32] CHIP:DMG: 				StatusIB =
CHIPTOOL   | 2023-11-30 16:20:29.569407 | [1701361229.199698][24:32] CHIP:DMG: 				{
CHIPTOOL   | 2023-11-30 16:20:29.580223 | [1701361229.199725][24:32] CHIP:DMG: 					status = 0x85 (INVALID_COMMAND),
CHIPTOOL   | 2023-11-30 16:20:29.582158 | [1701361229.199751][24:32] CHIP:DMG: 				},
CHIPTOOL   | 2023-11-30 16:20:29.583863 | [1701361229.199779][24:32] CHIP:DMG: 				
CHIPTOOL   | 2023-11-30 16:20:29.585437 | [1701361229.199802][24:32] CHIP:DMG: 			},
CHIPTOOL   | 2023-11-30 16:20:29.597587 | [1701361229.199834][24:32] CHIP:DMG: 			
CHIPTOOL   | 2023-11-30 16:20:29.599662 | [1701361229.199858][24:32] CHIP:DMG: 		},
CHIPTOOL   | 2023-11-30 16:20:29.612141 | [1701361229.199890][24:32] CHIP:DMG: 		
CHIPTOOL   | 2023-11-30 16:20:29.614272 | [1701361229.199913][24:32] CHIP:DMG: 	],
CHIPTOOL   | 2023-11-30 16:20:29.627167 | [1701361229.199946][24:32] CHIP:DMG: 	
CHIPTOOL   | 2023-11-30 16:20:29.629102 | [1701361229.199972][24:32] CHIP:DMG: 	InteractionModelRevision = 1
CHIPTOOL   | 2023-11-30 16:20:29.630763 | [1701361229.199994][24:32] CHIP:DMG: },
CHIPTOOL   | 2023-11-30 16:20:29.643055 | [1701361229.200084][24:32] CHIP:DMG: Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000A Status=0x85
CHIPTOOL   | 2023-11-30 16:20:29.645042 | [1701361229.200144][24:32] CHIP:TOO:  ***** Step Failure: status value mismatch: expected 0 but got 133
DEBUG      | 2023-11-30 16:20:29.646497 | Found failure:  status value mismatch: expected 0 but got 133
WARNING    | 2023-11-30 16:20:29.647938 | Test Failure:  status value mismatch: expected 0 but got 133

[PhLuReh]

@cecille How do you conclude? This error in step TH1 sends RemoveFabric command for TH2 is resulting from the failing test steps before.

[cecille]

Ah, sorry, I think I misread what you were trying to say here. Yeah, TH2 is failing to commission, which is why you're getting that fabric removal failure.

Which version of the script are you using? I looks like there were updates to this script recently to make it into a weird semi-automated thing for some unknown reason. Are you using that version?

[PhLuReh]

As I stated, I'm running on Matter TH in Version: v2.8.1-official Sha: 1446f09. It is the version provided on Github.

[fabiowmm]

Fixed.