From bd384580671e6af06b0ed452a3b3e210caef20cc Mon Sep 17 00:00:00 2001 From: Dmitry Balabanov Date: Tue, 24 May 2022 16:20:10 +0200 Subject: [PATCH] fix(logger): enable logging of arbitrary objects (#883) * fix(logger): enable logging of arbitrary objects * Update docs * Add E2E test * Use nested objects in tests * Update usage docs --- docs/core/logger.md | 34 ++++++++++------ packages/logger/examples/additional-keys.ts | 5 ++- packages/logger/src/types/Log.ts | 2 +- .../basicFeatures.middy.test.FunctionCode.ts | 19 ++++++++- .../tests/e2e/basicFeatures.middy.test.ts | 29 +++++++++++++- packages/logger/tests/unit/Logger.test.ts | 40 +++++++++++++++++++ 6 files changed, 112 insertions(+), 17 deletions(-) diff --git a/docs/core/logger.md b/docs/core/logger.md index d554d0e1e0..6a34cab816 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -273,34 +273,37 @@ You can append additional persistent keys and values in the logs generated durin !!! tip "Logger will automatically ignore any key with an `undefined` value" -### Appending additional log keys and values to a single log item +### Appending additional data to a single log item -You can append additional keys and values in a single log item passing them as parameters. -Pass a string for logging it with default key name `extra`. Alternatively, pass one or multiple objects with custom keys. -If you already have an object containing a `message` key and an additional property, you can pass this object directly. +You can append additional data to a single log item by passing objects as additional parameters. + +* Pass a simple string for logging it with default key name `extra` +* Pass one or multiple objects containing arbitrary data to be logged. Each data object should be placed in an enclosing object as a single property value, you can name this property as you need: `{ myData: arbitraryObjectToLog }` +* If you already have an object containing a `message` key and an additional property, you can pass this object directly === "handler.ts" - ```typescript hl_lines="14 18-19 23 31" + ```typescript hl_lines="14 18-20 24 32" import { Logger } from '@aws-lambda-powertools/logger'; const logger = new Logger(); - export const handler = async (_event: any, _context: any): Promise => { + export const handler = async (event: any, _context: any): Promise => { const myImportantVariable = { foo: 'bar' }; - // Pass additional keys and values in single log items + // Log additional data in single log items // As second parameter logger.info('This is a log with an extra variable', { data: myImportantVariable }); - // You can also pass multiple parameters - logger.info('This is a log with 2 extra variables', + // You can also pass multiple parameters containing arbitrary objects + logger.info('This is a log with 3 extra objects', { data: myImportantVariable }, - { correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } } + { correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } }, + { lambdaEvent: event } ); // Simply pass a string for logging additional data @@ -322,14 +325,14 @@ If you already have an object containing a `message` key and an additional prope ``` === "Example CloudWatch Logs excerpt" - ```json hl_lines="7 15-16 24 32" + ```json hl_lines="7 15-21 28 37" { "level": "INFO", "message": "This is a log with an extra variable", "service": "serverlessAirline", "timestamp": "2021-12-12T22:06:17.463Z", "xray_trace_id": "abcdef123456abcdef123456abcdef123456", - "data": { foo: "bar" } + "data": { "foo": "bar" } } { "level": "INFO", @@ -338,7 +341,12 @@ If you already have an object containing a `message` key and an additional prope "timestamp": "2021-12-12T22:06:17.466Z", "xray_trace_id": "abcdef123456abcdef123456abcdef123456", "data": { "foo": "bar" }, - "correlationIds": { "myCustomCorrelationId": "foo-bar-baz" } + "correlationIds": { "myCustomCorrelationId": "foo-bar-baz" }, + "lambdaEvent": { + "exampleEventData": { + "eventValue": 42 + } + } } { "level": "INFO", diff --git a/packages/logger/examples/additional-keys.ts b/packages/logger/examples/additional-keys.ts index 06dd9c6e02..673a820248 100644 --- a/packages/logger/examples/additional-keys.ts +++ b/packages/logger/examples/additional-keys.ts @@ -12,7 +12,7 @@ import { Logger } from '../src'; const logger = new Logger(); -const lambdaHandler: Handler = async () => { +const lambdaHandler: Handler = async (event) => { // Pass a custom correlation ID logger.warn('This is a WARN log', { correlationIds: { myCustomCorrelationId: 'foo-bar-baz' } }); @@ -23,6 +23,9 @@ const lambdaHandler: Handler = async () => { // Pass a simple string as additional data logger.info('This is an INFO log', 'Extra log data'); + // Pass an arbitrary object as additional data + logger.debug('This is a DEBUG log', { lambdaEvent: event }); + return { foo: 'bar' }; diff --git a/packages/logger/src/types/Log.ts b/packages/logger/src/types/Log.ts index d926483afc..0b7cd5d30f 100644 --- a/packages/logger/src/types/Log.ts +++ b/packages/logger/src/types/Log.ts @@ -9,7 +9,7 @@ type LogLevelThresholds = { [key in LogLevel]: number; }; -type LogAttributeValue = string | number | boolean | null | undefined | LogAttributeValue[] | { [key: string]: LogAttributeValue } | Error; +type LogAttributeValue = unknown; type LogAttributes = { [key: string]: LogAttributeValue }; type LogAttributesWithMessage = LogAttributes & { diff --git a/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts b/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts index 385c8a7d7e..3270b40830 100644 --- a/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts +++ b/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts @@ -1,5 +1,5 @@ import { injectLambdaContext, Logger } from '../../src'; -import { APIGatewayProxyEvent, Context } from 'aws-lambda'; +import { APIGatewayProxyEvent, Context, APIGatewayAuthorizerResult } from 'aws-lambda'; import middy from '@middy/core'; const PERSISTENT_KEY = process.env.PERSISTENT_KEY; @@ -7,6 +7,8 @@ const PERSISTENT_VALUE = process.env.PERSISTENT_VALUE; const ERROR_MSG = process.env.ERROR_MSG || 'error'; const SINGLE_LOG_ITEM_KEY = process.env.SINGLE_LOG_ITEM_KEY; const SINGLE_LOG_ITEM_VALUE = process.env.SINGLE_LOG_ITEM_VALUE; +const ARBITRARY_OBJECT_KEY = process.env.ARBITRARY_OBJECT_KEY; +const ARBITRARY_OBJECT_DATA = process.env.ARBITRARY_OBJECT_DATA; const logger = new Logger({ persistentLogAttributes: { @@ -34,6 +36,21 @@ const testFunction = async (event: APIGatewayProxyEvent, context: Context): Prom logger.error(ERROR_MSG, e as Error); } + // Test feature 7: Logging an arbitrary object + const obj: APIGatewayAuthorizerResult = { + principalId: ARBITRARY_OBJECT_DATA, + policyDocument: { + Version: 'Version' + ARBITRARY_OBJECT_DATA, + Statement: [{ + Effect: 'Effect' + ARBITRARY_OBJECT_DATA, + Action: 'Action' + ARBITRARY_OBJECT_DATA, + Resource: 'Resource' + ARBITRARY_OBJECT_DATA + }] + } + }; + + logger.info('A log entry with an object', { [ARBITRARY_OBJECT_KEY]: obj }); + return { requestId: context.awsRequestId, }; diff --git a/packages/logger/tests/e2e/basicFeatures.middy.test.ts b/packages/logger/tests/e2e/basicFeatures.middy.test.ts index c2e1b73a92..bb4cd014fe 100644 --- a/packages/logger/tests/e2e/basicFeatures.middy.test.ts +++ b/packages/logger/tests/e2e/basicFeatures.middy.test.ts @@ -10,6 +10,7 @@ import path from 'path'; import { randomUUID } from 'crypto'; import { App, Stack } from 'aws-cdk-lib'; +import { APIGatewayAuthorizerResult } from 'aws-lambda'; import { createStackWithLambdaFunction, generateUniqueName, @@ -45,6 +46,8 @@ const PERSISTENT_VALUE = `a persistent value that will be put in every log ${uui const SINGLE_LOG_ITEM_KEY = `keyForSingleLogItem${uuid}`; const SINGLE_LOG_ITEM_VALUE = `a value for a single log item${uuid}`; const ERROR_MSG = `error-${uuid}`; +const ARBITRARY_OBJECT_KEY = `keyForArbitraryObject${uuid}`; +const ARBITRARY_OBJECT_DATA = `arbitrary object data ${uuid}`; const integTestApp = new App(); let logGroupName: string; // We do not know it until deployment @@ -72,6 +75,8 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime} SINGLE_LOG_ITEM_KEY, SINGLE_LOG_ITEM_VALUE, ERROR_MSG, + ARBITRARY_OBJECT_KEY, + ARBITRARY_OBJECT_DATA, }, logGroupOutputKey: STACK_OUTPUT_LOG_GROUP, runtime: runtime, @@ -161,10 +166,32 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime} expect(logMessages).toHaveLength(1); }, TEST_CASE_TIMEOUT); + + it('should log additional arbitrary object only once', async () => { + const logMessages = invocationLogs[0].getFunctionLogs() + .filter(message => message.includes(ARBITRARY_OBJECT_DATA)); + + expect(logMessages).toHaveLength(1); + + const logObject = InvocationLogs.parseFunctionLog(logMessages[0]); + expect(logObject).toHaveProperty(ARBITRARY_OBJECT_KEY); + const arbitrary = logObject[ARBITRARY_OBJECT_KEY] as APIGatewayAuthorizerResult; + expect(arbitrary.principalId).toBe(ARBITRARY_OBJECT_DATA); + expect(arbitrary.policyDocument).toEqual(expect.objectContaining( + { + Version: 'Version' + ARBITRARY_OBJECT_DATA, + Statement: [{ + Effect: 'Effect' + ARBITRARY_OBJECT_DATA, + Action: 'Action' + ARBITRARY_OBJECT_DATA, + Resource: 'Resource' + ARBITRARY_OBJECT_DATA + }] + } + )); + }, TEST_CASE_TIMEOUT); }); describe('Logging an error object', () => { - it('should log additional keys and value only once', async () => { + it('should log error only once', async () => { const logMessages = invocationLogs[0].getFunctionLogs(LEVEL.ERROR) .filter(message => message.includes(ERROR_MSG)); diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index b22afda18d..a167ef5d1a 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -280,6 +280,14 @@ describe('Class: Logger', () => { }); const consoleSpy = jest.spyOn(logger['console'], methodOfLogger).mockImplementation(); + interface NestedObject { bool: boolean; str: string; num: number; err: Error } + interface ArbitraryObject { value: 'CUSTOM' | 'USER_DEFINED'; nested: TNested } + + const arbitraryObject: ArbitraryObject = { + value: 'CUSTOM', + nested: { bool: true, str: 'string value', num: 42, err: new Error('Arbitrary object error') } + }; + // Act if (logger[methodOfLogger]) { logger[methodOfLogger]('A log item without extra parameters'); @@ -289,6 +297,8 @@ describe('Class: Logger', () => { logger[methodOfLogger]('A log item with a string as first parameter, and an error as second parameter', new Error('Something happened!')); logger[methodOfLogger]('A log item with a string as first parameter, and an error with custom key as second parameter', { myCustomErrorKey: new Error('Something happened!') }); logger[methodOfLogger]('A log item with a string as first parameter, and a string as second parameter', 'parameter'); + logger[methodOfLogger]('A log item with a string as first parameter, and an inline object as second parameter', { extra: { custom: mockDate } }); + logger[methodOfLogger]('A log item with a string as first parameter, and an arbitrary object as second parameter', { extra: arbitraryObject }); } // Assess @@ -360,6 +370,36 @@ describe('Class: Logger', () => { xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', extra: 'parameter', })); + expect(consoleSpy).toHaveBeenNthCalledWith(8, JSON.stringify({ + level: method.toUpperCase(), + message: 'A log item with a string as first parameter, and an inline object as second parameter', + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + extra: { custom: '2016-06-20T12:08:10.000Z' } + })); + const parameterCallNumber9 = JSON.parse(consoleSpy.mock.calls[8][0]); + expect(parameterCallNumber9).toEqual(expect.objectContaining({ + level: method.toUpperCase(), + message: 'A log item with a string as first parameter, and an arbitrary object as second parameter', + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + extra: { + value: 'CUSTOM', + nested: { + bool: true, + str: 'string value', + num: 42, + err: { + location: expect.stringMatching(/Logger.test.ts:[0-9]+$/), + message: 'Arbitrary object error', + name: 'Error', + stack: expect.stringMatching(/Logger.test.ts:[0-9]+:[0-9]+/), + } + } + } + })); }); });