Merge pull request #1808 from cncf/task-timestamps

[1807] Add task runtime info to results file if `TASK_TIMESTAMPS` env var is set

spec/utils/cnf_manager_spec.cr

@@ -81,7 +81,7 @@ describe "SampleUtils" do
 
   it "'upsert_task' insert task in the results file", tags: ["tasks"]  do
     CNFManager::Points.clean_results_yml
-   CNFManager::Points.upsert_task("liveness", PASSED, CNFManager::Points.task_points("liveness"))
+   CNFManager::Points.upsert_task("liveness", PASSED, CNFManager::Points.task_points("liveness"), Time.utc)
     yaml = File.open("#{CNFManager::Points::Results.file}") do |file|
       YAML.parse(file)
     end
@@ -91,8 +91,8 @@ describe "SampleUtils" do
 
   it "'upsert_task' should find and update an existing task in the file", tags: ["tasks"]  do
     CNFManager::Points.clean_results_yml
-   CNFManager::Points.upsert_task("liveness", PASSED, CNFManager::Points.task_points("liveness"))
-   CNFManager::Points.upsert_task("liveness", PASSED, CNFManager::Points.task_points("liveness"))
+   CNFManager::Points.upsert_task("liveness", PASSED, CNFManager::Points.task_points("liveness"), Time.utc)
+   CNFManager::Points.upsert_task("liveness", PASSED, CNFManager::Points.task_points("liveness"), Time.utc)
     yaml = File.open("#{CNFManager::Points::Results.file}") do |file|
       YAML.parse(file)
     end
@@ -103,15 +103,15 @@ describe "SampleUtils" do
 
   it "'CNFManager::Points.total_points' should sum the total amount of points in the results", tags: ["points"] do
     CNFManager::Points.clean_results_yml
-   CNFManager::Points.upsert_task("liveness", PASSED, CNFManager::Points.task_points("liveness"))
+   CNFManager::Points.upsert_task("liveness", PASSED, CNFManager::Points.task_points("liveness"), Time.utc)
     (CNFManager::Points.total_points).should eq(100)
   end
 
   it "'CNFManager::Points.total_max_points' should not include na in the total potential points", tags: ["points"] do
     CNFManager::Points.clean_results_yml
-      upsert_passed_task("liveness", "✔️  PASSED: CNF had a reasonable startup time ")
+      upsert_passed_task("liveness", "✔️  PASSED: CNF had a reasonable startup time ", Time.utc)
     resp1 = CNFManager::Points.total_max_points
-      upsert_na_task("readiness", "✔️  NA")
+      upsert_na_task("readiness", "✔️  NA", Time.utc)
     resp2 = CNFManager::Points.total_max_points
 
     LOGGING.info "readiness points: #{CNFManager::Points.task_points("readiness").not_nil!.to_i}"
@@ -174,12 +174,12 @@ describe "SampleUtils" do
 
   it "'CNFManager::Points.all_result_test_names' should return the tasks assigned to a tag", tags: ["points"] do
     CNFManager::Points.clean_results_yml
-   CNFManager::Points.upsert_task("liveness", PASSED, CNFManager::Points.task_points("liveness"))
+   CNFManager::Points.upsert_task("liveness", PASSED, CNFManager::Points.task_points("liveness"), Time.utc)
     (CNFManager::Points.all_result_test_names(CNFManager::Points::Results.file)).should eq(["liveness"])
   end
   it "'CNFManager::Points.results_by_tag' should return a list of results by tag", tags: ["points"] do
     CNFManager::Points.clean_results_yml
-   CNFManager::Points.upsert_task("liveness", PASSED, CNFManager::Points.task_points("liveness"))
+   CNFManager::Points.upsert_task("liveness", PASSED, CNFManager::Points.task_points("liveness"), Time.utc)
     (CNFManager::Points.results_by_tag("resilience")).should eq([{"name" => "liveness", "status" => "passed", "type" => "essential", "points" => 100}])
     (CNFManager::Points.results_by_tag("does-not-exist")).should eq([] of YAML::Any) 
   end

spec/utils/utils_spec.cr

@@ -58,7 +58,7 @@ describe "Utils" do
 
   it "'upsert_skipped_task' should put a 0 in the results file", tags: ["task_runner"]  do
     CNFManager::Points.clean_results_yml
-    resp = upsert_skipped_task("ip_addresses","✖️  FAILED: IP addresses found")
+    resp = upsert_skipped_task("ip_addresses","✖️  FAILED: IP addresses found", Time.utc)
     yaml = File.open("#{CNFManager::Points::Results.file}") do |file|
       YAML.parse(file)
     end
@@ -100,9 +100,9 @@ describe "Utils" do
       Log.debug { "violator list: #{violation_list.flatten}" }
       emoji_security=""
       if resource_response 
-        resp = upsert_passed_task("privileged", "✔️  PASSED: No privileged containers")
+        resp = upsert_passed_task("privileged", "✔️  PASSED: No privileged containers", Time.utc)
       else
-        resp = upsert_failed_task("privileged", "✖️  FAILED: Found #{violation_list.size} privileged containers: #{violation_list.inspect}")
+        resp = upsert_failed_task("privileged", "✖️  FAILED: Found #{violation_list.size} privileged containers: #{violation_list.inspect}", Time.utc)
       end
       Log.info { resp }
       resp
@@ -129,14 +129,14 @@ describe "Utils" do
         end
         Dir.cd(cdir)
         if response.to_s.size > 0
-          resp = upsert_failed_task("ip_addresses","✖️  FAILED: IP addresses found")
+          resp = upsert_failed_task("ip_addresses","✖️  FAILED: IP addresses found", Time.utc)
         else
-          resp = upsert_passed_task("ip_addresses", "✔️  PASSED: No IP addresses found")
+          resp = upsert_passed_task("ip_addresses", "✔️  PASSED: No IP addresses found", Time.utc)
         end
         resp
       else
         Dir.cd(cdir)
-        resp = upsert_passed_task("ip_addresses", "✔️  PASSED: No IP addresses found")
+        resp = upsert_passed_task("ip_addresses", "✔️  PASSED: No IP addresses found", Time.utc)
       end
     end
     yaml = File.open("#{CNFManager::Points::Results.file}") do |file|
@@ -174,9 +174,9 @@ describe "Utils" do
       LOGGING.debug "violator list: #{violation_list.flatten}"
       emoji_security=""
       if resource_response 
-        resp = upsert_passed_task("privileged", "✔️  PASSED: No privileged containers")
+        resp = upsert_passed_task("privileged", "✔️  PASSED: No privileged containers", Time.utc)
       else
-        resp = upsert_failed_task("privileged", "✖️  FAILED: Found #{violation_list.size} privileged containers: #{violation_list.inspect}")
+        resp = upsert_failed_task("privileged", "✖️  FAILED: Found #{violation_list.size} privileged containers: #{violation_list.inspect}", Time.utc)
       end
       resp
     end

src/tasks/platform/hardware_and_scheduling.cr

@@ -25,10 +25,10 @@ namespace "platform" do
       LOGGING.info "all_oci_runtimes: #{all_oci_runtimes}"
       if all_oci_runtimes 
         emoji_chaos_oci_compliant="📶☠️"
-        upsert_passed_task("oci_compliant","✔️  PASSED: Your platform is using the following runtimes: [#{KubectlClient::Get.container_runtimes.join(",")}] which are OCI compliant runtimes #{emoji_chaos_oci_compliant}")
+        upsert_passed_task("oci_compliant","✔️  PASSED: Your platform is using the following runtimes: [#{KubectlClient::Get.container_runtimes.join(",")}] which are OCI compliant runtimes #{emoji_chaos_oci_compliant}", Time.utc)
       else
         emoji_chaos_oci_compliant="📶☠️"
-        upsert_failed_task("oci_compliant", "✖️  FAILED: Platform has at least one node that uses a non OCI compliant runtime #{emoji_chaos_oci_compliant}")
+        upsert_failed_task("oci_compliant", "✖️  FAILED: Platform has at least one node that uses a non OCI compliant runtime #{emoji_chaos_oci_compliant}", Time.utc)
       end
     end
   end

src/tasks/platform/observability.cr

@@ -32,10 +32,10 @@ namespace "platform" do
 
     if found
       emoji_kube_state_metrics="📶☠️"
-      upsert_passed_task("kube_state_metrics","✔️  PASSED: Your platform is using the release for kube state metrics #{emoji_kube_state_metrics}")
+      upsert_passed_task("kube_state_metrics","✔️  PASSED: Your platform is using the release for kube state metrics #{emoji_kube_state_metrics}", Time.utc)
     else
       emoji_kube_state_metrics="📶☠️"
-      upsert_failed_task("kube_state_metrics", "✖️  FAILED: Your platform does not have kube state metrics installed #{emoji_kube_state_metrics}")
+      upsert_failed_task("kube_state_metrics", "✖️  FAILED: Your platform does not have kube state metrics installed #{emoji_kube_state_metrics}", Time.utc)
     end
   end
 
@@ -57,10 +57,10 @@ namespace "platform" do
     Log.info { "Found Process: #{found}" }
     if found
       emoji_node_exporter="📶☠️"
-      upsert_passed_task("node_exporter","✔️  PASSED: Your platform is using the node exporter #{emoji_node_exporter}")
+      upsert_passed_task("node_exporter","✔️  PASSED: Your platform is using the node exporter #{emoji_node_exporter}", Time.utc)
     else
       emoji_node_exporter="📶☠️"
-      upsert_failed_task("node_exporter", "✖️  FAILED: Your platform does not have the node exporter installed #{emoji_node_exporter}")
+      upsert_failed_task("node_exporter", "✖️  FAILED: Your platform does not have the node exporter installed #{emoji_node_exporter}", Time.utc)
     end
   end
 
@@ -83,10 +83,10 @@ namespace "platform" do
 
     if found
       emoji_prometheus_adapter="📶☠️"
-      upsert_passed_task("prometheus_adapter","✔️  PASSED: Your platform is using the prometheus adapter #{emoji_prometheus_adapter}")
+      upsert_passed_task("prometheus_adapter","✔️  PASSED: Your platform is using the prometheus adapter #{emoji_prometheus_adapter}", Time.utc)
     else
       emoji_prometheus_adapter="📶☠️"
-      upsert_failed_task("prometheus_adapter", "✖️  FAILED: Your platform does not have the prometheus adapter installed #{emoji_prometheus_adapter}")
+      upsert_failed_task("prometheus_adapter", "✖️  FAILED: Your platform does not have the prometheus adapter installed #{emoji_prometheus_adapter}", Time.utc)
     end
   end
 
@@ -108,10 +108,10 @@ namespace "platform" do
       found = KernelIntrospection::K8s.find_first_process(CloudNativeIntrospection::METRICS_SERVER)
       if found
         emoji_metrics_server="📶☠️"
-        upsert_passed_task("metrics_server","✔️  PASSED: Your platform is using the metrics server #{emoji_metrics_server}")
+        upsert_passed_task("metrics_server","✔️  PASSED: Your platform is using the metrics server #{emoji_metrics_server}", Time.utc)
       else
         emoji_metrics_server="📶☠️"
-        upsert_failed_task("metrics_server", "✖️  FAILED: Your platform does not have the metrics server installed #{emoji_metrics_server}")
+        upsert_failed_task("metrics_server", "✖️  FAILED: Your platform does not have the metrics server installed #{emoji_metrics_server}", Time.utc)
       end
     end
   end

src/tasks/platform/platform.cr

@@ -70,10 +70,10 @@ task "k8s_conformance" do |_, args|
 
     failed_count = ((results.match(/Failed: (.*)/)).try &.[1]) 
     if failed_count.to_s.to_i > 0 
-      upsert_failed_task("k8s_conformance", "✖️  FAILED: K8s conformance test has #{failed_count} failure(s)!")
+      upsert_failed_task("k8s_conformance", "✖️  FAILED: K8s conformance test has #{failed_count} failure(s)!", Time.utc)
 
     else
-      upsert_passed_task("k8s_conformance", "✔️  PASSED: K8s conformance test has no failures")
+      upsert_passed_task("k8s_conformance", "✔️  PASSED: K8s conformance test has no failures", Time.utc)
     end
   rescue ex
     Log.error { ex.message }
@@ -134,9 +134,9 @@ task "clusterapi_enabled" do |_, args|
     emoji_control="✨"
 
     if clusterapi_namespaces_json["items"]? && clusterapi_namespaces_json["items"].as_a.size > 0 && clusterapi_control_planes_json["items"]? && clusterapi_control_planes_json["items"].as_a.size > 0
-      resp = upsert_passed_task("clusterapi_enabled", "✔️ Cluster API is enabled #{emoji_control}")
+      resp = upsert_passed_task("clusterapi_enabled", "✔️ Cluster API is enabled #{emoji_control}", Time.utc)
     else
-      resp = upsert_failed_task("clusterapi_enabled", "✖️ Cluster API NOT enabled #{emoji_control}")
+      resp = upsert_failed_task("clusterapi_enabled", "✖️ Cluster API NOT enabled #{emoji_control}", Time.utc)
     end
 
     resp

src/tasks/platform/resilience.cr

@@ -43,7 +43,7 @@ namespace "platform" do
           pod_ready = KubectlClient::Get.pod_status("reboot", "--field-selector spec.nodeName=#{worker_node}").split(",")[2]
           pod_ready_timeout = pod_ready_timeout - 1
           if pod_ready_timeout == 0
-            upsert_failed_task("worker_reboot_recovery", "✖️  FAILED: Failed to install reboot daemon")
+            upsert_failed_task("worker_reboot_recovery", "✖️  FAILED: Failed to install reboot daemon", Time.utc)
             exit 1
           end
           sleep 1
@@ -67,7 +67,7 @@ namespace "platform" do
           Log.info { "Node Ready Status: #{node_ready}" }
           node_failure_timeout = node_failure_timeout - 1
           if node_failure_timeout == 0
-            upsert_failed_task("worker_reboot_recovery", "✖️  FAILED: Node failed to go offline")
+            upsert_failed_task("worker_reboot_recovery", "✖️  FAILED: Node failed to go offline", Time.utc)
             exit 1
           end
           sleep 1
@@ -85,14 +85,14 @@ namespace "platform" do
           Log.info { "Node Ready Status: #{node_ready}" }
           node_online_timeout = node_online_timeout - 1
           if node_online_timeout == 0
-            upsert_failed_task("worker_reboot_recovery", "✖️  FAILED: Node failed to come back online")
+            upsert_failed_task("worker_reboot_recovery", "✖️  FAILED: Node failed to come back online", Time.utc)
             exit 1
           end
           sleep 1
         end
 
         emoji_worker_reboot_recovery=""
-        resp = upsert_passed_task("worker_reboot_recovery","✔️  PASSED: Node came back online #{emoji_worker_reboot_recovery}")
+        resp = upsert_passed_task("worker_reboot_recovery","✔️  PASSED: Node came back online #{emoji_worker_reboot_recovery}", Time.utc)
 
 
       ensure

src/tasks/platform/security.cr

@@ -20,9 +20,9 @@ namespace "platform" do
 
       emoji_security="🔓🔑"
       if test_report.failed_resources.size == 0
-        upsert_passed_task("control_plane_hardening", "✔️  PASSED: Control plane hardened #{emoji_security}")
+        upsert_passed_task("control_plane_hardening", "✔️  PASSED: Control plane hardened #{emoji_security}", Time.utc)
       else
-        resp = upsert_failed_task("control_plane_hardening", "✖️  FAILED: Control plane not hardened #{emoji_security}")
+        resp = upsert_failed_task("control_plane_hardening", "✖️  FAILED: Control plane not hardened #{emoji_security}", Time.utc)
         test_report.failed_resources.map {|r| stdout_failure(r.alert_message) }
         stdout_failure("Remediation: #{test_report.remediation}")
         resp
@@ -41,9 +41,9 @@ namespace "platform" do
 
       emoji_security="🔓🔑"
       if test_report.failed_resources.size == 0
-        upsert_passed_task("cluster_admin", "✔️  PASSED: No users with cluster admin role found #{emoji_security}")
+        upsert_passed_task("cluster_admin", "✔️  PASSED: No users with cluster admin role found #{emoji_security}", Time.utc)
       else
-        resp = upsert_failed_task("cluster_admin", "✖️  FAILED: Users with cluster admin role found #{emoji_security}")
+        resp = upsert_failed_task("cluster_admin", "✖️  FAILED: Users with cluster admin role found #{emoji_security}", Time.utc)
         test_report.failed_resources.map {|r| stdout_failure(r.alert_message) }
         stdout_failure("Remediation: #{test_report.remediation}")
         resp
@@ -63,9 +63,9 @@ namespace "platform" do
 
       emoji_security = "🔓🔑"
       if test_report.failed_resources.size == 0
-        upsert_passed_task("exposed_dashboard", "✔️  PASSED: No exposed dashboard found in the cluster #{emoji_security}")
+        upsert_passed_task("exposed_dashboard", "✔️  PASSED: No exposed dashboard found in the cluster #{emoji_security}", Time.utc)
       else
-        resp = upsert_failed_task("exposed_dashboard", "✖️  FAILED: Found exposed dashboard in the cluster #{emoji_security}")
+        resp = upsert_failed_task("exposed_dashboard", "✖️  FAILED: Found exposed dashboard in the cluster #{emoji_security}", Time.utc)
         test_report.failed_resources.map {|r| stdout_failure(r.alert_message) }
         stdout_failure("Remediation: #{test_report.remediation}")
         resp
@@ -84,9 +84,9 @@ namespace "platform" do
       failures = Kyverno::PolicyAudit.run(policy_path, EXCLUDE_NAMESPACES)
 
       if failures.size == 0
-        resp = upsert_passed_task("helm_tiller", "✔️  PASSED: No Helm Tiller containers are running #{emoji_security}")
+        resp = upsert_passed_task("helm_tiller", "✔️  PASSED: No Helm Tiller containers are running #{emoji_security}", Time.utc)
       else
-        resp = upsert_failed_task("helm_tiller", "✖️  FAILED: Containers with the Helm Tiller image are running #{emoji_security}")
+        resp = upsert_failed_task("helm_tiller", "✖️  FAILED: Containers with the Helm Tiller image are running #{emoji_security}", Time.utc)
         failures.each do |failure|
           failure.resources.each do |resource|
             puts "#{resource.kind} #{resource.name} in #{resource.namespace} namespace failed. #{failure.message}".colorize(:red)

src/tasks/utils/points.cr

@@ -382,7 +382,7 @@ module CNFManager
     end
 
 
-    def self.upsert_task(task, status, points)
+    def self.upsert_task(task, status, points, start_time)
       results = File.open("#{Results.file}") do |f|
         YAML.parse(f)
       end
@@ -394,7 +394,34 @@ module CNFManager
       end
       cmd = "#{Process.executable_path} #{ARGV.join(" ")}"
       Log.info {"cmd: #{cmd}"}
-      result_items << YAML.parse "{name: #{task}, status: #{status}, type: #{task_type_by_task(task)}, points: #{points}}"
+      end_time = Time.utc
+      task_runtime = (end_time - start_time).milliseconds
+
+      # The task result info has to be appeneded to an array of YAML::Any
+      # So encode it into YAML and parse it back again to assign it.
+      #
+      # Only add task timestamps if the env var is set.
+      if ENV.has_key?("TASK_TIMESTAMPS")
+        task_result_info = {
+          name: task,
+          status: status,
+          type: task_type_by_task(task),
+          points: points,
+          start_time: start_time,
+          end_time: end_time,
+          task_runtime_milliseconds: task_runtime
+        }
+        result_items << YAML.parse(task_result_info.to_yaml)
+      else
+        task_result_info = {
+          name: task,
+          status: status,
+          type: task_type_by_task(task),
+          points: points
+        }
+        result_items << YAML.parse(task_result_info.to_yaml)
+      end
+
       File.open("#{Results.file}", "w") do |f|
         YAML.dump({name: results["name"],
                    # testsuite_version: CnfTestSuite::VERSION,
@@ -405,21 +432,21 @@ module CNFManager
                    exit_code: results["exit_code"],
                    items: result_items}, f)
       end
-      Log.info { "upsert_task: task: #{task} has status: #{status} and is awarded: #{points} points" }
+      Log.info { "upsert_task: task: #{task} has status: #{status} and is awarded: #{points} points. Runtime: #{task_runtime} seconds" }
     end
 
     def self.failed_task(task, msg)
-      upsert_task(task, FAILED, task_points(task, false))
+      upsert_task(task, FAILED, task_points(task, false), start_time)
       stdout_failure "#{msg}"
     end
 
     def self.passed_task(task, msg)
-      upsert_task(task, PASSED, task_points(task))
+      upsert_task(task, PASSED, task_points(task), start_time)
       stdout_success "#{msg}"
     end
 
     def self.skipped_task(task, msg)
-      upsert_task(task, SKIPPED, task_points(task))
+      upsert_task(task, SKIPPED, task_points(task), start_time)
       stdout_success "#{msg}"
     end