diff --git a/src/core/server/logging/__tests__/__snapshots__/logging_service.test.ts.snap b/src/core/server/logging/__tests__/__snapshots__/logging_service.test.ts.snap new file mode 100644 index 00000000000000..ffde6cbcdebd1d --- /dev/null +++ b/src/core/server/logging/__tests__/__snapshots__/logging_service.test.ts.snap @@ -0,0 +1,94 @@ +// Jest Snapshot v1, https://goo.gl/fbAQLP + +exports[`appends records via multiple appenders.: console logs 1`] = ` +Array [ + Array [ + "[2012-02-01T00:00:00.000Z][INFO ][some-context] You know, just for your info.", + ], +] +`; + +exports[`appends records via multiple appenders.: file logs 1`] = ` +Array [ + Array [ + "[2012-02-01T00:00:00.000Z][WARN ][tests] Config is not ready! +", + ], + Array [ + "[2012-02-01T00:00:00.000Z][ERROR][tests.child] Too bad that config is not ready :/ +", + ], +] +`; + +exports[`asLoggerFactory() only allows to create new loggers. 1`] = ` +Array [ + Array [ + "{\\"@timestamp\\":\\"2012-02-01T00:00:00.000Z\\",\\"context\\":\\"test.context\\",\\"level\\":\\"TRACE\\",\\"message\\":\\"buffered trace message\\"}", + ], + Array [ + "{\\"@timestamp\\":\\"2012-02-01T00:00:00.000Z\\",\\"context\\":\\"test.context\\",\\"level\\":\\"INFO\\",\\"message\\":\\"buffered info message\\",\\"meta\\":{\\"some\\":\\"value\\"}}", + ], + Array [ + "{\\"@timestamp\\":\\"2012-02-01T00:00:00.000Z\\",\\"context\\":\\"test.context\\",\\"level\\":\\"FATAL\\",\\"message\\":\\"buffered fatal message\\"}", + ], +] +`; + +exports[`flushes memory buffer logger and switches to real logger once config is provided: buffered messages 1`] = ` +Array [ + Array [ + "{\\"@timestamp\\":\\"2012-02-01T00:00:00.000Z\\",\\"context\\":\\"test.context\\",\\"level\\":\\"INFO\\",\\"message\\":\\"buffered info message\\",\\"meta\\":{\\"some\\":\\"value\\"}}", + ], + Array [ + "{\\"@timestamp\\":\\"2012-02-01T00:00:00.000Z\\",\\"context\\":\\"test.context\\",\\"level\\":\\"FATAL\\",\\"message\\":\\"buffered fatal message\\"}", + ], +] +`; + +exports[`flushes memory buffer logger and switches to real logger once config is provided: new messages 1`] = ` +Array [ + Array [ + "{\\"@timestamp\\":\\"2012-02-01T00:00:00.000Z\\",\\"context\\":\\"test.context\\",\\"level\\":\\"INFO\\",\\"message\\":\\"some new info message\\"}", + ], +] +`; + +exports[`uses \`root\` logger if context is not specified. 1`] = ` +Array [ + Array [ + "[2012-02-01T00:00:00.000Z][INFO ][root] This message goes to a root context.", + ], +] +`; + +exports[`uses default memory buffer logger until config is provided 1`] = ` +Array [ + Array [ + Object { + "context": "test.context", + "level": LogLevel { + "id": "trace", + "value": 7, + }, + "message": "trace message", + "meta": undefined, + "timestamp": 2012-02-01T00:00:00.000Z, + }, + ], + Array [ + Object { + "context": "test.context2", + "level": LogLevel { + "id": "fatal", + "value": 2, + }, + "message": "fatal message", + "meta": Object { + "some": "value", + }, + "timestamp": 2012-02-01T00:00:00.000Z, + }, + ], +] +`; diff --git a/src/core/server/logging/__tests__/logger_factory.test.ts b/src/core/server/logging/__tests__/logger_factory.test.ts deleted file mode 100644 index d7552528f8bac0..00000000000000 --- a/src/core/server/logging/__tests__/logger_factory.test.ts +++ /dev/null @@ -1,168 +0,0 @@ -/* - * 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. - */ - -const mockCreateWriteStream: any = {}; - -jest.mock('fs', () => ({ - createWriteStream: () => mockCreateWriteStream, -})); - -import { MutableLoggerFactory } from '../logger_factory'; -import { LoggingConfig } from '../logging_config'; - -const tickMs = (ms: number) => new Promise(resolve => setTimeout(resolve, ms)); - -const mockStreamEndFinished = jest.fn(); -mockCreateWriteStream.write = jest.fn(); -mockCreateWriteStream.end = jest.fn(async (chunk, encoding, callback) => { - // It's required to make sure `dispose` waits for `end` to complete. - await tickMs(100); - mockStreamEndFinished(); - callback(); -}); - -const timestamp = new Date(Date.UTC(2012, 1, 1)); -const mockConsoleLog = jest.spyOn(global.console, 'log').mockImplementation(() => { - // noop -}); -jest.spyOn(global, 'Date').mockImplementation(() => timestamp); - -beforeEach(() => { - mockCreateWriteStream.write.mockClear(); - mockCreateWriteStream.end.mockClear(); - mockStreamEndFinished.mockClear(); - mockConsoleLog.mockClear(); -}); - -test('`get()` returns Logger that appends records to buffer if config is not ready.', () => { - const factory = new MutableLoggerFactory(); - const loggerWithoutConfig = factory.get('some-context'); - const testsLogger = factory.get('tests'); - const testsChildLogger = factory.get('tests', 'child'); - - loggerWithoutConfig.info('You know, just for your info.'); - testsLogger.warn('Config is not ready!'); - testsChildLogger.error('Too bad that config is not ready :/'); - testsChildLogger.info('Just some info that should not be logged.'); - - expect(mockConsoleLog).not.toHaveBeenCalled(); - expect(mockCreateWriteStream.write).not.toHaveBeenCalled(); - - const loggingConfigSchema = LoggingConfig.schema; - const config = new LoggingConfig( - loggingConfigSchema.validate({ - appenders: { - default: { - kind: 'console', - layout: { kind: 'pattern' }, - }, - file: { - kind: 'file', - layout: { kind: 'pattern' }, - path: 'path', - }, - }, - loggers: [ - { - appenders: ['file'], - context: 'tests', - level: 'warn', - }, - { - context: 'tests.child', - level: 'error', - }, - ], - }) - ); - - factory.updateConfig(config); - - // Now all logs should added to configured appenders. - expect(mockConsoleLog).toHaveBeenCalledTimes(1); - expect(mockConsoleLog).toHaveBeenCalledWith( - '[2012-02-01T00:00:00.000Z][INFO ][some-context] You know, just for your info.' - ); - - expect(mockCreateWriteStream.write).toHaveBeenCalledTimes(2); - expect(mockCreateWriteStream.write).toHaveBeenCalledWith( - '[2012-02-01T00:00:00.000Z][WARN ][tests] Config is not ready!\n' - ); - expect(mockCreateWriteStream.write).toHaveBeenCalledWith( - '[2012-02-01T00:00:00.000Z][ERROR][tests.child] Too bad that config is not ready :/\n' - ); -}); - -test('`get()` returns `root` logger if context is not specified.', () => { - const loggingConfigSchema = LoggingConfig.schema; - const factory = new MutableLoggerFactory(); - const config = loggingConfigSchema.validate({ - appenders: { - default: { - kind: 'console', - layout: { kind: 'pattern' }, - }, - }, - }); - factory.updateConfig(new LoggingConfig(config)); - - const rootLogger = factory.get(); - - rootLogger.info('This message goes to a root context.'); - - expect(mockConsoleLog).toHaveBeenCalledTimes(1); - expect(mockConsoleLog).toHaveBeenCalledWith( - '[2012-02-01T00:00:00.000Z][INFO ][root] This message goes to a root context.' - ); -}); - -test('`close()` disposes all resources used by appenders.', async () => { - const factory = new MutableLoggerFactory(); - - const loggingConfigSchema = LoggingConfig.schema; - const config = new LoggingConfig( - loggingConfigSchema.validate({ - appenders: { - default: { - kind: 'file', - layout: { kind: 'pattern' }, - path: 'path', - }, - }, - }) - ); - - factory.updateConfig(config); - - const logger = factory.get('some-context'); - logger.info('You know, just for your info.'); - - expect(mockCreateWriteStream.write).toHaveBeenCalled(); - expect(mockCreateWriteStream.end).not.toHaveBeenCalled(); - - await factory.close(); - - expect(mockCreateWriteStream.end).toHaveBeenCalledTimes(1); - expect(mockCreateWriteStream.end).toHaveBeenCalledWith( - undefined, - undefined, - expect.any(Function) - ); - expect(mockStreamEndFinished).toHaveBeenCalled(); -}); diff --git a/src/core/server/logging/__tests__/logging_service.test.ts b/src/core/server/logging/__tests__/logging_service.test.ts index ae823e29803297..eb452376d6ccc0 100644 --- a/src/core/server/logging/__tests__/logging_service.test.ts +++ b/src/core/server/logging/__tests__/logging_service.test.ts @@ -17,70 +17,157 @@ * under the License. */ -import { BehaviorSubject } from 'rxjs'; -import { MutableLoggerFactory } from '../logger_factory'; +const mockStreamWrite = jest.fn(); +jest.mock('fs', () => ({ + constants: {}, + createWriteStream: jest.fn(() => ({ write: mockStreamWrite })), +})); + +const timestamp = new Date(Date.UTC(2012, 1, 1)); +const mockConsoleLog = jest.spyOn(global.console, 'log').mockImplementation(() => { + // noop +}); +jest.spyOn(global, 'Date').mockImplementation(() => timestamp); + +import { createWriteStream } from 'fs'; +const mockCreateWriteStream = createWriteStream as jest.Mock; + import { LoggingConfig } from '../logging_config'; import { LoggingService } from '../logging_service'; -const createConfig = () => { - return new LoggingConfig({ - appenders: new Map(), - loggers: [], - root: { - appenders: ['default'], - level: 'info', - }, - }); -}; - -const getLastMockCallArgs = (mockFunction: jest.Mock<(config: LoggingConfig) => void>) => { - expect(mockFunction).toHaveBeenCalled(); - return mockFunction.mock.calls[mockFunction.mock.calls.length - 1]; -}; - -let factory: MutableLoggerFactory; let service: LoggingService; -let updateConfigMock: jest.Mock<(config: LoggingConfig) => void>; - -beforeEach(() => { - factory = new MutableLoggerFactory(); - updateConfigMock = jest.spyOn(factory, 'updateConfig').mockImplementation(() => { - // noop - }); - jest.spyOn(factory, 'close').mockImplementation(() => { - // noop - }); - - service = new LoggingService(factory); +beforeEach(() => (service = new LoggingService())); + +afterEach(() => { + mockConsoleLog.mockClear(); + mockCreateWriteStream.mockClear(); + mockStreamWrite.mockClear(); +}); + +test('uses default memory buffer logger until config is provided', () => { + const bufferAppendSpy = jest.spyOn((service as any).bufferAppender, 'append'); + + const logger = service.get('test', 'context'); + logger.trace('trace message'); + + // We shouldn't create new buffer appender for another context. + const anotherLogger = service.get('test', 'context2'); + anotherLogger.fatal('fatal message', { some: 'value' }); + + expect(bufferAppendSpy.mock.calls).toMatchSnapshot(); }); -test('`upgrade()` updates logging factory config.', () => { - expect(factory.updateConfig).not.toHaveBeenCalled(); +test('flushes memory buffer logger and switches to real logger once config is provided', () => { + const logger = service.get('test', 'context'); + + logger.trace('buffered trace message'); + logger.info('buffered info message', { some: 'value' }); + logger.fatal('buffered fatal message'); - const config = createConfig(); - const config$ = new BehaviorSubject(config); + const bufferAppendSpy = jest.spyOn((service as any).bufferAppender, 'append'); - service.upgrade(config$.asObservable()); + // Switch to console appender with `info` level, so that `trace` message won't go through. + service.upgrade( + new LoggingConfig( + LoggingConfig.schema.validate({ + appenders: { default: { kind: 'console', layout: { kind: 'json' } } }, + root: { level: 'info' }, + }) + ) + ); - expect(updateConfigMock).toHaveBeenCalledTimes(1); - expect(getLastMockCallArgs(updateConfigMock)[0]).toBe(config); + expect(mockConsoleLog.mock.calls).toMatchSnapshot('buffered messages'); + mockConsoleLog.mockClear(); - const newConfig = createConfig(); - config$.next(newConfig); - expect(updateConfigMock).toHaveBeenCalledTimes(2); - expect(getLastMockCallArgs(updateConfigMock)[0]).toBe(newConfig); + // Now message should go straight to thew newly configured appender, not buffered one. + logger.info('some new info message'); + expect(mockConsoleLog.mock.calls).toMatchSnapshot('new messages'); + expect(bufferAppendSpy).not.toHaveBeenCalled(); }); -test('`stop()` closes logger factory and stops config updates.', async () => { - const config$ = new BehaviorSubject(createConfig()); +test('appends records via multiple appenders.', () => { + const loggerWithoutConfig = service.get('some-context'); + const testsLogger = service.get('tests'); + const testsChildLogger = service.get('tests', 'child'); + + loggerWithoutConfig.info('You know, just for your info.'); + testsLogger.warn('Config is not ready!'); + testsChildLogger.error('Too bad that config is not ready :/'); + testsChildLogger.info('Just some info that should not be logged.'); + + expect(mockConsoleLog).not.toHaveBeenCalled(); + expect(mockCreateWriteStream).not.toHaveBeenCalled(); + + service.upgrade( + new LoggingConfig( + LoggingConfig.schema.validate({ + appenders: { + default: { kind: 'console', layout: { kind: 'pattern' } }, + file: { kind: 'file', layout: { kind: 'pattern' }, path: 'path' }, + }, + loggers: [ + { appenders: ['file'], context: 'tests', level: 'warn' }, + { context: 'tests.child', level: 'error' }, + ], + }) + ) + ); + + // Now all logs should added to configured appenders. + expect(mockConsoleLog.mock.calls).toMatchSnapshot('console logs'); + expect(mockStreamWrite.mock.calls).toMatchSnapshot('file logs'); +}); + +test('uses `root` logger if context is not specified.', () => { + service.upgrade( + new LoggingConfig( + LoggingConfig.schema.validate({ + appenders: { default: { kind: 'console', layout: { kind: 'pattern' } } }, + }) + ) + ); + + const rootLogger = service.get(); + rootLogger.info('This message goes to a root context.'); + + expect(mockConsoleLog.mock.calls).toMatchSnapshot(); +}); - service.upgrade(config$.asObservable()); - updateConfigMock.mockReset(); +test('`stop()` disposes all appenders.', async () => { + service.upgrade( + new LoggingConfig( + LoggingConfig.schema.validate({ + appenders: { default: { kind: 'console', layout: { kind: 'json' } } }, + root: { level: 'info' }, + }) + ) + ); + + const bufferDisposeSpy = jest.spyOn((service as any).bufferAppender, 'dispose'); + const consoleDisposeSpy = jest.spyOn((service as any).appenders.get('default'), 'dispose'); await service.stop(); - expect(factory.close).toHaveBeenCalled(); + expect(bufferDisposeSpy).toHaveBeenCalledTimes(1); + expect(consoleDisposeSpy).toHaveBeenCalledTimes(1); +}); + +test('asLoggerFactory() only allows to create new loggers.', () => { + const logger = service.asLoggerFactory().get('test', 'context'); + + service.upgrade( + new LoggingConfig( + LoggingConfig.schema.validate({ + appenders: { default: { kind: 'console', layout: { kind: 'json' } } }, + root: { level: 'all' }, + }) + ) + ); + + logger.trace('buffered trace message'); + logger.info('buffered info message', { some: 'value' }); + logger.fatal('buffered fatal message'); - config$.next(createConfig()); - expect(updateConfigMock).not.toHaveBeenCalled(); + expect(Object.keys(service.asLoggerFactory())).toEqual(['get']); + expect(mockConsoleLog.mock.calls).toMatchSnapshot(); }); diff --git a/src/core/server/logging/index.ts b/src/core/server/logging/index.ts index 2ecb73899935ed..eb31691028e1c5 100644 --- a/src/core/server/logging/index.ts +++ b/src/core/server/logging/index.ts @@ -19,3 +19,5 @@ export { Logger } from './logger'; export { LoggerFactory } from './logger_factory'; +export { LoggingConfig } from './logging_config'; +export { LoggingService } from './logging_service'; diff --git a/src/core/server/logging/logger_factory.ts b/src/core/server/logging/logger_factory.ts index 0d8f5919562f9d..10e7608eb7a9dc 100644 --- a/src/core/server/logging/logger_factory.ts +++ b/src/core/server/logging/logger_factory.ts @@ -17,12 +17,7 @@ * under the License. */ -import { Appenders, DisposableAppender } from './appenders/appenders'; -import { BufferAppender } from './appenders/buffer/buffer_appender'; -import { LogLevel } from './log_level'; -import { BaseLogger, Logger } from './logger'; -import { LoggerAdapter } from './logger_adapter'; -import { LoggerConfigType, LoggingConfig } from './logging_config'; +import { Logger } from './logger'; /** * The single purpose of `LoggerFactory` interface is to define a way to @@ -36,97 +31,3 @@ export interface LoggerFactory { */ get(...contextParts: string[]): Logger; } - -/** @internal */ -export class MutableLoggerFactory implements LoggerFactory { - private config?: LoggingConfig; - private readonly appenders: Map = new Map(); - private readonly bufferAppender = new BufferAppender(); - private readonly loggers: Map = new Map(); - - public get(...contextParts: string[]): Logger { - const context = LoggingConfig.getLoggerContext(contextParts); - if (this.loggers.has(context)) { - return this.loggers.get(context)!; - } - - this.loggers.set(context, new LoggerAdapter(this.createLogger(context, this.config))); - - return this.loggers.get(context)!; - } - - /** - * Updates all current active loggers with the new config values. - * @param config New config instance. - */ - public updateConfig(config: LoggingConfig) { - // Config update is asynchronous and may require some time to complete, so we should invalidate - // config so that new loggers will be using BufferAppender until newly configured appenders are ready. - this.config = undefined; - - // Appenders must be reset, so we first dispose of the current ones, then - // build up a new set of appenders. - - for (const appender of this.appenders.values()) { - appender.dispose(); - } - this.appenders.clear(); - - for (const [appenderKey, appenderConfig] of config.appenders.entries()) { - this.appenders.set(appenderKey, Appenders.create(appenderConfig)); - } - - for (const [loggerKey, loggerAdapter] of this.loggers.entries()) { - loggerAdapter.updateLogger(this.createLogger(loggerKey, config)); - } - - this.config = config; - - // Re-log all buffered log records with newly configured appenders. - for (const logRecord of this.bufferAppender.flush()) { - this.get(logRecord.context).log(logRecord); - } - } - - /** - * Disposes all loggers (closes log files, clears buffers etc.). Factory is not usable after - * calling of this method. - * @returns Promise that is resolved once all loggers are successfully disposed. - */ - public async close() { - for (const appender of this.appenders.values()) { - await appender.dispose(); - } - - await this.bufferAppender.dispose(); - - this.appenders.clear(); - this.loggers.clear(); - } - - private createLogger(context: string, config: LoggingConfig | undefined) { - if (config === undefined) { - // If we don't have config yet, use `buffered` appender that will store all logged messages in the memory - // until the config is ready. - return new BaseLogger(context, LogLevel.All, [this.bufferAppender]); - } - - const { level, appenders } = this.getLoggerConfigByContext(config, context); - const loggerLevel = LogLevel.fromId(level); - const loggerAppenders = appenders.map(appenderKey => this.appenders.get(appenderKey)!); - - return new BaseLogger(context, loggerLevel, loggerAppenders); - } - - private getLoggerConfigByContext(config: LoggingConfig, context: string): LoggerConfigType { - const loggerConfig = config.loggers.get(context); - if (loggerConfig !== undefined) { - return loggerConfig; - } - - // If we don't have configuration for the specified context and it's the "nested" one (eg. `foo.bar.baz`), - // let's move up to the parent context (eg. `foo.bar`) and check if it has config we can rely on. Otherwise - // we fallback to the `root` context that should always be defined (enforced by configuration schema). - return this.getLoggerConfigByContext(config, LoggingConfig.getParentLoggerContext(context)); - } -} diff --git a/src/core/server/logging/logging_service.ts b/src/core/server/logging/logging_service.ts index 6ea962bd12042d..90ee9524381dee 100644 --- a/src/core/server/logging/logging_service.ts +++ b/src/core/server/logging/logging_service.ts @@ -16,40 +16,112 @@ * specific language governing permissions and limitations * under the License. */ - -import { Observable, Subscription } from 'rxjs'; - -import { MutableLoggerFactory } from './logger_factory'; -import { LoggingConfig } from './logging_config'; +import { Appenders, DisposableAppender } from './appenders/appenders'; +import { BufferAppender } from './appenders/buffer/buffer_appender'; +import { LogLevel } from './log_level'; +import { BaseLogger, Logger } from './logger'; +import { LoggerAdapter } from './logger_adapter'; +import { LoggerFactory } from './logger_factory'; +import { LoggerConfigType, LoggingConfig } from './logging_config'; /** - * Service that is responsible for maintaining the log config subscription and - * pushing updates the the logger factory. + * Service that is responsible for maintaining loggers and logger appenders. */ -export class LoggingService { - private subscription?: Subscription; +export class LoggingService implements LoggerFactory { + private config?: LoggingConfig; + private readonly appenders: Map = new Map(); + private readonly bufferAppender = new BufferAppender(); + private readonly loggers: Map = new Map(); + + public get(...contextParts: string[]): Logger { + const context = LoggingConfig.getLoggerContext(contextParts); + if (this.loggers.has(context)) { + return this.loggers.get(context)!; + } - constructor(private readonly loggingFactory: MutableLoggerFactory) {} + this.loggers.set(context, new LoggerAdapter(this.createLogger(context, this.config))); + + return this.loggers.get(context)!; + } /** - * Takes `LoggingConfig` observable and pushes all config updates to the - * internal logger factory. - * @param config$ Observable that tracks all updates in the logging config. + * Safe wrapper that allows passing logging service as immutable LoggerFactory. */ - public upgrade(config$: Observable) { - this.subscription = config$.subscribe({ - next: config => this.loggingFactory.updateConfig(config), - }); + public asLoggerFactory(): LoggerFactory { + return { get: (...contextParts: string[]) => this.get(...contextParts) }; + } + + /** + * Updates all current active loggers with the new config values. + * @param config New config instance. + */ + public upgrade(config: LoggingConfig) { + // Config update is asynchronous and may require some time to complete, so we should invalidate + // config so that new loggers will be using BufferAppender until newly configured appenders are ready. + this.config = undefined; + + // Appenders must be reset, so we first dispose of the current ones, then + // build up a new set of appenders. + for (const appender of this.appenders.values()) { + appender.dispose(); + } + this.appenders.clear(); + + for (const [appenderKey, appenderConfig] of config.appenders) { + this.appenders.set(appenderKey, Appenders.create(appenderConfig)); + } + + for (const [loggerKey, loggerAdapter] of this.loggers.entries()) { + loggerAdapter.updateLogger(this.createLogger(loggerKey, config)); + } + + this.config = config; + + // Re-log all buffered log records with newly configured appenders. + for (const logRecord of this.bufferAppender.flush()) { + this.get(logRecord.context).log(logRecord); + } } /** - * Asynchronous method that causes service to unsubscribe from logging config updates - * and close internal logger factory. + * Disposes all loggers (closes log files, clears buffers etc.). Service is not usable after + * calling of this method until new config is provided via `upgrade` method. + * @returns Promise that is resolved once all loggers are successfully disposed. */ public async stop() { - if (this.subscription !== undefined) { - this.subscription.unsubscribe(); + for (const appender of this.appenders.values()) { + await appender.dispose(); } - await this.loggingFactory.close(); + + await this.bufferAppender.dispose(); + + this.appenders.clear(); + this.loggers.clear(); + } + + private createLogger(context: string, config: LoggingConfig | undefined) { + if (config === undefined) { + // If we don't have config yet, use `buffered` appender that will store all logged messages in the memory + // until the config is ready. + return new BaseLogger(context, LogLevel.All, [this.bufferAppender]); + } + + const { level, appenders } = this.getLoggerConfigByContext(config, context); + const loggerLevel = LogLevel.fromId(level); + const loggerAppenders = appenders.map(appenderKey => this.appenders.get(appenderKey)!); + + return new BaseLogger(context, loggerLevel, loggerAppenders); + } + + private getLoggerConfigByContext(config: LoggingConfig, context: string): LoggerConfigType { + const loggerConfig = config.loggers.get(context); + if (loggerConfig !== undefined) { + return loggerConfig; + } + + // If we don't have configuration for the specified context and it's the "nested" one (eg. `foo.bar.baz`), + // let's move up to the parent context (eg. `foo.bar`) and check if it has config we can rely on. Otherwise + // we fallback to the `root` context that should always be defined (enforced by configuration schema). + return this.getLoggerConfigByContext(config, LoggingConfig.getParentLoggerContext(context)); } } diff --git a/src/core/server/root/__tests__/__snapshots__/index.test.ts.snap b/src/core/server/root/__tests__/__snapshots__/index.test.ts.snap index e6ada3eaf3c30c..a4606c812bff64 100644 --- a/src/core/server/root/__tests__/__snapshots__/index.test.ts.snap +++ b/src/core/server/root/__tests__/__snapshots__/index.test.ts.snap @@ -1,12 +1,19 @@ // Jest Snapshot v1, https://goo.gl/fbAQLP -exports[`when configuring logger fails calls shutdown 1`] = `[Error: foo bar baz]`; +exports[`fails and stops services if initial logger upgrade fails 1`] = ` +Array [ + Array [ + "Configuring logger failed:", + [Error: logging config upgrade failed], + ], +] +`; -exports[`when configuring logger fails calls shutdown 2`] = ` +exports[`stops services if consequent logger upgrade fails 1`] = ` Array [ Array [ "Configuring logger failed:", - "foo bar baz", + [Error: logging config consequent upgrade failed], ], ] `; diff --git a/src/core/server/root/__tests__/index.test.ts b/src/core/server/root/__tests__/index.test.ts index d675dc7229cbfa..d59cee896cc1e6 100644 --- a/src/core/server/root/__tests__/index.test.ts +++ b/src/core/server/root/__tests__/index.test.ts @@ -17,52 +17,25 @@ * under the License. */ -import { getEnvOptions } from '../../config/__tests__/__mocks__/env'; - -const loggerConfig = {}; - -const configService = { - atPath: jest.fn(() => loggerConfig), -}; - -const mockConfigService = jest.fn(() => configService); - -const server = { - start: jest.fn(), - stop: jest.fn(), -}; -const mockServer = jest.fn(() => server); - -const loggingService = { - stop: jest.fn(), - upgrade: jest.fn(), -}; - -const logger = { - get: jest.fn(() => ({ - error: jest.fn(), - info: jest.fn(), - })), -}; +const mockLoggingService = { asLoggerFactory: jest.fn(), upgrade: jest.fn(), stop: jest.fn() }; +jest.mock('../../logging', () => ({ + LoggingService: jest.fn(() => mockLoggingService), +})); -const mockMutableLoggerFactory = jest.fn(() => logger); +const mockConfigService = { atPath: jest.fn() }; +jest.mock('../../config/config_service', () => ({ + ConfigService: jest.fn(() => mockConfigService), +})); -const mockLoggingService = jest.fn(() => loggingService); +const mockServer = { start: jest.fn(), stop: jest.fn() }; +jest.mock('../../', () => ({ Server: jest.fn(() => mockServer) })); import { BehaviorSubject } from 'rxjs'; - -jest.mock('../../config', () => ({ ConfigService: mockConfigService })); -jest.mock('../../', () => ({ Server: mockServer })); -jest.mock('../../logging/logging_service', () => ({ - LoggingService: mockLoggingService, -})); -jest.mock('../../logging/logger_factory', () => ({ - MutableLoggerFactory: mockMutableLoggerFactory, -})); - +import { filter, first } from 'rxjs/operators'; import { Root } from '../'; -import { Env } from '../../config/env'; -import { RawConfig } from '../../config/raw_config'; +import { Env, RawConfig } from '../../config'; +import { getEnvOptions } from '../../config/__tests__/__mocks__/env'; +import { logger } from '../../logging/__mocks__'; const env = new Env('.', getEnvOptions()); const config$ = new BehaviorSubject({} as RawConfig); @@ -70,86 +43,172 @@ const config$ = new BehaviorSubject({} as RawConfig); const mockProcessExit = jest.spyOn(global.process, 'exit').mockImplementation(() => { // noop }); + +const mockConsoleError = jest.spyOn(console, 'error').mockImplementation(() => { + // noop +}); + +beforeEach(() => { + mockLoggingService.asLoggerFactory.mockReturnValue(logger); + mockConfigService.atPath.mockReturnValue(new BehaviorSubject({ someValue: 'foo' })); +}); + afterEach(() => { mockProcessExit.mockReset(); + mockConsoleError.mockReset(); + + mockLoggingService.upgrade.mockReset(); + mockLoggingService.stop.mockReset(); + mockLoggingService.asLoggerFactory.mockReset(); + mockConfigService.atPath.mockReset(); + mockServer.start.mockReset(); + mockServer.stop.mockReset(); }); test('starts services on "start"', async () => { const root = new Root(config$, env); - expect(loggingService.upgrade).toHaveBeenCalledTimes(0); - expect(server.start).toHaveBeenCalledTimes(0); + expect(mockLoggingService.upgrade).not.toHaveBeenCalled(); + expect(mockServer.start).not.toHaveBeenCalled(); await root.start(); - expect(loggingService.upgrade).toHaveBeenCalledTimes(1); - expect(loggingService.upgrade).toHaveBeenLastCalledWith(loggerConfig); - expect(server.start).toHaveBeenCalledTimes(1); + expect(mockLoggingService.upgrade).toHaveBeenCalledTimes(1); + expect(mockLoggingService.upgrade).toHaveBeenLastCalledWith({ someValue: 'foo' }); + expect(mockServer.start).toHaveBeenCalledTimes(1); }); -test('stops services on "shutdown"', async () => { +test('upgrades logging configuration after start', async () => { + const mockLoggingConfig$ = new BehaviorSubject({ someValue: 'foo' }); + mockConfigService.atPath.mockReturnValue(mockLoggingConfig$); + const root = new Root(config$, env); + await root.start(); + + expect(mockLoggingService.upgrade).toHaveBeenCalledTimes(1); + expect(mockLoggingService.upgrade).toHaveBeenLastCalledWith({ someValue: 'foo' }); + mockLoggingService.upgrade.mockClear(); + + mockLoggingConfig$.next({ someValue: 'bar' }); + + expect(mockLoggingService.upgrade).toHaveBeenCalledTimes(1); + expect(mockLoggingService.upgrade).toHaveBeenLastCalledWith({ someValue: 'bar' }); +}); + +test('stops services on "shutdown"', async () => { + const mockOnShutdown = jest.fn(); + const root = new Root(config$, env, mockOnShutdown); await root.start(); - expect(loggingService.stop).toHaveBeenCalledTimes(0); - expect(server.stop).toHaveBeenCalledTimes(0); + expect(mockOnShutdown).not.toHaveBeenCalled(); + expect(mockLoggingService.stop).not.toHaveBeenCalled(); + expect(mockServer.stop).not.toHaveBeenCalled(); await root.shutdown(); - expect(loggingService.stop).toHaveBeenCalledTimes(1); - expect(server.stop).toHaveBeenCalledTimes(1); + expect(mockOnShutdown).toHaveBeenCalledTimes(1); + expect(mockOnShutdown).toHaveBeenCalledWith(undefined); + expect(mockLoggingService.stop).toHaveBeenCalledTimes(1); + expect(mockServer.stop).toHaveBeenCalledTimes(1); }); -test('calls onShutdown param on "shutdown"', async () => { - const onShutdown = jest.fn(); - - const root = new Root(config$, env, onShutdown); +test('stops services on "shutdown" an calls `onShutdown` with error passed to `shutdown`', async () => { + const mockOnShutdown = jest.fn(); + const root = new Root(config$, env, mockOnShutdown); await root.start(); - expect(onShutdown).toHaveBeenCalledTimes(0); + expect(mockOnShutdown).not.toHaveBeenCalled(); + expect(mockLoggingService.stop).not.toHaveBeenCalled(); + expect(mockServer.stop).not.toHaveBeenCalled(); - const err = new Error('shutdown'); + const someFatalError = new Error('some fatal error'); + await root.shutdown(someFatalError); - await root.shutdown(err); + expect(mockOnShutdown).toHaveBeenCalledTimes(1); + expect(mockOnShutdown).toHaveBeenCalledWith(someFatalError); + expect(mockLoggingService.stop).toHaveBeenCalledTimes(1); + expect(mockServer.stop).toHaveBeenCalledTimes(1); +}); + +test('fails and stops services if server fails to start', async () => { + const mockOnShutdown = jest.fn(); + const root = new Root(config$, env, mockOnShutdown); + + const serverError = new Error('server failed'); + mockServer.start.mockRejectedValue(serverError); + + expect(mockOnShutdown).not.toHaveBeenCalled(); + expect(mockLoggingService.stop).not.toHaveBeenCalled(); + expect(mockServer.stop).not.toHaveBeenCalled(); + + await expect(root.start()).rejects.toThrowError('server failed'); - expect(onShutdown).toHaveBeenCalledTimes(1); - expect(onShutdown).toHaveBeenLastCalledWith(err); + expect(mockOnShutdown).toHaveBeenCalledTimes(1); + expect(mockOnShutdown).toHaveBeenCalledWith(serverError); + expect(mockLoggingService.stop).toHaveBeenCalledTimes(1); + expect(mockServer.stop).toHaveBeenCalledTimes(1); }); -describe('when configuring logger fails', () => { - const logged = jest.spyOn(console, 'error'); +test('fails and stops services if initial logger upgrade fails', async () => { + const mockOnShutdown = jest.fn(); + const root = new Root(config$, env, mockOnShutdown); - beforeEach(() => { - logged.mockImplementation(() => { - // noop - }); + const loggingUpgradeError = new Error('logging config upgrade failed'); + mockLoggingService.upgrade.mockImplementation(() => { + throw loggingUpgradeError; }); - afterEach(() => { - logged.mockRestore(); - }); + expect(mockOnShutdown).not.toHaveBeenCalled(); + expect(mockLoggingService.stop).not.toHaveBeenCalled(); + expect(mockServer.start).not.toHaveBeenCalled(); - test('calls shutdown', async () => { - const onShutdown = jest.fn(); + await expect(root.start()).rejects.toThrowError('logging config upgrade failed'); - const root = new Root(config$, env, onShutdown); - const err = new Error('foo bar baz'); + expect(mockOnShutdown).toHaveBeenCalledTimes(1); + expect(mockOnShutdown).toHaveBeenCalledWith(loggingUpgradeError); + expect(mockServer.start).not.toHaveBeenCalled(); + expect(mockLoggingService.stop).toHaveBeenCalledTimes(1); - configService.atPath.mockImplementationOnce(() => { - throw err; - }); + expect(mockConsoleError.mock.calls).toMatchSnapshot(); +}); - mockServer.mockClear(); +test('stops services if consequent logger upgrade fails', async () => { + const onShutdown = new BehaviorSubject(null); + const mockOnShutdown = jest.fn(() => { + onShutdown.next('completed'); + onShutdown.complete(); + }); - await expect(root.start()).rejects.toMatchSnapshot(); + const mockLoggingConfig$ = new BehaviorSubject({ someValue: 'foo' }); + mockConfigService.atPath.mockReturnValue(mockLoggingConfig$); - expect(mockServer).not.toHaveBeenCalled(); + const root = new Root(config$, env, mockOnShutdown); + await root.start(); - expect(onShutdown).toHaveBeenCalledTimes(1); - expect(onShutdown).toHaveBeenLastCalledWith(err); + expect(mockOnShutdown).not.toHaveBeenCalled(); + expect(mockLoggingService.stop).not.toHaveBeenCalled(); + expect(mockServer.stop).not.toHaveBeenCalled(); - expect(logged.mock.calls).toMatchSnapshot(); + const loggingUpgradeError = new Error('logging config consequent upgrade failed'); + mockLoggingService.upgrade.mockImplementation(() => { + throw loggingUpgradeError; }); + mockLoggingConfig$.next({ someValue: 'bar' }); + + // Wait for shutdown to be called. + await onShutdown + .pipe( + filter(e => e !== null), + first() + ) + .toPromise(); + + expect(mockOnShutdown).toHaveBeenCalledTimes(1); + expect(mockOnShutdown).toHaveBeenCalledWith(loggingUpgradeError); + expect(mockLoggingService.stop).toHaveBeenCalledTimes(1); + expect(mockServer.stop).toHaveBeenCalledTimes(1); + + expect(mockConsoleError.mock.calls).toMatchSnapshot(); }); diff --git a/src/core/server/root/index.ts b/src/core/server/root/index.ts index 34e01abcfbfc11..25cba09681ac88 100644 --- a/src/core/server/root/index.ts +++ b/src/core/server/root/index.ts @@ -17,15 +17,13 @@ * under the License. */ -import { Observable } from 'rxjs'; +import { Observable, Subscription } from 'rxjs'; +import { catchError, first, map, shareReplay } from 'rxjs/operators'; import { Server } from '..'; import { ConfigService, Env, RawConfig } from '../config'; -import { Logger } from '../logging'; -import { LoggerFactory, MutableLoggerFactory } from '../logging/logger_factory'; -import { LoggingConfig } from '../logging/logging_config'; -import { LoggingService } from '../logging/logging_service'; +import { Logger, LoggerFactory, LoggingConfig, LoggingService } from '../logging'; export type OnShutdown = (reason?: Error) => void; @@ -33,11 +31,12 @@ export type OnShutdown = (reason?: Error) => void; * Top-level entry point to kick off the app and start the Kibana server. */ export class Root { - public configService: ConfigService; - public readonly log: Logger; public readonly logger: LoggerFactory; + protected readonly configService: ConfigService; + private readonly log: Logger; private server?: Server; private readonly loggingService: LoggingService; + private loggingConfigSubscription?: Subscription; constructor( rawConfig$: Observable, @@ -46,41 +45,35 @@ export class Root { // noop } ) { - const loggerFactory = new MutableLoggerFactory(); - this.loggingService = new LoggingService(loggerFactory); - this.logger = loggerFactory; + this.loggingService = new LoggingService(); + this.logger = this.loggingService.asLoggerFactory(); this.log = this.logger.get('root'); this.configService = new ConfigService(rawConfig$, env, this.logger); } public async start() { - try { - const loggingConfig$ = this.configService.atPath('logging', LoggingConfig); - this.loggingService.upgrade(loggingConfig$); - } catch (e) { - // This specifically console.logs because we were not able to configure - // the logger. - // tslint:disable no-console - console.error('Configuring logger failed:', e.message); - - await this.shutdown(e); - throw e; - } + this.log.debug('starting root'); try { + await this.setupLogging(); await this.startServer(); } catch (e) { - this.log.error(e); - await this.shutdown(e); throw e; } } public async shutdown(reason?: Error) { + this.log.debug('shutting root down'); + await this.stopServer(); + if (this.loggingConfigSubscription !== undefined) { + this.loggingConfigSubscription.unsubscribe(); + this.loggingConfigSubscription = undefined; + } + await this.loggingService.stop(); this.onShutdown(reason); @@ -99,4 +92,27 @@ export class Root { await this.server.stop(); this.server = undefined; } + + private async setupLogging() { + // Stream that maps config updates to logger updates, including update failures. + const update$ = this.configService.atPath('logging', LoggingConfig).pipe( + map(config => this.loggingService.upgrade(config)), + catchError(err => { + // This specifically console.logs because we were not able to configure the logger. + // tslint:disable-next-line no-console + console.error('Configuring logger failed:', err); + + throw err; + }), + shareReplay(1) + ); + + // Wait for the first update to complete and throw if it fails. + await update$.pipe(first()).toPromise(); + + // Send subsequent update failures to this.shutdown(), stopped via loggingConfigSubscription. + this.loggingConfigSubscription = update$.subscribe({ + error: error => this.shutdown(error), + }); + } }