Async Wars

Vladimir de Turckheim

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

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)

More?

Return of the domain

Domains are

dead

Long

live domains

What else?

The power awakens

We can

  • Have asynchronous flamecharts (WIP)
  • Have a request context in servers
  • Implement Zones
  • ...

Last news!

Wrap up

The last code

Async Hooks solve historical Node.js problems

Async Hooks allow people to build tools that make Node.js more entreprise friendly

Async Hooks is not dark magic

Node.js Async hooks

By Vladimir de Turckheim

Node.js Async hooks

  • 423
Loading comments...

More from Vladimir de Turckheim