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
This commit is contained in:
haozhe.yang 2026-07-08 10:47:32 +08:00
parent b71cf5e751
commit f054fe9a21
7 changed files with 195 additions and 25 deletions

View file

@ -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",

View file

@ -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",

View file

@ -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"
}

View file

@ -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":<n>`, 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<FastifyReply, number>();
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();
});
}

View file

@ -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);
}

View file

@ -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<Runnin
const app = Fastify({
loggerInstance: logger,
disableRequestLogging: false,
// Fastify's default access log records `res.statusCode`, but every
// kap-server response is HTTP 200 by design — the outcome lives in the
// envelope `code`. `registerRequestLogging` emits our own line instead.
disableRequestLogging: true,
genReqId: (req) => 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<Runnin
logger,
});
app.server.on('upgrade', async (req, socket, head) => {
const handleUpgrade = async (
req: IncomingMessage,
socket: Duplex,
head: Buffer,
): Promise<void> => {
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<Runnin
} else {
wssV2.handleUpgrade(req, socket, head, (ws) => wssV2.emit('connection', ws, req));
}
};
app.server.on('upgrade', (req, socket, head) => {
void handleUpgrade(req, socket, head);
});
app.addHook('onClose', async () => {

View file

@ -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<string, unknown>[] {
return lines
.map((line) => {
try {
return JSON.parse(line) as Record<string, unknown>;
} catch {
return null;
}
})
.filter((entry): entry is Record<string, unknown> => 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('<html/>')).toBeUndefined();
expect(extractEnvelopeCode('{"msg":"no code"}')).toBeUndefined();
});
});