feat(logger): backport to py3.7

Author: heitorlessa

aws_lambda_powertools/logging/logger.py

@@ -1,9 +1,11 @@
 import functools
 import inspect
+import io
 import logging
 import os
 import random
 import sys
+import traceback
 from typing import IO, Any, Callable, Dict, Iterable, Mapping, Optional, TypeVar, Union
 
 import jmespath
@@ -235,6 +237,9 @@ def _init_logger(self, **kwargs):
         self._logger.addHandler(self.logger_handler)
         self.structure_logs(**kwargs)
 
+        # Maintenance: We can drop this upon Py3.7 EOL. It's a backport for "location" key to work
+        self._logger.findCaller = self.findCaller
+
         # Pytest Live Log feature duplicates log records for colored output
         # but we explicitly add a filter for log deduplication.
         # This flag disables this protection when you explicit want logs to be duplicated (#262)
@@ -369,9 +374,10 @@ def info(
         extra: Optional[Mapping[str, object]] = None,
         **kwargs,
     ):
-        # NOTE: We need to solve stack frame location for Python <3.8
         extra = extra or {}
         extra = {**extra, **kwargs}
+
+        # Maintenance: We can drop this upon Py3.7 EOL. It's a backport for "location" key to work
         if sys.version_info < (3, 8):
             return self._logger.info(msg, *args, exc_info=exc_info, stack_info=stack_info, extra=extra)
         return self._logger.info(
@@ -388,9 +394,10 @@ def error(
         extra: Optional[Mapping[str, object]] = None,
         **kwargs,
     ):
-        # NOTE: We need to solve stack frame location for Python <3.8
         extra = extra or {}
         extra = {**extra, **kwargs}
+
+        # Maintenance: We can drop this upon Py3.7 EOL. It's a backport for "location" key to work
         if sys.version_info < (3, 8):
             return self._logger.error(msg, *args, exc_info=exc_info, stack_info=stack_info, extra=extra)
         return self._logger.error(
@@ -407,9 +414,10 @@ def exception(
         extra: Optional[Mapping[str, object]] = None,
         **kwargs,
     ):
-        # NOTE: We need to solve stack frame location for Python <3.8
         extra = extra or {}
         extra = {**extra, **kwargs}
+
+        # Maintenance: We can drop this upon Py3.7 EOL. It's a backport for "location" key to work
         if sys.version_info < (3, 8):
             return self._logger.exception(msg, *args, exc_info=exc_info, stack_info=stack_info, extra=extra)
         return self._logger.exception(
@@ -426,9 +434,10 @@ def critical(
         extra: Optional[Mapping[str, object]] = None,
         **kwargs,
     ):
-        # NOTE: We need to solve stack frame location for Python <3.8
         extra = extra or {}
         extra = {**extra, **kwargs}
+
+        # Maintenance: We can drop this upon Py3.7 EOL. It's a backport for "location" key to work
         if sys.version_info < (3, 8):
             return self._logger.critical(msg, *args, exc_info=exc_info, stack_info=stack_info, extra=extra)
         return self._logger.critical(
@@ -445,9 +454,10 @@ def warning(
         extra: Optional[Mapping[str, object]] = None,
         **kwargs,
     ):
-        # NOTE: We need to solve stack frame location for Python <3.8
         extra = extra or {}
         extra = {**extra, **kwargs}
+
+        # Maintenance: We can drop this upon Py3.7 EOL. It's a backport for "location" key to work
         if sys.version_info < (3, 8):
             return self._logger.warning(msg, *args, exc_info=exc_info, stack_info=stack_info, extra=extra)
         return self._logger.warning(
@@ -557,6 +567,41 @@ def _get_caller_filename():
         caller_frame = frame.f_back.f_back.f_back
         return caller_frame.f_globals["__name__"]
 
+    # Maintenance: We can drop this upon Py3.7 EOL. It's a backport for "location" key to work
+    def findCaller(self, stack_info=False, stacklevel=2):  # pragma: no cover
+        """
+        Find the stack frame of the caller so that we can note the source
+        file name, line number and function name.
+        """
+        f = logging.currentframe()  # noqa: VNE001
+        # On some versions of IronPython, currentframe() returns None if
+        # IronPython isn't run with -X:Frames.
+        if f is None:
+            return "(unknown file)", 0, "(unknown function)", None
+        while stacklevel > 0:
+            next_f = f.f_back
+            if next_f is None:
+                ## We've got options here.
+                ## If we want to use the last (deepest) frame:
+                break
+                ## If we want to mimic the warnings module:
+                # return ("sys", 1, "(unknown function)", None) # noqa: E800
+                ## If we want to be pedantic:  # noqa: E800
+                # raise ValueError("call stack is not deep enough") # noqa: E800
+            f = next_f  # noqa: VNE001
+            if not _is_internal_frame(f):
+                stacklevel -= 1
+        co = f.f_code
+        sinfo = None
+        if stack_info:
+            with io.StringIO() as sio:
+                sio.write("Stack (most recent call last):\n")
+                traceback.print_stack(f, file=sio)
+                sinfo = sio.getvalue()
+                if sinfo[-1] == "\n":
+                    sinfo = sinfo[:-1]
+        return co.co_filename, f.f_lineno, co.co_name, sinfo
+
 
 def set_package_logger(
     level: Union[str, int] = logging.DEBUG,
@@ -595,3 +640,13 @@ def set_package_logger(
     handler = logging.StreamHandler(stream)
     handler.setFormatter(formatter)
     logger.addHandler(handler)
+
+
+# Maintenance: We can drop this upon Py3.7 EOL. It's a backport for "location" key to work
+# The following is based on warnings._is_internal_frame. It makes sure that
+# frames of the import mechanism are skipped when logging at module level and
+# using a stacklevel value greater than one.
+def _is_internal_frame(frame):  # pragma: no cover
+    """Signal whether the frame is a CPython or logging module internal."""
+    filename = os.path.normcase(frame.f_code.co_filename)
+    return filename == logging._srcfile or ("importlib" in filename and "_bootstrap" in filename)

tests/functional/test_logger.py

@@ -415,14 +415,14 @@ def test_logger_extra_kwargs(stdout, service_name):
     assert "request_id" not in no_extra_fields_log
 
 
-def test_logger_kwargs_no_extra(stdout, service_name):
+def test_logger_arbitrary_fields_as_kwargs(stdout, service_name):
     # GIVEN Logger is initialized
     logger = Logger(service=service_name, stream=stdout)
 
-    # WHEN `request_id` is an extra field in a log message to the existing structured log
+    # WHEN `request_id` is an arbitrary field in a log message to the existing structured log
     fields = {"request_id": "blah"}
 
-    logger.info("with extra fields", **fields)
+    logger.info("with arbitrary fields", **fields)
     logger.info("without extra fields")
 
     extra_fields_log, no_extra_fields_log = capture_multiple_logging_statements_output(stdout)