From 1d95dbeebc5d3f2b372cf117694bb602ac598ed4 Mon Sep 17 00:00:00 2001 From: dtzp555 Date: Sat, 21 Mar 2026 17:38:45 +1000 Subject: [PATCH] =?UTF-8?q?feat:=20v2.4.0=20=E2=80=94=20per-model=20circui?= =?UTF-8?q?t=20breaker,=20adaptive=20timeout=20tiers,=20structured=20loggi?= =?UTF-8?q?ng?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit - Circuit breaker: consecutive timeouts (default 3) mark model as degraded for 60s, failing fast instead of blocking gateway with repeated timeout attempts - Per-model timeout tiers: Opus 60s base, Sonnet 45s, Haiku 30s, plus adaptive scaling by prompt size (~15s/100k chars for Opus) - Structured JSON logging for spawns, timeouts, breaker state changes - Late close guard: prevents double-settle when timeout fires before proc.close Co-Authored-By: Claude Opus 4.6 --- openclaw-claude-proxy/package.json | 4 +- openclaw-claude-proxy/server.mjs | 142 ++++++++++++++++++++++++----- package.json | 4 +- server.mjs | 122 ++++++++++++++++++++----- 4 files changed, 222 insertions(+), 50 deletions(-) diff --git a/openclaw-claude-proxy/package.json b/openclaw-claude-proxy/package.json index 46b84f3..37c6ffd 100644 --- a/openclaw-claude-proxy/package.json +++ b/openclaw-claude-proxy/package.json @@ -1,7 +1,7 @@ { "name": "openclaw-claude-proxy", - "version": "2.3.0", - "description": "OpenAI-compatible proxy for Claude CLI v2 — on-demand sessions, faster fallback, and safe coexistence with Claude Code channels", + "version": "2.4.0", + "description": "OpenAI-compatible proxy for Claude CLI v2 — per-model circuit breaker, adaptive first-byte timeout, structured logging", "type": "module", "bin": { "openclaw-claude-proxy": "./server.mjs" diff --git a/openclaw-claude-proxy/server.mjs b/openclaw-claude-proxy/server.mjs index e3c0fdb..88339fe 100644 --- a/openclaw-claude-proxy/server.mjs +++ b/openclaw-claude-proxy/server.mjs @@ -1,29 +1,29 @@ #!/usr/bin/env node /** - * openclaw-claude-proxy v2.3.0 — OpenAI-compatible proxy for Claude CLI + * openclaw-claude-proxy v2.4.0 — OpenAI-compatible proxy for Claude CLI * * Translates OpenAI chat/completions requests into `claude -p` CLI calls, * letting you use your Claude Pro/Max subscription as an OpenClaw model provider. * - * v2.0.0 highlights: - * - On-demand spawning: eliminates pool crash loops from v1.x - * - Session management: --resume support reduces token waste on multi-turn - * - Full tool access: configurable allowedTools (expanded defaults) - * - System prompt & MCP config pass-through - * - Concurrency control with queuing - * - Coexists safely with Claude Code interactive mode (Telegram, IDE, etc.) + * v2.4.0: + * - Per-model circuit breaker: consecutive timeouts temporarily mark a model as degraded + * - Adaptive first-byte timeout: scales by model tier + prompt size + * - Structured JSON logging for key events (easier to parse/alert on) + * - On-demand spawning (no pool), session management, full tool access * * Env vars: * CLAUDE_PROXY_PORT — listen port (default: 3456) * CLAUDE_BIN — path to claude binary (default: auto-detect) * CLAUDE_TIMEOUT — per-request timeout in ms (default: 120000) - * CLAUDE_FIRST_BYTE_TIMEOUT — abort if no stdout within this ms (default: 30000) + * CLAUDE_FIRST_BYTE_TIMEOUT — base first-byte timeout in ms (default: 45000) * CLAUDE_ALLOWED_TOOLS — comma-separated tools to allow (default: expanded set) * CLAUDE_SKIP_PERMISSIONS — "true" to bypass all permission checks (default: false) * CLAUDE_SYSTEM_PROMPT — system prompt appended to all requests * CLAUDE_MCP_CONFIG — path to MCP server config JSON file * CLAUDE_SESSION_TTL — session TTL in ms (default: 3600000 = 1h) * CLAUDE_MAX_CONCURRENT — max concurrent claude processes (default: 5) + * CLAUDE_BREAKER_THRESHOLD — consecutive timeouts before circuit opens (default: 3) + * CLAUDE_BREAKER_COOLDOWN — ms to wait before retrying after circuit opens (default: 60000) * PROXY_API_KEY — Bearer token for API auth (optional) */ import { createServer } from "node:http"; @@ -77,7 +77,7 @@ function resolveClaude() { const PORT = parseInt(process.env.CLAUDE_PROXY_PORT || "3456", 10); const CLAUDE = resolveClaude(); const TIMEOUT = parseInt(process.env.CLAUDE_TIMEOUT || "120000", 10); -const FIRST_BYTE_TIMEOUT = parseInt(process.env.CLAUDE_FIRST_BYTE_TIMEOUT || "30000", 10); +const BASE_FIRST_BYTE_TIMEOUT = parseInt(process.env.CLAUDE_FIRST_BYTE_TIMEOUT || "45000", 10); const PROXY_API_KEY = process.env.PROXY_API_KEY || ""; const SKIP_PERMISSIONS = process.env.CLAUDE_SKIP_PERMISSIONS === "true"; const ALLOWED_TOOLS = (process.env.CLAUDE_ALLOWED_TOOLS || @@ -87,10 +87,65 @@ const SYSTEM_PROMPT = process.env.CLAUDE_SYSTEM_PROMPT || ""; const MCP_CONFIG = process.env.CLAUDE_MCP_CONFIG || ""; const SESSION_TTL = parseInt(process.env.CLAUDE_SESSION_TTL || "3600000", 10); const MAX_CONCURRENT = parseInt(process.env.CLAUDE_MAX_CONCURRENT || "5", 10); +const BREAKER_THRESHOLD = parseInt(process.env.CLAUDE_BREAKER_THRESHOLD || "3", 10); +const BREAKER_COOLDOWN = parseInt(process.env.CLAUDE_BREAKER_COOLDOWN || "60000", 10); const VERSION = _pkg.version; const START_TIME = Date.now(); +// ── Structured logging helper ─────────────────────────────────────────── +function logEvent(level, event, data = {}) { + const entry = { ts: new Date().toISOString(), level, event, ...data }; + if (level === "error" || level === "warn") { + console.error(JSON.stringify(entry)); + } else { + console.log(JSON.stringify(entry)); + } +} + +// ── Per-model circuit breaker ─────────────────────────────────────────── +// Tracks consecutive timeouts per model. When threshold is reached, the +// model is marked "open" (degraded) for BREAKER_COOLDOWN ms. During that +// window, requests for this model fail fast with a clear error instead of +// waiting for yet another timeout that would block the gateway. +const breakers = new Map(); // cliModel → { failures, state, openedAt } + +function getBreakerState(cliModel) { + if (!breakers.has(cliModel)) { + breakers.set(cliModel, { failures: 0, state: "closed", openedAt: 0 }); + } + const b = breakers.get(cliModel); + + // Auto-recover: if cooldown has elapsed, transition to half-open + if (b.state === "open" && Date.now() - b.openedAt >= BREAKER_COOLDOWN) { + b.state = "half-open"; + logEvent("info", "breaker_half_open", { model: cliModel, cooldownMs: BREAKER_COOLDOWN }); + } + return b; +} + +function breakerRecordSuccess(cliModel) { + const b = getBreakerState(cliModel); + if (b.failures > 0 || b.state !== "closed") { + logEvent("info", "breaker_reset", { model: cliModel, previousFailures: b.failures, previousState: b.state }); + } + b.failures = 0; + b.state = "closed"; + b.openedAt = 0; +} + +function breakerRecordTimeout(cliModel) { + const b = getBreakerState(cliModel); + b.failures++; + logEvent("warn", "breaker_failure", { model: cliModel, consecutiveFailures: b.failures, threshold: BREAKER_THRESHOLD }); + + if (b.failures >= BREAKER_THRESHOLD && b.state !== "open") { + b.state = "open"; + b.openedAt = Date.now(); + logEvent("error", "breaker_open", { model: cliModel, failures: b.failures, cooldownMs: BREAKER_COOLDOWN }); + } +} + // ── Model mapping ─────────────────────────────────────────────────────── // Maps request model IDs and aliases to canonical claude CLI model IDs. const MODEL_MAP = { @@ -210,6 +265,26 @@ function messagesToPrompt(messages) { }).join("\n\n"); } +// Model tier multipliers for first-byte timeout. +// Opus is much slower to produce first token, especially with large contexts. +const MODEL_TIMEOUT_TIERS = { + "opus": { base: 60000, perPromptChar: 0.00015 }, // 60s base + ~15s per 100k chars + "sonnet": { base: 45000, perPromptChar: 0.00008 }, // 45s base + ~8s per 100k chars + "haiku": { base: 30000, perPromptChar: 0.00005 }, // 30s base + ~5s per 100k chars +}; + +function getModelTier(cliModel) { + if (cliModel.includes("opus")) return "opus"; + if (cliModel.includes("haiku")) return "haiku"; + return "sonnet"; +} + +function computeFirstByteTimeout(cliModel, promptLength) { + const tier = MODEL_TIMEOUT_TIERS[getModelTier(cliModel)]; + const timeout = tier.base + Math.floor(promptLength * tier.perPromptChar); + return Math.min(timeout, Math.max(TIMEOUT - 5000, 10000)); +} + // ── Call claude CLI ───────────────────────────────────────────────────── // On-demand spawning: each request spawns a fresh `claude -p` process. // No pool = no crash loops, no stale workers, no degraded states. @@ -219,10 +294,20 @@ function callClaude(model, messages, conversationId) { if (stats.activeRequests >= MAX_CONCURRENT) { return reject(new Error(`concurrency limit reached (${stats.activeRequests}/${MAX_CONCURRENT})`)); } + + const cliModel = MODEL_MAP[model] || model; + + // Circuit breaker check: fail fast if model is in open state + const breaker = getBreakerState(cliModel); + if (breaker.state === "open") { + const remainingMs = BREAKER_COOLDOWN - (Date.now() - breaker.openedAt); + logEvent("warn", "breaker_rejected", { model: cliModel, remainingCooldownMs: remainingMs }); + return reject(new Error(`circuit breaker open for ${cliModel}: ${breaker.failures} consecutive timeouts, retry in ${Math.ceil(remainingMs / 1000)}s`)); + } + stats.activeRequests++; stats.totalRequests++; - const cliModel = MODEL_MAP[model] || model; let sessionInfo = null; let prompt; @@ -271,6 +356,7 @@ function callClaude(model, messages, conversationId) { let stdout = ""; let stderr = ""; const t0 = Date.now(); + const firstByteTimeoutMs = computeFirstByteTimeout(cliModel, prompt.length); let settled = false; let gotFirstByte = false; @@ -306,13 +392,18 @@ function callClaude(model, messages, conversationId) { }); proc.stderr.on("data", (d) => (stderr += d)); - proc.on("close", (code) => { + proc.on("close", (code, signal) => { const elapsed = Date.now() - t0; + if (settled) { + logEvent("warn", "late_close", { model: cliModel, code, signal: signal || "none", elapsed }); + return; + } if (code !== 0) { - console.error(`[claude] exit=${code} model=${cliModel} elapsed=${elapsed}ms stderr=${stderr.slice(0, 500)}`); + logEvent("error", "claude_exit", { model: cliModel, code, signal: signal || "none", elapsed, stderr: stderr.slice(0, 300) }); settle(new Error(stderr.slice(0, 300) || stdout.slice(0, 300) || `claude exit ${code}`)); } else { - console.log(`[claude] ok model=${cliModel} chars=${stdout.length} elapsed=${elapsed}ms session=${conversationId ? conversationId.slice(0, 12) + "..." : "none"}`); + breakerRecordSuccess(cliModel); + logEvent("info", "claude_ok", { model: cliModel, chars: stdout.length, elapsed, session: conversationId ? conversationId.slice(0, 12) + "..." : "none" }); settle(null, stdout.trim()); } }); @@ -326,24 +417,27 @@ function callClaude(model, messages, conversationId) { proc.stdin.write(prompt); proc.stdin.end(); - console.log(`[claude] spawned model=${cliModel} prompt_chars=${prompt.length} session=${conversationId ? conversationId.slice(0, 12) + "..." : "none"}`); + logEvent("info", "claude_spawned", { model: cliModel, promptChars: prompt.length, firstByteTimeout: firstByteTimeoutMs, tier: getModelTier(cliModel), session: conversationId ? conversationId.slice(0, 12) + "..." : "none" }); // First-byte timeout: abort early if Claude CLI produces no output const firstByteTimer = setTimeout(() => { - if (!gotFirstByte) { + if (!gotFirstByte && !settled) { stats.timeouts++; - console.error(`[claude] first-byte timeout after ${FIRST_BYTE_TIMEOUT}ms model=${cliModel} — aborting`); - proc.kill("SIGTERM"); + breakerRecordTimeout(cliModel); + logEvent("error", "first_byte_timeout", { model: cliModel, timeoutMs: firstByteTimeoutMs, promptChars: prompt.length }); + try { proc.kill("SIGTERM"); } catch {} setTimeout(() => { try { proc.kill("SIGKILL"); } catch {} }, 5000); - settle(new Error(`first-byte timeout after ${FIRST_BYTE_TIMEOUT}ms`)); + settle(new Error(`first-byte timeout after ${firstByteTimeoutMs}ms`)); } - }, FIRST_BYTE_TIMEOUT); + }, firstByteTimeoutMs); // Overall request timeout with graceful kill const timer = setTimeout(() => { + if (settled) return; stats.timeouts++; - console.error(`[claude] timeout after ${TIMEOUT}ms model=${cliModel}`); - proc.kill("SIGTERM"); + breakerRecordTimeout(cliModel); + logEvent("error", "request_timeout", { model: cliModel, timeoutMs: TIMEOUT }); + try { proc.kill("SIGTERM"); } catch {} setTimeout(() => { try { proc.kill("SIGKILL"); } catch {} }, 5000); settle(new Error(`timeout after ${TIMEOUT}ms`)); }, TIMEOUT); @@ -492,7 +586,7 @@ const server = createServer(async (req, res) => { auth: authStatus, config: { timeout: TIMEOUT, - firstByteTimeout: FIRST_BYTE_TIMEOUT, + firstByteTimeout: BASE_FIRST_BYTE_TIMEOUT, maxConcurrent: MAX_CONCURRENT, sessionTTL: SESSION_TTL, allowedTools: SKIP_PERMISSIONS ? "all (skip-permissions)" : ALLOWED_TOOLS, @@ -535,7 +629,7 @@ server.listen(PORT, "0.0.0.0", () => { console.log(`Architecture: on-demand spawning (no pool)`); console.log(`Models: ${MODELS.map((m) => m.id).join(", ")}`); console.log(`Claude binary: ${CLAUDE}`); - console.log(`Timeout: ${TIMEOUT}ms (first-byte: ${FIRST_BYTE_TIMEOUT}ms) | Max concurrent: ${MAX_CONCURRENT}`); + console.log(`Timeout: ${TIMEOUT}ms (base first-byte: ${BASE_FIRST_BYTE_TIMEOUT}ms, adaptive by model/prompt) | Max concurrent: ${MAX_CONCURRENT}`); console.log(`Tools: ${SKIP_PERMISSIONS ? "all (skip-permissions)" : ALLOWED_TOOLS.join(", ")}`); console.log(`Sessions: TTL=${SESSION_TTL / 1000}s`); if (SYSTEM_PROMPT) console.log(`System prompt: "${SYSTEM_PROMPT.slice(0, 80)}..."`); diff --git a/package.json b/package.json index 2d4e5ae..37c6ffd 100644 --- a/package.json +++ b/package.json @@ -1,7 +1,7 @@ { "name": "openclaw-claude-proxy", - "version": "2.3.1", - "description": "OpenAI-compatible proxy for Claude CLI v2 — on-demand sessions, adaptive first-byte timeout, and safer timeout handling", + "version": "2.4.0", + "description": "OpenAI-compatible proxy for Claude CLI v2 — per-model circuit breaker, adaptive first-byte timeout, structured logging", "type": "module", "bin": { "openclaw-claude-proxy": "./server.mjs" diff --git a/server.mjs b/server.mjs index 0aecb35..88339fe 100644 --- a/server.mjs +++ b/server.mjs @@ -1,29 +1,29 @@ #!/usr/bin/env node /** - * openclaw-claude-proxy v2.3.1 — OpenAI-compatible proxy for Claude CLI + * openclaw-claude-proxy v2.4.0 — OpenAI-compatible proxy for Claude CLI * * Translates OpenAI chat/completions requests into `claude -p` CLI calls, * letting you use your Claude Pro/Max subscription as an OpenClaw model provider. * - * v2.0.0 highlights: - * - On-demand spawning: eliminates pool crash loops from v1.x - * - Session management: --resume support reduces token waste on multi-turn - * - Full tool access: configurable allowedTools (expanded defaults) - * - System prompt & MCP config pass-through - * - Concurrency control with queuing - * - Coexists safely with Claude Code interactive mode (Telegram, IDE, etc.) + * v2.4.0: + * - Per-model circuit breaker: consecutive timeouts temporarily mark a model as degraded + * - Adaptive first-byte timeout: scales by model tier + prompt size + * - Structured JSON logging for key events (easier to parse/alert on) + * - On-demand spawning (no pool), session management, full tool access * * Env vars: * CLAUDE_PROXY_PORT — listen port (default: 3456) * CLAUDE_BIN — path to claude binary (default: auto-detect) * CLAUDE_TIMEOUT — per-request timeout in ms (default: 120000) - * CLAUDE_FIRST_BYTE_TIMEOUT — abort if no stdout within this ms (default: 30000) + * CLAUDE_FIRST_BYTE_TIMEOUT — base first-byte timeout in ms (default: 45000) * CLAUDE_ALLOWED_TOOLS — comma-separated tools to allow (default: expanded set) * CLAUDE_SKIP_PERMISSIONS — "true" to bypass all permission checks (default: false) * CLAUDE_SYSTEM_PROMPT — system prompt appended to all requests * CLAUDE_MCP_CONFIG — path to MCP server config JSON file * CLAUDE_SESSION_TTL — session TTL in ms (default: 3600000 = 1h) * CLAUDE_MAX_CONCURRENT — max concurrent claude processes (default: 5) + * CLAUDE_BREAKER_THRESHOLD — consecutive timeouts before circuit opens (default: 3) + * CLAUDE_BREAKER_COOLDOWN — ms to wait before retrying after circuit opens (default: 60000) * PROXY_API_KEY — Bearer token for API auth (optional) */ import { createServer } from "node:http"; @@ -87,10 +87,65 @@ const SYSTEM_PROMPT = process.env.CLAUDE_SYSTEM_PROMPT || ""; const MCP_CONFIG = process.env.CLAUDE_MCP_CONFIG || ""; const SESSION_TTL = parseInt(process.env.CLAUDE_SESSION_TTL || "3600000", 10); const MAX_CONCURRENT = parseInt(process.env.CLAUDE_MAX_CONCURRENT || "5", 10); +const BREAKER_THRESHOLD = parseInt(process.env.CLAUDE_BREAKER_THRESHOLD || "3", 10); +const BREAKER_COOLDOWN = parseInt(process.env.CLAUDE_BREAKER_COOLDOWN || "60000", 10); const VERSION = _pkg.version; const START_TIME = Date.now(); +// ── Structured logging helper ─────────────────────────────────────────── +function logEvent(level, event, data = {}) { + const entry = { ts: new Date().toISOString(), level, event, ...data }; + if (level === "error" || level === "warn") { + console.error(JSON.stringify(entry)); + } else { + console.log(JSON.stringify(entry)); + } +} + +// ── Per-model circuit breaker ─────────────────────────────────────────── +// Tracks consecutive timeouts per model. When threshold is reached, the +// model is marked "open" (degraded) for BREAKER_COOLDOWN ms. During that +// window, requests for this model fail fast with a clear error instead of +// waiting for yet another timeout that would block the gateway. +const breakers = new Map(); // cliModel → { failures, state, openedAt } + +function getBreakerState(cliModel) { + if (!breakers.has(cliModel)) { + breakers.set(cliModel, { failures: 0, state: "closed", openedAt: 0 }); + } + const b = breakers.get(cliModel); + + // Auto-recover: if cooldown has elapsed, transition to half-open + if (b.state === "open" && Date.now() - b.openedAt >= BREAKER_COOLDOWN) { + b.state = "half-open"; + logEvent("info", "breaker_half_open", { model: cliModel, cooldownMs: BREAKER_COOLDOWN }); + } + return b; +} + +function breakerRecordSuccess(cliModel) { + const b = getBreakerState(cliModel); + if (b.failures > 0 || b.state !== "closed") { + logEvent("info", "breaker_reset", { model: cliModel, previousFailures: b.failures, previousState: b.state }); + } + b.failures = 0; + b.state = "closed"; + b.openedAt = 0; +} + +function breakerRecordTimeout(cliModel) { + const b = getBreakerState(cliModel); + b.failures++; + logEvent("warn", "breaker_failure", { model: cliModel, consecutiveFailures: b.failures, threshold: BREAKER_THRESHOLD }); + + if (b.failures >= BREAKER_THRESHOLD && b.state !== "open") { + b.state = "open"; + b.openedAt = Date.now(); + logEvent("error", "breaker_open", { model: cliModel, failures: b.failures, cooldownMs: BREAKER_COOLDOWN }); + } +} + // ── Model mapping ─────────────────────────────────────────────────────── // Maps request model IDs and aliases to canonical claude CLI model IDs. const MODEL_MAP = { @@ -210,13 +265,23 @@ function messagesToPrompt(messages) { }).join("\n\n"); } +// Model tier multipliers for first-byte timeout. +// Opus is much slower to produce first token, especially with large contexts. +const MODEL_TIMEOUT_TIERS = { + "opus": { base: 60000, perPromptChar: 0.00015 }, // 60s base + ~15s per 100k chars + "sonnet": { base: 45000, perPromptChar: 0.00008 }, // 45s base + ~8s per 100k chars + "haiku": { base: 30000, perPromptChar: 0.00005 }, // 30s base + ~5s per 100k chars +}; + +function getModelTier(cliModel) { + if (cliModel.includes("opus")) return "opus"; + if (cliModel.includes("haiku")) return "haiku"; + return "sonnet"; +} + function computeFirstByteTimeout(cliModel, promptLength) { - let timeout = BASE_FIRST_BYTE_TIMEOUT; - - if (cliModel.includes("opus")) timeout += 15000; - if (promptLength >= 120000) timeout += 15000; - if (promptLength >= 200000) timeout += 15000; - + const tier = MODEL_TIMEOUT_TIERS[getModelTier(cliModel)]; + const timeout = tier.base + Math.floor(promptLength * tier.perPromptChar); return Math.min(timeout, Math.max(TIMEOUT - 5000, 10000)); } @@ -229,10 +294,20 @@ function callClaude(model, messages, conversationId) { if (stats.activeRequests >= MAX_CONCURRENT) { return reject(new Error(`concurrency limit reached (${stats.activeRequests}/${MAX_CONCURRENT})`)); } + + const cliModel = MODEL_MAP[model] || model; + + // Circuit breaker check: fail fast if model is in open state + const breaker = getBreakerState(cliModel); + if (breaker.state === "open") { + const remainingMs = BREAKER_COOLDOWN - (Date.now() - breaker.openedAt); + logEvent("warn", "breaker_rejected", { model: cliModel, remainingCooldownMs: remainingMs }); + return reject(new Error(`circuit breaker open for ${cliModel}: ${breaker.failures} consecutive timeouts, retry in ${Math.ceil(remainingMs / 1000)}s`)); + } + stats.activeRequests++; stats.totalRequests++; - const cliModel = MODEL_MAP[model] || model; let sessionInfo = null; let prompt; @@ -320,14 +395,15 @@ function callClaude(model, messages, conversationId) { proc.on("close", (code, signal) => { const elapsed = Date.now() - t0; if (settled) { - console.warn(`[claude] late close ignored model=${cliModel} code=${code} signal=${signal || "none"} elapsed=${elapsed}ms`); + logEvent("warn", "late_close", { model: cliModel, code, signal: signal || "none", elapsed }); return; } if (code !== 0) { - console.error(`[claude] exit=${code} signal=${signal || "none"} model=${cliModel} elapsed=${elapsed}ms stderr=${stderr.slice(0, 500)}`); + logEvent("error", "claude_exit", { model: cliModel, code, signal: signal || "none", elapsed, stderr: stderr.slice(0, 300) }); settle(new Error(stderr.slice(0, 300) || stdout.slice(0, 300) || `claude exit ${code}`)); } else { - console.log(`[claude] ok model=${cliModel} chars=${stdout.length} elapsed=${elapsed}ms session=${conversationId ? conversationId.slice(0, 12) + "..." : "none"}`); + breakerRecordSuccess(cliModel); + logEvent("info", "claude_ok", { model: cliModel, chars: stdout.length, elapsed, session: conversationId ? conversationId.slice(0, 12) + "..." : "none" }); settle(null, stdout.trim()); } }); @@ -341,13 +417,14 @@ function callClaude(model, messages, conversationId) { proc.stdin.write(prompt); proc.stdin.end(); - console.log(`[claude] spawned model=${cliModel} prompt_chars=${prompt.length} first_byte_timeout=${firstByteTimeoutMs}ms session=${conversationId ? conversationId.slice(0, 12) + "..." : "none"}`); + logEvent("info", "claude_spawned", { model: cliModel, promptChars: prompt.length, firstByteTimeout: firstByteTimeoutMs, tier: getModelTier(cliModel), session: conversationId ? conversationId.slice(0, 12) + "..." : "none" }); // First-byte timeout: abort early if Claude CLI produces no output const firstByteTimer = setTimeout(() => { if (!gotFirstByte && !settled) { stats.timeouts++; - console.error(`[claude] first-byte timeout after ${firstByteTimeoutMs}ms model=${cliModel} prompt_chars=${prompt.length} — aborting`); + breakerRecordTimeout(cliModel); + logEvent("error", "first_byte_timeout", { model: cliModel, timeoutMs: firstByteTimeoutMs, promptChars: prompt.length }); try { proc.kill("SIGTERM"); } catch {} setTimeout(() => { try { proc.kill("SIGKILL"); } catch {} }, 5000); settle(new Error(`first-byte timeout after ${firstByteTimeoutMs}ms`)); @@ -358,7 +435,8 @@ function callClaude(model, messages, conversationId) { const timer = setTimeout(() => { if (settled) return; stats.timeouts++; - console.error(`[claude] timeout after ${TIMEOUT}ms model=${cliModel}`); + breakerRecordTimeout(cliModel); + logEvent("error", "request_timeout", { model: cliModel, timeoutMs: TIMEOUT }); try { proc.kill("SIGTERM"); } catch {} setTimeout(() => { try { proc.kill("SIGKILL"); } catch {} }, 5000); settle(new Error(`timeout after ${TIMEOUT}ms`));