A Cost Column That Is Allowed To Be NULL

Two questions arrive from different directions and get answered by the same code.

An owner opens the ops view and asks what the agents cost this month, and whether the prompt cache is actually working. An engineer reads a support ticket that says "it hung," and needs to know which request that was and what the model did inside it.

CommsCrew answers both from one capture point. Almost every Anthropic API call in the product goes through BaseCrewAgent, and the exceptions are counted at the end of this post. At the end of each call, one method fans the result into three sinks with three separate jobs: a durable agent_runs row for per-org accounting, Prometheus counters for operational aggregates, and an OpenTelemetry span for per-request flow.

The rest of this post is how those three stay honest.

Context is bound once at the edge, and nothing downstream participates

backend/app_new/core/logging.py is the only place logging is configured, and it is short. Structlog, contextvars merged first, ISO timestamps in UTC, and one branch that decides rendering: LOG_FORMAT=json gives one JSON object per line in production, console gives the colored dev default. Every entrypoint calls it, the FastAPI factory and migrate and dev_init, so a schema sync logs the same way the API does.

The interesting choice is one line down:

    logging.basicConfig(level=level, stream=sys.stdout, format="%(message)s")
    logging.getLogger("uvicorn.access").setLevel(logging.WARNING)

The uvicorn access log is demoted on purpose, because the app emits its own request line with far more context attached. That line comes from backend/app_new/core/request_context.py, a raw ASGI middleware rather than a BaseHTTPMiddleware subclass:

        request_id = _request_id_from(scope.get("headers", []))
        structlog.contextvars.clear_contextvars()
        structlog.contextvars.bind_contextvars(request_id=request_id)

        status_code = 500  # if send never fires, treat as a server failure
        start = time.perf_counter()

        async def send_with_request_id(message):
            nonlocal status_code
            if message["type"] == "http.response.start":
                status_code = message["status"]
                headers = MutableHeaders(scope=message)
                headers.append("X-Request-ID", request_id)

Raw ASGI buys three things. The app runs on the same task, so contextvars bound here are visible to every logger downstream with no cross-task copy semantics to reason about. Streaming responses pass through untouched, which matters in a product where the main content path is SSE. And duration_ms measures to the end of the stream instead of time to first byte, so a slow generation shows up as slow.

Note the default status_code = 500. If send never fires, that request is recorded as a server failure rather than silently absent. The failure mode being guarded is the one where a crash removes its own evidence.

An inbound X-Request-ID is honored so IDs correlate across hops, after being stripped to [A-Za-z0-9_-] and truncated to 64 characters. A header is attacker controlled, and this one lands in log lines and a String(64) database column.

Then backend/app_new/api/deps.py, in the auth dependency, adds the other half:

    structlog.contextvars.bind_contextvars(
        user_id=str(user.id), org_id=str(user.organization_id)
    )

That is the entire endpoint participation cost of request correlation. Zero. Every log line for the rest of the request, including the middleware's own request.completed line and every line an agent writes, carries request, user, and org, and no route handler had to remember anything.

Route templates, not paths, or the label set eats the process

The same middleware feeds the Prometheus duration histogram, and it labels by route template rather than by request path. A raw path carries UUIDs, and a Prometheus label set with UUIDs in it is unbounded cardinality that grows until the process dies. /api/v1/content/{content_id} is one label value forever.

Health probes and /metrics are excluded from the log line entirely, in _UNLOGGED_PATHS. Orchestrators and uptime checks poll every few seconds, and the failure mode there is a signal drowned in its own monitoring.

Telemetry writes on its own session, and is allowed to fail

backend/app_new/crew/telemetry.py builds one AgentRun row per model call. The correlation comes free:

    row = AgentRun(
        organization_id=org_id,
        user_id=user_id,
        request_id=structlog.contextvars.get_contextvars().get("request_id"),
        agent_role=agent_role,
        model=model,
        api_kind=api_kind,
        status=status,
        error_class=error_class,
        stop_reason=stop_reason,
        input_tokens=usage.get("input_tokens", 0) or 0,
        output_tokens=usage.get("output_tokens", 0) or 0,
        cache_read_tokens=usage.get("cache_read_input_tokens", 0) or 0,
        cache_write_tokens=usage.get("cache_creation_input_tokens", 0) or 0,
        latency_ms=round(latency_ms, 1),
    )

The writer reads the request ID out of the same contextvars the middleware bound, which means telemetry also works when there is no request at all. A scheduler-driven agent call records a row with request_id set to None and everything else intact.

The write itself never touches the request's session:

    try:
        task = asyncio.create_task(_persist(row))
        _pending.add(task)
        task.add_done_callback(_pending.discard)
    except RuntimeError:
        logger.warning("agent_run.not_scheduled", agent_role=agent_role, model=model)

The RuntimeError branch is the no-running-loop case, a sync or offline context where scheduling is impossible. It logs and returns. The persist itself, a few lines down, opens its own session from the factory rather than accepting one:

async def _persist(row: AgentRun) -> None:
    try:
        factory = get_session_factory()
        async with factory() as session:
            session.add(row)
            await session.commit()
    except Exception:
        logger.exception("agent_run.persist_failed", agent_role=row.agent_role)

Two escape hatches, pointing the same direction. No running loop, log and move on. Database write fails, log the traceback and move on. The bare except Exception around a commit would be a smell almost anywhere else in this codebase, and here it is the entire point. A module-level _pending set holds the tasks so tests and shutdown can await outstanding writes through flush_pending, which is the only reason a fire-and-forget write is testable at all.

The failure mode being guarded is a telemetry outage that turns into a product outage. If the accounting write shared the request's session, a constraint violation or a connection blip in the measurement path would roll back the user's actual work. That is why AgentRun also declines foreign keys on organization_id and user_id. The comment in backend/app_new/models/telemetry.py is blunt about why:

    # Plain (unconstrained) IDs: telemetry must be writable even for rows that
    # outlive their user, and the writer never holds a session with the parent.
    organization_id: Mapped[uuid.UUID] = mapped_column(Uuid(as_uuid=True), nullable=False, index=True)
    user_id: Mapped[uuid.UUID | None] = mapped_column(Uuid(as_uuid=True))
    request_id: Mapped[str | None] = mapped_column(String(64), index=True)

    agent_role: Mapped[str] = mapped_column(String(50), nullable=False, index=True)
    model: Mapped[str] = mapped_column(String(100), nullable=False)
    # Which call path produced the row: stream | respond | forced_tool | tool_loop
    api_kind: Mapped[str] = mapped_column(String(20), nullable=False, default="respond")

    status: Mapped[str] = mapped_column(String(20), nullable=False, default="ok")  # ok | error

A deleted user should not be able to delete the record of what they spent, and a cascade written for the user table should not be able to reach into the accounting table by accident.

An unknown model records NULL, never zero

backend/app_new/crew/pricing.py is a hand-maintained table of four model prefixes:

# model prefix → (input $/MTok, output $/MTok). Longest prefix wins, so a
# dated snapshot like "claude-sonnet-4-6-20260201" matches its family.
PRICING_PER_MTOK: dict[str, tuple[float, float]] = {
    "claude-opus-4": (5.00, 25.00),
    "claude-sonnet-4": (3.00, 15.00),
    "claude-haiku-4": (1.00, 5.00),
    "claude-3-5-haiku": (0.80, 4.00),
}

CACHE_WRITE_MULTIPLIER = 1.25
CACHE_READ_MULTIPLIER = 0.10

Longest prefix wins, so the configured default in config.py, claude-sonnet-4-6, matches its family without a table edit every time a dated snapshot ships. The cache multipliers follow Anthropic's published rules, cache writes at 1.25x the input rate and cache reads at 0.1x, which is what makes the cache hit rate an economically meaningful number rather than a trivia stat.

The single most important line in the file is the one that does nothing:

    match = None
    for prefix in PRICING_PER_MTOK:
        if model.startswith(prefix) and (match is None or len(prefix) > len(match)):
            match = prefix
    if match is None:
        return None

An unpriced model returns None, which lands in a nullable cost_usd column and surfaces in the stats endpoint as its own field, unpriced_runs. The failure mode is a silent zero. A model this table has never heard of would otherwise contribute exactly nothing to the monthly total, and the total would still render, and nobody would ever look twice at it.

The same discipline runs through to the aggregates. In backend/app_new/api/v1/ops.py the cache hit rate is the share of prompt tokens served from cache, cache_read / (input + cache_read + cache_write), which is the ratio that maps onto money given the 0.1x read multiplier. In backend/app_new/core/observability.py, the Prometheus cost counter increments only when a cost exists, so an unpriced run still adds to the run and token counters and contributes nothing to spend. Every place the number could quietly become zero, it becomes absent instead.

Under-reporting is worse than not reporting

Phase B shipped /ops/agent-runs and /ops/agent-stats, gated behind the manage_team_billing permission and scoped to the caller's org. The stats endpoint returns total_cost_usd, cache_hit_rate, avg_latency_ms, plus by-agent and by-day breakdowns. It looked finished.

It was wrong. Five call sites in the API layer were calling client.messages.create directly, hand-rolling exactly what respond_with_forced_tool already does, same forced tool_choice, same system prompt build, minus the instrumentation: the writer tool call and the editor score in content.py, campaign plan generation and the strategist tool call in campaigns.py, and suggestion generation in dashboard.py.

That is most of the product's real AI spend. Drafting, regenerating, rewriting, scoring, planning. All of it left no row, and /ops/agent-stats presented the remainder as the org's numbers.

An observability surface that silently under-reports is worse than none: the number looks authoritative and is wrong.

Commit 3a8b7f8 routed all five through BaseCrewAgent. What makes it a design decision rather than a cleanup is what shipped alongside, in backend/tests/test_telemetry_coverage.py:

# Raw SDK invocation, e.g. `agent.client.messages.create(` or `client.messages.create(`
RAW_SDK_CALL = re.compile(r"\.messages\.create\s*\(")

# Only BaseCrewAgent may talk to the SDK directly; the mock provider implements
# that same surface, so it is exempt by construction.
ALLOWED = {
    APP / "crew" / "base_agent.py",
    APP / "crew" / "mock_provider.py",
}

    def test_api_layer_never_calls_the_sdk_directly(self):
        offenders = _offenders(APP / "api")
        assert not offenders, (
            "API routers must call BaseCrewAgent.respond_with_forced_tool (or "
            "respond/respond_stream) so the call is recorded in AgentRun "
            "telemetry. Direct SDK calls found at: " + ", ".join(offenders)
        )

The invariant "one capture point" is now enforceable instead of aspirational. A coding agent asked to add a feature that needs a model call will reach for the SDK, because that is what the SDK is for, and this test is the thing that says no. The same commit started counting schema misses as schema_mismatch rather than returning None quietly, and stopped generate-plan from interpolating a raw provider exception into a 502 body, where an authentication error string could have reached a browser. It landed with 244 tests passing at 61.35% coverage.

/metrics fails closed

The Prometheus endpoint in backend/app_new/main.py is open in dev and gated everywhere else:

        cfg = get_settings()
        if cfg.METRICS_TOKEN:
            auth = request.headers.get("authorization", "")
            supplied = auth[7:] if auth.startswith("Bearer ") else ""
            if not (supplied and _secrets.compare_digest(supplied, cfg.METRICS_TOKEN)):
                return Response(status_code=401)
        elif cfg.ENVIRONMENT.lower() not in ("development", "dev", "test", "local"):
            return Response(status_code=403)

With a token configured, a wrong token is a 401 through compare_digest. With no token configured, production returns 403 rather than serving. Aggregate token, cost, and latency data is operational intel about a business, and the default for intel is closed. This gap was found by post-deploy verification on 2026-08-28, not by design review, which is its own small lesson about where verification pays.

Tracing stays inert until someone asks for it

backend/app_new/core/observability.py sets up OpenTelemetry only when an exporter is actually requested:

    otlp_endpoint = os.environ.get("OTEL_EXPORTER_OTLP_ENDPOINT", "")
    console = os.environ.get("OTEL_CONSOLE_EXPORT", "") == "1"
    if not otlp_endpoint and not console:
        return False

With neither set, the OTel API no-ops, the SDK is never imported, and the default deployment carries no tracing overhead and no dead configuration. On a box that costs six to eight dollars a month, that is not a small consideration.

When it is on, agent spans follow the GenAI semantic conventions and are emitted retroactively from the same capture point, with start time reconstructed from the measured latency:

    end_ns = time.time_ns()
    start_ns = end_ns - int(latency_ms * 1_000_000)
    tracer = trace.get_tracer("app_new.crew")
    span = tracer.start_span(f"gen_ai.chat {model}", start_time=start_ns)

gen_ai.system, gen_ai.request.model, gen_ai.usage.input_tokens, gen_ai.usage.output_tokens. Standard names, so any conforming backend understands them without a custom dashboard.

What this layer does not do

Here is the counted deflation. The design claim is that every model API call produces a durable row. Two call sites do not. backend/app_new/services/website_scanner.py:124 and backend/app_new/services/learning.py:50 each call .messages.create on a client they build themselves one line above, because their function signatures take only text and have no org in scope to attribute a row to. Brand voice extraction from a website and edit classification for the learning loop both spend real tokens that /ops/agent-stats has never seen. The guard test pins them as a strict xfail, so the day someone fixes them the suite fails until the pin is removed, but until then two of the product's model call sites are invisible and the honest description of coverage is "the API and crew layers, not services."

Other limits worth naming. agent_runs has no retention policy at all, one row per model call, forever, on a shared Neon instance, while the rate limit table next door prunes itself. The Prometheus counters are process-global and reset on every deploy, so they answer "is something spiking right now" and cannot answer "what did we spend." And cost_usd is an estimate from a table maintained by hand against a published pricing page, which means it drifts silently the moment prices change.

The one-liner: an observability layer earns its numbers by being willing to have none, and keeps them by making the capture point single enough that a test can guard it.

Next in the series: the deploy layer, one t4g.small ARM spot instance behind Caddy, where shipping a release and losing the server run the same code.

The views expressed here are my own and are not related to or reflective of my work or any organization I am affiliated with.