tests: ensure we are testing field order ("index") in ecs-logging validation

ecsLoggingValidate can only validate the "index" spec field if given a
log record *string*. This changes the tests to pass in a string rather
than a preparsed object. This brought up that pino does not satisfy the
"index" -- a known issue -- so support for explicitly skipping that
part of validation was added.

Author: trentm

loggers/morgan/test/basic.test.js

@@ -72,8 +72,9 @@ function makeExpressServerAndRequest (logger, path, reqOpts, body, cb) {
 test('Should produce valid ecs logs', t => {
   t.plan(3)
 
-  const stream = split(JSON.parse).on('data', line => {
-    t.true(validate(line))
+  const stream = split().on('data', line => {
+    const rec = JSON.parse(line)
+    t.true(validate(rec))
     t.equal(ecsLoggingValidate(line), null)
   })
   const logger = morgan(ecsFormat(), { stream })

loggers/pino/test/basic.test.js

@@ -38,10 +38,11 @@ addFormats(ajv)
 const validate = ajv.compile(require('../../../utils/schema.json'))
 
 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)
+  const stream = split().once('data', line => {
+    const rec = JSON.parse(line)
+    t.deepEqual(rec['log.level'], 'info')
+    t.ok(validate(rec))
+    t.equal(ecsLoggingValidate(line, { ignoreIndex: true }), null)
     t.end()
   })
 
@@ -50,10 +51,11 @@ test('Should produce valid ecs logs', t => {
 })
 
 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)
+  const stream = split().once('data', line => {
+    const rec = JSON.parse(line)
+    t.deepEqual(rec.log, { logger: 'myName' })
+    t.ok(validate(rec))
+    t.equal(ecsLoggingValidate(line, { ignoreIndex: true }), null)
     t.end()
   })
 
@@ -63,10 +65,11 @@ test('Should map "name" to "log.logger"', t => {
 })
 
 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)
+  const stream = split().once('data', line => {
+    const rec = JSON.parse(line)
+    t.equal(rec.foo, 'bar')
+    t.ok(validate(rec))
+    t.equal(ecsLoggingValidate(line, { ignoreIndex: true }), null)
     t.end()
   })
 
@@ -87,9 +90,10 @@ test('can log non-HTTP res & req fields', t => {
 test('convertReqRes:true and HTTP req, res', t => {
   t.plan(7)
 
-  const stream = split(JSON.parse).on('data', rec => {
+  const stream = split().on('data', line => {
+    const rec = JSON.parse(line)
     t.ok(validate(rec))
-    t.equal(ecsLoggingValidate(rec), null)
+    t.equal(ecsLoggingValidate(line, { ignoreIndex: true }), 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')
@@ -128,14 +132,14 @@ test('convertReqRes:true and HTTP req, res', t => {
 })
 
 test('convertErr is true by default', t => {
-  const recs = []
-  const stream = split(JSON.parse).on('data', rec => { recs.push(rec) })
+  const lines = []
+  const stream = split().on('data', line => { lines.push(line) })
   const log = pino({ ...ecsFormat() }, stream)
 
   log.info({ err: new Error('boom') }, 'hi')
-  const rec = recs[0]
+  const rec = JSON.parse(lines[0])
   t.ok(validate(rec))
-  t.equal(ecsLoggingValidate(rec), null)
+  t.equal(ecsLoggingValidate(lines[0], { ignoreIndex: true }), null)
   t.equal(rec.error.type, 'Error')
   t.equal(rec.error.message, 'boom')
   t.match(rec.error.stack_trace, /^Error: boom\n {4}at/)
@@ -159,18 +163,18 @@ test('convertErr does not blow up on non-Errors', t => {
 })
 
 test('convertErr=false allows passing through err=<non-Error>', t => {
-  const recs = []
-  const stream = split(JSON.parse).on('data', rec => { recs.push(rec) })
+  const lines = []
+  const stream = split().on('data', line => { lines.push(line) })
   // For *coverage* testing we also set `convertReqRes` to ensure
   // createEcsPinoOptions includes a `formatters.log` function.
   const log = pino(
     { ...ecsFormat({ convertErr: false, convertReqRes: true }) },
     stream)
 
   log.info({ err: 42 }, 'hi')
-  const rec = recs[0]
+  const rec = JSON.parse(lines[0])
   t.ok(validate(rec))
-  t.equal(ecsLoggingValidate(rec), null)
+  t.equal(ecsLoggingValidate(lines[0], { ignoreIndex: true }), null)
   t.equal(rec.err, 42, 'rec.err is unchanged')
   t.equal(rec.error, undefined, 'no rec.error is set')
   t.end()
@@ -180,14 +184,14 @@ test('createEcsPinoOptions with no formatters.log', t => {
   // There is a supposed fast path in createEcsPinoOptions where formatters.log
   // is excluded. Since convertErr is true by default, this case is rare.
   // For coverage testing, we concoct that case here.
-  const recs = []
-  const stream = split(JSON.parse).on('data', rec => { recs.push(rec) })
+  const lines = []
+  const stream = split().on('data', line => { lines.push(line) })
   const log = pino({ ...ecsFormat({ convertErr: false }) }, stream)
 
   log.info({ err: 42, req: 'my req', res: null }, 'hi')
-  const rec = recs[0]
+  const rec = JSON.parse(lines[0])
   t.ok(validate(rec))
-  t.equal(ecsLoggingValidate(rec), null)
+  t.equal(ecsLoggingValidate(lines[0], { ignoreIndex: true }), null)
   t.equal(rec.err, 42)
   t.equal(rec.req, 'my req')
   t.equal(rec.res, null)

loggers/winston/test/basic.test.js

@@ -66,7 +66,9 @@ test('Should produce valid ecs logs', t => {
 
   cap.records.forEach((rec) => {
     t.ok(validate(rec))
-    t.equal(ecsLoggingValidate(rec), null)
+  })
+  cap.infos.forEach((info) => {
+    t.equal(ecsLoggingValidate(info[MESSAGE]), null)
   })
   t.end()
 })
@@ -204,9 +206,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.equal(ecsLoggingValidate(cap.infos[0][MESSAGE]), null)
           t.ok(validate(cap.records[1]), 'record 1 is ECS valid')
-          t.equal(ecsLoggingValidate(cap.records[1]), null)
+          t.equal(ecsLoggingValidate(cap.infos[1][MESSAGE]), null)
           // Spot check that some of the ECS HTTP fields are there.
           t.equal(cap.records[0].http.request.method, 'post',
             'http.request.method')
@@ -224,24 +226,6 @@ test('http request and response (req, res keys)', t => {
   })
 })
 
-test('Keys order', t => {
-  t.plan(2)
-
-  const cap = new CaptureTransport()
-  const logger = winston.createLogger({
-    format: ecsFormat(),
-    transports: [cap]
-  })
-  logger.info('hi') // index 0
-  logger.error('oh noes', { hello: 'world' }) // index 1
-
-  t.equal(cap.infos[0][MESSAGE],
-    `{"@timestamp":"${cap.records[0]['@timestamp']}","log.level":"info","message":"hi","ecs":{"version":"${version}"}}`)
-  t.equal(cap.infos[1][MESSAGE],
-    `{"@timestamp":"${cap.records[1]['@timestamp']}","log.level":"error","message":"oh noes","ecs":{"version":"${version}"},"hello":"world"}`)
-  t.end()
-})
-
 test('convertErr is true by default', t => {
   const cap = new CaptureTransport()
   const log = winston.createLogger({
@@ -252,7 +236,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(ecsLoggingValidate(cap.infos[0][MESSAGE]), null)
   t.equal(rec.error.type, 'Error')
   t.equal(rec.error.message, 'boom')
   t.match(rec.error.stack_trace, /^Error: boom\n {4}at/)
@@ -288,7 +272,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(ecsLoggingValidate(cap.infos[0][MESSAGE]), null)
   t.equal(rec.err, 42, 'rec.err is unchanged')
   t.equal(rec.error, undefined, 'no rec.error is set')
   t.end()

utils/lib/ecs-logging-validate.js

@@ -97,7 +97,15 @@ function dottedLookup (obj, name) {
 // NOT maintain key order:
 //    > Object.keys(JSON.parse('{"a":true,"1":true,"c":true,"b":true}'))
 //    [ '1', 'a', 'c', 'b' ]
-function ecsLoggingValidate (rec) {
+//
+// - @param {String|Object} rec - The log record to validate. If an *object*
+//    is given then validation of "index" cannot be done.
+// - @param {Object} opts - Optional. Options to control validation.
+//    - {Boolean} opts.ignoreIndex - Set true to ignore "index" in validation.
+function ecsLoggingValidate (rec, opts) {
+  opts = opts || {}
+  const ignoreIndex = !!opts.ignoreIndex
+
   let recObj
   let recStr = null
   if (typeof (rec) === 'string') {
@@ -113,6 +121,9 @@ function ecsLoggingValidate (rec) {
 
   const details = []
   const addDetail = detail => {
+    if (ignoreIndex && detail.specKey === 'index') {
+      return
+    }
     details.push(detail)
   }
   const spec = loadSpec()