From 51d7dda5a726fd612eb71a85094217006faddacd Mon Sep 17 00:00:00 2001 From: Andrew Darqui Date: Tue, 1 Oct 2013 22:38:13 -0400 Subject: [PATCH 1/7] added basic logger using config.json --- src/webserver.js | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/src/webserver.js b/src/webserver.js index a134a4ac58..7212d3d235 100644 --- a/src/webserver.js +++ b/src/webserver.js @@ -79,6 +79,9 @@ var express = require('express'), function(next) { // Pre-router middlewares app.use(express.compress()); + if(nconf.get("express:logger") == true) { + app.use(express.logger()); + } app.use(express.favicon(path.join(__dirname, '../', 'public', 'favicon.ico'))); app.use(require('less-middleware')({ src: path.join(__dirname, '../', 'public'), @@ -544,4 +547,4 @@ var express = require('express'), }(WebServer)); -global.server = server; \ No newline at end of file +global.server = server; From aacd42f4bc79eb676578dccfa5f84dbf06c3174e Mon Sep 17 00:00:00 2001 From: Andrew Darqui Date: Tue, 1 Oct 2013 22:38:33 -0400 Subject: [PATCH 2/7] ignore vim .swp files from git --- .gitignore | 1 + 1 file changed, 1 insertion(+) diff --git a/.gitignore b/.gitignore index b5bda3e26f..40ea2a6a86 100644 --- a/.gitignore +++ b/.gitignore @@ -17,3 +17,4 @@ public/themes/* *.sublime-workspace plugins/* .project +*.swp From 55d84d0f9bef4f5bac44423de7b7e991c00d56fb Mon Sep 17 00:00:00 2001 From: Andrew Darqui Date: Wed, 2 Oct 2013 00:25:46 -0400 Subject: [PATCH 3/7] basic logger functionality added - accessible via http://nodebb/admin/logger --- public/src/templates.js | 2 +- public/templates/admin/header.tpl | 3 ++- public/templates/admin/logger.tpl | 33 +++++++++++++++++++++++++++++++ public/templates/config.json | 3 ++- src/routes/admin.js | 8 ++++++-- src/webserver.js | 11 +++++++++-- 6 files changed, 53 insertions(+), 7 deletions(-) create mode 100644 public/templates/admin/logger.tpl diff --git a/public/src/templates.js b/public/src/templates.js index 82c0438b05..a47ac42e73 100644 --- a/public/src/templates.js +++ b/public/src/templates.js @@ -306,4 +306,4 @@ module: { exports: {} } -} : module) \ No newline at end of file +} : module) diff --git a/public/templates/admin/header.tpl b/public/templates/admin/header.tpl index 72469a018a..8a5ca43dae 100644 --- a/public/templates/admin/header.tpl +++ b/public/templates/admin/header.tpl @@ -84,6 +84,7 @@
  • Plugins
  • Settings
  • Redis
    • +
  • Logger
  • MOTD
  • Social Authentication
    • @@ -107,4 +108,4 @@ -
    \ No newline at end of file +
    diff --git a/public/templates/admin/logger.tpl b/public/templates/admin/logger.tpl new file mode 100644 index 0000000000..c8abacff9b --- /dev/null +++ b/public/templates/admin/logger.tpl @@ -0,0 +1,33 @@ +

    Logger

    +
    + +

    Logger Settings

    +
    + +

    + By enabling the check box, you will receive http logs to standard output. If you specify a path, logs will then be saved to a file instead. +

    +
    + +
    + + +
    + + +
    +
    +
    + + + + diff --git a/public/templates/config.json b/public/templates/config.json index f97cd5ce26..636ef7f0b3 100644 --- a/public/templates/config.json +++ b/public/templates/config.json @@ -11,6 +11,7 @@ "^admin/settings.*": "admin/settings", "admin/twitter.*": "admin/twitter", "admin/facebook.*": "admin/facebook", + "admin/logger.*": "admin/logger", "admin/gplus.*": "admin/gplus", "admin/motd/?$": "admin/motd", "admin/groups/?$": "admin/groups", @@ -41,4 +42,4 @@ "force_refresh": { "logout": true } -} \ No newline at end of file +} diff --git a/src/routes/admin.js b/src/routes/admin.js index b6db9cf925..a26a1be15c 100644 --- a/src/routes/admin.js +++ b/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)); \ No newline at end of file +}(exports)); diff --git a/src/webserver.js b/src/webserver.js index 7212d3d235..3911c59c16 100644 --- a/src/webserver.js +++ b/src/webserver.js @@ -79,9 +79,16 @@ var express = require('express'), function(next) { // Pre-router middlewares app.use(express.compress()); - if(nconf.get("express:logger") == true) { - app.use(express.logger()); + + if(nconf.get("express:logger") == true || meta.config.loggerStatus > 0) { + var loggerObj = {}; + if(meta.config.loggerPath) { + loggerObj.stream = fs.createWriteStream(meta.config.loggerPath, {flags: 'a'}); + meta.config.loggerStream = loggerObj.stream + } + app.use(express.logger(loggerObj)); } + app.use(express.favicon(path.join(__dirname, '../', 'public', 'favicon.ico'))); app.use(require('less-middleware')({ src: path.join(__dirname, '../', 'public'), From 9007f9de9e9b601cc606263f59208f6a5dc1810e Mon Sep 17 00:00:00 2001 From: Andrew Darqui Date: Wed, 2 Oct 2013 01:15:45 -0400 Subject: [PATCH 4/7] added socket.io logging which can be dynamically enabled/disabled via the /admin/logger panel --- public/templates/admin/logger.tpl | 17 +++++++- src/webserver.js | 8 +++- src/websockets.js | 65 +++++++++++++++++++++++++++++++ 3 files changed, 88 insertions(+), 2 deletions(-) diff --git a/public/templates/admin/logger.tpl b/public/templates/admin/logger.tpl index c8abacff9b..e47d330f95 100644 --- a/public/templates/admin/logger.tpl +++ b/public/templates/admin/logger.tpl @@ -17,7 +17,22 @@
    -
    + +
    +
    +
    + + +
    + + + + +
    +
    +
    diff --git a/src/webserver.js b/src/webserver.js index 3911c59c16..b11c01e7c8 100644 --- a/src/webserver.js +++ b/src/webserver.js @@ -81,11 +81,17 @@ var express = require('express'), app.use(express.compress()); if(nconf.get("express:logger") == true || meta.config.loggerStatus > 0) { + /* + * HTTP request logging is enabled + */ var loggerObj = {}; if(meta.config.loggerPath) { loggerObj.stream = fs.createWriteStream(meta.config.loggerPath, {flags: 'a'}); - meta.config.loggerStream = loggerObj.stream } + else { + loggerObj.stream = process.stdout; + } + meta.config.loggerStream = loggerObj.stream; app.use(express.logger(loggerObj)); } diff --git a/src/websockets.js b/src/websockets.js index 27cdb0ef8a..04d2b96c93 100644 --- a/src/websockets.js +++ b/src/websockets.js @@ -16,6 +16,8 @@ var cookie = require('cookie'), async = require('async'), RedisStoreLib = require('connect-redis')(express), RDB = require('./redis'), + util = require('util'), + fs = require('fs') RedisStore = new RedisStoreLib({ client: RDB, ttl: 60 * 60 * 24 * 14 @@ -54,6 +56,26 @@ module.exports.init = function(io) { var hs = socket.handshake, sessionID, uid; + + +/* +(function() { + var emit = socket.emit; + socket.emit = function() { + console.log('***','emit', Array.prototype.slice.call(arguments)); + emit.apply(socket, arguments); + }; + var $emit = socket.$emit; + socket.$emit = function() { + console.log('***','on',Array.prototype.slice.call(arguments)); + $emit.apply(socket, arguments); + }; +})(); +*/ + + + + // Validate the session, if present socketCookieParser(hs, {}, function(err) { sessionID = socket.handshake.signedCookies["express.sid"]; @@ -64,6 +86,49 @@ module.exports.init = function(io) { userSockets[uid] = userSockets[uid] || []; userSockets[uid].push(socket); + + if(meta.config.loggerIOStatus > 0) { + var _prepare_loggerIO_string = function(_type, _uid, _args) { + try { + return 'io: '+_uid+' '+_type+' '+util.inspect(Array.prototype.slice.call(_args))+'\n'; + } catch(err) { + winston.err(err) + } + } + + + /* + * socket.io emit/on logging is enabled + */ + if(!meta.config.loggerIOStream) { + var loggerObj = {}; + if(meta.config.loggerIOPath) { + loggerObj.stream = fs.createWriteStream(meta.config.loggerIOPath, {flags: 'a'}); + } + else { + loggerObj.stream = process.stdout; + } + meta.config.loggerIOStream = loggerObj.stream; + } + + + (function() { + // courtesy of: http://stackoverflow.com/a/9674248 + var user = uid + if(!user) user = "?" + var emit = socket.emit; + socket.emit = function() { + meta.config.loggerIOStream.write(_prepare_loggerIO_string("emit",uid,arguments)); + emit.apply(socket, arguments); + }; + var $emit = socket.$emit; + socket.$emit = function() { + meta.config.loggerIOStream.write(_prepare_loggerIO_string("on",uid,arguments)); + $emit.apply(socket, arguments); + }; + })(); + } + if (uid) { RDB.zadd('users:online', Date.now(), uid, function(err, data) { From f48687528e1f9b6b08a153eb7fc28d8af35c2534 Mon Sep 17 00:00:00 2001 From: Andrew Darqui Date: Wed, 2 Oct 2013 01:28:37 -0400 Subject: [PATCH 5/7] fixed up logger.tpl a little. Added a basic 'collision detection' for the loggerPath and loggeIOPath filenames. --- public/templates/admin/logger.tpl | 8 +++++--- src/websockets.js | 23 +++-------------------- 2 files changed, 8 insertions(+), 23 deletions(-) diff --git a/public/templates/admin/logger.tpl b/public/templates/admin/logger.tpl index e47d330f95..969647f820 100644 --- a/public/templates/admin/logger.tpl +++ b/public/templates/admin/logger.tpl @@ -5,16 +5,17 @@

    - By enabling the check box, you will receive http logs to standard output. If you specify a path, logs will then be saved to a file instead. + By enabling the check boxes, you will receive logs to standard output. If you specify a path, logs will then be saved to a file instead. HTTP logging is useful for collecting statistics about who and when people access your forum. Socket.io logging, in combination with redis-cli monitor, can be very helpful for learning NodeBB's internals.



    +
    @@ -23,9 +24,10 @@

    +
    diff --git a/src/websockets.js b/src/websockets.js index 04d2b96c93..6f2841650a 100644 --- a/src/websockets.js +++ b/src/websockets.js @@ -57,25 +57,6 @@ module.exports.init = function(io) { sessionID, uid; - -/* -(function() { - var emit = socket.emit; - socket.emit = function() { - console.log('***','emit', Array.prototype.slice.call(arguments)); - emit.apply(socket, arguments); - }; - var $emit = socket.$emit; - socket.$emit = function() { - console.log('***','on',Array.prototype.slice.call(arguments)); - $emit.apply(socket, arguments); - }; -})(); -*/ - - - - // Validate the session, if present socketCookieParser(hs, {}, function(err) { sessionID = socket.handshake.signedCookies["express.sid"]; @@ -103,7 +84,9 @@ module.exports.init = function(io) { if(!meta.config.loggerIOStream) { var loggerObj = {}; if(meta.config.loggerIOPath) { - loggerObj.stream = fs.createWriteStream(meta.config.loggerIOPath, {flags: 'a'}); + var actual_path = meta.config.loggerIOPath; + if(meta.config.loggerIOPath == meta.config.loggerPath) { actual_path = actual_path + ".io.log"; } + loggerObj.stream = fs.createWriteStream(actual_path, {flags: 'a'}); } else { loggerObj.stream = process.stdout; From a3f6fee41f20d57a32b04fb6872f73d6e5534ce8 Mon Sep 17 00:00:00 2001 From: Andrew Darqui Date: Fri, 4 Oct 2013 01:46:50 -0400 Subject: [PATCH 6/7] refactored the logger completely. --- public/templates/admin/logger.tpl | 19 ++- src/logger.js | 198 ++++++++++++++++++++++++++++++ src/webserver.js | 18 +-- src/websockets.js | 52 ++------ 4 files changed, 220 insertions(+), 67 deletions(-) create mode 100644 src/logger.js diff --git a/public/templates/admin/logger.tpl b/public/templates/admin/logger.tpl index 969647f820..83f569010b 100644 --- a/public/templates/admin/logger.tpl +++ b/public/templates/admin/logger.tpl @@ -5,9 +5,13 @@

    - By enabling the check boxes, you will receive logs to standard output. If you specify a path, logs will then be saved to a file instead. HTTP logging is useful for collecting statistics about who and when people access your forum. Socket.io logging, in combination with redis-cli monitor, can be very helpful for learning NodeBB's internals. + By enabling the check boxes, you will receive logs to your terminal. If you specify a path, logs will then be saved to a file instead. HTTP logging is useful for collecting statistics about who, when, and what people access on your forum. In addition to logging HTTP requests, we can also log socket.io events. Socket.io logging, in combination with redis-cli monitor, can be very helpful for learning NodeBB's internals.


    +

    + Simply check/uncheck the logging settings to enable or disable logging on the fly. No restart needed. +

    +
    @@ -17,24 +21,19 @@

    - - -
    -
    -
    -

    - - + + +


    - +
    diff --git a/src/logger.js b/src/logger.js new file mode 100644 index 0000000000..37f5aab35b --- /dev/null +++ b/src/logger.js @@ -0,0 +1,198 @@ +/* + * 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 }, + } +}; + +(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(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: + */ + 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) { + 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)); diff --git a/src/webserver.js b/src/webserver.js index b11c01e7c8..f06f602b12 100644 --- a/src/webserver.js +++ b/src/webserver.js @@ -24,7 +24,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, @@ -80,20 +81,7 @@ var express = require('express'), // Pre-router middlewares app.use(express.compress()); - if(nconf.get("express:logger") == true || meta.config.loggerStatus > 0) { - /* - * HTTP request logging is enabled - */ - var loggerObj = {}; - if(meta.config.loggerPath) { - loggerObj.stream = fs.createWriteStream(meta.config.loggerPath, {flags: 'a'}); - } - else { - loggerObj.stream = process.stdout; - } - meta.config.loggerStream = loggerObj.stream; - app.use(express.logger(loggerObj)); - } + logger.init(app); app.use(express.favicon(path.join(__dirname, '../', 'public', 'favicon.ico'))); app.use(require('less-middleware')({ diff --git a/src/websockets.js b/src/websockets.js index 6f2841650a..76336dd99c 100644 --- a/src/websockets.js +++ b/src/websockets.js @@ -17,6 +17,7 @@ var cookie = require('cookie'), RedisStoreLib = require('connect-redis')(express), RDB = require('./redis'), util = require('util'), + logger = require('./logger.js'), fs = require('fs') RedisStore = new RedisStoreLib({ client: RDB, @@ -67,50 +68,15 @@ module.exports.init = function(io) { userSockets[uid] = userSockets[uid] || []; userSockets[uid].push(socket); - - if(meta.config.loggerIOStatus > 0) { - var _prepare_loggerIO_string = function(_type, _uid, _args) { - try { - return 'io: '+_uid+' '+_type+' '+util.inspect(Array.prototype.slice.call(_args))+'\n'; - } catch(err) { - winston.err(err) - } + /* Need to save some state for the logger & maybe some other modules later on */ + socket.state = { + user : { + uid : uid } + }; - - /* - * socket.io emit/on logging is enabled - */ - if(!meta.config.loggerIOStream) { - var loggerObj = {}; - if(meta.config.loggerIOPath) { - var actual_path = meta.config.loggerIOPath; - if(meta.config.loggerIOPath == meta.config.loggerPath) { actual_path = actual_path + ".io.log"; } - loggerObj.stream = fs.createWriteStream(actual_path, {flags: 'a'}); - } - else { - loggerObj.stream = process.stdout; - } - meta.config.loggerIOStream = loggerObj.stream; - } - - - (function() { - // courtesy of: http://stackoverflow.com/a/9674248 - var user = uid - if(!user) user = "?" - var emit = socket.emit; - socket.emit = function() { - meta.config.loggerIOStream.write(_prepare_loggerIO_string("emit",uid,arguments)); - emit.apply(socket, arguments); - }; - var $emit = socket.$emit; - socket.$emit = function() { - meta.config.loggerIOStream.write(_prepare_loggerIO_string("on",uid,arguments)); - $emit.apply(socket, arguments); - }; - })(); - } + /* If meta.config.loggerIOStatus > 0, logger.io_one will hook into this socket */ + logger.io_one(socket,uid); if (uid) { @@ -679,6 +645,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); }); }); From 7c1f7e7a23afa6867494ea334078118560088228 Mon Sep 17 00:00:00 2001 From: Andrew Darqui Date: Fri, 4 Oct 2013 01:54:23 -0400 Subject: [PATCH 7/7] just some text formatting fixes --- src/logger.js | 16 +++++++++++----- 1 file changed, 11 insertions(+), 5 deletions(-) diff --git a/src/logger.js b/src/logger.js index 37f5aab35b..06133ae1ca 100644 --- a/src/logger.js +++ b/src/logger.js @@ -23,6 +23,9 @@ var opts = { } }; + +/* -- Logger -- */ + (function(Logger) { @@ -51,7 +54,10 @@ var opts = { } 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; @@ -60,18 +66,15 @@ var opts = { 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; } @@ -145,6 +148,9 @@ var opts = { } Logger.io = function(socket) { + /* + * Go through all of the currently established sockets & hook their .emit/.on + */ if(socket == undefined && socket.io.sockets == undefined) { return; } @@ -186,7 +192,7 @@ var opts = { opts.streams.log.f.write(Logger.prepare_io_string("on",uid,arguments)); } try { - $emit.apply(socket, arguments); + $emit.apply(socket, arguments); } catch(err) { winston.info("Logger.io_one: $emit.apply: Failed", err); }