diff --git a/backend/.env.example b/backend/.env.example index 734692ae..c0c6a8b3 100644 --- a/backend/.env.example +++ b/backend/.env.example @@ -14,6 +14,15 @@ SUPABASE_SERVICE_KEY=your-service-role-key-here # app runtime, which goes through PostgREST. SUPABASE_DB_URL=postgresql://postgres:[password]@db.your-project-ref.supabase.co:5432/postgres +# Logfire ops/error/LLM tracing (optional). Get a write token from +# https://logfire.pydantic.dev → your project → Settings → Write tokens. +# When unset, Logfire stays dormant: the app behaves exactly as today with no +# egress. When set, FastAPI request traces and Pydantic AI agent spans (incl. +# per-call LLM token usage) stream to Logfire. Prompt/completion/document text +# is scrubbed to a length-capped preview + sha256 fingerprint before egress +# (services/logfire_scrubber.py); request bodies/headers are never captured. +# LOGFIRE_TOKEN= + # Deployment environment. Defaults to "production" when unset (strict, fail-closed checks). # Set APP_ENV=local for local dev (relaxes SESSION_SECRET); set APP_ENV=staging on the staging # deploy (drives the noindex header). "staging" is NOT in IS_LOCAL, so it stays fail-closed. diff --git a/backend/config.py b/backend/config.py index 38b1c0f8..cec89681 100644 --- a/backend/config.py +++ b/backend/config.py @@ -12,6 +12,12 @@ SUPABASE_URL = os.getenv("SUPABASE_URL", "") SUPABASE_SERVICE_KEY = os.getenv("SUPABASE_SERVICE_KEY", "") +# Logfire ops/error/LLM tracing. Optional: unset = dormant (main.py configures +# send_to_logfire="if-token-present", so no spans egress without it). Logfire's +# SDK reads this env var itself; surfaced here only so all env access stays +# visible through config.py. +LOGFIRE_TOKEN = os.getenv("LOGFIRE_TOKEN", "") + PORT = int(os.getenv("PORT", "5000")) FRONTEND_URL = os.getenv("FRONTEND_URL", "http://localhost:3000") SESSION_SECRET = os.getenv("SESSION_SECRET", "") diff --git a/backend/main.py b/backend/main.py index 12a07dcd..1780b266 100644 --- a/backend/main.py +++ b/backend/main.py @@ -84,8 +84,45 @@ async def _lifespan(_app: FastAPI): # No shutdown hooks today. +def _drop_request_arguments(_request, _attributes): + """request_attributes_mapper for instrument_fastapi: never log endpoint args. + + FastAPI instrumentation otherwise records the parsed endpoint arguments — + the request body and query/path params — on the request span under + ``fastapi.arguments.values``. In Sapling those carry student content: chat + messages, note bodies, quiz answers, uploaded document text. That path is + NOT covered by the ``scrub_value`` callback (Logfire routes only a subset of + attributes through scrubbing, and a body field named e.g. ``body`` matches + no risky pattern), so the only safe move is to drop the arguments entirely. + Returning ``None`` tells Logfire to record no argument attributes at all. + + We keep the method, route template, status, and latency — which is what the + request trace is actually for. (The full URL and rendered span message do + still carry the raw query string; Sapling query params are ids/enums plus a + couple of low-sensitivity search terms, never prompts/completions/document + text — see docs/observability-logging-tracking.md.) + """ + return None + + app = FastAPI(title="Sapling API", version="1.0.0", lifespan=_lifespan) +# Emit a span per HTTP request (method, route, status, latency) so request +# traces and errors show up in Logfire alongside the Pydantic AI agent spans. +# Like configure()/instrument_pydantic_ai() above, this is always on but inert +# without LOGFIRE_TOKEN (send_to_logfire="if-token-present"). +# +# Egress safety (layered): request bodies/params are dropped via +# _drop_request_arguments; request/response headers are not captured +# (capture_headers=False); and the separate arguments/endpoint spans are off +# (extra_spans=False). No student content leaves the process on request spans. +logfire.instrument_fastapi( + app, + capture_headers=False, + extra_spans=False, + request_attributes_mapper=_drop_request_arguments, +) + if recost_api_key and RecostMiddleware is not None: app.add_middleware( RecostMiddleware, diff --git a/backend/services/flashcard_import_service.py b/backend/services/flashcard_import_service.py index e09c9695..7706132b 100644 --- a/backend/services/flashcard_import_service.py +++ b/backend/services/flashcard_import_service.py @@ -10,6 +10,7 @@ import io import json import logging +import math import os import re import sqlite3 @@ -91,7 +92,11 @@ def check_rate_limit(user_id: str) -> int | None: now = time.time() bucket = [t for t in _rate_state.get(user_id, []) if now - t < _RATE_WINDOW_SEC] if len(bucket) >= _RATE_LIMIT: - retry = int(_RATE_WINDOW_SEC - (now - bucket[0])) + 1 + # Seconds until the oldest call in the window ages out (freeing a slot), + # rounded up. ceil keeps a sub-second remainder from reporting 0, and — + # unlike the old `int(...) + 1` — never overshoots to 61 when the calls + # land in the same clock tick (elapsed == 0). Always in [1, _RATE_WINDOW_SEC]. + retry = math.ceil(_RATE_WINDOW_SEC - (now - bucket[0])) _rate_state[user_id] = bucket return retry bucket.append(now) diff --git a/backend/tests/test_logfire_scrubber.py b/backend/tests/test_logfire_scrubber.py index 70550e27..b6187d6b 100644 --- a/backend/tests/test_logfire_scrubber.py +++ b/backend/tests/test_logfire_scrubber.py @@ -122,3 +122,125 @@ def test_scrub_value_redacts_when_inner_path_segment_is_risky(): result = scrub_value(match) assert isinstance(result, str) assert "redacted" in result + + +# ── instrument_fastapi wiring: no request bodies/headers may egress ────────── +# +# The scrubber only sees the attributes Logfire routes through it — and it does +# NOT route the FastAPI endpoint-argument attribute (`fastapi.arguments.values`) +# nor `http.url`/`logfire.msg`. That argument attribute otherwise carries the +# request body and params: chat messages, note bodies, quiz answers, uploaded +# document text. A body field named e.g. `body` matches no risky pattern, so +# scrubbing can't be relied on here. main.py therefore drops the arguments at +# the source via a `request_attributes_mapper` that returns None, keeps headers +# off (`capture_headers=False`), and keeps the extra argument/endpoint spans off +# (`extra_spans=False`). These guards fail loudly if any of that regresses. + +def _instrument_fastapi_kwargs(): + """Parse main.py (no import/side effects) and return the keyword + arguments passed to logfire.instrument_fastapi(...), as an AST map.""" + import ast + from pathlib import Path + + main_src = Path(__file__).resolve().parents[1] / "main.py" + tree = ast.parse(main_src.read_text(encoding="utf-8")) + for node in ast.walk(tree): + if ( + isinstance(node, ast.Call) + and isinstance(node.func, ast.Attribute) + and node.func.attr == "instrument_fastapi" + ): + return {kw.arg: kw.value for kw in node.keywords} + return None + + +def test_instrument_fastapi_is_wired(): + """FastAPI request traces (success criterion #1) require this call.""" + assert _instrument_fastapi_kwargs() is not None, ( + "logfire.instrument_fastapi(app) must be called in main.py so FastAPI " + "request traces reach Logfire." + ) + + +def test_instrument_fastapi_drops_arguments_and_headers(): + """Egress guard: request bodies/params/headers must never leave the process. + + - `request_attributes_mapper` must be provided (it drops `fastapi.arguments`). + - `capture_headers` / `extra_spans`, if present, must be explicitly False. + Flipping any of these would ship un-scrubbed student content. + """ + import ast + + kwargs = _instrument_fastapi_kwargs() + assert kwargs is not None + assert "request_attributes_mapper" in kwargs, ( + "instrument_fastapi must pass request_attributes_mapper to drop request " + "bodies/params (fastapi.arguments.values), which the scrubber can't reach." + ) + for flag in ("extra_spans", "capture_headers"): + val = kwargs.get(flag) + if val is not None: + assert isinstance(val, ast.Constant) and val.value is False, ( + f"instrument_fastapi({flag}=...) must be False so request " + f"bodies/headers are not sent to Logfire." + ) + + +def test_request_body_does_not_appear_in_exported_spans(): + """End-to-end: fire a real request with a body + query and assert the body + never lands in any exported span attribute. + + This is the concrete proof of "no student content leaves un-fingerprinted" + for the request-trace egress path introduced by instrument_fastapi. It + mirrors main.py's wiring (mapper drops args) against an in-memory exporter. + """ + import json + + import logfire + from fastapi import FastAPI, Query + from fastapi.testclient import TestClient + from logfire.testing import SimpleSpanProcessor, TestExporter + from pydantic import BaseModel + + from main import _drop_request_arguments # noqa: PLC2701 — the exact mapper we ship + + exporter = TestExporter() + logfire.configure( + send_to_logfire=False, + additional_span_processors=[SimpleSpanProcessor(exporter)], + ) + + app = FastAPI() + + class NoteIn(BaseModel): + title: str + body: str + + @app.post("/notes/{note_id}") + def create_note(note_id: str, note: NoteIn, q: str = Query("")): + return {"ok": True} + + logfire.instrument_fastapi( + app, + capture_headers=False, + extra_spans=False, + request_attributes_mapper=_drop_request_arguments, + ) + + secret = "MITOCHONDRIA_POWERHOUSE_ESSAY_BODY" + TestClient(app).post( + "/notes/note-123", json={"title": "Bio Notes", "body": secret + " " * 0} + ) + + spans = exporter.exported_spans_as_dict() + assert spans, "instrument_fastapi should emit a request span" + blob = json.dumps(spans) + assert secret not in blob, ( + "request body leaked into a span attribute — the request_attributes_mapper " + "is not dropping fastapi.arguments.values" + ) + # Sanity: the span still carries the useful ops fields. + attrs = spans[-1]["attributes"] + assert attrs.get("http.route") == "/notes/{note_id}" + assert attrs.get("http.method") == "POST" + assert "fastapi.arguments.values" not in attrs diff --git a/docs/observability-logging-tracking.md b/docs/observability-logging-tracking.md index 4d81a690..46eb3374 100644 --- a/docs/observability-logging-tracking.md +++ b/docs/observability-logging-tracking.md @@ -100,6 +100,65 @@ No raw content is ever stored — only fingerprints. - Admins can query usage, per-user activity, LLM cost rollups, and errors via `/api/admin/analytics`, and view them in an admin dashboard. +## Logfire (activated in #119) + +Logfire is our external ops/error/LLM tracing tool. It is **complementary** to +the owned Supabase `events`/`llm_usage` tables — it is not a replacement and +does not write to them, so enabling it cannot double-count anything (the two +capture paths share no code). + +### What Logfire captures + +- FastAPI **request traces**: method, route template (`/api/notes/{note_id}`), + status code, and latency — one span per request (`instrument_fastapi`). +- Pydantic AI **agent spans**: the agent run, tool calls, and **live per-call + LLM token usage** (`instrument_pydantic_ai`). + +### How to enable + +1. Create a **write token** in the Logfire UI: https://logfire.pydantic.dev → + your project → Settings → Write tokens. +2. Set `LOGFIRE_TOKEN=` in the environment (see `backend/.env.example`). +3. Restart the backend. Request and agent spans now stream to Logfire. + +With **no token**, Logfire is dormant: `logfire.configure(...)` uses +`send_to_logfire="if-token-present"`, so nothing egresses and the app behaves +exactly as before. `service_name="sapling-backend"` identifies the service in +the Logfire UI. Both settings live in `backend/main.py`. + +### What is scrubbed / kept out of egress + +**No student content (prompts, completions, uploaded document text) leaves the +process.** Three layers, all in `backend/main.py` + `services/logfire_scrubber.py`: + +- **Agent prompt/output** (`gen_ai.prompt`, `all_messages_events`, + `input/output.value`, …): the `scrub_value` callback truncates each string to + an 80-char preview and appends a `sha256` fingerprint, so a body is + debuggable/correlatable but never shipped in full. Logfire's built-in patterns + (`password`, `secret`, `api_key`, …) are still fully redacted. +- **Request bodies + params** (`fastapi.arguments.values` — chat messages, note + bodies, quiz answers, uploaded text): dropped entirely via a + `request_attributes_mapper` that returns `None`. Logfire does **not** route + this attribute through the scrubber, so dropping it at the source is the only + safe option. +- **Headers**: not captured (`capture_headers=False`). + +**Known, in-scope limitation — query strings.** The full request URL and the +rendered span message (`http.url`, `logfire.msg`) still contain the raw query +string, and Logfire deliberately keeps these standard attributes unscrubbed. +Sapling query params are ids / enums / pagination plus a couple of +low-sensitivity free-text terms (course search `q`, `check_username`) — **never +prompts, completions, or document text**. Convention: do not put sensitive +free-text in query params; send it in the request body (which is dropped). + +### Verifying the scrubbing + +`backend/tests/test_logfire_scrubber.py` covers it: unit tests for the +prompt/output redaction, AST guards that fail if `instrument_fastapi` ever loses +the argument-dropping mapper (or turns header/extra-span capture on), and an +end-to-end test that fires a request with a body and asserts the body never +appears in any exported span. + ## Conventions honored - Supabase access only via `db/connection.py::table()`.