danvics/ytptube
1
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity Actions 1

refactor: add more context to the actual log message.

Browse source
This commit is contained in:
arabcoders 2026-05-28 17:56:28 +03:00
parent cf90db3b4c
commit 39ed3d0361
28 changed files with 161 additions and 96 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

23
app/features/streaming/library/segments.py
View file

@ -171,10 +171,9 @@ class Segments:
stderr_task: asyncio.Task[None] = asyncio.create_task(_drain_stderr()) stderr_task: asyncio.Task[None] = asyncio.create_task(_drain_stderr())
LOG.debug( LOG.debug(
"Streaming '%s' segment '%s'. ffmpeg: %s", "Streaming segment %s for '%s'.",
file,
self.index, self.index,
" ".join(args), file,
extra={"file": str(file), "segment_index": self.index, "ffmpeg_args": args}, extra={"file": str(file), "segment_index": self.index, "ffmpeg_args": args},
) )
@ -197,7 +196,10 @@ class Segments:
try: try:
await asyncio.wait_for(proc.wait(), timeout=5) await asyncio.wait_for(proc.wait(), timeout=5)
except TimeoutError: 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() proc.kill()
raise raise
except ConnectionResetError: except ConnectionResetError:
@ -210,7 +212,10 @@ class Segments:
try: try:
rc: int = await asyncio.wait_for(proc.wait(), timeout=5) rc: int = await asyncio.wait_for(proc.wait(), timeout=5)
except TimeoutError: 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() proc.kill()
try: try:
rc = await asyncio.wait_for(proc.wait(), timeout=5) rc = await asyncio.wait_for(proc.wait(), timeout=5)
@ -221,7 +226,7 @@ class Segments:
try: try:
rc = await asyncio.wait_for(proc.wait(), timeout=30) rc = await asyncio.wait_for(proc.wait(), timeout=30)
except TimeoutError: 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() proc.kill()
try: try:
rc = await asyncio.wait_for(proc.wait(), timeout=5) rc = await asyncio.wait_for(proc.wait(), timeout=5)
@ -266,8 +271,10 @@ class Segments:
if 0 != rc: if 0 != rc:
err: str = stderr_text[:500] if stderr_text else "no error output" err: str = stderr_text[:500] if stderr_text else "no error output"
LOG.warning( LOG.warning(
"Hardware encoder failed (rc=%s): %s. Trying fallbacks.", "Retrying segment %s for '%s' because hardware encoder '%s' failed: %s.",
rc, self.index,
file,
s_codec,
err, err,
extra={"ffmpeg_args": ffmpeg_args, "returncode": rc, "stderr": err, "codec": s_codec}, extra={"ffmpeg_args": ffmpeg_args, "returncode": rc, "stderr": err, "codec": s_codec},
) )

2
app/features/streaming/library/thumbnail.py
View file

@ -35,7 +35,7 @@ def _get_semaphore() -> asyncio.Semaphore:
if _SEM is None or _SEM_LIMIT != limit: if _SEM is None or _SEM_LIMIT != limit:
_SEM = asyncio.Semaphore(limit) _SEM = asyncio.Semaphore(limit)
_SEM_LIMIT = 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 return _SEM

4
app/features/streaming/router.py
View file

@ -129,8 +129,10 @@ async def m3u8_create(request: Request, config: Config, app: web.Application) ->
text = await cls.make_stream(file=realFile) text = await cls.make_stream(file=realFile)
except StreamingError as e: except StreamingError as e:
LOG.exception( LOG.exception(
"Failed to create streaming playlist for '%s'.", "Failed to create %s streaming playlist for '%s': %s.",
mode,
file, file,
e,
extra={"route": "streaming.playlist", "file_path": file, "mode": mode, "exception_type": type(e).__name__}, 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.json_response(data={"error": str(e)}, status=web.HTTPNotFound.status_code)

2
app/features/streaming/tests/test_segments.py
View file

@ -262,7 +262,7 @@ async def test_stream_gpu_fallback(
assert len(resp.data) > 0 assert len(resp.data) > 0
# Ensure we logged the reason for GPU failure (message text may vary) # Ensure we logged the reason for GPU failure (message text may vary)
assert any( 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) assert any("nvenc failure" in r.message for r in caplog.records)
# Verify second invocation switched codec to a safe fallback (software) # Verify second invocation switched codec to a safe fallback (software)

4
app/features/tasks/definitions/handlers/generic.py
View file

@ -561,7 +561,7 @@ class GenericTaskHandler(BaseHandler):
container_selector = container.get("selector") or container.get("expression") or "" container_selector = container.get("selector") or container.get("expression") or ""
if not container_selector: if not container_selector:
LOG.error( LOG.error(
"Container missing selector/expression. Definition '%s'.", "Task definition '%s' is missing an item container selector.",
definition.name, definition.name,
extra={"definition": definition.name}, extra={"definition": definition.name},
) )
@ -771,7 +771,7 @@ class GenericTaskHandler(BaseHandler):
return values return values
if "jsonpath" == rule.type: 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 return values
selection: SelectorList[Selector] = ( selection: SelectorList[Selector] = (

41
app/features/tasks/definitions/service.py
View file

@ -158,7 +158,9 @@ class TaskHandle:
if result is None: if result is None:
LOG.error( 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__}, extra={"task_id": task.id, "task_name": task.name, "handler_name": handler.__name__},
) )
@ -166,7 +168,7 @@ class TaskHandle:
if len(tasks) > 0: if len(tasks) > 0:
LOG.info( 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["h"]),
len(s["u"]), len(s["u"]),
len(s["d"]), len(s["d"]),
@ -296,14 +298,20 @@ class TaskHandle:
msg = f"{msg} {extraction.error}" msg = f"{msg} {extraction.error}"
LOG.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}, extra={"task_id": task.id, "task_name": task.name, "handler_name": handler.__name__, "error": msg},
) )
return extraction return extraction
if not isinstance(extraction, TaskResult): if not isinstance(extraction, TaskResult):
LOG.error( 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={ extra={
"task_id": task.id, "task_id": task.id,
"task_name": task.name, "task_name": task.name,
@ -338,7 +346,10 @@ class TaskHandle:
for item in raw_items: for item in raw_items:
if not isinstance(item, TaskItem): if not isinstance(item, TaskItem):
LOG.warning( 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={ extra={
"task_id": task.id, "task_id": task.id,
"task_name": task.name, "task_name": task.name,
@ -355,7 +366,10 @@ class TaskHandle:
archive_id: str | None = item.archive_id archive_id: str | None = item.archive_id
if not archive_id: if not archive_id:
LOG.warning( 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}, extra={"task_id": task.id, "task_name": task.name, "handler_name": handler.__name__, "url": url},
) )
continue continue
@ -386,7 +400,10 @@ class TaskHandle:
if not filtered: if not filtered:
if raw_items: if raw_items:
LOG.debug( 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={ extra={
"task_id": task.id, "task_id": task.id,
"task_name": task.name, "task_name": task.name,
@ -397,7 +414,10 @@ class TaskHandle:
return TaskResult(items=[], metadata=metadata) return TaskResult(items=[], metadata=metadata)
LOG.info( LOG.info(
"Task handler found new items.", "Handler '%s' found %s new item(s) for task '%s'.",
handler.__name__,
len(filtered),
task.name,
extra={ extra={
"task_id": task.id, "task_id": task.id,
"task_name": task.name, "task_name": task.name,
@ -548,7 +568,10 @@ class TaskHandle:
if not isinstance(extraction, TaskResult): if not isinstance(extraction, TaskResult):
LOG.error( 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__}, extra={"handler_name": handler_cls.__name__, "url": url, "result_type": type(extraction).__name__},
) )
extraction = TaskResult() extraction = TaskResult()

29
app/features/tasks/router.py
View file

@ -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}) LOG.debug("Timeout while inferring name from '%s'.", url, extra={"url": url, "preset": preset})
return (None, None) return (None, None)
except Exception as e: 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) return (None, None)
@ -301,7 +306,6 @@ async def tasks_add(
"Failed to create task from request item %s.", "Failed to create task from request item %s.",
idx, idx,
extra={"index": idx, "error": str(exc), "exception_type": type(exc).__name__}, extra={"index": idx, "error": str(exc), "exception_type": type(exc).__name__},
exc_info=True,
) )
continue continue
@ -650,7 +654,8 @@ async def task_metadata(request: Request, repo: TasksRepository, config: Config,
save_path.mkdir(parents=True, exist_ok=True) save_path.mkdir(parents=True, exist_ok=True)
except Exception as e: except Exception as e:
LOG.warning( 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)}, extra={"task_id": task.id, "task_name": task.name, "error": str(e)},
exc_info=True, exc_info=True,
) )
@ -734,7 +739,9 @@ async def task_metadata(request: Request, repo: TasksRepository, config: Config,
try: try:
url = thumbnails.get(key) url = thumbnails.get(key)
LOG.info( 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}, extra={"task_id": task.id, "task_name": task.name, "thumbnail": key, "url": url},
) )
if not url: if not url:
@ -742,9 +749,12 @@ async def task_metadata(request: Request, repo: TasksRepository, config: Config,
try: try:
await asyncio.to_thread(validate_url, url, config.allow_internal_urls) await asyncio.to_thread(validate_url, url, config.allow_internal_urls)
except ValueError: except ValueError as exc:
LOG.warning( 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}, extra={"task_id": task.id, "task_name": task.name, "thumbnail": key, "url": url},
) )
continue 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)) thumbnails[key] = str(img_file.relative_to(config.download_path))
except Exception as e: except Exception as e:
LOG.warning( LOG.warning(
"Failed to fetch task metadata thumbnail.", "Failed to fetch '%s' thumbnail for task '%s'.",
key,
task.name,
extra={ extra={
"task_id": task.id, "task_id": task.id,
"task_name": task.name, "task_name": task.name,
@ -774,7 +786,8 @@ async def task_metadata(request: Request, repo: TasksRepository, config: Config,
continue continue
except Exception as e: except Exception as e:
LOG.warning( 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)}, extra={"task_id": task.id, "task_name": task.name, "error": str(e)},
exc_info=True, exc_info=True,
) )

18
app/features/ytdlp/router.py
View file

@ -38,8 +38,9 @@ def _get_preset_archive(preset: str) -> str | None:
opts: dict = YTDLPOpts.get_instance().preset(preset).get_all() opts: dict = YTDLPOpts.get_instance().preset(preset).get_all()
except Exception as e: except Exception as e:
LOG.exception( LOG.exception(
"Failed to build yt-dlp options for preset '%s'.", "Failed to build yt-dlp options for preset '%s': %s.",
preset, preset,
e,
extra={"preset": preset, "exception_type": type(e).__name__}, extra={"preset": preset, "exception_type": type(e).__name__},
) )
return None return None
@ -130,9 +131,10 @@ async def archiver_get(request: Request) -> Response:
) )
except Exception as e: except Exception as e:
LOG.exception( LOG.exception(
"Failed to read archive file '%s' for preset '%s'.", "Failed to read archive file '%s' for preset '%s': %s.",
archive_file, archive_file,
preset, preset,
e,
extra={ extra={
"route": "api/archiver/", "route": "api/archiver/",
"action": "read_archive", "action": "read_archive",
@ -187,10 +189,11 @@ async def archiver_add(request: Request) -> Response:
) )
except Exception as e: except Exception as e:
LOG.exception( 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), len(items),
archive_file, archive_file,
preset, preset,
e,
extra={ extra={
"route": "api/archiver/", "route": "api/archiver/",
"action": "add_archive_items", "action": "add_archive_items",
@ -244,10 +247,11 @@ async def archiver_delete(request: Request) -> Response:
) )
except Exception as e: except Exception as e:
LOG.exception( 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), len(items),
archive_file, archive_file,
preset, preset,
e,
extra={ extra={
"route": "api/archiver/", "route": "api/archiver/",
"action": "delete_archive_items", "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) return web.json_response(body=json.dumps(data, indent=4, default=str), status=web.HTTPOk.status_code)
except Exception as e: except Exception as e:
LOG.exception( LOG.exception(
"Failed to get video info for '%s'.", "Failed to get video info for '%s': %s.",
url, url,
e,
extra={ extra={
"route": "api/yt-dlp/url/info/", "route": "api/yt-dlp/url/info/",
"action": "get_video_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() command, info = YTDLPCli(item=it, config=config).build()
except Exception as e: except Exception as e:
LOG.exception( LOG.exception(
"Failed to build yt-dlp command for '%s'.", "Failed to build yt-dlp command for '%s': %s.",
it.url, it.url,
e,
extra={ extra={
"route": "api/yt-dlp/command/", "route": "api/yt-dlp/command/",
"action": "build_command", "action": "build_command",

2
app/features/ytdlp/tests/test_ytdlp_opts.py
View file

@ -442,7 +442,7 @@ class TestYTDLPOpts:
opts = YTDLPOpts() opts = YTDLPOpts()
opts.get_all(keep=True) 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): def test_cookie_loading_error_handling(self):
"""Test error handling when cookie loading fails.""" """Test error handling when cookie loading fails."""

5
app/features/ytdlp/ytdlp_opts.py
View file

@ -336,8 +336,9 @@ class YTDLPOpts:
self._preset_opts["cookiefile"] = str(file) self._preset_opts["cookiefile"] = str(file)
except ValueError as e: except ValueError as e:
LOG.exception( LOG.exception(
"Failed to load cookies for preset '%s'.", "Failed to load cookies for preset '%s': %s.",
preset.name, preset.name,
e,
extra={"preset": preset.name, "has_cookies": True, "exception_type": type(e).__name__}, extra={"preset": preset.name, "has_cookies": True, "exception_type": type(e).__name__},
) )
@ -407,7 +408,7 @@ class YTDLPOpts:
data["format"] = data["format"][1:] data["format"] = data["format"][1:]
if self._config.debug: 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 return data

6
app/library/BackgroundWorker.py
View file

@ -39,14 +39,14 @@ class BackgroundWorker(metaclass=Singleton):
Services.get_instance().add("background_worker", self) Services.get_instance().add("background_worker", self)
app.on_shutdown.append(self.on_shutdown) 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 = threading.Thread(target=self._run, daemon=True)
self.thread.start() self.thread.start()
async def on_shutdown(self, _: web.Application): async def on_shutdown(self, _: web.Application):
self.running = False self.running = False
try: try:
LOG.debug("Shutting down background worker thread...") LOG.debug("Stopping background worker thread.")
self.queue.put((CloseThread, (), {})) self.queue.put((CloseThread, (), {}))
self.thread.join(timeout=5) self.thread.join(timeout=5)
LOG.debug("Background worker thread has been shut down.") LOG.debug("Background worker thread has been shut down.")
@ -99,7 +99,7 @@ class BackgroundWorker(metaclass=Singleton):
loop.call_soon_threadsafe(loop.stop) loop.call_soon_threadsafe(loop.stop)
loop_thread.join(timeout=5) loop_thread.join(timeout=5)
loop.close() loop.close()
LOG.debug("Event loop has been stopped and closed.") LOG.debug("Stopped background worker event loop.")
except Exception as e: except Exception as e:
LOG.exception( LOG.exception(
"Failed to stop background worker event loop.", "Failed to stop background worker event loop.",

2
app/library/Events.py
View file

@ -327,7 +327,7 @@ class EventBus(metaclass=Singleton):
if self.debug or event not in Events.only_debug(): if self.debug or event not in Events.only_debug():
LOG.debug( LOG.debug(
"Emitting '%s' event to %s listener(s).", "Delivering '%s' event to %s listener(s).",
ev.event, ev.event,
len(self._listeners[event]), len(self._listeners[event]),
extra={ extra={

7
app/library/HttpSocket.py
View file

@ -145,7 +145,10 @@ class HttpSocket:
for route in socket_routes.values(): for route in socket_routes.values():
if self.config.debug: if self.config.debug:
LOG.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: async def handle_message(sid: str, message: str) -> None:
@ -221,6 +224,6 @@ class HttpSocket:
return ws return ws
if self.config.debug: 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") app.router.add_get(ws_path, ws_handler, name="ws")

2
app/library/PackageInstaller.py
View file

@ -181,7 +181,7 @@ class PackageInstaller:
if not pkgs.has_packages() or not self.user_site: if not pkgs.has_packages() or not self.user_site:
return 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: for package in pkgs.packages:
try: try:
self.action(package, upgrade=pkgs.allow_upgrade()) self.action(package, upgrade=pkgs.allow_upgrade())

4
app/library/TerminalSessionManager.py
View file

@ -296,7 +296,7 @@ class TerminalSessionManager(metaclass=Singleton):
master_fd: int | None = None master_fd: int | None = None
try: 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")] args = ["yt-dlp", *shlex.split(command, posix=os.name != "nt")]
env_vars = self._build_env() env_vars = self._build_env()
@ -377,7 +377,7 @@ class TerminalSessionManager(metaclass=Singleton):
try: try:
return_code = await asyncio.wait_for(proc.wait(), timeout=self._shutdown_timeout) return_code = await asyncio.wait_for(proc.wait(), timeout=self._shutdown_timeout)
except TimeoutError: 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: if proc is not None:
proc_returncode = getattr(proc, "returncode", None) proc_returncode = getattr(proc, "returncode", None)

12
app/library/UpdateChecker.py
View file

@ -146,7 +146,7 @@ class UpdateChecker(metaclass=Singleton):
) -> tuple[str, str | None]: ) -> tuple[str, str | None]:
try: try:
LOG.info( LOG.info(
"Checking for %s updates...", "Checking whether %s has an update available.",
name, name,
extra={"target_name": name, "api_url": api_url, "current_version": current_version}, 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): if self._compare_versions(compare_current, compare_latest):
LOG.warning( LOG.warning(
"%s update available: %s -> %s", "%s has an update available: %s -> %s.",
name, name,
current_version, current_version,
latest_tag, latest_tag,
@ -194,7 +194,7 @@ class UpdateChecker(metaclass=Singleton):
return result return result
LOG.info( LOG.info(
"No %s updates available.", "%s is already up to date.",
name, name,
extra={"target_name": name, "current_version": current_version}, extra={"target_name": name, "current_version": current_version},
) )
@ -203,7 +203,7 @@ class UpdateChecker(metaclass=Singleton):
return result return result
except Exception as e: except Exception as e:
LOG.exception( LOG.exception(
"Failed to check for %s updates.", "Failed to check whether %s has an update available.",
name, name,
extra={ extra={
"target_name": name, "target_name": name,
@ -234,7 +234,7 @@ class UpdateChecker(metaclass=Singleton):
async def _check_ytdlp_version(self) -> tuple[str, str | None]: async def _check_ytdlp_version(self) -> tuple[str, str | None]:
current_version: str = self._config._ytdlp_version() current_version: str = self._config._ytdlp_version()
if not current_version or "0.0.0" == current_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) return ("error", None)
status, new_version = await self._check_github_version( status, new_version = await self._check_github_version(
@ -270,7 +270,7 @@ class UpdateChecker(metaclass=Singleton):
return parse_version(latest) > parse_version(current) return parse_version(latest) > parse_version(current)
except Exception as e: except Exception as e:
LOG.warning( LOG.warning(
"Error comparing versions '%s' vs '%s': %s", "Failed to compare versions '%s' and '%s' because %s.",
current, current,
latest, latest,
e, e,

4
app/library/config.py
View file

@ -443,7 +443,7 @@ class Config(metaclass=Singleton):
extra={"host": "0.0.0.0", "port": self.debugpy_port}, extra={"host": "0.0.0.0", "port": self.debugpy_port},
) )
except ImportError: 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: except Exception as e:
LOG.exception( LOG.exception(
"Failed to start debugpy server.", "Failed to start debugpy server.",
@ -458,7 +458,7 @@ class Config(metaclass=Singleton):
if self.auth_password and self.auth_username: if self.auth_password and self.auth_username:
LOG.info( LOG.info(
"Authentication enabled with username '%s'.", "Basic authentication is enabled for user '%s'.",
self.auth_username, self.auth_username,
extra={"auth_username": self.auth_username}, extra={"auth_username": self.auth_username},
) )

4
app/library/downloads/hooks.py
View file

@ -34,7 +34,7 @@ class HookHandlers:
try: try:
d_safe = create_debug_safe_dict(data) d_safe = create_debug_safe_dict(data)
self.logger.debug( self.logger.debug(
"Received progress hook for download '%s'.", "Received a yt-dlp progress update for download '%s'.",
self.id, self.id,
extra={"download": {"download_id": self.id, "hook": "progress", "status": d_safe}}, 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 = create_debug_safe_dict(data)
d_safe["postprocessor"] = data.get("postprocessor") d_safe["postprocessor"] = data.get("postprocessor")
self.logger.debug( self.logger.debug(
"Received postprocessor hook for download '%s'.", "Received a yt-dlp post-processing update for download '%s'.",
self.id, self.id,
extra={"download": {"download_id": self.id, "hook": "postprocessor", "status": d_safe}}, extra={"download": {"download_id": self.id, "hook": "postprocessor", "status": d_safe}},
) )

3
app/library/downloads/monitors.py
View file

@ -290,8 +290,9 @@ async def delete_old_history(queue: "DownloadQueue") -> None:
if titles: if titles:
LOG.info( LOG.info(
"Automatically cleared %s old history item(s).", "Automatically cleared %s old history item(s), including '%s'.",
len(titles), len(titles),
titles[0],
extra={"deleted_count": len(titles), "titles": titles}, extra={"deleted_count": len(titles), "titles": titles},
) )

13
app/library/downloads/pool_manager.py
View file

@ -79,7 +79,7 @@ class PoolManager:
async def shutdown(self) -> None: async def shutdown(self) -> None:
if self._active: if self._active:
LOG.info( LOG.info(
"Cancelling %s active download(s).", "Cancelling active downloads (%s item(s)).",
len(self._active), len(self._active),
extra={"active_count": len(self._active), "download_ids": list(self._active)}, extra={"active_count": len(self._active), "download_ids": list(self._active)},
) )
@ -91,7 +91,7 @@ class PoolManager:
while True: while True:
while not self.queue.queue.has_downloads(): while not self.queue.queue.has_downloads():
LOG.info("Waiting for item to download.") LOG.info("Waiting for queued downloads.")
await self.event.wait() await self.event.wait()
self.event.clear() self.event.clear()
adaptive_sleep = 0.2 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) filePath: str = calc_download_path(base_path=self.config.download_path, folder=entry.info.folder)
LOG.info( LOG.info(
"Downloading '%s' from '%s' to '%s'.", "Started download for '%s' to '%s'.",
entry.info.title, entry.info.title,
entry.info.url,
filePath, filePath,
extra={ extra={
"download": { "download": {
@ -246,7 +245,11 @@ class PoolManager:
message=nMessage, message=nMessage,
) )
else: 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: if self.event:
self.event.set() self.event.set()

6
app/library/downloads/queue_manager.py
View file

@ -196,7 +196,7 @@ class DownloadQueue(metaclass=Singleton):
self.pool.pause() self.pool.pause()
if not shutdown: if not shutdown:
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}) LOG.warning("Paused the download queue.", extra={"paused_at": paused_at})
return True return True
return False return False
@ -212,7 +212,7 @@ class DownloadQueue(metaclass=Singleton):
if self.pool.is_paused(): if self.pool.is_paused():
self.pool.resume() self.pool.resume()
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}) LOG.warning("Resumed the download queue.", extra={"resumed_at": resumed_at})
return True return True
return False return False
@ -630,7 +630,7 @@ class DownloadQueue(metaclass=Singleton):
if deleted_count > 5: if deleted_count > 5:
summary += ", ..." summary += ", ..."
LOG.info( LOG.info(
"Cleared %s history item(s). %s", "Cleared %s history item(s), including %s.",
deleted_count, deleted_count,
summary, summary,
extra={"deleted_count": deleted_count, "removed_files": removed_files, "titles": deleted_titles[:5]}, extra={"deleted_count": deleted_count, "removed_files": removed_files, "titles": deleted_titles[:5]},

6
app/library/downloads/status_tracker.py
View file

@ -166,7 +166,7 @@ class StatusTracker:
if self.debug: if self.debug:
self.logger.debug( self.logger.debug(
"Received status update for '%s'.", "Received a download status update for '%s'.",
self.info.title, self.info.title,
extra={ extra={
"download": { "download": {
@ -302,7 +302,9 @@ class StatusTracker:
self.update_task.cancel() self.update_task.cancel()
except Exception as e: except Exception as e:
self.logger.exception( 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={ extra={
"download": { "download": {
"download_id": self.id, "download_id": self.id,

3
app/library/downloads/temp_manager.py
View file

@ -136,10 +136,9 @@ class TempManager:
) )
else: else:
self.logger.info( 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.temp_path,
self.info.title, self.info.title,
"succeeded" if status else "failed",
extra={ extra={
"download": { "download": {
"download_id": self.info._id, "download_id": self.info._id,

4
app/library/sqlite_store.py
View file

@ -627,13 +627,13 @@ class SqliteStore(metaclass=ThreadSafe):
self._conn = await self._engine.connect() self._conn = await self._engine.connect()
if version := await migrate.get_version(self._conn): 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") await migrate.upgrade(self._conn, ROOT_PATH / "migrations")
if not version: if not version:
migrated_version = await migrate.get_version(self._conn) migrated_version = await migrate.get_version(self._conn)
LOG.debug( LOG.debug(
"DB version after initial migration: '%s'.", "Database schema was initialized at version '%s'.",
migrated_version, migrated_version,
extra={"db_version": migrated_version}, extra={"db_version": migrated_version},
) )

4
app/main.py
View file

@ -164,7 +164,9 @@ class Main:
}, },
) )
LOG.info( 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: if self._config.is_native:
LOG.info("Running in native mode.") LOG.info("Running in native mode.")

40
app/routes/api/browser.py
View file

@ -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) return web.json_response(data=response, status=web.HTTPOk.status_code, dumps=encoder.encode)
except Exception as e: except Exception as e:
LOG.exception( LOG.exception(
"Failed to load file info for '%s'.", "Failed to load file info for '%s' because %s.",
file, file,
e,
extra={"route": "file_info", "file_path": file}, extra={"route": "file_info", "file_path": file},
) )
return web.json_response(data={"error": str(e)}, status=web.HTTPInternalServerError.status_code) 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: except OSError as e:
LOG.exception( LOG.exception(
"Failed to browse file path '%s'.", "Failed to browse file path '%s' because %s.",
req_path, req_path,
e,
extra={"route": "file_browser", "request_path": req_path}, extra={"route": "file_browser", "request_path": req_path},
) )
return web.json_response(data={"error": str(e)}, status=web.HTTPInternalServerError.status_code) 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( return web.json_response(
data={"error": "Invalid parameters expecting list of dicts."}, status=web.HTTPBadRequest.status_code data={"error": "Invalid parameters expecting list of dicts."}, status=web.HTTPBadRequest.status_code
) )
except Exception: except Exception as e:
LOG.exception("Failed to parse file browser actions request.", extra={"route": "browser.file.actions"}) 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) return web.json_response(data={"error": "Invalid JSON."}, status=web.HTTPBadRequest.status_code)
# validate each action before performing any operations # validate each action before performing any operations
@ -338,9 +343,10 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n
continue continue
except Exception as e: except Exception as e:
LOG.exception( 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, action,
req_path, req_path,
e,
extra={"route": "browser.file.actions", "action": action, "request_path": 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}) 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: except OSError as e:
LOG.exception( LOG.exception(
"Failed to create directory '%s'.", "Failed to create directory '%s' because %s.",
new_dir, new_dir,
e,
extra={ extra={
"route": "browser.file.actions", "route": "browser.file.actions",
"action": action, "action": action,
@ -438,8 +445,9 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n
) )
except OSError as e: except OSError as e:
LOG.exception( LOG.exception(
"Failed to rename file browser path '%s'.", "Failed to rename file browser path '%s' because %s.",
path.relative_to(config.download_path), path.relative_to(config.download_path),
e,
extra={ extra={
"route": "browser.file.actions", "route": "browser.file.actions",
"action": action, "action": action,
@ -487,8 +495,9 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n
) )
except OSError as e: except OSError as e:
LOG.exception( LOG.exception(
"Failed to delete file browser path '%s'.", "Failed to delete file browser path '%s' because %s.",
path.relative_to(config.download_path), path.relative_to(config.download_path),
e,
extra={ extra={
"route": "browser.file.actions", "route": "browser.file.actions",
"action": action, "action": action,
@ -566,8 +575,9 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n
) )
except OSError as e: except OSError as e:
LOG.exception( LOG.exception(
"Failed to move file browser path '%s'.", "Failed to move file browser path '%s' because %s.",
path.relative_to(config.download_path), path.relative_to(config.download_path),
e,
extra={ extra={
"route": "browser.file.actions", "route": "browser.file.actions",
"action": action, "action": action,
@ -673,16 +683,14 @@ async def stream_zip_download(request: Request, config: Config, cache: Cache) ->
try: try:
LOG.info( LOG.info(
"Streaming zip download for token '%s' with %d file(s).", "Started streaming a ZIP download with %d file(s).",
token,
len(files), len(files),
extra={"route": "browser.download.stream", "token": token, "file_count": len(files)}, extra={"route": "browser.download.stream", "token": token, "file_count": len(files)},
) )
for chunk in zs: for chunk in zs:
if request.transport is None or request.transport.is_closing(): if request.transport is None or request.transport.is_closing():
LOG.info( LOG.info(
"Client disconnected, aborting zip download for token '%s'.", "Stopped streaming the ZIP download because the client disconnected.",
token,
extra={"route": "browser.download.stream", "token": token}, extra={"route": "browser.download.stream", "token": token},
) )
break break
@ -690,14 +698,12 @@ async def stream_zip_download(request: Request, config: Config, cache: Cache) ->
await response.write_eof() await response.write_eof()
except asyncio.CancelledError: except asyncio.CancelledError:
LOG.info( LOG.info(
"Download cancelled by client for token '%s'.", "Stopped streaming the ZIP download because the client cancelled it.",
token,
extra={"route": "browser.download.stream", "token": token}, extra={"route": "browser.download.stream", "token": token},
) )
except Exception as e: except Exception as e:
LOG.exception( LOG.exception(
"Streaming zip download failed for token '%s'.", "Failed to stream the ZIP download.",
token,
extra={ extra={
"route": "browser.download.stream", "route": "browser.download.stream",
"token": token, "token": token,

5
app/routes/api/history.py
View file

@ -476,10 +476,9 @@ async def item_update(request: Request, queue: DownloadQueue, encoder: Encoder,
updated = True updated = True
setattr(item.info, k, v) setattr(item.info, k, v)
LOG.debug( LOG.debug(
"Updated '%s' to '%s' for '%s'.", "Updated history item '%s' field '%s'.",
k,
v,
item.info.id, item.info.id,
k,
extra={"route": "history.item_update", "item_id": item.info.id, "field": k, "value": v}, extra={"route": "history.item_update", "item_id": item.info.id, "field": k, "value": v},
) )

2
app/routes/api/logs.py
View file

@ -215,7 +215,6 @@ async def stream_logs(request: Request, config: Config, encoder: Encoder) -> Res
) )
try: try:
LOG.debug("Log streaming connected.")
while not log_task.done(): while not log_task.done():
await asyncio.sleep(1.0) await asyncio.sleep(1.0)
if request.transport is None or request.transport.is_closing(): 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: except asyncio.CancelledError:
pass pass
finally: finally:
LOG.debug("Log streaming disconnected.")
try: try:
await response.write_eof() await response.write_eof()
except ConnectionResetError: except ConnectionResetError: