diff --git a/src/Recording.ts b/src/Recording.ts index 7f6ac5de..b2c921f5 100644 --- a/src/Recording.ts +++ b/src/Recording.ts @@ -14,7 +14,7 @@ import { getDefaultMetadata } from "./metadata"; import { parameter } from "./parameter"; import type { FunctionInfo } from "./registry"; import compactObject from "./util/compactObject"; -import { getTime } from "./util/getTime"; +import { getTime, getTimeInMilliseconds } from "./util/getTime"; import { warn } from "./message"; export default class Recording { @@ -243,17 +243,32 @@ export default class Recording { warn("event emitted while recording not running"); return; } - if (Recording.buffering) { + // If the current buffer is alive more than allowed pass its events + // to the stream and clear it recursively. + if (Recording.buffering && !Recording.buffer.disposed && config().asyncTrackingTimeout != 0) { + const elapsed = getTimeInMilliseconds() - Recording.buffer.createdAt; + if (elapsed >= config().asyncTrackingTimeout) + Recording.passEventsAndClearBuffer(Recording.buffer); + } + + if (Recording.buffering && !Recording.buffer.disposed && config().asyncTrackingTimeout != 0) { this.bufferedEvents.set(event.id, event); - Recording.buffer.push({ event, owner: new WeakRef(this) }); + Recording.buffer.items.push({ event, owner: new WeakRef(this) }); } else this.stream.push(event); } - private static rootBuffer: EventBuffer = []; + private static _rootBuffer: EventBuffer | undefined; + private static get rootBuffer(): EventBuffer { + if (Recording._rootBuffer == undefined) + Recording._rootBuffer = { items: [], disposed: false, createdAt: getTimeInMilliseconds() }; + + return Recording._rootBuffer; + } + private static asyncStorage = new AsyncLocalStorage(); private static get buffering(): boolean { - return Recording.rootBuffer.length > 0; + return Recording.rootBuffer.items.length > 0; } private static get buffer(): EventBuffer { @@ -261,8 +276,9 @@ export default class Recording { } public static fork(fun: () => T): T { - const forked: EventBuffer = []; - Recording.buffer.push(forked); + const forked: EventBuffer = { items: [], disposed: false, createdAt: getTimeInMilliseconds() }; + Recording.buffer.items.push(forked); + return Recording.asyncStorage.run(forked, fun); } @@ -275,34 +291,57 @@ export default class Recording { return Recording.asyncStorage.getStore(); } + private static passEventsAndClearBuffer(buffer: EventBuffer) { + for (const event of buffer.items) { + if (isEventBuffer(event)) this.passEventsAndClearBuffer(event); + else { + const recording = event?.owner.deref(); + if (event && recording) { + recording.stream.push(event.event); + recording.bufferedEvents.delete(event.event.id); + } + } + } + buffer.disposed = true; + buffer.items = []; + } + 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); + for (const event of buffer.items) { + if (isEventBuffer(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; + for (let i = 0; i < buffer.items.length; i++) { + const event = buffer.items[i]; + if (isEventBuffer(event)) this.disposeBufferedEvents(event); + else if (event?.owner.deref() == this) buffer.items[i] = null; } } } +function isEventBuffer(obj: EventOrBuffer): obj is EventBuffer { + return obj != null && "items" in obj; +} + interface EventWithOwner { owner: WeakRef; event: AppMap.Event; } -type EventOrBuffer = EventWithOwner | null | EventOrBuffer[]; -export type EventBuffer = EventOrBuffer[]; +type EventOrBuffer = EventWithOwner | null | EventBuffer; +export interface EventBuffer { + items: EventOrBuffer[]; + disposed: boolean; + createdAt: number; +} export const writtenAppMaps: string[] = []; diff --git a/src/config.ts b/src/config.ts index b5caec52..dda3fac5 100644 --- a/src/config.ts +++ b/src/config.ts @@ -15,6 +15,9 @@ import tryOr from "./util/tryOr"; const responseBodyMaxLengthDefault = 10000; const kResponseBodyMaxLengthEnvar = "APPMAP_RESPONSE_BODY_MAX_LENGTH"; +const asyncTrackingTimeoutDefault = 3000; +const kAsyncTrackingTimeoutEnvar = "APPMAP_ASYNC_TRACKING_TIMEOUT"; + export class Config { public readonly relativeAppmapDir: string; public readonly appName: string; @@ -24,6 +27,8 @@ export class Config { public readonly packages: PackageMatcher; public readonly responseBodyMaxLength: number; public readonly language: string; + // If it's 0 then no async tracking. + public readonly asyncTrackingTimeout: number; private readonly document?: Document; private migrationPending = false; @@ -59,16 +64,26 @@ export class Config { ], ); - let envResponseBodyMaxLength: number | undefined; - if (process.env[kResponseBodyMaxLengthEnvar] != undefined) { - const value = parseInt(process.env[kResponseBodyMaxLengthEnvar]); - envResponseBodyMaxLength = value >= 0 ? value : undefined; - if (envResponseBodyMaxLength == undefined) - warn(`Environment variable ${kResponseBodyMaxLengthEnvar} must be a non-negative integer.`); + function getNonNegativeIntegerEnvVarValue(enVarName: string) { + let result: number | undefined; + if (process.env[enVarName] != undefined) { + const value = parseInt(process.env[enVarName]!); + result = value >= 0 ? value : undefined; + if (result == undefined) + warn(`Environment variable ${enVarName} must be a non-negative integer.`); + } + return result; } this.responseBodyMaxLength = - envResponseBodyMaxLength ?? config?.response_body_max_length ?? responseBodyMaxLengthDefault; + getNonNegativeIntegerEnvVarValue(kResponseBodyMaxLengthEnvar) ?? + config?.response_body_max_length ?? + responseBodyMaxLengthDefault; + + this.asyncTrackingTimeout = + getNonNegativeIntegerEnvVarValue(kAsyncTrackingTimeoutEnvar) ?? + config?.async_tracking_timeout ?? + asyncTrackingTimeoutDefault; } private absoluteAppmapDir?: string; @@ -151,6 +166,7 @@ interface ConfigFile { packages?: Package[]; response_body_max_length?: number; language?: string; + async_tracking_timeout?: number; } // Maintaining the YAML document is important to preserve existing comments and formatting @@ -188,6 +204,10 @@ function readConfigFile(document: Document): ConfigFile { const value = parseInt(String(config.response_body_max_length)); result.response_body_max_length = value >= 0 ? value : undefined; } + if ("async_tracking_timeout" in config) { + const value = parseInt(String(config.async_tracking_timeout)); + result.async_tracking_timeout = value >= 0 ? value : undefined; + } return result; } diff --git a/src/util/getTime.ts b/src/util/getTime.ts index daf009ce..204e9658 100644 --- a/src/util/getTime.ts +++ b/src/util/getTime.ts @@ -4,3 +4,7 @@ export function getTime(): number { const [sec, nano] = hrtime(); return sec + nano / 1000000000; } + +export function getTimeInMilliseconds(): number { + return Number(hrtime.bigint() / 1_000_000n); +} diff --git a/test/__snapshots__/simple.test.ts.snap b/test/__snapshots__/simple.test.ts.snap index 7ef77b31..b2745764 100644 --- a/test/__snapshots__/simple.test.ts.snap +++ b/test/__snapshots__/simple.test.ts.snap @@ -277,6 +277,493 @@ exports[`mapping a custom Error class with a message property 1`] = ` } `; +exports[`mapping a script using async tracking timeout 0 1`] = ` +{ + "classMap": [ + { + "children": [ + { + "children": [ + { + "location": "asyncTimeout.mjs:12", + "name": "task", + "static": true, + "type": "function", + }, + { + "location": "asyncTimeout.mjs:3", + "name": "process", + "static": true, + "type": "function", + }, + { + "location": "asyncTimeout.mjs:8", + "name": "getMessage", + "static": true, + "type": "function", + }, + ], + "name": "asyncTimeout", + "type": "class", + }, + ], + "name": "simple", + "type": "package", + }, + ], + "eventUpdates": { + "3": { + "elapsed": 31.337, + "event": "return", + "id": 3, + "parent_id": 2, + "return_value": { + "class": "Promise", + "object_id": 1, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, + "4": { + "elapsed": 31.337, + "event": "return", + "id": 4, + "parent_id": 1, + "return_value": { + "class": "Promise", + "object_id": 2, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, + "6": { + "elapsed": 31.337, + "event": "return", + "id": 6, + "parent_id": 5, + "return_value": { + "class": "Promise", + "object_id": 3, + "value": "Promise { 'message is process a task' }", + }, + "thread_id": 0, + }, + }, + "events": [ + { + "defined_class": "asyncTimeout", + "event": "call", + "id": 1, + "lineno": 12, + "method_id": "task", + "parameters": [ + { + "class": "String", + "name": "name", + "value": "'a task'", + }, + ], + "path": "asyncTimeout.mjs", + "static": true, + "thread_id": 0, + }, + { + "defined_class": "asyncTimeout", + "event": "call", + "id": 2, + "lineno": 3, + "method_id": "process", + "parameters": [ + { + "class": "String", + "name": "name", + "value": "'a task'", + }, + ], + "path": "asyncTimeout.mjs", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 3, + "parent_id": 2, + "return_value": { + "class": "Promise", + "object_id": 1, + "value": "Promise { }", + }, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 4, + "parent_id": 1, + "return_value": { + "class": "Promise", + "object_id": 2, + "value": "Promise { }", + }, + "thread_id": 0, + }, + { + "defined_class": "asyncTimeout", + "event": "call", + "id": 5, + "lineno": 8, + "method_id": "getMessage", + "parameters": [ + { + "class": "String", + "name": "message", + "value": "'process a task'", + }, + ], + "path": "asyncTimeout.mjs", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 6, + "parent_id": 5, + "return_value": { + "class": "Promise", + "object_id": 3, + "value": "Promise { }", + }, + "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 script using async tracking timeout 10 1`] = ` +{ + "classMap": [ + { + "children": [ + { + "children": [ + { + "location": "asyncTimeout.mjs:12", + "name": "task", + "static": true, + "type": "function", + }, + { + "location": "asyncTimeout.mjs:3", + "name": "process", + "static": true, + "type": "function", + }, + { + "location": "asyncTimeout.mjs:8", + "name": "getMessage", + "static": true, + "type": "function", + }, + ], + "name": "asyncTimeout", + "type": "class", + }, + ], + "name": "simple", + "type": "package", + }, + ], + "eventUpdates": { + "6": { + "elapsed": 31.337, + "event": "return", + "id": 6, + "parent_id": 5, + "return_value": { + "class": "Promise", + "object_id": 3, + "value": "Promise { 'message is process a task' }", + }, + "thread_id": 0, + }, + }, + "events": [ + { + "defined_class": "asyncTimeout", + "event": "call", + "id": 1, + "lineno": 12, + "method_id": "task", + "parameters": [ + { + "class": "String", + "name": "name", + "value": "'a task'", + }, + ], + "path": "asyncTimeout.mjs", + "static": true, + "thread_id": 0, + }, + { + "defined_class": "asyncTimeout", + "event": "call", + "id": 5, + "lineno": 8, + "method_id": "getMessage", + "parameters": [ + { + "class": "String", + "name": "message", + "value": "'process a task'", + }, + ], + "path": "asyncTimeout.mjs", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 6, + "parent_id": 5, + "return_value": { + "class": "Promise", + "object_id": 3, + "value": "Promise { }", + }, + "thread_id": 0, + }, + { + "defined_class": "asyncTimeout", + "event": "call", + "id": 2, + "lineno": 3, + "method_id": "process", + "parameters": [ + { + "class": "String", + "name": "name", + "value": "'a task'", + }, + ], + "path": "asyncTimeout.mjs", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 3, + "parent_id": 2, + "return_value": { + "class": "Promise", + "object_id": 1, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 4, + "parent_id": 1, + "return_value": { + "class": "Promise", + "object_id": 2, + "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 script using async tracking timeout 3000 1`] = ` +{ + "classMap": [ + { + "children": [ + { + "children": [ + { + "location": "asyncTimeout.mjs:12", + "name": "task", + "static": true, + "type": "function", + }, + { + "location": "asyncTimeout.mjs:3", + "name": "process", + "static": true, + "type": "function", + }, + { + "location": "asyncTimeout.mjs:8", + "name": "getMessage", + "static": true, + "type": "function", + }, + ], + "name": "asyncTimeout", + "type": "class", + }, + ], + "name": "simple", + "type": "package", + }, + ], + "events": [ + { + "defined_class": "asyncTimeout", + "event": "call", + "id": 1, + "lineno": 12, + "method_id": "task", + "parameters": [ + { + "class": "String", + "name": "name", + "value": "'a task'", + }, + ], + "path": "asyncTimeout.mjs", + "static": true, + "thread_id": 0, + }, + { + "defined_class": "asyncTimeout", + "event": "call", + "id": 2, + "lineno": 3, + "method_id": "process", + "parameters": [ + { + "class": "String", + "name": "name", + "value": "'a task'", + }, + ], + "path": "asyncTimeout.mjs", + "static": true, + "thread_id": 0, + }, + { + "defined_class": "asyncTimeout", + "event": "call", + "id": 5, + "lineno": 8, + "method_id": "getMessage", + "parameters": [ + { + "class": "String", + "name": "message", + "value": "'process a task'", + }, + ], + "path": "asyncTimeout.mjs", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 6, + "parent_id": 5, + "return_value": { + "class": "Promise", + "object_id": 3, + "value": "Promise { 'message is process a task' }", + }, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 3, + "parent_id": 2, + "return_value": { + "class": "Promise", + "object_id": 1, + "value": "Promise { undefined }", + }, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 4, + "parent_id": 1, + "return_value": { + "class": "Promise", + "object_id": 2, + "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 script with tangled async functions 1`] = ` { "classMap": [ diff --git a/test/simple.test.ts b/test/simple.test.ts index f08eb314..e7427f21 100644 --- a/test/simple.test.ts +++ b/test/simple.test.ts @@ -11,6 +11,7 @@ import { readAppmaps, resolveTarget, runAppmapNode, + runAppmapNodeWithOptions, spawnAppmapNode, testDir, } from "./helpers"; @@ -120,6 +121,33 @@ integrationTest("mapping a script with tangled async functions", () => { expect(readAppmap()).toMatchSnapshot(); }); +const asyncTimeoutCases = new Map([ + // No async tracking + ["0", ["1 task", "2 process", "return 2", "return 1", "5 getMessage", "return 5"]], + // Async tracking with a quick timeout + ["10", ["1 task", "5 getMessage", "return 5", "2 process", "return 2", "return 1"]], + // Full async tracking + ["3000", ["1 task", "2 process", "5 getMessage", "return 5", "return 2", "return 1"]], +]); + +for (const [timeout, expectedOrder] of asyncTimeoutCases) { + integrationTest("mapping a script using async tracking timeout " + timeout, () => { + const options = { + env: { ...process.env, APPMAP_ASYNC_TRACKING_TIMEOUT: timeout }, + }; + expect(runAppmapNodeWithOptions(options, "asyncTimeout.mjs").status).toBe(0); + const appmap = readAppmap(); + expect( + appmap.events?.map((e) => + e.event == "call" && "method_id" in e + ? `${e.id} ${e.method_id}` + : `${e.event} ${"parent_id" in e ? e.parent_id : ""}`, + ), + ).toEqual(expectedOrder); + expect(appmap).toMatchSnapshot(); + }); +} + integrationTest("creating a default config file", () => { const index = resolveTarget("index.js"); const target = tmp.dirSync({ unsafeCleanup: true }); diff --git a/test/simple/asyncTimeout.mjs b/test/simple/asyncTimeout.mjs new file mode 100644 index 00000000..317eddb4 --- /dev/null +++ b/test/simple/asyncTimeout.mjs @@ -0,0 +1,16 @@ +import { setTimeout } from "timers/promises"; + +async function process(name) { + await setTimeout(100); + await getMessage(`process ${name}`); +} + +async function getMessage(message) { + return `message is ${message}`; +} + +async function task(name) { + process(name).then(console.log); +} + +task("a task");