Skip to content

Commit

Permalink
Rewrite tests, improve readme (#8)
Browse files Browse the repository at this point in the history 
* Refactor

- rewritten tests
- replaced lodash.omit with ramda to unify middlewares
- stopped using event.requestContext
- added NPM keywords
- added README.md

* 0.1.0

* Update snapshot

* Mock perf_hooks module

Co-authored-by: Wojciech Iskra <[email protected]>
  • Loading branch information
@domeq
domeq and domeq authored Oct 28, 2020
1 parent 0d190d6 commit 4820451
Show file tree
Hide file tree
Showing 6 changed files with 193 additions and 82 deletions.
52 changes: 50 additions & 2 deletions README.md
View file
Original file line number Diff line number Diff line change
@@ -1,2 +1,50 @@
# middy-access-log
Middy middleware for logging processed requests in an access-log like fashion
# Schibsted Middy access log middleware

#### Access log middleware for the middy framework, the stylish Node.js middleware engine for AWS Lambda


This middleware logs processed requests in an access log like fashion.
I suggest using it together with [@schibsted/middy-error-handler](https://github.com/schibsted/middy-error-handler)

This access log is optimised for JSON loggers e.g. [bunyan](https://github.com/trentm/node-bunyan) or [pino](https://getpino.io/)

Sets headers in `after` and `onError` phases.


## Install

To install this middleware you can use NPM:

```bash
npm install --save @schibsted/middy-access-log
```


## Options

- `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


See the sample usage below.


## Sample usage

```javascript
const middy = require('@middy/core');
const accessLog = require('@schibsted/middy-access-log');

const handler = middy(async () => ({
statusCode: 200,
body: JSON.stringify({ foo: 'bar' }),
}));

handler
.use(accessLog());
```


## Contributing

Everyone is very welcome to contribute to this repository. Feel free to [raise issues](https://github.com/schibsted/middy-access-log/issues) or to [submit Pull Requests](https://github.com/schibsted/middy-access-log/pulls).
9 changes: 5 additions & 4 deletions __snapshots__/index.test.js.snap
View file
Original file line number Diff line number Diff line change
Expand Up @@ -19,11 +19,9 @@ exports[`Middleware logs on error 1`] = `
"method": "GET",
"url": "/foobar",
},
"res": Object {
"statusCode": 500,
},
"res": Object {},
},
" --> GET /foobar 500 0ns",
" --> GET /foobar 0ns",
],
],
"results": Array [
Expand Down Expand Up @@ -55,6 +53,9 @@ exports[`Middleware logs on success 1`] = `
"url": "/foobar",
},
"res": Object {
"headers": Object {
"someHeader": "someValue",
},
"statusCode": 200,
},
},
Expand Down
18 changes: 9 additions & 9 deletions index.js
View file
Original file line number Diff line number Diff line change
@@ -1,33 +1,33 @@
const { performance } = require('perf_hooks');
const omit = require('lodash.omit');
const R = require('ramda');

const logResponse = ({ logger, level, event, response, duration }) => {
logger[level](
{
req: {
method: event.requestContext.httpMethod,
method: event.httpMethod,
url: event.path,
headers: omit(event.headers, ['cookie']),
headers: R.omit(['cookie'], event.headers),
},
res: omit(response, ['body']),
res: R.omit(['body'], response),
duration,
},
` --> ${event.requestContext.httpMethod} ${event.path} ${response.statusCode} ${duration}ns`
` --> ${event.httpMethod} ${event.path} ${R.propOr('', 'statusCode', response)} ${duration}ns`
);
};

const accessLogMiddleware = ({ logger = console, level = 'info' } = {}) => ({
before: async ({ event }) => {
// eslint-disable-next-line no-param-reassign
event.requestContext.requestStart = performance.now();
event.requestStart = performance.now();
},
after: async (handler) => {
logResponse({
logger,
level,
event: { ...handler.event },
response: handler.response,
duration: Math.round(performance.now() - handler.event.requestContext.requestStart) * 1000000,
duration: Math.round(performance.now() - handler.event.requestStart) * 1000000,
});
},
onError: async (handler) => {
Expand All @@ -36,10 +36,10 @@ const accessLogMiddleware = ({ logger = console, level = 'info' } = {}) => ({
level,
event: { ...handler.event },
response: handler.response,
duration: Math.round(performance.now() - handler.event.requestContext.requestStart) * 1000000,
duration: Math.round(performance.now() - handler.event.requestStart) * 1000000,
});

return handler.error;
return handler;
},
});

Expand Down
117 changes: 61 additions & 56 deletions index.test.js
View file
Original file line number Diff line number Diff line change
@@ -1,82 +1,87 @@
test('Middleware returns all 3 handlers', () => {
const accessLogMiddleware = require('./index')();
const middy = require('@middy/core');
const createError = require('http-errors');
const middleware = require('./index');

expect(accessLogMiddleware.before).toBeInstanceOf(Function);
expect(accessLogMiddleware.after).toBeInstanceOf(Function);
expect(accessLogMiddleware.onError).toBeInstanceOf(Function);
jest.mock('perf_hooks', () => {
const performanceMock = {
now: jest.fn().mockReturnValue(1),
};
return { performance: performanceMock };
});

test('Middleware logs on success', async () => {
const handler = middy(async () => ({
statusCode: 200,
body: JSON.stringify({ foo: 'bar' }),
headers: {
someHeader: 'someValue',
},
}));

const mockLogger = {
info: jest.fn(() => {}),
};
const accessLogMiddleware = require('./index')({ logger: mockLogger });

const payload = {
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:
'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',
},
path: '/foobar',
requestContext: {
httpMethod: 'GET',
},
},
response: {
statusCode: 200,
handler.use(middleware({ logger: mockLogger }));

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:
'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',
},
path: '/foobar',
httpMethod: 'GET',
};

await accessLogMiddleware.before(payload);
await accessLogMiddleware.after(payload);

await handler(event, {});
expect(mockLogger.info).toHaveBeenCalledTimes(1);
expect(mockLogger.info).toMatchSnapshot();
});

test('Middleware logs on error', async () => {
const error = new createError.InternalServerError('whoops');
const handler = middy(async () => {
throw error;
});

const mockLogger = {
info: jest.fn(() => {}),
};
const accessLogMiddleware = require('./index')({ logger: mockLogger });

const payload = {
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:
'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',
},
path: '/foobar',
requestContext: {
httpMethod: 'GET',
},
},
response: {
statusCode: 500,
handler.use(middleware({ logger: mockLogger }));

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:
'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',
},
path: '/foobar',
httpMethod: 'GET',
};

await accessLogMiddleware.before(payload);
await accessLogMiddleware.after(payload);
await expect(handler(event, {})).rejects.toEqual(
expect.objectContaining({
error,
})
);

expect(mockLogger.info).toHaveBeenCalledTimes(1);
expect(mockLogger.info).toMatchSnapshot();
Expand Down
58 changes: 52 additions & 6 deletions package-lock.json
View file

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

Loading

0 comments on commit 4820451

Please sign in to comment.