From 3b992d35d222126b646fd43229c0f4ce05757ec2 Mon Sep 17 00:00:00 2001
From: rafsaf <rafal.safin12@gmail.com>
Date: Mon, 7 Aug 2023 23:58:34 +0200
Subject: [PATCH] better logging in run_backup, add thread name to logging

---
 backuper/config.py | 10 +++++-----
 backuper/core.py   |  2 +-
 backuper/main.py   | 19 +++++++++++++------
 3 files changed, 19 insertions(+), 12 deletions(-)

diff --git a/backuper/config.py b/backuper/config.py
index e8bd47f..b528366 100644
--- a/backuper/config.py
+++ b/backuper/config.py
@@ -55,7 +55,7 @@ def logging_config(log_level: str) -> None:
         "disable_existing_loggers": False,
         "formatters": {
             "verbose": {
-                "format": "{asctime} [{levelname}] {name}: {message}",
+                "format": "{asctime} {threadName} [{levelname}] {name}: {message}",
                 "style": "{",
             },
         },
@@ -69,7 +69,7 @@ def logging_config(log_level: str) -> None:
                 "class": "logging.handlers.RotatingFileHandler",
                 "filename": LOG_FOLDER_PATH / "backuper_error.log",
                 "formatter": "verbose",
-                "maxBytes": 10**5,
+                "maxBytes": 5 * 10**6,
                 "backupCount": 1,
                 "level": "ERROR",
             },
@@ -77,7 +77,7 @@ def logging_config(log_level: str) -> None:
                 "class": "logging.handlers.RotatingFileHandler",
                 "filename": LOG_FOLDER_PATH / "backuper_warning.log",
                 "formatter": "verbose",
-                "maxBytes": 10**5,
+                "maxBytes": 5 * 10**6,
                 "backupCount": 1,
                 "level": "WARNING",
             },
@@ -85,7 +85,7 @@ def logging_config(log_level: str) -> None:
                 "class": "logging.handlers.RotatingFileHandler",
                 "filename": LOG_FOLDER_PATH / "backuper_info.log",
                 "formatter": "verbose",
-                "maxBytes": 10**5,
+                "maxBytes": 5 * 10**6,
                 "backupCount": 1,
                 "level": "INFO",
             },
@@ -93,7 +93,7 @@ def logging_config(log_level: str) -> None:
                 "class": "logging.handlers.RotatingFileHandler",
                 "filename": LOG_FOLDER_PATH / "backuper_debug.log",
                 "formatter": "verbose",
-                "maxBytes": 10**5,
+                "maxBytes": 5 * 10**7,
                 "backupCount": 1,
                 "level": "DEBUG",
             },
diff --git a/backuper/core.py b/backuper/core.py
index 6199ed3..d3803a8 100644
--- a/backuper/core.py
+++ b/backuper/core.py
@@ -147,7 +147,7 @@ def create_provider_model() -> ProviderModel:
             target_model.__name__.lower().removesuffix("providermodel")
         )
         target_map[name] = target_model
-    log.info("start validating BACKUP_PROVIDER")
+    log.info("start validating BACKUP_PROVIDER environment variable")
 
     base_provider = _validate_model(
         "backup_provider",
diff --git a/backuper/main.py b/backuper/main.py
index b96a1b1..4121ad3 100644
--- a/backuper/main.py
+++ b/backuper/main.py
@@ -37,7 +37,7 @@ def backup_provider() -> BaseBackupProvider:
     log.debug("initializing %s with %s", provider_target_cls, provider_model)
     res_backup_provider = provider_target_cls(**provider_model.model_dump())
     log.info(
-        "success initializing target: `%s`",
+        "success initializing provider: `%s`",
         provider_model.name,
     )
     return res_backup_provider
@@ -78,7 +78,7 @@ def shutdown() -> NoReturn:
     deadline = start + timeout_secs
     log.info(
         "start backuper shutdown, force exit after SIGTERM_TIMEOUT_SECS=%ss, "
-        "use this environment to control it.",
+        "use this environment to control it, see https://backuper.rafsaf.pl/configuration/.",
         timeout_secs,
     )
     for thread in threading.enumerate():
@@ -121,6 +121,11 @@ def run_backup(target: BaseBackupTarget, provider: BaseBackupProvider) -> None:
         step_name=PROGRAM_STEP.BACKUP_CREATE, env_name=target.env_name
     ):
         backup_file = target.make_backup()
+    log.info(
+        "backup file created: %s, starting post save upload to provider %s",
+        backup_file,
+        provider.NAME,
+    )
     with NotificationsContext(
         step_name=PROGRAM_STEP.UPLOAD,
         env_name=target.env_name,
@@ -129,7 +134,7 @@ def run_backup(target: BaseBackupTarget, provider: BaseBackupProvider) -> None:
         provider.post_save(backup_file=backup_file)
 
     log.info(
-        "backup finished, next backup of target `%s` is: %s",
+        "backup and upload finished, next backup of target `%s` is: %s",
         target.env_name,
         target.next_backup_time,
     )
@@ -146,6 +151,7 @@ def setup_runtime_arguments() -> bool:
 
 
 def main() -> NoReturn:
+    log.info("start backuper configuration...")
     signal.signal(signalnum=signal.SIGINT, handler=quit)
     signal.signal(signalnum=signal.SIGTERM, handler=quit)
 
@@ -154,16 +160,17 @@ def main() -> NoReturn:
     provider = backup_provider()
     targets = backup_targets()
 
-    i = 0
+    log.info("backuper configuration finished")
+
     while not exit_event.is_set():
         for target in targets:
             if target.next_backup() or single_run:
-                i += 1
+                pretty_env_name = target.env_name.replace("_", "-")
                 backup_thread = Thread(
                     target=run_backup,
                     args=(target, provider),
                     daemon=True,
-                    name=f"{target.env_name}-{i}",
+                    name=f"Thread-{pretty_env_name}",
                 )
                 backup_thread.start()
                 exit_event.wait(0.5)