fix(observability): wire logging, tracing spans, and FastAPI instrumentation (#64)

sentinel/api/app.py

@@ -13,6 +13,7 @@
 import httpx
 from aiokafka import AIOKafkaConsumer
 from fastapi import FastAPI
+from opentelemetry.instrumentation.fastapi import FastAPIInstrumentor
 from redis.asyncio import Redis
 
 from sentinel import __version__
@@ -54,9 +55,9 @@
     MemoryPipeline,
     PgVectorIncidentStore,
 )
+from sentinel.observability import configure_observability
 from sentinel.observability.llm_audit import LLMAuditLogger
 from sentinel.observability.metrics import consumer_crashed_total
-from sentinel.observability.tracing import configure_tracing
 from sentinel.persistence.repositories import (
     OutboxRepository,
     PostgresDeployRepository,
@@ -154,7 +155,7 @@ def _callback(task: asyncio.Task[None]) -> None:
 @asynccontextmanager
 async def lifespan(app: FastAPI) -> AsyncIterator[None]:
     settings = load_settings()
-    configure_tracing(settings)
+    configure_observability(settings)
 
     engine = make_async_engine(settings)
     session_factory = make_session_factory(engine)
@@ -507,6 +508,11 @@ def build_app() -> FastAPI:
         ),
         lifespan=lifespan,
     )
+    # Emit a server span per request. Logging + tracing providers are configured
+    # in the lifespan; this only registers the ASGI middleware. Per-app (not the
+    # global `.instrument()`) and idempotent across repeated build_app() calls —
+    # the test fixtures construct the app many times (gh#64).
+    FastAPIInstrumentor.instrument_app(app)
     app.include_router(health_router)
     app.include_router(webhooks_router)
     app.include_router(resolve_router)

sentinel/diagnosis/llm_client.py

@@ -19,6 +19,7 @@
 from pydantic import SecretStr
 
 from sentinel.diagnosis.errors import LLMNoToolCall, LLMTimeout, LLMTransport
+from sentinel.observability.tracing import span_for_llm
 
 _BACKOFF_S = 0.5
 
@@ -82,19 +83,22 @@ async def diagnose_call(
         tool_name: str,
         repair: RepairTurn | None = None,
     ) -> LLMResult:
-        try:
-            return await asyncio.wait_for(
-                self._call_with_retry(
-                    system=system,
-                    user=user,
-                    tool_schema=tool_schema,
-                    tool_name=tool_name,
-                    repair=repair,
-                ),
-                timeout=self.timeout_s,
-            )
-        except TimeoutError as e:
-            raise LLMTimeout(f"LLM call exceeded {self.timeout_s}s") from e
+        # Wrap the whole call (incl. timeout + retry) in one span. gh#64:
+        # `span_for_llm` previously had zero call sites, so no LLM spans existed.
+        with span_for_llm(self.model):
+            try:
+                return await asyncio.wait_for(
+                    self._call_with_retry(
+                        system=system,
+                        user=user,
+                        tool_schema=tool_schema,
+                        tool_name=tool_name,
+                        repair=repair,
+                    ),
+                    timeout=self.timeout_s,
+                )
+            except TimeoutError as e:
+                raise LLMTimeout(f"LLM call exceeded {self.timeout_s}s") from e
 
     async def _call_with_retry(
         self,

sentinel/enrichment/orchestrator.py

@@ -26,6 +26,7 @@
     enrichment_failures_total,
     enrichment_section_status_total,
 )
+from sentinel.observability.tracing import span_for_fetcher
 from sentinel.schemas.context import FetcherResult, IncidentContext
 
 log = logging.getLogger(__name__)
@@ -69,6 +70,21 @@ async def _run(
     fetcher: Fetcher,
     incident: Any,
     deps: EnrichmentDeps,
+) -> FetcherResult[Any]:
+    """Run one fetcher wrapped in a per-fetcher tracing span.
+
+    The fetch/timeout/breaker/coerce logic lives in `_run_guarded` (which never
+    raises); this wrapper only opens the span so enrichment is actually traced.
+    gh#64: `span_for_fetcher` previously had zero call sites.
+    """
+    with span_for_fetcher(fetcher.name):
+        return await _run_guarded(fetcher, incident, deps)
+
+
+async def _run_guarded(
+    fetcher: Fetcher,
+    incident: Any,
+    deps: EnrichmentDeps,
 ) -> FetcherResult[Any]:
     started = time.monotonic()
     breaker = deps.breakers.get(fetcher.name)

sentinel/observability/__init__.py

@@ -5,6 +5,7 @@
 that needs instrumentation lands.
 """
 
+from sentinel.config.settings import Settings
 from sentinel.observability.cost import usd_cost
 from sentinel.observability.logging import (
     bind_request_context,
@@ -18,10 +19,24 @@
     span_for_llm,
 )
 
+
+def configure_observability(settings: Settings) -> None:
+    """Process-level observability init — structured logging + tracing.
+
+    The single entry point the app lifespan calls, so the "observability is
+    wired" contract has one place to set up and one to test. gh#64: the lifespan
+    previously called only ``configure_tracing``, leaving structlog inert and
+    runtime logging on bare stdlib.
+    """
+    configure_logging(settings)
+    configure_tracing(settings)
+
+
 __all__ = [
     "bind_request_context",
     "clear_request_context",
     "configure_logging",
+    "configure_observability",
     "configure_tracing",
     "get_llm_audit_logger",
     "span_for_fetcher",

tests/unit/api/test_instrumentation.py

@@ -0,0 +1,17 @@
+# tests/unit/api/test_instrumentation.py
+"""The FastAPI app must be OpenTelemetry-instrumented at build time.
+
+gh#64: `opentelemetry-instrumentation-fastapi` was a declared dependency but
+`FastAPIInstrumentor` was never imported, so no request spans were ever emitted.
+`instrument_app` sets `app._is_instrumented_by_opentelemetry = True`, which is
+the observable contract this test pins.
+"""
+
+from __future__ import annotations
+
+from sentinel.api.app import build_app
+
+
+def test_build_app_instruments_fastapi() -> None:
+    app = build_app()
+    assert getattr(app, "_is_instrumented_by_opentelemetry", False) is True

tests/unit/diagnosis/test_llm_client.py

@@ -309,3 +309,29 @@ async def test_no_tool_call_raises_llm_no_tool_call() -> None:
             tool_schema=_TOOL_SCHEMA,
             tool_name=_TOOL_NAME,
         )
+
+
+async def test_diagnose_call_emits_llm_span(monkeypatch: pytest.MonkeyPatch) -> None:
+    """The LLM call is wrapped in a tracing span (gh#64 — span_for_llm was unused)."""
+    from opentelemetry.sdk.trace import TracerProvider
+    from opentelemetry.sdk.trace.export import SimpleSpanProcessor
+    from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter
+
+    exporter = InMemorySpanExporter()
+    provider = TracerProvider()
+    provider.add_span_processor(SimpleSpanProcessor(exporter))
+    monkeypatch.setattr(
+        "sentinel.observability.tracing._tracer",
+        lambda: provider.get_tracer("sentinel"),
+    )
+
+    client = _make_client(stream_result=_FakeStream(_make_fake_message()))
+    await client.diagnose_call(
+        system="sys",
+        user="user",
+        tool_schema=_TOOL_SCHEMA,
+        tool_name=_TOOL_NAME,
+    )
+
+    names = {s.name for s in exporter.get_finished_spans()}
+    assert "llm.claude-sonnet-4-5" in names

tests/unit/enrichment/test_orchestrator.py

@@ -84,6 +84,33 @@ async def test_assemble_returns_incident_context() -> None:
     assert ctx.recent_deploys.status == "ok"
 
 
+@pytest.mark.asyncio
+async def test_assemble_emits_a_span_per_fetcher(monkeypatch: pytest.MonkeyPatch) -> None:
+    """Each fetcher run is wrapped in a tracing span.
+
+    gh#64: `span_for_fetcher` existed but had zero call sites, so enrichment
+    emitted no spans. Inject an in-memory exporter (the SDK forbids overriding a
+    set provider, so patch the tracer helper) and assert one span per fetcher.
+    """
+    from opentelemetry.sdk.trace import TracerProvider
+    from opentelemetry.sdk.trace.export import SimpleSpanProcessor
+    from opentelemetry.sdk.trace.export.in_memory_span_exporter import InMemorySpanExporter
+
+    exporter = InMemorySpanExporter()
+    provider = TracerProvider()
+    provider.add_span_processor(SimpleSpanProcessor(exporter))
+    monkeypatch.setattr(
+        "sentinel.observability.tracing._tracer",
+        lambda: provider.get_tracer("sentinel"),
+    )
+
+    deps = _make_deps(_six_ok())
+    await assemble(_make_incident(), deps)
+
+    names = {s.name for s in exporter.get_finished_spans()}
+    assert {f"fetcher.{n}" for n in ("deploys", "related_alerts", "runbooks")} <= names
+
+
 @pytest.mark.asyncio
 async def test_raising_fetcher_becomes_failed_result() -> None:
     incident = _make_incident()

tests/unit/ingestion/test_app_wiring.py

@@ -30,6 +30,7 @@ async def test_lifespan_starts_and_stops_producer_and_drainer(
         patch("sentinel.api.app.FastEmbedProvider") as MockEmbedProvider,
         patch("sentinel.api.app.PromptBundle") as MockPromptBundle,
         patch("sentinel.api.app._refresh_outbox_gauges") as MockGauges,
+        patch("sentinel.api.app.configure_observability") as MockConfigureObs,
     ):
         prod_instance = MockProducer.return_value
         prod_instance.start = AsyncMock()
@@ -93,6 +94,9 @@ async def _noop_gauges(*args: object, **kwargs: object) -> None:
             assert hasattr(app.state, "diagnosis_consumer")
             assert hasattr(app.state, "memory_consumer")
 
+        # gh#64: the lifespan must wire observability (logging + tracing), not
+        # just tracing as it did before.
+        MockConfigureObs.assert_called_once()
         prod_instance.start.assert_awaited_once()
         prod_instance.stop.assert_awaited_once()
         drainer_instance.stop.assert_called_once()

tests/unit/observability/test_setup.py

@@ -0,0 +1,47 @@
+# tests/unit/observability/test_setup.py
+"""`configure_observability` is the single process-level init entry point.
+
+It must wire BOTH structured logging and tracing — the gh#64 regression was that
+the lifespan called only `configure_tracing`, so structlog never activated and
+runtime logging fell back to bare stdlib.
+"""
+
+from __future__ import annotations
+
+import pytest
+from sentinel.config.settings import Settings
+
+
+def _settings() -> Settings:
+    return Settings(
+        postgres_dsn="postgresql+asyncpg://u:p@localhost/d",
+        redis_url="redis://localhost:6379/0",
+        kafka_brokers="localhost:9092",
+        anthropic_api_key="x",
+    )
+
+
+def test_configure_observability_wires_logging_and_tracing(
+    monkeypatch: pytest.MonkeyPatch,
+) -> None:
+    from sentinel.observability import configure_observability
+
+    calls: list[str] = []
+    monkeypatch.setattr(
+        "sentinel.observability.configure_logging", lambda s: calls.append("logging")
+    )
+    monkeypatch.setattr(
+        "sentinel.observability.configure_tracing", lambda s: calls.append("tracing")
+    )
+
+    configure_observability(_settings())
+
+    assert calls == ["logging", "tracing"]
+
+
+def test_configure_observability_runs_for_real_without_error() -> None:
+    """The real wiring must execute end-to-end (no endpoint configured)."""
+    from sentinel.observability import configure_observability
+
+    # Should not raise; logging is idempotent and tracing no-ops without an endpoint.
+    configure_observability(_settings())