Add request/response logging middleware

[bkeepers]

This PR is part of a series of changes to improve logging support in Probot: #320

This is an alternative to #270 and #314. It has the following advantages:

• It sets X-Request-ID in the response, which is a value either provided by the client in the request or generated. This allows tracing of errors by request by searching for req.headers.x-request-id and the value of the request id.
• Adds req.log which will include X-Request-ID in all log messages
• Like Added request logging #270, it logs all request headers so they can be searched later
• Like Add http-request-logging with morgan #314, it includes a nice format for normal response logging

TODO:

• After Add context.log to add event context to each log message #321 merges, update this to use lib/logging.js and wrap the logger on req.log so it can be called as req.log(foo) or req.log.trace(foo)
• Move custom req and res serializers into lib/serializers.js
• Remove some of the noise when LOG_LEVEL=info
• Round response time to 2 decimal places

[bkeepers]

Current log format in development:

20:00:55.030Z  INFO Probot: GET /ping 200 - 0.502784 ms (id=1fb3e537-90fb-4a29-ab00-d8f10faee694, duration=0.502784)
  HTTP/1.1 200 OK
  x-powered-by: Express
  x-request-id: 1fb3e537-90fb-4a29-ab00-d8f10faee694

[JasonEtco]

Suuuuuper nitpicky, but there's an extra space here 😎

[JasonEtco]

This is unrelated to your current work, but we should update this link.

[bkeepers]

Ok, calling this good enough. I'd love a set of eyes. Here's the current default info output of an app starting up and receiving a webhook:

Setting LOG_LEVEL=debug is more verbose and includes req/res headers and more details:

$ LOG_LEVEL=debug npm start

> probot-reminders@1.0.0 start /Users/bkeepers/projects/probot/reminders
> probot run ./index.js

21:27:45.921Z  INFO probot: GET /ping 200 - 2.87 ms (id=36cbef31-0b4b-4ebb-a6a2-059f6c89eb30)
21:27:45.923Z DEBUG probot:  (id=36cbef31-0b4b-4ebb-a6a2-059f6c89eb30, req.remoteAddress=::ffff:127.0.0.1, req.remotePort=49767, res.duration=2.87)
  GET /ping HTTP/1.1
  x-real-ip: 174.217.46.106
  x-forwarded-for: 174.217.46.106
  host: bkeepers.localtunnel.me
  x-forwarded-proto: https
  x-nginx-proxy: true
  connection: close
  --
  HTTP/1.1 200 OK
  x-powered-by: Express
  x-request-id: 36cbef31-0b4b-4ebb-a6a2-059f6c89eb30
Listening on https://bkeepers.localtunnel.me
21:27:46.188Z DEBUG probot: Scheduling interval (repository=bkeepers/test, delay=0, interval=900000)
21:28:06.758Z  INFO probot: Webhook received
  event: {
    "id": "b7007560-d21b-11e7-807b-96ed96b38a84",
    "event": "issue_comment.created",
    "repository": "robotland/test",
    "installation": 13055
  }
21:28:06.759Z  INFO probot: POST / 200 - 92.06 ms (id=b7007560-d21b-11e7-807b-96ed96b38a84)
21:28:06.760Z DEBUG probot:  (id=b7007560-d21b-11e7-807b-96ed96b38a84, req.remoteAddress=::ffff:127.0.0.1, req.remotePort=49766, res.duration=92.06)
  POST / HTTP/1.1
  x-real-ip: 192.30.252.42
  x-forwarded-for: 192.30.252.42
  host: bkeepers.localtunnel.me
  x-forwarded-proto: https
  x-nginx-proxy: true
  connection: close
  content-length: 9795
  accept: */*
  user-agent: GitHub-Hookshot/e20df6f
  x-github-event: issue_comment
  x-github-delivery: b7007560-d21b-11e7-807b-96ed96b38a84
  content-type: application/json
  x-hub-signature: sha1=3fc9ea44aec0b8dab4b9365f7d10fd4c3f79d6dc
  --
  HTTP/1.1 200 OK
  x-powered-by: Express
  x-request-id: b7007560-d21b-11e7-807b-96ed96b38a84
  content-type: application/json

[bkeepers]

I'm not sure why the PR status is not updating, because it is passing.