From b234e4d06d8d16501a161fbcd74a6581c2d8202b Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Mon, 3 Mar 2025 14:52:35 +0000 Subject: [PATCH 1/8] Add clearBuffer method The clearBuffer method clears the logger buffer. --- packages/logger/src/Logger.ts | 15 +++++++++++++++ 1 file changed, 15 insertions(+) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index d83c26bc66..1c4e958120 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -1361,6 +1361,21 @@ class Logger extends Utility implements LoggerInterface { this.#buffer?.delete(traceId); } + + /** + * Empties the buffer for the current request + * + */ + public clearBuffer(): void { + const traceId = this.envVarsService.getXrayTraceId(); + + if (traceId === undefined) { + return; + } + + this.#buffer?.delete(traceId); + } + /** * Test if the log meets the criteria to be buffered. * From 808cc79505e333b7b842f3909565ecfa64368f7d Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Mon, 3 Mar 2025 14:53:22 +0000 Subject: [PATCH 2/8] Flush buffer on uncaught error in middy middleware --- packages/logger/src/middleware/middy.ts | 30 +++++++++++----- packages/logger/tests/unit/logBuffer.test.ts | 37 ++++++++++++++++++++ 2 files changed, 59 insertions(+), 8 deletions(-) diff --git a/packages/logger/src/middleware/middy.ts b/packages/logger/src/middleware/middy.ts index 804444c4b4..2af8559d54 100644 --- a/packages/logger/src/middleware/middy.ts +++ b/packages/logger/src/middleware/middy.ts @@ -4,6 +4,7 @@ import type { MiddyLikeRequest, } from '@aws-lambda-powertools/commons/types'; import { Logger } from '../Logger.js'; +import { UncaughtErrorLogMessage } from '../constants.js'; import type { InjectLambdaContextOptions } from '../types/Logger.js'; /** @@ -76,13 +77,11 @@ const injectLambdaContext = ( const setCleanupFunction = (request: MiddyLikeRequest): void => { request.internal = { ...request.internal, - [LOGGER_KEY]: injectLambdaContextAfterOrOnError, + [LOGGER_KEY]: onAfter, }; }; - const injectLambdaContextBefore = async ( - request: MiddyLikeRequest - ): Promise => { + const onBefore = async (request: MiddyLikeRequest): Promise => { for (const logger of loggers) { if (isResetStateEnabled) { setCleanupFunction(request); @@ -99,18 +98,33 @@ const injectLambdaContext = ( } }; - const injectLambdaContextAfterOrOnError = async (): Promise => { + const onAfter = async (): Promise => { if (isResetStateEnabled) { for (const logger of loggers) { logger.resetKeys(); } } + + for (const logger of loggers) { + logger.clearBuffer(); + } + }; + const onError = async ({ error }): Promise => { + if (options?.flushBufferOnUncaughtError) { + for (const logger of loggers) { + logger.flushBuffer(); + logger.error({ + message: UncaughtErrorLogMessage, + error, + }); + } + } }; return { - before: injectLambdaContextBefore, - after: injectLambdaContextAfterOrOnError, - onError: injectLambdaContextAfterOrOnError, + before: onBefore, + after: onAfter, + onError, }; }; diff --git a/packages/logger/tests/unit/logBuffer.test.ts b/packages/logger/tests/unit/logBuffer.test.ts index 4ec8fb1061..d8b422f6ef 100644 --- a/packages/logger/tests/unit/logBuffer.test.ts +++ b/packages/logger/tests/unit/logBuffer.test.ts @@ -1,8 +1,10 @@ import context from '@aws-lambda-powertools/testing-utils/context'; import type { Context } from 'aws-lambda'; +import middy from 'middy5'; import { type Mock, beforeEach, describe, expect, it, vi } from 'vitest'; import { Logger } from '../../src/Logger.js'; import { LogLevel, UncaughtErrorLogMessage } from '../../src/constants.js'; +import { injectLambdaContext } from '../../src/middleware/middy.js'; import type { ConstructorOptions } from '../../src/types/Logger.js'; describe('Buffer logs', () => { @@ -227,6 +229,41 @@ describe('Buffer logs', () => { const lambda = new TestClass(); const handler = lambda.handler.bind(lambda); + // Act & Assess + await expect(() => + handler( + { + foo: 'bar', + }, + context + ) + ).rejects.toThrow(new Error('This is an error')); + expect(console.debug).toBeCalledTimes(1); + expect(console.info).toBeCalledTimes(1); + expect(console.error).toHaveLogged( + expect.objectContaining({ + message: UncaughtErrorLogMessage, + }) + ); + // If debug is called after info, it means it was buffered and then flushed + expect(console.debug).toHaveBeenCalledAfter(console.info as Mock); + // If error is called after debug, it means the buffer was flushed before the error log + expect(console.debug).toHaveBeenCalledBefore(console.error as Mock); + }); + it('flushes the buffer when an uncaught error is thrown in a middy', async () => { + // Prepare + const logger = new Logger({ logBufferOptions: { enabled: true } }); + + const handlerFn = async (_event: unknown, _context: Context) => { + logger.debug('This is a log message'); + logger.info('This is an info message'); + throw new Error('This is an error'); + }; + + const handler = middy() + .use(injectLambdaContext(logger, { flushBufferOnUncaughtError: true })) + .handler(handlerFn); + // Act & Assess await expect(() => handler( From bf767927354ba3935dac5ad4f2e1231cde79d387 Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Mon, 3 Mar 2025 14:58:22 +0000 Subject: [PATCH 3/8] Add test for case where clearBuffer is called without a traceId --- packages/logger/tests/unit/logBuffer.test.ts | 11 +++++++++++ 1 file changed, 11 insertions(+) diff --git a/packages/logger/tests/unit/logBuffer.test.ts b/packages/logger/tests/unit/logBuffer.test.ts index d8b422f6ef..c993cc33ae 100644 --- a/packages/logger/tests/unit/logBuffer.test.ts +++ b/packages/logger/tests/unit/logBuffer.test.ts @@ -197,6 +197,17 @@ describe('Buffer logs', () => { ); }); + it('it safely short circuits when clearBuffer is called without a trace id', () => { + // Prepare + process.env._X_AMZN_TRACE_ID = undefined; + const logger = new Logger({ + logLevel: LogLevel.ERROR, + logBufferOptions: { enabled: true, bufferAtVerbosity: LogLevel.DEBUG }, + }); + + // Assess + expect(() => logger.clearBuffer()).not.toThrow(); + }); it('it flushes the buffer when an error in logged', () => { // Prepare const logger = new Logger({ From 9498e843d58d719cde12cd40e34a62e8aebe0e8d Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Mon, 3 Mar 2025 15:02:07 +0000 Subject: [PATCH 4/8] Test clearBuffer --- packages/logger/tests/unit/logBuffer.test.ts | 17 +++++++++++++++++ 1 file changed, 17 insertions(+) diff --git a/packages/logger/tests/unit/logBuffer.test.ts b/packages/logger/tests/unit/logBuffer.test.ts index c993cc33ae..170570b582 100644 --- a/packages/logger/tests/unit/logBuffer.test.ts +++ b/packages/logger/tests/unit/logBuffer.test.ts @@ -208,6 +208,23 @@ describe('Buffer logs', () => { // Assess expect(() => logger.clearBuffer()).not.toThrow(); }); + + it('it clears the buffer', () => { + // Prepare + const logger = new Logger({ + logLevel: LogLevel.ERROR, + logBufferOptions: { enabled: true, bufferAtVerbosity: LogLevel.DEBUG }, + }); + + // Arrange + logger.debug('This is a log message'); + logger.clearBuffer(); + + logger.flushBuffer(); + + // Assess + expect(console.debug).not.toBeCalled; + }); it('it flushes the buffer when an error in logged', () => { // Prepare const logger = new Logger({ From 02e1440d6d1de29fe74561b2749c3b6cf470c4bb Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Tue, 4 Mar 2025 10:46:50 +0000 Subject: [PATCH 5/8] Incorporate feedback --- packages/logger/src/middleware/middy.ts | 23 ++-- packages/logger/tests/unit/logBuffer.test.ts | 126 +++++++++---------- 2 files changed, 68 insertions(+), 81 deletions(-) diff --git a/packages/logger/src/middleware/middy.ts b/packages/logger/src/middleware/middy.ts index 2af8559d54..45ccb82d70 100644 --- a/packages/logger/src/middleware/middy.ts +++ b/packages/logger/src/middleware/middy.ts @@ -77,11 +77,11 @@ const injectLambdaContext = ( const setCleanupFunction = (request: MiddyLikeRequest): void => { request.internal = { ...request.internal, - [LOGGER_KEY]: onAfter, + [LOGGER_KEY]: after, }; }; - const onBefore = async (request: MiddyLikeRequest): Promise => { + const before = async (request: MiddyLikeRequest): Promise => { for (const logger of loggers) { if (isResetStateEnabled) { setCleanupFunction(request); @@ -98,18 +98,17 @@ const injectLambdaContext = ( } }; - const onAfter = async (): Promise => { - if (isResetStateEnabled) { - for (const logger of loggers) { - logger.resetKeys(); - } - } - + const after = async (): Promise => { for (const logger of loggers) { logger.clearBuffer(); + + if (isResetStateEnabled) { + logger.resetKeys(); + } } }; - const onError = async ({ error }): Promise => { + + const onError = async ({ error }: { error: unknown }): Promise => { if (options?.flushBufferOnUncaughtError) { for (const logger of loggers) { logger.flushBuffer(); @@ -122,8 +121,8 @@ const injectLambdaContext = ( }; return { - before: onBefore, - after: onAfter, + before, + after, onError, }; }; diff --git a/packages/logger/tests/unit/logBuffer.test.ts b/packages/logger/tests/unit/logBuffer.test.ts index 170570b582..675dae48be 100644 --- a/packages/logger/tests/unit/logBuffer.test.ts +++ b/packages/logger/tests/unit/logBuffer.test.ts @@ -243,74 +243,62 @@ describe('Buffer logs', () => { expect(console.error).toBeCalledTimes(1); }); - it('flushes the buffer when an uncaught error is thrown', async () => { - // Prepare - const logger = new Logger({ logBufferOptions: { enabled: true } }); - class TestClass { - @logger.injectLambdaContext({ flushBufferOnUncaughtError: true }) - async handler(_event: unknown, _context: Context) { - logger.debug('This is a log message'); - logger.info('This is an info message'); - throw new Error('This is an error'); - } + it.each([ + { + handlerFactory: (logger: Logger) => + middy() + .use( + injectLambdaContext(logger, { flushBufferOnUncaughtError: true }) + ) + .handler(async () => { + logger.debug('This is a log message'); + logger.info('This is an info message'); + throw new Error('This is an error'); + }), + case: 'middleware', + }, + { + handlerFactory: (logger: Logger) => { + class TestClass { + @logger.injectLambdaContext({ flushBufferOnUncaughtError: true }) + async handler(_event: unknown, _context: Context) { + logger.debug('This is a log message'); + logger.info('This is an info message'); + throw new Error('This is an error'); + } + } + const lambda = new TestClass(); + return lambda.handler.bind(lambda); + }, + case: 'decorator', + }, + ])( + 'flushes the buffer when an uncaught error is thrown ($case)', + async ({ handlerFactory }) => { + // Prepare + const logger = new Logger({ logBufferOptions: { enabled: true } }); + const handler = handlerFactory(logger); + + // Act & Assess + await expect(() => + handler( + { + foo: 'bar', + }, + context + ) + ).rejects.toThrow(new Error('This is an error')); + expect(console.debug).toBeCalledTimes(1); + expect(console.info).toBeCalledTimes(1); + expect(console.error).toHaveLogged( + expect.objectContaining({ + message: UncaughtErrorLogMessage, + }) + ); + // If debug is called after info, it means it was buffered and then flushed + expect(console.debug).toHaveBeenCalledAfter(console.info as Mock); + // If error is called after debug, it means the buffer was flushed before the error log + expect(console.debug).toHaveBeenCalledBefore(console.error as Mock); } - const lambda = new TestClass(); - const handler = lambda.handler.bind(lambda); - - // Act & Assess - await expect(() => - handler( - { - foo: 'bar', - }, - context - ) - ).rejects.toThrow(new Error('This is an error')); - expect(console.debug).toBeCalledTimes(1); - expect(console.info).toBeCalledTimes(1); - expect(console.error).toHaveLogged( - expect.objectContaining({ - message: UncaughtErrorLogMessage, - }) - ); - // If debug is called after info, it means it was buffered and then flushed - expect(console.debug).toHaveBeenCalledAfter(console.info as Mock); - // If error is called after debug, it means the buffer was flushed before the error log - expect(console.debug).toHaveBeenCalledBefore(console.error as Mock); - }); - it('flushes the buffer when an uncaught error is thrown in a middy', async () => { - // Prepare - const logger = new Logger({ logBufferOptions: { enabled: true } }); - - const handlerFn = async (_event: unknown, _context: Context) => { - logger.debug('This is a log message'); - logger.info('This is an info message'); - throw new Error('This is an error'); - }; - - const handler = middy() - .use(injectLambdaContext(logger, { flushBufferOnUncaughtError: true })) - .handler(handlerFn); - - // Act & Assess - await expect(() => - handler( - { - foo: 'bar', - }, - context - ) - ).rejects.toThrow(new Error('This is an error')); - expect(console.debug).toBeCalledTimes(1); - expect(console.info).toBeCalledTimes(1); - expect(console.error).toHaveLogged( - expect.objectContaining({ - message: UncaughtErrorLogMessage, - }) - ); - // If debug is called after info, it means it was buffered and then flushed - expect(console.debug).toHaveBeenCalledAfter(console.info as Mock); - // If error is called after debug, it means the buffer was flushed before the error log - expect(console.debug).toHaveBeenCalledBefore(console.error as Mock); - }); + ); }); From 1f0b0acdfdbbd18e45642e6b28ac4b112262df16 Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Tue, 4 Mar 2025 11:33:16 +0000 Subject: [PATCH 6/8] Clear buffer if not flushed on error --- packages/logger/src/Logger.ts | 2 ++ packages/logger/src/middleware/middy.ts | 6 ++++-- 2 files changed, 6 insertions(+), 2 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 1c4e958120..57c861478e 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -449,6 +449,8 @@ class Logger extends Utility implements LoggerInterface { message: UncaughtErrorLogMessage, error, }); + } else { + loggerRef.clearBuffer(); } throw error; /* v8 ignore next */ diff --git a/packages/logger/src/middleware/middy.ts b/packages/logger/src/middleware/middy.ts index 45ccb82d70..f85b1af9f8 100644 --- a/packages/logger/src/middleware/middy.ts +++ b/packages/logger/src/middleware/middy.ts @@ -109,13 +109,15 @@ const injectLambdaContext = ( }; const onError = async ({ error }: { error: unknown }): Promise => { - if (options?.flushBufferOnUncaughtError) { - for (const logger of loggers) { + for (const logger of loggers) { + if (options?.flushBufferOnUncaughtError) { logger.flushBuffer(); logger.error({ message: UncaughtErrorLogMessage, error, }); + } else { + logger.clearBuffer(); } } }; From c04fda5104ec8717ec17421a2cd42dd7e0a143c0 Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Tue, 4 Mar 2025 11:50:40 +0000 Subject: [PATCH 7/8] Add tests for clearing buffer on uncaught error when flushBufferOnUncaughtError is false --- packages/logger/tests/unit/logBuffer.test.ts | 51 ++++++++++++++++++++ 1 file changed, 51 insertions(+) diff --git a/packages/logger/tests/unit/logBuffer.test.ts b/packages/logger/tests/unit/logBuffer.test.ts index 675dae48be..9e3000624d 100644 --- a/packages/logger/tests/unit/logBuffer.test.ts +++ b/packages/logger/tests/unit/logBuffer.test.ts @@ -301,4 +301,55 @@ describe('Buffer logs', () => { expect(console.debug).toHaveBeenCalledBefore(console.error as Mock); } ); + it.each([ + { + handlerFactory: (logger: Logger) => + middy() + .use( + injectLambdaContext(logger, { flushBufferOnUncaughtError: false }) + ) + .handler(async () => { + logger.debug('This is a log message'); + logger.info('This is an info message'); + throw new Error('This is an error'); + }), + case: 'middleware', + }, + { + handlerFactory: (logger: Logger) => { + class TestClass { + @logger.injectLambdaContext({ flushBufferOnUncaughtError: false }) + async handler(_event: unknown, _context: Context) { + logger.debug('This is a log message'); + logger.info('This is an info message'); + throw new Error('This is an error'); + } + } + const lambda = new TestClass(); + return lambda.handler.bind(lambda); + }, + case: 'decorator', + }, + ])( + 'clears the buffer when an uncaught error is thrown and flushBufferOnUncaughtError is false ($case)', + async ({ handlerFactory }) => { + // Prepare + const logger = new Logger({ logBufferOptions: { enabled: true } }); + const handler = handlerFactory(logger); + + // Act & Assess + await expect(() => + handler( + { + foo: 'bar', + }, + context + ) + ).rejects.toThrow(new Error('This is an error')); + + // Assess + expect(console.debug).not.toBeCalled; + expect(console.info).not.toBeCalled; + } + ); }); From 9d324bcdba57b2a871bb0911c38aff8e3b740993 Mon Sep 17 00:00:00 2001 From: Connor Kirkpatrick Date: Tue, 4 Mar 2025 12:56:06 +0000 Subject: [PATCH 8/8] Use finally block --- packages/logger/src/Logger.ts | 3 +-- 1 file changed, 1 insertion(+), 2 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 57c861478e..5efc099f45 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -449,13 +449,12 @@ class Logger extends Utility implements LoggerInterface { message: UncaughtErrorLogMessage, error, }); - } else { - loggerRef.clearBuffer(); } throw error; /* v8 ignore next */ } finally { if (options?.clearState || options?.resetKeys) loggerRef.resetKeys(); + loggerRef.clearBuffer(); } }; };