refactor(log): unify request lifecycle logging with session-colored tags
Collapse scattered per-request console lines (request/routing/auth/pending/ usage/stream-usage/stream) into 3 correlated lines: request, transform, done. Add stable per-session color tag so concurrent request lines are easy to follow, surface thinking intent, always-on full error logging for debug, re-enable warn level, and uppercase keyword labels. Also fix usage overview cards wrapping (5 cards -> grid-cols-5). Co-authored-by: Cursor <cursoragent@cursor.com>
This commit is contained in:
decolua
@@ -3,7 +3,6 @@ import { translateRequest } from "../translator/index.js";
|
||||
import { stripThinkingSuffix } from "../translator/concerns/thinkingUnified.js";
|
||||
import { FORMATS } from "../translator/formats.js";
|
||||
import { normalizeClaudePassthrough } from "../translator/formats/claude.js";
|
||||
import { COLORS } from "../utils/stream.js";
|
||||
import { createStreamController } from "../utils/streamHandler.js";
|
||||
import { refreshWithRetry } from "../services/tokenRefresh.js";
|
||||
import { createRequestLogger } from "../utils/requestLogger.js";
|
||||
@@ -22,12 +21,14 @@ import { detectClientTool, isNativePassthrough } from "../utils/clientDetector.j
|
||||
import { dedupeTools } from "../utils/toolDeduper.js";
|
||||
import { injectCaveman } from "../rtk/caveman.js";
|
||||
import { injectPonytail } from "../rtk/ponytail.js";
|
||||
import { compressMessages, formatRtkLog } from "../rtk/index.js";
|
||||
import { compressWithHeadroom, formatHeadroomLog, formatHeadroomSizeLog, isHeadroomPhantomSavings } from "../rtk/headroom.js";
|
||||
import { compressWithPxpipe, formatPxpipeLog } from "../rtk/pxpipe.js";
|
||||
import { compressMessages } from "../rtk/index.js";
|
||||
import { compressWithHeadroom, formatHeadroomSizeLog, isHeadroomPhantomSavings } from "../rtk/headroom.js";
|
||||
import { compressWithPxpipe } from "../rtk/pxpipe.js";
|
||||
import { getCapabilitiesForModel } from "../providers/capabilities.js";
|
||||
import { stripUnsupportedModalities } from "../translator/concerns/modality.js";
|
||||
import { prefetchRemoteImages } from "../translator/concerns/prefetch.js";
|
||||
import { extractThinking } from "../translator/concerns/thinkingUnified.js";
|
||||
import { resolveSessionId } from "../utils/sessionManager.js";
|
||||
|
||||
/**
|
||||
* Core chat handler - shared between SSE and Worker
|
||||
@@ -39,6 +40,15 @@ import { prefetchRemoteImages } from "../translator/concerns/prefetch.js";
|
||||
export async function handleChatCore({ body, modelInfo, credentials, log, onCredentialsRefreshed, onRequestSuccess, onDisconnect, clientRawRequest, connectionId, userAgent, apiKey, ccFilterNaming, rtkEnabled, headroomEnabled, headroomUrl, headroomCompressUserMessages, cavemanEnabled, cavemanLevel, ponytailEnabled, ponytailLevel, pxpipeEnabled, pxpipeMinChars, pxpipeTimeoutMs, pxpipeTransform, onPxpipeEvent, sourceFormatOverride, providerThinking }) {
|
||||
const { provider, model } = modelInfo;
|
||||
const requestStartTime = Date.now();
|
||||
// Stable per-session color so all lines of one CLI conversation share a tag
|
||||
const sessionSeed = (() => {
|
||||
try {
|
||||
return resolveSessionId({ headers: clientRawRequest?.headers, body, connectionId, scope: provider });
|
||||
} catch {
|
||||
return connectionId || "";
|
||||
}
|
||||
})();
|
||||
const reqTag = log?.tagForSession ? log.tagForSession(sessionSeed) : (log?.nextTag ? log.nextTag() : "");
|
||||
|
||||
const sourceFormat = sourceFormatOverride || detectFormat(body);
|
||||
|
||||
@@ -152,39 +162,68 @@ export async function handleChatCore({ body, modelInfo, credentials, log, onCred
|
||||
// Covers both passthrough (source shape) and translated (target shape) flows
|
||||
const finalFormat = passthrough ? sourceFormat : targetFormat;
|
||||
|
||||
// Request line: one correlated summary (fmt + thinking + counts + account)
|
||||
if (log?.line) {
|
||||
const clientModel = clientRawRequest?.body?.model || `${provider}/${model}`;
|
||||
const msgN = translatedBody.messages?.length || translatedBody.input?.length || translatedBody.contents?.length || body.messages?.length || body.input?.length || 0;
|
||||
const toolN = translatedBody.tools?.length || body.tools?.length || 0;
|
||||
const fmtStr = passthrough ? `FMT: ${sourceFormat} (passthrough)` : `FMT: ${sourceFormat}→${targetFormat}`;
|
||||
const think = log.fmtThink?.(extractThinking(translatedBody));
|
||||
const acc = credentials?.connectionName || credentials?.connectionId?.slice(0, 8) || "-";
|
||||
const parts = [
|
||||
`POST ${clientModel} → ${provider}/${model}`,
|
||||
fmtStr,
|
||||
stream ? "STREAM" : "JSON",
|
||||
`${msgN} MSG`,
|
||||
];
|
||||
if (toolN) parts.push(`${toolN} TOOL`);
|
||||
if (think) parts.push(`THINK:${think}`);
|
||||
parts.push(`ACC:${acc}`);
|
||||
log.line(reqTag, "▶", parts.join(" · "));
|
||||
}
|
||||
|
||||
// TTS models don't support tool messages/function calling
|
||||
if (getModelType(alias, model) === "tts" && translatedBody.messages) {
|
||||
translatedBody.messages = translatedBody.messages.filter(msg => msg.role !== "tool");
|
||||
delete translatedBody.tools;
|
||||
}
|
||||
|
||||
// Token-saver summary parts, printed as one "⚙" line at the end (only active ones)
|
||||
const xf = [];
|
||||
|
||||
// RTK: compress tool_result content
|
||||
const rtkStats = compressMessages(translatedBody, rtkEnabled);
|
||||
const rtkLine = formatRtkLog(rtkStats);
|
||||
if (rtkLine) console.log(rtkLine);
|
||||
if (rtkStats?.hits?.length) {
|
||||
const saved = rtkStats.bytesBefore - rtkStats.bytesAfter;
|
||||
const pct = rtkStats.bytesBefore > 0 ? ((saved / rtkStats.bytesBefore) * 100).toFixed(0) : "0";
|
||||
xf.push(`RTK −${saved}B(${pct}%)`);
|
||||
}
|
||||
|
||||
// Headroom: optional external proxy compression; fail open if proxy is absent.
|
||||
const headroomDiagnostics = {};
|
||||
const headroomStats = await compressWithHeadroom(translatedBody, { enabled: headroomEnabled, url: headroomUrl, model: upstreamModel, format: finalFormat, compressUserMessages: headroomCompressUserMessages, diagnostics: headroomDiagnostics });
|
||||
const headroomLine = formatHeadroomLog(headroomStats);
|
||||
const headroomSizeLine = formatHeadroomSizeLog(headroomDiagnostics);
|
||||
if (headroomLine) {
|
||||
log?.info?.("HEADROOM", `${headroomLine}${headroomSizeLine ? ` | ${headroomSizeLine}` : ""}`);
|
||||
if (headroomStats) {
|
||||
const before = headroomStats.tokens_before || 0;
|
||||
const delta = headroomStats.tokens_saved || 0;
|
||||
const pct = before > 0 ? ((delta / before) * 100).toFixed(1) : "0";
|
||||
xf.push(`HEADROOM −${delta}tok(${pct}%)`);
|
||||
if (isHeadroomPhantomSavings(headroomStats, headroomDiagnostics)) {
|
||||
log?.warn?.("HEADROOM", `reported token delta, but outbound JSON shrank <5%; provider may bill near-original payload | ${headroomSizeLine}`);
|
||||
log?.warn?.("HEADROOM", `reported token delta, but outbound JSON shrank <5%; provider may bill near-original payload | ${formatHeadroomSizeLog(headroomDiagnostics)}`);
|
||||
}
|
||||
} else if (headroomEnabled) log?.warn?.("HEADROOM", `skipped: ${headroomDiagnostics.reason || "compression unavailable"}${headroomDiagnostics.endpoint ? ` (${headroomDiagnostics.endpoint})` : ""}`);
|
||||
} else if (headroomEnabled) {
|
||||
log?.warn?.("HEADROOM", `skipped: ${headroomDiagnostics.reason || "compression unavailable"}${headroomDiagnostics.endpoint ? ` (${headroomDiagnostics.endpoint})` : ""}`);
|
||||
}
|
||||
|
||||
// Caveman: inject terse-style system prompt
|
||||
if (cavemanEnabled && cavemanLevel) {
|
||||
injectCaveman(translatedBody, finalFormat, cavemanLevel);
|
||||
log?.debug?.("CAVEMAN", `${cavemanLevel} | ${finalFormat}`);
|
||||
xf.push(`CAVEMAN:${cavemanLevel}`);
|
||||
}
|
||||
|
||||
// Ponytail: inject lazy-senior-dev system prompt
|
||||
if (ponytailEnabled && ponytailLevel) {
|
||||
injectPonytail(translatedBody, finalFormat, ponytailLevel);
|
||||
log?.debug?.("PONYTAIL", `${ponytailLevel} | ${finalFormat}`);
|
||||
xf.push(`PONYTAIL:${ponytailLevel}`);
|
||||
}
|
||||
|
||||
// PXPIPE: image bulky context (Claude-format bodies only), last saver before dispatch
|
||||
@@ -196,12 +235,12 @@ export async function handleChatCore({ body, modelInfo, credentials, log, onCred
|
||||
});
|
||||
pxpipeSummary = pxpipeResult.summary;
|
||||
if (pxpipeResult.body) translatedBody = pxpipeResult.body;
|
||||
const pxpipeLine = formatPxpipeLog(pxpipeSummary);
|
||||
if (pxpipeLine) log?.info?.("PXPIPE", pxpipeLine);
|
||||
else log?.debug?.("PXPIPE", `skipped: ${pxpipeSummary.reason}${pxpipeSummary.detail ? ` (${pxpipeSummary.detail})` : ""}`);
|
||||
if (pxpipeSummary?.applied) xf.push(`PXPIPE:${pxpipeSummary.imageCount}img`);
|
||||
try { onPxpipeEvent?.({ provider, model, ...pxpipeSummary }); } catch { /* stats must not break requests */ }
|
||||
}
|
||||
|
||||
if (xf.length && log?.line) log.line(reqTag, "⚙", xf.join(" · "));
|
||||
|
||||
const executor = getExecutor(provider);
|
||||
trackPendingRequest(model, provider, connectionId, true);
|
||||
appendRequestLog({ model, provider, connectionId, status: "PENDING" }).catch(() => { });
|
||||
@@ -215,7 +254,7 @@ export async function handleChatCore({ body, modelInfo, credentials, log, onCred
|
||||
if (onDisconnect) onDisconnect(reason);
|
||||
},
|
||||
onError: () => trackPendingRequest(model, provider, connectionId, false),
|
||||
log, provider, model
|
||||
log, provider, model, reqTag
|
||||
});
|
||||
|
||||
const proxyOptions = {
|
||||
@@ -279,7 +318,9 @@ export async function handleChatCore({ body, modelInfo, credentials, log, onCred
|
||||
return createErrorResult(499, "Request aborted");
|
||||
}
|
||||
const errMsg = formatProviderError(error, provider, model, HTTP_STATUS.BAD_GATEWAY);
|
||||
console.log(`${COLORS.red}[ERROR] ${errMsg}${COLORS.reset}`);
|
||||
if (log?.errorLine) {
|
||||
log.errorLine(reqTag, "✗", `ERROR 502 · ${provider}/${model} · ${Date.now() - requestStartTime}ms\n ${errMsg}${error.stack ? `\n ${error.stack}` : ""}`);
|
||||
}
|
||||
return createErrorResult(HTTP_STATUS.BAD_GATEWAY, errMsg);
|
||||
}
|
||||
|
||||
@@ -288,7 +329,7 @@ export async function handleChatCore({ body, modelInfo, credentials, log, onCred
|
||||
try {
|
||||
const newCredentials = await refreshWithRetry(() => executor.refreshCredentials(credentials, log), 3, log);
|
||||
if (newCredentials?.accessToken || newCredentials?.copilotToken) {
|
||||
log?.info?.("TOKEN", `${provider.toUpperCase()} | refreshed`);
|
||||
if (log?.line) log.line(reqTag, "🔑", `TOKEN REFRESHED · ${provider}/${model}`);
|
||||
Object.assign(credentials, newCredentials);
|
||||
if (onCredentialsRefreshed) {
|
||||
try { await onCredentialsRefreshed(newCredentials); } catch (e) { log?.warn?.("TOKEN", `onCredentialsRefreshed failed: ${e.message}`); }
|
||||
@@ -322,12 +363,15 @@ export async function handleChatCore({ body, modelInfo, credentials, log, onCred
|
||||
})).catch(() => { });
|
||||
|
||||
const errMsg = formatProviderError(new Error(message), provider, model, statusCode);
|
||||
console.log(`${COLORS.red}[ERROR] ${errMsg}${COLORS.reset}`);
|
||||
if (log?.errorLine) {
|
||||
const urlStr = providerUrl ? `\n URL: ${providerUrl}` : "";
|
||||
log.errorLine(reqTag, "✗", `ERROR ${statusCode} · ${provider}/${model} · ${Date.now() - requestStartTime}ms${urlStr}\n ${errMsg}`);
|
||||
}
|
||||
reqLogger.logError(new Error(message), finalBody || translatedBody);
|
||||
return createErrorResult(statusCode, errMsg, resetsAtMs);
|
||||
}
|
||||
|
||||
const sharedCtx = { provider, model, body, stream, translatedBody, finalBody, requestStartTime, connectionId, apiKey, clientRawRequest, onRequestSuccess, pxpipe: pxpipeSummary };
|
||||
const sharedCtx = { provider, model, body, stream, translatedBody, finalBody, requestStartTime, connectionId, apiKey, clientRawRequest, onRequestSuccess, pxpipe: pxpipeSummary, reqTag, log };
|
||||
const appendLog = (extra) => appendRequestLog({ model, provider, connectionId, ...extra }).catch(() => { });
|
||||
const trackDone = () => trackPendingRequest(model, provider, connectionId, false);
|
||||
|
||||
|
||||
Reference in New Issue
Block a user