Bug: Custom CloudWatch metrics not always appearing for split route(s)

[pawosty]

Expected Behaviour

When uploading a custom metric using the aws_lambda_powertools.metrics package, the metrics should appear in CloudWatch Metrics.

Current Behaviour

Metrics appear intermittently and appear to be tied to whether a lambda was cold started (and also had a cold start metric uploaded).

Code snippet

Split route handler:

metrics: Metrics = Metrics()

@router.delete("/v1/asset", cors=True)
@tracer.capture_method
def delete_asset() -> dict:
    metrics.add_metric(name="AssetDeleted", unit=MetricUnit.Count, value=1)
    return {"message": "Asset deletion successful"}

Lambda handler:

@metrics.log_metrics(capture_cold_start_metric=True)
@logger.inject_lambda_context(correlation_id_path=correlation_paths.API_GATEWAY_REST, log_event=True)
@tracer.capture_lambda_handler
@auth.enforce_allow_list
@auth.restrict_api_key
def lambda_handler(event: Dict, context: LambdaContext):
    return app.resolve(event, context)

Possible Solution

When examining the cloudwatch logs, the unsuccessful metrics appear in the same log line as the tracer log, for example:

{
    "resource": "/v1/asset",
    "path": "/v1/asset",
    "httpMethod": "DELETE",
...more data...
}{
    "_aws": {
        "Timestamp": 1672800187055,
        "CloudWatchMetrics": [
            {
                "Namespace": "MyNamespace",
                "Dimensions": [
                    [
                        "service"
                    ]
                ],
                "Metrics": [
                    {
                        "Name": "AssetDeleted",
                        "Unit": "Count"
                    }
                ]
            }
        ]
    },
    "service": "MyLambda",
    "AssetDeleted": [
        1
    ]
}

When successful metrics appear (such as when they are uploaded as part of a cold start), they appear in their own log line in CloudWatch and are presumably parsed.

Steps to Reproduce

• Create a split route lambda handler, log cold starts
• In the split route(s) attempt to create/upload custom metrics
• Observe not all metrics appear in CloudWatch metrics as expected

AWS Lambda Powertools for Python version

latest

AWS Lambda function runtime

3.6

Packaging format used

PyPi

Debugging logs

No response

[boring-cyborg]

Thanks for opening your first issue here! We'll come back to you as soon as we can.
In the meantime, check out the #python channel on our AWS Lambda Powertools Discord: Invite link

[leandrodamascena]

Hi @pawosty! Thank you for opening this issue and letting us know about a possible issue.

I inspected the code and tried to simulate this problem here and I couldn't. I don't know if I'm missing something specific you're doing, but I tried to create an example similar to what you did and I got the expected behavior: all metrics were sent to CloudWatch.

I created a project using sam cli and pushed it to a github repository (https://github.com/leandrodamascena/custom-metrics-example). You can look at the code I made to try to reproduce the problem and see if there is something different in your environment that I should adjust here to reproduce the problem.

Below are screenshots of the tests I performed.

Thank you.

[pawosty]

Thanks for looking into this! I have noticed that I have lambda context data appearing twice, once as a log item as you do, and then a second time clobbered with the metrics data, so I think there might be a dependency interfering. I'll try to get to the bottom of this and confirm.

[github-actions]

⚠️COMMENT VISIBILITY WARNING⚠️

This issue is now closed. Please be mindful that future comments 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.

[leandrodamascena]

Thanks for looking into this! I have noticed that I have lambda context data appearing twice, once as a log item as you do, and then a second time clobbered with the metrics data, so I think there might be a dependency interfering. I'll try to get to the bottom of this and confirm.

Thanks for reply.

Let me know if I can help in any way to detect if this is indeed a bug in Powertools. If so, we are fully interested in fixing it.

[pawosty]

Ok, I believe I found the issue. The extra JSON appearing in the logs was because I had "debug" enabled on the APIGatewayResolver object, causing this line to be executed:

if self._debug: print(self._json_dump(event), end="")

This gets combined with the metrics output and then ignored by CloudWatch metrics. A member on our team was able to confirm setting debug mode to FALSE results in metrics appearing as expected.

I'm not sure why this specific print behaves this way, maybe because a newline is being omitted? Regardless I think it's an unexpected interaction.

[github-actions]

⚠️COMMENT VISIBILITY WARNING⚠️

This issue is now closed. Please be mindful that future comments 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.

[github-actions]

This is now released under 2.6.0 version!