diff --git a/.env.production.exemple b/.env.production.exemple index 259e15e..4c9862f 100644 --- a/.env.production.exemple +++ b/.env.production.exemple @@ -28,6 +28,14 @@ STORAGE_REGION=us-east-1 ALLOW_ORIGIN=https://app.optimce.example # ── Observability (required in production) ── +# +# ALL CONTAINERS OF THIS SERVICE NEED THESE, not just the API: every entrypoint +# calls setup_tracer_provider() and exports its own telemetry. +# +# Leaving them BLANK is now inert rather than harmful: core/tracing.py returns +# early and logs a warning. It used to start a 15-second export loop and an OTLP +# root-log handler against the exporter's default endpoint, +# http://localhost:4318/, on every container. LOGGING_TOKEN= LOGGING_TRACES_URL= LOGGING_LOGS_URL= diff --git a/.env.staging.exemple b/.env.staging.exemple index cd5bac8..4071432 100644 --- a/.env.staging.exemple +++ b/.env.staging.exemple @@ -28,6 +28,14 @@ STORAGE_REGION=us-east-1 ALLOW_ORIGIN=https://app.staging.optimce.example # ── Observability (optional in staging, required in production) ── +# +# ALL CONTAINERS OF THIS SERVICE NEED THESE, not just the API: every entrypoint +# calls setup_tracer_provider() and exports its own telemetry. +# +# Leaving them BLANK is now inert rather than harmful: core/tracing.py returns +# early and logs a warning. It used to start a 15-second export loop and an OTLP +# root-log handler against the exporter's default endpoint, +# http://localhost:4318/, on every container. LOGGING_TOKEN= LOGGING_TRACES_URL= LOGGING_LOGS_URL= diff --git a/.github/workflows/build-worker.yml b/.github/workflows/build-worker.yml index 466fab0..163fc15 100644 --- a/.github/workflows/build-worker.yml +++ b/.github/workflows/build-worker.yml @@ -8,7 +8,7 @@ on: paths: - 'Dockerfile.worker' - 'core/**' - - 'algorithms/**' + - 'simulation/**' - 'shared/**' - 'worker/**' - 'locales/**' @@ -21,7 +21,7 @@ on: paths: - 'Dockerfile.worker' - 'core/**' - - 'algorithms/**' + - 'simulation/**' - 'shared/**' - 'worker/**' - 'locales/**' diff --git a/.github/workflows/build.yml b/.github/workflows/build.yml index 2fe0daf..fce2e99 100644 --- a/.github/workflows/build.yml +++ b/.github/workflows/build.yml @@ -10,7 +10,7 @@ on: - 'main.py' - 'api/**' - 'core/**' - - 'algorithms/**' + - 'simulation/**' - 'shared/**' - 'worker/**' - 'locales/**' @@ -25,7 +25,7 @@ on: - 'main.py' - 'api/**' - 'core/**' - - 'algorithms/**' + - 'simulation/**' - 'shared/**' - 'worker/**' - 'locales/**' diff --git a/core/tracing.py b/core/tracing.py index 69a26a6..dfd6c52 100644 --- a/core/tracing.py +++ b/core/tracing.py @@ -1,4 +1,7 @@ +import atexit import logging +import os +import uuid from opentelemetry import metrics, trace from opentelemetry.exporter.otlp.proto.http._log_exporter import OTLPLogExporter @@ -16,7 +19,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 def setup_tracer_provider() -> None: @@ -28,14 +39,47 @@ def setup_tracer_provider() -> None: if settings.ENV == Environment.LOCAL: return - resource = Resource.create({"service.name": "simulation-key-backend", "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": "simulation-key-backend", + "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)) @@ -46,19 +90,100 @@ 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=15000) 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) + + tracer = trace.get_tracer(__name__) diff --git a/tests/test_build_workflow_paths.py b/tests/test_build_workflow_paths.py new file mode 100644 index 0000000..4322896 --- /dev/null +++ b/tests/test_build_workflow_paths.py @@ -0,0 +1,195 @@ +"""A change to anything an image is built from must build that image. + +--------------------------------------------------------------------------- +WHY THIS EXISTS. + +`.github/workflows/build.yml` and `build-worker.yml` run only when a changed +file matches their `paths:` filter, and both filters were copied from the +service template: `core/`, `algorithms/`, `shared/`, `worker/`, `locales/`. +This service has no `algorithms/`: its engine lives in `simulation/`, which +both images copy and neither filter listed. + +So a fix confined to the simulation engine built nothing on its pull request +and published nothing on merge, and production went on pulling the previous +`:main-prod` and `:main-worker` with every check green. +--------------------------------------------------------------------------- + +The rule pinned here: every `COPY` source in each image's Dockerfile appears in +BOTH trigger lists of the workflow that builds it - 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] +WORKFLOWS = SERVICE_ROOT / ".github" / "workflows" + +# Every image CI publishes: (Dockerfile, the workflow that builds it). +IMAGES = [ + ("Dockerfile.production", "build.yml"), + ("Dockerfile.worker", "build-worker.yml"), +] + +TRIGGERS = ["push", "pull_request"] + +# `- 'x'`, `- "x"` or `- x`, with an optional trailing comment. +_LIST_ITEM = re.compile(r"""-\s+(?:'([^']+)'|"([^"]+)"|([^\s'"#][^#]*?))\s*(?:#.*)?""") + +# `file: Dockerfile.worker` in a docker/build-push-action step. +_BUILD_FILE = re.compile(r"""^\s*file:\s*['"]?([^'"\s#]+)['"]?\s*(?:#.*)?$""", re.MULTILINE) + + +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) +@pytest.mark.parametrize(("dockerfile", "workflow"), IMAGES) +def test_every_build_input_triggers_the_image_build(dockerfile, workflow, event): + paths = _trigger_paths((WORKFLOWS / workflow).read_text(encoding="utf-8"), event) + assert paths, f"{workflow} has an empty {event} paths: list" + sources = _copy_sources((SERVICE_ROOT / dockerfile).read_text(encoding="utf-8")) + assert sources, f"found no COPY from the build context in {dockerfile}, so this proved nothing" + + # They change the image without being COPY sources. + also_build_inputs = [dockerfile, ".dockerignore", f".github/workflows/{workflow}"] + 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"{workflow}'s {event} paths: filter is missing {missing}. " + f"{dockerfile} builds the image from them, so a change confined to " + "them builds nothing and production keeps the previous image." + ) + + +def test_the_images_checked_here_are_the_images_ci_builds(): + """A wrong or missing pair above would check one image against another's filter.""" + built = [ + (dockerfile, workflow.name) + for workflow in sorted(WORKFLOWS.glob("*.y*ml")) + for dockerfile in _BUILD_FILE.findall(workflow.read_text(encoding="utf-8")) + ] + assert sorted(built) == sorted(IMAGES) + + +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)