Bug: Logger Timestamps Misaligned with Local Time

[hemanth-m19]

Expected Behaviour

The logger should emit records using local time timestamp by default as per docs.

Current Behaviour

logger emits records using utc timestamp when running in Australia/Sydney timezone

Code snippet

from aws_lambda_powertools import Logger
from aws_lambda_powertools.event_handler import APIGatewayRestResolver
from aws_lambda_powertools.logging import correlation_paths

logger = Logger(service="APP")

app = APIGatewayRestResolver()


@app.get("/hello")
def hello():
    logger.info("Request from unknown received")
    return {"message": "hello unknown!"}


@logger.inject_lambda_context(correlation_id_path=correlation_paths.API_GATEWAY_REST, log_event=True)
def lambda_handler(event, context):
    return app.resolve(event, context)

Possible Solution

No response

Steps to Reproduce

Run above lambda code snippet in Sydney region (ap-southeast-2).

Powertools for AWS Lambda (Python) version

latest

AWS Lambda function runtime

3.9

Packaging format used

Lambda Layers

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 Powertools for AWS Lambda Discord: Invite link

[leandrodamascena]

Hey @hemanth-m19! Thanks for bringing up this unexpected behavior when using our Logger utility.

I was able to reproduce this error and indeed this should consider the localtime, but I have some considerations before we move forward:

1 - The default timezone in Lambda is UTC, it's means that doesn't matter the region the timezone always will be UTC. You can override the default timezone by setting the TZ env variable - https://docs.aws.amazon.com/lambda/latest/dg/configuration-envvars.html#configuration-envvars-runtime.

2 - Even if you define the env variable TZ, Powertools does not consider it and always creates the log with a UTC timestamp, whether using the utc parameter or not. For now I can suggest that an alternative is to use our Logger utility with the use_rfc3339 parameter. If you configure TZ env var and use this parameter, the log will be generated at the desired timestamp.

3 - I know the problem is here: https://github.com/aws-powertools/powertools-lambda-python/blob/develop/aws_lambda_powertools/logging/formatter.py#L171. But I need time to investigate further and find the best solution.

4 - We need to update our documentation to inform about Lambda TZ env var.

So once again, thanks for opening this bug and we will try to fix it as soon as possible. If you want to submit a PR to fix it, or even have a suggestion, we're open to discussing about this. 🚀

[hemanth-m19]

@leandrodamascena , Thanks for the detailed info,

You're absolutely correct, I tried the other day by configuring TZ env variable. However, powertools does not consider it.

I just tried your suggestion a moment ago! I used the Logger utility with the use_rfc3339 parameter and configured the TZ environment variable, and it worked perfectly.

logger = Logger(service="APP", use_rfc3339=True)

Sounds like a viable alternative to address the timestamp issue for now. Thanks again.

[leandrodamascena]

Hi @roger-zhangg! Can you take a look at this? 👁️

[roger-zhangg]

Hi,

The root cause for this issue is python's time.localtime in lambda python runtime doesn't accept TZ env variable. And it will always return UTC time regardless of TZ env var. We are working on possible solution to avoid using time.localtime in time conversion so that the formatter will behave according to TZ value.

The previous root cause was completely wrong. The actual error is lambda runtime's logging.Formatter.converter is defaulted to time.gmtime while locally the default is time.localtime. We should never assume default when working across runtimes.