Fix blocking bug of tar's output
[sitarba.git] / shbackup
index 17bd3318208b8ce01e6363c68a628e15a80a55a7..d5b8b812073f75208576f3b80e2465d0d3757ff1 100755 (executable)
--- a/shbackup
+++ b/shbackup
@@ -1,12 +1,16 @@
 #!/usr/bin/python3
 """Stefan Huber's simplistic backup solution."""
 
+__version__ = "0.1"
+__author__ = "Stefan Huber"
+
 import datetime
 import os, shutil, sys
 import configparser
 import hashlib
-import subprocess
+import subprocess, fcntl
 import random, re
+import logging
 
 
 Mode = ["full", "incr", "diff"]
@@ -195,9 +199,8 @@ class Config:
 class BackupManager:
     """List and create backups"""
 
-    def __init__(self, conffn, alwaysyes):
+    def __init__(self, conffn):
         self.conf = Config()
-        self.alwaysyes = alwaysyes
         self.conf.read(conffn)
 
 
@@ -252,7 +255,9 @@ class BackupManager:
     def backupFileSet(self, fileset, targetdir, since=None):
         """Create an archive for given fileset at given target directory."""
 
-        print("Running file set: " + fileset.name)
+        logfile = logging.getLogger('backuplog')
+        logfile.info("Running file set: " + fileset.name)
+
         tarpath = "/bin/tar"
         fsfn = os.path.join(targetdir, fileset.name) + "." + self.conf.format
 
@@ -264,13 +269,47 @@ class BackupManager:
         for pat in self.conf.exclpatterns:
             taropts += ["--exclude", pat]
 
+        # Launch the tar process
         tarargs = [tarpath] + taropts + ["-f", fsfn] + fileset.dirs
-        #print("tarargs: ", tarargs)
-        tarp = subprocess.Popen( tarargs )
-
+        logfile.debug("tar call: " + " ".join(tarargs))
+        tarp = subprocess.Popen( tarargs, bufsize=-1, \
+                stdout=subprocess.PIPE, stderr=subprocess.PIPE )
+
+        # Change tarp's stdout and stderr to non-blocking
+        for s in [tarp.stdout, tarp.stderr]:
+            fd = s.fileno()
+            fl = fcntl.fcntl(fd, fcntl.F_GETFL)
+            fcntl.fcntl(fd, fcntl.F_SETFL, fl | os.O_NONBLOCK)
+
+        def readlineNonBlocking(stream):
+            """Read a line nonblocking. Returns b'' if nothing read."""
+            try:
+                return stream.readline()
+            except:
+                return b''
+                pass
+
+
+        # Read stdout and stderr of tarp
+        errmsg = b""
+        while tarp.poll() == None:
+            l = readlineNonBlocking(tarp.stdout)
+            if l != b"":
+                logging.debug(l[:-1].decode())
+            errmsg += readlineNonBlocking(tarp.stderr)
+
+
+        # Get the remainging output of tarp
+        for l in tarp.stdout.readlines():
+            logging.debug(l.decode().rstrip())
+        errmsg += tarp.stderr.read()
+
+        # Get return code of tarp
         rett = tarp.wait()
         if rett != 0:
-            print(tarpath + " returned with exit status " + str(rett) + ":")
+            for l in errmsg.split("\n"):
+                logfile.error( l.decode().strip().rstrip() )
+            logfile.error(tarpath + " returned with exit status " + str(rett) + ".")
 
 
     def backup(self, epoch=None, mode=None):
@@ -285,25 +324,23 @@ class BackupManager:
         if epoch == None:
             epoch = self.getDesiredEpoch(oldbackups, now)
         if epoch == None:
-            print("No backup planned.")
+            logging.info("No backup planned.")
             return
 
         # Get mode of backup
         if mode == None:
             mode = self.conf.epochmodes[epoch]
-        print("Making a backup. Epoch: " + epoch + ", mode: " + mode)
+        logging.info("Making a backup. Epoch: " + epoch + ", mode: " + mode)
 
         oldfullbackups = [ b for b in oldbackups if b.mode == "full" ]
 
         # No old full backups existing
         if mode != "full" and len(oldfullbackups)==0:
-            print("No full backups existing. Making a full backup.")
+            logging.info("No full backups existing. Making a full backup.")
 
         # Checksum changed -> self.config file changed
-        if self.conf.checksum != self.conf.lastchecksum:
-            print("Config file changed since last time.")
-            if mode != "full":
-                print("** Warning: full backup recommended!")
+        if self.conf.checksum != self.conf.lastchecksum and mode != "full":
+            logging.warning("Full backup recommended as config file has changed.")
 
 
         # If we have a full backup, we backup everything
@@ -314,7 +351,7 @@ class BackupManager:
             since = sorted(oldbackups, key=lambda b: b.date)[-1].date
 
         if since != None:
-            print("Making backup relative to ", since.ctime())
+            logging.debug("Making backup relative to " + since.ctime())
 
         yesno = self.ask_user_yesno("Proceed? [Y, n] ")
         if yesno == "n":
@@ -328,10 +365,20 @@ class BackupManager:
         os.mkdir( targetdir )
 
 
+        # Add file logger
+        logfile = logging.getLogger("backuplog")
+        fil = logging.FileHandler( os.path.join(targetdir, "log") )
+        fil.setLevel(logging.DEBUG)
+        logfile.addHandler(fil)
+
+        logfile.info("Started: " + now.ctime())
+
         # Backup all file sets
         for s in self.conf.sets:
             self.backupFileSet(s, targetdir, since)
 
+        logfile.info("Stopped: " + datetime.datetime.now().ctime())
+
         # Rename backup directory to final name
         os.rename( targetdir, os.path.join(basedir, dirname) )
 
@@ -342,10 +389,11 @@ class BackupManager:
             f.close()
 
 
+
     def prune(self):
         """Prune old backup files"""
 
-        allDirs = self.listAllDirs()
+        allDirs = sorted(self.listAllDirs())
         # Collect all directories not matching backup name
         removeDirs = [ d for d in allDirs if not Backup.isBackupDir(d) ]
 
@@ -360,38 +408,44 @@ class BackupManager:
             removeDirs += [ Backup.getDirName(b.date, b.epoch, b.mode) for b in old]
 
 
-        print("List of stale/outdated entries:")
+        logging.info("List of stale/outdated entries:")
         for d in allDirs:
+            msg = ""
             if d in removeDirs:
-                print("[*]  ", end="")
+                msg = "[*]  "
             else:
-                print("[ ]  ", end="")
+                msg = "[ ]  "
 
             if Backup.isBackupDir(d):
-                print( Backup.fromDirName(d).colAlignedString())
+                msg += Backup.fromDirName(d).colAlignedString()
             else:
-                print(d)
+                msg += d
+
+            logging.info(msg)
 
         # Check that dirs to be removed is in list of all dirs
         for d in removeDirs:
             assert( d in allDirs )
 
         if len(removeDirs) == 0:
-            print("No stale/outdated entries to remove.")
+            logging.info("No stale/outdated entries to remove.")
             return
 
         basedir = self.conf.directory
         yesno = self.ask_user_yesno("Remove entries marked by '*'? [y, N] ")
         if yesno == "y":
             for d in removeDirs:
-                shutil.rmtree(os.path.join(basedir, d))
+                try:
+                    shutil.rmtree(os.path.join(basedir, d))
+                except OSError as e:
+                    logging.error("Error when removing '%s': %s" % (d,e.strerror) )
+
 
     def ask_user_yesno(self, question):
-        if self.alwaysyes:
-            print(question + " y")
-            return "y"
-        else:
+        if LogConf.con.level <= logging.INFO:
             return input(question)
+        else:
+            return "y"
 
 
 def printUsage():
@@ -415,16 +469,39 @@ def printUsage():
     print("  -e, --epoch <epoch>        force to create backup for given epoch:")
     print("                             year, month, week, day, hour, sporadic")
     print("  -m, --mode <mode>          override mode: full, diff, or incr")
-    print("  -y, --yes                  always assume 'yes' when user is asked")
+    print("  -v, --verbose              be more verbose and interact with user")
+    print("  --verbosity LEVEL          set verbosity to LEVEL, which can be")
+    print("                             error, warning, info, debug")
+    print("  -V, --version              print version info")
+
+
+
+class LogConf:
+    """Encapsulates logging configuration"""
+
+    con = logging.StreamHandler(sys.stderr)
+
+    @classmethod
+    def setup(cls):
+        """Setup logging system"""
+        conlog = logging.getLogger()
+        conlog.setLevel(logging.DEBUG)
+
+        cls.con.setLevel(logging.WARNING)
+        conlog.addHandler(cls.con)
+
+        fillog = logging.getLogger("backuplog")
+        fillog.setLevel(logging.DEBUG)
 
 
 if __name__ == "__main__":
 
+    LogConf.setup()
+
     conffn = "/etc/shbackup.conf"
     cmd = "list"
     mode = None
     epoch = None
-    yes = False
 
     i = 0
     while i < len(sys.argv)-1:
@@ -439,21 +516,33 @@ if __name__ == "__main__":
             i += 1
             conffn = sys.argv[i]
 
-        elif opt in ["-y", "--yes"]:
-            yes = True
+        elif opt in ["-V", "--version"]:
+            print("shbackup " + __version__)
+            exit(0)
+
+        elif opt in ["-v", "--verbose"]:
+            LogConf.con.setLevel(logging.INFO)
+
+        elif opt in ["--verbosity"]:
+            i += 1
+            level = sys.argv[i]
+            numlevel = getattr(logging, level.upper(), None)
+            if not isinstance(numlevel, int):
+                raise ValueError('Invalid verbosity level: %s' % level)
+            LogConf.con.setLevel(numlevel)
 
         elif opt in ["-m", "--mode"]:
             i += 1
             mode = sys.argv[i]
             if not mode in Mode:
-                print("Unknown mode '" + mode + "'.")
+                logging.error("Unknown mode '" + mode + "'.")
                 exit(1)
 
         elif opt in ["-e", "--epoch"]:
             i += 1
             epoch = sys.argv[i]
             if not epoch in Epoch:
-                print("Unknown epoch '" + epoch + "'.")
+                logging.error("Unknown epoch '" + epoch + "'.")
                 exit(1)
 
 
@@ -461,11 +550,11 @@ if __name__ == "__main__":
             cmd = opt
 
         else:
-            print("Unknown option: " + opt)
+            logging.error("Unknown option: " + opt)
             exit(1)
 
     try:
-        man = BackupManager(conffn, yes)
+        man = BackupManager(conffn)
 
         if cmd == "backup":
             man.backup(epoch, mode)
@@ -478,7 +567,7 @@ if __name__ == "__main__":
             man.prune()
 
     except (Config.ReadError, configparser.DuplicateOptionError) as e:
-        print("Error reading config file: " + e.message)
+        logging.error("Error reading config file: " + e.message)