From b6bb9fd26abd26ea81c1f9a70e58a465edcda540 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Tue, 12 Jan 2021 11:04:52 -0700 Subject: [PATCH 01/28] POC for KP ops metrics logging --- .../metrics_service.test.ts.snap | 20 +++++++ .../server/metrics/metrics_service.test.ts | 56 ++++++++++++++++++- src/core/server/metrics/metrics_service.ts | 16 +++++- 3 files changed, 90 insertions(+), 2 deletions(-) create mode 100644 src/core/server/metrics/__snapshots__/metrics_service.test.ts.snap diff --git a/src/core/server/metrics/__snapshots__/metrics_service.test.ts.snap b/src/core/server/metrics/__snapshots__/metrics_service.test.ts.snap new file mode 100644 index 0000000000000..2adbd5364b09d --- /dev/null +++ b/src/core/server/metrics/__snapshots__/metrics_service.test.ts.snap @@ -0,0 +1,20 @@ +// Jest Snapshot v1, https://goo.gl/fbAQLP + +exports[`MetricsService #start logs the metrics at every interval 1`] = ` +Array [ + Array [ + "memory: 100.0B uptime: 0:00:02 load: [10.00 20.00 30.00] delay: 50.000", + ], +] +`; + +exports[`MetricsService #start logs the metrics at every interval 2`] = ` +Array [ + Array [ + "memory: 100.0B uptime: 0:00:02 load: [10.00 20.00 30.00] delay: 50.000", + ], + Array [ + "memory: 200.0B uptime: 0:00:03 load: [20.00 30.00 40.00] delay: 100.000", + ], +] +`; diff --git a/src/core/server/metrics/metrics_service.test.ts b/src/core/server/metrics/metrics_service.test.ts index c39f5f25b02b6..c7aeb3d5265b8 100644 --- a/src/core/server/metrics/metrics_service.test.ts +++ b/src/core/server/metrics/metrics_service.test.ts @@ -24,12 +24,15 @@ import { mockOpsCollector } from './metrics_service.test.mocks'; import { MetricsService } from './metrics_service'; import { mockCoreContext } from '../core_context.mock'; import { httpServiceMock } from '../http/http_service.mock'; +import { loggingSystemMock } from '../logging/logging_system.mock'; import { take } from 'rxjs/operators'; const testInterval = 100; const dummyMetrics = { metricA: 'value', metricB: 'otherValue' }; +const logger = loggingSystemMock.create(); + describe('MetricsService', () => { const httpMock = httpServiceMock.createInternalSetupContract(); let metricsService: MetricsService; @@ -40,7 +43,7 @@ describe('MetricsService', () => { const configService = configServiceMock.create({ atPath: { interval: moment.duration(testInterval) }, }); - const coreContext = mockCoreContext.create({ configService }); + const coreContext = mockCoreContext.create({ logger, configService }); metricsService = new MetricsService(coreContext); }); @@ -129,6 +132,57 @@ describe('MetricsService', () => { expect(await nextEmission()).toEqual({ metric: 'first' }); expect(await nextEmission()).toEqual({ metric: 'second' }); }); + + it('logs the metrics at every interval', async () => { + const firstMetrics = { + process: { + memory: { heap: { used_in_bytes: 100 } }, + uptime_in_millis: 1500, + event_loop_delay: 50, + }, + os: { + load: [10, 20, 30], + }, + }; + const secondMetrics = { + process: { + memory: { heap: { used_in_bytes: 200 } }, + uptime_in_millis: 3000, + event_loop_delay: 100, + }, + os: { + load: [20, 30, 40], + }, + }; + mockOpsCollector.collect + .mockResolvedValueOnce(firstMetrics) + .mockResolvedValueOnce(secondMetrics); + await metricsService.setup({ http: httpMock }); + const { getOpsMetrics$ } = await metricsService.start(); + + const nextEmission = async () => { + jest.advanceTimersByTime(testInterval); + const emission = await getOpsMetrics$().pipe(take(1)).toPromise(); + await new Promise((resolve) => process.nextTick(resolve)); + return emission; + }; + expect(loggingSystemMock.collect(logger).info).toMatchSnapshot(); + await nextEmission(); + expect(loggingSystemMock.collect(logger).info).toMatchSnapshot(); + }); + + it('logs default metrics if they are missing or malformed', async () => { + mockOpsCollector.collect.mockResolvedValueOnce({ secondMetrics: 'metrics' }); + await metricsService.setup({ http: httpMock }); + await metricsService.start(); + expect(loggingSystemMock.collect(logger).info).toMatchInlineSnapshot(` + Array [ + Array [ + "memory: 0.0B uptime: 0:00:00 load: [] delay: 0.000", + ], + ] + `); + }); }); describe('#stop', () => { diff --git a/src/core/server/metrics/metrics_service.ts b/src/core/server/metrics/metrics_service.ts index d3495f2748c71..702018883fc1e 100644 --- a/src/core/server/metrics/metrics_service.ts +++ b/src/core/server/metrics/metrics_service.ts @@ -16,7 +16,7 @@ * specific language governing permissions and limitations * under the License. */ - +import numeral from '@elastic/numeral'; import { ReplaySubject } from 'rxjs'; import { first } from 'rxjs/operators'; import { CoreService } from '../../types'; @@ -78,10 +78,24 @@ export class MetricsService return this.service; } + private extractOpsLogsData({ process, os }: Partial): string { + const memoryLogEntryinMB = numeral(process?.memory?.heap?.used_in_bytes ?? 0).format('0.0b'); + // ProcessMetricsCollector converts from seconds to milliseconds. Format here is HH:mm:ss for backward compatibility + const uptimeLogEntry = numeral((process?.uptime_in_millis ?? 0) / 1000).format('00:00:00'); + const loadLogEntry = [...Object.values(os?.load ?? [])] + .map((val: number) => { + return numeral(val).format('0.00'); + }) + .join(' '); + const delayLogEntry = numeral(process?.event_loop_delay ?? 0).format('0.000'); + return `memory: ${memoryLogEntryinMB} uptime: ${uptimeLogEntry} load: [${loadLogEntry}] delay: ${delayLogEntry}`; + } private async refreshMetrics() { this.logger.debug('Refreshing metrics'); const metrics = await this.metricsCollector!.collect(); + const opsLogsMetrics = this.extractOpsLogsData(metrics); + this.logger.info(opsLogsMetrics); this.metricsCollector!.reset(); this.metrics$.next(metrics); } From b57556280ebea6a1b533874aa6b4a5dee45daacc Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Wed, 13 Jan 2021 17:05:47 -0700 Subject: [PATCH 02/28] Adds jest integration test for metrics service --- .../integration_tests/metrics_service.test.ts | 97 +++++++++++++++++++ 1 file changed, 97 insertions(+) create mode 100644 src/core/server/metrics/integration_tests/metrics_service.test.ts diff --git a/src/core/server/metrics/integration_tests/metrics_service.test.ts b/src/core/server/metrics/integration_tests/metrics_service.test.ts new file mode 100644 index 0000000000000..3aeb4ceb68942 --- /dev/null +++ b/src/core/server/metrics/integration_tests/metrics_service.test.ts @@ -0,0 +1,97 @@ +/* + * 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 numeral from '@elastic/numeral'; +import { OpsMetrics } from '..'; +import * as kbnTestServer from '../../../test_helpers/kbn_server'; +import { InternalCoreSetup } from '../../internal_types'; +import { Root } from '../../root'; + +const otherTestSettings = { + ops: { + interval: 500, + }, + logging: { + silent: true, // set "true" in kbnTestServer + appenders: { + 'custom-console': { + kind: 'console', + layout: { + highlight: false, + kind: 'pattern', + pattern: '%message', + }, + }, + }, + loggers: [ + { + context: 'metrics', + appenders: ['custom-console'], + level: 'info', + }, + ], + }, +}; + +function extractTestMetricsOfInterest({ process, os }: Partial) { + const memoryLogEntryinMB = numeral(process?.memory?.heap?.used_in_bytes ?? 0).format('0.0b'); + const uptimeLogEntry = numeral((process?.uptime_in_millis ?? 0) / 1000).format('00:00:00'); + const loadLogEntry = [...Object.values(os?.load ?? [])] + .map((val: number) => { + return numeral(val).format('0.00'); + }) + .join(' '); + const delayLogEntry = numeral(process?.event_loop_delay ?? 0).format('0.000'); + return `memory: ${memoryLogEntryinMB} uptime: ${uptimeLogEntry} load: [${loadLogEntry}] delay: ${delayLogEntry}`; +} + +describe('metrics service', () => { + let root: Root; + let coreSetup: InternalCoreSetup; + let mockConsoleLog: jest.SpyInstance; + let testData: Partial; + + describe('setup', () => { + beforeAll(async () => { + mockConsoleLog = jest.spyOn(global.console, 'log'); + mockConsoleLog.mockClear(); + root = kbnTestServer.createRoot({ ...otherTestSettings }); + coreSetup = await root.setup(); + }); + + afterAll(async () => { + await root.shutdown(); + mockConsoleLog.mockRestore(); + }); + + it('returns ops interval and getOpsMetrics$ observable', async () => { + expect(coreSetup.metrics).toHaveProperty( + 'collectionInterval', + otherTestSettings.ops.interval + ); + expect(coreSetup.metrics).toHaveProperty('getOpsMetrics$'); + }); + + it('logs memory, uptime, load and delay ops metrics', async () => { + coreSetup.metrics.getOpsMetrics$().subscribe((opsMetrics) => { + testData = opsMetrics; + }); + expect(mockConsoleLog).toHaveBeenLastCalledWith(extractTestMetricsOfInterest(testData)); + }); + }); +}); From c7308146bfe10ba2b21ce53eb8b92595128cf940 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Thu, 14 Jan 2021 14:05:18 -0700 Subject: [PATCH 03/28] Adds documentation on KP implementation of ops metrics logs --- src/core/README.md | 6 ++++-- src/core/server/logging/README.md | 29 ++++++++++++++++++++++++++++- 2 files changed, 32 insertions(+), 3 deletions(-) diff --git a/src/core/README.md b/src/core/README.md index e195bf30c054c..c73c6aa56bfd0 100644 --- a/src/core/README.md +++ b/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 diff --git a/src/core/server/logging/README.md b/src/core/server/logging/README.md index 8cb704f09ce8c..62888c862a406 100644 --- a/src/core/server/logging/README.md +++ b/src/core/server/logging/README.md @@ -312,6 +312,9 @@ logging: - context: telemetry level: all appenders: [json-file-appender] + - context: metrics + level: info + 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 | console | info | + +### 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` logger is configured with `info` 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 as follows: + +| Ops formatted log property | Location in metrics service | Log units +| :------------------------- | :-------------------------- | :-------------------------- | +| memory | process.memory.heap.used_in_bytes | MB | +| 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 @@ -382,6 +406,9 @@ The log will be less verbose with `warn` level for the `server` context: [2017-07-25T18:54:41.639Z][FATAL][server] Message with `fatal` log level. ``` +### Usage Example: Ops metrics +Ops metrics are logged under the `info` level from the metrics service. + ### Logging config migration Compatibility with the legacy logging system is assured until the end of the `v7` version. All log messages handled by `root` context are forwarded to the legacy logging service. If you re-write @@ -478,4 +505,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 }` | \ No newline at end of file +| error | `{ message, name, stack }` | `{ message, name, stack, code, signal }` | From a6e4ad9be7f334e1fa33109c327a9e2691e16e06 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Thu, 14 Jan 2021 15:16:38 -0700 Subject: [PATCH 04/28] Typo --- src/core/server/logging/README.md | 3 --- 1 file changed, 3 deletions(-) diff --git a/src/core/server/logging/README.md b/src/core/server/logging/README.md index 62888c862a406..f52013af788b5 100644 --- a/src/core/server/logging/README.md +++ b/src/core/server/logging/README.md @@ -406,9 +406,6 @@ The log will be less verbose with `warn` level for the `server` context: [2017-07-25T18:54:41.639Z][FATAL][server] Message with `fatal` log level. ``` -### Usage Example: Ops metrics -Ops metrics are logged under the `info` level from the metrics service. - ### Logging config migration Compatibility with the legacy logging system is assured until the end of the `v7` version. All log messages handled by `root` context are forwarded to the legacy logging service. If you re-write From 5fbc95756e1b1795b8e65378400445f70833710a Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Wed, 20 Jan 2021 07:21:20 -0700 Subject: [PATCH 05/28] Updates license headers --- .../integration_tests/metrics_service.test.ts | 22 +++++-------------- 1 file changed, 6 insertions(+), 16 deletions(-) diff --git a/src/core/server/metrics/integration_tests/metrics_service.test.ts b/src/core/server/metrics/integration_tests/metrics_service.test.ts index 3aeb4ceb68942..4fb0ab718f2dc 100644 --- a/src/core/server/metrics/integration_tests/metrics_service.test.ts +++ b/src/core/server/metrics/integration_tests/metrics_service.test.ts @@ -1,21 +1,11 @@ /* - * 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. + * 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 numeral from '@elastic/numeral'; import { OpsMetrics } from '..'; import * as kbnTestServer from '../../../test_helpers/kbn_server'; From d3d27402165097aed869ae6592934f50f84c12b7 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Wed, 20 Jan 2021 14:09:20 -0700 Subject: [PATCH 06/28] Uses new logger context and changes to ECS-compatible meta structure --- .../integration_tests/metrics_service.test.ts | 168 ++++++++++++++---- src/core/server/metrics/logging/ecs.ts | 41 +++++ .../logging/get_ops_metrics_log.test.ts | 119 +++++++++++++ .../metrics/logging/get_ops_metrics_log.ts | 82 +++++++++ src/core/server/metrics/logging/index.ts | 9 + .../server/metrics/metrics_service.test.ts | 120 ++++++++++++- src/core/server/metrics/metrics_service.ts | 7 +- 7 files changed, 505 insertions(+), 41 deletions(-) create mode 100644 src/core/server/metrics/logging/ecs.ts create mode 100644 src/core/server/metrics/logging/get_ops_metrics_log.test.ts create mode 100644 src/core/server/metrics/logging/get_ops_metrics_log.ts create mode 100644 src/core/server/metrics/logging/index.ts diff --git a/src/core/server/metrics/integration_tests/metrics_service.test.ts b/src/core/server/metrics/integration_tests/metrics_service.test.ts index 4fb0ab718f2dc..07e111515fa2d 100644 --- a/src/core/server/metrics/integration_tests/metrics_service.test.ts +++ b/src/core/server/metrics/integration_tests/metrics_service.test.ts @@ -6,11 +6,10 @@ * Public License, v 1. */ -import numeral from '@elastic/numeral'; -import { OpsMetrics } from '..'; import * as kbnTestServer from '../../../test_helpers/kbn_server'; import { InternalCoreSetup } from '../../internal_types'; import { Root } from '../../root'; +import { OpsMetrics } from '../types'; const otherTestSettings = { ops: { @@ -24,64 +23,173 @@ const otherTestSettings = { layout: { highlight: false, kind: 'pattern', - pattern: '%message', + pattern: '%message|%meta', }, }, }, + root: { + appenders: ['custom-console', 'default'], + level: 'warn', + }, loggers: [ { - context: 'metrics', + context: 'metrics.ops', appenders: ['custom-console'], - level: 'info', + level: 'debug', }, ], }, + plugins: { + initialize: false, + }, }; -function extractTestMetricsOfInterest({ process, os }: Partial) { - const memoryLogEntryinMB = numeral(process?.memory?.heap?.used_in_bytes ?? 0).format('0.0b'); - const uptimeLogEntry = numeral((process?.uptime_in_millis ?? 0) / 1000).format('00:00:00'); - const loadLogEntry = [...Object.values(os?.load ?? [])] - .map((val: number) => { - return numeral(val).format('0.00'); - }) - .join(' '); - const delayLogEntry = numeral(process?.event_loop_delay ?? 0).format('0.000'); - return `memory: ${memoryLogEntryinMB} uptime: ${uptimeLogEntry} load: [${loadLogEntry}] delay: ${delayLogEntry}`; -} - describe('metrics service', () => { let root: Root; let coreSetup: InternalCoreSetup; let mockConsoleLog: jest.SpyInstance; - let testData: Partial; + let testData: OpsMetrics; - describe('setup', () => { - beforeAll(async () => { - mockConsoleLog = jest.spyOn(global.console, 'log'); - mockConsoleLog.mockClear(); - root = kbnTestServer.createRoot({ ...otherTestSettings }); - coreSetup = await root.setup(); - }); + beforeAll(async () => { + mockConsoleLog = jest.spyOn(global.console, 'log'); + mockConsoleLog.mockClear(); + }); - afterAll(async () => { + afterEach(() => { + mockConsoleLog.mockClear(); + }); + + afterAll(async () => { + mockConsoleLog.mockRestore(); + if (root) { await root.shutdown(); - mockConsoleLog.mockRestore(); - }); + } + }); + 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$'); + await root.shutdown(); + }); + }); + + 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(); + + coreSetup.metrics.getOpsMetrics$().subscribe((opsMetrics) => { + testData = opsMetrics; + }); + + expect(mockConsoleLog).not.toHaveBeenCalled(); + await root.shutdown(); + }); + + 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(); + + coreSetup.metrics.getOpsMetrics$().subscribe((opsMetrics) => { + testData = opsMetrics; + }); + + expect(mockConsoleLog).toHaveBeenCalledTimes(1); + const [level, logger] = mockConsoleLog.mock.calls[0][0].split('|'); + expect(level).toBe('DEBUG'); + expect(logger).toBe('metrics.ops'); + + await root.shutdown(); }); + }); + 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(); - it('logs memory, uptime, load and delay ops metrics', async () => { coreSetup.metrics.getOpsMetrics$().subscribe((opsMetrics) => { testData = opsMetrics; }); - expect(mockConsoleLog).toHaveBeenLastCalledWith(extractTestMetricsOfInterest(testData)); + 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)); + + await root.shutdown(); + }); + + it('logs structured data in the log meta', async () => { + root = kbnTestServer.createRoot({ ...otherTestSettings }); + coreSetup = await root.setup(); + + coreSetup.metrics.getOpsMetrics$().subscribe((opsMetrics) => { + testData = opsMetrics; + }); + 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'])); + + await root.shutdown(); + }); + + it('logs ECS fields in the log meta', async () => { + root = kbnTestServer.createRoot({ ...otherTestSettings }); + coreSetup = await root.setup(); + + coreSetup.metrics.getOpsMetrics$().subscribe((opsMetrics) => { + testData = opsMetrics; + }); + const [, meta] = mockConsoleLog.mock.calls[0][0].split('|'); + expect(JSON.parse(meta).kind).toBe('metric'); + expect(JSON.parse(meta).ecs.version).toBe('1.7.0'); + expect(JSON.parse(meta).category).toEqual(expect.arrayContaining(['process', 'host'])); + + await root.shutdown(); }); }); }); diff --git a/src/core/server/metrics/logging/ecs.ts b/src/core/server/metrics/logging/ecs.ts new file mode 100644 index 0000000000000..ddef8ee602307 --- /dev/null +++ b/src/core/server/metrics/logging/ecs.ts @@ -0,0 +1,41 @@ +/* + * 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; + message?: string; + tags?: string[]; + kind?: string; + category?: string[]; + // other fields + process?: EcsProcessField; +} + +interface EcsProcessField { + uptime?: number; +} diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.test.ts b/src/core/server/metrics/logging/get_ops_metrics_log.test.ts new file mode 100644 index 0000000000000..8553d62362f78 --- /dev/null +++ b/src/core/server/metrics/logging/get_ops_metrics_log.test.ts @@ -0,0 +1,119 @@ +/* + * 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 { OpsMetrics } from '..'; +import { getEcsOpsMetricsLog } from './get_ops_metrics_log'; + +const createBaseOpsMetrics = () => ({ + collected_at: new Date('2020-01-01 01:00:00'), + process: { + memory: { + heap: { total_in_bytes: 1, used_in_bytes: 1, size_limit: 1 }, + resident_set_size_in_bytes: 1, + }, + event_loop_delay: 1, + pid: 1, + uptime_in_millis: 1, + }, + os: { + platform: 'darwin' as const, + platformRelease: 'test', + load: { '1m': 1, '5m': 1, '15m': 1 }, + memory: { total_in_bytes: 1, free_in_bytes: 1, used_in_bytes: 1 }, + uptime_in_millis: 1, + }, + response_times: { avg_in_millis: 1, max_in_millis: 1 }, + requests: { disconnects: 1, total: 1, statusCodes: { '200': 1 } }, + concurrent_connections: 1, +}); + +function createMockOpsMetrics(testMetrics: any) { + const base = createBaseOpsMetrics(); + return { + ...base, + ...testMetrics, + }; +} +const testMetrics = { + process: { + memory: { heap: { used_in_bytes: 100 } }, + uptime_in_millis: 1500, + event_loop_delay: 50, + }, + os: { + load: { + '1m': 10, + '5m': 20, + '15m': 30, + }, + }, +}; +describe('getEcsOpsMetricsLog', () => { + it('provides correctly formatted message', () => { + const result = getEcsOpsMetricsLog(createMockOpsMetrics(testMetrics)); + expect(result.message).toMatchInlineSnapshot( + `"memory: 100.0B uptime: 0:00:01 load: [10.00,20.00,30.00] delay: 50.000"` + ); + }); + + it('correctly formats process uptime', () => { + const logMeta = getEcsOpsMetricsLog(createMockOpsMetrics(testMetrics)); + expect(logMeta.process.uptime).toEqual(1); + }); + + it('excludes values from the message if unavailable', () => { + const baseMetrics = createBaseOpsMetrics(); + const missingMetrics = ({ + ...baseMetrics, + process: {}, + os: {}, + } as unknown) as Partial; + const logMeta = getEcsOpsMetricsLog(missingMetrics); + expect(logMeta.message).toMatchInlineSnapshot(`" "`); + }); + + it('specifies correct ECS version', () => { + const logMeta = getEcsOpsMetricsLog(createBaseOpsMetrics()); + expect(logMeta.ecs.version).toBe('1.7.0'); + }); + + it('provides an ECS-compatible response', () => { + const logMeta = getEcsOpsMetricsLog(createBaseOpsMetrics()); + expect(logMeta).toMatchInlineSnapshot(` + Object { + "category": Array [ + "process", + "host", + ], + "ecs": Object { + "version": "1.7.0", + }, + "host": Object { + "os": Object { + "load": Object { + "15m": 1, + "1m": 1, + "5m": 1, + }, + }, + }, + "kind": "metric", + "message": "memory: 1.0B load: [1.00,1.00,1.00] delay: 1.000", + "process": Object { + "eventLoopDelay": 1, + "memory": Object { + "heap": Object { + "usedInBytes": 1, + }, + }, + "uptime": 0, + }, + } + `); + }); +}); diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.ts b/src/core/server/metrics/logging/get_ops_metrics_log.ts new file mode 100644 index 0000000000000..e9c59c5269125 --- /dev/null +++ b/src/core/server/metrics/logging/get_ops_metrics_log.ts @@ -0,0 +1,82 @@ +/* + * 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 numeral from '@elastic/numeral'; +import { LogMeta } from '@kbn/logging'; +import { EcsOpsMetricsEvent } from './ecs'; +import { OpsMetrics } from '..'; + +/** + * Converts ops metrics into ECS-compliant `LogMeta` for logging + * + * @internal + */ +export function getEcsOpsMetricsLog({ process, os }: Partial): LogMeta { + const processMemoryUsedInBytes = process?.memory?.heap?.used_in_bytes; + const processMemoryUsedInBytesMsg = processMemoryUsedInBytes + ? `memory: ${numeral(processMemoryUsedInBytes).format('0.0b')}` + : ''; + + // ECS process.uptime is in seconds: + const uptimeVal = process?.uptime_in_millis + ? Math.floor(process.uptime_in_millis / 1000) + : undefined; + + // HH:mm:ss message format for backward compatibility + const uptimeValMsg = uptimeVal ? `uptime: ${numeral(uptimeVal).format('00:00:00')}` : ''; + + // Event loop delay is in ms + const eventLoopDelayVal = process?.event_loop_delay; + const eventLoopDelayValMsg = eventLoopDelayVal + ? `delay: ${numeral(process?.event_loop_delay).format('0.000')}` + : ''; + + const loadEntries = { + '1m': os?.load ? os?.load['1m'] : undefined, + '5m': os?.load ? os?.load['5m'] : undefined, + '15m': os?.load ? os?.load['15m'] : undefined, + }; + + const loadVals = [...Object.values(os?.load ?? [])]; + const loadValsMsg = + loadVals.length > 0 + ? `load: [${loadVals.map((val: number) => { + return numeral(val).format('0.00'); + })}]` + : ''; + + // ECS fields + const meta: EcsOpsMetricsEvent = { + ecs: { version: '1.7.0' }, + message: `${processMemoryUsedInBytesMsg} ${uptimeValMsg} ${loadValsMsg} ${eventLoopDelayValMsg}`, + kind: 'metric', + category: ['process', 'host'], + process: { + uptime: uptimeVal, + }, + }; + + // return ECS event with custom fields not yet part of ECS + return { + ...meta, + process: { + ...meta.process, + memory: { + heap: { + usedInBytes: processMemoryUsedInBytes, + }, + }, + eventLoopDelay: eventLoopDelayVal, + }, + host: { + os: { + load: { ...loadEntries }, + }, + }, + }; +} diff --git a/src/core/server/metrics/logging/index.ts b/src/core/server/metrics/logging/index.ts new file mode 100644 index 0000000000000..5b3f9aed56be0 --- /dev/null +++ b/src/core/server/metrics/logging/index.ts @@ -0,0 +1,9 @@ +/* + * 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. + */ + +export { getEcsOpsMetricsLog } from './get_ops_metrics_log'; diff --git a/src/core/server/metrics/metrics_service.test.ts b/src/core/server/metrics/metrics_service.test.ts index c6eaf6a25c8c8..aae6e2e49834a 100644 --- a/src/core/server/metrics/metrics_service.test.ts +++ b/src/core/server/metrics/metrics_service.test.ts @@ -130,7 +130,11 @@ describe('MetricsService', () => { event_loop_delay: 50, }, os: { - load: [10, 20, 30], + load: { + '1m': 10, + '5m': 20, + '15m': 30, + }, }, }; const secondMetrics = { @@ -140,9 +144,16 @@ describe('MetricsService', () => { event_loop_delay: 100, }, os: { - load: [20, 30, 40], + load: { + '1m': 20, + '5m': 30, + '15m': 40, + }, }, }; + + const opsLogger = logger.get('metrics', 'ops'); + mockOpsCollector.collect .mockResolvedValueOnce(firstMetrics) .mockResolvedValueOnce(secondMetrics); @@ -155,20 +166,111 @@ describe('MetricsService', () => { await new Promise((resolve) => process.nextTick(resolve)); return emission; }; - expect(loggingSystemMock.collect(logger).info).toMatchSnapshot(); + expect(loggingSystemMock.collect(opsLogger).debug[1]).toMatchInlineSnapshot(` + Array [ + "memory: 100.0B uptime: 0:00:01 load: [10.00,20.00,30.00] delay: 50.000", + Object { + "category": Array [ + "process", + "host", + ], + "ecs": Object { + "version": "1.7.0", + }, + "host": Object { + "os": Object { + "load": Object { + "15m": 30, + "1m": 10, + "5m": 20, + }, + }, + }, + "kind": "metric", + "process": Object { + "eventLoopDelay": 50, + "memory": Object { + "heap": Object { + "usedInBytes": 100, + }, + }, + "uptime": 1, + }, + }, + ] + `); await nextEmission(); - expect(loggingSystemMock.collect(logger).info).toMatchSnapshot(); + expect(loggingSystemMock.collect(opsLogger).debug[3]).toMatchInlineSnapshot(` + Array [ + "memory: 200.0B uptime: 0:00:03 load: [20.00,30.00,40.00] delay: 100.000", + Object { + "category": Array [ + "process", + "host", + ], + "ecs": Object { + "version": "1.7.0", + }, + "host": Object { + "os": Object { + "load": Object { + "15m": 40, + "1m": 20, + "5m": 30, + }, + }, + }, + "kind": "metric", + "process": Object { + "eventLoopDelay": 100, + "memory": Object { + "heap": Object { + "usedInBytes": 200, + }, + }, + "uptime": 3, + }, + }, + ] + `); }); - it('logs default metrics if they are missing or malformed', async () => { + it('omits metrics from log message if they are missing or malformed', async () => { + const opsLogger = logger.get('metrics', 'ops'); mockOpsCollector.collect.mockResolvedValueOnce({ secondMetrics: 'metrics' }); await metricsService.setup({ http: httpMock }); await metricsService.start(); - expect(loggingSystemMock.collect(logger).info).toMatchInlineSnapshot(` + expect(loggingSystemMock.collect(opsLogger).debug[1]).toMatchInlineSnapshot(` Array [ - Array [ - "memory: 0.0B uptime: 0:00:00 load: [] delay: 0.000", - ], + " ", + Object { + "category": Array [ + "process", + "host", + ], + "ecs": Object { + "version": "1.7.0", + }, + "host": Object { + "os": Object { + "load": Object { + "15m": undefined, + "1m": undefined, + "5m": undefined, + }, + }, + }, + "kind": "metric", + "process": Object { + "eventLoopDelay": undefined, + "memory": Object { + "heap": Object { + "usedInBytes": undefined, + }, + }, + "uptime": undefined, + }, + }, ] `); }); diff --git a/src/core/server/metrics/metrics_service.ts b/src/core/server/metrics/metrics_service.ts index 892fee67c7725..c5f58954ead45 100644 --- a/src/core/server/metrics/metrics_service.ts +++ b/src/core/server/metrics/metrics_service.ts @@ -15,6 +15,7 @@ import { InternalHttpServiceSetup } from '../http'; import { InternalMetricsServiceSetup, InternalMetricsServiceStart, OpsMetrics } from './types'; import { OpsMetricsCollector } from './ops_metrics_collector'; import { opsConfig, OpsConfigType } from './ops_config'; +import { getEcsOpsMetricsLog } from './logging'; interface MetricsServiceSetupDeps { http: InternalHttpServiceSetup; @@ -24,6 +25,7 @@ interface MetricsServiceSetupDeps { export class MetricsService implements CoreService { private readonly logger: Logger; + private readonly opsMetricsLogger: Logger; private metricsCollector?: OpsMetricsCollector; private collectInterval?: NodeJS.Timeout; private metrics$ = new ReplaySubject(1); @@ -31,6 +33,7 @@ export class MetricsService constructor(private readonly coreContext: CoreContext) { this.logger = coreContext.logger.get('metrics'); + this.opsMetricsLogger = coreContext.logger.get('metrics', 'ops'); } public async setup({ http }: MetricsServiceSetupDeps): Promise { @@ -83,8 +86,8 @@ export class MetricsService private async refreshMetrics() { this.logger.debug('Refreshing metrics'); const metrics = await this.metricsCollector!.collect(); - const opsLogsMetrics = this.extractOpsLogsData(metrics); - this.logger.info(opsLogsMetrics); + const { message, ...rest } = getEcsOpsMetricsLog(metrics); + this.opsMetricsLogger.debug(message!, rest); this.metricsCollector!.reset(); this.metrics$.next(metrics); } From 7e481a7be9c37b2e8b3dbb2d99a5773175dc24a2 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Wed, 20 Jan 2021 14:18:32 -0700 Subject: [PATCH 07/28] Uses inline snapshots --- .../metrics_service.test.ts.snap | 20 ------------------- 1 file changed, 20 deletions(-) delete mode 100644 src/core/server/metrics/__snapshots__/metrics_service.test.ts.snap diff --git a/src/core/server/metrics/__snapshots__/metrics_service.test.ts.snap b/src/core/server/metrics/__snapshots__/metrics_service.test.ts.snap deleted file mode 100644 index 2adbd5364b09d..0000000000000 --- a/src/core/server/metrics/__snapshots__/metrics_service.test.ts.snap +++ /dev/null @@ -1,20 +0,0 @@ -// Jest Snapshot v1, https://goo.gl/fbAQLP - -exports[`MetricsService #start logs the metrics at every interval 1`] = ` -Array [ - Array [ - "memory: 100.0B uptime: 0:00:02 load: [10.00 20.00 30.00] delay: 50.000", - ], -] -`; - -exports[`MetricsService #start logs the metrics at every interval 2`] = ` -Array [ - Array [ - "memory: 100.0B uptime: 0:00:02 load: [10.00 20.00 30.00] delay: 50.000", - ], - Array [ - "memory: 200.0B uptime: 0:00:03 load: [20.00 30.00 40.00] delay: 100.000", - ], -] -`; From a11e3fb253f05dafd4b56943d3c90feec89f5986 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Wed, 20 Jan 2021 14:47:12 -0700 Subject: [PATCH 08/28] Add config deprecation for logging.events.ops --- .../deprecation/core_deprecations.test.ts | 20 +++++++++++++++++++ .../config/deprecation/core_deprecations.ts | 12 +++++++++++ 2 files changed, 32 insertions(+) diff --git a/src/core/server/config/deprecation/core_deprecations.test.ts b/src/core/server/config/deprecation/core_deprecations.test.ts index a7c6a63826523..cbd846e29b3dc 100644 --- a/src/core/server/config/deprecation/core_deprecations.test.ts +++ b/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: { metrics: '*' } }, + }); + expect(messages).toEqual([]); + }); + }); }); diff --git a/src/core/server/config/deprecation/core_deprecations.ts b/src/core/server/config/deprecation/core_deprecations.ts index 6f6e6c3e0522e..23a3518cd8eb6 100644 --- a/src/core/server/config/deprecation/core_deprecations.ts +++ b/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, ]; From 093a540bf8fbac6301fa920e6cbc76a2fe78b6ad Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Wed, 20 Jan 2021 14:54:49 -0700 Subject: [PATCH 09/28] Uses real option for ops metrics deprecation test --- src/core/server/config/deprecation/core_deprecations.test.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/core/server/config/deprecation/core_deprecations.test.ts b/src/core/server/config/deprecation/core_deprecations.test.ts index cbd846e29b3dc..a791362d9166f 100644 --- a/src/core/server/config/deprecation/core_deprecations.test.ts +++ b/src/core/server/config/deprecation/core_deprecations.test.ts @@ -251,7 +251,7 @@ describe('core deprecations', () => { it('does not warn when other events are configured', () => { const { messages } = applyCoreDeprecations({ - logging: { events: { metrics: '*' } }, + logging: { events: { log: '*' } }, }); expect(messages).toEqual([]); }); From e0306fad69c1d21288fa47a9d6fc0aa6b27d72e2 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Wed, 20 Jan 2021 14:56:41 -0700 Subject: [PATCH 10/28] Disable legacy ops logs when logging.verbose=true --- packages/kbn-legacy-logging/src/get_logging_config.ts | 5 ++++- 1 file changed, 4 insertions(+), 1 deletion(-) diff --git a/packages/kbn-legacy-logging/src/get_logging_config.ts b/packages/kbn-legacy-logging/src/get_logging_config.ts index 5a28ab1271538..280b9f815c78c 100644 --- a/packages/kbn-legacy-logging/src/get_logging_config.ts +++ b/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: '*', From 1a59360b76dcb5f75a0c9e70caf5ea1c2aaf68a6 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Wed, 20 Jan 2021 14:58:53 -0700 Subject: [PATCH 11/28] Removes unused method --- src/core/server/metrics/metrics_service.ts | 12 ------------ 1 file changed, 12 deletions(-) diff --git a/src/core/server/metrics/metrics_service.ts b/src/core/server/metrics/metrics_service.ts index c5f58954ead45..ffb50cadd7b0d 100644 --- a/src/core/server/metrics/metrics_service.ts +++ b/src/core/server/metrics/metrics_service.ts @@ -70,18 +70,6 @@ export class MetricsService return this.service; } - private extractOpsLogsData({ process, os }: Partial): string { - const memoryLogEntryinMB = numeral(process?.memory?.heap?.used_in_bytes ?? 0).format('0.0b'); - // ProcessMetricsCollector converts from seconds to milliseconds. Format here is HH:mm:ss for backward compatibility - const uptimeLogEntry = numeral((process?.uptime_in_millis ?? 0) / 1000).format('00:00:00'); - const loadLogEntry = [...Object.values(os?.load ?? [])] - .map((val: number) => { - return numeral(val).format('0.00'); - }) - .join(' '); - const delayLogEntry = numeral(process?.event_loop_delay ?? 0).format('0.000'); - return `memory: ${memoryLogEntryinMB} uptime: ${uptimeLogEntry} load: [${loadLogEntry}] delay: ${delayLogEntry}`; - } private async refreshMetrics() { this.logger.debug('Refreshing metrics'); From 34fe95a54cd80e191c75362cbda13c6ac7afd1f0 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Wed, 20 Jan 2021 15:07:32 -0700 Subject: [PATCH 12/28] removes unused import --- src/core/server/metrics/metrics_service.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/core/server/metrics/metrics_service.ts b/src/core/server/metrics/metrics_service.ts index ffb50cadd7b0d..553a0f62c93d8 100644 --- a/src/core/server/metrics/metrics_service.ts +++ b/src/core/server/metrics/metrics_service.ts @@ -5,7 +5,7 @@ * compliance with, at your election, the Elastic License or the Server Side * Public License, v 1. */ -import numeral from '@elastic/numeral'; + import { ReplaySubject } from 'rxjs'; import { first } from 'rxjs/operators'; import { CoreService } from '../../types'; From 914beff2148d90cc27ac4237fe74e285863536c6 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Wed, 20 Jan 2021 15:43:46 -0700 Subject: [PATCH 13/28] Updates docs --- src/core/server/logging/README.md | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/src/core/server/logging/README.md b/src/core/server/logging/README.md index f52013af788b5..ba9eb735d02be 100644 --- a/src/core/server/logging/README.md +++ b/src/core/server/logging/README.md @@ -312,8 +312,8 @@ logging: - context: telemetry level: all appenders: [json-file-appender] - - context: metrics - level: info + - context: metrics.ops + level: debug appenders: [console] ``` @@ -327,7 +327,7 @@ Here is what we get with the config above: | server | console, file | fatal | | optimize | console | error | | telemetry | json-file-appender | all | -| metrics | console | info | +| metrics.ops | console | debug | ### Dedicated loggers @@ -336,8 +336,8 @@ The `root` logger has a dedicated configuration node since this context is speci 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` logger is configured with `info` 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 as follows: +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 | :------------------------- | :-------------------------- | :-------------------------- | From a4df1ebc77dc591cbc0e803a5aea26e8e9ea5e8c Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Thu, 21 Jan 2021 15:24:57 -0700 Subject: [PATCH 14/28] reformats message string construction to handle empty message --- .../server/metrics/logging/get_ops_metrics_log.test.ts | 4 ++-- src/core/server/metrics/logging/get_ops_metrics_log.ts | 8 ++++---- 2 files changed, 6 insertions(+), 6 deletions(-) diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.test.ts b/src/core/server/metrics/logging/get_ops_metrics_log.test.ts index 8553d62362f78..fc1ef92f1c1ef 100644 --- a/src/core/server/metrics/logging/get_ops_metrics_log.test.ts +++ b/src/core/server/metrics/logging/get_ops_metrics_log.test.ts @@ -74,7 +74,7 @@ describe('getEcsOpsMetricsLog', () => { os: {}, } as unknown) as Partial; const logMeta = getEcsOpsMetricsLog(missingMetrics); - expect(logMeta.message).toMatchInlineSnapshot(`" "`); + expect(logMeta.message).toMatchInlineSnapshot(`""`); }); it('specifies correct ECS version', () => { @@ -103,7 +103,7 @@ describe('getEcsOpsMetricsLog', () => { }, }, "kind": "metric", - "message": "memory: 1.0B load: [1.00,1.00,1.00] delay: 1.000", + "message": "memory: 1.0B load: [1.00,1.00,1.00] delay: 1.000", "process": Object { "eventLoopDelay": 1, "memory": Object { diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.ts b/src/core/server/metrics/logging/get_ops_metrics_log.ts index e9c59c5269125..4ae2cfbdad476 100644 --- a/src/core/server/metrics/logging/get_ops_metrics_log.ts +++ b/src/core/server/metrics/logging/get_ops_metrics_log.ts @@ -19,7 +19,7 @@ import { OpsMetrics } from '..'; export function getEcsOpsMetricsLog({ process, os }: Partial): LogMeta { const processMemoryUsedInBytes = process?.memory?.heap?.used_in_bytes; const processMemoryUsedInBytesMsg = processMemoryUsedInBytes - ? `memory: ${numeral(processMemoryUsedInBytes).format('0.0b')}` + ? `memory: ${numeral(processMemoryUsedInBytes).format('0.0b')} ` : ''; // ECS process.uptime is in seconds: @@ -28,7 +28,7 @@ export function getEcsOpsMetricsLog({ process, os }: Partial): LogMe : undefined; // HH:mm:ss message format for backward compatibility - const uptimeValMsg = uptimeVal ? `uptime: ${numeral(uptimeVal).format('00:00:00')}` : ''; + const uptimeValMsg = uptimeVal ? `uptime: ${numeral(uptimeVal).format('00:00:00')} ` : ''; // Event loop delay is in ms const eventLoopDelayVal = process?.event_loop_delay; @@ -47,13 +47,13 @@ export function getEcsOpsMetricsLog({ process, os }: Partial): LogMe loadVals.length > 0 ? `load: [${loadVals.map((val: number) => { return numeral(val).format('0.00'); - })}]` + })}] ` : ''; // ECS fields const meta: EcsOpsMetricsEvent = { ecs: { version: '1.7.0' }, - message: `${processMemoryUsedInBytesMsg} ${uptimeValMsg} ${loadValsMsg} ${eventLoopDelayValMsg}`, + message: `${processMemoryUsedInBytesMsg}${uptimeValMsg}${loadValsMsg}${eventLoopDelayValMsg}`, kind: 'metric', category: ['process', 'host'], process: { From d3e1bda5aef22022d73c7386b00864c0bbf1c623 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Thu, 21 Jan 2021 15:42:55 -0700 Subject: [PATCH 15/28] Moves ecs kind and ecs category fields to event namespace, adds event.type --- .../integration_tests/metrics_service.test.ts | 5 +++-- src/core/server/metrics/logging/ecs.ts | 9 +++++++-- .../metrics/logging/get_ops_metrics_log.test.ts | 13 ++++++++----- .../server/metrics/logging/get_ops_metrics_log.ts | 7 +++++-- 4 files changed, 23 insertions(+), 11 deletions(-) diff --git a/src/core/server/metrics/integration_tests/metrics_service.test.ts b/src/core/server/metrics/integration_tests/metrics_service.test.ts index 07e111515fa2d..9f89735e6c761 100644 --- a/src/core/server/metrics/integration_tests/metrics_service.test.ts +++ b/src/core/server/metrics/integration_tests/metrics_service.test.ts @@ -185,9 +185,10 @@ describe('metrics service', () => { testData = opsMetrics; }); const [, meta] = mockConsoleLog.mock.calls[0][0].split('|'); - expect(JSON.parse(meta).kind).toBe('metric'); + expect(JSON.parse(meta).event.kind).toBe('metric'); expect(JSON.parse(meta).ecs.version).toBe('1.7.0'); - expect(JSON.parse(meta).category).toEqual(expect.arrayContaining(['process', 'host'])); + expect(JSON.parse(meta).event.category).toEqual(expect.arrayContaining(['process', 'host'])); + expect(JSON.parse(meta).event.type).toBe('info'); await root.shutdown(); }); diff --git a/src/core/server/metrics/logging/ecs.ts b/src/core/server/metrics/logging/ecs.ts index ddef8ee602307..bdddc70585a4a 100644 --- a/src/core/server/metrics/logging/ecs.ts +++ b/src/core/server/metrics/logging/ecs.ts @@ -30,12 +30,17 @@ export interface EcsOpsMetricsEvent { labels?: Record; message?: string; tags?: string[]; - kind?: string; - category?: string[]; // other fields process?: EcsProcessField; + event?: EcsEventField; } interface EcsProcessField { uptime?: number; } + +interface EcsEventField { + kind?: string; + category?: string[]; + type?: string; +} diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.test.ts b/src/core/server/metrics/logging/get_ops_metrics_log.test.ts index fc1ef92f1c1ef..895c4be8244dc 100644 --- a/src/core/server/metrics/logging/get_ops_metrics_log.test.ts +++ b/src/core/server/metrics/logging/get_ops_metrics_log.test.ts @@ -86,13 +86,17 @@ describe('getEcsOpsMetricsLog', () => { const logMeta = getEcsOpsMetricsLog(createBaseOpsMetrics()); expect(logMeta).toMatchInlineSnapshot(` Object { - "category": Array [ - "process", - "host", - ], "ecs": Object { "version": "1.7.0", }, + "event": Object { + "category": Array [ + "process", + "host", + ], + "kind": "metric", + "type": "info", + }, "host": Object { "os": Object { "load": Object { @@ -102,7 +106,6 @@ describe('getEcsOpsMetricsLog', () => { }, }, }, - "kind": "metric", "message": "memory: 1.0B load: [1.00,1.00,1.00] delay: 1.000", "process": Object { "eventLoopDelay": 1, diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.ts b/src/core/server/metrics/logging/get_ops_metrics_log.ts index 4ae2cfbdad476..efa047d986e46 100644 --- a/src/core/server/metrics/logging/get_ops_metrics_log.ts +++ b/src/core/server/metrics/logging/get_ops_metrics_log.ts @@ -54,8 +54,11 @@ export function getEcsOpsMetricsLog({ process, os }: Partial): LogMe const meta: EcsOpsMetricsEvent = { ecs: { version: '1.7.0' }, message: `${processMemoryUsedInBytesMsg}${uptimeValMsg}${loadValsMsg}${eventLoopDelayValMsg}`, - kind: 'metric', - category: ['process', 'host'], + event: { + kind: 'metric', + category: ['process', 'host'], + type: 'info', + }, process: { uptime: uptimeVal, }, From 885c3e0e7d0a90bc099116313c432d28304aa238 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Thu, 21 Jan 2021 15:47:30 -0700 Subject: [PATCH 16/28] Moves root.shutdown to afterEach, removes unused code --- .../integration_tests/metrics_service.test.ts | 28 ++----------------- 1 file changed, 2 insertions(+), 26 deletions(-) diff --git a/src/core/server/metrics/integration_tests/metrics_service.test.ts b/src/core/server/metrics/integration_tests/metrics_service.test.ts index 9f89735e6c761..e39c1beb0a1a7 100644 --- a/src/core/server/metrics/integration_tests/metrics_service.test.ts +++ b/src/core/server/metrics/integration_tests/metrics_service.test.ts @@ -52,11 +52,11 @@ describe('metrics service', () => { beforeAll(async () => { mockConsoleLog = jest.spyOn(global.console, 'log'); - mockConsoleLog.mockClear(); }); - afterEach(() => { + afterEach(async () => { mockConsoleLog.mockClear(); + await root.shutdown(); }); afterAll(async () => { @@ -75,7 +75,6 @@ describe('metrics service', () => { otherTestSettings.ops.interval ); expect(coreSetup.metrics).toHaveProperty('getOpsMetrics$'); - await root.shutdown(); }); }); @@ -84,12 +83,7 @@ describe('metrics service', () => { root = kbnTestServer.createRoot({ logging: { quiet: true } }); coreSetup = await root.setup(); - coreSetup.metrics.getOpsMetrics$().subscribe((opsMetrics) => { - testData = opsMetrics; - }); - expect(mockConsoleLog).not.toHaveBeenCalled(); - await root.shutdown(); }); it('logs at the correct level and with the correct context', async () => { @@ -128,16 +122,10 @@ describe('metrics service', () => { root = kbnTestServer.createRoot({ ...testSettings }); coreSetup = await root.setup(); - coreSetup.metrics.getOpsMetrics$().subscribe((opsMetrics) => { - testData = opsMetrics; - }); - expect(mockConsoleLog).toHaveBeenCalledTimes(1); const [level, logger] = mockConsoleLog.mock.calls[0][0].split('|'); expect(level).toBe('DEBUG'); expect(logger).toBe('metrics.ops'); - - await root.shutdown(); }); }); describe('ops metrics logging content', () => { @@ -159,38 +147,26 @@ describe('metrics service', () => { // 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)); - - await root.shutdown(); }); it('logs structured data in the log meta', async () => { root = kbnTestServer.createRoot({ ...otherTestSettings }); coreSetup = await root.setup(); - coreSetup.metrics.getOpsMetrics$().subscribe((opsMetrics) => { - testData = opsMetrics; - }); 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'])); - - await root.shutdown(); }); it('logs ECS fields in the log meta', async () => { root = kbnTestServer.createRoot({ ...otherTestSettings }); coreSetup = await root.setup(); - coreSetup.metrics.getOpsMetrics$().subscribe((opsMetrics) => { - testData = opsMetrics; - }); const [, meta] = mockConsoleLog.mock.calls[0][0].split('|'); expect(JSON.parse(meta).event.kind).toBe('metric'); expect(JSON.parse(meta).ecs.version).toBe('1.7.0'); expect(JSON.parse(meta).event.category).toEqual(expect.arrayContaining(['process', 'host'])); expect(JSON.parse(meta).event.type).toBe('info'); - - await root.shutdown(); }); }); }); From e16f8868994187b8e904ea4906522e6c285fa8cb Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Thu, 21 Jan 2021 15:54:46 -0700 Subject: [PATCH 17/28] Moves test for log meta containing ECS fields to a unit test --- .../metrics/integration_tests/metrics_service.test.ts | 11 ----------- .../metrics/logging/get_ops_metrics_log.test.ts | 7 +++++++ 2 files changed, 7 insertions(+), 11 deletions(-) diff --git a/src/core/server/metrics/integration_tests/metrics_service.test.ts b/src/core/server/metrics/integration_tests/metrics_service.test.ts index e39c1beb0a1a7..72092cec56ff5 100644 --- a/src/core/server/metrics/integration_tests/metrics_service.test.ts +++ b/src/core/server/metrics/integration_tests/metrics_service.test.ts @@ -157,16 +157,5 @@ describe('metrics service', () => { expect(Object.keys(JSON.parse(meta).host.os.load)).toEqual(['1m', '5m', '15m']); expect(Object.keys(JSON.parse(meta).process)).toEqual(expect.arrayContaining(['uptime'])); }); - - it('logs ECS fields in the log meta', async () => { - root = kbnTestServer.createRoot({ ...otherTestSettings }); - coreSetup = await root.setup(); - - const [, meta] = mockConsoleLog.mock.calls[0][0].split('|'); - expect(JSON.parse(meta).event.kind).toBe('metric'); - expect(JSON.parse(meta).ecs.version).toBe('1.7.0'); - expect(JSON.parse(meta).event.category).toEqual(expect.arrayContaining(['process', 'host'])); - expect(JSON.parse(meta).event.type).toBe('info'); - }); }); }); diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.test.ts b/src/core/server/metrics/logging/get_ops_metrics_log.test.ts index 895c4be8244dc..c06c7bd1613fb 100644 --- a/src/core/server/metrics/logging/get_ops_metrics_log.test.ts +++ b/src/core/server/metrics/logging/get_ops_metrics_log.test.ts @@ -119,4 +119,11 @@ describe('getEcsOpsMetricsLog', () => { } `); }); + + it('logs ECS fields in the log meta', () => { + const logMeta = getEcsOpsMetricsLog(createBaseOpsMetrics()); + expect(logMeta.event.kind).toBe('metric'); + expect(logMeta.event.category).toEqual(expect.arrayContaining(['process', 'host'])); + expect(logMeta.event.type).toBe('info'); + }); }); From f4eb382feeb68b252373424e1537f00b867b2e18 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Thu, 21 Jan 2021 16:06:03 -0700 Subject: [PATCH 18/28] Updates ops format table in the logging README --- src/core/server/logging/README.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/core/server/logging/README.md b/src/core/server/logging/README.md index ba9eb735d02be..c08222bb6dfbd 100644 --- a/src/core/server/logging/README.md +++ b/src/core/server/logging/README.md @@ -341,7 +341,7 @@ The metrics that are logged are a subset of the data collected and are formatted | Ops formatted log property | Location in metrics service | Log units | :------------------------- | :-------------------------- | :-------------------------- | -| memory | process.memory.heap.used_in_bytes | MB | +| 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 | From 27e0e0e67b4f5d0838e39376354fecab564ae934 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Thu, 21 Jan 2021 16:47:14 -0700 Subject: [PATCH 19/28] Updates metrics_service unit test snapshots --- .../server/metrics/metrics_service.test.ts | 41 +++++++++++-------- 1 file changed, 25 insertions(+), 16 deletions(-) diff --git a/src/core/server/metrics/metrics_service.test.ts b/src/core/server/metrics/metrics_service.test.ts index aae6e2e49834a..3b3eade316faa 100644 --- a/src/core/server/metrics/metrics_service.test.ts +++ b/src/core/server/metrics/metrics_service.test.ts @@ -170,13 +170,17 @@ describe('MetricsService', () => { Array [ "memory: 100.0B uptime: 0:00:01 load: [10.00,20.00,30.00] delay: 50.000", Object { - "category": Array [ - "process", - "host", - ], "ecs": Object { "version": "1.7.0", }, + "event": Object { + "category": Array [ + "process", + "host", + ], + "kind": "metric", + "type": "info", + }, "host": Object { "os": Object { "load": Object { @@ -186,7 +190,6 @@ describe('MetricsService', () => { }, }, }, - "kind": "metric", "process": Object { "eventLoopDelay": 50, "memory": Object { @@ -204,13 +207,17 @@ describe('MetricsService', () => { Array [ "memory: 200.0B uptime: 0:00:03 load: [20.00,30.00,40.00] delay: 100.000", Object { - "category": Array [ - "process", - "host", - ], "ecs": Object { "version": "1.7.0", }, + "event": Object { + "category": Array [ + "process", + "host", + ], + "kind": "metric", + "type": "info", + }, "host": Object { "os": Object { "load": Object { @@ -220,7 +227,6 @@ describe('MetricsService', () => { }, }, }, - "kind": "metric", "process": Object { "eventLoopDelay": 100, "memory": Object { @@ -242,15 +248,19 @@ describe('MetricsService', () => { await metricsService.start(); expect(loggingSystemMock.collect(opsLogger).debug[1]).toMatchInlineSnapshot(` Array [ - " ", + "", Object { - "category": Array [ - "process", - "host", - ], "ecs": Object { "version": "1.7.0", }, + "event": Object { + "category": Array [ + "process", + "host", + ], + "kind": "metric", + "type": "info", + }, "host": Object { "os": Object { "load": Object { @@ -260,7 +270,6 @@ describe('MetricsService', () => { }, }, }, - "kind": "metric", "process": Object { "eventLoopDelay": undefined, "memory": Object { From 8e0c58a5d0d48dc433aa112e7dea84075845ebe8 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Mon, 25 Jan 2021 12:16:30 -0700 Subject: [PATCH 20/28] Moves custom fields into meta declaration --- .../integration_tests/metrics_service.test.ts | 3 +++ .../server/metrics/logging/get_ops_metrics_log.ts | 15 +++------------ 2 files changed, 6 insertions(+), 12 deletions(-) diff --git a/src/core/server/metrics/integration_tests/metrics_service.test.ts b/src/core/server/metrics/integration_tests/metrics_service.test.ts index 72092cec56ff5..02ea705bc8f2d 100644 --- a/src/core/server/metrics/integration_tests/metrics_service.test.ts +++ b/src/core/server/metrics/integration_tests/metrics_service.test.ts @@ -68,6 +68,7 @@ describe('metrics service', () => { describe('setup', () => { it('returns ops interval and getOpsMetrics$ observable', async () => { + // TODO: remove this test root = kbnTestServer.createRoot({ ...otherTestSettings }); coreSetup = await root.setup(); expect(coreSetup.metrics).toHaveProperty( @@ -79,6 +80,7 @@ describe('metrics service', () => { }); describe('ops metrics logging configuration', () => { + // TODO: remove this test it('does not log with logging set to quiet', async () => { root = kbnTestServer.createRoot({ logging: { quiet: true } }); coreSetup = await root.setup(); @@ -129,6 +131,7 @@ describe('metrics service', () => { }); }); describe('ops metrics logging content', () => { + // TODO: remove this test it('logs memory, uptime, load and delay ops metrics in the message', async () => { root = kbnTestServer.createRoot({ ...otherTestSettings }); coreSetup = await root.setup(); diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.ts b/src/core/server/metrics/logging/get_ops_metrics_log.ts index efa047d986e46..82e14e6adf561 100644 --- a/src/core/server/metrics/logging/get_ops_metrics_log.ts +++ b/src/core/server/metrics/logging/get_ops_metrics_log.ts @@ -7,7 +7,6 @@ */ import numeral from '@elastic/numeral'; -import { LogMeta } from '@kbn/logging'; import { EcsOpsMetricsEvent } from './ecs'; import { OpsMetrics } from '..'; @@ -16,7 +15,7 @@ import { OpsMetrics } from '..'; * * @internal */ -export function getEcsOpsMetricsLog({ process, os }: Partial): LogMeta { +export function getEcsOpsMetricsLog({ process, os }: Partial): EcsOpsMetricsEvent { const processMemoryUsedInBytes = process?.memory?.heap?.used_in_bytes; const processMemoryUsedInBytesMsg = processMemoryUsedInBytes ? `memory: ${numeral(processMemoryUsedInBytes).format('0.0b')} ` @@ -50,8 +49,7 @@ export function getEcsOpsMetricsLog({ process, os }: Partial): LogMe })}] ` : ''; - // ECS fields - const meta: EcsOpsMetricsEvent = { + return { ecs: { version: '1.7.0' }, message: `${processMemoryUsedInBytesMsg}${uptimeValMsg}${loadValsMsg}${eventLoopDelayValMsg}`, event: { @@ -61,14 +59,7 @@ export function getEcsOpsMetricsLog({ process, os }: Partial): LogMe }, process: { uptime: uptimeVal, - }, - }; - - // return ECS event with custom fields not yet part of ECS - return { - ...meta, - process: { - ...meta.process, + // @ts-expect-error custom fields not yet part of ECS memory: { heap: { usedInBytes: processMemoryUsedInBytes, From b9a78797e493e982cc48b4670930b7d82a6c4ce9 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Mon, 25 Jan 2021 12:19:17 -0700 Subject: [PATCH 21/28] Deletes metrics_service jest integration test that is already covered elsewhere --- .../integration_tests/metrics_service.test.ts | 164 ------------------ 1 file changed, 164 deletions(-) delete mode 100644 src/core/server/metrics/integration_tests/metrics_service.test.ts diff --git a/src/core/server/metrics/integration_tests/metrics_service.test.ts b/src/core/server/metrics/integration_tests/metrics_service.test.ts deleted file mode 100644 index 02ea705bc8f2d..0000000000000 --- a/src/core/server/metrics/integration_tests/metrics_service.test.ts +++ /dev/null @@ -1,164 +0,0 @@ -/* - * 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 () => { - // TODO: remove this test - 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', () => { - // TODO: remove this test - 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', () => { - // TODO: remove this test - 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'])); - }); - }); -}); From 2e489bf17c0279af141505de576b3916c1e7c33f Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Mon, 25 Jan 2021 15:04:59 -0700 Subject: [PATCH 22/28] Type fixes --- .../logging/get_ops_metrics_log.test.ts | 61 ++++++++++--------- .../metrics/logging/get_ops_metrics_log.ts | 3 +- src/core/server/metrics/metrics_service.ts | 4 +- 3 files changed, 36 insertions(+), 32 deletions(-) diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.test.ts b/src/core/server/metrics/logging/get_ops_metrics_log.test.ts index c06c7bd1613fb..820959910e764 100644 --- a/src/core/server/metrics/logging/get_ops_metrics_log.test.ts +++ b/src/core/server/metrics/logging/get_ops_metrics_log.test.ts @@ -9,37 +9,39 @@ import { OpsMetrics } from '..'; import { getEcsOpsMetricsLog } from './get_ops_metrics_log'; -const createBaseOpsMetrics = () => ({ - collected_at: new Date('2020-01-01 01:00:00'), - process: { - memory: { - heap: { total_in_bytes: 1, used_in_bytes: 1, size_limit: 1 }, - resident_set_size_in_bytes: 1, +function createBaseOpsMetrics(): OpsMetrics { + return { + collected_at: new Date('2020-01-01 01:00:00'), + process: { + memory: { + heap: { total_in_bytes: 1, used_in_bytes: 1, size_limit: 1 }, + resident_set_size_in_bytes: 1, + }, + event_loop_delay: 1, + pid: 1, + uptime_in_millis: 1, }, - event_loop_delay: 1, - pid: 1, - uptime_in_millis: 1, - }, - os: { - platform: 'darwin' as const, - platformRelease: 'test', - load: { '1m': 1, '5m': 1, '15m': 1 }, - memory: { total_in_bytes: 1, free_in_bytes: 1, used_in_bytes: 1 }, - uptime_in_millis: 1, - }, - response_times: { avg_in_millis: 1, max_in_millis: 1 }, - requests: { disconnects: 1, total: 1, statusCodes: { '200': 1 } }, - concurrent_connections: 1, -}); + os: { + platform: 'darwin' as const, + platformRelease: 'test', + load: { '1m': 1, '5m': 1, '15m': 1 }, + memory: { total_in_bytes: 1, free_in_bytes: 1, used_in_bytes: 1 }, + uptime_in_millis: 1, + }, + response_times: { avg_in_millis: 1, max_in_millis: 1 }, + requests: { disconnects: 1, total: 1, statusCodes: { '200': 1 } }, + concurrent_connections: 1, + }; +} -function createMockOpsMetrics(testMetrics: any) { +function createMockOpsMetrics(testMetrics: Partial): OpsMetrics { const base = createBaseOpsMetrics(); return { ...base, ...testMetrics, }; } -const testMetrics = { +const testMetrics = ({ process: { memory: { heap: { used_in_bytes: 100 } }, uptime_in_millis: 1500, @@ -52,7 +54,8 @@ const testMetrics = { '15m': 30, }, }, -}; +} as unknown) as Partial; + describe('getEcsOpsMetricsLog', () => { it('provides correctly formatted message', () => { const result = getEcsOpsMetricsLog(createMockOpsMetrics(testMetrics)); @@ -63,7 +66,7 @@ describe('getEcsOpsMetricsLog', () => { it('correctly formats process uptime', () => { const logMeta = getEcsOpsMetricsLog(createMockOpsMetrics(testMetrics)); - expect(logMeta.process.uptime).toEqual(1); + expect(logMeta.process!.uptime).toEqual(1); }); it('excludes values from the message if unavailable', () => { @@ -72,7 +75,7 @@ describe('getEcsOpsMetricsLog', () => { ...baseMetrics, process: {}, os: {}, - } as unknown) as Partial; + } as unknown) as OpsMetrics; const logMeta = getEcsOpsMetricsLog(missingMetrics); expect(logMeta.message).toMatchInlineSnapshot(`""`); }); @@ -122,8 +125,8 @@ describe('getEcsOpsMetricsLog', () => { it('logs ECS fields in the log meta', () => { const logMeta = getEcsOpsMetricsLog(createBaseOpsMetrics()); - expect(logMeta.event.kind).toBe('metric'); - expect(logMeta.event.category).toEqual(expect.arrayContaining(['process', 'host'])); - expect(logMeta.event.type).toBe('info'); + expect(logMeta.event!.kind).toBe('metric'); + expect(logMeta.event!.category).toEqual(expect.arrayContaining(['process', 'host'])); + expect(logMeta.event!.type).toBe('info'); }); }); diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.ts b/src/core/server/metrics/logging/get_ops_metrics_log.ts index 82e14e6adf561..146c894b40091 100644 --- a/src/core/server/metrics/logging/get_ops_metrics_log.ts +++ b/src/core/server/metrics/logging/get_ops_metrics_log.ts @@ -15,7 +15,8 @@ import { OpsMetrics } from '..'; * * @internal */ -export function getEcsOpsMetricsLog({ process, os }: Partial): EcsOpsMetricsEvent { +export function getEcsOpsMetricsLog(metrics: OpsMetrics): EcsOpsMetricsEvent { + const { process, os } = metrics; const processMemoryUsedInBytes = process?.memory?.heap?.used_in_bytes; const processMemoryUsedInBytesMsg = processMemoryUsedInBytes ? `memory: ${numeral(processMemoryUsedInBytes).format('0.0b')} ` diff --git a/src/core/server/metrics/metrics_service.ts b/src/core/server/metrics/metrics_service.ts index 553a0f62c93d8..e3ae344f184d5 100644 --- a/src/core/server/metrics/metrics_service.ts +++ b/src/core/server/metrics/metrics_service.ts @@ -74,8 +74,8 @@ export class MetricsService private async refreshMetrics() { this.logger.debug('Refreshing metrics'); const metrics = await this.metricsCollector!.collect(); - const { message, ...rest } = getEcsOpsMetricsLog(metrics); - this.opsMetricsLogger.debug(message!, rest); + const { message, ...meta } = getEcsOpsMetricsLog(metrics); + this.opsMetricsLogger.debug(message!, meta); this.metricsCollector!.reset(); this.metrics$.next(metrics); } From 48cb94cb7983297f526e86d7df109acfda39a99c Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Mon, 25 Jan 2021 15:51:52 -0700 Subject: [PATCH 23/28] Moves logger meta ECS type declarations to logging --- src/core/server/{metrics => }/logging/ecs.ts | 0 src/core/server/logging/index.ts | 1 + src/core/server/metrics/logging/get_ops_metrics_log.ts | 2 +- 3 files changed, 2 insertions(+), 1 deletion(-) rename src/core/server/{metrics => }/logging/ecs.ts (100%) diff --git a/src/core/server/metrics/logging/ecs.ts b/src/core/server/logging/ecs.ts similarity index 100% rename from src/core/server/metrics/logging/ecs.ts rename to src/core/server/logging/ecs.ts diff --git a/src/core/server/logging/index.ts b/src/core/server/logging/index.ts index f024bea1bf358..c7a172aeeb04a 100644 --- a/src/core/server/logging/index.ts +++ b/src/core/server/logging/index.ts @@ -17,6 +17,7 @@ export { LogLevelId, LogLevel, } from '@kbn/logging'; +export { EcsOpsMetricsEvent } from './ecs'; export { config, LoggingConfigType, diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.ts b/src/core/server/metrics/logging/get_ops_metrics_log.ts index 146c894b40091..299e6aa2002e3 100644 --- a/src/core/server/metrics/logging/get_ops_metrics_log.ts +++ b/src/core/server/metrics/logging/get_ops_metrics_log.ts @@ -7,7 +7,7 @@ */ import numeral from '@elastic/numeral'; -import { EcsOpsMetricsEvent } from './ecs'; +import { EcsOpsMetricsEvent } from '../../logging'; import { OpsMetrics } from '..'; /** From f9bcc2d89255906b2b35cf889b0114ccc79ac6bd Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Tue, 26 Jan 2021 12:41:01 -0700 Subject: [PATCH 24/28] removes unnecessary log, simplifies test --- .../metrics/logging/get_ops_metrics_log.ts | 5 +- .../server/metrics/metrics_service.test.ts | 82 ++----------------- src/core/server/metrics/metrics_service.ts | 1 - 3 files changed, 12 insertions(+), 76 deletions(-) diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.ts b/src/core/server/metrics/logging/get_ops_metrics_log.ts index 299e6aa2002e3..c60e9c0bc9b28 100644 --- a/src/core/server/metrics/logging/get_ops_metrics_log.ts +++ b/src/core/server/metrics/logging/get_ops_metrics_log.ts @@ -10,6 +10,7 @@ import numeral from '@elastic/numeral'; import { EcsOpsMetricsEvent } from '../../logging'; import { OpsMetrics } from '..'; +const ECS_VERSION = '1.7.0'; /** * Converts ops metrics into ECS-compliant `LogMeta` for logging * @@ -51,7 +52,7 @@ export function getEcsOpsMetricsLog(metrics: OpsMetrics): EcsOpsMetricsEvent { : ''; return { - ecs: { version: '1.7.0' }, + ecs: { version: ECS_VERSION }, message: `${processMemoryUsedInBytesMsg}${uptimeValMsg}${loadValsMsg}${eventLoopDelayValMsg}`, event: { kind: 'metric', @@ -70,7 +71,7 @@ export function getEcsOpsMetricsLog(metrics: OpsMetrics): EcsOpsMetricsEvent { }, host: { os: { - load: { ...loadEntries }, + load: loadEntries, }, }, }; diff --git a/src/core/server/metrics/metrics_service.test.ts b/src/core/server/metrics/metrics_service.test.ts index 3b3eade316faa..035b833e83066 100644 --- a/src/core/server/metrics/metrics_service.test.ts +++ b/src/core/server/metrics/metrics_service.test.ts @@ -166,79 +166,15 @@ describe('MetricsService', () => { await new Promise((resolve) => process.nextTick(resolve)); return emission; }; - expect(loggingSystemMock.collect(opsLogger).debug[1]).toMatchInlineSnapshot(` - Array [ - "memory: 100.0B uptime: 0:00:01 load: [10.00,20.00,30.00] delay: 50.000", - Object { - "ecs": Object { - "version": "1.7.0", - }, - "event": Object { - "category": Array [ - "process", - "host", - ], - "kind": "metric", - "type": "info", - }, - "host": Object { - "os": Object { - "load": Object { - "15m": 30, - "1m": 10, - "5m": 20, - }, - }, - }, - "process": Object { - "eventLoopDelay": 50, - "memory": Object { - "heap": Object { - "usedInBytes": 100, - }, - }, - "uptime": 1, - }, - }, - ] - `); + await nextEmission(); - expect(loggingSystemMock.collect(opsLogger).debug[3]).toMatchInlineSnapshot(` - Array [ - "memory: 200.0B uptime: 0:00:03 load: [20.00,30.00,40.00] delay: 100.000", - Object { - "ecs": Object { - "version": "1.7.0", - }, - "event": Object { - "category": Array [ - "process", - "host", - ], - "kind": "metric", - "type": "info", - }, - "host": Object { - "os": Object { - "load": Object { - "15m": 40, - "1m": 20, - "5m": 30, - }, - }, - }, - "process": Object { - "eventLoopDelay": 100, - "memory": Object { - "heap": Object { - "usedInBytes": 200, - }, - }, - "uptime": 3, - }, - }, - ] - `); + + const opsLogs = loggingSystemMock.collect(opsLogger).debug.filter((log) => { + // Only return the opsMetrics logs that contain both a message string and the meta + if (log.length > 1) return log; + }); + expect(opsLogs.length).toEqual(2); + expect(opsLogs[0][1]).not.toEqual(opsLogs[1][1]); }); it('omits metrics from log message if they are missing or malformed', async () => { @@ -246,7 +182,7 @@ describe('MetricsService', () => { mockOpsCollector.collect.mockResolvedValueOnce({ secondMetrics: 'metrics' }); await metricsService.setup({ http: httpMock }); await metricsService.start(); - expect(loggingSystemMock.collect(opsLogger).debug[1]).toMatchInlineSnapshot(` + expect(loggingSystemMock.collect(opsLogger).debug[0]).toMatchInlineSnapshot(` Array [ "", Object { diff --git a/src/core/server/metrics/metrics_service.ts b/src/core/server/metrics/metrics_service.ts index e3ae344f184d5..460035ad2e298 100644 --- a/src/core/server/metrics/metrics_service.ts +++ b/src/core/server/metrics/metrics_service.ts @@ -72,7 +72,6 @@ export class MetricsService } private async refreshMetrics() { - this.logger.debug('Refreshing metrics'); const metrics = await this.metricsCollector!.collect(); const { message, ...meta } = getEcsOpsMetricsLog(metrics); this.opsMetricsLogger.debug(message!, meta); From 5e7aad7c78328dcf0a7fae8419e2efc1846eb9e7 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Tue, 26 Jan 2021 12:45:33 -0700 Subject: [PATCH 25/28] simplifies test after removing text log --- src/core/server/metrics/metrics_service.test.ts | 6 +----- 1 file changed, 1 insertion(+), 5 deletions(-) diff --git a/src/core/server/metrics/metrics_service.test.ts b/src/core/server/metrics/metrics_service.test.ts index 035b833e83066..e21bad1ef4be7 100644 --- a/src/core/server/metrics/metrics_service.test.ts +++ b/src/core/server/metrics/metrics_service.test.ts @@ -168,11 +168,7 @@ describe('MetricsService', () => { }; await nextEmission(); - - const opsLogs = loggingSystemMock.collect(opsLogger).debug.filter((log) => { - // Only return the opsMetrics logs that contain both a message string and the meta - if (log.length > 1) return log; - }); + const opsLogs = loggingSystemMock.collect(opsLogger).debug; expect(opsLogs.length).toEqual(2); expect(opsLogs[0][1]).not.toEqual(opsLogs[1][1]); }); From 17149669f41299a79ea96efcb26af7f056635ac0 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Tue, 26 Jan 2021 14:19:33 -0700 Subject: [PATCH 26/28] Updates logging README, explicitly types event fields --- src/core/server/logging/README.md | 24 ++++----- src/core/server/logging/ecs.ts | 50 +++++++++++++++++-- src/core/server/logging/index.ts | 8 ++- .../metrics/logging/get_ops_metrics_log.ts | 8 +-- 4 files changed, 69 insertions(+), 21 deletions(-) diff --git a/src/core/server/logging/README.md b/src/core/server/logging/README.md index c08222bb6dfbd..1865962ff58a6 100644 --- a/src/core/server/logging/README.md +++ b/src/core/server/logging/README.md @@ -330,6 +330,17 @@ Here is what we get with the config above: | metrics.ops | console | debug | +For example to see _all_ log messages that fall back on the `root` logger configuration, just add one line to the configuration: + +```yaml +logging.root.level: all +``` + +Or disable logging entirely with `off`: + +```yaml +logging.root.level: off +``` ### Dedicated loggers The `root` logger has a dedicated configuration node since this context is special and should always exist. By @@ -353,19 +364,6 @@ 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 -logging.root.level: all -``` - -Or disable logging entirely with `off`: - -```yaml -logging.root.level: off -``` - ## Usage Usage is very straightforward, one should just get a logger for a specific context and use it to log messages with diff --git a/src/core/server/logging/ecs.ts b/src/core/server/logging/ecs.ts index bdddc70585a4a..d20f54a322744 100644 --- a/src/core/server/logging/ecs.ts +++ b/src/core/server/logging/ecs.ts @@ -39,8 +39,52 @@ interface EcsProcessField { uptime?: number; } -interface EcsEventField { - kind?: string; - category?: string[]; +export interface EcsEventField { + kind?: EcsEventKind; + category?: EcsEventCategory[]; type?: string; } + +export enum EcsEventKind { + ALERT = 'alert', + EVENT = 'event', + METRIC = 'metric', + STATE = 'state', + PIPELINE_ERROR = 'pipeline_error', + SIGNAL = 'signal', +} + +export enum EcsEventCategory { + AUTHENTICATION = 'authentication', + CONFIGURATION = 'configuration', + DATABASE = 'database', + DRIVER = 'driver', + FILE = 'file', + HOST = 'host', + IAM = 'iam', + INTRUSION_DETECTION = 'intrusion_detection', + MALWARE = 'malware', + NETWORK = 'network', + PACKAGE = 'package', + PROCESS = 'process', + WEB = 'web', +} + +export enum EcsEventType { + ACCESS = 'access', + ADMIN = 'admin', + ALLOWED = 'allowed', + CHANGE = 'change', + CONNECTION = 'connection', + CREATION = 'creation', + DELETION = 'deletion', + DENIED = 'denied', + END = 'end', + ERROR = 'error', + GROUP = 'group', + INFO = 'info', + INSTALLATION = 'installation', + PROTOCOL = 'protocol', + START = 'start', + USER = 'user', +} diff --git a/src/core/server/logging/index.ts b/src/core/server/logging/index.ts index c7a172aeeb04a..18a903af0a9fd 100644 --- a/src/core/server/logging/index.ts +++ b/src/core/server/logging/index.ts @@ -17,7 +17,13 @@ export { LogLevelId, LogLevel, } from '@kbn/logging'; -export { EcsOpsMetricsEvent } from './ecs'; +export { + EcsOpsMetricsEvent, + EcsEventField, + EcsEventKind, + EcsEventCategory, + EcsEventType, +} from './ecs'; export { config, LoggingConfigType, diff --git a/src/core/server/metrics/logging/get_ops_metrics_log.ts b/src/core/server/metrics/logging/get_ops_metrics_log.ts index c60e9c0bc9b28..361cac0bc310c 100644 --- a/src/core/server/metrics/logging/get_ops_metrics_log.ts +++ b/src/core/server/metrics/logging/get_ops_metrics_log.ts @@ -7,7 +7,7 @@ */ import numeral from '@elastic/numeral'; -import { EcsOpsMetricsEvent } from '../../logging'; +import { EcsOpsMetricsEvent, EcsEventKind, EcsEventCategory, EcsEventType } from '../../logging'; import { OpsMetrics } from '..'; const ECS_VERSION = '1.7.0'; @@ -55,9 +55,9 @@ export function getEcsOpsMetricsLog(metrics: OpsMetrics): EcsOpsMetricsEvent { ecs: { version: ECS_VERSION }, message: `${processMemoryUsedInBytesMsg}${uptimeValMsg}${loadValsMsg}${eventLoopDelayValMsg}`, event: { - kind: 'metric', - category: ['process', 'host'], - type: 'info', + kind: EcsEventKind.METRIC, + category: [EcsEventCategory.PROCESS, EcsEventCategory.HOST], + type: EcsEventType.INFO, }, process: { uptime: uptimeVal, From 56f267ad16e6f4e5e4306da27259d512daf87db7 Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Tue, 26 Jan 2021 14:22:26 -0700 Subject: [PATCH 27/28] minor fix --- src/core/server/logging/ecs.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/core/server/logging/ecs.ts b/src/core/server/logging/ecs.ts index d20f54a322744..0dbc403fca0b2 100644 --- a/src/core/server/logging/ecs.ts +++ b/src/core/server/logging/ecs.ts @@ -42,7 +42,7 @@ interface EcsProcessField { export interface EcsEventField { kind?: EcsEventKind; category?: EcsEventCategory[]; - type?: string; + type?: EcsEventType; } export enum EcsEventKind { From ed5f6bfd90c28d7519c37b8ee1536e05a23b50db Mon Sep 17 00:00:00 2001 From: Christiane Heiligers Date: Tue, 26 Jan 2021 14:28:43 -0700 Subject: [PATCH 28/28] Another logging README update --- src/core/server/logging/README.md | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/core/server/logging/README.md b/src/core/server/logging/README.md index 1865962ff58a6..cc2b6230d2d33 100644 --- a/src/core/server/logging/README.md +++ b/src/core/server/logging/README.md @@ -330,6 +330,10 @@ Here is what we get with the config above: | metrics.ops | console | debug | +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. + For example to see _all_ log messages that fall back on the `root` logger configuration, just add one line to the configuration: ```yaml @@ -343,10 +347,6 @@ logging.root.level: off ``` ### 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: