From aa299720ee20537770e2352ebd352697016656ab Mon Sep 17 00:00:00 2001 From: Diego Rodrigues de Sa e Souza <8016841+diegosouzapw@users.noreply.github.com> Date: Mon, 29 Jun 2026 11:21:37 -0300 Subject: [PATCH] fix(opencode): visible rotation logs + ProxyEgress + callLogs SQL-vars (#5217 Stage 1) (#5351) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Integrated into release/v3.8.41 β€” OpenCode rotation logs (info) + ProxyEgress applied-proxy sink + callLogs SQL-vars chunking (#5217 Stage 1). Tests green (apply-executor-proxy-info, call-log-trim-sql-vars, opencode-proxy-rotation). --- CHANGELOG.md | 8 +- open-sse/executors/opencode.ts | 6 +- open-sse/utils/proxyFetch.ts | 33 ++++++ src/lib/usage/callLogs.ts | 32 ++++-- src/sse/handlers/chat.ts | 8 +- src/sse/handlers/chatHelpers.ts | 31 ++++++ .../apply-executor-proxy-info-5217.test.ts | 42 ++++++++ .../unit/call-log-trim-sql-vars-5217.test.ts | 102 ++++++++++++++++++ .../unit/opencode-proxy-rotation-4954.test.ts | 79 +++++++++++++- 9 files changed, 324 insertions(+), 17 deletions(-) create mode 100644 tests/unit/apply-executor-proxy-info-5217.test.ts create mode 100644 tests/unit/call-log-trim-sql-vars-5217.test.ts diff --git a/CHANGELOG.md b/CHANGELOG.md index e0b966777c..6743300d17 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -10,10 +10,10 @@ _In development β€” bullets added per PR; finalized at release._ ### πŸ”§ Bug Fixes -- **routing:** auto-disable a depleted API key on upstream `402 "Insufficient account balance"` for API Key Round-Robin connections (multiple keys in one connection's `extraApiKeys`). The per-connection path already terminalized 402 (β†’ `credits_exhausted`), but the per-KEY health tracker (`recordKeyHealthStatus`) only recorded failures for `401`, so a 402-depleted key stayed in rotation and kept getting retried. Now a 402 marks the current key invalid immediately (terminal β€” balance won't recover mid-session) via a new `recordKeyTerminal`, so the rotator skips it and falls over to the next healthy key; the state persists across restarts. Also added `insufficient balance`/`insufficient_balance`/`insufficient account balance` to the credits-exhausted body signals so non-402 out-of-credit responses terminalize too. Regression guard: `tests/unit/key-health-402-disable-5239.test.ts`. ([#5239](https://github.com/diegosouzapw/OmniRoute/issues/5239) β€” thanks @muflifadla38) -- **cli:** `omniroute serve` no longer discards a user-set `NODE_OPTIONS=--max-old-space-size=…`. It used to unconditionally overwrite `NODE_OPTIONS` (and pass an explicit `--max-old-space-size` CLI arg) with the calibrated default, so a user who exported `--max-old-space-size=8192` still ran at the old cap and OOM'd (#5238 reporter set 8192, crashed at ~505MB). Now it mirrors the Electron and standalone launchers: if `NODE_OPTIONS` already pins the heap, that value wins (and the duplicate CLI arg is suppressed); otherwise the calibrated `--max-old-space-size` is appended, preserving unrelated flags. Regression guard: `tests/unit/serve-node-options-preserve-5238.test.ts`. (Defect C of [#5238](https://github.com/diegosouzapw/OmniRoute/issues/5238); the `b.mask`/OOM-root parts are tracked separately.) -- **dashboard:** restore the `{active}/{total} active` model-count badge in a provider's **Available Models** toolbar (provider detail page). It was dropped during the v3.8.13 god-file decomposition (#3327) β€” the `ModelVisibilityToolbar` still received `activeCount`/`totalCount` but they were orphaned as unused `_`-prefixed params and the rendering `` was never carried over (the `modelsActiveCount` i18n key stayed). Re-wired the existing props to the existing key; zero data-layer or i18n change. Regression guard: `modelVisibilityToolbarActiveCount.test.tsx`. ([#5264](https://github.com/diegosouzapw/OmniRoute/issues/5264)) -- **rerank:** `/v1/rerank` no longer rejects SiliconFlow and DeepInfra Qwen3-Reranker models with `400 "Invalid rerank model"` even though `/v1/models` lists them. The model-ID parser was never the problem (it already splits on the first slash, so `siliconflow/Qwen/Qwen3-Reranker-8B` parses correctly) β€” `siliconflow` and `deepinfra` were just missing from the rerank provider registry. Added both: SiliconFlow as Cohere-compatible, DeepInfra via a new `deepinfra` adapter (model in the URL path `POST /v1/inference/`, `{queries,documents}` request, positional `{scores}` response mapped to Cohere `results[]`). Regression guard: `tests/unit/rerank-providers-5332.test.ts`. ([#5332](https://github.com/diegosouzapw/OmniRoute/issues/5332) β€” thanks @maikokan) +- **opencode/observability:** make OpenCode Free account/proxy rotation visible and fix two real defects surfaced alongside it. **(1)** the per-request rotation selection log (`dispatch via account … through proxy …`) was `debug` (hidden at default `APP_LOG_LEVEL=info`) β€” promoted to `info` so the shuffle/cooldown lifecycle is auditable (token stays masked). **(2)** `[ProxyEgress]` reported `proxy=direct` even when an account proxy was applied, because the egress logger ran outside the executor's nested proxy context β€” the effective applied proxy is now captured (via an applied-proxy sink threaded through the proxy AsyncLocalStorage) and reflected in the egress log. **(3)** `[callLogs] too many SQL variables` β€” `deleteCallLogRowsByIds` deleted up to 5000 ids in one `IN (…)`, exceeding SQLite's ~999 bound-param cap and aborting log trimming/retention; ids are now chunked (≀500 per statement). Regression guards: `tests/unit/call-log-trim-sql-vars-5217.test.ts`, `apply-executor-proxy-info-5217.test.ts`, extended `opencode-proxy-rotation-4954.test.ts`. The Proxy Pool dropdown (by-id) UI (Gap 1) is a follow-up requiring browser validation. ([#5217](https://github.com/diegosouzapw/OmniRoute/issues/5217) β€” thanks @daniij) + +### πŸ”§ Bug Fixes + - **authz/dashboard:** stop rejecting every dashboard mutation with `403 INVALID_ORIGIN` when the dashboard is reached over a LAN IP / non-localhost host. The origin-pinning check (#5278) only accepted the configured `*_PUBLIC_BASE_URL` (typically `http://localhost:20128`) plus the internal `request.url` origin β€” which Next.js standalone reports as the bind host, not the real `Host`. So opening the dashboard at e.g. `http://192.168.0.15:20128` made the browser's same-origin `Origin` match no candidate, and **every** POST/PUT/DELETE (save API key, save provider, test connection) failed while GETs still worked. Two fixes: **(a)** the request `Host` (or a trusted `X-Forwarded-Host`) is now accepted as a valid mutation origin, gated by two independent checks β€” the token-stamped socket peer must be loopback/private-LAN **and** the Host itself must be a loopback/private-LAN IP literal, so a DNS-rebinding domain (which classifies as `remote`) can never become a trusted origin and the protocol is pinned to the actual connection; **(b)** the `INVALID_ORIGIN` response now carries an actionable message (set `OMNIROUTE_PUBLIC_BASE_URL`) and the dashboard surfaces API error `.message` via a shared `extractApiErrorMessage` helper instead of rendering the raw error object. Regression guards: `tests/unit/authz/public-origin.test.ts` (direct LAN/loopback + DNS-rebinding defense), `tests/unit/api-error-message-5340.test.ts`. ([#5340](https://github.com/diegosouzapw/OmniRoute/issues/5340)) --- diff --git a/open-sse/executors/opencode.ts b/open-sse/executors/opencode.ts index ce68ef694c..6fccf7117d 100644 --- a/open-sse/executors/opencode.ts +++ b/open-sse/executors/opencode.ts @@ -152,7 +152,11 @@ export class OpencodeExecutor extends BaseExecutor { for (let attempt = 0; attempt < this.accounts.length; attempt++) { const account = this.pickAccount(); const masked = OpencodeExecutor.maskAccountId(account.fingerprint); - log?.debug?.( + // #5217 (Gap 2): promoted debugβ†’info so the per-request account/proxy + // rotation selection is visible in the Console log view at the default + // APP_LOG_LEVEL=info (users could not see which account/proxy was used). + // Token stays masked β€” never log the full account id. + log?.info?.( "OPENCODE", `dispatch via account ${masked} (idx ${attempt + 1}/${this.accounts.length})` + (account.proxy ? ` through proxy ${account.proxy.host}:${account.proxy.port}` : " direct") diff --git a/open-sse/utils/proxyFetch.ts b/open-sse/utils/proxyFetch.ts index 680377009d..134aaf8311 100644 --- a/open-sse/utils/proxyFetch.ts +++ b/open-sse/utils/proxyFetch.ts @@ -28,6 +28,31 @@ function isTlsFingerprintEnabled() { type TlsFingerprintStore = { used: boolean }; const tlsFingerprintContext = new AsyncLocalStorage(); +/** + * #5217 (Gap-secondary): a mutable sink that records the proxy actually applied + * by `runWithProxyContext` for the in-flight request. Executors that pin their + * own per-account proxy *internally* (e.g. OpencodeExecutor wraps its dispatch + * in `runWithProxyContext(account.proxy, …)`) never propagate that choice back + * to the caller's `proxyInfo`, so the post-execution `[ProxyEgress]` line logged + * `proxy=direct` even though `[ProxyFetch] Applied request proxy context: …` + * fired. Wrapping the execution in `runWithAppliedProxyCapture(sink, fn)` lets + * the egress logger read the innermost applied proxy (the last writer wins, which + * is the executor's per-account proxy). + */ +export type AppliedProxySink = { proxy: unknown }; +const appliedProxyContext = new AsyncLocalStorage(); + +/** + * Run `fn` with an applied-proxy capture sink in context. Any + * `runWithProxyContext` call inside `fn` that ends up applying a proxy records + * that proxy config into `sink.proxy` (innermost wins). The sink is a plain + * mutable object the caller retains, so it can read `sink.proxy` after `fn` + * resolves. Pure plumbing β€” no behavioral change to the request itself. + */ +export function runWithAppliedProxyCapture(sink: AppliedProxySink, fn: () => T): T { + return appliedProxyContext.run(sink, fn); +} + type FetchWithDispatcherOptions = RequestInit & { dispatcher?: unknown }; type FetchWithDispatcher = ( input: RequestInfo | URL, @@ -334,6 +359,14 @@ export async function runWithProxyContext( `[ProxyFetch] Applied request proxy context: ${proxyUrlForLogs(resolvedProxyUrl)}` ); } + // #5217: record the proxy actually applied so a post-execution egress logger + // reflects the real egress (executors that pin a per-account proxy internally + // otherwise leave proxyInfo reading "direct"). Innermost runWithProxyContext + // wins, which is exactly the per-account proxy the executor selected. + if (effectiveProxyConfig) { + const sink = appliedProxyContext.getStore(); + if (sink) sink.proxy = effectiveProxyConfig; + } return fn(); }); } diff --git a/src/lib/usage/callLogs.ts b/src/lib/usage/callLogs.ts index ada9efee37..048f75addd 100644 --- a/src/lib/usage/callLogs.ts +++ b/src/lib/usage/callLogs.ts @@ -425,28 +425,40 @@ function listReferencedArtifacts() { ); } +// #5217: SQLite caps a statement at SQLITE_MAX_VARIABLE_NUMBER bound params +// (~999 on many builds). Callers like trimCallLogsToMaxRows() passed up to 5000 +// ids in one `IN (...)` β†’ "too many SQL variables" aborted trimming. Chunk well +// under the limit so each DELETE/SELECT stays valid. +const DELETE_ID_CHUNK_SIZE = 500; + function deleteCallLogRowsByIds(ids: string[]): DeleteResult { if (ids.length === 0) { return { deletedRows: 0, deletedArtifacts: 0 }; } const db = getDbInstance(); - const placeholders = ids.map(() => "?").join(", "); - const rows = db - .prepare(`SELECT artifact_relpath FROM call_logs WHERE id IN (${placeholders})`) - .all(...ids) as Array<{ artifact_relpath: string | null }>; - - const result = db.prepare(`DELETE FROM call_logs WHERE id IN (${placeholders})`).run(...ids); + let deletedRows = 0; let deletedArtifacts = 0; - for (const row of rows) { - if (deleteCallArtifact(row.artifact_relpath)) { - deletedArtifacts++; + + for (let i = 0; i < ids.length; i += DELETE_ID_CHUNK_SIZE) { + const chunk = ids.slice(i, i + DELETE_ID_CHUNK_SIZE); + const placeholders = chunk.map(() => "?").join(", "); + const rows = db + .prepare(`SELECT artifact_relpath FROM call_logs WHERE id IN (${placeholders})`) + .all(...chunk) as Array<{ artifact_relpath: string | null }>; + + const result = db.prepare(`DELETE FROM call_logs WHERE id IN (${placeholders})`).run(...chunk); + deletedRows += result.changes; + for (const row of rows) { + if (deleteCallArtifact(row.artifact_relpath)) { + deletedArtifacts++; + } } } cleanupEmptyCallLogDirs(); return { - deletedRows: result.changes, + deletedRows, deletedArtifacts, }; } diff --git a/src/sse/handlers/chat.ts b/src/sse/handlers/chat.ts index f2db6caff6..a12a65fd21 100644 --- a/src/sse/handlers/chat.ts +++ b/src/sse/handlers/chat.ts @@ -70,6 +70,7 @@ import { handleNoCredentials, safeResolveProxy, safeLogEvents, + applyExecutorProxyToInfo, shouldRetryStreamEarlyEof, withSessionHeader, withSelectedConnectionHeader, @@ -1227,6 +1228,9 @@ async function handleSingleModelChat( ); } const proxyInfo = await safeResolveProxy(credentials.connectionId, apiKeyInfo?.id); + // #5217: sink for the proxy the executor pins internally (e.g. OpencodeExecutor + // rotation) so the egress log below reflects the real egress, not "direct". + const appliedProxySink: { proxy: unknown } = { proxy: null }; const proxyStartTime = Date.now(); // 4. Execute chat via core after breaker gate checks (with optional TLS tracking) @@ -1239,6 +1243,7 @@ async function handleSingleModelChat( model: effectiveModel, refreshedCredentials, proxyInfo, + appliedProxySink, log, clientRawRequest, credentials, @@ -1266,9 +1271,10 @@ async function handleSingleModelChat( targetFormat; // 5. Log proxy + translation events (fire-and-forget; never blocks the response) + // #5217: reflect the proxy the executor actually applied (per-account rotation). void safeLogEvents({ result, - proxyInfo, + proxyInfo: applyExecutorProxyToInfo(proxyInfo, appliedProxySink.proxy), proxyLatency, provider, model, diff --git a/src/sse/handlers/chatHelpers.ts b/src/sse/handlers/chatHelpers.ts index 498f625336..992e4d3a76 100644 --- a/src/sse/handlers/chatHelpers.ts +++ b/src/sse/handlers/chatHelpers.ts @@ -22,8 +22,10 @@ import { import { HTTP_STATUS } from "@omniroute/open-sse/config/constants.ts"; import { runWithProxyContext, + runWithAppliedProxyCapture, runWithTlsTracking, isTlsFingerprintActive, + type AppliedProxySink, } from "@omniroute/open-sse/utils/proxyFetch.ts"; import { resolveProxyForConnection } from "@/lib/localDb"; import { @@ -363,6 +365,7 @@ export async function executeChatWithBreaker({ model, refreshedCredentials, proxyInfo, + appliedProxySink, log: handlerLog, clientRawRequest, credentials, @@ -388,8 +391,15 @@ export async function executeChatWithBreaker({ : "production"; const isShadowTraffic = normalizedTrafficType === "shadow"; + // #5217: capture the proxy actually applied during execution so the caller can + // merge it into proxyInfo before the egress log (executors pinning a per-account + // proxy internally otherwise leave the egress log reading "direct"). + const capture = (fn: () => T): T => + appliedProxySink ? runWithAppliedProxyCapture(appliedProxySink, fn) : fn(); + try { const chatFn = () => + capture(() => runWithProxyContext(proxyInfo?.proxy || null, () => (handleChatCore as any)({ body: { ...body, model: `${provider}/${model}` }, @@ -464,6 +474,7 @@ export async function executeChatWithBreaker({ ); }, }) + ) ); if (isShadowTraffic) { @@ -679,6 +690,26 @@ export async function safeResolveProxy(connectionId: string, apiKeyId?: string) } } +/** + * #5217: merge a proxy the executor applied internally (captured via + * AppliedProxySink) into the pre-execution proxyInfo so the egress logger reflects + * the real egress. No applied proxy β†’ proxyInfo unchanged. A pre-existing + * non-direct level is preserved; otherwise reported as "account" (per-account + * proxy, e.g. OpenCode rotation). Pure + unit-testable. + */ +export function applyExecutorProxyToInfo( + proxyInfo: { proxy?: unknown; level?: string; levelId?: string | null } | null | undefined, + appliedProxy: unknown +) { + if (!appliedProxy) return proxyInfo; + const priorLevel = proxyInfo?.level; + return { + ...(proxyInfo || {}), + proxy: appliedProxy, + level: priorLevel && priorLevel !== "direct" ? priorLevel : "account", + }; +} + // Async because the egress-IP lookup lazy-imports proxyEgress; callers treat // this as fire-and-forget logging (the internal try/catch swallows everything). export async function safeLogEvents({ diff --git a/tests/unit/apply-executor-proxy-info-5217.test.ts b/tests/unit/apply-executor-proxy-info-5217.test.ts new file mode 100644 index 0000000000..1b21e54fc5 --- /dev/null +++ b/tests/unit/apply-executor-proxy-info-5217.test.ts @@ -0,0 +1,42 @@ +import test from "node:test"; +import assert from "node:assert/strict"; +import { applyExecutorProxyToInfo } from "../../src/sse/handlers/chatHelpers.ts"; + +/** + * #5217 (secondary) β€” the egress logger logged `proxy=direct` even when an + * executor (OpencodeExecutor rotation) pinned a per-account proxy internally, + * because the pre-resolved `proxyInfo` never learned about it. + * `applyExecutorProxyToInfo` merges the executor-applied proxy back into proxyInfo + * so the egress line reflects the real egress. + */ + +test("returns proxyInfo unchanged when the executor applied no proxy", () => { + const proxyInfo = { proxy: null, level: "direct", levelId: null }; + assert.strictEqual(applyExecutorProxyToInfo(proxyInfo, null), proxyInfo); + assert.strictEqual(applyExecutorProxyToInfo(proxyInfo, undefined), proxyInfo); +}); + +test("injects the applied proxy and labels a previously-direct level as 'account'", () => { + const applied = { type: "http", host: "127.0.0.1", port: 9999 }; + const merged = applyExecutorProxyToInfo({ proxy: null, level: "direct", levelId: null }, applied); + assert.deepEqual(merged?.proxy, applied); + assert.equal(merged?.level, "account"); +}); + +test("injects the applied proxy even when proxyInfo is null/undefined", () => { + const applied = { type: "socks5", host: "10.0.0.1", port: 1080 }; + const merged = applyExecutorProxyToInfo(null, applied); + assert.deepEqual(merged?.proxy, applied); + assert.equal(merged?.level, "account"); +}); + +test("preserves an existing non-direct level (connection/key/global proxy)", () => { + const applied = { type: "http", host: "127.0.0.1", port: 8888 }; + const merged = applyExecutorProxyToInfo( + { proxy: { type: "http", host: "1.2.3.4", port: 1 }, level: "connection", levelId: "conn-1" }, + applied + ); + assert.deepEqual(merged?.proxy, applied, "proxy is overwritten by the actually-applied one"); + assert.equal(merged?.level, "connection", "a non-direct level must be preserved"); + assert.equal(merged?.levelId, "conn-1"); +}); diff --git a/tests/unit/call-log-trim-sql-vars-5217.test.ts b/tests/unit/call-log-trim-sql-vars-5217.test.ts new file mode 100644 index 0000000000..aedee5360c --- /dev/null +++ b/tests/unit/call-log-trim-sql-vars-5217.test.ts @@ -0,0 +1,102 @@ +import test from "node:test"; +import assert from "node:assert/strict"; +import fs from "node:fs"; +import os from "node:os"; +import path from "node:path"; + +/** + * #5217 β€” `trimCallLogsToMaxRows()` deleted up to batchSize=5000 ids in a single + * `DELETE … IN (?, ?, …)` via `deleteCallLogRowsByIds`. SQLite caps a statement at + * ~999 bound parameters by default, so any trim that needed to delete >999 rows + * threw "too many SQL variables", aborting the trim and blocking the Request-log + * table from being persisted/pruned. The delete must chunk the ids so a large + * trim succeeds instead of throwing. + */ + +const TEST_DATA_DIR = fs.mkdtempSync(path.join(os.tmpdir(), "omniroute-calllogs-trim-")); +process.env.DATA_DIR = TEST_DATA_DIR; +process.env.CALL_LOG_RETENTION_DAYS = "3650"; + +const core = await import("../../src/lib/db/core.ts"); +const callLogs = await import("../../src/lib/usage/callLogs.ts"); + +function insertCallLog(id: string, timestamp: string) { + const db = core.getDbInstance(); + db.prepare( + ` + INSERT INTO call_logs ( + id, timestamp, method, path, status, model, provider, detail_state + ) + VALUES (@id, @timestamp, 'POST', '/v1/chat/completions', 200, 'openai/gpt-4.1', 'openai', 'none') + ` + ).run({ id, timestamp }); +} + +test.beforeEach(() => { + core.resetDbInstance(); + fs.rmSync(TEST_DATA_DIR, { recursive: true, force: true }); + fs.mkdirSync(TEST_DATA_DIR, { recursive: true }); +}); + +test.after(() => { + core.resetDbInstance(); + fs.rmSync(TEST_DATA_DIR, { recursive: true, force: true }); +}); + +test("trimCallLogsToMaxRows deletes >999 rows in one pass without 'too many SQL variables'", () => { + const db = core.getDbInstance(); + const total = 1500; + const base = Date.parse("2026-01-01T00:00:00.000Z"); + const insertMany = db.transaction(() => { + for (let i = 0; i < total; i++) { + insertCallLog(`trim-${String(i).padStart(5, "0")}`, new Date(base + i * 1000).toISOString()); + } + }); + insertMany(); + + assert.equal( + (db.prepare("SELECT COUNT(*) AS cnt FROM call_logs").get() as { cnt: number }).cnt, + total + ); + + // Trim to 10 rows β†’ 1490 ids must be deleted in a single trim batch (batchSize=5000), + // which without chunking would exceed SQLite's ~999 bound-parameter limit and throw. + let result: { deletedRows: number; deletedArtifacts: number } | undefined; + assert.doesNotThrow(() => { + result = callLogs.trimCallLogsToMaxRows(10); + }); + + assert.equal(result!.deletedRows, total - 10, "all overflow rows must be deleted (chunked)"); + assert.equal( + (db.prepare("SELECT COUNT(*) AS cnt FROM call_logs").get() as { cnt: number }).cnt, + 10, + "exactly maxRows rows must remain" + ); +}); + +test("deleteCallLogsBefore deletes a batch larger than SQLite's variable limit without throwing", () => { + const db = core.getDbInstance(); + // Exceed SQLITE_MAX_VARIABLE_NUMBER (999 on many builds, 32766 on newer ones). + // deleteCallLogsBefore passes EVERY matching id to one DELETE … IN (...) β€” the + // un-chunked version threw "too many SQL variables"; chunking must avoid it on + // any build. 35k > the 32766 cap, so this reproduces even on modern SQLite. + const total = 35000; + const base = Date.parse("2026-01-01T00:00:00.000Z"); + const insertMany = db.transaction(() => { + for (let i = 0; i < total; i++) { + insertCallLog(`old-${String(i).padStart(5, "0")}`, new Date(base + i * 1000).toISOString()); + } + }); + insertMany(); + + let result: { deletedRows: number } | undefined; + assert.doesNotThrow(() => { + result = callLogs.deleteCallLogsBefore("2030-01-01T00:00:00.000Z"); + }); + + assert.equal(result!.deletedRows, total, "every row before the cutoff must be deleted"); + assert.equal( + (db.prepare("SELECT COUNT(*) AS cnt FROM call_logs").get() as { cnt: number }).cnt, + 0 + ); +}); diff --git a/tests/unit/opencode-proxy-rotation-4954.test.ts b/tests/unit/opencode-proxy-rotation-4954.test.ts index 25a1c49119..9a8b55743f 100644 --- a/tests/unit/opencode-proxy-rotation-4954.test.ts +++ b/tests/unit/opencode-proxy-rotation-4954.test.ts @@ -2,7 +2,10 @@ import { describe, it, beforeEach, afterEach, before, after } from "node:test"; import assert from "node:assert"; import net from "node:net"; import { OpencodeExecutor } from "../../open-sse/executors/opencode.ts"; -import { resolveProxyForRequest } from "../../open-sse/utils/proxyFetch.ts"; +import { + resolveProxyForRequest, + runWithAppliedProxyCapture, +} from "../../open-sse/utils/proxyFetch.ts"; /** * #4954 β€” "OpenCode Free" exposes per-account proxy + multi-account rotation in @@ -165,4 +168,78 @@ describe("OpencodeExecutor per-account proxy + rotation (#4954)", () => { assert.strictEqual(p.source, "context", "every dispatch must egress through a proxy context"); } }); + + // #5217 (Gap 2): the per-request account/proxy selection log was log.debug, which + // is hidden at the default APP_LOG_LEVEL=info β€” operators could not see which + // account/proxy a request rotated to. It must be emitted at info level. + it("logs the account/proxy rotation selection at info level (#5217)", async () => { + const exec = new OpencodeExecutor("opencode-zen"); + installFetchStub([200]); + + const infoCalls: Array<{ tag: unknown; msg: string }> = []; + const debugCalls: Array<{ tag: unknown; msg: string }> = []; + const spyLog = { + debug: (tag: unknown, msg: string) => debugCalls.push({ tag, msg }), + info: (tag: unknown, msg: string) => infoCalls.push({ tag, msg }), + warn() {}, + error() {}, + }; + + await exec.execute({ + model: "grok-code", + body: { messages: [{ role: "user", content: "hi" }], stream: false }, + stream: false, + signal: null, + credentials: credentialsWithProxies(), + log: spyLog as any, + }); + + const dispatchInfo = infoCalls.find( + (c) => c.tag === "OPENCODE" && /dispatch via account/.test(c.msg) + ); + assert.ok( + dispatchInfo, + `expected an info-level "dispatch via account …" log; info calls=${JSON.stringify(infoCalls)}` + ); + // The selection line must carry the masked account id + rotation index, and + // must NOT be emitted at debug (where it would be invisible at default level). + assert.match(dispatchInfo!.msg, /account aaaaaaaa…|account bbbbbbbb…/); + assert.match(dispatchInfo!.msg, /idx \d+\/2/); + assert.ok( + !debugCalls.some((c) => /dispatch via account/.test(c.msg)), + "the selection log must not also/only be at debug level" + ); + // Masking guard: never log the full 32-char account id. + assert.ok( + !/(a{32}|b{32})/.test(dispatchInfo!.msg), + "rotation log must keep the account id masked" + ); + }); + + // #5217 (secondary): the per-account proxy the executor pins internally must be + // captured into an AppliedProxySink so the post-execution egress logger reflects + // the real egress (was "direct") rather than the pre-resolved connection proxy. + it("records the executor-applied account proxy into the AppliedProxySink (#5217)", async () => { + const exec = new OpencodeExecutor("opencode-zen"); + installFetchStub([200]); + + const sink: { proxy: any } = { proxy: null }; + await runWithAppliedProxyCapture(sink, () => + exec.execute({ + model: "grok-code", + body: { messages: [{ role: "user", content: "hi" }], stream: false }, + stream: false, + signal: null, + credentials: credentialsWithProxies(), + log, + }) + ); + + assert.ok(sink.proxy, "sink must capture the proxy the executor actually applied"); + assert.equal(sink.proxy.host, "127.0.0.1", "captured proxy host must match the account proxy"); + assert.ok( + sink.proxy.port === portA || sink.proxy.port === portB, + `captured proxy port must be one of the configured account proxies, got ${sink.proxy.port}` + ); + }); });