Merge pull request #140 from gyft/fix-log-key-order

feat(logger): customizing logger output

Author: heitorlessa

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):
@@ -42,19 +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.
         """
-        self.default_json_formatter = kwargs.pop("json_default", json_formatter)
-        datefmt = kwargs.pop("datefmt", None)
+        # Set the default unserializable function, by default values will be cast as str.
+        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 the date format used by `asctime`
+        super(JsonFormatter, self).__init__(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",
-        }
-        self.format_dict.update(kwargs)
+        self.format_dict.update(
+            {"level": "%(levelname)s", "location": "%(funcName)s:%(lineno)d", "timestamp": "%(asctime)s", **kwargs}
+        )
 
     def update_formatter(self, **kwargs):
         self.format_dict.update(kwargs)
@@ -94,4 +76,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)

aws_lambda_powertools/logging/logger.py

@@ -136,16 +136,6 @@ 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
@@ -154,17 +144,6 @@ def _get_logger(self):
 
         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
 
@@ -291,6 +272,29 @@ 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
+
+        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
+
+    @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__"]
+
+        return filename
+
 
 def set_package_logger(
     level: Union[str, int] = logging.DEBUG, stream: sys.stdout = None, formatter: logging.Formatter = None

tests/functional/test_aws_lambda_logging.py

@@ -116,3 +116,57 @@ 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"] == "<non-serializable: Unserializable>"
     assert "json_default" not in log_dict
+
+
+def test_log_dict_key_seq(stdout):
+    # GIVEN the default logger configuration
+    logger = Logger(stream=stdout)
+
+    # WHEN logging a message
+    logger.info("Message")
+
+    log_dict: dict = json.loads(stdout.getvalue())
+
+    # 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 a logger configuration with format_keys set to ["message"]
+    logger = Logger(stream=stdout, log_record_order=["message"])
+
+    # WHEN logging a message
+    logger.info("Message")
+
+    log_dict: dict = json.loads(stdout.getvalue())
+
+    # 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`, '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` 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
+    # 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")
+
+    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"]