Avoid double-counting the /sign_in page when users return from authen…

…ticating with their primary.

* Instead of using the #AUTH_RETURN* hash, use ?AUTH_RETURN*, which is sent to the backend and can be used to avoid double count.
* /sign_in?AUTH_RETURN logs an `idp.auth_return` message
* /sign_in?AUTH_RETURN_CANCEL logs an `idp.auth_cancel` message
* Update tests.

fixes #3970

lib/logging/logging.js

@@ -37,7 +37,7 @@ const MetricsKpiggybankTransport = require('./transports/metrics-kpi');
 exports.logger.add(LogFileTransport, {});
 exports.logger.add(StatsdTransport, {});
 exports.logger.add(MetricsFileTransport, {});
-exports.logger.add(MetricsKpiggybankTransport, {});
+exports.logger.add(MetricsKpiggybankTransport.getInstance(), {}, true);
 
 exports.enableConsoleLogging = function() {
   exports.logger.add(winston.transports.Console, {

lib/logging/middleware/metrics.js

@@ -6,20 +6,51 @@
  * Metrics middleware that reports when the signin dialog is opened.
  */
 
-const logger = require("../logging").logger;
 const urlparse = require('urlparse');
+const _ = require('underscore');
+const logger = require("../logging").logger;
 
 
 // utility function to log a bunch of stuff at user entry point
 module.exports = function(req, res, next) {
-  if (req.url === '/sign_in') userEntry(req);
+  // NOTE - this only counts the first time the user sees the dialog, it does
+  // not count if the user returns from a primary. req.url will be
+  // /sign_in?AUTH_RETURN or /sign_in?AUTH_RETURN_CANCEL for users who are
+  // returning from their IdP.
+  if (req.url === '/sign_in')
+    signInEntry(req);
+  else if (req.url === '/sign_in?AUTH_RETURN')
+    idpAuthReturnEntry('idp.auth_return', req);
+  else if (req.url === '/sign_in?AUTH_RETURN_CANCEL')
+    idpAuthReturnEntry('idp.auth_cancel', req);
+
   next();
 };
 
-function userEntry(req) {
+function signInEntry(req) {
+  entry('signin', req, { rp: getReferer(req) });
+}
+
+function idpAuthReturnEntry(type, req) {
+  entry(type, req, { idp: getReferer(req) });
+}
+
+function entry(type, req, data) {
+  logger.info(type, _.extend({
+    browser: req.headers['user-agent'],
+    // IP address (this probably needs to be replaced with the
+    // X-forwarded-for value
+    ip: getIpAddress(req)
+  }, data));
+}
+
+function getIpAddress(req) {
   var ipAddress = req.connection.remoteAddress;
   if (req.headers['x-real-ip']) ipAddress = req.headers['x-real-ip'];
+  return ipAddress;
+}
 
+function getReferer(req) {
   var referer = null;
   try {
     // don't log more than we need
@@ -28,11 +59,5 @@ function userEntry(req) {
     // ignore malformed referrers.  just log null
   }
 
-  logger.info('signin', {
-    browser: req.headers['user-agent'],
-    rp: referer,
-    // IP address (this probably needs to be replaced with the
-    // X-forwarded-for value
-    ip: ipAddress
-  });
+  return referer;
 }

lib/logging/transports/filters/metrics.js

@@ -17,7 +17,8 @@ var MessageMatches = {
 var RegExpMatches = [
   /complete_(?:[^\.]+)\.success/,
   /stage_(?:[^\.]+)\.success/,
-  /^metrics\.report\./
+  /^metrics\.report\./,
+  /^idp\.auth_.*/
 ];
 
 exports.test = function(msg) {

lib/logging/transports/metrics-kpi.js

@@ -12,7 +12,9 @@ const filter = require('./filters/metrics');
 const FIELDS_TO_SEND_TO_PIGGYBANK = [
   "type",
   "timestamp",
-  "user_agent"
+  "user_agent",
+  "idp",
+  "rp"
 ];
 
 var MetricsKpiggybankTransport = function(options) {
@@ -22,8 +24,21 @@ var MetricsKpiggybankTransport = function(options) {
 };
 MetricsKpiggybankTransport.BATCH_SIZE = config.get('kpi.metrics_batch_size');
 
+var instance;
+MetricsKpiggybankTransport.getInstance = function() {
+  if (instance) return instance;
+
+  instance = new MetricsKpiggybankTransport();
+  return instance;
+};
+
 util.inherits(MetricsKpiggybankTransport, winston.Transport);
 
+
+MetricsKpiggybankTransport.prototype.reset = function() {
+  this.queue = [];
+};
+
 MetricsKpiggybankTransport.prototype.log
     = function(level, msg, meta, callback) {
   if ( ! filter.test(msg)) return callback(null, true);
@@ -43,6 +58,19 @@ MetricsKpiggybankTransport.prototype.getQueue = function() {
   return this.queue;
 };
 
+// used for testing to see whether a metric was logged.
+MetricsKpiggybankTransport.prototype.isLogged = function(msg) {
+  return this.queue.some(function(item) {
+    return item.type === msg;
+  });
+};
+
+MetricsKpiggybankTransport.prototype.getItem = function(msg) {
+  return this.queue.filter(function(item) {
+    return item.type === msg;
+  })[0];
+};
+
 function isQueueFull() {
   return this.queue.length >= MetricsKpiggybankTransport.BATCH_SIZE;
 }

resources/static/authentication_api.js

@@ -50,11 +50,11 @@
     // it is lost in IE whenever the page redirects to the IdP.
     // See issue #2287 - https://github.com/mozilla/browserid/issues/2287
     navigator.id.completeAuthentication = function(cb) {
-      window.location = ipServer + '/sign_in#AUTH_RETURN';
+      window.location = ipServer + '/sign_in?AUTH_RETURN';
     };
 
     navigator.id.raiseAuthenticationFailure = function(reason) {
-      window.location = ipServer + '/sign_in#AUTH_RETURN_CANCEL';
+      window.location = ipServer + '/sign_in?AUTH_RETURN_CANCEL';
     };
 
     navigator.id._primaryAPIIsShimmed = true;

resources/static/dialog/js/modules/validate_rp_params.js

@@ -28,7 +28,7 @@ BrowserID.Modules.ValidateRpParams = (function() {
     },
     validate: function(paramsFromRP) {
       var self = this,
-          hash = self.window.location.hash;
+          getParams = self.window.location.search;
 
       var originURL = paramsFromRP.originURL;
 
@@ -135,7 +135,7 @@ BrowserID.Modules.ValidateRpParams = (function() {
         }
       }
 
-      if (hash.indexOf("#AUTH_RETURN") === 0) {
+      if (getParams.indexOf("?AUTH_RETURN") === 0) {
         var primaryParams = storage.idpVerification.get();
         if (!primaryParams)
           throw new Error("Could not get IdP Verification Info");
@@ -146,7 +146,7 @@ BrowserID.Modules.ValidateRpParams = (function() {
         params.cancelled = false;
       }
 
-      if (hash.indexOf("#AUTH_RETURN_CANCEL") === 0) {
+      if (getParams.indexOf("?AUTH_RETURN_CANCEL") === 0) {
         params.cancelled = true;
       }
 

resources/static/test/cases/dialog/js/modules/dialog.js

@@ -41,7 +41,8 @@
       }
     };
     this.location = {
-      hash: "#1234"
+      hash: "#1234",
+      search: ""
     };
     this.navigator = {};
   }
@@ -233,9 +234,9 @@
     });
   }
 
-  asyncTest("initialization with #AUTH_RETURN_CANCEL - " +
+  asyncTest("initialization with ?AUTH_RETURN_CANCEL - " +
       " trigger start with cancelled=true", function() {
-    winMock.location.hash = "#AUTH_RETURN_CANCEL";
+    winMock.location.search = "?AUTH_RETURN_CANCEL";
     testReturnFromIdP({
       email: TESTEMAIL
     }, {
@@ -245,8 +246,8 @@
     });
   });
 
-  asyncTest("initialization with #AUTH_RETURN and add=false - trigger start with correct params", function() {
-    winMock.location.hash = "#AUTH_RETURN";
+  asyncTest("initialization with ?AUTH_RETURN and add=false - trigger start with correct params", function() {
+    winMock.location.search = "?AUTH_RETURN";
     testReturnFromIdP({
       add: false,
       email: TESTEMAIL
@@ -258,8 +259,8 @@
     });
   });
 
-  asyncTest("initialization with #AUTH_RETURN and add=true - trigger start with correct params", function() {
-    winMock.location.hash = "#AUTH_RETURN";
+  asyncTest("initialization with ?AUTH_RETURN and add=true - trigger start with correct params", function() {
+    winMock.location.search = "?AUTH_RETURN";
     testReturnFromIdP({
       add: true,
       email: TESTEMAIL
@@ -272,8 +273,8 @@
   });
 
 
-  asyncTest("#AUTH_RETURN while authenticated should call usedAddressAsPrimary", function() {
-    winMock.location.hash = "#AUTH_RETURN";
+  asyncTest("?AUTH_RETURN while authenticated should call usedAddressAsPrimary", function() {
+    winMock.location.search = "?AUTH_RETURN";
     storage.idpVerification.set({
       add: false,
       email: TESTEMAIL
@@ -300,8 +301,8 @@
     });
   });
 
-  asyncTest("#AUTH_RETURN with add=true should not call usedAddressAsPrimary", function() {
-    winMock.location.hash = "#AUTH_RETURN";
+  asyncTest("?AUTH_RETURN with add=true should not call usedAddressAsPrimary", function() {
+    winMock.location.search = "?AUTH_RETURN";
     storage.idpVerification.set({
       add: true,
       email: TESTEMAIL

resources/static/test/cases/dialog/js/modules/validate_rp_params.js

@@ -16,7 +16,8 @@
 
   function WinMock() {
     this.location = {
-      hash: "#1234"
+      hash: "#1234",
+      search: ""
     };
 
     this.opener = {

tests/metrics-header-test.js

@@ -6,14 +6,18 @@
 
 require('./lib/test_env.js');
 
-const assert = require('assert'),
-fs = require('fs'),
-path = require('path'),
-http = require('http'),
-vows = require('vows'),
-start_stop = require('./lib/start-stop.js'),
-wsapi = require('./lib/wsapi.js'),
-urlparse = require('urlparse');
+const assert = require('assert');
+const fs = require('fs');
+const path = require('path');
+const http = require('http');
+const vows = require('vows');
+const urlparse = require('urlparse');
+const logger = require('../lib/logging/logging').logger;
+const start_stop = require('./lib/start-stop');
+const wsapi = require('./lib/wsapi');
+const config = require('../lib/configuration');
+const metrics_middleware = require('../lib/logging/middleware/metrics');
+const KpiTransport = require('../lib/logging/transports/metrics-kpi');
 
 var suite = vows.describe('metrics header test');
 suite.options.error = false;
@@ -56,22 +60,25 @@ function doRequest(path, headers, cb) {
   req.end();
 }
 
+// check end to end for /sign_in
+
 suite.addBatch({
   '/sign_in': {
     topic: function() {
       doRequest('/sign_in', {'user-agent': 'Test Runner', 'x-real-ip': '123.0.0.1', 'referer': 'https://persona.org'}, this.callback);
     },
     "metrics log exists": {
-      topic: function (err, r) {
+      topic: function() {
         if (existsSync(process.env.METRICS_LOG_FILE)) {
           this.callback();
         } else {
           fs.watchFile(process.env.METRICS_LOG_FILE, null, this.callback);
         }
       },
-      "metric fields are logged properly": function (event, filename) {
+      "metric fields are logged properly": function () {
         var metrics = JSON.parse(fs.readFileSync(process.env.METRICS_LOG_FILE, "utf8").trim());
         var message = JSON.parse(metrics.message);
+        assert.equal(message.type, "signin");
         assert.equal(message.ip, "123.0.0.1");
         assert.equal(message.rp, "https://persona.org");
         assert.equal(message.browser, "Test Runner");
@@ -82,6 +89,83 @@ suite.addBatch({
 });
 
 
+// Listen for actual messages that are sent to the KPI transport.
+// reset the transport queue between each test run to ensure we only get the
+// messages we care about.
+var kpiTransport = KpiTransport.getInstance();
+
+function noOp() {}
+
+function sendRequestToMetricsMiddleware(url, referer) {
+  kpiTransport.reset();
+
+  metrics_middleware({
+    connection: {
+      remoteAddress: '127.0.0.2'
+    },
+    url: url,
+    headers: {
+      'user-agent': 'Firefox',
+      'x-real-ip': '127.0.0.1',
+      'referer': referer || 'https://sendmypin.org/auth'
+    }
+  }, noOp, noOp);
+}
+
+suite.addBatch({
+  'request to /sign_in': {
+    topic: function() {
+      this.origSendMetricsValue = config.get('kpi_send_metrics');
+      config.set('kpi_send_metrics', true);
+
+      sendRequestToMetricsMiddleware('/sign_in', 'https://123done.org');
+      return kpiTransport.getItem('signin');
+    },
+    "sends metrics fields to logger": function (entry) {
+      assert.equal(entry.rp, 'https://123done.org');
+    },
+    "reset kpi_send_metrics": function() {
+      config.set('kpi_send_metrics', this.origSendMetricsValue);
+    }
+  }
+});
+
+suite.addBatch({
+  'request to /sign_in?AUTH_RETURN': {
+    topic: function() {
+      this.origSendMetricsValue = config.get('kpi_send_metrics');
+      config.set('kpi_send_metrics', true);
+
+      sendRequestToMetricsMiddleware('/sign_in?AUTH_RETURN');
+      return kpiTransport.getItem('idp.auth_return');
+    },
+    "kpi transport logs metric": function(entry) {
+      assert.equal(entry.idp, 'https://sendmypin.org');
+    },
+    "reset kpi_send_metrics": function() {
+      config.set('kpi_send_metrics', this.origSendMetricsValue);
+    }
+  }
+});
+
+suite.addBatch({
+  'request to /sign_in?AUTH_RETURN_CANCEL': {
+    topic: function() {
+      this.origSendMetricsValue = config.get('kpi_send_metrics');
+      config.set('kpi_send_metrics', true);
+
+      sendRequestToMetricsMiddleware('/sign_in?AUTH_RETURN_CANCEL');
+      return kpiTransport.getItem('idp.auth_cancel');
+    },
+    "kpi transport logs metric": function(entry) {
+      assert.equal(entry.idp, 'https://sendmypin.org');
+    },
+    "reset kpi_send_metrics": function() {
+      config.set('kpi_send_metrics', this.origSendMetricsValue);
+    }
+  }
+});
+
 suite.addBatch({
   'clean up': function () {
     fs.unlink(process.env.METRICS_LOG_FILE);