Add more logging to ESR to help debug hanging (#28)

.gitignore

@@ -21,6 +21,7 @@ __pycache__/*
 .settings
 .idea
 tags
+.tags
 
 # Package files
 *.egg

src/etos_suite_runner/__main__.py

@@ -90,12 +90,15 @@ def _request_environment(self, ids):
             return None, str(exception)
         return task_id, ""
 
-    def _get_environment_status(self, task_id):
+    def _get_environment_status(self, task_id, identifier):
         """Wait for an environment being provided.
 
         :param task_id: Task ID to wait for.
         :type task_id: str
+        :param identifier: An identifier to use for logging.
+        :type identifier: str
         """
+        FORMAT_CONFIG.identifier = identifier
         timeout = self.etos.config.get("WAIT_FOR_ENVIRONMENT_TIMEOUT")
         wait_generator = self.etos.utils.wait(
             self.etos.http.wait_for_request,
@@ -119,6 +122,7 @@ def _get_environment_status(self, task_id):
                 "Unknown Error: Did not receive an environment "
                 f"within {self.etos.debug.default_http_timeout}s",
             )
+        self.logger.info("Test environment received.")
 
     def _release_environment(self, task_id):
         """Release an environment from the environment provider.
@@ -148,13 +152,15 @@ def _reserve_workers(self, ids):
             raise EnvironmentProviderException(msg, task_id)
         return task_id
 
-    def run_suites(self, triggered):
+    def run_suites(self, triggered, tercc_id):
         """Start up a suite runner handling multiple suites that execute within test runners.
 
         Will only start the test activity if there's a 'slot' available.
 
         :param triggered: Activity triggered.
         :type triggered: :obj:`eiffel.events.EiffelActivityTriggeredEvent`
+        :param tercc_id: The ID of the tercc that is going to be executed.
+        :type tercc_id: str
         """
         context = triggered.meta.event_id
         self.etos.config.set("context", context)
@@ -175,7 +181,7 @@ def run_suites(self, triggered):
             task_id = self._reserve_workers(ids)
             self.etos.config.set("task_id", task_id)
             threading.Thread(
-                target=self._get_environment_status, args=(task_id,), daemon=True
+                target=self._get_environment_status, args=(task_id, tercc_id), daemon=True
             ).start()
 
             self.etos.events.send_activity_started(triggered, {"CONTEXT": context})
@@ -234,7 +240,7 @@ def run(self):
             raise
 
         try:
-            self.run_suites(triggered)
+            self.run_suites(triggered, tercc_id)
             self.etos.events.send_activity_finished(
                 triggered, {"conclusion": "SUCCESSFUL"}, {"CONTEXT": context}
             )

src/etos_suite_runner/lib/esr_parameters.py

@@ -64,6 +64,7 @@ def __init__(self, etos):
     def set_status(self, status, error):
         """Set environment provider status."""
         with self.lock:
+            self.logger.debug("Setting environment status to %r, error %r", status, error)
             self.environment_status["status"] = status
             self.environment_status["error"] = error
 
@@ -166,16 +167,22 @@ def collect_environments(self):
             "status": "FAILURE",
             "error": "Couldn't collect any error information",
         }
+        self.logger.debug(
+            "Start collecting sub suite environments (timeout=%ds).",
+            self.etos.config.get("WAIT_FOR_ENVIRONMENT_TIMEOUT"),
+        )
         timeout = time.time() + self.etos.config.get("WAIT_FOR_ENVIRONMENT_TIMEOUT")
         while time.time() < timeout:
-            status = self.environment_status
+            with self.lock:
+                status = self.environment_status.copy()
             for environment in request_environment_defined(
                 self.etos, self.etos.config.get("context")
             ):
                 if environment["meta"]["id"] in downloaded:
                     continue
                 suite = self._download_sub_suite(environment)
                 if self.error:
+                    self.logger.warning("Stop collecting sub suites due to error: %r", self.error)
                     break
                 downloaded.append(environment["meta"]["id"])
                 if suite is None:  # Not a real sub suite environment defined event.
@@ -185,17 +192,24 @@ def collect_environments(self):
                     self.__environments.setdefault(suite["test_suite_started_id"], [])
                     self.__environments[suite["test_suite_started_id"]].append(suite)
             if status["status"] == "FAILURE":
+                self.logger.warning(
+                    "Stop collecting sub suites due to status: %r, reason %r",
+                    status["status"],
+                    status.get("error"),
+                )
                 break
             if status["status"] != "PENDING" and len(downloaded) >= len(self.test_suite):
                 # We must have found at least one environment for each test suite.
                 self.environment_provider_done = True
+                self.logger.debug("All sub suites have been collected")
                 break
             time.sleep(5)
         if status["status"] == "FAILURE":
             with self.lock:
                 self.error = EnvironmentProviderException(
                     status["error"], self.etos.config.get("task_id")
                 )
+                self.logger.warning("Sub suite collection exited with an error: %r", self.error)
 
     def _download_sub_suite(self, environment):
         """Download a sub suite from an EnvironmentDefined event.
@@ -236,6 +250,9 @@ def environments(self, test_suite_started_id):
                 with self.lock:
                     self.__environments[test_suite_started_id].remove(environment)
                 found += 1
+                self.logger.debug(
+                    "Sub suite environment received: %r", environment.get("test_suite_started_id")
+                )
                 yield environment
             if finished and found > 0:
                 break

src/etos_suite_runner/lib/suite.py

@@ -186,6 +186,7 @@ def start(self):
         threads = []
         assigner = None
         try:
+            self.logger.info("Waiting for all sub suite environments")
             for sub_suite_definition in self.sub_suite_definitions:
                 sub_suite = SubSuite(self.etos, sub_suite_definition)
                 with self.lock:
@@ -195,6 +196,7 @@ def start(self):
                 )
                 threads.append(thread)
                 thread.start()
+            self.logger.info("All sub suite environments received and sub suites triggered")
 
             self.logger.info("Assigning test suite started events to sub suites")
             assigner = threading.Thread(target=self._assign_test_suite_started)

tox.ini

@@ -11,7 +11,7 @@ envlist = py3,black,pylint,pydocstyle
 #     -r{toxinidir}/test-requirements.txt
 # commands =
 #     pytest -s --log-format="%(levelname)s: %(message)s" {posargs}
- 
+
 [testenv:black]
 deps =
     black