v3 (#60)

Add log metadata functions + Remove testing ignore flag + Update documentation + Update pino version to latest version

.travis.yml

@@ -1,6 +1,6 @@
 language: node_js
 node_js:
-  - "8.11.4"
+  - "12.17.0"
 dist: trusty
 
 script:

README.md

@@ -13,10 +13,14 @@ logger.error('something bad happened');
 ```
 This will output:
 ```
-[2019-06-14 17:35:13.772 +0000] INFO  (17439 on my-pc.local): hello world
-[2019-06-14 17:35:13.772 +0000] ERROR (17439 on my-pc.local): something bad happened
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"hello world"}
+{"level":22,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"something bad happened"}
 ```
 
+## Pretty print
+
+By default, we use NDJSON for logging, but if you want to format the logs in another way you can check the [pretty section](https://getpino.io/#/docs/pretty) of pino
+
 ## Advanced Usage
 
 The exported `createLogger` function takes one optional argument,
@@ -28,10 +32,7 @@ returns a `logger instance`.
 
 #### `options` (Object)
 Default (pino): `{
-  prettyPrint: {
-    translateTime: true,
-    colorize: false
-  }
+  mixin // we use this for add metadata log 
 }`
 
 Options for logger instance, check documentation of each package for more details ([pino](https://github.com/pinojs/pino/blob/master/docs/api.md#options))
@@ -78,10 +79,10 @@ app.use(expressMiddleware({ loggerFn: logger.info }));
 ```
 This in conjunction with the basic logs will output:
 ```
-[2019-06-14 17:35:13.770 +0000] INFO  (17439 on my-pc.local): Started GET /logger/test with params: {}, query: {}, body: {}.
-[2019-06-14 17:35:13.772 +0000] INFO  (17439 on my-pc.local): hello world
-[2019-06-14 17:35:13.772 +0000] ERROR (17439 on my-pc.local): something bad happened
-[2019-06-14 17:35:13.781 +0000] INFO  (17439 on my-pc.local): Ended GET /logger/test with status: 200 in 10 ms
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"Started GET /logger/test with params: {}, query: {}, body: {}"}
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"hello world"}
+{"level":22,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"something bad happened"}
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"Ended GET /logger/test with status: 200 in 10 ms"}
 ```
 
 ### Advanced Usage
@@ -107,7 +108,7 @@ Options for obfuscate body of request, could be a boolean (true or false) that a
 ```
 {
   obfuscateBody: {
-    '/some_url': { // this should be a regex of url to obfuscate
+    '/some_url': { // this should be a regex of url to obfuscate
       POST: true // method to obfuscate
     }
   }
@@ -123,12 +124,12 @@ app.use(expressMiddleware({ loggerFn: logger.info, obfuscatePlaceholder: '[SECRE
 ```
 This in conjunction with the basic logs will output:
 ```
-[2019-06-14 17:35:13.770 +0000] INFO  (17439 on my-pc.local): Started POST /secure with params: {}, query: {}, body: [SECRET].
-[2019-06-14 17:35:13.772 +0000] INFO  (17439 on my-pc.local): hello world
-[2019-06-14 17:35:13.781 +0000] INFO  (17439 on my-pc.local): Ended POST /secure with status: 200 in 10 ms
-[2019-06-14 17:35:13.770 +0000] INFO  (17439 on my-pc.local): Started GET /secure with params: {}, query: {}, body: {}.
-[2019-06-14 17:35:13.772 +0000] INFO  (17439 on my-pc.local): hello world
-[2019-06-14 17:35:13.781 +0000] INFO  (17439 on my-pc.local): Ended GET /secure with status: 200 in 10 ms
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"Started POST /secure with params: {}, query: {}, body: [SECRET]"}
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"hello world"}
+{"level":22,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"Ended POST /secure with status: 200 in 10 ms"}
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"Started GET /secure with params: {}, query: {}, body: {}"}
+{"level":22,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"hello world"}
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"Ended GET /secure with status: 200 in 10 ms"}
 ```
 
 ### Obfuscating body of all requests
@@ -139,16 +140,14 @@ app.use(expressMiddleware({ loggerFn: logger.info, obfuscatePlaceholder: '[SECRE
 ```
 This in conjunction with the basic logs will output:
 ```
-[2019-06-14 17:35:13.770 +0000] INFO  (17439 on my-pc.local): Started POST /secure with params: {}, query: {}, body: [SECRET].
-[2019-06-14 17:35:13.772 +0000] INFO  (17439 on my-pc.local): hello world
-[2019-06-14 17:35:13.781 +0000] INFO  (17439 on my-pc.local): Ended POST /secure with status: 200 in 10 ms
-[2019-06-14 17:35:13.770 +0000] INFO  (17439 on my-pc.local): Started GET /secure with params: {}, query: {}, body: [SECRET].
-[2019-06-14 17:35:13.772 +0000] INFO  (17439 on my-pc.local): hello world
-[2019-06-14 17:35:13.781 +0000] INFO  (17439 on my-pc.local): Ended GET /secure with status: 200 in 10 ms
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"Started POST /secure with params: {}, query: {}, body: [SECRET]"}
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"hello world"}
+{"level":22,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"Ended POST /secure with status: 200 in 10 ms"}
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"Started GET /secure with params: {}, query: {}, body: [SECRET]"}
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"hello world"}
+{"level":22,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"Ended GET /secure with status: 200 in 10 ms"}
 ```
 
-
-
 ## Request Ids
 We also provide an ExpressJs middleware that appends a `request id` to all logs made for a single request. This is useful for better tracking logs when there are several requests going on concurrently. Again, simply import it and use it like any other middleware.
 
@@ -160,8 +159,8 @@ app.use(expressRequestIdMiddleware());
 ```
 This, in conjunction with the basic logs will output:
 ```
-[2019-06-14 17:35:13.772 +0000] INFO  (17439 on my-pc.local): [GNc7JovB7] hello world
-[2019-06-14 17:35:13.772 +0000] ERROR (17439 on my-pc.local): [GNc7JovB7] something bad happened
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"hello world","requestId":"GNc7JovB7"}
+{"level":22,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"something bad happened","requestId":"GNc7JovB7" }
 ```
 Note, that if you are using [Sequelize](http://docs.sequelizejs.com/), you need to configure it to use the logger's CLS namespace, otherwise the `requests ids` will not persist through `sequelize` promises. The same may apply to other frameworks.
 
@@ -199,8 +198,8 @@ app.use(expressRequestIdMiddleware({ headerName: 'id', idGenerator: uuid }));
 ```
 This, in conjunction with the basic logs will output:
 ```
-[2019-06-14 17:35:13.772 +0000] INFO  (17439 on my-pc.local): [a2936029-9bd4-402d-ba43-a4873f228274] hello world
-[2019-06-14 17:35:13.772 +0000] ERROR (17439 on my-pc.local): [a2936029-9bd4-402d-ba43-a4873f228274] something bad happened
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"hello world","requestId":"a2936029-9bd4-402d-ba43-a4873f228274"}
+{"level":22,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"something bad happened","requestId":"a2936029-9bd4-402d-ba43-a4873f228274" }
 ```
 
 ### Forwarding the request Id
@@ -215,6 +214,24 @@ This will result in the requestId being logged through your services until the r
 
 We used [axios](https://www.npmjs.com/package/axios) for this example but other requets packages like [request-promise](https://github.com/request/request-promise) work exactly the same way.
 
+## Logging Metadata
+We provide some functions to allow logging some extra metadata like the request-id or any custom field that you need for tracking in all your app logs
+
+### Example
+```
+const { addLogMetadata, getLogMetadata } = require('express-wolox-logger');
+
+app.use((req, res, next) => {
+  addLogMetadata({ some_custom_field: res.locals.some_field, other_custom_field: 'APP_FLOW' })
+  next();
+})
+```
+This, in conjunction with the basic logs will output:
+```
+{"level":30,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"hello world","some_custom_field": "some_value", "other_custom_field": "APP_FLOW"}
+{"level":22,"time":1591139401676,"pid":45656,"hostname":"192.168.1.4","msg":"something bad happened","some_custom_field": "some_value", "other_custom_field": "APP_FLOW"}
+```
+
 ## Migrate from winston to express-wolox-logger
 If you are wondering how to migrate from wolox express-js boostrap configuration with winston to this package refer to the [step by step migration guide](Migrate.md)
 

lib/benchmarks.js

@@ -1,23 +1,28 @@
+/* eslint-disable global-require */
 'use strict';
-const bench = require('fastbench'),
-  pino = require('pino'),
-  { createLogger } = require('./loggers'),
-  nullLogger = createLogger({ options: pino.destination('/dev/null'), loggerOption: 'pino' }),
-  { type, platform, arch, release, cpus } = require('os');
+const { type, platform, arch, release, cpus } = require('os');
 
-const stringExample = 'This is a string',
-  objectExample = { foo: 'bar', foo1: 'bar', foo2: 'bar', foo3: 'bar' },
-  deepObjExample = { ...require('../package.json'), level: 'info' },
-  longStringExample = JSON.stringify(require('../package.json')),
-  longDeepObjExample = { ...require('../package-lock.json'), level: 'info' },
-  reallyLongStringExample = JSON.stringify(require('../package-lock.json'));
+const bench = require('fastbench');
+const pino = require('pino');
+const { createLogger } = require('./loggers');
+
+const nullLogger = createLogger({ options: pino.destination('/dev/null'), loggerOption: 'pino' });
+
+const stringExample = 'This is a string';
+const objectExample = { foo: 'bar', foo1: 'bar', foo2: 'bar', foo3: 'bar' };
+const deepObjExample = { ...require('../package.json'), level: 'info' };
+const longStringExample = JSON.stringify(require('../package.json'));
+
+const longDeepObjExample = { ...require('../package-lock.json'), level: 'info' };
+const reallyLongStringExample = JSON.stringify(require('../package-lock.json'));
 
 let iterations = 10;
 if (process.argv[2] && !isNaN(process.argv[2])) {
   iterations = process.argv[2];
 }
 
 const times = 10;
+// eslint-disable-next-line no-console
 console.log(`Wolox logger benchmarks
 -------------------------------------------------------------
 To set the iterations number (default is 10) add a number argument to this bench call.

lib/loggers/index.js

@@ -1,30 +1,13 @@
-const { getRequestId } = require('../namespace');
-
 const loggerOptions = ['pino'];
 
-const getRequestIdPrefix = () => {
-  const requestId = getRequestId();
-  return requestId ? `[${requestId}] ` : '';
-};
-
-const isTesting = process.env.NODE_ENV && process.env.NODE_ENV.toLowerCase() === 'testing',
-  logOnTesting = !!process.env.LOG_ON_TEST;
-
 const createLogger = opts => {
   const { options, loggerOption = 'pino' } = opts || {};
   if (!loggerOptions.includes(loggerOption)) {
     throw new Error(`Logger '${loggerOption}' is not available, available loggers are [${loggerOptions}]`);
   }
-
-  const { getLogger, getLogLevels } = require(`./${loggerOption}`);
-  const logger = getLogger(options);
-  const loggerWrapper = getLogLevels(logger).reduce((newLogger, logLevel) => {
-    newLogger[logLevel] =
-      isTesting && !logOnTesting ? () => true : (...args) => logger[logLevel](getRequestIdPrefix(), ...args);
-    return newLogger;
-  }, {});
-
-  return { ...logger, ...loggerWrapper };
+  // eslint-disable-next-line global-require
+  const { getLogger } = require(`./${loggerOption}`);
+  return getLogger(options);
 };
 
 module.exports = { createLogger, logger: createLogger() };

lib/loggers/pino.js

@@ -1,13 +1,12 @@
 const pino = require('pino');
 
-const defaultPinoOptions = {
-  prettyPrint: {
-    translateTime: true,
-    colorize: false
-  }
-};
+const { getLogMetadata } = require('../namespace');
 
 module.exports = {
   getLogLevels: logger => Object.keys(logger.levels.values),
-  getLogger: (options = defaultPinoOptions) => pino(options)
+  getLogger: (options = {}) =>
+    pino({
+      ...options,
+      mixin: () => getLogMetadata()
+    })
 };

lib/middlewares.js

@@ -38,11 +38,9 @@ const expressMiddleware = opts => {
     });
 
     loggerFn(
-      `Started ${url} ${method} with params:`,
+      `Started ${url} ${method} with params: %j query: %j body: %j`,
       params || {},
-      'query:',
       query || {},
-      'body:',
       formattedBody || {}
     );
     const begin = Date.now();

lib/namespace.js

@@ -3,11 +3,16 @@ const { createNamespace } = require('cls-hooked');
 
 const namespace = createNamespace(`express-wolox-logger:${shortid()}`);
 
-const getRequestId = () => (namespace ? namespace.get('requestId') : null);
+const getLogMetadata = () => (namespace && namespace.get('logMetadata')) || {};
+
+const addLogMetadata = newMetadata =>
+  namespace && namespace.set('logMetadata', { ...getLogMetadata(), ...newMetadata });
+
+const getRequestId = () => getLogMetadata().requestId || null;
 
 const setRequestId = id => {
-  namespace.set('requestId', id);
+  addLogMetadata({ requestId: id });
   return id;
 };
 
-module.exports = { namespace, getRequestId, setRequestId };
+module.exports = { namespace, getRequestId, setRequestId, getLogMetadata, addLogMetadata };