tests: add ecs-logging spec validation

This adds an ecs-logging spec validator
(utils/lib/ecs-loggin-validate.js) and uses it everywhere the ECS JSON
Schema-based validation was being done in tests.

Author: trentm

Makefile

@@ -20,13 +20,15 @@ check: check-license-headers
 	(cd loggers/winston && npx standard)
 	(cd loggers/morgan && npx standard)
 	(cd loggers/pino && npx standard)
+	(cd utils && npx standard)
 
 .PHONY: fmt
 fmt:
 	(cd helpers && npx standard --fix)
 	(cd loggers/winston && npx standard --fix)
 	(cd loggers/morgan && npx standard --fix)
 	(cd loggers/pino && npx standard --fix)
+	(cd utils && npx standard --fix)
 
 .PHONY: test
 test:

helpers/test.js

@@ -24,6 +24,8 @@ const Ajv = require('ajv').default
 const semver = require('semver')
 const test = require('tap').test
 
+const { ecsLoggingValidate } = require('../utils/lib/ecs-logging-validate')
+
 const {
   version,
   stringify,
@@ -40,7 +42,7 @@ addFormats(ajv)
 const validate = ajv.compile(require('../utils/schema.json'))
 
 test('stringify should return a valid ecs json', t => {
-  const ecs = {
+  const ecsFields = {
     '@timestamp': new Date().toISOString(),
     'log.level': 'info',
     message: 'hello world',
@@ -49,23 +51,49 @@ test('stringify should return a valid ecs json', t => {
     }
   }
 
-  const line = JSON.parse(stringify(ecs))
-  t.equal(validate(line), true)
+  const line = stringify(ecsFields)
+  const rec = JSON.parse(line)
+  t.equal(validate(rec), true)
+  t.equal(ecsLoggingValidate(line), null)
   t.end()
 })
 
-test('Bad ecs json (on purpose)', t => {
-  const ecs = {
+test('bad ECS json on purpose: @timestamp', t => {
+  const ecsFields = {
     '@timestamp': 'not a date',
     'log.level': 'info',
-    message: true,
+    message: 'foo',
     ecs: {
       version: '1.4.0'
     }
   }
 
-  const line = JSON.parse(stringify(ecs))
-  t.equal(validate(line), false)
+  const line = stringify(ecsFields)
+  const rec = JSON.parse(line)
+
+  t.equal(validate(rec), false)
+
+  const err = ecsLoggingValidate(line)
+  t.ok(err, 'got an ecsLoggingValidate error')
+  t.equal(err.details.length, 1)
+  t.ok(err.details[0].message)
+  t.equal(err.details[0].specKey, 'type')
+  t.equal(err.details[0].name, '@timestamp')
+
+  t.end()
+})
+
+test('bad ECS json on purpose: message type, ecs.version missing', t => {
+  const line = '{"@timestamp":"2021-02-01T21:21:06.281Z","log.level":"info","message":true,"foo":"bar"}'
+
+  const err = ecsLoggingValidate(line)
+  t.ok(err, 'got an ecsLoggingValidate error')
+  t.equal(err.details.length, 2)
+  t.equal(err.details[0].specKey, 'type')
+  t.equal(err.details[0].name, 'message')
+  t.equal(err.details[1].specKey, 'required')
+  t.equal(err.details[1].name, 'ecs.version')
+
   t.end()
 })
 
@@ -121,6 +149,7 @@ test('formatHttpRequest and formatHttpResponse should return a valid ecs object'
 
     const line = JSON.parse(stringify(ecs))
     t.ok(validate(line))
+    t.equal(ecsLoggingValidate(line), null)
 
     t.deepEqual(line.user_agent, { original: 'cool-agent' })
     t.deepEqual(line.url, {
@@ -171,6 +200,7 @@ test('stringify should emit valid tracing fields', t => {
 
   const after = JSON.parse(stringify(before))
   t.ok(validate(after))
+  t.equal(ecsLoggingValidate(after), null)
   t.deepEqual(after.trace, { id: '1' }, 'trace.id is stringified')
   t.deepEqual(after.transaction, { id: '2' }, 'transaction.id is stringified')
   t.deepEqual(after.span, { id: '3' },

loggers/morgan/test/apm.test.js

@@ -29,6 +29,8 @@ const Ajv = require('ajv').default
 const split = require('split2')
 const test = require('tap').test
 
+const { ecsLoggingValidate } = require('../../../utils/lib/ecs-logging-validate')
+
 const ajv = new Ajv({
   allErrors: true,
   verbose: true
@@ -117,6 +119,7 @@ test('tracing integration works', t => {
     }
     if (logObj) {
       t.ok(validate(logObj), 'logObj is ECS valid')
+      t.equal(ecsLoggingValidate(logObj), null)
       logObjs.push(logObj)
     }
     // Unlike the equivalent apm.test.js for other logging frameworks, we are

loggers/morgan/test/basic.test.js

@@ -27,6 +27,7 @@ const split = require('split2')
 const test = require('tap').test
 
 const ecsFormat = require('../')
+const { ecsLoggingValidate } = require('../../../utils/lib/ecs-logging-validate')
 
 const ajv = new Ajv({
   allErrors: true,
@@ -69,10 +70,11 @@ function makeExpressServerAndRequest (logger, path, reqOpts, body, cb) {
 }
 
 test('Should produce valid ecs logs', t => {
-  t.plan(2)
+  t.plan(3)
 
   const stream = split(JSON.parse).on('data', line => {
     t.true(validate(line))
+    t.equal(ecsLoggingValidate(line), null)
   })
   const logger = morgan(ecsFormat(), { stream })
 

loggers/pino/test/apm.test.js

@@ -29,6 +29,8 @@ const Ajv = require('ajv').default
 const split = require('split2')
 const test = require('tap').test
 
+const { ecsLoggingValidate } = require('../../../utils/lib/ecs-logging-validate')
+
 const ajv = new Ajv({
   allErrors: true,
   verbose: true
@@ -117,6 +119,7 @@ test('tracing integration works', t => {
     }
     if (logObj) {
       t.ok(validate(logObj), 'logObj is ECS valid')
+      t.equal(ecsLoggingValidate(logObj), null)
       logObjs.push(logObj)
     }
     if (traceObjs.length >= 3 && logObjs.length >= 1) {

loggers/pino/test/basic.test.js

@@ -28,6 +28,7 @@ const split = require('split2')
 const test = require('tap').test
 
 const ecsFormat = require('../')
+const { ecsLoggingValidate } = require('../../../utils/lib/ecs-logging-validate')
 
 const ajv = new Ajv({
   allErrors: true,
@@ -40,6 +41,7 @@ test('Should produce valid ecs logs', t => {
   const stream = split(JSON.parse).once('data', line => {
     t.deepEqual(line['log.level'], 'info')
     t.ok(validate(line))
+    t.equal(ecsLoggingValidate(line), null)
     t.end()
   })
 
@@ -51,6 +53,7 @@ test('Should map "name" to "log.logger"', t => {
   const stream = split(JSON.parse).once('data', line => {
     t.deepEqual(line.log, { logger: 'myName' })
     t.ok(validate(line))
+    t.equal(ecsLoggingValidate(line), null)
     t.end()
   })
 
@@ -63,6 +66,7 @@ test('Should append any additional property to the log message', t => {
   const stream = split(JSON.parse).once('data', line => {
     t.equal(line.foo, 'bar')
     t.ok(validate(line))
+    t.equal(ecsLoggingValidate(line), null)
     t.end()
   })
 
@@ -81,10 +85,11 @@ test('can log non-HTTP res & req fields', t => {
 })
 
 test('convertReqRes:true and HTTP req, res', t => {
-  t.plan(5)
+  t.plan(7)
 
   const stream = split(JSON.parse).on('data', rec => {
     t.ok(validate(rec))
+    t.equal(ecsLoggingValidate(rec), null)
     if (rec.message === 'handled request') {
       // Spot check that some of the ECS HTTP and User agent fields are there.
       t.equal(rec.http.request.method, 'get', 'http.request.method')
@@ -130,6 +135,7 @@ test('convertErr is true by default', t => {
   log.info({ err: new Error('boom') }, 'hi')
   const rec = recs[0]
   t.ok(validate(rec))
+  t.equal(ecsLoggingValidate(rec), null)
   t.equal(rec.error.type, 'Error')
   t.equal(rec.error.message, 'boom')
   t.match(rec.error.stack_trace, /^Error: boom\n {4}at/)
@@ -164,6 +170,7 @@ test('convertErr=false allows passing through err=<non-Error>', t => {
   log.info({ err: 42 }, 'hi')
   const rec = recs[0]
   t.ok(validate(rec))
+  t.equal(ecsLoggingValidate(rec), null)
   t.equal(rec.err, 42, 'rec.err is unchanged')
   t.equal(rec.error, undefined, 'no rec.error is set')
   t.end()
@@ -180,6 +187,7 @@ test('createEcsPinoOptions with no formatters.log', t => {
   log.info({ err: 42, req: 'my req', res: null }, 'hi')
   const rec = recs[0]
   t.ok(validate(rec))
+  t.equal(ecsLoggingValidate(rec), null)
   t.equal(rec.err, 42)
   t.equal(rec.req, 'my req')
   t.equal(rec.res, null)

loggers/winston/test/apm.test.js

@@ -29,6 +29,8 @@ const Ajv = require('ajv').default
 const split = require('split2')
 const test = require('tap').test
 
+const { ecsLoggingValidate } = require('../../../utils/lib/ecs-logging-validate')
+
 const ajv = new Ajv({
   allErrors: true,
   verbose: true
@@ -117,6 +119,7 @@ test('tracing integration works', t => {
     }
     if (logObj) {
       t.ok(validate(logObj), 'logObj is ECS valid')
+      t.equal(ecsLoggingValidate(logObj), null)
       logObjs.push(logObj)
     }
     if (traceObjs.length >= 3 && logObjs.length >= 1) {

loggers/winston/test/basic.test.js

@@ -27,6 +27,7 @@ const Ajv = require('ajv').default
 const { version } = require('@elastic/ecs-helpers')
 
 const ecsFormat = require('../')
+const { ecsLoggingValidate } = require('../../../utils/lib/ecs-logging-validate')
 
 const ajv = new Ajv({
   allErrors: true,
@@ -53,7 +54,7 @@ class CaptureTransport extends Transport {
 }
 
 test('Should produce valid ecs logs', t => {
-  t.plan(2)
+  t.plan(4)
 
   const cap = new CaptureTransport()
   const logger = winston.createLogger({
@@ -64,13 +65,14 @@ test('Should produce valid ecs logs', t => {
   logger.error('ecs is cool!', { hello: 'world' })
 
   cap.records.forEach((rec) => {
-    t.true(validate(rec))
+    t.ok(validate(rec))
+    t.equal(ecsLoggingValidate(rec), null)
   })
   t.end()
 })
 
 test('Bad ecs log (on purpose)', t => {
-  t.plan(1)
+  t.plan(2)
 
   const cap = new CaptureTransport()
   const logger = winston.createLogger({
@@ -82,6 +84,7 @@ test('Bad ecs log (on purpose)', t => {
   cap.records.forEach((rec) => {
     rec['@timestamp'] = true // Intentionally break it
     t.false(validate(rec))
+    t.notOk(ecsLoggingValidate(rec))
   })
   t.end()
 })
@@ -201,7 +204,9 @@ test('http request and response (req, res keys)', t => {
         res.on('close', function () {
           t.equal(cap.records.length, 2)
           t.ok(validate(cap.records[0]), 'record 0 is ECS valid')
+          t.equal(ecsLoggingValidate(cap.records[0]), null)
           t.ok(validate(cap.records[1]), 'record 1 is ECS valid')
+          t.equal(ecsLoggingValidate(cap.records[1]), null)
           // Spot check that some of the ECS HTTP fields are there.
           t.equal(cap.records[0].http.request.method, 'post',
             'http.request.method')
@@ -247,6 +252,7 @@ test('convertErr is true by default', t => {
   log.info('hi', { err: new Error('boom') })
   const rec = cap.records[0]
   t.ok(validate(rec))
+  t.equal(ecsLoggingValidate(rec), null)
   t.equal(rec.error.type, 'Error')
   t.equal(rec.error.message, 'boom')
   t.match(rec.error.stack_trace, /^Error: boom\n {4}at/)
@@ -282,6 +288,7 @@ test('convertErr=false allows passing through err=<non-Error>', t => {
   log.info('hi', { err: 42 })
   const rec = cap.records[0]
   t.ok(validate(rec))
+  t.equal(ecsLoggingValidate(rec), null)
   t.equal(rec.err, 42, 'rec.err is unchanged')
   t.equal(rec.error, undefined, 'no rec.error is set')
   t.end()