fix(analytics): stop logging latency_ms=0 for streaming and cache-hit requests

[hasitpbhatt]

Orca-Code-Review — push 1

Severity	Count
P0	0
P1	0
P2	4
P3	4

✅ no blocking findings

Problem

Every streaming request (and every cache hit) was persisted with latency_ms = 0. Root cause: the adapter never attaches _orca_meta to streams, so the SSE aggregator's agg_latency stays at its initial 0; because the synthetic meta includes the key with value 0, meta.get("latency_ms", latency_ms) never fell back to the real wall-clock measurement. Result: /v1/analytics/latency percentiles silently dragged toward zero.

Full root-cause chain in #82.

Fix

• app/routes/chat.py:156: meta.get("latency_ms", latency_ms) → meta.get("latency_ms") or latency_ms. Using truthiness (not is None) is deliberate: both known-bad producers emit literal 0.
• Cache-hit path no longer hardcodes "latency_ms": 0 in its synthetic meta; it logs the measured serve time.

Non-stream responses carrying a genuine adapter-supplied _orca_meta.latency_ms keep full precedence (regression-guarded).

Tests

New tests/unit/test_request_log_latency.py (5): adapter value wins; literal zero falls back to measured; missing key / missing meta use measured; exact streaming-_finalize() synthetic shape regression case.

Verification

• Full suite: 343 passed
• ruff check app packages tests: clean

Stacked on #81.

Closes #82

[orcacode-review]

🐳 OrcaCode Review

Found 8 issues in this PR: 🟡 4 P2 · ⚪ 4 P3.

Not attached to a line. GitHub only accepts an inline comment on a line this PR changes. The findings below point somewhere else, so they are listed here instead of being dropped.

---

.env.example (line 20): ⚪ P3 Update the encryption section of the config template to match the new non-auto-generated key behavior

This change removed the "auto-generated on first run" behavior (app/config.py now documents: "credential_encryption_key is NOT auto-generated … packages.db.guards refuses to boot once real credentials are at stake") and added the ORCA_ALLOW_INSECURE_DEV_KEY opt-out. The deployment config template .env.example was not touched and still tells the operator "# ── Encryption (auto-generated on first run if empty) ──" and leaves CREDENTIAL_ENCRYPTION_KEY commented out. An operator who copies the template (the documented flow) and opts into Postgres via the commented DATABASE_URL on line 7 now crash-loops at boot (the new guard raises RuntimeError for any non-SQLite DB without a key), with the template giving no hint that a key must be generated; and on the default SQLite path the template actively reassures them a key is auto-generated while provider credentials stored later are sealed with the publicly-known dev fallback key. The new flag (ORCA_ALLOW_INSECURE_DEV_KEY) is also absent from the template. The template should say the key is required (openssl rand -hex 32) and mention the dev-key fallback and its opt-out.

---

app/routes/providers.py (line 200): 🟡 P2 Gate provider-key write/delete routes with require_unrestricted like the keys routes

The new require_unrestricted() gate (app/routes/keys.py) blocks restricted keys (model_allowlist or budget_limit_cents set) from managing keys, with the rationale that such a key must not be able to escape its restrictions. But the other side of the same privilege surface was not updated: PUT /v1/providers/{provider} and DELETE /v1/providers/{provider} (app/routes/providers.py:140, :198) still accept any authenticated key, including restricted ones. The keys.py docstring claims restricted keys are bounded by "the same trust level as PUT /v1/providers/*", implying that operation is the ceiling restricted keys must not reach — yet they can. Concretely: an operator who mints a budget/allowlist-limited key and hands it to a less-trusted party can, with that key, PUT /v1/providers/openai with an attacker-controlled upstream key; every subsequent request in the workspace (including the unrestricted root key's traffic) is routed to the attacker's upstream, exposing all prompts and allowing denial of service — i.e. the restricted key escapes its restrictions through a route the change did not gate. If the invariant "restricted keys cannot manage keys" is meant to hold, the same require_unrestricted() check should be applied to the provider-key write/delete routes (and the claim in the docstring updated accordingly).

---

app/routes/keys.py (line 73): ⚪ P3 Surface model_allowlist/budget_limit_cents in list_keys like create_key does

The new key-restriction feature (create_key accepts model_allowlist and budget_limit_cents and echoes them in its 201 response, lines 106-107) is invisible after creation: list_keys' item shape (id, name, key_prefix, is_active, last_used_at, revoked_at, created_at) omits both fields. The existing equivalent in the same file — the create_key response — includes them, so the list endpoint is the one place the new feature's own API disagrees with itself. Concretely: an operator who provisions a budgeted child key (POST /v1/keys with budget_limit_cents=500) can never again see that key's budget or allowlist through the API or the dashboard (design/app.js renders only the listed fields), and a revoked/lost key's restrictions are unauditable — the only record is the one-shot creation response that also carries the plaintext key. The keys list is the management surface for the feature this commit adds; it should return the same restriction fields the create endpoint returns.

_{Reviewed via OrcaRouter — Route Smarter. Ship Safer. Spend Less.}

[orcacode-review]

🟡 P2 Make budget enforcement atomic (check-then-serve race lets the lifetime cap be exceeded)

The new budget enforcement is a pure read-then-decide with no reservation, lock, or compare-and-swap: get_lifetime_spend_microcents SELECTs the sum of the key's billable RequestLog rows, and only if it is below the cap is the request routed. The cost is recorded afterwards (blocking path commits the log row in the finally after acompletion; streaming path commits only at stream end via a separate session). Two requests for the same key that arrive together each see spend < cap and are both admitted; each then records its cost, so the key's lifetime spend lands above budget_limit_cents (e.g. cap $1, two concurrent $0.60 requests both pass a $0.90 remaining check → $1.20 recorded). A single in-flight request that starts just under the cap also always overshoots by its own cost. The advertised guarantee — "an exhausted key costs the operator nothing — no upstream attempt" — holds only for requests arriving after the cap is already crossed; under concurrency the cap is not binding at all and the operator is charged past the configured limit. Enforcing it atomically requires reserving the expected cost in the same transaction as the admission check (or a per-key lock), not a plain SUM read.

[orcacode-review]

🟡 P2 Make the credential-encryption startup guard fail closed instead of treating count errors as "no credentials"

assert_credential_encryption_ready is the fail-closed gate that refuses to boot when the publicly-known dev key would protect real stored credentials. Its only source of "are there credentials at risk" is _count_provider_keys, and any exception from that query is swallowed as key_rows = 0 ("table missing" comment). But the guard runs in lifespan immediately after create_all on the same engine, so a missing table cannot occur on the real boot path — the except clause only ever catches genuine DB failures (SQLite "database is locked" during concurrent multi-worker startup, I/O errors). On the SQLite path those errors now produce key_rows == 0 → the guard returns and the app boots with the dev key sealing whatever provider rows exist, which is precisely the state the guard exists to refuse. The same fail-open pattern exists in is_using_insecure_dev_key() (except Exception: return False), which makes the guard no-op if key resolution raises. The guard should fail closed (raise, or re-raise the count error) on any exception other than a demonstrably-missing table, instead of converting a DB failure into "no credentials at risk".

[orcacode-review]

🟡 P2 Make unhandled_exception_handler async so the traceback is actually captured

The handler was changed from async def to a plain def and registered with app.add_exception_handler(Exception, ...). Starlette runs non-async exception handlers through run_in_threadpool (ServerErrorMiddleware._run_handler / ExceptionMiddleware._run_handler), i.e. in a worker thread. Inside that worker thread sys.exc_info() is (None, None, None) — the ASGI exception is not active there. structlog.get_logger().exception() sets exc_info=True and the configured ConsoleRenderer has no active exception to format, so the "unhandled_exception" event carries no traceback. The commit's whole purpose (docstring: "The traceback MUST be recorded here — this is the only place an arbitrary exception surfaces, and without it every production 500 is undebuggable") is therefore not achieved: the structured log line only has path and error string. The test passes only because structlog.testing.capture_logs captures the raw event dict where exc_info=True is still present, not the rendered output. Fix: declare the handler async def unhandled_exception_handler(request, exc) — Starlette then awaits it in the same task inside the except block, where sys.exc_info() still holds the exception and the traceback is rendered.

[orcacode-review]

⚪ P3 test_truncated_blob expects InvalidTag but decrypt_credential raises ValueError for blob[:8]

The new test expects decrypt_credential(blob[:8]) (a v1 blob truncated below the 12-byte nonce) to raise InvalidTag. With the committed decrypt_credential, blob[:1] == b"\x01" but len(blob) = 8 < 29, so the v1 branch is skipped and the legacy parse passes an 8-byte nonce and empty ciphertext to AESGCM.decrypt, whose _check_params raises ValueError ("Data must be at least one byte" / "Nonce must be 12 bytes") — not InvalidTag. pytest.raises(InvalidTag) therefore errors out; the test cannot pass as written (e.g. blob[:20] would raise InvalidTag, but [:8] does not). Either the test should expect (InvalidTag, ValueError) or truncate to blob[:20]. This does not affect runtime callers (router_cache catches Exception), but it makes the committed test suite fail on this test.

[orcacode-review]

⚪ P3 Honor ORCA_ALLOW_INSECURE_DEV_KEY set in .env, not only in process env

The guard reads the opt-out only via os.environ.get("ORCA_ALLOW_INSECURE_DEV_KEY") (guards.py:22) or settings.allow_insecure_dev_key (config.py:64). Settings has no env_prefix="ORCA_", so pydantic-settings matches env vars to the field name allow_insecure_dev_key exactly (case-insensitive) — ORCA_ALLOW_INSECURE_DEV_KEY is never mapped to that field, and os.environ does not contain .env values. So an operator who sets ORCA_ALLOW_INSECURE_DEV_KEY=1 in .env — the app's documented config channel used for CREDENTIAL_ENCRYPTION_KEY and every other setting — still gets a refused boot (RuntimeError), while the same value exported to the process environment works. The flag documented in config.py, encryption.py, and the guard's error message is therefore half-wired: it only works as a process env var. Fix: configure env_prefix="ORCA_" (matching the ORCA_* naming used elsewhere, e.g. ORCA_API_KEY_PEPPER-style fields), or have the guard read the .env file, or document that this flag must be exported in the process environment.