diff --git a/CONTRIBUTING.md b/CONTRIBUTING.md index 90921e6df3..bcd69bf3e2 100644 --- a/CONTRIBUTING.md +++ b/CONTRIBUTING.md @@ -238,7 +238,11 @@ You can build and start the API reference website by running these two commands #### Docs website -You can build and start a local docs website by running these two commands: +You can build and start a local docs website by running: + +`npm run docs-website-build-run` + +Alternatively you can run these two commands: * `npm run docs-buildDockerImage` OR `docker build -t squidfunk/mkdocs-material ./docs/` * `npm run docs-runLocalDocker` OR `docker run --rm -it -p 8000:8000 -v ${PWD}:/docs squidfunk/mkdocs-material` diff --git a/docs/core/logger.md b/docs/core/logger.md index fb1c02aed4..621e4c58e1 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -14,9 +14,9 @@ Logger provides an opinionated logger with output structured as JSON. ## Key features -* Capture key fields from Lambda context, cold start and structures logging output as JSON -* Log Lambda context when instructed (disabled by default) -* Log sampling prints all logs for a percentage of invocations (disabled by default) +* Capture key fields from Lambda context, cold start and structure logging output as JSON +* Log Lambda event when instructed (disabled by default) +* Log sampling prints all the logs for a percentage of invocations (disabled by default) * Append additional keys to structured log at any point in time ## Getting started @@ -193,6 +193,50 @@ In each case, the printed log will look like this: } ``` +#### Log incoming event + +When debugging in non-production environments, you can instruct Logger to log the incoming event with the middleware/decorator parameter `logEvent` or via POWERTOOLS_LOGGER_LOG_EVENT env var set to `true`. + +???+ warning +This is disabled by default to prevent sensitive info being logged + +=== "Middy Middleware" + + ```typescript hl_lines="11" + import { Logger, injectLambdaContext } from '@aws-lambda-powertools/logger'; + import middy from '@middy/core'; + + const logger = new Logger(); + + const lambdaHandler = async (_event: any, _context: any): Promise => { + logger.info('This is an INFO log with some context'); + }; + + export const handler = middy(lambdaHandler) + .use(injectLambdaContext(logger, { logEvent: true })); + ``` + +=== "Decorator" + + ```typescript hl_lines="8" + import { Logger } from '@aws-lambda-powertools/logger'; + import { LambdaInterface } from '@aws-lambda-powertools/commons'; + + const logger = new Logger(); + + class Lambda implements LambdaInterface { + // Set the log event flag to true + @logger.injectLambdaContext({ logEvent: true }) + public async handler(_event: any, _context: any): Promise { + logger.info('This is an INFO log with some context'); + } + + } + + export const myFunction = new Lambda(); + export const handler = myFunction.handler; + ``` + ### Appending persistent additional log keys and values You can append additional persistent keys and values in the logs generated during a Lambda invocation using either mechanism: diff --git a/docs/index.md b/docs/index.md index aace91263e..60fb5d621a 100644 --- a/docs/index.md +++ b/docs/index.md @@ -45,20 +45,20 @@ Each TypeScript utility is installed as standalone NPM package. ## Environment variables !!! info - **Explicit parameters take precedence over environment variables.** - -| Environment variable | Description | Utility | Default | -|-------------------------------------------| --------------------------------------------------------------------------------- |---------------------------|-----------------------| -| **POWERTOOLS_SERVICE_NAME** | Sets service name used for tracing namespace, metrics dimension and structured logging | All | `"service_undefined"` | -| **POWERTOOLS_METRICS_NAMESPACE** | Sets namespace used for metrics | [Metrics](./core/metrics) | `None` | -| **POWERTOOLS_TRACE_ENABLED** | Explicitly disables tracing | [Tracer](./core/tracer) | `true` | -| **POWERTOOLS_TRACER_CAPTURE_RESPONSE** | Captures Lambda or method return as metadata. | [Tracer](./core/tracer) | `true` | -| **POWERTOOLS_TRACER_CAPTURE_ERROR** | Captures Lambda or method exception as metadata. | [Tracer](./core/tracer) | `true` | -| **POWERTOOLS_TRACER_CAPTURE_HTTPS_REQUESTS** | Captures HTTP(s) requests as segments. | [Tracer](./core/tracer) | `true` | -| **POWERTOOLS_LOGGER_LOG_EVENT** | Logs incoming event | [Logger](./core/logger) | `false` | -| **POWERTOOLS_LOGGER_SAMPLE_RATE** | Debug log sampling | [Logger](./core/logger) | `0` | -| **POWERTOOLS_LOG_DEDUPLICATION_DISABLED** | Disables log deduplication filter protection to use Pytest Live Log feature | [Logger](./core/logger) | `false` | -| **LOG_LEVEL** | Sets logging level | [Logger](./core/logger) | `INFO` | + **Explicit parameters passed in constructors or in middleware/decorators take precedence over environment variables.** + +| Environment variable | Description | Utility | Default | +|----------------------------------------------|----------------------------------------------------------------------------------------|---------------------------|-----------------------| +| **POWERTOOLS_SERVICE_NAME** | Sets service name used for tracing namespace, metrics dimension and structured logging | All | `"service_undefined"` | +| **POWERTOOLS_METRICS_NAMESPACE** | Sets namespace used for metrics | [Metrics](./core/metrics) | `None` | +| **POWERTOOLS_TRACE_ENABLED** | Explicitly disables tracing | [Tracer](./core/tracer) | `true` | +| **POWERTOOLS_TRACER_CAPTURE_RESPONSE** | Captures Lambda or method return as metadata. | [Tracer](./core/tracer) | `true` | +| **POWERTOOLS_TRACER_CAPTURE_ERROR** | Captures Lambda or method exception as metadata. | [Tracer](./core/tracer) | `true` | +| **POWERTOOLS_TRACER_CAPTURE_HTTPS_REQUESTS** | Captures HTTP(s) requests as segments. | [Tracer](./core/tracer) | `true` | +| **POWERTOOLS_LOGGER_LOG_EVENT** | Logs incoming event | [Logger](./core/logger) | `false` | +| **POWERTOOLS_LOGGER_SAMPLE_RATE** | Debug log sampling | [Logger](./core/logger) | `0` | +| **POWERTOOLS_LOGGER_LOG_EVENT** | Logs incoming events | [Logger](./core/logger) | `false` | +| **LOG_LEVEL** | Sets logging level | [Logger](./core/logger) | `INFO` | ## Examples diff --git a/package.json b/package.json index ca9db89246..19329e669a 100644 --- a/package.json +++ b/package.json @@ -29,8 +29,10 @@ "lerna-preversion": "lerna exec -- npm run lint", "lerna-version": "lerna exec -- npm run format && git add -A src", "postversion": "git push && git push --tags", + "docs-website-build-run": "npm run docs-buildDockerImage && npm run docs-runLocalDocker", "docs-buildDockerImage": "docker build -t powertool-typescript/docs ./docs/", "docs-runLocalDocker": "docker run --rm -it -p 8000:8000 -v ${PWD}:/docs powertool-typescript/docs", + "docs-api-build-run": "npm run docs-generateApiDoc && npx live-server api", "docs-generateApiDoc": "typedoc .", "docs-runLocalApiDoc": "npx live-server api" }, diff --git a/packages/commons/tests/utils/InvocationLogs.ts b/packages/commons/tests/utils/InvocationLogs.ts index 22e1334007..52d8656e40 100644 --- a/packages/commons/tests/utils/InvocationLogs.ts +++ b/packages/commons/tests/utils/InvocationLogs.ts @@ -56,6 +56,14 @@ export class InvocationLogs { return filteredLogs.length > 0; } + /** + * Return all the log of the function + * @returns Array of function logs + */ + public getAllFunctionLogs(): string[] { + return this.logs; + } + /** * Return only logs from function, exclude START, END, and REPORT generated by Lambda service * @param levelToFilter level to filter diff --git a/packages/logger/src/Logger.ts b/packages/logger/src/Logger.ts index c446e9c404..2d84eebd81 100644 --- a/packages/logger/src/Logger.ts +++ b/packages/logger/src/Logger.ts @@ -119,6 +119,8 @@ class Logger extends Utility implements ClassThatLogs { private envVarsService?: EnvironmentVariablesService; + private logEvent: boolean = false; + private logFormatter?: LogFormatterInterface; private logLevel?: LogLevel; @@ -222,6 +224,16 @@ class Logger extends Utility implements ClassThatLogs { this.processLogItem('ERROR', input, extraInput); } + /** + * It returns a boolean value. True means that the Lambda invocation events + * are printed in the logs. + * + * @returns {boolean} + */ + public getLogEvent(): boolean { + return this.logEvent; + } + /** * It returns a boolean value, if true all the logs will be printed. * @@ -280,6 +292,9 @@ class Logger extends Utility implements ClassThatLogs { } this.addContext(context); + if (options) { + this.logEventIfEnabled(event, options.logEvent); + } /* eslint-disable @typescript-eslint/no-non-null-assertion */ const result = originalMethod!.apply(target, [ event, context, callback ]); @@ -293,6 +308,20 @@ class Logger extends Utility implements ClassThatLogs { }; } + /** + * Logs a Lambda invocation event, if it *should*. + * + ** @param {unknown} event + * @param {boolean} [overwriteValue] + * @returns {void} + */ + public logEventIfEnabled(event: unknown, overwriteValue?: boolean): void { + if (!this.shouldLogEvent(overwriteValue)) { + return; + } + this.info('Lambda invocation event', { event }); + } + /** * If the sample rate feature is enabled, the calculation that determines whether the logs * will actually be printed or not for this invocation is done when the Logger class is @@ -353,6 +382,21 @@ class Logger extends Utility implements ClassThatLogs { this.getEnvVarsService().getSampleRateValue(); } + /** + * It checks whether the current Lambda invocation event should be printed in the logs or not. + * + * @private + * @param {boolean} [overwriteValue] + * @returns {boolean} + */ + public shouldLogEvent(overwriteValue?: boolean): boolean { + if (typeof overwriteValue === 'boolean') { + return overwriteValue; + } + + return this.getLogEvent(); + } + /** * It prints a log item with level WARN. * @@ -486,10 +530,10 @@ class Logger extends Utility implements ClassThatLogs { /** * It returns the current X-Ray Trace ID parsing the content of the `_X_AMZN_TRACE_ID` env variable. - * + * * The X-Ray Trace data available in the environment variable has this format: * `Root=1-5759e988-bd862e3fe1be46a994272793;Parent=557abcec3ee5a047;Sampled=1`, - * + * * The actual Trace ID is: `1-5759e988-bd862e3fe1be46a994272793`. * * @private diff --git a/packages/logger/src/config/ConfigService.ts b/packages/logger/src/config/ConfigService.ts index 4f38cf6ae6..6479ab32ee 100644 --- a/packages/logger/src/config/ConfigService.ts +++ b/packages/logger/src/config/ConfigService.ts @@ -19,6 +19,7 @@ abstract class ConfigService implements ConfigServiceInterface { * @protected */ protected currentEnvironmentVariable = 'ENVIRONMENT'; + protected logEventVariable = 'POWERTOOLS_LOGGER_LOG_EVENT'; protected logLevelVariable = 'LOG_LEVEL'; protected sampleRateValueVariable = 'POWERTOOLS_LOGGER_SAMPLE_RATE'; protected serviceNameVariable = 'POWERTOOLS_SERVICE_NAME'; @@ -38,6 +39,13 @@ abstract class ConfigService implements ConfigServiceInterface { */ public abstract getCurrentEnvironment(): string; + /** + * It returns the value of the POWERTOOLS_LOGGER_LOG_EVENT environment variable. + * + * @returns {boolean} + */ + public abstract getLogEvent(): boolean; + /** * It returns the value of the LOG_LEVEL environment variable. * @@ -59,6 +67,17 @@ abstract class ConfigService implements ConfigServiceInterface { */ public abstract getServiceName(): string; + /** + * It returns true if the string value represents a boolean true value. + * + * @param {string} value + * @returns boolean + * @protected + */ + protected isValueTrue(value: string): boolean { + return value.toLowerCase() === 'true' || value === '1'; + } + } export { diff --git a/packages/logger/src/config/ConfigServiceInterface.ts b/packages/logger/src/config/ConfigServiceInterface.ts index 0e9b62a409..1f1a6ecc32 100644 --- a/packages/logger/src/config/ConfigServiceInterface.ts +++ b/packages/logger/src/config/ConfigServiceInterface.ts @@ -22,6 +22,13 @@ interface ConfigServiceInterface { */ getCurrentEnvironment(): string + /** + * It returns the value of the POWERTOOLS_LOGGER_LOG_EVENT environment variable. + * + * @returns {boolean} + */ + getLogEvent(): boolean + /** * It returns the value of the LOG_LEVEL environment variable. * diff --git a/packages/logger/src/config/EnvironmentVariablesService.ts b/packages/logger/src/config/EnvironmentVariablesService.ts index 588af64a01..2484252a65 100644 --- a/packages/logger/src/config/EnvironmentVariablesService.ts +++ b/packages/logger/src/config/EnvironmentVariablesService.ts @@ -79,6 +79,15 @@ class EnvironmentVariablesService extends ConfigService { return this.get(this.functionVersionVariable); } + /** + * It returns the value of the POWERTOOLS_LOGGER_LOG_EVENT environment variable. + * + * @returns {boolean} + */ + public getLogEvent(): boolean { + return this.isValueTrue(this.get(this.logEventVariable)); + } + /** * It returns the value of the LOG_LEVEL environment variable. * diff --git a/packages/logger/src/middleware/middy.ts b/packages/logger/src/middleware/middy.ts index 5768e05397..34af3ac349 100644 --- a/packages/logger/src/middleware/middy.ts +++ b/packages/logger/src/middleware/middy.ts @@ -38,6 +38,9 @@ const injectLambdaContext = (target: Logger | Logger[], options?: HandlerOptions if (options && options.clearState === true) { persistentAttributes.push({ ...logger.getPersistentLogAttributes() }); } + if (options) { + logger.logEventIfEnabled(request.event, options.logEvent); + } }); }; @@ -48,7 +51,7 @@ const injectLambdaContext = (target: Logger | Logger[], options?: HandlerOptions }); } }; - + return { before: injectLambdaContextBefore, after: injectLambdaContextAfter diff --git a/packages/logger/src/types/Logger.ts b/packages/logger/src/types/Logger.ts index c0de42eadc..add56ee28a 100644 --- a/packages/logger/src/types/Logger.ts +++ b/packages/logger/src/types/Logger.ts @@ -9,6 +9,7 @@ type ClassThatLogs = { }; type HandlerOptions = { + logEvent?: boolean clearState?: boolean }; diff --git a/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts b/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts index 30e5323d9a..c434a7892a 100644 --- a/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts +++ b/packages/logger/tests/e2e/basicFeatures.middy.test.FunctionCode.ts @@ -3,6 +3,7 @@ import { Context, APIGatewayAuthorizerResult } from 'aws-lambda'; import middy from '@middy/core'; const PERSISTENT_KEY = process.env.PERSISTENT_KEY; +const PERSISTENT_KEY_FIRST_INVOCATION_ONLY = process.env.PERSISTENT_KEY_FIRST_INVOCATION_ONLY; const PERSISTENT_VALUE = process.env.PERSISTENT_VALUE; const REMOVABLE_KEY = process.env.REMOVABLE_KEY; const REMOVABLE_VALUE = process.env.REMOVABLE_VALUE; @@ -33,7 +34,7 @@ const testFunction = async (event: LambdaEvent, context: Context): Promise<{requ const specialValue = event.invocation; if (specialValue === 0) { logger.appendKeys({ - specialKey: specialValue + [PERSISTENT_KEY_FIRST_INVOCATION_ONLY]: specialValue }); } @@ -72,4 +73,5 @@ const testFunction = async (event: LambdaEvent, context: Context): Promise<{requ }; }; -export const handler = middy(testFunction).use(injectLambdaContext(logger, { clearState: true })); +export const handler = middy(testFunction) + .use(injectLambdaContext(logger, { clearState: true, logEvent: true })); diff --git a/packages/logger/tests/e2e/basicFeatures.middy.test.ts b/packages/logger/tests/e2e/basicFeatures.middy.test.ts index 921d20ee92..4cd268486f 100644 --- a/packages/logger/tests/e2e/basicFeatures.middy.test.ts +++ b/packages/logger/tests/e2e/basicFeatures.middy.test.ts @@ -42,6 +42,7 @@ const lambdaFunctionCodeFile = 'basicFeatures.middy.test.FunctionCode.ts'; // Text to be used by Logger in the Lambda function const PERSISTENT_KEY = 'persistentKey'; +const PERSISTENT_KEY_FIRST_INVOCATION_ONLY = 'specialKey'; const PERSISTENT_VALUE = `a persistent value that will be put in every log ${uuid}`; const REMOVABLE_KEY = 'removableKey'; const REMOVABLE_VALUE = `a persistent value that will be removed and not displayed in any log ${uuid}`; @@ -73,6 +74,7 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime} // Text to be used by Logger in the Lambda function PERSISTENT_KEY, + PERSISTENT_KEY_FIRST_INVOCATION_ONLY, PERSISTENT_VALUE, REMOVABLE_KEY, REMOVABLE_VALUE, @@ -127,9 +129,7 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime} expect(message).not.toContain(`"cold_start":true`); } }, TEST_CASE_TIMEOUT); - }); - describe('Context data', () => { it('should log context information in every log', async () => { const logMessages = invocationLogs[0].getFunctionLogs(); @@ -143,6 +143,34 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime} }, TEST_CASE_TIMEOUT); }); + describe('Log event', () => { + + it('should log the event on the first invocation', async () => { + const firstInvocationMessages = invocationLogs[0].getAllFunctionLogs(); + let eventLoggedInFirstInvocation = false; + for (const message of firstInvocationMessages) { + if (message.includes(`event`)) { + eventLoggedInFirstInvocation = true; + expect(message).toContain(`"event":{"invocation":0}`); + } + } + + const secondInvocationMessages = invocationLogs[1].getAllFunctionLogs(); + let eventLoggedInSecondInvocation = false; + for (const message of secondInvocationMessages) { + if (message.includes(`event`)) { + eventLoggedInSecondInvocation = true; + expect(message).toContain(`"event":{"invocation":1}`); + } + } + + expect(eventLoggedInFirstInvocation).toBe(true); + expect(eventLoggedInSecondInvocation).toBe(true); + + }, TEST_CASE_TIMEOUT); + + }); + describe('Persistent additional log keys and values', () => { it('should contain persistent value in every log', async () => { const logMessages = invocationLogs[0].getFunctionLogs(); @@ -163,12 +191,12 @@ describe(`logger E2E tests basic functionalities (middy) for runtime: ${runtime} it('with clear state enabled, should not persist keys across invocations', async () => { const firstInvocationMessages = invocationLogs[0].getFunctionLogs(); for (const message of firstInvocationMessages) { - expect(message).toContain(`"specialKey":0`); + expect(message).toContain(`"${PERSISTENT_KEY_FIRST_INVOCATION_ONLY}":0`); } const secondInvocationMessages = invocationLogs[1].getFunctionLogs(); for (const message of secondInvocationMessages) { - expect(message).not.toContain(`"specialKey":0`); + expect(message).not.toContain(`"${PERSISTENT_KEY_FIRST_INVOCATION_ONLY}":0`); } }, TEST_CASE_TIMEOUT); }); diff --git a/packages/logger/tests/unit/Logger.test.ts b/packages/logger/tests/unit/Logger.test.ts index ca3a830e05..8fe30c7bc2 100644 --- a/packages/logger/tests/unit/Logger.test.ts +++ b/packages/logger/tests/unit/Logger.test.ts @@ -572,6 +572,7 @@ describe('Class: Logger', () => { coldStart: false, // This is now false because the `coldStart` attribute has been already accessed once by the `addContext` method customConfigService: undefined, envVarsService: expect.any(EnvironmentVariablesService), + logEvent: false, logFormatter: expect.any(PowertoolLogFormatter), logLevel: 'DEBUG', logLevelThresholds: { @@ -808,6 +809,7 @@ describe('Class: Logger', () => { test('when used as decorator, it returns a function with the correct scope of the decorated class', async () => { // Prepare + const logger = new Logger(); const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation(); class LambdaFunction implements LambdaInterface { @@ -1042,6 +1044,7 @@ describe('Class: Logger', () => { coldStart: true, customConfigService: undefined, envVarsService: expect.any(EnvironmentVariablesService), + logEvent: false, logFormatter: expect.any(PowertoolLogFormatter), logLevel: 'DEBUG', logLevelThresholds: { @@ -1065,6 +1068,7 @@ describe('Class: Logger', () => { coldStart: true, customConfigService: undefined, envVarsService: expect.any(EnvironmentVariablesService), + logEvent: false, logFormatter: expect.any(PowertoolLogFormatter), logLevel: 'DEBUG', logLevelThresholds: { @@ -1090,6 +1094,7 @@ describe('Class: Logger', () => { coldStart: true, customConfigService: undefined, envVarsService: expect.any(EnvironmentVariablesService), + logEvent: false, logFormatter: expect.any(PowertoolLogFormatter), logLevel: 'DEBUG', logLevelThresholds: { @@ -1113,6 +1118,7 @@ describe('Class: Logger', () => { coldStart: true, customConfigService: undefined, envVarsService: expect.any(EnvironmentVariablesService), + logEvent: false, logFormatter: expect.any(PowertoolLogFormatter), logLevel: 'ERROR', logLevelThresholds: { @@ -1135,4 +1141,48 @@ describe('Class: Logger', () => { }); + describe('Method: logEventIfEnabled', () => { + + test('When the feature is disabled, it DOES NOT log the event', () => { + + // Prepare + const logger = new Logger(); + const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation(); + + // Act + logger.logEventIfEnabled(dummyEvent); + + // 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(logger['console'], 'info').mockImplementation(); + + // Act + logger.logEventIfEnabled(event, true); + + // Assess + expect(consoleSpy).toBeCalledTimes(1); + expect(consoleSpy).toHaveBeenNthCalledWith(1, JSON.stringify({ + level: 'INFO', + message: 'Lambda invocation event', + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + event: { + something: 'happened!' + } + }, + )); + }); + }); + }); \ No newline at end of file diff --git a/packages/logger/tests/unit/config/EnvironmentVariablesService.test.ts b/packages/logger/tests/unit/config/EnvironmentVariablesService.test.ts index ab810089c8..18d1e29221 100644 --- a/packages/logger/tests/unit/config/EnvironmentVariablesService.test.ts +++ b/packages/logger/tests/unit/config/EnvironmentVariablesService.test.ts @@ -136,6 +136,88 @@ describe('Class: EnvironmentVariablesService', () => { }); + 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 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 true if the environment variable POWERTOOLS_LOGGER_LOG_EVENT is "1"', () => { + + // Prepare + process.env.POWERTOOLS_LOGGER_LOG_EVENT = '1'; + 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 "0"', () => { + + // Prepare + process.env.POWERTOOLS_LOGGER_LOG_EVENT = '0'; + 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', () => { diff --git a/packages/logger/tests/unit/helpers.test.ts b/packages/logger/tests/unit/helpers.test.ts index 931a21c6b8..9309bea207 100644 --- a/packages/logger/tests/unit/helpers.test.ts +++ b/packages/logger/tests/unit/helpers.test.ts @@ -76,6 +76,7 @@ describe('Helper: createLogger function', () => { coldStart: true, customConfigService: expect.any(EnvironmentVariablesService), envVarsService: expect.any(EnvironmentVariablesService), + logEvent: false, logFormatter: expect.any(PowertoolLogFormatter), logLevel: 'WARN', console: expect.any(Console), @@ -115,6 +116,7 @@ describe('Helper: createLogger function', () => { coldStart: true, customConfigService: undefined, envVarsService: expect.any(EnvironmentVariablesService), + logEvent: false, logFormatter: expect.any(PowertoolLogFormatter), logLevel: 'INFO', console: expect.any(Console), @@ -235,6 +237,7 @@ describe('Helper: createLogger function', () => { coldStart: true, customConfigService: undefined, envVarsService: expect.any(EnvironmentVariablesService), + logEvent: false, logFormatter: expect.any(PowertoolLogFormatter), logLevel: 'INFO', console: expect.any(Console), @@ -292,6 +295,9 @@ describe('Helper: createLogger function', () => { getCurrentEnvironment(): string { return 'dev'; }, + getLogEvent(): boolean { + return true; + }, getLogLevel(): string { return 'INFO'; }, diff --git a/packages/logger/tests/unit/middleware/middy.test.ts b/packages/logger/tests/unit/middleware/middy.test.ts index 4601a91300..7c596182a3 100644 --- a/packages/logger/tests/unit/middleware/middy.test.ts +++ b/packages/logger/tests/unit/middleware/middy.test.ts @@ -4,19 +4,23 @@ * @group unit/logger/all */ -import { EnvironmentVariablesService } from '../../../src/config'; +import { ConfigServiceInterface, EnvironmentVariablesService } from '../../../src/config'; import { injectLambdaContext } from '../../../src/middleware/middy'; import { Logger } from './../../../src'; import middy from '@middy/core'; import { PowertoolLogFormatter } from '../../../src/formatter'; import { Console } from 'console'; +const mockDate = new Date(1466424490000); +const dateSpy = jest.spyOn(global, 'Date').mockImplementation(() => mockDate as unknown as string); + describe('Middy middleware', () => { const ENVIRONMENT_VARIABLES = process.env; beforeEach(() => { jest.resetModules(); + dateSpy.mockClear(); jest.spyOn(process.stdout, 'write').mockImplementation(() => null as unknown as boolean); process.env = { ...ENVIRONMENT_VARIABLES }; }); @@ -149,60 +153,185 @@ describe('Middy middleware', () => { }); }); + test('when a logger is passed with option logEvent set to true, it logs the event', async () => { + + // Prepare + const logger = new Logger(); + const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation(); + const lambdaHandler = (): void => { + logger.info('This is an INFO log with some context'); + }; + const handler = middy(lambdaHandler).use(injectLambdaContext(logger , { logEvent: true })); + const event = { foo: 'bar' }; + const getRandomInt = (): number => Math.floor(Math.random() * 1000000000); + const awsRequestId = getRandomInt().toString(); + const context = { + callbackWaitsForEmptyEventLoop: true, + functionVersion: '$LATEST', + functionName: 'foo-bar-function', + memoryLimitInMB: '128', + logGroupName: '/aws/lambda/foo-bar-function', + logStreamName: '2021/03/09/[$LATEST]abcdef123456abcdef123456abcdef123456', + invokedFunctionArn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + awsRequestId: awsRequestId, + getRemainingTimeInMillis: () => 1234, + done: () => console.log('Done!'), + fail: () => console.log('Failed!'), + succeed: () => console.log('Succeeded!'), + }; + + // Act + await handler(event, context, () => console.log('Lambda invoked!')); + + // 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: awsRequestId, + level: 'INFO', + message: 'Lambda invocation event', + service: 'hello-world', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + event: { + foo: 'bar' + } + })); - describe('Feature: clear state', () => { + }); - test('when enabled, the persistent log attributes added in the handler are removed after the handler\'s code is executed', async () => { + test('when a logger is passed with option logEvent set to true, it logs the event', async () => { + + // Prepare + const configService: ConfigServiceInterface = { + get(name: string): string { + return `a-string-from-${name}`; + }, + getCurrentEnvironment(): string { + return 'dev'; + }, + getLogEvent(): boolean { + return true; + }, + getLogLevel(): string { + return 'INFO'; + }, + getSampleRateValue(): number | undefined { + return undefined; + }, + getServiceName(): string { + return 'my-backend-service'; + }, + + }; + // Prepare + + const logger = new Logger({ + customConfigService: configService, + }); + const consoleSpy = jest.spyOn(logger['console'], 'info').mockImplementation(); + const lambdaHandler = (): void => { + logger.info('This is an INFO log with some context'); + }; + const handler = middy(lambdaHandler).use(injectLambdaContext(logger , { logEvent: true })); + const event = { foo: 'bar' }; + const getRandomInt = (): number => Math.floor(Math.random() * 1000000000); + const awsRequestId = getRandomInt().toString(); + const context = { + callbackWaitsForEmptyEventLoop: true, + functionVersion: '$LATEST', + functionName: 'foo-bar-function', + memoryLimitInMB: '128', + logGroupName: '/aws/lambda/foo-bar-function', + logStreamName: '2021/03/09/[$LATEST]abcdef123456abcdef123456abcdef123456', + invokedFunctionArn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + awsRequestId: awsRequestId, + getRemainingTimeInMillis: () => 1234, + done: () => console.log('Done!'), + fail: () => console.log('Failed!'), + succeed: () => console.log('Succeeded!'), + }; + + // Act + await handler(event, context, () => console.log('Lambda invoked!')); + + // 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: awsRequestId, + level: 'INFO', + message: 'Lambda invocation event', + service: 'my-backend-service', + timestamp: '2016-06-20T12:08:10.000Z', + xray_trace_id: '1-5759e988-bd862e3fe1be46a994272793', + event: { + foo: 'bar' + } + })); - // Prepare - const logger = new Logger({ - logLevel: 'DEBUG', - persistentLogAttributes: { - foo: 'bar', - biz: 'baz' - } - }); - const context = { - callbackWaitsForEmptyEventLoop: true, - functionVersion: '$LATEST', - functionName: 'foo-bar-function', - memoryLimitInMB: '128', - logGroupName: '/aws/lambda/foo-bar-function', - logStreamName: '2021/03/09/[$LATEST]abcdef123456abcdef123456abcdef123456', - invokedFunctionArn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', - awsRequestId: 'abcdef123456abcdef123456', - getRemainingTimeInMillis: () => 1234, - done: () => console.log('Done!'), - fail: () => console.log('Failed!'), - succeed: () => console.log('Succeeded!'), - }; + }); - const lambdaHandler = (event: { user_id: string }): void => { - // Only add these persistent for the scope of this lambda handler - logger.appendKeys({ - details: { user_id: event['user_id'] } - }); - logger.debug('This is a DEBUG log with the user_id'); - logger.debug('This is another DEBUG log with the user_id'); - }; - const handler = middy(lambdaHandler).use(injectLambdaContext(logger, { clearState: true })); - const persistentAttribs = { ...logger.getPersistentLogAttributes() }; + }); - // Act - await handler({ user_id: '123456' }, context, () => console.log('Lambda invoked!')); - const persistentAttribsAfterInvocation = { ...logger.getPersistentLogAttributes() }; + describe('Feature: clear state', () => { - // Assess - expect(persistentAttribs).toEqual({ + test('when enabled, the persistent log attributes added in the handler are removed after the handler\'s code is executed', async () => { + + // Prepare + const logger = new Logger({ + logLevel: 'DEBUG', + persistentLogAttributes: { foo: 'bar', biz: 'baz' + } + }); + const context = { + callbackWaitsForEmptyEventLoop: true, + functionVersion: '$LATEST', + functionName: 'foo-bar-function', + memoryLimitInMB: '128', + logGroupName: '/aws/lambda/foo-bar-function', + logStreamName: '2021/03/09/[$LATEST]abcdef123456abcdef123456abcdef123456', + invokedFunctionArn: 'arn:aws:lambda:eu-west-1:123456789012:function:foo-bar-function', + awsRequestId: 'abcdef123456abcdef123456', + getRemainingTimeInMillis: () => 1234, + done: () => console.log('Done!'), + fail: () => console.log('Failed!'), + succeed: () => console.log('Succeeded!'), + }; + + const lambdaHandler = (event: { user_id: string }): void => { + // Only add these persistent for the scope of this lambda handler + logger.appendKeys({ + details: { user_id: event['user_id'] } }); - expect(persistentAttribsAfterInvocation).toEqual(persistentAttribs); - + logger.debug('This is a DEBUG log with the user_id'); + logger.debug('This is another DEBUG log with the user_id'); + }; + const handler = middy(lambdaHandler).use(injectLambdaContext(logger, { clearState: true })); + const persistentAttribs = { ...logger.getPersistentLogAttributes() }; + + // Act + await handler({ user_id: '123456' }, context, () => console.log('Lambda invoked!')); + const persistentAttribsAfterInvocation = { ...logger.getPersistentLogAttributes() }; + + // Assess + expect(persistentAttribs).toEqual({ + foo: 'bar', + biz: 'baz' }); + expect(persistentAttribsAfterInvocation).toEqual(persistentAttribs); }); }); -}); \ No newline at end of file +}); +