From 4fff41a832fa4546878edd89d52ce8579f2f77af Mon Sep 17 00:00:00 2001 From: timo92 Date: Thu, 8 Aug 2024 08:47:44 +0200 Subject: [PATCH 01/12] feat(logger): introduce loglevel trace (#1589) --- packages/logger/src/Logger.ts | 12 ++++++++++++ packages/logger/src/constants.ts | 1 + packages/logger/src/types/Logger.ts | 1 + 3 files changed, 14 insertions(+) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 9bdf1e6f10..228d1b4e6c 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -158,6 +158,7 @@ class Logger extends Utility implements LoggerInterface { * The levels are in ascending order from the most verbose to the least verbose (no logs). */ private readonly logLevelThresholds: LogLevelThresholds = { + TRACE: 6, DEBUG: 8, INFO: 12, WARN: 16, @@ -636,6 +637,17 @@ class Logger extends Utility implements LoggerInterface { return this.getLogEvent(); } + /** + * It prints a log item with level TRACE. + * + * @param {LogItemMessage} input + * @param {Error | LogAttributes | string} extraInput + * @returns {void} + */ + public trace(input: LogItemMessage, ...extraInput: LogItemExtraInput): void { + this.processLogItem(6, input, extraInput); + } + /** * It prints a log item with level WARN. * diff --git a/packages/logger/src/constants.ts b/packages/logger/src/constants.ts index 5fbe2be5be..38db9bf468 100644 --- a/packages/logger/src/constants.ts +++ b/packages/logger/src/constants.ts @@ -15,6 +15,7 @@ const LogJsonIndent = { } as const; const LogLevel = { + TRACE: 'TRACE', DEBUG: 'DEBUG', INFO: 'INFO', WARN: 'WARN', diff --git a/packages/logger/src/types/Logger.ts b/packages/logger/src/types/Logger.ts index c08f7a9ed7..3138af4273 100644 --- a/packages/logger/src/types/Logger.ts +++ b/packages/logger/src/types/Logger.ts @@ -148,6 +148,7 @@ type LoggerInterface = { setLogLevel(logLevel: LogLevel): void; setPersistentLogAttributes(attributes?: LogAttributes): void; shouldLogEvent(overwriteValue?: boolean): boolean; + trace(input: LogItemMessage, ...extraInput: LogItemExtraInput): void; warn(input: LogItemMessage, ...extraInput: LogItemExtraInput): void; }; From fd5862aa13e0fc56c74b5a86430bc8741e57aa7c Mon Sep 17 00:00:00 2001 From: timo92 Date: Thu, 8 Aug 2024 09:01:23 +0200 Subject: [PATCH 02/12] test(logger): add test case for loglevel trace (#1589) --- packages/logger/tests/unit/Logger.test.ts | 104 +++++++++++++++++++++- 1 file changed, 100 insertions(+), 4 deletions(-) diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index 447e2b9786..78db5d5bc3 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -46,6 +46,7 @@ describe('Class: Logger', () => { bar: 'baz', }; const logLevelThresholds: LogLevelThresholds = { + TRACE: 6, DEBUG: 8, INFO: 12, WARN: 16, @@ -567,25 +568,90 @@ describe('Class: Logger', () => { }); describe.each([ + [ + 'trace', + 'DOES', + true, + 'DOES NOT', + false, + 'DOES NOT', + false, + 'DOES NOT', + false, + 'DOES NOT', + false, + ], [ 'debug', 'DOES', true, + 'DOES', + true, + 'DOES NOT', + false, + 'DOES NOT', + false, + 'DOES NOT', + false, + ], + [ + 'info', + 'DOES', + true, + 'DOES', + true, + 'DOES', + true, 'DOES NOT', false, 'DOES NOT', false, + ], + [ + 'warn', + 'DOES', + true, + 'DOES', + true, + 'DOES', + true, + 'DOES', + true, 'DOES NOT', false, ], - ['info', 'DOES', true, 'DOES', true, 'DOES NOT', false, 'DOES NOT', false], - ['warn', 'DOES', true, 'DOES', true, 'DOES', true, 'DOES NOT', false], - ['error', 'DOES', true, 'DOES', true, 'DOES', true, 'DOES', true], - ['critical', 'DOES', true, 'DOES', true, 'DOES', true, 'DOES', true], + [ + 'error', + 'DOES', + true, + 'DOES', + true, + 'DOES', + true, + 'DOES', + true, + 'DOES', + true, + ], + [ + 'critical', + 'DOES', + true, + 'DOES', + true, + 'DOES', + true, + 'DOES', + true, + 'DOES', + true, + ], ])( 'Method:', ( method: string, + traceAction, + tracePrints, debugAction, debugPrints, infoAction, @@ -598,6 +664,36 @@ describe('Class: Logger', () => { const methodOfLogger = method as keyof LogFunction; describe('Feature: log level', () => { + test(`when the level is TRACE, it ${traceAction} print to stdout`, () => { + // Prepare + const logger = new Logger({ + logLevel: LogLevel.TRACE, + }); + const consoleSpy = jest.spyOn( + // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing + logger['console'], + getConsoleMethod(method) + ); + // Act + logger[methodOfLogger]('foo'); + + // Assess + expect(consoleSpy).toBeCalledTimes(tracePrints ? 1 : 0); + if (tracePrints) { + expect(consoleSpy).toHaveBeenNthCalledWith( + 1, + JSON.stringify({ + level: methodOfLogger.toUpperCase(), + message: 'foo', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + } + }); + test(`when the level is DEBUG, it ${debugAction} print to stdout`, () => { // Prepare const logger = new Logger({ From e06d491e10f9f37c713185629cba0360e4117c28 Mon Sep 17 00:00:00 2001 From: timo92 Date: Thu, 8 Aug 2024 09:08:56 +0200 Subject: [PATCH 03/12] docs(logger): add loglevel trace to documentation (#1589) --- docs/core/logger.md | 1 + 1 file changed, 1 insertion(+) diff --git a/docs/core/logger.md b/docs/core/logger.md index ffce457122..8a8408c121 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -454,6 +454,7 @@ We support the following log levels: | Level | Numeric value | | ---------- | ------------- | +| `TRACE` | 6 | | `DEBUG` | 8 | | `INFO` | 12 | | `WARN` | 16 | From 72d34351a5a4d963af36de5d93ab0307667168df Mon Sep 17 00:00:00 2001 From: timo92 Date: Thu, 8 Aug 2024 09:17:25 +0200 Subject: [PATCH 04/12] refactor(logger): replace hardcoded loglevel values with variables --- packages/logger/src/Logger.ts | 16 ++++++++-------- 1 file changed, 8 insertions(+), 8 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 228d1b4e6c..1c769793d9 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -201,7 +201,7 @@ class Logger extends Utility implements LoggerInterface { * * We keep this value to be able to reset the log level to the initial value when the sample rate is refreshed. */ - #initialLogLevel = 12; + #initialLogLevel = this.logLevelThresholds.INFO; /** * Replacer function used to serialize the log items. */ @@ -338,7 +338,7 @@ class Logger extends Utility implements LoggerInterface { input: LogItemMessage, ...extraInput: LogItemExtraInput ): void { - this.processLogItem(24, input, extraInput); + this.processLogItem(this.logLevelThresholds.CRITICAL, input, extraInput); } /** @@ -349,7 +349,7 @@ class Logger extends Utility implements LoggerInterface { * @returns {void} */ public debug(input: LogItemMessage, ...extraInput: LogItemExtraInput): void { - this.processLogItem(8, input, extraInput); + this.processLogItem(this.logLevelThresholds.DEBUG, input, extraInput); } /** @@ -360,7 +360,7 @@ class Logger extends Utility implements LoggerInterface { * @returns {void} */ public error(input: LogItemMessage, ...extraInput: LogItemExtraInput): void { - this.processLogItem(20, input, extraInput); + this.processLogItem(this.logLevelThresholds.ERROR, input, extraInput); } /** @@ -404,7 +404,7 @@ class Logger extends Utility implements LoggerInterface { * @returns {void} */ public info(input: LogItemMessage, ...extraInput: LogItemExtraInput): void { - this.processLogItem(12, input, extraInput); + this.processLogItem(this.logLevelThresholds.INFO, input, extraInput); } /** @@ -645,7 +645,7 @@ class Logger extends Utility implements LoggerInterface { * @returns {void} */ public trace(input: LogItemMessage, ...extraInput: LogItemExtraInput): void { - this.processLogItem(6, input, extraInput); + this.processLogItem(this.logLevelThresholds.TRACE, input, extraInput); } /** @@ -656,7 +656,7 @@ class Logger extends Utility implements LoggerInterface { * @returns {void} */ public warn(input: LogItemMessage, ...extraInput: LogItemExtraInput): void { - this.processLogItem(16, input, extraInput); + this.processLogItem(this.logLevelThresholds.WARN, input, extraInput); } /** @@ -925,7 +925,7 @@ class Logger extends Utility implements LoggerInterface { log.prepareForPrint(); const consoleMethod = - logLevel === 24 + logLevel === this.logLevelThresholds.CRITICAL ? 'error' : (this.getLogLevelNameFromNumber(logLevel).toLowerCase() as keyof Omit< LogFunction, From a5271b8440c4d6146b62c9702329f9da7a8e3b1f Mon Sep 17 00:00:00 2001 From: timo92 Date: Thu, 8 Aug 2024 09:26:34 +0200 Subject: [PATCH 05/12] refactor(logger): reduce code duplicates in test case --- packages/logger/tests/unit/Logger.test.ts | 142 +++------------------- 1 file changed, 18 insertions(+), 124 deletions(-) diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index 78db5d5bc3..dc66e62f89 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -664,11 +664,7 @@ describe('Class: Logger', () => { const methodOfLogger = method as keyof LogFunction; describe('Feature: log level', () => { - test(`when the level is TRACE, it ${traceAction} print to stdout`, () => { - // Prepare - const logger = new Logger({ - logLevel: LogLevel.TRACE, - }); + function testLoggerPrints(logger: Logger, expectPrints: boolean): void { const consoleSpy = jest.spyOn( // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing logger['console'], @@ -678,8 +674,8 @@ describe('Class: Logger', () => { logger[methodOfLogger]('foo'); // Assess - expect(consoleSpy).toBeCalledTimes(tracePrints ? 1 : 0); - if (tracePrints) { + expect(consoleSpy).toBeCalledTimes(expectPrints ? 1 : 0); + if (expectPrints) { expect(consoleSpy).toHaveBeenNthCalledWith( 1, JSON.stringify({ @@ -692,6 +688,15 @@ describe('Class: Logger', () => { }) ); } + } + + test(`when the level is TRACE, it ${traceAction} print to stdout`, () => { + // Prepare + const logger = new Logger({ + logLevel: LogLevel.TRACE, + }); + + testLoggerPrints(logger, tracePrints); }); test(`when the level is DEBUG, it ${debugAction} print to stdout`, () => { @@ -699,29 +704,8 @@ describe('Class: Logger', () => { const logger = new Logger({ logLevel: LogLevel.DEBUG, }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(method) - ); - // Act - logger[methodOfLogger]('foo'); - // Assess - expect(consoleSpy).toBeCalledTimes(debugPrints ? 1 : 0); - if (debugPrints) { - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ - level: methodOfLogger.toUpperCase(), - message: 'foo', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }) - ); - } + testLoggerPrints(logger, debugPrints); }); test(`when the log level is INFO, it ${infoAction} print to stdout`, () => { @@ -729,29 +713,8 @@ describe('Class: Logger', () => { const logger = new Logger({ logLevel: 'INFO', }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - // Act - logger[methodOfLogger]('foo'); - // Assess - expect(consoleSpy).toBeCalledTimes(infoPrints ? 1 : 0); - if (infoPrints) { - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ - level: methodOfLogger.toUpperCase(), - message: 'foo', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }) - ); - } + testLoggerPrints(logger, infoPrints); }); test(`when the log level is WARN, it ${warnAction} print to stdout`, () => { @@ -759,29 +722,8 @@ describe('Class: Logger', () => { const logger = new Logger({ logLevel: LogLevel.WARN, }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - // Act - logger[methodOfLogger]('foo'); - // Assess - expect(consoleSpy).toBeCalledTimes(warnPrints ? 1 : 0); - if (warnPrints) { - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ - level: methodOfLogger.toUpperCase(), - message: 'foo', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }) - ); - } + testLoggerPrints(logger, warnPrints); }); test(`when the log level is ERROR, it ${errorAction} print to stdout`, () => { @@ -789,29 +731,8 @@ describe('Class: Logger', () => { const logger = new Logger({ logLevel: 'ERROR', }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - // Act - logger[methodOfLogger]('foo'); - // Assess - expect(consoleSpy).toBeCalledTimes(errorPrints ? 1 : 0); - if (errorPrints) { - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ - level: methodOfLogger.toUpperCase(), - message: 'foo', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }) - ); - } + testLoggerPrints(logger, errorPrints); }); test('when the log level is SILENT, it DOES NOT print to stdout', () => { @@ -819,43 +740,16 @@ describe('Class: Logger', () => { const logger = new Logger({ logLevel: LogLevel.SILENT, }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - // Act - logger[methodOfLogger]('foo'); - // Assess - expect(consoleSpy).toBeCalledTimes(0); + testLoggerPrints(logger, false); }); test('when the log level is set through POWERTOOLS_LOG_LEVEL env variable, it DOES print to stdout', () => { // Prepare process.env.POWERTOOLS_LOG_LEVEL = methodOfLogger.toUpperCase(); const logger = new Logger(); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - // Act - logger[methodOfLogger]('foo'); - // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ - level: methodOfLogger.toUpperCase(), - message: 'foo', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }) - ); + testLoggerPrints(logger, true); }); }); From b1fe2ae270713d0fae7e7cb15f992d54f4ad57cc Mon Sep 17 00:00:00 2001 From: timo92 Date: Thu, 8 Aug 2024 10:25:20 +0000 Subject: [PATCH 06/12] feat(logger): adjust samplingRate log level change Change log level to debug only if current log level is higher --- packages/logger/src/Logger.ts | 7 ++++++- 1 file changed, 6 insertions(+), 1 deletion(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 1c769793d9..5fa021d48f 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -1062,7 +1062,12 @@ class Logger extends Utility implements LoggerInterface { if (this.isValidSampleRate(value)) { this.powertoolsLogData.sampleRateValue = value; - if (value && randomInt(0, 100) / 100 <= value) { + if ( + this.logLevel > this.logLevelThresholds.DEBUG && + value && + randomInt(0, 100) / 100 <= value + ) { + // only change logLevel if higher than debug, i.e. don't change from e.g. tracing to debug this.setLogLevel('DEBUG'); this.debug('Setting log level to DEBUG due to sampling rate'); } else { From eb578a43c29b6538015d32f7567bf183b86eeec6 Mon Sep 17 00:00:00 2001 From: timo92 Date: Thu, 8 Aug 2024 10:26:10 +0000 Subject: [PATCH 07/12] test(logger): adjust tests for addition of log level TRACE --- packages/logger/tests/unit/Logger.test.ts | 86 ++++++++++++----------- 1 file changed, 46 insertions(+), 40 deletions(-) diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index dc66e62f89..613aaf6e86 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -32,6 +32,7 @@ const getConsoleMethod = ( jest.mock('node:console', () => ({ ...jest.requireActual('node:console'), Console: jest.fn().mockImplementation(() => ({ + trace: jest.fn(), debug: jest.fn(), info: jest.fn(), warn: jest.fn(), @@ -58,6 +59,7 @@ describe('Class: Logger', () => { beforeEach(() => { dateSpy.mockClear(); process.env = { ...ENVIRONMENT_VARIABLES }; + process.env.POWERTOOLS_LOG_LEVEL = 'trace'; }); describe('Method: constructor', () => { @@ -82,7 +84,7 @@ describe('Class: Logger', () => { envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, defaultServiceName: 'service_undefined', - logLevel: 8, + logLevel: logLevelThresholds.TRACE, logFormatter: expect.any(PowertoolsLogFormatter), }) ); @@ -115,7 +117,7 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: 0, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: 8, // 100% sample rate value changes log level to DEBUG + logLevel: logLevelThresholds.DEBUG, // 100% sample rate value changes log level from WARN to DEBUG console: expect.objectContaining({ debug: expect.any(Function), error: expect.any(Function), @@ -200,7 +202,7 @@ describe('Class: Logger', () => { }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, - logLevel: 8, + logLevel: logLevelThresholds.TRACE, logFormatter: expect.any(LogFormatter), }) ); @@ -228,7 +230,7 @@ describe('Class: Logger', () => { }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, - logLevel: 8, + logLevel: logLevelThresholds.TRACE, logFormatter: expect.any(PowertoolsLogFormatter), }) ); @@ -351,7 +353,7 @@ describe('Class: Logger', () => { }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, - logLevel: 8, + logLevel: logLevelThresholds.TRACE, logFormatter: expect.any(PowertoolsLogFormatter), }) ); @@ -456,7 +458,7 @@ describe('Class: Logger', () => { }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, - logLevel: 8, + logLevel: logLevelThresholds.TRACE, logFormatter: expect.any(PowertoolsLogFormatter), }) ); @@ -498,7 +500,7 @@ describe('Class: Logger', () => { }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, - logLevel: 8, + logLevel: logLevelThresholds.TRACE, logFormatter: expect.any(PowertoolsLogFormatter), }) ); @@ -560,7 +562,7 @@ describe('Class: Logger', () => { }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, - logLevel: 8, + logLevel: logLevelThresholds.TRACE, logFormatter: expect.any(PowertoolsLogFormatter), }) ); @@ -793,20 +795,24 @@ describe('Class: Logger', () => { } // Assess - expect(logger.level).toBe(8); + expect(logger.level).toBe(logLevelThresholds.DEBUG); expect(logger.getLevelName()).toBe('DEBUG'); - expect(consoleSpy).toBeCalledTimes(method === 'debug' ? 2 : 1); - expect(consoleSpy).toHaveBeenNthCalledWith( - method === 'debug' ? 2 : 1, - JSON.stringify({ - level: method.toUpperCase(), - message: 'foo', - sampling_rate: 1, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }) - ); + if (method === 'trace') { + expect(consoleSpy).toHaveBeenCalledTimes(0); + } else { + expect(consoleSpy).toBeCalledTimes(method === 'debug' ? 2 : 1); + expect(consoleSpy).toHaveBeenNthCalledWith( + method === 'debug' ? 2 : 1, + JSON.stringify({ + level: method.toUpperCase(), + message: 'foo', + sampling_rate: 1, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + } }); }); @@ -842,7 +848,7 @@ describe('Class: Logger', () => { test(`when the Lambda context is captured, it returns a valid ${method.toUpperCase()} log`, () => { // Prepare const logger = new Logger({ - logLevel: 'DEBUG', + logLevel: 'TRACE', }); logger.addContext(context); const consoleSpy = jest.spyOn( @@ -879,7 +885,7 @@ describe('Class: Logger', () => { describe('Feature: ephemeral log attributes', () => { const logger = new Logger({ - logLevel: 'DEBUG', + logLevel: 'TRACE', }); it.each([ @@ -1092,7 +1098,7 @@ describe('Class: Logger', () => { test('when persistent log attributes are added to the Logger instance, they should appear in all logs printed by the instance', () => { // Prepare const logger = new Logger({ - logLevel: 'DEBUG', + logLevel: 'TRACE', persistentLogAttributes: { aws_account_id: '123456789012', aws_region: 'eu-west-1', @@ -1130,7 +1136,7 @@ describe('Class: Logger', () => { test('when the `_X_AMZN_TRACE_ID` environment variable is set it parses it correctly and adds the Trace ID to the log', () => { // Prepare const logger = new Logger({ - logLevel: 'DEBUG', + logLevel: 'TRACE', }); const consoleSpy = jest.spyOn( // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing @@ -1161,7 +1167,7 @@ describe('Class: Logger', () => { // Prepare process.env._X_AMZN_TRACE_ID = undefined; const logger = new Logger({ - logLevel: 'DEBUG', + logLevel: 'TRACE', }); const consoleSpy = jest.spyOn( // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing @@ -1192,7 +1198,7 @@ describe('Class: Logger', () => { test('when a logged item references itself, the logger ignores the keys that cause a circular reference', () => { // Prepare const logger = new Logger({ - logLevel: 'DEBUG', + logLevel: 'TRACE', }); const consoleSpy = jest.spyOn( // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing @@ -2687,7 +2693,7 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: INDENTATION, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: 8, + logLevel: logLevelThresholds.TRACE, logLevelThresholds: { ...logLevelThresholds, }, @@ -2715,7 +2721,7 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: INDENTATION, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: 8, + logLevel: logLevelThresholds.TRACE, logLevelThresholds: { ...logLevelThresholds, }, @@ -2743,7 +2749,7 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: INDENTATION, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: 8, + logLevel: logLevelThresholds.TRACE, logLevelThresholds: { ...logLevelThresholds, }, @@ -2819,7 +2825,7 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: INDENTATION, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: 8, + logLevel: logLevelThresholds.TRACE, logLevelThresholds: { ...logLevelThresholds, }, @@ -2847,7 +2853,7 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: INDENTATION, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: 8, + logLevel: logLevelThresholds.TRACE, logLevelThresholds: { ...logLevelThresholds, }, @@ -2878,7 +2884,7 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: INDENTATION, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: 8, + logLevel: logLevelThresholds.TRACE, logLevelThresholds: { ...logLevelThresholds, }, @@ -2906,7 +2912,7 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: INDENTATION, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: 20, + logLevel: logLevelThresholds.ERROR, logLevelThresholds: { ...logLevelThresholds, }, @@ -3285,7 +3291,7 @@ describe('Class: Logger', () => { }); // Assess - expect(logger.level).toBe(8); + expect(logger.level).toBe(logLevelThresholds.DEBUG); expect(logger.getLevelName()).toBe('DEBUG'); }); @@ -3305,7 +3311,7 @@ describe('Class: Logger', () => { const logger: Logger = new Logger(loggerOptions); // Assess - expect(logger.level).toBe(8); + expect(logger.level).toBe(logLevelThresholds.DEBUG); expect(logger.getLevelName()).toBe('DEBUG'); }); @@ -3318,7 +3324,7 @@ describe('Class: Logger', () => { }); // Assess - expect(logger.level).toBe(8); + expect(logger.level).toBe(logLevelThresholds.DEBUG); expect(logger.getLevelName()).toBe('DEBUG'); }); @@ -3412,7 +3418,7 @@ describe('Class: Logger', () => { test('when sample rate is set in environmental variable, it should use POWERTOOLS_LOGGER_SAMPLE_RATE value', () => { // Prepare process.env.POWERTOOLS_LOGGER_SAMPLE_RATE = '1'; - const logger: Logger = new Logger(); + const logger: Logger = new Logger({ logLevel: 'WARN' }); const consoleSpy = jest.spyOn( // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing logger['console'], @@ -3422,7 +3428,7 @@ describe('Class: Logger', () => { logger.debug('foo'); // Assess - expect(consoleSpy).toBeCalledTimes(2); + expect(consoleSpy).toHaveBeenCalledTimes(2); expect(consoleSpy).toHaveBeenNthCalledWith( 1, JSON.stringify({ @@ -3585,7 +3591,7 @@ describe('Class: Logger', () => { const debugSpy = jest.spyOn(console, 'debug').mockImplementation(); // Act - new Logger({ sampleRateValue: 1 }); + new Logger({ sampleRateValue: 1, logLevel: 'WARN' }); // Assess expect(debugSpy).toHaveBeenCalledTimes(1); From 9ec8367c74df444099739b1f1f1837d3e2c918e3 Mon Sep 17 00:00:00 2001 From: timo92 Date: Thu, 8 Aug 2024 10:28:44 +0000 Subject: [PATCH 08/12] chore(logger): run lint:fix --- packages/logger/package.json | 9 ++------- 1 file changed, 2 insertions(+), 7 deletions(-) diff --git a/packages/logger/package.json b/packages/logger/package.json index 307a403afa..5438e15918 100644 --- a/packages/logger/package.json +++ b/packages/logger/package.json @@ -53,10 +53,7 @@ "lib/cjs/middleware/middy.d.ts", "lib/esm/middleware/middy.d.ts" ], - "types": [ - "lib/cjs/types/index.d.ts", - "lib/esm/types/index.d.ts" - ] + "types": ["lib/cjs/types/index.d.ts", "lib/esm/types/index.d.ts"] } }, "types": "./lib/cjs/index.d.ts", @@ -73,9 +70,7 @@ "optional": true } }, - "files": [ - "lib" - ], + "files": ["lib"], "repository": { "type": "git", "url": "git+https://github.com/aws-powertools/powertools-lambda-typescript.git" From fbd19092c47324053ad594a46a7fa38ed64ca21a Mon Sep 17 00:00:00 2001 From: timo92 Date: Thu, 8 Aug 2024 11:26:24 +0000 Subject: [PATCH 09/12] refactor(logger): don't print stacktrace when logging with trace --- packages/logger/src/Logger.ts | 5 +++++ packages/logger/tests/unit/Logger.test.ts | 6 ++++-- 2 files changed, 9 insertions(+), 2 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 5fa021d48f..858804a7e2 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -982,6 +982,11 @@ class Logger extends Utility implements LoggerInterface { } else { this.console = console; } + + // patch console.trace to no print stack trace + this.console.trace = (message: string, ...optionalParams: unknown[]) => { + this.console.log(message, ...optionalParams); + }; } /** diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index 613aaf6e86..01a832b425 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -32,7 +32,7 @@ const getConsoleMethod = ( jest.mock('node:console', () => ({ ...jest.requireActual('node:console'), Console: jest.fn().mockImplementation(() => ({ - trace: jest.fn(), + log: jest.fn(), // patched equivalent for trace debug: jest.fn(), info: jest.fn(), warn: jest.fn(), @@ -800,7 +800,9 @@ describe('Class: Logger', () => { if (method === 'trace') { expect(consoleSpy).toHaveBeenCalledTimes(0); } else { - expect(consoleSpy).toBeCalledTimes(method === 'debug' ? 2 : 1); + expect(consoleSpy).toHaveBeenCalledTimes( + method === 'debug' ? 2 : 1 + ); expect(consoleSpy).toHaveBeenNthCalledWith( method === 'debug' ? 2 : 1, JSON.stringify({ From a838d6105064c35d3e4b6e8b0854ab1378932b34 Mon Sep 17 00:00:00 2001 From: timo92 Date: Thu, 15 Aug 2024 09:28:14 +0200 Subject: [PATCH 10/12] chore(logger): Improve comment regarding patching console.trace --- packages/logger/src/Logger.ts | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 858804a7e2..48510a15d1 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -983,7 +983,9 @@ class Logger extends Utility implements LoggerInterface { this.console = console; } - // patch console.trace to no print stack trace + /** + * Patch `console.trace` to avoid printing a stack trace and aligning with AWS Lambda behavior - see #2902 + */ this.console.trace = (message: string, ...optionalParams: unknown[]) => { this.console.log(message, ...optionalParams); }; From ccb0d5633ae8227f19a51b42985a45e8b6b88eec Mon Sep 17 00:00:00 2001 From: timo92 Date: Thu, 15 Aug 2024 09:29:21 +0200 Subject: [PATCH 11/12] chore(logger): Revert lint fixes in package.json --- packages/logger/package.json | 9 +++++++-- 1 file changed, 7 insertions(+), 2 deletions(-) diff --git a/packages/logger/package.json b/packages/logger/package.json index 5438e15918..307a403afa 100644 --- a/packages/logger/package.json +++ b/packages/logger/package.json @@ -53,7 +53,10 @@ "lib/cjs/middleware/middy.d.ts", "lib/esm/middleware/middy.d.ts" ], - "types": ["lib/cjs/types/index.d.ts", "lib/esm/types/index.d.ts"] + "types": [ + "lib/cjs/types/index.d.ts", + "lib/esm/types/index.d.ts" + ] } }, "types": "./lib/cjs/index.d.ts", @@ -70,7 +73,9 @@ "optional": true } }, - "files": ["lib"], + "files": [ + "lib" + ], "repository": { "type": "git", "url": "git+https://github.com/aws-powertools/powertools-lambda-typescript.git" From 799c83e61c133f71fb34253ba5c32fa4272d0dc4 Mon Sep 17 00:00:00 2001 From: timo92 Date: Thu, 15 Aug 2024 10:16:20 +0200 Subject: [PATCH 12/12] test(logger): Don't set LogLevel via env variable for all tests --- packages/logger/tests/unit/Logger.test.ts | 69 ++++++++++++++--------- 1 file changed, 42 insertions(+), 27 deletions(-) diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index 01a832b425..3e9c93bfd9 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -29,6 +29,8 @@ const getConsoleMethod = ( method === 'critical' ? 'error' : (method.toLowerCase() as keyof Omit); +const getLogLevel = (method: string): LogLevelType => + method.toUpperCase() as LogLevelType; jest.mock('node:console', () => ({ ...jest.requireActual('node:console'), Console: jest.fn().mockImplementation(() => ({ @@ -59,7 +61,6 @@ describe('Class: Logger', () => { beforeEach(() => { dateSpy.mockClear(); process.env = { ...ENVIRONMENT_VARIABLES }; - process.env.POWERTOOLS_LOG_LEVEL = 'trace'; }); describe('Method: constructor', () => { @@ -84,7 +85,7 @@ describe('Class: Logger', () => { envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, defaultServiceName: 'service_undefined', - logLevel: logLevelThresholds.TRACE, + logLevel: logLevelThresholds.DEBUG, logFormatter: expect.any(PowertoolsLogFormatter), }) ); @@ -202,7 +203,7 @@ describe('Class: Logger', () => { }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, - logLevel: logLevelThresholds.TRACE, + logLevel: logLevelThresholds.DEBUG, logFormatter: expect.any(LogFormatter), }) ); @@ -230,7 +231,7 @@ describe('Class: Logger', () => { }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, - logLevel: logLevelThresholds.TRACE, + logLevel: logLevelThresholds.DEBUG, logFormatter: expect.any(PowertoolsLogFormatter), }) ); @@ -353,7 +354,7 @@ describe('Class: Logger', () => { }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, - logLevel: logLevelThresholds.TRACE, + logLevel: logLevelThresholds.DEBUG, logFormatter: expect.any(PowertoolsLogFormatter), }) ); @@ -458,7 +459,7 @@ describe('Class: Logger', () => { }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, - logLevel: logLevelThresholds.TRACE, + logLevel: logLevelThresholds.DEBUG, logFormatter: expect.any(PowertoolsLogFormatter), }) ); @@ -500,7 +501,7 @@ describe('Class: Logger', () => { }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, - logLevel: logLevelThresholds.TRACE, + logLevel: logLevelThresholds.DEBUG, logFormatter: expect.any(PowertoolsLogFormatter), }) ); @@ -562,7 +563,7 @@ describe('Class: Logger', () => { }, envVarsService: expect.any(EnvironmentVariablesService), customConfigService: undefined, - logLevel: logLevelThresholds.TRACE, + logLevel: logLevelThresholds.DEBUG, logFormatter: expect.any(PowertoolsLogFormatter), }) ); @@ -731,7 +732,7 @@ describe('Class: Logger', () => { test(`when the log level is ERROR, it ${errorAction} print to stdout`, () => { // Prepare const logger = new Logger({ - logLevel: 'ERROR', + logLevel: LogLevel.ERROR, }); testLoggerPrints(logger, errorPrints); @@ -821,7 +822,9 @@ describe('Class: Logger', () => { describe('Feature: inject context', () => { test(`when the Lambda context is not captured and a string is passed as log message, it should print a valid ${method.toUpperCase()} log`, () => { // Prepare - const logger = new Logger(); + const logger = new Logger({ + logLevel: getLogLevel(method), + }); const consoleSpy = jest.spyOn( // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing logger['console'], @@ -850,7 +853,7 @@ describe('Class: Logger', () => { test(`when the Lambda context is captured, it returns a valid ${method.toUpperCase()} log`, () => { // Prepare const logger = new Logger({ - logLevel: 'TRACE', + logLevel: getLogLevel(method), }); logger.addContext(context); const consoleSpy = jest.spyOn( @@ -887,7 +890,7 @@ describe('Class: Logger', () => { describe('Feature: ephemeral log attributes', () => { const logger = new Logger({ - logLevel: 'TRACE', + logLevel: getLogLevel(method), }); it.each([ @@ -1100,7 +1103,7 @@ describe('Class: Logger', () => { test('when persistent log attributes are added to the Logger instance, they should appear in all logs printed by the instance', () => { // Prepare const logger = new Logger({ - logLevel: 'TRACE', + logLevel: getLogLevel(method), persistentLogAttributes: { aws_account_id: '123456789012', aws_region: 'eu-west-1', @@ -1138,7 +1141,7 @@ describe('Class: Logger', () => { test('when the `_X_AMZN_TRACE_ID` environment variable is set it parses it correctly and adds the Trace ID to the log', () => { // Prepare const logger = new Logger({ - logLevel: 'TRACE', + logLevel: getLogLevel(method), }); const consoleSpy = jest.spyOn( // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing @@ -1169,7 +1172,7 @@ describe('Class: Logger', () => { // Prepare process.env._X_AMZN_TRACE_ID = undefined; const logger = new Logger({ - logLevel: 'TRACE', + logLevel: getLogLevel(method), }); const consoleSpy = jest.spyOn( // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing @@ -1200,7 +1203,7 @@ describe('Class: Logger', () => { test('when a logged item references itself, the logger ignores the keys that cause a circular reference', () => { // Prepare const logger = new Logger({ - logLevel: 'TRACE', + logLevel: getLogLevel(method), }); const consoleSpy = jest.spyOn( // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing @@ -1245,7 +1248,9 @@ describe('Class: Logger', () => { test('when a logged item has BigInt value, it does not throw TypeError', () => { // Prepare - const logger = new Logger(); + const logger = new Logger({ + logLevel: getLogLevel(method), + }); jest.spyOn( // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing logger['console'], @@ -1263,7 +1268,9 @@ describe('Class: Logger', () => { test('when a logged item has a BigInt value, it prints the log with value as a string', () => { // Prepare - const logger = new Logger(); + const logger = new Logger({ + logLevel: getLogLevel(method), + }); const consoleSpy = jest.spyOn( // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing logger['console'], @@ -1293,7 +1300,9 @@ describe('Class: Logger', () => { test('when a logged item has empty string, null, or undefined values, it removes it', () => { // Prepare - const logger = new Logger(); + const logger = new Logger({ + logLevel: getLogLevel(method), + }); const consoleSpy = jest.spyOn( // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing logger['console'], @@ -1333,7 +1342,10 @@ describe('Class: Logger', () => { value: unknown ) => (value instanceof Set ? [...value] : value); - const logger = new Logger({ jsonReplacerFn }); + const logger = new Logger({ + logLevel: getLogLevel(method), + jsonReplacerFn, + }); const consoleSpy = jest.spyOn( // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing logger['console'], @@ -1375,7 +1387,10 @@ describe('Class: Logger', () => { return value; }; - const logger = new Logger({ jsonReplacerFn }); + const logger = new Logger({ + logLevel: getLogLevel(method), + jsonReplacerFn, + }); const consoleSpy = jest.spyOn( // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing logger['console'], @@ -2695,7 +2710,7 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: INDENTATION, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: logLevelThresholds.TRACE, + logLevel: logLevelThresholds.DEBUG, logLevelThresholds: { ...logLevelThresholds, }, @@ -2723,7 +2738,7 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: INDENTATION, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: logLevelThresholds.TRACE, + logLevel: logLevelThresholds.DEBUG, logLevelThresholds: { ...logLevelThresholds, }, @@ -2751,7 +2766,7 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: INDENTATION, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: logLevelThresholds.TRACE, + logLevel: logLevelThresholds.DEBUG, logLevelThresholds: { ...logLevelThresholds, }, @@ -2827,7 +2842,7 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: INDENTATION, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: logLevelThresholds.TRACE, + logLevel: logLevelThresholds.DEBUG, logLevelThresholds: { ...logLevelThresholds, }, @@ -2855,7 +2870,7 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: INDENTATION, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: logLevelThresholds.TRACE, + logLevel: logLevelThresholds.DEBUG, logLevelThresholds: { ...logLevelThresholds, }, @@ -2886,7 +2901,7 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: INDENTATION, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: logLevelThresholds.TRACE, + logLevel: logLevelThresholds.DEBUG, logLevelThresholds: { ...logLevelThresholds, },