From 62b1f9e0d32cd5ed95ef1933b68a9b6c204eb226 Mon Sep 17 00:00:00 2001 From: Jason Lai Date: Wed, 29 Oct 2014 17:38:55 -0700 Subject: [PATCH] Initial version --- .jshintrc | 4 + LICENSE | 2 +- Makefile | 19 ++++ README.md | 234 ++++++++++++++++++++++++++++++++++++++++++- examples/nested.js | 48 +++++++++ examples/requests.js | 15 +++ examples/simple.js | 13 +++ index.js | 201 +++++++++++++++++++++++++++++++++++++ package.json | 41 ++++++++ test/index.js | 225 +++++++++++++++++++++++++++++++++++++++++ 10 files changed, 799 insertions(+), 3 deletions(-) create mode 100644 .jshintrc create mode 100644 Makefile create mode 100644 examples/nested.js create mode 100644 examples/requests.js create mode 100644 examples/simple.js create mode 100644 index.js create mode 100644 package.json create mode 100644 test/index.js diff --git a/.jshintrc b/.jshintrc new file mode 100644 index 0000000..58bc6ee --- /dev/null +++ b/.jshintrc @@ -0,0 +1,4 @@ +{ + "esnext": true, + "node": true +} diff --git a/LICENSE b/LICENSE index 0d0b58c..e89a7f8 100644 --- a/LICENSE +++ b/LICENSE @@ -1,6 +1,6 @@ The MIT License (MIT) -Copyright (c) 2014 pebble +Copyright (c) 2014 Pebble Technology Permission is hereby granted, free of charge, to any person obtaining a copy of this software and associated documentation files (the "Software"), to deal diff --git a/Makefile b/Makefile new file mode 100644 index 0000000..b77c925 --- /dev/null +++ b/Makefile @@ -0,0 +1,19 @@ +LINT = node_modules/.bin/jshint +MOCHA = node_modules/.bin/_mocha +ISTANBUL = node_modules/.bin/istanbul + +all: lint test-cov + +lint: index.js + @ $(LINT) index.js + +test: .PHONY + @ node --harmony $(MOCHA) + +test-cov: .PHONY + @ node --harmony $(ISTANBUL) cover $(MOCHA) + +test-travis: lint test-cov + @ node --harmony $(ISTANBUL) check-coverage + +.PHONY: diff --git a/README.md b/README.md index 73be802..fcd118d 100644 --- a/README.md +++ b/README.md @@ -1,2 +1,232 @@ -koa-bunyan-logger -================= +# koa-bunyan-logger + +Flexible log context and request logging middleware +for [koa](http://koajs.com/) using [bunyan](https://github.com/trentm/node-bunyan). + +Inspired by [koa-bunyan](https://github.com/ivpusic/koa-bunyan), +[koa-json-logger](https://github.com/rudijs/koa-json-logger), +[bunyan-request](https://github.com/vvo/bunyan-request), and others. + +A primary goal of this module is to be as flexible as possible, while +remaining relatively lightweight, leaving advanced functionality and +customization the app. + +```js +var koa = require('koa'); +var koaBunyanLogger = require('koa-bunyan-logger'); + +var app = koa(); +app.use(koaBunyanLogger()); + +app.use(function *() { + this.log.info({'Got a request from %s for %s', this.request.ip, this.path); +}); + +app.listen(8000); +``` + +Server: +``` +node --harmony examples/simple.js | ./node_modules/.bin/bunyan -o short` +``` + +Client: +``` +curl http://localhost:8000/ +``` + +Server output: +``` +07:50:14.014Z INFO koa: Got a request from ::1 for / +``` + +### Request logging + +```js +app.use(koaBunyanLogger()); +app.use(koaBunyanLogger.requestIdContext()); +app.use(koaBunyanLogger.requestLogger()); +``` + +Server: +``` +node --harmony examples/requests.js | ./node_modules/.bin/bunyan -o short +``` + +Client: +``` +curl -H "X-Request-Id: 1234" http://localhost:8000/ +``` + +Server output: +``` +20:19:24.526Z INFO koa: --> GET / (req_id=1234) + GET / HTTP/1.1 + -- + req.header: { + "user-agent": "curl/7.30.0", + "host": "localhost:8000", + "accept": "*/*", + "x-request-id": "1234" + } +20:19:24.527Z INFO koa: <-- GET / 1ms (req_id=1234, duration=1, res.status=200, res.message=OK) + GET / HTTP/1.1 + -- + x-powered-by: koa + content-type: text/plain; charset=utf-8 + content-length: 11 + -- + req.header: { + "user-agent": "curl/7.30.0", + "host": "localhost:8000", + "accept": "*/*", + "x-request-id": "1234" + } +``` + +### Suppressing default error stack traces + +To ensure that stack traces from request handling don't get logged in their +raw non-JSON forms, you can disable the app's default error handler: + +```js +app.on('error', function () {}); +``` + +## API Reference + +### koaBunyanLogger(logger) + +Parameters: +- logger: bunyan logger instance or an object to pass to bunyan.createLogger() + +#### Examples + +Use an existing logger: + +```js +var bunyan = require('bunyan'); +var koaBunyanLogger = require('koa-bunyan-logger'); + +var appLogger = bunyan.createLogger({name: 'myapp', level: 'debug'}); + +app.use(koaBunyanLogger(appLogger)); +``` + +Shortcut to create a new logger: + +```js +var koaBunyanLogger = require('koa-bunyan-logger'); + +app.use(koaBunyanLogger({ + name: 'myapp', + level: 'debug' +})); +``` + +### koaBunyanLogger.requestLogger(opts) + +Options: +- durationField: Name of field to store request duration in ms + +- levelFn: Function which will be called with (status, err) and should + return the name of a log level to be used for the response log entry. + The default function will log status 400-499 as warn, 500+ as error, + and all other responses as info. + +- updateLogFields: Function which will be called with a single argument, + an object containing the fields (req, res, err) to be logged with the + request and response message. + + The function has the opportunity to add or remove fields from the object, + or return a different object to replace the default set of fields. + The function will be called using the koa 'this' context, once for the + request and again for the response. + +- updateRequestLogFields: Function which will be called with a request + fields object when logging a request, after processing updateLogFields. + +- updateResponseLogFields: Function which will be called with a response + fields object when logging a response, after processing updateLogFields. + It also receives a second argument, err, if an error was thrown. + +- formatRequestLog: Function which will be called to generate a log message + for logging requests. The function will be called in the context of the + koa 'this' context and passed the request fields object. It should return + a string. + +- formatResponseLog: Same as formatRequestLog, but for responses. + +#### Examples + +Basic usage: + +```js +app.use(koaBunyanLogger()); +app.use(koaBunyanLogger.requestLogger()); +``` + +Add custom fields to include in request and response logs: + +```js +app.use(koaBunyanLogger.requestLogger({ + // Custom fields for both request and response + updateLogFields: function (fields) { + fields.authorized_user = this.user.id; + fields.client_version = this.request.get('X-Client-Version'); + }, + + // Custom fields for response only + updateResponseLogFields: function (fields, err) { + if (err) { + fields.last_db_query = this.db.lastDbQuery(); + } + } +})); +``` + +### koaBunyanLogger.requestIdContext(opts) + +Get X-Request-Id header, or if the header does not exist, generates a random +unique id for each request. + +Options: +- header: name of header to get request id from +- prop: property to store on context; defaults to 'reqId' e.g. this.reqId +- requestProp: property to store on request; defaults to 'reqId' e.g. this.request.reqId +- field: field to add to log messages in downstream middleware and handlers; + defaults to 'req_id' + +#### Examples + +```js +var koaBunyanLogger = require('koa-bunyan-logger'); + +app.use(koaBunyanLogger()); +app.use(koaBunyanLogger.requestIdContext()); +``` + +Or use a different header: + +```js +var koaBunyanLogger = require('koa-bunyan-logger'); + +app.use(koaBunyanLogger()); +app.use(koaBunyanLogger.requestIdContext({ + header: 'Request-Id' +})); +``` + +By default, the request id will be accessible as this.reqId and this.request.reqId: + +```js +var koaBunyanLogger = require('koa-bunyan-logger'); + +app.use(koaBunyanLogger()); +app.use(koaBunyanLogger.requestIdContext()); + +app.use(function * () { + this.response.set('X-Server-Request-Id', this.reqId); + this.body = "Hello world"; +}); +``` diff --git a/examples/nested.js b/examples/nested.js new file mode 100644 index 0000000..45157fb --- /dev/null +++ b/examples/nested.js @@ -0,0 +1,48 @@ +var koa = require('koa'); +var koaBunyanLogger = require('../'); + +var app = koa(); + +app.use(koaBunyanLogger()); +app.use(koaBunyanLogger.requestLogger()); + +var userByToken = { + 'token123': {id: 1, name: 'alice'}, + 'token345': {id: 2, name: 'bob'} +}; + +app.use(function *(next) { + var token = this.query.token; + + if (!token) { + this.throw(403, 'expected token\r\n'); + } + + this.log.trace('looking up user with token "%s"', token); + this.user = userByToken[token]; + + if (!this.user) { + this.throw(403, 'invalid user token\r\n'); + } + + yield next; +}); + +// All log messages from downstream middleware +// will now have 'authorized_user' added to the log fields +app.use(function *(next) { + this.log = this.log.child({ + authorized_user: this.user.id + }); + + yield next; +}); + +app.use(function *() { + this.log.info('doing stuff'); + + this.body = "OK\r\n"; +}); + +app.listen(8000); + diff --git a/examples/requests.js b/examples/requests.js new file mode 100644 index 0000000..d944174 --- /dev/null +++ b/examples/requests.js @@ -0,0 +1,15 @@ +var koa = require('koa'); +var koaBunyanLogger = require('../'); + +var app = koa(); + +app.use(koaBunyanLogger()); +app.use(koaBunyanLogger.requestIdContext()); +app.use(koaBunyanLogger.requestLogger()); + +app.use(function *() { + this.body = 'Hello world\r\n'; +}); + +app.listen(8000); + diff --git a/examples/simple.js b/examples/simple.js new file mode 100644 index 0000000..032dad1 --- /dev/null +++ b/examples/simple.js @@ -0,0 +1,13 @@ +var koa = require('koa'); +var koaBunyanLogger = require('../'); + +var app = koa(); + +app.use(koaBunyanLogger()); + +app.use(function *() { + this.log.info('Got a request from %s for %s', this.request.ip, this.path); + this.body = 'Hello world\r\n'; +}); + +app.listen(8000); diff --git a/index.js b/index.js new file mode 100644 index 0000000..128e495 --- /dev/null +++ b/index.js @@ -0,0 +1,201 @@ +'use strict'; + +var bunyan = require('bunyan'); +var uuid = require('node-uuid'); +var util = require('util'); +var onFinished = require('on-finished'); + +/* + * If logger is a bunyan logger instance, return it; + * otherwise, create a new logger with some reasonable defaults. + */ +function createOrUseLogger(logger) { + if (!logger || !logger.info || !logger.child) { + var loggerOpts = logger || {}; + loggerOpts.name = loggerOpts.name || 'koa'; + loggerOpts.serializers = loggerOpts.serializers || bunyan.stdSerializers; + + logger = bunyan.createLogger(loggerOpts); + } + + return logger; +} + +/* + * Koa middleware that adds this.log property to the koa context + * containing a bunyan logger instance. + * + * Parameters: + * - logger: bunyan logger instance, or an object with properties + * that will be passed to bunyan.createLogger. If not + * specified, a default logger will be used. + */ +module.exports = function (logger) { + logger = createOrUseLogger(logger); + + return function *(next) { + this.log = logger; + + yield *next; // jshint ignore:line + }; +}; + +/* + * Koa middleware that gets a unique request id from a header or + * generates a new one, and adds the requestId to all messages logged + * using this.log in downstream middleware and handlers. + * + * Must use(koaBunyanLogger()) before using this middleware. + * + * Parameters: + * - opts: object with optional properties: + * - header: name of header to get request id from (default X-Request-Id) + * - prop: property to store on 'this' context (default 'reqId') + * - requestProp: property to store on 'this.request' (default 'reqId') + * - field: log field name for bunyan (default 'req_id') + */ +module.exports.requestIdContext = function (opts) { + opts = opts || {}; + + var header = opts.header || 'X-Request-Id'; + var ctxProp = opts.prop || 'reqId'; + var requestProp = opts.requestProp || 'reqId'; + var logField = opts.field || 'req_id'; + var fallbackLogger; + + return function * (next) { + var reqId = this.request.get(header) || uuid.v4(); + + this[ctxProp] = reqId; + this.request[requestProp] = reqId; + + var logFields = {}; + logFields[logField] = reqId; + + if (!this.log) { + throw new Error('must use(koaBunyanLogger()) before this middleware'); + } + + this.log = this.log.child(logFields); + + yield *next; // jshint ignore:line + }; +}; + +/* + * Logs requests and responses. + * + * Must use(koaBunyanLogger()) before using this middleware. + * + * Parameters: + * - opts: object with optional properties + * - durationField: name of duration field + * - levelFn: function (status, err) + * - updateLogFields: function (data) + * - updateRequestLogFields: function (requestData) + * - updateResponseLogFields: function (responseData) + * - formatRequestMessage: function (requestData) + * - formatReponseMessage: function (responseData) + */ +module.exports.requestLogger = function (opts) { + opts = opts || {}; + + var levelFn = opts.levelFn || function (status, err) { + if (status >= 500) { + return 'error'; + } else if (status >= 400) { + return 'warn'; + } else { + return 'info'; + } + }; + + var durationField = opts.durationField || 'duration'; + + var formatRequestMessage = opts.formatRequestMessage || function (data) { + return util.format(' <-- %s %s', + this.request.method, this.request.originalUrl); + }; + + var formatResponseMessage = opts.formatResponseMessage || function (data) { + return util.format(' --> %s %s %d %sms', + this.request.method, this.request.originalUrl, + this.status, data[durationField]); + }; + + return function *(next) { + var url = this.url; + + var requestData = { + req: this.request + }; + + requestData = updateFields(this, opts.updateLogFields, requestData); + requestData = updateFields(this, opts.updateRequestLogFields, requestData); + + this.log.info(requestData, formatRequestMessage.call(this, requestData)); + + var startTime = new Date().getTime(); + var err; + + var onResponseFinished = function () { + var responseData = { + req: this.request, + res: this.response + }; + + if (err) { + responseData.err = err; + } + + responseData[durationField] = new Date().getTime() - startTime; + + responseData = updateFields(this, opts.updateLogFields, responseData); + responseData = updateFields(this, opts.updateResponseLogFields, + responseData, err); + + var status = this.status; + + if (err) { + responseData.err = err; + } + + var level = levelFn.call(this, this.status, err); + + this.log[level](responseData, + formatResponseMessage.call(this, responseData)); + + // Remove log object to mitigate accidental leaks + delete this.log; + }; + + try { + yield *next; // jshint ignore:line + } catch (e) { + err = e; + } finally { + // Handle response logging and cleanup when request is finished + // This ensures that the default error handler is done + onFinished(this.response.res, onResponseFinished.bind(this)); + } + + if (err) { + throw err; // rethrow + } + }; +}; + +function updateFields (ctx, func, data, err) { + if (!func) return data; + + try { + if (err) { + return func.call(ctx, data, err) || data; + } else { + return func.call(ctx, data) || data; + } + } catch (e) { + ctx.log.error(e); + return data; + } +} diff --git a/package.json b/package.json new file mode 100644 index 0000000..6cc1678 --- /dev/null +++ b/package.json @@ -0,0 +1,41 @@ +{ + "name": "koa-bunyan-logger", + "version": "0.1.0", + "description": "Koa middleware for logging requests using bunyan", + "main": "index.js", + "engines": { + "node": ">= 0.11.4" + }, + "scripts": { + "test": "make test" + }, + "keywords": [ + "co", + "koa", + "bunyan" + ], + "repository": { + "type": "git", + "url": "https://github.com/pebble/koa-bunyan-logger.git" + }, + "bugs": { + "url": "https://github.com/pebble/koa-bunyan-logger/issues" + }, + "homepage": "https://github.com/pebble/koa-bunyan-logger", + "author": "Jason Lai ", + "license": "MIT", + "dependencies": { + "bunyan": "^1.0", + "node-uuid": "^1.0", + "on-finished": "^2.0" + }, + "devDependencies": { + "co-mocha": "^1.0.0", + "co-supertest": "0.0.7", + "istanbul-harmony": "^0.3.0", + "jshint": "^2.0.0", + "koa": "^0.13.0", + "mocha": "^1.0", + "supertest": "^0.14.0" + } +} diff --git a/test/index.js b/test/index.js new file mode 100644 index 0000000..bdb85df --- /dev/null +++ b/test/index.js @@ -0,0 +1,225 @@ +var koa = require('koa'); +var koaBunyanLogger = require('../'); +var supertest = require('supertest'); +var assert = require('assert'); +var bunyan = require('bunyan'); + +require('co-mocha'); +require('co-supertest'); + +describe('koaBunyanLogger', function () { + var app; + var server; + var ringBuffer; + + beforeEach(function *() { + app = koa(); + app.on('error', function () {}); // suppress errors + + ringBuffer = new bunyan.RingBuffer({limit: 100}); + ringLogger = bunyan.createLogger({ + name: 'test', + streams: [{ + type: 'raw', + stream: ringBuffer + }] + }); + }); + + afterEach(function *() { + if (server) { + server.close(); + } + + app = null; + server = null; + }); + + var request = function () { + if (!server) { + server = app.listen(0); + } + + return supertest(server); + }; + + var record = function (i) { + assert.ok(i >= 0 || i < ringBuffer.records.length); + return ringBuffer.records[i]; + }; + + var helloWorld = function *() { + this.body = 'Hello world'; + }; + + it('creates a default logger', function *() { + app.use(koaBunyanLogger()); + app.use(function *() { + assert.ok(this.log); + this.body = ''; + }); + + yield request().get('/').expect(200).end(); + }); + + it('can log simple requests', function * () { + app.use(koaBunyanLogger(ringLogger)); + + app.use(function *() { + this.log.info('Got request'); + this.body = 'Hello world'; + }); + + yield request().get('/').expect(200).end(); + + assert.equal(record(0).msg, 'Got request'); + }); + + describe('koaBunyanLogger.requestLogger', function () { + var REQ_MESSAGE = / <-- GET \//; + var RES_MESSAGE = / --> GET \/ \d+ \d+ms/; + + beforeEach(function *() { + app.use(koaBunyanLogger(ringLogger)); + }); + + function checkRequestResponse (status) { + assert.equal(ringBuffer.records.length, 2); + assert.ok(record(0).msg.match(REQ_MESSAGE)); + assert.ok(record(1).msg.match(RES_MESSAGE)); + assert.equal(record(1).res.status, status); + } + + it('logs requests', function *() { + app.use(koaBunyanLogger.requestLogger()); + app.use(helloWorld); + + yield request().get('/').expect(200).end(); + + checkRequestResponse(200); + }); + + it('logs 404 errors', function *() { + app.use(koaBunyanLogger.requestLogger()); + + app.use(function *() { + this.throw(404); + }); + + yield request().get('/').expect(404).end(); + + checkRequestResponse(404); + }); + + it('logs 500 errors', function *() { + app.use(koaBunyanLogger.requestLogger()); + + app.use(function *() { + throw new Error('oh no'); + }); + + yield request().get('/').expect(500).end(); + + checkRequestResponse(500); + }); + + it('allows adding fields to request/response log data', function *() { + app.use(koaBunyanLogger.requestLogger({ + updateLogFields: function (fields) { + fields.foo = 'bar'; + fields.baz1 = 'fizz'; + fields.baz2 = 'fuzz'; + }, + + updateRequestLogFields: function (fields) { + fields.addedToReq = 'hello'; + delete fields.baz1; + }, + + updateResponseLogFields: function (fields, err) { + fields.addedToRes = 'world'; + delete fields.baz2; + + if (err) { + fields.error_handled = true; + } + } + })); + + app.use(function *() { + throw new Error('uh oh'); + }); + + yield request().get('/').expect(500).end(); + + checkRequestResponse(500); + + assert.equal(record(0).foo, 'bar'); + assert.equal(record(1).foo, 'bar'); + + assert.equal(typeof record(0).baz1, 'undefined'); + assert.equal(typeof record(1).baz2, 'undefined'); + assert.equal(record(0).baz2, 'fuzz'); + assert.equal(record(1).baz1, 'fizz'); + + assert.equal(record(1).error_handled, true); + }); + + it('logs errors in update methods and then continues', function *() { + app.use(koaBunyanLogger.requestLogger({ + updateResponseLogFields: function (fields) { + throw new Error('clumsy'); + } + })); + + app.use(helloWorld); + + yield request().get('/').expect(200).end(); + + assert.equal(ringBuffer.records.length, 3); + assert.ok(record(0).msg.match(REQ_MESSAGE)); + + // error processing logging + assert.ok(record(1).err); + assert.ok(record(1).msg.match('clumsy')); + + assert.ok(record(2).msg.match(RES_MESSAGE)); + assert.equal(record(2).res.status, 200); + }); + }); + + describe('koaBunyanLogger.requestIdContext', function () { + it('throws an exception if this.log is not available', function *() { + app.use(koaBunyanLogger.requestIdContext()); + yield request().get('/').expect(500).end(); + }); + + it('adds req_id from X-Request-Header to log messages', function *() { + app.use(koaBunyanLogger(ringLogger)); + app.use(koaBunyanLogger.requestIdContext()); + + app.use(function *() { + this.log.info('hello world'); + this.body = ""; + }); + + yield request().get('/').set({'X-Request-Id': '1234'}).expect(200).end(); + + assert.equal(ringBuffer.records[0].req_id, '1234'); + }); + + it('adds generated req_id to log messages if there is no header', function *() { + app.use(koaBunyanLogger(ringLogger)); + app.use(koaBunyanLogger.requestIdContext()); + + app.use(function *() { + this.log.info('hello world'); + this.body = ""; + }); + + yield request().get('/').expect(200).end(); + + assert.equal(ringBuffer.records[0].req_id.length, 36); + }); + }); +});