From 51f34e03fb8f7a5a889e0dc5f35f949bcfe7d72a Mon Sep 17 00:00:00 2001 From: Andrea Amorosi Date: Wed, 5 Feb 2025 17:58:16 +0100 Subject: [PATCH] improv(logger): switch key order for better readability --- docs/core/logger.md | 8 +- .../snippets/logger/customTimezoneOutput.json | 8 +- .../snippets/logger/reorderLogKeysOutput.json | 8 +- .../snippets/logger/unserializableValues.json | 10 +- .../src/formatter/PowertoolsLogFormatter.ts | 8 +- packages/logger/tests/unit/formatters.test.ts | 129 ++++++++---------- .../tests/unit/initializeLogger.test.ts | 4 +- 7 files changed, 85 insertions(+), 90 deletions(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index 2fc7516d8a..d4fa68f45d 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -148,15 +148,15 @@ In each case, the printed log will look like this: ```json hl_lines="2-6" { + "level": "INFO", + "message": "This is an INFO log with some context", + "timestamp": "2021-12-12T21:21:08.921Z", + "service": "serverlessAirline", "cold_start": true, "function_arn": "arn:aws:lambda:eu-west-1:123456789012:function:shopping-cart-api-lambda-prod-eu-west-1", "function_memory_size": 128, "function_request_id": "c6af9ac6-7b61-11e6-9a41-93e812345678", "function_name": "shopping-cart-api-lambda-prod-eu-west-1", - "level": "INFO", - "message": "This is an INFO log with some context", - "service": "serverlessAirline", - "timestamp": "2021-12-12T21:21:08.921Z", "xray_trace_id": "abcdef123456abcdef123456abcdef123456" } ``` diff --git a/examples/snippets/logger/customTimezoneOutput.json b/examples/snippets/logger/customTimezoneOutput.json index c8cf7f074f..0e146c6b5a 100644 --- a/examples/snippets/logger/customTimezoneOutput.json +++ b/examples/snippets/logger/customTimezoneOutput.json @@ -2,17 +2,17 @@ { "level": "INFO", "message": "Hello, World!", - "sampling_rate": 0, - "service": "serverlessAirline", "timestamp": "2024-07-01T11:00:37.886Z", + "service": "serverlessAirline", + "sampling_rate": 0, "xray_trace_id": "1-66828c55-2bb635c65eb609c820ebe7bc" }, { "level": "INFO", "message": "Ciao, Mondo!", - "sampling_rate": 0, - "service": "serverlessAirline", "timestamp": "2024-07-01T13:00:37.934+02:00", + "service": "serverlessAirline", + "sampling_rate": 0, "xray_trace_id": "1-66828c55-2bb635c65eb609c820ebe7bc" } ] diff --git a/examples/snippets/logger/reorderLogKeysOutput.json b/examples/snippets/logger/reorderLogKeysOutput.json index b9b23404cb..f0e8bb36fc 100644 --- a/examples/snippets/logger/reorderLogKeysOutput.json +++ b/examples/snippets/logger/reorderLogKeysOutput.json @@ -1,9 +1,9 @@ { - "timestamp": "2024-09-03T02:59:06.603Z", - "additionalKey": "additionalValue", "level": "INFO", "message": "Hello, World!", - "sampling_rate": 0, + "timestamp": "2024-09-03T02:59:06.603Z", "service": "serverlessAirline", + "additionalKey": "additionalValue", + "sampling_rate": 0, "xray_trace_id": "1-66d67b7a-79bc7b2346b32af01b437cf8" -} \ No newline at end of file +} diff --git a/examples/snippets/logger/unserializableValues.json b/examples/snippets/logger/unserializableValues.json index 9134cdcbe3..ffdd1c762e 100644 --- a/examples/snippets/logger/unserializableValues.json +++ b/examples/snippets/logger/unserializableValues.json @@ -1,9 +1,13 @@ { "level": "INFO", "message": "Serialize with custom serializer", - "sampling_rate": 0, - "service": "serverlessAirline", "timestamp": "2024-07-07T09:52:14.212Z", + "service": "serverlessAirline", + "sampling_rate": 0, "xray_trace_id": "1-668a654d-396c646b760ee7d067f32f18", - "serializedValue": [1, 2, 3] + "serializedValue": [ + 1, + 2, + 3 + ] } diff --git a/packages/logger/src/formatter/PowertoolsLogFormatter.ts b/packages/logger/src/formatter/PowertoolsLogFormatter.ts index aae7ecbade..9172d33ff1 100644 --- a/packages/logger/src/formatter/PowertoolsLogFormatter.ts +++ b/packages/logger/src/formatter/PowertoolsLogFormatter.ts @@ -44,16 +44,16 @@ class PowertoolsLogFormatter extends LogFormatter { const baseAttributes: Partial & Partial & LogAttributes = { + level: attributes.logLevel, + message: attributes.message, + timestamp: this.formatTimestamp(attributes.timestamp), + service: attributes.serviceName, cold_start: attributes.lambdaContext?.coldStart, function_arn: attributes.lambdaContext?.invokedFunctionArn, function_memory_size: attributes.lambdaContext?.memoryLimitInMB, function_name: attributes.lambdaContext?.functionName, function_request_id: attributes.lambdaContext?.awsRequestId, - level: attributes.logLevel, - message: attributes.message, sampling_rate: attributes.sampleRateValue, - service: attributes.serviceName, - timestamp: this.formatTimestamp(attributes.timestamp), xray_trace_id: attributes.xRayTraceId, }; diff --git a/packages/logger/tests/unit/formatters.test.ts b/packages/logger/tests/unit/formatters.test.ts index 611101a843..1097d2d78b 100644 --- a/packages/logger/tests/unit/formatters.test.ts +++ b/packages/logger/tests/unit/formatters.test.ts @@ -185,7 +185,7 @@ 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'], + logRecordOrder: ['message', 'timestamp', 'service'], }); const additionalLogAttributes: LogAttributes = {}; @@ -198,21 +198,19 @@ describe('Formatters', () => { 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', - }) - ); + expect(response).toStrictEqual({ + message: 'This is a WARN log', + timestamp: '2016-06-20T12:08:10.000Z', + service: 'hello-world', + level: 'WARN', + 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', + sampling_rate: 0.25, + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }); }); it('when `logRecordOrder` is set, it orders the attributes in the log item taking `additionalLogAttributes` into consideration', () => { @@ -222,8 +220,8 @@ describe('Formatters', () => { 'message', 'additional_key', 'timestamp', - 'serviceName', - 'environment', + 'level', + 'service', ]), }); const additionalLogAttributes: LogAttributes = { @@ -240,23 +238,21 @@ describe('Formatters', () => { 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', - }) - ); + expect(response).toStrictEqual({ + message: 'This is a WARN log', + additional_key: 'additional_value', + timestamp: '2016-06-20T12:08:10.000Z', + level: 'WARN', + service: 'hello-world', + 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', + sampling_rate: 0.25, + 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', () => { @@ -267,8 +263,7 @@ describe('Formatters', () => { 'additional_key', 'not_present', 'timestamp', - 'serviceName', - 'environment', + 'level', ], }); const additionalLogAttributes: LogAttributes = { @@ -284,22 +279,20 @@ describe('Formatters', () => { 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', - }) - ); + expect(response).toStrictEqual({ + message: 'This is a WARN log', + additional_key: 'additional_value', + timestamp: '2016-06-20T12:08:10.000Z', + level: 'WARN', + service: 'hello-world', + 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', + sampling_rate: 0.25, + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }); }); it('when logRecordOrder is not set, it will not order the attributes in the log item', () => { @@ -318,22 +311,20 @@ describe('Formatters', () => { 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', - }) - ); + expect(response).toStrictEqual({ + level: 'WARN', + message: 'This is a WARN log', + timestamp: '2016-06-20T12:08:10.000Z', + service: 'hello-world', + 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', + sampling_rate: 0.25, + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + additional_key: 'additional_value', + }); }); // #region format errors diff --git a/packages/logger/tests/unit/initializeLogger.test.ts b/packages/logger/tests/unit/initializeLogger.test.ts index cc763d2730..616382a1c6 100644 --- a/packages/logger/tests/unit/initializeLogger.test.ts +++ b/packages/logger/tests/unit/initializeLogger.test.ts @@ -151,9 +151,9 @@ describe('Log levels', () => { { level: 'INFO', message: 'Hello, world!', - sampling_rate: 0, - service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', + service: 'hello-world', + sampling_rate: 0, xray_trace_id: '1-abcdef12-3456abcdef123456abcdef12', }, null,