chore: add logging to tests/functional/conftest.py

JohnVillalovos · JohnVillalovos · commit a1ac9ae63828 · 2022-01-08T16:43:19.000-08:00
I have found trying to debug issues in the functional tests can be
difficult. Especially when trying to figure out failures in the CI
running on Github.

Add logging to `tests/functional/conftest.py` to have a better
understanding of what is happening during a test run which is useful
when trying to troubleshoot issues in the CI.
diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml
@@ -73,7 +73,7 @@ jobs:
       - name: Run tests
         env:
           TOXENV: ${{ matrix.toxenv }}
-        run: tox
+        run: tox -- --override-ini='log_cli=True'
       - name: Upload codecov coverage
         uses: codecov/codecov-action@v2
         with:
diff --git a/pyproject.toml b/pyproject.toml
@@ -90,3 +90,10 @@ disable = [
 
 [tool.pytest.ini_options]
 xfail_strict = true
+
+# If 'log_cli=True' the following apply
+# NOTE: If set 'log_cli_level' to 'DEBUG' will show a log of all of the HTTP requests
+# made in functional tests.
+log_cli_level = "INFO"
+log_cli_format = "%(asctime)s.%(msecs)03d [%(levelname)8s] (%(filename)s:%(funcName)s:L%(lineno)s) %(message)s"
+log_cli_date_format = "%Y-%m-%d %H:%M:%S"
diff --git a/tests/functional/conftest.py b/tests/functional/conftest.py
@@ -1,3 +1,4 @@
+import logging
 import tempfile
 import time
 import uuid
@@ -9,7 +10,7 @@
 import gitlab
 import gitlab.base
 
-SLEEP_INTERVAL = 0.1
+SLEEP_INTERVAL = 0.5
 TIMEOUT = 60  # seconds before timeout will occur
 
 
@@ -21,47 +22,69 @@ def fixture_dir(test_dir):
 def reset_gitlab(gl):
     # previously tools/reset_gitlab.py
     for project in gl.projects.list():
+        logging.info(f"Marking for deletion project: {project.path_with_namespace!r}")
         for deploy_token in project.deploytokens.list():
+            logging.info(
+                f"Marking for deletion token: {deploy_token.username!r} in "
+                f"project: {project.path_with_namespace!r}"
+            )
             deploy_token.delete()
         project.delete()
     for group in gl.groups.list():
+        logging.info(f"Marking for deletion group: {group.full_path!r}")
         for deploy_token in group.deploytokens.list():
+            logging.info(
+                f"Marking for deletion token: {deploy_token.username!r} in "
+                f"group: {group.path_with_namespace!r}"
+            )
             deploy_token.delete()
         group.delete()
     for variable in gl.variables.list():
+        logging.info(f"Marking for deletion variable: {variable.key!r}")
         variable.delete()
     for user in gl.users.list():
         if user.username != "root":
+            logging.info(f"Marking for deletion user: {user.username!r}")
             user.delete(hard_delete=True)
 
     max_iterations = int(TIMEOUT / SLEEP_INTERVAL)
 
     # Ensure everything has been reset
     start_time = time.perf_counter()
 
-    def wait_for_maximum_list_length(
+    def wait_for_list_size(
         rest_manager: gitlab.base.RESTManager, description: str, max_length: int = 0
     ) -> None:
         """Wait for the list() length to be no greater than expected maximum or fail
         test if timeout is exceeded"""
-        for _ in range(max_iterations):
-            if len(rest_manager.list()) <= max_length:
+        logging.info(f"Checking {description!r} has no more than {max_length} items")
+        for count in range(max_iterations):
+            items = rest_manager.list()
+            if len(items) <= max_length:
                 break
+            logging.info(
+                f"Iteration: {count} Waiting for {description!r} items to be deleted: "
+                f"{[x.name for x in items]}"
+            )
             time.sleep(SLEEP_INTERVAL)
-        assert len(rest_manager.list()) <= max_length, (
-            f"Did not delete required items for {description}. "
-            f"Elapsed_time: {time.perf_counter() - start_time}"
+
+        elapsed_time = time.perf_counter() - start_time
+        error_message = (
+            f"More than {max_length} {description!r} items still remaining and timeout "
+            f"({elapsed_time}) exceeded: {[x.name for x in items]}"
         )
+        if len(items) > max_length:
+            logging.error(error_message)
+        assert len(items) <= max_length, error_message
 
-    wait_for_maximum_list_length(rest_manager=gl.projects, description="projects")
-    wait_for_maximum_list_length(rest_manager=gl.groups, description="groups")
-    wait_for_maximum_list_length(rest_manager=gl.variables, description="variables")
-    wait_for_maximum_list_length(
-        rest_manager=gl.users, description="users", max_length=1
-    )
+    wait_for_list_size(rest_manager=gl.projects, description="projects")
+    wait_for_list_size(rest_manager=gl.groups, description="groups")
+    wait_for_list_size(rest_manager=gl.variables, description="variables")
+    wait_for_list_size(rest_manager=gl.users, description="users", max_length=1)
 
 
 def set_token(container, fixture_dir):
+    logging.info("Creating API token.")
     set_token_rb = fixture_dir / "set_token.rb"
 
     with open(set_token_rb, "r") as f:
@@ -76,6 +99,7 @@ def set_token(container, fixture_dir):
         set_token_command,
     ]
     output = check_output(rails_command).decode().strip()
+    logging.info("Finished creating API token.")
 
     return output
 
@@ -85,7 +109,7 @@ def pytest_report_collectionfinish(config, startdir, items):
         "",
         "Starting GitLab container.",
         "Waiting for GitLab to reconfigure.",
-        "This may take a few minutes.",
+        "This will take a few minutes.",
     ]
 
 
@@ -129,6 +153,7 @@ def check_is_alive():
     """
 
     def _check(container):
+        logging.info("Checking if GitLab container is up...")
         logs = ["docker", "logs", container]
         return "gitlab Reconfigured!" in check_output(logs).decode()
 
@@ -144,7 +169,7 @@ def wait_for_sidekiq(gl):
     """
 
     def _wait(timeout=30, step=0.5):
-        for _ in range(timeout):
+        for count in range(timeout):
             time.sleep(step)
             busy = False
             processes = gl.sidekiq.process_metrics()["processes"]
@@ -153,6 +178,7 @@ def _wait(timeout=30, step=0.5):
                     busy = True
             if not busy:
                 return True
+            logging.info(f"sidekiq busy {count} of {timeout}")
         return False
 
     return _wait
@@ -163,9 +189,11 @@ def gitlab_config(check_is_alive, docker_ip, docker_services, temp_dir, fixture_
     config_file = temp_dir / "python-gitlab.cfg"
     port = docker_services.port_for("gitlab", 80)
 
+    logging.info("Waiting for GitLab container to become ready.")
     docker_services.wait_until_responsive(
-        timeout=200, pause=5, check=lambda: check_is_alive("gitlab-test")
+        timeout=200, pause=10, check=lambda: check_is_alive("gitlab-test")
     )
+    logging.info("GitLab container is now ready.")
 
     token = set_token("gitlab-test", fixture_dir=fixture_dir)
 
@@ -188,7 +216,9 @@ def gitlab_config(check_is_alive, docker_ip, docker_services, temp_dir, fixture_
 def gl(gitlab_config):
     """Helper instance to make fixtures and asserts directly via the API."""
 
+    logging.info("Instantiating python-gitlab gitlab.Gitlab instance")
     instance = gitlab.Gitlab.from_config("local", [gitlab_config])
+
     reset_gitlab(instance)
 
     return instance
diff --git a/tox.ini b/tox.ini
@@ -4,7 +4,7 @@ skipsdist = True
 envlist = py310,py39,py38,py37,pep8,black,twine-check,mypy,isort
 
 [testenv]
-passenv = GITLAB_IMAGE GITLAB_TAG
+passenv = GITLAB_IMAGE GITLAB_TAG PY_COLORS NO_COLOR FORCE_COLOR
 setenv = VIRTUAL_ENV={envdir}
 whitelist_externals = true
 usedevelop = True
