diff --git a/README.md b/README.md index b4f5f53..78ceb5f 100644 --- a/README.md +++ b/README.md @@ -103,8 +103,7 @@ a base directory of `/tmp/dump/`, then the patched code will be written to ### Diagnostics Hook A diagnostics hook can be set which is called every time a module is transformed -or transformation fails. This hook will only work with the synchronous -`registerHooks` because the older `register` runs in a different thread. +or transformation fails. ```js import { setDiagnosticsHook } from '@apm-js-collab/tracing-hooks/hook-sync.mjs' @@ -116,4 +115,27 @@ setDiagnosticsHook(({ url, moduleName, error }) => { // injection succeeded } }) -``` \ No newline at end of file +``` + +With the synchronous `registerHooks` (and the `_compile` patch) this is all that +is needed. The older async `register` runs its hooks on a separate thread where +the hook set above is not visible, so pass a MessagePort created with +`createDiagnosticsPort()` for the loader thread to post its diagnostics back: + +```js +import { setDiagnosticsHook, createDiagnosticsPort } from '@apm-js-collab/tracing-hooks/hook-sync.mjs' + +setDiagnosticsHook(({ url, moduleName, error }) => { /* ... */ }) + +const diagnosticsPort = createDiagnosticsPort() +Module.register('@apm-js-collab/tracing-hooks/hook.mjs', import.meta.url, { + data: { instrumentations, diagnosticsPort }, + transferList: [diagnosticsPort] +}) +``` + +On this path, diagnostics for ES modules are posted from the loader thread and +therefore arrive asynchronously, some time after the module was transformed; +diagnostics for CommonJS modules come from the `_compile` patch and are emitted +synchronously as before. The port does not keep the process alive, so +diagnostics still in flight when the process exits are dropped. \ No newline at end of file diff --git a/hook-sync.mjs b/hook-sync.mjs index 2b221a1..979f9b8 100644 --- a/hook-sync.mjs +++ b/hook-sync.mjs @@ -1 +1 @@ -export { initializeSync as initialize, loadSync as load, resolveSync as resolve, setDiagnosticsHook } from './hook.mjs' +export { initializeSync as initialize, loadSync as load, resolveSync as resolve, setDiagnosticsHook, createDiagnosticsPort } from './hook.mjs' diff --git a/hook.mjs b/hook.mjs index 15aeb56..d8b121e 100644 --- a/hook.mjs +++ b/hook.mjs @@ -3,17 +3,35 @@ import createDebug from 'debug' import { create } from '@apm-js-collab/code-transformer' import parse from 'module-details-from-path' import { fileURLToPath } from 'node:url' +import { MessageChannel } from 'node:worker_threads' import getPackageVersion from './lib/get-package-version.js' +import { setDiagnosticsHook, emitDiagnostics } from './lib/diagnostics.js' import { readFileSync } from 'node:fs' const debug = createDebug('@apm-js-collab/tracing-hooks:esm-hook') let transformers = null let packages = null let instrumentator = null -let diagnosticsHook +export { setDiagnosticsHook } -export function setDiagnosticsHook(hook) { - diagnosticsHook = hook +// On the main thread diagnostics go straight to the hook set via +// `setDiagnosticsHook`. When these hooks run on the `Module.register` loader +// thread, `initialize` swaps this for a function that posts back over the +// MessagePort supplied in `data.diagnosticsPort`. +let emit = emitDiagnostics + +/** + * Creates a MessagePort that forwards diagnostics posted by the `Module.register` + * loader thread to the hook set via `setDiagnosticsHook` on this thread. Pass the + * returned port to `Module.register` in both `data.diagnosticsPort` and + * `transferList`. + */ +export function createDiagnosticsPort() { + const { port1, port2 } = new MessageChannel() + port1.on('message', emitDiagnostics) + // The diagnostics channel must not keep the process alive. + port1.unref() + return port2 } export async function initialize(data = {}) { @@ -24,6 +42,23 @@ export function initializeSync(data = {}) { instrumentator = create(instrumentations) packages = new Set(instrumentations.map(i => i.module.name)) transformers = new Map() + emit = data?.diagnosticsPort ? createPortEmitter(data.diagnosticsPort) : emitDiagnostics +} + +function createPortEmitter(port) { + return (diag) => { + try { + // Structured clone reliably carries Error instances but not arbitrary thrown + // values, so flatten anything else to an Error rather than let postMessage + // throw inside the load path. + const error = diag.error === undefined || diag.error instanceof Error + ? diag.error + : new Error(String(diag.error)) + port.postMessage({ ...diag, error }) + } catch (err) { + debug('failed to post diagnostics for %s: %o', diag.url, err) + } + } } export async function resolve(specifier, context, nextResolve) { @@ -107,14 +142,10 @@ export function loadResult(url, result) { const transformedCode = transformer.transform(source, moduleType) result.source = transformedCode?.code result.shortCircuit = true - if (diagnosticsHook) { - diagnosticsHook({ url, moduleName: transformer.moduleName }) - } + emit({ url, moduleName: transformer.moduleName }) } catch (err) { debug('Error transforming module %s: %o', url, err) - if (diagnosticsHook) { - diagnosticsHook({ url, moduleName: transformer.moduleName, error: err }) - } + emit({ url, moduleName: transformer.moduleName, error: err }) } finally { transformer.free() } diff --git a/index.js b/index.js index f97d5f2..985e20b 100644 --- a/index.js +++ b/index.js @@ -2,7 +2,9 @@ const { create } = require('@apm-js-collab/code-transformer') const Module = require('node:module') const parse = require('module-details-from-path') +const { pathToFileURL } = require('node:url') const getPackageVersion = require('./lib/get-package-version') +const { emitDiagnostics } = require('./lib/diagnostics') const debug = require('debug')('@apm-js-collab/tracing-hooks:module-patch') class ModulePatch { @@ -35,11 +37,13 @@ class ModulePatch { // match a CJS target. const transformedCode = transformer.transform(content, 'cjs') args[0] = transformedCode?.code + emitDiagnostics({ url: pathToFileURL(filename).href, moduleName: transformer.moduleName }) if (process.env.TRACING_DUMP) { dump(args[0], filename) } } catch (error) { debug('Error transforming module %s: %o', filename, error) + emitDiagnostics({ url: pathToFileURL(filename).href, moduleName: transformer.moduleName, error }) } finally { transformer.free() } diff --git a/lib/diagnostics.js b/lib/diagnostics.js new file mode 100644 index 0000000..80beb6a --- /dev/null +++ b/lib/diagnostics.js @@ -0,0 +1,22 @@ +'use strict' + +// Main-thread diagnostics state shared by everything that can transform a module on +// this thread: the ESM hooks (hook.mjs / hook-sync.mjs) and the +// `Module.prototype._compile` patch (index.js). One CJS module holds the hook so +// setting it once covers all of them. The `Module.register` loader thread gets its +// own copy of this module where the hook is never set — diagnostics from that thread +// arrive over a MessagePort instead (see createDiagnosticsPort in hook.mjs). + +let diagnosticsHook + +function setDiagnosticsHook(hook) { + diagnosticsHook = hook +} + +function emitDiagnostics(diag) { + if (diagnosticsHook) { + diagnosticsHook(diag) + } +} + +module.exports = { setDiagnosticsHook, emitDiagnostics } diff --git a/test/example-deps/lib/esm-app.mjs b/test/example-deps/lib/esm-app.mjs index b372492..4d78710 100644 --- a/test/example-deps/lib/esm-app.mjs +++ b/test/example-deps/lib/esm-app.mjs @@ -38,4 +38,9 @@ tracingChannel(scenario.channel).subscribe({ }) const result = await scenario.run() -console.log(JSON.stringify({ result, events })) + +// Diagnostics posted from the `Module.register` loader thread are delivered +// asynchronously; give the message queue a turn to drain before reporting. +await new Promise(resolve => setImmediate(resolve)) + +console.log(JSON.stringify({ result, events, diagnostics: globalThis.__diagnostics })) diff --git a/test/example-deps/lib/register-async-diagnostics.mjs b/test/example-deps/lib/register-async-diagnostics.mjs new file mode 100644 index 0000000..b90b189 --- /dev/null +++ b/test/example-deps/lib/register-async-diagnostics.mjs @@ -0,0 +1,21 @@ +// The Node < 24.13 registration with diagnostics wired up: ESM transforms happen on +// the `Module.register` loader thread and post their diagnostics back over the +// MessagePort from createDiagnosticsPort(), while CJS transforms happen in the +// `_compile` patch on this thread and reach the same hook directly. +import Module, { createRequire } from 'node:module' +import { setDiagnosticsHook, createDiagnosticsPort } from '../../../hook.mjs' +import { instrumentations } from './instrumentations.mjs' + +const ModulePatch = createRequire(import.meta.url)('../../../index.js') + +globalThis.__diagnostics = [] +setDiagnosticsHook(({ url, moduleName, error }) => { + globalThis.__diagnostics.push({ url, moduleName, error: error?.message }) +}) + +const diagnosticsPort = createDiagnosticsPort() +Module.register('../../../hook.mjs', import.meta.url, { + data: { instrumentations, diagnosticsPort }, + transferList: [diagnosticsPort] +}) +new ModulePatch({ instrumentations }).patch() diff --git a/test/hook.test.mjs b/test/hook.test.mjs index 5631cdd..15ed0fd 100644 --- a/test/hook.test.mjs +++ b/test/hook.test.mjs @@ -246,3 +246,79 @@ test('unrecognized format falls through to "unknown" without throwing', async (t const url = await esmLoaderRewriter.resolve('pkg-1', {}, resolveFn) await assert.doesNotReject(() => esmLoaderRewriter.load(url.url, {}, nextLoad)) }) + +// On the `Module.register` loader thread the main thread's diagnostics hook is not +// visible, so `initialize` accepts a MessagePort in `data.diagnosticsPort` and posts +// diagnostics over it instead. +test('initialize with a diagnosticsPort posts diagnostics over the port', async (t) => { + const { esmLoaderRewriter } = t.ctx + const posted = [] + esmLoaderRewriter.initialize({ + instrumentations: [ + { + channelName: 'unitTestEsm', + module: { name: 'esm-pkg', versionRange: '>=1', filePath: 'foo.js' }, + functionQuery: { className: 'Foo', methodName: 'doStuff', kind: 'Async' } + } + ], + diagnosticsPort: { postMessage: (diag) => posted.push(diag) } + }) + + const esmPath = path.join(import.meta.dirname, './example-deps/lib/node_modules/esm-pkg/foo.js') + async function resolveFn() { + return { url: `file://${esmPath}` } + } + async function nextLoad() { + return { format: 'module', source: readFileSync(esmPath, 'utf8') } + } + const url = await esmLoaderRewriter.resolve('esm-pkg', {}, resolveFn) + const result = await esmLoaderRewriter.load(url.url, {}, nextLoad) + + assert.equal(result.shortCircuit, true) + assert.deepEqual(posted, [{ url: `file://${esmPath}`, moduleName: 'esm-pkg', error: undefined }]) +}) + +test('a diagnosticsPort that fails to post must not break module loading', async (t) => { + const { esmLoaderRewriter } = t.ctx + esmLoaderRewriter.initialize({ + instrumentations: [ + { + channelName: 'unitTestEsm', + module: { name: 'esm-pkg', versionRange: '>=1', filePath: 'foo.js' }, + functionQuery: { className: 'Foo', methodName: 'doStuff', kind: 'Async' } + } + ], + diagnosticsPort: { postMessage: () => { throw new Error('boom') } } + }) + + const esmPath = path.join(import.meta.dirname, './example-deps/lib/node_modules/esm-pkg/foo.js') + async function resolveFn() { + return { url: `file://${esmPath}` } + } + async function nextLoad() { + return { format: 'module', source: readFileSync(esmPath, 'utf8') } + } + const url = await esmLoaderRewriter.resolve('esm-pkg', {}, resolveFn) + const result = await esmLoaderRewriter.load(url.url, {}, nextLoad) + + assert.equal(result.shortCircuit, true, 'the module must still be transformed') +}) + +// The main-thread half of the bridge: messages posted into the port returned by +// createDiagnosticsPort must reach the hook set with setDiagnosticsHook. +test('createDiagnosticsPort delivers posted diagnostics to the local hook', async (t) => { + const { esmLoaderRewriter } = t.ctx + const received = new Promise(resolve => esmLoaderRewriter.setDiagnosticsHook(resolve)) + const port = esmLoaderRewriter.createDiagnosticsPort() + // The receiving side of the port is deliberately unref'd so it can't keep a real + // process alive; here that means holding the event loop open until delivery. + const keepAlive = setTimeout(() => {}, 5000) + try { + port.postMessage({ url: 'file:///pkg/index.js', moduleName: 'pkg' }) + assert.deepEqual(await received, { url: 'file:///pkg/index.js', moduleName: 'pkg' }) + } finally { + clearTimeout(keepAlive) + port.close() + esmLoaderRewriter.setDiagnosticsHook(undefined) + } +}) diff --git a/test/index.test.js b/test/index.test.js index 68864c3..dd177ce 100644 --- a/test/index.test.js +++ b/test/index.test.js @@ -5,7 +5,9 @@ const assert = require('node:assert') const Module = require('node:module') const Snap = require('@matteo.collina/snap') const ModulePatch = require('../index.js') +const { setDiagnosticsHook } = require('../lib/diagnostics') const path = require('node:path') +const { pathToFileURL } = require('node:url') const { readFileSync, mkdirSync, rmSync, statSync } = require('node:fs') test.beforeEach((t) => { @@ -80,6 +82,40 @@ test('should not rewrite code for an unmatch patch', async (t) => { assert.deepEqual(rewrittenCode, snapshot) }) +// The `_compile` patch is what transforms CommonJS on the async-hooks path, so it has +// to emit diagnostics too — the loader thread never sees these modules. +test('should emit diagnostics when a module is transformed', (t) => { + const { modulePath, modulePatch } = t.ctx + const diagnostics = [] + setDiagnosticsHook(diag => diagnostics.push(diag)) + t.after(() => setDiagnosticsHook(undefined)) + + modulePatch.patch() + const resolvedPath = Module._resolveFilename(modulePath, null, false) + const data = readFileSync(resolvedPath, 'utf8') + new Module(resolvedPath)._compile(data, resolvedPath) + + assert.deepEqual(diagnostics, [{ url: pathToFileURL(resolvedPath).href, moduleName: 'pkg-1' }]) +}) + +test('should emit diagnostics with the error when transformation fails', (t) => { + const { modulePath, modulePatch } = t.ctx + const diagnostics = [] + setDiagnosticsHook(diag => diagnostics.push(diag)) + t.after(() => setDiagnosticsHook(undefined)) + + modulePatch.patch() + const resolvedPath = Module._resolveFilename(modulePath, null, false) + // Unparseable source makes the transformer throw; `_compile` then also throws on it, + // but the failure diagnostic must already have been emitted by then. + assert.throws(() => new Module(resolvedPath)._compile('const {', resolvedPath)) + + assert.equal(diagnostics.length, 1) + assert.equal(diagnostics[0].url, pathToFileURL(resolvedPath).href) + assert.equal(diagnostics[0].moduleName, 'pkg-1') + assert.ok(diagnostics[0].error instanceof Error) +}) + test('should not rewrite code if a function query does not exist in file', async (t) => { const { modulePath, snap } = t.ctx const subscribers = { diff --git a/test/loader-integration.test.mjs b/test/loader-integration.test.mjs index a324361..2de11c9 100644 --- a/test/loader-integration.test.mjs +++ b/test/loader-integration.test.mjs @@ -61,6 +61,32 @@ test('async hooks without the _compile patch do not instrument CJS', async () => assert.equal(result, 'middleware:esm-require-dep-linked', 'and the module itself still works') }) +// Diagnostics on the async path: the loader thread cannot see a hook set with +// `setDiagnosticsHook` on the main thread, so it posts transform events back over the +// MessagePort from `createDiagnosticsPort()`; the `_compile` patch emits directly on +// the main thread. Both must land in the one hook the app registered. +test('async hooks report diagnostics from both threads', async (t) => { + await t.test('ESM transform on the loader thread arrives over the port', async () => { + const { events, diagnostics } = await runApp('register-async-diagnostics.mjs', 'esm-app.mjs', 'esm') + + assert.deepEqual(events, ['start', 'end'], 'instrumentation must still work with diagnostics wired up') + assert.equal(diagnostics.length, 1) + assert.equal(diagnostics[0].moduleName, 'esm-pkg') + assert.match(diagnostics[0].url, /esm-pkg\/foo\.js$/) + assert.equal(diagnostics[0].error, undefined) + }) + + await t.test('CJS transform via the _compile patch emits on the main thread', async () => { + const { events, diagnostics } = await runApp('register-async-diagnostics.mjs', 'esm-app.mjs', 'cjs-require-esm') + + assert.deepEqual(events, ['start', 'end']) + assert.equal(diagnostics.length, 1) + assert.equal(diagnostics[0].moduleName, 'cjs-entry-lib') + assert.match(diagnostics[0].url, /cjs-entry-lib\/lib\/application\.js$/) + assert.equal(diagnostics[0].error, undefined) + }) +}) + // The sync hooks are the only path that transforms CommonJS in the loader itself. test('sync hooks instrument a CJS package whose require chain reaches ESM', { skip: !stableSyncHooks }, async () => { const { result, events } = await runApp('register-sync.mjs', 'esm-app.mjs', 'cjs-require-esm')