[CERT-TEST-FAILURE] CommissioningComplete Fails with Timeout in TC_CGEN_2_8 and TC_CGEN_2_9 Due to Data received on an unknown session at test step 8

[Rajashreekalmane]

Feature Area

Other

Test Case

TC_CGEN_2_8 and TC_CGEN_2_9

Reproduction steps

Issue Summary:

The TC_CGEN_2_8 and TC_CGEN_2_9 - Test case fail at Step 8 due to a session error and timeout after sending the CommissioningComplete command at step 8. Logs show "Data received on an unknown session (LSID=25849). Dropping it!", followed by retransmissions and a CHIP Error 0x00000032: Timeout.t.

Test Execution Details:

• Test Cases: TC_CGEN_2_8, TC_CGEN_2_9
• DUT terms-and-conditions-app

Logs:

DUT Launched with Command:
./chip-terms-and-conditions-app --tc-min-required-version 1 --tc-required-acknowledgements 1 --custom-flow 2 --capabilities 6

The following test cases were executed using the Python controller:

• python3 TC_CGEN_2_8.py --storage-path admin_storage.json --int-arg PIXIT.CGEN.FailsafeExpiryLengthSeconds:900 PIXIT.CGEN.RequiredTCAcknowledgements:1 PIXIT.CGEN.TCRevision:1 --qr-code MT:-24J08M.00KA0648G00 --PICS /home/ubuntu/Feb10_DUT/connectedhomeip/src/app/tests/suites/certification/ci-pics-values --in-test-commissioning-method on-network --timeout 100000

• python3 TC_CGEN_2_9.py --storage-path admin_storage.json --int-arg PIXIT.CGEN.FailsafeExpiryLengthSeconds:900 PIXIT.CGEN.RequiredTCAcknowledgements:1 PIXIT.CGEN.TCRevision:1 --qr-code MT:-24J08M.00KA0648G00 --PICS /home/ubuntu/Feb10_DUT/connectedhomeip/src/app/tests/suites/certification/ci-pics-values --in-test-commissioning-method on-network --timeout 1000

[MatterTest] 02-10 11:42:36.167 INFO Commissioning complete
[MatterTest] 02-10 11:42:36.168 INFO ***** Test Step 8 : TH sends CommissioningComplete to DUT.
[MatterTest] 02-10 11:42:36.168 INFO ***** Test Step 8 : TH sends CommissioningComplete to DUT.
[MatterTest] 02-10 11:42:36.170 INFO Found an existing secure session to [1:0000000012344321]!
[MatterTest] 02-10 11:42:36.173 INFO <<< [E:10160i S:1789 M:39330790] (S) Msg TX from 000000000001B669 to 1:0000000012344321 [80F1] [UDP:[fe80::5a08:6a03:c408:d1bb%wlan0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) (B:59)
[MatterTest] 02-10 11:42:36.173 INFO ??1 [E:10160i S:1789 M:39330790] (S) Msg Retransmission to 1:0000000012344321 scheduled for 621ms from now [State:Idle II:500 AI:300 AT:4000]
[MatterTest] 02-10 11:42:36.544 ERROR Data received on an unknown session (LSID=1790). Dropping it!
[MatterTest] 02-10 11:42:36.548 INFO Avahi browse: remove
[MatterTest] 02-10 11:42:36.795 INFO <<1 [E:10160i S:1789 M:39330790] (S) Msg Retransmission to 1:0000000012344321
[MatterTest] 02-10 11:42:36.797 INFO ??2 [E:10160i S:1789 M:39330790] (S) Msg Retransmission to 1:0000000012344321 scheduled for 594ms from now [State:Idle II:500 AI:300 AT:4000]
[MatterTest] 02-10 11:42:36.898 ERROR Data received on an unknown session (LSID=1790). Dropping it!
[MatterTest] 02-10 11:42:37.391 INFO <<2 [E:10160i S:1789 M:39330790] (S) Msg Retransmission to 1:0000000012344321
[MatterTest] 02-10 11:42:37.392 INFO ??3 [E:10160i S:1789 M:39330790] (S) Msg Retransmission to 1:0000000012344321 scheduled for 903ms from now [State:Idle II:500 AI:300 AT:4000]
[MatterTest] 02-10 11:42:37.530 ERROR Data received on an unknown session (LSID=1790). Dropping it!
[MatterTest] 02-10 11:42:38.296 INFO <<3 [E:10160i S:1789 M:39330790] (S) Msg Retransmission to 1:0000000012344321
[MatterTest] 02-10 11:42:38.297 INFO ??4 [E:10160i S:1789 M:39330790] (S) Msg Retransmission to 1:0000000012344321 scheduled for 1541ms from now [State:Idle II:500 AI:300 AT:4000]
[MatterTest] 02-10 11:42:38.542 ERROR Data received on an unknown session (LSID=1790). Dropping it!
[MatterTest] 02-10 11:42:39.840 INFO <<4 [E:10160i S:1789 M:39330790] (S) Msg Retransmission to 1:0000000012344321
[MatterTest] 02-10 11:42:39.841 INFO ??5 [E:10160i S:1789 M:39330790] (S) Msg Retransmission to 1:0000000012344321 scheduled for 2674ms from now [State:Idle II:500 AI:300 AT:4000]
[MatterTest] 02-10 11:42:42.518 ERROR <<5 [E:10160i S:1789 M:39330790] (S) Msg Retransmission to 1:0000000012344321 failure (max retries:4)
[MatterTest] 02-10 11:42:49.441 INFO SecureSession[0xffff9000b2f0, LSID:1789]: State change 'kActive' --> 'kDefunct'
[MatterTest] 02-10 11:42:49.444 INFO Time out! failed to receive invoke command response from Exchange: 10160i
[MatterTest] 02-10 11:42:49.446 ERROR Exception occurred in test_TC_CGEN_2_9.
Traceback (most recent call last):
File "/home/ubuntu/Feb10_DUT/connectedhomeip/no/lib/python3.12/site-packages/mobly/base_test.py", line 818, in exec_one_test
test_method()
File "/home/ubuntu/Feb10_DUT/connectedhomeip/no/lib/python3.12/site-packages/chip/testing/matter_testing.py", line 2220, in async_runner
return _async_runner(body, self, *args, **kwargs)
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/home/ubuntu/Feb10_DUT/connectedhomeip/no/lib/python3.12/site-packages/chip/testing/matter_testing.py", line 2208, in _async_runner
return self.event_loop.run_until_complete(asyncio.wait_for(body(self, *args, **kwargs), timeout=timeout))
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/usr/lib/python3.12/asyncio/base_events.py", line 687, in run_until_complete
return future.result()
^^^^^^^^^^^^^^^
File "/usr/lib/python3.12/asyncio/tasks.py", line 520, in wait_for
return await fut
^^^^^^^^^
File "/home/ubuntu/Feb10_DUT/connectedhomeip/src/python_testing/TC_CGEN_2_9.py", line 179, in test_TC_CGEN_2_9
response = await commissioner.SendCommand(
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
File "/home/ubuntu/Feb10_DUT/connectedhomeip/no/lib/python3.12/site-packages/chip/ChipDeviceCtrl.py", line 1216, in SendCommand
return await future
^^^^^^^^^^^^
chip.exceptions.ChipStackError: src/app/CommandSender.cpp:343: CHIP Error 0x00000032: Timeout
[MatterTest] 02-10 11:42:49.459 INFO ***** Test Failure :
[MatterTest] 02-10 11:42:49.459 INFO Finished test in 30382167.0ms
[MatterTest] 02-10 11:42:49.460 ERROR

---

• Test test_TC_CGEN_2_9 failed for the following reason:
• src/app/CommandSender.cpp:343: CHIP Error 0x00000032: Timeout
• File "/home/ubuntu/Feb10_DUT/connectedhomeip/no/lib/python3.12/site-packages/chip/ChipDeviceCtrl.py", line 1216, in SendCommand
• chip.exceptions.ChipStackError: src/app/CommandSender.cpp:343: CHIP Error 0x00000032: Timeout
• Test step:

• 8: TH sends CommissioningComplete to DUT.	Expected outcome: 
  

• Endpoint: None

---

[MatterTest] 02-10 11:42:49.461 INFO [Test] test_TC_CGEN_2_9 ERROR

Observed Behavior:

• TH sends CommissioningComplete, but the response from the DUT is not received.
• The session seems to be lost or mismatched (Data received on an unknown session (LSID=1790). Dropping it!).
• After multiple retransmissions, the test fails due to a timeout.

Expected Behavior:
The DUT should successfully process CommissioningComplete and respond to the TH.

Test-Plan Reference :
https://github.com/CHIP-Specifications/chip-test-plans/blob/master/src/cluster/General_Commissioning.adoc#tc-cgen-2-8-verification-that-tcacknowledgements-tcacceptedversion-and-tcacknowledgementsrequired-are-reset-after-factory-reset-dut_server
https://github.com/CHIP-Specifications/chip-test-plans/blob/master/src/cluster/General_Commissioning.adoc#tc-cgen-2-9-verification-that-tcacknowledgements-is-reset-after-all-fabrics-removed-dut_server

Script Reference :
https://github.com/project-chip/connectedhomeip/blob/master/src/python_testing/TC_CGEN_2_8.py
https://github.com/project-chip/connectedhomeip/blob/master/src/python_testing/TC_CGEN_2_9.py

Bug prevalence

whenever I do

GitHub hash of the SDK that was being used

e86768b

Platform

raspi

Anything else?

Execution logs for your reference :
TC-CGEN-2-8 DUT(terms-and-conditions-app).txt
TC-CGEN-2-8 python controller.txt

TC-CGEN-2-9 DUT(terms-and-conditions-app).txt
TC-CGEN-2-9 python controller.txt

[swan-amazon]

@Rajashreekalmane , did you perhaps not factory reset the device between test cases? If so, please remove any temporary storage between test cases. Let me know if this is the case and we can improve this as a followup.

[swan-amazon]

Hi @Rajashreekalmane , I took a closer look. Test TC_CGEN_2_8 requires manual user intervention to factory reset the device, and it appears you were running in a automated way with the PICS value set indicating that user input is available (but it wasn't). Same for 2_9. After the script removes all of the fabrics, the DUT needs to be manually set into commissioning mode. The sample apps don't automatically re-enter commissioning mode after all fabrics are removed. We should improve this in the near future.

[Rajashreekalmane]

@swan-amazon I performed manual user interaction on the DUT.
For the TC-CGEN-2.8 test case at step 5, I did a factory reset and relaunched the DUT.
For the TC-CGEN-2.9 test case at step 6, I rebooted and relaunched the DUT,
but the test case is still failing after enabling the self.is_pics_sdk_ci_only PICS