diff --git a/src/cli/mm.test.ts b/src/cli/mm.test.ts index 7c85363..9733fa6 100644 --- a/src/cli/mm.test.ts +++ b/src/cli/mm.test.ts @@ -1353,6 +1353,86 @@ describe('sendRequest', () => { observations: { state: 'home' }, }); }); + + describe('meta', () => { + const meta = { + timing: { queueMs: 0, toolMs: 12, observationMs: 30, totalMs: 45 }, + }; + + const printed = (): Record => + JSON.parse((stdoutSpy.mock.calls[0] as string[])[0]) as Record< + string, + unknown + >; + + it('prints meta after the result fields', async () => { + vi.spyOn(globalThis, 'fetch').mockResolvedValue({ + ok: true, + json: async () => ({ ok: true, result: { count: 2 }, meta }), + } as Response); + + await sendRequest(3000, 'POST', '/tool/get_state', {}); + + const output = printed(); + expect(output).toStrictEqual({ count: 2, meta }); + expect(Object.keys(output)).toStrictEqual(['count', 'meta']); + }); + + it('prints meta after observations', async () => { + vi.spyOn(globalThis, 'fetch').mockResolvedValue({ + ok: true, + json: async () => ({ + ok: true, + result: { clicked: true }, + observations: { state: 'home' }, + meta, + }), + } as Response); + + await sendRequest(3000, 'POST', '/tool/click', { a11yRef: 'e1' }); + + expect(Object.keys(printed())).toStrictEqual([ + 'clicked', + 'observations', + 'meta', + ]); + }); + + it('does not print meta for string results', async () => { + vi.spyOn(globalThis, 'fetch').mockResolvedValue({ + ok: true, + json: async () => ({ ok: true, result: 'simple string', meta }), + } as Response); + + await sendRequest(3000, 'GET', '/status', null); + + expect(stdoutSpy).toHaveBeenCalledWith('simple string\n'); + }); + + it('wraps array results so meta can be printed', async () => { + vi.spyOn(globalThis, 'fetch').mockResolvedValue({ + ok: true, + json: async () => ({ ok: true, result: [1, 2], meta }), + } as Response); + + await sendRequest(3000, 'POST', '/tool/get_state', {}); + + expect(printed()).toStrictEqual({ result: [1, 2], meta }); + }); + + it('prints meta once when the body has no result key', async () => { + vi.spyOn(globalThis, 'fetch').mockResolvedValue({ + ok: true, + json: async () => ({ ok: true, status: 'running', meta }), + } as Response); + + await sendRequest(3000, 'GET', '/status', null); + + const output = printed(); + expect(output).toStrictEqual({ ok: true, status: 'running', meta }); + expect(Object.keys(output).at(-1)).toBe('meta'); + }); + }); }); describe('routeCommand', () => { diff --git a/src/cli/mm.ts b/src/cli/mm.ts index ebf8f46..97e0e35 100644 --- a/src/cli/mm.ts +++ b/src/cli/mm.ts @@ -1094,8 +1094,9 @@ export async function sendRequest( try { const data = await daemonFetch(port, method, requestPath, body, timeout); - const result = data.result ?? data; - const observations = data.observations as + const { meta, ...rest } = data; + const result = rest.result ?? rest; + const observations = rest.observations as | Record | undefined; let output: unknown = result; @@ -1106,6 +1107,15 @@ export async function sendRequest( : { result }; output = { ...base, observations }; } + if (meta !== undefined && typeof output !== 'string') { + const base = + typeof output === 'object' && + output !== null && + !Array.isArray(output) + ? (output as Record) + : { result: output }; + output = { ...base, meta }; + } if (typeof output === 'string') { process.stdout.write(`${output}\n`); } else { diff --git a/src/server/create-server.test.ts b/src/server/create-server.test.ts index 68416f7..32f5f0b 100644 --- a/src/server/create-server.test.ts +++ b/src/server/create-server.test.ts @@ -1335,6 +1335,166 @@ describe('createServer with active session', () => { expect(mockSM.getExtensionState).toHaveBeenCalledTimes(1); }); }); + + describe('meta.timing', () => { + type TimedBody = { + ok: boolean; + error?: { code: string }; + meta?: { + timing: { + queueMs: number; + toolMs: number; + observationMs: number; + totalMs: number; + }; + }; + }; + + const post = async ( + urlPath: string, + body: string = JSON.stringify({}), + ): Promise<{ status: number; body: TimedBody }> => { + const res = await httpRequest( + `http://127.0.0.1:${state.port}${urlPath}`, + { + method: 'POST', + headers: { 'Content-Type': 'application/json' }, + body, + }, + ); + return { status: res.status, body: (await res.json()) as TimedBody }; + }; + + const expectValidTiming = (body: TimedBody): void => { + const timing = body.meta?.timing; + expect(timing).toBeDefined(); + for (const value of Object.values(timing ?? {})) { + expect(Number.isInteger(value)).toBe(true); + expect(value).toBeGreaterThanOrEqual(0); + } + expect(timing?.totalMs).toBeGreaterThanOrEqual( + (timing?.queueMs ?? 0) + + (timing?.toolMs ?? 0) + + (timing?.observationMs ?? 0), + ); + }; + + it('adds meta.timing as the last key of a successful response', async () => { + const { status, body } = await post('/cleanup'); + + expect(status).toBe(200); + expect(body.ok).toBe(true); + expectValidTiming(body); + expect(Object.keys(body).at(-1)).toBe('meta'); + }); + + it('measures tool and observation time separately', async () => { + mockSM.cleanup.mockImplementationOnce( + async () => + new Promise((resolve) => setTimeout(() => resolve(true), 60)), + ); + mockSM.getExtensionState.mockImplementationOnce( + async () => + new Promise((resolve) => + setTimeout(() => resolve({ isLoaded: true, currentUrl: '' }), 60), + ), + ); + + const { body } = await post('/cleanup'); + + expectValidTiming(body); + expect(body.meta?.timing.toolMs).toBeGreaterThanOrEqual(50); + expect(body.meta?.timing.observationMs).toBeGreaterThanOrEqual(50); + }); + + it('reports observationMs 0 when no session is active', async () => { + mockSM.hasActiveSession.mockReturnValue(false); + + const { body } = await post('/tool/get_context'); + + expectValidTiming(body); + expect(body.meta?.timing.observationMs).toBe(0); + }); + + it('reports queue wait for a request queued behind another', async () => { + let releaseFirst!: () => void; + mockSM.cleanup.mockImplementationOnce( + async () => + new Promise((resolve) => { + releaseFirst = () => resolve(true); + }), + ); + + const first = post('/cleanup'); + // The first request is now running inside the queue. + await vi.waitFor(() => expect(mockSM.cleanup).toHaveBeenCalled()); + const second = post('/tool/get_context'); + await new Promise((resolve) => setTimeout(resolve, 60)); + releaseFirst(); + + const [firstRes, secondRes] = await Promise.all([first, second]); + expectValidTiming(firstRes.body); + expectValidTiming(secondRes.body); + expect(secondRes.body.meta?.timing.queueMs).toBeGreaterThanOrEqual(50); + }); + + it('includes meta.timing when the tool throws', async () => { + mockSM.cleanup.mockRejectedValueOnce(new Error('Browser crash')); + + const { status, body } = await post('/cleanup'); + + expect(status).toBe(500); + expect(body.error?.code).toBe('TOOL_EXECUTION_FAILED'); + expectValidTiming(body); + }); + + it('includes meta.timing on validation errors', async () => { + const { status, body } = await post('/tool/click'); + + expect(status).toBe(400); + expect(body.error?.code).toBe('VALIDATION_ERROR'); + expectValidTiming(body); + expect(body.meta?.timing.toolMs).toBe(0); + }); + + it('includes meta.timing for unknown tools', async () => { + const { status, body } = await post('/tool/nonexistent'); + + expect(status).toBe(404); + expectValidTiming(body); + }); + + it('includes meta.timing for platform gate errors', async () => { + const { status, body } = await post( + '/tool/device_swipe', + JSON.stringify({ direction: 'up' }), + ); + + expect(status).toBe(200); + expect(body.error?.code).toBe('MM_TOOL_NOT_SUPPORTED_ON_PLATFORM'); + expectValidTiming(body); + }); + + it('includes meta.timing for malformed JSON bodies, measured from request arrival', async () => { + // Each performance.now() call advances 25ms, so a start recorded before + // the body parser yields totalMs > 0 in the error middleware. + let clock = 0; + const nowSpy = vi + .spyOn(performance, 'now') + .mockImplementation(() => (clock += 25)); + + try { + const { status, body } = await post('/tool/get_state', '{not json'); + + expect(status).toBe(500); + expect(body.error?.code).toBe('INTERNAL_ERROR'); + expectValidTiming(body); + expect(body.meta?.timing.totalMs).toBeGreaterThan(0); + } finally { + nowSpy.mockRestore(); + } + }); + }); }); describe('createServer with logging', () => { diff --git a/src/server/create-server.ts b/src/server/create-server.ts index b039027..b00fe1a 100644 --- a/src/server/create-server.ts +++ b/src/server/create-server.ts @@ -7,6 +7,12 @@ import * as http from 'node:http'; import { writeDaemonState, removeDaemonState } from './daemon-state.js'; import { compactObservation } from './observation-compaction.js'; import { RequestQueue } from './request-queue.js'; +import { + RequestTimer, + requestStartOf, + setRequestStart, + withMeta, +} from './response-timing.js'; import pkg from '../../package.json'; import type { PortMap, WorkflowContext } from '../capabilities/context.js'; import type { ExtensionState } from '../capabilities/types.js'; @@ -265,6 +271,13 @@ export function createServer(config: ServerConfig): ServerInstance { let idleCheckInterval: ReturnType | null = null; let lastObservation: StepRecordObservation | null = null; + // Registered before the body parser so `meta.timing.totalMs` includes body + // parsing, and so malformed-JSON errors still have a start time. + app.use((_req, res, next) => { + setRequestStart(res, performance.now()); + next(); + }); + // eslint-disable-next-line import-x/no-named-as-default-member app.use(express.json({ limit: '10mb' })); @@ -399,23 +412,37 @@ export function createServer(config: ServerConfig): ServerInstance { rawInput: unknown, res: express.Response, ): Promise { + const timer = new RequestTimer(requestStartOf(res)); const tool = toolRegistry.get(toolName); if (!tool) { - res.status(404).json({ - ok: false, - error: { code: 'TOOL_NOT_FOUND', message: `Unknown tool: ${toolName}` }, - }); + res.status(404).json( + withMeta( + { + ok: false, + error: { + code: 'TOOL_NOT_FOUND', + message: `Unknown tool: ${toolName}`, + }, + }, + timer.meta(), + ), + ); return; } if (!workflowContext) { - res.status(503).json({ - ok: false, - error: { - code: 'SERVER_NOT_STARTED', - message: 'Server has not been started yet.', - }, - }); + res.status(503).json( + withMeta( + { + ok: false, + error: { + code: 'SERVER_NOT_STARTED', + message: 'Server has not been started yet.', + }, + }, + timer.meta(), + ), + ); return; } @@ -426,19 +453,24 @@ export function createServer(config: ServerConfig): ServerInstance { if (schema) { const parsed = schema.safeParse(rawInput); if (!parsed.success) { - res.status(400).json({ - ok: false, - error: { - code: 'VALIDATION_ERROR', - message: parsed.error.issues - .map((i) => - i.path.length > 0 - ? `${i.path.join('.')}: ${i.message}` - : i.message, - ) - .join('; '), - }, - }); + res.status(400).json( + withMeta( + { + ok: false, + error: { + code: 'VALIDATION_ERROR', + message: parsed.error.issues + .map((i) => + i.path.length > 0 + ? `${i.path.join('.')}: ${i.message}` + : i.message, + ) + .join('; '), + }, + }, + timer.meta(), + ), + ); return; } validatedInput = parsed.data; @@ -454,7 +486,7 @@ export function createServer(config: ServerConfig): ServerInstance { config.sessionManager.getPlatformDriver?.()?.getPlatform(), ); if (gateError) { - res.json({ ok: false, error: gateError }); + res.json(withMeta({ ok: false, error: gateError }, timer.meta())); return; } @@ -466,10 +498,13 @@ export function createServer(config: ServerConfig): ServerInstance { : undefined; try { + timer.markEnqueued(); const { toolResult, observations } = await queue.enqueue( async () => { + timer.markTaskStart(); const context = buildToolContext(currentWorkflowContext); const result = await tool(validatedInput, context); + timer.markToolEnd(); let obs: StepRecordObservation | undefined; if ( @@ -479,6 +514,7 @@ export function createServer(config: ServerConfig): ServerInstance { ) && config.sessionManager.hasActiveSession() ) { + timer.markObservationStart(); try { obs = await Promise.race([ (async (): Promise => { @@ -566,6 +602,7 @@ export function createServer(config: ServerConfig): ServerInstance { } catch { // non-fatal: observation failure must not block the tool response } + timer.markObservationEnd(); } return { toolResult: result, observations: obs }; @@ -591,7 +628,12 @@ export function createServer(config: ServerConfig): ServerInstance { includeInResponse && observations ? compactObservation(observations, lastObservation) : undefined; - res.json(buildResponseBody(toolResult, responseObservations)); + res.json( + withMeta( + buildResponseBody(toolResult, responseObservations), + timer.meta(), + ), + ); if ( toolName === 'describe_screen' || @@ -618,13 +660,18 @@ export function createServer(config: ServerConfig): ServerInstance { startTime, ); - res.status(500).json({ - ok: false, - error: { - code: 'TOOL_EXECUTION_FAILED', - message: extractErrorMessage(error), - }, - }); + res.status(500).json( + withMeta( + { + ok: false, + error: { + code: 'TOOL_EXECUTION_FAILED', + message: extractErrorMessage(error), + }, + }, + timer.meta(), + ), + ); } } @@ -651,13 +698,18 @@ export function createServer(config: ServerConfig): ServerInstance { _next: express.NextFunction, ) => { appendLog(config.logFilePath, `[ERROR] ${error.message}`); - res.status(500).json({ - ok: false, - error: { - code: 'INTERNAL_ERROR', - message: error.message, - }, - }); + res.status(500).json( + withMeta( + { + ok: false, + error: { + code: 'INTERNAL_ERROR', + message: error.message, + }, + }, + new RequestTimer(requestStartOf(res)).meta(), + ), + ); }, ); diff --git a/src/server/response-timing.test.ts b/src/server/response-timing.test.ts new file mode 100644 index 0000000..6fb9bb1 --- /dev/null +++ b/src/server/response-timing.test.ts @@ -0,0 +1,113 @@ +import { afterEach, describe, expect, it, vi } from 'vitest'; + +import { RequestTimer, withMeta } from './response-timing.js'; + +describe('RequestTimer', () => { + let now = 0; + + afterEach(() => { + vi.restoreAllMocks(); + }); + + const useFakeClock = (start: number): void => { + now = start; + vi.spyOn(performance, 'now').mockImplementation(() => now); + }; + + it('reports zeros for phases that never started', () => { + useFakeClock(1000); + const timer = new RequestTimer(); + now = 1012.4; + + expect(timer.snapshot()).toStrictEqual({ + queueMs: 0, + toolMs: 0, + observationMs: 0, + totalMs: 12, + }); + }); + + it('measures each phase', () => { + useFakeClock(0); + const timer = new RequestTimer(0); + now = 5; + timer.markEnqueued(); + now = 25; + timer.markTaskStart(); + now = 125; + timer.markToolEnd(); + now = 130; + timer.markObservationStart(); + now = 180; + timer.markObservationEnd(); + now = 190; + + expect(timer.snapshot()).toStrictEqual({ + queueMs: 20, + toolMs: 100, + observationMs: 50, + totalMs: 190, + }); + }); + + it('measures an unfinished phase up to the snapshot', () => { + useFakeClock(0); + const timer = new RequestTimer(0); + timer.markEnqueued(); + timer.markTaskStart(); + now = 40; + + expect(timer.snapshot().toolMs).toBe(40); + }); + + it('never reports totalMs below the sum of the rounded phases', () => { + useFakeClock(0); + const timer = new RequestTimer(0); + timer.markEnqueued(); + now = 0.5; + timer.markTaskStart(); + now = 1; + timer.markToolEnd(); + timer.markObservationStart(); + now = 1.5; + timer.markObservationEnd(); + + // Each phase rounds up to 1ms; the 1.5ms total would round to 2. + expect(timer.snapshot()).toStrictEqual({ + queueMs: 1, + toolMs: 1, + observationMs: 1, + totalMs: 3, + }); + }); + + it('defaults the request start to now', () => { + useFakeClock(500); + const timer = new RequestTimer(); + now = 503; + + expect(timer.meta()).toStrictEqual({ + timing: { queueMs: 0, toolMs: 0, observationMs: 0, totalMs: 3 }, + }); + }); +}); + +describe('withMeta', () => { + const meta = { + timing: { queueMs: 1, toolMs: 2, observationMs: 3, totalMs: 7 }, + }; + + it('appends meta as the last key of an object body', () => { + const body = withMeta({ ok: true, result: { a: 1 } }, meta); + + expect(body).toStrictEqual({ ok: true, result: { a: 1 }, meta }); + expect(Object.keys(body as object)).toStrictEqual(['ok', 'result', 'meta']); + }); + + it.each([['text'], [null], [42], [[1, 2]]])( + 'returns non-object body %j unchanged', + (body) => { + expect(withMeta(body, meta)).toBe(body); + }, + ); +}); diff --git a/src/server/response-timing.ts b/src/server/response-timing.ts new file mode 100644 index 0000000..c4902c5 --- /dev/null +++ b/src/server/response-timing.ts @@ -0,0 +1,130 @@ +import type express from 'express'; + +import type { ToolResponseMeta, ToolResponseTiming } from '../types/http.js'; + +/** + * Records the phases of one tool request with a monotonic clock and turns + * them into a {@link ToolResponseTiming}. + * + * Phases that never started report 0. A phase that started but did not end + * (for example a tool that was still running when the queue timed out) is + * measured up to the moment of the snapshot. + */ +export class RequestTimer { + readonly #requestStart: number; + + #enqueuedAt: number | undefined; + + #taskStartedAt: number | undefined; + + #toolEndedAt: number | undefined; + + #observationStartedAt: number | undefined; + + #observationEndedAt: number | undefined; + + /** + * @param requestStart - `performance.now()` value when the request arrived. + * Defaults to now. + */ + constructor(requestStart: number = performance.now()) { + this.#requestStart = requestStart; + } + + /** Marks the moment the task was handed to the request queue. */ + markEnqueued(): void { + this.#enqueuedAt = performance.now(); + } + + /** Marks the moment the queued task started (the tool is about to run). */ + markTaskStart(): void { + this.#taskStartedAt = performance.now(); + } + + /** Marks the end of the tool function call. */ + markToolEnd(): void { + this.#toolEndedAt = performance.now(); + } + + /** Marks the start of observation collection. */ + markObservationStart(): void { + this.#observationStartedAt = performance.now(); + } + + /** Marks the end of observation collection. */ + markObservationEnd(): void { + this.#observationEndedAt = performance.now(); + } + + /** + * Returns the timing so far, in whole milliseconds. + * + * @returns The timing; `totalMs` is never less than the sum of the phases. + */ + snapshot(): ToolResponseTiming { + const now = performance.now(); + const span = ( + start: number | undefined, + end: number | undefined, + ): number => + start === undefined ? 0 : Math.max(0, Math.round((end ?? now) - start)); + + const queueMs = span(this.#enqueuedAt, this.#taskStartedAt); + const toolMs = span(this.#taskStartedAt, this.#toolEndedAt); + const observationMs = span( + this.#observationStartedAt, + this.#observationEndedAt, + ); + const totalMs = Math.max( + span(this.#requestStart, undefined), + queueMs + toolMs + observationMs, + ); + return { queueMs, toolMs, observationMs, totalMs }; + } + + /** + * Returns the `meta` object for a response body. + * + * @returns The response metadata with the current timing. + */ + meta(): ToolResponseMeta { + return { timing: this.snapshot() }; + } +} + +/** + * Adds `meta` to a response body. Bodies that are not plain objects (strings, + * arrays, null) are returned unchanged. + * + * @param body - The response body. + * @param meta - The metadata to attach. + * @returns The body with `meta` as its last key. + */ +export function withMeta(body: unknown, meta: ToolResponseMeta): unknown { + if (typeof body !== 'object' || body === null || Array.isArray(body)) { + return body; + } + return { ...(body as Record), meta }; +} + +const requestStarts = new WeakMap(); + +/** + * Records when a request arrived. Call it before the body parser runs. + * + * @param res - The Express response for the request. + * @param start - `performance.now()` value when the request arrived. + */ +export function setRequestStart(res: express.Response, start: number): void { + requestStarts.set(res, start); +} + +/** + * Returns when a request arrived, as recorded by {@link setRequestStart}. + * + * @param res - The Express response for the request. + * @returns The recorded start, or now if none was recorded. + */ +export function requestStartOf(res: express.Response): number { + return requestStarts.get(res) ?? performance.now(); +} diff --git a/src/types/http.ts b/src/types/http.ts index 6daf1ed..604f99d 100644 --- a/src/types/http.ts +++ b/src/types/http.ts @@ -44,6 +44,30 @@ export type ToolResponse = | { ok: true; result: T } | { ok: false; error: { code: string; message: string } }; +/** + * Server-side timing of one tool request, in whole milliseconds. + * + * Phases that did not run (for example `toolMs` for a validation error) are 0. + * `totalMs` is always at least `queueMs + toolMs + observationMs`. + */ +export type ToolResponseTiming = { + /** Time from enqueue until the queued task started (waiting for earlier requests). */ + queueMs: number; + /** Time spent inside the tool function. */ + toolMs: number; + /** Time spent collecting the post-tool observation (0 when skipped). */ + observationMs: number; + /** Time from request received until the response was sent. */ + totalMs: number; +}; + +/** + * Metadata attached to every `/tool/*`, `/launch` and `/cleanup` response body. + */ +export type ToolResponseMeta = { + timing: ToolResponseTiming; +}; + /** * Standalone tool function signature. *