diff --git a/layers/tests/e2e/layerPublisher.test.ts b/layers/tests/e2e/layerPublisher.test.ts index 560015eee5..9f5535c9c0 100644 --- a/layers/tests/e2e/layerPublisher.test.ts +++ b/layers/tests/e2e/layerPublisher.test.ts @@ -145,10 +145,14 @@ describe(`Layers E2E tests, publisher stack`, () => { it( 'should have one info log related to coldstart metric', () => { - const logs = invocationLogs.getFunctionLogs('INFO'); + const logs = invocationLogs.getFunctionLogs(); + const emfLogEntry = logs.find((log) => + log.match( + /{"_aws":{"Timestamp":\d+,"CloudWatchMetrics":\[\{"Namespace":"\S+","Dimensions":\[\["service"\]\],"Metrics":\[\{"Name":"ColdStart","Unit":"Count"\}\]\}\]},"service":"\S+","ColdStart":1}/ + ) + ); - expect(logs.length).toBe(1); - expect(logs[0]).toContain('ColdStart'); + expect(emfLogEntry).toBeDefined(); }, TEST_CASE_TIMEOUT ); diff --git a/packages/commons/src/config/ConfigService.ts b/packages/commons/src/config/ConfigService.ts index e149c27229..df2d69bd81 100644 --- a/packages/commons/src/config/ConfigService.ts +++ b/packages/commons/src/config/ConfigService.ts @@ -35,6 +35,13 @@ abstract class ConfigService { */ public abstract getXrayTraceId(): string | undefined; + /** + * It returns true if the `POWERTOOLS_DEV` environment variable is set to truthy value. + * + * @returns {boolean} + */ + public abstract isDevMode(): boolean; + /** * It returns true if the string value represents a boolean true value. * diff --git a/packages/commons/src/config/EnvironmentVariablesService.ts b/packages/commons/src/config/EnvironmentVariablesService.ts index c422163ad3..0148616c49 100644 --- a/packages/commons/src/config/EnvironmentVariablesService.ts +++ b/packages/commons/src/config/EnvironmentVariablesService.ts @@ -13,11 +13,12 @@ import { ConfigService } from './ConfigService.js'; * @see https://docs.aws.amazon.com/lambda/latest/dg/configuration-envvars.html#configuration-envvars-runtime * @see https://docs.powertools.aws.dev/lambda-typescript/latest/#environment-variables */ -class EnvironmentVariablesService extends ConfigService { +class EnvironmentVariablesService implements ConfigService { /** * @see https://docs.powertools.aws.dev/lambda-typescript/latest/#environment-variables * @protected */ + protected devModeVariable = 'POWERTOOLS_DEV'; protected serviceNameVariable = 'POWERTOOLS_SERVICE_NAME'; // Reserved environment variables private xRayTraceIdVariable = '_X_AMZN_TRACE_ID'; @@ -71,6 +72,15 @@ class EnvironmentVariablesService extends ConfigService { return xRayTraceData?.Sampled === '1'; } + /** + * It returns true if the `POWERTOOLS_DEV` environment variable is set to truthy value. + * + * @returns {boolean} + */ + public isDevMode(): boolean { + return this.isValueTrue(this.get(this.devModeVariable)); + } + /** * It returns true if the string value represents a boolean true value. * diff --git a/packages/commons/tests/unit/EnvironmentVariablesService.test.ts b/packages/commons/tests/unit/EnvironmentVariablesService.test.ts index c7b4c75d19..230e04afb0 100644 --- a/packages/commons/tests/unit/EnvironmentVariablesService.test.ts +++ b/packages/commons/tests/unit/EnvironmentVariablesService.test.ts @@ -162,4 +162,54 @@ describe('Class: EnvironmentVariablesService', () => { } ); }); + + describe('Method: isDevMode', () => { + test('it returns true if the environment variable POWERTOOLS_DEV is "true"', () => { + // Prepare + process.env.POWERTOOLS_DEV = 'true'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.isDevMode(); + + // Assess + expect(value).toEqual(true); + }); + + test('it returns false if the environment variable POWERTOOLS_DEV is "false"', () => { + // Prepare + process.env.POWERTOOLS_DEV = 'false'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.isDevMode(); + + // Assess + expect(value).toEqual(false); + }); + + test('it returns false if the environment variable POWERTOOLS_DEV is NOT set', () => { + // Prepare + process.env.POWERTOOLS_DEV = 'somethingsilly'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.isDevMode(); + + // Assess + expect(value).toEqual(false); + }); + + test('it returns false if the environment variable POWERTOOLS_DEV is "somethingsilly"', () => { + // Prepare + process.env.POWERTOOLS_DEV = 'somethingsilly'; + const service = new EnvironmentVariablesService(); + + // Act + const value = service.isDevMode(); + + // Assess + expect(value).toEqual(false); + }); + }); }); diff --git a/packages/logger/src/config/EnvironmentVariablesService.ts b/packages/logger/src/config/EnvironmentVariablesService.ts index a91ea1316f..8c9b496533 100644 --- a/packages/logger/src/config/EnvironmentVariablesService.ts +++ b/packages/logger/src/config/EnvironmentVariablesService.ts @@ -22,7 +22,6 @@ class EnvironmentVariablesService // Reserved environment variables private awsRegionVariable = 'AWS_REGION'; private currentEnvironmentVariable = 'ENVIRONMENT'; - private devModeVariable = 'POWERTOOLS_DEV'; private functionNameVariable = 'AWS_LAMBDA_FUNCTION_NAME'; private functionVersionVariable = 'AWS_LAMBDA_FUNCTION_VERSION'; private logEventVariable = 'POWERTOOLS_LOGGER_LOG_EVENT'; diff --git a/packages/metrics/src/Metrics.ts b/packages/metrics/src/Metrics.ts index 191b8e4ee6..ab04bf58cb 100644 --- a/packages/metrics/src/Metrics.ts +++ b/packages/metrics/src/Metrics.ts @@ -1,4 +1,5 @@ import type { Callback, Context, Handler } from 'aws-lambda'; +import { Console } from 'node:console'; import { Utility } from '@aws-lambda-powertools/commons'; import type { HandlerMethodDecorator } from '@aws-lambda-powertools/commons/types'; import { EnvironmentVariablesService } from './config/EnvironmentVariablesService.js'; @@ -108,6 +109,18 @@ import { * ``` */ class Metrics extends Utility implements MetricsInterface { + /** + * Console instance used to print logs. + * + * In AWS Lambda, we create a new instance of the Console class so that we can have + * full control over the output of the logs. In testing environments, we use the + * default console instance. + * + * This property is initialized in the constructor in setOptions(). + * + * @private + */ + private console!: Console; private customConfigService?: ConfigServiceInterface; private defaultDimensions: Dimensions = {}; private dimensions: Dimensions = {}; @@ -387,7 +400,7 @@ class Metrics extends Utility implements MetricsInterface { ); } const target = this.serializeMetrics(); - console.log(JSON.stringify(target)); + this.console.log(JSON.stringify(target)); this.clearMetrics(); this.clearDimensions(); this.clearMetadata(); @@ -590,6 +603,24 @@ class Metrics extends Utility implements MetricsInterface { } } + /** + * It initializes console property as an instance of the internal version of Console() class (PR #748) + * or as the global node console if the `POWERTOOLS_DEV' env variable is set and has truthy value. + * + * @private + * @returns {void} + */ + private setConsole(): void { + if (!this.getEnvVarsService().isDevMode()) { + this.console = new Console({ + stdout: process.stdout, + stderr: process.stderr, + }); + } else { + this.console = console; + } + } + /** * Sets the custom config service to be used. * @@ -639,6 +670,7 @@ class Metrics extends Utility implements MetricsInterface { } = options; this.setEnvVarsService(); + this.setConsole(); this.setCustomConfigService(customConfigService); this.setNamespace(namespace); this.setService(serviceName); diff --git a/packages/metrics/src/types/ConfigServiceInterface.ts b/packages/metrics/src/types/ConfigServiceInterface.ts index 81842a691d..ab88b92f11 100644 --- a/packages/metrics/src/types/ConfigServiceInterface.ts +++ b/packages/metrics/src/types/ConfigServiceInterface.ts @@ -2,6 +2,12 @@ interface ConfigServiceInterface { get?(name: string): string; getNamespace(): string; getServiceName(): string; + /** + * It returns the value of the POWERTOOLS_DEV environment variable. + * + * @returns {boolean} + */ + isDevMode(): boolean; } export type { ConfigServiceInterface }; diff --git a/packages/metrics/tests/unit/Metrics.test.ts b/packages/metrics/tests/unit/Metrics.test.ts index fa89364024..34c7d488ca 100644 --- a/packages/metrics/tests/unit/Metrics.test.ts +++ b/packages/metrics/tests/unit/Metrics.test.ts @@ -23,6 +23,13 @@ import { import { setupDecoratorLambdaHandler } from '../helpers/metricsUtils.js'; import { EnvironmentVariablesService } from '../../src/config/EnvironmentVariablesService.js'; +jest.mock('node:console', () => ({ + ...jest.requireActual('node:console'), + Console: jest.fn().mockImplementation(() => ({ + log: jest.fn(), + })), +})); +jest.spyOn(console, 'warn').mockImplementation(() => ({})); const mockDate = new Date(1466424490000); const dateSpy = jest.spyOn(global, 'Date').mockImplementation(() => mockDate); jest.spyOn(console, 'log').mockImplementation(); @@ -235,6 +242,9 @@ describe('Class: Metrics', () => { getServiceName(): string { return 'test-service'; }, + isDevMode(): boolean { + return false; + }, }; const metricsOptions: MetricsOptions = { customConfigService: configService, @@ -699,7 +709,7 @@ describe('Class: Metrics', () => { test('it should publish metrics when the array of values reaches the maximum size', () => { // Prepare const metrics: Metrics = new Metrics({ namespace: TEST_NAMESPACE }); - const consoleSpy = jest.spyOn(console, 'log'); + const consoleSpy = jest.spyOn(metrics['console'], 'log'); const metricName = 'test-metric'; // Act @@ -1242,7 +1252,9 @@ describe('Class: Metrics', () => { // Prepare const metrics: Metrics = new Metrics({ namespace: TEST_NAMESPACE }); metrics.addMetric('test-metric', MetricUnit.Count, 10); - const consoleLogSpy = jest.spyOn(console, 'log').mockImplementation(); + const consoleLogSpy = jest + .spyOn(metrics['console'], 'log') + .mockImplementation(); const mockData: EmfOutput = { _aws: { Timestamp: mockDate.getTime(), @@ -1512,7 +1524,7 @@ describe('Class: Metrics', () => { }); // Act - metrics.addMetric(testMetric, MetricUnits.Count, 10); + metrics.addMetric(testMetric, MetricUnit.Count, 10); metrics.addDimension('foo', 'baz'); const loggedData = metrics.serializeMetrics(); @@ -1531,7 +1543,7 @@ describe('Class: Metrics', () => { Metrics: [ { Name: testMetric, - Unit: MetricUnits.Count, + Unit: MetricUnit.Count, }, ], Namespace: TEST_NAMESPACE, @@ -2179,4 +2191,15 @@ describe('Class: Metrics', () => { ); }); }); + + describe('Feature: POWERTOOLS_DEV', () => { + it('uses the global console object when the environment variable is set', () => { + // Prepare + process.env.POWERTOOLS_DEV = 'true'; + const metrics: Metrics = new Metrics({ namespace: TEST_NAMESPACE }); + + // Act & Assess + expect(metrics['console']).toEqual(console); + }); + }); }); diff --git a/packages/metrics/tests/unit/middleware/middy.test.ts b/packages/metrics/tests/unit/middleware/middy.test.ts index 57109fd30d..a3727217ba 100644 --- a/packages/metrics/tests/unit/middleware/middy.test.ts +++ b/packages/metrics/tests/unit/middleware/middy.test.ts @@ -3,22 +3,29 @@ * * @group unit/metrics/middleware */ -import { Metrics, MetricUnit, MetricResolution } from '../../../src/index.js'; +import { Metrics, MetricUnit } from '../../../src/index.js'; import { logMetrics } from '../../../src/middleware/middy.js'; import middy from '@middy/core'; import { ExtraOptions } from '../../../src/types/index.js'; import { cleanupMiddlewares } from '@aws-lambda-powertools/commons'; import context from '@aws-lambda-powertools/testing-utils/context'; -const consoleSpy = jest.spyOn(console, 'log').mockImplementation(); -const consoleWarnSpy = jest.spyOn(console, 'warn').mockImplementation(); +jest.mock('node:console', () => ({ + ...jest.requireActual('node:console'), + Console: jest.fn().mockImplementation(() => ({ + log: jest.fn(), + })), +})); +jest.spyOn(console, 'warn').mockImplementation(() => ({})); const mockDate = new Date(1466424490000); jest.spyOn(global, 'Date').mockImplementation(() => mockDate); describe('Middy middleware', () => { + const ENVIRONMENT_VARIABLES = process.env; + beforeEach(() => { - jest.resetModules(); jest.clearAllMocks(); + process.env = { ...ENVIRONMENT_VARIABLES }; }); const event = { @@ -33,22 +40,13 @@ describe('Middy middleware', () => { namespace: 'serverlessAirline', serviceName: 'orders', }); - - const lambdaHandler = (): void => { - console.log('do nothing'); - }; - - const handler = middy(lambdaHandler).use( + const handler = middy(async (): Promise => undefined).use( logMetrics(metrics, { throwOnEmptyMetrics: true }) ); - try { - await handler(event, context, () => console.log('Lambda invoked!')); - } catch (e) { - expect((e).message).toBe( - 'The number of metrics recorded must be higher than zero' - ); - } + await expect(handler(event, context)).rejects.toThrowError( + 'The number of metrics recorded must be higher than zero' + ); }); test('should not throw on empty metrics if set to false', async () => { @@ -57,20 +55,12 @@ describe('Middy middleware', () => { namespace: 'serverlessAirline', serviceName: 'orders', }); - - const lambdaHandler = (): void => { - console.log('do nothing'); - }; - - const handler = middy(lambdaHandler).use( + const handler = middy(async (): Promise => undefined).use( logMetrics(metrics, { throwOnEmptyMetrics: false }) ); - try { - await handler(event, context, () => console.log('Lambda invoked!')); - } catch (e) { - fail(`Should not throw but got the following Error: ${e}`); - } + // Act & Assess + await expect(handler(event, context)).resolves.not.toThrowError(); }); test('should not throw on empty metrics if not set, but should log a warning', async () => { @@ -79,10 +69,10 @@ describe('Middy middleware', () => { namespace: 'serverlessAirline', serviceName: 'orders', }); - const lambdaHandler = async (): Promise => { - console.log('do nothing'); - }; - const handler = middy(lambdaHandler).use(logMetrics(metrics)); + const consoleWarnSpy = jest.spyOn(console, 'warn').mockImplementation(); + const handler = middy(async (): Promise => undefined).use( + logMetrics([metrics]) + ); // Act & Assess await expect(handler(event, context)).resolves.not.toThrowError(); @@ -100,23 +90,27 @@ describe('Middy middleware', () => { namespace: 'serverlessAirline', serviceName: 'orders', }); - - const lambdaHandler = (): void => { - console.log('{"message": "do nothing"}'); - }; - - const handler = middy(lambdaHandler).use( + const consoleSpy = jest + .spyOn(metrics['console'], 'log') + .mockImplementation(); + // Monkey patch the singleMetric method to return the metrics instance + // so that we can assert on the console output + jest.spyOn(metrics, 'singleMetric').mockImplementation(() => metrics); + + const handler = middy(async (): Promise => undefined).use( logMetrics(metrics, { captureColdStartMetric: true }) ); - await handler(event, context, () => console.log('Lambda invoked!')); - await handler(event, context, () => console.log('Lambda invoked! again')); + // Act + await handler(event, context); + await handler(event, context); + + // Assess const loggedData = [ JSON.parse(consoleSpy.mock.calls[0][0]), JSON.parse(consoleSpy.mock.calls[1][0]), ]; - - expect(console.log).toBeCalledTimes(5); + expect(consoleSpy).toBeCalledTimes(2); expect(loggedData[0]._aws.CloudWatchMetrics[0].Metrics.length).toBe(1); expect(loggedData[0]._aws.CloudWatchMetrics[0].Metrics[0].Name).toBe( 'ColdStart' @@ -133,23 +127,23 @@ describe('Middy middleware', () => { namespace: 'serverlessAirline', serviceName: 'orders', }); - - const lambdaHandler = (): void => { - console.log('{"message": "do nothing"}'); - }; - - const handler = middy(lambdaHandler).use( + const consoleSpy = jest + .spyOn(metrics['console'], 'log') + .mockImplementation(); + // Monkey patch the singleMetric method to return the metrics instance + // so that we can assert on the console output + jest.spyOn(metrics, 'singleMetric').mockImplementation(() => metrics); + const handler = middy(async (): Promise => undefined).use( logMetrics(metrics, { captureColdStartMetric: false }) ); - await handler(event, context, () => console.log('Lambda invoked!')); - await handler(event, context, () => console.log('Lambda invoked! again')); - const loggedData = [ - JSON.parse(consoleSpy.mock.calls[0][0]), - JSON.parse(consoleSpy.mock.calls[1][0]), - ]; + // Act + await handler(event, context); + + // Assess + const loggedData = JSON.parse(consoleSpy.mock.calls[0][0]); - expect(loggedData[0]._aws).toBe(undefined); + expect(loggedData._aws.CloudWatchMetrics[0].Metrics.length).toBe(0); }); test('should not throw on empty metrics if not set', async () => { @@ -158,21 +152,12 @@ describe('Middy middleware', () => { namespace: 'serverlessAirline', serviceName: 'orders', }); + const handler = middy(async (): Promise => undefined).use( + logMetrics(metrics) + ); - const lambdaHandler = (): void => { - console.log('{"message": "do nothing"}'); - }; - - const handler = middy(lambdaHandler).use(logMetrics(metrics)); - - await handler(event, context, () => console.log('Lambda invoked!')); - await handler(event, context, () => console.log('Lambda invoked! again')); - const loggedData = [ - JSON.parse(consoleSpy.mock.calls[0][0]), - JSON.parse(consoleSpy.mock.calls[1][0]), - ]; - - expect(loggedData[0]._aws).toBe(undefined); + // Act & Assess + await expect(handler(event, context)).resolves.not.toThrow(); }); }); @@ -183,19 +168,17 @@ describe('Middy middleware', () => { namespace: 'serverlessAirline', serviceName: 'orders', }); - - const lambdaHandler = (): void => { + const cosoleSpy = jest.spyOn(metrics['console'], 'log'); + const handler = middy(async (): Promise => { metrics.addMetric('successfulBooking', MetricUnit.Count, 2); metrics.addMetric('successfulBooking', MetricUnit.Count, 1); - }; - - const handler = middy(lambdaHandler).use(logMetrics(metrics)); + }).use(logMetrics(metrics)); // Act - await handler(event, context, () => console.log('Lambda invoked!')); + await handler(event, context); // Assess - expect(console.log).toHaveBeenNthCalledWith( + expect(cosoleSpy).toHaveBeenNthCalledWith( 1, JSON.stringify({ _aws: { @@ -220,47 +203,22 @@ describe('Middy middleware', () => { namespace: 'serverlessAirline', serviceName: 'orders', }); - - const lambdaHandler = (): void => { - metrics.addMetric('successfulBooking', MetricUnit.Count, 1); - }; + const consoleSpy = jest.spyOn(metrics['console'], 'log'); const metricsOptions: ExtraOptions = { throwOnEmptyMetrics: true, defaultDimensions: { environment: 'prod', aws_region: 'eu-west-1' }, captureColdStartMetric: true, }; - const handler = middy(lambdaHandler).use( - logMetrics(metrics, metricsOptions) - ); + const handler = middy(async (): Promise => { + metrics.addMetric('successfulBooking', MetricUnit.Count, 1); + }).use(logMetrics(metrics, metricsOptions)); // Act - await handler(event, context, () => console.log('Lambda invoked!')); + await handler(event, context); // Assess - expect(console.log).toHaveBeenNthCalledWith( + expect(consoleSpy).toHaveBeenNthCalledWith( 1, - JSON.stringify({ - _aws: { - Timestamp: 1466424490000, - CloudWatchMetrics: [ - { - Namespace: 'serverlessAirline', - Dimensions: [ - ['service', 'environment', 'aws_region', 'function_name'], - ], - Metrics: [{ Name: 'ColdStart', Unit: 'Count' }], - }, - ], - }, - service: 'orders', - environment: 'prod', - aws_region: 'eu-west-1', - function_name: 'foo-bar-function', - ColdStart: 1, - }) - ); - expect(console.log).toHaveBeenNthCalledWith( - 2, JSON.stringify({ _aws: { Timestamp: 1466424490000, @@ -286,18 +244,16 @@ describe('Middy middleware', () => { namespace: 'serverlessAirline', serviceName: 'orders', }); - - const lambdaHandler = (): void => { + const consoleSpy = jest.spyOn(metrics['console'], 'log'); + const handler = middy(async (): Promise => { metrics.addMetric('successfulBooking', MetricUnit.Count, 1); - }; - - const handler = middy(lambdaHandler).use(logMetrics(metrics)); + }).use(logMetrics(metrics)); // Act - await handler(event, context, () => console.log('Lambda invoked!')); + await handler(event, context); // Assess - expect(console.log).toHaveBeenNthCalledWith( + expect(consoleSpy).toHaveBeenNthCalledWith( 1, JSON.stringify({ _aws: { @@ -322,22 +278,20 @@ describe('Middy middleware', () => { namespace: 'serverlessAirline', serviceName: 'orders', }); - - const lambdaHandler = (): void => { + const consoleSpy = jest.spyOn(metrics['console'], 'log'); + const handler = middy(async (): Promise => { metrics.addMetric('successfulBooking', MetricUnit.Count, 1); - }; - const metricsOptions: ExtraOptions = { - throwOnEmptyMetrics: true, - }; - const handler = middy(lambdaHandler).use( - logMetrics([metrics], metricsOptions) + }).use( + logMetrics(metrics, { + throwOnEmptyMetrics: true, + }) ); // Act - await handler(event, context, () => console.log('Lambda invoked!')); + await handler(event, context); // Assess - expect(console.log).toHaveBeenNthCalledWith( + expect(consoleSpy).toHaveBeenNthCalledWith( 1, JSON.stringify({ _aws: { @@ -400,96 +354,4 @@ describe('Middy middleware', () => { expect(publishStoredMetricsSpy).toBeCalledTimes(2); }); }); - describe('Metrics resolution', () => { - test('serialized metrics in EMF format should not contain `StorageResolution` as key if `60` is set', async () => { - // Prepare - const metrics = new Metrics({ - namespace: 'serverlessAirline', - serviceName: 'orders', - }); - - const lambdaHandler = (): void => { - metrics.addMetric( - 'successfulBooking', - MetricUnit.Count, - 1, - MetricResolution.Standard - ); - }; - - const handler = middy(lambdaHandler).use(logMetrics(metrics)); - - // Act - await handler(event, context, () => console.log('Lambda invoked!')); - - // Assess - expect(console.log).toHaveBeenCalledWith( - JSON.stringify({ - _aws: { - Timestamp: 1466424490000, - CloudWatchMetrics: [ - { - Namespace: 'serverlessAirline', - Dimensions: [['service']], - Metrics: [ - { - Name: 'successfulBooking', - Unit: 'Count', - }, - ], - }, - ], - }, - service: 'orders', - successfulBooking: 1, - }) - ); - }); - - test('Should be StorageResolution `1` if MetricResolution is set to `High`', async () => { - // Prepare - const metrics = new Metrics({ - namespace: 'serverlessAirline', - serviceName: 'orders', - }); - - const lambdaHandler = (): void => { - metrics.addMetric( - 'successfulBooking', - MetricUnit.Count, - 1, - MetricResolution.High - ); - }; - - const handler = middy(lambdaHandler).use(logMetrics(metrics)); - - // Act - await handler(event, context, () => console.log('Lambda invoked!')); - - // Assess - expect(console.log).toHaveBeenCalledWith( - JSON.stringify({ - _aws: { - Timestamp: 1466424490000, - CloudWatchMetrics: [ - { - Namespace: 'serverlessAirline', - Dimensions: [['service']], - Metrics: [ - { - Name: 'successfulBooking', - Unit: 'Count', - StorageResolution: 1, - }, - ], - }, - ], - }, - service: 'orders', - successfulBooking: 1, - }) - ); - }); - }); });