diff --git a/src/lib/prompt-too-long.ts b/src/lib/prompt-too-long.ts index 05b89aa..2c66dd1 100644 --- a/src/lib/prompt-too-long.ts +++ b/src/lib/prompt-too-long.ts @@ -14,7 +14,8 @@ export function createPromptTooLongError( const modelCaps = state.models?.data.find((m) => m.id === payload.model) ?.capabilities.limits const modelLimit = getModelPromptLimit(payload.model, modelCaps) - const maxOutputTokens = payload.max_tokens ?? 0 + const maxOutputTokens = + payload.max_completion_tokens ?? payload.max_tokens ?? 0 consola.warn( `Context overflow -> returning 400 prompt-too-long (~${estimatedTokens} + ${maxOutputTokens} > ${modelLimit}) to trigger Claude Code reactive compaction`, diff --git a/src/lib/request-log.ts b/src/lib/request-log.ts new file mode 100644 index 0000000..05f7ba1 --- /dev/null +++ b/src/lib/request-log.ts @@ -0,0 +1,477 @@ +import type { Context, MiddlewareHandler } from "hono" + +import consola from "consola" +import { colors } from "consola/utils" + +import { state } from "./state" + +const MAX_JSON_BODY_CHARS = 2_000_000 +const MAX_SSE_LINE_CHARS = 512_000 +const ROUTE_COLUMN_WIDTH = 26 +// Wide enough to distinguish every model this proxy maps to: `claude-sonnet-5` +// and `claude-sonnet-4.6` both truncated to `claude-sonnet…` at 14, which hides +// exactly what translateModelName() decided. +const MODEL_COLUMN_WIDTH = 18 +const EFFORT_COLUMN_WIDTH = 7 +const TOKEN_COLUMN_WIDTH = 4 +const CACHE_COLUMN_WIDTH = 6 + TOKEN_COLUMN_WIDTH + +interface RequestLogMetadata { + effort?: string | null + model?: string | null +} + +interface RequestLogState extends RequestLogMetadata { + cachedTokens?: number + finished: boolean + inputTokens?: number + outputTokens?: number + startedAtMs: number +} + +interface RequestLogSummary extends RequestLogMetadata { + cachedTokens?: number + contextLimit?: number + durationMs: number + error?: string + inputTokens?: number + method: string + outputTokens?: number + path: string + status: number +} + +interface FinishRequestLogOptions { + c: Context + error?: string + requestState: RequestLogState + status: number + writeLog: LogWriter +} + +type LogWriter = (line: string) => void + +/** Control characters (C0, DEL, C1) that could forge log lines or drive a terminal. */ +// eslint-disable-next-line no-control-regex +const CONTROL_CHARACTERS = /[\u0000-\u001F\u007F-\u009F]/g + +const requestLogStates = new WeakMap() + +export function setRequestLogMetadata( + c: Context, + metadata: RequestLogMetadata, +): void { + const requestState = requestLogStates.get(c) + if (!requestState) return + + if (metadata.model !== undefined) requestState.model = metadata.model + if (metadata.effort !== undefined) requestState.effort = metadata.effort +} + +export function createRequestLogMiddleware( + writeLog: LogWriter = (line) => consola.info(line), +): MiddlewareHandler { + return async (c, next) => { + const requestState: RequestLogState = { + finished: false, + startedAtMs: performance.now(), + } + requestLogStates.set(c, requestState) + + try { + await next() + } catch (error) { + finishRequestLog({ + c, + requestState, + status: 500, + writeLog, + error: error instanceof Error ? error.message : "Unknown error", + }) + throw error + } + + const response = c.res + const contentType = response.headers.get("content-type") ?? "" + const isEventStream = contentType.includes("text/event-stream") + + if (!response.body) { + finishRequestLog({ + c, + requestState, + status: response.status, + writeLog, + }) + return + } + + // Non-streaming responses are logged as soon as the handler returns, not + // when their body is drained. A body nobody reads — `HEAD /`, a client that + // hangs up, an internal `app.request()` — would otherwise never reach the + // observer's end-of-stream, and the request would vanish from the log + // entirely. hono/logger logged unconditionally; this preserves that. + if (!isEventStream) { + await collectBufferedMetrics(response, requestState, contentType) + finishRequestLog({ + c, + requestState, + status: response.status, + writeLog, + }) + return + } + + const observer = new ResponseMetricsObserver(requestState, contentType) + const reader = (response.body as ReadableStream).getReader() + const observedBody = new ReadableStream({ + async pull(controller) { + try { + const result = await reader.read() + if (result.done) { + observer.finish() + finishRequestLog({ + c, + requestState, + status: response.status, + writeLog, + }) + controller.close() + return + } + + observer.push(result.value) + controller.enqueue(result.value) + } catch (error) { + observer.finish() + finishRequestLog({ + c, + requestState, + status: response.status, + writeLog, + error: + error instanceof Error ? error.message : "Response stream failed", + }) + controller.error(error) + } + }, + async cancel(reason) { + observer.finish() + finishRequestLog({ + c, + requestState, + status: response.status, + writeLog, + }) + await reader.cancel(reason) + }, + }) + + c.res = new Response(observedBody, { + status: response.status, + statusText: response.statusText, + headers: response.headers, + }) + } +} + +export const requestLogMiddleware = createRequestLogMiddleware() + +/** + * Read usage counts out of an already-buffered response. Cloning is cheap here + * because the body is fully in memory by the time the handler has returned, and + * it leaves the original untouched for the client. + */ +async function collectBufferedMetrics( + response: Response, + requestState: RequestLogState, + contentType: string, +): Promise { + try { + const body = await response.clone().text() + if (!body) return + + const observer = new ResponseMetricsObserver(requestState, contentType) + observer.pushText(body) + observer.finish() + } catch (readError) { + consola.debug("Failed to read response body for metrics:", readError) + } +} + +export function formatRequestLogLine(summary: RequestLogSummary): string { + const request = `${summary.method} ${summary.path}` + const segments = [ + ` --> ${padColumn(request, ROUTE_COLUMN_WIDTH)} ${formatStatus(summary.status)}`, + ] + + if (summary.model) { + const effort = + summary.effort ? + padColumn(summary.effort, EFFORT_COLUMN_WIDTH) + : " ".repeat(EFFORT_COLUMN_WIDTH) + segments.push( + `${colors.cyan(padColumn(summary.model, MODEL_COLUMN_WIDTH))} ${colors.magenta(effort)}`, + ) + } + + if (summary.inputTokens !== undefined || summary.outputTokens !== undefined) { + const cache = + (summary.cachedTokens ?? 0) > 0 ? + colors.yellow(`cache ${formatTokenColumn(summary.cachedTokens)}`) + : " ".repeat(CACHE_COLUMN_WIDTH) + segments.push( + `tokens ↑ ${colors.cyan(formatTokenColumn(summary.inputTokens))} ${cache} ↓ ${colors.green(formatTokenColumn(summary.outputTokens))}`, + ) + } + + if (summary.inputTokens !== undefined) { + const context = + summary.contextLimit ? + `${formatTokens(summary.inputTokens)}/${formatTokens(summary.contextLimit)} (${Math.round((summary.inputTokens / summary.contextLimit) * 100)}%)` + : formatTokens(summary.inputTokens) + segments.push(`context ${colors.dim(context)}`) + } + + const e2e = formatDuration(summary.durationMs) + segments.push(`total ${colors.green(e2e)}`) + + if (summary.error) segments.push(colors.red(summary.error)) + return segments.join(" │ ") +} + +class ResponseMetricsObserver { + private readonly decoder = new TextDecoder() + private readonly isEventStream: boolean + private readonly requestState: RequestLogState + private jsonBody = "" + private sseBuffer = "" + private skippingOversizedLine = false + + constructor(requestState: RequestLogState, contentType: string) { + this.requestState = requestState + this.isEventStream = contentType.includes("text/event-stream") + } + + push(chunk: Uint8Array): void { + const text = this.decoder.decode(chunk, { stream: true }) + if (this.isEventStream) { + this.pushSSEText(text) + return + } + + this.pushText(text) + } + + /** + * Feed already-decoded text. Non-streaming responses take this path: their + * body is read once, in full, after the handler returns, so there is nothing + * to accumulate across chunks. + */ + pushText(text: string): void { + if (this.isEventStream) { + this.pushSSEText(text) + return + } + + const remaining = MAX_JSON_BODY_CHARS - this.jsonBody.length + if (remaining > 0) this.jsonBody += text.slice(0, remaining) + } + + finish(): void { + const finalText = this.decoder.decode() + if (this.isEventStream) { + this.pushSSEText(finalText + "\n") + return + } + + const remaining = MAX_JSON_BODY_CHARS - this.jsonBody.length + if (remaining > 0) this.jsonBody += finalText.slice(0, remaining) + if (!this.jsonBody) return + + try { + mergeResponseMetrics( + this.requestState, + JSON.parse(this.jsonBody) as unknown, + ) + } catch { + // Non-JSON error responses still receive a basic request log line. + } + } + + private pushSSEText(text: string): void { + let remainingText = text + if (this.skippingOversizedLine) { + const newlineIndex = remainingText.indexOf("\n") + if (newlineIndex === -1) return + this.skippingOversizedLine = false + remainingText = remainingText.slice(newlineIndex + 1) + } + + this.sseBuffer += remainingText + let newlineIndex = this.sseBuffer.indexOf("\n") + while (newlineIndex !== -1) { + const line = this.sseBuffer.slice(0, newlineIndex).replace(/\r$/, "") + this.sseBuffer = this.sseBuffer.slice(newlineIndex + 1) + this.processSSELine(line) + newlineIndex = this.sseBuffer.indexOf("\n") + } + + if (this.sseBuffer.length > MAX_SSE_LINE_CHARS) { + this.sseBuffer = "" + this.skippingOversizedLine = true + } + } + + private processSSELine(line: string): void { + if (!line.startsWith("data:")) return + const data = line.slice(5).trimStart() + if (!data || data === "[DONE]" || data.length > MAX_SSE_LINE_CHARS) return + + try { + mergeResponseMetrics(this.requestState, JSON.parse(data) as unknown) + } catch { + // Ignore malformed or non-JSON SSE data while preserving the stream. + } + } +} + +function mergeResponseMetrics( + requestState: RequestLogState, + value: unknown, +): void { + if (!isRecord(value)) return + + for (const container of [ + value, + isRecord(value.response) ? value.response : undefined, + isRecord(value.message) ? value.message : undefined, + ]) { + if (!container || !isRecord(container.usage)) continue + mergeUsage(requestState, container.usage) + } +} + +function mergeUsage( + requestState: RequestLogState, + usage: Record, +): void { + const cacheRead = numberValue(usage.cache_read_input_tokens) + const cacheCreation = numberValue(usage.cache_creation_input_tokens) + const input = + numberValue(usage.prompt_tokens) ?? numberValue(usage.input_tokens) + const output = + numberValue(usage.completion_tokens) ?? numberValue(usage.output_tokens) + const cached = + cacheRead + ?? nestedNumberValue(usage.prompt_tokens_details, "cached_tokens") + ?? nestedNumberValue(usage.input_tokens_details, "cached_tokens") + + if (input !== undefined) { + const inputExcludesCachedTokens = + usage.prompt_tokens === undefined + && (cacheRead !== undefined || cacheCreation !== undefined) + requestState.inputTokens = + inputExcludesCachedTokens ? + input + (cacheRead ?? 0) + (cacheCreation ?? 0) + : input + } + if (output !== undefined) requestState.outputTokens = output + if (cached !== undefined) requestState.cachedTokens = cached +} + +function finishRequestLog(options: FinishRequestLogOptions): void { + const { c, error, requestState, status, writeLog } = options + if (requestState.finished) return + requestState.finished = true + + const endedAtMs = performance.now() + + // Observability must never be able to break request handling. Callers run + // inside the response-body observer, where a throw would error the stream + // and hand the client a truncated body instead of its response. + try { + const contextLimit = state.models?.data.find( + (model) => model.id === requestState.model, + )?.capabilities.limits.max_context_window_tokens + + writeLog( + formatRequestLogLine({ + method: c.req.method, + path: c.req.path, + status, + model: requestState.model, + effort: requestState.effort, + inputTokens: requestState.inputTokens, + outputTokens: requestState.outputTokens, + cachedTokens: requestState.cachedTokens, + contextLimit, + durationMs: endedAtMs - requestState.startedAtMs, + error, + }), + ) + } catch (logError) { + consola.debug("Failed to write request log line:", logError) + } +} + +function nestedNumberValue(value: unknown, key: string): number | undefined { + return isRecord(value) ? numberValue(value[key]) : undefined +} + +function numberValue(value: unknown): number | undefined { + return typeof value === "number" && Number.isFinite(value) ? value : undefined +} + +function isRecord(value: unknown): value is Record { + return typeof value === "object" && value !== null +} + +/** + * Render an untrusted string into a fixed-width column. + * + * `model` and `effort` arrive from client JSON that is only structurally typed + * by a `c.req.json()` cast, so at runtime they can be any JSON value. Three + * things have to hold regardless of what a client sends: + * + * - Non-strings must not throw. An exception here escapes through the + * response-body observer and destroys the client's response. + * - Control characters must not survive. A newline would let a caller forge + * an extra log line; an ESC would let it repaint the operator's terminal. + * - Width is bounded by the column, so a huge string cannot flood the log. + */ +function padColumn(value: unknown, width: number): string { + const text = typeof value === "string" ? value : String(value) + const safe = text.replaceAll(CONTROL_CHARACTERS, "\u00b7") + if (safe.length <= width) return safe.padEnd(width) + return `${safe.slice(0, Math.max(1, width - 1))}…` +} + +function formatStatus(status: number): string { + const value = String(status).padStart(3) + if (status >= 500) return colors.red(value) + if (status >= 400) return colors.yellow(value) + if (status >= 300) return colors.cyan(value) + return colors.green(value) +} + +function formatTokenColumn(value: number | undefined): string { + return (value === undefined ? "—" : formatTokens(value)).padStart( + TOKEN_COLUMN_WIDTH, + ) +} + +function formatTokens(value: number): string { + if (value >= 1_000_000) return `${formatCompactNumber(value / 1_000_000)}M` + if (value >= 1_000) return `${formatCompactNumber(value / 1_000)}K` + return Math.round(value).toString() +} + +function formatCompactNumber(value: number): string { + if (Number.isInteger(value)) return value.toString() + return value >= 10 ? Math.round(value).toString() : value.toFixed(1) +} + +function formatDuration(value: number): string { + if (value >= 1_000) return `${(value / 1_000).toFixed(1)}s` + return `${Math.max(0, Math.round(value))}ms` +} diff --git a/src/routes/chat-completions/handler.ts b/src/routes/chat-completions/handler.ts index d9aba82..355c061 100644 --- a/src/routes/chat-completions/handler.ts +++ b/src/routes/chat-completions/handler.ts @@ -5,6 +5,7 @@ import { streamSSE, type SSEMessage } from "hono/streaming" import { awaitApproval } from "~/lib/approval" import { checkRateLimit } from "~/lib/rate-limit" +import { setRequestLogMetadata } from "~/lib/request-log" import { state } from "~/lib/state" import { getTokenCount } from "~/lib/tokenizer" import { isNullish } from "~/lib/utils" @@ -19,6 +20,10 @@ export async function handleCompletion(c: Context) { let payload = await c.req.json() consola.debug("Request payload:", JSON.stringify(payload).slice(-400)) + setRequestLogMetadata(c, { + model: payload.model, + effort: payload.reasoning_effort, + }) // Find the selected model const selectedModel = state.models?.data.find( @@ -29,7 +34,7 @@ export async function handleCompletion(c: Context) { try { if (selectedModel) { const tokenCount = await getTokenCount(payload, selectedModel) - consola.info("Current token count:", tokenCount) + consola.debug("Current token count:", tokenCount) } else { consola.warn("No model selected, skipping token count calculation") } @@ -39,7 +44,10 @@ export async function handleCompletion(c: Context) { if (state.manualApprove) await awaitApproval() - if (isNullish(payload.max_tokens)) { + if ( + isNullish(payload.max_tokens) + && isNullish(payload.max_completion_tokens) + ) { payload = { ...payload, max_tokens: selectedModel?.capabilities.limits.max_output_tokens, diff --git a/src/routes/embeddings/route.ts b/src/routes/embeddings/route.ts index 982bdf5..6d32117 100644 --- a/src/routes/embeddings/route.ts +++ b/src/routes/embeddings/route.ts @@ -1,6 +1,7 @@ import { Hono } from "hono" import { forwardError } from "~/lib/error" +import { setRequestLogMetadata } from "~/lib/request-log" import { createEmbeddings, type EmbeddingRequest, @@ -11,6 +12,7 @@ export const embeddingRoutes = new Hono() embeddingRoutes.post("/", async (c) => { try { const payload = await c.req.json() + setRequestLogMetadata(c, { model: payload.model }) const response = await createEmbeddings(payload) return c.json(response) diff --git a/src/routes/messages/count-tokens-handler.ts b/src/routes/messages/count-tokens-handler.ts index acfdc9b..3560271 100644 --- a/src/routes/messages/count-tokens-handler.ts +++ b/src/routes/messages/count-tokens-handler.ts @@ -2,6 +2,7 @@ import type { Context } from "hono" import consola from "consola" +import { setRequestLogMetadata } from "~/lib/request-log" import { state } from "~/lib/state" import { getTokenCount } from "~/lib/tokenizer" @@ -18,6 +19,7 @@ export async function handleCountTokens(c: Context) { const anthropicPayload = await c.req.json() const openAIPayload = translateToOpenAI(anthropicPayload) + setRequestLogMetadata(c, { model: openAIPayload.model }) const selectedModel = state.models?.data.find( (model) => model.id === openAIPayload.model, @@ -67,7 +69,7 @@ export async function handleCountTokens(c: Context) { finalTokenCount = Math.round(finalTokenCount * 1.03) } - consola.info("Token count:", finalTokenCount) + consola.debug("Token count:", finalTokenCount) return c.json({ input_tokens: finalTokenCount, diff --git a/src/routes/messages/handler.ts b/src/routes/messages/handler.ts index a7edd6e..5f258da 100644 --- a/src/routes/messages/handler.ts +++ b/src/routes/messages/handler.ts @@ -15,6 +15,7 @@ import { import { HTTPError } from "~/lib/error" import { createPromptTooLongError } from "~/lib/prompt-too-long" import { checkRateLimit } from "~/lib/rate-limit" +import { setRequestLogMetadata } from "~/lib/request-log" import { state } from "~/lib/state" import { createChatCompletions, @@ -102,6 +103,11 @@ export async function handleCompletion(c: Context) { // Async preprocessing: PDF document block extraction, etc. const preprocessed = await preprocessAnthropicPayload(anthropicPayload) const openAIPayload = translateToOpenAI(preprocessed) + setRequestLogMetadata(c, { + model: openAIPayload.model, + effort: + openAIPayload.reasoning_effort ?? preprocessed.output_config?.effort, + }) const model = state.models?.data.find((m) => m.id === openAIPayload.model) if (shouldUseResponsesForMessages(model)) { diff --git a/src/routes/messages/responses-bridge.ts b/src/routes/messages/responses-bridge.ts index d26ea0e..3c11adc 100644 --- a/src/routes/messages/responses-bridge.ts +++ b/src/routes/messages/responses-bridge.ts @@ -33,6 +33,10 @@ export function translateAnthropicMessagesToResponses( model, input: payload.messages.flatMap((message) => translateMessage(message)), instructions: translateSystem(payload.system), + // Forwarded verbatim. Silently raising a client's cap to a floor the proxy + // guesses upstream wants leaves the caller unable to reason about what it + // asked for; if Copilot rejects a small value, that rejection is the honest + // answer and reaches the client intact. max_output_tokens: payload.max_tokens, temperature: payload.temperature, top_p: payload.top_p, @@ -43,6 +47,10 @@ export function translateAnthropicMessagesToResponses( name: tool.name, description: tool.description, parameters: tool.input_schema, + // Anthropic tools allow optional and action-dependent fields. Copilot + // Responses defaults omitted strictness to true and rewrites every + // property as required, which makes multiplexed MCP schemas unusable. + strict: false, })), tool_choice: translateToolChoice(payload.tool_choice), } @@ -58,6 +66,7 @@ export function translateResponsesToAnthropicMessage( const hitMaxTokens = response.status === "incomplete" && response.incomplete_details?.reason === "max_output_tokens" + const cachedTokens = response.usage?.input_tokens_details?.cached_tokens ?? 0 return { id: response.id, @@ -68,8 +77,12 @@ export function translateResponsesToAnthropicMessage( stop_reason: hitMaxTokens ? "max_tokens" : contentStopReason, stop_sequence: null, usage: { - input_tokens: response.usage?.input_tokens ?? 0, + input_tokens: Math.max( + 0, + (response.usage?.input_tokens ?? 0) - cachedTokens, + ), output_tokens: response.usage?.output_tokens ?? 0, + ...(cachedTokens > 0 ? { cache_read_input_tokens: cachedTokens } : {}), }, } } diff --git a/src/routes/responses/handler.ts b/src/routes/responses/handler.ts index 88b75ad..ac630a3 100644 --- a/src/routes/responses/handler.ts +++ b/src/routes/responses/handler.ts @@ -4,6 +4,7 @@ import consola from "consola" import { awaitApproval } from "~/lib/approval" import { checkRateLimit } from "~/lib/rate-limit" +import { setRequestLogMetadata } from "~/lib/request-log" import { state } from "~/lib/state" import { createResponses } from "~/services/copilot/create-responses" @@ -14,6 +15,10 @@ export async function handleResponses(c: Context): Promise { const request = await c.req.json() consola.debug("Responses API request:", JSON.stringify(request).slice(-400)) + setRequestLogMetadata(c, { + model: request.model, + effort: request.reasoning?.effort, + }) if (state.manualApprove) await awaitApproval() diff --git a/src/routes/responses/types.ts b/src/routes/responses/types.ts index 660ba9f..094cf91 100644 --- a/src/routes/responses/types.ts +++ b/src/routes/responses/types.ts @@ -141,6 +141,9 @@ export interface ResponsesUsage { input_tokens: number output_tokens: number total_tokens: number + input_tokens_details?: { + cached_tokens?: number + } } export interface ResponsesOutputItem { diff --git a/src/server.ts b/src/server.ts index 0e3762f..cd21bdb 100644 --- a/src/server.ts +++ b/src/server.ts @@ -1,8 +1,8 @@ import { Hono } from "hono" import { cors } from "hono/cors" -import { logger } from "hono/logger" import { optionalLocalAuth } from "./lib/local-auth" +import { requestLogMiddleware } from "./lib/request-log" import { requestTraceMiddleware } from "./lib/request-trace" import { completionRoutes } from "./routes/chat-completions/route" import { debugRoutes } from "./routes/debug/route" @@ -15,7 +15,7 @@ import { usageRoute } from "./routes/usage/route" export const server = new Hono() -server.use(logger()) +server.use(requestLogMiddleware) server.use(cors()) server.use(requestTraceMiddleware) diff --git a/src/services/copilot/create-chat-completions.ts b/src/services/copilot/create-chat-completions.ts index ee2ccde..d78dcec 100644 --- a/src/services/copilot/create-chat-completions.ts +++ b/src/services/copilot/create-chat-completions.ts @@ -16,14 +16,16 @@ export const createChatCompletions = async ( ) => { if (!state.copilotToken) throw new Error("Copilot token not found") - const enableVision = payload.messages.some( + const requestPayload = normalizeTokenLimitParameter(payload) + + const enableVision = requestPayload.messages.some( (x) => typeof x.content !== "string" && x.content?.some((x) => x.type === "image_url"), ) // Agent/user check for X-Initiator header - const isAgentCall = payload.messages.some((msg) => + const isAgentCall = requestPayload.messages.some((msg) => ["assistant", "tool"].includes(msg.role), ) @@ -32,9 +34,9 @@ export const createChatCompletions = async ( "X-Initiator": isAgentCall ? "agent" : "user", } - const body = JSON.stringify(payload) - consola.info( - `Sending payload: ${body.length} bytes, ${payload.messages.length} messages, model: ${payload.model}`, + const body = JSON.stringify(requestPayload) + consola.debug( + `Sending payload: ${body.length} bytes, ${requestPayload.messages.length} messages, model: ${requestPayload.model}`, ) let response: Response @@ -46,7 +48,7 @@ export const createChatCompletions = async ( }) } catch (error) { if (isLikelyContextOverflowTimeout(error, body.length)) { - throw createPromptTooLongError(payload, body.length) + throw createPromptTooLongError(requestPayload, body.length) } throw error } @@ -92,7 +94,7 @@ export const createChatCompletions = async ( // 168K for opus-4.7) rather than max_context_window_tokens (the // total window incl. output, ≥200K). Falling back to the larger field // and finally 200K preserves behavior for models lacking metadata. - throw createPromptTooLongError(payload, body.length) + throw createPromptTooLongError(requestPayload, body.length) } throw new HTTPError( @@ -196,6 +198,7 @@ export interface ChatCompletionsPayload { temperature?: number | null top_p?: number | null max_tokens?: number | null + max_completion_tokens?: number | null stop?: string | Array | null n?: number | null stream?: boolean | null @@ -218,6 +221,36 @@ export interface ChatCompletionsPayload { user?: string | null } +const MAX_COMPLETION_TOKENS_MODEL_PATTERN = + /^(?:gpt-5(?:[.-]|$)|o\d+(?:[.-]|$))/i + +function normalizeTokenLimitParameter( + payload: ChatCompletionsPayload, +): ChatCompletionsPayload { + const modelFamily = state.models?.data.find( + (model) => model.id === payload.model, + )?.capabilities.family + const requiresMaxCompletionTokens = [payload.model, modelFamily].some( + (model) => + model !== undefined && MAX_COMPLETION_TOKENS_MODEL_PATTERN.test(model), + ) + + if (!requiresMaxCompletionTokens) return payload + + const normalized = { ...payload } + const maxTokens = normalized.max_tokens + delete normalized.max_tokens + + if ( + normalized.max_completion_tokens === undefined + || normalized.max_completion_tokens === null + ) { + normalized.max_completion_tokens = maxTokens + } + + return normalized +} + export interface Tool { type: "function" function: { diff --git a/src/services/copilot/create-responses.ts b/src/services/copilot/create-responses.ts index 8eb1596..cb5fd1e 100644 --- a/src/services/copilot/create-responses.ts +++ b/src/services/copilot/create-responses.ts @@ -73,7 +73,7 @@ export async function createResponses( } const bodyLength = JSON.stringify(upstreamPayload).length - consola.info( + consola.debug( `Sending responses payload: ${bodyLength} bytes, model: ${payload.model}`, ) diff --git a/src/start.ts b/src/start.ts index f6e30e7..b6b6998 100644 --- a/src/start.ts +++ b/src/start.ts @@ -68,7 +68,7 @@ export async function runServer(options: RunServerOptions): Promise { await setupCopilotToken() await cacheModels() - consola.info( + consola.debug( `Available models: \n${state.models?.data.map((model) => `- ${model.id}`).join("\n")}`, ) @@ -118,7 +118,7 @@ export async function runServer(options: RunServerOptions): Promise { } } - consola.box( + consola.debug( `🌐 Usage Viewer: https://voidsteed.github.io/copilot-proxy-api/dashboard.html?endpoint=${serverUrl}/usage`, ) @@ -132,6 +132,10 @@ export async function runServer(options: RunServerOptions): Promise { // as "API Error: The socket connection was closed unexpectedly". bun: { idleTimeout: 0 }, }) + + consola.success( + `Ready — ${state.models?.data.length ?? 0} models available. Point your client at ${serverUrl}`, + ) } export const start = defineCommand({ diff --git a/tests/create-chat-completions.test.ts b/tests/create-chat-completions.test.ts index 7f14f7e..36fa945 100644 --- a/tests/create-chat-completions.test.ts +++ b/tests/create-chat-completions.test.ts @@ -16,7 +16,10 @@ state.accountType = "individual" function mockSuccessfulFetch() { const fetchMock = mock( - (_url: string, opts: { headers: Record }) => { + ( + _url: string, + opts: { body?: unknown; headers: Record }, + ) => { return { ok: true, json: () => ({ id: "123", object: "chat.completion", choices: [] }), @@ -62,6 +65,38 @@ test("sets X-Initiator to user if only user present", async () => { expect(headers["X-Initiator"]).toBe("user") }) +test("uses max_completion_tokens for GPT-5 models", async () => { + const fetchMock = mockSuccessfulFetch() + + await createChatCompletions({ + messages: [{ role: "user", content: "hi" }], + model: "gpt-5.4", + max_tokens: 123, + }) + + const body = JSON.parse( + fetchMock.mock.calls[0][1].body as string, + ) as ChatCompletionsPayload + expect(body.max_completion_tokens).toBe(123) + expect(body).not.toHaveProperty("max_tokens") +}) + +test("keeps max_tokens for legacy chat completion models", async () => { + const fetchMock = mockSuccessfulFetch() + + await createChatCompletions({ + messages: [{ role: "user", content: "hi" }], + model: "gpt-4o", + max_tokens: 123, + }) + + const body = JSON.parse( + fetchMock.mock.calls[0][1].body as string, + ) as ChatCompletionsPayload + expect(body.max_tokens).toBe(123) + expect(body).not.toHaveProperty("max_completion_tokens") +}) + test("large upstream timeout becomes prompt-too-long error", async () => { const timeoutFetchMock = mock(() => { throw new Error("The operation timed out.") diff --git a/tests/messages-responses-bridge.test.ts b/tests/messages-responses-bridge.test.ts index 2729220..cb8dac6 100644 --- a/tests/messages-responses-bridge.test.ts +++ b/tests/messages-responses-bridge.test.ts @@ -12,6 +12,27 @@ state.copilotToken = "test-token" state.vsCodeVersion = "1.0.0" state.accountType = "individual" +const notebookToolSchema = { + type: "object", + properties: { + action: { type: "string" }, + notebookUri: { type: "string" }, + }, + required: ["action", "notebookUri"], +} + +const anthropicNotebookTool = { + name: "fabric_notebook_content", + input_schema: notebookToolSchema, +} + +const responsesNotebookTool = { + type: "function", + name: "fabric_notebook_content", + strict: false, + parameters: notebookToolSchema, +} + afterEach(() => { mock.restore() state.models = undefined @@ -188,6 +209,7 @@ describe("Messages Responses bridge", () => { input: [{ role: "user", content: "hello" }], max_output_tokens: 100, stream: false, + tools: [responsesNotebookTool], }) return new Response( @@ -206,7 +228,12 @@ describe("Messages Responses bridge", () => { }, ], output_text: "bridged", - usage: { input_tokens: 1, output_tokens: 1, total_tokens: 2 }, + usage: { + input_tokens: 10, + output_tokens: 1, + total_tokens: 11, + input_tokens_details: { cached_tokens: 4 }, + }, status: "completed", }), { status: 200, headers: { "content-type": "application/json" } }, @@ -220,6 +247,7 @@ describe("Messages Responses bridge", () => { model: "gpt-5.5", max_tokens: 100, messages: [{ role: "user", content: "hello" }], + tools: [anthropicNotebookTool], }), headers: { "content-type": "application/json" }, }) @@ -230,6 +258,11 @@ describe("Messages Responses bridge", () => { model: "gpt-5.5", content: [{ type: "text", text: "bridged" }], stop_reason: "end_turn", + usage: { + input_tokens: 6, + output_tokens: 1, + cache_read_input_tokens: 4, + }, }) expect(fetchMock).toHaveBeenCalledTimes(1) }) diff --git a/tests/request-log.test.ts b/tests/request-log.test.ts new file mode 100644 index 0000000..fa52677 --- /dev/null +++ b/tests/request-log.test.ts @@ -0,0 +1,217 @@ +import { afterEach, describe, expect, test } from "bun:test" +import { stripAnsi } from "consola/utils" +import { Hono } from "hono" + +import { + createRequestLogMiddleware, + setRequestLogMetadata, +} from "~/lib/request-log" +import { state } from "~/lib/state" + +afterEach(() => { + state.models = undefined +}) + +function setModel(model: string, contextLimit = 1_000_000): void { + state.models = { + object: "list", + data: [ + { + id: model, + object: "model", + name: model, + model_picker_enabled: true, + preview: false, + vendor: "openai", + version: "1", + capabilities: { + family: model, + limits: { max_context_window_tokens: contextLimit }, + object: "model_capabilities", + supports: {}, + tokenizer: "o200k_base", + type: "chat", + }, + }, + ], + } +} + +describe("requestLogMiddleware", () => { + test("formats JSON response usage as a compact request summary", async () => { + setModel("gpt-5.5") + const logs: Array = [] + const app = new Hono() + app.use(createRequestLogMiddleware((line) => logs.push(line))) + app.post("/v1/responses", (c) => { + setRequestLogMetadata(c, { model: "gpt-5.5", effort: "medium" }) + return c.json({ + usage: { + input_tokens: 12_000, + output_tokens: 365, + total_tokens: 12_365, + input_tokens_details: { cached_tokens: 8_000 }, + }, + }) + }) + + const response = await app.request("/v1/responses", { method: "POST" }) + await response.text() + + expect(logs).toHaveLength(1) + const line = stripAnsi(logs[0] ?? "") + expect(line).toContain("--> POST /v1/responses") + expect(line).toContain("200") + expect(line).toMatch(/gpt-5\.5\s+medium/) + expect(line).not.toContain("effort") + expect(line).toContain("tokens ↑ 12K cache 8K ↓ 365") + expect(line).toContain("context 12K/1M (1%)") + expect(line).not.toContain("first-token") + expect(line).toContain("total") + }) + + test("extracts usage from SSE responses", async () => { + setModel("gpt-5.6-luna") + const logs: Array = [] + const app = new Hono() + app.use(createRequestLogMiddleware((line) => logs.push(line))) + app.get("/v1/responses", (c) => { + setRequestLogMetadata(c, { model: "gpt-5.6-luna", effort: "low" }) + return new Response( + [ + `data: ${JSON.stringify({ + type: "response.output_text.delta", + delta: "OK", + })}`, + `data: ${JSON.stringify({ + type: "response.completed", + response: { + usage: { + input_tokens: 11_000, + output_tokens: 27, + total_tokens: 11_027, + }, + }, + })}`, + "data: [DONE]", + "", + ].join("\n\n"), + { headers: { "content-type": "text/event-stream" } }, + ) + }) + + const response = await app.request("/v1/responses") + await response.text() + + expect(logs).toHaveLength(1) + const line = stripAnsi(logs[0] ?? "") + expect(line).toMatch(/gpt-5\.6-luna\s+low/) + expect(line).not.toContain("effort") + expect(line).toContain("tokens ↑ 11K ↓ 27") + expect(line).not.toContain("first-token") + expect(line).toContain("total") + }) +}) + +describe("requestLogMiddleware hardening", () => { + test("logs requests whose response body is never read", async () => { + const logs: Array = [] + const app = new Hono() + app.use(createRequestLogMiddleware((line) => logs.push(line))) + app.get("/", (c) => c.text("Server running")) + + // HEAD discards the body, so an observer that only fires at end-of-stream + // never runs. hono/logger logged this unconditionally. + await app.request("/", { method: "HEAD" }) + + expect(logs).toHaveLength(1) + expect(stripAnsi(logs[0] ?? "")).toContain("HEAD /") + }) + + test("non-string metadata cannot break the response body", async () => { + const logs: Array = [] + const app = new Hono() + app.use(createRequestLogMiddleware((line) => logs.push(line))) + app.post("/v1/responses", (c) => { + // `reasoning.effort` is only structurally typed by a c.req.json() + // cast, so a client can put any JSON value here. + setRequestLogMetadata(c, { + model: 5.5 as unknown as string, + effort: 123 as unknown as string, + }) + return c.json({ error: { message: "upstream 400" } }, 400) + }) + + const response = await app.request("/v1/responses", { method: "POST" }) + const body = await response.text() + + expect(response.status).toBe(400) + expect(body).toContain("upstream 400") + expect(logs).toHaveLength(1) + }) + + test("control characters in metadata cannot forge a log line", async () => { + const logs: Array = [] + const app = new Hono() + app.use(createRequestLogMiddleware((line) => logs.push(line))) + app.post("/v1/messages", (c) => { + setRequestLogMetadata(c, { + model: "evil\n --> GET /admin 200 | FORGED", + }) + return c.json({}) + }) + + await (await app.request("/v1/messages", { method: "POST" })).text() + + const line = stripAnsi(logs[0] ?? "") + expect(logs).toHaveLength(1) + expect(line).not.toContain("FORGED") + expect(line).not.toContain("\n") + }) + + test("escape sequences in metadata cannot drive the terminal", async () => { + const logs: Array = [] + const escape = String.fromCodePoint(27) + const app = new Hono() + app.use(createRequestLogMiddleware((line) => logs.push(line))) + app.post("/m", (c) => { + setRequestLogMetadata(c, { model: `${escape}[2J${escape}[1;31mPWNED` }) + return c.json({}) + }) + + await (await app.request("/m", { method: "POST" })).text() + + // colors.cyan() adds its own escapes, so assert on the interpolated value. + expect(logs[0] ?? "").not.toContain(`${escape}[2J`) + }) + + test("distinguishes model names that differ only by version", async () => { + const rendered: Array = [] + for (const model of ["claude-sonnet-5", "claude-sonnet-4.6"]) { + const logs: Array = [] + const app = new Hono() + app.use(createRequestLogMiddleware((line) => logs.push(line))) + app.post("/m", (c) => { + setRequestLogMetadata(c, { model }) + return c.json({}) + }) + await (await app.request("/m", { method: "POST" })).text() + rendered.push(stripAnsi(logs[0] ?? "")) + } + + expect(rendered[0]).toContain("claude-sonnet-5") + expect(rendered[1]).toContain("claude-sonnet-4.6") + expect(rendered[0]).not.toEqual(rendered[1]) + }) + + test("does not leak response body contents into the log line", async () => { + const logs: Array = [] + const app = new Hono() + app.use(createRequestLogMiddleware((line) => logs.push(line))) + app.get("/token", (c) => c.json({ token: "tid=SECRET_VALUE;exp=1" })) + + await (await app.request("/token")).text() + + expect(stripAnsi(logs[0] ?? "")).not.toContain("SECRET_VALUE") + }) +})