Merge pull request #42 from AnyFetch/bunyan

Using bunyan-logger

Author: Hugo Duroux

lib/handlers/hydrater.js

@@ -7,6 +7,10 @@
  */
 
 var restify = require('restify');
+
+var log = require('../index.js').log;
+
+
 /**
  * This handler receives a document to hydrate on a POST request and processes it.
  *
@@ -15,7 +19,7 @@ var restify = require('restify');
  * @param {Object} server Current server. See implementation in index.js
  * @param {Function} next Callback to call once res has been populated.
  */
-module.exports = function(req, res, server, logger, errLogger, next) {
+module.exports = function(req, res, server, next) {
   if(!req.params.callback) {
     return next(new restify.MissingParameterError('No specified callback'));
   }
@@ -40,10 +44,10 @@ module.exports = function(req, res, server, logger, errLogger, next) {
   var job = server.queue.createJob(task, {priority: task.priority});
   job.save(function(err) {
     if(err) {
-      errLogger("Error while queuing: " + ((task.file_path) ? task.file_path : task.document.id) + "\nError :" + err.toString());
+      log.warn(err, "Error while queuing " + (task.file_path) ? task.file_path : task.document.id);
     }
     else {
-      logger("Queuing: " + ((task.file_path) ? task.file_path : task.document.id));
+      log.info(task, "Queuing task");
     }
   });
 

lib/handlers/status.js

@@ -12,7 +12,7 @@
  * @param {Object} server Current server. See implementation in index.js
  * @param {Function} next Callback to call once res has been populated.
  */
-module.exports = function(req, res, server, logger, next) {
+module.exports = function(req, res, server, next) {
   server.queue.stats(function(err, stats) {
     if(err) {
       return next(err);

lib/helpers/hydrater.js

@@ -14,15 +14,14 @@ var rarity = require('rarity');
 var util = require('util');
 
 var lib = require('../index.js');
+var log = lib.log;
 var HydrationError = lib.HydrationError;
 var logError = require('../utils').logError;
 
 
 
-module.exports = function(hydraterFunction, childs, logger, errLogger) {
-  if(!errLogger) {
-    errLogger = logger;
-  }
+module.exports = function(hydraterFunction, childs) {
+
 
   /**
    * Handle a hydration task:
@@ -36,7 +35,7 @@ module.exports = function(hydraterFunction, childs, logger, errLogger) {
    */
   return function(job, done) {
     var task = job.data;
-    logger("Starting task: " + ((task.file_path) ? task.file_path : task.document.id));
+    log.info(task, "Starting task");
 
     async.waterfall([
       function performHydration(cb) {
@@ -66,10 +65,10 @@ module.exports = function(hydraterFunction, childs, logger, errLogger) {
             cb(err, changes);
           }
           if(stdout !== "") {
-            logger(stdout);
+            log.info({std: "out"}, stdout);
           }
           if(stderr !== "") {
-            errLogger(stderr);
+            log.info({std: "err"}, stderr);
           }
           clearTimeout(timeout);
         };
@@ -139,7 +138,7 @@ module.exports = function(hydraterFunction, childs, logger, errLogger) {
             var changes = {};
             changes.hydration_errored = true;
             changes.hydration_error = "Task took too long.";
-            errLogger('Killing task: ' + ((task.file_path) ? task.file_path : task.document.id));
+            log.warn(task, 'Killing task');
             child.process.kill('SIGTERM');
             setTimeout(function() {
               if(child.process.connected) {
@@ -178,11 +177,11 @@ module.exports = function(hydraterFunction, childs, logger, errLogger) {
       function patchDocument(changes, cb) {
         // Returning null means we won't complete the hydration, and are waiting for something else.
         if(changes === null) {
-          logger("Skipped task: " + ((task.file_path) ? task.file_path : task.document.id));
+          log.info(task, "Skipped task");
           return cb();
         }
 
-        logger("End of task: " + ((task.file_path) ? task.file_path : task.document.id));
+        log.info(task, "End of task");
 
         var apiUrl = url.parse(task.callback, false, true);
 
@@ -198,11 +197,11 @@ module.exports = function(hydraterFunction, childs, logger, errLogger) {
             var extra = JSON.parse(JSON.stringify(task));
             extra.changes = changes;
             logError(err, extra);
-            errLogger("ERR hydrating " + ((task.file_path) ? task.file_path : task.document.id), err.toString());
+            log.warn(err, "Unable to hydrate");
           }
 
           if(res && res.statusCode && res.statusCode !== 204) {
-            errLogger("ERR hydrating: server refused data! Code:" + res.statusCode);
+            log.warn({code: res.statusCode}, "Server refused data!");
           }
 
           cb(null);
@@ -228,7 +227,7 @@ module.exports = function(hydraterFunction, childs, logger, errLogger) {
           var extra = JSON.parse(JSON.stringify(task));
           extra.changes = changes;
           logError(internalErr, extra);
-          errLogger("INTERNAL ERR", internalErr);
+          log.error(internalErr, "Internal error");
         }
         done(err || internalErr, changes);
       });

lib/index.js

@@ -4,8 +4,19 @@ var util = require('util');
 var restify = require('restify');
 var yaqs = require('yaqs');
 var Childs = require('./helpers/Childs');
+var Logger = require("bunyan");
+var restifyBunyanLogger = require('restify-bunyan-logger');
 
 var utils = require('./utils.js');
+
+
+// Create bunyan logger
+var log = new Logger.createLogger({
+  name: process.env.APP_NAME || 'hydrater',
+});
+module.exports.log = log;
+
+
 /**
  * Create a new hydration server.
  * This server will use `config.hydrater_function` as its main function, to turn a file into metadata.
@@ -15,14 +26,12 @@ var utils = require('./utils.js');
  *       hydrater_function, the actual function to use for hydration. This function takes as params the path to the file on the disk, the current data about the document and a callback to use after hydration. First param is the path to the file, second param the document (metadata, binary_document_type). Third param is the callback, send as first argument an error if any, then the new document data.
  *    Optional:
  *       concurrency, max number of simultaneous calls to your hydrater function (default is 1)
- *       logger, function to use for logging. Defaults to console.log
+ *       opbeat, opbeat credentials
  */
 module.exports.createServer = function(config) {
   if(!config.hydrater_function) {
     throw new Error("Specify `hydrater_function`");
   }
-  config.logger = config.logger || console.log;
-  config.errLogger = config.errLogger || console.error;
 
   utils.logError.config = config;
 
@@ -41,14 +50,19 @@ module.exports.createServer = function(config) {
 
   var childs = new Childs(concurrency, tasksPerProcess);
 
-  var hydraterHelper = require('./helpers/hydrater.js')(config.hydrater_function, childs, config.logger, config.errLogger);
+  var hydraterHelper = require('./helpers/hydrater.js')(config.hydrater_function, childs);
+
+  var server = restify.createServer({
+    log: log
+  });
+
+  server.on('after', restifyBunyanLogger());
 
-  var server = restify.createServer();
   // Middleware Goes Here
+  server.use(restify.requestLogger());
   server.use(restify.acceptParser(server.acceptable));
   server.use(restify.queryParser());
   server.use(restify.bodyParser());
-  server.use(require('./middlewares/logger.js'));
 
   server.yaqsClient = yaqs({
     prefix: config.hydraterUrl,
@@ -63,10 +77,10 @@ module.exports.createServer = function(config) {
   function sigtermYaqs() {
     server.yaqsClient.stopAllQueues(function(err) {
       if(err) {
-        config.errLogger(err);
+        log.warn(err, "Unable to stop queues");
       }
       childs.stopAllChilds();
-      config.logger('YAQS has stopped.');
+      log.info('YAQS has stopped.');
       process.exit(0);
     });
   }
@@ -75,10 +89,10 @@ module.exports.createServer = function(config) {
 
   // Load routes
   server.post('/hydrate', function(req, res, next) {
-    hydraterEndpoint(req, res, server, config.logger, config.errLogger, next);
+    hydraterEndpoint(req, res, server, next);
   });
   server.get('/status', function(req, res, next) {
-    statusEndpoint(req, res, server, config.logger, next);
+    statusEndpoint(req, res, server, next);
   });
 
   // Expose the server

lib/middlewares/logger.js

@@ -27,6 +27,9 @@ module.exports.logError = function logError(err, req, extra) {
   if(module.exports.logError.config) {
     extra.hydrater = module.exports.logError.config.hydraterUrl;
   }
+  if(process.env.APP_NAME) {
+    extra.hydrater_name = process.env.APP_NAME;
+  }
 
   if(module.exports.logError.opbeat) {
     var meta = {

lib/utils.js

@@ -18,11 +18,12 @@
   ],
   "dependencies": {
     "async": "^0.9.0",
+    "bunyan": "^1.2.3",
     "opbeat": "^1.0.5",
     "rarity": "^2.1.1",
     "redis": "^0.12.1",
     "restify": "^2.8.3",
-    "restify-logger": "^2.0.1",
+    "restify-bunyan-logger": "^2.0.4",
     "supertest": "^0.14.0",
     "yaqs": "^1.0.3"
   },

package.json

@@ -136,7 +136,7 @@ concurrencies.forEach(function(concurrency) {
         this.timeout(10000);
 
         var config = {
-          hydrater_function: path.resolve(__dirname, '../hydraters/erroed-hydrater.js'),
+          hydrater_function: path.resolve(__dirname, './hydraters/errored-hydrater.js'),
           concurrency: concurrency,
           logger: function() {},
         };

test/cleaning.js

@@ -6,3 +6,10 @@ before(function flushRedis(cb) {
   var client = redis.createClient();
   client.flushdb(cb);
 });
+
+
+before(function removeLogging() {
+  // Disable logging while testing
+  var log = require('../lib/index.js').log;
+  log.info = log.warn = log.error = function() {};
+});