From df3cde1aa0fb332726c487ec800e93ec613bda95 Mon Sep 17 00:00:00 2001 From: svozza Date: Mon, 20 Oct 2025 23:51:00 +0100 Subject: [PATCH 1/3] feat(logger): use async local storage for logger --- packages/logger/src/LogAttributesStore.ts | 152 ++++++++ packages/logger/src/Logger.ts | 91 ++--- .../concurrency/logAttributesStore.test.ts | 154 ++++++++ .../tests/unit/concurrency/logger.test.ts | 339 ++++++++++++++++++ .../logger/tests/unit/workingWithkeys.test.ts | 19 + .../unit/concurrency/dimensionsStore.test.ts | 2 +- .../unit/concurrency/metadataStore.test.ts | 2 +- .../tests/unit/concurrency/metrics.test.ts | 2 +- .../unit/concurrency/metricsStore.test.ts | 2 +- packages/metrics/tests/unit/helpers.ts | 134 ------- packages/testing/src/helpers.ts | 134 +++++++ packages/testing/src/index.ts | 3 + 12 files changed, 834 insertions(+), 200 deletions(-) create mode 100644 packages/logger/src/LogAttributesStore.ts create mode 100644 packages/logger/tests/unit/concurrency/logAttributesStore.test.ts create mode 100644 packages/logger/tests/unit/concurrency/logger.test.ts delete mode 100644 packages/metrics/tests/unit/helpers.ts diff --git a/packages/logger/src/LogAttributesStore.ts b/packages/logger/src/LogAttributesStore.ts new file mode 100644 index 0000000000..a274d474ab --- /dev/null +++ b/packages/logger/src/LogAttributesStore.ts @@ -0,0 +1,152 @@ +import { InvokeStore } from '@aws/lambda-invoke-store'; +import type { LogAttributes } from './types/logKeys.js'; + +/** + * Manages storage of log attributes with automatic context detection. + * + * This class abstracts the storage mechanism for log attributes, automatically + * choosing between AsyncLocalStorage (when in async context) and a fallback + * object (when outside async context). The decision is made at runtime on + * every method call to support Lambda's transition to async contexts. + */ +class LogAttributesStore { + readonly #temporaryAttributesKey = Symbol( + 'powertools.logger.temporaryAttributes' + ); + readonly #keysKey = Symbol('powertools.logger.keys'); + + #fallbackTemporaryAttributes: LogAttributes = {}; + readonly #fallbackKeys: Map = new Map(); + #persistentAttributes: LogAttributes = {}; + + #getTemporaryAttributes(): LogAttributes { + if (InvokeStore.getContext() === undefined) { + return this.#fallbackTemporaryAttributes; + } + + let stored = InvokeStore.get(this.#temporaryAttributesKey) as + | LogAttributes + | undefined; + if (stored == null) { + stored = {}; + InvokeStore.set(this.#temporaryAttributesKey, stored); + } + return stored; + } + + #getKeys(): Map { + if (InvokeStore.getContext() === undefined) { + return this.#fallbackKeys; + } + + let stored = InvokeStore.get(this.#keysKey) as + | Map + | undefined; + if (stored == null) { + stored = new Map(); + InvokeStore.set(this.#keysKey, stored); + } + return stored; + } + + public appendTemporaryKeys(attributes: LogAttributes): void { + const tempAttrs = this.#getTemporaryAttributes(); + const keys = this.#getKeys(); + + for (const [key, value] of Object.entries(attributes)) { + tempAttrs[key] = value; + keys.set(key, 'temp'); + } + } + + public removeTemporaryKeys(keys: string[]): void { + const tempAttrs = this.#getTemporaryAttributes(); + const keysMap = this.#getKeys(); + + for (const key of keys) { + tempAttrs[key] = undefined; + + if (this.#persistentAttributes[key]) { + keysMap.set(key, 'persistent'); + } else { + keysMap.delete(key); + } + } + } + + public getTemporaryAttributes(): LogAttributes { + return { ...this.#getTemporaryAttributes() }; + } + + public clearTemporaryAttributes(): void { + const tempAttrs = this.#getTemporaryAttributes(); + const keysMap = this.#getKeys(); + + for (const key of Object.keys(tempAttrs)) { + if (this.#persistentAttributes[key]) { + keysMap.set(key, 'persistent'); + } else { + keysMap.delete(key); + } + } + + if (InvokeStore.getContext() === undefined) { + this.#fallbackTemporaryAttributes = {}; + return; + } + + InvokeStore.set(this.#temporaryAttributesKey, {}); + } + + public setPersistentAttributes(attributes: LogAttributes): void { + const keysMap = this.#getKeys(); + this.#persistentAttributes = { ...attributes }; + + for (const key of Object.keys(attributes)) { + keysMap.set(key, 'persistent'); + } + } + + public getPersistentAttributes(): LogAttributes { + return { ...this.#persistentAttributes }; + } + + public getAllAttributes(): LogAttributes { + const result: LogAttributes = {}; + const tempAttrs = this.#getTemporaryAttributes(); + const keysMap = this.#getKeys(); + + // First add all persistent attributes + for (const [key, value] of Object.entries(this.#persistentAttributes)) { + if (value !== undefined) { + result[key] = value; + } + } + + // Then override with temporary attributes based on keysMap + for (const [key, type] of keysMap.entries()) { + if (type === 'temp' && tempAttrs[key] !== undefined) { + result[key] = tempAttrs[key]; + } + } + + return result; + } + + public removePersistentKeys(keys: string[]): void { + const keysMap = this.#getKeys(); + const tempAttrs = this.#getTemporaryAttributes(); + + for (const key of keys) { + this.#persistentAttributes[key] = undefined; + + if (tempAttrs[key]) { + keysMap.set(key, 'temp'); + } else { + keysMap.delete(key); + } + } + } +} + +export { LogAttributesStore }; diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 9c409d6d26..f66e3de6df 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -24,6 +24,7 @@ import { import type { LogFormatter } from './formatter/LogFormatter.js'; import type { LogItem } from './formatter/LogItem.js'; import { PowertoolsLogFormatter } from './formatter/PowertoolsLogFormatter.js'; +import { LogAttributesStore } from './LogAttributesStore.js'; import { CircularMap } from './logBuffer.js'; import type { ConfigServiceInterface } from './types/ConfigServiceInterface.js'; import type { @@ -142,10 +143,6 @@ class Logger extends Utility implements LoggerInterface { * environment variable AWS_LAMBDA_LOG_LEVEL is set */ #alcLogLevel?: Uppercase; - /** - * Persistent log attributes that will be logged in all log items. - */ - private persistentLogAttributes: LogAttributes = {}; /** * Standard attributes managed by Powertools that will be logged in all log items. */ @@ -153,9 +150,9 @@ class Logger extends Utility implements LoggerInterface { sampleRateValue: 0, }; /** - * Temporary log attributes that can be appended with `appendKeys()` method. + * Store for managing temporary and persistent log attributes. */ - private temporaryLogAttributes: LogKeys = {}; + readonly #attributesStore = new LogAttributesStore(); /** * Buffer used to store logs until the logger is initialized. * @@ -170,13 +167,6 @@ class Logger extends Utility implements LoggerInterface { * Flag used to determine if the logger is initialized. */ readonly #isInitialized: boolean = 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. - */ - readonly #keys: Map = new Map(); /** * This is the initial log leval as set during the initialization of the logger. * @@ -345,7 +335,8 @@ class Logger extends Utility implements LoggerInterface { logFormatter: this.getLogFormatter(), customConfigService: this.getCustomConfigService(), environment: this.powertoolsLogData.environment, - persistentLogAttributes: this.persistentLogAttributes, + persistentLogAttributes: + this.#attributesStore.getPersistentAttributes(), jsonReplacerFn: this.#jsonReplacerFn, correlationIdSearchFn: this.#correlationIdSearchFn, ...(this.#bufferConfig.enabled && { @@ -365,8 +356,9 @@ class Logger extends Utility implements LoggerInterface { childLogger.addContext( this.powertoolsLogData.lambdaContext as unknown as Context ); - if (this.temporaryLogAttributes) { - childLogger.appendKeys(this.temporaryLogAttributes); + const temporaryAttributes = this.#attributesStore.getTemporaryAttributes(); + if (Object.keys(temporaryAttributes).length > 0) { + childLogger.appendKeys(temporaryAttributes); } return childLogger; @@ -431,7 +423,7 @@ class Logger extends Utility implements LoggerInterface { * that will be logged in all log items. */ public getPersistentLogAttributes(): LogAttributes { - return this.persistentLogAttributes; + return this.#attributesStore.getPersistentAttributes(); } /** @@ -604,15 +596,7 @@ class Logger extends Utility implements LoggerInterface { * @param keys - The keys to remove. */ public removeKeys(keys: string[]): void { - for (const key of keys) { - this.temporaryLogAttributes[key] = undefined; - - if (this.persistentLogAttributes[key]) { - this.#keys.set(key, 'persistent'); - } else { - this.#keys.delete(key); - } - } + this.#attributesStore.removeTemporaryKeys(keys); } /** @@ -634,15 +618,7 @@ class Logger extends Utility implements LoggerInterface { * @param keys - The keys to remove from the persistent attributes. */ public removePersistentKeys(keys: string[]): void { - for (const key of keys) { - this.persistentLogAttributes[key] = undefined; - - if (this.temporaryLogAttributes[key]) { - this.#keys.set(key, 'temp'); - } else { - this.#keys.delete(key); - } - } + this.#attributesStore.removePersistentKeys(keys); } /** @@ -656,14 +632,7 @@ class Logger extends Utility implements LoggerInterface { * Remove all temporary log attributes added with {@link appendKeys() `appendKeys()`} method. */ public resetKeys(): 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 = {}; + this.#attributesStore.clearTemporaryAttributes(); } /** @@ -687,7 +656,14 @@ class Logger extends Utility implements LoggerInterface { * @deprecated This method is deprecated and will be removed in the future major versions, please use {@link appendPersistentKeys() `appendPersistentKeys()`} instead. */ public setPersistentLogAttributes(attributes: LogKeys): void { - this.persistentLogAttributes = attributes; + this.#attributesStore.setPersistentAttributes(attributes); + } + + /** + * @deprecated Use getPersistentLogAttributes() instead + */ + public get persistentLogAttributes(): LogKeys { + return this.#attributesStore.getPersistentAttributes(); } /** @@ -810,15 +786,17 @@ class Logger extends Utility implements LoggerInterface { * @param type - The type of the attributes to add. */ #appendKeys(attributes: LogKeys, type: 'temp' | 'persistent'): void { - for (const attributeKey of Object.keys(attributes)) { - if (this.#checkReservedKeyAndWarn(attributeKey) === false) { - this.#keys.set(attributeKey, type); + const filtered: LogKeys = {}; + for (const [key, value] of Object.entries(attributes)) { + if (!this.#checkReservedKeyAndWarn(key)) { + filtered[key] = value; } } if (type === 'temp') { - merge(this.temporaryLogAttributes, attributes); + this.#attributesStore.appendTemporaryKeys(filtered); } else { - merge(this.persistentLogAttributes, attributes); + const current = this.#attributesStore.getPersistentAttributes(); + this.#attributesStore.setPersistentAttributes(merge(current, filtered)); } } @@ -875,18 +853,7 @@ class Logger extends Utility implements LoggerInterface { * Create additional attributes from persistent and temporary keys */ #createAdditionalAttributes(): LogAttributes { - const attributes: LogAttributes = {}; - - for (const [key, type] of this.#keys) { - if (!this.#checkReservedKeyAndWarn(key)) { - attributes[key] = - type === 'persistent' - ? this.persistentLogAttributes[key] - : this.temporaryLogAttributes[key]; - } - } - - return attributes; + return this.#attributesStore.getAllAttributes(); } /** @@ -1568,7 +1535,7 @@ class Logger extends Utility implements LoggerInterface { * Get the correlation ID from the log attributes. */ public getCorrelationId(): unknown { - return this.temporaryLogAttributes.correlation_id; + return this.#attributesStore.getTemporaryAttributes().correlation_id; } } diff --git a/packages/logger/tests/unit/concurrency/logAttributesStore.test.ts b/packages/logger/tests/unit/concurrency/logAttributesStore.test.ts new file mode 100644 index 0000000000..d64b526724 --- /dev/null +++ b/packages/logger/tests/unit/concurrency/logAttributesStore.test.ts @@ -0,0 +1,154 @@ +import { sequence } from '@aws-lambda-powertools/testing-utils'; +import { beforeEach, describe, expect, it, vi } from 'vitest'; +import { LogAttributesStore } from '../../../src/LogAttributesStore.js'; + +describe('LogAttributesStore concurrent invocation isolation', () => { + beforeEach(() => { + vi.clearAllMocks(); + }); + + it.each([ + { + description: 'without InvokeStore', + useInvokeStore: false, + expectedResult1: { key: 'value2' }, + expectedResult2: { key: 'value2' }, + }, + { + description: 'with InvokeStore', + useInvokeStore: true, + expectedResult1: { key: 'value1' }, + expectedResult2: { key: 'value2' }, + }, + ])( + 'handles storing temporary attributes $description', + async ({ useInvokeStore, expectedResult1, expectedResult2 }) => { + // Prepare + const store = new LogAttributesStore(); + + // Act + const [result1, result2] = await sequence( + { + sideEffects: [() => store.appendTemporaryKeys({ key: 'value1' })], + return: () => store.getTemporaryAttributes(), + }, + { + sideEffects: [() => store.appendTemporaryKeys({ key: 'value2' })], + return: () => store.getTemporaryAttributes(), + }, + { useInvokeStore } + ); + + // Assess + expect(result1).toEqual(expectedResult1); + expect(result2).toEqual(expectedResult2); + } + ); + + it.each([ + { + description: 'without InvokeStore', + useInvokeStore: false, + expectedResult1: {}, + expectedResult2: {}, + }, + { + description: 'with InvokeStore', + useInvokeStore: true, + expectedResult1: {}, + expectedResult2: { region: 'us-east-1' }, + }, + ])( + 'handles clearing temporary attributes $description', + async ({ useInvokeStore, expectedResult1, expectedResult2 }) => { + // Prepare + const store = new LogAttributesStore(); + + // Act + const [result1, result2] = await sequence( + { + sideEffects: [ + () => store.appendTemporaryKeys({ env: 'prod' }), + () => {}, // Wait for inv2 to add + () => store.clearTemporaryAttributes(), + ], + return: () => store.getTemporaryAttributes(), + }, + { + sideEffects: [ + () => {}, // Wait for inv1 to add + () => store.appendTemporaryKeys({ region: 'us-east-1' }), + () => {}, // Wait for clear + ], + return: () => store.getTemporaryAttributes(), + }, + { useInvokeStore } + ); + + // Assess + expect(result1).toEqual(expectedResult1); + expect(result2).toEqual(expectedResult2); + } + ); + + it('persistent attributes are shared across invocations', async () => { + // Prepare + const store = new LogAttributesStore(); + store.setPersistentAttributes({ service: 'my-service' }); + + // Act + const [result1, result2] = await sequence( + { + sideEffects: [() => store.appendTemporaryKeys({ env: 'prod' })], + return: () => store.getAllAttributes(), + }, + { + sideEffects: [() => store.appendTemporaryKeys({ env: 'dev' })], + return: () => store.getAllAttributes(), + }, + { useInvokeStore: true } + ); + + // Assess + expect(result1).toEqual({ service: 'my-service', env: 'prod' }); + expect(result2).toEqual({ service: 'my-service', env: 'dev' }); + }); + + it.each([ + { + description: 'without InvokeStore', + useInvokeStore: false, + expectedResult1: { key1: 'value1' }, + expectedResult2: { key1: 'value1' }, + }, + { + description: 'with InvokeStore', + useInvokeStore: true, + expectedResult1: { key1: 'value1' }, + expectedResult2: {}, + }, + ])( + 'isolates temporary keys $description', + async ({ useInvokeStore, expectedResult1, expectedResult2 }) => { + // Prepare + const store = new LogAttributesStore(); + + // Act + const [result1, result2] = await sequence( + { + sideEffects: [() => store.appendTemporaryKeys({ key1: 'value1' })], + return: () => store.getTemporaryAttributes(), + }, + { + sideEffects: [() => {}], // No-op + return: () => store.getTemporaryAttributes(), + }, + { useInvokeStore } + ); + + // Assess + expect(result1).toEqual(expectedResult1); + expect(result2).toEqual(expectedResult2); + } + ); +}); diff --git a/packages/logger/tests/unit/concurrency/logger.test.ts b/packages/logger/tests/unit/concurrency/logger.test.ts new file mode 100644 index 0000000000..53ceccecd1 --- /dev/null +++ b/packages/logger/tests/unit/concurrency/logger.test.ts @@ -0,0 +1,339 @@ +import { sequence } from '@aws-lambda-powertools/testing-utils'; +import { beforeEach, describe, expect, it, vi } from 'vitest'; +import { Logger } from '../../../src/index.js'; + +describe('Logger concurrent invocation isolation', () => { + beforeEach(() => { + vi.stubEnv('POWERTOOLS_DEV', 'true'); + vi.clearAllMocks(); + }); + + it.each([ + { + description: 'without InvokeStore', + useInvokeStore: false, + expectedKeys: [{ env: 'dev', requestId: 'req-2' }], + }, + { + description: 'with InvokeStore', + useInvokeStore: true, + expectedKeys: [ + { env: 'prod', requestId: 'req-1' }, + { env: 'dev', requestId: 'req-2' }, + ], + }, + ])( + 'handles temporary attributes $description', + async ({ useInvokeStore, expectedKeys }) => { + // Prepare + const logger = new Logger({ serviceName: 'test' }); + + // Act + await sequence( + { + sideEffects: [ + () => { + logger.appendKeys({ env: 'prod', requestId: 'req-1' }); + logger.info('Test message'); + }, + ], + return: () => {}, + }, + { + sideEffects: [ + () => { + logger.appendKeys({ env: 'dev', requestId: 'req-2' }); + logger.info('Test message'); + }, + ], + return: () => {}, + }, + { useInvokeStore } + ); + + // Assess + for (const expectedOutput of expectedKeys) { + expect(console.info).toHaveLogged( + expect.objectContaining(expectedOutput) + ); + } + } + ); + + it.each([ + { + description: 'without InvokeStore', + useInvokeStore: false, + expectedKeys: [{ region: 'us-east-1', version: '2.0' }], + }, + { + description: 'with InvokeStore', + useInvokeStore: true, + expectedKeys: [ + { region: 'us-west-2', version: '1.0' }, + { region: 'us-east-1', version: '2.0' }, + ], + }, + ])( + 'handles persistent attributes $description', + async ({ useInvokeStore, expectedKeys }) => { + // Prepare + const logger = new Logger({ + serviceName: 'test', + persistentKeys: { app: 'test' }, + }); + + // Act + await sequence( + { + sideEffects: [ + () => { + logger.appendPersistentKeys({ + region: 'us-west-2', + version: '1.0', + }); + logger.info('Test message'); + }, + ], + return: () => {}, + }, + { + sideEffects: [ + () => { + logger.appendPersistentKeys({ + region: 'us-east-1', + version: '2.0', + }); + logger.info('Test message'); + }, + ], + return: () => {}, + }, + { useInvokeStore } + ); + + // Assess + for (const expectedOutput of expectedKeys) { + expect(console.info).toHaveLogged( + expect.objectContaining(expectedOutput) + ); + } + } + ); + + it.each([ + { + description: 'without InvokeStore', + useInvokeStore: false, + expectedKeys: [{ env: 'dev', requestId: 'req-2' }], + }, + { + description: 'with InvokeStore', + useInvokeStore: true, + expectedKeys: [ + { env: 'prod', requestId: 'req-1' }, + { env: 'dev', requestId: 'req-2' }, + ], + }, + ])( + 'handles mixed temporary and persistent attributes $description', + async ({ useInvokeStore, expectedKeys }) => { + // Prepare + const logger = new Logger({ + serviceName: 'test', + persistentKeys: { app: 'test' }, + }); + + // Act + await sequence( + { + sideEffects: [ + () => { + logger.appendPersistentKeys({ env: 'prod' }); + logger.appendKeys({ requestId: 'req-1' }); + logger.info('Test message'); + }, + ], + return: () => {}, + }, + { + sideEffects: [ + () => { + logger.appendPersistentKeys({ env: 'dev' }); + logger.appendKeys({ requestId: 'req-2' }); + logger.info('Test message'); + }, + ], + return: () => {}, + }, + { useInvokeStore } + ); + + // Assess + for (const expectedOutput of expectedKeys) { + expect(console.info).toHaveLogged( + expect.objectContaining(expectedOutput) + ); + } + } + ); + + it.each([ + { + description: 'without InvokeStore', + useInvokeStore: false, + shouldContain: [], + }, + { + description: 'with InvokeStore', + useInvokeStore: true, + shouldContain: [{ requestId: 'req-2' }], + }, + ])( + 'handles clearing temporary attributes $description', + async ({ useInvokeStore, shouldContain }) => { + // Prepare + const logger = new Logger({ serviceName: 'test' }); + + // Act + await sequence( + { + sideEffects: [ + () => { + logger.appendKeys({ requestId: 'req-1', env: 'prod' }); + }, + () => {}, // Wait for inv2 to add + () => { + logger.resetKeys(); + logger.info('Test message'); + }, + ], + return: () => {}, + }, + { + sideEffects: [ + () => {}, // Wait for inv1 to add + () => { + logger.appendKeys({ requestId: 'req-2' }); + }, + () => { + logger.info('Test message'); + }, + ], + return: () => {}, + }, + { useInvokeStore } + ); + + // Assess + for (const expectedOutput of shouldContain) { + expect(console.info).toHaveLogged( + expect.objectContaining(expectedOutput) + ); + } + } + ); + + it.each([ + { + description: 'without InvokeStore', + useInvokeStore: false, + expectedKeys: [{ requestId: 'req-2' }], + }, + { + description: 'with InvokeStore', + useInvokeStore: true, + expectedKeys: [{ requestId: 'req-1' }, { requestId: 'req-2' }], + }, + ])( + 'handles removing specific temporary keys $description', + async ({ useInvokeStore, expectedKeys }) => { + // Prepare + const logger = new Logger({ serviceName: 'test' }); + + // Act + await sequence( + { + sideEffects: [ + () => { + logger.appendKeys({ requestId: 'req-1', env: 'prod' }); + logger.removeKeys(['env']); + logger.info('Test message'); + }, + ], + return: () => {}, + }, + { + sideEffects: [ + () => { + logger.appendKeys({ requestId: 'req-2', env: 'dev' }); + logger.removeKeys(['env']); + logger.info('Test message'); + }, + ], + return: () => {}, + }, + { useInvokeStore } + ); + + // Assess + for (const expectedOutput of expectedKeys) { + expect(console.info).toHaveLogged( + expect.objectContaining(expectedOutput) + ); + } + } + ); + + it.each([ + { + description: 'without InvokeStore', + useInvokeStore: false, + expectedKeys: [{ correlation_id: 'corr-2' }], + }, + { + description: 'with InvokeStore', + useInvokeStore: true, + expectedKeys: [ + { correlation_id: 'corr-1' }, + { correlation_id: 'corr-2' }, + ], + }, + ])( + 'handles correlation IDs $description', + async ({ useInvokeStore, expectedKeys }) => { + // Prepare + const logger = new Logger({ serviceName: 'test' }); + + // Act + await sequence( + { + sideEffects: [ + () => { + logger.setCorrelationId('corr-1'); + logger.info('Test message'); + }, + ], + return: () => {}, + }, + { + sideEffects: [ + () => { + logger.setCorrelationId('corr-2'); + logger.info('Test message'); + }, + ], + return: () => {}, + }, + { useInvokeStore } + ); + + // Assess + for (const expectedOutput of expectedKeys) { + expect(console.info).toHaveLogged( + expect.objectContaining(expectedOutput) + ); + } + } + ); +}); diff --git a/packages/logger/tests/unit/workingWithkeys.test.ts b/packages/logger/tests/unit/workingWithkeys.test.ts index 64c7b60c67..518e67530d 100644 --- a/packages/logger/tests/unit/workingWithkeys.test.ts +++ b/packages/logger/tests/unit/workingWithkeys.test.ts @@ -527,6 +527,25 @@ describe('Working with keys', () => { }); }); + it('propagates the temporary keys to the child logger instances', () => { + // Prepare + const logger = new Logger(); + logger.appendKeys({ temp: 'value' }); + + // Act + const childLogger = logger.createChild(); + childLogger.info('Hello, world!'); + + // Assess + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, + expect.objectContaining({ + temp: 'value', + }) + ); + }); + it('includes the X-Ray trace data in the log message', () => { // Prepare const logger = new Logger(); diff --git a/packages/metrics/tests/unit/concurrency/dimensionsStore.test.ts b/packages/metrics/tests/unit/concurrency/dimensionsStore.test.ts index f1433e7f5c..7080d79316 100644 --- a/packages/metrics/tests/unit/concurrency/dimensionsStore.test.ts +++ b/packages/metrics/tests/unit/concurrency/dimensionsStore.test.ts @@ -1,6 +1,6 @@ +import { sequence } from '@aws-lambda-powertools/testing-utils'; import { beforeEach, describe, expect, it, vi } from 'vitest'; import { DimensionsStore } from '../../../src/DimensionsStore.js'; -import { sequence } from '../helpers.js'; describe('DimensionsStore concurrent invocation isolation', () => { beforeEach(() => { diff --git a/packages/metrics/tests/unit/concurrency/metadataStore.test.ts b/packages/metrics/tests/unit/concurrency/metadataStore.test.ts index 8e31e45510..0f857e83cf 100644 --- a/packages/metrics/tests/unit/concurrency/metadataStore.test.ts +++ b/packages/metrics/tests/unit/concurrency/metadataStore.test.ts @@ -1,6 +1,6 @@ +import { sequence } from '@aws-lambda-powertools/testing-utils'; import { beforeEach, describe, expect, it, vi } from 'vitest'; import { MetadataStore } from '../../../src/MetadataStore.js'; -import { sequence } from '../helpers.js'; describe('MetadataStore concurrent invocation isolation', () => { beforeEach(() => { diff --git a/packages/metrics/tests/unit/concurrency/metrics.test.ts b/packages/metrics/tests/unit/concurrency/metrics.test.ts index 950a3550a2..f049b90994 100644 --- a/packages/metrics/tests/unit/concurrency/metrics.test.ts +++ b/packages/metrics/tests/unit/concurrency/metrics.test.ts @@ -1,6 +1,6 @@ +import { sequence } from '@aws-lambda-powertools/testing-utils'; import { beforeEach, describe, expect, it, vi } from 'vitest'; import { Metrics, MetricUnit } from '../../../src/index.js'; -import { sequence } from '../helpers.js'; describe('Metrics concurrent invocation isolation', () => { beforeEach(() => { diff --git a/packages/metrics/tests/unit/concurrency/metricsStore.test.ts b/packages/metrics/tests/unit/concurrency/metricsStore.test.ts index 75e83e7254..3969f331d6 100644 --- a/packages/metrics/tests/unit/concurrency/metricsStore.test.ts +++ b/packages/metrics/tests/unit/concurrency/metricsStore.test.ts @@ -1,8 +1,8 @@ +import { sequence } from '@aws-lambda-powertools/testing-utils'; import { beforeEach, describe, expect, it, vi } from 'vitest'; import { MetricUnit } from '../../../src/index.js'; import { MetricsStore } from '../../../src/MetricsStore.js'; import type { StoredMetric } from '../../../src/types/index.js'; -import { sequence } from '../helpers.js'; describe('MetricsStore concurrent invocation isolation', () => { beforeEach(() => { diff --git a/packages/metrics/tests/unit/helpers.ts b/packages/metrics/tests/unit/helpers.ts deleted file mode 100644 index 87eb7973c6..0000000000 --- a/packages/metrics/tests/unit/helpers.ts +++ /dev/null @@ -1,134 +0,0 @@ -import { InvokeStore } from '@aws/lambda-invoke-store'; - -type Invocation = { - sideEffects: (() => void)[]; - return: () => unknown; -}; - -/** - * Creates a Promise with externally accessible resolve and reject functions. - * - * This is a polyfill for the proposed Promise.withResolvers() method that provides - * a more convenient way to create promises that can be resolved or rejected from - * outside the Promise constructor. - * - * We need this polyfill because this function is not available in Node 20. When we drop - * support for this version of Node, then we should remove this function and use the - * inbuilt `Promise.withResolvers` static methods. - * - * @returns Object containing the promise and its resolve/reject functions - * - * @example - * ```typescript - * const { promise, resolve, reject } = withResolvers(); - * - * // Later, from somewhere else: - * resolve('success'); - * - * // Or: - * reject(new Error('failed')); - * ``` - */ -const withResolvers = () => { - let resolve: (value: T) => void = () => {}; - let reject: (reason?: unknown) => void = () => {}; - const promise = new Promise((res, rej) => { - resolve = res; - reject = rej; - }); - return { promise, resolve, reject }; -}; - -/** - * Executes two invocations concurrently with synchronized side effects to test isolation behavior. - * - * This function ensures that side effects are executed in a specific order across both - * invocations using barrier synchronization. Each step waits for the corresponding step - * in the other invocation to complete before proceeding to the next step. - * - * @param inv1 - First invocation configuration - * @param inv1.sideEffects - Array of functions to execute sequentially, synchronized with inv2 - * @param inv1.return - Function to call after all side effects, returns the test result - * @param inv2 - Second invocation configuration - * @param inv2.sideEffects - Array of functions to execute sequentially, synchronized with inv1 - * @param inv2.return - Function to call after all side effects, returns the test result - * @param options - Execution options - * @param options.useInvokeStore - Whether to run invocations in separate InvokeStore contexts - * - `true`: Each invocation runs in its own InvokeStore.run() context (isolated) - * - `false`: Both invocations run in shared context (no isolation) - * - * @returns Promise that resolves to tuple of [inv1Result, inv2Result] - * - * @example - * ```typescript - * // Basic 2-step sequencing: inv1 acts, then inv2 acts - * const [result1, result2] = await sequence({ - * sideEffects: [() => doSomething('A')], - * return: () => getResult() - * }, { - * sideEffects: [() => doSomething('B')], - * return: () => getResult() - * }, { useInvokeStore: true }); - * - * // Execution order: inv1 doSomething('A') → inv2 doSomething('B') → both return - * ``` - * - * @example - * ```typescript - * // Complex 3-step sequencing with barriers - * const [result1, result2] = await sequence({ - * sideEffects: [ - * () => action1(), // Step 1: inv1 acts first - * () => {}, // Step 2: inv1 waits for inv2 - * () => action3() // Step 3: inv1 acts after inv2 - * ], - * return: () => getResult() - * }, { - * sideEffects: [ - * () => {}, // Step 1: inv2 waits for inv1 - * () => action2(), // Step 2: inv2 acts after inv1 - * () => {} // Step 3: inv2 waits for inv1 - * ], - * return: () => getResult() - * }, { useInvokeStore: false }); - * - * // Execution order: action1() → action2() → action3() → both return - * ``` - */ -function sequence( - inv1: Invocation, - inv2: Invocation, - options: { useInvokeStore?: boolean } -) { - const executionEnv = options?.useInvokeStore - ? (f: () => unknown) => InvokeStore.run({}, f) - : (f: () => unknown) => f(); - - const inv1Barriers = inv1.sideEffects.map(() => withResolvers()); - const inv2Barriers = inv2.sideEffects.map(() => withResolvers()); - - const invocation1 = executionEnv(async () => { - for (let i = 0; i < inv1Barriers.length; i++) { - const sideEffect = inv1.sideEffects[i] ?? (() => {}); - sideEffect(); - inv1Barriers[i].resolve(); - await inv2Barriers[i].promise; - } - return inv1.return(); - }); - - const invocation2 = executionEnv(async () => { - for (let i = 0; i < inv2Barriers.length; i++) { - await inv1Barriers[i].promise; - const sideEffect = inv2.sideEffects[i] ?? (() => {}); - sideEffect(); - inv2Barriers[i].resolve(); - } - return inv2.return(); - }); - - return Promise.all([invocation1, invocation2]); -} - -export { withResolvers, sequence }; -export type { Invocation }; diff --git a/packages/testing/src/helpers.ts b/packages/testing/src/helpers.ts index 7df9bc0299..0b2e6fc846 100644 --- a/packages/testing/src/helpers.ts +++ b/packages/testing/src/helpers.ts @@ -1,4 +1,5 @@ import { randomUUID } from 'node:crypto'; +import { InvokeStore } from '@aws/lambda-invoke-store'; import { defaultArchitecture, defaultRuntime, @@ -98,6 +99,136 @@ const findAndGetStackOutputValue = ( return outputs[value]; }; +type Invocation = { + sideEffects: (() => void)[]; + return: () => unknown; +}; + +/** + * Creates a Promise with externally accessible resolve and reject functions. + * + * This is a polyfill for the proposed Promise.withResolvers() method that provides + * a more convenient way to create promises that can be resolved or rejected from + * outside the Promise constructor. + * + * We need this polyfill because this function is not available in Node 20. When we drop + * support for this version of Node, then we should remove this function and use the + * inbuilt `Promise.withResolvers` static methods. + * + * @returns Object containing the promise and its resolve/reject functions + * + * @example + * ```typescript + * const { promise, resolve, reject } = withResolvers(); + * + * // Later, from somewhere else: + * resolve('success'); + * + * // Or: + * reject(new Error('failed')); + * ``` + */ +const withResolvers = () => { + let resolve: (value: T) => void = () => {}; + let reject: (reason?: unknown) => void = () => {}; + const promise = new Promise((res, rej) => { + resolve = res; + reject = rej; + }); + return { promise, resolve, reject }; +}; + +/** + * Executes two invocations concurrently with synchronized side effects to test isolation behavior. + * + * This function ensures that side effects are executed in a specific order across both + * invocations using barrier synchronization. Each step waits for the corresponding step + * in the other invocation to complete before proceeding to the next step. + * + * @param inv1 - First invocation configuration + * @param inv1.sideEffects - Array of functions to execute sequentially, synchronized with inv2 + * @param inv1.return - Function to call after all side effects, returns the test result + * @param inv2 - Second invocation configuration + * @param inv2.sideEffects - Array of functions to execute sequentially, synchronized with inv1 + * @param inv2.return - Function to call after all side effects, returns the test result + * @param options - Execution options + * @param options.useInvokeStore - Whether to run invocations in separate InvokeStore contexts + * - `true`: Each invocation runs in its own InvokeStore.run() context (isolated) + * - `false`: Both invocations run in shared context (no isolation) + * + * @returns Promise that resolves to tuple of [inv1Result, inv2Result] + * + * @example + * ```typescript + * // Basic 2-step sequencing: inv1 acts, then inv2 acts + * const [result1, result2] = await sequence({ + * sideEffects: [() => doSomething('A')], + * return: () => getResult() + * }, { + * sideEffects: [() => doSomething('B')], + * return: () => getResult() + * }, { useInvokeStore: true }); + * + * // Execution order: inv1 doSomething('A') → inv2 doSomething('B') → both return + * ``` + * + * @example + * ```typescript + * // Complex 3-step sequencing with barriers + * const [result1, result2] = await sequence({ + * sideEffects: [ + * () => action1(), // Step 1: inv1 acts first + * () => {}, // Step 2: inv1 waits for inv2 + * () => action3() // Step 3: inv1 acts after inv2 + * ], + * return: () => getResult() + * }, { + * sideEffects: [ + * () => {}, // Step 1: inv2 waits for inv1 + * () => action2(), // Step 2: inv2 acts after inv1 + * () => {} // Step 3: inv2 waits for inv1 + * ], + * return: () => getResult() + * }, { useInvokeStore: false }); + * + * // Execution order: action1() → action2() → action3() → both return + * ``` + */ +function sequence( + inv1: Invocation, + inv2: Invocation, + options: { useInvokeStore?: boolean } +) { + const executionEnv = options?.useInvokeStore + ? (f: () => unknown) => InvokeStore.run({}, f) + : (f: () => unknown) => f(); + + const inv1Barriers = inv1.sideEffects.map(() => withResolvers()); + const inv2Barriers = inv2.sideEffects.map(() => withResolvers()); + + const invocation1 = executionEnv(async () => { + for (let i = 0; i < inv1Barriers.length; i++) { + const sideEffect = inv1.sideEffects[i] ?? (() => {}); + sideEffect(); + inv1Barriers[i].resolve(); + await inv2Barriers[i].promise; + } + return inv1.return(); + }); + + const invocation2 = executionEnv(async () => { + for (let i = 0; i < inv2Barriers.length; i++) { + await inv1Barriers[i].promise; + const sideEffect = inv2.sideEffects[i] ?? (() => {}); + sideEffect(); + inv2Barriers[i].resolve(); + } + return inv2.return(); + }); + + return Promise.all([invocation1, invocation2]); +} + export { isValidRuntimeKey, getRuntimeKey, @@ -105,4 +236,7 @@ export { concatenateResourceName, findAndGetStackOutputValue, getArchitectureKey, + withResolvers, + sequence, }; +export type { Invocation }; diff --git a/packages/testing/src/index.ts b/packages/testing/src/index.ts index 069b562a35..e73f303dc9 100644 --- a/packages/testing/src/index.ts +++ b/packages/testing/src/index.ts @@ -5,6 +5,7 @@ export { TEST_ARCHITECTURES, TEST_RUNTIMES, } from './constants.js'; +export type { Invocation } from './helpers.js'; export { concatenateResourceName, findAndGetStackOutputValue, @@ -12,6 +13,8 @@ export { getArchitectureKey, getRuntimeKey, isValidRuntimeKey, + sequence, + withResolvers, } from './helpers.js'; export { invokeFunction, invokeFunctionOnce } from './invokeTestFunction.js'; export { TestInvocationLogs } from './TestInvocationLogs.js'; From deee4b3d1a81939c1a2ef896f615c9258b296f8e Mon Sep 17 00:00:00 2001 From: svozza Date: Wed, 22 Oct 2025 23:55:37 +0100 Subject: [PATCH 2/3] add reserved key filter logic to setPersistentLogAttributes --- packages/logger/src/Logger.ts | 29 +++++++++---------- .../logger/tests/unit/workingWithkeys.test.ts | 28 ++++++++++++++++++ 2 files changed, 42 insertions(+), 15 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index f66e3de6df..4276437f83 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -656,7 +656,8 @@ class Logger extends Utility implements LoggerInterface { * @deprecated This method is deprecated and will be removed in the future major versions, please use {@link appendPersistentKeys() `appendPersistentKeys()`} instead. */ public setPersistentLogAttributes(attributes: LogKeys): void { - this.#attributesStore.setPersistentAttributes(attributes); + const filtered = this.#filterReservedAttributeKeys(attributes); + this.#attributesStore.setPersistentAttributes(filtered); } /** @@ -779,6 +780,16 @@ class Logger extends Utility implements LoggerInterface { merge(this.powertoolsLogData, attributes); } + #filterReservedAttributeKeys(attributes: LogKeys) { + const filtered: LogKeys = {}; + for (const [key, value] of Object.entries(attributes)) { + if (!this.#checkReservedKeyAndWarn(key)) { + filtered[key] = value; + } + } + return filtered; + } + /** * Shared logic for adding keys to the logger instance. * @@ -786,12 +797,7 @@ class Logger extends Utility implements LoggerInterface { * @param type - The type of the attributes to add. */ #appendKeys(attributes: LogKeys, type: 'temp' | 'persistent'): void { - const filtered: LogKeys = {}; - for (const [key, value] of Object.entries(attributes)) { - if (!this.#checkReservedKeyAndWarn(key)) { - filtered[key] = value; - } - } + const filtered = this.#filterReservedAttributeKeys(attributes); if (type === 'temp') { this.#attributesStore.appendTemporaryKeys(filtered); } else { @@ -834,7 +840,7 @@ class Logger extends Utility implements LoggerInterface { ...this.getPowertoolsLogData(), message: '', }; - const additionalAttributes = this.#createAdditionalAttributes(); + const additionalAttributes = this.#attributesStore.getAllAttributes(); this.#processMainInput( input, @@ -849,13 +855,6 @@ class Logger extends Utility implements LoggerInterface { ); } - /** - * Create additional attributes from persistent and temporary keys - */ - #createAdditionalAttributes(): LogAttributes { - return this.#attributesStore.getAllAttributes(); - } - /** * Process the main input message and add it to the attributes */ diff --git a/packages/logger/tests/unit/workingWithkeys.test.ts b/packages/logger/tests/unit/workingWithkeys.test.ts index 518e67530d..d575f1ecc7 100644 --- a/packages/logger/tests/unit/workingWithkeys.test.ts +++ b/packages/logger/tests/unit/workingWithkeys.test.ts @@ -619,6 +619,34 @@ describe('Working with keys', () => { ); }); + it('does not allow reserved keys with the deprecated setPersistentLogAttributes() method', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.setPersistentLogAttributes({ + // @ts-expect-error - testing invalid key at runtime + level: 'bar', + }); + + logger.info('test'); + + expect(console.info).toHaveLoggedNth( + 1, + expect.objectContaining({ + level: 'INFO', + }) + ); + + // Assess + expect(console.warn).toHaveLoggedNth( + 1, + expect.objectContaining({ + message: 'The key "level" is a reserved key and will be dropped.', + }) + ); + }); + it('logs a warning when using both the deprecated persistentLogAttributes and persistentKeys options', () => { // Prepare new Logger({ From 3c9ac2f0fa30f32accf34f93283e58db10d3da89 Mon Sep 17 00:00:00 2001 From: svozza Date: Tue, 28 Oct 2025 23:09:09 +0000 Subject: [PATCH 3/3] update package-lock.json file --- package-lock.json | 10 ++++++++++ packages/logger/package.json | 1 + 2 files changed, 11 insertions(+) diff --git a/package-lock.json b/package-lock.json index 23445f8192..c311cd4677 100644 --- a/package-lock.json +++ b/package-lock.json @@ -10793,6 +10793,7 @@ "license": "MIT-0", "dependencies": { "@aws-lambda-powertools/commons": "2.28.1", + "@aws/lambda-invoke-store": "0.1.1", "lodash.merge": "^4.6.2" }, "devDependencies": { @@ -10812,6 +10813,15 @@ } } }, + "packages/logger/node_modules/@aws/lambda-invoke-store": { + "version": "0.1.1", + "resolved": "https://registry.npmjs.org/@aws/lambda-invoke-store/-/lambda-invoke-store-0.1.1.tgz", + "integrity": "sha512-RcLam17LdlbSOSp9VxmUu1eI6Mwxp+OwhD2QhiSNmNCzoDb0EeUXTD2n/WbcnrAYMGlmf05th6QYq23VqvJqpA==", + "license": "Apache-2.0", + "engines": { + "node": ">=18.0.0" + } + }, "packages/metrics": { "name": "@aws-lambda-powertools/metrics", "version": "2.28.1", diff --git a/packages/logger/package.json b/packages/logger/package.json index b5276cd0a4..b971014b14 100644 --- a/packages/logger/package.json +++ b/packages/logger/package.json @@ -99,6 +99,7 @@ }, "dependencies": { "@aws-lambda-powertools/commons": "2.28.1", + "@aws/lambda-invoke-store": "0.1.1", "lodash.merge": "^4.6.2" }, "keywords": [