Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Feat(logger): log event functionality #1004

Merged
merged 11 commits into from
Jun 23, 2022
6 changes: 5 additions & 1 deletion CONTRIBUTING.md
Original file line number Diff line number Diff line change
Expand Up @@ -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`
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

would be cool in the future (not this PR) to have an additional combo command to run the docs & the API docs at the same time

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Sorry, I meant something like (name is just an example):

"docs-run-docs-and-api": "npm run docs-runLocalDocker && npm run docs-api-build-run"

This command would allow you to run the documentation + the API docs so you can browse between both. Right now when editing locally, if you start from the docs and click on "API Docs" on the left navigation menu it gives you a 404 because there's nothing on the /api path.

But again, we can do it at some point in the future!


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`
Expand Down
50 changes: 47 additions & 3 deletions docs/core/logger.md
Original file line number Diff line number Diff line change
Expand Up @@ -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)
dreamorosi marked this conversation as resolved.
Show resolved Hide resolved
* 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
Expand Down Expand Up @@ -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<void> => {
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<void> {
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:
Expand Down
28 changes: 14 additions & 14 deletions docs/index.md
Original file line number Diff line number Diff line change
Expand Up @@ -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

Expand Down
2 changes: 2 additions & 0 deletions package.json
Original file line number Diff line number Diff line change
Expand Up @@ -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",
dreamorosi marked this conversation as resolved.
Show resolved Hide resolved
"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"
},
Expand Down
8 changes: 8 additions & 0 deletions packages/commons/tests/utils/InvocationLogs.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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
Expand Down
48 changes: 46 additions & 2 deletions packages/logger/src/Logger.ts
Original file line number Diff line number Diff line change
Expand Up @@ -119,6 +119,8 @@ class Logger extends Utility implements ClassThatLogs {

private envVarsService?: EnvironmentVariablesService;

private logEvent: boolean = false;

private logFormatter?: LogFormatterInterface;

private logLevel?: LogLevel;
Expand Down Expand Up @@ -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.
*
Expand Down Expand Up @@ -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 ]);
Expand All @@ -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
Expand Down Expand Up @@ -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.
*
Expand Down Expand Up @@ -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
Expand Down
19 changes: 19 additions & 0 deletions packages/logger/src/config/ConfigService.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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';
Expand All @@ -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.
*
Expand All @@ -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 {
Expand Down
7 changes: 7 additions & 0 deletions packages/logger/src/config/ConfigServiceInterface.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*
Expand Down
9 changes: 9 additions & 0 deletions packages/logger/src/config/EnvironmentVariablesService.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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.
*
Expand Down
5 changes: 4 additions & 1 deletion packages/logger/src/middleware/middy.ts
Original file line number Diff line number Diff line change
Expand Up @@ -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);
}
});
};

Expand All @@ -48,7 +51,7 @@ const injectLambdaContext = (target: Logger | Logger[], options?: HandlerOptions
});
}
};

return {
before: injectLambdaContextBefore,
after: injectLambdaContextAfter
Expand Down
1 change: 1 addition & 0 deletions packages/logger/src/types/Logger.ts
Original file line number Diff line number Diff line change
Expand Up @@ -9,6 +9,7 @@ type ClassThatLogs = {
};

type HandlerOptions = {
logEvent?: boolean
clearState?: boolean
};

Expand Down
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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
dreamorosi marked this conversation as resolved.
Show resolved Hide resolved
});
}

Expand Down Expand Up @@ -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 }));
Loading