improves logging for explicitly handled errors (#694)

Amphora provides a mechanism to supply an error status code and message
in a response. This is accomplished by setting the following properties
on an **Error**:

```js
const err = new Error('Invalid Request');

err.status = 400;
err.message = 'Invalid Request';

throw err;
```

Errors thrown in a model's `render` or `save` will make their way to
the main error handler defined in `lib/responses.js`.

Prior to this commit, those errors were not logged, leaving the logging
up to the implementer.

Co-authored-by: Tiffany Chow <[email protected]>

lib/bootstrap.test.js

@@ -12,7 +12,6 @@ const _ = require('lodash'),
 
 describe(_.startCase(filename), function () {
   let sandbox,
-    bootstrapFake, // eslint-disable-line
     db,
     sitesFake,
     fakeLog;
@@ -41,8 +40,6 @@ describe(_.startCase(filename), function () {
       prefix: 'example4.com',
       subsite: 'example4'
     }];
-
-    bootstrapFake = files.getYaml(path.resolve('./test/fixtures/config/bootstrap'));
   });
 
   beforeEach(function () {

lib/responses.js

@@ -9,6 +9,25 @@ const _ = require('lodash'),
   filter = require('through2-filter'),
   metaController = require('./services/metadata');
 
+/**
+ * Returns a the name of the log level appropriate for a given HTTP response code.
+ * - 5xx = error
+ * - 4xx = warn
+ * - default = info
+ *
+ * @param {number} code: An HTTP status code.
+ * @returns {string}
+ */
+function logLevelFromStatusCode(code) {
+  if (code >= 500) {
+    return 'error';
+  }
+  if (code >= 400) {
+    return 'warn';
+  }
+  return 'info';
+}
+
 /**
  * Finds prefixToken, and removes it and anything before it.
  *
@@ -283,17 +302,17 @@ function notFound(err, res) {
  * @param {object} res
  */
 function serverError(err, res) {
-  // error is required to be logged
-  log('error', err.message, { stack: err.stack, url: _.get(res, 'locals.url') });
-
   const message = err.message || 'Server Error', // completely hide these messages from outside
-    code = 500;
+    code = 500,
+    level = logLevelFromStatusCode(code);
+
+  log(level, err.message, { code, stack: err.stack, url: _.get(res, 'locals.url') });
 
   sendDefaultResponseForCode(code, message, res);
 }
 
 /**
- * All client errors should look like this.
+ * All unauthorized requests should look like this.
  *
  * @param {object} res
  */
@@ -312,14 +331,32 @@ function unauthorized(res) {
  * @param {object} res
  */
 function clientError(err, res) {
-  log('error', err.message, { stack: err.stack, url: _.get(res, 'locals.url') });
   // They know it's a 400 already, we don't need to repeat the fact that its an error.
   const message = removePrefix(err.message, ':'),
-    code = 400;
+    code = 400,
+    level = logLevelFromStatusCode(code);
+
+  log(level, err.message, { code, stack: err.stack, url: _.get(res, 'locals.url') });
 
   sendDefaultResponseForCode(code, message, res);
 }
 
+/**
+ * This function dispatches an errors that have a manually set .status attribute.
+ * The .status attribute indicates that the error was intentionally constructed
+ * or caught and assigned a specific response code/message.
+ *
+ * @param {Error} err
+ * @param {object} res
+ */
+function explicitError(err, res) {
+  const code = err.status,
+    level = logLevelFromStatusCode(code);
+
+  log(level, err.message, { code, stack: err.stack, url: _.get(res, 'locals.url') });
+  sendDefaultResponseForCode(code, err.message, res);
+}
+
 /**
  * Handle errors in the standard/generic way
  * @param {object} res
@@ -330,7 +367,7 @@ function handleError(res) {
     if (err.status && err.name !== 'NotFoundError') {
       // If we're in this block, the error has a defined `status` property and
       // the error should be directed out immediately
-      sendDefaultResponseForCode(err.status, err.message, res);
+      explicitError(err, res);
     } else if (err.name === 'NotFoundError' ||
       err.message.indexOf('ENOENT') !== -1 ||
       err.message.indexOf('not found') !== -1) {

lib/responses.test.js

@@ -111,13 +111,29 @@ describe(_.startCase(filename), function () {
       fn(res)(new Error('something'));
     });
 
-    it('sends the error code defined in the `status` property', function (done) {
+    it('sends the error code defined in the `status` property, 4xx', function (done) {
       const res = createMockRes(),
         myError = new Error('something');
 
       myError.status = 403;
       expectStatus(res, 403);
-      expectResult(res, 'sendStatus: whatever', done);
+      expectResult(res, 'sendStatus: whatever', function () {
+        sinon.assert.calledWith(fakeLog, 'warn');
+        done();
+      });
+      fn(res)(myError);
+    });
+
+    it('sends the error code defined in the `status` property, 5xx', function (done) {
+      const res = createMockRes(),
+        myError = new Error('something');
+
+      myError.status = 500;
+      expectStatus(res, 500);
+      expectResult(res, 'sendStatus: whatever', function () {
+        sinon.assert.calledWith(fakeLog, 'error');
+        done();
+      });
       fn(res)(myError);
     });
   });
@@ -145,7 +161,7 @@ describe(_.startCase(filename), function () {
 
       expectStatus(res, 400);
       expectResult(res, 'sendStatus: whatever', function () {
-        sinon.assert.calledWith(fakeLog, 'error');
+        sinon.assert.calledWith(fakeLog, 'warn');
         done();
       });
       fn(new Error('something'), res);

lib/services/composer.js

@@ -31,11 +31,12 @@ function resolveComponentReferences(data, locals, filter = referenceProperty) {
             cmpt: referenceObject[referenceProperty]
           };
 
-          if (error.status) {
-            logObj.status = error.status;
+          // Errors with a .status property will be handled by lib/responses.js
+          // and logged with a level corresponding to the status code.
+          if (!error.status) {
+            log('error', `${error.message}`, logObj);
           }
 
-          log('error', `${error.message}`, logObj);
 
           return bluebird.reject(error);
         });

lib/services/composer.test.js

@@ -113,7 +113,7 @@ describe(_.startCase(filename), function () {
       });
     });
 
-    it('adds the status to the error message if it one is defined', function () {
+    it('adds the status to the error message if it one is defined, skips log', function () {
       const data = {
           a: {_ref: '/c/b'},
           c: {d: {_ref: '/c/e'}}
@@ -127,9 +127,8 @@ describe(_.startCase(filename), function () {
       components.get.withArgs('/c/m').returns(bluebird.reject(myError));
 
       return fn(data).catch((error) => {
-        sinon.assert.calledOnce(logSpy);
         expect(error.message).to.equal(errorMessage);
-        sinon.assert.calledWith(logSpy, 'error', errorMessage, { status: myError.status, cmpt: '/c/e', stack: myError.stack });
+        expect(error.status).to.equal(404);
       });
     });
   });