diff --git a/packages/logger/jest.config.cjs b/packages/logger/jest.config.cjs index deb2a416a5..0aeadae05f 100644 --- a/packages/logger/jest.config.cjs +++ b/packages/logger/jest.config.cjs @@ -26,5 +26,5 @@ module.exports = { }, }, coverageReporters: ['json-summary', 'text', 'lcov'], - setupFiles: ['/tests/helpers/populateEnvironmentVariables.ts'], + setupFiles: ['/tests/helpers/setupEnv.ts'], }; diff --git a/packages/logger/src/constants.ts b/packages/logger/src/constants.ts index 38db9bf468..9499687c56 100644 --- a/packages/logger/src/constants.ts +++ b/packages/logger/src/constants.ts @@ -24,4 +24,17 @@ const LogLevel = { CRITICAL: 'CRITICAL', } as const; -export { LogJsonIndent, LogLevel }; +/** + * Numeric values for each log level. + */ +const LogLevelThreshold = { + TRACE: 6, + DEBUG: 8, + INFO: 12, + WARN: 16, + ERROR: 20, + CRITICAL: 24, + SILENT: 28, +} as const; + +export { LogJsonIndent, LogLevel, LogLevelThreshold }; diff --git a/packages/logger/src/index.ts b/packages/logger/src/index.ts index c063afb43d..ae100eb930 100644 --- a/packages/logger/src/index.ts +++ b/packages/logger/src/index.ts @@ -1,4 +1,4 @@ export { Logger } from './Logger.js'; export { LogFormatter } from './formatter/LogFormatter.js'; export { LogItem } from './formatter/LogItem.js'; -export { LogLevel } from './constants.js'; +export { LogLevel, LogLevelThreshold } from './constants.js'; diff --git a/packages/logger/tests/helpers/populateEnvironmentVariables.ts b/packages/logger/tests/helpers/populateEnvironmentVariables.ts deleted file mode 100644 index 9c7e47f8cf..0000000000 --- a/packages/logger/tests/helpers/populateEnvironmentVariables.ts +++ /dev/null @@ -1,15 +0,0 @@ -// Reserved variables -process.env._X_AMZN_TRACE_ID = - 'Root=1-5759e988-bd862e3fe1be46a994272793;Parent=557abcec3ee5a047;Sampled=1'; -process.env.AWS_LAMBDA_FUNCTION_NAME = 'my-lambda-function'; -process.env.AWS_LAMBDA_FUNCTION_MEMORY_SIZE = '128'; -if ( - process.env.AWS_REGION === undefined && - process.env.CDK_DEFAULT_REGION === undefined -) { - process.env.AWS_REGION = 'eu-west-1'; -} - -// Powertools for AWS Lambda (TypeScript) variables -process.env.POWERTOOLS_LOG_LEVEL = 'DEBUG'; -process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; diff --git a/packages/logger/tests/helpers/setupEnv.ts b/packages/logger/tests/helpers/setupEnv.ts new file mode 100644 index 0000000000..755d93bf55 --- /dev/null +++ b/packages/logger/tests/helpers/setupEnv.ts @@ -0,0 +1,52 @@ +// Reserved variables +process.env._X_AMZN_TRACE_ID = + 'Root=1-5759e988-bd862e3fe1be46a994272793;Parent=557abcec3ee5a047;Sampled=1'; +process.env.AWS_LAMBDA_FUNCTION_NAME = 'my-lambda-function'; +process.env.AWS_LAMBDA_FUNCTION_MEMORY_SIZE = '128'; +process.env.AWS_LAMBDA_FUNCTION_VERSION = '$LATEST'; +if ( + process.env.AWS_REGION === undefined && + process.env.CDK_DEFAULT_REGION === undefined +) { + process.env.AWS_REGION = 'eu-west-1'; +} + +// Powertools for AWS Lambda (TypeScript) variables +process.env.POWERTOOLS_LOG_LEVEL = 'DEBUG'; +process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; + +jest.spyOn(console, 'error').mockImplementation(); +jest.spyOn(console, 'warn').mockImplementation(); +jest.spyOn(console, 'info').mockImplementation(); +jest.spyOn(console, 'debug').mockImplementation(); +jest.spyOn(console, 'log').mockImplementation(); + +jest.mock('node:console', () => ({ + ...jest.requireActual('node:console'), + Console: jest.fn().mockImplementation(() => ({ + log: jest.fn(), + debug: jest.fn(), + info: jest.fn(), + warn: jest.fn(), + error: jest.fn(), + })), +})); + +declare global { + namespace NodeJS { + interface ProcessEnv { + _X_AMZN_TRACE_ID: string | undefined; + AWS_LAMBDA_FUNCTION_NAME: string | undefined; + AWS_LAMBDA_FUNCTION_MEMORY_SIZE: string | undefined; + AWS_LAMBDA_FUNCTION_VERSION: string | undefined; + AWS_REGION: string | undefined; + CDK_DEFAULT_REGION: string | undefined; + POWERTOOLS_LOG_LEVEL: string | undefined; + POWERTOOLS_SERVICE_NAME: string | undefined; + POWERTOOLS_DEV: string | undefined; + POWERTOOLS_LOGGER_LOG_EVENT: string | undefined; + } + } +} + +export type {}; diff --git a/packages/logger/tests/unit/EnvironmentVariablesService.test.ts b/packages/logger/tests/unit/EnvironmentVariablesService.test.ts deleted file mode 100644 index 1d40af9e9f..0000000000 --- a/packages/logger/tests/unit/EnvironmentVariablesService.test.ts +++ /dev/null @@ -1,221 +0,0 @@ -/** - * Test Logger EnvironmentVariablesService class - * - * @group unit/logger/config - */ -import { EnvironmentVariablesService } from '../../src/config/EnvironmentVariablesService.js'; - -describe('Class: EnvironmentVariablesService', () => { - const ENVIRONMENT_VARIABLES = process.env; - - beforeEach(() => { - jest.resetModules(); - process.env = { ...ENVIRONMENT_VARIABLES }; - }); - - afterAll(() => { - process.env = ENVIRONMENT_VARIABLES; - }); - - describe('Method: getAwsLogLevel', () => { - it('returns the value of the environment variable AWS_LAMBDA_LOG_LEVEL and aliases it as needed', () => { - // Prepare - process.env.AWS_LAMBDA_LOG_LEVEL = 'FATAL'; - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getAwsLogLevel(); - - // Assess - expect(value).toEqual('CRITICAL'); - }); - }); - - describe('Method: getAwsRegion', () => { - test('it returns the value of the environment variable AWS_REGION', () => { - // Prepare - process.env.AWS_REGION = 'us-east-1'; - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getAwsRegion(); - - // Assess - expect(value).toEqual('us-east-1'); - }); - }); - - describe('Method: getCurrentEnvironment', () => { - test('it returns the value of the environment variable AWS_REGION', () => { - // Prepare - process.env.ENVIRONMENT = 'stage'; - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getCurrentEnvironment(); - - // Assess - expect(value).toEqual('stage'); - }); - }); - - describe('Method: getFunctionMemory', () => { - test('it returns the value of the environment variable AWS_LAMBDA_FUNCTION_MEMORY_SIZE', () => { - // Prepare - process.env.AWS_LAMBDA_FUNCTION_MEMORY_SIZE = '123456'; - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getFunctionMemory(); - - // Assess - expect(value).toBe(123456); - }); - }); - - describe('Method: getFunctionName', () => { - test('it returns the value of the environment variable AWS_LAMBDA_FUNCTION_NAME', () => { - // Prepare - process.env.AWS_LAMBDA_FUNCTION_NAME = 'my-lambda-function'; - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getFunctionName(); - - // Assess - expect(value).toEqual('my-lambda-function'); - }); - }); - - describe('Method: getFunctionVersion', () => { - test('it returns the value of the environment variable AWS_LAMBDA_FUNCTION_VERSION', () => { - // Prepare - process.env.AWS_LAMBDA_FUNCTION_VERSION = '1.4.0'; - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getFunctionVersion(); - - // Assess - expect(value).toEqual('1.4.0'); - }); - }); - - describe('Method: getLogEvent', () => { - test('it returns true if the environment variable POWERTOOLS_LOGGER_LOG_EVENT is "true"', () => { - // Prepare - process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'true'; - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getLogEvent(); - - // Assess - expect(value).toEqual(true); - }); - - test('it returns false if the environment variable POWERTOOLS_LOGGER_LOG_EVENT is "false"', () => { - // Prepare - process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'false'; - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getLogEvent(); - - // Assess - expect(value).toEqual(false); - }); - - test('it returns false if the environment variable POWERTOOLS_LOGGER_LOG_EVENT is "somethingsilly"', () => { - // Prepare - process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'somethingsilly'; - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getLogEvent(); - - // Assess - expect(value).toEqual(false); - }); - }); - - describe('Method: getLogLevel', () => { - test('it returns the value of the environment variable LOG_LEVEL when POWERTOOLS_LOG_LEVEL is not set', () => { - // Prepare - process.env.POWERTOOLS_LOG_LEVEL = undefined; - process.env.LOG_LEVEL = 'ERROR'; - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getLogLevel(); - - // Assess - expect(value).toEqual('ERROR'); - }); - - test('it returns the value of the environment variable POWERTOOLS_LOG_LEVEL when LOG_LEVEL one is also set', () => { - // Prepare - process.env.LOG_LEVEL = 'WARN'; - process.env.POWERTOOLS_LOG_LEVEL = 'INFO'; - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getLogLevel(); - - // Assess - expect(value).toEqual('INFO'); - }); - - test('it returns an empty value if neither POWERTOOLS_LOG_LEVEL nor LOG_LEVEL are set', () => { - // Prepare - process.env.LOG_LEVEL = undefined; - process.env.POWERTOOLS_LOG_LEVEL = undefined; - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getLogLevel(); - - // Assess - expect(value).toEqual(''); - }); - }); - - describe('Method: getSampleRateValue', () => { - test('it returns the value of the environment variable POWERTOOLS_LOGGER_SAMPLE_RATE', () => { - // Prepare - process.env.POWERTOOLS_LOGGER_SAMPLE_RATE = '0.01'; - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getSampleRateValue(); - - // Assess - expect(value).toEqual(0.01); - }); - }); - - describe('Method: getTimezone', () => { - it('returns the value of the TZ environment variable when set', () => { - // Prepare - process.env.TZ = 'Europe/London'; - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getTimezone(); - - // Assess - expect(value).toEqual('Europe/London'); - }); - - it('returns the default UTC value when no TZ is set', () => { - // Prepare - const service = new EnvironmentVariablesService(); - - // Act - const value = service.getTimezone(); - - // Assess - expect(value).toEqual('UTC'); - }); - }); -}); diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts deleted file mode 100644 index 3e9c93bfd9..0000000000 --- a/packages/logger/tests/unit/Logger.test.ts +++ /dev/null @@ -1,3679 +0,0 @@ -/** - * Test Logger class - * - * @group unit/logger/logger - */ -import type { LambdaInterface } from '@aws-lambda-powertools/commons/types'; -import context from '@aws-lambda-powertools/testing-utils/context'; -import type { Context } from 'aws-lambda'; -import { EnvironmentVariablesService } from '../../src/config/EnvironmentVariablesService.js'; -import { LogJsonIndent } from '../../src/constants.js'; -import { PowertoolsLogFormatter } from '../../src/formatter/PowertoolsLogFormatter.js'; -import { LogFormatter, LogLevel, Logger } from '../../src/index.js'; -import type { ConfigServiceInterface } from '../../src/types/ConfigServiceInterface.js'; -import type { - LogLevelThresholds, - LogLevel as LogLevelType, -} from '../../src/types/Log.js'; -import type { - ConstructorOptions, - CustomJsonReplacerFn, - LogFunction, -} from '../../src/types/Logger.js'; - -const mockDate = new Date(1466424490000); -const dateSpy = jest.spyOn(global, 'Date').mockImplementation(() => mockDate); -const getConsoleMethod = ( - method: string -): keyof Omit => - method === 'critical' - ? 'error' - : (method.toLowerCase() as keyof Omit); -const getLogLevel = (method: string): LogLevelType => - method.toUpperCase() as LogLevelType; -jest.mock('node:console', () => ({ - ...jest.requireActual('node:console'), - Console: jest.fn().mockImplementation(() => ({ - log: jest.fn(), // patched equivalent for trace - debug: jest.fn(), - info: jest.fn(), - warn: jest.fn(), - error: jest.fn(), - })), -})); - -describe('Class: Logger', () => { - const ENVIRONMENT_VARIABLES = process.env; - const event = { - foo: 'bar', - bar: 'baz', - }; - const logLevelThresholds: LogLevelThresholds = { - TRACE: 6, - DEBUG: 8, - INFO: 12, - WARN: 16, - ERROR: 20, - CRITICAL: 24, - SILENT: 28, - }; - - beforeEach(() => { - dateSpy.mockClear(); - process.env = { ...ENVIRONMENT_VARIABLES }; - }); - - describe('Method: constructor', () => { - test('when no constructor parameters are set, returns a Logger instance with the options set in the environment variables', () => { - // Prepare - const loggerOptions = undefined; - - // Act - const logger = new Logger(loggerOptions); - - // Assess - expect(logger).toBeInstanceOf(Logger); - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: {}, - powertoolsLogData: { - sampleRateValue: 0, - awsRegion: 'eu-west-1', - environment: '', - serviceName: 'hello-world', - }, - envVarsService: expect.any(EnvironmentVariablesService), - customConfigService: undefined, - defaultServiceName: 'service_undefined', - logLevel: logLevelThresholds.DEBUG, - logFormatter: expect.any(PowertoolsLogFormatter), - }) - ); - }); - - test('when no parameters are set, returns a Logger instance with the correct properties', () => { - // Prepare - const loggerOptions: ConstructorOptions = { - logLevel: 'WARN', - serviceName: 'my-lambda-service', - sampleRateValue: 1, - logFormatter: new PowertoolsLogFormatter(), - customConfigService: new EnvironmentVariablesService(), - persistentLogAttributes: { - awsAccountId: '123456789', - }, - environment: 'prod', - }; - - // Act - const logger = new Logger(loggerOptions); - - // Assess - expect(logger).toBeInstanceOf(Logger); - expect(logger).toEqual({ - coldStart: true, - defaultServiceName: 'service_undefined', - customConfigService: expect.any(EnvironmentVariablesService), - envVarsService: expect.any(EnvironmentVariablesService), - logEvent: false, - logIndentation: 0, - logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: logLevelThresholds.DEBUG, // 100% sample rate value changes log level from WARN to DEBUG - console: expect.objectContaining({ - debug: expect.any(Function), - error: expect.any(Function), - info: expect.any(Function), - warn: expect.any(Function), - }), - logLevelThresholds: { - ...logLevelThresholds, - }, - persistentLogAttributes: { - awsAccountId: '123456789', - }, - temporaryLogAttributes: {}, - powertoolsLogData: { - awsRegion: 'eu-west-1', - environment: 'prod', - sampleRateValue: 1, - serviceName: 'my-lambda-service', - }, - }); - }); - - test('when no constructor parameters and no environment variables are set, returns a Logger instance with the default properties', () => { - // Prepare - const loggerOptions = undefined; - process.env.POWERTOOLS_SERVICE_NAME = undefined; - process.env.POWERTOOLS_LOG_LEVEL = undefined; - - // Act - const logger = new Logger(loggerOptions); - - // Assess - expect(logger).toBeInstanceOf(Logger); - expect(logger).toEqual({ - coldStart: true, - customConfigService: undefined, - defaultServiceName: 'service_undefined', - envVarsService: expect.any(EnvironmentVariablesService), - logEvent: false, - logIndentation: 0, - logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: 12, - console: expect.objectContaining({ - debug: expect.any(Function), - error: expect.any(Function), - info: expect.any(Function), - warn: expect.any(Function), - }), - logLevelThresholds: { - ...logLevelThresholds, - }, - persistentLogAttributes: {}, - temporaryLogAttributes: {}, - powertoolsLogData: { - awsRegion: 'eu-west-1', - environment: '', - sampleRateValue: 0, - serviceName: 'service_undefined', - }, - }); - }); - - test('when a custom logFormatter is passed, returns a Logger instance with the correct properties', () => { - // Prepare - const loggerOptions: ConstructorOptions = { - logFormatter: expect.any(LogFormatter), - }; - - // Act - const logger = new Logger(loggerOptions); - - // Assess - expect(logger).toBeInstanceOf(Logger); - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: {}, - powertoolsLogData: { - sampleRateValue: 0, - awsRegion: 'eu-west-1', - environment: '', - serviceName: 'hello-world', - }, - envVarsService: expect.any(EnvironmentVariablesService), - customConfigService: undefined, - logLevel: logLevelThresholds.DEBUG, - logFormatter: expect.any(LogFormatter), - }) - ); - }); - - test('when a custom serviceName is passed, returns a Logger instance with the correct properties', () => { - // Prepare - const loggerOptions: ConstructorOptions = { - serviceName: 'my-backend-service', - }; - - // Act - const logger = new Logger(loggerOptions); - - // Assess - expect(logger).toBeInstanceOf(Logger); - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: {}, - powertoolsLogData: { - sampleRateValue: 0, - awsRegion: 'eu-west-1', - environment: '', - serviceName: 'my-backend-service', - }, - envVarsService: expect.any(EnvironmentVariablesService), - customConfigService: undefined, - logLevel: logLevelThresholds.DEBUG, - logFormatter: expect.any(PowertoolsLogFormatter), - }) - ); - }); - - test('when a custom uppercase logLevel is passed, returns a Logger instance with the correct properties', () => { - // Prepare - const loggerOptions: ConstructorOptions = { - logLevel: 'ERROR', - }; - - // Act - const logger = new Logger(loggerOptions); - - // Assess - expect(logger).toBeInstanceOf(Logger); - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: {}, - powertoolsLogData: { - sampleRateValue: 0, - awsRegion: 'eu-west-1', - environment: '', - serviceName: 'hello-world', - }, - envVarsService: expect.any(EnvironmentVariablesService), - customConfigService: undefined, - logLevel: 20, - logFormatter: expect.any(PowertoolsLogFormatter), - }) - ); - }); - - test('when a custom lowercase logLevel is passed, returns a Logger instance with the correct properties', () => { - // Prepare - const loggerOptions: ConstructorOptions = { - logLevel: 'warn', - }; - - // Act - const logger = new Logger(loggerOptions); - - // Assess - expect(logger).toBeInstanceOf(Logger); - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: {}, - powertoolsLogData: { - sampleRateValue: 0, - awsRegion: 'eu-west-1', - environment: '', - serviceName: 'hello-world', - }, - envVarsService: expect.any(EnvironmentVariablesService), - customConfigService: undefined, - logLevel: 16, - logFormatter: expect.any(PowertoolsLogFormatter), - }) - ); - }); - - test('when no log level is set, returns a Logger instance with INFO level', () => { - // Prepare - const loggerOptions: ConstructorOptions = {}; - process.env.POWERTOOLS_LOG_LEVEL = undefined; - - // Act - const logger = new Logger(loggerOptions); - - // Assess - expect(logger).toBeInstanceOf(Logger); - expect(logger).toEqual({ - coldStart: true, - customConfigService: undefined, - defaultServiceName: 'service_undefined', - envVarsService: expect.any(EnvironmentVariablesService), - logEvent: false, - logIndentation: 0, - logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: 12, - console: expect.objectContaining({ - debug: expect.any(Function), - error: expect.any(Function), - info: expect.any(Function), - warn: expect.any(Function), - }), - logLevelThresholds: { - ...logLevelThresholds, - }, - persistentLogAttributes: {}, - temporaryLogAttributes: {}, - powertoolsLogData: { - awsRegion: 'eu-west-1', - environment: '', - sampleRateValue: 0, - serviceName: 'hello-world', - }, - }); - }); - - test('when a custom sampleRateValue is passed, returns a Logger instance with the correct properties', () => { - // Prepare - const loggerOptions: ConstructorOptions = { - sampleRateValue: 1, - }; - - // Act - const logger = new Logger(loggerOptions); - - // Assess - expect(logger).toBeInstanceOf(Logger); - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: {}, - powertoolsLogData: { - sampleRateValue: 1, - awsRegion: 'eu-west-1', - environment: '', - serviceName: 'hello-world', - }, - envVarsService: expect.any(EnvironmentVariablesService), - customConfigService: undefined, - logLevel: logLevelThresholds.DEBUG, - logFormatter: expect.any(PowertoolsLogFormatter), - }) - ); - }); - - test('when a custom customConfigService is passed, returns a Logger instance with the correct properties', () => { - const configService: ConfigServiceInterface = { - get(name: string): string { - return `a-string-from-${name}`; - }, - getAwsLogLevel() { - return 'INFO'; - }, - getCurrentEnvironment(): string { - return 'dev'; - }, - getLogEvent(): boolean { - return true; - }, - getLogLevel(): string { - return 'INFO'; - }, - getSampleRateValue(): number | undefined { - return undefined; - }, - getServiceName(): string { - return 'my-backend-service'; - }, - getXrayTraceId(): string | undefined { - return undefined; - }, - getXrayTraceSampled() { - return true; - }, - isDevMode(): boolean { - return false; - }, - isValueTrue(): boolean { - return true; - }, - }; - // Prepare - const loggerOptions: ConstructorOptions = { - customConfigService: configService, - }; - - // Act - const logger = new Logger(loggerOptions); - - // Assess - expect(logger).toBeInstanceOf(Logger); - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: {}, - powertoolsLogData: { - sampleRateValue: 0, - awsRegion: 'eu-west-1', - environment: 'dev', - serviceName: 'my-backend-service', - }, - envVarsService: expect.any(EnvironmentVariablesService), - customConfigService: configService, - logLevel: 12, - logFormatter: expect.any(PowertoolsLogFormatter), - }) - ); - }); - - test('when custom persistentLogAttributes is passed, returns a Logger instance with the correct properties', () => { - // Prepare - const loggerOptions: ConstructorOptions = { - persistentLogAttributes: { - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - }; - - // Act - const logger = new Logger(loggerOptions); - - // Assess - expect(logger).toBeInstanceOf(Logger); - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: { - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - powertoolsLogData: { - sampleRateValue: 0, - awsRegion: 'eu-west-1', - environment: '', - serviceName: 'hello-world', - }, - envVarsService: expect.any(EnvironmentVariablesService), - customConfigService: undefined, - logLevel: logLevelThresholds.DEBUG, - logFormatter: expect.any(PowertoolsLogFormatter), - }) - ); - }); - - test('when custom persistentKeys is passed, returns a Logger instance with the correct properties', () => { - // Prepare - const loggerOptions: ConstructorOptions = { - persistentKeys: { - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - }; - - // Act - const logger = new Logger(loggerOptions); - - // Assess - expect(logger).toBeInstanceOf(Logger); - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: { - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - powertoolsLogData: { - sampleRateValue: 0, - awsRegion: 'eu-west-1', - environment: '', - serviceName: 'hello-world', - }, - envVarsService: expect.any(EnvironmentVariablesService), - customConfigService: undefined, - logLevel: logLevelThresholds.DEBUG, - logFormatter: expect.any(PowertoolsLogFormatter), - }) - ); - }); - - test('it emits a warning when both persistentKeys and persistentLogAttributes are used in the constructor', () => { - // Prepare - // Since the buffer is private and we are bypassing the public warn method, we need to spy on the console.warn - process.env.POWERTOOLS_DEV = 'true'; - const warningSpy = jest.spyOn(console, 'warn').mockImplementation(); - - type TestConstructorOptions = { - persistentLogAttributes?: Record; - persistentKeys?: Record; - }; - - const loggerOptions: TestConstructorOptions = { - persistentKeys: { - foo: 'bar', - }, - persistentLogAttributes: { - foo: 'bar', - }, - }; - - // Act - new Logger(loggerOptions as ConstructorOptions); - - // Assess - expect(warningSpy).toHaveBeenCalledTimes(1); - expect(warningSpy).toHaveBeenCalledWith( - expect.stringContaining( - 'Both persistentLogAttributes and persistentKeys options were provided. Using persistentKeys as persistentLogAttributes is deprecated and will be removed in future releases' - ) - ); - // Cleanup - warningSpy.mockRestore(); - }); - - test('when a custom environment is passed, returns a Logger instance with the correct properties', () => { - // Prepare - const loggerOptions: ConstructorOptions = { - environment: 'dev', - }; - - // Act - const logger = new Logger(loggerOptions); - - // Assess - expect(logger).toBeInstanceOf(Logger); - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: {}, - powertoolsLogData: { - sampleRateValue: 0, - awsRegion: 'eu-west-1', - environment: 'dev', - serviceName: 'hello-world', - }, - envVarsService: expect.any(EnvironmentVariablesService), - customConfigService: undefined, - logLevel: logLevelThresholds.DEBUG, - logFormatter: expect.any(PowertoolsLogFormatter), - }) - ); - }); - }); - - describe.each([ - [ - 'trace', - 'DOES', - true, - 'DOES NOT', - false, - 'DOES NOT', - false, - 'DOES NOT', - false, - 'DOES NOT', - false, - ], - [ - 'debug', - 'DOES', - true, - 'DOES', - true, - 'DOES NOT', - false, - 'DOES NOT', - false, - 'DOES NOT', - false, - ], - [ - 'info', - 'DOES', - true, - 'DOES', - true, - 'DOES', - true, - 'DOES NOT', - false, - 'DOES NOT', - false, - ], - [ - 'warn', - 'DOES', - true, - 'DOES', - true, - 'DOES', - true, - 'DOES', - true, - 'DOES NOT', - false, - ], - [ - 'error', - 'DOES', - true, - 'DOES', - true, - 'DOES', - true, - 'DOES', - true, - 'DOES', - true, - ], - [ - 'critical', - 'DOES', - true, - 'DOES', - true, - 'DOES', - true, - 'DOES', - true, - 'DOES', - true, - ], - ])( - 'Method:', - ( - method: string, - traceAction, - tracePrints, - debugAction, - debugPrints, - infoAction, - infoPrints, - warnAction, - warnPrints, - errorAction, - errorPrints - ) => { - const methodOfLogger = method as keyof LogFunction; - - describe('Feature: log level', () => { - function testLoggerPrints(logger: Logger, expectPrints: boolean): void { - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(method) - ); - // Act - logger[methodOfLogger]('foo'); - - // Assess - expect(consoleSpy).toBeCalledTimes(expectPrints ? 1 : 0); - if (expectPrints) { - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - 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', - }) - ); - } - } - - test(`when the level is TRACE, it ${traceAction} print to stdout`, () => { - // Prepare - const logger = new Logger({ - logLevel: LogLevel.TRACE, - }); - - testLoggerPrints(logger, tracePrints); - }); - - test(`when the level is DEBUG, it ${debugAction} print to stdout`, () => { - // Prepare - const logger = new Logger({ - logLevel: LogLevel.DEBUG, - }); - - testLoggerPrints(logger, debugPrints); - }); - - test(`when the log level is INFO, it ${infoAction} print to stdout`, () => { - // Prepare - const logger = new Logger({ - logLevel: 'INFO', - }); - - testLoggerPrints(logger, infoPrints); - }); - - test(`when the log level is WARN, it ${warnAction} print to stdout`, () => { - // Prepare - const logger = new Logger({ - logLevel: LogLevel.WARN, - }); - - testLoggerPrints(logger, warnPrints); - }); - - test(`when the log level is ERROR, it ${errorAction} print to stdout`, () => { - // Prepare - const logger = new Logger({ - logLevel: LogLevel.ERROR, - }); - - testLoggerPrints(logger, errorPrints); - }); - - test('when the log level is SILENT, it DOES NOT print to stdout', () => { - // Prepare - const logger = new Logger({ - logLevel: LogLevel.SILENT, - }); - - testLoggerPrints(logger, false); - }); - - test('when the log level is set through POWERTOOLS_LOG_LEVEL env variable, it DOES print to stdout', () => { - // Prepare - process.env.POWERTOOLS_LOG_LEVEL = methodOfLogger.toUpperCase(); - const logger = new Logger(); - - testLoggerPrints(logger, true); - }); - }); - - 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({ - logLevel: 'SILENT', - sampleRateValue: 0, - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - // Act - if (logger[methodOfLogger]) { - logger[methodOfLogger]('foo'); - } - - // 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 and changes log level to DEBUG', () => { - // Prepare - const logger = new Logger({ - logLevel: 'SILENT', - sampleRateValue: 1, - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - // Act - if (logger[methodOfLogger]) { - logger[methodOfLogger]('foo'); - } - - // Assess - expect(logger.level).toBe(logLevelThresholds.DEBUG); - expect(logger.getLevelName()).toBe('DEBUG'); - if (method === 'trace') { - expect(consoleSpy).toHaveBeenCalledTimes(0); - } else { - expect(consoleSpy).toHaveBeenCalledTimes( - method === 'debug' ? 2 : 1 - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - method === 'debug' ? 2 : 1, - JSON.stringify({ - level: method.toUpperCase(), - message: 'foo', - sampling_rate: 1, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }) - ); - } - }); - }); - - describe('Feature: inject context', () => { - test(`when the Lambda context is not captured and a string is passed as log message, it should print a valid ${method.toUpperCase()} log`, () => { - // Prepare - const logger = new Logger({ - logLevel: getLogLevel(method), - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - // Act - if (logger[methodOfLogger]) { - logger[methodOfLogger]('foo'); - } - - // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - 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', - }) - ); - }); - - test(`when the Lambda context is captured, it returns a valid ${method.toUpperCase()} log`, () => { - // Prepare - const logger = new Logger({ - logLevel: getLogLevel(method), - }); - logger.addContext(context); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - // Act - if (logger[methodOfLogger]) { - logger[methodOfLogger]('foo'); - } - - // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - 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', - }) - ); - }); - }); - - describe('Feature: ephemeral log attributes', () => { - const logger = new Logger({ - logLevel: getLogLevel(method), - }); - - it.each([ - { - idx: 0, - inputs: ['A log item without extra parameters'], - expected: { - level: method.toUpperCase(), - message: 'A log item without extra parameters', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }, - }, - { - idx: 1, - inputs: [ - 'A log item with a string as first parameter, and an object as second parameter', - { extra: 'parameter' }, - ], - expected: { - level: method.toUpperCase(), - message: - 'A log item with a string as first parameter, and an object as second parameter', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - extra: 'parameter', - }, - }, - { - idx: 2, - inputs: [ - 'A log item with a string as first parameter, and objects as other parameters', - { parameterOne: 'foo' }, - { parameterTwo: 'bar' }, - ], - expected: { - level: method.toUpperCase(), - message: - 'A log item with a string as first parameter, and objects as other parameters', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - parameterOne: 'foo', - parameterTwo: 'bar', - }, - }, - { - idx: 3, - inputs: [ - { - message: 'A log item with an object as first parameters', - extra: 'parameter', - }, - ], - expected: { - level: method.toUpperCase(), - message: 'A log item with an object as first parameters', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - extra: 'parameter', - }, - }, - { - idx: 4, - inputs: [ - 'A log item with a string as first parameter, and an error as second parameter', - new Error('Something happened!'), - ], - expected: { - level: method.toUpperCase(), - message: - 'A log item with a string as first parameter, and an error as second parameter', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - error: { - location: expect.any(String), - message: 'Something happened!', - name: 'Error', - stack: expect.any(String), - }, - }, - }, - { - idx: 5, - inputs: [ - 'A log item with a string as first parameter, and an error with custom key as second parameter', - { myCustomErrorKey: new Error('Something happened!') }, - ], - expected: { - level: method.toUpperCase(), - message: - 'A log item with a string as first parameter, and an error with custom key as second parameter', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - myCustomErrorKey: { - location: expect.any(String), - message: 'Something happened!', - name: 'Error', - stack: expect.any(String), - }, - }, - }, - { - idx: 6, - inputs: [ - 'A log item with a string as first parameter, and a string as second parameter', - 'parameter', - ], - expected: { - level: method.toUpperCase(), - message: - 'A log item with a string as first parameter, and a string as second parameter', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - extra: 'parameter', - }, - }, - { - idx: 7, - inputs: [ - 'A log item with a string as first parameter, and an inline object as second parameter', - { extra: { custom: mockDate } }, - ], - expected: { - level: method.toUpperCase(), - message: - 'A log item with a string as first parameter, and an inline object as second parameter', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - extra: { custom: '2016-06-20T12:08:10.000Z' }, - }, - }, - { - idx: 8, - inputs: [ - 'A log item with a string as first parameter, and an arbitrary object as second parameter', - { - extra: { - value: 'CUSTOM', - nested: { - bool: true, - str: 'string value', - num: 42, - err: new Error('Arbitrary object error'), - }, - }, - }, - ], - expected: { - level: method.toUpperCase(), - message: - 'A log item with a string as first parameter, and an arbitrary object as second parameter', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - extra: { - value: 'CUSTOM', - nested: { - bool: true, - str: 'string value', - num: 42, - err: { - location: expect.any(String), - message: 'Arbitrary object error', - name: 'Error', - stack: expect.any(String), - }, - }, - }, - }, - }, - ])( - 'when added, they should appear in that log item only', - ({ idx, inputs, expected }) => { - // Prepare - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - - // Act - // @ts-expect-error - we are testing the method dynamically - logger[methodOfLogger](...inputs); - - // Assess - const received = JSON.parse(consoleSpy.mock.calls[idx][0]); - expect(received).toEqual(expect.objectContaining(expected)); - } - ); - }); - - describe('Feature: persistent log attributes', () => { - test('when persistent log attributes are added to the Logger instance, they should appear in all logs printed by the instance', () => { - // Prepare - const logger = new Logger({ - logLevel: getLogLevel(method), - persistentLogAttributes: { - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - }, - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - // Act - if (logger[methodOfLogger]) { - logger[methodOfLogger]('foo'); - } - - // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - 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', - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - }) - ); - }); - }); - - describe('Feature: X-Ray Trace ID injection', () => { - test('when the `_X_AMZN_TRACE_ID` environment variable is set it parses it correctly and adds the Trace ID to the log', () => { - // Prepare - const logger = new Logger({ - logLevel: getLogLevel(method), - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - // Act - if (logger[methodOfLogger]) { - logger[methodOfLogger]('foo'); - } - - // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - 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', - }) - ); - }); - - test('when the `_X_AMZN_TRACE_ID` environment variable is NOT set it parses it correctly and adds the Trace ID to the log', () => { - // Prepare - process.env._X_AMZN_TRACE_ID = undefined; - const logger = new Logger({ - logLevel: getLogLevel(method), - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - // Act - if (logger[methodOfLogger]) { - logger[methodOfLogger]('foo'); - } - - // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ - level: method.toUpperCase(), - message: 'foo', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - }) - ); - }); - }); - - describe('Feature: custom JSON replacer function', () => { - test('when a logged item references itself, the logger ignores the keys that cause a circular reference', () => { - // Prepare - const logger = new Logger({ - logLevel: getLogLevel(method), - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - const circularObject = { - foo: 'bar', - self: {}, - }; - circularObject.self = circularObject; - const logCircularReference = (): string => { - if (logger[methodOfLogger]) { - logger[methodOfLogger]('A log with a circular reference', { - details: circularObject, - }); - } - - return 'All good!'; - }; - - // Act - const result = logCircularReference(); - - // Assess - expect(result).toBe('All good!'); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - 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', - details: { - foo: 'bar', - }, - }) - ); - }); - - test('when a logged item has BigInt value, it does not throw TypeError', () => { - // Prepare - const logger = new Logger({ - logLevel: getLogLevel(method), - }); - jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - const message = `This is an ${methodOfLogger} log with BigInt value`; - const logItem = { value: BigInt(42) }; - const errorMessage = 'Do not know how to serialize a BigInt'; - - // Act & Assess - expect(() => { - logger[methodOfLogger](message, logItem); - }).not.toThrow(errorMessage); - }); - - test('when a logged item has a BigInt value, it prints the log with value as a string', () => { - // Prepare - const logger = new Logger({ - logLevel: getLogLevel(method), - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - const message = `This is an ${methodOfLogger} log with BigInt value`; - const logItem = { value: BigInt(42) }; - - // Act - logger[methodOfLogger](message, logItem); - - // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - 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', - value: '42', - }) - ); - }); - - test('when a logged item has empty string, null, or undefined values, it removes it', () => { - // Prepare - const logger = new Logger({ - logLevel: getLogLevel(method), - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - const message = `This is an ${methodOfLogger} log with empty, null, and undefined values`; - const logItem = { - value: 42, - emptyValue: '', - undefinedValue: undefined, - nullValue: null, - }; - - // Act - logger[methodOfLogger](message, logItem); - - // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - 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', - value: 42, - }) - ); - }); - - it('should correctly serialize custom values using the provided jsonReplacerFn', () => { - // Prepare - const jsonReplacerFn: CustomJsonReplacerFn = ( - _: string, - value: unknown - ) => (value instanceof Set ? [...value] : value); - - const logger = new Logger({ - logLevel: getLogLevel(method), - jsonReplacerFn, - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - const message = `This is an ${methodOfLogger} log with Set value`; - - const logItem = { value: new Set([1, 2]) }; - - // Act - logger[methodOfLogger](message, logItem); - - // Assess - expect(consoleSpy).toHaveBeenCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - 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', - value: [1, 2], - }) - ); - }); - - it('should serialize using both the existing replacer and the customer-provided one', () => { - // Prepare - const jsonReplacerFn: CustomJsonReplacerFn = ( - _: string, - value: unknown - ) => { - if (value instanceof Set || value instanceof Map) { - return [...value]; - } - - return value; - }; - - const logger = new Logger({ - logLevel: getLogLevel(method), - jsonReplacerFn, - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - getConsoleMethod(methodOfLogger) - ); - - const message = `This is an ${methodOfLogger} log with Set value`; - const logItem = { value: new Set([1, 2]), number: BigInt(42) }; - - // Act - logger[methodOfLogger](message, logItem); - - // Assess - expect(consoleSpy).toHaveBeenCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - 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', - value: [1, 2], - number: '42', - }) - ); - }); - - it('should pass the JSON customer-provided replacer function to child loggers', () => { - // Prepare - const jsonReplacerFn: CustomJsonReplacerFn = ( - _: string, - value: unknown - ) => (value instanceof Set ? [...value] : value); - const logger = new Logger({ jsonReplacerFn }); - - // Act - const childLogger = logger.createChild(); - - // Assess - expect(() => - childLogger.info('foo', { foo: new Set([1, 2]) }) - ).not.toThrow(); - }); - }); - } - ); - - describe('Method: addContext', () => { - test('when called during a cold start invocation, it populates the logger powertoolsLogData object with coldStart set to TRUE', () => { - // Prepare - const logger = new Logger(); - - // Act - logger.addContext(context); - - // Assess - expect(logger).toEqual( - expect.objectContaining({ - coldStart: false, // This is now false because the `coldStart` attribute has been already accessed once by the `addContext` method - powertoolsLogData: expect.objectContaining({ - lambdaContext: expect.objectContaining({ - coldStart: true, - }), - sampleRateValue: 0, - serviceName: 'hello-world', - }), - }) - ); - }); - - test('when called with a context object, the object is not mutated', () => { - // Prepare - const logger = new Logger(); - const context1 = { - ...context, - awsRequestId: 'c6af9ac6-7b61-11e6-9a41-93e812345678', - }; - const context2 = { - ...context, - awsRequestId: 'd40c98a9-91c4-478c-a179-433c4b978289', - }; - - // Act - logger.addContext(context1); - logger.addContext(context2); - - // Assess - expect(context1.awsRequestId).toEqual( - 'c6af9ac6-7b61-11e6-9a41-93e812345678' - ); - expect(context2.awsRequestId).toEqual( - 'd40c98a9-91c4-478c-a179-433c4b978289' - ); - }); - - test('when called multiple times, the newer values override earlier values', () => { - // Prepare - const logger = new Logger(); - const context1 = { - ...context, - awsRequestId: 'c6af9ac6-7b61-11e6-9a41-93e812345678', - }; - const context2 = { - ...context, - awsRequestId: 'd40c98a9-91c4-478c-a179-433c4b978289', - }; - - // Act - logger.addContext(context1); - logger.addContext(context2); - - // Assess - expect(logger).toEqual( - expect.objectContaining({ - powertoolsLogData: expect.objectContaining({ - lambdaContext: expect.objectContaining({ - awsRequestId: context2.awsRequestId, - }), - }), - }) - ); - }); - }); - - describe('Method: appendKeys', () => { - test('when called, it populates the logger temporaryLogAttributes property', () => { - // Prepare - const logger = new Logger(); - - // Act - logger.appendKeys({ - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }); - - // Assess - expect(logger).toEqual( - expect.objectContaining({ - temporaryLogAttributes: { - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - }) - ); - }); - - test('when called with user-provided attribute objects, the objects are not mutated', () => { - // Prepare - const logger = new Logger(); - const attributes1 = { keyOne: 'abc' }; - const attributes2 = { keyTwo: 'def' }; - - // Act - logger.appendKeys(attributes1); - logger.appendKeys(attributes2); - - // Assess - expect(attributes1).toEqual({ keyOne: 'abc' }); - expect(attributes2).toEqual({ keyTwo: 'def' }); - }); - - test('when called multiple times, the newer values override earlier values', () => { - // Prepare - const logger = new Logger(); - - // Act - logger.appendKeys({ - duplicateKey: 'one', - }); - logger.appendKeys({ - duplicateKey: 'two', - }); - - // Assess - expect(logger).toEqual( - expect.objectContaining({ - temporaryLogAttributes: { - duplicateKey: 'two', - }, - }) - ); - }); - - test('when called with the same key as in persistentKeys container option, persistent keys will be overwritten', () => { - // Prepare - const logger = new Logger({ - persistentKeys: { - aws_account_id: '1234567890', - }, - }); - - logger.appendKeys({ - aws_account_id: '0987654321', - }); - - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - - // Act - logger.info('This is an INFO log with some log attributes'); - - // Assess - expect(consoleSpy).toHaveBeenCalledTimes(1); - const log = JSON.parse(consoleSpy.mock.calls[0][0]); - expect(log).toStrictEqual( - expect.objectContaining({ - aws_account_id: '0987654321', - }) - ); - }); - }); - - describe('Method: removeKeys', () => { - test('when called, it removes keys added with appendKeys() method', () => { - // Prepare - const logger = new Logger(); - logger.appendKeys({ - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }); - - // Act - logger.removeKeys(['aws_account_id', 'aws_region']); - - // Assess - expect(logger).toEqual( - expect.objectContaining({ - temporaryLogAttributes: { - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - }) - ); - }); - - test('when called, it DOES NOT remove persistent keys', () => { - // Prepare - const loggerOptions: ConstructorOptions = { - persistentKeys: { - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - }; - const logger = new Logger(loggerOptions); - - // Act - logger.removeKeys(['aws_account_id', 'aws_region']); - - // Assess - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: { - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - }) - ); - }); - - test('when called with non-existing keys, the logger instance is not mutated and it does not throw an error', () => { - // Prepare - const logger = new Logger(); - logger.appendKeys({ - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }); - const loggerBeforeKeysAreRemoved = { ...logger }; - - // Act - logger.removeKeys(['not_existing_key']); - - // Assess - expect(logger).toEqual(loggerBeforeKeysAreRemoved); - expect(logger).toEqual( - expect.objectContaining({ - temporaryLogAttributes: { - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - }) - ); - }); - - test('when called multiple times with the same keys, the outcome is the same', () => { - // Prepare - const logger = new Logger(); - logger.appendKeys({ - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }); - - // Act - logger.removeKeys(['aws_account_id', 'aws_region']); - logger.removeKeys(['aws_account_id', 'aws_region']); - - // Assess - expect(logger).toEqual( - expect.objectContaining({ - temporaryLogAttributes: { - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - }) - ); - }); - }); - - describe('Method: removePersistentLogAttributes', () => { - test('when called, it removes persistent keys', () => { - // Prepare - const loggerOptions: ConstructorOptions = { - persistentKeys: { - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - }; - const logger = new Logger(loggerOptions); - - // Act - logger.removePersistentLogAttributes(['aws_account_id', 'aws_region']); - - // Assess - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: { - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - }) - ); - }); - - test('when called, it DOES NOT remove temporary keys', () => { - // Prepare - const logger = new Logger(); - logger.appendKeys({ - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - }); - - // Act - logger.removePersistentLogAttributes(['aws_account_id', 'aws_region']); - - // Assess - expect(logger).toEqual( - expect.objectContaining({ - temporaryLogAttributes: { - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - }, - }) - ); - }); - }); - - describe('Method: resetKeys', () => { - test('when called, it removes all keys added with appendKeys() method', () => { - // Prepare - const logger = new Logger(); - logger.appendKeys({ - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }); - - // Act - logger.resetKeys(); - - // Assess - expect(logger).toEqual( - expect.objectContaining({ - temporaryLogAttributes: {}, - }) - ); - }); - - test('when called, it DOES NOT remove persistent keys', () => { - // Prepare - const loggerOptions: ConstructorOptions = { - persistentKeys: { - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - }; - const logger = new Logger(loggerOptions); - logger.appendKeys({ foo: 'bar' }); - - // Act - logger.resetKeys(); - - // Assess - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: { - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - temporaryLogAttributes: {}, - }) - ); - }); - - it('preserves persistent keys that were previously overwritten', () => { - // Prepare - const logger = new Logger({ - persistentKeys: { - aws_region: 'eu-west-1', - }, - }); - const debugSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - logger.appendKeys({ - aws_region: 'us-east-1', - }); - - // Act - logger.resetKeys(); - logger.info('foo'); - - // Assess - const log = JSON.parse(debugSpy.mock.calls[0][0]); - expect(log).toStrictEqual( - expect.objectContaining({ aws_region: 'eu-west-1' }) - ); - }); - }); - - describe('method: setPersistentLogAttributes (deprecated)', () => { - test('when called, it overwrites all persistent keys', () => { - // Prepare - const loggerOptions: ConstructorOptions = { - persistentKeys: { - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - }, - }; - const logger = new Logger(loggerOptions); - - // Act - logger.setPersistentLogAttributes({ - foo: 'bar', - }); - - // Assess - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: { - foo: 'bar', - }, - }) - ); - }); - }); - - describe('Method: appendPersistentKeys', () => { - it('overwrites existing persistent keys with new ones', () => { - // Prepare - const logger = new Logger({ - persistentKeys: { - aws_account_id: '123456789012', - }, - }); - - // Act - logger.appendPersistentKeys({ - aws_account_id: '0987654321', - }); - - // Assess - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: { - aws_account_id: '0987654321', - }, - }) - ); - }); - - it('overwrites existing temporary keys with new ones in the next log', () => { - // Prepare - const logger = new Logger(); - const debugSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - logger.appendKeys({ - aws_account_id: '123456789012', - }); - - // Act - logger.appendPersistentKeys({ - aws_account_id: '0987654321', - }); - logger.info('This is an INFO log with some log attributes'); - - // Assess - const log = JSON.parse(debugSpy.mock.calls[0][0]); - expect(log).toStrictEqual( - expect.objectContaining({ aws_account_id: '0987654321' }) - ); - }); - }); - - describe('Method: injectLambdaContext', () => { - beforeEach(() => { - jest.spyOn(console, 'log').mockImplementation(() => ({})); - }); - - test('it returns a decorated method with the correct scope of the decorated class', async () => { - // Prepare - - const logger = new Logger(); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - class LambdaFunction implements LambdaInterface { - @logger.injectLambdaContext() - public async handler( - _event: TEvent, - _context: Context - ): Promise { - this.myClassMethod(); - } - - private myClassMethod(): void { - logger.info('This is an INFO log with some context'); - } - } - const handlerClass = new LambdaFunction(); - const handler = handlerClass.handler.bind(handlerClass); - - // Act - await handler(event, context); - - // Assess - expect(consoleSpy).toHaveBeenCalledTimes(1); - const log = JSON.parse(consoleSpy.mock.calls[0][0]); - expect(log).toEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - 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', - }) - ); - }); - - test('it captures Lambda context information and adds it in the printed logs', async () => { - // Prepare - const logger = new Logger(); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - class LambdaFunction implements LambdaInterface { - @logger.injectLambdaContext() - public async handler( - _event: TEvent, - _context: Context - ): Promise { - logger.info('This is an INFO log with some context'); - } - } - const handlerClass = new LambdaFunction(); - const handler = handlerClass.handler.bind(handlerClass); - - // Act - logger.info('An INFO log without context!'); - await handler(event, context); - - // Assess - - expect(consoleSpy).toHaveBeenCalledTimes(2); - const log1 = JSON.parse(consoleSpy.mock.calls[0][0]); - expect(log1).toStrictEqual( - expect.objectContaining({ - 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', - }) - ); - const log2 = JSON.parse(consoleSpy.mock.calls[1][0]); - expect(log2).toStrictEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - 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', - }) - ); - }); - - test('it captures Lambda context information and adds it in the printed logs for async methods', async () => { - // Prepare - const expectedReturnValue = 'Lambda invoked!'; - const logger = new Logger(); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - class LambdaFunction implements LambdaInterface { - @logger.injectLambdaContext() - public async handler( - _event: TEvent, - _context: Context - ): Promise { - logger.info('This is an INFO log with some context'); - - return expectedReturnValue; - } - } - const handlerClass = new LambdaFunction(); - const handler = handlerClass.handler.bind(handlerClass); - - // Act - logger.info('An INFO log without context!'); - const actualResult = await handler(event, context); - - // Assess - - expect(actualResult).toEqual(expectedReturnValue); - expect(consoleSpy).toHaveBeenCalledTimes(2); - const log1 = JSON.parse(consoleSpy.mock.calls[0][0]); - expect(log1).toStrictEqual( - expect.objectContaining({ - 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', - }) - ); - const log2 = JSON.parse(consoleSpy.mock.calls[1][0]); - expect(log2).toStrictEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - 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', - }) - ); - }); - - test('when enabled, it clears all the log attributes added with appendKeys() inside and outside of the handler function', async () => { - // Prepare - const logger = new Logger({ - logLevel: 'DEBUG', - }); - logger.appendKeys({ - foo: 'bar', - biz: 'baz', - }); - - const debugSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'debug' - ); - - class LambdaFunction implements LambdaInterface { - @logger.injectLambdaContext({ clearState: true }) - public async handler( - _event: TEvent, - _context: Context - ): Promise { - // Only add these keys for the scope of this lambda handler - logger.appendKeys({ - details: { user_id: '1234' }, - }); - logger.debug('This is a DEBUG log with the user_id'); - } - } - - const handlerClass = new LambdaFunction(); - const handler = handlerClass.handler.bind(handlerClass); - - // Act - await handler(event, context); - logger.debug('Checking state after handler execution'); - - // Assess - expect(debugSpy).toHaveBeenCalledTimes(2); - const log1 = JSON.parse(debugSpy.mock.calls[0][0]); - expect(log1).toStrictEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', - level: 'DEBUG', - message: 'This is a DEBUG log with the user_id', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - foo: 'bar', - biz: 'baz', - details: { user_id: '1234' }, - }) - ); - const log2 = JSON.parse(debugSpy.mock.calls[1][0]); - expect(log2).toStrictEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', - level: 'DEBUG', - message: 'Checking state after handler execution', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }) - ); - }); - - test('when clearState is enabled, the persistent log attributes added in the handler ARE NOT cleared when the method returns', async () => { - // Prepare - const logger = new Logger({ - logLevel: 'DEBUG', - persistentLogAttributes: { - foo: 'bar', - biz: 'baz', - }, - }); - class LambdaFunction implements LambdaInterface { - @logger.injectLambdaContext({ clearState: true }) - public async handler( - _event: TEvent, - _context: Context - ): Promise { - // These persistent attributes stay persistent - logger.appendPersistentKeys({ - details: { user_id: '1234' }, - }); - logger.debug('This is a DEBUG log with the user_id'); - logger.debug('This is another DEBUG log with the user_id'); - } - } - const handlerClass = new LambdaFunction(); - const handler = handlerClass.handler.bind(handlerClass); - const persistentAttribsBeforeInvocation = { - ...logger.getPersistentLogAttributes(), - }; - - // Act - await handler(event, context); - const persistentAttribsAfterInvocation = { - ...logger.getPersistentLogAttributes(), - }; - - // Assess - expect(persistentAttribsBeforeInvocation).toEqual({ - foo: 'bar', - biz: 'baz', - }); - expect(persistentAttribsAfterInvocation).toEqual({ - foo: 'bar', - biz: 'baz', - details: { user_id: '1234' }, - }); - }); - - test('when clearState is enabled, persistent log attributes added in the handler stay persistent, but temporary added in the handler are cleared when the method returns', async () => { - // Prepare - const logger = new Logger({ - logLevel: 'DEBUG', - }); - - const debugSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'debug' - ); - - class LambdaFunction implements LambdaInterface { - @logger.injectLambdaContext({ clearState: true }) - public async handler( - _event: TEvent, - _context: Context - ): Promise { - // This key is persistent and will stay persistent - logger.appendPersistentKeys({ - foo: 'bar', - }); - // This attribute is temporary and will be cleared - logger.appendKeys({ - biz: 'baz', - }); - logger.debug( - 'This is a DEBUG log with both pesistent and temporary keys' - ); - } - } - const handlerClass = new LambdaFunction(); - const handler = handlerClass.handler.bind(handlerClass); - - // Act - await handler(event, context); - logger.debug('Checking state after handler execution'); - - // Assess - expect(debugSpy).toHaveBeenCalledTimes(2); - const log1 = JSON.parse(debugSpy.mock.calls[0][0]); - expect(log1).toStrictEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', - level: 'DEBUG', - message: 'This is a DEBUG log with both pesistent and temporary keys', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - foo: 'bar', - biz: 'baz', - }) - ); - const log2 = JSON.parse(debugSpy.mock.calls[1][0]); - expect(log2).toStrictEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', - level: 'DEBUG', - message: 'Checking state after handler execution', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - foo: 'bar', - }) - ); - - debugSpy.mockRestore(); - }); - - test('when clearState is enabled, the temporary log attributes added in the handler are cleared when the method throws', async () => { - // Prepare - const logger = new Logger({ - logLevel: 'DEBUG', - }); - - const debugSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'debug' - ); - - class LambdaFunction implements LambdaInterface { - @logger.injectLambdaContext({ clearState: true }) - public async handler( - _event: TEvent, - _context: Context - ): Promise { - // This key is persistent and will stay persistent - logger.appendPersistentKeys({ - foo: 'bar', - }); - // This attribute is temporary and will be cleared - logger.appendKeys({ - biz: 'baz', - }); - logger.debug( - 'This is a DEBUG log with both pesistent and temporary keys' - ); - throw new Error('Unexpected error occurred!'); - } - } - const handlerClass = new LambdaFunction(); - const handler = handlerClass.handler.bind(handlerClass); - - // Act & Assess - await expect(handler(event, context)).rejects.toThrow(); - - expect(debugSpy).toHaveBeenCalledTimes(1); - const log = JSON.parse(debugSpy.mock.calls[0][0]); - expect(log).toStrictEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', - level: 'DEBUG', - message: 'This is a DEBUG log with both pesistent and temporary keys', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - foo: 'bar', - biz: 'baz', - }) - ); - - expect(logger).toEqual( - expect.objectContaining({ - persistentLogAttributes: { - foo: 'bar', - }, - temporaryLogAttributes: {}, - }) - ); - - debugSpy.mockRestore(); - }); - - test('when logEvent is enabled, it logs the event in the first log', async () => { - // Prepare - const logger = new Logger({ - logLevel: LogLevel.DEBUG, - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - class LambdaFunction implements LambdaInterface { - @logger.injectLambdaContext({ logEvent: true }) - public async handler( - _event: TEvent, - _context: Context - ): Promise { - return; - } - } - const handlerClass = new LambdaFunction(); - const handler = handlerClass.handler.bind(handlerClass); - - // Act - await handler(event, context); - - // Assess - expect(consoleSpy).toHaveBeenCalledTimes(1); - const log = JSON.parse(consoleSpy.mock.calls[0][0]); - expect(log).toStrictEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - 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', - event: { - foo: 'bar', - bar: 'baz', - }, - }) - ); - }); - - test('when logEvent is enabled via POWERTOOLS_LOGGER_LOG_EVENT env var, it logs the event', async () => { - // Prepare - process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'true'; - const logger = new Logger({ - logLevel: 'DEBUG', - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - class LambdaFunction implements LambdaInterface { - @logger.injectLambdaContext() - public async handler( - _event: TEvent, - _context: Context - ): Promise { - return; - } - } - const handlerClass = new LambdaFunction(); - const handler = handlerClass.handler.bind(handlerClass); - - // Act - await handler(event, context); - - // Assess - expect(consoleSpy).toHaveBeenCalledTimes(1); - const log = JSON.parse(consoleSpy.mock.calls[0][0]); - expect(log).toStrictEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - 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', - event: { - foo: 'bar', - bar: 'baz', - }, - }) - ); - }); - - test('it preserves the value of `this` of the decorated method/class', async () => { - // Prepare - const logger = new Logger({ - logLevel: 'DEBUG', - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - class LambdaFunction implements LambdaInterface { - private readonly memberVariable: string; - - public constructor(memberVariable: string) { - this.memberVariable = memberVariable; - } - - @logger.injectLambdaContext() - public async handler( - _event: TEvent, - _context: Context - ): Promise { - this.dummyMethod(); - - return; - } - - private dummyMethod(): void { - logger.info({ message: `memberVariable:${this.memberVariable}` }); - } - } - const lambda = new LambdaFunction('someValue'); - const handler = lambda.handler.bind(lambda); - - // Act - await handler({}, context); - - // Assess - expect(consoleSpy).toHaveBeenCalledTimes(1); - const log = JSON.parse(consoleSpy.mock.calls[0][0]); - expect(log).toStrictEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - 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', - }) - ); - }); - - test('it awaits the decorated method correctly', async () => { - // Prepare - const logger = new Logger({ - logLevel: 'DEBUG', - }); - const resetKeysSpy = jest.spyOn(logger, 'resetKeys'); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - class LambdaFunction implements LambdaInterface { - @logger.injectLambdaContext({ clearState: true }) - public async handler( - _event: unknown, - _context: unknown - ): Promise { - await this.dummyMethod(); - logger.info('This is a DEBUG log'); - - return; - } - - private async dummyMethod(): Promise { - return; - } - } - const lambda = new LambdaFunction(); - const handler = lambda.handler.bind(lambda); - - // Act - await handler({}, context); - - // Assess - expect(consoleSpy).toHaveBeenCalledTimes(1); - // Here we assert that the logger.info method is called before the cleanup function that should always - // be called ONLY after the handler has returned. If logger.info is called after the cleanup function - // it means the decorator is NOT awaiting the handler which would cause the test to fail. - expect(consoleSpy.mock.invocationCallOrder[0]).toBeLessThan( - resetKeysSpy.mock.invocationCallOrder[0] - ); - }); - - test('when logEvent and clearState are both TRUE, and the logger has persistent attributes, any key added with appendKeys() in the handler is cleared properly', async () => { - // Prepare - const logger = new Logger({ - persistentKeys: { - version: '1.0.0', - }, - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - class LambdaFunction implements LambdaInterface { - @logger.injectLambdaContext({ clearState: true, logEvent: true }) - public async handler( - event: { foo: string }, - _context: unknown - ): Promise { - logger.appendKeys({ foo: event.foo }); - - return; - } - } - const lambda = new LambdaFunction(); - const handler = lambda.handler.bind(lambda); - - // Act - await handler({ foo: 'bar' }, {} as Context); - await handler({ foo: 'baz' }, {} as Context); - await handler({ foo: 'biz' }, {} as Context); - await handler({ foo: 'buz' }, {} as Context); - await handler({ foo: 'boz' }, {} as Context); - - expect(consoleSpy).toBeCalledTimes(5); - for (let i = 1; i === 5; i++) { - expect(consoleSpy).toHaveBeenNthCalledWith( - i, - expect.stringContaining('"message":"Lambda invocation event"') - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - i, - expect.stringContaining('"version":"1.0.0"') - ); - } - expect(consoleSpy).toHaveBeenNthCalledWith( - 2, - expect.not.stringContaining('"foo":"bar"') - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - 3, - expect.not.stringContaining('"foo":"baz"') - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - 4, - expect.not.stringContaining('"foo":"biz"') - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - 5, - expect.not.stringContaining('"foo":"buz"') - ); - }); - }); - - describe('Method: createChild', () => { - test('child and grandchild loggers should have all the options of its ancestor', () => { - // Prepare - const INDENTATION = LogJsonIndent.COMPACT; - const loggerOptions = { - serviceName: 'parent-service-name', - sampleRateValue: 0, - }; - const parentLogger = new Logger(loggerOptions); - - // Act - const childLoggerOptions = { sampleRateValue: 1 }; - const childLogger = parentLogger.createChild(childLoggerOptions); - - const grandchildLoggerOptions = { serviceName: 'grandchild-logger-name' }; - const grandchildLogger = childLogger.createChild(grandchildLoggerOptions); - - // Assess - expect(parentLogger === childLogger).toBe(false); - expect(childLogger === grandchildLogger).toBe(false); - expect(parentLogger === grandchildLogger).toBe(false); - - expect(parentLogger).toEqual({ - console: expect.objectContaining({ - debug: expect.any(Function), - error: expect.any(Function), - info: expect.any(Function), - warn: expect.any(Function), - }), - coldStart: true, - customConfigService: undefined, - defaultServiceName: 'service_undefined', - envVarsService: expect.any(EnvironmentVariablesService), - logEvent: false, - logIndentation: INDENTATION, - logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: logLevelThresholds.DEBUG, - logLevelThresholds: { - ...logLevelThresholds, - }, - persistentLogAttributes: {}, - temporaryLogAttributes: {}, - powertoolsLogData: { - awsRegion: 'eu-west-1', - environment: '', - sampleRateValue: 0, - serviceName: 'parent-service-name', - }, - }); - - expect(childLogger).toEqual({ - console: expect.objectContaining({ - debug: expect.any(Function), - error: expect.any(Function), - info: expect.any(Function), - warn: expect.any(Function), - }), - coldStart: true, - customConfigService: undefined, - defaultServiceName: 'service_undefined', - envVarsService: expect.any(EnvironmentVariablesService), - logEvent: false, - logIndentation: INDENTATION, - logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: logLevelThresholds.DEBUG, - logLevelThresholds: { - ...logLevelThresholds, - }, - persistentLogAttributes: {}, - temporaryLogAttributes: {}, - powertoolsLogData: { - awsRegion: 'eu-west-1', - environment: '', - sampleRateValue: 1, - serviceName: 'parent-service-name', - }, - }); - - expect(grandchildLogger).toEqual({ - console: expect.objectContaining({ - debug: expect.any(Function), - error: expect.any(Function), - info: expect.any(Function), - warn: expect.any(Function), - }), - coldStart: true, - customConfigService: undefined, - defaultServiceName: 'service_undefined', - envVarsService: expect.any(EnvironmentVariablesService), - logEvent: false, - logIndentation: INDENTATION, - logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: logLevelThresholds.DEBUG, - logLevelThresholds: { - ...logLevelThresholds, - }, - persistentLogAttributes: {}, - temporaryLogAttributes: {}, - powertoolsLogData: { - awsRegion: 'eu-west-1', - environment: '', - sampleRateValue: 1, - serviceName: 'grandchild-logger-name', - }, - }); - }); - - test('child logger should be a DISTINCT clone of the logger instance', () => { - // Prepare - const INDENTATION = LogJsonIndent.COMPACT; - const parentLogger = new Logger(); - - // Act - const childLogger = parentLogger.createChild(); - - const optionsWithPermanentAttributes = { - persistentLogAttributes: { - extra: - 'This is an attribute that will be logged only by the child logger', - }, - }; - const childLoggerWithPermanentAttributes = parentLogger.createChild( - optionsWithPermanentAttributes - ); - - const optionsWithSampleRateEnabled = { - sampleRateValue: 1, - }; - const childLoggerWithSampleRateEnabled = parentLogger.createChild( - optionsWithSampleRateEnabled - ); - - const optionsWithErrorLogLevel: ConstructorOptions = { - logLevel: 'ERROR', - }; - const childLoggerWithErrorLogLevel = parentLogger.createChild( - optionsWithErrorLogLevel - ); - - // Assess - expect(parentLogger === childLogger).toBe(false); - expect(childLogger).toEqual({ - ...parentLogger, - console: expect.objectContaining({ - debug: expect.any(Function), - error: expect.any(Function), - info: expect.any(Function), - warn: expect.any(Function), - }), - }); - expect(parentLogger === childLoggerWithPermanentAttributes).toBe(false); - expect(parentLogger === childLoggerWithSampleRateEnabled).toBe(false); - expect(parentLogger === childLoggerWithErrorLogLevel).toBe(false); - - expect(parentLogger).toEqual({ - console: expect.objectContaining({ - debug: expect.any(Function), - error: expect.any(Function), - info: expect.any(Function), - warn: expect.any(Function), - }), - coldStart: true, - customConfigService: undefined, - defaultServiceName: 'service_undefined', - envVarsService: expect.any(EnvironmentVariablesService), - logEvent: false, - logIndentation: INDENTATION, - logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: logLevelThresholds.DEBUG, - logLevelThresholds: { - ...logLevelThresholds, - }, - persistentLogAttributes: {}, - temporaryLogAttributes: {}, - powertoolsLogData: { - awsRegion: 'eu-west-1', - environment: '', - sampleRateValue: 0, - serviceName: 'hello-world', - }, - }); - - expect(childLoggerWithPermanentAttributes).toEqual({ - console: expect.objectContaining({ - debug: expect.any(Function), - error: expect.any(Function), - info: expect.any(Function), - warn: expect.any(Function), - }), - coldStart: true, - customConfigService: undefined, - defaultServiceName: 'service_undefined', - envVarsService: expect.any(EnvironmentVariablesService), - logEvent: false, - logIndentation: INDENTATION, - logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: logLevelThresholds.DEBUG, - logLevelThresholds: { - ...logLevelThresholds, - }, - persistentLogAttributes: { - extra: - 'This is an attribute that will be logged only by the child logger', - }, - temporaryLogAttributes: {}, - powertoolsLogData: { - awsRegion: 'eu-west-1', - environment: '', - sampleRateValue: 0, - serviceName: 'hello-world', - }, - }); - - expect(childLoggerWithSampleRateEnabled).toEqual({ - console: expect.objectContaining({ - debug: expect.any(Function), - error: expect.any(Function), - info: expect.any(Function), - warn: expect.any(Function), - }), - coldStart: true, - customConfigService: undefined, - defaultServiceName: 'service_undefined', - envVarsService: expect.any(EnvironmentVariablesService), - logEvent: false, - logIndentation: INDENTATION, - logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: logLevelThresholds.DEBUG, - logLevelThresholds: { - ...logLevelThresholds, - }, - persistentLogAttributes: {}, - temporaryLogAttributes: {}, - powertoolsLogData: { - awsRegion: 'eu-west-1', - environment: '', - sampleRateValue: 1, - serviceName: 'hello-world', - }, - }); - - expect(childLoggerWithErrorLogLevel).toEqual({ - console: expect.objectContaining({ - debug: expect.any(Function), - error: expect.any(Function), - info: expect.any(Function), - warn: expect.any(Function), - }), - coldStart: true, - customConfigService: undefined, - defaultServiceName: 'service_undefined', - envVarsService: expect.any(EnvironmentVariablesService), - logEvent: false, - logIndentation: INDENTATION, - logFormatter: expect.any(PowertoolsLogFormatter), - logLevel: logLevelThresholds.ERROR, - logLevelThresholds: { - ...logLevelThresholds, - }, - persistentLogAttributes: {}, - temporaryLogAttributes: {}, - powertoolsLogData: { - awsRegion: 'eu-west-1', - environment: '', - sampleRateValue: 0, - serviceName: 'hello-world', - }, - }); - }); - - test('child logger should have same keys in persistentLogAttributes as its parent', () => { - // Prepare - const parentLogger = new Logger(); - const childLogger = parentLogger.createChild(); - - // Act - parentLogger.appendPersistentKeys({ - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - test_key: 'key-for-test', - }); - const childLoggerWithKeys = parentLogger.createChild(); - - // Assess - expect(childLogger.getPersistentLogAttributes()).toEqual({}); - - expect(childLoggerWithKeys.getPersistentLogAttributes()).toEqual({ - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - test_key: 'key-for-test', - }); - - expect(parentLogger.getPersistentLogAttributes()).toEqual({ - aws_account_id: '123456789012', - aws_region: 'eu-west-1', - logger: { - name: 'aws-lambda-powertool-typescript', - version: '0.2.4', - }, - test_key: 'key-for-test', - }); - }); - - test('child logger should have same context as its parent', () => { - // Prepare - const parentLogger = new Logger(); - - // Act - parentLogger.addContext(context); - const childLoggerWithContext = parentLogger.createChild(); - - // Assess - expect(childLoggerWithContext).toEqual( - expect.objectContaining({ - coldStart: false, // This is now false because the `coldStart` attribute has been already accessed once by the `addContext` method - powertoolsLogData: { - awsRegion: 'eu-west-1', - environment: '', - lambdaContext: { - awsRequestId: 'c6af9ac6-7b61-11e6-9a41-93e812345678', - coldStart: true, - functionName: 'foo-bar-function', - functionVersion: '$LATEST', - invokedFunctionArn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - memoryLimitInMB: '128', - }, - sampleRateValue: 0, - serviceName: 'hello-world', - }, - }) - ); - }); - - test('child logger should have the same logFormatter as its parent', () => { - // Prepare - class MyCustomLogFormatter extends PowertoolsLogFormatter {} - const parentLogger = new Logger({ - logFormatter: new MyCustomLogFormatter(), - }); - - // Act - const childLoggerWithParentLogFormatter = parentLogger.createChild(); - - // Assess - expect(childLoggerWithParentLogFormatter).toEqual( - expect.objectContaining({ - logFormatter: expect.any(MyCustomLogFormatter), - }) - ); - }); - - test('child logger with custom logFormatter in options should have provided logFormatter', () => { - // Prepare - class MyCustomLogFormatter extends PowertoolsLogFormatter {} - const parentLogger = new Logger(); - - // Act - const childLoggerWithCustomLogFormatter = parentLogger.createChild({ - logFormatter: new MyCustomLogFormatter(), - }); - - // Assess - expect(parentLogger).toEqual( - expect.objectContaining({ - logFormatter: expect.any(PowertoolsLogFormatter), - }) - ); - - expect(childLoggerWithCustomLogFormatter).toEqual( - expect.objectContaining({ - logFormatter: expect.any(MyCustomLogFormatter), - }) - ); - }); - - test('child logger should have exact same attributes as the parent logger created with all non-default options', () => { - // Prepare - class MyCustomLogFormatter extends PowertoolsLogFormatter {} - class MyCustomEnvironmentVariablesService extends EnvironmentVariablesService {} - - const options: ConstructorOptions = { - logLevel: 'ERROR', - serviceName: 'test-service-name', - sampleRateValue: 1, - logFormatter: new MyCustomLogFormatter(), - customConfigService: new MyCustomEnvironmentVariablesService(), - persistentLogAttributes: { - aws_account_id: '1234567890', - aws_region: 'eu-west-1', - }, - environment: 'local', - }; - const parentLogger = new Logger(options); - - // Act - const childLogger = parentLogger.createChild(); - - // Assess - expect(childLogger).toEqual({ - ...parentLogger, - console: expect.objectContaining({ - debug: expect.any(Function), - error: expect.any(Function), - info: expect.any(Function), - warn: expect.any(Function), - }), - }); - - expect(childLogger).toEqual( - expect.objectContaining({ - logFormatter: expect.any(MyCustomLogFormatter), - }) - ); - - expect(childLogger).toEqual( - expect.objectContaining({ - customConfigService: expect.any(MyCustomEnvironmentVariablesService), - }) - ); - }); - }); - - describe('Method: logEventIfEnabled', () => { - test('When the feature is disabled, it DOES NOT log the event', () => { - // Prepare - const logger = new Logger(); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - // Act - logger.logEventIfEnabled(event); - - // Assess - expect(consoleSpy).toBeCalledTimes(0); - }); - - test('When the feature is enabled via overwrite flag, it DOES log the event', () => { - // Prepare - const event = { - something: 'happened!', - }; - const logger = new Logger(); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - // Act - logger.logEventIfEnabled(event, true); - - // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - 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', - event: { - something: 'happened!', - }, - }) - ); - }); - }); - - describe('Feature: Pretty indentation for a local or non-production environment', () => { - test('when the `POWERTOOLS_DEV` env var is SET it makes log output has multiple lines', () => { - // Prepare - process.env.POWERTOOLS_DEV = 'true'; - const INDENTATION = LogJsonIndent.PRETTY; - const logger = new Logger(); - const consoleSpy = jest.spyOn(console, 'info').mockImplementation(); - - // Act - logger.info('Message with pretty identation'); - - // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify( - { - 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', - }, - null, - INDENTATION - ) - ); - }); - - test('when the `POWERTOOLS_DEV` env var is NOT SET it makes log output as one-liner', () => { - // Prepare - const logger = new Logger(); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - // Act - logger.info('Message without pretty identation'); - - // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - 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', - }) - ); - }); - }); - - describe('Method: setConsole()', () => { - test('When the `POWERTOOLS_DEV` env var is SET console object is set to the global node console otherwise to the instance of the internal version of console', () => { - // Prepare - const logger = new Logger(); - process.env.POWERTOOLS_DEV = 'true'; - const devLogger = new Logger(); - - // Assess - expect(devLogger).toEqual({ - ...devLogger, - console: console, - }); - // since instances of a class are not equal objects, - // we assert the opposite – console is not the global node object - expect(logger).not.toEqual({ - ...logger, - console: console, - }); - }); - }); - - describe('Method: setLogLevel', () => { - test('it sets the correct log level provided', () => { - // Prepare - const logger = new Logger(); - - // Act - logger.setLogLevel(LogLevel.ERROR); - - // Assess - expect(logger.level).toBe(20); - expect(logger.getLevelName()).toBe('ERROR'); - }); - - test('it throws when passed an invalid log level name', () => { - // Prepare - const logger = new Logger(); - - // Act & Assess - expect(() => logger.setLogLevel('INVALID' as LogLevelType)).toThrow( - 'Invalid log level: INVALID' - ); - }); - - test('it uses log level set by ALC & emits a warning when setting a higher log level than ALC', () => { - // Prepare - process.env.AWS_LAMBDA_LOG_LEVEL = 'ERROR'; - process.env.LOG_LEVEL = undefined; - process.env.POWERTOOLS_LOG_LEVEL = undefined; - const logger = new Logger(); - const warningSpy = jest.spyOn(logger, 'warn'); - - // Act - logger.setLogLevel('WARN'); - - // Assess - expect(logger.level).toBe(20); - expect(logger.getLevelName()).toBe('ERROR'); - expect(warningSpy).toHaveBeenCalledTimes(1); - expect(warningSpy).toHaveBeenCalledWith( - 'Current log level (WARN) does not match AWS Lambda Advanced Logging Controls minimum log level (ERROR). This can lead to data loss, consider adjusting them.' - ); - }); - - test('it uses log level set by ALC & emits a warning when initializing with a higher log level than ALC', () => { - // Prepare - process.env.AWS_LAMBDA_LOG_LEVEL = 'INFO'; - process.env.LOG_LEVEL = undefined; - process.env.POWERTOOLS_LOG_LEVEL = undefined; - // Since the buffer is private and we are bypassing the public warn method, we need to spy on the console.warn - process.env.POWERTOOLS_DEV = 'true'; - const warningSpy = jest.spyOn(console, 'warn').mockImplementation(); - - // Act - const logger = new Logger({ logLevel: 'DEBUG' }); - - // Assess - expect(logger.level).toBe(12); - expect(logger.getLevelName()).toBe('INFO'); - expect(warningSpy).toHaveBeenCalledTimes(1); - expect(warningSpy).toHaveBeenCalledWith( - expect.stringContaining( - 'Current log level (DEBUG) does not match AWS Lambda Advanced Logging Controls minimum log level (INFO). This can lead to data loss, consider adjusting them.' - ) - ); - }); - }); - - describe('Feature: Sampling debug logs', () => { - 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(logLevelThresholds.DEBUG); - 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(logLevelThresholds.DEBUG); - 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: LogLevel.ERROR, - }); - - // Assess - expect(logger.level).toBe(logLevelThresholds.DEBUG); - 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( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - // 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( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - // 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({ logLevel: 'WARN' }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'debug' - ); - // Act - logger.debug('foo'); - - // Assess - expect(consoleSpy).toHaveBeenCalledTimes(2); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ - level: 'DEBUG', - message: 'Setting log level to DEBUG due to sampling rate', - sampling_rate: 1, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }) - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - 2, - 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( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - // 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: LogLevel.INFO, - sampleRateValue: 42, - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - // 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( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - // 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( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - // 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('logs a DEBUG log when the sample rate sets the level to DEBUG', () => { - // Prepare - // Since the buffer is private and we are bypassing the public warn method, we need to spy on the console.warn - process.env.POWERTOOLS_DEV = 'true'; - const debugSpy = jest.spyOn(console, 'debug').mockImplementation(); - - // Act - new Logger({ sampleRateValue: 1, logLevel: 'WARN' }); - - // Assess - expect(debugSpy).toHaveBeenCalledTimes(1); - expect(debugSpy).toHaveBeenCalledWith( - expect.stringContaining( - 'Setting log level to DEBUG due to sampling rate' - ) - ); - }); - - describe('Method: refreshSampleRateCalculation', () => { - test('when sample rate calculation is refreshed, it DOES NOT overwrite the sample rate value', () => { - // Prepare - const logger = new Logger({ - logLevel: LogLevel.INFO, - sampleRateValue: 1, - }); - const consoleSpy = jest.spyOn( - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - logger['console'], - 'info' - ); - // 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 - }); - - 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++; - } - } - - // Assess - expect(logLevelChangedToDebug).toBeGreaterThanOrEqual(minExpected); - expect(logLevelChangedToDebug).toBeLessThanOrEqual(maxExpected); - }); - }); - }); -}); diff --git a/packages/logger/tests/unit/configFromEnv.test.ts b/packages/logger/tests/unit/configFromEnv.test.ts new file mode 100644 index 0000000000..905f343e66 --- /dev/null +++ b/packages/logger/tests/unit/configFromEnv.test.ts @@ -0,0 +1,200 @@ +/** + * Test Logger EnvironmentVariablesService class + * + * @group unit/logger/config + */ +import { beforeEach, describe, expect, it, jest } from '@jest/globals'; +import { EnvironmentVariablesService } from '../../src/config/EnvironmentVariablesService.js'; + +describe('Class: EnvironmentVariablesService', () => { + const ENVIRONMENT_VARIABLES = process.env; + + beforeEach(() => { + jest.resetModules(); + process.env = { ...ENVIRONMENT_VARIABLES }; + }); + + it('returns the value of the environment variable AWS_LAMBDA_LOG_LEVEL and aliases it as needed', () => { + // Prepare + process.env.AWS_LAMBDA_LOG_LEVEL = 'FATAL'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getAwsLogLevel(); + + // Assess + // The Advanced Logging Controls feature in AWS Lambda supports the `FATAL` log level, which we don't support + // and instead map to `CRITICAL` as per the existing log levels. In this test, we expect the value to be `CRITICAL`. + expect(value).toEqual('CRITICAL'); + }); + + it('returns the value of the environment variable AWS_REGION', () => { + // Prepare + process.env.AWS_REGION = 'us-east-1'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getAwsRegion(); + + // Assess + expect(value).toEqual('us-east-1'); + }); + + it('returns the value of the environment variable AWS_REGION', () => { + // Prepare + process.env.ENVIRONMENT = 'stage'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getCurrentEnvironment(); + + // Assess + expect(value).toEqual('stage'); + }); + + it('returns the value of the environment variable AWS_LAMBDA_FUNCTION_MEMORY_SIZE', () => { + // Prepare + process.env.AWS_LAMBDA_FUNCTION_MEMORY_SIZE = '123456'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getFunctionMemory(); + + // Assess + expect(value).toBe(123456); + }); + + it('returns the value of the environment variable AWS_LAMBDA_FUNCTION_NAME', () => { + // Prepare + process.env.AWS_LAMBDA_FUNCTION_NAME = 'my-lambda-function'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getFunctionName(); + + // Assess + expect(value).toEqual('my-lambda-function'); + }); + + it('returns the value of the environment variable AWS_LAMBDA_FUNCTION_VERSION', () => { + // Prepare + process.env.AWS_LAMBDA_FUNCTION_VERSION = '1.4.0'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getFunctionVersion(); + + // Assess + expect(value).toEqual('1.4.0'); + }); + + it('returns true if the environment variable POWERTOOLS_LOGGER_LOG_EVENT is "true"', () => { + // Prepare + process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'true'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getLogEvent(); + + // Assess + expect(value).toEqual(true); + }); + + it('returns false if the environment variable POWERTOOLS_LOGGER_LOG_EVENT is "false"', () => { + // Prepare + process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'false'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getLogEvent(); + + // Assess + expect(value).toEqual(false); + }); + + it('returns false if the environment variable POWERTOOLS_LOGGER_LOG_EVENT is "somethingsilly"', () => { + // Prepare + process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'somethingsilly'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getLogEvent(); + + // Assess + expect(value).toEqual(false); + }); + + it('returns the value of the environment variable LOG_LEVEL when POWERTOOLS_LOG_LEVEL is not set', () => { + // Prepare + process.env.POWERTOOLS_LOG_LEVEL = undefined; + process.env.LOG_LEVEL = 'ERROR'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getLogLevel(); + + // Assess + expect(value).toEqual('ERROR'); + }); + + it('returns the value of the environment variable POWERTOOLS_LOG_LEVEL when LOG_LEVEL one is also set', () => { + // Prepare + process.env.LOG_LEVEL = 'WARN'; + process.env.POWERTOOLS_LOG_LEVEL = 'INFO'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getLogLevel(); + + // Assess + expect(value).toEqual('INFO'); + }); + + it('returns an empty value if neither POWERTOOLS_LOG_LEVEL nor LOG_LEVEL are set', () => { + // Prepare + process.env.LOG_LEVEL = undefined; + process.env.POWERTOOLS_LOG_LEVEL = undefined; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getLogLevel(); + + // Assess + expect(value).toEqual(''); + }); + + it('returns the value of the environment variable POWERTOOLS_LOGGER_SAMPLE_RATE', () => { + // Prepare + process.env.POWERTOOLS_LOGGER_SAMPLE_RATE = '0.01'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getSampleRateValue(); + + // Assess + expect(value).toEqual(0.01); + }); + + it('returns the value of the TZ environment variable when set', () => { + // Prepare + process.env.TZ = 'Europe/London'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getTimezone(); + + // Assess + expect(value).toEqual('Europe/London'); + }); + + it('returns the default UTC value when no TZ is set', () => { + // Prepare + const service = new EnvironmentVariablesService(); + + // Act + const value = service.getTimezone(); + + // Assess + expect(value).toEqual('UTC'); + }); +}); diff --git a/packages/logger/tests/unit/formatter/PowertoolsLogFormatter.test.ts b/packages/logger/tests/unit/formatter/PowertoolsLogFormatter.test.ts deleted file mode 100644 index 810bb2f3e0..0000000000 --- a/packages/logger/tests/unit/formatter/PowertoolsLogFormatter.test.ts +++ /dev/null @@ -1,578 +0,0 @@ -/** - * Test Logger formatter - * - * @group unit/logger/logFormatter - */ -import { AssertionError } from 'node:assert'; -import { EnvironmentVariablesService } from '../../../src/config/EnvironmentVariablesService.js'; -import { PowertoolsLogFormatter } from '../../../src/formatter/PowertoolsLogFormatter.js'; -import { LogItem } from '../../../src/index.js'; -import type { LogAttributes } from '../../../src/types/Log.js'; -import type { UnformattedAttributes } from '../../../src/types/Logger.js'; - -describe('Class: PowertoolsLogFormatter', () => { - const ENVIRONMENT_VARIABLES = process.env; - - beforeEach(() => { - const mockDate = new Date(1466424490000); - jest.useFakeTimers().setSystemTime(mockDate); - process.env = { ...ENVIRONMENT_VARIABLES }; - }); - - afterAll(() => { - process.env = ENVIRONMENT_VARIABLES; - jest.useRealTimers(); - }); - - describe('Method: formatAttributes', () => { - test('when optional parameters DO NOT have a value set, it returns an object with expected structure and values', () => { - // Prepare - const formatter = new PowertoolsLogFormatter(); - const unformattedAttributes: UnformattedAttributes = { - sampleRateValue: 0, - awsRegion: 'eu-west-1', - environment: '', - serviceName: 'hello-world', - xRayTraceId: '1-5759e988-bd862e3fe1be46a994272793', - logLevel: 'WARN', - timestamp: new Date(), - message: 'This is a WARN log', - }; - const additionalLogAttributes: LogAttributes = {}; - - // Act - const value = formatter.formatAttributes( - unformattedAttributes, - additionalLogAttributes - ); - - // Assess - expect(value.getAttributes()).toEqual({ - cold_start: undefined, - function_arn: undefined, - function_memory_size: undefined, - function_name: undefined, - function_request_id: undefined, - level: 'WARN', - message: 'This is a WARN log', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }); - expect(value).toBeInstanceOf(LogItem); - }); - - test('when optional parameters DO have a value set, it returns an object with expected structure and values', () => { - // Prepare - const formatter = new PowertoolsLogFormatter(); - const unformattedAttributes: UnformattedAttributes = { - sampleRateValue: 0.25, - awsRegion: 'eu-west-1', - environment: 'prod', - serviceName: 'hello-world', - xRayTraceId: '1-5759e988-bd862e3fe1be46a994272793', - logLevel: 'WARN', - timestamp: new Date(), - message: 'This is a WARN log', - error: new Error('Something happened!'), - lambdaContext: { - functionName: 'my-lambda-function', - memoryLimitInMB: '123', - functionVersion: '1.23.3', - coldStart: true, - invokedFunctionArn: - 'arn:aws:lambda:eu-west-1:123456789012:function:Example', - awsRequestId: 'abcdefg123456789', - }, - }; - const additionalLogAttributes: LogAttributes = {}; - - // Act - const value = formatter.formatAttributes( - unformattedAttributes, - additionalLogAttributes - ); - - // Assess - expect(value.getAttributes()).toEqual({ - cold_start: true, - function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:Example', - function_memory_size: '123', - function_name: 'my-lambda-function', - function_request_id: 'abcdefg123456789', - level: 'WARN', - message: 'This is a WARN log', - sampling_rate: 0.25, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }); - }); - }); - - describe('Method: formatError', () => { - test('when an error of type Error is passed, it returns an object with expected structure and values', () => { - // Prepare - const formatter = new PowertoolsLogFormatter(); - - // Act & Assess - const formattedError = formatter.formatError(new Error('Ouch!')); - expect(formattedError).toEqual({ - location: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+$/), - message: 'Ouch!', - name: 'Error', - stack: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+:\d+/), - }); - }); - - test('when an error of type ReferenceError is passed, it returns an object with expected structure and values', () => { - // Prepare - const formatter = new PowertoolsLogFormatter(); - - // Act & Assess - const formattedReferenceError = formatter.formatError( - new ReferenceError('doesNotExist is not defined') - ); - expect(formattedReferenceError).toEqual({ - location: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+$/), - message: 'doesNotExist is not defined', - name: 'ReferenceError', - stack: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+:\d+/), - }); - }); - - test('when an error of type AssertionError is passed, it returns an object with expected structure and values', () => { - // Prepare - const formatter = new PowertoolsLogFormatter(); - - // Act & Assess - const formattedAssertionError = formatter.formatError( - new AssertionError({ - message: 'Expected values to be strictly equal', - actual: 1, - expected: 2, - operator: 'strictEqual', - }) - ); - expect(formattedAssertionError).toEqual({ - location: expect.stringMatching( - /(node:)*internal\/assert\/assertion_error(.js)*:\d+$/ - ), - message: expect.stringMatching(/Expected values to be strictly equal/), - name: 'AssertionError', - stack: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+:\d+/), - }); - }); - - test('when an error of type RangeError is passed, it returns an object with expected structure and values', () => { - // Prepare - const formatter = new PowertoolsLogFormatter(); - - // Act & Assess - const formattedRangeError = formatter.formatError( - new RangeError('The argument must be between 10 and 20') - ); - expect(formattedRangeError).toEqual({ - location: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+/), - message: 'The argument must be between 10 and 20', - name: 'RangeError', - stack: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+:\d+/), - }); - }); - - test('when an error of type ReferenceError is passed, it returns an object with expected structure and values', () => { - // Prepare - const formatter = new PowertoolsLogFormatter(); - - // Act & Assess - const formattedError = formatter.formatError( - new ReferenceError('foo is not defined') - ); - expect(formattedError).toEqual({ - location: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+/), - message: 'foo is not defined', - name: 'ReferenceError', - stack: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+:\d+/), - }); - }); - - test('when an error of type SyntaxError is passed, it returns an object with expected structure and values', () => { - // Prepare - const formatter = new PowertoolsLogFormatter(); - - // Act & Assess - const formattedSyntaxError = formatter.formatError( - new SyntaxError(`Unexpected identifier 'bar'`) - ); - expect(formattedSyntaxError).toEqual({ - location: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+/), - message: `Unexpected identifier 'bar'`, - name: 'SyntaxError', - stack: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+:\d+/), - }); - }); - - test('when an error of type TypeError is passed, it returns an object with expected structure and values', () => { - // Prepare - const formatter = new PowertoolsLogFormatter(); - - // Act & Assess - const formattedTypeError = formatter.formatError( - new TypeError(`Cannot read property 'foo' of null`) - ); - expect(formattedTypeError).toEqual({ - location: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+/), - message: expect.stringMatching(/Cannot read propert/), - name: 'TypeError', - stack: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+:\d+/), - }); - }); - - test('when an error of type URIError is passed, it returns an object with expected structure and values', () => { - // Prepare - const formatter = new PowertoolsLogFormatter(); - - // Act & Assess - const formattedURIError = formatter.formatError( - new URIError('URI malformed') - ); - expect(formattedURIError).toEqual({ - location: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+/), - message: 'URI malformed', - name: 'URIError', - stack: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+:\d+/), - }); - }); - - test('when an error with cause of type Error is formatted, the cause key is included and formatted', () => { - // Prepare - const formatter = new PowertoolsLogFormatter(); - class ErrorWithCause extends Error { - public cause?: Error; - public constructor(message: string, options?: { cause: Error }) { - super(message); - this.cause = options?.cause; - } - } - - // Act - const formattedURIError = formatter.formatError( - new ErrorWithCause('foo', { cause: new Error('bar') }) - ); - - // Assess - expect(formattedURIError).toEqual({ - location: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+/), - message: 'foo', - name: 'Error', - stack: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+:\d+/), - cause: { - location: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+/), - message: 'bar', - name: 'Error', - stack: expect.stringMatching( - /PowertoolsLogFormatter.test.ts:\d+:\d+/ - ), - }, - }); - }); - - test('when an error with cause of type other than Error is formatted, the cause key is included as-is', () => { - // Prepare - const formatter = new PowertoolsLogFormatter(); - class ErrorWithCause extends Error { - public cause?: unknown; - public constructor(message: string, options?: { cause: unknown }) { - super(message); - this.cause = options?.cause; - } - } - - // Act - const formattedURIError = formatter.formatError( - new ErrorWithCause('foo', { cause: 'bar' }) - ); - - // Assess - expect(formattedURIError).toEqual({ - location: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+/), - message: 'foo', - name: 'Error', - stack: expect.stringMatching(/PowertoolsLogFormatter.test.ts:\d+:\d+/), - cause: 'bar', - }); - }); - }); - - describe('Method: formatTimestamp', () => { - test('it returns a datetime value ISO 8601 compliant', () => { - // Prepare - const formatter = new PowertoolsLogFormatter(); - - // Act - const timestamp = formatter.formatTimestamp(new Date()); - - // Assess - expect(timestamp).toEqual('2016-06-20T12:08:10.000Z'); - }); - - test('it formats the timestamp to ISO 8601, accounting for the `America/New_York` timezone offset', () => { - // Prepare - process.env.TZ = 'America/New_York'; - /* - Difference between UTC and `America/New_York`(GMT -04.00) is 240 minutes. - The positive value indicates that `America/New_York` is behind UTC. - */ - jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(240); - const formatter = new PowertoolsLogFormatter({ - envVarsService: new EnvironmentVariablesService(), - }); - - // Act - const timestamp = formatter.formatTimestamp(new Date()); - - // Assess - expect(timestamp).toEqual('2016-06-20T08:08:10.000-04:00'); - }); - - test('it formats the timestamp to ISO 8601 with correct milliseconds for `America/New_York` timezone', () => { - // Prepare - process.env.TZ = 'America/New_York'; - const mockDate = new Date('2016-06-20T12:08:10.910Z'); - jest.useFakeTimers().setSystemTime(mockDate); - /* - Difference between UTC and `America/New_York`(GMT -04.00) is 240 minutes. - The positive value indicates that `America/New_York` is behind UTC. - */ - jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(240); - const formatter = new PowertoolsLogFormatter({ - envVarsService: new EnvironmentVariablesService(), - }); - - // Act - const timestamp = formatter.formatTimestamp(new Date()); - - // Assess - expect(timestamp).toEqual('2016-06-20T08:08:10.910-04:00'); - }); - - test('it formats the timestamp to ISO 8601, adjusting for `America/New_York` timezone, preserving milliseconds and accounting for date change', () => { - // Prepare - process.env.TZ = 'America/New_York'; - const mockDate = new Date('2016-06-20T00:08:10.910Z'); - jest.useFakeTimers().setSystemTime(mockDate); - /* - Difference between UTC and `America/New_York`(GMT -04.00) is 240 minutes. - The positive value indicates that `America/New_York` is behind UTC. - */ - jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(240); - const formatter = new PowertoolsLogFormatter({ - envVarsService: new EnvironmentVariablesService(), - }); - - // Act - const timestamp = formatter.formatTimestamp(new Date()); - - // Assess - expect(timestamp).toEqual('2016-06-19T20:08:10.910-04:00'); - }); - - test('if `envVarsService` is not set, ensures timestamp is formatted to `UTC` even with `America/New_York` timezone', () => { - // Prepare - process.env.TZ = 'America/New_York'; - /* - Difference between UTC and `America/New_York`(GMT -04.00) is 240 minutes. - The positive value indicates that `America/New_York` is behind UTC. - */ - jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(240); - const formatter = new PowertoolsLogFormatter(); - - // Act - const timestamp = formatter.formatTimestamp(new Date()); - - // Assess - expect(timestamp).toEqual('2016-06-20T12:08:10.000Z'); - }); - - test('it formats the timestamp to ISO 8601, accounting for the `Asia/Dhaka` timezone offset', () => { - // Prepare - process.env.TZ = 'Asia/Dhaka'; - /* - Difference between UTC and `Asia/Dhaka`(GMT +06.00) is 360 minutes. - The negative value indicates that `Asia/Dhaka` is ahead of UTC. - */ - jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(-360); - const formatter = new PowertoolsLogFormatter({ - envVarsService: new EnvironmentVariablesService(), - }); - - // Act - const timestamp = formatter.formatTimestamp(new Date()); - - // Assess - expect(timestamp).toEqual('2016-06-20T18:08:10.000+06:00'); - }); - - test('it formats the timestamp to ISO 8601 with correct milliseconds for `Asia/Dhaka` timezone', () => { - // Prepare - process.env.TZ = 'Asia/Dhaka'; - jest.useFakeTimers().setSystemTime(new Date('2016-06-20T12:08:10.910Z')); - /* - Difference between UTC and `Asia/Dhaka`(GMT +06.00) is 360 minutes. - The negative value indicates that `Asia/Dhaka` is ahead of UTC. - */ - jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(-360); - const formatter = new PowertoolsLogFormatter({ - envVarsService: new EnvironmentVariablesService(), - }); - - // Act - const timestamp = formatter.formatTimestamp(new Date()); - - // Assess - expect(timestamp).toEqual('2016-06-20T18:08:10.910+06:00'); - }); - - test('it formats the timestamp to ISO 8601, adjusting for `Asia/Dhaka` timezone, preserving milliseconds and accounting for date change', () => { - // Prepare - process.env.TZ = 'Asia/Dhaka'; - const mockDate = new Date('2016-06-20T20:08:10.910Z'); - jest.useFakeTimers().setSystemTime(mockDate); - /* - Difference between UTC and `Asia/Dhaka`(GMT +06.00) is 360 minutes. - The negative value indicates that `Asia/Dhaka` is ahead of UTC. - */ - jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(-360); - const formatter = new PowertoolsLogFormatter({ - envVarsService: new EnvironmentVariablesService(), - }); - - // Act - const timestamp = formatter.formatTimestamp(new Date()); - - // Assess - expect(timestamp).toEqual('2016-06-21T02:08:10.910+06:00'); - }); - - test('if `envVarsService` is not set, ensures timestamp is formatted to `UTC` even with `Asia/Dhaka` timezone', () => { - // Prepare - process.env.TZ = 'Asia/Dhaka'; - /* - Difference between UTC and `Asia/Dhaka`(GMT +06.00) is 360 minutes. - The negative value indicates that `Asia/Dhaka` is ahead of UTC. - */ - jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(-360); - const formatter = new PowertoolsLogFormatter(); - - // Act - const timestamp = formatter.formatTimestamp(new Date()); - - // Assess - expect(timestamp).toEqual('2016-06-20T12:08:10.000Z'); - }); - - test('it is using UTC timezone when env var is set to :/etc/localtime', () => { - // Prepare - process.env.TZ = ':/etc/localtime'; - - jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(0); - const formatter = new PowertoolsLogFormatter({ - envVarsService: new EnvironmentVariablesService(), - }); - - // Act - const timestamp = formatter.formatTimestamp(new Date()); - - // Assess - expect(timestamp).toEqual('2016-06-20T12:08:10.000+00:00'); - }); - }); - - describe('Method: getCodeLocation', () => { - test.each([ - { - condition: 'stack IS present', - returnExpection: - 'it returns a location for a stackframe with absolute file path', - stack: - 'Error: Things keep happening!\n' + - ' at /home/foo/bar/file-that-threw-the-error.ts:22:5\n' + - ' at SomeOther.function (/home/foo/bar/some-file.ts:154:19)', - expectedLocation: '/home/foo/bar/some-file.ts:154', - }, - { - condition: 'stack IS present', - returnExpection: - 'it returns a location for a stackframe ending with an optional backslash', - stack: - 'Error: Reference Error!\n' + - ' at /home/foo/bar/file-that-threw-the-error.ts:22:5\n' + - ' at SomeOther.function (/home/foo/bar/some-frame-with-ending-backslash.ts:154:19)\\', - expectedLocation: - '/home/foo/bar/some-frame-with-ending-backslash.ts:154', - }, - { - condition: 'stack IS present', - returnExpection: - 'it returns a location for a path containing multiple colons', - stack: - 'Error: The message failed to send\n' + - 'at REPL2:1:17\n' + - 'at Script.runInThisContext (node:vm:130:12)\n' + - '... 7 lines matching cause stack trace ...\n' + - 'at [_line] [as _line] (node:internal/readline/interface:886:18) {\n' + - '[cause]: Error: The remote HTTP server responded with a 500 status\n' + - ' at REPL1:1:15\n' + - ' at Script.runInThisContext (node:vm:130:12)\n' + - ' at REPLServer.defaultEval (node:repl:574:29)\n' + - ' at bound (node:domain:426:15)\n' + - ' at REPLServer.runBound [as eval] (node:domain:437:12)\n' + - ' at REPLServer.onLine (node:repl:902:10)\n' + - ' at REPLServer.emit (node:events:549:35)\n' + - ' at REPLServer.emit (node:domain:482:12)\n' + - ' at [_onLine] [as _onLine] (node:internal/readline/interface:425:12)\n' + - ' at [_line] [as _line] (node:internal/readline/interface:886:18) \n', - expectedLocation: 'node:vm:130', - }, - { - condition: 'stack IS present', - returnExpection: 'it returns a location for a nested path', - stack: - 'Error: unknown\n' + - 'at eval (eval at (file:///home/foo/bar/some-file.ts:1:35), :1:7)\n' + - 'at (/home/foo/bar/file-that-threw-the-error.ts:52:3)\n' + - 'at ModuleJob.run (node:internal/modules/esm/module_job:218:25)\n' + - 'at async ModuleLoader.import (node:internal/modules/esm/loader:329:24)\n' + - 'at async loadESM (node:internal/process/esm_loader:28:7)\n' + - 'at async handleMainPromise (node:internal/modules/run_main:113:12)\n', - expectedLocation: '/home/foo/bar/file-that-threw-the-error.ts:52', - }, - { - condition: 'stack IS NOT present', - returnExpection: 'it returns an empty location', - stack: undefined, - expectedLocation: '', - }, - { - condition: 'stack IS present', - returnExpection: - 'if a stackframe does not have a location, it returns an empty location', - stack: 'A weird stack trace...', - expectedLocation: '', - }, - ])( - 'when the $condition, $returnExpection', - ({ stack, expectedLocation }) => { - // Prepare - const formatter = new PowertoolsLogFormatter(); - - // Act - const errorLocation = formatter.getCodeLocation(stack); - - // Assess - expect(errorLocation).toEqual(expectedLocation); - } - ); - }); -}); diff --git a/packages/logger/tests/unit/formatters.test.ts b/packages/logger/tests/unit/formatters.test.ts new file mode 100644 index 0000000000..152bc20b24 --- /dev/null +++ b/packages/logger/tests/unit/formatters.test.ts @@ -0,0 +1,660 @@ +/** + * Test Logger formatter + * + * @group unit/logger/logFormatter + */ +import { AssertionError } from 'node:assert'; +import { + afterAll, + beforeEach, + describe, + expect, + it, + jest, +} from '@jest/globals'; +import { EnvironmentVariablesService } from '../../src/config/EnvironmentVariablesService.js'; +import { PowertoolsLogFormatter } from '../../src/formatter/PowertoolsLogFormatter.js'; +import { + LogFormatter, + LogItem, + LogLevelThreshold, + Logger, +} from '../../src/index.js'; +import type { LogAttributes, LogLevel } from '../../src/types/Log.js'; +import type { + CustomJsonReplacerFn, + UnformattedAttributes, +} from '../../src/types/Logger.js'; + +const fileNameRegexp = new RegExp(/index.js:\d+$/); +const fileNameRegexpWithLine = new RegExp(/formatters.test.ts:\d+:\d+/); +const formatter = new PowertoolsLogFormatter(); +const formatterWithEnv = new PowertoolsLogFormatter({ + envVarsService: new EnvironmentVariablesService(), +}); + +class ErrorWithCause extends Error { + public constructor(message: string, options?: { cause: unknown }) { + super(message, options); + this.name = 'ErrorWithCause'; + } +} +class ErrorWithCauseString extends Error { + public constructor(message: string, options?: { cause: string }) { + super(message, options); + this.name = 'ErrorWithCauseString'; + } +} + +process.env.POWERTOOLS_DEV = 'true'; + +const logSpy = jest.spyOn(console, 'info'); + +const logger = new Logger(); + +const jsonReplacerFn: CustomJsonReplacerFn = (_: string, value: unknown) => + value instanceof Set ? [...value] : value; +const loggerWithReplacer = new Logger({ jsonReplacerFn }); + +/** + * A custom log formatter that formats logs using only the message, log level as a number, and timestamp. + * + * @example + * ```json + * { + * "message": "This is a WARN log", + * "logLevel": 16, + * "timestamp": "2016-06-20T12:08:10.000Z" + * } + * ``` + */ +class CustomFormatter extends LogFormatter { + public formatAttributes( + attributes: UnformattedAttributes, + additionalLogAttributes: LogAttributes + ): LogItem { + const { message, logLevel, timestamp } = attributes; + const customAttributes = { + message, + logLevel: + LogLevelThreshold[logLevel.toUpperCase() as Uppercase], + timestamp, + }; + return new LogItem({ attributes: customAttributes }).addAttributes( + additionalLogAttributes + ); + } +} +const loggerWithCustomLogFormatter = new Logger({ + logFormatter: new CustomFormatter(), +}); + +describe('Formatters', () => { + const ENVIRONMENT_VARIABLES = process.env; + + beforeEach(() => { + process.env = { ...ENVIRONMENT_VARIABLES }; + const mockDate = new Date(1466424490000); + jest.useFakeTimers().setSystemTime(mockDate); + jest.resetAllMocks(); + }); + + afterAll(() => { + jest.useRealTimers(); + }); + + // #region base log keys + + it('formats the base log keys', () => { + // Prepare + const unformattedAttributes: UnformattedAttributes = { + sampleRateValue: 0, + awsRegion: 'eu-west-1', + environment: '', + serviceName: 'hello-world', + xRayTraceId: '1-5759e988-bd862e3fe1be46a994272793', + logLevel: 'WARN', + timestamp: new Date(), + message: 'This is a WARN log', + }; + const additionalLogAttributes: LogAttributes = {}; + + // Act + const value = formatter.formatAttributes( + unformattedAttributes, + additionalLogAttributes + ); + + // Assess + expect(value.getAttributes()).toEqual({ + cold_start: undefined, + function_arn: undefined, + function_memory_size: undefined, + function_name: undefined, + function_request_id: undefined, + level: 'WARN', + message: 'This is a WARN log', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }); + expect(value).toBeInstanceOf(LogItem); + }); + + // #region base log keys with context + + it('formats the base log keys with context', () => { + // Prepare + const unformattedAttributes: UnformattedAttributes = { + sampleRateValue: 0.25, + awsRegion: 'eu-west-1', + environment: 'prod', + serviceName: 'hello-world', + xRayTraceId: '1-5759e988-bd862e3fe1be46a994272793', + logLevel: 'WARN', + timestamp: new Date(), + message: 'This is a WARN log', + error: new Error('Something happened!'), + lambdaContext: { + functionName: 'my-lambda-function', + memoryLimitInMB: '123', + functionVersion: '1.23.3', + coldStart: true, + invokedFunctionArn: + 'arn:aws:lambda:eu-west-1:123456789012:function:Example', + awsRequestId: 'abcdefg123456789', + }, + }; + const additionalLogAttributes: LogAttributes = {}; + + // Act + const value = formatter.formatAttributes( + unformattedAttributes, + additionalLogAttributes + ); + + // Assess + expect(value.getAttributes()).toEqual({ + cold_start: true, + function_arn: 'arn:aws:lambda:eu-west-1:123456789012:function:Example', + function_memory_size: '123', + function_name: 'my-lambda-function', + function_request_id: 'abcdefg123456789', + level: 'WARN', + message: 'This is a WARN log', + sampling_rate: 0.25, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }); + }); + + // #region format errors + + it.each([ + { + error: new Error('Something went wrong'), + name: 'Error', + expectedFields: { + message: 'Something went wrong', + cause: undefined, + }, + }, + { + error: new ReferenceError('doesNotExist is not defined'), + name: 'ReferenceError', + expectedFields: { + message: 'doesNotExist is not defined', + cause: undefined, + }, + }, + { + error: new AssertionError({ + message: 'Expected values to be strictly equal', + actual: 1, + expected: 2, + operator: 'strictEqual', + }), + name: 'AssertionError', + expectedFields: { + location: expect.stringMatching( + /(node:)*internal\/assert\/assertion_error(.js)*:\d+$/ + ), + message: expect.stringMatching(/Expected values to be strictly equal/), + cause: undefined, + }, + }, + { + error: new RangeError('The argument must be between 10 and 20'), + name: 'RangeError', + expectedFields: { + message: 'The argument must be between 10 and 20', + cause: undefined, + }, + }, + { + error: new ReferenceError('foo is not defined'), + name: 'ReferenceError', + expectedFields: { + message: 'foo is not defined', + cause: undefined, + }, + }, + { + error: new SyntaxError(`Unexpected identifier 'bar'`), + name: 'SyntaxError', + expectedFields: { + message: `Unexpected identifier 'bar'`, + cause: undefined, + }, + }, + { + error: new TypeError(`Cannot read property 'foo' of null`), + name: 'TypeError', + expectedFields: { + message: expect.stringMatching(/Cannot read property/), + cause: undefined, + }, + }, + { + error: new URIError('URI malformed'), + name: 'URIError', + expectedFields: { + message: 'URI malformed', + cause: undefined, + }, + }, + { + error: new ErrorWithCause('foo', { cause: new Error('bar') }), + name: 'ErrorWithCause', + expectedFields: { + message: 'foo', + cause: { + location: expect.stringMatching(fileNameRegexp), + message: 'bar', + name: 'Error', + stack: expect.stringMatching(fileNameRegexpWithLine), + }, + }, + }, + { + error: new ErrorWithCauseString('foo', { cause: 'bar' }), + name: 'ErrorWithCauseString', + expectedFields: { + message: 'foo', + cause: 'bar', + }, + }, + ])('formats errors correctly ($name)', ({ error, name, expectedFields }) => { + // Act + const formattedError = formatter.formatError(error); + + // Assess + expect(formattedError).toEqual({ + location: expect.stringMatching(fileNameRegexp), + stack: expect.stringMatching(fileNameRegexpWithLine), + name, + ...expectedFields, + }); + }); + + // #region format timestamps + + it('returns a compliant ISO 8601 timestamp', () => { + // Act + const timestamp = formatter.formatTimestamp(new Date()); + + // Assess + expect(timestamp).toEqual('2016-06-20T12:08:10.000Z'); + }); + + it('formats the timestamp to ISO 8601, accounting for the `America/New_York` timezone offset', () => { + // Prepare + process.env.TZ = 'America/New_York'; + /* + Difference between UTC and `America/New_York`(GMT -04.00) is 240 minutes. + The positive value indicates that `America/New_York` is behind UTC. + */ + jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(240); + + // Act + const timestamp = formatterWithEnv.formatTimestamp(new Date()); + + // Assess + expect(timestamp).toEqual('2016-06-20T08:08:10.000-04:00'); + }); + + it('formats the timestamp to ISO 8601 with correct milliseconds for `America/New_York` timezone', () => { + // Prepare + process.env.TZ = 'America/New_York'; + /* + Difference between UTC and `America/New_York`(GMT -04.00) is 240 minutes. + The positive value indicates that `America/New_York` is behind UTC. + */ + jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(240); + + // Act + const timestamp = formatterWithEnv.formatTimestamp(new Date()); + + // Assess + expect(timestamp).toEqual('2016-06-20T08:08:10.000-04:00'); + }); + + it('formats the timestamp to ISO 8601, adjusting for `America/New_York` timezone, preserving milliseconds and accounting for date change', () => { + // Prepare + process.env.TZ = 'America/New_York'; + /* + Difference between UTC and `America/New_York`(GMT -04.00) is 240 minutes. + The positive value indicates that `America/New_York` is behind UTC. + */ + jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(240); + + // Act + const timestamp = formatterWithEnv.formatTimestamp(new Date()); + + // Assess + expect(timestamp).toEqual('2016-06-20T08:08:10.000-04:00'); + }); + + it('it formats the timestamp to ISO 8601 with correct milliseconds for `Asia/Dhaka` timezone', () => { + // Prepare + process.env.TZ = 'Asia/Dhaka'; + jest.useFakeTimers().setSystemTime(new Date('2016-06-20T12:08:10.910Z')); + /* + Difference between UTC and `Asia/Dhaka`(GMT +06.00) is 360 minutes. + The negative value indicates that `Asia/Dhaka` is ahead of UTC. + */ + jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(-360); + const formatter = new PowertoolsLogFormatter({ + envVarsService: new EnvironmentVariablesService(), + }); + + // Act + const timestamp = formatter.formatTimestamp(new Date()); + + // Assess + expect(timestamp).toEqual('2016-06-20T18:08:10.910+06:00'); + }); + + it('formats the timestamp to ISO 8601, adjusting for `Asia/Dhaka` timezone, preserving milliseconds and accounting for date change', () => { + // Prepare + process.env.TZ = 'Asia/Dhaka'; + const mockDate = new Date('2016-06-20T20:08:10.910Z'); + jest.useFakeTimers().setSystemTime(mockDate); + /* + Difference between UTC and `Asia/Dhaka`(GMT +06.00) is 360 minutes. + The negative value indicates that `Asia/Dhaka` is ahead of UTC. + */ + jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(-360); + const formatter = new PowertoolsLogFormatter({ + envVarsService: new EnvironmentVariablesService(), + }); + + // Act + const timestamp = formatter.formatTimestamp(new Date()); + + // Assess + expect(timestamp).toEqual('2016-06-21T02:08:10.910+06:00'); + }); + + it('returns defaults to :UTC when an env variable service is not set', () => { + // Prepare + process.env.TZ = 'Asia/Dhaka'; + /* + Difference between UTC and `Asia/Dhaka`(GMT +06.00) is 360 minutes. + The negative value indicates that `Asia/Dhaka` is ahead of UTC. + */ + jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(-360); + const formatter = new PowertoolsLogFormatter(); + + // Act + const timestamp = formatter.formatTimestamp(new Date()); + + // Assess + expect(timestamp).toEqual('2016-06-20T12:08:10.000Z'); + }); + + it('defaults to :UTC when the TZ env variable is set to :/etc/localtime', () => { + // Prepare + process.env.TZ = ':/etc/localtime'; + jest.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(0); + const formatter = new PowertoolsLogFormatter({ + envVarsService: new EnvironmentVariablesService(), + }); + + // Act + const timestamp = formatter.formatTimestamp(new Date()); + + // Assess + expect(timestamp).toEqual('2016-06-20T12:08:10.000+00:00'); + }); + + // #region format stack traces + + it.each([ + { + action: 'returns a location for a stack with relative file path', + stack: + 'Error: Things keep happening!\n' + + ' at /home/foo/bar/file-that-threw-the-error.ts:22:5\n' + + ' at SomeOther.function (/home/foo/bar/some-file.ts:154:19)', + expected: '/home/foo/bar/some-file.ts:154', + }, + { + action: + 'returns a location for a stack ending with an optional backslash', + stack: + 'Error: Reference Error!\n' + + ' at /home/foo/bar/file-that-threw-the-error.ts:22:5\n' + + ' at SomeOther.function (/home/foo/bar/some-frame-with-ending-backslash.ts:154:19)\\', + expected: '/home/foo/bar/some-frame-with-ending-backslash.ts:154', + }, + { + action: 'returns a location for a path containing multiple colons', + stack: + 'Error: The message failed to send\n' + + 'at REPL2:1:17\n' + + 'at Script.runInThisContext (node:vm:130:12)\n' + + '... 7 lines matching cause stack trace ...\n' + + 'at [_line] [as _line] (node:internal/readline/interface:886:18) {\n' + + '[cause]: Error: The remote HTTP server responded with a 500 status\n' + + ' at REPL1:1:15\n' + + ' at Script.runInThisContext (node:vm:130:12)\n' + + ' at REPLServer.defaultEval (node:repl:574:29)\n' + + ' at bound (node:domain:426:15)\n' + + ' at REPLServer.runBound [as eval] (node:domain:437:12)\n' + + ' at REPLServer.onLine (node:repl:902:10)\n' + + ' at REPLServer.emit (node:events:549:35)\n' + + ' at REPLServer.emit (node:domain:482:12)\n' + + ' at [_onLine] [as _onLine] (node:internal/readline/interface:425:12)\n' + + ' at [_line] [as _line] (node:internal/readline/interface:886:18) \n', + expected: 'node:vm:130', + }, + { + action: 'returns a location for a nested path', + stack: + 'Error: unknown\n' + + 'at eval (eval at (file:///home/foo/bar/some-file.ts:1:35), :1:7)\n' + + 'at (/home/foo/bar/file-that-threw-the-error.ts:52:3)\n' + + 'at ModuleJob.run (node:internal/modules/esm/module_job:218:25)\n' + + 'at async ModuleLoader.import (node:internal/modules/esm/loader:329:24)\n' + + 'at async loadESM (node:internal/process/esm_loader:28:7)\n' + + 'at async handleMainPromise (node:internal/modules/run_main:113:12)\n', + expected: '/home/foo/bar/file-that-threw-the-error.ts:52', + }, + { + condition: 'returns an empty location when the stack is undefined', + stack: undefined, + expected: '', + }, + { + action: 'returns an empty location when the stack is malformed', + stack: 'A weird stack trace...', + expected: '', + }, + ])('it $action', ({ stack, expected }) => { + // Act + const errorLocation = formatter.getCodeLocation(stack); + + // Assess + expect(errorLocation).toEqual(expected); + }); + + // #region custom JSON replacer + + it('ignores keys with circular references when stringifying', () => { + // Prepare + const circularObject = { + foo: 'bar', + self: {}, + }; + circularObject.self = circularObject; + + // Act + logger.info('foo', { circularObject }); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual( + expect.objectContaining({ + level: 'INFO', + message: 'foo', + circularObject: { + foo: 'bar', + }, + }) + ); + }); + + it('replaces bigints with their string representation when stringifying', () => { + // Prepare + const bigIntValue = { bigint: BigInt(9007199254740991) }; + + // Act + logger.info('foo', bigIntValue); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual( + expect.objectContaining({ + level: 'INFO', + message: 'foo', + bigint: '9007199254740991', + }) + ); + }); + + it('removes falsy values, except zero, when stringifying', () => { + // Prepare + const values = { + zero: 0, + emptyString: '', + nullValue: null, + undefinedValue: undefined, + falseValue: false, + }; + + // Act + logger.info('foo', values); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual( + expect.objectContaining({ + level: 'INFO', + message: 'foo', + zero: 0, + }) + ); + }); + + it('should correctly serialize custom values using the provided jsonReplacerFn', () => { + // Prepare + const valueWithSet = { value: new Set([1, 2]) }; + + // Act + loggerWithReplacer.info('foo', valueWithSet); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual( + expect.objectContaining({ + level: 'INFO', + message: 'foo', + value: [1, 2], + }) + ); + }); + + it('should serialize using both the existing replacer and the customer-provided one', () => { + // Prepare + const valueWithSetAndBigInt = { + value: new Set([1, 2]), + number: BigInt(42), + }; + + // Act + loggerWithReplacer.info('foo', valueWithSetAndBigInt); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual( + expect.objectContaining({ + level: 'INFO', + message: 'foo', + value: [1, 2], + number: '42', + }) + ); + }); + + it('propagates the JSON customer-provided replacer function to child loggers', () => { + // Prepare + const childLogger = loggerWithReplacer.createChild(); + + // Act + childLogger.info('foo', { foo: new Set([1, 2]) }); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual( + expect.objectContaining({ + level: 'INFO', + message: 'foo', + foo: [1, 2], + }) + ); + }); + + // #region custom log formatter + + it('formats logs using a custom log formatter', () => { + // Act + loggerWithCustomLogFormatter.info('foo'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual({ + logLevel: 12, + message: 'foo', + timestamp: expect.any(String), + }); + }); + + it('propagates the custom log formatter to child loggers', () => { + // Prepare + const childLogger = loggerWithCustomLogFormatter.createChild(); + + // Act + childLogger.info('foo'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual({ + logLevel: 12, + message: 'foo', + timestamp: expect.any(String), + }); + }); +}); diff --git a/packages/logger/tests/unit/initializeLogger.test.ts b/packages/logger/tests/unit/initializeLogger.test.ts new file mode 100644 index 0000000000..6121f8d018 --- /dev/null +++ b/packages/logger/tests/unit/initializeLogger.test.ts @@ -0,0 +1,144 @@ +/** + * Logger log levels tests + * + * @group unit/logger/logger/logLevels + */ +import { beforeEach, describe, expect, it, jest } from '@jest/globals'; +import { Logger } from '../../src/Logger.js'; +import { LogJsonIndent, LogLevel } from '../../src/constants.js'; + +const logSpy = jest.spyOn(console, 'info'); + +describe('Log levels', () => { + const ENVIRONMENT_VARIABLES = process.env; + + beforeEach(() => { + process.env = { ...ENVIRONMENT_VARIABLES, POWERTOOLS_DEV: 'true' }; + jest.resetAllMocks(); + }); + + it('uses the default service name when none is provided', () => { + // Prepare + process.env.POWERTOOLS_SERVICE_NAME = undefined; + const logger = new Logger(); + + // Act + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ service: 'service_undefined' }) + ); + }); + + it('uses service name specified in environment variables', () => { + // Prepare + process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; + const logger = new Logger(); + + // Act + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ service: 'hello-world' }) + ); + }); + + it('uses service name specified in the constructor', () => { + // Prepare + process.env.POWERTOOLS_SERVICE_NAME = undefined; + const logger = new Logger({ serviceName: 'hello-world' }); + + // Act + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ service: 'hello-world' }) + ); + }); + + it('overrides the service name when creating a child logger', () => { + // Prepare + process.env.POWERTOOLS_SERVICE_NAME = 'hello-world'; + const logger = new Logger(); + const childLogger = logger.createChild({ serviceName: 'child-service' }); + + // Act + childLogger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ service: 'child-service' }) + ); + }); + + it('creates a child logger that is distinct from the parent logger', () => { + // Prepare + const debugSpy = jest.spyOn(console, 'debug'); + const logger = new Logger({ logLevel: LogLevel.CRITICAL }); + const childLogger = logger.createChild({ + logLevel: LogLevel.DEBUG, + serviceName: 'child-service', + }); + + // Act + logger.debug('Hello, world!'); + childLogger.appendKeys({ foo: 'bar' }); + childLogger.debug('Hello, world!'); + + // Assess + expect(debugSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(debugSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + service: 'child-service', + foo: 'bar', + level: LogLevel.DEBUG, + }) + ); + }); + + it("doesn't use the global console object by default", () => { + // Prepare + process.env.POWERTOOLS_DEV = undefined; + const logger = new Logger(); + + // Assess + // biome-ignore lint/complexity/useLiteralKeys: we need to access the internal console object + expect(logger['console']).not.toEqual(console); + }); + + it('uses pretty print when POWERTOOLS_DEV is set', () => { + // Prepare + const mockDate = new Date(1466424490000); + jest.useFakeTimers().setSystemTime(mockDate); + const logger = new Logger(); + + // Act + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(logSpy).toHaveBeenCalledWith( + JSON.stringify( + { + level: 'INFO', + message: 'Hello, world!', + sampling_rate: 0, + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }, + null, + LogJsonIndent.PRETTY + ) + ); + + jest.useRealTimers(); + }); +}); diff --git a/packages/logger/tests/unit/injectLambdaContext.test.ts b/packages/logger/tests/unit/injectLambdaContext.test.ts new file mode 100644 index 0000000000..edff5790a5 --- /dev/null +++ b/packages/logger/tests/unit/injectLambdaContext.test.ts @@ -0,0 +1,187 @@ +/** + * Logger injectLambdaContext tests + * + * @group unit/logger/logger/injectLambdaContext + */ +import context from '@aws-lambda-powertools/testing-utils/context'; +import { beforeEach, describe, expect, it, jest } from '@jest/globals'; +import middy from '@middy/core'; +import type { Context } from 'aws-lambda'; +import { Logger } from '../../src/Logger.js'; +import { injectLambdaContext } from '../../src/middleware/middy.js'; + +const event = { + foo: 'bar', +}; + +const getContextLogEntries = (overrides?: Record) => ({ + function_arn: context.invokedFunctionArn, + function_memory_size: context.memoryLimitInMB, + function_name: context.functionName, + function_request_id: context.awsRequestId, + cold_start: true, + ...overrides, +}); + +const logSpy = jest.spyOn(console, 'info'); + +describe('Inject Lambda Context', () => { + const ENVIRONMENT_VARIABLES = process.env; + + beforeEach(() => { + process.env = { + ...ENVIRONMENT_VARIABLES, + POWERTOOLS_DEV: 'true', + }; + jest.resetAllMocks(); + }); + + it('adds the context to log messages when the feature is enabled', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.addContext(context); + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + ...getContextLogEntries(), + }) + ); + }); + + it('replaces the context when a new context is added', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.addContext(context); + logger.info('Hello, world!'); + logger.addContext({ + ...context, + awsRequestId: 'c6af9ac6-7b61-11e6-9a41-93e812345679', + }); + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(2); + expect(JSON.parse(logSpy.mock.calls[1][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + ...getContextLogEntries({ + function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345679', + cold_start: false, + }), + }) + ); + }); + + it('adds the context to log messages when the feature is enabled in the Middy.js middleware', async () => { + // Prepare + const logger = new Logger(); + const handler = middy(async () => { + logger.info('Hello, world!'); + }).use(injectLambdaContext(logger)); + + // Act + await handler(event, context); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + ...getContextLogEntries(), + }) + ); + }); + + it('adds the context to the messages of each logger instance', async () => { + // Prepare + const logger1 = new Logger({ serviceName: 'parent' }); + const logger2 = logger1.createChild({ serviceName: 'child' }); + const handler = middy(async () => { + logger1.info('Hello, world!'); + logger2.info('Hello, world!'); + }).use(injectLambdaContext([logger1, logger2])); + + // Act + await handler(event, context); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(2); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + service: 'parent', + ...getContextLogEntries(), + }) + ); + expect(JSON.parse(logSpy.mock.calls[1][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + service: 'child', + ...getContextLogEntries(), + }) + ); + }); + + it('adds the context to the messages when the feature is enabled using the class method decorator', async () => { + // Prepare + const logger = new Logger(); + class Test { + readonly #greeting: string; + + public constructor(greeting: string) { + this.#greeting = greeting; + } + + @logger.injectLambdaContext() + async handler(_event: unknown, _context: Context) { + this.logGreeting(); + } + + logGreeting() { + logger.info(this.#greeting); + } + } + const lambda = new Test('Hello, world!'); + const handler = lambda.handler.bind(lambda); + + // Act + await handler(event, context); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + ...getContextLogEntries(), + }) + ); + }); + + it('propagates the context data to the child logger instances', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.addContext(context); + const childLogger = logger.createChild({ serviceName: 'child' }); + childLogger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + service: 'child', + ...getContextLogEntries(), + }) + ); + }); +}); diff --git a/packages/logger/tests/unit/logEvent.test.ts b/packages/logger/tests/unit/logEvent.test.ts new file mode 100644 index 0000000000..2ac66c11ef --- /dev/null +++ b/packages/logger/tests/unit/logEvent.test.ts @@ -0,0 +1,147 @@ +/** + * Logger log event tests + * + * @group unit/logger/logger/logEvent + */ +import context from '@aws-lambda-powertools/testing-utils/context'; +import { beforeEach, describe, expect, it, jest } from '@jest/globals'; +import middy from '@middy/core'; +import type { Context } from 'aws-lambda'; +import { Logger } from '../../src/Logger.js'; +import { injectLambdaContext } from '../../src/middleware/middy.js'; + +const event = { + foo: 'bar', +}; + +const logSpy = jest.spyOn(console, 'info'); + +describe('Log event', () => { + const ENVIRONMENT_VARIABLES = process.env; + + beforeEach(() => { + process.env = { + ...ENVIRONMENT_VARIABLES, + POWERTOOLS_LOGGER_LOG_EVENT: 'true', + POWERTOOLS_DEV: 'true', + }; + jest.resetAllMocks(); + }); + + it('logs the event with the correct log level and message', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.logEventIfEnabled(event); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ event }) + ); + }); + + it("doesn't log the event when the feature is disabled", () => { + // Prepare + process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'false'; + const logger = new Logger(); + + // Act + logger.logEventIfEnabled(event); + + // Assess + expect(logSpy).not.toHaveBeenCalled(); + }); + + it('respects the overwrite flag when provided', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.logEventIfEnabled(event, false); + + // Assess + expect(logSpy).not.toHaveBeenCalled(); + }); + + it('logs the event when logEvent is set in the Middy.js middleware', async () => { + // Prepare + const logger = new Logger(); + const handler = middy(async () => {}).use( + injectLambdaContext(logger, { logEvent: true }) + ); + + // Act + await handler(event, context); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + event, + function_arn: + 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + function_memory_size: '128', + function_name: 'foo-bar-function', + function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', + }) + ); + }); + + it('logs the event when logEvent is set in the class method decorator', async () => { + // Prepare + const logger = new Logger(); + class Test { + @logger.injectLambdaContext({ logEvent: true }) + async handler(event: unknown, context: Context) { + return event; + } + } + const handler = new Test().handler; + + // Act + await handler(event, context); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + event, + function_arn: + 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + function_memory_size: '128', + function_name: 'foo-bar-function', + function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', + }) + ); + }); + + it('prefers the local logEvent configuration over the environment variable', async () => { + // Prepare + process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'false'; + const logger = new Logger(); + const handler = middy(async () => {}).use( + injectLambdaContext(logger, { logEvent: true }) + ); + + // Act + await handler(event, context); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + }); + + it('passes down the log event configuration to child loggers', () => { + // Prepare + process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'false'; + const logger = new Logger(); + const childLogger = logger.createChild(); + + // Act + childLogger.logEventIfEnabled(event); + + // Assess + expect(logSpy).not.toHaveBeenCalled(); + }); +}); diff --git a/packages/logger/tests/unit/logLevels.test.ts b/packages/logger/tests/unit/logLevels.test.ts new file mode 100644 index 0000000000..0f35ffec26 --- /dev/null +++ b/packages/logger/tests/unit/logLevels.test.ts @@ -0,0 +1,208 @@ +/** + * Logger log levels tests + * + * @group unit/logger/logger/logLevels + */ +import { beforeEach, describe, expect, it, jest } from '@jest/globals'; +import { Logger } from '../../src/Logger.js'; +import { LogLevel, LogLevelThreshold } from '../../src/constants.js'; +import type { LogLevel as LogLevelType } from '../../src/types/Log.js'; +import type { LogFunction } from '../../src/types/Logger.js'; + +/** + * Helper function to get the console method for a given log level, we use this + * for properly mocking the console methods in the tests and account for the + * fact that `critical` is not a valid console method, which we proxy to `error`, + * and `trace` is internally proxied to `log`. + * + * @param method - The method to get the console method for + */ +const getConsoleMethod = ( + method: string +): keyof Omit | 'log' => { + const lowercaseMethod = method.toLowerCase(); + switch (lowercaseMethod) { + case 'trace': + return 'log'; + case 'critical': + return 'error'; + default: + return lowercaseMethod as keyof Omit; + } +}; + +describe('Log levels', () => { + const ENVIRONMENT_VARIABLES = process.env; + + beforeEach(() => { + process.env = { ...ENVIRONMENT_VARIABLES, POWERTOOLS_DEV: 'true' }; + jest.resetAllMocks(); + }); + + it('sets the correct log level when initialized with a log level', () => { + // Act + const logger = new Logger({ logLevel: LogLevel.WARN }); + + // Assess + expect(logger.level).toBe(LogLevelThreshold.WARN); + expect(logger.getLevelName()).toBe(LogLevel.WARN); + }); + + it('defaults to INFO log level when initialized without a log level', () => { + // Prepare + process.env.POWERTOOLS_LOG_LEVEL = undefined; + + // Act + const logger = new Logger(); + + // Assess + expect(logger.level).toBe(LogLevelThreshold.INFO); + expect(logger.getLevelName()).toBe(LogLevel.INFO); + }); + + it('defaults to INFO log level when initialized with an invalid log level', () => { + // Prepare + process.env.POWERTOOLS_LOG_LEVEL = undefined; + + // Act + const logger = new Logger({ logLevel: 'INVALID' as LogLevelType }); + + // Assess + expect(logger.level).toBe(LogLevelThreshold.INFO); + expect(logger.getLevelName()).toBe(LogLevel.INFO); + }); + + it('sets the correct log level when calling setLogLevel()', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.setLogLevel(LogLevel.ERROR); + + // Assess + expect(logger.level).toBe(LogLevelThreshold.ERROR); + expect(logger.getLevelName()).toBe(LogLevel.ERROR); + }); + + it('throws when trying to set an invalid log level via setLogLevel()', () => { + // Prepare + const logger = new Logger(); + + // Act & Assess + expect(() => logger.setLogLevel('INVALID' as LogLevelType)).toThrow( + 'Invalid log level: INVALID' + ); + }); + + it.each([ + { level: LogLevel.TRACE }, + { level: LogLevel.DEBUG }, + { level: LogLevel.INFO }, + { level: LogLevel.WARN }, + { level: LogLevel.ERROR }, + { level: LogLevel.CRITICAL }, + ])('logs at the correct level when calling $level()', ({ level }) => { + // Prepare + const logSpy = jest.spyOn(console, getConsoleMethod(level)); + const logger = new Logger({ logLevel: level }); + + // Act + logger[level.toLowerCase() as keyof LogFunction]('foo'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(logSpy).toHaveBeenCalledWith(expect.stringContaining(level)); + }); + + it.each([ + { level: LogLevel.DEBUG, moreVerboseLevel: LogLevel.TRACE }, + { level: LogLevel.INFO, moreVerboseLevel: LogLevel.DEBUG }, + { level: LogLevel.WARN, moreVerboseLevel: LogLevel.INFO }, + { level: LogLevel.ERROR, moreVerboseLevel: LogLevel.WARN }, + { level: LogLevel.CRITICAL, moreVerboseLevel: LogLevel.ERROR }, + ])( + "doesn't log when calling a level more verbose than the current log level ($level vs $moreVerboseLevel)", + ({ level, moreVerboseLevel }) => { + // Prepare + const logSpy = jest.spyOn(console, getConsoleMethod(moreVerboseLevel)); + const logger = new Logger({ logLevel: level }); + + // Act + logger[moreVerboseLevel.toLowerCase() as keyof LogFunction]('foo'); + + // Assess + expect(logSpy).not.toHaveBeenCalled(); + } + ); + + it.each([ + { level: LogLevel.TRACE, lessVerboseLevel: LogLevel.DEBUG }, + { level: LogLevel.DEBUG, lessVerboseLevel: LogLevel.INFO }, + { level: LogLevel.INFO, lessVerboseLevel: LogLevel.WARN }, + { level: LogLevel.WARN, lessVerboseLevel: LogLevel.ERROR }, + { level: LogLevel.ERROR, lessVerboseLevel: LogLevel.CRITICAL }, + ])( + 'logs when calling a level less verbose than the current log level ($level vs $lessVerboseLevel)', + ({ level, lessVerboseLevel }) => { + // Prepare + const logSpy = jest.spyOn(console, getConsoleMethod(lessVerboseLevel)); + const logger = new Logger({ logLevel: level }); + + // Act + logger[lessVerboseLevel.toLowerCase() as keyof LogFunction]('foo'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + } + ); + + it('emits a warning and falls back to the ALC level when trying to set a more verbose log level than the one set in ALC', () => { + // Prepare + process.env.AWS_LAMBDA_LOG_LEVEL = LogLevel.ERROR; + process.env.LOG_LEVEL = undefined; + process.env.POWERTOOLS_LOG_LEVEL = undefined; + const logger = new Logger(); + const warningSpy = jest.spyOn(logger, 'warn'); + + // Act + logger.setLogLevel(LogLevel.WARN); + + // Assess + expect(logger.level).toBe(LogLevelThreshold.ERROR); + expect(logger.getLevelName()).toBe(LogLevel.ERROR); + expect(warningSpy).toHaveBeenCalledTimes(1); + expect(warningSpy).toHaveBeenCalledWith( + 'Current log level (WARN) does not match AWS Lambda Advanced Logging Controls minimum log level (ERROR). This can lead to data loss, consider adjusting them.' + ); + }); + + it('emits a warning and falls back to the ALC level when trying to init the logger with a more verbose log level than the one set in ALC', () => { + // Prepare + process.env.AWS_LAMBDA_LOG_LEVEL = LogLevel.INFO; + process.env.LOG_LEVEL = undefined; + process.env.POWERTOOLS_LOG_LEVEL = undefined; + const warningSpy = jest.spyOn(console, 'warn'); + + // Act + const logger = new Logger({ logLevel: LogLevel.DEBUG }); + + // Assess + expect(logger.level).toBe(LogLevelThreshold.INFO); + expect(logger.getLevelName()).toBe(LogLevel.INFO); + expect(warningSpy).toHaveBeenCalledTimes(1); + expect(warningSpy).toHaveBeenCalledWith( + expect.stringContaining( + 'Current log level (DEBUG) does not match AWS Lambda Advanced Logging Controls minimum log level (INFO). This can lead to data loss, consider adjusting them.' + ) + ); + }); + + it('propagates the log level to child loggers', () => { + // Prepare + const parentLogger = new Logger({ logLevel: LogLevel.WARN }); + const childLogger = parentLogger.createChild(); + + // Act & Assess + expect(childLogger.level).toBe(LogLevelThreshold.WARN); + }); +}); diff --git a/packages/logger/tests/unit/middleware/middy.test.ts b/packages/logger/tests/unit/middleware/middy.test.ts deleted file mode 100644 index 2d31d575c1..0000000000 --- a/packages/logger/tests/unit/middleware/middy.test.ts +++ /dev/null @@ -1,616 +0,0 @@ -/** - * Test Logger middleware - * - * @group unit/logger/middleware - */ -import { cleanupMiddlewares } from '@aws-lambda-powertools/commons'; -import context from '@aws-lambda-powertools/testing-utils/context'; -import middy from '@middy/core'; -import type { Context } from 'aws-lambda'; -import { injectLambdaContext } from '../../../src/middleware/middy.js'; -import type { ConfigServiceInterface } from '../../../src/types/ConfigServiceInterface.js'; -import { Logger } from './../../../src/Logger.js'; - -const mockDate = new Date(1466424490000); -const dateSpy = jest.spyOn(global, 'Date').mockImplementation(() => mockDate); - -describe('Middy middleware', () => { - const ENVIRONMENT_VARIABLES = process.env; - const event = { - foo: 'bar', - bar: 'baz', - }; - - beforeEach(() => { - jest.resetModules(); - dateSpy.mockClear(); - jest - .spyOn(process.stdout, 'write') - .mockImplementation(() => null as unknown as boolean); - process.env = { ...ENVIRONMENT_VARIABLES }; - }); - - afterAll(() => { - process.env = ENVIRONMENT_VARIABLES; - }); - - describe('injectLambdaContext', () => { - describe('Feature: add context data', () => { - test('when a logger object is passed, it adds the context to the logger instance', async () => { - // Prepare - const logger = new Logger(); - const handler = middy((): void => { - logger.info('This is an INFO log with some context'); - }).use(injectLambdaContext(logger)); - - // Act - await handler(event, context); - - // Assess - expect(logger).toEqual( - expect.objectContaining({ - powertoolsLogData: expect.objectContaining({ - lambdaContext: { - awsRequestId: 'c6af9ac6-7b61-11e6-9a41-93e812345678', - coldStart: true, - functionName: 'foo-bar-function', - functionVersion: '$LATEST', - invokedFunctionArn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - memoryLimitInMB: '128', - }, - }), - }) - ); - }); - - test('when a logger array is passed, it adds the context to all logger instances', async () => { - // Prepare - const logger = new Logger(); - const anotherLogger = new Logger(); - const handler = middy((): void => { - logger.info('This is an INFO log with some context'); - anotherLogger.info('This is an INFO log with some context'); - }).use(injectLambdaContext([logger, anotherLogger])); - - // Act - await handler(event, context); - - // Assess - const expectation = expect.objectContaining({ - powertoolsLogData: expect.objectContaining({ - lambdaContext: { - awsRequestId: 'c6af9ac6-7b61-11e6-9a41-93e812345678', - coldStart: true, - functionName: 'foo-bar-function', - functionVersion: '$LATEST', - invokedFunctionArn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - memoryLimitInMB: '128', - }, - }), - }); - expect(logger).toEqual(expectation); - expect(anotherLogger).toEqual(expectation); - }); - }); - }); - - describe('Feature: reset state', () => { - test('when enabled, it clears all the log attributes added with appendKeys() inside and outside of the handler function', async () => { - // Prepare - const logger = new Logger({ - logLevel: 'DEBUG', - }); - logger.appendKeys({ - foo: 'bar', - biz: 'baz', - }); - - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - const debugSpy = jest.spyOn(logger['console'], 'debug'); - - const handler = middy((): void => { - // Only add these keys for the scope of this lambda handler - logger.appendKeys({ - details: { user_id: '1234' }, - }); - logger.debug('This is a DEBUG log with the user_id'); - }).use(injectLambdaContext(logger, { clearState: true })); - - // Act - await handler(event, context); - logger.debug('Checking state after handler execution'); - - // Assess - expect(debugSpy).toHaveBeenCalledTimes(2); - const log1 = JSON.parse(debugSpy.mock.calls[0][0]); - expect(log1).toStrictEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', - level: 'DEBUG', - message: 'This is a DEBUG log with the user_id', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - foo: 'bar', - biz: 'baz', - details: { user_id: '1234' }, - }) - ); - const log2 = JSON.parse(debugSpy.mock.calls[1][0]); - expect(log2).toStrictEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', - level: 'DEBUG', - message: 'Checking state after handler execution', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - }) - ); - }); - - test('when enabled, the temporary log attributes added within the handler scope are removed after the invocation ends', async () => { - // Prepare - const logger = new Logger({ - logLevel: 'DEBUG', - persistentLogAttributes: { - foo: 'bar', - }, - }); - logger.appendKeys({ - biz: 'baz', - }); - - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - const debugSpy = jest.spyOn(logger['console'], 'debug'); - - const handler = middy((): void => { - // These keys stay only in the scope of this lambda handler - logger.appendKeys({ - details: { user_id: '1234' }, - }); - logger.debug('This is a DEBUG log with the user_id'); - }).use(injectLambdaContext(logger, { clearState: true })); - - // Act - await handler(event, context); - logger.debug('Checking state after handler execution'); - - // Assess - expect(debugSpy).toHaveBeenCalledTimes(2); - const log1 = JSON.parse(debugSpy.mock.calls[0][0]); - expect(log1).toStrictEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', - level: 'DEBUG', - message: 'This is a DEBUG log with the user_id', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - foo: 'bar', - biz: 'baz', - details: { user_id: '1234' }, - }) - ); - const log2 = JSON.parse(debugSpy.mock.calls[1][0]); - expect(log2).toStrictEqual( - expect.objectContaining({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - function_request_id: 'c6af9ac6-7b61-11e6-9a41-93e812345678', - level: 'DEBUG', - message: 'Checking state after handler execution', - sampling_rate: 0, - service: 'hello-world', - timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', - foo: 'bar', - }) - ); - }); - - test('when enabled, the persistent log attributes added within the handler scope ARE NOT removed after the invocation ends', async () => { - // Prepare - const logger = new Logger({ - logLevel: 'DEBUG', - persistentLogAttributes: { - foo: 'bar', - biz: 'baz', - }, - }); - - const handler = middy((): void => { - // These persistent attributes stay persistent - logger.addPersistentLogAttributes({ - details: { user_id: '1234' }, - }); - logger.debug('This is a DEBUG log with the user_id'); - logger.debug('This is another DEBUG log with the user_id'); - }).use(injectLambdaContext(logger, { clearState: true })); - const persistentAttribsBeforeInvocation = { - ...logger.getPersistentLogAttributes(), - }; - - // Act - await handler(event, context); - - // Assess - const persistentAttribsAfterInvocation = { - ...logger.getPersistentLogAttributes(), - }; - expect(persistentAttribsBeforeInvocation).toEqual({ - foo: 'bar', - biz: 'baz', - }); - expect(persistentAttribsAfterInvocation).toEqual({ - foo: 'bar', - biz: 'baz', - details: { user_id: '1234' }, - }); - }); - - test('when enabled, the persistent log attributes added within the handler scope ARE NOT removed after the invocation ends even if an error is thrown', async () => { - // Prepare - const logger = new Logger({ - logLevel: 'DEBUG', - persistentLogAttributes: { - foo: 'bar', - biz: 'baz', - }, - }); - const handler = middy((): void => { - // These persistent attributes stay persistent - logger.addPersistentLogAttributes({ - details: { user_id: '1234' }, - }); - logger.debug('This is a DEBUG log with the user_id'); - logger.debug('This is another DEBUG log with the user_id'); - - throw new Error('Unexpected error occurred!'); - }).use(injectLambdaContext(logger, { clearState: true })); - const persistentAttribsBeforeInvocation = { - ...logger.getPersistentLogAttributes(), - }; - - // Act & Assess - await expect(handler(event, context)).rejects.toThrow(); - const persistentAttribsAfterInvocation = { - ...logger.getPersistentLogAttributes(), - }; - expect(persistentAttribsBeforeInvocation).toEqual({ - foo: 'bar', - biz: 'baz', - }); - expect(persistentAttribsAfterInvocation).toEqual({ - foo: 'bar', - biz: 'baz', - details: { user_id: '1234' }, - }); - }); - - test('when enabled, and another middleware returns early, it still clears the state', async () => { - // Prepare - const logger = new Logger({ - logLevel: 'DEBUG', - }); - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - const loggerSpy = jest.spyOn(logger['console'], 'debug'); - const myCustomMiddleware = (): middy.MiddlewareObj => { - const before = async ( - request: middy.Request - ): Promise => { - // Return early on the second invocation - if (request.event.idx === 1) { - // Cleanup Powertools resources - await cleanupMiddlewares(request); - - // Then return early - return 'foo'; - } - }; - - return { - before, - }; - }; - const handler = middy( - (event: { foo: string; bar: string } & { idx: number }): void => { - // Add a key only at the first invocation, so we can check that it's cleared - if (event.idx === 0) { - logger.appendKeys({ - details: { user_id: '1234' }, - }); - } - logger.debug('This is a DEBUG log'); - } - ) - .use(injectLambdaContext(logger, { clearState: true })) - .use(myCustomMiddleware()); - - // Act - await handler({ ...event, idx: 0 }, context); - await handler({ ...event, idx: 1 }, context); - - // Assess - const persistentAttribsAfterInvocation = { - ...logger.getPersistentLogAttributes(), - }; - expect(persistentAttribsAfterInvocation).toEqual({}); - // Only one log because the second invocation returned early - // from the custom middleware - expect(loggerSpy).toBeCalledTimes(1); - expect(loggerSpy).toHaveBeenNthCalledWith( - 1, - expect.stringContaining('"details":{"user_id":"1234"}') - ); - }); - }); - - describe('Feature: log event', () => { - test('when enabled, it logs the event', async () => { - // Prepare - const logger = new Logger(); - const consoleSpy = jest - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - .spyOn(logger['console'], 'info') - .mockImplementation(); - const handler = middy((): void => { - logger.info('This is an INFO log with some context'); - }).use(injectLambdaContext(logger, { logEvent: true })); - - // Act - await handler(event, context); - - // Assess - expect(consoleSpy).toBeCalledTimes(2); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - 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', - event: { - foo: 'bar', - bar: 'baz', - }, - }) - ); - }); - - test('when enabled, while also having a custom configService, it logs the event', async () => { - // Prepare - const configService: ConfigServiceInterface = { - get(name: string): string { - return `a-string-from-${name}`; - }, - getAwsLogLevel(): string { - return 'INFO'; - }, - getCurrentEnvironment(): string { - return 'dev'; - }, - getLogEvent(): boolean { - return true; - }, - getLogLevel(): string { - return 'INFO'; - }, - getSampleRateValue(): number | undefined { - return undefined; - }, - getServiceName(): string { - return 'my-backend-service'; - }, - getXrayTraceId(): string | undefined { - return undefined; - }, - getXrayTraceSampled(): boolean { - return false; - }, - isDevMode(): boolean { - return false; - }, - isValueTrue(): boolean { - return true; - }, - }; - - const logger = new Logger({ - customConfigService: configService, - }); - const consoleSpy = jest - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - .spyOn(logger['console'], 'info') - .mockImplementation(); - const handler = middy((): void => { - logger.info('This is an INFO log with some context'); - }).use(injectLambdaContext(logger, { logEvent: true })); - - // Act - await handler(event, context); - - // Assess - expect(consoleSpy).toBeCalledTimes(2); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - 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', - event: { - foo: 'bar', - bar: 'baz', - }, - }) - ); - }); - - test('when enabled via POWERTOOLS_LOGGER_LOG_EVENT env var, it logs the event', async () => { - // Prepare - process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'true'; - const logger = new Logger(); - const consoleSpy = jest - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - .spyOn(logger['console'], 'info') - .mockImplementation(); - const handler = middy((): void => { - logger.info('This is an INFO log with some context'); - }).use(injectLambdaContext(logger)); - - // Act - await handler(event, context); - - // Assess - expect(consoleSpy).toBeCalledTimes(2); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - 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', - event: { - foo: 'bar', - bar: 'baz', - }, - }) - ); - }); - - test('when disabled in the middleware, but enabled via POWERTOOLS_LOGGER_LOG_EVENT env var, it still does not log the event', async () => { - // Prepare - process.env.POWERTOOLS_LOGGER_LOG_EVENT = 'true'; - const logger = new Logger(); - const consoleSpy = jest - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - .spyOn(logger['console'], 'info') - .mockImplementation(); - const handler = middy((): void => { - logger.info('This is an INFO log'); - }).use(injectLambdaContext(logger, { logEvent: false })); - - // Act - await handler(event, context); - - // Assess - expect(consoleSpy).toBeCalledTimes(1); - expect(consoleSpy).toHaveBeenNthCalledWith( - 1, - JSON.stringify({ - cold_start: true, - function_arn: - 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - function_memory_size: '128', - function_name: 'foo-bar-function', - 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', - }) - ); - }); - - test('when logEvent and clearState are both TRUE, and the logger has persistent attributes, any key added in the handler is cleared properly', async () => { - const logger = new Logger({ - persistentLogAttributes: { - version: '1.0.0', - }, - }); - const consoleSpy = jest - // biome-ignore lint/complexity/useLiteralKeys: This needs to be accessed with literal key for testing - .spyOn(logger['console'], 'info') - .mockImplementation(); - const handler = middy( - async (event: { foo: string }, _context: Context) => { - logger.appendKeys({ foo: event.foo }); - } - ).use(injectLambdaContext(logger, { logEvent: true, clearState: true })); - - await handler({ foo: 'bar' }, {} as Context); - await handler({ foo: 'baz' }, {} as Context); - await handler({ foo: 'biz' }, {} as Context); - await handler({ foo: 'buz' }, {} as Context); - await handler({ foo: 'boz' }, {} as Context); - - expect(consoleSpy).toBeCalledTimes(5); - for (let i = 1; i === 5; i++) { - expect(consoleSpy).toHaveBeenNthCalledWith( - i, - expect.stringContaining('"message":"Lambda invocation event"') - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - i, - expect.stringContaining('"version":"1.0.0"') - ); - } - expect(consoleSpy).toHaveBeenNthCalledWith( - 2, - expect.not.stringContaining('"foo":"bar"') - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - 3, - expect.not.stringContaining('"foo":"baz"') - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - 4, - expect.not.stringContaining('"foo":"biz"') - ); - expect(consoleSpy).toHaveBeenNthCalledWith( - 5, - expect.not.stringContaining('"foo":"buz"') - ); - }); - }); -}); diff --git a/packages/logger/tests/unit/sampling.test.ts b/packages/logger/tests/unit/sampling.test.ts new file mode 100644 index 0000000000..2f8e0ce959 --- /dev/null +++ b/packages/logger/tests/unit/sampling.test.ts @@ -0,0 +1,180 @@ +/** + * Log Sampling + * + * @group unit/logger/logger/sampling + */ +import { beforeEach, describe, expect, it, jest } from '@jest/globals'; +import { EnvironmentVariablesService } from '../../src/config/EnvironmentVariablesService.js'; +import { LogLevel, LogLevelThreshold, Logger } from '../../src/index.js'; + +class CustomConfigService extends EnvironmentVariablesService { + #sampleRateValue = 1; + + public constructor(value = 1) { + super(); + this.#sampleRateValue = value; + } + + public getSampleRateValue(): number { + return this.#sampleRateValue; + } +} + +const logSpy = jest.spyOn(console, 'info'); + +describe('Log sampling', () => { + const ENVIRONMENT_VARIABLES = process.env; + + beforeEach(() => { + process.env = { ...ENVIRONMENT_VARIABLES, POWERTOOLS_DEV: 'true' }; + }); + + it('informs the customer that sample rate is setting the level to DEBUG', () => { + // Prepare + const debugSpy = jest.spyOn(console, 'debug'); + + // Act + new Logger({ sampleRateValue: 1, logLevel: LogLevel.CRITICAL }); + + // Assess + expect(debugSpy).toHaveBeenCalledTimes(1); + expect(debugSpy).toHaveBeenCalledWith( + expect.stringContaining('Setting log level to DEBUG due to sampling rate') + ); + }); + + it('changes the log level to DEBUG log sampling is configured via constructor', () => { + // Act + const logger: Logger = new Logger({ + logLevel: LogLevel.ERROR, + sampleRateValue: 1, + }); + + // Assess + expect(logger.level).toBe(LogLevelThreshold.DEBUG); + }); + + it('changes the log level to DEBUG log sampling is configured via custom config service', () => { + // Act + const logger: Logger = new Logger({ + logLevel: LogLevel.ERROR, + customConfigService: new CustomConfigService(), + }); + + // Assess + expect(logger.level).toBe(LogLevelThreshold.DEBUG); + }); + + it('changes the log level to debug log sampling is configured via env variable', () => { + // Prepare + process.env.POWERTOOLS_LOGGER_SAMPLE_RATE = '1'; + + // Act + const logger: Logger = new Logger({ + logLevel: LogLevel.ERROR, + }); + + // Assess + expect(logger.level).toBe(LogLevelThreshold.DEBUG); + }); + + it("doesn't change the log level when sample rate is 0", () => { + // Prepare & Act + const logger: Logger = new Logger({ + logLevel: LogLevel.ERROR, + sampleRateValue: 0, + }); + + // Assess + expect(logger.level).toBe(LogLevelThreshold.ERROR); + }); + + it('prioritizes and uses the sample rate specified in the constructor', () => { + // Prepare + process.env.POWERTOOLS_LOGGER_SAMPLE_RATE = '0.5'; + + // Act + const logger: Logger = new Logger({ + sampleRateValue: 1, + customConfigService: new CustomConfigService(0.75), + }); + + // Assess + expect(logger.level).toBe(LogLevelThreshold.DEBUG); + }); + + it.each([ + { + options: { + sampleRateValue: 42, + }, + type: 'constructor', + }, + { + options: { + customConfigService: new CustomConfigService(42), + }, + type: 'custom config service', + }, + { + options: {}, + type: 'env variable', + }, + ])('ignores invalid sample rate values via $type', ({ options, type }) => { + // Prepare + if (type === 'env variable') { + process.env.POWERTOOLS_LOGGER_SAMPLE_RATE = '42'; + } + + // Act + const logger: Logger = new Logger({ + logLevel: LogLevel.INFO, + ...options, + }); + + // Assess + expect(logger.getLevelName()).toBe(LogLevel.INFO); + }); + + it('when sample rate calculation is refreshed, it respects probability sampling and change log level to DEBUG ', () => { + // Prepare + const logger = new Logger({ + logLevel: LogLevel.ERROR, + sampleRateValue: 0.1, // 10% probability + }); + + 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() === LogLevel.DEBUG) { + logLevelChangedToDebug++; + } + } + + // Assess + expect(logLevelChangedToDebug).toBeGreaterThanOrEqual(minExpected); + expect(logLevelChangedToDebug).toBeLessThanOrEqual(maxExpected); + }); + + it('propagates the sample rate to child loggers', () => { + // Prepare + const logger = new Logger({ + sampleRateValue: 0.5, + }); + const childLogger = logger.createChild(); + + // Act + childLogger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ sampling_rate: 0.5 }) + ); + }); +}); diff --git a/packages/logger/tests/unit/workingWithkeys.test.ts b/packages/logger/tests/unit/workingWithkeys.test.ts new file mode 100644 index 0000000000..976ef9aba5 --- /dev/null +++ b/packages/logger/tests/unit/workingWithkeys.test.ts @@ -0,0 +1,610 @@ +/** + * Logger working with keys tests + * + * @group unit/logger/logger/keys + */ +import context from '@aws-lambda-powertools/testing-utils/context'; +import { beforeEach, describe, expect, it, jest } from '@jest/globals'; +import middy from '@middy/core'; +import type { Context } from 'aws-lambda'; +import { Logger } from '../../src/Logger.js'; +import { injectLambdaContext } from '../../src/middleware/middy.js'; +import type { ConstructorOptions } from '../../src/types/Logger.js'; + +const logSpy = jest.spyOn(console, 'info'); + +describe('Working with keys', () => { + const ENVIRONMENT_VARIABLES = process.env; + + beforeEach(() => { + process.env = { + ...ENVIRONMENT_VARIABLES, + POWERTOOLS_DEV: 'true', + }; + jest.resetAllMocks(); + }); + + it.each([ + { + inputs: ['Hello, world!', { extra: 'parameter' }], + expected: { + message: 'Hello, world!', + extra: 'parameter', + }, + info: 'adds the message and extra keys', + }, + { + inputs: ['Hello, world!', { parameterOne: 'foo' }, 'bar'], + expected: { + message: 'Hello, world!', + parameterOne: 'foo', + extra: 'bar', + }, + info: 'adds the message and multiple extra keys', + }, + { + inputs: [ + { + message: 'Hello, world!', + extra: 'parameter', + }, + ], + expected: { + message: 'Hello, world!', + extra: 'parameter', + }, + info: 'adds the message and extra keys as an object', + }, + { + inputs: ['Hello, world!', new Error('Something happened!')], + expected: { + message: 'Hello, world!', + error: { + location: expect.any(String), + message: 'Something happened!', + name: 'Error', + stack: expect.any(String), + }, + }, + info: 'adds the message and error', + }, + { + inputs: [ + 'Hello, world!', + { myCustomErrorKey: new Error('Something happened!') }, + ], + expected: { + message: 'Hello, world!', + myCustomErrorKey: { + location: expect.any(String), + message: 'Something happened!', + name: 'Error', + stack: expect.any(String), + }, + }, + info: 'adds the message and custom error', + }, + { + inputs: [ + 'Hello, world!', + { + extra: { + value: 'CUSTOM', + nested: { + bool: true, + str: 'string value', + num: 42, + err: new Error('Arbitrary object error'), + }, + }, + }, + ], + expected: { + message: 'Hello, world!', + extra: { + value: 'CUSTOM', + nested: { + bool: true, + str: 'string value', + num: 42, + err: { + location: expect.any(String), + message: 'Arbitrary object error', + name: 'Error', + stack: expect.any(String), + }, + }, + }, + }, + info: 'adds the message and nested object', + }, + ])('it $info when logging data', ({ inputs, expected }) => { + // Prepare + const logger = new Logger(); + + // Act + // @ts-expect-error - we are testing the method dynamically + logger.info(...inputs); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining(expected) + ); + }); + + it('adds the temporary keys to log messages', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.appendKeys({ + foo: 'bar', + }); + logger.info('Hello, world!'); + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(2); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + foo: 'bar', + }) + ); + expect(JSON.parse(logSpy.mock.calls[1][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + foo: 'bar', + }) + ); + }); + + it('overrides temporary keys when the same key is added', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.appendKeys({ + foo: 'bar', + }); + logger.info('Hello, world!'); + logger.appendKeys({ + foo: 'baz', + }); + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(2); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + foo: 'bar', + }) + ); + expect(JSON.parse(logSpy.mock.calls[1][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + foo: 'baz', + }) + ); + }); + + it('adds the temporary keys and clears them when calling resetKeys()', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.appendKeys({ + foo: 'bar', + }); + logger.info('Hello, world!'); + logger.resetKeys(); + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(2); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + foo: 'bar', + }) + ); + expect(JSON.parse(logSpy.mock.calls[1][0])).toStrictEqual( + expect.not.objectContaining({ + foo: 'bar', + }) + ); + }); + + it('adds persistent keys to log messages', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.appendPersistentKeys({ + foo: 'bar', + }); + logger.resetKeys(); + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + foo: 'bar', + }) + ); + }); + + it('adds the persistent keys via constructor', () => { + // Prepare + const logger = new Logger({ + persistentKeys: { + foo: 'bar', + }, + }); + + // Act + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + foo: 'bar', + }) + ); + }); + + it('overrides persistent keys when the same key is added', () => { + // Prepare + const logger = new Logger({ + persistentKeys: { + foo: 'bar', + }, + }); + + // Act + logger.appendPersistentKeys({ + foo: 'baz', + }); + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + foo: 'baz', + }) + ); + }); + + it('overrides temporary keys when the same key is added as persistent key', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.appendKeys({ + foo: 'bar', + }); + logger.appendPersistentKeys({ + foo: 'baz', + }); + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + foo: 'baz', + }) + ); + }); + + it('preserves previously overridden persistent keys when the same key is added as temporary key', () => { + // Prepare + const logger = new Logger({ + persistentKeys: { + foo: 'bar', + }, + }); + + // Act + logger.appendKeys({ + foo: 'baz', + }); + logger.resetKeys(); + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + message: 'Hello, world!', + foo: 'bar', + }) + ); + }); + + it('handles gracefully the removal of non-existing keys', () => { + // Prepare + const logger = new Logger(); + + // Act & Assess + expect(() => logger.removeKeys(['foo'])).not.toThrow(); + }); + + it('removes a temporary key from log messages', () => { + // Prepare + const logger = new Logger(); + logger.appendKeys({ + foo: 'bar', + }); + + // Act + logger.removeKeys(['foo']); + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.not.objectContaining({ + foo: 'bar', + }) + ); + }); + + it('restores the persistent key after removing it as temporary key', () => { + // Prepare + const logger = new Logger({ + persistentKeys: { + foo: 'bar', + }, + }); + + // Act + logger.appendKeys({ + foo: 'baz', + }); + logger.removeKeys(['foo']); + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + foo: 'bar', + }) + ); + }); + + it('removes a persistent key from log messages', () => { + // Prepare + const logger = new Logger({ + persistentKeys: { + foo: 'bar', + }, + }); + + // Act + logger.removePersistentKeys(['foo']); + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.not.objectContaining({ + foo: 'bar', + }) + ); + }); + + it('restores the temporary key after removing it as persistent key', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.appendKeys({ + foo: 'bar', + }); + logger.appendPersistentKeys({ + foo: 'baz', + }); + logger.removePersistentKeys(['foo']); + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + foo: 'bar', + }) + ); + }); + + it('removes the temporary keys when resetState is enabled in the Middy.js middleware', async () => { + // Prepare + const logger = new Logger({ + persistentKeys: { + foo: 'bar', + }, + }); + const handler = middy(async (addKey: boolean) => { + if (addKey) { + logger.appendKeys({ + foo: 'baz', + }); + } + logger.info('Hello, world!'); + }).use(injectLambdaContext(logger, { resetKeys: true })); + + // Act + await handler(true, context); + await handler(false, context); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(2); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + foo: 'baz', + }) + ); + expect(JSON.parse(logSpy.mock.calls[1][0])).toStrictEqual( + expect.objectContaining({ + foo: 'bar', + }) + ); + }); + + it('removes the temporary keys when resetState is enabled in the class method decorator', async () => { + // Prepare + const logger = new Logger({ + persistentKeys: { + foo: 'bar', + }, + }); + class Test { + @logger.injectLambdaContext({ resetKeys: true }) + async handler(addKey: boolean, context: Context) { + if (addKey) { + logger.appendKeys({ + foo: 'baz', + }); + } + logger.info('Hello, world!'); + } + } + const handler = new Test().handler; + + // Act + await handler(true, context); + await handler(false, context); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(2); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + foo: 'baz', + }) + ); + expect(JSON.parse(logSpy.mock.calls[1][0])).toStrictEqual( + expect.objectContaining({ + foo: 'bar', + }) + ); + }); + + it('propagates the persistent keys to the child logger instances', () => { + // Prepare + const logger = new Logger({ + persistentKeys: { + foo: 'bar', + }, + }); + + // Act + const childLogger = logger.createChild(); + + // Assess + expect(childLogger.getPersistentLogAttributes()).toEqual({ + foo: 'bar', + }); + }); + + it('includes the X-Ray trace data in the log message', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.objectContaining({ + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + }) + ); + }); + + it('adds persistent keys using the deprecated addPersistentLogAttributes() method', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.addPersistentLogAttributes({ + foo: 'bar', + }); + + // Assess + expect(logger.getPersistentLogAttributes()).toEqual({ + foo: 'bar', + }); + }); + + it('removes a persistent key using the deprecated removePersistentLogAttributes() method', () => { + // Prepare + const logger = new Logger({ + persistentKeys: { + foo: 'bar', + }, + }); + + // Act + logger.removePersistentLogAttributes(['foo']); + logger.info('Hello, world!'); + + // Assess + expect(logSpy).toHaveBeenCalledTimes(1); + expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect.not.objectContaining({ + foo: 'bar', + }) + ); + }); + + it('adds persistent keys using the deprecated setPersistentLogAttributes() method', () => { + // Prepare + const logger = new Logger(); + + // Act + logger.setPersistentLogAttributes({ + foo: 'bar', + }); + + // Assess + expect(logger).toEqual( + expect.objectContaining({ + persistentLogAttributes: { + foo: 'bar', + }, + }) + ); + }); + + it('logs a warning when using both the deprecated persistentLogAttributes and persistentKeys options', () => { + // Prepare + const logger = new Logger({ + persistentKeys: { + foo: 'bar', + }, + persistentLogAttributes: { + bar: 'baz', + }, + } as unknown as ConstructorOptions); + const warnSpy = jest.spyOn(console, 'warn'); + + // Assess + expect(warnSpy).toHaveBeenCalledTimes(1); + expect(warnSpy).toHaveBeenCalledWith( + expect.stringContaining( + 'Both persistentLogAttributes and persistentKeys options were provided. Using persistentKeys as persistentLogAttributes is deprecated and will be removed in future releases' + ) + ); + }); +});