Add request/response logging middleware

lib/index.js

@@ -26,7 +26,7 @@ module.exports = (options = {}) => {
     cert: options.cert,
     debug: process.env.LOG_LEVEL === 'trace'
   })
-  const server = createServer(webhook)
+  const server = createServer({webhook, logger})
 
   // Log all received webhooks
   webhook.on('*', event => {

lib/logger.js

@@ -6,5 +6,5 @@ module.exports = bunyan.createLogger({
   name: 'Probot',
   level: process.env.LOG_LEVEL || 'debug',
   stream: bunyanFormat({outputMode: process.env.LOG_FORMAT || 'short'}),
-  serializers
+  serializers: Object.assign(bunyan.stdSerializers, serializers)
 })

lib/middleware/logging.js

@@ -0,0 +1,32 @@
+// Borrowed from https://github.com/vvo/bunyan-request
+// Copyright (c) Christian Tellnes <christian@tellnes.no>
+var uuid = require('uuid')
+
+module.exports = function logRequest ({logger}) {
+  return function (req, res, next) {
+    // Use X-Request-ID from request if it is set, otherwise generate a uuid
+    req.id = req.headers['x-request-id'] || uuid.v4()
+    res.setHeader('x-request-id', req.id)
+
+    // Make a logger available on the request
+    req.log = logger.child({id: req.id}, true)
+
+    // Request started
+    req.log.debug({req}, `${req.method} ${req.url}`)
+
+    // Start the request timer
+    const time = process.hrtime()
+
+    res.on('finish', () => {
+      // Calculate how long the request took
+      const [seconds, nanoseconds] = process.hrtime(time)
+      const duration = (seconds * 1e3 + nanoseconds * 1e-6).toFixed(2)
+
+      const message = `${req.method} ${req.url} ${res.statusCode} - ${duration} ms`
+
+      req.log.info({req, res, duration}, message)
+    })
+
+    next()
+  }
+}

lib/serializers.js

@@ -13,5 +13,36 @@ module.exports = {
       }
     }
   },
-  installation: installation => installation.account.login
+  installation: installation => installation.account.login,
+
+  // Same as buyan's standard serializers, but adds `body` to allow debugging
+  // request parameters.
+  // https://github.com/trentm/node-bunyan/blob/fe31b83e42d9c7f784e83fdcc528a7c76e0dacae/lib/bunyan.js#L1087-L1103
+  req (req) {
+    if (!req || !req.connection) {
+      return req
+    }
+    return {
+      method: req.method,
+      url: req.url,
+      body: req.body,
+      headers: req.headers,
+      remoteAddress: req.connection.remoteAddress,
+      remotePort: req.connection.remotePort
+    }
+  },
+
+  // Same as buyan's standard serializers, but gets headers as an object
+  //  instead of a string.
+  // https://github.com/trentm/node-bunyan/blob/fe31b83e42d9c7f784e83fdcc528a7c76e0dacae/lib/bunyan.js#L1105-L1113
+  res (res) {
+    if (!res || !res.statusCode) {
+      return res
+    }
+
+    return {
+      statusCode: res.statusCode,
+      headers: res.getHeaders()
+    }
+  }
 }

lib/server.js

@@ -1,10 +1,12 @@
 const express = require('express')
 const path = require('path')
+const logging = require('./middleware/logging')
 
-module.exports = function (webhook) {
+module.exports = function ({webhook, logger}) {
   const app = express()
 
   app.use('/probot/static/', express.static(path.join(__dirname, '..', 'static')))
+  app.use(logging({logger}))
   app.use(webhook)
   app.set('view engine', 'hbs')
   app.set('views', path.join(__dirname, '..', 'views'))

package.json

@@ -30,7 +30,7 @@
     "cache-manager": "^2.4.0",
     "commander": "^2.11.0",
     "dotenv": "~4.0.0",
-    "express": "^4.15.4",
+    "express": "^4.16.2",
     "github": "^12.0.3",
     "github-webhook-handler": "github:rvagg/github-webhook-handler#v0.6.1",
     "hbs": "^4.0.1",

test/middleware/logging.test.js

@@ -0,0 +1,81 @@
+const request = require('supertest')
+const express = require('express')
+const bunyan = require('bunyan')
+const serializers = require('../../lib/serializers')
+const logging = require('../../lib/middleware/logging')
+
+describe('logging', () => {
+  let server, logger, output
+
+  beforeEach(() => {
+    server = express()
+    output = []
+    logger = bunyan({
+      name: 'test',
+      level: 'trace',
+      streams: [{type: 'raw', stream: {write: msg => output.push(msg)}}],
+      serializers
+    })
+
+    server.use(express.json())
+    server.use(logging({logger}))
+    server.get('/', (req, res) => {
+      res.set('X-Test-Header', 'testing')
+      res.send('OK')
+    })
+    server.post('/', (req, res) => res.send('OK'))
+  })
+
+  test('logs requests and responses', () => {
+    return request(server).get('/').expect(200).expect(res => {
+      var requestLog = output[0]
+      var responseLog = output[1]
+
+      // logs id with request and response
+      expect(requestLog.id).toBeTruthy()
+      expect(responseLog.id).toEqual(requestLog.id)
+      expect(res.headers['x-request-id']).toEqual(requestLog.id)
+
+      expect(requestLog).toEqual(expect.objectContaining({
+        msg: 'GET /',
+        req: expect.objectContaining({
+          method: 'GET',
+          url: '/',
+          remoteAddress: '::ffff:127.0.0.1',
+          headers: expect.objectContaining({
+            'accept-encoding': 'gzip, deflate',
+            'user-agent': expect.stringMatching(/^node-superagent/),
+            'connection': 'close'
+          })
+        })
+      }))
+
+      expect(responseLog).toEqual(expect.objectContaining({
+        id: requestLog.id,
+        msg: expect.stringMatching(/^GET \/ 200 - \d+.\d\d+ ms$/),
+        duration: expect.anything(),
+        res: expect.objectContaining({
+          headers: expect.objectContaining({
+            'x-request-id': requestLog.id,
+            'x-test-header': 'testing'
+          })
+        })
+      }))
+
+      expect(responseLog.duration).toMatch(/^\d\.\d\d$/)
+    })
+  })
+
+  test('uses supplied X-Request-ID', () => {
+    return request(server).get('/').set('X-Request-ID', '42').expect(200).expect(res => {
+      expect(res.header['x-request-id']).toEqual('42')
+      expect(output[0].id).toEqual('42')
+    })
+  })
+
+  test('request body', () => {
+    return request(server).post('/').send({foo: 'bar'}).expect(200).expect(res => {
+      expect(output[0].req.body).toEqual({foo: 'bar'})
+    })
+  })
+})

test/server.test.js

@@ -1,13 +1,15 @@
 const request = require('supertest')
 const createServer = require('../lib/server')
+const bunyan = require('bunyan')
+const logger = bunyan.createLogger({name: 'test', streams: []})
 
 describe('server', function () {
   let server
   let webhook
 
   beforeEach(() => {
     webhook = jest.fn((req, res, next) => next())
-    server = createServer(webhook)
+    server = createServer({webhook, logger})
 
     // Error handler to avoid printing logs
     server.use(function (err, req, res, next) {