✨ Allow listing headers to remove from log entries (#10)

* ✨ Allow listing headers to remove from log entries * 0.2.0 * 🤡 replace cookie value with a mock * 🚚 rename `headersToSkip` to `excludeHeaders` * ✅ simplify snapshots
schibsted · Dec 11, 2020 · 50abf27 · 50abf27
1 parent 4b212be
commit 50abf27
Show file tree

Hide file tree

Showing 6 changed files with 189 additions and 72 deletions.
diff --git a/README.md b/README.md
@@ -24,6 +24,7 @@ npm install --save @schibsted/middy-access-log
 
 - `logger` (defaults to `console`) - a logging function that is invoked with the current error as an argument. You can pass `false` if you don't want the logging to happen.
 - `level` (defaults to `info`) - log level to use for the log entries
+- `excludeHeaders` (array of header names, defaults to `[]`) - prevent specified headers from showing up in logs (e.g. user credentials)
 
 
 See the sample usage below.

diff --git a/__snapshots__/index.test.js.snap b/__snapshots__/index.test.js.snap
@@ -1,72 +1,105 @@
 // Jest Snapshot v1, https://goo.gl/fbAQLP
 
 exports[`Middleware logs on error 1`] = `
-[MockFunction] {
-  "calls": Array [
-    Array [
-      Object {
-        "duration": 0,
-        "req": Object {
-          "headers": Object {
-            "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9",
-            "accept-encoding": "gzip, deflate, br",
-            "accept-language": "en-GB,en;q=0.9,en-US;q=0.8,pl;q=0.7,nb;q=0.6,no;q=0.5",
-            "connection": "keep-alive",
-            "host": "localhost:3000",
-            "upgrade-insecure-requests": "1",
-            "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.111 Safari/537.36",
-          },
-          "method": "GET",
-          "url": "/foobar",
-        },
-        "res": Object {},
+Array [
+  Object {
+    "duration": 0,
+    "req": Object {
+      "headers": Object {
+        "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9",
+        "accept-encoding": "gzip, deflate, br",
+        "accept-language": "en-GB,en;q=0.9,en-US;q=0.8,pl;q=0.7,nb;q=0.6,no;q=0.5",
+        "connection": "keep-alive",
+        "cookie": "my cookie 1; my cookie 2",
+        "host": "localhost:3000",
+        "upgrade-insecure-requests": "1",
+        "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.111 Safari/537.36",
       },
-      "  --> GET /foobar  0ns",
-    ],
-  ],
-  "results": Array [
-    Object {
-      "type": "return",
-      "value": undefined,
+      "method": "GET",
+      "url": "/foobar",
     },
-  ],
-}
+    "res": Object {},
+  },
+  "  --> GET /foobar  0ns",
+]
 `;
 
 exports[`Middleware logs on success 1`] = `
-[MockFunction] {
-  "calls": Array [
-    Array [
-      Object {
-        "duration": 0,
-        "req": Object {
-          "headers": Object {
-            "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9",
-            "accept-encoding": "gzip, deflate, br",
-            "accept-language": "en-GB,en;q=0.9,en-US;q=0.8,pl;q=0.7,nb;q=0.6,no;q=0.5",
-            "connection": "keep-alive",
-            "host": "localhost:3000",
-            "upgrade-insecure-requests": "1",
-            "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.111 Safari/537.36",
-          },
-          "method": "GET",
-          "url": "/foobar",
-        },
-        "res": Object {
-          "headers": Object {
-            "someHeader": "someValue",
-          },
-          "statusCode": 200,
-        },
+Array [
+  Object {
+    "duration": 0,
+    "req": Object {
+      "headers": Object {
+        "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9",
+        "accept-encoding": "gzip, deflate, br",
+        "accept-language": "en-GB,en;q=0.9,en-US;q=0.8,pl;q=0.7,nb;q=0.6,no;q=0.5",
+        "connection": "keep-alive",
+        "cookie": "my cookie 1; my cookie 2",
+        "host": "localhost:3000",
+        "upgrade-insecure-requests": "1",
+        "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.111 Safari/537.36",
       },
-      "  --> GET /foobar 200 0ns",
-    ],
-  ],
-  "results": Array [
-    Object {
-      "type": "return",
-      "value": undefined,
+      "method": "GET",
+      "url": "/foobar",
     },
-  ],
-}
+    "res": Object {
+      "headers": Object {
+        "someHeader": "someValue",
+      },
+      "statusCode": 200,
+    },
+  },
+  "  --> GET /foobar 200 0ns",
+]
+`;
+
+exports[`Middleware skips sensitive headers on error 1`] = `
+Array [
+  Object {
+    "duration": 0,
+    "req": Object {
+      "headers": Object {
+        "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9",
+        "accept-encoding": "gzip, deflate, br",
+        "accept-language": "en-GB,en;q=0.9,en-US;q=0.8,pl;q=0.7,nb;q=0.6,no;q=0.5",
+        "connection": "keep-alive",
+        "host": "localhost:3000",
+        "upgrade-insecure-requests": "1",
+        "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.111 Safari/537.36",
+      },
+      "method": "GET",
+      "url": "/foobar",
+    },
+    "res": Object {},
+  },
+  "  --> GET /foobar  0ns",
+]
+`;
+
+exports[`Middleware skips sensitive headers on success 1`] = `
+Array [
+  Object {
+    "duration": 0,
+    "req": Object {
+      "headers": Object {
+        "accept": "text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9",
+        "accept-encoding": "gzip, deflate, br",
+        "accept-language": "en-GB,en;q=0.9,en-US;q=0.8,pl;q=0.7,nb;q=0.6,no;q=0.5",
+        "connection": "keep-alive",
+        "host": "localhost:3000",
+        "upgrade-insecure-requests": "1",
+        "user-agent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.111 Safari/537.36",
+      },
+      "method": "GET",
+      "url": "/foobar",
+    },
+    "res": Object {
+      "headers": Object {
+        "someHeader": "someValue",
+      },
+      "statusCode": 200,
+    },
+  },
+  "  --> GET /foobar 200 0ns",
+]
 `;
diff --git a/index.js b/index.js
@@ -1,13 +1,13 @@
 const { performance } = require('perf_hooks');
 const R = require('ramda');
 
-const logResponse = ({ logger, level, event, response, duration }) => {
+const logResponse = ({ logger, level, excludeHeaders, event, response, duration }) => {
     logger[level](
         {
             req: {
                 method: event.httpMethod,
                 url: event.path,
-                headers: R.omit(['cookie'], event.headers),
+                headers: R.omit(excludeHeaders, event.headers),
             },
             res: R.omit(['body'], response),
             duration,
@@ -16,7 +16,7 @@ const logResponse = ({ logger, level, event, response, duration }) => {
     );
 };
 
-const accessLogMiddleware = ({ logger = console, level = 'info' } = {}) => ({
+const accessLogMiddleware = ({ logger = console, level = 'info', excludeHeaders = [] } = {}) => ({
     before: async ({ event }) => {
         // eslint-disable-next-line no-param-reassign
         event.requestStart = performance.now();
@@ -25,6 +25,7 @@ const accessLogMiddleware = ({ logger = console, level = 'info' } = {}) => ({
         logResponse({
             logger,
             level,
+            excludeHeaders,
             event: { ...handler.event },
             response: handler.response,
             duration: Math.round(performance.now() - handler.event.requestStart) * 1000000,
@@ -34,6 +35,7 @@ const accessLogMiddleware = ({ logger = console, level = 'info' } = {}) => ({
         logResponse({
             logger,
             level,
+            excludeHeaders,
             event: { ...handler.event },
             response: handler.response,
             duration: Math.round(performance.now() - handler.event.requestStart) * 1000000,

diff --git a/index.test.js b/index.test.js
@@ -35,16 +35,15 @@ test('Middleware logs on success', async () => {
                 'text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9',
             'accept-encoding': 'gzip, deflate, br',
             'accept-language': 'en-GB,en;q=0.9,en-US;q=0.8,pl;q=0.7,nb;q=0.6,no;q=0.5',
-            cookie:
-                'Phpstorm-79d24baa=172d13ea-950c-4011-b17d-56aaa9bd9e7c; Phpstorm-79d24bab=739b7880-e8b6-48a3-86e9-5f8ff0258361; _lp4_u=s0CHloIZ5X; _lp4_c=; Phpstorm-79d24bac=04b072cb-9640-47c8-8bb7-69d89af629ed; Phpstorm-79d24f6c=941943f9-6402-4be0-8c4b-42ab91078d26; Phpstorm-79d24f6d=c27d49d1-ef78-47c8-a0d4-34057bbe6a6d; amplitude_id_8ac078110370fb0bbfbaf21c2f885725=eyJkZXZpY2VJZCI6Ijk0YjU4OTQ0LTliZDUtNGQ3ZC1iZDg1LWQ5NzBjMDdkZmEzZVIiLCJ1c2VySWQiOm51bGwsIm9wdE91dCI6ZmFsc2UsInNlc3Npb25JZCI6MTU3NTk4Mzc5OTkzNywibGFzdEV2ZW50VGltZSI6MTU3NTk4NTAwMTAwOSwiZXZlbnRJZCI6MTYsImlkZW50aWZ5SWQiOjAsInNlcXVlbmNlTnVtYmVyIjoxNn0=; Phpstorm-79d2532e=7ad47b13-068c-4b85-9a59-08bd667d4d3e; _hjid=920a43ae-c27e-4cd7-8bce-cfb25d673c8c; _ga=GA1.1.487932309.1584426684; _hjMinimizedPolls=498936; Phpstorm-78282354=0cb6d112-59c3-4771-8b0d-c49c2c35cd4f; _pulse2data=f22ccca8-e6fb-4fe8-a9e6-71037d264c6b%2Cv%2C%2C1602510266259%2CeyJpc3N1ZWRBdCI6IjIwMTctMDctMDVUMDY6NDZaIiwiZW5jIjoiQTEyOENCQy1IUzI1NiIsImFsZyI6ImRpciIsImtpZCI6IjIifQ..WMRVvkUtl5GSDDPG52oSoQ.x4RmfEYeHJDh6ut8oCm1dzfsFzA-R_MTSr9b0khJMOZWv43XUW0LGCCtD6SZipMBjDMY-ONX6ywW_ma2gSi7IC9dHjWSGa9D--3b92N_q_Dr9k8x8mrf_0Plh67PwosAsOGaROy2SEO0SPb0sInac36D4bJWWNVk1YkuzkKO8YW86AuPj5Fr4CoyB9UVUp79y2c1m6MffA7FAEQ6nGLL7fKdeQXbStZMejnSN_ptZtA.kWBMiCFRp2hNRERaFD4rKA%2C4443096159538299%2C1602523766259%2Ctrue%2C%2CeyJraWQiOiIyIiwiYWxnIjoiSFMyNTYifQ..j8qlnJn7-TFbyS8IF-EYFx5clLViCrfMwmQCL1OoZOw; Phpstorm-78282355=dba20690-40f7-472b-ae3a-c2b4f0f51611',
+            cookie: 'my cookie 1; my cookie 2',
         },
         path: '/foobar',
         httpMethod: 'GET',
     };
 
     await handler(event, {});
     expect(mockLogger.info).toHaveBeenCalledTimes(1);
-    expect(mockLogger.info).toMatchSnapshot();
+    expect(mockLogger.info.mock.calls[0]).toMatchSnapshot();
 });
 
 test('Middleware logs on error', async () => {
@@ -70,8 +69,7 @@ test('Middleware logs on error', async () => {
                 'text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9',
             'accept-encoding': 'gzip, deflate, br',
             'accept-language': 'en-GB,en;q=0.9,en-US;q=0.8,pl;q=0.7,nb;q=0.6,no;q=0.5',
-            cookie:
-                'Phpstorm-79d24baa=172d13ea-950c-4011-b17d-56aaa9bd9e7c; Phpstorm-79d24bab=739b7880-e8b6-48a3-86e9-5f8ff0258361; _lp4_u=s0CHloIZ5X; _lp4_c=; Phpstorm-79d24bac=04b072cb-9640-47c8-8bb7-69d89af629ed; Phpstorm-79d24f6c=941943f9-6402-4be0-8c4b-42ab91078d26; Phpstorm-79d24f6d=c27d49d1-ef78-47c8-a0d4-34057bbe6a6d; amplitude_id_8ac078110370fb0bbfbaf21c2f885725=eyJkZXZpY2VJZCI6Ijk0YjU4OTQ0LTliZDUtNGQ3ZC1iZDg1LWQ5NzBjMDdkZmEzZVIiLCJ1c2VySWQiOm51bGwsIm9wdE91dCI6ZmFsc2UsInNlc3Npb25JZCI6MTU3NTk4Mzc5OTkzNywibGFzdEV2ZW50VGltZSI6MTU3NTk4NTAwMTAwOSwiZXZlbnRJZCI6MTYsImlkZW50aWZ5SWQiOjAsInNlcXVlbmNlTnVtYmVyIjoxNn0=; Phpstorm-79d2532e=7ad47b13-068c-4b85-9a59-08bd667d4d3e; _hjid=920a43ae-c27e-4cd7-8bce-cfb25d673c8c; _ga=GA1.1.487932309.1584426684; _hjMinimizedPolls=498936; Phpstorm-78282354=0cb6d112-59c3-4771-8b0d-c49c2c35cd4f; _pulse2data=f22ccca8-e6fb-4fe8-a9e6-71037d264c6b%2Cv%2C%2C1602510266259%2CeyJpc3N1ZWRBdCI6IjIwMTctMDctMDVUMDY6NDZaIiwiZW5jIjoiQTEyOENCQy1IUzI1NiIsImFsZyI6ImRpciIsImtpZCI6IjIifQ..WMRVvkUtl5GSDDPG52oSoQ.x4RmfEYeHJDh6ut8oCm1dzfsFzA-R_MTSr9b0khJMOZWv43XUW0LGCCtD6SZipMBjDMY-ONX6ywW_ma2gSi7IC9dHjWSGa9D--3b92N_q_Dr9k8x8mrf_0Plh67PwosAsOGaROy2SEO0SPb0sInac36D4bJWWNVk1YkuzkKO8YW86AuPj5Fr4CoyB9UVUp79y2c1m6MffA7FAEQ6nGLL7fKdeQXbStZMejnSN_ptZtA.kWBMiCFRp2hNRERaFD4rKA%2C4443096159538299%2C1602523766259%2Ctrue%2C%2CeyJraWQiOiIyIiwiYWxnIjoiSFMyNTYifQ..j8qlnJn7-TFbyS8IF-EYFx5clLViCrfMwmQCL1OoZOw; Phpstorm-78282355=dba20690-40f7-472b-ae3a-c2b4f0f51611',
+            cookie: 'my cookie 1; my cookie 2',
         },
         path: '/foobar',
         httpMethod: 'GET',
@@ -84,5 +82,88 @@ test('Middleware logs on error', async () => {
     );
 
     expect(mockLogger.info).toHaveBeenCalledTimes(1);
-    expect(mockLogger.info).toMatchSnapshot();
+    expect(mockLogger.info.mock.calls[0]).toMatchSnapshot();
+});
+
+test('Middleware skips sensitive headers on success', async () => {
+    const handler = middy(async () => ({
+        statusCode: 200,
+        body: JSON.stringify({ foo: 'bar' }),
+        headers: {
+            someHeader: 'someValue',
+        },
+    }));
+
+    const mockLogger = {
+        info: jest.fn(() => {}),
+    };
+
+    handler.use(
+        middleware({ logger: mockLogger, excludeHeaders: ['cookie', 'authentication', 'customRequestSignature'] })
+    );
+
+    const event = {
+        headers: {
+            host: 'localhost:3000',
+            connection: 'keep-alive',
+            'upgrade-insecure-requests': '1',
+            'user-agent':
+                'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.111 Safari/537.36',
+            accept:
+                'text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9',
+            'accept-encoding': 'gzip, deflate, br',
+            'accept-language': 'en-GB,en;q=0.9,en-US;q=0.8,pl;q=0.7,nb;q=0.6,no;q=0.5',
+            cookie: 'my cookie 1; my cookie 2',
+            authentication: 'super secret token',
+            customRequestSignature: 'foobar 123',
+        },
+        path: '/foobar',
+        httpMethod: 'GET',
+    };
+
+    await handler(event, {});
+    expect(mockLogger.info).toHaveBeenCalledTimes(1);
+    expect(mockLogger.info.mock.calls[0]).toMatchSnapshot();
+});
+
+test('Middleware skips sensitive headers on error', async () => {
+    const error = new createError.InternalServerError('whoops');
+    const handler = middy(async () => {
+        throw error;
+    });
+
+    const mockLogger = {
+        info: jest.fn(() => {}),
+    };
+
+    handler.use(
+        middleware({ logger: mockLogger, excludeHeaders: ['cookie', 'authentication', 'customRequestSignature'] })
+    );
+    const event = {
+        headers: {
+            host: 'localhost:3000',
+            connection: 'keep-alive',
+            'upgrade-insecure-requests': '1',
+            'user-agent':
+                'Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/86.0.4240.111 Safari/537.36',
+            accept:
+                'text/html,application/xhtml+xml,application/xml;q=0.9,image/avif,image/webp,image/apng,*/*;q=0.8,application/signed-exchange;v=b3;q=0.9',
+            'accept-encoding': 'gzip, deflate, br',
+            'accept-language': 'en-GB,en;q=0.9,en-US;q=0.8,pl;q=0.7,nb;q=0.6,no;q=0.5',
+            cookie: 'my cookie 1; my cookie 2',
+            authentication: 'super secret token',
+            customRequestSignature: 'foobar 123',
+        },
+        path: '/foobar',
+        httpMethod: 'GET',
+    };
+
+    await expect(handler(event, {})).rejects.toEqual(
+        expect.objectContaining({
+            error,
+        })
+    );
+
+    expect(mockLogger.info).toHaveBeenCalledTimes(1);
+    expect(mockLogger.info.mock.calls[0]).toMatchSnapshot();
 });
diff --git a/package-lock.json b/package-lock.json
diff --git a/package.json b/package.json
@@ -1,6 +1,6 @@
 {
   "name": "@schibsted/middy-access-log",
-  "version": "0.1.1",
+  "version": "0.2.0",
   "description": "Middy middleware for logging processed requests in an access-log like fashion. Optimised for JSON loggers e.g. Bunyan or Pino.",
   "main": "index.js",
   "scripts": {