Skip to content

Commit

Permalink
Improved logging
Browse files Browse the repository at this point in the history 
- `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
  • Loading branch information
@aleclarson
aleclarson committed Sep 13, 2017
1 parent 7421553 commit ce78d73
Show file tree
Hide file tree
Showing 3 changed files with 84 additions and 43 deletions.
52 changes: 47 additions & 5 deletions lib/helper.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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, logger, logLevel) {
var maxLevel = logLevels[logLevel];
if (maxLevel === undefined) {
throw new Error('Unsupported log level: ' + logLevel);
}

var log = Function.prototype;
if (logger === undefined) {
log = function(message, level) {
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(message, logLevel) {
logger[logLevel](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(message, level);
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;

Expand Down
20 changes: 12 additions & 8 deletions lib/pool.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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);
Expand Down Expand Up @@ -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: ' + error.message);
self._log.error(error);
});
clearTimeout(connection.timeout);
}
Expand All @@ -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: ' + error.message);
self._log.error(error);
});
clearTimeout(connection.timeout);
}
Expand Down Expand Up @@ -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;
Expand All @@ -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: ' + error.message);
self._log.error(error);
for(var i=0; i<self.getAvailableLength(); i++) {
if (self._pool.get(i) === this) {
self._pool.delete(i);
Expand Down Expand Up @@ -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: ' + error.message);
self._log.error(error);

if (self._openingConnections === 0) {
self._consecutiveFails++;
Expand Down Expand Up @@ -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();
Expand Down
55 changes: 25 additions & 30 deletions lib/pool_master.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand All @@ -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 || 'info', 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;
Expand Down Expand Up @@ -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);
});
}
}
Expand Down Expand Up @@ -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();
Expand Down Expand Up @@ -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: ' + error.message);
self._log.error(error);
// We have to refetch everything as the server that was serving the feed may
// have died.
if (!self._draining) {
Expand All @@ -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`: ' + error.message);
self._log.error(error);
//TODO Retry
});
}, 1000);
Expand Down Expand Up @@ -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
Expand All @@ -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: ' + error.message);
self._log.error(error);

var timeout;
if (self._consecutiveFails === -1) {
timeout = 0;
Expand Down Expand Up @@ -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);
});
}

Expand Down

0 comments on commit ce78d73

Please sign in to comment.