From 6839e6b8a02b56cc6ab7df8f8a8c46df5b94ac62 Mon Sep 17 00:00:00 2001 From: Vishwak Thatikonda Date: Fri, 7 Aug 2026 23:17:30 -0700 Subject: [PATCH] fix(logger): scope debug sampling log level per invocation under LMI concurrency refreshSampleRateCalculation() runs once per invocation and wrote its random sampling decision into the instance-level log level shared by all concurrent invocations. Under Lambda Managed Instances concurrency, whichever invocation's refresh ran last won for every in-flight invocation: sampled-in invocations had their debug logs silently dropped, and sampled-out invocations emitted debug logs they were never sampled for. Store the effective log level in the InvokeStore when concurrency is enabled and an invocation context is active, falling back to the instance level set at initialization. The cold-start refresh guard stays environment-wide so only the first invocation of an environment keeps the boot-time sampling decision. Closes #5542 --- packages/logger/src/Logger.ts | 68 +++++++- .../tests/unit/concurrency/sampling.test.ts | 150 ++++++++++++++++++ 2 files changed, 213 insertions(+), 5 deletions(-) create mode 100644 packages/logger/tests/unit/concurrency/sampling.test.ts diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index b9859f0746..66a60965b4 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -16,6 +16,7 @@ import { getStringFromEnv, getXRayTraceIdFromEnv, isDevMode, + shouldUseInvokeStore, } from '@aws-lambda-powertools/commons/utils/env'; import type { Callback, Context, Handler } from 'aws-lambda'; import { @@ -138,9 +139,21 @@ class Logger extends Utility implements LoggerInterface { private logIndentation: number = LogJsonIndent.COMPACT; /** * Log level used internally by the current instance of Logger. + * + * Holds the level set at initialization time. When invocations run + * concurrently in the same execution environment (Lambda Managed + * Instances), per-invocation changes like the debug sampling decision are + * scoped to the invocation via the InvokeStore, with this field as the + * fallback, see {@link Logger.#getLogLevel | `#getLogLevel()`}. */ private logLevel: number = LogLevelThreshold.INFO; + /** + * Key used to store the per-invocation log level in the InvokeStore when + * concurrency is enabled. + */ + readonly #logLevelKey = Symbol('powertools.logger.logLevel'); + /** * Advanced Logging Control Log Level * If not a valid value this will be left undefined, even if the @@ -251,7 +264,7 @@ class Logger extends Utility implements LoggerInterface { * To get the log level name, use the {@link getLevelName()} method. */ public get level(): number { - return this.logLevel; + return this.#getLogLevel(); } public constructor(options: ConstructorOptions = {}) { @@ -419,7 +432,7 @@ class Logger extends Utility implements LoggerInterface { * To get the log level as a number, use the {@link Logger.level} property. */ public getLevelName(): Uppercase { - return this.getLogLevelNameFromNumber(this.logLevel); + return this.getLogLevelNameFromNumber(this.#getLogLevel()); } /** @@ -593,7 +606,7 @@ class Logger extends Utility implements LoggerInterface { } if ( this.#shouldEnableDebugSampling() && - this.logLevel > LogLevelThreshold.TRACE + this.#getLogLevel() > LogLevelThreshold.TRACE ) { this.setLogLevel('DEBUG'); this.debug('Setting log level to DEBUG due to sampling rate'); @@ -658,12 +671,57 @@ class Logger extends Utility implements LoggerInterface { public setLogLevel(logLevel: LogLevel): void { if (this.awsLogLevelShortCircuit(logLevel)) return; if (this.isValidLogLevel(logLevel)) { - this.logLevel = LogLevelThreshold[logLevel]; + this.#setLogLevel(LogLevelThreshold[logLevel]); } else { throw new Error(`Invalid log level: ${logLevel}`); } } + /** + * Get the log level currently in effect. + * + * When invocations run concurrently in the same execution environment + * (Lambda Managed Instances), a per-invocation log level stored in the + * InvokeStore takes precedence, so changes like the debug sampling decision + * of one invocation don't affect the others. The level set at + * initialization time is the fallback. + */ + #getLogLevel(): number { + if (!shouldUseInvokeStore()) { + return this.logLevel; + } + + if (globalThis.awslambda?.InvokeStore === undefined) { + throw new Error('InvokeStore is not available'); + } + + return ( + (globalThis.awslambda.InvokeStore.get(this.#logLevelKey) as + | number + | undefined) ?? this.logLevel + ); + } + + /** + * Set the log level, scoping it to the current invocation when concurrency + * is enabled and an invocation context is active. Outside an invocation + * context (e.g. during init) the instance level is set instead. + */ + #setLogLevel(logLevel: number): void { + if (shouldUseInvokeStore()) { + if (globalThis.awslambda?.InvokeStore === undefined) { + throw new Error('InvokeStore is not available'); + } + + const store = globalThis.awslambda.InvokeStore; + if (store.hasContext()) { + store.set(this.#logLevelKey, logLevel); + return; + } + } + this.logLevel = logLevel; + } + /** * @deprecated This method is deprecated and will be removed in the future major versions, please use {@link appendPersistentKeys() `appendPersistentKeys()`} instead. */ @@ -1102,7 +1160,7 @@ class Logger extends Utility implements LoggerInterface { return; } - if (logLevel >= this.logLevel) { + if (logLevel >= this.#getLogLevel()) { if (this.#isInitialized) { this.printLog( logLevel, diff --git a/packages/logger/tests/unit/concurrency/sampling.test.ts b/packages/logger/tests/unit/concurrency/sampling.test.ts new file mode 100644 index 0000000000..f4fa1294a1 --- /dev/null +++ b/packages/logger/tests/unit/concurrency/sampling.test.ts @@ -0,0 +1,150 @@ +import { randomInt } from 'node:crypto'; +import { InvokeStore } from '@aws/lambda-invoke-store'; +import { afterEach, beforeEach, describe, expect, it, vi } from 'vitest'; +import { Logger } from '../../../src/index.js'; + +vi.mock('node:crypto', async (importOriginal) => { + const mod = await importOriginal(); + return { ...mod, randomInt: vi.fn(mod.randomInt) }; +}); + +const XRAY_TRACE_ID_KEY = Symbol.for('_AWS_LAMBDA_X_RAY_TRACE_ID'); + +describe('Debug sampling concurrent invocation isolation', () => { + beforeEach(() => { + InvokeStore._testing?.reset(); + vi.stubEnv('POWERTOOLS_DEV', 'true'); + vi.stubEnv('AWS_LAMBDA_MAX_CONCURRENCY', '10'); + vi.clearAllMocks(); + }); + + afterEach(() => { + vi.unstubAllEnvs(); + }); + + describe('InvokeStore error handling', () => { + beforeEach(() => { + vi.stubGlobal('awslambda', undefined); + }); + + afterEach(() => { + vi.unstubAllGlobals(); + }); + + it('throws when reading the log level with InvokeStore unavailable', () => { + // Prepare + const logger = new Logger({ logLevel: 'INFO' }); + + // Act & Assess + expect(() => logger.level).toThrow('InvokeStore is not available'); + }); + + it('throws when setting the log level with InvokeStore unavailable', () => { + // Prepare + const logger = new Logger({ logLevel: 'INFO' }); + + // Act & Assess + expect(() => { + logger.setLogLevel('DEBUG'); + }).toThrow('InvokeStore is not available'); + }); + }); + + it('sets the instance log level when called outside an invocation context', async () => { + // Prepare + await InvokeStore.getInstanceAsync(); + const logger = new Logger({ logLevel: 'INFO' }); + + // Act + logger.setLogLevel('WARN'); + + // Assess + expect(logger.getLevelName()).toBe('WARN'); + }); + + it('applies the debug sampling decision only to the invocation that was sampled', async () => { + // Prepare + // Rolls: constructor -> not sampled (INFO); invocation A's refresh -> + // sampled in (DEBUG); invocation B's refresh -> not sampled (INFO) + vi.mocked(randomInt) + .mockReturnValueOnce(99 as never) + .mockReturnValueOnce(0 as never) + .mockReturnValueOnce(99 as never); + const store = await InvokeStore.getInstanceAsync(); + const logger = new Logger({ logLevel: 'INFO', sampleRateValue: 0.5 }); + // Cold-start invocation: the first refresh keeps the constructor decision + logger.refreshSampleRateCalculation(); + const aStarted = Promise.withResolvers(); + const bRefreshed = Promise.withResolvers(); + + // Act + // Warm invocation A is sampled in by its refresh, emits a debug log, + // yields, invocation B's refresh re-rolls and is NOT sampled, then A + // emits another debug log + const invocationA = store.run( + { [XRAY_TRACE_ID_KEY]: '1-aaaaaaaa-111111111111111111111111' }, + async () => { + logger.refreshSampleRateCalculation(); + logger.debug('A sampled debug log 1'); + aStarted.resolve(); + await bRefreshed.promise; + logger.debug('A sampled debug log 2'); + } + ); + const invocationB = (async () => { + await aStarted.promise; + await store.run( + { [XRAY_TRACE_ID_KEY]: '1-bbbbbbbb-222222222222222222222222' }, + async () => { + logger.refreshSampleRateCalculation(); + logger.debug('B unsampled debug log'); + } + ); + bRefreshed.resolve(); + })(); + await Promise.all([invocationA, invocationB]); + + // Assess + expect(console.debug).toHaveLogged( + expect.objectContaining({ message: 'A sampled debug log 1' }) + ); + expect(console.debug).toHaveLogged( + expect.objectContaining({ message: 'A sampled debug log 2' }) + ); + expect(console.debug).not.toHaveLogged( + expect.objectContaining({ message: 'B unsampled debug log' }) + ); + }); + + it('keeps the invocation-scoped log level from leaking into later invocations', async () => { + // Prepare + const store = await InvokeStore.getInstanceAsync(); + const logger = new Logger({ logLevel: 'INFO' }); + + // Act + // An invocation raises its own verbosity, then a later invocation logs + await store.run( + { [XRAY_TRACE_ID_KEY]: '1-aaaaaaaa-111111111111111111111111' }, + async () => { + logger.setLogLevel('DEBUG'); + logger.debug('debug log from the invocation that opted in'); + } + ); + await store.run( + { [XRAY_TRACE_ID_KEY]: '1-bbbbbbbb-222222222222222222222222' }, + async () => { + logger.debug('debug log from a later invocation'); + } + ); + + // Assess + expect(console.debug).toHaveLogged( + expect.objectContaining({ + message: 'debug log from the invocation that opted in', + }) + ); + expect(console.debug).not.toHaveLogged( + expect.objectContaining({ message: 'debug log from a later invocation' }) + ); + }); +});