project-chip / certification-tool

A test harness and tooling designed to simplify development, testing, and certification for devices, guided by the Connectivity Standards Alliance.
https://csa-iot.org/
Apache License 2.0
36 stars 22 forks source link

[Bug] TC-RR-1.1 testcases failed with the TypeError: 'ValueDecodeFailure' object is not iterable #124

Closed Saravana-kr22 closed 5 months ago

Saravana-kr22 commented 8 months ago

Describe the bug

TC-RR-1.1 is failed with the TypeError: 'ValueDecodeFailure' object is not iterable. The docker used for Execution of the SDK python testcases needs to be updated to hadle these type of issue.

Traceback (most recent call last): PYTHON_TEST | 2023-12-14 11:15:32.265469 | File "/usr/local/lib/python3.10/dist-packages/mobly/base_test.py", line 783, in exec_one_test PYTHON_TEST | 2023-12-14 11:15:32.266684 | test_method() PYTHON_TEST | 2023-12-14 11:15:32.267624 | File "/root/python_testing/matter_testing_support.py", line 1317, in async_runner PYTHON_TEST | 2023-12-14 11:15:32.268525 | return asyncio.run(runner_with_timeout) PYTHON_TEST | 2023-12-14 11:15:32.270253 | File "/usr/lib/python3.10/asyncio/runners.py", line 44, in run PYTHON_TEST | 2023-12-14 11:15:32.271333 | return loop.run_until_complete(main) PYTHON_TEST | 2023-12-14 11:15:32.272258 | File "/usr/lib/python3.10/asyncio/base_events.py", line 649, in run_until_complete PYTHON_TEST | 2023-12-14 11:15:32.273173 | return future.result() PYTHON_TEST | 2023-12-14 11:15:32.276691 | File "/usr/lib/python3.10/asyncio/tasks.py", line 445, in wait_for PYTHON_TEST | 2023-12-14 11:15:32.277757 | return fut.result() PYTHON_TEST | 2023-12-14 11:15:32.278752 | File "/root/python_testing/TC_RR_1_1.py", line 259, in test_TC_RR_1_1 PYTHON_TEST | 2023-12-14 11:15:32.279831 | await self.send_acl(test_step=3, client_by_name=client_by_name, enable_access_to_group_cluster=False, fabric_table=fabric_table) PYTHON_TEST | 2023-12-14 11:15:32.287346 | File "/root/python_testing/TC_RR_1_1.py", line 713, in send_acl PYTHON_TEST | 2023-12-14 11:15:32.288644 | for entry in acl_readback: PYTHON_TEST | 2023-12-14 11:15:32.289776 | TypeError: 'ValueDecodeFailure' object is not iterable

Log files

tc-rr-1-1.log

Additional Information

Note : This testcases is failed only in the UI but passed in the connectedhomeip/chip-cert-bins docker.

ccruzagralopes commented 8 months ago

@Saravana-kr22 can you please share the steps you took and the commands used to run the test directly in the docker container?

Saravana-kr22 commented 8 months ago

@ccruzagralopes here is the steps and command used to run in the docker container:

Step 1: Run the docker container docker run -v $PATH_TO_credentials:/credentials -v /var/run/dbus/system_bus_socket:/var/run/dbus/system_bus_socket -v $(pwd):/launch_dir --privileged --network host -it connectedhomeip/chip-cert-bins:548e4f3de32053abe44854c35882bbc354f0538a Step 2: Advertise the dut Step 3: Run the testcase in the docker using the command python3 python_testing/TC_RR_1_1.py --commissioning-method on-network --discriminator 3840 --passcode 20202021 --storage-path admin_storage.json --paa-trust-store-path /credentials/development/paa-root-certs/

ccruzagralopes commented 8 months ago

I get the same error when trying to run the test using TH UI, but I'm facing an error when trying to run it directly: TC_RR_1_1-error.log

ccruzagralopes commented 8 months ago

@cecille can you please take a look at this issue? Do you know of anything that could cause this particular test case to fail with TypeError: 'ValueDecodeFailure' object is not iterable when running in TH but pass when running directly in the command line?

cecille commented 8 months ago

It's not a value decode failure that's causing the failure, it's a timeout sending a command

atterTest] 01-11 18:01:41.770 INFO Time out! failed to receive invoke command response from Exchange: 4001i
[MatterTest] 01-11 18:01:41.771 ERROR Exception occurred in test_TC_RR_1_1.
Traceback (most recent call last):
  File "/usr/local/lib/python3.10/dist-packages/mobly/base_test.py", line 783, in exec_one_test
    test_method()
  File "/root/python_testing/matter_testing_support.py", line 1339, in async_runner
    return asyncio.run(runner_with_timeout)
  File "/usr/lib/python3.10/asyncio/runners.py", line 44, in run
    return loop.run_until_complete(main)
  File "/usr/lib/python3.10/asyncio/base_events.py", line 649, in run_until_complete
    return future.result()
  File "/usr/lib/python3.10/asyncio/tasks.py", line 445, in wait_for
    return fut.result()
  File "/root/python_testing/TC_RR_1_1.py", line 479, in test_TC_RR_1_1
    Dict[int, Clusters.GroupKeyManagement.Structs.GroupInfoMapStruct]] = await self.add_all_groups(
  File "/root/python_testing/TC_RR_1_1.py", line 657, in add_all_groups
    add_response: Clusters.Groups.Commands.AddGroupResponse = await client.SendCommand(
  File "/usr/local/lib/python3.10/dist-packages/chip/ChipDeviceCtrl.py", line 902, in SendCommand
    return await future
chip.exceptions.ChipStackError: src/app/CommandSender.cpp:298: CHIP Error 0x00000032: Timeout
[MatterTest] 01-11 18:01:41.774 INFO        ***** Test Failure : 
[MatterTest] 01-11 18:01:41.774 INFO Finished test in 18540ms
[MatterTest] 01-11 18:01:41.774 INFO [Test] test_TC_RR_1_1 ERROR
cecille commented 8 months ago

oh, sorry, the timeout was in your log. The top error is different.

cecille commented 8 months ago

Do you have DUT logs? It basically means the TH failed to read the ACL attribute from the device.

Saravana-kr22 commented 6 months ago

This testacase is failed with the same error in the latest TH : Version: 2.10-beta3+spring2024 Sha: 1fd1429

TH log: rr-1-1.log DUT log: tc-rr-1-1dut.txt

Saravana-kr22 commented 6 months ago

This testcase is passing in the connectedhomeip/chip-cert-bins docker

TH log: rr-1-1(docker).txt DUT log: rr-1-1(dut).txt

ccruzagralopes commented 6 months ago

I've run the test case in TH and manually using --trace-to json:log to get more logs:

During the failing step (Step 3b: Validating ACL entry for fabric 1):

In the manual logs, we can see that we get the expected data:

Manual logs ``` [MatterTest] 02-26 19:56:53.773 INFO <<< [E:44908i S:41059 M:190713032 (Ack:219340239)] (S) Msg TX to 1:0000000012344321 [F382] [UDP:[fe80::42:dfff:fe12:3271%docker0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [MatterTest] 02-26 19:56:53.775 INFO Found an existing secure session to [1:0000000012344321]! [MatterTest] 02-26 19:56:53.779 INFO { [MatterTest] 02-26 19:56:53.779 INFO "event" : "MessageSend", [MatterTest] 02-26 19:56:53.780 INFO "messageType" : "Secure", [MatterTest] 02-26 19:56:53.780 INFO "packetHeader" : [MatterTest] 02-26 19:56:53.780 INFO { [MatterTest] 02-26 19:56:53.781 INFO "flags" : 0, [MatterTest] 02-26 19:56:53.781 INFO "msgCounter" : 190713033, [MatterTest] 02-26 19:56:53.781 INFO "securityFlags" : 0, [MatterTest] 02-26 19:56:53.781 INFO "sessionId" : 37852 [MatterTest] 02-26 19:56:53.782 INFO }, [MatterTest] 02-26 19:56:53.783 INFO "payload" : [MatterTest] 02-26 19:56:53.783 INFO { [MatterTest] 02-26 19:56:53.783 INFO "decoded" : [MatterTest] 02-26 19:56:53.784 INFO { [MatterTest] 02-26 19:56:53.784 INFO "read_request" : [MatterTest] 02-26 19:56:53.785 INFO { [MatterTest] 02-26 19:56:53.785 INFO "attribute_requests" : [MatterTest] 02-26 19:56:53.786 INFO { [MatterTest] 02-26 19:56:53.787 INFO "Anonymous<0>" : [MatterTest] 02-26 19:56:53.788 INFO { [MatterTest] 02-26 19:56:53.788 INFO "attribute_id" : "0 == 'acl'", [MatterTest] 02-26 19:56:53.789 INFO "cluster_id" : "31 == 'AccessControl'", [MatterTest] 02-26 19:56:53.789 INFO "endpoint_id" : "0" [MatterTest] 02-26 19:56:53.789 INFO } [MatterTest] 02-26 19:56:53.789 INFO }, [MatterTest] 02-26 19:56:53.789 INFO "fabric_filtered" : "true", [MatterTest] 02-26 19:56:53.790 INFO "interaction_model_revison" : "11" [MatterTest] 02-26 19:56:53.790 INFO } [MatterTest] 02-26 19:56:53.790 INFO }, [MatterTest] 02-26 19:56:53.790 INFO "hex" : "1536001724020024031F2404001818290324FF0B18", [MatterTest] 02-26 19:56:53.791 INFO "size" : 21 [MatterTest] 02-26 19:56:53.791 INFO }, [MatterTest] 02-26 19:56:53.791 INFO "payloadHeader" : [MatterTest] 02-26 19:56:53.791 INFO { [MatterTest] 02-26 19:56:53.792 INFO "exchangeFlags" : 5, [MatterTest] 02-26 19:56:53.792 INFO "exchangeId" : 44909, [MatterTest] 02-26 19:56:53.792 INFO "initiator" : true, [MatterTest] 02-26 19:56:53.792 INFO "messageType" : 2, [MatterTest] 02-26 19:56:53.792 INFO "needsAck" : true, [MatterTest] 02-26 19:56:53.793 INFO "protocolId" : 1 [MatterTest] 02-26 19:56:53.794 INFO } [MatterTest] 02-26 19:56:53.794 INFO } [MatterTest] 02-26 19:56:53.794 INFO <<< [E:44909i S:41059 M:190713033] (S) Msg TX to 1:0000000012344321 [F382] [UDP:[fe80::42:dfff:fe12:3271%docker0]:5540] --- Type 0001:02 (IM:ReadRequest) [MatterTest] 02-26 19:56:53.798 INFO { [MatterTest] 02-26 19:56:53.798 INFO "event" : "MessageReceived", [MatterTest] 02-26 19:56:53.799 INFO "messageType" : "Secure", [MatterTest] 02-26 19:56:53.799 INFO "packetHeader" : [MatterTest] 02-26 19:56:53.800 INFO { [MatterTest] 02-26 19:56:53.801 INFO "flags" : 0, [MatterTest] 02-26 19:56:53.802 INFO "msgCounter" : 219340240, [MatterTest] 02-26 19:56:53.802 INFO "securityFlags" : 0, [MatterTest] 02-26 19:56:53.803 INFO "sessionId" : 41059 [MatterTest] 02-26 19:56:53.803 INFO }, [MatterTest] 02-26 19:56:53.803 INFO "payload" : [MatterTest] 02-26 19:56:53.804 INFO { [MatterTest] 02-26 19:56:53.806 INFO "decoded" : [MatterTest] 02-26 19:56:53.806 INFO { [MatterTest] 02-26 19:56:53.807 INFO "report_data" : [MatterTest] 02-26 19:56:53.808 INFO { [MatterTest] 02-26 19:56:53.808 INFO "attribute_reports" : [MatterTest] 02-26 19:56:53.808 INFO { [MatterTest] 02-26 19:56:53.810 INFO "Anonymous<0>" : [MatterTest] 02-26 19:56:53.811 INFO { [MatterTest] 02-26 19:56:53.811 INFO "attribute_data" : [MatterTest] 02-26 19:56:53.812 INFO { [MatterTest] 02-26 19:56:53.812 INFO "AccessControl::acl" : [MatterTest] 02-26 19:56:53.814 INFO { [MatterTest] 02-26 19:56:53.814 INFO "Anonymous<0>" : [MatterTest] 02-26 19:56:53.814 INFO { [MatterTest] 02-26 19:56:53.815 INFO "authMode" : "2 == kCASE", [MatterTest] 02-26 19:56:53.816 INFO "fabricIndex" : "1", [MatterTest] 02-26 19:56:53.816 INFO "privilege" : "5 == kAdminister", [MatterTest] 02-26 19:56:53.818 INFO "subjects" : [MatterTest] 02-26 19:56:53.818 INFO { [MatterTest] 02-26 19:56:53.819 INFO "Anonymous<0>" : "18446744060824715265", [MatterTest] 02-26 19:56:53.821 INFO "Anonymous<1>" : "2305843009213693953", [MatterTest] 02-26 19:56:53.821 INFO "Anonymous<2>" : "2305843009213693954", [MatterTest] 02-26 19:56:53.824 INFO "Anonymous<3>" : "2305843009213693955" [MatterTest] 02-26 19:56:53.826 INFO }, [MatterTest] 02-26 19:56:53.827 INFO "targets" : [MatterTest] 02-26 19:56:53.827 INFO { [MatterTest] 02-26 19:56:53.827 INFO "Anonymous<0>" : [MatterTest] 02-26 19:56:53.828 INFO { [MatterTest] 02-26 19:56:53.828 INFO "cluster" : "NULL", [MatterTest] 02-26 19:56:53.829 INFO "deviceType" : "NULL", [MatterTest] 02-26 19:56:53.830 INFO "endpoint" : "0" [MatterTest] 02-26 19:56:53.832 INFO }, [MatterTest] 02-26 19:56:53.832 INFO "Anonymous<1>" : [MatterTest] 02-26 19:56:53.833 INFO { [MatterTest] 02-26 19:56:53.834 INFO "cluster" : "4294048768", [MatterTest] 02-26 19:56:53.836 INFO "deviceType" : "4294032432", [MatterTest] 02-26 19:56:53.839 INFO "endpoint" : "NULL" [MatterTest] 02-26 19:56:53.839 INFO }, [MatterTest] 02-26 19:56:53.841 INFO "Anonymous<2>" : [MatterTest] 02-26 19:56:53.842 INFO { [MatterTest] 02-26 19:56:53.843 INFO "cluster" : "4294048769", [MatterTest] 02-26 19:56:53.844 INFO "deviceType" : "4294032433", [MatterTest] 02-26 19:56:53.845 INFO "endpoint" : "NULL" [MatterTest] 02-26 19:56:53.847 INFO } [MatterTest] 02-26 19:56:53.848 INFO } [MatterTest] 02-26 19:56:53.848 INFO }, [MatterTest] 02-26 19:56:53.849 INFO "Anonymous<1>" : [MatterTest] 02-26 19:56:53.849 INFO { [MatterTest] 02-26 19:56:53.850 INFO "authMode" : "2 == kCASE", [MatterTest] 02-26 19:56:53.850 INFO "fabricIndex" : "1", [MatterTest] 02-26 19:56:53.850 INFO "privilege" : "4 == kManage", [MatterTest] 02-26 19:56:53.852 INFO "subjects" : [MatterTest] 02-26 19:56:53.853 INFO { [MatterTest] 02-26 19:56:53.856 INFO "Anonymous<0>" : "1152921504606846977", [MatterTest] 02-26 19:56:53.856 INFO "Anonymous<1>" : "1152921504606846978", [MatterTest] 02-26 19:56:53.856 INFO "Anonymous<2>" : "1152921504606846979", [MatterTest] 02-26 19:56:53.856 INFO "Anonymous<3>" : "1152921504606846980" [MatterTest] 02-26 19:56:53.856 INFO }, [MatterTest] 02-26 19:56:53.858 INFO "targets" : [MatterTest] 02-26 19:56:53.859 INFO { [MatterTest] 02-26 19:56:53.862 INFO "Anonymous<0>" : [MatterTest] 02-26 19:56:53.862 INFO { [MatterTest] 02-26 19:56:53.862 INFO "cluster" : "4294048768", [MatterTest] 02-26 19:56:53.862 INFO "deviceType" : "4294032416", [MatterTest] 02-26 19:56:53.863 INFO "endpoint" : "NULL" [MatterTest] 02-26 19:56:53.863 INFO }, [MatterTest] 02-26 19:56:53.864 INFO "Anonymous<1>" : [MatterTest] 02-26 19:56:53.868 INFO { [MatterTest] 02-26 19:56:53.868 INFO "cluster" : "4294048769", [MatterTest] 02-26 19:56:53.868 INFO "deviceType" : "4294032417", [MatterTest] 02-26 19:56:53.869 INFO "endpoint" : "NULL" [MatterTest] 02-26 19:56:53.870 INFO }, [MatterTest] 02-26 19:56:53.870 INFO "Anonymous<2>" : [MatterTest] 02-26 19:56:53.870 INFO { [MatterTest] 02-26 19:56:53.870 INFO "cluster" : "4294048770", [MatterTest] 02-26 19:56:53.871 INFO "deviceType" : "4294032418", [MatterTest] 02-26 19:56:53.871 INFO "endpoint" : "NULL" [MatterTest] 02-26 19:56:53.876 INFO } [MatterTest] 02-26 19:56:53.876 INFO } [MatterTest] 02-26 19:56:53.876 INFO }, [MatterTest] 02-26 19:56:53.877 INFO "Anonymous<2>" : [MatterTest] 02-26 19:56:53.878 INFO { [MatterTest] 02-26 19:56:53.878 INFO "authMode" : "2 == kCASE", [MatterTest] 02-26 19:56:53.880 INFO "fabricIndex" : "1", [MatterTest] 02-26 19:56:53.880 INFO "privilege" : "3 == kOperate", [MatterTest] 02-26 19:56:53.881 INFO "subjects" : [MatterTest] 02-26 19:56:53.881 INFO { [MatterTest] 02-26 19:56:53.882 INFO "Anonymous<0>" : "3458764513820540929", [MatterTest] 02-26 19:56:53.882 INFO "Anonymous<1>" : "3458764513820540930", [MatterTest] 02-26 19:56:53.882 INFO "Anonymous<2>" : "3458764513820540931", [MatterTest] 02-26 19:56:53.883 INFO "Anonymous<3>" : "3458764513820540932" [MatterTest] 02-26 19:56:53.883 INFO }, [MatterTest] 02-26 19:56:53.884 INFO "targets" : [MatterTest] 02-26 19:56:53.884 INFO { [MatterTest] 02-26 19:56:53.885 INFO "Anonymous<0>" : [MatterTest] 02-26 19:56:53.885 INFO { [MatterTest] 02-26 19:56:53.885 INFO "cluster" : "4294048832", [MatterTest] 02-26 19:56:53.885 INFO "deviceType" : "4294032416", [MatterTest] 02-26 19:56:53.885 INFO "endpoint" : "NULL" [MatterTest] 02-26 19:56:53.886 INFO }, [MatterTest] 02-26 19:56:53.886 INFO "Anonymous<1>" : [MatterTest] 02-26 19:56:53.886 INFO { [MatterTest] 02-26 19:56:53.886 INFO "cluster" : "4294048833", [MatterTest] 02-26 19:56:53.886 INFO "deviceType" : "4294032417", [MatterTest] 02-26 19:56:53.886 INFO "endpoint" : "NULL" [MatterTest] 02-26 19:56:53.887 INFO }, [MatterTest] 02-26 19:56:53.887 INFO "Anonymous<2>" : [MatterTest] 02-26 19:56:53.887 INFO { [MatterTest] 02-26 19:56:53.887 INFO "cluster" : "4294048834", [MatterTest] 02-26 19:56:53.888 INFO "deviceType" : "4294032450", [MatterTest] 02-26 19:56:53.888 INFO "endpoint" : "NULL" [MatterTest] 02-26 19:56:53.889 INFO } [MatterTest] 02-26 19:56:53.889 INFO } [MatterTest] 02-26 19:56:53.889 INFO }, [MatterTest] 02-26 19:56:53.889 INFO "Anonymous<3>" : [MatterTest] 02-26 19:56:53.889 INFO { [MatterTest] 02-26 19:56:53.890 INFO "authMode" : "2 == kCASE", [MatterTest] 02-26 19:56:53.890 INFO "fabricIndex" : "1", [MatterTest] 02-26 19:56:53.890 INFO "privilege" : "1 == kView", [MatterTest] 02-26 19:56:53.890 INFO "subjects" : [MatterTest] 02-26 19:56:53.891 INFO { [MatterTest] 02-26 19:56:53.891 INFO "Anonymous<0>" : "4611686018427387905", [MatterTest] 02-26 19:56:53.891 INFO "Anonymous<1>" : "4611686018427387906", [MatterTest] 02-26 19:56:53.891 INFO "Anonymous<2>" : "4611686018427387907", [MatterTest] 02-26 19:56:53.892 INFO "Anonymous<3>" : "4611686018427387908" [MatterTest] 02-26 19:56:53.892 INFO }, [MatterTest] 02-26 19:56:53.892 INFO "targets" : [MatterTest] 02-26 19:56:53.893 INFO { [MatterTest] 02-26 19:56:53.893 INFO "Anonymous<0>" : [MatterTest] 02-26 19:56:53.893 INFO { [MatterTest] 02-26 19:56:53.893 INFO "cluster" : "4294048896", [MatterTest] 02-26 19:56:53.893 INFO "deviceType" : "4294032416", [MatterTest] 02-26 19:56:53.894 INFO "endpoint" : "NULL" [MatterTest] 02-26 19:56:53.894 INFO }, [MatterTest] 02-26 19:56:53.894 INFO "Anonymous<1>" : [MatterTest] 02-26 19:56:53.894 INFO { [MatterTest] 02-26 19:56:53.894 INFO "cluster" : "4294048897", [MatterTest] 02-26 19:56:53.895 INFO "deviceType" : "4294032417", [MatterTest] 02-26 19:56:53.895 INFO "endpoint" : "NULL" [MatterTest] 02-26 19:56:53.895 INFO }, [MatterTest] 02-26 19:56:53.896 INFO "Anonymous<2>" : [MatterTest] 02-26 19:56:53.896 INFO { [MatterTest] 02-26 19:56:53.896 INFO "cluster" : "4294048898", [MatterTest] 02-26 19:56:53.897 INFO "deviceType" : "4294032418", [MatterTest] 02-26 19:56:53.897 INFO "endpoint" : "NULL" [MatterTest] 02-26 19:56:53.897 INFO } [MatterTest] 02-26 19:56:53.897 INFO } [MatterTest] 02-26 19:56:53.897 INFO } [MatterTest] 02-26 19:56:53.897 INFO }, [MatterTest] 02-26 19:56:53.898 INFO "data_version" : "4049293974", [MatterTest] 02-26 19:56:53.898 INFO "path" : [MatterTest] 02-26 19:56:53.899 INFO { [MatterTest] 02-26 19:56:53.900 INFO "attribute_id" : "0 == 'acl'", [MatterTest] 02-26 19:56:53.900 INFO "cluster_id" : "31 == 'AccessControl'", [MatterTest] 02-26 19:56:53.900 INFO "endpoint_id" : "0" [MatterTest] 02-26 19:56:53.900 INFO } [MatterTest] 02-26 19:56:53.901 INFO } [MatterTest] 02-26 19:56:53.901 INFO } [MatterTest] 02-26 19:56:53.901 INFO }, [MatterTest] 02-26 19:56:53.901 INFO "interaction_model_revison" : "11", [MatterTest] 02-26 19:56:53.902 INFO "suppress_response" : "true" [MatterTest] 02-26 19:56:53.902 INFO } [MatterTest] 02-26 19:56:53.902 INFO }, [MatterTest] 02-26 19:56:53.902 INFO "hex" : "153601153501260096525BF1370124020024031F2404001836021524010524020236030701000100FDFFFFFF07010000000000002007020000000000002007030000000000002018360415340024010034021815260000FCF1FF3401260230BCF1FF1815260001FCF1FF3401260231BCF1FF181824FE01181524 [MatterTest] 02-26 19:56:53.903 INFO "size" : 433 [MatterTest] 02-26 19:56:53.903 INFO }, [MatterTest] 02-26 19:56:53.903 INFO "payloadHeader" : [MatterTest] 02-26 19:56:53.903 INFO { [MatterTest] 02-26 19:56:53.903 INFO "ackMessageCounter" : 190713033, [MatterTest] 02-26 19:56:53.904 INFO "exchangeFlags" : 6, [MatterTest] 02-26 19:56:53.904 INFO "exchangeId" : 44909, [MatterTest] 02-26 19:56:53.904 INFO "initiator" : false, [MatterTest] 02-26 19:56:53.904 INFO "messageType" : 5, [MatterTest] 02-26 19:56:53.905 INFO "needsAck" : true, [MatterTest] 02-26 19:56:53.905 INFO "protocolId" : 1 [MatterTest] 02-26 19:56:53.905 INFO } [MatterTest] 02-26 19:56:53.905 INFO } [MatterTest] 02-26 19:56:53.906 INFO >>> [E:44909i S:41059 M:219340240 (Ack:190713033)] (S) Msg RX from 1:0000000012344321 [F382] --- Type 0001:05 (IM:ReportData) ```

In the TH logs, we get kUnsupportedAccess:

TH logs ``` PYTHON_TEST | 2024-02-26 20:12:17.865449 | [MatterTest] 02-26 20:12:04.203 INFO <<< [E:16327i S:62707 M:54652188] (S) Msg TX to 1:0000000012344321 [3D0F] [UDP:[fe80::3432:deff:fecc:84c1%veth18ccd47]:5540] --- Type 0001:02 (IM:ReadRequest) PYTHON_TEST | 2024-02-26 20:12:17.866071 | [MatterTest] 02-26 20:12:04.207 INFO { PYTHON_TEST | 2024-02-26 20:12:17.866509 | [MatterTest] 02-26 20:12:04.207 INFO "event" : "MessageReceived", PYTHON_TEST | 2024-02-26 20:12:17.866988 | [MatterTest] 02-26 20:12:04.207 INFO "messageType" : "Secure", PYTHON_TEST | 2024-02-26 20:12:17.867435 | [MatterTest] 02-26 20:12:04.208 INFO "packetHeader" : PYTHON_TEST | 2024-02-26 20:12:17.867842 | [MatterTest] 02-26 20:12:04.208 INFO { PYTHON_TEST | 2024-02-26 20:12:17.868504 | [MatterTest] 02-26 20:12:04.208 INFO "flags" : 0, PYTHON_TEST | 2024-02-26 20:12:17.869038 | [MatterTest] 02-26 20:12:04.208 INFO "msgCounter" : 27918679, PYTHON_TEST | 2024-02-26 20:12:17.869539 | [MatterTest] 02-26 20:12:04.208 INFO "securityFlags" : 0, PYTHON_TEST | 2024-02-26 20:12:17.869987 | [MatterTest] 02-26 20:12:04.208 INFO "sessionId" : 62707 PYTHON_TEST | 2024-02-26 20:12:17.870421 | [MatterTest] 02-26 20:12:04.209 INFO }, PYTHON_TEST | 2024-02-26 20:12:17.870849 | [MatterTest] 02-26 20:12:04.209 INFO "payload" : PYTHON_TEST | 2024-02-26 20:12:17.871292 | [MatterTest] 02-26 20:12:04.209 INFO { PYTHON_TEST | 2024-02-26 20:12:17.871708 | [MatterTest] 02-26 20:12:04.209 INFO "decoded" : PYTHON_TEST | 2024-02-26 20:12:17.872389 | [MatterTest] 02-26 20:12:04.209 INFO { PYTHON_TEST | 2024-02-26 20:12:17.872802 | [MatterTest] 02-26 20:12:04.209 INFO "report_data" : PYTHON_TEST | 2024-02-26 20:12:17.873207 | [MatterTest] 02-26 20:12:04.209 INFO { PYTHON_TEST | 2024-02-26 20:12:17.873617 | [MatterTest] 02-26 20:12:04.209 INFO "attribute_reports" : PYTHON_TEST | 2024-02-26 20:12:17.874020 | [MatterTest] 02-26 20:12:04.209 INFO { PYTHON_TEST | 2024-02-26 20:12:17.874471 | [MatterTest] 02-26 20:12:04.210 INFO "Anonymous<0>" : PYTHON_TEST | 2024-02-26 20:12:17.874917 | [MatterTest] 02-26 20:12:04.210 INFO { PYTHON_TEST | 2024-02-26 20:12:17.875412 | [MatterTest] 02-26 20:12:04.210 INFO "attribute_status" : PYTHON_TEST | 2024-02-26 20:12:17.875795 | [MatterTest] 02-26 20:12:04.210 INFO { PYTHON_TEST | 2024-02-26 20:12:17.876499 | [MatterTest] 02-26 20:12:04.210 INFO "path" : PYTHON_TEST | 2024-02-26 20:12:17.876961 | [MatterTest] 02-26 20:12:04.210 INFO { PYTHON_TEST | 2024-02-26 20:12:17.877388 | [MatterTest] 02-26 20:12:04.210 INFO "attribute_id" : "0 == 'acl'", PYTHON_TEST | 2024-02-26 20:12:17.877813 | [MatterTest] 02-26 20:12:04.210 INFO "cluster_id" : "31 == 'AccessControl'", PYTHON_TEST | 2024-02-26 20:12:17.881214 | [MatterTest] 02-26 20:12:04.211 INFO "endpoint_id" : "0" PYTHON_TEST | 2024-02-26 20:12:17.882095 | [MatterTest] 02-26 20:12:04.211 INFO }, PYTHON_TEST | 2024-02-26 20:12:17.882531 | [MatterTest] 02-26 20:12:04.211 INFO "status" : PYTHON_TEST | 2024-02-26 20:12:17.887163 | [MatterTest] 02-26 20:12:04.211 INFO { PYTHON_TEST | 2024-02-26 20:12:17.887561 | [MatterTest] 02-26 20:12:04.211 INFO "status" : "126 == kUnsupportedAccess" PYTHON_TEST | 2024-02-26 20:12:17.887942 | [MatterTest] 02-26 20:12:04.211 INFO } PYTHON_TEST | 2024-02-26 20:12:17.888526 | [MatterTest] 02-26 20:12:04.211 INFO } PYTHON_TEST | 2024-02-26 20:12:17.888848 | [MatterTest] 02-26 20:12:04.211 INFO } PYTHON_TEST | 2024-02-26 20:12:17.889186 | [MatterTest] 02-26 20:12:04.211 INFO }, PYTHON_TEST | 2024-02-26 20:12:17.889497 | [MatterTest] 02-26 20:12:04.212 INFO "interaction_model_revison" : "11", PYTHON_TEST | 2024-02-26 20:12:17.889818 | [MatterTest] 02-26 20:12:04.212 INFO "suppress_response" : "true" PYTHON_TEST | 2024-02-26 20:12:17.890223 | [MatterTest] 02-26 20:12:04.212 INFO } PYTHON_TEST | 2024-02-26 20:12:17.890551 | [MatterTest] 02-26 20:12:04.212 INFO }, PYTHON_TEST | 2024-02-26 20:12:17.890870 | [MatterTest] 02-26 20:12:04.212 INFO "hex" : "153601153500370024020024031F24040018350124007E18181818290424FF0B18", PYTHON_TEST | 2024-02-26 20:12:17.896557 | [MatterTest] 02-26 20:12:04.212 INFO "size" : 33 PYTHON_TEST | 2024-02-26 20:12:17.896943 | [MatterTest] 02-26 20:12:04.212 INFO }, PYTHON_TEST | 2024-02-26 20:12:17.897358 | [MatterTest] 02-26 20:12:04.213 INFO "payloadHeader" : PYTHON_TEST | 2024-02-26 20:12:17.897764 | [MatterTest] 02-26 20:12:04.213 INFO { PYTHON_TEST | 2024-02-26 20:12:17.898218 | [MatterTest] 02-26 20:12:04.213 INFO "ackMessageCounter" : 54652188, PYTHON_TEST | 2024-02-26 20:12:17.898647 | [MatterTest] 02-26 20:12:04.213 INFO "exchangeFlags" : 6, PYTHON_TEST | 2024-02-26 20:12:17.899050 | [MatterTest] 02-26 20:12:04.213 INFO "exchangeId" : 16327, PYTHON_TEST | 2024-02-26 20:12:17.899511 | [MatterTest] 02-26 20:12:04.213 INFO "initiator" : false, PYTHON_TEST | 2024-02-26 20:12:17.899933 | [MatterTest] 02-26 20:12:04.214 INFO "messageType" : 5, PYTHON_TEST | 2024-02-26 20:12:17.900517 | [MatterTest] 02-26 20:12:04.214 INFO "needsAck" : true, PYTHON_TEST | 2024-02-26 20:12:17.900978 | [MatterTest] 02-26 20:12:04.214 INFO "protocolId" : 1 PYTHON_TEST | 2024-02-26 20:12:17.901424 | [MatterTest] 02-26 20:12:04.214 INFO } PYTHON_TEST | 2024-02-26 20:12:17.901827 | [MatterTest] 02-26 20:12:04.214 INFO } PYTHON_TEST | 2024-02-26 20:12:17.902283 | [MatterTest] 02-26 20:12:04.214 INFO >>> [E:16327i S:62707 M:27918679 (Ack:54652188)] (S) Msg RX from 1:0000000012344321 [3D0F] --- Type 0001:05 (IM:ReportData) ```
ccruzagralopes commented 6 months ago

@cecille do you have any ideia why there's a difference in these executions?

cecille commented 6 months ago

It's this:

if __name__ == "__main__":
    default_matter_test_main(maximize_cert_chains=True, controller_cat_tags=[0x0001_0001])

When the test is run on its own, the default controller is created with cat tags, and that's what's used to retain access to the acl cluster.

When it's run though the TH, it's not set up to do that. And because of the way those got crammed in there, there's no good way to pass them through. We'll have to make some changes to allow those to be set up by the TH. But actually, if we want this to be able to be run as a set, we should just cram those onto the cert for every commissioning.

ccruzagralopes commented 6 months ago

But actually, if we want this to be able to be run as a set, we should just cram those onto the cert for every commissioning.

I think that would be the best option, because we'd like to commission once and then run multiple test cases.

cecille commented 6 months ago

@ccruzagralopes - Carolina, would you mind trying out a PR in the TH to make sure it fixes the issue for the TH? https://github.com/project-chip/connectedhomeip/pull/32468

ccruzagralopes commented 6 months ago

Not at all, I'll test it. Thanks!

ccruzagralopes commented 6 months ago

I tried it out and that ValueDecodeFailure doesn't happen anymore, but I'm back to the timeout I was facing before. UI_Test_Run_2024_03_08_16_35_00.log

Maybe that's some problem with my environment. I'm using a VM right now, I'll try it out with a Raspberry Pi.

ccruzagralopes commented 6 months ago

Got the same result running in a Raspberry Pi