diff --git a/.github/workflows/build-worker.yml b/.github/workflows/build-worker.yml index 466fab0..5fc2262 100644 --- a/.github/workflows/build-worker.yml +++ b/.github/workflows/build-worker.yml @@ -8,10 +8,10 @@ on: paths: - 'Dockerfile.worker' - 'core/**' - - 'algorithms/**' + - 'domain/**' + - 'adapters/**' - 'shared/**' - 'worker/**' - - 'locales/**' - 'requirements/base.txt' - 'requirements/worker.txt' - '.dockerignore' @@ -21,10 +21,10 @@ on: paths: - 'Dockerfile.worker' - 'core/**' - - 'algorithms/**' + - 'domain/**' + - 'adapters/**' - 'shared/**' - 'worker/**' - - 'locales/**' - 'requirements/base.txt' - 'requirements/worker.txt' - '.dockerignore' diff --git a/adapters/renderers/pdf_form.py b/adapters/renderers/pdf_form.py index 831d978..364977b 100644 --- a/adapters/renderers/pdf_form.py +++ b/adapters/renderers/pdf_form.py @@ -12,9 +12,15 @@ template, so it lives in the bundle. A value may also map to a **list** of field names, for the comb boxes these forms -use to spell a code out one character per box (an 18-digit EAN across 16 boxes, -say). The string is then spread left-aligned across them and any leftover box is -cleared. +use to spell a code out one character per box (the 16 digits of an EAN that +follow a form's pre-printed "5 4", say). The string is then spread left-aligned +across them and any leftover box is cleared. + +A value LONGER than the field list is truncated from the right, silently. So a +manifest that maps a comb field must also declare its length in +``required_fields``: the JSON Schema gate in the orchestrator runs first and +turns an over-long value into a permanent VALIDATION_ERROR rather than a +plausible-looking, wrong document. Checkbox fields are detected from the PDF's own ``/FT`` and export states — a truthy value selects the non-``/Off`` state, a falsy one selects ``/Off`` — so a diff --git a/core/tracing.py b/core/tracing.py index f2a5aeb..9ca62c5 100644 --- a/core/tracing.py +++ b/core/tracing.py @@ -7,7 +7,10 @@ from __future__ import annotations +import atexit import logging +import os +import uuid from opentelemetry import metrics from opentelemetry.exporter.otlp.proto.http._log_exporter import OTLPLogExporter @@ -23,7 +26,15 @@ logger = logging.getLogger(__name__) -_EXPORTER_TIMEOUT_MS = 5000 +# SECONDS. The OTLP HTTP exporters take `timeout` in seconds - the SDK's own +# DEFAULT_TIMEOUT is 10 and it is used as `deadline_sec = time() + self._timeout` +# - while `MeterProvider.shutdown` and every MetricReader take MILLISECONDS. +# Handing one constant named `_MS` to both, which this template did, gave the +# exporters an 83-MINUTE HTTP timeout: a collector that accepts a connection and +# then hangs holds the export thread for the rest of the afternoon, and every +# batch queued behind it with it. +_EXPORTER_TIMEOUT_SECONDS = 5 +_EXPORTER_TIMEOUT_MS = _EXPORTER_TIMEOUT_SECONDS * 1000 _METRIC_EXPORT_INTERVAL_MS = 15000 @@ -32,14 +43,47 @@ def setup_tracer_provider() -> None: if settings.ENV in (Environment.LOCAL, Environment.TEST): return - resource = Resource.create({"service.name": "document-generation", "env": settings.ENV}) + # AND when there is nowhere to send it, whatever the ENV. + # + # The LOGGING_* triple is enforced in `core/config.py` only under PRODUCTION, + # while this function exports for anything that is not LOCAL - and the + # staging template ships the URLs BLANK. A blank endpoint is not inert: the + # OTLP exporter resolves it to its DEFAULT_ENDPOINT, `http://localhost:4318/`, + # so every container quietly starts a 15-second export loop and an OTLP + # root-log handler aimed at a port nothing is listening on. + # + # Verified against the pinned SDK, not inferred. + if not settings.LOGGING_METRICS_URL or not settings.LOGGING_LOGS_URL: + logger.warning( + "telemetry not configured - LOGGING_LOGS_URL/LOGGING_METRICS_URL are " + "blank, so no exporter is started (env=%s)", + settings.ENV, + ) + return + + resource = Resource.create( + { + "service.name": "document-generation", + "env": settings.ENV, + # `component`-free, unlike live-data: these services have one + # container each today. What this separates is REPLICAS - two + # processes of the same deployment otherwise emit byte-identical + # stream identities and the backend merges their cumulative + # histograms into nonsense. + # + # The container id, which Docker puts in HOSTNAME. The uuid fallback + # is for a bare process; it changes on restart, which is what + # `service.instance.id` is defined to do. + "service.instance.id": os.getenv("HOSTNAME") or str(uuid.uuid4()), + } + ) headers = {"Authorization": f"Bearer {settings.LOGGING_TOKEN}"} # --- Logs --- log_exporter = OTLPLogExporter( endpoint=settings.LOGGING_LOGS_URL, headers=headers, - timeout=_EXPORTER_TIMEOUT_MS, + timeout=_EXPORTER_TIMEOUT_SECONDS, ) log_provider = LoggerProvider(resource=resource) log_provider.add_log_record_processor(BatchLogRecordProcessor(log_exporter)) @@ -47,11 +91,14 @@ def setup_tracer_provider() -> None: handler.addFilter(RequestIdFilter()) logging.getLogger().addHandler(handler) + global _log_handler + _log_handler = handler + # --- Metrics --- metric_exporter = OTLPMetricExporter( endpoint=settings.LOGGING_METRICS_URL, headers=headers, - timeout=_EXPORTER_TIMEOUT_MS, + timeout=_EXPORTER_TIMEOUT_SECONDS, ) metric_reader = PeriodicExportingMetricReader( metric_exporter, export_interval_millis=_METRIC_EXPORT_INTERVAL_MS @@ -59,4 +106,82 @@ def setup_tracer_provider() -> None: meter_provider = MeterProvider(resource=resource, metric_readers=[metric_reader]) metrics.set_meter_provider(meter_provider) + global _meter_provider, _log_provider + _meter_provider = meter_provider + _log_provider = log_provider + + # AFTER the SDK's own, so LIFO puts this one first. See + # `shutdown_telemetry`: the SDK flushes too, on a 30-second budget + # against Docker's 10-second stop grace. + atexit.register(shutdown_telemetry) + logger.info("OpenTelemetry telemetry configured (logs, metrics)") + + +# Kept so `shutdown_telemetry` can reach them. `metrics.get_meter_provider()` +# returns the API-level object, which has no `shutdown`. +_meter_provider: MeterProvider | None = None +_log_provider: LoggerProvider | None = None +# Held so the flush can DETACH it - see `shutdown_telemetry`. +_log_handler: logging.Handler | None = None + + +def shutdown_telemetry(timeout_millis: int = _EXPORTER_TIMEOUT_MS) -> None: + """Flush the last batch, WITHIN A BUDGET DOCKER WILL ALLOW. + + --------------------------------------------------------------------------- + THE SDK ALREADY FLUSHES AT EXIT. THIS IS ABOUT THE TIMEOUT, NOT THE FLUSH. + + `MeterProvider.__init__` takes `shutdown_on_exit=True` by default and + registers `atexit(self.shutdown)`, and that handler really does export - one + final collect happens even with the interval nowhere near due. + + What it does NOT do is bound itself usefully. `atexit` calls `shutdown()` + with no arguments, so the budget is the SDK's default of **30 seconds**, + while Docker sends SIGKILL **10 seconds** after SIGTERM. Against an + unreachable or slow collector - which is exactly when a shutdown blocks - the + container is killed mid-flush: the data is lost anyway AND every deploy takes + the full grace period. + + Registered with `atexit` below rather than called from each entrypoint. + atexit is LIFO and the SDK registers its handler inside `MeterProvider(...)`, + so this one runs FIRST, with this budget, and the SDK's becomes a no-op + ("shutdown can only be called once"). It therefore covers every entrypoint, + including any added later. Nothing helps against SIGKILL itself. + --------------------------------------------------------------------------- + + Safe when no provider was installed, and safe to call twice. + """ + # LOGS FIRST, metrics second: a caller's last log line is written before this + # runs. `BatchLogRecordProcessor` batches on its own timer exactly like the + # metric reader, so an unflushed log provider drops the final lines that + # distinguish a clean stop from a kill. + # + # `force_flush` for logs and `shutdown` for metrics, because those are the + # two that take a BUDGET: `LoggerProvider.shutdown()` has no timeout + # parameter at all and would run unbounded. + global _log_handler + if _log_provider is not None: + try: + _log_provider.force_flush(timeout_millis=timeout_millis) + # AND DETACH IT. `logging.shutdown` is registered with atexit by the + # logging module at import, so LIFO runs it LAST - after the + # interpreter has begun tearing down, where `LoggingHandler.flush()` + # spawning a thread raises `RuntimeError: can't create new thread at + # interpreter shutdown`. Every container printed that traceback on + # exit. Once the batch is flushed there is nothing left to lose by + # removing the handler, and nothing left for `logging.shutdown` to do. + if _log_handler is not None: + logging.getLogger().removeHandler(_log_handler) + _log_handler = None + except Exception: + # A collector that is down or slow must not stop a container from + # exiting. The process is on its way out; there is nowhere to report + # to, and the next line would go to the handler being flushed. + logger.warning("flushing logs on shutdown failed", exc_info=True) + + if _meter_provider is not None: + try: + _meter_provider.shutdown(timeout_millis=timeout_millis) + except Exception: + logger.warning("flushing metrics on shutdown failed", exc_info=True) diff --git a/tests/test_build_workflow_paths.py b/tests/test_build_workflow_paths.py new file mode 100644 index 0000000..9fa6ca8 --- /dev/null +++ b/tests/test_build_workflow_paths.py @@ -0,0 +1,178 @@ +"""A change to anything the worker image is built from must build the image. + +--------------------------------------------------------------------------- +WHY THIS EXISTS. + +`.github/workflows/build-worker.yml` runs only when a changed file matches its +`paths:` filter, and that filter was copied from the service template: +`core/`, `algorithms/`, `shared/`, `worker/`, `locales/`. This service has no +`algorithms/` and no `locales/` - and the template has no `domain/` and no +`adapters/`, which is where everything this service actually does lives: the +orchestrator, the validator and every renderer. + +So a fix confined to a renderer built nothing on its pull request and +published nothing on merge, and production went on pulling the previous +`:main-worker` with every check green. The `pdf_form.py` fix that exposed it +only shipped because an unrelated `core/tracing.py` change rode along. +--------------------------------------------------------------------------- + +The rule pinned here: every `COPY` source in `Dockerfile.worker` appears in +BOTH trigger lists - as `/**` for a directory, verbatim for a file. + +PyYAML is not a dependency, so both files are read as text. The readers are +deliberately narrow and refuse what they do not recognise: a workflow they +cannot read must fail this test, not satisfy it with an empty list. +""" + +from __future__ import annotations + +import re +from pathlib import Path + +import pytest + +SERVICE_ROOT = Path(__file__).resolve().parents[1] +DOCKERFILE = SERVICE_ROOT / "Dockerfile.worker" +WORKFLOW = SERVICE_ROOT / ".github" / "workflows" / "build-worker.yml" + +TRIGGERS = ["push", "pull_request"] + +# They change the image without being COPY sources. +ALSO_BUILD_INPUTS = ["Dockerfile.worker", ".dockerignore", ".github/workflows/build-worker.yml"] + +# `- 'x'`, `- "x"` or `- x`, with an optional trailing comment. +_LIST_ITEM = re.compile(r"""-\s+(?:'([^']+)'|"([^"]+)"|([^\s'"#][^#]*?))\s*(?:#.*)?""") + + +class _UnreadableError(Exception): + """A file these readers do not understand. Never an empty result.""" + + +def _copy_sources(dockerfile: str) -> list[str]: + """Every COPY source taken from the build context, in file order.""" + sources: list[str] = [] + for line in re.sub(r"\\\r?\n", " ", dockerfile).splitlines(): + fields = line.split() + if not fields or fields[0].upper() != "COPY": + continue + # From another stage, not from the build context. `--chown=` and the + # other flags do not change where the files come from. + if any(field.startswith("--from") for field in fields): + continue + arguments = [field for field in fields[1:] if not field.startswith("--")] + if len(arguments) < 2 or arguments[0].startswith("["): + raise _UnreadableError(f"cannot read this COPY: {line.strip()!r}") + sources.extend(arguments[:-1]) + return sources + + +def _filter_entry(source: str) -> str: + """The `paths:` entry that a change under `source` has to match.""" + path = source.removeprefix("./").rstrip("/") + if source.endswith("/") or (SERVICE_ROOT / path).is_dir(): + return f"{path}/**" + return path + + +def _indent(line: str) -> int: + return len(line) - len(line.lstrip(" ")) + + +def _children(lines: list[str], key: str) -> list[str]: + """The lines nested under `key:`, which must be a direct child of `lines`.""" + lines = [line for line in lines if line.strip() and not line.lstrip().startswith("#")] + if not lines: + raise _UnreadableError(f"nothing to look for `{key}:` in") + level = min(_indent(line) for line in lines) + heads = [ + index + for index, line in enumerate(lines) + if _indent(line) == level and line.strip() == f"{key}:" + ] + if len(heads) != 1: + raise _UnreadableError(f"expected exactly one `{key}:` block, found {len(heads)}") + block: list[str] = [] + for line in lines[heads[0] + 1 :]: + if _indent(line) <= level: + break + block.append(line) + if not block: + raise _UnreadableError(f"`{key}:` has nothing nested under it") + return block + + +def _trigger_paths(workflow: str, event: str) -> list[str]: + """The `on..paths` list, which must be a block list of scalars.""" + block = _children(_children(_children(workflow.splitlines(), "on"), event), "paths") + level = _indent(block[0]) + entries: list[str] = [] + for line in block: + match = _LIST_ITEM.fullmatch(line.strip()) + if _indent(line) != level or match is None: + raise _UnreadableError(f"not a plain list item under {event}.paths: {line!r}") + entries.append(next(group for group in match.groups() if group is not None)) + return entries + + +@pytest.mark.parametrize("event", TRIGGERS) +def test_every_build_input_triggers_the_image_build(event): + paths = _trigger_paths(WORKFLOW.read_text(encoding="utf-8"), event) + assert paths, f"build-worker.yml has an empty {event} paths: list" + sources = _copy_sources(DOCKERFILE.read_text(encoding="utf-8")) + assert sources, "found no COPY from the build context, so this proved nothing" + + required = [*(_filter_entry(source) for source in sources), *ALSO_BUILD_INPUTS] + missing = [entry for entry in dict.fromkeys(required) if entry not in paths] + assert not missing, ( + f"build-worker.yml's {event} paths: filter is missing {missing}. " + "Dockerfile.worker builds the image from them, so a change confined to " + "them builds nothing and production keeps the previous :main-worker image." + ) + + +def test_the_copy_reader(): + """Multi-stage, flags, continuation lines and a lowercase keyword.""" + dockerfile = ( + "FROM python:3.12-slim AS builder\n" + "COPY requirements/base.txt requirements/base.txt\n" + "FROM python:3.12-slim\n" + "COPY --from=builder /install /usr/local\n" + "# COPY ignored/ ignored/\n" + "copy --chown=app:app core/ \\\n" + " domain/ /app/\n" + ) + assert _copy_sources(dockerfile) == ["requirements/base.txt", "core/", "domain/"] + + +def test_the_workflow_reader_reads_block_lists(): + workflow = ( + "on:\n" + " push:\n" + " branches: [main]\n" + " # a comment\n" + " paths:\n" + " - 'core/**'\n" + ' - "worker/**"\n' + " - Dockerfile.worker # trailing\n" + " pull_request:\n" + " paths:\n" + " - 'shared/**'\n" + ) + assert _trigger_paths(workflow, "push") == ["core/**", "worker/**", "Dockerfile.worker"] + assert _trigger_paths(workflow, "pull_request") == ["shared/**"] + + +@pytest.mark.parametrize( + "workflow", + [ + "on:\n push:\n branches: [main]\n", + "on:\n push:\n paths: ['core/**']\n", + "on:\n pull_request:\n paths:\n - 'core/**'\n", + "on:\n push:\n paths:\n core/**\n", + "on:\n push:\n paths:\n - 'core/**'\n - 'worker/**'\n", + ], + ids=["no-paths", "flow-style", "no-such-event", "not-a-list-item", "mixed-indent"], +) +def test_a_workflow_it_cannot_read_is_an_error_not_an_empty_list(workflow): + with pytest.raises(_UnreadableError): + _trigger_paths(workflow, "push") diff --git a/tests/test_tracing_guard.py b/tests/test_tracing_guard.py new file mode 100644 index 0000000..70ac274 --- /dev/null +++ b/tests/test_tracing_guard.py @@ -0,0 +1,280 @@ +"""Telemetry must stay OFF when there is nowhere to send it. + +--------------------------------------------------------------------------- +WHY THIS EXISTS. + +`core/config.py` enforces the `LOGGING_*` triple only under PRODUCTION, while +`setup_tracer_provider` exports for anything that is not LOCAL - and +`.env.staging.exemple` ships the URLs BLANK, in several annexes with a comment +saying that blank "boots cleanly". + +It did boot. A blank endpoint is not inert: the OTLP HTTP exporter resolves it to +its own `DEFAULT_ENDPOINT`, `http://localhost:4318/`, so each container started a +15-second export loop and attached an OTLP handler to the ROOT logger, both aimed +at a port nothing was listening on. + +Nothing could have caught it. The function returns early under LOCAL, so no dev +run reached the code - which is why the same defect was in all eight annexes at +once. `core/tracing.py` is copy-pasted between them. +--------------------------------------------------------------------------- + +THESE TESTS WATCH THE EXPORTER CONSTRUCTORS, NOT THE GLOBAL PROVIDER. + +The obvious assertion - "the meter provider is still the API's no-op proxy" - +is not available here. `metrics.set_meter_provider` is once-only per PROCESS and +several of these repos have a `tests/core/test_metrics.py` that installs a real +`MeterProvider` of its own, so by the time this file runs the global is already +whatever that test left behind. Asserting on it passes or fails by collection +order. + +Patching the two exporter classes is order-independent and says exactly what is +meant: with nowhere to send, nothing is constructed. +""" + +import inspect +import logging +from typing import Any + +import pytest + +import core.tracing as tracing +from core.config import Environment, settings +from core.tracing import setup_tracer_provider + +# Untyped on purpose. `live-data`'s `setup_tracer_provider` takes a `component` +# argument and every other annexe's takes none; this file is copied between them +# verbatim, so a statically-typed call would be a mypy error in seven repos or +# the eighth. The signature decides at runtime. +_SETUP: Any = setup_tracer_provider + + +def _setup() -> None: + if inspect.signature(_SETUP).parameters: + _SETUP("test") + else: + _SETUP() + + +@pytest.fixture +def no_exporter_may_be_built(monkeypatch): + """Both OTLP constructors become landmines. Returns the build log.""" + built: list[str] = [] + + def forbid(name): + def _ctor(*args, **kwargs): + built.append(name) + raise AssertionError(f"{name} was constructed with nowhere to send") + + return _ctor + + monkeypatch.setattr(tracing, "OTLPMetricExporter", forbid("OTLPMetricExporter")) + monkeypatch.setattr(tracing, "OTLPLogExporter", forbid("OTLPLogExporter")) + return built + + +@pytest.fixture +def record_what_is_built(monkeypatch): + """The positive control's counterpart: record instead of raising, and keep + the real provider out of this process.""" + built: list[str] = [] + + class Recorder: + def __init__(self, name): + self._name = name + + def __call__(self, *args, **kwargs): + built.append(self._name) + return object() + + monkeypatch.setattr(tracing, "OTLPMetricExporter", Recorder("metrics")) + monkeypatch.setattr(tracing, "OTLPLogExporter", Recorder("logs")) + monkeypatch.setattr(tracing, "BatchLogRecordProcessor", lambda *a, **k: object()) + monkeypatch.setattr(tracing, "PeriodicExportingMetricReader", lambda *a, **k: object()) + monkeypatch.setattr(tracing, "LoggerProvider", lambda *a, **k: _NullProvider()) + monkeypatch.setattr(tracing, "MeterProvider", lambda *a, **k: object()) + monkeypatch.setattr(tracing.metrics, "set_meter_provider", lambda *a, **k: None) + monkeypatch.setattr(tracing, "LoggingHandler", lambda *a, **k: logging.NullHandler()) + return built + + +class _NullProvider: + def add_log_record_processor(self, *args, **kwargs): + return None + + +@pytest.fixture +def built_with(monkeypatch): + """Every kwargs dict the two OTLP constructors were called with.""" + calls: list[dict] = [] + + class Recorder: + def __call__(self, *args, **kwargs): + calls.append(kwargs) + return object() + + monkeypatch.setattr(tracing, "OTLPMetricExporter", Recorder()) + monkeypatch.setattr(tracing, "OTLPLogExporter", Recorder()) + return calls + + +@pytest.fixture +def built_resources(monkeypatch): + """Every Resource the setup built, as a plain dict.""" + seen: list[dict] = [] + real = tracing.Resource.create + + def spy(attributes): + seen.append(dict(attributes)) + return real(attributes) + + monkeypatch.setattr(tracing.Resource, "create", staticmethod(spy)) + return seen + + +def test_blank_urls_build_no_exporter(monkeypatch, no_exporter_may_be_built): + """The shipped staging configuration, verbatim.""" + monkeypatch.setattr(settings, "ENV", Environment.STAGING) + monkeypatch.setattr(settings, "LOGGING_METRICS_URL", "") + monkeypatch.setattr(settings, "LOGGING_LOGS_URL", "") + monkeypatch.setattr(settings, "LOGGING_TOKEN", "") + + setup_tracer_provider() + assert no_exporter_may_be_built == [] + + +def test_it_says_so_rather_than_failing_silently(monkeypatch, caplog): + """Silence is indistinguishable from a working exporter, which is how the + original defect survived: the only symptom was on a dashboard.""" + monkeypatch.setattr(settings, "ENV", Environment.STAGING) + monkeypatch.setattr(settings, "LOGGING_METRICS_URL", "") + monkeypatch.setattr(settings, "LOGGING_LOGS_URL", "") + + with caplog.at_level(logging.WARNING, logger="core.tracing"): + setup_tracer_provider() + assert any("telemetry not configured" in record.message for record in caplog.records) + + +def test_local_builds_no_exporter_even_with_urls_set(monkeypatch, no_exporter_may_be_built): + """The other guard, which this file must not accidentally depend on.""" + monkeypatch.setattr(settings, "ENV", Environment.LOCAL) + monkeypatch.setattr(settings, "LOGGING_METRICS_URL", "http://collector:4318/v1/metrics") + monkeypatch.setattr(settings, "LOGGING_LOGS_URL", "http://collector:4318/v1/logs") + + setup_tracer_provider() + assert no_exporter_may_be_built == [] + + +def test_with_urls_it_does_build_them(monkeypatch, record_what_is_built): + """THE POSITIVE CONTROL, and the one that makes the rest mean anything. + + Without it every assertion above is satisfied by a function that returns on + its first line - which is precisely the bug in the opposite direction, and + would silently disable telemetry in production. + """ + monkeypatch.setattr(settings, "ENV", Environment.STAGING) + monkeypatch.setattr(settings, "LOGGING_METRICS_URL", "http://collector:4318/v1/metrics") + monkeypatch.setattr(settings, "LOGGING_LOGS_URL", "http://collector:4318/v1/logs") + monkeypatch.setattr(settings, "LOGGING_TOKEN", "a-token") + + setup_tracer_provider() + assert sorted(record_what_is_built) == ["logs", "metrics"] + + +def test_a_blank_endpoint_really_does_resolve_to_localhost(): + """The mechanism, pinned. If a future SDK stopped defaulting the endpoint the + guard would be belt without braces - worth knowing, not worth removing.""" + from opentelemetry.exporter.otlp.proto.http.metric_exporter import OTLPMetricExporter + + assert "localhost:4318" in OTLPMetricExporter(endpoint="")._endpoint + + +def test_the_exporters_get_seconds_not_milliseconds(monkeypatch, record_what_is_built, built_with): + """5000 handed to a constructor that takes SECONDS is 83 minutes. + + The SDK's own `DEFAULT_TIMEOUT` is 10 and it is used as + `deadline_sec = time() + self._timeout`, while `MeterProvider.shutdown` and + every MetricReader take MILLISECONDS. One constant named `_MS` was passed to + both, so a collector that accepted a connection and then hung would hold the + export thread for the rest of the afternoon. + """ + monkeypatch.setattr(settings, "ENV", Environment.STAGING) + monkeypatch.setattr(settings, "LOGGING_METRICS_URL", "http://collector:4318/v1/metrics") + monkeypatch.setattr(settings, "LOGGING_LOGS_URL", "http://collector:4318/v1/logs") + _setup() + + assert len(built_with) == 2, f"both exporters must be built, got {built_with}" + for kwargs in built_with: + timeout = kwargs.get("timeout") + assert timeout is not None, f"an exporter was built with no timeout: {kwargs}" + assert timeout < 60, ( + f"timeout={timeout} is being read as SECONDS by the exporter " + f"({timeout / 60:.0f} minutes). Pass the *_SECONDS constant." + ) + + +def test_replicas_are_distinguishable(monkeypatch, record_what_is_built, built_resources): + """Without `service.instance.id` two replicas emit byte-identical stream + identities and the backend merges their cumulative histograms.""" + monkeypatch.setattr(settings, "ENV", Environment.STAGING) + monkeypatch.setattr(settings, "LOGGING_METRICS_URL", "http://collector:4318/v1/metrics") + monkeypatch.setattr(settings, "LOGGING_LOGS_URL", "http://collector:4318/v1/logs") + _setup() + + assert built_resources, "no Resource was built" + for attributes in built_resources: + assert attributes.get("service.instance.id"), attributes + assert attributes.get("service.name"), attributes + + +def test_the_flush_is_bounded_below_dockers_stop_grace(): + """The SDK's atexit handler flushes too - on a 30-second budget, against + Docker's 10-second stop grace. Against a slow collector the container is + SIGKILLed mid-flush: the data is lost anyway and every deploy pays the full + grace period.""" + default = inspect.signature(tracing.shutdown_telemetry).parameters["timeout_millis"].default + assert default < 10_000, "Docker's default stop grace period" + + +def test_the_bounded_flush_is_registered_before_the_sdks(record_what_is_built, monkeypatch): + """atexit is LIFO, so ours must be registered AFTER the SDK's to run BEFORE + it. Registered inside `setup_tracer_provider`, after `MeterProvider(...)`.""" + registered: list = [] + monkeypatch.setattr(tracing.atexit, "register", lambda fn, *a, **k: registered.append(fn)) + + monkeypatch.setattr(settings, "ENV", Environment.STAGING) + monkeypatch.setattr(settings, "LOGGING_METRICS_URL", "http://collector:4318/v1/metrics") + monkeypatch.setattr(settings, "LOGGING_LOGS_URL", "http://collector:4318/v1/logs") + _setup() + + assert tracing.shutdown_telemetry in registered, ( + "the bounded flush is not registered with atexit, so only the SDK's " + "unbounded 30-second handler runs" + ) + + +def test_flushing_detaches_the_log_handler(monkeypatch): + """`logging.shutdown` is registered with atexit by the logging module at + import, so LIFO runs it LAST - after the interpreter has begun tearing down, + where `LoggingHandler.flush()` spawning a thread raises `RuntimeError: can't + create new thread at interpreter shutdown`. Every container printed that + traceback on exit.""" + flushed: list = [] + + class Provider: + def force_flush(self, timeout_millis=None): + flushed.append(timeout_millis) + + handler = logging.NullHandler() + logging.getLogger().addHandler(handler) + monkeypatch.setattr(tracing, "_log_provider", Provider()) + monkeypatch.setattr(tracing, "_log_handler", handler) + monkeypatch.setattr(tracing, "_meter_provider", None) + try: + tracing.shutdown_telemetry() + assert flushed, "the log provider was not flushed" + assert handler not in logging.getLogger().handlers, ( + "the OTLP handler is still attached, so logging.shutdown will try to " + "flush it during interpreter teardown" + ) + finally: + logging.getLogger().removeHandler(handler)