From 55f272bac80cb945707179791145c7a4493fb9c9 Mon Sep 17 00:00:00 2001
From: Mike Larsson <mikelarssonftw@gmail.com>
Date: Wed, 17 Jul 2013 12:54:10 -0400
Subject: [PATCH] Add validation timing to logs

---
 lib/logger.js  |  9 ++++++++-
 lib/website.js | 15 +++++++++++++++
 2 files changed, 23 insertions(+), 1 deletion(-)

diff --git a/lib/logger.js b/lib/logger.js
index a6f63ef..c3711db 100644
--- a/lib/logger.js
+++ b/lib/logger.js
@@ -1,13 +1,20 @@
 const bunyan = require('bunyan');
 const util = require('util');
 
+function validationSerializer(info) {
+  if ('resources' in info)
+    delete info.resources;
+  return info;
+}
+
 const log = module.exports = bunyan.createLogger({
   name: 'openbadges-validator-service',
   stream: process.stdout,
   level: 'info',
   serializers: {
     req: bunyan.stdSerializers.req,
-    res: bunyan.stdSerializers.res
+    res: bunyan.stdSerializers.res,
+    validation: validationSerializer
   }
 });
 
diff --git a/lib/website.js b/lib/website.js
index 5bc1dc1..c9bb7f1 100644
--- a/lib/website.js
+++ b/lib/website.js
@@ -1,5 +1,6 @@
 const validator = require('openbadges-validator');
 const dataurl = require('dataurl');
+const log = require('./logger');
 
 exports.index = function index(req, res, next) {
   res.render('index.html');
@@ -46,7 +47,21 @@ exports.validate = function validate(req, res, next) {
 
   res.locals.assertion = assertion;
 
+  const startTime = new Date();
+  log.info({ 
+    assertion: assertion
+  }, 'Validating');
+
   validator(assertion, function (err, info) {
+
+    const responseTime = new Date() - startTime;
+    log.info({ 
+      assertion: assertion,
+      err: err,
+      responseTime: responseTime,
+      validation: info
+    }, 'Validation result');
+
     // We might want to display the images that we found. The easiest
     // way to do that is to convert them to dataurls so we can just
     // stick 'em into <img> tags instead of trying to cache them and