fix lambda local tz

Author: roger-zhangg

aws_lambda_powertools/logging/formatter.py

@@ -4,7 +4,6 @@
 import json
 import logging
 import os
-import time
 from abc import ABCMeta, abstractmethod
 from datetime import datetime, timezone
 from functools import partial
@@ -42,6 +41,12 @@
 )
 
 
+def local_tz_converter(secs: float, utc: bool) -> datetime:
+    if utc:
+        return datetime.fromtimestamp(secs, tz=timezone.utc)
+    return datetime.fromtimestamp(secs).astimezone()
+
+
 class BasePowertoolsFormatter(logging.Formatter, metaclass=ABCMeta):
     @abstractmethod
     def append_keys(self, **additional_keys) -> None:
@@ -142,9 +147,6 @@ def __init__(
         self.update_formatter = self.append_keys  # alias to old method
         self.use_rfc3339_iso8601 = use_rfc3339
 
-        if self.utc:
-            self.converter = time.gmtime
-
         self.keys_combined = {**self._build_default_keys(), **kwargs}
         self.log_format.update(**self.keys_combined)
 
@@ -178,11 +180,10 @@ def formatTime(self, record: logging.LogRecord, datefmt: Optional[str] = None) -
                 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)
+        record_ts = local_tz_converter(record.created, self.utc)
 
         if datefmt is None:  # pragma: no cover, it'll always be None in std logging, but mypy
             datefmt = self.datefmt
@@ -211,11 +212,11 @@ def formatTime(self, record: logging.LogRecord, datefmt: Optional[str] = None) -
         # 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)
+            return record_ts.strftime(custom_fmt)
 
         # 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)
+        return record_ts.strftime(custom_fmt)
 
     def append_keys(self, **additional_keys) -> None:
         self.log_format.update(additional_keys)

tests/functional/test_logger.py

@@ -3,10 +3,12 @@
 import io
 import json
 import logging
+import os
 import random
 import re
 import string
 import sys
+import time
 import warnings
 from ast import Dict
 from collections import namedtuple
@@ -959,3 +961,36 @@ def test_stream_defaults_to_stdout(service_name, capsys):
     # NOTE: we can't assert on capsys.readouterr().err due to a known bug: https://github.com/pytest-dev/pytest/issues/5997
     log = json.loads(capsys.readouterr().out.strip())
     assert log["message"] == msg
+
+
+@pytest.mark.parametrize(
+    "utc,tz",
+    [(False, "Etc/GMT+11"), (True, "Etc/GMT+11"), (False, "US/Alaska"), (True, "US/Alaska")],
+)
+def test_tz_env_var(stdout, service_name, utc, tz, capsys):
+    # GIVEN
+
+    # set tz env var to tz input
+    os.environ["TZ"] = tz
+
+    # Refresh the local TZ to time lib, for we just changed tz env var
+    # we don't need this in prod env. Time Class read this info at import
+    time.tzset()
+
+    logger = Logger(
+        service=service_name,
+        datefmt="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 = json.loads(capsys.readouterr().out.strip())
+
+    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"],
+    )