feat(logger): support use_datetime_directive for timestamps (#920)

Co-authored-by: heitorlessa <[email protected]>

Author: huonw

aws_lambda_powertools/logging/formatter.py

@@ -3,6 +3,7 @@
 import os
 import time
 from abc import ABCMeta, abstractmethod
+from datetime import datetime, timezone
 from functools import partial
 from typing import Any, Callable, Dict, Iterable, List, Optional, Tuple, Union
 
@@ -61,9 +62,10 @@ def __init__(
         json_deserializer: Optional[Callable[[Union[Dict, str, bool, int, float]], str]] = None,
         json_default: Optional[Callable[[Any], Any]] = None,
         datefmt: Optional[str] = None,
+        use_datetime_directive: bool = False,
         log_record_order: Optional[List[str]] = None,
         utc: bool = False,
-        **kwargs
+        **kwargs,
     ):
         """Return a LambdaPowertoolsFormatter instance.
 
@@ -86,20 +88,30 @@ def __init__(
             Only used when no custom JSON encoder is set
 
         datefmt : str, optional
-            String directives (strftime) to format log timestamp
+            String directives (strftime) to format log timestamp.
 
-            See https://docs.python.org/3/library/time.html#time.strftime
+            See https://docs.python.org/3/library/time.html#time.strftime or
+        use_datetime_directive: str, optional
+            Interpret `datefmt` as a format string for `datetime.datetime.strftime`, rather than
+            `time.strftime` - Only useful when used alongside `datefmt`.
+
+            See https://docs.python.org/3/library/datetime.html#strftime-strptime-behavior . This
+            also supports a custom %F directive for milliseconds.
         utc : bool, optional
             set logging timestamp to UTC, by default False to continue to use local time as per stdlib
         log_record_order : list, optional
             set order of log keys when logging, by default ["level", "location", "message", "timestamp"]
         kwargs
             Key-value to be included in log messages
+
         """
         self.json_deserializer = json_deserializer or json.loads
         self.json_default = json_default or str
         self.json_serializer = json_serializer or partial(json.dumps, default=self.json_default, separators=(",", ":"))
+
         self.datefmt = datefmt
+        self.use_datetime_directive = use_datetime_directive
+
         self.utc = utc
         self.log_record_order = log_record_order or ["level", "location", "message", "timestamp"]
         self.log_format = dict.fromkeys(self.log_record_order)  # Set the insertion order for the log messages
@@ -129,13 +141,35 @@ def format(self, record: logging.LogRecord) -> str:  # noqa: A003
 
     def formatTime(self, record: logging.LogRecord, datefmt: Optional[str] = None) -> str:
         record_ts = self.converter(record.created)  # type: ignore
-        if datefmt:
-            return time.strftime(datefmt, record_ts)
+
+        if datefmt is None:  # pragma: no cover, it'll always be None in std logging, but mypy
+            datefmt = self.datefmt
 
         # NOTE: Python `time.strftime` doesn't provide msec directives
         # so we create a custom one (%F) and replace logging record ts
         # Reason 2 is that std logging doesn't support msec after TZ
         msecs = "%03d" % record.msecs
+
+        # Datetime format codes might be optionally used
+        # however it only makes a difference if `datefmt` is passed
+        # since format codes are the same except %f
+        if self.use_datetime_directive and datefmt:
+            # record.msecs are microseconds, divide by 1000 and we get milliseconds
+            timestamp = record.created + record.msecs / 1000
+
+            if self.utc:
+                dt = datetime.fromtimestamp(timestamp, tz=timezone.utc)
+            else:
+                # make sure local timezone is included
+                dt = datetime.fromtimestamp(timestamp).astimezone()
+
+            custom_fmt = datefmt.replace(self.custom_ms_time_directive, msecs)
+            return dt.strftime(custom_fmt)
+
+        elif datefmt:
+            custom_fmt = datefmt.replace(self.custom_ms_time_directive, msecs)
+            return time.strftime(custom_fmt, record_ts)
+
         custom_fmt = self.default_time_format.replace(self.custom_ms_time_directive, msecs)
         return time.strftime(custom_fmt, record_ts)
 
@@ -219,7 +253,7 @@ def _extract_log_keys(self, log_record: logging.LogRecord) -> Dict[str, Any]:
             Structured log as dictionary
         """
         record_dict = log_record.__dict__.copy()
-        record_dict["asctime"] = self.formatTime(record=log_record, datefmt=self.datefmt)
+        record_dict["asctime"] = self.formatTime(record=log_record)
         extras = {k: v for k, v in record_dict.items() if k not in RESERVED_LOG_ATTRS}
 
         formatted_log = {}

aws_lambda_powertools/logging/logger.py

@@ -78,9 +78,16 @@ class Logger(logging.Logger):  # lgtm [py/missing-call-to-init]
         custom logging handler e.g. logging.FileHandler("file.log")
 
     Parameters propagated to LambdaPowertoolsFormatter
-    ---------------------------------------------
+    --------------------------------------------------
     datefmt: str, optional
-        String directives (strftime) to format log timestamp, by default it uses RFC 3339.
+        String directives (strftime) to format log timestamp using `time`, by default it uses RFC
+        3339.
+    use_datetime_directive: str, optional
+        Interpret `datefmt` as a format string for `datetime.datetime.strftime`, rather than
+        `time.strftime`.
+
+        See https://docs.python.org/3/library/datetime.html#strftime-strptime-behavior . This
+        also supports a custom %F directive for milliseconds.
     json_serializer : Callable, optional
         function to serialize `obj` to a JSON formatted `str`, by default json.dumps
     json_deserializer : Callable, optional

docs/core/logger.md

@@ -656,6 +656,7 @@ Parameter | Description | Default
 **`json_deserializer`** | function to deserialize `str`, `bytes`, `bytearray` containing a JSON document to a Python obj | `json.loads`
 **`json_default`** | function to coerce unserializable values, when no custom serializer/deserializer is set | `str`
 **`datefmt`** | string directives (strftime) to format log timestamp | `%Y-%m-%d %H:%M:%S,%F%z`, where `%F` is a custom ms directive
+**`use_datetime_directive`** | format the `datefmt` timestamps using `datetime`, not `time`  (also supports the custom `%F` directive for milliseconds) | `False`
 **`utc`** | set logging timestamp to UTC | `False`
 **`log_record_order`** | set order of log keys when logging | `["level", "location", "message", "timestamp"]`
 **`kwargs`** | key-value to be included in log messages | `None`
@@ -726,13 +727,17 @@ In this case, Logger will register a Logger named `payment`, and a Logger named
 
 #### Overriding Log records
 
+???+ tip
+	Use `datefmt` for custom date formats - We honour standard [logging library string formats](https://docs.python.org/3/howto/logging.html#displaying-the-date-time-in-messages){target="_blank"}.
+
+	Prefer using [datetime string formats](https://docs.python.org/3/library/datetime.html#strftime-and-strptime-format-codes){target="_blank"}? Set `use_datetime_directive` at Logger constructor or at [Lambda Powertools Formatter](#lambdapowertoolsformatter).
+
 You might want to continue to use the same date formatting style, or override `location` to display the `package.function_name:line_number` as you previously had.
 
 Logger allows you to either change the format or suppress the following keys altogether at the initialization: `location`, `timestamp`, `level`, `xray_trace_id`.
 
-=== "lambda_handler.py"
-    > We honour standard [logging library string formats](https://docs.python.org/3/howto/logging.html#displaying-the-date-time-in-messages){target="_blank"}.
 
+=== "lambda_handler.py"
     ```python hl_lines="7 10"
     from aws_lambda_powertools import Logger
 

docs/utilities/feature_flags.md

@@ -385,7 +385,7 @@ You can use `get_enabled_features` method for scenarios where you need a list of
 ???+ info "When is this useful?"
     You might have a list of features to unlock for premium customers, unlock a specific set of features for admin users, etc.
 
-Feature flags can return any JSON values when `boolean_type` parameter is set to `False`. These can be dictionaries, list, string, integers, etc.
+Feature flags can return any JSON values when `boolean_type` parameter is set to `false`. These can be dictionaries, list, string, integers, etc.
 
 
 === "app.py"

tests/functional/test_logger.py

@@ -3,8 +3,10 @@
 import json
 import logging
 import random
+import re
 import string
 from collections import namedtuple
+from datetime import datetime, timezone
 from typing import Iterable
 
 import pytest
@@ -610,3 +612,26 @@ def handler(event, context, my_custom_option=None):
 
     # THEN
     handler({}, lambda_context, my_custom_option="blah")
+
+
+@pytest.mark.parametrize("utc", [False, True])
+def test_use_datetime(stdout, service_name, utc):
+    # GIVEN
+    logger = Logger(
+        service=service_name,
+        stream=stdout,
+        datefmt="custom timestamp: milliseconds=%F microseconds=%f timezone=%z",
+        use_datetime_directive=True,
+        utc=utc,
+    )
+
+    # WHEN a log statement happens
+    logger.info({})
+
+    # THEN the timestamp has the appropriate formatting
+    log = capture_logging_output(stdout)
+
+    expected_tz = datetime.now().astimezone(timezone.utc if utc else None).strftime("%z")
+    assert re.fullmatch(
+        f"custom timestamp: milliseconds=[0-9]+ microseconds=[0-9]+ timezone={re.escape(expected_tz)}", log["timestamp"]
+    )