Writing an asynchronous traceing tool

• Published npm module
• Read nodecore code
• Read v8 code

Andreas Madsen

Once Node.js core contributer

#9 – 5353 line changes
Cluster, Child Process, Domain, Stream v2

Besides that

Study: DTU - Mathematics and Technology
Work: Admazely ApS

function failure() {
  throw new Error('simple error');
}

setTimeout(failure, Math.random() * 1000);

setTimeout(failure, Math.random() * 1000);

/example/code.js:2
  throw new Error('simple error');
        ^
Error: simple error
    at failure [as _onTimeout] (/example/code.js:2:9)
    at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)
    at process._makeCallback (node.js:306:20)

events.js:71
        throw arguments[1]; // Unhandled 'error' event
                       ^
Error: connect ECONNREFUSED
    at errnoException (net.js:770:11)
    at Object.afterConnect [as oncomplete] (net.js:761:19)

events.js:71
        throw arguments[1]; // Unhandled 'error' event
                       ^
Error: connect ECONNREFUSED
    at errnoException (net.js:770:11)
    at Object.afterConnect [as oncomplete] (net.js:761:19)
    at new ClientRequest (http.js:1216:16)
    at Object.exports.request (http.js:1607:10)
    at Worker.exec (/example/file.js:121:37) // Important

function failure() {
  throw new Error('simple error');
}

function setTimeout(callback, time /*, and more */) {
  // Create stack trace and remove first line
  var trackingStack = (new Error()).stack.slice('Error'.length);
  global.setTimeout(function () {
    try { callback(); } catch (err) {
      // Overwrite err.stack by adding trackingStack
      err.stack += trackingStack;
      throw err;
    }
  }, time);
}

setTimeout(failure, Math.random() * 1000);

setTimeout(failure, Math.random() * 1000);

/example/code.js:12
      throw err;
            ^
Error: simple error
    at failure (/example/code.js:2:9)
    at null._onTimeout (/example/code.js:9:11)
    at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)
    at process._makeCallback (node.js:306:20)
    at setTimeout (/example/code.js:7:24)
    at Object.<anonymous> (/example/code.js:19:1) // Important

/example/code.js:12
      throw err;
            ^
Error: simple error
    at failure /example/code.js:2:9)
    at null._onTimeout (/example/code.js:9:11)
    at Timer.listOnTimeout [as ontimeout] (timers.js:110:15)
    at process._makeCallback (node.js:306:20)
    at setTimeout (/example/code.js:7:24)
    at Object.<anonymous> (/example/code.js:17:1) // Important

• npm install trycatch
• npm install long-stack-traces
• npm install longjohn
• and more ...

Missing generic overwrite

var original = process.nextTick;
process.nextTick = function () {
  try {
    original.apply(this, arguments); // Call must throw
  } catch (err) {
    throw internal.wrapLogic(err); // Changed throw origin
  }
};

fs.readFile('./file.js', function (err) {
  if (err) throw external.wrapLogic(err); // Require origin knowledge
});

Minimal wrapping

wrap(process, 'nextTick');
wrap(global, 'setTimeout');
wrap(global, 'setInterval');
Object.keys(fs).forEach(function(methodName) {
  wrap(fs, methodName);
});
// what about: net, tls, http, https, dgram, dns ...

• V8 stack trace hook
• Complete wrap logic
• On demand wrap logic

• Error.stackTraceLimit
• Error.prepareStackTrace

v8: /src/messages.js

• captureStackTrace
• prepareStackTrace
• FormatStackTrace

First thought: Manually written
list of modules and their
methods

[
  "timer": ["setTimeout", "setInterval"],
  "fs": ["readFile", "writeFile"],
  "dns": ["lookup", "resolve"]
]

hard to maintain

JSON version of
the node core documentation
contains all the information

nodejs.org/api/all.json

To require all modules is expensive and noisy.

require is a function and can't be patched Module.prototype.require can!

/node/src/node.js and /node/lib/module.js

var Module = require('module');

var original = Module.prototype.require;

Module.prototype.require = function (path) {
  var module = original.call(this, path);

  if (isCoreModule(path)) {
    patchAll(module, path);
  }

  return module;
};

var hook = require('async-hook'); // monkey patch everything
var chain = require('stack-chain'); // Error.prepearStackTrace wrapper

var previousStack = null;

hook.all.attach(function(name, callback) {
  // Async function executed
  var stack = chain.getCallSiteArray();
  stack.push.apply(stack, previousStack);

  return function () {
    // this is executed in another tick
    previousStack = stack;
    return callback.apply(this, arguments);
  };
});

chain.extend.attach(function (error, frames) {
  frames.push.apply(frames, previousStack);
  return frames;
});

chain.filter.attach(function (error, frames) {
  return frames.filter(function (callSite) {
    return (callSite.getFileName() === module.filename);
  });
});