Nodejs Async Hooks

for painless correlation id handling

Generate correlation id

Send the it in the headers

Read the header

Send the header

Read the header

Send the header

Read the header

C#, ASP.NET

// module.cs
httpContextAccessor.HttpContext.Items.Add("correlation-id", correlationId);

// later in logger.cs
void log(message) {
    var correlationId = httpContextAccessor.HttpContext.Items["correlation-id"];
    logMessage($"{correlationId}: {message}");
}

// AsyncLocal<T> is used under the hood:
var s = new AsyncLocal<string>();
s.Value = "this value is local for the current async flow"

// module.cs
httpContextAccessor.HttpContext.Items.Add("correlation-id", correlationId);

// later in logger.cs
void log(message) {
    var correlationId = httpContextAccessor.HttpContext.Items["correlation-id"];
    logMessage($"{correlationId}: {message}");
}

// AsyncLocal<T> Example:
var s = new AsyncLocal<string>();
s.Value = "this value is local for the current async flow"

NodeJS, expressjs

// notifications.module.js
async function processSingleOffer(req, res) {
  ......
	await offerProcessor.processSingleOffer(offerInfo, req.query.isFake, req.correlation);
  ......
}

// offer-processor.js
async function processSingleOffer(offerInfo, isFake, correlation) {
  .....
  logger.info(`Processing offer ${offerInfo.hashedExternalId}`, correlation());
  .....
  const offer = await submissionsProvider.getOffer(offerInfo, correlation);
  .....
  const result = await digester.digest(offer, correlation);
  .....
  logger.info(`Processed offer`, correlation());
}

// offer-digester.js
async digest(offer, correlation) {
  ....
  await this.firstStep.execute(offer, result, correlation);
  ....
}

// offer-updater.js
async setAsSentPerEmailAndPostDelivery(offer, result, correlation) {
  .....
  await http.new(correlation, config.paapiUrl).put(offer.links.offer, offer, requestConfig);
  .....
}

Nodejs async hooks

Added in: v8.1.0

Stability: 1 - Experimental

const async_hooks = require('async_hooks');

Tracking the lifetime of asynchronous resources.

Asynchronous resources represent objects with an associated callback.

Nodejs async hooks

async_hooks.createHook({
  init(asyncId, type, triggerAsyncId) {
    // the asynchronous object asyncId has been initialized
    // type can be 
  },
  before(asyncId) {
    // the asynchronous object asyncId is going to call its callback
  },
  after(asyncId) {
    // the asynchronous object asyncId callback execution was finished
  },
  destroy(asyncId) {
    // Called after the resource corresponding to asyncId is destroyed
  },
}).enable();


FSEVENTWRAP, FSREQWRAP, GETADDRINFOREQWRAP, GETNAMEINFOREQWRAP, HTTPPARSER,
JSSTREAM, PIPECONNECTWRAP, PIPEWRAP, PROCESSWRAP, QUERYWRAP, SHUTDOWNWRAP,
SIGNALWRAP, STATWATCHER, TCPCONNECTWRAP, TCPSERVER, TCPWRAP, TIMERWRAP, TTYWRAP,
UDPSENDWRAP, UDPWRAP, WRITEWRAP, ZLIB, SSLCONNECTION, PBKDF2REQUEST,
RANDOMBYTESREQUEST, TLSWRAP, Timeout, Immediate, TickObject, PROMISE

async_hooks.createHook({
  init(asyncId, type, triggerAsyncId) {
    // the asynchronous object asyncId has been initialized
    // type can be 
  },
  before(asyncId) {
    // the asynchronous object asyncId is going to call its callback
  },
  after(asyncId) {
    // the asynchronous object asyncId callback execution was finished
  },
  destroy(asyncId) {
    // Called after the resource corresponding to asyncId is destroyed
  },
}).enable();


FSEVENTWRAP, FSREQWRAP, GETADDRINFOREQWRAP, GETNAMEINFOREQWRAP, HTTPPARSER,
JSSTREAM, PIPECONNECTWRAP, PIPEWRAP, PROCESSWRAP, QUERYWRAP, SHUTDOWNWRAP,
SIGNALWRAP, STATWATCHER, TCPCONNECTWRAP, TCPSERVER, TCPWRAP, TIMERWRAP, TTYWRAP,
UDPSENDWRAP, UDPWRAP, WRITEWRAP, ZLIB, SSLCONNECTION, PBKDF2REQUEST,
RANDOMBYTESREQUEST, TLSWRAP, Timeout, Immediate, TickObject, PROMISE

async_hooks.createHook({
  init(asyncId, type, triggerAsyncId) {
    // the asynchronous object asyncId has been initialized
    // type can be 
  },
  before(asyncId) {
    // the asynchronous object asyncId is going to call its callback
  },
  after(asyncId) {
    // the asynchronous object asyncId callback execution was finished
  },
  destroy(asyncId) {
    // Called after the resource corresponding to asyncId is destroyed
  },
}).enable();


FSEVENTWRAP, FSREQWRAP, GETADDRINFOREQWRAP, GETNAMEINFOREQWRAP, HTTPPARSER,
JSSTREAM, PIPECONNECTWRAP, PIPEWRAP, PROCESSWRAP, QUERYWRAP, SHUTDOWNWRAP,
SIGNALWRAP, STATWATCHER, TCPCONNECTWRAP, TCPSERVER, TCPWRAP, TIMERWRAP, TTYWRAP,
UDPSENDWRAP, UDPWRAP, WRITEWRAP, ZLIB, SSLCONNECTION, PBKDF2REQUEST,
RANDOMBYTESREQUEST, TLSWRAP, Timeout, Immediate, TickObject, PROMISE

async_hooks.createHook({
  init(asyncId, type, triggerAsyncId) {
    // the asynchronous object asyncId has been initialized
    // type can be 
  },
  before(asyncId) {
    // the asynchronous object asyncId is going to call its callback
  },
  after(asyncId) {
    // the asynchronous object asyncId callback execution was finished
  },
  destroy(asyncId) {
    // Called after the resource corresponding to asyncId is destroyed
  },
}).enable();


FSEVENTWRAP, FSREQWRAP, GETADDRINFOREQWRAP, GETNAMEINFOREQWRAP, HTTPPARSER,
JSSTREAM, PIPECONNECTWRAP, PIPEWRAP, PROCESSWRAP, QUERYWRAP, SHUTDOWNWRAP,
SIGNALWRAP, STATWATCHER, TCPCONNECTWRAP, TCPSERVER, TCPWRAP, TIMERWRAP, TTYWRAP,
UDPSENDWRAP, UDPWRAP, WRITEWRAP, ZLIB, SSLCONNECTION, PBKDF2REQUEST,
RANDOMBYTESREQUEST, TLSWRAP, Timeout, Immediate, TickObject, PROMISE

Types:

PROMISE, FSEVENTWRAP, FSREQWRAP, GETADDRINFOREQWRAP, GETNAMEINFOREQWRAP, HTTPPARSER, JSSTREAM, PIPECONNECTWRAP, PIPEWRAP, PROCESSWRAP, QUERYWRAP, SHUTDOWNWRAP, SIGNALWRAP, STATWATCHER, TCPCONNECTWRAP, TCPSERVER, TCPWRAP, TIMERWRAP, TTYWRAP, UDPSENDWRAP, UDPWRAP, WRITEWRAP, ZLIB, SSLCONNECTION, PBKDF2REQUEST, RANDOMBYTESREQUEST, TLSWRAP, Timeout, Immediate, TickObject

Nodejs async hooks

setTimeout(() => {
  setTimeout(() => {
    setTimeout(() => {
      log("HELLO");
    }, 10);  
  }, 10);
}, 10);

const async_hooks = require('async_hooks');
const fs = require('fs');

let indent = 0;
function log(mes) {
  const indentStr = ' '.repeat(indent);
  fs.writeSync(1, `${indentStr}${mes}\n`);
}

async_hooks.createHook({
  init(asyncId, type, triggerAsyncId) {
    log(`INIT ${asyncId}, type ${type},
         trigger ${triggerAsyncId}`);
  },
  before(asyncId) {
    log(`BEFORE ${asyncId}`); 
    indent += 2;
  },
  after(asyncId) {
    indent -= 2;
    log(`AFTER ${asyncId}`); 
  }
}).enable();

Nodejs async hooks

// lead.module.js
async function setLeadPaid(ctx) {
        const correlationId = generateCorrelationId()
	globalAsyncStorage.setCorrelationId(correlationId);
	await leadService.setLeadPaid(ctx.params.leadId)
	....
}


// lead.service.js
async function setLeadPaid(leadId) {
	await db.updateOne('leads', { $set: { status: 'paid' } });
	logger.log(`Lead ${leadId} status set to paid`);
	await http.post(`${notifierUrl}/notify-lead-paid`, { leadId });
}

// logger.js
function log(message) {
      	const correlationId = globalAsyncStorage.getCorrelationId();
        fs.appendFile('log.txt', `${correlationId}: ${message}`);
}

Correlation Id managers

https://www.npmjs.com/package/correlation-id
https://www.npmjs.com/package/express-correlation-id
https://www.npmjs.com/package/async-local-storage
https://www.npmjs.com/package/cls-hooked
https://bitbucket.check24.de/projects/BU/repos/npm-current-context-storage

All are using async_hooks