Introduce generic logging infrastructure
[time-slider.git] / usr / share / time-slider / lib / time_slider / timesliderd.py
index 99f802a..1ff89bb 100755 (executable)
@@ -32,6 +32,8 @@ import datetime
 import calendar
 import signal
 import argparse
+import logging
+from logging.handlers import SysLogHandler
 
 import glib
 import gobject
@@ -45,7 +47,7 @@ import zfs
 import smf
 import time_slider.linux.timeslidersmf as timeslidersmf
 import time_slider.linux.autosnapsmf as autosnapsmf
-import plugin
+import plugin
 from time_slider.linux.rbac import RBACprofile
 import util
 
@@ -85,6 +87,7 @@ class SnapshotManager(threading.Thread):
         self._zpools = []
         self._poolstatus = {}
         self._destroyedsnaps = []
+        self.logger = logging.getLogger('time-slider')
 
         # This is also checked during the refresh() method but we need
         # to know it sooner for instantiation of the PluginManager
@@ -92,14 +95,14 @@ class SnapshotManager(threading.Thread):
         try:
             self.verbose = self._smf.get_verbose()
         except RuntimeError,message:
-            sys.stderr.write("Error determing whether debugging is enabled\n")
+            self.logger.error("Error determing whether debugging is enabled")
             self.verbose = False
 
         self._dbus = dbussvc.AutoSnap(bus,
                                       '/org/opensolaris/TimeSlider/autosnap',
                                       self)
 
-        self._plugin = plugin.PluginManager(self.verbose)
+        self._plugin = plugin.PluginManager(self.verbose)
         self.exitCode = smf.SMF_EXIT_OK
         self.refresh()
 
@@ -169,22 +172,22 @@ class SnapshotManager(threading.Thread):
                     self._conditionLock.wait(_MINUTE * 15)
 
             except OSError, message:
-                sys.stderr.write("Caught OSError exception in snapshot" +
-                                 " manager thread\n")
-                sys.stderr.write("Error details:\n" + \
+                self.logger.error("Caught OSError exception in snapshot" +
+                                 " manager thread")
+                self.logger.error("Error details:\n" + \
                                  "--------BEGIN ERROR MESSAGE--------\n" + \
                                  str(message) + \
-                                 "\n--------END ERROR MESSAGE--------\n")
+                                 "\n--------END ERROR MESSAGE--------")
                 self.exitCode = smf.SMF_EXIT_ERR_FATAL
                 # Exit this thread
                 break
             except RuntimeError,message:
-                sys.stderr.write("Caught RuntimeError exception in snapshot" +
-                                 " manager thread\n")
-                sys.stderr.write("Error details:\n" + \
+                self.logger.error("Caught RuntimeError exception in snapshot" +
+                                 " manager thread")
+                self.logger.error("Error details:\n" + \
                                  "--------BEGIN ERROR MESSAGE--------\n" + \
                                  str(message) + \
-                                 "\n--------END ERROR MESSAGE--------\n")
+                                 "\n--------END ERROR MESSAGE--------")
                 # Exit this thread
                 break
 
@@ -208,7 +211,7 @@ class SnapshotManager(threading.Thread):
             self._configure_svc_props()
             self._rebuild_schedules()
             self._update_schedules()
-            self._plugin.refresh()
+            self._plugin.refresh()
             self._stale = False
         self._refreshLock.release()
 
@@ -216,7 +219,7 @@ class SnapshotManager(threading.Thread):
         try:
             self.verbose = self._smf.get_verbose()
         except RuntimeError,message:
-            sys.stderr.write("Error determing whether debugging is enabled\n")
+            self.logger.error("Error determing whether debugging is enabled")
             self.verbose = False
 
         try:
@@ -228,12 +231,12 @@ class SnapshotManager(threading.Thread):
             emer = self._smf.get_cleanup_level("emergency")
             util.debug("Emergency level value is: %d%%" % emer, self.verbose)
         except RuntimeError,message:
-            sys.stderr.write("Failed to determine cleanup threshhold levels\n")
-            sys.stderr.write("Details:\n" + \
+            self.logger.error("Failed to determine cleanup threshhold levels")
+            self.logger.error("Details:\n" + \
                              "--------BEGIN ERROR MESSAGE--------\n" + \
                              str(message) + \
                              "\n---------END ERROR MESSAGE---------\n")
-            sys.stderr.write("Using factory defaults of 80%, 90% and 95%\n")
+            self.logger.error("Using factory defaults of 80%, 90% and 95%")
             #Go with defaults
             #FIXME - this would be an appropriate case to mark svc as degraded
             self._remedialCleanup = True
@@ -250,12 +253,12 @@ class SnapshotManager(threading.Thread):
             self._keepEmpties = self._smf.get_keep_empties()
         except RuntimeError,message:
             # Not fatal, just assume we delete them (default configuration)
-            sys.stderr.write("Can't determine whether to keep empty snapshots\n")
-            sys.stderr.write("Details:\n" + \
+            self.logger.error("Can't determine whether to keep empty snapshots")
+            self.logger.error("Details:\n" + \
                              "--------BEGIN ERROR MESSAGE--------\n" + \
                              str(message) + \
-                             "\n---------END ERROR MESSAGE---------\n")
-            sys.stderr.write("Assuming default value: False\n")
+                             "\n---------END ERROR MESSAGE---------")
+            self.logger.error("Assuming default value: False")
             self._keepEmpties = False
 
         # Previously, snapshot labels used the ":" character was used as a 
@@ -282,7 +285,7 @@ class SnapshotManager(threading.Thread):
                     self._zpools.append(zpool)
                 util.debug(str(zpool), self.verbose)
         except RuntimeError,message:
-            sys.stderr.write("Could not list Zpools\n")
+            self.logger.error("Could not list Zpools")
             self.exitCode = smf.SMF_EXIT_ERR_FATAL
             # Propogate exception up to thread's run() method
             raise RuntimeError,message
@@ -343,7 +346,7 @@ class SnapshotManager(threading.Thread):
                                                           schedule))
                 except RuntimeError,message:
                     self.exitCode = smf.SMF_EXIT_ERR_FATAL
-                    sys.stderr.write("Failed to list snapshots during schedule update\n")
+                    self.logger.error("Failed to list snapshots during schedule update")
                     #Propogate up to the thread's run() method
                     raise RuntimeError,message
 
@@ -361,9 +364,9 @@ class SnapshotManager(threading.Thread):
                     totalinterval = intervals[interval] * period
                 except KeyError:
                     self.exitCode = smf.SMF_EXIT_ERR_CONFIG
-                    sys.stderr.write(schedule + \
+                    self.logger.error(schedule + \
                                       " schedule has invalid interval: " + \
-                                      "'%s\'\n" % interval)
+                                      "'%s\'" % interval)
                     #Propogate up to thread's run() method
                     raise RuntimeError
                 if [schedule,interval,period,keep] in self._defaultSchedules:
@@ -451,7 +454,7 @@ class SnapshotManager(threading.Thread):
         now = long(time.time())
         while next != None and next <= now:
             label = self._take_snapshots(schedule)
-            self._plugin.execute_plugins(schedule, label)
+            self._plugin.execute_plugins(schedule, label)
             self._refreshLock.acquire()
             self._update_schedules()
             next,schedule = self._next_due();
@@ -474,7 +477,7 @@ class SnapshotManager(threading.Thread):
         except RuntimeError, message:
             # Write an error message, set the exit code and pass it up the
             # stack so the thread can terminate
-            sys.stderr.write("Failed to create snapshots for schedule: %s\n" \
+            self.logger.error("Failed to create snapshots for schedule: %s" \
                              % (schedule))
             self.exitCode = smf.SMF_EXIT_MON_DEGRADE
             raise RuntimeError,message
@@ -508,7 +511,7 @@ class SnapshotManager(threading.Thread):
             # while iterating through it.
             remainingsnaps = snaps[:]
         except RuntimeError,message:
-            sys.stderr.write("Failed to list snapshots during snapshot cleanup\n")
+            self.logger.error("Failed to list snapshots during snapshot cleanup")
             self.exitCode = smf.SMF_EXIT_ERR_FATAL
             raise RuntimeError,message
 
@@ -521,7 +524,7 @@ class SnapshotManager(threading.Thread):
                 try:
                     snapshot = zfs.Snapshot(snapname)
                 except Exception,message:
-                    sys.stderr.write(str(message))
+                    self.logger.error(str(message))
                     # Not fatal, just skip to the next snapshot
                     continue
 
@@ -532,15 +535,15 @@ class SnapshotManager(threading.Thread):
                         try:
                             snapshot.destroy()
                         except RuntimeError,message:
-                            sys.stderr.write("Failed to destroy snapshot: " +
-                                             snapname + "\n")
+                            self.logger.error("Failed to destroy snapshot: " +
+                                             snapname)
                             self.exitCode = smf.SMF_EXIT_MON_DEGRADE
                             # Propogate exception so thread can exit
                             raise RuntimeError,message
                         remainingsnaps.remove(snapname)
                 except RuntimeError,message:
-                    sys.stderr.write("Can not determine used size of: " + \
-                                     snapname + "\n")
+                    self.logger.error("Can not determine used size of: " + \
+                                     snapname)
                     self.exitCode = smf.SMF_EXIT_MON_DEGRADE
                     #Propogate the exception to the thead run() method
                     raise RuntimeError,message
@@ -558,15 +561,15 @@ class SnapshotManager(threading.Thread):
             try:
                 snapshot = zfs.Snapshot(remainingsnaps[counter])
             except Exception,message:
-                    sys.stderr.write(str(message))
+                    self.logger.error(str(message))
                     # Not fatal, just skip to the next snapshot
                     counter += 1
                     continue
             try:
                 snapshot.destroy()
             except RuntimeError,message:
-                sys.stderr.write("Failed to destroy snapshot: " +
-                                 snapshot.name + "\n")
+                self.logger.error("Failed to destroy snapshot: " +
+                                 snapshot.name)
                 self.exitCode = smf.SMF_EXIT_ERR_FATAL
                 # Propogate exception so thread can exit
                 raise RuntimeError,message
@@ -584,8 +587,8 @@ class SnapshotManager(threading.Thread):
                 dataset = zfs.ReadWritableDataset(name)
                 self._prune_snapshots(dataset, schedule)
         except RuntimeError,message:
-            sys.stderr.write("Error listing datasets during " + \
-                             "removal of expired snapshots\n")
+            self.logger.error("Error listing datasets during " + \
+                             "removal of expired snapshots")
             self.exitCode = smf.SMF_EXIT_ERR_FATAL
             # Propogate up to thread's run() method
             raise RuntimeError,message
@@ -623,8 +626,8 @@ class SnapshotManager(threading.Thread):
                                 self._cleanupLock.release()
                                 return True
                 except RuntimeError, message:
-                    sys.stderr.write("Error checking zpool capacity of: " + \
-                                     zpool.name + "\n")
+                    self.logger.error("Error checking zpool capacity of: " + \
+                                     zpool.name)
                     self._cleanupLock.release()
                     self.exitCode = smf.SMF_EXIT_ERR_FATAL
                     # Propogate up to thread's run() mehod.
@@ -660,9 +663,9 @@ class SnapshotManager(threading.Thread):
             # This also catches exceptions thrown from _run_<level>_cleanup()
             # and _run_cleanup() in methods called by _perform_cleanup()
             except RuntimeError,message:
-                sys.stderr.write("Remedial space cleanup failed because " + \
+                self.logger.error("Remedial space cleanup failed because " + \
                                  "of failure to determinecapacity of: " + \
-                                 zpool.name + "\n")
+                                 zpool.name)
                 self.exitCode = smf.SMF_EXIT_ERR_FATAL
                 self._cleanupLock.release()
                 # Propogate up to thread's run() method.
@@ -683,7 +686,7 @@ class SnapshotManager(threading.Thread):
         # Avoid needless list iteration for non-debug mode
         if self.verbose == True and len(self._destroyedsnaps) > 0:
             for snap in self._destroyedsnaps:
-                sys.stderr.write("\t%s\n" % snap)
+                self.logger.error("\t%s" % snap)
         self._cleanupLock.release()
 
     def _run_warning_cleanup(self, zpool):
@@ -730,12 +733,12 @@ class SnapshotManager(threading.Thread):
         try:
             clonedsnaps = self._datasets.list_cloned_snapshots()
         except RuntimeError,message:
-                sys.stderr.write("Error (non-fatal) listing cloned snapshots" +
-                                 " while recovering pool capacity\n")
-                sys.stderr.write("Error details:\n" + \
+                self.logger.error("Error (non-fatal) listing cloned snapshots" +
+                                 " while recovering pool capacity")
+                self.logger.error("Error details:\n" + \
                                  "--------BEGIN ERROR MESSAGE--------\n" + \
                                  str(message) + \
-                                 "\n--------END ERROR MESSAGE--------\n")    
+                                 "\n--------END ERROR MESSAGE--------")    
 
         # Build a list of snapshots in the given schedule, that are not
         # cloned, and sort the result in reverse chronological order.
@@ -746,15 +749,15 @@ class SnapshotManager(threading.Thread):
                             if not s in clonedsnaps]
             snapshots.reverse()
         except RuntimeError,message:
-            sys.stderr.write("Error listing snapshots" +
-                             " while recovering pool capacity\n")
+            self.logger.error("Error listing snapshots" +
+                             " while recovering pool capacity")
             self.exitCode = smf.SMF_EXIT_ERR_FATAL
             # Propogate the error up to the thread's run() method.
             raise RuntimeError,message
    
         while zpool.get_capacity() > threshold:
             if len(snapshots) == 0:
-                syslog.syslog(syslog.LOG_NOTICE,
+                self.logger.info( \
                               "No more %s snapshots left" \
                                % schedule)
                 return
@@ -791,9 +794,9 @@ class SnapshotManager(threading.Thread):
                 # Would be nice to be able to mark service as degraded here
                 # but it's better to try to continue on rather than to give
                 # up alltogether (SMF maintenance state)
-                sys.stderr.write("Warning: Cleanup failed to destroy: %s\n" % \
+                self.logger.error("Warning: Cleanup failed to destroy: %s" % \
                                  (snapshot.name))
-                sys.stderr.write("Details:\n%s\n" % (str(message)))
+                self.logger.error("Details:\n%s" % (str(message)))
             else:
                 self._destroyedsnaps.append(snapname)
             # Give zfs some time to recalculate.
@@ -803,28 +806,27 @@ class SnapshotManager(threading.Thread):
         for zpool in self._zpools:
             status = self._poolstatus[zpool.name]
             if status == 4:
-                syslog.syslog(syslog.LOG_EMERG,
-                              "%s is over %d%% capacity. " \
+                self.logger.critical( \
                               "All automatic snapshots were destroyed" \
                                % (zpool.name, self._emergencyLevel))
             elif status == 3:
-                syslog.syslog(syslog.LOG_ALERT,
+                self.logger.error( \
                               "%s exceeded %d%% capacity. " \
                               "Automatic snapshots over 1 hour old were destroyed" \
                                % (zpool.name, self._emergencyLevel))
             elif status == 2:
-                syslog.syslog(syslog.LOG_CRIT,
+                self.logger.critical( \
                               "%s exceeded %d%% capacity. " \
                               "Weekly, hourly and daily automatic snapshots were destroyed" \
                                % (zpool.name, self._criticalLevel))                             
             elif status == 1:
-                syslog.syslog(syslog.LOG_WARNING,
+                self.logger.warning( \
                               "%s exceeded %d%% capacity. " \
                               "Hourly and daily automatic snapshots were destroyed" \
                                % (zpool.name, self._warningLevel))
 
         if len(self._destroyedsnaps) > 0:
-            syslog.syslog(syslog.LOG_NOTICE,
+            self.logger.warning( \
                           "%d automatic snapshots were destroyed" \
                            % len(self._destroyedsnaps))
 
@@ -852,10 +854,11 @@ class SnapshotManager(threading.Thread):
 
 
 def monitor_threads(snapthread):
+    logger = logging.getLogger('time-slider')
     if snapthread.is_alive():
         return True
     else:
-        sys.stderr.write("Snapshot monitor thread exited.\n")
+        logger.error("Snapshot monitor thread exited.")
         if snapthread.exitCode == smf.SMF_EXIT_MON_DEGRADE:
             # FIXME - it would be nicer to mark the service as degraded than
             # go into maintenance state for some situations such as a
@@ -878,8 +881,8 @@ def monitor_threads(snapthread):
             sys.exit(smf.SMF_EXIT_ERR_FATAL)
             return False
         else:
-            sys.stderr.write("Snapshot monitor thread exited abnormally\n")
-            sys.stderr.write("Exit code: %d\n" % (snapthread.exitCode))
+            logger.error("Snapshot monitor thread exited abnormally")
+            logger.error("Exit code: %d" % (snapthread.exitCode))
             #subprocess.call(["/usr/sbin/svcadm", "mark", "maintenance",
             #                 os.getenv("SMF_FMRI")])
             sys.exit(smf.SMF_EXIT_ERR_FATAL)
@@ -934,8 +937,23 @@ def main(argv):
     parser = argparse.ArgumentParser()
     parser.add_argument('--foreground', action='store_true', help='Do not daemonize', default=False)
     parser.add_argument('--config', '-c', type=str, help='Configuration file', default='/etc/time-slider/timesliderd.conf')
+    parser.add_argument('--configdump', action='store_true', help='Dump default values in config file format', default=False)
     args, _ = parser.parse_known_args()
 
+    logger = logging.getLogger('time-slider')
+    logger.setLevel(logging.DEBUG)
+    if args.foreground:
+        handler = logging.StreamHandler()
+    else:
+        handler = SysLogHandler(address='/dev/log')
+    handler.setLevel(logging.DEBUG)
+    handler.setFormatter(logging.Formatter('%(asctime)s %(levelname)s: %(message)s', '%b %d %H:%M:%S time-sliderd:'))
+    logger.addHandler(handler)
+
+    if args.configdump:
+        timesliderconfig.configdump()
+        sys.exit(smf.SMF_EXIT_OK)
+
     timesliderconfig.configfile = args.config
 
     # Daemonise the service.
@@ -945,7 +963,6 @@ def main(argv):
     # The user security attributes checked are the following:
     # Note that UID == 0 will match any profile search so
     # no need to check it explicitly.
-    syslog.openlog("time-sliderd", 0, syslog.LOG_DAEMON)
     rbacp = RBACprofile()
     if rbacp.has_profile("ZFS File System Management"):
 
@@ -971,11 +988,9 @@ def main(argv):
             mainloop.quit()
             sys.exit(smf.SMF_EXIT_OK)
     else:
-        syslog.syslog(syslog.LOG_ERR,
+        logger.error( \
                "%s has insufficient privileges to run time-sliderd!" \
                % rbacp.name)
-        syslog.closelog()    
         sys.exit(smf.SMF_EXIT_ERR_PERM)
-    syslog.closelog()
     sys.exit(smf.SMF_EXIT_OK)