diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 2f342f6ff7..8324e29196 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -174,23 +174,26 @@ class Logger extends Utility implements LoggerInterface { */ protected isBufferEnabled = false; + /** + * Whether the buffer should be flushed when an error is logged + */ + protected flushOnErrorLog = true; /** * Log level threshold for the buffer * Logs with a level lower than this threshold will be buffered + * Default is DEBUG */ - protected bufferLogThreshold: number = LogLevelThreshold.DEBUG; + protected bufferAtVerbosity: number = LogLevelThreshold.DEBUG; /** * Max size of the buffer. Additions to the buffer beyond this size will * cause older logs to be evicted from the buffer */ - readonly #maxBufferBytesSize = 1024; + #maxBufferBytesSize = 20480; /** * Contains buffered logs, grouped by _X_AMZN_TRACE_ID, each group with a max size of `maxBufferBytesSize` */ - readonly #buffer: CircularMap = new CircularMap({ - maxBytesSize: this.#maxBufferBytesSize, - }); + #buffer?: CircularMap; /** * Log level used by the current instance of Logger. @@ -330,6 +333,9 @@ class Logger extends Utility implements LoggerInterface { * @param extraInput - The extra input to log. */ public error(input: LogItemMessage, ...extraInput: LogItemExtraInput): void { + if (this.isBufferEnabled && this.flushOnErrorLog) { + this.flushBuffer(); + } this.processLogItem(LogLevelThreshold.ERROR, input, extraInput); } @@ -1167,6 +1173,7 @@ class Logger extends Utility implements LoggerInterface { environment, jsonReplacerFn, logRecordOrder, + logBufferOptions, } = options; if (persistentLogAttributes && persistentKeys) { @@ -1193,6 +1200,10 @@ class Logger extends Utility implements LoggerInterface { this.setLogIndentation(); this.#jsonReplacerFn = jsonReplacerFn; + if (logBufferOptions !== undefined) { + this.#setLogBuffering(logBufferOptions); + } + return this; } @@ -1223,6 +1234,35 @@ class Logger extends Utility implements LoggerInterface { persistentKeys && this.appendPersistentKeys(persistentKeys); } + #setLogBuffering( + options: NonNullable + ) { + if (options.maxBytes !== undefined) { + this.#maxBufferBytesSize = options.maxBytes; + } + + this.#buffer = new CircularMap({ + maxBytesSize: this.#maxBufferBytesSize, + }); + + if (options.enabled === false) { + this.isBufferEnabled = false; + } else { + this.isBufferEnabled = true; + } + + if (options.flushOnErrorLog === false) { + this.flushOnErrorLog = false; + } else { + this.flushOnErrorLog = true; + } + const bufferAtLogLevel = options.bufferAtVerbosity?.toUpperCase(); + + if (this.isValidLogLevel(bufferAtLogLevel)) { + this.bufferAtVerbosity = LogLevelThreshold[bufferAtLogLevel]; + } + } + /** * Add a log to the buffer * @param xrayTraceId - _X_AMZN_TRACE_ID of the request @@ -1242,20 +1282,20 @@ class Logger extends Utility implements LoggerInterface { this.logIndentation ); - this.#buffer.setItem(xrayTraceId, stringified, logLevel); + this.#buffer?.setItem(xrayTraceId, stringified, logLevel); } /** * Flushes all items of the respective _X_AMZN_TRACE_ID within * the buffer. */ - protected flushBuffer(): void { + public flushBuffer(): void { const traceId = this.envVarsService.getXrayTraceId(); if (traceId === undefined) { return; } - const buffer = this.#buffer.get(traceId); + const buffer = this.#buffer?.get(traceId); if (buffer === undefined) { return; } @@ -1280,7 +1320,7 @@ class Logger extends Utility implements LoggerInterface { ); } - this.#buffer.delete(traceId); + this.#buffer?.delete(traceId); } /** * Tests if the log meets the criteria to be buffered @@ -1294,7 +1334,7 @@ class Logger extends Utility implements LoggerInterface { return ( this.isBufferEnabled && traceId !== undefined && - logLevel <= this.bufferLogThreshold + logLevel <= this.bufferAtVerbosity ); } } diff --git a/packages/logger/src/types/Logger.ts b/packages/logger/src/types/Logger.ts index 1e453f1ee5..819f35d898 100644 --- a/packages/logger/src/types/Logger.ts +++ b/packages/logger/src/types/Logger.ts @@ -173,12 +173,46 @@ type LogRecordOrderOption = { logFormatter?: never; }; +/** + * Options for the `logBuffer` constructor option. + * + * Used to configure the log buffer functionality. + */ +type LogBufferOption = { + logBufferOptions?: { + /** + * Whether logs should be buffered + */ + enabled?: boolean; + /** + * Maximum size of the buffer in bytes + * @default `20480` + */ + maxBytes?: number; + /** + * Flush the buffer when an error is logged + * @default `true` + */ + flushOnErrorLog?: boolean; + /** + * The threshold to buffer logs. Logs with a level below + * this threshold will be buffered + * @default `'DEBUG'` + */ + bufferAtVerbosity?: Omit< + LogLevel, + 'ERROR' | 'error' | 'CRITICAL' | 'critical' | 'SILENT' | 'silent' + >; + }; +}; + /** * Options to configure the Logger. */ type ConstructorOptions = BaseConstructorOptions & (PersistentKeysOption | DeprecatedPersistentKeysOption) & - (LogFormatterOption | LogRecordOrderOption); + (LogFormatterOption | LogRecordOrderOption) & + LogBufferOption; type LogItemMessage = string | LogAttributesWithMessage; type LogItemExtraInput = [Error | string] | LogAttributes[]; @@ -194,6 +228,7 @@ type LoggerInterface = { critical(input: LogItemMessage, ...extraInput: LogItemExtraInput): void; debug(input: LogItemMessage, ...extraInput: LogItemExtraInput): void; error(input: LogItemMessage, ...extraInput: LogItemExtraInput): void; + flushBuffer(): void; getLevelName(): Uppercase; getLogEvent(): boolean; getPersistentLogAttributes(): LogAttributes; diff --git a/packages/logger/tests/unit/logBuffer.test.ts b/packages/logger/tests/unit/logBuffer.test.ts index 9ba2923bc3..f7e4558c73 100644 --- a/packages/logger/tests/unit/logBuffer.test.ts +++ b/packages/logger/tests/unit/logBuffer.test.ts @@ -1,140 +1,231 @@ import { beforeEach, describe, expect, it, vi } from 'vitest'; import { Logger } from '../../src/Logger.js'; -import { LogLevelThreshold } from '../../src/constants.js'; +import { LogLevel } from '../../src/constants.js'; class TestLogger extends Logger { - public enableBuffering() { - this.isBufferEnabled = true; - } - public disableBuffering() { - this.isBufferEnabled = false; - } - - public flushBufferWrapper(): void { - this.flushBuffer(); - } - public overrideBufferLogItem(): void { this.bufferLogItem = vi.fn().mockImplementation(() => { throw new Error('bufferLogItem error'); }); } - - public setbufferLevelThreshold(level: number): void { - this.bufferLogThreshold = level; - } } +describe('Log Buffer', () => { + describe('Configuration', () => { + const ENVIRONMENT_VARIABLES = process.env; + + beforeEach(() => { + process.env = { + ...ENVIRONMENT_VARIABLES, + POWERTOOLS_LOGGER_LOG_EVENT: 'true', + POWERTOOLS_DEV: 'true', + }; + vi.clearAllMocks(); + }); -describe('bufferLog', () => { - it('outputs a warning when there is an error buffering the log', () => { - // Prepare - process.env.POWERTOOLS_DEV = 'true'; - const logger = new TestLogger(); - logger.enableBuffering(); - logger.overrideBufferLogItem(); - - // Act - logger.debug('This is a debug'); + it('does not buffer logs when disabled', () => { + // Prepare + const logger = new TestLogger({ + logLevel: LogLevel.ERROR, + logBufferOptions: { enabled: false }, + }); + + // Act + logger.debug('This is a log message'); + logger.flushBuffer(); + // Assess + expect(console.debug).toBeCalledTimes(0); + }); - // Assess - expect(console.debug).toBeCalledTimes(1); - expect(console.warn).toBeCalledTimes(1); - }); -}); + it('does not flush on error logs when flushOnErrorLog is disabled ', () => { + // Prepare + const logger = new TestLogger({ + logLevel: LogLevel.ERROR, + logBufferOptions: { enabled: true, flushOnErrorLog: false }, + }); + + // Act + logger.debug('This is a log message'); + logger.error('This is an error message'); + // Assess + expect(console.debug).toBeCalledTimes(0); + expect(console.error).toBeCalledTimes(1); + }); -describe('flushBuffer', () => { - const ENVIRONMENT_VARIABLES = process.env; + it('buffers logs when the config object is provided, but not specifically enabled', () => { + // Prepare + const logger = new TestLogger({ + logLevel: LogLevel.ERROR, + logBufferOptions: { maxBytes: 100 }, + }); + + // Act + logger.debug('This is a log message'); + logger.flushBuffer(); + // Assess + expect(console.debug).toBeCalledTimes(1); + }); - beforeEach(() => { - process.env = { - ...ENVIRONMENT_VARIABLES, - POWERTOOLS_LOGGER_LOG_EVENT: 'true', - POWERTOOLS_DEV: 'true', - }; - vi.clearAllMocks(); + it('sets a max buffer sized when specified', () => { + // Prepare + const logger = new TestLogger({ + logBufferOptions: { + maxBytes: 250, + bufferAtVerbosity: LogLevel.DEBUG, + enabled: true, + }, + }); + + // Act + logger.debug('this is a debug'); + logger.debug('this is a debug'); + logger.flushBuffer(); + + // Assess + expect(console.debug).toBeCalledTimes(1); + expect(console.warn).toHaveLogged( + expect.objectContaining({ + level: 'WARN', + message: + 'Some logs are not displayed because they were evicted from the buffer. Increase buffer size to store more logs in the buffer', + }) + ); + }); }); - it('outputs buffered logs', () => { - // Prepare - const logger = new TestLogger({ logLevel: 'SILENT' }); - logger.enableBuffering(); - logger.setbufferLevelThreshold(LogLevelThreshold.CRITICAL); + describe('Functionality', () => { + const ENVIRONMENT_VARIABLES = process.env; - // Act - logger.debug('This is a debug'); - logger.warn('This is a warning'); - logger.critical('this is a critical'); + beforeEach(() => { + process.env = { + ...ENVIRONMENT_VARIABLES, + POWERTOOLS_LOGGER_LOG_EVENT: 'true', + POWERTOOLS_DEV: 'true', + }; + vi.clearAllMocks(); + }); + it('outputs a warning when there is an error buffering the log', () => { + // Prepare + process.env.POWERTOOLS_DEV = 'true'; + const logger = new TestLogger({ logBufferOptions: { enabled: true } }); + logger.overrideBufferLogItem(); + + // Act + logger.debug('This is a debug'); + + // Assess + expect(console.debug).toBeCalledTimes(1); + expect(console.warn).toBeCalledTimes(1); + }); - // Assess - expect(console.warn).toHaveBeenCalledTimes(0); - expect(console.error).toHaveBeenCalledTimes(0); + it('outputs buffered logs', () => { + // Prepare + const logger = new TestLogger({ + logLevel: 'SILENT', + logBufferOptions: { + enabled: true, + bufferAtVerbosity: LogLevel.CRITICAL, + }, + }); + + // Act + logger.debug('This is a debug'); + logger.warn('This is a warning'); + logger.critical('this is a critical'); + + // Assess + expect(console.warn).toHaveBeenCalledTimes(0); + expect(console.error).toHaveBeenCalledTimes(0); + + // Act + logger.flushBuffer(); + + // Assess + expect(console.warn).toHaveBeenCalledTimes(1); + expect(console.error).toHaveBeenCalledTimes(1); + }); - // Act - logger.flushBufferWrapper(); + it('handles an empty buffer', () => { + // Prepare + const logger = new TestLogger({ logBufferOptions: { enabled: true } }); - // Assess - expect(console.warn).toHaveBeenCalledTimes(1); - expect(console.error).toHaveBeenCalledTimes(1); - }); + // Act + logger.flushBuffer(); + }); - it('handles an empty buffer', () => { - // Prepare - const logger = new TestLogger(); - logger.enableBuffering(); + it('does not output buffered logs when trace id is not set', () => { + // Prepare + process.env._X_AMZN_TRACE_ID = undefined; + const logger = new TestLogger({ logBufferOptions: { enabled: true } }); - // Act - logger.flushBufferWrapper(); - }); + // Act + logger.debug('This is a debug'); + logger.warn('this is a warning'); - it('does not output buffered logs when trace id is not set', () => { - // Prepare - process.env._X_AMZN_TRACE_ID = undefined; - const logger = new TestLogger({}); - logger.enableBuffering(); + // Assess + expect(console.debug).toHaveBeenCalledTimes(0); + expect(console.warn).toHaveBeenCalledTimes(1); - // Act - logger.debug('This is a debug'); - logger.warn('this is a warning'); + // Act + logger.flushBuffer(); - // Assess - expect(console.debug).toHaveBeenCalledTimes(0); - expect(console.warn).toHaveBeenCalledTimes(1); + // Assess + expect(console.debug).toHaveBeenCalledTimes(0); + expect(console.warn).toHaveBeenCalledTimes(1); + }); - // Act - logger.flushBufferWrapper(); + it('outputs a warning when buffered logs have been evicted', () => { + // Prepare + const logger = new TestLogger({ + logLevel: LogLevel.ERROR, + logBufferOptions: { + enabled: true, + bufferAtVerbosity: LogLevel.INFO, + maxBytes: 1024, + }, + }); + + // Act + const longMessage = 'blah'.repeat(10); + + let i = 0; + while (i < 4) { + logger.info( + `${i} This is a really long log message intended to exceed the buffer ${longMessage}` + ); + i++; + } + + // Act + logger.flushBuffer(); + + // Assess + expect(console.warn).toHaveLogged( + expect.objectContaining({ + level: LogLevel.WARN, + message: + 'Some logs are not displayed because they were evicted from the buffer. Increase buffer size to store more logs in the buffer', + }) + ); + }); - // Assess - expect(console.debug).toHaveBeenCalledTimes(0); - expect(console.warn).toHaveBeenCalledTimes(1); - }); + it('it flushes the buffer when an error in logged', () => { + // Prepare + const logger = new TestLogger({ + logLevel: LogLevel.ERROR, + logBufferOptions: { enabled: true, bufferAtVerbosity: LogLevel.DEBUG }, + }); - it('outputs a warning when buffered logs have been evicted', () => { - // Prepare - const logger = new TestLogger({ logLevel: 'ERROR' }); - logger.enableBuffering(); - logger.setbufferLevelThreshold(LogLevelThreshold.INFO); + const spy = vi.spyOn(logger, 'flushBuffer'); - // Act - const longMessage = 'blah'.repeat(10); + // Act + logger.debug('This is a log message'); - let i = 0; - while (i < 4) { - logger.info( - `${i} This is a really long log message intended to exceed the buffer ${longMessage}` - ); - i++; - } - - // Act - logger.flushBufferWrapper(); - - // Assess - expect(console.warn).toHaveLogged( - expect.objectContaining({ - level: 'WARN', - message: - 'Some logs are not displayed because they were evicted from the buffer. Increase buffer size to store more logs in the buffer', - }) - ); + logger.error('This is an error message'); + + // Assess + expect(spy).toBeCalledTimes(1); + expect(console.debug).toBeCalledTimes(1); + expect(console.error).toBeCalledTimes(1); + }); }); });