Skip to content

feat(proxy-logs): record per-attempt upstream timing on proxy log rows - #14892

Merged
diegosouzapw merged 5 commits into
diegosouzapw:release/v3.8.51from
maxmad64bis:fix/attempt-timing-columns
Sep 28, 2026
Merged

diegosouzapw merged 5 commits into
diegosouzapw:release/v3.8.51from
maxmad64bis:fix/attempt-timing-columns

Conversation

@maxmad64bis

@maxmad64bis maxmad64bis commented Sep 26, 2026 •

Copy link
Copy Markdown
Contributor

⚠️ base-red inherited: #14963

Summary

Long requests could not separate upstream queue wait from generation time: no stored row said when the response headers or the first useful chunk arrived. Each attempt row now records both durations from send start (headers_ms, first_chunk_ms, nullable, migration 194), measured on the raw upstream body before any translation, and the proxy log detail shows them as "Headers after" and "First chunk after" (a dash when unknown, never 0). The queue/generation split is readable from the row and on screen without replaying logs.

Related Issues

  • No linked issue — proactive observability improvement with no prior report.

Validation

  • Change type: DB
  • Focused tests and category gates from the golden path — 8/8 touched suites green; all nine new timing cases fail without the change
  • npm run lint — ESLint on the touched files is clean
  • Reconciled with the current active release base; focused checks rerun afterward
  • Production-code changes include a new or updated automated test in this PR

Tests Added Or Updated

  • tests/unit/proxy-logs-attempt-timing.test.ts (new, 9 cases): column defaults and deferred update, sanitization, bounded pending registry (settle and flood), lazy body envelope (no stamp before the downstream read, status/headers kept, null settle on empty, failed or missing bodies).
  • tests/unit/proxy-logger-observed-fields.test.tsx (1 new case): the detail view shows both durations, and a dash when they are unknown.

Coverage Notes

  • open-sse/utils/upstreamStatusCapture.ts (capture wrapper): proxy-logs-attempt-timing.test.ts (lazy body envelope, settle on empty or failed bodies).
  • src/lib/db/ (migration 194, columns, deferred update), src/lib/proxyLogger.ts and src/sse/handlers/proxyJournal.ts: the same file (column defaults, deferred update, sanitization, bounded pending registry).
  • src/shared/components/ProxyLogDetail.tsx: proxy-logger-observed-fields.test.tsx.

Reviewer Notes

  • The docs gate reports the migration count moving from 190 to 191 in README.md, AGENTS.md and llm.txt. Those counts are left untouched on purpose: per the maintainer's note on fix(proxies): steer selector to members without recent refusals #14804 they only move on the release train.
  • One timing sanitizer is shared by the capture wrapper, the journal and the deferred patch; the stale no-unused-vars suppression for ProxyLogDetail.tsx (already unused at the base) is pruned so ESLint stays clean on that file.
  • Inherited from the base (🔴 Release branch not green: release/v3.8.51 #14963): mutation-test-coverage --strict fails the same way on the release base; no file of this PR is involved.

Maintainer rework (merge-batch 2026-09-28)

  • The first-byte body envelope and the deferred first_chunk_ms row patch are now opt-in via PROXY_LOG_FIRST_CHUNK_TIMING (default off, documented in .env.example and docs/reference/ENVIRONMENT.md). With it off the upstream Response passes through untouched (same object) and only headers_ms is recorded; the journal registers no pending link.
  • The enveloped Response now keeps url, redirected and type from the upstream response (same approach as tlsClient.ts).
  • Removed the duplicated sanitizeAttemptTiming; the journal reuses sanitizeTimingMs.
  • Removed ensureProxyLogsColumns from the per-flush path (it already runs at init).
  • New tests: identity preserved through the envelope; flag off (unset/false/0) returns the same Response unwrapped; flag off registers no deferred patch in the journal (control with flag on). They fail on the previous head (3/12) and pass now (12/12).
  • Migration 194 is still the next free number on the tip.

@maxmad64bis
maxmad64bis force-pushed the fix/attempt-timing-columns branch 4 times, most recently from 168ed9e to d243e67 Compare September 26, 2026 16:10
@maxmad64bis
maxmad64bis marked this pull request as ready for review September 26, 2026 16:36
@maxmad64bis
maxmad64bis force-pushed the fix/attempt-timing-columns branch 2 times, most recently from 78f393a to d756127 Compare September 28, 2026 13:52
@maxmad64bis
maxmad64bis force-pushed the fix/attempt-timing-columns branch from d756127 to e89b35b Compare September 28, 2026 16:41
…nd keep response identity

- The first-chunk body envelope and its deferred row patch now run only with
  PROXY_LOG_FIRST_CHUNK_TIMING=true; off by default the upstream Response
  passes through untouched and only headers_ms is recorded.
- The enveloped Response keeps url/redirected/type, as tlsClient.ts does.
- Reuse sanitizeTimingMs instead of a duplicated journal helper.
- Drop ensureProxyLogsColumns from the per-flush path (it already runs at init).
@diegosouzapw diegosouzapw changed the title fix(db): record per-attempt upstream timing on proxy log rows feat(proxy-logs): record per-attempt upstream timing on proxy log rows Sep 28, 2026
@diegosouzapw
diegosouzapw merged commit 8d7e2e4 into diegosouzapw:release/v3.8.51 Sep 28, 2026
10 of 16 checks passed
diegosouzapw added a commit that referenced this pull request Sep 29, 2026
…ync init cycle

#14892 made src/lib/db/proxyLogs.ts import sanitizeTimingMs from
upstreamStatusCapture.ts, which reaches usage/migrations (top-level await)
through providerRequestLogging. Every DB module importing proxyLogs became
async and the esbuild MCP bundle deadlocked on import again. The helper
moves to a zero-import leaf; upstreamStatusCapture re-exports it.
diegosouzapw added a commit that referenced this pull request Sep 29, 2026
…leak, MCP bundle deadlocks, sidebar keys, flush-empty-retry, proxy-status and pack-policy tests (#14820)

Fixes the reds still present on the tip: client-abort listener leak (#14342 vs #12406), MCP bundle deadlock (quotaCache init cycle via the quotaCacheState leaf, plus the new #14892 proxyLogs -> upstreamStatusCapture -> usage/migrations cycle via the zero-import timingMs leaf), sidebar Model catalog keys, and the stale flush-empty-retry / proxy-status / pack-policy tests. Combo pre-content retry and zh-TW glossary were already fixed on the tip and dropped. Merged tree: 102/102 focused incl. mcp-bundle-startup (red on the tip), typecheck:core clean, open-sse typecheck 0, check:cycles OK, file-size OK.
@maxmad64bis
maxmad64bis deleted the fix/attempt-timing-columns branch September 30, 2026 00:21
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