diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 739e0fdadb..34d5bb6e18 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -172,6 +172,10 @@ class Logger extends Utility implements LoggerInterface { * Standard attributes managed by Powertools that will be logged in all log items. */ private 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. * @@ -183,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 = new Map(); /** * Log level used by the current instance of Logger. @@ -234,23 +245,40 @@ 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. + * + * @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); } /** - * 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 appendKeys(attributes?: LogAttributes): void { - this.addPersistentLogAttributes(attributes); + public appendKeys(attributes: LogAttributes): void { + for (const attributeKey of Object.keys(attributes)) { + this.#keys.set(attributeKey, 'temp'); + } + 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 { + for (const attributeKey of Object.keys(attributes)) { + this.#keys.set(attributeKey, 'persistent'); + } + merge(this.persistentLogAttributes, attributes); } /** @@ -274,6 +302,7 @@ class Logger extends Utility implements LoggerInterface { customConfigService: this.getCustomConfigService(), environment: this.powertoolsLogData.environment, persistentLogAttributes: this.persistentLogAttributes, + temporaryLogAttributes: this.temporaryLogAttributes, }, options ) @@ -417,13 +446,6 @@ class Logger extends Utility implements LoggerInterface { context, callback ) { - let initialPersistentAttributes = {}; - if (options && options.clearState === true) { - initialPersistentAttributes = { - ...loggerRef.getPersistentLogAttributes(), - }; - } - Logger.injectLambdaContextBefore(loggerRef, event, context, options); let result: unknown; @@ -432,11 +454,7 @@ class Logger extends Utility implements LoggerInterface { } catch (error) { throw error; } finally { - Logger.injectLambdaContextAfterOrOnError( - loggerRef, - initialPersistentAttributes, - options - ); + if (options?.clearState) loggerRef.resetState(); } return result; @@ -444,13 +462,17 @@ class Logger extends Utility implements LoggerInterface { }; } + /** + * @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, - initialPersistentAttributes: LogAttributes, + _persistentAttributes: LogAttributes, options?: InjectLambdaContextOptions ): void { if (options && options.clearState === true) { - logger.setPersistentLogAttributes(initialPersistentAttributes); + logger.resetState(); } } @@ -493,27 +515,53 @@ class Logger extends Utility implements LoggerInterface { } /** - * Alias for removePersistentLogAttributes. + * 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 { - this.removePersistentLogAttributes(keys); + for (const key of keys) { + this.temporaryLogAttributes[key] = undefined; + + if (this.persistentLogAttributes[key]) { + this.#keys.set(key, 'persistent'); + } else { + this.#keys.delete(key); + } + } } /** - * 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} */ 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. + */ + 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 = {}; } /** @@ -537,6 +585,8 @@ class Logger extends Utility implements LoggerInterface { * 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} */ @@ -665,10 +715,18 @@ class Logger extends Utility implements LoggerInterface { ...this.getPowertoolsLogData(), }; - // gradually merge additional attributes starting from customer-provided persistent attributes - let additionalLogAttributes = { ...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 = @@ -678,12 +736,12 @@ class Logger extends Utility implements LoggerInterface { ? { extra: item } : item; - additionalLogAttributes = merge(additionalLogAttributes, attributes); + merge(additionalAttributes, attributes); } return this.getLogFormatter().formatAttributes( unformattedBaseAttributes, - additionalLogAttributes + additionalAttributes ); } @@ -1023,13 +1081,23 @@ class Logger extends Utility implements LoggerInterface { serviceName, sampleRateValue, logFormatter, - persistentLogAttributes, + persistentKeys, + persistentLogAttributes, // deprecated in favor of persistentKeys environment, } = options; + if (persistentLogAttributes && persistentKeys) { + this.warn( + 'Both persistentLogAttributes and persistentKeys options were provided. Using persistentKeys as persistentLogAttributes is deprecated and will be removed in future releases' + ); + } + // configurations that affect log content - this.setPowertoolsLogData(serviceName, environment); - this.addPersistentLogAttributes(persistentLogAttributes); + this.setPowertoolsLogData( + serviceName, + environment, + persistentKeys || persistentLogAttributes + ); // configurations that affect Logger behavior this.setLogEvent(); @@ -1070,7 +1138,7 @@ class Logger extends Utility implements LoggerInterface { this.getEnvVarsService().getServiceName() || this.getDefaultServiceName(), }); - this.addPersistentLogAttributes(persistentLogAttributes); + this.appendPersistentKeys(persistentLogAttributes); } } diff --git a/packages/logger/src/middleware/middy.ts b/packages/logger/src/middleware/middy.ts index 4e970e55a9..5b3a33dba2 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 => { - loggers.forEach((logger: Logger, index: number) => { + loggers.forEach((logger: Logger) => { if (isClearState) { - persistentAttributes[index] = { - ...logger.getPersistentLogAttributes(), - }; - setCleanupFunction(request); } Logger.injectLambdaContextBefore( @@ -74,12 +68,8 @@ const injectLambdaContext = ( const injectLambdaContextAfterOrOnError = async (): Promise => { if (isClearState) { - loggers.forEach((logger: Logger, index: number) => { - Logger.injectLambdaContextAfterOrOnError( - logger, - persistentAttributes[index], - options - ); + loggers.forEach((logger: Logger) => { + logger.resetState(); }); } }; 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' diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index e9e34beace..f5ead4bb6c 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: '', @@ -454,6 +457,82 @@ 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 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; + persistentKeys?: Record; + }; + + const loggerOptions: TestConstructorOptions = { + persistentKeys: { + foo: 'bar', + }, + persistentLogAttributes: { + foo: 'bar', + }, + }; + + // 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', () => { // Prepare const loggerOptions: ConstructorOptions = { @@ -1315,7 +1394,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(); @@ -1332,7 +1411,7 @@ describe('Class: Logger', () => { // Assess expect(logger).toEqual( expect.objectContaining({ - persistentLogAttributes: { + temporaryLogAttributes: { aws_account_id: '123456789012', aws_region: 'eu-west-1', logger: { @@ -1374,16 +1453,43 @@ 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); + const log = JSON.parse(consoleSpy.mock.calls[0][0]); + expect(log).toStrictEqual( + expect.objectContaining({ + aws_account_id: '0987654321', + }) + ); + }); }); 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({ @@ -1398,10 +1504,42 @@ describe('Class: Logger', () => { // 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: { + 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']); + // 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', @@ -1411,7 +1549,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({ @@ -1431,7 +1569,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: { @@ -1459,6 +1597,38 @@ describe('Class: Logger', () => { logger.removeKeys(['aws_account_id', 'aws_region']); logger.removeKeys(['aws_account_id', 'aws_region']); + // Assess + expect(logger).toEqual( + expect.objectContaining({ + temporaryLogAttributes: { + logger: { + name: 'aws-lambda-powertool-typescript', + version: '0.2.4', + }, + }, + }) + ); + }); + }); + + 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({ @@ -1471,6 +1641,187 @@ describe('Class: Logger', () => { }) ); }); + + 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: {}, + }) + ); + }); + + 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)', () => { + 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: 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', () => { @@ -1503,10 +1854,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', @@ -1545,10 +1896,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, @@ -1557,9 +1908,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', @@ -1602,10 +1953,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, @@ -1614,9 +1965,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', @@ -1633,7 +1984,81 @@ 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', + }); + + const debugSpy = jest.spyOn(logger['console'], 'debug'); + + class LambdaFunction implements LambdaInterface { + @logger.injectLambdaContext({ clearState: true }) + public async handler( + _event: TEvent, + _context: Context + ): Promise { + // 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'); + } + } + + const handlerClass = new LambdaFunction(); + const handler = handlerClass.handler.bind(handlerClass); + + // Act + await handler(event, context); + logger.debug('Checking state after handler execution'); + + // Assess + expect(debugSpy).toHaveBeenCalledTimes(2); + 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', + 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' }, + }) + ); + 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', + 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', + }) + ); + }); + + 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', @@ -1648,8 +2073,8 @@ describe('Class: Logger', () => { _event: TEvent, _context: Context ): Promise { - // Only add these persistent for the scope of this lambda handler - logger.appendKeys({ + // These persistent attributes stay persistent + logger.appendPersistentKeys({ details: { user_id: '1234' }, }); logger.debug('This is a DEBUG log with the user_id'); @@ -1673,54 +2098,155 @@ 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, the persistent log attributes added in the handler are cleared when the method throws', async () => { + 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', - persistentLogAttributes: { + }); + + const debugSpy = jest.spyOn(logger['console'], 'debug'); + + class LambdaFunction implements LambdaInterface { + @logger.injectLambdaContext({ clearState: true }) + public async handler( + _event: TEvent, + _context: Context + ): Promise { + // This key is persistent and will stay persistent + logger.appendPersistentKeys({ + 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' + ); + } + } + const handlerClass = new LambdaFunction(); + const handler = handlerClass.handler.bind(handlerClass); + + // Act + await handler(event, context); + logger.debug('Checking state after handler execution'); + + // Assess + expect(debugSpy).toHaveBeenCalledTimes(2); + 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', + 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', - }, + }) + ); + 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', + 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', }); + + const debugSpy = jest.spyOn(logger['console'], 'debug'); + class LambdaFunction implements LambdaInterface { @logger.injectLambdaContext({ clearState: true }) public async handler( _event: TEvent, _context: Context ): Promise { - // Only add these persistent for the scope of this lambda handler + // This key is persistent and will stay persistent + logger.appendPersistentKeys({ + foo: 'bar', + }); + // This attribute is temporary and will be cleared logger.appendKeys({ - details: { user_id: '1234' }, + biz: 'baz', }); - logger.debug('This is a DEBUG log with the user_id'); - logger.debug('This is another DEBUG log with the user_id'); - + 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(), - }; // Act & Assess await expect(handler(event, context)).rejects.toThrow(); - const persistentAttribsAfterInvocation = { - ...logger.getPersistentLogAttributes(), - }; - expect(persistentAttribsBeforeInvocation).toEqual({ - foo: 'bar', - biz: 'baz', - }); - expect(persistentAttribsAfterInvocation).toEqual( - persistentAttribsBeforeInvocation + + expect(debugSpy).toHaveBeenCalledTimes(1); + 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', + 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 () => { @@ -1745,10 +2271,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', @@ -1792,10 +2318,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', @@ -1850,10 +2376,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', @@ -1872,16 +2398,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 @@ -1903,19 +2426,19 @@ 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] ); }); - 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', }, }); @@ -2012,6 +2535,7 @@ describe('Class: Logger', () => { ...logLevelThresholds, }, persistentLogAttributes: {}, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -2039,6 +2563,7 @@ describe('Class: Logger', () => { ...logLevelThresholds, }, persistentLogAttributes: {}, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -2066,6 +2591,7 @@ describe('Class: Logger', () => { ...logLevelThresholds, }, persistentLogAttributes: {}, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -2141,6 +2667,7 @@ describe('Class: Logger', () => { ...logLevelThresholds, }, persistentLogAttributes: {}, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -2171,6 +2698,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: '', @@ -2198,6 +2726,7 @@ describe('Class: Logger', () => { ...logLevelThresholds, }, persistentLogAttributes: {}, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -2225,6 +2754,7 @@ describe('Class: Logger', () => { ...logLevelThresholds, }, persistentLogAttributes: {}, + temporaryLogAttributes: {}, powertoolsLogData: { awsRegion: 'eu-west-1', environment: '', @@ -2240,7 +2770,7 @@ describe('Class: Logger', () => { const childLogger = parentLogger.createChild(); // Act - parentLogger.appendKeys({ + parentLogger.appendPersistentKeys({ aws_account_id: '123456789012', aws_region: 'eu-west-1', logger: { @@ -2250,7 +2780,6 @@ describe('Class: Logger', () => { test_key: 'key-for-test', }); const childLoggerWithKeys = parentLogger.createChild(); - childLoggerWithKeys.removeKeys(['test_key']); // Assess expect(childLogger.getPersistentLogAttributes()).toEqual({}); @@ -2262,6 +2791,7 @@ describe('Class: Logger', () => { name: 'aws-lambda-powertool-typescript', version: '0.2.4', }, + test_key: 'key-for-test', }); expect(parentLogger.getPersistentLogAttributes()).toEqual({ @@ -2533,7 +3063,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; @@ -2553,7 +3083,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; @@ -2851,7 +3381,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'; diff --git a/packages/logger/tests/unit/middleware/middy.test.ts b/packages/logger/tests/unit/middleware/middy.test.ts index 5cc612f5eb..eb9c9a7932 100644 --- a/packages/logger/tests/unit/middleware/middy.test.ts +++ b/packages/logger/tests/unit/middleware/middy.test.ts @@ -96,23 +96,156 @@ 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 () => { + 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({ logLevel: 'DEBUG', - persistentLogAttributes: { + }); + logger.appendKeys({ + foo: 'bar', + biz: 'baz', + }); + + const debugSpy = jest.spyOn(logger['console'], 'debug'); + + const handler = middy((): void => { + // 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'); + }).use(injectLambdaContext(logger, { clearState: true })); + + // Act + await handler(event, context); + logger.debug('Checking state after handler execution'); + + // Assess + expect(debugSpy).toHaveBeenCalledTimes(2); + 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', + 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' }, + }) + ); + 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', + 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', + }) + ); + }); + + 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', + persistentLogAttributes: { + foo: 'bar', }, }); + logger.appendKeys({ + biz: 'baz', + }); + + const debugSpy = jest.spyOn(logger['console'], 'debug'); 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' }, }); logger.debug('This is a DEBUG log with the user_id'); + }).use(injectLambdaContext(logger, { clearState: true })); + + // Act + await handler(event, context); + logger.debug('Checking state after handler execution'); + + // Assess + expect(debugSpy).toHaveBeenCalledTimes(2); + 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', + 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' }, + }) + ); + 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', + 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', + }) + ); + }); + + 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', + 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'); logger.debug('This is another DEBUG log with the user_id'); }).use(injectLambdaContext(logger, { clearState: true })); const persistentAttribsBeforeInvocation = { @@ -130,12 +263,14 @@ 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, 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 even if an error is thrown', async () => { // Prepare const logger = new Logger({ logLevel: 'DEBUG', @@ -145,8 +280,8 @@ describe('Middy middleware', () => { }, }); 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'); @@ -167,9 +302,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 () => {