From 2b013424227623ab0eae4b129ce6c3a3458b99b5 Mon Sep 17 00:00:00 2001 From: Alexander Schueren Date: Mon, 24 Feb 2025 12:59:30 +0100 Subject: [PATCH 1/5] feat(logger): refresh sample rate calculation before each invocation in logger context --- packages/logger/src/Logger.ts | 1 + packages/logger/src/middleware/middy.ts | 3 ++ .../tests/unit/injectLambdaContext.test.ts | 36 +++++++++++++++++++ 3 files changed, 40 insertions(+) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 35397f7659..0684dec973 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -413,6 +413,7 @@ class Logger extends Utility implements LoggerInterface { context, callback ) { + loggerRef.refreshSampleRateCalculation(); Logger.injectLambdaContextBefore(loggerRef, event, context, options); let result: unknown; diff --git a/packages/logger/src/middleware/middy.ts b/packages/logger/src/middleware/middy.ts index e399c1bae8..804444c4b4 100644 --- a/packages/logger/src/middleware/middy.ts +++ b/packages/logger/src/middleware/middy.ts @@ -87,6 +87,9 @@ const injectLambdaContext = ( if (isResetStateEnabled) { setCleanupFunction(request); } + + logger.refreshSampleRateCalculation(); + Logger.injectLambdaContextBefore( logger, request.event, diff --git a/packages/logger/tests/unit/injectLambdaContext.test.ts b/packages/logger/tests/unit/injectLambdaContext.test.ts index e7107ad94a..e51a163a65 100644 --- a/packages/logger/tests/unit/injectLambdaContext.test.ts +++ b/packages/logger/tests/unit/injectLambdaContext.test.ts @@ -184,4 +184,40 @@ describe('Inject Lambda Context', () => { }) ); }); + + it('refreshes sample rate calculation before each invocation using decorator', async () => { + // Prepare + const logger = new Logger({ sampleRateValue: 0.5 }); + const refreshSpy = vi.spyOn(logger, 'refreshSampleRateCalculation'); + + class Lambda { + @logger.injectLambdaContext() + public async handler(_event: unknown, _context: Context): Promise { + logger.info('test'); + } + } + const lambda = new Lambda(); + + // Act + await lambda.handler({}, {} as Context); + + // Assess + expect(refreshSpy).toHaveBeenCalledTimes(1); + }); + + it('refreshes sample rate calculation before each invocation using middleware', async () => { + // Prepare + const logger = new Logger({ sampleRateValue: 0.5 }); + const refreshSpy = vi.spyOn(logger, 'refreshSampleRateCalculation'); + + const handler = middy(async () => { + logger.info('Hello, world!'); + }).use(injectLambdaContext(logger)); + + // Act + await handler(event, context); + + // Assess + expect(refreshSpy).toHaveBeenCalledTimes(1); + }); }); From 80ce1e7987f8f2b6f4bab1f3ba3ebcd23147a6ba Mon Sep 17 00:00:00 2001 From: Alexander Schueren Date: Mon, 24 Feb 2025 13:09:26 +0100 Subject: [PATCH 2/5] docs(logger): update sampling documentation to clarify refresh behavior for invocations --- docs/core/logger.md | 7 +++---- examples/snippets/logger/logSampling.ts | 2 ++ 2 files changed, 5 insertions(+), 4 deletions(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index 0a0ea34bcc..6a1d918d53 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -634,7 +634,7 @@ Once a child logger is created, the logger and its parent will act as separate i ### Sampling debug logs -Use sampling when you want to dynamically change your log level to **DEBUG** based on a **percentage of your concurrent/cold start invocations**. +Use sampling when you want to dynamically change your log level to **DEBUG** based on a **percentage of your concurrent invocations**. You can use values ranging from `0` to `1` (100%) when setting the `sampleRateValue` constructor option or `POWERTOOLS_LOGGER_SAMPLE_RATE` env var. @@ -643,10 +643,9 @@ You can use values ranging from `0` to `1` (100%) when setting the `sampleRateVa This feature takes into account transient issues where additional debugging information can be useful. -Sampling decision happens at the Logger initialization. This means sampling may happen significantly more or less than depending on your traffic patterns, for example a steady low number of invocations and thus few cold starts. +Sampling decision happens at the Logger initialization. When using the `injectLambdaContext` method either as a decorator or middleware, the sampling decision is refreshed at the beginning of each Lambda invocation for you. -!!! note - Open a [feature request](https://github.com/aws-powertools/powertools-lambda-typescript/issues/new?assignees=&labels=type%2Ffeature-request%2Ctriage&projects=aws-powertools%2F7&template=feature_request.yml&title=Feature+request%3A+TITLE) if you want Logger to calculate sampling for every invocation +If you're not using either of these, you'll need to manually call the `refreshSamplingRate()` function at the start of your handler to refresh the sampling decision for each invocation. === "handler.ts" diff --git a/examples/snippets/logger/logSampling.ts b/examples/snippets/logger/logSampling.ts index ea808f18ca..0067afb73f 100644 --- a/examples/snippets/logger/logSampling.ts +++ b/examples/snippets/logger/logSampling.ts @@ -10,6 +10,8 @@ export const handler = async ( _event: unknown, _context: unknown ): Promise => { + // Refresh sample rate calculation on runtime, only when not using injectLambdaContext + logger.refreshSampleRateCalculation(); // This log item (equal to log level 'ERROR') will be printed to standard output // in all Lambda invocations logger.error('This is an ERROR log'); From a5e70657dfbb44894b4797dbdbda3ec45641c6b9 Mon Sep 17 00:00:00 2001 From: Alexander Schueren Date: Thu, 27 Feb 2025 14:30:26 +0100 Subject: [PATCH 3/5] fix(logger): update sampling behavior to avoid double sampling on cold starts --- docs/core/logger.md | 2 +- packages/commons/src/Utility.ts | 2 +- packages/logger/src/Logger.ts | 8 +++++++- packages/logger/tests/unit/injectLambdaContext.test.ts | 5 ++--- packages/logger/tests/unit/sampling.test.ts | 4 +++- 5 files changed, 14 insertions(+), 7 deletions(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index 6a1d918d53..69fc7a6c7e 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -643,7 +643,7 @@ You can use values ranging from `0` to `1` (100%) when setting the `sampleRateVa This feature takes into account transient issues where additional debugging information can be useful. -Sampling decision happens at the Logger initialization. When using the `injectLambdaContext` method either as a decorator or middleware, the sampling decision is refreshed at the beginning of each Lambda invocation for you. +Sampling decision happens at the Logger initialization. When using the `injectLambdaContext` method either as a decorator or middleware, the sampling decision is refreshed at the beginning of each Lambda invocation for you, except for cold starts. If you're not using either of these, you'll need to manually call the `refreshSamplingRate()` function at the start of your handler to refresh the sampling decision for each invocation. diff --git a/packages/commons/src/Utility.ts b/packages/commons/src/Utility.ts index 4a79cc82dc..cd2e6e0a4d 100644 --- a/packages/commons/src/Utility.ts +++ b/packages/commons/src/Utility.ts @@ -51,7 +51,7 @@ * ``` */ export class Utility { - private coldStart = true; + protected coldStart = true; private readonly defaultServiceName: string = 'service_undefined'; /** diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 0684dec973..f2902b172d 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -490,7 +490,13 @@ class Logger extends Utility implements LoggerInterface { * potentially yielding a different outcome. */ public refreshSampleRateCalculation(): void { - this.setInitialSampleRate(this.powertoolsLogData.sampleRateValue); + /** + * we don't want to refresh the sample rate for cold starts + * because it might lead to double sampling, one in constructor and one here + */ + if (!this.coldStart) { + this.setInitialSampleRate(this.powertoolsLogData.sampleRateValue); + } } /** diff --git a/packages/logger/tests/unit/injectLambdaContext.test.ts b/packages/logger/tests/unit/injectLambdaContext.test.ts index e51a163a65..36c6d7c6fa 100644 --- a/packages/logger/tests/unit/injectLambdaContext.test.ts +++ b/packages/logger/tests/unit/injectLambdaContext.test.ts @@ -185,7 +185,7 @@ describe('Inject Lambda Context', () => { ); }); - it('refreshes sample rate calculation before each invocation using decorator', async () => { + it('refreshes sample rate calculation before each invocation using decorator for warm start only', async () => { // Prepare const logger = new Logger({ sampleRateValue: 0.5 }); const refreshSpy = vi.spyOn(logger, 'refreshSampleRateCalculation'); @@ -197,7 +197,6 @@ describe('Inject Lambda Context', () => { } } const lambda = new Lambda(); - // Act await lambda.handler({}, {} as Context); @@ -205,7 +204,7 @@ describe('Inject Lambda Context', () => { expect(refreshSpy).toHaveBeenCalledTimes(1); }); - it('refreshes sample rate calculation before each invocation using middleware', async () => { + it('refreshes sample rate calculation before each invocation using middleware for warm start only', async () => { // Prepare const logger = new Logger({ sampleRateValue: 0.5 }); const refreshSpy = vi.spyOn(logger, 'refreshSampleRateCalculation'); diff --git a/packages/logger/tests/unit/sampling.test.ts b/packages/logger/tests/unit/sampling.test.ts index 086be99908..2453afc7f3 100644 --- a/packages/logger/tests/unit/sampling.test.ts +++ b/packages/logger/tests/unit/sampling.test.ts @@ -129,13 +129,15 @@ describe('Log sampling', () => { expect(logger.getLevelName()).toBe(LogLevel.INFO); }); - it('when sample rate calculation is refreshed, it respects probability sampling and change log level to DEBUG ', () => { + it('when sample rate calculation is refreshed, it respects probability sampling and change log level to DEBUG when not in coldStart ', () => { // Prepare const logger = new Logger({ logLevel: LogLevel.ERROR, sampleRateValue: 0.1, // 10% probability }); + logger.getColdStart(); // Set coldStart to false + let logLevelChangedToDebug = 0; const numOfIterations = 1000; const minExpected = numOfIterations * 0.05; // Min expected based on 5% probability From 7b96a23185573a91818e4ad3cb67ed3c5de0f6fd Mon Sep 17 00:00:00 2001 From: Alexander Schueren Date: Thu, 27 Feb 2025 14:37:10 +0100 Subject: [PATCH 4/5] docs(logger): update sampling documentation to clarify log level change based on invocation percentage --- docs/core/logger.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index 69fc7a6c7e..9133eead82 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -634,7 +634,7 @@ Once a child logger is created, the logger and its parent will act as separate i ### Sampling debug logs -Use sampling when you want to dynamically change your log level to **DEBUG** based on a **percentage of your concurrent invocations**. +Use sampling when you want to dynamically change your log level to **DEBUG** based on a **percentage of your invocations**. You can use values ranging from `0` to `1` (100%) when setting the `sampleRateValue` constructor option or `POWERTOOLS_LOGGER_SAMPLE_RATE` env var. From 8ee14416e813d5ad26cb96709ce4d74874012f0f Mon Sep 17 00:00:00 2001 From: Alexander Schueren Date: Thu, 27 Feb 2025 15:04:03 +0100 Subject: [PATCH 5/5] fix(logger): move comment to doc strings --- packages/logger/src/Logger.ts | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 3a3369db83..bb93df7d32 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -494,12 +494,10 @@ class Logger extends Utility implements LoggerInterface { * This method allows recalculating the initial sampling decision for changing * the log level to DEBUG based on a sample rate value used during initialization, * potentially yielding a different outcome. + * + * This only works for warm starts, because we don't to avoid double sampling. */ public refreshSampleRateCalculation(): void { - /** - * we don't want to refresh the sample rate for cold starts - * because it might lead to double sampling, one in constructor and one here - */ if (!this.coldStart) { this.setInitialSampleRate(this.powertoolsLogData.sampleRateValue); }