[core.logging] Add ops logs to the KP logging system

packages/kbn-legacy-logging/src/get_logging_config.ts

@@ -28,7 +28,10 @@ export function getLoggingConfiguration(config: LegacyLoggingConfig, opsInterval
   } else if (config.verbose) {
     _.defaults(events, {
       log: '*',
-      ops: '*',
+      // To avoid duplicate logs, we explicitly disable this in verbose
+      // mode as it is already provided by the new logging config under
+      // the `metrics.ops` context.
+      ops: '!',
       request: '*',
       response: '*',
       error: '*',

src/core/README.md

@@ -28,8 +28,10 @@ Even though the new validation system provided by the `core` is also based on Jo
 rules tailored to our needs (e.g. `byteSize`, `duration` etc.). That means that config values that were previously accepted
 by the "legacy" Kibana may be rejected by the `core` now.
 
-Even though `core` has its own logging system it doesn't output log records directly (e.g. to file or terminal), but instead
-forward them to the "legacy" Kibana so that they look the same as the rest of the log records throughout Kibana.
+### Logging
+`core` has its own [logging system](./server/logging/README.md) and will output log records directly (e.g. to file or terminal) when configured. When no 
+specific configuration is provided, logs are forwarded to the "legacy" Kibana so that they look the same as the rest of the
+log records throughout Kibana.
 
 ## Core API Review
 To provide a stable API for plugin developers, it is important that the Core Public and Server API's are stable and

src/core/server/config/deprecation/core_deprecations.test.ts

@@ -236,4 +236,24 @@ describe('core deprecations', () => {
       ).toEqual([`worker-src blob:`]);
     });
   });
+
+  describe('logging.events.ops', () => {
+    it('warns when ops events are used', () => {
+      const { messages } = applyCoreDeprecations({
+        logging: { events: { ops: '*' } },
+      });
+      expect(messages).toMatchInlineSnapshot(`
+        Array [
+          "\\"logging.events.ops\\" has been deprecated and will be removed in 8.0. To access ops data moving forward, please enable debug logs for the \\"metrics.ops\\" context in your logging configuration.",
+        ]
+      `);
+    });
+
+    it('does not warn when other events are configured', () => {
+      const { messages } = applyCoreDeprecations({
+        logging: { events: { log: '*' } },
+      });
+      expect(messages).toEqual([]);
+    });
+  });
 });

src/core/server/config/deprecation/core_deprecations.ts

@@ -103,6 +103,17 @@ const mapManifestServiceUrlDeprecation: ConfigDeprecation = (settings, fromPath,
   return settings;
 };
 
+const opsLoggingEventDeprecation: ConfigDeprecation = (settings, fromPath, log) => {
+  if (has(settings, 'logging.events.ops')) {
+    log(
+      '"logging.events.ops" has been deprecated and will be removed ' +
+        'in 8.0. To access ops data moving forward, please enable debug logs for the ' +
+        '"metrics.ops" context in your logging configuration.'
+    );
+  }
+  return settings;
+};
+
 export const coreDeprecationProvider: ConfigDeprecationProvider = ({ rename, unusedFromRoot }) => [
   unusedFromRoot('savedObjects.indexCheckTimeout'),
   unusedFromRoot('server.xsrf.token'),
@@ -137,4 +148,5 @@ export const coreDeprecationProvider: ConfigDeprecationProvider = ({ rename, unu
   rewriteBasePathDeprecation,
   cspRulesDeprecation,
   mapManifestServiceUrlDeprecation,
+  opsLoggingEventDeprecation,
 ];

src/core/server/logging/README.md

@@ -312,6 +312,9 @@ logging:
     - context: telemetry
       level: all
       appenders: [json-file-appender]
+    - context: metrics.ops
+      level: debug
+      appenders: [console]
 ```
 
 Here is what we get with the config above:
@@ -324,12 +327,33 @@ Here is what we get with the config above:
 | server           | console, file            | fatal |
 | optimize         | console                  | error |
 | telemetry        | json-file-appender       | all   |
+| metrics.ops      | console                  | debug |
+
 
+### Dedicated loggers
 
 The `root` logger has a dedicated configuration node since this context is special and should always exist. By 
 default `root` is configured with `info` level and `default` appender that is also always available. This is the 
 configuration that all custom loggers will use unless they're re-configured explicitly.
 
+The `metrics.ops` logger is configured with `debug` level and will automatically output sample system and process information at a regular interval.
+The metrics that are logged are a subset of the data collected and are formatted in the log message as follows:
+
+| Ops formatted log property | Location in metrics service | Log units
+| :------------------------- | :-------------------------- | :-------------------------- |
+| memory | process.memory.heap.used_in_bytes | [depends on the value](http://numeraljs.com/#format), typically MB or GB |
+| uptime  | process.uptime_in_millis | HH:mm:ss |
+| load  | os.load | [ "load for the last 1 min" "load for the last 5 min" "load for the last 15 min"] |
+| delay | process.event_loop_delay | ms |
+
+The log interval is the same as the interval at which system and process information is refreshed and is configurable under `ops.interval`:
+
+```yaml
+ops.interval: 5000
+```
+
+The minimum interval is 100ms and defaults to 5000ms.
+
 For example to see _all_ log messages that fall back on the `root` logger configuration, just add one line to the configuration:
 
 ```yaml
@@ -478,4 +502,4 @@ TBD
 | meta            | separate property `"meta": {"to": "v8"}`   | merged in log record  `{... "to": "v8"}`     |
 | pid             | `pid: 12345`                               | `pid: 12345`                                 |
 | type            | N/A                                        | `type: log`                                  |
-| error           | `{ message, name, stack }`                 | `{ message, name, stack, code, signal }`     |
+| error           | `{ message, name, stack }`                 | `{ message, name, stack, code, signal }`     |

src/core/server/metrics/integration_tests/metrics_service.test.ts

@@ -0,0 +1,161 @@
+/*
+ * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
+ * or more contributor license agreements. Licensed under the Elastic License
+ * and the Server Side Public License, v 1; you may not use this file except in
+ * compliance with, at your election, the Elastic License or the Server Side
+ * Public License, v 1.
+ */
+
+import * as kbnTestServer from '../../../test_helpers/kbn_server';
+import { InternalCoreSetup } from '../../internal_types';
+import { Root } from '../../root';
+import { OpsMetrics } from '../types';
+
+const otherTestSettings = {
+  ops: {
+    interval: 500,
+  },
+  logging: {
+    silent: true, // set "true" in kbnTestServer
+    appenders: {
+      'custom-console': {
+        kind: 'console',
+        layout: {
+          highlight: false,
+          kind: 'pattern',
+          pattern: '%message|%meta',
+        },
+      },
+    },
+    root: {
+      appenders: ['custom-console', 'default'],
+      level: 'warn',
+    },
+    loggers: [
+      {
+        context: 'metrics.ops',
+        appenders: ['custom-console'],
+        level: 'debug',
+      },
+    ],
+  },
+  plugins: {
+    initialize: false,
+  },
+};
+
+describe('metrics service', () => {
+  let root: Root;
+  let coreSetup: InternalCoreSetup;
+  let mockConsoleLog: jest.SpyInstance;
+  let testData: OpsMetrics;
+
+  beforeAll(async () => {
+    mockConsoleLog = jest.spyOn(global.console, 'log');
+  });
+
+  afterEach(async () => {
+    mockConsoleLog.mockClear();
+    await root.shutdown();
+  });
+
+  afterAll(async () => {
+    mockConsoleLog.mockRestore();
+    if (root) {
+      await root.shutdown();
+    }
+  });
+
+  describe('setup', () => {
+    it('returns ops interval and getOpsMetrics$ observable', async () => {
+      root = kbnTestServer.createRoot({ ...otherTestSettings });
+      coreSetup = await root.setup();
+      expect(coreSetup.metrics).toHaveProperty(
+        'collectionInterval',
+        otherTestSettings.ops.interval
+      );
+      expect(coreSetup.metrics).toHaveProperty('getOpsMetrics$');
+    });
+  });
+
+  describe('ops metrics logging configuration', () => {
+    it('does not log with logging set to quiet', async () => {
+      root = kbnTestServer.createRoot({ logging: { quiet: true } });
+      coreSetup = await root.setup();
+
+      expect(mockConsoleLog).not.toHaveBeenCalled();
+    });
+
+    it('logs at the correct level and with the correct context', async () => {
+      const testSettings = {
+        ops: {
+          interval: 500,
+        },
+        logging: {
+          silent: true, // set "true" in kbnTestServer
+          appenders: {
+            'custom-console': {
+              kind: 'console',
+              layout: {
+                highlight: false,
+                kind: 'pattern',
+                pattern: '%level|%logger',
+              },
+            },
+          },
+          root: {
+            appenders: ['custom-console', 'default'],
+            level: 'warn',
+          },
+          loggers: [
+            {
+              context: 'metrics.ops',
+              appenders: ['custom-console'],
+              level: 'debug',
+            },
+          ],
+        },
+        plugins: {
+          initialize: false,
+        },
+      };
+      root = kbnTestServer.createRoot({ ...testSettings });
+      coreSetup = await root.setup();
+
+      expect(mockConsoleLog).toHaveBeenCalledTimes(1);
+      const [level, logger] = mockConsoleLog.mock.calls[0][0].split('|');
+      expect(level).toBe('DEBUG');
+      expect(logger).toBe('metrics.ops');
+    });
+  });
+  describe('ops metrics logging content', () => {
+    it('logs memory, uptime, load and delay ops metrics in the message', async () => {
+      root = kbnTestServer.createRoot({ ...otherTestSettings });
+      coreSetup = await root.setup();
+
+      coreSetup.metrics.getOpsMetrics$().subscribe((opsMetrics) => {
+        testData = opsMetrics;
+      });
+      const expectedArray = ['memory:', 'uptime:', 'load:', 'delay:'];
+
+      expect(testData).toBeTruthy();
+      expect(mockConsoleLog).toHaveBeenCalledTimes(1);
+      const [message] = mockConsoleLog.mock.calls[0][0].split('|');
+
+      const messageParts = message.split(' ');
+      const testParts = [messageParts[0], messageParts[2], messageParts[4], messageParts[6]];
+      // the contents of the message are variable based on the process environment,
+      // so we are only performing assertions against parts of the string
+      expect(testParts).toEqual(expect.arrayContaining(expectedArray));
+    });
+
+    it('logs structured data in the log meta', async () => {
+      root = kbnTestServer.createRoot({ ...otherTestSettings });
+      coreSetup = await root.setup();
+
+      const [, meta] = mockConsoleLog.mock.calls[0][0].split('|');
+      expect(Object.keys(JSON.parse(meta).host.os.load)).toEqual(['1m', '5m', '15m']);
+      expect(Object.keys(JSON.parse(meta).process)).toEqual(expect.arrayContaining(['uptime']));
+    });
+  });
+});

src/core/server/metrics/logging/ecs.ts

@@ -0,0 +1,46 @@
+/*
+ * Copyright Elasticsearch B.V. and/or licensed to Elasticsearch B.V. under one
+ * or more contributor license agreements. Licensed under the Elastic License
+ * and the Server Side Public License, v 1; you may not use this file except in
+ * compliance with, at your election, the Elastic License or the Server Side
+ * Public License, v 1.
+ */
+
+/**
+ * Typings for some ECS fields which core uses internally.
+ * These are not a complete set of ECS typings and should not
+ * be used externally; the only types included here are ones
+ * currently used in core.
+ *
+ * @internal
+ */
+
+export interface EcsOpsMetricsEvent {
+  /**
+   * These typings were written as of ECS 1.7.0.
+   * Don't change this value without checking the rest
+   * of the types to conform to that ECS version.
+   *
+   * https://www.elastic.co/guide/en/ecs/1.7/index.html
+   */
+  ecs: { version: '1.7.0' };
+
+  // base fields
+  ['@timestamp']?: string;
+  labels?: Record<string, unknown>;
+  message?: string;
+  tags?: string[];
+  // other fields
+  process?: EcsProcessField;
+  event?: EcsEventField;
+}
+
+interface EcsProcessField {
+  uptime?: number;
+}
+
+interface EcsEventField {
+  kind?: string;
+  category?: string[];
+  type?: string;
+}