Merge pull request #2910 from mozilla/pb/2884-better-500-errors

https://github.com/mozilla/fxa-auth-server/pull/2910
r=vladikoff

docs/api.md

@@ -312,8 +312,6 @@ for `code` and `errno` are:
   A backend service request failed.
 * `code: 500, errno: 998`:
   An internal validation check failed.
-* `code: 500, errno: 999`:
-  Unspecified error
 
 The following errors
 include additional response properties:
@@ -343,6 +341,7 @@ include additional response properties:
 * `errno: 201`: retryAfter
 * `errno: 202`: retryAfter
 * `errno: 203`: service, operation
+* `errno: 998`: op, data
 
 #### Responses from intermediary servers
 <!--begin-responses-from-intermediary-servers-->

lib/backendService.js

@@ -132,7 +132,7 @@ module.exports = function createBackendServiceAPI(log, config, serviceName, meth
             message: err.message,
             value
           })
-          reject(error.internalValidationError())
+          reject(error.internalValidationError(fullMethodName, { location, value }))
         })
       })
     }

lib/error.js

@@ -86,7 +86,7 @@ var ERRNO = {
   UNEXPECTED_ERROR: 999
 }
 
-var DEFAULTS = {
+const DEFAULTS = {
   code: 500,
   error: 'Internal Server Error',
   errno: ERRNO.UNEXPECTED_ERROR,
@@ -94,15 +94,48 @@ var DEFAULTS = {
   info: 'https://github.com/mozilla/fxa-auth-server/blob/master/docs/api.md#response-format'
 }
 
-var TOO_LARGE = /^Payload (?:content length|size) greater than maximum allowed/
+const TOO_LARGE = /^Payload (?:content length|size) greater than maximum allowed/
 
-var BAD_SIGNATURE_ERRORS = [
+const BAD_SIGNATURE_ERRORS = [
   'Bad mac',
   'Unknown algorithm',
   'Missing required payload hash',
   'Payload is invalid'
 ]
 
+// Payload properties that might help us debug unexpected errors
+// when they show up in production. Obviously we don't want to
+// accidentally send any sensitive data or PII to a 3rd-party,
+// so the set is opt-in rather than opt-out.
+const DEBUGGABLE_PAYLOAD_KEYS = new Set([
+  'availableCommands',
+  'capabilities',
+  'client_id',
+  'code',
+  'command',
+  'duration',
+  'excluded',
+  'features',
+  'marketingOptIn',
+  'messageId',
+  'metricsContext',
+  'name',
+  'preVerified',
+  'publicKey',
+  'reason',
+  'redirectTo',
+  'reminder',
+  'scope',
+  'service',
+  'target',
+  'to',
+  'TTL',
+  'ttl',
+  'type',
+  'unblockCode',
+  'verificationMethod',
+])
+
 function AppError(options, extra, headers) {
   this.message = options.message || DEFAULTS.message
   this.isBoom = true
@@ -144,7 +177,7 @@ AppError.prototype.backtrace = function (traced) {
 /**
   Translates an error from Hapi format to our format
 */
-AppError.translate = function (response) {
+AppError.translate = function (request, response) {
   var error
   if (response instanceof AppError) {
     return response
@@ -152,7 +185,7 @@ AppError.translate = function (response) {
   var payload = response.output.payload
   var reason = response.reason
   if (! payload) {
-    error = new AppError({})
+    error = AppError.unexpectedError(request)
   } else if (payload.statusCode === 500 && /(socket hang up|ECONNREFUSED)/.test(reason)) {
     // A connection to a remote service either was not made or timed out.
     error = AppError.backendServiceFailure()
@@ -194,6 +227,9 @@ AppError.translate = function (response) {
       info: payload.info,
       stack: response.stack
     })
+    if (payload.statusCode >= 500) {
+      decorateErrorWithRequest(error, request)
+    }
   }
   return error
 }
@@ -886,18 +922,53 @@ AppError.backendServiceFailure = (service, operation) => {
   })
 }
 
-AppError.internalValidationError = () => {
+AppError.internalValidationError = (op, data) => {
   return new AppError({
     code: 500,
     error: 'Internal Server Error',
     errno: ERRNO.INTERNAL_VALIDATION_ERROR,
     message: 'An internal validation check failed.'
+  }, {
+    op,
+    data
   })
 }
 
-AppError.unexpectedError = () => {
+AppError.unexpectedError = request => {
-  return new AppError({})
+  const error = new AppError({})
+  decorateErrorWithRequest(error, request)
+  return error
 }
 
 module.exports = AppError
 module.exports.ERRNO = ERRNO
+
+function decorateErrorWithRequest (error, request) {
+  if (request) {
+    error.output.payload.request = {
+      // request.app.devices and request.app.metricsContext are async, so can't be included here
+      acceptLanguage: request.app.acceptLanguage,
+      locale: request.app.locale,
+      userAgent: request.app.ua,
+      method: request.method,
+      path: request.path,
+      query: request.query,
+      payload: scrubPii(request.payload),
+      headers: request.headers
+    }
+  }
+}
+
+function scrubPii (payload) {
+  if (! payload) {
+    return
+  }
+
+  return Object.entries(payload).reduce((scrubbed, [ key, value ]) => {
+    if (DEBUGGABLE_PAYLOAD_KEYS.has(key)) {
+      scrubbed[key] = value
+    }
+
+    return scrubbed
+  }, {})
+}

lib/safe-url.js

@@ -5,7 +5,7 @@
 // This module exports a safe URL-builder interface, ensuring that no
 // unsafe input can leak into generated URLs.
 //
-// It takes the approach of throwing error.unexpectedError() when unsafe
+// It takes the approach of throwing error.internalValidationError() when unsafe
 // input is encountered, for extra visibility. An alternative approach
 // would be to use encodeURIComponent instead to convert unsafe input on
 // the fly. However, we have no valid use case for encoding weird data
@@ -21,9 +21,9 @@
 //   url.render({ uid: 'foo' })               // returns '/account/foo/sessions'
 //   url.render({ uid: 'bar' })               // returns '/account/bar/sessions'
 //   url.render({ uid: 'bar' }, {foo: 'baz'}) // returns '/account/bar/sessions?foo=baz'
-//   url.render({ uid: 'foo\n' })             // throws error.unexpectedError()
+//   url.render({ uid: 'foo\n' })             // throws error.internalValidationError()
-//   url.render({})                           // throws error.unexpectedError()
+//   url.render({})                           // throws error.internalValidationError()
-//   url.render({ uid: 'foo', id: 'bar' })    // throws error.unexpectedError()
+//   url.render({ uid: 'foo', id: 'bar' })    // throws error.internalValidationError()
 
 'use strict'
 
@@ -87,6 +87,6 @@ module.exports = log => class SafeUrl {
 
   _fail (op, data) {
     log.error(Object.assign({ op, caller: this._caller }, data))
-    throw error.internalValidationError()
+    throw error.internalValidationError(op, data)
   }
 }

lib/server.js

@@ -250,7 +250,7 @@ async function create (log, error, config, routes, db, oauthdb, translator) {
     let response = request.response
     if (response.isBoom) {
       logEndpointErrors(response, log)
-      response = error.translate(response)
+      response = error.translate(request, response)
       if (config.env !== 'prod') {
         response.backtrace(request.app.traced)
       }

test/local/backendService.js

@@ -123,6 +123,13 @@ describe('createBackendServiceAPI', () => {
       assert.fail('should have thrown')
     } catch (err) {
       assert.equal(err.errno, error.ERRNO.INTERNAL_VALIDATION_ERROR)
+      assert.equal(err.output.payload.op, 'mock-service.testSimplePost')
+      assert.deepEqual(err.output.payload.data, {
+        location: 'request',
+        value: {
+          foo: 123
+        }
+      })
       assert.equal(log.error.callCount, 1, 'an error was logged')
       assert.equal(log.error.getCall(0).args[0].op, 'mock-service.testSimplePost')
       assert.equal(log.error.getCall(0).args[0].error, 'request schema validation failed')
@@ -136,6 +143,14 @@ describe('createBackendServiceAPI', () => {
       assert.fail('should have thrown')
     } catch (err) {
       assert.equal(err.errno, error.ERRNO.INTERNAL_VALIDATION_ERROR)
+      assert.equal(err.output.payload.op, 'mock-service.testGetWithValidation')
+      assert.deepEqual(err.output.payload.data, {
+        location: 'params',
+        value: {
+          first: 'ABC',
+          second: '123'
+        }
+      })
       assert.equal(log.error.callCount, 1, 'an error was logged')
       assert.equal(log.error.getCall(0).args[0].op, 'mock-service.testGetWithValidation')
       assert.equal(log.error.getCall(0).args[0].error, 'params schema validation failed')
@@ -172,6 +187,13 @@ describe('createBackendServiceAPI', () => {
       assert.fail('should have thrown')
     } catch (err) {
       assert.equal(err.errno, error.ERRNO.INTERNAL_VALIDATION_ERROR)
+      assert.equal(err.output.payload.op, 'mock-service.testGetWithValidation')
+      assert.deepEqual(err.output.payload.data, {
+        location: 'query',
+        value: {
+          foo: 123
+        }
+      })
       assert.equal(log.error.callCount, 1, 'an error was logged')
       assert.equal(log.error.getCall(0).args[0].op, 'mock-service.testGetWithValidation')
       assert.equal(log.error.getCall(0).args[0].error, 'query schema validation failed')

test/local/error.js

@@ -5,8 +5,9 @@
 'use strict'
 
 const { assert } = require('chai')
-var messages = require('joi/lib/language')
+const messages = require('joi/lib/language')
 const AppError = require('../../lib/error')
+const P = require('../../lib/promise')
 
 describe('AppErrors', () => {
 
@@ -24,7 +25,7 @@ describe('AppErrors', () => {
       assert.equal(typeof AppError, 'function')
       assert.equal(AppError.length, 3)
       assert.equal(typeof AppError.translate, 'function')
-      assert.equal(AppError.translate.length, 1)
+      assert.lengthOf(AppError.translate, 2)
       assert.equal(typeof AppError.invalidRequestParameter, 'function')
       assert.equal(AppError.invalidRequestParameter.length, 1)
       assert.equal(typeof AppError.missingRequestParameter, 'function')
@@ -35,7 +36,7 @@ describe('AppErrors', () => {
   it(
     'should translate with missing required parameters',
     () => {
-      var result = AppError.translate({
+      var result = AppError.translate(null, {
         output: {
           payload: {
             message: 'foo' + messages.errors.any.required,
@@ -59,7 +60,7 @@ describe('AppErrors', () => {
   it(
     'should translate with invalid parameter',
     () => {
-      var result = AppError.translate({
+      var result = AppError.translate(null, {
         output: {
           payload: {
             validation: 'foo'
@@ -80,7 +81,7 @@ describe('AppErrors', () => {
   it(
     'should translate with missing payload',
     () => {
-      var result = AppError.translate({
+      var result = AppError.translate(null, {
         output: {}
       })
       assert.ok(result instanceof AppError, 'instanceof AppError')
@@ -112,10 +113,85 @@ describe('AppErrors', () => {
     }
   )
 
+  it('unexpectedError without request data', () => {
+    const err = AppError.unexpectedError()
+    assert.instanceOf(err, AppError)
+    assert.instanceOf(err, Error)
+    assert.equal(err.errno, 999)
+    assert.equal(err.message, 'Unspecified error')
+    assert.equal(err.output.statusCode, 500)
+    assert.equal(err.output.payload.error, 'Internal Server Error')
+    assert.isUndefined(err.output.payload.request)
+  })
+
+  it('unexpectedError with request data', () => {
+    const err = AppError.unexpectedError({
+      app: {
+        acceptLanguage: 'en, fr',
+        locale: 'en',
+        geo: {
+          city: 'Mountain View',
+          state: 'California'
+        },
+        ua: {
+          os: 'Android',
+          osVersion: '9'
+        },
+        devices: P.resolve([ { id: 1 } ]),
+        metricsContext: P.resolve({
+          service: 'sync'
+        })
+      },
+      method: 'GET',
+      path: '/v1/wibble',
+      query: {
+        foo: 'bar'
+      },
+      payload: {
+        baz: 'qux',
+        email: 'foo@example.com',
+        displayName: 'Foo Bar',
+        metricsContext: {
+          utmSource: 'thingy'
+        },
+        service: 'sync'
+      },
+      headers: {
+        wibble: 'blee'
+      }
+    })
+    assert.equal(err.errno, 999)
+    assert.equal(err.message, 'Unspecified error')
+    assert.equal(err.output.statusCode, 500)
+    assert.equal(err.output.payload.error, 'Internal Server Error')
+    assert.deepEqual(err.output.payload.request, {
+      acceptLanguage: 'en, fr',
+      locale: 'en',
+      userAgent: {
+        os: 'Android',
+        osVersion: '9'
+      },
+      method: 'GET',
+      path: '/v1/wibble',
+      query: {
+        foo: 'bar'
+      },
+      payload: {
+        metricsContext: {
+          utmSource: 'thingy'
+        },
+        service: 'sync'
+      },
+      headers: {
+        wibble: 'blee'
+      }
+    })
+  })
+
   const reasons = ['socket hang up', 'ECONNREFUSED'];
   reasons.forEach((reason) => {
     it(`converts ${reason} errors to backend service error`, () => {
-      const result = AppError.translate({
+      const result = AppError.translate(null, {
         output: {
           payload: {
             errno: 999,

test/local/safe-url.js

@@ -46,7 +46,18 @@ describe('require:', () => {
     })
 
     it('logs an error and throws when param is missing', () => {
-      assert.throws(() => safeUrl.render({}))
+      let threw = false
+      try {
+        safeUrl.render({})
+      } catch (err) {
+        threw = true
+        assert.equal(err.output.payload.op, 'safeUrl.params.mismatch')
+        assert.deepEqual(err.output.payload.data, {
+          expected: [ 'bar' ],
+          keys: []
+        })
+      }
+      assert.equal(threw, true)
       assert.equal(log.error.callCount, 1)
       assert.deepEqual(log.error.args[0][0], {
         op: 'safeUrl.params.mismatch',
@@ -68,7 +79,19 @@ describe('require:', () => {
     })
 
     it('logs an error and throws when param is empty string', () => {
-      assert.throws(() => safeUrl.render({ bar: '' }))
+      let threw = false
+      try {
+        safeUrl.render({ bar: '' })
+      } catch (err) {
+        threw = true
+        assert.equal(err.output.payload.op, 'safeUrl.bad')
+        assert.deepEqual(err.output.payload.data, {
+          location: 'paramVal',
+          key: 'bar',
+          value: ''
+        })
+      }
+      assert.equal(threw, true)
       assert.equal(log.error.callCount, 1)
       assert.deepEqual(log.error.args[0][0], {
         location: 'paramVal',
@@ -106,7 +129,19 @@ describe('require:', () => {
     })
 
     it('logs an error and throws for bad query keys', () => {
-      assert.throws(() => safeUrl.render({ bar: 'baz' }, {'💩': 'bar'}))
+      let threw = false
+      try {
+        safeUrl.render({ bar: 'baz' }, {'💩': 'bar'})
+      } catch (err) {
+        threw = true
+        assert.equal(err.output.payload.op, 'safeUrl.unsafe')
+        assert.deepEqual(err.output.payload.data, {
+          location: 'queryKey',
+          key: '💩',
+          value: '💩'
+        })
+      }
+      assert.equal(threw, true)
       assert.equal(log.error.callCount, 1)
       assert.deepEqual(log.error.args[0][0], {
         location: 'queryKey',

test/local/server.js

@@ -389,7 +389,7 @@ describe('lib/server', () => {
           })
 
           it('called log.error correctly', () => {
-            assert.equal(log.error.callCount, 1)
+            assert.isAtLeast(log.error.callCount, 1)
             const args = log.error.args[0]
             assert.equal(args.length, 1)
             assert.deepEqual(args[0], {