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.18k stars 1.9k forks source link

[Pairing Reliability] #5 : Failed to commission: src/controller/CHIPDeviceController.cpp:2696: CHIP Error 0x000000AC: Internal error #34061

Open Saravana-kr22 opened 1 week ago

Saravana-kr22 commented 1 week ago

Description: I have used python controller to run a stress test on my RPI sample dut (all-clusters-app) on Pair-Unpair test scenario for 10,000 iterations. The test passed in iteration 5 without any error but the iteration 6 is Failed to commission the dut during the WiFiNetworkEnable step with the below error

2024-06-24 06:20:40,185 - chip.native.CTL - ERROR - init.py:_RedirectToPythonLogging:39 - Error on commissioning step 'WiFiNetworkEnable': 'src/controller/CHIPDeviceController.cpp:2696: CHIP Error 0x000000AC: Internal error' 2024-06-24 06:20:40,185 - chip.native.CTL - INFO - init.py:_RedirectToPythonLogging:41 - Going from commissioning step 'WiFiNetworkEnable' with lastErr = 'src/controller/CHIPDeviceController.cpp:2696: CHIP Error 0x000000AC: Internal error' -> 'Cleanup'

GitHub hash of the SDK that was being used: https://github.com/project-chip/connectedhomeip/commit/c829a2cb6b3e60f9075146130fcb92d1529b24b3

Platform controller - python controller running on mac, DUT - all-cluster-app running on raspi Provisioned using ble-wifi

Platform Version(s) RPI-4, 8GB RAM

Test Scenario

Pair/Provision the DUT (All-cluster-app running on raspi) using on-network Read device information after the device is provisioned sleep for 2 secs Unpair the DUT (i.e. removing the fabric) factory reset the DUT repeat step1 - 6 for 10,000 iterations Script reference: https://github.com/CHIP-Specifications/matter-qa/blob/main/src/matter_qa/scripts/reliability_scripts/TC_Pair.py

Reference log: Example of Passed iteration details:

The iteration number 5 is passed, below log files for the same TH log: log_2024-06-24_06-18-55.log DUT log: Dut_log_5_2024-06-24T06_19_35_060866.log TCP_DUMP: controller_tcpdump_2024-06-24_06-18-55.zip

Example of Failed iteration details:

The iteration number 6 is failed with this error below the log file TH log: log_2024-06-24_06-19-51.log DUT log: Dut_log_6_2024-06-24T06_20_40_340852.log TCP_DUMP: controller_tcpdump_2024-06-24_06-19-51.zip

bzbarsky-apple commented 1 week ago

The relevant bit from the TH log:

2024-06-24 06:20:40,180 - chip.native.DMG - DEBUG - __init__.py:_RedirectToPythonLogging:43 - InvokeResponseMessage =
...
                CommandPathIB =
2024-06-24 06:20:40,182 - chip.native.DMG - DEBUG - __init__.py:_RedirectToPythonLogging:43 -               {
2024-06-24 06:20:40,182 - chip.native.DMG - DEBUG - __init__.py:_RedirectToPythonLogging:43 -                   EndpointId = 0x0,
2024-06-24 06:20:40,182 - chip.native.DMG - DEBUG - __init__.py:_RedirectToPythonLogging:43 -                   ClusterId = 0x31,
2024-06-24 06:20:40,182 - chip.native.DMG - DEBUG - __init__.py:_RedirectToPythonLogging:43 -                   CommandId = 0x7,
...
                CommandFields = 
2024-06-24 06:20:40,183 - chip.native.DMG - DEBUG - __init__.py:_RedirectToPythonLogging:43 -               {
2024-06-24 06:20:40,183 - chip.native.DMG - DEBUG - __init__.py:_RedirectToPythonLogging:43 -                   0x0 = 12 (unsigned), 
2024-06-24 06:20:40,183 - chip.native.DMG - DEBUG - __init__.py:_RedirectToPythonLogging:43 -                   0x2 = -3 (signed), 
2024-06-24 06:20:40,183 - chip.native.DMG - DEBUG - __init__.py:_RedirectToPythonLogging:43 -               },

That is a ConnectNetworkResponse and the payload is { NetworkingStatus: UnknownError, ErrorValue: -3 }.

From the DUT log:

[1719235227.307305][3223:3223] CHIP:NP: LinuxWiFiDriver: ConnectNetwork 'Partyguys'
...
[1719235240.159935][3223:3224] CHIP:DL: wpa_supplicant:PropertiesChanged:key:DisconnectReason -> -3
[1719235240.163315][3223:3224] CHIP:DL: wpa_supplicant:PropertiesChanged:key:State -> 'disconnected'

I think "-3" for wpa_supplicant is:

reason=3 "Deauthenticated because sending STA is leaving (or has left) the BSS"

but I could be wrong. In either case, the issue is that the DUT was not able to join the wifi network.