tests/test_observability.py

"""Foundation smoke tests for the observability facade (ADR-0024).

Zero mocks: exercises the real facade with the in-memory store + a real OTEL
tracer provider, asserting that logs, spans, context, and metrics all land.
"""

from __future__ import annotations

import logging

from src import observability as obs


def _fresh(**env) -> None:
    """Reconfigure the facade with explicit settings (force past the singleton)."""
    obs.configure(level="DEBUG", tracing="memory", force=True, **env)
    obs.telemetry_store().clear()


def test_configure_is_idempotent():
    obs.configure()
    store = obs.telemetry_store()
    obs.configure()  # second call must not replace the store
    assert obs.telemetry_store() is store


def test_log_emits_structured_record_to_store():
    _fresh()
    obs.log("event.append", kind="agent.spoke", actor="spy-bex", turn=3)
    logs = obs.telemetry_store().recent_logs()
    appended = [r for r in logs if r.get("event") == "event.append"]
    assert appended, "expected the structured log to reach the store"
    assert appended[-1]["kind"] == "agent.spoke"
    assert appended[-1]["actor"] == "spy-bex"


def test_log_sanitises_reserved_field_names():
    _fresh()
    # 'module' is a reserved LogRecord attribute — must not raise, gets suffixed.
    obs.log("oddity", module="memory", name="x")
    record = [r for r in obs.telemetry_store().recent_logs() if r.get("event") == "oddity"][-1]
    assert record.get("module_") == "memory"
    assert record.get("name_") == "x"


def test_context_binding_stamps_logs():
    _fresh()
    # `set_context` (used by the conductor for run/turn) persists by design, so the
    # process context may be non-empty here; capture it and assert bind RESTORES it.
    before = obs.current_context().get("run_id")
    with obs.bind(run_id="run-7", turn=2, agent="clue-gatherer"):
        assert obs.current_context()["run_id"] == "run-7"
        obs.log("memory.recall", k=5)
    record = [r for r in obs.telemetry_store().recent_logs() if r.get("event") == "memory.recall"][-1]
    assert record["run_id"] == "run-7"
    assert record["turn"] == 2
    assert record["agent"] == "clue-gatherer"
    # Binding is scoped — run_id returns to whatever it was before the block.
    assert obs.current_context().get("run_id") == before


def test_span_recorded_with_attributes_and_nesting():
    _fresh()
    with obs.bind(run_id="run-9"):
        with obs.span("turn", **{"mal.turn": 1}):
            with obs.span("llm.call", **{"gen_ai.request.model": "gpt-oss-20b"}):
                obs.add_span_attrs(**{"gen_ai.usage.output_tokens": 42})
    spans = {s.name: s for s in obs.telemetry_store().recent_spans()}
    assert "turn" in spans and "llm.call" in spans
    llm = spans["llm.call"]
    assert llm.attributes["gen_ai.request.model"] == "gpt-oss-20b"
    assert llm.attributes["gen_ai.usage.output_tokens"] == 42
    # llm.call nests under turn.
    assert llm.parent_id == spans["turn"].span_id


def test_span_records_exception_status():
    _fresh()
    try:
        with obs.span("boom"):
            raise ValueError("kaboom")
    except ValueError:
        pass
    boom = [s for s in obs.telemetry_store().recent_spans() if s.name == "boom"][-1]
    assert boom.status == "ERROR"


def test_metrics_counters_and_observations():
    _fresh()
    obs.record_llm_call("gpt-oss-20b", prompt_tokens=100, completion_tokens=20, cost_usd=0.001)
    obs.record_agent_turn("spy-bex", 0.25)
    obs.record_governor_trip("max_total_tokens")
    totals = obs.telemetry_store().counter_totals()
    assert totals["llm.calls"] == 1
    assert totals["llm.tokens.input"] == 100
    assert totals["llm.tokens.output"] == 20
    assert totals["governor.trips"] == 1
    latencies = obs.telemetry_store().metric_points("agent.turn.seconds")
    assert latencies and latencies[-1].value == 0.25


def test_store_is_bounded():
    obs.configure(force=True)
    store = obs.telemetry_store()
    store.clear()
    for i in range(store._logs.maxlen + 50):
        obs.log("spam", i=i)
    assert len(store.recent_logs(10_000_000)) == store._logs.maxlen


def test_get_logger_returns_standard_logger():
    assert isinstance(obs.get_logger("x.y"), logging.Logger)