diff --git a/.github/workflows/reusable-run-linting-check-and-unit-tests.yml b/.github/workflows/reusable-run-linting-check-and-unit-tests.yml index b6e8a36e95..9f5e7354de 100644 --- a/.github/workflows/reusable-run-linting-check-and-unit-tests.yml +++ b/.github/workflows/reusable-run-linting-check-and-unit-tests.yml @@ -43,9 +43,10 @@ jobs: workspace: [ "packages/batch", "packages/commons", - "packages/jmespath", + "packages/event-handler", "packages/idempotency", - "packages/event-handler" + "packages/jmespath", + "packages/logger", ] fail-fast: false steps: @@ -88,15 +89,13 @@ jobs: nodeVersion: ${{ matrix.version }} - name: Run linting run: | - npm run lint -w packages/logger \ - -w packages/tracer \ + npm run lint -w -w packages/tracer \ -w packages/metrics \ -w packages/parameters \ -w packages/parser - name: Run unit tests run: | - npm t -w packages/logger \ - -w packages/tracer \ + npm t -w packages/tracer \ -w packages/metrics \ -w packages/parameters \ -w packages/parser diff --git a/.husky/pre-push b/.husky/pre-push index 29e324aa7b..2b304916c9 100755 --- a/.husky/pre-push +++ b/.husky/pre-push @@ -1,5 +1,4 @@ npm t \ - -w packages/logger \ -w packages/metrics \ -w packages/tracer \ -w packages/parameters \ diff --git a/packages/logger/package.json b/packages/logger/package.json index 56272630ea..79e27f5ff1 100644 --- a/packages/logger/package.json +++ b/packages/logger/package.json @@ -10,9 +10,10 @@ "access": "public" }, "scripts": { - "test": "npm run test:unit", - "test:unit": "jest --group=unit --detectOpenHandles --coverage --verbose", - "jest": "jest --detectOpenHandles --verbose", + "test": "vitest --run tests/unit", + "test:unit": "vitest --run tests/unit", + "test:unit:coverage": "vitest --run tests/unit --coverage.enabled --coverage.thresholds.100 --coverage.include='src/**'", + "test:unit:types": "echo 'Not Implemented'", "test:e2e:nodejs18x": "RUNTIME=nodejs18x jest --group=e2e", "test:e2e:nodejs20x": "RUNTIME=nodejs20x jest --group=e2e", "test:e2e": "jest --group=e2e", diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index de806ac146..647f5e4ada 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -418,8 +418,7 @@ class Logger extends Utility implements LoggerInterface { /** * @deprecated This method is deprecated and will be removed in the future major versions. Use {@link resetKeys()} instead. */ - /* istanbul ignore next */ - public static injectLambdaContextAfterOrOnError( + /* v8 ignore start */ public static injectLambdaContextAfterOrOnError( logger: Logger, _persistentAttributes: LogAttributes, options?: InjectLambdaContextOptions @@ -427,7 +426,7 @@ class Logger extends Utility implements LoggerInterface { if (options && (options.clearState || options?.resetKeys)) { logger.resetKeys(); } - } + } /* v8 ignore stop */ /** * @deprecated - This method is deprecated and will be removed in the next major version. diff --git a/packages/logger/tests/tsconfig.json b/packages/logger/tests/tsconfig.json index 45ba862a85..195239b807 100644 --- a/packages/logger/tests/tsconfig.json +++ b/packages/logger/tests/tsconfig.json @@ -1,8 +1,12 @@ { "extends": "../tsconfig.json", "compilerOptions": { - "rootDir": "../", + "rootDir": "../../", "noEmit": true }, - "include": ["../src/**/*", "./**/*"] -} + "include": [ + "../../testing/src/setupEnv.ts", + "../src/**/*", + "./**/*" + ] +} \ No newline at end of file diff --git a/packages/logger/tests/unit/configFromEnv.test.ts b/packages/logger/tests/unit/configFromEnv.test.ts index 905f343e66..87cf414d31 100644 --- a/packages/logger/tests/unit/configFromEnv.test.ts +++ b/packages/logger/tests/unit/configFromEnv.test.ts @@ -1,16 +1,10 @@ -/** - * Test Logger EnvironmentVariablesService class - * - * @group unit/logger/config - */ -import { beforeEach, describe, expect, it, jest } from '@jest/globals'; +import { beforeEach, describe, expect, it } from 'vitest'; import { EnvironmentVariablesService } from '../../src/config/EnvironmentVariablesService.js'; describe('Class: EnvironmentVariablesService', () => { const ENVIRONMENT_VARIABLES = process.env; beforeEach(() => { - jest.resetModules(); process.env = { ...ENVIRONMENT_VARIABLES }; }); diff --git a/packages/logger/tests/unit/formatters.test.ts b/packages/logger/tests/unit/formatters.test.ts index 7bdde1ff4d..3250b95d69 100644 --- a/packages/logger/tests/unit/formatters.test.ts +++ b/packages/logger/tests/unit/formatters.test.ts @@ -1,17 +1,5 @@ -/** - * Test Logger formatter - * - * @group unit/logger/logFormatter - */ import { AssertionError } from 'node:assert'; -import { - afterAll, - beforeEach, - describe, - expect, - it, - jest, -} from '@jest/globals'; +import { afterAll, beforeEach, describe, expect, it, vi } from 'vitest'; import { EnvironmentVariablesService } from '../../src/config/EnvironmentVariablesService.js'; import { PowertoolsLogFormatter } from '../../src/formatter/PowertoolsLogFormatter.js'; import { @@ -73,8 +61,6 @@ const unformattedAttributes: UnformattedAttributes = { process.env.POWERTOOLS_DEV = 'true'; -const logSpy = jest.spyOn(console, 'info'); - const logger = new Logger(); const jsonReplacerFn: CustomJsonReplacerFn = (_: string, value: unknown) => @@ -120,14 +106,13 @@ describe('Formatters', () => { beforeEach(() => { process.env = { ...ENVIRONMENT_VARIABLES }; const mockDate = new Date(1466424490000); - jest.useFakeTimers().setSystemTime(mockDate); - jest.resetAllMocks(); + vi.useFakeTimers().setSystemTime(mockDate); + vi.resetAllMocks(); unformattedAttributes.timestamp = mockDate; }); afterAll(() => { - jest.useRealTimers(); - unformattedAttributes.timestamp = new Date(); + vi.useRealTimers(); }); // #region base log keys @@ -477,7 +462,7 @@ describe('Formatters', () => { 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); + vi.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(240); // Act const timestamp = formatterWithEnv.formatTimestamp(new Date()); @@ -493,7 +478,7 @@ describe('Formatters', () => { 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); + vi.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(240); // Act const timestamp = formatterWithEnv.formatTimestamp(new Date()); @@ -509,7 +494,7 @@ describe('Formatters', () => { 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); + vi.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(240); // Act const timestamp = formatterWithEnv.formatTimestamp(new Date()); @@ -521,12 +506,12 @@ describe('Formatters', () => { 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')); + vi.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); + vi.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(-360); const formatter = new PowertoolsLogFormatter({ envVarsService: new EnvironmentVariablesService(), }); @@ -542,12 +527,12 @@ describe('Formatters', () => { // Prepare process.env.TZ = 'Asia/Dhaka'; const mockDate = new Date('2016-06-20T20:08:10.910Z'); - jest.useFakeTimers().setSystemTime(mockDate); + vi.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); + vi.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(-360); const formatter = new PowertoolsLogFormatter({ envVarsService: new EnvironmentVariablesService(), }); @@ -566,7 +551,7 @@ describe('Formatters', () => { 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); + vi.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(-360); const formatter = new PowertoolsLogFormatter(); // Act @@ -579,7 +564,7 @@ describe('Formatters', () => { 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); + vi.spyOn(Date.prototype, 'getTimezoneOffset').mockReturnValue(0); const formatter = new PowertoolsLogFormatter({ envVarsService: new EnvironmentVariablesService(), }); @@ -676,8 +661,9 @@ describe('Formatters', () => { logger.info('foo', { circularObject }); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ level: 'INFO', message: 'foo', @@ -696,8 +682,9 @@ describe('Formatters', () => { logger.info('foo', bigIntValue); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ level: 'INFO', message: 'foo', @@ -720,8 +707,9 @@ describe('Formatters', () => { logger.info('foo', values); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ level: 'INFO', message: 'foo', @@ -738,8 +726,9 @@ describe('Formatters', () => { loggerWithReplacer.info('foo', valueWithSet); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ level: 'INFO', message: 'foo', @@ -759,8 +748,9 @@ describe('Formatters', () => { loggerWithReplacer.info('foo', valueWithSetAndBigInt); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ level: 'INFO', message: 'foo', @@ -778,8 +768,9 @@ describe('Formatters', () => { childLogger.info('foo', { foo: new Set([1, 2]) }); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ level: 'INFO', message: 'foo', @@ -795,8 +786,8 @@ describe('Formatters', () => { loggerWithCustomLogFormatter.info('foo'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual({ + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth(1, { logLevel: 12, message: 'foo', timestamp: expect.any(String), @@ -811,8 +802,8 @@ describe('Formatters', () => { childLogger.info('foo'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toEqual({ + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth(1, { 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 index 4cc6310fcc..28bc5aa942 100644 --- a/packages/logger/tests/unit/initializeLogger.test.ts +++ b/packages/logger/tests/unit/initializeLogger.test.ts @@ -1,20 +1,13 @@ -/** - * Logger log levels tests - * - * @group unit/logger/logger/logLevels - */ -import { beforeEach, describe, expect, it, jest } from '@jest/globals'; +import { type Mock, beforeEach, describe, expect, it, vi } from 'vitest'; 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(); + vi.resetAllMocks(); }); it('uses the default service name when none is provided', () => { @@ -26,8 +19,9 @@ describe('Log levels', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ service: 'service_undefined' }) ); }); @@ -41,8 +35,9 @@ describe('Log levels', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ service: 'hello-world' }) ); }); @@ -56,8 +51,9 @@ describe('Log levels', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ service: 'hello-world' }) ); }); @@ -72,15 +68,15 @@ describe('Log levels', () => { childLogger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, 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, @@ -93,8 +89,9 @@ describe('Log levels', () => { childLogger.debug('Hello, world!'); // Assess - expect(debugSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(debugSpy.mock.calls[0][0])).toStrictEqual( + expect(console.debug).toHaveBeenCalledTimes(1); + expect(console.debug).toHaveLoggedNth( + 1, expect.objectContaining({ service: 'child-service', foo: 'bar', @@ -105,15 +102,6 @@ describe('Log levels', () => { it('`logRecordOrder` should be passed down to child logger', () => { // Prepare - const logger = new Logger({ logRecordOrder: ['service', 'timestamp'] }); - const childLogger = logger.createChild({ serviceName: 'child-service' }); - - // Act - logger.info('Hello, world!'); - childLogger.info('Hello, world from child!'); - - // Assess - expect(logSpy).toHaveBeenCalledTimes(2); const expectedKeys = [ 'service', 'timestamp', @@ -122,9 +110,19 @@ describe('Log levels', () => { 'sampling_rate', 'xray_trace_id', ]; - logSpy.mock.calls.forEach((call, index) => { - expect(Object.keys(JSON.parse(call[0]))).toEqual(expectedKeys); - }); + const logger = new Logger({ logRecordOrder: ['service', 'timestamp'] }); + const childLogger = logger.createChild({ serviceName: 'child-service' }); + + // Act + logger.info('Hello, world!'); + childLogger.info('Hello, world from child!'); + + // Assess + expect(console.info).toHaveBeenCalledTimes(2); + // For this test don't care about the values, just the order of the keys + const calls = (console.info as Mock).mock.calls; + expect(Object.keys(JSON.parse(calls[0][0]))).toEqual(expectedKeys); + expect(Object.keys(JSON.parse(calls[1][0]))).toEqual(expectedKeys); }); it("doesn't use the global console object by default", () => { @@ -140,29 +138,29 @@ describe('Log levels', () => { it('uses pretty print when POWERTOOLS_DEV is set', () => { // Prepare const mockDate = new Date(1466424490000); - jest.useFakeTimers().setSystemTime(mockDate); + vi.useFakeTimers().setSystemTime(mockDate); const logger = new Logger(); // Act logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(logSpy).toHaveBeenCalledWith( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveBeenCalledWith( JSON.stringify( { level: 'INFO', message: 'Hello, world!', sampling_rate: 0, - service: 'hello-world', + service: 'service_undefined', timestamp: '2016-06-20T12:08:10.000Z', - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + xray_trace_id: '1-abcdef12-3456abcdef123456abcdef12', }, null, LogJsonIndent.PRETTY ) ); - jest.useRealTimers(); + vi.useRealTimers(); }); }); diff --git a/packages/logger/tests/unit/injectLambdaContext.test.ts b/packages/logger/tests/unit/injectLambdaContext.test.ts index edff5790a5..07a76e151d 100644 --- a/packages/logger/tests/unit/injectLambdaContext.test.ts +++ b/packages/logger/tests/unit/injectLambdaContext.test.ts @@ -1,12 +1,7 @@ -/** - * 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 { beforeEach, describe, expect, it, vi } from 'vitest'; import { Logger } from '../../src/Logger.js'; import { injectLambdaContext } from '../../src/middleware/middy.js'; @@ -23,8 +18,6 @@ const getContextLogEntries = (overrides?: Record) => ({ ...overrides, }); -const logSpy = jest.spyOn(console, 'info'); - describe('Inject Lambda Context', () => { const ENVIRONMENT_VARIABLES = process.env; @@ -33,7 +26,7 @@ describe('Inject Lambda Context', () => { ...ENVIRONMENT_VARIABLES, POWERTOOLS_DEV: 'true', }; - jest.resetAllMocks(); + vi.resetAllMocks(); }); it('adds the context to log messages when the feature is enabled', () => { @@ -45,8 +38,9 @@ describe('Inject Lambda Context', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ message: 'Hello, world!', ...getContextLogEntries(), @@ -68,8 +62,9 @@ describe('Inject Lambda Context', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(2); - expect(JSON.parse(logSpy.mock.calls[1][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(2); + expect(console.info).toHaveLoggedNth( + 2, expect.objectContaining({ message: 'Hello, world!', ...getContextLogEntries({ @@ -91,8 +86,9 @@ describe('Inject Lambda Context', () => { await handler(event, context); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ message: 'Hello, world!', ...getContextLogEntries(), @@ -113,15 +109,17 @@ describe('Inject Lambda Context', () => { await handler(event, context); // Assess - expect(logSpy).toHaveBeenCalledTimes(2); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(2); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ message: 'Hello, world!', service: 'parent', ...getContextLogEntries(), }) ); - expect(JSON.parse(logSpy.mock.calls[1][0])).toStrictEqual( + expect(console.info).toHaveLoggedNth( + 2, expect.objectContaining({ message: 'Hello, world!', service: 'child', @@ -156,8 +154,9 @@ describe('Inject Lambda Context', () => { await handler(event, context); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ message: 'Hello, world!', ...getContextLogEntries(), @@ -175,8 +174,9 @@ describe('Inject Lambda Context', () => { childLogger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ message: 'Hello, world!', service: 'child', diff --git a/packages/logger/tests/unit/logEvent.test.ts b/packages/logger/tests/unit/logEvent.test.ts index 2ac66c11ef..17ed444534 100644 --- a/packages/logger/tests/unit/logEvent.test.ts +++ b/packages/logger/tests/unit/logEvent.test.ts @@ -1,12 +1,7 @@ -/** - * 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 { beforeEach, describe, expect, it, vi } from 'vitest'; import { Logger } from '../../src/Logger.js'; import { injectLambdaContext } from '../../src/middleware/middy.js'; @@ -14,8 +9,6 @@ const event = { foo: 'bar', }; -const logSpy = jest.spyOn(console, 'info'); - describe('Log event', () => { const ENVIRONMENT_VARIABLES = process.env; @@ -25,7 +18,7 @@ describe('Log event', () => { POWERTOOLS_LOGGER_LOG_EVENT: 'true', POWERTOOLS_DEV: 'true', }; - jest.resetAllMocks(); + vi.resetAllMocks(); }); it('logs the event with the correct log level and message', () => { @@ -36,10 +29,8 @@ describe('Log event', () => { logger.logEventIfEnabled(event); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( - expect.objectContaining({ event }) - ); + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth(1, expect.objectContaining({ event })); }); it("doesn't log the event when the feature is disabled", () => { @@ -51,7 +42,7 @@ describe('Log event', () => { logger.logEventIfEnabled(event); // Assess - expect(logSpy).not.toHaveBeenCalled(); + expect(console.info).not.toHaveBeenCalled(); }); it('respects the overwrite flag when provided', () => { @@ -62,7 +53,7 @@ describe('Log event', () => { logger.logEventIfEnabled(event, false); // Assess - expect(logSpy).not.toHaveBeenCalled(); + expect(console.info).not.toHaveBeenCalled(); }); it('logs the event when logEvent is set in the Middy.js middleware', async () => { @@ -76,8 +67,9 @@ describe('Log event', () => { await handler(event, context); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ event, function_arn: @@ -104,8 +96,9 @@ describe('Log event', () => { await handler(event, context); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ event, function_arn: @@ -129,7 +122,7 @@ describe('Log event', () => { await handler(event, context); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); + expect(console.info).toHaveBeenCalledTimes(1); }); it('passes down the log event configuration to child loggers', () => { @@ -142,6 +135,6 @@ describe('Log event', () => { childLogger.logEventIfEnabled(event); // Assess - expect(logSpy).not.toHaveBeenCalled(); + expect(console.info).not.toHaveBeenCalled(); }); }); diff --git a/packages/logger/tests/unit/logLevels.test.ts b/packages/logger/tests/unit/logLevels.test.ts index f5017436c7..1e92f302d9 100644 --- a/packages/logger/tests/unit/logLevels.test.ts +++ b/packages/logger/tests/unit/logLevels.test.ts @@ -1,11 +1,7 @@ -/** - * Logger log levels tests - * - * @group unit/logger/logger/logLevels - */ -import { beforeEach, describe, expect, it, jest } from '@jest/globals'; +import { beforeEach, describe, expect, it, vi } from 'vitest'; import { Logger } from '../../src/Logger.js'; import { LogLevel, LogLevelThreshold } from '../../src/constants.js'; +import type { ConfigServiceInterface } from '../../src/types/ConfigServiceInterface.js'; import type { LogFunction, LogLevel as LogLevelType, @@ -38,7 +34,7 @@ describe('Log levels', () => { beforeEach(() => { process.env = { ...ENVIRONMENT_VARIABLES, POWERTOOLS_DEV: 'true' }; - jest.resetAllMocks(); + vi.resetAllMocks(); }); it('sets the correct log level when initialized with a log level', () => { @@ -96,6 +92,36 @@ describe('Log levels', () => { ); }); + it('sets the correct log level when setting the POWERTOOLS_LOG_LEVEL environment variable', () => { + // Prepare + process.env.POWERTOOLS_LOG_LEVEL = LogLevel.CRITICAL; + + // Act + const logger = new Logger(); + + // Assess + expect(logger.level).toBe(LogLevelThreshold.CRITICAL); + expect(logger.getLevelName()).toBe(LogLevel.CRITICAL); + }); + + it('sets the correct log level when using a custom config service', () => { + // Prepare + process.env.POWERTOOLS_LOG_LEVEL = undefined; + const customConfigService = { + getLogLevel: () => LogLevel.WARN, + getCurrentEnvironment: vi.fn(), + getServiceName: vi.fn(), + getSampleRateValue: vi.fn(), + } as unknown as ConfigServiceInterface; + + // Act + const logger = new Logger({ customConfigService }); + + // Assess + expect(logger.level).toBe(LogLevelThreshold.WARN); + expect(logger.getLevelName()).toBe(LogLevel.WARN); + }); + it.each([ { level: LogLevel.TRACE }, { level: LogLevel.DEBUG }, @@ -105,15 +131,17 @@ describe('Log levels', () => { { level: LogLevel.CRITICAL }, ])('logs at the correct level when calling $level()', ({ level }) => { // Prepare - const logSpy = jest.spyOn(console, getConsoleMethod(level)); + const consoleMethod = 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)); + expect(console[consoleMethod]).toHaveBeenCalledTimes(1); + expect(console[consoleMethod]).toHaveLogged( + expect.objectContaining({ level: level }) + ); }); it.each([ @@ -126,14 +154,14 @@ describe('Log levels', () => { "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 consoleMethod = getConsoleMethod(moreVerboseLevel); const logger = new Logger({ logLevel: level }); // Act logger[moreVerboseLevel.toLowerCase() as keyof LogFunction]('foo'); // Assess - expect(logSpy).not.toHaveBeenCalled(); + expect(console[consoleMethod]).not.toHaveBeenCalled(); } ); @@ -147,14 +175,14 @@ describe('Log levels', () => { '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 consoleMethod = getConsoleMethod(lessVerboseLevel); const logger = new Logger({ logLevel: level }); // Act logger[lessVerboseLevel.toLowerCase() as keyof LogFunction]('foo'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); + expect(console[consoleMethod]).toHaveBeenCalledTimes(1); } ); @@ -164,7 +192,7 @@ describe('Log levels', () => { process.env.LOG_LEVEL = undefined; process.env.POWERTOOLS_LOG_LEVEL = undefined; const logger = new Logger(); - const warningSpy = jest.spyOn(logger, 'warn'); + const warningSpy = vi.spyOn(logger, 'warn'); // Act logger.setLogLevel(LogLevel.WARN); @@ -183,7 +211,7 @@ describe('Log levels', () => { 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'); + const warningSpy = vi.spyOn(console, 'warn'); // Act const logger = new Logger({ logLevel: LogLevel.DEBUG }); diff --git a/packages/logger/tests/unit/sampling.test.ts b/packages/logger/tests/unit/sampling.test.ts index 2f8e0ce959..086be99908 100644 --- a/packages/logger/tests/unit/sampling.test.ts +++ b/packages/logger/tests/unit/sampling.test.ts @@ -1,9 +1,4 @@ -/** - * Log Sampling - * - * @group unit/logger/logger/sampling - */ -import { beforeEach, describe, expect, it, jest } from '@jest/globals'; +import { beforeEach, describe, expect, it } from 'vitest'; import { EnvironmentVariablesService } from '../../src/config/EnvironmentVariablesService.js'; import { LogLevel, LogLevelThreshold, Logger } from '../../src/index.js'; @@ -20,8 +15,6 @@ class CustomConfigService extends EnvironmentVariablesService { } } -const logSpy = jest.spyOn(console, 'info'); - describe('Log sampling', () => { const ENVIRONMENT_VARIABLES = process.env; @@ -30,16 +23,16 @@ describe('Log sampling', () => { }); 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') + expect(console.debug).toHaveBeenCalledTimes(1); + expect(console.debug).toHaveLoggedNth( + 1, + expect.objectContaining({ + message: 'Setting log level to DEBUG due to sampling rate', + }) ); }); @@ -172,8 +165,9 @@ describe('Log sampling', () => { childLogger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ sampling_rate: 0.5 }) ); }); diff --git a/packages/logger/tests/unit/workingWithkeys.test.ts b/packages/logger/tests/unit/workingWithkeys.test.ts index 976ef9aba5..15c8da50d2 100644 --- a/packages/logger/tests/unit/workingWithkeys.test.ts +++ b/packages/logger/tests/unit/workingWithkeys.test.ts @@ -1,18 +1,11 @@ -/** - * 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 { beforeEach, describe, expect, it, vi } from 'vitest'; 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; @@ -21,7 +14,7 @@ describe('Working with keys', () => { ...ENVIRONMENT_VARIABLES, POWERTOOLS_DEV: 'true', }; - jest.resetAllMocks(); + vi.resetAllMocks(); }); it.each([ @@ -127,10 +120,8 @@ describe('Working with keys', () => { logger.info(...inputs); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( - expect.objectContaining(expected) - ); + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth(1, expect.objectContaining(expected)); }); it('adds the temporary keys to log messages', () => { @@ -145,14 +136,16 @@ describe('Working with keys', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(2); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(2); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ message: 'Hello, world!', foo: 'bar', }) ); - expect(JSON.parse(logSpy.mock.calls[1][0])).toStrictEqual( + expect(console.info).toHaveLoggedNth( + 2, expect.objectContaining({ message: 'Hello, world!', foo: 'bar', @@ -175,14 +168,16 @@ describe('Working with keys', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(2); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(2); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ message: 'Hello, world!', foo: 'bar', }) ); - expect(JSON.parse(logSpy.mock.calls[1][0])).toStrictEqual( + expect(console.info).toHaveLoggedNth( + 2, expect.objectContaining({ message: 'Hello, world!', foo: 'baz', @@ -203,14 +198,16 @@ describe('Working with keys', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(2); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(2); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ message: 'Hello, world!', foo: 'bar', }) ); - expect(JSON.parse(logSpy.mock.calls[1][0])).toStrictEqual( + expect(console.info).toHaveLoggedNth( + 2, expect.not.objectContaining({ foo: 'bar', }) @@ -229,8 +226,9 @@ describe('Working with keys', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ message: 'Hello, world!', foo: 'bar', @@ -250,8 +248,9 @@ describe('Working with keys', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ message: 'Hello, world!', foo: 'bar', @@ -274,8 +273,9 @@ describe('Working with keys', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ message: 'Hello, world!', foo: 'baz', @@ -297,8 +297,9 @@ describe('Working with keys', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ message: 'Hello, world!', foo: 'baz', @@ -322,8 +323,9 @@ describe('Working with keys', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ message: 'Hello, world!', foo: 'bar', @@ -351,8 +353,9 @@ describe('Working with keys', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.not.objectContaining({ foo: 'bar', }) @@ -375,8 +378,9 @@ describe('Working with keys', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ foo: 'bar', }) @@ -396,8 +400,9 @@ describe('Working with keys', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.not.objectContaining({ foo: 'bar', }) @@ -419,8 +424,9 @@ describe('Working with keys', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ foo: 'bar', }) @@ -448,13 +454,15 @@ describe('Working with keys', () => { await handler(false, context); // Assess - expect(logSpy).toHaveBeenCalledTimes(2); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(2); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ foo: 'baz', }) ); - expect(JSON.parse(logSpy.mock.calls[1][0])).toStrictEqual( + expect(console.info).toHaveLoggedNth( + 2, expect.objectContaining({ foo: 'bar', }) @@ -486,13 +494,15 @@ describe('Working with keys', () => { await handler(false, context); // Assess - expect(logSpy).toHaveBeenCalledTimes(2); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(2); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ foo: 'baz', }) ); - expect(JSON.parse(logSpy.mock.calls[1][0])).toStrictEqual( + expect(console.info).toHaveLoggedNth( + 2, expect.objectContaining({ foo: 'bar', }) @@ -524,10 +534,11 @@ describe('Working with keys', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.objectContaining({ - xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + xray_trace_id: '1-abcdef12-3456abcdef123456abcdef12', }) ); }); @@ -560,8 +571,9 @@ describe('Working with keys', () => { logger.info('Hello, world!'); // Assess - expect(logSpy).toHaveBeenCalledTimes(1); - expect(JSON.parse(logSpy.mock.calls[0][0])).toStrictEqual( + expect(console.info).toHaveBeenCalledTimes(1); + expect(console.info).toHaveLoggedNth( + 1, expect.not.objectContaining({ foo: 'bar', }) @@ -597,14 +609,15 @@ describe('Working with keys', () => { 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' - ) + expect(console.warn).toHaveBeenCalledTimes(1); + expect(console.warn).toHaveLoggedNth( + 1, + expect.objectContaining({ + message: + 'Both persistentLogAttributes and persistentKeys options were provided. Using persistentKeys as persistentLogAttributes is deprecated and will be removed in future releases', + }) ); }); }); diff --git a/packages/logger/vitest.config.ts b/packages/logger/vitest.config.ts new file mode 100644 index 0000000000..9f1196ef1f --- /dev/null +++ b/packages/logger/vitest.config.ts @@ -0,0 +1,8 @@ +import { defineProject } from 'vitest/config'; + +export default defineProject({ + test: { + environment: 'node', + setupFiles: ['../testing/src/setupEnv.ts'], + }, +}); diff --git a/packages/testing/src/setupEnv.ts b/packages/testing/src/setupEnv.ts index 334d7c25c9..f0d7b06c47 100644 --- a/packages/testing/src/setupEnv.ts +++ b/packages/testing/src/setupEnv.ts @@ -11,9 +11,103 @@ vi.spyOn(console, 'debug').mockReturnValue(); vi.spyOn(console, 'info').mockReturnValue(); vi.spyOn(console, 'log').mockReturnValue(); +expect.extend({ + toHaveLogged(received, expected) { + const calls = received.mock.calls; + const messages = new Array(calls.length); + for (const [idx, call] of calls.entries()) { + const [rawMessage] = call; + try { + messages[idx] = JSON.parse(rawMessage); + } catch (error) { + messages[idx] = rawMessage; + } + if (this.equals(messages[idx], expected)) { + return { + message: () => '', + pass: true, + }; + } + } + + return { + message: () => 'Expected function to have logged provided object', + pass: false, + actual: messages, + expected, + }; + }, + toHaveLoggedNth(received, nth, expected) { + const call = received.mock.calls[nth - 1]; + if (!call) { + return { + message: () => + `Expected function to have logged provided object during ${nth} call`, + pass: false, + actual: 'No log found at index', + expected, + }; + } + const [rawMessage] = call; + const message = JSON.parse(rawMessage); + if (this.equals(message, expected)) { + return { + message: () => '', + pass: true, + }; + } + + return { + message: () => 'Expected function to have logged provided object', + pass: false, + actual: message, + expected, + }; + }, +}); + declare module 'vitest' { // biome-ignore lint/suspicious/noExplicitAny: vitest typings expect an any type - interface Assertion extends CustomMatcher {} + interface Assertion extends CustomMatcher { + /** + * Asserts that the logger function has been called with the expected log message + * during any call. + * + * @example + * ```ts + * vi.spyOn(console, 'info').mockReturnValue(); + * + * expect(console.info).toHaveLogged( + * expect.objectContaining({ + * message: 'Hello, world!', + * }) + * ); + * ``` + * + * @param expected - The expected log message + */ + toHaveLogged(expected: Record): void; + /** + * Asserts that the logger function has been called with the expected log message + * during the specific nth call. + * + * @example + * ```ts + * vi.spyOn(console, 'info').mockReturnValue(); + * + * expect(console.info).toHaveLoggedNth( + * 1, + * expect.objectContaining({ + * message: 'Hello, world!', + * }) + * ); + * ``` + * + * @param nth - The index of the call to check + * @param expected - The expected log message + */ + toHaveLoggedNth(nth: number, expected: Record): void; + } interface AsymmetricMatchersContaining extends CustomMatcher {} } diff --git a/vitest.config.ts b/vitest.config.ts index 81203c1290..86ff981bfb 100644 --- a/vitest.config.ts +++ b/vitest.config.ts @@ -18,7 +18,7 @@ export default defineConfig({ 'packages/event-handler/src/types/**', 'packages/idempotency/src/types/**', 'packages/jmespath/src/types.ts', - 'packages/logger/**', + 'packages/logger/src/types/**', 'packages/metrics/**', 'packages/parameters/**', 'packages/parser/**',