Python Controller pairing fails with CHIP Error 0x00000003: Incorrect state

[Harshith-GRL]

Description:
I have used python controller to run a stress test on my Nordic nrf52840-DK board with sample dut all-clusters-app on Pair-Unpair test scenario for 500 iterations using TC_Darwin_pair.py script. The test passed in few iterations without any error but there are iterations which have Failed to establish PASE session while commissioning with the dut, The most frequently encountered exception is
chip.exceptions.ChipStackError: src/controller/python/ChipDeviceController-ScriptDevicePairingDelegate.cpp:96: CHIP Error 0x00000003: Incorrect state

GitHub hash of the SDK that was being used: 1b4c56c

Platform
controller - python controller running on Raspberrypi 4B -8GB,
DUT - all-cluster-app running on Nordic nrf52840-DK board
Provisioned using ble-thread

Test scenario

1. Pair/Provision the DUT (All-cluster-app running on raspi) as per drawiin pairing flow using ble-wifi
2. Read device information after the device is provisioned
3. sleep for 2 secs
4. Unpair the DUT (i.e. removing the fabric)
5. Factory reset the DUT
6. repeat step1 - 6 for 500 iterations
   Script reference: https://github.com/CHIP-Specifications/matter-qa/blob/main/src/matter_qa/scripts/reliability_scripts/TC_Darwin_Pair.py

In our execution of this script we have seen exception mentioned above in numerous occasions not only in the ble-thread transport but also in ble-wifi transport as well. We are having doubts on the python controller not interacting efficiently with the Bluetooth hardware.

In few iterations the pairing works fine but if we encounter this exception during execution, the pairing fails constantly for a quite a large number like 5 to 10, or until the execution of the script is completed, sometimes the pairing starts to work again in the iterations after this exception is encountered. Logs are attached here for reference.

Reference log:
Example of Passed iteration details:
attached below are log and tcpdump files for one of the passed iterations i.e, iteration 4 .
Controller/TH: iteration_4_controller_log_2025-01-06_13-15-34.log
TCPDUMP: iteration_4_controller_tcpdump_2025-01-06_13-15-34.zip
attached below is the
DUT: Dut_log_iteration_4_2025-01-06T13_15_34_128839.log

Example of Failed iteration details:
attached below are log and tcpdump files for one of the Failed iterations i.e, iteration 5.
Controller/TH: iteration_5_controller_log_2025-01-06_13-18-18.log

TCPDUMP: iteration_5_controller_tcpdump_2025-01-06_13-18-18.zip
Note: the DUT logs are empty here as there was no interaction with the DUT
DUT:
Dut_log_5_2025-01-06T13_18_18_078854.log

Example of Passed iteration details:
attached below are log and tcpdump files for one of the passed iterations i.e, iteration 121.
Controller/TH: iteration_121_log_2025-01-06_14-27-17.log

TCPDUMP: iteration_121_controller_tcpdump_2025-01-06_14-27-17.zip

DUT: Dut_log_121_2025-01-06T14_27_17_431889.log

[Damian-Nordic]

@Harshith-GRL do you have full DUT logs? It seems for each iterations DUT logs are collected from the moment when a BLE connection has been established and in the failed iteration this never happens because DUT is not discovered over BLE. Hence we have no DUT logs to tell why it hasn't started BLE advertising. Would it be possible to collect logs from the boot start for each iteration?

[cjandhyala]

@Harshith-GRL can you pls provide DUT logs for this issue ?

[Harshith-GRL]

@cjandhyala the stress Test code is not capturing the code from where Damian is requesting, i believe we need to update the code and try to capture the logs we will raise an issue and capture the logs from where the DUt wil advertise and Also this issue i believe is being faced by another person and he also has raised issue #37963

[suhailab]

An issue has been logged in the matter-qa repository for tracking: #265.

Additionally, PR has been raised (#267), which is expected to be merged by the end of this week.

If the problem persists after the fix, we will share the relevant logs for further analysis.