From e7a1e73b3b14a01165be2f6784882efd27736027 Mon Sep 17 00:00:00 2001 From: zermelo-wisen Date: Wed, 24 Jul 2024 10:58:56 +0300 Subject: [PATCH] feat: Async context tracking --- src/AppMapStream.ts | 2 +- src/Recording.ts | 97 +++- src/__tests__/AppMapStream.test.ts | 4 +- src/hooks/prisma.ts | 55 +- src/recorder.ts | 6 +- test/__snapshots__/httpClient.test.ts.snap | 288 +++------- test/__snapshots__/jest.test.ts.snap | 34 +- test/__snapshots__/mysql.test.ts.snap | 146 ++--- test/__snapshots__/prisma.test.ts.snap | 590 +-------------------- test/__snapshots__/simple.test.ts.snap | 537 +++++++++++++++++-- test/__snapshots__/sqlite.test.ts.snap | 125 ++--- test/simple.test.ts | 5 + test/simple/async.mjs | 26 + 13 files changed, 839 insertions(+), 1076 deletions(-) create mode 100644 test/simple/async.mjs diff --git a/src/AppMapStream.ts b/src/AppMapStream.ts index 534ea6fb..8906524b 100644 --- a/src/AppMapStream.ts +++ b/src/AppMapStream.ts @@ -29,7 +29,7 @@ export default class AppMapStream { return true; } - public emit(event: unknown) { + public push(event: unknown) { if (this.fd === undefined) this.fd = this.open(); else writeSync(this.fd, ","); writeSync(this.fd, JSON.stringify(event)); diff --git a/src/Recording.ts b/src/Recording.ts index 0ef768be..3e69ea76 100644 --- a/src/Recording.ts +++ b/src/Recording.ts @@ -1,4 +1,5 @@ import assert from "node:assert"; +import { AsyncLocalStorage } from "node:async_hooks"; import { readFileSync, renameSync, rmSync } from "node:fs"; import { join } from "node:path"; import { inspect } from "node:util"; @@ -13,8 +14,8 @@ import { defaultMetadata } from "./metadata"; import { parameter } from "./parameter"; import type { FunctionInfo } from "./registry"; import compactObject from "./util/compactObject"; -import { shouldRecord } from "./recorderControl"; import { getTime } from "./util/getTime"; +import { warn } from "./message"; export default class Recording { constructor(type: AppMap.RecorderType, recorder: string, ...names: string[]) { @@ -32,7 +33,7 @@ export default class Recording { private nextId = 1; private functionsSeen = new Set(); - private stream: AppMapStream | undefined; + private stream: AppMapStream; private partPath: string; public readonly path; public metadata: AppMap.Metadata; @@ -198,30 +199,25 @@ export default class Recording { return event; } - private emit(event: unknown) { - // Check here if we should record instead of requiring each - // possible hook to check it. - // This is also checked in recorder.record() to prevent - // unnecessary event object creation. Checking this inside hooks, - // (http, sqlite, pg, mysql, ...) will save some CPU cycles but - // will complicate their code. - if (!shouldRecord()) return; - assert(this.stream); - this.stream.emit(event); - } - private eventUpdates: Record = {}; fixup(event: AppMap.Event) { - this.eventUpdates[event.id] = event; + if (this.bufferedEvents.has(event.id)) { + const buffered = this.bufferedEvents.get(event.id)!; + if (event === buffered) return; + else Object.assign(buffered, event); + } else this.eventUpdates[event.id] = event; } abandon(): void { - if (this.stream?.close()) rmSync(this.partPath); - this.stream = undefined; + if (this.running && this.stream?.close()) rmSync(this.partPath); + this.running = false; + this.disposeBufferedEvents(Recording.rootBuffer); } finish(): boolean { + if (!this.running) return false; + this.passEvents(this.stream, Recording.rootBuffer); const written = this.stream?.close( compactObject({ classMap: makeClassMap(this.functionsSeen.keys()), @@ -229,24 +225,85 @@ export default class Recording { eventUpdates: Object.keys(this.eventUpdates).length > 0 ? this.eventUpdates : undefined, }), ); - this.stream = undefined; if (written) { renameSync(this.partPath, this.path); writtenAppMaps.push(this.path); } + this.running = false; + this.disposeBufferedEvents(Recording.rootBuffer); return !!written; } - get running(): boolean { - return !!this.stream; + public running = true; + + private bufferedEvents = new Map(); + + public emit(event: AppMap.Event) { + if (!this.running) { + warn("event emitted while recording not running"); + return; + } + if (Recording.buffering) { + this.bufferedEvents.set(event.id, event); + Recording.buffer.push({ event, owner: new WeakRef(this) }); + } else this.stream.push(event); + } + + private static rootBuffer: EventBuffer = []; + private static asyncStorage = new AsyncLocalStorage(); + + private static get buffering(): boolean { + return Recording.rootBuffer.length > 0; + } + + private static get buffer(): EventBuffer { + return Recording.asyncStorage.getStore() ?? Recording.rootBuffer; + } + + public static fork(fun: () => T): T { + const forked: EventBuffer = []; + Recording.buffer.push(forked); + return Recording.asyncStorage.run(forked, fun); + } + + public static run(context: EventBuffer | undefined, fun: () => void) { + if (context) Recording.asyncStorage.run(context, fun); + else fun(); + } + + public static getContext() { + return Recording.asyncStorage.getStore(); } readAppMap(): AppMap.AppMap { assert(!this.running); return JSON.parse(readFileSync(this.path, "utf8")) as AppMap.AppMap; } + + private passEvents(stream: AppMapStream, buffer: EventBuffer) { + for (const event of buffer) { + if (Array.isArray(event)) this.passEvents(stream, event); + else if (event?.owner.deref() == this) stream.push(event.event); + } + } + + private disposeBufferedEvents(buffer: EventBuffer) { + for (let i = 0; i < buffer.length; i++) { + const event = buffer[i]; + if (Array.isArray(event)) this.disposeBufferedEvents(event); + else if (event?.owner.deref() == this) buffer[i] = null; + } + } } +interface EventWithOwner { + owner: WeakRef; + event: AppMap.Event; +} + +type EventOrBuffer = EventWithOwner | null | EventOrBuffer[]; +export type EventBuffer = EventOrBuffer[]; + export const writtenAppMaps: string[] = []; function makeAppMapFilename(name: string): string { diff --git a/src/__tests__/AppMapStream.test.ts b/src/__tests__/AppMapStream.test.ts index 5b1f1eef..358b50c0 100644 --- a/src/__tests__/AppMapStream.test.ts +++ b/src/__tests__/AppMapStream.test.ts @@ -17,8 +17,8 @@ describe(AppMapStream, () => { const stream = new AppMapStream("./test.appmap.json"); expect(stream.seenAny).toBe(false); - stream.emit({ event: "call" }); - stream.emit({ event: "return" }); + stream.push({ event: "call" }); + stream.push({ event: "return" }); expect(stream.close()).toBe(true); expect(stream.seenAny).toBe(true); diff --git a/src/hooks/prisma.ts b/src/hooks/prisma.ts index 6dc2ec72..bec2fcc6 100644 --- a/src/hooks/prisma.ts +++ b/src/hooks/prisma.ts @@ -9,6 +9,8 @@ import { getActiveRecordings } from "../recorder"; import { FunctionInfo } from "../registry"; import config from "../config"; import { setCustomInspect } from "../parameter"; +import { isPromise } from "node:util/types"; +import Recording, { EventBuffer } from "../Recording"; const patchedModules = new WeakSet(); const sqlHookAttachedPrismaClientInstances = new WeakSet(); @@ -124,6 +126,15 @@ function getFunctionInfo(model: string, action: string, moduleId: string) { // than 2 levels deep structure. const argsCustomInspect = (v: unknown) => inspect(v, { customInspect: true, depth: 10 }); +// We need to create sql events in the same async context with the function call +// events created to represent Prisma query methods. Context is remembered between +// the function call and return events (created after promise is settled) of a Prisma +// query method. On the other hand, events created by listening to direct queries +// sent with prisma.$queryRaw() for example may not appear inside the context of the +// async function running prisma.$queryRaw() because we won't have the same context +// in the callback. +let queryMethodContext: EventBuffer | undefined; + function createPrismaClientMethodProxy unknown>( prismaClientMethod: T, moduleId: string, @@ -139,9 +150,17 @@ function createPrismaClientMethodProxy unknown const action = requestParams.action; const model = requestParams.model; const argsArg = [setCustomInspect(requestParams.args, argsCustomInspect)]; - prismaCalls = recordings.map((recording) => - recording.functionCall(getFunctionInfo(model, action, moduleId), model, argsArg), - ); + + queryMethodContext = Recording.getContext(); + + prismaCalls = recordings.map((recording) => { + const result = recording.functionCall( + getFunctionInfo(model, action, moduleId), + model, + argsArg, + ); + return result; + }); } } @@ -151,9 +170,14 @@ function createPrismaClientMethodProxy unknown try { const result = target.apply(thisArg, argArray); - recordings.forEach((recording, idx) => - recording.functionReturn(calls[idx].id, result, startTime), - ); + assert(isPromise(result)); + void result.finally(() => { + queryMethodContext = undefined; + recordings.forEach((recording, idx) => + recording.functionReturn(calls[idx].id, result, startTime), + ); + }); + return result; } catch (exn: unknown) { recordings.forEach((recording, idx) => @@ -190,12 +214,17 @@ function attachSqlHook(thisArg: unknown) { assert("$on" in thisArg && typeof thisArg.$on === "function"); thisArg.$on("query", (queryEvent: QueryEvent) => { const recordings = getActiveRecordings(); - const callEvents = recordings.map((recording) => recording.sqlQuery(dbType, queryEvent.query)); - const elapsedSec = queryEvent.duration / 1000.0; - // Give a startTime so that functionReturn calculates same elapsedSec - const startTime = getTime() - elapsedSec; - recordings.forEach((recording, idx) => - recording.functionReturn(callEvents[idx].id, undefined, startTime), - ); + + Recording.run(queryMethodContext, () => { + const callEvents = recordings.map((recording) => + recording.sqlQuery(dbType, queryEvent.query), + ); + const elapsedSec = queryEvent.duration / 1000.0; + // Give a startTime so that functionReturn calculates same elapsedSec + const startTime = getTime() - elapsedSec; + recordings.forEach((recording, idx) => + recording.functionReturn(callEvents[idx].id, undefined, startTime), + ); + }); }); } diff --git a/src/recorder.ts b/src/recorder.ts index 439bd735..eb19f1e4 100644 --- a/src/recorder.ts +++ b/src/recorder.ts @@ -75,13 +75,15 @@ export function record( const startTime = getTime(); try { - const result = fun.apply(this, args); + const result = funInfo.async + ? Recording.fork(() => fun.apply(this, args)) + : fun.apply(this, args); recordings.forEach((recording, idx) => recording.functionReturn(callEvents[idx].id, result, startTime), ); return result; } catch (exn: unknown) { - recordings.map((recording, idx) => + recordings.forEach((recording, idx) => recording.functionException(callEvents[idx].id, exn, startTime), ); throw exn; diff --git a/test/__snapshots__/httpClient.test.ts.snap b/test/__snapshots__/httpClient.test.ts.snap index fd13d464..50498758 100644 --- a/test/__snapshots__/httpClient.test.ts.snap +++ b/test/__snapshots__/httpClient.test.ts.snap @@ -88,20 +88,6 @@ exports[`mapping http client requests (ESM) 1`] = ` "type": "package", }, ], - "eventUpdates": { - "2": { - "elapsed": 31.337, - "event": "return", - "id": 2, - "parent_id": 1, - "return_value": { - "class": "Promise", - "object_id": 1, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - }, "events": [ { "defined_class": "esm", @@ -114,18 +100,6 @@ exports[`mapping http client requests (ESM) 1`] = ` "static": true, "thread_id": 0, }, - { - "elapsed": 31.337, - "event": "return", - "id": 2, - "parent_id": 1, - "return_value": { - "class": "Promise", - "object_id": 1, - "value": "Promise { }", - }, - "thread_id": 0, - }, { "event": "call", "http_client_request": { @@ -156,6 +130,18 @@ exports[`mapping http client requests (ESM) 1`] = ` "parent_id": 3, "thread_id": 0, }, + { + "elapsed": 31.337, + "event": "return", + "id": 2, + "parent_id": 1, + "return_value": { + "class": "Promise", + "object_id": 1, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, ], "metadata": { "app": "http-client-appmap-node-test", @@ -207,80 +193,6 @@ exports[`mapping http client requests 1`] = ` "type": "package", }, ], - "eventUpdates": { - "12": { - "elapsed": 31.337, - "event": "return", - "id": 12, - "parent_id": 11, - "return_value": { - "class": "Promise", - "object_id": 7, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "16": { - "elapsed": 31.337, - "event": "return", - "id": 16, - "parent_id": 15, - "return_value": { - "class": "Promise", - "object_id": 9, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "20": { - "elapsed": 31.337, - "event": "return", - "id": 20, - "parent_id": 19, - "return_value": { - "class": "Promise", - "object_id": 12, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "3": { - "elapsed": 31.337, - "event": "return", - "id": 3, - "parent_id": 2, - "return_value": { - "class": "Promise", - "object_id": 2, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "4": { - "elapsed": 31.337, - "event": "return", - "id": 4, - "parent_id": 1, - "return_value": { - "class": "Promise", - "object_id": 3, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "8": { - "elapsed": 31.337, - "event": "return", - "id": 8, - "parent_id": 7, - "return_value": { - "class": "Promise", - "object_id": 5, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - }, "events": [ { "defined_class": "index", @@ -317,21 +229,9 @@ exports[`mapping http client requests 1`] = ` "id": 3, "parent_id": 2, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 2, - "value": "Promise { }", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 4, - "parent_id": 1, - "return_value": { - "class": "Promise", - "object_id": 3, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -389,9 +289,9 @@ exports[`mapping http client requests 1`] = ` "id": 8, "parent_id": 7, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 5, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -446,9 +346,9 @@ exports[`mapping http client requests 1`] = ` "id": 12, "parent_id": 11, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 7, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -502,9 +402,9 @@ exports[`mapping http client requests 1`] = ` "id": 16, "parent_id": 15, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 9, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -573,9 +473,9 @@ exports[`mapping http client requests 1`] = ` "id": 20, "parent_id": 19, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 12, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -609,6 +509,18 @@ exports[`mapping http client requests 1`] = ` "parent_id": 21, "thread_id": 0, }, + { + "elapsed": 31.337, + "event": "return", + "id": 4, + "parent_id": 1, + "return_value": { + "class": "Promise", + "object_id": 3, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, ], "metadata": { "app": "http-client-appmap-node-test", @@ -666,80 +578,6 @@ exports[`mapping mocked http client requests 1`] = ` "type": "package", }, ], - "eventUpdates": { - "10": { - "elapsed": 31.337, - "event": "return", - "id": 10, - "parent_id": 9, - "return_value": { - "class": "Promise", - "object_id": 5, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "14": { - "elapsed": 31.337, - "event": "return", - "id": 14, - "parent_id": 13, - "return_value": { - "class": "Promise", - "object_id": 7, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "18": { - "elapsed": 31.337, - "event": "return", - "id": 18, - "parent_id": 17, - "return_value": { - "class": "Promise", - "object_id": 9, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "22": { - "elapsed": 31.337, - "event": "return", - "id": 22, - "parent_id": 21, - "return_value": { - "class": "Promise", - "object_id": 11, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "4": { - "elapsed": 31.337, - "event": "return", - "id": 4, - "parent_id": 3, - "return_value": { - "class": "Promise", - "object_id": 2, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "5": { - "elapsed": 31.337, - "event": "return", - "id": 5, - "parent_id": 2, - "return_value": { - "class": "Promise", - "object_id": 3, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - }, "events": [ { "defined_class": "index", @@ -787,31 +625,12 @@ exports[`mapping mocked http client requests 1`] = ` "id": 4, "parent_id": 3, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 2, - "value": "Promise { }", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 5, - "parent_id": 2, - "return_value": { - "class": "Promise", - "object_id": 3, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, - { - "elapsed": 31.337, - "event": "return", - "id": 6, - "parent_id": 1, - "thread_id": 0, - }, { "event": "call", "http_client_request": { @@ -863,9 +682,9 @@ exports[`mapping mocked http client requests 1`] = ` "id": 10, "parent_id": 9, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 5, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -921,9 +740,9 @@ exports[`mapping mocked http client requests 1`] = ` "id": 14, "parent_id": 13, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 7, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -975,9 +794,9 @@ exports[`mapping mocked http client requests 1`] = ` "id": 18, "parent_id": 17, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 9, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -1029,9 +848,9 @@ exports[`mapping mocked http client requests 1`] = ` "id": 22, "parent_id": 21, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 11, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -1059,6 +878,25 @@ exports[`mapping mocked http client requests 1`] = ` "parent_id": 23, "thread_id": 0, }, + { + "elapsed": 31.337, + "event": "return", + "id": 5, + "parent_id": 2, + "return_value": { + "class": "Promise", + "object_id": 3, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 6, + "parent_id": 1, + "thread_id": 0, + }, ], "metadata": { "app": "http-client-appmap-node-test", diff --git a/test/__snapshots__/jest.test.ts.snap b/test/__snapshots__/jest.test.ts.snap index 26fbb53e..8b3ef433 100644 --- a/test/__snapshots__/jest.test.ts.snap +++ b/test/__snapshots__/jest.test.ts.snap @@ -185,32 +185,6 @@ Add a timeout value to this test to increase the timeout, if this is a long-runn "type": "package", }, ], - "eventUpdates": { - "2": { - "elapsed": 31.337, - "event": "return", - "id": 2, - "parent_id": 1, - "return_value": { - "class": "Promise", - "object_id": 1, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "4": { - "elapsed": 31.337, - "event": "return", - "id": 4, - "parent_id": 3, - "return_value": { - "class": "Promise", - "object_id": 2, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - }, "events": [ { "defined_class": "asyncLib.test", @@ -235,9 +209,9 @@ Add a timeout value to this test to increase the timeout, if this is a long-runn "id": 2, "parent_id": 1, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 1, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -264,9 +238,9 @@ Add a timeout value to this test to increase the timeout, if this is a long-runn "id": 4, "parent_id": 3, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 2, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, diff --git a/test/__snapshots__/mysql.test.ts.snap b/test/__snapshots__/mysql.test.ts.snap index 6f4200a9..7e0662f9 100644 --- a/test/__snapshots__/mysql.test.ts.snap +++ b/test/__snapshots__/mysql.test.ts.snap @@ -34,56 +34,6 @@ exports[`mapping MySQL tests 1`] = ` "type": "package", }, ], - "eventUpdates": { - "13": { - "elapsed": 31.337, - "event": "return", - "id": 13, - "parent_id": 11, - "return_value": { - "class": "Promise", - "object_id": 7, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "19": { - "elapsed": 31.337, - "event": "return", - "id": 19, - "parent_id": 17, - "return_value": { - "class": "Promise", - "object_id": 11, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "6": { - "elapsed": 31.337, - "event": "return", - "id": 6, - "parent_id": 4, - "return_value": { - "class": "Promise", - "object_id": 2, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "7": { - "elapsed": 31.337, - "event": "return", - "id": 7, - "parent_id": 1, - "return_value": { - "class": "Promise", - "object_id": 3, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - }, "events": [ { "defined_class": "index", @@ -265,30 +215,6 @@ exports[`mapping MySQL tests 1`] = ` }, "thread_id": 0, }, - { - "elapsed": 31.337, - "event": "return", - "id": 6, - "parent_id": 4, - "return_value": { - "class": "Promise", - "object_id": 2, - "value": "Promise { }", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 7, - "parent_id": 1, - "return_value": { - "class": "Promise", - "object_id": 3, - "value": "Promise { }", - }, - "thread_id": 0, - }, { "elapsed": 31.337, "event": "return", @@ -303,6 +229,18 @@ exports[`mapping MySQL tests 1`] = ` "parent_id": 5, "thread_id": 0, }, + { + "elapsed": 31.337, + "event": "return", + "id": 6, + "parent_id": 4, + "return_value": { + "class": "Promise", + "object_id": 2, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, { "defined_class": "index", "event": "call", @@ -478,18 +416,6 @@ exports[`mapping MySQL tests 1`] = ` }, "thread_id": 0, }, - { - "elapsed": 31.337, - "event": "return", - "id": 13, - "parent_id": 11, - "return_value": { - "class": "Promise", - "object_id": 7, - "value": "Promise { }", - }, - "thread_id": 0, - }, { "elapsed": 31.337, "event": "return", @@ -504,6 +430,18 @@ exports[`mapping MySQL tests 1`] = ` "parent_id": 12, "thread_id": 0, }, + { + "elapsed": 31.337, + "event": "return", + "id": 13, + "parent_id": 11, + "return_value": { + "class": "Promise", + "object_id": 7, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, { "defined_class": "index", "event": "call", @@ -680,18 +618,6 @@ exports[`mapping MySQL tests 1`] = ` }, "thread_id": 0, }, - { - "elapsed": 31.337, - "event": "return", - "id": 19, - "parent_id": 17, - "return_value": { - "class": "Promise", - "object_id": 11, - "value": "Promise { }", - }, - "thread_id": 0, - }, { "elapsed": 31.337, "event": "return", @@ -706,6 +632,18 @@ exports[`mapping MySQL tests 1`] = ` "parent_id": 18, "thread_id": 0, }, + { + "elapsed": 31.337, + "event": "return", + "id": 19, + "parent_id": 17, + "return_value": { + "class": "Promise", + "object_id": 11, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, { "defined_class": "index", "event": "call", @@ -807,6 +745,18 @@ exports[`mapping MySQL tests 1`] = ` "parent_id": 23, "thread_id": 0, }, + { + "elapsed": 31.337, + "event": "return", + "id": 7, + "parent_id": 1, + "return_value": { + "class": "Promise", + "object_id": 3, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, ], "metadata": { "app": "mysql-appmap-node-test", diff --git a/test/__snapshots__/prisma.test.ts.snap b/test/__snapshots__/prisma.test.ts.snap index 2a5a5259..3baee5af 100644 --- a/test/__snapshots__/prisma.test.ts.snap +++ b/test/__snapshots__/prisma.test.ts.snap @@ -9,18 +9,6 @@ exports[`mapping Prisma tests 1`] = ` "children": [ { "children": [ - { - "children": [ - { - "location": "@prisma/client/Post:2", - "name": "deleteMany", - "static": true, - "type": "function", - }, - ], - "name": "Post", - "type": "class", - }, { "children": [ { @@ -29,18 +17,6 @@ exports[`mapping Prisma tests 1`] = ` "static": true, "type": "function", }, - { - "location": "@prisma/client/User:3", - "name": "deleteMany", - "static": true, - "type": "function", - }, - { - "location": "@prisma/client/User:4", - "name": "create", - "static": true, - "type": "function", - }, ], "name": "User", "type": "class", @@ -70,92 +46,6 @@ exports[`mapping Prisma tests 1`] = ` "type": "package", }, ], - "eventUpdates": { - "12": { - "elapsed": 31.337, - "event": "return", - "id": 12, - "parent_id": 11, - "return_value": { - "class": "Promise", - "object_id": 5, - "value": "Promise { { count: 0 } }", - }, - "thread_id": 0, - }, - "2": { - "elapsed": 31.337, - "event": "return", - "id": 2, - "parent_id": 1, - "return_value": { - "class": "Promise", - "object_id": 1, - "value": "Promise { undefined }", - }, - "thread_id": 0, - }, - "20": { - "elapsed": 31.337, - "event": "return", - "id": 20, - "parent_id": 19, - "return_value": { - "class": "Promise", - "object_id": 7, - "value": "Promise { { id: 1, email: 'alice@prisma.io', name: 'Alice' } }", - }, - "thread_id": 0, - }, - "24": { - "elapsed": 31.337, - "event": "return", - "id": 24, - "parent_id": 23, - "return_value": { - "class": "Promise", - "object_id": 9, - "value": "Promise { { id: 2, email: 'bob@prisma.io', name: 'Bob' } }", - }, - "thread_id": 0, - }, - "36": { - "elapsed": 31.337, - "event": "return", - "id": 36, - "parent_id": 35, - "return_value": { - "class": "Promise", - "object_id": 11, - "value": "Promise { [ { id: 2, email: 'bob@prisma.io', name: 'Bob', posts: [Array] } ] }", - }, - "thread_id": 0, - }, - "4": { - "elapsed": 31.337, - "event": "return", - "id": 4, - "parent_id": 3, - "return_value": { - "class": "Promise", - "object_id": 3, - "value": "Promise { [] }", - }, - "thread_id": 0, - }, - "8": { - "elapsed": 31.337, - "event": "return", - "id": 8, - "parent_id": 7, - "return_value": { - "class": "Promise", - "object_id": 4, - "value": "Promise { { count: 0 } }", - }, - "thread_id": 0, - }, - }, "events": [ { "defined_class": "script", @@ -168,18 +58,6 @@ exports[`mapping Prisma tests 1`] = ` "static": true, "thread_id": 0, }, - { - "elapsed": 31.337, - "event": "return", - "id": 2, - "parent_id": 1, - "return_value": { - "class": "Promise", - "object_id": 1, - "value": "Promise { }", - }, - "thread_id": 0, - }, { "defined_class": "User", "event": "call", @@ -226,484 +104,38 @@ exports[`mapping Prisma tests 1`] = ` "id": 4, "parent_id": 3, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 3, - "value": "Promise { }", - }, - "thread_id": 0, - }, - { - "event": "call", - "id": 5, - "sql_query": { - "database_type": "sqlite", - "sql": "SELECT \`main\`.\`User\`.\`id\`, \`main\`.\`User\`.\`email\`, \`main\`.\`User\`.\`name\` FROM \`main\`.\`User\` WHERE (\`main\`.\`User\`.\`name\` LIKE ? AND \`main\`.\`User\`.\`email\` LIKE ?) LIMIT ? OFFSET ?", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 6, - "parent_id": 5, - "thread_id": 0, - }, - { - "defined_class": "Post", - "event": "call", - "id": 7, - "lineno": 2, - "method_id": "deleteMany", - "parameters": [ - { - "class": "undefined", - "name": "args", - "value": "undefined", - }, - ], - "path": "@prisma/client/Post", - "receiver": { - "class": "String", - "value": "'Post'", - }, - "static": false, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 8, - "parent_id": 7, - "return_value": { - "class": "Promise", - "object_id": 4, - "value": "Promise { }", - }, - "thread_id": 0, - }, - { - "event": "call", - "id": 9, - "sql_query": { - "database_type": "sqlite", - "sql": "DELETE FROM \`main\`.\`Post\` WHERE 1=1", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 10, - "parent_id": 9, - "thread_id": 0, - }, - { - "defined_class": "User", - "event": "call", - "id": 11, - "lineno": 3, - "method_id": "deleteMany", - "parameters": [ - { - "class": "undefined", - "name": "args", - "value": "undefined", - }, - ], - "path": "@prisma/client/User", - "receiver": { - "class": "String", - "value": "'User'", - }, - "static": false, - "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, - }, - { - "event": "call", - "id": 13, - "sql_query": { - "database_type": "sqlite", - "sql": "DELETE FROM \`main\`.\`User\` WHERE 1=1", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 14, - "parent_id": 13, - "thread_id": 0, - }, - { - "event": "call", - "id": 15, - "sql_query": { - "database_type": "sqlite", - "sql": "delete from sqlite_sequence where name='Post'", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 16, - "parent_id": 15, - "thread_id": 0, - }, - { - "event": "call", - "id": 17, - "sql_query": { - "database_type": "sqlite", - "sql": "delete from sqlite_sequence where name='User'", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 18, - "parent_id": 17, - "thread_id": 0, - }, - { - "defined_class": "User", - "event": "call", - "id": 19, - "lineno": 4, - "method_id": "create", - "parameters": [ - { - "class": "Object", - "name": "args", - "object_id": 6, - "properties": [ - { - "class": "Object", - "name": "data", - "properties": [ - { - "class": "String", - "name": "name", - }, - { - "class": "String", - "name": "email", - }, - ], - }, - ], - "value": "{ data: { name: 'Alice', email: 'alice@prisma.io' } }", - }, - ], - "path": "@prisma/client/User", - "receiver": { - "class": "String", - "value": "'User'", - }, - "static": false, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 20, - "parent_id": 19, - "return_value": { - "class": "Promise", - "object_id": 7, - "value": "Promise { }", - }, - "thread_id": 0, - }, - { - "event": "call", - "id": 21, - "sql_query": { - "database_type": "sqlite", - "sql": "INSERT INTO \`main\`.\`User\` (\`email\`, \`name\`) VALUES (?,?) RETURNING \`id\` AS \`id\`, \`email\` AS \`email\`, \`name\` AS \`name\`", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 22, - "parent_id": 21, - "thread_id": 0, - }, - { - "defined_class": "User", - "event": "call", - "id": 23, - "lineno": 4, - "method_id": "create", - "parameters": [ - { - "class": "Object", - "name": "args", - "object_id": 8, - "properties": [ - { - "class": "Object", - "name": "data", - "properties": [ - { - "class": "String", - "name": "name", - }, - { - "class": "String", - "name": "email", - }, - { - "class": "Object", - "name": "posts", - "properties": [ - { - "class": "Object", - "name": "create", - "properties": [ - { - "class": "String", - "name": "title", - }, - ], - }, - ], - }, - ], - }, - ], - "value": "{ - data: { - name: 'Bob', - email: 'bob@prisma.io', - posts: { create: { title: 'Hello World' } } - } -}", - }, - ], - "path": "@prisma/client/User", - "receiver": { - "class": "String", - "value": "'User'", - }, - "static": false, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 24, - "parent_id": 23, - "return_value": { - "class": "Promise", - "object_id": 9, - "value": "Promise { }", - }, - "thread_id": 0, - }, - { - "event": "call", - "id": 25, - "sql_query": { - "database_type": "sqlite", - "sql": "BEGIN", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 26, - "parent_id": 25, - "thread_id": 0, - }, - { - "event": "call", - "id": 27, - "sql_query": { - "database_type": "sqlite", - "sql": "INSERT INTO \`main\`.\`User\` (\`email\`, \`name\`) VALUES (?,?) RETURNING \`id\` AS \`id\`", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 28, - "parent_id": 27, - "thread_id": 0, - }, - { - "event": "call", - "id": 29, - "sql_query": { - "database_type": "sqlite", - "sql": "INSERT INTO \`main\`.\`Post\` (\`title\`, \`published\`, \`authorId\`) VALUES (?,?,?) RETURNING \`id\` AS \`id\`", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 30, - "parent_id": 29, - "thread_id": 0, - }, - { - "event": "call", - "id": 31, - "sql_query": { - "database_type": "sqlite", - "sql": "SELECT \`main\`.\`User\`.\`id\`, \`main\`.\`User\`.\`email\`, \`main\`.\`User\`.\`name\` FROM \`main\`.\`User\` WHERE \`main\`.\`User\`.\`id\` = ? LIMIT ? OFFSET ?", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 32, - "parent_id": 31, - "thread_id": 0, - }, - { - "event": "call", - "id": 33, - "sql_query": { - "database_type": "sqlite", - "sql": "COMMIT", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 34, - "parent_id": 33, - "thread_id": 0, - }, - { - "defined_class": "User", - "event": "call", - "id": 35, - "lineno": 1, - "method_id": "findMany", - "parameters": [ - { - "class": "Object", - "name": "args", - "object_id": 10, - "properties": [ - { - "class": "Object", - "name": "include", - "properties": [ - { - "class": "Boolean", - "name": "posts", - }, - ], - }, - { - "class": "Object", - "name": "where", - "properties": [ - { - "class": "Object", - "name": "name", - "properties": [ - { - "class": "String", - "name": "contains", - }, - ], - }, - ], - }, - ], - "value": "{ include: { posts: true }, where: { name: { contains: 'Bob' } } }", - }, - ], - "path": "@prisma/client/User", - "receiver": { - "class": "String", - "value": "'User'", + "value": "Promise { [] }", }, - "static": false, "thread_id": 0, }, { "elapsed": 31.337, "event": "return", - "id": 36, - "parent_id": 35, + "id": 2, + "parent_id": 1, "return_value": { - "class": "Promise", - "object_id": 11, - "value": "Promise { }", - }, - "thread_id": 0, - }, - { - "event": "call", - "id": 37, - "sql_query": { - "database_type": "sqlite", - "sql": "SELECT \`main\`.\`User\`.\`id\`, \`main\`.\`User\`.\`email\`, \`main\`.\`User\`.\`name\` FROM \`main\`.\`User\` WHERE \`main\`.\`User\`.\`name\` LIKE ? LIMIT ? OFFSET ?", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 38, - "parent_id": 37, - "thread_id": 0, - }, - { - "event": "call", - "id": 39, - "sql_query": { - "database_type": "sqlite", - "sql": "SELECT \`main\`.\`Post\`.\`id\`, \`main\`.\`Post\`.\`title\`, \`main\`.\`Post\`.\`content\`, \`main\`.\`Post\`.\`published\`, \`main\`.\`Post\`.\`authorId\` FROM \`main\`.\`Post\` WHERE \`main\`.\`Post\`.\`authorId\` IN (?) LIMIT ? OFFSET ?", + "class": "Promise", + "object_id": 1, + "value": "Promise { undefined }", }, "thread_id": 0, }, - { - "elapsed": 31.337, - "event": "return", - "id": 40, - "parent_id": 39, - "thread_id": 0, - }, { "event": "call", - "id": 41, + "id": 5, "sql_query": { "database_type": "sqlite", - "sql": "SELECT 1", + "sql": "SELECT \`main\`.\`User\`.\`id\`, \`main\`.\`User\`.\`email\`, \`main\`.\`User\`.\`name\` FROM \`main\`.\`User\` WHERE (\`main\`.\`User\`.\`name\` LIKE ? AND \`main\`.\`User\`.\`email\` LIKE ?) LIMIT ? OFFSET ?", }, "thread_id": 0, }, { "elapsed": 31.337, "event": "return", - "id": 42, - "parent_id": 41, + "id": 6, + "parent_id": 5, "thread_id": 0, }, ], diff --git a/test/__snapshots__/simple.test.ts.snap b/test/__snapshots__/simple.test.ts.snap index 1b75c564..ed51427b 100644 --- a/test/__snapshots__/simple.test.ts.snap +++ b/test/__snapshots__/simple.test.ts.snap @@ -209,7 +209,7 @@ exports[`mapping a custom Error class with a message property 1`] = ` } `; -exports[`mapping a simple script 1`] = ` +exports[`mapping a script with tangled async functions 1`] = ` { "classMap": [ { @@ -217,31 +217,31 @@ exports[`mapping a simple script 1`] = ` { "children": [ { - "location": "index.js:15", - "name": "immediatePromise", + "location": "async.mjs:13", + "name": "processMessage", "static": true, "type": "function", }, { - "location": "index.js:19", - "name": "throws", + "location": "async.mjs:18", + "name": "task", "static": true, "type": "function", }, { - "location": "index.js:4", - "name": "foo", + "location": "async.mjs:3", + "name": "process", "static": true, "type": "function", }, { - "location": "index.js:9", - "name": "promised", + "location": "async.mjs:8", + "name": "getMessage", "static": true, "type": "function", }, ], - "name": "index", + "name": "async", "type": "class", }, ], @@ -249,51 +249,360 @@ exports[`mapping a simple script 1`] = ` "type": "package", }, ], - "eventUpdates": { - "10": { + "events": [ + { + "defined_class": "async", + "event": "call", + "id": 1, + "lineno": 18, + "method_id": "task", + "parameters": [ + { + "class": "String", + "name": "name", + "value": "'first'", + }, + ], + "path": "async.mjs", + "static": true, + "thread_id": 0, + }, + { + "defined_class": "async", + "event": "call", + "id": 2, + "lineno": 3, + "method_id": "process", + "parameters": [ + { + "class": "String", + "name": "name", + "value": "'first'", + }, + ], + "path": "async.mjs", + "static": true, + "thread_id": 0, + }, + { + "defined_class": "async", + "event": "call", + "id": 3, + "lineno": 8, + "method_id": "getMessage", + "parameters": [ + { + "class": "String", + "name": "message", + "value": "'process first'", + }, + ], + "path": "async.mjs", + "static": true, + "thread_id": 0, + }, + { "elapsed": 31.337, "event": "return", - "exceptions": [ + "id": 4, + "parent_id": 3, + "return_value": { + "class": "Promise", + "object_id": 1, + "value": "Promise { 'message is process first' }", + }, + "thread_id": 0, + }, + { + "defined_class": "async", + "event": "call", + "id": 17, + "lineno": 13, + "method_id": "processMessage", + "parameters": [ { - "class": "Error", - "message": "throws intentionally", - "object_id": 5, + "class": "String", + "name": "message", + "value": "'message is process first'", }, ], - "id": 10, - "parent_id": 9, + "path": "async.mjs", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 18, + "parent_id": 17, "return_value": { - "class": "Promise", + "class": "Promise", + "object_id": 9, + "value": "Promise { 'processed message message is process first' }", + }, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 5, + "parent_id": 2, + "return_value": { + "class": "Promise", + "object_id": 2, + "value": "Promise { 'processed message message is process first' }", + }, + "thread_id": 0, + }, + { + "defined_class": "async", + "event": "call", + "id": 13, + "lineno": 8, + "method_id": "getMessage", + "parameters": [ + { + "class": "String", + "name": "message", + "value": "'first toplevel'", + }, + ], + "path": "async.mjs", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 14, + "parent_id": 13, + "return_value": { + "class": "Promise", + "object_id": 7, + "value": "Promise { 'message is first toplevel' }", + }, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 6, + "parent_id": 1, + "return_value": { + "class": "Promise", "object_id": 3, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, - "12": { + { + "defined_class": "async", + "event": "call", + "id": 7, + "lineno": 18, + "method_id": "task", + "parameters": [ + { + "class": "String", + "name": "name", + "value": "'second'", + }, + ], + "path": "async.mjs", + "static": true, + "thread_id": 0, + }, + { + "defined_class": "async", + "event": "call", + "id": 8, + "lineno": 3, + "method_id": "process", + "parameters": [ + { + "class": "String", + "name": "name", + "value": "'second'", + }, + ], + "path": "async.mjs", + "static": true, + "thread_id": 0, + }, + { + "defined_class": "async", + "event": "call", + "id": 9, + "lineno": 8, + "method_id": "getMessage", + "parameters": [ + { + "class": "String", + "name": "message", + "value": "'process second'", + }, + ], + "path": "async.mjs", + "static": true, + "thread_id": 0, + }, + { "elapsed": 31.337, "event": "return", - "id": 12, - "parent_id": 11, + "id": 10, + "parent_id": 9, "return_value": { "class": "Promise", "object_id": 4, - "value": "Promise { 'immediate' }", + "value": "Promise { 'message is process second' }", }, "thread_id": 0, }, - "8": { + { + "defined_class": "async", + "event": "call", + "id": 19, + "lineno": 13, + "method_id": "processMessage", + "parameters": [ + { + "class": "String", + "name": "message", + "value": "'message is process second'", + }, + ], + "path": "async.mjs", + "static": true, + "thread_id": 0, + }, + { "elapsed": 31.337, "event": "return", - "id": 8, - "parent_id": 7, + "id": 20, + "parent_id": 19, "return_value": { "class": "Promise", - "object_id": 2, - "value": "Promise { 'promised return' }", + "object_id": 10, + "value": "Promise { 'processed message message is process second' }", + }, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 11, + "parent_id": 8, + "return_value": { + "class": "Promise", + "object_id": 5, + "value": "Promise { 'processed message message is process second' }", + }, + "thread_id": 0, + }, + { + "defined_class": "async", + "event": "call", + "id": 15, + "lineno": 8, + "method_id": "getMessage", + "parameters": [ + { + "class": "String", + "name": "message", + "value": "'second toplevel'", + }, + ], + "path": "async.mjs", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 16, + "parent_id": 15, + "return_value": { + "class": "Promise", + "object_id": 8, + "value": "Promise { 'message is second toplevel' }", }, "thread_id": 0, }, + { + "elapsed": 31.337, + "event": "return", + "id": 12, + "parent_id": 7, + "return_value": { + "class": "Promise", + "object_id": 6, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, + ], + "metadata": { + "app": "simple", + "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", +} +`; + +exports[`mapping a simple script 1`] = ` +{ + "classMap": [ + { + "children": [ + { + "children": [ + { + "location": "index.js:15", + "name": "immediatePromise", + "static": true, + "type": "function", + }, + { + "location": "index.js:19", + "name": "throws", + "static": true, + "type": "function", + }, + { + "location": "index.js:4", + "name": "foo", + "static": true, + "type": "function", + }, + { + "location": "index.js:9", + "name": "promised", + "static": true, + "type": "function", + }, + ], + "name": "index", + "type": "class", + }, + ], + "name": "simple", + "type": "package", + }, + ], "events": [ { "defined_class": "index", @@ -393,9 +702,9 @@ exports[`mapping a simple script 1`] = ` "id": 8, "parent_id": 7, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 2, - "value": "Promise { }", + "value": "Promise { 'promised return' }", }, "thread_id": 0, }, @@ -416,15 +725,47 @@ exports[`mapping a simple script 1`] = ` "static": true, "thread_id": 0, }, + { + "defined_class": "index", + "event": "call", + "id": 13, + "lineno": 19, + "method_id": "throws", + "parameters": [], + "path": "index.js", + "static": true, + "thread_id": 0, + }, { "elapsed": 31.337, "event": "return", + "exceptions": [ + { + "class": "Error", + "message": "throws intentionally", + "object_id": 5, + }, + ], + "id": 14, + "parent_id": 13, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "exceptions": [ + { + "class": "Error", + "message": "throws intentionally", + "object_id": 5, + }, + ], "id": 10, "parent_id": 9, "return_value": { "class": "Promise", "object_id": 3, - "value": "Promise { }", + "value": "Promise { }", }, "thread_id": 0, }, @@ -445,35 +786,141 @@ exports[`mapping a simple script 1`] = ` "id": 12, "parent_id": 11, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 4, - "value": "Promise { }", + "value": "Promise { 'immediate' }", }, "thread_id": 0, }, + ], + "metadata": { + "app": "simple", + "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", +} +`; + +exports[`mapping a simple script with tangled async functions 1`] = ` +{ + "classMap": [ { - "defined_class": "index", + "children": [ + { + "children": [ + { + "location": "async.js:1", + "name": "bar", + "static": true, + "type": "function", + }, + { + "location": "async.js:4", + "name": "foo", + "static": true, + "type": "function", + }, + ], + "name": "async", + "type": "class", + }, + ], + "name": "simple", + "type": "package", + }, + ], + "events": [ + { + "defined_class": "async", "event": "call", - "id": 13, - "lineno": 19, - "method_id": "throws", + "id": 1, + "lineno": 4, + "method_id": "foo", "parameters": [], - "path": "index.js", + "path": "async.js", + "static": true, + "thread_id": 0, + }, + { + "defined_class": "async", + "event": "call", + "id": 5, + "lineno": 1, + "method_id": "bar", + "parameters": [ + { + "class": "Number", + "name": "x", + "value": "1", + }, + ], + "path": "async.js", "static": true, "thread_id": 0, }, { "elapsed": 31.337, "event": "return", - "exceptions": [ + "id": 6, + "parent_id": 5, + "return_value": { + "class": "Number", + "value": "2", + }, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 2, + "parent_id": 1, + "return_value": { + "class": "Promise", + "object_id": 1, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, + { + "defined_class": "async", + "event": "call", + "id": 3, + "lineno": 1, + "method_id": "bar", + "parameters": [ { - "class": "Error", - "message": "throws intentionally", - "object_id": 5, + "class": "Number", + "name": "x", + "value": "2", }, ], - "id": 14, - "parent_id": 13, + "path": "async.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 4, + "parent_id": 3, + "return_value": { + "class": "Number", + "value": "4", + }, "thread_id": 0, }, ], diff --git a/test/__snapshots__/sqlite.test.ts.snap b/test/__snapshots__/sqlite.test.ts.snap index c389327a..cb54b647 100644 --- a/test/__snapshots__/sqlite.test.ts.snap +++ b/test/__snapshots__/sqlite.test.ts.snap @@ -28,6 +28,7 @@ exports[`mapping Sqlite tests 1`] = ` "type": "package", }, ], +<<<<<<< HEAD "eventUpdates": { "13": { "elapsed": 31.337, @@ -210,6 +211,8 @@ exports[`mapping Sqlite tests 1`] = ` "thread_id": 0, }, }, +======= +>>>>>>> d1f88ce (feat: Async tracking) "events": [ { "defined_class": "index", @@ -264,21 +267,9 @@ exports[`mapping Sqlite tests 1`] = ` "id": 4, "parent_id": 2, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 2, - "value": "Promise { }", - }, - "thread_id": 0, - }, - { - "elapsed": 31.337, - "event": "return", - "id": 5, - "parent_id": 1, - "return_value": { - "class": "Promise", - "object_id": 3, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -331,9 +322,9 @@ exports[`mapping Sqlite tests 1`] = ` "id": 9, "parent_id": 7, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 4, - "value": "Promise { }", + "value": "Promise { [ { "'Database.all'": 'Database.all' } ] }", }, "thread_id": 0, }, @@ -386,9 +377,9 @@ exports[`mapping Sqlite tests 1`] = ` "id": 13, "parent_id": 11, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 5, - "value": "Promise { }", + "value": "Promise { { "'Database.get'": 'Database.get' } }", }, "thread_id": 0, }, @@ -441,19 +432,12 @@ exports[`mapping Sqlite tests 1`] = ` "id": 17, "parent_id": 15, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 6, - "value": "Promise { }", + "value": "Promise { { "'Database.each'": 'Database.each' } }", }, "thread_id": 0, }, - { - "elapsed": 31.337, - "event": "return", - "id": 18, - "parent_id": 16, - "thread_id": 0, - }, { "defined_class": "index", "event": "call", @@ -496,9 +480,9 @@ exports[`mapping Sqlite tests 1`] = ` "id": 21, "parent_id": 19, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 7, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -555,19 +539,12 @@ exports[`mapping Sqlite tests 1`] = ` "id": 25, "parent_id": 23, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 8, - "value": "Promise { }", + "value": "Promise { 1 }", }, "thread_id": 0, }, - { - "elapsed": 31.337, - "event": "return", - "id": 26, - "parent_id": 24, - "thread_id": 0, - }, { "defined_class": "index", "event": "call", @@ -618,9 +595,9 @@ exports[`mapping Sqlite tests 1`] = ` "id": 29, "parent_id": 27, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 9, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -688,9 +665,9 @@ exports[`mapping Sqlite tests 1`] = ` "id": 33, "parent_id": 31, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 11, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -739,9 +716,9 @@ exports[`mapping Sqlite tests 1`] = ` "id": 37, "parent_id": 35, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 13, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -790,9 +767,9 @@ exports[`mapping Sqlite tests 1`] = ` "id": 41, "parent_id": 39, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 15, - "value": "Promise { }", + "value": "Promise { [ { "'Statement.all'": 'Statement.all' } ] }", }, "thread_id": 0, }, @@ -841,9 +818,9 @@ exports[`mapping Sqlite tests 1`] = ` "id": 45, "parent_id": 43, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 17, - "value": "Promise { }", + "value": "Promise { { "'Statement.get'": 'Statement.get' } }", }, "thread_id": 0, }, @@ -892,19 +869,12 @@ exports[`mapping Sqlite tests 1`] = ` "id": 49, "parent_id": 47, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 19, - "value": "Promise { }", + "value": "Promise { { "'Statement.each'": 'Statement.each' } }", }, "thread_id": 0, }, - { - "elapsed": 31.337, - "event": "return", - "id": 50, - "parent_id": 48, - "thread_id": 0, - }, { "defined_class": "index", "event": "call", @@ -943,9 +913,9 @@ exports[`mapping Sqlite tests 1`] = ` "id": 53, "parent_id": 51, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 21, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -994,9 +964,9 @@ exports[`mapping Sqlite tests 1`] = ` "id": 57, "parent_id": 55, "return_value": { - "class": "Promise", + "class": "Promise", "object_id": 22, - "value": "Promise { }", + "value": "Promise { undefined }", }, "thread_id": 0, }, @@ -1039,6 +1009,39 @@ exports[`mapping Sqlite tests 1`] = ` "parent_id": 61, "thread_id": 0, }, + { + "elapsed": 31.337, + "event": "return", + "id": 5, + "parent_id": 1, + "return_value": { + "class": "Promise", + "object_id": 3, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 18, + "parent_id": 16, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 26, + "parent_id": 24, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 50, + "parent_id": 48, + "thread_id": 0, + }, ], "metadata": { "app": "sqlite-appmap-node-test", diff --git a/test/simple.test.ts b/test/simple.test.ts index 7dbe05cc..f6dacc59 100644 --- a/test/simple.test.ts +++ b/test/simple.test.ts @@ -87,6 +87,11 @@ integrationTest("running a script after changing the current directory", () => { expect(readAppmap()).toBeDefined(); }); +integrationTest("mapping a script with tangled async functions", () => { + expect(runAppmapNode("async.mjs").status).toBe(0); + expect(readAppmap()).toMatchSnapshot(); +}); + integrationTest("creating a default config file", () => { const index = resolveTarget("index.js"); const target = tmp.dirSync({ unsafeCleanup: true }); diff --git a/test/simple/async.mjs b/test/simple/async.mjs new file mode 100644 index 00000000..63398d8b --- /dev/null +++ b/test/simple/async.mjs @@ -0,0 +1,26 @@ +import { setTimeout } from "timers/promises"; + +async function process(name) { + const message = await getMessage(`process ${name}`); + return processMessage(message); +} + +async function getMessage(message) { + await setTimeout(100); + return `message is ${message}`; +} + +async function processMessage(message) { + await setTimeout(100); + return `processed message ${message}`; +} + +async function task(name) { + process(name).then(console.log); + await setTimeout(50); + return getMessage(`${name} toplevel`).then(console.log); +} + +task("first"); +await setTimeout(25); +task("second");