Use tqdm logging_redirect_tqdm to not break progress bars (#294)

Author: abbbi

Changelog

@@ -2,7 +2,8 @@ Version 2.41
 ---------
  * Disable building rust bindings when creating venv (#293)
  * Small code cleanups
-
+ * Use tqdm logging_redirect_tqdm to not break progress bars (#294) 
+
 Version 2.40
 ---------
  * Add OpenSUSE 16 to build scripts

libvirtnbdbackup/backup/disk.py

@@ -52,7 +52,7 @@ def _getExtentHandler(args: Namespace, nbdClient):
     """Query dirty blocks either via qemu client or self
     implemented extend handler"""
     if args.qemu:
-        logging.info("Using qemu tools to query extents")
+        lib.safeInfo("Using qemu tools to query extents")
         extentHandler = extenthandler.ExtentHandler(
             qemu.util(nbdClient.cType.exportName),
             nbdClient.cType,
@@ -94,7 +94,7 @@ def backup(  # pylint: disable=too-many-arguments,too-many-branches, too-many-lo
             raise exceptions.DiskBackupFailed("Failed to start NBD server.")
 
     if disk.discardOption is not None:
-        logging.info("Virtual disk discard option: [%s]", disk.discardOption)
+        lib.safeInfo("Virtual disk discard option: [%s]", disk.discardOption)
 
     connection = server.connect(args, disk, metaContext, remoteIP, port, virtClient)
 
@@ -107,17 +107,17 @@ def backup(  # pylint: disable=too-many-arguments,too-many-branches, too-many-lo
         return 0, False
 
     thinBackupSize = sum(extent.length for extent in extents if extent.data is True)
-    logging.info("Got %s extents to backup.", len(extents))
+    lib.safeInfo("Got %s extents to backup.", len(extents))
     logging.debug("%s", lib.dumpExtentJson(extents))
-    logging.info("%s bytes [%s] virtual disk size", diskSize, lib.humanize(diskSize))
-    logging.info(
+    lib.safeInfo("%s bytes [%s] virtual disk size", diskSize, lib.humanize(diskSize))
+    lib.safeInfo(
         "%s bytes [%s] of data extents to backup",
         thinBackupSize,
         lib.humanize(thinBackupSize),
     )
 
     if args.level in ("inc", "diff") and thinBackupSize == 0:
-        logging.info("No dirty blocks found")
+        lib.safeInfo("No dirty blocks found")
         args.noprogress = True
 
     targetFile, targetFilePartial = target.Set(args, disk)
@@ -132,10 +132,10 @@ def backup(  # pylint: disable=too-many-arguments,too-many-branches, too-many-lo
     writer = target.get(args, fileStream, targetFile, targetFilePartial)
 
     if streamType == "raw":
-        logging.info("Creating full provisioned raw backup image")
+        lib.safeInfo("Creating full provisioned raw backup image")
         writer.truncate(diskSize)
     else:
-        logging.info("Creating thin provisioned stream backup image")
+        lib.safeInfo("Creating thin provisioned stream backup image")
         header = dStream.dumpMetadata(
             args,
             diskSize,
@@ -213,15 +213,15 @@ def backup(  # pylint: disable=too-many-arguments,too-many-branches, too-many-lo
     connection.disconnect()
 
     if args.offline is True and virtClient.remoteHost == "":
-        logging.info("Stopping NBD Service.")
+        lib.safeInfo("Stopping NBD Service.")
         lib.killProc(nbdProc.pid)
 
     if args.offline is True:
         lib.remove(args, nbdProc.pidFile)
 
     if not args.stdout:
         if args.noprogress is True:
-            logging.info(
+            lib.safeInfo(
                 "Backup of disk [%s] finished, file: [%s]", disk.target, targetFile
             )
         partialfile.rename(targetFilePartial, targetFile)

libvirtnbdbackup/backup/metadata.py

@@ -27,6 +27,7 @@
 from libvirtnbdbackup.qemu.exceptions import ProcessError
 from libvirtnbdbackup.ssh.exceptions import sshError
 from libvirtnbdbackup.output.exceptions import OutputException
+from libvirtnbdbackup.common import safeInfo
 
 
 log = logging.getLogger()
@@ -36,9 +37,9 @@ def backupChecksum(fileStream, targetFile):
     """Save the calculated adler32 checksum, it can be verified
     by virtnbdbrestore's verify function.'"""
     checksum = fileStream.checksum()
-    log.info("Checksum for file: [%s]:[%s]", targetFile, checksum)
+    safeInfo("Checksum for file: [%s]:[%s]", targetFile, checksum)
     chksumfile = f"{targetFile}.chksum"
-    log.info("Saving checksum to: [%s]", chksumfile)
+    safeInfo("Saving checksum to: [%s]", chksumfile)
     with output.openfile(chksumfile, "w") as cf:
         cf.write(f"{checksum}")
 

libvirtnbdbackup/backup/target.py

@@ -19,7 +19,7 @@
 from typing import BinaryIO
 from argparse import Namespace
 from libvirtnbdbackup.virt.client import DomainDisk
-from libvirtnbdbackup.common import getIdent
+from libvirtnbdbackup.common import getIdent, safeInfo
 
 
 def get(
@@ -30,7 +30,7 @@ def get(
         logging.info("Writing data to zip archive.")
         fileStream.open(targetFile)
     else:
-        logging.info("Write data to target file: [%s].", targetFilePartial)
+        safeInfo("Write data to target file: [%s].", targetFilePartial)
         fileStream.open(targetFilePartial)
 
     return fileStream

libvirtnbdbackup/common.py

@@ -107,6 +107,22 @@ def getLogFile(fileName: str) -> Optional[logging.FileHandler]:
         return None
 
 
+def safeInfo(msg, *args, **kwargs):
+    """Use tqdm redirect to not destroy progress bars"""
+    rootlog = logging.getLogger("")
+    kwargs.setdefault("stacklevel", 2)
+    try:
+        from tqdm.contrib.logging import (  # pylint: disable=import-outside-toplevel
+            logging_redirect_tqdm,
+        )
+    except ModuleNotFoundError:
+        rootlog.info(msg, *args, **kwargs)
+        return
+
+    with logging_redirect_tqdm():
+        rootlog.info(msg, *args, **kwargs)
+
+
 def configLogger(
     args: Namespace, fileLog: Optional[logging.FileHandler], counter: logCount
 ):

libvirtnbdbackup/extenthandler/extenthandler.py

@@ -19,7 +19,7 @@
 from typing import List, Any, Generator, Dict
 from nbd import CONTEXT_BASE_ALLOCATION
 from libvirtnbdbackup.objects import Extent, _ExtentObj
-from libvirtnbdbackup.common import humanize
+from libvirtnbdbackup.common import humanize, safeInfo
 
 log = logging.getLogger("extenthandler")
 
@@ -249,7 +249,7 @@ def overlap(self, extents: List[Extent]) -> List[Extent]:
                 j += 1
 
         if totalLength > 0:
-            log.info(
+            safeInfo(
                 "Detected %d bytes [%s] non-sparse blocks for current bitmap.",
                 totalLength,
                 humanize(totalLength),
@@ -261,9 +261,9 @@ def queryBlockStatus(self) -> List[Extent]:
         """Check the status for each extent, whether if it is
         real data or zeroes, return a list of extent objects
         """
-        log.info("Start receiving backup extents.")
+        safeInfo("Start receiving backup extents.")
         extents = self.queryExtents()
-        log.info("Finished receiving extents.")
+        safeInfo("Finished receiving extents.")
         extentList: List[Extent] = []
         start: int = 0
         baseStart: int = 0
@@ -290,7 +290,7 @@ def queryBlockStatus(self) -> List[Extent]:
                 extObj.offset + extObj.length,
             )
         if self.no_sparse_detection is True:
-            log.info("Skipping detection of sparse/fstrimmed blocks.")
+            safeInfo("Skipping detection of sparse/fstrimmed blocks.")
             return extentList
 
         if self._metaContext != CONTEXT_BASE_ALLOCATION: