Improved logging

- `options.logLevel` can be a string, where its value must be 'debug', 'verbose', 'info', 'warn', or 'error'
- `options.log` can be an object with {debug, verbose, info, warn, error} methods
- When `options.log` is a function, its second argument will be the log level of the given message
- When `options.log` is undefined, the `console` methods are used by default
- When `options.log` is falsy (or `options.silent` is truthy), log messages are silenced
- Some log messages have been tweaked, and log levels attached
- The pool master now emits an 'error' event with the associated `Error` object

Author: aleclarson

lib/helper.js

@@ -3,14 +3,56 @@ var termTypes = protodef.Term.TermType;
 var datumTypes = protodef.Datum.DatumType;
 var net = require('net');
 
+var logLevels = {
+  error: 0,
+  warn: 1,
+  info: 2,
+  verbose: 3,
+  debug: 4,
+};
 
-function createLogger(poolMaster, silent) {
-  return function(message) {
-    if (silent !== true) {
-      console.error(message);
+function createLogger(poolMaster, logLevel, logger) {
+  var maxLevel = logLevels[logLevel];
+  if (maxLevel === undefined) {
+    throw new Error('Unsupported log level: ' + logLevel);
+  }
+
+  var log = Function.prototype;
+  if (logger === undefined) {
+    log = function(level, message) {
+      if (level === 'error') {
+        console.error(message);
+      } else if (level === 'warn') {
+        console.warn(message);
+      } else {
+        console.log(message);
+      }
+    };
+  } else if (logger) {
+    if (typeof logger === 'function') {
+      log = logger;
+    } else if (typeof logger === 'object') {
+      log = function(level, message) {
+        logger[level](message);
+      };
+    } else {
+      throw new TypeError('`options.log` must be an object or function');
     }
-    poolMaster.emit('log', message);
   }
+
+  return {
+    log: function(level, message) {
+      if (logLevels[level] <= maxLevel) {
+        log(level, message);
+        poolMaster.emit('log', message, level);
+      }
+    },
+    error: function(error) {
+      log(error.stack, 'error');
+      poolMaster.emit('log', error.stack, 'error');
+      poolMaster.emit('error', error);
+    }
+  };
 }
 module.exports.createLogger = createLogger;
 

lib/pool.js

@@ -61,7 +61,7 @@ function Pool(r, options) {
     }
   }, 0);
   this.id = Math.floor(Math.random()*100000);
-  this._log('Creating a pool connected to '+this.getAddress());
+  this._log('info', 'Creating a pool connected to: ' + this.getAddress());
 }
 
 util.inherits(Pool, events.EventEmitter);
@@ -152,7 +152,8 @@ Pool.prototype.putConnection = function(connection) {
   else if (self._extraConnections > 0) {
     self._extraConnections--;
     connection.close().error(function(error) {
-      self._log('Fail to properly close a connection. Error:'+JSON.stringify(error));
+      self._log('debug', 'Failed to close a connection properly');
+      self._log.error(error);
     });
     clearTimeout(connection.timeout);
   }
@@ -162,7 +163,8 @@ Pool.prototype.putConnection = function(connection) {
     // Note that because we have available connections here, the pool master has no pending
     // queries.
     connection.close().error(function(error) {
-      self._log('Fail to properly close a connection. Error:'+JSON.stringify(error));
+      self._log('debug', 'Failed to close a connection properly');
+      self._log.error(error);
     });
     clearTimeout(connection.timeout);
   }
@@ -219,7 +221,7 @@ Pool.prototype.createConnection = function() {
     }
     // Need another flag
     else if ((self._slowlyGrowing === true) && (self._slowGrowth === true) && (self._consecutiveFails > 0)) {
-      self._log('Exiting slow growth mode');
+      self._log('info', 'Exiting slow growth mode');
       self._consecutiveFails = 0;
       self._slowGrowth = false;
       self._slowlyGrowing = false;
@@ -231,7 +233,8 @@ Pool.prototype.createConnection = function() {
     connection.on('error', function(error) {
       // We are going to close connection, but we don't want another process to use it before
       // So we remove it from the pool now (if it's inside)
-      self._log('Error emitted by a connection: '+JSON.stringify(error));
+      self._log('debug', 'Error emitted by a connection');
+      self._log.error(error);
       for(var i=0; i<self.getAvailableLength(); i++) {
         if (self._pool.get(i) === this) {
           self._pool.delete(i);
@@ -292,12 +295,13 @@ Pool.prototype.createConnection = function() {
 
     self._slowGrowth = true;
     if (self._slowlyGrowing === false) {
-      self._log('Entering slow growth mode');
+      self._log('warn', 'Entering slow growth mode');
     }
     self._slowlyGrowing = true;
 
     // Log an error
-    self._log('Fail to create a new connection for the connection pool. Error:'+JSON.stringify(error));
+    self._log('debug', 'Failed to create a new connection');
+    self._log.error(error);
 
     if (self._openingConnections === 0) {
       self._consecutiveFails++;
@@ -371,7 +375,7 @@ Pool.prototype.drainLocalhost = function() {
 Pool.prototype.drain = function() {
   var self = this;
   self._draining = true;
-  self._log('Draining the pool connected to '+this.getAddress());
+  self._log('verbose', 'Draining the pool connected to: ' + this.getAddress());
   self.emit('draining');
   var p = new Promise(function(resolve, reject) {
     var connection = self._pool.pop();

lib/pool_master.js

@@ -26,10 +26,6 @@ function PoolMaster(r, options) {
   self._options = options;
   self._options.buffer = options.buffer || 50;
   self._options.max = options.max || 1000;
-  self._log = helper.createLogger(self, options.silent || false);
-  if (typeof options.log == 'function') {
-    self.on('log', options.log);
-  }
   self._draining = false;
   self._numConnections = 0;
   self._numAvailableConnections = 0;
@@ -39,6 +35,10 @@ function PoolMaster(r, options) {
   self._timeoutError = options.timeoutError || 1000; // How long should we wait before recreating a connection that failed?
   self._maxExponent = options.maxExponent || 6; // Maximum timeout is 2^maxExponent*timeoutError
 
+  var logger = helper.createLogger(self, options.logLevel || 'debug', options.silent ? null : options.log);
+  self._log = logger.log;
+  self._log.error = logger.error;
+
   //TODO
   //self._usingPool = true; // If we have used the pool
   self._seed = 0;
@@ -211,13 +211,12 @@ PoolMaster.prototype.handleAllServersResponse = function(servers) {
   for(var i=0;i<self._pools[UNKNOWN_POOLS].length; i++) {
     // These pools does not match any server returned by RethinkDB.
     var pool = self._pools[UNKNOWN_POOLS].splice(i, 1)[0];
-    self._log('Removing pool connected to: '+pool.getAddress())
+    self._log('verbose', 'Removing pool connected to: ' + pool.getAddress());
     pool.drain().then(function() {
       pool.removeAllListeners();
     }).error(function(error) {
-      self._log('Pool connected to: '+self._pools[UNKNOWN_POOLS][i].getAddress()+' could not be properly drained.')
-      self._log(error.message);
-      self._log(error.stack);
+      self._log('debug', 'Pool failed to drain properly: ' + pool.getAddress());
+      self._log.error(error);
     });
   }
 }
@@ -264,13 +263,12 @@ PoolMaster.prototype.createPool = function(server) {
 PoolMaster.prototype.deletePool = function(key) {
   var self = this;
   var pool = self._pools[key];
-  self._log('Removing pool connected to: '+pool.getAddress())
+  self._log('verbose', 'Removing pool connected to: ' + pool.getAddress());
   pool.drain().then(function() {
     pool.removeAllListeners();
   }).error(function(error) {
-    self._log('Pool connected to: '+self._pools[key].getAddress()+' could not be properly drained.')
-    self._log(error.message);
-    self._log(error.stack);
+    self._log('debug', 'Pool failed to drain properly: ' + pool.getAddress());
+    self._log.error(error);
   });
   delete self._pools[key];
   self.resetBufferParameters();
@@ -307,9 +305,10 @@ PoolMaster.prototype.fetchServers = function(useSeeds) {
     self._feed = feed;
     var initializing = true;
     var servers = [];
-    feed.each(function(err, change) {
-      if (err) {
-        self._log('The changefeed on server_status returned an error: '+err.toString());
+    feed.each(function(error, change) {
+      if (error) {
+        self._log('debug', 'The changefeed on `server_status` returned an error');
+        self._log.error(error);
         // We have to refetch everything as the server that was serving the feed may
         // have died.
         if (!self._draining) {
@@ -329,7 +328,8 @@ PoolMaster.prototype.fetchServers = function(useSeeds) {
             self._r.db('rethinkdb').table('server_status').run({cursor: false}).then(function(servers) {
               self.handleAllServersResponse(servers);
             }).error(function(error) {
-              self._log('Fail to retrieve a second copy of server_status');
+              self._log('debug', 'Failed to fetch another copy of `server_status`');
+              self._log.error(error);
               //TODO Retry
             });
           }, 1000);
@@ -359,24 +359,21 @@ PoolMaster.prototype.fetchServers = function(useSeeds) {
               found = true;
 
               (function (pool) {
-                self._log('Removing pool connected to: '+pool.getAddress())
+                self._log('verbose', 'Removing pool connected to: ' + pool.getAddress());
                 var pool = self._pools[UNKNOWN_POOLS].splice(i, 1)[0];
                 pool.drain().then(function() {
                   pool.removeAllListeners();
                 }).error(function(error) {
-                  if (self._options.silent !== true) {
-                    self._log('Pool connected to: '+pool.getAddress()+' could not be properly drained.')
-                    self._log(error.message);
-                    self._log(error.stack);
-                  }
+                  self._log('debug', 'Pool failed to drain properly: ' + pool.getAddress());
+                  self._log.error(error);
                 });
               })(self._pools[UNKNOWN_POOLS][i]);
               break;
             }
           }
         }
         if (found === false) {
-          self._log('A server was removed but no pool for this server exists...')
+          self._log('verbose', 'Removed server has no associated pool');
         }
       }
       // We ignore this change since this it doesn't affect whether the server
@@ -385,8 +382,9 @@ PoolMaster.prototype.fetchServers = function(useSeeds) {
     });
     return null;
   }).error(function(error) {
-    self._log('Could not retrieve the data from server_status: '+JSON.stringify(error));
-    
+    self._log('debug', 'Failed to get data from `server_status` feed');
+    self._log.error(error);
+
     var timeout;
     if (self._consecutiveFails === -1) {
       timeout = 0;
@@ -526,11 +524,8 @@ PoolMaster.prototype.drain = function() {
       pools[i].removeAllListeners();
     }
   }).error(function(error) {
-    if (self._options.silent !== true) {
-      self._log('Failed to drain all the pools:');
-      self._log(error.message);
-      self._log(error.stack);
-    }
+    self._log('debug', 'Failed to drain all the pools');
+    self._log.error(error);
   });
 }