From 38e5f592a8d3d301f8de99fd7697ce42bd5d860b Mon Sep 17 00:00:00 2001 From: Huon Wilson Date: Tue, 21 Dec 2021 10:24:56 +1100 Subject: [PATCH 1/8] Add 'datetime_fmt' for log message timestamps using datetime --- aws_lambda_powertools/logging/formatter.py | 38 +++++++++++++++++++--- aws_lambda_powertools/logging/logger.py | 6 +++- tests/functional/test_logger.py | 24 ++++++++++++++ 3 files changed, 62 insertions(+), 6 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 246fa171d4e..c645322c2ed 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/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, + datetime_fmt: Optional[str] = None, log_record_order: Optional[List[str]] = None, utc: bool = False, - **kwargs + **kwargs, ): """Return a LambdaPowertoolsFormatter instance. @@ -86,20 +88,33 @@ 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 using `time`. Only one of `datefmt` + and `datetime_fmt` should be specified. See https://docs.python.org/3/library/time.html#time.strftime + datetime_fmt : str, optional + String directives (strftime) to format log timestamp using `datetime`. Only one of + `datefmt` and `datetime_fmt` should be specified. + + 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=(",", ":")) + + if datefmt and datetime_fmt: + raise ValueError(f"at most one of datefmt {datefmt!r} and datetime_fmt {datetime_fmt!r} can be specified") self.datefmt = datefmt + self.datetime_fmt = datetime_fmt + 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 +144,26 @@ 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) # 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 + + if datefmt or self.datefmt: + return time.strftime(datefmt or self.datefmt, record_ts) + + elif self.datetime_fmt: + timestamp = record.created + record.msecs / 1000 + + dt = datetime.fromtimestamp(timestamp, tz=timezone.utc) + if not self.utc: + # convert back to local time + dt = dt.astimezone() + + custom_fmt = self.datetime_fmt.replace(self.custom_ms_time_directive, msecs) + return dt.strftime(custom_fmt) + custom_fmt = self.default_time_format.replace(self.custom_ms_time_directive, msecs) return time.strftime(custom_fmt, record_ts) @@ -219,7 +247,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 = {} diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 7ca5a18e6f4..5ae53711048 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -80,7 +80,11 @@ class Logger(logging.Logger): # lgtm [py/missing-call-to-init] 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. Only one of `datefmt` and `datetime_fmt` should be specified. + datetime_fmt : str, optional + String directives (strftime) to format log timestamp using `datetime`. Only one of `datefmt` + and `datetime_fmt` should be specified. 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 3fb43474081..cb428cf578d 100644 --- a/tests/functional/test_logger.py +++ b/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,25 @@ def handler(event, context, my_custom_option=None): # THEN handler({}, lambda_context, my_custom_option="blah") + + +@pytest.mark.parametrize("utc", [False, True]) +def test_datetime_fmt(stdout, service_name, utc): + # GIVEN + logger = Logger( + service=service_name, + stream=stdout, + datetime_fmt="custom timestamp: milliseconds=%F microseconds=%f timezone=%z", + 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"] + ) From 88fe303ef40041773097222a958ac19759bc5997 Mon Sep 17 00:00:00 2001 From: Huon Wilson Date: Thu, 23 Dec 2021 12:50:47 +1100 Subject: [PATCH 2/8] Switch to use_datetime --- aws_lambda_powertools/logging/formatter.py | 30 +++++++++++----------- aws_lambda_powertools/logging/logger.py | 11 +++++--- tests/functional/test_logger.py | 5 ++-- 3 files changed, 25 insertions(+), 21 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index c645322c2ed..198c55cac17 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -62,7 +62,7 @@ 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, - datetime_fmt: Optional[str] = None, + use_datetime: bool = False, log_record_order: Optional[List[str]] = None, utc: bool = False, **kwargs, @@ -88,13 +88,12 @@ def __init__( Only used when no custom JSON encoder is set datefmt : str, optional - String directives (strftime) to format log timestamp using `time`. Only one of `datefmt` - and `datetime_fmt` should be specified. + String directives (strftime) to format log timestamp. - See https://docs.python.org/3/library/time.html#time.strftime - datetime_fmt : str, optional - String directives (strftime) to format log timestamp using `datetime`. Only one of - `datefmt` and `datetime_fmt` should be specified. + See https://docs.python.org/3/library/time.html#time.strftime or + use_datetime: 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. @@ -110,10 +109,8 @@ def __init__( self.json_default = json_default or str self.json_serializer = json_serializer or partial(json.dumps, default=self.json_default, separators=(",", ":")) - if datefmt and datetime_fmt: - raise ValueError(f"at most one of datefmt {datefmt!r} and datetime_fmt {datetime_fmt!r} can be specified") self.datefmt = datefmt - self.datetime_fmt = datetime_fmt + self.use_datetime = use_datetime self.utc = utc self.log_record_order = log_record_order or ["level", "location", "message", "timestamp"] @@ -145,15 +142,15 @@ 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 is None: + 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 - if datefmt or self.datefmt: - return time.strftime(datefmt or self.datefmt, record_ts) - - elif self.datetime_fmt: + if self.use_datetime: timestamp = record.created + record.msecs / 1000 dt = datetime.fromtimestamp(timestamp, tz=timezone.utc) @@ -161,9 +158,12 @@ def formatTime(self, record: logging.LogRecord, datefmt: Optional[str] = None) - # convert back to local time dt = dt.astimezone() - custom_fmt = self.datetime_fmt.replace(self.custom_ms_time_directive, msecs) + custom_fmt = (datefmt or self.default_time_format).replace(self.custom_ms_time_directive, msecs) return dt.strftime(custom_fmt) + elif datefmt: + return time.strftime(datefmt, record_ts) + 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 5ae53711048..b07240b66c3 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -81,10 +81,13 @@ class Logger(logging.Logger): # lgtm [py/missing-call-to-init] --------------------------------------------- datefmt: str, optional String directives (strftime) to format log timestamp using `time`, by default it uses RFC - 3339. Only one of `datefmt` and `datetime_fmt` should be specified. - datetime_fmt : str, optional - String directives (strftime) to format log timestamp using `datetime`. Only one of `datefmt` - and `datetime_fmt` should be specified. + 3339. + use_datetime: 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 diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index cb428cf578d..9f8504c9c69 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -615,12 +615,13 @@ def handler(event, context, my_custom_option=None): @pytest.mark.parametrize("utc", [False, True]) -def test_datetime_fmt(stdout, service_name, utc): +def test_use_datetime(stdout, service_name, utc): # GIVEN logger = Logger( service=service_name, stream=stdout, - datetime_fmt="custom timestamp: milliseconds=%F microseconds=%f timezone=%z", + datefmt="custom timestamp: milliseconds=%F microseconds=%f timezone=%z", + use_datetime=True, utc=utc, ) From cd93938db4d565c903d0bb845e2dbf2f8b09f162 Mon Sep 17 00:00:00 2001 From: Huon Wilson Date: Thu, 23 Dec 2021 12:50:57 +1100 Subject: [PATCH 3/8] Docs --- docs/core/logger.md | 1 + 1 file changed, 1 insertion(+) diff --git a/docs/core/logger.md b/docs/core/logger.md index 833d5a5c721..b21bfe5d87a 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -639,6 +639,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`** | 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` From 00a07d4684f1b4f6aebe96f040df920c539bb300 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Fri, 31 Dec 2021 17:44:52 +0100 Subject: [PATCH 4/8] chore: comments, flag rename to be more explicit --- aws_lambda_powertools/logging/formatter.py | 28 +++++++++++++--------- 1 file changed, 17 insertions(+), 11 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 198c55cac17..5904ae3dc59 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -62,7 +62,7 @@ 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: bool = False, + use_datetime_directive: bool = False, log_record_order: Optional[List[str]] = None, utc: bool = False, **kwargs, @@ -91,9 +91,9 @@ def __init__( String directives (strftime) to format log timestamp. See https://docs.python.org/3/library/time.html#time.strftime or - use_datetime: str, optional + use_datetime_directive: str, optional Interpret `datefmt` as a format string for `datetime.datetime.strftime`, rather than - `time.strftime`. + `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. @@ -110,7 +110,7 @@ def __init__( self.json_serializer = json_serializer or partial(json.dumps, default=self.json_default, separators=(",", ":")) self.datefmt = datefmt - self.use_datetime = use_datetime + self.use_datetime = use_datetime_directive self.utc = utc self.log_record_order = log_record_order or ["level", "location", "message", "timestamp"] @@ -150,19 +150,25 @@ def formatTime(self, record: logging.LogRecord, datefmt: Optional[str] = None) - # Reason 2 is that std logging doesn't support msec after TZ msecs = "%03d" % record.msecs - if self.use_datetime: + # 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 and datefmt: + # record.msecs are microseconds, divide by 1000 and we get milliseconds timestamp = record.created + record.msecs / 1000 - dt = datetime.fromtimestamp(timestamp, tz=timezone.utc) - if not self.utc: - # convert back to local time - dt = dt.astimezone() + 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 or self.default_time_format).replace(self.custom_ms_time_directive, msecs) + custom_fmt = datefmt.replace(self.custom_ms_time_directive, msecs) return dt.strftime(custom_fmt) elif datefmt: - return time.strftime(datefmt, record_ts) + 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) From 311ff50de64b4cfbe313d276a06f886d80c15e47 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Fri, 31 Dec 2021 18:00:57 +0100 Subject: [PATCH 5/8] docs: mention new use_datetime_directive usage --- aws_lambda_powertools/logging/logger.py | 4 ++-- docs/core/logger.md | 10 +++++++--- 2 files changed, 9 insertions(+), 5 deletions(-) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index b07240b66c3..938742fb0a3 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -78,11 +78,11 @@ 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 using `time`, by default it uses RFC 3339. - use_datetime: str, optional + use_datetime_directive: str, optional Interpret `datefmt` as a format string for `datetime.datetime.strftime`, rather than `time.strftime`. diff --git a/docs/core/logger.md b/docs/core/logger.md index c144486e5e9..6b3370be174 100644 --- a/docs/core/logger.md +++ b/docs/core/logger.md @@ -656,7 +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`** | format the `datefmt` timestamps using `datetime`, not `time` (also supports the custom `%F` directive for milliseconds) | `False` +**`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` @@ -727,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 From fb05528100cc6ab158e8ec165dd6e28b1bf85ebf Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Fri, 31 Dec 2021 18:04:44 +0100 Subject: [PATCH 6/8] chore: linting --- aws_lambda_powertools/logging/formatter.py | 4 ++-- tests/functional/test_logger.py | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 5904ae3dc59..8eb93957445 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -110,7 +110,7 @@ def __init__( self.json_serializer = json_serializer or partial(json.dumps, default=self.json_default, separators=(",", ":")) self.datefmt = datefmt - self.use_datetime = use_datetime_directive + self.use_datetime_directive = use_datetime_directive self.utc = utc self.log_record_order = log_record_order or ["level", "location", "message", "timestamp"] @@ -153,7 +153,7 @@ def formatTime(self, record: logging.LogRecord, datefmt: Optional[str] = None) - # 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 and datefmt: + if self.use_datetime_directive and datefmt: # record.msecs are microseconds, divide by 1000 and we get milliseconds timestamp = record.created + record.msecs / 1000 diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index 9f8504c9c69..6b05119b88b 100644 --- a/tests/functional/test_logger.py +++ b/tests/functional/test_logger.py @@ -621,7 +621,7 @@ def test_use_datetime(stdout, service_name, utc): service=service_name, stream=stdout, datefmt="custom timestamp: milliseconds=%F microseconds=%f timezone=%z", - use_datetime=True, + use_datetime_directive=True, utc=utc, ) From 5ee69d98d0515cbc842e4bfd0f223c192cb570b4 Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Fri, 31 Dec 2021 18:08:46 +0100 Subject: [PATCH 7/8] chore: coverage --- aws_lambda_powertools/logging/formatter.py | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 8eb93957445..a15452da9fd 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -142,7 +142,7 @@ 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 is None: + 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 From e0c5751044fcca974e0a591bd371f0849131effc Mon Sep 17 00:00:00 2001 From: heitorlessa Date: Fri, 31 Dec 2021 18:10:00 +0100 Subject: [PATCH 8/8] chore: left over from other PR --- docs/utilities/feature_flags.md | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/docs/utilities/feature_flags.md b/docs/utilities/feature_flags.md index 9fb79ac1eec..416b768e77e 100644 --- a/docs/utilities/feature_flags.md +++ b/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"