diff --git a/docs/core/logger.md b/docs/core/logger.md index 74be0bfde3..8417e0ee0b 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -542,6 +542,25 @@ 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. +### 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. + +!!! note + This feature is available only in the default log formatter and not with custom log formatters. + +=== "reorderLogKeys.ts" + + ```typescript hl_lines="5 10" + --8<-- "examples/snippets/logger/reorderLogKeys.ts" + ``` + +=== "reorderLogKeysOutput.json" + + ```json hl_lines="2-3" + --8<-- "examples/snippets/logger/reorderLogKeysOutput.json" + ``` + ### 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` diff --git a/examples/snippets/logger/reorderLogKeys.ts b/examples/snippets/logger/reorderLogKeys.ts new file mode 100644 index 0000000000..9739ac3382 --- /dev/null +++ b/examples/snippets/logger/reorderLogKeys.ts @@ -0,0 +1,12 @@ +import { Logger } from '@aws-lambda-powertools/logger'; + +const logger = new Logger({ + serviceName: 'serverlessAirline', + logRecordOrder: ['timestamp', 'additionalKey'], +}); + +export const handler = async (): Promise => { + logger.info('Hello, World!', { + additionalKey: 'additionalValue', + }); +}; diff --git a/examples/snippets/logger/reorderLogKeysOutput.json b/examples/snippets/logger/reorderLogKeysOutput.json new file mode 100644 index 0000000000..b9b23404cb --- /dev/null +++ b/examples/snippets/logger/reorderLogKeysOutput.json @@ -0,0 +1,9 @@ +{ + "timestamp": "2024-09-03T02:59:06.603Z", + "additionalKey": "additionalValue", + "level": "INFO", + "message": "Hello, World!", + "sampling_rate": 0, + "service": "serverlessAirline", + "xray_trace_id": "1-66d67b7a-79bc7b2346b32af01b437cf8" +} \ No newline at end of file diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 642fbf6795..5947db21f1 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -23,6 +23,7 @@ import type { LogFunction, LogItemExtraInput, LogItemMessage, + LogRecordOrder, LoggerInterface, PowertoolsLogData, } from './types/Logger.js'; @@ -1077,15 +1078,22 @@ class Logger extends Utility implements LoggerInterface { /** * Set the log formatter instance, in charge of giving a custom format - * to the structured logs + * to the structured logs, and optionally the ordering for keys within logs. * * @private - * @param {LogFormatterInterface} logFormatter - The log formatt er + * @param {LogFormatterInterface} logFormatter - The log formatter + * @param {LogRecordOrder} logRecordOrder - Optional list of keys to specify order in logs */ - private setLogFormatter(logFormatter?: LogFormatterInterface): void { + private setLogFormatter( + logFormatter?: LogFormatterInterface, + logRecordOrder?: LogRecordOrder + ): void { this.logFormatter = logFormatter ?? - new PowertoolsLogFormatter({ envVarsService: this.getEnvVarsService() }); + new PowertoolsLogFormatter({ + envVarsService: this.getEnvVarsService(), + logRecordOrder, + }); } /** @@ -1119,6 +1127,7 @@ class Logger extends Utility implements LoggerInterface { persistentLogAttributes, // deprecated in favor of persistentKeys environment, jsonReplacerFn, + logRecordOrder, } = options; if (persistentLogAttributes && persistentKeys) { @@ -1140,7 +1149,7 @@ class Logger extends Utility implements LoggerInterface { this.setInitialSampleRate(sampleRateValue); // configurations that affect how logs are printed - this.setLogFormatter(logFormatter); + this.setLogFormatter(logFormatter, logRecordOrder); this.setConsole(); this.setLogIndentation(); this.#jsonReplacerFn = jsonReplacerFn; diff --git a/packages/logger/src/formatter/PowertoolsLogFormatter.ts b/packages/logger/src/formatter/PowertoolsLogFormatter.ts index 35fbacb08d..b69aab16c2 100644 --- a/packages/logger/src/formatter/PowertoolsLogFormatter.ts +++ b/packages/logger/src/formatter/PowertoolsLogFormatter.ts @@ -1,5 +1,9 @@ -import type { LogAttributes, PowertoolsLog } from '../types/Log.js'; -import type { UnformattedAttributes } from '../types/Logger.js'; +import type { + LogAttributes, + PowerToolsLogFormatterOptions, + PowertoolsLog, +} from '../types/Log.js'; +import type { LogRecordOrder, UnformattedAttributes } from '../types/Logger.js'; import { LogFormatter } from './LogFormatter.js'; import { LogItem } from './LogItem.js'; @@ -11,6 +15,17 @@ import { LogItem } from './LogItem.js'; * @extends {LogFormatter} */ class PowertoolsLogFormatter extends LogFormatter { + /** + * An array of keys that defines the order of the log record. + */ + #logRecordOrder?: LogRecordOrder; + + public constructor(options?: PowerToolsLogFormatterOptions) { + super(options); + + this.#logRecordOrder = options?.logRecordOrder; + } + /** * It formats key-value pairs of log attributes. * @@ -34,8 +49,45 @@ class PowertoolsLogFormatter extends LogFormatter { timestamp: this.formatTimestamp(attributes.timestamp), xray_trace_id: attributes.xRayTraceId, }; - const powertoolsLogItem = new LogItem({ attributes: baseAttributes }); - powertoolsLogItem.addAttributes(additionalLogAttributes); + + // If logRecordOrder is not set, return the log item with the attributes in the order they were added + if (this.#logRecordOrder === undefined) { + return new LogItem({ attributes: baseAttributes }).addAttributes( + additionalLogAttributes + ); + } + + const orderedAttributes = {} as PowertoolsLog; + + // If logRecordOrder is set, order the attributes in the log item + for (const key of this.#logRecordOrder) { + if (key in baseAttributes && !(key in orderedAttributes)) { + orderedAttributes[key] = baseAttributes[key]; + } else if ( + key in additionalLogAttributes && + !(key in orderedAttributes) + ) { + orderedAttributes[key] = additionalLogAttributes[key]; + } + } + + // Add remaining attributes from baseAttributes + for (const key in baseAttributes) { + if (!(key in orderedAttributes)) { + orderedAttributes[key] = baseAttributes[key]; + } + } + + // Add remaining attributes from additionalLogAttributes + for (const key in additionalLogAttributes) { + if (!(key in orderedAttributes)) { + orderedAttributes[key] = additionalLogAttributes[key]; + } + } + + const powertoolsLogItem = new LogItem({ + attributes: orderedAttributes, + }); return powertoolsLogItem; } diff --git a/packages/logger/src/types/Log.ts b/packages/logger/src/types/Log.ts index 27d58ccdd4..6e26008bed 100644 --- a/packages/logger/src/types/Log.ts +++ b/packages/logger/src/types/Log.ts @@ -1,7 +1,7 @@ import type { EnvironmentVariablesService } from '../config/EnvironmentVariablesService.js'; import type { LogLevel as LogLevelList } from '../constants.js'; import type { LogItem } from '../formatter/LogItem.js'; -import type { UnformattedAttributes } from './Logger.js'; +import type { LogRecordOrder, UnformattedAttributes } from './Logger.js'; type LogLevel = | (typeof LogLevelList)[keyof typeof LogLevelList] @@ -127,6 +127,20 @@ type LogFormatterOptions = { envVarsService?: EnvironmentVariablesService; }; +/** + * Options for the `PowertoolsLogFormatter`. + * + * @type {Object} PowertoolsLogFormatterOptions + * @extends {LogFormatterOptions} + * @property {LogRecordOrder} [logRecordOrder] - Optional list of keys to specify order in logs + */ +type PowerToolsLogFormatterOptions = LogFormatterOptions & { + /** + * An array of keys that defines the order of the log record. + */ + logRecordOrder?: LogRecordOrder; +}; + /** * @interface */ @@ -175,4 +189,5 @@ export type { LogItemInterface, LogFormatterOptions, LogFormatterInterface, + PowerToolsLogFormatterOptions, }; diff --git a/packages/logger/src/types/Logger.ts b/packages/logger/src/types/Logger.ts index 0d6b7999ff..c2de245f86 100644 --- a/packages/logger/src/types/Logger.ts +++ b/packages/logger/src/types/Logger.ts @@ -65,7 +65,6 @@ type CustomJsonReplacerFn = (key: string, value: unknown) => unknown; * @property {LogLevel} [logLevel] - The log level. * @property {string} [serviceName] - The service name. * @property {number} [sampleRateValue] - The sample rate value. - * @property {LogFormatterInterface} [logFormatter] - The custom log formatter. * @property {ConfigServiceInterface} [customConfigService] - The custom config service. * @property {Environment} [environment] - The environment. */ @@ -73,7 +72,6 @@ type BaseConstructorOptions = { logLevel?: LogLevel; serviceName?: string; sampleRateValue?: number; - logFormatter?: LogFormatterInterface; customConfigService?: ConfigServiceInterface; environment?: Environment; /** @@ -115,6 +113,40 @@ type DeprecatedOption = { persistentKeys?: never; }; +/** + * Options for the `logFormatter` constructor option. + * + * @type {Object} LogFormatterOption + * @property {LogFormatterInterface} [logFormatter] - The custom log formatter. + */ +type LogFormatterOption = { + /** + * The custom log formatter. + */ + logFormatter?: LogFormatterInterface; + /** + * Optional list of keys to specify order in logs + */ + logRecordOrder?: never; +}; + +/** + * Options for the `logRecordOrder` constructor option. + * + * @type {Object} LogRecordOrderOption + * @property {LogRecordOrder} [logRecordOrder] - The log record order. + */ +type LogRecordOrderOption = { + /** + * Optional list of keys to specify order in logs + */ + logRecordOrder?: LogRecordOrder; + /** + * The custom log formatter. + */ + logFormatter?: never; +}; + /** * Options for the Logger class constructor. * @@ -126,9 +158,11 @@ type DeprecatedOption = { * @property {ConfigServiceInterface} [customConfigService] - The custom config service. * @property {Environment} [environment] - The environment. * @property {LogAttributes} [persistentKeys] - Keys that will be added in all log items. + * @property {LogRecordOrder} [logRecordOrder] - The log record order. */ type ConstructorOptions = BaseConstructorOptions & - (PersistentKeysOption | DeprecatedOption); + (PersistentKeysOption | DeprecatedOption) & + (LogFormatterOption | LogRecordOrderOption); type LambdaFunctionContext = Pick< Context, @@ -157,6 +191,8 @@ type UnformattedAttributes = PowertoolsLogData & { message: string; }; +type LogRecordOrder = Array; + type LogItemMessage = string | LogAttributesWithMessage; type LogItemExtraInput = [Error | string] | LogAttributes[]; @@ -197,4 +233,5 @@ export type { ConstructorOptions, InjectLambdaContextOptions, CustomJsonReplacerFn, + LogRecordOrder, }; diff --git a/packages/logger/tests/unit/formatters.test.ts b/packages/logger/tests/unit/formatters.test.ts index 152bc20b24..a8aa727000 100644 --- a/packages/logger/tests/unit/formatters.test.ts +++ b/packages/logger/tests/unit/formatters.test.ts @@ -46,6 +46,30 @@ class ErrorWithCauseString extends Error { } } +/** + * Unformatted attributes for testing + */ +const unformattedAttributes: UnformattedAttributes = { + sampleRateValue: 0.25, + awsRegion: 'eu-west-1', + environment: 'prod', + serviceName: 'hello-world', + xRayTraceId: '1-5759e988-bd862e3fe1be46a994272793', + logLevel: 'WARN', + timestamp: new Date(), + message: 'This is a WARN log', + error: new Error('Something happened!'), + lambdaContext: { + functionName: 'my-lambda-function', + memoryLimitInMB: '123', + functionVersion: '1.23.3', + coldStart: true, + invokedFunctionArn: + 'arn:aws:lambda:eu-west-1:123456789012:function:Example', + awsRequestId: 'abcdefg123456789', + }, +}; + process.env.POWERTOOLS_DEV = 'true'; const logSpy = jest.spyOn(console, 'info'); @@ -97,10 +121,12 @@ describe('Formatters', () => { const mockDate = new Date(1466424490000); jest.useFakeTimers().setSystemTime(mockDate); jest.resetAllMocks(); + unformattedAttributes.timestamp = mockDate; }); afterAll(() => { jest.useRealTimers(); + unformattedAttributes.timestamp = new Date(); }); // #region base log keys @@ -146,26 +172,6 @@ describe('Formatters', () => { it('formats the base log keys with context', () => { // Prepare - const unformattedAttributes: UnformattedAttributes = { - sampleRateValue: 0.25, - awsRegion: 'eu-west-1', - environment: 'prod', - serviceName: 'hello-world', - xRayTraceId: '1-5759e988-bd862e3fe1be46a994272793', - logLevel: 'WARN', - timestamp: new Date(), - message: 'This is a WARN log', - error: new Error('Something happened!'), - lambdaContext: { - functionName: 'my-lambda-function', - memoryLimitInMB: '123', - functionVersion: '1.23.3', - coldStart: true, - invokedFunctionArn: - 'arn:aws:lambda:eu-west-1:123456789012:function:Example', - awsRequestId: 'abcdefg123456789', - }, - }; const additionalLogAttributes: LogAttributes = {}; // Act @@ -190,6 +196,160 @@ describe('Formatters', () => { }); }); + it('when `logRecordOrder` is set, it orders the attributes in the log item', () => { + // Prepare + const formatter = new PowertoolsLogFormatter({ + logRecordOrder: ['message', 'timestamp', 'serviceName', 'environment'], + }); + const additionalLogAttributes: LogAttributes = {}; + + // Act + const value = formatter.formatAttributes( + unformattedAttributes, + additionalLogAttributes + ); + + const response = value.getAttributes(); + + // Assess + expect(JSON.stringify(response)).toEqual( + JSON.stringify({ + message: 'This is a WARN log', + timestamp: '2016-06-20T12:08:10.000Z', + cold_start: true, + function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:Example', + function_memory_size: '123', + function_name: 'my-lambda-function', + function_request_id: 'abcdefg123456789', + level: 'WARN', + sampling_rate: 0.25, + service: 'hello-world', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + }); + + it('when `logRecordOrder` is set, it orders the attributes in the log item taking `additionalLogAttributes` into consideration', () => { + // Prepare + const formatter = new PowertoolsLogFormatter({ + logRecordOrder: [ + 'message', + 'additional_key', + 'timestamp', + 'serviceName', + 'environment', + ], + }); + const additionalLogAttributes: LogAttributes = { + additional_key: 'additional_value', + another_key: 'another_value', + }; + + // Act + const value = formatter.formatAttributes( + unformattedAttributes, + additionalLogAttributes + ); + + const response = value.getAttributes(); + + // Assess + expect(JSON.stringify(response)).toEqual( + JSON.stringify({ + message: 'This is a WARN log', + additional_key: 'additional_value', + timestamp: '2016-06-20T12:08:10.000Z', + cold_start: true, + function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:Example', + function_memory_size: '123', + function_name: 'my-lambda-function', + function_request_id: 'abcdefg123456789', + level: 'WARN', + sampling_rate: 0.25, + service: 'hello-world', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + another_key: 'another_value', + }) + ); + }); + + it('when `logRecordOrder` is set, even if a key does not exist in attributes, it orders the attributes correctly', () => { + // Prepare + const formatter = new PowertoolsLogFormatter({ + logRecordOrder: [ + 'message', + 'additional_key', + 'not_present', + 'timestamp', + 'serviceName', + 'environment', + ], + }); + const additionalLogAttributes: LogAttributes = { + additional_key: 'additional_value', + }; + + // Act + const value = formatter.formatAttributes( + unformattedAttributes, + additionalLogAttributes + ); + + const response = value.getAttributes(); + + // Assess + expect(JSON.stringify(response)).toEqual( + JSON.stringify({ + message: 'This is a WARN log', + additional_key: 'additional_value', + timestamp: '2016-06-20T12:08:10.000Z', + cold_start: true, + function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:Example', + function_memory_size: '123', + function_name: 'my-lambda-function', + function_request_id: 'abcdefg123456789', + level: 'WARN', + sampling_rate: 0.25, + service: 'hello-world', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + }); + + it('when logRecordOrder is not set, it will not order the attributes in the log item', () => { + // Prepare + const formatter = new PowertoolsLogFormatter({}); + const additionalLogAttributes: LogAttributes = { + additional_key: 'additional_value', + }; + + // Act + const value = formatter.formatAttributes( + unformattedAttributes, + additionalLogAttributes + ); + + const response = value.getAttributes(); + + // Assess + expect(JSON.stringify(response)).toEqual( + JSON.stringify({ + cold_start: true, + function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:Example', + function_memory_size: '123', + function_name: 'my-lambda-function', + function_request_id: 'abcdefg123456789', + level: 'WARN', + message: 'This is a WARN log', + sampling_rate: 0.25, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + additional_key: 'additional_value', + }) + ); + }); + // #region format errors it.each([ diff --git a/packages/logger/tests/unit/initializeLogger.test.ts b/packages/logger/tests/unit/initializeLogger.test.ts index 6121f8d018..4cc6310fcc 100644 --- a/packages/logger/tests/unit/initializeLogger.test.ts +++ b/packages/logger/tests/unit/initializeLogger.test.ts @@ -103,6 +103,30 @@ describe('Log levels', () => { ); }); + it('`logRecordOrder` should be passed down to child logger', () => { + // Prepare + const logger = new Logger({ logRecordOrder: ['service', 'timestamp'] }); + const childLogger = logger.createChild({ serviceName: 'child-service' }); + + // Act + logger.info('Hello, world!'); + childLogger.info('Hello, world from child!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(2); + const expectedKeys = [ + 'service', + 'timestamp', + 'level', + 'message', + 'sampling_rate', + 'xray_trace_id', + ]; + logSpy.mock.calls.forEach((call, index) => { + expect(Object.keys(JSON.parse(call[0]))).toEqual(expectedKeys); + }); + }); + it("doesn't use the global console object by default", () => { // Prepare process.env.POWERTOOLS_DEV = undefined;