[Fuego] [PATCH 13/14] Improve logging

Guilherme Campos Camargo guicc at profusion.mobi
Tue Apr 24 17:24:50 UTC 2018


Use LOGGER.info for the messages that are required to identify which
tests are running and if they passed.

Use Logger.error for test failures.

Use Logger.debug for additional information that may be useful while
debugging the tests' execution.

Signed-off-by: Guilherme Campos Camargo <guicc at profusion.mobi>
---
 .../Functional.fuego_release_test/test_run.py | 81 +++++++++++--------
 1 file changed, 49 insertions(+), 32 deletions(-)

diff --git a/engine/tests/Functional.fuego_release_test/test_run.py b/engine/tests/Functional.fuego_release_test/test_run.py
index a36014d..0fe9260 100755
--- a/engine/tests/Functional.fuego_release_test/test_run.py
+++ b/engine/tests/Functional.fuego_release_test/test_run.py
@@ -52,8 +52,8 @@ class SeleniumCommand:
     def exec(self, selenium_ctx):
         self.driver = selenium_ctx.driver
         self.driver.refresh()
-        LOGGER.debug("Executing Selenium Command '%s'",
-                     self.__class__.__name__)
+        LOGGER.info("Executing Selenium Command '%s'",
+                    self.__class__.__name__)
 
     @staticmethod
     def check_element_text(element, text):
@@ -62,11 +62,13 @@ class SeleniumCommand:
                 LOGGER.\
                     debug("  Text '%s' matches element.text '%s'",
                           text, element.text)
+                LOGGER.info("  Matching text found")
                 return True
             else:
                 LOGGER.\
                     debug("  Text '%s' does not match element.text '%s'",
                           text, element.text)
+                LOGGER.error("  Matching text not found.")
                 return False
         except (selenium_exceptions.ElementNotVisibleException,
                 selenium_exceptions.NoSuchAttributeException,):
@@ -77,7 +79,7 @@ class SeleniumCommand:
     def click_element(element):
         try:
             element.click()
-            LOGGER.debug("  Element clicked")
+            LOGGER.info("  Element clicked")
             return True
         except (selenium_exceptions.ElementClickInterceptedException,
                 selenium_exceptions.ElementNotVisibleException,):
@@ -124,17 +126,17 @@ class Visit(SeleniumCommand):
     def exec(self, selenium_ctx):
         super().exec(selenium_ctx)
 
-        LOGGER.debug("  Visiting '%s'", self.url)
+        LOGGER.info("  Visiting '%s'", self.url)
         self.driver.get(self.url)
 
         r = requests.get(self.url)
         if r.status_code != self.expected_result:
-            LOGGER.debug("  HTTP Status Code '%s' is different " +
+            LOGGER.error("  HTTP Status Code '%s' is different " +
                          "from the expected '%s'", r.status_cod, self.url)
             return False
 
-        LOGGER.debug("  HTTP Status Code is same as expected '%s'",
-                     r.status_code)
+        LOGGER.info("  HTTP Status Code is same as expected '%s'",
+                    r.status_code)
         return True
 
 
@@ -280,21 +282,21 @@ class CheckScreenshot(SeleniumCommand):
         result = RESULTS_REGEX.search(stderr)
 
         if not result:
-            LOGGER.error("   Error processing the output.")
+            LOGGER.error("   Error processing the output")
             return False
 
         difference = float(result.group(1))
         if difference > threshold:
-            LOGGER.debug("  Resulting difference (%s) above threshold (%s). ",
+            LOGGER.error("  Resulting difference (%s) above threshold (%s)",
                          difference, threshold)
-            LOGGER.debug("  Element's screenshot does not match the reference."
+            LOGGER.error("  Element's screenshot does not match the reference."
                          "  See %s for a visual representation of the "
                          "  differences.", diff_img_path)
             return False
 
-        LOGGER.debug("  Resulting difference (%s) below threshold (%s).",
-                     difference, threshold)
-        LOGGER.debug("  Element's screenshot matches the reference.")
+        LOGGER.info("  Resulting difference (%s) below threshold (%s)",
+                    difference, threshold)
+        LOGGER.info("  Element's screenshot matches the reference")
         return True
 
     def exec(self, selenium_ctx):
@@ -354,8 +356,8 @@ class Back(SeleniumCommand):
     def exec(self, selenium_ctx):
         super().exec(selenium_ctx)
 
-        LOGGER.debug("  Going back")
         self.driver.back()
+        LOGGER.info("  Went back")
 
         return True
 
@@ -378,7 +380,7 @@ class ShExpect():
     def exec(self, pexpect_ctx):
         self.client = pexpect_ctx.client
 
-        LOGGER.debug("Executing command '%s'", self.cmd)
+        LOGGER.info("Executing command '%s'", self.cmd)
         try:
             self.client.sendline('%s=$(%s 2>&1)' %
                                  (self.OUTPUT_VARIABLE, self.cmd))
@@ -413,6 +415,9 @@ class ShExpect():
         except pexpect.exceptions.EOF:
             LOGGER.error("Lost connection with docker. Aborting")
             return False
+
+        LOGGER.info("  Command result and command output matches " +
+                    "the expected result. (Return code: %d)", result)
         return True
 
 
@@ -428,10 +433,10 @@ class FuegoContainer:
     def delete(self):
         if self.container:
             if self.rm_after_test:
-                LOGGER.debug("Removing Container")
+                LOGGER.info("Removing Container")
                 self.container.remove(force=True)
             else:
-                LOGGER.debug("Not Removing the test container")
+                LOGGER.info("Not Removing the test container")
 
     def install(self):
         self.docker_client = docker.APIClient()
@@ -476,22 +481,25 @@ class FuegoContainer:
                     mount['source'] = None
 
         cmd = './%s %s' % (self.install_script, self.image_name)
-        LOGGER.debug("Running '%s' to install the docker image. " +
-                     "This may take a while....", cmd)
+        LOGGER.info("Running '%s' to install the docker image. " +
+                    "This may take a while....", cmd)
         status = subprocess.call(cmd, shell=True)
 
         LOGGER.debug("Install output code: %s", status)
 
         if status != 0:
+            LOGGER.error("Installation Failed")
             return None
 
+        LOGGER.info("Installation Complete")
+        LOGGER.info("Creating the container '%s'..." % self.container_name)
+
         docker_client = docker.from_env()
         containers = docker_client.containers.list(
             all=True, filters={'name': self.container_name})
         if containers:
-            LOGGER.debug(
-                "Erasing the container '%s', so a new one can be created",
-                self.container_name)
+            LOGGER.debug("Container already exists. Removing it, so a new " +
+                         "one can be created")
             containers[0].remove(force=True)
 
         mounts = [
@@ -530,7 +538,7 @@ class FuegoContainer:
                     for m in mounts],
             name=self.container_name, command='/bin/bash')
 
-        LOGGER.debug("Container '%s' created", self.container_name)
+        LOGGER.info("Container '%s' successfully created", self.container_name)
         return container
 
     def is_running(self):
@@ -584,14 +592,16 @@ class PexpectContainerSession():
         self.timeout = timeout
 
     def start(self):
-        LOGGER.debug(
-            "Starting container '%s'", self.container.container_name)
+        LOGGER.info(
+            "Starting container '%s'...", self.container.container_name)
         self.client = pexpect.spawnu(
             '%s %s' % (self.start_script, self.container.container_name),
             echo=False, timeout=self.timeout)
 
         PexpectContainerSession.set_ps1(self.client)
 
+        LOGGER.info("Container started with the ip '%s'",
+                    self.container.get_ip())
         if not self.wait_for_jenkins():
             return False
 
@@ -629,14 +639,13 @@ class PexpectContainerSession():
         container_addr = self.container.get_ip()
         if container_addr is None:
             return False
-        LOGGER.debug("Trying to reach jenkins at container '%s' via " +
-                     "the container's IP '%s' at port '%d'",
-                     self.container.container_name,
-                     container_addr, self.container.jenkins_port)
+        LOGGER.info("Waiting for jenkins on '%s:%d'...",
+                    container_addr, self.container.jenkins_port)
         if not loop_until_timeout(ping_jenkins, timeout=60):
             LOGGER.error("Could not connect to jenkins")
             return False
 
+        LOGGER.info("Jenkins is running")
         return True
 
 
@@ -649,6 +658,7 @@ class SeleniumContainerSession():
         self.viewport_height = viewport_height
 
     def start(self):
+        LOGGER.info("Starting a Selenium Session on %s...", self.root_url)
         options = webdriver.ChromeOptions()
         options.add_argument('headless')
         options.add_argument('no-sandbox')
@@ -662,7 +672,7 @@ class SeleniumContainerSession():
 
         self.driver.get(self.root_url)
 
-        LOGGER.debug("Started a Selenium Session on %s", self.root_url)
+        LOGGER.info("Selenium Session started successfully")
         return True
 
     def __del__(self):
@@ -696,7 +706,7 @@ def main():
         return abs_install_dir, abs_working_dir
 
     def execute_tests(timeout):
-        LOGGER.debug("Starting tests")
+        LOGGER.info("Starting tests...")
 
         ctx_mapper = {
             ShExpect: pexpect_session,
@@ -709,10 +719,14 @@ def main():
                 if isinstance(cmd, base_class):
                     if not cmd.exec(ctx):
                         tests_ok = False
+                        LOGGER.error("  FAIL")
                         break
+                    LOGGER.info("  PASS")
 
         if tests_ok:
-            LOGGER.debug("Tests finished.")
+            LOGGER.info("All tests finished with SUCCESS")
+        else:
+            LOGGER.info("Tests finished with ERRORS")
 
         return tests_ok
 
@@ -770,11 +784,14 @@ def main():
     pexpect_session = PexpectContainerSession(container, args.start_script,
                                               args.timeout)
     if not pexpect_session.start():
+        LOGGER.error("Pexpect session failed to start")
         return 1
 
     selenium_session = SeleniumContainerSession(container, viewport_width=1920,
                                                 viewport_height=1080)
+
     if not selenium_session.start():
+        LOGGER.error("Selenium session failed to start")
         return 1
 
     if os.getcwd != args.working_dir:
-- 
2.17.0



More information about the Fuego mailing list