diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 246fa171d4e..a15452da9fd 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, + 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 = {} diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 7ca5a18e6f4..938742fb0a3 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/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 diff --git a/docs/core/logger.md b/docs/core/logger.md index 6de24577b66..6b3370be174 100644 --- a/docs/core/logger.md +++ b/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 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" diff --git a/tests/functional/test_logger.py b/tests/functional/test_logger.py index 3fb43474081..6b05119b88b 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,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"] + )