From 257b2b755d92cafcbeb895a9cfa1389c22251637 Mon Sep 17 00:00:00 2001 From: Ming Date: Thu, 3 Apr 2025 14:14:21 +1100 Subject: [PATCH] TE-3588: more logs and defensive mechanism for test collection --- .editorconfig | 21 ++++++++++ .gitignore | 2 + src/buildkite_test_collector/collector/api.py | 19 +++++----- .../collector/constants.py | 2 +- .../pytest_plugin/__init__.py | 3 -- .../pytest_plugin/buildkite_plugin.py | 32 +++++++++++++++- .../pytest_plugin/logger.py | 38 +++++++++++++++++++ .../collector/test_api.py | 4 +- 8 files changed, 104 insertions(+), 17 deletions(-) create mode 100644 .editorconfig create mode 100644 src/buildkite_test_collector/pytest_plugin/logger.py diff --git a/.editorconfig b/.editorconfig new file mode 100644 index 0000000..1008e05 --- /dev/null +++ b/.editorconfig @@ -0,0 +1,21 @@ +# EditorConfig is awesome: https://EditorConfig.org + +# top-most EditorConfig file +root = true + +# Unix-style newlines with a newline ending every file +[*] +end_of_line = lf +insert_final_newline = true +charset = utf-8 +trim_trailing_whitespace = true + +# Python files +[*.py] +indent_style = space +indent_size = 4 + +# YAML files +[*.{yml,yaml}] +indent_style = space +indent_size = 2 diff --git a/.gitignore b/.gitignore index 1ef15ac..0adf074 100644 --- a/.gitignore +++ b/.gitignore @@ -14,3 +14,5 @@ __pycache__ .env* .direnv/* + +build diff --git a/src/buildkite_test_collector/collector/api.py b/src/buildkite_test_collector/collector/api.py index 47e5085..1c49b0b 100644 --- a/src/buildkite_test_collector/collector/api.py +++ b/src/buildkite_test_collector/collector/api.py @@ -2,22 +2,21 @@ from typing import Optional from os import environ -from sys import stderr import traceback from requests import post, Response from requests.exceptions import InvalidHeader, HTTPError from .payload import Payload +from ..pytest_plugin.logger import logger def submit(payload: Payload, batch_size=100) -> Optional[Response]: """Submit a payload to the API""" token = environ.get("BUILDKITE_ANALYTICS_TOKEN") - debug = environ.get("BUILDKITE_ANALYTICS_DEBUG_ENABLED") api_url = environ.get("BUILDKITE_ANALYTICS_API_URL", "https://analytics-api.buildkite.com/v1") response = None - if debug and not token: - print("Warning: No `BUILDKITE_ANALYTICS_TOKEN` environment variable present", file=stderr) + if not token: + logger.warning("No `BUILDKITE_ANALYTICS_TOKEN` environment variable present") if token: try: @@ -32,12 +31,12 @@ def submit(payload: Payload, batch_size=100) -> Optional[Response]: response.raise_for_status() return response except InvalidHeader as error: - print("Warning: Invalid `BUILDKITE_ANALYTICS_TOKEN` environment variable", file=stderr) - print(error, file=stderr) + logger.warning("Invalid `BUILDKITE_ANALYTICS_TOKEN` environment variable") + logger.warning(error) except HTTPError as err: - print("Warning: Failed to uploads test results to buildkite", file=stderr) - print(err, file=stderr) - except Exception: # pylint: disable=broad-except + logger.warning("Failed to uploads test results to buildkite") + logger.warning(err) + except Exception: # pylint: disable=broad-except error_message = traceback.format_exc() - print(error_message, file=stderr) + logger.warning(error_message) return None diff --git a/src/buildkite_test_collector/collector/constants.py b/src/buildkite_test_collector/collector/constants.py index ba731e3..bd3446b 100644 --- a/src/buildkite_test_collector/collector/constants.py +++ b/src/buildkite_test_collector/collector/constants.py @@ -3,4 +3,4 @@ """This module defines collector-level constants.""" COLLECTOR_NAME='buildkite-test-collector' -VERSION='1.0.0' +VERSION='1.0.1rc1' diff --git a/src/buildkite_test_collector/pytest_plugin/__init__.py b/src/buildkite_test_collector/pytest_plugin/__init__.py index 5df87ff..8f2e1ed 100644 --- a/src/buildkite_test_collector/pytest_plugin/__init__.py +++ b/src/buildkite_test_collector/pytest_plugin/__init__.py @@ -1,9 +1,6 @@ # pylint: disable=line-too-long """Buildkite test collector for Pytest.""" -from logging import warning -from os import environ - import pytest from ..collector.payload import Payload diff --git a/src/buildkite_test_collector/pytest_plugin/buildkite_plugin.py b/src/buildkite_test_collector/pytest_plugin/buildkite_plugin.py index 3e11624..ec3c5da 100644 --- a/src/buildkite_test_collector/pytest_plugin/buildkite_plugin.py +++ b/src/buildkite_test_collector/pytest_plugin/buildkite_plugin.py @@ -3,6 +3,7 @@ from uuid import uuid4 from ..collector.payload import TestData +from .logger import logger class BuildkitePlugin: """Buildkite test collector plugin for Pytest""" @@ -14,6 +15,7 @@ def __init__(self, payload): def pytest_runtest_logstart(self, nodeid, location): """pytest_runtest_logstart hook callback""" + logger.debug('Enter pytest_runtest_logstart for %s', nodeid) if not self.payload.is_started(): self.payload = self.payload.started() @@ -41,6 +43,7 @@ def pytest_runtest_logreport(self, report): nodeid = report.nodeid test_data = self.in_flight.get(nodeid) + logger.debug('Enter pytest_runtest_logreport for %s', nodeid) if test_data: if report.passed: @@ -59,6 +62,7 @@ def pytest_runtest_logreport(self, report): def pytest_runtest_teardown(self, item): """pytest_runtest_hook hook callback to mark test as finished and add it to the payload""" + logger.debug('Enter pytest_runtest_teardown for %s', item.nodeid) test_data = self.in_flight.get(item.nodeid) if test_data: @@ -68,8 +72,34 @@ def pytest_runtest_teardown(self, item): for tag in tags: test_data = test_data.tag_execution(tag.args[0], tag.args[1]) - del self.in_flight[item.nodeid] + self.in_flight[item.nodeid] = test_data + + self.finalize_test(item.nodeid) + else: + logger.warning('Unexpected missing test_data during pytest_runtest_teardown') + + # Strictly speaking, we do not need this hook. + # But in pytest it's hard to predict how plugins interfere each other. + # So let's be defensive here. + def pytest_runtest_logfinish(self, nodeid, location): # pylint: disable=unused-argument + """pytest_runtest_logfinish hook always runs in the very end""" + logger.debug('Enter pytest_runtest_logfinish for %s', nodeid) + if self.finalize_test(nodeid): + logger.warning( + 'Detected possible interference in pytest_runtest_teardown hook. ' + 'Falling back to pytest_runtest_logfinish, but note that test tags ' + 'will not be uploaded.' + ) + + + def finalize_test(self, nodeid): + """ Attempting to move test data for a nodeid to payload area for upload """ + test_data = self.in_flight.get(nodeid) + if test_data: + del self.in_flight[nodeid] self.payload = self.payload.push_test_data(test_data) + return True + return False def save_payload_as_json(self, path): """ Save payload into a json file """ diff --git a/src/buildkite_test_collector/pytest_plugin/logger.py b/src/buildkite_test_collector/pytest_plugin/logger.py new file mode 100644 index 0000000..694b989 --- /dev/null +++ b/src/buildkite_test_collector/pytest_plugin/logger.py @@ -0,0 +1,38 @@ +"""A plugin internal logger, use DEBUG=1 env var to turn on all debug logs""" +import os +import logging + +def setup_logger(name=__name__): + """ + Configure and return a logger with the specified name. + + The logger's level is set based on the DEBUG environment variable. + If DEBUG=1, the level is set to DEBUG, otherwise it's set to INFO. + + Args: + name (str): The name for the logger. Defaults to the current module name. + + Returns: + logging.Logger: A configured logger instance. + """ + l = logging.getLogger(name) + + # Set level based on DEBUG env var + l.setLevel(logging.DEBUG if os.getenv("DEBUG") == "1" else logging.INFO) + + # Add handler only if none exists (prevents duplicate logs) + if not l.handlers: + handler = logging.StreamHandler() # Log to console + formatter = logging.Formatter( + "%(name)s - %(levelname)s - %(message)s" + ) + handler.setFormatter(formatter) + l.addHandler(handler) + + # Optional: Stop propagation to root logger + l.propagate = False + + return l + +# Example default logger (optional) +logger = setup_logger("buildkite-test-collector") diff --git a/tests/buildkite_test_collector/collector/test_api.py b/tests/buildkite_test_collector/collector/test_api.py index 4db993d..57e188f 100644 --- a/tests/buildkite_test_collector/collector/test_api.py +++ b/tests/buildkite_test_collector/collector/test_api.py @@ -42,7 +42,7 @@ def test_submit_with_payload_timeout_captures_ConnectTimeout_error(capfd, succes result = submit(payload) captured = capfd.readouterr() - assert captured.err.startswith("Traceback") + assert captured.err.startswith("buildkite-test-collector - WARNING -") assert "ConnectTimeout" in captured.err @responses.activate @@ -62,7 +62,7 @@ def test_submit_with_payload_timeout_captures_ReadTimeout_error(capfd, successfu result = submit(payload) captured = capfd.readouterr() - assert captured.err.startswith("Traceback") + assert captured.err.startswith("buildkite-test-collector - WARNING -") assert "ReadTimeout" in captured.err @responses.activate