Why would an AWS Lambda Alias only log the INIT_START event to CloudWatch?

Question

I have an AWS Lambda function that is triggered via a Rest API Gateway. It logs to the /aws/lambda/my-function CloudWatch log group as expected.

I wanted to use provisioned concurrency, so set the API Gateway to invoke a Lambda Alias instead. The function is called and generates the expected response. It creates a new log stream with the function version number in the name instead of [$LATEST], as expected, however the only event logged is the INIT_START when the provisioned Lambdas start up.

I tried invoking using a test event via the AWS console to eliminate API Gateway as an issue. Again, invoking the function directly works as expected, but the alias with the same event produces the expected response but does not log to CloudWatch.

I have tried widening the CloudWatch-related IAM permissions for the Lambda function’s execution role but that didn’t improve things (to logs:CreateLogGroup/CreateLogStream/PutEvents on arn:aws:logs:*:*:*).

I tried publishing a new version of my function to update the alias, ensuring my test changes were picked up.

Edit 1: I added the context object to my returned response to confirm it is definitely my alias being called, and that the logging config looks correct:

{
  "context": {
    "callbackWaitsForEmptyEventLoop": true,
    "functionVersion": "6",
    "functionName": "my-function",
    "memoryLimitInMB": "128",
    "logGroupName": "/aws/lambda/my-function",
    "logStreamName": "2023/03/08/[6]541834ec8f884588ba63e209f0be0789",
    "invokedFunctionArn": "arn:aws:lambda:us-east-1:XXXXXXXXXXXX:function:my-function:my-function",
    "awsRequestId": "e0812992-cf58-4a8b-b4a6-1ac0a91445b1"
  }
}

You can see there that the invokedFunctionArn is the alias - when testing the function directly there is only one :my-function on the end. Also when calling directly the functionVersion is $LATEST.

Answer 1

The issue here was not with my function and its logging, but I was looking at the most recent streams in the CloudWatch console sorted by “last event time”, and the timestamps do not appear to be updating.

I added the Lambda call context object to my response to confirm that the invocation was being made against my Lambda alias (see Edit 1) in the question.

When I returned to this later I noticed that this also included the logStreamName so went about inspecting that in the API.

I can see for example a log stream that has:

// log stream
lastEventTimestamp: Wed, 08 Mar 2023 21:50:45 GMT
lastIngestionTime:  Wed, 08 Mar 2023 21:50:46 GMT

// actual most recent event
timestamp:          Wed, 08 Mar 2023 21:52:09 GMT
ingestionTime:      Wed, 08 Mar 2023 21:52:10 GMT

These stale values above are being returned some 30 minutes after the actual event, but as per the documentation are “eventually consistent” and do eventually update.

The confusion was exacerbated by each direct invocation of the Lambda function creating a new log stream with up-to-date “last event” timestamps, versus the behavior when invoking via the alias described above giving stale “last event” timestamps.