search

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
28 stars 15 forks source link

[Bug] TC-IDM-10.4 need check PulsewidthModulation in level control cluster, but can not found in xml. #309

Closed ZeddChen closed 2 weeks ago

ZeddChen commented 3 weeks ago

Describe the bug

PulsewidthModulation is a provisional cluster, and not have any PICS item. I don't think it's necessary to check this cluster.

Steps to reproduce the behavior

No response

Expected behavior

No response

Log files

root@ubuntu:~# python3 python_testing/scripts/sdk/TC_pics_checker.py --discriminator 300 --passcode 96097820 --commissioning-method ble-wifi --wifi-ssid dekra --wifi-passphrase dekra2019 --paa-trust-store-path /credentials/development/paa-root-certs/ --storage-path admin_storage.json --PICS /credentials/ci-pics-lighting_EP1.txt --endpoint 1 [1720495532.070759][70:70] CHIP:CTL: Setting attestation nonce to random value [1720495532.073336][70:70] CHIP:CTL: Setting CSR nonce to random value [1720495532.075015][70:70] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_kvs [1720495532.075352][70:70] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_factory.ini [1720495532.075785][70:70] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_config.ini [1720495532.076043][70:70] CHIP:DL: ChipLinuxStorage::Init: Using KVS config file: /tmp/chip_counters.ini [1720495532.076752][70:70] CHIP:DL: writing settings to file (/tmp/chip_counters.ini-eFYuBj) [1720495532.077488][70:70] CHIP:DL: renamed tmp file to file (/tmp/chip_counters.ini) [1720495532.077574][70:70] CHIP:DL: NVS set: chip-counters/reboot-count = 3 (0x3) [1720495532.078696][70:70] CHIP:DL: Got Ethernet interface: eth0 [1720495532.079310][70:70] CHIP:DL: Found the primary Ethernet interface:eth0 [1720495532.080030][70:70] CHIP:DL: Got WiFi interface: wlan0 [1720495532.080116][70:70] CHIP:DL: Failed to reset WiFi statistic counts Initializing persistent storage from file: admin_storage.json Loading configuration from admin_storage.json... [1720495532.082769][70:70] CHIP:IN: UDP::Init bind&listen port=0 [1720495532.082953][70:70] CHIP:IN: UDP::Init bound to port=43525 [1720495532.082992][70:70] CHIP:IN: UDP::Init bind&listen port=0 [1720495532.083094][70:70] CHIP:IN: UDP::Init bound to port=52953 [1720495532.083118][70:70] CHIP:IN: BLEBase::Init - setting/overriding transport [1720495532.083140][70:70] CHIP:IN: TransportMgr initialized [1720495532.083250][70:70] CHIP:FP: Initializing FabricTable from persistent storage [1720495532.083293][70:70] CHIP:CTL: StorageAdapter::GetKeyValue: Key = g/lkgt, Value = 0xffffea4facd0 (18) [1720495532.083414][70:70] CHIP:CTL: Key Found 8

[1720495532.083510][70:70] CHIP:TS: Last Known Good Time: 2023-10-14T01:16:48 [1720495532.083552][70:70] CHIP:CTL: StorageAdapter::GetKeyValue: Key = g/fidx, Value = 0xffffea4faeb8 (44) [1720495532.083618][70:70] CHIP:CTL: Key Found 10

[1720495532.083686][70:70] CHIP:CTL: StorageAdapter::GetKeyValue: Key = f/1/n, Value = 0xffffea4fa9b8 (400) [1720495532.083819][70:70] CHIP:CTL: Key Found 244

[1720495532.083857][70:70] CHIP:CTL: StorageAdapter::GetKeyValue: Key = f/1/r, Value = 0xffffea4fab48 (400) [1720495532.083965][70:70] CHIP:CTL: Key Found 231

[1720495532.084969][70:70] CHIP:CTL: StorageAdapter::GetKeyValue: Key = f/1/m, Value = 0xffffea4fa878 (44) [1720495532.085114][70:70] CHIP:CTL: Key Found 9

[1720495532.085215][70:70] CHIP:FP: Fabric index 0x1 was retrieved from storage. Compressed FabricId 0x5D422CAC62E2779C, FabricId 0x0000000000000001, NodeId 0x000000000001B669, VendorId 0xFFF1 [1720495532.085251][70:70] CHIP:CTL: StorageAdapter::GetKeyValue: Key = g/fs/c, Value = 0xffffea4fad60 (36) [1720495532.085291][70:70] CHIP:CTL: Key Not Found

[1720495532.085418][70:70] CHIP:CTL: StorageAdapter::GetKeyValue: Key = g/gcc, Value = 0xffffea4fadec (4) [1720495532.085491][70:70] CHIP:CTL: Key Found 4

[1720495532.085521][70:70] CHIP:CTL: StorageAdapter::GetKeyValue: Key = g/gdc, Value = 0xffffea4fadec (4) [1720495532.085566][70:70] CHIP:CTL: Key Found 4

[1720495532.085595][70:70] CHIP:CTL: StorageAdapter::SetKeyValue: Key = g/gcc, Value = 0xffffea4fadec (4) [1720495532.086624][70:70] CHIP:CTL: StorageAdapter::SetKeyValue: Key = g/gdc, Value = 0xffffea4fadec (4) [1720495532.087263][70:70] CHIP:ZCL: Using ZAP configuration... [1720495532.091035][70:70] CHIP:DL: Avahi client registered [1720495532.091176][70:70] CHIP:IN: CASE Server enabling CASE session setups [1720495532.091312][70:70] CHIP:IN: SecureSession[0xaaab0750cc40]: Allocated Type:2 LSID:26568 [1720495532.091380][70:70] CHIP:SC: Allocated SecureSession (0xaaab0750cc40) - waiting for Sigma1 msg [1720495532.091467][70:70] CHIP:CTL: System State Initialized... [1720495532.091796][70:73] CHIP:DL: CHIP task running [1720495532.092120][70:73] CHIP:DL: HandlePlatformSpecificBLEEvent 32786 Loading certificate authorities from storage... New CertificateAuthority at index 1 Loading fabric admins from storage... New FabricAdmin: FabricId: 0x0000000000000001, VendorId = 0xFFF1 Allocating new controller with CaIndex: 1, FabricId: 0x0000000000000001, NodeId: 0x000000000001B669, CatTags: [] Long dispatch time: 441 ms, for event type 2 [MatterTest] 07-09 03:25:32.756 INFO Starting test set, running 1 tests [MatterTest] 07-09 03:25:32.770 INFO ==========> CommissionDeviceTest <========== [MatterTest] 07-09 03:25:32.773 INFO [Test] test_run_commissioning [MatterTest] 07-09 03:25:32.774 INFO Starting commissioning for root index 1, fabric ID 0x0000000000000001, node ID 0x0000000012344321 [MatterTest] 07-09 03:25:32.774 INFO Commissioning method: ble-wifi [MatterTest] 07-09 03:25:32.775 INFO Setting wifi credentials from parameters [MatterTest] 07-09 03:25:32.776 INFO Setting attestation nonce to random value [MatterTest] 07-09 03:25:32.776 INFO Setting CSR nonce to random value [MatterTest] 07-09 03:25:32.777 INFO Commission called for node ID 0x0000000012344321 [MatterTest] 07-09 03:25:32.794 INFO BLE removing known devices. [MatterTest] 07-09 03:25:32.801 INFO BLE initiating scan. [MatterTest] 07-09 03:25:32.833 INFO New device scanned: E3:53:42:96:1B:70 [MatterTest] 07-09 03:25:32.834 INFO Device discriminator match. Attempting to connect. [MatterTest] 07-09 03:25:33.200 INFO New device connected: E3:53:42:96:1B:70 [MatterTest] 07-09 03:25:33.710 INFO Avahi group established [MatterTest] 07-09 03:25:33.725 INFO Avahi group established [MatterTest] 07-09 03:25:35.458 INFO Closing all BLE connections [MatterTest] 07-09 03:25:35.461 INFO <<< [E:19541i S:0 M:100148207] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:20 (SecureChannel:PBKDFParamRequest) [MatterTest] 07-09 03:25:35.880 INFO subscribe complete, ep = 0xffff91623dc0 [MatterTest] 07-09 03:25:35.883 INFO peripheral chose BTP version 4; central expected between 4 and 4 [MatterTest] 07-09 03:25:35.884 INFO using BTP fragment sizes rx 244 / tx 244. [MatterTest] 07-09 03:25:35.884 INFO local and remote recv window size = 5 [MatterTest] 07-09 03:25:36.222 INFO >>> [E:19541i S:0 M:127557633] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:21 (SecureChannel:PBKDFParamResponse) [MatterTest] 07-09 03:25:36.247 INFO <<< [E:19541i S:0 M:100148208] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:22 (SecureChannel:PASE_Pake1) [MatterTest] 07-09 03:25:37.393 INFO >>> [E:19541i S:0 M:127557634] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:23 (SecureChannel:PASE_Pake2) [MatterTest] 07-09 03:25:37.398 INFO <<< [E:19541i S:0 M:100148209] (U) Msg TX to 0:0000000000000000 [0000] [BLE] --- Type 0000:24 (SecureChannel:PASE_Pake3) [MatterTest] 07-09 03:25:37.539 INFO >>> [E:19541i S:0 M:127557635] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [MatterTest] 07-09 03:25:37.541 INFO SecureSession[0xffff7c0208f0, LSID:26569]: State change 'kEstablishing' --> 'kActive' Established secure session with Device [MatterTest] 07-09 03:25:37.543 INFO Commissioning stage next step: 'SecurePairing' -> 'ReadCommissioningInfo' [MatterTest] 07-09 03:25:37.544 INFO Performing next commissioning step 'ReadCommissioningInfo' [MatterTest] 07-09 03:25:37.545 INFO Sending read request for commissioning information [MatterTest] 07-09 03:25:37.547 INFO <<< [E:19542i S:26569 M:170360024] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest) [MatterTest] 07-09 03:25:37.978 INFO >>> [E:19542i S:26569 M:158016237] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [MatterTest] 07-09 03:25:38.006 INFO Successfully finished commissioning step 'ReadCommissioningInfo' [MatterTest] 07-09 03:25:38.006 INFO Commissioning stage next step: 'ReadCommissioningInfo' -> 'ReadCommissioningInfo2' [MatterTest] 07-09 03:25:38.007 INFO Performing next commissioning step 'ReadCommissioningInfo2' [MatterTest] 07-09 03:25:38.008 INFO <<< [E:19543i S:26569 M:170360025] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:02 (IM:ReadRequest) [MatterTest] 07-09 03:25:38.171 INFO >>> [E:19543i S:26569 M:158016238] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:05 (IM:ReportData) [MatterTest] 07-09 03:25:38.185 INFO ----- NetworkCommissioning Features: has WiFi. endpointid = 0 [MatterTest] 07-09 03:25:38.186 INFO No matching fabric found [MatterTest] 07-09 03:25:38.186 INFO Successfully finished commissioning step 'ReadCommissioningInfo2' [MatterTest] 07-09 03:25:38.187 INFO Commissioning stage next step: 'ReadCommissioningInfo2' -> 'ArmFailSafe' [MatterTest] 07-09 03:25:38.188 INFO Performing next commissioning step 'ArmFailSafe' [MatterTest] 07-09 03:25:38.188 INFO Arming failsafe (60 seconds) [MatterTest] 07-09 03:25:38.190 INFO <<< [E:19544i S:26569 M:170360026] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [MatterTest] 07-09 03:25:38.272 INFO >>> [E:19544i S:26569 M:158016239] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [MatterTest] 07-09 03:25:38.280 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [MatterTest] 07-09 03:25:38.281 INFO Received ArmFailSafe response errorCode=0 [MatterTest] 07-09 03:25:38.281 INFO Successfully finished commissioning step 'ArmFailSafe' [MatterTest] 07-09 03:25:38.282 INFO Commissioning stage next step: 'ArmFailSafe' -> 'ConfigRegulatory' [MatterTest] 07-09 03:25:38.282 INFO Performing next commissioning step 'ConfigRegulatory' [MatterTest] 07-09 03:25:38.283 INFO Setting Regulatory Config [MatterTest] 07-09 03:25:38.283 INFO No regulatory config supplied by controller, leaving as device default (0) [MatterTest] 07-09 03:25:38.285 INFO <<< [E:19545i S:26569 M:170360027] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [MatterTest] 07-09 03:25:38.564 INFO >>> [E:19545i S:26569 M:158016240] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [MatterTest] 07-09 03:25:38.573 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0003 [MatterTest] 07-09 03:25:38.574 INFO Received SetRegulatoryConfig response errorCode=0 [MatterTest] 07-09 03:25:38.574 INFO Successfully finished commissioning step 'ConfigRegulatory' [MatterTest] 07-09 03:25:38.575 INFO Commissioning stage next step: 'ConfigRegulatory' -> 'SendPAICertificateRequest' [MatterTest] 07-09 03:25:38.576 INFO Performing next commissioning step 'SendPAICertificateRequest' [MatterTest] 07-09 03:25:38.577 INFO Sending request for PAI certificate [MatterTest] 07-09 03:25:38.578 INFO <<< [E:19546i S:26569 M:170360028] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [MatterTest] 07-09 03:25:39.149 INFO >>> [E:19546i S:26569 M:158016241] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [MatterTest] 07-09 03:25:39.159 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [MatterTest] 07-09 03:25:39.160 INFO Received certificate chain from the device [MatterTest] 07-09 03:25:39.160 INFO Successfully finished commissioning step 'SendPAICertificateRequest' [MatterTest] 07-09 03:25:39.161 INFO Commissioning stage next step: 'SendPAICertificateRequest' -> 'SendDACCertificateRequest' [MatterTest] 07-09 03:25:39.162 INFO Performing next commissioning step 'SendDACCertificateRequest' [MatterTest] 07-09 03:25:39.162 INFO Sending request for DAC certificate [MatterTest] 07-09 03:25:39.164 INFO <<< [E:19547i S:26569 M:170360029] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [MatterTest] 07-09 03:25:39.734 INFO >>> [E:19547i S:26569 M:158016242] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [MatterTest] 07-09 03:25:39.744 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0003 [MatterTest] 07-09 03:25:39.744 INFO Received certificate chain from the device [MatterTest] 07-09 03:25:39.745 INFO Successfully finished commissioning step 'SendDACCertificateRequest' [MatterTest] 07-09 03:25:39.745 INFO Commissioning stage next step: 'SendDACCertificateRequest' -> 'SendAttestationRequest' [MatterTest] 07-09 03:25:39.746 INFO Performing next commissioning step 'SendAttestationRequest' [MatterTest] 07-09 03:25:39.747 INFO Sending Attestation Request to the device. [MatterTest] 07-09 03:25:39.749 INFO <<< [E:19548i S:26569 M:170360030] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [MatterTest] 07-09 03:25:40.416 INFO >>> [E:19548i S:26569 M:158016243] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [MatterTest] 07-09 03:25:40.427 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0001 [MatterTest] 07-09 03:25:40.428 INFO Received Attestation Information from the device [MatterTest] 07-09 03:25:40.428 INFO Successfully finished commissioning step 'SendAttestationRequest' [MatterTest] 07-09 03:25:40.429 INFO Commissioning stage next step: 'SendAttestationRequest' -> 'AttestationVerification' [MatterTest] 07-09 03:25:40.429 INFO Performing next commissioning step 'AttestationVerification' [MatterTest] 07-09 03:25:40.430 INFO Verifying attestation [MatterTest] 07-09 03:25:40.482 INFO Successfully validated 'Attestation Information' command received from the device. [MatterTest] 07-09 03:25:40.483 INFO Successfully finished commissioning step 'AttestationVerification' [MatterTest] 07-09 03:25:40.484 INFO Commissioning stage next step: 'AttestationVerification' -> 'SendOpCertSigningRequest' [MatterTest] 07-09 03:25:40.484 INFO Performing next commissioning step 'SendOpCertSigningRequest' [MatterTest] 07-09 03:25:40.486 INFO <<< [E:19549i S:26569 M:170360031] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [MatterTest] 07-09 03:25:41.829 INFO >>> [E:19549i S:26569 M:158016244] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [MatterTest] 07-09 03:25:41.840 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0005 [MatterTest] 07-09 03:25:41.841 INFO Received certificate signing request from the device [MatterTest] 07-09 03:25:41.841 INFO Successfully finished commissioning step 'SendOpCertSigningRequest' [MatterTest] 07-09 03:25:41.842 INFO Commissioning stage next step: 'SendOpCertSigningRequest' -> 'ValidateCSR' [MatterTest] 07-09 03:25:41.843 INFO Performing next commissioning step 'ValidateCSR' [MatterTest] 07-09 03:25:41.846 INFO Successfully finished commissioning step 'ValidateCSR' [MatterTest] 07-09 03:25:41.847 INFO Commissioning stage next step: 'ValidateCSR' -> 'GenerateNOCChain' [MatterTest] 07-09 03:25:41.847 INFO Performing next commissioning step 'GenerateNOCChain' [MatterTest] 07-09 03:25:41.848 INFO Getting certificate chain for the device from the issuer [MatterTest] 07-09 03:25:41.851 INFO Verifying Certificate Signing Request [MatterTest] 07-09 03:25:41.855 INFO Generating NOC [MatterTest] 07-09 03:25:41.855 INFO Providing certificate chain to the commissioner [MatterTest] 07-09 03:25:41.856 INFO Received callback from the CA for NOC Chain generation. Status src/controller/ExampleOperationalCredentialsIssuer.cpp:395: Success [MatterTest] 07-09 03:25:41.856 INFO Successfully finished commissioning step 'GenerateNOCChain' [MatterTest] 07-09 03:25:41.857 INFO Performing next commissioning step 'SendTrustedRootCert' [MatterTest] 07-09 03:25:41.858 INFO Sending root certificate to the device [MatterTest] 07-09 03:25:41.859 INFO <<< [E:19550i S:26569 M:170360032] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [MatterTest] 07-09 03:25:41.861 INFO Sent root certificate to the device [MatterTest] 07-09 03:25:42.463 INFO >>> [E:19550i S:26569 M:158016245] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [MatterTest] 07-09 03:25:42.474 INFO Received Command Response Status for Endpoint=0 Cluster=0x0000_003E Command=0x0000_000B Status=0x0 [MatterTest] 07-09 03:25:42.474 INFO Device confirmed that it has received the root certificate [MatterTest] 07-09 03:25:42.475 INFO Successfully finished commissioning step 'SendTrustedRootCert' [MatterTest] 07-09 03:25:42.475 INFO Commissioning stage next step: 'SendTrustedRootCert' -> 'SendNOC' [MatterTest] 07-09 03:25:42.476 INFO Performing next commissioning step 'SendNOC' [MatterTest] 07-09 03:25:42.478 INFO <<< [E:19551i S:26569 M:170360033] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [MatterTest] 07-09 03:25:42.479 INFO Sent operational certificate to the device [MatterTest] 07-09 03:25:43.926 INFO >>> [E:19551i S:26569 M:158016246] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [MatterTest] 07-09 03:25:43.936 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_003E Command=0x0000_0008 [MatterTest] 07-09 03:25:43.936 INFO Device returned status 0 on receiving the NOC [MatterTest] 07-09 03:25:43.937 INFO Operational credentials provisioned on device 0xffff7c00b770 [MatterTest] 07-09 03:25:43.937 INFO Secure Pairing Success [MatterTest] 07-09 03:25:43.938 INFO Successfully finished commissioning step 'SendNOC' [MatterTest] 07-09 03:25:43.939 INFO No NetworkScan enabled or WiFi/Thread endpoint not specified, skipping ScanNetworks [MatterTest] 07-09 03:25:43.939 INFO Commissioning stage next step: 'SendNOC' -> 'WiFiNetworkSetup' [MatterTest] 07-09 03:25:43.940 INFO Performing next commissioning step 'WiFiNetworkSetup' [MatterTest] 07-09 03:25:43.942 INFO <<< [E:19552i S:26569 M:170360034] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [MatterTest] 07-09 03:25:44.024 INFO >>> [E:19552i S:26569 M:158016247] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [MatterTest] 07-09 03:25:44.033 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0005 [MatterTest] 07-09 03:25:44.033 INFO Received NetworkConfig response, networkingStatus=0 [MatterTest] 07-09 03:25:44.034 INFO Successfully finished commissioning step 'WiFiNetworkSetup' [MatterTest] 07-09 03:25:44.034 INFO Commissioning stage next step: 'WiFiNetworkSetup' -> 'FailsafeBeforeWiFiEnable' [MatterTest] 07-09 03:25:44.035 INFO Performing next commissioning step 'FailsafeBeforeWiFiEnable' [MatterTest] 07-09 03:25:44.035 INFO Arming failsafe (69 seconds) [MatterTest] 07-09 03:25:44.037 INFO <<< [E:19553i S:26569 M:170360035] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [MatterTest] 07-09 03:25:44.170 INFO >>> [E:19553i S:26569 M:158016248] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [MatterTest] 07-09 03:25:44.180 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0001 [MatterTest] 07-09 03:25:44.180 INFO Received ArmFailSafe response errorCode=0 [MatterTest] 07-09 03:25:44.181 INFO Successfully finished commissioning step 'FailsafeBeforeWiFiEnable' [MatterTest] 07-09 03:25:44.181 INFO Commissioning stage next step: 'FailsafeBeforeWiFiEnable' -> 'WiFiNetworkEnable' [MatterTest] 07-09 03:25:44.182 INFO Setting wifi connection time min = 20 [MatterTest] 07-09 03:25:44.182 INFO Performing next commissioning step 'WiFiNetworkEnable' [MatterTest] 07-09 03:25:44.183 INFO SendCommand kWiFiNetworkEnable, supportsConcurrentConnection=1 [MatterTest] 07-09 03:25:44.184 INFO <<< [E:19554i S:26569 M:170360036] (S) Msg TX to 0:FFFFFFFB00000000 [0000] [BLE] --- Type 0001:08 (IM:InvokeCommandRequest) [MatterTest] 07-09 03:25:48.509 INFO >>> [E:19554i S:26569 M:158016249] (S) Msg RX from 0:FFFFFFFB00000000 [0000] --- Type 0001:09 (IM:InvokeCommandResponse) [MatterTest] 07-09 03:25:48.517 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0031 Command=0x0000_0007 [MatterTest] 07-09 03:25:48.518 INFO Received ConnectNetwork response, networkingStatus=0 [MatterTest] 07-09 03:25:48.518 INFO Successfully finished commissioning step 'WiFiNetworkEnable' [MatterTest] 07-09 03:25:48.519 INFO Commissioning stage next step: 'WiFiNetworkEnable' -> 'FindOperational' [MatterTest] 07-09 03:25:48.520 INFO Performing next commissioning step 'FindOperational' [MatterTest] 07-09 03:25:48.521 INFO Resolving 5D422CAC62E2779C:0000000012344321 ... [MatterTest] 07-09 03:25:48.722 INFO Checking node lookup status after 201 ms [MatterTest] 07-09 03:25:50.067 INFO Avahi resolve found [MatterTest] 07-09 03:25:50.069 INFO Node ID resolved for 5D422CAC62E2779C:0000000012344321 [MatterTest] 07-09 03:25:50.074 INFO UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540: new best score: 7 [MatterTest] 07-09 03:25:50.075 INFO Checking node lookup status after 1553 ms [MatterTest] 07-09 03:25:50.079 INFO Initiating session on local FabricIndex 1 from 0x000000000001B669 -> 0x0000000012344321 [MatterTest] 07-09 03:25:50.082 INFO <<< [E:19555i S:0 M:100148210] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540] --- Type 0000:30 (SecureChannel:CASE_Sigma1) [MatterTest] 07-09 03:25:50.083 INFO Sent Sigma1 msg [MatterTest] 07-09 03:25:50.210 INFO >>> [E:19555i S:0 M:127557636 (Ack:100148210)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [MatterTest] 07-09 03:25:51.211 INFO >>> [E:19555i S:0 M:127557637 (Ack:100148210)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:31 (SecureChannel:CASE_Sigma2) [MatterTest] 07-09 03:25:51.213 INFO Received Sigma2 msg [MatterTest] 07-09 03:25:51.225 INFO <<< [E:19555i S:0 M:100148211 (Ack:127557637)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540] --- Type 0000:32 (SecureChannel:CASE_Sigma3) [MatterTest] 07-09 03:25:51.226 INFO Sent Sigma3 msg [MatterTest] 07-09 03:25:51.262 INFO >>> [E:19555i S:0 M:127557638 (Ack:100148211)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:10 (SecureChannel:StandaloneAck) [MatterTest] 07-09 03:25:52.623 INFO >>> [E:19555i S:0 M:127557639 (Ack:100148211)] (U) Msg RX from 0:0000000000000000 [0000] --- Type 0000:40 (SecureChannel:StatusReport) [MatterTest] 07-09 03:25:52.628 INFO Success status report received. Session was established [MatterTest] 07-09 03:25:52.629 INFO SetSdkKey: f/1/s/0000000012344321 = b'\x150\x03\x10\x9b\xbcf\x89\xaea\xcb\xf0\xde\xc9%\x84\x91\xdb\t\x8d0\x04 \xa6\xb5 \xee\x1f\x11\xc3\xa8\xe3\xf2\x99x\x17\T>\xe0\x10\xbb,\xb3\x8f\xa7\x13#\xb5\xb8+T)z"0\x05\x0c\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x00\x18' [MatterTest] 07-09 03:25:52.629 INFO Committing... [MatterTest] 07-09 03:25:52.630 INFO SetSdkKey: g/s/m7xmia5hy/DeySWEkdsJjQ== = b'\x15$\x01\x01&\x02!C4\x12\x18' [MatterTest] 07-09 03:25:52.630 INFO Committing... [MatterTest] 07-09 03:25:52.632 INFO SetSdkKey: g/sri = b'\x16\x15$\x01\x01&\x02!C4\x12\x18\x18' [MatterTest] 07-09 03:25:52.633 INFO Committing... [MatterTest] 07-09 03:25:52.634 INFO SecureSession[0xffff7c04ebc0, LSID:26570]: State change 'kEstablishing' --> 'kActive' [MatterTest] 07-09 03:25:52.635 INFO Successfully finished commissioning step 'FindOperational' [MatterTest] 07-09 03:25:52.635 INFO Commissioning stage next step: 'FindOperational' -> 'SendComplete' [MatterTest] 07-09 03:25:52.636 INFO Performing next commissioning step 'SendComplete' [MatterTest] 07-09 03:25:52.638 INFO <<< [E:19556i S:26570 M:205934533] (S) Msg TX to 1:0000000012344321 [779C] [UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540] --- Type 0001:08 (IM:InvokeCommandRequest) [MatterTest] 07-09 03:25:52.639 INFO <<< [E:19555i S:0 M:100148212 (Ack:127557639)] (U) Msg TX to 0:0000000000000000 [0000] [UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [MatterTest] 07-09 03:25:53.009 INFO Retransmitting MessageCounter:205934533 on exchange 19556i Send Cnt 1 [MatterTest] 07-09 03:25:53.255 INFO >>> [E:19556i S:26570 M:90949165 (Ack:205934533)] (S) Msg RX from 1:0000000012344321 [779C] --- Type 0001:09 (IM:InvokeCommandResponse) [MatterTest] 07-09 03:25:53.268 INFO Received Command Response Data, Endpoint=0 Cluster=0x0000_0030 Command=0x0000_0005 [MatterTest] 07-09 03:25:53.268 INFO Received CommissioningComplete response, errorCode=0 [MatterTest] 07-09 03:25:53.269 INFO Successfully finished commissioning step 'SendComplete' [MatterTest] 07-09 03:25:53.269 INFO Commissioning stage next step: 'SendComplete' -> 'Cleanup' [MatterTest] 07-09 03:25:53.270 INFO Performing next commissioning step 'Cleanup' [MatterTest] 07-09 03:25:53.270 INFO Closing all BLE connections [MatterTest] 07-09 03:25:53.271 INFO Auto-closing end point's BLE connection. [MatterTest] 07-09 03:25:53.272 INFO Closing BLE GATT connection (con 0xffff74055b80) [MatterTest] 07-09 03:25:53.919 INFO SecureSession[0xffff7c0208f0, LSID:26569]: State change 'kActive' --> 'kPendingEviction' [MatterTest] 07-09 03:25:53.920 INFO Bluez notify CHIPoBluez connection disconnected [MatterTest] 07-09 03:25:53.924 INFO Successfully finished commissioning step 'Cleanup' Commissioning complete [MatterTest] 07-09 03:25:53.928 INFO <<< [E:19556i S:26570 M:205934534 (Ack:90949165)] (S) Msg TX to 1:0000000012344321 [779C] [UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [MatterTest] 07-09 03:25:53.929 INFO [Test] test_run_commissioning PASS [MatterTest] 07-09 03:25:53.934 ERROR no endpoint for unsub complete [MatterTest] 07-09 03:25:53.935 INFO Summary for test class CommissionDeviceTest: Error 0, Executed 1, Failed 0, Passed 1, Requested 1, Skipped 0 [MatterTest] 07-09 03:25:53.937 INFO >>> [E:19556i S:26570 M:90949166 (Ack:205934533)] (S) Msg RX from 1:0000000012344321 [779C] --- Type 0000:10 (SecureChannel:StandaloneAck) [MatterTest] 07-09 03:25:53.947 INFO >>> [E:19556i S:26570 M:90949165 (Ack:205934533)] (S) Msg RX from 1:0000000012344321 [779C] --- Type 0001:09 (IM:InvokeCommandResponse) [MatterTest] 07-09 03:25:53.949 INFO ==========> TC_PICS_Checker <========== [MatterTest] 07-09 03:25:53.951 INFO <<< [E:19556i S:26570 M:205934535 (Ack:90949165)] (S) Msg TX to 1:0000000012344321 [779C] [UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [MatterTest] 07-09 03:25:53.954 INFO Found an existing secure session to [1:0000000012344321]! [MatterTest] 07-09 03:25:53.957 INFO <<< [E:19557i S:26570 M:205934536] (S) Msg TX to 1:0000000012344321 [779C] [UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540] --- Type 0001:02 (IM:ReadRequest) [MatterTest] 07-09 03:25:53.979 INFO >>> [E:19557i S:26570 M:90949167 (Ack:205934536)] (S) Msg RX from 1:0000000012344321 [779C] --- Type 0001:05 (IM:ReportData) [MatterTest] 07-09 03:25:54.065 INFO <<< [E:19557i S:26570 M:205934537 (Ack:90949167)] (S) Msg TX to 1:0000000012344321 [779C] [UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540] --- Type 0001:01 (IM:StatusResponse) [MatterTest] 07-09 03:25:54.093 INFO >>> [E:19557i S:26570 M:90949168 (Ack:205934537)] (S) Msg RX from 1:0000000012344321 [779C] --- Type 0001:05 (IM:ReportData) [MatterTest] 07-09 03:25:54.183 INFO <<< [E:19557i S:26570 M:205934538 (Ack:90949168)] (S) Msg TX to 1:0000000012344321 [779C] [UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540] --- Type 0001:01 (IM:StatusResponse) [MatterTest] 07-09 03:25:54.206 INFO >>> [E:19557i S:26570 M:90949169 (Ack:205934538)] (S) Msg RX from 1:0000000012344321 [779C] --- Type 0001:05 (IM:ReportData) [MatterTest] 07-09 03:25:54.273 INFO <<< [E:19557i S:26570 M:205934539 (Ack:90949169)] (S) Msg TX to 1:0000000012344321 [779C] [UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540] --- Type 0001:01 (IM:StatusResponse) [MatterTest] 07-09 03:25:54.293 INFO >>> [E:19557i S:26570 M:90949170 (Ack:205934539)] (S) Msg RX from 1:0000000012344321 [779C] --- Type 0001:05 (IM:ReportData) [MatterTest] 07-09 03:25:54.355 INFO <<< [E:19557i S:26570 M:205934540 (Ack:90949170)] (S) Msg TX to 1:0000000012344321 [779C] [UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540] --- Type 0001:01 (IM:StatusResponse) [MatterTest] 07-09 03:25:54.381 INFO >>> [E:19557i S:26570 M:90949171 (Ack:205934540)] (S) Msg RX from 1:0000000012344321 [779C] --- Type 0001:05 (IM:ReportData) [MatterTest] 07-09 03:25:54.418 INFO <<< [E:19557i S:26570 M:205934541 (Ack:90949171)] (S) Msg TX to 1:0000000012344321 [779C] [UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540] --- Type 0001:01 (IM:StatusResponse) [MatterTest] 07-09 03:25:54.434 INFO >>> [E:19557i S:26570 M:90949172 (Ack:205934541)] (S) Msg RX from 1:0000000012344321 [779C] --- Type 0001:05 (IM:ReportData) [MatterTest] 07-09 03:25:54.525 INFO <<< [E:19557i S:26570 M:205934542 (Ack:90949172)] (S) Msg TX to 1:0000000012344321 [779C] [UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540] --- Type 0001:01 (IM:StatusResponse) [MatterTest] 07-09 03:25:54.537 INFO >>> [E:19557i S:26570 M:90949173 (Ack:205934542)] (S) Msg RX from 1:0000000012344321 [779C] --- Type 0001:05 (IM:ReportData) [MatterTest] 07-09 03:25:54.848 INFO <<< [E:19557i S:26570 M:205934543 (Ack:90949173)] (S) Msg TX to 1:0000000012344321 [779C] [UDP:[fe80::3613:43ff:fe2f:f7da%eth0]:5540] --- Type 0000:10 (SecureChannel:StandaloneAck) [MatterTest] 07-09 03:25:54.877 INFO ########################################################### [MatterTest] 07-09 03:25:54.877 INFO Start of actual tests [MatterTest] 07-09 03:25:54.878 INFO ########################################################### [MatterTest] 07-09 03:25:54.881 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/BooleanStateConfiguration.xml [MatterTest] 07-09 03:25:54.883 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/OTARequestor.xml [MatterTest] 07-09 03:25:54.886 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Mode_EVSE.xml [MatterTest] 07-09 03:25:54.887 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Mode_WaterHeater.xml [MatterTest] 07-09 03:25:54.888 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/DeviceEnergyManagement.xml [MatterTest] 07-09 03:25:54.891 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/WiFiPerDeviceCredentials.xml [MatterTest] 07-09 03:25:54.893 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Scenes.xml [MatterTest] 07-09 03:25:54.895 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/EnergyPreference.xml [MatterTest] 07-09 03:25:54.897 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Label-Cluster-FixedLabelCluster.xml [MatterTest] 07-09 03:25:54.899 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/LocalizationTimeFormat.xml [MatterTest] 07-09 03:25:54.900 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ContentAppObserver.xml [MatterTest] 07-09 03:25:54.902 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/DoorLock.xml [MatterTest] 07-09 03:25:54.917 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Mode_RVCRun.xml [MatterTest] 07-09 03:25:54.919 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/DishwasherAlarm.xml [MatterTest] 07-09 03:25:54.920 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ContentLauncher.xml [MatterTest] 07-09 03:25:54.923 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/FanControl.xml [MatterTest] 07-09 03:25:54.925 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/energy_management.xml [MatterTest] 07-09 03:25:54.926 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/GeneralCommissioningCluster.xml [MatterTest] 07-09 03:25:54.928 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Mode_DeviceEnergyManagement.xml [MatterTest] 07-09 03:25:54.930 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/EnergyCalendar.xml [MatterTest] 07-09 03:25:54.932 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ConcentrationMeasurement.xml [MatterTest] 07-09 03:25:54.939 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/WindowCovering.xml [MatterTest] 07-09 03:25:54.944 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/MediaPlayback.xml [MatterTest] 07-09 03:25:54.947 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/DemandResponseLoadControl.xml [MatterTest] 07-09 03:25:54.952 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/PumpConfigurationControl.xml [MatterTest] 07-09 03:25:54.956 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ElectricalEnergyMeasurement.xml [MatterTest] 07-09 03:25:54.958 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/DiagnosticsGeneral.xml [MatterTest] 07-09 03:25:54.961 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ApplicationBasic.xml [MatterTest] 07-09 03:25:54.963 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/network_infrastructure.xml [MatterTest] 07-09 03:25:54.964 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/bridge-clusters-ActionsCluster.xml [MatterTest] 07-09 03:25:54.966 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/OnOff.xml [MatterTest] 07-09 03:25:54.969 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/TemperatureMeasurement.xml [MatterTest] 07-09 03:25:54.970 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/SmokeCOAlarm.xml [MatterTest] 07-09 03:25:54.973 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ResourceMonitoring.xml [MatterTest] 07-09 03:25:54.975 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ModeBase.xml [MatterTest] 07-09 03:25:54.977 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/MicrowaveOvenControl.xml [MatterTest] 07-09 03:25:54.979 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Label-Cluster-LabelCluster.xml [MatterTest] 07-09 03:25:54.980 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/DiagnosticsWiFi.xml [MatterTest] 07-09 03:25:54.982 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ModeSelect.xml [MatterTest] 07-09 03:25:54.984 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/BallastConfiguration.xml [MatterTest] 07-09 03:25:54.986 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ContentControl.xml [MatterTest] 07-09 03:25:54.990 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Mode_Refrigerator.xml [MatterTest] 07-09 03:25:54.991 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Thermostat.xml [MatterTest] 07-09 03:25:54.998 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/IlluminanceMeasurement.xml [MatterTest] 07-09 03:25:55.000 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/OccupancySensing.xml [MatterTest] 07-09 03:25:55.002 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/OTASoftwareUpdate.xml [MatterTest] 07-09 03:25:55.003 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/OperationalCredentialCluster.xml [MatterTest] 07-09 03:25:55.005 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Groups.xml [MatterTest] 07-09 03:25:55.008 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/LaundryWasherControls.xml [MatterTest] 07-09 03:25:55.009 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/OperationalState_Oven.xml [MatterTest] 07-09 03:25:55.011 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/PressureMeasurement.xml [MatterTest] 07-09 03:25:55.012 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ThermostatUserInterfaceConfiguration.xml [MatterTest] 07-09 03:25:55.014 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/EnergyEVSE.xml [MatterTest] 07-09 03:25:55.018 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Identify.xml [MatterTest] 07-09 03:25:55.020 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/LocalizationUnit.xml [MatterTest] 07-09 03:25:55.021 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/BasicInformationCluster.xml [MatterTest] 07-09 03:25:55.024 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Mode_RVCClean.xml [MatterTest] 07-09 03:25:55.026 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ElectricalPowerMeasurement.xml [MatterTest] 07-09 03:25:55.029 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/TimeSync.xml [MatterTest] 07-09 03:25:55.033 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/LocalizationConfiguration.xml [MatterTest] 07-09 03:25:55.035 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/PowerSourceCluster.xml [MatterTest] 07-09 03:25:55.040 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/FlowMeasurement.xml [MatterTest] 07-09 03:25:55.042 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/BooleanState.xml [MatterTest] 07-09 03:25:55.043 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/LowPower.xml [MatterTest] 07-09 03:25:55.044 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/WakeOnLAN.xml [MatterTest] 07-09 03:25:55.046 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/PowerTopology.xml [MatterTest] 07-09 03:25:55.047 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/DiagnosticsEthernet.xml [MatterTest] 07-09 03:25:55.049 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Descriptor-Cluster.xml [MatterTest] 07-09 03:25:55.050 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/DiagnosticLogsCluster.xml [MatterTest] 07-09 03:25:55.052 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/AdminCommissioningCluster.xml [MatterTest] 07-09 03:25:55.053 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/NetworkIdentityManagement.xml [MatterTest] 07-09 03:25:55.055 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Switch.xml [MatterTest] 07-09 03:25:55.057 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/EnergyPrice.xml [MatterTest] 07-09 03:25:55.059 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/OperationalState.xml [MatterTest] 07-09 03:25:55.062 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/TemperatureControl.xml [MatterTest] 07-09 03:25:55.064 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ColorControl.xml [MatterTest] 07-09 03:25:55.071 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ThreadBorderRouterDiagnostics.xml [MatterTest] 07-09 03:25:55.073 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/DiagnosticsThread.xml [MatterTest] 07-09 03:25:55.078 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/OperationalState_RVC.xml [MatterTest] 07-09 03:25:55.080 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/RefrigeratorAlarm.xml [MatterTest] 07-09 03:25:55.082 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Binding-Cluster.xml [MatterTest] 07-09 03:25:55.083 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ACL-Cluster.xml [MatterTest] 07-09 03:25:55.085 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Group-Key-Management-Cluster.xml [MatterTest] 07-09 03:25:55.087 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/LaundryDryerControls.xml [MatterTest] 07-09 03:25:55.089 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/DiagnosticsSoftware.xml [MatterTest] 07-09 03:25:55.090 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/PowerSourceConfigurationCluster.xml [MatterTest] 07-09 03:25:55.092 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Channel.xml [MatterTest] 07-09 03:25:55.095 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/TargetNavigator.xml [MatterTest] 07-09 03:25:55.096 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Messages.xml [MatterTest] 07-09 03:25:55.098 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/AlarmBase.xml [MatterTest] 07-09 03:25:55.100 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/OTAProvider.xml [MatterTest] 07-09 03:25:55.102 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ApplicationLauncher.xml [MatterTest] 07-09 03:25:55.104 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/AccountLogin.xml [MatterTest] 07-09 03:25:55.105 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/WaterContentMeasurement.xml [MatterTest] 07-09 03:25:55.107 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/bridge-clusters-BridgedDeviceBasicInformationCluster.xml [MatterTest] 07-09 03:25:55.108 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/AirQuality.xml [MatterTest] 07-09 03:25:55.110 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/KeypadInput.xml [MatterTest] 07-09 03:25:55.112 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ValveConfigurationControl.xml [MatterTest] 07-09 03:25:55.114 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/WiFiNetworkManagement.xml [MatterTest] 07-09 03:25:55.116 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/LevelControl.xml [MatterTest] 07-09 03:25:55.120 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/NetworkCommissioningCluster.xml [MatterTest] 07-09 03:25:55.124 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/AudioOutput.xml [MatterTest] 07-09 03:25:55.126 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Mode_Dishwasher.xml [MatterTest] 07-09 03:25:55.128 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Mode_LaundryWasher.xml [MatterTest] 07-09 03:25:55.129 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/MediaInput.xml [MatterTest] 07-09 03:25:55.130 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Mode_Oven.xml [MatterTest] 07-09 03:25:55.132 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/ICDManagement.xml [MatterTest] 07-09 03:25:55.134 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/WaterHeaterManagement.xml [MatterTest] 07-09 03:25:55.136 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Label-Cluster-UserLabelCluster.xml [MatterTest] 07-09 03:25:55.137 INFO Parsing file /root/python_testing/scripts/sdk/../../data_model/clusters/Mode_MicrowaveOven.xml [MatterTest] 07-09 03:25:55.156 INFO [Test] test_TC_IDM_10_4 [MatterTest] 07-09 03:25:55.157 INFO Starting test from /root/python_testing/scripts/sdk/TC_pics_checker.py: test_TC_IDM_10_4 - 6 steps [MatterTest] 07-09 03:25:55.157 INFO Test Step 1 : TH performs a wildcard read of all attributes on the endpoint under test [MatterTest] 07-09 03:25:55.158 INFO Test Step 2 : For every standard cluster: If the cluster is present on the endpoint, ensure the server-side PICS code for the cluster is present in the PICS file (e.g. OO.S for On/Off cluster).If the cluster is not present on the endpoint, ensure the cluster server PICS code is not present in the PICS file. [MatterTest] 07-09 03:25:55.160 INFO Test Step 3 : For every standard cluster, for every attribute in the cluster:If the cluster is present on the endpoint and the attribute ID is present in the AttributeList global attribute within the cluster, ensure the server-side PICS code for the attribute is present in the PICS file (e.g. OO.S.A000 for On/Off cluster¡¯s OnOff attribute).Otherwise, ensure the attribute PICS code is NOT present in the PICS file. [MatterTest] 07-09 03:25:55.168 INFO Test Step 4 : For every cluster present in the spec, for every client ¡ú server command in the cluster: If the cluster is present on the endpoint and the command id is present in the accepted commands list, ensure the PICS code for the accepted command is present in the PICS file. Otherwise, ensure the accepted command PICS code is not present in the PICS file. [MatterTest] 07-09 03:25:55.171 INFO Test Step 5 : For every cluster present in the spec, for every server ¡ú client command in the cluster: If the cluster is present on the endpoint and the command id is present in the generated commands list, ensure the PICS code for the generated command is present in the PICS file. Otherwise, ensure the generated command PICS code is not present in the PICS file. [MatterTest] 07-09 03:25:55.173 INFO Test Step 6 : For every cluster present in the spec, for every feature in the cluster: If the cluster is present on the endpoint and the feature is marked in the feature map, ensure the PICS code for the feature is present in the PICS file. Otherwise, ensure the feature PICS code is not present in the PICS file. [MatterTest] 07-09 03:25:55.181 ERROR Exception occurred in test_TC_IDM_10_4. Traceback (most recent call last): File "/usr/local/lib/python3.10/dist-packages/mobly/base_test.py", line 783, in exec_one_test test_method() File "/root/python_testing/scripts/sdk/TC_pics_checker.py", line 194, in test_TC_IDM_10_4 self.fail_current_test("At least one PICS error was found for this endpoint") File "/root/python_testing/scripts/sdk/basic_composition_support.py", line 149, in fail_current_test asserts.fail(msg) File "/usr/local/lib/python3.10/dist-packages/mobly/asserts.py", line 475, in fail raise signals.TestFailure(msg, extras) mobly.signals.TestFailure: Details=At least one PICS error was found for this endpoint, Extras=None [MatterTest] 07-09 03:25:55.186 INFO ***** Test Failure : [MatterTest] 07-09 03:25:55.186 INFO Finished test in 29ms [MatterTest] 07-09 03:25:55.186 INFO [Test] test_TC_IDM_10_4 FAIL [MatterTest] 07-09 03:25:55.193 INFO ########################################################### [MatterTest] 07-09 03:25:55.193 INFO Problems found: [MatterTest] 07-09 03:25:55.194 INFO =============== [MatterTest] 07-09 03:25:55.194 INFO Problem: ProblemSeverity.WARNING test_name: Spec XML parsing location: Endpoint: 0, Cluster: 257 (0x101) DoorLock, Command: 32 (0x20) problem: Command with unknown direction spec_location:

[MatterTest] 07-09 03:25:55.194 INFO Problem: ProblemSeverity.WARNING test_name: Spec XML parsing location: Endpoint: 0, Cluster: 257 (0x101) DoorLock, Command: 33 (0x21) problem: Command with unknown direction spec_location:

[MatterTest] 07-09 03:25:55.195 INFO Problem: ProblemSeverity.ERROR test_name: PICS check location: Endpoint: 1, Cluster: 28 (0x1c) PulseWidthModulation problem: PICS LVL.S found in PICS list, but not on device spec_location:

[MatterTest] 07-09 03:25:55.195 INFO Problem: ProblemSeverity.WARNING test_name: PICS check location: Endpoint: 1, Cluster: 84 (0x54) RvcRunMode, Feature: Feature.kNoFeatures problem: Unable to parse feature mask 0 from cluster <class 'chip.clusters.Objects.RvcRunMode'> spec_location:

[MatterTest] 07-09 03:25:55.196 INFO Problem: ProblemSeverity.WARNING test_name: PICS check location: Endpoint: 1, Cluster: 85 (0x55) RvcCleanMode, Feature: Feature.kNoFeatures problem: Unable to parse feature mask 0 from cluster <class 'chip.clusters.Objects.RvcCleanMode'> spec_location:

[MatterTest] 07-09 03:25:55.196 INFO ########################################################### [MatterTest] 07-09 03:25:55.198 INFO Summary for test class TC_PICS_Checker: Error 0, Executed 1, Failed 1, Passed 0, Requested 1, Skipped 0 [MatterTest] 07-09 03:25:55.200 INFO Summary for test run MatterTest@07-09-2024_03-25-32-754: Total time elapsed 22.443213253000067s Artifacts are saved in "/tmp/matter_testing/logs/MatterTest/07-09-2024_03-25-32-754" Test summary saved in "/tmp/matter_testing/logs/MatterTest/07-09-2024_03-25-32-754/test_summary.yaml" Test results: Error 0, Executed 2, Failed 1, Passed 1, Requested 2, Skipped 0 INFO:root:Finished test set, ran for 22444183.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[0xffff7c04ebc0]: MarkForEviction Type:2 LSID:26570 INFO:chip.native.SC:SecureSession[0xffff7c04ebc0, LSID:26570]: State change 'kActive' --> 'kPendingEviction' DEBUG:chip.native.IN:SecureSession[0xffff7c04ebc0]: Released - Type:2 LSID:26570 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 = 0xffff8ae1d820 (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[0xaaab0750cc40]: Released - Type:2 LSID:26568 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 = 0xffffea4fb910 (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-quYvTL) 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 ERROR:root:Final result: FAIL ! root@ubuntu:~#

PICS file

No response

Screenshots

No response

Environment

No response

Additional Information

No response

rquidute commented 3 weeks ago

Hi @cecille any thoughts on this?

cecille commented 3 weeks ago

DM scrape pics code for pulse width modulation is incorrect. Should be fixed in 1.2.5. I will prep a workaround for now.

cecille commented 3 weeks ago

https://github.com/project-chip/connectedhomeip/pull/34259

ZeddChen commented 2 weeks ago

In the Matter1.3 certification test, this fix took work.