diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 3bf7b3caf9..1016a1a98a 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -158,8 +158,6 @@ class Logger extends Utility implements ClassThatLogs { SILENT: 28, }; - private logsSampled = false; - private persistentLogAttributes?: LogAttributes = {}; private powertoolLogData: PowertoolLogData = {}; @@ -238,6 +236,7 @@ class Logger extends Utility implements ClassThatLogs { logLevel: this.getLevelName(), customConfigService: this.getCustomConfigService(), logFormatter: this.getLogFormatter(), + sampleRateValue: this.powertoolLogData.sampleRateValue, }; const parentsPowertoolsLogData = this.getPowertoolLogData(); const childLogger = this.createLogger( @@ -311,15 +310,6 @@ class Logger extends Utility implements ClassThatLogs { return this.logEvent; } - /** - * It returns a boolean value, if true all the logs will be printed. - * - * @returns {boolean} - */ - public getLogsSampled(): boolean { - return this.logsSampled; - } - /** * It returns the persistent log attributes, which are the attributes * that will be logged in all log items. @@ -459,15 +449,14 @@ class Logger extends Utility implements ClassThatLogs { } /** - * If the sample rate feature is enabled, the calculation that determines whether the logs - * will actually be printed or not for this invocation is done when the Logger class is - * initialized. - * This method will repeat that calculation (with possible different outcome). + * This method allows recalculating the initial sampling decision for changing + * the log level to DEBUG based on a sample rate value used during initialization, + * potentially yielding a different outcome. * * @returns {void} */ public refreshSampleRateCalculation(): void { - this.setLogsSampled(); + this.setInitialSampleRate(this.powertoolLogData.sampleRateValue); } /** @@ -518,19 +507,6 @@ class Logger extends Utility implements ClassThatLogs { this.persistentLogAttributes = attributes; } - /** - * It sets the user-provided sample rate value. - * - * @param {number} [sampleRateValue] - * @returns {void} - */ - public setSampleRateValue(sampleRateValue?: number): void { - this.powertoolLogData.sampleRateValue = - sampleRateValue || - this.getCustomConfigService()?.getSampleRateValue() || - this.getEnvVarsService().getSampleRateValue(); - } - /** * It checks whether the current Lambda invocation event should be printed in the logs or not. * @@ -558,36 +534,31 @@ class Logger extends Utility implements ClassThatLogs { } /** - * Creates a new Logger instance. + * Factory method for instantiating logger instances. Used by `createChild` method. + * Important for customization and subclassing. It allows subclasses, like `MyOwnLogger`, + * to override its behavior while keeping the main business logic in `createChild` intact. * - * @param {ConstructorOptions} [options] - * @returns {Logger} + * @example + * ```typescript + * // MyOwnLogger subclass + * class MyOwnLogger extends Logger { + * protected createLogger(options?: ConstructorOptions): MyOwnLogger { + * return new MyOwnLogger(options); + * } + * // No need to re-implement business logic from `createChild` and keep track on changes + * public createChild(options?: ConstructorOptions): MyOwnLogger { + * return super.createChild(options) as MyOwnLogger; + * } + * } + * ``` + * + * @param {ConstructorOptions} [options] Logger configuration options. + * @returns {Logger} A new logger instance. */ protected createLogger(options?: ConstructorOptions): Logger { return new Logger(options); } - /** - * Decides whether the current log item should be printed or not. - * - * The decision is based on the log level and the sample rate value. - * A log item will be printed if: - * 1. The log level is greater than or equal to the Logger's log level. - * 2. The log level is less than the Logger's log level, but the - * current sampling value is set to `true`. - * - * @param {number} logLevel - * @returns {boolean} - * @protected - */ - protected shouldPrint(logLevel: number): boolean { - if (logLevel >= this.logLevel) { - return true; - } - - return this.getLogsSampled(); - } - /** * It stores information that is printed in all log items. * @@ -753,20 +724,6 @@ class Logger extends Utility implements ClassThatLogs { }; } - /** - * It returns the numeric sample rate value. - * - * @private - * @returns {number} - */ - private getSampleRateValue(): number { - if (!this.powertoolLogData.sampleRateValue) { - this.setSampleRateValue(); - } - - return this.powertoolLogData.sampleRateValue as number; - } - /** * It returns true and type guards the log level if a given log level is valid. * @@ -780,6 +737,23 @@ class Logger extends Utility implements ClassThatLogs { return typeof logLevel === 'string' && logLevel in this.logLevelThresholds; } + /** + * It returns true and type guards the sample rate value if a given value is valid. + * + * @param sampleRateValue + * @private + * @returns {boolean} + */ + private isValidSampleRate( + sampleRateValue?: number + ): sampleRateValue is number { + return ( + typeof sampleRateValue === 'number' && + 0 <= sampleRateValue && + sampleRateValue <= 1 + ); + } + /** * It prints a given log with given log level. * @@ -820,13 +794,12 @@ class Logger extends Utility implements ClassThatLogs { input: LogItemMessage, extraInput: LogItemExtraInput ): void { - if (!this.shouldPrint(logLevel)) { - return; + if (logLevel >= this.logLevel) { + this.printLog( + logLevel, + this.createAndPopulateLogItem(logLevel, input, extraInput) + ); } - this.printLog( - logLevel, - this.createAndPopulateLogItem(logLevel, input, extraInput) - ); } /** @@ -908,6 +881,37 @@ class Logger extends Utility implements ClassThatLogs { } } + /** + * It sets sample rate value with the following prioprity: + * 1. Constructor value + * 2. Custom config service value + * 3. Environment variable value + * 4. Default value (zero) + * + * @private + * @param {number} [sampleRateValue] + * @returns {void} + */ + private setInitialSampleRate(sampleRateValue?: number): void { + this.powertoolLogData.sampleRateValue = 0; + const constructorValue = sampleRateValue; + const customConfigValue = + this.getCustomConfigService()?.getSampleRateValue(); + const envVarsValue = this.getEnvVarsService().getSampleRateValue(); + for (const value of [constructorValue, customConfigValue, envVarsValue]) { + if (this.isValidSampleRate(value)) { + this.powertoolLogData.sampleRateValue = value; + + if (value && randomInt(0, 100) / 100 <= value) { + this.setLogLevel('DEBUG'); + this.debug('Setting log level to DEBUG due to sampling rate'); + } + + return; + } + } + } + /** * If the log event feature is enabled via env variable, it sets a property that tracks whether * the event passed to the Lambda function handler should be logged or not. @@ -946,20 +950,6 @@ class Logger extends Utility implements ClassThatLogs { } } - /** - * If the sample rate feature is enabled, it sets a property that tracks whether this Lambda function invocation - * will print logs or not. - * - * @private - * @returns {void} - */ - private setLogsSampled(): void { - const sampleRateValue = this.getSampleRateValue(); - this.logsSampled = - sampleRateValue !== undefined && - (sampleRateValue === 1 || randomInt(0, 100) / 100 <= sampleRateValue); - } - /** * It configures the Logger instance settings that will affect the Logger's behaviour * and the content of all logs. @@ -984,10 +974,9 @@ class Logger extends Utility implements ClassThatLogs { this.setConsole(); this.setCustomConfigService(customConfigService); this.setInitialLogLevel(logLevel); - this.setSampleRateValue(sampleRateValue); - this.setLogsSampled(); this.setLogFormatter(logFormatter); this.setPowertoolLogData(serviceName, environment); + this.setInitialSampleRate(sampleRateValue); this.setLogEvent(); this.setLogIndentation(); @@ -1017,7 +1006,6 @@ class Logger extends Utility implements ClassThatLogs { environment || this.getCustomConfigService()?.getCurrentEnvironment() || this.getEnvVarsService().getCurrentEnvironment(), - sampleRateValue: this.getSampleRateValue(), serviceName: serviceName || this.getCustomConfigService()?.getServiceName() || diff --git a/packages/logger/src/config/EnvironmentVariablesService.ts b/packages/logger/src/config/EnvironmentVariablesService.ts index 71b0dabab9..a9c0786eb6 100644 --- a/packages/logger/src/config/EnvironmentVariablesService.ts +++ b/packages/logger/src/config/EnvironmentVariablesService.ts @@ -100,7 +100,7 @@ class EnvironmentVariablesService /** * It returns the value of the POWERTOOLS_LOGGER_SAMPLE_RATE environment variable. * - * @returns {string|undefined} + * @returns {number|undefined} */ public getSampleRateValue(): number | undefined { const value = this.get(this.sampleRateValueVariable); diff --git a/packages/logger/src/types/Logger.ts b/packages/logger/src/types/Logger.ts index 193d72daef..c937d66542 100644 --- a/packages/logger/src/types/Logger.ts +++ b/packages/logger/src/types/Logger.ts @@ -47,7 +47,7 @@ type LambdaFunctionContext = { type PowertoolLogData = LogAttributes & { environment?: Environment; serviceName: string; - sampleRateValue?: number; + sampleRateValue: number; lambdaFunctionContext: LambdaFunctionContext; xRayTraceId?: string; awsRegion: string; diff --git a/packages/logger/tests/e2e/sampleRate.decorator.test.ts b/packages/logger/tests/e2e/sampleRate.decorator.test.ts index e87f661a56..dfb60141ab 100644 --- a/packages/logger/tests/e2e/sampleRate.decorator.test.ts +++ b/packages/logger/tests/e2e/sampleRate.decorator.test.ts @@ -81,7 +81,12 @@ describe(`Logger E2E tests, sample rate and injectLambdaContext()`, () => { if (logMessages.length === 1 && logMessages[0].includes('ERROR')) { countNotSampled++; - } else if (logMessages.length === 4) { + } else if ( + logMessages.length === 5 && + logMessages[0].includes( + 'Setting log level to DEBUG due to sampling rate' + ) + ) { countSampled++; } else { console.error(`Log group ${logGroupName} contains missing log`); diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index f1a5474de0..c3ecc4729f 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -59,10 +59,9 @@ describe('Class: Logger', () => { expect(logger).toBeInstanceOf(Logger); expect(logger).toEqual( expect.objectContaining({ - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { - sampleRateValue: undefined, + sampleRateValue: 0, awsRegion: 'eu-west-1', environment: '', serviceName: 'hello-world', @@ -103,12 +102,11 @@ describe('Class: Logger', () => { logEvent: false, logIndentation: 0, logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: 16, + logLevel: 8, // 100% sample rate value changes log level to DEBUG console: expect.any(Console), logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: true, persistentLogAttributes: { awsAccountId: '123456789', }, @@ -145,12 +143,11 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'service_undefined', }, }); @@ -169,10 +166,9 @@ describe('Class: Logger', () => { expect(logger).toBeInstanceOf(Logger); expect(logger).toEqual( expect.objectContaining({ - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { - sampleRateValue: undefined, + sampleRateValue: 0, awsRegion: 'eu-west-1', environment: '', serviceName: 'hello-world', @@ -198,10 +194,9 @@ describe('Class: Logger', () => { expect(logger).toBeInstanceOf(Logger); expect(logger).toEqual( expect.objectContaining({ - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { - sampleRateValue: undefined, + sampleRateValue: 0, awsRegion: 'eu-west-1', environment: '', serviceName: 'my-backend-service', @@ -227,10 +222,9 @@ describe('Class: Logger', () => { expect(logger).toBeInstanceOf(Logger); expect(logger).toEqual( expect.objectContaining({ - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { - sampleRateValue: undefined, + sampleRateValue: 0, awsRegion: 'eu-west-1', environment: '', serviceName: 'hello-world', @@ -256,10 +250,9 @@ describe('Class: Logger', () => { expect(logger).toBeInstanceOf(Logger); expect(logger).toEqual( expect.objectContaining({ - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { - sampleRateValue: undefined, + sampleRateValue: 0, awsRegion: 'eu-west-1', environment: '', serviceName: 'hello-world', @@ -295,12 +288,11 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -319,7 +311,6 @@ describe('Class: Logger', () => { expect(logger).toBeInstanceOf(Logger); expect(logger).toEqual( expect.objectContaining({ - logsSampled: true, persistentLogAttributes: {}, powertoolLogData: { sampleRateValue: 1, @@ -374,10 +365,9 @@ describe('Class: Logger', () => { expect(logger).toBeInstanceOf(Logger); expect(logger).toEqual( expect.objectContaining({ - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { - sampleRateValue: undefined, + sampleRateValue: 0, awsRegion: 'eu-west-1', environment: 'dev', serviceName: 'my-backend-service', @@ -410,7 +400,6 @@ describe('Class: Logger', () => { expect(logger).toBeInstanceOf(Logger); expect(logger).toEqual( expect.objectContaining({ - logsSampled: false, persistentLogAttributes: { aws_account_id: '123456789012', aws_region: 'eu-west-1', @@ -420,7 +409,7 @@ describe('Class: Logger', () => { }, }, powertoolLogData: { - sampleRateValue: undefined, + sampleRateValue: 0, awsRegion: 'eu-west-1', environment: '', serviceName: 'hello-world', @@ -446,10 +435,9 @@ describe('Class: Logger', () => { expect(logger).toBeInstanceOf(Logger); expect(logger).toEqual( expect.objectContaining({ - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { - sampleRateValue: undefined, + sampleRateValue: 0, awsRegion: 'eu-west-1', environment: 'dev', serviceName: 'hello-world', @@ -515,6 +503,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: methodOfLogger.toUpperCase(), message: 'foo', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -543,6 +532,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: methodOfLogger.toUpperCase(), message: 'foo', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -571,6 +561,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: methodOfLogger.toUpperCase(), message: 'foo', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -599,6 +590,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: methodOfLogger.toUpperCase(), message: 'foo', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -641,6 +633,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: methodOfLogger.toUpperCase(), message: 'foo', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -649,7 +642,7 @@ describe('Class: Logger', () => { }); }); - describe('Feature: sample rate', () => { + describe('Feature: sampling debug logs', () => { test('when the log level is higher and the current Lambda invocation IS NOT sampled for logging, it DOES NOT print to stdout', () => { // Prepare const logger = new Logger({ @@ -666,10 +659,12 @@ describe('Class: Logger', () => { } // Assess + expect(logger.level).toBe(28); + expect(logger.getLevelName()).toBe('SILENT'); expect(consoleSpy).toBeCalledTimes(0); }); - test('when the log level is higher and the current Lambda invocation IS sampled for logging, it DOES print to stdout', () => { + test('when the log level is higher and the current Lambda invocation IS sampled for logging, it DOES print to stdout and changes log level to DEBUG', () => { // Prepare const logger = new Logger({ logLevel: 'SILENT', @@ -685,6 +680,8 @@ describe('Class: Logger', () => { } // Assess + expect(logger.level).toBe(8); + expect(logger.getLevelName()).toBe('DEBUG'); expect(consoleSpy).toBeCalledTimes(1); expect(consoleSpy).toHaveBeenNthCalledWith( 1, @@ -724,6 +721,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: method.toUpperCase(), message: 'foo', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -764,6 +762,7 @@ describe('Class: Logger', () => { function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', level: method.toUpperCase(), message: 'foo', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -848,6 +847,7 @@ describe('Class: Logger', () => { JSON.stringify({ 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', @@ -859,6 +859,7 @@ describe('Class: Logger', () => { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an object as second parameter', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -871,6 +872,7 @@ describe('Class: Logger', () => { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and objects as other parameters', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -883,6 +885,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: method.toUpperCase(), message: 'A log item with an object as first parameters', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -895,6 +898,7 @@ describe('Class: Logger', () => { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an error as second parameter', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -914,6 +918,7 @@ describe('Class: Logger', () => { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an error with custom key as second parameter', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -931,6 +936,7 @@ describe('Class: Logger', () => { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and a string as second parameter', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -943,6 +949,7 @@ describe('Class: Logger', () => { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an inline object as second parameter', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -955,6 +962,7 @@ describe('Class: Logger', () => { level: method.toUpperCase(), message: 'A log item with a string as first parameter, and an arbitrary object as second parameter', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -1005,6 +1013,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: method.toUpperCase(), message: 'foo', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -1037,6 +1046,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: method.toUpperCase(), message: 'foo', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -1066,6 +1076,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: method.toUpperCase(), message: 'foo', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', }) @@ -1107,6 +1118,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: method.toUpperCase(), message: 'A log with a circular reference', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -1152,6 +1164,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: methodOfLogger.toUpperCase(), message: message, + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -1184,6 +1197,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: methodOfLogger.toUpperCase(), message: message, + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -1217,7 +1231,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', @@ -1231,7 +1244,7 @@ describe('Class: Logger', () => { 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', memoryLimitInMB: 128, }, - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -1494,6 +1507,7 @@ describe('Class: Logger', () => { function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', level: 'INFO', message: 'This is an INFO log with some context', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -1531,6 +1545,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: 'INFO', message: 'An INFO log without context!', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -1547,6 +1562,7 @@ describe('Class: Logger', () => { function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', level: 'INFO', message: 'This is an INFO log with some context', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -1588,6 +1604,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: 'INFO', message: 'An INFO log without context!', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -1604,6 +1621,7 @@ describe('Class: Logger', () => { function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', level: 'INFO', message: 'This is an INFO log with some context', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -1739,6 +1757,7 @@ describe('Class: Logger', () => { function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', level: 'INFO', message: 'Lambda invocation event', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -1788,6 +1807,7 @@ describe('Class: Logger', () => { function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', level: 'INFO', message: 'Lambda invocation event', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -1848,6 +1868,7 @@ describe('Class: Logger', () => { function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', level: 'INFO', message: 'memberVariable:someValue', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -1960,29 +1981,6 @@ describe('Class: Logger', () => { }); }); - describe('Method: refreshSampleRateCalculation', () => { - test('it recalculates whether the current Lambda invocation logs will be printed or not', () => { - // Prepare - const logger = new Logger({ - logLevel: 'ERROR', - sampleRateValue: 0.1, // 10% probability - }); - let logsSampledCount = 0; - - // Act - for (let i = 0; i < 1000; i++) { - logger.refreshSampleRateCalculation(); - if (logger.getLogsSampled() === true) { - logsSampledCount++; - } - } - - // Assess - expect(logsSampledCount > 50).toBe(true); - expect(logsSampledCount < 150).toBe(true); - }); - }); - describe('Method: createChild', () => { test('child and grandchild loggers should have all the options of its ancestor', () => { // Prepare @@ -2018,12 +2016,11 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'parent-service-name', }, }); @@ -2041,7 +2038,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: true, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', @@ -2064,7 +2060,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: true, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', @@ -2130,12 +2125,11 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -2153,7 +2147,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: { extra: 'This is an attribute that will be logged only by the child logger', @@ -2161,7 +2154,7 @@ describe('Class: Logger', () => { powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -2179,7 +2172,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: true, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', @@ -2202,12 +2194,11 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -2246,12 +2237,11 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -2269,7 +2259,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: { aws_account_id: '123456789012', aws_region: 'eu-west-1', @@ -2281,7 +2270,7 @@ describe('Class: Logger', () => { powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -2299,7 +2288,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: { aws_account_id: '123456789012', aws_region: 'eu-west-1', @@ -2312,7 +2300,7 @@ describe('Class: Logger', () => { powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -2340,7 +2328,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', @@ -2354,7 +2341,7 @@ describe('Class: Logger', () => { 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', memoryLimitInMB: 128, }, - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -2410,7 +2397,7 @@ describe('Class: Logger', () => { const options: ConstructorOptions = { logLevel: 'ERROR', serviceName: 'test-service-name', - sampleRateValue: 0.77, + sampleRateValue: 1, logFormatter: new MyCustomLogFormatter(), customConfigService: new MyCustomEnvironmentVariablesService(), persistentLogAttributes: { @@ -2428,7 +2415,6 @@ describe('Class: Logger', () => { expect(childLogger).toEqual({ ...parentLogger, console: expect.any(Console), - logsSampled: expect.any(Boolean), }); expect(childLogger).toEqual( @@ -2480,6 +2466,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: 'INFO', message: 'Lambda invocation event', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -2512,6 +2499,7 @@ describe('Class: Logger', () => { { level: 'INFO', message: 'Message with pretty identation', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -2539,6 +2527,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: 'INFO', message: 'Message without pretty identation', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -2591,4 +2580,352 @@ describe('Class: Logger', () => { ); }); }); + + describe('Feature: Sampling debug logs', () => { + test('when sample rate is set in constructor, it DOES change log level to DEBUG', () => { + // Prepare & Act + const logger: Logger = new Logger({ + logLevel: 'ERROR', + sampleRateValue: 1, + }); + + // Assess + expect(logger.level).toBe(8); + expect(logger.getLevelName()).toBe('DEBUG'); + }); + + test('when sample rate is set in custom config service, it DOES change log level to DEBUG', () => { + // Prepare & Act + class MyCustomEnvironmentVariablesService extends EnvironmentVariablesService { + private sampleRateValue = 1; + public getSampleRateValue(): number { + return this.sampleRateValue; + } + } + + const loggerOptions: ConstructorOptions = { + logLevel: 'ERROR', + customConfigService: new MyCustomEnvironmentVariablesService(), + }; + + const logger: Logger = new Logger(loggerOptions); + + // Assess + expect(logger.level).toBe(8); + expect(logger.getLevelName()).toBe('DEBUG'); + }); + + test('when sample rate is set in environmental variable, it DOES change log level to DEBUG', () => { + // Prepare & Act + process.env.POWERTOOLS_LOGGER_SAMPLE_RATE = '1'; + + const logger: Logger = new Logger({ + logLevel: 'ERROR', + }); + + // Assess + expect(logger.level).toBe(8); + expect(logger.getLevelName()).toBe('DEBUG'); + }); + + test('when sample rate is disabled it DOES NOT changes log level to DEBUG', () => { + // Prepare & Act + const logger: Logger = new Logger({ + logLevel: 'ERROR', + sampleRateValue: 0, + }); + + // Assess + expect(logger.level).toBe(20); + expect(logger.getLevelName()).toBe('ERROR'); + }); + + test('when sample rate is set in constructor, custom config, and environmental variable, it should prioritize constructor value', () => { + // Prepare + process.env.POWERTOOLS_LOGGER_SAMPLE_RATE = '0.5'; + + class MyCustomEnvironmentVariablesService extends EnvironmentVariablesService { + private sampleRateValue = 0.75; + public getSampleRateValue(): number { + return this.sampleRateValue; + } + } + const loggerOptions: ConstructorOptions = { + sampleRateValue: 1, + customConfigService: new MyCustomEnvironmentVariablesService(), + }; + const logger: Logger = new Logger(loggerOptions); + + const consoleSpy = jest + .spyOn(logger['console'], 'info') + .mockImplementation(); + + // Act + logger.info('foo'); + + // Assess + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith( + 1, + JSON.stringify({ + level: 'INFO', + message: 'foo', + sampling_rate: 1, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + }); + + test('when sample rate is set in custom config and environmental variable, it should prioritize custom config value', () => { + // Prepare + process.env.POWERTOOLS_LOGGER_SAMPLE_RATE = '0.75'; + + class MyCustomEnvironmentVariablesService extends EnvironmentVariablesService { + private sampleRateValue = 1; + public getSampleRateValue(): number { + return this.sampleRateValue; + } + } + const loggerOptions: ConstructorOptions = { + customConfigService: new MyCustomEnvironmentVariablesService(), + }; + const logger: Logger = new Logger(loggerOptions); + + const consoleSpy = jest + .spyOn(logger['console'], 'info') + .mockImplementation(); + + // Act + logger.info('foo'); + + // Assess + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith( + 1, + JSON.stringify({ + level: 'INFO', + message: 'foo', + sampling_rate: 1, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + }); + + test('when sample rate is set in environmental variable, it should use POWERTOOLS_LOGGER_SAMPLE_RATE value', () => { + // Prepare + process.env.POWERTOOLS_LOGGER_SAMPLE_RATE = '1'; + const logger: Logger = new Logger(); + const consoleSpy = jest + .spyOn(logger['console'], 'debug') + .mockImplementation(); + + // Act + logger.debug('foo'); + + // Assess + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith( + 1, + JSON.stringify({ + level: 'DEBUG', + message: 'foo', + sampling_rate: 1, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + }); + + test('when sample rate is set in custom config service, it should use custom config service value', () => { + // Prepare + class MyCustomEnvironmentVariablesService extends EnvironmentVariablesService { + private sampleRateValue = 1; + public getSampleRateValue(): number { + return this.sampleRateValue; + } + } + const loggerOptions: ConstructorOptions = { + customConfigService: new MyCustomEnvironmentVariablesService(), + }; + + const logger: Logger = new Logger(loggerOptions); + const consoleSpy = jest + .spyOn(logger['console'], 'info') + .mockImplementation(); + + // Act + logger.info('foo'); + + // Assess + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith( + 1, + JSON.stringify({ + level: 'INFO', + message: 'foo', + sampling_rate: 1, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + }); + + test('when sample rate in constructor is out of expected range, it should be ignored', () => { + // Prepare + const logger: Logger = new Logger({ + logLevel: 'INFO', + sampleRateValue: 42, + }); + const consoleSpy = jest + .spyOn(logger['console'], 'info') + .mockImplementation(); + + // Act + logger.info('foo'); + + // Assess + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith( + 1, + JSON.stringify({ + level: 'INFO', + message: 'foo', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + }); + + test('when sample rate in custom config service is out of expected range, it should be ignored', () => { + // Prepare + class MyCustomEnvironmentVariablesService extends EnvironmentVariablesService { + private sampleRateValue = 42; + public getSampleRateValue(): number { + return this.sampleRateValue; + } + } + const loggerOptions: ConstructorOptions = { + logLevel: 'INFO', + customConfigService: new MyCustomEnvironmentVariablesService(), + }; + + const logger: Logger = new Logger(loggerOptions); + const consoleSpy = jest + .spyOn(logger['console'], 'info') + .mockImplementation(); + + // Act + logger.info('foo'); + + // Assess + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith( + 1, + JSON.stringify({ + level: 'INFO', + message: 'foo', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + }); + + test('when sample rate in environmental variable is out of expected range, it should be ignored', () => { + // Prepare + process.env.POWERTOOLS_LOGGER_SAMPLE_RATE = '42'; + const logger: Logger = new Logger({ + logLevel: 'INFO', + }); + const consoleSpy = jest + .spyOn(logger['console'], 'info') + .mockImplementation(); + + // Act + logger.info('foo'); + + // Assess + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith( + 1, + JSON.stringify({ + level: 'INFO', + message: 'foo', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + }); + + describe('Method: refreshSampleRateCalculation', () => { + test('when sample rate calculation is refreshed, it DOES NOT overwrite the sample rate value', () => { + // Prepare + const logger = new Logger({ + logLevel: 'INFO', + sampleRateValue: 1, + }); + const consoleSpy = jest + .spyOn(logger['console'], 'info') + .mockImplementation(); + + // Act + logger.refreshSampleRateCalculation(); + logger.info('foo'); + + // Assess + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith( + 1, + JSON.stringify({ + level: 'INFO', + message: 'foo', + sampling_rate: 1, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + }); + + test('when sample rate calculation is refreshed, it respects probability sampling and change log level to DEBUG ', () => { + // Prepare + const logger = new Logger({ + logLevel: 'ERROR', + sampleRateValue: 0.1, // 10% probability + }); + + // suppress "Setting log level to DEBUG due to sampling rate" log messages + jest.spyOn(logger['console'], 'debug').mockImplementation(); + + let logLevelChangedToDebug = 0; + const numOfIterations = 1000; + const minExpected = numOfIterations * 0.05; // Min expected based on 5% probability + const maxExpected = numOfIterations * 0.15; // Max expected based on 15% probability + + // Act + for (let i = 0; i < numOfIterations; i++) { + logger.refreshSampleRateCalculation(); + if (logger.getLevelName() === 'DEBUG') { + logLevelChangedToDebug++; + logger.setLogLevel('ERROR'); + } + } + + // Assess + expect(logLevelChangedToDebug).toBeGreaterThanOrEqual(minExpected); + expect(logLevelChangedToDebug).toBeLessThanOrEqual(maxExpected); + }); + }); + }); }); diff --git a/packages/logger/tests/unit/middleware/middy.test.ts b/packages/logger/tests/unit/middleware/middy.test.ts index cea1597f8e..a37fc5e816 100644 --- a/packages/logger/tests/unit/middleware/middy.test.ts +++ b/packages/logger/tests/unit/middleware/middy.test.ts @@ -52,10 +52,9 @@ describe('Middy middleware', () => { // Assess expect(logger).toEqual( expect.objectContaining({ - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { - sampleRateValue: undefined, + sampleRateValue: 0, awsRegion: 'eu-west-1', environment: '', lambdaContext: { @@ -91,10 +90,9 @@ describe('Middy middleware', () => { // Assess const expectation = expect.objectContaining({ - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { - sampleRateValue: undefined, + sampleRateValue: 0, awsRegion: 'eu-west-1', environment: '', lambdaContext: { @@ -280,6 +278,7 @@ describe('Middy middleware', () => { function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', level: 'INFO', message: 'Lambda invocation event', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -346,6 +345,7 @@ describe('Middy middleware', () => { function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', level: 'INFO', message: 'Lambda invocation event', + sampling_rate: 0, service: 'my-backend-service', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -384,6 +384,7 @@ describe('Middy middleware', () => { function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', level: 'INFO', message: 'Lambda invocation event', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -422,6 +423,7 @@ describe('Middy middleware', () => { function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', level: 'INFO', message: 'This is an INFO log', + sampling_rate: 0, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', diff --git a/packages/testing/src/TestInvocationLogs.ts b/packages/testing/src/TestInvocationLogs.ts index 8c37d73a56..0581e0d927 100644 --- a/packages/testing/src/TestInvocationLogs.ts +++ b/packages/testing/src/TestInvocationLogs.ts @@ -1,6 +1,14 @@ import { LogLevel } from './constants.js'; import type { FunctionLog } from './types.js'; +const CloudWatchLogKeywords = { + END: 'END RequestId', + INIT_START: 'INIT_START', + REPORT: 'REPORT RequestId', + START: 'START RequestId', + XRAY: 'XRAY TraceId', +} as const; + class TestInvocationLogs { public static LEVEL = LogLevel; @@ -51,25 +59,26 @@ class TestInvocationLogs { } /** - * Return the index of the log that contains END RequestId + * Return the index of the log that contains `END RequestId` * @param logs * @returns {number} index of the log that contains END RequestId */ public static getEndLogIndex(logs: string[]): number { - return logs.findIndex((log) => log.startsWith('END RequestId')); + return logs.findIndex((log) => log.startsWith(CloudWatchLogKeywords.END)); } /** - * Return only logs from function, exclude START, END, REPORT, + * Return only logs from function, exclude INIT_START, START, END, REPORT, * and X-Ray log generated by the Lambda service. * * @param {typeof LogLevel} [levelToFilter] - Level to filter the logs * @returns Array of function logs, filtered by level if provided */ public getFunctionLogs(levelToFilter?: keyof typeof LogLevel): string[] { - const startLogIndex = TestInvocationLogs.getStartLogIndex(this.logs); - const endLogIndex = TestInvocationLogs.getEndLogIndex(this.logs); - let filteredLogs = this.logs.slice(startLogIndex + 1, endLogIndex); + const exclusionKeywords = Object.values(CloudWatchLogKeywords); + let filteredLogs = this.logs.filter( + (log) => !exclusionKeywords.some((keyword) => log.startsWith(keyword)) + ); if (levelToFilter) { filteredLogs = filteredLogs.filter((log) => { @@ -89,8 +98,44 @@ class TestInvocationLogs { return filteredLogs; } + /** + * Return the index of the log that contains `INIT_START` + * @param logs + * @returns {number} index of the log that contains `INIT_START` + */ + public static getInitLogIndex(logs: string[]): number { + return logs.findIndex((log) => + log.startsWith(CloudWatchLogKeywords.INIT_START) + ); + } + + /** + * Return the index of the log that contains `REPORT RequestId` + * @param logs + * @returns {number} index of the log that contains `REPORT RequestId` + */ + public static getReportLogIndex(logs: string[]): number { + return logs.findIndex((log) => + log.startsWith(CloudWatchLogKeywords.REPORT) + ); + } + + /** + * Return the index of the log that contains `START RequestId` + * @param logs + * @returns {number} index of the log that contains `START RequestId` + */ public static getStartLogIndex(logs: string[]): number { - return logs.findIndex((log) => log.startsWith('START RequestId')); + return logs.findIndex((log) => log.startsWith(CloudWatchLogKeywords.START)); + } + + /** + * Return the index of the log that contains `XRAY TraceId` + * @param logs + * @returns {number} index of the log that contains `XRAY TraceId` + */ + public static getXRayLogIndex(logs: string[]): number { + return logs.findIndex((log) => log.startsWith(CloudWatchLogKeywords.XRAY)); } /**