Fix promise traces

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
+};

test/expected/async-await-follow.txt

@@ -0,0 +1,27 @@
+Error: FAIL
+    at f1 (/scripts/async-await-follow.js:r:c)
+    at Function.resolve (<anonymous>)
+    at f1 (/scripts/async-await-follow.js:r:c)
+    at <anonymous>
+    at f1 (/scripts/async-await-follow.js:r:c)
+    at f2 (/scripts/async-await-follow.js:r:c)
+    at Function.resolve (<anonymous>)
+    at f2 (/scripts/async-await-follow.js:r:c)
+    at <anonymous>
+    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 (<anonymous>)
+    at f3 (/scripts/async-await-follow.js:r:c)
+    at <anonymous>
+    at f3 (/scripts/async-await-follow.js:r:c)
+    at Object.<anonymous> (/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)

test/expected/promise-child-stack.txt

@@ -1,21 +1,16 @@
 Error: hello
     at scopeThrow (/scripts/promise-child-stack.js:r:c)
-    at <anonymous>
     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 (<anonymous>)
     at Object.<anonymous> (/scripts/promise-child-stack.js:r:c)
-    at PromiseWrap.emitInitNative (internal/async_hooks.js:r:c)
     at Function.resolve (<anonymous>)
     at Object.<anonymous> (/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)

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 (<anonymous>)
+    at f1 (/scripts/promise-resolve-follow.js:r:c)
+    at Promise (/scripts/promise-resolve-follow.js:r:c)
+    at new Promise (<anonymous>)
+    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 (<anonymous>)
+    at Promise.catch (<anonymous>)
+    at f3 (/scripts/promise-resolve-follow.js:r:c)
+    at Promise.then (<anonymous>)
+    at f3 (/scripts/promise-resolve-follow.js:r:c)
+    at Function.resolve (<anonymous>)
+    at f3 (/scripts/promise-resolve-follow.js:r:c)
+    at Object.<anonymous> (/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)

test/expected/regression-delayed-formater.txt

@@ -4,11 +4,11 @@ throw new Error('trace');
 
 Error: trace
     at-hack Object.<anonymous> (/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)

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.<anonymous> (/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)

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.<anonymous> (/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)

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.<anonymous> (/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)

test/expected/regression-net-socket.txt

@@ -6,22 +6,20 @@ Error: trace
     at Server.<anonymous> (/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.<anonymous> (/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)