feat: Make LazyLoggerFactory buffer messages.

This commit is contained in:
Ruben Verborgh 2022-03-30 14:08:09 +02:00 committed by Joachim Van Herwegen
parent 2c6167e0cb
commit 238570b3d2
8 changed files with 240 additions and 192 deletions

View File

@ -215,7 +215,6 @@ export * from './init/ServerInitializer';
export * from './init/ModuleVersionVerifier'; export * from './init/ModuleVersionVerifier';
// Logging // Logging
export * from './logging/LazyLogger';
export * from './logging/LazyLoggerFactory'; export * from './logging/LazyLoggerFactory';
export * from './logging/Logger'; export * from './logging/Logger';
export * from './logging/LoggerFactory'; export * from './logging/LoggerFactory';

View File

@ -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);
}
}

View File

@ -1,45 +1,109 @@
import { LazyLogger } from './LazyLogger'; import { Logger } from './Logger';
import type { Logger } from './Logger'; import type { BasicLogger } from './Logger';
import type { LoggerFactory } from './LoggerFactory'; import type { LoggerFactory } from './LoggerFactory';
import type { LogLevel } from './LogLevel';
/** /**
* Wraps over another {@link LoggerFactory} that can be set lazily. * Wraps around another {@link Logger} that can be set lazily.
* This is a singleton class, for which the instance can be retrieved using {@link LazyLoggerFactory.getInstance}. */
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. * Loggers can be created even before a {@link LoggerFactory} is set;
* But an error will be thrown if {@link Logger.log} is invoked before a {@link LoggerFactory} is set. * any log messages will be buffered and re-emitted.
*
* This creates instances of {@link LazyLogger}.
*/ */
export class LazyLoggerFactory implements LoggerFactory { export class LazyLoggerFactory implements LoggerFactory {
private static readonly instance = new LazyLoggerFactory(); private factory: LoggerFactory;
private ploggerFactory: LoggerFactory | undefined; public constructor(options: { bufferSize?: number } = {}) {
this.factory = new TemporaryLoggerFactory(options.bufferSize);
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 get loggerFactory(): LoggerFactory { public get loggerFactory(): LoggerFactory {
if (!this.ploggerFactory) { if (this.factory instanceof TemporaryLoggerFactory) {
throw new Error('No logger factory has been set. Can be caused by logger invocation during initialization.'); throw new Error('Logger factory not yet set.');
} }
return this.ploggerFactory; return this.factory;
} }
public set loggerFactory(loggerFactory: LoggerFactory) { 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);
} }
} }

View File

@ -2,11 +2,12 @@ import { LazyLoggerFactory } from './LazyLoggerFactory';
import type { Logger } from './Logger'; import type { Logger } from './Logger';
import type { LoggerFactory } from './LoggerFactory'; import type { LoggerFactory } from './LoggerFactory';
let loggerFactoryWrapper = new LazyLoggerFactory();
let classLoggers = new WeakMap<Constructor, Logger>();
/** /**
* Gets a logger instance for the given class instance. * 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: * The following shows a typical pattern on how to create loggers:
* ``` * ```
* class MyClass { * class MyClass {
@ -21,32 +22,51 @@ import type { LoggerFactory } from './LoggerFactory';
* @param loggable - A class instance or a class string name. * @param loggable - A class instance or a class string name.
*/ */
export function getLoggerFor(loggable: string | Instance): Logger { export function getLoggerFor(loggable: string | Instance): Logger {
return LazyLoggerFactory.getInstance() let logger: Logger;
.createLogger(typeof loggable === 'string' ? loggable : loggable.constructor.name); // 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. * 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. * @param loggerFactory - A logger factory.
*/ */
export function setGlobalLoggerFactory(loggerFactory: LoggerFactory): void { export function setGlobalLoggerFactory(loggerFactory: LoggerFactory): void {
LazyLoggerFactory.getInstance().loggerFactory = loggerFactory; loggerFactoryWrapper.loggerFactory = loggerFactory;
} }
/** /**
* Resets the global logger factory to undefined. * Resets the internal logger factory, which holds the global logger factory.
* * For testing purposes only.
* This typically only needs to be called during testing.
* Call this at your own risk.
*/ */
export function resetGlobalLoggerFactory(): void { export function resetInternalLoggerFactory(factory = new LazyLoggerFactory()): void {
LazyLoggerFactory.getInstance().resetLoggerFactory(); loggerFactoryWrapper = factory;
classLoggers = new WeakMap();
} }
/** /**
* Helper interface to identify class instances. * Any class constructor.
*/
interface Constructor {
name: string;
}
/**
* Any class instance.
*/ */
interface Instance { interface Instance {
constructor: { name: string }; constructor: Constructor;
} }

View File

@ -1,11 +1,27 @@
import type { LogLevel } from './LogLevel'; import type { LogLevel } from './LogLevel';
/** /**
* Logs messages on a certain level. * Logs messages on a specific level.
* *
* @see getLoggerFor on how to instantiate loggers. * @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. * Log the given message at the given level.
* If the internal level is higher than the given level, the message may be voided. * If the internal level is higher than the given level, the message may be voided.

View File

@ -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<void> => {
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<void> => {
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<void> => {
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<void> => {
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');
});
});

View File

@ -1,65 +1,89 @@
import { LazyLogger } from '../../../src/logging/LazyLogger';
import { LazyLoggerFactory } from '../../../src/logging/LazyLoggerFactory'; import { LazyLoggerFactory } from '../../../src/logging/LazyLoggerFactory';
import type { Logger } from '../../../src/logging/Logger';
import type { LoggerFactory } from '../../../src/logging/LoggerFactory';
describe('LazyLoggerFactory', (): void => { describe('LazyLoggerFactory', (): void => {
let dummyLogger: any; let lazyLoggerFactory: LazyLoggerFactory;
let dummyLoggerFactory: any; let dummyLoggerFactory: jest.Mocked<LoggerFactory>;
beforeEach(async(): Promise<void> => { beforeEach(async(): Promise<void> => {
LazyLoggerFactory.getInstance().resetLoggerFactory(); lazyLoggerFactory = new LazyLoggerFactory();
dummyLogger = {
log: jest.fn((): any => dummyLogger),
};
dummyLoggerFactory = { dummyLoggerFactory = {
createLogger: jest.fn((): any => dummyLogger), createLogger: jest.fn((): jest.Mocked<Logger> => ({
}; log: jest.fn((): any => null),
}) as any),
} as any;
}); });
it('is a singleton.', async(): Promise<void> => { it('does not allow reading the internal factory before it is set.', (): void => {
expect(LazyLoggerFactory.getInstance()).toBeInstanceOf(LazyLoggerFactory); 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<void> => { it('allows setting the internal factory.', (): void => {
const logger = LazyLoggerFactory.getInstance().createLogger('MyLabel'); lazyLoggerFactory.loggerFactory = dummyLoggerFactory;
expect(logger).toBeInstanceOf(LazyLogger); expect(lazyLoggerFactory.loggerFactory).toBe(dummyLoggerFactory);
}); });
it('allows LazyLoggers to be created after an inner factory was set.', async(): Promise<void> => { it('creates loggers with the right labels.', (): void => {
LazyLoggerFactory.getInstance().loggerFactory = dummyLoggerFactory; lazyLoggerFactory.createLogger('LoggerA');
const logger = LazyLoggerFactory.getInstance().createLogger('MyLabel'); lazyLoggerFactory.createLogger('LoggerB');
expect(logger).toBeInstanceOf(LazyLogger);
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<void> => { it('emits logged messages after a logger is set.', (): void => {
expect((): any => LazyLoggerFactory.getInstance().loggerFactory) const loggerA = lazyLoggerFactory.createLogger('LoggerA');
.toThrow('No logger factory has been set. Can be caused by logger invocation during initialization.'); 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<Logger>;
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<Logger>;
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<void> => { it('does not store more messages than the buffer limit.', (): void => {
LazyLoggerFactory.getInstance().loggerFactory = dummyLoggerFactory; lazyLoggerFactory = new LazyLoggerFactory({ bufferSize: 100 });
expect(LazyLoggerFactory.getInstance().loggerFactory).toBe(dummyLoggerFactory); 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<void> => { for (let i = 0; i < 50; i++) {
LazyLoggerFactory.getInstance().loggerFactory = dummyLoggerFactory; loggerA.info('info');
const logger = LazyLoggerFactory.getInstance().createLogger('MyLabel'); }
logger.log('debug', 'my message', { abc: true }); for (let i = 0; i < 50; i++) {
loggerB.info('info');
}
expect(dummyLogger.log).toHaveBeenCalledTimes(1); lazyLoggerFactory.loggerFactory = dummyLoggerFactory;
expect(dummyLogger.log).toHaveBeenCalledWith('debug', 'my message', { abc: true });
});
it('allows LazyLoggers to be invoked if a factory has been after lazy logger creation.', async(): Promise<void> => { expect(dummyLoggerFactory.createLogger).toHaveBeenCalledTimes(3);
const logger = LazyLoggerFactory.getInstance().createLogger('MyLabel'); const wrappedA = dummyLoggerFactory.createLogger.mock.results[0].value as jest.Mocked<Logger>;
LazyLoggerFactory.getInstance().loggerFactory = dummyLoggerFactory; const wrappedB = dummyLoggerFactory.createLogger.mock.results[1].value as jest.Mocked<Logger>;
logger.log('debug', 'my message', { abc: true }); const warningLogger = dummyLoggerFactory.createLogger.mock.results[2].value as jest.Mocked<Logger>;
expect(dummyLogger.log).toHaveBeenCalledTimes(1); expect(wrappedA.log).toHaveBeenCalledTimes(50);
expect(dummyLogger.log).toHaveBeenCalledWith('debug', 'my message', { abc: true }); expect(wrappedB.log).toHaveBeenCalledTimes(49);
}); expect(warningLogger.log).toHaveBeenCalledTimes(1);
expect(warningLogger.log).toHaveBeenCalledWith('warn', 'Memory-buffered logging limit of 100 reached');
it('errors on invoking LazyLoggers if a factory has not been set yet.', async(): Promise<void> => {
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.');
}); });
}); });

View File

@ -1,33 +1,40 @@
import { LazyLogger } from '../../../src/logging/LazyLogger'; import { resetInternalLoggerFactory, getLoggerFor, setGlobalLoggerFactory } from '../../../src/logging/LogUtil';
import { LazyLoggerFactory } from '../../../src/logging/LazyLoggerFactory';
import { getLoggerFor, resetGlobalLoggerFactory, setGlobalLoggerFactory } from '../../../src/logging/LogUtil'; let currentFactory: any;
import { VoidLogger } from '../../../src/logging/VoidLogger';
import { VoidLoggerFactory } from '../../../src/logging/VoidLoggerFactory'; class Dummy {
private readonly label = 'dummy';
}
describe('LogUtil', (): void => { describe('LogUtil', (): void => {
beforeEach(async(): Promise<void> => { beforeAll((): void => {
resetGlobalLoggerFactory(); 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<void> => { it('allows creating a lazy logger for a string label.', async(): Promise<void> => {
expect(getLoggerFor('MyLabel')).toBeInstanceOf(LazyLogger); expect(getLoggerFor('MyLabel')).toEqual({ label: 'MyLabel' });
expect((getLoggerFor('MyLabel') as any).label).toBe('MyLabel');
}); });
it('allows creating a lazy logger for a class instance.', async(): Promise<void> => { it('allows creating a lazy logger for a class instance.', async(): Promise<void> => {
expect(getLoggerFor(new VoidLogger())).toBeInstanceOf(LazyLogger); expect(getLoggerFor(new Dummy())).toEqual({ label: 'Dummy' });
expect((getLoggerFor(new VoidLogger()) as any).label).toBe('VoidLogger'); });
it('reuses loggers for instances of the same class.', async(): Promise<void> => {
expect(getLoggerFor(new Dummy())).toBe(getLoggerFor(new Dummy()));
}); });
it('allows setting the global logger factory.', async(): Promise<void> => { it('allows setting the global logger factory.', async(): Promise<void> => {
setGlobalLoggerFactory(new VoidLoggerFactory()); const factory = {} as any;
expect(LazyLoggerFactory.getInstance().loggerFactory).toBeInstanceOf(VoidLoggerFactory); setGlobalLoggerFactory(factory);
}); expect(currentFactory).toBe(factory);
it('allows unsetting the global logger factory.', async(): Promise<void> => {
setGlobalLoggerFactory(new VoidLoggerFactory());
resetGlobalLoggerFactory();
expect((): any => LazyLoggerFactory.getInstance().loggerFactory)
.toThrow('No logger factory has been set. Can be caused by logger invocation during initialization.');
}); });
}); });