[Resolve #1304] Adding StackLoggerAdapter to hooks, resolvers, and te…

…mplate handlers (#1309)

This converts the loggers for Hooks, Resolvers, and Template Handlers to be LoggerAdapters that prefix all log messages with the Stack name

sceptre/hooks/__init__.py

@@ -3,22 +3,28 @@
 from functools import wraps
 
 from sceptre.helpers import _call_func_on_values
+from sceptre.logging import StackLoggerAdapter
 
+from typing import TYPE_CHECKING, Any
 
-class Hook(object):
+if TYPE_CHECKING:
+    from sceptre.stack import Stack
+
+
+class Hook(abc.ABC):
     """
     Hook is an abstract base class that should be inherited by all hooks.
 
     :param argument: The argument of the hook.
-    :type argument: str
     :param stack: The associated stack of the hook.
-    :type stack: sceptre.stack.Stack
     """
 
-    __metaclass__ = abc.ABCMeta
-
-    def __init__(self, argument=None, stack=None):
+    def __init__(self, argument: Any = None, stack: "Stack" = None):
         self.logger = logging.getLogger(__name__)
+
+        if stack is not None:
+            self.logger = StackLoggerAdapter(self.logger, stack.name)
+
         self.argument = argument
         self.stack = stack
 
@@ -37,6 +43,15 @@ def run(self):
         """
         pass  # pragma: no cover
 
+    def clone(self, stack: "Stack") -> "Hook":
+        """
+        Produces a "fresh" copy of the Hook, with the specified stack.
+
+        :param stack: The stack to set on the cloned resolver
+        """
+        clone = type(self)(self.argument, stack)
+        return clone
+
 
 class HookProperty(object):
     """
@@ -61,16 +76,16 @@ def __get__(self, instance, type):
         """
         return getattr(instance, self.name)
 
-    def __set__(self, instance, value):
+    def __set__(self, instance: "Stack", value):
         """
         Attribute setter which adds a stack reference to any hooks in the
         data structure `value` and calls the setup method.
 
         """
 
-        def setup(attr, key, value):
-            value.stack = instance
-            value.setup()
+        def setup(attr, key, value: Hook):
+            attr[key] = clone = value.clone(instance)
+            clone.setup()
 
         _call_func_on_values(setup, value, Hook)
         setattr(instance, self.name, value)

sceptre/logging.py

@@ -0,0 +1,20 @@
+from logging import LoggerAdapter, Logger
+from typing import MutableMapping, Any, Tuple
+
+
+class StackLoggerAdapter(LoggerAdapter):
+    def __init__(self, logger: Logger, stack_name: str, extra: dict = None):
+        """A small wrapper around a Logger that prefixes log messages with the stack name.
+
+        :param logger: The logger to wrap
+        :param stack_name: The name of the stack to every log message
+        :param extra: Extra kwargs to add to the log context (if any)
+        """
+        super().__init__(logger, extra or {})
+        self.stack_name = stack_name
+
+    def process(
+        self, msg: str, kwargs: MutableMapping[str, Any]
+    ) -> Tuple[Any, MutableMapping[str, Any]]:
+        msg = f"{self.stack_name} - {msg}"
+        return super().process(msg, kwargs)

sceptre/resolvers/__init__.py

@@ -6,6 +6,7 @@
 from typing import Any, TYPE_CHECKING, Type, Union, TypeVar
 
 from sceptre.helpers import _call_func_on_values
+from sceptre.logging import StackLoggerAdapter
 from sceptre.resolvers.placeholders import (
     create_placeholder_value,
     are_placeholders_enabled,
@@ -33,6 +34,9 @@ class Resolver(abc.ABC):
 
     def __init__(self, argument: Any = None, stack: "stack.Stack" = None):
         self.logger = logging.getLogger(__name__)
+        if stack is not None:
+            self.logger = StackLoggerAdapter(self.logger, stack.name)
+
         self.argument = argument
         self.stack = stack
 

sceptre/template.py

@@ -15,6 +15,7 @@
 import sceptre.helpers
 
 from sceptre.exceptions import TemplateHandlerNotFoundError
+from sceptre.logging import StackLoggerAdapter
 
 
 class Template(object):
@@ -54,8 +55,7 @@ def __init__(
         connection_manager=None,
         s3_details=None,
     ):
-        self.logger = logging.getLogger(__name__)
-
+        self.logger = StackLoggerAdapter(logging.getLogger(__name__), name)
         self.name = name
         self.handler_config = handler_config
         if self.handler_config is not None and self.handler_config.get("type") is None:

sceptre/template_handlers/__init__.py

@@ -6,6 +6,7 @@
 from jsonschema import validate, ValidationError
 
 from sceptre.exceptions import TemplateHandlerArgumentsInvalidError
+from sceptre.logging import StackLoggerAdapter
 
 
 @six.add_metaclass(abc.ABCMeta)
@@ -49,7 +50,7 @@ def __init__(
         connection_manager=None,
         stack_group_config=None,
     ):
-        self.logger = logging.getLogger(__name__)
+        self.logger = StackLoggerAdapter(logging.getLogger(__name__), name)
         self.name = name
         self.arguments = arguments
         self.sceptre_user_data = sceptre_user_data

sceptre/template_handlers/s3.py

@@ -92,5 +92,5 @@ def _get_template(self, path):
             )
             return response["Body"].read()
         except Exception as e:
-            self.logger.fatal(e)
+            self.logger.critical(e)
             raise e

tests/test_hooks/test_asg_scaling_processes.py

@@ -14,6 +14,7 @@
 class TestASGScalingProcesses(object):
     def setup_method(self, test_method):
         self.stack = MagicMock(spec=Stack)
+        self.stack.name = "my/stack.yaml"
         self.stack.connection_manager = MagicMock(spec=ConnectionManager)
         self.stack.external_name = "external_name"
         self.asg_scaling_processes = ASGScalingProcesses(None, self.stack)

tests/test_hooks/test_cmd.py

@@ -12,6 +12,7 @@
 class TestCmd(object):
     def setup_method(self, test_method):
         self.stack = Mock(Stack)
+        self.stack.name = "my/stack.yaml"
         self.cmd = Cmd(stack=self.stack)
 
     def test_run_with_non_str_argument(self):

tests/test_hooks/test_hooks.py

@@ -1,7 +1,10 @@
 # -*- coding: utf-8 -*-
-from unittest.mock import MagicMock
+from unittest import TestCase
+from unittest.mock import MagicMock, Mock
 
 from sceptre.hooks import Hook, HookProperty, add_stack_hooks, execute_hooks
+from sceptre.stack import Stack
+import logging
 
 
 class MockHook(Hook):
@@ -60,17 +63,23 @@ def test_execute_hooks_with_multiple_hook(self):
         hook_2.run.called_once_with()
 
 
-class TestHook(object):
-    def setup_method(self, test_method):
-        self.hook = MockHook()
+class TestHook(TestCase):
+    def setUp(self):
+        self.stack = Mock(Stack)
+        self.stack.name = "my/stack"
+        self.hook = MockHook(stack=self.stack)
+
+    def test_logger__logs_have_stack_name_prefix(self):
+        with self.assertLogs(self.hook.logger.name, logging.INFO) as handler:
+            self.hook.logger.info("Bonjour")
 
-    def test_hook_inheritance(self):
-        assert isinstance(self.hook, Hook)
+        assert handler.records[0].message == f"{self.stack.name} - Bonjour"
 
 
 class MockClass(object):
     hook_property = HookProperty("hook_property")
     config = MagicMock()
+    name = "my/stack.yaml"
 
 
 class TestHookPropertyDescriptor(object):
@@ -81,7 +90,7 @@ def test_setting_hook_property(self):
         mock_hook = MagicMock(spec=MockHook)
 
         self.mock_object.hook_property = [mock_hook]
-        assert self.mock_object._hook_property == [mock_hook]
+        assert self.mock_object._hook_property == [mock_hook.clone.return_value]
 
     def test_getting_hook_property(self):
         self.mock_object._hook_property = self.mock_object

tests/test_resolvers/test_resolver.py

@@ -1,4 +1,6 @@
 # -*- coding: utf-8 -*-
+import logging
+from unittest import TestCase
 from unittest.mock import call, Mock
 
 import pytest
@@ -41,9 +43,11 @@ class MockClass(object):
     )
     config = MagicMock()
 
+    name = "my/stack"
 
-class TestResolver(object):
-    def setup_method(self, test_method):
+
+class TestResolver(TestCase):
+    def setUp(self):
         self.mock_resolver = MockResolver(
             argument=sentinel.argument, stack=sentinel.stack
         )
@@ -52,6 +56,12 @@ def test_init(self):
         assert self.mock_resolver.stack == sentinel.stack
         assert self.mock_resolver.argument == sentinel.argument
 
+    def test_logger__logs_have_stack_name_prefix(self):
+        with self.assertLogs(self.mock_resolver.logger.name, logging.INFO) as handler:
+            self.mock_resolver.logger.info("Bonjour")
+
+        assert handler.records[0].message == f"{sentinel.stack.name} - Bonjour"
+
 
 class TestResolvableContainerPropertyDescriptor:
     def setup_method(self, test_method):

tests/test_resolvers/test_stack_attr.py

@@ -10,6 +10,7 @@ class TestResolver(object):
     def setup_method(self, test_method):
         self.stack_group_config = {}
         self.stack = Mock(spec=Stack, stack_group_config=self.stack_group_config)
+        self.stack.name = "my/stack.yaml"
 
         self.resolver = StackAttr(stack=self.stack)
 

tests/test_resolvers/test_stack_output.py

@@ -20,6 +20,7 @@ class TestStackOutputResolver(object):
     @patch("sceptre.resolvers.stack_output.StackOutput._get_output_value")
     def test_resolver(self, mock_get_output_value):
         stack = MagicMock(spec=Stack)
+        stack.name = "my/stack"
         stack.dependencies = []
         stack.project_code = "project-code"
         stack._connection_manager = MagicMock(spec=ConnectionManager)
@@ -52,6 +53,7 @@ def test_resolver(self, mock_get_output_value):
     @patch("sceptre.resolvers.stack_output.StackOutput._get_output_value")
     def test_resolver_with_existing_dependencies(self, mock_get_output_value):
         stack = MagicMock(spec=Stack)
+        stack.name = "my/stack"
         stack.dependencies = ["existing"]
         stack.project_code = "project-code"
         stack._connection_manager = MagicMock(spec=ConnectionManager)
@@ -84,6 +86,7 @@ def test_resolver_with_existing_dependencies(self, mock_get_output_value):
     @patch("sceptre.resolvers.stack_output.StackOutput._get_output_value")
     def test_resolve_with_implicit_stack_reference(self, mock_get_output_value):
         stack = MagicMock(spec=Stack)
+        stack.name = "my/stack"
         stack.dependencies = []
         stack.project_code = "project-code"
         stack.name = "account/dev/stack"
@@ -119,6 +122,7 @@ def test_resolve_with_implicit_stack_reference_top_level(
         self, mock_get_output_value
     ):
         stack = MagicMock(spec=Stack)
+        stack.name = "my/stack"
         stack.dependencies = []
         stack.project_code = "project-code"
         stack.name = "stack"
@@ -154,6 +158,7 @@ class TestStackOutputExternalResolver(object):
     @patch("sceptre.resolvers.stack_output.StackOutputExternal._get_output_value")
     def test_resolve(self, mock_get_output_value):
         stack = MagicMock(spec=Stack)
+        stack.name = "my/stack"
         stack.dependencies = []
         stack._connection_manager = MagicMock(spec=ConnectionManager)
         stack_output_external_resolver = StackOutputExternal(
@@ -169,6 +174,7 @@ def test_resolve(self, mock_get_output_value):
     @patch("sceptre.resolvers.stack_output.StackOutputExternal._get_output_value")
     def test_resolve_with_args(self, mock_get_output_value):
         stack = MagicMock(spec=Stack)
+        stack.name = "my/stack"
         stack.dependencies = []
         stack._connection_manager = MagicMock(spec=ConnectionManager)
         stack_output_external_resolver = StackOutputExternal(
@@ -200,6 +206,7 @@ def resolve(self):
 class TestStackOutputBaseResolver(object):
     def setup_method(self, test_method):
         self.stack = MagicMock(spec=Stack)
+        self.stack.name = "my/stack.yaml"
         self.stack._connection_manager = MagicMock(spec=ConnectionManager)
         self.base_stack_output_resolver = MockStackOutputBase(None, self.stack)
 

tests/test_template_handlers/test_template_handlers.py

@@ -1,3 +1,6 @@
+import logging
+from unittest import TestCase
+
 import pytest
 
 from sceptre.exceptions import TemplateHandlerArgumentsInvalidError
@@ -19,7 +22,7 @@ def handle(self):
         return "TestTemplateHandler"
 
 
-class TestTemplateHandlers(object):
+class TestTemplateHandlers(TestCase):
     def test_template_handler_validates_schema(self):
         handler = MockTemplateHandler(name="mock", arguments={"argument": "test"})
         handler.validate()
@@ -30,3 +33,12 @@ def test_template_handler_errors_when_arguments_invalid(self):
                 name="mock", arguments={"non-existent": "test"}
             )
             handler.validate()
+
+    def test_logger__logs_have_stack_name_prefix(self):
+        template_handler = MockTemplateHandler(
+            name="mock", arguments={"argument": "test"}
+        )
+        with self.assertLogs(template_handler.logger.name, logging.INFO) as handler:
+            template_handler.logger.info("Bonjour")
+
+        assert handler.records[0].message == f"{template_handler.name} - Bonjour"