Skip to content
This repository was archived by the owner on Nov 7, 2020. It is now read-only.

Commit

Permalink
Refactored logging and structured analytics
Browse files Browse the repository at this point in the history 
Revamp logging throughout the server-side codebase.  Include an
``analytics`` logger that logs structured data from a taxonomy to JSON,
for better post-hoc analysis.
  • Loading branch information
@yourcelf
yourcelf committed Jan 10, 2014
1 parent 795f2cf commit 37877d9
Show file tree
Hide file tree
Showing 12 changed files with 299 additions and 164 deletions.
19 changes: 19 additions & 0 deletions DEVELOPMENT.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
5 changes: 3 additions & 2 deletions lib/hangout-farming.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 + "<br><a href='//" + options.HOST + ":" + options.PORT + "/hangout-farming'>CLICK ME</a>");

// 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.
Expand Down Expand Up @@ -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});
});
}

Expand All @@ -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;
Expand Down
157 changes: 105 additions & 52 deletions lib/logging.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}
}

Expand Down
89 changes: 51 additions & 38 deletions lib/permalink-routes.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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))
Expand All @@ -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;
}

Expand All @@ -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);
Expand All @@ -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;
}

Expand All @@ -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
Expand Down
4 changes: 2 additions & 2 deletions lib/redis-sync.js
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
}

Expand Down Expand Up @@ -105,4 +105,4 @@ exports.resetIds = function() {

exports.flush = function() {
redis.flushdb();
}
}
Loading

0 comments on commit 37877d9

Please sign in to comment.