From 238570b3d29d19cbda8e3ba9263f34d4a5679ff4 Mon Sep 17 00:00:00 2001 From: Ruben Verborgh Date: Wed, 30 Mar 2022 14:08:09 +0200 Subject: [PATCH] feat: Make LazyLoggerFactory buffer messages. --- src/index.ts | 1 - src/logging/LazyLogger.ts | 29 ----- src/logging/LazyLoggerFactory.ts | 122 +++++++++++++++----- src/logging/LogUtil.ts | 48 +++++--- src/logging/Logger.ts | 20 +++- test/unit/logging/LazyLogger.test.ts | 53 --------- test/unit/logging/LazyLoggerFactory.test.ts | 112 +++++++++++------- test/unit/logging/LogUtil.test.ts | 47 ++++---- 8 files changed, 240 insertions(+), 192 deletions(-) delete mode 100644 src/logging/LazyLogger.ts delete mode 100644 test/unit/logging/LazyLogger.test.ts diff --git a/src/index.ts b/src/index.ts index b2470a6fa..e175a0b60 100644 --- a/src/index.ts +++ b/src/index.ts @@ -215,7 +215,6 @@ export * from './init/ServerInitializer'; export * from './init/ModuleVersionVerifier'; // Logging -export * from './logging/LazyLogger'; export * from './logging/LazyLoggerFactory'; export * from './logging/Logger'; export * from './logging/LoggerFactory'; diff --git a/src/logging/LazyLogger.ts b/src/logging/LazyLogger.ts deleted file mode 100644 index 3299c3535..000000000 --- a/src/logging/LazyLogger.ts +++ /dev/null @@ -1,29 +0,0 @@ -import type { LazyLoggerFactory } from './LazyLoggerFactory'; -import { Logger } from './Logger'; -import type { LogLevel } from './LogLevel'; - -/** - * Creates a logger lazily using a reference to {@link LazyLoggerFactory}. - * - * An error will be thrown if {@link LazyLogger.log} is invoked - * before a {@link LoggerFactory} is set in {@link LazyLoggerFactory}. - */ -export class LazyLogger extends Logger { - private readonly lazyLoggerFactory: LazyLoggerFactory; - private readonly label: string; - - private logger: Logger | undefined; - - public constructor(lazyLoggerFactory: LazyLoggerFactory, label: string) { - super(); - this.lazyLoggerFactory = lazyLoggerFactory; - this.label = label; - } - - public log(level: LogLevel, message: string): Logger { - if (!this.logger) { - this.logger = this.lazyLoggerFactory.loggerFactory.createLogger(this.label); - } - return this.logger.log(level, message); - } -} diff --git a/src/logging/LazyLoggerFactory.ts b/src/logging/LazyLoggerFactory.ts index eed0dda8c..1469ba55a 100644 --- a/src/logging/LazyLoggerFactory.ts +++ b/src/logging/LazyLoggerFactory.ts @@ -1,45 +1,109 @@ -import { LazyLogger } from './LazyLogger'; -import type { Logger } from './Logger'; +import { Logger } from './Logger'; +import type { BasicLogger } from './Logger'; import type { LoggerFactory } from './LoggerFactory'; +import type { LogLevel } from './LogLevel'; /** - * Wraps over another {@link LoggerFactory} that can be set lazily. - * This is a singleton class, for which the instance can be retrieved using {@link LazyLoggerFactory.getInstance}. + * Wraps around another {@link Logger} that can be set lazily. + */ +class WrappingLogger extends Logger { + public logger: BasicLogger; + + public constructor(logger: BasicLogger) { + super(); + this.logger = logger; + } + + public log(level: LogLevel, message: string): Logger { + this.logger.log(level, message); + return this; + } +} + +/** + * Temporary {@link LoggerFactory} that creates buffered {@link WrappingLogger}s + * until the {@link TemporaryLoggerFactory#switch} method is called. + */ +class TemporaryLoggerFactory implements LoggerFactory { + private bufferSpaces: number; + private readonly wrappers: { wrapper: WrappingLogger; label: string }[] = []; + private readonly buffer: { logger: Logger; level: LogLevel; message: string }[] = []; + + public constructor(bufferSize = 1024) { + this.bufferSpaces = bufferSize; + } + + public createLogger(label: string): WrappingLogger { + const wrapper = new WrappingLogger({ + log: (level: LogLevel, message: string): Logger => + this.bufferLogEntry(wrapper, level, message), + }); + this.wrappers.push({ wrapper, label }); + return wrapper; + } + + private bufferLogEntry(logger: WrappingLogger, level: LogLevel, message: string): Logger { + // Buffer the message if spaces are still available + if (this.bufferSpaces > 0) { + this.bufferSpaces -= 1; + // If this is the last space, instead generate a warning through a new logger + if (this.bufferSpaces === 0) { + logger = this.createLogger('LazyLoggerFactory'); + level = 'warn'; + message = `Memory-buffered logging limit of ${this.buffer.length + 1} reached`; + } + this.buffer.push({ logger, level, message }); + } + return logger; + } + + /** + * Swaps all lazy loggers to new loggers from the given factory, + * and emits any buffered messages through those actual loggers. + */ + public switch(loggerFactory: LoggerFactory): void { + // Instantiate an actual logger within every lazy logger + for (const { wrapper, label } of this.wrappers.splice(0, this.wrappers.length)) { + wrapper.logger = loggerFactory.createLogger(label); + } + // Emit all buffered log messages + for (const { logger, level, message } of this.buffer.splice(0, this.buffer.length)) { + logger.log(level, message); + } + } +} + +/** + * Wraps around another {@link LoggerFactory} that can be set lazily. + * This is useful when objects are instantiated (and when they create loggers) + * before the logging system has been fully instantiated, + * as is the case when using a dependency injection framework such as Components.js. * - * Loggers can safely be created before a {@link LoggerFactory} is set. - * But an error will be thrown if {@link Logger.log} is invoked before a {@link LoggerFactory} is set. - * - * This creates instances of {@link LazyLogger}. + * Loggers can be created even before a {@link LoggerFactory} is set; + * any log messages will be buffered and re-emitted. */ export class LazyLoggerFactory implements LoggerFactory { - private static readonly instance = new LazyLoggerFactory(); + private factory: LoggerFactory; - private ploggerFactory: LoggerFactory | undefined; - - private constructor() { - // Singleton instance - } - - public static getInstance(): LazyLoggerFactory { - return LazyLoggerFactory.instance; - } - - public createLogger(label: string): Logger { - return new LazyLogger(this, label); - } - - public resetLoggerFactory(): void { - this.ploggerFactory = undefined; + public constructor(options: { bufferSize?: number } = {}) { + this.factory = new TemporaryLoggerFactory(options.bufferSize); } public get loggerFactory(): LoggerFactory { - if (!this.ploggerFactory) { - throw new Error('No logger factory has been set. Can be caused by logger invocation during initialization.'); + if (this.factory instanceof TemporaryLoggerFactory) { + throw new Error('Logger factory not yet set.'); } - return this.ploggerFactory; + return this.factory; } public set loggerFactory(loggerFactory: LoggerFactory) { - this.ploggerFactory = loggerFactory; + if (this.factory instanceof TemporaryLoggerFactory) { + this.factory.switch(loggerFactory); + } + this.factory = loggerFactory; + } + + public createLogger(label: string): Logger { + return this.factory.createLogger(label); } } diff --git a/src/logging/LogUtil.ts b/src/logging/LogUtil.ts index f285230c8..04628a073 100644 --- a/src/logging/LogUtil.ts +++ b/src/logging/LogUtil.ts @@ -2,11 +2,12 @@ import { LazyLoggerFactory } from './LazyLoggerFactory'; import type { Logger } from './Logger'; import type { LoggerFactory } from './LoggerFactory'; +let loggerFactoryWrapper = new LazyLoggerFactory(); +let classLoggers = new WeakMap(); + /** * Gets a logger instance for the given class instance. * - * The returned type of logger depends on the configured {@link LoggerFactory} in {@link Setup}. - * * The following shows a typical pattern on how to create loggers: * ``` * class MyClass { @@ -21,32 +22,51 @@ import type { LoggerFactory } from './LoggerFactory'; * @param loggable - A class instance or a class string name. */ export function getLoggerFor(loggable: string | Instance): Logger { - return LazyLoggerFactory.getInstance() - .createLogger(typeof loggable === 'string' ? loggable : loggable.constructor.name); + let logger: Logger; + // Create a logger with a text label + if (typeof loggable === 'string') { + logger = loggerFactoryWrapper.createLogger(loggable); + // Create or reuse a logger for a specific class + } else { + const { constructor } = loggable; + if (classLoggers.has(constructor)) { + logger = classLoggers.get(constructor)!; + } else { + logger = loggerFactoryWrapper.createLogger(constructor.name); + classLoggers.set(constructor, logger); + } + } + return logger; } /** * Sets the global logger factory. - * This will cause all loggers created by {@link getLoggerFor} to be delegated to a logger from the given factory. + * This causes loggers created by {@link getLoggerFor} to delegate to a logger from the given factory. * @param loggerFactory - A logger factory. */ export function setGlobalLoggerFactory(loggerFactory: LoggerFactory): void { - LazyLoggerFactory.getInstance().loggerFactory = loggerFactory; + loggerFactoryWrapper.loggerFactory = loggerFactory; } /** - * Resets the global logger factory to undefined. - * - * This typically only needs to be called during testing. - * Call this at your own risk. + * Resets the internal logger factory, which holds the global logger factory. + * For testing purposes only. */ -export function resetGlobalLoggerFactory(): void { - LazyLoggerFactory.getInstance().resetLoggerFactory(); +export function resetInternalLoggerFactory(factory = new LazyLoggerFactory()): void { + loggerFactoryWrapper = factory; + classLoggers = new WeakMap(); } /** - * Helper interface to identify class instances. + * Any class constructor. + */ +interface Constructor { + name: string; +} + +/** + * Any class instance. */ interface Instance { - constructor: { name: string }; + constructor: Constructor; } diff --git a/src/logging/Logger.ts b/src/logging/Logger.ts index b2f727c80..c31888c35 100644 --- a/src/logging/Logger.ts +++ b/src/logging/Logger.ts @@ -1,11 +1,27 @@ import type { LogLevel } from './LogLevel'; /** - * Logs messages on a certain level. + * Logs messages on a specific level. * * @see getLoggerFor on how to instantiate loggers. */ -export abstract class Logger { +export type BasicLogger = { + /** + * Log the given message at the given level. + * If the internal level is higher than the given level, the message may be voided. + * @param level - The level to log at. + * @param message - The message to log. + * @param meta - Optional metadata to include in the log message. + */ + log: (level: LogLevel, message: string) => BasicLogger; +}; + +/** + * Logs messages, with convenience methods to log on a specific level. + * + * @see getLoggerFor on how to instantiate loggers. + */ +export abstract class Logger implements BasicLogger { /** * Log the given message at the given level. * If the internal level is higher than the given level, the message may be voided. diff --git a/test/unit/logging/LazyLogger.test.ts b/test/unit/logging/LazyLogger.test.ts deleted file mode 100644 index a077275fc..000000000 --- a/test/unit/logging/LazyLogger.test.ts +++ /dev/null @@ -1,53 +0,0 @@ -import { LazyLogger } from '../../../src/logging/LazyLogger'; -import { LazyLoggerFactory } from '../../../src/logging/LazyLoggerFactory'; - -describe('LazyLogger', (): void => { - let lazyLoggerFactory: LazyLoggerFactory; - let logger: LazyLogger; - beforeEach(async(): Promise => { - lazyLoggerFactory = LazyLoggerFactory.getInstance(); - lazyLoggerFactory.resetLoggerFactory(); - logger = new LazyLogger(lazyLoggerFactory, 'MyLabel'); - }); - - it('throws when no logger factory is set in the lazy logger factory.', async(): Promise => { - expect((): any => logger.log('debug', 'my message', { abc: true })) - .toThrow('No logger factory has been set. Can be caused by logger invocation during initialization.'); - }); - - it('creates a new logger using the factory.', async(): Promise => { - const dummyLogger: any = { - log: jest.fn((): any => dummyLogger), - }; - const dummyLoggerFactory: any = { - createLogger: jest.fn((): any => dummyLogger), - }; - lazyLoggerFactory.loggerFactory = dummyLoggerFactory; - - expect(logger.log('debug', 'my message')).toBe(dummyLogger); - expect(dummyLoggerFactory.createLogger).toHaveBeenCalledTimes(1); - expect(dummyLoggerFactory.createLogger).toHaveBeenCalledWith('MyLabel'); - expect(dummyLogger.log).toHaveBeenCalledTimes(1); - expect(dummyLogger.log).toHaveBeenCalledWith('debug', 'my message'); - }); - - it('reuses the logger for repeated calls.', async(): Promise => { - const dummyLogger: any = { - log: jest.fn((): any => dummyLogger), - }; - const dummyLoggerFactory: any = { - createLogger: jest.fn((): any => dummyLogger), - }; - lazyLoggerFactory.loggerFactory = dummyLoggerFactory; - - expect(logger.log('debug', 'my message 1')).toBe(dummyLogger); - expect(logger.log('debug', 'my message 2')).toBe(dummyLogger); - expect(logger.log('debug', 'my message 3')).toBe(dummyLogger); - expect(dummyLoggerFactory.createLogger).toHaveBeenCalledTimes(1); - expect(dummyLoggerFactory.createLogger).toHaveBeenCalledWith('MyLabel'); - expect(dummyLogger.log).toHaveBeenCalledTimes(3); - expect(dummyLogger.log).toHaveBeenNthCalledWith(1, 'debug', 'my message 1'); - expect(dummyLogger.log).toHaveBeenNthCalledWith(2, 'debug', 'my message 2'); - expect(dummyLogger.log).toHaveBeenNthCalledWith(3, 'debug', 'my message 3'); - }); -}); diff --git a/test/unit/logging/LazyLoggerFactory.test.ts b/test/unit/logging/LazyLoggerFactory.test.ts index 9a03265c7..239dd80ab 100644 --- a/test/unit/logging/LazyLoggerFactory.test.ts +++ b/test/unit/logging/LazyLoggerFactory.test.ts @@ -1,65 +1,89 @@ -import { LazyLogger } from '../../../src/logging/LazyLogger'; import { LazyLoggerFactory } from '../../../src/logging/LazyLoggerFactory'; +import type { Logger } from '../../../src/logging/Logger'; +import type { LoggerFactory } from '../../../src/logging/LoggerFactory'; describe('LazyLoggerFactory', (): void => { - let dummyLogger: any; - let dummyLoggerFactory: any; + let lazyLoggerFactory: LazyLoggerFactory; + let dummyLoggerFactory: jest.Mocked; + beforeEach(async(): Promise => { - LazyLoggerFactory.getInstance().resetLoggerFactory(); - dummyLogger = { - log: jest.fn((): any => dummyLogger), - }; + lazyLoggerFactory = new LazyLoggerFactory(); dummyLoggerFactory = { - createLogger: jest.fn((): any => dummyLogger), - }; + createLogger: jest.fn((): jest.Mocked => ({ + log: jest.fn((): any => null), + }) as any), + } as any; }); - it('is a singleton.', async(): Promise => { - expect(LazyLoggerFactory.getInstance()).toBeInstanceOf(LazyLoggerFactory); + it('does not allow reading the internal factory before it is set.', (): void => { + expect((): void => { + expect(lazyLoggerFactory.loggerFactory).toBeNull(); + }).toThrow('Logger factory not yet set.'); }); - it('allows LazyLoggers to be created before an inner factory was set.', async(): Promise => { - const logger = LazyLoggerFactory.getInstance().createLogger('MyLabel'); - expect(logger).toBeInstanceOf(LazyLogger); + it('allows setting the internal factory.', (): void => { + lazyLoggerFactory.loggerFactory = dummyLoggerFactory; + expect(lazyLoggerFactory.loggerFactory).toBe(dummyLoggerFactory); }); - it('allows LazyLoggers to be created after an inner factory was set.', async(): Promise => { - LazyLoggerFactory.getInstance().loggerFactory = dummyLoggerFactory; - const logger = LazyLoggerFactory.getInstance().createLogger('MyLabel'); - expect(logger).toBeInstanceOf(LazyLogger); + it('creates loggers with the right labels.', (): void => { + lazyLoggerFactory.createLogger('LoggerA'); + lazyLoggerFactory.createLogger('LoggerB'); + + lazyLoggerFactory.loggerFactory = dummyLoggerFactory; + + expect(dummyLoggerFactory.createLogger).toHaveBeenCalledTimes(2); + expect(dummyLoggerFactory.createLogger).toHaveBeenNthCalledWith(1, 'LoggerA'); + expect(dummyLoggerFactory.createLogger).toHaveBeenNthCalledWith(2, 'LoggerB'); + + lazyLoggerFactory.createLogger('LoggerC'); + expect(dummyLoggerFactory.createLogger).toHaveBeenCalledTimes(3); + expect(dummyLoggerFactory.createLogger).toHaveBeenNthCalledWith(3, 'LoggerC'); }); - it('throws when retrieving the inner factory if none has been set.', async(): Promise => { - expect((): any => LazyLoggerFactory.getInstance().loggerFactory) - .toThrow('No logger factory has been set. Can be caused by logger invocation during initialization.'); + it('emits logged messages after a logger is set.', (): void => { + const loggerA = lazyLoggerFactory.createLogger('LoggerA'); + const loggerB = lazyLoggerFactory.createLogger('LoggerB'); + loggerA.warn('message1'); + loggerB.warn('message2'); + loggerB.error('message3'); + loggerA.error('message4'); + + lazyLoggerFactory.loggerFactory = dummyLoggerFactory; + + const wrappedA = dummyLoggerFactory.createLogger.mock.results[0].value as jest.Mocked; + expect(wrappedA.log).toHaveBeenCalledTimes(2); + expect(wrappedA.log).toHaveBeenNthCalledWith(1, 'warn', 'message1'); + expect(wrappedA.log).toHaveBeenNthCalledWith(2, 'error', 'message4'); + + const wrappedB = dummyLoggerFactory.createLogger.mock.results[1].value as jest.Mocked; + expect(wrappedB.log).toHaveBeenCalledTimes(2); + expect(wrappedB.log).toHaveBeenNthCalledWith(1, 'warn', 'message2'); + expect(wrappedB.log).toHaveBeenNthCalledWith(2, 'error', 'message3'); }); - it('Returns the inner factory if one has been set.', async(): Promise => { - LazyLoggerFactory.getInstance().loggerFactory = dummyLoggerFactory; - expect(LazyLoggerFactory.getInstance().loggerFactory).toBe(dummyLoggerFactory); - }); + it('does not store more messages than the buffer limit.', (): void => { + lazyLoggerFactory = new LazyLoggerFactory({ bufferSize: 100 }); + const loggerA = lazyLoggerFactory.createLogger('LoggerA'); + const loggerB = lazyLoggerFactory.createLogger('LoggerB'); - it('allows LazyLoggers to be invoked if a factory has been set beforehand.', async(): Promise => { - LazyLoggerFactory.getInstance().loggerFactory = dummyLoggerFactory; - const logger = LazyLoggerFactory.getInstance().createLogger('MyLabel'); - logger.log('debug', 'my message', { abc: true }); + for (let i = 0; i < 50; i++) { + loggerA.info('info'); + } + for (let i = 0; i < 50; i++) { + loggerB.info('info'); + } - expect(dummyLogger.log).toHaveBeenCalledTimes(1); - expect(dummyLogger.log).toHaveBeenCalledWith('debug', 'my message', { abc: true }); - }); + lazyLoggerFactory.loggerFactory = dummyLoggerFactory; - it('allows LazyLoggers to be invoked if a factory has been after lazy logger creation.', async(): Promise => { - const logger = LazyLoggerFactory.getInstance().createLogger('MyLabel'); - LazyLoggerFactory.getInstance().loggerFactory = dummyLoggerFactory; - logger.log('debug', 'my message', { abc: true }); + expect(dummyLoggerFactory.createLogger).toHaveBeenCalledTimes(3); + const wrappedA = dummyLoggerFactory.createLogger.mock.results[0].value as jest.Mocked; + const wrappedB = dummyLoggerFactory.createLogger.mock.results[1].value as jest.Mocked; + const warningLogger = dummyLoggerFactory.createLogger.mock.results[2].value as jest.Mocked; - expect(dummyLogger.log).toHaveBeenCalledTimes(1); - expect(dummyLogger.log).toHaveBeenCalledWith('debug', 'my message', { abc: true }); - }); - - it('errors on invoking LazyLoggers if a factory has not been set yet.', async(): Promise => { - const logger = LazyLoggerFactory.getInstance().createLogger('MyLabel'); - expect((): any => logger.log('debug', 'my message', { abc: true })) - .toThrow('No logger factory has been set. Can be caused by logger invocation during initialization.'); + expect(wrappedA.log).toHaveBeenCalledTimes(50); + expect(wrappedB.log).toHaveBeenCalledTimes(49); + expect(warningLogger.log).toHaveBeenCalledTimes(1); + expect(warningLogger.log).toHaveBeenCalledWith('warn', 'Memory-buffered logging limit of 100 reached'); }); }); diff --git a/test/unit/logging/LogUtil.test.ts b/test/unit/logging/LogUtil.test.ts index 2de366c0c..a8e960d6e 100644 --- a/test/unit/logging/LogUtil.test.ts +++ b/test/unit/logging/LogUtil.test.ts @@ -1,33 +1,40 @@ -import { LazyLogger } from '../../../src/logging/LazyLogger'; -import { LazyLoggerFactory } from '../../../src/logging/LazyLoggerFactory'; -import { getLoggerFor, resetGlobalLoggerFactory, setGlobalLoggerFactory } from '../../../src/logging/LogUtil'; -import { VoidLogger } from '../../../src/logging/VoidLogger'; -import { VoidLoggerFactory } from '../../../src/logging/VoidLoggerFactory'; +import { resetInternalLoggerFactory, getLoggerFor, setGlobalLoggerFactory } from '../../../src/logging/LogUtil'; + +let currentFactory: any; + +class Dummy { + private readonly label = 'dummy'; +} describe('LogUtil', (): void => { - beforeEach(async(): Promise => { - resetGlobalLoggerFactory(); + beforeAll((): void => { + resetInternalLoggerFactory(); + resetInternalLoggerFactory({ + get loggerFactory(): any { + return currentFactory; + }, + set loggerFactory(value: any) { + currentFactory = value; + }, + createLogger: jest.fn((label: string): any => ({ label })), + } as any); }); it('allows creating a lazy logger for a string label.', async(): Promise => { - expect(getLoggerFor('MyLabel')).toBeInstanceOf(LazyLogger); - expect((getLoggerFor('MyLabel') as any).label).toBe('MyLabel'); + expect(getLoggerFor('MyLabel')).toEqual({ label: 'MyLabel' }); }); it('allows creating a lazy logger for a class instance.', async(): Promise => { - expect(getLoggerFor(new VoidLogger())).toBeInstanceOf(LazyLogger); - expect((getLoggerFor(new VoidLogger()) as any).label).toBe('VoidLogger'); + expect(getLoggerFor(new Dummy())).toEqual({ label: 'Dummy' }); + }); + + it('reuses loggers for instances of the same class.', async(): Promise => { + expect(getLoggerFor(new Dummy())).toBe(getLoggerFor(new Dummy())); }); it('allows setting the global logger factory.', async(): Promise => { - setGlobalLoggerFactory(new VoidLoggerFactory()); - expect(LazyLoggerFactory.getInstance().loggerFactory).toBeInstanceOf(VoidLoggerFactory); - }); - - it('allows unsetting the global logger factory.', async(): Promise => { - setGlobalLoggerFactory(new VoidLoggerFactory()); - resetGlobalLoggerFactory(); - expect((): any => LazyLoggerFactory.getInstance().loggerFactory) - .toThrow('No logger factory has been set. Can be caused by logger invocation during initialization.'); + const factory = {} as any; + setGlobalLoggerFactory(factory); + expect(currentFactory).toBe(factory); }); });