feat(logger): add use_rfc3339 and auto-complete formatter opts in Logger (#1662)

Author: heitorlessa

aws_lambda_powertools/logging/formatter.py

@@ -62,6 +62,7 @@ class LambdaPowertoolsFormatter(BasePowertoolsFormatter):
 
     default_time_format = "%Y-%m-%d %H:%M:%S,%F%z"  # '2021-04-17 18:19:57,656+0200'
     custom_ms_time_directive = "%F"
+    RFC3339_ISO8601_FORMAT = "%Y-%m-%dT%H:%M:%S.%F%z"  # '2022-10-27T16:27:43.738+02:00'
 
     def __init__(
         self,
@@ -72,6 +73,7 @@ def __init__(
         use_datetime_directive: bool = False,
         log_record_order: Optional[List[str]] = None,
         utc: bool = False,
+        use_rfc3339: bool = False,
         **kwargs,
     ):
         """Return a LambdaPowertoolsFormatter instance.
@@ -106,6 +108,9 @@ def __init__(
             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
+        use_rfc3339: bool, optional
+            Whether to use a popular dateformat that complies with both RFC3339 and ISO8601.
+            e.g., 2022-10-27T16:27:43.738+02:00.
         log_record_order : list, optional
             set order of log keys when logging, by default ["level", "location", "message", "timestamp"]
         kwargs
@@ -129,6 +134,7 @@ def __init__(
         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
         self.update_formatter = self.append_keys  # alias to old method
+        self.use_rfc3339_iso8601 = use_rfc3339
 
         if self.utc:
             self.converter = time.gmtime  # type: ignore
@@ -153,36 +159,51 @@ def format(self, record: logging.LogRecord) -> str:  # noqa: A003
         return self.serialize(log=formatted_log)
 
     def formatTime(self, record: logging.LogRecord, datefmt: Optional[str] = None) -> str:
+        # As of Py3.7, we can infer milliseconds directly from any datetime
+        # saving processing time as we can shortcircuit early
+        # Maintenance: In V3, we (and Java) should move to this format by default
+        # since we've provided enough time for those migrating from std logging
+        if self.use_rfc3339_iso8601:
+            if self.utc:
+                ts_as_datetime = datetime.fromtimestamp(record.created, tz=timezone.utc)
+            else:
+                ts_as_datetime = datetime.fromtimestamp(record.created).astimezone()
+
+            return ts_as_datetime.isoformat(timespec="milliseconds")  # 2022-10-27T17:42:26.841+0200
+
+        # converts to local/UTC TZ as struct time
         record_ts = self.converter(record.created)  # type: ignore
 
         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
+        # 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
+        # Datetime format codes is a superset of time format codes
+        # therefore we only honour them if explicitly asked
+        # by default, those migrating from std logging will use time format codes
+        # https://docs.python.org/3/library/datetime.html#strftime-and-strptime-format-codes
         if self.use_datetime_directive and datefmt:
-            # record.msecs are microseconds, divide by 1000 and we get milliseconds
+            # record.msecs are microseconds, divide by 1000 to 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)
 
+        # Only time format codes being used
         elif datefmt:
             custom_fmt = datefmt.replace(self.custom_ms_time_directive, msecs)
             return time.strftime(custom_fmt, record_ts)
 
+        # Use default fmt: 2021-05-03 10:20:19,650+0200
         custom_fmt = self.default_time_format.replace(self.custom_ms_time_directive, msecs)
         return time.strftime(custom_fmt, record_ts)
 

aws_lambda_powertools/logging/logger.py

@@ -6,7 +6,18 @@
 import random
 import sys
 import traceback
-from typing import IO, Any, Callable, Dict, Iterable, Mapping, Optional, TypeVar, Union
+from typing import (
+    IO,
+    Any,
+    Callable,
+    Dict,
+    Iterable,
+    List,
+    Mapping,
+    Optional,
+    TypeVar,
+    Union,
+)
 
 import jmespath
 
@@ -86,14 +97,16 @@ class Logger(logging.Logger):  # lgtm [py/missing-call-to-init]
     Parameters propagated to LambdaPowertoolsFormatter
     --------------------------------------------------
     datefmt: str, optional
-        String directives (strftime) to format log timestamp using `time`, by default it uses RFC
-        3339.
+        String directives (strftime) to format log timestamp using `time`, by default it uses 2021-05-03 11:47:12,494+0200. # noqa: E501
     use_datetime_directive: bool, 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.
+    use_rfc3339: bool, optional
+        Whether to use a popular date format that complies with both RFC3339 and ISO8601.
+        e.g., 2022-10-27T16:27:43.738+02:00.
     json_serializer : Callable, optional
         function to serialize `obj` to a JSON formatted `str`, by default json.dumps
     json_deserializer : Callable, optional
@@ -187,6 +200,14 @@ def __init__(
         stream: Optional[IO[str]] = None,
         logger_formatter: Optional[PowertoolsFormatter] = None,
         logger_handler: Optional[logging.Handler] = None,
+        json_serializer: Optional[Callable[[Dict], str]] = None,
+        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,
+        use_rfc3339: bool = False,
         **kwargs,
     ):
         self.service = resolve_env_var_choice(
@@ -205,7 +226,20 @@ def __init__(
         self._default_log_keys = {"service": self.service, "sampling_rate": self.sampling_rate}
         self._logger = self._get_logger()
 
-        self._init_logger(**kwargs)
+        # NOTE: This is primarily to improve UX, so IDEs can autocomplete LambdaPowertoolsFormatter options
+        # previously, we masked all of them as kwargs thus limiting feature discovery
+        formatter_options = {
+            "json_serializer": json_serializer,
+            "json_deserializer": json_deserializer,
+            "json_default": json_default,
+            "datefmt": datefmt,
+            "use_datetime_directive": use_datetime_directive,
+            "log_record_order": log_record_order,
+            "utc": utc,
+            "use_rfc3339": use_rfc3339,
+        }
+
+        self._init_logger(formatter_options=formatter_options, **kwargs)
 
     def __getattr__(self, name):
         # Proxy attributes not found to actual logger to support backward compatibility
@@ -220,7 +254,7 @@ def _get_logger(self):
 
         return logging.getLogger(logger_name)
 
-    def _init_logger(self, **kwargs):
+    def _init_logger(self, formatter_options: Optional[Dict] = None, **kwargs):
         """Configures new logger"""
 
         # Skip configuration if it's a child logger or a pre-configured logger
@@ -235,7 +269,7 @@ def _init_logger(self, **kwargs):
         self._configure_sampling()
         self._logger.setLevel(self.log_level)
         self._logger.addHandler(self.logger_handler)
-        self.structure_logs(**kwargs)
+        self.structure_logs(formatter_options=formatter_options, **kwargs)
 
         # Maintenance: We can drop this upon Py3.7 EOL. It's a backport for "location" key to work
         self._logger.findCaller = self.findCaller
@@ -501,19 +535,23 @@ def registered_formatter(self) -> BasePowertoolsFormatter:
         """Convenience property to access logger formatter"""
         return self.registered_handler.formatter  # type: ignore
 
-    def structure_logs(self, append: bool = False, **keys):
+    def structure_logs(self, append: bool = False, formatter_options: Optional[Dict] = None, **keys):
         """Sets logging formatting to JSON.
 
         Optionally, it can append keyword arguments
-        to an existing logger so it is available across future log statements.
+        to an existing logger, so it is available across future log statements.
 
         Last keyword argument and value wins if duplicated.
 
         Parameters
         ----------
         append : bool, optional
             append keys provided to logger formatter, by default False
+        formatter_options : dict, optional
+            LambdaPowertoolsFormatter options to be propagated, by default {}
         """
+        formatter_options = formatter_options or {}
+
         # There are 3 operational modes for this method
         ## 1. Register a Powertools Formatter for the first time
         ## 2. Append new keys to the current logger formatter; deprecated in favour of append_keys
@@ -523,7 +561,7 @@ def structure_logs(self, append: bool = False, **keys):
         log_keys = {**self._default_log_keys, **keys}
         is_logger_preconfigured = getattr(self._logger, "init", False)
         if not is_logger_preconfigured:
-            formatter = self.logger_formatter or LambdaPowertoolsFormatter(**log_keys)  # type: ignore
+            formatter = self.logger_formatter or LambdaPowertoolsFormatter(**formatter_options, **log_keys)  # type: ignore # noqa: E501
             self.registered_handler.setFormatter(formatter)
 
             # when using a custom Lambda Powertools Formatter

docs/core/logger.md

@@ -291,6 +291,30 @@ Use `logger.exception` method to log contextual information about exceptions. Lo
     --8<-- "examples/logger/src/logging_exceptions_output.json"
     ```
 
+### Date formatting
+
+Logger uses Python's standard logging date format with the addition of timezone: `2021-05-03 11:47:12,494+0200`.
+
+You can easily change the date format using one of the following parameters:
+
+* **`datefmt`**. You can pass any [strftime format codes](https://strftime.org/){target="_blank"}. Use `%F` if you need milliseconds.
+* **`use_rfc3339`**. This flag will use a format compliant with both RFC3339 and ISO8601: `2022-10-27T16:27:43.738+02:00`
+
+???+ tip "Prefer using [datetime string formats](https://docs.python.org/3/library/datetime.html#strftime-and-strptime-format-codes){target="_blank"}?"
+	Use `use_datetime_directive` flag along with `datefmt` to instruct Logger to use `datetime` instead of `time.strftime`.
+
+=== "date_formatting.py"
+
+    ```python hl_lines="5 8"
+    --8<-- "examples/logger/src/date_formatting.py"
+    ```
+
+=== "date_formatting_output.json"
+
+    ```json hl_lines="6 13"
+    --8<-- "examples/logger/src/date_formatting_output.json"
+    ```
+
 ## Advanced
 
 ### Built-in Correlation ID expressions
@@ -451,24 +475,19 @@ Do this instead:
 
 #### 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`.
+Logger allows you to either change the format or suppress the following keys at initialization: `location`, `timestamp`, `xray_trace_id`.
 
 === "overriding_log_records.py"
 
-    ```python hl_lines="7 10"
+    ```python hl_lines="6 10"
     --8<-- "examples/logger/src/overriding_log_records.py"
     ```
 
 === "overriding_log_records_output.json"
 
-    ```json hl_lines="3 5"
+    ```json hl_lines="4"
     --8<-- "examples/logger/src/overriding_log_records_output.json"
     ```
 

examples/logger/src/date_formatting.py

@@ -0,0 +1,9 @@
+from aws_lambda_powertools import Logger
+
+date_format = "%m/%d/%Y %I:%M:%S %p"
+
+logger = Logger(service="payment", use_rfc3339=True)
+logger.info("Collecting payment")
+
+logger_custom_format = Logger(service="loyalty", datefmt=date_format)
+logger_custom_format.info("Calculating points")

examples/logger/src/date_formatting_output.json

@@ -0,0 +1,16 @@
+[
+    {
+        "level": "INFO",
+        "location": "<module>:6",
+        "message": "Collecting payment",
+        "timestamp": "2022-10-28T14:35:03.210+02:00",
+        "service": "payment"
+    },
+    {
+        "level": "INFO",
+        "location": "<module>:9",
+        "message": "Calculating points",
+        "timestamp": "10/28/2022 02:35:03 PM",
+        "service": "loyalty"
+    }
+]

examples/logger/src/overriding_log_records.py

@@ -1,12 +1,11 @@
 from aws_lambda_powertools import Logger
 
-date_format = "%m/%d/%Y %I:%M:%S %p"
 location_format = "[%(funcName)s] %(module)s"
 
 # override location and timestamp format
-logger = Logger(service="payment", location=location_format, datefmt=date_format)
-
-# suppress the location key with a None value
-logger_two = Logger(service="payment", location=None)
-
+logger = Logger(service="payment", location=location_format)
 logger.info("Collecting payment")
+
+# suppress keys with a None value
+logger_two = Logger(service="loyalty", location=None)
+logger_two.info("Calculating points")

examples/logger/src/overriding_log_records_output.json

@@ -1,7 +1,15 @@
-{
-    "level": "INFO",
-    "location": "[<module>] lambda_handler",
-    "message": "Collecting payment",
-    "timestamp": "02/09/2021 09:25:17 AM",
-    "service": "payment"
-}
+[
+    {
+        "level": "INFO",
+        "location": "[<module>] overriding_log_records",
+        "message": "Collecting payment",
+        "timestamp": "2022-10-28 14:40:43,801+0200",
+        "service": "payment"
+    },
+    {
+        "level": "INFO",
+        "message": "Calculating points",
+        "timestamp": "2022-10-28 14:40:43,801+0200",
+        "service": "loyalty"
+    }
+]

tests/functional/test_logger.py

@@ -814,6 +814,21 @@ def test_use_datetime(stdout, service_name, utc):
     )
 
 
+@pytest.mark.parametrize("utc", [False, True])
+def test_use_rfc3339_iso8601(stdout, service_name, utc):
+    # GIVEN
+    logger = Logger(service=service_name, stream=stdout, use_rfc3339=True, utc=utc)
+    RFC3339_REGEX = r"^((?:(\d{4}-\d{2}-\d{2})T(\d{2}:\d{2}:\d{2}(?:\.\d+)?))(Z|[\+-]\d{2}:\d{2})?)$"
+
+    # WHEN a log statement happens
+    logger.info({})
+
+    # THEN the timestamp has the appropriate formatting
+    log = capture_logging_output(stdout)
+
+    assert re.fullmatch(RFC3339_REGEX, log["timestamp"])  # "2022-10-27T17:42:26.841+0200"
+
+
 def test_inject_lambda_context_log_event_request_data_classes(lambda_context, stdout, lambda_event, service_name):
     # GIVEN Logger is initialized
     logger = Logger(service=service_name, stream=stdout)