Fix and test trace logging in BaseJsonService (#1944)

This fixes a regression introduced in #1929 which was caught by service tests post-merge.

services/base-json.js

@@ -26,7 +26,7 @@ class BaseJsonService extends BaseService {
         underlyingError: error,
       })
     } else {
-      this.logTrace(
+      trace.logTrace(
         'validate',
         emojic.bathtub,
         'JSON after validation',

services/base-json.spec.js

@@ -3,12 +3,18 @@
 const Joi = require('joi')
 const chai = require('chai')
 const { expect } = chai
+const sinon = require('sinon')
 
 const BaseJsonService = require('./base-json')
 const { invalidJSON } = require('./response-fixtures')
+const trace = require('./trace')
 
 chai.use(require('chai-as-promised'))
 
+const dummySchema = Joi.object({
+  requiredString: Joi.string().required(),
+}).required()
+
 class DummyJsonService extends BaseJsonService {
   static get category() {
     return 'cat'
@@ -21,7 +27,7 @@ class DummyJsonService extends BaseJsonService {
   }
 
   async handle() {
-    const { value } = await this._requestJson({ schema: Joi.any() })
+    const { value } = await this._requestJson({ schema: dummySchema })
     return { message: value }
   }
 }
@@ -36,10 +42,7 @@ describe('BaseJsonService', function() {
       { sendAndCacheRequest },
       { handleInternalErrors: false }
     )
-    const serviceData = await serviceInstance.invokeHandler(
-      { schema: Joi.any() },
-      {}
-    )
+    const serviceData = await serviceInstance.invokeHandler({}, {})
     expect(serviceData).to.deep.equal({
       color: 'lightgray',
       message: 'unparseable json response',
@@ -57,4 +60,56 @@ describe('BaseJsonService', function() {
       ).to.be.rejectedWith('A Joi schema is required')
     })
   })
+
+  describe('logging', function() {
+    let sandbox
+    beforeEach(function() {
+      sandbox = sinon.createSandbox()
+    })
+    afterEach(function() {
+      sandbox.restore()
+    })
+    beforeEach(function() {
+      sandbox.stub(trace, 'logTrace')
+    })
+
+    it('logs valid responses', async function() {
+      const sendAndCacheRequest = async () => ({
+        buffer: JSON.stringify({ requiredString: 'bar' }),
+        res: { statusCode: 200 },
+      })
+      const serviceInstance = new DummyJsonService(
+        { sendAndCacheRequest },
+        { handleInternalErrors: false }
+      )
+      await serviceInstance.invokeHandler({}, {})
+      expect(trace.logTrace).to.be.calledWithMatch(
+        'validate',
+        sinon.match.string,
+        'JSON after validation',
+        { requiredString: 'bar' },
+        { deep: true }
+      )
+    })
+
+    it('logs invalid responses', async function() {
+      const sendAndCacheRequest = async () => ({
+        buffer: JSON.stringify({
+          requiredString: ['this', "shouldn't", 'work'],
+        }),
+        res: { statusCode: 200 },
+      })
+      const serviceInstance = new DummyJsonService(
+        { sendAndCacheRequest },
+        { handleInternalErrors: false }
+      )
+      await serviceInstance.invokeHandler({}, {})
+      expect(trace.logTrace).to.be.calledWithMatch(
+        'validate',
+        sinon.match.string,
+        'Response did not match schema',
+        'child "requiredString" fails because ["requiredString" must be a string]'
+      )
+    })
+  })
 })