[Bug] [SVE 1.6] TC-SC-3.5 Too many logs, too short timeouts for user prompt (trying to read logs)

[TUVRKvora]

Describe the bug

Docker used

docker run -v /var/paa-root-certs/:/paa_roots -v /var/run/dbus/system_bus_socket:/var/run/dbus/system_bus_socket -v mapped_data_model:/root/python_testing/data_model -v /home/ubuntu/certification-tool/backend/test_collections/matter/sdk_tests/sdk_checkout/python_testing/scripts/sdk:/root/python_testing -v $(pwd):/launch_dir --privileged --network host -it connectedhomeip/chip-cert-bins:96b1d9b9415310d61c844466fe2e1338902f662d

command used

python3 python_testing/TC_SC_3_5.py --storage-path admin_storage.json --string-arg th_server_app_path:/root/chip-all-clusters-app-nlfaultinject

test case just ends in Error

Steps to reproduce the behavior

TC-SC-3.5_Issue.txt

Expected behavior

No response

Log files

No response

PICS file

No response

Screenshots

No response

Environment

No response

Additional Information

No response

[TUVRKvora]

Hello, When i execute test case in docker the script executes with error

1. need help how to execute test case
2. there are python3 TC_SC_3_5.py --storage-path admin_storage.json --string-arg th_server_app_path:</root/chip-all-clusters-app-nlfaultinject> in command which we have removed else bash gives issue --- this should be either removed form .xlsx

[cecille]

@Alami-Amine - would you be able to take a look here?

[Alami-Amine]

• The failure happens in Commissioning, in the "precondition" before the test starts --> in the call to await self.th_client.CommissionOnNetwork
• It looks like an environment issue, maybe you need to delete something before running the test? maybe /tmp/repl-storage.json
• Because It looks like your PAA is at fault.

[MatterTest] 04-23 15:13:52.818 ERROR Unable to find PAA, err: src/credentials/attestation_verifier/FileAttestationTrustStore.cpp:157: CHIP Error 0x0000004A: CA certificate not found, PAI's AKID: 6A:FD:22:77:1F:51:1F:EC:BF:16:41:97:67:10:DC:DC:31:A1:71:7E

• Log for the failing Commissioning Stage (AttestationVerification (12)):

[MatterTest] 04-23 15:13:52.771 INFO stageStarting=AttestationVerification (12)
[MatterTest] 04-23 15:13:52.772 INFO Verifying Device Attestation information received from the device
[MatterTest] 04-23 15:13:52.785 INFO Device candidate DAC chain details:
[MatterTest] 04-23 15:13:52.786 INFO --> DAC's VID: 0xFFF1, PID: 0x8001
[MatterTest] 04-23 15:13:52.787 INFO ==== DAC certificate considered (491 bytes) ====
[MatterTest] 04-23 15:13:52.788 INFO -----BEGIN CERTIFICATE-----
[MatterTest] 04-23 15:13:52.789 INFO MIIB5zCCAY6gAwIBAgIIac3xDenlTtEwCgYIKoZIzj0EAwIwPTElMCMGA1UEAwwc
[MatterTest] 04-23 15:13:52.789 INFO TWF0dGVyIERldiBQQUkgMHhGRkYxIG5vIFBJRDEUMBIGCisGAQQBgqJ8AgEMBEZG
[MatterTest] 04-23 15:13:52.790 INFO RjEwIBcNMjIwMjA1MDAwMDAwWhgPOTk5OTEyMzEyMzU5NTlaMFMxJTAjBgNVBAMM
[MatterTest] 04-23 15:13:52.791 INFO HE1hdHRlciBEZXYgREFDIDB4RkZGMS8weDgwMDExFDASBgorBgEEAYKifAIBDARG
[MatterTest] 04-23 15:13:52.791 INFO RkYxMRQwEgYKKwYBBAGConwCAgwEODAwMTBZMBMGByqGSM49AgEGCCqGSM49AwEH
[MatterTest] 04-23 15:13:52.792 INFO A0IABEY6xpNCkQoOVYj8b/Vrtj5i7M7LFI99TrA+5VJgFBV2fRalxmP3k+SRIyYL
[MatterTest] 04-23 15:13:52.793 INFO gpenzX58/HsxaznZjpDSk3dzjoKjYDBeMAwGA1UdEwEB/wQCMAAwDgYDVR0PAQH/
[MatterTest] 04-23 15:13:52.793 INFO BAQDAgeAMB0GA1UdDgQWBBSI3eezADgpMs/3NMBGJIEPRBaKbzAfBgNVHSMEGDAW
[MatterTest] 04-23 15:13:52.794 INFO gBRjVA5H9kscONE4hKRi0WwZXY/7PDAKBggqhkjOPQQDAgNHADBEAiABJ6J7S0Rh
[MatterTest] 04-23 15:13:52.795 INFO DuL83E0reIVWNmC8D3bxchntagjfsrPBzQIga1ngr0Xz6yqFuRnTVzFSjGAoxBUj
[MatterTest] 04-23 15:13:52.795 INFO lUXhCOTlTnCXE1M=
[MatterTest] 04-23 15:13:52.796 INFO -----END CERTIFICATE-----
[MatterTest] 04-23 15:13:52.798 INFO --> DAC certificate SKID: 88:DD:E7:B3:00:38:29:32:CF:F7:34:C0:46:24:81:0F:44:16:8A:6F
[MatterTest] 04-23 15:13:52.800 INFO --> DAC certificate AKID: 63:54:0E:47:F6:4B:1C:38:D1:38:84:A4:62:D1:6C:19:5D:8F:FB:3C
[MatterTest] 04-23 15:13:52.801 INFO ==== PAI certificate considered (463 bytes) ====
[MatterTest] 04-23 15:13:52.801 INFO -----BEGIN CERTIFICATE-----
[MatterTest] 04-23 15:13:52.802 INFO MIIByzCCAXGgAwIBAgIIVq2CIq2UW2QwCgYIKoZIzj0EAwIwMDEYMBYGA1UEAwwP
[MatterTest] 04-23 15:13:52.803 INFO TWF0dGVyIFRlc3QgUEFBMRQwEgYKKwYBBAGConwCAQwERkZGMTAgFw0yMjAyMDUw
[MatterTest] 04-23 15:13:52.804 INFO MDAwMDBaGA85OTk5MTIzMTIzNTk1OVowPTElMCMGA1UEAwwcTWF0dGVyIERldiBQ
[MatterTest] 04-23 15:13:52.804 INFO QUkgMHhGRkYxIG5vIFBJRDEUMBIGCisGAQQBgqJ8AgEMBEZGRjEwWTATBgcqhkjO
[MatterTest] 04-23 15:13:52.805 INFO PQIBBggqhkjOPQMBBwNCAARBmpMVwhc+DIyHbQPM/JRIUmR/f+xeUIL0BZko7KiU
[MatterTest] 04-23 15:13:52.806 INFO xZQVEwmsYx5MsDOSr2hLC6+35ls7gWLC9Sv5MbjneqqCo2YwZDASBgNVHRMBAf8E
[MatterTest] 04-23 15:13:52.806 INFO CDAGAQH/AgEAMA4GA1UdDwEB/wQEAwIBBjAdBgNVHQ4EFgQUY1QOR/ZLHDjROISk
[MatterTest] 04-23 15:13:52.807 INFO YtFsGV2P+zwwHwYDVR0jBBgwFoAUav0idx9RH+y/FkGXZxDc3DGhcX4wCgYIKoZI
[MatterTest] 04-23 15:13:52.808 INFO zj0EAwIDSAAwRQIhALLvJ/Sa6bUPuR7qyUxNC9u415KcbLiPrOUpNo0SBUwMAiBl
[MatterTest] 04-23 15:13:52.809 INFO Xckrhr2QmIKmxiF3uCXX0F7b58Ivn+pxIg5+pwP4kQ==
[MatterTest] 04-23 15:13:52.809 INFO -----END CERTIFICATE-----
[MatterTest] 04-23 15:13:52.811 INFO --> PAI certificate SKID: 63:54:0E:47:F6:4B:1C:38:D1:38:84:A4:62:D1:6C:19:5D:8F:FB:3C
[MatterTest] 04-23 15:13:52.813 INFO --> PAI certificate AKID: 6A:FD:22:77:1F:51:1F:EC:BF:16:41:97:67:10:DC:DC:31:A1:71:7E
[MatterTest] 04-23 15:13:52.818 ERROR Unable to find PAA, err: src/credentials/attestation_verifier/FileAttestationTrustStore.cpp:157: CHIP Error 0x0000004A: CA certificate not found, PAI's AKID: 6A:FD:22:77:1F:51:1F:EC:BF:16:41:97:67:10:DC:DC:31:A1:71:7E
[MatterTest] 04-23 15:13:52.819 ERROR Error on commissioning step 'AttestationVerification': 'src/controller/CHIPDeviceController.cpp:1389: CHIP Error 0x00000020: Failed Device Attestation'
[MatterTest] 04-23 15:13:52.820 ERROR Failed verifying attestation information. Now checking DAC chain revoked status.
[MatterTest] 04-23 15:13:52.821 INFO Commissioning stage next step: 'AttestationVerification' -> 'AttestationRevocationCheck'
[MatterTest] 04-23 15:13:52.822 INFO Performing next commissioning step 'AttestationRevocationCheck' with completion status = 'src/controller/CHIPDeviceController.cpp:1389: CHIP Error 0x00000020: Failed Device Attestation'
[MatterTest] 04-23 15:13:52.822 INFO ScriptDevicePairingDelegate::OnCommissioningStageStart
[MatterTest] 04-23 15:13:52.823 INFO nodeId=0000000000000457
[MatterTest] 04-23 15:13:52.824 INFO stageStarting=AttestationRevocationCheck (13)
[MatterTest] 04-23 15:13:52.824 INFO Verifying the device's DAC chain revocation status
[MatterTest] 04-23 15:13:52.825 INFO WARNING: No revocation delegate available. Revocation checks will be skipped!
[MatterTest] 04-23 15:13:52.826 ERROR Failed in verifying 'Attestation Information' command received from the device: err 101 (PAA not found in DCL and/or local PAA trust store)
[SERVER][1776957232.279] [16:16] [EM] >>> [E:53470r S:58708 M:257632237 (Ack:54345985)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] to 0000000000000000 --- Type 0000:10 (SecureChannel:StandaloneAck) (B:34)
[MatterTest] 04-23 15:13:52.827 ERROR Error on commissioning step 'AttestationRevocationCheck': 'src/controller/CHIPDeviceController.cpp:1436: CHIP Error 0x00000020: Failed Device Attestation'

[Apollon77]

We will try to repro this today with another TH

[Apollon77]

Ok, the first result of retest here:

• We were not able to reproduce the results from @TUVRKvora TH but his TH is definively somehow broken
• The test (when working) is spamming the shell with logs (MDNS and also others from the "SERVER") and so any user prompts are burried in these logs. This together with the fact that you only have a limited time before the test times out in some places you need to be fast finding it
• The user prompt information about the "do a pairing now" is just including "chip tool like cli lines" with the PIN! ... Basically no real controller allows users to pair with a PIN, so we need to have the manual pairing code here instead. We tried to search for the manual pairingcode in the logs but because there are multiple logged it is then another "race against time" before there is a timeout ...

So essence: We were able to do the first pairing and test steps there, but then always fail to get the data of the second pairing try "in time" ...

[Alami-Amine]

• Can you please try with this script? I am printing the manual pairing code in the 'user prompt'
  TC_SC_3_5.py

[EDTEmadH]

• Can you please try with this script? I am printing the manual pairing code in the 'user prompt'
  TC_SC_3_5.py

Managed to complete a successful run with the updated script. However, there is a very short time window to verify the controller responses for successful and failed commissioning.

[PASS]_TC_SC_3_5_Matter16_controller_v2.txt

[Alami-Amine]

The test (when working) is spamming the shell with logs (MDNS and also others from the "SERVER") and so any user prompts are burried in these logs. This together with the fact that you only have a limited time before the test times out in some places you need to be fast finding it

• chip_minmdns_high_verbosity = true was activated for All-clusters-app for debugging purposes, we will either disable it or make it configurable, to avoid such issues in future

[Apollon77]

Additionally: The expectation that the controller directly sees a single "Case error on operative connection" as "commissioning failed" and directly ending commissioning that way is not backed by any requirements ... boils again to the waaayyy to short user prompt timeouts (as discussed above already)

It seems that the test seems the invalidParam correctly too BUT then it shuts off the device directly because what I get is

• we find 4 IPs
• we try the first one and get that InvalidParam which - in case of matter,js - does not needingly mean a direct fail because we have a 4 minute window and would try another IP to see how it is there
• but now we get "all IPs are expired" which brings our engine back into the discovery mode because we have no IPs anymore to do the CASE with

So or so we would have a 4 min operational establishment window.

The reason why "InvalidParam" is not hard cancel reason for us is that we already saw devices in the wild that were reachable via CASE in some startup or commissioning situations BUT were returning InvalidParam because they were internally still booting up or such and a next CASE try solved that

[abhisheksingh-esp]

I can reproduce this pattern, and it looks like TC-SC-3.5 depends on initialization/orchestration normally handled by TH (th-cli/backend), which is easy to miss when running the script directly in a standalone docker command.

In TH flow, there are setup steps beyond just launching TC_SC_3_5.py (commissioning context, prompt flow, runtime args, storage/state handling).
When these are not aligned, the test may end in generic error.

Could you please try running the same test through TH-CLI once and compare?

th-cli run-tests -t TC_SC_3_5 --title "TC_SC_3_5" --project-id <id> -c <config>

Also ensure:

string-arg includes th_server_app_path:/root/chip-all-clusters-app-nlfaultinject
commissioning parameters (mode/discriminator/passcode) match the DUT state
If direct docker execution is required, we may need to document the full required preconditions/args that TH usually prepares automatically.