refactor(signin): Add support for sending flow metrics in email (#1593); r=pb,vladikoff

Emails now include X-Flow-Id and X-Flow-Begin-Time headers, and we use them
to emit flow events if the email bounces.

lib/bounces.js

@@ -67,6 +67,8 @@ module.exports = function (log, error) {
 
 
     function handleBounce(message) {
+      const currentTime = Date.now()
+
       var recipients = []
       if (message.bounce && message.bounce.bounceType === 'Permanent') {
         recipients = message.bounce.bouncedRecipients
@@ -108,6 +110,26 @@ module.exports = function (log, error) {
           }
         }
 
+        // Log flow metrics if `flowId` and `flowBeginTime` specified in headers
+        const flowId = getHeaderValue('X-Flow-Id', message)
+        const flowBeginTime = getHeaderValue('X-Flow-Begin-Time', message)
+        const elapsedTime = currentTime - flowBeginTime
+
+        if (flowId && flowBeginTime && (elapsedTime > 0)) {
+          const eventName = `email.${templateName}.bounced`
+
+          // Flow events have a specific event and structure that must be emitted.
+          // Ref `gather` in https://github.com/mozilla/fxa-auth-server/blob/master/lib/metrics/context.js
+          const flowEventInfo = {
+            event: eventName,
+            time: currentTime,
+            flow_id: flowId,
+            flow_time: elapsedTime
+          }
+
+          log.info('flowEvent', flowEventInfo)
+        }
+
         log.info(logData)
         log.increment('account.email_bounced')
 

lib/mailer.js

@@ -22,6 +22,8 @@ module.exports = function (config, log) {
         return P.resolve(mailer.verifyEmail(
           {
             email: account.email,
+            flowId: opts.flowId,
+            flowBeginTime: opts.flowBeginTime,
             uid: account.uid.toString('hex'),
             code: code.toString('hex'),
             service: opts.service,
@@ -44,6 +46,8 @@ module.exports = function (config, log) {
             code: code.toString('hex'),
             email: account.email,
             ip: opts.ip,
+            flowId: opts.flowId,
+            flowBeginTime: opts.flowBeginTime,
             location: opts.location,
             redirectTo: opts.redirectTo,
             resume: opts.resume,
@@ -61,6 +65,8 @@ module.exports = function (config, log) {
         return P.resolve(mailer.recoveryEmail(
           {
             email: token.email,
+            flowId: opts.flowId,
+            flowBeginTime: opts.flowBeginTime,
             token: token.data.toString('hex'),
             code: code.toString('hex'),
             service: opts.service,
@@ -95,7 +101,9 @@ module.exports = function (config, log) {
         return P.resolve(mailer.passwordResetEmail(
           {
             email: email,
-            acceptLanguage: opts.acceptLanguage || defaultLanguage
+            acceptLanguage: opts.acceptLanguage || defaultLanguage,
+            flowId: opts.flowId,
+            flowBeginTime: opts.flowBeginTime,
           }
         ))
       }
@@ -103,6 +111,8 @@ module.exports = function (config, log) {
         return P.resolve(mailer.newDeviceLoginEmail(
           {
             acceptLanguage: opts.acceptLanguage || defaultLanguage,
+            flowId: opts.flowId,
+            flowBeginTime: opts.flowBeginTime,
             email: email,
             ip: opts.ip,
             location: opts.location,
@@ -126,6 +136,8 @@ module.exports = function (config, log) {
         return P.resolve(mailer.unblockCodeEmail(
           {
             acceptLanguage: opts.acceptLanguage || defaultLanguage,
+            flowId: opts.flowId,
+            flowBeginTime: opts.flowBeginTime,
             email: account.email,
             ip: opts.ip,
             location: opts.location,

lib/routes/account.js

@@ -104,6 +104,13 @@ module.exports = function (
 
         request.validateMetricsContext()
 
+        // Store flowId and flowBeginTime to send in email
+        let flowId, flowBeginTime
+        if (request.payload.metricsContext) {
+          flowId = request.payload.metricsContext.flowId
+          flowBeginTime = request.payload.metricsContext.flowBeginTime
+        }
+
         customs.check(request, email, 'accountCreate')
           .then(db.emailRecord.bind(db, email))
           .then(deleteAccountIfUnverified, ignoreUnknownAccountError)
@@ -281,6 +288,8 @@ module.exports = function (
                   redirectTo: form.redirectTo,
                   resume: form.resume,
                   acceptLanguage: request.app.acceptLanguage,
+                  flowId: flowId,
+                  flowBeginTime: flowBeginTime,
                   ip: ip,
                   location: geoData.location,
                   uaBrowser: sessionToken.uaBrowser,
@@ -420,6 +429,13 @@ module.exports = function (
 
         request.validateMetricsContext()
 
+        // Store flowId and flowBeginTime to send in email
+        let flowId, flowBeginTime
+        if (request.payload.metricsContext) {
+          flowId = request.payload.metricsContext.flowId
+          flowBeginTime = request.payload.metricsContext.flowBeginTime
+        }
+
         checkIsBlockForced()
           .then(() => customs.check(request, email, 'accountLogin'))
           .catch(extractUnblockCode)
@@ -835,6 +851,8 @@ module.exports = function (
                     redirectTo: redirectTo,
                     resume: resume,
                     acceptLanguage: request.app.acceptLanguage,
+                    flowId: flowId,
+                    flowBeginTime: flowBeginTime,
                     ip: ip,
                     location: geoData.location,
                     uaBrowser: sessionToken.uaBrowser,
@@ -867,6 +885,8 @@ module.exports = function (
                     emailRecord.email,
                     {
                       acceptLanguage: request.app.acceptLanguage,
+                      flowId: flowId,
+                      flowBeginTime: flowBeginTime,
                       ip: ip,
                       location: geoData.location,
                       timeZone: geoData.timeZone,
@@ -898,6 +918,8 @@ module.exports = function (
                     tokenVerificationId,
                     {
                       acceptLanguage: request.app.acceptLanguage,
+                      flowId: flowId,
+                      flowBeginTime: flowBeginTime,
                       ip: ip,
                       location: geoData.location,
                       redirectTo: redirectTo,
@@ -1790,6 +1812,15 @@ module.exports = function (
         var ip = request.app.clientAddress
         var emailRecord
 
+        request.validateMetricsContext()
+
+        // Store flowId and flowBeginTime to send in email
+        let flowId, flowBeginTime
+        if (request.payload.metricsContext) {
+          flowId = request.payload.metricsContext.flowId
+          flowBeginTime = request.payload.metricsContext.flowBeginTime
+        }
+
         return customs.check(request, email, 'sendUnblockCode')
           .then(lookupAccount)
           .then(createUnblockCode)
@@ -1821,6 +1852,8 @@ module.exports = function (
             .then((geoData) => {
               return mailer.sendUnblockCode(emailRecord, code, userAgent.call({
                 acceptLanguage: request.app.acceptLanguage,
+                flowId: flowId,
+                flowBeginTime: flowBeginTime,
                 ip: ip,
                 location: geoData.location,
                 timeZone: geoData.timeZone

lib/routes/password.js

@@ -366,6 +366,13 @@ module.exports = function (
 
         request.validateMetricsContext()
 
+        // Store flowId and flowBeginTime to send in email
+        let flowId, flowBeginTime
+        if (request.payload.metricsContext) {
+          flowId = request.payload.metricsContext.flowId
+          flowBeginTime = request.payload.metricsContext.flowBeginTime
+        }
+
         request.emitMetricsEvent('password.forgot.send_code.start')
           .then(
             customs.check.bind(
@@ -396,6 +403,8 @@ module.exports = function (
                         redirectTo: request.payload.redirectTo,
                         resume: request.payload.resume,
                         acceptLanguage: request.app.acceptLanguage,
+                        flowId: flowId,
+                        flowBeginTime: flowBeginTime,
                         ip: ip,
                         location: geoData.location,
                         timeZone: geoData.timeZone
@@ -463,6 +472,13 @@ module.exports = function (
 
         request.validateMetricsContext()
 
+        // Store flowId and flowBeginTime to send in email
+        let flowId, flowBeginTime
+        if (request.payload.metricsContext) {
+          flowId = request.payload.metricsContext.flowId
+          flowBeginTime = request.payload.metricsContext.flowBeginTime
+        }
+
         request.emitMetricsEvent('password.forgot.resend_code.start')
           .then(
             customs.check.bind(
@@ -484,6 +500,8 @@ module.exports = function (
                         redirectTo: request.payload.redirectTo,
                         resume: request.payload.resume,
                         acceptLanguage: request.app.acceptLanguage,
+                        flowId: flowId,
+                        flowBeginTime: flowBeginTime,
                         ip: ip,
                         location: geoData.location,
                         timeZone: geoData.timeZone
@@ -539,6 +557,13 @@ module.exports = function (
 
         request.validateMetricsContext()
 
+        // Store flowId and flowBeginTime to send in email
+        let flowId, flowBeginTime
+        if (request.payload.metricsContext) {
+          flowId = request.payload.metricsContext.flowId
+          flowBeginTime = request.payload.metricsContext.flowBeginTime
+        }
+
         request.emitMetricsEvent('password.forgot.verify_code.start')
           .then(
             customs.check.bind(
@@ -557,7 +582,9 @@ module.exports = function (
                       return mailer.sendPasswordResetNotification(
                         passwordForgotToken.email,
                         {
-                          acceptLanguage: request.app.acceptLanguage
+                          acceptLanguage: request.app.acceptLanguage,
+                          flowId: flowId,
+                          flowBeginTime: flowBeginTime
                         }
                       )
                       .then(

test/client/api.js

@@ -419,7 +419,8 @@ module.exports = config => {
         email: email,
         service: options.service || undefined,
         redirectTo: options.redirectTo || undefined,
-        resume: options.resume || undefined
+        resume: options.resume || undefined,
+        metricsContext: options.metricsContext || undefined
       },
       headers
     )
@@ -445,7 +446,11 @@ module.exports = config => {
       )
   }
 
-  ClientApi.prototype.passwordForgotVerifyCode = function (passwordForgotTokenHex, code, headers) {
+  ClientApi.prototype.passwordForgotVerifyCode = function (passwordForgotTokenHex, code, headers, options) {
+    if (!options) {
+      options = {}
+    }
+
     return tokens.PasswordForgotToken.fromHex(passwordForgotTokenHex)
       .then(
         function (token) {
@@ -454,7 +459,8 @@ module.exports = config => {
             this.baseURL + '/password/forgot/verify_code',
             token,
             {
-              code: code
+              code: code,
+              metricsContext: options.metricsContext || undefined
             },
             headers
           )

test/client/index.js

@@ -393,8 +393,8 @@ module.exports = config => {
     return this.api.passwordForgotResendCode(this.passwordForgotToken, this.email)
   }
 
-  Client.prototype.verifyPasswordResetCode = function (code, headers) {
+  Client.prototype.verifyPasswordResetCode = function (code, headers, options) {
-    return this.api.passwordForgotVerifyCode(this.passwordForgotToken, code, headers)
+    return this.api.passwordForgotVerifyCode(this.passwordForgotToken, code, headers, options)
       .then(
         function (result) {
           this.accountResetToken = result.accountResetToken

test/local/bounce_tests.js

@@ -323,4 +323,61 @@ describe('bounce messages', () => {
       })
     }
   )
+
+  it(
+    'should emit flow metrics',
+    () => {
+      var mockLog = spyLog()
+      var mockDB = {
+        emailRecord: sinon.spy(function (email) {
+          return P.resolve({
+            uid: '123456',
+            email: email,
+            emailVerified: false
+          })
+        }),
+        deleteAccount: sinon.spy(function () {
+          return P.resolve({ })
+        })
+      }
+      var mockMsg = mockMessage({
+        bounce: {
+          bounceType: 'Permanent',
+          bounceSubType: 'General',
+          bouncedRecipients: [
+            {emailAddress: 'test@example.com'}
+          ]
+        },
+        mail: {
+          headers: [
+            {
+              name: 'X-Template-Name',
+              value: 'verifyLoginEmail'
+            },
+            {
+              name: 'X-Flow-Id',
+              value: 'someFlowId'
+            },
+            {
+              name: 'X-Flow-Begin-Time',
+              value: 1234
+            }
+          ]
+        }
+      })
+
+      return mockedBounces(mockLog, mockDB).handleBounce(mockMsg).then(function () {
+        assert.equal(mockDB.emailRecord.callCount, 1)
+        assert.equal(mockDB.emailRecord.args[0][0], 'test@example.com')
+        assert.equal(mockDB.deleteAccount.callCount, 1)
+        assert.equal(mockDB.deleteAccount.args[0][0].email, 'test@example.com')
+        assert.equal(mockLog.messages.length, 4)
+        assert.equal(mockLog.messages[0].args[0], 'flowEvent')
+        assert.equal(mockLog.messages[0].args[1]['event'], 'email.verifyLoginEmail.bounced')
+        assert.equal(mockLog.messages[0].args[1]['flow_id'], 'someFlowId')
+        assert.equal(mockLog.messages[0].args[1]['flow_time'] > 0, true)
+        assert.equal(mockLog.messages[0].args[1]['time'] > 0, true)
+      })
+    }
+  )
 })

test/mocks.js

@@ -10,6 +10,7 @@ const sinon = require('sinon')
 const extend = require('util')._extend
 const P = require('../lib/promise')
 const crypto = require('crypto')
+const config = require('../config').getProperties()
 
 const CUSTOMS_METHOD_NAMES = [
   'check',
@@ -89,6 +90,7 @@ const PUSH_METHOD_NAMES = [
 ]
 
 module.exports = {
+  generateMetricsContext: generateMetricsContext,
   mockCustoms: mockObject(CUSTOMS_METHOD_NAMES),
   mockDB: mockDB,
   mockDevices: mockDevices,
@@ -281,6 +283,24 @@ function spyLog (methods) {
   return mockLog(methods)
 }
 
+function generateMetricsContext(){
+  const randomBytes = crypto.randomBytes(16).toString('hex')
+  const flowBeginTime = Date.now()
+  const flowSignature = crypto.createHmac('sha256', config.metrics.flow_id_key)
+    .update([
+      randomBytes,
+      flowBeginTime.toString(16),
+      undefined
+    ].join('\n'))
+    .digest('hex')
+    .substr(0, 32)
+
+  return {
+    flowBeginTime: flowBeginTime,
+    flowId: randomBytes + flowSignature
+  }
+}
+
 function mockRequest (data) {
   const events = require('../lib/metrics/events')(data.log || module.exports.mockLog())
   const metricsContext = data.metricsContext || module.exports.mockMetricsContext()

test/remote/account_create_tests.js

@@ -9,6 +9,7 @@ var TestServer = require('../test_server')
 var crypto = require('crypto')
 const Client = require('../client')()
 var config = require('../../config').getProperties()
+const mocks = require('../mocks')
 
 describe('remote account create', function() {
   this.timeout(15000)
@@ -483,13 +484,16 @@ describe('remote account create', function() {
     'account creation works with maximal metricsContext metadata',
     () => {
       var email = server.uniqueEmail()
-      return Client.create(config.publicUrl, email, 'foo', {
+      var opts = {
-        metricsContext: {
+        metricsContext: mocks.generateMetricsContext()
-          flowId: 'deadbeefbaadf00ddeadbeefbaadf00ddeadbeefbaadf00ddeadbeefbaadf00d',
+      }
-          flowBeginTime: 1
+      return Client.create(config.publicUrl, email, 'foo', opts).then(function (client) {
-        }
-      }).then(function (client) {
         assert.ok(client, 'created account')
+        return server.mailbox.waitForEmail(email)
+      })
+      .then(function (emailData) {
+        assert.equal(emailData.headers['x-flow-begin-time'], opts.metricsContext.flowBeginTime, 'flow begin time set')
+        assert.equal(emailData.headers['x-flow-id'], opts.metricsContext.flowId, 'flow id set')
       })
     }
   )

test/remote/account_signin_verification_tests.js

@@ -18,6 +18,8 @@ var publicKey = {
   'e': '65537'
 }
 
+const mocks = require('../mocks')
+
 describe('remote account signin verification', function() {
   this.timeout(30000)
   let server
@@ -114,6 +116,10 @@ describe('remote account signin verification', function() {
       var client = null
       var uid
       var code
+      var loginOpts = {
+        keys: true,
+        metricsContext: mocks.generateMetricsContext()
+      }
       return Client.createAndVerify(config.publicUrl, email, password, server.mailbox)
         .then(
           function (x) {
@@ -133,7 +139,7 @@ describe('remote account signin verification', function() {
         )
         .then(
           function () {
-            return client.login({keys:true})
+            return client.login(loginOpts)
           }
         )
         .then(
@@ -155,6 +161,9 @@ describe('remote account signin verification', function() {
             assert.equal(emailData.subject, 'Confirm new sign-in to Firefox')
             assert.ok(uid, 'sent uid')
             assert.ok(code, 'sent verify code')
+
+            assert.equal(emailData.headers['x-flow-begin-time'], loginOpts.metricsContext.flowBeginTime, 'flow begin time set')
+            assert.equal(emailData.headers['x-flow-id'], loginOpts.metricsContext.flowId, 'flow id set')
           }
         )
         .then(

test/remote/password_forgot_tests.js

@@ -12,6 +12,7 @@ var crypto = require('crypto')
 var base64url = require('base64url')
 
 var config = require('../../config').getProperties()
+const mocks = require('../mocks')
 
 describe('remote password forgot', function() {
   this.timeout(15000)
@@ -32,7 +33,11 @@ describe('remote password forgot', function() {
       var wrapKb = null
       var kA = null
       var client = null
-      return Client.createAndVerify(config.publicUrl, email, password, server.mailbox, {keys:true})
+      var opts = {
+        keys: true,
+        metricsContext: mocks.generateMetricsContext()
+      }
+      return Client.createAndVerify(config.publicUrl, email, password, server.mailbox, opts)
         .then(
           function (x) {
             client = x
@@ -54,13 +59,15 @@ describe('remote password forgot', function() {
         .then(
           function (emailData) {
             assert.equal(emailData.html.indexOf('IP address') > -1, true, 'contains ip location data')
+            assert.equal(emailData.headers['x-flow-begin-time'], opts.metricsContext.flowBeginTime, 'flow begin time set')
+            assert.equal(emailData.headers['x-flow-id'], opts.metricsContext.flowId, 'flow id set')
             return emailData.headers['x-recovery-code']
           }
         )
         .then(
           function (code) {
             assert.throws(function() { client.resetPassword(newPassword) })
-            return resetPassword(client, code, newPassword)
+            return resetPassword(client, code, newPassword, undefined, opts)
           }
         )
         .then(
@@ -73,6 +80,9 @@ describe('remote password forgot', function() {
             var link = emailData.headers['x-link']
             var query = url.parse(link, true).query
             assert.ok(query.email, 'email is in the link')
+
+            assert.equal(emailData.headers['x-flow-begin-time'], opts.metricsContext.flowBeginTime, 'flow begin time set')
+            assert.equal(emailData.headers['x-flow-id'], opts.metricsContext.flowId, 'flow id set')
           }
         )
         .then(
@@ -431,8 +441,8 @@ describe('remote password forgot', function() {
     return TestServer.stop(server)
   })
 
-  function resetPassword(client, code, newPassword, options) {
+  function resetPassword(client, code, newPassword, headers, options) {
-    return client.verifyPasswordResetCode(code)
+    return client.verifyPasswordResetCode(code, headers, options)
       .then(function() {
         return client.resetPassword(newPassword, {}, options)
       })