Merge branch 'change/better-format' into 'master'

Change express format

See merge request Backend/ackee-node-logger!11

Author: smoliji

CHANGELOG.md

@@ -1,3 +1,11 @@
+## [0.2.8] - 2018-10-15
+
+### Changed
+- output format of express middleware logging
+
+### Fixed
+- bug in `enableFields` options
+
 ## [0.2.7] - 2018-10-10
 
 ### Changed

README.md

@@ -80,7 +80,7 @@ If you use it together with logger's error express middleware, it will also log
 app.use(logger.expressError)
 ```
 
-All those log messages will contain request and possibly response, error, time from request to response and status code.
+All those log messages will contain request and possibly response, error, time from request to response, status code and `user-agent`, `x-deviceid` and `authorization` request headers.
 
 ## Environment-specific behavior
 `ackee-node-logger` is meant to be used throughout different environments (development, testing, production) and some of its configuration is setup differently based on the environment it runs in.

express.js

@@ -2,8 +2,8 @@ const onFinished = require('on-finished');
 const onHeaders = require('on-headers');
 
 const expressMiddleware = function(req, response, next) {
-    const reqInfo = `${req.method} ${req.originalUrl} HTTP/${req.httpVersion}`;
-    this.debug({ req, ackId: req.ackId }, `${reqInfo} - Request accepted`);
+    const reqIn = `--- ${req.method} ${req.originalUrl} ${req.headers['user-agent']}`;
+    this.debug({ req, ackId: req.ackId }, `${reqIn} - Request accepted`);
     req._startAt = process.hrtime();
     onHeaders(response, () => {
         response._startAt = process.hrtime();
@@ -14,15 +14,16 @@ const expressMiddleware = function(req, response, next) {
     });
     onFinished(response, (err, res) => {
         const error = res[Symbol.for('error')];
+        const reqOut = `${res.statusCode} ${req.method} ${req.originalUrl} ${res.time} ms ${req.headers['user-agent']}`;
         if (this.options.ignoredHttpMethods.includes(req.method)) {
             return;
         }
         if (error) {
-            this.error({ error, req, res, ackId: req.ackId }, `${reqInfo} - Error handler at the end of app`);
+            this.error({ error, req, res, ackId: req.ackId }, `${reqOut} - Error handler at the end of app`);
         } else if (res.out) {
-            this.debug({ req, res, ackId: req.ackId }, `${reqInfo} - Standard output [${res.statusCode}]`);
+            this.debug({ req, res, ackId: req.ackId }, `${reqOut} - Standard output`);
         } else {
-            this.info({ req, res, ackId: req.ackId }, `${reqInfo} - Standard output [${res.statusCode}]`);
+            this.info({ req, res, ackId: req.ackId }, `${reqOut} - Standard output`);
         }
     });
     next();

package-lock.json

@@ -1,6 +1,6 @@
 {
   "name": "ackee-node-logger",
-  "version": "0.2.7",
+  "version": "0.2.8",
   "description": "Ackee Node Logger",
   "main": "index.js",
   "scripts": {
@@ -23,10 +23,10 @@
     "lodash.isempty": "^4.4.0",
     "lodash.isobject": "^3.0.2",
     "lodash.isstring": "^4.0.1",
-    "lodash.pick": "^4.4.0",
     "omit-deep": "^0.3.0",
     "on-finished": "^2.3.0",
     "on-headers": "^1.0.1",
+    "pick-deep": "^1.0.0",
     "pino": "^4.13.0",
     "pino-multi-stream": "3.1.2"
   },
@@ -37,10 +37,14 @@
     "flush-write-stream": "^1.0.2",
     "husky": "^0.14.3",
     "jest": "^22.4.2",
+    "jest-expect-message": "^1.0.1",
     "lint-staged": "^7.0.0",
     "npm-check": "^5.5.2",
     "prettier": "^1.11.0",
     "split2": "^2.2.0",
     "supertest": "^3.1.0"
+  },
+  "jest": {
+    "setupTestFrameworkScriptFile": "jest-expect-message"
   }
 }

package.json

@@ -1,5 +1,5 @@
 const forEach = require('lodash.foreach');
-const pick = require('lodash.pick');
+const pick = require('pick-deep');
 const { removeEmpty } = require('./utils');
 const omit = require('omit-deep');
 
@@ -24,6 +24,7 @@ const serializers = {
         return removeEmpty(Object.assign({}, filteredEnv, rest));
     },
     req(obj) {
+        const pickHeaders = ['x-deviceid', 'authorization', 'user-agent'];
         const [body, query] = ['body', 'query'].map(name => {
             const source = obj[name];
             if (source) {
@@ -39,6 +40,7 @@ const serializers = {
             query,
             url: obj.originalUrl || obj.url,
             method: obj.method,
+            headers: pick(obj.headers, pickHeaders),
         });
     },
     res(obj) {

serializers.js

@@ -1,6 +1,8 @@
-const pick = require('lodash.pick');
+const pick = require('pick-deep');
 const omitDeep = require('omit-deep');
 const stream = require('stream');
+const express = require('express');
+const supertest = require('supertest');
 
 let loggerFactory;
 
@@ -172,3 +174,96 @@ test('Enable custom path', () => {
     logger.info({ req });
     expect(loggerWrites).toBeCalled();
 });
+
+test('Some express headers are enabled by default', () => {
+    const loggerWrites = jest.fn();
+    const logger = loggerFactory({
+        streams: [
+            {
+                stream: new stream.Writable({
+                    write: (chunk, encoding, next) => {
+                        const json = JSON.parse(chunk);
+                        const validHeaders = ['x-deviceid', 'authorization', 'user-agent'];
+                        validHeaders.forEach(header =>
+                            expect(json.req.headers[header], `${header} header should be defined`).toBeDefined()
+                        );
+                        Object.keys(json.req.headers).forEach(header =>
+                            expect(validHeaders.includes(header), `${header} header should not be defined`).toBe(true)
+                        );
+                        loggerWrites();
+                        next();
+                    },
+                }),
+            },
+        ],
+    });
+    const app = express();
+    const request = supertest(app);
+    app.use(logger.express);
+    return request
+        .get('/')
+        .set('x-deviceid', '12345abcde')
+        .set('Authorization', 'Basic pass')
+        .set('User-Agent', 'Jest tests')
+        .set('Age', 100)
+        .then(() => {
+            expect(loggerWrites).toBeCalled();
+        });
+});
+
+test('Express fields and headers can be enabled', () => {
+    const loggerWrites = jest.fn();
+    const logger = loggerFactory({
+        enableFields: ['req.protocol', 'req.headers.host'],
+        streams: [
+            {
+                stream: new stream.Writable({
+                    write: (chunk, encoding, next) => {
+                        const json = JSON.parse(chunk);
+                        expect(json.req.protocol).toBe('http');
+                        expect(json.req.headers.host).toBe('localhost');
+                        loggerWrites();
+                        next();
+                    },
+                }),
+            },
+        ],
+    });
+    const app = express();
+    const request = supertest(app);
+    app.use(logger.express);
+    return request
+        .get('/')
+        .set('host', 'localhost')
+        .then(() => {
+            expect(loggerWrites).toBeCalled();
+        });
+});
+
+test('Default express headers can be disabled', () => {
+    const loggerWrites = jest.fn();
+    const logger = loggerFactory({
+        disableFields: ['req.headers.user-agent'],
+        streams: [
+            {
+                stream: new stream.Writable({
+                    write: (chunk, encoding, next) => {
+                        const json = JSON.parse(chunk);
+                        expect(json.req.headers['user-agent']).toBeUndefined();
+                        loggerWrites();
+                        next();
+                    },
+                }),
+            },
+        ],
+    });
+    const app = express();
+    const request = supertest(app);
+    app.use(logger.express);
+    return request
+        .get('/')
+        .set('x-deviceid', '1234')
+        .then(() => {
+            expect(loggerWrites).toBeCalled();
+        });
+});