Better logging using python's logging module.

Verbose logs included in sosreport (sos_logs/sos.log)


git-svn-id: svn+ssh://svn.fedorahosted.org/svn/sos/trunk@104 ef72aa8b-4018-0410-8976-d6e080ef94d8

2 files changed, 51 insertions, 42 deletions

diff --git a/src/lib/sos/plugintools.py b/src/lib/sos/plugintools.py
index 73d29b6a..3e7e9881 100644
--- a/src/lib/sos/plugintools.py
+++ b/src/lib/sos/plugintools.py
@@ -84,9 +84,7 @@ class PluginBase:
                     except KeyboardInterrupt:
                       raise KeyboardInterrupt
                     except Exception, e:
-                        print e
-                        sys.stderr.write("Problem at path %s\n" % abspath)
-                        sys.stderr.flush()
+                        self.cInfo['soslog'].error("Problem at path %s (%s)\n" % (abspath,e))
                         break
         return False
 
@@ -142,9 +140,7 @@ class PluginBase:
                         except KeyboardInterrupt:
                           raise KeyboardInterrupt
                         except Exception, e:
-                            print e
-                            sys.stderr.write("1Problem at path %s\n" %  srcpath+'/'+afile)
-                            sys.stderr.flush()
+                            self.cInfo['soslog'].error("Problem at path %s (%s)" % (srcpath+'/'+afile, e))
                         # if on forbidden list, abspath is null
                         if not abspath == '':
                             dstslname = sosRelPath(self.cInfo['rptdir'], abspath)
@@ -158,9 +154,7 @@ class PluginBase:
                 except KeyboardInterrupt:
                   raise KeyboardInterrupt
                 except Exception, e:
-                    print e
-                    sys.stderr.write("2Problem at path %s\n" % srcpath)
-                    sys.stderr.flush()
+                    self.cInfo['soslog'].error("Problem at path %s (%s)" % (srcpath, e))
 
 
             # Recurse to copy whatever it points to
@@ -172,18 +166,15 @@ class PluginBase:
             except KeyboardInterrupt:
               raise KeyboardInterrupt
             except EnvironmentError, (errno, strerror):
-                print errno
-                print strerror
                 if (errno != 17):
                     # we ignore 'file exists' errors
-                    sys.stderr.write("3Problem at path %s\n" % newpath)
-                    sys.stderr.flush()
+                    self.cInfo['soslog'].error("Problem at path %s ([%d] %s)" % (newpath, errno, strerror))
             
             return abspath
 
         else:
             if not os.path.exists(srcpath):
-                self.cInfo['logfd'].write("File or directory %s does not exist\n" % srcpath)
+                self.cInfo['soslog'].debug("File or directory %s does not exist\n" % srcpath)
             elif  os.path.isdir(srcpath):
                 for afile in os.listdir(srcpath):
                     if afile == '.' or afile == '..':
@@ -203,8 +194,9 @@ class PluginBase:
         try:
             # pylint: disable-msg = W0612
             status, shout, sherr = sosGetCommandOutput("/bin/cp --parents -p " + src +" " + self.cInfo['dstroot'])
-            self.cInfo['logfd'].write(shout)
-            self.cInfo['logfd'].write(sherr)
+            if status:
+                self.cInfo['soslog'].debug(shout)
+                self.cInfo['soslog'].debug(sherr)
             abspath = os.path.join(self.cInfo['dstroot'], src.lstrip(os.path.sep))
             relpath = sosRelPath(self.cInfo['rptdir'], abspath)
             return relpath, abspath
@@ -213,8 +205,7 @@ class PluginBase:
         except KeyboardInterrupt:
           raise KeyboardInterrupt
         except Exception,e:
-            sys.stderr.write("4Problem copying file %s\n" % src,)
-            print e
+            self.cInfo['soslog'].error("Problem copying file %s (%s)" % (src, e))
 
     def addForbiddenPath(self, forbiddenPath):
         """Specify a path to not copy, even if it's part of a copyPaths[] entry.
@@ -281,6 +272,7 @@ class PluginBase:
         """                        
         # First check to make sure the binary exists and is runnable.
         if not os.access(prog.split()[0], os.X_OK):
+            self.cInfo['soslog'].verbose2("Binary '%s' does not exist or is not runnable" % prog.split()[0])
             return
 
         # pylint: disable-msg = W0612
@@ -306,6 +298,7 @@ class PluginBase:
         """
         # First check to make sure the binary exists and is runnable.
         if not os.access(exe.split()[0], os.X_OK):
+            self.cInfo['soslog'].verbose2("Binary '%s' does not exist or is not runnable" % exe.split()[0])
             return
 
         # pylint: disable-msg = W0612
@@ -327,7 +320,7 @@ class PluginBase:
         outfd = open(outfn, "w")
         outfd.write(shout)
         outfd.close()
-        self.cInfo['logfd'].write(sherr)
+        self.cInfo['soslog'].debug(sherr)
         # sosStatus(status)
         # save info for later
         self.executedCommands.append({'exe': exe, 'file':outfn}) # save in our list
@@ -368,6 +361,7 @@ class PluginBase:
         Collect the data for a plugin
         """
         for path in self.copyPaths:
+            self.cInfo['soslog'].debug("copying pathspec %s" % path)
             try:
                 self.doCopyFileOrDir(path)
             except SystemExit:
@@ -375,10 +369,9 @@ class PluginBase:
             except KeyboardInterrupt:
               raise KeyboardInterrupt
             except Exception, e:
-                sys.stderr.write("Error copying from pathspec %s\n" % path,)
-                print e
-                sys.stderr.flush()
+                self.cInfo['soslog'].error("Error copying from pathspec %s (%s)" % (path,e))
         for prog in self.collectProgs:
+            self.cInfo['soslog'].debug("collecting output of '%s'" % prog)
             try:
                 self.collectOutputNow(prog)
             except SystemExit:
@@ -386,8 +379,7 @@ class PluginBase:
             except KeyboardInterrupt:
               raise KeyboardInterrupt
             except:
-                sys.stderr.write("Error collecting output of '%s'\n" % prog,)
-                sys.stderr.flush()
+                self.cInfo['soslog'].error("Error collecting output of '%s'" % prog,)
     
     def collect(self):
         """ This function has been replaced with setup().  Please change your
diff --git a/src/sosreport b/src/sosreport
index 2dfce3d4..894537b8 100755
--- a/src/sosreport
+++ b/src/sosreport
@@ -34,6 +34,7 @@ from sos.helpers import *
 from snack import *
 from threading import Thread, activeCount, enumerate
 import signal
+import logging
 
 __breakHits__ = 0  # Use this to track how many times we enter the exit routine
 
@@ -255,11 +256,23 @@ def sosreport():
     os.mkdir(rptdir, 0755)
 
     # open log file
-    logfd = open(logdir + "/sos.log", "w")
+    logging.basicConfig(level=logging.DEBUG,
+                    format='%(asctime)s %(levelname)s: %(message)s',
+                    filename=logdir + "/sos.log",
+                    filemode='w')
+    # define a Handler which writes INFO messages or higher to the sys.stderr
+    console = logging.StreamHandler()
+    console.setLevel(logging.INFO)
+    console.setFormatter(logging.Formatter('%(message)s'))
+    logging.getLogger('').addHandler(console)
+    logging.addLevelName(17,"verbose")
+    logging.addLevelName(16,"verbose2")
+    logging.addLevelName(15,"verbose3")
+    soslog = logging.getLogger('')
 
     # set up dict so everyone can share the following
     commons = {'dstroot': dstroot, 'cmddir': cmddir, 'logdir': logdir, 'rptdir': rptdir,
-               'logfd': logfd, 'policy': policy, 'verbosity' : __cmdLineOpts__.verbosity}
+               'soslog': soslog, 'policy': policy, 'verbosity' : __cmdLineOpts__.verbosity}
 
 
     # Make policy aware of the commons
@@ -288,27 +301,30 @@ def sosreport():
                     if policy.validatePlugin(pluginpath + plug):
                         pluginClass = importPlugin(pidot, plugbase)
                     else:
-                        print "Plugin %s does not validate, skipping" % plug
+                        soslog.warning("Plugin %s does not validate, skipping" % plug)
                         continue
                     loadedplugins.append((plugbase, pluginClass(plugbase, commons)))
                 except:
-                    print "Plugin %s does not install, skipping" % plug
+                    soslog.warning("Plugin %s does not install, skipping" % plug)
                     raise
             except:
                 if __raisePlugins__:
                     raise
-                print "plugin load failed for %s" % plug
+                soslog.warning("plugin load failed for %s" % plug)
 
     if not len(loadedplugins):
-        print "no valid plugins were enabled"
+        soslog.error("no valid plugins were enabled")
         sys.exit(1)
 
+    soslog.info("Welcome to sosreport (%d plugins loaded)" % (len(loadedplugins)))
+    sys.stdout.write("\n")
+
     # Iterate over plugins for each stage
 
     # First, gather and process options
     for plugname, plug in loadedplugins:
-        if __cmdLineOpts__.verbosity > 3:
-            print "processing options from plugin: %s" % plugname
+        if __cmdLineOpts__.verbosity > 2:
+            soslog.verbose3("processing options from plugin: %s" % plugname)
         try:
             len(__cmdLineOpts__.noplugins)
             if plugname not in __cmdLineOpts__.noplugins:
@@ -327,7 +343,7 @@ def sosreport():
             except "Cancelled":
                 sys.exit("Exiting.")
         else:
-            print "no options available for selected plugins"
+            soslog.info("no options available for selected plugins")
     elif __cmdLineOpts__.fastoptions:
         for i in range(len(alloptions)):
             for plug, plugname, optname, optparm in alloptions:
@@ -345,7 +361,7 @@ def sosreport():
     # Call the setup method for each plugin
     for plugname, plug in loadedplugins:
         if __cmdLineOpts__.verbosity > 1:
-            print "Setting up plugin module %s" % plugname,
+            soslog.verbose2("Setting up plugin module %s" % plugname)
         plug.setup()
         if __cmdLineOpts__.progressbar:
             pbar.incAmount()
@@ -354,7 +370,7 @@ def sosreport():
     # Call the collect method for each plugin
     for plugname, plug in loadedplugins:
         if __cmdLineOpts__.verbosity > 0:
-            print "Executing plugin %s" % plugname
+            soslog.verbose("Executing plugin %s" % plugname)
         if __cmdLineOpts__.multithread:
             plug.doCollect()
         else:
@@ -370,7 +386,7 @@ def sosreport():
     if __cmdLineOpts__.multithread:
         for plugname, plug in loadedplugins:
             if __cmdLineOpts__.verbosity > 1:
-                print "Waiting for plugin %s to return" % plugname,
+                soslog.verbose2("Waiting for plugin %s to return" % plugname)
             plug.wait()
             if __cmdLineOpts__.progressbar:
                 pbar.incAmount(30)
@@ -379,7 +395,7 @@ def sosreport():
     # Call the analyze method for each plugin
     for plugname, plug in loadedplugins:
         if __cmdLineOpts__.verbosity > 1:
-            print "Analyzing results of plugin %s" % plugname,
+            soslog.verbose2("Analyzing results of plugin %s" % plugname,)
         plug.analyze()
         if __cmdLineOpts__.progressbar:
             pbar.incAmount()
@@ -387,6 +403,7 @@ def sosreport():
 
     if __cmdLineOpts__.progressbar:
         pbar.finished()
+        sys.stdout.write("\n")
 
     # Sort the module names to do the report in alphabetical order
     loadedplugins.sort()
@@ -447,22 +464,22 @@ def sosreport():
 
     # Collect any needed user information (name, etc)
 
-    # Close all log files and perform any cleanup
-    logfd.close()
-
     # Call the postproc method for each plugin
     for plugname, plug in loadedplugins:
         plug.postproc()
   
     if __cmdLineOpts__.gatheronly:
-        print "Collected information is in " + dstroot
-        print "Your html report is in " + rptdir + "/" + "sosreport.html"
+        soslog.info("Collected information is in " + dstroot)
+        soslog.info("Your html report is in " + rptdir + "/" + "sosreport.html")
     else:
         # package up the results for the support organization
         policy.packageResults()
         # delete gathered files
         os.system("rm -rf %s" % dstroot)
         # automated submission will go here
+
+    # Close all log files and perform any cleanup
+    logging.shutdown()
  
     
 if __name__ == '__main__':