V4 (#73)

* feature(cls): Move from cls-hooked to AsyncLocalStorage (#69)

* fix(middleware): Fix addLogMetadata function and update dependencies (#72)

* Add node version + experimental features in the readme (#74)

README.md

@@ -4,6 +4,24 @@
 
 ExpressJS logger that wraps [pino](https://github.com/pinojs/pino) with additional features like middlewares for unique request ids and automatic logging of request beginnings and endings.
 
+## Node versions support
+
+Below is a table with each version an the minimum version that is needed:
+
+|    | Node 8 | Node 10 | Node 12.17+ |
+|----|--------|---------|---------|
+| v1 | :white_check_mark:      |    :white_check_mark:     |    :white_check_mark:     |
+| v2 | :white_check_mark:      |    :white_check_mark:     |    :white_check_mark:     |
+| v3 | :x:       | :white_check_mark:       |    :white_check_mark:     |
+| v4 | :x:       |   :x:      | :white_check_mark:       |
+
+## Logging context
+
+In order to implement the context logging (like the request-id and the log metadata) we rely on experimental features of NodeJS, specifically on [async_hooks](https://nodejs.org/dist/latest-v12.x/docs/api/async_hooks.html), some versions use different APIs:
+
+- v0-v3: [AsyncHook](https://nodejs.org/dist/latest-v12.x/docs/api/async_hooks.html#async_hooks_async_hooks_createhook_callbacks) through the package [cls-hooked](https://www.npmjs.com/package/cls-hooked)
+- v4: [AsyncLocalStorage](https://nodejs.org/dist/latest-v12.x/docs/api/async_hooks.html#async_hooks_class_asynclocalstorage) internal node API
+
 ## Basic Usage
 ```
 const { logger } = require('express-wolox-logger');

lib/context.js

@@ -0,0 +1,49 @@
+const { AsyncLocalStorage, AsyncResource } = require('async_hooks');
+
+const appMetadataKey = 'logMetadata';
+const appKey = 'express-wolox-logger';
+const asyncLocalStorage = new AsyncLocalStorage();
+
+const getLogStore = () => asyncLocalStorage && asyncLocalStorage.getStore();
+
+const getLogMetadata = () => {
+  const logStore = getLogStore();
+  return (logStore && logStore.get(appMetadataKey)) || {};
+};
+
+const addLogMetadata = newMetadata => {
+  const actualStore = getLogStore();
+  const actualLogMetadata = getLogMetadata();
+  if (actualStore) {
+    actualStore.set(appMetadataKey, { ...actualLogMetadata, ...newMetadata });
+  }
+};
+
+const getRequestId = () => getLogMetadata().requestId || null;
+
+const setRequestId = id => {
+  addLogMetadata({ requestId: id });
+  return id;
+};
+
+const runWithContext = callback => {
+  const resource = new AsyncResource(appKey);
+  return (...args) => resource.runInAsyncScope(callback, null, ...args);
+};
+
+const getInitialContext = ({ requestId }) => {
+  const context = new Map();
+  context.set(appMetadataKey, { requestId });
+  return context;
+};
+
+module.exports = {
+  runWithContext,
+  getInitialContext,
+  asyncLocalStorage,
+  getRequestId,
+  setRequestId,
+  getLogStore,
+  getLogMetadata,
+  addLogMetadata
+};

lib/index.js

@@ -1,9 +1,9 @@
 const loggers = require('./loggers');
 const middlewares = require('./middlewares');
-const namespace = require('./namespace');
+const context = require('./context');
 
 module.exports = {
   ...loggers,
   ...middlewares,
-  ...namespace
+  ...context
 };

lib/loggers/pino.js

@@ -1,6 +1,6 @@
 const pino = require('pino');
 
-const { getLogMetadata } = require('../namespace');
+const { getLogMetadata } = require('../context');
 
 module.exports = {
   getLogLevels: logger => Object.keys(logger.levels.values),

lib/middlewares.js

@@ -1,7 +1,7 @@
 const onFinished = require('on-finished');
 const shortid = require('shortid');
 
-const { namespace, setRequestId } = require('./namespace');
+const { runWithContext, getInitialContext, asyncLocalStorage } = require('./context');
 
 const secure = '[SECURE]';
 
@@ -67,7 +67,7 @@ const expressMiddleware = opts => {
 
     logStartMsg({ req, formattedBody, loggerFn, startFn });
     const begin = Date.now();
-    const onFinish = namespace.bind((error, response) => {
+    const onFinish = runWithContext((error, response) => {
       const end = Date.now();
       const responseTime = error ? '-' : end - begin;
       logEndMsg({ req, res: response, loggerFn, endFn, responseTime });
@@ -77,15 +77,15 @@ const expressMiddleware = opts => {
   };
 };
 
-const expressRequestIdMiddleware = opts => (req, res, next) => {
+const expressRequestIdMiddleware = opts => {
   const { headerName = 'x-request-id', idGenerator = shortid.generate } = opts || {};
-  namespace.bindEmitter(req);
-  namespace.bindEmitter(res);
-  return namespace.run(() => {
+  return (req, res, next) => {
     const requestId = req.headers[headerName] || idGenerator();
-    setRequestId(requestId);
-    next();
-  });
+    const initialContext = getInitialContext({ requestId });
+    return asyncLocalStorage.run(initialContext, () => {
+      next();
+    });
+  };
 };
 
 module.exports = { expressMiddleware, expressRequestIdMiddleware };