Fix blocking bug of tar's output

[sitarba.git] / shbackup

diff --git a/shbackup b/shbackup
index da28afecb1c8532307a7c795b29bf63be63ee2a1..d5b8b812073f75208576f3b80e2465d0d3757ff1 100755 (executable)
--- a/shbackup
+++ b/shbackup
@@ -8,7 +8,7 @@ import datetime
 import os, shutil, sys
 import configparser
 import hashlib
-import subprocess
+import subprocess, fcntl
 import random, re
 import logging
 
@@ -255,9 +255,9 @@ class BackupManager:
     def backupFileSet(self, fileset, targetdir, since=None):
         """Create an archive for given fileset at given target directory."""
 
-        logger = logging.getLogger('backup')
+        logfile = logging.getLogger('backuplog')
+        logfile.info("Running file set: " + fileset.name)
 
-        logger.info("Running file set: " + fileset.name)
         tarpath = "/bin/tar"
         fsfn = os.path.join(targetdir, fileset.name) + "." + self.conf.format
 
@@ -269,27 +269,47 @@ class BackupManager:
         for pat in self.conf.exclpatterns:
             taropts += ["--exclude", pat]
 
+        # Launch the tar process
         tarargs = [tarpath] + taropts + ["-f", fsfn] + fileset.dirs
-        logger.debug("tar call: " + " ".join(tarargs))
+        logfile.debug("tar call: " + " ".join(tarargs))
         tarp = subprocess.Popen( tarargs, bufsize=-1, \
                 stdout=subprocess.PIPE, stderr=subprocess.PIPE )
 
-        # Output stdout of tar
+        # 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 = tarp.stdout.readline()
-            if l != "":
-                logging.debug(l.decode().rstrip())
+            l = readlineNonBlocking(tarp.stdout)
+            if l != b"":
+                logging.debug(l[:-1].decode())
+            errmsg += readlineNonBlocking(tarp.stderr)
+
 
-        # Output remaining output of tar
+        # 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:
-            for l in tarp.stderr.readlines():
-                logger.error( l.decode().strip().rstrip() )
-            sys.stderr.write( tarp.stderr.read().decode() )
-            logger.error(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):
@@ -345,17 +365,19 @@ class BackupManager:
         os.mkdir( targetdir )
 
 
-        logger = logging.getLogger('backup')
-        ch = logging.FileHandler( os.path.join(targetdir, "log") )
-        ch.setLevel(logging.INFO)
-        logger.addHandler(ch)
-        logger.info("Started: " + now.ctime())
+        # 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)
 
-        logger.info("Stopped: " + datetime.datetime.now().ctime())
+        logfile.info("Stopped: " + datetime.datetime.now().ctime())
 
         # Rename backup directory to final name
         os.rename( targetdir, os.path.join(basedir, dirname) )
@@ -413,10 +435,14 @@ class BackupManager:
         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 logging.getLogger().isEnabledFor(logging.INFO):
+        if LogConf.con.level <= logging.INFO:
             return input(question)
         else:
             return "y"
@@ -445,13 +471,33 @@ def printUsage():
     print("  -m, --mode <mode>          override mode: full, diff, or incr")
     print("  -v, --verbose              be more verbose and interact with user")
     print("  --verbosity LEVEL          set verbosity to LEVEL, which can be")
-    print("                             warning, info, debug")
+    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__":
 
-    logging.basicConfig(format='%(message)s')
+    LogConf.setup()
+
     conffn = "/etc/shbackup.conf"
     cmd = "list"
     mode = None
@@ -475,7 +521,7 @@ if __name__ == "__main__":
             exit(0)
 
         elif opt in ["-v", "--verbose"]:
-            logging.getLogger().setLevel(logging.INFO)
+            LogConf.con.setLevel(logging.INFO)
 
         elif opt in ["--verbosity"]:
             i += 1
@@ -483,7 +529,7 @@ if __name__ == "__main__":
             numlevel = getattr(logging, level.upper(), None)
             if not isinstance(numlevel, int):
                 raise ValueError('Invalid verbosity level: %s' % level)
-            logging.getLogger().setLevel(numlevel)
+            LogConf.con.setLevel(numlevel)
 
         elif opt in ["-m", "--mode"]:
             i += 1