From 634bf10d49a09493541db3412e6c1628b0c6d548 Mon Sep 17 00:00:00 2001 From: Tim Sullivan Date: Thu, 30 Nov 2017 13:54:52 -0700 Subject: [PATCH] [6.0] [Logging] more tests and added robustness to log formatting (#15035) (#15163) (#15310) * [Logging] more tests and added robustness to log formatting (#15035) * [Logging] more tests and added robustness to log formatting * empty string for default error message, along with TODO question comment * try to use stack trace from error when there is no error message * simplify using the stack as the default error message * destructure get from lodash * default no-message to static string instead of error stack * fix tests * remove ineligible useUTC tests --- .../logging/__tests__/log_format_json.js | 180 ++++++++++++++++++ src/server/logging/log_format.js | 31 +-- 2 files changed, 197 insertions(+), 14 deletions(-) create mode 100644 src/server/logging/__tests__/log_format_json.js diff --git a/src/server/logging/__tests__/log_format_json.js b/src/server/logging/__tests__/log_format_json.js new file mode 100644 index 000000000000..60ada9b6353c --- /dev/null +++ b/src/server/logging/__tests__/log_format_json.js @@ -0,0 +1,180 @@ +import moment from 'moment'; +import expect from 'expect.js'; + +import { + createListStream, + createPromiseFromStreams, +} from '../../../utils'; + +import KbnLoggerJsonFormat from '../log_format_json'; + +const time = +moment('2010-01-01T05:15:59Z', moment.ISO_8601); + +const makeEvent = eventType => ({ + event: eventType, + timestamp: time, +}); + +describe('KbnLoggerJsonFormat', () => { + const config = {}; + + describe('event types and messages', () => { + let format; + beforeEach(() => { + format = new KbnLoggerJsonFormat(config); + }); + + it('log', async () => { + const result = await createPromiseFromStreams([ + createListStream([makeEvent('log')]), + format + ]); + const { type, message } = JSON.parse(result); + + expect(type).to.be('log'); + expect(message).to.be('undefined'); + }); + + it('response', async () => { + const event = { + ...makeEvent('response'), + statusCode: 200, + contentLength: 800, + responseTime: 12000, + method: 'GET', + path: '/path/to/resource', + responsePayload: '1234567879890', + source: { + remoteAddress: '127.0.0.1', + userAgent: 'Test Thing', + referer: 'elastic.co', + } + }; + const result = await createPromiseFromStreams([ + createListStream([event]), + format + ]); + const { type, method, statusCode, message } = JSON.parse(result); + + expect(type).to.be('response'); + expect(method).to.be('GET'); + expect(statusCode).to.be(200); + expect(message).to.be('GET /path/to/resource 200 12000ms - 13.0B'); + }); + + it('ops', async () => { + const event = { + ...makeEvent('ops'), + os: { + load: [1, 1, 2] + } + }; + const result = await createPromiseFromStreams([ + createListStream([event]), + format + ]); + const { type, message } = JSON.parse(result); + + expect(type).to.be('ops'); + expect(message).to.be('memory: 0.0B uptime: 0:00:00 load: [1.00 1.00 2.00] delay: 0.000'); + }); + + describe('errors', () => { + it('error type', async () => { + const event = { + ...makeEvent('error'), + error: { + message: 'test error 0' + } + }; + const result = await createPromiseFromStreams([ + createListStream([event]), + format + ]); + const { level, message, error } = JSON.parse(result); + + expect(level).to.be('error'); + expect(message).to.be('test error 0'); + expect(error).to.eql({ message: 'test error 0' }); + }); + + it('with no message', async () => { + const event = { + event: 'error', + error: {} + }; + const result = await createPromiseFromStreams([ + createListStream([event]), + format + ]); + const { level, message, error } = JSON.parse(result); + + expect(level).to.be('error'); + expect(message).to.be('Unknown error (no message)'); + expect(error).to.eql({}); + }); + + it('event data instanceof Error', async () => { + const event = { + data: new Error('test error 2'), + }; + const result = await createPromiseFromStreams([ + createListStream([event]), + format + ]); + const { level, message, error } = JSON.parse(result); + + expect(level).to.be('error'); + expect(message).to.be('test error 2'); + + expect(error.message).to.be(event.data.message); + expect(error.name).to.be(event.data.name); + expect(error.stack).to.be(event.data.stack); + expect(error.code).to.be(event.data.code); + expect(error.signal).to.be(event.data.signal); + }); + + it('event data instanceof Error - fatal', async () => { + const event = { + data: new Error('test error 2'), + tags: ['fatal', 'tag2'] + }; + const result = await createPromiseFromStreams([ + createListStream([event]), + format + ]); + const { tags, level, message, error } = JSON.parse(result); + + expect(tags).to.eql(['fatal', 'tag2']); + expect(level).to.be('fatal'); + expect(message).to.be('test error 2'); + + expect(error.message).to.be(event.data.message); + expect(error.name).to.be(event.data.name); + expect(error.stack).to.be(event.data.stack); + expect(error.code).to.be(event.data.code); + expect(error.signal).to.be(event.data.signal); + }); + + it('event data instanceof Error, no message', async () => { + const event = { + data: new Error(''), + }; + const result = await createPromiseFromStreams([ + createListStream([event]), + format + ]); + const { level, message, error } = JSON.parse(result); + + expect(level).to.be('error'); + expect(message).to.be('Unknown error object (no message)'); + + expect(error.message).to.be(event.data.message); + expect(error.name).to.be(event.data.name); + expect(error.stack).to.be(event.data.stack); + expect(error.code).to.be(event.data.code); + expect(error.signal).to.be(event.data.signal); + }); + }); + }); +}); diff --git a/src/server/logging/log_format.js b/src/server/logging/log_format.js index b5233ff52d02..8ab304e01956 100644 --- a/src/server/logging/log_format.js +++ b/src/server/logging/log_format.js @@ -1,6 +1,6 @@ import Stream from 'stream'; import moment from 'moment'; -import _ from 'lodash'; +import { get, _ } from 'lodash'; import numeral from '@elastic/numeral'; import ansicolors from 'ansicolors'; import stringify from 'json-stringify-safe'; @@ -8,7 +8,7 @@ import querystring from 'querystring'; import applyFiltersToKeys from './apply_filters_to_keys'; import { inspect } from 'util'; -function serializeError(err) { +function serializeError(err = {}) { return { message: err.message, name: err.name, @@ -60,13 +60,14 @@ module.exports = class TransformObjStream extends Stream.Transform { 'statusCode' ])); + const source = get(event, 'source', {}); data.req = { url: event.path, - method: event.method, + method: event.method || '', headers: event.headers, - remoteAddress: event.source.remoteAddress, - userAgent: event.source.remoteAddress, - referer: event.source.referer + remoteAddress: source.remoteAddress, + userAgent: source.remoteAddress, + referer: source.referer }; let contentLength = 0; @@ -85,8 +86,7 @@ module.exports = class TransformObjStream extends Stream.Transform { const query = querystring.stringify(event.query); if (query) data.req.url += '?' + query; - - data.message = data.req.method.toUpperCase() + ' '; + data.message = data.req.method.toUpperCase() + ' '; data.message += data.req.url; data.message += ' '; data.message += levelColor(data.res.statusCode); @@ -102,30 +102,33 @@ module.exports = class TransformObjStream extends Stream.Transform { 'load' ])); data.message = ansicolors.brightBlack('memory: '); - data.message += numeral(data.proc.mem.heapUsed).format('0.0b'); + data.message += numeral(get(data, 'proc.mem.heapUsed')).format('0.0b'); data.message += ' '; data.message += ansicolors.brightBlack('uptime: '); - data.message += numeral(data.proc.uptime).format('00:00:00'); + data.message += numeral(get(data, 'proc.uptime')).format('00:00:00'); data.message += ' '; data.message += ansicolors.brightBlack('load: ['); - data.message += data.os.load.map(function (val) { + data.message += get(data, 'os.load', []).map(function (val) { return numeral(val).format('0.00'); }).join(' '); data.message += ansicolors.brightBlack(']'); data.message += ' '; data.message += ansicolors.brightBlack('delay: '); - data.message += numeral(data.proc.delay).format('0.000'); + data.message += numeral(get(data, 'proc.delay')).format('0.000'); } else if (data.type === 'error') { data.level = 'error'; - data.message = event.error.message; data.error = serializeError(event.error); data.url = event.url; + const message = get(event, 'error.message'); + data.message = message || 'Unknown error (no message)'; } else if (event.data instanceof Error) { + data.type = 'error'; data.level = _.contains(event.tags, 'fatal') ? 'fatal' : 'error'; - data.message = event.data.message; data.error = serializeError(event.data); + const message = get(event, 'data.message'); + data.message = message || 'Unknown error object (no message)'; } else if (_.isPlainObject(event.data) && event.data.tmpl) { _.assign(data, event.data);