Service logging tweaks (#1929)

- Log the response when using `test:services:trace`
- Fully log large nested objects

Since the `badgeData` is in a different format from the JSON response, and also doesn't include the title, including this output is helpful. It makes it clearer what the Joi matchers are trying to match.

Sometimes when there's a deep nested structure, it's helpful or necessary to see the entire thing.

services/base-json.js

@@ -6,6 +6,7 @@ const Joi = require('joi')
 const { checkErrorResponse, asJson } = require('../lib/error-helper')
 const BaseService = require('./base')
 const { InvalidResponse } = require('./errors')
+const trace = require('./trace')
 
 class BaseJsonService extends BaseService {
   static _validate(json, schema) {
@@ -14,7 +15,7 @@ class BaseJsonService extends BaseService {
       stripUnknown: true,
     })
     if (error) {
-      this.logTrace(
+      trace.logTrace(
         'validate',
         emojic.womanShrugging,
         'Response did not match schema',
@@ -25,13 +26,19 @@ class BaseJsonService extends BaseService {
         underlyingError: error,
       })
     } else {
-      this.logTrace('validate', emojic.bathtub, 'JSON after validation', value)
+      this.logTrace(
+        'validate',
+        emojic.bathtub,
+        'JSON after validation',
+        value,
+        { deep: true }
+      )
       return value
     }
   }
 
   async _requestJson({ schema, url, options = {}, errorMessages = {} }) {
-    const logTrace = (...args) => this.constructor.logTrace('fetch', ...args)
+    const logTrace = (...args) => trace.logTrace('fetch', ...args)
     if (!schema || !schema.isJoi) {
       throw Error('A Joi schema is required')
     }
@@ -48,7 +55,9 @@ class BaseJsonService extends BaseService {
       .then(checkErrorResponse.asPromise(errorMessages))
       .then(asJson)
       .then(json => {
-        logTrace(emojic.dart, 'Response JSON (before validation)', json)
+        logTrace(emojic.dart, 'Response JSON (before validation)', json, {
+          deep: true,
+        })
         return json
       })
       .then(json => this.constructor._validate(json, schema))

services/base.js

@@ -2,7 +2,6 @@
 
 // See available emoji at http://emoji.muan.co/
 const emojic = require('emojic')
-const chalk = require('chalk')
 const {
   NotFound,
   InvalidResponse,
@@ -16,14 +15,7 @@ const {
   makeColor,
   setBadgeColor,
 } = require('../lib/badge-data')
-// Config is loaded globally but it would be better to inject it. To do that,
-// there needs to be one instance of the service created at registration time,
-// which gets the config injected into it, instead of one instance per request.
-// That way most of the current static methods could become instance methods,
-// thereby gaining access to the injected config.
-const {
-  services: { trace: enableTraceLogging },
-} = require('../lib/server-config')
+const trace = require('./trace')
 
 class BaseService {
   constructor({ sendAndCacheRequest }, { handleInternalErrors }) {
@@ -155,20 +147,19 @@ class BaseService {
   }
 
   async invokeHandler(namedParams, queryParams) {
-    const logTrace = (...args) => this.constructor.logTrace(...args)
-    logTrace(
+    trace.logTrace(
       'inbound',
       emojic.womanCook,
       'Service class',
       this.constructor.name
     )
-    logTrace('inbound', emojic.ticket, 'Named params', namedParams)
-    logTrace('inbound', emojic.crayon, 'Query params', queryParams)
+    trace.logTrace('inbound', emojic.ticket, 'Named params', namedParams)
+    trace.logTrace('inbound', emojic.crayon, 'Query params', queryParams)
     try {
       return await this.handle(namedParams, queryParams)
     } catch (error) {
       if (error instanceof NotFound || error instanceof InvalidParameter) {
-        logTrace('outbound', emojic.noGoodWoman, 'Handled error', error)
+        trace.logTrace('outbound', emojic.noGoodWoman, 'Handled error', error)
         return {
           message: error.prettyMessage,
           color: 'red',
@@ -177,14 +168,14 @@ class BaseService {
         error instanceof InvalidResponse ||
         error instanceof Inaccessible
       ) {
-        logTrace('outbound', emojic.noGoodWoman, 'Handled error', error)
+        trace.logTrace('outbound', emojic.noGoodWoman, 'Handled error', error)
         return {
           message: error.prettyMessage,
           color: 'lightgray',
         }
       } else if (this._handleInternalErrors) {
         if (
-          !logTrace(
+          !trace.logTrace(
             'unhandledError',
             emojic.boom,
             'Unhandled internal error',
@@ -201,7 +192,7 @@ class BaseService {
           color: 'lightgray',
         }
       } else {
-        logTrace(
+        trace.logTrace(
           'unhandledError',
           emojic.boom,
           'Unhandled internal error',
@@ -274,7 +265,7 @@ class BaseService {
             namedParams,
             queryParams
           )
-          this.logTrace('outbound', emojic.shield, 'Service data', serviceData)
+          trace.logTrace('outbound', emojic.shield, 'Service data', serviceData)
           const badgeData = this._makeBadgeData(queryParams, serviceData)
 
           // Assumes the final capture group is the extension
@@ -284,31 +275,6 @@ class BaseService {
       })
     )
   }
-
-  static _formatLabelForStage(stage, label) {
-    const colorFn = {
-      inbound: chalk.black.bgBlue,
-      fetch: chalk.black.bgYellow,
-      validate: chalk.black.bgGreen,
-      unhandledError: chalk.white.bgRed,
-      outbound: chalk.black.bgBlue,
-    }[stage]
-    return colorFn(` ${label} `)
-  }
-
-  static logTrace(stage, symbol, label, ...content) {
-    if (enableTraceLogging) {
-      console.log(
-        this._formatLabelForStage(stage, label),
-        symbol,
-        '\n',
-        ...content
-      )
-      return true
-    } else {
-      return false
-    }
-  }
 }
 
 module.exports = BaseService

services/base.spec.js

@@ -3,6 +3,7 @@
 const { expect } = require('chai')
 const { test, given, forCases } = require('sazerac')
 const sinon = require('sinon')
+const trace = require('./trace')
 
 const {
   NotFound,
@@ -98,7 +99,7 @@ describe('BaseService', function() {
       sandbox.restore()
     })
     beforeEach(function() {
-      sinon.stub(DummyService, 'logTrace')
+      sandbox.stub(trace, 'logTrace')
     })
     it('Invokes the logger as expected', async function() {
       const serviceInstance = new DummyService({}, defaultConfig)
@@ -108,13 +109,13 @@ describe('BaseService', function() {
         },
         { queryParamA: '!' }
       )
-      expect(DummyService.logTrace).to.be.calledWithMatch(
+      expect(trace.logTrace).to.be.calledWithMatch(
         'inbound',
         sinon.match.string,
         'Service class',
         'DummyService'
       )
-      expect(DummyService.logTrace).to.be.calledWith(
+      expect(trace.logTrace).to.be.calledWith(
         'inbound',
         sinon.match.string,
         'Named params',
@@ -122,7 +123,7 @@ describe('BaseService', function() {
           namedParamA: 'bar.bar.bar',
         }
       )
-      expect(DummyService.logTrace).to.be.calledWith(
+      expect(trace.logTrace).to.be.calledWith(
         'inbound',
         sinon.match.string,
         'Query params',

services/service-tester.js

@@ -1,7 +1,9 @@
 'use strict'
 
 const frisby = require('icedfrisby-nock')(require('icedfrisby'))
+const emojic = require('emojic')
 const config = require('../lib/test-config')
+const trace = require('./trace')
 
 /**
  * Encapsulate a suite of tests. Create new tests using create() and register
@@ -48,6 +50,16 @@ class ServiceTester {
       .before(() => {
         this.beforeEach()
       })
+      // eslint-disable-next-line mocha/prefer-arrow-callback
+      .finally(function() {
+        // `this` is the IcedFrisby instance.
+        trace.logTrace(
+          'outbound',
+          emojic.shield,
+          'Response',
+          JSON.parse(this._response.body)
+        )
+      })
 
     this.specs.push(spec)
 

services/trace.js

@@ -0,0 +1,41 @@
+'use strict'
+
+const chalk = require('chalk')
+
+// Config is loaded globally but it would be better to inject it. To do that,
+// there needs to be one instance of the service created at registration time,
+// which gets the config injected into it, instead of one instance per request.
+// That way most of the current static methods could become instance methods,
+// thereby gaining access to the injected config.
+const {
+  services: { trace: enableTraceLogging },
+} = require('../lib/server-config')
+
+function _formatLabelForStage(stage, label) {
+  const colorFn = {
+    inbound: chalk.black.bgBlue,
+    fetch: chalk.black.bgYellow,
+    validate: chalk.black.bgGreen,
+    unhandledError: chalk.white.bgRed,
+    outbound: chalk.black.bgBlue,
+  }[stage]
+  return colorFn(` ${label} `)
+}
+
+function logTrace(stage, symbol, label, content, { deep = false } = {}) {
+  if (enableTraceLogging) {
+    if (deep) {
+      console.log(_formatLabelForStage(stage, label), symbol)
+      console.dir(content, { depth: null })
+    } else {
+      console.log(_formatLabelForStage(stage, label), symbol, '\n', content)
+    }
+    return true
+  } else {
+    return false
+  }
+}
+
+module.exports = {
+  logTrace,
+}