Merge pull request #609 from arabcoders/dev

feat: make log level runtime configurable
This commit is contained in:
Abdulmohsen 2026-05-31 21:07:00 +03:00 committed by GitHub
commit 6df1250a43
No known key found for this signature in database
GPG key ID: B5690EEEBB952194
106 changed files with 4779 additions and 1487 deletions

59
API.md
View file

@ -88,6 +88,8 @@ This document describes the available endpoints and their usage. All endpoints r
- [DELETE /api/conditions/{id}](#delete-apiconditionsid)
- [GET /api/logs](#get-apilogs)
- [GET /api/logs/stream](#get-apilogsstream)
- [GET /api/logs/level](#get-apilogslevel)
- [POST /api/logs/level/{level}](#post-apilogslevellevel)
- [GET /api/notifications/](#get-apinotifications)
- [GET /api/notifications/events/](#get-apinotificationsevents)
- [POST /api/notifications/](#post-apinotifications)
@ -2318,8 +2320,8 @@ Binary image data with appropriate headers
"datetime": "2026-05-18T12:00:00.000+00:00",
"level": "error",
"levelno": 40,
"logger": "downloads.queue",
"message": "Download failed",
"logger": "ytptube",
"message": "Failed to download 'Example Video'.",
"exception": {
"type": "ValueError",
"message": "bad",
@ -2342,7 +2344,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,
@ -2369,8 +2381,8 @@ Binary image data with appropriate headers
"datetime": "2026-05-18T12:00:00.000+00:00",
"level": "error",
"levelno": 40,
"logger": "downloads.queue",
"message": "Download failed",
"logger": "ytptube",
"message": "Failed to download 'Example Video'.",
"exception": {
"type": "ValueError",
"message": "bad",
@ -2393,7 +2405,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
}
}
}
```
@ -2401,6 +2423,31 @@ Binary image data with appropriate headers
---
### GET /api/logs/level
**Purpose**: Read the active runtime log level.
**Response**:
```json
{
"conf": "info",
"active": "info",
"levels": ["debug", "info", "warning", "error"]
}
```
---
### POST /api/logs/level/{level}
**Purpose**: Change the active runtime log level.
**Path Parameter**:
- `level`: One of `debug`, `info`, `warning`, `error`.
**Response**:
- `204 No Content` on success.
---
### GET /api/notifications/
**Purpose**: Retrieve notification targets with pagination.

24
FAQ.md
View file

@ -119,6 +119,30 @@ As this is a simple basic authentication, if your browser doesn't show the promp
`http://username:password@your_ytptube_url:port`
# Security recommendations
YTPTube is designed for LAN and home-lab use behind a firewall or reverse proxy. The web interface and API are
unauthenticated by default because in a trusted network, auth adds friction without meaningful benefit. However,
if you expose YTPTube to the internet directly or via port forwarding **YOU MUST enable authentication**.
### Without auth, anyone who can reach the API can:
- Download arbitrary content through your IP and server.
- Delete or modify your downloaded files and database.
- Run arbitrary `yt-dlp` options, including `--exec`, which executes shell commands inside the container.
This is not a vulnerability, it's the intended design. The `cli` field passes options directly to `yt-dlp`,
a tool that by design can execute commands. Auth is the mechanism that controls who gets to use that power.
**If you expose YTPTube to untrusted networks**, do one of the following:
1. **Enable authentication** — set both `YTP_AUTH_USERNAME` and `YTP_AUTH_PASSWORD`.
2. **Put it behind a reverse proxy** with its own authentication layer (see [Run behind reverse proxy](#run-behind-reverse-proxy)).
3. **Keep it on a private network** with no public exposure.
YTPTube already gates other powerful features behind explicit opt-in: the built-in terminal, file browser actions and internal
URL requests for example. The `cli` field is no different, its power is by design, and access control is your responsibility.
# I cant download anything
If you are receiving errors like:

View file

@ -44,6 +44,9 @@ Please read the [FAQ](FAQ.md) for more information.
# Installation
> [!IMPORTANT]
> By default YTPTube runs without authentication. If you expose it to the internet, **enable auth**. See [security recommendations](FAQ.md#security-recommendations).
## Run using docker command
```bash

View file

@ -1,18 +1,18 @@
from __future__ import annotations
import json
import logging
from pathlib import Path
from typing import TYPE_CHECKING, Any, cast
from app.features.conditions.models import ConditionModel
from app.features.core.migration import Migration as FeatureMigration
from app.library.config import Config
from app.library.log import get_logger
if TYPE_CHECKING:
from app.features.conditions.repository import ConditionsRepository
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
class Migration(FeatureMigration):
@ -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)

View file

@ -1,6 +1,5 @@
from __future__ import annotations
import logging
from typing import TYPE_CHECKING, Any
from app.features.conditions.migration import Migration
@ -18,8 +17,9 @@ from sqlalchemy import delete, func, or_, select
from app.features.conditions.models import ConditionModel
from app.features.core.deps import get_session
from app.library.log import get_logger
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
class ConditionsRepository(metaclass=Singleton):

View file

@ -1,5 +1,4 @@
import asyncio
import logging
from collections import OrderedDict
from typing import Any
@ -15,10 +14,11 @@ from app.library.cache import Cache
from app.library.config import Config
from app.library.encoder import Encoder
from app.library.Events import EventBus, Events
from app.library.log import get_logger
from app.library.router import route
from app.library.Utils import validate_url
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
def _model(model: Any) -> Condition:
@ -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,

View file

@ -1,4 +1,3 @@
import logging
from collections.abc import Iterable
from numbers import Number
@ -8,9 +7,10 @@ from app.features.conditions.models import ConditionModel
from app.features.conditions.repository import ConditionsRepository
from app.features.ytdlp.mini_filter import match_str
from app.library.Events import EventBus, Events
from app.library.log import get_logger
from app.library.Singleton import Singleton
LOG: logging.Logger = logging.getLogger("feature.conditions")
LOG = get_logger()
def _ignored_identifiers(ignore_conditions: Iterable[str | Number] | None) -> tuple[set[str], bool]:
@ -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

View file

@ -1,15 +1,16 @@
from __future__ import annotations
import abc
import logging
import time
from pathlib import Path
from typing import TYPE_CHECKING
from app.library.log import get_logger
if TYPE_CHECKING:
from app.library.config import Config
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
class Migration(abc.ABC):
@ -26,7 +27,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

View file

@ -1,18 +1,18 @@
from __future__ import annotations
import json
import logging
from pathlib import Path
from typing import TYPE_CHECKING, Any, cast
from app.features.core.migration import Migration as FeatureMigration
from app.features.dl_fields.schemas import DLField
from app.library.config import Config
from app.library.log import get_logger
if TYPE_CHECKING:
from app.features.dl_fields.repository import DLFieldsRepository
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
class Migration(FeatureMigration):
@ -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)

View file

@ -1,6 +1,5 @@
from __future__ import annotations
import logging
from typing import TYPE_CHECKING, Any
from sqlalchemy import delete, func, or_, select
@ -8,6 +7,7 @@ from sqlalchemy import delete, func, or_, select
from app.features.core.deps import get_session
from app.features.dl_fields.migration import Migration
from app.features.dl_fields.models import DLFieldModel
from app.library.log import get_logger
from app.library.Singleton import Singleton
if TYPE_CHECKING:
@ -18,7 +18,7 @@ if TYPE_CHECKING:
from sqlalchemy.sql.elements import ColumnElement
from sqlalchemy.sql.selectable import Select
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
class DLFieldsRepository(metaclass=Singleton):

View file

@ -1,4 +1,3 @@
import logging
from typing import Any
from aiohttp import web
@ -11,9 +10,10 @@ from app.features.dl_fields.schemas import DLField, DLFieldList, DLFieldPatch
from app.features.dl_fields.service import DLFields
from app.library.encoder import Encoder
from app.library.Events import EventBus, Events
from app.library.log import get_logger
from app.library.router import route
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
def _model(model: Any) -> DLField:

View file

@ -1,18 +1,18 @@
from __future__ import annotations
import logging
from typing import TYPE_CHECKING, Any
from app.features.dl_fields.models import DLFieldModel
from app.features.dl_fields.repository import DLFieldsRepository
from app.features.dl_fields.schemas import DLField
from app.library.Events import EventBus, Events
from app.library.log import get_logger
from app.library.Singleton import Singleton
if TYPE_CHECKING:
from aiohttp import web
LOG: logging.Logger = logging.getLogger("feature.dl_fields")
LOG = get_logger()
class DLFields(metaclass=Singleton):

View file

@ -1,7 +1,6 @@
from __future__ import annotations
import json
import logging
from pathlib import Path
from typing import TYPE_CHECKING, Any, cast
@ -9,11 +8,12 @@ from app.features.core.migration import Migration as FeatureMigration
from app.features.notifications.schemas import NotificationEvents
from app.features.presets.service import Presets
from app.library.config import Config
from app.library.log import get_logger
if TYPE_CHECKING:
from app.features.notifications.repository import NotificationsRepository
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
class Migration(FeatureMigration):
@ -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)

View file

@ -1,6 +1,5 @@
from __future__ import annotations
import logging
from typing import TYPE_CHECKING, Any
from sqlalchemy import func, or_, select
@ -8,6 +7,7 @@ from sqlalchemy import func, or_, select
from app.features.core.deps import get_session
from app.features.notifications.migration import Migration
from app.features.notifications.models import NotificationModel
from app.library.log import get_logger
from app.library.Singleton import Singleton
if TYPE_CHECKING:
@ -18,7 +18,7 @@ if TYPE_CHECKING:
from sqlalchemy.sql.elements import ColumnElement
from sqlalchemy.sql.selectable import Select
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
class NotificationsRepository(metaclass=Singleton):

View file

@ -1,4 +1,3 @@
import logging
from typing import Any
from aiohttp import web
@ -11,9 +10,10 @@ from app.features.notifications.schemas import Notification, NotificationEvents,
from app.features.notifications.service import Notifications
from app.library.encoder import Encoder
from app.library.Events import EventBus, Events
from app.library.log import get_logger
from app.library.router import route
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
def _model(model: Any) -> Notification:

View file

@ -1,8 +1,6 @@
from __future__ import annotations
import asyncio
import logging
import traceback
from pathlib import Path
from typing import TYPE_CHECKING, Any
@ -23,6 +21,7 @@ from app.library.encoder import Encoder
from app.library.Events import Event, EventBus, Events
from app.library.httpx_client import async_client
from app.library.ItemDTO import Item, ItemDTO
from app.library.log import get_logger
from app.library.Singleton import Singleton
if TYPE_CHECKING:
@ -31,7 +30,7 @@ if TYPE_CHECKING:
import httpx
from aiohttp import web
LOG: logging.Logger = logging.getLogger("feature.notifications")
LOG = get_logger()
class Notifications(metaclass=Singleton):
@ -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)}

View file

@ -1,7 +1,6 @@
from __future__ import annotations
import json
import logging
from pathlib import Path
from typing import TYPE_CHECKING, Any
@ -9,11 +8,12 @@ from app.features.core.migration import Migration as FeatureMigration
from app.features.presets.schemas import Preset
from app.features.presets.utils import preset_name
from app.library.config import Config
from app.library.log import get_logger
if TYPE_CHECKING:
from app.features.presets.repository import PresetsRepository
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
class Migration(FeatureMigration):
@ -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)

View file

@ -1,6 +1,5 @@
from __future__ import annotations
import logging
from typing import TYPE_CHECKING, Any
from sqlalchemy import func, or_, select
@ -12,6 +11,7 @@ from app.features.presets.models import PresetModel
from app.features.presets.utils import preset_name, seed_defaults
from app.library.config import Config
from app.library.Events import Event, EventBus, Events
from app.library.log import get_logger
from app.library.Services import Services
from app.library.Singleton import Singleton
@ -27,7 +27,7 @@ if TYPE_CHECKING:
SessionFactory = Callable[[], AbstractAsyncContextManager[AsyncSession]]
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
class PresetsRepository(metaclass=Singleton):

View file

@ -1,10 +1,11 @@
import logging
import re
from datetime import UTC, datetime
from app.library.log import get_logger
NAME_WHITESPACE_PATTERN = re.compile(r"\s+")
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
async def seed_defaults(repo) -> None:
@ -48,7 +49,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:

View file

@ -5,7 +5,6 @@ Python wrapper for ffprobe command line tool. ffprobe must exist in the path.
import asyncio
import functools
import json
import logging
import operator
import os
import subprocess # qa: ignore
@ -14,9 +13,10 @@ from pathlib import Path
import anyio
from app.features.streaming.types import FFProbeError
from app.library.log import get_logger
from app.library.Utils import timed_lru_cache
LOG: logging.Logger = logging.getLogger("streaming.ffprobe")
LOG = get_logger()
class FFStream:

View file

@ -1,5 +1,4 @@
import asyncio
import logging
import os
import subprocess # type: ignore
import sys
@ -19,6 +18,7 @@ from app.features.streaming.library.segment_encoders import (
select_encoder,
)
from app.library.config import SUPPORTED_CODECS, Config
from app.library.log import get_logger
if TYPE_CHECKING:
from asyncio.subprocess import Process
@ -26,7 +26,7 @@ if TYPE_CHECKING:
from .ffprobe import FFProbeResult
from .segment_encoders import EncoderBuilder
LOG: logging.Logger = logging.getLogger("player.segments")
LOG = get_logger()
class Segments:
@ -170,7 +170,12 @@ 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 segment %s for '%s'.",
self.index,
file,
extra={"file": str(file), "segment_index": self.index, "ffmpeg_args": args},
)
try:
while True:
@ -191,7 +196,10 @@ 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(
"Segment stream for '%s' did not stop ffmpeg in time after the client disconnected; killing it.",
file,
)
proc.kill()
raise
except ConnectionResetError:
@ -204,7 +212,10 @@ 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(
"Segment stream for '%s' did not stop ffmpeg in time after the client disconnected; killing it.",
file,
)
proc.kill()
try:
rc = await asyncio.wait_for(proc.wait(), timeout=5)
@ -215,7 +226,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("Segment stream for '%s' did not stop ffmpeg in time; killing the process.", file)
proc.kill()
try:
rc = await asyncio.wait_for(proc.wait(), timeout=5)
@ -233,7 +244,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 +270,14 @@ 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(
"Retrying segment %s for '%s' because hardware encoder '%s' failed: %s.",
self.index,
file,
s_codec,
err,
extra={"ffmpeg_args": ffmpeg_args, "returncode": rc, "stderr": err, "codec": s_codec},
)
self.attempted.add(s_codec)
finally:
if stream_input.is_symlink():

View file

@ -1,6 +1,5 @@
from __future__ import annotations
import logging
from dataclasses import dataclass
from pathlib import Path
@ -9,9 +8,10 @@ import pysubs2
from pysubs2.formats.substation import SubstationFormat
from pysubs2.time import ms_to_times
from app.library.log import get_logger
from app.library.Utils import ALLOWED_SUBS_EXTENSIONS, get_file_sidecar
LOG: logging.Logger = logging.getLogger("player.subtitle")
LOG = get_logger()
SOURCE_FORMATS: tuple[str, ...] = ("vtt", "srt", "ass")
DELIVERY_FORMATS: dict[str, str] = {

View file

@ -1,7 +1,6 @@
from __future__ import annotations
import asyncio
import logging
import os
import subprocess
from pathlib import Path
@ -9,9 +8,10 @@ from pathlib import Path
from app.features.streaming.library.ffprobe import ffprobe
from app.library.cache import Cache
from app.library.config import Config
from app.library.log import get_logger
from app.library.Utils import FILES_TYPE, get_file_sidecar
LOG: logging.Logger = logging.getLogger("player.thumbnail")
LOG = get_logger()
IMAGE_TYPES: tuple[str, ...] = (".jpg", ".jpeg", ".png", ".webp")
FOLDER_IMAGE_ORDER: tuple[str, ...] = ("thumbnail", "poster", "artwork", "cover", "fanart")
@ -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("Configured thumbnail generation to run %s job(s) at a time.", 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

View file

@ -1,4 +1,3 @@
import logging
import time
from datetime import UTC, datetime
from pathlib import Path
@ -12,10 +11,11 @@ from app.features.streaming.library.segments import Segments
from app.features.streaming.library.subtitle import Subtitle, get_subtitle_tracks
from app.features.streaming.types import StreamingError
from app.library.config import Config
from app.library.log import get_logger
from app.library.router import route
from app.library.Utils import get_file
LOG: logging.Logger = logging.getLogger("streaming")
LOG = get_logger()
@route("GET", "api/player/playlist/{file:.*}.m3u8", "playlist_create")
@ -128,7 +128,13 @@ 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 %s streaming playlist for '%s': %s.",
mode,
file,
e,
extra={"route": "streaming.playlist", "file_path": file, "mode": mode, "exception_type": type(e).__name__},
)
return web.json_response(data={"error": str(e)}, status=web.HTTPNotFound.status_code)
return web.Response(

View file

@ -255,14 +255,14 @@ async def test_stream_gpu_fallback(
# Encourage GPU preference
seg.vcodec = "" # empty -> try GPUs first
resp = _FakeResp()
with caplog.at_level(logging.WARNING, logger="player.segments"):
with caplog.at_level(logging.WARNING, logger="ytptube"):
await seg.stream(tmp_path / "file.mp4", resp)
# Ensure fallback path streamed data
assert len(resp.data) > 0
# Ensure we logged the reason for GPU failure (message text may vary)
assert any(
("Hardware encoder failed" in r.message) or ("transcoding has failed" in r.message) for r in caplog.records
("hardware encoder" in r.message.lower()) or ("transcoding has failed" in r.message) for r in caplog.records
)
assert any("nvenc failure" in r.message for r in caplog.records)
# Verify second invocation switched codec to a safe fallback (software)

View file

@ -6,7 +6,6 @@ import asyncio
import fnmatch
import hashlib
import json
import logging
import re
from collections.abc import Mapping
from typing import TYPE_CHECKING, Any
@ -26,6 +25,7 @@ from app.features.ytdlp.utils import get_archive_id
from app.library.cache import Cache
from app.library.config import Config
from app.library.httpx_client import Globals, build_request_headers, get_async_client, resolve_curl_transport
from app.library.log import get_logger
from ._base_handler import BaseHandler
@ -34,7 +34,7 @@ if TYPE_CHECKING:
from parsel.selector import SelectorList
LOG: logging.Logger = logging.getLogger("handlers.generic")
LOG = get_logger()
CACHE: Cache = Cache()
@ -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(
"Task definition '%s' is missing an item container selector.",
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):
@ -672,7 +771,7 @@ class GenericTaskHandler(BaseHandler):
return values
if "jsonpath" == rule.type:
LOG.error("Extraction type 'jsonpath' is only valid for JSON responses.")
LOG.error("Field '%s' uses 'jsonpath' on a non-JSON response.", field, extra={"field": field})
return values
selection: SelectorList[Selector] = (
@ -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():

View file

@ -1,5 +1,4 @@
import hashlib
import logging
import re
from typing import TYPE_CHECKING, Any
from xml.etree.ElementTree import Element
@ -10,13 +9,14 @@ from app.features.tasks.definitions.results import HandleTask, TaskFailure, Task
from app.features.ytdlp.extractor import fetch_info
from app.features.ytdlp.utils import get_archive_id
from app.library.cache import Cache
from app.library.log import get_logger
from ._base_handler import BaseHandler
if TYPE_CHECKING:
from xml.etree.ElementTree import Element
LOG: logging.Logger = logging.getLogger("handlers.rss")
LOG = get_logger()
CACHE: Cache = Cache()
@ -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

View file

@ -1,14 +1,14 @@
import logging
import re
import httpx
from app.features.tasks.definitions.results import HandleTask, TaskFailure, TaskItem, TaskResult
from app.features.ytdlp.utils import get_archive_id
from app.library.log import get_logger
from ._base_handler import BaseHandler
LOG: logging.Logger = logging.getLogger("handlers.tver")
LOG = get_logger()
class TverHandler(BaseHandler):
@ -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] = []

View file

@ -1,4 +1,3 @@
import logging
import re
from typing import TYPE_CHECKING
from xml.etree.ElementTree import Element
@ -7,13 +6,14 @@ import httpx
from app.features.tasks.definitions.results import HandleTask, TaskFailure, TaskItem, TaskResult
from app.features.ytdlp.utils import get_archive_id
from app.library.log import get_logger
from ._base_handler import BaseHandler
if TYPE_CHECKING:
from xml.etree.ElementTree import Element
LOG: logging.Logger = logging.getLogger("handlers.twitch")
LOG = get_logger()
class TwitchHandler(BaseHandler):
@ -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] = []

View file

@ -1,4 +1,3 @@
import logging
import re
from typing import TYPE_CHECKING, Any
from xml.etree.ElementTree import Element
@ -7,13 +6,14 @@ import httpx
from app.features.tasks.definitions.results import HandleTask, TaskFailure, TaskItem, TaskResult
from app.features.ytdlp.utils import get_archive_id
from app.library.log import get_logger
from ._base_handler import BaseHandler
if TYPE_CHECKING:
from xml.etree.ElementTree import Element
LOG: logging.Logger = logging.getLogger("handlers.youtube")
LOG = get_logger()
class YoutubeHandler(BaseHandler):
@ -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] = []

View file

@ -1,17 +1,17 @@
from __future__ import annotations
import json
import logging
from pathlib import Path
from typing import TYPE_CHECKING, Any
from app.features.core.migration import Migration as FeatureMigration
from app.library.config import Config
from app.library.log import get_logger
if TYPE_CHECKING:
from app.features.tasks.definitions.repository import TaskDefinitionsRepository
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
class Migration(FeatureMigration):
@ -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):

View file

@ -1,6 +1,5 @@
from __future__ import annotations
import logging
from typing import TYPE_CHECKING, Any
from sqlalchemy import func, or_, select
@ -10,6 +9,7 @@ from app.features.core.schemas import CEFeature, ConfigEvent
from app.features.tasks.definitions.migration import Migration
from app.features.tasks.definitions.models import TaskDefinitionModel
from app.library.Events import Event, EventBus, Events
from app.library.log import get_logger
from app.library.Services import Services
from app.library.Singleton import Singleton
@ -21,7 +21,7 @@ if TYPE_CHECKING:
from sqlalchemy.sql.elements import ColumnElement
from sqlalchemy.sql.selectable import Select
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
class TaskDefinitionsRepository(metaclass=Singleton):

View file

@ -1,4 +1,3 @@
import logging
from typing import Any
from aiohttp import web
@ -16,9 +15,10 @@ from app.features.tasks.definitions.schemas import (
from app.features.tasks.definitions.utils import model_to_schema, schema_to_payload
from app.library.encoder import Encoder
from app.library.Events import EventBus, Events
from app.library.log import get_logger
from app.library.router import route
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
@route("GET", "api/tasks/definitions/", "task_definitions")
@ -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,

View file

@ -3,7 +3,6 @@ from __future__ import annotations
import asyncio
import importlib
import inspect
import logging
import pkgutil
import random
from datetime import UTC, datetime
@ -15,6 +14,7 @@ from app.features.ytdlp.utils import archive_read
from app.library.downloads.queue_manager import DownloadQueue
from app.library.Events import EventBus, Events
from app.library.ItemDTO import Item, ItemDTO
from app.library.log import get_logger
from app.library.Services import Services
if TYPE_CHECKING:
@ -22,7 +22,7 @@ if TYPE_CHECKING:
from app.library.config import Config
from app.library.Scheduler import Scheduler
LOG: logging.Logger = logging.getLogger("definitions.service")
LOG = get_logger()
class TaskHandle:
@ -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,28 @@ class TaskHandle:
continue
if result is None:
LOG.error(f"Handler '{handler.__name__}' returned no result for task '{task.name}'.")
LOG.error(
"Handler '%s' returned no result for task '%s'.",
handler.__name__,
task.name,
extra={"task_id": task.id, "task_name": task.name, "handler_name": handler.__name__},
)
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 dispatch finished: %s handled, %s unhandled, %s disabled, %s failed.",
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 +195,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 +209,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 +221,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 +265,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 +297,27 @@ 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(
"Handler '%s' failed to extract items for task '%s' because %s.",
handler.__name__,
task.name,
msg,
extra={"task_id": task.id, "task_name": task.name, "handler_name": handler.__name__, "error": msg},
)
return extraction
if not isinstance(extraction, TaskResult):
LOG.error(
f"Handler '{handler.__name__}' returned unexpected result type '{type(extraction).__name__}'.",
"Handler '%s' returned unexpected result type '%s' for task '%s'.",
handler.__name__,
type(extraction).__name__,
task.name,
extra={
"task_id": task.id,
"task_name": task.name,
"handler_name": handler.__name__,
"result_type": type(extraction).__name__,
},
)
return TaskFailure(
message="Handler returned invalid result type.", metadata={"type": type(extraction).__name__}
@ -249,7 +345,18 @@ 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(
"Handler '%s' returned unexpected item type '%s' for task '%s'.",
handler.__name__,
type(item).__name__,
task.name,
extra={
"task_id": task.id,
"task_name": task.name,
"handler_name": handler.__name__,
"item_type": type(item).__name__,
},
)
continue
url: str = item.url
@ -258,7 +365,13 @@ 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(
"Handler '%s' skipped '%s' for task '%s' because it has no archive ID.",
handler.__name__,
url,
task.name,
extra={"task_id": task.id, "task_name": task.name, "handler_name": handler.__name__, "url": url},
)
continue
if archive_id in queued:
@ -287,12 +400,31 @@ 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."
"Handler '%s' found %s item(s) for task '%s', but none were queued.",
handler.__name__,
len(raw_items),
task.name,
extra={
"task_id": task.id,
"task_name": task.name,
"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)})."
"Handler '%s' found %s new item(s) for task '%s'.",
handler.__name__,
len(filtered),
task.name,
extra={
"task_id": task.id,
"task_name": task.name,
"handler_name": handler.__name__,
"item_count": len(filtered),
"raw_count": len(raw_items),
},
)
base_item = Item.format(
@ -367,7 +499,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 +542,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 +568,11 @@ class TaskHandle:
if not isinstance(extraction, TaskResult):
LOG.error(
f"Handler '{handler_cls.__name__}' returned unexpected result type '{type(extraction).__name__}' during inspection.",
"Handler '%s' returned unexpected result type '%s' while inspecting '%s'.",
handler_cls.__name__,
type(extraction).__name__,
url,
extra={"handler_name": handler_cls.__name__, "url": url, "result_type": type(extraction).__name__},
)
extraction = TaskResult()

View file

@ -1,18 +1,18 @@
from __future__ import annotations
import json
import logging
from pathlib import Path
from typing import TYPE_CHECKING, Any
from app.features.core.migration import Migration as FeatureMigration
from app.features.tasks.schemas import Task
from app.library.config import Config
from app.library.log import get_logger
if TYPE_CHECKING:
from app.features.tasks.repository import TasksRepository
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
class Migration(FeatureMigration):
@ -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)

View file

@ -1,12 +1,12 @@
from __future__ import annotations
import logging
from typing import TYPE_CHECKING, Any
from sqlalchemy import func, or_, select
from app.features.core.deps import get_session
from app.features.tasks.models import TaskModel
from app.library.log import get_logger
from app.library.Singleton import Singleton
if TYPE_CHECKING:
@ -17,7 +17,7 @@ if TYPE_CHECKING:
from sqlalchemy.sql.elements import ColumnElement
from sqlalchemy.sql.selectable import Select
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
class TasksRepository(metaclass=Singleton):

View file

@ -1,5 +1,4 @@
import asyncio
import logging
from typing import TYPE_CHECKING, Any
from aiohttp import web
@ -18,6 +17,7 @@ from app.library.ag_utils import ag
from app.library.config import Config
from app.library.encoder import Encoder
from app.library.Events import EventBus, Events
from app.library.log import get_logger
from app.library.router import route
from app.library.Utils import get_channel_images, get_file, validate_url
@ -25,7 +25,7 @@ if TYPE_CHECKING:
from pathlib import Path
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
TIMER_SLOTS_PER_HOUR: int = 12
@ -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,15 @@ 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 a task name from '%s' because %s.",
url,
e,
extra={"url": url, "preset": preset, "error": str(e)},
)
return (None, None)
@ -234,12 +243,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 +302,11 @@ 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__},
)
continue
if len(created_tasks) == 0:
@ -482,7 +495,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 +653,12 @@ 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 the metadata output path for task '%s'.",
task.name,
extra={"task_id": task.id, "task_name": task.name, "error": str(e)},
exc_info=True,
)
info = {
"id": ag(metadata, ["id", "channel_id"]),
@ -649,7 +676,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 +738,25 @@ 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 '%s' thumbnail for task '%s'.",
key,
task.name,
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}'")
except ValueError as exc:
LOG.warning(
"Task '%s' has an invalid '%s' thumbnail URL because %s.",
task.name,
key,
exc,
extra={"task_id": task.id, "task_name": task.name, "thumbnail": key, "url": url},
)
continue
resp = await client.request(
@ -727,11 +770,27 @@ 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 '%s' thumbnail for task '%s'.",
key,
task.name,
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 metadata thumbnails for task '%s'.",
task.name,
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:

View file

@ -1,12 +1,12 @@
from __future__ import annotations
import logging
from typing import TYPE_CHECKING
from app.features.core.schemas import CEAction, CEFeature, ConfigEvent
from app.features.tasks.models import TaskModel
from app.features.tasks.utils import cron_time
from app.library.Events import Event, EventBus, Events
from app.library.log import get_logger
from app.library.Scheduler import Scheduler
from app.library.Services import Services
from app.library.Singleton import Singleton
@ -14,7 +14,7 @@ from app.library.Singleton import Singleton
if TYPE_CHECKING:
from aiohttp import web
LOG: logging.Logger = logging.getLogger("tasks.service")
LOG = get_logger()
class Tasks(metaclass=Singleton):
@ -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},

View file

@ -1,6 +1,6 @@
import logging
from app.library.log import get_logger
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
def cron_time(timer: str) -> str:
@ -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

View file

@ -1,12 +1,12 @@
import logging
import os
import threading
import time
from pathlib import Path
from app.library.log import get_logger
from app.library.Singleton import ThreadSafe
LOG: logging.Logger = logging.getLogger("Archiver")
LOG = get_logger()
class _Entry:
@ -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:

View file

@ -12,10 +12,11 @@ from aiohttp import web
from app.features.ytdlp.utils import _DATA, LogWrapper, get_archive_id
from app.features.ytdlp.ytdlp import YTDLP
from app.library.log import get_logger
from app.library.Services import Services
from app.library.Singleton import Singleton
LOG: logging.Logger = logging.getLogger("downloads.extractor")
LOG = get_logger()
LIVE_REEXTRACT_STATUSES: set[str] = {"is_live", "post_live"}
REEXTRACT_INFO_KEY = "_ytptube_reextract"
@ -180,7 +181,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 +465,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,

View file

@ -1,9 +1,10 @@
import logging
import subprocess
import sys
from typing import Any
LOG: logging.Logger = logging.getLogger("ytdlp.utils")
from app.library.log import get_logger
LOG = get_logger()
def patch_metadataparser() -> None:
@ -14,7 +15,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 +67,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):

View file

@ -18,10 +18,11 @@ from app.library.cache import Cache
from app.library.config import Config
from app.library.encoder import Encoder
from app.library.ItemDTO import Item
from app.library.log import get_logger
from app.library.router import route
from app.library.Utils import validate_url
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
def _get_preset_archive(preset: str) -> str | None:
@ -37,7 +38,12 @@ 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': %s.",
preset,
e,
extra={"preset": preset, "exception_type": type(e).__name__},
)
return None
if not (archive_file := opts.get("download_archive")):
@ -125,7 +131,19 @@ 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': %s.",
archive_file,
preset,
e,
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 +189,21 @@ 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': %s.",
len(items),
archive_file,
preset,
e,
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 +247,20 @@ 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': %s.",
len(items),
archive_file,
preset,
e,
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 +452,19 @@ 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': %s.",
url,
e,
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 +552,19 @@ 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': %s.",
it.url,
e,
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,

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("Prepared 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"

View file

@ -11,9 +11,10 @@ from typing import Any
from app.features.ytdlp.patches import apply_ytdlp_patches
from app.features.ytdlp.ytdlp import YTDLP
from app.library.log import get_logger
from app.library.Utils import merge_dict, timed_lru_cache
LOG: logging.Logger = logging.getLogger("ytdlp.utils")
LOG = get_logger()
class _DATA:
@ -462,8 +463,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

View file

@ -1,5 +1,4 @@
# flake8: noqa: F401, RUF100, W291, I001
import logging
import sys
from typing import Any
@ -10,6 +9,7 @@ from yt_dlp.utils import make_archive_id
from app.features.ytdlp.outtmpl import rewrite_outtmpl
from app.features.ytdlp.patches import apply_ytdlp_patches
from app.library.cf_solver_handler import set_cf_handler
from app.library.log import get_logger
class _ArchiveProxy:
@ -67,7 +67,7 @@ class YTDLP(yt_dlp.YoutubeDL):
postprocessors.value.update({"NFOMakerPP": NFOMakerPP})
YTDLP._registered = True
except Exception:
logging.getLogger("ytdlp.wrapper").exception("Failed to register yt-dlp plugins")
get_logger().exception("Failed to register yt-dlp plugins")
# Avoid yt-dlp preloading the archive file by stripping the param first
orig_file = None

View file

@ -1,4 +1,3 @@
import logging
import shlex
from pathlib import Path
from typing import Any
@ -6,9 +5,10 @@ from typing import Any
from app.features.presets.schemas import Preset
from app.features.ytdlp.utils import arg_converter
from app.library.config import Config
from app.library.log import get_logger
from app.library.Utils import calc_download_path, create_cookies_file, merge_dict
LOG: logging.Logger = logging.getLogger("ytdlp.ytdlp_opts")
LOG = get_logger()
class ARGSMerger:
@ -335,7 +335,12 @@ 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': %s.",
preset.name,
e,
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 +408,7 @@ class YTDLPOpts:
data["format"] = data["format"][1:]
if self._config.debug:
LOG.debug(f"Final yt-dlp options: '{data!s}'.")
LOG.debug("Prepared final yt-dlp options.", extra={"ytdlp_options": data})
return data

View file

@ -1,15 +1,16 @@
import asyncio
import inspect
import logging
import threading
from queue import Empty, Queue
from aiohttp import web
from app.library.log import get_logger
from .Services import Services
from .Singleton import Singleton
LOG: logging.Logger = logging.getLogger("BackgroundWorker")
LOG = get_logger()
class CloseThread:
@ -39,19 +40,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("Started background worker thread.")
self.thread = threading.Thread(target=self._run, daemon=True)
self.thread.start()
async def on_shutdown(self, _: web.Application):
self.running = False
try:
LOG.debug("Shutting down background worker...")
LOG.debug("Stopping 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 +83,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
@ -88,9 +100,12 @@ class BackgroundWorker(metaclass=Singleton):
loop.call_soon_threadsafe(loop.stop)
loop_thread.join(timeout=5)
loop.close()
LOG.debug("Event loop has been stopped and closed.")
LOG.debug("Stopped background worker event loop.")
except Exception as e:
LOG.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))

View file

@ -1,15 +1,16 @@
import copy
import logging
from collections import OrderedDict
from collections.abc import Iterable
from enum import Enum
from app.library.log import get_logger
from .downloads import Download
from .ItemDTO import ItemDTO
from .operations import matches_condition
from .sqlite_store import SqliteStore
LOG = logging.getLogger("datastore")
LOG = get_logger()
class StoreType(str, Enum):

View file

@ -1,16 +1,16 @@
import asyncio
import datetime
import logging
from collections.abc import Callable
from dataclasses import dataclass, field
from typing import Any
from app.features.core.utils import gen_random
from app.library.log import get_logger
from .BackgroundWorker import BackgroundWorker
from .Singleton import Singleton
LOG: logging.Logger = logging.getLogger("events")
LOG = get_logger()
class Events:
@ -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(
"Delivering '%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:
"""

View file

@ -1,7 +1,6 @@
import base64
import hmac
import inspect
import logging
from collections.abc import Awaitable
from datetime import UTC, datetime, timedelta
from pathlib import Path
@ -9,7 +8,9 @@ from pathlib import Path
import anyio
from aiohttp import web
from aiohttp.web import Request, RequestHandler, Response
from aiohttp.web_log import AccessLogger
from app.library.log import get_logger
from app.library.Services import Services
from .cache import Cache
@ -19,7 +20,33 @@ from .Events import EventBus
from .router import RouteType, get_routes
from .Utils import decrypt_data, encrypt_data, get_file, load_modules
LOG: logging.Logger = logging.getLogger("http_api")
LOG = get_logger("http")
class HttpAccessLogger(AccessLogger):
def log(self, request: Request, response: Response, time: float) -> None:
try:
fmt_info = self._format_line(request, response, time)
values: list[object] = []
extra: dict[str, object] = {"elapsed_ms": round(time * 1000.0, 2)}
for key, value in fmt_info:
values.append(value)
if isinstance(key, str):
extra[key] = value
else:
parent, child = key
group = extra.get(parent, {})
if not isinstance(group, dict):
group = {}
group[child] = value
extra[parent] = group
message = self._log_format % tuple(values)
self.logger.info(message, extra=extra)
except Exception:
self.logger.exception("Error in logging")
class HttpAPI:
@ -89,7 +116,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 +160,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 +209,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 +269,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 +361,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 +378,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,

View file

@ -1,13 +1,13 @@
import asyncio
import functools
import json
import logging
from pathlib import Path
from typing import Any
from aiohttp import web
from app.features.core.utils import gen_random
from app.library.log import get_logger
from app.library.router import Route, RouteType, get_routes
from app.library.Services import Services
from app.library.Utils import load_modules
@ -17,7 +17,7 @@ from .encoder import Encoder
from .Events import Event, EventBus, Events
from .ItemDTO import Item
LOG: logging.Logger = logging.getLogger("socket_api")
LOG = get_logger()
class WebSocketHub:
@ -145,7 +145,10 @@ class HttpSocket:
for route in socket_routes.values():
if self.config.debug:
LOG.debug(
f"Add ({route.name}) {route.method.value if isinstance(route.method, RouteType) else route.method}: {route.path}."
"Registered socket route '%s' for %s %s.",
route.name,
route.method.value if isinstance(route.method, RouteType) else route.method,
route.path,
)
async def handle_message(sid: str, message: str) -> None:
@ -161,7 +164,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 +186,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 +195,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 +208,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("Registered WebSocket endpoint at '%s'.", ws_path, extra={"method": "GET", "path": ws_path})
app.router.add_get(ws_path, ws_handler, name="ws")

View file

@ -1,4 +1,3 @@
import logging
import re
import time
import uuid
@ -10,12 +9,13 @@ from typing import TYPE_CHECKING, Any
from app.features.ytdlp.utils import archive_add, archive_delete, archive_read, get_archive_id
from app.features.ytdlp.ytdlp_opts import YTDLPOpts
from app.library.encoder import Encoder
from app.library.log import get_logger
from app.library.Utils import clean_item, get_file, get_file_sidecar
if TYPE_CHECKING:
from app.features.presets.schemas import Preset
LOG: logging.Logger = logging.getLogger("ItemDTO")
LOG = get_logger()
@dataclass(kw_only=True)

View file

@ -1,14 +1,15 @@
import importlib
import importlib.metadata
import logging
import os
import subprocess
import sys
from pathlib import Path
from app.library.log import get_logger
from .httpx_client import sync_client
LOG: logging.Logger = logging.getLogger("package_installer")
LOG = get_logger()
def parse_version(v: str) -> tuple[int, ...]:
@ -64,19 +65,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 +109,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 +162,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 +182,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 configured user pip 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:
"""

View file

@ -1,13 +1,14 @@
import asyncio
import logging
from aiocron import Cron
from aiohttp import web
from app.library.log import get_logger
from .Events import EventBus, Events
from .Singleton import Singleton
LOG = logging.getLogger("scheduler")
LOG = get_logger()
class Scheduler(metaclass=Singleton):
@ -46,10 +47,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 +131,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 +155,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

View file

@ -1,12 +1,12 @@
import inspect
import logging
from dataclasses import dataclass
from typing import Annotated, Any, TypeVar, get_args, get_origin, get_type_hints
from app.library.log import get_logger
from app.library.Singleton import Singleton
T = TypeVar("T")
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
def _unwrap_annotation(ann: Any) -> Any:

View file

@ -3,7 +3,6 @@ from __future__ import annotations
import asyncio
import errno
import json
import logging
import os
import shlex
import shutil
@ -16,6 +15,7 @@ from typing import TYPE_CHECKING, Any
from aiohttp import web
from app.library.config import Config
from app.library.log import get_logger
from app.library.Scheduler import Scheduler
from app.library.Services import Services
from app.library.Singleton import Singleton
@ -26,7 +26,7 @@ if TYPE_CHECKING:
from aiohttp.web import Request
LOG: logging.Logger = logging.getLogger("terminal_manager")
LOG = get_logger()
ACTIVE_FILE_NAME = "active.json"
METADATA_FILE_NAME = "metadata.json"
@ -296,7 +296,7 @@ class TerminalSessionManager(metaclass=Singleton):
master_fd: int | None = None
try:
LOG.info("Cli command from client. '%s'", command)
LOG.info("Starting terminal session '%s' command.", session_id, extra={"session_id": session_id})
args = ["yt-dlp", *shlex.split(command, posix=os.name != "nt")]
env_vars = self._build_env()
@ -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)
@ -371,7 +377,7 @@ class TerminalSessionManager(metaclass=Singleton):
try:
return_code = await asyncio.wait_for(proc.wait(), timeout=self._shutdown_timeout)
except TimeoutError:
LOG.warning("Terminal session '%s' process did not exit cleanly.", session_id)
LOG.warning("Terminal session '%s' did not exit after repeated shutdown attempts.", session_id)
if proc is not None:
proc_returncode = getattr(proc, "returncode", None)

View file

@ -1,10 +1,11 @@
import asyncio
import logging
import re
from typing import Any
from aiohttp import web
from app.library.log import get_logger
from .cache import Cache
from .config import Config
from .Events import EventBus, Events
@ -13,7 +14,7 @@ from .Scheduler import Scheduler
from .Singleton import Singleton
from .version import APP_VERSION
LOG: logging.Logger = logging.getLogger("update_checker")
LOG = get_logger()
class UpdateChecker(metaclass=Singleton):
@ -145,7 +146,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 whether %s has an update available.",
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 +160,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 has an 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(
"%s is already up to date.",
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 whether %s has an update available.",
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]:
@ -203,7 +235,7 @@ class UpdateChecker(metaclass=Singleton):
async def _check_ytdlp_version(self) -> tuple[str, str | None]:
current_version: str = self._config._ytdlp_version()
if not current_version or "0.0.0" == current_version:
LOG.warning("Could not determine yt-dlp version, skipping yt-dlp update check.")
LOG.warning("Skipping the yt-dlp update check because the current version could not be determined.")
return ("error", None)
status, new_version = await self._check_github_version(
@ -238,5 +270,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(
"Failed to compare versions '%s' and '%s' because %s.",
current,
latest,
e,
extra={"current_version": current, "latest_version": latest, "exception_type": type(e).__name__},
exc_info=True,
)
return False

View file

@ -18,7 +18,9 @@ from typing import Any
from Crypto.Cipher import AES
LOG: logging.Logger = logging.getLogger("Utils")
from app.library.log import get_logger
LOG = get_logger()
ALLOWED_SUBS_EXTENSIONS: set[str] = {".srt", ".vtt", ".ass"}
"Allowed subtitle file extensions."
@ -43,6 +45,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 +88,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 +505,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 +565,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 +697,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 +794,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 +929,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 +1104,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 +1152,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 +1363,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 +1415,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]]:

View file

@ -1,17 +1,17 @@
import hashlib
import logging
import threading
import time
from typing import Any
from aiohttp import web
from app.library.log import get_logger
from app.library.Services import Services
from .Scheduler import Scheduler
from .Singleton import ThreadSafe
LOG = logging.getLogger("cache")
LOG = get_logger()
class Cache(metaclass=ThreadSafe):
@ -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)},
)

View file

@ -1,7 +1,6 @@
from __future__ import annotations
import http.cookiejar
import logging
from abc import ABC
from collections.abc import Callable
from typing import Any, ClassVar
@ -20,8 +19,9 @@ from yt_dlp.networking.exceptions import HTTPError
from yt_dlp.utils.networking import clean_headers
from app.library.cf_solver_shared import CACHE, is_cf_challenge, solver
from app.library.log import get_logger
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
SolverFn = Callable[[Request, Response, RequestHandler], Request | None]
@ -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()

View file

@ -2,16 +2,17 @@
from __future__ import annotations
import json
import logging
import time
import urllib.request
from typing import Any
from urllib.parse import urlparse
from app.library.log import get_logger
from .cache import Cache
CACHE: Cache = Cache()
LOG: logging.Logger = logging.getLogger("cf_solver")
LOG = get_logger()
def solver(url: str, cookies: list[dict[str, Any]], user_agent: str | None) -> dict[str, Any] | None:
@ -63,16 +64,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(

View file

@ -12,10 +12,21 @@ from typing import TYPE_CHECKING, Any
import coloredlogs
from dotenv import load_dotenv
from app.library.log import get_logger
from .Singleton import Singleton
from .Utils import JsonLogFormatter
from .version import APP_BRANCH, APP_BUILD_DATE, APP_COMMIT_SHA, APP_VERSION
APP_THIRD_PARTY_LOG_LEVELS: tuple[tuple[str, int], ...] = (
("httpx", logging.WARNING),
("urllib3.connectionpool", logging.WARNING),
("apprise", logging.WARNING),
("httpcore", logging.INFO),
("aiosqlite", logging.INFO),
("asyncio", logging.INFO),
)
if TYPE_CHECKING:
from subprocess import CompletedProcess
@ -75,9 +86,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."""
@ -313,6 +321,7 @@ class Config(metaclass=Singleton):
_frontend_vars: tuple = (
"download_path",
"keep_archive",
"log_level",
"output_template",
"started",
"remove_files",
@ -360,12 +369,13 @@ class Config(metaclass=Singleton):
def __init__(self, is_native: bool = False):
baseDefaultPath: str = str(Path(__file__).parent.parent.parent.absolute())
LOG = get_logger()
self.config_path = os.environ.get("YTP_CONFIG_PATH", None) or str(Path(baseDefaultPath) / "var" / "config")
envFile: str = Path(self.config_path) / ".env"
if envFile.exists():
logging.info(f"Loading environment variables from '{envFile}'.")
LOG.info("Loading environment variables from '%s'.", envFile)
load_dotenv(envFile)
self.is_native = is_native
@ -395,7 +405,7 @@ class Config(metaclass=Singleton):
for key in re.findall(r"\{.*?\}", v):
localKey: str = key[1:-1]
if localKey not in self.__dict__:
logging.error(f"Config variable '{k}' had non-existing config reference '{key}'.")
LOG.error("Config variable '%s' had non-existing config reference '%s'.", k, key)
sys.exit(1)
v: str = v.replace(key, str(getattr(self, localKey)))
@ -433,18 +443,23 @@ class Config(metaclass=Singleton):
encoding="utf-8",
)
LOG: logging.Logger = logging.getLogger("config")
if self.debug:
try:
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.error("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 +468,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(
"Basic authentication is enabled for user '%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 +491,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)
@ -489,14 +508,7 @@ class Config(metaclass=Singleton):
self.started = time.time()
_log_levels = (
("httpx", logging.WARNING),
("urllib3.connectionpool", logging.WARNING),
("apprise", logging.WARNING),
("httpcore", logging.INFO),
("aiosqlite", logging.INFO),
)
for _tool, _level in _log_levels:
for _tool, _level in APP_THIRD_PARTY_LOG_LEVELS:
logging.getLogger(_tool).setLevel(_level)
if self.app_env not in ("production", "development"):
@ -571,6 +583,9 @@ class Config(metaclass=Singleton):
data: dict[str, Any] = {k: getattr(self, k) for k in self._frontend_vars}
data["ytdlp_version"] = Config._ytdlp_version()
from app.library.log_control import get_runtime_log_level
data["runtime_log_level"] = get_runtime_log_level()
return data
def get_replacers(self) -> dict[str, str]:
@ -598,6 +613,7 @@ class Config(metaclass=Singleton):
Updates the version of the application using git tags.
This is used to set the version to the latest git tag.
"""
LOG = get_logger()
git_path: str = Path(__file__).parent / ".." / ".." / ".git"
if not git_path.exists():
return
@ -615,12 +631,12 @@ class Config(metaclass=Singleton):
)
if 0 != branch_result.returncode:
logging.error(f"Git rev-parse failed: {branch_result.stderr.strip()}")
LOG.error("Git rev-parse failed: %s", branch_result.stderr.strip())
return
branch_name: str = branch_result.stdout.strip()
if not branch_name:
logging.warning("Git branch name is empty.")
LOG.warning("Git branch name is empty.")
return
commit_result: CompletedProcess[str] = subprocess.run(
@ -633,12 +649,12 @@ class Config(metaclass=Singleton):
)
if 0 != commit_result.returncode:
logging.error(f"Git log failed: {commit_result.stderr.strip()}")
LOG.error("Git log failed: %s", commit_result.stderr.strip())
return
commit_info: str = commit_result.stdout.strip()
if not commit_info:
logging.warning("Git commit info is empty.")
LOG.warning("Git commit info is empty.")
return
commit_date, commit_sha = commit_info.split("_", 1)
@ -654,6 +670,6 @@ class Config(metaclass=Singleton):
"commit": self.app_commit_sha,
"build_date": self.app_build_date,
}
logging.info(f"Application version info set to '{version_data}'")
LOG.info("Application version info set to '%s'", version_data)
except Exception as e:
logging.error(f"Error while getting git version: {e!s}")
LOG.error("Error while getting git version: %s", e)

View file

@ -19,6 +19,7 @@ from app.features.ytdlp.utils import extract_ytdlp_logs
from app.features.ytdlp.ytdlp import YTDLP
from app.library.config import Config
from app.library.Events import EventBus, Events
from app.library.log import get_logger
from app.library.Utils import create_cookies_file
from ...features.ytdlp.extractor import REEXTRACT_INFO_KEY, extract_info_sync
@ -64,7 +65,7 @@ class Download:
self.max_workers = int(config.max_workers)
self.is_live: bool = bool(info.is_live) or info.live_in is not None
self.info_dict: dict | None = info_dict
self.logger: logging.Logger = logging.getLogger(f"Download.{info.id or info._id}")
self.logger: logging.Logger = get_logger()
self.started_time = 0
self.queue_time: datetime = datetime.now(tz=UTC)
self.logs: list[str] = logs or []
@ -138,12 +139,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 +174,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 +194,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 +245,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 +270,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 +334,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 +371,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 +394,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 +416,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 +446,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 +572,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 +612,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"

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 a yt-dlp progress update 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 a yt-dlp post-processing update 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)

View file

@ -14,6 +14,7 @@ from app.features.ytdlp.extractor import fetch_info
from app.features.ytdlp.utils import archive_add, archive_read, arg_converter, get_extras, ytdlp_reject
from app.library.Events import Events
from app.library.ItemDTO import ItemDTO
from app.library.log import get_logger
from app.library.Utils import create_cookies_file, merge_dict
from .core import Download
@ -26,7 +27,7 @@ if TYPE_CHECKING:
from .queue_manager import DownloadQueue
LOG: logging.Logger = logging.getLogger("downloads.add")
LOG = get_logger()
def _get_ignored_conditions(extras: dict | None) -> list[str]:
@ -122,7 +123,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 +140,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 +169,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 +230,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 +281,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 +363,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 +378,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 +411,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 +431,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 +496,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)

View file

@ -1,6 +1,5 @@
"""Queue monitoring functions."""
import logging
from datetime import UTC, datetime, timedelta
from pathlib import Path
from typing import TYPE_CHECKING
@ -8,12 +7,13 @@ from typing import TYPE_CHECKING
from app.library.ag_utils import ag
from app.library.Events import Events
from app.library.ItemDTO import Item, ItemDTO
from app.library.log import get_logger
from app.library.Utils import dt_delta, str_to_dt
if TYPE_CHECKING:
from .queue_manager import DownloadQueue
LOG: logging.Logger = logging.getLogger("downloads.monitors")
LOG = get_logger()
async def check_for_stale(queue: "DownloadQueue") -> None:
@ -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,12 @@ 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), including '%s'.",
len(titles),
titles[0],
extra={"deleted_count": len(titles), "titles": titles},
)
async def cleanup_thumbnails(queue: "DownloadQueue") -> None:
@ -201,7 +324,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})

View file

@ -1,9 +1,9 @@
"""Playlist processing."""
import logging
from typing import TYPE_CHECKING, Any
from app.features.ytdlp.utils import ytdlp_reject
from app.library.log import get_logger
from app.library.Utils import merge_dict
if TYPE_CHECKING:
@ -11,7 +11,7 @@ if TYPE_CHECKING:
from .queue_manager import DownloadQueue
LOG: logging.Logger = logging.getLogger("downloads.playlist")
LOG = get_logger()
async def process_playlist(
@ -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 {

View file

@ -1,10 +1,10 @@
"""Download pool management - worker coordination and execution."""
import asyncio
import logging
from typing import TYPE_CHECKING
from app.library.Events import EventBus, Events
from app.library.log import get_logger
from app.library.Utils import calc_download_path
from .core import Download
@ -15,7 +15,7 @@ if TYPE_CHECKING:
from .queue_manager import DownloadQueue
LOG: logging.Logger = logging.getLogger("downloads.pool")
LOG = get_logger()
class PoolManager:
@ -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 active downloads (%s item(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:
@ -87,7 +91,7 @@ class PoolManager:
while True:
while not self.queue.queue.has_downloads():
LOG.info("Waiting for item to download.")
LOG.info("Waiting for queued downloads.")
await self.event.wait()
self.event.clear()
adaptive_sleep = 0.2
@ -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,22 @@ 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(
"Started download for '%s' to '%s'.",
entry.info.title,
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 +199,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 +245,11 @@ class PoolManager:
message=nMessage,
)
else:
LOG.warning(f"Download '{id}' not found in queue.")
LOG.warning(
"Completed download '%s' was not found in the queue.",
entry.info.title or id,
extra={"download_id": id, "title": entry.info.title},
)
if self.event:
self.event.set()

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

View file

@ -1,6 +1,5 @@
import functools
import glob
import logging
from datetime import UTC, datetime
from pathlib import Path
from typing import TYPE_CHECKING
@ -10,6 +9,7 @@ from aiohttp import web
from app.library.config import Config
from app.library.Events import EventBus, Events
from app.library.ItemDTO import Item, ItemDTO
from app.library.log import get_logger
from app.library.Scheduler import Scheduler
from app.library.Services import Services
from app.library.Singleton import Singleton
@ -24,7 +24,7 @@ from .pool_manager import PoolManager
if TYPE_CHECKING:
from app.library.DataStore import StoreType
LOG: logging.Logger = logging.getLogger("downloads.queue")
LOG = get_logger()
class DownloadQueue(metaclass=Singleton):
@ -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("Paused the download queue.", 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("Resumed the download queue.", 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), including %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)

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 a download 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,19 @@ 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(
"Failed to cancel the progress update task for '%s' because %s.",
self.info.title,
e,
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."""

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,50 @@ 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(
"Deleted temp folder '%s' for '%s'." if status else "Failed to delete 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),
"deleted": status,
}
},
)

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

View file

@ -1,6 +1,5 @@
"""Video entry processing."""
import logging
import time
from datetime import UTC, datetime, timedelta
from email.utils import formatdate
@ -11,6 +10,7 @@ from app.features.ytdlp.utils import extract_ytdlp_logs, get_extras
from app.library.downloads import Download
from app.library.Events import Events
from app.library.ItemDTO import ItemDTO
from app.library.log import get_logger
from app.library.Utils import calc_download_path, merge_dict, str_to_dt
if TYPE_CHECKING:
@ -18,7 +18,7 @@ if TYPE_CHECKING:
from .queue_manager import DownloadQueue
LOG: logging.Logger = logging.getLogger("downloads.video")
LOG = get_logger()
async def add_video(queue: "DownloadQueue", entry: dict, item: "Item", logs: list[str] | None = None) -> dict[str, str]:
@ -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)}

View file

@ -2,13 +2,14 @@ from __future__ import annotations
import asyncio
import functools
import logging
import threading
from dataclasses import dataclass
from typing import Any, Literal, cast, overload
import httpx
from app.library.log import get_logger
from .cf_solver_shared import is_cf_challenge, solver
__all__: list[str] = [
@ -21,7 +22,7 @@ __all__: list[str] = [
"sync_client",
]
LOG: logging.Logger = logging.getLogger("httpx_cf")
LOG = get_logger()
class Globals:

17
app/library/log.py Normal file
View file

@ -0,0 +1,17 @@
from __future__ import annotations
import logging
from typing import Literal
APP_LOGGER_NAME = "ytptube"
HTTP_LOGGER_NAME = "http_api"
LoggerKind = Literal["app", "http"]
def get_logger_name(kind: LoggerKind = "app") -> str:
return HTTP_LOGGER_NAME if kind == "http" else APP_LOGGER_NAME
def get_logger(kind: LoggerKind = "app") -> logging.Logger:
return logging.getLogger(get_logger_name(kind))

View file

@ -0,0 +1,33 @@
from __future__ import annotations
import logging
from app.library.log import get_logger, get_logger_name
SUPPORTED_LOG_LEVELS: tuple[str, ...] = ("debug", "info", "warning", "error")
def normalize_log_level(level: str) -> str:
value: str = level.strip().lower()
if value not in SUPPORTED_LOG_LEVELS:
msg: str = f"Unsupported log level '{level}'."
raise ValueError(msg)
return value
def get_runtime_log_level() -> str:
return logging.getLevelName(logging.getLogger(get_logger_name()).getEffectiveLevel()).lower()
def set_runtime_log_level(level: str) -> str:
normalized: str = normalize_log_level(level)
numeric_level: int | None = getattr(logging, normalized.upper(), None)
if not isinstance(numeric_level, int):
msg: str = f"Unsupported log level '{level}'."
raise ValueError(msg)
for _logger in (get_logger(),):
_logger.setLevel(numeric_level)
return normalized

View file

@ -1,11 +1,12 @@
import logging
import re
from collections.abc import Awaitable, Callable
from enum import Enum
from functools import wraps
from typing import Any
LOG: logging.Logger = logging.getLogger(__name__)
from app.library.log import get_logger
LOG = get_logger()
# make a enum for route types

View file

@ -1,7 +1,6 @@
import asyncio
import contextlib
import json
import logging
import os
from collections.abc import Iterable
from dataclasses import fields
@ -14,6 +13,8 @@ from sqlalchemy import text
from sqlalchemy.ext.asyncio import AsyncEngine, AsyncSession, async_sessionmaker, create_async_engine
from sqlalchemy.ext.asyncio.engine import AsyncConnection
from app.library.log import get_logger
from .Events import EventBus, Events
from .ItemDTO import ItemDTO
from .operations import Operation, matches_condition
@ -21,7 +22,7 @@ from .Services import Services
from .Singleton import ThreadSafe
from .Utils import init_class
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
ITEM_DTO_FIELDS: set[str] = {f.name for f in fields(ItemDTO)}
@ -500,7 +501,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 +628,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("Database schema version is '%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(
"Database schema was initialized at version '%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"))

View file

@ -30,16 +30,17 @@ from app.library.cache import Cache
from app.library.config import Config
from app.library.downloads import DownloadQueue
from app.library.Events import EventBus, Events
from app.library.HttpAPI import HttpAPI
from app.library.HttpAPI import HttpAccessLogger, HttpAPI
from app.library.HttpSocket import HttpSocket
from app.library.httpx_client import close_shared_clients
from app.library.log import get_logger
from app.library.Scheduler import Scheduler
from app.library.Services import Services
from app.library.sqlite_store import SqliteStore
from app.library.TerminalSessionManager import TerminalSessionManager
from app.library.UpdateChecker import UpdateChecker
LOG = logging.getLogger("app")
LOG = get_logger()
MIME = magic.Magic(mime=True)
ROOT_PATH: Path = Path(__file__).parent.absolute()
@ -73,22 +74,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 +152,23 @@ 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(
"Using download path '%s'.",
self._config.download_path,
extra={"download_path": self._config.download_path},
)
if self._config.is_native:
LOG.info("Running in native mode.")
LOG.info("=" * 40)
@ -166,22 +190,27 @@ class Main:
cb()
HTTP_LOGGER = None
HTTP_LOGGER_CLASS = None
if self._config.access_log:
from app.library.HttpAPI import LOG as HTTP_LOGGER
HTTP_LOGGER.addFilter(
lambda record: f"GET {str(self._app.router['ping'].url_for()).rstrip('/')}" not in record.getMessage()
)
HTTP_LOGGER_CLASS = HttpAccessLogger
web.run_app(
self._app,
host=host,
port=port,
loop=asyncio.get_event_loop(),
access_log=HTTP_LOGGER,
print=started,
handle_signals=cb is None,
)
run_args = {
"host": host,
"port": port,
"loop": asyncio.get_event_loop(),
"access_log": HTTP_LOGGER,
"print": started,
"handle_signals": cb is None,
}
if HTTP_LOGGER_CLASS is not None:
run_args["access_log_class"] = HTTP_LOGGER_CLASS
web.run_app(self._app, **run_args)
if __name__ == "__main__":

View file

@ -1,4 +1,3 @@
import logging
from pathlib import Path, PurePosixPath
import magic
@ -6,11 +5,12 @@ from aiohttp import web
from aiohttp.web import Request, StreamResponse
from app.library.config import Config
from app.library.log import get_logger
from app.library.router import add_route
from app.library.Utils import get_file
MIME = magic.Magic(mime=True)
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
EXT_TO_MIME: dict[str, str] = {
".html": "text/html",
@ -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)}
)

View file

@ -1,5 +1,4 @@
import asyncio
import logging
from pathlib import Path
from typing import Any
from urllib.parse import unquote_plus
@ -14,10 +13,11 @@ from app.library.config import Config
from app.library.downloads import DownloadQueue
from app.library.encoder import Encoder
from app.library.Events import EventBus, Events
from app.library.log import get_logger
from app.library.router import route
from app.library.Utils import delete_dir, get_file, get_file_sidecar, get_files, get_mime_type, move_file, rename_file
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
@route("GET", "api/file/ffprobe/{file:.*}", "ffprobe")
@ -114,7 +114,12 @@ 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' because %s.",
file,
e,
extra={"route": "file_info", "file_path": file},
)
return web.json_response(data={"error": str(e)}, status=web.HTTPInternalServerError.status_code)
@ -196,7 +201,12 @@ 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' because %s.",
req_path,
e,
extra={"route": "file_browser", "request_path": req_path},
)
return web.json_response(data={"error": str(e)}, status=web.HTTPInternalServerError.status_code)
@ -229,7 +239,10 @@ async def path_actions(request: Request, config: Config, queue: DownloadQueue, n
data={"error": "Invalid parameters expecting list of dicts."}, status=web.HTTPBadRequest.status_code
)
except Exception as e:
LOG.exception(e)
LOG.debug(
"Ignoring invalid file browser actions JSON.",
extra={"route": "browser.file.actions", "error": str(e)},
)
return web.json_response(data={"error": "Invalid JSON."}, status=web.HTTPBadRequest.status_code)
# validate each action before performing any operations
@ -329,7 +342,13 @@ 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' because %s.",
action,
req_path,
e,
extra={"route": "browser.file.actions", "action": action, "request_path": req_path},
)
record(req_path, ok=False, error=str(e), action=action, extra={"item": params})
continue
@ -368,9 +387,26 @@ 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' because %s.",
new_dir,
e,
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 +425,36 @@ 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' because %s.",
path.relative_to(config.download_path),
e,
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 +488,22 @@ 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' because %s.",
path.relative_to(config.download_path),
e,
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 +554,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 +561,30 @@ 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' because %s.",
path.relative_to(config.download_path),
e,
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 +682,34 @@ 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(
"Started streaming a ZIP download with %d file(s).",
len(files),
extra={"route": "browser.download.stream", "token": token, "file_count": len(files)},
)
for chunk in zs:
if request.transport is None or request.transport.is_closing():
LOG.info("Client disconnected, aborting zip download.")
LOG.info(
"Stopped streaming the ZIP download because the client disconnected.",
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(
"Stopped streaming the ZIP download because the client cancelled it.",
extra={"route": "browser.download.stream", "token": token},
)
except Exception as e:
LOG.error(f"Streaming zip download error. {type(e).__name__}: {e}")
LOG.exception(
"Failed to stream the ZIP download.",
extra={
"route": "browser.download.stream",
"token": token,
"file_count": len(files),
"exception_type": type(e).__name__,
},
)
return response

View file

@ -1,14 +1,14 @@
import asyncio
import logging
from aiohttp import web
from aiohttp.web import Response
from app.library.config import Config
from app.library.encoder import Encoder
from app.library.log import get_logger
from app.library.router import route
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
@route("GET", "api/dev/loop/", "debug_loop")

View file

@ -1,4 +1,3 @@
import logging
import time
from datetime import UTC, datetime
@ -9,9 +8,10 @@ from app.features.ytdlp.ytdlp_opts import YTDLPOpts
from app.library.cache import Cache
from app.library.config import Config
from app.library.httpx_client import Globals, build_request_headers, get_async_client, resolve_curl_transport
from app.library.log import get_logger
from app.library.router import add_route, route
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
STATIC_FILES = ["README.md", "FAQ.md", "API.md", "sc_short.jpg", "sc_simple.jpg"]
EXT_TO_MIME: dict = {
@ -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)

View file

@ -1,13 +1,12 @@
import logging
from aiohttp import web
from aiohttp.web import Request, Response
from app.library.config import Config
from app.library.log import get_logger
from app.library.router import route
from app.library.Utils import get_file
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
@route(["GET", "HEAD"], "/api/download/{filename:.+}", "download_static")
@ -43,8 +42,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,

View file

@ -1,5 +1,4 @@
import asyncio
import logging
from pathlib import Path
from typing import TYPE_CHECKING, Any
@ -17,6 +16,7 @@ from app.library.downloads.utils import safe_relative_path
from app.library.encoder import Encoder
from app.library.Events import EventBus, Events
from app.library.ItemDTO import Item
from app.library.log import get_logger
from app.library.router import route
from app.library.Utils import calc_download_path, get_file_sidecar, rename_file
@ -24,7 +24,7 @@ if TYPE_CHECKING:
from library.downloads import Download
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
@route("GET", r"api/history/", "items_list")
@ -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,12 @@ 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 history item '%s' field '%s'.",
item.info.id,
k,
extra={"route": "history.item_update", "item_id": item.info.id, "field": k, "value": v},
)
if updated:
await queue.done.put(item)
@ -861,7 +889,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,

View file

@ -1,4 +1,3 @@
import logging
import random
from typing import Any
from urllib.parse import urlparse, urlsplit, urlunsplit
@ -11,9 +10,10 @@ from app.library.ag_utils import ag
from app.library.cache import Cache
from app.library.config import Config
from app.library.httpx_client import Globals, build_request_headers, get_async_client, resolve_curl_transport
from app.library.log import get_logger
from app.library.router import route
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
IS_REQUESTING_BACKGROUND: bool = False
@ -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,

View file

@ -1,6 +1,5 @@
import asyncio
import json
import logging
import os
from pathlib import Path
@ -9,9 +8,16 @@ from aiohttp.web import Request, Response
from app.library.config import Config
from app.library.encoder import Encoder
from app.library.log import get_logger
from app.library.log_control import (
SUPPORTED_LOG_LEVELS,
get_runtime_log_level,
normalize_log_level,
set_runtime_log_level,
)
from app.library.router import route
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
def _parse_jsonl_line(line: bytes | str) -> dict | None:
@ -130,8 +136,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
@ -176,6 +182,40 @@ async def logs(request: Request, config: Config, encoder: Encoder) -> Response:
)
@route("GET", "api/logs/level", "logs.level")
async def get_logs_level(config: Config, encoder: Encoder) -> Response:
configured = normalize_log_level(config.log_level)
active = get_runtime_log_level()
return web.json_response(
data={
"conf": configured,
"active": active,
"levels": list(SUPPORTED_LOG_LEVELS),
},
status=web.HTTPOk.status_code,
dumps=encoder.encode,
)
@route("POST", "api/logs/level/{level}", "logs.level.set")
async def set_logs_level(request: Request) -> Response:
if not (level := request.match_info.get("level")):
return web.json_response(
{"error": "Log level is required."},
status=web.HTTPBadRequest.status_code,
)
try:
set_runtime_log_level(level)
except ValueError as e:
return web.json_response(
{"error": f"{e!s} Available levels: {', '.join(SUPPORTED_LOG_LEVELS)}."},
status=web.HTTPBadRequest.status_code,
)
return web.Response(status=web.HTTPNoContent.status_code)
@route("GET", "api/logs/stream", "logs.stream")
async def stream_logs(request: Request, config: Config, encoder: Encoder) -> Response | web.StreamResponse:
if not config.file_logging:
@ -215,7 +255,6 @@ async def stream_logs(request: Request, config: Config, encoder: Encoder) -> Res
)
try:
LOG.debug("Log streaming connected.")
while not log_task.done():
await asyncio.sleep(1.0)
if request.transport is None or request.transport.is_closing():
@ -225,7 +264,6 @@ async def stream_logs(request: Request, config: Config, encoder: Encoder) -> Res
except asyncio.CancelledError:
pass
finally:
LOG.debug("Log streaming disconnected.")
try:
await response.write_eof()
except ConnectionResetError:

View file

@ -1,5 +1,4 @@
import asyncio
import logging
import os
import time
from pathlib import Path
@ -17,12 +16,13 @@ from app.library.downloads import DownloadQueue
from app.library.downloads.core import Download
from app.library.encoder import Encoder
from app.library.Events import EventBus, Events
from app.library.log import get_logger
from app.library.router import route
from app.library.TerminalSessionManager import TerminalSessionConflictError, TerminalSessionManager
from app.library.UpdateChecker import UpdateChecker
from app.library.Utils import list_folders
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
DIAGNOSTICS_CACHE_KEY = "system:diagnostics"
DIAGNOSTICS_CACHE_TTL = 5.0
@ -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)

View file

@ -1,9 +1,8 @@
import logging
from app.library.Events import EventBus, Events
from app.library.log import get_logger
from app.library.router import RouteType, route
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
@route(RouteType.SOCKET, "connect", "socket_connect")

View file

@ -1,11 +1,10 @@
import logging
from app.library.downloads import DownloadQueue
from app.library.Events import EventBus, Events
from app.library.ItemDTO import Item
from app.library.log import get_logger
from app.library.router import RouteType, route
LOG: logging.Logger = logging.getLogger(__name__)
LOG = get_logger()
@route(RouteType.SOCKET, "add_url", "add_url")
@ -26,7 +25,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)

View file

@ -23,11 +23,12 @@ if APP_ROOT not in sys.path:
from app.library.DataStore import StoreType
from app.library.encoder import Encoder
from app.library.log import get_logger
if TYPE_CHECKING:
from collections.abc import Iterable, Iterator, Sequence
LOG = logging.getLogger("seed_db")
LOG = get_logger()
USED_IDS: set[str] = set()

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"

View file

@ -65,7 +65,13 @@ 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
and record.getMessage().startswith("Failed to request random background image")
)
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"

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

View file

@ -12,7 +12,9 @@ from pathlib import Path
from library.PackageInstaller import PackageInstaller, Packages
LOG: logging.Logger = logging.getLogger("upgrader")
from app.library.log import get_logger
LOG = get_logger()
class Upgrader:
@ -24,14 +26,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 +57,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 +96,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 +126,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__":

View file

@ -33,6 +33,8 @@ const state = reactive<ConfigState>({
app_env: 'production',
simple_mode: false,
default_pagination: 50,
log_level: '',
runtime_log_level: '',
check_for_updates: true,
new_version: '',
yt_new_version: '',

View file

@ -79,19 +79,17 @@
:description="requiredAlertDescription"
/>
<section class="rounded-md border border-default bg-default shadow-sm">
<div class="border-b border-default px-4 py-3 sm:px-5">
<div class="flex items-center gap-2 text-sm font-semibold text-highlighted">
<UIcon name="i-lucide-gauge" class="size-4 text-toned" />
<span>Overview</span>
</div>
<section class="space-y-3">
<div class="flex items-center gap-2 text-sm font-semibold text-highlighted">
<UIcon name="i-lucide-gauge" class="size-4 text-toned" />
<span>Overview</span>
</div>
<div class="grid gap-3 p-4 sm:grid-cols-2 sm:p-5 xl:grid-cols-4">
<div class="grid gap-3 sm:grid-cols-2 xl:grid-cols-4">
<article
v-for="item in summaryCards"
:key="item.label"
class="rounded-md border border-default bg-muted/20 px-3 py-3"
class="rounded-md border border-default bg-default px-3 py-3 shadow-sm"
>
<div class="flex items-start justify-between gap-3">
<div class="min-w-0">
@ -113,35 +111,34 @@
</div>
</section>
<section class="rounded-md border border-default bg-default shadow-sm">
<div class="border-b border-default px-4 py-3 sm:px-5">
<div class="flex items-center gap-2 text-sm font-semibold text-highlighted">
<UIcon name="i-lucide-server" class="size-4 text-toned" />
<span>Runtime</span>
</div>
<section class="space-y-3">
<div class="flex items-center gap-2 text-sm font-semibold text-highlighted">
<UIcon name="i-lucide-server" class="size-4 text-toned" />
<span>Runtime</span>
</div>
<div class="grid gap-3 p-4 sm:grid-cols-2 sm:p-5 xl:grid-cols-3">
<div class="grid gap-3 sm:grid-cols-2 xl:grid-cols-3">
<article
v-for="row in runtimeRows"
:key="row.label"
class="rounded-md border border-default bg-muted/20 px-3 py-3"
class="rounded-md border border-default bg-default px-3 py-3 shadow-sm"
>
<div class="flex items-start gap-3">
<div class="flex items-start justify-between gap-3">
<div class="min-w-0">
<p class="text-xs font-medium uppercase tracking-wide text-toned">
{{ row.label }}
</p>
<p class="mt-1 text-xs text-toned">{{ row.description }}</p>
</div>
<span
class="inline-flex size-8 shrink-0 items-center justify-center rounded-md border border-default bg-default"
>
<UIcon :name="row.icon" class="size-4 text-toned" />
</span>
<div class="min-w-0">
<p class="text-xs font-medium uppercase tracking-wide text-toned">
{{ row.label }}
</p>
<p class="mt-2 text-sm font-semibold text-default">{{ row.value }}</p>
<p class="mt-1 text-xs text-toned">{{ row.description }}</p>
</div>
</div>
<p class="mt-4 wrap-break-word text-sm font-semibold text-default">{{ row.value }}</p>
</article>
</div>
</section>
@ -155,27 +152,19 @@
</div>
<p class="text-sm text-toned">{{ section.description }}</p>
</div>
<div class="flex flex-wrap gap-2 text-xs text-toned">
<span class="inline-flex items-center gap-1 rounded-md border border-default px-2 py-1">
<span class="font-medium text-default">Checks:</span>
<span>{{ section.items.length }}</span>
</span>
<span class="inline-flex items-center gap-1 rounded-md border border-default px-2 py-1">
<span class="font-medium text-default">Required fails:</span>
<span>{{ requiredFails(section.items) }}</span>
</span>
</div>
</div>
<div class="grid gap-4 lg:grid-cols-2 2xl:grid-cols-3">
<article v-for="item in section.items" :key="item.id" :class="cardClass(item.status)">
<article
v-for="item in section.items"
:key="item.id"
class="rounded-md border border-default bg-default px-4 py-4 shadow-sm"
>
<div class="min-w-0 space-y-3">
<div class="space-y-2">
<div class="flex flex-wrap items-center gap-2">
<span :class="tagDotClass(item.status)"></span>
<p class="text-base font-semibold text-default">{{ item.label }}</p>
<span :class="badgeClass(item.status)">{{ statusLabel(item.status) }}</span>
<span
class="inline-flex items-center rounded-md border border-default px-2 py-1 text-xs text-toned"
>
@ -334,7 +323,6 @@ const summaryCards = computed<Array<SummaryCard>>(() => {
const runtimeRows = computed<Array<DetailRow>>(() => {
const runtime = report.value?.runtime;
const generatedAt = report.value?.generated_at;
const python = report.value?.requirements.python;
if (!runtime || !python) {
@ -360,24 +348,6 @@ const runtimeRows = computed<Array<DetailRow>>(() => {
value: python.current,
icon: 'i-lucide-square-terminal',
},
{
label: 'Started',
description: 'Process start time.',
value: runtime.started ? moment.unix(runtime.started).fromNow() : 'Unknown',
icon: 'i-lucide-power',
},
{
label: 'Uptime',
description: 'Current process uptime.',
value: moment.duration(runtime.uptime_seconds, 'seconds').humanize(),
icon: 'i-lucide-timer',
},
{
label: 'Snapshot',
description: 'Diagnostics timestamp.',
value: generatedAt ? moment.unix(generatedAt).fromNow() : 'Unknown',
icon: 'i-lucide-clock-3',
},
];
});
@ -405,8 +375,6 @@ const shareText = computed(() => {
);
lines.push(`- Python: ${current.requirements.python.current}`);
lines.push(`- Started: ${formatIsoTimestamp(current.runtime.started)}`);
lines.push(`- Uptime: ${formatIsoDuration(current.runtime.uptime_seconds)}`);
lines.push(`- Snapshot: ${formatIsoTimestamp(current.generated_at)}`);
for (const section of featureSections.value) {
lines.push('', section.label);
@ -414,7 +382,7 @@ const shareText = computed(() => {
for (const item of section.items) {
const versionSuffix = formatShareVersion(item);
lines.push(
`- ${item.label} (${item.required ? 'Required' : 'Optional'}) (${statusLabel(item.status)})${versionSuffix}`,
`- [${statusLabel(item.status)}] ${item.label} (${item.required ? 'Required' : 'Optional'})${versionSuffix}`,
);
}
}
@ -434,10 +402,6 @@ const copyDiagnostics = (): void => {
copyText(shareText.value);
};
const requiredFails = (items: Array<DiagnosticCheck>): number => {
return items.filter((item) => item.required && item.status === 'fail').length;
};
const showMessage = (item: DiagnosticCheck): boolean => {
if (item.status === 'pass') {
return false;
@ -449,30 +413,14 @@ const showMessage = (item: DiagnosticCheck): boolean => {
const statusLabel = (status: DiagnosticStatus): string => {
switch (status) {
case 'pass':
return 'Pass';
return 'PASS';
case 'fail':
return 'Fail';
return 'FAIL';
case 'warn':
return 'Warn';
return 'WARN';
case 'skip':
default:
return 'Skip';
}
};
const cardClass = (status: DiagnosticStatus): string => {
const base = 'rounded-md border border-default bg-default px-4 py-4 shadow-sm ring-1 ring-inset';
switch (status) {
case 'pass':
return `${base} ring-success/10`;
case 'fail':
return `${base} ring-error/10`;
case 'warn':
return `${base} ring-warning/10`;
case 'skip':
default:
return `${base} ring-default/40`;
return 'SKIP';
}
};
@ -492,22 +440,6 @@ const tagDotClass = (status: DiagnosticStatus): string => {
}
};
const badgeClass = (status: DiagnosticStatus): string => {
const base = 'inline-flex items-center rounded-md border px-2 py-1 text-xs font-medium';
switch (status) {
case 'pass':
return `${base} border-success/30 bg-success/10 text-success`;
case 'fail':
return `${base} border-error/30 bg-error/10 text-error`;
case 'warn':
return `${base} border-warning/30 bg-warning/10 text-warning`;
case 'skip':
default:
return `${base} border-default bg-muted/40 text-toned`;
}
};
const formatValue = (value: DiagnosticCheck['details'][string]): string => {
if (value === null || value === undefined || value === '') {
return 'n/a';
@ -528,14 +460,6 @@ const formatIsoTimestamp = (value: number | undefined): string => {
return moment.unix(value).utc().format('YYYY-MM-DDTHH:mm:ss[Z]');
};
const formatIsoDuration = (value: number | undefined): string => {
if (typeof value !== 'number' || Number.isNaN(value)) {
return 'Unknown';
}
return moment.duration(value, 'seconds').toISOString();
};
const formatShareVersion = (item: DiagnosticCheck): string => {
const version = item.details?.version;
if (version === null || version === undefined || version === '') {

View file

@ -80,6 +80,19 @@
</template>
</USelect>
<UButton
color="neutral"
variant="outline"
size="sm"
icon="i-lucide-sliders-horizontal"
class="shrink-0"
:loading="runtimeLogLevelLoading"
:disabled="!canApplyRuntimeLogLevel || runtimeLogLevelLoading"
@click="applyRuntimeLogLevel"
>
Apply
</UButton>
<UInput
v-if="toggleFilter || query"
id="filter"
@ -170,7 +183,9 @@
{{ getLogLevel(entry.log.level) }}
</span>
<span
v-if="entry.log.logger"
v-if="
entry.log.logger && !['ytptube', 'http_api'].includes(entry.log.logger)
"
:title="entry.log.logger"
class="inline-block max-w-[46vw] truncate align-middle text-[11px] font-semibold text-toned sm:max-w-104"
>[{{ entry.log.logger }}]</span
@ -196,11 +211,11 @@
<div class="space-y-1">
<p class="text-sm font-medium text-default">
{{ emptyStateTitle }}
{{ hasActiveFilter ? 'No logs match these filters' : 'No log lines available' }}
</p>
<p class="text-sm text-toned">
{{ emptyStateDescription }}
{{ hasActiveFilter ? 'No logs match these filters' : 'No log lines available' }}
</p>
</div>
</div>
@ -425,6 +440,10 @@ const LOG_LEVEL_ICON: Record<LogLevel, string> = {
warning: 'i-lucide-triangle-alert',
error: 'i-lucide-circle-x',
};
const formatLogLevel = (level: LogLevel): string => level.charAt(0).toUpperCase() + level.slice(1);
const getStoredRuntimeLogLevel = (): LogLevel | null => {
return config.app.runtime_log_level ? getLogLevel(config.app.runtime_log_level) : null;
};
let scrollTimeout: NodeJS.Timeout | null = null;
@ -441,6 +460,8 @@ const rawJsonOpen = useStorage<boolean>('logs_raw_json_open', false);
const sourceOpen = useStorage<boolean>('logs_source_open', true);
const selectedLevels = useStorage<LogLevel[]>('logs_level_filter', [...LOG_LEVELS]);
const sseController = ref<AbortController | null>(null);
const runtimeLogLevel = ref<LogLevel | null>(null);
const runtimeLogLevelLoading = ref(false);
const logs = ref<Array<log_line>>([]);
const selectedLog = ref<log_line | null>(null);
@ -512,15 +533,39 @@ const levelCounts = computed<Record<LogLevel, number>>(() => {
return counts;
});
const levelFilterItems = computed<LevelFilterItem[]>(() => [
...LOG_LEVELS.map((level) => ({
label: `${level.charAt(0).toUpperCase()}${level.slice(1)} (${levelCounts.value[level]})`,
label: `${formatLogLevel(level)} (${levelCounts.value[level]})`,
value: level,
})),
]);
const runtimeLogLevelCandidate = computed<LogLevel | null>(() => {
for (const level of LOG_LEVELS) {
const thresholdLevels = LOG_LEVELS.slice(LOG_LEVELS.indexOf(level));
if (thresholdLevels.length !== selectedLevelSet.value.size) {
continue;
}
if (thresholdLevels.every((item) => selectedLevelSet.value.has(item))) {
return level;
}
}
return null;
});
const canApplyRuntimeLogLevel = computed(
() =>
runtimeLogLevelCandidate.value !== null &&
runtimeLogLevel.value !== null &&
runtimeLogLevelCandidate.value !== runtimeLogLevel.value,
);
const levelFilterLabel = computed(() => {
if (selectedLevelSet.value.size === LOG_LEVELS.length) {
return `All levels (${logs.value.length})`;
return `All levels`;
}
if (selectedLevelSet.value.size === 0) {
@ -529,29 +574,7 @@ const levelFilterLabel = computed(() => {
return LOG_LEVELS.filter((level) => selectedLevelSet.value.has(level)).join(', ');
});
const activeFilterLabel = computed(() => {
const parts: string[] = [];
if (hasTextFilter.value) {
parts.push(`query "${searchTerm.value}"`);
}
if (hasLevelFilter.value) {
const levels = LOG_LEVELS.filter((level) => selectedLevelSet.value.has(level));
parts.push(levels.length ? `levels ${levels.join(', ')}` : 'no selected levels');
}
return parts.join(' and ');
});
const emptyStateTitle = computed(() =>
hasActiveFilter.value ? 'No logs match these filters' : 'No log lines available',
);
const emptyStateDescription = computed(() => {
if (!hasActiveFilter.value) {
return 'No log lines are available yet.';
}
return `No loaded log lines match ${activeFilterLabel.value}. Adjust filters or load older lines.`;
});
watch(toggleFilter, () => {
if (!toggleFilter.value) {
query.value = '';
@ -718,6 +741,72 @@ const scrollToBottom = async (fast = false): Promise<void> => {
await scrollLogContainerToBottom(fast ? 'auto' : 'smooth');
};
const loadRuntimeLogLevel = async (): Promise<void> => {
try {
const response = await request('/api/logs/level');
if (!response.ok) {
runtimeLogLevel.value = getStoredRuntimeLogLevel();
return;
}
const data = await response.json();
if (typeof data.conf === 'string' && data.conf) {
config.app.log_level = getLogLevel(data.conf);
}
if (!config.app.log_level && getStoredRuntimeLogLevel() === null) {
runtimeLogLevel.value = null;
return;
}
if (typeof data.active === 'string' && data.active) {
const level = getLogLevel(data.active);
runtimeLogLevel.value = level;
config.app.runtime_log_level = level;
return;
}
runtimeLogLevel.value = getStoredRuntimeLogLevel();
} catch (error) {
runtimeLogLevel.value = getStoredRuntimeLogLevel();
console.error('Failed to load runtime log level:', error);
}
};
const applyRuntimeLogLevel = async (): Promise<void> => {
const normalized = runtimeLogLevelCandidate.value;
if (!normalized || runtimeLogLevel.value === null || normalized === runtimeLogLevel.value) {
return;
}
const previous = runtimeLogLevel.value;
try {
runtimeLogLevelLoading.value = true;
const response = await request(`/api/logs/level/${normalized}`, {
method: 'POST',
});
if (!response.ok) {
const data = await response.json();
const message = await parse_api_error(data);
runtimeLogLevel.value = previous;
toast.error(`Failed to change log level. ${message}`);
return;
}
runtimeLogLevel.value = normalized;
config.app.runtime_log_level = normalized;
toast.success('log level updated until next restart.');
} catch (error: any) {
runtimeLogLevel.value = previous;
const message = error?.message || 'Unknown error';
toast.error(`Failed to change log level. ${message}`);
} finally {
runtimeLogLevelLoading.value = false;
}
};
const handleStreamMessage = (event: EventSourceMessage): void => {
if (event.event !== 'log_lines' || !event.data) {
return;
@ -967,6 +1056,8 @@ onMounted(async () => {
return;
}
runtimeLogLevel.value = getStoredRuntimeLogLevel();
await loadRuntimeLogLevel();
await fetchLogs();
await startLogStream();
});

Some files were not shown because too many files have changed in this diff Show more