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

refactor: update log mesages to take advantage of JSONL

Browse source
This commit is contained in:
arabcoders 2026-05-27 16:47:30 +03:00
parent 434d3e981d
commit cf90db3b4c
72 changed files with 2984 additions and 508 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

28
API.md
View file

@ -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
}
}
}
```

12
app/features/conditions/migration.py
View file

@ -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)

24
app/features/conditions/router.py
View file

@ -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,

18
app/features/conditions/service.py
View file

@ -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

6
app/features/core/migration.py
View file

@ -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

12
app/features/dl_fields/migration.py
View file

@ -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)

12
app/features/notifications/migration.py
View file

@ -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)

29
app/features/notifications/service.py
View file

@ -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)}

12
app/features/presets/migration.py
View file

@ -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)

6
app/features/presets/utils.py
View file

@ -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:

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

@ -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():

51
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:
_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

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

@ -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(

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

@ -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():

68
app/features/tasks/definitions/handlers/rss.py
View file

@ -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

61
app/features/tasks/definitions/handlers/tver.py
View file

@ -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] = []

37
app/features/tasks/definitions/handlers/twitch.py
View file

@ -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<id>\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] = []

31
app/features/tasks/definitions/handlers/youtube.py
View file

@ -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] = []

18
app/features/tasks/definitions/migration.py
View file

@ -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):

28
app/features/tasks/definitions/router.py
View file

@ -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,

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

@ -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()

12
app/features/tasks/migration.py
View file

@ -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)

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

@ -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:

70
app/features/tasks/service.py
View file

@ -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},

6
app/features/tasks/utils.py
View file

@ -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

49
app/features/ytdlp/archiver.py
View file

@ -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:

24
app/features/ytdlp/extractor.py
View file

@ -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,

14
app/features/ytdlp/patches.py
View file

@ -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):

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

@ -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,

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

@ -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"

8
app/features/ytdlp/utils.py
View file

@ -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

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

@ -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

28
app/library/BackgroundWorker.py
View file

@ -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))

70
app/library/Events.py
View file

@ -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:
"""

46
app/library/HttpAPI.py
View file

@ -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,

24
app/library/HttpSocket.py
View file

@ -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")

58
app/library/PackageInstaller.py
View file

@ -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:
"""

20
app/library/Scheduler.py
View file

@ -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

12
app/library/TerminalSessionManager.py
View file

@ -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)

54
app/library/UpdateChecker.py
View file

@ -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

206
app/library/Utils.py
View file

@ -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]]:

6
app/library/cache.py
View file

@ -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)},
)

2
app/library/cf_solver_handler.py
View file

@ -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()

19
app/library/cf_solver_shared.py
View file

@ -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(

31
app/library/config.py
View file

@ -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)

245
app/library/downloads/core.py
View file

@ -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"

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

@ -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)

167
app/library/downloads/item_adder.py
View file

@ -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)

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

@ -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})

44
app/library/downloads/playlist_processor.py
View file

@ -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 {

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

@ -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()

173
app/library/downloads/process_manager.py
View file

@ -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

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

@ -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)

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

@ -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."""

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

@ -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,
}
},
)

25
app/library/downloads/utils.py
View file

@ -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__),
)

73
app/library/downloads/video_processor.py
View file

@ -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)}

15
app/library/sqlite_store.py
View file

@ -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"))

39
app/main.py
View file

@ -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)

7
app/routes/api/_static.py
View file

@ -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)}
)

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

@ -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

13
app/routes/api/docs.py
View file

@ -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)

8
app/routes/api/download.py
View file

@ -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,

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

@ -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,

20
app/routes/api/images.py
View file

@ -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,

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

@ -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

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

@ -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)

6
app/routes/socket/history.py
View file

@ -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)

4
app/tests/test_download_utils.py
View file

@ -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"

9
app/tests/test_images_routes.py
View file

@ -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"

15
app/tests/test_utils.py
View file

@ -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):

54
app/upgrader.py
View file

@ -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__":