From 90db1ea6983fc6aeca329804b39082c37b39833e Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev Date: Fri, 13 Oct 2023 16:21:51 -0500 Subject: [PATCH 01/11] test(logger): remove logsSampled field, add default sampleRateValue --- packages/logger/tests/unit/Logger.test.ts | 138 +++++++++--------- .../tests/unit/middleware/middy.test.ts | 10 +- 2 files changed, 78 insertions(+), 70 deletions(-) diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index f1a5474de0..830ac3c18b 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', @@ -724,6 +717,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 +758,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 +843,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 +855,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 +868,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 +881,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 +894,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 +914,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 +932,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 +945,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 +958,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 +1009,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 +1042,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 +1072,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 +1114,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 +1160,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 +1193,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 +1227,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', @@ -1231,7 +1240,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 +1503,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 +1541,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 +1558,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 +1600,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 +1617,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 +1753,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 +1803,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 +1864,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', @@ -1961,26 +1978,24 @@ 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); - }); + // 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', () => { @@ -2018,12 +2033,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 +2055,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: true, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', @@ -2064,7 +2077,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: true, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', @@ -2130,12 +2142,11 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -2153,7 +2164,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 +2171,7 @@ describe('Class: Logger', () => { powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -2179,7 +2189,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: true, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', @@ -2202,12 +2211,11 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -2246,12 +2254,11 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -2269,7 +2276,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: { aws_account_id: '123456789012', aws_region: 'eu-west-1', @@ -2281,7 +2287,7 @@ describe('Class: Logger', () => { powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -2299,7 +2305,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: { aws_account_id: '123456789012', aws_region: 'eu-west-1', @@ -2312,7 +2317,7 @@ describe('Class: Logger', () => { powertoolLogData: { awsRegion: 'eu-west-1', environment: '', - sampleRateValue: undefined, + sampleRateValue: 0, serviceName: 'hello-world', }, }); @@ -2340,7 +2345,6 @@ describe('Class: Logger', () => { logLevelThresholds: { ...logLevelThresholds, }, - logsSampled: false, persistentLogAttributes: {}, powertoolLogData: { awsRegion: 'eu-west-1', @@ -2354,7 +2358,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 +2414,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 +2432,6 @@ describe('Class: Logger', () => { expect(childLogger).toEqual({ ...parentLogger, console: expect.any(Console), - logsSampled: expect.any(Boolean), }); expect(childLogger).toEqual( @@ -2480,6 +2483,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 +2516,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 +2544,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', 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', From 8b44ac7db9a96b3ec3d69a17f6f950a5298013a8 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev Date: Fri, 13 Oct 2023 17:04:43 -0500 Subject: [PATCH 02/11] test(logger): add tests for sampling debug logs feature --- packages/logger/tests/unit/Logger.test.ts | 143 ++++++++++++++++++---- 1 file changed, 122 insertions(+), 21 deletions(-) diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index 830ac3c18b..f57d5deca5 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -1977,27 +1977,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 @@ -2597,4 +2576,126 @@ describe('Class: Logger', () => { ); }); }); + + /** + * TODO: test sample rate value priority for constructor/custom config/env var + */ + describe('Feature: Sampling debug logs', () => { + test('when sampling 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 sampling 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 value 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 value is set in custom config service, sampling_rate should be set and logLevel should be changed to DEBUG', () => { + // 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(logger.level).toBe(8); + expect(logger.getLevelName()).toBe('DEBUG'); + 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 POWERTOOLS_LOGGER_SAMPLE_RATE env variable is set, sampling_rate should be set and logLevel should be changed to DEBUG', () => { + // 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(logger.level).toBe(8); + expect(logger.getLevelName()).toBe('DEBUG'); + 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', + }) + ); + }); + }); }); From 38d0f2a2a7f29977bd16703af358b432753948fd Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev Date: Fri, 13 Oct 2023 17:14:22 -0500 Subject: [PATCH 03/11] feat(logger): change implementation to make sampling decision at per-function level --- packages/logger/src/Logger.ts | 154 ++++++++---------- .../src/config/EnvironmentVariablesService.ts | 2 +- packages/logger/src/types/Logger.ts | 2 +- 3 files changed, 74 insertions(+), 84 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 3bf7b3caf9..48514001bf 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 = {}; @@ -311,15 +309,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. @@ -458,18 +447,6 @@ class Logger extends Utility implements ClassThatLogs { this.info('Lambda invocation event', { event }); } - /** - * 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). - * - * @returns {void} - */ - public refreshSampleRateCalculation(): void { - this.setLogsSampled(); - } - /** * Alias for removePersistentLogAttributes. * @@ -518,19 +495,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. * @@ -567,27 +531,6 @@ class Logger extends Utility implements ClassThatLogs { 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. * @@ -603,6 +546,17 @@ class Logger extends Utility implements ClassThatLogs { }); } + /** + * It dynamically sets log level based on sampling rate value + */ + private configureSampling(): void { + const sampleRateValue = this.getSampleRateValue(); + if (sampleRateValue && randomInt(0, 100) / 100 <= sampleRateValue) { + this.debug('Setting log level to DEBUG due to sampling rate'); + this.setLogLevel('DEBUG'); + } + } + /** * 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; @@ -761,10 +715,10 @@ class Logger extends Utility implements ClassThatLogs { */ private getSampleRateValue(): number { if (!this.powertoolLogData.sampleRateValue) { - this.setSampleRateValue(); + this.setInitialSampleRate(); } - return this.powertoolLogData.sampleRateValue as number; + return this.powertoolLogData.sampleRateValue; } /** @@ -780,6 +734,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 +791,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 +878,41 @@ 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 { + const constructorValue = sampleRateValue; + if (this.isValidSampleRate(constructorValue)) { + this.powertoolLogData.sampleRateValue = constructorValue; + + return; + } + const customConfigValue = + this.getCustomConfigService()?.getSampleRateValue(); + if (this.isValidSampleRate(customConfigValue)) { + this.powertoolLogData.sampleRateValue = customConfigValue; + + return; + } + const envVarsValue = this.getEnvVarsService().getSampleRateValue(); + if (this.isValidSampleRate(envVarsValue)) { + this.powertoolLogData.sampleRateValue = envVarsValue; + + return; + } + + this.powertoolLogData.sampleRateValue = 0; + } + /** * 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 +951,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,12 +975,12 @@ class Logger extends Utility implements ClassThatLogs { this.setConsole(); this.setCustomConfigService(customConfigService); this.setInitialLogLevel(logLevel); - this.setSampleRateValue(sampleRateValue); - this.setLogsSampled(); + this.setInitialSampleRate(sampleRateValue); this.setLogFormatter(logFormatter); this.setPowertoolLogData(serviceName, environment); this.setLogEvent(); this.setLogIndentation(); + this.configureSampling(); this.addPersistentLogAttributes(persistentLogAttributes); @@ -1017,7 +1008,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; From 11a799595be83d291c6a8188a8f85016fbf29f5c Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev Date: Fri, 13 Oct 2023 17:19:38 -0500 Subject: [PATCH 04/11] refactor(logger): remove redundant createLogger method --- packages/logger/src/Logger.ts | 14 ++------------ 1 file changed, 2 insertions(+), 12 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 48514001bf..bbe42e8090 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -238,7 +238,7 @@ class Logger extends Utility implements ClassThatLogs { logFormatter: this.getLogFormatter(), }; const parentsPowertoolsLogData = this.getPowertoolLogData(); - const childLogger = this.createLogger( + const childLogger = new Logger( merge(parentsOptions, parentsPowertoolsLogData, options) ); @@ -521,16 +521,6 @@ class Logger extends Utility implements ClassThatLogs { this.processLogItem(16, input, extraInput); } - /** - * Creates a new Logger instance. - * - * @param {ConstructorOptions} [options] - * @returns {Logger} - */ - protected createLogger(options?: ConstructorOptions): Logger { - return new Logger(options); - } - /** * It stores information that is printed in all log items. * @@ -893,7 +883,7 @@ class Logger extends Utility implements ClassThatLogs { const constructorValue = sampleRateValue; if (this.isValidSampleRate(constructorValue)) { this.powertoolLogData.sampleRateValue = constructorValue; - + return; } const customConfigValue = From 62f4063621596780cbb2842a123b58cac9ae1db0 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev Date: Fri, 13 Oct 2023 17:32:15 -0500 Subject: [PATCH 05/11] refactor(logger): remove getSampleRateValue method --- packages/logger/src/Logger.ts | 16 +--------------- 1 file changed, 1 insertion(+), 15 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index bbe42e8090..29c34b049e 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -540,7 +540,7 @@ class Logger extends Utility implements ClassThatLogs { * It dynamically sets log level based on sampling rate value */ private configureSampling(): void { - const sampleRateValue = this.getSampleRateValue(); + const sampleRateValue = this.powertoolLogData.sampleRateValue; if (sampleRateValue && randomInt(0, 100) / 100 <= sampleRateValue) { this.debug('Setting log level to DEBUG due to sampling rate'); this.setLogLevel('DEBUG'); @@ -697,20 +697,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.setInitialSampleRate(); - } - - return this.powertoolLogData.sampleRateValue; - } - /** * It returns true and type guards the log level if a given log level is valid. * From 8f57cf3fd2524083919370175eb73aab2b09eb07 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev Date: Fri, 13 Oct 2023 17:51:37 -0500 Subject: [PATCH 06/11] test(logger): improve tests --- packages/logger/tests/unit/Logger.test.ts | 8 ++++++-- 1 file changed, 6 insertions(+), 2 deletions(-) diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index f57d5deca5..e234f095c2 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -642,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({ @@ -659,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', @@ -678,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, From 6e993a595bc91c9f5def30f70adab017e2b107f8 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev Date: Sun, 15 Oct 2023 12:51:08 -0500 Subject: [PATCH 07/11] refactor(logger): return createLogger() back with the detailed comment of the method importance --- packages/logger/src/Logger.ts | 30 +++++++++++++++++++++++++++++- 1 file changed, 29 insertions(+), 1 deletion(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 29c34b049e..e7fa40d098 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -238,7 +238,7 @@ class Logger extends Utility implements ClassThatLogs { logFormatter: this.getLogFormatter(), }; const parentsPowertoolsLogData = this.getPowertoolLogData(); - const childLogger = new Logger( + const childLogger = this.createLogger( merge(parentsOptions, parentsPowertoolsLogData, options) ); @@ -521,6 +521,34 @@ class Logger extends Utility implements ClassThatLogs { this.processLogItem(16, input, extraInput); } + /** + * 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. + * + * **Please do not remove this method during refactoring!** + * + * @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); + } + /** * It stores information that is printed in all log items. * From 54cf7ea7214c006c88a3259493afca6a2681da6c Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev Date: Sun, 15 Oct 2023 13:50:29 -0500 Subject: [PATCH 08/11] test(logger): add constructor/custom config/env var priority tests for sampling rate feature, improve description --- packages/logger/tests/unit/Logger.test.ts | 206 +++++++++++++++++++--- 1 file changed, 186 insertions(+), 20 deletions(-) diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index e234f095c2..510f4757ad 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -2581,12 +2581,9 @@ describe('Class: Logger', () => { }); }); - /** - * TODO: test sample rate value priority for constructor/custom config/env var - */ describe('Feature: Sampling debug logs', () => { - test('when sampling rate is set in constructor it DOES change log level to DEBUG', () => { - // Prepare && Act + 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, @@ -2597,8 +2594,42 @@ describe('Class: Logger', () => { expect(logger.getLevelName()).toBe('DEBUG'); }); - test('when sampling rate is disabled it DOES NOT changes log level to DEBUG', () => { - // Prepare && Act + 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, @@ -2609,12 +2640,22 @@ describe('Class: Logger', () => { expect(logger.getLevelName()).toBe('ERROR'); }); - test('when sample rate value in constructor is out of expected range, it should be ignored', () => { + test('when sample rate is set in constructor, custom config, and environmental variable, it should prioritize constructor value', () => { // Prepare - const logger: Logger = new Logger({ - logLevel: 'INFO', - sampleRateValue: 42, - }); + 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(); @@ -2629,7 +2670,7 @@ describe('Class: Logger', () => { JSON.stringify({ level: 'INFO', message: 'foo', - sampling_rate: 0, + sampling_rate: 1, service: 'hello-world', timestamp: '2016-06-20T12:08:10.000Z', xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', @@ -2637,8 +2678,10 @@ describe('Class: Logger', () => { ); }); - test('when sample rate value is set in custom config service, sampling_rate should be set and logLevel should be changed to DEBUG', () => { + 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 { @@ -2648,8 +2691,8 @@ describe('Class: Logger', () => { const loggerOptions: ConstructorOptions = { customConfigService: new MyCustomEnvironmentVariablesService(), }; - const logger: Logger = new Logger(loggerOptions); + const consoleSpy = jest .spyOn(logger['console'], 'info') .mockImplementation(); @@ -2658,8 +2701,6 @@ describe('Class: Logger', () => { logger.info('foo'); // Assess - expect(logger.level).toBe(8); - expect(logger.getLevelName()).toBe('DEBUG'); expect(consoleSpy).toBeCalledTimes(1); expect(consoleSpy).toHaveBeenNthCalledWith( 1, @@ -2674,7 +2715,7 @@ describe('Class: Logger', () => { ); }); - test('when POWERTOOLS_LOGGER_SAMPLE_RATE env variable is set, sampling_rate should be set and logLevel should be changed to DEBUG', () => { + 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(); @@ -2686,8 +2727,6 @@ describe('Class: Logger', () => { logger.debug('foo'); // Assess - expect(logger.level).toBe(8); - expect(logger.getLevelName()).toBe('DEBUG'); expect(consoleSpy).toBeCalledTimes(1); expect(consoleSpy).toHaveBeenNthCalledWith( 1, @@ -2701,5 +2740,132 @@ describe('Class: Logger', () => { }) ); }); + + 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', + }) + ); + }); }); }); From a1c5e63501880aee98e40345a921b36bf12b9001 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev Date: Thu, 19 Oct 2023 14:40:29 -0500 Subject: [PATCH 09/11] refactor(logger): address review comments --- packages/logger/src/Logger.ts | 43 +++++++++++------------------------ 1 file changed, 13 insertions(+), 30 deletions(-) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index e7fa40d098..3952a06194 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -236,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( @@ -526,8 +527,6 @@ class Logger extends Utility implements ClassThatLogs { * Important for customization and subclassing. It allows subclasses, like `MyOwnLogger`, * to override its behavior while keeping the main business logic in `createChild` intact. * - * **Please do not remove this method during refactoring!** - * * @example * ```typescript * // MyOwnLogger subclass @@ -564,17 +563,6 @@ class Logger extends Utility implements ClassThatLogs { }); } - /** - * It dynamically sets log level based on sampling rate value - */ - private configureSampling(): void { - const sampleRateValue = this.powertoolLogData.sampleRateValue; - if (sampleRateValue && randomInt(0, 100) / 100 <= sampleRateValue) { - this.debug('Setting log level to DEBUG due to sampling rate'); - this.setLogLevel('DEBUG'); - } - } - /** * 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; @@ -894,27 +882,23 @@ class Logger extends Utility implements ClassThatLogs { * @returns {void} */ private setInitialSampleRate(sampleRateValue?: number): void { + this.powertoolLogData.sampleRateValue = 0; const constructorValue = sampleRateValue; - if (this.isValidSampleRate(constructorValue)) { - this.powertoolLogData.sampleRateValue = constructorValue; - - return; - } const customConfigValue = this.getCustomConfigService()?.getSampleRateValue(); - if (this.isValidSampleRate(customConfigValue)) { - this.powertoolLogData.sampleRateValue = customConfigValue; - - return; - } const envVarsValue = this.getEnvVarsService().getSampleRateValue(); - if (this.isValidSampleRate(envVarsValue)) { - this.powertoolLogData.sampleRateValue = envVarsValue; + for (const value of [constructorValue, customConfigValue, envVarsValue]) { + if (this.isValidSampleRate(value)) { + this.powertoolLogData.sampleRateValue = value; - return; - } + if (value && randomInt(0, 100) / 100 <= value) { + this.setLogLevel('DEBUG'); + this.debug('Setting log level to DEBUG due to sampling rate'); + } - this.powertoolLogData.sampleRateValue = 0; + return; + } + } } /** @@ -979,12 +963,11 @@ class Logger extends Utility implements ClassThatLogs { this.setConsole(); this.setCustomConfigService(customConfigService); this.setInitialLogLevel(logLevel); - this.setInitialSampleRate(sampleRateValue); this.setLogFormatter(logFormatter); this.setPowertoolLogData(serviceName, environment); + this.setInitialSampleRate(sampleRateValue); this.setLogEvent(); this.setLogIndentation(); - this.configureSampling(); this.addPersistentLogAttributes(persistentLogAttributes); From 1bf5bcd15af6a603225288bab475be00b4b08fb9 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev Date: Thu, 19 Oct 2023 16:19:17 -0500 Subject: [PATCH 10/11] feat(logger): add refreshSampleRateCalculation method and tests --- packages/logger/src/Logger.ts | 11 +++++ packages/logger/tests/unit/Logger.test.ts | 60 +++++++++++++++++++++++ 2 files changed, 71 insertions(+) diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index 3952a06194..1016a1a98a 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -448,6 +448,17 @@ class Logger extends Utility implements ClassThatLogs { this.info('Lambda invocation event', { event }); } + /** + * 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.setInitialSampleRate(this.powertoolLogData.sampleRateValue); + } + /** * Alias for removePersistentLogAttributes. * diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index 510f4757ad..c3ecc4729f 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -2867,5 +2867,65 @@ describe('Class: Logger', () => { }) ); }); + + 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); + }); + }); }); }); From 09878fbbc4e0e17f44355d5c971ee27844261271 Mon Sep 17 00:00:00 2001 From: Sergei Cherniaev Date: Thu, 19 Oct 2023 16:44:52 -0500 Subject: [PATCH 11/11] test(logger): adjust end-to-end tests --- .../tests/e2e/sampleRate.decorator.test.ts | 7 ++- packages/testing/src/TestInvocationLogs.ts | 59 ++++++++++++++++--- 2 files changed, 58 insertions(+), 8 deletions(-) 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/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)); } /**