Adding sever.logWithMetadata (#28767)

* Allowing first-class support of structured log messages

* Renaming to logWithMetadata and changing log statement structure

* Fixing unit tests

src/server/logging/index.js

@@ -19,6 +19,7 @@
 
 import good from '@elastic/good';
 import loggingConfiguration from './configuration';
+import { logWithMetadata } from './log_with_metadata';
 
 export async function setupLogging(server, config) {
   return await server.register({
@@ -28,5 +29,6 @@ export async function setupLogging(server, config) {
 }
 
 export async function loggingMixin(kbnServer, server, config) {
+  logWithMetadata.decorateServer(server);
   return await setupLogging(server, config);
 }

src/server/logging/log_format.js

@@ -26,6 +26,7 @@ import stringify from 'json-stringify-safe';
 import querystring from 'querystring';
 import applyFiltersToKeys from './apply_filters_to_keys';
 import { inspect } from 'util';
+import { logWithMetadata } from './log_with_metadata';
 
 function serializeError(err = {}) {
   return {
@@ -158,6 +159,9 @@ export default class TransformObjStream extends Stream.Transform {
       const message =  get(event, 'error.message');
       data.message = message || 'Unknown error object (no message)';
     }
+    else if (logWithMetadata.isLogEvent(event.data)) {
+      _.assign(data, logWithMetadata.getLogEventData(event.data));
+    }
     else if (_.isPlainObject(event.data) && event.data.tmpl) {
       _.assign(data, event.data);
       data.tmpl = undefined;

src/server/logging/log_with_metadata.js

@@ -0,0 +1,45 @@
+/*
+ * 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.
+ */
+import { isPlainObject } from 'lodash';
+const symbol = Symbol('log message with metadata');
+
+export const logWithMetadata = {
+  isLogEvent(eventData) {
+    return Boolean(isPlainObject(eventData) && eventData[symbol]);
+  },
+
+  getLogEventData(eventData) {
+    const { message, metadata } = eventData[symbol];
+    return {
+      ...metadata,
+      message
+    };
+  },
+
+  decorateServer(server) {
+    server.decorate('server', 'logWithMetadata', (tags, message, metadata = {}) => {
+      server.log(tags, {
+        [symbol]: {
+          message,
+          metadata,
+        },
+      });
+    });
+  },
+};

x-pack/server/lib/audit_logger.js

@@ -11,10 +11,9 @@ export class AuditLogger {
   }
 
   log(eventType, message, data = {}) {
-    this._server.log(['info', 'audit', this._pluginId, eventType], {
-      tmpl: message,
+    this._server.logWithMetadata(['info', 'audit', this._pluginId, eventType], message, {
+      ...data,
       eventType,
-      ...data
     });
   }
 }

x-pack/server/lib/audit_logger.test.js

@@ -7,49 +7,48 @@ import { AuditLogger } from './audit_logger';
 
 test(`calls server.log with 'info', audit', pluginId and eventType as tags`, () => {
   const mockServer = {
-    log: jest.fn()
+    logWithMetadata: jest.fn()
   };
   const pluginId = 'foo';
   const auditLogger = new AuditLogger(mockServer, pluginId);
 
   const eventType = 'bar';
   auditLogger.log(eventType, '');
-  expect(mockServer.log).toHaveBeenCalledTimes(1);
-  expect(mockServer.log).toHaveBeenCalledWith(['info', 'audit', pluginId, eventType], expect.anything());
+  expect(mockServer.logWithMetadata).toHaveBeenCalledTimes(1);
+  expect(mockServer.logWithMetadata).toHaveBeenCalledWith(['info', 'audit', pluginId, eventType], expect.anything(), expect.anything());
 });
 
 
-test(`calls server.log with message as tmpl`, () => {
+test(`calls server.log with message`, () => {
   const mockServer = {
-    log: jest.fn()
+    logWithMetadata: jest.fn()
   };
 
   const auditLogger = new AuditLogger(mockServer, 'foo');
 
   const message = 'summary of what happened';
   auditLogger.log('bar', message);
-  expect(mockServer.log).toHaveBeenCalledTimes(1);
-  expect(mockServer.log).toHaveBeenCalledWith(expect.anything(), expect.objectContaining({
-    tmpl: message
-  }));
+  expect(mockServer.logWithMetadata).toHaveBeenCalledTimes(1);
+  expect(mockServer.logWithMetadata).toHaveBeenCalledWith(expect.anything(), message, expect.anything());
 });
 
-test(`calls server.log with data appended to log message`, () => {
+test(`calls server.log with metadata `, () => {
   const mockServer = {
-    log: jest.fn()
+    logWithMetadata: jest.fn()
   };
 
   const auditLogger = new AuditLogger(mockServer, 'foo');
 
   const data = {
     foo: 'yup',
-    bar: 'nah',
+    baz: 'nah',
   };
 
   auditLogger.log('bar', 'summary of what happened', data);
-  expect(mockServer.log).toHaveBeenCalledTimes(1);
-  expect(mockServer.log).toHaveBeenCalledWith(expect.anything(), expect.objectContaining({
+  expect(mockServer.logWithMetadata).toHaveBeenCalledTimes(1);
+  expect(mockServer.logWithMetadata).toHaveBeenCalledWith(expect.anything(), expect.anything(), {
+    eventType: 'bar',
     foo: data.foo,
-    bar: data.bar,
-  }));
+    baz: data.baz,
+  });
 });