Merge pull request #381 from adarqui/express-logger-0.0.7

Express & Socket.io logger

src/logger.js

@@ -0,0 +1,204 @@
+/*
+ * Logger module: ability to dynamically turn on/off logging for http requests & socket.io events
+ */
+
+var fs = require('fs'),
+	express = require('express'),
+	winston = require('winston'),
+	util = require('util'),
+	socketio = require('socket.io'),
+	meta = require('./meta.js');
+
+var opts = {
+	/*
+	 * state used by Logger
+	 */
+	express : {
+		app : {},
+		set : 0,
+		ofn : null,
+	},
+	streams : {
+		log : { f : process.stdout },
+	}
+};
+
+
+/* -- Logger -- */
+
+(function(Logger) {
+
+
+	Logger.init = function(app) {
+		opts.express.app = app;
+		/* Open log file stream & initialize express logging if meta.config.logger* variables are set */
+		Logger.setup();
+	}
+
+	Logger.setup = function() {
+		Logger.setup_one('loggerPath', meta.config.loggerPath);
+	}
+
+	Logger.setup_one = function(key,value) {
+		/*
+		 * 1. Open the logger stream: stdout or file
+		 * 2. Re-initialize the express logger hijack
+		 */
+		switch(key) {
+			case 'loggerPath': {
+				Logger.setup_one_log(value);
+				Logger.express_open();
+			}
+			default: return;
+		}
+	}
+
+	Logger.setup_one_log = function(value) {
+		/*
+		 * If logging is currently enabled, create a stream.
+		 * Otherwise, close the current stream
+		 */
+		if(meta.config.loggerStatus > 0 || meta.config.loggerIOStatus) {
+			var stream = Logger.open(value);
+			if(stream) opts.streams.log.f = stream;
+			else opts.streams.log.f = process.stdout;
+		}
+		else {
+			Logger.close(opts.streams.log);
+		}
+	}
+
+	Logger.open = function(value) {
+		/* Open the streams to log to: either a path or stdout */
+		var stream;
+		if(value)
+			stream = fs.createWriteStream(value, {flags: 'a'});
+		else
+			stream = process.stdout;
+		return stream;
+	}
+
+	Logger.close = function(stream) {
+		if(stream.f != process.stdout && stream.f != null) stream.end();
+		stream.f = null;
+	}
+
+	Logger.monitorConfig = function(socket, data) {
+		/*
+		 * This monitor's when a user clicks "save" in the Logger section of the admin panel
+		 */
+		Logger.setup_one(data.key,data.value);
+		Logger.io_close(socket);
+		Logger.io(socket);
+	}
+
+	Logger.express_open = function() {
+		if(opts.express.set != 1) {
+			opts.express.set = 1;
+			opts.express.app.use(Logger.expressLogger);
+		}
+		/*
+		 * Always initialize "ofn" (original function) with the original logger function
+		 */
+		opts.express.ofn = express.logger({stream : opts.streams.log.f});
+	}
+
+	Logger.expressLogger = function(req,res,next) {
+		/*
+		 * The new express.logger
+		 *
+		 * This hijack allows us to turn logger on/off dynamically within express
+		 */
+		if(meta.config.loggerStatus > 0) {
+			return opts.express.ofn(req,res,next);
+		}
+		else {
+			return next()
+		}
+	}
+
+	Logger.prepare_io_string = function(_type, _uid, _args) {
+		/*
+		 * This prepares the output string for intercepted socket.io events
+		 *
+		 * The format is: io: <uid> <event> <args>
+		 */
+		try {
+			return 'io: '+_uid+' '+_type+' '+util.inspect(Array.prototype.slice.call(_args))+'\n';
+		} catch(err) {
+			winston.info("Logger.prepare_io_string: Failed",err)
+			return "error";
+		}
+	}
+
+	Logger.io_close = function(socket) {
+		/*
+		 * Restore all hijacked sockets to their original emit/on functions
+		 */
+		var clients = socket.io.sockets.clients();
+		for(var v in clients) {
+			var client = clients[v];
+
+			if(client.oEmit != client.emit)
+				client.emit = client.oEmit;
+
+			if(client.$oEmit != client.$emit)
+				client.$emit = client.$oEmit;
+		}
+	}
+
+	Logger.io = function(socket) {
+		/*
+		 * Go through all of the currently established sockets & hook their .emit/.on
+		 */
+		if(socket == undefined && socket.io.sockets == undefined) {
+			return;
+		}
+
+		var clients = socket.io.sockets.clients();
+		for(var v in clients) {
+			var client = clients[v];
+			Logger.io_one(client,client.state.user.uid);
+		}
+	}
+
+	Logger.io_one = function(socket,uid) {
+		/*
+		 * This function replaces a socket's .emit/.on functions in order to intercept events
+		 */
+		if(socket != undefined && meta.config.loggerIOStatus > 0) {
+
+			(function() {
+				// courtesy of: http://stackoverflow.com/a/9674248
+				var user = uid
+				if(!user) user = "?"
+				socket.oEmit = socket.emit;
+				var emit = socket.emit;
+				socket.emit = function() {
+					if(opts.streams.log.f != null) {
+						opts.streams.log.f.write(Logger.prepare_io_string("emit",uid,arguments));
+					}
+					try {
+						emit.apply(socket, arguments);
+					} catch(err) {
+						winston.info("Logger.io_one: emit.apply: Failed", err);
+					}
+				};
+				socket.$oEmit = socket.$emit;
+				var $emit = socket.$emit;
+				socket.$emit = function() {
+
+					if(opts.streams.log.f != null) {
+						opts.streams.log.f.write(Logger.prepare_io_string("on",uid,arguments));
+					}
+					try {
+						$emit.apply(socket, arguments);
+					} catch(err) {
+						winston.info("Logger.io_one: $emit.apply: Failed", err);
+					}
+				};
+			})();
+		}
+	}
+
+}(exports));

src/routes/admin.js

@@ -30,7 +30,7 @@ var user = require('./../user.js'),
 		(function () {
 			var routes = [
 				'categories/active', 'categories/disabled', 'users', 'topics', 'settings', 'themes',
-				'twitter', 'facebook', 'gplus', 'redis', 'motd', 'groups',
+				'twitter', 'facebook', 'gplus', 'redis', 'motd', 'groups','logger',
 				'users/latest', 'users/sort-posts', 'users/sort-reputation',
 				'users/search', 'plugins'
 			];
@@ -224,6 +224,10 @@ var user = require('./../user.js'),
 				res.json(200, {});
 			});
 
+			app.get('/logger', function(req, res) {
+				res.json(200, {});
+			});
+
 			app.get('/themes', function (req, res) {
 				res.json(200, {});
 			});
@@ -257,4 +261,4 @@ var user = require('./../user.js'),
 	};
 
 
-}(exports));
+}(exports));

src/webserver.js

@@ -23,7 +23,8 @@ var express = require('express'),
 	plugins = require('./plugins'),
 	nconf = require('nconf'),
 	winston = require('winston'),
-	validator = require('validator');
+	validator = require('validator'),
+	logger = require('./logger.js');
 
 (function (app) {
 	var templates = null,
@@ -81,6 +82,9 @@ var express = require('express'),
 			function(next) {
 				// Pre-router middlewares
 				app.use(express.compress());
+
+				logger.init(app);
+
 				app.use(express.favicon(path.join(__dirname, '../', 'public', 'favicon.ico')));
 				app.use(require('less-middleware')({
 					src: path.join(__dirname, '../', 'public'),
@@ -546,4 +550,4 @@ var express = require('express'),
 }(WebServer));
 
 
-global.server = server;
+global.server = server;

src/websockets.js

@@ -16,6 +16,9 @@ var	cookie = require('cookie'),
 	async = require('async'),
 	RedisStoreLib = require('connect-redis')(express),
 	RDB = require('./redis'),
+	util = require('util'),
+	logger = require('./logger.js'),
+	fs = require('fs')
 	RedisStore = new RedisStoreLib({
 		client: RDB,
 		ttl: 60 * 60 * 24 * 14
@@ -54,6 +57,7 @@ module.exports.init = function(io) {
 		var hs = socket.handshake,
 			sessionID, uid;
 
+
 		// Validate the session, if present
 		socketCookieParser(hs, {}, function(err) {
 			sessionID = socket.handshake.signedCookies["express.sid"];
@@ -64,6 +68,16 @@ module.exports.init = function(io) {
 				userSockets[uid] = userSockets[uid] || [];
 				userSockets[uid].push(socket);
 
+				/* Need to save some state for the logger & maybe some other modules later on */
+				socket.state = {
+					user : {
+						uid : uid
+					}
+				};
+
+				/* If meta.config.loggerIOStatus > 0, logger.io_one will hook into this socket */
+				logger.io_one(socket,uid);
+
 				if (uid) {
 
 					RDB.zadd('users:online', Date.now(), uid, function(err, data) {
@@ -645,6 +659,8 @@ module.exports.init = function(io) {
 				if (!err) socket.emit('api:config.set', {
 					status: 'ok'
 				});
+				/* Another hook, for my (adarqui's) logger module */
+				logger.monitorConfig(this, data);
 			});
 		});