From 4f5e8cbb0910813b9c6806faa0be0417f115bdd7 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rafa=C5=82=20Rzepecki?= Date: Thu, 12 Mar 2026 14:40:14 +0100 Subject: [PATCH 1/7] test: handle Node 24 Symbol property format change in test snapshots Node 24's util.inspect changed Symbol property format from `[Symbol(foo)]` to `Symbol(foo)`. The `fixValue()` helper in tests was already stripping these to keep snapshots stable across Node versions, but the regex only matched the old bracketed format. Co-Authored-By: Claude Sonnet 4.6 --- test/helpers.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/test/helpers.ts b/test/helpers.ts index 718348a..2c1eb60 100644 --- a/test/helpers.ts +++ b/test/helpers.ts @@ -163,7 +163,7 @@ function fixValue(value: unknown): void { if (v.startsWith("Next")) value.value = v.split(" ")[0]; else if (v.includes("ObjectId")) value.value = v.replaceAll(/ObjectId\('.*'\)/g, "ObjectId('test')"); - else value.value = v.replaceAll(/\s+\[Symbol.*/g, ""); + else value.value = v.replaceAll(/\s+\[?Symbol.*/g, ""); } } From f089cb0f8bd6820bd614e91e412f6da6c4bb827d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rafa=C5=82=20Rzepecki?= Date: Thu, 12 Mar 2026 14:57:04 +0100 Subject: [PATCH 2/7] fix: restore async context in sqlite/mysql callbacks for correct event ordering Native DB callbacks (sqlite3, mysql) fire outside any AsyncLocalStorage context in Node 24+, causing return events to be appended to the root buffer after all call events instead of inline at the correct position. Fix by capturing the context at call time and restoring it when emitting the return event. Update sqlite snapshot to reflect the now-correct ordering. Co-Authored-By: Claude Sonnet 4.6 --- src/hooks/mysql.ts | 34 ++++++++++++--------- src/hooks/sqlite.ts | 28 +++++++++++------ test/__snapshots__/sqlite.test.ts.snap | 42 +++++++++++++------------- 3 files changed, 60 insertions(+), 44 deletions(-) diff --git a/src/hooks/mysql.ts b/src/hooks/mysql.ts index 99c9a36..9982024 100644 --- a/src/hooks/mysql.ts +++ b/src/hooks/mysql.ts @@ -2,6 +2,7 @@ import assert from "node:assert"; import type mysql from "mysql"; +import Recording from "../Recording"; import { getActiveRecordings, isActive } from "../recorder"; import { getTime } from "../util/getTime"; @@ -46,6 +47,9 @@ function createQueryProxy(query: mysql.QueryFunction) { const recordings = getActiveRecordings(); const callEvents = recordings.map((recording) => recording.sqlQuery("mysql", sql)); const startTime = getTime(); + // Capture the current async context so the callback can emit return events + // in the correct buffer position. See sqlite.ts for the same pattern. + const asyncContext = Recording.getContext(); const originalCallback = typeof argArray[argArray.length - 1] === "function" @@ -53,20 +57,22 @@ function createQueryProxy(query: mysql.QueryFunction) { : undefined; const newCallback: mysql.queryCallback = (err, results, fields) => { - if (err) - recordings.forEach( - (recording, idx) => - isActive(recording) && - recording.functionException(callEvents[idx].id, err, startTime), - ); - else - recordings.forEach( - (recording, idx) => - isActive(recording) && - recording.functionReturn(callEvents[idx].id, undefined, startTime), - ); - - originalCallback?.call(this, err, results, fields); + // Restore the captured context to keep events in causal order. + Recording.run(asyncContext, () => { + if (err) + recordings.forEach( + (recording, idx) => + isActive(recording) && + recording.functionException(callEvents[idx].id, err, startTime), + ); + else + recordings.forEach( + (recording, idx) => + isActive(recording) && + recording.functionReturn(callEvents[idx].id, undefined, startTime), + ); + originalCallback?.call(this, err, results, fields); + }); }; argArray.push(newCallback); diff --git a/src/hooks/sqlite.ts b/src/hooks/sqlite.ts index 9c4e7b2..abed298 100644 --- a/src/hooks/sqlite.ts +++ b/src/hooks/sqlite.ts @@ -1,6 +1,7 @@ /* eslint-disable @typescript-eslint/unbound-method */ import type sqlite from "sqlite3"; +import Recording from "../Recording"; import { getActiveRecordings, isActive } from "../recorder"; import { getTime } from "../util/getTime"; @@ -54,6 +55,11 @@ function createRecordingProxy( const recordings = getActiveRecordings(); const callEvents = recordings.map((recording) => recording.sqlQuery("sqlite", sql)); const startTime = getTime(); + // Capture the current async context so the completion callback can emit + // return events in the correct buffer position. Native sqlite callbacks + // fire outside any AsyncLocalStorage context (especially in Node 24+), + // which would otherwise place return events after all buffered call events. + const asyncContext = Recording.getContext(); // Extract callback argument(s) to functionArgs const functionArgs = []; @@ -87,15 +93,19 @@ function createRecordingProxy( | ((...args: unknown[]) => unknown); const newCompletionCallback = (...args: unknown[]) => { - const isError = args.length > 0 && args[0] != undefined; - if (!isError) { - recordings.forEach( - (recording, idx) => - isActive(recording) && - recording.functionReturn(callEvents[idx].id, undefined, startTime), - ); - } - originalCompletionCallback?.apply(this, args); + // Restore the captured context to keep events in causal order, and run + // the original callback inside it so any instrumented work it does is + // also recorded in the correct position. + Recording.run(asyncContext, () => { + const isError = args.length > 0 && args[0] != undefined; + if (!isError) + recordings.forEach( + (recording, idx) => + isActive(recording) && + recording.functionReturn(callEvents[idx].id, undefined, startTime), + ); + originalCompletionCallback?.apply(this, args); + }); }; newFunctionArgs.push(newCompletionCallback); diff --git a/test/__snapshots__/sqlite.test.ts.snap b/test/__snapshots__/sqlite.test.ts.snap index da8499e..dbf8f19 100644 --- a/test/__snapshots__/sqlite.test.ts.snap +++ b/test/__snapshots__/sqlite.test.ts.snap @@ -312,6 +312,13 @@ exports[`mapping Sqlite tests 1`] = ` }, "thread_id": 0, }, + { + "elapsed": 31.337, + "event": "return", + "id": 22, + "parent_id": 20, + "thread_id": 0, + }, { "defined_class": "index", "event": "call", @@ -364,6 +371,13 @@ exports[`mapping Sqlite tests 1`] = ` }, "thread_id": 0, }, + { + "elapsed": 31.337, + "event": "return", + "id": 26, + "parent_id": 24, + "thread_id": 0, + }, { "defined_class": "index", "event": "call", @@ -698,6 +712,13 @@ exports[`mapping Sqlite tests 1`] = ` }, "thread_id": 0, }, + { + "elapsed": 31.337, + "event": "return", + "id": 50, + "parent_id": 48, + "thread_id": 0, + }, { "defined_class": "index", "event": "call", @@ -844,27 +865,6 @@ exports[`mapping Sqlite tests 1`] = ` }, "thread_id": 0, }, - { - "elapsed": 31.337, - "event": "return", - "id": 22, - "parent_id": 20, - "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", From 5f35ed42a7f8486951cb7ac3ba2a23fe94ddf934 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rafa=C5=82=20Rzepecki?= Date: Thu, 12 Mar 2026 15:02:12 +0100 Subject: [PATCH 3/7] test: add delays between HTTP requests in test to ensure distinct timestamps Node 24 can complete consecutive requests within the same millisecond, giving them identical filename prefixes and non-deterministic glob ordering. 10ms gaps guarantee each request gets a unique timestamp. Co-Authored-By: Claude Sonnet 4.6 --- test/httpServer.test.ts | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/test/httpServer.test.ts b/test/httpServer.test.ts index c0a4a8e..98ad3a4 100644 --- a/test/httpServer.test.ts +++ b/test/httpServer.test.ts @@ -1,4 +1,5 @@ import { type IncomingMessage, request, OutgoingMessage } from "node:http"; +import { setTimeout as sleep } from "node:timers/promises"; import { SpawnAppmapNodeOptions, @@ -93,9 +94,16 @@ async function waitForLine( } async function makeRequests(port: number) { + // Small delays ensure each request gets a distinct millisecond timestamp in its + // AppMap filename. Without them, consecutive requests can complete within the same + // millisecond (especially on Node 24), producing identical filename prefixes whose + // glob ordering is non-deterministic. await makeRequest(port, ""); + await sleep(10); await makeRequest(port, "/nonexistent"); + await sleep(10); await makeRequest(port, "/api/foo?param1=3¶m2=4"); + await sleep(10); await makeRequest(port, "/api/bar", "POST", (req) => { req.appendHeader("Content-Type", "application/json"); req.write( From 67141480bec8e078866a07a0b97607c5a597bde4 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rafa=C5=82=20Rzepecki?= Date: Thu, 12 Mar 2026 15:18:52 +0100 Subject: [PATCH 4/7] fix: replace racy BroadcastChannel patching with eager pre-patching at startup MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit ## Background To instrument library modules (e.g. json5, node:console) under ESM, appmap-node used a CJS-cache trick: requiring a module via CommonJS pre-populates the cache that ESM also consults for CJS-format packages and built-ins. The challenge is doing this in the main thread before any ESM module body evaluates the import. The previous mechanism: 1. The ESM loader's resolve() hook (running in a separate worker thread in Node 22+) called forceRequire(specifier), which: a. Called cjsRequire(specifier) in the loader thread (ineffective in Node 22+ since the loader thread has its own separate CJS cache) b. Posted a BroadcastChannel message to the main thread 2. The main thread's esmRequireChannel.onmessage handler received the message and called cjsRequire(specifier) to patch the module in the main thread's cache. This was always racy: BroadcastChannel messages are delivered asynchronously through the event loop. In Node 24, the main thread consistently evaluates ESM module bodies before the broadcast message is processed, so the patched version of the module was never seen by the importing code. The existing http/https pre-patching in register.ts (added earlier to address the same race for those specific modules) was the correct pattern — it just wasn't generalised to all configured library modules. ## Fix Move all library module pre-patching into register.ts, which runs via --require in the main thread before any ESM evaluation takes place. This makes the patching unconditionally race-free regardless of Node.js version or scheduling behaviour. - Extend the pre-patch loop to cover all packages with a `module` field in the user's appmap.yml config (previously only node:http and node:https were covered) - Also pre-patch Prisma client module IDs, which were previously patched via forceRequire() in the loader's load() hook - Extract a prePatch() helper that silently ignores missing modules (a module listed in config may not be installed) ## Cleanup With all patching now handled at startup, the cross-thread side-channel is no longer needed: - Remove the BroadcastChannel (esmRequireChannel) and its onmessage handler from register.ts - Remove the forceRequire() export from register.ts - Remove the forceRequire() call sites from loader.ts (resolve() hook for library packages, load() hook for Prisma) - Remove the now-empty resolve() hook from loader.ts (Node only invokes exported hooks, so a passthrough adds overhead for no benefit) - Remove the node:worker_threads and config imports that are no longer needed Co-Authored-By: Claude Sonnet 4.6 --- src/loader.ts | 24 ------------------ src/register.ts | 67 +++++++++++++++++++++++-------------------------- 2 files changed, 31 insertions(+), 60 deletions(-) diff --git a/src/loader.ts b/src/loader.ts index 513eabf..189139d 100644 --- a/src/loader.ts +++ b/src/loader.ts @@ -3,28 +3,9 @@ import { URL, fileURLToPath } from "node:url"; import type { NodeLoaderHooksAPI2 } from "ts-node"; -import config from "./config"; import { warn } from "./message"; import transform, { findHook, getSourceMap, shouldMatchOriginalSourcePaths } from "./transform"; import { readPkgUp } from "./util/readPkgUp"; -import { forceRequire } from "./register"; - -export const resolve: NodeLoaderHooksAPI2["resolve"] = async function resolve( - url, - context, - nextResolve, -) { - const result = await nextResolve(url, context, nextResolve); - - // For libraries, we preempt import with CommonJS require here, instead - // of load function, because for third party libraries we can catch - // their import name here (i.e. url: "json5"). Then it gets resolved - // to a path (i.e. result.path: ".../node_modules/json5/lib/index.js") - // and passed to the load function. - if (config().getPackage(url, true) != undefined) forceRequire(url); - - return result; -}; export const load: NodeLoaderHooksAPI2["load"] = async function load(url, context, defaultLoad) { const urlObj = new URL(url); @@ -62,10 +43,5 @@ export const load: NodeLoaderHooksAPI2["load"] = async function load(url, contex return original; } - // For Prisma client modules, we preempt import with CommonJS require to allow our hooks to - // modify the loaded module in cache. http/https are handled in register.ts instead, where - // they are pre-patched in the main thread before any ESM imports can race against them. - if (config().prismaClientModuleIds.includes(url)) forceRequire(url); - return original; }; diff --git a/src/register.ts b/src/register.ts index 54f35a2..0deb250 100644 --- a/src/register.ts +++ b/src/register.ts @@ -1,7 +1,8 @@ import Module from "node:module"; import { pathToFileURL } from "node:url"; -import worker from "node:worker_threads"; +import config from "./config.js"; +import { warn } from "./message.js"; import { record } from "./recorder.js"; import requireHook from "./requireHook.js"; import transform from "./transform.js"; @@ -32,42 +33,36 @@ declare global { } global.AppMapRecordHook = record; -// A side channel to allow requiring a module when requested from -// the loader. This is a bit of a hack to allow patching modules like -// http and https in ESM; import hooks don't have a way to modify -// the module after it's loaded (like require hooks), but they share -// module cache for the built-in modules. By catching an import -// and requiring it before the import happens we pre-populate the -// cache with our patched version. -export function forceRequire(specifier: string): void { - cjsRequire(specifier); - // We also broadcast to other threads so it works when the - // loader is in a separate thread (as in newer nodes) with - // a separate module cache. - esmRequireChannel.postMessage(specifier); -} - const cjsRequire = Module.createRequire(__filename); -// Pre-patch http/https in the main thread so they're already instrumented before any ESM module -// imports them. Without this there is a race: when an ESM module does `import http from "http"`, -// the loader thread calls forceRequire() and sends a BroadcastChannel message to patch http in the -// main thread. But the main thread evaluates the ESM module body synchronously and can call into -// http (e.g. new http.ClientRequest()) before the BroadcastChannel message is ever processed. -cjsRequire("node:http"); -cjsRequire("node:https"); +// Pre-patch library modules in the main thread so they're already instrumented before any ESM +// module imports them. The ESM load() hook cannot transform built-in modules (node:http etc.) +// since they have no source, and for CJS-format third-party libraries the CJS cache is the only +// shared state between the loader thread and the main thread. register.ts runs via --require +// before any ESM evaluation, so these require() calls are race-free. +function prePatch(id: string, { warnOnFailure = false } = {}) { + try { + cjsRequire(id); + } catch (err: unknown) { + if (!warnOnFailure) return; + // Warn rather than crash. The module may not be installed, or it may be + // installed but broken (bad transitive dep, syntax error, etc.). Either + // way, if the application never actually imports it the problem is + // invisible without appmap — crashing the process here would make appmap + // appear to be the cause. A warning gives the user enough context to + // investigate without interrupting their workflow. + const detail = err instanceof Error ? err.message : String(err); + warn(`could not pre-patch '${id}' for instrumentation: ${detail}`); + } +} -const esmRequireChannel = new worker.BroadcastChannel("appmap-node/register/esm-require").unref(); +// Built-in patches: always attempted, silently skipped if not present. +prePatch("node:http"); +prePatch("node:https"); +for (const id of config().prismaClientModuleIds) prePatch(id); -esmRequireChannel.onmessage = (message: unknown) => { - if ( - !( - message != null && - typeof message == "object" && - "data" in message && - typeof message.data == "string" - ) - ) - return; - cjsRequire(message.data); -}; +// User-configured library modules: warn if pre-patching fails, since the +// user explicitly asked for instrumentation of these. +for (const pkg of config().packages) { + if (pkg.module) prePatch(pkg.module, { warnOnFailure: true }); +} From f805f27dcf9017b425efc1b485905256bdf76d54 Mon Sep 17 00:00:00 2001 From: Hleb Rubanau Date: Wed, 11 Mar 2026 17:40:07 +0100 Subject: [PATCH 5/7] chore(ci): matrix test against node 22, 24 --- .github/workflows/ci.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 67579be..6f880e4 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -16,7 +16,7 @@ jobs: test: strategy: matrix: - node-version: [18, 20, 21] + node-version: [18, 20, 22, 24] runs-on: ubuntu-latest services: From 9080cc078bea3bc1a71fa23febf4ad3f5732668d Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rafa=C5=82=20Rzepecki?= Date: Thu, 12 Mar 2026 17:06:28 +0100 Subject: [PATCH 6/7] test: normalize ObjectId inspect format in snapshots for Node 24 compat Node 24 changed util.inspect format for Symbol properties from [Symbol(foo)] to Symbol(foo), breaking the MongoDB snapshot which contained ObjectId { [Symbol(id)]: ... }. Extend the ObjectId normalizer in fixValue() to also collapse the inspect form (ObjectId { ... }) to ObjectId('...'), matching the existing handling of the string form ObjectId('hex'). Both now normalize to ObjectId('...') for stable cross-version snapshots. Co-Authored-By: Claude Sonnet 4.6 --- test/__snapshots__/mongo.test.ts.snap | 6 +++--- test/helpers.ts | 4 +++- 2 files changed, 6 insertions(+), 4 deletions(-) diff --git a/test/__snapshots__/mongo.test.ts.snap b/test/__snapshots__/mongo.test.ts.snap index 45e559e..a4b6445 100644 --- a/test/__snapshots__/mongo.test.ts.snap +++ b/test/__snapshots__/mongo.test.ts.snap @@ -149,7 +149,7 @@ exports[`mapping MongoDB tests 1`] = ` "object_id": 5, "value": "Promise { { acknowledged: true, - insertedId: ObjectId { [Symbol(id)]: [Buffer [Uint8Array]] } + insertedId: ObjectId('...') } }", }, "thread_id": 0, @@ -193,7 +193,7 @@ exports[`mapping MongoDB tests 1`] = ` "object_id": 7, "value": "Promise { { acknowledged: true, - insertedId: ObjectId { [Symbol(id)]: [Buffer [Uint8Array]] } + insertedId: ObjectId('...') } }", }, "thread_id": 0, @@ -348,7 +348,7 @@ exports[`mapping MongoDB tests 1`] = ` "return_value": { "class": "Promise", "object_id": 14, - "value": "Promise { { _id: ObjectId { [Symbol(id)]: [Buffer [Uint8Array]] }, a: 3 } }", + "value": "Promise { { _id: ObjectId('...'), a: 3 } }", }, "thread_id": 0, }, diff --git a/test/helpers.ts b/test/helpers.ts index 2c1eb60..0ca1c1a 100644 --- a/test/helpers.ts +++ b/test/helpers.ts @@ -162,7 +162,9 @@ function fixValue(value: unknown): void { const v = value.value; if (v.startsWith("Next")) value.value = v.split(" ")[0]; else if (v.includes("ObjectId")) - value.value = v.replaceAll(/ObjectId\('.*'\)/g, "ObjectId('test')"); + value.value = v + .replaceAll(/ObjectId\('[^']*'\)/g, "ObjectId('...')") + .replaceAll(/ObjectId\s*\{[^}]*\}/g, "ObjectId('...')"); else value.value = v.replaceAll(/\s+\[?Symbol.*/g, ""); } } From 0d31528e8bed145481ced3cd01d8a4c8f8d12718 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Rafa=C5=82=20Rzepecki?= Date: Thu, 12 Mar 2026 17:15:09 +0100 Subject: [PATCH 7/7] chore(ci): update GH actions to newest versions --- .github/workflows/ci.yml | 22 +++++++++++----------- .github/workflows/publish.yml | 4 ++-- 2 files changed, 13 insertions(+), 13 deletions(-) diff --git a/.github/workflows/ci.yml b/.github/workflows/ci.yml index 6f880e4..d2e57b4 100644 --- a/.github/workflows/ci.yml +++ b/.github/workflows/ci.yml @@ -6,8 +6,8 @@ jobs: lint: runs-on: ubuntu-latest steps: - - uses: actions/checkout@v4 - - uses: actions/setup-node@v4 + - uses: actions/checkout@v6 + - uses: actions/setup-node@v6 with: cache: yarn - run: yarn @@ -37,8 +37,8 @@ jobs: - 27017:27017 steps: - - uses: actions/checkout@v4 - - uses: actions/setup-node@v4 + - uses: actions/checkout@v6 + - uses: actions/setup-node@v6 with: node-version: ${{matrix.node-version}} cache: yarn @@ -52,8 +52,8 @@ jobs: windows-test: runs-on: windows-latest steps: - - uses: actions/checkout@v4 - - uses: actions/setup-node@v4 + - uses: actions/checkout@v6 + - uses: actions/setup-node@v6 with: cache: yarn - run: yarn @@ -64,14 +64,14 @@ jobs: pack: runs-on: ubuntu-latest steps: - - uses: actions/checkout@v4 - - uses: actions/setup-node@v4 + - uses: actions/checkout@v6 + - uses: actions/setup-node@v6 with: cache: yarn - run: yarn - run: echo "SHORT_SHA=$(git rev-parse --short HEAD)" >> $GITHUB_ENV - run: yarn pack -o appmap-node-${{ env.SHORT_SHA }}.tgz - - uses: actions/upload-artifact@v4 + - uses: actions/upload-artifact@v6 with: name: appmap-node-${{ env.SHORT_SHA }} path: appmap-node-${{ env.SHORT_SHA }}.tgz @@ -88,11 +88,11 @@ jobs: with: app-id: ${{ secrets.RELEASE_BOT_APP_ID }} private-key: ${{ secrets.RELEASE_BOT_PRIVATE_KEY }} - - uses: actions/checkout@v4 + - uses: actions/checkout@v6 with: fetch-depth: 0 token: ${{ steps.app-token.outputs.token }} - - uses: actions/setup-node@v4 + - uses: actions/setup-node@v6 with: cache: yarn - run: yarn diff --git a/.github/workflows/publish.yml b/.github/workflows/publish.yml index 0723139..9a8677b 100644 --- a/.github/workflows/publish.yml +++ b/.github/workflows/publish.yml @@ -11,8 +11,8 @@ jobs: id-token: write contents: read steps: - - uses: actions/checkout@v4 - - uses: actions/setup-node@v4 + - uses: actions/checkout@v6 + - uses: actions/setup-node@v6 with: node-version: 24 cache: yarn