From ca759dbb755529ce0480bd0e5c10bf694b1dca83 Mon Sep 17 00:00:00 2001 From: zermelo-wisen Date: Thu, 4 Apr 2024 10:34:37 +0300 Subject: [PATCH] feat: Multiple recording support (process always active) _ Added always active process recording mode with an env var: APPMAP_RECORDER_PROCESS_ALWAYS. - Removed the global recording: Recording instance and encapsulated new Recording instances (processRecording and nonProcessRecording) inside recorder.ts. - Changed related hooks to work with multiple possible recordings using getActiveRecordings(). - Added tests for test and remote recording for always active process recording mode: jest.test.ts, mocha.test.ts and httpServer.test.ts. --- src/__tests__/recorder.test.ts | 16 +- src/facade.ts | 15 +- src/hooks/http.ts | 149 +++-- src/hooks/jest.ts | 22 +- src/hooks/mocha.ts | 15 +- src/hooks/mongo.ts | 50 +- src/hooks/mysql.ts | 18 +- src/hooks/pg.ts | 21 +- src/hooks/prisma.ts | 44 +- src/hooks/sqlite.ts | 14 +- src/hooks/vitest.ts | 17 +- src/recorder.ts | 176 +++-- src/recorderControl.ts | 4 +- test/__snapshots__/httpServer.test.ts.snap | 361 +++++++++- test/__snapshots__/jest.test.ts.snap | 734 +++++++++++++++++++++ test/__snapshots__/mocha.test.ts.snap | 388 +++++++++++ test/helpers.ts | 21 +- test/httpServer.test.ts | 29 +- test/jest.test.ts | 21 +- test/mocha.test.ts | 19 +- 20 files changed, 1911 insertions(+), 223 deletions(-) diff --git a/src/__tests__/recorder.test.ts b/src/__tests__/recorder.test.ts index cc63e317..14c6b9a7 100644 --- a/src/__tests__/recorder.test.ts +++ b/src/__tests__/recorder.test.ts @@ -50,13 +50,14 @@ describe(recorder.record, () => { }); }); -describe(recorder.fixReturnEventIfPromiseResult, () => { +describe(recorder.fixReturnEventsIfPromiseResult, () => { it("records a fix up after the promise resolves", async () => { const promise = Promise.resolve("resolved"); - const result = recorder.fixReturnEventIfPromiseResult( + const result = recorder.fixReturnEventsIfPromiseResult( + recorder.getActiveRecordings().slice(0, 1), promise, - returnEvent, - callEvent, + [returnEvent], + [callEvent], getTime(), ); @@ -76,10 +77,11 @@ describe(recorder.fixReturnEventIfPromiseResult, () => { it("records a fix up after the promise rejects", async () => { const promise = Promise.reject(new Error("test")); - const result = recorder.fixReturnEventIfPromiseResult( + const result = recorder.fixReturnEventsIfPromiseResult( + recorder.getActiveRecordings().slice(0, 1), promise, - returnEvent, - callEvent, + [returnEvent], + [callEvent], getTime(), ); await expect(result).rejects.toThrowError("test"); diff --git a/src/facade.ts b/src/facade.ts index b8ea0b87..42cf79f5 100644 --- a/src/facade.ts +++ b/src/facade.ts @@ -3,16 +3,16 @@ import { isPromise } from "node:util/types"; import type * as AppMap from "./AppMap"; import { exceptionMetadata } from "./metadata"; -import { recording, start } from "./recorder"; +import { getActiveRecordings, getCodeBlockRecording, startCodeBlockRecording } from "./recorder"; import { disableGlobalRecording, - startCodeBlockRecording, - stopCodeBlockRecording, + setCodeBlockRecordingActive, + unsetCodeBlockRecordingActive, } from "./recorderControl"; -import Recording from "./Recording"; // Since _this_ module is loaded, we'll do code block recording only. -recording.abandon(); +// We ignore APPMAP_RECORDER_PROCESS_ALWAYS environment variable in this mode. +getActiveRecordings().forEach((r) => r.abandon()); disableGlobalRecording(); function isInstrumented() { @@ -30,8 +30,8 @@ export function record( if (!isInstrumented()) throw Error("Code is not instrumented. Please run the project with appmap-node."); - start(new Recording("block", "block", new Date().toISOString())); startCodeBlockRecording(); + setCodeBlockRecordingActive(); try { const result = block(); if (isPromise(result)) return result.then(() => finishRecording(), finishRecording); @@ -42,7 +42,8 @@ export function record( } function finishRecording(exn?: unknown): AppMap.AppMap | undefined { - stopCodeBlockRecording(); + unsetCodeBlockRecordingActive(); + const recording = getCodeBlockRecording(); if (!recording.finish()) return; const appmap = recording.readAppMap(); diff --git a/src/hooks/http.ts b/src/hooks/http.ts index 2124f425..bbbb6e1e 100644 --- a/src/hooks/http.ts +++ b/src/hooks/http.ts @@ -7,10 +7,16 @@ import { URL } from "node:url"; import type * as AppMap from "../AppMap"; import config from "../config"; -import Recording from "../Recording"; import { info, warn } from "../message"; import { parameter } from "../parameter"; -import { recording, start } from "../recorder"; +import { + getActiveRecordings, + getRemoteRecording, + getRequestRecording, + startProcessRecording, + startRemoteRecording, + startRequestRecording, +} from "../recorder"; import { getTime } from "../util/getTime"; type HTTP = typeof http | typeof https; @@ -92,8 +98,9 @@ function handleClientRequest(request: http.ClientRequest) { const startTime = getTime(); request.on("finish", () => { const url = extractRequestURL(request); + const recordings = getActiveRecordings(); // recording may have finished at this point - if (!recording.running) { + if (recordings.length == 0) { warnRecordingNotRunning(url); return; } @@ -101,10 +108,11 @@ function handleClientRequest(request: http.ClientRequest) { // Setting port to the default port for the protocol makes it empty string. // See: https://nodejs.org/api/url.html#urlport url.port = request.socket?.remotePort + ""; - const clientRequestEvent = recording.httpClientRequest( - request.method, - `${url.protocol}//${url.host}${url.pathname}`, - normalizeHeaders(request.getHeaders()), + + const urlString = `${url.protocol}//${url.host}${url.pathname}`; + const headers = normalizeHeaders(request.getHeaders()); + const clientRequestEvents = recordings.map((r) => + r.httpClientRequest(request.method, urlString, headers), ); request.on("response", (response) => { @@ -114,11 +122,27 @@ function handleClientRequest(request: http.ClientRequest) { }); response.once("end", () => { - if (!recording.running) { + const elapsed = getTime() - startTime; + const headers = normalizeHeaders(response.headers); + const returnValue = capture.createReturnValue( + response.headers["content-type"]?.startsWith("application/json") ?? false, + ); + + if (getActiveRecordings().length == 0) { warnRecordingNotRunning(url); return; } - handleClientResponse(clientRequestEvent, startTime, response, capture); + + recordings.forEach((recording, idx) => { + assert(response.statusCode != undefined); + recording.httpClientResponse( + clientRequestEvents[idx].id, + elapsed, + response.statusCode, + headers, + returnValue, + ); + }); }); }); }); @@ -135,24 +159,6 @@ function extractRequestURL(request: ClientRequest): URL { return new URL(`${protocol}//${host}${request.path}`); } -function handleClientResponse( - requestEvent: AppMap.HttpClientRequestEvent, - startTime: number, - response: http.IncomingMessage, - capture: BodyCapture, -): void { - assert(response.statusCode != undefined); - recording.httpClientResponse( - requestEvent.id, - getTime() - startTime, - response.statusCode, - normalizeHeaders(response.headers), - capture.createReturnValue( - response.headers["content-type"]?.startsWith("application/json") ?? false, - ), - ); -} - let remoteRunning = false; // TODO: return ![next, ...].some(h => h.shouldIgnoreRequest?.(request)) @@ -256,14 +262,15 @@ function handleRequest(request: http.IncomingMessage, response: http.ServerRespo if (shouldIgnoreRequest(request)) return; const url = new URL(request.url, "http://example"); - const testRunning = recording.metadata.recorder.type == "tests"; + const testRunning = getActiveRecordings().some((r) => r.metadata.recorder.type == "tests"); const timestamp = remoteRunning || testRunning ? undefined : startRequestRecording(url.pathname); - const requestEvent = recording.httpRequest( - request.method, - url.pathname, - `HTTP/${request.httpVersion}`, - normalizeHeaders(request.headers), - url.searchParams, + + const method = request.method; + const headers = normalizeHeaders(request.headers); + const protocol = `HTTP/${request.httpVersion}`; + const recordings = getActiveRecordings(); + const requestEvents = recordings.map((r) => + r.httpRequest(method, url.pathname, protocol, headers, url.searchParams), ); const capture = new BodyCapture(); @@ -271,7 +278,36 @@ function handleRequest(request: http.IncomingMessage, response: http.ServerRespo const startTime = getTime(); response.once("finish", () => { - handleResponse(request, requestEvent, startTime, timestamp, response, capture); + const contentType = response.getHeader("Content-Type"); + const isJson = typeof contentType == "string" && contentType.startsWith("application/json"); + + const elapsed = getTime() - startTime; + const headers = normalizeHeaders(response.getHeaders()); + const returnValue = capture.createReturnValue(isJson); + + recordings.forEach((recording, idx) => { + if (fixupEvent(request, requestEvents[idx])) recording.fixup(requestEvents[idx]); + + recording.httpResponse( + requestEvents[idx].id, + elapsed, + response.statusCode, + headers, + returnValue, + ); + }); + + // If there is a test or remote recording we don't create a separate request recording + // appmap, so we don't have to finish it. + const testRunning = recordings.some((r) => r.metadata.recorder.type == "tests"); + if (remoteRunning || testRunning) return; + + const recording = getRequestRecording(); + const { request_method, path_info } = requestEvents[0].http_server_request; + recording.metadata.name = `${request_method} ${path_info} (${response.statusCode}) — ${timestamp}`; + recording.finish(); + info("Wrote %s", recording.path); + startProcessRecording(); // just so there's always a recording running }); } @@ -332,42 +368,6 @@ function normalizeHeaders( return result; } -function handleResponse( - request: http.IncomingMessage, - requestEvent: AppMap.HttpServerRequestEvent, - startTime: number, - timestamp: string | undefined, - response: http.ServerResponse, - capture: BodyCapture, -): void { - if (fixupEvent(request, requestEvent)) recording.fixup(requestEvent); - - const contentType = response.getHeader("Content-Type"); - const isJson = typeof contentType == "string" && contentType.startsWith("application/json"); - - recording.httpResponse( - requestEvent.id, - getTime() - startTime, - response.statusCode, - normalizeHeaders(response.getHeaders()), - capture.createReturnValue(isJson), - ); - if (remoteRunning || recording.metadata.recorder.type == "tests") return; - - const { request_method, path_info } = requestEvent.http_server_request; - recording.metadata.name = `${request_method} ${path_info} (${response.statusCode}) — ${timestamp}`; - recording.finish(); - info("Wrote %s", recording.path); - start(); // just so there's always a recording running -} - -function startRequestRecording(pathname: string): string { - recording.abandon(); - const timestamp = new Date().toISOString(); - start(new Recording("requests", "requests", [timestamp, pathname].join(" "))); - return timestamp; -} - function capitalize(str: string): string { return str[0].toUpperCase() + str.slice(1).toLowerCase(); } @@ -387,14 +387,13 @@ function handleRemoteRecording( res.writeHead(200); remoteRunning = true; res.end("Recording started"); - info("Remote recording started"); - recording.abandon(); - start(new Recording("remote", "remote", new Date().toISOString())); + startRemoteRecording(); } break; case "DELETE": if (remoteRunning) { remoteRunning = false; + const recording = getRemoteRecording(); if (recording.finish()) { res.writeHead(200); const { path } = recording; @@ -402,7 +401,7 @@ function handleRemoteRecording( rmSync(path); } else res.writeHead(200).end("{}"); info("Remote recording finished"); - start(); // just so there's always a recording running + startProcessRecording(); // just so there's always a recording running } else res.writeHead(404).end("No recording is in progress"); break; default: diff --git a/src/hooks/jest.ts b/src/hooks/jest.ts index 60a19cc6..574eadb7 100644 --- a/src/hooks/jest.ts +++ b/src/hooks/jest.ts @@ -1,4 +1,3 @@ -import assert from "node:assert"; import { pathToFileURL } from "node:url"; import type { Circus } from "@jest/types"; @@ -6,11 +5,14 @@ import { simple as walk } from "acorn-walk"; import type { ESTree } from "meriyah"; import { expressionFor, wrap } from "."; -import Recording from "../Recording"; import { assignment, call_, identifier, memberId } from "../generate"; import { info } from "../message"; import { exceptionMetadata } from "../metadata"; -import { recording, start } from "../recorder"; +import { + abandonProcessRecordingIfNotAlwaysActive, + getTestRecording, + startTestRecording, +} from "../recorder"; import genericTranform from "../transform"; import { isId } from "../util/isId"; @@ -44,7 +46,7 @@ const passGlobals: ESTree.Statement[] = ["AppMap", "AppMapRecordHook"].map((name ); export function patchCircus(program: ESTree.Program): ESTree.Program { - recording.abandon(); + abandonProcessRecordingIfNotAlwaysActive(); info("Detected Jest. Tests will be automatically recorded."); program.body.push({ type: "ExpressionStatement", @@ -54,17 +56,18 @@ export function patchCircus(program: ESTree.Program): ESTree.Program { } function eventHandler(event: Circus.Event) { + let recording; switch (event.name) { case "test_fn_start": - start(createRecording(event.test)); + startTestRecording("tests", "jest", ...testNames(event.test)); break; case "test_fn_failure": - assert(recording.metadata.recorder.type == "tests"); + recording = getTestRecording(); recording.metadata.test_status = "failed"; recording.metadata.exception = exceptionMetadata(event.error); return recording.finish(); case "test_fn_success": - assert(recording.metadata.recorder.type == "tests"); + recording = getTestRecording(); recording.metadata.test_status = "succeeded"; return recording.finish(); } @@ -84,8 +87,3 @@ function testNames(test: Circus.TestEntry): string[] { for (let block = test.parent; block.parent; block = block.parent) names.push(block.name); return names.reverse(); } - -function createRecording(test: Circus.TestEntry): Recording { - const recording = new Recording("tests", "jest", ...testNames(test)); - return recording; -} diff --git a/src/hooks/mocha.ts b/src/hooks/mocha.ts index 7ad1bf17..3d7ee2ab 100644 --- a/src/hooks/mocha.ts +++ b/src/hooks/mocha.ts @@ -5,9 +5,12 @@ import { simple as walk } from "acorn-walk"; import type { ESTree } from "meriyah"; import { expressionFor } from "."; -import Recording from "../Recording"; import { call_, this_ } from "../generate"; -import { recording, start } from "../recorder"; +import { + abandonProcessRecordingIfNotAlwaysActive, + getTestRecording, + startTestRecording, +} from "../recorder"; import { info } from "../message"; import { exceptionMetadata } from "../metadata"; @@ -32,7 +35,7 @@ export function transform(program: ESTree.Program): ESTree.Program { type: "ExpressionStatement", expression: call_(expressionFor(registerEventListeners), this_), }); - recording.abandon(); + abandonProcessRecordingIfNotAlwaysActive(); info("Detected Mocha. Tests will be automatically recorded."); }, }); @@ -54,19 +57,19 @@ const EVENT_TEST_FAIL = "fail"; function registerEventListeners(runner: EventEmitter) { runner.on(EVENT_TEST_BEGIN, function (test: Test) { - const rec = new Recording("tests", "mocha", ...test.titlePath()); - start(rec); + startTestRecording("tests", "mocha", ...test.titlePath()); }); // eslint-disable-next-line @typescript-eslint/no-unused-vars runner.on(EVENT_TEST_PASS, function (test: Test) { + const recording = getTestRecording(); recording.metadata.test_status = "succeeded"; recording.finish(); }); // eslint-disable-next-line @typescript-eslint/no-unused-vars runner.on(EVENT_TEST_FAIL, function (test: Test, err: unknown) { - console.log(test); + const recording = getTestRecording(); recording.metadata.test_status = "failed"; recording.metadata.exception = exceptionMetadata(err); recording.finish(); diff --git a/src/hooks/mongo.ts b/src/hooks/mongo.ts index 6db1737f..a0e9d4f4 100644 --- a/src/hooks/mongo.ts +++ b/src/hooks/mongo.ts @@ -3,7 +3,7 @@ import { inspect } from "node:util"; import type mongodb from "mongodb"; import { identifier } from "../generate"; -import { fixReturnEventIfPromiseResult, recording } from "../recorder"; +import { fixReturnEventsIfPromiseResult, getActiveRecordings } from "../recorder"; import { FunctionInfo } from "../registry"; import { getTime } from "../util/getTime"; import { setCustomInspect } from "../parameter"; @@ -95,38 +95,60 @@ function patchMethod>( this: mongodb.Collection, ...args: unknown[] ): ReturnType { - if (!recording) return Reflect.apply(original, this, args) as ReturnType; + const recordings = getActiveRecordings(); + if (!recordings.length) + return Reflect.apply(original, this, args) as ReturnType; const funInfo = functionInfo(methodName, this.collectionName, argNames); const callback = extractOptionalCallback(args); if (callback) { - const callEvent = recording.functionCall( - funInfo, - this, - args.map((x) => setCustomInspect(x, customInspect)), + const functionCallArgs = args.map((x) => setCustomInspect(x, customInspect)); + const callEvents = recordings.map((recording) => + recording.functionCall(funInfo, this, functionCallArgs), ); + const startTime = getTime(); args.push((err: unknown, res: unknown) => { setCustomInspect(res, customInspect); - if (err) recording.functionException(callEvent.id, err, getTime() - startTime); - else recording.functionReturn(callEvent.id, res, getTime() - startTime); + + const elapsed = getTime() - startTime; + if (err) + recordings.forEach((recording, idx) => + recording.functionException(callEvents[idx].id, err, elapsed), + ); + else + recordings.forEach((recording, idx) => + recording.functionReturn(callEvents[idx].id, res, elapsed), + ); + return callback(err, res) as unknown; }); return Reflect.apply(original, this, args) as ReturnType; } - const callEvent = recording.functionCall(funInfo, this, args); + const callEvents = recordings.map((recording) => recording.functionCall(funInfo, this, args)); const startTime = getTime(); try { const result = Reflect.apply(original, this, args) as unknown; setCustomInspect(result, customInspect); - const returnEvent = recording.functionReturn(callEvent.id, result, getTime() - startTime); - return fixReturnEventIfPromiseResult(result, returnEvent, callEvent, startTime) as ReturnType< - typeof original - >; + + const elapsed = getTime() - startTime; + const returnEvents = recordings.map((recording, idx) => + recording.functionReturn(callEvents[idx].id, result, elapsed), + ); + return fixReturnEventsIfPromiseResult( + recordings, + result, + returnEvents, + callEvents, + startTime, + ) as ReturnType; } catch (exn: unknown) { - recording.functionException(callEvent.id, exn, getTime() - startTime); + const elapsed = getTime() - startTime; + recordings.map((recording, idx) => + recording.functionException(callEvents[idx].id, exn, elapsed), + ); throw exn; } }; diff --git a/src/hooks/mysql.ts b/src/hooks/mysql.ts index 0025a90e..c4a04a18 100644 --- a/src/hooks/mysql.ts +++ b/src/hooks/mysql.ts @@ -2,7 +2,7 @@ import assert from "node:assert"; import type mysql from "mysql"; -import { recording } from "../recorder"; +import { getActiveRecordings } from "../recorder"; import { getTime } from "../util/getTime"; export default function mysqlHook(mod: typeof mysql) { @@ -43,8 +43,9 @@ function createQueryProxy(query: mysql.QueryFunction) { const sql: string = hasStringSqlProperty(argArray[0]) ? argArray[0].sql : argArray[0]; - const call = recording.sqlQuery("mysql", sql); - const start = getTime(); + const recordings = getActiveRecordings(); + const callEvents = recordings.map((recording) => recording.sqlQuery("mysql", sql)); + const startTime = getTime(); const originalCallback = typeof argArray[argArray.length - 1] === "function" @@ -52,8 +53,15 @@ function createQueryProxy(query: mysql.QueryFunction) { : undefined; const newCallback: mysql.queryCallback = (err, results, fields) => { - if (err) recording.functionException(call.id, err, getTime() - start); - else recording.functionReturn(call.id, undefined, getTime() - start); + const elapsed = getTime() - startTime; + if (err) + recordings.forEach((recording, idx) => + recording.functionException(callEvents[idx].id, err, elapsed), + ); + else + recordings.forEach((recording, idx) => + recording.functionReturn(callEvents[idx].id, undefined, elapsed), + ); originalCallback?.call(this, err, results, fields); }; diff --git a/src/hooks/pg.ts b/src/hooks/pg.ts index 30096c56..c298e45e 100644 --- a/src/hooks/pg.ts +++ b/src/hooks/pg.ts @@ -1,6 +1,6 @@ import type pg from "pg"; -import { fixReturnEventIfPromiseResult, recording } from "../recorder"; +import { fixReturnEventsIfPromiseResult, getActiveRecordings } from "../recorder"; import { getTime } from "../util/getTime"; export default function pgHook(mod: typeof pg) { @@ -28,12 +28,23 @@ function createQueryProxy( // https://github.com/brianc/node-postgres/blob/master/packages/pg/lib/utils.js#L149 const sql: string = hasStringTextProperty(argArray[0]) ? argArray[0].text : argArray[0]; - const call = recording.sqlQuery("postgres", sql); - const start = getTime(); + const recordings = getActiveRecordings(); + const callEvents = recordings.map((recording) => recording.sqlQuery("postgres", sql)); + const startTime = getTime(); const result = target.apply(thisArg, argArray); - const ret = recording.functionReturn(call.id, result, getTime() - start); - return fixReturnEventIfPromiseResult(result, ret, call, start); + const elapsed = getTime() - startTime; + const returnEvents = recordings.map((recording, idx) => + recording.functionReturn(callEvents[idx].id, result, elapsed), + ); + + return fixReturnEventsIfPromiseResult( + recordings, + result, + returnEvents, + callEvents, + startTime, + ); }, }); } diff --git a/src/hooks/prisma.ts b/src/hooks/prisma.ts index aab59449..d178f0c2 100644 --- a/src/hooks/prisma.ts +++ b/src/hooks/prisma.ts @@ -5,7 +5,7 @@ import type prisma from "@prisma/client"; import type * as AppMap from "../AppMap"; import { getTime } from "../util/getTime"; -import { fixReturnEventIfPromiseResult, recording } from "../recorder"; +import { fixReturnEventsIfPromiseResult, getActiveRecordings } from "../recorder"; import { FunctionInfo } from "../registry"; import config from "../config"; @@ -105,34 +105,52 @@ function createProxy unknown>( thisArg._engine.config.logQueries = true; assert("$on" in thisArg && typeof thisArg.$on === "function"); thisArg.$on("query", (queryEvent: QueryEvent) => { - const call = recording.sqlQuery(dbType, queryEvent.query); + const recordings = getActiveRecordings(); + const callEvents = recordings.map((recording) => + recording.sqlQuery(dbType, queryEvent.query), + ); const elapsedSec = queryEvent.duration / 1000.0; - recording.functionReturn(call.id, undefined, elapsedSec); + recordings.forEach((recording, idx) => + recording.functionReturn(callEvents[idx].id, undefined, elapsedSec), + ); }); } // Report Prisma query as a function call, if suitable - let prismaCall: AppMap.FunctionCallEvent | undefined; + let prismaCalls: AppMap.FunctionCallEvent[] | undefined; + const recordings = getActiveRecordings(); if (argArray?.length > 0) { const requestParams = argArray[0] as PrismaRequestParams; if (requestParams.action && requestParams.model) { - prismaCall = recording.functionCall( - getFunctionInfo(requestParams.model, requestParams.action, moduleId), - requestParams.model, - [requestParams.args?.data, requestParams.args?.include, requestParams.args?.where], + const action = requestParams.action; + const model = requestParams.model; + prismaCalls = recordings.map((recording) => + recording.functionCall(getFunctionInfo(model, action, moduleId), model, [ + requestParams.args?.data, + requestParams.args?.include, + requestParams.args?.where, + ]), ); } } - if (prismaCall) { - const start = getTime(); + if (prismaCalls != undefined) { + const startTime = getTime(); + const calls = prismaCalls; try { const result = target.apply(thisArg, argArray); - const ret = recording.functionReturn(prismaCall.id, result, getTime() - start); - return fixReturnEventIfPromiseResult(result, ret, prismaCall, start); + + const elapsed = getTime() - startTime; + const returnEvents = recordings.map((recording, idx) => + recording.functionReturn(calls[idx].id, result, elapsed), + ); + return fixReturnEventsIfPromiseResult(recordings, result, returnEvents, calls, startTime); } catch (exn: unknown) { - recording.functionException(prismaCall.id, exn, getTime() - start); + const elapsed = getTime() - startTime; + recordings.forEach((recording, idx) => + recording.functionException(calls[idx].id, exn, elapsed), + ); throw exn; } } diff --git a/src/hooks/sqlite.ts b/src/hooks/sqlite.ts index 63cdecbc..25d80175 100644 --- a/src/hooks/sqlite.ts +++ b/src/hooks/sqlite.ts @@ -1,7 +1,7 @@ /* eslint-disable @typescript-eslint/unbound-method */ import type sqlite from "sqlite3"; -import { recording } from "../recorder"; +import { getActiveRecordings } from "../recorder"; import { getTime } from "../util/getTime"; type RecordingProxyTarget = @@ -51,8 +51,9 @@ function createRecordingProxy( sql = argArray[0]; } - const call = recording.sqlQuery("sqlite", sql); - const start = getTime(); + const recordings = getActiveRecordings(); + const callEvents = recordings.map((recording) => recording.sqlQuery("sqlite", sql)); + const startTime = getTime(); // Extract callback argument(s) to functionArgs const functionArgs = []; @@ -82,7 +83,12 @@ function createRecordingProxy( const newCompletionCallback = (...args: unknown[]) => { const isError = args.length > 0 && args[0] != undefined; - if (!isError) recording.functionReturn(call.id, undefined, getTime() - start); + if (!isError) { + const elapsed = getTime() - startTime; + recordings.forEach((recording, idx) => + recording.functionReturn(callEvents[idx].id, undefined, elapsed), + ); + } originalCompletionCallback?.apply(this, args); }; newFunctionArgs.push(newCompletionCallback); diff --git a/src/hooks/vitest.ts b/src/hooks/vitest.ts index fa6f8065..eb8e5bca 100644 --- a/src/hooks/vitest.ts +++ b/src/hooks/vitest.ts @@ -5,7 +5,6 @@ import worker from "node:worker_threads"; import { simple as walk } from "acorn-walk"; import { type ESTree } from "meriyah"; -import Recording from "../Recording"; import { args as args_, assignment, @@ -17,7 +16,11 @@ import { ret, } from "../generate"; import { info, warn } from "../message"; -import { recording, start } from "../recorder"; +import { + abandonProcessRecordingIfNotAlwaysActive, + getTestRecording, + startTestRecording, +} from "../recorder"; import genericTransform from "../transform"; function createInitChannel() { @@ -77,12 +80,13 @@ export async function wrapRunTest( ): Promise { const [test] = args; - recording.abandon(); + abandonProcessRecordingIfNotAlwaysActive(); + startTestRecording("tests", "vitest", ...testNames(test)); - start(createRecording(test)); const result = fun(...args); await result; + const recording = getTestRecording(); switch (test.result?.state) { case "pass": recording.metadata.test_status = "succeeded"; @@ -102,11 +106,6 @@ export async function wrapRunTest( return result; } -function createRecording(test: Test): Recording { - const recording = new Recording("tests", "vitest", ...testNames(test)); - return recording; -} - function patchRunTest(fd: ESTree.FunctionDeclaration) { const wrapped: ESTree.BlockStatement = { type: "BlockStatement", diff --git a/src/recorder.ts b/src/recorder.ts index 6098ef2e..11216ab6 100644 --- a/src/recorder.ts +++ b/src/recorder.ts @@ -11,7 +11,21 @@ import { FunctionInfo } from "./registry"; import commonPathPrefix from "./util/commonPathPrefix"; import { getTime } from "./util/getTime"; -export let recording: Recording; +const processRecordingShouldAlwaysBeActive = "APPMAP_RECORDER_PROCESS_ALWAYS" in process.env; + +// If APPMAP_RECORDER_PROCESS_ALWAYS is set we can have +// two recordings active simultaneously. Always active +// one for process recording and one for the others +// (request, test, remote) when needed. +let processRecording: Recording; +let nonProcessRecording: Recording; + +export function getActiveRecordings() { + const result = []; + if (processRecording?.running) result.push(processRecording); + if (nonProcessRecording?.running) result.push(nonProcessRecording); + return result; +} export function record( this: This, @@ -19,61 +33,81 @@ export function record( args: unknown[], funInfo: FunctionInfo, ): Return { - if (!recording.running || !shouldRecord()) return fun.apply(this, args); - - const call = recording.functionCall( - funInfo, - isGlobal(this) || isNullPrototype(this) ? undefined : this, - [...args], - ); + const recordings = getActiveRecordings(); + if (recordings.length == 0 || !shouldRecord()) return fun.apply(this, args); - const start = getTime(); + const thisArg = isGlobal(this) || isNullPrototype(this) ? undefined : this; + const callEvents = recordings.map((r) => r.functionCall(funInfo, thisArg, [...args])); + const startTime = getTime(); try { const result = fun.apply(this, args); - const ret = recording.functionReturn(call.id, result, getTime() - start); - return fixReturnEventIfPromiseResult(result, ret, call, start) as Return; + + const elapsed = getTime() - startTime; + const returnEvents = recordings.map((recording, idx) => + recording.functionReturn(callEvents[idx].id, result, elapsed), + ); + return fixReturnEventsIfPromiseResult( + recordings, + result, + returnEvents, + callEvents, + startTime, + ) as Return; } catch (exn: unknown) { - recording.functionException(call.id, exn, getTime() - start); + const elapsed = getTime() - startTime; + recordings.map((recording, idx) => + recording.functionException(callEvents[idx].id, exn, elapsed), + ); throw exn; } } -export function fixReturnEventIfPromiseResult( +export function fixReturnEventsIfPromiseResult( + recordings: Recording[], result: unknown, - returnEvent: AppMap.FunctionReturnEvent, - callEvent: AppMap.CallEvent, + returnEvents: AppMap.FunctionReturnEvent[], + callEvents: AppMap.CallEvent[], startTime: number, ) { - if (isPromise(result) && returnEvent.return_value?.value.includes("")) + // returnEvents would have the same return_value, in case of multiple recordings. + if (isPromise(result) && returnEvents[0].return_value?.value.includes("")) return result.then( (value) => { - const newReturn = makeReturnEvent( - returnEvent.id, - callEvent.id, - result, - getTime() - startTime, - ); - newReturn.return_value!.class = `Promise<${getClass(value)}>`; - recording.fixup(newReturn); + const elapsed = getTime() - startTime; + const promiseClass = `Promise<${getClass(value)}>`; + recordings.map((recording, idx) => { + const newReturn = makeReturnEvent( + returnEvents[idx].id, + callEvents[idx].id, + result, + elapsed, + ); + newReturn.return_value!.class = promiseClass; + recording.fixup(newReturn); + }); return result; }, (reason) => { - const event = makeExceptionEvent( - returnEvent.id, - callEvent.id, - reason, - getTime() - startTime, - ); - // add return_value too, so it's not unambiguous whether the function - // threw or returned a promise which then rejected - event.return_value = { - class: "Promise", - // don't repeat the exception info - value: "Promise { }", - object_id: objectId(result), - }; - recording.fixup(event); + const elapsed = getTime() - startTime; + recordings.map((recording, idx) => { + const event = makeExceptionEvent( + returnEvents[idx].id, + callEvents[idx].id, + reason, + elapsed, + ); + // add return_value too, so it's not unambiguous whether the function + // threw or returned a promise which then rejected + event.return_value = { + class: "Promise", + // don't repeat the exception info + value: "Promise { }", + object_id: objectId(result), + }; + recording.fixup(event); + }); + return result; }, ); @@ -93,23 +127,69 @@ function isNullPrototype(obj: unknown) { return obj != null && Object.getPrototypeOf(obj) === null; } -export function start( - newRecording: Recording = new Recording("process", "process", new Date().toISOString()), +export function abandonProcessRecordingIfNotAlwaysActive() { + if (!processRecordingShouldAlwaysBeActive) processRecording?.abandon(); +} + +export function startProcessRecording() { + if (!processRecordingShouldAlwaysBeActive) assert(!processRecording?.running); + if (!processRecording?.running) + processRecording = new Recording("process", "process", new Date().toISOString()); +} + +export function startTestRecording( + type: AppMap.RecorderType, + recorder: string, + ...names: string[] ) { - assert(!recording?.running); - recording = newRecording; + abandonProcessRecordingIfNotAlwaysActive(); + nonProcessRecording?.abandon(); + nonProcessRecording = new Recording(type, recorder, ...names); +} + +export function startRemoteRecording() { + info("Remote recording started"); + + abandonProcessRecordingIfNotAlwaysActive(); + + nonProcessRecording?.abandon(); + nonProcessRecording = new Recording("remote", "remote", new Date().toISOString()); +} + +export function startRequestRecording(pathname: string): string { + abandonProcessRecordingIfNotAlwaysActive(); + + const timestamp = new Date().toISOString(); + nonProcessRecording?.abandon(); + nonProcessRecording = new Recording("requests", "requests", [timestamp, pathname].join(" ")); + return timestamp; } -start(); +export function startCodeBlockRecording() { + nonProcessRecording = new Recording("block", "block", new Date().toISOString()); +} + +export const getTestRecording = () => getNonProcessRecording("tests"); +export const getRequestRecording = () => getNonProcessRecording("requests"); +export const getRemoteRecording = () => getNonProcessRecording("remote"); +export const getCodeBlockRecording = () => getNonProcessRecording("block"); + +function getNonProcessRecording(type: AppMap.RecorderType) { + assert(nonProcessRecording?.metadata.recorder.type == type); + return nonProcessRecording; +} + +startProcessRecording(); + +function finishRecordings() { + getActiveRecordings().forEach((r) => r.finish()); -function finishRecording() { - recording.finish(); if (writtenAppMaps.length === 1) info("Wrote %s", writtenAppMaps[0]); else if (writtenAppMaps.length > 1) info("Wrote %d AppMaps to %s", writtenAppMaps.length, commonPathPrefix(writtenAppMaps)); } -process.on("exit", finishRecording); +process.on("exit", finishRecordings); const finishSignals: NodeJS.Signals[] = ["SIGINT", "SIGTERM"]; finishSignals.forEach(registerFinishSignalHandler); @@ -119,7 +199,7 @@ function registerFinishSignalHandler(signal: NodeJS.Signals) { if (process.listeners(signal).length > 0) return; const handler = () => { - finishRecording(); + finishRecordings(); process.kill(process.pid, signal); }; diff --git a/src/recorderControl.ts b/src/recorderControl.ts index a3773a91..d2f51ecf 100644 --- a/src/recorderControl.ts +++ b/src/recorderControl.ts @@ -10,8 +10,8 @@ export const enableGlobalRecording = () => (_globalRecordingDisabled = false); export const globalRecordingDisabled = () => _globalRecordingDisabled; let _codeBlockRecordingActive = false; -export const startCodeBlockRecording = () => (_codeBlockRecordingActive = true); -export const stopCodeBlockRecording = () => (_codeBlockRecordingActive = false); +export const setCodeBlockRecordingActive = () => (_codeBlockRecordingActive = true); +export const unsetCodeBlockRecordingActive = () => (_codeBlockRecordingActive = false); export const codeBlockRecordingActive = () => _codeBlockRecordingActive; export const shouldRecord = () => diff --git a/test/__snapshots__/httpServer.test.ts.snap b/test/__snapshots__/httpServer.test.ts.snap index 43b2abea..d9097dbf 100644 --- a/test/__snapshots__/httpServer.test.ts.snap +++ b/test/__snapshots__/httpServer.test.ts.snap @@ -419,7 +419,7 @@ exports[`mapping Express.js requests 1`] = ` { "class": "Object", "name": "obj", - "object_id": 7, + "object_id": 8, "properties": [ { "class": "Number", @@ -447,14 +447,14 @@ exports[`mapping Express.js requests 1`] = ` ], }, "name": "arr", - "object_id": 8, + "object_id": 9, "size": 2, "value": "[ { foo: 43 }, { foo: 44 } ]", }, { "class": "Array", "name": "heterogenous", - "object_id": 9, + "object_id": 10, "size": 2, "value": "[ 42, 'str' ]", }, @@ -609,7 +609,7 @@ exports[`mapping Express.js requests 1`] = ` }, "return_value": { "class": "Object", - "object_id": 10, + "object_id": 7, "properties": [ { "class": "String", @@ -750,7 +750,7 @@ exports[`mapping Express.js requests with remote recording 1`] = ` { "class": "Object", "name": "obj", - "object_id": 7, + "object_id": 8, "properties": [ { "class": "Number", @@ -778,14 +778,14 @@ exports[`mapping Express.js requests with remote recording 1`] = ` ], }, "name": "arr", - "object_id": 8, + "object_id": 9, "size": 2, "value": "[ { foo: 43 }, { foo: 44 } ]", }, { "class": "Array", "name": "heterogenous", - "object_id": 9, + "object_id": 10, "size": 2, "value": "[ 42, 'str' ]", }, @@ -1195,7 +1195,7 @@ exports[`mapping Express.js requests with remote recording 1`] = ` }, "return_value": { "class": "Object", - "object_id": 10, + "object_id": 7, "properties": [ { "class": "String", @@ -1483,6 +1483,351 @@ exports[`mapping node:http requests 1`] = ` } `; +exports[`mapping node:http requests with process recording active 1`] = ` +{ + "./tmp/appmap/process/.appmap.json": { + "classMap": [], + "events": [ + { + "event": "call", + "http_server_request": { + "headers": { + "Host": "127.0.0.1:27627", + }, + "path_info": "/", + "protocol": "HTTP/1.1", + "request_method": "GET", + }, + "id": 1, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "http_server_response": { + "headers": {}, + "status_code": 200, + }, + "id": 2, + "parent_id": 1, + "thread_id": 0, + }, + { + "event": "call", + "http_server_request": { + "headers": { + "Host": "127.0.0.1:27627", + }, + "path_info": "/nonexistent", + "protocol": "HTTP/1.1", + "request_method": "GET", + }, + "id": 3, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "http_server_response": { + "headers": {}, + "status_code": 200, + }, + "id": 4, + "parent_id": 3, + "thread_id": 0, + }, + { + "event": "call", + "http_server_request": { + "headers": { + "Host": "127.0.0.1:27627", + }, + "path_info": "/api/foo", + "protocol": "HTTP/1.1", + "request_method": "GET", + }, + "id": 5, + "message": [ + { + "class": "String", + "name": "param1", + "value": "'3'", + }, + { + "class": "String", + "name": "param2", + "value": "'4'", + }, + ], + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "http_server_response": { + "headers": {}, + "status_code": 200, + }, + "id": 6, + "parent_id": 5, + "thread_id": 0, + }, + { + "event": "call", + "http_server_request": { + "headers": { + "Content-Type": "application/json", + "Host": "127.0.0.1:27627", + "Transfer-Encoding": "chunked", + }, + "path_info": "/api/bar", + "protocol": "HTTP/1.1", + "request_method": "POST", + }, + "id": 7, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "http_server_response": { + "headers": {}, + "status_code": 204, + }, + "id": 8, + "parent_id": 7, + "thread_id": 0, + }, + ], + "metadata": { + "app": "http-server-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "test process recording", + "recorder": { + "name": "process", + "type": "process", + }, + }, + "version": "1.12", + }, + "./tmp/appmap/requests/_-.appmap.json": { + "classMap": [], + "events": [ + { + "event": "call", + "http_server_request": { + "headers": { + "Host": "127.0.0.1:27627", + }, + "path_info": "/", + "protocol": "HTTP/1.1", + "request_method": "GET", + }, + "id": 1, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "http_server_response": { + "headers": {}, + "status_code": 200, + }, + "id": 2, + "parent_id": 1, + "thread_id": 0, + }, + ], + "metadata": { + "app": "http-server-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "GET / (200) — ", + "recorder": { + "name": "requests", + "type": "requests", + }, + }, + "version": "1.12", + }, + "./tmp/appmap/requests/_-nonexistent.appmap.json": { + "classMap": [], + "events": [ + { + "event": "call", + "http_server_request": { + "headers": { + "Host": "127.0.0.1:27627", + }, + "path_info": "/nonexistent", + "protocol": "HTTP/1.1", + "request_method": "GET", + }, + "id": 1, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "http_server_response": { + "headers": {}, + "status_code": 200, + }, + "id": 2, + "parent_id": 1, + "thread_id": 0, + }, + ], + "metadata": { + "app": "http-server-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "GET /nonexistent (200) — ", + "recorder": { + "name": "requests", + "type": "requests", + }, + }, + "version": "1.12", + }, + "./tmp/appmap/requests/_-api-foo.appmap.json": { + "classMap": [], + "events": [ + { + "event": "call", + "http_server_request": { + "headers": { + "Host": "127.0.0.1:27627", + }, + "path_info": "/api/foo", + "protocol": "HTTP/1.1", + "request_method": "GET", + }, + "id": 1, + "message": [ + { + "class": "String", + "name": "param1", + "value": "'3'", + }, + { + "class": "String", + "name": "param2", + "value": "'4'", + }, + ], + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "http_server_response": { + "headers": {}, + "status_code": 200, + }, + "id": 2, + "parent_id": 1, + "thread_id": 0, + }, + ], + "metadata": { + "app": "http-server-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "GET /api/foo (200) — ", + "recorder": { + "name": "requests", + "type": "requests", + }, + }, + "version": "1.12", + }, + "./tmp/appmap/requests/_-api-bar.appmap.json": { + "classMap": [], + "events": [ + { + "event": "call", + "http_server_request": { + "headers": { + "Content-Type": "application/json", + "Host": "127.0.0.1:27627", + "Transfer-Encoding": "chunked", + }, + "path_info": "/api/bar", + "protocol": "HTTP/1.1", + "request_method": "POST", + }, + "id": 1, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "http_server_response": { + "headers": {}, + "status_code": 204, + }, + "id": 2, + "parent_id": 1, + "thread_id": 0, + }, + ], + "metadata": { + "app": "http-server-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "POST /api/bar (204) — ", + "recorder": { + "name": "requests", + "type": "requests", + }, + }, + "version": "1.12", + }, +} +`; + exports[`mapping node:http requests with remote recording 1`] = ` { "classMap": [], diff --git a/test/__snapshots__/jest.test.ts.snap b/test/__snapshots__/jest.test.ts.snap index c6d60899..c18b6718 100644 --- a/test/__snapshots__/jest.test.ts.snap +++ b/test/__snapshots__/jest.test.ts.snap @@ -444,3 +444,737 @@ Received: 3", }, } `; + +exports[`mapping Jest tests with process recording active mode 1`] = ` +{ + "./tmp/appmap/jest/exception_handling/intentionally_throws.appmap.json": { + "classMap": [ + { + "children": [ + { + "children": [ + { + "location": "test.js:18", + "name": "errorOut", + "static": true, + "type": "function", + }, + ], + "name": "test", + "type": "class", + }, + ], + "name": "jest-appmap-node-test", + "type": "package", + }, + ], + "events": [ + { + "defined_class": "test", + "event": "call", + "id": 1, + "lineno": 18, + "method_id": "errorOut", + "parameters": [], + "path": "test.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "exceptions": [ + { + "class": "TestError", + "message": "test error", + "object_id": 2, + }, + ], + "id": 2, + "parent_id": 1, + "thread_id": 0, + }, + ], + "metadata": { + "app": "jest-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "exception": { + "class": "TestError", + "message": "test error", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "exception handling intentionally throws", + "recorder": { + "name": "jest", + "type": "tests", + }, + "test_status": "failed", + }, + "version": "1.12", + }, + "./tmp/appmap/jest/exception_handling/times_out.appmap.json": { + "classMap": [ + { + "children": [ + { + "children": [ + { + "location": "test.js:22", + "name": "wait", + "static": true, + "type": "function", + }, + ], + "name": "test", + "type": "class", + }, + ], + "name": "jest-appmap-node-test", + "type": "package", + }, + ], + "events": [ + { + "defined_class": "test", + "event": "call", + "id": 1, + "lineno": 22, + "method_id": "wait", + "parameters": [ + { + "class": "Number", + "name": "ms", + "value": "20", + }, + ], + "path": "test.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 2, + "parent_id": 1, + "return_value": { + "class": "Promise", + "object_id": 3, + "value": "Promise { }", + }, + "thread_id": 0, + }, + ], + "metadata": { + "app": "jest-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "exception": { + "class": "String", + "message": "Exceeded timeout of 10 ms for a test. +Add a timeout value to this test to increase the timeout, if this is a long-running test. See https://jestjs.io/docs/api#testname-fn-timeout.", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "exception handling times out", + "recorder": { + "name": "jest", + "type": "tests", + }, + "test_status": "failed", + }, + "version": "1.12", + }, + "./tmp/appmap/jest/jest_test_with_async_library/instrumented_lambda_does_not_cause_timeout.appmap.json": { + "classMap": [ + { + "children": [ + { + "children": [ + { + "location": "asyncLib.test.js:4", + "name": "lambda1", + "static": true, + "type": "function", + }, + ], + "name": "asyncLib.test", + "type": "class", + }, + ], + "name": "jest-appmap-node-test", + "type": "package", + }, + ], + "eventUpdates": { + "2": { + "elapsed": 31.337, + "event": "return", + "id": 2, + "parent_id": 1, + "return_value": { + "class": "Promise", + "object_id": 4, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, + "4": { + "elapsed": 31.337, + "event": "return", + "id": 4, + "parent_id": 3, + "return_value": { + "class": "Promise", + "object_id": 5, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, + }, + "events": [ + { + "defined_class": "asyncLib.test", + "event": "call", + "id": 1, + "lineno": 4, + "method_id": "lambda1", + "parameters": [ + { + "class": "String", + "name": "r", + "value": "'task1'", + }, + ], + "path": "asyncLib.test.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 2, + "parent_id": 1, + "return_value": { + "class": "Promise", + "object_id": 4, + "value": "Promise { }", + }, + "thread_id": 0, + }, + { + "defined_class": "asyncLib.test", + "event": "call", + "id": 3, + "lineno": 4, + "method_id": "lambda1", + "parameters": [ + { + "class": "String", + "name": "r", + "value": "'task2'", + }, + ], + "path": "asyncLib.test.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 4, + "parent_id": 3, + "return_value": { + "class": "Promise", + "object_id": 5, + "value": "Promise { }", + }, + "thread_id": 0, + }, + ], + "metadata": { + "app": "jest-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "jest test with async library instrumented lambda does not cause timeout", + "recorder": { + "name": "jest", + "type": "tests", + }, + "test_status": "succeeded", + }, + "version": "1.12", + }, + "./tmp/appmap/jest/sub/subtracts_numbers_correctly.appmap.json": { + "classMap": [ + { + "children": [ + { + "children": [ + { + "location": "calc.js:1", + "name": "sum", + "static": true, + "type": "function", + }, + ], + "name": "calc", + "type": "class", + }, + ], + "name": "jest-appmap-node-test", + "type": "package", + }, + ], + "events": [ + { + "defined_class": "calc", + "event": "call", + "id": 1, + "lineno": 1, + "method_id": "sum", + "parameters": [ + { + "class": "Number", + "name": "x", + "value": "1", + }, + { + "class": "Number", + "name": "y", + "value": "2", + }, + ], + "path": "calc.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 2, + "parent_id": 1, + "return_value": { + "class": "Number", + "value": "3", + }, + "thread_id": 0, + }, + ], + "metadata": { + "app": "jest-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "exception": { + "class": "JestAssertionError", + "message": "expect(received).toBe(expected) // Object.is equality + +Expected: -1 +Received: 3", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "sub subtracts numbers correctly", + "recorder": { + "name": "jest", + "type": "tests", + }, + "test_status": "failed", + }, + "version": "1.12", + }, + "./tmp/appmap/jest/sum/sums_numbers_correctly.appmap.json": { + "classMap": [ + { + "children": [ + { + "children": [ + { + "location": "calc.js:1", + "name": "sum", + "static": true, + "type": "function", + }, + ], + "name": "calc", + "type": "class", + }, + ], + "name": "jest-appmap-node-test", + "type": "package", + }, + ], + "events": [ + { + "defined_class": "calc", + "event": "call", + "id": 1, + "lineno": 1, + "method_id": "sum", + "parameters": [ + { + "class": "Number", + "name": "x", + "value": "1", + }, + { + "class": "Number", + "name": "y", + "value": "2", + }, + ], + "path": "calc.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 2, + "parent_id": 1, + "return_value": { + "class": "Number", + "value": "3", + }, + "thread_id": 0, + }, + ], + "metadata": { + "app": "jest-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "sum sums numbers correctly", + "recorder": { + "name": "jest", + "type": "tests", + }, + "test_status": "succeeded", + }, + "version": "1.12", + }, + "./tmp/appmap/process/.appmap.json": { + "classMap": [ + { + "children": [ + { + "children": [ + { + "location": "asyncLib.test.js:4", + "name": "lambda1", + "static": true, + "type": "function", + }, + ], + "name": "asyncLib.test", + "type": "class", + }, + { + "children": [ + { + "location": "calc.js:1", + "name": "sum", + "static": true, + "type": "function", + }, + ], + "name": "calc", + "type": "class", + }, + { + "children": [ + { + "location": "test.js:18", + "name": "errorOut", + "static": true, + "type": "function", + }, + { + "location": "test.js:22", + "name": "wait", + "static": true, + "type": "function", + }, + ], + "name": "test", + "type": "class", + }, + ], + "name": "jest-appmap-node-test", + "type": "package", + }, + ], + "eventUpdates": { + "10": { + "elapsed": 31.337, + "event": "return", + "id": 10, + "parent_id": 9, + "return_value": { + "class": "Promise", + "object_id": 4, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, + "12": { + "elapsed": 31.337, + "event": "return", + "id": 12, + "parent_id": 11, + "return_value": { + "class": "Promise", + "object_id": 5, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, + "8": { + "elapsed": 31.337, + "event": "return", + "id": 8, + "parent_id": 7, + "return_value": { + "class": "Promise", + "object_id": 3, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, + }, + "events": [ + { + "defined_class": "calc", + "event": "call", + "id": 1, + "lineno": 1, + "method_id": "sum", + "parameters": [ + { + "class": "Number", + "name": "x", + "value": "1", + }, + { + "class": "Number", + "name": "y", + "value": "2", + }, + ], + "path": "calc.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 2, + "parent_id": 1, + "return_value": { + "class": "Number", + "value": "3", + }, + "thread_id": 0, + }, + { + "defined_class": "calc", + "event": "call", + "id": 3, + "lineno": 1, + "method_id": "sum", + "parameters": [ + { + "class": "Number", + "name": "x", + "value": "1", + }, + { + "class": "Number", + "name": "y", + "value": "2", + }, + ], + "path": "calc.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 4, + "parent_id": 3, + "return_value": { + "class": "Number", + "value": "3", + }, + "thread_id": 0, + }, + { + "defined_class": "test", + "event": "call", + "id": 5, + "lineno": 18, + "method_id": "errorOut", + "parameters": [], + "path": "test.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "exceptions": [ + { + "class": "TestError", + "message": "test error", + "object_id": 2, + }, + ], + "id": 6, + "parent_id": 5, + "thread_id": 0, + }, + { + "defined_class": "test", + "event": "call", + "id": 7, + "lineno": 22, + "method_id": "wait", + "parameters": [ + { + "class": "Number", + "name": "ms", + "value": "20", + }, + ], + "path": "test.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 8, + "parent_id": 7, + "return_value": { + "class": "Promise", + "object_id": 3, + "value": "Promise { }", + }, + "thread_id": 0, + }, + { + "defined_class": "asyncLib.test", + "event": "call", + "id": 9, + "lineno": 4, + "method_id": "lambda1", + "parameters": [ + { + "class": "String", + "name": "r", + "value": "'task1'", + }, + ], + "path": "asyncLib.test.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 10, + "parent_id": 9, + "return_value": { + "class": "Promise", + "object_id": 4, + "value": "Promise { }", + }, + "thread_id": 0, + }, + { + "defined_class": "asyncLib.test", + "event": "call", + "id": 11, + "lineno": 4, + "method_id": "lambda1", + "parameters": [ + { + "class": "String", + "name": "r", + "value": "'task2'", + }, + ], + "path": "asyncLib.test.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 12, + "parent_id": 11, + "return_value": { + "class": "Promise", + "object_id": 5, + "value": "Promise { }", + }, + "thread_id": 0, + }, + ], + "metadata": { + "app": "jest-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "test process recording", + "recorder": { + "name": "process", + "type": "process", + }, + }, + "version": "1.12", + }, +} +`; diff --git a/test/__snapshots__/mocha.test.ts.snap b/test/__snapshots__/mocha.test.ts.snap index 92d67b1f..aac950b2 100644 --- a/test/__snapshots__/mocha.test.ts.snap +++ b/test/__snapshots__/mocha.test.ts.snap @@ -235,3 +235,391 @@ exports[`mapping Mocha tests 1`] = ` }, } `; + +exports[`mapping Mocha tests with process recording active mode 1`] = ` +{ + "./tmp/appmap/mocha/exception_handling/intentionally_throws.appmap.json": { + "classMap": [ + { + "children": [ + { + "children": [ + { + "location": "test.js:18", + "name": "errorOut", + "static": true, + "type": "function", + }, + ], + "name": "test", + "type": "class", + }, + ], + "name": "mocha-appmap-node-test", + "type": "package", + }, + ], + "events": [ + { + "defined_class": "test", + "event": "call", + "id": 1, + "lineno": 18, + "method_id": "errorOut", + "parameters": [], + "path": "test.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "exceptions": [ + { + "class": "TestError", + "message": "test error", + "object_id": 2, + }, + ], + "id": 2, + "parent_id": 1, + "thread_id": 0, + }, + ], + "metadata": { + "app": "mocha-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "exception": { + "class": "TestError", + "message": "test error", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "exception handling intentionally throws", + "recorder": { + "name": "mocha", + "type": "tests", + }, + "test_status": "failed", + }, + "version": "1.12", + }, + "./tmp/appmap/mocha/multiply/calculates_power_correctly.appmap.json": { + "classMap": [ + { + "children": [ + { + "children": [ + { + "location": "calc.js:5", + "name": "power", + "static": true, + "type": "function", + }, + ], + "name": "calc", + "type": "class", + }, + ], + "name": "mocha-appmap-node-test", + "type": "package", + }, + ], + "events": [ + { + "defined_class": "calc", + "event": "call", + "id": 1, + "lineno": 5, + "method_id": "power", + "parameters": [ + { + "class": "Number", + "name": "x", + "value": "3", + }, + { + "class": "Number", + "name": "y", + "value": "2", + }, + ], + "path": "calc.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 2, + "parent_id": 1, + "return_value": { + "class": "Number", + "value": "8", + }, + "thread_id": 0, + }, + ], + "metadata": { + "app": "mocha-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "exception": { + "class": "AssertionError", + "message": "8 == 9", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "multiply calculates power correctly", + "recorder": { + "name": "mocha", + "type": "tests", + }, + "test_status": "failed", + }, + "version": "1.12", + }, + "./tmp/appmap/mocha/multiply/multiplies_numbers_correctly.appmap.json": { + "classMap": [ + { + "children": [ + { + "children": [ + { + "location": "calc.js:1", + "name": "multiply", + "static": true, + "type": "function", + }, + ], + "name": "calc", + "type": "class", + }, + ], + "name": "mocha-appmap-node-test", + "type": "package", + }, + ], + "events": [ + { + "defined_class": "calc", + "event": "call", + "id": 1, + "lineno": 1, + "method_id": "multiply", + "parameters": [ + { + "class": "Number", + "name": "x", + "value": "2", + }, + { + "class": "Number", + "name": "y", + "value": "5", + }, + ], + "path": "calc.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 2, + "parent_id": 1, + "return_value": { + "class": "Number", + "value": "10", + }, + "thread_id": 0, + }, + ], + "metadata": { + "app": "mocha-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "multiply multiplies numbers correctly", + "recorder": { + "name": "mocha", + "type": "tests", + }, + "test_status": "succeeded", + }, + "version": "1.12", + }, + "./tmp/appmap/process/.appmap.json": { + "classMap": [ + { + "children": [ + { + "children": [ + { + "location": "calc.js:1", + "name": "multiply", + "static": true, + "type": "function", + }, + { + "location": "calc.js:5", + "name": "power", + "static": true, + "type": "function", + }, + ], + "name": "calc", + "type": "class", + }, + { + "children": [ + { + "location": "test.js:18", + "name": "errorOut", + "static": true, + "type": "function", + }, + ], + "name": "test", + "type": "class", + }, + ], + "name": "mocha-appmap-node-test", + "type": "package", + }, + ], + "events": [ + { + "defined_class": "calc", + "event": "call", + "id": 1, + "lineno": 1, + "method_id": "multiply", + "parameters": [ + { + "class": "Number", + "name": "x", + "value": "2", + }, + { + "class": "Number", + "name": "y", + "value": "5", + }, + ], + "path": "calc.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 2, + "parent_id": 1, + "return_value": { + "class": "Number", + "value": "10", + }, + "thread_id": 0, + }, + { + "defined_class": "calc", + "event": "call", + "id": 3, + "lineno": 5, + "method_id": "power", + "parameters": [ + { + "class": "Number", + "name": "x", + "value": "3", + }, + { + "class": "Number", + "name": "y", + "value": "2", + }, + ], + "path": "calc.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 4, + "parent_id": 3, + "return_value": { + "class": "Number", + "value": "8", + }, + "thread_id": 0, + }, + { + "defined_class": "test", + "event": "call", + "id": 5, + "lineno": 18, + "method_id": "errorOut", + "parameters": [], + "path": "test.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "exceptions": [ + { + "class": "TestError", + "message": "test error", + "object_id": 2, + }, + ], + "id": 6, + "parent_id": 5, + "thread_id": 0, + }, + ], + "metadata": { + "app": "mocha-appmap-node-test", + "client": { + "name": "appmap-node", + "url": "https://github.com/getappmap/appmap-node", + "version": "test node-appmap version", + }, + "language": { + "engine": "Node.js", + "name": "javascript", + "version": "test node version", + }, + "name": "test process recording", + "recorder": { + "name": "process", + "type": "process", + }, + }, + "version": "1.12", + }, +} +`; diff --git a/test/helpers.ts b/test/helpers.ts index d4c7ff85..c43ffe66 100644 --- a/test/helpers.ts +++ b/test/helpers.ts @@ -13,8 +13,20 @@ import fwdSlashPath from "../src/util/fwdSlashPath"; const binPath = resolve(__dirname, "../bin/appmap-node.js"); export function runAppmapNode(...args: string[]) { + return runAppmapNodeWithOptions({}, ...args); +} + +export function spawnAppmapNode(...args: string[]) { + return spawnAppmapNodeWithOptions({}, ...args); +} + +export interface SpawnAppmapNodeOptions { + env?: NodeJS.ProcessEnv; +} + +export function runAppmapNodeWithOptions(options: SpawnAppmapNodeOptions, ...args: string[]) { console.debug("Running %s %s", binPath, args.join(" ")); - const result = spawnSync(process.argv[0], [binPath, ...args], { cwd: target }); + const result = spawnSync(process.argv[0], [binPath, ...args], { cwd: target, ...options }); let message = ""; if (result.stdout.length > 0) message += "stdout:\n" + result.stdout.toString(); if (result.stderr.length > 0) message += "stderr:\n" + result.stderr.toString(); @@ -22,9 +34,12 @@ export function runAppmapNode(...args: string[]) { return result; } -export function spawnAppmapNode(...args: string[]): ChildProcessWithoutNullStreams { +export function spawnAppmapNodeWithOptions( + options: SpawnAppmapNodeOptions, + ...args: string[] +): ChildProcessWithoutNullStreams { console.debug("Running %s %s", binPath, args.join(" ")); - const result = spawn(process.argv[0], [binPath, ...args], { cwd: target }); + const result = spawn(process.argv[0], [binPath, ...args], { cwd: target, ...options }); result.stdout.on("data", (chunk: Buffer) => console.debug("stdout: %s", chunk)); result.stderr.on("data", (chunk: Buffer) => console.debug("stderr: %s", chunk)); return result; diff --git a/test/httpServer.test.ts b/test/httpServer.test.ts index 31bd524c..c89a4e1b 100644 --- a/test/httpServer.test.ts +++ b/test/httpServer.test.ts @@ -1,6 +1,12 @@ import { type IncomingMessage, request, OutgoingMessage } from "node:http"; -import { fixAppmap, integrationTest, readAppmaps, spawnAppmapNode } from "./helpers"; +import { + SpawnAppmapNodeOptions, + fixAppmap, + integrationTest, + readAppmaps, + spawnAppmapNodeWithOptions, +} from "./helpers"; import { ChildProcessWithoutNullStreams } from "child_process"; integrationTest("mapping Express.js requests", async () => { @@ -23,6 +29,23 @@ integrationTest("mapping node:http requests", async () => { expect(readAppmaps()).toMatchSnapshot(); }); +integrationTest("mapping node:http requests with process recording active", async () => { + expect.assertions(3); + const server = await spawnServer("vanilla.js", { + env: { ...process.env, APPMAP_RECORDER_PROCESS_ALWAYS: "true" }, + }); + await makeRequests(); + // Wait for the last request to finish + await awaitStdoutOnData(server, "api-bar.appmap.json"); + await killServer(server); + + const appmaps = readAppmaps(); + const appmapsArray = Object.values(appmaps); + expect(appmapsArray.filter((a) => a.metadata?.recorder.type == "process").length).toEqual(1); + expect(appmapsArray.filter((a) => a.metadata?.recorder.type == "requests").length).toEqual(4); + expect(appmaps).toMatchSnapshot(); +}); + integrationTest("mapping Express.js requests with remote recording", async () => { expect.assertions(1); const server = await spawnServer("express.js"); @@ -68,8 +91,8 @@ async function makeRequests() { }); } -async function spawnServer(script: string) { - const server = spawnAppmapNode(script); +async function spawnServer(script: string, options: SpawnAppmapNodeOptions = {}) { + const server = spawnAppmapNodeWithOptions(options, script); await awaitStdoutOnData(server, "listening"); return server; } diff --git a/test/jest.test.ts b/test/jest.test.ts index 98550394..6829980b 100644 --- a/test/jest.test.ts +++ b/test/jest.test.ts @@ -1,7 +1,26 @@ -import { integrationTest, readAppmaps, runAppmapNode } from "./helpers"; +import { integrationTest, readAppmaps, runAppmapNode, runAppmapNodeWithOptions } from "./helpers"; integrationTest("mapping Jest tests", () => { expect(runAppmapNode("yarn", "jest", "test", "--color").status).toBe(1); expect(runAppmapNode("yarn", "jest", "asyncLib", "--color").status).toBe(0); expect(readAppmaps()).toMatchSnapshot(); }); + +integrationTest("mapping Jest tests with process recording active", () => { + expect( + runAppmapNodeWithOptions( + { + env: { ...process.env, APPMAP_RECORDER_PROCESS_ALWAYS: "true" }, + }, + "yarn", + "jest", + "test", + "--color", + ).status, + ).toBe(1); + const appmaps = readAppmaps(); + const appmapsArray = Object.values(appmaps); + expect(appmapsArray.filter((a) => a.metadata?.recorder.type == "process").length).toEqual(1); + expect(appmapsArray.filter((a) => a.metadata?.recorder.type == "tests").length).toEqual(5); + expect(appmaps).toMatchSnapshot(); +}); diff --git a/test/mocha.test.ts b/test/mocha.test.ts index 3c2eda2b..2cd81a10 100644 --- a/test/mocha.test.ts +++ b/test/mocha.test.ts @@ -1,6 +1,23 @@ -import { integrationTest, readAppmaps, runAppmapNode } from "./helpers"; +import { integrationTest, readAppmaps, runAppmapNode, runAppmapNodeWithOptions } from "./helpers"; integrationTest("mapping Mocha tests", () => { expect(runAppmapNode("yarn", "mocha").status).toBeGreaterThan(0); expect(readAppmaps()).toMatchSnapshot(); }); + +integrationTest("mapping Mocha tests with process recording active", () => { + expect( + runAppmapNodeWithOptions( + { + env: { ...process.env, APPMAP_RECORDER_PROCESS_ALWAYS: "true" }, + }, + "yarn", + "mocha", + ).status, + ).toBeGreaterThan(0); + const appmaps = readAppmaps(); + const appmapsArray = Object.values(appmaps); + expect(appmapsArray.filter((a) => a.metadata?.recorder.type == "process").length).toEqual(1); + expect(appmapsArray.filter((a) => a.metadata?.recorder.type == "tests").length).toEqual(3); + expect(appmaps).toMatchSnapshot(); +});