feat(sse): record per-request added wait with cause in call logs

changelog.d/fixes/14756-request-added-wait.md

@@ -0,0 +1 @@
+- **feat(sse):** record per-request added wait with cause in call logs ([#14756](https://github.com/diegosouzapw/OmniRoute/pull/14756)) — thanks @maxmad64bis

config/quality/file-size-baseline.json

@@ -1,4 +1,5 @@
 {
+  "_rebaseline_2026_09_25_14756_request_added_wait": "PR #14756 own growth (per-request added wait before dispatch, migration 192), re-measured with split(\"\\n\").length after merging release/v3.8.51 @96f6aee2 (post #14750/#14795/#14810/#14659; replaces the PR's earlier entry, which had rewound unrelated tip ceilings): open-sse/executors/opencode.ts 1419->1452 (+33 = request-scoped accumulator + park-sleep counting wrapper + wall-clock around the paced acquire + publish to the capture sink, at the existing dispatch chokepoint); open-sse/utils/proxyFetch.ts 1341->1383 (tip file 1338; +45 = two AppliedProxySink fields + noteAddedWait/readAddedWait on the existing applied-proxy ALS sink, which is private to this module); src/lib/db/core.ts 1800->1802 (+2 = added_wait_ms/added_wait_cause in the call_logs base schema); src/shared/components/RequestLoggerDetail.tsx 1216->1226 (+10 = the Added wait cell next to the existing duration cells). Additive and null-safe. Covered by tests/unit/opencode-added-wait.test.ts.",
   "_rebaseline_2026_09_25_14810_resilience_actions_wiring": "PR #14810 own growth (resilience-actions observability wiring, irreducible call-site lines after extraction of the note logic into chatCore/*_notes modules + opencodeResilienceNotes + requestLoggerResilience, all under cap): open-sse/handlers/chatCore.ts 6426->6441 (+15 = wrapper handleChatCore/handleChatCoreInner + resumed-flag param/note/strip + 3 one-line note calls, logic in chatCore/resilienceAttemptContext + resumedResilienceNotes + emptyTurnResilienceNotes + continuationResilienceNotes + recoveryTraceLogging); open-sse/executors/opencode.ts 1338->1354, re-measured 1354->1370 after merging release/v3.8.51 @86870a82 (the tip itself had grown to 1354 via the applied-egress tracker) (+16 = served-account tracker + park/replay/stored notes wiring, logic in opencodeResilienceNotes); src/sse/handlers/chat.ts 2567->2582 (+15 on the reconciled tip = resumed-flag threading via body marker + dispatch param + 2 combo forwards); src/shared/components/RequestLoggerDetail.tsx 1210->1216, re-measured on release/v3.8.51 @4b9388a1 (tip file 1205 after #14795; +11 = one import + badge computation + badge render loop, badge logic in requestLoggerResilience); src/lib/usage/callLogs.ts stays under the 1200 cap (resilience-actions parser moved to src/lib/usage/resilienceActionsParse.ts). Measured with split(\"\\n\").length. Covered by tests/unit/resilience-actions-context (11) + sink (5) + notes (9) + badges (5) + db/migration-191 (2).",
   "_rebaseline_2026_09_24_14802_transport_setaside": "PR #14802 own growth: open-sse/utils/proxyFetch.ts 1334->1341 (+7 = two-symbol import + proxied-success hook at the single dispatch return + tagged-failure guard at the single final throw; full evidence helpers live in open-sse/utils/proxyRefusalMemory.ts (not frozen), irreducible call-site wiring at the two existing chokepoints). Covered by tests/unit/proxy-transport-setaside-cross-evidence.test.ts (10/10) + tests/unit/proxy-transport-traffic-simulation.test.ts (4/4).",
   "_rebaseline_2026_09_24_14708_persisted_cooldown_precedence": "PR #14708 own growth: open-sse/services/combo/roundRobinCombo.ts 1263->1285 (+22 = the persisted-cooldown pre-check at the only round-robin dispatch point with no persisted check (import + async pre-check + skip/continue), plus the sticky-target reflow). Irreducible: the check must live at the dispatch site that bypasses executeTargetAttempt. Covered by tests/unit/combo-transient-persisted-precedence.test.ts.",
@@ -513,7 +514,7 @@
     "open-sse/services/combo/executeTargetAttempt.ts": 1273,
     "open-sse/translator/response/openai-responses.ts": 1536,
     "open-sse/utils/cursorAgentProtobuf.ts": 1588,
-    "open-sse/utils/proxyFetch.ts": 1341,
+    "open-sse/utils/proxyFetch.ts": 1383,
     "open-sse/utils/stream.ts": 3296,
     "open-sse/vendor/codex-chatgpt-web/adapters/chatgpt-web/browser-worker.ts": 4398,
     "open-sse/vendor/codex-chatgpt-web/bridge.ts": 1335,
@@ -535,7 +536,7 @@
     "src/app/api/v1/models/catalog.ts": 2127,
     "src/app/docs/lib/openapi.generated.ts": 1347,
     "src/lib/db/apiKeys.ts": 1719,
-    "src/lib/db/core.ts": 1800,
+    "src/lib/db/core.ts": 1802,
     "src/lib/db/migrationRunner.ts": 1206,
     "src/lib/tailscaleTunnel.ts": 1208,
     "src/lib/tokenHealthCheck.ts": 1254,
@@ -548,12 +549,12 @@
     "tests/unit/provider-validation-specialty.test.ts": 4656,
     "open-sse/services/autoCombo/virtualFactory.ts": 1258,
     "open-sse/services/combo/roundRobinCombo.ts": 1285,
-    "src/shared/components/RequestLoggerDetail.tsx": 1216,
+    "src/shared/components/RequestLoggerDetail.tsx": 1226,
     "src/shared/middleware/chatBodyAdmission.ts": 1206,
     "open-sse/executors/deepseek-web.ts": 1224,
     "open-sse/executors/default.ts": 1207,
     "open-sse/services/rateLimitManager.ts": 1329,
-    "open-sse/executors/opencode.ts": 1419
+    "open-sse/executors/opencode.ts": 1452
   },
   "_rebaseline_2026_09_15_roundrobin_dashboard_events": "Fix #13089 (Combo Studio Live dashboard shows an empty backlog for round-robin combos): open-sse/services/combo/roundRobinCombo.ts 1205->1213. Round-robin is the only combo strategy that bypasses handleComboChat/executeTargetAttempt.ts, the path that publishes the combo.target.attempt/succeeded/failed EventBus events the Live dashboard listens for — so round-robin completions never showed up. The new call-site wiring (createRRDashboardEvents(...) instantiated once per target, one-line .attempt()/.succeeded()/.failed() calls at the 6 existing dispatch/outcome points) is the emitter logic actually extracted into a new module, open-sse/services/combo/rrDashboardEvents.ts — this is the minimum irreducible footprint for wiring 6 required call sites into 6 fixed control-flow points of the frozen file. Covered by tests/unit/issue-13089-roundrobin-live-ws-events.test.ts (2 tests: success + failure paths).",
   "_rebaseline_base_2026_08_10_proxyfetch": "Base-red fix (green-prs sweep, issue #9985): open-sse/utils/proxyFetch.ts 1207 > cap 1000 — new proxied-TLS fetch helper introduced by the Fal reference-image work. Owner-authorized quick rebaseline to green; structural slim tracked for v3.9.0.",

open-sse/executors/opencode.ts

@@ -16,7 +16,9 @@ import {
   runWithDirectFetchContext,
   runWithProxyContext,
   noteRotationAccount,
+  noteAddedWait,
   resolveProxyForRequest,
+  type AddedWaitCause,
 } from "../utils/proxyFetch.ts";
 import {
   createServedAccountTracker,
@@ -676,6 +678,27 @@ export class OpencodeExecutor extends BaseExecutor {
       const requestPacing = egressPacing.initEgressPacingForRequest(); // Off by default.
       // served-account changes (effective-change counting) live in the leaf tracker.
       const noteServedAccount = createServedAccountTracker();
+      // Cumulative wait imposed before dispatch (egress pacing + park),
+      // published as snapshots to the ALS capture sink. A stopwatch, never a
+      // key attribute — no egress-key read here.
+      const addedWait = { ms: 0, causes: new Set<AddedWaitCause>() };
+      const publishAddedWait = (): void => noteAddedWait(addedWait.ms, addedWait.causes);
+      // Single park counter (wrapper alone, no hook in the park
+      // module). parkWithHeartbeat calls driver.sleep per elapsed step in both
+      // stream (closure start()) and non-stream paths, so wrapping this one
+      // sleep counts every parked step exactly once. Monotone += only.
+      const parkSleepCounting = async (
+        ms: number,
+        signal?: AbortSignal | null
+      ): Promise<boolean> => {
+        const elapsed = await this.parkSleep(ms, signal);
+        if (elapsed) {
+          addedWait.ms += ms;
+          addedWait.causes.add("park");
+          publishAddedWait();
+        }
+        return elapsed;
+      };
       const appliedEgress = egressPacing.createAppliedEgressTracker(
         this.buildUrl(String(input.model ?? ""), Boolean(input.stream)),
         resolveProxyForRequest
@@ -787,6 +810,10 @@ export class OpencodeExecutor extends BaseExecutor {
         // Pin egress to this account's proxy for the whole BaseExecutor dispatch
         // (incl. its intra-URL 429 retries). skipUpstreamRetry lets THIS loop own
         // the cross-account 429 fallback instead of BaseExecutor's same-key retry.
+        // Wall-clock around the paced acquire (sync repick included —
+        // µs against waits in seconds). Time endured in queue counts on every
+        // outcome: slot granted, fail-open null, or repick.
+        const throttleStart = Date.now();
         const paced = await egressPacing.startPacedDispatch(
           requestPacing,
           account,
@@ -797,6 +824,12 @@ export class OpencodeExecutor extends BaseExecutor {
         );
         const egressRelease = paced.release;
         account = paced.account;
+        const throttleDelta = Math.max(0, Date.now() - throttleStart);
+        if (throttleDelta > 0) {
+          addedWait.ms += throttleDelta;
+          addedWait.causes.add("throttle");
+          publishAddedWait();
+        }
         appliedEgress.rememberServed(account); // Served (post repick), never acquire-time.
         let result: HttpExecuteResult;
         try {
@@ -946,7 +979,7 @@ export class OpencodeExecutor extends BaseExecutor {
                     execute: (i: ExecuteInput) =>
                       super.execute(i) as Promise<ExecutorExecuteResult & { response: Response }>,
                     markSuccess: (a: ScopedAccount) => markSuccess(a),
-                    sleep: this.parkSleep,
+                    sleep: parkSleepCounting,
                     accounts,
                     replayKeyOfMember: keyOfMember,
                   },

open-sse/handlers/chatCore/attemptLogging.ts

@@ -23,6 +23,7 @@ import { sanitizeErrorMessage } from "../../utils/error.ts";
 import { isEstimatedUsage } from "../../utils/usageTracking.ts";
 import { cloneBoundedChatLogPayload, truncateForLog } from "./logTruncation.ts";
 import { attachLogMeta } from "./cacheUsageMeta.ts";
+import { readAddedWait } from "../../utils/proxyFetch.ts";
 
 const OMITTED_VIDEO_TRANSCRIPT_REQUEST = { _omniroute_omitted: "video-transcript" };
 
@@ -549,6 +550,10 @@ export function persistAttemptLogs(args: PersistAttemptLogsArgs, ctx: PersistAtt
   // pendingRequestId and must not share the row key. correlationId still
   // pairs the row with request.started. pendingRequestId is NOT the row key: it only
   // routes token usage to the live in-memory request row (#14324).
+  // Late read of the per-request added wait published on the ALS
+  // capture sink by the executor. Fail-soft: null outside a capture or when
+  // nothing was published — the row stores NULL (no wait), never throws.
+  const addedWait = readAddedWait();
   saveCallLog({
     pendingRequestId: ctx.pendingRequestId,
     method: "POST",
@@ -608,6 +613,8 @@ export function persistAttemptLogs(args: PersistAttemptLogsArgs, ctx: PersistAtt
     sessionTag: sessionTag || null,
     responseId: extractResponsesId(sourceFormat, clientResponse),
     videoContentRemoved: videoContentRemoved || false,
+    addedWaitMs: addedWait?.ms ?? null,
+    addedWaitCause: addedWait?.cause ?? null,
   }).catch(() => {});
 
   // Emit the terminal request-lifecycle event to the live dashboard bus. `request.started`

open-sse/utils/proxyFetch.ts

@@ -197,6 +197,10 @@ export type AppliedProxySink = {
   upstreamStatus?: number;
   /** Masked serving-account id (N112) — set by the rotation executor at dispatch. */
   rotationAccount?: string | null;
+  /** Added wait before dispatch, ms — null means none was imposed. */
+  addedWaitMs?: number | null;
+  /** Added-wait cause: throttle, park, or throttle+park. */
+  addedWaitCause?: string | null;
   /**
    * Pool-member resolver published by the chat layer when the resolved egress
    * came from a connection pool that may offer another member on a per-address
@@ -249,6 +253,47 @@ export function noteRotationAccount(masked: string): void {
   }
 }
 
+/** Added-wait causes. Plain data — numbers plus this enum, nothing to mask. */
+export type AddedWaitCause = "throttle" | "park" | "throttle+park";
+
+/**
+ * Cumulative wait before dispatch (pacing, park) on the capture sink.
+ * Snapshot: callers publish cumulative totals, so last-write-wins loses
+ * nothing. Best-effort like noteRotationAccount: no-op outside a capture.
+ */
+export function noteAddedWait(totalMs: number, causes: Set<AddedWaitCause>): void {
+  try {
+    const sink = getAppliedProxyContext().getStore();
+    if (!sink) return;
+    if (!Number.isFinite(totalMs) || totalMs <= 0 || causes.size === 0) {
+      sink.addedWaitMs = null;
+      sink.addedWaitCause = null;
+      return;
+    }
+    sink.addedWaitMs = Math.round(totalMs);
+    sink.addedWaitCause = causes.size > 1 ? "throttle+park" : ([...causes][0] ?? null);
+  } catch {
+    /* added-wait is best-effort; never break the request path */
+  }
+}
+
+/**
+ * Late read of the added wait on the capture sink. Fail-soft: null
+ * outside a capture or when nothing was published — callers persist NULL.
+ */
+export function readAddedWait(): { ms: number | null; cause: string | null } | null {
+  try {
+    const sink = getAppliedProxyContext().getStore();
+    if (!sink) return null;
+    const ms = typeof sink.addedWaitMs === "number" ? sink.addedWaitMs : null;
+    if (ms === null) return null;
+    const cause = typeof sink.addedWaitCause === "string" ? sink.addedWaitCause : null;
+    return { ms, cause };
+  } catch {
+    return null;
+  }
+}
+
 type FetchWithDispatcherOptions = RequestInit & { dispatcher?: unknown };
 type FetchWithDispatcher = (
   input: RequestInfo | URL,

src/app/api/usage/call-logs/route.ts

@@ -152,6 +152,9 @@ export function buildCallLogListRows({
       connectionId: detail.connectionId,
       duration: Math.max(0, now - detail.startedAt),
       tokens: detail.tokens || { in: 0, out: 0 },
+      // In-memory details carry no added wait yet — null like "no wait".
+      addedWaitMs: null,
+      addedWaitCause: null,
       cacheSource: null,
       sourceFormat: null,
       targetFormat: null,
@@ -194,6 +197,9 @@ export function buildCallLogListRows({
       connectionId: detail.connectionId,
       duration,
       tokens: detail.tokens || { in: 0, out: 0 },
+      // In-memory details carry no added wait yet — null like "no wait".
+      addedWaitMs: null,
+      addedWaitCause: null,
       cacheSource: null,
       sourceFormat: null,
       targetFormat: null,

src/i18n/messages/am.json

@@ -11403,6 +11403,7 @@
       "compressed": "መጭመቅ",
       "tps": "TPS",
       "duration": "ቆይታ",
+      "addedWait": "ተጨማሪ መቆየት",
       "time": "ጊዜ",
       "conversation": "ውይይት",
       "ttft": "TTFT"
@@ -11477,6 +11478,7 @@
       "startedAt": "የተጀመረበት ጊዜ",
       "endedAt": "ያበቃበት ጊዜ",
       "duration": "የቆይታ ጊዜ",
+      "addedWait": "ተጨማሪ መቆየት",
       "model": "ሞዴል",
       "provider": "አቅራቢ",
       "account": "መለያ",

src/i18n/messages/ar.json

@@ -11403,6 +11403,7 @@
       "compressed": "ضغط",
       "tps": "TPS",
       "duration": "المدة",
+      "addedWait": "انتظار مضاف",
       "time": "الوقت",
       "conversation": "المحادثة",
       "ttft": "TTFT"
@@ -11477,6 +11478,7 @@
       "startedAt": "بدأت في",
       "endedAt": "انتهى في",
       "duration": "المدة",
+      "addedWait": "انتظار مضاف",
       "model": "نموذج",
       "provider": "مزود",
       "account": "حساب",

src/i18n/messages/az.json

@@ -11403,6 +11403,7 @@
       "compressed": "Sıxılma",
       "tps": "TPS",
       "duration": "Müddət",
+      "addedWait": "Əlavə Gözləmə",
       "time": "Vaxt",
       "conversation": "Söhbət",
       "ttft": "TTFT"
@@ -11477,6 +11478,7 @@
       "startedAt": "Başlanğıc Tarixi",
       "endedAt": "Bitdi Saatı",
       "duration": "Müddət",
+      "addedWait": "Əlavə Gözləmə",
       "model": "Model",
       "provider": "Təchizatçı",
       "account": "Hesab",

src/i18n/messages/bg.json

@@ -11403,6 +11403,7 @@
       "compressed": "Компресия",
       "tps": "TPS",
       "duration": "Продължителност",
+      "addedWait": "Добавено чакане",
       "time": "Време",
       "conversation": "Разговор",
       "ttft": "TTFT"
@@ -11477,6 +11478,7 @@
       "startedAt": "Започнато в",
       "endedAt": "Завършено На",
       "duration": "Продължителност",
+      "addedWait": "Добавено чакане",
       "model": "Модел",
       "provider": "Доставчик",
       "account": "Акаунт",

src/i18n/messages/bn.json

@@ -11403,6 +11403,7 @@
       "compressed": "কম্প্রেশন",
       "tps": "TPS",
       "duration": "সময়কাল",
+      "addedWait": "অতিরিক্ত অপেক্ষা",
       "time": "সময়",
       "conversation": "কথোপকথন",
       "ttft": "TTFT"
@@ -11477,6 +11478,7 @@
       "startedAt": "শুরু হয়েছে",
       "endedAt": "শেষ হয়েছে",
       "duration": "স্থায়িত্ব",
+      "addedWait": "অতিরিক্ত অপেক্ষা",
       "model": "মডেল",
       "provider": "প্রদানকারী",
       "account": "অ্যাকাউন্ট",

src/i18n/messages/bs.json

@@ -11403,6 +11403,7 @@
       "compressed": "Kompresija",
       "tps": "TPS",
       "duration": "Trajanje",
+      "addedWait": "Dodatno čekanje",
       "time": "Vrijeme",
       "conversation": "Konverzacija",
       "ttft": "TTFT"
@@ -11477,6 +11478,7 @@
       "startedAt": "Započeto u",
       "endedAt": "Završeno u",
       "duration": "Trajanje",
+      "addedWait": "Dodatno čekanje",
       "model": "Model",
       "provider": "Provajder",
       "account": "Račun",

src/i18n/messages/cs.json

@@ -11403,6 +11403,7 @@
       "compressed": "Komprese",
       "tps": "TPS",
       "duration": "Doba trvání",
+      "addedWait": "Přidané čekání",
       "time": "Čas",
       "conversation": "Konverzace",
       "ttft": "TTFT"
@@ -11477,6 +11478,7 @@
       "startedAt": "Začalo v",
       "endedAt": "Skončilo v",
       "duration": "Doba trvání",
+      "addedWait": "Přidané čekání",
       "model": "Model",
       "provider": "Poskytovatel",
       "account": "Účet",

src/i18n/messages/da.json

@@ -11403,6 +11403,7 @@
       "compressed": "Kompression",
       "tps": "TPS",
       "duration": "Varighed",
+      "addedWait": "Tilføjet ventetid",
       "time": "Tidspunkt",
       "conversation": "Samtale",
       "ttft": "TTFT"
@@ -11477,6 +11478,7 @@
       "startedAt": "Startede Ved",
       "endedAt": "Afsluttet Den",
       "duration": "Varighed",
+      "addedWait": "Tilføjet ventetid",
       "model": "Model",
       "provider": "Udbyder",
       "account": "Konto",

src/i18n/messages/de.json

@@ -11403,6 +11403,7 @@
       "compressed": "Komprimierung",
       "tps": "TPS",
       "duration": "Dauer",
+      "addedWait": "Zusätzliche Wartezeit",
       "time": "Zeit",
       "conversation": "Konversation",
       "ttft": "TTFT"
@@ -11477,6 +11478,7 @@
       "startedAt": "Begonnen Am",
       "endedAt": "Beendet Am",
       "duration": "Dauer",
+      "addedWait": "Zusätzliche Wartezeit",
       "model": "Modell",
       "provider": "Anbieter",
       "account": "Konto",

src/i18n/messages/el.json

@@ -11403,6 +11403,7 @@
       "compressed": "Συμπίεση",
       "tps": "TPS",
       "duration": "Διάρκεια",
+      "addedWait": "Επιπλέον αναμονή",
       "time": "Ώρα",
       "conversation": "Συνομιλία",
       "ttft": "TTFT"
@@ -11477,6 +11478,7 @@
       "startedAt": "Ξεκίνησε στις",
       "endedAt": "Τελείωσε στις",
       "duration": "Διάρκεια",
+      "addedWait": "Επιπλέον αναμονή",
       "model": "Μοντέλο",
       "provider": "Πάροχος",
       "account": "Λογαριασμός",