Skip to content

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

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

Closed
ijemmy opened this issue Jan 27, 2022 · 1 comment · Fixed by #550
Closed

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

ijemmy opened this issue Jan 27, 2022 · 1 comment · Fixed by #550
Assignees
Labels
bug Something isn't working completed This item is complete and has been merged/shipped logger This item relates to the Logger Utility

Comments

@ijemmy
Copy link
Contributor

ijemmy commented Jan 27, 2022

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

@ijemmy ijemmy added bug Something isn't working triage This item has not been triaged by a maintainer, please wait labels Jan 27, 2022
@saragerion saragerion added this to the production-ready-release milestone Jan 27, 2022
@dreamorosi dreamorosi linked a pull request Feb 10, 2022 that will close this issue
12 tasks
@dreamorosi dreamorosi self-assigned this Feb 10, 2022
@github-actions
Copy link
Contributor

⚠️ COMMENT VISIBILITY WARNING ⚠️

Comments on closed issues are hard for our team to see.
If you need more assistance, please either tag a team member or open a new issue that references this one.
If you wish to keep having a conversation with other community members under this issue feel free to do so.

@dreamorosi dreamorosi removed the triage This item has not been triaged by a maintainer, please wait label Oct 19, 2022
@dreamorosi dreamorosi changed the title (logger): Cold start flag is set to true in subsequent invocations Bug: cold start flag is set to true in subsequent invocations in Logger Nov 14, 2022
@dreamorosi dreamorosi added logger This item relates to the Logger Utility completed This item is complete and has been merged/shipped labels Nov 14, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
bug Something isn't working completed This item is complete and has been merged/shipped logger This item relates to the Logger Utility
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants