diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index b8736c1dad..739e0fdadb 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -126,23 +126,31 @@ class Logger extends Utility implements LoggerInterface { * @private */ private console!: Console; - + /** + * Custom config service instance used to configure the logger. + */ private customConfigService?: ConfigServiceInterface; - - // envVarsService is always initialized in the constructor in setOptions() - private envVarsService!: EnvironmentVariablesService; - + /** + * Environment variables service instance used to fetch environment variables. + */ + private envVarsService = new EnvironmentVariablesService(); + /** + * Whether to print the Lambda invocation event in the logs. + */ private logEvent = false; - + /** + * Formatter used to format the log items. + * @default new PowertoolsLogFormatter() + */ private logFormatter?: LogFormatterInterface; - + /** + * JSON indentation used to format the logs. + */ private logIndentation: number = LogJsonIndent.COMPACT; - /** * Log level used internally by the current instance of Logger. */ private logLevel = 12; - /** * Log level thresholds used internally by the current instance of Logger. * @@ -156,10 +164,25 @@ class Logger extends Utility implements LoggerInterface { CRITICAL: 24, SILENT: 28, }; - + /** + * Persistent log attributes that will be logged in all log items. + */ private persistentLogAttributes: LogAttributes = {}; - + /** + * Standard attributes managed by Powertools that will be logged in all log items. + */ private powertoolsLogData: PowertoolsLogData = {}; + /** + * Buffer used to store logs until the logger is initialized. + * + * Sometimes we need to log warnings before the logger is fully initialized, however we can't log them + * immediately because the logger is not ready yet. This buffer stores those logs until the logger is ready. + */ + #buffer: [number, Parameters][] = []; + /** + * Flag used to determine if the logger is initialized. + */ + #isInitialized = false; /** * Log level used by the current instance of Logger. @@ -178,7 +201,16 @@ class Logger extends Utility implements LoggerInterface { */ public constructor(options: ConstructorOptions = {}) { super(); - this.setOptions(options); + const { customConfigService, ...rest } = options; + this.setCustomConfigService(customConfigService); + // all logs are buffered until the logger is initialized + this.setOptions(rest); + this.#isInitialized = true; + for (const [level, log] of this.#buffer) { + // we call the method directly and create the log item just in time + this.printLog(level, this.createAndPopulateLogItem(...log)); + } + this.#buffer = []; } /** @@ -596,41 +628,49 @@ class Logger extends Utility implements LoggerInterface { } /** - * It processes a particular log item so that it can be printed to stdout: - * - Merges ephemeral log attributes with persistent log attributes (printed for all logs) and additional info; - * - Formats all the log attributes; + * Create a log item and populate it with the given log level, input, and extra input. * - * @private - * @param {number} logLevel - * @param {LogItemMessage} input - * @param {LogItemExtraInput} extraInput - * @returns {LogItem} + * We start with creating an object with base attributes managed by Powertools. + * Then we create a second object with persistent attributes provided by customers either + * directly to the log entry or through initial configuration and `appendKeys` method. + * + * Once we have the two objects, we pass them to the formatter that will apply the desired + * formatting to the log item. + * + * @param logLevel The log level of the log item to be printed + * @param input The main input of the log item, this can be a string or an object with additional attributes + * @param extraInput Additional attributes to be added to the log item */ private createAndPopulateLogItem( logLevel: number, input: LogItemMessage, extraInput: LogItemExtraInput ): LogItem { - // TODO: this method's logic is hard to understand, there is an opportunity here to simplify this logic. - const unformattedBaseAttributes = merge( - { - logLevel: this.getLogLevelNameFromNumber(logLevel), - timestamp: new Date(), - message: typeof input === 'string' ? input : input.message, - xRayTraceId: this.envVarsService.getXrayTraceId(), - }, - this.getPowertoolsLogData() - ); - - let additionalLogAttributes: LogAttributes = {}; - additionalLogAttributes = merge( - additionalLogAttributes, - this.getPersistentLogAttributes() - ); - if (typeof input !== 'string') { - additionalLogAttributes = merge(additionalLogAttributes, input); + let message = ''; + let otherInput: { [key: string]: unknown } = {}; + if (typeof input === 'string') { + message = input; + } else { + const { message: inputMessage, ...rest } = input; + message = inputMessage; + otherInput = rest; } - extraInput.forEach((item: Error | LogAttributes | string) => { + + // create base attributes + const unformattedBaseAttributes = { + logLevel: this.getLogLevelNameFromNumber(logLevel), + timestamp: new Date(), + message, + xRayTraceId: this.envVarsService.getXrayTraceId(), + ...this.getPowertoolsLogData(), + }; + + // gradually merge additional attributes starting from customer-provided persistent attributes + let additionalLogAttributes = { ...this.getPersistentLogAttributes() }; + // if the main input is not a string, then it's an object with additional attributes, so we merge it + additionalLogAttributes = merge(additionalLogAttributes, otherInput); + // then we merge the extra input attributes (if any) + for (const item of extraInput) { const attributes: LogAttributes = item instanceof Error ? { error: item } @@ -639,14 +679,12 @@ class Logger extends Utility implements LoggerInterface { : item; additionalLogAttributes = merge(additionalLogAttributes, attributes); - }); + } - const logItem = this.getLogFormatter().formatAttributes( + return this.getLogFormatter().formatAttributes( unformattedBaseAttributes, additionalLogAttributes ); - - return logItem; } /** @@ -816,10 +854,14 @@ class Logger extends Utility implements LoggerInterface { extraInput: LogItemExtraInput ): void { if (logLevel >= this.logLevel) { - this.printLog( - logLevel, - this.createAndPopulateLogItem(logLevel, input, extraInput) - ); + if (this.#isInitialized) { + this.printLog( + logLevel, + this.createAndPopulateLogItem(logLevel, input, extraInput) + ); + } else { + this.#buffer.push([logLevel, [logLevel, input, extraInput]]); + } } } @@ -857,17 +899,6 @@ class Logger extends Utility implements LoggerInterface { : undefined; } - /** - * Sets the Logger's custom config service instance, which will be used - * to fetch environment variables. - * - * @private - * @returns {void} - */ - private setEnvVarsService(): void { - this.envVarsService = new EnvironmentVariablesService(); - } - /** * Sets the initial Logger log level based on the following order: * 1. If a log level is set using AWS Lambda Advanced Logging Controls, it sets it. @@ -965,7 +996,7 @@ class Logger extends Utility implements LoggerInterface { } /** - * If the `POWERTOOLS_DEV' env variable is set, + * If the `POWERTOOLS_DEV` env variable is set, * it adds JSON indentation for pretty printing logs. * * @private @@ -982,31 +1013,33 @@ class Logger extends Utility implements LoggerInterface { * and the content of all logs. * * @private - * @param {ConstructorOptions} options - * @returns {Logger} + * @param options Options to configure the Logger instance */ - private setOptions(options: ConstructorOptions): Logger { + private setOptions( + options: Omit + ): this { const { logLevel, serviceName, sampleRateValue, logFormatter, - customConfigService, persistentLogAttributes, environment, } = options; - // order is important, EnvVarsService() is used by other methods - this.setEnvVarsService(); - this.setConsole(); - this.setCustomConfigService(customConfigService); - this.setInitialLogLevel(logLevel); - this.setLogFormatter(logFormatter); + // configurations that affect log content this.setPowertoolsLogData(serviceName, environment); - this.setInitialSampleRate(sampleRateValue); + this.addPersistentLogAttributes(persistentLogAttributes); + + // configurations that affect Logger behavior this.setLogEvent(); + this.setInitialLogLevel(logLevel); + this.setInitialSampleRate(sampleRateValue); + + // configurations that affect how logs are printed + this.setLogFormatter(logFormatter); + this.setConsole(); this.setLogIndentation(); - this.addPersistentLogAttributes(persistentLogAttributes); return this; } diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index b5f8ae462a..0d79edd22a 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -802,89 +802,30 @@ describe('Class: Logger', () => { }); describe('Feature: ephemeral log attributes', () => { - test('when added, they should appear in that log item only', () => { - // Prepare - const logger = new Logger({ - logLevel: 'DEBUG', - }); - const consoleSpy = jest.spyOn( - logger['console'], - getConsoleMethod(methodOfLogger) - ); - 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'); - logger[methodOfLogger]( - 'A log item with a string as first parameter, and an object as second parameter', - { extra: 'parameter' } - ); - logger[methodOfLogger]( - 'A log item with a string as first parameter, and objects as other parameters', - { parameterOne: 'foo' }, - { parameterTwo: 'bar' } - ); - logger[methodOfLogger]({ - message: 'A log item with an object as first parameters', - extra: 'parameter', - }); - 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 } - ); - } + const logger = new Logger({ + logLevel: 'DEBUG', + }); - // Assess - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ + it.each([ + { + idx: 0, + inputs: ['A log item without extra parameters'], + expected: { level: method.toUpperCase(), message: 'A log item without extra parameters', sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }) - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - 2, - JSON.stringify({ + }, + }, + { + idx: 1, + inputs: [ + 'A log item with a string as first parameter, and an object as second parameter', + { extra: 'parameter' }, + ], + expected: { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an object as second parameter', @@ -893,11 +834,16 @@ describe('Class: Logger', () => { timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', extra: 'parameter', - }) - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - 3, - JSON.stringify({ + }, + }, + { + idx: 2, + inputs: [ + 'A log item with a string as first parameter, and objects as other parameters', + { parameterOne: 'foo' }, + { parameterTwo: 'bar' }, + ], + expected: { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and objects as other parameters', @@ -907,11 +853,17 @@ describe('Class: Logger', () => { xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', parameterOne: 'foo', parameterTwo: 'bar', - }) - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - 4, - JSON.stringify({ + }, + }, + { + idx: 3, + inputs: [ + { + message: 'A log item with an object as first parameters', + extra: 'parameter', + }, + ], + expected: { level: method.toUpperCase(), message: 'A log item with an object as first parameters', sampling_rate: 0, @@ -919,11 +871,15 @@ describe('Class: Logger', () => { timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', extra: 'parameter', - }) - ); - const parameterCallNumber5 = JSON.parse(consoleSpy.mock.calls[4][0]); - expect(parameterCallNumber5).toEqual( - expect.objectContaining({ + }, + }, + { + idx: 4, + inputs: [ + 'A log item with a string as first parameter, and an error as second parameter', + new Error('Something happened!'), + ], + expected: { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an error as second parameter', @@ -932,18 +888,20 @@ describe('Class: Logger', () => { timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', error: { - location: expect.stringMatching(/Logger.test.ts:[0-9]+$/), + location: expect.any(String), message: 'Something happened!', name: 'Error', - stack: expect.stringMatching(/Logger.test.ts:[0-9]+:[0-9]+/), + stack: expect.any(String), }, - }) - ); - const parameterCallNumber6 = JSON.parse( - consoleSpy.mock.calls[5][0] as string - ); - expect(parameterCallNumber6).toEqual( - expect.objectContaining({ + }, + }, + { + idx: 5, + inputs: [ + 'A log item with a string as first parameter, and an error with custom key as second parameter', + { myCustomErrorKey: new Error('Something happened!') }, + ], + expected: { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an error with custom key as second parameter', @@ -952,16 +910,20 @@ describe('Class: Logger', () => { timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', myCustomErrorKey: { - location: expect.stringMatching(/Logger.test.ts:[0-9]+$/), + location: expect.any(String), message: 'Something happened!', name: 'Error', - stack: expect.stringMatching(/Logger.test.ts:[0-9]+:[0-9]+/), + stack: expect.any(String), }, - }) - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - 7, - JSON.stringify({ + }, + }, + { + idx: 6, + inputs: [ + 'A log item with a string as first parameter, and a string as second parameter', + 'parameter', + ], + expected: { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and a string as second parameter', @@ -970,11 +932,15 @@ describe('Class: Logger', () => { timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', extra: 'parameter', - }) - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - 8, - JSON.stringify({ + }, + }, + { + idx: 7, + inputs: [ + 'A log item with a string as first parameter, and an inline object as second parameter', + { extra: { custom: mockDate } }, + ], + expected: { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an inline object as second parameter', @@ -983,11 +949,25 @@ describe('Class: Logger', () => { 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({ + }, + }, + { + idx: 8, + inputs: [ + 'A log item with a string as first parameter, and an arbitrary object as second parameter', + { + extra: { + value: 'CUSTOM', + nested: { + bool: true, + str: 'string value', + num: 42, + err: new Error('Arbitrary object error'), + }, + }, + }, + ], + expected: { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an arbitrary object as second parameter', @@ -1002,18 +982,33 @@ describe('Class: Logger', () => { str: 'string value', num: 42, err: { - location: expect.stringMatching(/Logger.test.ts:[0-9]+$/), + location: expect.any(String), message: 'Arbitrary object error', name: 'Error', - stack: expect.stringMatching( - /Logger.test.ts:[0-9]+:[0-9]+/ - ), + stack: expect.any(String), }, }, }, - }) - ); - }); + }, + }, + ])( + 'when added, they should appear in that log item only', + ({ idx, inputs, expected }) => { + // Prepare + const consoleSpy = jest.spyOn( + logger['console'], + getConsoleMethod(methodOfLogger) + ); + + // Act + // @ts-expect-error - we are testing the method dynamically + logger[methodOfLogger](...inputs); + + // Assess + const received = JSON.parse(consoleSpy.mock.calls[idx][0]); + expect(received).toEqual(expect.objectContaining(expected)); + } + ); }); describe('Feature: persistent log attributes', () => { @@ -2554,6 +2549,29 @@ describe('Class: Logger', () => { 'Current log level (WARN) does not match AWS Lambda Advanced Logging Controls minimum log level (ERROR). This can lead to data loss, consider adjusting them.' ); }); + + it('uses log level set by ALC & emits a warning when initializing with a higher log level than ALC', () => { + // Prepare + process.env.AWS_LAMBDA_LOG_LEVEL = 'INFO'; + process.env.LOG_LEVEL = undefined; + process.env.POWERTOOLS_LOG_LEVEL = undefined; + // Since the buffer is private and we are bypassing the public warn method, we need to spy on the console.warn + process.env.POWERTOOLS_DEV = 'true'; + const warningSpy = jest.spyOn(console, 'warn').mockImplementation(); + + // Act + const logger = new Logger({ logLevel: 'DEBUG' }); + + // Assess + expect(logger.level).toBe(12); + expect(logger.getLevelName()).toBe('INFO'); + expect(warningSpy).toHaveBeenCalledTimes(1); + expect(warningSpy).toHaveBeenCalledWith( + expect.stringContaining( + 'Current log level (DEBUG) does not match AWS Lambda Advanced Logging Controls minimum log level (INFO). This can lead to data loss, consider adjusting them.' + ) + ); + }); }); describe('Feature: Sampling debug logs', () => { @@ -2830,6 +2848,24 @@ describe('Class: Logger', () => { ); }); + it('logs a DEBUG log when the sample rate sets the level to DEBUG', () => { + // Prepare + // Since the buffer is private and we are bypassing the public warn method, we need to spy on the console.warn + process.env.POWERTOOLS_DEV = 'true'; + const debugSpy = jest.spyOn(console, 'debug').mockImplementation(); + + // Act + new Logger({ sampleRateValue: 1 }); + + // Assess + expect(debugSpy).toHaveBeenCalledTimes(1); + expect(debugSpy).toHaveBeenCalledWith( + expect.stringContaining( + 'Setting log level to DEBUG due to sampling rate' + ) + ); + }); + describe('Method: refreshSampleRateCalculation', () => { test('when sample rate calculation is refreshed, it DOES NOT overwrite the sample rate value', () => { // Prepare