fix(logging): log errors when we encounter unexpected createdAt values

#1641

r=vbudhram

lib/routes/account.js

@@ -252,6 +252,18 @@ module.exports = function (
             tokenVerificationId = undefined
           }
 
+          if (query._createdAt) {
+            // We don't expect this to be set outside the tests so log an error
+            // if we do encounter it, to help debug what's going on.
+            log.error({
+              op: 'account.create.createSessionToken',
+              err: new Error('Unexpected _createdAt query parameter'),
+              _createdAt: query._createdAt,
+              userAgent: request.headers['user-agent'],
+              service
+            })
+          }
+
           return db.createSessionToken({
             uid: account.uid,
             email: account.email,

lib/tokens/token.js

@@ -59,6 +59,18 @@ module.exports = function (log, random, P, hkdf, Bundle, error) {
   // This uses randomly-generated seed data to derive the keys.
   //
   Token.createNewToken = function(TokenType, details) {
+    if (details.createdAt) {
+      // We don't expect this to be set outside the tests so log an error
+      // if we do encounter it, to help debug what's going on.
+      const err = new Error('Unexpected createdAt data')
+      log.error({
+        op: 'token.constructor',
+        TokenType: TokenType.name,
+        createdAt: details.createdAt,
+        err,
+        stack: err.stack
+      })
+    }
     return random(32)
       .then(bytes => Token.deriveTokenKeys(TokenType, bytes))
       .then(keys => new TokenType(keys, details || {}))

test/local/routes/account.js

@@ -179,7 +179,7 @@ describe('/account/reset', function () {
   })
 })
 
-describe('/account/create', function () {
+describe('/account/create', () => {
   it('should create an account', () => {
     // We want to test what's actually written to stdout by the logger.
     const mockLog = log('ERROR', 'test', {
@@ -198,6 +198,7 @@ describe('/account/create', function () {
     mockLog.flowEvent = sinon.spy(() => {
       return P.resolve()
     })
+    mockLog.error = sinon.spy()
     const mockMetricsContext = mocks.mockMetricsContext()
     const mockRequest = mocks.mockRequest({
       log: mockLog,
@@ -264,7 +265,7 @@ describe('/account/create', function () {
     const now = Date.now()
     sinon.stub(Date, 'now', () => now)
 
-    return runTest(route, mockRequest, function () {
+    return runTest(route, mockRequest, () => {
       assert.equal(mockDB.createAccount.callCount, 1, 'createAccount was called')
 
       assert.equal(mockLog.stdout.write.callCount, 1, 'an sqs event was logged')
@@ -348,6 +349,21 @@ describe('/account/create', function () {
       assert.equal(args[2].uaOS, 'Mac OS X')
       assert.equal(args[2].uaOSVersion, '10.10')
       assert.strictEqual(args[2].uaDeviceType, undefined)
+
+      assert.equal(mockLog.error.callCount, 0)
+
+      mockRequest.query._createdAt = Date.now()
+      return runTest(route, mockRequest, () => {
+        assert.equal(mockLog.error.callCount, 1)
+        const args = mockLog.error.args[0]
+        assert.equal(args.length, 1)
+        assert.equal(args[0].op, 'account.create.createSessionToken')
+        assert.ok(args[0].err instanceof Error)
+        assert.equal(args[0].err.message, 'Unexpected _createdAt query parameter')
+        assert.equal(args[0]._createdAt, mockRequest.query._createdAt)
+        assert.equal(args[0].userAgent, 'test user-agent')
+        assert.equal(args[0].service, 'sync')
+      })
     }).finally(() => Date.now.restore())
   })
 })

test/local/tokens/key_fetch_token.js

@@ -6,7 +6,7 @@
 
 const assert = require('insist')
 const crypto = require('crypto')
-const log = { trace() {} }
+const log = { trace () {}, error () {} }
 
 const tokens = require('../../../lib/tokens/index')(log)
 const KeyFetchToken = tokens.KeyFetchToken

test/local/tokens/session_token.js

@@ -5,19 +5,23 @@
 'use strict'
 
 const assert = require('insist')
-var sinon = require('sinon')
-var log = { trace: function() {}, info: function () {} }
-var crypto = require('crypto')
+const sinon = require('sinon')
+const log = {
+  trace () {},
+  info () {},
+  error: sinon.spy()
+}
+const crypto = require('crypto')
 
 const config = {
   lastAccessTimeUpdates: {}
 }
 const tokens = require('../../../lib/tokens/index')(log, config)
-var SessionToken = tokens.SessionToken
+const SessionToken = tokens.SessionToken
 
-var TOKEN_FRESHNESS_THRESHOLD = require('../../../lib/tokens/session_token').TOKEN_FRESHNESS_THREADHOLD
+const TOKEN_FRESHNESS_THRESHOLD = require('../../../lib/tokens/session_token').TOKEN_FRESHNESS_THREADHOLD
 
-var ACCOUNT = {
+const ACCOUNT = {
   createdAt: Date.now(),
   uid: 'xxx',
   email: Buffer('test@example.com').toString('hex'),
@@ -31,12 +35,23 @@ describe('SessionToken', () => {
     'interface is correct',
     () => {
       return SessionToken.create(ACCOUNT)
-        .then(function (token) {
+        .then(token => {
           assert.equal(typeof token.lastAuthAt, 'function', 'lastAuthAt method is defined')
           assert.equal(typeof token.update, 'function', 'update method is defined')
           assert.equal(typeof token.isFresh, 'function', 'isFresh method is defined')
           assert.equal(typeof token.setUserAgentInfo, 'function', 'setUserAgentInfo method is defined')
+
+          assert.equal(log.error.callCount, 1, 'log.error was called once')
+          const args = log.error.args[0]
+          assert.equal(args.length, 1, 'log.error was passed one argument')
+          assert.equal(args[0].op, 'token.constructor', 'log.error was passed correct op')
+          assert.equal(args[0].TokenType, 'SessionToken', 'log.error was passed correct TokenType')
+          assert.equal(args[0].createdAt, ACCOUNT.createdAt, 'log.error was passed correct createdAt')
+          assert.ok(args[0].err instanceof Error, 'log.error was passed valid err')
+          assert.equal(args[0].err.message, 'Unexpected createdAt data', 'log.error was passed correct error message')
+          assert.equal(args[0].stack, args[0].err.stack, 'log.error was passed correct stack')
         })
+        .finally(() => log.error.reset())
     }
   )
 
@@ -71,6 +86,7 @@ describe('SessionToken', () => {
             assert.equal(token.tokenVerificationId, token2.tokenVerificationId)
           }
         )
+        .finally(() => log.error.reset())
     }
   )
 
@@ -86,6 +102,8 @@ describe('SessionToken', () => {
           var now = Date.now()
           assert.ok(token.createdAt > now - 1000 && token.createdAt <= now)
           assert.equal(token.accountCreatedAt, null)
+
+          assert.equal(log.error.callCount, 0, 'log.error was not called')
         }
       )
     }

test/mocks.js

@@ -29,6 +29,7 @@ const DB_METHOD_NAMES = [
   'createPasswordForgotToken',
   'createSessionToken',
   'createUnblockCode',
+  'createVerificationReminder',
   'deleteAccount',
   'deleteDevice',
   'deleteKeyFetchToken',

test/remote/db_tests.js

@@ -8,7 +8,7 @@ const assert = require('insist')
 var uuid = require('uuid')
 var crypto = require('crypto')
 var base64url = require('base64url')
-var log = { trace() {}, info() {} }
+const log = { trace () {}, info () {}, error () {} }
 
 var config = require('../../config').getProperties()
 var P = require('../../lib/promise')

test/remote/push_db_tests.js

@@ -10,7 +10,7 @@ var uuid = require('uuid')
 var crypto = require('crypto')
 var base64url = require('base64url')
 var proxyquire = require('proxyquire')
-var log = { trace() {}, info() {} }
+const log = { trace () {}, info () {}, error () {} }
 
 var config = require('../../config').getProperties()
 var TestServer = require('../test_server')