Skip to content

fix(passthrough): stop reconcile worker from re-selecting permanently-failed transactions forever - #813

Open
sjawhar wants to merge 5 commits into
LuthienResearch:mainfrom
trajectory-labs-pbc:fix/passthrough-reconcile-convergence
Open

sjawhar wants to merge 5 commits into
LuthienResearch:mainfrom
trajectory-labs-pbc:fix/passthrough-reconcile-convergence

Conversation

@sjawhar

@sjawhar sjawhar commented Aug 23, 2026 •

Copy link
Copy Markdown
Collaborator

Problem

PassthroughReconcileWorker (gated by PASSTHROUGH_MATERIALIZE_BACKFILL_ENABLED, running in the luthien-admin ECS service) runs reconcile_passthrough every 300s forever. Each sweep:

  1. Runs _ELIGIBLE_UNMATERIALIZED_TRANSACTIONS_SQL to find the oldest 200 unmaterialized passthrough transactions. request_logs had no index supporting the query's filter, so this ran a Parallel Seq Scan discarding essentially the whole table every cycle.
  2. Attempts to materialize all 200. When a transaction is permanently unparseable (missing_required_field, unsupported_variant, etc.), it fails.
  3. reconcile.py did failed += 1; continue and never persisted the failure anywhere the eligibility query's NOT EXISTS(conversation_events) check could see.

This PR stacks on #796 (feat/passthrough-multiprovider-capture) because that's the branch that introduces passthrough_materialize/ -- none of this code exists on main yet. GitHub cannot target a PR's base at a branch that only exists in a fork (not upstream), so this PR's base is main and its diff necessarily includes #796's full changeset until #796 merges. The commits unique to this fix are the single top commit, fix(passthrough): stop reconcile worker from re-selecting permanently-failed transactions forever -- everything else is #796's. This PR should not merge before #796 does; once #796 merges, this branch will be rebased onto main and its diff will shrink to just that one commit.

Fix

1. Dead-letter permanent failures (reconcile.py)

Every MaterializationFailed reason except missing_request_logs is raised only after read_raw_transaction/parse_captured_transaction successfully fetched request_logs bytes and then found them unparseable/invalid for the matched endpoint (the PassthroughNormalizeReason enum values, missing_endpoint, and the _InvalidRequestLog family of invalid_<column>/missing_<column> reasons). request_logs rows are never updated after insert, so retrying one of those without a code change reproduces the identical outcome forever -- they're permanent.

missing_request_logs (zero rows found for the transaction_id) is the one reason that reflects an absence rather than malformed content already read. Treating it as permanent risks permanently blacklisting a transaction whose row simply hadn't landed yet, so it's the only reason left retryable. Raw DB exceptions (timeouts, connection errors) were already handled separately in reconcile_passthrough's try/except before ever becoming a MaterializationFailed -- untouched by this change, and correctly never dead-lettered.

Permanent failures are now recorded in a new passthrough_materialization_dead_letters table (transaction_id PK, reason, failed_at) and excluded via NOT EXISTS in the eligibility query.

2. Index (migrations/023_add_passthrough_materialization_dead_letters.sql)

A partial index whose WHERE clause mirrors the eligibility query's predicate verbatim (direction = 'inbound' AND the four passthrough endpoint patterns), so Postgres can use it as a covering index-only scan restricted to just the rows that could ever be eligible, rather than indexing everything that's merely direction = 'inbound'.

EXPLAIN evidence (measured locally against a seeded Postgres 16 instance: 2.4M request_logs rows -- 1.2M outbound, 1.2M inbound non-passthrough, 3,000 already-materialized passthrough, 5,265 permanently-broken passthrough matching the production backlog's date range and size):

Before After
Plan Parallel Seq Scan on request_logs Index Only Scan using idx_request_logs_passthrough_eligible
Rows removed by filter (per worker) 800,000 0 (fully covered by the partial predicate)
Planner cost 70408.58 309.86 (~227x)
Execution time 194ms (cold) 7ms
Buffers 1204 hit + 45295 read 102 hit, 0 read

A second sweep, after dead-lettering the 5,265-row backlog, returns 0 rows in 6ms via the same index -- confirming convergence.

CREATE INDEX CONCURRENTLY is used given the table's size (multi-GB, multi-million-row, live production traffic); verified psql -f commits the CREATE TABLE and CREATE INDEX CONCURRENTLY in this one file as two independent statements (not wrapped in an implicit transaction), and confirmed indisvalid = true after the build.

3. One-shot semantics (worker.py)

PASSTHROUGH_MATERIALIZE_BACKFILL_ENABLED's own config docstring says "Enable one-shot passthrough materialization backfill for historical request_logs" -- but the worker looped on a fixed interval forever regardless of backlog state, which is what turned "permanently broken rows never converging" into "runs forever burning ACU." PassthroughReconcileWorker now stops itself once a sweep selects zero eligible rows at all (distinct from "nothing succeeded" -- a sweep that only hit failures must keep running to dead-letter/retry them). This makes the worker's actual behavior match its documented one-shot contract, and means a drained backlog stops all further DB load until the next app restart (one more sweep, immediately terminates).

Tests

13 new/updated tests in tests/luthien_proxy/unit_tests/passthrough_materialize/{test_reconcile,test_worker}.py:

  • test_reconcile_materializes_only_eligible_unmaterialized_transactions_and_converges_next_sweep -- updated from the pre-fix version, which asserted the bug (second_pass == ReconcileStats(failed=1), i.e. the same broken row re-selected forever); now asserts second_pass == ReconcileStats() and that the dead-letter row was written with reason="missing_required_field".
  • test_reconcile_converges_when_the_entire_backlog_is_permanently_broken -- reproduces the production bug shape directly (an all-broken backlog) and shows sweep 2 selects nothing.
  • test_reconcile_leaves_a_transient_failure_reason_eligible_for_retry -- missing_request_logs is re-selected and re-attempted on both sweeps, never dead-lettered.
  • test_migration_creates_the_dead_letter_table_and_supporting_index -- SQLite side of migration 023 applies cleanly (exercised via check_migrations in every fixture in this file already; this asserts the resulting schema directly). Postgres side verified manually (see EXPLAIN evidence above; a live Postgres instance isn't available in the default dev_checks.sh/CI gate -- tests/luthien_proxy/integration_tests/test_migration_sync.py is @pytest.mark.integration and pre-existing, not selected by default, per fix(migrations): stop swallowing failed migrations in run-migrations.sh #812's notes).
  • test_reconcile_worker_stops_once_a_sweep_selects_nothing / test_reconcile_worker_keeps_sweeping_while_failures_remain -- the new one-shot termination behavior, and that it doesn't fire prematurely while there's still failed work to process.

Full suite: 3177 tests, 3174 passed, 3 failed. The 3 failures (test_onboard.py::test_find_docker_ports_respects_env_vars, test_config_registry.py::TestResolveDefaults::test_default_value_when_no_overrides, test_config_registry.py::TestResolvePriority::test_db_ignored_for_non_db_settable) are pre-existing and unrelated -- reproduced byte-for-byte on a clean checkout of this PR's own base branch (feat/passthrough-multiprovider-capture tip, before any of this PR's changes) in this sandbox, and pass individually in isolation (environment-dependent test-isolation flakiness in POSTGRES_PORT/REDIS_PORT env var resolution, unrelated to passthrough_materialize). ruff format, ruff check, and pyright are all clean (0 errors/warnings).

Non-goals

  • Not touching scripts/backfill_passthrough_materialization.py / drain_passthrough_backfill (the manual one-shot CLI script) -- it already terminates correctly (sweep.materialized == 0); it benefits from the index and dead-letter table for free.
  • Not adding an operator UI/endpoint to clear dead-lettered rows for re-materialization after a future parser fix ships -- out of scope for this concern; the table is a plain transaction_id-keyed row, trivial to clear later.

CI: expect claude-review to fail (ANTHROPIC_API_KEY not exposed to fork-triggered runs, per repo convention) -- everything else should be green.

sjawhar added 5 commits July 5, 2026 01:57
…ABLED and bound stream capture

Addresses LuthienResearch#796 review: the passthrough routes forwarded client-supplied
upstream credentials with no auth, so an always-on deployment acted as an
open relay that anyone with network reach could use to write request_logs.
The routes now mount only when PASSTHROUGH_ROUTES_ENABLED=true (else 404),
and streamed-response capture is bounded by PASSTHROUGH_STREAM_CAPTURE_MAX_BYTES
(default 10 MiB) so a large stream can't exhaust memory.
…ation history + retrieval

Normalize captured OpenAI (chat + Responses) and Gemini (generateContent +
streamGenerateContent) passthrough payloads into canonical Anthropic-shaped
conversation events while preserving exact provider-native request/response
for faithful reprobe. Idempotent (advisory lock + existence guard, single txn,
two summary updates); live post-commit RequestLogRecorder callback gated by
PASSTHROUGH_MATERIALIZE_ENABLED plus a dashboard-only reconcile worker + one-shot
backfill CLI gated by PASSTHROUGH_MATERIALIZE_BACKFILL_ENABLED. Passthrough user
attribution mirrors the Anthropic trusted-header/JWT policy. Existing history/
debug/summary/FTS/export read paths light up with zero new migrations.

fix(passthrough): SDK-typed normalizers + Gemini contents[].role defaulting + OpenAI reasoning tokens + content_filter mapping

Four fixes to the passthrough materialization pipeline, all discovered while
backfilling ~2600 historical prod rows against the initial hand-rolled
normalizers.

1. Provider-SDK-based normalizers (openai + google-genai typed models):
   Replaces hand-rolled OpenAI/Gemini payload parsing with SDK validation via
   openai.types + google.genai.types. Lenient by design - skip unknown output/
   input items, parts, tools; never fatal on a novel variant. Wraps OpenAI
   response parsers in try/except ValidationError -> typed MALFORMED_PAYLOAD so
   novel SDK-rejected values skip one transaction instead of wedging the
   backfill batch. Fixes reasoning-model support (gpt-5.6-sol) and Gemini
   serviceTier extra_forbidden.

2. Default missing Gemini contents[].role to 'user' per API spec:
   _content_message previously dropped role-less contents, then _request_messages
   reported the misleading MISSING_REQUIRED_FIELD:contents error. Fixed with
   'role = optional_string(content, "role") or "user"'.
   Ref: https://ai.google.dev/api/generate-content#Content

3. Gemini stream ValidationError fallback (from oracle+fable code review):
   gemini_stream.py._add_chunk on SDK ValidationError keeps the raw chunk so
   downstream lenient mapping proceeds. Mirrors gemini_response.py's buffered
   raw fallback. Prevents streamed captures failing MALFORMED_PAYLOAD on the
   same usageMetadata.serviceTier field that buffered handles.

4. Delete validate_*_request no-op helpers + dead code (oracle+fable):
   validate_openai_chat_request / validate_openai_responses_request /
   validate_gemini_request all caught ValidationError and returned None -
   behavioral no-ops with ~90 lines of pydantic parse overhead and zero
   effect. Also deleted openai_common.object_field + strict
   text_content_from_openai (zero callers repo-wide).

5. OpenAI reasoning_tokens in canonical usage:
   canonical_usage now lifts reasoning_tokens from
   completion_tokens_details.reasoning_tokens (Chat) or
   output_tokens_details.reasoning_tokens (Responses) into the canonical
   usage dict, matching what gemini_common already does for
   thoughtsTokenCount. Non-reasoning models omit the field entirely at the
   API level; the SDK parser injects 0 as a default, so we treat 0 as
   absent to avoid polluting non-reasoning outputs with a spurious 0.

6. OpenAI content_filter -> canonical safety (not end_turn):
   stop_reason() previously collapsed content_filter into end_turn, making
   safety-policy blocks indistinguishable from natural stops. Now maps to
   'safety' (matching the Gemini normalizer's SAFETY bucket) so downstream
   consumers can filter blocked completions.

Verification:
  84/84 passthrough_materialize unit tests pass (was 78/78 before + review
  regressions + reasoning_tokens + content_filter tests).
  ruff format + check clean. basedpyright clean.
  Real prod-data validation: chat 59/60, Responses 60/60, gpt-5.6-sol
  reasoning 60/60, Gemini 60/60.
  Prod backfill drain: 2618/2623 eligible materialized (99.8%).
…-failed transactions forever

PassthroughReconcileWorker re-ran the same unindexed eligibility query every
300s and re-selected the same permanently-broken transactions forever, since
MaterializationFailed outcomes were never persisted anywhere the eligibility
query's NOT EXISTS(conversation_events) check could see. Two independent
problems, one PR because they're both needed for the worker to converge:

- Add passthrough_materialization_dead_letters, keyed by transaction_id, and
  exclude it from the eligibility query. Every MaterializationFailed reason
  except missing_request_logs reflects a deterministic parse/validation
  failure on already-persisted, immutable request_logs bytes -- retrying
  without a code change reproduces the identical outcome forever, so those
  are dead-lettered. missing_request_logs (zero rows found) is the one
  failure that could reflect an absence rather than malformed content, so it
  stays retryable. Raw DB exceptions (timeouts, connection errors) were
  already handled outside MaterializationFailed and remain untouched.
- Add a partial index (migrations/023) whose predicate mirrors the
  eligibility query's WHERE clause verbatim, turning its Parallel Seq Scan
  into a covering index-only scan. Measured locally against a seeded
  2.4M-row table: cost 70408->310 (~227x), 194ms->7ms.
- PASSTHROUGH_MATERIALIZE_BACKFILL_ENABLED's own docstring says 'one-shot',
  but the worker looped forever on a fixed interval regardless of backlog
  state. It now stops itself once a sweep selects zero eligible rows.
@legion-implementer
legion-implementer Bot force-pushed the fix/passthrough-reconcile-convergence branch from 279d492 to 1024404 Compare August 23, 2026 23:38
legion-implementer Bot pushed a commit to trajectory-labs-pbc/luthien-proxy that referenced this pull request Sep 8, 2026
…ompleted_at T-form mismatch

Round-2 reviewer findings on LuthienResearch#806:

(1) Migration number collision: 022 is already claimed by sibling PR LuthienResearch#811
(migrations/{postgres,sqlite}/022_add_request_logs_created_at_index.sql) and
023 by LuthienResearch#813. Renumbered this migration's three copies (postgres, sqlite,
bundled) to 024, the next free prefix.

(2) request_logs.started_at/completed_at are written via to_timestamp(?) (a
float unix-epoch bind, translated by _translate_params to SQLite's native
datetime(?, 'unixepoch')), never a raw datetime bind -- so the previous
commit's _convert_arg fix never touched them, and SQLite's own
datetime(unixepoch) always emits a space separator, permanently (a
migration alone cannot fix this for future rows). request_log/service.py's
after/before filters bind a raw datetime (datetime.fromisoformat), which
after the previous commit becomes T-form via the now-fixed _convert_arg.
Without this fix, a same-day after/before filter would silently return
wrong results forever -- not just for legacy rows, for every row written
after the previous commit landed. Fixed by wrapping the to_timestamp(?)
translation in replace(..., ' ', 'T'). Migration 024 also now backfills
existing request_logs.started_at/completed_at (added the two UPDATE
statements; same LIKE-gated, idempotent shape as the other four columns).

red (test_to_timestamp_write_comparable_with_datetime_bind_filter against
the to_timestamp(?) → datetime(?, 'unixepoch') translation, no replace()):
  AssertionError: assert '2026-08-10 12:00:00' == '2026-08-10T12:00:00'
also red: test_to_timestamp (asserted bare 'datetime(?, ...)' output before)

green (same tests, replace(..., ' ', 'T') wrap restored):
  uv run pytest tests/luthien_proxy/unit_tests/utils/test_db_sqlite.py -k 'test_to_timestamp or test_to_timestamp_write_comparable' -q --no-cov
  -> 2 passed

green (full file + repo-wide gate on the changed files):
  uv run pytest tests/luthien_proxy/unit_tests/utils/test_db_sqlite.py -> 46 passed
  uv run pytest tests/luthien_proxy/unit_tests/utils/test_migration_naming.py tests/luthien_proxy/unit_tests/utils/test_sqlite_migrations_are_native.py -> all pass
  uv run pytest tests/luthien_proxy/unit_tests -> exit 0
  ruff format --check / ruff check / pyright on changed files -> clean

Omp-Session: 01a081d4-2514-7000-b8e2-ff8548776146

This branch has not been deployed

No deployments
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Labels

None yet

Projects

None yet

Development

Successfully merging this pull request may close these issues.

1 participant