Skip to content

Bug: cold start flag is set to true in subsequent invocations in Logger #518

Closed
@ijemmy

Description

@ijemmy

Bug description

When logger capture context information, it adds cold_start key with boolean value into each log.

I call the same Lambda twice. The cold_start value should be false after the first call. However, it is still true in other calls.

image

Expected Behavior

cold_start value should be false in subsequent calls.

Current Behavior

cold_start value is still true in subsequent calls.

Possible Solution

Steps to Reproduce

  1. This is the Lambda function code I use.
import { injectLambdaContext, Logger } from "../../src";
import { APIGatewayProxyEvent } from "aws-lambda";
import middy from "@middy/core"

const persistentKey = process.env.PERSISTENT_KEY_IN_LOG;
const persistentValue = process.env.PERSISTENT_VALUE_IN_LOG;

const logger = new Logger({
  persistentLogAttributes: {
    [persistentKey]: persistentValue,
  }
});

const testFunction = async (event: APIGatewayProxyEvent) => {

  // 1. Context data appears in log
  // 2. LOG_LEVEL works as expected
  // 3. persistentLogAttributes prop works 
  logger.debug("##### This should not appear");
  logger.info("This is an INFO log with some context and persistent key");

  // 4. Can add additional key value in the log method
  logger.info("This is an INFO log with some context", {
    additionalKey: 'additionalValue'
  });

  // 5. Can log error object
  try {
    throw new Error('you cannot prevent this');
  }catch(e){
    logger.error("There was an error", e);
  }

  return formatJSONResponse({
    message: `E2E testing Lambda function`,
    event,
  });
}

const formatJSONResponse = (response: Record<string, any>) => {
  return {
    statusCode: 200,
    body: JSON.stringify(response)
  }
}

export const handler = middy(testFunction)
  .use(injectLambdaContext(logger));
  1. I deploy and trigger the Lambda function twice with this code
    const sdkProvider = await SdkProvider.withAwsCliCompatibleDefaults({
      profile: process.env.AWS_PROFILE,
    });
    const cloudFormation = new CloudFormationDeployments({ sdkProvider });

    // WHEN lambda function is deployed
    const result = await cloudFormation.deployStack({
      stack: stackArtifact,
      quiet: true,
    });

    logGroupName = result.outputs[STACK_OUTPUT_LOG_GROUP];
    
    // and invoked twice (one for cold start, another for warm start)
    let promises = [];
    
    for (let i = 0; i < invocationCount; i++) {
      const invokePromise = lambdaClient
        .invoke({
          FunctionName: functionName,
          LogType: 'Tail', // Wait until execution completes and return all logs
        })
        .promise();
    }
    await Promise.all(promises); 
  1. I check CloudWatch log and found this. Notice that INIT is only in the first call (which indicates cold start)

image

Environment

  • Powertools version used:0.3.3
  • Packaging format (Layers, npm):npm
  • AWS Lambda function runtime: n/a
  • Debugging logs: n/a

Related issues, RFCs

n/a

Metadata

Metadata

Assignees

Labels

bugSomething isn't workingcompletedThis item is complete and has been merged/shippedloggerThis item relates to the Logger Utility

Type

No type

Projects

No projects

Relationships

None yet

Development

No branches or pull requests

Issue actions