From f054fe9a211501bf763d17e1bf7f7a89e2c2a98e Mon Sep 17 00:00:00 2001 From: "haozhe.yang" Date: Wed, 8 Jul 2026 10:47:32 +0800 Subject: [PATCH] feat(kap-server): log envelope code instead of HTTP status - add custom onSend/onResponse access logging that records the envelope code - disable Fastify built-in request logging (every response is HTTP 200) - drop pino-pretty; logger always emits newline-delimited JSON - rename dev:server-v2 script to dev:kap-server --- apps/kimi-code/package.json | 5 +- package.json | 2 +- packages/kap-server/package.json | 9 +- packages/kap-server/src/requestLogging.ts | 77 ++++++++++++++++ .../src/services/pinoLoggerService.ts | 19 +--- packages/kap-server/src/start.ts | 18 +++- .../kap-server/test/requestLogging.test.ts | 90 +++++++++++++++++++ 7 files changed, 195 insertions(+), 25 deletions(-) create mode 100644 packages/kap-server/src/requestLogging.ts create mode 100644 packages/kap-server/test/requestLogging.test.ts diff --git a/apps/kimi-code/package.json b/apps/kimi-code/package.json index 22a5eaefe..68137acf1 100644 --- a/apps/kimi-code/package.json +++ b/apps/kimi-code/package.json @@ -63,7 +63,7 @@ "dev": "node scripts/dev.mjs", "dev:cli-only": "tsx --import ../../build/register-raw-text-loader.mjs ./src/main.ts", "dev:server": "tsx --tsconfig ./tsconfig.dev.json --import ../../build/register-raw-text-loader.mjs ./src/main.ts server run --foreground", - "dev:server-v2": "KIMI_CODE_EXPERIMENTAL_FLAG=1 tsx --tsconfig ./tsconfig.dev.json --import ../../build/register-raw-text-loader.mjs --import ../../build/register-hash-imports-loader.mjs ./src/main.ts server run --foreground", + "dev:kap-server": "KIMI_CODE_EXPERIMENTAL_FLAG=1 tsx --tsconfig ./tsconfig.dev.json --import ../../build/register-raw-text-loader.mjs --import ../../build/register-hash-imports-loader.mjs ./src/main.ts server run --foreground", "dev:server:restart": "node scripts/dev-server-restart.mjs", "dev:plugin-marketplace": "node scripts/dev-plugin-marketplace-server.mjs", "build:plugin-marketplace": "node scripts/build-plugin-marketplace-cdn.mjs", @@ -81,6 +81,8 @@ }, "devDependencies": { "@moonshot-ai/acp-adapter": "workspace:^", + "@moonshot-ai/agent-core-v2": "workspace:^", + "@moonshot-ai/kap-server": "workspace:^", "@moonshot-ai/kimi-code-oauth": "workspace:^", "@moonshot-ai/kimi-code-sdk": "workspace:^", "@moonshot-ai/kimi-telemetry": "workspace:^", @@ -88,7 +90,6 @@ "@moonshot-ai/migration-legacy": "workspace:^", "@moonshot-ai/pi-tui": "workspace:^", "@moonshot-ai/server": "workspace:^", - "@moonshot-ai/kap-server": "workspace:^", "@moonshot-ai/vis-server": "workspace:^", "@moonshot-ai/vis-web": "workspace:*", "@types/semver": "^7.7.0", diff --git a/package.json b/package.json index 8e30a44c9..965f1ca8d 100644 --- a/package.json +++ b/package.json @@ -13,7 +13,7 @@ "dev:web": "pnpm -C apps/kimi-web run dev", "dev:desktop": "pnpm -C apps/kimi-desktop run dev", "dev:server": "pnpm -C apps/kimi-code run dev:server", - "dev:server-v2": "pnpm -C apps/kimi-code run dev:server-v2", + "dev:kap-server": "pnpm -C apps/kimi-code run dev:kap-server", "build:plugin-marketplace": "pnpm -C apps/kimi-code run build:plugin-marketplace", "vis": "pnpm -C apps/vis run dev", "dev:docs": "pnpm -C docs install --ignore-workspace && pnpm -C docs run dev", diff --git a/packages/kap-server/package.json b/packages/kap-server/package.json index ccbc515b4..3573e1d3d 100644 --- a/packages/kap-server/package.json +++ b/packages/kap-server/package.json @@ -25,17 +25,16 @@ "@fastify/swagger": "^9.7.0", "@moonshot-ai/agent-core-v2": "workspace:^", "@moonshot-ai/protocol": "workspace:^", - "bcryptjs": "2.4.3", + "bcryptjs": "^2.4.3", "fastify": "^5.1.0", "pino": "^9.5.0", - "pino-pretty": "^13.0.0", - "smol-toml": "1.6.1", + "smol-toml": "^1.6.1", "ulid": "^3.0.1", - "ws": "^8.20.0", + "ws": "^8.18.0", "zod": "catalog:" }, "devDependencies": { - "@types/bcryptjs": "2.4.6", + "@types/bcryptjs": "^2.4.6", "@types/ws": "^8.18.0", "tsx": "^4.21.0" } diff --git a/packages/kap-server/src/requestLogging.ts b/packages/kap-server/src/requestLogging.ts new file mode 100644 index 000000000..1745e6088 --- /dev/null +++ b/packages/kap-server/src/requestLogging.ts @@ -0,0 +1,77 @@ +/** + * Custom HTTP access logging for kap-server. + * + * Fastify's default request log records `res.statusCode`, but kap-server returns + * HTTP 200 for *every* response by design — the real business outcome lives in + * the envelope `code` field (see `error-handler.ts` and `protocol/envelope`). + * + * So we disable Fastify's built-in request logging and emit our own `request + * completed` line that carries the envelope `code` instead of the meaningless + * HTTP status code. + * + * The envelope code is captured in an `onSend` hook (where the serialized body + * is available) and read back in an `onResponse` hook (where `elapsedTime` is + * final). Envelopes always lead with `"code":`, so a cheap prefix match + * extracts it without parsing the whole body — large payloads stay cheap. + */ + +import type { FastifyInstance, FastifyReply } from 'fastify'; + +/** + * Pull the envelope `code` out of a serialized JSON response body. + * + * Returns `undefined` for non-string payloads (buffers, streams) and for bodies + * that are not envelopes (e.g. `/openapi.json`, static assets) — those simply + * log without a `code` field. + */ +export function extractEnvelopeCode(payload: unknown): number | undefined { + if (typeof payload !== 'string') { + return undefined; + } + const match = /^\s*\{\s*"code"\s*:\s*(-?\d+)/.exec(payload); + if (match === null) { + return undefined; + } + const code = Number(match[1]); + return Number.isSafeInteger(code) ? code : undefined; +} + +/** + * Register the `onSend` + `onResponse` hooks that emit the access log line. + * + * The `onResponse` line mirrors Fastify's default shape (reqId via the child + * logger, `req`, `responseTime`, `msg: 'request completed'`) but swaps + * `res.statusCode` for the envelope `code`. + */ +export function registerRequestLogging(app: FastifyInstance): void { + // Per-request stash from `onSend` (payload known) to `onResponse` (timing + // known). Keyed by reply object so entries are GC'd with the request. + const codes = new WeakMap(); + + app.addHook('onSend', (req, reply, payload, done) => { + const code = extractEnvelopeCode(payload); + if (code !== undefined) { + codes.set(reply, code); + } + done(null, payload); + }); + + app.addHook('onResponse', (req, reply, done) => { + req.log.info( + { + req: { + method: req.method, + url: req.url, + version: req.headers['accept-version'], + host: req.host, + remoteAddress: req.ip, + remotePort: req.socket === undefined ? undefined : req.socket.remotePort, + }, + code: codes.get(reply), + responseTime: reply.elapsedTime, + }, + 'request completed', + ); + done(); + }); +} diff --git a/packages/kap-server/src/services/pinoLoggerService.ts b/packages/kap-server/src/services/pinoLoggerService.ts index 43114d03c..940d79ce5 100644 --- a/packages/kap-server/src/services/pinoLoggerService.ts +++ b/packages/kap-server/src/services/pinoLoggerService.ts @@ -5,10 +5,13 @@ * v1 server, server-v2 does not adapt this logger into the engine's * `ILogService` — `agent-core-v2` registers its own `ILogService` at Core scope, * so the HTTP-layer logger stays a plain pino instance. + * + * Output is always newline-delimited JSON (pino's default). The HTTP status is + * not logged on the access line — every response is HTTP 200 by design, with + * the business outcome carried in the envelope `code` (see `requestLogging.ts`). */ import { pino, type Logger, type LoggerOptions } from 'pino'; -import prettyStream from 'pino-pretty'; export type ServerLogger = Logger; @@ -16,27 +19,13 @@ export type ServerLogLevel = 'fatal' | 'error' | 'warn' | 'info' | 'debug' | 'tr export interface CreateLoggerOptions { level: ServerLogLevel; - pretty?: boolean; } export function createServerLogger(opts: CreateLoggerOptions): ServerLogger { - const pretty = opts.pretty ?? process.stdout.isTTY === true; const base: LoggerOptions = { level: opts.level, base: { name: 'kimi-server-v2' }, timestamp: pino.stdTimeFunctions.isoTime, }; - if (pretty) { - return pino( - base, - prettyStream({ - colorize: true, - translateTime: 'SYS:HH:MM:ss.l o', - ignore: 'pid,hostname', - singleLine: false, - destination: process.stdout, - }), - ); - } return pino(base); } diff --git a/packages/kap-server/src/start.ts b/packages/kap-server/src/start.ts index fd8e0d3e9..5932c20e0 100644 --- a/packages/kap-server/src/start.ts +++ b/packages/kap-server/src/start.ts @@ -26,6 +26,7 @@ import { installErrorHandler } from './error-handler'; import { acquireLock, type AcquireLockResult, ServerLockedError } from './lock'; import { createInstanceRegistry, type InstanceRegistration } from './instanceRegistry'; import { transformOpenApiDocument } from './openapi/transforms'; +import { registerRequestLogging } from './requestLogging'; import { resolveRequestId } from './request-id'; import { registerApiV1Routes } from './routes/registerApiV1Routes'; import { registerWebAssetRoutes } from './routes/webAssets'; @@ -36,6 +37,8 @@ import { } from './services/pinoLoggerService'; import { join } from 'node:path'; import type { Socket } from 'node:net'; +import type { IncomingMessage } from 'node:http'; +import type { Duplex } from 'node:stream'; import { registerRpcRoutes } from './transport/registerRpcRoutes'; import { @@ -238,9 +241,13 @@ export async function startServer(opts: ServerStartOptions = {}): Promise resolveRequestId(req.headers), }) as unknown as FastifyInstance; + registerRequestLogging(app); // Validation is performed by the route-level Zod preHandlers (defineRoute), // not by Fastify's AJV layer — keep both compilers as pass-throughs. app.setValidatorCompiler(() => () => true); @@ -366,7 +373,11 @@ export async function startServer(opts: ServerStartOptions = {}): Promise { + const handleUpgrade = async ( + req: IncomingMessage, + socket: Duplex, + head: Buffer, + ): Promise => { const url = req.url ?? ''; const isV1 = url === WS_PATH_V1 || url.startsWith(`${WS_PATH_V1}?`); const isV2 = url === WS_PATH_V2 || url.startsWith(`${WS_PATH_V2}?`); @@ -419,6 +430,9 @@ export async function startServer(opts: ServerStartOptions = {}): Promise wssV2.emit('connection', ws, req)); } + }; + app.server.on('upgrade', (req, socket, head) => { + void handleUpgrade(req, socket, head); }); app.addHook('onClose', async () => { diff --git a/packages/kap-server/test/requestLogging.test.ts b/packages/kap-server/test/requestLogging.test.ts new file mode 100644 index 000000000..123c01c24 --- /dev/null +++ b/packages/kap-server/test/requestLogging.test.ts @@ -0,0 +1,90 @@ +import { mkdtemp, rm } from 'node:fs/promises'; +import { tmpdir } from 'node:os'; +import { join } from 'node:path'; +import { Writable } from 'node:stream'; + +import { pino, type Logger } from 'pino'; +import { afterEach, assert, describe, expect, it } from 'vitest'; + +import { extractEnvelopeCode } from '../src/requestLogging'; +import { type RunningServer, startServer } from '../src/start'; + +function captureLogger(): { logger: Logger; lines: string[] } { + const lines: string[] = []; + const stream = new Writable({ + write(chunk, _enc, cb) { + lines.push(chunk.toString()); + cb(); + }, + }); + return { logger: pino({ level: 'info' }, stream), lines }; +} + +function parseEntries(lines: string[]): Record[] { + return lines + .map((line) => { + try { + return JSON.parse(line) as Record; + } catch { + return null; + } + }) + .filter((entry): entry is Record => entry !== null); +} + +describe('requestLogging', () => { + let server: RunningServer | undefined; + let home: string | undefined; + + afterEach(async () => { + if (server !== undefined) { + await server.close(); + server = undefined; + } + if (home !== undefined) { + await rm(home, { recursive: true, force: true }); + home = undefined; + } + }); + + it('logs the envelope code instead of the HTTP status code', async () => { + home = await mkdtemp(join(tmpdir(), 'kimi-server-v2-request-log-')); + const { logger, lines } = captureLogger(); + server = await startServer({ host: '127.0.0.1', port: 0, homeDir: home, logger }); + + const res = await fetch(`http://127.0.0.1:${String(server.port)}/api/v1/healthz`); + expect(res.status).toBe(200); + expect(((await res.json()) as { code: number }).code).toBe(0); + + // Let the post-response `onResponse` hook flush its log line. + await new Promise((resolve) => setImmediate(resolve)); + + const completed = parseEntries(lines).filter((entry) => entry['msg'] === 'request completed'); + expect(completed.length).toBeGreaterThanOrEqual(1); + const entry = completed[completed.length - 1]; + assert(entry !== undefined); + + // The access line carries the envelope `code`, not the HTTP status code. + expect(entry['code']).toBe(0); + expect(entry).not.toHaveProperty('statusCode'); + expect(entry['res']).toBeUndefined(); + expect(entry['req']).toMatchObject({ method: 'GET', url: '/api/v1/healthz' }); + expect(typeof entry['responseTime']).toBe('number'); + }); +}); + +describe('extractEnvelopeCode', () => { + it('extracts a leading code from an envelope body', () => { + expect(extractEnvelopeCode('{"code":0,"msg":"success","data":null,"request_id":"r"}')).toBe(0); + expect( + extractEnvelopeCode('{"code":40001,"msg":"validation.failed","data":null,"request_id":"r"}'), + ).toBe(40001); + }); + + it('returns undefined for non-envelope or non-string payloads', () => { + expect(extractEnvelopeCode(undefined)).toBeUndefined(); + expect(extractEnvelopeCode(Buffer.from('{"code":1}'))).toBeUndefined(); + expect(extractEnvelopeCode('')).toBeUndefined(); + expect(extractEnvelopeCode('{"msg":"no code"}')).toBeUndefined(); + }); +});