[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

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);
+      });
+    });
+  });
+});

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);