From fa6812ad06742392c596631de68115cbba154c27 Mon Sep 17 00:00:00 2001 From: Einar Forselv Date: Fri, 15 Nov 2019 16:47:40 +0100 Subject: [PATCH] More logging + stream container log --- restic_volume_backup/backup_runner.py | 30 +++++++++++++++++++++++---- restic_volume_backup/cli.py | 23 +++++++------------- restic_volume_backup/log.py | 12 +++++++++++ restic_volume_backup/restic.py | 10 +++++++-- 4 files changed, 53 insertions(+), 22 deletions(-) create mode 100644 restic_volume_backup/log.py diff --git a/restic_volume_backup/backup_runner.py b/restic_volume_backup/backup_runner.py index 777b727..bf4386b 100644 --- a/restic_volume_backup/backup_runner.py +++ b/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() diff --git a/restic_volume_backup/cli.py b/restic_volume_backup/cli.py index e54cbb4..9062f5b 100644 --- a/restic_volume_backup/cli.py +++ b/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 - if containers.backup_process_container else 'Not Running') + # logger.info("Backup process: %s", containers.backup_process_container.name + # 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) diff --git a/restic_volume_backup/log.py b/restic_volume_backup/log.py new file mode 100644 index 0000000..2992507 --- /dev/null +++ b/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) diff --git a/restic_volume_backup/restic.py b/restic_volume_backup/restic.py index 273e6b8..8b574bf 100644 --- a/restic_volume_backup/restic.py +++ b/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