From a1ac9ae63828ca2012289817410d420da066d8df Mon Sep 17 00:00:00 2001 From: "John L. Villalovos" Date: Sat, 8 Jan 2022 16:43:19 -0800 Subject: [PATCH] chore: add logging to `tests/functional/conftest.py` 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. --- .github/workflows/test.yml | 2 +- pyproject.toml | 7 ++++ tests/functional/conftest.py | 62 ++++++++++++++++++++++++++---------- tox.ini | 2 +- 4 files changed, 55 insertions(+), 18 deletions(-) diff --git a/.github/workflows/test.yml b/.github/workflows/test.yml index cc012bd26..a4b495a10 100644 --- 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 index bc0530aee..8c29140d5 100644 --- 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 index 7c4e58480..8b25c6c0e 100644 --- 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,17 +22,29 @@ 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) @@ -39,29 +52,39 @@ def reset_gitlab(gl): # 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 index 1606471c8..4d502be8e 100644 --- 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