feat(metrics): Emit additional data for the DataFlow fraud detection pipeline.

Adds `email`, `phoneNumber` and `method`

fixes #2858

lib/log.js

@@ -71,7 +71,7 @@ Lug.prototype.stat = function (stats) {
 }
 
 // Log a request summary line.
-// This gets called once for each compelted request.
+// This gets called once for each completed request.
 // See https://mana.mozilla.org/wiki/display/CLOUDSERVICES/Logging+Standard
 // for a discussion of this format and why it's used.
 
@@ -82,9 +82,12 @@ Lug.prototype.summary = function (request, response) {
 
   request.emitRouteFlowEvent(response)
 
-  var payload = request.payload || {}
-  var query = request.query || {}
-  var line = {
+  const payload = request.payload || {}
+  const query = request.query || {}
+  const credentials = (request.auth && request.auth.credentials) || {}
+  const responseBody = (response && response.source) || {}
+
+  const line = {
     op: 'request.summary',
     status: (response.isBoom) ? response.output.statusCode : response.statusCode,
     errno: response.errno || 0,
@@ -94,17 +97,21 @@ Lug.prototype.summary = function (request, response) {
     agent: request.headers['user-agent'],
     remoteAddressChain: request.app.remoteAddressChain,
     accountRecreated: request.app.accountRecreated,
-    t: Date.now() - request.info.received
+    t: Date.now() - request.info.received,
+    uid: credentials.uid || payload.uid || query.uid || response.uid || responseBody.uid || '00',
+    service: payload.service || query.service,
+    reason: payload.reason || query.reason,
+    redirectTo: payload.redirectTo || query.redirectTo,
+    keys: query.keys,
+
+    // Additional data used by the DataFlow fraud detection pipeline.
+    // Logging PII for the fraud detection pipeline has been given
+    // the green light so that the fraud detection logic can
+    // handle much of the logic the customs server currently does.
+    method: request.method,
+    email: credentials.email || payload.email || query.email,
+    phoneNumber: responseBody.formattedPhoneNumber,
   }
-  line.uid = (request.auth && request.auth.credentials) ?
-    request.auth.credentials.uid :
-    payload.uid || query.uid || response.uid ||
-    (response.source && response.source.uid) || '00'
-  line.service = payload.service || query.service
-  line.reason = payload.reason || query.reason
-  line.redirectTo = payload.redirectTo || query.redirectTo
-  line.keys = query.keys
-  line.email = payload.email || query.email
 
   if (line.status >= 500) {
     line.trace = request.app.traced

test/local/log.js

@@ -462,28 +462,135 @@ describe('log', () => {
   it('.summary should log an info message and call request.emitRouteFlowEvent', () => {
     const emitRouteFlowEvent = sinon.spy()
     log.summary({
-      app: {},
+      app: {
+        accountRecreated: false,
+        acceptLanguage: 'en',
+        remoteAddressChain: ['95.85.19.180', '78.144.14.50']
+      },
+      auth: {
+        credentials: {
+          email: 'quix',
+          uid: 'quid',
+        }
+      },
       emitRouteFlowEvent: emitRouteFlowEvent,
+      headers: {
+        'user-agent': 'Firefox Fenix'
+      },
+      id: 'quuz',
+      info: {
+        received: Date.now()
+      },
+      method: 'get',
+      path: '/v1/frobnicate',
+      payload: {
+        reason: 'grault',
+        redirectTo: 'garply',
+        service: 'corge',
+      },
+      query: {
+        keys: true
+      }
+    }, {
+      code: 200,
+      errno: 109,
+      statusCode: 201,
+      source: {
+        formattedPhoneNumber: 'garply'
+      }
+    })
+
+    assert.equal(logger.info.callCount, 1)
+
+    const line = logger.info.args[0][1]
+
+    // Because t is generated using Date.now and subtracting info.received,
+    // it should be >= 0, but we don't know the exact value.
+    assert.isNumber(line.t)
+    assert.isTrue(line.t >= 0)
+
+    // Compare only known values.
+    delete line.t;
+
+    assert.deepEqual(line, {
+      op: 'request.summary',
+      status: 201,
+      errno: 109,
+      rid: 'quuz',
+      path: '/v1/frobnicate',
+      lang: 'en',
+      agent: 'Firefox Fenix',
+      remoteAddressChain: ['95.85.19.180', '78.144.14.50'],
+      accountRecreated: false,
+      uid: 'quid',
+      service: 'corge',
+      reason: 'grault',
+      redirectTo: 'garply',
+      keys: true,
+      method: 'get',
+      email: 'quix',
+      phoneNumber: 'garply',
+    })
+
+    assert.equal(emitRouteFlowEvent.callCount, 1)
+    assert.equal(emitRouteFlowEvent.args[0].length, 1)
+    assert.deepEqual(emitRouteFlowEvent.args[0][0], { code: 200, errno: 109, statusCode: 201, source: {
+      formattedPhoneNumber: 'garply'
+    }})
+    assert.equal(logger.error.callCount, 0)
+  })
+
+  it('.summary with email in payload', () => {
+    log.summary({
+      app: {},
+      auth: {
+        credentials: {
+          uid: 'quid',
+        }
+      },
+      emitRouteFlowEvent: () => {},
       headers: {},
       info: {
         received: Date.now()
       },
+      method: 'get',
       path: '/v1/frobnicate',
-      payload: {}
+      payload: {
+        email: 'quix'
+      }
     }, {
       code: 200,
       statusCode: 201
     })
 
-    assert.equal(logger.info.callCount, 1)
-    assert.equal(logger.info.args[0][1].op, 'request.summary')
-    assert.equal(logger.info.args[0][1].status, 201)
-    assert.equal(logger.info.args[0][1].code, undefined)
-    assert.equal(emitRouteFlowEvent.callCount, 1)
-    assert.equal(emitRouteFlowEvent.args[0].length, 1)
-    assert.deepEqual(emitRouteFlowEvent.args[0][0], { code: 200, statusCode: 201 })
-    assert.equal(logger.error.callCount, 0)
-  })
+    assert.equal(logger.info.args[0][1].email, 'quix')
+  });
+
+  it('.summary with email in query', () => {
+    log.summary({
+      app: {},
+      auth: {
+        credentials: {
+          uid: 'quid',
+        }
+      },
+      emitRouteFlowEvent: () => {},
+      headers: {},
+      info: {
+        received: Date.now()
+      },
+      method: 'get',
+      path: '/v1/frobnicate',
+      query: {
+        email: 'quix'
+      }
+    }, {
+      code: 200,
+      statusCode: 201
+    })
+
+    assert.equal(logger.info.args[0][1].email, 'quix')
+  });
 
   it('.notifyAttachedServices should send a notification', () => {
     const now = Date.now()