feat(metrics): send account verification time to statsd

lib/log.js

@@ -135,6 +135,10 @@ Lug.prototype.summary = function (request, response) {
   }
 }
 
+Lug.prototype.timing = function(name, timing, tags) {
+  this.statsd.timing(name, timing, tags)
+}
+
 module.exports = function (level, name) {
   var log = new Lug(
     {

lib/metrics/statsd.js

@@ -5,6 +5,7 @@
 var StatsD = require('node-statsd')
 
 var STATSD_PREFIX = 'fxa.auth.'
+var TIMING_SUFFIX = '.time'
 
 function StatsDCollector(log) {
   if (! log) {
@@ -56,15 +57,26 @@ StatsDCollector.prototype = {
   },
 
   increment: function (name, tags) {
-    var self = this
+    if (this.client) {
+      this.client.increment(
+        STATSD_PREFIX + name,
+        1,
+        this.sampleRate,
+        tags,
+        handleErrors(this, 'increment')
+      )
+    }
+  },
 
-    if (self.client) {
-      self.client.increment(STATSD_PREFIX + name, 1, self.sampleRate, tags, function messageSentCallback(err) {
-        // this only gets called once after all messages have been sent
-        if (err) {
-          self.log.error({op: 'statsd', err: err})
-        }
-      })
+  timing: function (name, timing, tags) {
+    if (this.client) {
+      this.client.timing(
+        STATSD_PREFIX + name + TIMING_SUFFIX,
+        timing,
+        this.sampleRate,
+        tags,
+        handleErrors(this, 'timing')
+      )
     }
   },
 
@@ -79,4 +91,15 @@ StatsDCollector.prototype = {
   }
 }
 
+function handleErrors (self, method) {
+  return function (error) {
+    if (error) {
+      self.log.error({
+        op: 'statsd.' + method,
+        err: error
+      })
+    }
+  }
+}
+
 module.exports = StatsDCollector

lib/routes/account.js

@@ -678,6 +678,7 @@ module.exports = function (
               if (!butil.buffersAreEqual(code, account.emailCode)) {
                 throw error.invalidVerificationCode()
               }
+              log.timing('account.verified', Date.now() - account.createdAt)
               log.event('verified', { email: account.email, uid: account.uid, locale: account.locale })
               log.increment('account.verified')
               return db.verifyEmail(account)

test/local/statsd_tests.js

@@ -97,7 +97,7 @@ test(
   function (t) {
     var mockLog = {
       error: function (log) {
-        t.equal(log.op, 'statsd')
+        t.equal(log.op, 'statsd.increment')
         t.equal(log.err.message, 'Failed to send message')
         t.end()
       }
@@ -122,6 +122,64 @@ test(
   }
 )
 
+test(
+  'statsd.timing',
+  function (t) {
+    function StatsDMock() {
+      return {
+        socket: {},
+        increment: function () {
+          t.fail('statsd.increment should not be called')
+          t.end()
+        },
+        timing: function () {
+          t.equal(arguments.length, 5, 'statsd.timing received the correct number arguments')
+          t.equal(arguments[0], 'fxa.auth.foo.time', 'statsd.timing received the correct name argument')
+          t.equal(arguments[1], 1, 'statsd.timing received the correct timing argument')
+          t.equal(typeof arguments[2], 'number', 'statsd.timing received the correct timing argument')
+          t.equal(arguments[3], undefined, 'statsd.timing received the correct tags argument')
+          t.equal(typeof arguments[4], 'function', 'statsd.timing received the correct callback argument')
+          t.end()
+        }
+      }
+    }
+
+    var statsd = new StatsDCollector(mockLog)
+    statsd.init()
+    statsd.client = new StatsDMock()
+    var log = require('../../lib/log')('info')
+    log.statsd = statsd
+    log.timing('foo', 1)
+  }
+)
+
+test(
+  'statsd.timing error',
+  function (t) {
+    var mockLog = {
+      error: function (log) {
+        t.equal(log.op, 'statsd.timing')
+        t.equal(log.err, 'foo')
+        t.end()
+      }
+    }
+
+    function StatsDMock() {
+      return {
+        socket: {},
+        timing: function () {
+          arguments[4]('foo')
+        }
+      }
+    }
+
+    var statsd = new StatsDCollector(mockLog)
+    statsd.init()
+    statsd.client = new StatsDMock()
+    statsd.timing('wibble', 42)
+  }
+)
+
 test(
   'statsd close',
   function (t) {