Merge pull request 'Improve logging: named logger, rotation, richer format' (#62) from logging-improvement into main

Reviewed-on: #62

README.md

@@ -52,6 +52,9 @@ password = "pass"
 use_log = true
 log_level = "INFO"
 log_path = "./qc.log"
+# Optional: log rotation (defaults shown)
+log_max_bytes = 5000000
+log_backup_count = 3
 
 [app_tags]
 protected_tag = "ipt"
@@ -97,4 +100,22 @@ save = "save"
 [healthcheck]
 use_healthcheck = false
 healthcheck_url = "https://example.com/ping/<uuid>>"
+```
+
+## Logging
+
+qbit-maid uses a named logger (`qbit-maid`) that writes to both the configured
+log file and the console (useful for Docker/cron output).
+
+- `use_log` — enable or disable logging entirely.
+- `log_level` — one of `DEBUG`, `INFO`, `WARN`, `ERROR`, `CRITICAL`.
+- `log_path` — path to the log file.
+- `log_max_bytes` — rotate the log file once it reaches this size (default 5 MB).
+- `log_backup_count` — number of rotated backups to keep (default 3).
+
+Log lines include the timestamp, level, logger name, function, and line number,
+for example:
+
+```
+10/26/2026 10:10:00 PM [INFO] qbit-maid:tor_processor:24 - Submitted ["My Torrent..."] for deletion.
 ```

config.toml.example

@@ -8,6 +8,9 @@ password = "pass"
 use_log = true
 log_level = "INFO"
 log_path = "./qc.log"
+# Optional: log rotation (defaults shown)
+log_max_bytes = 5000000
+log_backup_count = 3
 
 [app_tags]
 protected_tag = "ipt" 

qbit-maid.py

@@ -38,7 +38,6 @@ class Qbt:
             password=self.config["qbittorrent"]["password"],
         )
         # Create the logging and pushover objects
-        self.tl = logging
         self.po = pushover
         self.ct = Counter
         self.cv = csv
@@ -48,6 +47,12 @@ class Qbt:
         self.use_log = self.config["logging"]["use_log"]
         self.log_path = self.config["logging"]["log_path"]
         self.log_level = self.config["logging"]["log_level"]
+        self.log_max_bytes = self.config["logging"].get("log_max_bytes", 5_000_000)
+        self.log_backup_count = self.config["logging"].get("log_backup_count", 3)
+        self.tl = setup_logging(
+            self.use_log, self.log_path, self.log_level,
+            self.log_max_bytes, self.log_backup_count,
+        )
 
         #app_tags
         self.tracker_protected_tag = self.config["app_tags"]["protected_tag"]
@@ -91,7 +96,6 @@ class Qbt:
         self.healthcheck_url = self.config["healthcheck"]["healthcheck_url"]
 
         # Calling log and notify functions
-        tor_log(self)
         tor_notify(self)
         self.t = time
 
@@ -105,8 +109,7 @@ class Qbt:
         self.preme_tor_counter = 0
         self.ignored_counter = 0
         self.torrent_hash_delete_list = []
-        if self.use_log:
+        self.tl.debug(self.tracker_whitelist)
-            self.tl.debug(self.tracker_whitelist)
         #logging in
         try:
             self.tl.info('Connecting to host.')
@@ -118,17 +121,14 @@ class Qbt:
         # Pulling all torrent data
         self.torrent_list = self.qbt_client.torrents_info()
         #Main process block
-        if self.use_log:
+        list_qbit_api_info(self)
-            list_qbit_api_info(self)
+        list_first_tor(self)
-            list_first_tor(self)
+        debug_torrent_list(self)
-            debug_torrent_list(self)
         build_tor_list(self)
         process_counts(self)
-        if self.use_log:
+        torrent_count(self)
-            torrent_count(self)
         tor_processor(self)
-        if self.use_log:
+        print_processor(self)
-            print_processor(self)
         if self.delete_torrents:
             tor_delete(self)
         self.et = datetime.datetime.now()

qlist.py

@@ -1,33 +1,28 @@
 def build_tor_list(self):
         """Builds multiple lists of torrents to be sorted. Also adds tags to the torents.
         There are more effecient ways of doing things but I did this rather quickly.
-        V2 will certainly be more performant. The reason two lists were used was so that torrents 
+        V2 will certainly be more performant. The reason two lists were used was so that torrents
         that are in public trackers woudln't be around as long as torrents from a private tracker.
         """
-        self.total_torrents = len(self.torrent_list) 
+        self.total_torrents = len(self.torrent_list)
         while self.torrent_list:
             torrent = self.torrent_list.pop()
-            if self.use_log:
+            self.tl.debug(f'---Analyzing ["{torrent["name"][0:20]}..."] {torrent["infohash_v1"]}---')
-                self.tl.debug(f'---Analyzing ["{torrent["name"][0:20]}..."] {torrent["infohash_v1"]}---')
             # Need a way to tag when the tracker is blank
             if is_tracker_blank(torrent['tracker']):
-                if self.use_log:
+                self.tl.warning(f'Torrent doesn\'t have a tracker ["{torrent["name"][0:20]}..."] hash: {torrent["hash"]}')
-                    self.tl.warning(f'Torrent doesn\'t have a tracker ["{torrent["name"][0:20]}..."] hash: {torrent["hash"]}')
                 self.ignored_counter += 1
                 continue
             elif is_cat_ignored(torrent['category'], self.cat_whitelist.values()):
-                if self.use_log:
+                self.tl.info(f'Ignored category: ["{torrent["name"][0:20]}..."] category:[{torrent["category"]}] hash: {torrent["hash"]}')
-                    self.tl.info(f'Ignored category: ["{torrent["name"][0:20]}..."] category:[{torrent["category"]}] hash: {torrent["hash"]}')
                 self.ignored_counter += 1
                 continue
             elif is_ignored_tag(self.ignored_tags.values(),torrent['tags']):
-                if self.use_log:
+                self.tl.info(f'Ignored tag: ["{torrent["name"][0:20]}..."] tags: {torrent["tags"]} hash: {torrent["hash"]}')
-                    self.tl.info(f'Ignored tag: ["{torrent["name"][0:20]}..."] tags: {torrent["tags"]} hash: {torrent["hash"]}')
                 self.ignored_counter += 1
                 continue
             if is_tag_blank(torrent['tags']):
-                if self.use_log:
+                self.tl.debug(f'Tagging new torrent: ["{torrent["name"][0:20]}..."] {torrent["tracker"]}hash: {torrent["hash"]}')
-                    self.tl.debug(f'Tagging new torrent: ["{torrent["name"][0:20]}..."] {torrent["tracker"]}hash: {torrent["hash"]}')
                 if is_protected_tracker(torrent['tracker'], self.tracker_whitelist.values()):
                     self.qbt_client.torrents_add_tags(self.tracker_protected_tag,torrent['hash'])
                 elif is_not_protected_tracker(torrent['tracker'], self.tracker_whitelist.values()):
@@ -39,14 +34,12 @@ def build_tor_list(self):
             elif is_protected_tracker(torrent['tracker'], self.tracker_whitelist.values()):
                 if is_tag_blank(torrent['tags']):
                     self.qbt_client.torrents_add_tags(self.tracker_protected_tag,torrent['hash'])
-                    if self.use_log:
+                    self.tl.debug(f'Tagging Protected torrent: ["{torrent["name"][0:20]}..."] {torrent["tracker"]}hash: {torrent["hash"]}')
-                        self.tl.debug(f'Tagging Protected torrent: ["{torrent["name"][0:20]}..."] {torrent["tracker"]}hash: {torrent["hash"]}')
                 self.tracker_list.append(torrent)
             elif is_not_protected_tracker(torrent['tracker'], self.tracker_whitelist.values()):
                 if is_tag_blank(torrent['tags']):
                     self.qbt_client.torrents_add_tags(self.tracker_non_protected_tag,torrent['hash'])
-                    if self.use_log:
+                    self.tl.debug(f'Tagging Non-protected torrent: ["{torrent["name"][0:20]}..."] {torrent["tracker"]}hash: {torrent["hash"]}')
-                        self.tl.debug(f'Tagging Non-protected torrent: ["{torrent["name"][0:20]}..."] {torrent["tracker"]}hash: {torrent["hash"]}')
                 self.tracker_list.append(torrent)
 
 

qlogging.py

@@ -1,14 +1,6 @@
-def tor_log(self):
+import logging
-    """Setting up the log file, if self.use_log is set to true and self.loglevel is DEBUG OR INFO"""
+from logging.handlers import RotatingFileHandler
-    if self.use_log:
+
-        if self.log_level.lower() == 'debug':
-            self.tl.basicConfig(filename=self.log_path, format='%(asctime)s:%(levelname)s:%(message)s', encoding='utf-8', datefmt='%m/%d/%Y %I:%M:%S %p',level=self.tl.DEBUG)
-        elif self.log_level.lower() == 'info':
-            self.tl.basicConfig(filename=self.log_path, format='%(asctime)s:%(levelname)s:%(message)s', encoding='utf-8', datefmt='%m/%d/%Y %I:%M:%S %p',level=self.tl.INFO)
-        elif self.log_level.lower() == 'warn':
-            self.tl.basicConfig(filename=self.log_path, format='%(asctime)s:%(levelname)s:%(message)s', encoding='utf-8', datefmt='%m/%d/%Y %I:%M:%S %p',level=self.tl.WARN)
-        elif self.log_level.lower() == 'error':
-            self.tl.basicConfig(filename=self.log_path, format='%(asctime)s:%(levelname)s:%(message)s', encoding='utf-8', datefmt='%m/%d/%Y %I:%M:%S %p',level=self.tl.ERROR)
 
 def tor_notify(self):
     """Seting up to use pushover, if self.use_pushover is set to true and 
@@ -79,8 +71,7 @@ def torrent_count(self):
 
 def get_script_runtime(self):
     elapsed_time = self.et - self.st
-    if self.use_log:
+    self.tl.info(f'Execution time: [{elapsed_time}]')
-        self.tl.info(f'Execution time: [{elapsed_time}]')
     if self.use_pushover:
         self.extm = f"Execution time: [{elapsed_time}]"
     if self.use_apprise:
@@ -93,4 +84,87 @@ def send_ping(self, req_obj, healthcheck_url):
         self.tl.info(f"Ping failed: {e}")
 
 def debug_torrent_list(self):
-    self.tl.debug(self.torrent_list)
+    self.tl.debug(self.torrent_list)
+
+
+# ---------------------------------------------------------------------------
+# New logging infrastructure (Phase 1 & 3)
+# ---------------------------------------------------------------------------
+LOGGER_NAME = "qbit-maid"
+DEFAULT_MAX_BYTES = 5_000_000
+DEFAULT_BACKUP_COUNT = 3
+
+
+def setup_logging(use_log: bool, log_path: str, log_level: str,
+                  max_bytes: int = DEFAULT_MAX_BYTES,
+                  backup_count: int = DEFAULT_BACKUP_COUNT) -> logging.Logger:
+    """Configure and return the qbit-maid logger.
+
+    Args:
+        use_log: If False, adds a NullHandler and sets level to CRITICAL.
+        log_path: Path to the log file.
+        log_level: One of debug, info, warn, warning, error, critical.
+        max_bytes: Max size of a log file before rotation (default 5 MB).
+        backup_count: Number of rotated backups to keep (default 3).
+
+    Returns:
+        A configured :class:`logging.Logger` named ``"qbit-maid"``.
+    """
+    logger = logging.getLogger(LOGGER_NAME)
+
+    # Make setup idempotent: clear any handlers from a previous call
+    for handler in list(logger.handlers):
+        logger.removeHandler(handler)
+
+    if not use_log:
+        logger.addHandler(logging.NullHandler())
+        logger.setLevel(logging.CRITICAL)
+        return logger
+
+    level_map = {
+        "debug": logging.DEBUG,
+        "info": logging.INFO,
+        "warn": logging.WARNING,
+        "warning": logging.WARNING,
+        "error": logging.ERROR,
+        "critical": logging.CRITICAL,
+    }
+    level = level_map.get(log_level.lower(), logging.INFO)
+    logger.setLevel(level)
+
+    formatter = logging.Formatter(
+        fmt="%(asctime)s [%(levelname)s] %(name)s:%(funcName)s:%(lineno)d - %(message)s",
+        datefmt="%m/%d/%Y %I:%M:%S %p",
+    )
+
+    # File handler with rotation
+    file_handler = RotatingFileHandler(
+        log_path, maxBytes=max_bytes, backupCount=backup_count, encoding="utf-8"
+    )
+    file_handler.setFormatter(formatter)
+    logger.addHandler(file_handler)
+
+    # Console handler for Docker / cron visibility
+    console_handler = logging.StreamHandler()
+    console_handler.setFormatter(formatter)
+    logger.addHandler(console_handler)
+
+    return logger
+
+
+def log_torrent(logger: logging.Logger, level: int, torrent: dict, message: str = ""):
+    """Log a torrent record with structured extra fields.
+
+    Args:
+        logger: The qbit-maid logger instance.
+        level: Logging level constant (e.g. ``logging.INFO``).
+        torrent: A dict with torrent fields (hash, name, tracker, tags, etc.).
+        message: Optional human-readable message.
+    """
+    extra = {
+        "torrent_hash": torrent.get("infohash_v1", ""),
+        "torrent_name": (torrent.get("name", "") or "")[:20],
+        "torrent_tracker": torrent.get("tracker", "") or "",
+        "torrent_tags": torrent.get("tags", "") or "",
+    }
+    logger.log(level, message, extra=extra)

qprocess.py

@@ -5,37 +5,29 @@ def tor_processor(self):
     for canidate in self.tracker_list:
         if self.enable_telemetry:
             header = ['state','ratio','tags','added','hash','name','tracker']
-            row = [canidate['state'],canidate['ratio'],canidate["tags"],canidate['added_on'],canidate['infohash_v1'],canidate["name"][0:20],canidate['tracker']] 
+            row = [canidate['state'],canidate['ratio'],canidate["tags"],canidate['added_on'],canidate['infohash_v1'],canidate["name"][0:20],canidate['tracker']]
             write_csv(self.cv,self.telemetry_outfile,header,row)
-        if self.use_log:
+        self.tl.debug(f'---Reviewing canidate: ["{canidate["name"][0:20]}..."] {canidate["infohash_v1"]}---')
-            self.tl.debug(f'---Reviewing canidate: ["{canidate["name"][0:20]}..."] {canidate["infohash_v1"]}---')
         if is_downloading(canidate['state']):
-            if self.use_log:
+            self.tl.info(f'["{canidate["name"][0:20]}..."] is still downloading and will be skipped.')
-                self.tl.info(f'["{canidate["name"][0:20]}..."] is still downloading and will be skipped.')
             continue
         elif is_protected_under_ratio(canidate['ratio'], 1.05, self.tracker_protected_tag, canidate["tags"]):
-            if self.use_log:
+            self.tl.debug(f'["{canidate["name"][0:20]}..."] is below a 1.05 ratio({canidate["ratio"]})')
-                self.tl.debug(f'["{canidate["name"][0:20]}..."] is below a 1.05 ratio({canidate["ratio"]})')
             if is_old_tor(canidate['time_active'], self.max_age):
-                if self.use_log:
+                self.tl.debug(f'["{canidate["name"][0:20]}..."] Seconds old: {canidate["time_active"]} Delta: {canidate["time_active"] - self.max_age}')
-                    self.tl.debug(f'["{canidate["name"][0:20]}..."] Seconds old: {canidate["time_active"]} Delta: {canidate["time_active"] - self.max_age}')
                 self.torrent_hash_delete_list.append(canidate['infohash_v1'])
-                if self.use_log:
-                    self.tl.info(f'Submitted ["{canidate["name"][0:20]}..."] for deletion from the protected list.') 
-        elif is_protected_over_ratio(canidate['ratio'], 1.05, self.tracker_protected_tag, canidate["tags"]):
-            if self.use_log:
-                self.tl.debug(f'["{canidate["name"][0:20]}..."] is above a 1.05 ratio({canidate["ratio"]}).')  
-            self.torrent_hash_delete_list.append(canidate['infohash_v1'])
-            if self.use_log:
                 self.tl.info(f'Submitted ["{canidate["name"][0:20]}..."] for deletion from the protected list.')
+        elif is_protected_over_ratio(canidate['ratio'], 1.05, self.tracker_protected_tag, canidate["tags"]):
+            self.tl.debug(f'["{canidate["name"][0:20]}..."] is above a 1.05 ratio({canidate["ratio"]}).')
+            self.torrent_hash_delete_list.append(canidate['infohash_v1'])
+            self.tl.info(f'Submitted ["{canidate["name"][0:20]}..."] for deletion from the protected list.')
         elif is_not_protected_tor(self.tracker_non_protected_tag, canidate["tags"]):
             self.torrent_hash_delete_list.append(canidate['infohash_v1'])
-            if self.use_log:   
+            self.tl.info(f'Submitted ["{canidate["name"][0:20]}..."] for deletion.')
-                self.tl.info(f'Submitted ["{canidate["name"][0:20]}..."] for deletion.')
         else:
             if self.enable_dragnet:
                 header = ['state','ratio','tags','added','thash','tname','trname']
-                row = [canidate['state'],canidate['ratio'],canidate["tags"],canidate['added_on'],canidate['infohash_v1'],canidate["name"][0:20],canidate['tracker']] 
+                row = [canidate['state'],canidate['ratio'],canidate["tags"],canidate['added_on'],canidate['infohash_v1'],canidate["name"][0:20],canidate['tracker']]
                 write_csv(self.cv,self.dragnet_outfile,header,row)
             self.tl.info(f'["{canidate["name"][0:20]}..."] is orphaned.')
             self.up_tor_counter += 1
@@ -46,11 +38,10 @@ def tor_delete_tags(self):
     self.qbt_client.torrents_delete_tags(tag_list)
 
 def tor_delete(self):
-    """Remove torrents, will also delete files, this keeps the filesystem clean. 
+    """Remove torrents, will also delete files, this keeps the filesystem clean.
     Only pass self.torrent_hash_delete_list if you would like to keep the files."""
-    if self.use_log:
+    self.tl.debug('Hash list submitted for deletion:')
-        self.tl.debug('Hash list submitted for deletion:')
+    self.tl.debug(self.torrent_hash_delete_list)
-        self.tl.debug(self.torrent_hash_delete_list)
     if self.torrent_hash_delete_list:
         self.qbt_client.torrents_delete(True, self.torrent_hash_delete_list)