From 0591d97c896d57e52f72f1dd7aed43cceda63023 Mon Sep 17 00:00:00 2001 From: Mikeal Rogers Date: Wed, 14 Sep 2011 14:56:54 -0700 Subject: [PATCH] Adding metrics. --- node/handler/PadMessageHandler.js | 36 +++++- node/handler/SocketIORouter.js | 2 +- node/metrics.js | 29 +++++ node/server.js | 177 ++++++++++++++++++------------ node/utils/Settings.js | 5 +- package.json | 3 +- 6 files changed, 178 insertions(+), 74 deletions(-) create mode 100644 node/metrics.js diff --git a/node/handler/PadMessageHandler.js b/node/handler/PadMessageHandler.js index f89f4934cd7..ff5c086fed5 100644 --- a/node/handler/PadMessageHandler.js +++ b/node/handler/PadMessageHandler.js @@ -29,6 +29,7 @@ var securityManager = require("../db/SecurityManager"); var log4js = require('log4js'); var os = require("os"); var messageLogger = log4js.getLogger("message"); +var metrics = require('../metrics') /** * A associative array that translates a session to a pad @@ -151,6 +152,16 @@ exports.handleDisconnect = function(client) * @param client the client that send this message * @param message the message from the client */ + +var timers = + { CLIENT_READY: metrics.timer('message.CLIENT_READY') + , notify_CLIENT_READY: metrics.timer('message.notify.CLIENT_READY') + , USER_CHANGES: metrics.timer('message.USER_CHANGES') + , USERINFO_UPDATE: metrics.timer('message.USERINFO_UPDATE') + , CHAT_MESSAGE: metrics.timer('message.CHAT_MESSAGE') + , CLIENT_MESSAGE: metrics.timer('message.CLIENT_MESSAGE') + } + exports.handleMessage = function(client, message) { if(message == null) @@ -164,6 +175,13 @@ exports.handleMessage = function(client, message) return; } + client.starttime = new Date(); + if (message.type === 'CLIENT_READY') { + client.timer = timers['CLIENT_READY'] + } else if (message.data && message.data.type && timers[message.data.type]){ + client.timer = timers[message.data.type] + } + //Check what type of message we get and delegate to the other methodes if(message.type == "CLIENT_READY") { @@ -190,6 +208,7 @@ exports.handleMessage = function(client, message) { handleSuggestUserName(client, message); } + //if the message type is unkown, throw an exception else { @@ -252,7 +271,7 @@ function handleChatMessage(client, message) { socketio.sockets.sockets[pad2sessions[padId][i]].json.send(msg); } - + client.timer.update((new Date()) - client.starttime); callback(); } ], function(err) @@ -292,6 +311,7 @@ function handleSuggestUserName(client, message) break; } } + client.timer.update((new Date()) - client.starttime) } /** @@ -334,6 +354,7 @@ function handleUserInfoUpdate(client, message) socketio.sockets.sockets[pad2sessions[padId][i]].json.send(message); } } + client.timer.update((new Date()) - client.starttime) } /** @@ -401,6 +422,7 @@ function handleUserChanges(client, message) { console.warn("Can't apply USER_CHANGES "+changeset+", cause it faild checkRep"); client.json.send({disconnect:"badChangeset"}); + client.timer.update((new Date()) - client.starttime) return; } @@ -447,6 +469,7 @@ function handleUserChanges(client, message) { console.warn("Can't apply USER_CHANGES "+changeset+" with oldLen " + Changeset.oldLen(changeset) + " to document of length " + prevText.length); client.json.send({disconnect:"badChangeset"}); + client.timer.update((new Date()) - client.starttime) callback(); return; } @@ -466,6 +489,7 @@ function handleUserChanges(client, message) } exports.updatePadClients(pad, callback); + client.timer.update((new Date()) - client.starttime) } ], function(err) { @@ -813,6 +837,8 @@ function handleClientReady(client, message) sessioninfos[client.id].rev = pad.getHeadRevisionNumber(); sessioninfos[client.id].author = author; + client.timer.update((new Date()) - client.starttime) + //prepare the notification for the other users on the pad, that this user joined var messageToTheOtherUsers = { "type": "COLLABROOM", @@ -833,6 +859,8 @@ function handleClientReady(client, message) messageToTheOtherUsers.data.userInfo.name = authorName; } + var starttime = new Date() + //Run trough all sessions of this pad async.forEach(pad2sessions[message.padId], function(sessionID, callback) { @@ -883,11 +911,15 @@ function handleClientReady(client, message) } } }; + client.json.send(messageToNotifyTheClientAboutTheOthers); } } ], callback); - }, callback); + }, function () { + callback() + timers['notify_CLIENT_READY'].update((new Date()) - starttime) + }); } ],function(err) { diff --git a/node/handler/SocketIORouter.js b/node/handler/SocketIORouter.js index 2d8f4f44d3a..c30d3283cbc 100644 --- a/node/handler/SocketIORouter.js +++ b/node/handler/SocketIORouter.js @@ -127,7 +127,7 @@ exports.setSocketIO = function(_socket) } //drop message else - { + { messageLogger.warn("Droped message cause of bad permissions:" + stringifyWithoutPassword(message)); } } diff --git a/node/metrics.js b/node/metrics.js new file mode 100644 index 00000000000..ac620546e64 --- /dev/null +++ b/node/metrics.js @@ -0,0 +1,29 @@ +var metrics = require('metrics') + ; + +var server = new metrics.Server() + +exports.timer = function (ns) { + var x = new metrics.Timer() + server.addMetric(ns, x) + return x +} + +exports.histogram = function (ns) { + var x = metrics.Histogram.createExponentialDecayHistogram(5000) + server.addMetric(ns, x) + return x +} + +exports.listen = function () { + server.listen.apply(server, arguments) +} + +var port = 9091 + +if (process.argv.indexOf('metrics') !== -1) { + if (parseInt(process.argv[process.argv.indexOf('metrics') + 1])) { + port = parseInt(process.argv[process.argv.indexOf('metrics') + 1]) + } + exports.listen(port) +} \ No newline at end of file diff --git a/node/server.js b/node/server.js index 74d14093de3..3cf4fe888f3 100644 --- a/node/server.js +++ b/node/server.js @@ -1,6 +1,6 @@ /** - * This module is started with bin/run.sh. It sets up a Express HTTP and a Socket.IO Server. - * Static file Requests are answered directly from this module, Socket.IO messages are passed + * This module is started with bin/run.sh. It sets up a Express HTTP and a Socket.IO Server. + * Static file Requests are answered directly from this module, Socket.IO messages are passed * to MessageHandler and minfied requests are passed to minified. */ @@ -54,13 +54,13 @@ var argv = nopt({ var version = ""; try { - var ref = fs.readFileSync("../.git/HEAD", "utf-8"); - var refPath = "../.git/" + ref.substring(5, ref.indexOf("\n")); + var ref = fs.readFileSync(path.join(__dirname, "../.git/HEAD"), "utf-8"); + var refPath = path.join(__dirname, "../.git/") + ref.substring(5, ref.indexOf("\n")); version = fs.readFileSync(refPath, "utf-8"); version = version.substring(0, 7); console.log("Your Etherpad Lite git version is " + version); } -catch(e) +catch(e) { console.warn("Can't get git version for server header\n" + e.message) } @@ -79,14 +79,54 @@ async.waterfall([ //initalize the database function (callback) { - db.init(callback); + db.init(function () { + if (db.db.db.wrappedDB.emit) { + var metrics = require('./metrics') + , initTimer = metrics.timer('db.init') + , getTimer = metrics.timer('db.get') + , setTimer = metrics.timer('db.set') + , removeTimer = metrics.timer('db.remove') + , bulkTimer = metrics.timer('db.bulk') + , initHist = metrics.histogram('db.ops.init') + , getHist = metrics.histogram('db.ops.get') + , setHist = metrics.histogram('db.ops.set') + , removeHist = metrics.histogram('db.ops.remove') + , bulkHist = metrics.histogram('db.ops.bulk') + , bulkCountHist = metrics.histogram('db.ops.bulk.count') + ; + db.db.db.wrappedDB.on('metric.init', function (duration) { + initTimer.update(duration) + initHist.update(1, (new Date()).getTime()) + }) + db.db.db.wrappedDB.on('metric.get', function (duration) { + getTimer.update(duration) + getHist.update(1, (new Date()).getTime()) + }) + db.db.db.wrappedDB.on('metric.set', function (duration) { + setTimer.update(duration) + setHist.update(1, (new Date()).getTime()) + }) + db.db.db.wrappedDB.on('metric.remove', function (duration) { + removeTimer.update(duration) + removeHist.update(1, (new Date()).getTime()) + }) + db.db.db.wrappedDB.on('metric.bulk', function (duration) { + bulkTimer.update(duration) + bulkHist.update(1, (new Date()).getTime()) + }) + db.db.db.wrappedDB.on('metric.bulk.count', function (num) { + bulkCountHist.update(num, (new Date()).getTime()) + }) + } + callback.apply(this, arguments) + }); }, //initalize the http server function (callback) { //create server var app = express.createServer(); - + //load modules that needs a initalized db readOnlyManager = require("./db/ReadOnlyManager"); exporthtml = require("./utils/ExportHtml"); @@ -96,31 +136,31 @@ async.waterfall([ padManager = require('./db/PadManager'); securityManager = require('./db/SecurityManager'); socketIORouter = require("./handler/SocketIORouter"); - - //install logging + + //install logging var httpLogger = log4js.getLogger("http"); - app.configure(function() + app.configure(function() { app.use(log4js.connectLogger(httpLogger, { level: log4js.levels.INFO, format: ':status, :method :url'})); app.use(express.cookieParser()); }); - + //serve static files app.get('/static/*', function(req, res) - { + { res.header("Server", serverName); var filePath = path.normalize(__dirname + "/.." + req.url.replace(/\.\./g, '').split("?")[0]); res.sendfile(filePath, { maxAge: exports.maxAge }); }); - + //serve minified files app.get('/minified/:id', function(req, res, next) - { + { res.header("Server", serverName); - + var id = req.params.id; - + if(id == "pad.js" || id == "timeslider.js") { minify.minifyJS(req,res,id); @@ -130,14 +170,14 @@ async.waterfall([ next(); } }); - + //checks for padAccess function hasPadAccess(req, res, callback) { securityManager.checkAccess(req.params.pad, req.cookies.sessionid, req.cookies.token, req.cookies.password, function(err, accessObj) { if(err) throw err; - + //there is access, continue if(accessObj.accessStatus == "grant") { @@ -150,16 +190,16 @@ async.waterfall([ } }); } - + //serve read only pad app.get('/ro/:id', function(req, res) - { + { res.header("Server", serverName); - + var html; var padId; var pad; - + async.series([ //translate the read only pad to a padId function(callback) @@ -167,10 +207,10 @@ async.waterfall([ readOnlyManager.getPadId(req.params.id, function(err, _padId) { padId = _padId; - - //we need that to tell hasPadAcess about the pad - req.params.pad = padId; - + + //we need that to tell hasPadAcess about the pad + req.params.pad = padId; + callback(err); }); }, @@ -183,7 +223,7 @@ async.waterfall([ callback("notfound"); return; } - + hasPadAccess(req, res, function() { //render the html document @@ -199,29 +239,29 @@ async.waterfall([ //throw any unexpected error if(err && err != "notfound") throw err; - + if(err == "notfound") res.send('404 - Not Found', 404); else res.send(html); }); }); - + //serve pad.html under /p app.get('/p/:pad', function(req, res, next) - { + { //ensure the padname is valid and the url doesn't end with a / if(!padManager.isValidPadId(req.params.pad) || /\/$/.test(req.url)) { res.send('Such a padname is forbidden', 404); return; } - + res.header("Server", serverName); var filePath = path.normalize(__dirname + "/../static/pad.html"); res.sendfile(filePath, { maxAge: exports.maxAge }); }); - + //serve timeslider.html under /p/$padname/timeslider app.get('/p/:pad/timeslider', function(req, res, next) { @@ -231,12 +271,12 @@ async.waterfall([ res.send('Such a padname is forbidden', 404); return; } - + res.header("Server", serverName); var filePath = path.normalize(__dirname + "/../static/timeslider.html"); res.sendfile(filePath, { maxAge: exports.maxAge }); }); - + //serve timeslider.html under /p/$padname/timeslider app.get('/p/:pad/export/:type', function(req, res, next) { @@ -246,7 +286,7 @@ async.waterfall([ res.send('Such a padname is forbidden', 404); return; } - + var types = ["pdf", "doc", "txt", "html", "odt"]; //send a 404 if we don't support this filetype if(types.indexOf(req.params.type) == -1) @@ -254,23 +294,23 @@ async.waterfall([ next(); return; } - + //if abiword is disabled, and this is a format we only support with abiword, output a message if(settings.abiword == null && req.params.type != "html" && req.params.type != "txt" ) { res.send("Abiword is not enabled at this Etherpad Lite instance. Set the path to Abiword in settings.json to enable this feature"); return; } - + res.header("Access-Control-Allow-Origin", "*"); res.header("Server", serverName); - + hasPadAccess(req, res, function() { exportHandler.doExport(req, res, req.params.pad, req.params.type); }); }); - + //handle import requests app.post('/p/:pad/import', function(req, res, next) { @@ -280,70 +320,70 @@ async.waterfall([ res.send('Such a padname is forbidden', 404); return; } - + //if abiword is disabled, skip handling this request if(settings.abiword == null) { next(); - return; + return; } - + res.header("Server", serverName); - + hasPadAccess(req, res, function() { importHandler.doImport(req, res, req.params.pad); }); }); - + var apiLogger = log4js.getLogger("API"); - + //This is a api call, collect all post informations and pass it to the apiHandler app.get('/api/1/:func', function(req, res) { res.header("Server", serverName); res.header("Content-Type", "application/json; charset=utf-8"); - + apiLogger.info("REQUEST, " + req.params.func + ", " + JSON.stringify(req.query)); - + //wrap the send function so we can log the response res._send = res.send; res.send = function(response) { response = JSON.stringify(response); apiLogger.info("RESPONSE, " + req.params.func + ", " + response); - + //is this a jsonp call, if yes, add the function call if(req.query.jsonp) response = req.query.jsonp + "(" + response + ")"; - + res._send(response); } - + //call the api handler apiHandler.handle(req.params.func, req.query, req, res); }); - + //The Etherpad client side sends information about how a disconnect happen app.post('/ep/pad/connection-diagnostic-info', function(req, res) { - new formidable.IncomingForm().parse(req, function(err, fields, files) - { + new formidable.IncomingForm().parse(req, function(err, fields, files) + { console.log("DIAGNOSTIC-INFO: " + fields.diagnosticInfo); res.end("OK"); }); }); - + //The Etherpad client side sends information about client side javscript errors app.post('/jserror', function(req, res) { - new formidable.IncomingForm().parse(req, function(err, fields, files) - { + new formidable.IncomingForm().parse(req, function(err, fields, files) + { console.error("CLIENT SIDE JAVASCRIPT ERROR: " + fields.errorInfo); res.end("OK"); }); }); - + //serve index.html under / app.get('/', function(req, res) { @@ -351,7 +391,7 @@ async.waterfall([ var filePath = path.normalize(__dirname + "/../static/index.html"); res.sendfile(filePath, { maxAge: exports.maxAge }); }); - + //serve robots.txt app.get('/robots.txt', function(req, res) { @@ -359,7 +399,7 @@ async.waterfall([ var filePath = path.normalize(__dirname + "/../static/robots.txt"); res.sendfile(filePath, { maxAge: exports.maxAge }); }); - + //serve favicon.ico app.get('/favicon.ico', function(req, res) { @@ -439,24 +479,24 @@ async.waterfall([ process.on('SIGINT', gracefulShutdown); } + process.on('SIGHUP', gracefulShutdown); process.on('SIGTERM', gracefulShutdown); - process.on('uncaughtException', gracefulShutdown) //init socket.io and redirect all requests to the MessageHandler var io = socketio.listen(app); - + //this is only a workaround to ensure it works with all browers behind a proxy //we should remove this when the new socket.io version is more stable io.set('transports', ['xhr-polling']); - + var socketIOLogger = log4js.getLogger("socket.io"); io.set('logger', { debug: function (str) { socketIOLogger.debug(str); - }, + }, info: function (str) { socketIOLogger.info(str); @@ -470,19 +510,20 @@ async.waterfall([ socketIOLogger.error(str); }, }); - + + //minify socket.io javascript if(settings.minify) io.enable('browser client minification'); - + var padMessageHandler = require("./handler/PadMessageHandler"); var timesliderMessageHandler = require("./handler/TimesliderMessageHandler"); - + //Initalize the Socket.IO Router socketIORouter.setSocketIO(io); socketIORouter.addComponent("pad", padMessageHandler); socketIORouter.addComponent("timeslider", timesliderMessageHandler); - - callback(null); + + callback(null); } ]); diff --git a/node/utils/Settings.js b/node/utils/Settings.js index 1d855a53d6d..10d37344a8b 100644 --- a/node/utils/Settings.js +++ b/node/utils/Settings.js @@ -20,6 +20,7 @@ */ var fs = require("fs"); +var path = require("path"); /** * The IP ep-lite should listen to @@ -37,7 +38,7 @@ exports.dbType = "dirty"; /** * This setting is passed with dbType to ueberDB to set up the database */ -exports.dbSettings = { "filename" : "../var/dirty.db" }; +exports.dbSettings = { "filename" : path.join(__dirname, "../var/dirty.db") }; /** * The default Text of a new pad */ @@ -58,7 +59,7 @@ exports.abiword = null; exports.loglevel = "INFO"; //read the settings sync -var settingsStr = fs.readFileSync("../settings.json").toString(); +var settingsStr = fs.readFileSync(path.join(__dirname, "../../settings.json")).toString(); //remove all comments settingsStr = settingsStr.replace(/\*([^*]|[\r\n]|(\*+([^*/]|[\r\n])))*\*+/gm,"").replace(/#.*/g,"").replace(/\/\/.*/g,""); diff --git a/package.json b/package.json index 9d72a7d8fa3..1414223fb31 100644 --- a/package.json +++ b/package.json @@ -20,7 +20,8 @@ "uglify-js" : "1.0.7", "gzip" : "0.1.0", "formidable" : "1.0.2", - "log4js" : "0.3.8" + "log4js" : "0.3.8", + "metrics" : "0.1.4" }, "version" : "1.0.0" }