Merge pull request cloudtools#532 from remind101/simple-logging

Simplified logging

CHANGELOG.md

@@ -3,6 +3,8 @@
 - assertRenderedBlueprint always dumps current results [GH-528]
 - stacker now builds a DAG internally [GH-523]
 - an unecessary DescribeStacks network call was removed [GH-529]
+- logging output has been simplified and no longer uses ANSI escape sequences to clear the screen [GH-532]
+- logging output is now colorized in `--interactive` mode if the terminal has a TTY [GH-532]
 
 ## 1.1.4 (2018-01-26)
 

scripts/stacker

@@ -1,9 +1,10 @@
 #!/usr/bin/env python
 
+from stacker.logger import setup_logging
 from stacker.commands import Stacker
 
 if __name__ == "__main__":
-    stacker = Stacker()
+    stacker = Stacker(setup_logging=setup_logging)
     args = stacker.parse_args()
     stacker.configure(args)
     args.run(args)

setup.py

@@ -10,7 +10,6 @@
     "boto3>=1.3.1,<1.5.0",
     "PyYAML~=3.12",
     "awacs>=0.6.0",
-    "colorama~=0.3.7",
     "formic~=0.9b",
     "gitpython~=2.0",
     "schematics~=2.0.1",

stacker/actions/base.py

@@ -35,17 +35,12 @@ def plan(description, action, stacks,
         Step(stack, fn=action, watch_func=tail)
         for stack in stacks]
 
-    plan = build_plan(
+    return build_plan(
         description=description,
         steps=steps,
         targets=targets,
         reverse=reverse)
 
-    for step in steps:
-        step.status_changed_func = plan._check_point
-
-    return plan
-
 
 def stack_template_key_name(blueprint):
     """Given a blueprint, produce an appropriate key name.

stacker/commands/stacker/__init__.py

@@ -41,7 +41,6 @@ def configure(self, options, **kwargs):
         options.context = Context(
             environment=options.environment,
             config=config,
-            logger_type=self.logger_type,
             # Allow subcommands to provide any specific kwargs to the Context
             # that it wants.
             **options.get_context_kwargs(options)

stacker/commands/stacker/base.py

@@ -3,10 +3,6 @@
 import logging
 
 from ...environment import parse_environment
-from ...logger import (
-    BASIC_LOGGER_TYPE,
-    setup_logging,
-)
 
 
 class KeyValueAction(argparse.Action):
@@ -61,9 +57,9 @@ class BaseCommand(object):
     description = None
     subcommands = tuple()
     subcommands_help = None
-    logger_type = BASIC_LOGGER_TYPE
 
-    def __init__(self, *args, **kwargs):
+    def __init__(self, setup_logging=None, *args, **kwargs):
+        self.setup_logging = setup_logging
         if not self.name:
             raise ValueError("Subcommands must set \"name\": %s" % (self,))
 
@@ -99,11 +95,8 @@ def run(self, options, **kwargs):
         pass
 
     def configure(self, options, **kwargs):
-        self.logger_type = setup_logging(
-            options.verbose,
-            interactive=options.interactive,
-            tail=getattr(options, "tail", False)
-        )
+        if self.setup_logging:
+            self.setup_logging(options.verbose)
 
     def get_context_kwargs(self, options, **kwargs):
         """Return a dictionary of kwargs that will be used with the Context.

stacker/context.py

@@ -45,11 +45,9 @@ class Context(object):
     def __init__(self, environment=None,
                  stack_names=None,
                  config=None,
-                 logger_type=None,
                  force_stacks=None):
         self.environment = environment
         self.stack_names = stack_names or []
-        self.logger_type = logger_type
         self.config = config or Config()
         self.force_stacks = force_stacks or []
         self.hook_data = {}

stacker/logger/__init__.py

@@ -1,46 +1,36 @@
 import sys
 import logging
 
-from .handler import LogLoopStreamHandler
-from .formatter import ColorFormatter
-
 DEBUG_FORMAT = ("[%(asctime)s] %(levelname)s %(name)s:%(lineno)d"
                 "(%(funcName)s): %(message)s")
 INFO_FORMAT = ("[%(asctime)s] %(message)s")
-COLOR_FORMAT = ("[%(asctime)s] %(color)s%(message)s")
+COLOR_FORMAT = ("[%(asctime)s] \033[%(color)sm%(message)s\033[39m")
 
 ISO_8601 = "%Y-%m-%dT%H:%M:%S"
 
-BASIC_LOGGER_TYPE = 0
-LOOP_LOGGER_TYPE = 1
+
+class ColorFormatter(logging.Formatter):
+    """ Handles colorizing formatted log messages if color provided. """
+    def format(self, record):
+        if 'color' not in record.__dict__:
+            record.__dict__['color'] = 37
+        msg = super(ColorFormatter, self).format(record)
+        return msg
 
 
-def setup_logging(verbosity, interactive=False, tail=False):
-    enable_loop_logger = (
-        verbosity == 0 and
-        sys.stdout.isatty() and
-        not (interactive or tail)
-    )
+def setup_logging(verbosity):
     log_level = logging.INFO
     log_format = INFO_FORMAT
+    if sys.stdout.isatty():
+        log_format = COLOR_FORMAT
+
     if verbosity > 0:
         log_level = logging.DEBUG
         log_format = DEBUG_FORMAT
     if verbosity < 2:
         logging.getLogger("botocore").setLevel(logging.CRITICAL)
 
-    log_type = BASIC_LOGGER_TYPE
-    if enable_loop_logger:
-        log_type = LOOP_LOGGER_TYPE
-        fmt = ColorFormatter(COLOR_FORMAT, ISO_8601)
-        hdlr = LogLoopStreamHandler()
-        hdlr.setFormatter(fmt)
-        logging.root.addHandler(hdlr)
-        logging.root.setLevel(log_level)
-    else:
-        logging.basicConfig(
-            format=log_format,
-            datefmt=ISO_8601,
-            level=log_level,
-        )
-    return log_type
+    hdlr = logging.StreamHandler()
+    hdlr.setFormatter(ColorFormatter(log_format, ISO_8601))
+    logging.root.addHandler(hdlr)
+    logging.root.setLevel(log_level)

stacker/plan.py

@@ -4,8 +4,6 @@
 import uuid
 import multiprocessing
 
-from colorama.ansi import Fore
-
 from .util import stack_template_key_name
 from .exceptions import (
     CancelExecution,
@@ -24,6 +22,19 @@
 
 logger = logging.getLogger(__name__)
 
+COLOR_CODES = {
+    SUBMITTED.code: 33,  # yellow
+    COMPLETE.code: 32,   # green
+}
+
+
+def log_step(step):
+    msg = "%s: %s" % (step.name, step.status.name)
+    if step.status.reason:
+        msg += " (%s)" % (step.status.reason)
+    color_code = COLOR_CODES.get(step.status.code, 37)
+    logger.info(msg, extra={"color": color_code})
+
 
 class Step(object):
     """State machine for executing generic actions related to stacks.
@@ -34,18 +45,14 @@ class Step(object):
             be ran multiple times until the step is "done".
         watch_func (func): an optional function that will be called to "tail"
             the step action.
-        status_changed_func (func): an optional function that will be called
-            when the step changes status.
     """
 
-    def __init__(self, stack, fn, watch_func=None,
-                 status_changed_func=None):
+    def __init__(self, stack, fn, watch_func=None):
         self.stack = stack
         self.status = PENDING
         self.last_updated = time.time()
         self.fn = fn
         self.watch_func = watch_func
-        self.status_changed_func = status_changed_func
 
     def __repr__(self):
         return "<stacker.plan.Step:%s>" % (self.stack.fqn,)
@@ -64,9 +71,6 @@ def run(self):
             watcher.start()
 
         try:
-            if self.status_changed_func:
-                self.status_changed_func()
-
             while not self.done:
                 self._run_once()
         finally:
@@ -137,8 +141,7 @@ def set_status(self, status):
                          status.name)
             self.status = status
             self.last_updated = time.time()
-            if self.status_changed_func:
-                self.status_changed_func()
+            log_step(self)
 
     def complete(self):
         """A shortcut for set_status(COMPLETE)"""
@@ -355,37 +358,6 @@ def walk_func(step):
 
         return self.graph.walk(walk_func)
 
-    def _check_point(self):
-        """Outputs the current status of all steps in the plan."""
-        status_to_color = {
-            SUBMITTED.code: Fore.YELLOW,
-            COMPLETE.code: Fore.GREEN,
-        }
-        logger.info("Plan Status:", extra={"reset": True, "loop": self.id})
-
-        longest = 0
-        messages = []
-        for step in self.steps:
-            length = len(step.name)
-            if length > longest:
-                longest = length
-
-            msg = "%s: %s" % (step.name, step.status.name)
-            if step.status.reason:
-                msg += " (%s)" % (step.status.reason)
-
-            messages.append((msg, step))
-
-        for msg, step in messages:
-            parts = msg.split(' ', 1)
-            fmt = "\t{0: <%d}{1}" % (longest + 2,)
-            color = status_to_color.get(step.status.code, Fore.WHITE)
-            logger.info(fmt.format(*parts), extra={
-                'loop': self.id,
-                'color': color,
-                'last_updated': step.last_updated,
-            })
-
     @property
     def steps(self):
         steps = self.graph.topological_sort()