feat(logs): log endpoint errors for better debugging (#1627) r=vbudhr…

…am,philbooth

New "server.EndpointError" error logging...

lib/server.js

@@ -9,6 +9,39 @@ var Hapi = require('hapi')
 
 var HEX_STRING = require('./routes/validators').HEX_STRING
 
+function trimLocale(header) {
+  if (!header) {
+    return header
+  }
+  if (header.length < 256) {
+    return header.trim()
+  }
+  var parts = header.split(',')
+  var str = parts[0]
+  if (str.length >= 255) { return null }
+  for (var i = 1; i < parts.length && str.length + parts[i].length < 255; i++) {
+    str += ',' + parts[i]
+  }
+  return str.trim()
+}
+
+function logEndpointErrors(response, log) {
+  // When requests to DB timeout and fail for unknown reason they are an 'EndpointError'.
+  // The error response hides error information from the user, but we log it here
+  // to better understand the DB timeouts.
+  if (response.__proto__ && response.__proto__.name === 'EndpointError') {
+    var endpointLog = {
+      op: 'server.EndpointError',
+      message: response.message,
+      reason: response.reason
+    }
+    if (response.attempt && response.attempt.method) {
+      // log the DB attempt to understand the action
+      endpointLog.method = response.attempt.method
+    }
+    log.error(endpointLog)
+  }
+}
 
 function create(log, error, config, routes, db) {
 
@@ -230,22 +263,6 @@ function create(log, error, config, routes, db) {
     }
   )
 
-  function trimLocale(header) {
-    if (!header) {
-      return header
-    }
-    if (header.length < 256) {
-      return header.trim()
-    }
-    var parts = header.split(',')
-    var str = parts[0]
-    if (str.length >= 255) { return null }
-    for (var i = 1; i < parts.length && str.length + parts[i].length < 255; i++) {
-      str += ',' + parts[i]
-    }
-    return str.trim()
-  }
-
   server.ext(
     'onPreAuth',
     function (request, reply) {
@@ -285,6 +302,7 @@ function create(log, error, config, routes, db) {
     function (request, reply) {
       var response = request.response
       if (response.isBoom) {
+        logEndpointErrors(response, log)
         response = error.translate(response)
         if (config.env !== 'prod') {
           response.backtrace(request.app.traced)
@@ -319,5 +337,8 @@ function create(log, error, config, routes, db) {
 }
 
 module.exports = {
-  create: create
+  create: create,
+  // Functions below exported for testing
+  _trimLocale: trimLocale,
+  _logEndpointErrors: logEndpointErrors
 }

test/local/lib_server_tests.js

@@ -0,0 +1,57 @@
+/* This Source Code Form is subject to the terms of the Mozilla Public
+ * License, v. 2.0. If a copy of the MPL was not distributed with this
+ * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
+
+'use strict'
+
+const assert = require('insist')
+const server = require('../../lib/server')
+
+describe('lib/server', () => {
+  describe('trimLocale', () => {
+    it('trims given locale', () => {
+      assert.equal(server._trimLocale('   fr-CH, fr;q=0.9    '), 'fr-CH, fr;q=0.9')
+    })
+  })
+
+  describe('logEndpointErrors', () => {
+    let msg = 'Timeout'
+    let reason = 'Socket fail'
+    let response = {
+      __proto__: {
+        name: 'EndpointError'
+      },
+      message: msg,
+      reason: reason
+    }
+
+    it('logs an endpoint error', (done) => {
+      const mockLog = {
+        error: (err) => {
+          assert.equal(err.op, 'server.EndpointError')
+          assert.equal(err.message, msg)
+          assert.equal(err.reason, reason)
+          done()
+        }
+      }
+      assert.equal(server._logEndpointErrors(response, mockLog))
+    })
+
+    it('logs an endpoint error with a method', (done) => {
+      response.attempt = {
+        method: 'PUT'
+      }
+
+      const mockLog = {
+        error: (err) => {
+          assert.equal(err.op, 'server.EndpointError')
+          assert.equal(err.message, msg)
+          assert.equal(err.reason, reason)
+          assert.equal(err.method, 'PUT')
+          done()
+        }
+      }
+      assert.equal(server._logEndpointErrors(response, mockLog))
+    })
+  })
+})