Skip to content
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.

Commit 1ca4b26

Browse files
authoredMar 7, 2025··
refactor(logger): align implementation to spec + docs (#3701)
1 parent 1a48d2c commit 1ca4b26

File tree

11 files changed

+464
-153
lines changed

11 files changed

+464
-153
lines changed
 

‎docs/core/logger.md

Lines changed: 166 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -9,7 +9,8 @@ Logger provides an opinionated logger with output structured as JSON.
99

1010
* Capturing key fields from the Lambda context, cold starts, and structure logging output as JSON.
1111
* Logging Lambda invocation events when instructed (disabled by default).
12-
* Printing all the logs only for a percentage of invocations via log sampling (disabled by default).
12+
* Switch log level to `DEBUG` for a percentage of invocations (sampling).
13+
* Buffering logs for a specific request or invocation, and flushing them automatically on error or manually as needed.
1314
* Appending additional keys to structured logs at any point in time.
1415
* Providing a custom log formatter (Bring Your Own Formatter) to output logs in a structure compatible with your organization’s Logging RFC.
1516

@@ -547,6 +548,167 @@ We prioritise log level settings in this order:
547548

548549
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.
549550

551+
### Buffering logs
552+
553+
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.
554+
555+
!!! 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."
556+
557+
=== "logBufferingGettingStarted.ts"
558+
559+
```typescript hl_lines="4-7"
560+
--8<-- "examples/snippets/logger/logBufferingGettingStarted.ts"
561+
```
562+
563+
#### Configuring the buffer
564+
565+
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:
566+
567+
| Parameter | Description | Configuration | Default |
568+
|-------------------- |------------------------------------------------- |------------------------------------ | ------- |
569+
| `enabled` | Enable or disable log buffering | `true`, `false` | `false` |
570+
| `maxBytes` | Maximum size of the log buffer in bytes | `number` | `20480` |
571+
| `bufferAtVerbosity` | Minimum log level to buffer | `TRACE`, `DEBUG`, `INFO`, `WARNING` | `DEBUG` |
572+
| `flushOnErrorLog` | Automatically flush buffer when logging an error | `true`, `false` | `true` |
573+
574+
=== "logBufferingBufferAtVerbosity.ts"
575+
576+
```typescript hl_lines="5"
577+
--8<-- "examples/snippets/logger/logBufferingBufferAtVerbosity.ts"
578+
```
579+
580+
1. Setting `bufferAtVerbosity: 'warn'` configures log buffering for `WARNING` and all lower severity levels like `INFO`, `DEBUG`, and `TRACE`.
581+
2. Calling `logger.clearBuffer()` will clear the buffer without emitting the logs.
582+
583+
=== "logBufferingflushOnErrorLog.ts"
584+
585+
```typescript hl_lines="6"
586+
--8<-- "examples/snippets/logger/logBufferingflushOnErrorLog.ts"
587+
```
588+
589+
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.
590+
591+
#### Flushing on errors
592+
593+
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.
594+
595+
=== "logBufferingFlushOnErrorDecorator.ts"
596+
597+
```typescript hl_lines="6 10-12"
598+
--8<-- "examples/snippets/logger/logBufferingFlushOnErrorDecorator.ts"
599+
```
600+
601+
=== "logBufferingFlushOnErrorMiddy.ts"
602+
603+
```typescript hl_lines="6 11"
604+
--8<-- "examples/snippets/logger/logBufferingFlushOnErrorMiddy.ts"
605+
```
606+
607+
#### Buffering workflows
608+
609+
##### Manual flush
610+
611+
<center>
612+
```mermaid
613+
sequenceDiagram
614+
participant Client
615+
participant Lambda
616+
participant Logger
617+
participant CloudWatch
618+
Client->>Lambda: Invoke Lambda
619+
Lambda->>Logger: Initialize with DEBUG level buffering
620+
Logger-->>Lambda: Logger buffer ready
621+
Lambda->>Logger: logger.debug("First debug log")
622+
Logger-->>Logger: Buffer first debug log
623+
Lambda->>Logger: logger.info("Info log")
624+
Logger->>CloudWatch: Directly log info message
625+
Lambda->>Logger: logger.debug("Second debug log")
626+
Logger-->>Logger: Buffer second debug log
627+
Lambda->>Logger: logger.flush_buffer()
628+
Logger->>CloudWatch: Emit buffered logs to stdout
629+
Lambda->>Client: Return execution result
630+
```
631+
<i>Flushing buffer manually</i>
632+
</center>
633+
634+
##### Flushing when logging an error
635+
636+
<center>
637+
```mermaid
638+
sequenceDiagram
639+
participant Client
640+
participant Lambda
641+
participant Logger
642+
participant CloudWatch
643+
Client->>Lambda: Invoke Lambda
644+
Lambda->>Logger: Initialize with DEBUG level buffering
645+
Logger-->>Lambda: Logger buffer ready
646+
Lambda->>Logger: logger.debug("First log")
647+
Logger-->>Logger: Buffer first debug log
648+
Lambda->>Logger: logger.debug("Second log")
649+
Logger-->>Logger: Buffer second debug log
650+
Lambda->>Logger: logger.debug("Third log")
651+
Logger-->>Logger: Buffer third debug log
652+
Lambda->>Lambda: Exception occurs
653+
Lambda->>Logger: logger.error("Error details")
654+
Logger->>CloudWatch: Emit buffered debug logs
655+
Logger->>CloudWatch: Emit error log
656+
Lambda->>Client: Raise exception
657+
```
658+
<i>Flushing buffer when an error happens</i>
659+
</center>
660+
661+
##### Flushing on error
662+
663+
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.
664+
665+
<center>
666+
```mermaid
667+
sequenceDiagram
668+
participant Client
669+
participant Lambda
670+
participant Logger
671+
participant CloudWatch
672+
Client->>Lambda: Invoke Lambda
673+
Lambda->>Logger: Using decorator
674+
Logger-->>Lambda: Logger context injected
675+
Lambda->>Logger: logger.debug("First log")
676+
Logger-->>Logger: Buffer first debug log
677+
Lambda->>Logger: logger.debug("Second log")
678+
Logger-->>Logger: Buffer second debug log
679+
Lambda->>Lambda: Uncaught Exception
680+
Lambda->>CloudWatch: Automatically emit buffered debug logs
681+
Lambda->>Client: Raise uncaught exception
682+
```
683+
<i>Flushing buffer when an uncaught exception happens</i>
684+
</center>
685+
686+
#### Buffering FAQs
687+
688+
1. **Does the buffer persist across Lambda invocations?**
689+
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.
690+
691+
2. **Are my logs buffered during cold starts?**
692+
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.
693+
694+
3. **How can I prevent log buffering from consuming excessive memory?**
695+
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.
696+
697+
4. **What happens if the log buffer reaches its maximum size?**
698+
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.
699+
700+
5. **What timestamp is used when I flush the logs?**
701+
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.
702+
703+
6. **What happens if I try to add a log line that is bigger than max buffer size?**
704+
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.
705+
706+
7. **What happens if Lambda times out without flushing the buffer?**
707+
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.
708+
709+
8. **Do child loggers inherit the buffer?**
710+
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.
711+
550712
### Reordering log keys position
551713

552714
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 +728,7 @@ You can change the order of [standard Logger keys](#standard-structured-keys) or
566728
--8<-- "examples/snippets/logger/reorderLogKeysOutput.json"
567729
```
568730

569-
### Setting timestamp to custom Timezone
731+
### Setting timestamp to custom timezone
570732

571733
By default, Logger emits records with the default Lambda timestamp in **UTC**, i.e. `2016-06-20T12:08:10.000Z`
572734

@@ -586,7 +748,7 @@ If you prefer to log in a specific timezone, you can configure it by setting the
586748
--8<-- "examples/snippets/logger/customTimezoneOutput.json"
587749
```
588750

589-
### Using multiple Logger instances across your code
751+
### Creating child loggers
590752

591753
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).
592754

@@ -803,7 +965,7 @@ When working with custom log formatters, you take full control over the structur
803965

804966
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.
805967

806-
### Bring your own JSON serializer
968+
### Extend JSON replacer function
807969

808970
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.
809971

‎docs/upgrade.md

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -213,7 +213,7 @@ Logger `sampleRateValue` **continues** to determine the percentage of concurrent
213213

214214
### Custom log formatter
215215

216-
!!! note "Disregard if you are not customizing log output with a [custom log formatter](./core/logger.md#custom-log-formatter-bring-your-own-formatter)."
216+
!!! note "Disregard if you are not customizing log output with a [custom log formatter](./core/logger.md#custom-log-formatter)."
217217

218218
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.
219219

Lines changed: 16 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,16 @@
1+
import { Logger } from '@aws-lambda-powertools/logger';
2+
3+
const logger = new Logger({
4+
logBufferOptions: {
5+
bufferAtVerbosity: 'warn', // (1)!
6+
},
7+
});
8+
9+
export const handler = async () => {
10+
// All logs below are buffered
11+
logger.debug('This is a debug message');
12+
logger.info('This is an info message');
13+
logger.warn('This is a warn message');
14+
15+
logger.clearBuffer(); // (2)!
16+
};
Lines changed: 23 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,23 @@
1+
import { Logger } from '@aws-lambda-powertools/logger';
2+
import type { Context } from 'aws-lambda';
3+
4+
const logger = new Logger({
5+
logLevel: 'DEBUG',
6+
logBufferOptions: { enabled: true },
7+
});
8+
9+
class Lambda {
10+
@logger.injectLambdaContext({
11+
flushBufferOnUncaughtError: true,
12+
})
13+
async handler(_event: unknown, _context: Context) {
14+
// Both logs below are buffered
15+
logger.debug('a debug log');
16+
logger.debug('another debug log');
17+
18+
throw new Error('an error log'); // This causes the buffer to flush
19+
}
20+
}
21+
22+
const lambda = new Lambda();
23+
export const handler = lambda.handler.bind(lambda);
Lines changed: 18 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,18 @@
1+
import { Logger } from '@aws-lambda-powertools/logger';
2+
import { injectLambdaContext } from '@aws-lambda-powertools/logger/middleware';
3+
import middy from '@middy/core';
4+
5+
const logger = new Logger({
6+
logLevel: 'DEBUG',
7+
logBufferOptions: { enabled: true },
8+
});
9+
10+
export const handler = middy()
11+
.use(injectLambdaContext(logger, { flushBufferOnUncaughtError: true }))
12+
.handler(async (event: unknown) => {
13+
// Both logs below are buffered
14+
logger.debug('a debug log');
15+
logger.debug('another debug log');
16+
17+
throw new Error('an error log'); // This causes the buffer to flush
18+
});
Lines changed: 20 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,20 @@
1+
import { Logger } from '@aws-lambda-powertools/logger';
2+
3+
const logger = new Logger({
4+
logBufferOptions: {
5+
maxBytes: 20480,
6+
flushOnErrorLog: true,
7+
},
8+
});
9+
10+
logger.debug('This is a debug message'); // This is NOT buffered
11+
12+
export const handler = async () => {
13+
logger.debug('This is a debug message'); // This is buffered
14+
logger.info('This is an info message');
15+
16+
// your business logic here
17+
18+
logger.error('This is an error message'); // This also flushes the buffer
19+
// or logger.flushBuffer(); // to flush the buffer manually
20+
};
Lines changed: 27 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,27 @@
1+
import { Logger } from '@aws-lambda-powertools/logger';
2+
3+
const logger = new Logger({
4+
logBufferOptions: {
5+
maxBytes: 20480,
6+
flushOnErrorLog: false, // (1)!
7+
},
8+
});
9+
10+
export const handler = async () => {
11+
logger.debug('This is a debug message'); // This is buffered
12+
13+
try {
14+
throw new Error('a non fatal error');
15+
} catch (error) {
16+
logger.error('A non fatal error occurred', { error }); // This does NOT flush the buffer
17+
}
18+
19+
logger.debug('This is another debug message'); // This is buffered
20+
21+
try {
22+
throw new Error('a fatal error');
23+
} catch (error) {
24+
logger.error('A fatal error occurred', { error }); // This does NOT flush the buffer
25+
logger.flushBuffer();
26+
}
27+
};

‎packages/logger/src/Logger.ts

Lines changed: 82 additions & 68 deletions
Original file line numberDiff line numberDiff line change
@@ -41,10 +41,12 @@ import type {
4141
* The Logger utility provides an opinionated logger with output structured as JSON for AWS Lambda.
4242
*
4343
* **Key features**
44-
* * Capture key fields from AWS Lambda context, cold start, and structure log output as JSON
45-
* * Append additional keys to one or all log items
46-
* * Switch log level to `DEBUG` based on a sample rate value for a percentage of invocations
47-
* * Ability to buffer logs in memory and flush them when there's an error
44+
* Capturing key fields from the Lambda context, cold starts, and structure logging output as JSON.
45+
* Logging Lambda invocation events when instructed (disabled by default).
46+
* Switch log level to `DEBUG` for a percentage of invocations (sampling).
47+
* Buffering logs for a specific request or invocation, and flushing them automatically on error or manually as needed.
48+
* Appending additional keys to structured logs at any point in time.
49+
* Providing a custom log formatter (Bring Your Own Formatter) to output logs in a structure compatible with your organization’s Logging RFC.
4850
*
4951
* After initializing the Logger class, you can use the methods to log messages at different levels.
5052
*
@@ -176,25 +178,35 @@ class Logger extends Utility implements LoggerInterface {
176178
#jsonReplacerFn?: CustomJsonReplacerFn;
177179

178180
/**
179-
* Represents whether the buffering functionality is enabled in the logger
181+
* Buffer configuration options.
180182
*/
181-
protected isBufferEnabled = false;
182-
183-
/**
184-
* Whether the buffer should be flushed when an error is logged
185-
*/
186-
protected flushOnErrorLog = true;
187-
/**
188-
* Log level threshold for the buffer
189-
* Logs with a level lower than this threshold will be buffered
190-
* Default is DEBUG
191-
*/
192-
protected bufferAtVerbosity: number = LogLevelThreshold.DEBUG;
193-
/**
194-
* Max size of the buffer. Additions to the buffer beyond this size will
195-
* cause older logs to be evicted from the buffer
196-
*/
197-
#maxBufferBytesSize = 20480;
183+
readonly #bufferConfig: {
184+
/**
185+
* Whether the buffer should is enabled
186+
*/
187+
enabled: boolean;
188+
/**
189+
* Whether the buffer should be flushed when an error is logged
190+
*/
191+
flushOnErrorLog: boolean;
192+
/**
193+
* Max size of the buffer. Additions to the buffer beyond this size will
194+
* cause older logs to be evicted from the buffer
195+
*/
196+
maxBytes: number;
197+
/**
198+
* Log level threshold for the buffer
199+
* Logs with a level lower than this threshold will be buffered
200+
* Default is DEBUG
201+
* Can be specified as a number (LogLevelThreshold value) or a string (log level name)
202+
*/
203+
bufferAtVerbosity: number;
204+
} = {
205+
enabled: false,
206+
flushOnErrorLog: true,
207+
maxBytes: 20480,
208+
bufferAtVerbosity: LogLevelThreshold.DEBUG,
209+
};
198210

199211
/**
200212
* Contains buffered logs, grouped by `_X_AMZN_TRACE_ID`, each group with a max size of `maxBufferBytesSize`
@@ -295,8 +307,16 @@ class Logger extends Utility implements LoggerInterface {
295307
customConfigService: this.getCustomConfigService(),
296308
environment: this.powertoolsLogData.environment,
297309
persistentLogAttributes: this.persistentLogAttributes,
298-
temporaryLogAttributes: this.temporaryLogAttributes,
299310
jsonReplacerFn: this.#jsonReplacerFn,
311+
...(this.#bufferConfig.enabled && {
312+
logBufferOptions: {
313+
maxBytes: this.#bufferConfig.maxBytes,
314+
bufferAtVerbosity: this.getLogLevelNameFromNumber(
315+
this.#bufferConfig.bufferAtVerbosity
316+
),
317+
flushOnErrorLog: this.#bufferConfig.flushOnErrorLog,
318+
},
319+
}),
300320
},
301321
options
302322
)
@@ -305,6 +325,9 @@ class Logger extends Utility implements LoggerInterface {
305325
childLogger.addContext(
306326
this.powertoolsLogData.lambdaContext as unknown as Context
307327
);
328+
if (this.temporaryLogAttributes) {
329+
childLogger.appendKeys(this.temporaryLogAttributes);
330+
}
308331

309332
return childLogger;
310333
}
@@ -339,7 +362,7 @@ class Logger extends Utility implements LoggerInterface {
339362
* @param extraInput - The extra input to log.
340363
*/
341364
public error(input: LogItemMessage, ...extraInput: LogItemExtraInput): void {
342-
if (this.isBufferEnabled && this.flushOnErrorLog) {
365+
if (this.#bufferConfig.enabled && this.#bufferConfig.flushOnErrorLog) {
343366
this.flushBuffer();
344367
}
345368
this.processLogItem(LogLevelThreshold.ERROR, input, extraInput);
@@ -994,18 +1017,6 @@ class Logger extends Utility implements LoggerInterface {
9941017
input: LogItemMessage,
9951018
extraInput: LogItemExtraInput
9961019
): void {
997-
if (logLevel >= this.logLevel) {
998-
if (this.#isInitialized) {
999-
this.printLog(
1000-
logLevel,
1001-
this.createAndPopulateLogItem(logLevel, input, extraInput)
1002-
);
1003-
} else {
1004-
this.#initBuffer.push([logLevel, [logLevel, input, extraInput]]);
1005-
}
1006-
return;
1007-
}
1008-
10091020
const traceId = this.envVarsService.getXrayTraceId();
10101021
if (traceId !== undefined && this.shouldBufferLog(traceId, logLevel)) {
10111022
try {
@@ -1029,6 +1040,19 @@ class Logger extends Utility implements LoggerInterface {
10291040
this.createAndPopulateLogItem(logLevel, input, extraInput)
10301041
);
10311042
}
1043+
1044+
return;
1045+
}
1046+
1047+
if (logLevel >= this.logLevel) {
1048+
if (this.#isInitialized) {
1049+
this.printLog(
1050+
logLevel,
1051+
this.createAndPopulateLogItem(logLevel, input, extraInput)
1052+
);
1053+
} else {
1054+
this.#initBuffer.push([logLevel, [logLevel, input, extraInput]]);
1055+
}
10321056
}
10331057
}
10341058

@@ -1230,10 +1254,7 @@ class Logger extends Utility implements LoggerInterface {
12301254
this.setConsole();
12311255
this.setLogIndentation();
12321256
this.#jsonReplacerFn = jsonReplacerFn;
1233-
1234-
if (logBufferOptions !== undefined) {
1235-
this.#setLogBuffering(logBufferOptions);
1236-
}
1257+
this.#setLogBuffering(logBufferOptions);
12371258

12381259
return this;
12391260
}
@@ -1270,32 +1291,30 @@ class Logger extends Utility implements LoggerInterface {
12701291
*
12711292
* @param options - Options to configure the Logger instance
12721293
*/
1273-
#setLogBuffering(
1274-
options: NonNullable<ConstructorOptions['logBufferOptions']>
1275-
) {
1276-
if (options.maxBytes !== undefined) {
1277-
this.#maxBufferBytesSize = options.maxBytes;
1294+
#setLogBuffering(options?: ConstructorOptions['logBufferOptions']) {
1295+
if (options === undefined) {
1296+
return;
12781297
}
1298+
// `enabled` is a boolean, so we set it to true if it's not explicitly set to false
1299+
this.#bufferConfig.enabled = options?.enabled !== false;
1300+
// if `enabled` is false, we don't need to set any other options
1301+
if (this.#bufferConfig.enabled === false) return;
12791302

1303+
if (options?.maxBytes !== undefined) {
1304+
this.#bufferConfig.maxBytes = options.maxBytes;
1305+
}
12801306
this.#buffer = new CircularMap({
1281-
maxBytesSize: this.#maxBufferBytesSize,
1307+
maxBytesSize: this.#bufferConfig.maxBytes,
12821308
});
12831309

1284-
if (options.enabled === false) {
1285-
this.isBufferEnabled = false;
1286-
} else {
1287-
this.isBufferEnabled = true;
1288-
}
1289-
1290-
if (options.flushOnErrorLog === false) {
1291-
this.flushOnErrorLog = false;
1292-
} else {
1293-
this.flushOnErrorLog = true;
1310+
if (options?.flushOnErrorLog === false) {
1311+
this.#bufferConfig.flushOnErrorLog = false;
12941312
}
1295-
const bufferAtLogLevel = options.bufferAtVerbosity?.toUpperCase();
12961313

1314+
const bufferAtLogLevel = options?.bufferAtVerbosity?.toUpperCase();
12971315
if (this.isValidLogLevel(bufferAtLogLevel)) {
1298-
this.bufferAtVerbosity = LogLevelThreshold[bufferAtLogLevel];
1316+
this.#bufferConfig.bufferAtVerbosity =
1317+
LogLevelThreshold[bufferAtLogLevel];
12991318
}
13001319
}
13011320

@@ -1341,12 +1360,9 @@ class Logger extends Utility implements LoggerInterface {
13411360
}
13421361

13431362
for (const item of buffer) {
1344-
const consoleMethod =
1345-
item.logLevel === LogLevelThreshold.CRITICAL
1346-
? 'error'
1347-
: (this.getLogLevelNameFromNumber(
1348-
item.logLevel
1349-
).toLowerCase() as keyof Omit<LogFunction, 'critical'>);
1363+
const consoleMethod = this.getLogLevelNameFromNumber(
1364+
item.logLevel
1365+
).toLowerCase() as keyof Omit<LogFunction, 'critical'>;
13501366
this.console[consoleMethod](item.value);
13511367
}
13521368
if (buffer.hasEvictedLog) {
@@ -1369,11 +1385,9 @@ class Logger extends Utility implements LoggerInterface {
13691385
*/
13701386
public clearBuffer(): void {
13711387
const traceId = this.envVarsService.getXrayTraceId();
1372-
13731388
if (traceId === undefined) {
13741389
return;
13751390
}
1376-
13771391
this.#buffer?.delete(traceId);
13781392
}
13791393

@@ -1388,9 +1402,9 @@ class Logger extends Utility implements LoggerInterface {
13881402
logLevel: number
13891403
): boolean {
13901404
return (
1391-
this.isBufferEnabled &&
1405+
this.#bufferConfig.enabled &&
13921406
traceId !== undefined &&
1393-
logLevel <= this.bufferAtVerbosity
1407+
logLevel <= this.#bufferConfig.bufferAtVerbosity
13941408
);
13951409
}
13961410
}

‎packages/logger/src/logBuffer.ts

Lines changed: 47 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -1,5 +1,10 @@
11
import { isString } from '@aws-lambda-powertools/commons/typeutils';
22

3+
/**
4+
* A data structure that holds a value and its byte size.
5+
*
6+
* @internal
7+
*/
38
export class SizedItem<V> {
49
public value: V;
510
public logLevel: number;
@@ -15,16 +20,31 @@ export class SizedItem<V> {
1520
}
1621
}
1722

23+
/**
24+
* A set that tracks its current byte size.
25+
*
26+
* @internal
27+
*/
1828
export class SizedSet<V> extends Set<SizedItem<V>> {
1929
public currentBytesSize = 0;
2030
public hasEvictedLog = false;
2131

32+
/**
33+
* Adds an item to the set and updates the current byte size.
34+
*
35+
* @param item - The item to add
36+
*/
2237
add(item: SizedItem<V>): this {
2338
this.currentBytesSize += item.byteSize;
2439
super.add(item);
2540
return this;
2641
}
2742

43+
/**
44+
* Deletes an item from the set and updates the current byte size.
45+
*
46+
* @param item - The item to delete
47+
*/
2848
delete(item: SizedItem<V>): boolean {
2949
const wasDeleted = super.delete(item);
3050
if (wasDeleted) {
@@ -33,11 +53,17 @@ export class SizedSet<V> extends Set<SizedItem<V>> {
3353
return wasDeleted;
3454
}
3555

56+
/**
57+
* Clears all items from the set and resets the current byte size.
58+
*/
3659
clear(): void {
3760
super.clear();
3861
this.currentBytesSize = 0;
3962
}
4063

64+
/**
65+
* Removes the first item from the set and returns it.
66+
*/
4167
shift(): SizedItem<V> | undefined {
4268
const firstElement = this.values().next().value;
4369
if (firstElement) {
@@ -47,6 +73,11 @@ export class SizedSet<V> extends Set<SizedItem<V>> {
4773
}
4874
}
4975

76+
/**
77+
* A ring buffer that stores logs in a circular manner.
78+
*
79+
* @internal
80+
*/
5081
export class CircularMap<V> extends Map<string, SizedSet<V>> {
5182
readonly #maxBytesSize: number;
5283
readonly #onBufferOverflow?: () => void;
@@ -63,6 +94,13 @@ export class CircularMap<V> extends Map<string, SizedSet<V>> {
6394
this.#onBufferOverflow = onBufferOverflow;
6495
}
6596

97+
/**
98+
* Adds an item to the buffer, evicting older items if necessary.
99+
*
100+
* @param key - The key to associate with the item
101+
* @param value - The item to add
102+
* @param logLevel - The log level of the item
103+
*/
66104
setItem(key: string, value: V, logLevel: number): this {
67105
const item = new SizedItem<V>(value, logLevel);
68106

@@ -84,13 +122,19 @@ export class CircularMap<V> extends Map<string, SizedSet<V>> {
84122
return this;
85123
}
86124

87-
readonly #deleteFromBufferUntilSizeIsLessThanMax = (
125+
/**
126+
* Deletes an item from the buffer.
127+
*
128+
* @param key - The key associated with the item
129+
* @param value - The item to delete
130+
*/
131+
#deleteFromBufferUntilSizeIsLessThanMax(
88132
buffer: SizedSet<V>,
89133
item: SizedItem<V>
90-
) => {
134+
) {
91135
while (buffer.currentBytesSize + item.byteSize >= this.#maxBytesSize) {
92136
buffer.shift();
93137
buffer.hasEvictedLog = true;
94138
}
95-
};
139+
}
96140
}

‎packages/logger/src/types/Logger.ts

Lines changed: 11 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -201,14 +201,19 @@ type LogBufferOption = {
201201
*/
202202
flushOnErrorLog?: boolean;
203203
/**
204-
* The threshold to buffer logs. Logs with a level below
205-
* this threshold will be buffered
204+
* The threshold to buffer logs. Logs with a level more severe than this will be logged immediately.
205+
* Only 'DEBUG', 'INFO', 'WARN' or their lowercase variants are allowed.
206206
* @default `DEBUG`
207207
*/
208-
bufferAtVerbosity?: Omit<
209-
LogLevel,
210-
'ERROR' | 'error' | 'CRITICAL' | 'critical' | 'SILENT' | 'silent'
211-
>;
208+
bufferAtVerbosity?:
209+
| Extract<
210+
(typeof LogLevelList)[keyof typeof LogLevelList],
211+
'DEBUG' | 'INFO' | 'WARN'
212+
>
213+
| Extract<
214+
Lowercase<(typeof LogLevelList)[keyof typeof LogLevelList]>,
215+
'debug' | 'info' | 'warn'
216+
>;
212217
};
213218
};
214219

‎packages/logger/tests/unit/logBuffer.test.ts

Lines changed: 53 additions & 71 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,6 @@ import { type Mock, beforeEach, describe, expect, it, vi } from 'vitest';
55
import { Logger } from '../../src/Logger.js';
66
import { LogLevel, UncaughtErrorLogMessage } from '../../src/constants.js';
77
import { injectLambdaContext } from '../../src/middleware/middy.js';
8-
import type { ConstructorOptions } from '../../src/types/Logger.js';
98

109
describe('Buffer logs', () => {
1110
const ENVIRONMENT_VARIABLES = process.env;
@@ -28,6 +27,7 @@ describe('Buffer logs', () => {
2827
// Act
2928
logger.debug('This is a log message');
3029
logger.flushBuffer();
30+
3131
// Assess
3232
expect(console.debug).toBeCalledTimes(0);
3333
});
@@ -42,6 +42,7 @@ describe('Buffer logs', () => {
4242
// Act
4343
logger.debug('This is a log message');
4444
logger.error('This is an error message');
45+
4546
// Assess
4647
expect(console.debug).toBeCalledTimes(0);
4748
expect(console.error).toBeCalledTimes(1);
@@ -51,33 +52,37 @@ describe('Buffer logs', () => {
5152
// Prepare
5253
const logger = new Logger({
5354
logLevel: LogLevel.ERROR,
54-
logBufferOptions: { maxBytes: 100 },
55+
logBufferOptions: { maxBytes: 20480 },
5556
});
5657

5758
// Act
5859
logger.debug('This is a log message');
59-
logger.flushBuffer();
60+
6061
// Assess
61-
expect(console.debug).toBeCalledTimes(1);
62+
expect(console.debug).toBeCalledTimes(0);
6263
});
6364

6465
it('sets a max buffer sized when specified', () => {
6566
// Prepare
6667
const logger = new Logger({
6768
logBufferOptions: {
6869
maxBytes: 250,
69-
bufferAtVerbosity: LogLevel.DEBUG,
70-
enabled: true,
7170
},
7271
});
7372

7473
// Act
75-
logger.debug('this is a debug');
76-
logger.debug('this is a debug');
74+
logger.debug('this is a debug 1');
75+
logger.debug('this is a debug 2');
7776
logger.flushBuffer();
7877

7978
// Assess
80-
expect(console.debug).toBeCalledTimes(1);
79+
expect(console.debug).toHaveLoggedNth(
80+
1,
81+
expect.objectContaining({
82+
level: LogLevel.DEBUG,
83+
message: 'this is a debug 2',
84+
})
85+
);
8186
expect(console.warn).toHaveLogged(
8287
expect.objectContaining({
8388
level: 'WARN',
@@ -89,50 +94,50 @@ describe('Buffer logs', () => {
8994

9095
it('outputs a warning when there is an error buffering the log', () => {
9196
// Prepare
92-
class MockLogger extends Logger {
93-
constructor(options: ConstructorOptions) {
94-
super(options);
95-
// We want to simulate an error in the bufferLogItem method, which is protected, so we override it
96-
this.bufferLogItem = vi.fn().mockImplementation(() => {
97-
throw new Error('bufferLogItem error');
98-
});
99-
}
100-
}
101-
const logger = new MockLogger({ logBufferOptions: { enabled: true } });
97+
const logger = new Logger({ logBufferOptions: { maxBytes: 100 } });
10298

10399
// Act
104100
logger.debug('This is a debug');
105101

106102
// Assess
107-
expect(console.debug).toBeCalledTimes(1);
108-
expect(console.warn).toBeCalledTimes(1);
103+
expect(console.debug).toHaveLogged(
104+
expect.objectContaining({
105+
level: LogLevel.DEBUG,
106+
message: 'This is a debug',
107+
})
108+
);
109+
expect(console.warn).toHaveLoggedNth(
110+
1,
111+
expect.objectContaining({
112+
message: expect.stringContaining('Unable to buffer log: Item too big'),
113+
level: LogLevel.WARN,
114+
})
115+
);
109116
});
110117

111118
it('outputs buffered logs', () => {
112119
// Prepare
113120
const logger = new Logger({
114121
logLevel: 'SILENT',
115122
logBufferOptions: {
116-
enabled: true,
117-
bufferAtVerbosity: LogLevel.CRITICAL,
123+
bufferAtVerbosity: LogLevel.WARN,
118124
},
119125
});
120126

121127
// Act
122128
logger.debug('This is a debug');
123129
logger.warn('This is a warning');
124-
logger.critical('this is a critical');
125130

126131
// Assess
132+
expect(console.debug).toHaveBeenCalledTimes(0);
127133
expect(console.warn).toHaveBeenCalledTimes(0);
128-
expect(console.error).toHaveBeenCalledTimes(0);
129134

130135
// Act
131136
logger.flushBuffer();
132137

133138
// Assess
139+
expect(console.debug).toHaveBeenCalledTimes(1);
134140
expect(console.warn).toHaveBeenCalledTimes(1);
135-
expect(console.error).toHaveBeenCalledTimes(1);
136141
});
137142

138143
it('handles an empty buffer', () => {
@@ -151,52 +156,13 @@ describe('Buffer logs', () => {
151156
// Act
152157
logger.debug('This is a debug');
153158
logger.warn('this is a warning');
154-
155-
// Assess
156-
expect(console.debug).toHaveBeenCalledTimes(0);
157-
expect(console.warn).toHaveBeenCalledTimes(1);
158-
159-
// Act
160159
logger.flushBuffer();
161160

162161
// Assess
163162
expect(console.debug).toHaveBeenCalledTimes(0);
164163
expect(console.warn).toHaveBeenCalledTimes(1);
165164
});
166165

167-
it('outputs a warning when buffered logs have been evicted', () => {
168-
// Prepare
169-
const logger = new Logger({
170-
logLevel: LogLevel.ERROR,
171-
logBufferOptions: {
172-
enabled: true,
173-
bufferAtVerbosity: LogLevel.INFO,
174-
maxBytes: 1024,
175-
},
176-
});
177-
178-
// Act
179-
const longMessage = 'blah'.repeat(10);
180-
181-
let i = 0;
182-
while (i < 4) {
183-
logger.info(
184-
`${i} This is a really long log message intended to exceed the buffer ${longMessage}`
185-
);
186-
i++;
187-
}
188-
logger.flushBuffer();
189-
190-
// Assess
191-
expect(console.warn).toHaveLogged(
192-
expect.objectContaining({
193-
level: LogLevel.WARN,
194-
message:
195-
'Some logs are not displayed because they were evicted from the buffer. Increase buffer size to store more logs in the buffer',
196-
})
197-
);
198-
});
199-
200166
it('it safely short circuits when clearBuffer is called without a trace id', () => {
201167
// Prepare
202168
process.env._X_AMZN_TRACE_ID = undefined;
@@ -219,30 +185,45 @@ describe('Buffer logs', () => {
219185
// Arrange
220186
logger.debug('This is a log message');
221187
logger.clearBuffer();
222-
223188
logger.flushBuffer();
224189

225190
// Assess
226-
expect(console.debug).not.toBeCalled;
191+
expect(console.debug).not.toBeCalled();
227192
});
228-
it('it flushes the buffer when an error in logged', () => {
193+
194+
it('it flushes the buffer when an error is logged', () => {
229195
// Prepare
230196
const logger = new Logger({
231197
logLevel: LogLevel.ERROR,
232-
logBufferOptions: { enabled: true, bufferAtVerbosity: LogLevel.DEBUG },
198+
logBufferOptions: { enabled: true },
233199
});
234-
const flushBufferSpy = vi.spyOn(logger, 'flushBuffer');
235200

236201
// Act
237202
logger.debug('This is a log message');
238203
logger.error('This is an error message');
239204

240205
// Assess
241-
expect(flushBufferSpy).toBeCalledTimes(1);
242206
expect(console.debug).toBeCalledTimes(1);
243207
expect(console.error).toBeCalledTimes(1);
244208
});
245209

210+
it('passes down the same buffer config to child loggers', () => {
211+
// Prepare
212+
const logger = new Logger({
213+
logLevel: LogLevel.TRACE,
214+
logBufferOptions: { enabled: true, bufferAtVerbosity: LogLevel.INFO },
215+
});
216+
const childLogger = logger.createChild();
217+
218+
// Assess
219+
childLogger.debug('This is a log message');
220+
childLogger.info('This is an info message');
221+
222+
// Assess
223+
expect(console.debug).toBeCalledTimes(0);
224+
expect(console.info).toBeCalledTimes(0);
225+
});
226+
246227
it.each([
247228
{
248229
handlerFactory: (logger: Logger) =>
@@ -301,6 +282,7 @@ describe('Buffer logs', () => {
301282
expect(console.debug).toHaveBeenCalledBefore(console.error as Mock);
302283
}
303284
);
285+
304286
it.each([
305287
{
306288
handlerFactory: (logger: Logger) =>

0 commit comments

Comments
 (0)
Please sign in to comment.