From 9374878e91b86948be342d328d90ac6815cb5483 Mon Sep 17 00:00:00 2001 From: Mikhail Shustov Date: Fri, 31 Jan 2020 11:55:46 +0100 Subject: [PATCH 01/10] pass config to the new platform --- .../config/legacy_object_to_config_adapter.ts | 15 +++++++++++---- src/legacy/server/config/schema.js | 4 ++++ 2 files changed, 15 insertions(+), 4 deletions(-) diff --git a/src/core/server/legacy/config/legacy_object_to_config_adapter.ts b/src/core/server/legacy/config/legacy_object_to_config_adapter.ts index 30bb150e6c15a..3e496648c3af9 100644 --- a/src/core/server/legacy/config/legacy_object_to_config_adapter.ts +++ b/src/core/server/legacy/config/legacy_object_to_config_adapter.ts @@ -19,12 +19,13 @@ import { ConfigPath } from '../../config'; import { ObjectToConfigAdapter } from '../../config/object_to_config_adapter'; +import { LoggingConfigType } from '../../logging/logging_config'; import { LegacyVars } from '../types'; /** * Represents logging config supported by the legacy platform. */ -interface LegacyLoggingConfig { +export interface LegacyLoggingConfig { silent?: boolean; verbose?: boolean; quiet?: boolean; @@ -33,18 +34,24 @@ interface LegacyLoggingConfig { events?: Record; } +type MixedLoggingConfig = LegacyLoggingConfig & Partial; + /** * Represents adapter between config provided by legacy platform and `Config` * supported by the current platform. * @internal */ export class LegacyObjectToConfigAdapter extends ObjectToConfigAdapter { - private static transformLogging(configValue: LegacyLoggingConfig = {}) { + private static transformLogging(configValue: MixedLoggingConfig = {}) { + const { appenders, root, loggers, ...legacyLoggingConfig } = configValue; + const loggingConfig = { appenders: { - default: { kind: 'legacy-appender', legacyLoggingConfig: configValue }, + ...appenders, + default: { kind: 'legacy-appender', legacyLoggingConfig }, }, - root: { level: 'info' }, + root: { level: 'info', ...root }, + loggers, }; if (configValue.silent) { diff --git a/src/legacy/server/config/schema.js b/src/legacy/server/config/schema.js index 88a794445870c..4395bec97d0a1 100644 --- a/src/legacy/server/config/schema.js +++ b/src/legacy/server/config/schema.js @@ -103,6 +103,10 @@ export default () => logging: Joi.object() .keys({ + appenders: HANDLED_IN_NEW_PLATFORM, + loggers: HANDLED_IN_NEW_PLATFORM, + root: HANDLED_IN_NEW_PLATFORM, + silent: Joi.boolean().default(false), quiet: Joi.boolean().when('silent', { From a51c3b43c36d9503a7b832858d934c9345a21a47 Mon Sep 17 00:00:00 2001 From: Mikhail Shustov Date: Fri, 31 Jan 2020 12:03:01 +0100 Subject: [PATCH 02/10] add default appenders --- src/core/server/logging/logging_config.ts | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/src/core/server/logging/logging_config.ts b/src/core/server/logging/logging_config.ts index 84d707a3247e6..5b76e96006a77 100644 --- a/src/core/server/logging/logging_config.ts +++ b/src/core/server/logging/logging_config.ts @@ -118,12 +118,19 @@ export class LoggingConfig { */ public readonly appenders: Map = new Map([ [ - DEFAULT_APPENDER_NAME, + 'console', { kind: 'console', layout: { kind: 'pattern', highlight: true }, } as AppenderConfigType, ], + [ + 'file', + { + kind: 'file', + layout: { kind: 'pattern', highlight: false }, + } as AppenderConfigType, + ], ]); /** From de254128a22d47b712280ad925f88659f6cac921 Mon Sep 17 00:00:00 2001 From: Mikhail Shustov Date: Fri, 31 Jan 2020 12:06:22 +0100 Subject: [PATCH 03/10] remove receiveAllAppenders flag it breaks legacy-appender compatibility with legacy flags: silent, quiet, verbose --- .../server/logging/appenders/appenders.ts | 6 -- src/core/server/logging/logger.test.ts | 82 ------------------- src/core/server/logging/logger.ts | 2 +- 3 files changed, 1 insertion(+), 89 deletions(-) diff --git a/src/core/server/logging/appenders/appenders.ts b/src/core/server/logging/appenders/appenders.ts index 871acb8c465ca..3aa86495e4d82 100644 --- a/src/core/server/logging/appenders/appenders.ts +++ b/src/core/server/logging/appenders/appenders.ts @@ -42,12 +42,6 @@ export type AppenderConfigType = TypeOf; */ export interface Appender { append(record: LogRecord): void; - - /** - * Used to signal to `Logger` that log level filtering should be ignored for this appender. Defaults to `false`. - * @deprecated Should be removed once the `LegacyAppender` is removed. - */ - receiveAllLevels?: boolean; } /** diff --git a/src/core/server/logging/logger.test.ts b/src/core/server/logging/logger.test.ts index eeebb8ad5a0fa..026e24fc5df54 100644 --- a/src/core/server/logging/logger.test.ts +++ b/src/core/server/logging/logger.test.ts @@ -410,85 +410,3 @@ test('passes log record to appenders only if log level is supported.', () => { }); } }); - -test('passes log record to appender with receiveAllLevels: true, regardless if log level is supported', () => { - const receiveAllAppender = { append: jest.fn(), receiveAllLevels: true }; - const warnLogger = new BaseLogger(context, LogLevel.Warn, [receiveAllAppender], factory); - - warnLogger.trace('trace-message'); - expect(receiveAllAppender.append).toHaveBeenCalledTimes(1); - expect(receiveAllAppender.append.mock.calls[0][0]).toMatchObject({ - level: LogLevel.Trace, - message: 'trace-message', - }); - - warnLogger.debug('debug-message'); - expect(receiveAllAppender.append).toHaveBeenCalledTimes(2); - expect(receiveAllAppender.append.mock.calls[1][0]).toMatchObject({ - level: LogLevel.Debug, - message: 'debug-message', - }); - - warnLogger.info('info-message'); - expect(receiveAllAppender.append).toHaveBeenCalledTimes(3); - expect(receiveAllAppender.append.mock.calls[2][0]).toMatchObject({ - level: LogLevel.Info, - message: 'info-message', - }); - - warnLogger.warn('warn-message'); - expect(receiveAllAppender.append).toHaveBeenCalledTimes(4); - expect(receiveAllAppender.append.mock.calls[3][0]).toMatchObject({ - level: LogLevel.Warn, - message: 'warn-message', - }); - - warnLogger.error('error-message'); - expect(receiveAllAppender.append).toHaveBeenCalledTimes(5); - expect(receiveAllAppender.append.mock.calls[4][0]).toMatchObject({ - level: LogLevel.Error, - message: 'error-message', - }); - - warnLogger.fatal('fatal-message'); - expect(receiveAllAppender.append).toHaveBeenCalledTimes(6); - expect(receiveAllAppender.append.mock.calls[5][0]).toMatchObject({ - level: LogLevel.Fatal, - message: 'fatal-message', - }); -}); - -test('passes log record to appender with receiveAllLevels: false, only if log level is supported', () => { - const notReceiveAllAppender = { append: jest.fn(), receiveAllLevels: false }; - const warnLogger = new BaseLogger(context, LogLevel.Warn, [notReceiveAllAppender], factory); - - warnLogger.trace('trace-message'); - expect(notReceiveAllAppender.append).toHaveBeenCalledTimes(0); - - warnLogger.debug('debug-message'); - expect(notReceiveAllAppender.append).toHaveBeenCalledTimes(0); - - warnLogger.info('info-message'); - expect(notReceiveAllAppender.append).toHaveBeenCalledTimes(0); - - warnLogger.warn('warn-message'); - expect(notReceiveAllAppender.append).toHaveBeenCalledTimes(1); - expect(notReceiveAllAppender.append.mock.calls[0][0]).toMatchObject({ - level: LogLevel.Warn, - message: 'warn-message', - }); - - warnLogger.error('error-message'); - expect(notReceiveAllAppender.append).toHaveBeenCalledTimes(2); - expect(notReceiveAllAppender.append.mock.calls[1][0]).toMatchObject({ - level: LogLevel.Error, - message: 'error-message', - }); - - warnLogger.fatal('fatal-message'); - expect(notReceiveAllAppender.append).toHaveBeenCalledTimes(3); - expect(notReceiveAllAppender.append.mock.calls[2][0]).toMatchObject({ - level: LogLevel.Fatal, - message: 'fatal-message', - }); -}); diff --git a/src/core/server/logging/logger.ts b/src/core/server/logging/logger.ts index ab6906ff5d684..99a2014be97c1 100644 --- a/src/core/server/logging/logger.ts +++ b/src/core/server/logging/logger.ts @@ -139,7 +139,7 @@ export class BaseLogger implements Logger { const supportedLevel = this.level.supports(record.level); for (const appender of this.appenders) { - if (supportedLevel || appender.receiveAllLevels) { + if (supportedLevel) { appender.append(record); } } From 003cd4371e9e289c71d76a92e27155149db2f31c Mon Sep 17 00:00:00 2001 From: Mikhail Shustov Date: Fri, 31 Jan 2020 12:07:04 +0100 Subject: [PATCH 04/10] add integration tests --- .../legacy/integration_tests/logging.test.ts | 220 ++++++++++++++++++ .../logging/integration_tests/logging.test.ts | 114 +++++++++ .../server/logging/integration_tests/utils.ts | 57 +++++ 3 files changed, 391 insertions(+) create mode 100644 src/core/server/legacy/integration_tests/logging.test.ts create mode 100644 src/core/server/logging/integration_tests/logging.test.ts create mode 100644 src/core/server/logging/integration_tests/utils.ts diff --git a/src/core/server/legacy/integration_tests/logging.test.ts b/src/core/server/legacy/integration_tests/logging.test.ts new file mode 100644 index 0000000000000..a91a4e1278453 --- /dev/null +++ b/src/core/server/legacy/integration_tests/logging.test.ts @@ -0,0 +1,220 @@ +/* + * 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 Fs from 'fs'; +import Path from 'path'; +import Util from 'util'; +import del from 'del'; + +import * as kbnTestServer from '../../../../test_utils/kbn_server'; +import { fromRoot } from '../../utils'; +import { + getPlatformLoggingContent as _getPlatformLoggingContent, + getLegacyPlatformLoggingContent as _getLegacyPlatformLoggingContent, +} from '../../logging/integration_tests/utils'; + +import { LegacyLoggingConfig } from '../config/legacy_object_to_config_adapter'; + +const mkdir = Util.promisify(Fs.mkdir); +const truncate = Util.promisify(Fs.truncate); + +const tempFolderPath = fromRoot('data/test/tmp-logging-service'); +const platformDestination = Path.join(tempFolderPath, 'compatibility-np.txt'); +const legacyPlatformDestination = Path.join(tempFolderPath, 'compatibility-lp.txt'); + +const getPlatformLoggingContent = () => _getPlatformLoggingContent(platformDestination); +const getLegacyPlatformLoggingContent = () => + _getLegacyPlatformLoggingContent(legacyPlatformDestination); + +function createRoot(legacyLoggingConfig: LegacyLoggingConfig = {}) { + return kbnTestServer.createRoot({ + logging: { + // legacy platform config + silent: false, + dest: legacyPlatformDestination, + json: false, + ...legacyLoggingConfig, + events: { + log: ['test-file-legacy'], + }, + // platform config + appenders: { + file: { + kind: 'file', + path: platformDestination, + layout: { + kind: 'pattern', + }, + }, + }, + loggers: [ + { + context: 'test-file', + appenders: ['file'], + level: 'info', + }, + ], + }, + }); +} + +describe('logging service', () => { + describe('compatibility', () => { + beforeAll(async () => { + await mkdir(tempFolderPath, { recursive: true }); + }); + afterAll(async () => { + await del(tempFolderPath); + }); + afterEach(async () => { + await truncate(platformDestination); + await truncate(legacyPlatformDestination); + }); + describe('uses configured loggers', () => { + let root: ReturnType; + beforeAll(async () => { + root = createRoot(); + + await root.setup(); + await root.start(); + }, 30000); + + afterAll(async () => { + await root.shutdown(); + }); + + it('when context matches', async () => { + root.logger.get('test-file').info('handled by NP'); + + expect(await getPlatformLoggingContent()).toMatchInlineSnapshot(` + "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] handled by NP + " + `); + + expect(await getLegacyPlatformLoggingContent()).toHaveLength(0); + }); + + it('falls back to the root legacy logger otherwise', async () => { + root.logger.get('test-file-legacy').info('handled by LP'); + + expect(await getLegacyPlatformLoggingContent()).toMatchInlineSnapshot(` + " log [xx:xx:xx.xxx] [info][test-file-legacy] handled by LP + " + `); + expect(await getPlatformLoggingContent()).toHaveLength(0); + }); + }); + + describe('logging config respects legacy logging settings', () => { + it('"silent": true', async () => { + const root = createRoot({ silent: true }); + + await root.setup(); + await root.start(); + + const platformLogger = root.logger.get('test-file'); + platformLogger.info('info'); + platformLogger.warn('warn'); + platformLogger.error('error'); + + const legacyPlatformLogger = root.logger.get('test-file-legacy'); + legacyPlatformLogger.info('info'); + legacyPlatformLogger.warn('warn'); + legacyPlatformLogger.error('error'); + + // calls shutdown to close write stream and flush logged messages + await root.shutdown(); + + expect(await getPlatformLoggingContent()).toMatchInlineSnapshot(` + "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info + [xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn + [xxxx-xx-xxTxx:xx:xx.xxxZ][ERROR][test-file] error + " + `); + + expect(await getLegacyPlatformLoggingContent()).toHaveLength(0); + }); + + it('"quiet": true', async () => { + const root = createRoot({ quiet: true }); + + await root.setup(); + await root.start(); + + const platformLogger = root.logger.get('test-file'); + platformLogger.info('info'); + platformLogger.warn('warn'); + platformLogger.error('error'); + + const legacyPlatformLogger = root.logger.get('test-file-legacy'); + legacyPlatformLogger.info('info'); + legacyPlatformLogger.warn('warn'); + legacyPlatformLogger.error('error'); + + // calls shutdown to close write stream and flush logged messages + await root.shutdown(); + + expect(await getPlatformLoggingContent()).toMatchInlineSnapshot(` + "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info + [xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn + [xxxx-xx-xxTxx:xx:xx.xxxZ][ERROR][test-file] error + " + `); + + expect(await getLegacyPlatformLoggingContent()).toMatchInlineSnapshot(` + " log [xx:xx:xx.xxx] [error][test-file-legacy] error + " + `); + }); + + it('"verbose": true', async () => { + const root = createRoot({ verbose: true }); + + await root.setup(); + await root.start(); + + const platformLogger = root.logger.get('test-file'); + platformLogger.info('info'); + platformLogger.warn('warn'); + platformLogger.error('error'); + + const legacyPlatformLogger = root.logger.get('test-file-legacy'); + legacyPlatformLogger.info('info'); + legacyPlatformLogger.warn('warn'); + legacyPlatformLogger.error('error'); + + // calls shutdown to close write stream and flush logged messages + await root.shutdown(); + + expect(await getPlatformLoggingContent()).toMatchInlineSnapshot(` + "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info + [xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn + [xxxx-xx-xxTxx:xx:xx.xxxZ][ERROR][test-file] error + " + `); + + expect(await getLegacyPlatformLoggingContent()).toMatchInlineSnapshot(` + " log [xx:xx:xx.xxx] [info][test-file-legacy] info + log [xx:xx:xx.xxx] [warning][test-file-legacy] warn + log [xx:xx:xx.xxx] [error][test-file-legacy] error + " + `); + }); + }); + }); +}); diff --git a/src/core/server/logging/integration_tests/logging.test.ts b/src/core/server/logging/integration_tests/logging.test.ts new file mode 100644 index 0000000000000..7142f91300f12 --- /dev/null +++ b/src/core/server/logging/integration_tests/logging.test.ts @@ -0,0 +1,114 @@ +/* + * 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 * as kbnTestServer from '../../../../test_utils/kbn_server'; + +function createRoot() { + return kbnTestServer.createRoot({ + logging: { + silent: true, // set "true" in kbnTestServer + appenders: { + 'test-console': { + kind: 'console', + layout: { + highlight: false, + kind: 'pattern', + pattern: '{level}|{context}|{message}', + }, + }, + }, + loggers: [ + { + context: 'parent', + appenders: ['test-console'], + level: 'warn', + }, + { + context: 'parent.child', + appenders: ['test-console'], + level: 'error', + }, + ], + }, + }); +} + +describe('logging service', () => { + describe('logs according to context hierarchy', () => { + let root: ReturnType; + let mockConsoleLog: jest.SpyInstance; + beforeAll(async () => { + mockConsoleLog = jest.spyOn(global.console, 'log'); + root = createRoot(); + + await root.setup(); + }, 30000); + + beforeEach(() => { + mockConsoleLog.mockClear(); + }); + + afterAll(async () => { + mockConsoleLog.mockRestore(); + await root.shutdown(); + }); + + it('uses the most specific context', () => { + const logger = root.logger.get('parent.child'); + + logger.error('error from "parent.child" context'); + logger.warn('warning from "parent.child" context'); + logger.info('info from "parent.child" context'); + + expect(mockConsoleLog).toHaveBeenCalledTimes(1); + expect(mockConsoleLog).toHaveBeenCalledWith( + 'ERROR|parent.child|error from "parent.child" context' + ); + }); + + it('uses parent context', () => { + const logger = root.logger.get('parent.another-child'); + + logger.error('error from "parent.another-child" context'); + logger.warn('warning from "parent.another-child" context'); + logger.info('info from "parent.another-child" context'); + + expect(mockConsoleLog).toHaveBeenCalledTimes(2); + expect(mockConsoleLog).toHaveBeenNthCalledWith( + 1, + 'ERROR|parent.another-child|error from "parent.another-child" context' + ); + expect(mockConsoleLog).toHaveBeenNthCalledWith( + 2, + 'WARN |parent.another-child|warning from "parent.another-child" context' + ); + }); + + it('falls back to the root settings', () => { + const logger = root.logger.get('fallback'); + + logger.error('error from "fallback" context'); + logger.warn('warning from fallback" context'); + logger.info('info from "fallback" context'); + + // output muted by silent: true + expect(mockConsoleLog).toHaveBeenCalledTimes(0); + }); + }); +}); diff --git a/src/core/server/logging/integration_tests/utils.ts b/src/core/server/logging/integration_tests/utils.ts new file mode 100644 index 0000000000000..925118b2e5865 --- /dev/null +++ b/src/core/server/logging/integration_tests/utils.ts @@ -0,0 +1,57 @@ +/* + * 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 Fs from 'fs'; +import Util from 'util'; +const readFile = Util.promisify(Fs.readFile); + +function replaceAllNumbers(input: string) { + return input.replace(/\d/g, 'x'); +} + +function replaceTimestamp(input: string) { + return input.replace(/\[(.*?)\]/, (full, key) => `[${replaceAllNumbers(key)}]`); +} + +function stripColors(input: string) { + return input.replace(/\u001b[^m]+m/g, ''); +} + +export function normalizePlatformLogging(input: string) { + return replaceTimestamp(input); +} + +export function normalizeLegacyPlatformLogging(input: string) { + return replaceTimestamp(stripColors(input)); +} + +export async function getPlatformLoggingContent(path: string) { + const fileContent = await readFile(path, 'utf-8'); + return fileContent + .split('\n') + .map(s => normalizePlatformLogging(s)) + .join('\n'); +} + +export async function getLegacyPlatformLoggingContent(path: string) { + const fileContent = await readFile(path, 'utf-8'); + return fileContent + .split('\n') + .map(s => normalizeLegacyPlatformLogging(s)) + .join('\n'); +} From 7f51269028e006bd8314402ff4fbc18d6c8cbfc3 Mon Sep 17 00:00:00 2001 From: restrry Date: Fri, 31 Jan 2020 14:21:18 +0100 Subject: [PATCH 05/10] use console mocks to simplify test setup --- .../legacy/integration_tests/logging.test.ts | 186 ++++++++++-------- .../server/logging/integration_tests/utils.ts | 15 +- 2 files changed, 115 insertions(+), 86 deletions(-) diff --git a/src/core/server/legacy/integration_tests/logging.test.ts b/src/core/server/legacy/integration_tests/logging.test.ts index a91a4e1278453..6cf7ba1d35686 100644 --- a/src/core/server/legacy/integration_tests/logging.test.ts +++ b/src/core/server/legacy/integration_tests/logging.test.ts @@ -16,37 +16,20 @@ * specific language governing permissions and limitations * under the License. */ -import Fs from 'fs'; -import Path from 'path'; -import Util from 'util'; -import del from 'del'; - import * as kbnTestServer from '../../../../test_utils/kbn_server'; -import { fromRoot } from '../../utils'; + import { - getPlatformLoggingContent as _getPlatformLoggingContent, - getLegacyPlatformLoggingContent as _getLegacyPlatformLoggingContent, + getPlatformLoggingFromMock, + getLegacyPlatformLoggingFromMock, } from '../../logging/integration_tests/utils'; import { LegacyLoggingConfig } from '../config/legacy_object_to_config_adapter'; -const mkdir = Util.promisify(Fs.mkdir); -const truncate = Util.promisify(Fs.truncate); - -const tempFolderPath = fromRoot('data/test/tmp-logging-service'); -const platformDestination = Path.join(tempFolderPath, 'compatibility-np.txt'); -const legacyPlatformDestination = Path.join(tempFolderPath, 'compatibility-lp.txt'); - -const getPlatformLoggingContent = () => _getPlatformLoggingContent(platformDestination); -const getLegacyPlatformLoggingContent = () => - _getLegacyPlatformLoggingContent(legacyPlatformDestination); - function createRoot(legacyLoggingConfig: LegacyLoggingConfig = {}) { return kbnTestServer.createRoot({ logging: { // legacy platform config silent: false, - dest: legacyPlatformDestination, json: false, ...legacyLoggingConfig, events: { @@ -54,10 +37,10 @@ function createRoot(legacyLoggingConfig: LegacyLoggingConfig = {}) { }, // platform config appenders: { - file: { - kind: 'file', - path: platformDestination, + 'test-console': { + kind: 'console', layout: { + highlight: false, kind: 'pattern', }, }, @@ -65,7 +48,7 @@ function createRoot(legacyLoggingConfig: LegacyLoggingConfig = {}) { loggers: [ { context: 'test-file', - appenders: ['file'], + appenders: ['test-console'], level: 'info', }, ], @@ -74,17 +57,20 @@ function createRoot(legacyLoggingConfig: LegacyLoggingConfig = {}) { } describe('logging service', () => { + let mockConsoleLog: jest.SpyInstance; + let mockStdout: jest.SpyInstance; + + beforeAll(async () => { + mockConsoleLog = jest.spyOn(global.console, 'log'); + mockStdout = jest.spyOn(global.process.stdout, 'write'); + }); + + afterAll(async () => { + mockConsoleLog.mockRestore(); + mockStdout.mockRestore(); + }); + describe('compatibility', () => { - beforeAll(async () => { - await mkdir(tempFolderPath, { recursive: true }); - }); - afterAll(async () => { - await del(tempFolderPath); - }); - afterEach(async () => { - await truncate(platformDestination); - await truncate(legacyPlatformDestination); - }); describe('uses configured loggers', () => { let root: ReturnType; beforeAll(async () => { @@ -98,31 +84,49 @@ describe('logging service', () => { await root.shutdown(); }); + beforeEach(() => { + mockConsoleLog.mockClear(); + mockStdout.mockClear(); + }); + it('when context matches', async () => { root.logger.get('test-file').info('handled by NP'); - expect(await getPlatformLoggingContent()).toMatchInlineSnapshot(` - "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] handled by NP - " + expect(mockConsoleLog).toHaveBeenCalledTimes(1); + const loggedString = getPlatformLoggingFromMock(mockConsoleLog); + expect(loggedString).toMatchInlineSnapshot(` + Array [ + "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] handled by NP", + ] `); - - expect(await getLegacyPlatformLoggingContent()).toHaveLength(0); }); it('falls back to the root legacy logger otherwise', async () => { root.logger.get('test-file-legacy').info('handled by LP'); - expect(await getLegacyPlatformLoggingContent()).toMatchInlineSnapshot(` + expect(mockStdout).toHaveBeenCalledTimes(1); + + const loggedString = getLegacyPlatformLoggingFromMock(mockStdout); + expect(loggedString).toMatchInlineSnapshot(` + Array [ " log [xx:xx:xx.xxx] [info][test-file-legacy] handled by LP - " + ", + ] `); - expect(await getPlatformLoggingContent()).toHaveLength(0); }); }); describe('logging config respects legacy logging settings', () => { + let root: ReturnType; + + afterEach(async () => { + mockConsoleLog.mockClear(); + mockStdout.mockClear(); + await root.shutdown(); + }); + it('"silent": true', async () => { - const root = createRoot({ silent: true }); + root = createRoot({ silent: true }); await root.setup(); await root.start(); @@ -132,26 +136,28 @@ describe('logging service', () => { platformLogger.warn('warn'); platformLogger.error('error'); + expect(mockConsoleLog).toHaveBeenCalledTimes(3); + + expect(getPlatformLoggingFromMock(mockConsoleLog)).toMatchInlineSnapshot(` + Array [ + "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info", + "[xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn", + "[xxxx-xx-xxTxx:xx:xx.xxxZ][ERROR][test-file] error", + ] + `); + + mockStdout.mockClear(); + const legacyPlatformLogger = root.logger.get('test-file-legacy'); legacyPlatformLogger.info('info'); legacyPlatformLogger.warn('warn'); legacyPlatformLogger.error('error'); - // calls shutdown to close write stream and flush logged messages - await root.shutdown(); - - expect(await getPlatformLoggingContent()).toMatchInlineSnapshot(` - "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info - [xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn - [xxxx-xx-xxTxx:xx:xx.xxxZ][ERROR][test-file] error - " - `); - - expect(await getLegacyPlatformLoggingContent()).toHaveLength(0); + expect(mockStdout).toHaveBeenCalledTimes(0); }); it('"quiet": true', async () => { - const root = createRoot({ quiet: true }); + root = createRoot({ quiet: true }); await root.setup(); await root.start(); @@ -161,29 +167,34 @@ describe('logging service', () => { platformLogger.warn('warn'); platformLogger.error('error'); + expect(mockConsoleLog).toHaveBeenCalledTimes(3); + + expect(getPlatformLoggingFromMock(mockConsoleLog)).toMatchInlineSnapshot(` + Array [ + "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info", + "[xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn", + "[xxxx-xx-xxTxx:xx:xx.xxxZ][ERROR][test-file] error", + ] + `); + + mockStdout.mockClear(); + const legacyPlatformLogger = root.logger.get('test-file-legacy'); legacyPlatformLogger.info('info'); legacyPlatformLogger.warn('warn'); legacyPlatformLogger.error('error'); - // calls shutdown to close write stream and flush logged messages - await root.shutdown(); - - expect(await getPlatformLoggingContent()).toMatchInlineSnapshot(` - "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info - [xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn - [xxxx-xx-xxTxx:xx:xx.xxxZ][ERROR][test-file] error - " - `); - - expect(await getLegacyPlatformLoggingContent()).toMatchInlineSnapshot(` - " log [xx:xx:xx.xxx] [error][test-file-legacy] error - " + expect(mockStdout).toHaveBeenCalledTimes(1); + expect(getLegacyPlatformLoggingFromMock(mockStdout)).toMatchInlineSnapshot(` + Array [ + " log [xx:xx:xx.xxx] [error][test-file-legacy] error + ", + ] `); }); it('"verbose": true', async () => { - const root = createRoot({ verbose: true }); + root = createRoot({ verbose: true }); await root.setup(); await root.start(); @@ -193,26 +204,33 @@ describe('logging service', () => { platformLogger.warn('warn'); platformLogger.error('error'); + expect(mockConsoleLog).toHaveBeenCalledTimes(3); + + expect(getPlatformLoggingFromMock(mockConsoleLog)).toMatchInlineSnapshot(` + Array [ + "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info", + "[xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn", + "[xxxx-xx-xxTxx:xx:xx.xxxZ][ERROR][test-file] error", + ] + `); + + mockStdout.mockClear(); + const legacyPlatformLogger = root.logger.get('test-file-legacy'); legacyPlatformLogger.info('info'); legacyPlatformLogger.warn('warn'); legacyPlatformLogger.error('error'); - // calls shutdown to close write stream and flush logged messages - await root.shutdown(); - - expect(await getPlatformLoggingContent()).toMatchInlineSnapshot(` - "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info - [xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn - [xxxx-xx-xxTxx:xx:xx.xxxZ][ERROR][test-file] error - " - `); - - expect(await getLegacyPlatformLoggingContent()).toMatchInlineSnapshot(` - " log [xx:xx:xx.xxx] [info][test-file-legacy] info - log [xx:xx:xx.xxx] [warning][test-file-legacy] warn - log [xx:xx:xx.xxx] [error][test-file-legacy] error - " + expect(mockStdout).toHaveBeenCalledTimes(3); + expect(getLegacyPlatformLoggingFromMock(mockStdout)).toMatchInlineSnapshot(` + Array [ + " log [xx:xx:xx.xxx] [info][test-file-legacy] info + ", + " log [xx:xx:xx.xxx] [warning][test-file-legacy] warn + ", + " log [xx:xx:xx.xxx] [error][test-file-legacy] error + ", + ] `); }); }); diff --git a/src/core/server/logging/integration_tests/utils.ts b/src/core/server/logging/integration_tests/utils.ts index 925118b2e5865..c81b96763c879 100644 --- a/src/core/server/logging/integration_tests/utils.ts +++ b/src/core/server/logging/integration_tests/utils.ts @@ -32,14 +32,25 @@ function stripColors(input: string) { return input.replace(/\u001b[^m]+m/g, ''); } -export function normalizePlatformLogging(input: string) { +function normalizePlatformLogging(input: string) { return replaceTimestamp(input); } -export function normalizeLegacyPlatformLogging(input: string) { +function normalizeLegacyPlatformLogging(input: string) { return replaceTimestamp(stripColors(input)); } +export function getPlatformLoggingFromMock(logMock: jest.SpyInstance) { + return logMock.mock.calls.map(([message]) => message).map(normalizePlatformLogging); +} + +export function getLegacyPlatformLoggingFromMock(stdoutMock: jest.SpyInstance) { + return stdoutMock.mock.calls + .map(([message]) => message) + .map(String) + .map(normalizeLegacyPlatformLogging); +} + export async function getPlatformLoggingContent(path: string) { const fileContent = await readFile(path, 'utf-8'); return fileContent From e6bbae433bf563eb2fcc4b6b89433d9f06ff454c Mon Sep 17 00:00:00 2001 From: restrry Date: Fri, 31 Jan 2020 14:39:03 +0100 Subject: [PATCH 06/10] update tests --- .../legacy_object_to_config_adapter.test.ts.snap | 2 ++ src/core/server/logging/logging_config.test.ts | 12 ++++++++++-- src/core/server/logging/logging_config.ts | 7 +++++++ 3 files changed, 19 insertions(+), 2 deletions(-) diff --git a/src/core/server/legacy/config/__snapshots__/legacy_object_to_config_adapter.test.ts.snap b/src/core/server/legacy/config/__snapshots__/legacy_object_to_config_adapter.test.ts.snap index 74ecaa9f09c0e..3b16bed92df97 100644 --- a/src/core/server/legacy/config/__snapshots__/legacy_object_to_config_adapter.test.ts.snap +++ b/src/core/server/legacy/config/__snapshots__/legacy_object_to_config_adapter.test.ts.snap @@ -72,6 +72,7 @@ Object { }, }, }, + "loggers": undefined, "root": Object { "level": "off", }, @@ -90,6 +91,7 @@ Object { }, }, }, + "loggers": undefined, "root": Object { "level": "all", }, diff --git a/src/core/server/logging/logging_config.test.ts b/src/core/server/logging/logging_config.test.ts index 8eb79ac46e499..988f96c1cf104 100644 --- a/src/core/server/logging/logging_config.test.ts +++ b/src/core/server/logging/logging_config.test.ts @@ -46,15 +46,23 @@ test('`getLoggerContext()` returns correct joined context name.', () => { expect(LoggingConfig.getLoggerContext([])).toEqual('root'); }); -test('correctly fills in default `appenders` config.', () => { +test('correctly fills in default config.', () => { const configValue = new LoggingConfig(config.schema.validate({})); - expect(configValue.appenders.size).toBe(1); + expect(configValue.appenders.size).toBe(3); expect(configValue.appenders.get('default')).toEqual({ kind: 'console', layout: { kind: 'pattern', highlight: true }, }); + expect(configValue.appenders.get('console')).toEqual({ + kind: 'console', + layout: { kind: 'pattern', highlight: true }, + }); + expect(configValue.appenders.get('file')).toEqual({ + kind: 'file', + layout: { kind: 'pattern', highlight: false }, + }); }); test('correctly fills in custom `appenders` config.', () => { diff --git a/src/core/server/logging/logging_config.ts b/src/core/server/logging/logging_config.ts index 5b76e96006a77..aa87cd6c0c1ff 100644 --- a/src/core/server/logging/logging_config.ts +++ b/src/core/server/logging/logging_config.ts @@ -117,6 +117,13 @@ export class LoggingConfig { * Map of the appender unique arbitrary key and its corresponding config. */ public readonly appenders: Map = new Map([ + [ + 'default', + { + kind: 'console', + layout: { kind: 'pattern', highlight: true }, + } as AppenderConfigType, + ], [ 'console', { From bae5b6f901fe9acca6ca11f59d7674d83efe697b Mon Sep 17 00:00:00 2001 From: restrry Date: Fri, 31 Jan 2020 14:41:59 +0100 Subject: [PATCH 07/10] improve names --- .../legacy/integration_tests/logging.test.ts | 18 +++++++++--------- .../server/logging/integration_tests/utils.ts | 8 ++++---- 2 files changed, 13 insertions(+), 13 deletions(-) diff --git a/src/core/server/legacy/integration_tests/logging.test.ts b/src/core/server/legacy/integration_tests/logging.test.ts index 6cf7ba1d35686..1923ed2866cde 100644 --- a/src/core/server/legacy/integration_tests/logging.test.ts +++ b/src/core/server/legacy/integration_tests/logging.test.ts @@ -19,8 +19,8 @@ import * as kbnTestServer from '../../../../test_utils/kbn_server'; import { - getPlatformLoggingFromMock, - getLegacyPlatformLoggingFromMock, + getPlatformLogsFromMock, + getLegacyPlatformLogsFromMock, } from '../../logging/integration_tests/utils'; import { LegacyLoggingConfig } from '../config/legacy_object_to_config_adapter'; @@ -93,7 +93,7 @@ describe('logging service', () => { root.logger.get('test-file').info('handled by NP'); expect(mockConsoleLog).toHaveBeenCalledTimes(1); - const loggedString = getPlatformLoggingFromMock(mockConsoleLog); + const loggedString = getPlatformLogsFromMock(mockConsoleLog); expect(loggedString).toMatchInlineSnapshot(` Array [ "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] handled by NP", @@ -106,7 +106,7 @@ describe('logging service', () => { expect(mockStdout).toHaveBeenCalledTimes(1); - const loggedString = getLegacyPlatformLoggingFromMock(mockStdout); + const loggedString = getLegacyPlatformLogsFromMock(mockStdout); expect(loggedString).toMatchInlineSnapshot(` Array [ " log [xx:xx:xx.xxx] [info][test-file-legacy] handled by LP @@ -138,7 +138,7 @@ describe('logging service', () => { expect(mockConsoleLog).toHaveBeenCalledTimes(3); - expect(getPlatformLoggingFromMock(mockConsoleLog)).toMatchInlineSnapshot(` + expect(getPlatformLogsFromMock(mockConsoleLog)).toMatchInlineSnapshot(` Array [ "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info", "[xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn", @@ -169,7 +169,7 @@ describe('logging service', () => { expect(mockConsoleLog).toHaveBeenCalledTimes(3); - expect(getPlatformLoggingFromMock(mockConsoleLog)).toMatchInlineSnapshot(` + expect(getPlatformLogsFromMock(mockConsoleLog)).toMatchInlineSnapshot(` Array [ "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info", "[xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn", @@ -185,7 +185,7 @@ describe('logging service', () => { legacyPlatformLogger.error('error'); expect(mockStdout).toHaveBeenCalledTimes(1); - expect(getLegacyPlatformLoggingFromMock(mockStdout)).toMatchInlineSnapshot(` + expect(getLegacyPlatformLogsFromMock(mockStdout)).toMatchInlineSnapshot(` Array [ " log [xx:xx:xx.xxx] [error][test-file-legacy] error ", @@ -206,7 +206,7 @@ describe('logging service', () => { expect(mockConsoleLog).toHaveBeenCalledTimes(3); - expect(getPlatformLoggingFromMock(mockConsoleLog)).toMatchInlineSnapshot(` + expect(getPlatformLogsFromMock(mockConsoleLog)).toMatchInlineSnapshot(` Array [ "[xxxx-xx-xxTxx:xx:xx.xxxZ][INFO ][test-file] info", "[xxxx-xx-xxTxx:xx:xx.xxxZ][WARN ][test-file] warn", @@ -222,7 +222,7 @@ describe('logging service', () => { legacyPlatformLogger.error('error'); expect(mockStdout).toHaveBeenCalledTimes(3); - expect(getLegacyPlatformLoggingFromMock(mockStdout)).toMatchInlineSnapshot(` + expect(getLegacyPlatformLogsFromMock(mockStdout)).toMatchInlineSnapshot(` Array [ " log [xx:xx:xx.xxx] [info][test-file-legacy] info ", diff --git a/src/core/server/logging/integration_tests/utils.ts b/src/core/server/logging/integration_tests/utils.ts index c81b96763c879..81a76ce76ad73 100644 --- a/src/core/server/logging/integration_tests/utils.ts +++ b/src/core/server/logging/integration_tests/utils.ts @@ -40,18 +40,18 @@ function normalizeLegacyPlatformLogging(input: string) { return replaceTimestamp(stripColors(input)); } -export function getPlatformLoggingFromMock(logMock: jest.SpyInstance) { +export function getPlatformLogsFromMock(logMock: jest.SpyInstance) { return logMock.mock.calls.map(([message]) => message).map(normalizePlatformLogging); } -export function getLegacyPlatformLoggingFromMock(stdoutMock: jest.SpyInstance) { +export function getLegacyPlatformLogsFromMock(stdoutMock: jest.SpyInstance) { return stdoutMock.mock.calls .map(([message]) => message) .map(String) .map(normalizeLegacyPlatformLogging); } -export async function getPlatformLoggingContent(path: string) { +export async function getPlatformLogsFromFile(path: string) { const fileContent = await readFile(path, 'utf-8'); return fileContent .split('\n') @@ -59,7 +59,7 @@ export async function getPlatformLoggingContent(path: string) { .join('\n'); } -export async function getLegacyPlatformLoggingContent(path: string) { +export async function getLegacyPlatformLogsFromFile(path: string) { const fileContent = await readFile(path, 'utf-8'); return fileContent .split('\n') From b4b698cd5806a677b4eb5de69aa770c2f782ba73 Mon Sep 17 00:00:00 2001 From: Mikhail Shustov Date: Tue, 4 Feb 2020 09:56:26 +0100 Subject: [PATCH 08/10] validate that default appender always presents on root level required during migration period to make sure logs are sent to the LP logging system --- .../__snapshots__/logging_config.test.ts.snap | 2 ++ .../server/logging/logging_config.test.ts | 10 ++++++++ src/core/server/logging/logging_config.ts | 23 +++++++++++++------ 3 files changed, 28 insertions(+), 7 deletions(-) diff --git a/src/core/server/logging/__snapshots__/logging_config.test.ts.snap b/src/core/server/logging/__snapshots__/logging_config.test.ts.snap index 10509b20e8942..fe1407563a635 100644 --- a/src/core/server/logging/__snapshots__/logging_config.test.ts.snap +++ b/src/core/server/logging/__snapshots__/logging_config.test.ts.snap @@ -13,6 +13,8 @@ Object { } `; +exports[`\`schema\` throws if \`root\` logger does not have "default" appender configured. 1`] = `"[root]: \\"default\\" appender required for migration period till the next major release"`; + exports[`\`schema\` throws if \`root\` logger does not have appenders configured. 1`] = `"[root.appenders]: array size is [0], but cannot be smaller than [1]"`; exports[`fails if loggers use unknown appenders. 1`] = `"Logger \\"some.nested.context\\" contains unsupported appender key \\"unknown\\"."`; diff --git a/src/core/server/logging/logging_config.test.ts b/src/core/server/logging/logging_config.test.ts index 988f96c1cf104..b3631abb9ff00 100644 --- a/src/core/server/logging/logging_config.test.ts +++ b/src/core/server/logging/logging_config.test.ts @@ -33,6 +33,16 @@ test('`schema` throws if `root` logger does not have appenders configured.', () ).toThrowErrorMatchingSnapshot(); }); +test('`schema` throws if `root` logger does not have "default" appender configured.', () => { + expect(() => + config.schema.validate({ + root: { + appenders: ['console'], + }, + }) + ).toThrowErrorMatchingSnapshot(); +}); + test('`getParentLoggerContext()` returns correct parent context name.', () => { expect(LoggingConfig.getParentLoggerContext('a.b.c')).toEqual('a.b'); expect(LoggingConfig.getParentLoggerContext('a.b')).toEqual('a'); diff --git a/src/core/server/logging/logging_config.ts b/src/core/server/logging/logging_config.ts index aa87cd6c0c1ff..f1fbf787737b4 100644 --- a/src/core/server/logging/logging_config.ts +++ b/src/core/server/logging/logging_config.ts @@ -72,13 +72,22 @@ export const config = { loggers: schema.arrayOf(createLoggerSchema, { defaultValue: [], }), - root: schema.object({ - appenders: schema.arrayOf(schema.string(), { - defaultValue: [DEFAULT_APPENDER_NAME], - minSize: 1, - }), - level: createLevelSchema, - }), + root: schema.object( + { + appenders: schema.arrayOf(schema.string(), { + defaultValue: [DEFAULT_APPENDER_NAME], + minSize: 1, + }), + level: createLevelSchema, + }, + { + validate(rawConfig) { + if (!rawConfig.appenders.includes(DEFAULT_APPENDER_NAME)) { + return `"${DEFAULT_APPENDER_NAME}" appender required for migration period till the next major release`; + } + }, + } + ), }), }; From 554f26f616e9dcd335985f2330a58fd838a36057 Mon Sep 17 00:00:00 2001 From: Mikhail Shustov Date: Tue, 4 Feb 2020 09:57:46 +0100 Subject: [PATCH 09/10] do not check condition in the loop --- src/core/server/logging/logger.ts | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/core/server/logging/logger.ts b/src/core/server/logging/logger.ts index 99a2014be97c1..ac79c1916c07b 100644 --- a/src/core/server/logging/logger.ts +++ b/src/core/server/logging/logger.ts @@ -136,12 +136,12 @@ export class BaseLogger implements Logger { } public log(record: LogRecord) { - const supportedLevel = this.level.supports(record.level); + if (!this.level.supports(record.level)) { + return; + } for (const appender of this.appenders) { - if (supportedLevel) { - appender.append(record); - } + appender.append(record); } } From 8f5f3926ed59c411c162332e2530a00f843c61eb Mon Sep 17 00:00:00 2001 From: Mikhail Shustov Date: Tue, 4 Feb 2020 09:58:12 +0100 Subject: [PATCH 10/10] fix integration tests --- src/core/server/legacy/integration_tests/logging.test.ts | 1 + 1 file changed, 1 insertion(+) diff --git a/src/core/server/legacy/integration_tests/logging.test.ts b/src/core/server/legacy/integration_tests/logging.test.ts index 1923ed2866cde..66234f677903f 100644 --- a/src/core/server/legacy/integration_tests/logging.test.ts +++ b/src/core/server/legacy/integration_tests/logging.test.ts @@ -27,6 +27,7 @@ import { LegacyLoggingConfig } from '../config/legacy_object_to_config_adapter'; function createRoot(legacyLoggingConfig: LegacyLoggingConfig = {}) { return kbnTestServer.createRoot({ + migrations: { skip: true }, // otherwise stuck in polling ES logging: { // legacy platform config silent: false,