project-chip / matter-test-scripts

Test scripts related to Matter Certification
https://csa-iot.org/
Apache License 2.0
6 stars 3 forks source link

Python script evidence of input/output for validation. #159

Open SamCullen-Element opened 5 months ago

SamCullen-Element commented 5 months ago

When validating a python script during a Test Event or SVE, the python script does not provide supporting evidence to show that it is conforming to the test plan and does not provide evidence to support the reported verdict.

Description:

When reviewing the output from a python script test case there is a common theme that there is no log of the command that was issued by the test harness and no log of the returned value from a sample.

A script that was previously validated, but has been changed, excluding through the CCB process as this is slightly different, does not usually inherit its previously validated state under normal CSA rules. As a result, and following usual processes, these scripts become provisional again and need to be revalidated.

Example 1: python output. Python output

A primary part of the requirements for a reviewer in a Test Event or SVE is to validate that the scripts going through testing are correct and the evidence for this is the log of that test case which is submitted for review. These logs are the primary evidence the CSA has historically used to show that test cases and test scripts are compliant and validated. The issue here is that the log does not provide evidence to show that the step has been run accurately and it does not show the values of attributes when read from a sample that would confirm the accuracy of the PASS/FAIL verdict presented by the script. This means that a reviewer would not be able to confidently agree with the test or its verdict, either in an event or a live certification or a recertification review.

To satisfy the proof of evidence we would need the script output log to show the command issued from a test harness, such as with Example 2. and the response data from the sample that is assessed to generate the PASS/FAIL verdict, such as with Example 3.

Example 2: evidence of issued command. YAML evidence of issued command and values

Example 3: evidence of sample response to support a verdict. YAML evidence of return value

fabiowmm commented 5 months ago

@SamCullen-Element the TH GUI provides essentially the same information you get from executing the python scripts by hand, as was the norm before introducing this feature (execution from the TH GUI). I have attached two log files from local runs (one manual and the other via TH) to make it easier to verify if someone feels like that. Being that way, I understand your request is not about TH itself but rather about the level of information provided by python test scripts in general. Is that right? CC @raju-apple @cecille logs_from_manual_execution.txt logs_from_th_gui_execution.txt

cecille commented 5 months ago

suggest adding --trace-to json:log flag to the script args when calling scripts. I think this should get the ATLs all the info as the chip tool. Slightly different format because it's going through trace rather than pretty print, but it's all parsed and human-readable.

cecille commented 5 months ago

ex, here is the remove fabric command exchange with trace logging on :

[2024-02-15 20:56:20.146726][TEST][STDOUT][MatterTest] 02-15 20:56:20.146 INFO Found an existing secure session to [1:0000000012344321]!
[2024-02-15 20:56:20.147057][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO {
[2024-02-15 20:56:20.147084][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO  "event" : "MessageSend",
[2024-02-15 20:56:20.147110][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO  "messageType" : "Secure",
[2024-02-15 20:56:20.147134][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO  "packetHeader" : 
[2024-02-15 20:56:20.147158][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO  {
[2024-02-15 20:56:20.147182][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO      "flags" : 0,
[2024-02-15 20:56:20.147206][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO      "msgCounter" : 204496637,
[2024-02-15 20:56:20.147229][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO      "securityFlags" : 0,
[2024-02-15 20:56:20.147252][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO      "sessionId" : 63625
[2024-02-15 20:56:20.147275][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO  },
[2024-02-15 20:56:20.147298][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO  "payload" : 
[2024-02-15 20:56:20.147322][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO  {
[2024-02-15 20:56:20.147345][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO      "decoded" : 
[2024-02-15 20:56:20.147367][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO      {
[2024-02-15 20:56:20.147391][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO          "invoke_request" : 
[2024-02-15 20:56:20.147415][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO          {
[2024-02-15 20:56:20.147438][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO              "interaction_model_revison" : "11",
[2024-02-15 20:56:20.147462][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO              "invoke_requests" : 
[2024-02-15 20:56:20.147485][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO              {
[2024-02-15 20:56:20.147508][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO                  "Anonymous<0>" : 
[2024-02-15 20:56:20.147531][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO                  {
[2024-02-15 20:56:20.147554][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO                      "OperationalCredentials::RemoveFabric" : 
[2024-02-15 20:56:20.147577][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO                      {
[2024-02-15 20:56:20.147601][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO                          "fabricIndex" : "3"
[2024-02-15 20:56:20.147625][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO                      },
[2024-02-15 20:56:20.147648][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO                      "path" : 
[2024-02-15 20:56:20.147671][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO                      {
[2024-02-15 20:56:20.147695][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO                          "cluster_id" : "62 == 'OperationalCredentials'",
[2024-02-15 20:56:20.147719][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO                          "command_id" : "10 == 'RemoveFabric'",
[2024-02-15 20:56:20.147743][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO                          "endpoint_id" : "0"
[2024-02-15 20:56:20.147766][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO                      }
[2024-02-15 20:56:20.147789][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO                  }
[2024-02-15 20:56:20.147812][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO              },
[2024-02-15 20:56:20.147834][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO              "suppress_response" : "false",
[2024-02-15 20:56:20.147858][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO              "timed_request" : "false"
[2024-02-15 20:56:20.147881][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO          }
[2024-02-15 20:56:20.147904][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO      },
[2024-02-15 20:56:20.147928][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO      "hex" : "1528002801360215370024000024013E24020A18350124000318181824FF0B18",
[2024-02-15 20:56:20.147952][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO      "size" : 32
[2024-02-15 20:56:20.147975][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO  },
[2024-02-15 20:56:20.147999][TEST][STDOUT][MatterTest] 02-15 20:56:20.147 INFO  "payloadHeader" : 
[2024-02-15 20:56:20.148029][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO  {
[2024-02-15 20:56:20.148054][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO      "exchangeFlags" : 5,
[2024-02-15 20:56:20.148077][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO      "exchangeId" : 33948,
[2024-02-15 20:56:20.148102][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO      "initiator" : true,
[2024-02-15 20:56:20.148125][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO      "messageType" : 8,
[2024-02-15 20:56:20.148149][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO      "needsAck" : true,
[2024-02-15 20:56:20.148172][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO      "protocolId" : 1
[2024-02-15 20:56:20.148196][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO  }
[2024-02-15 20:56:20.148222][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO }
[2024-02-15 20:56:20.148288][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO <<< [E:33948i S:28533 M:204496637] (S) Msg TX to 1:0000000012344321 [FE52] [UDP:[fe80::5e1c:b73a:5635:3713%wlp0s20f3]:5540] --- Type 0001:08 (IM:InvokeCommandRequest)
[2024-02-15 20:56:20.148618][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO {
[2024-02-15 20:56:20.148667][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO  "event" : "MessageReceived",
[2024-02-15 20:56:20.148720][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO  "messageType" : "Secure",
[2024-02-15 20:56:20.148764][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO  "packetHeader" : 
[2024-02-15 20:56:20.148849][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO  {
[2024-02-15 20:56:20.148912][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO      "flags" : 0,
[2024-02-15 20:56:20.148952][TEST][STDOUT][MatterTest] 02-15 20:56:20.148 INFO      "msgCounter" : 201145402,
[2024-02-15 20:56:20.149029][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO      "securityFlags" : 0,
[2024-02-15 20:56:20.149073][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO      "sessionId" : 28533
[2024-02-15 20:56:20.149125][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO  },
[2024-02-15 20:56:20.149208][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO  "payload" : 
[2024-02-15 20:56:20.149254][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO  {
[2024-02-15 20:56:20.149294][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO      "decoded" : 
[2024-02-15 20:56:20.149353][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO      {
[2024-02-15 20:56:20.149409][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO          "mrp_ack" : ""
[2024-02-15 20:56:20.149456][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO      },
[2024-02-15 20:56:20.149510][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO      "hex" : "",
[2024-02-15 20:56:20.149552][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO      "size" : 0
[2024-02-15 20:56:20.149604][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO  },
[2024-02-15 20:56:20.149653][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO  "payloadHeader" : 
[2024-02-15 20:56:20.149698][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO  {
[2024-02-15 20:56:20.149773][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO      "ackMessageCounter" : 204496637,
[2024-02-15 20:56:20.149823][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO      "exchangeFlags" : 2,
[2024-02-15 20:56:20.149866][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO      "exchangeId" : 33948,
[2024-02-15 20:56:20.149916][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO      "initiator" : false,
[2024-02-15 20:56:20.149952][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO      "messageType" : 16,
[2024-02-15 20:56:20.149982][TEST][STDOUT][MatterTest] 02-15 20:56:20.149 INFO      "needsAck" : false,
[2024-02-15 20:56:20.150017][TEST][STDOUT][MatterTest] 02-15 20:56:20.150 INFO      "protocolId" : 0
[2024-02-15 20:56:20.150049][TEST][STDOUT][MatterTest] 02-15 20:56:20.150 INFO  }
[2024-02-15 20:56:20.150079][TEST][STDOUT][MatterTest] 02-15 20:56:20.150 INFO }
[2024-02-15 20:56:20.150126][TEST][STDOUT][MatterTest] 02-15 20:56:20.150 INFO >>> [E:33948i S:28533 M:201145402 (Ack:204496637)] (S) Msg RX from 1:0000000012344321 [FE52] --- Type 0000:10 (SecureChannel:StandaloneAck)
[2024-02-15 20:56:20.156378][TEST][STDOUT][MatterTest] 02-15 20:56:20.156 INFO {
[2024-02-15 20:56:20.156509][TEST][STDOUT][MatterTest] 02-15 20:56:20.156 INFO  "event" : "MessageReceived",
[2024-02-15 20:56:20.156597][TEST][STDOUT][MatterTest] 02-15 20:56:20.156 INFO  "messageType" : "Secure",
[2024-02-15 20:56:20.156677][TEST][STDOUT][MatterTest] 02-15 20:56:20.156 INFO  "packetHeader" : 
[2024-02-15 20:56:20.156762][TEST][STDOUT][MatterTest] 02-15 20:56:20.156 INFO  {
[2024-02-15 20:56:20.156843][TEST][STDOUT][MatterTest] 02-15 20:56:20.156 INFO      "flags" : 0,
[2024-02-15 20:56:20.156924][TEST][STDOUT][MatterTest] 02-15 20:56:20.156 INFO      "msgCounter" : 201145403,
[2024-02-15 20:56:20.157002][TEST][STDOUT][MatterTest] 02-15 20:56:20.156 INFO      "securityFlags" : 0,
[2024-02-15 20:56:20.157090][TEST][STDOUT][MatterTest] 02-15 20:56:20.157 INFO      "sessionId" : 28533
[2024-02-15 20:56:20.157148][TEST][STDOUT][MatterTest] 02-15 20:56:20.157 INFO  },
[2024-02-15 20:56:20.157248][TEST][STDOUT][MatterTest] 02-15 20:56:20.157 INFO  "payload" : 
[2024-02-15 20:56:20.157284][TEST][STDOUT][MatterTest] 02-15 20:56:20.157 INFO  {
[2024-02-15 20:56:20.157378][TEST][STDOUT][MatterTest] 02-15 20:56:20.157 INFO      "decoded" : 
[2024-02-15 20:56:20.157449][TEST][STDOUT][MatterTest] 02-15 20:56:20.157 INFO      {
[2024-02-15 20:56:20.157538][TEST][STDOUT][MatterTest] 02-15 20:56:20.157 INFO          "invoke_response" : 
[2024-02-15 20:56:20.157634][TEST][STDOUT][MatterTest] 02-15 20:56:20.157 INFO          {
[2024-02-15 20:56:20.157700][TEST][STDOUT][MatterTest] 02-15 20:56:20.157 INFO              "interaction_model_revison" : "11",
[2024-02-15 20:56:20.157788][TEST][STDOUT][MatterTest] 02-15 20:56:20.157 INFO              "invoke_responses" : 
[2024-02-15 20:56:20.157866][TEST][STDOUT][MatterTest] 02-15 20:56:20.157 INFO              {
[2024-02-15 20:56:20.157955][TEST][STDOUT][MatterTest] 02-15 20:56:20.157 INFO                  "Anonymous<0>" : 
[2024-02-15 20:56:20.158071][TEST][STDOUT][MatterTest] 02-15 20:56:20.157 INFO                  {
[2024-02-15 20:56:20.158078][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                      "command" : 
[2024-02-15 20:56:20.158128][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                      {
[2024-02-15 20:56:20.158175][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                          "OperationalCredentials::NOCResponse" : 
[2024-02-15 20:56:20.158228][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                          {
[2024-02-15 20:56:20.158276][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                              "fabricIndex" : "3",
[2024-02-15 20:56:20.158324][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                              "statusCode" : "0 == kOK"
[2024-02-15 20:56:20.158376][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                          },
[2024-02-15 20:56:20.158426][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                          "path" : 
[2024-02-15 20:56:20.158476][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                          {
[2024-02-15 20:56:20.158537][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                              "cluster_id" : "62 == 'OperationalCredentials'",
[2024-02-15 20:56:20.158581][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                              "command_id" : "8 == 'NOCResponse'",
[2024-02-15 20:56:20.158628][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                              "endpoint_id" : "0"
[2024-02-15 20:56:20.158682][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                          }
[2024-02-15 20:56:20.158740][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                      }
[2024-02-15 20:56:20.158782][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO                  }
[2024-02-15 20:56:20.158823][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO              },
[2024-02-15 20:56:20.158867][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO              "suppress_response" : "false"
[2024-02-15 20:56:20.158911][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO          }
[2024-02-15 20:56:20.158956][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO      },
[2024-02-15 20:56:20.159014][TEST][STDOUT][MatterTest] 02-15 20:56:20.158 INFO      "hex" : "1528003601153500370024000024013E2402081835012400002401031818181824FF0B18",
[2024-02-15 20:56:20.159063][TEST][STDOUT][MatterTest] 02-15 20:56:20.159 INFO      "size" : 36
[2024-02-15 20:56:20.159110][TEST][STDOUT][MatterTest] 02-15 20:56:20.159 INFO  },
[2024-02-15 20:56:20.159157][TEST][STDOUT][MatterTest] 02-15 20:56:20.159 INFO  "payloadHeader" : 
[2024-02-15 20:56:20.159205][TEST][STDOUT][MatterTest] 02-15 20:56:20.159 INFO  {
[2024-02-15 20:56:20.159254][TEST][STDOUT][MatterTest] 02-15 20:56:20.159 INFO      "ackMessageCounter" : 204496637,
[2024-02-15 20:56:20.159301][TEST][STDOUT][MatterTest] 02-15 20:56:20.159 INFO      "exchangeFlags" : 6,
[2024-02-15 20:56:20.159347][TEST][STDOUT][MatterTest] 02-15 20:56:20.159 INFO      "exchangeId" : 33948,
[2024-02-15 20:56:20.159397][TEST][STDOUT][MatterTest] 02-15 20:56:20.159 INFO      "initiator" : false,
[2024-02-15 20:56:20.159452][TEST][STDOUT][MatterTest] 02-15 20:56:20.159 INFO      "messageType" : 9,
[2024-02-15 20:56:20.159534][TEST][STDOUT][MatterTest] 02-15 20:56:20.159 INFO      "needsAck" : true,
[2024-02-15 20:56:20.159608][TEST][STDOUT][MatterTest] 02-15 20:56:20.159 INFO      "protocolId" : 1
[2024-02-15 20:56:20.159661][TEST][STDOUT][MatterTest] 02-15 20:56:20.159 INFO  }
[2024-02-15 20:56:20.159706][TEST][STDOUT][MatterTest] 02-15 20:56:20.159 INFO }
fabiowmm commented 4 months ago

As requested by @raju-apple , find attached some samples with both the new and old log formats.

tc-ace-1.3_old.log tc-ace-1.3_new.log tc-acl-2.2_new.log tc-ace-1.3+tc-da-1.5_new.log

raju-apple commented 4 months ago

@SamCullen-Element Can you review the logs attached and confirm if the Python logs now are sufficient for validation ?

SamCullen-Element commented 4 months ago

@raju-apple The new logs show the details of the outgoing and incoming payloads and show what I would need to see for validating. The crucial part was the body of the request/response.