diff --git a/sentinel/api/app.py b/sentinel/api/app.py index a36974d..b2ac42f 100644 --- a/sentinel/api/app.py +++ b/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) diff --git a/sentinel/diagnosis/llm_client.py b/sentinel/diagnosis/llm_client.py index 1bf15d1..ef3e570 100644 --- a/sentinel/diagnosis/llm_client.py +++ b/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, diff --git a/sentinel/enrichment/orchestrator.py b/sentinel/enrichment/orchestrator.py index df18ee3..e0be1ca 100644 --- a/sentinel/enrichment/orchestrator.py +++ b/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) diff --git a/sentinel/observability/__init__.py b/sentinel/observability/__init__.py index f9a379e..fb5a1b3 100644 --- a/sentinel/observability/__init__.py +++ b/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", diff --git a/tests/unit/api/test_instrumentation.py b/tests/unit/api/test_instrumentation.py new file mode 100644 index 0000000..93a2472 --- /dev/null +++ b/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 diff --git a/tests/unit/diagnosis/test_llm_client.py b/tests/unit/diagnosis/test_llm_client.py index 22a5ffd..ce5caa5 100644 --- a/tests/unit/diagnosis/test_llm_client.py +++ b/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 diff --git a/tests/unit/enrichment/test_orchestrator.py b/tests/unit/enrichment/test_orchestrator.py index d160d90..e963913 100644 --- a/tests/unit/enrichment/test_orchestrator.py +++ b/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() diff --git a/tests/unit/ingestion/test_app_wiring.py b/tests/unit/ingestion/test_app_wiring.py index 8b39c84..ed5d3d8 100644 --- a/tests/unit/ingestion/test_app_wiring.py +++ b/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() diff --git a/tests/unit/observability/test_setup.py b/tests/unit/observability/test_setup.py new file mode 100644 index 0000000..0382b42 --- /dev/null +++ b/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())