Re-implement checkpoint logging

stacker/__init__.py

@@ -13,8 +13,13 @@ def plan(description=None, action=None,
         Step(stack, fn=action, watch_func=tail)
         for stack in stacks]
 
-    return build_plan(
+    plan = build_plan(
         description=description,
         steps=steps,
         step_names=stack_names,
         reverse=reverse)
+
+    for step in steps:
+        step.status_changed_func = plan._check_point
+
+    return plan

stacker/plan2.py

@@ -4,6 +4,8 @@
 import uuid
 import multiprocessing
 
+from colorama.ansi import Fore
+
 from .actions.base import stack_template_key_name
 from .exceptions import (
     GraphError,
@@ -20,26 +22,21 @@
 logger = logging.getLogger(__name__)
 
 
-def log_status(name, status):
-    msg = "%s: %s" % (name, status.name)
-    if status.reason:
-        msg += " (%s)" % (status.reason)
-    logger.info(msg)
-
-
 class Step(object):
     """State machine for executing generic actions related to stacks.
     Args:
         stack (:class:`stacker.stack.Stack`): the stack associated
             with this step
     """
 
-    def __init__(self, stack, fn=None, watch_func=None):
+    def __init__(self, stack, fn=None, watch_func=None,
+                 status_changed_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,)
@@ -49,8 +46,6 @@ def run(self):
         skipped.
         """
 
-        log_status(self.name, self.status)
-
         watcher = None
         if self.watch_func:
             watcher = multiprocessing.Process(
@@ -60,6 +55,9 @@ def run(self):
             watcher.start()
 
         try:
+            if self.status_changed_func:
+                self.status_changed_func()
+
             while not self.done:
                 status = self.fn(self.stack, status=self.status)
                 self.set_status(status)
@@ -121,9 +119,10 @@ def set_status(self, status):
         if status is not self.status:
             logger.debug("Setting %s state to %s.", self.stack.name,
                          status.name)
-            log_status(self.name, status)
             self.status = status
             self.last_updated = time.time()
+            if self.status_changed_func:
+                self.status_changed_func()
 
     def complete(self):
         """A shortcut for set_status(COMPLETE)"""
@@ -297,6 +296,37 @@ 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()