perf(logging): optimize logging with rotation, async I/O, and lazy formatting

Co-Authored-By: Claude Opus 4.6 <noreply@anthropic.com>

Author: EstrellaXD

CHANGELOG.md

@@ -1,3 +1,18 @@
+# [Unreleased]
+
+## Backend
+
+### Performance
+
+- 优化日志系统性能，适配长时间运行的 Docker 环境
+  - `RotatingFileHandler` 替代 `FileHandler`（5 MB 轮转，最多 3 个备份 = 20 MB 上限）
+  - `QueueHandler` + `QueueListener` 实现异步日志写入，不阻塞事件循环
+  - `GET /api/log` 仅读取最后 512 KB，防止大日志文件导致 OOM
+  - 所有 `logger.debug(f"...")` 转为惰性 `%s` 格式化（~80 处），避免禁用 debug 时的无效字符串拼接
+  - 移除高频缓存命中的 debug 日志噪音（Mikan、TMDB 解析器）
+
+---
+
 # [3.2.3-beta.3] - 2026-01-30
 
 ## Backend

backend/src/module/ab_decorator/__init__.py

@@ -16,7 +16,7 @@ async def wrapper(*args, **kwargs):
             try:
                 return await func(*args, **kwargs)
             except Exception as e:
-                logger.debug(f"URL: {args[0]}")
+                logger.debug("URL: %s", args[0])
                 logger.warning(e)
                 logger.warning("Cannot connect to qBittorrent. Wait 5 min and retry...")
                 await asyncio.sleep(300)
@@ -31,7 +31,7 @@ async def wrapper(*args, **kwargs):
         try:
             return await func(*args, **kwargs)
         except Exception as e:
-            logger.debug(f"URL: {args[0]}")
+            logger.debug("URL: %s", args[0])
             logger.warning("Wrong API response.")
             logger.debug(e)
 

backend/src/module/api/log.py

@@ -8,11 +8,26 @@
 router = APIRouter(prefix="/log", tags=["log"])
 
 
+_TAIL_BYTES = 512 * 1024  # 512 KB
+
+
 @router.get("", response_model=str, dependencies=[Depends(get_current_user)])
 async def get_log():
     if LOG_PATH.exists():
         with open(LOG_PATH, "rb") as f:
-            return Response(f.read(), media_type="text/plain")
+            f.seek(0, 2)
+            size = f.tell()
+            if size > _TAIL_BYTES:
+                f.seek(-_TAIL_BYTES, 2)
+                data = f.read()
+                # Drop first partial line
+                idx = data.find(b"\n")
+                if idx != -1:
+                    data = data[idx + 1 :]
+            else:
+                f.seek(0)
+                data = f.read()
+            return Response(data, media_type="text/plain")
     else:
         return Response("Log file not found", status_code=404)
 

backend/src/module/conf/log.py

@@ -1,13 +1,20 @@
+import atexit
 import logging
+from logging.handlers import QueueHandler, QueueListener, RotatingFileHandler
 from pathlib import Path
+from queue import SimpleQueue
 
 from .config import settings
 
 LOG_ROOT = Path("data")
 LOG_PATH = LOG_ROOT / "log.txt"
 
+_listener: QueueListener | None = None
+
 
 def setup_logger(level: int = logging.INFO, reset: bool = False):
+    global _listener
+
     level = logging.DEBUG if settings.log.debug_enable else level
     LOG_ROOT.mkdir(exist_ok=True)
 
@@ -19,15 +26,26 @@ def setup_logger(level: int = logging.INFO, reset: bool = False):
     logging.addLevelName(logging.WARNING, "WARNING:")
     LOGGING_FORMAT = "[%(asctime)s] %(levelname)-8s  %(message)s"
     TIME_FORMAT = "%Y-%m-%d %H:%M:%S"
+    formatter = logging.Formatter(LOGGING_FORMAT, datefmt=TIME_FORMAT)
+
+    file_handler = RotatingFileHandler(
+        LOG_PATH, maxBytes=5 * 1024 * 1024, backupCount=3, encoding="utf-8"
+    )
+    file_handler.setFormatter(formatter)
+
+    stream_handler = logging.StreamHandler()
+    stream_handler.setFormatter(formatter)
+
+    log_queue: SimpleQueue = SimpleQueue()
+    queue_handler = QueueHandler(log_queue)
+
+    _listener = QueueListener(log_queue, file_handler, stream_handler, respect_handler_level=True)
+    _listener.start()
+    atexit.register(_listener.stop)
+
     logging.basicConfig(
         level=level,
-        format=LOGGING_FORMAT,
-        datefmt=TIME_FORMAT,
-        encoding="utf-8",
-        handlers=[
-            logging.FileHandler(LOG_PATH, encoding="utf-8"),
-            logging.StreamHandler(),
-        ],
+        handlers=[queue_handler],
     )
 
     # Suppress verbose HTTP request logs from httpx

backend/src/module/conf/uvicorn_logging.py

@@ -11,10 +11,12 @@
     },
     "handlers": {
         "file": {
-            "class": "logging.FileHandler",
+            "class": "logging.handlers.RotatingFileHandler",
             "filename": LOG_PATH,
             "formatter": "default",
             "encoding": "utf-8",
+            "maxBytes": 5242880,
+            "backupCount": 3,
         },
         "console": {
             "class": "logging.StreamHandler",

backend/src/module/database/bangumi.py

@@ -116,8 +116,11 @@ def find_semantic_duplicate(self, data: Bangumi) -> Optional[Bangumi]:
             )
             if is_semantic_match:
                 logger.debug(
-                    f"[Database] Found semantic duplicate: '{data.title_raw}' matches "
-                    f"existing '{candidate.title_raw}' (official: {data.official_title})"
+                    "[Database] Found semantic duplicate: '%s' matches "
+                    "existing '%s' (official: %s)",
+                    data.title_raw,
+                    candidate.title_raw,
+                    data.official_title,
                 )
                 return candidate
 
@@ -177,7 +180,9 @@ def _is_duplicate(self, data: Bangumi) -> bool:
     def add(self, data: Bangumi) -> bool:
         if self._is_duplicate(data):
             logger.debug(
-                f"[Database] Skipping duplicate: {data.official_title} ({data.group_name})"
+                "[Database] Skipping duplicate: %s (%s)",
+                data.official_title,
+                data.group_name,
             )
             return False
 
@@ -195,7 +200,7 @@ def add(self, data: Bangumi) -> bool:
         self.session.add(data)
         self.session.commit()
         _invalidate_bangumi_cache()
-        logger.debug(f"[Database] Insert {data.official_title} into database.")
+        logger.debug("[Database] Insert %s into database.", data.official_title)
         return True
 
     def add_all(self, datas: list[Bangumi]) -> int:
@@ -250,12 +255,14 @@ def add_all(self, datas: list[Bangumi]) -> int:
         if not unique_to_add:
             if semantic_merged > 0:
                 logger.debug(
-                    f"[Database] {semantic_merged} bangumi merged as aliases, "
-                    f"rest were duplicates."
+                    "[Database] %s bangumi merged as aliases, "
+                    "rest were duplicates.",
+                    semantic_merged,
                 )
             else:
                 logger.debug(
-                    f"[Database] All {len(datas)} bangumi already exist, skipping."
+                    "[Database] All %s bangumi already exist, skipping.",
+                    len(datas),
                 )
             return 0
 
@@ -265,12 +272,16 @@ def add_all(self, datas: list[Bangumi]) -> int:
         skipped = len(datas) - len(unique_to_add) - semantic_merged
         if skipped > 0 or semantic_merged > 0:
             logger.debug(
-                f"[Database] Insert {len(unique_to_add)} bangumi, "
-                f"skipped {skipped} duplicates, merged {semantic_merged} as aliases."
+                "[Database] Insert %s bangumi, "
+                "skipped %s duplicates, merged %s as aliases.",
+                len(unique_to_add),
+                skipped,
+                semantic_merged,
             )
         else:
             logger.debug(
-                f"[Database] Insert {len(unique_to_add)} bangumi into database."
+                "[Database] Insert %s bangumi into database.",
+                len(unique_to_add),
             )
         return len(unique_to_add)
 
@@ -289,14 +300,14 @@ def update(self, data: Bangumi | BangumiUpdate, _id: int = None) -> bool:
         self.session.add(db_data)
         self.session.commit()
         _invalidate_bangumi_cache()
-        logger.debug(f"[Database] Update {data.official_title}")
+        logger.debug("[Database] Update %s", data.official_title)
         return True
 
     def update_all(self, datas: list[Bangumi]):
         self.session.add_all(datas)
         self.session.commit()
         _invalidate_bangumi_cache()
-        logger.debug(f"[Database] Update {len(datas)} bangumi.")
+        logger.debug("[Database] Update %s bangumi.", len(datas))
 
     def update_rss(self, title_raw: str, rss_set: str):
         statement = select(Bangumi).where(Bangumi.title_raw == title_raw)
@@ -308,7 +319,7 @@ def update_rss(self, title_raw: str, rss_set: str):
             self.session.add(bangumi)
             self.session.commit()
             _invalidate_bangumi_cache()
-            logger.debug(f"[Database] Update {title_raw} rss_link to {rss_set}.")
+            logger.debug("[Database] Update %s rss_link to %s.", title_raw, rss_set)
 
     def update_poster(self, title_raw: str, poster_link: str):
         statement = select(Bangumi).where(Bangumi.title_raw == title_raw)
@@ -319,7 +330,7 @@ def update_poster(self, title_raw: str, poster_link: str):
             self.session.add(bangumi)
             self.session.commit()
             _invalidate_bangumi_cache()
-            logger.debug(f"[Database] Update {title_raw} poster_link to {poster_link}.")
+            logger.debug("[Database] Update %s poster_link to %s.", title_raw, poster_link)
 
     def delete_one(self, _id: int):
         statement = select(Bangumi).where(Bangumi.id == _id)
@@ -329,7 +340,7 @@ def delete_one(self, _id: int):
             self.session.delete(bangumi)
             self.session.commit()
             _invalidate_bangumi_cache()
-            logger.debug(f"[Database] Delete bangumi id: {_id}.")
+            logger.debug("[Database] Delete bangumi id: %s.", _id)
 
     def delete_all(self):
         statement = delete(Bangumi)
@@ -362,7 +373,7 @@ def search_id(self, _id: int) -> Optional[Bangumi]:
         if bangumi is None:
             logger.warning(f"[Database] Cannot find bangumi id: {_id}.")
             return None
-        logger.debug(f"[Database] Find bangumi id: {_id}.")
+        logger.debug("[Database] Find bangumi id: %s.", _id)
         return bangumi
 
     def search_ids(self, ids: list[int]) -> list[Bangumi]:
@@ -426,7 +437,8 @@ def match_list(self, torrent_list: list, rss_link: str) -> list:
             self.session.commit()
             _invalidate_bangumi_cache()
             logger.debug(
-                f"[Database] Batch updated rss_link for {len(rss_updated)} bangumi."
+                "[Database] Batch updated rss_link for %s bangumi.",
+                len(rss_updated),
             )
         return unmatched
 
@@ -485,7 +497,7 @@ def disable_rule(self, _id: int):
             self.session.add(bangumi)
             self.session.commit()
             _invalidate_bangumi_cache()
-            logger.debug(f"[Database] Disable rule {bangumi.title_raw}.")
+            logger.debug("[Database] Disable rule %s.", bangumi.title_raw)
 
     def search_rss(self, rss_link: str) -> list[Bangumi]:
         statement = select(Bangumi).where(func.instr(rss_link, Bangumi.rss_link) > 0)
@@ -502,7 +514,7 @@ def archive_one(self, _id: int) -> bool:
         self.session.add(bangumi)
         self.session.commit()
         _invalidate_bangumi_cache()
-        logger.debug(f"[Database] Archived bangumi id: {_id}.")
+        logger.debug("[Database] Archived bangumi id: %s.", _id)
         return True
 
     def unarchive_one(self, _id: int) -> bool:
@@ -515,7 +527,7 @@ def unarchive_one(self, _id: int) -> bool:
         self.session.add(bangumi)
         self.session.commit()
         _invalidate_bangumi_cache()
-        logger.debug(f"[Database] Unarchived bangumi id: {_id}.")
+        logger.debug("[Database] Unarchived bangumi id: %s.", _id)
         return True
 
     def match_by_save_path(self, save_path: str) -> Optional[Bangumi]:
@@ -615,8 +627,12 @@ def set_needs_review(
         self.session.commit()
         _invalidate_bangumi_cache()
         logger.debug(
-            f"[Database] Marked bangumi id {_id} as needs_review: {reason} "
-            f"(suggested: season={suggested_season_offset}, episode={suggested_episode_offset})"
+            "[Database] Marked bangumi id %s as needs_review: %s "
+            "(suggested: season=%s, episode=%s)",
+            _id,
+            reason,
+            suggested_season_offset,
+            suggested_episode_offset,
         )
         return True
 
@@ -632,5 +648,5 @@ def clear_needs_review(self, _id: int) -> bool:
         self.session.add(bangumi)
         self.session.commit()
         _invalidate_bangumi_cache()
-        logger.debug(f"[Database] Cleared needs_review for bangumi id {_id}")
+        logger.debug("[Database] Cleared needs_review for bangumi id %s", _id)
         return True

backend/src/module/database/rss.py

@@ -16,10 +16,10 @@ def add(self, data: RSSItem) -> bool:
         result = self.session.execute(statement)
         db_data = result.scalar_one_or_none()
         if db_data:
-            logger.debug(f"RSS Item {data.url} already exists.")
+            logger.debug("RSS Item %s already exists.", data.url)
             return False
         else:
-            logger.debug(f"RSS Item {data.url} not exists, adding...")
+            logger.debug("RSS Item %s not exists, adding...", data.url)
             self.session.add(data)
             self.session.commit()
             self.session.refresh(data)
@@ -36,7 +36,7 @@ def add_all(self, data: list[RSSItem]):
         if new_items:
             self.session.add_all(new_items)
             self.session.commit()
-            logger.debug(f"Batch inserted {len(new_items)} RSS items.")
+            logger.debug("Batch inserted %s RSS items.", len(new_items))
 
     def update(self, _id: int, data: RSSUpdate) -> bool:
         statement = select(RSSItem).where(RSSItem.id == _id)

backend/src/module/database/torrent.py

@@ -14,17 +14,17 @@ def __init__(self, session: Session):
     def add(self, data: Torrent):
         self.session.add(data)
         self.session.commit()
-        logger.debug(f"Insert {data.name} in database.")
+        logger.debug("Insert %s in database.", data.name)
 
     def add_all(self, datas: list[Torrent]):
         self.session.add_all(datas)
         self.session.commit()
-        logger.debug(f"Insert {len(datas)} torrents in database.")
+        logger.debug("Insert %s torrents in database.", len(datas))
 
     def update(self, data: Torrent):
         self.session.add(data)
         self.session.commit()
-        logger.debug(f"Update {data.name} in database.")
+        logger.debug("Update %s in database.", data.name)
 
     def update_all(self, datas: list[Torrent]):
         self.session.add_all(datas)
@@ -33,7 +33,7 @@ def update_all(self, datas: list[Torrent]):
     def update_one_user(self, data: Torrent):
         self.session.add(data)
         self.session.commit()
-        logger.debug(f"Update {data.name} in database.")
+        logger.debug("Update %s in database.", data.name)
 
     def search(self, _id: int) -> Torrent | None:
         result = self.session.execute(select(Torrent).where(Torrent.id == _id))
@@ -82,6 +82,6 @@ def update_qb_hash(self, torrent_id: int, qb_hash: str) -> bool:
             torrent.qb_hash = qb_hash
             self.session.add(torrent)
             self.session.commit()
-            logger.debug(f"Updated qb_hash for torrent {torrent_id}: {qb_hash}")
+            logger.debug("Updated qb_hash for torrent %s: %s", torrent_id, qb_hash)
             return True
         return False