Async Wars

Vladimir de Turckheim

Lead Node.js engineer @ Sqreen (ex. Steamulo, Secway)

@poledesfetes

@vdeturckheim

PSA

Join Node.js Security WG

Do not need to be a security expert
Awesome opportunity to learn
Mostly review and communication work
Ping me!

Outline

Holliday special
The phantom problem
Attack of the event loop
Revenge of the Hackers
A new Hope
Hackers strike back
Return of the domain
The power awakens
The last code

The async_hooks module provides an API to register callbacks tracking the lifetime of asynchronous resources created inside a Node.js application.

Holliday special

Let me start with an example

The phantom problem

app.get(/stuff, (req, res) => {
    throw new Error('hello');
});

MacBook-Air-de-Vladimir:tt vladimir$ node index.js 
Error: hello
    at app.get (/Users/vladimir/tmp/tt/index.js:5:11)
    at Layer.handle [as handle_request] (/Users/vladimir/tmp/tt/node_modules/express/lib/router/layer.js:95:5)
    at next (/Users/vladimir/tmp/tt/node_modules/express/lib/router/route.js:137:13)
    at Route.dispatch (/Users/vladimir/tmp/tt/node_modules/express/lib/router/route.js:112:3)
    at Layer.handle [as handle_request] (/Users/vladimir/tmp/tt/node_modules/express/lib/router/layer.js:95:5)
    at /Users/vladimir/tmp/tt/node_modules/express/lib/router/index.js:281:22
    at Function.process_params (/Users/vladimir/tmp/tt/node_modules/express/lib/router/index.js:335:12)
    at next (/Users/vladimir/tmp/tt/node_modules/express/lib/router/index.js:275:10)
    at expressInit (/Users/vladimir/tmp/tt/node_modules/express/lib/middleware/init.js:40:5)
    at Layer.handle [as handle_request] (/Users/vladimir/tmp/tt/node_modules/express/lib/router/layer.js:95:5)

app.get('/other', (req, res) => {
    setTimeout(() => {
        throw new Error('hello')
    });
});

MacBook-Air-de-Vladimir:tt vladimir$ node index.js 
/Users/vladimir/tmp/tt/index.js:10
        throw new Error('hello')
        ^

Error: hello
    at Timeout.setTimeout [as _onTimeout] (/Users/vladimir/tmp/tt/index.js:10:15)
    at ontimeout (timers.js:469:11)
    at tryOnTimeout (timers.js:304:5)
    at Timer.listOnTimeout (timers.js:264:5)

Process crashed

Stacktraces in Node.js are short

Stacktraces in Node.js are useless

Meet the event loop

Attack of the event loop

app.get('/stuff', (req, res) => {
  fs.readFile('./myFile', (err, result) => {
    // context loss
    db.getById(555, async (err, doc) => {
      // context loss
      const api_result = await API.call('thing');
      // context loss
      res.json({ result, doc, api_result });
    });
  });
});

app.get('/other', (req, res) => {
    setTimeout(() => {
        res.end('ok');
    });
});

Debugging is impossible

Historical solutions

Revenge of the Hackers

Domains

const d = require('domain').create();
d.on('error', (er) => {
  console.log(`error, but oh well ${er.message}`);
});
d.run(() => {
  require('http').createServer((req, res) => {
    handleRequest(req, res);
  }).listen(PORT);
});

Userland patching

var fs = require('fs');
massWrap(
  fs,
  [
    'watch',
    'rename',
    'truncate',
    'chown',
    'fchown',
    'chmod',
    'fchmod',
    'stat',
    'lstat',
    'fstat',
    'link',
    'symlink',
    'readlink',
    'realpath',
    'unlink',
    'rmdir',
    'mkdir',
    'readdir',
    'close',
    'open',
    'utimes',
    'futimes',
    'fsync',
    'write',
    'read',
    'readFile',
    'writeFile',
    'appendFile',
    'watchFile',
    'unwatchFile',
    "exists",
  ],
  activator
);

Does not work with async/await

Enter Async Hooks

A new Hope

async_hooks.createHook({
  init(asyncId, type, triggerAsyncId) {
    // I run when an async resource is created
  },
  before(asyncId) {
    // I run before the callback
  },
  after(asyncId) {
    // I run after the callback
  },
  destroy(asyncId) {
    // I run when the resource is destroyed
  },
}).enable();

Action

Hackers strike back

app.get('/other', (req, res) => {
    console.log(new Error());
    setTimeout(() => {
        console.log(new Error());
        res.end('ok');
    });
});

Error
    at app.get (/Users/vladimir/tmp/tt/index.js:27:17)
    at Layer.handle [as handle_request] (/Users/vladimir/tmp/tt/node_modules/express/lib/router/layer.js:95:5)
    at next (/Users/vladimir/tmp/tt/node_modules/express/lib/router/route.js:137:13)
    at Route.dispatch (/Users/vladimir/tmp/tt/node_modules/express/lib/router/route.js:112:3)
    at Layer.handle [as handle_request] (/Users/vladimir/tmp/tt/node_modules/express/lib/router/layer.js:95:5)
    at /Users/vladimir/tmp/tt/node_modules/express/lib/router/index.js:281:22
    at Function.process_params (/Users/vladimir/tmp/tt/node_modules/express/lib/router/index.js:335:12)
    at next (/Users/vladimir/tmp/tt/node_modules/express/lib/router/index.js:275:10)
    at expressInit (/Users/vladimir/tmp/tt/node_modules/express/lib/middleware/init.js:40:5)
    at Layer.handle [as handle_request] (/Users/vladimir/tmp/tt/node_modules/express/lib/router/layer.js:95:5)
Error
    at Timeout.setTimeout [as _onTimeout] (/Users/vladimir/tmp/tt/index.js:29:21)
    at ontimeout (timers.js:469:11)
    at tryOnTimeout (timers.js:304:5)
    at Timer.listOnTimeout (timers.js:264:5)

Let's do it?

const AsyncHook = require('async_hooks');

const map = new Map();

AsyncHook.createHook({
    init(asyncId, type, triggerAsyncId) {

        const stack = map.get(triggerAsyncId) || '' ;
        const stackPart = (new Error()).stack.split('\n').slice(1).join('\n');
        map.set(asyncId, stackPart + stack);
    }
})
    .enable();

const getError = function (...args) {

    const err = new Error(...args);
    err.stack += map.get(AsyncHook.executionAsyncId());
    return err;
};

app.get('/other', (req, res) => {
    setTimeout(() => {
        console.log(getError());
        res.end('ok');
    });
});

Error
    at getError (/Users/vladimir/tmp/tt/index.js:17:17)
    at Timeout.setTimeout [as _onTimeout] (/Users/vladimir/tmp/tt/index.js:28:21)
    at ontimeout (timers.js:469:11)
    at tryOnTimeout (timers.js:304:5)
    at Timer.listOnTimeout (timers.js:264:5)    at AsyncHook.init (/Users/vladimir/tmp/tt/index.js:9:28)
    at emitInitNative (async_hooks.js:458:43)
    at emitInitScript (async_hooks.js:361:3)
    at new Timeout (timers.js:573:5)
    at createSingleTimeout (timers.js:453:15)
    at setTimeout (timers.js:437:10)
    at app.get (/Users/vladimir/tmp/tt/index.js:27:5)
    at Layer.handle [as handle_request] (/Users/vladimir/tmp/tt/node_modules/express/lib/router/layer.js:95:5)
    at next (/Users/vladimir/tmp/tt/node_modules/express/lib/router/route.js:137:13)
    at Route.dispatch (/Users/vladimir/tmp/tt/node_modules/express/lib/router/route.js:112:3)    at AsyncHook.init (/Users/vladimir/tmp/tt/index.js:9:28)
    at HTTPParser.emitInitNative (async_hooks.js:458:43)
    at Server.connectionListener (_http_server.js:307:10)
    at emitOne (events.js:115:13)
    at Server.emit (events.js:210:7)
    at TCP.onconnection (net.js:1560:8)    at AsyncHook.init (/Users/vladimir/tmp/tt/index.js:9:28)
    at TCP.emitInitNative (async_hooks.js:458:43)
    at createServerHandle (net.js:1267:14)
    at Server.setupListenHandle [as _listen2] (net.js:1310:14)
    at listenInCluster (net.js:1391:12)
    at Server.listen (net.js:1474:7)
    at Function.listen (/Users/vladimir/tmp/tt/node_modules/express/lib/application.js:618:24)
    at Object.<anonymous> (/Users/vladimir/tmp/tt/index.js:33:5)
    at Module._compile (module.js:624:30)
    at Object.Module._extensions..js (module.js:635:10)