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] TC-ACE-1.5 failing on TH2 steps #103

Closed
PhLuReh opened this issue Nov 30, 2023 · 5 comments
Closed

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

PhLuReh opened this issue Nov 30, 2023 · 5 comments
Assignees
@manjunath-grl
Labels
Awaiting Dev Feedback Bug Something isn't working

Comments

@PhLuReh
Copy link

PhLuReh commented Nov 30, 2023

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

PICS file

No response

Screenshots

image

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
@antonio-amjr antonio-amjr added the Bug Something isn't working label Nov 30, 2023
@cecille
Copy link

cecille commented Nov 30, 2023

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
Copy link
Author

PhLuReh commented Dec 1, 2023

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

@cecille
Copy link

cecille commented Dec 1, 2023 •
edited
Loading

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
Copy link
Author

PhLuReh commented Dec 4, 2023

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

@gvargas-csa gvargas-csa mentioned this issue Dec 13, 2023
Merged
@PhLuReh PhLuReh mentioned this issue Dec 28, 2023
Closed
@fabiowmm
Copy link
Contributor

Fixed.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@manjunath-grl manjunath-grl

Labels
Awaiting Dev Feedback Bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
6 participants
@cecille @raju-apple @manjunath-grl @fabiowmm @antonio-amjr @PhLuReh