Replace Morph.msg with Morph.status

The new method takes a list of keyword arguments. This is more useful
than the old way of giving just a string, since now the presentation
layer may transmogrify the status update. For example, it can usefully
translate the message to another language.

Add --verbose option to allow more control over what the user sees.

2 files changed, 134 insertions, 55 deletions

diff --git a/morphlib/app.py b/morphlib/app.py
index bcacbea1..3f0d8ac9 100755
--- a/morphlib/app.py
+++ b/morphlib/app.py
@@ -1,5 +1,3 @@
-#!/usr/bin/python
-#
 # Copyright (C) 2011-2012  Codethink Limited
 # 
 # This program is free software; you can redistribute it and/or modify
@@ -24,6 +22,7 @@ import logging
 import os
 import shutil
 import tempfile
+import time
 
 import morphlib
 
@@ -58,7 +57,10 @@ class Morph(cliapp.Application):
     system_repo_name = 'baserock:%s' % system_repo_base
 
     def add_settings(self):
-        self.settings.boolean(['verbose', 'v'], 'show what is happening')
+        self.settings.boolean(['verbose', 'v'], 
+                              'show what is happening in much detail')
+        self.settings.boolean(['quiet', 'q'],
+                              'show no output unless there is an error')
         self.settings.string_list(['repo-alias'],
                             'define URL prefix aliases to allow repository '
                                 'addresses to be shortened; '
@@ -174,46 +176,48 @@ class Morph(cliapp.Application):
         return pool
 
     def compute_build_order(self, repo_name, ref, filename, ckc, lrc, rrc):
-        self.msg('Figuring out the right build order')
+        self.status(msg='Figuring out the right build order')
 
-        logging.debug('creating source pool')
+        self.status(msg='Creating source pool', chatty=True)
         srcpool = self._create_source_pool(
                 lrc, rrc, (repo_name, ref, filename))
 
-        logging.debug('creating artifact resolver')
+        self.status(msg='Creating artifact resolver', chatty=True)
         ar = morphlib.artifactresolver.ArtifactResolver()
 
-        logging.debug('resolving artifacts')
+        self.status(msg='Resolving artifacts', chatty=True)
         artifacts = ar.resolve_artifacts(srcpool)
 
-        logging.debug('computing cache keys')
+        self.status(msg='Computing cache keys', chatty=True)
         for artifact in artifacts:
             artifact.cache_key = ckc.compute_key(artifact)
             artifact.cache_id = ckc.get_cache_id(artifact)
 
-        logging.debug('computing build order')
+        self.status(msg='Computing build order', chatty=True)
         order = morphlib.buildorder.BuildOrder(artifacts)
         
         return order
 
     def find_what_needs_building(self, order, lac, rac):
-        logging.debug('finding what needs to be built')
+        self.status(msg='Finding out what needs to be built', chatty=True)
         needed = []
         for group in order.groups:
             for artifact in group:
                 if not lac.has(artifact):
                     if not rac or not rac.has(artifact):
                         needed.append(artifact)
+        self.status(msg='There are %(count)s artifacts that need building',
+                    count=len(needed))
         return needed
 
     def get_source_repositories(self, needed, lrc):
-        logging.debug('cloning/updating cached repos')
         done = set()
         for artifact in needed:
             if self.settings['no-git-update']:
                 artifact.source.repo = lrc.get_repo(artifact.source.repo_name)
             else:
-                self.msg('Cloning/updating %s' % artifact.source.repo_name)
+                self.status(msg='Cloning/updating %(repo_name)s',
+                            repo_name=artifact.source.repo_name)
                 artifact.source.repo = lrc.cache_repo(
                         artifact.source.repo_name)
                 self._cache_repo_and_submodules(
@@ -237,6 +241,7 @@ class Morph(cliapp.Application):
             install_chunks = False
             setup_mounts = False
 
+        self.status(msg='Creating staging area')
         staging_area = morphlib.stagingarea.StagingArea(self,
                                                         staging_root,
                                                         staging_temp)
@@ -247,26 +252,34 @@ class Morph(cliapp.Application):
 
     def remove_staging_area(self, staging_area):
         if staging_area.dirname != '/':
+            self.status(msg='Removing staging area')
             staging_area.remove()
         if (staging_area.tempdir != '/' and 
             os.path.exists(staging_area.tempdir)):
+            self.status(msg='Removing temporary staging directory')
             shutil.rmtree(staging_area.tempdir)
 
     def install_artifacts(self, staging_area, lac, rac, chunk_artifacts):
         for chunk_artifact in chunk_artifacts:
-            self.msg('  Installing %s' % chunk_artifact.name)
             if not lac.has(chunk_artifact) and rac:
+                self.status(msg='Fetching artifact from remote server')
                 remote = rac.get(chunk_artifact)
                 local = lac.put(chunk_artifact)
                 shutil.copyfileobj(remote, local)
                 remote.close()
                 local.close()
+
+            self.status(msg='Installing %(kind)s %(artifact_name)s',
+                        artifact_name=chunk_artifact.name,
+                        kind=chunk_artifact.source.morphology['kind'])
             handle = lac.get(chunk_artifact)
             staging_area.install_artifact(handle)
 
     def build_group(self, artifacts, builder, lac, staging_area):
         for artifact in artifacts:
-            self.msg('Building %s' % artifact.name)
+            self.status(msg='Building %(kind)s %(artifact_name)s',
+                        artifact_name=artifact.name,
+                        kind=artifact.source.morphology['kind'])
             builder.build_and_cache(artifact)
 
     def new_build_env(self):
@@ -331,7 +344,7 @@ class Morph(cliapp.Application):
         
         '''
 
-        self.msg('Build starts')
+        self.status(msg='Build starts')
 
         build_env = self.new_build_env()
         ckc = self.new_cache_key_computer(build_env)
@@ -339,7 +352,8 @@ class Morph(cliapp.Application):
         lrc, rrc = self.new_repo_caches()
 
         for repo_name, ref, filename in self._itertriplets(args):
-            self.msg('Building %s %s %s' % (repo_name, ref, filename))
+            self.status(msg='Building %(repo_name)s %(ref)s %(filename)s',
+                        repo_name=repo_name, ref=ref, filename=filename)
             order = self.compute_build_order(repo_name, ref, filename,
                                              ckc, lrc, rrc)
             needed = self.find_what_needs_building(order, lac, rac)
@@ -356,7 +370,9 @@ class Morph(cliapp.Application):
                     self.install_artifacts(staging_area, lac, rac, to_install)
                     del to_install[:]
                 for artifact in set(group).difference(set(needed)):
-                    self.msg('Using cached %s' % artifact.name)
+                    self.status(msg='Using cached %(artifact_name)s',
+                                artifact_name=artifact.name,
+                                chatty=True)
                 wanted = [x for x in group if x in needed]
                 self.build_group(wanted, builder, lac, staging_area)
                 to_install.extend(
@@ -369,12 +385,14 @@ class Morph(cliapp.Application):
                 self.install_artifacts(staging_area, lac, rac, to_install)
 
             self.remove_staging_area(staging_area)
+            self.status(msg='Build ends successfully')
 
     def _install_initial_staging(self, staging_area):
         logging.debug('Pre-populating staging area %s' % staging_area.dirname)
         logging.debug('Fillers: %s' % repr(self.settings['staging-filler']))
         for filename in self.settings['staging-filler']:
             with open(filename, 'rb') as f:
+                self.status(msg='Installing %(filename)s', filename=filename)
                 staging_area.install_artifact(f)
 
     def cmd_show_dependencies(self, args):
@@ -485,7 +503,8 @@ class Morph(cliapp.Application):
         subs_to_process = set()
         
         def visit(reponame, ref, filename, absref, morphology):
-            self.msg('Updating %s|%s|%s' % (reponame, ref, filename))
+            self.status(msg='Updating %(repo_name)s %(ref)s %(filename)s',
+                        repo_name=reponame, ref=ref, filename=filename)
             assert cache.has_repo(reponame)
             cached_repo = cache.get_repo(reponame)
             try:
@@ -880,35 +899,67 @@ class Morph(cliapp.Application):
                 morph = json.load(f)
             
             if morph['kind'] != 'stratum':
-                self.msg('Not a stratum: %s' % filename)
+                self.status(msg='Not a stratum: %(filename)s',
+                            filename=filename)
                 continue
 
-            self.msg('Petrifying %s' % filename)
+            self.status(msg='Petrifying %(filename)s', filename=filename)
 
             for source in morph['sources']:
                 reponame = source.get('repo', source['name'])
                 ref = source['ref']
-                self.msg('.. looking up sha1 for %s %s' % (reponame, ref))
+                self.status(msg='Looking up sha1 for %(repo_name)s %(ref)s',
+                            repo_name=reponame, 
+                            ref=ref)
                 repo = cache.get_repo(reponame)
                 source['ref'] = repo.resolve_ref(ref)
             
             with open(filename, 'w') as f:
                 json.dump(morph, f, indent=2)
 
-    def msg(self, msg):
-        '''Show a message to the user about what is going on.'''
-        logging.debug(msg)
-        if self.settings['verbose']:
-            self.output.write('%s\n' % msg)
-            self.output.flush()
+    def status(self, **kwargs):
+        '''Show user a status update.
+        
+        The keyword arguments are formatted and presented to the user in
+        a pleasing manner. Some keywords are special:
+        
+        * ``msg`` is the message text; it can use ``%(foo)s`` to embed the
+          value of keyword argument ``foo``
+        * ``chatty`` should be true when the message is only informative,
+          and only useful for users who want to know everything (--verbose)
+        * ``error`` should be true when it is an error message
+        
+        All other keywords are ignored unless embedded in ``msg``.
+        
+        '''
 
-    def runcmd(self, argv, *args, **kwargs):
-        # check which msg function to use
-        msg = self.msg
         if 'msg' in kwargs:
-            msg = kwargs['msg']
-            del kwargs['msg']
+            text = kwargs['msg'] % kwargs
+        else:
+            text = 'Morph tried to say something, but couldn\'t decide what'
+        
+        timestamp = time.strftime('%Y-%m-%d %H:%M:%S', time.gmtime())
+        text = '%s %s' % (timestamp, text)
+        
+        error = kwargs.get('error', False)
+        chatty = kwargs.get('chatty', False)
+        quiet = self.settings['quiet']
+        verbose = self.settings['verbose']
+        
+        ok = verbose or (quiet and error) or (not quiet and not chatty)
+
+        if error:
+            logging.error(text)
+        elif chatty:
+            logging.debug(text)
+        else:
+            logging.info(text)
+        
+        if ok:
+            self.output.write('%s\n' % text)
+            self.output.flush()
 
+    def runcmd(self, argv, *args, **kwargs):
         if 'env' not in kwargs:
             kwargs['env'] = dict(os.environ)
 
@@ -921,7 +972,9 @@ class Morph(cliapp.Application):
         commands = [' '.join(command) for command in commands]
 
         # print the command line
-        msg('# %s' % ' | '.join(commands))
+        self.status(msg='# %(cmdline)s',
+                    cmdline=' | '.join(commands),
+                    chatty=True)
         
         # Log the environment.
         for name in kwargs['env']:
diff --git a/morphlib/builder2.py b/morphlib/builder2.py
index 3bc8bb10..4e6f7dde 100644
--- a/morphlib/builder2.py
+++ b/morphlib/builder2.py
@@ -287,7 +287,9 @@ class ChunkBuilder(BuilderBase):
         cache_dir = os.path.dirname(self.artifact.source.repo.path)
 
         def extract_repo(path, sha1, destdir):
-            logging.debug('Extracting %s into %s' % (path, destdir))
+            self.app.status(msg='Extracting %(source)s into %(target)s',
+                            source=path,
+                            target=destdir))
             if not os.path.exists(destdir):
                 os.mkdir(destdir)
             morphlib.git.copy_repository(self.app.runcmd, path, destdir)
@@ -376,6 +378,7 @@ class ChunkBuilder(BuilderBase):
                 with self.local_artifact_cache.put(artifact) as f:
                     logging.debug('assembling chunk %s' % artifact_name)
                     logging.debug('assembling into %s' % f.name)
+                    self.app.status(msg='Creating chunk')
                     morphlib.bins.create_chunk(destdir, f, patterns)
                 built_artifacts.append(artifact)
     
@@ -409,6 +412,10 @@ class StratumBuilder(BuilderBase):
                     logging.warning('Overlaps in stratum artifact %s detected'
                                     % self.artifact.name)
                     log_overlaps(overlaps)
+                    self.app.status(msg='Overlaps in stratum artifact '
+                                        '%(stratum_name)s detected',
+                                    stratum_name=self.artifact.name,
+                                    error=True)
                     write_overlap_metadata(self.artifact, overlaps,
                                            self.local_artifact_cache)
 
@@ -431,7 +438,8 @@ class SystemBuilder(BuilderBase): # pragma: no cover
 
     def build_and_cache(self):
         with self.build_watch('overall-build'):
-            logging.debug('SystemBuilder.do_build called')
+            self.app.status(msg='Building system %(system_name)s',
+                            system_name=self.artifact.name)
 
             arch = self.artifact.source.morphology['arch']
             
@@ -473,8 +481,8 @@ class SystemBuilder(BuilderBase): # pragma: no cover
                 
                 self._unmount(mount_point)
             except BaseException, e:
-                logging.error('Got error while system image building, '
-                                'unmounting and device unmapping')
+                self.app.status(msg='Error while building system',
+                                error=True)
                 self._unmount(mount_point)
                 self._undo_device_mapping(image_name)
                 handle.abort()
@@ -487,47 +495,56 @@ class SystemBuilder(BuilderBase): # pragma: no cover
         return [self.artifact]
 
     def _create_image(self, image_name):
-        logging.debug('Creating disk image %s' % image_name)
+        self.app.status(msg='Creating disk image %(filename)s',
+                        filename=image_name, chatty=True)
         with self.build_watch('create-image'):
             morphlib.fsutils.create_image(
                 self.app.runcmd, image_name,
                 self.artifact.source.morphology['disk-size'])
 
     def _partition_image(self, image_name):
-        logging.debug('Partitioning disk image %s' % image_name)
+        self.app.status(msg='Partitioning disk image %(filename)s',
+                        filename=image_name)
         with self.build_watch('partition-image'):
             morphlib.fsutils.partition_image(self.app.runcmd, image_name)
 
     def _install_mbr(self, arch, image_name):
-        logging.debug('Installing mbr on disk image %s' % image_name)
+        self.app.status(msg='Installing mbr on disk image %(filename)s',
+                        filename=image_name, chatty=True)
         if arch not in ('x86', 'x86_64', None):
             return
         with self.build_watch('install-mbr'):
             morphlib.fsutils.install_syslinux_mbr(self.app.runcmd, image_name)
 
     def _setup_device_mapping(self, image_name):
-        logging.debug('Device mapping partitions in %s' % image_name)
+        self.app.status(msg='Device mapping partitions in %(filename)s',
+                        filename=image_name, chatty=True)
         with self.build_watch('setup-device-mapper'):
             return morphlib.fsutils.setup_device_mapping(self.app.runcmd,
                                                          image_name)
 
     def _create_fs(self, partition):
-        logging.debug('Creating filesystem on %s' % partition)
+        self.app.status(msg='Creating filesystem on %(filename)s',
+                        filename=image_name, chatty=True)
         with self.build_watch('create-filesystem'):
             morphlib.fsutils.create_fs(self.app.runcmd, partition)
 
     def _mount(self, partition, mount_point):
-        logging.debug('Mounting %s on %s' % (partition, mount_point))
+        self.app.status(msg='Mounting %(partition) on %(mount_point)s',
+                        partition=partition, mount_point=mount_point,
+                        chatty=True)
         with self.build_watch('mount-filesystem'):
             morphlib.fsutils.mount(self.app.runcmd, partition, mount_point)
 
     def _create_subvolume(self, path):
-        logging.debug('Creating subvolume %s' % path)
+        self.app.status(msg='Creating subvolume %(path)s', 
+                        path=path, chatty=True)
         with self.build_watch('create-factory-subvolume'):
             self.app.runcmd(['btrfs', 'subvolume', 'create', path])
 
     def _unpack_strata(self, path):
-        logging.debug('Unpacking strata to %s' % path)
+        self.app.status(msg='Unpacking strata to %(path)s',
+                        path=path, chatty=True)
         with self.build_watch('unpack-strata'):
             # download the stratum artifacts if necessary
             download_depends(self.artifact.dependencies,
@@ -548,8 +565,10 @@ class SystemBuilder(BuilderBase): # pragma: no cover
             overlaps = get_overlaps(self.artifact, self.artifact.dependencies,
                                     self.local_artifact_cache)
             if len(overlaps) > 0:
-                logging.warning('Overlaps in system artifact %s detected' %
-                                self.artifact.name)
+                self.app.status(msg='Overlaps in system artifact '
+                                    '%(artifact_name)detected',
+                                artifact_name=self.artifact.name,
+                                error=True)
                 log_overlaps(overlaps)
                 write_overlap_metadata(self.artifact, overlaps,
                                        self.local_artifact_cache)
@@ -574,7 +593,8 @@ class SystemBuilder(BuilderBase): # pragma: no cover
             ldconfig(self.app.runcmd, path)
 
     def _create_fstab(self, path):
-        logging.debug('Creating fstab in %s' % path)
+        self.app.status(msg='Creating fstab in %(path)s',
+                        path=path, chatty=True)
         with self.build_watch('create-fstab'):
             fstab = os.path.join(path, 'etc', 'fstab')
             if not os.path.exists(os.path.dirname(fstab)):# FIXME: should exist
@@ -585,7 +605,8 @@ class SystemBuilder(BuilderBase): # pragma: no cover
                 f.write('/dev/sda1 / btrfs errors=remount-ro 0 1\n')
 
     def _create_extlinux_config(self, path):
-        logging.debug('Creating extlinux.conf in %s' % path)
+        self.app.status(msg='Creating extlinux.conf in %(path)s',
+                        path=path, chatty=True)
         with self.build_watch('create-extlinux-config'):
             config = os.path.join(path, 'extlinux.conf')
             with open(config, 'w') as f:
@@ -597,14 +618,16 @@ class SystemBuilder(BuilderBase): # pragma: no cover
                         'init=/sbin/init rw\n')
     
     def _create_subvolume_snapshot(self, path, source, target):
-        logging.debug('Creating subvolume snapshot %s to %s' % 
-                        (source, target))
+        self.app.status(msg='Creating subvolume snapshot '
+                            '%(source)s to %(target)s',
+                        source=source, target=target, chatty=True)
         with self.build_watch('create-runtime-snapshot'):
             self.app.runcmd(['btrfs', 'subvolume', 'snapshot', source, target],
                          cwd=path)
 
     def _install_boot_files(self, arch, sourcefs, targetfs):
-        logging.debug('installing boot files into root volume')
+        self.app.status(msg='Installing boot files into root volume',
+                        chatty=True)
         with self.build_watch('install-boot-files'):
             if arch in ('x86', 'x86_64', None):
                 shutil.copy2(os.path.join(sourcefs, 'extlinux.conf'),
@@ -616,7 +639,8 @@ class SystemBuilder(BuilderBase): # pragma: no cover
                              os.path.join(targetfs, 'boot', 'System.map'))
 
     def _install_extlinux(self, path):
-        logging.debug('Installing extlinux to %s' % path)
+        self.app.status(msg='Installing extlinux to %(path)s',
+                        path=path, chatty=True)
         with self.build_watch('install-bootloader'):
             self.app.runcmd(['extlinux', '--install', path])
 
@@ -625,13 +649,15 @@ class SystemBuilder(BuilderBase): # pragma: no cover
             time.sleep(2)
 
     def _unmount(self, mount_point):
-        logging.debug('Unmounting %s' % mount_point)
+        self.app.status(msg='Unmounting %(mount_point)s',
+                        mount_point=mount_point, chatty=True)
         with self.build_watch('unmount-filesystem'):
             if mount_point is not None:
                 morphlib.fsutils.unmount(self.app.runcmd, mount_point)
 
     def _undo_device_mapping(self, image_name):
-        logging.debug('Undoing device mappings for %s' % image_name)
+        self.app.status(msg='Undoing device mappings for %(filename)s',
+                        filename=image_name, chatty=True)
         with self.build_watch('undo-device-mapper'):
             morphlib.fsutils.undo_device_mapping(self.app.runcmd, image_name)