From cf90db3b4c09663bb8c4a1e533b7a80674804623 Mon Sep 17 00:00:00 2001 From: arabcoders Date: Wed, 27 May 2026 16:47:30 +0300 Subject: [PATCH] refactor: update log mesages to take advantage of JSONL --- API.md | 28 +- app/features/conditions/migration.py | 12 +- app/features/conditions/router.py | 24 +- app/features/conditions/service.py | 18 +- app/features/core/migration.py | 6 +- app/features/dl_fields/migration.py | 12 +- app/features/notifications/migration.py | 12 +- app/features/notifications/service.py | 29 +- app/features/presets/migration.py | 12 +- app/features/presets/utils.py | 6 +- app/features/streaming/library/segments.py | 23 +- app/features/streaming/library/thumbnail.py | 51 +++- app/features/streaming/router.py | 6 +- .../tasks/definitions/handlers/generic.py | 144 ++++++++-- .../tasks/definitions/handlers/rss.py | 68 ++++- .../tasks/definitions/handlers/tver.py | 61 ++++- .../tasks/definitions/handlers/twitch.py | 37 ++- .../tasks/definitions/handlers/youtube.py | 31 ++- app/features/tasks/definitions/migration.py | 18 +- app/features/tasks/definitions/router.py | 28 +- app/features/tasks/definitions/service.py | 165 ++++++++++-- app/features/tasks/migration.py | 12 +- app/features/tasks/router.py | 74 +++++- app/features/tasks/service.py | 70 ++++- app/features/tasks/utils.py | 6 +- app/features/ytdlp/archiver.py | 49 +++- app/features/ytdlp/extractor.py | 24 +- app/features/ytdlp/patches.py | 14 +- app/features/ytdlp/router.py | 75 +++++- app/features/ytdlp/tests/test_ytdlp_opts.py | 13 +- app/features/ytdlp/utils.py | 8 +- app/features/ytdlp/ytdlp_opts.py | 8 +- app/library/BackgroundWorker.py | 28 +- app/library/Events.py | 70 ++++- app/library/HttpAPI.py | 46 +++- app/library/HttpSocket.py | 24 +- app/library/PackageInstaller.py | 58 +++- app/library/Scheduler.py | 20 +- app/library/TerminalSessionManager.py | 12 +- app/library/UpdateChecker.py | 54 +++- app/library/Utils.py | 206 ++++++++++++-- app/library/cache.py | 6 +- app/library/cf_solver_handler.py | 2 +- app/library/cf_solver_shared.py | 19 +- app/library/config.py | 31 ++- app/library/downloads/core.py | 245 +++++++++++++++-- app/library/downloads/hooks.py | 32 ++- app/library/downloads/item_adder.py | 167 ++++++++++-- app/library/downloads/monitors.py | 160 +++++++++-- app/library/downloads/playlist_processor.py | 44 ++- app/library/downloads/pool_manager.py | 45 +++- app/library/downloads/process_manager.py | 173 ++++++++++-- app/library/downloads/queue_manager.py | 251 +++++++++++++++--- app/library/downloads/status_tracker.py | 109 +++++++- app/library/downloads/temp_manager.py | 60 ++++- app/library/downloads/utils.py | 25 +- app/library/downloads/video_processor.py | 73 ++++- app/library/sqlite_store.py | 15 +- app/main.py | 39 ++- app/routes/api/_static.py | 7 +- app/routes/api/browser.py | 143 ++++++++-- app/routes/api/docs.py | 13 +- app/routes/api/download.py | 8 +- app/routes/api/history.py | 49 +++- app/routes/api/images.py | 20 +- app/routes/api/logs.py | 4 +- app/routes/api/system.py | 2 +- app/routes/socket/history.py | 6 +- app/tests/test_download_utils.py | 4 +- app/tests/test_images_routes.py | 9 +- app/tests/test_utils.py | 15 +- app/upgrader.py | 54 +++- 72 files changed, 2984 insertions(+), 508 deletions(-) diff --git a/API.md b/API.md index 8f568173..184cb195 100644 --- a/API.md +++ b/API.md @@ -2319,7 +2319,7 @@ Binary image data with appropriate headers "level": "error", "levelno": 40, "logger": "downloads.queue", - "message": "Download failed", + "message": "Failed to download 'Example Video'.", "exception": { "type": "ValueError", "message": "bad", @@ -2342,7 +2342,17 @@ Binary image data with appropriate headers "function": "start", "line": 123 }, - "fields": {} + "fields": { + "download": { + "download_id": "abc123", + "media_id": "video-id", + "title": "Example Video", + "url": "https://example.test/video", + "preset": "default", + "status": "error", + "has_cookies": false + } + } } ], "offset": 0, @@ -2370,7 +2380,7 @@ Binary image data with appropriate headers "level": "error", "levelno": 40, "logger": "downloads.queue", - "message": "Download failed", + "message": "Failed to download 'Example Video'.", "exception": { "type": "ValueError", "message": "bad", @@ -2393,7 +2403,17 @@ Binary image data with appropriate headers "function": "start", "line": 123 }, - "fields": {} + "fields": { + "download": { + "download_id": "abc123", + "media_id": "video-id", + "title": "Example Video", + "url": "https://example.test/video", + "preset": "default", + "status": "error", + "has_cookies": false + } + } } ``` diff --git a/app/features/conditions/migration.py b/app/features/conditions/migration.py index 8b973486..48edc671 100644 --- a/app/features/conditions/migration.py +++ b/app/features/conditions/migration.py @@ -36,7 +36,11 @@ class Migration(FeatureMigration): try: items: list[dict] | None = json.loads(self._source_file.read_text()) except Exception as exc: - LOG.exception("Failed to read %s: %s. Ignoring", self._source_file, exc) + LOG.exception( + "Failed to read conditions migration file '%s'. Ignoring.", + self._source_file, + extra={"file_path": str(self._source_file), "exception_type": type(exc).__name__}, + ) await self._move_file(self._source_file) return @@ -54,7 +58,11 @@ class Migration(FeatureMigration): await self._repo.create(normalized) inserted += 1 except Exception as exc: - LOG.exception("Failed to insert condition '%s': %s", normalized.name, exc) + LOG.exception( + "Failed to insert condition '%s'.", + normalized.name, + extra={"condition_name": normalized.name, "exception_type": type(exc).__name__}, + ) LOG.info("Migrated %s condition(s) from %s.", inserted, self._source_file) await self._move_file(self._source_file) diff --git a/app/features/conditions/router.py b/app/features/conditions/router.py index beef2612..251c0c49 100644 --- a/app/features/conditions/router.py +++ b/app/features/conditions/router.py @@ -115,7 +115,17 @@ async def conditions_test(request: Request, encoder: Encoder, cache: Cache, conf else: data = cache.get(key) except Exception as e: - LOG.exception(e) + LOG.exception( + "Failed to extract video info for condition check '%s'.", + cond, + extra={ + "route": "conditions.match", + "condition": cond, + "url": url, + "preset": preset, + "exception_type": type(e).__name__, + }, + ) return web.json_response( data={"error": f"Failed to extract video info. '{e!s}'"}, status=web.HTTPInternalServerError.status_code, @@ -126,7 +136,17 @@ async def conditions_test(request: Request, encoder: Encoder, cache: Cache, conf status: bool = match_str(cond, data) except Exception as e: - LOG.exception(e) + LOG.exception( + "Failed to evaluate condition '%s'.", + cond, + extra={ + "route": "conditions.match", + "condition": cond, + "url": url, + "preset": preset, + "exception_type": type(e).__name__, + }, + ) return web.json_response( data={"error": str(e)}, status=web.HTTPBadRequest.status_code, diff --git a/app/features/conditions/service.py b/app/features/conditions/service.py index de8bdf7b..5464706d 100644 --- a/app/features/conditions/service.py +++ b/app/features/conditions/service.py @@ -145,17 +145,29 @@ class Conditions(metaclass=Singleton): continue if not item.filter: - LOG.error(f"Filter is empty for '{item.name}'.") + LOG.error( + "Filter is empty for '%s'.", item.name, extra={"condition_id": item.id, "condition_name": item.name} + ) continue try: if not match_str(item.filter, info): continue - LOG.debug(f"Matched '{item.id}: {item.name}' with filter '{item.filter}'.") + LOG.debug( + "Matched '%s: %s' with filter '%s'.", + item.id, + item.name, + item.filter, + extra={"condition_id": item.id, "condition_name": item.name, "filter": item.filter}, + ) return item except Exception as e: - LOG.error(f"Failed to evaluate '{item.id}: {item.name}'. '{e!s}'.") + LOG.exception( + "Failed to evaluate condition '%s'.", + item.name, + extra={"condition_id": item.id, "condition_name": item.name, "exception_type": type(e).__name__}, + ) continue return None diff --git a/app/features/core/migration.py b/app/features/core/migration.py index a323e21a..1a8921ba 100644 --- a/app/features/core/migration.py +++ b/app/features/core/migration.py @@ -26,7 +26,11 @@ class Migration(abc.ABC): try: await self.migrate() except Exception as exc: - LOG.exception("Feature migration '%s' failed: %s", self.name, exc) + LOG.exception( + "Feature migration '%s' failed.", + self.name, + extra={"feature": self.name, "exception_type": type(exc).__name__}, + ) return False return True diff --git a/app/features/dl_fields/migration.py b/app/features/dl_fields/migration.py index 2673c0de..4987b79c 100644 --- a/app/features/dl_fields/migration.py +++ b/app/features/dl_fields/migration.py @@ -36,7 +36,11 @@ class Migration(FeatureMigration): try: items: list[dict[str, Any]] | None = json.loads(self._source_file.read_text()) except Exception as exc: - LOG.exception("Failed to read %s: %s. Ignoring", self._source_file, exc) + LOG.exception( + "Failed to read download fields migration file '%s'. Ignoring.", + self._source_file, + extra={"file_path": str(self._source_file), "exception_type": type(exc).__name__}, + ) await self._move_file(self._source_file) return @@ -54,7 +58,11 @@ class Migration(FeatureMigration): await self._repo.create(normalized) inserted += 1 except Exception as exc: - LOG.exception("Failed to insert dl field '%s': %s", normalized["name"], exc) + LOG.exception( + "Failed to insert download field '%s'.", + normalized["name"], + extra={"field_name": normalized["name"], "exception_type": type(exc).__name__}, + ) LOG.info("Migrated %s dl field(s) from %s.", inserted, self._source_file) await self._move_file(self._source_file) diff --git a/app/features/notifications/migration.py b/app/features/notifications/migration.py index 6262cdee..51ea94f9 100644 --- a/app/features/notifications/migration.py +++ b/app/features/notifications/migration.py @@ -37,7 +37,11 @@ class Migration(FeatureMigration): try: items: list[dict] | None = json.loads(self._source_file.read_text()) except Exception as exc: - LOG.exception("Failed to read %s: %s. Ignoring", self._source_file, exc) + LOG.exception( + "Failed to read notifications migration file '%s'. Ignoring.", + self._source_file, + extra={"file_path": str(self._source_file), "exception_type": type(exc).__name__}, + ) await self._move_file(self._source_file) return @@ -56,7 +60,11 @@ class Migration(FeatureMigration): await self._repo.create(normalized) inserted += 1 except Exception as exc: - LOG.exception("Failed to insert notification '%s': %s", normalized.get("name"), exc) + LOG.exception( + "Failed to insert notification target '%s'.", + normalized.get("name"), + extra={"target_name": normalized.get("name"), "exception_type": type(exc).__name__}, + ) LOG.info("Migrated %s notification target(s) from %s.", inserted, self._source_file) await self._move_file(self._source_file) diff --git a/app/features/notifications/service.py b/app/features/notifications/service.py index bdef57b7..1f5e8bb8 100644 --- a/app/features/notifications/service.py +++ b/app/features/notifications/service.py @@ -2,7 +2,6 @@ from __future__ import annotations import asyncio import logging -import traceback from pathlib import Path from typing import TYPE_CHECKING, Any @@ -274,8 +273,17 @@ class Notifications(metaclass=Singleton): msg = "Apprise failed to send notification." raise RuntimeError(msg) # noqa: TRY301 except Exception as exc: - LOG.exception(exc) - LOG.error("Error sending Apprise notification: %s", exc) + LOG.exception( + "Failed to send Apprise notification for event '%s'.", + ev.event, + extra={ + "event_id": ev.id, + "event": ev.event, + "target_count": len(targets), + "targets": [t.name for t in targets], + "exception_type": type(exc).__name__, + }, + ) return {"error": str(exc), "event": ev.event, "id": ev.id, "targets": [t.name for t in targets]} return {} @@ -335,14 +343,17 @@ class Notifications(metaclass=Singleton): return resp_data except Exception as exc: - err_msg = str(exc) or type(exc).__name__ - tb = "".join(traceback.format_exception(type(exc), exc, exc.__traceback__)) - LOG.error( - "Error sending notification event '%s: %s' to '%s'. '%s'. %s", + LOG.exception( + "Failed to send notification event '%s: %s' to '%s'.", ev.event, ev.id, target.name, - err_msg, - tb, + extra={ + "event_id": ev.id, + "event": ev.event, + "target_name": target.name, + "url": target.request.url, + "exception_type": type(exc).__name__, + }, ) return {"url": target.request.url, "status": 500, "text": str(ev)} diff --git a/app/features/presets/migration.py b/app/features/presets/migration.py index eb000334..61a106af 100644 --- a/app/features/presets/migration.py +++ b/app/features/presets/migration.py @@ -32,7 +32,11 @@ class Migration(FeatureMigration): try: items: list[dict[str, Any]] | None = json.loads(self._source_file.read_text()) except Exception as exc: - LOG.exception("Failed to read %s: %s. Ignoring", self._source_file, exc) + LOG.exception( + "Failed to read presets migration file '%s'. Ignoring.", + self._source_file, + extra={"file_path": str(self._source_file), "exception_type": type(exc).__name__}, + ) await self._move_file(self._source_file) return @@ -51,7 +55,11 @@ class Migration(FeatureMigration): await self._repo.create(normalized) inserted += 1 except Exception as exc: - LOG.exception("Failed to insert preset '%s': %s", normalized["name"], exc) + LOG.exception( + "Failed to insert preset '%s'.", + normalized["name"], + extra={"preset": normalized["name"], "exception_type": type(exc).__name__}, + ) LOG.info("Migrated %s preset(s) from %s.", inserted, self._source_file) await self._move_file(self._source_file) diff --git a/app/features/presets/utils.py b/app/features/presets/utils.py index 0164da9a..0362e54e 100644 --- a/app/features/presets/utils.py +++ b/app/features/presets/utils.py @@ -48,7 +48,11 @@ async def seed_defaults(repo) -> None: await repo.update(existing.id, payload) except Exception as exc: - LOG.exception("Failed to seed default preset '%s': %s", preset.get("name"), exc) + LOG.exception( + "Failed to seed default preset '%s'.", + preset.get("name"), + extra={"preset": preset.get("name"), "exception_type": type(exc).__name__}, + ) def preset_name(value: str) -> str: diff --git a/app/features/streaming/library/segments.py b/app/features/streaming/library/segments.py index 11d71f66..73c445d1 100644 --- a/app/features/streaming/library/segments.py +++ b/app/features/streaming/library/segments.py @@ -170,7 +170,13 @@ class Segments: stderr_task: asyncio.Task[None] = asyncio.create_task(_drain_stderr()) - LOG.debug(f"Streaming '{file}' segment '{self.index}'. ffmpeg: {' '.join(args)}") + LOG.debug( + "Streaming '%s' segment '%s'. ffmpeg: %s", + file, + self.index, + " ".join(args), + extra={"file": str(file), "segment_index": self.index, "ffmpeg_args": args}, + ) try: while True: @@ -191,7 +197,7 @@ class Segments: try: await asyncio.wait_for(proc.wait(), timeout=5) except TimeoutError: - LOG.error("ffmpeg process did not terminate in time. Killing it.") + LOG.warning("ffmpeg process did not terminate in time. Killing it.") proc.kill() raise except ConnectionResetError: @@ -204,7 +210,7 @@ class Segments: try: rc: int = await asyncio.wait_for(proc.wait(), timeout=5) except TimeoutError: - LOG.error("ffmpeg process did not terminate in time after disconnect. Killing it.") + LOG.warning("ffmpeg process did not terminate in time after disconnect. Killing it.") proc.kill() try: rc = await asyncio.wait_for(proc.wait(), timeout=5) @@ -215,7 +221,7 @@ class Segments: try: rc = await asyncio.wait_for(proc.wait(), timeout=30) except TimeoutError: - LOG.error("ffmpeg process wait timed out. Killing it.") + LOG.warning("ffmpeg process wait timed out. Killing it.") proc.kill() try: rc = await asyncio.wait_for(proc.wait(), timeout=5) @@ -233,7 +239,7 @@ class Segments: if not codec or codec not in SUPPORTED_CODECS: codec: str = select_encoder(self.vcodec or "") - LOG.debug(f"Selected video codec '{codec}' for segment streaming.") + LOG.debug("Selected video codec '%s' for segment streaming.", codec, extra={"codec": codec}) if Segments._cached_vcodec and Segments._cache_initialized: codecs: list[str] = [Segments._cached_vcodec] @@ -259,7 +265,12 @@ class Segments: if 0 != rc: err: str = stderr_text[:500] if stderr_text else "no error output" - LOG.warning(f"transcoding has failed (cmd={ffmpeg_args}) (rc={rc}): {err}. Trying fallbacks.") + LOG.warning( + "Hardware encoder failed (rc=%s): %s. Trying fallbacks.", + rc, + err, + extra={"ffmpeg_args": ffmpeg_args, "returncode": rc, "stderr": err, "codec": s_codec}, + ) self.attempted.add(s_codec) finally: if stream_input.is_symlink(): diff --git a/app/features/streaming/library/thumbnail.py b/app/features/streaming/library/thumbnail.py index a4fb91e5..dd432c06 100644 --- a/app/features/streaming/library/thumbnail.py +++ b/app/features/streaming/library/thumbnail.py @@ -35,7 +35,7 @@ def _get_semaphore() -> asyncio.Semaphore: if _SEM is None or _SEM_LIMIT != limit: _SEM = asyncio.Semaphore(limit) _SEM_LIMIT = limit - LOG.info(f"Configured thumbnail generation concurrency limit: {limit}") + LOG.info("Thumbnail generation concurrency limit: %s", limit, extra={"limit": limit}) return _SEM @@ -129,7 +129,11 @@ def _build_ffmpeg_args(media_file: Path, output_file: Path, *, seek_seconds: flo async def _run_ffmpeg(media_file: Path, output_file: Path) -> Path | None: ff_info = await ffprobe(media_file) if not ff_info.has_video(): - LOG.debug(f"Skipping thumbnail generation for '{media_file}' because no video stream exists.") + LOG.debug( + "Skipping thumbnail generation for '%s' because no video stream exists.", + media_file, + extra={"media_file": str(media_file)}, + ) return None output_file.parent.mkdir(parents=True, exist_ok=True) @@ -146,7 +150,12 @@ async def _run_ffmpeg(media_file: Path, output_file: Path) -> Path | None: sem = _get_semaphore() if sem.locked(): limit = _SEM_LIMIT or 1 - LOG.debug(f"Waiting for thumbnail generation slot for '{media_file}'. limit={limit}") + LOG.debug( + "Waiting for a thumbnail generation slot for '%s' (limit=%s).", + media_file, + limit, + extra={"media_file": str(media_file), "limit": limit}, + ) async with sem: last_error: str = "ffmpeg produced an empty thumbnail file" @@ -154,7 +163,17 @@ async def _run_ffmpeg(media_file: Path, output_file: Path) -> Path | None: temp_file.unlink(missing_ok=True) args: list[str] = _build_ffmpeg_args(media_file, temp_file, seek_seconds=attempt_seek) LOG.debug( - f"Generating thumbnail for '{media_file}'. attempt={idx}/{len(attempts)} seek={'none' if attempt_seek is None else f'{attempt_seek:.3f}s'}" + "Generating thumbnail for '%s'. attempt=%s/%s seek=%s", + media_file, + idx, + len(attempts), + "none" if attempt_seek is None else f"{attempt_seek:.3f}s", + extra={ + "media_file": str(media_file), + "attempt": idx, + "attempt_count": len(attempts), + "seek": "none" if attempt_seek is None else f"{attempt_seek:.3f}s", + }, ) try: @@ -171,7 +190,12 @@ async def _run_ffmpeg(media_file: Path, output_file: Path) -> Path | None: stdout, stderr = await proc.communicate() if 0 == proc.returncode and temp_file.exists() and temp_file.stat().st_size > 0: temp_file.replace(output_file) - LOG.info(f"Generated thumbnail '{output_file}' for '{media_file}'.") + LOG.info( + "Generated thumbnail '%s' for '%s'.", + output_file, + media_file, + extra={"media_file": str(media_file), "output_file": str(output_file)}, + ) return output_file if 0 != proc.returncode: @@ -184,7 +208,13 @@ async def _run_ffmpeg(media_file: Path, output_file: Path) -> Path | None: last_error: str = "ffmpeg produced an empty thumbnail file" LOG.debug( - f"Thumbnail generation attempt failed for '{media_file}'. seek={'none' if attempt_seek is None else f'{attempt_seek:.3f}s'}" + "Thumbnail generation attempt failed for '%s'. seek=%s", + media_file, + "none" if attempt_seek is None else f"{attempt_seek:.3f}s", + extra={ + "media_file": str(media_file), + "seek": "none" if attempt_seek is None else f"{attempt_seek:.3f}s", + }, ) temp_file.unlink(missing_ok=True) @@ -224,11 +254,16 @@ async def ensure_thumb(media_file: Path, cache_root: Path, item_id: str | None = task = _IN_PROCESS.get(thumb_id) if task is not None and not task.done(): - LOG.debug(f"Waiting for thumbnail generation for '{media_file}'.") + LOG.debug("Waiting for thumbnail generation for '%s'.", media_file, extra={"media_file": str(media_file)}) else: task = asyncio.create_task(_run_ffmpeg(media_file, cache_file), name=f"thumb-{item_id or media_file.stem}") _IN_PROCESS[thumb_id] = task - LOG.debug(f"Starting thumbnail generation task for '{media_file}' -> '{cache_file}'.") + LOG.debug( + "Starting thumbnail generation for '%s' -> '%s'.", + media_file, + cache_file, + extra={"media_file": str(media_file), "cache_file": str(cache_file)}, + ) try: result: Path | None = await task diff --git a/app/features/streaming/router.py b/app/features/streaming/router.py index 5affd517..3fc34637 100644 --- a/app/features/streaming/router.py +++ b/app/features/streaming/router.py @@ -128,7 +128,11 @@ async def m3u8_create(request: Request, config: Config, app: web.Application) -> else: text = await cls.make_stream(file=realFile) except StreamingError as e: - LOG.exception(e) + LOG.exception( + "Failed to create streaming playlist for '%s'.", + file, + extra={"route": "streaming.playlist", "file_path": file, "mode": mode, "exception_type": type(e).__name__}, + ) return web.json_response(data={"error": str(e)}, status=web.HTTPNotFound.status_code) return web.Response( diff --git a/app/features/tasks/definitions/handlers/generic.py b/app/features/tasks/definitions/handlers/generic.py index 6369bfb7..51c276b7 100644 --- a/app/features/tasks/definitions/handlers/generic.py +++ b/app/features/tasks/definitions/handlers/generic.py @@ -69,7 +69,10 @@ class GenericTaskHandler(BaseHandler): cls._definitions = [model_to_schema(model) for model in models] return cls._definitions except Exception as exc: - LOG.error(f"Failed to load task definitions from database: {exc}") + LOG.exception( + "Failed to load generic task definitions.", + extra={"error": str(exc), "exception_type": type(exc).__name__}, + ) return [] @classmethod @@ -102,7 +105,15 @@ class GenericTaskHandler(BaseHandler): if pattern_str and re.match(pattern_str, url): return definition except Exception as exc: - LOG.error(f"Error while matching definition '{definition.name}': {exc}") + LOG.exception( + "Failed to match a generic task definition.", + extra={ + "definition": definition.name, + "url": url, + "error": str(exc), + "exception_type": type(exc).__name__, + }, + ) return None @@ -120,7 +131,11 @@ class GenericTaskHandler(BaseHandler): """ definition: TaskDefinition | None = await GenericTaskHandler._find_definition(task.url) if definition: - LOG.debug(f"'{task.name}': Matched generic task definition '{definition.name}'.") + LOG.debug( + "Task '%s' matched a generic task definition.", + task.name, + extra={"task_name": task.name, "url": task.url, "definition": definition.name}, + ) return True return False @@ -134,7 +149,16 @@ class GenericTaskHandler(BaseHandler): ytdlp_opts: dict[str, Any] = task.get_ytdlp_opts().get_all() target_url: str = definition.definition.request.url or task.url - LOG.debug(f"{task.name!r}: Fetching '{target_url}' using engine '{definition.definition.engine.type}'.") + LOG.debug( + "Fetching content for task '%s'.", + task.name, + extra={ + "task_name": task.name, + "definition": definition.name, + "url": target_url, + "engine": definition.definition.engine.type, + }, + ) try: body_text, json_data = await GenericTaskHandler._fetch_content( @@ -143,7 +167,16 @@ class GenericTaskHandler(BaseHandler): except httpx.HTTPError as exc: return TaskFailure(message="Failed to fetch target URL.", error=str(exc)) except Exception as exc: - LOG.exception(exc) + LOG.exception( + "Failed to fetch content for task '%s'.", + task.name, + extra={ + "task_name": task.name, + "definition": definition.name, + "url": target_url, + "exception_type": type(exc).__name__, + }, + ) return TaskFailure(message="Failed to fetch target URL.", error=str(exc)) if "json" == definition.definition.response.type and json_data is None: @@ -181,7 +214,9 @@ class GenericTaskHandler(BaseHandler): continue else: LOG.warning( - f"[{definition.name}]: '{task.name}': Unable to generate static archive id for '{url}' in feed. Doing real request to fetch yt-dlp archive id." + "Task '%s' could not generate a static archive ID. Fetching it with yt-dlp.", + task.name, + extra={"definition": definition.name, "task_name": task.name, "url": url}, ) (info, _) = await fetch_info( @@ -194,14 +229,18 @@ class GenericTaskHandler(BaseHandler): if not info: LOG.error( - f"[{definition.name}]: '{task.name}': Failed to extract info for URL '{url}' to generate archive ID. Skipping." + "Task '%s' failed to extract info to generate an archive ID. Skipping item.", + task.name, + extra={"definition": definition.name, "task_name": task.name, "url": url}, ) CACHE.set(cache_key, None) continue if not info.get("id") or not info.get("extractor_key"): LOG.error( - f"[{definition.name}]: '{task.name}': Incomplete info extracted for URL '{url}' to generate archive ID. Skipping." + "Task '%s' returned incomplete info while generating an archive ID. Skipping item.", + task.name, + extra={"definition": definition.name, "task_name": task.name, "url": url}, ) CACHE.set(cache_key, None) continue @@ -297,7 +336,17 @@ class GenericTaskHandler(BaseHandler): try: json_data: dict[str, Any] = response.json() except Exception as exc: - LOG.error(f"Failed to decode JSON response from '{url}': {exc}") + LOG.exception( + "Task definition '%s' returned invalid JSON for '%s'.", + definition.name, + url, + extra={ + "definition": definition.name, + "url": url, + "error": str(exc), + "exception_type": type(exc).__name__, + }, + ) return response.text, None return response.text, json_data @@ -327,7 +376,11 @@ class GenericTaskHandler(BaseHandler): from selenium.webdriver.support import expected_conditions as EC from selenium.webdriver.support.ui import WebDriverWait except ImportError as exc: - LOG.error(f"Selenium engine requested but selenium is not installed: {exc!s}.") + LOG.exception( + "Task definition '%s' requested Selenium, but Selenium is not installed.", + definition.name, + extra={"definition": definition.name, "error": str(exc), "exception_type": type(exc).__name__}, + ) return (None, None) options_map: dict[str, Any] = definition.definition.engine.options @@ -340,7 +393,12 @@ class GenericTaskHandler(BaseHandler): browser: str = str(options_map.get("browser", "chrome")).lower() if "chrome" != browser: - LOG.error(f"Unsupported selenium browser '{browser}'. Only 'chrome' is supported.") + LOG.error( + "Task definition '%s' requested unsupported Selenium browser '%s'.", + definition.name, + browser, + extra={"definition": definition.name, "browser": browser}, + ) return (None, None) arguments: list[str] | str = options_map.get("arguments", ["--headless", "--disable-gpu"]) @@ -422,7 +480,9 @@ class GenericTaskHandler(BaseHandler): link_values: list[str] = extracted.get("link", []) if not link_values: - LOG.debug(f"Definition '{definition.name}' produced no link values.") + LOG.debug( + "Definition '%s' produced no link values.", definition.name, extra={"definition": definition.name} + ) return [] total_items: int = len(link_values) @@ -457,7 +517,11 @@ class GenericTaskHandler(BaseHandler): base_url: str, ) -> list[dict[str, str]]: if json_data is None: - LOG.debug(f"Definition '{definition.name}' expects JSON but no data was parsed.") + LOG.debug( + "Definition '%s' expects JSON but no data was parsed.", + definition.name, + extra={"definition": definition.name}, + ) return [] if definition.definition.parse.get("items"): @@ -496,7 +560,11 @@ class GenericTaskHandler(BaseHandler): container_type = container.get("type", "css") container_selector = container.get("selector") or container.get("expression") or "" if not container_selector: - LOG.error(f"Container missing selector/expression. Definition '{definition.name}'.") + LOG.error( + "Container missing selector/expression. Definition '%s'.", + definition.name, + extra={"definition": definition.name}, + ) return [] container_fields = container.get("fields", {}) @@ -550,7 +618,11 @@ class GenericTaskHandler(BaseHandler): container_fields = container.get("fields", {}) if "jsonpath" != container_type: - LOG.error(f"JSON response requires container selector type 'jsonpath'. Definition '{definition.name}'.") + LOG.error( + "JSON response requires container selector type 'jsonpath'. Definition '%s'.", + definition.name, + extra={"definition": definition.name, "container_type": container_type}, + ) return [] nodes: Any = GenericTaskHandler._json_search(json_data, container_selector) @@ -606,7 +678,16 @@ class GenericTaskHandler(BaseHandler): try: pattern: re.Pattern[str] = re.compile(rule.expression, re.MULTILINE | re.DOTALL) except re.error as exc: - LOG.error(f"Invalid regex expression '{rule.expression}': {exc}") + LOG.exception( + "Invalid regex expression '%s'.", + rule.expression, + extra={ + "field": field, + "expression": rule.expression, + "error": str(exc), + "exception_type": type(exc).__name__, + }, + ) return values for match in pattern.finditer(target): @@ -617,7 +698,12 @@ class GenericTaskHandler(BaseHandler): return values - LOG.error(f"Unsupported extraction type '{rule.type}' for JSON data in field '{field}'.") + LOG.error( + "Unsupported extraction type '%s' for JSON data in field '%s'.", + rule.type, + field, + extra={"field": field, "rule_type": rule.type}, + ) return values @staticmethod @@ -625,7 +711,11 @@ class GenericTaskHandler(BaseHandler): try: return jmespath.search(expression, data) except Exception as exc: - LOG.error(f"JSONPath search failed for expression '{expression}': {exc}") + LOG.exception( + "JSONPath search failed for expression '%s'.", + expression, + extra={"expression": expression, "error": str(exc), "exception_type": type(exc).__name__}, + ) return None @staticmethod @@ -660,7 +750,16 @@ class GenericTaskHandler(BaseHandler): try: pattern: re.Pattern[str] = re.compile(rule.expression, re.MULTILINE | re.DOTALL) except re.error as exc: - LOG.error(f"Invalid regex expression '{rule.expression}': {exc}") + LOG.exception( + "Invalid regex expression '%s'.", + rule.expression, + extra={ + "field": field, + "expression": rule.expression, + "error": str(exc), + "exception_type": type(exc).__name__, + }, + ) return values for match in pattern.finditer(html): @@ -704,7 +803,12 @@ class GenericTaskHandler(BaseHandler): try: return match.group(attribute) except (IndexError, KeyError): - LOG.debug(f"Regex group '{attribute}' not found in pattern '{match.re.pattern}'.") + LOG.debug( + "Regex group '%s' not found in pattern '%s'.", + attribute, + match.re.pattern, + extra={"attribute": attribute, "pattern": match.re.pattern}, + ) return None if match.groupdict(): diff --git a/app/features/tasks/definitions/handlers/rss.py b/app/features/tasks/definitions/handlers/rss.py index 964afbef..40108839 100644 --- a/app/features/tasks/definitions/handlers/rss.py +++ b/app/features/tasks/definitions/handlers/rss.py @@ -28,7 +28,11 @@ class RssGenericHandler(BaseHandler): @staticmethod async def can_handle(task: HandleTask) -> bool: - LOG.debug(f"'{task.name}': Checking if task URL is parsable RSS feed: {task.url}") + LOG.debug( + "Checking if task '%s' uses a parsable RSS feed.", + task.name, + extra={"task_name": task.name, "url": task.url}, + ) return RssGenericHandler.parse(task.url) is not None @staticmethod @@ -52,7 +56,11 @@ class RssGenericHandler(BaseHandler): from defusedxml.ElementTree import fromstring feed_url: str = parsed["url"] - LOG.debug(f"'{task.name}': Fetching RSS/Atom feed from {feed_url}") + LOG.debug( + "Fetching RSS/Atom feed for task '%s'.", + task.name, + extra={"task_name": task.name, "feed_url": feed_url}, + ) response = await RssGenericHandler.request(url=feed_url, ytdlp_opts=params) response.raise_for_status() @@ -73,7 +81,12 @@ class RssGenericHandler(BaseHandler): # Try to parse as Atom feed first entries = root.findall("atom:entry", ns) if entries: - LOG.debug(f"'{task.name}': Detected Atom feed format with {len(entries)} entries") + LOG.debug( + "'%s': Detected Atom feed format with %s entries", + task.name, + len(entries), + extra={"task_name": task.name, "feed_url": feed_url, "entry_count": len(entries)}, + ) for entry in entries: link_elem: Element | None = entry.find("atom:link[@rel='alternate']", ns) if link_elem is None: @@ -84,7 +97,11 @@ class RssGenericHandler(BaseHandler): url = link_elem.get("href", "") if not url: - LOG.warning(f"'{task.name}': Atom entry missing URL. Skipping.") + LOG.warning( + "'%s': Atom entry missing URL. Skipping.", + task.name, + extra={"task_name": task.name, "feed_url": feed_url}, + ) continue title_elem: Element | None = entry.find("atom:title", ns) @@ -98,7 +115,12 @@ class RssGenericHandler(BaseHandler): else: # Try to parse as RSS feed rss_items = root.findall(".//item") - LOG.debug(f"'{task.name}': Detected RSS feed format with {len(rss_items)} items") + LOG.debug( + "'%s': Detected RSS feed format with %s items", + task.name, + len(rss_items), + extra={"task_name": task.name, "feed_url": feed_url, "entry_count": len(rss_items)}, + ) for item in rss_items: # Try different link element names (link, url, media:content) @@ -119,7 +141,11 @@ class RssGenericHandler(BaseHandler): url = enclosure_elem.get("url", "") if not url: - LOG.warning(f"'{task.name}': RSS item missing URL. Skipping.") + LOG.warning( + "'%s': RSS item missing URL. Skipping.", + task.name, + extra={"task_name": task.name, "feed_url": feed_url}, + ) continue title_elem = item.find("title") @@ -156,7 +182,16 @@ class RssGenericHandler(BaseHandler): except httpx.HTTPError as exc: return TaskFailure(message="Failed to fetch RSS/Atom feed.", error=str(exc)) except Exception as exc: - LOG.exception(exc) + LOG.exception( + "Failed to fetch RSS/Atom feed for task '%s'.", + task.name, + extra={ + "task_id": task.id, + "task_name": task.name, + "url": task.url, + "exception_type": type(exc).__name__, + }, + ) return TaskFailure(message="Failed to fetch RSS/Atom feed.", error=str(exc)) task_items: list[TaskItem] = [] @@ -176,12 +211,17 @@ class RssGenericHandler(BaseHandler): if CACHE.has(cache_key): archive_id = CACHE.get(cache_key) if not archive_id: - LOG.debug(f"'{task.name}': Cached failure for URL '{url}'. Skipping.") + LOG.debug( + "Task '%s' has a cached archive ID lookup failure. Skipping item.", + task.name, + extra={"task_name": task.name, "url": url}, + ) continue else: LOG.warning( - f"'{task.name}': Unable to generate static archive ID for '{url}' in feed. " - "Doing real request to fetch yt-dlp archive ID." + "Task '%s' could not generate a static archive ID. Fetching it with yt-dlp.", + task.name, + extra={"task_name": task.name, "url": url}, ) (info, _) = await fetch_info( @@ -194,14 +234,18 @@ class RssGenericHandler(BaseHandler): if not info: LOG.error( - f"'{task.name}': Failed to extract info for URL '{url}' to generate archive ID. Skipping." + "Task '%s' failed to extract info to generate an archive ID. Skipping item.", + task.name, + extra={"task_name": task.name, "url": url}, ) CACHE.set(cache_key, None) continue if not info.get("id") or not info.get("extractor_key"): LOG.error( - f"'{task.name}': Incomplete info extracted for URL '{url}' to generate archive ID. Skipping." + "Task '%s' returned incomplete info while generating an archive ID. Skipping item.", + task.name, + extra={"task_name": task.name, "url": url}, ) CACHE.set(cache_key, None) continue diff --git a/app/features/tasks/definitions/handlers/tver.py b/app/features/tasks/definitions/handlers/tver.py index ff413e00..db411e01 100644 --- a/app/features/tasks/definitions/handlers/tver.py +++ b/app/features/tasks/definitions/handlers/tver.py @@ -24,7 +24,11 @@ class TverHandler(BaseHandler): @staticmethod async def can_handle(task: HandleTask) -> bool: - LOG.debug(f"Checking if task '{task.name}' is using parsable Tver series URL: {task.url}") + LOG.debug( + "Checking if task '%s' uses a parsable Tver series URL.", + task.name, + extra={"task_name": task.name, "url": task.url}, + ) return TverHandler.parse(task.url) is not None @staticmethod @@ -55,7 +59,11 @@ class TverHandler(BaseHandler): return {"platform_uid": platform_uid, "platform_token": platform_token} except Exception as exc: - LOG.warning(f"Failed to create tver session: {exc}") + LOG.warning( + "Failed to create Tver session.", + extra={"error": str(exc), "exception_type": type(exc).__name__}, + exc_info=True, + ) return None @staticmethod @@ -83,7 +91,11 @@ class TverHandler(BaseHandler): feed_url = TverHandler.SERIES_API.format(id=series_id) - LOG.debug(f"Fetching '{task.name}' episodes from tver series {series_id}.") + LOG.debug( + "Fetching Tver episodes for task '%s'.", + task.name, + extra={"task_name": task.name, "series_id": series_id, "feed_url": feed_url}, + ) response = await TverHandler.request( url=feed_url, @@ -105,7 +117,11 @@ class TverHandler(BaseHandler): try: contents = data.get("result", {}).get("contents", []) if not contents: - LOG.warning(f"No contents found in tver series response for '{task.name}'.") + LOG.warning( + "No contents found in Tver series response for '%s'.", + task.name, + extra={"task_name": task.name, "series_id": series_id, "feed_url": feed_url}, + ) return feed_url, items, has_items season_block = contents[0] if contents else {} @@ -116,9 +132,13 @@ class TverHandler(BaseHandler): continue content = episode_data.get("content", {}) - episode_id = content.pop("id") + episode_id = content.pop("id", None) if not episode_id: - LOG.warning(f"Episode missing ID in '{task.name}' feed. Skipping.") + LOG.warning( + "Episode missing ID in '%s' feed. Skipping.", + task.name, + extra={"task_name": task.name, "series_id": series_id, "feed_url": feed_url}, + ) continue url = f"https://tver.jp/episodes/{episode_id}" @@ -129,7 +149,9 @@ class TverHandler(BaseHandler): archive_id = id_dict.get("archive_id") if not archive_id: LOG.warning( - f"Could not compute archive ID for episode '{episode_id}' in '{task.name}' feed. Skipping." + "Task '%s' could not compute an archive ID for an episode. Skipping item.", + task.name, + extra={"task_name": task.name, "series_id": series_id, "episode_id": episode_id, "url": url}, ) continue @@ -139,7 +161,18 @@ class TverHandler(BaseHandler): ) except Exception as exc: - LOG.warning(f"Error parsing tver episodes for '{task.name}': {exc}") + LOG.warning( + "Failed to parse Tver episodes for task '%s'.", + task.name, + extra={ + "task_id": task.id, + "task_name": task.name, + "series_id": series_id, + "error": str(exc), + "exception_type": type(exc).__name__, + }, + exc_info=True, + ) return feed_url, items, has_items @@ -156,7 +189,17 @@ class TverHandler(BaseHandler): except httpx.HTTPError as exc: return TaskFailure(message="Failed to fetch Tver feed.", error=str(exc)) except Exception as exc: - LOG.exception(exc) + LOG.exception( + "Failed to fetch Tver feed for task '%s'.", + task.name, + extra={ + "task_id": task.id, + "task_name": task.name, + "url": task.url, + "series_id": series_id, + "exception_type": type(exc).__name__, + }, + ) return TaskFailure(message="Failed to fetch Tver feed.", error=str(exc)) task_items: list[TaskItem] = [] diff --git a/app/features/tasks/definitions/handlers/twitch.py b/app/features/tasks/definitions/handlers/twitch.py index 8aac9b29..0508ede1 100644 --- a/app/features/tasks/definitions/handlers/twitch.py +++ b/app/features/tasks/definitions/handlers/twitch.py @@ -23,7 +23,11 @@ class TwitchHandler(BaseHandler): @staticmethod async def can_handle(task: HandleTask) -> bool: - LOG.debug(f"Checking if task '{task.name}' is using parsable Twitch URL: {task.url}") + LOG.debug( + "Checking if task '%s' uses a parsable Twitch URL.", + task.name, + extra={"task_name": task.name, "url": task.url}, + ) return TwitchHandler.parse(task.url) is not None @staticmethod @@ -36,7 +40,7 @@ class TwitchHandler(BaseHandler): feed_url: str = TwitchHandler.FEED.format(handle=handle_name) - LOG.debug(f"Fetching '{task.name}' feed.") + LOG.debug("Fetching '%s' feed.", task.name, extra={"task_name": task.name, "feed_url": feed_url}) response = await TwitchHandler.request(url=feed_url, ytdlp_opts=params) response.raise_for_status() @@ -48,14 +52,22 @@ class TwitchHandler(BaseHandler): link_elem: Element[str] | None = entry.find("link") url: str = link_elem.text.strip() if link_elem is not None and link_elem.text else "" if not url: - LOG.warning(f"Entry in '{task.name}' feed is missing URL. Skipping entry.") + LOG.warning( + "Entry in '%s' feed is missing URL. Skipping entry.", + task.name, + extra={"task_name": task.name, "feed_url": feed_url}, + ) continue match: re.Match[str] | None = re.search( r"^https?://(?:www\.)?twitch\.tv/videos/(?P\d+)(?:[/?].*)?$", url ) if not match: - LOG.warning(f"URL in '{task.name}' feed does not look like a VOD link: {url}") + LOG.warning( + "Task '%s' produced a feed entry that does not look like a Twitch VOD link. Skipping entry.", + task.name, + extra={"task_name": task.name, "url": url}, + ) continue vid: str = match.group("id") @@ -68,7 +80,11 @@ class TwitchHandler(BaseHandler): id_dict = get_archive_id(url) archive_id: str | None = id_dict.get("archive_id") if not archive_id: - LOG.warning(f"Could not compute archive ID for video '{vid}' in '{task.name}' feed. Skipping entry.") + LOG.warning( + "Task '%s' could not compute an archive ID for a Twitch video. Skipping entry.", + task.name, + extra={"task_name": task.name, "video_id": vid, "url": url}, + ) continue items.append({"id": vid, "url": url, "title": title, "archive_id": archive_id}) @@ -88,7 +104,16 @@ class TwitchHandler(BaseHandler): except httpx.HTTPError as exc: return TaskFailure(message="Failed to fetch Twitch feed.", error=str(exc)) except Exception as exc: - LOG.exception(exc) + LOG.exception( + "Failed to fetch Twitch feed for task '%s'.", + task.name, + extra={ + "task_id": task.id, + "task_name": task.name, + "url": task.url, + "exception_type": type(exc).__name__, + }, + ) return TaskFailure(message="Failed to fetch Twitch feed.", error=str(exc)) task_items: list[TaskItem] = [] diff --git a/app/features/tasks/definitions/handlers/youtube.py b/app/features/tasks/definitions/handlers/youtube.py index 777f0c5e..d708ab2d 100644 --- a/app/features/tasks/definitions/handlers/youtube.py +++ b/app/features/tasks/definitions/handlers/youtube.py @@ -29,7 +29,11 @@ class YoutubeHandler(BaseHandler): @staticmethod async def can_handle(task: HandleTask) -> bool: - LOG.debug(f"'{task.name}': Checking if task URL is parsable YouTube URL: {task.url}") + LOG.debug( + "Checking if task '%s' uses a parsable YouTube URL.", + task.name, + extra={"task_name": task.name, "url": task.url}, + ) return YoutubeHandler.parse(task.url) is not None @staticmethod @@ -49,7 +53,7 @@ class YoutubeHandler(BaseHandler): from defusedxml.ElementTree import fromstring feed_url: str = YoutubeHandler.FEED.format(type=parsed["type"], id=parsed["id"]) - LOG.debug(f"'{task.name}': Fetching feed.") + LOG.debug("'%s': Fetching feed.", task.name, extra={"task_name": task.name, "feed_url": feed_url}) response = await YoutubeHandler.request(url=feed_url, ytdlp_opts=params) response.raise_for_status() @@ -67,7 +71,11 @@ class YoutubeHandler(BaseHandler): vid_elem: Element[str] | None = entry.find("yt:videoId", ns) vid: str = vid_elem.text if vid_elem is not None and vid_elem.text else "" if not vid: - LOG.warning(f"'{task.name}': Entry in the feed is missing a video ID. Skipping.") + LOG.warning( + "'%s': Entry in the feed is missing a video ID. Skipping.", + task.name, + extra={"task_name": task.name, "feed_url": feed_url}, + ) continue url: str = f"https://www.youtube.com/watch?v={vid}" @@ -75,7 +83,11 @@ class YoutubeHandler(BaseHandler): id_dict: dict[str, str | None] = get_archive_id(url) archive_id: str | None = id_dict.get("archive_id") if not archive_id: - LOG.warning(f"'{task.name}': Could not compute archive ID for video '{vid}' in feed. Skipping.") + LOG.warning( + "Task '%s' could not compute an archive ID for a YouTube video. Skipping item.", + task.name, + extra={"task_name": task.name, "video_id": vid, "url": url}, + ) continue title_elem: Element[str] | None = entry.find("atom:title", ns) @@ -103,7 +115,16 @@ class YoutubeHandler(BaseHandler): except httpx.HTTPError as exc: return TaskFailure(message="Failed to fetch YouTube feed.", error=str(exc)) except Exception as exc: - LOG.exception(exc) + LOG.exception( + "Failed to fetch YouTube feed for task '%s'.", + task.name, + extra={ + "task_id": task.id, + "task_name": task.name, + "url": task.url, + "exception_type": type(exc).__name__, + }, + ) return TaskFailure(message="Failed to fetch YouTube feed.", error=str(exc)) task_items: list[TaskItem] = [] diff --git a/app/features/tasks/definitions/migration.py b/app/features/tasks/definitions/migration.py index 74d519c9..94872fc6 100644 --- a/app/features/tasks/definitions/migration.py +++ b/app/features/tasks/definitions/migration.py @@ -48,7 +48,11 @@ class Migration(FeatureMigration): await self._repo.create(normalized) inserted += 1 except Exception as exc: - LOG.exception("Failed to insert task definition '%s': %s", normalized.get("name"), exc) + LOG.exception( + "Failed to insert task definition '%s'.", + normalized.get("name"), + extra={"definition": normalized.get("name"), "exception_type": type(exc).__name__}, + ) finally: await self._move_file(path) @@ -62,13 +66,21 @@ class Migration(FeatureMigration): try: content = path.read_text(encoding="utf-8") except Exception as exc: - LOG.error("Failed to read task definition '%s': %s", path, exc) + LOG.exception( + "Failed to read task definition '%s'.", + path, + extra={"path": str(path), "exception_type": type(exc).__name__}, + ) return None try: payload = json.loads(content) except Exception as exc: - LOG.error("Failed to parse JSON for '%s': %s", path, exc) + LOG.exception( + "Failed to parse JSON for task definition '%s'.", + path, + extra={"path": str(path), "exception_type": type(exc).__name__}, + ) return None if not isinstance(payload, dict): diff --git a/app/features/tasks/definitions/router.py b/app/features/tasks/definitions/router.py index 56ee5054..e1a829e9 100644 --- a/app/features/tasks/definitions/router.py +++ b/app/features/tasks/definitions/router.py @@ -95,7 +95,11 @@ async def task_definitions_create(request: Request, encoder: Encoder, notify: Ev except ValueError as exc: return web.json_response(data={"error": str(exc)}, status=web.HTTPBadRequest.status_code) except Exception as exc: - LOG.exception(exc) + LOG.exception( + "Failed to create task definition '%s'.", + getattr(definition_input, "name", None), + extra={"definition": getattr(definition_input, "name", None), "exception_type": type(exc).__name__}, + ) return web.json_response( data={"error": "Failed to create task definition."}, status=web.HTTPInternalServerError.status_code, @@ -144,7 +148,15 @@ async def task_definitions_update(request: Request, encoder: Encoder, notify: Ev except ValueError as exc: return web.json_response(data={"error": str(exc)}, status=web.HTTPBadRequest.status_code) except Exception as exc: - LOG.exception(exc) + LOG.exception( + "Failed to update task definition '%s'.", + definition_input.name, + extra={ + "definition_id": identifier, + "definition": definition_input.name, + "exception_type": type(exc).__name__, + }, + ) return web.json_response( data={"error": "Failed to update task definition."}, status=web.HTTPInternalServerError.status_code, @@ -202,7 +214,11 @@ async def task_definitions_patch(request: Request, encoder: Encoder, notify: Eve except ValueError as exc: return web.json_response(data={"error": str(exc)}, status=web.HTTPBadRequest.status_code) except Exception as exc: - LOG.exception(exc) + LOG.exception( + "Failed to patch task definition '%s'.", + identifier, + extra={"definition_id": identifier, "exception_type": type(exc).__name__}, + ) return web.json_response( data={"error": "Failed to patch task definition."}, status=web.HTTPInternalServerError.status_code, @@ -228,7 +244,11 @@ async def task_definitions_delete(request: Request, encoder: Encoder, notify: Ev except KeyError as exc: return web.json_response(data={"error": str(exc)}, status=web.HTTPNotFound.status_code) except Exception as exc: - LOG.exception(exc) + LOG.exception( + "Failed to delete task definition '%s'.", + identifier, + extra={"definition_id": identifier, "exception_type": type(exc).__name__}, + ) return web.json_response( data={"error": "Failed to delete task definition."}, status=web.HTTPInternalServerError.status_code, diff --git a/app/features/tasks/definitions/service.py b/app/features/tasks/definitions/service.py index 5e2aa50a..a5ae4ef9 100644 --- a/app/features/tasks/definitions/service.py +++ b/app/features/tasks/definitions/service.py @@ -58,7 +58,16 @@ class TaskHandle: CronSim(timer, datetime.now(UTC)) except Exception as e: timer = "15 */1 * * *" - LOG.error(f"Invalid timer format. '{e!s}'. Defaulting to '{timer}'.") + LOG.error( + "Invalid task handler timer '%s'; using default '%s'.", + self._config.tasks_handler_timer, + timer, + extra={ + "timer": self._config.tasks_handler_timer, + "default_timer": timer, + "exception_type": type(e).__name__, + }, + ) self._scheduler.add( timer=timer, @@ -82,7 +91,11 @@ class TaskHandle: continue if not task.get_ytdlp_opts().get_all().get("download_archive"): - LOG.debug(f"Task '{task.name}' does not have an archive file configured.") + LOG.debug( + "Task '%s' does not have an archive file configured.", + task.name, + extra={"task_id": task.id, "task_name": task.name}, + ) s["f"].append(task.name) continue @@ -97,7 +110,11 @@ class TaskHandle: handler_groups[handler_name] = [] handler_groups[handler_name].append((task, handler)) except Exception as e: - LOG.error(f"Failed to handle task '{task.name}'. '{e!s}'.") + LOG.exception( + "Failed to find handler for task '%s'.", + task.name, + extra={"task_id": task.id, "task_name": task.name, "exception_type": type(e).__name__}, + ) s["f"].append(task.name) for tasks_with_handlers in handler_groups.values(): @@ -114,7 +131,17 @@ class TaskHandle: t.add_done_callback(lambda fut, t=task: self._handle_exception(fut, t)) dispatches.append((task, handler, t)) except Exception as e: - LOG.error(f"Failed to dispatch task '{task.name}'. '{e!s}'.") + LOG.exception( + "Failed to schedule handler '%s' for task '%s'.", + handler.__name__, + task.name, + extra={ + "task_id": task.id, + "task_name": task.name, + "handler_name": handler.__name__, + "exception_type": type(e).__name__, + }, + ) s["f"].append(task.name) if dispatches: @@ -130,13 +157,26 @@ class TaskHandle: continue if result is None: - LOG.error(f"Handler '{handler.__name__}' returned no result for task '{task.name}'.") + LOG.error( + "Task handler returned no result.", + extra={"task_id": task.id, "task_name": task.name, "handler_name": handler.__name__}, + ) s["f"].append(task.name) if len(tasks) > 0: LOG.info( - f"Tasks handler summary: Handled: {len(s['h'])}, Unhandled: {len(s['u'])}, Disabled: {len(s['d'])}, Failed: {len(s['f'])}." + "Task handler summary: handled %s, unhandled %s, disabled %s, failed %s.", + len(s["h"]), + len(s["u"]), + len(s["d"]), + len(s["f"]), + extra={ + "handled_count": len(s["h"]), + "unhandled_count": len(s["u"]), + "disabled_count": len(s["d"]), + "failed_count": len(s["f"]), + }, ) async def _dispatch(self, task: HandleTask, handler: type, delay: float) -> TaskResult | TaskFailure | None: @@ -153,7 +193,12 @@ class TaskHandle: """ if delay > 0: - LOG.debug(f"Delaying dispatch of task '{task.name}' by {delay:.1f} seconds.") + LOG.debug( + "Delaying dispatch of task '%s' by %.1f seconds.", + task.name, + delay, + extra={"task_id": task.id, "task_name": task.name, "delay_s": round(delay, 1)}, + ) await asyncio.sleep(delay) return await self.dispatch(task, handler=handler) @@ -162,7 +207,11 @@ class TaskHandle: return if exc := fut.exception(): - LOG.error(f"Exception while handling task '{task.name}': {exc}") + LOG.exception( + "Task handler raised after dispatch.", + extra={"task_id": task.id, "task_name": task.name, "exception_type": type(exc).__name__}, + exc_info=(type(exc), exc, exc.__traceback__), + ) async def _find_handler(self, task: HandleTask) -> type | None: for cls in self._handlers: @@ -170,7 +219,17 @@ class TaskHandle: if await Services.get_instance().handle_async(handler=cls.can_handle, task=task): return cls except Exception as e: - LOG.exception(e) + LOG.exception( + "Handler '%s' capability check failed for task '%s'.", + cls.__name__, + task.name, + extra={ + "task_id": task.id, + "task_name": task.name, + "handler_name": cls.__name__, + "exception_type": type(e).__name__, + }, + ) continue return None @@ -204,11 +263,31 @@ class TaskHandle: extraction: TaskResult | TaskFailure = await services.handle_async( handler=handler.extract, task=task, config=self._config ) - except NotImplementedError: - LOG.error(f"Handler '{handler.__name__}' does not implement extract().") + except NotImplementedError as exc: + LOG.exception( + "Task handler '%s' does not implement extraction for task '%s'.", + handler.__name__, + task.name, + extra={ + "task_id": task.id, + "task_name": task.name, + "handler_name": handler.__name__, + "exception_type": type(exc).__name__, + }, + ) return TaskFailure(message="Handler does not support extraction.") except Exception as exc: - LOG.exception(exc) + LOG.exception( + "Handler '%s' extraction failed for task '%s'.", + handler.__name__, + task.name, + extra={ + "task_id": task.id, + "task_name": task.name, + "handler_name": handler.__name__, + "exception_type": type(exc).__name__, + }, + ) raise if isinstance(extraction, TaskFailure): @@ -216,12 +295,21 @@ class TaskHandle: if extraction.error and extraction.error != extraction.message: msg = f"{msg} {extraction.error}" - LOG.error(f"Handler '{handler.__name__}' failed to extract items for task '{task.name}': {msg}") + LOG.error( + "Task handler failed to extract items.", + extra={"task_id": task.id, "task_name": task.name, "handler_name": handler.__name__, "error": msg}, + ) return extraction if not isinstance(extraction, TaskResult): LOG.error( - f"Handler '{handler.__name__}' returned unexpected result type '{type(extraction).__name__}'.", + "Task handler returned unexpected result type.", + extra={ + "task_id": task.id, + "task_name": task.name, + "handler_name": handler.__name__, + "result_type": type(extraction).__name__, + }, ) return TaskFailure( message="Handler returned invalid result type.", metadata={"type": type(extraction).__name__} @@ -249,7 +337,15 @@ class TaskHandle: for item in raw_items: if not isinstance(item, TaskItem): - LOG.warning(f"Handler '{handler.__name__}' returned unexpected result: {item!r}") + LOG.warning( + "Task handler returned unexpected item type.", + extra={ + "task_id": task.id, + "task_name": task.name, + "handler_name": handler.__name__, + "item_type": type(item).__name__, + }, + ) continue url: str = item.url @@ -258,7 +354,10 @@ class TaskHandle: archive_id: str | None = item.archive_id if not archive_id: - LOG.warning(f"'{task.name}': Item with URL '{url}' is missing an archive ID. Skipping.") + LOG.warning( + "Task handler item is missing an archive ID.", + extra={"task_id": task.id, "task_name": task.name, "handler_name": handler.__name__, "url": url}, + ) continue if archive_id in queued: @@ -287,12 +386,25 @@ class TaskHandle: if not filtered: if raw_items: LOG.debug( - f"Handler '{handler.__name__}' produced '{len(raw_items)}' for '{task.name}' items, none queued after filtering." + "Task handler produced items, but none were queued after filtering.", + extra={ + "task_id": task.id, + "task_name": task.name, + "handler_name": handler.__name__, + "raw_count": len(raw_items), + }, ) return TaskResult(items=[], metadata=metadata) LOG.info( - f"Handler '{handler.__name__}' Found '{len(filtered)}' new items for '{task.name}' (raw={len(raw_items)})." + "Task handler found new items.", + extra={ + "task_id": task.id, + "task_name": task.name, + "handler_name": handler.__name__, + "item_count": len(filtered), + "raw_count": len(raw_items), + }, ) base_item = Item.format( @@ -367,7 +479,12 @@ class TaskHandle: try: matched = await services.handle_async(handler=handler_cls.can_handle, task=task) except Exception as exc: # pragma: no cover - defensive - LOG.exception(exc) + LOG.exception( + "Handler '%s' inspection capability check failed for '%s'.", + handler_cls.__name__, + url, + extra={"handler_name": handler_cls.__name__, "url": url, "exception_type": type(exc).__name__}, + ) message = str(exc) return TaskFailure( message=message, @@ -405,7 +522,12 @@ class TaskHandle: metadata={**base_metadata, "supported": False}, ) except Exception as exc: - LOG.exception(exc) + LOG.exception( + "Handler '%s' manual inspection failed for '%s'.", + handler_cls.__name__, + url, + extra={"handler_name": handler_cls.__name__, "url": url, "exception_type": type(exc).__name__}, + ) message = str(exc) return TaskFailure( message=message, @@ -426,7 +548,8 @@ class TaskHandle: if not isinstance(extraction, TaskResult): LOG.error( - f"Handler '{handler_cls.__name__}' returned unexpected result type '{type(extraction).__name__}' during inspection.", + "Task handler returned unexpected result type during inspection.", + extra={"handler_name": handler_cls.__name__, "url": url, "result_type": type(extraction).__name__}, ) extraction = TaskResult() diff --git a/app/features/tasks/migration.py b/app/features/tasks/migration.py index 77e4928a..ada72926 100644 --- a/app/features/tasks/migration.py +++ b/app/features/tasks/migration.py @@ -36,7 +36,11 @@ class Migration(FeatureMigration): try: items: list[dict[str, Any]] | None = json.loads(self._source_file.read_text()) except Exception as exc: - LOG.exception("Failed to read %s: %s. Ignoring", self._source_file, exc) + LOG.exception( + "Failed to read tasks migration file '%s'. Ignoring.", + self._source_file, + extra={"file_path": str(self._source_file), "exception_type": type(exc).__name__}, + ) await self._move_file(self._source_file) return @@ -54,7 +58,11 @@ class Migration(FeatureMigration): await self._repo.create(normalized) inserted += 1 except Exception as exc: - LOG.exception("Failed to insert task '%s': %s", normalized["name"], exc) + LOG.exception( + "Failed to insert task '%s'.", + normalized["name"], + extra={"task_name": normalized["name"], "exception_type": type(exc).__name__}, + ) LOG.info("Migrated %s task(s) from %s.", inserted, self._source_file) await self._move_file(self._source_file) diff --git a/app/features/tasks/router.py b/app/features/tasks/router.py index 0f15e14d..aa601e23 100644 --- a/app/features/tasks/router.py +++ b/app/features/tasks/router.py @@ -94,7 +94,11 @@ def _offset_timer(timer: str, index: int) -> str: return f"{minute} {hour} {dom} {month} {dow}" except Exception as e: - LOG.warning(f"Failed to offset timer '{timer}': {e}") + LOG.warning( + "Failed to offset task timer.", + extra={"timer": timer, "index": index, "error": str(e), "exception_type": type(e).__name__}, + exc_info=True, + ) return timer @@ -137,10 +141,10 @@ async def _get_info(url: str, preset: str) -> tuple[str | None, str | None]: return (name, converted_url) except TimeoutError: - LOG.debug(f"Timeout while inferring name from '{url}'") + LOG.debug("Timeout while inferring name from '%s'.", url, extra={"url": url, "preset": preset}) return (None, None) except Exception as e: - LOG.debug(f"Failed to infer name from '{url}': {e}") + LOG.debug("Failed to infer task name from URL.", extra={"url": url, "preset": preset, "error": str(e)}) return (None, None) @@ -234,12 +238,12 @@ async def tasks_add( for idx, item in enumerate(data): if not isinstance(item, dict): - LOG.warning(f"Skipping item {idx}: not a dict") + LOG.warning("Skipping item %s: not a dict.", idx, extra={"index": idx}) continue url = str(item.get("url", "")).strip() if not url: - LOG.debug(f"Skipping item {idx}: empty URL") + LOG.debug("Skipping item %s: empty URL.", idx, extra={"index": idx}) continue inferred_name, converted_url = await _get_info(url, item.get("preset", first_task.preset)) @@ -293,7 +297,12 @@ async def tasks_add( data=ConfigEvent(feature=CEFeature.TASKS, action=CEAction.CREATE, data=saved), ) except ValueError as exc: - LOG.warning(f"Failed to create task {idx}: {exc}") + LOG.warning( + "Failed to create task from request item %s.", + idx, + extra={"index": idx, "error": str(exc), "exception_type": type(exc).__name__}, + exc_info=True, + ) continue if len(created_tasks) == 0: @@ -482,7 +491,16 @@ async def task_handler_inspect(request: Request, handler: TaskHandle, encoder: E url=url, preset=preset, handler_name=handler_name, static_only=static_only ) except Exception as e: - LOG.exception(e) + LOG.exception( + "Failed to inspect task handler for '%s'.", + url, + extra={ + "handler_name": handler_name, + "url": url, + "static_only": static_only, + "exception_type": type(e).__name__, + }, + ) return web.json_response( {"error": "Failed to inspect handler.", "message": str(e)}, status=web.HTTPInternalServerError.status_code, @@ -631,7 +649,11 @@ async def task_metadata(request: Request, repo: TasksRepository, config: Config, if not save_path.exists(): save_path.mkdir(parents=True, exist_ok=True) except Exception as e: - LOG.warning(f"Failed to resolve final path from outtmpl. '{e!s}'") + LOG.warning( + "Failed to resolve task metadata path from output template.", + extra={"task_id": task.id, "task_name": task.name, "error": str(e)}, + exc_info=True, + ) info = { "id": ag(metadata, ["id", "channel_id"]), @@ -649,7 +671,12 @@ async def task_metadata(request: Request, repo: TasksRepository, config: Config, data={"error": "Failed to get title from metadata."}, status=web.HTTPBadRequest.status_code ) - LOG.info(f"Generating metadata for task '{task.name}' in '{save_path!s}'") + LOG.info( + "Generating metadata for task '%s' in '%s'.", + task.name, + save_path, + extra={"task_id": task.id, "task_name": task.name, "save_path": str(save_path)}, + ) from yt_dlp.utils import sanitize_filename @@ -706,14 +733,20 @@ async def task_metadata(request: Request, repo: TasksRepository, config: Config, url: str | None = None try: url = thumbnails.get(key) - LOG.info(f"Fetching thumbnail '{key}' from '{url}'") + LOG.info( + "Fetching task metadata thumbnail.", + extra={"task_id": task.id, "task_name": task.name, "thumbnail": key, "url": url}, + ) if not url: continue try: await asyncio.to_thread(validate_url, url, config.allow_internal_urls) except ValueError: - LOG.warning(f"Invalid thumbnail url '{url}'") + LOG.warning( + "Invalid task metadata thumbnail URL.", + extra={"task_id": task.id, "task_name": task.name, "thumbnail": key, "url": url}, + ) continue resp = await client.request( @@ -727,11 +760,24 @@ async def task_metadata(request: Request, repo: TasksRepository, config: Config, img_file.write_bytes(resp.content) thumbnails[key] = str(img_file.relative_to(config.download_path)) except Exception as e: - url_log = url or "unknown" - LOG.warning(f"Failed to fetch thumbnail '{key}' from '{url_log}'. '{e!s}'") + LOG.warning( + "Failed to fetch task metadata thumbnail.", + extra={ + "task_id": task.id, + "task_name": task.name, + "thumbnail": key, + "url": url, + "error": str(e), + }, + exc_info=True, + ) continue except Exception as e: - LOG.warning(f"Failed to fetch thumbnails. '{e!s}'") + LOG.warning( + "Failed to fetch task metadata thumbnails.", + extra={"task_id": task.id, "task_name": task.name, "error": str(e)}, + exc_info=True, + ) return web.json_response(data=info, status=web.HTTPOk.status_code, dumps=encoder.encode) except ValueError as e: diff --git a/app/features/tasks/service.py b/app/features/tasks/service.py index 82d5cd50..076a7a6e 100644 --- a/app/features/tasks/service.py +++ b/app/features/tasks/service.py @@ -59,10 +59,23 @@ class Tasks(metaclass=Singleton): try: self._scheduler.add(timer=task.timer, func=self._runner, args=(task,), id=f"task-cronjob-{task.id}") - LOG.info(f"Task '{task.id}: {task.name}' queued to be executed '{cron_time(task.timer)}'.") + LOG.info( + "Queued task '%s' to run at '%s'.", + task.name, + cron_time(task.timer), + extra={"task_id": task.id, "task_name": task.name, "timer": task.timer}, + ) except Exception as e: - LOG.exception(e) - LOG.error(f"Failed to queue task '{task.name}'. '{e!s}'.") + LOG.exception( + "Failed to queue task '%s'.", + task.name, + extra={ + "task_id": task.id, + "task_name": task.name, + "timer": task.timer, + "exception_type": type(e).__name__, + }, + ) async def _init_handlers_service(self, scheduler) -> None: """Initialize the handlers service after migrations.""" @@ -95,7 +108,12 @@ class Tasks(metaclass=Singleton): if task.timer and task.enabled: self._scheduler.add(timer=task.timer, func=self._runner, args=(task,), id=task_id) - LOG.info(f"Task '{task.id}: {task.name}' queued to be executed '{cron_time(task.timer)}'.") + LOG.info( + "Queued task '%s' to run at '%s'.", + task.name, + cron_time(task.timer), + extra={"task_id": task.id, "task_name": task.name, "timer": task.timer}, + ) async def _runner(self, task: TaskModel) -> None: """ @@ -113,17 +131,27 @@ class Tasks(metaclass=Singleton): from app.library.ItemDTO import Item timeNow: str = datetime.now(UTC).isoformat() + task_id = task.id + task_name = task.name try: - if not (task := await self._repo.get(task.id)): - LOG.info(f"Task '{task.name}' no longer exists.") + if not (task := await self._repo.get(task_id)): + LOG.info("Task '%s' no longer exists.", task_name, extra={"task_id": task_id, "task_name": task_name}) return if not task.enabled: - LOG.debug(f"Task '{task.name}' is disabled. Skipping execution.") + LOG.debug( + "Task '%s' is disabled. Skipping execution.", + task.name, + extra={"task_id": task.id, "task_name": task.name}, + ) return if not task.url: - LOG.error(f"Failed to dispatch '{task.name}'. No URL found.") + LOG.error( + "Failed to dispatch task '%s' because it has no URL.", + task.name, + extra={"task_id": task.id, "task_name": task.name}, + ) return started: float = time.time() @@ -156,7 +184,19 @@ class Tasks(metaclass=Singleton): timeNow = datetime.now(UTC).isoformat() ended: float = time.time() - LOG.info(f"Task '{task.name}' completed at '{timeNow}' took '{ended - started:.2f}' seconds.") + LOG.info( + "Task '%s' completed in %.2f seconds.", + task.name, + ended - started, + extra={ + "task_id": task.id, + "task_name": task.name, + "url": task.url, + "preset": preset, + "elapsed_s": round(ended - started, 2), + "status": status.get("status") if isinstance(status, dict) else None, + }, + ) notify.emit( Events.TASK_DISPATCHED, @@ -171,7 +211,17 @@ class Tasks(metaclass=Singleton): message=f"Task '{task.name}' completed in '{ended - started:.2f}'.", ) except Exception as e: - LOG.error(f"Failed to execute '{task.name}' at '{timeNow}'. '{e!s}'.") + LOG.exception( + "Failed to execute scheduled task '%s'.", + task.name, + extra={ + "task_id": task.id, + "task_name": task.name, + "url": task.url, + "time": timeNow, + "exception_type": type(e).__name__, + }, + ) EventBus.get_instance().emit( Events.LOG_ERROR, data={"preset": task.preset}, diff --git a/app/features/tasks/utils.py b/app/features/tasks/utils.py index f411a576..216f1e97 100644 --- a/app/features/tasks/utils.py +++ b/app/features/tasks/utils.py @@ -12,5 +12,9 @@ def cron_time(timer: str) -> str: cs = CronSim(timer, datetime.now(UTC)) return cs.explain() except Exception as exc: - LOG.exception(exc) + LOG.exception( + "Failed to explain task timer '%s'.", + timer, + extra={"timer": timer, "exception_type": type(exc).__name__}, + ) return timer diff --git a/app/features/ytdlp/archiver.py b/app/features/ytdlp/archiver.py index 6b17f323..baa8cb6b 100644 --- a/app/features/ytdlp/archiver.py +++ b/app/features/ytdlp/archiver.py @@ -169,12 +169,21 @@ class Archiver(metaclass=ThreadSafe): continue ids.add(s) except OSError as e: - LOG.error(f"Failed to read archive file '{key}': {e!s}") + LOG.exception( + "Failed to read archive file '%s'.", + key, + extra={"archive_file": key, "operation": "read", "exception_type": type(e).__name__}, + ) ids = set() try: elapsed_ms: float = (time.perf_counter() - start) * 1000.0 - LOG.debug(f"_ensure_loaded took {elapsed_ms:.2f}ms (loaded={len(ids)})") + LOG.debug( + "_ensure_loaded took %.2fms (loaded=%s)", + elapsed_ms, + len(ids), + extra={"archive_file": key, "elapsed_ms": round(elapsed_ms, 2), "loaded_count": len(ids)}, + ) except Exception: pass @@ -283,7 +292,17 @@ class Archiver(metaclass=ThreadSafe): f.write("".join(f"{x}\n" for x in new_ids)) except OSError as e: - LOG.error(f"Failed to write to archive file '{key}': {e!s}") + LOG.exception( + "Failed to write %s item(s) to archive file '%s'.", + len(new_ids), + key, + extra={ + "archive_file": key, + "operation": "add", + "item_count": len(new_ids), + "exception_type": type(e).__name__, + }, + ) return False entry.ids.update(new_ids) @@ -335,7 +354,17 @@ class Archiver(metaclass=ThreadSafe): continue kept_lines.append(line) except OSError as e: - LOG.error(f"Failed reading archive for delete '{key}': {e!s}") + LOG.exception( + "Failed to read archive file '%s' before deleting %s item(s).", + key, + len(remove_ids), + extra={ + "archive_file": key, + "operation": "delete_read", + "item_count": len(remove_ids), + "exception_type": type(e).__name__, + }, + ) return False if not changed: @@ -351,7 +380,17 @@ class Archiver(metaclass=ThreadSafe): with path.open("w", encoding="utf-8") as f: f.writelines(kept_lines) except OSError as e: - LOG.error(f"Failed writing archive after delete '{key}': {e!s}") + LOG.exception( + "Failed to write archive file '%s' after deleting %s item(s).", + key, + len(remove_ids), + extra={ + "archive_file": key, + "operation": "delete_write", + "item_count": len(remove_ids), + "exception_type": type(e).__name__, + }, + ) return False if entry.loaded: diff --git a/app/features/ytdlp/extractor.py b/app/features/ytdlp/extractor.py index 10c509b1..8f2d5533 100644 --- a/app/features/ytdlp/extractor.py +++ b/app/features/ytdlp/extractor.py @@ -180,7 +180,10 @@ class ExtractorPool(metaclass=Singleton): self._pool.shutdown(wait=False, cancel_futures=False) LOG.debug("Extractor process pool shutdown complete") except Exception as exc: - LOG.error("Error shutting down extractor process pool: %s", exc) + LOG.exception( + "Failed to shut down the extractor process pool.", + extra={"exception_type": type(exc).__name__}, + ) else: self._pool = None @@ -461,8 +464,23 @@ async def fetch_info( raise except Exception as exc: - LOG.exception(exc) - LOG.warning("extract_info process pool failed, falling back to thread pool url=%s error=%s", url, exc) + LOG.warning( + "yt-dlp extraction for '%s' fell back to the thread pool after the process pool failed.", + url, + extra={ + "url": url, + "timeout": timeout, + "concurrency": extractor_config.concurrency, + "pool": "process", + "fallback": "thread", + "follow_redirect": follow_redirect, + "no_archive": no_archive, + "sanitize_info": sanitize_info, + "capture_logs_level": capture_logs, + "exception_type": type(exc).__name__, + }, + exc_info=True, + ) return await asyncio.wait_for( fut=loop.run_in_executor( None, diff --git a/app/features/ytdlp/patches.py b/app/features/ytdlp/patches.py index d38b2a64..417b21f2 100644 --- a/app/features/ytdlp/patches.py +++ b/app/features/ytdlp/patches.py @@ -14,7 +14,12 @@ def patch_metadataparser() -> None: from yt_dlp.postprocessor.metadataparser import MetadataParserPP from yt_dlp.utils import Namespace except Exception as exc: - LOG.warning(f"Unable to import yt_dlp metadata parser for patching: {exc!s}") + LOG.warning( + "Unable to import yt-dlp metadata parser for patching: %s", + exc, + extra={"patch": "metadata_parser", "exception_type": type(exc).__name__}, + exc_info=True, + ) return if getattr(MetadataParserPP.Actions, "_ytptube_patched", False): @@ -61,7 +66,12 @@ def patch_windows_popen_wait() -> None: try: from yt_dlp.utils import Popen except Exception as exc: - LOG.warning(f"Unable to import yt_dlp Popen for patching: {exc!s}") + LOG.warning( + "Unable to import yt-dlp Popen for patching: %s", + exc, + extra={"patch": "windows_popen_wait", "exception_type": type(exc).__name__}, + exc_info=True, + ) return if getattr(Popen, "_ytptube_wait_patched", False): diff --git a/app/features/ytdlp/router.py b/app/features/ytdlp/router.py index d1653b11..7a3707b0 100644 --- a/app/features/ytdlp/router.py +++ b/app/features/ytdlp/router.py @@ -37,7 +37,11 @@ def _get_preset_archive(preset: str) -> str | None: try: opts: dict = YTDLPOpts.get_instance().preset(preset).get_all() except Exception as e: - LOG.error(f"Failed to build yt-dlp opts for preset '{preset}'. {e!s}") + LOG.exception( + "Failed to build yt-dlp options for preset '%s'.", + preset, + extra={"preset": preset, "exception_type": type(e).__name__}, + ) return None if not (archive_file := opts.get("download_archive")): @@ -125,7 +129,18 @@ async def archiver_get(request: Request) -> Response: data={"file": archive_file, "items": data, "count": len(data)}, status=web.HTTPOk.status_code ) except Exception as e: - LOG.exception(e) + LOG.exception( + "Failed to read archive file '%s' for preset '%s'.", + archive_file, + preset, + extra={ + "route": "api/archiver/", + "action": "read_archive", + "preset": preset, + "archive_file": archive_file, + "ids": ids, + }, + ) return web.json_response( data={"error": f"Failed to read archive file for preset '{preset}'.", "message": str(e)}, status=web.HTTPInternalServerError.status_code, @@ -171,7 +186,20 @@ async def archiver_add(request: Request) -> Response: status=web.HTTPOk.status_code if status else web.HTTPNotModified.status_code, ) except Exception as e: - LOG.exception(e) + LOG.exception( + "Failed to add %s item(s) to archive file '%s' for preset '%s'.", + len(items), + archive_file, + preset, + extra={ + "route": "api/archiver/", + "action": "add_archive_items", + "preset": preset, + "archive_file": archive_file, + "item_count": len(items), + "skip_check": skip_check, + }, + ) return web.json_response( data={"error": f"Failed to add items to archive for preset '{preset}'.", "message": str(e)}, status=web.HTTPInternalServerError.status_code, @@ -215,7 +243,19 @@ async def archiver_delete(request: Request) -> Response: status=web.HTTPOk.status_code if status else web.HTTPNotModified.status_code, ) except Exception as e: - LOG.exception(e) + LOG.exception( + "Failed to delete %s item(s) from archive file '%s' for preset '%s'.", + len(items), + archive_file, + preset, + extra={ + "route": "api/archiver/", + "action": "delete_archive_items", + "preset": preset, + "archive_file": archive_file, + "item_count": len(items), + }, + ) return web.json_response( data={"error": f"Failed to delete items from archive for preset '{preset}'.", "message": str(e)}, status=web.HTTPInternalServerError.status_code, @@ -407,8 +447,18 @@ async def get_info(request: Request, cache: Cache, config: Config) -> Response: return web.json_response(body=json.dumps(data, indent=4, default=str), status=web.HTTPOk.status_code) except Exception as e: - LOG.exception(e) - LOG.error(f"Error encountered while getting video info for '{url}'. '{e!s}'.") + LOG.exception( + "Failed to get video info for '%s'.", + url, + extra={ + "route": "api/yt-dlp/url/info/", + "action": "get_video_info", + "url": url, + "preset": preset, + "cache_key": key if "key" in locals() else None, + "has_cli_args": bool(cli_args), + }, + ) return web.json_response( data={ "error": "failed to get video info.", @@ -496,7 +546,18 @@ async def make_command(request: Request, config: Config, encoder: Encoder) -> Re try: command, info = YTDLPCli(item=it, config=config).build() except Exception as e: - LOG.exception(e) + LOG.exception( + "Failed to build yt-dlp command for '%s'.", + it.url, + extra={ + "route": "api/yt-dlp/command/", + "action": "build_command", + "url": it.url, + "preset": it.preset, + "has_cookies": bool(it.cookies), + "exception_type": type(e).__name__, + }, + ) return web.json_response( data={"error": "Failed to build CLI command"}, status=web.HTTPBadRequest.status_code, diff --git a/app/features/ytdlp/tests/test_ytdlp_opts.py b/app/features/ytdlp/tests/test_ytdlp_opts.py index 3dcc40f8..7b728b2d 100644 --- a/app/features/ytdlp/tests/test_ytdlp_opts.py +++ b/app/features/ytdlp/tests/test_ytdlp_opts.py @@ -442,7 +442,7 @@ class TestYTDLPOpts: opts = YTDLPOpts() opts.get_all(keep=True) - mock_log.debug.assert_called_once_with(f"Final yt-dlp options: '{test_data!s}'.") + mock_log.debug.assert_called_once_with("Final yt-dlp options", extra={"ytdlp_options": test_data}) def test_cookie_loading_error_handling(self): """Test error handling when cookie loading fails.""" @@ -475,11 +475,12 @@ class TestYTDLPOpts: opts = YTDLPOpts() opts.preset("cookie_preset") - # Should log error but not raise - mock_log.error.assert_called_once() - error_args = mock_log.error.call_args[0][0] - assert "Failed to load" in error_args - assert "Cookie Preset" in error_args + # Should log exception but not raise + mock_log.exception.assert_called_once() + error_fields = mock_log.exception.call_args.kwargs["extra"] + assert error_fields["preset"] == "Cookie Preset" + assert error_fields["has_cookies"] is True + assert error_fields["exception_type"] == "ValueError" assert "cookiefile" not in opts._preset_opts, "cookiefile should not be set" diff --git a/app/features/ytdlp/utils.py b/app/features/ytdlp/utils.py index c3932c65..1910b3d2 100644 --- a/app/features/ytdlp/utils.py +++ b/app/features/ytdlp/utils.py @@ -462,8 +462,12 @@ def get_archive_id(url: str) -> dict[str, str | None]: idDict["archive_id"] = make_archive_id(_ie, temp_id) break except Exception as e: - LOG.exception(e) - LOG.error(f"Error getting archive ID: {e}") + LOG.exception( + "Failed to get archive ID for '%s' with extractor '%s'.", + url, + key, + extra={"url": url, "extractor": key, "exception_type": type(e).__name__}, + ) return idDict diff --git a/app/features/ytdlp/ytdlp_opts.py b/app/features/ytdlp/ytdlp_opts.py index 4b8340eb..5f4d094e 100644 --- a/app/features/ytdlp/ytdlp_opts.py +++ b/app/features/ytdlp/ytdlp_opts.py @@ -335,7 +335,11 @@ class YTDLPOpts: if file and file.exists(): self._preset_opts["cookiefile"] = str(file) except ValueError as e: - LOG.error(f"Failed to load '{preset.name}' cookies. {e!s}") + LOG.exception( + "Failed to load cookies for preset '%s'.", + preset.name, + extra={"preset": preset.name, "has_cookies": True, "exception_type": type(e).__name__}, + ) if preset.template: self._preset_opts["outtmpl"] = {"default": preset.template, "chapter": self._config.output_template_chapter} @@ -403,7 +407,7 @@ class YTDLPOpts: data["format"] = data["format"][1:] if self._config.debug: - LOG.debug(f"Final yt-dlp options: '{data!s}'.") + LOG.debug("Final yt-dlp options", extra={"ytdlp_options": data}) return data diff --git a/app/library/BackgroundWorker.py b/app/library/BackgroundWorker.py index f5f4dea9..b5770b13 100644 --- a/app/library/BackgroundWorker.py +++ b/app/library/BackgroundWorker.py @@ -39,19 +39,22 @@ class BackgroundWorker(metaclass=Singleton): Services.get_instance().add("background_worker", self) app.on_shutdown.append(self.on_shutdown) - LOG.debug("Starting background worker...") + LOG.debug("Starting background worker thread.") self.thread = threading.Thread(target=self._run, daemon=True) self.thread.start() async def on_shutdown(self, _: web.Application): self.running = False try: - LOG.debug("Shutting down background worker...") + LOG.debug("Shutting down background worker thread...") self.queue.put((CloseThread, (), {})) self.thread.join(timeout=5) - LOG.debug("Background worker has been shut down.") + LOG.debug("Background worker thread has been shut down.") except Exception as e: - LOG.error(f"Failed to shut down background worker: {e}") + LOG.exception( + "Failed to shut down background worker thread.", + extra={"exception_type": type(e).__name__}, + ) def _run(self): asyncio.set_event_loop(asyncio.new_event_loop()) @@ -79,8 +82,16 @@ class BackgroundWorker(metaclass=Singleton): if inspect.iscoroutine(result): loop.call_soon_threadsafe(loop.create_task, result) except Exception as e: - LOG.exception(e) - LOG.error(f"Failed to run '{fn.__name__}'. {e!s}") + function = getattr(fn, "__name__", fn.__class__.__name__) + LOG.exception( + "Failed to run background worker function '%s'.", + function, + extra={ + "function": function, + "thread_name": threading.current_thread().name, + "exception_type": type(e).__name__, + }, + ) except Empty: continue @@ -90,7 +101,10 @@ class BackgroundWorker(metaclass=Singleton): loop.close() LOG.debug("Event loop has been stopped and closed.") except Exception as e: - LOG.error(f"Failed to stop the event loop: {e!s}") + LOG.exception( + "Failed to stop background worker event loop.", + extra={"thread_name": loop_thread.name, "exception_type": type(e).__name__}, + ) def submit(self, fn, *args, **kwargs): self.queue.put((fn, args, kwargs)) diff --git a/app/library/Events.py b/app/library/Events.py index 045b7336..b1ea9fc6 100644 --- a/app/library/Events.py +++ b/app/library/Events.py @@ -242,7 +242,12 @@ class EventBus(metaclass=Singleton): event = Events.frontend() else: if event not in all_events: - LOG.error(f"'{name}' attempted to listen on '{event}' which does not exist.") + LOG.error( + "Listener '%s' tried to subscribe to unknown event '%s'.", + name, + event, + extra={"listener": name, "event": event}, + ) return self event = [event] @@ -252,7 +257,12 @@ class EventBus(metaclass=Singleton): for e in event: if e not in all_events: - LOG.error(f"'{name}' attempted to listen on '{e}' which does not exist.") + LOG.error( + "Listener '%s' tried to subscribe to unknown event '%s'.", + name, + e, + extra={"listener": name, "event": e}, + ) continue if e not in self._listeners: @@ -261,7 +271,7 @@ class EventBus(metaclass=Singleton): self._listeners[e] = [(n, listener) for n, listener in self._listeners[e] if n != name] self._listeners[e].append((name, EventListener(name, callback))) - LOG.debug(f"'{name}' subscribed to '{event}'.") + LOG.debug("Listener '%s' has subscribed.", name, extra={"listener": name, "events": event}) return self @@ -289,7 +299,7 @@ class EventBus(metaclass=Singleton): events.append(e) if len(events) > 0: - LOG.debug(f"'{name}' unsubscribed from '{events}'.") + LOG.debug("Listener '%s' unsubscribed from '%s'.", name, events, extra={"listener": name, "events": events}) return self @@ -316,7 +326,17 @@ class EventBus(metaclass=Singleton): ev = Event(event=event, title=title, message=message, data=data) if self.debug or event not in Events.only_debug(): - LOG.debug(f"Emitting event '{ev.id}: {ev.event}'.", extra={"data": data}) + LOG.debug( + "Emitting '%s' event to %s listener(s).", + ev.event, + len(self._listeners[event]), + extra={ + "event_id": ev.id, + "event": ev.event, + "handler_count": len(self._listeners[event]), + "data": data, + }, + ) try: loop = asyncio.get_running_loop() @@ -329,16 +349,35 @@ class EventBus(metaclass=Singleton): if asyncio.iscoroutine(coro): await coro else: - LOG.warning(f"Expected coroutine from async handler '{handler.name}', got {type(coro)}") + LOG.warning( + "Async handler '%s' returned '%s' instead of a coroutine.", + handler.name, + type(coro).__name__, + extra={"handler": handler.name, "returned_type": type(coro).__name__}, + ) else: await self._call(handler, ev, kwargs) except Exception as e: - LOG.exception(e) - LOG.error(f"Failed to emit event '{ev.event}' to '{handler.name}'. Error message '{e!s}'.") + LOG.exception( + "Failed to emit '%s' event to listener '%s'.", + ev.event, + handler.name, + extra={ + "event_id": ev.id, + "event": ev.event, + "handler": handler.name, + "exception_type": type(e).__name__, + }, + ) loop.create_task(execute_handlers()) except RuntimeError: - LOG.debug(f"No event loop detected - using BackgroundWorker for {len(self._listeners[event])} handlers") + LOG.debug( + "No event loop detected; offloading '%s' event to %s background listener(s).", + ev.event, + len(self._listeners[event]), + extra={"event_id": ev.id, "event": ev.event, "handler_count": len(self._listeners[event])}, + ) for _, handler in self._listeners[event]: try: if not self._offload: @@ -346,8 +385,17 @@ class EventBus(metaclass=Singleton): self._offload.submit(handler.handle, ev, **kwargs) except Exception as e: - LOG.exception(e) - LOG.error(f"Failed to emit event '{ev.event}' to '{handler.name}'. Error message '{e!s}'.") + LOG.exception( + "Failed to offload '%s' event to listener '%s'.", + ev.event, + handler.name, + extra={ + "event_id": ev.id, + "event": ev.event, + "handler": handler.name, + "exception_type": type(e).__name__, + }, + ) def clear(self) -> None: """ diff --git a/app/library/HttpAPI.py b/app/library/HttpAPI.py index e956b5c0..4a70087f 100644 --- a/app/library/HttpAPI.py +++ b/app/library/HttpAPI.py @@ -89,7 +89,10 @@ class HttpAPI: try: app.on_response_prepare.append(on_prepare) except Exception as e: - LOG.exception(e) + LOG.exception( + "Failed to register response preparation middleware.", + extra={"operation": "register_on_response_prepare", "exception_type": type(e).__name__}, + ) app.on_shutdown.append(self.on_shutdown) @@ -130,7 +133,13 @@ class HttpAPI: route.path = f"{base_path}/{route.path.lstrip('/')}" if self.config.debug: - LOG.debug(f"Add ({route.name}) {route.method}: {route.path}.") + LOG.debug( + "Adding route '%s' %s: %s.", + route.name, + route.method, + route.path, + extra={"route_name": route.name, "method": route.method, "path": route.path}, + ) app.router.add_route(route.method, route.path, handler=_handle(route.handler), name=route.name) @@ -173,7 +182,14 @@ class HttpAPI: data = base64.b64encode(data.encode()).decode() auth_header = f"Basic {data}" except Exception as e: - LOG.exception(e) + LOG.exception( + "Failed to decrypt authentication cookie.", + extra={ + "route": str(request.rel_url), + "method": request.method, + "exception_type": type(e).__name__, + }, + ) if auth_header is None: return web.json_response( @@ -226,7 +242,11 @@ class HttpAPI: samesite="Strict", ) except Exception as e: - LOG.exception(e) + LOG.exception( + "Failed to set authentication cookie for '%s'.", + request.rel_url, + extra={"route": str(request.rel_url), "method": request.method, "exception_type": type(e).__name__}, + ) return response @@ -314,7 +334,16 @@ class HttpAPI: else: response = await Services.get_instance().handle_async(handler, request=request) except TypeError as te: - LOG.exception(te) + LOG.exception( + "Failed to inject route handler dependencies for '%s'.", + getattr(handler, "__name__", handler.__class__.__name__), + extra={ + "handler": getattr(handler, "__name__", handler.__class__.__name__), + "route": str(request.rel_url), + "method": request.method, + "exception_type": type(te).__name__, + }, + ) if "missing 1 required positional argument" in str(te) and "request" in str(te): response = await handler(request) else: @@ -322,7 +351,12 @@ class HttpAPI: except web.HTTPException as e: return web.json_response(data={"error": str(e)}, status=e.status_code) except Exception as e: - LOG.exception(e) + LOG.exception( + "Failed to handle request '%s %s'.", + request.method, + request.rel_url, + extra={"route": str(request.rel_url), "method": request.method, "exception_type": type(e).__name__}, + ) response = web.json_response( data={"error": "Internal Server Error"}, status=web.HTTPInternalServerError.status_code, diff --git a/app/library/HttpSocket.py b/app/library/HttpSocket.py index ceb8264c..6b419f46 100644 --- a/app/library/HttpSocket.py +++ b/app/library/HttpSocket.py @@ -161,7 +161,7 @@ class HttpSocket: return if not (route := socket_routes.get(event)): - LOG.debug(f"Unknown websocket event '{event}'.") + LOG.debug("Unknown WebSocket event '%s'.", event, extra={"sid": sid, "event": event}) return data = payload.get("data") if isinstance(payload, dict) else None @@ -183,7 +183,7 @@ class HttpSocket: sid: str = gen_random(14) self.sio.add(sid, ws) - LOG.debug(f"WebSocket client '{sid}' connected.") + LOG.debug("WebSocket client '%s' connected.", sid, extra={"sid": sid}) await handle_connect(sid) @@ -192,8 +192,11 @@ class HttpSocket: try: await handle_message(sid, message) except Exception as e: - LOG.exception(e) - LOG.error(f"Error handling WebSocket message from client '{sid}': {e}") + LOG.exception( + "Failed to handle WebSocket message from client '%s'.", + sid, + extra={"sid": sid, "message_size": len(message), "exception_type": type(e).__name__}, + ) try: i: int = 0 @@ -202,15 +205,22 @@ class HttpSocket: i = i + 1 asyncio.create_task(handle_message_safe(sid, msg.data), name=f"ws_msg_{sid}_{i}") elif msg.type == web.WSMsgType.ERROR: - LOG.error(f"WebSocket connection closed with exception {ws.exception()}") + LOG.error( + "WebSocket connection closed with exception %s", + ws.exception(), + extra={ + "sid": sid, + "exception": str(ws.exception()) if ws.exception() else None, + }, + ) finally: await handle_disconnect(sid, getattr(ws, "close_reason", None)) self.sio.remove(sid) - LOG.debug(f"WebSocket client '{sid}' disconnected.") + LOG.debug("WebSocket client '%s' disconnected.", sid, extra={"sid": sid}) return ws if self.config.debug: - LOG.debug(f"Add (ws) GET: {ws_path}.") + LOG.debug("Add (ws) GET: %s.", ws_path, extra={"method": "GET", "path": ws_path}) app.router.add_get(ws_path, ws_handler, name="ws") diff --git a/app/library/PackageInstaller.py b/app/library/PackageInstaller.py index 30c27bf0..9b796015 100644 --- a/app/library/PackageInstaller.py +++ b/app/library/PackageInstaller.py @@ -64,19 +64,34 @@ class PackageInstaller: current_version: str | None = self._get_installed_version(pkg) if current_version and version and self.compare_versions(current_version, version): - LOG.info(f"'{pkg}' is already installed with the specified version ({version}). Skipping installation.") + LOG.info( + "Package '%s' is already installed at version '%s'; skipping installation.", + pkg, + version, + extra={"package": pkg, "installed_version": current_version, "requested_version": version}, + ) return if upgrade and current_version and not version: latest_version: str | None = self._get_latest_version(pkg) if latest_version and parse_version(current_version) >= parse_version(latest_version): - LOG.info(f"'{pkg}' is already the latest version ({current_version}). Skipping upgrade.") + LOG.info( + "Package '%s' is already at the latest version '%s'; skipping upgrade.", + pkg, + current_version, + extra={"package": pkg, "installed_version": current_version, "latest_version": latest_version}, + ) return if current_version: - LOG.info(f"'{pkg}' is already installed (version: {current_version}). Proceeding with upgrade...") + LOG.info( + "Package '%s' is installed at '%s'; proceeding with upgrade.", + pkg, + current_version, + extra={"package": pkg, "installed_version": current_version}, + ) else: - LOG.info(f"'{pkg}' is not installed. Installing...") + LOG.info("Package '%s' is not installed; installing it.", pkg, extra={"package": pkg}) self._install_pkg(pkg, version=version) @@ -93,9 +108,20 @@ class PackageInstaller: resp = client.get(url) if 200 == resp.status_code: return resp.json()["info"]["version"] - LOG.warning(f"Failed to fetch '{pkg}' info: HTTP {resp.status_code}") + LOG.warning( + "Failed to fetch PyPI metadata for '%s': HTTP %s.", + pkg, + resp.status_code, + extra={"package": pkg, "status_code": resp.status_code, "url": url}, + ) except Exception as e: - LOG.warning(f"Error while querying PyPI for '{pkg}': {e}") + LOG.warning( + "Failed to query PyPI for '%s': %s", + pkg, + e, + extra={"package": pkg, "url": url, "exception_type": type(e).__name__}, + exc_info=True, + ) return None def _install_pkg(self, pkg: str, version: str | None = None) -> bool: @@ -135,7 +161,12 @@ class PackageInstaller: return 0 == proc.returncode except subprocess.CalledProcessError as e: - LOG.error(f"Failed to install '{pkg}' (exit {e.returncode}). {e!s}") + LOG.exception( + "Failed to install package '%s' (exit %s).", + pkg, + e.returncode, + extra={"package": pkg, "returncode": e.returncode, "exception_type": type(e).__name__}, + ) self.out(out=e.stdout, err=e.stderr) raise @@ -150,13 +181,20 @@ class PackageInstaller: if not pkgs.has_packages() or not self.user_site: return - LOG.info(f"Checking for user pip packages: {', '.join(pkgs.packages)}") + LOG.info("Checking user pip packages: %s", ", ".join(pkgs.packages), extra={"packages": pkgs.packages}) for package in pkgs.packages: try: self.action(package, upgrade=pkgs.allow_upgrade()) except Exception as e: - LOG.error(f"Failed to install or upgrade package '{package}'. Error message: {e!s}") - LOG.exception(e) + LOG.exception( + "Failed to install or upgrade package '%s'.", + package, + extra={ + "package": package, + "allow_upgrade": pkgs.allow_upgrade(), + "exception_type": type(e).__name__, + }, + ) def compare_versions(self, current: str, target: str) -> bool: """ diff --git a/app/library/Scheduler.py b/app/library/Scheduler.py index 7d09b1ef..f4eeba3a 100644 --- a/app/library/Scheduler.py +++ b/app/library/Scheduler.py @@ -46,10 +46,13 @@ class Scheduler(metaclass=Singleton): for job in self._jobs: try: self._jobs[job].stop() - LOG.debug(f"Stopped job '{job}'.") + LOG.debug("Stopped job '%s'.", job, extra={"job_id": job}) except Exception as e: - LOG.exception(e) - LOG.error(f"Failed to stop job '{job}'. Error message '{e!s}'.") + LOG.exception( + "Failed to stop scheduler job '%s'.", + job, + extra={"job_id": job, "exception_type": type(e).__name__}, + ) self._jobs = {} @@ -127,7 +130,7 @@ class Scheduler(metaclass=Singleton): self._jobs[job_id] = job - LOG.debug(f"Added '{job_id}' to the scheduler to run on '{timer}'.") + LOG.debug("Added job '%s' to run on '%s'.", job_id, timer, extra={"job_id": job_id, "timer": timer}) return job_id @@ -151,12 +154,15 @@ class Scheduler(metaclass=Singleton): try: self._jobs[id].stop() except Exception as e: - LOG.exception(e) - LOG.error(f"Failed to stop job '{id}'. Error message '{e!s}'.") + LOG.exception( + "Failed to stop scheduler job '%s'.", + id, + extra={"job_id": id, "exception_type": type(e).__name__}, + ) return False del self._jobs[id] - LOG.debug(f"Removed job '{id}' from the scheduler.") + LOG.debug("Removed job '%s' from the scheduler.", id, extra={"job_id": id}) return True return False diff --git a/app/library/TerminalSessionManager.py b/app/library/TerminalSessionManager.py index 07edb9a1..1a6b8c00 100644 --- a/app/library/TerminalSessionManager.py +++ b/app/library/TerminalSessionManager.py @@ -343,7 +343,10 @@ class TerminalSessionManager(metaclass=Singleton): try: os.close(slave_fd) except Exception as exc: - LOG.error("Error closing PTY. '%s'.", str(exc)) + LOG.exception( + "Failed to close the PTY slave file descriptor.", + extra={"exception_type": type(exc).__name__}, + ) read_task = asyncio.create_task( self._read_process_output(session_id=session_id, proc=proc, use_pty=use_pty, master_fd=master_fd), @@ -356,8 +359,11 @@ class TerminalSessionManager(metaclass=Singleton): final_status = "interrupted" except Exception as exc: final_status = "failed" - LOG.error("CLI execute exception was thrown.") - LOG.exception(exc) + LOG.exception( + "Terminal session '%s' command failed.", + session_id, + extra={"session_id": session_id, "use_pty": use_pty, "exception_type": type(exc).__name__}, + ) await self._append_event(session_id, "output", {"type": "stderr", "line": str(exc)}) finally: final_status = await self._resolve_final_status(session_id=session_id, status=final_status) diff --git a/app/library/UpdateChecker.py b/app/library/UpdateChecker.py index db430982..be857359 100644 --- a/app/library/UpdateChecker.py +++ b/app/library/UpdateChecker.py @@ -145,7 +145,11 @@ class UpdateChecker(metaclass=Singleton): strip_v_prefix: bool = False, ) -> tuple[str, str | None]: try: - LOG.info(f"Checking for {name} updates...") + LOG.info( + "Checking for %s updates...", + name, + extra={"target_name": name, "api_url": api_url, "current_version": current_version}, + ) client = get_async_client(use_curl=False) response = await client.get( @@ -155,32 +159,59 @@ class UpdateChecker(metaclass=Singleton): ) if 200 != response.status_code: - LOG.warning(f"Failed to check for {name} updates: HTTP {response.status_code}") + LOG.warning( + "Failed to check for %s updates: HTTP %s", + name, + response.status_code, + extra={"target_name": name, "api_url": api_url, "status_code": response.status_code}, + ) return ("error", None) data: dict[str, Any] = response.json() latest_tag: str = data.get("tag_name", "") if not latest_tag: - LOG.warning(f"No tag_name found in {name} GitHub release data.") + LOG.warning( + "No tag_name found in %s GitHub release data.", + name, + extra={"target_name": name, "api_url": api_url}, + ) return ("error", None) compare_current: str = current_version.lstrip("v") if strip_v_prefix else current_version compare_latest: str = latest_tag.lstrip("v") if strip_v_prefix else latest_tag if self._compare_versions(compare_current, compare_latest): - LOG.warning(f"{name} update available: {current_version} -> {latest_tag}") + LOG.warning( + "%s update available: %s -> %s", + name, + current_version, + latest_tag, + extra={"target_name": name, "current_version": current_version, "latest_version": latest_tag}, + ) result = ("update_available", latest_tag) await self._cache.aset(cache_key, result, self.CACHE_DURATION) return result - LOG.info(f"No {name} updates available.") + LOG.info( + "No %s updates available.", + name, + extra={"target_name": name, "current_version": current_version}, + ) result = ("up_to_date", None) await self._cache.aset(cache_key, result, self.CACHE_DURATION) return result except Exception as e: - LOG.exception(e) - LOG.error(f"Error checking for {name} updates: {e!s}") + LOG.exception( + "Failed to check for %s updates.", + name, + extra={ + "target_name": name, + "api_url": api_url, + "cache_key": cache_key, + "exception_type": type(e).__name__, + }, + ) return ("error", None) async def _check_app_version(self) -> tuple[str, str | None]: @@ -238,5 +269,12 @@ class UpdateChecker(metaclass=Singleton): return parse_version(latest) > parse_version(current) except Exception as e: - LOG.warning(f"Error comparing versions '{current}' vs '{latest}': {e}") + LOG.warning( + "Error comparing versions '%s' vs '%s': %s", + current, + latest, + e, + extra={"current_version": current, "latest_version": latest, "exception_type": type(e).__name__}, + exc_info=True, + ) return False diff --git a/app/library/Utils.py b/app/library/Utils.py index 4c383524..125ace63 100644 --- a/app/library/Utils.py +++ b/app/library/Utils.py @@ -43,6 +43,7 @@ class FileLogFormatter(logging.Formatter): LOG_RECORD_ATTRS: set[str] = set(logging.makeLogRecord({}).__dict__) | {"asctime", "message"} +SKIP_LOG_FIELD = object() class JsonLogFormatter(logging.Formatter): @@ -85,11 +86,43 @@ class JsonLogFormatter(logging.Formatter): if key in LOG_RECORD_ATTRS or key.startswith("_"): continue - if isinstance(value, str | int | float | bool) or value is None: + value = JsonLogFormatter._field(value) + if value is not SKIP_LOG_FIELD: extra[key] = value return extra + @staticmethod + def _field(value: Any) -> Any: + if isinstance(value, str | int | float | bool) or value is None: + return value + + if isinstance(value, Path): + return str(value) + + if isinstance(value, dict): + data: dict[str, Any] = {} + for key, item in value.items(): + if not isinstance(key, str) or key.startswith("_"): + continue + + item = JsonLogFormatter._field(item) + if item is not SKIP_LOG_FIELD: + data[key] = item + + return data + + if isinstance(value, list): + data: list[Any] = [] + for item in value: + item = JsonLogFormatter._field(item) + if item is not SKIP_LOG_FIELD: + data.append(item) + + return data + + return SKIP_LOG_FIELD + @staticmethod def _exception( exc_info: tuple[type[BaseException], BaseException, Any] | tuple[None, None, None], @@ -470,7 +503,11 @@ def check_id(file: Path) -> bool | str: return f.absolute() except OSError as e: - LOG.error(f"Error checking file '{file}': {e!s}") + LOG.exception( + "Failed to check for a matching file for '%s'.", + file, + extra={"file_path": str(file), "operation": "check_id", "exception_type": type(e).__name__}, + ) return False return False @@ -526,7 +563,11 @@ def validate_url(url: str, allow_internal: bool = False) -> bool: msg = "Access to internal urls or private networks is not allowed." raise ValueError(msg) except socket.gaierror as e: - LOG.error(f"Error resolving hostname '{hostname}': {e!s}") + LOG.exception( + "Failed to resolve hostname '%s'.", + hostname, + extra={"hostname": hostname, "exception_type": type(e).__name__}, + ) msg = "Invalid hostname." raise ValueError(msg) from e @@ -654,16 +695,46 @@ def rename_file(old_path: Path, new_name: str) -> tuple[Path, list[tuple[Path, P renamed_sidecar: Path = old_sidecar.rename(new_sidecar) renamed_sidecars.append((old_sidecar, renamed_sidecar)) except OSError as e: - LOG.error(f"Failed to rename sidecar '{old_sidecar}': {e}") + LOG.exception( + "Failed to rename sidecar '%s' to '%s'.", + old_sidecar, + new_sidecar, + extra={ + "old_path": str(old_sidecar), + "new_path": str(new_sidecar), + "operation": "rename_sidecar", + "exception_type": type(e).__name__, + }, + ) try: renamed_main.rename(old_path) - except OSError: - LOG.error(f"Failed to rollback main file rename from '{renamed_main}' to '{old_path}'") + except OSError as rollback_error: + LOG.exception( + "Failed to roll back main file rename from '%s' to '%s'.", + renamed_main, + old_path, + extra={ + "old_path": str(renamed_main), + "new_path": str(old_path), + "operation": "rename_rollback", + "exception_type": type(rollback_error).__name__, + }, + ) raise return renamed_main, renamed_sidecars except OSError as e: - LOG.error(f"Failed to rename '{old_path}' to '{new_path}': {e}") + LOG.exception( + "Failed to rename '%s' to '%s'.", + old_path, + new_path, + extra={ + "old_path": str(old_path), + "new_path": str(new_path), + "operation": "rename", + "exception_type": type(e).__name__, + }, + ) raise @@ -721,24 +792,62 @@ def move_file(old_path: Path, target_dir: Path) -> tuple[Path, list[tuple[Path, moved_sidecar: Path = old_sidecar.rename(new_sidecar) renamed_sidecars.append((old_sidecar, moved_sidecar)) except OSError as e: - LOG.error(f"Failed to move sidecar '{old_sidecar}': {e}") + LOG.exception( + "Failed to move sidecar '%s' to '%s'.", + old_sidecar, + new_sidecar, + extra={ + "old_path": str(old_sidecar), + "new_path": str(new_sidecar), + "operation": "move_sidecar", + "exception_type": type(e).__name__, + }, + ) try: moved_main.rename(old_path) # Rollback any sidecars that were already moved for rolled_back_old, rolled_back_new in renamed_sidecars: try: rolled_back_new.rename(rolled_back_old) - except OSError: - LOG.error( - f"Failed to rollback sidecar move from '{rolled_back_new}' to '{rolled_back_old}'" + except OSError as rollback_error: + LOG.exception( + "Failed to roll back sidecar move from '%s' to '%s'.", + rolled_back_new, + rolled_back_old, + extra={ + "old_path": str(rolled_back_new), + "new_path": str(rolled_back_old), + "operation": "move_sidecar_rollback", + "exception_type": type(rollback_error).__name__, + }, ) - except OSError: - LOG.error(f"Failed to rollback main file move from '{moved_main}' to '{old_path}'") + except OSError as rollback_error: + LOG.exception( + "Failed to roll back main file move from '%s' to '%s'.", + moved_main, + old_path, + extra={ + "old_path": str(moved_main), + "new_path": str(old_path), + "operation": "move_rollback", + "exception_type": type(rollback_error).__name__, + }, + ) raise return moved_main, renamed_sidecars except OSError as e: - LOG.error(f"Failed to move '{old_path}' to '{new_path}': {e}") + LOG.exception( + "Failed to move '%s' to '%s'.", + old_path, + new_path, + extra={ + "old_path": str(old_path), + "new_path": str(new_path), + "operation": "move", + "exception_type": type(e).__name__, + }, + ) raise @@ -818,7 +927,11 @@ def get_file(download_path: str | Path, file: str | Path) -> tuple[Path, int]: if realFile.exists(): return (realFile, 200) except Exception as e: - LOG.error(f"Error calculating download path. {e!s}") + LOG.exception( + "Failed to resolve download file path for '%s'.", + file, + extra={"file_path": str(file), "download_path": str(download_path), "exception_type": type(e).__name__}, + ) return (Path(file), 404) possibleFile: bool | str = check_id(file=realFile) @@ -989,21 +1102,41 @@ def get_files( try: dir_path = dir_path.resolve() except OSError as e: - LOG.warning(f"Failed to resolve '{dir}' - {e}") + LOG.warning( + "Failed to resolve '%s': %s", + dir, + e, + extra={"requested_dir": dir, "base_path": str(base_path), "exception_type": type(e).__name__}, + exc_info=True, + ) return [] try: dir_path.relative_to(base_path) except ValueError: - LOG.warning(f"Invalid path: '{dir_path}' - must be inside '{base_path}'.") + LOG.warning( + "Invalid path '%s': must be inside '%s'.", + dir_path, + base_path, + extra={"path": str(dir_path), "base_path": str(base_path)}, + ) return [] if not str(dir_path).startswith(str(base_path)): - LOG.warning(f"Invalid path: '{dir_path}' - must be inside '{base_path}'.") + LOG.warning( + "Invalid path '%s': must be inside '%s'.", + dir_path, + base_path, + extra={"path": str(dir_path), "base_path": str(base_path)}, + ) return [] if not dir_path.is_dir(): - LOG.warning(f"Invalid path: '{dir_path}' - must be a directory.") + LOG.warning( + "Invalid path '%s': must be a directory.", + dir_path, + extra={"path": str(dir_path), "base_path": str(base_path)}, + ) return [] contents: list = [] @@ -1017,13 +1150,28 @@ def get_files( test: Path = file.resolve() test.relative_to(base_path) if not str(test).startswith(str(base_path)): - LOG.warning(f"Invalid symlink: '{file}' - must resolve inside '{base_path}'.") + LOG.warning( + "Invalid symlink '%s': must resolve inside '%s'.", + file, + base_path, + extra={"path": str(file), "resolved_path": str(test), "base_path": str(base_path)}, + ) continue except ValueError: - LOG.warning(f"Invalid symlink: '{file}' - must resolve inside '{base_path}'.") + LOG.warning( + "Invalid symlink '%s': must resolve inside '%s'.", + file, + base_path, + extra={"path": str(file), "base_path": str(base_path)}, + ) continue - except OSError: - LOG.warning(f"Skipping broken symlink: {file}") + except OSError as e: + LOG.warning( + "Skipping broken symlink '%s'.", + file, + extra={"path": str(file), "base_path": str(base_path), "exception_type": type(e).__name__}, + exc_info=True, + ) continue content_type = None @@ -1213,7 +1361,11 @@ def delete_dir(dir: Path) -> bool: dir.rmdir() return True except Exception as e: - LOG.error(f"Failed to delete directory '{dir}': {e}") + LOG.exception( + "Failed to delete directory '%s'.", + dir, + extra={"dir": str(dir), "exception_type": type(e).__name__}, + ) return False @@ -1261,7 +1413,11 @@ def load_modules(root_path: Path, directory: Path): try: importlib.import_module(full_name) except ImportError as e: - LOG.error(f"Failed to import module '{full_name}': {e}") + LOG.exception( + "Failed to import module '%s'.", + full_name, + extra={"module_name": full_name, "exception_type": type(e).__name__}, + ) def parse_tags(text: str) -> tuple[str, dict[str, str | bool]]: diff --git a/app/library/cache.py b/app/library/cache.py index cce18362..507e7c11 100644 --- a/app/library/cache.py +++ b/app/library/cache.py @@ -175,4 +175,8 @@ class Cache(metaclass=ThreadSafe): del self._cache[key] if expired_keys: - LOG.debug(f"Cleaned up {len(expired_keys)} expired cache entries.") + LOG.debug( + "Cleaned up %s expired cache entries.", + len(expired_keys), + extra={"expired_count": len(expired_keys)}, + ) diff --git a/app/library/cf_solver_handler.py b/app/library/cf_solver_handler.py index 4b23bec4..19debf09 100644 --- a/app/library/cf_solver_handler.py +++ b/app/library/cf_solver_handler.py @@ -215,7 +215,7 @@ class CFSolverRH(RequestHandler, ABC): def _send(self, request: Request) -> Response: host: str = self._get_host(request.url) if host and (cached := CACHE.get(host)): - LOG.info(f"Injecting cached Cloudflare cookies for '{host}'.") + LOG.info("Injecting cached Cloudflare cookies for '%s'.", host, extra={"host": host}) self._apply_solution(cached, request.url, request.headers, self._get_cookiejar(request)) director: RequestDirector = self._build_fallback() diff --git a/app/library/cf_solver_shared.py b/app/library/cf_solver_shared.py index b95e0029..a54a881b 100644 --- a/app/library/cf_solver_shared.py +++ b/app/library/cf_solver_shared.py @@ -63,16 +63,29 @@ def solver(url: str, cookies: list[dict[str, Any]], user_agent: str | None) -> d method="POST", ) - LOG.info(f"Solving Cloudflare challenge for '{host}' via FlareSolverr.") + LOG.info( + "Solving Cloudflare challenge for '%s' via FlareSolverr.", host, extra={"host": host, "endpoint": endpoint} + ) start_time = time.time() with urllib.request.urlopen(req, timeout=float(config.flaresolverr_client_timeout)) as resp: result = json.loads(resp.read().decode("utf-8")) if "ok" != result.get("status"): - LOG.error(f"FlareSolverr failed to solve challenge for '{host}': {result.get('message')}") + LOG.error( + "FlareSolverr failed to solve challenge for '%s': %s", + host, + result.get("message"), + extra={"host": host, "endpoint": endpoint, "solver_message": result.get("message")}, + ) return None - LOG.info(f"FlareSolverr successfully solved challenge for '{host}'. (Took {time.time() - start_time:.2f} seconds)") + elapsed_s: float = time.time() - start_time + LOG.info( + "FlareSolverr solved challenge for '%s' in %.2f seconds.", + host, + elapsed_s, + extra={"host": host, "endpoint": endpoint, "elapsed_s": round(elapsed_s, 2)}, + ) solution = result.get("solution") or {} CACHE.set( diff --git a/app/library/config.py b/app/library/config.py index f3d8b4f4..e671be31 100644 --- a/app/library/config.py +++ b/app/library/config.py @@ -75,9 +75,6 @@ class Config(metaclass=Singleton): log_level: str = "info" """The log level to use for the application.""" - log_level_file: str = "info" - """The log level to use for the file logging.""" - base_path: str = "/" """The base path to use for the application.""" @@ -440,11 +437,18 @@ class Config(metaclass=Singleton): import debugpy debugpy.listen(("0.0.0.0", self.debugpy_port), in_process_debug_adapter=True) - LOG.info(f"starting debugpy server on '0.0.0.0:{self.debugpy_port}'.") + LOG.info( + "Starting debugpy server on '0.0.0.0:%s'.", + self.debugpy_port, + extra={"host": "0.0.0.0", "port": self.debugpy_port}, + ) except ImportError: - LOG.error("debugpy package not found, install it with 'uv sync'.") + LOG.exception("debugpy package not found; install it with 'uv sync'.") except Exception as e: - LOG.error(f"Error starting debugpy server at '0.0.0.0:{self.debugpy_port}'. {e}") + LOG.exception( + "Failed to start debugpy server.", + extra={"host": "0.0.0.0", "port": self.debugpy_port, "exception_type": type(e).__name__}, + ) if (Path(self.config_path) / "ytdlp.cli").exists(): LOG.error("Support for ./ytdlp.cli file is removed, migrate to presets and remove the file.") @@ -453,12 +457,16 @@ class Config(metaclass=Singleton): LOG.warning("Keep temp files option is enabled.") if self.auth_password and self.auth_username: - LOG.info(f"Authentication enabled with username '{self.auth_username}'.") + LOG.info( + "Authentication enabled with username '%s'.", + self.auth_username, + extra={"auth_username": self.auth_username}, + ) if self.file_logging: - log_level_file: int | None = getattr(logging, self.log_level_file.upper(), None) - if not isinstance(log_level_file, int): - msg = f"Invalid file log level '{self.log_level_file}' specified." + file_log_level: int | None = getattr(logging, self.log_level.upper(), None) + if not isinstance(file_log_level, int): + msg = f"Invalid log level '{self.log_level}' specified." raise TypeError(msg) loggingPath: Path = Path(self.config_path) / "logs" @@ -472,7 +480,7 @@ class Config(metaclass=Singleton): encoding="utf-8", ) - handler.setLevel(log_level_file) + handler.setLevel(file_log_level) formatter = JsonLogFormatter() handler.setFormatter(formatter) logging.getLogger().addHandler(handler) @@ -495,6 +503,7 @@ class Config(metaclass=Singleton): ("apprise", logging.WARNING), ("httpcore", logging.INFO), ("aiosqlite", logging.INFO), + ("asyncio", logging.INFO), ) for _tool, _level in _log_levels: logging.getLogger(_tool).setLevel(_level) diff --git a/app/library/downloads/core.py b/app/library/downloads/core.py index e532ad22..8efb21c5 100644 --- a/app/library/downloads/core.py +++ b/app/library/downloads/core.py @@ -138,12 +138,32 @@ class Download: try: cookie_file = Path(self._temp_manager.temp_path or self.temp_dir) / f"cookie_{self.info._id}.txt" self.logger.debug( - f"Creating cookie file for '{self.info.id}: {self.info.title}' - '{cookie_file}'." + f"Creating cookie file for '{self.info.title}' at '{cookie_file}'.", + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "path": str(cookie_file), + "has_cookies": True, + } + }, ) params["cookiefile"] = str(create_cookies_file(self.info.cookies, cookie_file)) except Exception as e: err_msg: str = f"Failed to create cookie file for '{self.info.id}: {self.info.title}'. '{e!s}'." - self.logger.error(err_msg) + self.logger.error( + err_msg, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "has_cookies": True, + "exception_type": type(e).__name__, + } + }, + ) raise ValueError(err_msg) from e if self.info_dict and isinstance(self.info_dict, dict): @@ -153,7 +173,19 @@ class Download: ) self.info_dict = None elif self.info_dict.get("extractor_key") in GENERIC_EXTRACTORS and self.info.get_preset().default: - self.logger.debug(f"Removing 'download_archive' for generic extractor. url={self.info.url}") + self.logger.debug( + "Removing download archive option for generic extractor on '%s'.", + self.info.url, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "url": self.info.url, + "extractor": self.info_dict.get("extractor_key"), + } + }, + ) params.pop("download_archive", None) if self.info_dict and self.download_info_expires > 0: @@ -161,10 +193,34 @@ class Download: _ts_dt = datetime.fromtimestamp(_ts, tz=UTC) if _ts else None if not _ts_dt or (datetime.now(tz=UTC) - _ts_dt).total_seconds() > self.download_info_expires: self.info_dict = None - self.logger.warning(f"Info for '{self.info.url}' has expired, re-extracting info.") + self.logger.warning( + "Pre-extracted info for '%s' expired; extracting again.", + self.info.url, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "url": self.info.url, + "expires_s": self.download_info_expires, + } + }, + ) if not self.info_dict or not isinstance(self.info_dict, dict): - self.logger.info(f"Extracting info for '{self.info.url}'.") + self.logger.info( + f"Extracting info for '{self.info.url}'.", + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "url": self.info.url, + "preset": self.info.preset, + "has_cookies": bool(params.get("cookiefile")), + } + }, + ) ie_params: dict = params.copy() (info, logs) = extract_info_sync( @@ -188,7 +244,20 @@ class Download: deletedOpts.append(opt) if len(deletedOpts) > 0: - self.logger.warning(f"Live stream detected for '{self.info.title}', deleted opts: {deletedOpts}") + self.logger.warning( + "Removed unsupported live stream options before downloading '%s'.", + self.info.title, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "url": self.info.url, + "removed_options": deletedOpts, + "is_live": self.is_live, + } + }, + ) if isinstance(self.info_dict, dict) and not ( len(self.info_dict.get("formats", [])) > 0 or self.info_dict.get("url") @@ -200,11 +269,36 @@ class Download: raise ValueError(msg) # noqa: TRY301 self.logger.info( - f'Download {self.info.name()}, preset="{self.info.preset}", cookies="{bool(params.get("cookiefile"))}" started.' + f"Downloading '{self.info.title}' from '{self.info.url}' to '{self.download_dir}'.", + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "url": self.info.url, + "path": self.download_dir, + "preset": self.info.preset, + "has_cookies": bool(params.get("cookiefile")), + "download_skipped": download_skipped, + } + }, ) if self.debug: - self.logger.debug(f"Params before passing to yt-dlp. {params}") + self.logger.debug( + "Prepared yt-dlp parameters for '%s'.", + self.info.title, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "url": self.info.url, + "option_keys": sorted(str(key) for key in params), + "has_cookies": bool(params.get("cookiefile")), + } + }, + ) params["logger"] = NestedLogger(self.logger) @@ -239,7 +333,19 @@ class Download: self.status_queue.put({"id": self.id, "status": "downloading", "download_skipped": download_skipped}) if isinstance(self.info_dict, dict) and len(self.info_dict) > 1: - self.logger.debug(f"Downloading '{self.info.url}' using pre-info.") + self.logger.debug( + "Downloading '%s' using pre-extracted info.", + self.info.title, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "url": self.info.url, + "preset": self.info.preset, + } + }, + ) _dct: dict = self.info_dict.copy() if isinstance(self.info.extras, dict) and len(self.info.extras) > 0: _dct.update( @@ -264,7 +370,19 @@ class Download: cls.process_ie_result(ie_result=_dct, download=True) ret: int = cls._download_retcode else: - self.logger.debug(f"Downloading using url: {self.info.url}") + self.logger.debug( + "Downloading '%s' directly from URL.", + self.info.title, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "url": self.info.url, + "preset": self.info.preset, + } + }, + ) ret = cls.download(url_list=[self.info.url]) self.status_queue.put( @@ -275,7 +393,19 @@ class Download: } ) except yt_dlp.utils.ExistingVideoReached as exc: - self.logger.error(exc) + self.logger.error( + f"Skipping already downloaded '{self.info.title}' from '{self.info.url}'. {exc!s}", + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "url": self.info.url, + "status": "skip", + "exception_type": type(exc).__name__, + } + }, + ) self.status_queue.put( { "id": self.id, @@ -285,8 +415,22 @@ class Download: } ) except Exception as exc: - self.logger.exception(exc) - self.logger.error(exc) + self.logger.exception( + f"Failed to download '{self.info.title}' from '{self.info.url}'.", + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "url": self.info.url, + "path": self.download_dir, + "preset": self.info.preset, + "has_cookies": bool(params.get("cookiefile")), + "status": "error", + "exception_type": type(exc).__name__, + } + }, + ) self.status_queue.put( { "id": self.id, @@ -301,12 +445,46 @@ class Download: if cookie_file and cookie_file.exists(): try: cookie_file.unlink() - self.logger.debug(f"Deleted cookie file: {cookie_file}") + self.logger.debug( + f"Deleted cookie file for '{self.info.title}' at '{cookie_file}'.", + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "path": str(cookie_file), + "has_cookies": True, + } + }, + ) except Exception as e: - self.logger.error(f"Failed to delete cookie file: {cookie_file}. {e}") + self.logger.error( + f"Failed to delete cookie file for '{self.info.title}' at '{cookie_file}'. {e!s}", + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "path": str(cookie_file), + "has_cookies": True, + "exception_type": type(e).__name__, + } + }, + ) self.logger.info( - f'Task {self.info.name()} preset="{self.info.preset}" cookies="{bool(params.get("cookiefile"))}" completed.' + f"Download task finished for '{self.info.title}'.", + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "url": self.info.url, + "path": self.download_dir, + "preset": self.info.preset, + "has_cookies": bool(params.get("cookiefile")), + } + }, ) async def start(self) -> int | None: @@ -393,8 +571,19 @@ class Download: return True except Exception as e: - self.logger.error(f"Failed to close process. {e}") - self.logger.exception(e) + self.logger.exception( + f"Failed to close download process for '{self.info.title}'.", + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "url": self.info.url, + "status": self.info.status, + "exception_type": type(e).__name__, + } + }, + ) return False @@ -422,12 +611,28 @@ class Download: """ if self.started_time < 1: - self.logger.debug(f"Download task '{self.info.name()}' not started yet.") + self.logger.debug( + "Download task for '%s' has not started yet.", + self.info.title, + extra={"download": {"download_id": self.id, "item_id": self.info.id, "title": self.info.title}}, + ) return False elapsed = int(time.time()) - self.started_time if elapsed < 300: - self.logger.debug(f"Download task '{self.info.title}: {self.info.id}' started for '{elapsed}' seconds.") + self.logger.debug( + "Download task for '%s' has been running for %s seconds.", + self.info.title, + elapsed, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "elapsed_s": elapsed, + } + }, + ) return False status: str = self.info.status or "unknown" diff --git a/app/library/downloads/hooks.py b/app/library/downloads/hooks.py index 113ca63b..dd446230 100644 --- a/app/library/downloads/hooks.py +++ b/app/library/downloads/hooks.py @@ -33,9 +33,19 @@ class HookHandlers: if self.debug: try: d_safe = create_debug_safe_dict(data) - self.logger.debug(f"PG Hook: {d_safe}") + self.logger.debug( + "Received progress hook for download '%s'.", + self.id, + extra={"download": {"download_id": self.id, "hook": "progress", "status": d_safe}}, + ) except Exception as e: - self.logger.debug(f"PG Hook: Error creating debug info: {e}") + self.logger.exception( + "Failed to create progress hook debug info for download '%s'.", + self.id, + extra={ + "download": {"download_id": self.id, "hook": "progress", "exception_type": type(e).__name__} + }, + ) self.status_queue.put( { @@ -62,9 +72,23 @@ class HookHandlers: try: d_safe = create_debug_safe_dict(data) d_safe["postprocessor"] = data.get("postprocessor") - self.logger.debug(f"PP Hook: {d_safe}") + self.logger.debug( + "Received postprocessor hook for download '%s'.", + self.id, + extra={"download": {"download_id": self.id, "hook": "postprocessor", "status": d_safe}}, + ) except Exception as e: - self.logger.debug(f"PP Hook: Error creating debug info: {e}") + self.logger.exception( + "Failed to create postprocessor hook debug info for download '%s'.", + self.id, + extra={ + "download": { + "download_id": self.id, + "hook": "postprocessor", + "exception_type": type(e).__name__, + } + }, + ) self.status_queue.put(status) diff --git a/app/library/downloads/item_adder.py b/app/library/downloads/item_adder.py index 7467cf87..68aa74c6 100644 --- a/app/library/downloads/item_adder.py +++ b/app/library/downloads/item_adder.py @@ -122,7 +122,11 @@ async def add( try: arg_converter(args=item.cli, level=True) except Exception as e: - LOG.error(f"Invalid command options for yt-dlp '{item.cli}'. {e!s}") + LOG.error( + "Invalid yt-dlp command options for '%s'.", + item.url, + extra={"url": item.url, "preset": item.preset, "exception_type": type(e).__name__}, + ) return {"status": "error", "msg": f"Invalid command options for yt-dlp '{item.cli}'. {e!s}"} if _preset: @@ -135,12 +139,27 @@ async def add( yt_conf = {} cookie_file: Path = Path(queue.config.temp_path) / f"c_{uuid.uuid4().hex}.txt" - LOG.info(f"Adding '{item!r}'.") + LOG.info( + f"Adding '{item.url}' to downloads.", + extra={ + "download": { + "url": item.url, + "preset": item.preset, + "folder": item.folder, + "has_cookies": bool(item.cookies), + "auto_start": item.auto_start, + } + }, + ) already = set() if already is None else already if item.url in already: - LOG.warning(f"Recursion detected with url '{item.url}' skipping.") + LOG.warning( + "Skipping recursive download URL '%s'.", + item.url, + extra={"url": item.url, "preset": item.preset}, + ) return {"status": "ok"} already.add(item.url) @@ -149,7 +168,16 @@ async def add( yt_conf: dict = item.get_ytdlp_opts().get_all() if yt_conf.get("external_downloader"): - LOG.warning(f"Using external downloader '{yt_conf.get('external_downloader')}' for '{item.url}'.") + LOG.warning( + "Using external downloader '%s' for '%s'.", + yt_conf.get("external_downloader"), + item.url, + extra={ + "url": item.url, + "preset": item.preset, + "external_downloader": yt_conf.get("external_downloader"), + }, + ) item.extras.update({"external_downloader": True}) archive_id: str | None = item.get_archive_id() @@ -201,14 +229,45 @@ async def add( yt_conf["cookiefile"] = str(create_cookies_file(item.cookies, cookie_file)) except Exception as e: msg = f"Failed to create cookie file for '{item.url}'. '{e!s}'." - LOG.error(msg) + LOG.exception( + msg, + extra={ + "download": { + "url": item.url, + "preset": item.preset, + "path": str(cookie_file), + "has_cookies": True, + "exception_type": type(e).__name__, + } + }, + ) return {"status": "error", "msg": msg} if entry: - LOG.info(f"[P] Extracting '{item.url}'{' with cookies' if yt_conf.get('cookiefile') else ''}.") + LOG.info( + f"Processing pre-extracted info for '{item.url}'.", + extra={ + "download": { + "url": item.url, + "preset": item.preset, + "has_cookies": bool(yt_conf.get("cookiefile")), + "pre_extracted": True, + } + }, + ) if not entry: - LOG.info(f"Extracting '{item.url}'{' with cookies' if yt_conf.get('cookiefile') else ''}.") + LOG.info( + f"Extracting info for '{item.url}'.", + extra={ + "download": { + "url": item.url, + "preset": item.preset, + "has_cookies": bool(yt_conf.get("cookiefile")), + "pre_extracted": False, + } + }, + ) (entry, logs) = await fetch_info( config=yt_conf, url=item.url, @@ -221,7 +280,17 @@ async def add( ) if not entry: - LOG.error(f"Unable to extract info for '{item.url}'. Logs: {logs}") + LOG.error( + f"Unable to extract info for '{item.url}'.", + extra={ + "download": { + "url": item.url, + "preset": item.preset, + "has_cookies": bool(yt_conf.get("cookiefile")), + "yt_dlp_logs": logs, + } + }, + ) return {"status": "error", "msg": "Unable to extract info." + "\n".join(logs)} # Sometimes playlists or extractor returns different ID than what we get from the make_archive_id() @@ -293,7 +362,9 @@ async def add( ): already.pop() - message = f"Condition '{condition.name}' matched for '{item!r}'." + display = str(entry.get("title") or entry.get("webpage_url") or entry.get("url") or item.url) + + message = f"Condition '{condition.name}' matched for '{display}'." if condition.cli: message += f" Re-queuing with '{condition.cli}'." @@ -306,8 +377,8 @@ async def add( archive_add(_archive_file, [archive_id]) extra_msg = f" and added to archive file '{_archive_file}'" - _name = entry.get("title", entry.get("id")) - log_message = f"Ignoring download of '{_name!r}' as per condition '{condition.name}'{extra_msg}." + _name = str(entry.get("title") or entry.get("id") or item.url) + log_message = f"Ignoring download of '{_name}' as per condition '{condition.name}'{extra_msg}." store_type, dlInfo = await queue.get_item(archive_id=archive_id) if not store_type: @@ -339,7 +410,10 @@ async def add( if condition.extras.get("set_preset") and (target_preset := condition.extras.get("set_preset")): if Presets.get_instance().has(target_preset): - log_message: str = f"Switching preset from '{item.preset}' to '{target_preset}' for '{item!r}' as per condition '{condition.name}'." + log_message: str = ( + f"Switching preset from '{item.preset}' to '{target_preset}' for '{display}' " + f"as per condition '{condition.name}'." + ) LOG.info(log_message) queue._notify.emit(Events.LOG_INFO, data={}, title="Preset Switched", message=log_message) item = item.new_with(preset=target_preset) @@ -356,15 +430,61 @@ async def add( return {"status": "error", "msg": _msg} end_time = time.perf_counter() - started - LOG.debug(f"extract_info: for 'URL: {item.url}' is done in '{end_time:.3f}'. Length: '{len(entry)}/keys'.") + LOG.debug( + f"Extracted info for '{item.url}' in '{end_time:.3f}' seconds.", + extra={ + "download": { + "url": item.url, + "preset": item.preset, + "has_cookies": bool(yt_conf.get("cookiefile")), + "elapsed_seconds": round(end_time, 3), + "entry_keys": len(entry), + } + }, + ) except yt_dlp.utils.ExistingVideoReached as exc: - LOG.error(f"Video has been downloaded already and recorded in archive.log file. '{exc!s}'.") + LOG.error( + "Video '%s' is already recorded in the download archive.", + item.url, + extra={ + "download": { + "url": item.url, + "preset": item.preset, + "status": "skip", + "exception_type": type(exc).__name__, + } + }, + ) return {"status": "error", "msg": "Video has been downloaded already and recorded in archive.log file."} except yt_dlp.utils.YoutubeDLError as exc: - LOG.error(f"YoutubeDLError: Unable to extract info. '{exc!s}'.") + LOG.exception( + "Failed to extract media info for '%s'.", + item.url, + extra={ + "download": { + "url": item.url, + "preset": item.preset, + "has_cookies": bool(yt_conf.get("cookiefile")), + "exception_type": type(exc).__name__, + } + }, + ) return {"status": "error", "msg": str(exc)} except asyncio.exceptions.TimeoutError as exc: - LOG.error(f"TimeoutError: Unable to extract info. '{exc!s}'.") + LOG.exception( + "Timed out extracting media info for '%s' after %s second(s).", + item.url, + queue.config.extract_info_timeout, + extra={ + "download": { + "url": item.url, + "preset": item.preset, + "has_cookies": bool(yt_conf.get("cookiefile")), + "timeout_seconds": queue.config.extract_info_timeout, + "exception_type": type(exc).__name__, + } + }, + ) return { "status": "error", "msg": f"TimeoutError: {queue.config.extract_info_timeout}s reached Unable to extract info.", @@ -375,6 +495,19 @@ async def add( cookie_file.unlink(missing_ok=True) yt_conf.pop("cookiefile", None) except Exception as e: - LOG.error(f"Failed to remove cookie file '{yt_conf['cookiefile']}'. {e!s}") + LOG.exception( + "Failed to remove cookie file for '%s' at '%s'.", + item.url, + yt_conf["cookiefile"], + extra={ + "download": { + "url": item.url, + "preset": item.preset, + "path": yt_conf["cookiefile"], + "has_cookies": True, + "exception_type": type(e).__name__, + } + }, + ) return await add_item(queue=queue, entry=entry, item=item, already=already, logs=logs, yt_params=yt_conf) diff --git a/app/library/downloads/monitors.py b/app/library/downloads/monitors.py index ac739c36..c13736d5 100644 --- a/app/library/downloads/monitors.py +++ b/app/library/downloads/monitors.py @@ -31,16 +31,37 @@ async def check_for_stale(queue: "DownloadQueue") -> None: return for _id, item in list(queue.queue.items()): - item_ref = f"{_id=} {item.info.id=} {item.info.title=}" if not item.is_stale(): continue try: - LOG.warning(f"Cancelling staled item '{item_ref}' from download queue.") + LOG.warning( + f"Cancelling stale download '{item.info.title}' from queue.", + extra={ + "download": { + "download_id": _id, + "item_id": item.info.id, + "title": item.info.title, + "url": item.info.url, + "status": item.info.status, + } + }, + ) await queue.cancel([_id]) except Exception as e: - LOG.error(f"Failed to cancel staled item '{item_ref}'. {e!s}") - LOG.exception(e) + LOG.exception( + f"Failed to cancel stale download '{item.info.title}'.", + extra={ + "download": { + "download_id": _id, + "item_id": item.info.id, + "title": item.info.title, + "url": item.info.url, + "status": item.info.status, + "exception_type": type(e).__name__, + } + }, + ) async def check_live(queue: "DownloadQueue") -> None: @@ -68,9 +89,19 @@ async def check_live(queue: "DownloadQueue") -> None: if item.info.status not in status: continue - item_ref: str = f"{id=} {item.info.id=} {item.info.title=}" if not item.is_live: - LOG.debug(f"Item '{item_ref}' is not a live stream.") + LOG.debug( + "Skipping history item '%s' because it is not a live stream.", + item.info.title, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "status": item.info.status, + } + }, + ) continue duration: int | None = item.info.extras.get("duration", None) @@ -79,7 +110,17 @@ async def check_live(queue: "DownloadQueue") -> None: live_in: str | None = item.info.live_in or ag(item.info.extras, ["live_in", "release_in"], None) if not live_in: LOG.debug( - f"Item '{item_ref}' marked as {'premiere video' if is_premiere else 'live stream'}, but no date is set." + "Skipping %s '%s' because no start time is set.", + "premiere video" if is_premiere else "live stream", + item.info.title, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "is_premiere": is_premiere, + } + }, ) continue @@ -87,24 +128,76 @@ async def check_live(queue: "DownloadQueue") -> None: starts_in = starts_in.replace(tzinfo=UTC) if starts_in.tzinfo is None else starts_in.astimezone(UTC) if time_now < (starts_in + timedelta(minutes=1)): - LOG.debug(f"Item '{item_ref}' is not yet live. will start at '{dt_delta(starts_in - time_now)}'.") + starts_in_text = dt_delta(starts_in - time_now) + LOG.debug( + "Live item '%s' is not ready yet; starts in %s.", + item.info.title, + starts_in_text, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "live_in": live_in, + "starts_in": starts_in_text, + } + }, + ) continue if queue.config.prevent_live_premiere and is_premiere and duration: buffer_time = queue.config.live_premiere_buffer if queue.config.live_premiere_buffer >= 0 else 5 premiere_ends: datetime = starts_in + timedelta(minutes=buffer_time, seconds=duration) if time_now < premiere_ends: + start_after = premiere_ends.astimezone().isoformat() LOG.debug( - f"Item '{item_ref}' is premiering, download will start in '{(starts_in + timedelta(minutes=buffer_time, seconds=duration)).astimezone().isoformat()}'" + "Premiere '%s' is still running; download will start after '%s'.", + item.info.title, + start_after, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "is_premiere": is_premiere, + "start_after": start_after, + } + }, ) continue - LOG.info(f"Retrying item '{item_ref} {item.info.extras=}' for download.") + LOG.info( + f"Retrying live download '{item.info.title}' from '{item.info.url}'.", + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "url": item.info.url, + "preset": item.info.preset, + "live_in": live_in, + "is_premiere": is_premiere, + } + }, + ) try: await queue.clear([item.info._id], remove_file=False) except Exception as e: - LOG.error(f"Failed to clear item '{item_ref}'. {e!s}") + LOG.exception( + "Failed to clear live download '%s' before retry.", + item.info.title, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "url": item.info.url, + "preset": item.info.preset, + "exception_type": type(e).__name__, + } + }, + ) continue try: @@ -121,8 +214,21 @@ async def check_live(queue: "DownloadQueue") -> None: ) except Exception as e: await queue.done.put(item) - LOG.exception(e) - LOG.error(f"Failed to retry item '{item_ref}'. {e!s}") + LOG.exception( + "Failed to retry live download '%s' from '%s'.", + item.info.title, + item.info.url, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "url": item.info.url, + "preset": item.info.preset, + "exception_type": type(e).__name__, + } + }, + ) async def delete_old_history(queue: "DownloadQueue") -> None: @@ -156,7 +262,19 @@ async def delete_old_history(queue: "DownloadQueue") -> None: if item_datetime < cutoff_date: items_to_delete.append((key, info)) except (OSError, ValueError, OverflowError) as e: - LOG.error(f"Failed to parse timestamp '{info.timestamp}' for item '{info.title}': {e}") + LOG.exception( + "Failed to parse timestamp for history item '%s'.", + info.title, + extra={ + "download": { + "download_id": key, + "item_id": info.id, + "title": info.title, + "timestamp": info.timestamp, + "exception_type": type(e).__name__, + } + }, + ) titles: list[str] = [] for key, info in items_to_delete: @@ -171,7 +289,11 @@ async def delete_old_history(queue: "DownloadQueue") -> None: await queue.done.delete(key) if titles: - LOG.info(f"Automatically cleared '{', '.join(titles)}' from download history due to age.") + LOG.info( + "Automatically cleared %s old history item(s).", + len(titles), + extra={"deleted_count": len(titles), "titles": titles}, + ) async def cleanup_thumbnails(queue: "DownloadQueue") -> None: @@ -201,7 +323,11 @@ async def cleanup_thumbnails(queue: "DownloadQueue") -> None: thumb.unlink(missing_ok=True) removed += 1 except OSError as exc: - LOG.warning(f"Failed to remove orphaned thumbnail '{thumb}'. {exc!s}") + LOG.exception( + "Failed to remove orphaned thumbnail '%s'.", + thumb, + extra={"file_path": str(thumb), "exception_type": type(exc).__name__}, + ) if removed > 0: - LOG.info(f"Removed '{removed}' orphaned cached thumbnails.") + LOG.info("Removed %s orphaned cached thumbnail(s).", removed, extra={"removed_count": removed}) diff --git a/app/library/downloads/playlist_processor.py b/app/library/downloads/playlist_processor.py index cde700bf..6d6fffd5 100644 --- a/app/library/downloads/playlist_processor.py +++ b/app/library/downloads/playlist_processor.py @@ -38,7 +38,17 @@ async def process_playlist( playlist_name: str = f"{entry.get('id')}: {entry.get('title')}" - LOG.info(f"Processing '{playlist_name} ({len(entries)})' Playlist.") + LOG.info( + "Processing playlist '%s' with %s entrie(s).", + playlist_name, + len(entries), + extra={ + "playlist_id": entry.get("id"), + "playlist_title": entry.get("title"), + "entry_count": len(entries), + "preset": getattr(item, "preset", None), + }, + ) playlistCount = entry.get("playlist_count") playlistCount: int = int(playlistCount) if playlistCount else len(entries) @@ -62,7 +72,18 @@ async def process_playlist( item_name: str = ( f"'{entry.get('title')}: {i}/{playlist_keys['n_entries']}' - '{etr.get('id')}: {etr.get('title')}'" ) - LOG.info(f"Processing '{item_name}'.") + LOG.info( + "Processing playlist item '%s'.", + item_name, + extra={ + "playlist_id": entry.get("id"), + "playlist_title": entry.get("title"), + "playlist_index": i, + "entry_count": playlist_keys["n_entries"], + "item_id": etr.get("id"), + "title": etr.get("title"), + }, + ) _status, _msg = ytdlp_reject(entry=etr, yt_params=yt_params) if not _status: @@ -110,12 +131,23 @@ async def process_playlist( results.append(await process_item(i, etr)) - log_msg: str = f"Playlist '{playlist_name}' processing completed with '{len(results)}' entries." + skipped = 0 if max_downloads > 0 and len(entries) > max_downloads: - skipped: int = len(entries) - max_downloads - log_msg += f" Limited to '{max_downloads}' items, skipped '{skipped}' remaining items." + skipped = len(entries) - max_downloads - LOG.info(log_msg) + LOG.info( + "Playlist '%s' processing completed with %s item(s).", + playlist_name, + len(results), + extra={ + "playlist_id": entry.get("id"), + "playlist_title": entry.get("title"), + "processed_count": len(results), + "entry_count": len(entries), + "max_downloads": max_downloads, + "skipped_count": skipped, + }, + ) if any("error" == res["status"] for res in results): return { diff --git a/app/library/downloads/pool_manager.py b/app/library/downloads/pool_manager.py index beadcf8a..a566c570 100644 --- a/app/library/downloads/pool_manager.py +++ b/app/library/downloads/pool_manager.py @@ -78,7 +78,11 @@ class PoolManager: async def shutdown(self) -> None: if self._active: - LOG.info(f"Cancelling '{len(self._active)}' active downloads.") + LOG.info( + "Cancelling %s active download(s).", + len(self._active), + extra={"active_count": len(self._active), "download_ids": list(self._active)}, + ) await self.queue.cancel(list(self._active.keys())) async def _download_pool(self) -> None: @@ -140,7 +144,11 @@ class PoolManager: # No items could be processed, back off a bit to avoid busy-waiting. if 0 == items_processed: adaptive_sleep: float = min(adaptive_sleep * 1.5, max_sleep) - LOG.debug(f"No download slots available. Backing off for {adaptive_sleep:.2f}s before next attempt.") + LOG.debug( + "No download slots available; backing off for %.2f seconds.", + adaptive_sleep, + extra={"backoff_s": round(adaptive_sleep, 2), "active_count": len(self._active)}, + ) else: adaptive_sleep = 0.2 @@ -156,7 +164,23 @@ class PoolManager: """ filePath: str = calc_download_path(base_path=self.config.download_path, folder=entry.info.folder) - LOG.info(f"Downloading 'id: {entry.id}', 'Title: {entry.info.title}', 'URL: {entry.info.url}' To '{filePath}'.") + LOG.info( + "Downloading '%s' from '%s' to '%s'.", + entry.info.title, + entry.info.url, + filePath, + extra={ + "download": { + "download_id": entry.id, + "item_id": entry.info.id, + "title": entry.info.title, + "url": entry.info.url, + "download_dir": filePath, + "preset": entry.info.preset, + "is_live": entry.is_live, + } + }, + ) try: self._active[entry.info._id] = entry @@ -176,7 +200,18 @@ class PoolManager: await entry.close() if await self.queue.queue.exists(key=id): - LOG.debug(f"Download Task '{id}' is completed. Removing from queue.") + LOG.debug( + "Removing completed download '%s' from queue.", + entry.info.title, + extra={ + "download": { + "download_id": id, + "item_id": entry.info.id, + "title": entry.info.title, + "status": entry.info.status, + } + }, + ) await self.queue.queue.delete(key=id) nTitle: str | None = None @@ -211,7 +246,7 @@ class PoolManager: message=nMessage, ) else: - LOG.warning(f"Download '{id}' not found in queue.") + LOG.warning("Completed download '%s' was not found in queue.", id, extra={"download_id": id}) if self.event: self.event.set() diff --git a/app/library/downloads/process_manager.py b/app/library/downloads/process_manager.py index ec36e8be..851fe181 100644 --- a/app/library/downloads/process_manager.py +++ b/app/library/downloads/process_manager.py @@ -101,52 +101,159 @@ class ProcessManager: procId: int | None = self.proc.ident try: - self.logger.info(f"Killing download process: PID={self.proc.pid}, ident={procId}.") + self.logger.info( + "Stopping download process PID=%s.", + self.proc.pid, + extra={ + "download": { + "download_id": self.download_id, + "process_id": self.proc.pid, + "process_ident": procId, + "is_live": self.is_live, + } + }, + ) if self.is_live: - self.logger.debug(f"Requesting graceful live cancellation for PID={self.proc.pid}.") + self.logger.debug( + "Requesting graceful live cancellation for PID=%s.", + self.proc.pid, + extra={ + "download": { + "download_id": self.download_id, + "process_id": self.proc.pid, + "is_live": self.is_live, + } + }, + ) self.cancel_event.set() if wait_for_process_with_timeout(self.proc, 10): - self.logger.debug(f"Process PID={self.proc.pid} terminated gracefully.") + self.logger.debug( + "Download process PID=%s stopped gracefully.", + self.proc.pid, + extra={ + "download": { + "download_id": self.download_id, + "process_id": self.proc.pid, + "is_live": self.is_live, + } + }, + ) return True self.logger.warning( - f"Process PID={self.proc.pid} did not respond to live cancellation, forcing termination." + "Download process PID=%s did not respond to live cancellation; forcing termination.", + self.proc.pid, + extra={ + "download": { + "download_id": self.download_id, + "process_id": self.proc.pid, + "is_live": self.is_live, + "force": True, + } + }, ) elif self.proc.pid and "posix" == os.name: signal_name = "SIGUSR1" try: - self.logger.debug(f"Sending {signal_name} signal to PID={self.proc.pid}.") + self.logger.debug( + "Sending %s signal to download process PID=%s.", + signal_name, + self.proc.pid, + extra={ + "download": { + "download_id": self.download_id, + "process_id": self.proc.pid, + "signal": signal_name, + } + }, + ) os.kill(self.proc.pid, signal.SIGUSR1) if wait_for_process_with_timeout(self.proc, 5): - self.logger.debug(f"Process PID={self.proc.pid} terminated gracefully.") + self.logger.debug( + "Download process PID=%s stopped gracefully.", + self.proc.pid, + extra={ + "download": { + "download_id": self.download_id, + "process_id": self.proc.pid, + "signal": signal_name, + } + }, + ) return True self.logger.warning( - f"Process PID={self.proc.pid} did not respond to {signal_name} (regular download), " - f"forcing termination." + "Download process PID=%s did not respond to %s; forcing termination.", + self.proc.pid, + signal_name, + extra={ + "download": { + "download_id": self.download_id, + "process_id": self.proc.pid, + "signal": signal_name, + "force": True, + } + }, ) except (OSError, AttributeError) as e: - self.logger.debug(f"Failed to send {signal_name} signal: {e}") + self.logger.debug( + "Failed to send %s signal to download process PID=%s. %s", + signal_name, + self.proc.pid, + e, + extra={ + "download": { + "download_id": self.download_id, + "process_id": self.proc.pid, + "signal": signal_name, + "exception_type": type(e).__name__, + } + }, + ) if self.proc.is_alive(): - self.logger.info(f"Force-terminating process PID={self.proc.pid}.") + self.logger.info( + "Terminating download process PID=%s.", + self.proc.pid, + extra={"download": {"download_id": self.download_id, "process_id": self.proc.pid, "force": True}}, + ) self.proc.terminate() if not wait_for_process_with_timeout(self.proc, 1 if self.is_live else 2): - self.logger.warning(f"Process PID={self.proc.pid} did not respond, killing forcefully.") + self.logger.warning( + "Download process PID=%s did not terminate; killing forcefully.", + self.proc.pid, + extra={ + "download": {"download_id": self.download_id, "process_id": self.proc.pid, "force": True} + }, + ) self.proc.kill() wait_for_process_with_timeout(self.proc, 1) - self.logger.info(f"Process PID={self.proc.pid} killed.") + self.logger.info( + "Download process PID=%s stopped.", + self.proc.pid, + extra={"download": {"download_id": self.download_id, "process_id": self.proc.pid}}, + ) return True except Exception as e: - self.logger.error(f"Failed to kill process PID={self.proc.pid}, ident={procId}. {e}") - self.logger.exception(e) + self.logger.exception( + f"Failed to stop download process PID={self.proc.pid}, ident={procId}.", + extra={ + "download": { + "download_id": self.download_id, + "process_id": self.proc.pid, + "process_ident": procId, + "is_live": self.is_live, + "exception_type": type(e).__name__, + } + }, + ) return False @@ -173,7 +280,11 @@ class ProcessManager: self.logger.warning("Attempted to close download process, but it is not running.") return False - self.logger.info(f"Closing PID='{procId}' download process.") + self.logger.info( + "Closing download process PID='%s'.", + procId, + extra={"download": {"download_id": self.download_id, "process_ident": procId, "is_live": self.is_live}}, + ) try: self.kill() @@ -183,19 +294,41 @@ class ProcessManager: loop = asyncio.get_running_loop() if self.proc.is_alive(): - self.logger.debug(f"Waiting for PID='{procId}' to close.") + self.logger.debug( + "Waiting for download process PID='%s' to close.", + procId, + extra={"download": {"download_id": self.download_id, "process_ident": procId}}, + ) await loop.run_in_executor(None, self.proc.join) - self.logger.debug(f"PID='{procId}' closed.") + self.logger.debug( + "Download process PID='%s' closed.", + procId, + extra={"download": {"download_id": self.download_id, "process_ident": procId}}, + ) if self.proc: self.proc.close() self.proc = None - self.logger.debug(f"Closed PID='{procId}' download process.") + self.logger.debug( + "Closed download process PID='%s'.", + procId, + extra={"download": {"download_id": self.download_id, "process_ident": procId}}, + ) return True except Exception as e: - self.logger.error(f"Failed to close process: '{procId}'. {e}") - self.logger.exception(e) + self.logger.exception( + f"Failed to close download process PID='{procId}'.", + extra={ + "download": { + "download_id": self.download_id, + "process_id": self.proc.pid if self.proc else None, + "process_ident": procId, + "is_live": self.is_live, + "exception_type": type(e).__name__, + } + }, + ) return False diff --git a/app/library/downloads/queue_manager.py b/app/library/downloads/queue_manager.py index 185b0248..90fa84ed 100644 --- a/app/library/downloads/queue_manager.py +++ b/app/library/downloads/queue_manager.py @@ -113,7 +113,9 @@ class DownloadQueue(metaclass=Singleton): except KeyError as e: status[item_id] = f"not found: {e!s}" status["status"] = "error" - LOG.warning(f"Start requested for non-existent item {item_id=}.") + LOG.warning( + "Start requested for missing queued download '%s'.", item_id, extra={"download_id": item_id} + ) continue if item.info.auto_start: @@ -156,7 +158,9 @@ class DownloadQueue(metaclass=Singleton): except KeyError as e: status[item_id] = f"not found: {e!s}" status["status"] = "error" - LOG.warning(f"Start requested for non-existent item {item_id=}.") + LOG.warning( + "Pause requested for missing queued download '%s'.", item_id, extra={"download_id": item_id} + ) continue if item.started() or item.is_cancelled(): @@ -191,7 +195,8 @@ class DownloadQueue(metaclass=Singleton): if not self.pool.is_paused(): self.pool.pause() if not shutdown: - LOG.warning(f"Download paused at. {datetime.now(tz=UTC).isoformat()}") + paused_at = datetime.now(tz=UTC).isoformat() + LOG.warning("Download queue paused at %s.", paused_at, extra={"paused_at": paused_at}) return True return False @@ -206,7 +211,8 @@ class DownloadQueue(metaclass=Singleton): """ if self.pool.is_paused(): self.pool.resume() - LOG.warning(f"Downloading resumed at. {datetime.now(tz=UTC).isoformat()}") + resumed_at = datetime.now(tz=UTC).isoformat() + LOG.warning("Download queue resumed at %s.", resumed_at, extra={"resumed_at": resumed_at}) return True return False @@ -258,20 +264,51 @@ class DownloadQueue(metaclass=Singleton): except KeyError as e: status[id] = str(e) status["status"] = "error" - LOG.warning(f"Requested cancel for non-existent download {id=}. {e!s}") + LOG.warning("Cancel requested for missing queued download '%s'.", id, extra={"download_id": id}) continue - item_ref = f"{id=} {item.info.id=} {item.info.title=}" - if item.running(): - LOG.debug(f"Canceling {item_ref}") + LOG.debug( + "Cancelling running download '%s'.", + item.info.title, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "url": item.info.url, + } + }, + ) item.cancel() - LOG.info(f"Cancelled {item_ref}") + LOG.info( + "Cancelled running download '%s'.", + item.info.title, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "url": item.info.url, + } + }, + ) if not item.is_live: await item.close() else: await item.close() - LOG.debug(f"Deleting from queue {item_ref}") + LOG.debug( + "Removing cancelled download '%s' from queue.", + item.info.title, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "url": item.info.url, + } + }, + ) await self.queue.delete(id) self._notify.emit( Events.ITEM_CANCELLED, @@ -287,7 +324,19 @@ class DownloadQueue(metaclass=Singleton): title="Download Cancelled", message=f"Download '{item.info.title}' has been cancelled.", ) - LOG.info(f"Deleted from queue {item_ref}") + LOG.info( + "Moved cancelled download '%s' from queue to history.", + item.info.title, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "url": item.info.url, + "status": item.info.status, + } + }, + ) status[id] = "ok" @@ -314,17 +363,28 @@ class DownloadQueue(metaclass=Singleton): except KeyError as e: status[id] = str(e) status["status"] = "error" - LOG.warning(f"Requested delete for non-existent download {id=}. {e!s}") + LOG.warning("Delete requested for missing history download '%s'.", id, extra={"download_id": id}) continue - itemRef: str = f"{id=} {item.info.id=} {item.info.title=}" removed_files = 0 filename: str = "" if self.config.remove_files is not True: remove_file = False - LOG.debug(f"{remove_file=} {itemRef} - Removing local files: {item.info.status=}") + LOG.debug( + "Clearing history download '%s'.", + item.info.title, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "status": item.info.status, + "remove_file": remove_file, + } + }, + ) if remove_file and "finished" == item.info.status and item.info.filename: filename = str(item.info.filename) @@ -344,16 +404,66 @@ class DownloadQueue(metaclass=Singleton): for f in rf.parent.glob(f"{glob.escape(rf.stem)}.*"): if f.is_file() and f.exists() and not f.name.startswith("."): removed_files += 1 - LOG.debug(f"Removing '{itemRef}' local file '{f.name}'.") + LOG.debug( + "Removing local file '%s' for '%s'.", + f.name, + item.info.title, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "filename": f.name, + } + }, + ) f.unlink(missing_ok=True) else: - LOG.debug(f"Removing '{itemRef}' local file '{rf.name}'.") + LOG.debug( + "Removing local file '%s' for '%s'.", + rf.name, + item.info.title, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "filename": rf.name, + } + }, + ) rf.unlink(missing_ok=True) removed_files += 1 else: - LOG.warning(f"Failed to remove '{itemRef}' local file '{filename}'. File not found.") + LOG.warning( + "Could not remove local file '%s' for '%s' because it was not found.", + filename, + item.info.title, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "filename": filename, + } + }, + ) except Exception as e: - LOG.error(f"Unable to remove '{itemRef}' local file '{filename}'. {e!s}") + LOG.exception( + "Failed to remove local file '%s' for '%s'.", + filename, + item.info.title, + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "filename": filename, + "remove_file": remove_file, + "exception_type": type(e).__name__, + } + }, + ) await self.done.delete(id) deleted_ids.append(id) @@ -366,11 +476,19 @@ class DownloadQueue(metaclass=Singleton): message=f"{_status} '{item.info.title}' from history.", ) - msg = f"Deleted completed download '{itemRef}'." - if removed_files > 0: - msg += f" and removed '{removed_files}' local files." - - LOG.info(msg=msg) + LOG.info( + "Deleted completed download '%s' from history%s.", + item.info.title, + f" and removed {removed_files} local file(s)" if removed_files > 0 else "", + extra={ + "download": { + "download_id": id, + "item_id": item.info.id, + "title": item.info.title, + "removed_files": removed_files, + } + }, + ) status[id] = "ok" if deleted_ids: @@ -394,10 +512,21 @@ class DownloadQueue(metaclass=Singleton): deleted_titles: list[str] = [] for item_id, item in items: - item_ref: str = f"{item_id=} {item.info.id=} {item.info.title=}" filename: str = "" - LOG.debug(f"{remove_file=} {item_ref} - Removing local files: {item.info.status=}") + LOG.debug( + "Clearing history download '%s'.", + item.info.title, + extra={ + "download": { + "download_id": item_id, + "item_id": item.info.id, + "title": item.info.title, + "status": item.info.status, + "remove_file": remove_file, + } + }, + ) if remove_file and "finished" == item.info.status and item.info.filename: filename = str(item.info.filename) @@ -417,16 +546,66 @@ class DownloadQueue(metaclass=Singleton): for file_ref in rf.parent.glob(f"{glob.escape(rf.stem)}.*"): if file_ref.is_file() and file_ref.exists() and not file_ref.name.startswith("."): removed_files += 1 - LOG.debug(f"Removing '{item_ref}' local file '{file_ref.name}'.") + LOG.debug( + "Removing local file '%s' for '%s'.", + file_ref.name, + item.info.title, + extra={ + "download": { + "download_id": item_id, + "item_id": item.info.id, + "title": item.info.title, + "filename": file_ref.name, + } + }, + ) file_ref.unlink(missing_ok=True) else: - LOG.debug(f"Removing '{item_ref}' local file '{rf.name}'.") + LOG.debug( + "Removing local file '%s' for '%s'.", + rf.name, + item.info.title, + extra={ + "download": { + "download_id": item_id, + "item_id": item.info.id, + "title": item.info.title, + "filename": rf.name, + } + }, + ) rf.unlink(missing_ok=True) removed_files += 1 else: - LOG.warning(f"Failed to remove '{item_ref}' local file '{filename}'. File not found.") + LOG.warning( + "Could not remove local file '%s' for '%s' because it was not found.", + filename, + item.info.title, + extra={ + "download": { + "download_id": item_id, + "item_id": item.info.id, + "title": item.info.title, + "filename": filename, + } + }, + ) except Exception as e: - LOG.error(f"Unable to remove '{item_ref}' local file '{filename}'. {e!s}") + LOG.exception( + "Failed to remove local file '%s' for '%s'.", + filename, + item.info.title, + extra={ + "download": { + "download_id": item_id, + "item_id": item.info.id, + "title": item.info.title, + "filename": filename, + "remove_file": remove_file, + "exception_type": type(e).__name__, + } + }, + ) deleted_ids.append(item_id) deleted_titles.append(item.info.title or item.info.id or item_id) @@ -450,7 +629,12 @@ class DownloadQueue(metaclass=Singleton): summary = ", ".join(deleted_titles[:5]) if deleted_count > 5: summary += ", ..." - LOG.info(f"Cleared '{deleted_count}' items. {summary}") + LOG.info( + "Cleared %s history item(s). %s", + deleted_count, + summary, + extra={"deleted_count": deleted_count, "removed_files": removed_files, "titles": deleted_titles[:5]}, + ) return {"deleted": deleted_count} @@ -469,7 +653,12 @@ class DownloadQueue(metaclass=Singleton): title="History Cleared", message=f"Cleared {deleted_count} item{'s' if deleted_count != 1 else ''} from history.", ) - LOG.info(f"Cleared '{deleted_count}' items. Filter '{status_filter}'.") + LOG.info( + "Cleared %s history item(s) with status '%s'.", + deleted_count, + status_filter, + extra={"deleted_count": deleted_count, "status_filter": status_filter}, + ) return {"deleted": deleted_count} items = await self.done.get_many_by_status(status_filter) diff --git a/app/library/downloads/status_tracker.py b/app/library/downloads/status_tracker.py index d7a10748..3514f470 100644 --- a/app/library/downloads/status_tracker.py +++ b/app/library/downloads/status_tracker.py @@ -68,12 +68,36 @@ class StatusTracker: self.info.datetime = str(formatdate(time.time())) self.info.filename = safe_relative_path(filepath, Path(self.download_dir)) self.final_update = True - self.logger.debug(f"Final file name: '{filepath}'.") + self.logger.debug( + "Final download file for '%s' is '%s'.", + self.info.title, + filepath, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "file_path": str(filepath), + } + }, + ) try: filepath.relative_to(self.download_dir) except ValueError: self.logger.warning( - f"Final file '{filepath}' is outside of the intended download directory '{self.download_dir}'." + "Final file '%s' for '%s' is outside download directory '%s'.", + filepath, + self.info.title, + self.download_dir, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "file_path": str(filepath), + "download_dir": self.download_dir, + } + }, ) self.info.filename = None return @@ -97,8 +121,19 @@ class StatusTracker: except Exception as e: self.info.extras["is_video"] = True self.info.extras["is_audio"] = True - self.logger.exception(e) - self.logger.error(f"Failed to run ffprobe. {e}") + self.logger.exception( + "Failed to inspect completed file '%s' with ffprobe.", + filepath, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "file_path": str(filepath), + "exception_type": type(e).__name__, + } + }, + ) async def process_status_update(self, status: StatusDict) -> None: """ @@ -115,11 +150,33 @@ class StatusTracker: return if status.get("id") != self.id or len(status) < 2: - self.logger.warning(f"Received invalid status update. {status}") + self.logger.warning( + "Received invalid status update for '%s'.", + self.info.title, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "status": status, + } + }, + ) return if self.debug: - self.logger.debug(f"Status Update: _id={self.info._id} status={status}") + self.logger.debug( + "Received status update for '%s'.", + self.info.title, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "status": status, + } + }, + ) if isinstance(status, str): self._notify.emit(Events.ITEM_UPDATED, data=self.info) @@ -139,7 +196,19 @@ class StatusTracker: if self.info.status == "error" and "error" in status: self.info.error = status.get("error") if self._candidate_filepath and self._candidate_filepath.exists(): - self.logger.debug(f"Cleaning up partial file: {self._candidate_filepath}") + self.logger.debug( + "Cleaning up partial file '%s' for '%s'.", + self._candidate_filepath, + self.info.title, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "file_path": str(self._candidate_filepath), + } + }, + ) await self._finalize_file(self._candidate_filepath) self._notify.emit( @@ -203,7 +272,19 @@ class StatusTracker: for i in range(drain_count): if self.final_update: - self.logger.info(f"({max_iterations}/{i}) Draining stopped. Final update received.") + self.logger.info( + "Stopped draining status queue for '%s' after final update.", + self.info.title, + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "max_iterations": max_iterations, + "iteration": i, + } + }, + ) break try: @@ -220,7 +301,17 @@ class StatusTracker: if self.update_task and not self.update_task.done(): self.update_task.cancel() except Exception as e: - self.logger.error(f"Failed to cancel update task. {e}") + self.logger.exception( + f"Failed to cancel progress update task for '{self.info.title}'. {e!s}", + extra={ + "download": { + "download_id": self.id, + "item_id": self.info.id, + "title": self.info.title, + "exception_type": type(e).__name__, + } + }, + ) def put_terminator(self) -> None: """Put a terminator sentinel in the status queue.""" diff --git a/app/library/downloads/temp_manager.py b/app/library/downloads/temp_manager.py index 52335137..e38c4729 100644 --- a/app/library/downloads/temp_manager.py +++ b/app/library/downloads/temp_manager.py @@ -80,7 +80,20 @@ class TempManager: and self.info.downloaded_bytes and self.info.downloaded_bytes > 0 ): - self.logger.warning(f"Keeping temp folder '{self.temp_path}'. status={self.info.status}") + self.logger.warning( + "Keeping temp folder '%s' for unfinished download '%s'.", + self.temp_path, + self.info.title, + extra={ + "download": { + "download_id": self.info._id, + "item_id": self.info.id, + "title": self.info.title, + "temp_path": str(self.temp_path), + "status": self.info.status, + } + }, + ) return tmp_dir = Path(self.temp_path) @@ -89,12 +102,51 @@ class TempManager: return if not self.temp_dir or not is_safe_to_delete_dir(tmp_dir, self.temp_dir): - self.logger.warning(f"Refusing to delete video temp folder '{self.temp_path}' as it's temp root.") + self.logger.warning( + "Refusing to delete temp folder '%s' for '%s' because it is not safe.", + self.temp_path, + self.info.title, + extra={ + "download": { + "download_id": self.info._id, + "item_id": self.info.id, + "title": self.info.title, + "temp_path": str(self.temp_path), + "temp_dir": self.temp_dir, + } + }, + ) return status: bool = delete_dir(tmp_dir) if by_pass: tmp_dir.mkdir(parents=True, exist_ok=True) - self.logger.info(f"Temp folder '{self.temp_path}' emptied.") + self.logger.info( + "Emptied temp folder '%s' for '%s'.", + self.temp_path, + self.info.title, + extra={ + "download": { + "download_id": self.info._id, + "item_id": self.info.id, + "title": self.info.title, + "temp_path": str(self.temp_path), + } + }, + ) else: - self.logger.info(f"Temp folder '{self.temp_path}' deletion is {'success' if status else 'failed'}.") + self.logger.info( + "Temp folder '%s' deletion for '%s' %s.", + self.temp_path, + self.info.title, + "succeeded" if status else "failed", + extra={ + "download": { + "download_id": self.info._id, + "item_id": self.info.id, + "title": self.info.title, + "temp_path": str(self.temp_path), + "deleted": status, + } + }, + ) diff --git a/app/library/downloads/utils.py b/app/library/downloads/utils.py index 898c0946..b2b9cf7c 100644 --- a/app/library/downloads/utils.py +++ b/app/library/downloads/utils.py @@ -128,7 +128,12 @@ def parse_extractor_limit( limit: int = min(int(env_limit), max_workers) else: if env_limit and logger: - logger.warning(f"Invalid extractor limit '{env_limit}' for '{extractor}', using default limit.") + logger.warning( + "Invalid extractor limit '%s' for '%s'; using default limit.", + env_limit, + extractor, + extra={"extractor": extractor, "env_limit": env_limit, "default_limit": default_limit}, + ) limit = default_limit return min(limit, max_workers) @@ -156,7 +161,12 @@ def get_extractor_limit( if extractor not in LIMITS: limit = parse_extractor_limit(extractor, max_workers_per_extractor, max_workers, logger) LIMITS[extractor] = asyncio.Semaphore(limit) - logger.info(f"Created limits container for extractor '{extractor}': {limit}") + logger.info( + "Created download limit for extractor '%s' with %s worker(s).", + extractor, + limit, + extra={"extractor": extractor, "limit": limit, "max_workers": max_workers}, + ) return LIMITS[extractor] @@ -247,7 +257,10 @@ def handle_task_exception(task: asyncio.Task, logger: logging.Logger) -> None: return task_name: str = task.get_name() if task.get_name() else "unknown_task" - import traceback - - tb = "".join(traceback.format_exception(type(exc), exc, exc.__traceback__)) - logger.error(f"Unhandled exception in background task '{task_name}': {exc!s}. {tb}") + logger.error( + "Unhandled exception in background task '%s'. %s", + task_name, + exc, + extra={"task_name": task_name, "exception_type": type(exc).__name__}, + exc_info=(type(exc), exc, exc.__traceback__), + ) diff --git a/app/library/downloads/video_processor.py b/app/library/downloads/video_processor.py index c7d41ac4..4d2ed9a3 100644 --- a/app/library/downloads/video_processor.py +++ b/app/library/downloads/video_processor.py @@ -58,7 +58,19 @@ async def add_video(queue: "DownloadQueue", entry: dict, item: "Item", logs: lis else: error = entry.get("msg") - LOG.debug(f"Entry id '{entry.get('id')}' url '{entry.get('webpage_url')} - {entry.get('url')}'.") + entry_url = entry.get("webpage_url") or entry.get("url") + LOG.debug( + f"Processing extracted entry '{entry.get('title')}' from '{entry_url}'.", + extra={ + "download": { + "item_id": entry.get("id"), + "title": entry.get("title"), + "url": entry_url, + "preset": item.preset, + "has_cookies": bool(item.cookies), + } + }, + ) try: _item: Download = await queue.done.get(key=entry.get("id"), url=entry.get("webpage_url") or entry.get("url")) @@ -84,7 +96,17 @@ async def add_video(queue: "DownloadQueue", entry: dict, item: "Item", logs: lis try: download_dir: str = calc_download_path(base_path=queue.config.download_path, folder=item.folder) except Exception as e: - LOG.exception(e) + LOG.exception( + f"Failed to resolve download path for '{item.url}' in folder '{item.folder}'.", + extra={ + "download": { + "url": item.url, + "folder": item.folder, + "preset": item.preset, + "exception_type": type(e).__name__, + } + }, + ) return {"status": "error", "msg": str(e)} for field in ("uploader", "channel", "thumbnail"): @@ -191,7 +213,21 @@ async def add_video(queue: "DownloadQueue", entry: dict, item: "Item", logs: lis dlInfo.info.error += f" Download will start at {starts_in.astimezone().isoformat()}." _requeue = False except Exception as e: - LOG.error(f"Failed to parse live_in date '{release_in}'. {e!s}") + LOG.error( + "Failed to parse live start date '%s' for '%s'.", + release_in, + dlInfo.info.title, + extra={ + "download": { + "download_id": dlInfo.id, + "item_id": dlInfo.info.id, + "title": dlInfo.info.title, + "url": dlInfo.info.url, + "live_in": release_in, + "exception_type": type(e).__name__, + } + }, + ) dlInfo.info.error += f" Failed to parse live_in date '{release_in}'." else: dlInfo.info.error += f" Delaying download by '{300 + dl.extras.get('duration', 0)}' seconds." @@ -218,7 +254,20 @@ async def add_video(queue: "DownloadQueue", entry: dict, item: "Item", logs: lis if item.auto_start: queue.pool.trigger_download() else: - LOG.debug(f"Item {itemDownload.info.name()} is not set to auto-start.") + LOG.debug( + "Download '%s' was queued without auto-start.", + itemDownload.info.title, + extra={ + "download": { + "download_id": itemDownload.id, + "item_id": itemDownload.info.id, + "title": itemDownload.info.title, + "url": itemDownload.info.url, + "preset": itemDownload.info.preset, + "auto_start": itemDownload.info.auto_start, + } + }, + ) queue._notify.emit( nEvent, @@ -231,6 +280,18 @@ async def add_video(queue: "DownloadQueue", entry: dict, item: "Item", logs: lis return {"status": "ok"} except Exception as e: - LOG.exception(e) - LOG.error(f"Failed to download item. '{e!s}'") + LOG.exception( + f"Failed to queue extracted item '{dl.title}' from '{dl.url}'.", + extra={ + "download": { + "item_id": dl.id, + "title": dl.title, + "url": dl.url, + "path": dl.download_dir, + "preset": dl.preset, + "has_cookies": bool(dl.cookies), + "exception_type": type(e).__name__, + } + }, + ) return {"status": "error", "msg": str(e)} diff --git a/app/library/sqlite_store.py b/app/library/sqlite_store.py index 4ba2c1be..8e54a783 100644 --- a/app/library/sqlite_store.py +++ b/app/library/sqlite_store.py @@ -500,7 +500,11 @@ class SqliteStore(metaclass=ThreadSafe): async with self._lock: await self._apply(op) except Exception as ex: - LOG.exception(ex) + LOG.exception( + "Failed to apply queued SQLite write operation '%s'.", + op.op, + extra={"operation": op.op, "type_value": op.type_value, "exception_type": type(ex).__name__}, + ) finally: self._queue.task_done() await asyncio.sleep(self._flush_interval) @@ -623,11 +627,16 @@ class SqliteStore(metaclass=ThreadSafe): self._conn = await self._engine.connect() if version := await migrate.get_version(self._conn): - LOG.debug(f"DB Version: '{version}'.") + LOG.debug("DB version: '%s'.", version, extra={"db_version": version}) await migrate.upgrade(self._conn, ROOT_PATH / "migrations") if not version: - LOG.debug(f"DB Version after initial migration: '{await migrate.get_version(self._conn)}'.") + migrated_version = await migrate.get_version(self._conn) + LOG.debug( + "DB version after initial migration: '%s'.", + migrated_version, + extra={"db_version": migrated_version}, + ) await self._conn.execute(text("PRAGMA journal_mode=wal")) await self._conn.execute(text("PRAGMA busy_timeout=5000")) diff --git a/app/main.py b/app/main.py index f2a6dca0..3a36be01 100644 --- a/app/main.py +++ b/app/main.py @@ -73,22 +73,30 @@ class Main: for folder in folders: folder = Path(folder) try: - LOG.debug(f"Checking folder at '{folder}'.") + LOG.debug("Checking folder '%s'.", folder, extra={"folder": str(folder)}) if not folder.exists(): - LOG.info(f"Creating folder at '{folder}'.") + LOG.info("Creating folder '%s'.", folder, extra={"folder": str(folder)}) folder.mkdir(parents=True, exist_ok=True) - except OSError: - LOG.error(f"Could not create folder at '{folder}'.") + except OSError as e: + LOG.exception( + "Failed to create folder '%s'.", + folder, + extra={"folder": str(folder), "exception_type": type(e).__name__}, + ) raise try: db_file = Path(self._config.db_file) - LOG.debug(f"Checking database file at '{db_file}'.") + LOG.debug("Checking database file '%s'.", db_file, extra={"db_file": str(db_file)}) if not db_file.exists(): - LOG.info(f"Creating database file at '{db_file}'.") + LOG.info("Creating database file '%s'.", db_file, extra={"db_file": str(db_file)}) db_file.touch(exist_ok=True) except OSError as e: - LOG.error(f"Could not create database file at '{self._config.db_file}'. {e!s}") + LOG.exception( + "Failed to create database file at '%s'.", + self._config.db_file, + extra={"db_file": str(self._config.db_file), "exception_type": type(e).__name__}, + ) raise async def on_shutdown(self, _: web.Application): @@ -143,8 +151,21 @@ class Main: def started(_): LOG.info("=" * 40) - LOG.info(f"YTPTube {self._config.app_version} - started on http://{host}:{port}{self._config.base_path}") - LOG.info(f"Download path: {self._config.download_path}") + LOG.info( + "YTPTube %s started on %s.", + self._config.app_version, + f"http://{host}:{port}{self._config.base_path}", + extra={ + "app_version": self._config.app_version, + "listen_url": f"http://{host}:{port}{self._config.base_path}", + "host": host, + "port": port, + "base_path": self._config.base_path, + }, + ) + LOG.info( + "Download path: %s", self._config.download_path, extra={"download_path": self._config.download_path} + ) if self._config.is_native: LOG.info("Running in native mode.") LOG.info("=" * 40) diff --git a/app/routes/api/_static.py b/app/routes/api/_static.py index 698e5071..aaecab72 100644 --- a/app/routes/api/_static.py +++ b/app/routes/api/_static.py @@ -59,7 +59,8 @@ def get_root(root_path: Path, config: Config) -> Path | None: if path.is_dir(): return path - message: str = f"Could not find the frontend assets in '{[str(path) for path in search_paths]=}'." + paths = [str(path) for path in search_paths] + message: str = f"Could not find frontend assets in any configured search path: {paths}." if config.ignore_ui: LOG.warning(message) return None @@ -191,4 +192,6 @@ def setup_static_routes(root_path: Path, config: Config) -> None: add_route(method="GET", path="/", handler=redirect_index, name="index_redirect") - LOG.info(f"Serving frontend static assets from '{STATIC_STATE.root}'.") + LOG.info( + "Serving frontend static assets from '%s'.", STATIC_STATE.root, extra={"static_root": str(STATIC_STATE.root)} + ) diff --git a/app/routes/api/browser.py b/app/routes/api/browser.py index 34153d3b..6c21cef6 100644 --- a/app/routes/api/browser.py +++ b/app/routes/api/browser.py @@ -114,7 +114,11 @@ async def get_file_info(request: Request, config: Config, encoder: Encoder, app: return web.json_response(data=response, status=web.HTTPOk.status_code, dumps=encoder.encode) except Exception as e: - LOG.exception(e) + LOG.exception( + "Failed to load file info for '%s'.", + file, + extra={"route": "file_info", "file_path": file}, + ) return web.json_response(data={"error": str(e)}, status=web.HTTPInternalServerError.status_code) @@ -196,7 +200,11 @@ async def file_browser(request: Request, config: Config, encoder: Encoder) -> Re dumps=encoder.encode, ) except OSError as e: - LOG.exception(e) + LOG.exception( + "Failed to browse file path '%s'.", + req_path, + extra={"route": "file_browser", "request_path": req_path}, + ) return web.json_response(data={"error": str(e)}, status=web.HTTPInternalServerError.status_code) @@ -228,8 +236,8 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n return web.json_response( data={"error": "Invalid parameters expecting list of dicts."}, status=web.HTTPBadRequest.status_code ) - except Exception as e: - LOG.exception(e) + except Exception: + LOG.exception("Failed to parse file browser actions request.", extra={"route": "browser.file.actions"}) return web.json_response(data={"error": "Invalid JSON."}, status=web.HTTPBadRequest.status_code) # validate each action before performing any operations @@ -329,7 +337,12 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n record(req_path, ok=False, error="Path outside download root.", action=action) continue except Exception as e: - LOG.exception(e) + LOG.exception( + "Failed to resolve file browser action '%s' for path '%s'.", + action, + req_path, + extra={"route": "browser.file.actions", "action": action, "request_path": req_path}, + ) record(req_path, ok=False, error=str(e), action=action, extra={"item": params}) continue @@ -368,9 +381,25 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n try: new_path.mkdir(parents=True, exist_ok=True) record(path, ok=True, action=action, extra={"new_dir": new_path.relative_to(config.download_path)}) - LOG.info(f"Created directory '{new_path.relative_to(config.download_path)}'") + LOG.info( + "Created directory '%s'.", + new_path.relative_to(config.download_path), + extra={ + "route": "browser.file.actions", + "directory": str(new_path.relative_to(config.download_path)), + }, + ) except OSError as e: - LOG.exception(e) + LOG.exception( + "Failed to create directory '%s'.", + new_dir, + extra={ + "route": "browser.file.actions", + "action": action, + "request_path": req_path, + "new_dir": new_dir, + }, + ) record(path, ok=False, error=str(e), action=action, extra={"item": params}) continue @@ -389,24 +418,35 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n try: sidecar_count: int = 0 - sidecar_info: str = "" sidecar_renamed: list[tuple[Path, Path]] = [] if path.is_dir(): renamed: Path = path.rename(new_path) else: renamed, sidecar_renamed = rename_file(path, new_name) sidecar_count: int = len(sidecar_renamed) - sidecar_info: str = ( - f" (with {sidecar_count} sidecar file{'s' if sidecar_count != 1 else ''})" - if sidecar_count > 0 - else "" - ) LOG.info( - f"Renamed '{path.relative_to(config.download_path)}' to '{renamed.relative_to(config.download_path)}'{sidecar_info}" + "Renamed '%s' to '%s'.", + path.relative_to(config.download_path), + renamed.relative_to(config.download_path), + extra={ + "route": "browser.file.actions", + "old_path": str(path.relative_to(config.download_path)), + "new_path": str(renamed.relative_to(config.download_path)), + "sidecar_count": sidecar_count, + }, ) except OSError as e: - LOG.exception(e) + LOG.exception( + "Failed to rename file browser path '%s'.", + path.relative_to(config.download_path), + extra={ + "route": "browser.file.actions", + "action": action, + "file_path": str(path.relative_to(config.download_path)), + "new_name": new_name, + }, + ) record(path, ok=False, error=str(e), action=action, extra={"item": params}) continue except ValueError as e: @@ -440,9 +480,21 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n else: path.unlink(missing_ok=True) - LOG.info(f"Deleted '{path.relative_to(config.download_path)}'") + LOG.info( + "Deleted '%s'.", + path.relative_to(config.download_path), + extra={"route": "browser.file.actions", "file_path": str(path.relative_to(config.download_path))}, + ) except OSError as e: - LOG.exception(e) + LOG.exception( + "Failed to delete file browser path '%s'.", + path.relative_to(config.download_path), + extra={ + "route": "browser.file.actions", + "action": action, + "file_path": str(path.relative_to(config.download_path)), + }, + ) record(path, ok=False, error=str(e), action=action, extra={"item": params}) continue else: @@ -493,7 +545,6 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n try: sidecar_count: int = 0 sidecar_moved: list[tuple[Path, Path]] = [] - sidecar_info: str = "" if path.is_dir(): dest: Path = target_dir.joinpath(path.name) @@ -501,17 +552,29 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n else: moved, sidecar_moved = move_file(path, target_dir) sidecar_count: int = len(sidecar_moved) - sidecar_info: str = ( - f" (with {sidecar_count} sidecar file{'s' if sidecar_count != 1 else ''})" - if sidecar_count > 0 - else "" - ) LOG.info( - f"Moved '{path.relative_to(config.download_path)}' to '{moved.relative_to(config.download_path)}'{sidecar_info}" + "Moved '%s' to '%s'.", + path.relative_to(config.download_path), + moved.relative_to(config.download_path), + extra={ + "route": "browser.file.actions", + "old_path": str(path.relative_to(config.download_path)), + "new_path": str(moved.relative_to(config.download_path)), + "sidecar_count": sidecar_count, + }, ) except OSError as e: - LOG.exception(e) + LOG.exception( + "Failed to move file browser path '%s'.", + path.relative_to(config.download_path), + extra={ + "route": "browser.file.actions", + "action": action, + "file_path": str(path.relative_to(config.download_path)), + "new_path": raw_new, + }, + ) record(path, ok=False, error=str(e), action=action, extra={"item": params}) continue except ValueError as e: @@ -609,16 +672,38 @@ async def stream_zip_download(request: Request, config: Config, cache: Cache) -> await response.prepare(request) try: - LOG.info(f"Streaming zip download for token: '{token}', files: {len(files)}") + LOG.info( + "Streaming zip download for token '%s' with %d file(s).", + token, + len(files), + extra={"route": "browser.download.stream", "token": token, "file_count": len(files)}, + ) for chunk in zs: if request.transport is None or request.transport.is_closing(): - LOG.info("Client disconnected, aborting zip download.") + LOG.info( + "Client disconnected, aborting zip download for token '%s'.", + token, + extra={"route": "browser.download.stream", "token": token}, + ) break await response.write(chunk) await response.write_eof() except asyncio.CancelledError: - LOG.info("Download cancelled by client.") + LOG.info( + "Download cancelled by client for token '%s'.", + token, + extra={"route": "browser.download.stream", "token": token}, + ) except Exception as e: - LOG.error(f"Streaming zip download error. {type(e).__name__}: {e}") + LOG.exception( + "Streaming zip download failed for token '%s'.", + token, + extra={ + "route": "browser.download.stream", + "token": token, + "file_count": len(files), + "exception_type": type(e).__name__, + }, + ) return response diff --git a/app/routes/api/docs.py b/app/routes/api/docs.py index 96e9ae69..c6a218f4 100644 --- a/app/routes/api/docs.py +++ b/app/routes/api/docs.py @@ -57,7 +57,7 @@ async def get_doc(request: Request, config: Config, cache: Cache) -> Response: cache_key = f"doc:{file}" if dct := cache.get(cache_key): - LOG.debug(f"Serving doc '{file}' from cache.") + LOG.debug("Serving doc '%s' from cache.", file, extra={"doc_file": file, "cache_key": cache_key}) return web.Response(**dct) url = f"https://raw.githubusercontent.com/arabcoders/ytptube/refs/heads/dev/{file}" @@ -72,7 +72,7 @@ async def get_doc(request: Request, config: Config, cache: Cache) -> Response: proxy = ytdlp_args.get("proxy") client = get_async_client(proxy=proxy, use_curl=use_curl) - LOG.debug(f"Fetching doc from '{url}'.") + LOG.debug("Fetching doc '%s' from '%s'.", file, url, extra={"route": "docs.get", "doc_file": file, "url": url}) response = await client.request( method="GET", url=url, @@ -96,8 +96,13 @@ async def get_doc(request: Request, config: Config, cache: Cache) -> Response: cache.set(cache_key, dct, ttl=3600) return web.Response(**dct) - except Exception as e: - LOG.error(f"Failed to request doc from '{url}'.'. '{e!s}'.") + except Exception: + LOG.exception( + "Failed to request doc '%s' from '%s'.", + file, + url, + extra={"route": "docs.get", "doc_file": file, "url": url}, + ) return web.json_response(data={"error": "Failed to get doc."}, status=web.HTTPInternalServerError.status_code) diff --git a/app/routes/api/download.py b/app/routes/api/download.py index ae6aeb74..b9eb094f 100644 --- a/app/routes/api/download.py +++ b/app/routes/api/download.py @@ -43,8 +43,12 @@ async def download_file(request: Request, config: Config, app: web.Application) if web.HTTPNotFound.status_code == status: return web.json_response(data={"error": "File not found"}, status=status) - except Exception as e: - LOG.exception("Error retrieving file '%s': %s", filename, str(e)) + except Exception: + LOG.exception( + "Failed to retrieve download file '%s'.", + filename, + extra={"route": "download_static", "file_path": filename}, + ) return web.json_response( data={"error": "Internal server error."}, status=web.HTTPInternalServerError.status_code, diff --git a/app/routes/api/history.py b/app/routes/api/history.py index d8fad7d1..864e9b74 100644 --- a/app/routes/api/history.py +++ b/app/routes/api/history.py @@ -338,10 +338,19 @@ async def item_thumbnail(request: Request, queue: DownloadQueue, config: Config) filepath, Path(config.temp_path) / "thumbnails", item_id=item.info._id ) except OSError as e: - LOG.warning(f"Failed to generate thumbnail for '{filepath}'. {e!s}") + LOG.warning( + "Failed to generate thumbnail for file '%s'.", + filepath, + extra={"route": "history.item.thumbnail", "item_id": id, "file_path": str(filepath), "error": str(e)}, + exc_info=True, + ) generated = None - except Exception as e: - LOG.exception(e) + except Exception: + LOG.exception( + "Failed to generate thumbnail for file '%s'.", + filepath, + extra={"route": "history.item.thumbnail", "item_id": id, "file_path": str(filepath)}, + ) generated = None if generated and generated.exists() and generated.is_file(): @@ -385,7 +394,11 @@ async def item_rename( except ValueError as e: return web.json_response(data={"error": str(e)}, status=web.HTTPConflict.status_code) except OSError as e: - LOG.exception(e) + LOG.exception( + "Failed to rename history item file '%s'.", + filepath, + extra={"route": "history.item.rename", "item_id": id, "file_path": str(filepath), "new_name": new_name}, + ) return web.json_response(data={"error": str(e)}, status=web.HTTPInternalServerError.status_code) item_dir: Path = ( @@ -404,8 +417,18 @@ async def item_rename( notify.emit(Events.ITEM_UPDATED, data=item.info) sidecar_count: int = len(sidecar_renamed) - sidecar_msg: str = f" and {sidecar_count} sidecar file/s" if sidecar_count > 0 else "" - LOG.info(f"Renamed file '{filepath}' to '{renamed}'{sidecar_msg}") + LOG.info( + "Renamed file '%s' to '%s'.", + filepath, + renamed, + extra={ + "route": "history.item.rename", + "item_id": id, + "old_path": str(filepath), + "new_path": str(renamed), + "sidecar_count": sidecar_count, + }, + ) return web.json_response( data=item.info, @@ -452,7 +475,13 @@ async def item_update(request: Request, queue: DownloadQueue, encoder: Encoder, updated = True setattr(item.info, k, v) - LOG.debug(f"Updated '{k}' to '{v}' for '{item.info.id}'") + LOG.debug( + "Updated '%s' to '%s' for '%s'.", + k, + v, + item.info.id, + extra={"route": "history.item_update", "item_id": item.info.id, "field": k, "value": v}, + ) if updated: await queue.done.put(item) @@ -861,7 +890,11 @@ async def item_nfo_generate(request: Request, queue: DownloadQueue) -> Response: status=web.HTTPOk.status_code if result["success"] else web.HTTPBadRequest.status_code, ) except Exception as e: - LOG.exception(f"Failed to generate NFO for item '{id}': {e}") + LOG.exception( + "Failed to generate NFO for item '%s'.", + id, + extra={"route": "history.item.nfo.generate", "item_id": id, "file_path": str(filepath), "mode": mode}, + ) return web.json_response( data={"error": f"failed to generate NFO: {e!s}"}, status=web.HTTPInternalServerError.status_code, diff --git a/app/routes/api/images.py b/app/routes/api/images.py index ebb55af8..522eafce 100644 --- a/app/routes/api/images.py +++ b/app/routes/api/images.py @@ -125,7 +125,11 @@ async def get_background(request: Request, config: Config, cache: Cache) -> Resp status=web.HTTPInternalServerError.status_code, ) - LOG.debug(f"Requesting random picture from '{safe_backend}'.") + LOG.debug( + "Requesting random picture from '%s'.", + safe_backend, + extra={"route": "images.background.random", "url": safe_backend}, + ) response = await client.request( method="GET", @@ -153,7 +157,11 @@ async def get_background(request: Request, config: Config, cache: Cache) -> Resp await cache.aset(key=CACHE_KEY, value=data, ttl=3600) - LOG.debug(f"Random background image from '{safe_backend}' cached.") + LOG.debug( + "Random background image from '%s' cached.", + safe_backend, + extra={"route": "images.background.random", "url": safe_backend}, + ) return web.Response( body=data.get("content"), @@ -164,8 +172,12 @@ async def get_background(request: Request, config: Config, cache: Cache) -> Resp **response_headers, }, ) - except Exception as e: - LOG.error(f"Failed to request random background image from '{safe_backend}'. '{e!s}'.") + except Exception as exc: + LOG.exception( + "Failed to request random background image from '%s'.", + safe_backend, + extra={"route": "images.background.random", "url": safe_backend, "exception_type": type(exc).__name__}, + ) return web.json_response( data={"error": "failed to retrieve the random background image."}, status=web.HTTPInternalServerError.status_code, diff --git a/app/routes/api/logs.py b/app/routes/api/logs.py index 07c7aec4..f4ac708a 100644 --- a/app/routes/api/logs.py +++ b/app/routes/api/logs.py @@ -130,8 +130,8 @@ async def _tail_log(file: Path, emitter: callable, sleep_time: float = 0.5): if log := _parse_jsonl_line(line): await emitter(log) - except Exception as e: - LOG.error(f"Error while tailing log file '{file!s}': {e!s}") + except Exception: + LOG.exception("Failed to tail log file '%s'.", file, extra={"route": "logs.stream", "file_path": str(file)}) return diff --git a/app/routes/api/system.py b/app/routes/api/system.py index fbee3c88..1b9eb42c 100644 --- a/app/routes/api/system.py +++ b/app/routes/api/system.py @@ -244,7 +244,7 @@ async def system_diagnostics( try: data = await collect_diagnostics(config) except Exception: - LOG.exception("Diagnostics collection failed.") + LOG.exception("Failed to collect system diagnostics.") data = diagnostics_error_report(config) else: cache.set(cache_key, data, ttl=60) diff --git a/app/routes/socket/history.py b/app/routes/socket/history.py index 0508de8d..d5b6f0b7 100644 --- a/app/routes/socket/history.py +++ b/app/routes/socket/history.py @@ -26,7 +26,11 @@ async def add_url(queue: DownloadQueue, notify: EventBus, sid: str, data: dict): to=sid, ) except ValueError as e: - LOG.exception(e) + LOG.exception( + "Failed to add URL '%s' from socket request.", + url, + extra={"route": "socket.add_url", "url": url, "preset": item.preset, "sid": sid}, + ) notify.emit(Events.LOG_ERROR, data={"preset": item.preset}, title="Error Adding URL", message=str(e), to=sid) diff --git a/app/tests/test_download_utils.py b/app/tests/test_download_utils.py index 75cb530b..67a6d5da 100644 --- a/app/tests/test_download_utils.py +++ b/app/tests/test_download_utils.py @@ -330,7 +330,7 @@ class TestTaskExceptionHandling: handle_task_exception(task, logger) logger.error.assert_called_once() - error_msg = logger.error.call_args[0][0] + error_msg = logger.error.call_args[0][0] % logger.error.call_args[0][1:] assert "test_task" in error_msg, "Should include task name" assert "Test error" in error_msg, "Should include exception message" @@ -349,5 +349,5 @@ class TestTaskExceptionHandling: handle_task_exception(task, logger) logger.error.assert_called_once() - error_msg = logger.error.call_args[0][0] + error_msg = logger.error.call_args[0][0] % logger.error.call_args[0][1:] assert "unknown_task" in error_msg or "Task" in error_msg, "Should handle unknown task name" diff --git a/app/tests/test_images_routes.py b/app/tests/test_images_routes.py index c8d4ea1d..2d9bb9e4 100644 --- a/app/tests/test_images_routes.py +++ b/app/tests/test_images_routes.py @@ -65,7 +65,8 @@ async def test_bg_log_redact(caplog: pytest.LogCaptureFixture, monkeypatch: pyte response = await images.get_background(req, config, DummyCache()) assert response.status == web.HTTPInternalServerError.status_code - logs = caplog.text - assert "apitoken=secret" not in logs - assert "user:pass@" not in logs - assert "https://redacted:redacted@example.com/bg.jpg?redacted#redacted" in logs + record = next(record for record in caplog.records if record.name == images.LOG.name) + assert "apitoken=secret" not in record.getMessage() + assert "user:pass@" not in record.getMessage() + assert record.url == "https://redacted:redacted@example.com/bg.jpg?redacted#redacted" + assert record.exception_type == "RuntimeError" diff --git a/app/tests/test_utils.py b/app/tests/test_utils.py index 96493605..7f7579e1 100644 --- a/app/tests/test_utils.py +++ b/app/tests/test_utils.py @@ -287,7 +287,14 @@ class TestJsonLogFormatter: formatter = JsonLogFormatter() record = logging.LogRecord("test.logger", logging.WARNING, __file__, 123, "hello %s", ("world",), None) record.download_id = "abc" - record.payload = {"ignored": True} + record.payload = { + "enabled": True, + "items": [{"name": "one", "path": Path("downloads/file.mp4")}], + "_token": "secret", + } + record.tags = ["video", {"quality": "720p", "_private": "hidden"}] + record._private = "hidden" + record.relativeCreated = 123 data = json.loads(formatter.format(record)) @@ -296,7 +303,11 @@ class TestJsonLogFormatter: assert data["levelno"] == logging.WARNING assert data["logger"] == "test.logger" assert data["message"] == "hello world" - assert data["fields"] == {"download_id": "abc"} + assert data["fields"] == { + "download_id": "abc", + "payload": {"enabled": True, "items": [{"name": "one", "path": "downloads/file.mp4"}]}, + "tags": ["video", {"quality": "720p"}], + } assert data["source"]["line"] == 123 def test_exception(self): diff --git a/app/upgrader.py b/app/upgrader.py index 0cf62778..dfefdef6 100644 --- a/app/upgrader.py +++ b/app/upgrader.py @@ -24,14 +24,14 @@ class Upgrader: os.environ.update({"YTP_CONFIG_PATH": str(config_path)}) if not config_path.exists(): - LOG.error(f"config path '{config_path}' doesn't exists.") + LOG.error("Config path '%s' does not exist.", config_path, extra={"config_path": str(config_path)}) return envFile: Path = config_path / ".env" if envFile.exists(): from dotenv import load_dotenv - LOG.debug(f"loading environment variables from '{envFile}'.") + LOG.debug("Loading environment variables from '%s'.", envFile, extra={"env_file": str(envFile)}) load_dotenv(str(envFile)) user_site: Path = config_path / f"python{sys.version_info.major}.{sys.version_info.minor}-packages" @@ -55,20 +55,33 @@ class Upgrader: self.check(config_path, user_site) def clean_up(self, user_site: Path, user_site_ver: Path, app_version: str) -> None: - LOG.info(f"Cleaning up user site packages at '{user_site}' for app version '{app_version}'.") + LOG.info( + "Cleaning up user site packages at '%s' for app version '%s'.", + user_site, + app_version, + extra={"user_site": str(user_site), "app_version": app_version}, + ) from app.library.Utils import delete_dir if not delete_dir(user_site): - LOG.error(f"Failed to clean up user site packages at '{user_site}'.") + LOG.error("Failed to clean up user site packages at '%s'.", user_site, extra={"user_site": str(user_site)}) return try: user_site.mkdir(parents=True, exist_ok=True) user_site_ver.write_text(app_version) - LOG.info(f"User site packages cleaned up and ready for app version '{app_version}'.") + LOG.info( + "User site packages at '%s' are ready for app version '%s'.", + user_site, + app_version, + extra={"user_site": str(user_site), "app_version": app_version}, + ) except Exception as e: - LOG.exception(e) - LOG.error(f"Failed to recreate user site packages at '{user_site}'. '{e!s}'.") + LOG.exception( + "Failed to recreate user site packages at '%s'.", + user_site, + extra={"user_site": str(user_site), "app_version": app_version, "exception_type": type(e).__name__}, + ) def check(self, config_path: Path, user_site: Path) -> None: pkg_installer = PackageInstaller(pkg_path=user_site) @@ -81,17 +94,26 @@ class Upgrader: LOG.info("Checking for newer versions of 'yt-dlp' package.") pkg_name = "yt_dlp" if ytdlp_version: - LOG.info(f"Using specified version '{ytdlp_version}' for '{pkg_name}'.") + LOG.info( + "Using requested version '%s' for package '%s'.", + ytdlp_version, + pkg_name, + extra={"package": pkg_name, "requested_version": ytdlp_version}, + ) pkg_name += f"=={ytdlp_version}" pkg_installer.action(pkg=pkg_name, upgrade=True) from yt_dlp.version import __version__ as YTDLP_VERSION - LOG.info(f"yt-dlp version is '{YTDLP_VERSION}' ") + LOG.info( + "yt-dlp version is '%s'.", YTDLP_VERSION, extra={"package": "yt_dlp", "version": YTDLP_VERSION} + ) except Exception as e: - LOG.exception(e) - LOG.error(f"Failed to check/upgrade for yt-dlp package. '{e!s}'.") + LOG.exception( + "Failed to check or upgrade yt-dlp package.", + extra={"package": "yt_dlp", "requested_version": ytdlp_version, "exception_type": type(e).__name__}, + ) try: pkg_installer.check( @@ -102,8 +124,14 @@ class Upgrader: ) ) except Exception as e: - LOG.exception(e) - LOG.error(f"Failed to check for packages. '{e!s}'.") + LOG.exception( + "Failed to check configured pip packages.", + extra={ + "config_path": str(config_path), + "user_site": str(user_site), + "exception_type": type(e).__name__, + }, + ) if __name__ == "__main__":