diff --git a/app/features/streaming/library/segments.py b/app/features/streaming/library/segments.py index 73c445d1..bee0d047 100644 --- a/app/features/streaming/library/segments.py +++ b/app/features/streaming/library/segments.py @@ -171,10 +171,9 @@ class Segments: stderr_task: asyncio.Task[None] = asyncio.create_task(_drain_stderr()) LOG.debug( - "Streaming '%s' segment '%s'. ffmpeg: %s", - file, + "Streaming segment %s for '%s'.", self.index, - " ".join(args), + file, extra={"file": str(file), "segment_index": self.index, "ffmpeg_args": args}, ) @@ -197,7 +196,10 @@ class Segments: try: await asyncio.wait_for(proc.wait(), timeout=5) except TimeoutError: - LOG.warning("ffmpeg process did not terminate in time. Killing it.") + LOG.warning( + "Segment stream for '%s' did not stop ffmpeg in time after the client disconnected; killing it.", + file, + ) proc.kill() raise except ConnectionResetError: @@ -210,7 +212,10 @@ class Segments: try: rc: int = await asyncio.wait_for(proc.wait(), timeout=5) except TimeoutError: - LOG.warning("ffmpeg process did not terminate in time after disconnect. Killing it.") + LOG.warning( + "Segment stream for '%s' did not stop ffmpeg in time after the client disconnected; killing it.", + file, + ) proc.kill() try: rc = await asyncio.wait_for(proc.wait(), timeout=5) @@ -221,7 +226,7 @@ class Segments: try: rc = await asyncio.wait_for(proc.wait(), timeout=30) except TimeoutError: - LOG.warning("ffmpeg process wait timed out. Killing it.") + LOG.warning("Segment stream for '%s' did not stop ffmpeg in time; killing the process.", file) proc.kill() try: rc = await asyncio.wait_for(proc.wait(), timeout=5) @@ -266,8 +271,10 @@ class Segments: if 0 != rc: err: str = stderr_text[:500] if stderr_text else "no error output" LOG.warning( - "Hardware encoder failed (rc=%s): %s. Trying fallbacks.", - rc, + "Retrying segment %s for '%s' because hardware encoder '%s' failed: %s.", + self.index, + file, + s_codec, err, extra={"ffmpeg_args": ffmpeg_args, "returncode": rc, "stderr": err, "codec": s_codec}, ) diff --git a/app/features/streaming/library/thumbnail.py b/app/features/streaming/library/thumbnail.py index dd432c06..31b40a31 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("Thumbnail generation concurrency limit: %s", limit, extra={"limit": limit}) + LOG.info("Configured thumbnail generation to run %s job(s) at a time.", limit, extra={"limit": limit}) return _SEM diff --git a/app/features/streaming/router.py b/app/features/streaming/router.py index 3fc34637..7f33de5a 100644 --- a/app/features/streaming/router.py +++ b/app/features/streaming/router.py @@ -129,8 +129,10 @@ async def m3u8_create(request: Request, config: Config, app: web.Application) -> text = await cls.make_stream(file=realFile) except StreamingError as e: LOG.exception( - "Failed to create streaming playlist for '%s'.", + "Failed to create %s streaming playlist for '%s': %s.", + mode, file, + e, 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) diff --git a/app/features/streaming/tests/test_segments.py b/app/features/streaming/tests/test_segments.py index 33ec0e03..2c1d9eca 100644 --- a/app/features/streaming/tests/test_segments.py +++ b/app/features/streaming/tests/test_segments.py @@ -262,7 +262,7 @@ async def test_stream_gpu_fallback( assert len(resp.data) > 0 # Ensure we logged the reason for GPU failure (message text may vary) assert any( - ("Hardware encoder failed" in r.message) or ("transcoding has failed" in r.message) for r in caplog.records + ("hardware encoder" in r.message.lower()) or ("transcoding has failed" in r.message) for r in caplog.records ) assert any("nvenc failure" in r.message for r in caplog.records) # Verify second invocation switched codec to a safe fallback (software) diff --git a/app/features/tasks/definitions/handlers/generic.py b/app/features/tasks/definitions/handlers/generic.py index 51c276b7..40e924fe 100644 --- a/app/features/tasks/definitions/handlers/generic.py +++ b/app/features/tasks/definitions/handlers/generic.py @@ -561,7 +561,7 @@ class GenericTaskHandler(BaseHandler): container_selector = container.get("selector") or container.get("expression") or "" if not container_selector: LOG.error( - "Container missing selector/expression. Definition '%s'.", + "Task definition '%s' is missing an item container selector.", definition.name, extra={"definition": definition.name}, ) @@ -771,7 +771,7 @@ class GenericTaskHandler(BaseHandler): return values if "jsonpath" == rule.type: - LOG.error("Extraction type 'jsonpath' is only valid for JSON responses.") + LOG.error("Field '%s' uses 'jsonpath' on a non-JSON response.", field, extra={"field": field}) return values selection: SelectorList[Selector] = ( diff --git a/app/features/tasks/definitions/service.py b/app/features/tasks/definitions/service.py index a5ae4ef9..dcc5a17c 100644 --- a/app/features/tasks/definitions/service.py +++ b/app/features/tasks/definitions/service.py @@ -158,7 +158,9 @@ class TaskHandle: if result is None: LOG.error( - "Task handler returned no result.", + "Handler '%s' returned no result for task '%s'.", + handler.__name__, + task.name, extra={"task_id": task.id, "task_name": task.name, "handler_name": handler.__name__}, ) @@ -166,7 +168,7 @@ class TaskHandle: if len(tasks) > 0: LOG.info( - "Task handler summary: handled %s, unhandled %s, disabled %s, failed %s.", + "Task dispatch finished: %s handled, %s unhandled, %s disabled, %s failed.", len(s["h"]), len(s["u"]), len(s["d"]), @@ -296,14 +298,20 @@ class TaskHandle: msg = f"{msg} {extraction.error}" LOG.error( - "Task handler failed to extract items.", + "Handler '%s' failed to extract items for task '%s' because %s.", + handler.__name__, + task.name, + msg, extra={"task_id": task.id, "task_name": task.name, "handler_name": handler.__name__, "error": msg}, ) return extraction if not isinstance(extraction, TaskResult): LOG.error( - "Task handler returned unexpected result type.", + "Handler '%s' returned unexpected result type '%s' for task '%s'.", + handler.__name__, + type(extraction).__name__, + task.name, extra={ "task_id": task.id, "task_name": task.name, @@ -338,7 +346,10 @@ class TaskHandle: for item in raw_items: if not isinstance(item, TaskItem): LOG.warning( - "Task handler returned unexpected item type.", + "Handler '%s' returned unexpected item type '%s' for task '%s'.", + handler.__name__, + type(item).__name__, + task.name, extra={ "task_id": task.id, "task_name": task.name, @@ -355,7 +366,10 @@ class TaskHandle: archive_id: str | None = item.archive_id if not archive_id: LOG.warning( - "Task handler item is missing an archive ID.", + "Handler '%s' skipped '%s' for task '%s' because it has no archive ID.", + handler.__name__, + url, + task.name, extra={"task_id": task.id, "task_name": task.name, "handler_name": handler.__name__, "url": url}, ) continue @@ -386,7 +400,10 @@ class TaskHandle: if not filtered: if raw_items: LOG.debug( - "Task handler produced items, but none were queued after filtering.", + "Handler '%s' found %s item(s) for task '%s', but none were queued.", + handler.__name__, + len(raw_items), + task.name, extra={ "task_id": task.id, "task_name": task.name, @@ -397,7 +414,10 @@ class TaskHandle: return TaskResult(items=[], metadata=metadata) LOG.info( - "Task handler found new items.", + "Handler '%s' found %s new item(s) for task '%s'.", + handler.__name__, + len(filtered), + task.name, extra={ "task_id": task.id, "task_name": task.name, @@ -548,7 +568,10 @@ class TaskHandle: if not isinstance(extraction, TaskResult): LOG.error( - "Task handler returned unexpected result type during inspection.", + "Handler '%s' returned unexpected result type '%s' while inspecting '%s'.", + handler_cls.__name__, + type(extraction).__name__, + url, extra={"handler_name": handler_cls.__name__, "url": url, "result_type": type(extraction).__name__}, ) extraction = TaskResult() diff --git a/app/features/tasks/router.py b/app/features/tasks/router.py index aa601e23..9728ae0e 100644 --- a/app/features/tasks/router.py +++ b/app/features/tasks/router.py @@ -144,7 +144,12 @@ async def _get_info(url: str, preset: str) -> tuple[str | None, str | None]: LOG.debug("Timeout while inferring name from '%s'.", url, extra={"url": url, "preset": preset}) return (None, None) except Exception as e: - LOG.debug("Failed to infer task name from URL.", extra={"url": url, "preset": preset, "error": str(e)}) + LOG.debug( + "Failed to infer a task name from '%s' because %s.", + url, + e, + extra={"url": url, "preset": preset, "error": str(e)}, + ) return (None, None) @@ -301,7 +306,6 @@ async def tasks_add( "Failed to create task from request item %s.", idx, extra={"index": idx, "error": str(exc), "exception_type": type(exc).__name__}, - exc_info=True, ) continue @@ -650,7 +654,8 @@ async def task_metadata(request: Request, repo: TasksRepository, config: Config, save_path.mkdir(parents=True, exist_ok=True) except Exception as e: LOG.warning( - "Failed to resolve task metadata path from output template.", + "Failed to resolve the metadata output path for task '%s'.", + task.name, extra={"task_id": task.id, "task_name": task.name, "error": str(e)}, exc_info=True, ) @@ -734,7 +739,9 @@ async def task_metadata(request: Request, repo: TasksRepository, config: Config, try: url = thumbnails.get(key) LOG.info( - "Fetching task metadata thumbnail.", + "Fetching '%s' thumbnail for task '%s'.", + key, + task.name, extra={"task_id": task.id, "task_name": task.name, "thumbnail": key, "url": url}, ) if not url: @@ -742,9 +749,12 @@ async def task_metadata(request: Request, repo: TasksRepository, config: Config, try: await asyncio.to_thread(validate_url, url, config.allow_internal_urls) - except ValueError: + except ValueError as exc: LOG.warning( - "Invalid task metadata thumbnail URL.", + "Task '%s' has an invalid '%s' thumbnail URL because %s.", + task.name, + key, + exc, extra={"task_id": task.id, "task_name": task.name, "thumbnail": key, "url": url}, ) continue @@ -761,7 +771,9 @@ async def task_metadata(request: Request, repo: TasksRepository, config: Config, thumbnails[key] = str(img_file.relative_to(config.download_path)) except Exception as e: LOG.warning( - "Failed to fetch task metadata thumbnail.", + "Failed to fetch '%s' thumbnail for task '%s'.", + key, + task.name, extra={ "task_id": task.id, "task_name": task.name, @@ -774,7 +786,8 @@ async def task_metadata(request: Request, repo: TasksRepository, config: Config, continue except Exception as e: LOG.warning( - "Failed to fetch task metadata thumbnails.", + "Failed to fetch metadata thumbnails for task '%s'.", + task.name, extra={"task_id": task.id, "task_name": task.name, "error": str(e)}, exc_info=True, ) diff --git a/app/features/ytdlp/router.py b/app/features/ytdlp/router.py index 7a3707b0..61f0bfae 100644 --- a/app/features/ytdlp/router.py +++ b/app/features/ytdlp/router.py @@ -38,8 +38,9 @@ def _get_preset_archive(preset: str) -> str | None: opts: dict = YTDLPOpts.get_instance().preset(preset).get_all() except Exception as e: LOG.exception( - "Failed to build yt-dlp options for preset '%s'.", + "Failed to build yt-dlp options for preset '%s': %s.", preset, + e, extra={"preset": preset, "exception_type": type(e).__name__}, ) return None @@ -130,9 +131,10 @@ async def archiver_get(request: Request) -> Response: ) except Exception as e: LOG.exception( - "Failed to read archive file '%s' for preset '%s'.", + "Failed to read archive file '%s' for preset '%s': %s.", archive_file, preset, + e, extra={ "route": "api/archiver/", "action": "read_archive", @@ -187,10 +189,11 @@ async def archiver_add(request: Request) -> Response: ) except Exception as e: LOG.exception( - "Failed to add %s item(s) to archive file '%s' for preset '%s'.", + "Failed to add %s item(s) to archive file '%s' for preset '%s': %s.", len(items), archive_file, preset, + e, extra={ "route": "api/archiver/", "action": "add_archive_items", @@ -244,10 +247,11 @@ async def archiver_delete(request: Request) -> Response: ) except Exception as e: LOG.exception( - "Failed to delete %s item(s) from archive file '%s' for preset '%s'.", + "Failed to delete %s item(s) from archive file '%s' for preset '%s': %s.", len(items), archive_file, preset, + e, extra={ "route": "api/archiver/", "action": "delete_archive_items", @@ -448,8 +452,9 @@ 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( - "Failed to get video info for '%s'.", + "Failed to get video info for '%s': %s.", url, + e, extra={ "route": "api/yt-dlp/url/info/", "action": "get_video_info", @@ -547,8 +552,9 @@ async def make_command(request: Request, config: Config, encoder: Encoder) -> Re command, info = YTDLPCli(item=it, config=config).build() except Exception as e: LOG.exception( - "Failed to build yt-dlp command for '%s'.", + "Failed to build yt-dlp command for '%s': %s.", it.url, + e, extra={ "route": "api/yt-dlp/command/", "action": "build_command", diff --git a/app/features/ytdlp/tests/test_ytdlp_opts.py b/app/features/ytdlp/tests/test_ytdlp_opts.py index 7b728b2d..a9ed5f62 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("Final yt-dlp options", extra={"ytdlp_options": test_data}) + mock_log.debug.assert_called_once_with("Prepared final yt-dlp options.", extra={"ytdlp_options": test_data}) def test_cookie_loading_error_handling(self): """Test error handling when cookie loading fails.""" diff --git a/app/features/ytdlp/ytdlp_opts.py b/app/features/ytdlp/ytdlp_opts.py index 5f4d094e..d0d7e2b4 100644 --- a/app/features/ytdlp/ytdlp_opts.py +++ b/app/features/ytdlp/ytdlp_opts.py @@ -336,8 +336,9 @@ class YTDLPOpts: self._preset_opts["cookiefile"] = str(file) except ValueError as e: LOG.exception( - "Failed to load cookies for preset '%s'.", + "Failed to load cookies for preset '%s': %s.", preset.name, + e, extra={"preset": preset.name, "has_cookies": True, "exception_type": type(e).__name__}, ) @@ -407,7 +408,7 @@ class YTDLPOpts: data["format"] = data["format"][1:] if self._config.debug: - LOG.debug("Final yt-dlp options", extra={"ytdlp_options": data}) + LOG.debug("Prepared final yt-dlp options.", extra={"ytdlp_options": data}) return data diff --git a/app/library/BackgroundWorker.py b/app/library/BackgroundWorker.py index b5770b13..a66974f2 100644 --- a/app/library/BackgroundWorker.py +++ b/app/library/BackgroundWorker.py @@ -39,14 +39,14 @@ class BackgroundWorker(metaclass=Singleton): Services.get_instance().add("background_worker", self) app.on_shutdown.append(self.on_shutdown) - LOG.debug("Starting background worker thread.") + LOG.debug("Started 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 thread...") + LOG.debug("Stopping background worker thread.") self.queue.put((CloseThread, (), {})) self.thread.join(timeout=5) LOG.debug("Background worker thread has been shut down.") @@ -99,7 +99,7 @@ class BackgroundWorker(metaclass=Singleton): loop.call_soon_threadsafe(loop.stop) loop_thread.join(timeout=5) loop.close() - LOG.debug("Event loop has been stopped and closed.") + LOG.debug("Stopped background worker event loop.") except Exception as e: LOG.exception( "Failed to stop background worker event loop.", diff --git a/app/library/Events.py b/app/library/Events.py index b1ea9fc6..d8c35819 100644 --- a/app/library/Events.py +++ b/app/library/Events.py @@ -327,7 +327,7 @@ class EventBus(metaclass=Singleton): if self.debug or event not in Events.only_debug(): LOG.debug( - "Emitting '%s' event to %s listener(s).", + "Delivering '%s' event to %s listener(s).", ev.event, len(self._listeners[event]), extra={ diff --git a/app/library/HttpSocket.py b/app/library/HttpSocket.py index 6b419f46..eca2c6d2 100644 --- a/app/library/HttpSocket.py +++ b/app/library/HttpSocket.py @@ -145,7 +145,10 @@ class HttpSocket: for route in socket_routes.values(): if self.config.debug: LOG.debug( - f"Add ({route.name}) {route.method.value if isinstance(route.method, RouteType) else route.method}: {route.path}." + "Registered socket route '%s' for %s %s.", + route.name, + route.method.value if isinstance(route.method, RouteType) else route.method, + route.path, ) async def handle_message(sid: str, message: str) -> None: @@ -221,6 +224,6 @@ class HttpSocket: return ws if self.config.debug: - LOG.debug("Add (ws) GET: %s.", ws_path, extra={"method": "GET", "path": ws_path}) + LOG.debug("Registered WebSocket endpoint at '%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 9b796015..a643a50a 100644 --- a/app/library/PackageInstaller.py +++ b/app/library/PackageInstaller.py @@ -181,7 +181,7 @@ class PackageInstaller: if not pkgs.has_packages() or not self.user_site: return - LOG.info("Checking user pip packages: %s", ", ".join(pkgs.packages), extra={"packages": pkgs.packages}) + LOG.info("Checking configured user pip packages.", extra={"packages": pkgs.packages}) for package in pkgs.packages: try: self.action(package, upgrade=pkgs.allow_upgrade()) diff --git a/app/library/TerminalSessionManager.py b/app/library/TerminalSessionManager.py index 1a6b8c00..ac064cca 100644 --- a/app/library/TerminalSessionManager.py +++ b/app/library/TerminalSessionManager.py @@ -296,7 +296,7 @@ class TerminalSessionManager(metaclass=Singleton): master_fd: int | None = None try: - LOG.info("Cli command from client. '%s'", command) + LOG.info("Starting terminal session '%s' command.", session_id, extra={"session_id": session_id}) args = ["yt-dlp", *shlex.split(command, posix=os.name != "nt")] env_vars = self._build_env() @@ -377,7 +377,7 @@ class TerminalSessionManager(metaclass=Singleton): try: return_code = await asyncio.wait_for(proc.wait(), timeout=self._shutdown_timeout) except TimeoutError: - LOG.warning("Terminal session '%s' process did not exit cleanly.", session_id) + LOG.warning("Terminal session '%s' did not exit after repeated shutdown attempts.", session_id) if proc is not None: proc_returncode = getattr(proc, "returncode", None) diff --git a/app/library/UpdateChecker.py b/app/library/UpdateChecker.py index be857359..76b29deb 100644 --- a/app/library/UpdateChecker.py +++ b/app/library/UpdateChecker.py @@ -146,7 +146,7 @@ class UpdateChecker(metaclass=Singleton): ) -> tuple[str, str | None]: try: LOG.info( - "Checking for %s updates...", + "Checking whether %s has an update available.", name, extra={"target_name": name, "api_url": api_url, "current_version": current_version}, ) @@ -183,7 +183,7 @@ class UpdateChecker(metaclass=Singleton): if self._compare_versions(compare_current, compare_latest): LOG.warning( - "%s update available: %s -> %s", + "%s has an update available: %s -> %s.", name, current_version, latest_tag, @@ -194,7 +194,7 @@ class UpdateChecker(metaclass=Singleton): return result LOG.info( - "No %s updates available.", + "%s is already up to date.", name, extra={"target_name": name, "current_version": current_version}, ) @@ -203,7 +203,7 @@ class UpdateChecker(metaclass=Singleton): return result except Exception as e: LOG.exception( - "Failed to check for %s updates.", + "Failed to check whether %s has an update available.", name, extra={ "target_name": name, @@ -234,7 +234,7 @@ class UpdateChecker(metaclass=Singleton): async def _check_ytdlp_version(self) -> tuple[str, str | None]: current_version: str = self._config._ytdlp_version() if not current_version or "0.0.0" == current_version: - LOG.warning("Could not determine yt-dlp version, skipping yt-dlp update check.") + LOG.warning("Skipping the yt-dlp update check because the current version could not be determined.") return ("error", None) status, new_version = await self._check_github_version( @@ -270,7 +270,7 @@ class UpdateChecker(metaclass=Singleton): return parse_version(latest) > parse_version(current) except Exception as e: LOG.warning( - "Error comparing versions '%s' vs '%s': %s", + "Failed to compare versions '%s' and '%s' because %s.", current, latest, e, diff --git a/app/library/config.py b/app/library/config.py index e671be31..55499a7a 100644 --- a/app/library/config.py +++ b/app/library/config.py @@ -443,7 +443,7 @@ class Config(metaclass=Singleton): extra={"host": "0.0.0.0", "port": self.debugpy_port}, ) except ImportError: - LOG.exception("debugpy package not found; install it with 'uv sync'.") + LOG.error("debugpy package not found; install it with 'uv sync'.") except Exception as e: LOG.exception( "Failed to start debugpy server.", @@ -458,7 +458,7 @@ class Config(metaclass=Singleton): if self.auth_password and self.auth_username: LOG.info( - "Authentication enabled with username '%s'.", + "Basic authentication is enabled for user '%s'.", self.auth_username, extra={"auth_username": self.auth_username}, ) diff --git a/app/library/downloads/hooks.py b/app/library/downloads/hooks.py index dd446230..3dae6d4d 100644 --- a/app/library/downloads/hooks.py +++ b/app/library/downloads/hooks.py @@ -34,7 +34,7 @@ class HookHandlers: try: d_safe = create_debug_safe_dict(data) self.logger.debug( - "Received progress hook for download '%s'.", + "Received a yt-dlp progress update for download '%s'.", self.id, extra={"download": {"download_id": self.id, "hook": "progress", "status": d_safe}}, ) @@ -73,7 +73,7 @@ class HookHandlers: d_safe = create_debug_safe_dict(data) d_safe["postprocessor"] = data.get("postprocessor") self.logger.debug( - "Received postprocessor hook for download '%s'.", + "Received a yt-dlp post-processing update for download '%s'.", self.id, extra={"download": {"download_id": self.id, "hook": "postprocessor", "status": d_safe}}, ) diff --git a/app/library/downloads/monitors.py b/app/library/downloads/monitors.py index c13736d5..c18da55f 100644 --- a/app/library/downloads/monitors.py +++ b/app/library/downloads/monitors.py @@ -290,8 +290,9 @@ async def delete_old_history(queue: "DownloadQueue") -> None: if titles: LOG.info( - "Automatically cleared %s old history item(s).", + "Automatically cleared %s old history item(s), including '%s'.", len(titles), + titles[0], extra={"deleted_count": len(titles), "titles": titles}, ) diff --git a/app/library/downloads/pool_manager.py b/app/library/downloads/pool_manager.py index a566c570..91cf215d 100644 --- a/app/library/downloads/pool_manager.py +++ b/app/library/downloads/pool_manager.py @@ -79,7 +79,7 @@ class PoolManager: async def shutdown(self) -> None: if self._active: LOG.info( - "Cancelling %s active download(s).", + "Cancelling active downloads (%s item(s)).", len(self._active), extra={"active_count": len(self._active), "download_ids": list(self._active)}, ) @@ -91,7 +91,7 @@ class PoolManager: while True: while not self.queue.queue.has_downloads(): - LOG.info("Waiting for item to download.") + LOG.info("Waiting for queued downloads.") await self.event.wait() self.event.clear() adaptive_sleep = 0.2 @@ -165,9 +165,8 @@ class PoolManager: """ filePath: str = calc_download_path(base_path=self.config.download_path, folder=entry.info.folder) LOG.info( - "Downloading '%s' from '%s' to '%s'.", + "Started download for '%s' to '%s'.", entry.info.title, - entry.info.url, filePath, extra={ "download": { @@ -246,7 +245,11 @@ class PoolManager: message=nMessage, ) else: - LOG.warning("Completed download '%s' was not found in queue.", id, extra={"download_id": id}) + LOG.warning( + "Completed download '%s' was not found in the queue.", + entry.info.title or id, + extra={"download_id": id, "title": entry.info.title}, + ) if self.event: self.event.set() diff --git a/app/library/downloads/queue_manager.py b/app/library/downloads/queue_manager.py index 90fa84ed..a085867c 100644 --- a/app/library/downloads/queue_manager.py +++ b/app/library/downloads/queue_manager.py @@ -196,7 +196,7 @@ class DownloadQueue(metaclass=Singleton): self.pool.pause() if not shutdown: paused_at = datetime.now(tz=UTC).isoformat() - LOG.warning("Download queue paused at %s.", paused_at, extra={"paused_at": paused_at}) + LOG.warning("Paused the download queue.", extra={"paused_at": paused_at}) return True return False @@ -212,7 +212,7 @@ class DownloadQueue(metaclass=Singleton): if self.pool.is_paused(): self.pool.resume() resumed_at = datetime.now(tz=UTC).isoformat() - LOG.warning("Download queue resumed at %s.", resumed_at, extra={"resumed_at": resumed_at}) + LOG.warning("Resumed the download queue.", extra={"resumed_at": resumed_at}) return True return False @@ -630,7 +630,7 @@ class DownloadQueue(metaclass=Singleton): if deleted_count > 5: summary += ", ..." LOG.info( - "Cleared %s history item(s). %s", + "Cleared %s history item(s), including %s.", deleted_count, summary, extra={"deleted_count": deleted_count, "removed_files": removed_files, "titles": deleted_titles[:5]}, diff --git a/app/library/downloads/status_tracker.py b/app/library/downloads/status_tracker.py index 3514f470..5a29a77c 100644 --- a/app/library/downloads/status_tracker.py +++ b/app/library/downloads/status_tracker.py @@ -166,7 +166,7 @@ class StatusTracker: if self.debug: self.logger.debug( - "Received status update for '%s'.", + "Received a download status update for '%s'.", self.info.title, extra={ "download": { @@ -302,7 +302,9 @@ class StatusTracker: self.update_task.cancel() except Exception as e: self.logger.exception( - f"Failed to cancel progress update task for '{self.info.title}'. {e!s}", + "Failed to cancel the progress update task for '%s' because %s.", + self.info.title, + e, extra={ "download": { "download_id": self.id, diff --git a/app/library/downloads/temp_manager.py b/app/library/downloads/temp_manager.py index e38c4729..2e309385 100644 --- a/app/library/downloads/temp_manager.py +++ b/app/library/downloads/temp_manager.py @@ -136,10 +136,9 @@ class TempManager: ) else: self.logger.info( - "Temp folder '%s' deletion for '%s' %s.", + "Deleted temp folder '%s' for '%s'." if status else "Failed to delete temp folder '%s' for '%s'.", self.temp_path, self.info.title, - "succeeded" if status else "failed", extra={ "download": { "download_id": self.info._id, diff --git a/app/library/sqlite_store.py b/app/library/sqlite_store.py index 8e54a783..fe0766af 100644 --- a/app/library/sqlite_store.py +++ b/app/library/sqlite_store.py @@ -627,13 +627,13 @@ class SqliteStore(metaclass=ThreadSafe): self._conn = await self._engine.connect() if version := await migrate.get_version(self._conn): - LOG.debug("DB version: '%s'.", version, extra={"db_version": version}) + LOG.debug("Database schema version is '%s'.", version, extra={"db_version": version}) await migrate.upgrade(self._conn, ROOT_PATH / "migrations") if not version: migrated_version = await migrate.get_version(self._conn) LOG.debug( - "DB version after initial migration: '%s'.", + "Database schema was initialized at version '%s'.", migrated_version, extra={"db_version": migrated_version}, ) diff --git a/app/main.py b/app/main.py index 3a36be01..0fb6836a 100644 --- a/app/main.py +++ b/app/main.py @@ -164,7 +164,9 @@ class Main: }, ) LOG.info( - "Download path: %s", self._config.download_path, extra={"download_path": self._config.download_path} + "Using 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.") diff --git a/app/routes/api/browser.py b/app/routes/api/browser.py index 6c21cef6..b9923ec1 100644 --- a/app/routes/api/browser.py +++ b/app/routes/api/browser.py @@ -115,8 +115,9 @@ 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( - "Failed to load file info for '%s'.", + "Failed to load file info for '%s' because %s.", file, + e, extra={"route": "file_info", "file_path": file}, ) return web.json_response(data={"error": str(e)}, status=web.HTTPInternalServerError.status_code) @@ -201,8 +202,9 @@ async def file_browser(request: Request, config: Config, encoder: Encoder) -> Re ) except OSError as e: LOG.exception( - "Failed to browse file path '%s'.", + "Failed to browse file path '%s' because %s.", req_path, + e, extra={"route": "file_browser", "request_path": req_path}, ) return web.json_response(data={"error": str(e)}, status=web.HTTPInternalServerError.status_code) @@ -236,8 +238,11 @@ 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: - LOG.exception("Failed to parse file browser actions request.", extra={"route": "browser.file.actions"}) + except Exception as e: + LOG.debug( + "Ignoring invalid file browser actions JSON.", + extra={"route": "browser.file.actions", "error": str(e)}, + ) return web.json_response(data={"error": "Invalid JSON."}, status=web.HTTPBadRequest.status_code) # validate each action before performing any operations @@ -338,9 +343,10 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n continue except Exception as e: LOG.exception( - "Failed to resolve file browser action '%s' for path '%s'.", + "Failed to resolve file browser action '%s' for path '%s' because %s.", action, req_path, + e, extra={"route": "browser.file.actions", "action": action, "request_path": req_path}, ) record(req_path, ok=False, error=str(e), action=action, extra={"item": params}) @@ -391,8 +397,9 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n ) except OSError as e: LOG.exception( - "Failed to create directory '%s'.", + "Failed to create directory '%s' because %s.", new_dir, + e, extra={ "route": "browser.file.actions", "action": action, @@ -438,8 +445,9 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n ) except OSError as e: LOG.exception( - "Failed to rename file browser path '%s'.", + "Failed to rename file browser path '%s' because %s.", path.relative_to(config.download_path), + e, extra={ "route": "browser.file.actions", "action": action, @@ -487,8 +495,9 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n ) except OSError as e: LOG.exception( - "Failed to delete file browser path '%s'.", + "Failed to delete file browser path '%s' because %s.", path.relative_to(config.download_path), + e, extra={ "route": "browser.file.actions", "action": action, @@ -566,8 +575,9 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n ) except OSError as e: LOG.exception( - "Failed to move file browser path '%s'.", + "Failed to move file browser path '%s' because %s.", path.relative_to(config.download_path), + e, extra={ "route": "browser.file.actions", "action": action, @@ -673,16 +683,14 @@ async def stream_zip_download(request: Request, config: Config, cache: Cache) -> try: LOG.info( - "Streaming zip download for token '%s' with %d file(s).", - token, + "Started streaming a ZIP download with %d file(s).", 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 for token '%s'.", - token, + "Stopped streaming the ZIP download because the client disconnected.", extra={"route": "browser.download.stream", "token": token}, ) break @@ -690,14 +698,12 @@ async def stream_zip_download(request: Request, config: Config, cache: Cache) -> await response.write_eof() except asyncio.CancelledError: LOG.info( - "Download cancelled by client for token '%s'.", - token, + "Stopped streaming the ZIP download because the client cancelled it.", extra={"route": "browser.download.stream", "token": token}, ) except Exception as e: LOG.exception( - "Streaming zip download failed for token '%s'.", - token, + "Failed to stream the ZIP download.", extra={ "route": "browser.download.stream", "token": token, diff --git a/app/routes/api/history.py b/app/routes/api/history.py index 864e9b74..5ce775c3 100644 --- a/app/routes/api/history.py +++ b/app/routes/api/history.py @@ -476,10 +476,9 @@ async def item_update(request: Request, queue: DownloadQueue, encoder: Encoder, updated = True setattr(item.info, k, v) LOG.debug( - "Updated '%s' to '%s' for '%s'.", - k, - v, + "Updated history item '%s' field '%s'.", item.info.id, + k, extra={"route": "history.item_update", "item_id": item.info.id, "field": k, "value": v}, ) diff --git a/app/routes/api/logs.py b/app/routes/api/logs.py index f4ac708a..969f8a53 100644 --- a/app/routes/api/logs.py +++ b/app/routes/api/logs.py @@ -215,7 +215,6 @@ async def stream_logs(request: Request, config: Config, encoder: Encoder) -> Res ) try: - LOG.debug("Log streaming connected.") while not log_task.done(): await asyncio.sleep(1.0) if request.transport is None or request.transport.is_closing(): @@ -225,7 +224,6 @@ async def stream_logs(request: Request, config: Config, encoder: Encoder) -> Res except asyncio.CancelledError: pass finally: - LOG.debug("Log streaming disconnected.") try: await response.write_eof() except ConnectionResetError: