Skip to content
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

Bug: CloudWatch logs do not use same logging level as PowerTools #783

Closed
nCubed opened this issue Feb 24, 2025 · 12 comments · Fixed by #835
Closed

Bug: CloudWatch logs do not use same logging level as PowerTools #783

nCubed opened this issue Feb 24, 2025 · 12 comments · Fixed by #835
Labels
area/logging Core logging utility bug Unexpected, reproducible and unintended software behaviour need-more-information Missing information before making any calls pending-release Fix or implementation already in dev waiting to be released
Milestone

Comments

@nCubed
Copy link
Contributor

nCubed commented Feb 24, 2025

Expected Behaviour

When the logs are written to CloudWatch, the logging level is only applied at the structured logging. The CloudWatch logs have a different log level.

For example, when log level is set to "Error" with PowerTools, the CloudWatch log remains at "info". This is the same for all logging levels.

The issue here is that when our logs are ingested by company-wide logging aggregator (DataDog), the logs now are tagged with both "Error" and "info".

Is there a way to coerce the CloudWatch logging level to align with the PowerTools logging level?

Current Behaviour

2025-02-24T13:36:06.483Z	f6e6096f-5d28-57bd-99a3-6959252efdd6	info
{
    "cold_start": false,
    "xray_trace_id": "1-67bc<snip>",
    "function_name": "<snip>",
    "function_version": "$LATEST",
    "function_memory_size": 350,
    "function_arn": "arn:aws:lambda:us-east-2:<snip>",
    "function_request_id": "f6e6096f-<snip>",
    "timestamp": "2025-02-24T13:36:06.4837199Z",
    "level": "Error",
    "service": "<snip>",
    "name": "AWS.Lambda.Powertools.Logging.Logger",
    "message": "<snip>"
}

Code snippet

Use any standard logging message.

Possible Solution

No response

Steps to Reproduce

Log an event as an "Error". Json output is correctly set at "Error". CloudWatch is set at "info".

Powertools for AWS Lambda (.NET) version

latest

AWS Lambda function runtime

dotnet8

Debugging logs

@nCubed nCubed added bug Unexpected, reproducible and unintended software behaviour triage Pending triage from maintainers labels Feb 24, 2025
@hjgraca hjgraca added the area/logging Core logging utility label Feb 24, 2025
@hjgraca
Copy link
Contributor

hjgraca commented Feb 24, 2025

@nCubed, are you using Advanced Logging Controls (https://docs.aws.amazon.com/lambda/latest/dg/monitoring-cloudwatchlogs-advanced.html) feature?

@nCubed
Copy link
Contributor Author

nCubed commented Feb 24, 2025

@hjgraca Looks like we were using the OOB "text" format. I updated to "json" format and the structured logging is useless because the message is now an escaped string.

{
    "timestamp": "2025-02-24T13:36:06.483Z",
    "requestId": "f6e6096f-5d28-57bd-99a3-6959252efdd6",
    "level": "info",
    "traceId": "Root=1-67bc<snip>"
    "message": "{\"cold_start\":false,\"xray_trace_id\":\"1-67bc<snip>\",\"function_name\":\"<snip>\",\"function_version\":\"$LATEST\",\"function_memory_size\":350,\"function_arn\":\"arn:aws:lambda:us-east-2:<snip>\",\"function_request_id\":\"f6e6096f-<snip>\",\"timestamp\":\"2025-02-24T13:36:06.4837199Z\",\"level\":\"Error\",\"service\":\"<snip>\",\"name\":\"AWS.Lambda.Powertools.Logging.Logger\",\"message\":\"<snip>\"}"
}

Am I missing a configuration setting?

@hjgraca
Copy link
Contributor

hjgraca commented Feb 24, 2025

I was just trying to understand if you were using ALC because only ALC can change the log level.
Also in ALC mode Logging should be outputting LogLevel and not Level as you are showing and the json should not be inside a string.

Give me some time I am going to try reproduce your scenario, top level statement lambda correct? can you share a snippet of code that could help debug?

Thanks.

@nCubed
Copy link
Contributor Author

nCubed commented Feb 24, 2025

Yes. Top level statement.

I'm going to need to run some more tests. In our actual lambdas, changing the ALC from text to json causes the json message to be an escaped string. In the standard sample I've shared with you in the past, the output is correctly structured.

This is a lower priority for us, so it may be a bit. However, I can confirm that in the message is a fully escaped string instead of structured json in our actual lambdas. Both this sandbox lambda and our actual lambdas all use the exact same build/deploy process, as well as same function definitions using Terraform.

@hjgraca
Copy link
Contributor

hjgraca commented Feb 24, 2025

Thanks, you should not need to enable ALC, was just wondering if you had enabled, but will try and get to the bottom of that.

@hjgraca
Copy link
Contributor

hjgraca commented Feb 25, 2025

Hi @nCubed I was not able to reproduce your issue. On our side from Lambda to CloudWatch everything seems fine.
But I want to understand your issue better, I might be missing something.
Please send me an email with your availability so we can have a chat to [email protected]

Thank you.

@nCubed
Copy link
Contributor Author

nCubed commented Feb 25, 2025

Hi @hjgraca - we're working through a release this week. I'm going to set aside another timeslot in the next day or two and re-validate the issue I encountered on my end. The log files still exist, so we at least have that as some evidence. Once I'm able to repro the issue, I'll ping you here and shoot you an email. Thanks for the follow up.

@hjgraca
Copy link
Contributor

hjgraca commented Mar 4, 2025

Hi @nCubed.
We had a meeting regarding this issue and we might have found the culprit.
We are calling Console.WriteLine and not the appropriate Console.Error, this will indeed affect the output to CloudWatch since the default log level is Info.

Regarding this line
2025-02-24T13:36:06.483Z f6e6096f-5d28-57bd-99a3-6959252efdd6 info
Are you doing any other logging without Powertools maybe using context.Logger? Where do you see it?

I am working on Logging v2 at the moment, but will do a fix for this and hopefully can get it out this week or next week.
Thanks for reporting the issue

@nCubed
Copy link
Contributor Author

nCubed commented Mar 4, 2025

Hey @hjgraca - sorry for the delay on my side. We have been heads down; didn't quite expect to take this long. I'll still try to reproduce on my end when time permits.

Heads up... I will be submitting another bug for Tracing where it throws an exception which masks the underlying exception from the app. I saw a similar bug in the issues and it was closed. So this may be another avenue where the Trace tools can mask the system exception.

@hjgraca hjgraca moved this to 📋 Backlog in Powertools for AWS Lambda (.NET) Mar 10, 2025
@hjgraca hjgraca added need-more-information Missing information before making any calls and removed triage Pending triage from maintainers labels Mar 10, 2025
@dreamorosi
Copy link
Contributor

We are going to close this issue for now since we haven't heard from you - if the issue persists, please reopen with the info above.

@dreamorosi dreamorosi closed this as not planned Won't fix, can't repro, duplicate, stale Mar 31, 2025
@dreamorosi dreamorosi moved this from 📋 Backlog to ✅ Done in Powertools for AWS Lambda (.NET) Mar 31, 2025
@hjgraca
Copy link
Contributor

hjgraca commented Apr 4, 2025

@nCubed I found the issue, and will be fixed on the next release of Logging, which will be v2.
Thanks for bringing this to our attention.

The issue is that on top level statements the LambdaLogger, hijacks at the last time the Console.SetOut to their log, so I had to hijjack back to our log format :)
So now instead of this

Image

you get only the json as you should and do in non top level lambdas

Image

@hjgraca hjgraca reopened this Apr 4, 2025
@hjgraca hjgraca moved this from ✅ Done to 📋 Backlog in Powertools for AWS Lambda (.NET) Apr 4, 2025
@hjgraca hjgraca added this to the Logging V2 milestone Apr 4, 2025
@hjgraca hjgraca mentioned this issue Apr 7, 2025
7 tasks
@hjgraca hjgraca moved this from 📋 Backlog to 🏗 In progress in Powertools for AWS Lambda (.NET) Apr 7, 2025
@hjgraca hjgraca moved this from 🏗 In progress to 👀 In review in Powertools for AWS Lambda (.NET) Apr 7, 2025
@hjgraca hjgraca linked a pull request Apr 7, 2025 that will close this issue
7 tasks
@github-actions github-actions bot added the pending-release Fix or implementation already in dev waiting to be released label Apr 8, 2025
@hjgraca
Copy link
Contributor

hjgraca commented Apr 8, 2025

Fix:
Release 1.4.0

  • Logging 1.7.0
  • Logging 2.0.0-preview.1

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/logging Core logging utility bug Unexpected, reproducible and unintended software behaviour need-more-information Missing information before making any calls pending-release Fix or implementation already in dev waiting to be released
Projects
Status: 👀 In review
Development

Successfully merging a pull request may close this issue.

3 participants