project-chip / certification-tool

A test harness and tooling designed to simplify development, testing, and certification for devices, guided by the Connectivity Standards Alliance.
https://csa-iot.org/
Apache License 2.0
38 stars 23 forks source link

[Bug] Test harness hangs when python PICS guard skips steps (maybe the last step is skipped) #214

Open jamesharrow opened 7 months ago

jamesharrow commented 7 months ago

Describe the bug

In trying to fix a bug in TC_EEM_2_1.py which incorrectly tried to read attributes from DUT's that don't support the attribute, I added several if self.pics_guard(self.check_pics("EEM.S.A0001")): style checks to the test steps.

See main SDK repo PR: https://github.com/project-chip/connectedhomeip/pull/32464

This now seems hang the test harness at the end of the test case (although it passes)

Steps to reproduce the behavior

  1. git clone the connectedhomeip repo somewhere (could be on the PI, but I'm sure you have it on your laptop) - ultimately you need to scp the files on to the PI.

  2. cd connectedhomeip/

  3. git checkout master

  4. git pull

  5. git pull origin pull/32464/head <-- this is my PR with the newer version of the scripts (note the PR has not been approved or merged yet) [Somehow copy the contents of src/python_testing/*.py onto the PI somewhere] Then on the PI (with the test harness running):

  6. docker ps -a (to work out which is the backend container ID)

  7. docker cp src/python_testing/TC_EEM_2_1.py :/app/test_collections/matter/sdk_tests/sdk_checkout/python_testing/scripts/sdk/

  8. Stop the test harness (./scripts/stop.sh)

  9. Start the test harness (./scripts/start.sh)

  10. Change the PICS for EEM to disable some of the steps - e.g. using the test harness edit the project settings and add the JSON below. { "config": { "network": { "wifi": { "ssid": "testharness", "password": "wifi-password" }, "thread": { "rcp_serial_path": "/dev/ttyACM0", "rcp_baudrate": 115200, "on_mesh_prefix": "fd11:22::/64", "network_interface": "eth0", "dataset": { "channel": "15", "panid": "0x1234", "extpanid": "1111111122222222", "networkkey": "00112233445566778899aabbccddeeff", "networkname": "DEMO" }, "otbr_docker_image": null } }, "dut_config": { "discriminator": "3840", "setup_code": "20202021", "pairing_mode": "onnetwork", "chip_timeout": null, "chip_use_paa_certs": false, "trace_log": true }, "test_parameters": { "endpoint": 1 } }, "pics": { "clusters": { "Electrical Energy Measurement Cluster Test Plan": { "name": "Electrical Energy Measurement Cluster Test Plan", "items": { "EEM.S": { "number": "EEM.S", "enabled": true }, "EEM.S.A0000": { "number": "EEM.S.A0000", "enabled": true }, "EEM.S.A0001": { "number": "EEM.S.A0001", "enabled": true }, "EEM.S.A0002": { "number": "EEM.S.A0002", "enabled": false }, "EEM.S.A0003": { "number": "EEM.S.A0003", "enabled": false }, "EEM.S.A0004": { "number": "EEM.S.A0004", "enabled": false }, "EEM.S.A0005": { "number": "EEM.S.A0005", "enabled": true }, "EEM.S.E00": { "number": "EEM.S.E00", "enabled": true }, "EEM.S.E01": { "number": "EEM.S.E01", "enabled": false }, "EEM.S.F00": { "number": "EEM.S.F00", "enabled": true }, "EEM.S.F01": { "number": "EEM.S.F01", "enabled": false }, "EEM.S.F02": { "number": "EEM.S.F02", "enabled": true }, "EEM.S.F03": { "number": "EEM.S.F03", "enabled": false } } }, "Electrical Power Measurement Cluster Test Plan": { "name": "Electrical Power Measurement Cluster Test Plan", "items": { "EPM.S": { "number": "EPM.S", "enabled": true }, "EPM.S.A0000": { "number": "EPM.S.A0000", "enabled": true }, "EPM.S.A0001": { "number": "EPM.S.A0001", "enabled": true }, "EPM.S.A0002": { "number": "EPM.S.A0002", "enabled": true }, "EPM.S.A0003": { "number": "EPM.S.A0003", "enabled": true }, "EPM.S.A0004": { "number": "EPM.S.A0004", "enabled": true }, "EPM.S.A0005": { "number": "EPM.S.A0005", "enabled": true }, "EPM.S.A0006": { "number": "EPM.S.A0006", "enabled": false }, "EPM.S.A0007": { "number": "EPM.S.A0007", "enabled": false }, "EPM.S.A0008": { "number": "EPM.S.A0008", "enabled": true }, "EPM.S.A0009": { "number": "EPM.S.A0009", "enabled": false }, "EPM.S.A000a": { "number": "EPM.S.A000a", "enabled": false }, "EPM.S.A000b": { "number": "EPM.S.A000b", "enabled": false }, "EPM.S.A000c": { "number": "EPM.S.A000c", "enabled": false }, "EPM.S.A000d": { "number": "EPM.S.A000d", "enabled": false }, "EPM.S.A000e": { "number": "EPM.S.A000e", "enabled": false }, "EPM.S.A000f": { "number": "EPM.S.A000f", "enabled": false }, "EPM.S.A0010": { "number": "EPM.S.A0010", "enabled": false }, "EPM.S.A0011": { "number": "EPM.S.A0011", "enabled": false }, "EPM.S.A0012": { "number": "EPM.S.A0012", "enabled": false }, "EPM.S.E00": { "number": "EPM.S.E00", "enabled": false }, "EPM.S.F00": { "number": "EPM.S.F00", "enabled": false }, "EPM.S.F01": { "number": "EPM.S.F01", "enabled": true }, "EPM.S.F02": { "number": "EPM.S.F02", "enabled": false }, "EPM.S.F03": { "number": "EPM.S.F03", "enabled": false }, "EPM.S.F04": { "number": "EPM.S.F04", "enabled": false }, "EPM.M.PowerChange": { "number": "EPM.M.PowerChange", "enabled": false } } } } } }

  11. Click on Project and Goto Test Run

  12. Create a new test run to execute SDK Python Tests and select TC-EEM-2.1 image

  13. Using energy-management-app as an example put the DUT into commissioning mode

  14. Start the test run

  15. Select Make sure the DUT is in Commissioning Mode (Done)

The test case will skip some of the steps because EEM.S.A0002, A0003, A0004 are not enabled.

The test harness seems to get stuck forever at the end although the test case has passed.

image

The same test case can be run manually from within the docker container and seems to pass.

ubuntu@ubuntu:~/certification-tool$ export SHA=9f6d627e0262e1d023986291948bb4e845be803e
ubuntu@ubuntu:~/certification-tool$ docker run -v $PATH_TO_PAA_ROOTS:/paa_roots -v /var/run/dbus/system_bus_socket:/var/run/dbus/system_bus_socket -v /home/ubuntu/certification-tool/backend/test_collections/matter/sdk_tests/sdk_checkout/python_testing:/root/python_testing -v $(pwd):/launch_dir --privileged --network host -it connectedhomeip/chip-cert-bins:$SHA

Within the container:

root@ubuntu:~# export DISCRIMINATOR=3840
root@ubuntu:~# export SETUP_PASSCODE=20202021
root@ubuntu:~# rm -f admin_storage.json && python3 python_testing/scripts/sdk/TC_EEM_2_1.py --discriminator $DISCRIMINATOR --passcode $SETUP_PASSCODE --commissioning-method on-network --paa-trust-store-path /paa_roots --storage-path admin_storage.json --endpoint 1

The script seems to pass ok (steps are skipped since no PICS file was included every step was skipped):

[1709834670.973334][21:21] CHIP:CTL: Setting CSR nonce to random value
[1709834670.974966][21:21] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs
[1709834670.975292][21:21] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini
[1709834670.975706][21:21] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini
[1709834670.975931][21:21] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini
[1709834670.976583][21:21] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-t4csvx)
[1709834670.977236][21:21] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini)
[1709834670.977316][21:21] CHIP:DL: NVS set: chip-counters/reboot-count = 3 (0x3)
[1709834670.978333][21:21] CHIP:DL: Got Ethernet interface: eth0
[1709834670.978955][21:21] CHIP:DL: Found the primary Ethernet interface:eth0
[1709834670.979590][21:21] CHIP:DL: Got WiFi interface: wlan0
[1709834670.979667][21:21] CHIP:DL: Failed to reset WiFi statistic counts
Initializing persistent storage from file: admin_storage.json
ERROR:root:[Errno 2] No such file or directory: 'admin_storage.json'
CRITICAL:root:Could not load configuration from admin_storage.json - resetting configuration...
WARNING:root:No valid SDK configuration present - clearing out configuration
WARNING:root:No valid REPL configuration present - clearing out configuration
[1709834670.982120][21:21] CHIP:IN: UDP::Init bind&listen port=0
[1709834670.982300][21:21] CHIP:IN: UDP::Init bound to port=34113
[1709834670.982338][21:21] CHIP:IN: UDP::Init bind&listen port=0
[1709834670.982437][21:21] CHIP:IN: UDP::Init bound to port=37238
[1709834670.982460][21:21] CHIP:IN: BLEBase::Init - setting/overriding transport
[1709834670.982483][21:21] CHIP:IN: TransportMgr initialized
[1709834670.982571][21:21] CHIP:FP: Initializing FabricTable from persistent storage
[1709834670.982614][21:21] CHIP:CTL: StorageAdapter::GetKeyValue: Key = g/lkgt, Value = 0xffffeb39a360 (18)
[1709834670.982690][21:21] CHIP:CTL: Key Not Found

[1709834670.982756][21:21] CHIP:TS: Last Known Good Time: [unknown]
[1709834670.982784][21:21] CHIP:TS: Setting Last Known Good Time to firmware build time 2023-10-14T01:16:48
[1709834670.982829][21:21] CHIP:CTL: StorageAdapter::SetKeyValue: Key = g/lkgt, Value = 0xffffeb39a360 (8)
[1709834670.983741][21:21] CHIP:CTL: StorageAdapter::GetKeyValue: Key = g/fidx, Value = 0xffffeb39a548 (44)
[1709834670.983817][21:21] CHIP:CTL: Key Not Found

[1709834670.983855][21:21] CHIP:CTL: StorageAdapter::GetKeyValue: Key = g/fs/c, Value = 0xffffeb39a3f0 (36)
[1709834670.983885][21:21] CHIP:CTL: Key Not Found

[1709834670.984017][21:21] CHIP:CTL: StorageAdapter::GetKeyValue: Key = g/gcc, Value = 0xffffeb39a47c (4)
[1709834670.984057][21:21] CHIP:CTL: Key Not Found

[1709834670.984103][21:21] CHIP:CTL: StorageAdapter::GetKeyValue: Key = g/gdc, Value = 0xffffeb39a47c (4)
[1709834670.984132][21:21] CHIP:CTL: Key Not Found

[1709834670.984174][21:21] CHIP:CTL: StorageAdapter::SetKeyValue: Key = g/gcc, Value = 0xffffeb39a47c (4)
[1709834670.984527][21:21] CHIP:CTL: StorageAdapter::SetKeyValue: Key = g/gdc, Value = 0xffffeb39a47c (4)
[1709834670.984891][21:21] CHIP:ZCL: Using ZAP configuration...
[1709834670.988899][21:21] CHIP:DL: Avahi client registered
[1709834670.989044][21:21] CHIP:IN: CASE Server enabling CASE session setups
[1709834670.989197][21:21] CHIP:IN: SecureSession[0xaaab1131a330]: Allocated Type:2 LSID:26529
[1709834670.989290][21:21] CHIP:SC: Allocated SecureSession (0xaaab1131a330) - waiting for Sigma1 msg
[1709834670.989383][21:21] CHIP:CTL: System State Initialized...
[1709834670.989743][21:24] CHIP:DL: CHIP task running
[1709834670.990060][21:24] CHIP:DL: HandlePlatformSpecificBLEEvent 32786
WARNING:CertificateAuthorityManager:Loading certificate authorities from storage...
WARNING:matter.python_testing:Didn't find any CertificateAuthorities in storage -- creating a new CertificateAuthority + FabricAdmin...
WARNING:CertificateAuthority:New CertificateAuthority at index 1
WARNING:FabricAdmin:New FabricAdmin: FabricId: 0x0000000000000001, VendorId = 0xFFF1
WARNING:FabricAdmin:Allocating new controller with CaIndex: 1, FabricId: 0x0000000000000001, NodeId: 0x000000000001B669, CatTags: []
ERROR:chip.native.DL:Long dispatch time: 417 ms, for event type 2
[MatterTest] 03-07 18:04:31.627 INFO Starting test set, running 1 tests
[MatterTest] 03-07 18:04:31.632 INFO ==========> CommissionDeviceTest <==========
[MatterTest] 03-07 18:04:31.635 INFO [Test] test_run_commissioning
[MatterTest] 03-07 18:04:31.636 INFO Starting commissioning for root index 1, fabric ID 0x0000000000000001, node ID 0x0000000012344321
[MatterTest] 03-07 18:04:31.636 INFO Commissioning method: on-network
[MatterTest] 03-07 18:04:31.649 INFO Avahi browse: cache new
[MatterTest] 03-07 18:04:31.650 INFO Avahi browse: cache new
[MatterTest] 03-07 18:04:31.650 INFO Avahi browse: cache exhausted
[MatterTest] 03-07 18:04:32.611 INFO Avahi group established
[MatterTest] 03-07 18:04:32.625 INFO Avahi group established
[MatterTest] 03-07 18:04:32.650 INFO Avahi browse: all for now
[MatterTest] 03-07 18:04:32.654 INFO Avahi resolve found
[MatterTest] 03-07 18:04:32.657 INFO Discovered Device: fe80::e2ae:b2ff:fe06:c205:5540
[MatterTest] 03-07 18:04:32.658 INFO <<< [E:4626i S:0 M:46775033] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:20 (SecureChannel:PBKDFParamRequest)
[MatterTest] 03-07 18:04:32.659 INFO Setting attestation nonce to random value
[MatterTest] 03-07 18:04:32.660 INFO Setting CSR nonce to random value
[MatterTest] 03-07 18:04:32.660 INFO Commission called for node ID 0x0000000012344321
[MatterTest] 03-07 18:04:32.660 ERROR Unknown filter type; all matches will fail
[MatterTest] 03-07 18:04:32.662 INFO Avahi resolve found
[MatterTest] 03-07 18:04:32.665 INFO Discovered device does not have an open commissioning window.
[MatterTest] 03-07 18:04:32.681 INFO >>> [E:4626i S:0 M:218110981 (Ack:46775033)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse)
[MatterTest] 03-07 18:04:32.689 INFO <<< [E:4626i S:0 M:46775034 (Ack:218110981)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:22 (SecureChannel:PASE_Pake1)
[MatterTest] 03-07 18:04:32.775 INFO >>> [E:4626i S:0 M:218110982 (Ack:46775034)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2)
[MatterTest] 03-07 18:04:32.778 INFO <<< [E:4626i S:0 M:46775035 (Ack:218110982)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:24 (SecureChannel:PASE_Pake3)
[MatterTest] 03-07 18:04:32.799 INFO >>> [E:4626i S:0 M:218110983 (Ack:46775035)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[MatterTest] 03-07 18:04:32.800 INFO SecureSession[0xffffa800ff40, LSID:26530]: State change 'kEstablishing' --> 'kActive'
Established secure session with Device
[MatterTest] 03-07 18:04:32.801 INFO Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo'
[MatterTest] 03-07 18:04:32.802 INFO Performing next commissioning step 'ReadCommissioningInfo'
[MatterTest] 03-07 18:04:32.802 INFO Sending read request for commissioning information
[MatterTest] 03-07 18:04:32.804 INFO <<< [E:4627i S:26530 M:97687565] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0001:02 (IM:ReadRequest)
[MatterTest] 03-07 18:04:32.805 INFO <<< [E:4626i S:0 M:46775036 (Ack:218110983)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:33.161 INFO Received unknown unsecure packet for initiator 0xB6546F3BFBF06412
[MatterTest] 03-07 18:04:33.200 INFO Retransmitting MessageCounter:97687565 on exchange 4627i Send Cnt 1
[MatterTest] 03-07 18:04:33.224 INFO >>> [E:4627i S:26530 M:25967466 (Ack:97687565)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
[MatterTest] 03-07 18:04:33.241 INFO Successfully finished commissioning step 'ReadCommissioningInfo'
[MatterTest] 03-07 18:04:33.241 INFO Commissioning stage next step: 'ReadCommissioningInfo' -> 'ReadCommissioningInfo2'
[MatterTest] 03-07 18:04:33.242 INFO Performing next commissioning step 'ReadCommissioningInfo2'
[MatterTest] 03-07 18:04:33.243 INFO <<< [E:4628i S:26530 M:97687566] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0001:02 (IM:ReadRequest)
[MatterTest] 03-07 18:04:33.245 INFO <<< [E:4627i S:26530 M:97687567 (Ack:25967466)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:33.296 INFO >>> [E:4627i S:26530 M:25967467 (Ack:97687565)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:33.389 INFO >>> [E:4628i S:26530 M:25967468 (Ack:97687566)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData)
[MatterTest] 03-07 18:04:33.399 INFO ----- NetworkCommissioning Features: has Ethernet. endpointid = 0
[MatterTest] 03-07 18:04:33.399 INFO No matching fabric found
[MatterTest] 03-07 18:04:33.400 INFO Successfully finished commissioning step 'ReadCommissioningInfo2'
[MatterTest] 03-07 18:04:33.400 INFO Commissioning stage next step: 'ReadCommissioningInfo2' -> 'ArmFailSafe'
[MatterTest] 03-07 18:04:33.401 INFO Performing next commissioning step 'ArmFailSafe'
[MatterTest] 03-07 18:04:33.401 INFO Arming failsafe (60 seconds)
[MatterTest] 03-07 18:04:33.403 INFO <<< [E:4629i S:26530 M:97687568] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[MatterTest] 03-07 18:04:33.404 INFO <<< [E:4628i S:26530 M:97687569 (Ack:25967468)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:33.518 INFO >>> [E:4629i S:26530 M:25967469 (Ack:97687568)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[MatterTest] 03-07 18:04:33.523 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001
[MatterTest] 03-07 18:04:33.524 INFO Received ArmFailSafe response errorCode=0
[MatterTest] 03-07 18:04:33.524 INFO Successfully finished commissioning step 'ArmFailSafe'
[MatterTest] 03-07 18:04:33.525 INFO Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory'
[MatterTest] 03-07 18:04:33.525 INFO Performing next commissioning step 'ConfigRegulatory'
[MatterTest] 03-07 18:04:33.526 INFO Setting Regulatory Config
[MatterTest] 03-07 18:04:33.526 INFO No regulatory config supplied by controller, leaving as device default (0)
[MatterTest] 03-07 18:04:33.528 INFO <<< [E:4630i S:26530 M:97687570] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[MatterTest] 03-07 18:04:33.529 INFO <<< [E:4629i S:26530 M:97687571 (Ack:25967469)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:33.643 INFO >>> [E:4630i S:26530 M:25967470 (Ack:97687570)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[MatterTest] 03-07 18:04:33.648 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003
[MatterTest] 03-07 18:04:33.648 INFO Received SetRegulatoryConfig response errorCode=0
[MatterTest] 03-07 18:04:33.649 INFO Successfully finished commissioning step 'ConfigRegulatory'
[MatterTest] 03-07 18:04:33.649 INFO Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest'
[MatterTest] 03-07 18:04:33.650 INFO Performing next commissioning step 'SendPAICertificateRequest'
[MatterTest] 03-07 18:04:33.650 INFO Sending request for PAI certificate
[MatterTest] 03-07 18:04:33.652 INFO <<< [E:4631i S:26530 M:97687572] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[MatterTest] 03-07 18:04:33.654 INFO <<< [E:4630i S:26530 M:97687573 (Ack:25967470)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:33.666 INFO Avahi browse: cache new
[MatterTest] 03-07 18:04:33.667 INFO Avahi browse: cache new
[MatterTest] 03-07 18:04:33.668 INFO Avahi browse: cache exhausted
[MatterTest] 03-07 18:04:33.746 INFO >>> [E:4631i S:26530 M:25967471 (Ack:97687572)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[MatterTest] 03-07 18:04:33.751 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[MatterTest] 03-07 18:04:33.751 INFO Received certificate chain from the device
[MatterTest] 03-07 18:04:33.752 INFO Successfully finished commissioning step 'SendPAICertificateRequest'
[MatterTest] 03-07 18:04:33.752 INFO Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest'
[MatterTest] 03-07 18:04:33.753 INFO Performing next commissioning step 'SendDACCertificateRequest'
[MatterTest] 03-07 18:04:33.753 INFO Sending request for DAC certificate
[MatterTest] 03-07 18:04:33.755 INFO <<< [E:4632i S:26530 M:97687574] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[MatterTest] 03-07 18:04:33.757 INFO <<< [E:4631i S:26530 M:97687575 (Ack:25967471)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:33.836 INFO >>> [E:4632i S:26530 M:25967472 (Ack:97687574)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[MatterTest] 03-07 18:04:33.841 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003
[MatterTest] 03-07 18:04:33.842 INFO Received certificate chain from the device
[MatterTest] 03-07 18:04:33.842 INFO Successfully finished commissioning step 'SendDACCertificateRequest'
[MatterTest] 03-07 18:04:33.842 INFO Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest'
[MatterTest] 03-07 18:04:33.843 INFO Performing next commissioning step 'SendAttestationRequest'
[MatterTest] 03-07 18:04:33.844 INFO Sending Attestation Request to the device.
[MatterTest] 03-07 18:04:33.845 INFO <<< [E:4633i S:26530 M:97687576] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[MatterTest] 03-07 18:04:33.847 INFO <<< [E:4632i S:26530 M:97687577 (Ack:25967472)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:33.912 INFO >>> [E:4633i S:26530 M:25967473 (Ack:97687576)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:34.009 INFO >>> [E:4633i S:26530 M:25967474 (Ack:97687576)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[MatterTest] 03-07 18:04:34.015 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001
[MatterTest] 03-07 18:04:34.015 INFO Received Attestation Information from the device
[MatterTest] 03-07 18:04:34.016 INFO Successfully finished commissioning step 'SendAttestationRequest'
[MatterTest] 03-07 18:04:34.017 INFO Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification'
[MatterTest] 03-07 18:04:34.017 INFO Performing next commissioning step 'AttestationVerification'
[MatterTest] 03-07 18:04:34.018 INFO Verifying attestation
[MatterTest] 03-07 18:04:34.051 INFO Successfully validated 'Attestation Information' command received from the device.
[MatterTest] 03-07 18:04:34.052 INFO Successfully finished commissioning step 'AttestationVerification'
[MatterTest] 03-07 18:04:34.052 INFO Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest'
[MatterTest] 03-07 18:04:34.053 INFO Performing next commissioning step 'SendOpCertSigningRequest'
[MatterTest] 03-07 18:04:34.055 INFO <<< [E:4634i S:26530 M:97687578] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[MatterTest] 03-07 18:04:34.057 INFO <<< [E:4633i S:26530 M:97687579 (Ack:25967474)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:34.131 INFO >>> [E:4634i S:26530 M:25967475 (Ack:97687578)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:34.206 INFO >>> [E:4634i S:26530 M:25967476 (Ack:97687578)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[MatterTest] 03-07 18:04:34.211 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005
[MatterTest] 03-07 18:04:34.212 INFO Received certificate signing request from the device
[MatterTest] 03-07 18:04:34.212 INFO Successfully finished commissioning step 'SendOpCertSigningRequest'
[MatterTest] 03-07 18:04:34.213 INFO Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR'
[MatterTest] 03-07 18:04:34.213 INFO Performing next commissioning step 'ValidateCSR'
[MatterTest] 03-07 18:04:34.217 INFO Successfully finished commissioning step 'ValidateCSR'
[MatterTest] 03-07 18:04:34.218 INFO Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain'
[MatterTest] 03-07 18:04:34.218 INFO Performing next commissioning step 'GenerateNOCChain'
[MatterTest] 03-07 18:04:34.219 INFO Getting certificate chain for the device from the issuer
[MatterTest] 03-07 18:04:34.222 INFO Verifying Certificate Signing Request
[MatterTest] 03-07 18:04:34.225 INFO Generating NOC
[MatterTest] 03-07 18:04:34.226 INFO Providing certificate chain to the commissioner
[MatterTest] 03-07 18:04:34.227 INFO Received callback from the CA for NOC Chain generation. Status src/controller/ExampleOperationalCredentialsIssuer.cpp:395: Success
[MatterTest] 03-07 18:04:34.227 INFO Successfully finished commissioning step 'GenerateNOCChain'
[MatterTest] 03-07 18:04:34.228 INFO Performing next commissioning step 'SendTrustedRootCert'
[MatterTest] 03-07 18:04:34.228 INFO Sending root certificate to the device
[MatterTest] 03-07 18:04:34.230 INFO <<< [E:4635i S:26530 M:97687580] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[MatterTest] 03-07 18:04:34.231 INFO Sent root certificate to the device
[MatterTest] 03-07 18:04:34.233 INFO <<< [E:4634i S:26530 M:97687581 (Ack:25967476)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:34.321 INFO >>> [E:4635i S:26530 M:25967477 (Ack:97687580)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:34.384 INFO >>> [E:4635i S:26530 M:25967478 (Ack:97687580)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[MatterTest] 03-07 18:04:34.389 INFO Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0
[MatterTest] 03-07 18:04:34.389 INFO Device confirmed that it has received the root certificate
[MatterTest] 03-07 18:04:34.390 INFO Successfully finished commissioning step 'SendTrustedRootCert'
[MatterTest] 03-07 18:04:34.390 INFO Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC'
[MatterTest] 03-07 18:04:34.391 INFO Performing next commissioning step 'SendNOC'
[MatterTest] 03-07 18:04:34.393 INFO <<< [E:4636i S:26530 M:97687582] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[MatterTest] 03-07 18:04:34.394 INFO Sent operational certificate to the device
[MatterTest] 03-07 18:04:34.395 INFO <<< [E:4635i S:26530 M:97687583 (Ack:25967478)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:34.496 INFO >>> [E:4636i S:26530 M:25967479 (Ack:97687582)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:34.667 INFO Avahi browse: all for now
[MatterTest] 03-07 18:04:34.673 INFO Avahi resolve found
[MatterTest] 03-07 18:04:34.675 INFO Discovered device does not have an open commissioning window.
[MatterTest] 03-07 18:04:34.677 INFO Avahi resolve found
[MatterTest] 03-07 18:04:34.680 INFO Discovered device does not have an open commissioning window.
[MatterTest] 03-07 18:04:34.681 INFO Avahi resolve found
[MatterTest] 03-07 18:04:34.684 INFO Discovered device does not have an open commissioning window.
[MatterTest] 03-07 18:04:34.685 INFO Avahi resolve found
[MatterTest] 03-07 18:04:34.688 INFO Discovered device does not have an open commissioning window.
[MatterTest] 03-07 18:04:34.732 INFO >>> [E:4636i S:26530 M:25967480 (Ack:97687582)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[MatterTest] 03-07 18:04:34.737 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008
[MatterTest] 03-07 18:04:34.738 INFO Device returned status 0 on receiving the NOC
[MatterTest] 03-07 18:04:34.738 INFO Operational credentials provisioned on device 0xffffa805e700
[MatterTest] 03-07 18:04:34.739 INFO Secure Pairing Success
[MatterTest] 03-07 18:04:34.739 INFO Successfully finished commissioning step 'SendNOC'
[MatterTest] 03-07 18:04:34.739 INFO Commissioning stage next step: 'SendNOC' -> 'FindOperational'
[MatterTest] 03-07 18:04:34.740 INFO Performing next commissioning step 'FindOperational'
[MatterTest] 03-07 18:04:34.741 INFO Resolving 8A114705473352A3:0000000012344321 ...
[MatterTest] 03-07 18:04:34.743 INFO <<< [E:4636i S:26530 M:97687584 (Ack:25967480)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:34.745 INFO >>> [E:4635i S:26530 M:25967478 (Ack:97687580)] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse)
[MatterTest] 03-07 18:04:34.746 INFO <<< [E:4635i S:26530 M:97687585 (Ack:25967478)] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:34.747 INFO Avahi resolve found
[MatterTest] 03-07 18:04:34.748 INFO Node ID resolved for 8A114705473352A3:0000000012344321
[MatterTest] 03-07 18:04:34.750 INFO UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540: new best score: 7
[MatterTest] 03-07 18:04:34.750 INFO Checking node lookup status after 9 ms
[MatterTest] 03-07 18:04:34.750 INFO Keeping DNSSD lookup active
[MatterTest] 03-07 18:04:34.942 INFO Checking node lookup status after 201 ms
[MatterTest] 03-07 18:04:34.943 INFO Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000012344321
[MatterTest] 03-07 18:04:34.946 INFO <<< [E:4637i S:0 M:46775037] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1)
[MatterTest] 03-07 18:04:34.947 INFO Sent Sigma1 msg
[MatterTest] 03-07 18:04:35.020 INFO >>> [E:4637i S:0 M:218110984 (Ack:46775037)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2)
[MatterTest] 03-07 18:04:35.021 INFO Received Sigma2 msg
[MatterTest] 03-07 18:04:35.029 INFO <<< [E:4637i S:0 M:46775038 (Ack:218110984)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3)
[MatterTest] 03-07 18:04:35.029 INFO Sent Sigma3 msg
[MatterTest] 03-07 18:04:35.201 INFO >>> [E:4637i S:0 M:218110985 (Ack:46775038)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport)
[MatterTest] 03-07 18:04:35.202 INFO Success status report received. Session was established
[MatterTest] 03-07 18:04:35.203 INFO SetSdkKey: f/1/s/0000000012344321 = b'\x150\x03\x10K\x01<\xe5IUC\xcc\xbc\x7f\xc5W\x0c\xb0\xed\xb40\x04 \xb8\xd9\xc0\xa6\xe0\xeb\xf3i\xfe#\x8a\xb5\xdc\xadn\r\x892Q\xe1\x8ei\xb5\xdfl\xedR!\xbd\xdf\xaaC0\x05\x0c\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x18'
[MatterTest] 03-07 18:04:35.203 INFO Committing...
[MatterTest] 03-07 18:04:35.205 INFO SetSdkKey: g/s/SwE85UlVQ8y8f8VXDLDttA== = b'\x15$\x01\x01&\x02!C4\x12\x18'
[MatterTest] 03-07 18:04:35.205 INFO Committing...
[MatterTest] 03-07 18:04:35.206 INFO SetSdkKey: g/sri = b'\x16\x15$\x01\x01&\x02!C4\x12\x18\x18'
[MatterTest] 03-07 18:04:35.206 INFO Committing...
[MatterTest] 03-07 18:04:35.207 INFO SecureSession[0xffffa80078d0, LSID:26531]: State change 'kEstablishing' --> 'kActive'
[MatterTest] 03-07 18:04:35.209 INFO Successfully finished commissioning step 'FindOperational'
[MatterTest] 03-07 18:04:35.209 INFO Commissioning stage next step: 'FindOperational' -> 'SendComplete'
[MatterTest] 03-07 18:04:35.209 INFO Performing next commissioning step 'SendComplete'
[MatterTest] 03-07 18:04:35.211 INFO <<< [E:4638i S:26531 M:83024463] (S) Msg TX to 1:0000000012344321 [52A3] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[MatterTest] 03-07 18:04:35.212 INFO <<< [E:4637i S:0 M:46775039 (Ack:218110985)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:35.371 INFO >>> [E:4638i S:26531 M:94042381 (Ack:83024463)] (S) Msg RX from 1:0000000012344321 [52A3] --- Type 0001:09 (IM:InvokeCommandResponse)
[MatterTest] 03-07 18:04:35.376 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005
[MatterTest] 03-07 18:04:35.377 INFO Received CommissioningComplete response, errorCode=0
[MatterTest] 03-07 18:04:35.377 INFO Successfully finished commissioning step 'SendComplete'
[MatterTest] 03-07 18:04:35.377 INFO Commissioning stage next step: 'SendComplete' -> 'Cleanup'
[MatterTest] 03-07 18:04:35.378 INFO Performing next commissioning step 'Cleanup'
[MatterTest] 03-07 18:04:35.379 INFO SecureSession[0xffffa800ff40, LSID:26530]: State change 'kActive' --> 'kPendingEviction'
[MatterTest] 03-07 18:04:35.379 INFO Successfully finished commissioning step 'Cleanup'
Commissioning complete
[MatterTest] 03-07 18:04:35.382 INFO <<< [E:4638i S:26531 M:83024464 (Ack:94042381)] (S) Msg TX to 1:0000000012344321 [52A3] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:35.382 INFO [Test] test_run_commissioning PASS
[MatterTest] 03-07 18:04:35.388 INFO Summary for test class CommissionDeviceTest: Error 0, Executed 1, Failed 0, Passed 1, Requested 1, Skipped 0
[MatterTest] 03-07 18:04:35.392 INFO ==========> TC_EEM_2_1 <==========
[MatterTest] 03-07 18:04:35.394 INFO [Test] test_TC_EEM_2_1
[MatterTest] 03-07 18:04:35.395 INFO Starting test from /root/python_testing/scripts/sdk/TC_EEM_2_1.py: 5.1.2. [TC-EEM-2.1] Attributes with Server as DUT - 7 steps
[MatterTest] 03-07 18:04:35.397 INFO        ***** Test Step 1 : Commissioning, already done
[MatterTest] 03-07 18:04:35.397 INFO        ***** Test Step 2 : TH reads Accuracy attribute. Verify that the DUT response contains a MeasurementAccuracyStruct value.
[MatterTest] 03-07 18:04:35.399 INFO Found an existing secure session to [1:0000000012344321]!
[MatterTest] 03-07 18:04:35.401 INFO <<< [E:4639i S:26531 M:83024465] (S) Msg TX to 1:0000000012344321 [52A3] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0001:02 (IM:ReadRequest)
[MatterTest] 03-07 18:04:35.693 INFO Received unknown unsecure packet for initiator 0xC8562DB4612AF4DD
[MatterTest] 03-07 18:04:35.788 INFO Retransmitting MessageCounter:83024465 on exchange 4639i Send Cnt 1
[MatterTest] 03-07 18:04:35.789 INFO >>> [E:4639i S:26531 M:94042382 (Ack:83024465)] (S) Msg RX from 1:0000000012344321 [52A3] --- Type 0001:05 (IM:ReportData)
[MatterTest] 03-07 18:04:35.801 INFO <<< [E:4639i S:26531 M:83024466 (Ack:94042382)] (S) Msg TX to 1:0000000012344321 [52A3] [UDP:[fe80::e2ae:b2ff:fe06:c205%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck)
[MatterTest] 03-07 18:04:35.801 INFO Rx'd Accuracy: ElectricalEnergyMeasurement.Structs.MeasurementAccuracyStruct(measurementType=<MeasurementTypeEnum.kElectricalEnergy: 14>, measured=True, minMeasuredValue=0, maxMeasuredValue=1000000000000000, accuracyRanges=[ElectricalEnergyMeasurement.Structs.MeasurementAccuracyRangeStruct(rangeMin=150333132148, rangeMax=-4294967296, percentMax=0, percentMin=141, percentTypical=0, fixedMax=150333132148, fixedMin=None, fixedTypical=21)])
[MatterTest] 03-07 18:04:35.803 INFO        ***** Test Step 3 : TH reads CumulativeEnergyImported attribute. Verify that the DUT response contains either null or an EnergyMeasurementStruct value.
[MatterTest] 03-07 18:04:35.803 INFO        **** Skipping: 3
[MatterTest] 03-07 18:04:35.804 INFO        ***** Test Step 4 : TH reads CumulativeEnergyExported attribute. Verify that the DUT response contains either null or an EnergyMeasurementStruct value.
[MatterTest] 03-07 18:04:35.804 INFO        **** Skipping: 4
[MatterTest] 03-07 18:04:35.805 INFO        ***** Test Step 5 : TH reads PeriodicEnergyImported attribute. Verify that the DUT response contains either null or an EnergyMeasurementStruct value.
[MatterTest] 03-07 18:04:35.805 INFO        **** Skipping: 5
[MatterTest] 03-07 18:04:35.806 INFO        ***** Test Step 6 : TH reads PeriodicEnergyExported attribute. Verify that the DUT response contains either null or an EnergyMeasurementStruct value.
[MatterTest] 03-07 18:04:35.806 INFO        **** Skipping: 6
[MatterTest] 03-07 18:04:35.806 INFO        ***** Test Step 7 : TH reads CumulativeEnergyReset attribute. Verify that the DUT response contains either null or an CumulativeEnergyResetStruct value.
[MatterTest] 03-07 18:04:35.807 INFO        **** Skipping: 7
[MatterTest] 03-07 18:04:35.809 INFO Finished test in 414ms
[MatterTest] 03-07 18:04:35.809 INFO [Test] test_TC_EEM_2_1 PASS
[MatterTest] 03-07 18:04:35.813 INFO Summary for test class TC_EEM_2_1: Error 0, Executed 1, Failed 0, Passed 1, Requested 1, Skipped 0
[MatterTest] 03-07 18:04:35.816 INFO Summary for test run MatterTest@03-07-2024_18-04-31-625:
Total time elapsed 4.188163943000291s
Artifacts are saved in "/tmp/matter_testing/logs/MatterTest/03-07-2024_18-04-31-625"
Test summary saved in "/tmp/matter_testing/logs/MatterTest/03-07-2024_18-04-31-625/test_summary.yaml"
Test results: Error 0, Executed 2, Failed 0, Passed 2, Requested 2, Skipped 0
INFO:root:Finished test set, ran for 4189174.0ms
DEBUG:chip.native.CTL:Shutting down the commissioner
DEBUG:chip.native.CTL:Shutting down the controller
DEBUG:chip.native.IN:Expiring all sessions for fabric 0x1!!
DEBUG:chip.native.IN:SecureSession[0xffffa80078d0]: MarkForEviction Type:2 LSID:26531
INFO:chip.native.SC:SecureSession[0xffffa80078d0, LSID:26531]: State change 'kActive' --> 'kPendingEviction'
DEBUG:chip.native.IN:SecureSession[0xffffa80078d0]: Released - Type:2 LSID:26531
INFO:chip.native.FP:Forgetting fabric 0x1
INFO:chip.native.TS:Pending Last Known Good Time: 2023-10-14T01:16:48
DEBUG:chip.native.CTL:StorageAdapter::GetKeyValue: Key = g/lkgt, Value = 0xffffb0e7d820 (18)
DEBUG:chip.native.CTL:Key Found 8

INFO:chip.native.TS:Previous Last Known Good Time: 2023-10-14T01:16:48
INFO:chip.native.TS:Reverted Last Known Good Time to previous value
ERROR:chip.native.CTL:Shutting down the stack...
DEBUG:chip.native.CTL:Shutting down the System State, this will teardown the CHIP Stack
DEBUG:chip.native.IN:SecureSession[0xaaab1131a330]: Released - Type:2 LSID:26529
DEBUG:chip.native.DMG:All ReadHandler-s are clean, clear GlobalDirtySet
INFO:chip.native.FP:Shutting down FabricTable
INFO:chip.native.TS:Pending Last Known Good Time: 2023-10-14T01:16:48
DEBUG:chip.native.CTL:StorageAdapter::GetKeyValue: Key = g/lkgt, Value = 0xffffeb39afa0 (18)
DEBUG:chip.native.CTL:Key Found 8

INFO:chip.native.TS:Previous Last Known Good Time: 2023-10-14T01:16:48
INFO:chip.native.TS:Reverted Last Known Good Time to previous value
INFO:chip.native.DL:writing settings to file (/tmp/chip_counters.ini-G9xbx1)
INFO:chip.native.DL:renamed tmp file to file (/tmp/chip_counters.ini)
INFO:chip.native.DL:NVS set: chip-counters/total-operational-hours = 0 (0x0)
ERROR:chip.native.DL:Inet Layer shutdown
ERROR:chip.native.DL:BLE shutdown
ERROR:chip.native.DL:System Layer shutdown
INFO:root:Final result: PASS !

Expected behavior

The test harness should mark the test as passed and allow the results to be uploaded.

Log files

Cannot attach the full logs from the test harness because it only copies a screenful of text into the clipboard. Since the download and save logs buttons are disabled in this state:

image

This is the very end of the log:

<html>
<body>
<!--StartFragment-->
[MatterTest] 03-07 20:03:25.547 INFO "sessionId" : 61621
--
[MatterTest] 03-07 20:03:25.548 INFO },
[MatterTest] 03-07 20:03:25.549 INFO Summary for test class TC_EEM_2_1: Error 0, Executed 1, Failed 0, Passed 1, Requested 1, Skipped 0
[MatterTest] 03-07 20:03:25.550 INFO "payload" :
[MatterTest] 03-07 20:03:25.551 INFO {
[MatterTest] 03-07 20:03:25.554 INFO Summary for test run MatterTest@03-07-2024_20-03-24-444:
Total time elapsed 1.0576781820000178s
Artifacts are saved in "/tmp/matter_testing/logs/MatterTest/03-07-2024_20-03-24-444"
Test summary saved in "/tmp/matter_testing/logs/MatterTest/03-07-2024_20-03-24-444/test_summary.yaml"
Test results: Error 0, Executed 1, Failed 0, Passed 1, Requested 1, Skipped 0
[MatterTest] 03-07 20:03:25.555 INFO "decoded" :
---- End of Python test logs ----
Test Step Completed [PASSED]: TH reads PeriodicEnergyImported attribute. Verify that the DUT response contains either null or an EnergyMeasurementStruct value.
Test Cleanup
Test Case Completed[PENDING]: TC-EEM-2.1
Suite Cleanup
Stopping SDK container
Test Suite Completed [PENDING]: Python Testing Suite
Test Run Completed [PENDING]

<!--EndFragment-->
</body>
</html>

PICS file

PICS_for_THIssue.zip

Screenshots

No response

Environment

Additional Information

No response

rquidute commented 6 months ago

Hi @jamesharrow, there is an update in the release branch. Could you check if the changes works for you? Could you please follow the steps bellow in order to update the release branch and test again?

jamesharrow commented 6 months ago

I have upgrade the PI using the instructions above - and I didn't touch the patched TC_EPM_2_1.py test script I had on there.

It seems better (it doesn't hang) but gets an error trying to look at the test_output.txt: image

Test Step Error: Error occurred during execution of test case TC_EEM_2_1. [Errno 2] No such file or directory: '/app/backend/test_collections/matter/sdk_tests/sdk_checkout/python_testing/test_output.txt'

rquidute commented 6 months ago

Hi @jamesharrow, There is a new fix, could you please follow the steps bellow again?

./scripts/stop.sh cd certification-tool git fetch git checkout v2.10-beta3+spring2024 git submodule update --init --recursive ./scripts/start.sh

jamesharrow commented 6 months ago

Ok - tried again - some very slight improvement - the green "Success" banner popped up for a few seconds but it is still recording the error with missing test_output.txt and a red X at the end.

image

UI_Test_Run_issue_2024_03_14_22_27_34.log UI_Test_Run_issue_2024_03_14_22_27_34-54.json

rquidute commented 6 months ago

Hi @jamesharrow that's odd. I performed the test in my setup and it worked.

Could you share the output for this command:cat /home/ubuntu/certification-tool/backend/test_collections/matter/sdk_tests/support/python_testing/models/test_case.py

Maybe in the proposed steps, the git pull is missing, so one more time, could you try again with the steps bellow: ./scripts/stop.sh cd certification-tool git fetch git checkout v2.10-beta3+spring2024 git pull git submodule update --init --recursive ./scripts/start.sh

Screenshot 2024-03-14 at 19 48 10

hiltonlima commented 3 months ago

Hello, @jamesharrow . Thanks for the feedback. Looking at the log I noticed that you are using an old version of TH. Could you update to version v2.10+spring2024 and check if the problem still occurs?