diff --git a/.vscode/settings.json b/.vscode/settings.json index 8a57380c..cb2fc994 100644 --- a/.vscode/settings.json +++ b/.vscode/settings.json @@ -21,6 +21,7 @@ "finaldir", "getpid", "httpx", + "levelno", "libcurl", "libx", "matroska", diff --git a/app/library/Download.py b/app/library/Download.py index 7f794e89..15af8d9f 100644 --- a/app/library/Download.py +++ b/app/library/Download.py @@ -3,6 +3,7 @@ import hashlib import logging import multiprocessing import os +import re import shutil import time from email.utils import formatdate @@ -16,7 +17,22 @@ from .ffprobe import ffprobe from .ItemDTO import ItemDTO from .YTDLPOpts import YTDLPOpts -LOG = logging.getLogger("download") + +class DebugPreProcessor(logging.Filter): + def filter(self, record: logging.LogRecord): + if record.levelno != logging.DEBUG: + return True + + if record.__dict__.get("processed", None): + return True + + logging.getLogger(record.name).log( + level=logging.DEBUG if record.msg.startswith("") else logging.INFO, + msg=re.sub(r"^\[.*\] ", "", record.msg), + extra={"processed": True}, + ) + + return False class Download: @@ -89,6 +105,9 @@ class Download: self.is_live = bool(info.is_live) or info.live_in is not None self.is_manifestless = "is_manifestless" in self.info.options and self.info.options["is_manifestless"] is True self.info_dict = info_dict + self.logger = logging.getLogger(f"Download.{info.id if info.id else info._id}") + self.ytdlp_logger = logging.getLogger(f"ytdlp.{info.id if info.id else info._id}") + self.ytdlp_logger.addFilter(DebugPreProcessor()) def _progress_hook(self, data: dict): dataDict = {k: v for k, v in data.items() if k in self._ytdlp_fields} @@ -105,7 +124,7 @@ class Download: return if self.debug: - LOG.debug(f"Postprocessor hook: {data}") + self.logger.debug(f"Postprocessor hook: {data}") if "__finaldir" in data["info_dict"]: filename = os.path.join(data["info_dict"]["__finaldir"], os.path.basename(data["info_dict"]["filepath"])) @@ -154,12 +173,14 @@ class Download: if self.info.cookies: try: cookie_file = os.path.join(self.temp_path, f"cookie_{self.info._id}.txt") - LOG.debug(f"Creating cookie file for '{self.info.id}: {self.info.title}' - '{cookie_file}'.") + self.logger.debug( + f"Creating cookie file for '{self.info.id}: {self.info.title}' - '{cookie_file}'." + ) with open(cookie_file, "w") as f: f.write(self.info.cookies) params["cookiefile"] = f.name except ValueError as e: - LOG.error(f"Failed to create cookie file for '{self.info.id}: {self.info.title}'. '{e!s}'.") + self.logger.error(f"Failed to create cookie file for '{self.info.id}: {self.info.title}'. '{e!s}'.") if self.is_live or self.is_manifestless: hasDeletedOptions = False @@ -171,37 +192,39 @@ class Download: deletedOpts.append(opt) if hasDeletedOptions: - LOG.warning( + self.logger.warning( f"Live stream detected for '{self.info.title}', The following opts '{deletedOpts=}' have been deleted which are known to cause issues with live stream and post stream manifestless mode." ) - LOG.info( + self.logger.info( f'Task id="{self.info.id}" PID="{os.getpid()}" title="{self.info.title}" preset="{self.preset}" started.' ) - LOG.debug("Params before passing to yt-dlp.", extra=params) + self.logger.debug("Params before passing to yt-dlp.", extra=params) if "impersonate" in params: from yt_dlp.networking.impersonate import ImpersonateTarget params["impersonate"] = ImpersonateTarget.from_str(params["impersonate"]) + params["logger"] = self.ytdlp_logger + cls = yt_dlp.YoutubeDL(params=params) if isinstance(self.info_dict, dict) and len(self.info_dict) > 1: - LOG.debug(f"Downloading '{self.info.url}' using pre-info.") + self.logger.debug(f"Downloading '{self.info.url}' using pre-info.") cls.process_ie_result(self.info_dict, download=True) ret = cls._download_retcode else: - LOG.debug(f"Downloading using url: {self.info.url}") + self.logger.debug(f"Downloading using url: {self.info.url}") ret = cls.download([self.info.url]) self.status_queue.put({"id": self.id, "status": "finished" if ret == 0 else "error"}) except Exception as exc: - LOG.exception(exc) + self.logger.exception(exc) self.status_queue.put({"id": self.id, "status": "error", "msg": str(exc), "error": str(exc)}) - LOG.info(f'Task id="{self.info.id}" PID="{os.getpid()}" title="{self.info.title}" completed.') + self.logger.info(f'Task id="{self.info.id}" PID="{os.getpid()}" title="{self.info.title}" completed.') async def start(self, emitter: Emitter): self.emitter = emitter @@ -244,28 +267,28 @@ class Download: self.cancel_in_progress = True procId = self.proc.ident - LOG.info(f"Closing PID='{procId}' download process.") + self.logger.info(f"Closing PID='{procId}' download process.") try: try: if "update_task" in self.__dict__ and self.update_task.done() is False: self.update_task.cancel() except Exception as e: - LOG.error(f"Failed to close status queue: '{procId}'. {e}") + self.logger.error(f"Failed to close status queue: '{procId}'. {e}") self.kill() loop = asyncio.get_running_loop() if self.proc.is_alive(): - LOG.debug(f"Waiting for PID='{procId}' to close.") + self.logger.debug(f"Waiting for PID='{procId}' to close.") await loop.run_in_executor(None, self.proc.join) - LOG.debug(f"PID='{procId}' closed.") + self.logger.debug(f"PID='{procId}' closed.") if self.status_queue: - LOG.debug(f"Closing status queue for PID='{procId}'.") + self.logger.debug(f"Closing status queue for PID='{procId}'.") self.status_queue.put(Terminator()) - LOG.debug(f"Closed status queue for PID='{procId}'.") + self.logger.debug(f"Closed status queue for PID='{procId}'.") if self.proc: self.proc.close() @@ -273,11 +296,11 @@ class Download: self.delete_temp() - LOG.debug(f"Closed PID='{procId}' download process.") + self.logger.debug(f"Closed PID='{procId}' download process.") return True except Exception as e: - LOG.error(f"Failed to close process: '{procId}'. {e}") + self.logger.error(f"Failed to close process: '{procId}'. {e}") return False @@ -295,11 +318,11 @@ class Download: return False try: - LOG.info(f"Killing download process: '{self.proc.ident}'.") + self.logger.info(f"Killing download process: '{self.proc.ident}'.") self.proc.kill() return True except Exception as e: - LOG.error(f"Failed to kill process: '{self.proc.ident}'. {e}") + self.logger.error(f"Failed to kill process: '{self.proc.ident}'. {e}") return False @@ -308,7 +331,7 @@ class Download: return if "finished" != self.info.status and self.is_live: - LOG.warning( + self.logger.warning( f"Keeping live temp folder '{self.temp_path}', as the reported status is not finished '{self.info.status}'." ) return @@ -317,12 +340,12 @@ class Download: return if self.temp_path == self.temp_dir: - LOG.warning( + self.logger.warning( f"Attempted to delete video temp folder: {self.temp_path}, but it is the same as main temp folder." ) return - LOG.info(f"Deleting Temp folder '{self.temp_path}'.") + self.logger.info(f"Deleting Temp folder '{self.temp_path}'.") shutil.rmtree(self.temp_path, ignore_errors=True) async def progress_update(self): @@ -343,7 +366,7 @@ class Download: continue if self.debug: - LOG.debug(f"Status Update: {self.info._id=} {status=}") + self.logger.debug(f"Status Update: {self.info._id=} {status=}") if isinstance(status, str): asyncio.create_task(self.emitter.updated(dl=self.info), name=f"emitter-u-{self.id}") @@ -400,7 +423,7 @@ class Download: except Exception as e: self.info.extras["is_video"] = True self.info.extras["is_audio"] = True - LOG.exception(e) - LOG.error(f"Failed to ffprobe: {status.get}. {e}") + self.logger.exception(e) + self.logger.error(f"Failed to ffprobe: {status.get}. {e}") asyncio.create_task(self.emitter.updated(dl=self.info), name=f"emitter-u-{self.id}")