From 969cdfc1b4e3aeec78c3499f727c915785b6d810 Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Thu, 6 Mar 2025 18:31:01 +0100 Subject: [PATCH 1/6] refactor(logger): align implementation to spec --- packages/logger/src/Logger.ts | 68 +++++------- packages/logger/src/types/Logger.ts | 17 +-- packages/logger/tests/unit/logBuffer.test.ts | 106 +++++++------------ 3 files changed, 76 insertions(+), 115 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 5efc099f45..bd8e100994 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -994,18 +994,6 @@ class Logger extends Utility implements LoggerInterface { input: LogItemMessage, extraInput: LogItemExtraInput ): void { - if (logLevel >= this.logLevel) { - if (this.#isInitialized) { - this.printLog( - logLevel, - this.createAndPopulateLogItem(logLevel, input, extraInput) - ); - } else { - this.#initBuffer.push([logLevel, [logLevel, input, extraInput]]); - } - return; - } - const traceId = this.envVarsService.getXrayTraceId(); if (traceId !== undefined && this.shouldBufferLog(traceId, logLevel)) { try { @@ -1029,6 +1017,19 @@ class Logger extends Utility implements LoggerInterface { this.createAndPopulateLogItem(logLevel, input, extraInput) ); } + + return; + } + + if (logLevel >= this.logLevel) { + if (this.#isInitialized) { + this.printLog( + logLevel, + this.createAndPopulateLogItem(logLevel, input, extraInput) + ); + } else { + this.#initBuffer.push([logLevel, [logLevel, input, extraInput]]); + } } } @@ -1230,10 +1231,7 @@ class Logger extends Utility implements LoggerInterface { this.setConsole(); this.setLogIndentation(); this.#jsonReplacerFn = jsonReplacerFn; - - if (logBufferOptions !== undefined) { - this.#setLogBuffering(logBufferOptions); - } + this.#setLogBuffering(logBufferOptions); return this; } @@ -1270,30 +1268,27 @@ class Logger extends Utility implements LoggerInterface { * * @param options - Options to configure the Logger instance */ - #setLogBuffering( - options: NonNullable - ) { - if (options.maxBytes !== undefined) { - this.#maxBufferBytesSize = options.maxBytes; + #setLogBuffering(options?: ConstructorOptions['logBufferOptions']) { + if (options === undefined) { + return; } + // `enabled` is a boolean, so we set it to true if it's not explicitly set to false + this.isBufferEnabled = options?.enabled !== false; + // if `enabled` is false, we don't need to set any other options + if (this.isBufferEnabled === false) return; + if (options?.maxBytes !== undefined) { + this.#maxBufferBytesSize = options.maxBytes; + } this.#buffer = new CircularMap({ maxBytesSize: this.#maxBufferBytesSize, }); - if (options.enabled === false) { - this.isBufferEnabled = false; - } else { - this.isBufferEnabled = true; - } - - if (options.flushOnErrorLog === false) { + if (options?.flushOnErrorLog === false) { this.flushOnErrorLog = false; - } else { - this.flushOnErrorLog = true; } - const bufferAtLogLevel = options.bufferAtVerbosity?.toUpperCase(); + const bufferAtLogLevel = options?.bufferAtVerbosity?.toUpperCase(); if (this.isValidLogLevel(bufferAtLogLevel)) { this.bufferAtVerbosity = LogLevelThreshold[bufferAtLogLevel]; } @@ -1341,12 +1336,9 @@ class Logger extends Utility implements LoggerInterface { } for (const item of buffer) { - const consoleMethod = - item.logLevel === LogLevelThreshold.CRITICAL - ? 'error' - : (this.getLogLevelNameFromNumber( - item.logLevel - ).toLowerCase() as keyof Omit); + const consoleMethod = this.getLogLevelNameFromNumber( + item.logLevel + ).toLowerCase() as keyof Omit; this.console[consoleMethod](item.value); } if (buffer.hasEvictedLog) { @@ -1369,11 +1361,9 @@ class Logger extends Utility implements LoggerInterface { */ public clearBuffer(): void { const traceId = this.envVarsService.getXrayTraceId(); - if (traceId === undefined) { return; } - this.#buffer?.delete(traceId); } diff --git a/packages/logger/src/types/Logger.ts b/packages/logger/src/types/Logger.ts index 899d6078da..01b7fbad20 100644 --- a/packages/logger/src/types/Logger.ts +++ b/packages/logger/src/types/Logger.ts @@ -201,14 +201,19 @@ type LogBufferOption = { */ flushOnErrorLog?: boolean; /** - * The threshold to buffer logs. Logs with a level below - * this threshold will be buffered + * The threshold to buffer logs. Logs with a level more severe than this will be logged immediately. + * Only 'DEBUG', 'INFO', 'WARN' or their lowercase variants are allowed. * @default `DEBUG` */ - bufferAtVerbosity?: Omit< - LogLevel, - 'ERROR' | 'error' | 'CRITICAL' | 'critical' | 'SILENT' | 'silent' - >; + bufferAtVerbosity?: + | Extract< + (typeof LogLevelList)[keyof typeof LogLevelList], + 'DEBUG' | 'INFO' | 'WARN' + > + | Extract< + Lowercase<(typeof LogLevelList)[keyof typeof LogLevelList]>, + 'debug' | 'info' | 'warn' + >; }; }; diff --git a/packages/logger/tests/unit/logBuffer.test.ts b/packages/logger/tests/unit/logBuffer.test.ts index 9e3000624d..99d0907b2e 100644 --- a/packages/logger/tests/unit/logBuffer.test.ts +++ b/packages/logger/tests/unit/logBuffer.test.ts @@ -28,6 +28,7 @@ describe('Buffer logs', () => { // Act logger.debug('This is a log message'); logger.flushBuffer(); + // Assess expect(console.debug).toBeCalledTimes(0); }); @@ -42,6 +43,7 @@ describe('Buffer logs', () => { // Act logger.debug('This is a log message'); logger.error('This is an error message'); + // Assess expect(console.debug).toBeCalledTimes(0); expect(console.error).toBeCalledTimes(1); @@ -51,14 +53,14 @@ describe('Buffer logs', () => { // Prepare const logger = new Logger({ logLevel: LogLevel.ERROR, - logBufferOptions: { maxBytes: 100 }, + logBufferOptions: { maxBytes: 20480 }, }); // Act logger.debug('This is a log message'); - logger.flushBuffer(); + // Assess - expect(console.debug).toBeCalledTimes(1); + expect(console.debug).toBeCalledTimes(0); }); it('sets a max buffer sized when specified', () => { @@ -66,18 +68,22 @@ describe('Buffer logs', () => { const logger = new Logger({ logBufferOptions: { maxBytes: 250, - bufferAtVerbosity: LogLevel.DEBUG, - enabled: true, }, }); // Act - logger.debug('this is a debug'); - logger.debug('this is a debug'); + logger.debug('this is a debug 1'); + logger.debug('this is a debug 2'); logger.flushBuffer(); // Assess - expect(console.debug).toBeCalledTimes(1); + expect(console.debug).toHaveLoggedNth( + 1, + expect.objectContaining({ + level: LogLevel.DEBUG, + message: 'this is a debug 2', + }) + ); expect(console.warn).toHaveLogged( expect.objectContaining({ level: 'WARN', @@ -89,23 +95,25 @@ describe('Buffer logs', () => { it('outputs a warning when there is an error buffering the log', () => { // Prepare - class MockLogger extends Logger { - constructor(options: ConstructorOptions) { - super(options); - // We want to simulate an error in the bufferLogItem method, which is protected, so we override it - this.bufferLogItem = vi.fn().mockImplementation(() => { - throw new Error('bufferLogItem error'); - }); - } - } - const logger = new MockLogger({ logBufferOptions: { enabled: true } }); + const logger = new Logger({ logBufferOptions: { maxBytes: 100 } }); // Act logger.debug('This is a debug'); // Assess - expect(console.debug).toBeCalledTimes(1); - expect(console.warn).toBeCalledTimes(1); + expect(console.debug).toHaveLogged( + expect.objectContaining({ + level: LogLevel.DEBUG, + message: 'This is a debug', + }) + ); + expect(console.warn).toHaveLoggedNth( + 1, + expect.objectContaining({ + message: expect.stringContaining('Unable to buffer log: Item too big'), + level: LogLevel.WARN, + }) + ); }); it('outputs buffered logs', () => { @@ -113,26 +121,24 @@ describe('Buffer logs', () => { const logger = new Logger({ logLevel: 'SILENT', logBufferOptions: { - enabled: true, - bufferAtVerbosity: LogLevel.CRITICAL, + bufferAtVerbosity: LogLevel.WARN, }, }); // Act logger.debug('This is a debug'); logger.warn('This is a warning'); - logger.critical('this is a critical'); // Assess + expect(console.debug).toHaveBeenCalledTimes(0); expect(console.warn).toHaveBeenCalledTimes(0); - expect(console.error).toHaveBeenCalledTimes(0); // Act logger.flushBuffer(); // Assess + expect(console.debug).toHaveBeenCalledTimes(1); expect(console.warn).toHaveBeenCalledTimes(1); - expect(console.error).toHaveBeenCalledTimes(1); }); it('handles an empty buffer', () => { @@ -151,12 +157,6 @@ describe('Buffer logs', () => { // Act logger.debug('This is a debug'); logger.warn('this is a warning'); - - // Assess - expect(console.debug).toHaveBeenCalledTimes(0); - expect(console.warn).toHaveBeenCalledTimes(1); - - // Act logger.flushBuffer(); // Assess @@ -164,39 +164,6 @@ describe('Buffer logs', () => { expect(console.warn).toHaveBeenCalledTimes(1); }); - it('outputs a warning when buffered logs have been evicted', () => { - // Prepare - const logger = new Logger({ - logLevel: LogLevel.ERROR, - logBufferOptions: { - enabled: true, - bufferAtVerbosity: LogLevel.INFO, - maxBytes: 1024, - }, - }); - - // Act - const longMessage = 'blah'.repeat(10); - - let i = 0; - while (i < 4) { - logger.info( - `${i} This is a really long log message intended to exceed the buffer ${longMessage}` - ); - i++; - } - logger.flushBuffer(); - - // Assess - expect(console.warn).toHaveLogged( - expect.objectContaining({ - level: LogLevel.WARN, - message: - 'Some logs are not displayed because they were evicted from the buffer. Increase buffer size to store more logs in the buffer', - }) - ); - }); - it('it safely short circuits when clearBuffer is called without a trace id', () => { // Prepare process.env._X_AMZN_TRACE_ID = undefined; @@ -219,26 +186,24 @@ describe('Buffer logs', () => { // Arrange logger.debug('This is a log message'); logger.clearBuffer(); - logger.flushBuffer(); // Assess - expect(console.debug).not.toBeCalled; + expect(console.debug).not.toBeCalled(); }); - it('it flushes the buffer when an error in logged', () => { + + it('it flushes the buffer when an error is logged', () => { // Prepare const logger = new Logger({ logLevel: LogLevel.ERROR, - logBufferOptions: { enabled: true, bufferAtVerbosity: LogLevel.DEBUG }, + logBufferOptions: { enabled: true }, }); - const flushBufferSpy = vi.spyOn(logger, 'flushBuffer'); // Act logger.debug('This is a log message'); logger.error('This is an error message'); // Assess - expect(flushBufferSpy).toBeCalledTimes(1); expect(console.debug).toBeCalledTimes(1); expect(console.error).toBeCalledTimes(1); }); @@ -301,6 +266,7 @@ describe('Buffer logs', () => { expect(console.debug).toHaveBeenCalledBefore(console.error as Mock); } ); + it.each([ { handlerFactory: (logger: Logger) => From 040707432099329e33684c2a0752ed9b3951179a Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Thu, 6 Mar 2025 18:58:55 +0100 Subject: [PATCH 2/6] chore: propagate buffer config to child loggers --- packages/logger/src/Logger.ts | 78 +++++++++++++------- packages/logger/tests/unit/logBuffer.test.ts | 17 +++++ 2 files changed, 67 insertions(+), 28 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index bd8e100994..ba270099a5 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -176,25 +176,35 @@ class Logger extends Utility implements LoggerInterface { #jsonReplacerFn?: CustomJsonReplacerFn; /** - * Represents whether the buffering functionality is enabled in the logger + * Buffer configuration options. */ - protected isBufferEnabled = false; - - /** - * Whether the buffer should be flushed when an error is logged - */ - protected flushOnErrorLog = true; - /** - * Log level threshold for the buffer - * Logs with a level lower than this threshold will be buffered - * Default is DEBUG - */ - protected bufferAtVerbosity: number = LogLevelThreshold.DEBUG; - /** - * Max size of the buffer. Additions to the buffer beyond this size will - * cause older logs to be evicted from the buffer - */ - #maxBufferBytesSize = 20480; + #bufferOptions: { + /** + * Whether the buffer should is enabled + */ + enabled: boolean; + /** + * Whether the buffer should be flushed when an error is logged + */ + flushOnErrorLog: boolean; + /** + * Max size of the buffer. Additions to the buffer beyond this size will + * cause older logs to be evicted from the buffer + */ + maxBytes: number; + /** + * Log level threshold for the buffer + * Logs with a level lower than this threshold will be buffered + * Default is DEBUG + * Can be specified as a number (LogLevelThreshold value) or a string (log level name) + */ + bufferAtVerbosity: number; + } = { + enabled: false, + flushOnErrorLog: true, + maxBytes: 20480, + bufferAtVerbosity: LogLevelThreshold.DEBUG, + }; /** * Contains buffered logs, grouped by `_X_AMZN_TRACE_ID`, each group with a max size of `maxBufferBytesSize` @@ -295,8 +305,16 @@ class Logger extends Utility implements LoggerInterface { customConfigService: this.getCustomConfigService(), environment: this.powertoolsLogData.environment, persistentLogAttributes: this.persistentLogAttributes, - temporaryLogAttributes: this.temporaryLogAttributes, jsonReplacerFn: this.#jsonReplacerFn, + ...(this.#bufferOptions.enabled && { + logBufferOptions: { + maxBytes: this.#bufferOptions.maxBytes, + bufferAtVerbosity: this.getLogLevelNameFromNumber( + this.#bufferOptions.bufferAtVerbosity + ), + flushOnErrorLog: this.#bufferOptions.flushOnErrorLog, + }, + }), }, options ) @@ -305,6 +323,9 @@ class Logger extends Utility implements LoggerInterface { childLogger.addContext( this.powertoolsLogData.lambdaContext as unknown as Context ); + if (this.temporaryLogAttributes) { + childLogger.appendKeys(this.temporaryLogAttributes); + } return childLogger; } @@ -339,7 +360,7 @@ class Logger extends Utility implements LoggerInterface { * @param extraInput - The extra input to log. */ public error(input: LogItemMessage, ...extraInput: LogItemExtraInput): void { - if (this.isBufferEnabled && this.flushOnErrorLog) { + if (this.#bufferOptions.enabled && this.#bufferOptions.flushOnErrorLog) { this.flushBuffer(); } this.processLogItem(LogLevelThreshold.ERROR, input, extraInput); @@ -1273,24 +1294,25 @@ class Logger extends Utility implements LoggerInterface { return; } // `enabled` is a boolean, so we set it to true if it's not explicitly set to false - this.isBufferEnabled = options?.enabled !== false; + this.#bufferOptions.enabled = options?.enabled !== false; // if `enabled` is false, we don't need to set any other options - if (this.isBufferEnabled === false) return; + if (this.#bufferOptions.enabled === false) return; if (options?.maxBytes !== undefined) { - this.#maxBufferBytesSize = options.maxBytes; + this.#bufferOptions.maxBytes = options.maxBytes; } this.#buffer = new CircularMap({ - maxBytesSize: this.#maxBufferBytesSize, + maxBytesSize: this.#bufferOptions.maxBytes, }); if (options?.flushOnErrorLog === false) { - this.flushOnErrorLog = false; + this.#bufferOptions.flushOnErrorLog = false; } const bufferAtLogLevel = options?.bufferAtVerbosity?.toUpperCase(); if (this.isValidLogLevel(bufferAtLogLevel)) { - this.bufferAtVerbosity = LogLevelThreshold[bufferAtLogLevel]; + this.#bufferOptions.bufferAtVerbosity = + LogLevelThreshold[bufferAtLogLevel]; } } @@ -1378,9 +1400,9 @@ class Logger extends Utility implements LoggerInterface { logLevel: number ): boolean { return ( - this.isBufferEnabled && + this.#bufferOptions.enabled && traceId !== undefined && - logLevel <= this.bufferAtVerbosity + logLevel <= this.#bufferOptions.bufferAtVerbosity ); } } diff --git a/packages/logger/tests/unit/logBuffer.test.ts b/packages/logger/tests/unit/logBuffer.test.ts index 99d0907b2e..e39ed54196 100644 --- a/packages/logger/tests/unit/logBuffer.test.ts +++ b/packages/logger/tests/unit/logBuffer.test.ts @@ -208,6 +208,23 @@ describe('Buffer logs', () => { expect(console.error).toBeCalledTimes(1); }); + it('passes down the same buffer config to child loggers', () => { + // Prepare + const logger = new Logger({ + logLevel: LogLevel.TRACE, + logBufferOptions: { enabled: true, bufferAtVerbosity: LogLevel.INFO }, + }); + const childLogger = logger.createChild(); + + // Assess + childLogger.debug('This is a log message'); + childLogger.info('This is an info message'); + + // Assess + expect(console.debug).toBeCalledTimes(0); + expect(console.info).toBeCalledTimes(0); + }); + it.each([ { handlerFactory: (logger: Logger) => From a63f431fa59e1ecbf117c9fcb70392008bc6b76a Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Thu, 6 Mar 2025 20:22:55 +0100 Subject: [PATCH 3/6] docs: document feature --- docs/core/logger.md | 167 +++++++++++++++++- docs/upgrade.md | 2 +- .../logger/logBufferingBufferAtVerbosity.ts | 16 ++ .../logBufferingFlushOnErrorDecorator.ts | 23 +++ .../logger/logBufferingFlushOnErrorMiddy.ts | 18 ++ .../logger/logBufferingGettingStarted.ts | 20 +++ .../logger/logBufferingflushOnErrorLog.ts | 27 +++ packages/logger/src/Logger.ts | 28 +-- packages/logger/src/logBuffer.ts | 50 +++++- 9 files changed, 330 insertions(+), 21 deletions(-) create mode 100644 examples/snippets/logger/logBufferingBufferAtVerbosity.ts create mode 100644 examples/snippets/logger/logBufferingFlushOnErrorDecorator.ts create mode 100644 examples/snippets/logger/logBufferingFlushOnErrorMiddy.ts create mode 100644 examples/snippets/logger/logBufferingGettingStarted.ts create mode 100644 examples/snippets/logger/logBufferingflushOnErrorLog.ts diff --git a/docs/core/logger.md b/docs/core/logger.md index 9133eead82..f87da1f412 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -547,6 +547,167 @@ We prioritise log level settings in this order: In the event you have set a log level in Powertools to a level that is lower than the ACL setting, we will output a warning log message informing you that your messages will be discarded by Lambda. +### Buffering logs + +Log buffering enables you to buffer logs for a specific request or invocation. Enable log buffering by passing `logBufferOptions` when initializing a Logger instance. You can buffer logs at the `WARNING`, `INFO`, `DEBUG`, or `TRACE` level, and flush them automatically on error or manually as needed. + +!!! tip "This is useful when you want to reduce the number of log messages emitted while still having detailed logs when needed, such as when troubleshooting issues." + +=== "logBufferingGettingStarted.ts" + + ```typescript hl_lines="4-7" + --8<-- "examples/snippets/logger/logBufferingGettingStarted.ts" + ``` + +#### Configuring the buffer + +When configuring the buffer, you can set the following options to fine-tune how logs are captured, stored, and emitted. You can configure the following options in the `logBufferOptions` constructor parameter: + +| Parameter | Description | Configuration | Default | +|-------------------- |------------------------------------------------- |------------------------------------ | ------- | +| `enabled` | Enable or disable log buffering | `true`, `false` | `false` | +| `maxBytes` | Maximum size of the log buffer in bytes | `number` | 20480 | +| `bufferAtVerbosity` | Minimum log level to buffer | `TRACE`, `DEBUG`, `INFO`, `WARNING` | `DEBUG` | +| `flushOnErrorLog` | Automatically flush buffer when logging an error | `true`, `false` | `true` | + +=== "logBufferingBufferAtVerbosity.ts" + + ```typescript hl_lines="5" + --8<-- "examples/snippets/logger/logBufferingBufferAtVerbosity.ts" + ``` + + 1. Setting `bufferAtVerbosity: 'warn'` configures log buffering for `WARNING` and all lower severity levels like `INFO`, `DEBUG`, and `TRACE`. + 2. Calling `logger.clearBuffer()` will clear the buffer without emitting the logs. + +=== "logBufferingflushOnErrorLog.ts" + + ```typescript hl_lines="6" + --8<-- "examples/snippets/logger/logBufferingflushOnErrorLog.ts" + ``` + + 1. Disabling `flushOnErrorLog` will not flush the buffer when logging an error. This is useful when you want to control when the buffer is flushed by calling the `logger.flushBuffer()` method. + +#### Flushing on errors + +When using the `logger.injectLambdaContext()` class method decorator or the `injectLambdaContext()` middleware, you can configure the logger to automatically flush the buffer when an error occurs. This is done by setting the `flushBufferOnUncaughtError` option to `true` in the decorator or middleware options. + +=== "logBufferingFlushOnErrorDecorator.ts" + + ```typescript hl_lines="6 10-12" + --8<-- "examples/snippets/logger/logBufferingFlushOnErrorDecorator.ts" + ``` + +=== "logBufferingFlushOnErrorMiddy.ts" + + ```typescript hl_lines="6 11" + --8<-- "examples/snippets/logger/logBufferingFlushOnErrorMiddy.ts" + ``` + +#### Buffering workflows + +##### Manual flush + +
+```mermaid +sequenceDiagram + participant Client + participant Lambda + participant Logger + participant CloudWatch + Client->>Lambda: Invoke Lambda + Lambda->>Logger: Initialize with DEBUG level buffering + Logger-->>Lambda: Logger buffer ready + Lambda->>Logger: logger.debug("First debug log") + Logger-->>Logger: Buffer first debug log + Lambda->>Logger: logger.info("Info log") + Logger->>CloudWatch: Directly log info message + Lambda->>Logger: logger.debug("Second debug log") + Logger-->>Logger: Buffer second debug log + Lambda->>Logger: logger.flush_buffer() + Logger->>CloudWatch: Emit buffered logs to stdout + Lambda->>Client: Return execution result +``` +Flushing buffer manually +
+ +##### Flushing when logging an error + +
+```mermaid +sequenceDiagram + participant Client + participant Lambda + participant Logger + participant CloudWatch + Client->>Lambda: Invoke Lambda + Lambda->>Logger: Initialize with DEBUG level buffering + Logger-->>Lambda: Logger buffer ready + Lambda->>Logger: logger.debug("First log") + Logger-->>Logger: Buffer first debug log + Lambda->>Logger: logger.debug("Second log") + Logger-->>Logger: Buffer second debug log + Lambda->>Logger: logger.debug("Third log") + Logger-->>Logger: Buffer third debug log + Lambda->>Lambda: Exception occurs + Lambda->>Logger: logger.error("Error details") + Logger->>CloudWatch: Emit buffered debug logs + Logger->>CloudWatch: Emit error log + Lambda->>Client: Raise exception +``` +Flushing buffer when an error happens +
+ +##### Flushing on error + +This works only when using the `logger.injectLambdaContext()` class method decorator or the `injectLambdaContext()` middleware. You can configure the logger to automatically flush the buffer when an error occurs by setting the `flushBufferOnUncaughtError` option to `true` in the decorator or middleware options. + +
+```mermaid +sequenceDiagram + participant Client + participant Lambda + participant Logger + participant CloudWatch + Client->>Lambda: Invoke Lambda + Lambda->>Logger: Using decorator + Logger-->>Lambda: Logger context injected + Lambda->>Logger: logger.debug("First log") + Logger-->>Logger: Buffer first debug log + Lambda->>Logger: logger.debug("Second log") + Logger-->>Logger: Buffer second debug log + Lambda->>Lambda: Uncaught Exception + Lambda->>CloudWatch: Automatically emit buffered debug logs + Lambda->>Client: Raise uncaught exception +``` +Flushing buffer when an uncaught exception happens +
+ +#### Buffering FAQs + +1. **Does the buffer persist across Lambda invocations?** + No, each Lambda invocation has its own buffer. The buffer is initialized when the Lambda function is invoked and is cleared after the function execution completes or when flushed manually. + +2. **Are my logs buffered during cold starts?** + No, we never buffer logs during cold starts. This is because we want to ensure that logs emitted during this phase are always available for debugging and monitoring purposes. The buffer is only used during the execution of the Lambda function. + +3. **How can I prevent log buffering from consuming excessive memory?** + You can limit the size of the buffer by setting the `maxBytes` option in the `logBufferOptions` constructor parameter. This will ensure that the buffer does not grow indefinitely and consume excessive memory. + +4. **What happens if the log buffer reaches its maximum size?** + Older logs are removed from the buffer to make room for new logs. This means that if the buffer is full, you may lose some logs if they are not flushed before the buffer reaches its maximum size. When this happens, we emit a warning when flushing the buffer to indicate that some logs have been dropped. + +5. **What timestamp is used when I flush the logs?** + The timestamp preserves the original time when the log record was created. If you create a log record at 11:00:10 and flush it at 11:00:25, the log line will retain its original timestamp of 11:00:10. + +6. **What happens if I try to add a log line that is bigger than max buffer size?** + The log will be emitted directly to standard output and not buffered. When this happens, we emit a warning to indicate that the log line was too big to be buffered. + +7. **What happens if Lambda times out without flushing the buffer?** + Logs that are still in the buffer will be lost. If you are using the log buffer to log asynchronously, you should ensure that the buffer is flushed before the Lambda function times out. You can do this by calling the `logger.flushBuffer()` method at the end of your Lambda function. + +8. **Do child loggers inherit the buffer?** + No, child loggers do not inherit the buffer from their parent logger but only the buffer configuration. This means that if you create a child logger, it will have its own buffer and will not share the buffer with the parent logger. + ### Reordering log keys position You can change the order of [standard Logger keys](#standard-structured-keys) or any keys that will be appended later at runtime via the `logRecordOrder` parameter. @@ -566,7 +727,7 @@ You can change the order of [standard Logger keys](#standard-structured-keys) or --8<-- "examples/snippets/logger/reorderLogKeysOutput.json" ``` -### Setting timestamp to custom Timezone +### Setting timestamp to custom timezone By default, Logger emits records with the default Lambda timestamp in **UTC**, i.e. `2016-06-20T12:08:10.000Z` @@ -586,7 +747,7 @@ If you prefer to log in a specific timezone, you can configure it by setting the --8<-- "examples/snippets/logger/customTimezoneOutput.json" ``` -### Using multiple Logger instances across your code +### Creating child loggers The `createChild` method allows you to create a child instance of the Logger, which inherits all of the attributes from its parent. You have the option to override any of the settings and attributes from the parent logger, including [its settings](#utility-settings), any [extra keys](#appending-additional-keys), and [the log formatter](#custom-log-formatter). @@ -803,7 +964,7 @@ When working with custom log formatters, you take full control over the structur Note that when implementing this method, you should avoid mutating the `attributes` and `additionalLogAttributes` objects directly. Instead, create a new object with the desired structure and return it. If mutation is necessary, you can create a [`structuredClone`](https://developer.mozilla.org/en-US/docs/Web/API/Window/structuredClone) of the object to avoid side effects. -### Bring your own JSON serializer +### Extend JSON replacer function You can extend the default JSON serializer by passing a custom serializer function to the `Logger` constructor, using the `jsonReplacerFn` option. This is useful when you want to customize the serialization of specific values. diff --git a/docs/upgrade.md b/docs/upgrade.md index df57b45f3d..c55656a157 100644 --- a/docs/upgrade.md +++ b/docs/upgrade.md @@ -213,7 +213,7 @@ Logger `sampleRateValue` **continues** to determine the percentage of concurrent ### Custom log formatter -!!! note "Disregard if you are not customizing log output with a [custom log formatter](./core/logger.md#custom-log-formatter-bring-your-own-formatter)." +!!! note "Disregard if you are not customizing log output with a [custom log formatter](./core/logger.md#custom-log-formatter)." In v1, `Logger` exposed the [standard](./core/logger.md#standard-structured-keys) as a single argument, _e.g., `formatAttributes(attributes: UnformattedAttributes)`_. It expected a plain object with keys and values you wanted in the final log output. diff --git a/examples/snippets/logger/logBufferingBufferAtVerbosity.ts b/examples/snippets/logger/logBufferingBufferAtVerbosity.ts new file mode 100644 index 0000000000..0b25118836 --- /dev/null +++ b/examples/snippets/logger/logBufferingBufferAtVerbosity.ts @@ -0,0 +1,16 @@ +import { Logger } from '@aws-lambda-powertools/logger'; + +const logger = new Logger({ + logBufferOptions: { + bufferAtVerbosity: 'warn', // (1)! + }, +}); + +export const handler = async () => { + // All logs below are buffered + logger.debug('This is a debug message'); + logger.info('This is an info message'); + logger.warn('This is a warn message'); + + logger.clearBuffer(); // (2)! +}; diff --git a/examples/snippets/logger/logBufferingFlushOnErrorDecorator.ts b/examples/snippets/logger/logBufferingFlushOnErrorDecorator.ts new file mode 100644 index 0000000000..24af7df748 --- /dev/null +++ b/examples/snippets/logger/logBufferingFlushOnErrorDecorator.ts @@ -0,0 +1,23 @@ +import { Logger } from '@aws-lambda-powertools/logger'; +import type { Context } from 'aws-lambda'; + +const logger = new Logger({ + logLevel: 'DEBUG', + logBufferOptions: { enabled: true }, +}); + +class Lambda { + @logger.injectLambdaContext({ + flushBufferOnUncaughtError: true, + }) + async handler(_event: unknown, _context: Context) { + // Both logs below are buffered + logger.debug('a debug log'); + logger.debug('another debug log'); + + throw new Error('an error log'); // This causes the buffer to flush + } +} + +const lambda = new Lambda(); +export const handler = lambda.handler.bind(lambda); diff --git a/examples/snippets/logger/logBufferingFlushOnErrorMiddy.ts b/examples/snippets/logger/logBufferingFlushOnErrorMiddy.ts new file mode 100644 index 0000000000..0758375a34 --- /dev/null +++ b/examples/snippets/logger/logBufferingFlushOnErrorMiddy.ts @@ -0,0 +1,18 @@ +import { Logger } from '@aws-lambda-powertools/logger'; +import { injectLambdaContext } from '@aws-lambda-powertools/logger/middleware'; +import middy from '@middy/core'; + +const logger = new Logger({ + logLevel: 'DEBUG', + logBufferOptions: { enabled: true }, +}); + +export const handler = middy() + .use(injectLambdaContext(logger, { flushBufferOnUncaughtError: true })) + .handler(async (event: unknown) => { + // Both logs below are buffered + logger.debug('a debug log'); + logger.debug('another debug log'); + + throw new Error('an error log'); // This causes the buffer to flush + }); diff --git a/examples/snippets/logger/logBufferingGettingStarted.ts b/examples/snippets/logger/logBufferingGettingStarted.ts new file mode 100644 index 0000000000..b94e79e9e1 --- /dev/null +++ b/examples/snippets/logger/logBufferingGettingStarted.ts @@ -0,0 +1,20 @@ +import { Logger } from '@aws-lambda-powertools/logger'; + +const logger = new Logger({ + logBufferOptions: { + maxBytes: 20480, + flushOnErrorLog: true, + }, +}); + +logger.debug('This is a debug message'); // This is NOT buffered + +export const handler = async () => { + logger.debug('This is a debug message'); // This is buffered + logger.info('This is an info message'); + + // your business logic here + + logger.error('This is an error message'); // This also flushes the buffer + // or logger.flushBuffer(); // to flush the buffer manually +}; diff --git a/examples/snippets/logger/logBufferingflushOnErrorLog.ts b/examples/snippets/logger/logBufferingflushOnErrorLog.ts new file mode 100644 index 0000000000..c2177e2aae --- /dev/null +++ b/examples/snippets/logger/logBufferingflushOnErrorLog.ts @@ -0,0 +1,27 @@ +import { Logger } from '@aws-lambda-powertools/logger'; + +const logger = new Logger({ + logBufferOptions: { + maxBytes: 20480, + flushOnErrorLog: false, // (1)! + }, +}); + +export const handler = async () => { + logger.debug('This is a debug message'); // This is buffered + + try { + throw new Error('a non fatal error'); + } catch (error) { + logger.error('A non fatal error occurred', { error }); // This does NOT flush the buffer + } + + logger.debug('This is another debug message'); // This is buffered + + try { + throw new Error('a fatal error'); + } catch (error) { + logger.error('A fatal error occurred', { error }); // This does NOT flush the buffer + logger.flushBuffer(); + } +}; diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index ba270099a5..70506f4d44 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -178,7 +178,7 @@ class Logger extends Utility implements LoggerInterface { /** * Buffer configuration options. */ - #bufferOptions: { + #bufferConfig: { /** * Whether the buffer should is enabled */ @@ -306,13 +306,13 @@ class Logger extends Utility implements LoggerInterface { environment: this.powertoolsLogData.environment, persistentLogAttributes: this.persistentLogAttributes, jsonReplacerFn: this.#jsonReplacerFn, - ...(this.#bufferOptions.enabled && { + ...(this.#bufferConfig.enabled && { logBufferOptions: { - maxBytes: this.#bufferOptions.maxBytes, + maxBytes: this.#bufferConfig.maxBytes, bufferAtVerbosity: this.getLogLevelNameFromNumber( - this.#bufferOptions.bufferAtVerbosity + this.#bufferConfig.bufferAtVerbosity ), - flushOnErrorLog: this.#bufferOptions.flushOnErrorLog, + flushOnErrorLog: this.#bufferConfig.flushOnErrorLog, }, }), }, @@ -360,7 +360,7 @@ class Logger extends Utility implements LoggerInterface { * @param extraInput - The extra input to log. */ public error(input: LogItemMessage, ...extraInput: LogItemExtraInput): void { - if (this.#bufferOptions.enabled && this.#bufferOptions.flushOnErrorLog) { + if (this.#bufferConfig.enabled && this.#bufferConfig.flushOnErrorLog) { this.flushBuffer(); } this.processLogItem(LogLevelThreshold.ERROR, input, extraInput); @@ -1294,24 +1294,24 @@ class Logger extends Utility implements LoggerInterface { return; } // `enabled` is a boolean, so we set it to true if it's not explicitly set to false - this.#bufferOptions.enabled = options?.enabled !== false; + this.#bufferConfig.enabled = options?.enabled !== false; // if `enabled` is false, we don't need to set any other options - if (this.#bufferOptions.enabled === false) return; + if (this.#bufferConfig.enabled === false) return; if (options?.maxBytes !== undefined) { - this.#bufferOptions.maxBytes = options.maxBytes; + this.#bufferConfig.maxBytes = options.maxBytes; } this.#buffer = new CircularMap({ - maxBytesSize: this.#bufferOptions.maxBytes, + maxBytesSize: this.#bufferConfig.maxBytes, }); if (options?.flushOnErrorLog === false) { - this.#bufferOptions.flushOnErrorLog = false; + this.#bufferConfig.flushOnErrorLog = false; } const bufferAtLogLevel = options?.bufferAtVerbosity?.toUpperCase(); if (this.isValidLogLevel(bufferAtLogLevel)) { - this.#bufferOptions.bufferAtVerbosity = + this.#bufferConfig.bufferAtVerbosity = LogLevelThreshold[bufferAtLogLevel]; } } @@ -1400,9 +1400,9 @@ class Logger extends Utility implements LoggerInterface { logLevel: number ): boolean { return ( - this.#bufferOptions.enabled && + this.#bufferConfig.enabled && traceId !== undefined && - logLevel <= this.#bufferOptions.bufferAtVerbosity + logLevel <= this.#bufferConfig.bufferAtVerbosity ); } } diff --git a/packages/logger/src/logBuffer.ts b/packages/logger/src/logBuffer.ts index e17512515b..54ce203bfd 100644 --- a/packages/logger/src/logBuffer.ts +++ b/packages/logger/src/logBuffer.ts @@ -1,5 +1,10 @@ import { isString } from '@aws-lambda-powertools/commons/typeutils'; +/** + * A data structure that holds a value and its byte size. + * + * @internal + */ export class SizedItem { public value: V; public logLevel: number; @@ -15,16 +20,31 @@ export class SizedItem { } } +/** + * A set that tracks its current byte size. + * + * @internal + */ export class SizedSet extends Set> { public currentBytesSize = 0; public hasEvictedLog = false; + /** + * Adds an item to the set and updates the current byte size. + * + * @param item - The item to add + */ add(item: SizedItem): this { this.currentBytesSize += item.byteSize; super.add(item); return this; } + /** + * Deletes an item from the set and updates the current byte size. + * + * @param item - The item to delete + */ delete(item: SizedItem): boolean { const wasDeleted = super.delete(item); if (wasDeleted) { @@ -33,11 +53,17 @@ export class SizedSet extends Set> { return wasDeleted; } + /** + * Clears all items from the set and resets the current byte size. + */ clear(): void { super.clear(); this.currentBytesSize = 0; } + /** + * Removes the first item from the set and returns it. + */ shift(): SizedItem | undefined { const firstElement = this.values().next().value; if (firstElement) { @@ -47,6 +73,11 @@ export class SizedSet extends Set> { } } +/** + * A ring buffer that stores logs in a circular manner. + * + * @internal + */ export class CircularMap extends Map> { readonly #maxBytesSize: number; readonly #onBufferOverflow?: () => void; @@ -63,6 +94,13 @@ export class CircularMap extends Map> { this.#onBufferOverflow = onBufferOverflow; } + /** + * Adds an item to the buffer, evicting older items if necessary. + * + * @param key - The key to associate with the item + * @param value - The item to add + * @param logLevel - The log level of the item + */ setItem(key: string, value: V, logLevel: number): this { const item = new SizedItem(value, logLevel); @@ -84,13 +122,19 @@ export class CircularMap extends Map> { return this; } - readonly #deleteFromBufferUntilSizeIsLessThanMax = ( + /** + * Deletes an item from the buffer. + * + * @param key - The key associated with the item + * @param value - The item to delete + */ + #deleteFromBufferUntilSizeIsLessThanMax( buffer: SizedSet, item: SizedItem - ) => { + ) { while (buffer.currentBytesSize + item.byteSize >= this.#maxBytesSize) { buffer.shift(); buffer.hasEvictedLog = true; } - }; + } } From 3be63640c7c3ecd483c87810a0e30fcc0e6027bc Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Thu, 6 Mar 2025 20:24:50 +0100 Subject: [PATCH 4/6] docs: update key features --- docs/core/logger.md | 3 ++- packages/logger/src/Logger.ts | 10 ++++++---- 2 files changed, 8 insertions(+), 5 deletions(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index f87da1f412..5bdbbbb08d 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -9,7 +9,8 @@ Logger provides an opinionated logger with output structured as JSON. * Capturing key fields from the Lambda context, cold starts, and structure logging output as JSON. * Logging Lambda invocation events when instructed (disabled by default). -* Printing all the logs only for a percentage of invocations via log sampling (disabled by default). +* Switch log level to `DEBUG` for a percentage of invocations (sampling). +* Buffering logs for a specific request or invocation, and flushing them automatically on error or manually as needed. * Appending additional keys to structured logs at any point in time. * Providing a custom log formatter (Bring Your Own Formatter) to output logs in a structure compatible with your organization’s Logging RFC. diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 70506f4d44..b86fa86a95 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -41,10 +41,12 @@ import type { * The Logger utility provides an opinionated logger with output structured as JSON for AWS Lambda. * * **Key features** - * * Capture key fields from AWS Lambda context, cold start, and structure log output as JSON - * * Append additional keys to one or all log items - * * Switch log level to `DEBUG` based on a sample rate value for a percentage of invocations - * * Ability to buffer logs in memory and flush them when there's an error + * Capturing key fields from the Lambda context, cold starts, and structure logging output as JSON. + * Logging Lambda invocation events when instructed (disabled by default). + * Switch log level to `DEBUG` for a percentage of invocations (sampling). + * Buffering logs for a specific request or invocation, and flushing them automatically on error or manually as needed. + * Appending additional keys to structured logs at any point in time. + * Providing a custom log formatter (Bring Your Own Formatter) to output logs in a structure compatible with your organization’s Logging RFC. * * After initializing the Logger class, you can use the methods to log messages at different levels. * From a0484b49d30ace8ec8e3d83e8cc6c3def83155ec Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Thu, 6 Mar 2025 20:31:55 +0100 Subject: [PATCH 5/6] chore: format --- 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 5bdbbbb08d..523214a147 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -567,7 +567,7 @@ When configuring the buffer, you can set the following options to fine-tune how | Parameter | Description | Configuration | Default | |-------------------- |------------------------------------------------- |------------------------------------ | ------- | | `enabled` | Enable or disable log buffering | `true`, `false` | `false` | -| `maxBytes` | Maximum size of the log buffer in bytes | `number` | 20480 | +| `maxBytes` | Maximum size of the log buffer in bytes | `number` | `20480` | | `bufferAtVerbosity` | Minimum log level to buffer | `TRACE`, `DEBUG`, `INFO`, `WARNING` | `DEBUG` | | `flushOnErrorLog` | Automatically flush buffer when logging an error | `true`, `false` | `true` | From 3075944d384503650b3deed7d707961ebdb72ecd Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Thu, 6 Mar 2025 20:32:37 +0100 Subject: [PATCH 6/6] chore: sonarqube findings --- packages/logger/src/Logger.ts | 2 +- packages/logger/tests/unit/logBuffer.test.ts | 1 - 2 files changed, 1 insertion(+), 2 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index b86fa86a95..f39bb8ef0e 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -180,7 +180,7 @@ class Logger extends Utility implements LoggerInterface { /** * Buffer configuration options. */ - #bufferConfig: { + readonly #bufferConfig: { /** * Whether the buffer should is enabled */ diff --git a/packages/logger/tests/unit/logBuffer.test.ts b/packages/logger/tests/unit/logBuffer.test.ts index e39ed54196..4f75b939ca 100644 --- a/packages/logger/tests/unit/logBuffer.test.ts +++ b/packages/logger/tests/unit/logBuffer.test.ts @@ -5,7 +5,6 @@ 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', () => { const ENVIRONMENT_VARIABLES = process.env;