From 3041007d2901ee8c696464a4214de21262090b23 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev <sergei@cherniaev.com> Date: Mon, 15 Apr 2024 15:13:38 -0500 Subject: [PATCH 01/14] deprecate setPersistentLogAttributes && persistentLogAttributes, add persistentKeys field --- packages/logger/src/Logger.ts | 8 ++++++++ 1 file changed, 8 insertions(+) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 739e0fdadb..41967d2cc3 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -165,6 +165,12 @@ class Logger extends Utility implements LoggerInterface { SILENT: 28, }; /** + * Constructor option to specify keys that will be persisted in all log items. + */ + private persistentKeys: LogAttributes = {}; + /** + * @deprecated Use `persistentKeys` instead. + * * Persistent log attributes that will be logged in all log items. */ private persistentLogAttributes: LogAttributes = {}; @@ -534,6 +540,8 @@ class Logger extends Utility implements LoggerInterface { } /** + * @deprecated This method is deprecated and will be removed in the future major versions. + * * It sets the given attributes (key-value pairs) to all log items generated by this Logger instance. * Note: this replaces the pre-existing value. * From d2190632ada8ba7700d17a7a2551fd99f52f1cd8 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev <sergei@cherniaev.com> Date: Mon, 15 Apr 2024 15:42:33 -0500 Subject: [PATCH 02/14] update types for logger constructor options to mutually exclude persistentLogAttributes && persistentKeys --- packages/logger/src/types/Logger.ts | 29 +++++++++++++++++++++++++++-- 1 file changed, 27 insertions(+), 2 deletions(-) diff --git a/packages/logger/src/types/Logger.ts b/packages/logger/src/types/Logger.ts index fdeb41d4e3..258c468897 100644 --- a/packages/logger/src/types/Logger.ts +++ b/packages/logger/src/types/Logger.ts @@ -21,16 +21,41 @@ type InjectLambdaContextOptions = { clearState?: boolean; }; -type ConstructorOptions = { +type BaseConstructorOptions = { logLevel?: LogLevel; serviceName?: string; sampleRateValue?: number; logFormatter?: LogFormatterInterface; customConfigService?: ConfigServiceInterface; - persistentLogAttributes?: LogAttributes; environment?: Environment; }; +type PersistentKeysOption = { + persistentKeys?: LogAttributes; + persistentLogAttributes?: never; +}; + +type DeprecatedOption = { + persistentLogAttributes?: LogAttributes; + persistentKeys?: never; +}; + +/** + * Options for the Logger class constructor. + * + * @type {Object} ConstructorOptions + * @property {LogLevel} [logLevel] - The log level. + * @property {string} [serviceName] - The service name. + * @property {number} [sampleRateValue] - The sample rate value. + * @property {LogFormatterInterface} [logFormatter] - The custom log formatter. + * @property {ConfigServiceInterface} [customConfigService] - The custom config service. + * @property {Environment} [environment] - The environment. + * @property {LogAttributes} [persistentKeys] - The keys that will be persisted in all log items. + * @property {LogAttributes} [persistentLogAttributes] - **Deprecated!** Use `persistentKeys`. + */ +type ConstructorOptions = BaseConstructorOptions & + (PersistentKeysOption | DeprecatedOption); + type LambdaFunctionContext = Pick< Context, | 'functionName' From 45399f9ed9d159ba1fab31558ffd6de7b9d556b5 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev <sergei@cherniaev.com> Date: Tue, 16 Apr 2024 20:05:31 -0500 Subject: [PATCH 03/14] add persistentKeys constructor option, add unit tests, handle usage of both persistentKeys and persistentLogAttributes --- packages/logger/src/Logger.ts | 17 +++--- packages/logger/tests/unit/Logger.test.ts | 64 +++++++++++++++++++++++ 2 files changed, 73 insertions(+), 8 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 41967d2cc3..1cccd02d68 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -165,12 +165,6 @@ class Logger extends Utility implements LoggerInterface { SILENT: 28, }; /** - * Constructor option to specify keys that will be persisted in all log items. - */ - private persistentKeys: LogAttributes = {}; - /** - * @deprecated Use `persistentKeys` instead. - * * Persistent log attributes that will be logged in all log items. */ private persistentLogAttributes: LogAttributes = {}; @@ -1031,13 +1025,20 @@ class Logger extends Utility implements LoggerInterface { serviceName, sampleRateValue, logFormatter, - persistentLogAttributes, + persistentKeys, + persistentLogAttributes, // deprecated in favor of persistentKeys environment, } = options; + if (persistentLogAttributes && persistentKeys) { + throw new Error( + `Both persistentLogAttributes and persistentKeys options are provided. Use only persistentKeys as persistentLogAttributes is deprecated.` + ); + } + // configurations that affect log content this.setPowertoolsLogData(serviceName, environment); - this.addPersistentLogAttributes(persistentLogAttributes); + this.addPersistentLogAttributes(persistentKeys || persistentLogAttributes); // configurations that affect Logger behavior this.setLogEvent(); diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index 0d79edd22a..ab0b7d5546 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -451,6 +451,70 @@ describe('Class: Logger', () => { ); }); + test('when custom persistentKeys is passed, returns a Logger instance with the correct properties', () => { + // Prepare + const loggerOptions: ConstructorOptions = { + persistentKeys: { + aws_account_id: '123456789012', + aws_region: 'eu-west-1', + logger: { + name: 'aws-lambda-powertool-typescript', + version: '0.2.4', + }, + }, + }; + + // Act + const logger = new Logger(loggerOptions); + + // Assess + expect(logger).toBeInstanceOf(Logger); + expect(logger).toEqual( + expect.objectContaining({ + persistentLogAttributes: { + aws_account_id: '123456789012', + aws_region: 'eu-west-1', + logger: { + name: 'aws-lambda-powertool-typescript', + version: '0.2.4', + }, + }, + powertoolsLogData: { + sampleRateValue: 0, + awsRegion: 'eu-west-1', + environment: '', + serviceName: 'hello-world', + }, + envVarsService: expect.any(EnvironmentVariablesService), + customConfigService: undefined, + logLevel: 8, + logFormatter: expect.any(PowertoolsLogFormatter), + }) + ); + }); + + test('it throws when both persistentKeys and persistentLogAttributes are used in the constructor', () => { + // Prepare + type TestConstructorOptions = { + persistentLogAttributes?: Record<string, string>; + persistentKeys?: Record<string, string>; + }; + + const loggerOptions: TestConstructorOptions = { + persistentKeys: { + foo: 'bar', + }, + persistentLogAttributes: { + foo: 'bar', + }, + }; + + // Act & Assess + expect(() => new Logger(loggerOptions as ConstructorOptions)).toThrow( + 'Both persistentLogAttributes and persistentKeys options are provided. Use only persistentKeys as persistentLogAttributes is deprecated.' + ); + }); + test('when a custom environment is passed, returns a Logger instance with the correct properties', () => { // Prepare const loggerOptions: ConstructorOptions = { From 55418255633bb018af2b53595f9eac3dda0e1e93 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev <sergei@cherniaev.com> Date: Sun, 21 Apr 2024 23:20:39 -0500 Subject: [PATCH 04/14] add clearState method, change internal logic with appendKeys treating as temporary keys, add tests --- packages/logger/src/Logger.ts | 83 ++++++-- packages/logger/tests/unit/Logger.test.ts | 226 +++++++++++++++++++--- 2 files changed, 266 insertions(+), 43 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 1cccd02d68..51e8281313 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -178,6 +178,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. */ + /** + * Temporary log attributes that can be appended with `appendKeys()` method. + */ + private temporaryLogAttributes: LogAttributes = {}; #buffer: [number, Parameters<Logger['createAndPopulateLogItem']>][] = []; /** * Flag used to determine if the logger is initialized. @@ -234,7 +238,7 @@ class Logger extends Utility implements LoggerInterface { } /** - * It adds the given attributes (key-value pairs) to all log items generated by this Logger instance. + * It adds the given persistent attributes (key-value pairs) to all log items generated by this Logger instance. * * @param {LogAttributes} attributes * @returns {void} @@ -244,13 +248,32 @@ class Logger extends Utility implements LoggerInterface { } /** - * Alias for addPersistentLogAttributes. + * It adds the given temporary attributes (key-value pairs) to all log items generated by this Logger instance. + * + * @param {LogAttributes} attributes + * @returns {void} + */ + public addTemporaryLogAttributes(attributes?: LogAttributes): void { + merge(this.temporaryLogAttributes, attributes); + } + + /** + * Alias for addTemporaryLogAttributes. * * @param {LogAttributes} attributes * @returns {void} */ public appendKeys(attributes?: LogAttributes): void { - this.addPersistentLogAttributes(attributes); + this.addTemporaryLogAttributes(attributes); + } + + /** + * It clears temporary log attributes. + * + * @returns {void} + */ + public clearState(): void { + this.temporaryLogAttributes = {}; } /** @@ -274,6 +297,7 @@ class Logger extends Utility implements LoggerInterface { customConfigService: this.getCustomConfigService(), environment: this.powertoolsLogData.environment, persistentLogAttributes: this.persistentLogAttributes, + temporaryLogAttributes: this.temporaryLogAttributes, }, options ) @@ -354,6 +378,16 @@ class Logger extends Utility implements LoggerInterface { return this.persistentLogAttributes; } + /** + * It returns the temporary log attributes, added with `appendKeys()` method. + * + * @private + * @returns {LogAttributes} + */ + public getTemporaryLogAttributes(): LogAttributes { + return this.temporaryLogAttributes; + } + /** * It prints a log item with level INFO. * @@ -417,11 +451,8 @@ class Logger extends Utility implements LoggerInterface { context, callback ) { - let initialPersistentAttributes = {}; if (options && options.clearState === true) { - initialPersistentAttributes = { - ...loggerRef.getPersistentLogAttributes(), - }; + loggerRef.clearState(); } Logger.injectLambdaContextBefore(loggerRef, event, context, options); @@ -434,7 +465,7 @@ class Logger extends Utility implements LoggerInterface { } finally { Logger.injectLambdaContextAfterOrOnError( loggerRef, - initialPersistentAttributes, + loggerRef.getPersistentLogAttributes(), options ); } @@ -446,11 +477,12 @@ class Logger extends Utility implements LoggerInterface { public static injectLambdaContextAfterOrOnError( logger: Logger, - initialPersistentAttributes: LogAttributes, + persistentAttributes: LogAttributes, options?: InjectLambdaContextOptions ): void { if (options && options.clearState === true) { - logger.setPersistentLogAttributes(initialPersistentAttributes); + logger.clearState(); + logger.addPersistentLogAttributes(persistentAttributes); } } @@ -500,10 +532,11 @@ class Logger extends Utility implements LoggerInterface { */ public removeKeys(keys: string[]): void { this.removePersistentLogAttributes(keys); + this.removeTemporaryLogAttributes(keys); } /** - * It removes attributes based on provided keys to all log items generated by this Logger instance. + * It removes persistent attributes based on provided keys to all log items generated by this Logger instance. * * @param {string[]} keys * @returns {void} @@ -516,6 +549,20 @@ class Logger extends Utility implements LoggerInterface { } } + /** + * It removes temporary attributes based on provided keys to all log items generated by this Logger instance. + * + * @param {string[]} keys + * @returns {void} + */ + public removeTemporaryLogAttributes(keys: string[]): void { + for (const key of keys) { + if (this.temporaryLogAttributes && key in this.temporaryLogAttributes) { + delete this.temporaryLogAttributes[key]; + } + } + } + /** * Set the log level for this Logger instance. * @@ -667,8 +714,11 @@ class Logger extends Utility implements LoggerInterface { ...this.getPowertoolsLogData(), }; - // gradually merge additional attributes starting from customer-provided persistent attributes - let additionalLogAttributes = { ...this.getPersistentLogAttributes() }; + // gradually merge additional attributes starting from customer-provided persistent & temporary attributes + let additionalLogAttributes = { + ...this.getPersistentLogAttributes(), + ...this.getTemporaryLogAttributes(), + }; // if the main input is not a string, then it's an object with additional attributes, so we merge it additionalLogAttributes = merge(additionalLogAttributes, otherInput); // then we merge the extra input attributes (if any) @@ -1037,8 +1087,11 @@ class Logger extends Utility implements LoggerInterface { } // configurations that affect log content - this.setPowertoolsLogData(serviceName, environment); - this.addPersistentLogAttributes(persistentKeys || persistentLogAttributes); + this.setPowertoolsLogData( + serviceName, + environment, + persistentKeys || persistentLogAttributes + ); // configurations that affect Logger behavior this.setLogEvent(); diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index ab0b7d5546..4836dec69d 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -123,6 +123,7 @@ describe('Class: Logger', () => { persistentLogAttributes: { awsAccountId: '123456789', }, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: 'prod', @@ -162,6 +163,7 @@ describe('Class: Logger', () => { ...logLevelThresholds, }, persistentLogAttributes: {}, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -312,6 +314,7 @@ describe('Class: Logger', () => { ...logLevelThresholds, }, persistentLogAttributes: {}, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -1376,7 +1379,7 @@ describe('Class: Logger', () => { }); describe('Method: appendKeys', () => { - test('when called, it populates the logger persistentLogAttributes property', () => { + test('when called, it populates the logger temporaryLogAttributes property', () => { // Prepare const logger = new Logger(); @@ -1393,7 +1396,7 @@ describe('Class: Logger', () => { // Assess expect(logger).toEqual( expect.objectContaining({ - persistentLogAttributes: { + temporaryLogAttributes: { aws_account_id: '123456789012', aws_region: 'eu-west-1', logger: { @@ -1435,26 +1438,61 @@ describe('Class: Logger', () => { // Assess expect(logger).toEqual( expect.objectContaining({ - persistentLogAttributes: { + temporaryLogAttributes: { duplicateKey: 'two', }, }) ); }); + + test('when called with the same key as in persistentKeys container option, persistent keys will be overwritten', () => { + // Prepare + const logger = new Logger({ + persistentKeys: { + aws_account_id: '1234567890', + }, + }); + + logger.appendKeys({ + aws_account_id: '0987654321', + }); + + const consoleSpy = jest.spyOn(logger['console'], 'info'); + + // Act + logger.info('This is an INFO log with some log attributes'); + + // Assess + expect(consoleSpy).toHaveBeenCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith( + 1, + JSON.stringify({ + level: 'INFO', + message: 'This is an INFO log with some log attributes', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + aws_account_id: '0987654321', + }) + ); + }); }); describe('Method: removeKeys', () => { test('when called, it removes keys from the logger persistentLogAttributes property', () => { // Prepare - const logger = new Logger(); - logger.appendKeys({ - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', + const loggerOptions: ConstructorOptions = { + persistentKeys: { + aws_account_id: '123456789012', + aws_region: 'eu-west-1', + logger: { + name: 'aws-lambda-powertool-typescript', + version: '0.2.4', + }, }, - }); + }; + const logger = new Logger(loggerOptions); // Act logger.removeKeys(['aws_account_id', 'aws_region']); @@ -1492,7 +1530,7 @@ describe('Class: Logger', () => { expect(logger).toEqual(loggerBeforeKeysAreRemoved); expect(logger).toEqual( expect.objectContaining({ - persistentLogAttributes: { + temporaryLogAttributes: { aws_account_id: '123456789012', aws_region: 'eu-west-1', logger: { @@ -1523,7 +1561,7 @@ describe('Class: Logger', () => { // Assess expect(logger).toEqual( expect.objectContaining({ - persistentLogAttributes: { + temporaryLogAttributes: { logger: { name: 'aws-lambda-powertool-typescript', version: '0.2.4', @@ -1694,7 +1732,52 @@ describe('Class: Logger', () => { ); }); - test('when clearState is enabled, the persistent log attributes added in the handler are cleared when the method returns', async () => { + test('when enabled, it clears all the log attributes added with appendKeys() inside and outside of the handler function', async () => { + // Prepare + const logger = new Logger({ + logLevel: 'DEBUG', + }); + logger.appendKeys({ + foo: 'bar', + biz: 'baz', + }); + + class LambdaFunction implements LambdaInterface { + @logger.injectLambdaContext({ clearState: true }) + public async handler<TEvent>( + _event: TEvent, + _context: Context + ): Promise<void> { + // Only add these persistent for the scope of this lambda handler + logger.appendKeys({ + details: { user_id: '1234' }, + }); + logger.debug('This is a DEBUG log with the user_id'); + logger.debug('This is another DEBUG log with the user_id'); + } + } + const handlerClass = new LambdaFunction(); + const handler = handlerClass.handler.bind(handlerClass); + + const temporaryAttribsBeforeInvocation = { + ...logger.getTemporaryLogAttributes(), + }; + + // Act + await handler(event, context); + + // Assess + expect(temporaryAttribsBeforeInvocation).toEqual({ + foo: 'bar', + biz: 'baz', + }); + const temporaryAttribsAfterInvocation = { + ...logger.getTemporaryLogAttributes(), + }; + expect(temporaryAttribsAfterInvocation).toEqual({}); + }); + + test('when clearState is enabled, the persistent log attributes added in the handler ARE NOT cleared when the method returns', async () => { // Prepare const logger = new Logger({ logLevel: 'DEBUG', @@ -1709,8 +1792,8 @@ describe('Class: Logger', () => { _event: TEvent, _context: Context ): Promise<void> { - // Only add these persistent for the scope of this lambda handler - logger.appendKeys({ + // These persistent attributes stay persistent + logger.addPersistentLogAttributes({ details: { user_id: '1234' }, }); logger.debug('This is a DEBUG log with the user_id'); @@ -1734,12 +1817,79 @@ describe('Class: Logger', () => { foo: 'bar', biz: 'baz', }); - expect(persistentAttribsAfterInvocation).toEqual( - persistentAttribsBeforeInvocation - ); + expect(persistentAttribsAfterInvocation).toEqual({ + foo: 'bar', + biz: 'baz', + details: { user_id: '1234' }, + }); + }); + + test('when clearState is enabled, persistent log attributes added in the handler stay persistent, but temporary added in the handler are cleared when the method returns', async () => { + // Prepare + const logger = new Logger({ + logLevel: 'DEBUG', + persistentKeys: { + foo: 'bar', + biz: 'baz', + }, + }); + logger.appendKeys({ + type: 'temporary', + }); + + class LambdaFunction implements LambdaInterface { + @logger.injectLambdaContext({ clearState: true }) + public async handler<TEvent>( + _event: TEvent, + _context: Context + ): Promise<void> { + // These persistent attributes stay persistent + logger.addPersistentLogAttributes({ + type: 'persistent', + }); + logger.debug( + 'This is a DEBUG log with both pesistent and temporary keys' + ); + logger.debug( + 'This is another DEBUG log with both pesistent and temporary keys' + ); + } + } + const handlerClass = new LambdaFunction(); + const handler = handlerClass.handler.bind(handlerClass); + const persistentAttribsBeforeInvocation = { + ...logger.getPersistentLogAttributes(), + }; + const temporaryAttribsBeforeInvocation = { + ...logger.getTemporaryLogAttributes(), + }; + + // Act + await handler(event, context); + const persistentAttribsAfterInvocation = { + ...logger.getPersistentLogAttributes(), + }; + const temporaryAttribsAfterInvocation = { + ...logger.getTemporaryLogAttributes(), + }; + + // Assess + expect(persistentAttribsBeforeInvocation).toEqual({ + foo: 'bar', + biz: 'baz', + }); + expect(persistentAttribsAfterInvocation).toEqual({ + foo: 'bar', + biz: 'baz', + type: 'persistent', + }); + expect(temporaryAttribsBeforeInvocation).toEqual({ + type: 'temporary', + }); + expect(temporaryAttribsAfterInvocation).toEqual({}); }); - test('when clearState is enabled, the persistent log attributes added in the handler are cleared when the method throws', async () => { + test('when clearState is enabled, the temporary log attributes added in the handler are cleared when the method throws', async () => { // Prepare const logger = new Logger({ logLevel: 'DEBUG', @@ -1748,14 +1898,17 @@ describe('Class: Logger', () => { biz: 'baz', }, }); + logger.appendKeys({ + type: 'temporary', + }); class LambdaFunction implements LambdaInterface { @logger.injectLambdaContext({ clearState: true }) public async handler<TEvent>( _event: TEvent, _context: Context ): Promise<string> { - // Only add these persistent for the scope of this lambda handler - logger.appendKeys({ + // These persistent attributes stay persistent + logger.addPersistentLogAttributes({ details: { user_id: '1234' }, }); logger.debug('This is a DEBUG log with the user_id'); @@ -1769,6 +1922,9 @@ describe('Class: Logger', () => { const persistentAttribsBeforeInvocation = { ...logger.getPersistentLogAttributes(), }; + const temporaryAttribsBeforeInvocation = { + ...logger.getTemporaryLogAttributes(), + }; // Act & Assess await expect(handler(event, context)).rejects.toThrow(); @@ -1779,9 +1935,16 @@ describe('Class: Logger', () => { foo: 'bar', biz: 'baz', }); - expect(persistentAttribsAfterInvocation).toEqual( - persistentAttribsBeforeInvocation - ); + expect(persistentAttribsAfterInvocation).toEqual({ + foo: 'bar', + biz: 'baz', + details: { user_id: '1234' }, + }); + const temporaryAttribsAfterInvocation = { + ...logger.getTemporaryLogAttributes(), + }; + expect(temporaryAttribsBeforeInvocation).toEqual({ type: 'temporary' }); + expect(temporaryAttribsAfterInvocation).toEqual({}); }); test('when logEvent is enabled, it logs the event in the first log', async () => { @@ -1973,10 +2136,10 @@ describe('Class: Logger', () => { ); }); - test('when logEvent and clearState are both TRUE, and the logger has persistent attributes, any key added in the handler is cleared properly', async () => { + test('when logEvent and clearState are both TRUE, and the logger has persistent attributes, any key added with appendKeys() in the handler is cleared properly', async () => { // Prepare const logger = new Logger({ - persistentLogAttributes: { + persistentKeys: { version: '1.0.0', }, }); @@ -2073,6 +2236,7 @@ describe('Class: Logger', () => { ...logLevelThresholds, }, persistentLogAttributes: {}, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -2100,6 +2264,7 @@ describe('Class: Logger', () => { ...logLevelThresholds, }, persistentLogAttributes: {}, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -2127,6 +2292,7 @@ describe('Class: Logger', () => { ...logLevelThresholds, }, persistentLogAttributes: {}, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -2202,6 +2368,7 @@ describe('Class: Logger', () => { ...logLevelThresholds, }, persistentLogAttributes: {}, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -2232,6 +2399,7 @@ describe('Class: Logger', () => { extra: 'This is an attribute that will be logged only by the child logger', }, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -2259,6 +2427,7 @@ describe('Class: Logger', () => { ...logLevelThresholds, }, persistentLogAttributes: {}, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -2286,6 +2455,7 @@ describe('Class: Logger', () => { ...logLevelThresholds, }, persistentLogAttributes: {}, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -2301,7 +2471,7 @@ describe('Class: Logger', () => { const childLogger = parentLogger.createChild(); // Act - parentLogger.appendKeys({ + parentLogger.addPersistentLogAttributes({ aws_account_id: '123456789012', aws_region: 'eu-west-1', logger: { From f1f33e8c64cd78d605fdd50a557fc995703f025e Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev <sergei@cherniaev.com> Date: Sun, 21 Apr 2024 23:21:55 -0500 Subject: [PATCH 05/14] change clear state logic for middleware, add tests --- packages/logger/src/middleware/middy.ts | 13 +-- .../tests/unit/middleware/middy.test.ts | 106 ++++++++++++++++-- 2 files changed, 102 insertions(+), 17 deletions(-) diff --git a/packages/logger/src/middleware/middy.ts b/packages/logger/src/middleware/middy.ts index 4e970e55a9..c93f1838ef 100644 --- a/packages/logger/src/middleware/middy.ts +++ b/packages/logger/src/middleware/middy.ts @@ -1,5 +1,4 @@ import { Logger } from '../Logger.js'; -import type { LogAttributes } from '../types/Log.js'; import type { InjectLambdaContextOptions } from '../types/Logger.js'; import { LOGGER_KEY } from '@aws-lambda-powertools/commons'; import type { @@ -37,7 +36,6 @@ const injectLambdaContext = ( options?: InjectLambdaContextOptions ): MiddlewareLikeObj => { const loggers = target instanceof Array ? target : [target]; - const persistentAttributes: LogAttributes[] = []; const isClearState = options && options.clearState === true; /** @@ -55,12 +53,8 @@ const injectLambdaContext = ( const injectLambdaContextBefore = async ( request: MiddyLikeRequest ): Promise<void> => { - loggers.forEach((logger: Logger, index: number) => { + loggers.forEach((logger: Logger) => { if (isClearState) { - persistentAttributes[index] = { - ...logger.getPersistentLogAttributes(), - }; - setCleanupFunction(request); } Logger.injectLambdaContextBefore( @@ -74,10 +68,11 @@ const injectLambdaContext = ( const injectLambdaContextAfterOrOnError = async (): Promise<void> => { if (isClearState) { - loggers.forEach((logger: Logger, index: number) => { + loggers.forEach((logger: Logger) => { + logger.clearState(); Logger.injectLambdaContextAfterOrOnError( logger, - persistentAttributes[index], + logger.getPersistentLogAttributes(), options ); }); diff --git a/packages/logger/tests/unit/middleware/middy.test.ts b/packages/logger/tests/unit/middleware/middy.test.ts index 532b923c03..275e6d7b79 100644 --- a/packages/logger/tests/unit/middleware/middy.test.ts +++ b/packages/logger/tests/unit/middleware/middy.test.ts @@ -97,7 +97,44 @@ describe('Middy middleware', () => { }); describe('Feature: clear state', () => { - test('when enabled, the persistent log attributes added within the handler scope are removed after the invocation ends', async () => { + test('when enabled, it clears all the log attributes added with appendKeys() inside and outside of the handler function', async () => { + // Prepare + const logger = new Logger({ + logLevel: 'DEBUG', + }); + logger.appendKeys({ + foo: 'bar', + biz: 'baz', + }); + + const handler = middy((): void => { + // Only add these persistent for the scope of this lambda handler + logger.appendKeys({ + details: { user_id: '1234' }, + }); + logger.debug('This is a DEBUG log with the user_id'); + logger.debug('This is another DEBUG log with the user_id'); + }).use(injectLambdaContext(logger, { clearState: true })); + + const temporaryAttribsBeforeInvocation = { + ...logger.getTemporaryLogAttributes(), + }; + + // Act + await handler(event, context); + + // Assess + expect(temporaryAttribsBeforeInvocation).toEqual({ + foo: 'bar', + biz: 'baz', + }); + const temporaryAttribsAfterInvocation = { + ...logger.getTemporaryLogAttributes(), + }; + expect(temporaryAttribsAfterInvocation).toEqual({}); + }); + + test('when enabled, the temporary log attributes added within the handler scope are removed after the invocation ends', async () => { // Prepare const logger = new Logger({ logLevel: 'DEBUG', @@ -106,9 +143,12 @@ describe('Middy middleware', () => { biz: 'baz', }, }); + logger.appendKeys({ + type: 'temporary', + }); const handler = middy((): void => { - // Only add these persistent for the scope of this lambda handler + // These keys stay only in the scope of this lambda handler logger.appendKeys({ details: { user_id: '1234' }, }); @@ -118,6 +158,9 @@ describe('Middy middleware', () => { const persistentAttribsBeforeInvocation = { ...logger.getPersistentLogAttributes(), }; + const temporaryAttribsBeforeInvocation = { + ...logger.getTemporaryLogAttributes(), + }; // Act await handler(event, context); @@ -133,9 +176,14 @@ describe('Middy middleware', () => { expect(persistentAttribsAfterInvocation).toEqual( persistentAttribsBeforeInvocation ); + expect(temporaryAttribsBeforeInvocation).toEqual({ type: 'temporary' }); + const temporaryAttribsAfterInvocation = { + ...logger.getTemporaryLogAttributes(), + }; + expect(temporaryAttribsAfterInvocation).toEqual({}); }); - test('when enabled, the persistent log attributes added within the handler scope are removed after the invocation ends even if an error is thrown', async () => { + test('when enabled, the persistent log attributes added within the handler scope ARE NOT removed after the invocation ends', async () => { // Prepare const logger = new Logger({ logLevel: 'DEBUG', @@ -144,9 +192,49 @@ describe('Middy middleware', () => { biz: 'baz', }, }); + const handler = middy((): void => { - // Only add these persistent for the scope of this lambda handler - logger.appendKeys({ + // These persistent attributes stay persistent + logger.addPersistentLogAttributes({ + details: { user_id: '1234' }, + }); + logger.debug('This is a DEBUG log with the user_id'); + logger.debug('This is another DEBUG log with the user_id'); + }).use(injectLambdaContext(logger, { clearState: true })); + const persistentAttribsBeforeInvocation = { + ...logger.getPersistentLogAttributes(), + }; + + // Act + await handler(event, context); + + // Assess + const persistentAttribsAfterInvocation = { + ...logger.getPersistentLogAttributes(), + }; + expect(persistentAttribsBeforeInvocation).toEqual({ + foo: 'bar', + biz: 'baz', + }); + expect(persistentAttribsAfterInvocation).toEqual({ + foo: 'bar', + biz: 'baz', + details: { user_id: '1234' }, + }); + }); + + test('when enabled, the persistent log attributes added within the handler scope ARE NOT removed after the invocation ends even if an error is thrown', async () => { + // Prepare + const logger = new Logger({ + logLevel: 'DEBUG', + persistentLogAttributes: { + foo: 'bar', + biz: 'baz', + }, + }); + const handler = middy((): void => { + // These persistent attributes stay persistent + logger.addPersistentLogAttributes({ details: { user_id: '1234' }, }); logger.debug('This is a DEBUG log with the user_id'); @@ -167,9 +255,11 @@ describe('Middy middleware', () => { foo: 'bar', biz: 'baz', }); - expect(persistentAttribsAfterInvocation).toEqual( - persistentAttribsBeforeInvocation - ); + expect(persistentAttribsAfterInvocation).toEqual({ + foo: 'bar', + biz: 'baz', + details: { user_id: '1234' }, + }); }); test('when enabled, and another middleware returns early, it still clears the state', async () => { From 55fbc0713bf15b33b3ee4d6f59ab092312e57951 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev <sergei@cherniaev.com> Date: Fri, 26 Apr 2024 21:41:10 -0500 Subject: [PATCH 06/14] move merging temporary attrs logic to appendKeys() --- packages/logger/src/Logger.ts | 12 +----------- 1 file changed, 1 insertion(+), 11 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 51e8281313..e731ae329d 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -247,16 +247,6 @@ class Logger extends Utility implements LoggerInterface { merge(this.persistentLogAttributes, attributes); } - /** - * It adds the given temporary attributes (key-value pairs) to all log items generated by this Logger instance. - * - * @param {LogAttributes} attributes - * @returns {void} - */ - public addTemporaryLogAttributes(attributes?: LogAttributes): void { - merge(this.temporaryLogAttributes, attributes); - } - /** * Alias for addTemporaryLogAttributes. * @@ -264,7 +254,7 @@ class Logger extends Utility implements LoggerInterface { * @returns {void} */ public appendKeys(attributes?: LogAttributes): void { - this.addTemporaryLogAttributes(attributes); + merge(this.temporaryLogAttributes, attributes); } /** From 2e8c71f611778fab25f7c57d270944a49086dd87 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev <sergei@cherniaev.com> Date: Fri, 26 Apr 2024 22:07:02 -0500 Subject: [PATCH 07/14] remove redundant calls --- packages/logger/src/Logger.ts | 4 ---- packages/logger/src/middleware/middy.ts | 5 ----- 2 files changed, 9 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index e731ae329d..c6d218fa2e 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -441,10 +441,6 @@ class Logger extends Utility implements LoggerInterface { context, callback ) { - if (options && options.clearState === true) { - loggerRef.clearState(); - } - Logger.injectLambdaContextBefore(loggerRef, event, context, options); let result: unknown; diff --git a/packages/logger/src/middleware/middy.ts b/packages/logger/src/middleware/middy.ts index c93f1838ef..92f2addae2 100644 --- a/packages/logger/src/middleware/middy.ts +++ b/packages/logger/src/middleware/middy.ts @@ -70,11 +70,6 @@ const injectLambdaContext = ( if (isClearState) { loggers.forEach((logger: Logger) => { logger.clearState(); - Logger.injectLambdaContextAfterOrOnError( - logger, - logger.getPersistentLogAttributes(), - options - ); }); } }; From b7d14eefb2e27ea03d7ae975967878a4bab9fc78 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev <sergei@cherniaev.com> Date: Wed, 1 May 2024 22:36:37 -0500 Subject: [PATCH 08/14] switch to console warning, when both persistentLogAttributes and persistentKeys are used in constructor, update tests --- packages/logger/src/Logger.ts | 4 ++-- packages/logger/tests/unit/Logger.test.ts | 26 +++++++++++++++++------ 2 files changed, 21 insertions(+), 9 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index c6d218fa2e..ffd9984bc5 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -1067,8 +1067,8 @@ class Logger extends Utility implements LoggerInterface { } = options; if (persistentLogAttributes && persistentKeys) { - throw new Error( - `Both persistentLogAttributes and persistentKeys options are provided. Use only persistentKeys as persistentLogAttributes is deprecated.` + this.warn( + 'Both persistentLogAttributes and persistentKeys options were provided. Using persistentKeys as persistentLogAttributes is deprecated and will be removed in future releases' ); } diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index 4836dec69d..a68f06cfa4 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -496,8 +496,12 @@ describe('Class: Logger', () => { ); }); - test('it throws when both persistentKeys and persistentLogAttributes are used in the constructor', () => { + test('it emits a warning when both persistentKeys and persistentLogAttributes are used in the constructor', () => { // Prepare + // Since the buffer is private and we are bypassing the public warn method, we need to spy on the console.warn + process.env.POWERTOOLS_DEV = 'true'; + const warningSpy = jest.spyOn(console, 'warn').mockImplementation(); + type TestConstructorOptions = { persistentLogAttributes?: Record<string, string>; persistentKeys?: Record<string, string>; @@ -512,10 +516,18 @@ describe('Class: Logger', () => { }, }; - // Act & Assess - expect(() => new Logger(loggerOptions as ConstructorOptions)).toThrow( - 'Both persistentLogAttributes and persistentKeys options are provided. Use only persistentKeys as persistentLogAttributes is deprecated.' + // Act + new Logger(loggerOptions as ConstructorOptions); + + // Assess + expect(warningSpy).toHaveBeenCalledTimes(1); + expect(warningSpy).toHaveBeenCalledWith( + expect.stringContaining( + 'Both persistentLogAttributes and persistentKeys options were provided. Using persistentKeys as persistentLogAttributes is deprecated and will be removed in future releases' + ) ); + // Cleanup + warningSpy.mockRestore(); }); test('when a custom environment is passed, returns a Logger instance with the correct properties', () => { @@ -2764,7 +2776,7 @@ describe('Class: Logger', () => { ); }); - it('uses log level set by ALC & emits a warning when setting a higher log level than ALC', () => { + test('it uses log level set by ALC & emits a warning when setting a higher log level than ALC', () => { // Prepare process.env.AWS_LAMBDA_LOG_LEVEL = 'ERROR'; process.env.LOG_LEVEL = undefined; @@ -2784,7 +2796,7 @@ describe('Class: Logger', () => { ); }); - it('uses log level set by ALC & emits a warning when initializing with a higher log level than ALC', () => { + test('it uses log level set by ALC & emits a warning when initializing with a higher log level than ALC', () => { // Prepare process.env.AWS_LAMBDA_LOG_LEVEL = 'INFO'; process.env.LOG_LEVEL = undefined; @@ -3082,7 +3094,7 @@ describe('Class: Logger', () => { ); }); - it('logs a DEBUG log when the sample rate sets the level to DEBUG', () => { + test('logs a DEBUG log when the sample rate sets the level to DEBUG', () => { // Prepare // Since the buffer is private and we are bypassing the public warn method, we need to spy on the console.warn process.env.POWERTOOLS_DEV = 'true'; From 4e6de939b65fa37fda0a0ddd123903ac84baa85e Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev <sergei@cherniaev.com> Date: Wed, 1 May 2024 22:59:53 -0500 Subject: [PATCH 09/14] remove removeTemporaryLogAttributes, refactor removeKeys --- packages/logger/src/Logger.ts | 33 +++++++++++---------------------- 1 file changed, 11 insertions(+), 22 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index ffd9984bc5..debce1cc94 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -511,42 +511,31 @@ class Logger extends Utility implements LoggerInterface { } /** - * Alias for removePersistentLogAttributes. + * It removes attributes based on provided keys to all log items generated by this Logger instance. * * @param {string[]} keys * @returns {void} */ public removeKeys(keys: string[]): void { - this.removePersistentLogAttributes(keys); - this.removeTemporaryLogAttributes(keys); - } - - /** - * It removes persistent attributes based on provided keys to all log items generated by this Logger instance. - * - * @param {string[]} keys - * @returns {void} - */ - public removePersistentLogAttributes(keys: string[]): void { - for (const key of keys) { - if (this.persistentLogAttributes && key in this.persistentLogAttributes) { - delete this.persistentLogAttributes[key]; + const removeKey = (attributes: LogAttributes, key: string): void => { + if (attributes && key in attributes) { + delete attributes[key]; } + }; + for (const key of keys) { + removeKey(this.persistentLogAttributes, key); + removeKey(this.temporaryLogAttributes, key); } } /** - * It removes temporary attributes based on provided keys to all log items generated by this Logger instance. + * Alias for removeKeys(). * * @param {string[]} keys * @returns {void} */ - public removeTemporaryLogAttributes(keys: string[]): void { - for (const key of keys) { - if (this.temporaryLogAttributes && key in this.temporaryLogAttributes) { - delete this.temporaryLogAttributes[key]; - } - } + public removePersistentLogAttributes(keys: string[]): void { + this.removeKeys(keys); } /** From 25deb2a2a978e8b2d7f85d8e1667be1630145be2 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev <sergei@cherniaev.com> Date: Thu, 23 May 2024 21:00:54 +0400 Subject: [PATCH 10/14] test(logger): adjust tests --- packages/logger/tests/unit/Logger.test.ts | 399 ++++++++++++++---- .../tests/unit/middleware/middy.test.ts | 123 ++++-- 2 files changed, 395 insertions(+), 127 deletions(-) diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index a68f06cfa4..7b5fb59316 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -1492,7 +1492,35 @@ describe('Class: Logger', () => { }); describe('Method: removeKeys', () => { - test('when called, it removes keys from the logger persistentLogAttributes property', () => { + test('when called, it removes keys added with appendKeys() method', () => { + // Prepare + const logger = new Logger(); + logger.appendKeys({ + aws_account_id: '123456789012', + aws_region: 'eu-west-1', + logger: { + name: 'aws-lambda-powertool-typescript', + version: '0.2.4', + }, + }); + + // Act + logger.removeKeys(['aws_account_id', 'aws_region']); + + // Assess + expect(logger).toEqual( + expect.objectContaining({ + temporaryLogAttributes: { + logger: { + name: 'aws-lambda-powertool-typescript', + version: '0.2.4', + }, + }, + }) + ); + }); + + test('when called, it DOES NOT remove persistent keys', () => { // Prepare const loggerOptions: ConstructorOptions = { persistentKeys: { @@ -1513,6 +1541,8 @@ describe('Class: Logger', () => { expect(logger).toEqual( expect.objectContaining({ persistentLogAttributes: { + aws_account_id: '123456789012', + aws_region: 'eu-west-1', logger: { name: 'aws-lambda-powertool-typescript', version: '0.2.4', @@ -1522,7 +1552,7 @@ describe('Class: Logger', () => { ); }); - test('when called with non-existing keys, the logger property persistentLogAttributes is not mutated and it does not throw an error', () => { + test('when called with non-existing keys, the logger instance is not mutated and it does not throw an error', () => { // Prepare const logger = new Logger(); logger.appendKeys({ @@ -1584,6 +1614,150 @@ describe('Class: Logger', () => { }); }); + describe('Method: removePersistentLogAttributes', () => { + test('when called, it removes persistent keys', () => { + // Prepare + const loggerOptions: ConstructorOptions = { + persistentKeys: { + aws_account_id: '123456789012', + aws_region: 'eu-west-1', + logger: { + name: 'aws-lambda-powertool-typescript', + version: '0.2.4', + }, + }, + }; + const logger = new Logger(loggerOptions); + + // Act + logger.removePersistentLogAttributes(['aws_account_id', 'aws_region']); + + // Assess + expect(logger).toEqual( + expect.objectContaining({ + persistentLogAttributes: { + logger: { + name: 'aws-lambda-powertool-typescript', + version: '0.2.4', + }, + }, + }) + ); + }); + + test('when called, it DOES NOT remove temporary keys', () => { + // Prepare + const logger = new Logger(); + logger.appendKeys({ + aws_account_id: '123456789012', + aws_region: 'eu-west-1', + }); + + // Act + logger.removePersistentLogAttributes(['aws_account_id', 'aws_region']); + + // Assess + expect(logger).toEqual( + expect.objectContaining({ + temporaryLogAttributes: { + aws_account_id: '123456789012', + aws_region: 'eu-west-1', + }, + }) + ); + }); + }); + + describe('Method: resetState', () => { + test('when called, it removes all keys added with appendKeys() method', () => { + // Prepare + const logger = new Logger(); + logger.appendKeys({ + aws_account_id: '123456789012', + aws_region: 'eu-west-1', + logger: { + name: 'aws-lambda-powertool-typescript', + version: '0.2.4', + }, + }); + + // Act + logger.resetState(); + + // Assess + expect(logger).toEqual( + expect.objectContaining({ + temporaryLogAttributes: {}, + }) + ); + }); + + test('when called, it DOES NOT remove persistent keys', () => { + // Prepare + const loggerOptions: ConstructorOptions = { + persistentKeys: { + aws_account_id: '123456789012', + aws_region: 'eu-west-1', + logger: { + name: 'aws-lambda-powertool-typescript', + version: '0.2.4', + }, + }, + }; + const logger = new Logger(loggerOptions); + logger.appendKeys({ foo: 'bar' }); + + // Act + logger.resetState(); + + // Assess + expect(logger).toEqual( + expect.objectContaining({ + persistentLogAttributes: { + aws_account_id: '123456789012', + aws_region: 'eu-west-1', + logger: { + name: 'aws-lambda-powertool-typescript', + version: '0.2.4', + }, + }, + temporaryLogAttributes: {}, + }) + ); + }); + }); + + describe('method: setPersistentLogAttributes (deprecated)', () => { + test('when called, it overwrites all persistent keys', () => { + // Prepare + const loggerOptions: ConstructorOptions = { + persistentKeys: { + aws_account_id: '123456789012', + aws_region: 'eu-west-1', + logger: { + name: 'aws-lambda-powertool-typescript', + version: '0.2.4', + }, + }, + }; + const logger = new Logger(loggerOptions); + + // Act + logger.setPersistentLogAttributes({ + foo: 'bar', + }); + + // Assess + expect(logger).toEqual( + expect.objectContaining({ + persistentLogAttributes: { + foo: 'bar', + }, + }) + ); + }); + }); + describe('Method: injectLambdaContext', () => { beforeEach(() => { jest.spyOn(console, 'log').mockImplementation(() => ({})); @@ -1754,39 +1928,68 @@ describe('Class: Logger', () => { biz: 'baz', }); + const debugSpy = jest.spyOn(logger['console'], 'debug'); + class LambdaFunction implements LambdaInterface { @logger.injectLambdaContext({ clearState: true }) public async handler<TEvent>( _event: TEvent, _context: Context ): Promise<void> { - // Only add these persistent for the scope of this lambda handler + // Only add these keys for the scope of this lambda handler logger.appendKeys({ details: { user_id: '1234' }, }); logger.debug('This is a DEBUG log with the user_id'); - logger.debug('This is another DEBUG log with the user_id'); } } + const handlerClass = new LambdaFunction(); const handler = handlerClass.handler.bind(handlerClass); - const temporaryAttribsBeforeInvocation = { - ...logger.getTemporaryLogAttributes(), - }; - // Act await handler(event, context); + logger.debug('Checking state after handler execution'); // Assess - expect(temporaryAttribsBeforeInvocation).toEqual({ - foo: 'bar', - biz: 'baz', - }); - const temporaryAttribsAfterInvocation = { - ...logger.getTemporaryLogAttributes(), - }; - expect(temporaryAttribsAfterInvocation).toEqual({}); + expect(debugSpy).toHaveBeenCalledTimes(2); + expect(debugSpy).toHaveBeenCalledWith( + JSON.stringify({ + cold_start: true, + function_arn: + 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + function_memory_size: '128', + function_name: 'foo-bar-function', + function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', + level: 'DEBUG', + message: 'This is a DEBUG log with the user_id', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + foo: 'bar', + biz: 'baz', + details: { user_id: '1234' }, + }) + ); + expect(debugSpy).toHaveBeenLastCalledWith( + JSON.stringify({ + cold_start: true, + function_arn: + 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + function_memory_size: '128', + function_name: 'foo-bar-function', + function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', + level: 'DEBUG', + message: 'Checking state after handler execution', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + + debugSpy.mockRestore(); }); test('when clearState is enabled, the persistent log attributes added in the handler ARE NOT cleared when the method returns', async () => { @@ -1840,123 +2043,141 @@ describe('Class: Logger', () => { // Prepare const logger = new Logger({ logLevel: 'DEBUG', - persistentKeys: { - foo: 'bar', - biz: 'baz', - }, - }); - logger.appendKeys({ - type: 'temporary', }); + const debugSpy = jest.spyOn(logger['console'], 'debug'); + class LambdaFunction implements LambdaInterface { @logger.injectLambdaContext({ clearState: true }) public async handler<TEvent>( _event: TEvent, _context: Context ): Promise<void> { - // These persistent attributes stay persistent + // This key is persistent and will stay persistent logger.addPersistentLogAttributes({ - type: 'persistent', + foo: 'bar', + }); + // This attribute is temporary and will be cleared + logger.appendKeys({ + biz: 'baz', }); logger.debug( 'This is a DEBUG log with both pesistent and temporary keys' ); - logger.debug( - 'This is another DEBUG log with both pesistent and temporary keys' - ); } } const handlerClass = new LambdaFunction(); const handler = handlerClass.handler.bind(handlerClass); - const persistentAttribsBeforeInvocation = { - ...logger.getPersistentLogAttributes(), - }; - const temporaryAttribsBeforeInvocation = { - ...logger.getTemporaryLogAttributes(), - }; // Act await handler(event, context); - const persistentAttribsAfterInvocation = { - ...logger.getPersistentLogAttributes(), - }; - const temporaryAttribsAfterInvocation = { - ...logger.getTemporaryLogAttributes(), - }; + logger.debug('Checking state after handler execution'); // Assess - expect(persistentAttribsBeforeInvocation).toEqual({ - foo: 'bar', - biz: 'baz', - }); - expect(persistentAttribsAfterInvocation).toEqual({ - foo: 'bar', - biz: 'baz', - type: 'persistent', - }); - expect(temporaryAttribsBeforeInvocation).toEqual({ - type: 'temporary', - }); - expect(temporaryAttribsAfterInvocation).toEqual({}); + expect(debugSpy).toHaveBeenCalledTimes(2); + expect(debugSpy).toHaveBeenCalledWith( + JSON.stringify({ + cold_start: true, + function_arn: + 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + function_memory_size: '128', + function_name: 'foo-bar-function', + function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', + level: 'DEBUG', + message: 'This is a DEBUG log with both pesistent and temporary keys', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + foo: 'bar', + biz: 'baz', + }) + ); + expect(debugSpy).toHaveBeenLastCalledWith( + JSON.stringify({ + cold_start: true, + function_arn: + 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + function_memory_size: '128', + function_name: 'foo-bar-function', + function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', + level: 'DEBUG', + message: 'Checking state after handler execution', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + foo: 'bar', + }) + ); + + debugSpy.mockRestore(); }); test('when clearState is enabled, the temporary log attributes added in the handler are cleared when the method throws', async () => { // Prepare const logger = new Logger({ logLevel: 'DEBUG', - persistentLogAttributes: { - foo: 'bar', - biz: 'baz', - }, - }); - logger.appendKeys({ - type: 'temporary', }); + + const debugSpy = jest.spyOn(logger['console'], 'debug'); + class LambdaFunction implements LambdaInterface { @logger.injectLambdaContext({ clearState: true }) public async handler<TEvent>( _event: TEvent, _context: Context ): Promise<string> { - // These persistent attributes stay persistent + // This key is persistent and will stay persistent logger.addPersistentLogAttributes({ - details: { user_id: '1234' }, + foo: 'bar', }); - logger.debug('This is a DEBUG log with the user_id'); - logger.debug('This is another DEBUG log with the user_id'); - + // This attribute is temporary and will be cleared + logger.appendKeys({ + biz: 'baz', + }); + logger.debug( + 'This is a DEBUG log with both pesistent and temporary keys' + ); throw new Error('Unexpected error occurred!'); } } const handlerClass = new LambdaFunction(); const handler = handlerClass.handler.bind(handlerClass); - const persistentAttribsBeforeInvocation = { - ...logger.getPersistentLogAttributes(), - }; - const temporaryAttribsBeforeInvocation = { - ...logger.getTemporaryLogAttributes(), - }; // Act & Assess await expect(handler(event, context)).rejects.toThrow(); - const persistentAttribsAfterInvocation = { - ...logger.getPersistentLogAttributes(), - }; - expect(persistentAttribsBeforeInvocation).toEqual({ - foo: 'bar', - biz: 'baz', - }); - expect(persistentAttribsAfterInvocation).toEqual({ - foo: 'bar', - biz: 'baz', - details: { user_id: '1234' }, - }); - const temporaryAttribsAfterInvocation = { - ...logger.getTemporaryLogAttributes(), - }; - expect(temporaryAttribsBeforeInvocation).toEqual({ type: 'temporary' }); - expect(temporaryAttribsAfterInvocation).toEqual({}); + + expect(debugSpy).toHaveBeenCalledTimes(1); + expect(debugSpy).toHaveBeenCalledWith( + JSON.stringify({ + cold_start: true, + function_arn: + 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + function_memory_size: '128', + function_name: 'foo-bar-function', + function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', + level: 'DEBUG', + message: 'This is a DEBUG log with both pesistent and temporary keys', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + foo: 'bar', + biz: 'baz', + }) + ); + + expect(logger).toEqual( + expect.objectContaining({ + persistentLogAttributes: { + foo: 'bar', + }, + temporaryLogAttributes: {}, + }) + ); + + debugSpy.mockRestore(); }); test('when logEvent is enabled, it logs the event in the first log', async () => { @@ -2493,7 +2714,6 @@ describe('Class: Logger', () => { test_key: 'key-for-test', }); const childLoggerWithKeys = parentLogger.createChild(); - childLoggerWithKeys.removeKeys(['test_key']); // Assess expect(childLogger.getPersistentLogAttributes()).toEqual({}); @@ -2505,6 +2725,7 @@ describe('Class: Logger', () => { name: 'aws-lambda-powertool-typescript', version: '0.2.4', }, + test_key: 'key-for-test', }); expect(parentLogger.getPersistentLogAttributes()).toEqual({ diff --git a/packages/logger/tests/unit/middleware/middy.test.ts b/packages/logger/tests/unit/middleware/middy.test.ts index 275e6d7b79..7ba84f6018 100644 --- a/packages/logger/tests/unit/middleware/middy.test.ts +++ b/packages/logger/tests/unit/middleware/middy.test.ts @@ -96,7 +96,7 @@ describe('Middy middleware', () => { }); }); - describe('Feature: clear state', () => { + describe('Feature: reset state', () => { test('when enabled, it clears all the log attributes added with appendKeys() inside and outside of the handler function', async () => { // Prepare const logger = new Logger({ @@ -107,31 +107,59 @@ describe('Middy middleware', () => { biz: 'baz', }); + const debugSpy = jest.spyOn(logger['console'], 'debug'); + const handler = middy((): void => { - // Only add these persistent for the scope of this lambda handler + // Only add these keys for the scope of this lambda handler logger.appendKeys({ details: { user_id: '1234' }, }); logger.debug('This is a DEBUG log with the user_id'); - logger.debug('This is another DEBUG log with the user_id'); }).use(injectLambdaContext(logger, { clearState: true })); - const temporaryAttribsBeforeInvocation = { - ...logger.getTemporaryLogAttributes(), - }; - // Act await handler(event, context); + logger.debug('Checking state after handler execution'); // Assess - expect(temporaryAttribsBeforeInvocation).toEqual({ - foo: 'bar', - biz: 'baz', - }); - const temporaryAttribsAfterInvocation = { - ...logger.getTemporaryLogAttributes(), - }; - expect(temporaryAttribsAfterInvocation).toEqual({}); + expect(debugSpy).toHaveBeenCalledTimes(2); + expect(debugSpy).toHaveBeenCalledWith( + JSON.stringify({ + cold_start: true, + function_arn: + 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + function_memory_size: '128', + function_name: 'foo-bar-function', + function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', + level: 'DEBUG', + message: 'This is a DEBUG log with the user_id', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + foo: 'bar', + biz: 'baz', + details: { user_id: '1234' }, + }) + ); + expect(debugSpy).toHaveBeenLastCalledWith( + JSON.stringify({ + cold_start: true, + function_arn: + 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + function_memory_size: '128', + function_name: 'foo-bar-function', + function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', + level: 'DEBUG', + message: 'Checking state after handler execution', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + + debugSpy.mockRestore(); }); test('when enabled, the temporary log attributes added within the handler scope are removed after the invocation ends', async () => { @@ -140,47 +168,66 @@ describe('Middy middleware', () => { logLevel: 'DEBUG', persistentLogAttributes: { foo: 'bar', - biz: 'baz', }, }); logger.appendKeys({ - type: 'temporary', + biz: 'baz', }); + const debugSpy = jest.spyOn(logger['console'], 'debug'); + const handler = middy((): void => { // These keys stay only in the scope of this lambda handler logger.appendKeys({ details: { user_id: '1234' }, }); logger.debug('This is a DEBUG log with the user_id'); - logger.debug('This is another DEBUG log with the user_id'); }).use(injectLambdaContext(logger, { clearState: true })); - const persistentAttribsBeforeInvocation = { - ...logger.getPersistentLogAttributes(), - }; - const temporaryAttribsBeforeInvocation = { - ...logger.getTemporaryLogAttributes(), - }; // Act await handler(event, context); + logger.debug('Checking state after handler execution'); // Assess - const persistentAttribsAfterInvocation = { - ...logger.getPersistentLogAttributes(), - }; - expect(persistentAttribsBeforeInvocation).toEqual({ - foo: 'bar', - biz: 'baz', - }); - expect(persistentAttribsAfterInvocation).toEqual( - persistentAttribsBeforeInvocation + expect(debugSpy).toHaveBeenCalledTimes(2); + expect(debugSpy).toHaveBeenCalledWith( + JSON.stringify({ + cold_start: true, + function_arn: + 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + function_memory_size: '128', + function_name: 'foo-bar-function', + function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', + level: 'DEBUG', + message: 'This is a DEBUG log with the user_id', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + foo: 'bar', + biz: 'baz', + details: { user_id: '1234' }, + }) ); - expect(temporaryAttribsBeforeInvocation).toEqual({ type: 'temporary' }); - const temporaryAttribsAfterInvocation = { - ...logger.getTemporaryLogAttributes(), - }; - expect(temporaryAttribsAfterInvocation).toEqual({}); + expect(debugSpy).toHaveBeenLastCalledWith( + JSON.stringify({ + cold_start: true, + function_arn: + 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + function_memory_size: '128', + function_name: 'foo-bar-function', + function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', + level: 'DEBUG', + message: 'Checking state after handler execution', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + foo: 'bar', + }) + ); + + debugSpy.mockRestore(); }); test('when enabled, the persistent log attributes added within the handler scope ARE NOT removed after the invocation ends', async () => { From dd404c031b1df856b02aec8ccbda02f9418aa36e Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev <sergei@cherniaev.com> Date: Thu, 23 May 2024 21:12:29 +0400 Subject: [PATCH 11/14] add requested changes --- packages/logger/src/Logger.ts | 72 +++++++++++-------------- packages/logger/src/middleware/middy.ts | 2 +- 2 files changed, 31 insertions(+), 43 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index debce1cc94..e9a0c1dd32 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -172,16 +172,16 @@ class Logger extends Utility implements LoggerInterface { * Standard attributes managed by Powertools that will be logged in all log items. */ private powertoolsLogData: PowertoolsLogData = <PowertoolsLogData>{}; + /** + * Temporary log attributes that can be appended with `appendKeys()` method. + */ + private temporaryLogAttributes: LogAttributes = {}; /** * Buffer used to store logs until the logger is initialized. * * 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. */ - /** - * Temporary log attributes that can be appended with `appendKeys()` method. - */ - private temporaryLogAttributes: LogAttributes = {}; #buffer: [number, Parameters<Logger['createAndPopulateLogItem']>][] = []; /** * Flag used to determine if the logger is initialized. @@ -257,15 +257,6 @@ class Logger extends Utility implements LoggerInterface { merge(this.temporaryLogAttributes, attributes); } - /** - * It clears temporary log attributes. - * - * @returns {void} - */ - public clearState(): void { - this.temporaryLogAttributes = {}; - } - /** * It creates a separate Logger instance, identical to the current one * It's possible to overwrite the new instance options by passing them. @@ -368,16 +359,6 @@ class Logger extends Utility implements LoggerInterface { return this.persistentLogAttributes; } - /** - * It returns the temporary log attributes, added with `appendKeys()` method. - * - * @private - * @returns {LogAttributes} - */ - public getTemporaryLogAttributes(): LogAttributes { - return this.temporaryLogAttributes; - } - /** * It prints a log item with level INFO. * @@ -449,11 +430,7 @@ class Logger extends Utility implements LoggerInterface { } catch (error) { throw error; } finally { - Logger.injectLambdaContextAfterOrOnError( - loggerRef, - loggerRef.getPersistentLogAttributes(), - options - ); + Logger.injectLambdaContextAfterOrOnError(loggerRef, {}, options); } return result; @@ -461,14 +438,16 @@ class Logger extends Utility implements LoggerInterface { }; } + /** + * @deprecated This method is deprecated and will be removed in the future major versions. + */ public static injectLambdaContextAfterOrOnError( logger: Logger, - persistentAttributes: LogAttributes, + _persistentAttributes: LogAttributes, options?: InjectLambdaContextOptions ): void { if (options && options.clearState === true) { - logger.clearState(); - logger.addPersistentLogAttributes(persistentAttributes); + logger.resetState(); } } @@ -511,31 +490,40 @@ class Logger extends Utility implements LoggerInterface { } /** - * It removes attributes based on provided keys to all log items generated by this Logger instance. + * It removes temporary attributes based on provided keys to all log items generated by this Logger instance. * * @param {string[]} keys * @returns {void} */ public removeKeys(keys: string[]): void { - const removeKey = (attributes: LogAttributes, key: string): void => { - if (attributes && key in attributes) { - delete attributes[key]; - } - }; for (const key of keys) { - removeKey(this.persistentLogAttributes, key); - removeKey(this.temporaryLogAttributes, key); + if (this.temporaryLogAttributes && key in this.temporaryLogAttributes) { + delete this.temporaryLogAttributes[key]; + } } } /** - * Alias for removeKeys(). + * It removes persistent attributes based on provided keys to all log items generated by this Logger instance. * * @param {string[]} keys * @returns {void} */ public removePersistentLogAttributes(keys: string[]): void { - this.removeKeys(keys); + for (const key of keys) { + if (this.persistentLogAttributes && key in this.persistentLogAttributes) { + delete this.persistentLogAttributes[key]; + } + } + } + + /** + * It resets the state, by removing all temporary log attributes added with `appendKeys()` method. + * + * @returns {void} + */ + public resetState(): void { + this.temporaryLogAttributes = {}; } /** @@ -692,7 +680,7 @@ class Logger extends Utility implements LoggerInterface { // gradually merge additional attributes starting from customer-provided persistent & temporary attributes let additionalLogAttributes = { ...this.getPersistentLogAttributes(), - ...this.getTemporaryLogAttributes(), + ...this.temporaryLogAttributes, }; // if the main input is not a string, then it's an object with additional attributes, so we merge it additionalLogAttributes = merge(additionalLogAttributes, otherInput); diff --git a/packages/logger/src/middleware/middy.ts b/packages/logger/src/middleware/middy.ts index 92f2addae2..5b3a33dba2 100644 --- a/packages/logger/src/middleware/middy.ts +++ b/packages/logger/src/middleware/middy.ts @@ -69,7 +69,7 @@ const injectLambdaContext = ( const injectLambdaContextAfterOrOnError = async (): Promise<void> => { if (isClearState) { loggers.forEach((logger: Logger) => { - logger.clearState(); + logger.resetState(); }); } }; From edbbc4d0ebb7557d328f0e42bd4d63c06e686bd5 Mon Sep 17 00:00:00 2001 From: Andrea Amorosi <dreamorosi@gmail.com> Date: Mon, 3 Jun 2024 18:49:45 +0200 Subject: [PATCH 12/14] chore: refactor tests to isolate feature gap --- packages/logger/src/Logger.ts | 21 ++- packages/logger/tests/unit/Logger.test.ts | 153 +++++++++++------- .../tests/unit/middleware/middy.test.ts | 24 +-- 3 files changed, 126 insertions(+), 72 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index e9a0c1dd32..8e1cf82859 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -240,11 +240,13 @@ class Logger extends Utility implements LoggerInterface { /** * It adds the given persistent attributes (key-value pairs) to all log items generated by this Logger instance. * + * @deprecated This method is deprecated and will be removed in the future major versions, please use {@link appendPersistentKeys()} instead. + * * @param {LogAttributes} attributes * @returns {void} */ - public addPersistentLogAttributes(attributes?: LogAttributes): void { - merge(this.persistentLogAttributes, attributes); + public addPersistentLogAttributes(attributes: LogAttributes): void { + this.appendPersistentKeys(attributes); } /** @@ -257,6 +259,15 @@ class Logger extends Utility implements LoggerInterface { merge(this.temporaryLogAttributes, attributes); } + /** + * It adds the given persistent attributes (key-value pairs) to all log items generated by this Logger instance. + * + * @param attributes - The attributes to add to all log items. + */ + public appendPersistentKeys(attributes: LogAttributes): void { + merge(this.persistentLogAttributes, attributes); + } + /** * It creates a separate Logger instance, identical to the current one * It's possible to overwrite the new instance options by passing them. @@ -544,11 +555,11 @@ class Logger extends Utility implements LoggerInterface { } /** - * @deprecated This method is deprecated and will be removed in the future major versions. - * * It sets the given attributes (key-value pairs) to all log items generated by this Logger instance. * Note: this replaces the pre-existing value. * + * @deprecated This method is deprecated and will be removed in the future major versions, please use {@link appendPersistentKeys()} instead. + * * @param {LogAttributes} attributes * @returns {void} */ @@ -679,8 +690,8 @@ class Logger extends Utility implements LoggerInterface { // gradually merge additional attributes starting from customer-provided persistent & temporary attributes let additionalLogAttributes = { - ...this.getPersistentLogAttributes(), ...this.temporaryLogAttributes, + ...this.getPersistentLogAttributes(), }; // if the main input is not a string, then it's an object with additional attributes, so we merge it additionalLogAttributes = merge(additionalLogAttributes, otherInput); diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index 7b5fb59316..b5fefa783f 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -1476,15 +1476,9 @@ describe('Class: Logger', () => { // Assess expect(consoleSpy).toHaveBeenCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ - level: 'INFO', - message: 'This is an INFO log with some log attributes', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + const log = JSON.parse(consoleSpy.mock.calls[0][0]); + expect(log).toStrictEqual( + expect.objectContaining({ aws_account_id: '0987654321', }) ); @@ -1758,6 +1752,52 @@ describe('Class: Logger', () => { }); }); + describe('Method: appendPersistentKeys', () => { + it('overwrites existing persistent keys with new ones', () => { + // Prepare + const logger = new Logger({ + persistentKeys: { + aws_account_id: '123456789012', + }, + }); + + // Act + logger.appendPersistentKeys({ + aws_account_id: '0987654321', + }); + + // Assess + expect(logger).toEqual( + expect.objectContaining({ + persistentLogAttributes: { + aws_account_id: '0987654321', + }, + }) + ); + }); + + it('overwrites existing temporary keys with new ones in the next log', () => { + // Prepare + const logger = new Logger(); + const debugSpy = jest.spyOn(logger['console'], 'info'); + logger.appendKeys({ + aws_account_id: '123456789012', + }); + + // Act + logger.appendPersistentKeys({ + aws_account_id: '0987654321', + }); + logger.info('This is an INFO log with some log attributes'); + + // Assess + const log = JSON.parse(debugSpy.mock.calls[0][0]); + expect(log).toStrictEqual( + expect.objectContaining({ aws_account_id: '0987654321' }) + ); + }); + }); + describe('Method: injectLambdaContext', () => { beforeEach(() => { jest.spyOn(console, 'log').mockImplementation(() => ({})); @@ -1788,10 +1828,10 @@ describe('Class: Logger', () => { await handler(event, context); // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ + expect(consoleSpy).toHaveBeenCalledTimes(1); + const log = JSON.parse(consoleSpy.mock.calls[0][0]); + expect(log).toEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -1830,10 +1870,10 @@ describe('Class: Logger', () => { // Assess - expect(consoleSpy).toBeCalledTimes(2); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ + expect(consoleSpy).toHaveBeenCalledTimes(2); + const log1 = JSON.parse(consoleSpy.mock.calls[0][0]); + expect(log1).toStrictEqual( + expect.objectContaining({ level: 'INFO', message: 'An INFO log without context!', sampling_rate: 0, @@ -1842,9 +1882,9 @@ describe('Class: Logger', () => { xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', }) ); - expect(consoleSpy).toHaveBeenNthCalledWith( - 2, - JSON.stringify({ + const log2 = JSON.parse(consoleSpy.mock.calls[1][0]); + expect(log2).toStrictEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -1887,10 +1927,10 @@ describe('Class: Logger', () => { // Assess expect(actualResult).toEqual(expectedReturnValue); - expect(consoleSpy).toBeCalledTimes(2); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ + expect(consoleSpy).toHaveBeenCalledTimes(2); + const log1 = JSON.parse(consoleSpy.mock.calls[0][0]); + expect(log1).toStrictEqual( + expect.objectContaining({ level: 'INFO', message: 'An INFO log without context!', sampling_rate: 0, @@ -1899,9 +1939,9 @@ describe('Class: Logger', () => { xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', }) ); - expect(consoleSpy).toHaveBeenNthCalledWith( - 2, - JSON.stringify({ + const log2 = JSON.parse(consoleSpy.mock.calls[1][0]); + expect(log2).toStrictEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -1953,8 +1993,9 @@ describe('Class: Logger', () => { // Assess expect(debugSpy).toHaveBeenCalledTimes(2); - expect(debugSpy).toHaveBeenCalledWith( - JSON.stringify({ + const log1 = JSON.parse(debugSpy.mock.calls[0][0]); + expect(log1).toStrictEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -1972,8 +2013,9 @@ describe('Class: Logger', () => { details: { user_id: '1234' }, }) ); - expect(debugSpy).toHaveBeenLastCalledWith( - JSON.stringify({ + const log2 = JSON.parse(debugSpy.mock.calls[1][0]); + expect(log2).toStrictEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -1988,8 +2030,6 @@ describe('Class: Logger', () => { xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', }) ); - - debugSpy.mockRestore(); }); test('when clearState is enabled, the persistent log attributes added in the handler ARE NOT cleared when the method returns', async () => { @@ -2008,7 +2048,7 @@ describe('Class: Logger', () => { _context: Context ): Promise<void> { // These persistent attributes stay persistent - logger.addPersistentLogAttributes({ + logger.appendPersistentKeys({ details: { user_id: '1234' }, }); logger.debug('This is a DEBUG log with the user_id'); @@ -2054,7 +2094,7 @@ describe('Class: Logger', () => { _context: Context ): Promise<void> { // This key is persistent and will stay persistent - logger.addPersistentLogAttributes({ + logger.appendPersistentKeys({ foo: 'bar', }); // This attribute is temporary and will be cleared @@ -2075,8 +2115,9 @@ describe('Class: Logger', () => { // Assess expect(debugSpy).toHaveBeenCalledTimes(2); - expect(debugSpy).toHaveBeenCalledWith( - JSON.stringify({ + const log1 = JSON.parse(debugSpy.mock.calls[0][0]); + expect(log1).toStrictEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -2093,8 +2134,9 @@ describe('Class: Logger', () => { biz: 'baz', }) ); - expect(debugSpy).toHaveBeenLastCalledWith( - JSON.stringify({ + const log2 = JSON.parse(debugSpy.mock.calls[1][0]); + expect(log2).toStrictEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -2129,7 +2171,7 @@ describe('Class: Logger', () => { _context: Context ): Promise<string> { // This key is persistent and will stay persistent - logger.addPersistentLogAttributes({ + logger.appendPersistentKeys({ foo: 'bar', }); // This attribute is temporary and will be cleared @@ -2149,8 +2191,9 @@ describe('Class: Logger', () => { await expect(handler(event, context)).rejects.toThrow(); expect(debugSpy).toHaveBeenCalledTimes(1); - expect(debugSpy).toHaveBeenCalledWith( - JSON.stringify({ + const log = JSON.parse(debugSpy.mock.calls[0][0]); + expect(log).toStrictEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -2202,10 +2245,10 @@ describe('Class: Logger', () => { await handler(event, context); // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ + expect(consoleSpy).toHaveBeenCalledTimes(1); + const log = JSON.parse(consoleSpy.mock.calls[0][0]); + expect(log).toStrictEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -2249,10 +2292,10 @@ describe('Class: Logger', () => { await handler(event, context); // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ + expect(consoleSpy).toHaveBeenCalledTimes(1); + const log = JSON.parse(consoleSpy.mock.calls[0][0]); + expect(log).toStrictEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -2307,10 +2350,10 @@ describe('Class: Logger', () => { await handler({}, context); // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ + expect(consoleSpy).toHaveBeenCalledTimes(1); + const log = JSON.parse(consoleSpy.mock.calls[0][0]); + expect(log).toStrictEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -2704,7 +2747,7 @@ describe('Class: Logger', () => { const childLogger = parentLogger.createChild(); // Act - parentLogger.addPersistentLogAttributes({ + parentLogger.appendPersistentKeys({ aws_account_id: '123456789012', aws_region: 'eu-west-1', logger: { diff --git a/packages/logger/tests/unit/middleware/middy.test.ts b/packages/logger/tests/unit/middleware/middy.test.ts index 7ba84f6018..e5e7b828bf 100644 --- a/packages/logger/tests/unit/middleware/middy.test.ts +++ b/packages/logger/tests/unit/middleware/middy.test.ts @@ -123,8 +123,9 @@ describe('Middy middleware', () => { // Assess expect(debugSpy).toHaveBeenCalledTimes(2); - expect(debugSpy).toHaveBeenCalledWith( - JSON.stringify({ + const log1 = JSON.parse(debugSpy.mock.calls[0][0]); + expect(log1).toStrictEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -142,8 +143,9 @@ describe('Middy middleware', () => { details: { user_id: '1234' }, }) ); - expect(debugSpy).toHaveBeenLastCalledWith( - JSON.stringify({ + const log2 = JSON.parse(debugSpy.mock.calls[1][0]); + expect(log2).toStrictEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -158,8 +160,6 @@ describe('Middy middleware', () => { xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', }) ); - - debugSpy.mockRestore(); }); test('when enabled, the temporary log attributes added within the handler scope are removed after the invocation ends', async () => { @@ -190,8 +190,9 @@ describe('Middy middleware', () => { // Assess expect(debugSpy).toHaveBeenCalledTimes(2); - expect(debugSpy).toHaveBeenCalledWith( - JSON.stringify({ + const log1 = JSON.parse(debugSpy.mock.calls[0][0]); + expect(log1).toStrictEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -209,8 +210,9 @@ describe('Middy middleware', () => { details: { user_id: '1234' }, }) ); - expect(debugSpy).toHaveBeenLastCalledWith( - JSON.stringify({ + const log2 = JSON.parse(debugSpy.mock.calls[1][0]); + expect(log2).toStrictEqual( + expect.objectContaining({ cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', @@ -226,8 +228,6 @@ describe('Middy middleware', () => { foo: 'bar', }) ); - - debugSpy.mockRestore(); }); test('when enabled, the persistent log attributes added within the handler scope ARE NOT removed after the invocation ends', async () => { From 12c60c515987a1a3d33e1f371d38932b004ea791 Mon Sep 17 00:00:00 2001 From: Andrea Amorosi <dreamorosi@gmail.com> Date: Tue, 4 Jun 2024 14:32:56 +0200 Subject: [PATCH 13/14] chore: consistent keys merging --- packages/logger/src/Logger.ts | 63 +++++++++++++++++------ packages/logger/tests/unit/Logger.test.ts | 23 +++++++++ 2 files changed, 70 insertions(+), 16 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 8e1cf82859..3aa7692ecd 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -187,6 +187,13 @@ class Logger extends Utility implements LoggerInterface { * Flag used to determine if the logger is initialized. */ #isInitialized = false; + /** + * Map used to hold the list of keys and their type. + * + * Because keys of different types can be overwritten, we keep a list of keys that were added and their last + * type. We then use this map at log preparation time to pick the last one. + */ + #keys: Map<string, 'temp' | 'persistent'> = new Map(); /** * Log level used by the current instance of Logger. @@ -255,7 +262,10 @@ class Logger extends Utility implements LoggerInterface { * @param {LogAttributes} attributes * @returns {void} */ - public appendKeys(attributes?: LogAttributes): void { + public appendKeys(attributes: LogAttributes): void { + for (const attributeKey of Object.keys(attributes)) { + this.#keys.set(attributeKey, 'temp'); + } merge(this.temporaryLogAttributes, attributes); } @@ -265,6 +275,9 @@ class Logger extends Utility implements LoggerInterface { * @param attributes - The attributes to add to all log items. */ public appendPersistentKeys(attributes: LogAttributes): void { + for (const attributeKey of Object.keys(attributes)) { + this.#keys.set(attributeKey, 'persistent'); + } merge(this.persistentLogAttributes, attributes); } @@ -508,8 +521,12 @@ class Logger extends Utility implements LoggerInterface { */ public removeKeys(keys: string[]): void { for (const key of keys) { - if (this.temporaryLogAttributes && key in this.temporaryLogAttributes) { - delete this.temporaryLogAttributes[key]; + this.temporaryLogAttributes[key] = undefined; + + if (this.persistentLogAttributes[key]) { + this.#keys.set(key, 'persistent'); + } else { + this.#keys.delete(key); } } } @@ -522,18 +539,27 @@ class Logger extends Utility implements LoggerInterface { */ public removePersistentLogAttributes(keys: string[]): void { for (const key of keys) { - if (this.persistentLogAttributes && key in this.persistentLogAttributes) { - delete this.persistentLogAttributes[key]; + this.persistentLogAttributes[key] = undefined; + + if (this.temporaryLogAttributes[key]) { + this.#keys.set(key, 'temp'); + } else { + this.#keys.delete(key); } } } /** * It resets the state, by removing all temporary log attributes added with `appendKeys()` method. - * - * @returns {void} */ public resetState(): void { + for (const key of Object.keys(this.temporaryLogAttributes)) { + if (this.persistentLogAttributes[key]) { + this.#keys.set(key, 'persistent'); + } else { + this.#keys.delete(key); + } + } this.temporaryLogAttributes = {}; } @@ -688,13 +714,18 @@ class Logger extends Utility implements LoggerInterface { ...this.getPowertoolsLogData(), }; - // gradually merge additional attributes starting from customer-provided persistent & temporary attributes - let additionalLogAttributes = { - ...this.temporaryLogAttributes, - ...this.getPersistentLogAttributes(), - }; + const additionalAttributes: LogAttributes = {}; + // gradually add additional attributes picking only the last added for each key + for (const [key, type] of this.#keys) { + if (type === 'persistent') { + additionalAttributes[key] = this.persistentLogAttributes[key]; + } else { + additionalAttributes[key] = this.temporaryLogAttributes[key]; + } + } + // if the main input is not a string, then it's an object with additional attributes, so we merge it - additionalLogAttributes = merge(additionalLogAttributes, otherInput); + merge(additionalAttributes, otherInput); // then we merge the extra input attributes (if any) for (const item of extraInput) { const attributes: LogAttributes = @@ -704,12 +735,12 @@ class Logger extends Utility implements LoggerInterface { ? { extra: item } : item; - additionalLogAttributes = merge(additionalLogAttributes, attributes); + merge(additionalAttributes, attributes); } return this.getLogFormatter().formatAttributes( unformattedBaseAttributes, - additionalLogAttributes + additionalAttributes ); } @@ -1106,7 +1137,7 @@ class Logger extends Utility implements LoggerInterface { this.getEnvVarsService().getServiceName() || this.getDefaultServiceName(), }); - this.addPersistentLogAttributes(persistentLogAttributes); + this.appendPersistentKeys(persistentLogAttributes); } } diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index b5fefa783f..dc5bc58708 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -1719,6 +1719,29 @@ describe('Class: Logger', () => { }) ); }); + + it('preserves persistent keys that were previously overwritten', () => { + // Prepare + const logger = new Logger({ + persistentKeys: { + aws_region: 'eu-west-1', + }, + }); + const debugSpy = jest.spyOn(logger['console'], 'info'); + logger.appendKeys({ + aws_region: 'us-east-1', + }); + + // Act + logger.resetState(); + logger.info('foo'); + + // Assess + const log = JSON.parse(debugSpy.mock.calls[0][0]); + expect(log).toStrictEqual( + expect.objectContaining({ aws_region: 'eu-west-1' }) + ); + }); }); describe('method: setPersistentLogAttributes (deprecated)', () => { From ca76e127b717d2a8a934ddb7dc32b785940f15d4 Mon Sep 17 00:00:00 2001 From: Andrea Amorosi <dreamorosi@gmail.com> Date: Fri, 14 Jun 2024 16:02:51 +0200 Subject: [PATCH 14/14] chore: update usage of deprecated method --- packages/logger/src/Logger.ts | 7 ++++--- packages/logger/tests/unit/Logger.test.ts | 11 ++++------- 2 files changed, 8 insertions(+), 10 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 3aa7692ecd..34d5bb6e18 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -257,7 +257,7 @@ class Logger extends Utility implements LoggerInterface { } /** - * Alias for addTemporaryLogAttributes. + * It adds the given temporary attributes (key-value pairs) to all log items generated by this Logger instance. * * @param {LogAttributes} attributes * @returns {void} @@ -454,7 +454,7 @@ class Logger extends Utility implements LoggerInterface { } catch (error) { throw error; } finally { - Logger.injectLambdaContextAfterOrOnError(loggerRef, {}, options); + if (options?.clearState) loggerRef.resetState(); } return result; @@ -463,8 +463,9 @@ class Logger extends Utility implements LoggerInterface { } /** - * @deprecated This method is deprecated and will be removed in the future major versions. + * @deprecated This method is deprecated and will be removed in the future major versions. Use {@link resetState()} instead. */ + /* istanbul ignore next */ public static injectLambdaContextAfterOrOnError( logger: Logger, _persistentAttributes: LogAttributes, diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index dc5bc58708..649e694585 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -2395,16 +2395,13 @@ describe('Class: Logger', () => { test('it awaits the decorated method correctly', async () => { // Prepare - const injectLambdaContextAfterOrOnErrorSpy = jest.spyOn( - Logger, - 'injectLambdaContextAfterOrOnError' - ); const logger = new Logger({ logLevel: 'DEBUG', }); + const resetStateSpy = jest.spyOn(logger, 'resetState'); const consoleSpy = jest.spyOn(logger['console'], 'info'); class LambdaFunction implements LambdaInterface { - @logger.injectLambdaContext() + @logger.injectLambdaContext({ clearState: true }) public async handler( _event: unknown, _context: unknown @@ -2426,12 +2423,12 @@ describe('Class: Logger', () => { await handler({}, context); // Assess - expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenCalledTimes(1); // Here we assert that the logger.info method is called before the cleanup function that should always // be called ONLY after the handler has returned. If logger.info is called after the cleanup function // it means the decorator is NOT awaiting the handler which would cause the test to fail. expect(consoleSpy.mock.invocationCallOrder[0]).toBeLessThan( - injectLambdaContextAfterOrOnErrorSpy.mock.invocationCallOrder[0] + resetStateSpy.mock.invocationCallOrder[0] ); });