From fb896e84ceb79f35b3f45e21d3ec41958c834bfe Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Thu, 13 Feb 2025 10:31:33 +0000 Subject: [PATCH 1/8] feat(logger): Add log buffer and flush method This commit implements basic buffering logic to the logger utility, and the `flushLogger` method for flushing the buffered logs. --- packages/logger/src/Logger.ts | 119 ++++++++- packages/logger/tests/unit/logBuffer.test.ts | 231 +++++++++--------- .../tests/unit/logBufferStructures.test.ts | 147 +++++++++++ 3 files changed, 381 insertions(+), 116 deletions(-) create mode 100644 packages/logger/tests/unit/logBufferStructures.test.ts diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 61f2da3df7..4d3c587df5 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -13,6 +13,7 @@ import { LogJsonIndent, LogLevelThreshold, ReservedKeys } from './constants.js'; import type { LogFormatter } from './formatter/LogFormatter.js'; import type { LogItem } from './formatter/LogItem.js'; import { PowertoolsLogFormatter } from './formatter/PowertoolsLogFormatter.js'; +import { CircularMap } from './logBuffer.js'; import type { ConfigServiceInterface } from './types/ConfigServiceInterface.js'; import type { ConstructorOptions, @@ -142,7 +143,7 @@ class Logger extends Utility implements LoggerInterface { * Sometimes we need to log warnings before the logger is fully initialized, however we can't log them * immediately because the logger is not ready yet. This buffer stores those logs until the logger is ready. */ - #buffer: [number, Parameters][] = []; + #initBuffer: [number, Parameters][] = []; /** * Flag used to determine if the logger is initialized. */ @@ -165,6 +166,29 @@ class Logger extends Utility implements LoggerInterface { */ #jsonReplacerFn?: CustomJsonReplacerFn; + /** + * isBufferEnabled represents whether the buffering functionality is enabled in the logger + */ + protected isBufferEnabled = false; + + /** + * bufferLogThreshold represents the log level threshold for the buffer + * Logs with a level lower than this threshold will be buffered + */ + protected bufferLogThreshold: number = LogLevelThreshold.DEBUG; + /** + * maxBufferBytesSize is the max size of the buffer. Additions to the buffer beyond this size will + * cause older logs to be evicted from the buffer + */ + #maxBufferBytesSize = 1024; + + /** + * buffer stores logs up to `maxBufferBytesSize` + */ + #buffer: CircularMap = new CircularMap({ + maxBytesSize: this.#maxBufferBytesSize, + }); + /** * Log level used by the current instance of Logger. * @@ -182,11 +206,11 @@ class Logger extends Utility implements LoggerInterface { // all logs are buffered until the logger is initialized this.setOptions(rest); this.#isInitialized = true; - for (const [level, log] of this.#buffer) { + for (const [level, log] of this.#initBuffer) { // we call the method directly and create the log item just in time this.printLog(level, this.createAndPopulateLogItem(...log)); } - this.#buffer = []; + this.#initBuffer = []; } /** @@ -937,7 +961,33 @@ class Logger extends Utility implements LoggerInterface { this.createAndPopulateLogItem(logLevel, input, extraInput) ); } else { - this.#buffer.push([logLevel, [logLevel, input, extraInput]]); + this.#initBuffer.push([logLevel, [logLevel, input, extraInput]]); + } + return; + } + + const trace_id = this.envVarsService.getXrayTraceId(); + if (trace_id !== undefined && this.shouldBufferLog(trace_id, logLevel)) { + try { + this.bufferLogItem( + trace_id, + this.createAndPopulateLogItem(logLevel, input, extraInput), + logLevel + ); + } catch (e) { + this.printLog( + LogLevelThreshold.WARN, + this.createAndPopulateLogItem( + LogLevelThreshold.WARN, + `Unable to buffer log: ${e}`, + extraInput + ) + ); + + this.printLog( + logLevel, + this.createAndPopulateLogItem(logLevel, input, extraInput) + ); } } } @@ -1169,6 +1219,67 @@ class Logger extends Utility implements LoggerInterface { }); persistentKeys && this.appendPersistentKeys(persistentKeys); } + + /** + * bufferLogItem adds a log to the buffer + * @param xrayTraceId + * @param log + * @param logLevel + */ + protected bufferLogItem( + xrayTraceId: string, + log: LogItem, + logLevel: number + ): void { + log.prepareForPrint(); + + const stringified = JSON.stringify( + log.getAttributes(), + this.getJsonReplacer(), + this.logIndentation + ); + + this.#buffer.setItem(xrayTraceId, stringified, logLevel); + } + + /** + * flushBuffer logs the items of the respective _X_AMZN_TRACE_ID within + * the buffer. + * @returns + */ + protected flushBuffer(): void { + const trace_id = this.envVarsService.getXrayTraceId(); + if (trace_id === undefined) { + return; + } + + const buffer = this.#buffer.get(trace_id) || []; + + for (const item of buffer) { + const consoleMethod = + item.logLevel === LogLevelThreshold.CRITICAL + ? 'error' + : (this.getLogLevelNameFromNumber( + item.logLevel + ).toLowerCase() as keyof Omit); + this.console[consoleMethod](item.value); + } + + this.#buffer.delete(trace_id); + } + /** + * shouldBufferLog returns true if the log meets the criteria to be buffered + * @param trace_id _X_AMZN_TRACE_ID + * @param logLevel The level of the log being considered + * @returns + */ + shouldBufferLog(trace_id: string | undefined, logLevel: number): boolean { + return ( + this.isBufferEnabled && + trace_id !== undefined && + logLevel <= this.bufferLogThreshold + ); + } } export { Logger }; diff --git a/packages/logger/tests/unit/logBuffer.test.ts b/packages/logger/tests/unit/logBuffer.test.ts index 05d930ede2..e07f2d9ee8 100644 --- a/packages/logger/tests/unit/logBuffer.test.ts +++ b/packages/logger/tests/unit/logBuffer.test.ts @@ -1,146 +1,153 @@ -import { describe, expect, it, vi } from 'vitest'; -import { CircularMap, SizedItem, SizedSet } from '../../src/logBuffer.js'; +import { beforeEach, describe, expect, it, vi } from 'vitest'; +import { Logger } from '../../src/Logger.js'; +import { LogLevelThreshold } 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'); + }); + } -describe('SizedItem', () => { - it('calculates the byteSize based on string value', () => { - // Prepare - const logEntry = 'hello world'; + public setbufferLevelThreshold(level: number): void { + this.bufferLogThreshold = level; + } +} - // Act - const item = new SizedItem(logEntry, 1); +describe('bufferLog', () => { + const ENVIRONMENT_VARIABLES = process.env; - // Assess - const expectedByteSize = Buffer.byteLength(logEntry); - expect(item.byteSize).toBe(expectedByteSize); + beforeEach(() => { + process.env = { + ...ENVIRONMENT_VARIABLES, + POWERTOOLS_LOGGER_LOG_EVENT: 'true', + POWERTOOLS_DEV: 'true', + }; + vi.clearAllMocks(); }); - it('throws an error if value is not a string', () => { - // Prepare - const invalidValue = { message: 'not a string' }; + it('outputs a warning when there is an error buffering the log', () => { + const logger = new TestLogger(); + logger.enableBuffering(); + logger.overrideBufferLogItem(); - // Act & Assess - expect( - () => new SizedItem(invalidValue as unknown as string, 1) - ).toThrowError('Value should be a string'); + logger.debug('This is a debug'); + expect(console.debug).toBeCalledTimes(1); + expect(console.warn).toBeCalledTimes(1); }); }); -describe('SizedSet', () => { - it('adds an item and updates currentBytesSize correctly', () => { - // Prepare - const set = new SizedSet(); - const item = new SizedItem('value', 1); - - // Act - set.add(item); +describe('flushBuffer', () => { + const ENVIRONMENT_VARIABLES = process.env; - // Assess - expect(set.currentBytesSize).toBe(item.byteSize); - expect(set.has(item)).toBe(true); + beforeEach(() => { + process.env = { + ...ENVIRONMENT_VARIABLES, + POWERTOOLS_LOGGER_LOG_EVENT: 'true', + POWERTOOLS_DEV: 'true', + }; + vi.clearAllMocks(); }); - it('deletes an item and updates currentBytesSize correctly', () => { - // Prepare - const set = new SizedSet(); - const item = new SizedItem('value', 1); - set.add(item); - const initialSize = set.currentBytesSize; + it('outputs buffered logs', () => { + const logger = new TestLogger({ logLevel: 'SILENT' }); + logger.enableBuffering(); + logger.setbufferLevelThreshold(LogLevelThreshold.CRITICAL); - // Act - const result = set.delete(item); + logger.debug('This is a debug'); + logger.warn('This is a warning'); + logger.critical('this is a critical'); - // Assess - expect(result).toBe(true); - expect(set.currentBytesSize).toBe(initialSize - item.byteSize); - expect(set.has(item)).toBe(false); - }); + expect(console.warn).toHaveBeenCalledTimes(0); + expect(console.error).toHaveBeenCalledTimes(0); - it('clears all items and resets currentBytesSize to 0', () => { - // Prepare - const set = new SizedSet(); - set.add(new SizedItem('b', 1)); - set.add(new SizedItem('d', 1)); + logger.flushBufferWrapper(); - // Act - set.clear(); + expect(console.warn).toHaveBeenCalledTimes(1); + expect(console.error).toHaveBeenCalledTimes(1); + }); - // Assess - expect(set.currentBytesSize).toBe(0); - expect(set.size).toBe(0); + it('handles an empty buffer', () => { + const logger = new TestLogger({ logLevel: 'SILENT' }); + logger.enableBuffering(); + + logger.flushBufferWrapper(); }); - it('removes the first inserted item with shift', () => { - // Prepare - const set = new SizedSet(); - const item1 = new SizedItem('first', 1); - const item2 = new SizedItem('second', 1); - set.add(item1); - set.add(item2); - - // Act - const shiftedItem = set.shift(); - - // Assess - expect(shiftedItem).toEqual(item1); - expect(set.has(item1)).toBe(false); - expect(set.currentBytesSize).toBe(item2.byteSize); + it('does not output buffered logs when trace id is not set', () => { + process.env._X_AMZN_TRACE_ID = undefined; + + const logger = new TestLogger({}); + logger.enableBuffering(); + + logger.debug('This is a debug'); + logger.warn('this is a warning'); + + expect(console.debug).toHaveBeenCalledTimes(0); + expect(console.warn).toHaveBeenCalledTimes(1); + + logger.flushBufferWrapper(); + + expect(console.debug).toHaveBeenCalledTimes(0); + expect(console.warn).toHaveBeenCalledTimes(1); }); }); -describe('CircularMap', () => { - it('adds items to a new buffer for a given key', () => { - // Prepare - const maxBytes = 200; - const circularMap = new CircularMap({ - maxBytesSize: maxBytes, - }); +describe('shouldBufferLog', () => { + const ENVIRONMENT_VARIABLES = process.env; - // Act - circularMap.setItem('trace-1', 'first log', 1); + beforeEach(() => { + process.env = { + ...ENVIRONMENT_VARIABLES, + POWERTOOLS_LOGGER_LOG_EVENT: 'true', + POWERTOOLS_DEV: 'true', + }; + vi.clearAllMocks(); + }); + it('returns false when _X_AMZN_TRACE_ID is not set', () => { + const logger = new TestLogger({}); + process.env._X_AMZN_TRACE_ID = undefined; + logger.enableBuffering(); - // Assess - const buffer = circularMap.get('trace-1'); - expect(buffer).toBeDefined(); - if (buffer) { - expect(buffer.currentBytesSize).toBeGreaterThan(0); - expect(buffer.size).toBe(1); - } + expect(logger.shouldBufferLog(undefined, LogLevelThreshold.TRACE)).toBe( + false + ); }); - it('throws an error when an item exceeds maxBytesSize', () => { - // Prepare - const maxBytes = 10; - const circularMap = new CircularMap({ - maxBytesSize: maxBytes, - }); + it('returns false when the buffer is disabled', () => { + const logger = new TestLogger({}); + logger.disableBuffering(); - // Act & Assess - expect(() => { - circularMap.setItem('trace-1', 'a very long message', 1); - }).toThrowError('Item too big'); + const trace = process.env._X_AMZN_TRACE_ID; + + expect(logger.shouldBufferLog(trace, LogLevelThreshold.TRACE)).toBe(false); }); - it('evicts items when the buffer overflows and call the overflow callback', () => { - // Prepare - const options = { - maxBytesSize: 15, - onBufferOverflow: vi.fn(), - }; - const circularMap = new CircularMap(options); - const smallEntry = '12345'; + it('returns false when the log level above the bufferLevelThreshold', () => { + const logger = new TestLogger({}); + logger.enableBuffering(); - const entryByteSize = Buffer.byteLength(smallEntry); - const entriesCount = Math.ceil(options.maxBytesSize / entryByteSize); + const trace = process.env._X_AMZN_TRACE_ID; - // Act - for (let i = 0; i < entriesCount; i++) { - circularMap.setItem('trace-1', smallEntry, 1); - } + expect(logger.shouldBufferLog(trace, LogLevelThreshold.INFO)).toBe(false); + }); - // Assess - expect(options.onBufferOverflow).toHaveBeenCalledTimes(1); - expect(circularMap.get('trace-1')?.currentBytesSize).toBeLessThan( - options.maxBytesSize - ); + it('returns true when the criteria is met', () => { + const logger = new TestLogger({}); + logger.enableBuffering(); + const trace = process.env._X_AMZN_TRACE_ID; + + expect(logger.shouldBufferLog(trace, LogLevelThreshold.TRACE)).toBe(true); }); }); diff --git a/packages/logger/tests/unit/logBufferStructures.test.ts b/packages/logger/tests/unit/logBufferStructures.test.ts new file mode 100644 index 0000000000..8d44eb25c1 --- /dev/null +++ b/packages/logger/tests/unit/logBufferStructures.test.ts @@ -0,0 +1,147 @@ +import { describe, expect, it, vi } from 'vitest'; + +import { CircularMap, SizedItem, SizedSet } from '../../src/logBuffer.js'; + +describe('SizedItem', () => { + it('calculates the byteSize based on string value', () => { + // Prepare + const logEntry = 'hello world'; + + // Act + const item = new SizedItem(logEntry, 1); + + // Assess + const expectedByteSize = Buffer.byteLength(logEntry); + expect(item.byteSize).toBe(expectedByteSize); + }); + + it('throws an error if value is not a string', () => { + // Prepare + const invalidValue = { message: 'not a string' }; + + // Act & Assess + expect( + () => new SizedItem(invalidValue as unknown as string, 1) + ).toThrowError('Value should be a string'); + }); +}); + +describe('SizedSet', () => { + it('adds an item and updates currentBytesSize correctly', () => { + // Prepare + const set = new SizedSet(); + const item = new SizedItem('value', 1); + + // Act + set.add(item); + + // Assess + expect(set.currentBytesSize).toBe(item.byteSize); + expect(set.has(item)).toBe(true); + }); + + it('deletes an item and updates currentBytesSize correctly', () => { + // Prepare + const set = new SizedSet(); + const item = new SizedItem('value', 1); + set.add(item); + const initialSize = set.currentBytesSize; + + // Act + const result = set.delete(item); + + // Assess + expect(result).toBe(true); + expect(set.currentBytesSize).toBe(initialSize - item.byteSize); + expect(set.has(item)).toBe(false); + }); + + it('clears all items and resets currentBytesSize to 0', () => { + // Prepare + const set = new SizedSet(); + set.add(new SizedItem('b', 1)); + set.add(new SizedItem('d', 1)); + + // Act + set.clear(); + + // Assess + expect(set.currentBytesSize).toBe(0); + expect(set.size).toBe(0); + }); + + it('removes the first inserted item with shift', () => { + // Prepare + const set = new SizedSet(); + const item1 = new SizedItem('first', 1); + const item2 = new SizedItem('second', 1); + set.add(item1); + set.add(item2); + + // Act + const shiftedItem = set.shift(); + + // Assess + expect(shiftedItem).toEqual(item1); + expect(set.has(item1)).toBe(false); + expect(set.currentBytesSize).toBe(item2.byteSize); + }); +}); + +describe('CircularMap', () => { + it('adds items to a new buffer for a given key', () => { + // Prepare + const maxBytes = 200; + const circularMap = new CircularMap({ + maxBytesSize: maxBytes, + }); + + // Act + circularMap.setItem('trace-1', 'first log', 1); + + // Assess + const buffer = circularMap.get('trace-1'); + expect(buffer).toBeDefined(); + if (buffer) { + expect(buffer.currentBytesSize).toBeGreaterThan(0); + expect(buffer.size).toBe(1); + } + }); + + it('throws an error when an item exceeds maxBytesSize', () => { + // Prepare + const maxBytes = 10; + const circularMap = new CircularMap({ + maxBytesSize: maxBytes, + }); + + // Act & Assess + expect(() => { + circularMap.setItem('trace-1', 'a very long message', 1); + }).toThrowError('Item too big'); + }); + + it('evicts items when the buffer overflows and call the overflow callback', () => { + // Prepare + const options = { + maxBytesSize: 15, + onBufferOverflow: vi.fn(), + }; + const circularMap = new CircularMap(options); + const smallEntry = '12345'; + + const entryByteSize = Buffer.byteLength(smallEntry); + const entriesCount = Math.ceil(options.maxBytesSize / entryByteSize); + + // Act + for (let i = 0; i < entriesCount; i++) { + circularMap.setItem('trace-1', smallEntry, 1); + } + + // Assess + expect(options.onBufferOverflow).toHaveBeenCalledTimes(1); + expect(circularMap.get('trace-1')?.currentBytesSize).toBeLessThan( + options.maxBytesSize + ); + }); +}); From 90568f439cea337f8cf46fdcad3d940fed608515 Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Wed, 19 Feb 2025 09:58:47 +0000 Subject: [PATCH 2/8] Add SonarCube feedback --- packages/logger/src/Logger.ts | 9 ++++++--- 1 file changed, 6 insertions(+), 3 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 4d3c587df5..7a0047698f 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -143,7 +143,10 @@ class Logger extends Utility implements LoggerInterface { * Sometimes we need to log warnings before the logger is fully initialized, however we can't log them * immediately because the logger is not ready yet. This buffer stores those logs until the logger is ready. */ - #initBuffer: [number, Parameters][] = []; + readonly #initBuffer: [ + number, + Parameters, + ][] = []; /** * Flag used to determine if the logger is initialized. */ @@ -180,12 +183,12 @@ class Logger extends Utility implements LoggerInterface { * maxBufferBytesSize is the max size of the buffer. Additions to the buffer beyond this size will * cause older logs to be evicted from the buffer */ - #maxBufferBytesSize = 1024; + readonly #maxBufferBytesSize = 1024; /** * buffer stores logs up to `maxBufferBytesSize` */ - #buffer: CircularMap = new CircularMap({ + readonly #buffer: CircularMap = new CircularMap({ maxBytesSize: this.#maxBufferBytesSize, }); From d18049fa799b50d9ac98ecda4cfdb5be261d8868 Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Wed, 19 Feb 2025 10:03:33 +0000 Subject: [PATCH 3/8] Rename trace_id to traceId --- packages/logger/src/Logger.ts | 20 ++++++++++---------- 1 file changed, 10 insertions(+), 10 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 7a0047698f..73899ec154 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -969,11 +969,11 @@ class Logger extends Utility implements LoggerInterface { return; } - const trace_id = this.envVarsService.getXrayTraceId(); - if (trace_id !== undefined && this.shouldBufferLog(trace_id, logLevel)) { + const traceId = this.envVarsService.getXrayTraceId(); + if (traceId !== undefined && this.shouldBufferLog(traceId, logLevel)) { try { this.bufferLogItem( - trace_id, + traceId, this.createAndPopulateLogItem(logLevel, input, extraInput), logLevel ); @@ -1251,12 +1251,12 @@ class Logger extends Utility implements LoggerInterface { * @returns */ protected flushBuffer(): void { - const trace_id = this.envVarsService.getXrayTraceId(); - if (trace_id === undefined) { + const traceId = this.envVarsService.getXrayTraceId(); + if (traceId === undefined) { return; } - const buffer = this.#buffer.get(trace_id) || []; + const buffer = this.#buffer.get(traceId) || []; for (const item of buffer) { const consoleMethod = @@ -1268,18 +1268,18 @@ class Logger extends Utility implements LoggerInterface { this.console[consoleMethod](item.value); } - this.#buffer.delete(trace_id); + this.#buffer.delete(traceId); } /** * shouldBufferLog returns true if the log meets the criteria to be buffered - * @param trace_id _X_AMZN_TRACE_ID + * @param traceId _X_AMZN_TRACE_ID * @param logLevel The level of the log being considered * @returns */ - shouldBufferLog(trace_id: string | undefined, logLevel: number): boolean { + shouldBufferLog(traceId: string | undefined, logLevel: number): boolean { return ( this.isBufferEnabled && - trace_id !== undefined && + traceId !== undefined && logLevel <= this.bufferLogThreshold ); } From 1b64fbd8cb675718679e886705e74dd78f785ae4 Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Wed, 19 Feb 2025 10:04:41 +0000 Subject: [PATCH 4/8] Use error instead of e --- packages/logger/src/Logger.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 73899ec154..dcfb1cfa33 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -977,12 +977,12 @@ class Logger extends Utility implements LoggerInterface { this.createAndPopulateLogItem(logLevel, input, extraInput), logLevel ); - } catch (e) { + } catch (error) { this.printLog( LogLevelThreshold.WARN, this.createAndPopulateLogItem( LogLevelThreshold.WARN, - `Unable to buffer log: ${e}`, + `Unable to buffer log: ${(error as Error).message}`, extraInput ) ); From ce131775ae1b20678a3d216fc7d274554d5744b7 Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Wed, 19 Feb 2025 10:37:12 +0000 Subject: [PATCH 5/8] Update test feedback --- packages/logger/tests/unit/logBuffer.test.ts | 68 +++++--------------- 1 file changed, 17 insertions(+), 51 deletions(-) diff --git a/packages/logger/tests/unit/logBuffer.test.ts b/packages/logger/tests/unit/logBuffer.test.ts index e07f2d9ee8..bde806a7fa 100644 --- a/packages/logger/tests/unit/logBuffer.test.ts +++ b/packages/logger/tests/unit/logBuffer.test.ts @@ -36,13 +36,16 @@ describe('bufferLog', () => { }; vi.clearAllMocks(); }); - it('outputs a warning when there is an error buffering the log', () => { + // Prepare const logger = new TestLogger(); logger.enableBuffering(); logger.overrideBufferLogItem(); + // Act logger.debug('This is a debug'); + + // Assess expect(console.debug).toBeCalledTimes(1); expect(console.warn).toBeCalledTimes(1); }); @@ -61,93 +64,56 @@ describe('flushBuffer', () => { }); it('outputs buffered logs', () => { + // Prepare const logger = new TestLogger({ logLevel: 'SILENT' }); logger.enableBuffering(); logger.setbufferLevelThreshold(LogLevelThreshold.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.flushBufferWrapper(); + // Assess expect(console.warn).toHaveBeenCalledTimes(1); expect(console.error).toHaveBeenCalledTimes(1); }); it('handles an empty buffer', () => { - const logger = new TestLogger({ logLevel: 'SILENT' }); + // Prepare + const logger = new TestLogger(); logger.enableBuffering(); + // Act logger.flushBufferWrapper(); }); 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(); + // Act logger.debug('This is a debug'); logger.warn('this is a warning'); + // Assess expect(console.debug).toHaveBeenCalledTimes(0); expect(console.warn).toHaveBeenCalledTimes(1); + // Act logger.flushBufferWrapper(); + // Assess expect(console.debug).toHaveBeenCalledTimes(0); expect(console.warn).toHaveBeenCalledTimes(1); }); }); - -describe('shouldBufferLog', () => { - const ENVIRONMENT_VARIABLES = process.env; - - beforeEach(() => { - process.env = { - ...ENVIRONMENT_VARIABLES, - POWERTOOLS_LOGGER_LOG_EVENT: 'true', - POWERTOOLS_DEV: 'true', - }; - vi.clearAllMocks(); - }); - it('returns false when _X_AMZN_TRACE_ID is not set', () => { - const logger = new TestLogger({}); - process.env._X_AMZN_TRACE_ID = undefined; - logger.enableBuffering(); - - expect(logger.shouldBufferLog(undefined, LogLevelThreshold.TRACE)).toBe( - false - ); - }); - - it('returns false when the buffer is disabled', () => { - const logger = new TestLogger({}); - logger.disableBuffering(); - - const trace = process.env._X_AMZN_TRACE_ID; - - expect(logger.shouldBufferLog(trace, LogLevelThreshold.TRACE)).toBe(false); - }); - - it('returns false when the log level above the bufferLevelThreshold', () => { - const logger = new TestLogger({}); - logger.enableBuffering(); - - const trace = process.env._X_AMZN_TRACE_ID; - - expect(logger.shouldBufferLog(trace, LogLevelThreshold.INFO)).toBe(false); - }); - - it('returns true when the criteria is met', () => { - const logger = new TestLogger({}); - logger.enableBuffering(); - const trace = process.env._X_AMZN_TRACE_ID; - - expect(logger.shouldBufferLog(trace, LogLevelThreshold.TRACE)).toBe(true); - }); -}); From a897111ab09541de1ecf54d0cca396010664c338 Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Wed, 19 Feb 2025 11:14:19 +0000 Subject: [PATCH 6/8] Improve jsdoc comments --- packages/logger/src/Logger.ts | 33 +++++++++++++++++---------------- 1 file changed, 17 insertions(+), 16 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index dcfb1cfa33..47192b3a7d 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -170,23 +170,23 @@ class Logger extends Utility implements LoggerInterface { #jsonReplacerFn?: CustomJsonReplacerFn; /** - * isBufferEnabled represents whether the buffering functionality is enabled in the logger + * Represents whether the buffering functionality is enabled in the logger */ protected isBufferEnabled = false; /** - * bufferLogThreshold represents the log level threshold for the buffer + * Log level threshold for the buffer * Logs with a level lower than this threshold will be buffered */ protected bufferLogThreshold: number = LogLevelThreshold.DEBUG; /** - * maxBufferBytesSize is the max size of the buffer. Additions to the buffer beyond this size will + * 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; /** - * buffer stores logs up to `maxBufferBytesSize` + * 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, @@ -946,7 +946,7 @@ class Logger extends Utility implements LoggerInterface { } /** - * Print a given log with given log level. + * Print or buffer a given log with given log level. * * @param logLevel - The log level threshold * @param input - The log message @@ -1224,10 +1224,10 @@ class Logger extends Utility implements LoggerInterface { } /** - * bufferLogItem adds a log to the buffer - * @param xrayTraceId - * @param log - * @param logLevel + * Add a log to the buffer + * @param xrayTraceId - _X_AMZN_TRACE_ID of the request + * @param log - Log to be buffered + * @param logLevel - level of log to be buffered */ protected bufferLogItem( xrayTraceId: string, @@ -1246,9 +1246,8 @@ class Logger extends Utility implements LoggerInterface { } /** - * flushBuffer logs the items of the respective _X_AMZN_TRACE_ID within + * Flushes all items of the respective _X_AMZN_TRACE_ID within * the buffer. - * @returns */ protected flushBuffer(): void { const traceId = this.envVarsService.getXrayTraceId(); @@ -1271,12 +1270,14 @@ class Logger extends Utility implements LoggerInterface { this.#buffer.delete(traceId); } /** - * shouldBufferLog returns true if the log meets the criteria to be buffered - * @param traceId _X_AMZN_TRACE_ID - * @param logLevel The level of the log being considered - * @returns + * Tests if the log meets the criteria to be buffered + * @param traceId - _X_AMZN_TRACE_ID of the request + * @param logLevel - The level of the log being considered */ - shouldBufferLog(traceId: string | undefined, logLevel: number): boolean { + protected shouldBufferLog( + traceId: string | undefined, + logLevel: number + ): boolean { return ( this.isBufferEnabled && traceId !== undefined && From cc55e01448c1383767a15b4a146084dccd1d1af3 Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Wed, 19 Feb 2025 11:15:54 +0000 Subject: [PATCH 7/8] Remove beforeEach block --- packages/logger/tests/unit/logBuffer.test.ts | 11 +---------- 1 file changed, 1 insertion(+), 10 deletions(-) diff --git a/packages/logger/tests/unit/logBuffer.test.ts b/packages/logger/tests/unit/logBuffer.test.ts index bde806a7fa..4cbc5caaea 100644 --- a/packages/logger/tests/unit/logBuffer.test.ts +++ b/packages/logger/tests/unit/logBuffer.test.ts @@ -26,18 +26,9 @@ class TestLogger extends Logger { } describe('bufferLog', () => { - const ENVIRONMENT_VARIABLES = process.env; - - 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(); logger.enableBuffering(); logger.overrideBufferLogItem(); From 33ff87fb36b025766678a5d3d6821d1d0e721d1e Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Wed, 19 Feb 2025 12:29:42 +0000 Subject: [PATCH 8/8] Pass error as extra input --- packages/logger/src/Logger.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 47192b3a7d..35397f7659 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -983,7 +983,7 @@ class Logger extends Utility implements LoggerInterface { this.createAndPopulateLogItem( LogLevelThreshold.WARN, `Unable to buffer log: ${(error as Error).message}`, - extraInput + [error as Error] ) );