diff --git a/docs/core/logger.md b/docs/core/logger.md index 6e66a92787..2fc7516d8a 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -52,6 +52,9 @@ These settings will be used across all logs emitted: | **Logging level** | Sets how verbose Logger should be, from the most verbose to the least verbose (no logs) | `POWERTOOLS_LOG_LEVEL` | `INFO` | `DEBUG`, `INFO`, `WARN`, `ERROR`, `CRITICAL`, `SILENT` | `ERROR` | `logLevel` | | **Sample rate** | Probability that a Lambda invocation will print all the log items regardless of the log level setting | `POWERTOOLS_LOGGER_SAMPLE_RATE` | `0` | `0.0` to `1.0` | `0.1` | `sampleRateValue` | +???+ info + When `POWERTOOLS_DEV` environment variable is present and set to `"true"` or `"1"`, Logger will pretty-print log messages for easier readability. We recommend to use this setting only when debugging on local environments. + See all environment variables in the [Environment variables](../index.md/#environment-variables) section. Check API docs to learn more about [Logger constructor options](https://docs.powertools.aws.dev/lambda/typescript/latest/api/types/_aws_lambda_powertools_logger.types.ConstructorOptions.html){target="_blank"}. @@ -91,8 +94,8 @@ Your Logger will include the following keys to your structured logging (default | **xray_trace_id**: `string` | `1-5759e988-bd862e3fe1be46a994272793` | X-Ray Trace ID. This value is always presented in Lambda environment, whether [tracing is enabled](https://docs.aws.amazon.com/lambda/latest/dg/services-xray.html){target="_blank"} or not. Logger will always log this value. | | **error**: `Object` | `{ name: "Error", location: "/my-project/handler.ts:18", message: "Unexpected error #1", stack: "[stacktrace]"}` | Optional - An object containing information about the Error passed to the logger | -???+ info - When `POWERTOOLS_DEV` environment variable is present and set to `"true"` or `"1"`, Logger will pretty-print log messages for easier readability. We recommend to use this setting only when debugging on local environments. +???+ note + If you emit a log message with a key that matches one of `level`, `message`, `sampling_rate`, `service`, or `timestamp`, the Logger will log a warning message and ignore the key. ### Capturing Lambda context info @@ -211,6 +214,8 @@ You can append additional keys using either mechanism: * Append **temporary keys** to all future log messages via the `appendKeys()` method until `resetKeys()` is called * Set **Persistent keys** for the logger instance via the `persistentKeys` constructor option or the `appendPersistentKeys()` method +To prevent you from accidentally overwriting some of the [standard keys](#standard-structured-keys), we will log a warning message and ignore the key if you try to overwrite them. + #### Extra keys You can append additional data to a single log item by passing objects as additional parameters. diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 69e84184c2..ee1a240789 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -9,7 +9,7 @@ import type { import type { Context, Handler } from 'aws-lambda'; import merge from 'lodash.merge'; import { EnvironmentVariablesService } from './config/EnvironmentVariablesService.js'; -import { LogJsonIndent, LogLevelThreshold } from './constants.js'; +import { LogJsonIndent, LogLevelThreshold, ReservedKeys } from './constants.js'; import type { LogFormatter } from './formatter/LogFormatter.js'; import type { LogItem } from './formatter/LogItem.js'; import { PowertoolsLogFormatter } from './formatter/PowertoolsLogFormatter.js'; @@ -25,7 +25,11 @@ import type { LogLevel, LoggerInterface, } from './types/Logger.js'; -import type { PowertoolsLogData } from './types/logKeys.js'; +import type { + LogKeys, + PowertoolsLogData, + UnformattedAttributes, +} from './types/logKeys.js'; /** * The Logger utility provides an opinionated logger with output structured as JSON for AWS Lambda. @@ -131,7 +135,7 @@ class Logger extends Utility implements LoggerInterface { /** * Temporary log attributes that can be appended with `appendKeys()` method. */ - private temporaryLogAttributes: LogAttributes = {}; + private temporaryLogAttributes: LogKeys = {}; /** * Buffer used to store logs until the logger is initialized. * @@ -205,38 +209,34 @@ class Logger extends Utility implements LoggerInterface { } /** - * Add the given persistent attributes (key-value pairs) to all log items generated by this Logger instance. - * - * @deprecated This method is deprecated and will be removed in the future major versions, please use {@link appendPersistentKeys()} instead. - * - * @param attributes - The attributes to add to all log items. + * @deprecated This method is deprecated and will be removed in the future major versions, please use {@link appendPersistentKeys() `appendPersistentKeys()`} instead. */ - public addPersistentLogAttributes(attributes: LogAttributes): void { + public addPersistentLogAttributes(attributes: LogKeys): void { this.appendPersistentKeys(attributes); } /** * Add the given temporary attributes (key-value pairs) to all log items generated by this Logger instance. * + * If the key already exists in the attributes, it will be overwritten. If the key is one of `level`, `message`, `sampling_rate`, + * `service`, or `timestamp` we will log a warning and drop the value. + * * @param attributes - The attributes to add to all log items. */ - public appendKeys(attributes: LogAttributes): void { - for (const attributeKey of Object.keys(attributes)) { - this.#keys.set(attributeKey, 'temp'); - } - merge(this.temporaryLogAttributes, attributes); + public appendKeys(attributes: LogKeys): void { + this.#appendKeys(attributes, 'temp'); } /** * Add the given persistent attributes (key-value pairs) to all log items generated by this Logger instance. * + * If the key already exists in the attributes, it will be overwritten. If the key is one of `level`, `message`, `sampling_rate`, + * `service`, or `timestamp` we will log a warning and drop the value. + * * @param attributes - The attributes to add to all log items. */ - public appendPersistentKeys(attributes: LogAttributes): void { - for (const attributeKey of Object.keys(attributes)) { - this.#keys.set(attributeKey, 'persistent'); - } - merge(this.persistentLogAttributes, attributes); + public appendPersistentKeys(attributes: LogKeys): void { + this.#appendKeys(attributes, 'persistent'); } /** @@ -514,15 +514,13 @@ class Logger extends Utility implements LoggerInterface { /** * @deprecated This method is deprecated and will be removed in the future major versions. Use {@link removePersistentKeys()} instead. - * - * @param keys - The keys to remove. */ public removePersistentLogAttributes(keys: string[]): void { this.removePersistentKeys(keys); } /** - * Remove all temporary log attributes added with `appendKeys()` method. + * Remove all temporary log attributes added with {@link appendKeys() `appendKeys()`} method. */ public resetKeys(): void { for (const key of Object.keys(this.temporaryLogAttributes)) { @@ -553,14 +551,9 @@ class Logger extends Utility implements LoggerInterface { } /** - * Set the given attributes (key-value pairs) to all log items generated by this Logger instance. - * Note: this replaces the pre-existing value. - * - * @deprecated This method is deprecated and will be removed in the future major versions, please use {@link appendPersistentKeys()} instead. - * - * @param attributes - The attributes to set. + * @deprecated This method is deprecated and will be removed in the future major versions, please use {@link appendPersistentKeys() `appendPersistentKeys()`} instead. */ - public setPersistentLogAttributes(attributes: LogAttributes): void { + public setPersistentLogAttributes(attributes: LogKeys): void { this.persistentLogAttributes = attributes; } @@ -666,6 +659,25 @@ class Logger extends Utility implements LoggerInterface { merge(this.powertoolsLogData, attributes); } + /** + * Shared logic for adding keys to the logger instance. + * + * @param attributes - The attributes to add to the log item. + * @param type - The type of the attributes to add. + */ + #appendKeys(attributes: LogKeys, type: 'temp' | 'persistent'): void { + for (const attributeKey of Object.keys(attributes)) { + if (this.#checkReservedKeyAndWarn(attributeKey) === false) { + this.#keys.set(attributeKey, type); + } + } + if (type === 'temp') { + merge(this.temporaryLogAttributes, attributes); + } else { + merge(this.persistentLogAttributes, attributes); + } + } + private awsLogLevelShortCircuit(selectedLogLevel?: string): boolean { const awsLogLevel = this.getEnvVarsService().getAwsLogLevel(); if (this.isValidLogLevel(awsLogLevel)) { @@ -688,70 +700,118 @@ class Logger extends Utility implements LoggerInterface { /** * Create a log item and populate it with the given log level, input, and extra input. - * - * We start with creating an object with base attributes managed by Powertools. - * Then we create a second object with persistent attributes provided by customers either - * directly to the log entry or through initial configuration and `appendKeys` method. - * - * Once we have the two objects, we pass them to the formatter that will apply the desired - * formatting to the log item. - * - * @param logLevel - The log level of the log item to be printed - * @param input - The main input of the log item, this can be a string or an object with additional attributes - * @param extraInput - Additional attributes to be added to the log item */ protected createAndPopulateLogItem( logLevel: number, input: LogItemMessage, extraInput: LogItemExtraInput ): LogItem { - let message = ''; - let otherInput: { [key: string]: unknown } = {}; - if (typeof input === 'string') { - message = input; - } else { - const { message: inputMessage, ...rest } = input; - message = inputMessage; - otherInput = rest; - } - - // create base attributes const unformattedBaseAttributes = { logLevel: this.getLogLevelNameFromNumber(logLevel), timestamp: new Date(), - message, xRayTraceId: this.envVarsService.getXrayTraceId(), ...this.getPowertoolsLogData(), + message: '', }; + const additionalAttributes = this.#createAdditionalAttributes(); + + this.#processMainInput( + input, + unformattedBaseAttributes, + additionalAttributes + ); + this.#processExtraInput(extraInput, additionalAttributes); + + return this.getLogFormatter().formatAttributes( + unformattedBaseAttributes, + additionalAttributes + ); + } + + /** + * Create additional attributes from persistent and temporary keys + */ + #createAdditionalAttributes(): LogAttributes { + const attributes: LogAttributes = {}; - const additionalAttributes: LogAttributes = {}; - // gradually add additional attributes picking only the last added for each key for (const [key, type] of this.#keys) { - if (type === 'persistent') { - additionalAttributes[key] = this.persistentLogAttributes[key]; - } else { - additionalAttributes[key] = this.temporaryLogAttributes[key]; + if (!this.#checkReservedKeyAndWarn(key)) { + attributes[key] = + type === 'persistent' + ? this.persistentLogAttributes[key] + : this.temporaryLogAttributes[key]; } } - // if the main input is not a string, then it's an object with additional attributes, so we merge it - merge(additionalAttributes, otherInput); - // then we merge the extra input attributes (if any) + return attributes; + } + + /** + * Process the main input message and add it to the attributes + */ + #processMainInput( + input: LogItemMessage, + baseAttributes: UnformattedAttributes, + additionalAttributes: LogAttributes + ): void { + if (typeof input === 'string') { + baseAttributes.message = input; + return; + } + + const { message, ...rest } = input; + baseAttributes.message = message; + + for (const [key, value] of Object.entries(rest)) { + if (!this.#checkReservedKeyAndWarn(key)) { + additionalAttributes[key] = value; + } + } + } + + /** + * Process extra input items and add them to additional attributes + */ + #processExtraInput( + extraInput: LogItemExtraInput, + additionalAttributes: LogAttributes + ): void { for (const item of extraInput) { - const attributes: LogAttributes = - item instanceof Error - ? { error: item } - : typeof item === 'string' - ? { extra: item } - : item; - - merge(additionalAttributes, attributes); + if (item instanceof Error) { + additionalAttributes.error = item; + } else if (typeof item === 'string') { + additionalAttributes.extra = item; + } else { + this.#processExtraObject(item, additionalAttributes); + } } + } - return this.getLogFormatter().formatAttributes( - unformattedBaseAttributes, - additionalAttributes - ); + /** + * Process an extra input object and add its properties to additional attributes + */ + #processExtraObject( + item: Record, + additionalAttributes: LogAttributes + ): void { + for (const [key, value] of Object.entries(item)) { + if (!this.#checkReservedKeyAndWarn(key)) { + additionalAttributes[key] = value; + } + } + } + + /** + * Check if a given key is reserved and warn the user if it is. + * + * @param key - The key to check + */ + #checkReservedKeyAndWarn(key: string): boolean { + if (ReservedKeys.includes(key)) { + this.warn(`The key "${key}" is a reserved key and will be dropped.`); + return true; + } + return false; } /** @@ -1090,7 +1150,7 @@ class Logger extends Utility implements LoggerInterface { private setPowertoolsLogData( serviceName?: ConstructorOptions['serviceName'], environment?: ConstructorOptions['environment'], - persistentKeys: ConstructorOptions['persistentKeys'] = {} + persistentKeys?: ConstructorOptions['persistentKeys'] ): void { this.addToPowertoolsLogData({ awsRegion: this.getEnvVarsService().getAwsRegion(), @@ -1104,7 +1164,7 @@ class Logger extends Utility implements LoggerInterface { this.getEnvVarsService().getServiceName() || this.getDefaultServiceName(), }); - this.appendPersistentKeys(persistentKeys); + persistentKeys && this.appendPersistentKeys(persistentKeys); } } diff --git a/packages/logger/src/constants.ts b/packages/logger/src/constants.ts index 9499687c56..a95ed293c7 100644 --- a/packages/logger/src/constants.ts +++ b/packages/logger/src/constants.ts @@ -37,4 +37,17 @@ const LogLevelThreshold = { SILENT: 28, } as const; -export { LogJsonIndent, LogLevel, LogLevelThreshold }; +/** + * Reserved keys that are included in every log item when using the default log formatter. + * + * These keys are reserved and cannot be overwritten by custom log attributes. + */ +const ReservedKeys = [ + 'level', + 'message', + 'sampling_rate', + 'service', + 'timestamp', +]; + +export { LogJsonIndent, LogLevel, LogLevelThreshold, ReservedKeys }; diff --git a/packages/logger/src/formatter/LogItem.ts b/packages/logger/src/formatter/LogItem.ts index 90516aae4f..3e5587bc09 100644 --- a/packages/logger/src/formatter/LogItem.ts +++ b/packages/logger/src/formatter/LogItem.ts @@ -23,7 +23,7 @@ class LogItem { * @param params - The parameters for the LogItem. */ public constructor(params: { attributes: LogAttributes }) { - this.addAttributes(params.attributes); + this.setAttributes(params.attributes); } /** @@ -50,7 +50,7 @@ class LogItem { * This operation removes empty keys from the log item, see {@link removeEmptyKeys | removeEmptyKeys()} for more information. */ public prepareForPrint(): void { - this.setAttributes(this.removeEmptyKeys(this.getAttributes())); + this.attributes = this.removeEmptyKeys(this.getAttributes()); } /** diff --git a/packages/logger/src/types/Logger.ts b/packages/logger/src/types/Logger.ts index a460b5c6e8..1e453f1ee5 100644 --- a/packages/logger/src/types/Logger.ts +++ b/packages/logger/src/types/Logger.ts @@ -8,6 +8,7 @@ import type { Environment, LogAttributes, LogAttributesWithMessage, + LogKeys, } from './logKeys.js'; /** @@ -108,7 +109,14 @@ type PersistentKeysOption = { /** * Keys that will be added to all log items. */ - persistentKeys?: LogAttributes; + persistentKeys?: LogAttributes & { + message?: never; + level?: never; + sampling_rate?: never; + service?: never; + timestamp?: never; + error?: never; + }; /** * @deprecated Use `persistentKeys` instead. */ @@ -180,8 +188,8 @@ type LogItemExtraInput = [Error | string] | LogAttributes[]; */ type LoggerInterface = { addContext(context: Context): void; - addPersistentLogAttributes(attributes?: LogAttributes): void; - appendKeys(attributes?: LogAttributes): void; + appendPersistentKeys(attributes?: LogKeys): void; + appendKeys(attributes?: LogKeys): void; createChild(options?: ConstructorOptions): LoggerInterface; critical(input: LogItemMessage, ...extraInput: LogItemExtraInput): void; debug(input: LogItemMessage, ...extraInput: LogItemExtraInput): void; diff --git a/packages/logger/src/types/logKeys.ts b/packages/logger/src/types/logKeys.ts index 1f2749445d..ad4966fd41 100644 --- a/packages/logger/src/types/logKeys.ts +++ b/packages/logger/src/types/logKeys.ts @@ -24,7 +24,26 @@ type LogAttributes = { [key: string]: unknown }; * This is the most common log attribute object and it's used as first argument in the logger methods. */ type LogAttributesWithMessage = LogAttributes & { + /** + * Your log message. + */ message: string; + /** + * This key is generated by the logger and cannot be set manually. + */ + level?: never; + /** + * This key is generated by the logger and cannot be set manually. + */ + sampling_rate?: never; + /** + * This key is generated by the logger and cannot be set manually. + */ + service?: never; + /** + * This key is generated by the logger and cannot be set manually. + */ + timestamp?: never; }; /** @@ -217,7 +236,31 @@ type LogKey = | keyof PowertoolsLambdaContextKeys | AutocompletableString; +type LogKeys = { [key: string]: unknown } & { + /** + * This key is passed when emitting a log message and cannot be set manually. + */ + message?: never; + /** + * This key is generated by the logger and cannot be added to the logger. + */ + level?: never; + /** + * This key is generated by the logger and cannot be added to the logger. + */ + sampling_rate?: never; + /** + * This key is generated by the logger and cannot be added to the logger. + */ + service?: never; + /** + * This key is generated by the logger and cannot be added to the logger. + */ + timestamp?: never; +}; + export type { + LogKeys, LogAttributes, LogAttributesWithMessage, Environment, diff --git a/packages/logger/tests/unit/workingWithkeys.test.ts b/packages/logger/tests/unit/workingWithkeys.test.ts index 15c8da50d2..c2af93bcb9 100644 --- a/packages/logger/tests/unit/workingWithkeys.test.ts +++ b/packages/logger/tests/unit/workingWithkeys.test.ts @@ -620,4 +620,123 @@ describe('Working with keys', () => { }) ); }); + + it("doesn't overwrite standard keys when appending keys", () => { + // Prepare + const logger = new Logger(); + + // Act + logger.appendKeys({ + // @ts-expect-error - testing invalid key at runtime + level: 'Hello, World!', + }); + logger.info('foo'); + + // Assess + expect(console.info).toHaveLoggedNth( + 1, + expect.objectContaining({ + level: 'INFO', + }) + ); + expect(console.warn).toHaveLoggedNth( + 1, + expect.objectContaining({ + message: 'The key "level" is a reserved key and will be dropped.', + }) + ); + }); + + it("doesn't overwrite standard keys when appending persistent keys", () => { + // Prepare + const logger = new Logger(); + + // Act + logger.appendPersistentKeys({ + // @ts-expect-error - testing invalid key at runtime + timestamp: 'Hello, World!', + }); + logger.info('foo'); + + // Assess + expect(console.info).toHaveLoggedNth( + 1, + expect.objectContaining({ + timestamp: expect.not.stringMatching('Hello, World!'), + }) + ); + expect(console.warn).toHaveLoggedNth( + 1, + expect.objectContaining({ + message: 'The key "timestamp" is a reserved key and will be dropped.', + }) + ); + }); + + it("doesn't overwrite standard keys when appending keys via constructor", () => { + // Prepare + const logger = new Logger({ + persistentKeys: { + // @ts-expect-error - testing invalid key at runtime + sampling_rate: 'Hello, World!', + }, + }); + + // Act + logger.info('foo'); + + // Assess + expect(console.info).toHaveLoggedNth( + 1, + expect.objectContaining({ + sampling_rate: expect.not.stringMatching('Hello, World!'), + }) + ); + expect(console.warn).toHaveLoggedNth( + 1, + expect.objectContaining({ + message: + 'The key "sampling_rate" is a reserved key and will be dropped.', + }) + ); + }); + + it("doesn't overwrite standard keys when passing keys to log method", () => { + // Prepare + const logger = new Logger(); + + // Act + logger.info( + { + message: 'foo', + // @ts-expect-error - testing invalid key at runtime + timestamp: 'Hello, World!', + }, + { + level: 'Hello, World!', + } + ); + + // Assess + expect(console.info).toHaveLoggedNth( + 1, + expect.objectContaining({ + message: 'foo', + timestamp: expect.not.stringMatching('Hello, World!'), + level: 'INFO', + }) + ); + expect(console.warn).toHaveLoggedNth( + 1, + expect.objectContaining({ + message: 'The key "timestamp" is a reserved key and will be dropped.', + }) + ); + expect(console.warn).toHaveLoggedNth( + 2, + expect.objectContaining({ + message: 'The key "level" is a reserved key and will be dropped.', + }) + ); + }); });