diff --git a/aws_lambda_powertools/logging/formatter.py b/aws_lambda_powertools/logging/formatter.py index bb0d9865f2c..bc7923d27eb 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): @@ -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) diff --git a/aws_lambda_powertools/logging/logger.py b/aws_lambda_powertools/logging/logger.py index b566ee83a83..55b1b766427 100644 --- a/aws_lambda_powertools/logging/logger.py +++ b/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 diff --git a/tests/functional/test_aws_lambda_logging.py b/tests/functional/test_aws_lambda_logging.py index 86c6124cb1f..b633acca390 100644 --- a/tests/functional/test_aws_lambda_logging.py +++ b/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"] == "" 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"]