From c1675c16967510a33d57ec39762ffbc8a37fc91a Mon Sep 17 00:00:00 2001 From: Bilal Quadri Date: Fri, 7 Jul 2023 14:15:13 -0400 Subject: [PATCH] feat(logger): improve default log formatter ordering This resolves #1568. The problem raised in that issue is that the log formatter outputs log lines with keys written in alphabetical order. In practice, that means they start off with the cold start flag, the `function_arn`, `function_name`, `function_memory_size`, and a whole bunch of other stuff that is not usually of interest. The actual log level and message are buried and need log lines expanded to be seen. Even when expanded, they're hard to visually spot at a glance. When viewing a log group in Cloudwatch or some other UI that truncates log lines, you effectively see no useful information at all (see screenshot in #1568 for example). This change addresses the problem by surfacing log properties in order of usefulness. This is a subjective decision, and opinions may vary, but the order submitted in this PR should be preferable for the vast majority of users. The "at-a-glance" view of logs should now be actionable and help with log-diving and debugging. The actual information recorded is unchanged and log insight queries should still work as before. The serialization order is well-defined in modern ECMAScript engines: Serialization From the MDN docs on `JSON.stringify`: > Only enumerable own properties are visited. This means `Map`, `Set`, > etc. will become `"{}"`. You can use the replacer parameter to > serialize them to something more useful. Properties are visited using > the same algorithm as `Object.keys()`, which has a well-defined order > and is stable across implementations. For example, `JSON.stringify` on > the same object will always produce the same string, and > `JSON.parse(JSON.stringify(obj))` would produce an object with the > same key ordering as the original (assuming the object is completely > JSON-serializable). > > Source: https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Global_Objects/JSON/stringify#description And the note about what that order is: > The traversal order, as of modern ECMAScript specification, is > well-defined and consistent across implementations. Within each > component of the prototype chain, all non-negative integer keys (those > that can be array indices) will be traversed first in ascending order > by value, then other string keys in ascending chronological order of > property creation. > > Source: https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Statements/for...in --- .../src/formatter/PowertoolLogFormatter.ts | 18 +++--- .../formatter/PowertoolLogFormatter.test.ts | 59 +++++++++++++++++++ 2 files changed, 69 insertions(+), 8 deletions(-) diff --git a/packages/logger/src/formatter/PowertoolLogFormatter.ts b/packages/logger/src/formatter/PowertoolLogFormatter.ts index 0fa77928e2..ba5db4645d 100644 --- a/packages/logger/src/formatter/PowertoolLogFormatter.ts +++ b/packages/logger/src/formatter/PowertoolLogFormatter.ts @@ -4,7 +4,9 @@ import { PowertoolLog } from '../types/formats'; /** * This class is used to transform a set of log key-value pairs - * in the AWS Lambda Powertools' default structure log format. + * in the AWS Lambda Powertools' default structure log format. It orders + * attribute keys in a way that should be useful when visually scanning logs in + * a UI such as the Cloudwatch console. * * @class * @extends {LogFormatter} @@ -18,17 +20,17 @@ class PowertoolLogFormatter extends LogFormatter { */ public formatAttributes(attributes: UnformattedAttributes): PowertoolLog { return { - 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, + function_request_id: attributes.lambdaContext?.awsRequestId, + xray_trace_id: attributes.xRayTraceId, + cold_start: attributes.lambdaContext?.coldStart, + function_memory_size: attributes.lambdaContext?.memoryLimitInMB, service: attributes.serviceName, + sampling_rate: attributes.sampleRateValue, + function_arn: attributes.lambdaContext?.invokedFunctionArn, + function_name: attributes.lambdaContext?.functionName, timestamp: this.formatTimestamp(attributes.timestamp), - xray_trace_id: attributes.xRayTraceId, }; } } diff --git a/packages/logger/tests/unit/formatter/PowertoolLogFormatter.test.ts b/packages/logger/tests/unit/formatter/PowertoolLogFormatter.test.ts index 49daebe597..f42d3d11dd 100644 --- a/packages/logger/tests/unit/formatter/PowertoolLogFormatter.test.ts +++ b/packages/logger/tests/unit/formatter/PowertoolLogFormatter.test.ts @@ -91,6 +91,65 @@ describe('Class: PowertoolLogFormatter', () => { xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', }); }); + + test('it returns an object whose properties serialize in a useful order for viewing in Cloudwatch console', () => { + // Prepare + const formatter = new PowertoolLogFormatter(); + 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', + }, + }; + + // Act + const value = formatter.formatAttributes(unformattedAttributes); + const serializedValue = JSON.stringify(value); + + // Assess + const orderOf = (key: string): number => serializedValue.indexOf(key); + // These are execution specific properties where order matters most + expect(orderOf('level')).toBeLessThan(orderOf('message')); + expect(orderOf('message')).toBeLessThan(orderOf('function_request_id')); + expect(orderOf('function_request_id')).toBeLessThan( + orderOf('xray_trace_id') + ); + expect(orderOf('xray_trace_id')).toBeLessThan(orderOf('cold_start')); + expect(orderOf('cold_start')).toBeLessThan( + orderOf('function_memory_size') + ); + // For all other properties, we just need to check that they come after + // the ones above. Timestamp is technicially execution specific, but log + // entries in Cloudwatch already have timestamps anyway, so it is less + // important for at-a-glance viewing. + expect(orderOf('function_memory_size')).toBeLessThan(orderOf('service')); + expect(orderOf('function_memory_size')).toBeLessThan( + orderOf('sampling_rate') + ); + expect(orderOf('function_memory_size')).toBeLessThan( + orderOf('function_arn') + ); + expect(orderOf('function_memory_size')).toBeLessThan( + orderOf('function_name') + ); + expect(orderOf('function_memory_size')).toBeLessThan( + orderOf('timestamp') + ); + }); }); describe('Method: formatError', () => {