From 9cdc3744aa3de36acc1b8e01c87398409c948360 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Thu, 27 Oct 2022 19:21:30 +0200 Subject: [PATCH 1/4] feat(logger): add use_rfc3339_iso8601 option --- aws_lambda_powertools/logging/formatter.py | 33 ++++++++++++++++++---- aws_lambda_powertools/logging/logger.py | 4 +++ tests/functional/test_logger.py | 15 ++++++++++ 3 files changed, 46 insertions(+), 6 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 25f9c227c97..c6f55db91d2 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/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_iso8601: 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_iso8601: bool, optional + Whether to use a popular dateformat that complies with both RFC3339 and ISO8601. + 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_iso8601 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) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 2b97df75c1f..40625fbb0ed 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -94,6 +94,10 @@ class Logger(logging.Logger): # lgtm [py/missing-call-to-init] See https://docs.python.org/3/library/datetime.html#strftime-strptime-behavior . This also supports a custom %F directive for milliseconds. + use_rfc3339_iso8601: bool, optional + Whether to use a popular dateformat that complies with both RFC3339 and ISO8601. + + Example: 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 diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index 4876da5cacf..a30dc8ec5a7 100644 --- a/tests/functional/test_logger.py +++ b/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_iso8601=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) From f89ab73dd060d0bbb225b3fae6e7ee486576076e Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Fri, 28 Oct 2022 13:48:49 +0200 Subject: [PATCH 2/4] feat(logger): expose LambdaPowertoolsFormatter options in Logger for IDE aid --- aws_lambda_powertools/logging/logger.py | 53 ++++++++++++++++++++----- 1 file changed, 44 insertions(+), 9 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 40625fbb0ed..ba22799153e 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/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,8 +97,7 @@ 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`. @@ -191,6 +201,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_iso8601: bool = False, **kwargs, ): self.service = resolve_env_var_choice( @@ -209,7 +227,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_iso8601": use_rfc3339_iso8601, + } + + self._init_logger(formatter_options=formatter_options, **kwargs) def __getattr__(self, name): # Proxy attributes not found to actual logger to support backward compatibility @@ -224,7 +255,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 @@ -239,7 +270,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 @@ -505,11 +536,11 @@ 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. @@ -517,7 +548,11 @@ def structure_logs(self, append: bool = False, **keys): ---------- 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 @@ -527,7 +562,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 From 58186be69dfdd3246b77c13779f76c2a86cc9438 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Fri, 28 Oct 2022 13:56:21 +0200 Subject: [PATCH 3/4] chore: address leandro's feedback and shorten to use_rfc3339 --- aws_lambda_powertools/logging/formatter.py | 8 ++++---- aws_lambda_powertools/logging/logger.py | 11 +++++------ tests/functional/test_logger.py | 2 +- 3 files changed, 10 insertions(+), 11 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index c6f55db91d2..07971ba0a26 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -73,7 +73,7 @@ def __init__( use_datetime_directive: bool = False, log_record_order: Optional[List[str]] = None, utc: bool = False, - use_rfc3339_iso8601: bool = False, + use_rfc3339: bool = False, **kwargs, ): """Return a LambdaPowertoolsFormatter instance. @@ -108,9 +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_iso8601: bool, optional + 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 @@ -134,7 +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_iso8601 + self.use_rfc3339_iso8601 = use_rfc3339 if self.utc: self.converter = time.gmtime # type: ignore diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index ba22799153e..be30c098db4 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -104,10 +104,9 @@ class Logger(logging.Logger): # lgtm [py/missing-call-to-init] See https://docs.python.org/3/library/datetime.html#strftime-strptime-behavior . This also supports a custom %F directive for milliseconds. - use_rfc3339_iso8601: bool, optional - Whether to use a popular dateformat that complies with both RFC3339 and ISO8601. - - Example: 2022-10-27T16:27:43.738+02:00. + 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 @@ -208,7 +207,7 @@ def __init__( use_datetime_directive: bool = False, log_record_order: Optional[List[str]] = None, utc: bool = False, - use_rfc3339_iso8601: bool = False, + use_rfc3339: bool = False, **kwargs, ): self.service = resolve_env_var_choice( @@ -237,7 +236,7 @@ def __init__( "use_datetime_directive": use_datetime_directive, "log_record_order": log_record_order, "utc": utc, - "use_rfc3339_iso8601": use_rfc3339_iso8601, + "use_rfc3339": use_rfc3339, } self._init_logger(formatter_options=formatter_options, **kwargs) diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index a30dc8ec5a7..f171ba7ee5b 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -817,7 +817,7 @@ 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_iso8601=True, utc=utc) + 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 From fdd92616cd5787ec92888e97c071706b114dd2e9 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Fri, 28 Oct 2022 14:44:42 +0200 Subject: [PATCH 4/4] docs(logger): dedicated section for date formatting --- docs/core/logger.md | 35 ++++++++++++++----- examples/logger/src/date_formatting.py | 9 +++++ .../logger/src/date_formatting_output.json | 16 +++++++++ examples/logger/src/overriding_log_records.py | 11 +++--- .../src/overriding_log_records_output.json | 22 ++++++++---- 5 files changed, 72 insertions(+), 21 deletions(-) create mode 100644 examples/logger/src/date_formatting.py create mode 100644 examples/logger/src/date_formatting_output.json diff --git a/docs/core/logger.md b/docs/core/logger.md index 8fc9da441ac..471186cba5b 100644 --- a/docs/core/logger.md +++ b/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" ``` diff --git a/examples/logger/src/date_formatting.py b/examples/logger/src/date_formatting.py new file mode 100644 index 00000000000..edca29201ec --- /dev/null +++ b/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") diff --git a/examples/logger/src/date_formatting_output.json b/examples/logger/src/date_formatting_output.json new file mode 100644 index 00000000000..2d5ba1dff88 --- /dev/null +++ b/examples/logger/src/date_formatting_output.json @@ -0,0 +1,16 @@ +[ + { + "level": "INFO", + "location": ":6", + "message": "Collecting payment", + "timestamp": "2022-10-28T14:35:03.210+02:00", + "service": "payment" + }, + { + "level": "INFO", + "location": ":9", + "message": "Calculating points", + "timestamp": "10/28/2022 02:35:03 PM", + "service": "loyalty" + } +] \ No newline at end of file diff --git a/examples/logger/src/overriding_log_records.py b/examples/logger/src/overriding_log_records.py index f32da431158..519d8ef2220 100644 --- a/examples/logger/src/overriding_log_records.py +++ b/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") diff --git a/examples/logger/src/overriding_log_records_output.json b/examples/logger/src/overriding_log_records_output.json index ba2f1dfe8d5..676f36ca298 100644 --- a/examples/logger/src/overriding_log_records_output.json +++ b/examples/logger/src/overriding_log_records_output.json @@ -1,7 +1,15 @@ -{ - "level": "INFO", - "location": "[] lambda_handler", - "message": "Collecting payment", - "timestamp": "02/09/2021 09:25:17 AM", - "service": "payment" -} +[ + { + "level": "INFO", + "location": "[] 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" + } +] \ No newline at end of file