Merge branch 'metrics' into develop

Conflicts:
	src/node/handler/PadMessageHandler.js

doc/index.md

@@ -1,4 +1,5 @@
 @include documentation
+@include stats
 @include localization
 @include custom_static
 @include api/api

doc/stats.md

@@ -0,0 +1,18 @@
+# Statistics
+Etherpad keeps track of the goings-on inside the edit machinery. If you'd like to have a look at this, just point your browser to `/stats`.
+
+We currently measure:
+
+ - totalUsers (counter)
+ - connects (meter)
+ - disconnects (meter)
+ - pendingEdits (counter)
+ - edits (timer)
+ - failedChangesets (meter)
+ - httpRequests (timer)
+ - http500 (meter)
+ - memoryUsage (gauge)
+
+Under the hood, we are happy to rely on [measured](https://github.com/felixge/node-measured) for all our metrics needs.
+
+To modify or simply access our stats in your plugin, simply `require('ep_etherpad-lite/stats')` which is a `measured.Collection`.

src/node/handler/PadMessageHandler.js

@@ -36,6 +36,7 @@ var accessLogger = log4js.getLogger("access");
 var _ = require('underscore');
 var hooks = require("ep_etherpad-lite/static/js/pluginfw/hooks.js");
 var channels = require("channels");
+var stats = require('../stats');
 
 /**
  * A associative array that saves informations about a session
@@ -50,6 +51,11 @@ var channels = require("channels");
 var sessioninfos = {};
 exports.sessioninfos = sessioninfos;
 
+// Measure total amount of users
+stats.gauge('totalUsers', function() {
+  return Object.keys(socketio.sockets.sockets).length
+})
+
 /**
  * A changeset queue per pad that is processed by handleUserChanges()
  */
@@ -74,7 +80,9 @@ exports.setSocketIO = function(socket_io)
  * @param client the new client
  */
 exports.handleConnect = function(client)
-{  
+{
+  stats.meter('connects').mark();
+
   //Initalize sessioninfos for this new session
   sessioninfos[client.id]={};
 }
@@ -99,12 +107,23 @@ exports.kickSessionsFromPad = function(padID)
  */
 exports.handleDisconnect = function(client)
 {  
+  stats.meter('disconnects').mark();
+  
   //save the padname of this session
   var session = sessioninfos[client.id];
   
   //if this connection was already etablished with a handshake, send a disconnect message to the others
   if(session && session.author)
   {
+    client.get('remoteAddress', function(er, ip) {
+      //Anonymize the IP address if IP logging is disabled
+      if(settings.disableIPlogging) {
+        ip = 'ANONYMOUS';
+      }
+
+      accessLogger.info('[LEAVE] Pad "'+session.padId+'": Author "'+session.author+'" on client '+client.id+' with IP "'+ip+'" left the pad')
+    })
+
     //get the author color out of the db
     authorManager.getAuthorColorId(session.author, function(err, color)
     {
@@ -129,15 +148,6 @@ exports.handleDisconnect = function(client)
     }); 
   }
   
-  client.get('remoteAddress', function(er, ip) {
-    //Anonymize the IP address if IP logging is disabled
-    if(settings.disableIPlogging) {
-      ip = 'ANONYMOUS';
-    }
-
-    accessLogger.info('[LEAVE] Pad "'+session.padId+'": Author "'+session.author+'" on client '+client.id+' with IP "'+ip+'" left the pad')
-  })
-  
   //Delete the sessioninfos entrys of this session
   delete sessioninfos[client.id]; 
 }
@@ -189,6 +199,7 @@ exports.handleMessage = function(client, message)
       if (sessioninfos[client.id].readonly) {
         messageLogger.warn("Dropped message, COLLABROOM for readonly pad");
       } else if (message.data.type == "USER_CHANGES") {
+        stats.counter('pendingEdits').inc()
         padChannels.emit(message.padId, {client: client, message: message});// add to pad queue
       } else if (message.data.type == "USERINFO_UPDATE") {
         handleUserInfoUpdate(client, message);
@@ -558,6 +569,9 @@ function handleUserChanges(data, cb)
   var client = data.client
     , message = data.message
 
+  // This one's no longer pending, as we're gonna process it now
+  stats.counter('pendingEdits').dec()
+
   // Make sure all required fields are present
   if(message.data.baseRev == null)
   {
@@ -584,6 +598,9 @@ function handleUserChanges(data, cb)
   var thisSession = sessioninfos[client.id];
       
   var r, apool, pad;
+
+  // Measure time to process edit
+  var stopWatch = stats.timer('edits').start();
     
   async.series([
     //get the pad
@@ -637,6 +654,7 @@ function handleUserChanges(data, cb)
       {
         // There is an error in this changeset, so just refuse it
         client.json.send({disconnect:"badChangeset"});
+        stats.meter('failedChangesets').mark();
         return callback(new Error("Can't apply USER_CHANGES, because "+e.message));
       }
         
@@ -667,6 +685,7 @@ function handleUserChanges(data, cb)
               changeset = Changeset.follow(c, changeset, false, apool);
             }catch(e){
               client.json.send({disconnect:"badChangeset"});
+              stats.meter('failedChangesets').mark();
               return callback(new Error("Can't apply USER_CHANGES, because "+e.message));
             }
 
@@ -689,6 +708,7 @@ function handleUserChanges(data, cb)
       if (Changeset.oldLen(changeset) != prevText.length) 
       {
         client.json.send({disconnect:"badChangeset"});
+        stats.meter('failedChangesets').mark();
         return callback(new Error("Can't apply USER_CHANGES "+changeset+" with oldLen " + Changeset.oldLen(changeset) + " to document of length " + prevText.length));
       }
         
@@ -712,6 +732,7 @@ function handleUserChanges(data, cb)
     }
   ], function(err)
   {
+    stopWatch.end()
     cb();
     if(err) console.warn(err.stack || err)
   });
@@ -797,7 +818,7 @@ exports.updatePadClients = function(pad, callback)
 }
 
 /**
- * Copied from the Etherpad Source Code. Don't know what this methode does excatly...
+ * Copied from the Etherpad Source Code. Don't know what this method does excatly...
  */
 function _correctMarkersInPad(atext, apool) {
   var text = atext.text;

src/node/hooks/express/errorhandling.js

@@ -1,5 +1,6 @@
 var os = require("os");
 var db = require('../../db/DB');
+var stats = require('ep_etherpad-lite/node/stats')
 
 
 exports.onShutdown = false;
@@ -40,6 +41,7 @@ exports.expressCreateServer = function (hook_name, args, cb) {
     // allowing you to respond however you like
     res.send(500, { error: 'Sorry, something bad happened!' });
     console.error(err.stack? err.stack : err.toString());
+    stats.meter('http500').mark()
   })
 
   //connect graceful shutdown with sigint and uncaughtexception

src/node/hooks/express/specialpages.js

@@ -2,6 +2,10 @@ var path = require('path');
 var eejs = require('ep_etherpad-lite/node/eejs');
 
 exports.expressCreateServer = function (hook_name, args, cb) {
+  // expose current stats
+  args.app.get('/stats', function(req, res) {
+    res.json(require('ep_etherpad-lite/node/stats').toJSON())
+  })
 
   //serve index.html under /
   args.app.get('/', function(req, res)

src/node/hooks/express/webaccess.js

@@ -5,6 +5,7 @@ var settings = require('../../utils/Settings');
 var randomString = require('ep_etherpad-lite/static/js/pad_utils').randomString;
 var hooks = require('ep_etherpad-lite/static/js/pluginfw/hooks');
 var ueberStore = require('../../db/SessionStore');
+var stats = require('ep_etherpad-lite/node/stats')
 
 //checks for basic http auth
 exports.basicAuth = function (req, res, next) {
@@ -91,10 +92,21 @@ exports.basicAuth = function (req, res, next) {
 exports.secret = null;
 
 exports.expressConfigure = function (hook_name, args, cb) {
+  // Measure response time
+  args.app.use(function(req, res, next) {
+    var stopWatch = stats.timer('httpRequests').start();
+    var sendFn = res.send
+    res.send = function() {
+      stopWatch.end()
+      sendFn.apply(res, arguments)
+    }
+    next()
+  })
+
   // If the log level specified in the config file is WARN or ERROR the application server never starts listening to requests as reported in issue #158.
   // Not installing the log4js connect logger when the log level has a higher severity than INFO since it would not log at that level anyway.
   if (!(settings.loglevel === "WARN" || settings.loglevel == "ERROR"))
-    args.app.use(log4js.connectLogger(httpLogger, { level: log4js.levels.DEBUG, format: ':status, :method :url -- :response-timems'}));
+    args.app.use(log4js.connectLogger(httpLogger, { level: log4js.levels.DEBUG, format: ':status, :method :url'}));
 
   /* Do not let express create the session, so that we can retain a
    * reference to it for socket.io to use. Also, set the key (cookie

src/node/server.js

@@ -23,10 +23,15 @@
 
 var log4js = require('log4js')
   , async = require('async')
+  , stats = require('./stats')
   ;
 
 log4js.replaceConsole();
 
+stats.gauge('memoryUsage', function() {
+  return process.memoryUsage().rss
+})
+
 var settings
   , db
   , plugins
@@ -48,7 +53,6 @@ async.waterfall([
     plugins = require("ep_etherpad-lite/static/js/pluginfw/plugins");
     hooks = require("ep_etherpad-lite/static/js/pluginfw/hooks");
     hooks.plugins = plugins;
-
     callback();
   },
   

src/node/stats.js

@@ -0,0 +1,3 @@
+var measured = require('measured')
+
+module.exports = measured.createCollection();

src/package.json

@@ -38,7 +38,8 @@
                       "unorm"                   : "1.0.0",
                       "languages4translatewiki" : "0.1.3",
                       "swagger-node-express"    : "1.2.3",
-                      "channels"                : "0.0.x"
+                      "channels"                : "0.0.x",
+                      "measured"                : "0.1.3"
                      },
   "bin":             { "etherpad-lite": "./node/server.js" },
   "devDependencies": {