From 133f26028020e71008c0f1228596f52500b58efc Mon Sep 17 00:00:00 2001 From: Michael Brewer Date: Thu, 27 Aug 2020 07:23:57 -0700 Subject: [PATCH 1/6] feat(logger): readable log_dict seq Ensure that the initial key seq is: timestamp,level,location,message Closes #138 --- aws_lambda_powertools/logging/formatter.py | 1 + tests/functional/test_aws_lambda_logging.py | 13 +++++++++++++ 2 files changed, 14 insertions(+) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index bb0d9865f2c..b21f845ea2a 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -53,6 +53,7 @@ def __init__(self, **kwargs): "timestamp": "%(asctime)s", "level": "%(levelname)s", "location": "%(funcName)s:%(lineno)d", + "message": "", } self.format_dict.update(kwargs) diff --git a/tests/functional/test_aws_lambda_logging.py b/tests/functional/test_aws_lambda_logging.py index 86c6124cb1f..4908beee109 100644 --- a/tests/functional/test_aws_lambda_logging.py +++ b/tests/functional/test_aws_lambda_logging.py @@ -116,3 +116,16 @@ class Unserializable: # THEN json_default should not be in the log message and the custom unserializable handler should be used assert log_dict["message"]["x"] == "" assert "json_default" not in log_dict + + +def test_log_dict_key_seq(stdout): + # GIVEN any logger configuration + logger = Logger(level="INFO", stream=stdout, another="xxx") + + # WHEN logging a message + logger.info("Message") + + log_dict: dict = json.loads(stdout.getvalue()) + + # THEN the key sequence should be `timestamp,level,location,message` + assert ",".join(list(log_dict.keys())[:4]) == "timestamp,level,location,message" From f9f4bde20f3aa028f76e1ad87defcf109751a78f Mon Sep 17 00:00:00 2001 From: Michael Brewer Date: Thu, 27 Aug 2020 08:10:48 -0700 Subject: [PATCH 2/6] refactor: use None instead of --- 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 b21f845ea2a..327fde7155e 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -53,7 +53,7 @@ def __init__(self, **kwargs): "timestamp": "%(asctime)s", "level": "%(levelname)s", "location": "%(funcName)s:%(lineno)d", - "message": "", + "message": None, } self.format_dict.update(kwargs) From e148ffc674724b5b5654085cdc758721acb8a125 Mon Sep 17 00:00:00 2001 From: Michael Brewer Date: Thu, 27 Aug 2020 11:36:58 -0700 Subject: [PATCH 3/6] feat(logging): allow for custom json order Changes: * add `format_key` to allow for a custom order * remove unessarly verbose `json_formatter` with just `str` * update tests --- aws_lambda_powertools/logging/formatter.py | 34 +++------------------ tests/functional/test_aws_lambda_logging.py | 17 +++++++++-- 2 files changed, 20 insertions(+), 31 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 327fde7155e..6fada71fa9c 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -1,27 +1,5 @@ import json import logging -from typing import Any - - -def json_formatter(unserializable_value: Any): - """JSON custom serializer to cast unserializable values to strings. - - Example - ------- - - **Serialize unserializable value to string** - - class X: pass - value = {"x": X()} - - json.dumps(value, default=json_formatter) - - Parameters - ---------- - unserializable_value: Any - Python object unserializable by JSON - """ - return str(unserializable_value) class JsonFormatter(logging.Formatter): @@ -44,17 +22,15 @@ def __init__(self, **kwargs): Other kwargs are used to specify log field format strings. """ - self.default_json_formatter = kwargs.pop("json_default", json_formatter) + self.default_json_formatter = kwargs.pop("json_default", str) datefmt = kwargs.pop("datefmt", None) super(JsonFormatter, self).__init__(datefmt=datefmt) self.reserved_keys = ["timestamp", "level", "location"] - self.format_dict = { - "timestamp": "%(asctime)s", - "level": "%(levelname)s", - "location": "%(funcName)s:%(lineno)d", - "message": None, - } + self.format_dict = dict.fromkeys(kwargs.pop("format_key", ["level", "location", "message", "timestamp"])) + self.format_dict.update( + {"level": "%(levelname)s", "location": "%(funcName)s:%(lineno)d", "timestamp": "%(asctime)s"} + ) self.format_dict.update(kwargs) def update_formatter(self, **kwargs): diff --git a/tests/functional/test_aws_lambda_logging.py b/tests/functional/test_aws_lambda_logging.py index 4908beee109..d882d96c2f5 100644 --- a/tests/functional/test_aws_lambda_logging.py +++ b/tests/functional/test_aws_lambda_logging.py @@ -127,5 +127,18 @@ def test_log_dict_key_seq(stdout): log_dict: dict = json.loads(stdout.getvalue()) - # THEN the key sequence should be `timestamp,level,location,message` - assert ",".join(list(log_dict.keys())[:4]) == "timestamp,level,location,message" + # THEN the key sequence should be `level,location,message,timestamp` + assert ",".join(list(log_dict.keys())[:4]) == "level,location,message,timestamp" + + +def test_log_dict_key_custom_seq(stdout): + # GIVEN any logger configuration + logger = Logger(level="INFO", stream=stdout, another="xxx", format_key=["message"]) + + # WHEN logging a message + logger.info("Message") + + log_dict: dict = json.loads(stdout.getvalue()) + + # THEN the key sequence should be `level,location,message,timestamp` + assert ",".join(list(log_dict.keys())[:4]) == "message,level,location,timestamp" From 3e0116bd106cd4fdebce652ae0c1728f2a4855e6 Mon Sep 17 00:00:00 2001 From: Michael Brewer Date: Thu, 27 Aug 2020 15:00:05 -0700 Subject: [PATCH 4/6] feat(logging): suppress some log keys Some keys like `location` and `timestamp` can be suppressed by setting them to None. Changes: * logger.py - Convert some methods to static functions * test_aws_lambda_logging - Add more tests and some which can be used for documentation --- aws_lambda_powertools/logging/formatter.py | 5 ++- aws_lambda_powertools/logging/logger.py | 50 +++++++++++---------- tests/functional/test_aws_lambda_logging.py | 36 ++++++++++++--- 3 files changed, 62 insertions(+), 29 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 6fada71fa9c..6c1adfdd02b 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -27,7 +27,7 @@ def __init__(self, **kwargs): super(JsonFormatter, self).__init__(datefmt=datefmt) self.reserved_keys = ["timestamp", "level", "location"] - self.format_dict = dict.fromkeys(kwargs.pop("format_key", ["level", "location", "message", "timestamp"])) + self.format_dict = dict.fromkeys(kwargs.pop("format_keys", ["level", "location", "message", "timestamp"])) self.format_dict.update( {"level": "%(levelname)s", "location": "%(funcName)s:%(lineno)d", "timestamp": "%(asctime)s"} ) @@ -71,4 +71,7 @@ def format(self, record): # noqa: A003 if record.exc_text: log_dict["exception"] = record.exc_text + # Filter out top level key with values that are None + log_dict = {k: v for k, v in log_dict.items() if v is not None} + return json.dumps(log_dict, default=self.default_json_formatter) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index b566ee83a83..2b519a089f8 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -123,7 +123,7 @@ def __init__( ): self.service = service or os.getenv("POWERTOOLS_SERVICE_NAME") or "service_undefined" self.sampling_rate = sampling_rate or os.getenv("POWERTOOLS_LOGGER_SAMPLE_RATE") or 0.0 - self.log_level = self._get_log_level(level) + self.log_level = _get_log_level(level) self.child = child self._handler = logging.StreamHandler(stream) if stream is not None else logging.StreamHandler(sys.stdout) self._default_log_keys = {"service": self.service, "sampling_rate": self.sampling_rate} @@ -136,35 +136,14 @@ def __getattr__(self, name): # https://github.com/awslabs/aws-lambda-powertools-python/issues/97 return getattr(self._logger, name) - def _get_log_level(self, level: Union[str, int]) -> Union[str, int]: - """ Returns preferred log level set by the customer in upper case """ - if isinstance(level, int): - return level - - log_level: str = level or os.getenv("LOG_LEVEL") - log_level = log_level.upper() if log_level is not None else logging.INFO - - return log_level - def _get_logger(self): """ Returns a Logger named {self.service}, or {self.service.filename} for child loggers""" logger_name = self.service if self.child: - logger_name = f"{self.service}.{self._get_caller_filename()}" + logger_name = f"{self.service}.{_get_caller_filename()}" return logging.getLogger(logger_name) - def _get_caller_filename(self): - """ Return caller filename by finding the caller frame """ - # Current frame => _get_logger() - # Previous frame => logger.py - # Before previous frame => Caller - frame = inspect.currentframe() - caller_frame = frame.f_back.f_back.f_back - filename = caller_frame.f_globals["__name__"] - - return filename - def _init_logger(self, **kwargs): """Configures new logger""" @@ -207,6 +186,8 @@ def inject_lambda_context(self, lambda_handler: Callable[[Dict, Any], Any] = Non Parameters ---------- + lambda_handler : Callable + Method to inject the lambda context log_event : bool, optional Instructs logger to log Lambda Event, by default False @@ -292,6 +273,29 @@ def structure_logs(self, append: bool = False, **kwargs): handler.setFormatter(JsonFormatter(**self._default_log_keys, **kwargs)) +def _get_log_level(level: Union[str, int]) -> Union[str, int]: + """ Returns preferred log level set by the customer in upper case """ + if isinstance(level, int): + return level + + log_level: str = level or os.getenv("LOG_LEVEL") + log_level = log_level.upper() if log_level is not None else logging.INFO + + return log_level + + +def _get_caller_filename(): + """ Return caller filename by finding the caller frame """ + # Current frame => _get_logger() + # Previous frame => logger.py + # Before previous frame => Caller + frame = inspect.currentframe() + caller_frame = frame.f_back.f_back.f_back + filename = caller_frame.f_globals["__name__"] + + return filename + + def set_package_logger( level: Union[str, int] = logging.DEBUG, stream: sys.stdout = None, formatter: logging.Formatter = None ): diff --git a/tests/functional/test_aws_lambda_logging.py b/tests/functional/test_aws_lambda_logging.py index d882d96c2f5..8b06b4e06ca 100644 --- a/tests/functional/test_aws_lambda_logging.py +++ b/tests/functional/test_aws_lambda_logging.py @@ -127,18 +127,44 @@ def test_log_dict_key_seq(stdout): log_dict: dict = json.loads(stdout.getvalue()) - # THEN the key sequence should be `level,location,message,timestamp` + # THEN the beginning key sequence must be `level,location,message,timestamp` assert ",".join(list(log_dict.keys())[:4]) == "level,location,message,timestamp" def test_log_dict_key_custom_seq(stdout): - # GIVEN any logger configuration - logger = Logger(level="INFO", stream=stdout, another="xxx", format_key=["message"]) + # GIVEN a logger configuration with format_keys set to ["message"] + logger = Logger(stream=stdout, format_keys=["message"]) # WHEN logging a message logger.info("Message") log_dict: dict = json.loads(stdout.getvalue()) - # THEN the key sequence should be `level,location,message,timestamp` - assert ",".join(list(log_dict.keys())[:4]) == "message,level,location,timestamp" + # THEN the first key should be "message" + assert list(log_dict.keys())[0] == "message" + + +def test_log_custom_formatting(stdout): + # GIVEN a logger where we have a custom location format + logger = Logger(stream=stdout, location="[%(funcName)s] %(module)s") + + # WHEN logging a message + logger.info("foo") + + log_dict: dict = json.loads(stdout.getvalue()) + + # THEN the `location` match the formatting + assert log_dict["location"] == "[test_log_custom_formatting] test_aws_lambda_logging" + + +def test_log_dict_key_strip_nones(stdout): + # GIVEN a logger confirmation where we set `location` and `timestamp` to None + logger = Logger(stream=stdout, location=None, timestamp=None) + + # WHEN logging a message + logger.info("foo") + + log_dict: dict = json.loads(stdout.getvalue()) + + # THEN the keys should only include `level`, `message`, `service`, `sampling_rate` + assert sorted(log_dict.keys()) == ["level", "message", "sampling_rate", "service"] From e4c1e8e3517190167c65ca304ea69162a6c6c7bd Mon Sep 17 00:00:00 2001 From: Michael Brewer Date: Thu, 27 Aug 2020 22:47:26 -0700 Subject: [PATCH 5/6] refactor: make requested changes Changes: * Add missing comments and docs * formatter - Group the kwargs code * logger - convert back to class static methods --- aws_lambda_powertools/logging/formatter.py | 15 +++++--- aws_lambda_powertools/logging/logger.py | 40 ++++++++++----------- tests/functional/test_aws_lambda_logging.py | 16 +++++---- 3 files changed, 39 insertions(+), 32 deletions(-) diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index 6c1adfdd02b..f865c616a6e 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -20,18 +20,23 @@ def __init__(self, **kwargs): unserializable values. It must not throw. Defaults to a function that coerces the value to a string. + The `log_record_order` kwarg is used to specify the order of the keys used in + the structured json logs. By default the order is: "level", "location", "message", "timestamp", + "service" and "sampling_rate". + Other kwargs are used to specify log field format strings. """ + # Set the default unserializable function, by default values will be cast as str. self.default_json_formatter = kwargs.pop("json_default", str) - datefmt = kwargs.pop("datefmt", None) + # Set the insertion order for the log messages + self.format_dict = dict.fromkeys(kwargs.pop("log_record_order", ["level", "location", "message", "timestamp"])) + # Set timestamp the date format + super(JsonFormatter, self).__init__(datefmt=kwargs.pop("datefmt", None)) - super(JsonFormatter, self).__init__(datefmt=datefmt) self.reserved_keys = ["timestamp", "level", "location"] - self.format_dict = dict.fromkeys(kwargs.pop("format_keys", ["level", "location", "message", "timestamp"])) self.format_dict.update( - {"level": "%(levelname)s", "location": "%(funcName)s:%(lineno)d", "timestamp": "%(asctime)s"} + {"level": "%(levelname)s", "location": "%(funcName)s:%(lineno)d", "timestamp": "%(asctime)s", **kwargs} ) - self.format_dict.update(kwargs) def update_formatter(self, **kwargs): self.format_dict.update(kwargs) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index 2b519a089f8..55b1b766427 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/aws_lambda_powertools/logging/logger.py @@ -123,7 +123,7 @@ def __init__( ): self.service = service or os.getenv("POWERTOOLS_SERVICE_NAME") or "service_undefined" self.sampling_rate = sampling_rate or os.getenv("POWERTOOLS_LOGGER_SAMPLE_RATE") or 0.0 - self.log_level = _get_log_level(level) + self.log_level = self._get_log_level(level) self.child = child self._handler = logging.StreamHandler(stream) if stream is not None else logging.StreamHandler(sys.stdout) self._default_log_keys = {"service": self.service, "sampling_rate": self.sampling_rate} @@ -140,7 +140,7 @@ def _get_logger(self): """ Returns a Logger named {self.service}, or {self.service.filename} for child loggers""" logger_name = self.service if self.child: - logger_name = f"{self.service}.{_get_caller_filename()}" + logger_name = f"{self.service}.{self._get_caller_filename()}" return logging.getLogger(logger_name) @@ -272,28 +272,28 @@ def structure_logs(self, append: bool = False, **kwargs): # Set a new formatter for a logger handler handler.setFormatter(JsonFormatter(**self._default_log_keys, **kwargs)) + @staticmethod + def _get_log_level(level: Union[str, int]) -> Union[str, int]: + """ Returns preferred log level set by the customer in upper case """ + if isinstance(level, int): + return level -def _get_log_level(level: Union[str, int]) -> Union[str, int]: - """ Returns preferred log level set by the customer in upper case """ - if isinstance(level, int): - return level + log_level: str = level or os.getenv("LOG_LEVEL") + log_level = log_level.upper() if log_level is not None else logging.INFO - log_level: str = level or os.getenv("LOG_LEVEL") - log_level = log_level.upper() if log_level is not None else logging.INFO + return log_level - return log_level + @staticmethod + def _get_caller_filename(): + """ Return caller filename by finding the caller frame """ + # Current frame => _get_logger() + # Previous frame => logger.py + # Before previous frame => Caller + frame = inspect.currentframe() + caller_frame = frame.f_back.f_back.f_back + filename = caller_frame.f_globals["__name__"] - -def _get_caller_filename(): - """ Return caller filename by finding the caller frame """ - # Current frame => _get_logger() - # Previous frame => logger.py - # Before previous frame => Caller - frame = inspect.currentframe() - caller_frame = frame.f_back.f_back.f_back - filename = caller_frame.f_globals["__name__"] - - return filename + return filename def set_package_logger( diff --git a/tests/functional/test_aws_lambda_logging.py b/tests/functional/test_aws_lambda_logging.py index 8b06b4e06ca..b633acca390 100644 --- a/tests/functional/test_aws_lambda_logging.py +++ b/tests/functional/test_aws_lambda_logging.py @@ -119,8 +119,8 @@ class Unserializable: def test_log_dict_key_seq(stdout): - # GIVEN any logger configuration - logger = Logger(level="INFO", stream=stdout, another="xxx") + # GIVEN the default logger configuration + logger = Logger(stream=stdout) # WHEN logging a message logger.info("Message") @@ -133,7 +133,7 @@ def test_log_dict_key_seq(stdout): def test_log_dict_key_custom_seq(stdout): # GIVEN a logger configuration with format_keys set to ["message"] - logger = Logger(stream=stdout, format_keys=["message"]) + logger = Logger(stream=stdout, log_record_order=["message"]) # WHEN logging a message logger.info("Message") @@ -145,21 +145,23 @@ def test_log_dict_key_custom_seq(stdout): def test_log_custom_formatting(stdout): - # GIVEN a logger where we have a custom location format - logger = Logger(stream=stdout, location="[%(funcName)s] %(module)s") + # GIVEN a logger where we have a custom `location`, 'datefmt' format + logger = Logger(stream=stdout, location="[%(funcName)s] %(module)s", datefmt="fake-datefmt") # WHEN logging a message logger.info("foo") log_dict: dict = json.loads(stdout.getvalue()) - # THEN the `location` match the formatting + # THEN the `location` and "timestamp" should match the formatting assert log_dict["location"] == "[test_log_custom_formatting] test_aws_lambda_logging" + assert log_dict["timestamp"] == "fake-datefmt" def test_log_dict_key_strip_nones(stdout): # GIVEN a logger confirmation where we set `location` and `timestamp` to None - logger = Logger(stream=stdout, location=None, timestamp=None) + # Note: level, sampling_rate and service can not be suppressed + logger = Logger(stream=stdout, level=None, location=None, timestamp=None, sampling_rate=None, service=None) # WHEN logging a message logger.info("foo") From 42f6b22e9a350db09ddb6e952810e870a3b330dc Mon Sep 17 00:00:00 2001 From: Michael Brewer Date: Thu, 27 Aug 2020 22:53:26 -0700 Subject: [PATCH 6/6] chore: doc typo --- 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 f865c616a6e..bc7923d27eb 100644 --- a/aws_lambda_powertools/logging/formatter.py +++ b/aws_lambda_powertools/logging/formatter.py @@ -30,7 +30,7 @@ def __init__(self, **kwargs): self.default_json_formatter = kwargs.pop("json_default", str) # Set the insertion order for the log messages self.format_dict = dict.fromkeys(kwargs.pop("log_record_order", ["level", "location", "message", "timestamp"])) - # Set timestamp the date format + # Set the date format used by `asctime` super(JsonFormatter, self).__init__(datefmt=kwargs.pop("datefmt", None)) self.reserved_keys = ["timestamp", "level", "location"]