Merge branch 'develop' into issue/242

* develop:
  chore: move env names to constant file (#264)
  docs: fix import (#267)
  feat: Add AppConfig parameter provider (#236)
  chore: update stale bot
  improv: override Tracer auto-capture response/exception via env vars (#259)
  docs: add info about extras layer (#260)
  feat: support extra parameter in Logger messages (#257)
  chore: general simplifications and cleanup (#255)

Author: heitorlessa

.github/stale.yml

@@ -1,12 +1,9 @@
 only: issues
-daysUntilStale: 30
+daysUntilStale: 14
 daysUntilClose: 7
 exemptLabels:
   - bug
-  - documentation
-  - enhancement
   - feature-request
-  - RFC
 staleLabel: pending-close-response-required
 markComment: >
   This issue has been automatically marked as stale because it has not had

aws_lambda_powertools/logging/filters.py

@@ -13,4 +13,4 @@ def filter(self, record):  # noqa: A003
         created by loggers who don't have a handler.
         """
         logger = record.name
-        return False if self.logger in logger else True
+        return self.logger not in logger

aws_lambda_powertools/logging/formatter.py

@@ -1,6 +1,33 @@
 import json
 import logging
 import os
+from typing import Dict, Iterable, Optional, Union
+
+from ..shared import constants
+
+STD_LOGGING_KEYS = (
+    "name",
+    "msg",
+    "args",
+    "levelname",
+    "levelno",
+    "pathname",
+    "filename",
+    "module",
+    "exc_info",
+    "exc_text",
+    "stack_info",
+    "lineno",
+    "funcName",
+    "created",
+    "msecs",
+    "relativeCreated",
+    "thread",
+    "threadName",
+    "processName",
+    "process",
+    "asctime",
+)
 
 
 class JsonFormatter(logging.Formatter):
@@ -30,12 +57,12 @@ def __init__(self, **kwargs):
         # 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"]))
+        self.log_format = dict.fromkeys(kwargs.pop("log_record_order", ["level", "location", "message", "timestamp"]))
         self.reserved_keys = ["timestamp", "level", "location"]
         # Set the date format used by `asctime`
         super(JsonFormatter, self).__init__(datefmt=kwargs.pop("datefmt", None))
 
-        self.format_dict.update(self._build_root_keys(**kwargs))
+        self.log_format.update(self._build_root_keys(**kwargs))
 
     @staticmethod
     def _build_root_keys(**kwargs):
@@ -48,53 +75,99 @@ def _build_root_keys(**kwargs):
 
     @staticmethod
     def _get_latest_trace_id():
-        xray_trace_id = os.getenv("_X_AMZN_TRACE_ID")
-        trace_id = xray_trace_id.split(";")[0].replace("Root=", "") if xray_trace_id else None
-
-        return trace_id
+        xray_trace_id = os.getenv(constants.XRAY_TRACE_ID_ENV)
+        return xray_trace_id.split(";")[0].replace("Root=", "") if xray_trace_id else None
 
     def update_formatter(self, **kwargs):
-        self.format_dict.update(kwargs)
+        self.log_format.update(kwargs)
 
-    def format(self, record):  # noqa: A003
-        record_dict = record.__dict__.copy()
-        record_dict["asctime"] = self.formatTime(record, self.datefmt)
+    @staticmethod
+    def _extract_log_message(log_record: logging.LogRecord) -> Union[Dict, str, bool, Iterable]:
+        """Extract message from log record and attempt to JSON decode it
+
+        Parameters
+        ----------
+        log_record : logging.LogRecord
+            Log record to extract message from
+
+        Returns
+        -------
+        message: Union[Dict, str, bool, Iterable]
+            Extracted message
+        """
+        if isinstance(log_record.msg, dict):
+            return log_record.msg
 
-        log_dict = {}
+        message: str = log_record.getMessage()
 
-        for key, value in self.format_dict.items():
-            if value and key in self.reserved_keys:
-                # converts default logging expr to its record value
-                # e.g. '%(asctime)s' to '2020-04-24 09:35:40,698'
-                log_dict[key] = value % record_dict
-            else:
-                log_dict[key] = value
+        # Attempt to decode non-str messages e.g. msg = '{"x": "y"}'
+        try:
+            message = json.loads(log_record.msg)
+        except (json.decoder.JSONDecodeError, TypeError, ValueError):
+            pass
+
+        return message
+
+    def _extract_log_exception(self, log_record: logging.LogRecord) -> Optional[str]:
+        """Format traceback information, if available
 
-        if isinstance(record_dict["msg"], dict):
-            log_dict["message"] = record_dict["msg"]
-        else:
-            log_dict["message"] = record.getMessage()
+        Parameters
+        ----------
+        log_record : logging.LogRecord
+            Log record to extract message from
+
+        Returns
+        -------
+        log_record: Optional[str]
+            Log record with constant traceback info
+        """
+        if log_record.exc_info:
+            return self.formatException(log_record.exc_info)
 
-            # Attempt to decode the message as JSON, if so, merge it with the
-            # overall message for clarity.
-            try:
-                log_dict["message"] = json.loads(log_dict["message"])
-            except (json.decoder.JSONDecodeError, TypeError, ValueError):
-                pass
+        return None
 
-        if record.exc_info and not record.exc_text:
-            # Cache the traceback text to avoid converting it multiple times
-            # (it's constant anyway)
-            # from logging.Formatter:format
-            record.exc_text = self.formatException(record.exc_info)
+    def _extract_log_keys(self, log_record: logging.LogRecord) -> Dict:
+        """Extract and parse custom and reserved log keys
 
-        if record.exc_text:
-            log_dict["exception"] = record.exc_text
+        Parameters
+        ----------
+        log_record : logging.LogRecord
+            Log record to extract keys from
 
-        # fetch latest X-Ray Trace ID, if any
-        log_dict.update({"xray_trace_id": self._get_latest_trace_id()})
+        Returns
+        -------
+        formatted_log: Dict
+            Structured log as dictionary
+        """
+        record_dict = log_record.__dict__.copy()  # has extra kwargs we are after
+        record_dict["asctime"] = self.formatTime(log_record, self.datefmt)
+
+        formatted_log = {}
+
+        # We have to iterate over a default or existing log structure
+        # then replace any logging expression for reserved keys e.g. '%(level)s' to 'INFO'
+        # and lastly add or replace incoming keys (those added within the constructor or .structure_logs method)
+        for key, value in self.log_format.items():
+            if value and key in self.reserved_keys:
+                formatted_log[key] = value % record_dict
+            else:
+                formatted_log[key] = value
+
+        # pick up extra keys when logging a new message e.g. log.info("my message", extra={"additional_key": "value"}
+        # these messages will be added to the root of the final structure not within `message` key
+        for key, value in record_dict.items():
+            if key not in STD_LOGGING_KEYS:
+                formatted_log[key] = value
+
+        return formatted_log
+
+    def format(self, record):  # noqa: A003
+        formatted_log = self._extract_log_keys(log_record=record)
+        formatted_log["message"] = self._extract_log_message(log_record=record)
+        formatted_log["exception"] = self._extract_log_exception(log_record=record)
+        formatted_log.update({"xray_trace_id": self._get_latest_trace_id()})  # fetch latest Trace ID, if any
 
         # 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}
+        formatted_log = {k: v for k, v in formatted_log.items() if v is not None}
 
-        return json.dumps(log_dict, default=self.default_json_formatter)
+        return json.dumps(formatted_log, default=self.default_json_formatter)

aws_lambda_powertools/logging/logger.py

@@ -4,9 +4,10 @@
 import os
 import random
 import sys
-from distutils.util import strtobool
 from typing import Any, Callable, Dict, Union
 
+from ..shared import constants
+from ..shared.functions import resolve_env_var_choice, resolve_truthy_env_var_choice
 from .exceptions import InvalidLoggerSamplingRateError
 from .filters import SuppressFilter
 from .formatter import JsonFormatter
@@ -122,8 +123,12 @@ def __init__(
         stream: sys.stdout = None,
         **kwargs,
     ):
-        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.service = resolve_env_var_choice(
+            choice=service, env=os.getenv(constants.SERVICE_NAME_ENV, "service_undefined")
+        )
+        self.sampling_rate = resolve_env_var_choice(
+            choice=sampling_rate, env=os.getenv(constants.LOGGER_LOG_SAMPLING_RATE, 0.0)
+        )
         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)
@@ -193,7 +198,7 @@ def _configure_sampling(self):
                 f"Please review POWERTOOLS_LOGGER_SAMPLE_RATE environment variable."
             )
 
-    def inject_lambda_context(self, lambda_handler: Callable[[Dict, Any], Any] = None, log_event: bool = False):
+    def inject_lambda_context(self, lambda_handler: Callable[[Dict, Any], Any] = None, log_event: bool = None):
         """Decorator to capture Lambda contextual info and inject into logger
 
         Parameters
@@ -242,8 +247,9 @@ def handler(event, context):
             logger.debug("Decorator called with parameters")
             return functools.partial(self.inject_lambda_context, log_event=log_event)
 
-        log_event_env_option = str(os.getenv("POWERTOOLS_LOGGER_LOG_EVENT", "false"))
-        log_event = strtobool(log_event_env_option) or log_event
+        log_event = resolve_truthy_env_var_choice(
+            choice=log_event, env=os.getenv(constants.LOGGER_LOG_EVENT_ENV, "false")
+        )
 
         @functools.wraps(lambda_handler)
         def decorate(event, context):
@@ -291,9 +297,10 @@ def _get_log_level(level: Union[str, int]) -> Union[str, 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
+        if log_level is None:
+            return logging.INFO
 
-        return log_level
+        return log_level.upper()
 
     @staticmethod
     def _get_caller_filename():
@@ -303,9 +310,7 @@ def _get_caller_filename():
         # 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 caller_frame.f_globals["__name__"]
 
 
 def set_package_logger(

aws_lambda_powertools/metrics/base.py

@@ -10,6 +10,8 @@
 
 import fastjsonschema
 
+from ..shared import constants
+from ..shared.functions import resolve_env_var_choice
 from .exceptions import MetricUnitError, MetricValueError, SchemaValidationError
 
 logger = logging.getLogger(__name__)
@@ -88,8 +90,8 @@ def __init__(
     ):
         self.metric_set = metric_set if metric_set is not None else {}
         self.dimension_set = dimension_set if dimension_set is not None else {}
-        self.namespace = namespace or os.getenv("POWERTOOLS_METRICS_NAMESPACE")
-        self.service = service or os.environ.get("POWERTOOLS_SERVICE_NAME")
+        self.namespace = resolve_env_var_choice(choice=namespace, env=os.getenv(constants.METRICS_NAMESPACE_ENV))
+        self.service = resolve_env_var_choice(choice=service, env=os.getenv(constants.SERVICE_NAME_ENV))
         self._metric_units = [unit.value for unit in MetricUnit]
         self._metric_unit_options = list(MetricUnit.__members__)
         self.metadata_set = self.metadata_set if metadata_set is not None else {}
@@ -240,10 +242,7 @@ def add_dimension(self, name: str, value: str):
         # Cast value to str according to EMF spec
         # Majority of values are expected to be string already, so
         # checking before casting improves performance in most cases
-        if isinstance(value, str):
-            self.dimension_set[name] = value
-        else:
-            self.dimension_set[name] = str(value)
+        self.dimension_set[name] = value if isinstance(value, str) else str(value)
 
     def add_metadata(self, key: str, value: Any):
         """Adds high cardinal metadata for metrics object

aws_lambda_powertools/middleware_factory/factory.py

@@ -2,16 +2,17 @@
 import inspect
 import logging
 import os
-from distutils.util import strtobool
 from typing import Callable
 
+from ..shared import constants
+from ..shared.functions import resolve_truthy_env_var_choice
 from ..tracing import Tracer
 from .exceptions import MiddlewareInvalidArgumentError
 
 logger = logging.getLogger(__name__)
 
 
-def lambda_handler_decorator(decorator: Callable = None, trace_execution=False):
+def lambda_handler_decorator(decorator: Callable = None, trace_execution: bool = None):
     """Decorator factory for decorating Lambda handlers.
 
     You can use lambda_handler_decorator to create your own middlewares,
@@ -104,7 +105,9 @@ def lambda_handler(event, context):
     if decorator is None:
         return functools.partial(lambda_handler_decorator, trace_execution=trace_execution)
 
-    trace_execution = trace_execution or strtobool(str(os.getenv("POWERTOOLS_TRACE_MIDDLEWARES", False)))
+    trace_execution = resolve_truthy_env_var_choice(
+        choice=trace_execution, env=os.getenv(constants.MIDDLEWARE_FACTORY_TRACE_ENV, "false")
+    )
 
     @functools.wraps(decorator)
     def final_decorator(func: Callable = None, **kwargs):

aws_lambda_powertools/shared/__init__.py

@@ -0,0 +1,15 @@
+TRACER_CAPTURE_RESPONSE_ENV: str = "POWERTOOLS_TRACER_CAPTURE_RESPONSE"
+TRACER_CAPTURE_ERROR_ENV: str = "POWERTOOLS_TRACER_CAPTURE_ERROR"
+TRACER_DISABLED_ENV: str = "POWERTOOLS_TRACE_DISABLED"
+
+LOGGER_LOG_SAMPLING_RATE: str = "POWERTOOLS_LOGGER_SAMPLE_RATE"
+LOGGER_LOG_EVENT_ENV: str = "POWERTOOLS_LOGGER_LOG_EVENT"
+
+MIDDLEWARE_FACTORY_TRACE_ENV: str = "POWERTOOLS_TRACE_MIDDLEWARES"
+
+METRICS_NAMESPACE_ENV: str = "POWERTOOLS_METRICS_NAMESPACE"
+
+SAM_LOCAL_ENV: str = "AWS_SAM_LOCAL"
+CHALICE_LOCAL_ENV: str = "AWS_CHALICE_CLI_MODE"
+SERVICE_NAME_ENV: str = "POWERTOOLS_SERVICE_NAME"
+XRAY_TRACE_ID_ENV: str = "_X_AMZN_TRACE_ID"

aws_lambda_powertools/shared/constants.py

@@ -0,0 +1,42 @@
+from distutils.util import strtobool
+from typing import Any, Union
+
+
+def resolve_truthy_env_var_choice(env: Any, choice: bool = None) -> bool:
+    """ Pick explicit choice over truthy env value, if available, otherwise return truthy env value
+
+    NOTE: Environment variable should be resolved by the caller.
+
+    Parameters
+    ----------
+    env : Any
+        environment variable actual value
+    choice : bool
+        explicit choice
+
+    Returns
+    -------
+    choice : str
+        resolved choice as either bool or environment value
+    """
+    return choice if choice is not None else strtobool(env)
+
+
+def resolve_env_var_choice(env: Any, choice: bool = None) -> Union[bool, Any]:
+    """ Pick explicit choice over env, if available, otherwise return env value received
+
+    NOTE: Environment variable should be resolved by the caller.
+
+    Parameters
+    ----------
+    env : Any
+        environment variable actual value
+    choice : bool
+        explicit choice
+
+    Returns
+    -------
+    choice : str
+        resolved choice as either bool or environment value
+    """
+    return choice if choice is not None else env