Unable to get sub-second timestamps with custom datefmt (e.g. ISO8601)

[huonw]

What were you trying to accomplish?

The structured logging is great, thank you.

We find the timestamp field somewhat unexpected, e.g. use of , rather than . (ignoring device locale), and some might want to follow ISO8601 more strictly and use the T date/time separator: 2000-01-02T03:04:05.006+07:08. (Or even other date/time formatting standards.)

Unfortunately, it seems that it's impossible to provide a custom format ala "%Y-%m-%dT%H:%M:%S.%f%z" that satisfies this and retain the subsecond precision because neither datetime.strftime's microsecond %f nor the custom millisecond %F are supported due to the use of time.struct_time/time.strftime

Expected Behavior

It would be great to be able to get sub-second timestamp precision with a custom datefmt.

Current Behavior

Subsecond precision formatters are ignored. See output below.

Possible Solution

• Do custom interpolating of %F in a custom datefmt in addition to default_time_format (for instance, set self.datefmt = datefmt or default_time_format and remove the if self.datefmt in formatTime)
• Use datetime rather than time within formatTime

Steps to Reproduce (for bugs)

from aws_lambda_powertools.logging import Logger, logger

logger.set_package_logger()

print("trying %f")
Logger(datefmt="%Y-%m-%dT%H:%M:%S.%f%z").info({})

print("\ntrying %F")
Logger(datefmt="%Y-%m-%dT%H:%M:%S.%F%z").info({})

Output:

trying %f
2021-12-17 08:56:31,557 aws_lambda_powertools.logging.logger [DEBUG] Adding filter in root logger to suppress child logger records to bubble up
2021-12-17 08:56:31,557 aws_lambda_powertools.logging.logger [DEBUG] Marking logger service_undefined as preconfigured
{"level":"INFO","location":"<module>:7","message":{},"timestamp":"2021-12-17T08:56:31.f+1100","service":"service_undefined"}

trying %F
{"level":"INFO","location":"<module>:10","message":{},"timestamp":"2021-12-17T08:56:31.f+1100","service":"service_undefined"}

Note that the timestamp fields both come out as "2021-12-17T08:56:31.f+1100" with a f instead of sub-second precision.

Environment

• Powertools version used: 1.22.0

aws-lambda-powertools==1.22.0
aws-xray-sdk==2.9.0
boto3==1.20.24
botocore==1.23.24
fastjsonschema==2.15.2
future==0.18.2
jmespath==0.10.0
pydantic==1.8.2
python-dateutil==2.8.2
s3transfer==0.5.0
six==1.16.0
typing_extensions==4.0.1
urllib3==1.26.7
wrapt==1.13.3

• Packaging format (Layers, PyPi): N/A
• AWS Lambda function runtime: N/A
• Debugging logs interleaved into output above

[heitorlessa]

Hey @huonw perhaps this is not a bug unless this is supported in the standard logging library.

Regardless, I'd like to provide a better way to handle this as I kept the standard time format used by std logging.

I'd appreciate any suggestions you might have on how we can make this effortless -- changing the format now will break customers, but it should be easier to support other formats and custom formats

[huonw]

Hey @huonw perhaps this is not a bug unless this is supported in the standard logging library.

Yeah, maybe it's a feature request. 😅

Regardless, I'd like to provide a better way to handle this as I kept the standard time format used by std logging.

I'd appreciate any suggestions you might have on how we can make this effortless -- changing the format now will break customers, but it should be easier to support other formats and custom formats

I could imagine that datetime's strftime directives are a superset of time's, and it'd be... weird if someone was specifying %f and expecting to get f as output. However, a breaking change is definitely suboptimal, I've proposed an idea in #920 that adds a new (mutually exclusive) argument datetime_fmt so that existing users of datefmt aren't affected but others can opt in to use of datetime_fmt.

What do you think?

[heitorlessa]

Waiting for last CI checks and releasing it ;-)

Changed the name slightly so it's easier for newcomers to know what to search

    logger = Logger(
        service=service_name,
        datefmt="custom timestamp: milliseconds=%F microseconds=%f timezone=%z",
        use_datetime_directive=True,  # from use_datetime
    )

[heitorlessa]

Hey @huonw this is available in 1.24.0 release - thank you so much again for helping out :)