From a17ef209494c9aa7c7b80198c181f865fdd0386d Mon Sep 17 00:00:00 2001 From: Anthony Volk Date: Wed, 8 Jul 2026 22:12:12 +0200 Subject: [PATCH 1/9] Bound Google Cloud Logging writes with an explicit budget log_struct exposes no call options, so writes inherited the transport defaults (60s retry deadline) and a degraded Logging API could hold one write for a minute. The gapic write method is the single choke point underneath log_struct, so the destination rebinds it on its own client with a retry whose transient-error budget and per-call timeout are both capped by OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS (default 10s). The knob is clamped through a new shared clamped() helper that rejects zero, negative, and non-finite values, so a stray env value can never disable or unbound the write. The emit path also accepts an optional timestamp so queued transports can preserve event time. Co-Authored-By: Claude Fable 5 --- changelog.d/22.changed.md | 1 + policyengine_observability/config.py | 5 + .../destinations/base.py | 16 +++ .../destinations/google_cloud_logging.py | 60 ++++++++- tests/test_destinations.py | 115 +++++++++++++++++- tests/test_runtime.py | 16 +++ 6 files changed, 211 insertions(+), 2 deletions(-) create mode 100644 changelog.d/22.changed.md diff --git a/changelog.d/22.changed.md b/changelog.d/22.changed.md new file mode 100644 index 0000000..63043d7 --- /dev/null +++ b/changelog.d/22.changed.md @@ -0,0 +1 @@ +Google Cloud Logging writes now carry an explicit per-call budget (default 10 seconds, `OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS`, clamped to sane bounds) that caps both the call and its transient-error retries, replacing the transport defaults that could hold a single write for up to 60 seconds when the Logging API degrades. diff --git a/policyengine_observability/config.py b/policyengine_observability/config.py index 2e37860..3a72f58 100644 --- a/policyengine_observability/config.py +++ b/policyengine_observability/config.py @@ -87,6 +87,7 @@ class ObservabilityConfig: log_destinations: tuple[str, ...] = ("stdout",) google_cloud_project: str | None = None google_cloud_log_name: str = "policyengine-observability" + google_cloud_write_timeout_seconds: float = 10.0 @classmethod def from_env( @@ -166,6 +167,10 @@ def from_env( os.getenv("OBSERVABILITY_GOOGLE_CLOUD_LOG_NAME") or cls.google_cloud_log_name ), + google_cloud_write_timeout_seconds=float_from_env( + "OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS", + cls.google_cloud_write_timeout_seconds, + ), ) diff --git a/policyengine_observability/destinations/base.py b/policyengine_observability/destinations/base.py index 72e798e..be24644 100644 --- a/policyengine_observability/destinations/base.py +++ b/policyengine_observability/destinations/base.py @@ -1,5 +1,6 @@ from __future__ import annotations +import math from collections.abc import Mapping, Sequence from typing import Any, Protocol @@ -17,6 +18,21 @@ def emit( """Write one structured observability payload.""" +def clamped(value: Any, *, low: float, high: float, default: float) -> float: + """Coerce a config knob to a finite float within [low, high]. + + Anything unparseable or non-finite falls back to the default, so a + stray env value can never disable or unbound the mechanism it tunes. + """ + try: + number = float(value) + except (TypeError, ValueError): + return default + if not math.isfinite(number): + return default + return min(max(number, low), high) + + def normalize_payload(value: Any) -> Any: if value is None or isinstance(value, str | bool | int | float): return value diff --git a/policyengine_observability/destinations/google_cloud_logging.py b/policyengine_observability/destinations/google_cloud_logging.py index 8d8d918..f7d1105 100644 --- a/policyengine_observability/destinations/google_cloud_logging.py +++ b/policyengine_observability/destinations/google_cloud_logging.py @@ -1,6 +1,8 @@ from __future__ import annotations +import functools from collections.abc import Callable +from datetime import datetime from typing import Any, Protocol from policyengine_observability.google_credentials import ( @@ -8,7 +10,11 @@ load_google_credentials, ) -from .base import normalize_payload +from .base import clamped, normalize_payload + +DEFAULT_WRITE_TIMEOUT_SECONDS = 10.0 +MIN_WRITE_TIMEOUT_SECONDS = 0.5 +MAX_WRITE_TIMEOUT_SECONDS = 60.0 class GoogleCloudLogger(Protocol): @@ -40,9 +46,16 @@ def __init__( project: str | None, log_name: str, client_factory: GoogleCloudLoggingClientFactory | None = None, + write_timeout_seconds: float | None = None, ) -> None: self.project = project self.log_name = log_name + self.write_timeout_seconds = clamped( + write_timeout_seconds, + low=MIN_WRITE_TIMEOUT_SECONDS, + high=MAX_WRITE_TIMEOUT_SECONDS, + default=DEFAULT_WRITE_TIMEOUT_SECONDS, + ) credentials = load_google_credentials(prefer_workload_identity=True) if credentials is None: configure_google_application_credentials() @@ -61,6 +74,46 @@ def client_factory( self.client = client_factory(project, credentials) self.project = project or getattr(self.client, "project", None) self.logger = self.client.logger(log_name) + self._bound_write_timeout() + + def _bound_write_timeout(self) -> None: + """Bound every write on this destination's own client. + + ``log_struct`` exposes no call options, and the transport default + lets a degraded Logging API hold one write for up to 60 seconds. + The gapic method is the single choke point underneath + ``log_struct``, so rebind it on this client instance with a retry + whose transient-error budget and per-call timeout are both capped + by ``write_timeout_seconds``. When the private handle is absent + (HTTP transport, injected fakes), the library default applies — + acceptable because no write on this destination ever runs on a + request thread. + """ + api = getattr(self.client, "logging_api", None) + gapic = getattr(api, "_gapic_api", None) + if gapic is None: + return + try: + from google.api_core import exceptions as api_exceptions + from google.api_core.retry import Retry, if_exception_type + except ImportError: # pragma: no cover - google extra always has it + return + retry = Retry( + initial=0.1, + maximum=1.0, + multiplier=1.3, + timeout=self.write_timeout_seconds, + predicate=if_exception_type( + api_exceptions.DeadlineExceeded, + api_exceptions.InternalServerError, + api_exceptions.ServiceUnavailable, + ), + ) + gapic.write_log_entries = functools.partial( + gapic.write_log_entries, + retry=retry, + timeout=self.write_timeout_seconds, + ) def emit( self, @@ -68,12 +121,17 @@ def emit( *, log_type: str, severity: str, + timestamp: datetime | None = None, ) -> None: normalized = normalize_payload(payload) kwargs: dict[str, Any] = { "severity": severity, "labels": _labels(normalized, log_type=log_type), } + if timestamp is not None: + # Supplied by queued transports so delayed writes keep the + # record's event time instead of the delivery time. + kwargs["timestamp"] = timestamp trace_id = normalized.get("trace_id") if trace_id and self.project: kwargs["trace"] = f"projects/{self.project}/traces/{trace_id}" diff --git a/tests/test_destinations.py b/tests/test_destinations.py index 10c1941..10890b4 100644 --- a/tests/test_destinations.py +++ b/tests/test_destinations.py @@ -1,10 +1,15 @@ from __future__ import annotations +import math + +import pytest + from policyengine_observability.destinations import ( GoogleCloudLoggingDestination, google_cloud_logging, normalize_payload, ) +from policyengine_observability.destinations.base import clamped class Unprintable: @@ -20,17 +25,72 @@ def log_struct(self, payload, **kwargs) -> None: self.calls.append((payload, kwargs)) -class FakeClient: +class FakeGapicApi: + def __init__(self) -> None: + self.calls = [] + + def write_log_entries(self, *args, **kwargs) -> None: + self.calls.append((args, kwargs)) + + +class FakeLoggingApi: def __init__(self) -> None: + self._gapic_api = FakeGapicApi() + + +class FakeClient: + def __init__(self, *, gapic: bool = False) -> None: self.project = "resolved-project" self.fake_logger = FakeLogger() self.log_names = [] + if gapic: + self.logging_api = FakeLoggingApi() def logger(self, log_name: str) -> FakeLogger: self.log_names.append(log_name) return self.fake_logger +def _google_destination(monkeypatch, client, **kwargs): + monkeypatch.setattr( + google_cloud_logging, + "load_google_credentials", + lambda *, prefer_workload_identity: None, + ) + monkeypatch.setattr( + google_cloud_logging, + "configure_google_application_credentials", + lambda: None, + ) + return GoogleCloudLoggingDestination( + project=None, + log_name="policyengine-observability", + client_factory=lambda _project, _credentials: client, + **kwargs, + ) + + +@pytest.mark.parametrize( + ("value", "expected"), + [ + (5.0, 5.0), + ("5", 5.0), + (0, 0.5), + (-3, 0.5), + (1000, 60.0), + (float("inf"), 10.0), + (float("nan"), 10.0), + (None, 10.0), + ("garbage", 10.0), + ], +) +def test_clamped_bounds_and_rejects_non_finite(value, expected) -> None: + result = clamped(value, low=0.5, high=60.0, default=10.0) + + assert result == expected + assert math.isfinite(result) + + def test_normalize_payload_recursively_stringifies_unsafe_values() -> None: normalized = normalize_payload( { @@ -102,6 +162,59 @@ def test_google_destination_writes_structured_log_with_bounded_labels( assert "path" not in kwargs["labels"] +def test_google_destination_bounds_gapic_writes(monkeypatch) -> None: + client = FakeClient(gapic=True) + + destination = _google_destination( + monkeypatch, client, write_timeout_seconds=5.0 + ) + # The write path under log_struct funnels through this method; the + # rebinding must inject the bounded retry and per-call timeout. + client.logging_api._gapic_api.write_log_entries(request="sentinel") + + assert destination.write_timeout_seconds == 5.0 + ((args, kwargs),) = client.logging_api._gapic_api.calls + assert kwargs["request"] == "sentinel" + assert kwargs["timeout"] == 5.0 + assert kwargs["retry"].timeout == 5.0 + + +def test_google_destination_clamps_write_timeout(monkeypatch) -> None: + destination = _google_destination( + monkeypatch, FakeClient(gapic=True), write_timeout_seconds=0.0 + ) + + assert destination.write_timeout_seconds == 0.5 + + +def test_google_destination_without_gapic_transport_still_works( + monkeypatch, +) -> None: + client = FakeClient() + + destination = _google_destination(monkeypatch, client) + destination.emit({"event": "x"}, log_type="event", severity="INFO") + + assert len(client.fake_logger.calls) == 1 + + +def test_google_destination_forwards_enqueue_timestamp(monkeypatch) -> None: + from datetime import UTC, datetime + + client = FakeClient() + destination = _google_destination(monkeypatch, client) + stamp = datetime(2026, 7, 8, 12, 0, 0, tzinfo=UTC) + + destination.emit( + {"event": "x"}, log_type="event", severity="INFO", timestamp=stamp + ) + destination.emit({"event": "y"}, log_type="event", severity="INFO") + + (_, stamped_kwargs), (_, plain_kwargs) = client.fake_logger.calls + assert stamped_kwargs["timestamp"] is stamp + assert "timestamp" not in plain_kwargs + + # ── Destination circuit breaker ────────────────────────────────────────── diff --git a/tests/test_runtime.py b/tests/test_runtime.py index 6dfaf7c..7d75925 100644 --- a/tests/test_runtime.py +++ b/tests/test_runtime.py @@ -1166,6 +1166,22 @@ def test_from_env_invalid_shutdown_timeout_falls_back(monkeypatch) -> None: assert config.shutdown_timeout_seconds == 3.0 +def test_from_env_reads_google_write_timeout(monkeypatch) -> None: + monkeypatch.setenv("OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS", "2.5") + + config = ObservabilityConfig.from_env(service_name="svc") + + assert config.google_cloud_write_timeout_seconds == 2.5 + + +def test_from_env_google_write_timeout_defaults(monkeypatch) -> None: + monkeypatch.setenv("OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS", "bad") + + config = ObservabilityConfig.from_env(service_name="svc") + + assert config.google_cloud_write_timeout_seconds == 10.0 + + def test_from_env_enables_otel_by_default() -> None: config = ObservabilityConfig.from_env(service_name="svc") From 68a3026a3ebd5e1d73823139ceb00207e711ed10 Mon Sep 17 00:00:00 2001 From: Anthony Volk Date: Wed, 8 Jul 2026 22:15:01 +0200 Subject: [PATCH 2/9] Add stdout formatter registry with an agent-native google format MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Stdout lines gain a named-formatter hook: formatters register by name and shape the normalized payload into the JSON line a platform's log agent expects. The core knows only the plain default; the google formatter (severity plus the logging.googleapis.com trace/spanId/labels special keys the Cloud Run and GKE agents promote to LogEntry fields) lives in the google module and registers itself. No time key is set: emission is synchronous, so the agent's receive time is the event time. A broken formatter degrades to the unformatted line — stdout is the fallback sink and must keep delivering. Co-Authored-By: Claude Fable 5 --- changelog.d/22.added.md | 1 + policyengine_observability/config.py | 4 + .../destinations/google_cloud_logging.py | 34 ++++ .../destinations/manager.py | 3 +- .../destinations/stdout.py | 50 +++++- tests/test_destinations.py | 160 ++++++++++++++++++ tests/test_runtime.py | 8 + 7 files changed, 258 insertions(+), 2 deletions(-) create mode 100644 changelog.d/22.added.md diff --git a/changelog.d/22.added.md b/changelog.d/22.added.md new file mode 100644 index 0000000..ff6c831 --- /dev/null +++ b/changelog.d/22.added.md @@ -0,0 +1 @@ +Added an agent-native stdout format (`OBSERVABILITY_STDOUT_FORMAT=google`): JSON lines carry the special keys the Cloud Run/GKE logging agent promotes to first-class LogEntry fields (severity, trace, span, labels), enabling full-fidelity Cloud Logging ingestion from stdout with no in-process network emission. Formatters are a named registry, so future backends can contribute their own agent-native shapes. diff --git a/policyengine_observability/config.py b/policyengine_observability/config.py index 3a72f58..4000a15 100644 --- a/policyengine_observability/config.py +++ b/policyengine_observability/config.py @@ -88,6 +88,7 @@ class ObservabilityConfig: google_cloud_project: str | None = None google_cloud_log_name: str = "policyengine-observability" google_cloud_write_timeout_seconds: float = 10.0 + stdout_format: str = "plain" @classmethod def from_env( @@ -171,6 +172,9 @@ def from_env( "OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS", cls.google_cloud_write_timeout_seconds, ), + stdout_format=( + os.getenv("OBSERVABILITY_STDOUT_FORMAT") or cls.stdout_format + ), ) diff --git a/policyengine_observability/destinations/google_cloud_logging.py b/policyengine_observability/destinations/google_cloud_logging.py index f7d1105..85b1b72 100644 --- a/policyengine_observability/destinations/google_cloud_logging.py +++ b/policyengine_observability/destinations/google_cloud_logging.py @@ -11,11 +11,18 @@ ) from .base import clamped, normalize_payload +from .stdout import StdoutFormatter, register_stdout_formatter DEFAULT_WRITE_TIMEOUT_SECONDS = 10.0 MIN_WRITE_TIMEOUT_SECONDS = 0.5 MAX_WRITE_TIMEOUT_SECONDS = 60.0 +# Structured-JSON keys the Cloud Run/GKE logging agent promotes to +# first-class LogEntry fields when it ingests a stdout line. +GOOGLE_TRACE_KEY = "logging.googleapis.com/trace" +GOOGLE_SPAN_ID_KEY = "logging.googleapis.com/spanId" +GOOGLE_LABELS_KEY = "logging.googleapis.com/labels" + class GoogleCloudLogger(Protocol): def log_struct( @@ -153,3 +160,30 @@ def _labels(payload: dict[str, Any], *, log_type: str) -> dict[str, str]: if value is not None: labels[key] = str(value) return labels + + +def _google_stdout_formatter_factory(config: Any) -> StdoutFormatter: + """Shape stdout lines with the agent-native Cloud Logging keys. + + Emission stays synchronous, so no ``time`` key is set — the agent's + receive time is the event time. + """ + project = getattr(config, "google_cloud_project", None) + + def format_google( + payload: dict[str, Any], *, log_type: str, severity: str + ) -> dict[str, Any]: + payload["severity"] = str(severity).upper() + payload[GOOGLE_LABELS_KEY] = _labels(payload, log_type=log_type) + trace_id = payload.get("trace_id") + if trace_id and project: + payload[GOOGLE_TRACE_KEY] = f"projects/{project}/traces/{trace_id}" + span_id = payload.get("span_id") + if span_id: + payload[GOOGLE_SPAN_ID_KEY] = str(span_id) + return payload + + return format_google + + +register_stdout_formatter("google", _google_stdout_formatter_factory) diff --git a/policyengine_observability/destinations/manager.py b/policyengine_observability/destinations/manager.py index 76b4725..a746083 100644 --- a/policyengine_observability/destinations/manager.py +++ b/policyengine_observability/destinations/manager.py @@ -7,7 +7,7 @@ from ..config import ObservabilityConfig from .base import LogDestination from .google_cloud_logging import GoogleCloudLoggingDestination -from .stdout import StdoutJsonDestination +from .stdout import StdoutJsonDestination, resolve_stdout_formatter # A destination that fails this many consecutive emits is disabled for the # rest of the process. Emission is synchronous on the caller's (request) path, @@ -141,4 +141,5 @@ def _stdout_destination(self) -> StdoutJsonDestination: return StdoutJsonDestination( loggers=self.loggers, serializer=self.serializer, + formatter=resolve_stdout_formatter(self.config), ) diff --git a/policyengine_observability/destinations/stdout.py b/policyengine_observability/destinations/stdout.py index 5bc01b1..8e8f6a6 100644 --- a/policyengine_observability/destinations/stdout.py +++ b/policyengine_observability/destinations/stdout.py @@ -6,6 +6,41 @@ from .base import normalize_payload +# A stdout formatter shapes the normalized payload into the JSON line a +# platform's log agent expects. Formatters are registered by name so +# backend modules can contribute agent-native shapes without the core +# knowing about any backend; "plain" is the built-in default. Factories +# receive the ObservabilityConfig so a formatter can close over settings +# it needs (duck-typed to keep this module config-agnostic). +StdoutFormatter = Callable[..., dict[str, Any]] +StdoutFormatterFactory = Callable[[Any], StdoutFormatter] + +_FORMATTER_FACTORIES: dict[str, StdoutFormatterFactory] = {} + + +def register_stdout_formatter( + name: str, factory: StdoutFormatterFactory +) -> None: + _FORMATTER_FACTORIES[name.strip().lower()] = factory + + +def resolve_stdout_formatter(config: Any) -> StdoutFormatter: + name = (getattr(config, "stdout_format", None) or "plain").strip().lower() + factory = _FORMATTER_FACTORIES.get(name) or _FORMATTER_FACTORIES["plain"] + return factory(config) + + +def _plain_formatter_factory(config: Any) -> StdoutFormatter: + def format_plain( + payload: dict[str, Any], *, log_type: str, severity: str + ) -> dict[str, Any]: + return payload + + return format_plain + + +register_stdout_formatter("plain", _plain_formatter_factory) + class StdoutJsonDestination: name = "stdout" @@ -15,9 +50,11 @@ def __init__( *, loggers: Mapping[str, logging.Logger], serializer: Callable[[dict[str, Any]], str], + formatter: StdoutFormatter | None = None, ) -> None: self.loggers = loggers self.serializer = serializer + self.formatter = formatter or _plain_formatter_factory(None) def emit( self, @@ -26,8 +63,19 @@ def emit( log_type: str, severity: str, ) -> None: + normalized = normalize_payload(payload) + try: + # Formatters receive (and may mutate) the private normalized + # copy. Stdout is the fallback sink, so a broken formatter + # degrades to the unformatted line rather than losing the + # record or tripping the breaker. + formatted = self.formatter( + normalized, log_type=log_type, severity=severity + ) + except Exception: + formatted = normalized + message = self.serializer(formatted) logger = self.loggers.get(log_type) or self.loggers["event"] - message = self.serializer(normalize_payload(payload)) if severity in {"ERROR", "CRITICAL"}: logger.error(message) elif severity == "WARNING": diff --git a/tests/test_destinations.py b/tests/test_destinations.py index 10890b4..e3f4e15 100644 --- a/tests/test_destinations.py +++ b/tests/test_destinations.py @@ -215,6 +215,166 @@ def test_google_destination_forwards_enqueue_timestamp(monkeypatch) -> None: assert "timestamp" not in plain_kwargs +# ── Stdout formatters ──────────────────────────────────────────────────── + + +class RecordingLogger: + def __init__(self) -> None: + self.lines = [] + + def info(self, message) -> None: + self.lines.append(("INFO", message)) + + def warning(self, message) -> None: + self.lines.append(("WARNING", message)) + + def error(self, message) -> None: + self.lines.append(("ERROR", message)) + + +def _stdout_destination(config=None, formatter=None): + import json + + from policyengine_observability.destinations.stdout import ( + StdoutJsonDestination, + resolve_stdout_formatter, + ) + + logger = RecordingLogger() + if formatter is None and config is not None: + formatter = resolve_stdout_formatter(config) + destination = StdoutJsonDestination( + loggers={"event": logger}, + serializer=json.dumps, + formatter=formatter, + ) + return destination, logger + + +def _emitted_line(logger): + import json + + ((_, message),) = logger.lines + return json.loads(message) + + +def test_stdout_google_formatter_maps_agent_native_keys() -> None: + from policyengine_observability.config import ObservabilityConfig + + config = ObservabilityConfig( + stdout_format="google", google_cloud_project="proj" + ) + destination, logger = _stdout_destination(config) + + destination.emit( + { + "schema_version": "policyengine.observability.event.v1", + "service_name": "svc", + "event": "x", + "trace_id": "abc123", + "span_id": 456, + }, + log_type="event", + severity="error", + ) + + line = _emitted_line(logger) + assert line["severity"] == "ERROR" + assert line["logging.googleapis.com/trace"] == ( + "projects/proj/traces/abc123" + ) + assert line["logging.googleapis.com/spanId"] == "456" + assert line["logging.googleapis.com/labels"] == { + "log_type": "event", + "service_name": "svc", + "schema_version": "policyengine.observability.event.v1", + } + assert "time" not in line + assert line["event"] == "x" + + +def test_stdout_google_formatter_omits_trace_without_project() -> None: + from policyengine_observability.config import ObservabilityConfig + + config = ObservabilityConfig(stdout_format="google") + destination, logger = _stdout_destination(config) + + destination.emit( + {"event": "x", "trace_id": "abc"}, log_type="event", severity="INFO" + ) + + line = _emitted_line(logger) + assert "logging.googleapis.com/trace" not in line + + +def test_stdout_unknown_format_falls_back_to_plain() -> None: + from policyengine_observability.config import ObservabilityConfig + + config = ObservabilityConfig(stdout_format=" GoOgLeX ") + destination, logger = _stdout_destination(config) + + destination.emit({"event": "x"}, log_type="event", severity="INFO") + + assert _emitted_line(logger) == {"event": "x"} + + +def test_stdout_format_name_is_normalized() -> None: + from policyengine_observability.config import ObservabilityConfig + + config = ObservabilityConfig(stdout_format=" GOOGLE ") + destination, logger = _stdout_destination(config) + + destination.emit({"event": "x"}, log_type="event", severity="INFO") + + assert _emitted_line(logger)["severity"] == "INFO" + + +def test_stdout_broken_formatter_degrades_to_unformatted() -> None: + def broken(payload, *, log_type, severity): + raise RuntimeError("formatter bug") + + destination, logger = _stdout_destination(formatter=broken) + + destination.emit({"event": "x"}, log_type="event", severity="INFO") + + assert _emitted_line(logger) == {"event": "x"} + + +def test_stdout_google_formatter_never_mutates_caller_payload() -> None: + from policyengine_observability.config import ObservabilityConfig + + config = ObservabilityConfig( + stdout_format="google", google_cloud_project="proj" + ) + destination, logger = _stdout_destination(config) + payload = {"event": "x", "trace_id": "abc"} + + destination.emit(payload, log_type="event", severity="INFO") + + assert payload == {"event": "x", "trace_id": "abc"} + + +def test_custom_stdout_formatter_registers_and_resolves() -> None: + from policyengine_observability.config import ObservabilityConfig + from policyengine_observability.destinations.stdout import ( + _FORMATTER_FACTORIES, + register_stdout_formatter, + ) + + def factory(config): + return lambda payload, *, log_type, severity: {"wrapped": payload} + + register_stdout_formatter("custom-test", factory) + try: + config = ObservabilityConfig(stdout_format="custom-test") + destination, logger = _stdout_destination(config) + destination.emit({"event": "x"}, log_type="event", severity="INFO") + finally: + _FORMATTER_FACTORIES.pop("custom-test", None) + + assert _emitted_line(logger) == {"wrapped": {"event": "x"}} + + # ── Destination circuit breaker ────────────────────────────────────────── diff --git a/tests/test_runtime.py b/tests/test_runtime.py index 7d75925..d761765 100644 --- a/tests/test_runtime.py +++ b/tests/test_runtime.py @@ -1174,6 +1174,14 @@ def test_from_env_reads_google_write_timeout(monkeypatch) -> None: assert config.google_cloud_write_timeout_seconds == 2.5 +def test_from_env_reads_stdout_format(monkeypatch) -> None: + monkeypatch.setenv("OBSERVABILITY_STDOUT_FORMAT", "google") + + config = ObservabilityConfig.from_env(service_name="svc") + + assert config.stdout_format == "google" + + def test_from_env_google_write_timeout_defaults(monkeypatch) -> None: monkeypatch.setenv("OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS", "bad") From 6971ca11727b460e11ab0d571986471521b9912c Mon Sep 17 00:00:00 2001 From: Anthony Volk Date: Wed, 8 Jul 2026 22:22:05 +0200 Subject: [PATCH 3/9] Add a destination registry and generic queued transport MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Destinations now register as named strategies: inline strategies (stdout) write synchronously on the caller's thread, and every remote strategy is wrapped in QueuedLogDestination, so no remote write can ever run on a request thread. The manager builds by registry lookup and carries no destination names; the google strategy registers itself and its aliases from its own module. QueuedLogDestination is built on stdlib queue.Queue plus logging.handlers.QueueListener so CPython owns the thread and shutdown machinery. Its mutable state is exactly four pieces (queue, listener, drop counter, closed flag). emit() snapshots the payload, stamps the enqueue time, and never blocks or raises: a full queue drops the newest record with counted, throttled reports. close() is idempotent and deadline-bounded — one monotonic deadline covers the sentinel put and the thread join, and an undrained listener is abandoned as a daemon with a report rather than waited on. Reconfiguring the manager closes replaced destinations and clears the id()-keyed failure ledger. Co-Authored-By: Claude Fable 5 --- changelog.d/22.added.md | 2 +- policyengine_observability/config.py | 20 + .../destinations/__init__.py | 4 + .../destinations/google_cloud_logging.py | 17 + .../destinations/manager.py | 72 ++- .../destinations/queued.py | 297 ++++++++++++ .../destinations/registry.py | 49 ++ .../destinations/stdout.py | 12 + tests/test_queued_destination.py | 453 ++++++++++++++++++ tests/test_runtime.py | 26 +- 10 files changed, 934 insertions(+), 18 deletions(-) create mode 100644 policyengine_observability/destinations/queued.py create mode 100644 policyengine_observability/destinations/registry.py create mode 100644 tests/test_queued_destination.py diff --git a/changelog.d/22.added.md b/changelog.d/22.added.md index ff6c831..8da9b82 100644 --- a/changelog.d/22.added.md +++ b/changelog.d/22.added.md @@ -1 +1 @@ -Added an agent-native stdout format (`OBSERVABILITY_STDOUT_FORMAT=google`): JSON lines carry the special keys the Cloud Run/GKE logging agent promotes to first-class LogEntry fields (severity, trace, span, labels), enabling full-fidelity Cloud Logging ingestion from stdout with no in-process network emission. Formatters are a named registry, so future backends can contribute their own agent-native shapes. +Added an agent-native stdout format (`OBSERVABILITY_STDOUT_FORMAT=google`): JSON lines carry the special keys the Cloud Run/GKE logging agent promotes to first-class LogEntry fields (severity, trace, span, labels), enabling full-fidelity Cloud Logging ingestion from stdout with no in-process network emission. Added a destination strategy registry and a generic queued transport: destinations register as `inline` (synchronous, e.g. stdout) or `remote`, and every remote destination is wrapped in a bounded queue drained by a stdlib QueueListener thread, so no remote write ever runs on a request thread. The queue drops-and-counts when full (throttled reports), and close is deadline-bounded (`OBSERVABILITY_LOG_QUEUE_MAXSIZE`, `OBSERVABILITY_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS`). diff --git a/policyengine_observability/config.py b/policyengine_observability/config.py index 4000a15..216d4fd 100644 --- a/policyengine_observability/config.py +++ b/policyengine_observability/config.py @@ -55,6 +55,16 @@ def float_from_env(name: str, default: float) -> float: return default +def int_from_env(name: str, default: int) -> int: + raw_value = os.getenv(name) + if raw_value is None: + return default + try: + return int(raw_value) + except ValueError: + return default + + def default_environment() -> str: return ( os.getenv("OBSERVABILITY_ENVIRONMENT") @@ -89,6 +99,8 @@ class ObservabilityConfig: google_cloud_log_name: str = "policyengine-observability" google_cloud_write_timeout_seconds: float = 10.0 stdout_format: str = "plain" + log_queue_maxsize: int = 1000 + log_queue_close_timeout_seconds: float = 2.0 @classmethod def from_env( @@ -175,6 +187,14 @@ def from_env( stdout_format=( os.getenv("OBSERVABILITY_STDOUT_FORMAT") or cls.stdout_format ), + log_queue_maxsize=int_from_env( + "OBSERVABILITY_LOG_QUEUE_MAXSIZE", + cls.log_queue_maxsize, + ), + log_queue_close_timeout_seconds=float_from_env( + "OBSERVABILITY_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS", + cls.log_queue_close_timeout_seconds, + ), ) diff --git a/policyengine_observability/destinations/__init__.py b/policyengine_observability/destinations/__init__.py index 5703e23..886a9e4 100644 --- a/policyengine_observability/destinations/__init__.py +++ b/policyengine_observability/destinations/__init__.py @@ -3,12 +3,16 @@ from .base import LogDestination, normalize_payload from .google_cloud_logging import GoogleCloudLoggingDestination from .manager import LogDestinationManager +from .queued import QueuedLogDestination +from .registry import register_destination from .stdout import StdoutJsonDestination __all__ = [ "GoogleCloudLoggingDestination", "LogDestination", "LogDestinationManager", + "QueuedLogDestination", "StdoutJsonDestination", "normalize_payload", + "register_destination", ] diff --git a/policyengine_observability/destinations/google_cloud_logging.py b/policyengine_observability/destinations/google_cloud_logging.py index 85b1b72..db960ef 100644 --- a/policyengine_observability/destinations/google_cloud_logging.py +++ b/policyengine_observability/destinations/google_cloud_logging.py @@ -11,6 +11,7 @@ ) from .base import clamped, normalize_payload +from .registry import register_destination from .stdout import StdoutFormatter, register_stdout_formatter DEFAULT_WRITE_TIMEOUT_SECONDS = 10.0 @@ -187,3 +188,19 @@ def format_google( register_stdout_formatter("google", _google_stdout_formatter_factory) + + +def _google_destination_factory(*, config: Any, **_: Any): + return GoogleCloudLoggingDestination( + project=config.google_cloud_project, + log_name=config.google_cloud_log_name, + write_timeout_seconds=config.google_cloud_write_timeout_seconds, + ) + + +register_destination( + "google_cloud_logging", + _google_destination_factory, + transport="remote", + aliases=("google", "google_cloud"), +) diff --git a/policyengine_observability/destinations/manager.py b/policyengine_observability/destinations/manager.py index a746083..4b2dd0d 100644 --- a/policyengine_observability/destinations/manager.py +++ b/policyengine_observability/destinations/manager.py @@ -6,14 +6,17 @@ from ..config import ObservabilityConfig from .base import LogDestination -from .google_cloud_logging import GoogleCloudLoggingDestination +from .queued import QueuedLogDestination +from .registry import destination_strategy from .stdout import StdoutJsonDestination, resolve_stdout_formatter # A destination that fails this many consecutive emits is disabled for the -# rest of the process. Emission is synchronous on the caller's (request) path, -# so a persistently failing destination — e.g. a credential exchange that -# errors after long internal retries — must not keep charging every request; -# an observability sink can never be allowed to degrade the host service. +# rest of the process. Inline destinations emit synchronously on the +# caller's (request) path, so a persistently failing one — e.g. a broken +# serializer — must not keep charging every request; an observability sink +# can never be allowed to degrade the host service. Queued destinations +# never raise from emit (drops are counted internally), so this breaker +# only ever governs inline strategies. DESTINATION_FAILURE_LIMIT = 3 @@ -35,6 +38,15 @@ def __init__( self._consecutive_failures: dict[int, int] = {} def configure(self) -> None: + # Reconfigure (restart_observability) runs only from + # single-threaded lifecycle moments by documented contract, so + # replaced destinations can simply be closed before rebuilding. + # The failure ledger is keyed by id(); stale entries could + # otherwise attach to a new destination via id() reuse. + previous = self.destinations + self.destinations = [] + self._consecutive_failures.clear() + self._close_destinations(previous) failures: list[tuple[str, BaseException]] = [] destinations: list[LogDestination] = [] for destination_name in self.config.log_destinations or ("stdout",): @@ -96,6 +108,28 @@ def emit( for destination in tripped: self._disable_destination(destination) + def close(self, deadline_seconds: float | None = None) -> None: + """Close every destination that supports closing, best-effort.""" + self._close_destinations(self.destinations, deadline_seconds) + + def _close_destinations( + self, + destinations: list[LogDestination], + deadline_seconds: float | None = None, + ) -> None: + for destination in destinations: + close = getattr(destination, "close", None) + if not callable(close): + continue + try: + close(deadline_seconds) + except Exception as exc: + self.on_failure( + "logging.destination_close", + exc, + destination=getattr(destination, "name", None), + ) + def _ensure_destinations(self) -> list[LogDestination]: if not self.configured: try: @@ -125,17 +159,27 @@ def _disable_destination(self, destination: LogDestination) -> None: self.destinations.append(self._stdout_destination()) def _build_destination(self, destination_name: str) -> LogDestination: - normalized = destination_name.strip().lower().replace("-", "_") - if normalized == "stdout": - return self._stdout_destination() - if normalized in {"google", "google_cloud", "google_cloud_logging"}: - return GoogleCloudLoggingDestination( - project=self.config.google_cloud_project, - log_name=self.config.google_cloud_log_name, + strategy = destination_strategy(destination_name) + if strategy is None: + raise ValueError( + f"Unknown observability log destination: {destination_name}" ) - raise ValueError( - f"Unknown observability log destination: {destination_name}" + destination = strategy.factory( + config=self.config, + loggers=self.loggers, + serializer=self.serializer, ) + if strategy.transport == "remote": + # No remote strategy may ever write on a request thread. + destination = QueuedLogDestination( + inner=destination, + on_failure=self.on_failure, + maxsize=self.config.log_queue_maxsize, + close_timeout_seconds=( + self.config.log_queue_close_timeout_seconds + ), + ) + return destination def _stdout_destination(self) -> StdoutJsonDestination: return StdoutJsonDestination( diff --git a/policyengine_observability/destinations/queued.py b/policyengine_observability/destinations/queued.py new file mode 100644 index 0000000..970bb4f --- /dev/null +++ b/policyengine_observability/destinations/queued.py @@ -0,0 +1,297 @@ +"""Bounded, best-effort background delivery for remote log destinations. + +``QueuedLogDestination`` wraps any ``LogDestination`` so the caller's +thread only ever enqueues: a stdlib ``logging.handlers.QueueListener`` +thread performs the actual writes, so a degraded sink can never stall a +request. Delivery is best-effort by contract — the stdout sibling +destination is the durable record — so a full queue drops the newest +record and counts it, and there is deliberately no circuit breaker, +retry queue, or recovery machinery in this component. + +Mutable state census (any addition needs design review): + +1. ``_queue`` — thread-safe by construction (``queue.Queue``). +2. ``_listener``— started once in ``__init__``, stopped once in ``close``. +3. ``_dropped`` — best-effort counter for drop accounting and throttling. +4. ``_closed`` — one-way flag flipped by ``close``. + +Accepted races, all bounded and within the best-effort contract: + +- An ``emit`` that passes the ``_closed`` check while ``close`` runs can + lose that one record uncounted. +- When ``close`` times out, the daemon listener thread is abandoned; it + keeps draining in the background until process exit. +- A process that forks after construction (e.g. gunicorn ``--preload``) + inherits a dead listener; records drop with ``reason="full"`` until + the child calls ``restart_observability()`` from a post-fork hook. + There are deliberately no fork hooks or pid checks here. +""" + +from __future__ import annotations + +import atexit +import inspect +import queue as queue_module +import time +from collections.abc import Callable +from dataclasses import dataclass +from datetime import UTC, datetime +from logging.handlers import QueueListener +from typing import Any + +from .base import LogDestination, clamped, normalize_payload + +DEFAULT_QUEUE_MAXSIZE = 1000 +MIN_QUEUE_MAXSIZE = 10 +MAX_QUEUE_MAXSIZE = 100_000 +DEFAULT_CLOSE_TIMEOUT_SECONDS = 2.0 +MIN_CLOSE_TIMEOUT_SECONDS = 0.0 +MAX_CLOSE_TIMEOUT_SECONDS = 30.0 +DROP_REPORT_INTERVAL = 100 +WRITE_FAILURE_REPORT_INTERVAL = 100 + + +@dataclass(frozen=True, slots=True) +class _QueuedRecord: + payload: Any + log_type: str + severity: str + enqueued_at: datetime + + +def _accepts_timestamp(destination: LogDestination) -> bool: + try: + parameters = inspect.signature(destination.emit).parameters + except (TypeError, ValueError): + return False + return "timestamp" in parameters + + +class _QueuedRecordHandler: + """Duck-typed QueueListener handler: only ``handle`` is ever called. + + ``write_failures`` is confined to the listener thread. A write + failure must never kill the listener, so everything below the emit + is guarded; ``BaseException`` is deliberately not caught (swallowing + ``SystemExit`` on a worker thread is worse than losing the queue — + the consequences of a dead listener are bounded to counted drops). + """ + + def __init__( + self, + inner: LogDestination, + on_failure: Callable[..., None], + *, + forward_timestamp: bool, + report_interval: int = WRITE_FAILURE_REPORT_INTERVAL, + ) -> None: + self.inner = inner + self.on_failure = on_failure + self.forward_timestamp = forward_timestamp + self.report_interval = max(1, report_interval) + self.write_failures = 0 + + def handle(self, record: _QueuedRecord) -> None: + try: + if self.forward_timestamp: + self.inner.emit( + record.payload, + log_type=record.log_type, + severity=record.severity, + timestamp=record.enqueued_at, + ) + else: + self.inner.emit( + record.payload, + log_type=record.log_type, + severity=record.severity, + ) + except Exception as exc: + self.write_failures += 1 + count = self.write_failures + if count != 1 and count % self.report_interval != 0: + return + try: + self.on_failure( + "logging.queue_write", + exc, + destination=getattr(self.inner, "name", None), + log_type=record.log_type, + write_failures_total=count, + ) + except Exception: + pass + + +class _BoundedQueueListener(QueueListener): + """QueueListener whose stop can be given a hard deadline. + + The stdlib ``stop()`` enqueues its sentinel with ``put_nowait`` + (which raises on a jammed bounded queue) and then joins the worker + thread without a timeout. Here one monotonic deadline covers both + the blocking sentinel put and the join; on expiry the daemon thread + is abandoned and ``False`` is returned. + """ + + def stop(self, timeout: float | None = None) -> bool: + thread = self._thread + if thread is None: + return True + if timeout is None: + super().stop() + return True + deadline = time.monotonic() + max(0.0, timeout) + try: + self.queue.put( + self._sentinel, + timeout=max(0.0, deadline - time.monotonic()), + ) + except queue_module.Full: + pass + thread.join(max(0.0, deadline - time.monotonic())) + stopped = not thread.is_alive() + self._thread = None + return stopped + + +class QueuedLogDestination: + def __init__( + self, + *, + inner: LogDestination, + on_failure: Callable[..., None], + maxsize: float = DEFAULT_QUEUE_MAXSIZE, + close_timeout_seconds: float = DEFAULT_CLOSE_TIMEOUT_SECONDS, + drop_report_interval: int = DROP_REPORT_INTERVAL, + ) -> None: + self.inner = inner + self.on_failure = on_failure + self.name = f"queued_{getattr(inner, 'name', 'destination')}" + self.maxsize = int( + clamped( + maxsize, + low=MIN_QUEUE_MAXSIZE, + high=MAX_QUEUE_MAXSIZE, + default=DEFAULT_QUEUE_MAXSIZE, + ) + ) + self.close_timeout_seconds = clamped( + close_timeout_seconds, + low=MIN_CLOSE_TIMEOUT_SECONDS, + high=MAX_CLOSE_TIMEOUT_SECONDS, + default=DEFAULT_CLOSE_TIMEOUT_SECONDS, + ) + self.drop_report_interval = max(1, int(drop_report_interval)) + self._queue: queue_module.Queue[_QueuedRecord | None] = ( + queue_module.Queue(self.maxsize) + ) + self._listener = _BoundedQueueListener( + self._queue, + _QueuedRecordHandler( + inner, + on_failure, + forward_timestamp=_accepts_timestamp(inner), + ), + ) + self._dropped = 0 + self._closed = False + # Construction happens at configure time on the startup thread, + # never lazily on a request thread. + self._listener.start() + atexit.register(self.close) + + def emit( + self, + payload: dict[str, Any], + *, + log_type: str, + severity: str, + ) -> None: + try: + if self._closed: + self._record_drop("closed", log_type) + return + record = _QueuedRecord( + # Snapshot now: callers keep mutating nested structures + # after emit returns, and the write happens later on the + # listener thread. The enqueue time becomes the entry + # timestamp so delayed writes keep event time. + payload=normalize_payload(payload), + log_type=log_type, + severity=severity, + enqueued_at=datetime.now(UTC), + ) + try: + self._queue.put_nowait(record) + except queue_module.Full: + self._record_drop("full", log_type) + except Exception as exc: + self._record_drop("exception", log_type, exc=exc) + + def close(self, deadline_seconds: float | None = None) -> None: + if self._closed: + return + self._closed = True + atexit.unregister(self.close) + deadline = clamped( + deadline_seconds, + low=MIN_CLOSE_TIMEOUT_SECONDS, + high=MAX_CLOSE_TIMEOUT_SECONDS, + default=self.close_timeout_seconds, + ) + drained = self._listener.stop(timeout=deadline) + if not drained: + try: + self.on_failure( + "logging.queue_close_timeout", + TimeoutError( + "Observability log queue did not drain before " + "the close deadline; remaining records are lost." + ), + destination=self.name, + deadline_seconds=deadline, + pending_records=self._queue.qsize(), + ) + except Exception: + pass + # The abandoned listener may still be mid-write; leave the + # inner destination alone rather than closing it underneath + # an active write. + return + inner_close = getattr(self.inner, "close", None) + if callable(inner_close): + try: + inner_close() + except Exception as exc: + try: + self.on_failure( + "logging.destination_close", + exc, + destination=getattr(self.inner, "name", None), + ) + except Exception: + pass + + def _record_drop( + self, + reason: str, + log_type: str, + exc: BaseException | None = None, + ) -> None: + self._dropped += 1 + count = self._dropped + if count != 1 and count % self.drop_report_interval != 0: + return + try: + self.on_failure( + "logging.queue_drop", + exc + or RuntimeError("Observability log queue dropped a record."), + destination=self.name, + log_type=log_type, + reason=reason, + dropped_total=count, + queue_maxsize=self.maxsize, + ) + except Exception: + pass diff --git a/policyengine_observability/destinations/registry.py b/policyengine_observability/destinations/registry.py new file mode 100644 index 0000000..0be988f --- /dev/null +++ b/policyengine_observability/destinations/registry.py @@ -0,0 +1,49 @@ +"""Named destination strategies. + +Backend modules register themselves here so the manager can build +destinations without knowing any backend: an ``inline`` strategy writes +synchronously on the caller's thread (stdout — the durable, dependency- +free record), while every ``remote`` strategy is wrapped in the bounded +queue transport, so no remote write can ever run on a request thread. +""" + +from __future__ import annotations + +from collections.abc import Callable +from dataclasses import dataclass +from typing import Literal + +from .base import LogDestination + +# Factories are called with keyword arguments (config, loggers, +# serializer) and may ignore what they do not need. +DestinationFactory = Callable[..., LogDestination] + + +@dataclass(frozen=True) +class DestinationStrategy: + factory: DestinationFactory + transport: Literal["inline", "remote"] + + +_STRATEGIES: dict[str, DestinationStrategy] = {} + + +def register_destination( + name: str, + factory: DestinationFactory, + *, + transport: Literal["inline", "remote"], + aliases: tuple[str, ...] = (), +) -> None: + strategy = DestinationStrategy(factory=factory, transport=transport) + for key in (name, *aliases): + _STRATEGIES[_normalize(key)] = strategy + + +def destination_strategy(name: str) -> DestinationStrategy | None: + return _STRATEGIES.get(_normalize(name)) + + +def _normalize(name: str) -> str: + return name.strip().lower().replace("-", "_") diff --git a/policyengine_observability/destinations/stdout.py b/policyengine_observability/destinations/stdout.py index 8e8f6a6..391c312 100644 --- a/policyengine_observability/destinations/stdout.py +++ b/policyengine_observability/destinations/stdout.py @@ -5,6 +5,7 @@ from typing import Any from .base import normalize_payload +from .registry import register_destination # A stdout formatter shapes the normalized payload into the JSON line a # platform's log agent expects. Formatters are registered by name so @@ -82,3 +83,14 @@ def emit( logger.warning(message) else: logger.info(message) + + +def _stdout_factory(*, config: Any, loggers: Any, serializer: Any, **_: Any): + return StdoutJsonDestination( + loggers=loggers, + serializer=serializer, + formatter=resolve_stdout_formatter(config), + ) + + +register_destination("stdout", _stdout_factory, transport="inline") diff --git a/tests/test_queued_destination.py b/tests/test_queued_destination.py new file mode 100644 index 0000000..9eab2fa --- /dev/null +++ b/tests/test_queued_destination.py @@ -0,0 +1,453 @@ +"""QueuedLogDestination tests. + +Determinism strategy: real listener threads are used, but sequencing is +via threading.Event only — close()/stop() drain to a sentinel enqueued +behind the records, so "close then assert delivered" is deterministic. +The only real-time waits are bounded joins that are themselves the +behavior under test, with generous ceilings. +""" + +from __future__ import annotations + +import threading +import time +from datetime import UTC, datetime + +from policyengine_observability.destinations.queued import ( + QueuedLogDestination, +) + + +class RecordingInner: + name = "recording-inner" + + def __init__(self) -> None: + self.calls = [] + + def emit(self, payload, *, log_type, severity, timestamp=None) -> None: + self.calls.append((payload, log_type, severity, timestamp)) + + +class TimestampBlindInner: + name = "timestamp-blind" + + def __init__(self) -> None: + self.calls = [] + + def emit(self, payload, *, log_type, severity) -> None: + self.calls.append((payload, log_type, severity)) + + +class BlockingInner: + name = "blocking-inner" + + def __init__(self) -> None: + self.entered = threading.Event() + self.release = threading.Event() + self.calls = 0 + + def emit(self, payload, *, log_type, severity, timestamp=None) -> None: + self.calls += 1 + self.entered.set() + self.release.wait(10) + + +class FailingInner: + name = "failing-inner" + + def __init__(self, fail_first: int | None = None) -> None: + self.calls = 0 + self.fail_first = fail_first + self.delivered = [] + + def emit(self, payload, *, log_type, severity, timestamp=None) -> None: + self.calls += 1 + if self.fail_first is None or self.calls <= self.fail_first: + raise RuntimeError("write failed") + self.delivered.append(payload) + + +def _queued(inner, **kwargs): + failures = [] + destination = QueuedLogDestination( + inner=inner, + on_failure=lambda operation, exc, **fields: failures.append( + (operation, fields) + ), + **kwargs, + ) + return destination, failures + + +def _release_abandoned_listener(destination, blocking_inner) -> None: + """Let an abandoned listener thread exit so tests do not leak it.""" + blocking_inner.release.set() + try: + destination._queue.put_nowait(None) # the stdlib sentinel + except Exception: + pass + + +def test_close_drains_all_records_in_order_with_enqueue_timestamps() -> None: + inner = RecordingInner() + destination, failures = _queued(inner) + before = datetime.now(UTC) + + for index in range(5): + destination.emit({"index": index}, log_type="event", severity="INFO") + destination.close(5.0) + + assert [payload["index"] for payload, *_ in inner.calls] == [ + 0, + 1, + 2, + 3, + 4, + ] + for _payload, log_type, severity, timestamp in inner.calls: + assert log_type == "event" + assert severity == "INFO" + assert timestamp.tzinfo is not None + assert before <= timestamp <= datetime.now(UTC) + assert failures == [] + + +def test_timestamp_not_forwarded_to_blind_inner() -> None: + inner = TimestampBlindInner() + destination, failures = _queued(inner) + + destination.emit({"event": "x"}, log_type="event", severity="INFO") + destination.close(5.0) + + assert inner.calls == [({"event": "x"}, "event", "INFO")] + assert failures == [] + + +def test_payload_snapshot_taken_at_enqueue() -> None: + inner = RecordingInner() + destination, _failures = _queued(inner) + payload = {"nested": {"value": 1}} + + destination.emit(payload, log_type="event", severity="INFO") + payload["nested"]["value"] = 2 + destination.close(5.0) + + ((delivered, *_),) = inner.calls + assert delivered["nested"]["value"] == 1 + + +def test_overflow_drops_newest_and_throttles_reports() -> None: + inner = BlockingInner() + destination, failures = _queued(inner, maxsize=10, drop_report_interval=3) + + destination.emit({"index": 0}, log_type="event", severity="INFO") + assert inner.entered.wait(5) + # The listener holds record 0; fill the 10-slot queue, then drop 4. + started = time.monotonic() + for index in range(1, 15): + destination.emit({"index": index}, log_type="event", severity="INFO") + assert time.monotonic() - started < 1.0 + + drops = [fields for op, fields in failures if op == "logging.queue_drop"] + assert [d["dropped_total"] for d in drops] == [1, 3] + assert all(d["reason"] == "full" for d in drops) + assert all(d["queue_maxsize"] == 10 for d in drops) + assert destination._dropped == 4 + + inner.release.set() + destination.close(5.0) + + +def test_close_with_stuck_write_is_bounded_and_terminal() -> None: + inner = BlockingInner() + destination, failures = _queued(inner) + destination.emit({"index": 0}, log_type="event", severity="INFO") + assert inner.entered.wait(5) + destination.emit({"index": 1}, log_type="event", severity="INFO") + + started = time.monotonic() + destination.close(0.05) + elapsed = time.monotonic() - started + + assert elapsed < 1.0 + timeouts = [ + fields + for op, fields in failures + if op == "logging.queue_close_timeout" + ] + assert len(timeouts) == 1 + assert timeouts[0]["pending_records"] >= 1 + + destination.emit({"index": 2}, log_type="event", severity="INFO") + drops = [fields for op, fields in failures if op == "logging.queue_drop"] + assert drops[-1]["reason"] == "closed" + + _release_abandoned_listener(destination, inner) + + +def test_close_with_sentinel_blocked_by_full_queue_is_bounded() -> None: + inner = BlockingInner() + destination, failures = _queued(inner, maxsize=10) + destination.emit({"index": 0}, log_type="event", severity="INFO") + assert inner.entered.wait(5) + for index in range(1, 11): + destination.emit({"index": index}, log_type="event", severity="INFO") + + started = time.monotonic() + destination.close(0.05) + elapsed = time.monotonic() - started + + assert elapsed < 1.0 + assert any(op == "logging.queue_close_timeout" for op, _fields in failures) + + _release_abandoned_listener(destination, inner) + + +def test_listener_survives_write_failures_and_throttles_reports() -> None: + inner = FailingInner(fail_first=3) + destination, failures = _queued(inner) + + for index in range(5): + destination.emit({"index": index}, log_type="event", severity="INFO") + destination.close(5.0) + + assert [p["index"] for p in inner.delivered] == [3, 4] + writes = [fields for op, fields in failures if op == "logging.queue_write"] + # Throttle: failure 1 reports, failures 2-3 are under the interval. + assert [w["write_failures_total"] for w in writes] == [1] + assert writes[0]["destination"] == "failing-inner" + + +def test_emit_never_raises() -> None: + inner = RecordingInner() + destination, _failures = _queued(inner) + destination.on_failure = _raise_on_failure + + poisoned = {} + poisoned["self"] = poisoned # RecursionError inside normalize + destination.emit(poisoned, log_type="event", severity="INFO") + + destination.close(5.0) + destination.emit({"event": "x"}, log_type="event", severity="INFO") + + blocked = BlockingInner() + full_destination, _ = _queued(blocked, maxsize=10) + full_destination.on_failure = _raise_on_failure + for index in range(12): + full_destination.emit( + {"index": index}, log_type="event", severity="INFO" + ) + + blocked.release.set() + full_destination.on_failure = lambda *args, **kwargs: None + full_destination.close(5.0) + + +def _raise_on_failure(*args, **kwargs): + raise RuntimeError("reporting channel is broken") + + +def test_atexit_registered_on_construction_unregistered_on_close( + monkeypatch, +) -> None: + registered = [] + unregistered = [] + monkeypatch.setattr( + "policyengine_observability.destinations.queued.atexit.register", + lambda func: registered.append(func), + ) + monkeypatch.setattr( + "policyengine_observability.destinations.queued.atexit.unregister", + lambda func: unregistered.append(func), + ) + inner = RecordingInner() + + destination, failures = _queued(inner) + destination.close(5.0) + destination.close(5.0) # idempotent: no second stop, no reports + + assert registered == [destination.close] + assert unregistered == [destination.close] + assert failures == [] + + +def test_close_forwards_to_inner_close_only_when_drained() -> None: + class ClosableInner(RecordingInner): + def __init__(self) -> None: + super().__init__() + self.closed = 0 + + def close(self) -> None: + self.closed += 1 + + inner = ClosableInner() + destination, _failures = _queued(inner) + destination.emit({"event": "x"}, log_type="event", severity="INFO") + destination.close(5.0) + + assert inner.closed == 1 + + +def test_knobs_are_clamped() -> None: + inner = RecordingInner() + destination, _failures = _queued( + inner, maxsize=float("inf"), close_timeout_seconds=-5 + ) + + assert destination.maxsize == 1000 + assert destination.close_timeout_seconds == 0.0 + destination.close(5.0) + + +# ── Destination registry ───────────────────────────────────────────────── + + +def test_registry_builds_remote_wrapped_and_inline_bare() -> None: + import json + import logging + + from policyengine_observability.config import ObservabilityConfig + from policyengine_observability.destinations.manager import ( + LogDestinationManager, + ) + from policyengine_observability.destinations.registry import ( + _STRATEGIES, + register_destination, + ) + + register_destination( + "fake-remote", + lambda **kwargs: RecordingInner(), + transport="remote", + ) + try: + manager = LogDestinationManager( + config=ObservabilityConfig( + log_destinations=("fake_remote", "stdout") + ), + loggers={"event": logging.getLogger("test-registry")}, + serializer=json.dumps, + on_failure=lambda *args, **kwargs: None, + ) + manager.configure() + + remote, inline = manager.destinations + assert isinstance(remote, QueuedLogDestination) + assert remote.name == "queued_recording-inner" + assert not isinstance(inline, QueuedLogDestination) + manager.close() + finally: + _STRATEGIES.pop("fake_remote", None) + + +def test_registry_unknown_name_reports_config_failure() -> None: + import json + import logging + + from policyengine_observability.config import ObservabilityConfig + from policyengine_observability.destinations.manager import ( + LogDestinationManager, + ) + + failures = [] + manager = LogDestinationManager( + config=ObservabilityConfig(log_destinations=("nonexistent",)), + loggers={"event": logging.getLogger("test-registry")}, + serializer=json.dumps, + on_failure=lambda operation, exc, **fields: failures.append( + (operation, fields) + ), + ) + manager.configure() + + assert any( + op == "logging.destination_config" + and fields.get("destination") == "nonexistent" + for op, fields in failures + ) + + +def test_google_strategy_registered_as_remote_with_aliases() -> None: + from policyengine_observability.destinations.registry import ( + destination_strategy, + ) + + canonical = destination_strategy("google_cloud_logging") + assert canonical is not None + assert canonical.transport == "remote" + assert destination_strategy("google") is canonical + assert destination_strategy(" Google-Cloud ") is canonical + + +# ── Manager integration ────────────────────────────────────────────────── + + +def test_manager_breaker_never_disables_queued_destination() -> None: + import json + import logging + + from policyengine_observability.config import ObservabilityConfig + from policyengine_observability.destinations.manager import ( + LogDestinationManager, + ) + + inner = FailingInner() + failures = [] + manager = LogDestinationManager( + config=ObservabilityConfig(), + loggers={"event": logging.getLogger("test-breaker")}, + serializer=json.dumps, + on_failure=lambda operation, exc, **fields: failures.append(operation), + ) + destination = QueuedLogDestination( + inner=inner, on_failure=manager.on_failure + ) + manager.destinations = [destination] + manager.configured = True + + for _ in range(5): + manager.emit({"event": "x"}, log_type="event", severity="INFO") + destination.close(5.0) + + assert destination in manager.destinations + assert "logging.destination_disabled" not in failures + assert "logging.destination_emit" not in failures + + +def test_reconfigure_closes_previous_destinations() -> None: + import json + import logging + + from policyengine_observability.config import ObservabilityConfig + from policyengine_observability.destinations.manager import ( + LogDestinationManager, + ) + from policyengine_observability.destinations.registry import ( + _STRATEGIES, + register_destination, + ) + + register_destination( + "fake-remote", + lambda **kwargs: RecordingInner(), + transport="remote", + ) + try: + manager = LogDestinationManager( + config=ObservabilityConfig(log_destinations=("fake_remote",)), + loggers={"event": logging.getLogger("test-reconfigure")}, + serializer=json.dumps, + on_failure=lambda *args, **kwargs: None, + ) + manager.configure() + first = manager.destinations[0] + manager._consecutive_failures[id(first)] = 2 + + manager.configure() + + assert first._closed is True + assert manager._consecutive_failures == {} + assert manager.destinations[0] is not first + manager.close() + finally: + _STRATEGIES.pop("fake_remote", None) diff --git a/tests/test_runtime.py b/tests/test_runtime.py index d761765..58443d2 100644 --- a/tests/test_runtime.py +++ b/tests/test_runtime.py @@ -19,7 +19,7 @@ from policyengine_observability import runtime as runtime_module from policyengine_observability.config import DEFAULT_METRIC_ATTRIBUTE_KEYS from policyengine_observability.destinations import ( - manager as destination_manager_module, + google_cloud_logging as google_cloud_logging_module, ) @@ -1182,6 +1182,26 @@ def test_from_env_reads_stdout_format(monkeypatch) -> None: assert config.stdout_format == "google" +def test_from_env_reads_queue_knobs(monkeypatch) -> None: + monkeypatch.setenv("OBSERVABILITY_LOG_QUEUE_MAXSIZE", "50") + monkeypatch.setenv("OBSERVABILITY_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS", "1.5") + + config = ObservabilityConfig.from_env(service_name="svc") + + assert config.log_queue_maxsize == 50 + assert config.log_queue_close_timeout_seconds == 1.5 + + +def test_from_env_queue_knobs_fall_back_on_garbage(monkeypatch) -> None: + monkeypatch.setenv("OBSERVABILITY_LOG_QUEUE_MAXSIZE", "many") + monkeypatch.setenv("OBSERVABILITY_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS", "soon") + + config = ObservabilityConfig.from_env(service_name="svc") + + assert config.log_queue_maxsize == 1000 + assert config.log_queue_close_timeout_seconds == 2.0 + + def test_from_env_google_write_timeout_defaults(monkeypatch) -> None: monkeypatch.setenv("OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS", "bad") @@ -1925,7 +1945,7 @@ def fail_google_destination(**_kwargs): raise ImportError("google-cloud-logging missing") monkeypatch.setattr( - destination_manager_module, + google_cloud_logging_module, "GoogleCloudLoggingDestination", fail_google_destination, ) @@ -1952,7 +1972,7 @@ def fail_google_destination(**_kwargs): raise AssertionError("google destination should not initialize") monkeypatch.setattr( - destination_manager_module, + google_cloud_logging_module, "GoogleCloudLoggingDestination", fail_google_destination, ) From b687aa067d4a9a97bf3d5a67e49f87a4e0ac57ac Mon Sep 17 00:00:00 2001 From: Anthony Volk Date: Wed, 8 Jul 2026 22:25:25 +0200 Subject: [PATCH 4/9] Bound shutdown around destination close and add restart_observability MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit shutdown() now closes log destinations first, inline (destination close is inherently deadline-bounded), with a deadline derived from the shutdown budget: half when OTel providers still need flushing, the full budget otherwise. The provider flush thread is only spawned when providers exist and is joined with the remaining budget, so a slow log sink can never starve the OTel flush and a disabled runtime spawns no thread. The budget itself is clamped against pathological env values. restart_observability() closes and rebuilds log destinations from configuration for forked or snapshot-restored processes, documented for single-threaded lifecycle moments only — no locking machinery. Co-Authored-By: Claude Fable 5 --- changelog.d/22.restart.added.md | 1 + policyengine_observability/__init__.py | 12 +++ policyengine_observability/runtime.py | 34 ++++++++- tests/test_public_api.py | 2 + tests/test_runtime.py | 100 +++++++++++++++++++++++++ 5 files changed, 147 insertions(+), 2 deletions(-) create mode 100644 changelog.d/22.restart.added.md diff --git a/changelog.d/22.restart.added.md b/changelog.d/22.restart.added.md new file mode 100644 index 0000000..604c900 --- /dev/null +++ b/changelog.d/22.restart.added.md @@ -0,0 +1 @@ +Added `restart_observability()`: closes and rebuilds log destinations from configuration, for runtimes whose processes fork or restore from memory snapshots (threads and network clients survive neither). Documented for single-threaded lifecycle moments only — post-snapshot-restore hooks, post-fork hooks, before serving traffic. Runtime shutdown now closes log destinations first, inside the same shutdown budget that bounds the OpenTelemetry flush. diff --git a/policyengine_observability/__init__.py b/policyengine_observability/__init__.py index 88a8fdf..ca5f7c7 100644 --- a/policyengine_observability/__init__.py +++ b/policyengine_observability/__init__.py @@ -109,6 +109,17 @@ def shutdown_tracing() -> None: shutdown_observability() +def restart_observability() -> None: + """Close and rebuild log destinations from configuration. + + For runtimes whose processes fork or restore from memory snapshots + (threads and network clients do not survive either). Call ONLY from + single-threaded lifecycle moments — a post-snapshot-restore hook, a + post-fork hook, before serving traffic. + """ + observability_runtime().restart_log_destinations() + + def operation(name: str, *, flavor: str | None = None, **attrs: Any): return observability_runtime().operation(name, flavor=flavor, **attrs) @@ -167,6 +178,7 @@ def collect_timings(name: str = "operation", **attrs: Any): "operation", "record_error", "record_event", + "restart_observability", "segment", "set_attribute", "set_observability_runtime", diff --git a/policyengine_observability/runtime.py b/policyengine_observability/runtime.py index 8fbda49..839291e 100644 --- a/policyengine_observability/runtime.py +++ b/policyengine_observability/runtime.py @@ -24,6 +24,7 @@ _metric_attrs, ) from .destinations import LogDestinationManager +from .destinations.base import clamped from .logging import configure_plain_logger from .segments import coerce_segment_name @@ -1071,6 +1072,12 @@ def instrument_httpx(self) -> None: self.log_observability_failure("httpx.auto_instrument", exc) def shutdown(self) -> None: + budget = clamped( + self.config.shutdown_timeout_seconds, + low=0.0, + high=60.0, + default=3.0, + ) providers = [ ("trace", self.tracer_provider), ("metrics", self.meter_provider), @@ -1080,8 +1087,20 @@ def shutdown(self) -> None: for name, provider in providers if provider is not None ] + # Destination close is inherently deadline-bounded, so it runs + # inline and first, with a deadline that leaves room for the + # provider flush when there is one. Everything below fits inside + # the one shutdown budget by construction. + started = time.monotonic() + try: + self.log_destination_manager.close( + budget / 2 if providers else budget + ) + except BaseException as exc: + self.log_observability_failure("logging.destination_close", exc) if not providers: return + remaining = max(0.0, budget - (time.monotonic() - started)) def flush() -> None: for name, provider in providers: @@ -1099,17 +1118,28 @@ def flush() -> None: daemon=True, ) thread.start() - thread.join(timeout=self.config.shutdown_timeout_seconds) + thread.join(timeout=remaining) if thread.is_alive(): self.log_observability_failure( "otel.shutdown_timeout", TimeoutError("OpenTelemetry shutdown timed out."), - timeout_seconds=self.config.shutdown_timeout_seconds, + timeout_seconds=remaining, ) def shutdown_tracing(self) -> None: self.shutdown() + def restart_log_destinations(self) -> None: + """Close and rebuild log destinations from configuration. + + Call ONLY from single-threaded lifecycle moments — a + post-snapshot-restore hook, a post-fork hook, before serving + traffic. There is deliberately no locking here: under that + contract there is no concurrency, and a violated contract costs + at most a counted drop into a closing destination. + """ + self.log_destination_manager.configure() + def log_observability_failure( self, operation: str, diff --git a/tests/test_public_api.py b/tests/test_public_api.py index 26bfbaa..9b3b6a6 100644 --- a/tests/test_public_api.py +++ b/tests/test_public_api.py @@ -84,9 +84,11 @@ async def async_step() -> str: observability.instrument_httpx() observability.shutdown_tracing() observability.shutdown_observability() + observability.restart_observability() assert runtime.operation_duration.calls assert runtime.segment_duration.calls + assert runtime.log_destination_manager.configured is True def test_setting_public_runtime_clears_stale_context() -> None: diff --git a/tests/test_runtime.py b/tests/test_runtime.py index 58443d2..bb8e72f 100644 --- a/tests/test_runtime.py +++ b/tests/test_runtime.py @@ -1455,6 +1455,106 @@ def shutdown(self) -> None: assert "otel.shutdown_timeout" in failures +def test_shutdown_closes_destinations_with_full_budget_and_no_thread( + monkeypatch, +) -> None: + observed = runtime(shutdown_timeout_seconds=2.0) + close_calls = [] + monkeypatch.setattr( + observed.log_destination_manager, + "close", + lambda deadline=None: close_calls.append(deadline), + ) + + def fail_thread(*args, **kwargs): + raise AssertionError( + "no watchdog thread should exist without providers" + ) + + monkeypatch.setattr(runtime_module.threading, "Thread", fail_thread) + + observed.shutdown() + + assert close_calls == [2.0] + + +def test_shutdown_destination_deadline_fits_inside_provider_budget( + monkeypatch, +) -> None: + """The prior design gave the log flush a deadline larger than the + join bounding it, starving provider shutdown; the deadline must be + derived from (and smaller than) the shutdown budget.""" + + class Provider: + def __init__(self) -> None: + self.shutdown_called = False + + def shutdown(self) -> None: + self.shutdown_called = True + + observed = runtime(shutdown_timeout_seconds=2.0) + provider = Provider() + observed.tracer_provider = provider + close_calls = [] + monkeypatch.setattr( + observed.log_destination_manager, + "close", + lambda deadline=None: close_calls.append(deadline), + ) + + observed.shutdown() + + assert close_calls == [1.0] + assert provider.shutdown_called + + +def test_shutdown_slow_destination_close_still_runs_providers() -> None: + class Provider: + def __init__(self) -> None: + self.shutdown_called = False + + def shutdown(self) -> None: + self.shutdown_called = True + + observed = runtime(shutdown_timeout_seconds=0.2) + provider = Provider() + observed.tracer_provider = provider + observed.log_destination_manager.close = lambda deadline=None: time.sleep( + 0.05 + ) + + observed.shutdown() + + assert provider.shutdown_called + + +def test_shutdown_clamps_pathological_budget(monkeypatch) -> None: + observed = runtime(shutdown_timeout_seconds=float("inf")) + close_calls = [] + monkeypatch.setattr( + observed.log_destination_manager, + "close", + lambda deadline=None: close_calls.append(deadline), + ) + + observed.shutdown() + + assert close_calls == [3.0] + + +def test_restart_log_destinations_rebuilds_from_config() -> None: + observed = runtime(otel_enabled=False) + observed.configure() + first = observed.log_destination_manager.destinations[0] + + observed.restart_log_destinations() + + rebuilt = observed.log_destination_manager.destinations + assert len(rebuilt) == 1 + assert rebuilt[0] is not first + assert observed.log_destination_manager.configured is True + + def test_configure_otel_creates_real_providers_and_instruments() -> None: observed = runtime(otel_enabled=True) From 432bd19ae2a17bc3268f2d28e5a59fdb605072e6 Mon Sep 17 00:00:00 2001 From: Anthony Volk Date: Wed, 8 Jul 2026 22:28:30 +0200 Subject: [PATCH 5/9] Add log profiles with platform auto-detection MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit One env var now expands to a full routing configuration: OBSERVABILITY_LOG_PROFILE=gcp-agent (agent-native google-format stdout only), gcp-direct (plain stdout plus queued direct Cloud Logging writes), plain-sync (plain stdout, guaranteed zero threads — the kill switch), or auto (default). Auto detects the platform in precedence order OBSERVABILITY_PLATFORM, K_SERVICE, Modal markers, and preserves caller-supplied defaults when nothing matches, so consumers stop carrying platform routing logic. Profiles are presets expanding to generic primitives (destination names and a formatter name); the mechanism knows no backend. Explicit OBSERVABILITY_LOG_DESTINATIONS and OBSERVABILITY_STDOUT_FORMAT still override the expansion, gcp-direct downgrades to plain-sync with a warning when no Google Cloud project is resolvable, and unknown profiles warn and fall back to plain-sync; the manager reports these warnings through the internal-error channel at configure time. Co-Authored-By: Claude Fable 5 --- changelog.d/22.profiles.added.md | 1 + policyengine_observability/config.py | 107 +++++++- .../destinations/manager.py | 2 + tests/test_log_profiles.py | 251 ++++++++++++++++++ 4 files changed, 348 insertions(+), 13 deletions(-) create mode 100644 changelog.d/22.profiles.added.md create mode 100644 tests/test_log_profiles.py diff --git a/changelog.d/22.profiles.added.md b/changelog.d/22.profiles.added.md new file mode 100644 index 0000000..15dfff4 --- /dev/null +++ b/changelog.d/22.profiles.added.md @@ -0,0 +1 @@ +Added log profiles (`OBSERVABILITY_LOG_PROFILE`): one env var expands to a full routing configuration — `gcp-agent` (agent-native google-format stdout only, for platforms whose agent ingests stdout), `gcp-direct` (plain stdout plus queued direct Cloud Logging writes, for platforms without an agent), `plain-sync` (plain stdout, guaranteed zero threads — the kill switch), and `auto` (default: detects the platform via `OBSERVABILITY_PLATFORM`, `K_SERVICE`, or Modal markers, and preserves caller defaults when none match). Explicit `OBSERVABILITY_LOG_DESTINATIONS`/`OBSERVABILITY_STDOUT_FORMAT` still override the expansion; `gcp-direct` downgrades to `plain-sync` with a warning when no Google Cloud project is resolvable. diff --git a/policyengine_observability/config.py b/policyengine_observability/config.py index 216d4fd..d31bc90 100644 --- a/policyengine_observability/config.py +++ b/policyengine_observability/config.py @@ -75,6 +75,69 @@ def default_environment() -> str: ) +# A log profile is a named preset expanding to generic routing primitives +# (a destination-name tuple and a stdout-formatter name). Presets may name +# strategies; the expansion mechanism knows nothing about any backend. +LOG_PROFILE_PRESETS: dict[str, tuple[tuple[str, ...], str]] = { + # Platforms whose logging agent ingests stdout (Cloud Run, GKE): + # agent-native stdout only, fully synchronous, zero threads. + "gcp-agent": (("stdout",), "google"), + # Platforms with no ingesting agent (Modal): plain stdout as the + # durable record plus queued direct Cloud Logging writes. + "gcp-direct": (("stdout", "google_cloud_logging"), "plain"), + # Local development and the kill switch: plain stdout, zero threads. + "plain-sync": (("stdout",), "plain"), +} + + +def _detect_log_profile() -> str | None: + platform = (os.getenv("OBSERVABILITY_PLATFORM") or "").strip().lower() + if platform == "google_cloud_run": + return "gcp-agent" + if platform == "modal": + return "gcp-direct" + if os.getenv("K_SERVICE"): + return "gcp-agent" + if os.getenv("MODAL_ENVIRONMENT") or os.getenv("MODAL_TASK_ID"): + return "gcp-direct" + return None + + +def _resolve_log_profile( + raw_profile: str, + *, + google_cloud_project: str | None, +) -> tuple[str, tuple[tuple[str, ...], str] | None, list[str]]: + """Resolve a profile name to (name, preset-or-None, warnings). + + ``auto`` without a recognized platform marker resolves to no preset, + so caller-supplied defaults keep applying. + """ + warnings: list[str] = [] + profile = raw_profile.strip().lower() + if profile == "auto": + detected = _detect_log_profile() + if detected is None: + return "auto", None, warnings + profile = detected + preset = LOG_PROFILE_PRESETS.get(profile) + if preset is None: + warnings.append( + f"Unknown OBSERVABILITY_LOG_PROFILE {raw_profile!r}; " + "using plain-sync." + ) + profile = "plain-sync" + preset = LOG_PROFILE_PRESETS[profile] + if "google_cloud_logging" in preset[0] and not google_cloud_project: + warnings.append( + "Log profile gcp-direct requires a resolvable Google Cloud " + "project; using plain-sync." + ) + profile = "plain-sync" + preset = LOG_PROFILE_PRESETS[profile] + return profile, preset, warnings + + @dataclass(frozen=True) class ObservabilityConfig: service_name: str = "policyengine-service" @@ -101,6 +164,8 @@ class ObservabilityConfig: stdout_format: str = "plain" log_queue_maxsize: int = 1000 log_queue_close_timeout_seconds: float = 2.0 + log_profile: str = "auto" + config_warnings: tuple[str, ...] = () @classmethod def from_env( @@ -134,6 +199,30 @@ def from_env( or DEFAULT_METRIC_ATTRIBUTE_KEYS, (*extra_metric_attribute_keys, *env_extra_metric_keys), ) + google_cloud_project = ( + os.getenv("OBSERVABILITY_GOOGLE_CLOUD_PROJECT") + or os.getenv("GOOGLE_CLOUD_PROJECT") + or os.getenv("GCP_PROJECT") + or os.getenv("GCLOUD_PROJECT") + or None + ) + log_profile, preset, profile_warnings = _resolve_log_profile( + os.getenv("OBSERVABILITY_LOG_PROFILE") or cls.log_profile, + google_cloud_project=google_cloud_project, + ) + profile_destinations, profile_stdout_format = preset or (None, None) + # Explicit granular env vars override the profile's expansion; + # the profile overrides caller-supplied defaults. + resolved_log_destinations = _dedupe( + env_log_destinations + or profile_destinations + or default_log_destinations + ) + resolved_stdout_format = ( + os.getenv("OBSERVABILITY_STDOUT_FORMAT") + or profile_stdout_format + or cls.stdout_format + ) return cls( service_name=os.getenv("OBSERVABILITY_SERVICE_NAME") or os.getenv("OTEL_SERVICE_NAME") @@ -166,16 +255,8 @@ def from_env( instrument_httpx, ), metric_attribute_keys=resolved_metric_keys, - log_destinations=_dedupe( - env_log_destinations or default_log_destinations - ), - google_cloud_project=( - os.getenv("OBSERVABILITY_GOOGLE_CLOUD_PROJECT") - or os.getenv("GOOGLE_CLOUD_PROJECT") - or os.getenv("GCP_PROJECT") - or os.getenv("GCLOUD_PROJECT") - or None - ), + log_destinations=resolved_log_destinations, + google_cloud_project=google_cloud_project, google_cloud_log_name=( os.getenv("OBSERVABILITY_GOOGLE_CLOUD_LOG_NAME") or cls.google_cloud_log_name @@ -184,9 +265,7 @@ def from_env( "OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS", cls.google_cloud_write_timeout_seconds, ), - stdout_format=( - os.getenv("OBSERVABILITY_STDOUT_FORMAT") or cls.stdout_format - ), + stdout_format=resolved_stdout_format, log_queue_maxsize=int_from_env( "OBSERVABILITY_LOG_QUEUE_MAXSIZE", cls.log_queue_maxsize, @@ -195,6 +274,8 @@ def from_env( "OBSERVABILITY_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS", cls.log_queue_close_timeout_seconds, ), + log_profile=log_profile, + config_warnings=tuple(profile_warnings), ) diff --git a/policyengine_observability/destinations/manager.py b/policyengine_observability/destinations/manager.py index 4b2dd0d..f369d76 100644 --- a/policyengine_observability/destinations/manager.py +++ b/policyengine_observability/destinations/manager.py @@ -73,6 +73,8 @@ def configure(self) -> None: exc, destination=destination_name, ) + for warning in getattr(self.config, "config_warnings", ()): + self.on_failure("logging.profile_config", ValueError(warning)) def emit( self, diff --git a/tests/test_log_profiles.py b/tests/test_log_profiles.py new file mode 100644 index 0000000..2250160 --- /dev/null +++ b/tests/test_log_profiles.py @@ -0,0 +1,251 @@ +from __future__ import annotations + +import json +import logging + +import pytest + +from policyengine_observability.config import ObservabilityConfig +from policyengine_observability.destinations.manager import ( + LogDestinationManager, +) +from policyengine_observability.destinations.queued import ( + QueuedLogDestination, +) + +PLATFORM_MARKERS = ( + "OBSERVABILITY_LOG_PROFILE", + "OBSERVABILITY_PLATFORM", + "K_SERVICE", + "MODAL_ENVIRONMENT", + "MODAL_TASK_ID", + "OBSERVABILITY_LOG_DESTINATIONS", + "OBSERVABILITY_STDOUT_FORMAT", + "OBSERVABILITY_GOOGLE_CLOUD_PROJECT", + "GOOGLE_CLOUD_PROJECT", + "GCP_PROJECT", + "GCLOUD_PROJECT", +) + + +@pytest.fixture(autouse=True) +def _clean_environment(monkeypatch): + for name in PLATFORM_MARKERS: + monkeypatch.delenv(name, raising=False) + + +def _from_env(monkeypatch, **env): + for name, value in env.items(): + monkeypatch.setenv(name, value) + return ObservabilityConfig.from_env(service_name="svc") + + +def test_explicit_gcp_agent_profile(monkeypatch) -> None: + config = _from_env(monkeypatch, OBSERVABILITY_LOG_PROFILE="gcp-agent") + + assert config.log_profile == "gcp-agent" + assert config.log_destinations == ("stdout",) + assert config.stdout_format == "google" + assert config.config_warnings == () + + +def test_explicit_gcp_direct_profile_with_project(monkeypatch) -> None: + config = _from_env( + monkeypatch, + OBSERVABILITY_LOG_PROFILE="gcp-direct", + OBSERVABILITY_GOOGLE_CLOUD_PROJECT="proj", + ) + + assert config.log_profile == "gcp-direct" + assert config.log_destinations == ("stdout", "google_cloud_logging") + assert config.stdout_format == "plain" + assert config.config_warnings == () + + +def test_gcp_direct_without_project_downgrades_with_warning( + monkeypatch, +) -> None: + config = _from_env(monkeypatch, OBSERVABILITY_LOG_PROFILE="gcp-direct") + + assert config.log_profile == "plain-sync" + assert config.log_destinations == ("stdout",) + assert config.stdout_format == "plain" + assert len(config.config_warnings) == 1 + assert "Google Cloud project" in config.config_warnings[0] + + +def test_explicit_plain_sync_profile_is_kill_switch(monkeypatch) -> None: + config = _from_env( + monkeypatch, + OBSERVABILITY_LOG_PROFILE="plain-sync", + OBSERVABILITY_PLATFORM="modal", + OBSERVABILITY_GOOGLE_CLOUD_PROJECT="proj", + ) + + assert config.log_profile == "plain-sync" + assert config.log_destinations == ("stdout",) + assert config.stdout_format == "plain" + + +def test_unknown_profile_falls_back_to_plain_sync_with_warning( + monkeypatch, +) -> None: + config = _from_env(monkeypatch, OBSERVABILITY_LOG_PROFILE="gcp-agnet") + + assert config.log_profile == "plain-sync" + assert config.log_destinations == ("stdout",) + assert any("gcp-agnet" in w for w in config.config_warnings) + + +def test_auto_detects_cloud_run_via_observability_platform( + monkeypatch, +) -> None: + config = _from_env(monkeypatch, OBSERVABILITY_PLATFORM="google_cloud_run") + + assert config.log_profile == "gcp-agent" + assert config.stdout_format == "google" + + +def test_auto_detects_modal_via_observability_platform(monkeypatch) -> None: + config = _from_env( + monkeypatch, + OBSERVABILITY_PLATFORM="modal", + OBSERVABILITY_GOOGLE_CLOUD_PROJECT="proj", + ) + + assert config.log_profile == "gcp-direct" + assert config.log_destinations == ("stdout", "google_cloud_logging") + + +def test_auto_detects_cloud_run_via_k_service(monkeypatch) -> None: + config = _from_env(monkeypatch, K_SERVICE="household-api") + + assert config.log_profile == "gcp-agent" + + +def test_auto_detects_modal_via_task_marker(monkeypatch) -> None: + config = _from_env( + monkeypatch, + MODAL_TASK_ID="ta-123", + OBSERVABILITY_GOOGLE_CLOUD_PROJECT="proj", + ) + + assert config.log_profile == "gcp-direct" + + +def test_observability_platform_beats_generic_markers(monkeypatch) -> None: + config = _from_env( + monkeypatch, + OBSERVABILITY_PLATFORM="google_cloud_run", + MODAL_TASK_ID="ta-123", + ) + + assert config.log_profile == "gcp-agent" + + +def test_auto_without_markers_preserves_caller_defaults(monkeypatch) -> None: + config = ObservabilityConfig.from_env( + service_name="svc", + default_log_destinations=("stdout", "custom"), + ) + + assert config.log_profile == "auto" + assert config.log_destinations == ("stdout", "custom") + assert config.stdout_format == "plain" + assert config.config_warnings == () + + +def test_explicit_destination_env_overrides_profile(monkeypatch) -> None: + config = _from_env( + monkeypatch, + OBSERVABILITY_LOG_PROFILE="gcp-agent", + OBSERVABILITY_LOG_DESTINATIONS="stdout,google_cloud_logging", + OBSERVABILITY_GOOGLE_CLOUD_PROJECT="proj", + ) + + assert config.log_destinations == ("stdout", "google_cloud_logging") + # The profile's other half still applies. + assert config.stdout_format == "google" + + +def test_explicit_stdout_format_env_overrides_profile(monkeypatch) -> None: + config = _from_env( + monkeypatch, + OBSERVABILITY_LOG_PROFILE="gcp-agent", + OBSERVABILITY_STDOUT_FORMAT="plain", + ) + + assert config.stdout_format == "plain" + assert config.log_destinations == ("stdout",) + + +def _configured_manager(config): + failures = [] + manager = LogDestinationManager( + config=config, + loggers={"event": logging.getLogger("test-profiles")}, + serializer=json.dumps, + on_failure=lambda operation, exc, **fields: failures.append( + (operation, str(exc)) + ), + ) + manager.configure() + return manager, failures + + +def test_sync_profiles_build_no_queued_destinations(monkeypatch) -> None: + for profile in ("gcp-agent", "plain-sync"): + config = _from_env(monkeypatch, OBSERVABILITY_LOG_PROFILE=profile) + manager, failures = _configured_manager(config) + + assert not any( + isinstance(destination, QueuedLogDestination) + for destination in manager.destinations + ) + assert failures == [] + + +def test_manager_reports_profile_warnings_once(monkeypatch) -> None: + config = _from_env(monkeypatch, OBSERVABILITY_LOG_PROFILE="bogus") + manager, failures = _configured_manager(config) + + warnings = [ + message + for operation, message in failures + if operation == "logging.profile_config" + ] + assert len(warnings) == 1 + assert "bogus" in warnings[0] + manager.close() + + +def test_gcp_direct_profile_builds_queued_google(monkeypatch) -> None: + from policyengine_observability.destinations import ( + google_cloud_logging as google_module, + ) + + class StubGoogle: + name = "google_cloud_logging" + + def __init__(self, **kwargs) -> None: + self.kwargs = kwargs + + def emit(self, payload, *, log_type, severity, timestamp=None): + pass + + monkeypatch.setattr( + google_module, "GoogleCloudLoggingDestination", StubGoogle + ) + config = _from_env( + monkeypatch, + OBSERVABILITY_LOG_PROFILE="gcp-direct", + OBSERVABILITY_GOOGLE_CLOUD_PROJECT="proj", + ) + manager, failures = _configured_manager(config) + + stdout_destination, queued = manager.destinations + assert isinstance(queued, QueuedLogDestination) + assert isinstance(queued.inner, StubGoogle) + assert queued.inner.kwargs["project"] == "proj" + assert failures == [] + manager.close() From 372921c87995285110f08b069f9720b3b5eb0694 Mon Sep 17 00:00:00 2001 From: Anthony Volk Date: Wed, 8 Jul 2026 22:30:24 +0200 Subject: [PATCH 6/9] Document log profiles, delivery semantics, and lifecycle Co-Authored-By: Claude Fable 5 --- README.md | 95 +++++++++++++++---- .../operations/google-cloud-stage3-runbook.md | 12 ++- 2 files changed, 83 insertions(+), 24 deletions(-) diff --git a/README.md b/README.md index 5a2ca2b..e23b9d4 100644 --- a/README.md +++ b/README.md @@ -15,38 +15,91 @@ configured, spans and metrics stay in-process while logs still receive trace context. Set `OTEL_ENABLED=false` to opt out. Configure `OTEL_EXPORTER_OTLP_ENDPOINT` to export traces and metrics. -Structured logs write to stdout by default: +## Log routing profiles + +Log routing is owned by this package: consumers set one env var and the +package expands it into destinations, formats, and transport. ```bash -OBSERVABILITY_LOG_DESTINATIONS=stdout +OBSERVABILITY_LOG_PROFILE=gcp-agent # or gcp-direct | plain-sync | auto ``` -Applications can override that default in code when constructing -`ObservabilityConfig`: +- `gcp-agent` — google-format stdout only, for platforms whose logging + agent ingests stdout (Cloud Run, GKE). Fully synchronous, zero + threads; the agent ships lines to Cloud Logging with severity, trace, + span, and labels promoted to first-class LogEntry fields. +- `gcp-direct` — plain stdout (the durable record) plus queued direct + Cloud Logging writes, for platforms with no ingesting agent (Modal). + Requires a resolvable Google Cloud project; downgrades to `plain-sync` + with a warning otherwise. +- `plain-sync` — plain stdout only, guaranteed zero threads. Local + development and the kill switch: setting it disables all background + log machinery. +- `auto` (default) — detects the platform via `OBSERVABILITY_PLATFORM` + (`google_cloud_run`/`modal`), then `K_SERVICE`, then Modal env + markers; when nothing matches, caller-supplied defaults apply. + +The granular controls still exist underneath and override the profile's +expansion when set explicitly: -```python -ObservabilityConfig.from_env( - service_name="policyengine-api", - default_log_destinations=("google_cloud_logging",), -) +```bash +OBSERVABILITY_LOG_DESTINATIONS=stdout,google_cloud_logging +OBSERVABILITY_STDOUT_FORMAT=google +OBSERVABILITY_GOOGLE_CLOUD_PROJECT=policyengine-api +OBSERVABILITY_GOOGLE_CLOUD_LOG_NAME=policyengine-observability ``` -`OBSERVABILITY_LOG_DESTINATIONS` still has precedence over application -defaults. Cloud Run captures stdout and stderr into Google Cloud Logging -automatically, but applications that need one consistent destination across -Cloud Run and non-GCP runtimes can write directly to Google Cloud Logging by -installing the `google` extra and enabling the Google destination: +Destinations are named strategies: `stdout` is `inline` (synchronous on +the caller's thread), and every `remote` strategy — `google_cloud_logging` +today; future backends register the same way — is automatically wrapped +in the queued transport below. Google Cloud Logging uses Application +Default Credentials and requires permission to create log entries, +typically through `roles/logging.logWriter`. + +## Log emission and delivery semantics + +Remote destinations never write on a request thread. The log call only +snapshots the payload, stamps the enqueue time, and appends to a bounded +in-memory queue (microseconds, never blocks, never raises); a stdlib +`QueueListener` thread drains the queue and performs the writes, sending +the enqueue time as the entry timestamp so delayed writes keep their +event time. + +Delivery through the queue is best-effort by design — stdout is the +durable sibling record. When the queue is full the newest record is +dropped, and drops are counted and reported through the internal-error +channel (first drop, then every 100th). Write failures are likewise +reported and the record dropped; there is deliberately no breaker or +retry queue in the transport. Each Google write carries an explicit +budget that caps the call and its transient-error retries: ```bash -OBSERVABILITY_LOG_DESTINATIONS=google_cloud_logging -OBSERVABILITY_GOOGLE_CLOUD_PROJECT=policyengine-api -OBSERVABILITY_GOOGLE_CLOUD_LOG_NAME=policyengine-observability +OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS=10.0 +OBSERVABILITY_LOG_QUEUE_MAXSIZE=1000 +OBSERVABILITY_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS=2.0 ``` -Multiple destinations can be enabled with a comma-separated list, for example -`OBSERVABILITY_LOG_DESTINATIONS=stdout,google_cloud_logging`. Google Cloud -Logging uses Application Default Credentials and requires permission to create -log entries, typically through `roles/logging.logWriter`. +(The bounded write rebinds the client's private gapic method at +construction; when that handle is unavailable — HTTP transports, +injected fakes — the library's ~60s default applies, which is harmless +off the request path. All numeric knobs are clamped, so `0`, negative, +or non-finite values can never disable or unbound a mechanism. Because +entries are written directly per record, the Google client library's +one-time instrumentation diagnostic entry is not emitted.) + +Shutdown closes log destinations inside the same bounded budget that +flushes OpenTelemetry (`OBSERVABILITY_SHUTDOWN_TIMEOUT_SECONDS`); a +queue that cannot drain before its deadline is abandoned with a report. +A hard kill loses whatever was still queued. Note the google stdout +format sets no `time` key: stdout emission is synchronous, so the +agent's receive time is the correct event time. + +Processes that fork or restore from memory snapshots do not preserve +threads or network clients. Call `restart_observability()` from the +post-restore or post-fork hook (for example gunicorn `post_fork` when +using `--preload`, or a Modal post-snapshot hook) — it closes and +rebuilds destinations from configuration, and must only be called from +single-threaded lifecycle moments, before serving traffic. Request and operation logs include two timing views: diff --git a/docs/operations/google-cloud-stage3-runbook.md b/docs/operations/google-cloud-stage3-runbook.md index 6f0ea5d..c6c25b2 100644 --- a/docs/operations/google-cloud-stage3-runbook.md +++ b/docs/operations/google-cloud-stage3-runbook.md @@ -100,7 +100,12 @@ the services being deployed. Use these variables for deployed Cloud Run and Modal environments: ```bash -OBSERVABILITY_LOG_DESTINATIONS=google_cloud_logging +# Cloud Run: the agent ingests stdout, no direct writes needed. +OBSERVABILITY_LOG_PROFILE=gcp-agent +OBSERVABILITY_GOOGLE_CLOUD_PROJECT= + +# Modal: stdout plus queued direct Cloud Logging writes. +OBSERVABILITY_LOG_PROFILE=gcp-direct OBSERVABILITY_GOOGLE_CLOUD_PROJECT= OBSERVABILITY_GOOGLE_CLOUD_LOG_NAME= OBSERVABILITY_GOOGLE_WORKLOAD_IDENTITY_PROVIDER=projects//locations/global/workloadIdentityPools//providers/ @@ -170,10 +175,11 @@ jsonPayload.event="observability_internal_error" ## Rollback -For a failing runtime, set: +For a failing runtime, set the kill switch — plain stdout only, with all +background log machinery disabled: ```bash -OBSERVABILITY_LOG_DESTINATIONS=stdout +OBSERVABILITY_LOG_PROFILE=plain-sync ``` To restore the temporary bridge destination, set: From ee055cf0f50bd42e7bfbabbd67b89f9e3c998aad Mon Sep 17 00:00:00 2001 From: Anthony Volk Date: Thu, 9 Jul 2026 15:36:57 +0200 Subject: [PATCH 7/9] Address review findings: lifecycle bugs, strategy purity, DRY, coverage MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Bugs: - restart_observability() now honors the OBSERVABILITY_ENABLED kill switch (mirrors configure()), so a disabled deployment's post-fork hook cannot build clients or start listener threads. - configure() installs the new destinations before closing the replaced ones, so close-phase failure reports (which route through emit) have a sink instead of vanishing into an empty destination list. - The Google client library's one-time instrumentation diagnostic entry is suppressed at construction, matching the documented behavior. - GoogleCloudLoggingDestination gains close(), so a drained queue close releases the owned client instead of leaking it on restart. - Manager close shares one monotonic deadline across all destinations, so N stuck closes cannot take N times the shutdown budget. Strategy purity: - Strategy requirements are declarative: register_destination() takes required_config, and profile expansion checks it generically — the google-conditional in core config is gone and the downgrade warning names the actual profile and missing fields. - Backend knobs are strategy-owned: the google factory parses OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS itself; the per-backend config field is removed. - register_destination/register_stdout_formatter exported at top level; google_credentials moved under destinations/ (shim kept). DRY: - Shared safe_report/_ThrottledCounter replace four hand-rolled guarded report sites; one close_destination() contract (deadline passed only when accepted) replaces two divergent duck-typed close conventions. - One normalize_name() for destination, formatter, and profile lookups; unknown stdout formats are reported instead of silently degrading. - Queue knob defaults hoisted to config; stdout construction unified in build_stdout_destination(); trace resource name built in one helper. Tests: shared fakes/conftest; new coverage for close-failure containment, configure-crash fallback, gcp-agent end-to-end formatting, constructor-level broken reporting channel, timed-out close leaving the inner destination alone, clamp boundary pins, knob wiring, restart delivery resumption, Modal auto-detection edge cases, and the restart/shutdown lifecycle guards. 216 tests, 92% branch coverage. Fixes #22 Co-Authored-By: Claude Fable 5 --- README.md | 25 +- changelog.d/22.added.md | 2 +- changelog.d/22.restart.added.md | 2 +- changelog.d/22.shutdown.changed.md | 1 + policyengine_observability/__init__.py | 5 +- policyengine_observability/config.py | 72 +++- .../destinations/__init__.py | 3 +- .../destinations/base.py | 70 +++- .../destinations/google_cloud_logging.py | 47 ++- .../destinations/google_credentials.py | 176 ++++++++ .../destinations/manager.py | 112 ++++-- .../destinations/queued.py | 155 ++++---- .../destinations/registry.py | 26 +- .../destinations/stdout.py | 47 ++- .../google_credentials.py | 202 ++-------- policyengine_observability/runtime.py | 7 +- tests/conftest.py | 21 + tests/fakes.py | 121 ++++++ tests/test_destinations.py | 328 ++++++++++----- tests/test_google_credentials.py | 10 +- tests/test_log_profiles.py | 89 +++-- tests/test_public_api.py | 20 + tests/test_queued_destination.py | 375 +++++++++--------- tests/test_runtime.py | 61 ++- 24 files changed, 1327 insertions(+), 650 deletions(-) create mode 100644 changelog.d/22.shutdown.changed.md create mode 100644 policyengine_observability/destinations/google_credentials.py create mode 100644 tests/conftest.py create mode 100644 tests/fakes.py diff --git a/README.md b/README.md index e23b9d4..ea3bcc5 100644 --- a/README.md +++ b/README.md @@ -56,6 +56,20 @@ in the queued transport below. Google Cloud Logging uses Application Default Credentials and requires permission to create log entries, typically through `roles/logging.logWriter`. +Backends plug in through two top-level hooks, `register_destination` +(with `transport="inline"|"remote"` and an optional `required_config` +tuple naming the config fields the strategy needs — profiles that name +the strategy downgrade gracefully when one is missing) and +`register_stdout_formatter`. Registration happens at import time, so an +external backend module must be imported before observability is +configured. Backend-specific knobs are the strategy's own: the Google +strategy reads `OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS` itself at +construction (so it is re-read on `restart_observability()`) rather +than through a core config field. Name lookups for destinations, +formatters, and profiles all forgive case, whitespace, and +hyphen/underscore variance; an unknown format name falls back to plain +and is reported through the internal-error channel. + ## Log emission and delivery semantics Remote destinations never write on a request thread. The log call only @@ -83,9 +97,10 @@ OBSERVABILITY_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS=2.0 construction; when that handle is unavailable — HTTP transports, injected fakes — the library's ~60s default applies, which is harmless off the request path. All numeric knobs are clamped, so `0`, negative, -or non-finite values can never disable or unbound a mechanism. Because -entries are written directly per record, the Google client library's -one-time instrumentation diagnostic entry is not emitted.) +or non-finite values can never disable or unbound a mechanism. The +Google client library's one-time instrumentation diagnostic entry is +suppressed at construction, so the stream carries only the records the +service asked to write.) Shutdown closes log destinations inside the same bounded budget that flushes OpenTelemetry (`OBSERVABILITY_SHUTDOWN_TIMEOUT_SECONDS`); a @@ -99,7 +114,9 @@ threads or network clients. Call `restart_observability()` from the post-restore or post-fork hook (for example gunicorn `post_fork` when using `--preload`, or a Modal post-snapshot hook) — it closes and rebuilds destinations from configuration, and must only be called from -single-threaded lifecycle moments, before serving traffic. +single-threaded lifecycle moments, before serving traffic. It is a +no-op when observability is disabled, so the kill switch holds across +forks and restores. Request and operation logs include two timing views: diff --git a/changelog.d/22.added.md b/changelog.d/22.added.md index 8da9b82..e2d37f7 100644 --- a/changelog.d/22.added.md +++ b/changelog.d/22.added.md @@ -1 +1 @@ -Added an agent-native stdout format (`OBSERVABILITY_STDOUT_FORMAT=google`): JSON lines carry the special keys the Cloud Run/GKE logging agent promotes to first-class LogEntry fields (severity, trace, span, labels), enabling full-fidelity Cloud Logging ingestion from stdout with no in-process network emission. Added a destination strategy registry and a generic queued transport: destinations register as `inline` (synchronous, e.g. stdout) or `remote`, and every remote destination is wrapped in a bounded queue drained by a stdlib QueueListener thread, so no remote write ever runs on a request thread. The queue drops-and-counts when full (throttled reports), and close is deadline-bounded (`OBSERVABILITY_LOG_QUEUE_MAXSIZE`, `OBSERVABILITY_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS`). +Added an agent-native stdout format (`OBSERVABILITY_STDOUT_FORMAT=google`): JSON lines carry the special keys the Cloud Run/GKE logging agent promotes to first-class LogEntry fields (severity, trace, span, labels), enabling full-fidelity Cloud Logging ingestion from stdout with no in-process network emission. Added a destination strategy registry and a generic queued transport: destinations register as `inline` (synchronous, e.g. stdout) or `remote`, and every remote destination is wrapped in a bounded queue drained by a stdlib QueueListener thread, so no remote write ever runs on a request thread. The queue drops-and-counts when full (throttled reports), and close is deadline-bounded (`OBSERVABILITY_LOG_QUEUE_MAXSIZE`, `OBSERVABILITY_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS`). `register_destination` and `register_stdout_formatter` are exported at the package top level so external backends can register strategies (with `required_config` declaring the config fields a strategy needs, checked generically during profile expansion), and the Google credential helpers moved to `policyengine_observability.destinations.google_credentials` (the old import path remains as a shim). diff --git a/changelog.d/22.restart.added.md b/changelog.d/22.restart.added.md index 604c900..9328093 100644 --- a/changelog.d/22.restart.added.md +++ b/changelog.d/22.restart.added.md @@ -1 +1 @@ -Added `restart_observability()`: closes and rebuilds log destinations from configuration, for runtimes whose processes fork or restore from memory snapshots (threads and network clients survive neither). Documented for single-threaded lifecycle moments only — post-snapshot-restore hooks, post-fork hooks, before serving traffic. Runtime shutdown now closes log destinations first, inside the same shutdown budget that bounds the OpenTelemetry flush. +Added `restart_observability()`: closes and rebuilds log destinations from configuration, for runtimes whose processes fork or restore from memory snapshots (threads and network clients survive neither). Documented for single-threaded lifecycle moments only — post-snapshot-restore hooks, post-fork hooks, before serving traffic. `restart_observability()` is a no-op when observability is disabled, so the kill switch holds across forks and restores. diff --git a/changelog.d/22.shutdown.changed.md b/changelog.d/22.shutdown.changed.md new file mode 100644 index 0000000..f242de8 --- /dev/null +++ b/changelog.d/22.shutdown.changed.md @@ -0,0 +1 @@ +Runtime shutdown now closes log destinations first, inside the same bounded shutdown budget that bounds the OpenTelemetry flush; one deadline is shared across all destination closes. The Google Cloud Logging client library's one-time instrumentation diagnostic entry is suppressed, and unknown `OBSERVABILITY_STDOUT_FORMAT` names are reported through the internal-error channel instead of silently falling back to plain. diff --git a/policyengine_observability/__init__.py b/policyengine_observability/__init__.py index ca5f7c7..538d1f0 100644 --- a/policyengine_observability/__init__.py +++ b/policyengine_observability/__init__.py @@ -4,7 +4,8 @@ from .config import ObservabilityConfig from .context import OperationObservabilityContext, RequestObservabilityContext -from .google_credentials import ( +from .destinations import register_destination, register_stdout_formatter +from .destinations.google_credentials import ( configure_google_application_credentials, load_google_credentials, ) @@ -178,6 +179,8 @@ def collect_timings(name: str = "operation", **attrs: Any): "operation", "record_error", "record_event", + "register_destination", + "register_stdout_formatter", "restart_observability", "segment", "set_attribute", diff --git a/policyengine_observability/config.py b/policyengine_observability/config.py index d31bc90..5d58448 100644 --- a/policyengine_observability/config.py +++ b/policyengine_observability/config.py @@ -2,8 +2,15 @@ import logging import os -from collections.abc import Sequence +from collections.abc import Mapping, Sequence from dataclasses import dataclass +from typing import Any + +# Defaults for the generic queued-transport knobs; the queued destination +# imports these so a constructor call and an env-configured build can +# never disagree about what "default" means. +DEFAULT_LOG_QUEUE_MAXSIZE = 1000 +DEFAULT_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS = 2.0 DEFAULT_METRIC_ATTRIBUTE_KEYS = ( "service.name", @@ -103,18 +110,49 @@ def _detect_log_profile() -> str | None: return None +def _missing_strategy_requirements( + destination_names: Sequence[str], + resolved_config: Mapping[str, Any], +) -> list[tuple[str, str]]: + """(destination, config field) pairs a preset needs but lacks. + + Strategies declare their requirements at registration + (``register_destination(required_config=...)``); this check knows + nothing about any backend. + """ + # Imported lazily: the destinations package imports this module, so + # a module-level import here would be circular. By the time a config + # is resolved the package (and its strategy registrations) is loaded. + from .destinations.registry import destination_strategy + + missing: list[tuple[str, str]] = [] + for name in destination_names: + strategy = destination_strategy(name) + if strategy is None: + continue + for field in strategy.required_config: + if not resolved_config.get(field): + missing.append((name, field)) + return missing + + def _resolve_log_profile( raw_profile: str, *, - google_cloud_project: str | None, + resolved_config: Mapping[str, Any], ) -> tuple[str, tuple[tuple[str, ...], str] | None, list[str]]: """Resolve a profile name to (name, preset-or-None, warnings). ``auto`` without a recognized platform marker resolves to no preset, - so caller-supplied defaults keep applying. + so caller-supplied defaults keep applying. ``resolved_config`` + carries the already-resolved config values that registered + strategies may declare as requirements. """ warnings: list[str] = [] - profile = raw_profile.strip().lower() + # Canonical profile names are hyphenated; accept the same case, + # whitespace, and hyphen/underscore variance as destination and + # formatter names. + profile = raw_profile.strip().lower().replace("_", "-") if profile == "auto": detected = _detect_log_profile() if detected is None: @@ -128,10 +166,13 @@ def _resolve_log_profile( ) profile = "plain-sync" preset = LOG_PROFILE_PRESETS[profile] - if "google_cloud_logging" in preset[0] and not google_cloud_project: + missing = _missing_strategy_requirements(preset[0], resolved_config) + if missing: + requirements = ", ".join( + f"{field} (destination {name})" for name, field in missing + ) warnings.append( - "Log profile gcp-direct requires a resolvable Google Cloud " - "project; using plain-sync." + f"Log profile {profile} requires {requirements}; using plain-sync." ) profile = "plain-sync" preset = LOG_PROFILE_PRESETS[profile] @@ -160,10 +201,11 @@ class ObservabilityConfig: log_destinations: tuple[str, ...] = ("stdout",) google_cloud_project: str | None = None google_cloud_log_name: str = "policyengine-observability" - google_cloud_write_timeout_seconds: float = 10.0 stdout_format: str = "plain" - log_queue_maxsize: int = 1000 - log_queue_close_timeout_seconds: float = 2.0 + log_queue_maxsize: int = DEFAULT_LOG_QUEUE_MAXSIZE + log_queue_close_timeout_seconds: float = ( + DEFAULT_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS + ) log_profile: str = "auto" config_warnings: tuple[str, ...] = () @@ -208,7 +250,9 @@ def from_env( ) log_profile, preset, profile_warnings = _resolve_log_profile( os.getenv("OBSERVABILITY_LOG_PROFILE") or cls.log_profile, - google_cloud_project=google_cloud_project, + # The values strategies may declare via required_config; + # extend as future fields become requirement candidates. + resolved_config={"google_cloud_project": google_cloud_project}, ) profile_destinations, profile_stdout_format = preset or (None, None) # Explicit granular env vars override the profile's expansion; @@ -244,7 +288,7 @@ def from_env( meter_name=os.getenv("OBSERVABILITY_METER_NAME"), shutdown_timeout_seconds=float_from_env( "OBSERVABILITY_SHUTDOWN_TIMEOUT_SECONDS", - 3.0, + cls.shutdown_timeout_seconds, ), instrument_fastapi=bool_from_env( "OBSERVABILITY_INSTRUMENT_FASTAPI", @@ -261,10 +305,6 @@ def from_env( os.getenv("OBSERVABILITY_GOOGLE_CLOUD_LOG_NAME") or cls.google_cloud_log_name ), - google_cloud_write_timeout_seconds=float_from_env( - "OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS", - cls.google_cloud_write_timeout_seconds, - ), stdout_format=resolved_stdout_format, log_queue_maxsize=int_from_env( "OBSERVABILITY_LOG_QUEUE_MAXSIZE", diff --git a/policyengine_observability/destinations/__init__.py b/policyengine_observability/destinations/__init__.py index 886a9e4..e37847b 100644 --- a/policyengine_observability/destinations/__init__.py +++ b/policyengine_observability/destinations/__init__.py @@ -5,7 +5,7 @@ from .manager import LogDestinationManager from .queued import QueuedLogDestination from .registry import register_destination -from .stdout import StdoutJsonDestination +from .stdout import StdoutJsonDestination, register_stdout_formatter __all__ = [ "GoogleCloudLoggingDestination", @@ -15,4 +15,5 @@ "StdoutJsonDestination", "normalize_payload", "register_destination", + "register_stdout_formatter", ] diff --git a/policyengine_observability/destinations/base.py b/policyengine_observability/destinations/base.py index be24644..8c93e09 100644 --- a/policyengine_observability/destinations/base.py +++ b/policyengine_observability/destinations/base.py @@ -1,7 +1,8 @@ from __future__ import annotations +import inspect import math -from collections.abc import Mapping, Sequence +from collections.abc import Callable, Mapping, Sequence from typing import Any, Protocol @@ -18,6 +19,73 @@ def emit( """Write one structured observability payload.""" +def normalize_name(name: str) -> str: + """Canonical lookup key for registered names. + + Destination, formatter, and profile lookups all forgive case, + surrounding whitespace, and hyphen/underscore variance the same way, + so a spelling that works for one registry works for every registry. + """ + return name.strip().lower().replace("-", "_") + + +def accepts_keyword(func: Callable[..., Any], name: str) -> bool: + """Whether ``func`` can safely be called with keyword ``name``.""" + try: + parameters = inspect.signature(func).parameters + except (TypeError, ValueError): + return False + if name in parameters: + return True + return any( + parameter.kind is inspect.Parameter.VAR_KEYWORD + for parameter in parameters.values() + ) + + +def safe_report( + on_failure: Callable[..., None], + operation: str, + exc: BaseException, + **fields: Any, +) -> None: + """Report through the internal-error channel; never raises.""" + try: + on_failure(operation, exc, **fields) + except Exception: + pass + + +def close_destination( + destination: LogDestination, + *, + on_failure: Callable[..., None], + deadline_seconds: float | None = None, +) -> None: + """Close a destination if it supports closing; never raises. + + ``close`` is duck-typed with one calling convention everywhere: the + deadline is passed only when the signature accepts it, so both + ``close(self)`` and ``close(self, deadline_seconds=None)`` work under + every close path (manager shutdown, reconfigure, queued drain). + """ + close = getattr(destination, "close", None) + if not callable(close): + return + try: + if accepts_keyword(close, "deadline_seconds"): + close(deadline_seconds=deadline_seconds) + else: + close() + except Exception as exc: + safe_report( + on_failure, + "logging.destination_close", + exc, + destination=getattr(destination, "name", None), + ) + + def clamped(value: Any, *, low: float, high: float, default: float) -> float: """Coerce a config knob to a finite float within [low, high]. diff --git a/policyengine_observability/destinations/google_cloud_logging.py b/policyengine_observability/destinations/google_cloud_logging.py index db960ef..2e1c96e 100644 --- a/policyengine_observability/destinations/google_cloud_logging.py +++ b/policyengine_observability/destinations/google_cloud_logging.py @@ -5,12 +5,12 @@ from datetime import datetime from typing import Any, Protocol -from policyengine_observability.google_credentials import ( +from ..config import float_from_env +from .base import clamped, normalize_payload +from .google_credentials import ( configure_google_application_credentials, load_google_credentials, ) - -from .base import clamped, normalize_payload from .registry import register_destination from .stdout import StdoutFormatter, register_stdout_formatter @@ -83,6 +83,21 @@ def client_factory( self.project = project or getattr(self.client, "project", None) self.logger = self.client.logger(log_name) self._bound_write_timeout() + self._suppress_instrumentation_entry() + + def _suppress_instrumentation_entry(self) -> None: + """Keep the library's diagnostic entry out of the log stream. + + ``log_struct`` prepends a one-time instrumentation diagnostic + entry to the first write per process; observability entries + should be only the records we were asked to write. + """ + try: + from google.cloud import logging_v2 + + logging_v2._instrumentation_emitted = True + except ImportError: # pragma: no cover - google extra has it + pass def _bound_write_timeout(self) -> None: """Bound every write on this destination's own client. @@ -142,12 +157,25 @@ def emit( kwargs["timestamp"] = timestamp trace_id = normalized.get("trace_id") if trace_id and self.project: - kwargs["trace"] = f"projects/{self.project}/traces/{trace_id}" + kwargs["trace"] = _trace_resource(self.project, trace_id) span_id = normalized.get("span_id") if span_id: kwargs["span_id"] = span_id self.logger.log_struct(normalized, **kwargs) + def close(self) -> None: + """Release the owned client's transport, if it supports it.""" + close = getattr(self.client, "close", None) + if callable(close): + close() + + +def _trace_resource(project: str, trace_id: str) -> str: + # The LogEntry trace resource name; the direct write path and the + # agent-native stdout formatter must build it identically for trace + # correlation to work. + return f"projects/{project}/traces/{trace_id}" + def _labels(payload: dict[str, Any], *, log_type: str) -> dict[str, str]: labels = {"log_type": log_type} @@ -178,7 +206,7 @@ def format_google( payload[GOOGLE_LABELS_KEY] = _labels(payload, log_type=log_type) trace_id = payload.get("trace_id") if trace_id and project: - payload[GOOGLE_TRACE_KEY] = f"projects/{project}/traces/{trace_id}" + payload[GOOGLE_TRACE_KEY] = _trace_resource(project, trace_id) span_id = payload.get("span_id") if span_id: payload[GOOGLE_SPAN_ID_KEY] = str(span_id) @@ -194,7 +222,13 @@ def _google_destination_factory(*, config: Any, **_: Any): return GoogleCloudLoggingDestination( project=config.google_cloud_project, log_name=config.google_cloud_log_name, - write_timeout_seconds=config.google_cloud_write_timeout_seconds, + # Backend knobs belong to the strategy: parsed here at + # construction (so re-read on restart_observability()), keeping + # per-backend fields off the core config dataclass. + write_timeout_seconds=float_from_env( + "OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS", + DEFAULT_WRITE_TIMEOUT_SECONDS, + ), ) @@ -203,4 +237,5 @@ def _google_destination_factory(*, config: Any, **_: Any): _google_destination_factory, transport="remote", aliases=("google", "google_cloud"), + required_config=("google_cloud_project",), ) diff --git a/policyengine_observability/destinations/google_credentials.py b/policyengine_observability/destinations/google_credentials.py new file mode 100644 index 0000000..bed34be --- /dev/null +++ b/policyengine_observability/destinations/google_credentials.py @@ -0,0 +1,176 @@ +from __future__ import annotations + +import json +import os +import tempfile +from pathlib import Path +from typing import Any + +OIDC_TOKEN_ENV = "OBSERVABILITY_GOOGLE_OIDC_TOKEN" +MODAL_IDENTITY_TOKEN_ENV = "MODAL_IDENTITY_TOKEN" +WORKLOAD_IDENTITY_PROVIDER_ENV = ( + "OBSERVABILITY_GOOGLE_WORKLOAD_IDENTITY_PROVIDER" +) +SERVICE_ACCOUNT_EMAIL_ENV = "OBSERVABILITY_GOOGLE_SERVICE_ACCOUNT_EMAIL" +STS_TOKEN_URL_ENV = "OBSERVABILITY_GOOGLE_STS_TOKEN_URL" +DEFAULT_STS_TOKEN_URL = "https://sts.googleapis.com/v1/token" +JWT_SUBJECT_TOKEN_TYPE = "urn:ietf:params:oauth:token-type:jwt" +GOOGLE_CREDENTIAL_SCOPES = ("https://www.googleapis.com/auth/cloud-platform",) + + +def configure_google_application_credentials( + *, + credentials_json_env: str = "GCP_CREDENTIALS_JSON", + application_credentials_env: str = "GOOGLE_APPLICATION_CREDENTIALS", + credentials_path: Path | None = None, +) -> Path | None: + try: + existing_path = os.getenv(application_credentials_env) + if existing_path: + return Path(existing_path) + + path = _materialize_json_credentials( + credentials_json_env=credentials_json_env, + credentials_path=credentials_path, + ) + if path is None: + path = _materialize_workload_identity_credentials() + if path is None: + return None + + os.environ[application_credentials_env] = str(path) + return path + except Exception: + return None + + +def load_google_credentials( + *, + credentials_json_env: str = "GCP_CREDENTIALS_JSON", + application_credentials_env: str = "GOOGLE_APPLICATION_CREDENTIALS", + credentials_path: Path | None = None, + prefer_workload_identity: bool = False, +) -> Any | None: + try: + path: Path | None = None + if prefer_workload_identity: + path = _materialize_workload_identity_credentials() + if path is None: + existing_path = os.getenv(application_credentials_env) + if existing_path: + path = Path(existing_path) + if path is None: + path = _materialize_json_credentials( + credentials_json_env=credentials_json_env, + credentials_path=credentials_path, + ) + if path is None and not prefer_workload_identity: + path = _materialize_workload_identity_credentials() + if path is None: + return None + + return _load_credentials_from_file(path) + except Exception: + return None + + +def _materialize_json_credentials( + *, + credentials_json_env: str, + credentials_path: Path | None, +) -> Path | None: + credentials_json = os.getenv(credentials_json_env) + if not credentials_json: + return None + + json.loads(credentials_json) + + path = credentials_path or Path(tempfile.gettempdir()).joinpath( + "policyengine-observability-gcp.json" + ) + path.write_text(credentials_json) + path.chmod(0o600) + return path + + +def _materialize_workload_identity_credentials() -> Path | None: + token = os.getenv(OIDC_TOKEN_ENV) or os.getenv(MODAL_IDENTITY_TOKEN_ENV) + provider = os.getenv(WORKLOAD_IDENTITY_PROVIDER_ENV) + if not token or not provider: + return None + + directory = Path(tempfile.gettempdir()) + token_path = directory / "policyengine-observability-oidc.jwt" + config_path = directory / "policyengine-observability-wif.json" + + token_path.write_text(token) + token_path.chmod(0o600) + config = _external_account_config( + provider=provider, + token_path=token_path, + service_account_email=os.getenv(SERVICE_ACCOUNT_EMAIL_ENV), + token_url=os.getenv(STS_TOKEN_URL_ENV) or DEFAULT_STS_TOKEN_URL, + ) + config_path.write_text(json.dumps(config)) + config_path.chmod(0o600) + return config_path + + +def _load_credentials_from_file(path: Path) -> Any: + config = json.loads(path.read_text()) + scopes = list(GOOGLE_CREDENTIAL_SCOPES) + + if config.get("type") == "external_account": + from google.auth import identity_pool + + return identity_pool.Credentials.from_info(config, scopes=scopes) + + if config.get("type") == "service_account": + from google.oauth2.service_account import Credentials + + return Credentials.from_service_account_file( + str(path), + scopes=scopes, + ) + + import google.auth + + credentials, _project = google.auth.load_credentials_from_file( + str(path), + scopes=scopes, + ) + return credentials + + +def _external_account_config( + *, + provider: str, + token_path: Path, + service_account_email: str | None, + token_url: str, +) -> dict[str, object]: + config: dict[str, object] = { + "type": "external_account", + "audience": _workload_identity_audience(provider), + "subject_token_type": JWT_SUBJECT_TOKEN_TYPE, + "token_url": token_url, + "credential_source": { + "file": str(token_path), + "format": {"type": "text"}, + }, + } + if service_account_email: + config["service_account_impersonation_url"] = ( + "https://iamcredentials.googleapis.com/v1/projects/-/" + f"serviceAccounts/{service_account_email}:generateAccessToken" + ) + return config + + +def _workload_identity_audience(provider: str) -> str: + value = provider.strip() + if value.startswith("//iam.googleapis.com/"): + return value + if value.startswith("projects/"): + return f"//iam.googleapis.com/{value}" + return value diff --git a/policyengine_observability/destinations/manager.py b/policyengine_observability/destinations/manager.py index f369d76..086e377 100644 --- a/policyengine_observability/destinations/manager.py +++ b/policyengine_observability/destinations/manager.py @@ -1,14 +1,15 @@ from __future__ import annotations import logging +import time from collections.abc import Callable, Mapping from typing import Any from ..config import ObservabilityConfig -from .base import LogDestination +from .base import LogDestination, close_destination from .queued import QueuedLogDestination from .registry import destination_strategy -from .stdout import StdoutJsonDestination, resolve_stdout_formatter +from .stdout import StdoutJsonDestination, build_stdout_destination # A destination that fails this many consecutive emits is disabled for the # rest of the process. Inline destinations emit synchronously on the @@ -39,40 +40,54 @@ def __init__( def configure(self) -> None: # Reconfigure (restart_observability) runs only from - # single-threaded lifecycle moments by documented contract, so - # replaced destinations can simply be closed before rebuilding. - # The failure ledger is keyed by id(); stale entries could - # otherwise attach to a new destination via id() reuse. + # single-threaded lifecycle moments by documented contract. + # Construction-time reports are deferred until the new + # destinations are installed: reporting routes through emit, so + # firing mid-build would recurse into configure. previous = self.destinations - self.destinations = [] - self._consecutive_failures.clear() - self._close_destinations(previous) - failures: list[tuple[str, BaseException]] = [] + deferred: list[tuple[str, BaseException, dict[str, Any]]] = [] + + def deferred_report( + operation: str, exc: BaseException, **fields: Any + ) -> None: + deferred.append((operation, exc, fields)) + destinations: list[LogDestination] = [] for destination_name in self.config.log_destinations or ("stdout",): try: - destinations.append(self._build_destination(destination_name)) + destinations.append( + self._build_destination( + destination_name, + build_on_failure=deferred_report, + ) + ) except BaseException as exc: - failures.append((destination_name, exc)) + deferred_report( + "logging.destination_config", + exc, + destination=destination_name, + ) if not destinations: destinations.append(self._stdout_destination()) - failures.append( - ( - "stdout_fallback", - RuntimeError( - "No configured observability log destination " - "initialized; falling back to stdout." - ), - ) + deferred_report( + "logging.destination_config", + RuntimeError( + "No configured observability log destination " + "initialized; falling back to stdout." + ), + destination="stdout_fallback", ) self.destinations = destinations + # The failure ledger is keyed by id(); clear it with the swap so + # stale entries cannot attach to a new destination via id reuse. + self._consecutive_failures.clear() self.configured = True - for destination_name, exc in failures: - self.on_failure( - "logging.destination_config", - exc, - destination=destination_name, - ) + # Close the replaced destinations only after the new ones are + # installed, so their close-phase failure reports (which route + # through emit) still have a sink. + self._close_destinations(previous) + for operation, exc, fields in deferred: + self.on_failure(operation, exc, **fields) for warning in getattr(self.config, "config_warnings", ()): self.on_failure("logging.profile_config", ValueError(warning)) @@ -119,18 +134,26 @@ def _close_destinations( destinations: list[LogDestination], deadline_seconds: float | None = None, ) -> None: + # One deadline covers the whole batch: each close gets whatever + # budget the earlier ones left, so N stuck destinations cannot + # take N times the budget. None means each destination applies + # its own default (a reconfigure, not a bounded shutdown). + deadline = ( + None + if deadline_seconds is None + else time.monotonic() + max(0.0, deadline_seconds) + ) for destination in destinations: - close = getattr(destination, "close", None) - if not callable(close): - continue - try: - close(deadline_seconds) - except Exception as exc: - self.on_failure( - "logging.destination_close", - exc, - destination=getattr(destination, "name", None), - ) + remaining = ( + None + if deadline is None + else max(0.0, deadline - time.monotonic()) + ) + close_destination( + destination, + on_failure=self.on_failure, + deadline_seconds=remaining, + ) def _ensure_destinations(self) -> list[LogDestination]: if not self.configured: @@ -160,7 +183,12 @@ def _disable_destination(self, destination: LogDestination) -> None: if not self.destinations: self.destinations.append(self._stdout_destination()) - def _build_destination(self, destination_name: str) -> LogDestination: + def _build_destination( + self, + destination_name: str, + *, + build_on_failure: Callable[..., None], + ) -> LogDestination: strategy = destination_strategy(destination_name) if strategy is None: raise ValueError( @@ -170,6 +198,7 @@ def _build_destination(self, destination_name: str) -> LogDestination: config=self.config, loggers=self.loggers, serializer=self.serializer, + on_failure=build_on_failure, ) if strategy.transport == "remote": # No remote strategy may ever write on a request thread. @@ -184,8 +213,11 @@ def _build_destination(self, destination_name: str) -> LogDestination: return destination def _stdout_destination(self) -> StdoutJsonDestination: - return StdoutJsonDestination( + # The fail-open fallback: built directly (registry-free) and + # with reporting suppressed, because this can run from inside a + # failure-reporting path where another report would recurse. + return build_stdout_destination( + config=self.config, loggers=self.loggers, serializer=self.serializer, - formatter=resolve_stdout_formatter(self.config), ) diff --git a/policyengine_observability/destinations/queued.py b/policyengine_observability/destinations/queued.py index 970bb4f..1b5f30f 100644 --- a/policyengine_observability/destinations/queued.py +++ b/policyengine_observability/destinations/queued.py @@ -12,9 +12,12 @@ 1. ``_queue`` — thread-safe by construction (``queue.Queue``). 2. ``_listener``— started once in ``__init__``, stopped once in ``close``. -3. ``_dropped`` — best-effort counter for drop accounting and throttling. +3. ``_drops`` — best-effort drop counter with its throttle state. 4. ``_closed`` — one-way flag flipped by ``close``. +(The handler's write-failure counter is confined to the listener +thread, so it is not shared mutable state.) + Accepted races, all bounded and within the best-effort contract: - An ``emit`` that passes the ``_closed`` check while ``close`` runs can @@ -30,7 +33,6 @@ from __future__ import annotations import atexit -import inspect import queue as queue_module import time from collections.abc import Callable @@ -39,12 +41,21 @@ from logging.handlers import QueueListener from typing import Any -from .base import LogDestination, clamped, normalize_payload +from ..config import ( + DEFAULT_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS, + DEFAULT_LOG_QUEUE_MAXSIZE, +) +from .base import ( + LogDestination, + accepts_keyword, + clamped, + close_destination, + normalize_payload, + safe_report, +) -DEFAULT_QUEUE_MAXSIZE = 1000 MIN_QUEUE_MAXSIZE = 10 MAX_QUEUE_MAXSIZE = 100_000 -DEFAULT_CLOSE_TIMEOUT_SECONDS = 2.0 MIN_CLOSE_TIMEOUT_SECONDS = 0.0 MAX_CLOSE_TIMEOUT_SECONDS = 30.0 DROP_REPORT_INTERVAL = 100 @@ -59,18 +70,33 @@ class _QueuedRecord: enqueued_at: datetime -def _accepts_timestamp(destination: LogDestination) -> bool: - try: - parameters = inspect.signature(destination.emit).parameters - except (TypeError, ValueError): - return False - return "timestamp" in parameters +class _ThrottledCounter: + """Count occurrences; say when one should be reported. + + The shared throttle policy for failure-path reporting: the first + occurrence always reports, then every ``interval``-th, so a + persistent problem stays visible without flooding the internal-error + channel. + """ + + __slots__ = ("count", "interval") + + def __init__(self, interval: int) -> None: + self.interval = max(1, int(interval)) + self.count = 0 + + def tick(self) -> int | None: + """Increment; return the count when this occurrence reports.""" + self.count += 1 + if self.count == 1 or self.count % self.interval == 0: + return self.count + return None class _QueuedRecordHandler: """Duck-typed QueueListener handler: only ``handle`` is ever called. - ``write_failures`` is confined to the listener thread. A write + The failure counter is confined to the listener thread. A write failure must never kill the listener, so everything below the emit is guarded; ``BaseException`` is deliberately not caught (swallowing ``SystemExit`` on a worker thread is worse than losing the queue — @@ -88,8 +114,7 @@ def __init__( self.inner = inner self.on_failure = on_failure self.forward_timestamp = forward_timestamp - self.report_interval = max(1, report_interval) - self.write_failures = 0 + self.failures = _ThrottledCounter(report_interval) def handle(self, record: _QueuedRecord) -> None: try: @@ -107,20 +132,17 @@ def handle(self, record: _QueuedRecord) -> None: severity=record.severity, ) except Exception as exc: - self.write_failures += 1 - count = self.write_failures - if count != 1 and count % self.report_interval != 0: + count = self.failures.tick() + if count is None: return - try: - self.on_failure( - "logging.queue_write", - exc, - destination=getattr(self.inner, "name", None), - log_type=record.log_type, - write_failures_total=count, - ) - except Exception: - pass + safe_report( + self.on_failure, + "logging.queue_write", + exc, + destination=getattr(self.inner, "name", None), + log_type=record.log_type, + write_failures_total=count, + ) class _BoundedQueueListener(QueueListener): @@ -160,8 +182,8 @@ def __init__( *, inner: LogDestination, on_failure: Callable[..., None], - maxsize: float = DEFAULT_QUEUE_MAXSIZE, - close_timeout_seconds: float = DEFAULT_CLOSE_TIMEOUT_SECONDS, + maxsize: float = DEFAULT_LOG_QUEUE_MAXSIZE, + close_timeout_seconds: float = DEFAULT_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS, drop_report_interval: int = DROP_REPORT_INTERVAL, ) -> None: self.inner = inner @@ -172,16 +194,15 @@ def __init__( maxsize, low=MIN_QUEUE_MAXSIZE, high=MAX_QUEUE_MAXSIZE, - default=DEFAULT_QUEUE_MAXSIZE, + default=DEFAULT_LOG_QUEUE_MAXSIZE, ) ) self.close_timeout_seconds = clamped( close_timeout_seconds, low=MIN_CLOSE_TIMEOUT_SECONDS, high=MAX_CLOSE_TIMEOUT_SECONDS, - default=DEFAULT_CLOSE_TIMEOUT_SECONDS, + default=DEFAULT_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS, ) - self.drop_report_interval = max(1, int(drop_report_interval)) self._queue: queue_module.Queue[_QueuedRecord | None] = ( queue_module.Queue(self.maxsize) ) @@ -190,10 +211,10 @@ def __init__( _QueuedRecordHandler( inner, on_failure, - forward_timestamp=_accepts_timestamp(inner), + forward_timestamp=accepts_keyword(inner.emit, "timestamp"), ), ) - self._dropped = 0 + self._drops = _ThrottledCounter(drop_report_interval) self._closed = False # Construction happens at configure time on the startup thread, # never lazily on a request thread. @@ -241,36 +262,22 @@ def close(self, deadline_seconds: float | None = None) -> None: ) drained = self._listener.stop(timeout=deadline) if not drained: - try: - self.on_failure( - "logging.queue_close_timeout", - TimeoutError( - "Observability log queue did not drain before " - "the close deadline; remaining records are lost." - ), - destination=self.name, - deadline_seconds=deadline, - pending_records=self._queue.qsize(), - ) - except Exception: - pass + safe_report( + self.on_failure, + "logging.queue_close_timeout", + TimeoutError( + "Observability log queue did not drain before " + "the close deadline; remaining records are lost." + ), + destination=self.name, + deadline_seconds=deadline, + pending_records=self._queue.qsize(), + ) # The abandoned listener may still be mid-write; leave the # inner destination alone rather than closing it underneath # an active write. return - inner_close = getattr(self.inner, "close", None) - if callable(inner_close): - try: - inner_close() - except Exception as exc: - try: - self.on_failure( - "logging.destination_close", - exc, - destination=getattr(self.inner, "name", None), - ) - except Exception: - pass + close_destination(self.inner, on_failure=self.on_failure) def _record_drop( self, @@ -278,20 +285,16 @@ def _record_drop( log_type: str, exc: BaseException | None = None, ) -> None: - self._dropped += 1 - count = self._dropped - if count != 1 and count % self.drop_report_interval != 0: + count = self._drops.tick() + if count is None: return - try: - self.on_failure( - "logging.queue_drop", - exc - or RuntimeError("Observability log queue dropped a record."), - destination=self.name, - log_type=log_type, - reason=reason, - dropped_total=count, - queue_maxsize=self.maxsize, - ) - except Exception: - pass + safe_report( + self.on_failure, + "logging.queue_drop", + exc or RuntimeError("Observability log queue dropped a record."), + destination=self.name, + log_type=log_type, + reason=reason, + dropped_total=count, + queue_maxsize=self.maxsize, + ) diff --git a/policyengine_observability/destinations/registry.py b/policyengine_observability/destinations/registry.py index 0be988f..25b9521 100644 --- a/policyengine_observability/destinations/registry.py +++ b/policyengine_observability/destinations/registry.py @@ -13,10 +13,12 @@ from dataclasses import dataclass from typing import Literal -from .base import LogDestination +from .base import LogDestination, normalize_name # Factories are called with keyword arguments (config, loggers, -# serializer) and may ignore what they do not need. +# serializer, on_failure) and may ignore what they do not need. The +# on_failure callable is for construction-time reporting only; reports +# made through it may be deferred until the build completes. DestinationFactory = Callable[..., LogDestination] @@ -24,6 +26,11 @@ class DestinationStrategy: factory: DestinationFactory transport: Literal["inline", "remote"] + # Config attribute names that must resolve truthy for the strategy + # to be usable. Profiles naming this strategy downgrade gracefully + # (with a warning) when a requirement is missing, instead of failing + # at construction and falling back with a config-failure report. + required_config: tuple[str, ...] = () _STRATEGIES: dict[str, DestinationStrategy] = {} @@ -35,15 +42,16 @@ def register_destination( *, transport: Literal["inline", "remote"], aliases: tuple[str, ...] = (), + required_config: tuple[str, ...] = (), ) -> None: - strategy = DestinationStrategy(factory=factory, transport=transport) + strategy = DestinationStrategy( + factory=factory, + transport=transport, + required_config=required_config, + ) for key in (name, *aliases): - _STRATEGIES[_normalize(key)] = strategy + _STRATEGIES[normalize_name(key)] = strategy def destination_strategy(name: str) -> DestinationStrategy | None: - return _STRATEGIES.get(_normalize(name)) - - -def _normalize(name: str) -> str: - return name.strip().lower().replace("-", "_") + return _STRATEGIES.get(normalize_name(name)) diff --git a/policyengine_observability/destinations/stdout.py b/policyengine_observability/destinations/stdout.py index 391c312..e8bdb7e 100644 --- a/policyengine_observability/destinations/stdout.py +++ b/policyengine_observability/destinations/stdout.py @@ -4,7 +4,7 @@ from collections.abc import Callable, Mapping from typing import Any -from .base import normalize_payload +from .base import normalize_name, normalize_payload, safe_report from .registry import register_destination # A stdout formatter shapes the normalized payload into the JSON line a @@ -22,12 +22,26 @@ def register_stdout_formatter( name: str, factory: StdoutFormatterFactory ) -> None: - _FORMATTER_FACTORIES[name.strip().lower()] = factory - - -def resolve_stdout_formatter(config: Any) -> StdoutFormatter: - name = (getattr(config, "stdout_format", None) or "plain").strip().lower() - factory = _FORMATTER_FACTORIES.get(name) or _FORMATTER_FACTORIES["plain"] + _FORMATTER_FACTORIES[normalize_name(name)] = factory + + +def resolve_stdout_formatter( + config: Any, + on_failure: Callable[..., None] | None = None, +) -> StdoutFormatter: + raw = getattr(config, "stdout_format", None) or "plain" + factory = _FORMATTER_FACTORIES.get(normalize_name(raw)) + if factory is None: + # Falling back must not lose the record, but a typo'd format + # name should not pass silently either — the agent-native shape + # it named would just quietly never appear. + if on_failure is not None: + safe_report( + on_failure, + "logging.stdout_format", + ValueError(f"Unknown stdout format {raw!r}; using plain."), + ) + factory = _FORMATTER_FACTORIES["plain"] return factory(config) @@ -85,12 +99,25 @@ def emit( logger.info(message) -def _stdout_factory(*, config: Any, loggers: Any, serializer: Any, **_: Any): +def build_stdout_destination( + *, + config: Any, + loggers: Any, + serializer: Any, + on_failure: Callable[..., None] | None = None, + **_: Any, +) -> StdoutJsonDestination: + """The one place a configured stdout destination is assembled. + + Used both as the registered ``stdout`` strategy factory and by the + manager's fail-open fallback, so formatter resolution can never + diverge between the two paths. + """ return StdoutJsonDestination( loggers=loggers, serializer=serializer, - formatter=resolve_stdout_formatter(config), + formatter=resolve_stdout_formatter(config, on_failure=on_failure), ) -register_destination("stdout", _stdout_factory, transport="inline") +register_destination("stdout", build_stdout_destination, transport="inline") diff --git a/policyengine_observability/google_credentials.py b/policyengine_observability/google_credentials.py index bed34be..6990e84 100644 --- a/policyengine_observability/google_credentials.py +++ b/policyengine_observability/google_credentials.py @@ -1,176 +1,34 @@ -from __future__ import annotations - -import json -import os -import tempfile -from pathlib import Path -from typing import Any - -OIDC_TOKEN_ENV = "OBSERVABILITY_GOOGLE_OIDC_TOKEN" -MODAL_IDENTITY_TOKEN_ENV = "MODAL_IDENTITY_TOKEN" -WORKLOAD_IDENTITY_PROVIDER_ENV = ( - "OBSERVABILITY_GOOGLE_WORKLOAD_IDENTITY_PROVIDER" -) -SERVICE_ACCOUNT_EMAIL_ENV = "OBSERVABILITY_GOOGLE_SERVICE_ACCOUNT_EMAIL" -STS_TOKEN_URL_ENV = "OBSERVABILITY_GOOGLE_STS_TOKEN_URL" -DEFAULT_STS_TOKEN_URL = "https://sts.googleapis.com/v1/token" -JWT_SUBJECT_TOKEN_TYPE = "urn:ietf:params:oauth:token-type:jwt" -GOOGLE_CREDENTIAL_SCOPES = ("https://www.googleapis.com/auth/cloud-platform",) - - -def configure_google_application_credentials( - *, - credentials_json_env: str = "GCP_CREDENTIALS_JSON", - application_credentials_env: str = "GOOGLE_APPLICATION_CREDENTIALS", - credentials_path: Path | None = None, -) -> Path | None: - try: - existing_path = os.getenv(application_credentials_env) - if existing_path: - return Path(existing_path) - - path = _materialize_json_credentials( - credentials_json_env=credentials_json_env, - credentials_path=credentials_path, - ) - if path is None: - path = _materialize_workload_identity_credentials() - if path is None: - return None - - os.environ[application_credentials_env] = str(path) - return path - except Exception: - return None - - -def load_google_credentials( - *, - credentials_json_env: str = "GCP_CREDENTIALS_JSON", - application_credentials_env: str = "GOOGLE_APPLICATION_CREDENTIALS", - credentials_path: Path | None = None, - prefer_workload_identity: bool = False, -) -> Any | None: - try: - path: Path | None = None - if prefer_workload_identity: - path = _materialize_workload_identity_credentials() - if path is None: - existing_path = os.getenv(application_credentials_env) - if existing_path: - path = Path(existing_path) - if path is None: - path = _materialize_json_credentials( - credentials_json_env=credentials_json_env, - credentials_path=credentials_path, - ) - if path is None and not prefer_workload_identity: - path = _materialize_workload_identity_credentials() - if path is None: - return None - - return _load_credentials_from_file(path) - except Exception: - return None - - -def _materialize_json_credentials( - *, - credentials_json_env: str, - credentials_path: Path | None, -) -> Path | None: - credentials_json = os.getenv(credentials_json_env) - if not credentials_json: - return None - - json.loads(credentials_json) - - path = credentials_path or Path(tempfile.gettempdir()).joinpath( - "policyengine-observability-gcp.json" - ) - path.write_text(credentials_json) - path.chmod(0o600) - return path +"""Deprecated import location kept for backward compatibility. +The Google credential helpers are edge (backend-specific) code and live +in ``policyengine_observability.destinations.google_credentials``. +Import them from there or from the package top level. +""" -def _materialize_workload_identity_credentials() -> Path | None: - token = os.getenv(OIDC_TOKEN_ENV) or os.getenv(MODAL_IDENTITY_TOKEN_ENV) - provider = os.getenv(WORKLOAD_IDENTITY_PROVIDER_ENV) - if not token or not provider: - return None - - directory = Path(tempfile.gettempdir()) - token_path = directory / "policyengine-observability-oidc.jwt" - config_path = directory / "policyengine-observability-wif.json" - - token_path.write_text(token) - token_path.chmod(0o600) - config = _external_account_config( - provider=provider, - token_path=token_path, - service_account_email=os.getenv(SERVICE_ACCOUNT_EMAIL_ENV), - token_url=os.getenv(STS_TOKEN_URL_ENV) or DEFAULT_STS_TOKEN_URL, - ) - config_path.write_text(json.dumps(config)) - config_path.chmod(0o600) - return config_path - - -def _load_credentials_from_file(path: Path) -> Any: - config = json.loads(path.read_text()) - scopes = list(GOOGLE_CREDENTIAL_SCOPES) - - if config.get("type") == "external_account": - from google.auth import identity_pool - - return identity_pool.Credentials.from_info(config, scopes=scopes) - - if config.get("type") == "service_account": - from google.oauth2.service_account import Credentials - - return Credentials.from_service_account_file( - str(path), - scopes=scopes, - ) - - import google.auth - - credentials, _project = google.auth.load_credentials_from_file( - str(path), - scopes=scopes, - ) - return credentials - - -def _external_account_config( - *, - provider: str, - token_path: Path, - service_account_email: str | None, - token_url: str, -) -> dict[str, object]: - config: dict[str, object] = { - "type": "external_account", - "audience": _workload_identity_audience(provider), - "subject_token_type": JWT_SUBJECT_TOKEN_TYPE, - "token_url": token_url, - "credential_source": { - "file": str(token_path), - "format": {"type": "text"}, - }, - } - if service_account_email: - config["service_account_impersonation_url"] = ( - "https://iamcredentials.googleapis.com/v1/projects/-/" - f"serviceAccounts/{service_account_email}:generateAccessToken" - ) - return config +from __future__ import annotations +from .destinations.google_credentials import ( + DEFAULT_STS_TOKEN_URL, + GOOGLE_CREDENTIAL_SCOPES, + JWT_SUBJECT_TOKEN_TYPE, + MODAL_IDENTITY_TOKEN_ENV, + OIDC_TOKEN_ENV, + SERVICE_ACCOUNT_EMAIL_ENV, + STS_TOKEN_URL_ENV, + WORKLOAD_IDENTITY_PROVIDER_ENV, + configure_google_application_credentials, + load_google_credentials, +) -def _workload_identity_audience(provider: str) -> str: - value = provider.strip() - if value.startswith("//iam.googleapis.com/"): - return value - if value.startswith("projects/"): - return f"//iam.googleapis.com/{value}" - return value +__all__ = [ + "DEFAULT_STS_TOKEN_URL", + "GOOGLE_CREDENTIAL_SCOPES", + "JWT_SUBJECT_TOKEN_TYPE", + "MODAL_IDENTITY_TOKEN_ENV", + "OIDC_TOKEN_ENV", + "SERVICE_ACCOUNT_EMAIL_ENV", + "STS_TOKEN_URL_ENV", + "WORKLOAD_IDENTITY_PROVIDER_ENV", + "configure_google_application_credentials", + "load_google_credentials", +] diff --git a/policyengine_observability/runtime.py b/policyengine_observability/runtime.py index 839291e..051f79a 100644 --- a/policyengine_observability/runtime.py +++ b/policyengine_observability/runtime.py @@ -1076,7 +1076,7 @@ def shutdown(self) -> None: self.config.shutdown_timeout_seconds, low=0.0, high=60.0, - default=3.0, + default=ObservabilityConfig.shutdown_timeout_seconds, ) providers = [ ("trace", self.tracer_provider), @@ -1137,7 +1137,12 @@ def restart_log_destinations(self) -> None: traffic. There is deliberately no locking here: under that contract there is no concurrency, and a violated contract costs at most a counted drop into a closing destination. + + A no-op when observability is disabled, mirroring configure(): + the kill switch must hold across forks and snapshot restores. """ + if not self.enabled: + return self.log_destination_manager.configure() def log_observability_failure( diff --git a/tests/conftest.py b/tests/conftest.py new file mode 100644 index 0000000..dbc84a1 --- /dev/null +++ b/tests/conftest.py @@ -0,0 +1,21 @@ +from __future__ import annotations + +import pytest +from fakes import RecordingDestination + +from policyengine_observability.destinations.registry import ( + _STRATEGIES, + register_destination, +) + + +@pytest.fixture +def fake_remote_strategy(): + """Register a fake remote strategy; yields its destination name.""" + register_destination( + "fake-remote", + lambda **kwargs: RecordingDestination(), + transport="remote", + ) + yield "fake_remote" + _STRATEGIES.pop("fake_remote", None) diff --git a/tests/fakes.py b/tests/fakes.py new file mode 100644 index 0000000..b4ea394 --- /dev/null +++ b/tests/fakes.py @@ -0,0 +1,121 @@ +"""Shared destination fakes and manager builders for the test suite.""" + +from __future__ import annotations + +import json +import logging +import threading + +from policyengine_observability.config import ObservabilityConfig +from policyengine_observability.destinations.manager import ( + LogDestinationManager, +) + + +class RecordingLogger: + """Captures level-routed serialized lines like a stdlib logger.""" + + def __init__(self) -> None: + self.lines = [] + + def info(self, message) -> None: + self.lines.append(("INFO", message)) + + def warning(self, message) -> None: + self.lines.append(("WARNING", message)) + + def error(self, message) -> None: + self.lines.append(("ERROR", message)) + + +class RecordingDestination: + name = "recording" + + def __init__(self) -> None: + self.calls = [] + + @property + def payloads(self): + return [payload for payload, *_ in self.calls] + + def emit(self, payload, *, log_type, severity, timestamp=None) -> None: + self.calls.append((payload, log_type, severity, timestamp)) + + +class ClosableRecordingDestination(RecordingDestination): + """A recording destination with a zero-argument duck-typed close.""" + + def __init__(self) -> None: + super().__init__() + self.closed = 0 + + def close(self) -> None: + self.closed += 1 + + +class TimestampBlindDestination: + name = "timestamp-blind" + + def __init__(self) -> None: + self.calls = [] + + def emit(self, payload, *, log_type, severity) -> None: + self.calls.append((payload, log_type, severity)) + + +class BlockingDestination: + """Blocks inside emit until released; sequenced via Events.""" + + name = "blocking" + + def __init__(self) -> None: + self.entered = threading.Event() + self.release = threading.Event() + self.calls = 0 + self.closed = 0 + + def emit(self, payload, *, log_type, severity, timestamp=None) -> None: + self.calls += 1 + self.entered.set() + self.release.wait(10) + + def close(self) -> None: + self.closed += 1 + + +class FailingDestination: + """Raises from emit — always, or only for the first ``fail_first``.""" + + name = "failing" + + def __init__(self, fail_first: int | None = None) -> None: + self.calls = 0 + self.fail_first = fail_first + self.delivered = [] + + def emit(self, payload, *, log_type, severity, timestamp=None) -> None: + self.calls += 1 + if self.fail_first is None or self.calls <= self.fail_first: + raise RuntimeError("emit failed") + self.delivered.append(payload) + + +def make_manager(config=None, *, loggers=None, destinations=None): + """A manager with a failure-capturing on_failure. + + Returns ``(manager, failures)`` where each failure is the + ``(operation, exception, fields)`` triple the manager reported. + """ + failures = [] + manager = LogDestinationManager( + config=config or ObservabilityConfig(), + loggers=loggers or {"event": logging.getLogger("test-manager")}, + serializer=json.dumps, + on_failure=lambda operation, exc, **fields: failures.append( + (operation, exc, fields) + ), + ) + if destinations is not None: + manager.destinations = list(destinations) + manager.configured = True + return manager, failures diff --git a/tests/test_destinations.py b/tests/test_destinations.py index e3f4e15..ab581ae 100644 --- a/tests/test_destinations.py +++ b/tests/test_destinations.py @@ -1,15 +1,31 @@ from __future__ import annotations +import json import math import pytest +from fakes import ( + ClosableRecordingDestination, + FailingDestination, + RecordingDestination, + RecordingLogger, + make_manager, +) +from policyengine_observability.config import ObservabilityConfig from policyengine_observability.destinations import ( GoogleCloudLoggingDestination, google_cloud_logging, normalize_payload, ) -from policyengine_observability.destinations.base import clamped +from policyengine_observability.destinations.base import ( + accepts_keyword, + clamped, +) +from policyengine_observability.destinations.stdout import ( + StdoutJsonDestination, + resolve_stdout_formatter, +) class Unprintable: @@ -91,6 +107,24 @@ def test_clamped_bounds_and_rejects_non_finite(value, expected) -> None: assert math.isfinite(result) +def test_accepts_keyword_covers_named_var_keyword_and_uninspectable() -> None: + def named(payload, *, timestamp=None): + pass + + def var_keyword(payload, **kwargs): + pass + + def blind(payload): + pass + + assert accepts_keyword(named, "timestamp") is True + assert accepts_keyword(var_keyword, "timestamp") is True + assert accepts_keyword(blind, "timestamp") is False + # Builtins without introspectable signatures degrade to False + # instead of raising at construction time. + assert accepts_keyword(min, "timestamp") is False + + def test_normalize_payload_recursively_stringifies_unsafe_values() -> None: normalized = normalize_payload( { @@ -215,31 +249,103 @@ def test_google_destination_forwards_enqueue_timestamp(monkeypatch) -> None: assert "timestamp" not in plain_kwargs -# ── Stdout formatters ──────────────────────────────────────────────────── +def test_google_destination_close_closes_client(monkeypatch) -> None: + class ClosableFakeClient(FakeClient): + def __init__(self) -> None: + super().__init__() + self.closed = 0 + def close(self) -> None: + self.closed += 1 -class RecordingLogger: - def __init__(self) -> None: - self.lines = [] + client = ClosableFakeClient() + destination = _google_destination(monkeypatch, client) + + destination.close() - def info(self, message) -> None: - self.lines.append(("INFO", message)) + assert client.closed == 1 - def warning(self, message) -> None: - self.lines.append(("WARNING", message)) - def error(self, message) -> None: - self.lines.append(("ERROR", message)) +def test_google_destination_close_tolerates_closeless_client( + monkeypatch, +) -> None: + destination = _google_destination(monkeypatch, FakeClient()) + destination.close() # FakeClient has no close; must be a no-op -def _stdout_destination(config=None, formatter=None): - import json - from policyengine_observability.destinations.stdout import ( - StdoutJsonDestination, - resolve_stdout_formatter, +def test_google_destination_suppresses_instrumentation_entry( + monkeypatch, +) -> None: + logging_v2 = pytest.importorskip("google.cloud.logging_v2") + monkeypatch.setattr( + logging_v2, "_instrumentation_emitted", False, raising=False ) + _google_destination(monkeypatch, FakeClient()) + + assert logging_v2._instrumentation_emitted is True + + +def test_google_factory_reads_write_timeout_env(monkeypatch) -> None: + captured = {} + + class StubDestination: + def __init__(self, **kwargs) -> None: + captured.update(kwargs) + + monkeypatch.setattr( + google_cloud_logging, "GoogleCloudLoggingDestination", StubDestination + ) + monkeypatch.setenv("OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS", "2.5") + + from policyengine_observability.destinations.registry import ( + destination_strategy, + ) + + destination_strategy("google_cloud_logging").factory( + config=ObservabilityConfig(google_cloud_project="proj"), + loggers={}, + serializer=json.dumps, + ) + + assert captured["project"] == "proj" + assert captured["write_timeout_seconds"] == 2.5 + + +def test_google_factory_write_timeout_defaults_without_env( + monkeypatch, +) -> None: + captured = {} + + class StubDestination: + def __init__(self, **kwargs) -> None: + captured.update(kwargs) + + monkeypatch.setattr( + google_cloud_logging, "GoogleCloudLoggingDestination", StubDestination + ) + monkeypatch.delenv( + "OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS", raising=False + ) + + from policyengine_observability.destinations.registry import ( + destination_strategy, + ) + + destination_strategy("google_cloud_logging").factory( + config=ObservabilityConfig(google_cloud_project="proj"), + loggers={}, + serializer=json.dumps, + ) + + assert captured["write_timeout_seconds"] == 10.0 + + +# ── Stdout formatters ──────────────────────────────────────────────────── + + +def _stdout_destination(config=None, formatter=None): logger = RecordingLogger() if formatter is None and config is not None: formatter = resolve_stdout_formatter(config) @@ -252,15 +358,11 @@ def _stdout_destination(config=None, formatter=None): def _emitted_line(logger): - import json - ((_, message),) = logger.lines return json.loads(message) def test_stdout_google_formatter_maps_agent_native_keys() -> None: - from policyengine_observability.config import ObservabilityConfig - config = ObservabilityConfig( stdout_format="google", google_cloud_project="proj" ) @@ -294,8 +396,6 @@ def test_stdout_google_formatter_maps_agent_native_keys() -> None: def test_stdout_google_formatter_omits_trace_without_project() -> None: - from policyengine_observability.config import ObservabilityConfig - config = ObservabilityConfig(stdout_format="google") destination, logger = _stdout_destination(config) @@ -308,8 +408,6 @@ def test_stdout_google_formatter_omits_trace_without_project() -> None: def test_stdout_unknown_format_falls_back_to_plain() -> None: - from policyengine_observability.config import ObservabilityConfig - config = ObservabilityConfig(stdout_format=" GoOgLeX ") destination, logger = _stdout_destination(config) @@ -318,9 +416,24 @@ def test_stdout_unknown_format_falls_back_to_plain() -> None: assert _emitted_line(logger) == {"event": "x"} -def test_stdout_format_name_is_normalized() -> None: - from policyengine_observability.config import ObservabilityConfig +def test_stdout_unknown_format_reports_when_channel_available() -> None: + failures = [] + formatter = resolve_stdout_formatter( + ObservabilityConfig(stdout_format="agent-natve"), + on_failure=lambda operation, exc, **fields: failures.append( + (operation, str(exc)) + ), + ) + + formatted = formatter({"event": "x"}, log_type="event", severity="INFO") + + assert formatted == {"event": "x"} + assert len(failures) == 1 + assert failures[0][0] == "logging.stdout_format" + assert "agent-natve" in failures[0][1] + +def test_stdout_format_name_is_normalized() -> None: config = ObservabilityConfig(stdout_format=" GOOGLE ") destination, logger = _stdout_destination(config) @@ -341,8 +454,6 @@ def broken(payload, *, log_type, severity): def test_stdout_google_formatter_never_mutates_caller_payload() -> None: - from policyengine_observability.config import ObservabilityConfig - config = ObservabilityConfig( stdout_format="google", google_cloud_project="proj" ) @@ -355,7 +466,6 @@ def test_stdout_google_formatter_never_mutates_caller_payload() -> None: def test_custom_stdout_formatter_registers_and_resolves() -> None: - from policyengine_observability.config import ObservabilityConfig from policyengine_observability.destinations.stdout import ( _FORMATTER_FACTORIES, register_stdout_formatter, @@ -366,62 +476,18 @@ def factory(config): register_stdout_formatter("custom-test", factory) try: - config = ObservabilityConfig(stdout_format="custom-test") + # Hyphen/underscore variance is forgiven the same way it is for + # destination names. + config = ObservabilityConfig(stdout_format=" Custom_Test ") destination, logger = _stdout_destination(config) destination.emit({"event": "x"}, log_type="event", severity="INFO") finally: - _FORMATTER_FACTORIES.pop("custom-test", None) + _FORMATTER_FACTORIES.pop("custom_test", None) assert _emitted_line(logger) == {"wrapped": {"event": "x"}} -# ── Destination circuit breaker ────────────────────────────────────────── - - -class FlakyDestination: - name = "flaky" - - def __init__(self, fail_first: int | None = None) -> None: - self.calls = 0 - self.fail_first = fail_first - - def emit(self, payload, *, log_type, severity) -> None: - self.calls += 1 - if self.fail_first is None or self.calls <= self.fail_first: - raise RuntimeError("emit failed") - - -class RecordingDestination: - name = "recording" - - def __init__(self) -> None: - self.payloads = [] - - def emit(self, payload, *, log_type, severity) -> None: - self.payloads.append(payload) - - -def _manager(destinations): - import json - import logging - - from policyengine_observability.config import ObservabilityConfig - from policyengine_observability.destinations.manager import ( - LogDestinationManager, - ) - - failures = [] - manager = LogDestinationManager( - config=ObservabilityConfig(), - loggers={"event": logging.getLogger("test-destinations")}, - serializer=json.dumps, - on_failure=lambda operation, exc, **fields: failures.append( - (operation, fields) - ), - ) - manager.destinations = list(destinations) - manager.configured = True - return manager, failures +# ── Destination circuit breaker and manager lifecycle ─────────────────── def test_destination_disabled_after_consecutive_emit_failures() -> None: @@ -429,9 +495,9 @@ def test_destination_disabled_after_consecutive_emit_failures() -> None: DESTINATION_FAILURE_LIMIT, ) - flaky = FlakyDestination() + flaky = FailingDestination() healthy = RecordingDestination() - manager, failures = _manager([flaky, healthy]) + manager, failures = make_manager(destinations=[flaky, healthy]) for _ in range(DESTINATION_FAILURE_LIMIT + 2): manager.emit({"event": "x"}, log_type="event", severity="INFO") @@ -439,7 +505,7 @@ def test_destination_disabled_after_consecutive_emit_failures() -> None: assert flaky.calls == DESTINATION_FAILURE_LIMIT assert flaky not in manager.destinations assert len(healthy.payloads) == DESTINATION_FAILURE_LIMIT + 2 - assert any(op == "logging.destination_disabled" for op, _ in failures) + assert any(op == "logging.destination_disabled" for op, *_ in failures) def test_emit_success_resets_the_failure_counter() -> None: @@ -447,8 +513,8 @@ def test_emit_success_resets_the_failure_counter() -> None: DESTINATION_FAILURE_LIMIT, ) - flaky = FlakyDestination(fail_first=DESTINATION_FAILURE_LIMIT - 1) - manager, failures = _manager([flaky]) + flaky = FailingDestination(fail_first=DESTINATION_FAILURE_LIMIT - 1) + manager, failures = make_manager(destinations=[flaky]) for _ in range(DESTINATION_FAILURE_LIMIT + 2): manager.emit({"event": "x"}, log_type="event", severity="INFO") @@ -456,7 +522,7 @@ def test_emit_success_resets_the_failure_counter() -> None: assert flaky in manager.destinations counts = [ fields["consecutive_failures"] - for op, fields in failures + for op, _exc, fields in failures if op == "logging.destination_emit" ] assert max(counts) == DESTINATION_FAILURE_LIMIT - 1 @@ -466,12 +532,9 @@ def test_sole_disabled_destination_falls_back_to_stdout() -> None: from policyengine_observability.destinations.manager import ( DESTINATION_FAILURE_LIMIT, ) - from policyengine_observability.destinations.stdout import ( - StdoutJsonDestination, - ) - flaky = FlakyDestination() - manager, failures = _manager([flaky]) + flaky = FailingDestination() + manager, _failures = make_manager(destinations=[flaky]) for _ in range(DESTINATION_FAILURE_LIMIT + 1): manager.emit({"event": "x"}, log_type="event", severity="INFO") @@ -481,3 +544,90 @@ def test_sole_disabled_destination_falls_back_to_stdout() -> None: isinstance(destination, StdoutJsonDestination) for destination in manager.destinations ) + + +def test_manager_close_reports_failures_and_closes_the_rest() -> None: + class ExplodingClose(RecordingDestination): + def close(self) -> None: + raise RuntimeError("close failed") + + exploding = ExplodingClose() + closable = ClosableRecordingDestination() + manager, failures = make_manager(destinations=[exploding, closable]) + + manager.close(1.0) # must not raise + + assert closable.closed == 1 + assert any(op == "logging.destination_close" for op, *_ in failures) + + +def test_manager_close_accepts_zero_argument_close() -> None: + """A duck-typed close(self) works under every close path — the + deadline is passed only when the signature accepts it.""" + closable = ClosableRecordingDestination() + manager, failures = make_manager(destinations=[closable]) + + manager.close(1.0) + + assert closable.closed == 1 + assert failures == [] + + +def test_manager_close_shares_one_deadline_across_destinations() -> None: + import time + + deadlines = [] + + class SlowClose(RecordingDestination): + def close(self, deadline_seconds=None) -> None: + deadlines.append(deadline_seconds) + time.sleep(0.05) + + manager, _failures = make_manager(destinations=[SlowClose(), SlowClose()]) + + manager.close(1.0) + + first, second = deadlines + # The second destination only gets what the first one left, so N + # stuck destinations cannot take N times the budget. + assert first <= 1.0 + assert second <= first - 0.04 + + +def test_emit_falls_back_to_stdout_when_configure_crashes( + monkeypatch, +) -> None: + logger = RecordingLogger() + manager, failures = make_manager(loggers={"event": logger}) + + def broken_configure() -> None: + raise RuntimeError("configure exploded") + + monkeypatch.setattr(manager, "configure", broken_configure) + + manager.emit({"event": "x"}, log_type="event", severity="INFO") + + assert manager.configured is True + assert isinstance(manager.destinations[0], StdoutJsonDestination) + assert _emitted_line(logger) == {"event": "x", "severity": "INFO"} + assert any(op == "logging.destination_config" for op, *_ in failures) + + +def test_reconfigure_closes_previous_after_installing_new() -> None: + """Close-phase failure reports route through emit; the replaced + destinations must be closed only after the new ones are installed + so those reports still have a sink.""" + sink_states = [] + manager, _failures = make_manager() + + class CloseProbe(RecordingDestination): + def close(self) -> None: + sink_states.append(list(manager.destinations)) + + manager.destinations = [CloseProbe()] + manager.configured = True + + manager.configure() + + assert len(sink_states) == 1 + assert sink_states[0], "previous destination closed before new install" diff --git a/tests/test_google_credentials.py b/tests/test_google_credentials.py index c112ab0..4870c26 100644 --- a/tests/test_google_credentials.py +++ b/tests/test_google_credentials.py @@ -7,9 +7,11 @@ import pytest -from policyengine_observability import google_credentials -from policyengine_observability.destinations import google_cloud_logging -from policyengine_observability.google_credentials import ( +from policyengine_observability.destinations import ( + google_cloud_logging, + google_credentials, +) +from policyengine_observability.destinations.google_credentials import ( configure_google_application_credentials, load_google_credentials, ) @@ -96,7 +98,7 @@ def test_configure_google_application_credentials_fails_open_on_unexpected_error monkeypatch.delenv("GOOGLE_APPLICATION_CREDENTIALS", raising=False) monkeypatch.setenv("GCP_CREDENTIALS_JSON", '{"project_id":"test"}') monkeypatch.setattr( - "policyengine_observability.google_credentials.json.loads", + "policyengine_observability.destinations.google_credentials.json.loads", lambda _value: (_ for _ in ()).throw(RuntimeError("boom")), ) diff --git a/tests/test_log_profiles.py b/tests/test_log_profiles.py index 2250160..ddade7a 100644 --- a/tests/test_log_profiles.py +++ b/tests/test_log_profiles.py @@ -1,14 +1,11 @@ from __future__ import annotations import json -import logging import pytest +from fakes import RecordingLogger, make_manager from policyengine_observability.config import ObservabilityConfig -from policyengine_observability.destinations.manager import ( - LogDestinationManager, -) from policyengine_observability.destinations.queued import ( QueuedLogDestination, ) @@ -49,6 +46,13 @@ def test_explicit_gcp_agent_profile(monkeypatch) -> None: assert config.config_warnings == () +def test_profile_name_accepts_underscore_variant(monkeypatch) -> None: + config = _from_env(monkeypatch, OBSERVABILITY_LOG_PROFILE=" GCP_Agent ") + + assert config.log_profile == "gcp-agent" + assert config.config_warnings == () + + def test_explicit_gcp_direct_profile_with_project(monkeypatch) -> None: config = _from_env( monkeypatch, @@ -71,7 +75,10 @@ def test_gcp_direct_without_project_downgrades_with_warning( assert config.log_destinations == ("stdout",) assert config.stdout_format == "plain" assert len(config.config_warnings) == 1 - assert "Google Cloud project" in config.config_warnings[0] + # The requirement comes from the strategy registration, and the + # warning names the actual profile — no hard-coded backend text. + assert "gcp-direct" in config.config_warnings[0] + assert "google_cloud_project" in config.config_warnings[0] def test_explicit_plain_sync_profile_is_kill_switch(monkeypatch) -> None: @@ -133,6 +140,27 @@ def test_auto_detects_modal_via_task_marker(monkeypatch) -> None: assert config.log_profile == "gcp-direct" +def test_auto_detects_modal_via_environment_marker(monkeypatch) -> None: + config = _from_env( + monkeypatch, + MODAL_ENVIRONMENT="main", + OBSERVABILITY_GOOGLE_CLOUD_PROJECT="proj", + ) + + assert config.log_profile == "gcp-direct" + + +def test_auto_detected_modal_without_project_downgrades(monkeypatch) -> None: + """The deployment-realistic failure: Modal markers present but no + resolvable project must land on plain-sync with a warning, exactly + like the explicit profile.""" + config = _from_env(monkeypatch, MODAL_TASK_ID="ta-123") + + assert config.log_profile == "plain-sync" + assert config.log_destinations == ("stdout",) + assert any("google_cloud_project" in w for w in config.config_warnings) + + def test_observability_platform_beats_generic_markers(monkeypatch) -> None: config = _from_env( monkeypatch, @@ -179,24 +207,11 @@ def test_explicit_stdout_format_env_overrides_profile(monkeypatch) -> None: assert config.log_destinations == ("stdout",) -def _configured_manager(config): - failures = [] - manager = LogDestinationManager( - config=config, - loggers={"event": logging.getLogger("test-profiles")}, - serializer=json.dumps, - on_failure=lambda operation, exc, **fields: failures.append( - (operation, str(exc)) - ), - ) - manager.configure() - return manager, failures - - def test_sync_profiles_build_no_queued_destinations(monkeypatch) -> None: for profile in ("gcp-agent", "plain-sync"): config = _from_env(monkeypatch, OBSERVABILITY_LOG_PROFILE=profile) - manager, failures = _configured_manager(config) + manager, failures = make_manager(config) + manager.configure() assert not any( isinstance(destination, QueuedLogDestination) @@ -205,13 +220,38 @@ def test_sync_profiles_build_no_queued_destinations(monkeypatch) -> None: assert failures == [] +def test_gcp_agent_profile_formats_stdout_through_manager( + monkeypatch, +) -> None: + """End-to-end wiring: the profile's formatter half must survive the + manager's build path, not just direct construction.""" + config = _from_env( + monkeypatch, + OBSERVABILITY_LOG_PROFILE="gcp-agent", + OBSERVABILITY_GOOGLE_CLOUD_PROJECT="proj", + ) + logger = RecordingLogger() + manager, failures = make_manager(config, loggers={"event": logger}) + manager.configure() + + manager.emit( + {"event": "x", "trace_id": "abc"}, log_type="event", severity="INFO" + ) + + line = json.loads(logger.lines[0][1]) + assert line["logging.googleapis.com/labels"]["log_type"] == "event" + assert line["logging.googleapis.com/trace"] == "projects/proj/traces/abc" + assert failures == [] + + def test_manager_reports_profile_warnings_once(monkeypatch) -> None: config = _from_env(monkeypatch, OBSERVABILITY_LOG_PROFILE="bogus") - manager, failures = _configured_manager(config) + manager, failures = make_manager(config) + manager.configure() warnings = [ - message - for operation, message in failures + str(exc) + for operation, exc, _fields in failures if operation == "logging.profile_config" ] assert len(warnings) == 1 @@ -241,7 +281,8 @@ def emit(self, payload, *, log_type, severity, timestamp=None): OBSERVABILITY_LOG_PROFILE="gcp-direct", OBSERVABILITY_GOOGLE_CLOUD_PROJECT="proj", ) - manager, failures = _configured_manager(config) + manager, failures = make_manager(config) + manager.configure() stdout_destination, queued = manager.destinations assert isinstance(queued, QueuedLogDestination) diff --git a/tests/test_public_api.py b/tests/test_public_api.py index 9b3b6a6..5c0491b 100644 --- a/tests/test_public_api.py +++ b/tests/test_public_api.py @@ -119,3 +119,23 @@ async def run() -> dict[str, float]: return timings assert "load_ms" in asyncio.run(run()) + + +def test_deprecated_google_credentials_path_still_imports() -> None: + # The module moved to destinations/google_credentials; the old path + # is a compatibility shim that must keep re-exporting the API. + from policyengine_observability import google_credentials as shim + from policyengine_observability.destinations import ( + google_credentials as edge, + ) + + assert shim.load_google_credentials is edge.load_google_credentials + assert ( + shim.configure_google_application_credentials + is edge.configure_google_application_credentials + ) + + +def test_registration_hooks_are_exported_at_top_level() -> None: + assert callable(observability.register_destination) + assert callable(observability.register_stdout_formatter) diff --git a/tests/test_queued_destination.py b/tests/test_queued_destination.py index 9eab2fa..b5b5364 100644 --- a/tests/test_queued_destination.py +++ b/tests/test_queued_destination.py @@ -9,62 +9,25 @@ from __future__ import annotations -import threading import time from datetime import UTC, datetime +import pytest +from fakes import ( + BlockingDestination, + FailingDestination, + RecordingDestination, + TimestampBlindDestination, + make_manager, +) + +from policyengine_observability.config import ObservabilityConfig from policyengine_observability.destinations.queued import ( QueuedLogDestination, ) - - -class RecordingInner: - name = "recording-inner" - - def __init__(self) -> None: - self.calls = [] - - def emit(self, payload, *, log_type, severity, timestamp=None) -> None: - self.calls.append((payload, log_type, severity, timestamp)) - - -class TimestampBlindInner: - name = "timestamp-blind" - - def __init__(self) -> None: - self.calls = [] - - def emit(self, payload, *, log_type, severity) -> None: - self.calls.append((payload, log_type, severity)) - - -class BlockingInner: - name = "blocking-inner" - - def __init__(self) -> None: - self.entered = threading.Event() - self.release = threading.Event() - self.calls = 0 - - def emit(self, payload, *, log_type, severity, timestamp=None) -> None: - self.calls += 1 - self.entered.set() - self.release.wait(10) - - -class FailingInner: - name = "failing-inner" - - def __init__(self, fail_first: int | None = None) -> None: - self.calls = 0 - self.fail_first = fail_first - self.delivered = [] - - def emit(self, payload, *, log_type, severity, timestamp=None) -> None: - self.calls += 1 - if self.fail_first is None or self.calls <= self.fail_first: - raise RuntimeError("write failed") - self.delivered.append(payload) +from policyengine_observability.destinations.registry import ( + destination_strategy, +) def _queued(inner, **kwargs): @@ -79,6 +42,10 @@ def _queued(inner, **kwargs): return destination, failures +def _raise_on_failure(*args, **kwargs): + raise RuntimeError("reporting channel is broken") + + def _release_abandoned_listener(destination, blocking_inner) -> None: """Let an abandoned listener thread exit so tests do not leak it.""" blocking_inner.release.set() @@ -89,7 +56,7 @@ def _release_abandoned_listener(destination, blocking_inner) -> None: def test_close_drains_all_records_in_order_with_enqueue_timestamps() -> None: - inner = RecordingInner() + inner = RecordingDestination() destination, failures = _queued(inner) before = datetime.now(UTC) @@ -113,7 +80,7 @@ def test_close_drains_all_records_in_order_with_enqueue_timestamps() -> None: def test_timestamp_not_forwarded_to_blind_inner() -> None: - inner = TimestampBlindInner() + inner = TimestampBlindDestination() destination, failures = _queued(inner) destination.emit({"event": "x"}, log_type="event", severity="INFO") @@ -123,8 +90,42 @@ def test_timestamp_not_forwarded_to_blind_inner() -> None: assert failures == [] +def test_timestamp_forwarded_to_var_keyword_inner() -> None: + class KwargsDestination: + name = "kwargs" + + def __init__(self) -> None: + self.kwargs = [] + + def emit(self, payload, **kwargs) -> None: + self.kwargs.append(kwargs) + + inner = KwargsDestination() + destination, failures = _queued(inner) + + destination.emit({"event": "x"}, log_type="event", severity="INFO") + destination.close(5.0) + + assert inner.kwargs[0]["timestamp"].tzinfo is not None + assert failures == [] + + +def test_uninspectable_inner_emit_degrades_to_timestamp_blind() -> None: + class BuiltinEmitDestination: + # inspect.signature(min) raises; construction must survive and + # fall back to timestamp-blind delivery. + name = "builtin-emit" + emit = min + + destination, _failures = _queued(BuiltinEmitDestination()) + + handler = destination._listener.handlers[0] + assert handler.forward_timestamp is False + destination.close(5.0) + + def test_payload_snapshot_taken_at_enqueue() -> None: - inner = RecordingInner() + inner = RecordingDestination() destination, _failures = _queued(inner) payload = {"nested": {"value": 1}} @@ -137,7 +138,7 @@ def test_payload_snapshot_taken_at_enqueue() -> None: def test_overflow_drops_newest_and_throttles_reports() -> None: - inner = BlockingInner() + inner = BlockingDestination() destination, failures = _queued(inner, maxsize=10, drop_report_interval=3) destination.emit({"index": 0}, log_type="event", severity="INFO") @@ -152,14 +153,14 @@ def test_overflow_drops_newest_and_throttles_reports() -> None: assert [d["dropped_total"] for d in drops] == [1, 3] assert all(d["reason"] == "full" for d in drops) assert all(d["queue_maxsize"] == 10 for d in drops) - assert destination._dropped == 4 + assert destination._drops.count == 4 inner.release.set() destination.close(5.0) def test_close_with_stuck_write_is_bounded_and_terminal() -> None: - inner = BlockingInner() + inner = BlockingDestination() destination, failures = _queued(inner) destination.emit({"index": 0}, log_type="event", severity="INFO") assert inner.entered.wait(5) @@ -185,8 +186,22 @@ def test_close_with_stuck_write_is_bounded_and_terminal() -> None: _release_abandoned_listener(destination, inner) +def test_timed_out_close_leaves_inner_unclosed() -> None: + """An abandoned listener may be mid-write; the inner destination + must not be closed underneath it.""" + inner = BlockingDestination() + destination, _failures = _queued(inner) + destination.emit({"index": 0}, log_type="event", severity="INFO") + assert inner.entered.wait(5) + + destination.close(0.05) + + assert inner.closed == 0 + _release_abandoned_listener(destination, inner) + + def test_close_with_sentinel_blocked_by_full_queue_is_bounded() -> None: - inner = BlockingInner() + inner = BlockingDestination() destination, failures = _queued(inner, maxsize=10) destination.emit({"index": 0}, log_type="event", severity="INFO") assert inner.entered.wait(5) @@ -204,7 +219,7 @@ def test_close_with_sentinel_blocked_by_full_queue_is_bounded() -> None: def test_listener_survives_write_failures_and_throttles_reports() -> None: - inner = FailingInner(fail_first=3) + inner = FailingDestination(fail_first=3) destination, failures = _queued(inner) for index in range(5): @@ -215,13 +230,29 @@ def test_listener_survives_write_failures_and_throttles_reports() -> None: writes = [fields for op, fields in failures if op == "logging.queue_write"] # Throttle: failure 1 reports, failures 2-3 are under the interval. assert [w["write_failures_total"] for w in writes] == [1] - assert writes[0]["destination"] == "failing-inner" + assert writes[0]["destination"] == "failing" + + +def test_listener_survives_broken_reporting_channel() -> None: + """The write-failure report itself is guarded on the listener + thread: a raising on_failure must not kill delivery.""" + inner = FailingDestination(fail_first=1) + destination = QueuedLogDestination( + inner=inner, on_failure=_raise_on_failure + ) + + destination.emit({"index": 0}, log_type="event", severity="INFO") + destination.emit({"index": 1}, log_type="event", severity="INFO") + destination.close(5.0) + + assert [p["index"] for p in inner.delivered] == [1] def test_emit_never_raises() -> None: - inner = RecordingInner() - destination, _failures = _queued(inner) - destination.on_failure = _raise_on_failure + inner = RecordingDestination() + destination = QueuedLogDestination( + inner=inner, on_failure=_raise_on_failure + ) poisoned = {} poisoned["self"] = poisoned # RecursionError inside normalize @@ -230,23 +261,19 @@ def test_emit_never_raises() -> None: destination.close(5.0) destination.emit({"event": "x"}, log_type="event", severity="INFO") - blocked = BlockingInner() - full_destination, _ = _queued(blocked, maxsize=10) - full_destination.on_failure = _raise_on_failure + blocked = BlockingDestination() + full_destination = QueuedLogDestination( + inner=blocked, on_failure=_raise_on_failure, maxsize=10 + ) for index in range(12): full_destination.emit( {"index": index}, log_type="event", severity="INFO" ) blocked.release.set() - full_destination.on_failure = lambda *args, **kwargs: None full_destination.close(5.0) -def _raise_on_failure(*args, **kwargs): - raise RuntimeError("reporting channel is broken") - - def test_atexit_registered_on_construction_unregistered_on_close( monkeypatch, ) -> None: @@ -260,7 +287,7 @@ def test_atexit_registered_on_construction_unregistered_on_close( "policyengine_observability.destinations.queued.atexit.unregister", lambda func: unregistered.append(func), ) - inner = RecordingInner() + inner = RecordingDestination() destination, failures = _queued(inner) destination.close(5.0) @@ -272,7 +299,7 @@ def test_atexit_registered_on_construction_unregistered_on_close( def test_close_forwards_to_inner_close_only_when_drained() -> None: - class ClosableInner(RecordingInner): + class ClosableInner(RecordingDestination): def __init__(self) -> None: super().__init__() self.closed = 0 @@ -288,8 +315,20 @@ def close(self) -> None: assert inner.closed == 1 +def test_inner_close_failure_is_reported_not_raised() -> None: + class ExplodingClose(RecordingDestination): + def close(self) -> None: + raise RuntimeError("client teardown failed") + + destination, failures = _queued(ExplodingClose()) + + destination.close(5.0) # must not raise (atexit calls this) + + assert any(op == "logging.destination_close" for op, _ in failures) + + def test_knobs_are_clamped() -> None: - inner = RecordingInner() + inner = RecordingDestination() destination, _failures = _queued( inner, maxsize=float("inf"), close_timeout_seconds=-5 ) @@ -299,82 +338,58 @@ def test_knobs_are_clamped() -> None: destination.close(5.0) -# ── Destination registry ───────────────────────────────────────────────── +@pytest.mark.parametrize( + ("kwargs", "attribute", "expected"), + [ + ({"maxsize": 3}, "maxsize", 10), + ({"maxsize": 10**6}, "maxsize", 100_000), + ({"close_timeout_seconds": 100}, "close_timeout_seconds", 30.0), + ], +) +def test_knob_boundaries_are_pinned(kwargs, attribute, expected) -> None: + """Pin the clamp bounds so a low/high swap cannot pass silently.""" + destination, _failures = _queued(RecordingDestination(), **kwargs) + assert getattr(destination, attribute) == expected + destination.close(5.0) -def test_registry_builds_remote_wrapped_and_inline_bare() -> None: - import json - import logging - from policyengine_observability.config import ObservabilityConfig - from policyengine_observability.destinations.manager import ( - LogDestinationManager, - ) - from policyengine_observability.destinations.registry import ( - _STRATEGIES, - register_destination, - ) +# ── Destination registry ───────────────────────────────────────────────── - register_destination( - "fake-remote", - lambda **kwargs: RecordingInner(), - transport="remote", + +def test_registry_builds_remote_wrapped_and_inline_bare( + fake_remote_strategy, +) -> None: + manager, _failures = make_manager( + ObservabilityConfig(log_destinations=(fake_remote_strategy, "stdout")) ) - try: - manager = LogDestinationManager( - config=ObservabilityConfig( - log_destinations=("fake_remote", "stdout") - ), - loggers={"event": logging.getLogger("test-registry")}, - serializer=json.dumps, - on_failure=lambda *args, **kwargs: None, - ) - manager.configure() + manager.configure() - remote, inline = manager.destinations - assert isinstance(remote, QueuedLogDestination) - assert remote.name == "queued_recording-inner" - assert not isinstance(inline, QueuedLogDestination) - manager.close() - finally: - _STRATEGIES.pop("fake_remote", None) + remote, inline = manager.destinations + assert isinstance(remote, QueuedLogDestination) + assert remote.name == "queued_recording" + assert not isinstance(inline, QueuedLogDestination) + manager.close() def test_registry_unknown_name_reports_config_failure() -> None: - import json - import logging - - from policyengine_observability.config import ObservabilityConfig - from policyengine_observability.destinations.manager import ( - LogDestinationManager, - ) - - failures = [] - manager = LogDestinationManager( - config=ObservabilityConfig(log_destinations=("nonexistent",)), - loggers={"event": logging.getLogger("test-registry")}, - serializer=json.dumps, - on_failure=lambda operation, exc, **fields: failures.append( - (operation, fields) - ), + manager, failures = make_manager( + ObservabilityConfig(log_destinations=("nonexistent",)) ) manager.configure() assert any( op == "logging.destination_config" and fields.get("destination") == "nonexistent" - for op, fields in failures + for op, _exc, fields in failures ) def test_google_strategy_registered_as_remote_with_aliases() -> None: - from policyengine_observability.destinations.registry import ( - destination_strategy, - ) - canonical = destination_strategy("google_cloud_logging") assert canonical is not None assert canonical.transport == "remote" + assert canonical.required_config == ("google_cloud_project",) assert destination_strategy("google") is canonical assert destination_strategy(" Google-Cloud ") is canonical @@ -383,22 +398,8 @@ def test_google_strategy_registered_as_remote_with_aliases() -> None: def test_manager_breaker_never_disables_queued_destination() -> None: - import json - import logging - - from policyengine_observability.config import ObservabilityConfig - from policyengine_observability.destinations.manager import ( - LogDestinationManager, - ) - - inner = FailingInner() - failures = [] - manager = LogDestinationManager( - config=ObservabilityConfig(), - loggers={"event": logging.getLogger("test-breaker")}, - serializer=json.dumps, - on_failure=lambda operation, exc, **fields: failures.append(operation), - ) + inner = FailingDestination() + manager, failures = make_manager() destination = QueuedLogDestination( inner=inner, on_failure=manager.on_failure ) @@ -409,45 +410,63 @@ def test_manager_breaker_never_disables_queued_destination() -> None: manager.emit({"event": "x"}, log_type="event", severity="INFO") destination.close(5.0) + operations = [op for op, *_ in failures] assert destination in manager.destinations - assert "logging.destination_disabled" not in failures - assert "logging.destination_emit" not in failures - + assert "logging.destination_disabled" not in operations + assert "logging.destination_emit" not in operations -def test_reconfigure_closes_previous_destinations() -> None: - import json - import logging - from policyengine_observability.config import ObservabilityConfig - from policyengine_observability.destinations.manager import ( - LogDestinationManager, +def test_manager_passes_queue_knobs_to_queued_destination( + fake_remote_strategy, +) -> None: + manager, _failures = make_manager( + ObservabilityConfig( + log_destinations=(fake_remote_strategy,), + log_queue_maxsize=50, + log_queue_close_timeout_seconds=7.5, + ) ) - from policyengine_observability.destinations.registry import ( - _STRATEGIES, - register_destination, + manager.configure() + + queued = manager.destinations[0] + assert queued.maxsize == 50 + assert queued.close_timeout_seconds == 7.5 + manager.close() + + +def test_reconfigure_closes_previous_destinations( + fake_remote_strategy, +) -> None: + manager, _failures = make_manager( + ObservabilityConfig(log_destinations=(fake_remote_strategy,)) ) + manager.configure() + first = manager.destinations[0] + manager._consecutive_failures[id(first)] = 2 + + manager.configure() + + assert first._closed is True + assert manager._consecutive_failures == {} + assert manager.destinations[0] is not first + manager.close() + - register_destination( - "fake-remote", - lambda **kwargs: RecordingInner(), - transport="remote", +def test_reconfigure_after_close_resumes_delivery( + fake_remote_strategy, +) -> None: + """The fork/snapshot story: close → drops → configure() → a fresh + listener delivers again.""" + manager, _failures = make_manager( + ObservabilityConfig(log_destinations=(fake_remote_strategy,)) ) - try: - manager = LogDestinationManager( - config=ObservabilityConfig(log_destinations=("fake_remote",)), - loggers={"event": logging.getLogger("test-reconfigure")}, - serializer=json.dumps, - on_failure=lambda *args, **kwargs: None, - ) - manager.configure() - first = manager.destinations[0] - manager._consecutive_failures[id(first)] = 2 - - manager.configure() - - assert first._closed is True - assert manager._consecutive_failures == {} - assert manager.destinations[0] is not first - manager.close() - finally: - _STRATEGIES.pop("fake_remote", None) + manager.configure() + manager.close() + manager.emit({"event": "dropped"}, log_type="event", severity="INFO") + + manager.configure() + manager.emit({"event": "delivered"}, log_type="event", severity="INFO") + manager.close(5.0) + + rebuilt = manager.destinations[0] + assert [p["event"] for p in rebuilt.inner.payloads] == ["delivered"] diff --git a/tests/test_runtime.py b/tests/test_runtime.py index bb8e72f..e940594 100644 --- a/tests/test_runtime.py +++ b/tests/test_runtime.py @@ -1166,14 +1166,6 @@ def test_from_env_invalid_shutdown_timeout_falls_back(monkeypatch) -> None: assert config.shutdown_timeout_seconds == 3.0 -def test_from_env_reads_google_write_timeout(monkeypatch) -> None: - monkeypatch.setenv("OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS", "2.5") - - config = ObservabilityConfig.from_env(service_name="svc") - - assert config.google_cloud_write_timeout_seconds == 2.5 - - def test_from_env_reads_stdout_format(monkeypatch) -> None: monkeypatch.setenv("OBSERVABILITY_STDOUT_FORMAT", "google") @@ -1202,14 +1194,6 @@ def test_from_env_queue_knobs_fall_back_on_garbage(monkeypatch) -> None: assert config.log_queue_close_timeout_seconds == 2.0 -def test_from_env_google_write_timeout_defaults(monkeypatch) -> None: - monkeypatch.setenv("OBSERVABILITY_GOOGLE_WRITE_TIMEOUT_SECONDS", "bad") - - config = ObservabilityConfig.from_env(service_name="svc") - - assert config.google_cloud_write_timeout_seconds == 10.0 - - def test_from_env_enables_otel_by_default() -> None: config = ObservabilityConfig.from_env(service_name="svc") @@ -1555,6 +1539,51 @@ def test_restart_log_destinations_rebuilds_from_config() -> None: assert observed.log_destination_manager.configured is True +def test_restart_log_destinations_noops_when_disabled(monkeypatch) -> None: + """The kill switch must hold across forks and snapshot restores: + a disabled runtime's restart must not build destinations.""" + observed = runtime(enabled=False) + configure_calls = [] + monkeypatch.setattr( + observed.log_destination_manager, + "configure", + lambda: configure_calls.append(True), + ) + + observed.restart_log_destinations() + + assert configure_calls == [] + + +def test_shutdown_survives_destination_close_failure(monkeypatch) -> None: + class Provider: + def __init__(self) -> None: + self.shutdown_called = False + + def shutdown(self) -> None: + self.shutdown_called = True + + observed = runtime(shutdown_timeout_seconds=1.0) + provider = Provider() + observed.tracer_provider = provider + failures = [] + observed.log_observability_failure = lambda operation, exc, **fields: ( + failures.append(operation) + ) + + def broken_close(deadline=None): + raise RuntimeError("close exploded") + + monkeypatch.setattr( + observed.log_destination_manager, "close", broken_close + ) + + observed.shutdown() + + assert provider.shutdown_called + assert "logging.destination_close" in failures + + def test_configure_otel_creates_real_providers_and_instruments() -> None: observed = runtime(otel_enabled=True) From 10f8836c48c05850a365766661f83429800777f8 Mon Sep 17 00:00:00 2001 From: Anthony Volk Date: Thu, 9 Jul 2026 16:05:01 +0200 Subject: [PATCH 8/9] Guard stdout formatter factories so the fallback stays fail-open MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit resolve_stdout_formatter() called the registered factory unguarded, so a third-party formatter factory that raises (registered through the newly public register_stdout_formatter) escaped every path that resolves it: manager.configure()'s empty-destinations fallback and the _ensure_destinations except-branch re-raised through the same broken factory, propagating into runtime.configure() at host startup and leaving the lazy path rebuilding (and raising) on every emit. The factory call now degrades to the built-in plain formatter — not the registry's "plain" entry, which could itself be the overridden broken one — and reports through the internal-error channel when a reporting channel exists. Tests pin the resolver-level degrade+report and the previously-crashing configure fallback path end to end. Fixes #22 Co-Authored-By: Claude Fable 5 --- README.md | 4 +- changelog.d/22.shutdown.changed.md | 2 +- .../destinations/stdout.py | 17 +++++- tests/test_destinations.py | 57 +++++++++++++++++++ 4 files changed, 77 insertions(+), 3 deletions(-) diff --git a/README.md b/README.md index ea3bcc5..15ebeb2 100644 --- a/README.md +++ b/README.md @@ -68,7 +68,9 @@ construction (so it is re-read on `restart_observability()`) rather than through a core config field. Name lookups for destinations, formatters, and profiles all forgive case, whitespace, and hyphen/underscore variance; an unknown format name falls back to plain -and is reported through the internal-error channel. +and is reported through the internal-error channel, and a registered +formatter factory that raises degrades to the built-in plain formatter +the same way rather than breaking configuration. ## Log emission and delivery semantics diff --git a/changelog.d/22.shutdown.changed.md b/changelog.d/22.shutdown.changed.md index f242de8..8b2fe4a 100644 --- a/changelog.d/22.shutdown.changed.md +++ b/changelog.d/22.shutdown.changed.md @@ -1 +1 @@ -Runtime shutdown now closes log destinations first, inside the same bounded shutdown budget that bounds the OpenTelemetry flush; one deadline is shared across all destination closes. The Google Cloud Logging client library's one-time instrumentation diagnostic entry is suppressed, and unknown `OBSERVABILITY_STDOUT_FORMAT` names are reported through the internal-error channel instead of silently falling back to plain. +Runtime shutdown now closes log destinations first, inside the same bounded shutdown budget that bounds the OpenTelemetry flush; one deadline is shared across all destination closes. The Google Cloud Logging client library's one-time instrumentation diagnostic entry is suppressed, and unknown `OBSERVABILITY_STDOUT_FORMAT` names are reported through the internal-error channel instead of silently falling back to plain, and a registered stdout-formatter factory that raises degrades to the built-in plain formatter (with a report) instead of breaking configuration. diff --git a/policyengine_observability/destinations/stdout.py b/policyengine_observability/destinations/stdout.py index e8bdb7e..2f562f5 100644 --- a/policyengine_observability/destinations/stdout.py +++ b/policyengine_observability/destinations/stdout.py @@ -42,7 +42,22 @@ def resolve_stdout_formatter( ValueError(f"Unknown stdout format {raw!r}; using plain."), ) factory = _FORMATTER_FACTORIES["plain"] - return factory(config) + try: + return factory(config) + except Exception as exc: + # Stdout is the fail-open record, and this resolver also runs on + # the manager's last-resort fallback path: a registered factory + # that raises must degrade to the built-in plain formatter (not + # the registry entry, which could be the broken one), never + # break configure or startup. + if on_failure is not None: + safe_report( + on_failure, + "logging.stdout_format", + exc, + stdout_format=raw, + ) + return _plain_formatter_factory(config) def _plain_formatter_factory(config: Any) -> StdoutFormatter: diff --git a/tests/test_destinations.py b/tests/test_destinations.py index ab581ae..ae51fb5 100644 --- a/tests/test_destinations.py +++ b/tests/test_destinations.py @@ -453,6 +453,63 @@ def broken(payload, *, log_type, severity): assert _emitted_line(logger) == {"event": "x"} +def test_stdout_broken_formatter_factory_degrades_to_plain() -> None: + from policyengine_observability.destinations.stdout import ( + _FORMATTER_FACTORIES, + register_stdout_formatter, + ) + + def broken_factory(config): + raise RuntimeError("factory bug") + + register_stdout_formatter("broken-test", broken_factory) + try: + failures = [] + formatter = resolve_stdout_formatter( + ObservabilityConfig(stdout_format="broken-test"), + on_failure=lambda operation, exc, **fields: failures.append( + (operation, fields) + ), + ) + finally: + _FORMATTER_FACTORIES.pop("broken_test", None) + + formatted = formatter({"event": "x"}, log_type="event", severity="INFO") + + assert formatted == {"event": "x"} + assert len(failures) == 1 + assert failures[0][0] == "logging.stdout_format" + assert failures[0][1]["stdout_format"] == "broken-test" + + +def test_configure_fallback_survives_broken_formatter_factory() -> None: + """The crash path: no destination builds, so the manager's + last-resort stdout fallback resolves the same broken formatter — + configure must stay fail-open and emit must still write plain.""" + from policyengine_observability.destinations.stdout import ( + _FORMATTER_FACTORIES, + register_stdout_formatter, + ) + + def broken_factory(config): + raise RuntimeError("factory bug") + + register_stdout_formatter("broken-test", broken_factory) + try: + config = ObservabilityConfig( + log_destinations=("nonexistent",), stdout_format="broken-test" + ) + logger = RecordingLogger() + manager, _failures = make_manager(config, loggers={"event": logger}) + + manager.configure() # raised before the resolver guard existed + manager.emit({"event": "x"}, log_type="event", severity="INFO") + finally: + _FORMATTER_FACTORIES.pop("broken_test", None) + + assert _emitted_line(logger) == {"event": "x", "severity": "INFO"} + + def test_stdout_google_formatter_never_mutates_caller_payload() -> None: config = ObservabilityConfig( stdout_format="google", google_cloud_project="proj" From 5e373aac496db553d64733357e21311e285e9763 Mon Sep 17 00:00:00 2001 From: Anthony Volk Date: Thu, 9 Jul 2026 16:14:19 +0200 Subject: [PATCH 9/9] Drop the google_credentials compatibility shim MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Verified no consumer imports the old module path: the household API's only google_credentials references are its own unrelated policyengine_household_modal module, and org-wide code search finds no external importers — everything goes through the top-level re-exports, which are unchanged. The path removal gets its own .removed changelog fragment (still a minor bump). Fixes #22 Co-Authored-By: Claude Fable 5 --- changelog.d/22.added.md | 2 +- changelog.d/22.credentials.removed.md | 1 + .../google_credentials.py | 34 ------------------- tests/test_public_api.py | 15 -------- 4 files changed, 2 insertions(+), 50 deletions(-) create mode 100644 changelog.d/22.credentials.removed.md delete mode 100644 policyengine_observability/google_credentials.py diff --git a/changelog.d/22.added.md b/changelog.d/22.added.md index e2d37f7..e1e0f77 100644 --- a/changelog.d/22.added.md +++ b/changelog.d/22.added.md @@ -1 +1 @@ -Added an agent-native stdout format (`OBSERVABILITY_STDOUT_FORMAT=google`): JSON lines carry the special keys the Cloud Run/GKE logging agent promotes to first-class LogEntry fields (severity, trace, span, labels), enabling full-fidelity Cloud Logging ingestion from stdout with no in-process network emission. Added a destination strategy registry and a generic queued transport: destinations register as `inline` (synchronous, e.g. stdout) or `remote`, and every remote destination is wrapped in a bounded queue drained by a stdlib QueueListener thread, so no remote write ever runs on a request thread. The queue drops-and-counts when full (throttled reports), and close is deadline-bounded (`OBSERVABILITY_LOG_QUEUE_MAXSIZE`, `OBSERVABILITY_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS`). `register_destination` and `register_stdout_formatter` are exported at the package top level so external backends can register strategies (with `required_config` declaring the config fields a strategy needs, checked generically during profile expansion), and the Google credential helpers moved to `policyengine_observability.destinations.google_credentials` (the old import path remains as a shim). +Added an agent-native stdout format (`OBSERVABILITY_STDOUT_FORMAT=google`): JSON lines carry the special keys the Cloud Run/GKE logging agent promotes to first-class LogEntry fields (severity, trace, span, labels), enabling full-fidelity Cloud Logging ingestion from stdout with no in-process network emission. Added a destination strategy registry and a generic queued transport: destinations register as `inline` (synchronous, e.g. stdout) or `remote`, and every remote destination is wrapped in a bounded queue drained by a stdlib QueueListener thread, so no remote write ever runs on a request thread. The queue drops-and-counts when full (throttled reports), and close is deadline-bounded (`OBSERVABILITY_LOG_QUEUE_MAXSIZE`, `OBSERVABILITY_LOG_QUEUE_CLOSE_TIMEOUT_SECONDS`). `register_destination` and `register_stdout_formatter` are exported at the package top level so external backends can register strategies (with `required_config` declaring the config fields a strategy needs, checked generically during profile expansion), and the Google credential helpers moved to `policyengine_observability.destinations.google_credentials`. diff --git a/changelog.d/22.credentials.removed.md b/changelog.d/22.credentials.removed.md new file mode 100644 index 0000000..eeddf4c --- /dev/null +++ b/changelog.d/22.credentials.removed.md @@ -0,0 +1 @@ +Removed the `policyengine_observability.google_credentials` module path; the credential helpers live at `policyengine_observability.destinations.google_credentials` and remain re-exported from the package top level (`load_google_credentials`, `configure_google_application_credentials`), which no known consumer's imports go beyond. diff --git a/policyengine_observability/google_credentials.py b/policyengine_observability/google_credentials.py deleted file mode 100644 index 6990e84..0000000 --- a/policyengine_observability/google_credentials.py +++ /dev/null @@ -1,34 +0,0 @@ -"""Deprecated import location kept for backward compatibility. - -The Google credential helpers are edge (backend-specific) code and live -in ``policyengine_observability.destinations.google_credentials``. -Import them from there or from the package top level. -""" - -from __future__ import annotations - -from .destinations.google_credentials import ( - DEFAULT_STS_TOKEN_URL, - GOOGLE_CREDENTIAL_SCOPES, - JWT_SUBJECT_TOKEN_TYPE, - MODAL_IDENTITY_TOKEN_ENV, - OIDC_TOKEN_ENV, - SERVICE_ACCOUNT_EMAIL_ENV, - STS_TOKEN_URL_ENV, - WORKLOAD_IDENTITY_PROVIDER_ENV, - configure_google_application_credentials, - load_google_credentials, -) - -__all__ = [ - "DEFAULT_STS_TOKEN_URL", - "GOOGLE_CREDENTIAL_SCOPES", - "JWT_SUBJECT_TOKEN_TYPE", - "MODAL_IDENTITY_TOKEN_ENV", - "OIDC_TOKEN_ENV", - "SERVICE_ACCOUNT_EMAIL_ENV", - "STS_TOKEN_URL_ENV", - "WORKLOAD_IDENTITY_PROVIDER_ENV", - "configure_google_application_credentials", - "load_google_credentials", -] diff --git a/tests/test_public_api.py b/tests/test_public_api.py index 5c0491b..a24f474 100644 --- a/tests/test_public_api.py +++ b/tests/test_public_api.py @@ -121,21 +121,6 @@ async def run() -> dict[str, float]: assert "load_ms" in asyncio.run(run()) -def test_deprecated_google_credentials_path_still_imports() -> None: - # The module moved to destinations/google_credentials; the old path - # is a compatibility shim that must keep re-exporting the API. - from policyengine_observability import google_credentials as shim - from policyengine_observability.destinations import ( - google_credentials as edge, - ) - - assert shim.load_google_credentials is edge.load_google_credentials - assert ( - shim.configure_google_application_credentials - is edge.configure_google_application_credentials - ) - - def test_registration_hooks_are_exported_at_top_level() -> None: assert callable(observability.register_destination) assert callable(observability.register_stdout_formatter)