Improve progress reporting

12 files changed, 72 insertions, 38 deletions

diff --git a/vmdb/__init__.py b/vmdb/__init__.py
index e0d06b2..7fc079d 100644
--- a/vmdb/__init__.py
+++ b/vmdb/__init__.py
@@ -24,5 +24,5 @@ from .step_list import (
     NoMatchingRunner,
     StepError,
 )
-from .runcmd import runcmd
+from .runcmd import runcmd, set_runcmd_progress, progress
 from .app import Vmdb2
diff --git a/vmdb/app.py b/vmdb/app.py
index 0633825..943165a 100644
--- a/vmdb/app.py
+++ b/vmdb/app.py
@@ -21,7 +21,7 @@ import sys
 
 import cliapp
 import jinja2
-
+import ttystatus
 import yaml
 
 import vmdb
@@ -35,10 +35,16 @@ class Vmdb2(cliapp.Application):
             'create image file FILE',
             metavar='FILE')
 
+        self.settings.boolean(
+            ['verbose', 'v'],
+            'verbose output')
+
     def setup(self):
         self.step_runners = vmdb.StepRunnerList()
 
     def process_args(self, args):
+        self.progress = self.create_progress()
+
         spec = self.load_spec_file(args[0])
 
         steps = spec['steps']
@@ -48,15 +54,29 @@ class Vmdb2(cliapp.Application):
 
         state = vmdb.State()
         steps_taken, core_meltdown = self.run_steps(steps, state)
+        self.progress.clear()
+        self.progress = self.create_progress()
+        if core_meltdown:
+            vmdb.progress('Something went wrong, cleaning up!')
+        else:
+            vmdb.progress('All went find, cleaning up.')
         self.run_teardowns(steps_taken, state)
 
+        self.progress.finish()
+
         if core_meltdown:
             logging.error('An error occurred, exiting with non-zero exit code')
             sys.exit(1)
 
+    def create_progress(self):
+        progress = ttystatus.TerminalStatus(period=0)
+        progress.format(
+            '%ElapsedTime() Step %Index(step,steps): %String(current)')
+        vmdb.set_runcmd_progress(progress, self.settings['verbose'])
+        return progress
+
     def load_spec_file(self, filename):
-        sys.stdout.write('Load spec file {}\n'.format(filename))
-        logging.info('Load spec file %s', filename)
+        vmdb.progress('Load spec file {}\n'.format(filename))
         with open(filename) as f:
             return yaml.safe_load(f)
 
@@ -66,12 +86,13 @@ class Vmdb2(cliapp.Application):
 
     def run_teardowns(self, steps, state):
         return self.run_steps_helper(
-            reversed(steps), state, 'Running teardown: %r', 'teardown', True)
+            list(reversed(steps)), state, 'Running teardown: %r', 'teardown', True)
 
     def run_steps_helper(self, steps, state, msg, method_name, keep_going):
         core_meltdown = False
         steps_taken = []
 
+        self.progress['steps'] = steps
         for step in steps:
             try:
                 logging.info(msg, step)
@@ -79,16 +100,21 @@ class Vmdb2(cliapp.Application):
                 expanded_step = self.expand_step_spec(step, state)
                 runner = self.step_runners.find(step)
                 method = getattr(runner, method_name)
+                self.progress['step'] = step
+                self.progress['curstep'] = self.format_step(runner, step)
                 method(expanded_step, self.settings, state)
             except Exception as e:
                 logging.error('ERROR: %s', str(e), exc_info=True)
-                sys.stderr.write('ERROR: {}\n'.format(str(e)))
+                self.progress.error('ERROR: {}\n'.format(str(e)))
                 core_meltdown = True
                 if not keep_going:
                     break
 
         return steps_taken, core_meltdown
 
+    def format_step(self, runner, step):
+        return str(step)
+
     def expand_step_spec(self, step, state):
         expanded = {}
         for key in step:
diff --git a/vmdb/plugins/chroot_plugin.py b/vmdb/plugins/chroot_plugin.py
index a1a3a51..cf61d9b 100644
--- a/vmdb/plugins/chroot_plugin.py
+++ b/vmdb/plugins/chroot_plugin.py
@@ -44,11 +44,9 @@ class ChrootStepRunner(vmdb.StepRunnerInterface):
 
         mount_point = state.mounts[fs_tag]
 
-        sys.stdout.write(
+        vmdb.progress(
             'chroot {} to {}\n'.format(mount_point, ' '.join(shell.split('\n'))))
-        vmdb.runcmd(
-            ['chroot', mount_point, 'sh', '-c', shell],
-            stdout=None, stderr=None)
+        vmdb.runcmd(['chroot', mount_point, 'sh', '-c', shell])
         
 
 class ShellStepRunner(vmdb.StepRunnerInterface):
@@ -60,10 +58,8 @@ class ShellStepRunner(vmdb.StepRunnerInterface):
         shell = step['shell']
         fs_tag = step['root-fs']
 
-        sys.stdout.write(
+        vmdb.progress(
             'run shell {}\n'.format(' '.join(shell.split('\n'))))
         env = dict(os.environ)
         env['ROOT'] = state.mounts[fs_tag]
-        vmdb.runcmd(
-            ['sh', '-c', shell],
-            stdout=None, stderr=None, env=env)
+        vmdb.runcmd(['sh', '-c', shell], env=env)
diff --git a/vmdb/plugins/debootstrap_plugin.py b/vmdb/plugins/debootstrap_plugin.py
index 5a1100b..f67f74c 100644
--- a/vmdb/plugins/debootstrap_plugin.py
+++ b/vmdb/plugins/debootstrap_plugin.py
@@ -43,6 +43,6 @@ class DebootstrapStepRunner(vmdb.StepRunnerInterface):
         mirror = step['mirror']
         if not (suite and tag and target and mirror):
             raise Exception('missing arg for debootstrap step')
-        sys.stdout.write(
+        vmdb.progress(
             'Debootstrap {} {} {}\n'.format(suite, target, mirror))
-        vmdb.runcmd(['debootstrap', suite, target, mirror], stdout=None, stderr=None)
+        vmdb.runcmd(['echo', 'debootstrap', suite, target, mirror])
diff --git a/vmdb/plugins/echo_plugin.py b/vmdb/plugins/echo_plugin.py
index b3eb4d4..faa6b2d 100644
--- a/vmdb/plugins/echo_plugin.py
+++ b/vmdb/plugins/echo_plugin.py
@@ -38,10 +38,10 @@ class EchoStepRunner(vmdb.StepRunnerInterface):
 
     def run(self, step, settings, state):
         text = step['echo']
-        sys.stdout.write('{}\n'.format(text))
+        vmdb.progress('{}\n'.format(text))
 
     def teardown(self, step, settings, state):
         if 'teardown' in step:
             text = step['teardown']
-            sys.stdout.write('{}\n'.format(text))
+            vmdb.progress('{}\n'.format(text))
             logging.info('%s', text)
diff --git a/vmdb/plugins/error_plugin.py b/vmdb/plugins/error_plugin.py
index b417cc9..cc26579 100644
--- a/vmdb/plugins/error_plugin.py
+++ b/vmdb/plugins/error_plugin.py
@@ -37,10 +37,10 @@ class ErrorStepRunner(vmdb.StepRunnerInterface):
         return ['error', 'teardown']
 
     def run(self, step, settings, state):
-        sys.stdout.write('ERROR: {}\n'.format(step['error']))
+        vmdb.progress('ERROR: {}\n'.format(step['error']))
         logging.error('%s', step['error'])
         raise vmdb.StepError('an error occurred')
 
     def teardown(self, step, settings, state):
-        sys.stdout.write('ERROR: {}\n'.format(step['teardown']))
+        vmdb.progress('ERROR: {}\n'.format(step['teardown']))
         logging.error('error cleanup: %s', step['teardown'])
diff --git a/vmdb/plugins/kernel_plugin.py b/vmdb/plugins/kernel_plugin.py
index 249a3b0..5756cfd 100644
--- a/vmdb/plugins/kernel_plugin.py
+++ b/vmdb/plugins/kernel_plugin.py
@@ -40,10 +40,10 @@ class KernelStepRunner(vmdb.StepRunnerInterface):
         package = step['kernel']
         fstag = step['fs-tag']
         mount_point = state.mounts[fstag]
-        sys.stdout.write(
+        vmdb.progress(
             'Install {} to filesystem at {} ({})\n'.format(
                 package, mount_point, fstag))
         vmdb.runcmd(
-            ['chroot', mount_point, 'apt', '-y', 'install', package],
-            stdout=None, stderr=None)
+            ['echo', 'chroot', mount_point,
+             'apt-get', '-y', '--no-show-progress', 'install', package])
 
diff --git a/vmdb/plugins/mkfs_plugin.py b/vmdb/plugins/mkfs_plugin.py
index 770d258..0a2a754 100644
--- a/vmdb/plugins/mkfs_plugin.py
+++ b/vmdb/plugins/mkfs_plugin.py
@@ -40,6 +40,6 @@ class MkfsStepRunner(vmdb.StepRunnerInterface):
         fstype = step['mkfs']
         part_tag = step['partition']
         device = state.parts[part_tag]
-        sys.stdout.write(
+        vmdb.progress(
             'Creating {} filesystem on {}\n'.format(fstype, device))
         vmdb.runcmd(['/sbin/mkfs', '-t', fstype, device])
diff --git a/vmdb/plugins/mkimg_plugin.py b/vmdb/plugins/mkimg_plugin.py
index 27e6262..2f81151 100644
--- a/vmdb/plugins/mkimg_plugin.py
+++ b/vmdb/plugins/mkimg_plugin.py
@@ -43,7 +43,6 @@ class MkimgStepRunner(vmdb.StepRunnerInterface):
     def run(self, step, settings, state):
         filename = step['mkimg']
         size = step['size']
-        sys.stdout.write(
+        vmdb.progress(
             'Creating image file {} (size {})\n'.format(filename, size))
-        vmdb.runcmd(
-            ['qemu-img', 'create', '-f', 'raw', filename, size])
+        vmdb.runcmd(['qemu-img', 'create', '-f', 'raw', filename, size])
diff --git a/vmdb/plugins/mount_plugin.py b/vmdb/plugins/mount_plugin.py
index 62698cf..6c611ef 100644
--- a/vmdb/plugins/mount_plugin.py
+++ b/vmdb/plugins/mount_plugin.py
@@ -50,7 +50,7 @@ class MountStepRunner(vmdb.StepRunnerInterface):
         device = state.parts[part_tag]
         mount_point = tempfile.mkdtemp()
 
-        sys.stdout.write(
+        vmdb.progress(
             'Mounting {} ({}) on {}\n'.format(device, fs_tag, mount_point))
         vmdb.runcmd(['mount', device, mount_point])
         state.mounts[fs_tag] = mount_point
@@ -61,7 +61,7 @@ class MountStepRunner(vmdb.StepRunnerInterface):
         fs_tag = step['fs-tag']
         mount_point = state.mounts[fs_tag]
         
-        sys.stdout.write(
+        vmdb.progress(
             'Unmounting {} ({}) from {}\n'.format(mount_point, fs_tag, device))
         vmdb.runcmd(['umount', mount_point])
         os.rmdir(mount_point)
diff --git a/vmdb/plugins/partition_plugin.py b/vmdb/plugins/partition_plugin.py
index a76fd39..65e45df 100644
--- a/vmdb/plugins/partition_plugin.py
+++ b/vmdb/plugins/partition_plugin.py
@@ -41,7 +41,7 @@ class MklabelStepRunner(vmdb.StepRunnerInterface):
     def run(self, step, settings, state):
         label_type = step['mklabel']
         device = step['device']
-        sys.stdout.write(
+        vmdb.progress(
             'Creating partition table ({}) on {}\n'.format(label_type, device))
         vmdb.runcmd(['parted', device, 'mklabel', label_type])
         state.parts = {}
@@ -59,7 +59,7 @@ class MkpartStepRunner(vmdb.StepRunnerInterface):
         end = step['end']
         part_tag = step['part-tag']
 
-        sys.stdout.write(
+        vmdb.progress(
             'Creating partition ({}) on {} ({} to {})\n'.format(
                 part_type, device, start, end))
         vmdb.runcmd(['parted', '-s', device, 'mkpart', part_type, start, end])
@@ -80,6 +80,6 @@ class MkpartStepRunner(vmdb.StepRunnerInterface):
 
     def teardown(self, step, settings, state):
         device = step['device']
-        sys.stdout.write(
+        vmdb.progress(
             'Undoing loopback devices for partitions on {}\n'.format(device))
         vmdb.runcmd(['kpartx', '-d', device])
diff --git a/vmdb/runcmd.py b/vmdb/runcmd.py
index 9d8cc87..f3c59cf 100644
--- a/vmdb/runcmd.py
+++ b/vmdb/runcmd.py
@@ -22,7 +22,26 @@ import sys
 import cliapp
 
 
+_progress = None
+_verbose = False
+
+
+def set_runcmd_progress(progress, verbose):
+    global _progress, _verbose
+    _progress = progress
+    _verbose = verbose
+
+
+def progress(msg):
+    logging.error(repr(msg))
+    logging.info(msg)
+    _progress['current'] = msg
+    if _verbose:
+        _progress.notify(msg.rstrip())
+
+
 def runcmd(argv, *argvs, **kwargs):
+    progress('Exec: %r' % (argv,))
     kwargs['stdout_callback'] = _log_stdout
     kwargs['stderr_callback'] = _log_stderr
     return cliapp.runcmd(argv, *argvs, **kwargs)
@@ -30,15 +49,9 @@ def runcmd(argv, *argvs, **kwargs):
 
 def _log_stdout(data):
     logging.debug('STDOUT: %r', data)
-    sys.stdout.write(data)
-    if not data.endswith('\n'):
-        sys.stdout.write('\n')
     return data
 
 
 def _log_stderr(data):
     logging.debug('STDERR: %r', data)
-    sys.stderr.write(data)
-    if not data.endswith('\n'):
-        sys.stderr.write('\n')
     return data