search

project-chip / connectedhomeip

Matter (formerly Project CHIP) creates more connections between more objects, simplifying development for manufacturers and increasing compatibility for consumers, guided by the Connectivity Standards Alliance.
https://buildwithmatter.com
Apache License 2.0
7.45k stars 1.99k forks source link

[CERT-TEST-FAILURE] [TC-SEAR-1.5, 1.6] Python Test Failure #34905

Closed Ashwinigrl closed 1 month ago

Ashwinigrl commented 2 months ago

Feature Area

Other

Test Case

TC-SEAR-1.5 TC-SEAR-1.6

Reproduction steps

  1. Command used to launch the DUT : ./chip-rvc-app
  2. Command used to run the python script :python3 TC_SEAR_1_6.py --commissioning-method on-network --discriminator 3840 --passcode 20202021 --PICS ServiceArea.txt --app-pid 30984 --storage-path admin_storage.json --endpoint 1 --paa-trust-store-path ../../credentials/development/paa-root-certs/

While executing the TC-SEAR-1.6 Python script, the test is failing at Test Step 4 : Read SelectedAreas attribute. This test step expects to verify that selected_areas has at least one entry. and depending on the test step 2 Manually intervene to put the device in the idle state and ensure SupportedAreas and SelectedAreas are not empty as we are not doing any manual intervene test step 3 Read SelectedAreas is failing with null value but expecting atleast one entry in list. However, the script does not include any method to trigger the DUT to do the Manual intervene .Therefore, the Python script needs to be updated to include a method for triggering the DUT.

[MatterTest] 08-09 07:46:52.216 INFO ** Test Step 4 : Read SelectedAreas attribute [MatterTest] 08-09 07:46:52.219 INFO Found an existing secure session to [1:0000000012344321]! [MatterTest] 08-09 07:46:52.221 INFO 0 data version filters provided, 0 not relevant, 0 encoded, 0 skipped due to lack of space [MatterTest] 08-09 07:46:52.222 INFO <<< [E:6622i S:61662 M:257281917] (S) Msg TX to 1:0000000012344321 [F5F8] [UDP:[fe80::e65f:1ff:fe0e:baf7%eth0]:5540] --- Type 0001:02 (IM:ReadRequest) (B:52) [MatterTest] 08-09 07:46:52.225 INFO >>> [E:6622i S:61662 M:61093412 (Ack:257281917)] (S) Msg RX from 1:0000000012344321 [F5F8] --- Type 0001:05 (IM:ReportData) (B:71) [MatterTest] 08-09 07:46:52.233 INFO <<< [E:6622i S:61662 M:257281918 (Ack:61093412)] (S) Msg TX to 1:0000000012344321 [F5F8] [UDP:[fe80::e65f:1ff:fe0e:baf7%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34) [MatterTest] 08-09 07:46:52.233 INFO SelectedAreas [] [MatterTest] 08-09 07:46:52.236 ERROR Exception occurred in test_TC_SEAR_1_6. Traceback (most recent call last): File "/home/ubuntu/cntr/connectedhomeip/no/lib/python3.10/site-packages/mobly/base_test.py", line 783, in exec_one_test test_method() File "/home/ubuntu/cntr/connectedhomeip/src/python_testing/matter_testing_support.py", line 1744, in async_runner return _async_runner(body, self, args, kwargs) File "/home/ubuntu/cntr/connectedhomeip/src/python_testing/matter_testing_support.py", line 1732, 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 "/home/ubuntu/cntr/connectedhomeip/src/python_testing/TC_SEAR_1_6.py", line 112, in test_TC_SEAR_1_6 asserts.assert_true(len(selected_areas) > 0, "SelectedAreas is empty") File "/home/ubuntu/cntr/connectedhomeip/no/lib/python3.10/site-packages/mobly/asserts.py", line 353, in assert_true fail(msg, extras) File "/home/ubuntu/cntr/connectedhomeip/no/lib/python3.10/site-packages/mobly/asserts.py", line 475, in fail raise signals.TestFailure(msg, extras) mobly.signals.TestFailure: Details=SelectedAreas is empty, Extras=None

Bug prevalence

Whenever I do

GitHub hash of the SDK that was being used

78d4020a890e78ac58dad5b1bf846714fb5f334c

Platform

raspi

Anything else?

same Issue with TC-SEAR-1.5

Python Script References:

Reference Log: TC-SEAR-1.6.txt TC-SEAR-1_5.txt

Below python TC-RVCRUNM-2.2 test for reference, It is using write_to_app_pipe for test step Manually intervene required.

raul-marquez-csa commented 2 months ago

@Ashwinigrl, can you provide the ServiceArea.txt PICS file mentioned in the run command?

raul-marquez-csa commented 2 months ago

In absense of the ServiceArea.txt PICS file, I used examples/rvc-app/rvc-common/pics/rvc-app-pics-values.

This is how I'm running the command: python3 src/python_testing/TC_SEAR_1_6.py --commissioning-method on-network --discriminator 3840 --passcode 20202021 --PICS examples/rvc-app/rvc-common/pics/rvc-app-pics-values --app-pid $(pidof chip-rvc-app) --storage-path admin_storage.json --endpoint 1 --paa-trust-store-path /credentials/development/paa-root-certs/

Unable to commision, getting this error:

Successfully finished commissioning step 'Cleanup'
[MatterTest] 08-17 17:42:01.693 INFO SecureSession[0x7feaf800cd30, LSID:3140]: State change 'kActive' --> 'kPendingEviction'
[MatterTest] 08-17 17:42:01.693 ERROR Failed to send Solitary ack for MessageCounter:46460044 on exchange 14598i:src/messaging/ExchangeContext.cpp:99: CHIP Error 0x00000002: Connection aborted
[MatterTest] 08-17 17:42:01.693 INFO Commissioning complete for node ID 0x0000000012344321: src/controller/CHIPDeviceController.cpp:1329: CHIP Error 0x000000AC: Internal error
[MatterTest] 08-17 17:42:01.693 WARNING Failed to commission: src/controller/CHIPDeviceController.cpp:1329: CHIP Error 0x000000AC: Internal error
[MatterTest] 08-17 17:42:01.693 ERROR Commissioning failed: src/controller/CHIPDeviceController.cpp:1329: CHIP Error 0x000000AC: Internal error
[MatterTest] 08-17 17:42:01.694 INFO [Test] test_run_commissioning FAIL
[MatterTest] 08-17 17:42:01.695 INFO Summary for test class CommissionDeviceTest: Error 0, Executed 1, Failed 1, Passed 0, Requested 1, Skipped 0
[MatterTest] 08-17 17:42:01.695 WARNING Abort all subsequent test classes. Reason: Details=All remaining tests aborted due to: Failed to commission node, Extras=None

Logs from the rvc app:

[1723941721.692711][452959:452959] CHIP:IN: SecureSession[0x55f22a2ec380]: MarkForEviction Type:1 LSID:56102
[1723941721.692714][452959:452959] CHIP:SC: SecureSession[0x55f22a2ec380, LSID:56102]: State change 'kActive' --> 'kPendingEviction'
[1723941721.692723][452959:452959] CHIP:IN: SecureSession[0x55f22a2ec380]: Released - Type:1 LSID:56102
[1723941721.692737][452959:452959] CHIP:SVR: Commissioning failed (attempt 1): src/app/server/CommissioningWindowManager.cpp:89: CHIP Error 0x00000032: Timeout
[1723941721.692760][452959:452959] CHIP:IN: SecureSession[0x55f22a2ec380]: Allocated Type:1 LSID:56104
[1723941721.692770][452959:452959] CHIP:SC: Assigned local session key ID 56104
[1723941721.692773][452959:452959] CHIP:SC: Waiting for PBKDF param request
[1723941721.692778][452959:452959] CHIP:DIS: Updating services using commissioning mode 1
[1723941721.696045][452959:452959] CHIP:DIS: CHIP minimal mDNS started advertising.
[1723941721.703220][452959:452959] CHIP:DL: Using WiFi MAC for hostname
[1723941721.703282][452959:452959] CHIP:DIS: Advertise commission parameter vendorID=65521 productID=32769 discriminator=3840/15 cm=1 cp=0
[1723941721.703291][452959:452959] CHIP:DIS: Responding with _matterc._udp.local
[1723941721.703303][452959:452959] CHIP:DIS: Responding with 2B74D48BBD4835CD._matterc._udp.local
[1723941721.703305][452959:452959] CHIP:DIS: Responding with 00155DCF11DE0000.local
[1723941721.703307][452959:452959] CHIP:DIS: Responding with 00155DCF11DE0000.local
[1723941721.703310][452959:452959] CHIP:DIS: Responding with _V65521._sub._matterc._udp.local
[1723941721.703312][452959:452959] CHIP:DIS: Responding with _S15._sub._matterc._udp.local
[1723941721.703322][452959:452959] CHIP:DIS: Responding with _L3840._sub._matterc._udp.local
[1723941721.703326][452959:452959] CHIP:DIS: Responding with _CM._sub._matterc._udp.local
[1723941721.703330][452959:452959] CHIP:DIS: Responding with 2B74D48BBD4835CD._matterc._udp.local
[1723941721.703333][452959:452959] CHIP:DIS: CHIP minimal mDNS configured as 'Commissionable node device'; instance name: 2B74D48BBD4835CD.
[1723941721.712380][452959:452959] CHIP:DIS: mDNS service published: _matterc._udp
[1723941721.712400][452959:452959] CHIP:ZCL: OpCreds: Got FailSafeTimerExpired
[1723941721.712403][452959:452959] CHIP:ZCL: OpCreds: Proceeding to FailSafeCleanup on fail-safe expiry!
[1723941721.712411][452959:452959] CHIP:TS: Pending Last Known Good Time: 2023-10-14T01:16:48
[1723941721.712432][452959:452959] CHIP:TS: Previous Last Known Good Time: 2023-10-14T01:16:48
[1723941721.712443][452959:452959] CHIP:TS: Reverted Last Known Good Time to previous value
[1723941721.712454][452959:452959] CHIP:DMG: Endpoint 0, Cluster 0x0000_0030 update version to 92008cc3
[1723941721.712472][452959:452959] CHIP:FS: Fail-safe cleanly disarmed
[1723941721.712508][452959:452959] CHIP:IN: Data received on an unknown session (LSID=56102). Dropping it!
Ashwinigrl commented 2 months ago

@Ashwinigrl, can you provide the ServiceArea.txt PICS file mentioned in the run command?

@raul-marquez-csa Here is the PICS file used [ Service Area Cluster Test Plan.zip…]()

Ashwinigrl commented 2 months ago

@raul-marquez-csa Can you please run the test in the src/python_testing path using the following command: python3 TC_SEAR_1_6.py --commissioning-method on-network --discriminator 3840 --passcode 20202021 --PICS <PICS FILE> --app-pid <PID of RVC app> --storage-path admin_storage.json --endpoint 1 --paa-trust-store-path ../../credentials/development/paa-root-certs/. I am able to commission with this.

Reference Log: TC-SEAR-1.6.txt

PICS file used: Service Area Cluster Test Plan.zip

hicklin commented 1 month ago

@Ashwinigrl, is it OK to close this now? These tests are running in CI following this PR so the issue that you are pointing out here clearly dose not exist anymore.

Ashwinigrl commented 1 month ago

Issue fixed . Hence closing it.