From 45a67a698c9b3d3fced95427c4c16ceb30421926 Mon Sep 17 00:00:00 2001 From: zirkelc Date: Thu, 3 Oct 2024 17:28:35 +0200 Subject: [PATCH 1/3] feat(logger): add context for low prio logs --- packages/logger/src/Logger.ts | 34 ++++++++++++++++++++++++++++++++++ 1 file changed, 34 insertions(+) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 2a4a81d53b..18c7702d0f 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -139,6 +139,11 @@ class Logger extends Utility implements LoggerInterface { * immediately because the logger is not ready yet. This buffer stores those logs until the logger is ready. */ #buffer: [number, Parameters][] = []; + + + #context: Record>> = {} + + /** * Flag used to determine if the logger is initialized. */ @@ -183,6 +188,7 @@ class Logger extends Utility implements LoggerInterface { this.printLog(level, this.createAndPopulateLogItem(...log)); } this.#buffer = []; + this.#context = {}; } /** @@ -868,6 +874,22 @@ class Logger extends Utility implements LoggerInterface { extraInput: LogItemExtraInput ): void { if (logLevel >= this.logLevel) { + const xRayTraceId = this.envVarsService.getXrayTraceId(); + + // Print all log items in the context + if (this.#context[xRayTraceId]) { + for (const contextItem of this.#context[xRayTraceId]) { + this.printLog( + logLevel, + this.createAndPopulateLogItem(...contextItem) + ); + } + + // Clear the context after flushing + // This also removes entries from other X-Ray trace IDs + this.#context = {}; + } + if (this.#isInitialized) { this.printLog( logLevel, @@ -876,6 +898,18 @@ class Logger extends Utility implements LoggerInterface { } else { this.#buffer.push([logLevel, [logLevel, input, extraInput]]); } + } else { + const xRayTraceId = this.envVarsService.getXrayTraceId() as string; + + // Add the log item to the context + const context = this.#context[xRayTraceId] ?? []; + context.push([logLevel, input, extraInput]); + + // Assign the updated context to the context property + // This also removes other X-Ray trace IDs from the context + this.#context = { + [xRayTraceId]: context, + }; } } From 7e99f1f5ca87def3e6d88010ea06ed7164fcaece Mon Sep 17 00:00:00 2001 From: zirkelc Date: Mon, 7 Oct 2024 13:22:30 +0200 Subject: [PATCH 2/3] feat(logger): save formatted log to context --- packages/logger/src/Logger.ts | 44 +++++++++++++++++++---------------- 1 file changed, 24 insertions(+), 20 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 18c7702d0f..16135241be 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -140,9 +140,7 @@ class Logger extends Utility implements LoggerInterface { */ #buffer: [number, Parameters][] = []; - - #context: Record>> = {} - + #context: Record> = {}; /** * Flag used to determine if the logger is initialized. @@ -841,9 +839,7 @@ class Logger extends Utility implements LoggerInterface { * @param logLevel - The log level * @param log - The log item to print */ - private printLog(logLevel: number, log: LogItem): void { - log.prepareForPrint(); - + private printLog(logLevel: number, log: LogItem | string): void { const consoleMethod = logLevel === LogLevelThreshold.CRITICAL ? 'error' @@ -853,11 +849,17 @@ class Logger extends Utility implements LoggerInterface { >); this.console[consoleMethod]( - JSON.stringify( - log.getAttributes(), - this.getJsonReplacer(), - this.logIndentation - ) + typeof log === 'string' ? log : this.formatLog(log) + ); + } + + private formatLog(log: LogItem): string { + log.prepareForPrint(); + + return JSON.stringify( + log.getAttributes(), + this.getJsonReplacer(), + this.logIndentation ); } @@ -874,17 +876,14 @@ class Logger extends Utility implements LoggerInterface { extraInput: LogItemExtraInput ): void { if (logLevel >= this.logLevel) { - const xRayTraceId = this.envVarsService.getXrayTraceId(); - + const xRayTraceId = this.envVarsService.getXrayTraceId() as string; + // Print all log items in the context if (this.#context[xRayTraceId]) { for (const contextItem of this.#context[xRayTraceId]) { - this.printLog( - logLevel, - this.createAndPopulateLogItem(...contextItem) - ); + this.printLog(...contextItem); } - + // Clear the context after flushing // This also removes entries from other X-Ray trace IDs this.#context = {}; @@ -903,9 +902,14 @@ class Logger extends Utility implements LoggerInterface { // Add the log item to the context const context = this.#context[xRayTraceId] ?? []; - context.push([logLevel, input, extraInput]); + context.push([ + logLevel, + this.formatLog( + this.createAndPopulateLogItem(logLevel, input, extraInput) + ), + ]); - // Assign the updated context to the context property + // Assign the updated context to the context property // This also removes other X-Ray trace IDs from the context this.#context = { [xRayTraceId]: context, From b434aa52e16220cbbfe263721c9cc55ead42db1e Mon Sep 17 00:00:00 2001 From: zirkelc Date: Wed, 9 Oct 2024 14:48:47 +0200 Subject: [PATCH 3/3] test: add test for flushing buffers --- packages/logger/src/Logger.ts | 23 ++--- .../logger/tests/unit/logFlushBuffer.test.ts | 84 +++++++++++++++++++ 2 files changed, 97 insertions(+), 10 deletions(-) create mode 100644 packages/logger/tests/unit/logFlushBuffer.test.ts diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 16135241be..8cf286a100 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -876,17 +876,20 @@ class Logger extends Utility implements LoggerInterface { extraInput: LogItemExtraInput ): void { if (logLevel >= this.logLevel) { - const xRayTraceId = this.envVarsService.getXrayTraceId() as string; - - // Print all log items in the context - if (this.#context[xRayTraceId]) { - for (const contextItem of this.#context[xRayTraceId]) { - this.printLog(...contextItem); + // Only flush buffer when log level is higher than the configured log level + if (logLevel > this.logLevel) { + const xRayTraceId = this.envVarsService.getXrayTraceId() as string; + + // Print all log items in the context + if (this.#context[xRayTraceId]) { + for (const contextItem of this.#context[xRayTraceId]) { + this.printLog(...contextItem); + } + + // Clear the context after flushing + // This also removes entries from other X-Ray trace IDs + this.#context = {}; } - - // Clear the context after flushing - // This also removes entries from other X-Ray trace IDs - this.#context = {}; } if (this.#isInitialized) { diff --git a/packages/logger/tests/unit/logFlushBuffer.test.ts b/packages/logger/tests/unit/logFlushBuffer.test.ts new file mode 100644 index 0000000000..1735f5792f --- /dev/null +++ b/packages/logger/tests/unit/logFlushBuffer.test.ts @@ -0,0 +1,84 @@ +import { beforeEach, describe, expect, it, vi } from 'vitest'; +import { Logger } from '../../src/Logger.js'; +import { LogLevel, LogLevelThreshold } from '../../src/constants.js'; +import type { ConfigServiceInterface } from '../../src/types/ConfigServiceInterface.js'; +import type { + LogFunction, + LogLevel as LogLevelType, +} from '../../src/types/Logger.js'; + +/** + * Helper function to get the console method for a given log level, we use this + * for properly mocking the console methods in the tests and account for the + * fact that `critical` is not a valid console method, which we proxy to `error`, + * and `trace` is internally proxied to `log`. + * + * @param method - The method to get the console method for + */ +const getConsoleMethod = ( + method: string +): keyof Omit | 'log' => { + const lowercaseMethod = method.toLowerCase(); + switch (lowercaseMethod) { + case 'trace': + return 'log'; + case 'critical': + return 'error'; + default: + return lowercaseMethod as keyof Omit; + } +}; + +describe('Log flush buffer', () => { + const ENVIRONMENT_VARIABLES = process.env; + + beforeEach(() => { + process.env = { ...ENVIRONMENT_VARIABLES, POWERTOOLS_DEV: 'true' }; + vi.resetAllMocks(); + }); + + it("doesn't flush buffer when calling a log level lower than the configured log level", () => { + // Prepare + const logger = new Logger({ logLevel: 'WARN' }); + + // Act + logger.debug('debug'); + logger.info('info'); + + // Assess + expect(console.debug).not.toHaveBeenCalled(); + expect(console.info).not.toHaveBeenCalled(); + }); + + it("doesn't flush buffer when calling a log level equal to the configured log level", () => { + // Prepare + const logger = new Logger({ logLevel: 'WARN' }); + + // Act + logger.debug('debug'); + logger.info('info'); + logger.warn('warn'); + + // Assess + expect(console.debug).not.toHaveBeenCalled(); + expect(console.info).not.toHaveBeenCalled(); + expect(console.warn).toHaveBeenCalled(); + }); + + it('flushes buffer when calling a log level higher than the configured log level', () => { + // Prepare + const logger = new Logger({ logLevel: 'WARN' }); + + // Act + logger.debug('debug'); + logger.info('info'); + logger.warn('warn'); + logger.error('error'); + + // Assess + expect(console.debug).toHaveBeenCalled(); + expect(console.info).toHaveBeenCalled(); + expect(console.warn).toHaveBeenCalled(); + expect(console.error).toHaveBeenCalled(); + }); +});