Logging improvements

Improve logging output and make consistent use of log levels in
plugin code.

Log messages for the archive and plugin classes now use their
own class-level logging interface to prefix messages with a
label indicating the message source, e.g.:

  [plugin:yum] collecting output of 'yum -C repolist'
  [archive:TarFileArchive] finalizing archive '/var/tmp/sosreport-f20-vm1-20140406162540'

Convert existing plugin and archive code to use the new
interfaces.

Signed-off-by: Bryn M. Reeves <bmr@redhat.com>

8 files changed, 93 insertions, 44 deletions

diff --git a/sos/archive.py b/sos/archive.py
index 7f4d78d7..a252ee06 100644
--- a/sos/archive.py
+++ b/sos/archive.py
@@ -38,10 +38,31 @@ if six.PY3:
 
 class Archive(object):
 
+    @classmethod
+    def archive_type(class_):
+        """Returns the archive class's name as a string.
+        """
+        return class_.__name__
+
     log = logging.getLogger("sos")
 
     _name = "unset"
 
+    def _format_msg(self,msg):
+        return "[archive:%s] %s" % (self.archive_type(), msg)
+
+    def log_error(self, msg):
+        self.log.error(self._format_msg(msg))
+
+    def log_warn(self,msg):
+        self.log.warning(self._format_msg(msg))
+
+    def log_info(self, msg):
+        self.log.info(self._format_msg(msg))
+
+    def log_debug(self, msg):
+        self.log.debug(self._format_msg(msg))
+
     # this is our contract to clients of the Archive class hierarchy.
     # All sub-classes need to implement these methods (or inherit concrete
     # implementations from a parent class.
@@ -96,7 +117,7 @@ class FileCacheArchive(Archive):
         self._tmp_dir = tmpdir
         self._archive_root = os.path.join(tmpdir, name)
         os.makedirs(self._archive_root, 0o700)
-        self.log.debug("initialised empty FileCacheArchive at %s" %
+        self.log_info("initialised empty FileCacheArchive at '%s'" %
                        (self._archive_root,))
 
     def dest_path(self, name):
@@ -119,7 +140,7 @@ class FileCacheArchive(Archive):
         try:
             shutil.copy(src, dest)
         except IOError as e:
-            self.log.debug("caught %s copying %s" % (e, src))
+            self.log_debug("caught '%s' copying '%s'" % (e, src))
         try:
             shutil.copystat(src, dest)
         except PermissionError:
@@ -129,8 +150,8 @@ class FileCacheArchive(Archive):
             stat = os.stat(src)
             os.chown(dest, stat.st_uid, stat.st_gid)
         except Exception as e:
-            self.log.debug("caught %s setting ownership of %s" % (e, dest))
-        self.log.debug("added %s to FileCacheArchive %s" %
+            self.log_debug("caught '%s' setting ownership of '%s'" % (e, dest))
+        self.log_debug("added '%s' to FileCacheArchive '%s'" %
                        (src, self._archive_root))
 
     def add_string(self, content, dest):
@@ -144,7 +165,7 @@ class FileCacheArchive(Archive):
                 shutil.copystat(src, dest)
             except PermissionError:
                 pass
-        self.log.debug("added string at %s to FileCacheArchive %s"
+        self.log_debug("added string at '%s' to FileCacheArchive '%s'"
                        % (src, self._archive_root))
 
     def add_link(self, source, link_name):
@@ -152,7 +173,7 @@ class FileCacheArchive(Archive):
         self._check_path(dest)
         if not os.path.exists(dest):
             os.symlink(source, dest)
-        self.log.debug("added symlink at %s to %s in FileCacheArchive %s"
+        self.log_debug("added symlink at '%s' to '%s' in FileCacheArchive '%s'"
                        % (dest, source, self._archive_root))
 
     def add_dir(self, path):
@@ -169,7 +190,7 @@ class FileCacheArchive(Archive):
 
     def makedirs(self, path, mode=0o700):
         self._makedirs(self.dest_path(path))
-        self.log.debug("created directory at %s in FileCacheArchive %s"
+        self.log_debug("created directory at '%s' in FileCacheArchive '%s'"
                        % (path, self._archive_root))
 
     def open_file(self, path):
@@ -180,10 +201,10 @@ class FileCacheArchive(Archive):
         shutil.rmtree(self._archive_root)
 
     def finalize(self, method):
-        self.log.debug("finalizing archive %s" % self._archive_root)
+        self.log_info("finalizing archive '%s'" % self._archive_root)
         self._build_archive()
         self.cleanup()
-        self.log.debug("built archive at %s (size=%d)" % (self._archive_name,
+        self.log_info("built archive at '%s' (size=%d)" % (self._archive_name,
                        os.stat(self._archive_name).st_size))
         return self._compress()
 
@@ -253,7 +274,6 @@ class TarFileArchive(FileCacheArchive):
             methods = [self.method]
 
         last_error = Exception("compression failed for an unknown reason")
-        log = logging.getLogger('sos')
 
         for cmd in methods:
             suffix = "." + cmd.replace('ip', '')
@@ -269,9 +289,9 @@ class TarFileArchive(FileCacheArchive):
                           close_fds=True)
                 stdout, stderr = p.communicate()
                 if stdout:
-                    log.info(stdout.decode('utf-8'))
+                    self.log_info(stdout.decode('utf-8'))
                 if stderr:
-                    log.error(stderr.decode('utf-8'))
+                    self.log_error(stderr.decode('utf-8'))
                 self._suffix += suffix
                 return self.name()
             except Exception as e:
diff --git a/sos/plugins/__init__.py b/sos/plugins/__init__.py
index 8a938a9b..f5042b41 100644
--- a/sos/plugins/__init__.py
+++ b/sos/plugins/__init__.py
@@ -122,6 +122,21 @@ class Plugin(object):
             return class_.plugin_name
         return class_.__name__.lower()
 
+    def _format_msg(self,msg):
+        return "[plugin:%s] %s" % (self.name(), msg)
+
+    def log_error(self, msg):
+        self.soslog.error(self._format_msg(msg))
+
+    def log_warn(self,msg):
+        self.soslog.warning(self._format_msg(msg))
+
+    def log_info(self, msg):
+        self.soslog.info(self._format_msg(msg))
+
+    def log_debug(self, msg):
+        self.soslog.debug(self._format_msg(msg))
+
     def policy(self):
         return self.commons["policy"]
 
@@ -141,7 +156,7 @@ class Plugin(object):
         This function returns the number of replacements made.
         '''
         globstr = '*' + cmd + '*'
-        self.soslog.debug("substituting '%s' for '%s' in commands matching %s"
+        self.log_debug("substituting '%s' for '%s' in commands matching '%s'"
                     % (subst, regexp, globstr))
 
         if not self.executed_commands:
@@ -155,7 +170,7 @@ class Plugin(object):
                     continue
                 if fnmatch.fnmatch(called['exe'], globstr):
                     path = os.path.join(self.commons['cmddir'], called['file'])
-                    self.soslog.debug("applying substitution to %s" % path)
+                    self.log_debug("applying substitution to '%s'" % path)
                     readable = self.archive.open_file(path)
                     result, replacements = re.subn(
                             regexp, subst, readable.read())
@@ -163,8 +178,8 @@ class Plugin(object):
                         self.archive.add_string(result, path)
 
         except Exception as e:
-            msg = 'regex substitution failed for %s in plugin %s with: "%s"'
-            self.soslog.error(msg % (called['exe'], self.name(), e))
+            msg = "regex substitution failed for '%s' with: '%s'"
+            self.log_error(msg % (called['exe'], e))
             replacements = None
         return replacements
         
@@ -178,7 +193,7 @@ class Plugin(object):
         '''
         try:
             path = self._get_dest_for_srcpath(srcpath)
-            self.soslog.debug("substituting '%s' for '%s' in %s"
+            self.log_debug("substituting '%s' for '%s' in '%s'"
                     % (subst, regexp, path))
             if not path:
                 return 0
@@ -189,8 +204,8 @@ class Plugin(object):
             else:
                 replacements = 0
         except Exception as e:
-            msg = 'regex substitution failed for %s in plugin %s with: "%s"'
-            self.soslog.error(msg % (path, self.name(), e))
+            msg = "regex substitution failed for '%s' with: '%s'"
+            self.log_error(msg % (path, e))
             replacements = 0
         return replacements
 
@@ -219,17 +234,17 @@ class Plugin(object):
         if os.path.isabs(linkdest):
                 reldest = os.path.relpath(linkdest,
                                 os.path.dirname(srcpath))
-                self.soslog.debug("made link target %s relative as %s"
+                self.log_debug("made link target '%s' relative as '%s'"
                                 % (linkdest, reldest))
         else:
                 reldest = linkdest
 
-        self.soslog.debug(
-                "copying link %s pointing to %s with isdir=%s"
+        self.log_debug(
+                "copying link '%s' pointing to '%s' with isdir=%s"
                 % (srcpath, linkdest, os.path.isdir(absdest)))
 
         if os.path.isdir(absdest):
-            self.soslog.debug("link %s is a directory, skipping..."
+            self.log_debug("link '%s' is a directory, skipping..."
                             % linkdest)
             return
 
@@ -238,7 +253,7 @@ class Plugin(object):
 
         # copy the symlink target translating relative targets
         # to absolute paths to pass to do_copy_path.
-        self.soslog.debug("normalized link target %s as %s"
+        self.log_debug("normalized link target '%s' as '%s'"
                         %(linkdest, absdest))
         self.do_copy_path(absdest)
 
@@ -270,11 +285,11 @@ class Plugin(object):
         saved for use later in preparing a report.
         '''
         if self.is_forbidden_path(srcpath):
-            self.soslog.debug("%s is in the forbidden path list" % srcpath)
+            self.log_debug("skipping forbidden path '%s'" % srcpath)
             return ''
 
         if not os.path.exists(srcpath):
-            self.soslog.debug("file or directory %s does not exist" % srcpath)
+            self.log_debug("path '%s' does not exist" % srcpath)
             return
 
         if not dest:
@@ -289,7 +304,7 @@ class Plugin(object):
                 return
 
         # if we get here, it's definitely a regular file (not a symlink or dir)
-        self.soslog.debug("copying file %s to %s" % (srcpath,dest))
+        self.log_debug("copying file '%s' to archive:'%s'" % (srcpath,dest))
 
         try:
             stat = os.stat(srcpath)
@@ -306,8 +321,9 @@ class Plugin(object):
                 'symlink':"no"})
 
         except Exception as e:
-            self.soslog.error("Unable to copy %s to %s" % (srcpath, dest))
-            self.soslog.error(traceback.format_exc())
+            self.log_error("unable to add file '%s' to archive:'%s'"
+                           % (srcpath, dest))
+            self.log_error(traceback.format_exc())
 
 
     def add_forbidden_path(self, forbiddenPath):
@@ -419,19 +435,19 @@ class Plugin(object):
         copied into the sosreport by this module.
         """
         if not (copyspec and len(copyspec)):
-            self.soslog.warning("plugin %s %s"
-                % ("added null or empty copy spec", self.name()))
+            self.log_warn("added null or empty copy spec")
             return False
         copy_paths = self.expand_copy_spec(copyspec)
         self.copy_paths.update(copy_paths)
+        self.log_debug("added copyspec '%s'" % copyspec)
 
     def get_command_output(self, prog, timeout=300):
         result = sos_get_command_output(prog, timeout)
         if result['status'] == 124:
-            self.soslog.warning("command '%s' timed out after %ds"
+            self.log_warn("command '%s' timed out after %ds"
                     % (prog, timeout))
         if result['status'] == 127:
-            self.soslog.info("could not run '%s': command not found" % prog)
+            self.log_debug("could not run '%s': command not found" % prog)
         return result
 
     def call_ext_prog(self, prog, timeout=300):
@@ -452,6 +468,7 @@ class Plugin(object):
     def add_cmd_output(self, exe, suggest_filename=None, root_symlink=None, timeout=300):
         """Run a program and collect the output"""
         self.collect_cmds.append( (exe, suggest_filename, root_symlink, timeout) )
+        self.log_debug("added cmd output '%s'" % exe)
 
     def get_cmd_output_path(self, name=None, make=True):
         """Return a path into which this module should store collected
@@ -496,6 +513,7 @@ class Plugin(object):
     def add_string_as_file(self, content, filename):
         """Add a string to the archive as a file named `filename`"""
         self.copy_strings.append((content, filename))
+        self.log_debug("added string '%s' as '%s'" % (content,filename))
 
     def get_cmd_output_now(self, exe, suggest_filename=None, root_symlink=False, timeout=300):
         """Execute a command and save the output to a file for inclusion in the
@@ -544,27 +562,30 @@ class Plugin(object):
 
     def collect_copy_specs(self):
         for path in self.copy_paths:
+                self.log_info("collecting path '%s'" % path)
                 self.do_copy_path(path)
 
     def collect_cmd_output(self):
         for progs in zip(self.collect_cmds):
             prog, suggest_filename, root_symlink, timeout = progs[0]
-            self.soslog.debug("collecting output of '%s'" % prog)
+            self.log_info("collecting output of '%s'" % prog)
             try:
                 self.get_cmd_output_now(prog, suggest_filename,
                         root_symlink, timeout)
             except Exception as e:
-                self.soslog.debug("error collecting output of '%s' (%s)"
+                self.log_debug("could not collect output of '%s': %s"
                         % (prog, e))
 
     def collect_strings(self):
         for string, file_name in self.copy_strings:
+            self.log_info("collecting string '%s' as '%s'"
+                          % (self.name(), string, file_name))
             try:
                 self.archive.add_string(string,
                         os.path.join('sos_strings', self.name(), file_name))
             except Exception as e:
-                self.soslog.debug("could not create %s, traceback follows: %s"
-                        % (file_name, e))
+                self.log_debug("could not add string '%s': %s"
+                               % (file_name, e))
 
     def collect(self):
         """Collect the data for a plugin."""
diff --git a/sos/plugins/cluster.py b/sos/plugins/cluster.py
index 5b13294b..b3cff0f9 100644
--- a/sos/plugins/cluster.py
+++ b/sos/plugins/cluster.py
@@ -93,7 +93,7 @@ class Cluster(Plugin, RedHatPlugin):
                         str(self.get_option('crm_from'))):
                 crm_from = self.get_option('crm_from')
             else:
-                self.soslog.error(
+                self.log_error(
                     "crm_from parameter '%s' is not a valid date: using default"
                             % self.get_option('crm_from'))
 
diff --git a/sos/plugins/kernel.py b/sos/plugins/kernel.py
index d40f5493..f17d78fc 100644
--- a/sos/plugins/kernel.py
+++ b/sos/plugins/kernel.py
@@ -32,7 +32,7 @@ class Kernel(Plugin, RedHatPlugin, DebianPlugin, UbuntuPlugin):
             modules = os.listdir(self.sys_module)
             self.add_cmd_output("modinfo " + " ".join(modules))
         except OSError:
-            self.soslog.warning("could not list %s" % self.sys_module)
+            self.log_warn("could not list %s" % self.sys_module)
 
         self.add_cmd_output("dmesg")
         self.add_cmd_output("sysctl -a")
diff --git a/sos/plugins/kvm.py b/sos/plugins/kvm.py
index 7bb7c310..5f90e0fa 100644
--- a/sos/plugins/kvm.py
+++ b/sos/plugins/kvm.py
@@ -40,7 +40,7 @@ class Kvm(Plugin, RedHatPlugin, DebianPlugin, UbuntuPlugin):
             r = self.call_ext_prog("mount -t debugfs debugfs %s"
                                     % self.debugfs_path)
             if r['status'] != 0:
-                self.soslog.error("debugfs not mounted and mount attempt failed")
+                self.log_error("debugfs not mounted and mount attempt failed")
                 self._debugfs_cleanup = False
                 return
         self.add_cmd_output("kvm_stat --once")
@@ -48,6 +48,6 @@ class Kvm(Plugin, RedHatPlugin, DebianPlugin, UbuntuPlugin):
     def postproc(self):
         if self._debugfs_cleanup and os.path.ismount(debugfs_path):
             r = self.call_ext_prog("umount %s" % self.debugfs_path)
-            self.soslog.error("could not unmount %s" % self.debugfs_path)
+            self.log_error("could not unmount %s" % self.debugfs_path)
 
 # vim: et ts=4 sw=4
diff --git a/sos/plugins/postgresql.py b/sos/plugins/postgresql.py
index 290b6a5d..07a12926 100644
--- a/sos/plugins/postgresql.py
+++ b/sos/plugins/postgresql.py
@@ -66,7 +66,7 @@ class PostgreSQL(Plugin):
         if (result['status'] == 0):
             self.add_copy_spec(dest_file)
         else:
-            self.soslog.error(
+            self.log_error(
                 "Unable to execute pg_dump. Error(%s)" % (result['output'])
             )
             self.add_alert(
diff --git a/sos/plugins/sar.py b/sos/plugins/sar.py
index 56cc637a..a89d27f1 100644
--- a/sos/plugins/sar.py
+++ b/sos/plugins/sar.py
@@ -39,7 +39,7 @@ class Sar(Plugin,):
         try:
             dirList = os.listdir(self.sa_path)
         except:
-            self.soslog.warning("sar: could not list %s" % self.sa_path)
+            self.log_warn("sar: could not list %s" % self.sa_path)
             return
         # find all the sa file that don't have an existing sar file
         for fname in dirList:
diff --git a/sos/sosreport.py b/sos/sosreport.py
index 334415ee..31ef0fa8 100644
--- a/sos/sosreport.py
+++ b/sos/sosreport.py
@@ -905,6 +905,7 @@ class SoSReport(object):
     def prework(self):
         try:
             self.policy.pre_work()
+            self.ui_log.info(_(" Setting up archive ..."))
             self._set_archive()
             self._make_archive_paths()
         except Exception as e:
@@ -914,6 +915,7 @@ class SoSReport(object):
             self._exit(0)
 
     def setup(self):
+        self.ui_log.info(_(" Setting up plugins ..."))
         for plugname, plug in self.loaded_plugins:
             try:
                 plug.archive = self.archive
@@ -945,8 +947,14 @@ class SoSReport(object):
         for i in zip(self.loaded_plugins):
             plugruncount += 1
             plugname, plug = i[0]
+            status_line = ("  Running %d/%d: %s...        "
+                           % (plugruncount, len(self.loaded_plugins), plugname))
+            if self.opts.verbosity == 0:
+                status_line = "\r%s" % status_line
+            else:
+                status_line = "%s\n" % status_line
             if not self.opts.quiet:
-                sys.stdout.write("\r  Running %d/%d: %s...        " % (plugruncount, len(self.loaded_plugins), plugname))
+                sys.stdout.write(status_line)
                 sys.stdout.flush()
             try:
                 plug.collect()