More logging + stream container log

restic_volume_backup/backup_runner.py

@@ -1,11 +1,15 @@
+import logging
 import os
 import docker
 
 from restic_volume_backup.config import Config
 
+logger = logging.getLogger(__name__)
+
 
 def run(image: str = None, command: str = None, volumes: dict = None,
         environment: dict = None, labels: dict = None):
+    logger.info("Starting backup container")
     config = Config()
     client = docker.DockerClient(base_url=config.docker_base_url)
 
@@ -21,14 +25,32 @@ def run(image: str = None, command: str = None, volumes: dict = None,
         tty=True,
     )
 
-    print("Backup process container:", container.name)
+    logger.info("Backup process container: %s", container.name)
     log_generator = container.logs(stdout=True, stderr=True, stream=True, follow=True)
+
+    def readlines(stream):
+        """Read stream line by line"""
+        while True:
+            line = ""
+            while True:
+                try:
+                    line += next(stream).decode()
+                    if line.endswith('\n'):
+                        break
+                except StopIteration:
+                    break
+            if line:
+                yield line.strip()
+            else:
+                break
+
     with open('backup.log', 'w') as fd:
-        for line in log_generator:
+        for line in readlines(log_generator):
             line = line.decode()
             fd.write(line)
-            print(line, end='')
+            logger.info(line)
+
 
     container.reload()
-    print("ExitCode", container.attrs['State']['ExitCode'])
+    logger.info("Container ExitCode %s", container.attrs['State']['ExitCode'])
     container.remove()

restic_volume_backup/cli.py

@@ -2,6 +2,7 @@ import argparse
 import pprint
 import logging
 
+from restic_volume_backup import log
 from restic_volume_backup.config import Config
 from restic_volume_backup.containers import RunningContainers
 from restic_volume_backup import backup_runner
@@ -10,17 +11,6 @@ from restic_volume_backup import restic
 logger = logging.getLogger(__name__)
 
 
-def setup_logger(level=logging.INFO):
-    logger.setLevel(level)
-    ch = logging.StreamHandler()
-    ch.setLevel(logging.DEBUG)
-    ch.setFormatter(logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s'))
-    logger.addHandler(ch)
-
-
-setup_logger()
-
-
 def main():
     """CLI entrypoint"""
     args = parse_args()
@@ -42,8 +32,8 @@ def status(config, containers):
 
     logger.info("Backup config for compose project '%s'", containers.this_container.project_name)
     logger.info("Current service: %s", containers.this_container.name)
-    logger.info("Backup process: %s", containers.backup_process_container.name
+    # logger.info("Backup process: %s", containers.backup_process_container.name
-                if containers.backup_process_container else 'Not Running')
+    #             if containers.backup_process_container else 'Not Running')
     logger.info("Backup running: %s", containers.backup_process_running)
 
     backup_containers = containers.containers_for_backup()
@@ -91,23 +81,24 @@ def backup(config, containers):
 
 
 def start_backup_process(config, containers):
-    """Start the backup process container"""
+    """The actual backup process running inside the spawned container"""
     if (not containers.backup_process_container
        or containers.this_container == containers.backup_process_container is False):
-        print(
+        logger.error(
             "Cannot run backup process in this container. Use backup command instead. "
             "This will spawn a new container with the necessary mounts."
         )
         return
 
-    logger.info("start-backup-process")
     status(config, containers)
+    logger.info("start-backup-process")
 
     # Waste a few seconds faking a backup
     print("Fake backup running")
     import time
     for i in range(5):
         time.sleep(1)
+        logger.info('test')
         print(i)
 
     exit(0)

restic_volume_backup/log.py

@@ -0,0 +1,12 @@
+import logging
+import sys
+
+logger = logging.getLogger('restic_volume_backup')
+
+level = logging.INFO
+logger.setLevel(level)
+ch = logging.StreamHandler(stream=sys.stdout)
+ch.setLevel(level)
+ch.setFormatter(logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s'))
+# ch.setFormatter(logging.Formatter('%(asctime)s - %(levelname)s - %(message)s'))
+logger.addHandler(ch)

restic_volume_backup/restic.py

@@ -52,7 +52,13 @@ def run_command(cmd):
     stdoutdata, stderrdata = child.communicate()
 
     if stdoutdata:
-        print(stdoutdata.decode())
+        logger.info(stdoutdata.decode().strip())
+        logger.info('-' * 28)
 
     if stderrdata:
-        print(stderrdata.decode())
+        logger.info('%s STDERR %s', '-' * 10, '-' * 10)
+        logger.info(stderrdata.decode().strip())
+        logger.info('-' * 28)
+
+    logger.info("returncode %s", child.returncode)
+    return child.returncode