Changing the logging over to bunyan

package.json

@@ -35,7 +35,9 @@
     "url": "https://github.com/elasticsearch/kibana.git"
   },
   "dependencies": {
+    "ansicolors": "^0.3.2",
     "body-parser": "~1.10.1",
+    "bunyan": "^1.2.3",
     "commander": "^2.6.0",
     "compression": "^1.3.0",
     "cookie-parser": "~1.3.3",

src/server/app.js

@@ -1,7 +1,7 @@
 var express = require('express');
 var path = require('path');
 var favicon = require('serve-favicon');
-var logger = require('./lib/logger');
+var requestLogger = require('./lib/requestLogger');
 var cookieParser = require('cookie-parser');
 var bodyParser = require('body-parser');
 var compression = require('compression');
@@ -18,7 +18,7 @@ app.set('view engine', 'jade');
 
 // uncomment after placing your favicon in /public
 //app.use(favicon(__dirname + '/public/favicon.ico'));
-if (!config.quiet) app.use(logger('dev'));
+if (!config.quiet) app.use(requestLogger());
 
 // The proxy must be set up before all the other middleware.
 // TODO: WE might want to move the middleware to each of the individual routes

src/server/index.js

@@ -3,9 +3,9 @@
  */
 
 var app = require('./app');
-var debug = require('debug')('node-server:server');
 var http = require('http');
 var config = require('./config');
+var logger = require('./lib/logger');
 
 
 /**
@@ -33,14 +33,15 @@ function onError(error) {
   // handle specific listen errors with friendly messages
   switch (error.code) {
     case 'EACCES':
-      console.error('Port ' + app.get('port') + ' requires elevated privileges');
+      logger.error({ err: error }, 'Port %s requires elevated privileges', app.get('port'));
       process.exit(1);
       break;
     case 'EADDRINUSE':
-      console.error('Port ' + app.get('port') + ' is already in use');
+      logger.error({ err: error }, 'Port %s is already in use', app.get('port'));
       process.exit(1);
       break;
     default:
+      logger.error({ err: error });
       throw error;
   }
 }
@@ -51,7 +52,7 @@ function onError(error) {
 
 function onListening() {
   var address = server.address();
-  debug('Listening on ' + address.address + ':' + address.port);
+  logger.info('Listening on %s:%d', address.address, address.port);
 }
 
 module.exports = {

src/server/lib/JSONStream.js

@@ -0,0 +1,41 @@
+var _ = require('lodash');
+var Writable = require('stream').Writable;
+var util = require('util');
+
+var levels = {
+  10: 'trace',
+  20: 'debug',
+  30: 'info',
+  40: 'warn',
+  50: 'error',
+  60: 'fatal'
+};
+
+function JSONStream (options) {
+  options = options || {};
+  Writable.call(this, options);
+}
+
+util.inherits(JSONStream, Writable);
+
+JSONStream.prototype._write = function (entry, encoding, callback) {
+
+    entry = JSON.parse(entry.toString('utf8'));
+    var env = process.env.NODE_ENV || 'development';
+
+    var output = {
+      '@timestamp': entry.time,
+      'level': levels[entry.level],
+      'message': entry.msg,
+      'node_env': env,
+      'request': entry.req,
+      'response': entry.res
+    };
+
+    if (entry.error) output.error = entry.err;
+
+    process.stdout.write(JSON.stringify(output) + "\n");
+    callback();
+};
+
+module.exports = JSONStream;

src/server/lib/StdOutStream.js

@@ -0,0 +1,66 @@
+var bunyan = require('bunyan');
+var ansicolors = require('ansicolors');
+var Writable = require('stream').Writable;
+var util = require('util');
+
+var levels = {
+  10: 'trace',
+  20: 'debug',
+  30: 'info',
+  40: 'warn',
+  50: 'error',
+  60: 'fatal'
+};
+
+var colors = {
+  10: 'blue',
+  20: 'green',
+  30: 'cyan',
+  40: 'yellow',
+  50: 'red',
+  60: 'magenta'
+};
+
+var levelColor = function (code) {
+  if (code < 299) {
+    return ansicolors.green(code);
+  }
+  if (code < 399) {
+    return ansicolors.yellow(code)
+  };
+  if (code < 499) {
+    return ansicolors.magenta(code)
+  };
+  return ansicolors.red(code);
+};
+
+function StdOutStream(options) {
+  Writable.call(this, options);
+}
+
+util.inherits(StdOutStream, Writable);
+
+StdOutStream.prototype._write = function (entry, encoding, callback) {
+  entry = JSON.parse(entry.toString('utf8'));
+
+  var crayon = ansicolors[colors[entry.level]];
+  var output = crayon(levels[entry.level].toUpperCase());
+  output += ' ';
+  output += ansicolors.brightBlack(entry.time);
+  output += ' ';
+
+  if (entry.req && entry.res) {
+    output += util.format('%s %s ', entry.req.method, entry.req.url);
+    output += levelColor(entry.res.statusCode);
+    output += ansicolors.brightBlack(util.format(' %dms - %d', entry.res.responseTime, entry.res.contentLength));
+  } else if (entry.msg) {
+    output += entry.msg;
+  }
+  process.stdout.write(output + "\n");
+  if (entry.err) {
+    process.stdout.write(ansicolors.brightRed(entry.err.stack) + "\n");
+  }
+  callback();
+};
+
+module.exports = StdOutStream;

src/server/lib/logger.js

@@ -1,46 +1,27 @@
+var _ = require('lodash');
 var morgan = require('morgan');
 var env = process.env.NODE_ENV || 'development';
-var format = 'dev';
+var bunyan = require('bunyan');
+var StdOutStream = require('./StdOutStream');
+var JSONStream = require('./JSONStream');
+var stream = { stream: new JSONStream() };
 
-if (env !== 'development') {
-  // Content lenght needs to be a number or null
-  morgan.token('content-length', function (req, res) {
-    var contentLength = (res._headers || {})['content-length'];
-    return contentLength && parseInt(contentLength, 10) || 'null';
-  });
-
-
-  // Need to ensure the response time is a number or null
-  var responseTime = morgan['response-time'];
-  morgan['response-time'] = function (req, res) {
-    var value = responseTime(req, res);
-    if (value === '-') return 'null';
-    return value;
-  };
-
-  // Log level
-  morgan.token('level', function (req, res) {
-    return (res.statusCode > 399) ? 'ERROR' : 'INFO';
-  });
-
-  var jsonFormat = '{ ';
-  jsonFormat += '"@timestamp": ":date[iso]", ';
-  jsonFormat += '"status": :status, ';
-  jsonFormat += '"level": ":level", ';
-  jsonFormat += '"name": "kibana", ';
-  jsonFormat += '"request_method": ":method", ';
-  jsonFormat += '"request": ":url", ';
-  jsonFormat += '"remote_addr": ":remote-addr", ';
-  jsonFormat += '"remote_user": ":remote-user", ';
-  jsonFormat += '"http_version": ":http-version", ';
-  jsonFormat += '"content_length": :content-length, ';
-  jsonFormat += '"response_time": :response-time ';
-  jsonFormat += ' }';
-  morgan.format('json', jsonFormat);
-
-  format = 'json';
+if (env === 'development') {
+  stream.stream = new StdOutStream();
 }
 
-module.exports = function () {
-  return morgan(format);
-};
+var logger = module.exports = bunyan.createLogger({
+  name: 'Kibana',
+  streams: [ stream ],
+  serializers: _.assign(bunyan.stdSerializers, {
+    res: function (res) {
+      if (!res) return res;
+      return {
+        statusCode: res.statusCode,
+        responseTime: res.responseTime,
+        contentLength: res.contentLength
+      };
+    }
+  })
+});
+

src/server/lib/requestLogger.js

@@ -0,0 +1,15 @@
+var logger = require('./logger');
+module.exports = function (options) {
+  return function (req, res, next) {
+    var startTime = new Date();
+    var end = res.end;
+    res.end = function (chunk, encoding) {
+      var contentLength = parseInt(res._header['content-length'], 10);
+      res.responseTime = (new Date()).getTime() - startTime.getTime();
+      res.contentLength = isNaN(contentLength) ? 0 : contentLength;
+      end.call(res, chunk, encoding);
+      logger.info({ req: req, res: res }, '%s %s %d - %dms', req.method, req.url, res.statusCode, res.responseTime);
+    };
+    next();
+  };
+};