From 3a78c9a21f20cb4fc52ea21d1c29902ca1a2bcfd Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Thu, 4 Jul 2024 17:43:57 +0600 Subject: [PATCH 01/28] feat: define `logRecordOrder` option in Logger types --- packages/logger/src/types/Log.ts | 2 ++ packages/logger/src/types/Logger.ts | 1 + 2 files changed, 3 insertions(+) diff --git a/packages/logger/src/types/Log.ts b/packages/logger/src/types/Log.ts index e415ee2544..3054548be9 100644 --- a/packages/logger/src/types/Log.ts +++ b/packages/logger/src/types/Log.ts @@ -132,6 +132,8 @@ type LogFormatterOptions = { * If set, it gives the LogFormatter access to environment variables. */ envVarsService?: EnvironmentVariablesService; + + logRecordOrder?: Array; }; /** diff --git a/packages/logger/src/types/Logger.ts b/packages/logger/src/types/Logger.ts index e662669fe3..06ec00337a 100644 --- a/packages/logger/src/types/Logger.ts +++ b/packages/logger/src/types/Logger.ts @@ -35,6 +35,7 @@ type BaseConstructorOptions = { logFormatter?: LogFormatterInterface; customConfigService?: ConfigServiceInterface; environment?: Environment; + logRecordOrder?: Array; }; type PersistentKeysOption = { From a8dde6b17d7c97a9eb760b1eb05d30dddd47635b Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Thu, 4 Jul 2024 17:46:15 +0600 Subject: [PATCH 02/28] feat: pass the `logRecordOrder` option to `LogFormatter` --- packages/logger/src/Logger.ts | 15 ++++++++++++--- packages/logger/src/formatter/LogFormatter.ts | 6 ++++++ 2 files changed, 18 insertions(+), 3 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 6c0c37e740..468dec1920 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -24,6 +24,7 @@ import type { LogItemMessage, LoggerInterface, PowertoolsLogData, + UnformattedAttributes, } from './types/Logger.js'; /** @@ -1080,12 +1081,19 @@ class Logger extends Utility implements LoggerInterface { * * @private * @param {LogFormatterInterface} logFormatter + * @param {Array} logRecordOrder * @returns {void} */ - private setLogFormatter(logFormatter?: LogFormatterInterface): void { + private setLogFormatter( + logFormatter?: LogFormatterInterface, + logRecordOrder?: Array + ): 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 { persistentKeys, persistentLogAttributes, // deprecated in favor of persistentKeys environment, + 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(); diff --git a/packages/logger/src/formatter/LogFormatter.ts b/packages/logger/src/formatter/LogFormatter.ts index b072f6140c..ba22c782a9 100644 --- a/packages/logger/src/formatter/LogFormatter.ts +++ b/packages/logger/src/formatter/LogFormatter.ts @@ -21,8 +21,14 @@ abstract class LogFormatter implements LogFormatterInterface { */ protected envVarsService?: EnvironmentVariablesService; + /** + * An array of keys that defines the order of the log record. + */ + protected logRecordOrder?: Array; + public constructor(options?: LogFormatterOptions) { this.envVarsService = options?.envVarsService; + this.logRecordOrder = options?.logRecordOrder; } /** From 4f3967f8bfd6d2846224ee9b9582c6f0dc988e5e Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Thu, 4 Jul 2024 17:53:53 +0600 Subject: [PATCH 03/28] feat: order attributes if logRecordOrder is available --- .../src/formatter/PowertoolsLogFormatter.ts | 20 ++++++++++++++++++- 1 file changed, 19 insertions(+), 1 deletion(-) diff --git a/packages/logger/src/formatter/PowertoolsLogFormatter.ts b/packages/logger/src/formatter/PowertoolsLogFormatter.ts index 80c0406bbb..49d5719ae5 100644 --- a/packages/logger/src/formatter/PowertoolsLogFormatter.ts +++ b/packages/logger/src/formatter/PowertoolsLogFormatter.ts @@ -35,7 +35,25 @@ class PowertoolsLogFormatter extends LogFormatter { timestamp: this.formatTimestamp(attributes.timestamp), xray_trace_id: attributes.xRayTraceId, }; - const powertoolsLogItem = new LogItem({ attributes: baseAttributes }); + + const orderedAttributes = {} as PowertoolsLog; + + // If logRecordOrder is set, order the attributes in the log item + this.logRecordOrder?.forEach((key) => { + if (key in baseAttributes) { + orderedAttributes[key] = baseAttributes[key]; + delete baseAttributes[key]; + } + }); + + // Merge the ordered attributes with the rest of the attributes + const powertoolsLogItem = new LogItem({ + attributes: { + ...orderedAttributes, + ...baseAttributes, + }, + }); + powertoolsLogItem.addAttributes(additionalLogAttributes); return powertoolsLogItem; From c743eb019d3fd2f89a41170e9f0bc21ac111be04 Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Thu, 4 Jul 2024 18:17:07 +0600 Subject: [PATCH 04/28] feat: use `lodash.merge` for merging ordered & base order attributes --- packages/logger/src/formatter/PowertoolsLogFormatter.ts | 6 ++---- 1 file changed, 2 insertions(+), 4 deletions(-) diff --git a/packages/logger/src/formatter/PowertoolsLogFormatter.ts b/packages/logger/src/formatter/PowertoolsLogFormatter.ts index 49d5719ae5..3c1c76e82b 100644 --- a/packages/logger/src/formatter/PowertoolsLogFormatter.ts +++ b/packages/logger/src/formatter/PowertoolsLogFormatter.ts @@ -1,3 +1,4 @@ +import merge from 'lodash.merge'; import type { LogAttributes, PowertoolsLog } from '../types/Log.js'; import type { UnformattedAttributes } from '../types/Logger.js'; import { LogFormatter } from './LogFormatter.js'; @@ -48,10 +49,7 @@ class PowertoolsLogFormatter extends LogFormatter { // Merge the ordered attributes with the rest of the attributes const powertoolsLogItem = new LogItem({ - attributes: { - ...orderedAttributes, - ...baseAttributes, - }, + attributes: merge(orderedAttributes, baseAttributes), }); powertoolsLogItem.addAttributes(additionalLogAttributes); From e1539ac507199ac06487f6a862e2911d98d30b3b Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Thu, 4 Jul 2024 18:31:09 +0600 Subject: [PATCH 05/28] test: `logRecordOrder` option during formatting --- .../formatter/PowertoolsLogFormatter.test.ts | 54 +++++++++++++++++++ 1 file changed, 54 insertions(+) diff --git a/packages/logger/tests/unit/formatter/PowertoolsLogFormatter.test.ts b/packages/logger/tests/unit/formatter/PowertoolsLogFormatter.test.ts index b4e8753cb7..d31211fb39 100644 --- a/packages/logger/tests/unit/formatter/PowertoolsLogFormatter.test.ts +++ b/packages/logger/tests/unit/formatter/PowertoolsLogFormatter.test.ts @@ -102,6 +102,60 @@ describe('Class: PowertoolsLogFormatter', () => { xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', }); }); + + test('when logRecordOrder is set, it orders the attributes in the log item', () => { + // Prepare + const formatter = new PowertoolsLogFormatter({ + logRecordOrder: ['message', 'timestamp', 'serviceName', 'environment'], + }); + 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 + 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', + }) + ); + }); }); describe('Method: formatError', () => { From e7be7a2b43b6aaf94f10453d3556251088fe298e Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Mon, 2 Sep 2024 10:31:33 +0600 Subject: [PATCH 06/28] refactor: `LogRecordOrder` type union of `UnformattedAttributes` & `LogAttributes` keys --- packages/logger/src/Logger.ts | 6 +++--- packages/logger/src/formatter/LogFormatter.ts | 4 ++-- packages/logger/src/types/Log.ts | 4 ++-- packages/logger/src/types/Logger.ts | 5 ++++- 4 files changed, 11 insertions(+), 8 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 2cbbc1e9f3..34467aed37 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -23,9 +23,9 @@ import type { LogFunction, LogItemExtraInput, LogItemMessage, + LogRecordOrder, LoggerInterface, PowertoolsLogData, - UnformattedAttributes, } from './types/Logger.js'; /** @@ -1121,12 +1121,12 @@ class Logger extends Utility implements LoggerInterface { * * @private * @param {LogFormatterInterface} logFormatter - * @param {Array} logRecordOrder + * @param {LogRecordOrder} logRecordOrder * @returns {void} */ private setLogFormatter( logFormatter?: LogFormatterInterface, - logRecordOrder?: Array + logRecordOrder?: LogRecordOrder ): void { this.logFormatter = logFormatter ?? diff --git a/packages/logger/src/formatter/LogFormatter.ts b/packages/logger/src/formatter/LogFormatter.ts index 0ac54d8175..10d6d68cc1 100644 --- a/packages/logger/src/formatter/LogFormatter.ts +++ b/packages/logger/src/formatter/LogFormatter.ts @@ -4,7 +4,7 @@ import type { LogFormatterInterface, LogFormatterOptions, } from '../types/Log.js'; -import type { UnformattedAttributes } from '../types/Logger.js'; +import type { LogRecordOrder, UnformattedAttributes } from '../types/Logger.js'; import type { LogItem } from './LogItem.js'; /** @@ -24,7 +24,7 @@ abstract class LogFormatter implements LogFormatterInterface { /** * An array of keys that defines the order of the log record. */ - protected logRecordOrder?: Array; + protected logRecordOrder?: LogRecordOrder; public constructor(options?: LogFormatterOptions) { this.envVarsService = options?.envVarsService; diff --git a/packages/logger/src/types/Log.ts b/packages/logger/src/types/Log.ts index 53d5656cc7..7009e419a6 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] @@ -117,7 +117,7 @@ type LogFormatterOptions = { */ envVarsService?: EnvironmentVariablesService; - logRecordOrder?: Array; + logRecordOrder?: LogRecordOrder; }; /** diff --git a/packages/logger/src/types/Logger.ts b/packages/logger/src/types/Logger.ts index 038d3ef059..f6288ccceb 100644 --- a/packages/logger/src/types/Logger.ts +++ b/packages/logger/src/types/Logger.ts @@ -57,7 +57,7 @@ type BaseConstructorOptions = { * This allows you to customize the serialization while still benefiting from the default behavior. */ jsonReplacerFn?: CustomJsonReplacerFn; - logRecordOrder?: Array; + logRecordOrder?: LogRecordOrder; }; type PersistentKeysOption = { @@ -124,6 +124,8 @@ type UnformattedAttributes = PowertoolsLogData & { message: string; }; +type LogRecordOrder = Array; + type LogItemMessage = string | LogAttributesWithMessage; type LogItemExtraInput = [Error | string] | LogAttributes[]; @@ -164,4 +166,5 @@ export type { ConstructorOptions, InjectLambdaContextOptions, CustomJsonReplacerFn, + LogRecordOrder, }; From 22ab7b99ff35ff58a4e96bc187a8f62ff7ec6163 Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Mon, 2 Sep 2024 10:45:08 +0600 Subject: [PATCH 07/28] test: logRecordOrder option during formatting --- packages/logger/tests/unit/formatters.test.ts | 59 +++++++++++++++++++ 1 file changed, 59 insertions(+) diff --git a/packages/logger/tests/unit/formatters.test.ts b/packages/logger/tests/unit/formatters.test.ts index 152bc20b24..b9b1a6d538 100644 --- a/packages/logger/tests/unit/formatters.test.ts +++ b/packages/logger/tests/unit/formatters.test.ts @@ -657,4 +657,63 @@ describe('Formatters', () => { timestamp: expect.any(String), }); }); + + it('when logRecordOrder is set, it orders the attributes in the log item', () => { + // Prepare + const formatter = new PowertoolsLogFormatter({ + logRecordOrder: [ + 'arnab', + 'message', + 'timestamp', + 'serviceName', + 'environment', + ], + }); + 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 + 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', + }) + ); + }); }); From 94b647fbdb4f2176036d5a3ce8bd72d356f21bec Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Mon, 2 Sep 2024 10:47:40 +0600 Subject: [PATCH 08/28] refactor: replace `lodash.merge` wih native JS --- .../src/formatter/PowertoolsLogFormatter.ts | 16 ++++++++++------ 1 file changed, 10 insertions(+), 6 deletions(-) diff --git a/packages/logger/src/formatter/PowertoolsLogFormatter.ts b/packages/logger/src/formatter/PowertoolsLogFormatter.ts index 3c1c76e82b..35c2be7156 100644 --- a/packages/logger/src/formatter/PowertoolsLogFormatter.ts +++ b/packages/logger/src/formatter/PowertoolsLogFormatter.ts @@ -1,4 +1,3 @@ -import merge from 'lodash.merge'; import type { LogAttributes, PowertoolsLog } from '../types/Log.js'; import type { UnformattedAttributes } from '../types/Logger.js'; import { LogFormatter } from './LogFormatter.js'; @@ -40,16 +39,21 @@ class PowertoolsLogFormatter extends LogFormatter { const orderedAttributes = {} as PowertoolsLog; // If logRecordOrder is set, order the attributes in the log item - this.logRecordOrder?.forEach((key) => { - if (key in baseAttributes) { + for (const key of this.logRecordOrder || []) { + if (key in baseAttributes && !(key in orderedAttributes)) { orderedAttributes[key] = baseAttributes[key]; - delete baseAttributes[key]; } - }); + } + + for (const key in baseAttributes) { + if (!(key in orderedAttributes)) { + orderedAttributes[key] = baseAttributes[key]; + } + } // Merge the ordered attributes with the rest of the attributes const powertoolsLogItem = new LogItem({ - attributes: merge(orderedAttributes, baseAttributes), + attributes: orderedAttributes, }); powertoolsLogItem.addAttributes(additionalLogAttributes); From e8014f4c5f44ab9f5fc97fed97dcf760485ad4cb Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Mon, 2 Sep 2024 10:53:27 +0600 Subject: [PATCH 09/28] test: `logRecordOrder` takes `additionalLogAttributes` into consideration during ordering --- packages/logger/tests/unit/formatters.test.ts | 60 ++++++++++++++++++- 1 file changed, 58 insertions(+), 2 deletions(-) diff --git a/packages/logger/tests/unit/formatters.test.ts b/packages/logger/tests/unit/formatters.test.ts index b9b1a6d538..e2a2468fd4 100644 --- a/packages/logger/tests/unit/formatters.test.ts +++ b/packages/logger/tests/unit/formatters.test.ts @@ -659,11 +659,64 @@ 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 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 + 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: [ - 'arnab', 'message', + 'additional_key', 'timestamp', 'serviceName', 'environment', @@ -689,7 +742,9 @@ describe('Formatters', () => { awsRequestId: 'abcdefg123456789', }, }; - const additionalLogAttributes: LogAttributes = {}; + const additionalLogAttributes: LogAttributes = { + additional_key: 'additional_value', + }; // Act const value = formatter.formatAttributes( @@ -703,6 +758,7 @@ describe('Formatters', () => { 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', From 80a23336d6c3389848d71c4234dbafb0ca91a0e6 Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Mon, 2 Sep 2024 11:07:45 +0600 Subject: [PATCH 10/28] test: formatter when `logRecordOrder` is not set --- packages/logger/tests/unit/formatters.test.ts | 284 +++++++++++------- 1 file changed, 169 insertions(+), 115 deletions(-) diff --git a/packages/logger/tests/unit/formatters.test.ts b/packages/logger/tests/unit/formatters.test.ts index e2a2468fd4..c6de3d4b0a 100644 --- a/packages/logger/tests/unit/formatters.test.ts +++ b/packages/logger/tests/unit/formatters.test.ts @@ -190,6 +190,175 @@ 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 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 + 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 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 = { + 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 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 = { + 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([ @@ -657,119 +826,4 @@ describe('Formatters', () => { timestamp: expect.any(String), }); }); - - it('when logRecordOrder is set, it orders the attributes in the log item', () => { - // Prepare - const formatter = new PowertoolsLogFormatter({ - logRecordOrder: ['message', 'timestamp', 'serviceName', 'environment'], - }); - 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 - 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 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 = { - 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', - }) - ); - }); }); From 2dd0cc55e3d1d1092ae9304a9a675d4bdc9ad370 Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Mon, 2 Sep 2024 11:08:28 +0600 Subject: [PATCH 11/28] feat: during formatting, apply ordering for `additionalLogAttributes` keys --- .../src/formatter/PowertoolsLogFormatter.ts | 16 +++++++++++++--- 1 file changed, 13 insertions(+), 3 deletions(-) diff --git a/packages/logger/src/formatter/PowertoolsLogFormatter.ts b/packages/logger/src/formatter/PowertoolsLogFormatter.ts index 35c2be7156..bdcc178d62 100644 --- a/packages/logger/src/formatter/PowertoolsLogFormatter.ts +++ b/packages/logger/src/formatter/PowertoolsLogFormatter.ts @@ -42,22 +42,32 @@ class PowertoolsLogFormatter extends LogFormatter { 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]; } } - // Merge the ordered attributes with the rest of the attributes + // Add remaining attributes from additionalLogAttributes + for (const key in additionalLogAttributes) { + if (!(key in orderedAttributes)) { + orderedAttributes[key] = additionalLogAttributes[key]; + } + } + const powertoolsLogItem = new LogItem({ attributes: orderedAttributes, }); - powertoolsLogItem.addAttributes(additionalLogAttributes); - return powertoolsLogItem; } } From 31efcecb236ebdcd165d855526e9663228d0faf2 Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Mon, 2 Sep 2024 11:25:29 +0600 Subject: [PATCH 12/28] test: `logRecordOrder` orders correctly when key doesn't even exist --- packages/logger/tests/unit/formatters.test.ts | 67 ++++++++++++++++++- 1 file changed, 65 insertions(+), 2 deletions(-) diff --git a/packages/logger/tests/unit/formatters.test.ts b/packages/logger/tests/unit/formatters.test.ts index c6de3d4b0a..86c164177b 100644 --- a/packages/logger/tests/unit/formatters.test.ts +++ b/packages/logger/tests/unit/formatters.test.ts @@ -190,7 +190,7 @@ describe('Formatters', () => { }); }); - it('when logRecordOrder is set, it orders the attributes in the log item', () => { + it('when `logRecordOrder` is set, it orders the attributes in the log item', () => { // Prepare const formatter = new PowertoolsLogFormatter({ logRecordOrder: ['message', 'timestamp', 'serviceName', 'environment'], @@ -243,7 +243,7 @@ describe('Formatters', () => { ); }); - it('when logRecordOrder is set, it orders the attributes in the log item taking `additionalLogAttributes` into consideration', () => { + it('when `logRecordOrder` is set, it orders the attributes in the log item taking `additionalLogAttributes` into consideration', () => { // Prepare const formatter = new PowertoolsLogFormatter({ logRecordOrder: [ @@ -305,6 +305,69 @@ describe('Formatters', () => { ); }); + 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 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 = { + 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({}); From 85ec8aa54eb754323fc390186f2b4fb5a6e3cbee Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Mon, 2 Sep 2024 21:45:05 +0600 Subject: [PATCH 13/28] test: `logRecordOrder` should be passed down to child logger --- .../tests/unit/initializeLogger.test.ts | 37 +++++++++++++++++++ 1 file changed, 37 insertions(+) diff --git a/packages/logger/tests/unit/initializeLogger.test.ts b/packages/logger/tests/unit/initializeLogger.test.ts index 6121f8d018..5558f38275 100644 --- a/packages/logger/tests/unit/initializeLogger.test.ts +++ b/packages/logger/tests/unit/initializeLogger.test.ts @@ -103,6 +103,43 @@ describe('Log levels', () => { ); }); + it('`logRecordOrder` should be passed down to child logger', () => { + // Prepare + const mockDate = new Date(1466424490000); + jest.useFakeTimers().setSystemTime(mockDate); + 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); + expect(JSON.stringify(JSON.parse(logSpy.mock.calls[0][0]))).toStrictEqual( + JSON.stringify({ + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + level: 'INFO', + message: 'Hello, world!', + sampling_rate: 0, + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + expect(JSON.stringify(JSON.parse(logSpy.mock.calls[1][0]))).toStrictEqual( + JSON.stringify({ + service: 'child-service', + timestamp: '2016-06-20T12:08:10.000Z', + level: 'INFO', + message: 'Hello, world from child!', + sampling_rate: 0, + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + + jest.useRealTimers(); + }); + it("doesn't use the global console object by default", () => { // Prepare process.env.POWERTOOLS_DEV = undefined; From 986245ca030451e1925bf5cdea9f9c70108ec0bc Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Tue, 3 Sep 2024 09:03:36 +0600 Subject: [PATCH 14/28] doc: reordering log keys position --- docs/core/logger.md | 16 ++++++++++++++++ examples/snippets/logger/reorderLogKeys.ts | 12 ++++++++++++ .../snippets/logger/reorderLogKeysOutput.json | 9 +++++++++ 3 files changed, 37 insertions(+) create mode 100644 examples/snippets/logger/reorderLogKeys.ts create mode 100644 examples/snippets/logger/reorderLogKeysOutput.json diff --git a/docs/core/logger.md b/docs/core/logger.md index 74be0bfde3..65a006266d 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -542,6 +542,22 @@ 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. + +=== "reorderLogKeys.ts" + + ```typescript hl_lines="3" + --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 From bd63350fefa19409b6e5689c0725524625bbdc7b Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Tue, 3 Sep 2024 09:05:45 +0600 Subject: [PATCH 15/28] doc: fix reorderLogKeys example highlight line --- docs/core/logger.md | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index 65a006266d..040efe3380 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -548,13 +548,13 @@ You can change the order of [standard Logger keys](#standard-structured-keys) or === "reorderLogKeys.ts" - ```typescript hl_lines="3" + ```typescript hl_lines="5 10" --8<-- "examples/snippets/logger/reorderLogKeys.ts" ``` === "reorderLogKeysOutput.json" - ```json hl_lines="2 3" + ```json hl_lines="2-3" --8<-- "examples/snippets/logger/reorderLogKeysOutput.json" ``` From e3bac0675866916e7e9a7d94efd9ce1da3915e83 Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Tue, 3 Sep 2024 09:20:49 +0600 Subject: [PATCH 16/28] doc: remove @returns --- packages/logger/src/Logger.ts | 1 - 1 file changed, 1 deletion(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index d32e709050..0769cc0f3f 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -1083,7 +1083,6 @@ class Logger extends Utility implements LoggerInterface { * @private * @param {LogFormatterInterface} logFormatter - The log formatt er * @param {LogRecordOrder} logRecordOrder - * @returns {void} */ private setLogFormatter( logFormatter?: LogFormatterInterface, From 1c6b2f6d87cdba5a1f9ae24281cdd4d907f44575 Mon Sep 17 00:00:00 2001 From: Asifur Rahman Arnab Date: Sat, 7 Sep 2024 10:49:37 +0600 Subject: [PATCH 17/28] Update packages/logger/src/Logger.ts Co-authored-by: Andrea Amorosi --- packages/logger/src/Logger.ts | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 0769cc0f3f..1d6042a5ea 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -1082,7 +1082,7 @@ class Logger extends Utility implements LoggerInterface { * * @private * @param {LogFormatterInterface} logFormatter - The log formatt er - * @param {LogRecordOrder} logRecordOrder + * @param {LogRecordOrder} logRecordOrder - Optional list of keys to specify order in logs */ private setLogFormatter( logFormatter?: LogFormatterInterface, From 07ba5406c01d023c3333de7f0d85a4005995764c Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Sat, 7 Sep 2024 10:50:57 +0600 Subject: [PATCH 18/28] doc: update `setLogFormatter` function doc block --- packages/logger/src/Logger.ts | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 1d6042a5ea..5947db21f1 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -1078,10 +1078,10 @@ 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( From bfe95105d1a4f34ef5cef8bb759d1190a894248b Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Sat, 7 Sep 2024 10:58:34 +0600 Subject: [PATCH 19/28] refactor: return early if `logRecordOrder` is not set --- packages/logger/src/formatter/PowertoolsLogFormatter.ts | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/packages/logger/src/formatter/PowertoolsLogFormatter.ts b/packages/logger/src/formatter/PowertoolsLogFormatter.ts index 089f4645e9..693c6a5929 100644 --- a/packages/logger/src/formatter/PowertoolsLogFormatter.ts +++ b/packages/logger/src/formatter/PowertoolsLogFormatter.ts @@ -35,10 +35,17 @@ class PowertoolsLogFormatter extends LogFormatter { xray_trace_id: attributes.xRayTraceId, }; + // 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 || []) { + for (const key of this.logRecordOrder) { if (key in baseAttributes && !(key in orderedAttributes)) { orderedAttributes[key] = baseAttributes[key]; } else if ( From da62495b0a9d668acde5aa53d46de7c75c48f10f Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Sun, 8 Sep 2024 10:20:19 +0600 Subject: [PATCH 20/28] refactor: make `logRecordOrder` & `logFormatter` mutually exclusive --- packages/logger/src/types/Logger.ts | 41 ++++++++++++++++++++++++++--- 1 file changed, 37 insertions(+), 4 deletions(-) diff --git a/packages/logger/src/types/Logger.ts b/packages/logger/src/types/Logger.ts index f8203a674e..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; /** @@ -85,7 +83,6 @@ type BaseConstructorOptions = { * This allows you to customize the serialization while still benefiting from the default behavior. */ jsonReplacerFn?: CustomJsonReplacerFn; - logRecordOrder?: LogRecordOrder; }; /** @@ -116,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. * @@ -127,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, From 4ae836c69802aaed706eae1f12db9e4a674a0475 Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Sun, 8 Sep 2024 10:36:58 +0600 Subject: [PATCH 21/28] refactor: use `logRecordOrder` only inside `PowertoolsLogFormatter` class --- packages/logger/src/formatter/LogFormatter.ts | 8 +------ .../src/formatter/PowertoolsLogFormatter.ts | 23 +++++++++++++++---- packages/logger/src/types/Log.ts | 13 +++++++++++ 3 files changed, 33 insertions(+), 11 deletions(-) diff --git a/packages/logger/src/formatter/LogFormatter.ts b/packages/logger/src/formatter/LogFormatter.ts index aeb59f5c6d..d34c222666 100644 --- a/packages/logger/src/formatter/LogFormatter.ts +++ b/packages/logger/src/formatter/LogFormatter.ts @@ -4,7 +4,7 @@ import type { LogFormatterInterface, LogFormatterOptions, } from '../types/Log.js'; -import type { LogRecordOrder, UnformattedAttributes } from '../types/Logger.js'; +import type { UnformattedAttributes } from '../types/Logger.js'; import type { LogItem } from './LogItem.js'; /** @@ -19,14 +19,8 @@ abstract class LogFormatter implements LogFormatterInterface { */ protected envVarsService?: EnvironmentVariablesService; - /** - * An array of keys that defines the order of the log record. - */ - protected logRecordOrder?: LogRecordOrder; - public constructor(options?: LogFormatterOptions) { this.envVarsService = options?.envVarsService; - this.logRecordOrder = options?.logRecordOrder; } /** diff --git a/packages/logger/src/formatter/PowertoolsLogFormatter.ts b/packages/logger/src/formatter/PowertoolsLogFormatter.ts index 693c6a5929..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. * @@ -36,7 +51,7 @@ class PowertoolsLogFormatter extends LogFormatter { }; // If logRecordOrder is not set, return the log item with the attributes in the order they were added - if (this.logRecordOrder === undefined) { + if (this.#logRecordOrder === undefined) { return new LogItem({ attributes: baseAttributes }).addAttributes( additionalLogAttributes ); @@ -45,7 +60,7 @@ class PowertoolsLogFormatter extends LogFormatter { const orderedAttributes = {} as PowertoolsLog; // If logRecordOrder is set, order the attributes in the log item - for (const key of this.logRecordOrder) { + for (const key of this.#logRecordOrder) { if (key in baseAttributes && !(key in orderedAttributes)) { orderedAttributes[key] = baseAttributes[key]; } else if ( diff --git a/packages/logger/src/types/Log.ts b/packages/logger/src/types/Log.ts index 393871a70c..6e26008bed 100644 --- a/packages/logger/src/types/Log.ts +++ b/packages/logger/src/types/Log.ts @@ -125,7 +125,19 @@ type LogFormatterOptions = { * If set, it gives the LogFormatter access to environment variables. */ 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; }; @@ -177,4 +189,5 @@ export type { LogItemInterface, LogFormatterOptions, LogFormatterInterface, + PowerToolsLogFormatterOptions, }; From 0a50ee5a2a5ef2d05cadde96fbbae2906c3bc4b0 Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Sun, 8 Sep 2024 15:23:07 +0600 Subject: [PATCH 22/28] test: refactor test to match the key orders --- .../tests/unit/initializeLogger.test.ts | 40 ++++++++----------- 1 file changed, 16 insertions(+), 24 deletions(-) diff --git a/packages/logger/tests/unit/initializeLogger.test.ts b/packages/logger/tests/unit/initializeLogger.test.ts index 5558f38275..c3dbeb3c92 100644 --- a/packages/logger/tests/unit/initializeLogger.test.ts +++ b/packages/logger/tests/unit/initializeLogger.test.ts @@ -105,8 +105,6 @@ describe('Log levels', () => { it('`logRecordOrder` should be passed down to child logger', () => { // Prepare - const mockDate = new Date(1466424490000); - jest.useFakeTimers().setSystemTime(mockDate); const logger = new Logger({ logRecordOrder: ['service', 'timestamp'] }); const childLogger = logger.createChild({ serviceName: 'child-service' }); @@ -116,28 +114,22 @@ describe('Log levels', () => { // Assess expect(logSpy).toHaveBeenCalledTimes(2); - expect(JSON.stringify(JSON.parse(logSpy.mock.calls[0][0]))).toStrictEqual( - JSON.stringify({ - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - level: 'INFO', - message: 'Hello, world!', - sampling_rate: 0, - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }) - ); - expect(JSON.stringify(JSON.parse(logSpy.mock.calls[1][0]))).toStrictEqual( - JSON.stringify({ - service: 'child-service', - timestamp: '2016-06-20T12:08:10.000Z', - level: 'INFO', - message: 'Hello, world from child!', - sampling_rate: 0, - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }) - ); - - jest.useRealTimers(); + expect(Object.keys(JSON.parse(logSpy.mock.calls[0][0]))).toEqual([ + 'service', + 'timestamp', + 'level', + 'message', + 'sampling_rate', + 'xray_trace_id', + ]); + expect(Object.keys(JSON.parse(logSpy.mock.calls[1][0]))).toEqual([ + 'service', + 'timestamp', + 'level', + 'message', + 'sampling_rate', + 'xray_trace_id', + ]); }); it("doesn't use the global console object by default", () => { From 37b43b220136e2b4756af0388f7076c14587cc1b Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Sun, 8 Sep 2024 15:40:07 +0600 Subject: [PATCH 23/28] refactor: extract unformattedAttributes to the top level --- packages/logger/tests/unit/formatters.test.ts | 131 ++++-------------- 1 file changed, 26 insertions(+), 105 deletions(-) diff --git a/packages/logger/tests/unit/formatters.test.ts b/packages/logger/tests/unit/formatters.test.ts index 86c164177b..5b46d1a636 100644 --- a/packages/logger/tests/unit/formatters.test.ts +++ b/packages/logger/tests/unit/formatters.test.ts @@ -46,6 +46,27 @@ class ErrorWithCauseString extends Error { } } +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'); @@ -146,26 +167,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 @@ -185,7 +186,7 @@ describe('Formatters', () => { message: 'This is a WARN log', sampling_rate: 0.25, service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', + timestamp: unformattedAttributes.timestamp.toISOString(), xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', }); }); @@ -195,26 +196,6 @@ describe('Formatters', () => { const formatter = new PowertoolsLogFormatter({ logRecordOrder: ['message', 'timestamp', 'serviceName', 'environment'], }); - 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 @@ -229,7 +210,7 @@ describe('Formatters', () => { expect(JSON.stringify(response)).toEqual( JSON.stringify({ message: 'This is a WARN log', - timestamp: '2016-06-20T12:08:10.000Z', + timestamp: unformattedAttributes.timestamp.toISOString(), cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:Example', function_memory_size: '123', @@ -254,26 +235,6 @@ describe('Formatters', () => { 'environment', ], }); - 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 = { additional_key: 'additional_value', }; @@ -291,7 +252,7 @@ describe('Formatters', () => { JSON.stringify({ message: 'This is a WARN log', additional_key: 'additional_value', - timestamp: '2016-06-20T12:08:10.000Z', + timestamp: unformattedAttributes.timestamp.toISOString(), cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:Example', function_memory_size: '123', @@ -317,26 +278,6 @@ describe('Formatters', () => { 'environment', ], }); - 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 = { additional_key: 'additional_value', }; @@ -354,7 +295,7 @@ describe('Formatters', () => { JSON.stringify({ message: 'This is a WARN log', additional_key: 'additional_value', - timestamp: '2016-06-20T12:08:10.000Z', + timestamp: unformattedAttributes.timestamp.toISOString(), cold_start: true, function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:Example', function_memory_size: '123', @@ -371,26 +312,6 @@ describe('Formatters', () => { it('when logRecordOrder is not set, it will not order the attributes in the log item', () => { // Prepare const formatter = new PowertoolsLogFormatter({}); - 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 = { additional_key: 'additional_value', }; @@ -415,7 +336,7 @@ describe('Formatters', () => { message: 'This is a WARN log', sampling_rate: 0.25, service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', + timestamp: unformattedAttributes.timestamp.toISOString(), xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', additional_key: 'additional_value', }) From ce2cb90916eabc16d42ab92ecce392e8df62beeb Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Sun, 8 Sep 2024 16:01:29 +0600 Subject: [PATCH 24/28] test: update test to add uncovered line --- packages/logger/tests/unit/formatters.test.ts | 2 ++ 1 file changed, 2 insertions(+) diff --git a/packages/logger/tests/unit/formatters.test.ts b/packages/logger/tests/unit/formatters.test.ts index 5b46d1a636..bc6f6e137b 100644 --- a/packages/logger/tests/unit/formatters.test.ts +++ b/packages/logger/tests/unit/formatters.test.ts @@ -237,6 +237,7 @@ describe('Formatters', () => { }); const additionalLogAttributes: LogAttributes = { additional_key: 'additional_value', + another_key: 'another_value', }; // Act @@ -262,6 +263,7 @@ describe('Formatters', () => { sampling_rate: 0.25, service: 'hello-world', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + another_key: 'another_value', }) ); }); From 8f90b9005e42707d811a149c64d73705ec4cb941 Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Sun, 8 Sep 2024 16:12:19 +0600 Subject: [PATCH 25/28] test: set `unformattedAttributes.timestamp` inside `beforeEach` --- packages/logger/tests/unit/formatters.test.ts | 11 ++++++----- 1 file changed, 6 insertions(+), 5 deletions(-) diff --git a/packages/logger/tests/unit/formatters.test.ts b/packages/logger/tests/unit/formatters.test.ts index bc6f6e137b..0db9ab3f1e 100644 --- a/packages/logger/tests/unit/formatters.test.ts +++ b/packages/logger/tests/unit/formatters.test.ts @@ -118,6 +118,7 @@ describe('Formatters', () => { const mockDate = new Date(1466424490000); jest.useFakeTimers().setSystemTime(mockDate); jest.resetAllMocks(); + unformattedAttributes.timestamp = mockDate; }); afterAll(() => { @@ -186,7 +187,7 @@ describe('Formatters', () => { message: 'This is a WARN log', sampling_rate: 0.25, service: 'hello-world', - timestamp: unformattedAttributes.timestamp.toISOString(), + timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', }); }); @@ -210,7 +211,7 @@ describe('Formatters', () => { expect(JSON.stringify(response)).toEqual( JSON.stringify({ message: 'This is a WARN log', - timestamp: unformattedAttributes.timestamp.toISOString(), + 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', @@ -253,7 +254,7 @@ describe('Formatters', () => { JSON.stringify({ message: 'This is a WARN log', additional_key: 'additional_value', - timestamp: unformattedAttributes.timestamp.toISOString(), + 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', @@ -297,7 +298,7 @@ describe('Formatters', () => { JSON.stringify({ message: 'This is a WARN log', additional_key: 'additional_value', - timestamp: unformattedAttributes.timestamp.toISOString(), + 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', @@ -338,7 +339,7 @@ describe('Formatters', () => { message: 'This is a WARN log', sampling_rate: 0.25, service: 'hello-world', - timestamp: unformattedAttributes.timestamp.toISOString(), + timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', additional_key: 'additional_value', }) From 735c650433d8df6756d4b15f9950215cbd557420 Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Sun, 8 Sep 2024 16:21:58 +0600 Subject: [PATCH 26/28] doc: add callout --- docs/core/logger.md | 3 +++ 1 file changed, 3 insertions(+) diff --git a/docs/core/logger.md b/docs/core/logger.md index 040efe3380..8417e0ee0b 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -546,6 +546,9 @@ In the event you have set a log level in Powertools to a level that is lower tha 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" From 62f0aeff50e47edfbf44e0393608e00032a55c91 Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Sun, 8 Sep 2024 16:25:35 +0600 Subject: [PATCH 27/28] style: doc block & afterAll cleanup for `unformattedAttributes` --- packages/logger/tests/unit/formatters.test.ts | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/packages/logger/tests/unit/formatters.test.ts b/packages/logger/tests/unit/formatters.test.ts index 0db9ab3f1e..a8aa727000 100644 --- a/packages/logger/tests/unit/formatters.test.ts +++ b/packages/logger/tests/unit/formatters.test.ts @@ -46,6 +46,9 @@ class ErrorWithCauseString extends Error { } } +/** + * Unformatted attributes for testing + */ const unformattedAttributes: UnformattedAttributes = { sampleRateValue: 0.25, awsRegion: 'eu-west-1', @@ -123,6 +126,7 @@ describe('Formatters', () => { afterAll(() => { jest.useRealTimers(); + unformattedAttributes.timestamp = new Date(); }); // #region base log keys From 74f614f59726c0bc44fc8df898bd74dd8235a3f5 Mon Sep 17 00:00:00 2001 From: arnabrahman Date: Sun, 8 Sep 2024 16:42:28 +0600 Subject: [PATCH 28/28] test: refactor `logRecordOrder` test for child logger --- .../logger/tests/unit/initializeLogger.test.ts | 15 +++++---------- 1 file changed, 5 insertions(+), 10 deletions(-) diff --git a/packages/logger/tests/unit/initializeLogger.test.ts b/packages/logger/tests/unit/initializeLogger.test.ts index c3dbeb3c92..4cc6310fcc 100644 --- a/packages/logger/tests/unit/initializeLogger.test.ts +++ b/packages/logger/tests/unit/initializeLogger.test.ts @@ -114,22 +114,17 @@ describe('Log levels', () => { // Assess expect(logSpy).toHaveBeenCalledTimes(2); - expect(Object.keys(JSON.parse(logSpy.mock.calls[0][0]))).toEqual([ + const expectedKeys = [ 'service', 'timestamp', 'level', 'message', 'sampling_rate', 'xray_trace_id', - ]); - expect(Object.keys(JSON.parse(logSpy.mock.calls[1][0]))).toEqual([ - '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", () => {