Add runtime info to report. #39

Author: GilbN

ci/ci.py

@@ -231,6 +231,8 @@ class CI(SetEnvs):
     def __init__(self) -> None:
         super().__init__()  # Init the SetEnvs object.
         self.logger = logging.getLogger("LSIO CI")
+        self.start_time: float = 0.0
+        self.total_runtime: float = 0.0
         logging.getLogger("botocore.auth").setLevel(logging.INFO)  # Don't log the S3 authentication steps.
 
         self.client: DockerClient = docker.from_env()
@@ -249,13 +251,15 @@ def run(self,tags: list) -> None:
             `tags` (list): All the tags we will test on the image.
 
         """
+        self.start_time = time.time()
         thread_pool = ThreadPool(processes=10)
         thread_pool.map(self.container_test,tags)
         display = Display(size=(1920, 1080)) # Setup an x virtual frame buffer (Xvfb) that Selenium can use during the tests.
         display.start()
         thread_pool.close()
         thread_pool.join()
         display.stop()
+        self.total_runtime = time.time() - self.start_time
 
     def container_test(self, tag: str) -> None:
         """Main container test logic.
@@ -286,30 +290,31 @@ def container_test(self, tag: str) -> None:
         logsfound: bool = self.watch_container_logs(container, tag) # Watch the logs for no more than 5 minutes
         if not logsfound:
             self.logger.error("Test of %s FAILED after %.2f seconds", tag, time.time() - start_time)
-            self._endtest(container, tag, "ERROR", "ERROR", False)
+            build_info = {"version": "-", "created": "-", "size": "-", "maintainer": "-"}
+            self._endtest(container, tag, build_info, "ERROR", False, start_time)
             return
 
         # build_version: str = self.get_build_version(container,tag) # Get the image build version
         build_info: dict = self.get_build_info(container,tag) # Get the image build info
         if build_info["version"] == "ERROR":
             self.logger.error("Test of %s FAILED after %.2f seconds", tag, time.time() - start_time)
-            self._endtest(container, tag, build_info, "ERROR", False)
+            self._endtest(container, tag, build_info, "ERROR", False, start_time)
             return
 
         sbom: str = self.generate_sbom(tag)
         if sbom == "ERROR":
             self.logger.error("Test of %s FAILED after %.2f seconds", tag, time.time() - start_time)
-            self._endtest(container, tag, build_info, sbom, False)
+            self._endtest(container, tag, build_info, sbom, False, start_time)
             return
 
         # Screenshot the web interface and check connectivity
         self.take_screenshot(container, tag)
 
-        self._endtest(container, tag, build_info, sbom, True)
+        self._endtest(container, tag, build_info, sbom, True, start_time)
         self.logger.success("Test of %s PASSED after %.2f seconds", tag, time.time() - start_time)
         return
 
-    def _endtest(self, container:Container, tag:str, build_info:dict[str,str], packages:str, test_success: bool) -> None:
+    def _endtest(self, container:Container, tag:str, build_info:dict[str,str], packages:str, test_success: bool, start_time:float|int = 0.0) -> None:
         """End the test with as much info as we have and append to the report.
 
         Args:
@@ -318,7 +323,12 @@ def _endtest(self, container:Container, tag:str, build_info:dict[str,str], packa
             `build_info` (str): Information about the build (version, size etc)
             `packages` (str): SBOM dump from the container
             `test_success` (bool): If the testing of the container failed or not
+            `start_time` (float, optional): The start time of the test. Defaults to 0.0. Used to calculate the runtime of the test.
         """
+        if not start_time:
+            runtime = "-"
+        if isinstance(start_time,(float, int)):
+            runtime = f"{time.time() - start_time:.2f}s"
         logblob: Any = container.logs().decode("utf-8")
         self.create_html_ansi_file(logblob, tag, "log") # Generate an html container log file based on the latest logs
         try:
@@ -338,9 +348,9 @@ def _endtest(self, container:Container, tag:str, build_info:dict[str,str], packa
                 "uwsgi": warning_texts["uwsgi"] if "uwsgi" in packages and "arm" in tag else ""
             },
             "build_info": build_info,
-            # "build_version": build_version,
             "test_results": self.tag_report_tests[tag]["test"],
             "test_success": test_success,
+            "runtime": runtime
             }
         self.report_containers[tag]["has_warnings"] = any(warning[1] for warning in self.report_containers[tag]["warnings"].items())
 
@@ -427,7 +437,7 @@ def generate_sbom(self, tag:str) -> str:
                 logblob: str = syft.logs().decode("utf-8")
                 if "VERSION" in logblob:
                     self.logger.info("Get package versions for %s completed", tag)
-                    self._add_test_result(tag, test, "PASS", "-")
+                    self._add_test_result(tag, test, "PASS", "-", start_time)
                     self.logger.success("%s package list %s: PASSED after %.2f seconds", test, tag, time.time() - start_time)
                     self.create_html_ansi_file(str(logblob),tag,"sbom")
                     try:
@@ -440,7 +450,7 @@ def generate_sbom(self, tag:str) -> str:
                 self.logger.exception("Creating SBOM package list on %s: FAIL", tag)
         self.logger.error("Failed to generate SBOM output on tag %s. SBOM output:\n%s",tag, logblob)
         self.report_status = "FAIL"
-        self._add_test_result(tag, test, "FAIL", str(error_message))
+        self._add_test_result(tag, test, "FAIL", str(error_message), start_time)
         try:
             syft.remove(force=True)
         except Exception:
@@ -496,6 +506,7 @@ def get_build_info(self,container:Container,tag:str) -> dict[str,str]:
             ```
         """
         test = "Get build info"
+        start_time = time.time()
         try:
             self.logger.info("Fetching build info on tag: %s",tag)
             build_info: dict[str,str] = {
@@ -504,14 +515,14 @@ def get_build_info(self,container:Container,tag:str) -> dict[str,str]:
                 "size": "%.2f" % float(int(container.image.attrs["Size"])/1000000) + "MB",
                 "maintainer": container.attrs["Config"]["Labels"]["maintainer"],
             }
-            self._add_test_result(tag, test, "PASS", "-")
+            self._add_test_result(tag, test, "PASS", "-", start_time)
             self.logger.success("Get build info on tag '%s': PASS", tag)
         except (APIError,KeyError) as error:
             self.logger.exception("Get build info on tag '%s': FAIL", tag)
             build_info = {"version": "ERROR", "created": "ERROR", "size": "ERROR", "maintainer": "ERROR"}
             if isinstance(error,KeyError):
                 error: str = f"KeyError: {error}"
-            self._add_test_result(tag, test, "FAIL", str(error))
+            self._add_test_result(tag, test, "FAIL", str(error), start_time)
             self.report_status = "FAIL"
         return build_info
 
@@ -535,17 +546,17 @@ def watch_container_logs(self, container:Container, tag:str) -> bool:
                 logblob: str = container.logs().decode("utf-8")
                 if "[services.d] done." in logblob or "[ls.io-init] done." in logblob:
                     self.logger.info("%s completed for %s",test, tag)
-                    self._add_test_result(tag, test, "PASS", "-")
+                    self._add_test_result(tag, test, "PASS", "-", start_time)
                     self.logger.success("%s %s: PASSED after %.2f seconds", test, tag, time.time() - start_time)
                     return True
                 time.sleep(1)
             except APIError as error:
                 self.logger.exception("%s %s: FAIL - INIT NOT FINISHED", test, tag)
-                self._add_test_result(tag, test, "FAIL", f"INIT NOT FINISHED: {str(error)}")
+                self._add_test_result(tag, test, "FAIL", f"INIT NOT FINISHED: {str(error)}", start_time)
                 self.report_status = "FAIL"
                 return False
         self.logger.error("%s failed for %s", test, tag)
-        self._add_test_result(tag, test, "FAIL", "INIT NOT FINISHED")
+        self._add_test_result(tag, test, "FAIL", "INIT NOT FINISHED", start_time)
         self.logger.error("%s %s: FAIL - INIT NOT FINISHED", test, tag)
         self.report_status = "FAIL"
         return False
@@ -565,7 +576,8 @@ def report_render(self) -> None:
             image=self.image,
             bucket=self.bucket,
             region=self.region,
-            screenshot=self.screenshot
+            screenshot=self.screenshot,
+            total_runtime=f"{self.total_runtime:.2f}s",
             ))
 
     def badge_render(self) -> None:
@@ -668,22 +680,28 @@ def log_upload(self) -> None:
         except (S3UploadFailedError, ClientError):
             self.logger.exception("Failed to upload the CI logs!")
 
-    def _add_test_result(self, tag:str, test:str, status:str, message:str) -> None:
+    def _add_test_result(self, tag:str, test:str, status:str, message:str, start_time:float|int = 0.0) -> None:
         """Add a test result to the report
 
         Args:
             tag (str): The tag we are testing
             test (str): The test we are running
             status (str): The status of the test
             message (str): The message of the test
+            start_time (str, optional): The start time of the test. Defaults to 0.0. Used to calculate the runtime of the test.
         """
         if status not in ["PASS","FAIL"]:
             raise ValueError("Status must be either PASS or FAIL")
         if tag not in self.tags:
             raise ValueError("Tag not in the list of tags")
+        if not start_time:
+            runtime = "-"
+        if isinstance(start_time,(float, int)):
+            runtime: str = f"{time.time() - start_time:.2f}s"
         self.tag_report_tests[tag]["test"][test] = (dict(sorted({
             "status":status,
-            "message":message}.items())))
+            "message":message,
+            "runtime": runtime}.items())))
 
     def take_screenshot(self, container: Container, tag:str) -> None:
         """Take a screenshot and save it to self.outdir if self.screenshot is True
@@ -717,7 +735,7 @@ def take_screenshot(self, container: Container, tag:str) -> None:
                     driver.get_screenshot_as_file(f"{self.outdir}/{tag}.png")
                     if not os.path.isfile(f"{self.outdir}/{tag}.png"):
                         raise FileNotFoundError(f"Screenshot '{self.outdir}/{tag}.png' not found")
-                    self._add_test_result(tag, test, "PASS", "-")
+                    self._add_test_result(tag, test, "PASS", "-", start_time)
                     self.logger.success("Screenshot %s: PASSED after %.2f seconds", tag, time.time() - start_time)
                     return
                 except Exception as error:
@@ -728,13 +746,13 @@ def take_screenshot(self, container: Container, tag:str) -> None:
                         raise error
             raise TimeoutException("Timeout taking screenshot")
         except (requests.Timeout, requests.ConnectionError, KeyError) as error:
-            self._add_test_result(tag, test, "FAIL", f"CONNECTION ERROR: {str(error)}")
+            self._add_test_result(tag, test, "FAIL", f"CONNECTION ERROR: {str(error)}", start_time)
             self.logger.exception("Screenshot %s FAIL CONNECTION ERROR", tag)
         except TimeoutException as error:
-            self._add_test_result(tag, test, "FAIL", f"TIMEOUT: {str(error)}")
+            self._add_test_result(tag, test, "FAIL", f"TIMEOUT: {str(error)}", start_time)
             self.logger.exception("Screenshot %s FAIL TIMEOUT", tag)
         except (WebDriverException, Exception) as error:
-            self._add_test_result(tag, test, "FAIL", f"UNKNOWN: {str(error)}")
+            self._add_test_result(tag, test, "FAIL", f"UNKNOWN: {str(error)}", start_time)
             self.logger.exception("Screenshot %s FAIL UNKNOWN", tag)
         finally:
             try:

ci/logger.py

@@ -95,6 +95,7 @@ def formatMessage(self, record) -> str:
 def configure_logging(log_level:str) -> None:
     """Setup console and file logging"""
 
+    log_level = log_level.upper()
     logger.handlers = []
     logger.setLevel(log_level)
 

ci/template.html

@@ -121,6 +121,11 @@
         color:rgba(218, 59, 138);
       }
 
+      .runtime {
+        border-bottom: 1px solid rgba(255, 255, 255, 0.1);
+        background: rgba(0, 0, 0, 0.25);
+      }
+
       strong {
         color: rgba(218, 59, 138);
       }
@@ -206,6 +211,11 @@
         background: #f5f5f5;
       }
 
+      .runtime {
+        border-bottom: 1px solid #dcdcdc;
+        background: #f5f5f5;
+      }
+
       .build-header {
         color:#738694;
       }
@@ -553,7 +563,8 @@ <h1>Linux<span>Server</span>.io</h1>
     </header>
     <div id="results">
       <h1>Test Results <strong>{{ image }}:{{ meta_tag }}</strong></h1>
-      <h2>Cumulative: <span class="report-status-{{ report_status.lower() }}">{{ report_status }}</span></h2>
+      <h2 style="margin-bottom: 0">Cumulative: <span class="report-status-{{ report_status.lower() }}">{{ report_status }}</span></h2>
+      <span>Total Runtime: {{ total_runtime }}</span>
       <main>
         {% for tag in report_containers %}
         <section>
@@ -565,6 +576,7 @@ <h3 class="section-header-status"><span class="report-status-fail">FAIL</span></
             {% endif %}
             <h2 class="section-header-h2"> {{ image }}:{{ tag }} </h2>
           </div>
+          <div class="runtime build-section">Runtime: {{ report_containers[tag]["runtime"] }}</div>
           {% if screenshot %}
           <a href="{{ tag }}.png">
             <img src="{{ tag }}.png" alt="{{ tag }}" width="600" height="auto" onerror="this.onerror=null; this.src='404.jpg'; this.parentElement.setAttribute('href','#')">
@@ -626,6 +638,7 @@ <h2 class="section-header-h2"> {{ image }}:{{ tag }} </h2>
                   <th>Test</th>
                   <th>Result</th>
                   <th>Message</th>
+                  <th>Runtime</th>
                 </tr>
               </thead>
               <tbody>
@@ -638,6 +651,7 @@ <h2 class="section-header-h2"> {{ image }}:{{ tag }} </h2>
                   <td class="result-cell">{{ report_containers[tag]["test_results"][test]['status'] }} <i class="fas fa-exclamation-circle"></i></td>
                   {% endif %}
                   <td>{{ report_containers[tag]["test_results"][test]["message"] }}</td>
+                  <td>{{ report_containers[tag]["test_results"][test]["runtime"] }}</td>
                 </tr>
                 {% endfor %}
               </tbody>

test_build.py

@@ -7,15 +7,13 @@
 
 def run_test() -> None:
     """Run tests on container tags then build and upload reports"""
-    start_time = time.time()
     ci.run(ci.tags)
     # Don't set the whole report as failed if any of the ARM tag fails.
     for tag in ci.report_containers.keys():
         if tag.startswith("amd64") and ci.report_containers[tag]['test_success'] == True:
             ci.report_status = 'PASS' # Override the report_status if an ARM tag failed, but the amd64 tag passed.
     if ci.report_status == 'PASS':
-        logger.success('All tests PASSED after %.2f seconds', time.time() - start_time)
-
+        logger.success('All tests PASSED after %.2f seconds', ci.total_runtime)
     ci.report_render()
     ci.badge_render()
     ci.json_render()