diff --git a/docs/intro.asciidoc b/docs/intro.asciidoc index 2a175bd..1d0b97e 100644 --- a/docs/intro.asciidoc +++ b/docs/intro.asciidoc @@ -17,7 +17,7 @@ popular web frameworks. A minimal log record includes the following fields: "@timestamp": "2021-01-13T21:32:38.095Z", "log.level": "info", "message": "hi", - "ecs": {"version":"1.6.0"} + "ecs.version": "1.6.0" } ---- diff --git a/docs/morgan.asciidoc b/docs/morgan.asciidoc index 2320d9c..53c4117 100644 --- a/docs/morgan.asciidoc +++ b/docs/morgan.asciidoc @@ -85,9 +85,7 @@ similar to the following: "@timestamp": "2021-01-16T00:03:23.279Z", "log.level": "info", "message": "::1 - - [16/Jan/2021:00:03:23 +0000] \"GET / HTTP/1.1\" 200 13 \"-\" \"curl/7.64.1\"", - "ecs": { - "version": "1.6.0" - }, + "ecs.version": "1.6.0", "http": { "version": "1.1", "request": { @@ -178,19 +176,11 @@ For example, running https://github.com/elastic/ecs-logging-nodejs/blob/main/log ---- % node examples/express-with-apm.js | jq . { - ... - "event": { - "dataset": "express-with-elastic-apm.log" - }, - "trace": { - "id": "e097193afa9ac221017b45a1f674601c" - }, - "transaction": { - "id": "c6aa5b47e01bad72" - }, - "service": { - "name": "express-with-elastic-apm" - } + // The same fields as before, plus: + "trace.id": "e097193afa9ac221017b45a1f674601c", + "transaction.id": "c6aa5b47e01bad72", + "service.name": "express-with-elastic-apm", + "event.dataset": "express-with-elastic-apm" } ---- diff --git a/docs/pino.asciidoc b/docs/pino.asciidoc index 0b57087..2478820 100644 --- a/docs/pino.asciidoc +++ b/docs/pino.asciidoc @@ -68,8 +68,8 @@ Running this will produce log output similar to the following: [source,cmd] ---- -{"log.level":"info","@timestamp":"2021-01-19T22:51:12.142Z","ecs":{"version":"1.6.0"},"process":{"pid":82240},"host":{"hostname":"pink.local"},"message":"Hello world"} -{"log.level":"warn","@timestamp":"2021-01-19T22:51:12.143Z","ecs":{"version":"1.6.0"},"process":{"pid":82240},"host":{"hostname":"pink.local"},"module":"foo","message":"From child"} +{"log.level":"info","@timestamp":"2023-10-14T02:07:47.901Z","process.pid":56645,"host.hostname":"pink.local","ecs.version":"1.6.0","message":"Hello world"} +{"log.level":"warn","@timestamp":"2023-10-14T02:07:47.901Z","process.pid":56645,"host.hostname":"pink.local","ecs.version":"1.6.0","module":"foo","message":"From child"} ---- [float] @@ -159,22 +159,17 @@ For example: ... # run 'curl http://localhost:3000/' { "log.level": "info", - "@timestamp": "2021-01-19T22:58:59.649Z", - "ecs": { - "version": "1.6.0" - }, - "process": { - "pid": 82670 - }, - "host": { - "hostname": "pink.local" - }, + "@timestamp": "2023-10-14T02:10:14.477Z", + "process.pid": 56697, + "host.hostname": "pink.local", + "ecs.version": "1.6.0", "http": { "version": "1.1", "request": { "method": "GET", "headers": { "host": "localhost:3000", + "user-agent": "curl/8.1.2", "accept": "*/*" } }, @@ -189,8 +184,13 @@ For example: "full": "http://localhost:3000/", "path": "/" }, + "client": { + "address": "::ffff:127.0.0.1", + "ip": "::ffff:127.0.0.1", + "port": 49504 + }, "user_agent": { - "original": "curl/7.64.1" + "original": "curl/8.1.2" }, "message": "handled request" } @@ -220,21 +220,10 @@ For example, running https://github.com/elastic/ecs-logging-nodejs/blob/main/log ---- % node examples/http-with-elastic-apm.js | jq . ... - "service": { - "name": "http-with-elastic-apm" - }, - "event": { - "dataset": "http-with-elastic-apm.log" - }, - "trace": { - "id": "a1c23e04d7174462f330f5921c8f036d" - }, - "transaction": { - "id": "2550c4c267d4dd53" - }, - "span": { - "id": "16a8704258dbc328" - }, + "service.name": "http-with-elastic-apm", + "event.dataset": "http-with-elastic-apm", + "trace.id": "79de6da334efae17ad43758573d57f1c", + "transaction.id": "8bf944f94b72c54d", ... ---- diff --git a/docs/winston.asciidoc b/docs/winston.asciidoc index 1a3d9cb..270ce58 100644 --- a/docs/winston.asciidoc +++ b/docs/winston.asciidoc @@ -78,8 +78,8 @@ Running this script (available https://github.com/elastic/ecs-logging-nodejs/blo [source,cmd] ---- % node examples/basic.js -{"@timestamp":"2021-01-13T21:32:38.095Z","log.level":"info","message":"hi","ecs":{"version":"1.6.0"}} -{"@timestamp":"2021-01-13T21:32:38.096Z","log.level":"error","message":"oops there is a problem","ecs":{"version":"1.6.0"},"foo":"bar"} +{"@timestamp":"2023-10-14T02:14:17.302Z","log.level":"info","message":"hi","ecs.version":"1.6.0"} +{"@timestamp":"2023-10-14T02:14:17.304Z","log.level":"error","message":"oops there is a problem","ecs.version":"1.6.0","foo":"bar"} ---- The formatter handles serialization to JSON, so you don't need to add the @@ -120,14 +120,12 @@ will yield (pretty-printed for readability): "@timestamp": "2021-01-26T17:25:07.983Z", "log.level": "info", "message": "oops", - "ecs": { - "version": "1.6.0" - }, "error": { "type": "Error", "message": "boom", "stack_trace": "Error: boom\n at Object. (..." - } + }, + "ecs.version": "1.6.0" } ---- @@ -189,18 +187,16 @@ For https://github.com/elastic/ecs-logging-nodejs/blob/main/loggers/winston/exam % node examples/http.js | jq . # using jq for pretty printing ... # run 'curl http://localhost:3000/' { - "@timestamp": "2021-01-13T22:00:07.442Z", + "@timestamp": "2023-10-14T02:15:54.768Z", "log.level": "info", "message": "handled request", - "ecs": { - "version": "1.6.0" - }, "http": { "version": "1.1", "request": { "method": "GET", "headers": { "host": "localhost:3000", + "user-agent": "curl/8.1.2", "accept": "*/*" } }, @@ -215,9 +211,15 @@ For https://github.com/elastic/ecs-logging-nodejs/blob/main/loggers/winston/exam "path": "/", "full": "http://localhost:3000/" }, + "client": { + "address": "::ffff:127.0.0.1", + "ip": "::ffff:127.0.0.1", + "port": 49538 + }, "user_agent": { - "original": "curl/7.64.1" - } + "original": "curl/8.1.2" + }, + "ecs.version": "1.6.0" } ---- @@ -239,19 +241,11 @@ For example, running https://github.com/elastic/ecs-logging-nodejs/blob/main/log ---- % node examples/http-with-elastic-apm.js | jq . ... - "event": { - "dataset": "http-with-elastic-apm.log" - }, - "trace": { - "id": "74631535a02bbe6a07c298b28c7443f4" - }, - "transaction": { - "id": "505400b77aba4d9a" - }, - "service": { - "name": "http-with-elastic-apm" - } -... + "service.name": "http-with-elastic-apm", + "event.dataset": "http-with-elastic-apm", + "trace.id": "7fd75f0f33ff49aba85d060b46dcad7e", + "transaction.id": "6c97c7c1b468fa05" +} ---- These IDs match trace data reported by the APM agent. diff --git a/loggers/morgan/CHANGELOG.md b/loggers/morgan/CHANGELOG.md index 80b9680..23c3c5f 100644 --- a/loggers/morgan/CHANGELOG.md +++ b/loggers/morgan/CHANGELOG.md @@ -1,5 +1,16 @@ # @elastic/ecs-morgan-format Changelog +## Unreleased + +- Change to adding dotted field names (`"ecs.version": "1.6.0"`), rather than + namespaced fields (`"ecs": {"version": "1.6.0"}`) for most fields. This is + supported by the ecs-logging spec, and arguably preferred in the ECS logging + docs. It is also what the ecs-logging-java libraries do. The resulting output + is slightly shorter, and accidental collisions with user fields is less + likely. +- Stop adding ".log" suffix to `event.dataset` field. + ([#95](https://github.com/elastic/ecs-logging-nodejs/issues/95)) + ## v1.1.0 - Update @elastic/ecs-helpers@1.1.0 to get more robust HTTP req and res diff --git a/loggers/morgan/examples/express-with-apm.js b/loggers/morgan/examples/express-with-apm.js index 52c8871..99bfca9 100644 --- a/loggers/morgan/examples/express-with-apm.js +++ b/loggers/morgan/examples/express-with-apm.js @@ -22,9 +22,9 @@ // // If usage of Elastic APM is detected (i.e. the "elastic-apm-node" package // is being used), then log records will include trace identifiers, e.g.: -// "trace": { "id": "678f2a0189f259baf2ea17db8af5a4d0" }, -// "transaction": { "id": "1cc6339964575165" }, -// "span": { "id": "f72c52ceda81777a" }, +// "trace.id": "678f2a0189f259baf2ea17db8af5a4d0", +// "transaction.id": "1cc6339964575165", +// "span.id": "f72c52ceda81777a", // to correlate log and trace data in Kibana. /* eslint-disable-next-line no-unused-vars */ @@ -32,7 +32,8 @@ const apm = require('elastic-apm-node').start({ serviceName: 'express-with-elastic-apm', centralConfig: false, captureExceptions: false, - metricsInterval: 0 + metricsInterval: '0s', + logLevel: 'warn' // avoid APM agent log preamble }) const app = require('express')() diff --git a/loggers/morgan/index.js b/loggers/morgan/index.js index a3f3f09..498a991 100644 --- a/loggers/morgan/index.js +++ b/loggers/morgan/index.js @@ -45,7 +45,7 @@ try { // APM agent is detected, then log records will include the following // fields: // - "service.name" - the configured serviceName in the agent -// - "event.dataset" - set to "$serviceName.log" for correlation in Kibana +// - "event.dataset" - set to "$serviceName" for correlation in Kibana // - "trace.id", "transaction.id", and "span.id" - if there is a current // active trace when the log call is made // Default true. @@ -82,21 +82,17 @@ function ecsFormat (opts) { apm = elasticApm } - let serviceField - let eventField + const extraFields = {} if (apm) { - // https://github.com/elastic/apm-agent-nodejs/pull/1949 is adding - // getServiceName() in v3.11.0. Fallback to private `apm._conf`. // istanbul ignore next const serviceName = apm.getServiceName - ? apm.getServiceName() + ? apm.getServiceName() // added in elastic-apm-node@3.11.0 : apm._conf.serviceName - // A mis-configured APM Agent can be "started" but not have a - // "serviceName". + // A mis-configured APM Agent can be "started" but not have a "serviceName". // istanbul ignore else if (serviceName) { - serviceField = { name: serviceName } - eventField = { dataset: serviceName + '.log' } + extraFields['service.name'] = serviceName + extraFields['event.dataset'] = serviceName } } @@ -105,14 +101,8 @@ function ecsFormat (opts) { '@timestamp': new Date().toISOString(), 'log.level': res.statusCode < 500 ? 'info' : 'error', message: fmt(token, req, res), - ecs: { version } - } - - if (serviceField) { - ecsFields.service = serviceField - } - if (eventField) { - ecsFields.event = eventField + 'ecs.version': version, + ...extraFields } // https://www.elastic.co/guide/en/ecs/current/ecs-tracing.html @@ -120,10 +110,8 @@ function ecsFormat (opts) { const tx = apm.currentTransaction // istanbul ignore else if (tx) { - ecsFields.trace = ecsFields.trace || {} - ecsFields.trace.id = tx.traceId - ecsFields.transaction = ecsFields.transaction || {} - ecsFields.transaction.id = tx.id + ecsFields['trace.id'] = tx.traceId + ecsFields['transaction.id'] = tx.id // Not including `span.id` because the way morgan logs (on the HTTP // Response "finished" event), any spans during the request handler // are no longer active. diff --git a/loggers/morgan/test/apm.test.js b/loggers/morgan/test/apm.test.js index f816251..7b9ac29 100644 --- a/loggers/morgan/test/apm.test.js +++ b/loggers/morgan/test/apm.test.js @@ -132,10 +132,10 @@ test('tracing integration works', t => { t.ok(traceObjs[0].metadata, 'traceObjs[0] is metadata') t.ok(traceObjs[1].transaction, 'traceObjs[1] is transaction') const tx = traceObjs[1].transaction - t.equal(logObjs[0].trace.id, tx.trace_id, 'trace.id matches') - t.equal(logObjs[0].transaction.id, tx.id, 'transaction.id matches') - t.equal(logObjs[0].service.name, 'test-apm') - t.equal(logObjs[0].event.dataset, 'test-apm.log') + t.equal(logObjs[0]['trace.id'], tx.trace_id, 'trace.id matches') + t.equal(logObjs[0]['transaction.id'], tx.id, 'transaction.id matches') + t.equal(logObjs[0]['service.name'], 'test-apm') + t.equal(logObjs[0]['event.dataset'], 'test-apm') finish() } } diff --git a/loggers/pino/CHANGELOG.md b/loggers/pino/CHANGELOG.md index 0f3461d..0122162 100644 --- a/loggers/pino/CHANGELOG.md +++ b/loggers/pino/CHANGELOG.md @@ -1,5 +1,16 @@ # @elastic/ecs-pino-format Changelog +## Unreleased + +- Change to adding dotted field names (`"ecs.version": "1.6.0"`), rather than + namespaced fields (`"ecs": {"version": "1.6.0"}`) for most fields. This is + supported by the ecs-logging spec, and arguably preferred in the ECS logging + docs. It is also what the ecs-logging-java libraries do. The resulting output + is slightly shorter, and accidental collisions with user fields is less + likely. +- Stop adding ".log" suffix to `event.dataset` field. + ([#95](https://github.com/elastic/ecs-logging-nodejs/issues/95)) + ## v1.3.0 - TypeScript types. ([#82](https://github.com/elastic/ecs-logging-nodejs/pull/82)) diff --git a/loggers/pino/examples/http-with-elastic-apm.js b/loggers/pino/examples/http-with-elastic-apm.js index 65a6e78..85a83ce 100644 --- a/loggers/pino/examples/http-with-elastic-apm.js +++ b/loggers/pino/examples/http-with-elastic-apm.js @@ -22,9 +22,9 @@ // // If usage of Elastic APM is detected (i.e. the "elastic-apm-node" package // is being used), then log records will include trace identifiers, e.g.: -// "trace": { "id": "678f2a0189f259baf2ea17db8af5a4d0" }, -// "transaction": { "id": "1cc6339964575165" }, -// "span": { "id": "f72c52ceda81777a" }, +// "trace.id": "678f2a0189f259baf2ea17db8af5a4d0", +// "transaction.id": "1cc6339964575165", +// "span.id": "f72c52ceda81777a", // to correlate log and trace data in Kibana. /* eslint-disable-next-line no-unused-vars */ @@ -32,7 +32,8 @@ const apm = require('elastic-apm-node').start({ serviceName: 'http-with-elastic-apm', centralConfig: false, captureExceptions: false, - metricsInterval: 0 + metricsInterval: '0s', + logLevel: 'warn' // avoid APM agent log preamble }) const http = require('http') diff --git a/loggers/pino/index.d.ts b/loggers/pino/index.d.ts index e419df4..215b2b4 100644 --- a/loggers/pino/index.d.ts +++ b/loggers/pino/index.d.ts @@ -18,7 +18,7 @@ interface Config { * fields: * * - "service.name" - the configured serviceName in the agent - * - "event.dataset" - set to "$serviceName.log" for correlation in Kibana + * - "event.dataset" - set to "$serviceName" for correlation in Kibana * - "trace.id", "transaction.id", and "span.id" - if there is a current * active trace when the log call is made * diff --git a/loggers/pino/index.js b/loggers/pino/index.js index 2f0f8d5..24055ec 100644 --- a/loggers/pino/index.js +++ b/loggers/pino/index.js @@ -42,7 +42,7 @@ let elasticApm = null // APM agent is detected, then log records will include the following // fields: // - "service.name" - the configured serviceName in the agent -// - "event.dataset" - set to "$serviceName.log" for correlation in Kibana +// - "event.dataset" - set to "$serviceName" for correlation in Kibana // - "trace.id", "transaction.id", and "span.id" - if there is a current // active trace when the log call is made // Default true. @@ -85,16 +85,21 @@ function createEcsPinoOptions (opts) { } if (elasticApm && elasticApm.isStarted && elasticApm.isStarted()) { apm = elasticApm - // Elastic APM v3.11.0 added getServiceName(). Fallback to private `apm._conf`. // istanbul ignore next apmServiceName = apm.getServiceName - ? apm.getServiceName() + ? apm.getServiceName() // added in elastic-apm-node@3.11.0 : apm._conf.serviceName } } - let isServiceNameInBindings = false - let isEventDatasetInBindings = false + let wasBindingsCalled = false + function addStaticEcsBindings (obj) { + obj['ecs.version'] = version + if (apmServiceName) { + obj['service.name'] = apmServiceName + obj['event.dataset'] = apmServiceName + } + } const ecsPinoOptions = { messageKey: 'message', @@ -112,32 +117,27 @@ function createEcsPinoOptions (opts) { hostname, // name is defined if `log = pino({name: 'my name', ...})` name, - // Warning: silently drop any "ecs" value from `base`. See - // "ecs.version" comment below. - ecs, ...ecsBindings } = bindings if (pid !== undefined) { // https://www.elastic.co/guide/en/ecs/current/ecs-process.html#field-process-pid - ecsBindings.process = { pid: pid } + ecsBindings['process.pid'] = pid } if (hostname !== undefined) { // https://www.elastic.co/guide/en/ecs/current/ecs-host.html#field-host-hostname - ecsBindings.host = { hostname: hostname } + ecsBindings['host.hostname'] = hostname } if (name !== undefined) { // https://www.elastic.co/guide/en/ecs/current/ecs-log.html#field-log-logger - ecsBindings.log = { logger: name } + ecsBindings['log.logger'] = name } - // Note if service.name & event.dataset are set, to not do so again below. - if (bindings.service && bindings.service.name) { - isServiceNameInBindings = true - } - if (bindings.event && bindings.event.dataset) { - isEventDatasetInBindings = true - } + // With `pino({base: null, ...})` the `formatters.bindings` is *not* + // called. In this case we need to make sure to add our static bindings + // in `log()` below. + wasBindingsCalled = true + addStaticEcsBindings(ecsBindings) return ecsBindings }, @@ -150,56 +150,20 @@ function createEcsPinoOptions (opts) { ...ecsObj } = obj - // https://www.elastic.co/guide/en/ecs/current/ecs-ecs.html - // For "ecs.version" we take a heavier-handed approach, because it is - // a require ecs-logging field: overwrite any possible "ecs" value from - // the log statement. This means we don't need to spend the time - // guarding against "ecs" being null, Array, Buffer, Date, etc. - ecsObj.ecs = { version } + if (!wasBindingsCalled) { + addStaticEcsBindings(ecsObj) + } if (apm) { - // A mis-configured APM Agent can be "started" but not have a - // "serviceName". - if (apmServiceName) { - // Per https://github.com/elastic/ecs-logging/blob/main/spec/spec.json - // "service.name" and "event.dataset" should be automatically set - // if not already by the user. - if (!isServiceNameInBindings) { - const service = ecsObj.service - if (service === undefined) { - ecsObj.service = { name: apmServiceName } - } else if (!isVanillaObject(service)) { - // Warning: "service" type conflicts with ECS spec. Overwriting. - ecsObj.service = { name: apmServiceName } - } else if (typeof service.name !== 'string') { - ecsObj.service.name = apmServiceName - } - } - if (!isEventDatasetInBindings) { - const event = ecsObj.event - if (event === undefined) { - ecsObj.event = { dataset: apmServiceName + '.log' } - } else if (!isVanillaObject(event)) { - // Warning: "event" type conflicts with ECS spec. Overwriting. - ecsObj.event = { dataset: apmServiceName + '.log' } - } else if (typeof event.dataset !== 'string') { - ecsObj.event.dataset = apmServiceName + '.log' - } - } - } - // https://www.elastic.co/guide/en/ecs/current/ecs-tracing.html const tx = apm.currentTransaction if (tx) { - ecsObj.trace = ecsObj.trace || {} - ecsObj.trace.id = tx.traceId - ecsObj.transaction = ecsObj.transaction || {} - ecsObj.transaction.id = tx.id + ecsObj['trace.id'] = tx.traceId + ecsObj['transaction.id'] = tx.id const span = apm.currentSpan // istanbul ignore else if (span) { - ecsObj.span = ecsObj.span || {} - ecsObj.span.id = span.id + ecsObj['span.id'] = span.id } } } @@ -237,19 +201,4 @@ function createEcsPinoOptions (opts) { return ecsPinoOptions } -// Return true if the given arg is a "vanilla" object. Roughly the intent is -// whether this is basic mapping of string keys to values that will serialize -// as a JSON object. -// -// Currently, it excludes Map. The uses above don't really expect a user to: -// service = new Map([["foo", "bar"]]) -// log.info({ service }, '...') -// -// There are many ways tackle this. See some attempts and benchmarks at: -// https://gist.github.com/trentm/34131a92eede80fd2109f8febaa56f5a -function isVanillaObject (o) { - return (typeof o === 'object' && - (!o.constructor || o.constructor.name === 'Object')) -} - module.exports = createEcsPinoOptions diff --git a/loggers/pino/test/apm.test.js b/loggers/pino/test/apm.test.js index d7a1e1b..2dc80bf 100644 --- a/loggers/pino/test/apm.test.js +++ b/loggers/pino/test/apm.test.js @@ -130,11 +130,11 @@ test('tracing integration works', t => { const span = traceObjs[1].span || traceObjs[2].span t.ok(trans, 'got transaction') t.ok(span, 'got span') - t.equal(logObjs[0].trace.id, span.trace_id, 'trace.id matches') - t.equal(logObjs[0].transaction.id, span.transaction_id, 'transaction.id matches') - t.equal(logObjs[0].span.id, span.id, 'span.id matches') - t.equal(logObjs[0].service.name, 'test-apm') - t.equal(logObjs[0].event.dataset, 'test-apm.log') + t.equal(logObjs[0]['trace.id'], span.trace_id, 'trace.id matches') + t.equal(logObjs[0]['transaction.id'], span.transaction_id, 'transaction.id matches') + t.equal(logObjs[0]['span.id'], span.id, 'span.id matches') + t.equal(logObjs[0]['service.name'], 'test-apm') + t.equal(logObjs[0]['event.dataset'], 'test-apm') finish() } } @@ -323,64 +323,30 @@ test('apmIntegration=false disables tracing integration', t => { }) }) -test('can override service.name, event.dataset', t => { - execFile(process.execPath, [ - path.join(__dirname, 'use-apm-override-service-name.js'), - 'test-apm' - ], { - timeout: 5000 - }, function (err, stdout, stderr) { - t.error(err) - const recs = stdout.trim().split(/\n/g).map(JSON.parse) - t.equal(recs[0].service.name, 'myname') - t.equal(recs[0].event.dataset, 'mydataset') - - // If integrating with APM and the log record sets "service.name" to a - // non-string or "service" to a non-object, then ecs-pino-format will - // overwrite it because it conflicts with the ECS specified type. - t.equal(recs[1].service.name, 'test-apm') - t.equal(recs[1].event.dataset, 'test-apm.log') - t.equal(recs[2].service.name, 'test-apm') - t.equal(recs[2].event.dataset, 'test-apm.log') - - t.equal(recs[3].service.name, 'test-apm') - t.equal(recs[3].event.dataset, 'test-apm.log') - t.end() - }) -}) - -test('can override service.name, event.dataset in base arg to constructor', t => { - execFile(process.execPath, [ - path.join(__dirname, 'use-apm-override-service-name.js'), - 'test-apm', // apm "serviceName" - 'mybindingname' // pino logger "service.name" value for `base` arg - ], { - timeout: 5000 - }, function (err, stdout, stderr) { - t.error(err) - const recs = stdout.trim().split(/\n/g).map(JSON.parse) - t.equal(recs[0].service.name, 'myname') - t.equal(recs[0].event.dataset, 'mydataset') - - t.equal(recs[3].service.name, 'mybindingname') - t.equal(recs[3].event.dataset, 'mybindingname') - t.end() - }) -}) - -test('invalid APM serviceName does not set service.name or event.dataset, but also does not break', t => { - execFile(process.execPath, [ - path.join(__dirname, 'use-apm-override-service-name.js'), - 'foo☃bar' // Use an invalid . - ], { - timeout: 5000 - }, function (err, stdout, stderr) { - t.error(err) - const recs = stdout.trim().split(/\n/g).map(JSON.parse) - t.equal(recs[0].service.name, 'myname') - t.equal(recs[0].event.dataset, 'mydataset') - t.equal(recs[3].service, undefined) - t.equal(recs[3].event, undefined) - t.end() - }) +test('invalid APM serviceName does not set service.name or event.dataset', t => { + execFile( + process.execPath, + ['simple-log-hi.js'], + { + cwd: __dirname, + env: Object.assign( + {}, + process.env, + { + NODE_OPTIONS: '--require elastic-apm-node/start.js', + ELASTIC_APM_LOG_LEVEL: 'off', + ELASTIC_APM_SERVICE_NAME: 'foo☃bar' + } + ), + timeout: 5000 + }, + function (err, stdout, _stderr) { + t.error(err) + const recs = stdout.trim().split(/\n/g).map(JSON.parse) + t.equal(recs[0].message, 'hi') + t.equal(recs[0]['service.name'], undefined) + t.equal(recs[0]['event.dataset'], undefined) + t.end() + } + ) }) diff --git a/loggers/pino/test/basic.test.js b/loggers/pino/test/basic.test.js index 8f73702..849d35e 100644 --- a/loggers/pino/test/basic.test.js +++ b/loggers/pino/test/basic.test.js @@ -49,9 +49,9 @@ test('ecsPinoFormat cases', suite => { }, rec: { 'log.level': 'info', - ecs: { version: ecsVersion }, - process: { pid: process.pid }, - host: { hostname: os.hostname }, + 'process.pid': process.pid, + 'host.hostname': os.hostname(), + 'ecs.version': ecsVersion, message: 'Hello, world!' } }, @@ -63,10 +63,10 @@ test('ecsPinoFormat cases', suite => { }, rec: { 'log.level': 'info', - ecs: { version: ecsVersion }, - process: { pid: process.pid }, - host: { hostname: os.hostname }, - log: { logger: 'myName' }, + 'process.pid': process.pid, + 'host.hostname': os.hostname(), + 'log.logger': 'myName', + 'ecs.version': ecsVersion, message: 'hi' } }, @@ -78,9 +78,9 @@ test('ecsPinoFormat cases', suite => { }, rec: { 'log.level': 'info', - ecs: { version: ecsVersion }, - process: { pid: process.pid }, - host: { hostname: os.hostname }, + 'process.pid': process.pid, + 'host.hostname': os.hostname(), + 'ecs.version': ecsVersion, message: 'hi', foo: 'bar' } @@ -93,9 +93,9 @@ test('ecsPinoFormat cases', suite => { }, rec: { 'log.level': 'info', - ecs: { version: ecsVersion }, - process: { pid: process.pid }, - host: { hostname: os.hostname }, + 'process.pid': process.pid, + 'host.hostname': os.hostname(), + 'ecs.version': ecsVersion, message: 'hi', req: { id: 42 }, res: { status: 'OK' } @@ -109,7 +109,7 @@ test('ecsPinoFormat cases', suite => { }, rec: { 'log.level': 'info', - ecs: { version: ecsVersion }, + 'ecs.version': ecsVersion, message: 'hi' } }, @@ -128,7 +128,7 @@ test('ecsPinoFormat cases', suite => { }, rec: { 'log.level': 'info', - ecs: { version: ecsVersion }, + 'ecs.version': ecsVersion, message: 'hi' } }, @@ -140,9 +140,9 @@ test('ecsPinoFormat cases', suite => { }, rec: { 'log.level': 'info', - ecs: { version: ecsVersion }, - process: { pid: process.pid }, - host: { hostname: os.hostname }, + 'process.pid': process.pid, + 'host.hostname': os.hostname(), + 'ecs.version': ecsVersion, foo: 'bar' } } @@ -161,7 +161,7 @@ test('ecsPinoFormat cases', suite => { t.equal(ecsLoggingValidate(lines[0], { ignoreIndex: true }), null) delete rec['@timestamp'] // normalize before comparison - t.same(rec, fc.rec, 'logged record matches expected record') + t.strictSame(rec, fc.rec, 'logged record matches expected record') t.end() }) @@ -241,7 +241,7 @@ test('convertErr does not blow up on non-Errors', t => { t.equal(recs[0].err, 42) t.equal(recs[1].err, false) t.equal(recs[2].err, null) - t.same(recs[3].err, { foo: 'bar' }) + t.strictSame(recs[3].err, { foo: 'bar' }) t.end() }) diff --git a/loggers/pino/test/simple-log-hi.js b/loggers/pino/test/simple-log-hi.js new file mode 100644 index 0000000..d49114e --- /dev/null +++ b/loggers/pino/test/simple-log-hi.js @@ -0,0 +1,26 @@ +// Licensed to Elasticsearch B.V. under one or more contributor +// license agreements. See the NOTICE file distributed with +// this work for additional information regarding copyright +// ownership. Elasticsearch B.V. licenses this file to you under +// the Apache License, Version 2.0 (the "License"); you may +// not use this file except in compliance with the License. +// You may obtain a copy of the License at +// +// http://www.apache.org/licenses/LICENSE-2.0 +// +// Unless required by applicable law or agreed to in writing, +// software distributed under the License is distributed on an +// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY +// KIND, either express or implied. See the License for the +// specific language governing permissions and limitations +// under the License. + +'use strict' + +// This script is used by "apm.test.js". + +const ecsFormat = require('../') // @elastic/ecs-pino-format +const pino = require('pino') + +const log = pino(ecsFormat()) +log.info('hi') diff --git a/loggers/pino/test/use-apm-override-service-name.js b/loggers/pino/test/use-apm-override-service-name.js deleted file mode 100644 index fd125f3..0000000 --- a/loggers/pino/test/use-apm-override-service-name.js +++ /dev/null @@ -1,51 +0,0 @@ -// Licensed to Elasticsearch B.V. under one or more contributor -// license agreements. See the NOTICE file distributed with -// this work for additional information regarding copyright -// ownership. Elasticsearch B.V. licenses this file to you under -// the Apache License, Version 2.0 (the "License"); you may -// not use this file except in compliance with the License. -// You may obtain a copy of the License at -// -// http://www.apache.org/licenses/LICENSE-2.0 -// -// Unless required by applicable law or agreed to in writing, -// software distributed under the License is distributed on an -// "AS IS" BASIS, WITHOUT WARRANTIES OR CONDITIONS OF ANY -// KIND, either express or implied. See the License for the -// specific language governing permissions and limitations -// under the License. - -'use strict' - -// This script is used by "apm.test.js". -// -// It will: -// - use the APM agent (using serviceName from argv[2]) -// - log, setting service.name and event.dataset -// - log, without setting service.name and event.dataset -// - flush APM and exit - -const serviceName = process.argv[2] || '' -const pinoServiceName = process.argv[3] || '' -/* eslint-disable-next-line no-unused-vars */ -const apm = require('elastic-apm-node').start({ - // Use default serverUrl (fire and forget) - serviceName, - centralConfig: false, - captureExceptions: false, - metricsInterval: 0, - logLevel: 'off' -}) - -const ecsFormat = require('../') // @elastic/ecs-pino-format -const pino = require('pino') - -const pinoOpts = ecsFormat() -if (pinoServiceName) { - pinoOpts.base = { service: { name: pinoServiceName }, event: { dataset: pinoServiceName } } -} -const log = pino(pinoOpts) -log.info({ service: { name: 'myname' }, event: { dataset: 'mydataset' } }, 'override values') -log.info({ service: { name: 42 }, event: { dataset: 42 } }, 'override values with nums') -log.info({ service: 'myname', event: 'myevent' }, 'override top-level keys with invalid ECS type') -log.info('bye') diff --git a/loggers/winston/CHANGELOG.md b/loggers/winston/CHANGELOG.md index 4608227..7e36a71 100644 --- a/loggers/winston/CHANGELOG.md +++ b/loggers/winston/CHANGELOG.md @@ -1,5 +1,16 @@ # @elastic/ecs-winston-format Changelog +## Unreleased + +- Change to adding dotted field names (`"ecs.version": "1.6.0"`), rather than + namespaced fields (`"ecs": {"version": "1.6.0"}`) for most fields. This is + supported by the ecs-logging spec, and arguably preferred in the ECS logging + docs. It is also what the ecs-logging-java libraries do. The resulting output + is slightly shorter, and accidental collisions with user fields is less + likely. +- Stop adding ".log" suffix to `event.dataset` field. + ([#95](https://github.com/elastic/ecs-logging-nodejs/issues/95)) + ## v1.3.1 - Fix types expression in ambient context error. diff --git a/loggers/winston/examples/http-with-elastic-apm.js b/loggers/winston/examples/http-with-elastic-apm.js index 6a0879d..09013af 100644 --- a/loggers/winston/examples/http-with-elastic-apm.js +++ b/loggers/winston/examples/http-with-elastic-apm.js @@ -22,9 +22,9 @@ // // If usage of Elastic APM is detected (i.e. the "elastic-apm-node" package // is being used), then log records will include trace identifiers, e.g.: -// "trace": { "id": "678f2a0189f259baf2ea17db8af5a4d0" }, -// "transaction": { "id": "1cc6339964575165" }, -// "span": { "id": "f72c52ceda81777a" }, +// "trace.id": "678f2a0189f259baf2ea17db8af5a4d0", +// "transaction.id": "1cc6339964575165", +// "span.id": "f72c52ceda81777a", // to correlate log and trace data in Kibana. /* eslint-disable-next-line no-unused-vars */ @@ -32,7 +32,8 @@ const apm = require('elastic-apm-node').start({ serviceName: 'http-with-elastic-apm', centralConfig: false, captureExceptions: false, - metricsInterval: 0 + metricsInterval: '0s', + logLevel: 'warn' // avoid APM agent log preamble }) const http = require('http') diff --git a/loggers/winston/index.d.ts b/loggers/winston/index.d.ts index 99b6f25..fe9e00b 100644 --- a/loggers/winston/index.d.ts +++ b/loggers/winston/index.d.ts @@ -18,7 +18,7 @@ interface Config { * fields: * * - "service.name" - the configured serviceName in the agent - * - "event.dataset" - set to "$serviceName.log" for correlation in Kibana + * - "event.dataset" - set to "$serviceName" for correlation in Kibana * - "trace.id", "transaction.id", and "span.id" - if there is a current * active trace when the log call is made * diff --git a/loggers/winston/index.js b/loggers/winston/index.js index 25e26bd..45e627b 100644 --- a/loggers/winston/index.js +++ b/loggers/winston/index.js @@ -58,7 +58,7 @@ const reservedFields = { // APM agent is detected, then log records will include the following // fields: // - "service.name" - the configured serviceName in the agent -// - "event.dataset" - set to "$serviceName.log" for correlation in Kibana +// - "event.dataset" - set to "$serviceName" for correlation in Kibana // - "trace.id", "transaction.id", and "span.id" - if there is a current // active trace when the log call is made // Default true. @@ -83,7 +83,7 @@ function ecsTransform (info, opts) { '@timestamp': new Date().toISOString(), 'log.level': info.level, message: info.message, - ecs: { version } + 'ecs.version': version } // Add all unreserved fields. @@ -102,53 +102,26 @@ function ecsTransform (info, opts) { // istanbul ignore else if (apm) { - // Set "service.name" and "event.dataset" from APM conf, if not already set. - let serviceName = (ecsFields.service && ecsFields.service.name && typeof ecsFields.service.name === 'string' - ? ecsFields.service.name - : undefined) - if (!serviceName) { - // istanbul ignore next - serviceName = apm.getServiceName - ? apm.getServiceName() // added in elastic-apm-node@3.11.0 - : apm._conf.serviceName // fallback to private `_conf` - // A mis-configured APM Agent can be "started" but not have a - // "serviceName". - if (serviceName) { - if (ecsFields.service === undefined) { - ecsFields.service = { name: serviceName } - } else if (!isVanillaObject(ecsFields.service)) { - // Warning: "service" type conflicts with ECS spec. Overwriting. - ecsFields.service = { name: serviceName } - } else { - ecsFields.service.name = serviceName - } - } - } - if (serviceName && - !(ecsFields.event && ecsFields.event.dataset && - typeof ecsFields.event.dataset === 'string')) { - if (ecsFields.event === undefined) { - ecsFields.event = { dataset: serviceName + '.log' } - } else if (!isVanillaObject(ecsFields.event)) { - // Warning: "event" type conflicts with ECS spec. Overwriting. - ecsFields.event = { dataset: serviceName + '.log' } - } else { - ecsFields.event.dataset = serviceName + '.log' - } + // Set "service.name" and "event.dataset" from APM conf. + // istanbul ignore next + const serviceName = apm.getServiceName + ? apm.getServiceName() // added in elastic-apm-node@3.11.0 + : apm._conf.serviceName // fallback to private `_conf` + // A mis-configured APM Agent can be "started" but not have a "serviceName". + if (serviceName) { + ecsFields['service.name'] = serviceName + ecsFields['event.dataset'] = serviceName } // https://www.elastic.co/guide/en/ecs/current/ecs-tracing.html const tx = apm.currentTransaction if (tx) { - ecsFields.trace = ecsFields.trace || {} - ecsFields.trace.id = tx.traceId - ecsFields.transaction = ecsFields.transaction || {} - ecsFields.transaction.id = tx.id + ecsFields['trace.id'] = tx.traceId + ecsFields['transaction.id'] = tx.id const span = apm.currentSpan // istanbul ignore else if (span) { - ecsFields.span = ecsFields.span || {} - ecsFields.span.id = span.id + ecsFields['span.id'] = span.id } } } @@ -182,19 +155,4 @@ function ecsTransform (info, opts) { return info } -// Return true if the given arg is a "vanilla" object. Roughly the intent is -// whether this is basic mapping of string keys to values that will serialize -// as a JSON object. -// -// Currently, it excludes Map. The uses above don't really expect a user to: -// service = new Map([["foo", "bar"]]) -// log.info({ service }, '...') -// -// There are many ways tackle this. See some attempts and benchmarks at: -// https://gist.github.com/trentm/34131a92eede80fd2109f8febaa56f5a -function isVanillaObject (o) { - return (typeof o === 'object' && - (!o.constructor || o.constructor.name === 'Object')) -} - module.exports = format(ecsTransform) diff --git a/loggers/winston/test/apm.test.js b/loggers/winston/test/apm.test.js index e1ecdd7..5a66d6f 100644 --- a/loggers/winston/test/apm.test.js +++ b/loggers/winston/test/apm.test.js @@ -132,11 +132,11 @@ test('tracing integration works', t => { const span = traceObjs[1].span || traceObjs[2].span t.ok(trans, 'got transaction') t.ok(span, 'got span') - t.equal(logObjs[0].trace.id, span.trace_id, 'trace.id matches') - t.equal(logObjs[0].transaction.id, span.transaction_id, 'transaction.id matches') - t.equal(logObjs[0].span.id, span.id, 'span.id matches') - t.equal(logObjs[0].service.name, 'test-apm', 'service.name matches') - t.equal(logObjs[0].event.dataset, 'test-apm.log', 'event.dataset matches') + t.equal(logObjs[0]['trace.id'], span.trace_id, 'trace.id matches') + t.equal(logObjs[0]['transaction.id'], span.transaction_id, 'transaction.id matches') + t.equal(logObjs[0]['span.id'], span.id, 'span.id matches') + t.equal(logObjs[0]['service.name'], 'test-apm', 'service.name matches') + t.equal(logObjs[0]['event.dataset'], 'test-apm', 'event.dataset matches') finish() } } @@ -327,45 +327,30 @@ test('apmIntegration=false disables tracing integration', t => { }) }) -test('can override service.name, event.dataset', t => { - execFile(process.execPath, [ - path.join(__dirname, 'use-apm-override-service-name.js'), - 'test-apm' - ], { - timeout: 5000 - }, function (err, stdout, stderr) { - t.error(err) - const recs = stdout.trim().split(/\n/g).map(JSON.parse) - t.equal(recs[0].service.name, 'myname') - t.equal(recs[0].event.dataset, 'mydataset') - - // If integrating with APM and the log record sets "service.name" to a - // non-string or "service" to a non-object, then ecs-winston-format will - // overwrite it because it conflicts with the ECS specified type. - t.equal(recs[1].service.name, 'test-apm') - t.equal(recs[1].event.dataset, 'test-apm.log') - t.equal(recs[2].service.name, 'test-apm') - t.equal(recs[2].event.dataset, 'test-apm.log') - - t.equal(recs[3].service.name, 'test-apm') - t.equal(recs[3].event.dataset, 'test-apm.log') - t.end() - }) -}) - -test('invalid APM serviceName does not set service.name or event.dataset, but also does not break', t => { - execFile(process.execPath, [ - path.join(__dirname, 'use-apm-override-service-name.js'), - 'foo☃bar' // Use an invalid . - ], { - timeout: 5000 - }, function (err, stdout, stderr) { - t.error(err) - const recs = stdout.trim().split(/\n/g).map(JSON.parse) - t.equal(recs[0].service.name, 'myname') - t.equal(recs[0].event.dataset, 'mydataset') - t.equal(recs[3].service, undefined) - t.equal(recs[3].event, undefined) - t.end() - }) +test('invalid APM serviceName does not set service.name or event.dataset', t => { + execFile( + process.execPath, + ['simple-log-hi.js'], + { + cwd: __dirname, + env: Object.assign( + {}, + process.env, + { + NODE_OPTIONS: '--require elastic-apm-node/start.js', + ELASTIC_APM_LOG_LEVEL: 'off', + ELASTIC_APM_SERVICE_NAME: 'foo☃bar' + } + ), + timeout: 5000 + }, + function (err, stdout, _stderr) { + t.error(err) + const recs = stdout.trim().split(/\n/g).map(JSON.parse) + t.equal(recs[0].message, 'hi') + t.equal(recs[0]['service.name'], undefined) + t.equal(recs[0]['event.dataset'], undefined) + t.end() + } + ) }) diff --git a/loggers/winston/test/basic.test.js b/loggers/winston/test/basic.test.js index 7dbb2c0..fd6daa2 100644 --- a/loggers/winston/test/basic.test.js +++ b/loggers/winston/test/basic.test.js @@ -142,8 +142,8 @@ test('Should not be able to override ECS fields with additional fields', t => { }) const rec = cap.records[0] - t.equal(rec['log.level'], 'info', '"log.level"') - t.equal(rec.ecs.version, version, 'ecs.version') + t.equal(rec['log.level'], 'info', 'log.level') + t.equal(rec['ecs.version'], version, 'ecs.version') t.not(rec['@timestamp'], 'boom', '@timestamp') t.end() }) diff --git a/loggers/winston/test/use-apm-override-service-name.js b/loggers/winston/test/simple-log-hi.js similarity index 59% rename from loggers/winston/test/use-apm-override-service-name.js rename to loggers/winston/test/simple-log-hi.js index 43b3713..89b0950 100644 --- a/loggers/winston/test/use-apm-override-service-name.js +++ b/loggers/winston/test/simple-log-hi.js @@ -18,22 +18,6 @@ 'use strict' // This script is used by "apm.test.js". -// -// It will: -// - use the APM agent (using serviceName from argv[2]) -// - log, setting service.name and event.dataset -// - log, without setting service.name and event.dataset -// - flush APM and exit - -const serviceName = process.argv[2] || '' -require('elastic-apm-node').start({ - // Use default serverUrl (fire and forget) - serviceName, - centralConfig: false, - captureExceptions: false, - metricsInterval: 0, - logLevel: 'off' -}) const ecsFormat = require('../') // @elastic/ecs-winston-format const winston = require('winston') @@ -46,10 +30,4 @@ const log = winston.createLogger({ ] }) -log.info('override values', - { service: { name: 'myname' }, event: { dataset: 'mydataset' } }) -log.info('override values with nums', - { service: { name: 42 }, event: { dataset: 42 } }) -log.info('override top-level keys with invalid ECS type', - { service: 'myname', event: 'myevent' }) -log.info('bye') +log.info('hi')