diff --git a/debug.js b/debug.js new file mode 100644 index 0000000..ecaa265 --- /dev/null +++ b/debug.js @@ -0,0 +1,59 @@ +'use strict'; + +// We cannot use console.log for debugging because it would call back into our hook +const fs = require('fs'); +function debug(msg) { + fs.writeSync(1, 'trace.js DEBUG ' + msg + '\n'); +} + +function printRootTraces(traces) { + const rootAsyncIds = findRootAsyncIds(traces); + for (const asyncId of rootAsyncIds) { + printTree(traces, traces.get(asyncId)); + } +} + +function findRootAsyncIds(traces) { + const asyncIds = new Set(traces.keys()); + for (const trace of traces.values()) { + for (const notRootTrace of trace.relatedTraces) { + asyncIds.delete(notRootTrace.asyncId); + } + } + return asyncIds; +} + +function printTree(traces, trace, indent='', isLast=true, visited=new Set()) { + let line = indent + '\\-' + trace.asyncId; + + if (isLast) { + indent += ' '; + } else { + indent += '| '; + } + + if (!traces.get(trace.asyncId)) { + line += ' (not-root)'; + } + + if (visited.has(trace.asyncId)) { + line += ' (cycle)'; + } + + fs.writeSync(1, line + '\n'); + + if (visited.has(trace.asyncId)) { + return; + } + visited.add(trace.asyncId); + + for (let i = 0; i < trace.relatedTraces.length; ++i) { + const isLast = i === trace.relatedTraces.length - 1; + printTree(traces, trace.relatedTraces[i], indent, isLast, visited); + } +} + +module.exports = { + debug, + printRootTraces +}; diff --git a/test/expected/async-await-follow.txt b/test/expected/async-await-follow.txt new file mode 100644 index 0000000..1406bcd --- /dev/null +++ b/test/expected/async-await-follow.txt @@ -0,0 +1,27 @@ +Error: FAIL + at f1 (/scripts/async-await-follow.js:r:c) + at Function.resolve () + at f1 (/scripts/async-await-follow.js:r:c) + at + at f1 (/scripts/async-await-follow.js:r:c) + at f2 (/scripts/async-await-follow.js:r:c) + at Function.resolve () + at f2 (/scripts/async-await-follow.js:r:c) + at + at f2 (/scripts/async-await-follow.js:r:c) + at f3 (/scripts/async-await-follow.js:r:c) + at process._tickCallback (internal/process/next_tick.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at Function.resolve () + at f3 (/scripts/async-await-follow.js:r:c) + at + at f3 (/scripts/async-await-follow.js:r:c) + at Object. (/scripts/async-await-follow.js:r:c) + at Module._compile (internal/modules/cjs/loader.js:r:c) + at Object.Module._extensions..js (internal/modules/cjs/loader.js:r:c) + at Module.load (internal/modules/cjs/loader.js:r:c) + at tryModuleLoad (internal/modules/cjs/loader.js:r:c) + at Function.Module._load (internal/modules/cjs/loader.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at startup (internal/bootstrap/node.js:r:c) + at bootstrapNodeJSCore (internal/bootstrap/node.js:r:c) diff --git a/test/expected/promise-child-stack.txt b/test/expected/promise-child-stack.txt index de25af6..0feea13 100644 --- a/test/expected/promise-child-stack.txt +++ b/test/expected/promise-child-stack.txt @@ -1,21 +1,16 @@ Error: hello at scopeThrow (/scripts/promise-child-stack.js:r:c) - at at process._tickCallback (internal/process/next_tick.js:r:c) - at Function.Module.runMain (module.js:r:c) - at startup (bootstrap_node.js:r:c) - at bootstrap_node.js:r:c - at PromiseWrap.emitInitNative (internal/async_hooks.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) at Promise.then () at Object. (/scripts/promise-child-stack.js:r:c) - at PromiseWrap.emitInitNative (internal/async_hooks.js:r:c) at Function.resolve () at Object. (/scripts/promise-child-stack.js:r:c) - at Module._compile (module.js:r:c) - at Object.Module._extensions..js (module.js:r:c) - at Module.load (module.js:r:c) - at tryModuleLoad (module.js:r:c) - at Function.Module._load (module.js:r:c) - at Function.Module.runMain (module.js:r:c) - at startup (bootstrap_node.js:r:c) - at bootstrap_node.js:r:c + at Module._compile (internal/modules/cjs/loader.js:r:c) + at Object.Module._extensions..js (internal/modules/cjs/loader.js:r:c) + at Module.load (internal/modules/cjs/loader.js:r:c) + at tryModuleLoad (internal/modules/cjs/loader.js:r:c) + at Function.Module._load (internal/modules/cjs/loader.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at startup (internal/bootstrap/node.js:r:c) + at bootstrapNodeJSCore (internal/bootstrap/node.js:r:c) diff --git a/test/expected/promise-resolve-follow.txt b/test/expected/promise-resolve-follow.txt new file mode 100644 index 0000000..a15a034 --- /dev/null +++ b/test/expected/promise-resolve-follow.txt @@ -0,0 +1,28 @@ +Error: FAIL + at Timeout.setTimeout [as _onTimeout] (/scripts/promise-resolve-follow.js:r:c) + at listOnTimeout (timers.js:r:c) + at processTimers (timers.js:r:c) + at new Promise () + at f1 (/scripts/promise-resolve-follow.js:r:c) + at Promise (/scripts/promise-resolve-follow.js:r:c) + at new Promise () + at f2 (/scripts/promise-resolve-follow.js:r:c) + at Promise.resolve.then (/scripts/promise-resolve-follow.js:r:c) + at process._tickCallback (internal/process/next_tick.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at Promise.then () + at Promise.catch () + at f3 (/scripts/promise-resolve-follow.js:r:c) + at Promise.then () + at f3 (/scripts/promise-resolve-follow.js:r:c) + at Function.resolve () + at f3 (/scripts/promise-resolve-follow.js:r:c) + at Object. (/scripts/promise-resolve-follow.js:r:c) + at Module._compile (internal/modules/cjs/loader.js:r:c) + at Object.Module._extensions..js (internal/modules/cjs/loader.js:r:c) + at Module.load (internal/modules/cjs/loader.js:r:c) + at tryModuleLoad (internal/modules/cjs/loader.js:r:c) + at Function.Module._load (internal/modules/cjs/loader.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at startup (internal/bootstrap/node.js:r:c) + at bootstrapNodeJSCore (internal/bootstrap/node.js:r:c) diff --git a/test/expected/regression-delayed-formater.txt b/test/expected/regression-delayed-formater.txt index 44054ad..c4d155f 100644 --- a/test/expected/regression-delayed-formater.txt +++ b/test/expected/regression-delayed-formater.txt @@ -4,11 +4,11 @@ throw new Error('trace'); Error: trace at-hack Object. (/scripts/regression-delayed-formater.js:r:c) - at-hack Module._compile (module.js:r:c) - at-hack Object.Module._extensions..js (module.js:r:c) - at-hack Module.load (module.js:r:c) - at-hack tryModuleLoad (module.js:r:c) - at-hack Function.Module._load (module.js:r:c) - at-hack Function.Module.runMain (module.js:r:c) - at-hack startup (bootstrap_node.js:r:c) - at-hack bootstrap_node.js:r:c + at-hack Module._compile (internal/modules/cjs/loader.js:r:c) + at-hack Object.Module._extensions..js (internal/modules/cjs/loader.js:r:c) + at-hack Module.load (internal/modules/cjs/loader.js:r:c) + at-hack tryModuleLoad (internal/modules/cjs/loader.js:r:c) + at-hack Function.Module._load (internal/modules/cjs/loader.js:r:c) + at-hack Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at-hack startup (internal/bootstrap/node.js:r:c) + at-hack bootstrapNodeJSCore (internal/bootstrap/node.js:r:c) diff --git a/test/expected/regression-http-close.txt b/test/expected/regression-http-close.txt index 25f4a3c..e32be73 100644 --- a/test/expected/regression-http-close.txt +++ b/test/expected/regression-http-close.txt @@ -7,87 +7,29 @@ Error: trace at Object.onceWrapper (events.js:r:c) at Server.emit (events.js:r:c) at emitCloseNT (net.js:r:c) - at process._tickCallback (internal/process/next_tick.js:r:c) - at emitInitNative (internal/async_hooks.js:r:c) - at emitInitScript (internal/async_hooks.js:r:c) at new TickObject (internal/process/next_tick.js:r:c) - at internalNextTick (internal/process/next_tick.js:r:c) + at nextTick (internal/process/next_tick.js:r:c) at Server._emitCloseIfDrained (net.js:r:c) at Server.close (net.js:r:c) at IncomingMessage.end (/scripts/regression-http-close.js:r:c) at Object.onceWrapper (events.js:r:c) at IncomingMessage.emit (events.js:r:c) at endReadableNT (_stream_readable.js:r:c) - at process._tickCallback (internal/process/next_tick.js:r:c) - at emitInitNative (internal/async_hooks.js:r:c) - at emitInitScript (internal/async_hooks.js:r:c) - at new TickObject (internal/process/next_tick.js:r:c) - at process.nextTick (internal/process/next_tick.js:r:c) - at endReadable (_stream_readable.js:r:c) - at IncomingMessage.Readable.read (_stream_readable.js:r:c) - at flow (_stream_readable.js:r:c) - at resume_ (_stream_readable.js:r:c) - at process._tickCallback (internal/process/next_tick.js:r:c) - at emitInitNative (internal/async_hooks.js:r:c) - at emitInitScript (internal/async_hooks.js:r:c) - at new TickObject (internal/process/next_tick.js:r:c) - at process.nextTick (internal/process/next_tick.js:r:c) - at resume (_stream_readable.js:r:c) - at IncomingMessage.Readable.resume (_stream_readable.js:r:c) - at IncomingMessage.Readable.on (_stream_readable.js:r:c) - at ClientRequest.get (/scripts/regression-http-close.js:r:c) - at Object.onceWrapper (events.js:r:c) - at ClientRequest.emit (events.js:r:c) - at HTTPParser.parserOnIncomingClient (_http_client.js:r:c) - at HTTPParser.parserOnHeadersComplete (_http_common.js:r:c) - at Socket.socketOnData (_http_client.js:r:c) - at Socket.emit (events.js:r:c) - at addChunk (_stream_readable.js:r:c) - at readableAddChunk (_stream_readable.js:r:c) - at Socket.Readable.push (_stream_readable.js:r:c) - at TCP.onread (net.js:r:c) - at HTTPParser.emitInitNative (internal/async_hooks.js:r:c) - at tickOnSocket (_http_client.js:r:c) - at onSocketNT (_http_client.js:r:c) - at process._tickCallback (internal/process/next_tick.js:r:c) - at emitInitNative (internal/async_hooks.js:r:c) - at emitInitScript (internal/async_hooks.js:r:c) - at new TickObject (internal/process/next_tick.js:r:c) - at process.nextTick (internal/process/next_tick.js:r:c) - at ClientRequest.onSocket (_http_client.js:r:c) - at handleSocketCreation_Inner (_http_agent.js:r:c) - at oncreate (_http_agent.js:r:c) - at Agent.createSocket (_http_agent.js:r:c) - at Agent.addRequest (_http_agent.js:r:c) - at new ClientRequest (_http_client.js:r:c) - at request (http.js:r:c) - at Object.get (http.js:r:c) - at Server.listen (/scripts/regression-http-close.js:r:c) - at Object.onceWrapper (events.js:r:c) - at Server.emit (events.js:r:c) - at emitListeningNT (net.js:r:c) - at process._tickCallback (internal/process/next_tick.js:r:c) - at emitInitNative (internal/async_hooks.js:r:c) - at emitInitScript (internal/async_hooks.js:r:c) - at new TickObject (internal/process/next_tick.js:r:c) - at internalNextTick (internal/process/next_tick.js:r:c) - at Server.setupListenHandle [as _listen2] (net.js:r:c) - at TCP.emitInitNative (internal/async_hooks.js:r:c) + at process.internalTickCallback (internal/process/next_tick.js:r:c) at createServerHandle (net.js:r:c) at Server.setupListenHandle [as _listen2] (net.js:r:c) at listenInCluster (net.js:r:c) at GetAddrInfoReqWrap.doListen [as callback] (net.js:r:c) at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:r:c) - at GetAddrInfoReqWrap.emitInitNative (internal/async_hooks.js:r:c) at Object.lookup (dns.js:r:c) at lookupAndListen (net.js:r:c) at Server.listen (net.js:r:c) at Object. (/scripts/regression-http-close.js:r:c) - at Module._compile (module.js:r:c) - at Object.Module._extensions..js (module.js:r:c) - at Module.load (module.js:r:c) - at tryModuleLoad (module.js:r:c) - at Function.Module._load (module.js:r:c) - at Function.Module.runMain (module.js:r:c) - at startup (bootstrap_node.js:r:c) - at bootstrap_node.js:r:c + at Module._compile (internal/modules/cjs/loader.js:r:c) + at Object.Module._extensions..js (internal/modules/cjs/loader.js:r:c) + at Module.load (internal/modules/cjs/loader.js:r:c) + at tryModuleLoad (internal/modules/cjs/loader.js:r:c) + at Function.Module._load (internal/modules/cjs/loader.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at startup (internal/bootstrap/node.js:r:c) + at bootstrapNodeJSCore (internal/bootstrap/node.js:r:c) diff --git a/test/expected/regression-http-parser.txt b/test/expected/regression-http-parser.txt index 9df13c7..7cc80d2 100644 --- a/test/expected/regression-http-parser.txt +++ b/test/expected/regression-http-parser.txt @@ -5,11 +5,15 @@ Error: trace at Socket.res.socket._read (/scripts/regression-http-parser.js:r:c) at Socket.Readable.read (_stream_readable.js:r:c) + at maybeReadMore_ (_stream_readable.js:r:c) + at process.internalTickCallback (internal/process/next_tick.js:r:c) + at new TickObject (internal/process/next_tick.js:r:c) + at process.nextTick (internal/process/next_tick.js:r:c) + at maybeReadMore (_stream_readable.js:r:c) at addChunk (_stream_readable.js:r:c) at readableAddChunk (_stream_readable.js:r:c) at Socket.Readable.push (_stream_readable.js:r:c) - at TCP.onread (net.js:r:c) - at TCP.emitInitNative (internal/async_hooks.js:r:c) + at TCP.onStreamRead [as onread] (internal/stream_base_commons.js:r:c) at Socket.connect (net.js:r:c) at Agent.connect [as createConnection] (net.js:r:c) at Agent.createSocket (_http_agent.js:r:c) @@ -21,28 +25,24 @@ Error: trace at Object.onceWrapper (events.js:r:c) at Server.emit (events.js:r:c) at emitListeningNT (net.js:r:c) - at process._tickCallback (internal/process/next_tick.js:r:c) - at emitInitNative (internal/async_hooks.js:r:c) - at emitInitScript (internal/async_hooks.js:r:c) + at process.internalTickCallback (internal/process/next_tick.js:r:c) at new TickObject (internal/process/next_tick.js:r:c) - at internalNextTick (internal/process/next_tick.js:r:c) + at nextTick (internal/process/next_tick.js:r:c) at Server.setupListenHandle [as _listen2] (net.js:r:c) - at TCP.emitInitNative (internal/async_hooks.js:r:c) at createServerHandle (net.js:r:c) at Server.setupListenHandle [as _listen2] (net.js:r:c) at listenInCluster (net.js:r:c) at GetAddrInfoReqWrap.doListen [as callback] (net.js:r:c) at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:r:c) - at GetAddrInfoReqWrap.emitInitNative (internal/async_hooks.js:r:c) at Object.lookup (dns.js:r:c) at lookupAndListen (net.js:r:c) at Server.listen (net.js:r:c) at Object. (/scripts/regression-http-parser.js:r:c) - at Module._compile (module.js:r:c) - at Object.Module._extensions..js (module.js:r:c) - at Module.load (module.js:r:c) - at tryModuleLoad (module.js:r:c) - at Function.Module._load (module.js:r:c) - at Function.Module.runMain (module.js:r:c) - at startup (bootstrap_node.js:r:c) - at bootstrap_node.js:r:c + at Module._compile (internal/modules/cjs/loader.js:r:c) + at Object.Module._extensions..js (internal/modules/cjs/loader.js:r:c) + at Module.load (internal/modules/cjs/loader.js:r:c) + at tryModuleLoad (internal/modules/cjs/loader.js:r:c) + at Function.Module._load (internal/modules/cjs/loader.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at startup (internal/bootstrap/node.js:r:c) + at bootstrapNodeJSCore (internal/bootstrap/node.js:r:c) diff --git a/test/expected/regression-net-connect.txt b/test/expected/regression-net-connect.txt index 12e77d8..20edce4 100644 --- a/test/expected/regression-net-connect.txt +++ b/test/expected/regression-net-connect.txt @@ -3,32 +3,24 @@ ^ Error: connect ECONNREFUSED 127.0.0.1:24075 - at Object._errnoException (util.js:r:c) - at _exceptionWithHostPort (util.js:r:c) at TCPConnectWrap.afterConnect [as oncomplete] (net.js:r:c) - at emitInitNative (internal/async_hooks.js:r:c) - at emitInitScript (internal/async_hooks.js:r:c) at new TickObject (internal/process/next_tick.js:r:c) at process.nextTick (internal/process/next_tick.js:r:c) at _destroy (internal/streams/destroy.js:r:c) at Socket._destroy (net.js:r:c) at Socket.destroy (internal/streams/destroy.js:r:c) at TCPConnectWrap.afterConnect [as oncomplete] (net.js:r:c) - at TCPConnectWrap.emitInitNative (internal/async_hooks.js:r:c) - at net.js:r:c - at defaultTriggerAsyncIdScope (internal/async_hooks.js:r:c) at internalConnect (net.js:r:c) at GetAddrInfoReqWrap.emitLookup [as callback] (net.js:r:c) at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:r:c) - at TCP.emitInitNative (internal/async_hooks.js:r:c) at Socket.connect (net.js:r:c) at Object.connect (net.js:r:c) at Object. (/scripts/regression-net-connect.js:r:c) - at Module._compile (module.js:r:c) - at Object.Module._extensions..js (module.js:r:c) - at Module.load (module.js:r:c) - at tryModuleLoad (module.js:r:c) - at Function.Module._load (module.js:r:c) - at Function.Module.runMain (module.js:r:c) - at startup (bootstrap_node.js:r:c) - at bootstrap_node.js:r:c + at Module._compile (internal/modules/cjs/loader.js:r:c) + at Object.Module._extensions..js (internal/modules/cjs/loader.js:r:c) + at Module.load (internal/modules/cjs/loader.js:r:c) + at tryModuleLoad (internal/modules/cjs/loader.js:r:c) + at Function.Module._load (internal/modules/cjs/loader.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at startup (internal/bootstrap/node.js:r:c) + at bootstrapNodeJSCore (internal/bootstrap/node.js:r:c) diff --git a/test/expected/regression-net-socket.txt b/test/expected/regression-net-socket.txt index b9f1567..fe5dc85 100644 --- a/test/expected/regression-net-socket.txt +++ b/test/expected/regression-net-socket.txt @@ -6,22 +6,20 @@ Error: trace at Server. (/scripts/regression-net-socket.js:r:c) at Server.emit (events.js:r:c) at TCP.onconnection (net.js:r:c) - at TCP.emitInitNative (internal/async_hooks.js:r:c) at createServerHandle (net.js:r:c) at Server.setupListenHandle [as _listen2] (net.js:r:c) at listenInCluster (net.js:r:c) at GetAddrInfoReqWrap.doListen [as callback] (net.js:r:c) at GetAddrInfoReqWrap.onlookup [as oncomplete] (dns.js:r:c) - at GetAddrInfoReqWrap.emitInitNative (internal/async_hooks.js:r:c) at Object.lookup (dns.js:r:c) at lookupAndListen (net.js:r:c) at Server.listen (net.js:r:c) at Object. (/scripts/regression-net-socket.js:r:c) - at Module._compile (module.js:r:c) - at Object.Module._extensions..js (module.js:r:c) - at Module.load (module.js:r:c) - at tryModuleLoad (module.js:r:c) - at Function.Module._load (module.js:r:c) - at Function.Module.runMain (module.js:r:c) - at startup (bootstrap_node.js:r:c) - at bootstrap_node.js:r:c + at Module._compile (internal/modules/cjs/loader.js:r:c) + at Object.Module._extensions..js (internal/modules/cjs/loader.js:r:c) + at Module.load (internal/modules/cjs/loader.js:r:c) + at tryModuleLoad (internal/modules/cjs/loader.js:r:c) + at Function.Module._load (internal/modules/cjs/loader.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at startup (internal/bootstrap/node.js:r:c) + at bootstrapNodeJSCore (internal/bootstrap/node.js:r:c) diff --git a/test/expected/rethrow-callback.txt b/test/expected/rethrow-callback.txt new file mode 100644 index 0000000..922ec83 --- /dev/null +++ b/test/expected/rethrow-callback.txt @@ -0,0 +1,33 @@ +/scripts/rethrow-callback.js:8 + throw err; + ^ + +Error: error + at asyncFunction (/scripts/rethrow-callback.js:r:c) + at mainFunction (/scripts/rethrow-callback.js:r:c) + at Object. (/scripts/rethrow-callback.js:r:c) + at Module._compile (internal/modules/cjs/loader.js:r:c) + at Object.Module._extensions..js (internal/modules/cjs/loader.js:r:c) + at Module.load (internal/modules/cjs/loader.js:r:c) + at tryModuleLoad (internal/modules/cjs/loader.js:r:c) + at Function.Module._load (internal/modules/cjs/loader.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at new TickObject (internal/process/next_tick.js:r:c) + at process.nextTick (internal/process/next_tick.js:r:c) + at nextTickFunction (/scripts/rethrow-callback.js:r:c) + at internalTickCallback (internal/process/next_tick.js:r:c) + at process._tickCallback (internal/process/next_tick.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at new TickObject (internal/process/next_tick.js:r:c) + at process.nextTick (internal/process/next_tick.js:r:c) + at asyncFunction (/scripts/rethrow-callback.js:r:c) + at mainFunction (/scripts/rethrow-callback.js:r:c) + at Object. (/scripts/rethrow-callback.js:r:c) + at Module._compile (internal/modules/cjs/loader.js:r:c) + at Object.Module._extensions..js (internal/modules/cjs/loader.js:r:c) + at Module.load (internal/modules/cjs/loader.js:r:c) + at tryModuleLoad (internal/modules/cjs/loader.js:r:c) + at Function.Module._load (internal/modules/cjs/loader.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at startup (internal/bootstrap/node.js:r:c) + at bootstrapNodeJSCore (internal/bootstrap/node.js:r:c) diff --git a/test/expected/simple-fs-read.txt b/test/expected/simple-fs-read.txt index 2f1cc28..70662a7 100644 --- a/test/expected/simple-fs-read.txt +++ b/test/expected/simple-fs-read.txt @@ -4,23 +4,19 @@ Error: trace at callback (/scripts/simple-fs-read.js:r:c) - at FSReqWrap.readFileAfterClose [as oncomplete] (fs.js:r:c) - at FSReqWrap.emitInitNative (internal/async_hooks.js:r:c) - at ReadFileContext.close (fs.js:r:c) - at FSReqWrap.readFileAfterRead [as oncomplete] (fs.js:r:c) - at FSReqWrap.emitInitNative (internal/async_hooks.js:r:c) - at ReadFileContext.read (fs.js:r:c) - at FSReqWrap.readFileAfterStat [as oncomplete] (fs.js:r:c) - at FSReqWrap.emitInitNative (internal/async_hooks.js:r:c) - at FSReqWrap.readFileAfterOpen [as oncomplete] (fs.js:r:c) - at FSReqWrap.emitInitNative (internal/async_hooks.js:r:c) - at Object.fs.readFile (fs.js:r:c) + at FSReqCallback.readFileAfterClose [as oncomplete] (internal/fs/read_file_context.js:r:c) + at ReadFileContext.close (internal/fs/read_file_context.js:r:c) + at FSReqCallback.readFileAfterRead [as oncomplete] (internal/fs/read_file_context.js:r:c) + at ReadFileContext.read (internal/fs/read_file_context.js:r:c) + at FSReqCallback.readFileAfterStat [as oncomplete] (fs.js:r:c) + at FSReqCallback.readFileAfterOpen [as oncomplete] (fs.js:r:c) + at Object.readFile (fs.js:r:c) at Object. (/scripts/simple-fs-read.js:r:c) - at Module._compile (module.js:r:c) - at Object.Module._extensions..js (module.js:r:c) - at Module.load (module.js:r:c) - at tryModuleLoad (module.js:r:c) - at Function.Module._load (module.js:r:c) - at Function.Module.runMain (module.js:r:c) - at startup (bootstrap_node.js:r:c) - at bootstrap_node.js:r:c + at Module._compile (internal/modules/cjs/loader.js:r:c) + at Object.Module._extensions..js (internal/modules/cjs/loader.js:r:c) + at Module.load (internal/modules/cjs/loader.js:r:c) + at tryModuleLoad (internal/modules/cjs/loader.js:r:c) + at Function.Module._load (internal/modules/cjs/loader.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at startup (internal/bootstrap/node.js:r:c) + at bootstrapNodeJSCore (internal/bootstrap/node.js:r:c) diff --git a/test/expected/simple-next-tick.txt b/test/expected/simple-next-tick.txt index 9fca408..83aec45 100644 --- a/test/expected/simple-next-tick.txt +++ b/test/expected/simple-next-tick.txt @@ -4,20 +4,17 @@ Error: trace at callback (/scripts/simple-next-tick.js:r:c) + at internalTickCallback (internal/process/next_tick.js:r:c) at process._tickCallback (internal/process/next_tick.js:r:c) - at Function.Module.runMain (module.js:r:c) - at startup (bootstrap_node.js:r:c) - at bootstrap_node.js:r:c - at emitInitNative (internal/async_hooks.js:r:c) - at emitInitScript (internal/async_hooks.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) at new TickObject (internal/process/next_tick.js:r:c) at process.nextTick (internal/process/next_tick.js:r:c) at Object. (/scripts/simple-next-tick.js:r:c) - at Module._compile (module.js:r:c) - at Object.Module._extensions..js (module.js:r:c) - at Module.load (module.js:r:c) - at tryModuleLoad (module.js:r:c) - at Function.Module._load (module.js:r:c) - at Function.Module.runMain (module.js:r:c) - at startup (bootstrap_node.js:r:c) - at bootstrap_node.js:r:c + at Module._compile (internal/modules/cjs/loader.js:r:c) + at Object.Module._extensions..js (internal/modules/cjs/loader.js:r:c) + at Module.load (internal/modules/cjs/loader.js:r:c) + at tryModuleLoad (internal/modules/cjs/loader.js:r:c) + at Function.Module._load (internal/modules/cjs/loader.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at startup (internal/bootstrap/node.js:r:c) + at bootstrapNodeJSCore (internal/bootstrap/node.js:r:c) diff --git a/test/expected/simple-timer.txt b/test/expected/simple-timer.txt index 6b68c78..416feb8 100644 --- a/test/expected/simple-timer.txt +++ b/test/expected/simple-timer.txt @@ -4,19 +4,17 @@ Error: trace at Timeout.callback [as _onTimeout] (/scripts/simple-timer.js:r:c) - at ontimeout (timers.js:r:c) - at tryOnTimeout (timers.js:r:c) - at Timer.listOnTimeout (timers.js:r:c) - at emitInitNative (internal/async_hooks.js:r:c) - at emitInitScript (internal/async_hooks.js:r:c) - at new Timeout (timers.js:r:c) + at listOnTimeout (timers.js:r:c) + at processTimers (timers.js:r:c) + at initAsyncResource (internal/timers.js:r:c) + at new Timeout (internal/timers.js:r:c) at setTimeout (timers.js:r:c) at Object. (/scripts/simple-timer.js:r:c) - at Module._compile (module.js:r:c) - at Object.Module._extensions..js (module.js:r:c) - at Module.load (module.js:r:c) - at tryModuleLoad (module.js:r:c) - at Function.Module._load (module.js:r:c) - at Function.Module.runMain (module.js:r:c) - at startup (bootstrap_node.js:r:c) - at bootstrap_node.js:r:c + at Module._compile (internal/modules/cjs/loader.js:r:c) + at Object.Module._extensions..js (internal/modules/cjs/loader.js:r:c) + at Module.load (internal/modules/cjs/loader.js:r:c) + at tryModuleLoad (internal/modules/cjs/loader.js:r:c) + at Function.Module._load (internal/modules/cjs/loader.js:r:c) + at Function.Module.runMain (internal/modules/cjs/loader.js:r:c) + at startup (internal/bootstrap/node.js:r:c) + at bootstrapNodeJSCore (internal/bootstrap/node.js:r:c) diff --git a/test/scripts/async-await-follow.js b/test/scripts/async-await-follow.js new file mode 100644 index 0000000..8028fd2 --- /dev/null +++ b/test/scripts/async-await-follow.js @@ -0,0 +1,20 @@ +async function f1() { + await Promise.resolve(); + throw new Error('FAIL'); +} + +async function f2() { + await Promise.resolve() + await f1(); +} + +async function f3() { + await Promise.resolve(); + try { + await f2(); + } catch (err) { + console.log(err); + } +} + +f3(); diff --git a/test/scripts/promise-resolve-follow.js b/test/scripts/promise-resolve-follow.js new file mode 100644 index 0000000..6b5789f --- /dev/null +++ b/test/scripts/promise-resolve-follow.js @@ -0,0 +1,21 @@ +function f1() { + return new Promise((resolve, reject) => { + setTimeout(() => { + reject(new Error('FAIL')); + }, 0); + }, 0); +} + +function f2() { + return new Promise((resolve, reject) => { + f1().then(resolve, reject); + }); +} + +function f3() { + return Promise.resolve() + .then(() => f2()) + .catch((err) => console.log(err)); +} + +f3(); diff --git a/test/scripts/rethrow-callback.js b/test/scripts/rethrow-callback.js new file mode 100644 index 0000000..51fc24a --- /dev/null +++ b/test/scripts/rethrow-callback.js @@ -0,0 +1,13 @@ +function asyncFunction(callback) { + process.nextTick(callback, new Error('error')); +} + +function mainFunction() { + asyncFunction(function nextTickFunction(err) { + process.nextTick(() => { + throw err; + }) + }); +} + +mainFunction(); diff --git a/trace.js b/trace.js index 32f85b9..56875d6 100644 --- a/trace.js +++ b/trace.js @@ -1,41 +1,70 @@ 'use strict'; +const DEBUG = false; +const {printRootTraces, debug} = DEBUG ? require('./debug') : {}; + +// Arbitrarily limit ourselves so we don't use up all memory on storing stack traces +const MAX_RELATED_TRACES = 10; +const MAX_RELATED_TRAVERSAL_DEPTH = 10; +const MAX_STACKS_TO_JOIN = 50; + const chain = require('stack-chain'); const asyncHook = require('async_hooks'); -// Contains init asyncId of the active scope(s) -// Because we can't know when the root scope ends, a permanent Set is keept -// for the root scope. -const executionScopeInits = new Set(); -let executionScopeDepth = 0; -// Contains the call site objects of all active scopes +// Contains the Trace objects of all active async execution contexts const traces = new Map(); -// -// Mainiputlate stack trace -// -// add lastTrace to the callSite array -chain.filter.attach(function (error, frames) { - return frames.filter(function (callSite) { +// Manipulate stack traces +chain.filter.attach(filterFrames); +chain.extend.attach(extendFrames); +function filterFrames(error, frames) { + return frames.filter((callSite) => { const name = callSite && callSite.getFileName(); - return (!name || name !== 'async_hooks.js'); + return name !== 'async_hooks.js' && name !== 'internal/async_hooks.js'; }); -}); +} + +function extendFrames(error, frames) { + const asyncId = asyncHook.executionAsyncId(); + const trace = traces.get(asyncId); + + if (!trace) { + return frames; + } + + + trace.sortStacks(); + + if (DEBUG) { + debug(`extending: ${asyncId} with ${trace.stacks.map(({asyncId}) => asyncId)}`); + printRootTraces(traces); + } + + for (const stack of trace.stacks) { + appendUniqueFrames(frames, stack.frames); + } -chain.extend.attach(function (error, frames) { - const lastTrace = traces.get(asyncHook.executionAsyncId()); - frames.push.apply(frames, lastTrace); return frames; -}); +} + +function appendUniqueFrames(frames, newFrames) { + for (let i = 1; i <= newFrames.length && frames.length > 1; ++i) { + if (equalCallSite(newFrames[newFrames.length - i], frames[frames.length - 1])) { + frames.pop(); + } + } + + frames.push(...newFrames); +} + // // Track handle objects // const hooks = asyncHook.createHook({ init: asyncInit, - before: asyncBefore, - after: asyncAfter, - destroy: asyncDestroy + destroy: asyncDestroy, + promiseResolve: asyncPromiseResolve }); hooks.enable(); @@ -43,14 +72,46 @@ function getCallSites(skip) { const limit = Error.stackTraceLimit; Error.stackTraceLimit = limit + skip; - const stack = chain.callSite({ + const frames = chain.callSite({ extend: false, filter: true, slice: skip }); Error.stackTraceLimit = limit; - return stack; + return copyFrames(frames); +} + +// We must take a copy of the CallSite objects to avoid retaining references to Promises. +// If we retain a Promise reference then asyncDestroy for the Promise won't be called, +// so we'll leak memory. +class CallSiteCopy { + constructor(callSite) { + this._fileName = callSite.getFileName(); + this._lineNumber = callSite.getLineNumber(); + this._columnNumber = callSite.getColumnNumber(); + this._toString = callSite.toString(); // TODO this is slow + } + + getFileName() { + return this._fileName; + } + + getLineNumber() { + return this._lineNumber; + } + + getColumnNumber() { + return this._columnNumber; + } + + toString() { + return this._toString; + } +} + +function copyFrames(frames) { + return frames.map((callSite) => new CallSiteCopy(callSite)); } function equalCallSite(a, b) { @@ -58,68 +119,121 @@ function equalCallSite(a, b) { const aLine = a.getLineNumber(); const aColumn = a.getColumnNumber(); - if (aFile === null || aLine === null || aColumn === null) { - return false; - } - return (aFile === b.getFileName() && aLine === b.getLineNumber() && aColumn === b.getColumnNumber()); } -function asyncInit(asyncId, type, triggerAsyncId, resource) { - const trace = getCallSites(2); - - // In cases where the trigger is in the same synchronous execution scope - // as this resource, the stack trace of the trigger will overlap with - // `trace`, this mostly happens with promises. - // Example: - // p0 = Promise.resolve(1); // will have `root` in stack trace - // p1 = p0.then(() => throw new Error('hello')); // will also have `root` - // The async stack trace should be: root, p0, p1 - // - // To avoid (n^2) string matching, it is assumed that `Error.stackTraceLimit` - // hasn't changed. By this assumtion we know the current trace will go beyond - // the trigger trace, thus the check can be limited to trace[-1]. - if (executionScopeInits.has(triggerAsyncId)) { - const parentTrace = traces.get(triggerAsyncId); - - let i = parentTrace.length; - while(i-- && trace.length > 1) { - if (equalCallSite(parentTrace[i], trace[trace.length - 1])) { - trace.pop(); - } - } - } +// +// Async hook functions +// + +function asyncInit(asyncId, type, triggerAsyncId) { + const frames = getCallSites(2); + const stack = new NamedStack(asyncId, frames); + const trace = new Trace(asyncId, stack); + traces.set(asyncId, trace); + if (DEBUG) debug(`asyncInit ${stack}`); - // Add all the callSites from previuse ticks - if (triggerAsyncId !== 0) { - trace.push.apply(trace, traces.get(triggerAsyncId)); + const triggerTrace = traces.get(triggerAsyncId); + if (triggerTrace) { + triggerTrace.recordRelatedTrace(trace); } +} - // Cut the trace so it don't contain callSites there won't be shown anyway - // because of Error.stackTraceLimit - trace.splice(Error.stackTraceLimit); +function asyncDestroy(asyncId) { + if (DEBUG) debug(`asyncDestroy ${asyncId}`); + traces.delete(asyncId); +} - // `trace` now contains callSites from this ticks and all the ticks leading - // up to this event in time - traces.set(asyncId, trace); +function asyncPromiseResolve(asyncId) { + const triggerAsyncId = asyncHook.triggerAsyncId(); + + const triggerTrace = traces.get(triggerAsyncId); + const trace = traces.get(asyncId); - // add asyncId to the list of all inits in this execution scope - executionScopeInits.add(asyncId); + if (trace && triggerTrace) { + triggerTrace.recordRelatedTrace(trace); + } } -function asyncBefore(asyncId) { - if (executionScopeDepth === 0) { - executionScopeInits.clear(); + +// +// Async context graph data structure +// + +class NamedStack { + constructor(asyncId, frames) { + this.asyncId = asyncId; + this.frames = frames; + } + + toString() { + return `${this.asyncId}\n ${this.frames.join('\n ')}\n`; } - executionScopeDepth += 1; } -function asyncAfter(asyncId) { - executionScopeDepth -= 1; +class Trace { + constructor(asyncId, stack) { + this.asyncId = asyncId; + this.stacks = [stack]; + this.relatedTraces = []; + } + + recordRelatedTrace(relatedTrace) { + if (this.relatedTraces.includes(relatedTrace)) { + return; + } + + this.relatedTraces.push(relatedTrace); + this.removeOldestRelatedTraces(); + + for (const subRelatedTrace of relatedTrace.walk()) { + mergeStacks(subRelatedTrace.stacks, this.stacks); + subRelatedTrace.removeOldestStacks(); + } + } + + removeOldestRelatedTraces() { + if (this.relatedTraces.length < MAX_RELATED_TRACES) { + return; + } + + this.relatedTraces.sort((a, b) => b.asyncId - b.asyncId); + this.relatedTraces.length = MAX_RELATED_TRACES + } + + sortStacks() { + this.stacks.sort((a, b) => b.asyncId - a.asyncId); + } + + removeOldestStacks() { + if (this.stacks.length < MAX_STACKS_TO_JOIN) { + return; + } + + this.sortStacks(); + this.stacks.length = MAX_STACKS_TO_JOIN; + } + + walk(visited=[this], depth=0) { + if (depth > MAX_RELATED_TRAVERSAL_DEPTH) { + return; + } + for (const trace of this.relatedTraces) { + if (!visited.includes(trace)) { + visited.push(trace); + trace.walk(visited, depth + 1); + } + } + return visited; + } } -function asyncDestroy(asyncId) { - traces.delete(asyncId); +function mergeStacks(dest, source) { + for (const stack of source) { + if (!dest.includes(stack)) { + dest.push(stack); + } + } }