Skip to content

fix(serving): stop a usage-accounting write from 500-ing a served request - #172

Merged
brownjuly2003-code merged 1 commit into
mainfrom
fix/usage-write-500
Jul 9, 2026
Merged

fix(serving): stop a usage-accounting write from 500-ing a served request#172
brownjuly2003-code merged 1 commit into
mainfrom
fix/usage-write-500

Conversation

@brownjuly2003-code

Copy link
Copy Markdown
Owner

The bug

Load Test on main went red after af20c9d and again after 617bbb7. It was not runner noise and not a latency threshold: 19 of 1712 requests returned 500, spread across all six endpoints, each with the same traceback:

auth/middleware.py:113  await run_in_threadpool(manager.record_usage, ...)
  auth/usage_table.py:39  manager.store.record_api_usage(...)
    control_plane/embedded.py:1391  conn = connect_duckdb(self._usage_db_path)
      duckdb_connection.py:25  return duckdb.connect(path)
_duckdb.BinderException: Unique file handle conflict: Cannot attach
"agentflow-api-usage" - the database file is already attached by database
"agentflow-api-usage"

Every authenticated request writes an api_usage row from a worker thread, and analytics.py / admin_ui.py build a throwaway store per request — each opening its own duckdb.connect() on the same file. The last close destroys the DuckDB instance, so a close racing an open leaves the file momentarily attached by two instances, and DuckDB refuses. Nothing caught it, so a request that had authenticated and would have served a 200 came back a 500.

Not caused by the recent merges: duckdb is 1.5.4 in both the red and green runs, and the sibling failure at af20c9d (docs+compose only) has the identical signature with 38 occurrences. The green run in between has zero. It is chronic and load-dependent.

The fix

Root. EmbeddedControlPlaneStore keeps one owning connection per usage-db path for the life of the process and hands out .cursor() children — the shape DuckDBPool already uses for the serving database. There is no longer a destroy/recreate window to race. Call sites are untouched: _usage_cursor() is a drop-in for connect_duckdb(...), and the conn.close() in each finally now closes a cursor, leaving the connection alive.

Measured on the store's own code path:

physical duckdb.connect calls
80 concurrent usage writes, before 80
80 concurrent usage writes, after 1

Defence in depth. record_api_usage still raises on exhausted retries — record_usage depends on the exception to skip its audit publish, and store.py documents that. But the exception stops at AuthMiddleware, which counts the new agentflow_usage_record_failures_total, logs api_usage_record_skipped, and serves the request. Accounting is a side-channel; a dropped row must not fail the request it was counting. The port docstring now says so.

Verification

  • tests/unit/test_auth_usage_write_failure.pyfails on the pre-fix tree with the exact BinderException, passes here.
  • tests/unit/test_usage_db_connection_reuse.py — 8 threads × 8 stores × 10 writes open the database exactly once; cursor close leaves the connection usable; a poisoned connection is evicted and reopened.
  • 1670 unit + 263 integration pass locally (Windows, no Docker). The pre-existing test_version env failure and the 4 Docker-gated integration errors are unrelated — both also occur on unmodified main.
  • Four existing tests pinned the old per-call-connect mechanism (connect_duckdb called once per retry). They now drop the cached connection before injecting their fault and assert on retry attempts rather than connect counts — the behaviour they guard is unchanged.
  • Load Test runs on this PR (it touches src/**) — that lane is the real-world confirmation.

What is not claimed

The race's timing does not reproduce on this workstation, on duckdb 1.5.1 or 1.5.4, with or without a synchronising barrier. So the regression tests pin the mechanism that removes the race (one connection, never destroyed) rather than the timing. The CI Load Test is the end-to-end check.

🤖 Generated with Claude Code

…uest

Every authenticated request appends an api_usage row from a worker thread,
and the analytics/admin routers build a throwaway store per request. Each
of those opened its own duckdb.connect() on the usage file. The last close
destroys the DuckDB instance, so a close racing an open leaves the file
attached by two instances and DuckDB raises

    BinderException: Unique file handle conflict

That escaped AuthMiddleware and turned requests that had already succeeded
into 500s: the 2026-07-09 Load Test on main saw 19 of 1712 fail across all
six endpoints, every traceback ending in record_api_usage -> connect_duckdb.

Root cause: EmbeddedControlPlaneStore now holds one owning connection per
usage-db path for the life of the process and hands out .cursor() children,
the shape DuckDBPool already uses for the serving database. Call sites are
untouched — they still close() what they are given, and closing a cursor
leaves the connection alive. 80 concurrent usage writes: 80 connects -> 1.

Defence in depth: record_api_usage still raises on exhausted retries (its
caller depends on that to skip the audit publish), but the middleware now
catches it, counts agentflow_usage_record_failures_total, logs
api_usage_record_skipped, and serves the request. Accounting is a
side-channel and must not fail the request it was counting.

Four tests pinned the old per-call-connect mechanism rather than the
behaviour; they now drop the cached connection before injecting their
fault and assert on retry attempts instead of connect counts.

Verified: 1670 unit + 263 integration pass locally; the middleware
regression test fails on the pre-fix tree with the exact BinderException.
The race's timing reproduces only on the CI runner, so the new tests pin
the mechanism that removes it rather than the timing.

Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
@github-actions

github-actions Bot commented Jul 9, 2026

Copy link
Copy Markdown

DORA Metrics

  • Window: last 30 days
  • Branch: main
  • Deployment frequency: 94 total / 21.93 per week
  • Lead time for changes: avg 0.43h / median 0.0h
  • Change failure rate: 57.45% (54/94)
  • MTTR: n/a across 0 incident(s)

MTTR note: No failed mainline CI runs in the selected window.

@brownjuly2003-code
brownjuly2003-code merged commit 7db39f1 into main Jul 9, 2026
23 checks passed
@brownjuly2003-code
brownjuly2003-code deleted the fix/usage-write-500 branch July 9, 2026 03:38
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.

2 participants