diff --git a/.agents/rules/testing-python.md b/.agents/rules/testing-python.md index 71b02a1db3d..86b873c2187 100644 --- a/.agents/rules/testing-python.md +++ b/.agents/rules/testing-python.md @@ -63,6 +63,10 @@ Skip tests that only exercise library behavior: plain `Enum` value/round-trip ch If the logic needs only in-memory inputs (a `SchemaBranch`, a dataclass, a pure function), write a unit test without DB fixtures — don't default to a component test because a neighbor uses one. Use the database or containers only when behavior genuinely depends on them. +## Don't leak process-global state + +Every test in an xdist worker shares one interpreter. Change `logging` levels/handlers/filters, `structlog` config, module-level registries/singletons, `sys.path`/`sys.modules` or env vars only through a save/restore fixture (change it, `yield`, restore it), or `monkeypatch` where it applies. Never call an application startup routine such as `infrahub.log.configure_logging` from a test — it owns the whole process and undoes nothing, so it reconfigures every later test in the worker. Install only the piece under test and remove it after the `yield`. See `dev/guidelines/backend/testing.md` §"Leave process-global state as you found it". + ## Test file placement Test files mirror source structure: `infrahub/core/node.py` → `tests/unit/core/test_node.py` diff --git a/backend/infrahub/log.py b/backend/infrahub/log.py index e93a54053ab..563d7e1d8a9 100644 --- a/backend/infrahub/log.py +++ b/backend/infrahub/log.py @@ -59,6 +59,22 @@ def filter(self, record: logging.LogRecord) -> bool: return type(exception) not in self._suppressed_types +def install_traceback_suppression_filter() -> TracebackSuppressionFilter: + """Install the traceback suppression filter on the Prefect run loggers and return it. + + Prefect ships flow/task run logs to its API; drop tracebacks for failures that are reported as a + clean classified reason rather than a crash to debug. The filter reads the shared registry that + each expected-failure type opts into via suppress_traceback_in_logs. + + The installed filter is returned so a caller that must leave logging state as it found it can + remove it again from every logger in PREFECT_RUN_LOGGERS. + """ + traceback_filter = TracebackSuppressionFilter(_TRACEBACK_SUPPRESSED_TYPES) + for prefect_logger_name in PREFECT_RUN_LOGGERS: + logging.getLogger(prefect_logger_name).addFilter(traceback_filter) + return traceback_filter + + def clear_log_context() -> None: structlog.contextvars.clear_contextvars() @@ -86,13 +102,8 @@ def configure_logging(production: bool, log_level: str) -> None: # the infrahub logger importlib.import_module("prefect.main") - # Prefect ships flow/task run logs to its API; drop tracebacks for failures that - # are reported as a clean classified reason rather than a crash to debug. Installed after the - # prefect.main import above so it survives Prefect's logging reset; reads the shared registry that - # each expected-failure type opts into via suppress_traceback_in_logs. - traceback_filter = TracebackSuppressionFilter(_TRACEBACK_SUPPRESSED_TYPES) - for prefect_logger_name in PREFECT_RUN_LOGGERS: - logging.getLogger(prefect_logger_name).addFilter(traceback_filter) + # Installed after the prefect.main import above so it survives Prefect's logging reset. + install_traceback_suppression_filter() shared_processors: list[Processor] = [ structlog.contextvars.merge_contextvars, diff --git a/backend/tests/component/webhook/test_traceback_suppression.py b/backend/tests/component/webhook/test_traceback_suppression.py index 701708b6590..06fcb850b04 100644 --- a/backend/tests/component/webhook/test_traceback_suppression.py +++ b/backend/tests/component/webhook/test_traceback_suppression.py @@ -1,12 +1,12 @@ from __future__ import annotations import logging +from typing import TYPE_CHECKING import httpx import pytest from prefect import flow, task -from infrahub.log import configure_logging from infrahub.webhook.classifier import ( EXPECTED_DELIVERY_ERRORS, ClassifiedFailure, @@ -14,6 +14,10 @@ WebhookDeliveryError, WebhookFailureClassifier, ) +from tests.helpers.log import traceback_suppression + +if TYPE_CHECKING: + from collections.abc import Generator CLASSIFIED_MESSAGE = "The target responded with HTTP 404." @@ -46,12 +50,14 @@ async def _send_classifying_in_task() -> None: @pytest.fixture -def configured_logging() -> None: - # Register the traceback filter on the Prefect run loggers, as production startup does. - configure_logging(production=False, log_level="DEBUG") +def traceback_suppression_installed() -> Generator[None, None, None]: + with traceback_suppression(): + yield -async def test_classified_failure_logs_no_traceback(configured_logging: None, caplog: pytest.LogCaptureFixture) -> None: +async def test_classified_failure_logs_no_traceback( + traceback_suppression_installed: None, caplog: pytest.LogCaptureFixture +) -> None: with ( caplog.at_level(logging.INFO, logger="prefect.flow_runs"), pytest.raises(WebhookDeliveryError, match=r"^The target responded with HTTP 404\.$"), @@ -66,7 +72,7 @@ async def test_classified_failure_logs_no_traceback(configured_logging: None, ca async def test_classified_failure_from_task_logs_no_traceback( - configured_logging: None, caplog: pytest.LogCaptureFixture + traceback_suppression_installed: None, caplog: pytest.LogCaptureFixture ) -> None: # The transport error is caught and classified inside the task, so the failure the engine records # for the task run is a delivery error whose traceback is dropped — not the raw transport stacktrace. @@ -84,7 +90,7 @@ async def test_classified_failure_from_task_logs_no_traceback( async def test_unclassified_failure_logs_a_traceback( - configured_logging: None, caplog: pytest.LogCaptureFixture + traceback_suppression_installed: None, caplog: pytest.LogCaptureFixture ) -> None: with ( caplog.at_level(logging.INFO, logger="prefect.flow_runs"), diff --git a/backend/tests/helpers/log.py b/backend/tests/helpers/log.py new file mode 100644 index 00000000000..448e894d30f --- /dev/null +++ b/backend/tests/helpers/log.py @@ -0,0 +1,25 @@ +"""Install the infrahub.log traceback suppression filter for a test, then remove it again.""" + +from __future__ import annotations + +import logging +from contextlib import contextmanager +from typing import TYPE_CHECKING + +from infrahub.log import PREFECT_RUN_LOGGERS, install_traceback_suppression_filter + +if TYPE_CHECKING: + from collections.abc import Iterator + + from infrahub.log import TracebackSuppressionFilter + + +@contextmanager +def traceback_suppression() -> Iterator[TracebackSuppressionFilter]: + """Register the traceback filter on the Prefect run loggers, as production startup does, then remove it.""" + traceback_filter = install_traceback_suppression_filter() + try: + yield traceback_filter + finally: + for prefect_logger_name in PREFECT_RUN_LOGGERS: + logging.getLogger(prefect_logger_name).removeFilter(traceback_filter) diff --git a/backend/tests/unit/test_log.py b/backend/tests/unit/test_log.py index cbe2ad9663b..a01c74b052e 100644 --- a/backend/tests/unit/test_log.py +++ b/backend/tests/unit/test_log.py @@ -1,9 +1,19 @@ from __future__ import annotations import logging +from typing import TYPE_CHECKING -from infrahub.log import _TRACEBACK_SUPPRESSED_TYPES, TracebackSuppressionFilter, suppress_traceback_in_logs +from infrahub.log import ( + _TRACEBACK_SUPPRESSED_TYPES, + PREFECT_RUN_LOGGERS, + TracebackSuppressionFilter, + suppress_traceback_in_logs, +) from infrahub.webhook.classifier import ClassifiedFailure, StatusClass, WebhookDeliveryError +from tests.helpers.log import traceback_suppression + +if TYPE_CHECKING: + from collections.abc import Sequence def _record(exception: BaseException | None) -> logging.LogRecord: @@ -42,3 +52,33 @@ class _ExpectedFailureError(Exception): ... # The production filter is wired to this shared registry, so a decorated type is suppressed. assert TracebackSuppressionFilter(_TRACEBACK_SUPPRESSED_TYPES).filter(_record(_ExpectedFailureError())) is False + + +def test_startup_installs_the_filter_on_the_prefect_run_loggers() -> None: + """Importing infrahub.log configures logging for the process, which is what installs the filter.""" + installed_on = [ + name + for name in PREFECT_RUN_LOGGERS + if any(isinstance(log_filter, TracebackSuppressionFilter) for log_filter in logging.getLogger(name).filters) + ] + assert installed_on == list(PREFECT_RUN_LOGGERS) + + +def _run_logger_filters() -> dict[str, Sequence[object]]: + # Logger.filters is a union of filter forms; the identity of what is attached is all that matters here. + return {name: list(logging.getLogger(name).filters) for name in PREFECT_RUN_LOGGERS} + + +def test_traceback_suppression_leaves_logging_state_unchanged() -> None: + """The suppression context must hand logging back exactly as it found it.""" + root_logger = logging.getLogger() + level_before, filters_before = root_logger.level, _run_logger_filters() + + with traceback_suppression() as traceback_filter: + assert _run_logger_filters() == { + name: [*filters_before[name], traceback_filter] for name in PREFECT_RUN_LOGGERS + } + assert root_logger.level == level_before + + assert _run_logger_filters() == filters_before + assert root_logger.level == level_before diff --git a/dev/guidelines/backend/testing.md b/dev/guidelines/backend/testing.md index 74ce53aba82..a2e73271146 100644 --- a/dev/guidelines/backend/testing.md +++ b/dev/guidelines/backend/testing.md @@ -111,6 +111,33 @@ The module provides individual node/generic schemas (`CAR`, `DEVICE`, `TAG`, `PE `config.SETTINGS` is populated from `INFRAHUB_*` environment variables at process start, so values exported in the developer's shell leak into the test process. Any test whose behavior depends on a settings field must pin it in a save/restore fixture (set the value, `yield`, restore the original) — see `import_every_remote_branch` in `backend/tests/integration/git/conftest.py`. Never assume a field holds its default. +## Leave process-global state as you found it + +Under `pytest-xdist` every test in a worker shares one interpreter, so whatever a test changes outside +its own fixtures stays changed for every test that follows it there. Touch global state only through a +save/restore fixture (change it, `yield`, restore the original). Pinning a setting, above, is one case +of that rule; it also covers: + +- the `logging` module — root and per-logger levels, handlers, filters +- `structlog` configuration +- module-level registries, caches and singletons +- environment variables (prefer `monkeypatch.setenv`, which restores on teardown) +- `sys.path`, `sys.modules`, warning filters + +**Never call an application startup routine from a test.** `infrahub.log.configure_logging` is the +example to learn from: it runs once at process start and owns the process when it does — setting the +root log level, replacing the root handler and reconfiguring structlog — so, being startup code, it has +no counterpart that undoes any of that. Called from a fixture it silently reconfigures every later test +in the worker. Install only the piece the test needs, extracting it from the startup routine when it is +not already reusable, and undo it after the `yield` — see `traceback_suppression` in +`backend/tests/helpers/log.py`, which the webhook suppression tests use to install the traceback +suppression filter alone rather than calling `configure_logging`. + +Such a leak is invisible locally and expensive in CI. A root logger left at `DEBUG` overrides the +`WARNING` level `pytest_configure` pins, and the Neo4j driver then logs a line per Bolt message for +every test that follows in that worker: one job produced 185k lines of driver output and pushed three +unrelated tests past their 300s timeout. + ## Dataclass Test Case Pattern For parametrized tests with multiple scenarios, use dataclasses to define test cases. This pattern provides type safety, readable test IDs, and clear separation between test data and test logic.