diff --git a/src/__tests__/recorder.test.ts b/src/__tests__/recorder.test.ts index 2cb19f55..d79e3ea6 100644 --- a/src/__tests__/recorder.test.ts +++ b/src/__tests__/recorder.test.ts @@ -1,9 +1,11 @@ /* eslint-disable @typescript-eslint/unbound-method */ import AppMap from "../AppMap"; -import { createTestFn } from "./helpers"; +import Recording from "../Recording"; +import { resetObjectIds } from "../parameter"; import * as recorder from "../recorder"; import { pauseRecorder, resumeRecorder } from "../recorderPause"; -import Recording from "../Recording"; +import { getTime } from "../util/getTime"; +import { createTestFn } from "./helpers"; describe(recorder.record, () => { it("records the function call", () => { @@ -48,8 +50,84 @@ describe(recorder.record, () => { }); }); +describe(recorder.fixReturnEventIfPromiseResult, () => { + it("records a fix up after the promise resolves", async () => { + const promise = Promise.resolve("resolved"); + const result = recorder.fixReturnEventIfPromiseResult( + promise, + returnEvent, + callEvent, + getTime(), + ); + + await expect(result).resolves.toBe("resolved"); + + expect(Recording.prototype.fixup).toBeCalledTimes(1); + expect(Recording.prototype.fixup).toBeCalledWith({ + ...returnEvent, + return_value: { + class: "Promise", + value: "Promise { 'resolved' }", + object_id: 1, + }, + elapsed: 0, + }); + }); + + it("records a fix up after the promise rejects", async () => { + const promise = Promise.reject(new Error("test")); + const result = recorder.fixReturnEventIfPromiseResult( + promise, + returnEvent, + callEvent, + getTime(), + ); + await expect(result).rejects.toThrowError("test"); + + expect(Recording.prototype.fixup).toBeCalledTimes(1); + + // this should have both return_value and exceptions + expect(Recording.prototype.fixup).toBeCalledWith({ + ...returnEvent, + return_value: { + class: "Promise", + value: "Promise { }", + object_id: 2, + }, + exceptions: [ + { + class: "Error", + message: "test", + object_id: 1, + }, + ], + elapsed: 0, + }); + }); + + const callEvent: AppMap.FunctionCallEvent = { + event: "call", + defined_class: "Test", + id: 42, + method_id: "test", + static: true, + thread_id: 0, + }; + const returnEvent: AppMap.FunctionReturnEvent = { + event: "return", + id: 43, + parent_id: 42, + thread_id: 0, + return_value: { + class: "Promise", + value: "Promise { }", + }, + }; +}); + afterEach(() => { jest.clearAllMocks(); + resetObjectIds(); }); jest.mock("../Recording"); diff --git a/src/parameter.ts b/src/parameter.ts index ce3cf119..fea7000a 100644 --- a/src/parameter.ts +++ b/src/parameter.ts @@ -70,7 +70,7 @@ function propertiesSchema( } let nextId = 1; -const objectIds = new WeakMap(); +let objectIds = new WeakMap(); export function objectId(object: object | null): number { if (object === null) return 0; @@ -78,3 +78,9 @@ export function objectId(object: object | null): number { if (!objectIds.has(object)) objectIds.set(object, id); return id; } + +// for testing purposes +export function resetObjectIds() { + nextId = 1; + objectIds = new WeakMap(); +} diff --git a/src/recorder.ts b/src/recorder.ts index 1dd20b52..7cc95fae 100644 --- a/src/recorder.ts +++ b/src/recorder.ts @@ -3,8 +3,9 @@ import { isPromise } from "node:util/types"; import AppMap from "./AppMap"; import Recording, { writtenAppMaps } from "./Recording"; -import { makeReturnEvent } from "./event"; +import { makeExceptionEvent, makeReturnEvent } from "./event"; import { info } from "./message"; +import { objectId } from "./parameter"; import { recorderPaused } from "./recorderPause"; import { FunctionInfo } from "./registry"; import commonPathPrefix from "./util/commonPathPrefix"; @@ -45,10 +46,32 @@ export function fixReturnEventIfPromiseResult( startTime: number, ) { if (isPromise(result) && returnEvent.return_value?.value.includes("")) - return result.then(() => { - recording.fixup(makeReturnEvent(returnEvent.id, callEvent.id, result, getTime() - startTime)); - return result; - }); + return result.then( + () => { + recording.fixup( + makeReturnEvent(returnEvent.id, callEvent.id, result, getTime() - startTime), + ); + 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); + return result; + }, + ); return result; } diff --git a/test/__snapshots__/simple.test.ts.snap b/test/__snapshots__/simple.test.ts.snap index 9f45e3ee..741251b1 100644 --- a/test/__snapshots__/simple.test.ts.snap +++ b/test/__snapshots__/simple.test.ts.snap @@ -205,13 +205,13 @@ exports[`mapping a simple script 1`] = ` { "children": [ { - "location": "./index.js:13", + "location": "./index.js:14", "name": "immediatePromise", "static": true, "type": "function", }, { - "location": "./index.js:17", + "location": "./index.js:18", "name": "throws", "static": true, "type": "function", @@ -238,6 +238,25 @@ exports[`mapping a simple script 1`] = ` }, ], "eventUpdates": { + "10": { + "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 { }", + }, + "thread_id": 0, + }, "8": { "elapsed": 31.337, "event": "return", @@ -256,7 +275,7 @@ exports[`mapping a simple script 1`] = ` "defined_class": "index", "event": "call", "id": 1, - "lineno": 17, + "lineno": 18, "method_id": "throws", "parameters": [], "path": "./index.js", @@ -360,9 +379,15 @@ exports[`mapping a simple script 1`] = ` "defined_class": "index", "event": "call", "id": 9, - "lineno": 13, - "method_id": "immediatePromise", - "parameters": [], + "lineno": 8, + "method_id": "promised", + "parameters": [ + { + "class": "Boolean", + "name": "ok", + "value": "false", + }, + ], "path": "./index.js", "static": true, "thread_id": 0, @@ -375,10 +400,58 @@ exports[`mapping a simple script 1`] = ` "return_value": { "class": "Promise", "object_id": 3, + "value": "Promise { }", + }, + "thread_id": 0, + }, + { + "defined_class": "index", + "event": "call", + "id": 11, + "lineno": 14, + "method_id": "immediatePromise", + "parameters": [], + "path": "./index.js", + "static": true, + "thread_id": 0, + }, + { + "elapsed": 31.337, + "event": "return", + "id": 12, + "parent_id": 11, + "return_value": { + "class": "Promise", + "object_id": 4, "value": "Promise { 'immediate' }", }, "thread_id": 0, }, + { + "defined_class": "index", + "event": "call", + "id": 13, + "lineno": 18, + "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, + }, ], "metadata": { "app": "appmap-node", diff --git a/test/simple/index.js b/test/simple/index.js index 4f1ac85c..c826be39 100644 --- a/test/simple/index.js +++ b/test/simple/index.js @@ -5,8 +5,9 @@ function foo(x) { return x * 2; } -async function promised() { - await setTimeout(100); +async function promised(ok = true) { + await setTimeout(10); + if (!ok) throws(); return "promised return"; } @@ -28,4 +29,5 @@ try { console.log(foo(42)); promised().then(console.log); +promised(false).catch(console.log); immediatePromise().then(console.log);