From e5a530ced60ef1e393ee498310f494d069f4e882 Mon Sep 17 00:00:00 2001 From: "Bryn M. Reeves" Date: Sun, 6 Apr 2014 16:26:55 +0100 Subject: 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 --- sos/archive.py | 44 +++++++++++++++++++++-------- sos/plugins/__init__.py | 71 ++++++++++++++++++++++++++++++----------------- sos/plugins/cluster.py | 2 +- sos/plugins/kernel.py | 2 +- sos/plugins/kvm.py | 4 +-- sos/plugins/postgresql.py | 2 +- sos/plugins/sar.py | 2 +- sos/sosreport.py | 10 ++++++- 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() -- cgit