diff --git a/DEVELOPMENT.md b/DEVELOPMENT.md
index 680eeef9..00032082 100644
--- a/DEVELOPMENT.md
+++ b/DEVELOPMENT.md
@@ -104,3 +104,22 @@ Testing
Tests are written with mocha; and integration tests with selenium. Wherever possible, core functionality should be backed up with tests. See INSTALLATION.md for instructions on running tests (with or without selenium, and with or without a headless X-server).
Common functions for starting up the server and building the selenium webdriver are found in ``test/common.js``. Selenium webdriver uses a "promise" syntax to handle asynchronous code (see http://code.google.com/p/selenium/wiki/WebDriverJs for full documentation).
+
+Analytics/logging taxonomy
+--------------------------
+
+The ``lib/logging.js`` library contains a logger to use both for informational/debug logging and for structured analytics. Log with ``logger.debug()``, ``loger.info()``, ``loger.warn()``, ``loger.error()``, or ``logger.analytics``. Debug messages only show up in the console during development. Info and above are logged to a file in production (where ``NODE_ENV="production"``). Only use these messages for information that is pertinent during development (at ``debug`` level), or pertinent to sysadmins figuring out what's going on with a live server (mostly ``error`` and ``warn``, though occasionally ``info`` helps). If in doubt, use ``debug``.
+
+``analytics`` logging logs to a separate file in JSON format -- use these judiciously, with an intention of logging only those events that are helpful in doing post-hoc analysis on how the site is being used, not real-time analysis of what the server is up to or development. ``logger.analytics`` takes two arguments: ``(key, opts)``. ``key`` is a term from the taxonomy below, and ``opts`` is an object containing data to log. Several higher-level properties are accepted, including ``req``, ``res``, ``user``, ``session``, ``event``, and ``socket`` -- these will each have the relevant bits peeled off for logging.
+
+The following taxonomy describes what things we do analytics for, used with the ``key`` parameter to ``logger.analytics``. Use these terms if possible, and document new terms if you add them.
+
+ - ``server``: Server lifecycle events (starting, stopping, etc). Include high-level statistical data about the current state of the server (e.g. counts for the various models in the database).
+ - ``users``: User lifecycle events (sign up, login, logout, etc).
+ - ``events``: Happenings pertinent to ``event`` models. Creation, starting, stopping, joining, leaving, chatting, etc.
+ - ``sessions``: Happenings pertinent to ``session`` models that are part of events. Starting, stopping, setting URLs. Due to its complexity, we make a particular effort to log details around hangout farming.
+ - ``permalinks``: Happenings pertinent to sessions which are permalinks. Same type of stuff.
+ - ``route``: Default web request logging, done via connect middleware.
+ - ``farming``: Events pertinent to the farming of hangout URLs.
+
+Include reasonable detail for each logged event, with an eye toward automated parsing and stats rather than human consumption.
diff --git a/lib/hangout-farming.js b/lib/hangout-farming.js
index 6ac07dff..017d8242 100644
--- a/lib/hangout-farming.js
+++ b/lib/hangout-farming.js
@@ -93,12 +93,12 @@ exports.init = function(app, db, options) {
if(!err && "hangoutLink" in event) {
// push it into redis for safekeeping.
db.redis.lpush("global:hangout_urls", event.hangoutLink, function(err, num) {
- logger.info("logged new hangout url: " + event.hangoutLink + "; total: " + num);
// purely for convenience of clicking to farm another url.
res.send("urls available: " + num + "
CLICK ME");
// update the tracking number.
numHangoutUrlsAvailable = num;
+ logger.analytics("farming", {action: "create", url: event.hangoutLink, total: num});
// TODO test whether it's okay to do this.
// now delete the event so it doesn't clutter up the user's calendar.
@@ -133,11 +133,11 @@ exports.getNextHangoutUrl = function(callback) {
// just hit redis directly here, with an rpop.
curDb.redis.rpop("global:hangout_urls", function(err, url) {
- logger.debug("returning hangout url: " + url + " (err: " + err + ")");
if (!err) {
numHangoutUrlsAvailable--;
}
callback && callback(err, url);
+ logger.analytics("farming", {action: "consume", url: url, total: numHangoutUrlsAvailable});
});
}
@@ -146,6 +146,7 @@ exports.getNextHangoutUrl = function(callback) {
// join a new hangout in rapid succession)
exports.reuseUrl = function(url, callback) {
curDb.redis.rpush("global:hangout_urls", url, function(err, num) {
+ logger.analytics("farming", {action: "recycle", url: url});
logger.debug("re-added a url that was no longer needed: " + url);
if (!err) {
numHangoutUrlsAvailable = num;
diff --git a/lib/logging.js b/lib/logging.js
index c82f333c..676a88d1 100644
--- a/lib/logging.js
+++ b/lib/logging.js
@@ -3,63 +3,116 @@ var winston = require('winston'),
winstonMail = require('winston-mail'),
_ = require('underscore');
+var logger = new (winston.Logger)();
+if (process.env.NODE_ENV === "production") {
+ logger.add(winston.transports.File, {
+ filename: __dirname + '/../logs/server.log',
+ level: 'info'
+ });
+ if (conf.EMAIL_LOG_RECIPIENTS && conf.EMAIL_LOG_RECIPIENTS.length > 0) {
+ logger.add(winstonMail.Mail, {
+ level: 'error',
+ to: conf.EMAIL_LOG_RECIPIENTS.join(","),
+ host: conf.EMAIL_LOG_HOST || "localhost",
+ port: conf.EMAIL_LOG_PORT || (conf.EMAIL_LOG_SECURE ? 587 : 25),
+ secure: conf.EMAIL_LOG_SECURE || false,
+ username: conf.EMAIL_LOG_USERNAME || undefined,
+ password: conf.EMAIL_LOG_PASSWORD || undefined,
+ silent: false,
+ handleExceptions: true
+ });
+ } else {
+ logger.warn("No EMAIL_LOG_RECIPIENTS specified; skipping email logger transport.")
+ }
+} else if (process.env.NODE_ENV === "testing") {
+ logger.add(winston.transports.Console, {level: 'crit'});
+ logger.cli();
+} else {
+ logger.add(winston.transports.Console, {level: 'debug'});
+ logger.cli();
+}
+
+//
+// A second logger for analytics -- log to file, in a more tightly
+// controlled format.
+//
+var analyticsLogger = new (winston.Logger)();
+analyticsLogger.add(winston.transports.File, {
+ filename: __dirname + "/../logs/analytics.log",
+ level: 'info',
+ timestamp: true,
+ maxsize: 10000000 // 10 MB
+});
+logger.analytics = function(key, opts) {
+ var args = {};
+ opts = opts || {};
+ if (opts.req) {
+ args.url = opts.req.originalUrl || opts.req.url;
+ args.method = opts.req.method;
+ args['user-agent'] = opts.req.headers['user-agent'];
+ args.referrer = opts.req.headers['referer'] || opts.req.headers['referrer'];
+ args['remote-addr'] = opts.req.ip;
+ if (opts.req.user) {
+ args.userId = opts.req.user.id;
+ }
+ delete opts.req;
+ }
+ if (opts.res) {
+ args.status = opts.res.statusCode;
+ if (opts.res._errorReason) {
+ args.errorReason = opts.res._errorReason;
+ }
+ delete opts.res;
+ }
+ if (opts.socket) {
+ if (opts.socket.user) {
+ args.userId = opts.socket.user.id;
+ }
+ delete opts.socket;
+ }
+ if (opts.user) {
+ args.userId = opts.user.id;
+ delete opts.user;
+ }
+ if (opts.event) {
+ args.eventId = opts.event.id;
+ delete opts.event;
+ }
+ if (opts.session) {
+ args.sessionId = opts.session.id;
+ delete opts.session;
+ }
+ _.extend(args, opts);
+ analyticsLogger.info(key, args)
+ // Assume we always want to shadow analytics logs with debug logs.
+ logger.debug(key, args)
+};
+
module.exports = {
getLogger: function() {
- var logger = new (winston.Logger)();
- if (process.env.NODE_ENV === "production") {
- logger.add(winston.transports.File, {
- filename: __dirname + '/../logs/server.log',
- level: 'info'
- });
- if (conf.EMAIL_LOG_RECIPIENTS && conf.EMAIL_LOG_RECIPIENTS.length > 0) {
- logger.add(winstonMail.Mail, {
- level: 'error',
- to: conf.EMAIL_LOG_RECIPIENTS.join(","),
- host: conf.EMAIL_LOG_HOST || "localhost",
- port: conf.EMAIL_LOG_PORT || (conf.EMAIL_LOG_SECURE ? 587 : 25),
- secure: conf.EMAIL_LOG_SECURE || false,
- username: conf.EMAIL_LOG_USERNAME || undefined,
- password: conf.EMAIL_LOG_PASSWORD || undefined,
- silent: false
+ return logger;
+ },
+ // Connect middleware for logging, for analytics.
+ analyticsMiddleware: function() {
+ return function(req, res, next) {
+ req._startTime = new Date();
+ // Cache the original res.end, and replace it with our own, to log once
+ // the request is finished.
+ var end = res.end;
+ res.end = function(chunk, encoding) {
+ // restore original res.end and call it.
+ res.end = end;
+ res.end(chunk, encoding);
+ // Log!
+ logger.analytics("route", {
+ req: req,
+ res: res,
+ 'response-time': new Date() - req._startTime,
});
- } else {
- logger.warn("No EMAIL_LOG_RECIPIENTS specified; skipping email logger transport.")
}
- } else if (process.env.NODE_ENV === "testing") {
- logger.add(winston.transports.Console, {level: 'crit'});
- logger.cli();
- } else {
- logger.add(winston.transports.Console, {level: 'debug'});
- logger.cli();
+ // Proceed with next middleware.
+ next();
}
-
- //
- // A second logger for analytics -- log to file, in a more tightly
- // controlled format.
- //
- var analyticsLogger = new (winston.Logger)();
- analyticsLogger.add(winston.transports.File, {
- filename: __dirname + "/../logs/analytics.log",
- level: 'info',
- timestamp: true
- });
- logger.analytics = function(key, message, user, event, session, extra) {
- var args = {key: key};
- if (user) {
- args.userId = user.id;
- }
- if (event) {
- args.eventId = event.id ? event.id : event;
- }
- if (session) {
- args.sessionId = session.id ? session.id : session;
- }
- if (extra) {
- _.extend(args, extra);
- }
- analyticsLogger.info(message, args)
- };
- return logger;
}
}
diff --git a/lib/permalink-routes.js b/lib/permalink-routes.js
index d8cecfb2..daeae15d 100644
--- a/lib/permalink-routes.js
+++ b/lib/permalink-routes.js
@@ -33,11 +33,54 @@ module.exports = {
} else {
logger.warn("Attempt to load /h/admin/:code/:key with invalid key for this session: " + req.params.key);
res.status(403);
+ res._errorReason = "invalid creationKey";
res.send();
return;
}
});
+
+ app.post("/h/admin/:code", utils.ensureAuthenticated, function(req, res) {
+ if(!("creationKey" in req.body)) {
+ res.status(400);
+ res.send();
+ return;
+ }
+
+ // otherwise, if creationKey is present, check it against the specified session.
+ var session = db.permalinkSessions.find(function(s) {
+ return s.get("shortCode")==req.params.code;
+ });
+
+ if(_.isUndefined(session)) {
+ logger.warn("sess:unknown (set title/desc)" + JSON.stringify(req.body));
+ res.status(404);
+ res.send();
+ return;
+ }
+
+ if(req.body.creationKey===session.get("creationKey")) {
+ session.set("title", req.body.title);
+ session.set("description", req.body.description);
+ session.save();
+
+ res.redirect("/h/" + req.params.code);
+ logger.analytics("permalinks", {
+ action: "update",
+ title: req.body.title,
+ description: req.body.description,
+ shortCode: session.get("shortCode"),
+ req: req,
+ session: session
+ });
+ } else {
+ logger.warn("POST to /h/admin/:code with invaid creationKey.");
+ res.status(403);
+ res._errorReason = "invalid creationKey",
+ res.send();
+ return;
+ }
+ });
app.get("/h/:code", utils.ensureAuthenticated, function(req, res) {
logger.debug("GET /h/" +req.params.code + ": " + JSON.stringify(req.body))
@@ -52,6 +95,7 @@ module.exports = {
logger.warn("GET /h/" + req.params.code + " is not a valid hangout permalink");
res.status(400);
res.send();
+ res._errorReason = "invalid shortCode";
return;
}
@@ -61,7 +105,6 @@ module.exports = {
});
if(_.isUndefined(session)) {
- logger.debug("No session found for shortcode: '" + req.params.code + "', creating a new one.");
session = new models.ServerSession();
session.set("isPermalinkSession", true);
@@ -74,8 +117,14 @@ module.exports = {
session.save();
// now redirect them to the admin page for this session.
- logger.info("Redirecting to admin page for a new permalink session code.");
res.redirect("/h/admin/" + req.params.code + "/" + session.get("creationKey"));
+ logger.analytics("permalinks", {
+ action: "create",
+ shortCode: req.params.code,
+ session: session,
+ req: req,
+ res: res
+ });
return;
}
@@ -94,42 +143,6 @@ module.exports = {
session.save();
}
});
-
- app.post("/h/admin/:code", utils.ensureAuthenticated, function(req, res) {
- logger.info("POST /h/admin/"+ req.params.code + ": " + JSON.stringify(req.body));
- if(!("creationKey" in req.body)) {
- res.status(400);
- res.send();
- return;
- }
-
- // otherwise, if creationKey is present, check it against the specified session.
- var session = db.permalinkSessions.find(function(s) {
- return s.get("shortCode")==req.params.code;
- });
-
- if(_.isUndefined(session)) {
- logger.warn("sess:unknown (set title/desc)" + JSON.stringify(req.body));
- res.status(404);
- res.send();
- return;
- }
-
- if(req.body.creationKey===session.get("creationKey")) {
- session.set("title", req.body.title);
- session.set("description", req.body.description);
- session.save();
-
- logger.debug("updating session with params: " + JSON.stringify(req.body));
-
- res.redirect("/h/" + req.params.code);
- } else {
- logger.warn("POST to /h/admin/:code with invaid creationKey.");
- res.status(403);
- res.send();
- return;
- }
- });
// this endpoint manually stops a shortcode session.
// we seem to occasionally get sessions that are broken and stay open when
diff --git a/lib/redis-sync.js b/lib/redis-sync.js
index f3fcf510..27ae0473 100644
--- a/lib/redis-sync.js
+++ b/lib/redis-sync.js
@@ -28,7 +28,7 @@ exports.sync = function(method, model, options) {
}
if(!redis.connected) {
- logger.err("tried to sync, but redis is not connected");
+ logger.error("tried to sync, but redis is not connected");
return;
}
@@ -105,4 +105,4 @@ exports.resetIds = function() {
exports.flush = function() {
redis.flushdb();
-}
\ No newline at end of file
+}
diff --git a/lib/room-manager.js b/lib/room-manager.js
index 664fca33..d120b6be 100644
--- a/lib/room-manager.js
+++ b/lib/room-manager.js
@@ -122,11 +122,11 @@ _.extend(exports.RoomManager.prototype, events.EventEmitter.prototype, {
this.sockServer.removeListener("connection", this.handleConnection);
for (var socketId in this.socketBindings) {
this.unbind(socketId);
- logger.debug("unbinding ID " + socketId);
+ logger.debug("RoomManager unbinding ID " + socketId);
}
},
handleConnection: function(socket, data) {
- logger.info('connection' + socket);
+ logger.debug('RoomManager connection' + socket);
socket.user = null;
socket.id = uuid.v4();
@@ -147,7 +147,7 @@ _.extend(exports.RoomManager.prototype, events.EventEmitter.prototype, {
this.route(socket, data);
}
}, this);
- logger.debug("binding ID" + socket.id);
+ logger.debug("RoomManager binding ID" + socket.id);
socket.once('close', bindings.events.close);
socket.on('data', bindings.events.data);
this.socketBindings[socket.id] = bindings;
@@ -199,7 +199,7 @@ _.extend(exports.RoomManager.prototype, events.EventEmitter.prototype, {
return this.writeErr(socket, "auth", "Invalid key or user id " + args.id);
}
- logger.info("AUTHENTICATED sock " + socket.id + " to user " + user.id + " (" + user.get("displayName") + ")");
+ logger.debug("RoomManager authenticated sock " + socket.id + " to user " + user.id);
socket.user = user;
this.socketIdToUser[socket.id] = user;
var sockets = this.userIdToSockets[user.id] || [];
@@ -318,7 +318,7 @@ _.extend(exports.RoomManager.prototype, events.EventEmitter.prototype, {
handleDisconnect: function(socket) {
// Last refers to whether this is the last socket belonging to this
// user. If the user was not authenticated, last is null.
- logger.info("disconnection" + socket);
+ logger.debug("RoomManager disconnection " + socket);
var last = null;
if (this.socketIdToUser[socket.id]) {
delete this.socketIdToUser[socket.id];
@@ -354,7 +354,13 @@ _.extend(exports.RoomManager.prototype, events.EventEmitter.prototype, {
this.writeData(socket, type + "-ack", args);
},
writeErr: function(socket, type, args) {
- logger.warn("Socket error", {type: type, args: args});
+ logger.warn("RoomManager socket error", {type: type, args: args});
+ logger.analytics("socket-error", {
+ module: "room-manager",
+ type: type,
+ args: args,
+ socket: socket
+ });
this.writeData(socket, type + "-err", args);
},
writeData: function(socket, type, args) {
diff --git a/lib/server-models.js b/lib/server-models.js
index 255e03bc..c6f409da 100644
--- a/lib/server-models.js
+++ b/lib/server-models.js
@@ -167,7 +167,15 @@ exports.ServerEvent = client_models.Event.extend({
var attrs = client_models.Event.prototype.toJSON.call(this);
delete attrs["recentMessages"];
return attrs;
- }
+ },
+ logAnalytics: function(opts) {
+ logger.analytics("events", _.extend({
+ event: this,
+ eventStart: this.get('start'),
+ eventEnd: this.get('end'),
+ connectedUsers: this.get('connectedUsers').length
+ }, opts));
+ }
});
exports.ServerSession = client_models.Session.extend({
@@ -219,7 +227,7 @@ exports.ServerSession = client_models.Session.extend({
// server crashes while hangouts are running, and the sockets
// re-connect.
if(this.get("hangoutConnected")) {
- logger.debug("Triggering hangout-started on load.");
+ logger.debug("server-models triggering hangout-started on load.");
// this is an annoying hack. it turns out that
// ServerSession.collection isn't set, because in the
@@ -249,10 +257,9 @@ exports.ServerSession = client_models.Session.extend({
}
this.set("total-instances", this.get("total-instances")+1);
this.set("hangout-start-time", new Date().getTime());
+ this.logAnalytics({action: "start"});
},
onHangoutStopped: function() {
- logger.info("hangout shutdown for session " + this.id + ":" + this.get("title"));
-
// clear the connected participants list, too, so it's properly
// initialized for a future connection.
this.set("connectedParticipants", []);
@@ -265,6 +272,7 @@ exports.ServerSession = client_models.Session.extend({
}
this.save();
+ this.logAnalytics({action: "stop"});
},
url: function() {
@@ -275,8 +283,8 @@ exports.ServerSession = client_models.Session.extend({
// trying to start a hangout, and have anyone else who tries to join
// wait on their hangout to phone home.
startHangoutWithUser: function(user) {
- logger.debug("starting hangout with user: " + JSON.stringify(user));
if(this.isHangoutPending()) {
+ this.logAnalytics({action: "unfarmed start denied while pending", user: user});
return new Error("Hangout is pending, cannot start it again");
} else {
// if a user is provided, add in the user id.
@@ -287,13 +295,12 @@ exports.ServerSession = client_models.Session.extend({
obj["userId"] = user.id;
}
this.set("hangout-pending", obj);
- logger.debug("set hangout pending: " + JSON.stringify(this.get("hangout-pending")));
+ this.logAnalytics({action: "unfarmed start", user: user});
return true;
}
},
isHangoutPending: function() {
- logger.debug("checking hangout pending, field: " + JSON.stringify(this.get("hangout-pending")));
if(_.isNull(this.get("hangout-pending"))) {
return false;
} else {
@@ -307,7 +314,7 @@ exports.ServerSession = client_models.Session.extend({
var obj = this.get("hangout-pending");
if((new Date().getTime() - obj.time) > HANGOUT_CREATION_TIMEOUT) {
- logger.debug("Hangout pending was too old, returning false and resetting hangout-pending to null.");
+ this.logAnalytics({action: "unfarmed start timeout"});
this.set("hangout-pending", null);
return false;
}
@@ -321,11 +328,11 @@ exports.ServerSession = client_models.Session.extend({
setHangoutUrl: function(url) {
if(_.isNull(this.get("hangout-url"))) {
- logger.debug("setting hangout url: " + url + " and clearing pending. notifying listeners.");
this.set("hangout-url", url);
// if we have a valid hangout url set, mark it as not pending anymore.
- this.set("hangout-pending", null);
+ var wasUnfarmed = this.get("hangout-pending");
+ this.set("hangout-pending", null);
// let anyone who was waiting for a hangout url from this session know
// that we have a valid one now.
@@ -335,17 +342,23 @@ exports.ServerSession = client_models.Session.extend({
// hangout URL if no one joins.
if (this.getNumConnectedParticipants() == 0) {
this._hangoutConnectionTimeout = setTimeout(_.bind(function() {
+ this.logAnalytics({action: "invalidate hangout url", url: url});
if (this.getNumConnectedParticipants() == 0) {
this.set("hangout-url", null);
}
}, this), HANGOUT_CONNECTION_TIMEOUT);
}
+ this.logAnalytics({action: "set hangout url", url: url, wasUnfarmed: wasUnfarmed});
} else {
// If someone tries to overwrite an active hangout URL with a
// different one, return false, so we can warn them what the
// correct URL is.
if (this.get("hangout-url") != url) {
- logger.debug("Attempt to double-set hangout url failed - existing: " + this.get("hangout-url") + " requested: " + url);
+ this.logAnalytics({
+ action: "double-set hangout url denied",
+ url: url,
+ existing: this.get("hangout-url")
+ })
return false;
}
}
@@ -373,6 +386,13 @@ exports.ServerSession = client_models.Session.extend({
logger.debug("setting connected participants to: " + _.pluck(participants, "id"));
},
+ logAnalytics: function(opts) {
+ logger.analytics(this.get("isPermalinkSession") ? "permalinks" : "sessions", _.extend({
+ session: this,
+ shortCode: this.get('shortCode'),
+ event: this.collection && this.collection.event ? this.collection.event : null
+ }, opts));
+ },
// We don't actually use this yet. We would only care about this when
// people don't want to name their new session themselves.
diff --git a/lib/unhangout-db.js b/lib/unhangout-db.js
index f4786036..5bcfdfce 100644
--- a/lib/unhangout-db.js
+++ b/lib/unhangout-db.js
@@ -48,7 +48,7 @@ _.extend(UnhangoutDb.prototype, events.EventEmitter.prototype, {
}, this));
redis.auth(this.options.REDIS_PASSWORD);
- redis.on("end", function() { logger.error("redis end"); });
+ redis.on("end", function() { logger.warn("redis end"); });
redis.on("error", function(err) { logger.error("redis error: ", err); });
redis.on("ready", function() { logger.info("redis ready"); });
redis.once("ready", _.bind(function(err) {
diff --git a/lib/unhangout-routes.js b/lib/unhangout-routes.js
index 0428a2c2..58da274e 100644
--- a/lib/unhangout-routes.js
+++ b/lib/unhangout-routes.js
@@ -15,10 +15,11 @@ module.exports = {
route: function(app, db, options) {
// Local middleware to check if someone is an event admin.
function ensureEventAdmin(req, res, next) {
- if (req.user.isAdminOf(db.events.get(req.params.id))) {
+ var event = db.events.get(req.params.id)
+ if (req.user.isAdminOf(event)) {
return next();
}
- logger.warn("ensureEventAdmin: User " + req.user.id + " not an admin of event " + req.params.id)
+ res._errorReason = "not an admin of event";
return res.redirect("/")
}
// routing for the homepage
@@ -73,9 +74,8 @@ module.exports = {
}
if(_.isUndefined(e)) {
- logger.warn("Request for a non-existent event id: " + req.params.id);
res.status(404);
- res.send();
+ res.send("404 Not Found");
return;
}
@@ -113,10 +113,12 @@ module.exports = {
} else {
res.redirect("/");
}
+ logger.analytics("users", {action: "login", user: req.user});
}
);
app.get("/logout", function(req, res) {
+ logger.analytics("users", {action: "logout", user: req.user});
req.logout();
res.redirect("/");
});
@@ -131,11 +133,8 @@ module.exports = {
app.get("/session/:id", ensureAuthenticated, function(req, res) {
var session = getSession(req.params.id, db.events, db.permalinkSessions);
var queryargs = generateSessionHangoutGDParam(session, options);
- logger.info("ROUTING TO SESSION: " + JSON.stringify(session));
-
if(!session) {
- logger.warn("request for unknown session id: " + req.params.id);
- return res.send(404);
+ return res.send(404, "404 Not Found");
}
// three options at this point:
// 1. the session is already running and has a hangout link // populated -> redirect to hangout
@@ -143,8 +142,6 @@ module.exports = {
// 3. the session doesn't have a hangout link, and doesn't yet have a pending link -> send to google
if(session.getHangoutUrl()) {
- logger.info("redirecting user to existing hangout url: " + session.getHangoutUrl());
-
// append all the google hangout app info to enforce loading it on startup
return res.redirect(session.getHangoutUrl() + queryargs);
}
@@ -164,7 +161,7 @@ module.exports = {
// if it's pending, wait on the hangout-url event.
//TODO: Would be nice to auto re-try here if we're timing out.
return session.once("hangout-url", function(hangoutUrl) {
- logger.info("issueing redirect to requests waiting for a hangout link to be created: " + hangoutUrl);
+ logger.debug("issueing redirect to requests waiting for a hangout link to be created: " + hangoutUrl);
// when we get the hangout url, redirect this request to it.
res.redirect(hangoutUrl + queryargs);
});
@@ -189,7 +186,6 @@ module.exports = {
if(!session.setHangoutUrl(farmedUrl)) {
// and push the url we were going to use back on the
// end of the queue.
- logger.warning("race condition assigning farmed hangout-url");
farming.reuseUrl(farmedUrl);
}
res.redirect(session.getHangoutUrl() + queryargs);
@@ -198,13 +194,10 @@ module.exports = {
});
app.post("/subscribe", _.bind(function(req, res) {
- logger.debug("POST /subscribe");
-
// save subscription emails
if("email" in req.body && req.body.email.length > 5 && req.body.email.length < 100) {
//TODO: move any redis-specific stuff to unhangout-db.
db.redis.lpush("global:subscriptions", req.body.email);
- logger.info("subscribed email: " + req.body.email);
res.status(200);
res.send();
} else {
@@ -214,7 +207,6 @@ module.exports = {
}, this));
app.get("/admin", ensureAuthenticated, _.bind(function(req, res) {
- logger.info("GET /admin");
var allowedEvents = db.events.filter(function(e) { return req.user.isAdminOf(e); });
var sessions = _.flatten(_.map(allowedEvents, function(event) {
if(event.isLive()) {
@@ -236,7 +228,6 @@ module.exports = {
}, this));
app.get("/admin/users/", ensureAuthenticated, ensureSuperuser, function(req, res) {
- logger.debug("GET /admin/users/");
// Organize events by the users that admin them, so we can display
// a list of events each user admins.
res.render('admin-users.ejs', {
@@ -301,14 +292,11 @@ module.exports = {
});
app.get("/admin/event/new", ensureAuthenticated, ensureAdmin, _.bind(function(req, res) {
- logger.debug("GET /admin/event/new");
var context = {user:req.user, events:db.events, create:true};
res.render('admin-event.ejs', context);
}, this));
app.post("/admin/event/new", ensureAuthenticated, ensureAdmin, _.bind(function(req, res) {
- logger.debug("POST /admin/event/new " + JSON.stringify(req.body));
-
// make sure title and description are present, otherwise reject the request.
if(!("title" in req.body) || !("description" in req.body)) {
res.status(400);
@@ -322,8 +310,6 @@ module.exports = {
event.save();
db.events.add(event);
- logger.info("Created a new event: " + JSON.stringify(event));
-
res.redirect("/admin");
}, this));
@@ -331,9 +317,8 @@ module.exports = {
var event = db.events.get(req.params.id);
if(_.isUndefined(event)) {
- logger.warn("Attempt to stop unknown event id: " + req.params.id);
res.status(404);
- res.send();
+ res.send("404 Not Found");
return;
};
@@ -341,12 +326,11 @@ module.exports = {
if(err) {
res.status(500);
+ res._errorReason = err;
res.send(err);
return;
}
-
- logger.info("Started event:" + req.params.id);
-
+ event.logAnalytics({action: "start", user: req.user});
res.redirect("/admin/");
}, this));
@@ -354,20 +338,19 @@ module.exports = {
var event = db.events.get(req.params.id);
if(_.isUndefined(event)) {
- logger.warn("Attempt to start unknown event id: " + req.params.id);
res.status(404);
- res.send();
+ res.send("404 Not Found");
return;
};
var err = event.stop();
if(err) {
res.status(500);
+ res._errorReason = err;
res.send(err);
return;
}
-
- logger.info("Stopped event:" + req.params.id);
+ event.logAnalytics({action: "stop", user: req.user});
res.redirect("/admin/");
}, this));
@@ -378,7 +361,7 @@ module.exports = {
if(_.isUndefined(event)) {
logger.warn("Attempt to load unknown event id: " + req.params.id);
res.status(404);
- res.send();
+ res.send("404 Not Found");
return;
};
@@ -411,7 +394,15 @@ module.exports = {
event.set("blurDisabled", req.body.blurDisabled);
event.save();
- logger.debug("new event attributes: " + JSON.stringify(event));
+ event.logAnalytics({
+ action: "update",
+ title: event.get("title"),
+ shortName: event.get("shortName"),
+ description: event.get("description"),
+ welcomeMessage: event.get("welcomeMessage"),
+ organizer: event.get("organizer"),
+ blurDisabled: event.get("blurDisabled")
+ });
if(shouldBroadcast) {
event.trigger("broadcast", event, "event-update", event.toJSON());
diff --git a/lib/unhangout-server.js b/lib/unhangout-server.js
index bba5a60f..ecdff391 100644
--- a/lib/unhangout-server.js
+++ b/lib/unhangout-server.js
@@ -1,4 +1,5 @@
-var logger = require('./logging').getLogger(),
+var logging = require('./logging'),
+ logger = logging.getLogger(),
_ = require('underscore')._,
EventEmitter = require('events').EventEmitter,
UnhangoutDb = require('./unhangout-db'),
@@ -84,8 +85,10 @@ exports.UnhangoutServer.prototype = {
if (!err) {
this.inited = true;
this.emit("inited");
+ logger.analytics("server", {action: "init"});
}
}, this));
+
},
@@ -96,8 +99,6 @@ exports.UnhangoutServer.prototype = {
return;
}
- logger.log("info", "Starting UnhangoutServer on %s:%d", this.options.HOST, this.options.PORT);
-
this.express = express();
this.express.locals = {
_: _,
@@ -173,7 +174,7 @@ exports.UnhangoutServer.prototype = {
newUser.save();
this.db.users.add(newUser);
- logger.debug("users.length" + this.db.users.length);
+ logger.analytics("users", {action: "create", user: newUser, totalUsers: this.db.users.length});
return done(null, newUser.toJSON());
}, this)));
@@ -205,6 +206,7 @@ exports.UnhangoutServer.prototype = {
// express basics. bodyParser is important - makes it easier to extract
// post parameters from POST requests.
+ this.express.use(logging.analyticsMiddleware()); // Put this first so we can track request durations.
this.express.use(express.cookieParser());
this.express.use(express.bodyParser());
@@ -257,10 +259,18 @@ exports.UnhangoutServer.prototype = {
this.http.setTimeout(400);
}
- logger.info("http server listening");
+ logger.info("http server listening on port " + this.options.PORT);
this.emit("started");
this.running = true;
+ logger.analytics("server", {
+ action: "start",
+ host: this.options.HOST,
+ port: this.options.PORT,
+ totalUsers: this.db.users.length,
+ totalEvents: this.db.events.length,
+ totalPermalinkSessions: this.db.permalinkSessions.length
+ });
},
// stops the unhangout server.
@@ -270,9 +280,8 @@ exports.UnhangoutServer.prototype = {
this.emit("error", "Tried to stop a server that was not running.");
return;
}
- logger.info("Stopping UnhangoutServer!");
+ logger.info("http server shutting down");
this.emit("stopping");
-
this.socketManager.shutdown(_.bind(function(err, message) {
logger.info("Socket manager stopped");
if (err) {
@@ -288,7 +297,8 @@ exports.UnhangoutServer.prototype = {
logger.info("HTTP Closed");
this.running = false;
this.emit("stopped");
- }, this));
+ logger.analytics("server", {action: "stop", host: this.options.HOST, port: this.options.PORT});
+ }, this));
}, this));
},
@@ -301,6 +311,8 @@ exports.UnhangoutServer.prototype = {
logger.info("destroyed");
this.emit("destroyed");
+ this.options = this.options || {};
+ logger.analytics("server", {action: "destroy", host: this.options.HOST, port: this.options.PORT});
}
}
diff --git a/lib/unhangout-sockets.js b/lib/unhangout-sockets.js
index e889a0c3..312bea22 100644
--- a/lib/unhangout-sockets.js
+++ b/lib/unhangout-sockets.js
@@ -37,8 +37,6 @@ _.extend(UnhangoutSocketManager.prototype, events.EventEmitter.prototype, {
var channel = args.roomId.split("/")[0];
if (channel == "event") {
var event = this.getEvent(args.roomId);
- logger.info("user:" + socket.user.id + " joining event:" + event.id);
-
event.get("recentMessages").each(function(message) {
var obj = message.toJSON();
mgr.writeData(socket, "chat", obj);
@@ -54,20 +52,20 @@ _.extend(UnhangoutSocketManager.prototype, events.EventEmitter.prototype, {
event.get("connectedUsers").set(mgr.roomToUsers[args.roomId]);
event.userConnected(socket.user);
}
- logger.debug("connected users: " + JSON.stringify(event.get("connectedUsers").pluck("displayName")));
+ event.logAnalytics({action: "join", user: socket.user})
} else if (channel == "session" && args.userFirst) {
var session = this.getSession(args.roomId);
if (!session) {
- logger.warn("Attempt to join room for unknown session", args.roomId);
+ mgr.writeErr(socket, "join", "session not found");
return;
}
- logger.info("user:" + socket.user.id + " joining session:" + session.id);
if (args.roomFirst) {
session.set("hangoutConnected", true);
}
if (session.addConnectedParticipant(socket.user.toJSON())) {
session.save();
}
+ session.logAnalytics({action: "join", user: socket.user});
}
}, this));
@@ -83,6 +81,7 @@ _.extend(UnhangoutSocketManager.prototype, events.EventEmitter.prototype, {
if (args.roomLast) {
this.clearVideoSync(event.getRoomId());
}
+ event.logAnalytics({action: "leave", user: socket.user})
} else if (channel == "session" && args.userLast) {
var session = this.getSession(args.roomId);
logger.info("user:" + socket.user.id + " leaving session:" + session.id);
@@ -92,6 +91,7 @@ _.extend(UnhangoutSocketManager.prototype, events.EventEmitter.prototype, {
this.clearVideoSync(session.getRoomId());
}
session.save();
+ session.logAnalytics({action: "leave", user: socket.user})
}
}, this));
@@ -112,6 +112,7 @@ _.extend(UnhangoutSocketManager.prototype, events.EventEmitter.prototype, {
// TODO: Put roomId in broadcast? Can a socket be in more than one room?
mgr.broadcast(args.roomId, "chat", msg.toJSON());
mgr.writeAck(socket, "chat");
+ event.logAnalytics({action: "chat", user: socket.user});
} else {
mgr.writeErr(socket, "chat", "Unknown room");
}
@@ -150,6 +151,14 @@ _.extend(UnhangoutSocketManager.prototype, events.EventEmitter.prototype, {
mgr.broadcast(args.roomId, "create-session", newSession.toJSON());
});
mgr.writeAck(socket, "create-session");
+ event.logAnalytics({
+ action: "create-session",
+ user: socket.user,
+ session: newSession,
+ title: args.title,
+ activities: args.activities,
+ description: args.description
+ });
} else {
mgr.writeErr(socket, "create-session");
}
@@ -160,6 +169,7 @@ _.extend(UnhangoutSocketManager.prototype, events.EventEmitter.prototype, {
event.openSessions();
mgr.broadcast(args.roomId, "open-sessions", {roomId: args.roomId});
mgr.writeAck(socket, "open-sessions");
+ event.logAnalytics({action: "open-sessions", user: socket.user});
} else {
mgr.writeErr(socket, "open-sessions")
}
@@ -170,6 +180,7 @@ _.extend(UnhangoutSocketManager.prototype, events.EventEmitter.prototype, {
event.closeSessions();
mgr.broadcast(args.roomId, "close-sessions", {roomId: args.roomId});
mgr.writeAck(socket, "close-sessions");
+ event.logAnalytics({action: "close-sessions", user: socket.user});
} else {
mgr.writeErr(socket, "close-sessions");
}
@@ -182,7 +193,9 @@ _.extend(UnhangoutSocketManager.prototype, events.EventEmitter.prototype, {
session.destroy();
event.removeSession(session);
mgr.broadcast(args.roomId, "delete-session", {id: args.id, roomId: args.roomId});
- return mgr.writeAck(socket, "delete-session");
+ mgr.writeAck(socket, "delete-session");
+ event.logAnalytics({action: "delete-session", user: socket.user, session: args.id});
+ return
}
}
mgr.writeErr(socket, "delete-session");
@@ -200,6 +213,7 @@ _.extend(UnhangoutSocketManager.prototype, events.EventEmitter.prototype, {
event.save();
mgr.broadcast(args.roomId, "embed", {ytId: args.ytId, roomId: args.roomId});
mgr.writeAck(socket, "embed");
+ event.logAnalytics({action: "embed", user: socket.user, ytId: args.ytId});
} else {
return mgr.writeErr(socket, "embed", "Missing event or not admin");
}
@@ -223,6 +237,7 @@ _.extend(UnhangoutSocketManager.prototype, events.EventEmitter.prototype, {
});
}
sync.control(args);
+ event.logAnalytics({action: "control-video", user: socket.user, args: args});
}
}, this));
@@ -260,7 +275,13 @@ _.extend(UnhangoutSocketManager.prototype, events.EventEmitter.prototype, {
if (!session.validationError) {
mgr.broadcast(session.getRoomId(), "session/set-activities",
args, socket);
- return mgr.writeAck(socket, "session/set-activities");
+ mgr.writeAck(socket, "session/set-activities");
+ session.logAnalytics({
+ action: "set-activities",
+ activities: args.activities,
+ user: socket.user
+ });
+ return
}
}
return mgr.writeErr(socket, "session/set-activities");
@@ -285,6 +306,7 @@ _.extend(UnhangoutSocketManager.prototype, events.EventEmitter.prototype, {
});
}
sync.control(args);
+ session.logAnalytics({action: "control-video", user: socket.user, args: args});
}
}, this));
diff --git a/lib/utils.js b/lib/utils.js
index 7c303cba..b3b5fc8a 100644
--- a/lib/utils.js
+++ b/lib/utils.js
@@ -16,20 +16,18 @@ module.exports = {
return req.user && req.user.isSuperuser() ? next() : res.send(403);
},
ensureSuperuser: function (req, res, next) {
- logger.info("superuser check: " + req.user.get("displayName"));
if(req.user.isSuperuser()) {
next();
} else {
- logger.warn("... not an admin.")
+ res._errorReason = "Not a superuser";
res.send(401, "Permission denied");
}
},
ensureAdmin: function (req, res, next) {
- logger.info("admin check: " + req.user.get("displayName"));
if(req.user.isSuperuser() || req.user.isAdminOfSomeEvent()) {
next();
} else {
- logger.warn("... not an admin.")
+ res._errorReason = "Not an admin";
res.send(401, "Permission denied");
}
},