Closed
Description
Bug description
Looks like decorator clears states too early on async/await codes.
https://awslabs.github.io/aws-lambda-powertools-typescript/latest/core/logger/#clearing-all-state
import { Logger } from "@aws-lambda-powertools/logger";
import { LambdaInterface } from "@aws-lambda-powertools/commons";
import { setTimeout } from "timers";
const logger = new Logger({
logLevel: "DEBUG",
persistentLogAttributes: {
foo: "bar",
biz: "baz",
},
});
class Lambda implements LambdaInterface {
// Enable the clear state flag
@logger.injectLambdaContext({ clearState: true })
public async handler(event: any, _context: any): Promise<void> {
logger.appendKeys({ temporaryState: true });
logger.debug("This is a DEBUG log");
await this.doSomethingAsync();
logger.debug("This is a DEBUG log");
}
private async doSomethingAsync(): Promise<void> {
return new Promise((resolve) => setTimeout(resolve, 5 * 1000));
}
}
const myFunction = new Lambda();
export const handler = myFunction.handler.bind(myFunction);Expected Behavior
States are not cleared until handler execution is complete.
CloudWatch Logs
Current Behavior
State are cleared before the handler's execution is complete.
CloudWatch Logs
{
"cold_start": true,
"function_arn": "arn:aws:lambda:us-east-1:000000000000:function:function_foo",
"function_memory_size": 128,
"function_name": "function_foo",
"function_request_id": "4577ef0f-1e74-47b9-b8e6-40d45e736089",
"level": "DEBUG",
"message": "This is a DEBUG log",
"service": "service_undefined",
"timestamp": "2022-09-09T05:03:32.625Z",
"xray_trace_id": "1-631ac924-7290afce25c885af5a324679",
"foo": "bar",
"biz": "baz",
"temporaryState": true
}
{
"cold_start": true,
"function_arn": "arn:aws:lambda:us-east-1:000000000000:function:function_foo",
"function_memory_size": 128,
"function_name": "function_foo",
"function_request_id": "4577ef0f-1e74-47b9-b8e6-40d45e736089",
"level": "DEBUG",
"message": "This is a DEBUG log",
"service": "service_undefined",
"timestamp": "2022-09-09T05:03:37.670Z",
"xray_trace_id": "1-631ac924-7290afce25c885af5a324679",
"foo": "bar",
"biz": "baz"
// <== !!!
}Possible Solution
await handler and then clear states?
https://github.com/awslabs/aws-lambda-powertools-typescript/blob/34d3a766acccce9c8292aeb3795d95d2aeea683a/packages/logger/src/Logger.ts#L299-L305
Steps to Reproduce
- deploy lambda using AWS CDK.
new lambdaNodeJs.NodejsFunction(
stack,
"MyLambdaFunction",
{
entry: "src/lambda/powertools-bug.ts",
memorySize: 128,
runtime: lambda.Runtime.NODEJS_16_X,
architecture: lambda.Architecture.ARM_64,
timeout: cdk.Duration.minutes(1),
retryAttempts: 0,
tracing: lambda.Tracing.ACTIVE,
bundling: { keepNames: true },
}
);Environment
- Powertools version used: 1.2.1
- Packaging format (Layers, npm): npm
- AWS Lambda function runtime:: Node.js 16.x (arm)
- Debugging logs:
{ "cold_start": true, "function_arn": "arn:aws:lambda:us-east-1:000000000000:function:function_foo", "function_memory_size": 128, "function_name": "function_foo", "function_request_id": "4577ef0f-1e74-47b9-b8e6-40d45e736089", "level": "DEBUG", "message": "This is a DEBUG log", "service": "service_undefined", "timestamp": "2022-09-09T05:03:32.625Z", "xray_trace_id": "1-631ac924-7290afce25c885af5a324679", "foo": "bar", "biz": "baz", "temporaryState": true } { "cold_start": true, "function_arn": "arn:aws:lambda:us-east-1:000000000000:function:function_foo", "function_memory_size": 128, "function_name": "function_foo", "function_request_id": "4577ef0f-1e74-47b9-b8e6-40d45e736089", "level": "DEBUG", "message": "This is a DEBUG log", "service": "service_undefined", "timestamp": "2022-09-09T05:03:37.670Z", "xray_trace_id": "1-631ac924-7290afce25c885af5a324679", "foo": "bar", "biz": "baz", "temporaryState": true // <== }