diff --git a/unshackle/commands/dl.py b/unshackle/commands/dl.py index 8b37032..cba5ee9 100644 --- a/unshackle/commands/dl.py +++ b/unshackle/commands/dl.py @@ -56,7 +56,8 @@ from unshackle.core.titles.episode import Episode from unshackle.core.tracks import Audio, Subtitle, Tracks, Video from unshackle.core.tracks.attachment import Attachment from unshackle.core.tracks.hybrid import Hybrid -from unshackle.core.utilities import get_system_fonts, is_close_match, time_elapsed_since +from unshackle.core.utilities import (get_debug_logger, get_system_fonts, init_debug_logger, is_close_match, + time_elapsed_since) from unshackle.core.utils import tags from unshackle.core.utils.click_types import (LANGUAGE_RANGE, QUALITY_LIST, SEASON_RANGE, ContextData, MultipleChoice, SubtitleCodecChoice, VideoCodecChoice) @@ -313,6 +314,40 @@ class dl: self.tmdb_name = tmdb_name self.tmdb_year = tmdb_year + # Initialize debug logger with service name if debug logging is enabled + if config.debug or logging.root.level == logging.DEBUG: + from collections import defaultdict + from datetime import datetime + + debug_log_path = config.directories.logs / config.filenames.debug_log.format_map( + defaultdict(str, service=self.service, time=datetime.now().strftime("%Y%m%d-%H%M%S")) + ) + init_debug_logger( + log_path=debug_log_path, + enabled=True, + log_keys=config.debug_keys + ) + self.debug_logger = get_debug_logger() + + if self.debug_logger: + self.debug_logger.log( + level="INFO", + operation="download_init", + message=f"Download command initialized for service {self.service}", + service=self.service, + context={ + "profile": profile, + "proxy": proxy, + "tag": tag, + "tmdb_id": tmdb_id, + "tmdb_name": tmdb_name, + "tmdb_year": tmdb_year, + "cli_params": {k: v for k, v in ctx.params.items() if k not in ['profile', 'proxy', 'tag', 'tmdb_id', 'tmdb_name', 'tmdb_year']} + } + ) + else: + self.debug_logger = None + if self.profile: self.log.info(f"Using profile: '{self.profile}'") @@ -321,6 +356,13 @@ class dl: if service_config_path.exists(): self.service_config = yaml.safe_load(service_config_path.read_text(encoding="utf8")) self.log.info("Service Config loaded") + if self.debug_logger: + self.debug_logger.log( + level="DEBUG", + operation="load_service_config", + service=self.service, + context={"config_path": str(service_config_path), "config": self.service_config} + ) else: self.service_config = {} merge_dict(config.services.get(self.service), self.service_config) @@ -384,18 +426,32 @@ class dl: self.cdm = self.get_cdm(self.service, self.profile) except ValueError as e: self.log.error(f"Failed to load CDM, {e}") + if self.debug_logger: + self.debug_logger.log_error("load_cdm", e, service=self.service) sys.exit(1) if self.cdm: + cdm_info = {} if isinstance(self.cdm, DecryptLabsRemoteCDM): drm_type = "PlayReady" if self.cdm.is_playready else "Widevine" self.log.info(f"Loaded {drm_type} Remote CDM: DecryptLabs (L{self.cdm.security_level})") + cdm_info = {"type": "DecryptLabs", "drm_type": drm_type, "security_level": self.cdm.security_level} elif hasattr(self.cdm, "device_type") and self.cdm.device_type.name in ["ANDROID", "CHROME"]: self.log.info(f"Loaded Widevine CDM: {self.cdm.system_id} (L{self.cdm.security_level})") + cdm_info = {"type": "Widevine", "system_id": self.cdm.system_id, "security_level": self.cdm.security_level, "device_type": self.cdm.device_type.name} else: self.log.info( f"Loaded PlayReady CDM: {self.cdm.certificate_chain.get_name()} (L{self.cdm.security_level})" ) + cdm_info = {"type": "PlayReady", "certificate": self.cdm.certificate_chain.get_name(), "security_level": self.cdm.security_level} + + if self.debug_logger and cdm_info: + self.debug_logger.log( + level="INFO", + operation="load_cdm", + service=self.service, + context={"cdm": cdm_info} + ) self.proxy_providers = [] if no_proxy: @@ -521,18 +577,83 @@ class dl: else: vaults_only = not cdm_only + if self.debug_logger: + self.debug_logger.log( + level="DEBUG", + operation="drm_mode_config", + service=self.service, + context={ + "cdm_only": cdm_only, + "vaults_only": vaults_only, + "mode": "CDM only" if cdm_only else ("Vaults only" if vaults_only else "Both CDM and Vaults") + } + ) + with console.status("Authenticating with Service...", spinner="dots"): - cookies = self.get_cookie_jar(self.service, self.profile) - credential = self.get_credentials(self.service, self.profile) - service.authenticate(cookies, credential) - if cookies or credential: - self.log.info("Authenticated with Service") + try: + cookies = self.get_cookie_jar(self.service, self.profile) + credential = self.get_credentials(self.service, self.profile) + service.authenticate(cookies, credential) + if cookies or credential: + self.log.info("Authenticated with Service") + if self.debug_logger: + self.debug_logger.log( + level="INFO", + operation="authenticate", + service=self.service, + context={ + "has_cookies": bool(cookies), + "has_credentials": bool(credential), + "profile": self.profile + } + ) + except Exception as e: + if self.debug_logger: + self.debug_logger.log_error( + "authenticate", + e, + service=self.service, + context={"profile": self.profile} + ) + raise with console.status("Fetching Title Metadata...", spinner="dots"): - titles = service.get_titles_cached() - if not titles: - self.log.error("No titles returned, nothing to download...") - sys.exit(1) + try: + titles = service.get_titles_cached() + if not titles: + self.log.error("No titles returned, nothing to download...") + if self.debug_logger: + self.debug_logger.log( + level="ERROR", + operation="get_titles", + service=self.service, + message="No titles returned from service", + success=False + ) + sys.exit(1) + except Exception as e: + if self.debug_logger: + self.debug_logger.log_error( + "get_titles", + e, + service=self.service + ) + raise + + if self.debug_logger: + titles_info = { + "type": titles.__class__.__name__, + "count": len(titles) if hasattr(titles, "__len__") else 1, + "title": str(titles) + } + if hasattr(titles, "seasons"): + titles_info["seasons"] = len(titles.seasons) if hasattr(titles, "seasons") else 0 + self.debug_logger.log( + level="INFO", + operation="get_titles", + service=self.service, + context={"titles": titles_info} + ) if self.tmdb_year and self.tmdb_id: sample_title = titles[0] if hasattr(titles, "__getitem__") else titles @@ -621,8 +742,55 @@ class dl: title.tracks.subtitles = [] with console.status("Getting tracks...", spinner="dots"): - title.tracks.add(service.get_tracks(title), warn_only=True) - title.tracks.chapters = service.get_chapters(title) + try: + title.tracks.add(service.get_tracks(title), warn_only=True) + title.tracks.chapters = service.get_chapters(title) + except Exception as e: + if self.debug_logger: + self.debug_logger.log_error( + "get_tracks", + e, + service=self.service, + context={"title": str(title)} + ) + raise + + if self.debug_logger: + tracks_info = { + "title": str(title), + "video_tracks": len(title.tracks.videos), + "audio_tracks": len(title.tracks.audio), + "subtitle_tracks": len(title.tracks.subtitles), + "has_chapters": bool(title.tracks.chapters), + "videos": [{ + "codec": str(v.codec), + "resolution": f"{v.width}x{v.height}" if v.width and v.height else "unknown", + "bitrate": v.bitrate, + "range": str(v.range), + "language": str(v.language) if v.language else None, + "drm": [str(type(d).__name__) for d in v.drm] if v.drm else [] + } for v in title.tracks.videos], + "audio": [{ + "codec": str(a.codec), + "bitrate": a.bitrate, + "channels": a.channels, + "language": str(a.language) if a.language else None, + "descriptive": a.descriptive, + "drm": [str(type(d).__name__) for d in a.drm] if a.drm else [] + } for a in title.tracks.audio], + "subtitles": [{ + "codec": str(s.codec), + "language": str(s.language) if s.language else None, + "forced": s.forced, + "sdh": s.sdh + } for s in title.tracks.subtitles] + } + self.debug_logger.log( + level="INFO", + operation="get_tracks", + service=self.service, + context=tracks_info + ) # strip SDH subs to non-SDH if no equivalent same-lang non-SDH is available # uses a loose check, e.g, wont strip en-US SDH sub if a non-SDH en-GB is available @@ -1009,6 +1177,14 @@ class dl: download.result() except KeyboardInterrupt: console.print(Padding(":x: Download Cancelled...", (0, 5, 1, 5))) + if self.debug_logger: + self.debug_logger.log( + level="WARNING", + operation="download_tracks", + service=self.service, + message="Download cancelled by user", + context={"title": str(title)} + ) return except Exception as e: # noqa error_messages = [ @@ -1031,6 +1207,19 @@ class dl: # CalledProcessError already lists the exception trace console.print_exception() console.print(Padding(Group(*error_messages), (1, 5))) + + if self.debug_logger: + self.debug_logger.log_error( + "download_tracks", + e, + service=self.service, + context={ + "title": str(title), + "error_type": type(e).__name__, + "tracks_count": len(title.tracks), + "returncode": getattr(e, "returncode", None) + } + ) return if skip_dl: @@ -1106,11 +1295,11 @@ class dl: if family_dir.exists(): fonts = family_dir.glob("*.*tf") for font in fonts: - title.tracks.add(Attachment(font, f"{font_name} ({font.stem})")) + title.tracks.add(Attachment(path=font, name=f"{font_name} ({font.stem})")) font_count += 1 elif fonts_from_system: for font in fonts_from_system: - title.tracks.add(Attachment(font, f"{font_name} ({font.stem})")) + title.tracks.add(Attachment(path=font, name=f"{font_name} ({font.stem})")) font_count += 1 else: self.log.warning(f"Subtitle uses font [text2]{font_name}[/] but it could not be found...") @@ -1394,6 +1583,20 @@ class dl: self.cdm = playready_cdm if isinstance(drm, Widevine): + if self.debug_logger: + self.debug_logger.log_drm_operation( + drm_type="Widevine", + operation="prepare_drm", + service=self.service, + context={ + "track": str(track), + "title": str(title), + "pssh": drm.pssh.dumps() if drm.pssh else None, + "kids": [k.hex for k in drm.kids], + "track_kid": track_kid.hex if track_kid else None + } + ) + with self.DRM_TABLE_LOCK: pssh_display = self._truncate_pssh_for_display(drm.pssh.dumps(), "Widevine") cek_tree = Tree(Text.assemble(("Widevine", "cyan"), (f"({pssh_display})", "text"), overflow="fold")) @@ -1422,11 +1625,32 @@ class dl: if not any(f"{kid.hex}:{content_key}" in x.label for x in cek_tree.children): cek_tree.add(label) self.vaults.add_key(kid, content_key, excluding=vault_used) + + if self.debug_logger: + self.debug_logger.log_vault_query( + vault_name=vault_used, + operation="get_key_success", + service=self.service, + context={ + "kid": kid.hex, + "content_key": content_key, + "track": str(track), + "from_cache": True + } + ) elif vaults_only: msg = f"No Vault has a Key for {kid.hex} and --vaults-only was used" cek_tree.add(f"[logging.level.error]{msg}") if not pre_existing_tree: table.add_row(cek_tree) + if self.debug_logger: + self.debug_logger.log( + level="ERROR", + operation="vault_key_not_found", + service=self.service, + message=msg, + context={"kid": kid.hex, "track": str(track)} + ) raise Widevine.Exceptions.CEKNotFound(msg) else: need_license = True @@ -1437,6 +1661,18 @@ class dl: if need_license and not vaults_only: from_vaults = drm.content_keys.copy() + if self.debug_logger: + self.debug_logger.log( + level="INFO", + operation="get_license", + service=self.service, + message="Requesting Widevine license from service", + context={ + "track": str(track), + "kids_needed": [k.hex for k in all_kids if k not in drm.content_keys] + } + ) + try: if self.service == "NF": drm.get_NF_content_keys(cdm=self.cdm, licence=licence, certificate=certificate) @@ -1450,8 +1686,30 @@ class dl: cek_tree.add(f"[logging.level.error]{msg}") if not pre_existing_tree: table.add_row(cek_tree) + if self.debug_logger: + self.debug_logger.log_error( + "get_license", + e, + service=self.service, + context={ + "track": str(track), + "exception_type": type(e).__name__ + } + ) raise e + if self.debug_logger: + self.debug_logger.log( + level="INFO", + operation="license_keys_retrieved", + service=self.service, + context={ + "track": str(track), + "keys_count": len(drm.content_keys), + "kids": [k.hex for k in drm.content_keys.keys()] + } + ) + for kid_, key in drm.content_keys.items(): if key == "0" * 32: key = f"[red]{key}[/]" @@ -1497,6 +1755,20 @@ class dl: export.write_text(jsonpickle.dumps(keys, indent=4), encoding="utf8") elif isinstance(drm, PlayReady): + if self.debug_logger: + self.debug_logger.log_drm_operation( + drm_type="PlayReady", + operation="prepare_drm", + service=self.service, + context={ + "track": str(track), + "title": str(title), + "pssh": drm.pssh_b64 or "", + "kids": [k.hex for k in drm.kids], + "track_kid": track_kid.hex if track_kid else None + } + ) + with self.DRM_TABLE_LOCK: pssh_display = self._truncate_pssh_for_display(drm.pssh_b64 or "", "PlayReady") cek_tree = Tree( @@ -1531,11 +1803,33 @@ class dl: if not any(f"{kid.hex}:{content_key}" in x.label for x in cek_tree.children): cek_tree.add(label) self.vaults.add_key(kid, content_key, excluding=vault_used) + + if self.debug_logger: + self.debug_logger.log_vault_query( + vault_name=vault_used, + operation="get_key_success", + service=self.service, + context={ + "kid": kid.hex, + "content_key": content_key, + "track": str(track), + "from_cache": True, + "drm_type": "PlayReady" + } + ) elif vaults_only: msg = f"No Vault has a Key for {kid.hex} and --vaults-only was used" cek_tree.add(f"[logging.level.error]{msg}") if not pre_existing_tree: table.add_row(cek_tree) + if self.debug_logger: + self.debug_logger.log( + level="ERROR", + operation="vault_key_not_found", + service=self.service, + message=msg, + context={"kid": kid.hex, "track": str(track), "drm_type": "PlayReady"} + ) raise PlayReady.Exceptions.CEKNotFound(msg) else: need_license = True @@ -1556,6 +1850,17 @@ class dl: cek_tree.add(f"[logging.level.error]{msg}") if not pre_existing_tree: table.add_row(cek_tree) + if self.debug_logger: + self.debug_logger.log_error( + "get_license_playready", + e, + service=self.service, + context={ + "track": str(track), + "exception_type": type(e).__name__, + "drm_type": "PlayReady" + } + ) raise e for kid_, key in drm.content_keys.items(): diff --git a/unshackle/core/__main__.py b/unshackle/core/__main__.py index e4717fa..6cf2fac 100644 --- a/unshackle/core/__main__.py +++ b/unshackle/core/__main__.py @@ -1,6 +1,5 @@ import atexit import logging -from pathlib import Path import click import urllib3 @@ -16,23 +15,16 @@ from unshackle.core.config import config from unshackle.core.console import ComfyRichHandler, console from unshackle.core.constants import context_settings from unshackle.core.update_checker import UpdateChecker -from unshackle.core.utilities import rotate_log_file - -LOGGING_PATH = None +from unshackle.core.utilities import close_debug_logger, init_debug_logger @click.command(cls=Commands, invoke_without_command=True, context_settings=context_settings) @click.option("-v", "--version", is_flag=True, default=False, help="Print version information.") -@click.option("-d", "--debug", is_flag=True, default=False, help="Enable DEBUG level logs.") -@click.option( - "--log", - "log_path", - type=Path, - default=config.directories.logs / config.filenames.log, - help="Log path (or filename). Path can contain the following f-string args: {name} {time}.", -) -def main(version: bool, debug: bool, log_path: Path) -> None: +@click.option("-d", "--debug", is_flag=True, default=False, help="Enable DEBUG level logs and JSON debug logging.") +def main(version: bool, debug: bool) -> None: """unshackle—Modular Movie, TV, and Music Archival Software.""" + debug_logging_enabled = debug or config.debug + logging.basicConfig( level=logging.DEBUG if debug else logging.INFO, format="%(message)s", @@ -48,11 +40,8 @@ def main(version: bool, debug: bool, log_path: Path) -> None: ], ) - if log_path: - global LOGGING_PATH - console.record = True - new_log_path = rotate_log_file(log_path) - LOGGING_PATH = new_log_path + if debug_logging_enabled: + init_debug_logger(enabled=True) urllib3.disable_warnings(InsecureRequestWarning) @@ -98,10 +87,9 @@ def main(version: bool, debug: bool, log_path: Path) -> None: @atexit.register -def save_log(): - if console.record and LOGGING_PATH: - # TODO: Currently semi-bust. Everything that refreshes gets duplicated. - console.save_text(LOGGING_PATH) +def cleanup(): + """Clean up resources on exit.""" + close_debug_logger() if __name__ == "__main__": diff --git a/unshackle/core/config.py b/unshackle/core/config.py index 79483ce..6ac5f29 100644 --- a/unshackle/core/config.py +++ b/unshackle/core/config.py @@ -31,6 +31,7 @@ class Config: class _Filenames: # default filenames, do not modify here, set via config log = "unshackle_{name}_{time}.log" # Directories.logs + debug_log = "unshackle_debug_{service}_{time}.jsonl" # Directories.logs config = "config.yaml" # Directories.services / tag root_config = "unshackle.yaml" # Directories.user_configs chapters = "Chapters_{title}_{random}.txt" # Directories.temp @@ -98,6 +99,9 @@ class Config: self.title_cache_max_retention: int = kwargs.get("title_cache_max_retention", 86400) # 24 hours default self.title_cache_enabled: bool = kwargs.get("title_cache_enabled", True) + self.debug: bool = kwargs.get("debug", False) + self.debug_keys: bool = kwargs.get("debug_keys", False) + @classmethod def from_yaml(cls, path: Path) -> Config: if not path.exists(): diff --git a/unshackle/core/utilities.py b/unshackle/core/utilities.py index 9302e0d..d97e9bd 100644 --- a/unshackle/core/utilities.py +++ b/unshackle/core/utilities.py @@ -1,19 +1,22 @@ import ast import contextlib import importlib.util +import json import logging import os import re import socket import sys import time +import traceback import unicodedata from collections import defaultdict -from datetime import datetime +from datetime import datetime, timezone from pathlib import Path from types import ModuleType -from typing import Optional, Sequence, Union +from typing import Any, Optional, Sequence, Union from urllib.parse import ParseResult, urlparse +from uuid import uuid4 import chardet import requests @@ -122,7 +125,7 @@ def is_exact_match(language: Union[str, Language], languages: Sequence[Union[str return closest_match(language, list(map(str, languages)))[1] <= LANGUAGE_EXACT_DISTANCE -def get_boxes(data: bytes, box_type: bytes, as_bytes: bool = False) -> Box: +def get_boxes(data: bytes, box_type: bytes, as_bytes: bool = False) -> Box: # type: ignore """ Scan a byte array for a wanted MP4/ISOBMFF box, then parse and yield each find. @@ -457,3 +460,334 @@ class FPS(ast.NodeVisitor): @classmethod def parse(cls, expr: str) -> float: return cls().visit(ast.parse(expr).body[0]) + + +""" +Structured JSON debug logging for unshackle. + +Provides comprehensive debugging information for service developers and troubleshooting. +When enabled, logs all operations, requests, responses, DRM operations, and errors in JSON format. +""" + + +class DebugLogger: + """ + Structured JSON debug logger for unshackle. + + Outputs JSON Lines format where each line is a complete JSON object. + This makes it easy to parse, filter, and analyze logs programmatically. + """ + + def __init__(self, log_path: Optional[Path] = None, enabled: bool = False, log_keys: bool = False): + """ + Initialize the debug logger. + + Args: + log_path: Path to the log file. If None, logging is disabled. + enabled: Whether debug logging is enabled. + log_keys: Whether to log decryption keys (for debugging key issues). + """ + self.enabled = enabled and log_path is not None + self.log_path = log_path + self.session_id = str(uuid4())[:8] + self.file_handle = None + self.log_keys = log_keys + + if self.enabled: + self.log_path.parent.mkdir(parents=True, exist_ok=True) + self.file_handle = open(self.log_path, "a", encoding="utf-8") + self._log_session_start() + + def _log_session_start(self): + """Log the start of a new session with environment information.""" + import platform + + from unshackle.core import __version__ + + self.log( + level="INFO", + operation="session_start", + message="Debug logging session started", + context={ + "unshackle_version": __version__, + "python_version": sys.version, + "platform": platform.platform(), + "platform_system": platform.system(), + "platform_release": platform.release(), + }, + ) + + def log( + self, + level: str = "DEBUG", + operation: str = "", + message: str = "", + context: Optional[dict[str, Any]] = None, + service: Optional[str] = None, + error: Optional[Exception] = None, + request: Optional[dict[str, Any]] = None, + response: Optional[dict[str, Any]] = None, + duration_ms: Optional[float] = None, + success: Optional[bool] = None, + **kwargs, + ): + """ + Log a structured JSON entry. + + Args: + level: Log level (DEBUG, INFO, WARNING, ERROR) + operation: Name of the operation being performed + message: Human-readable message + context: Additional context information + service: Service name (e.g., DSNP, NF) + error: Exception object if an error occurred + request: Request details (URL, method, headers, body) + response: Response details (status, headers, body) + duration_ms: Operation duration in milliseconds + success: Whether the operation succeeded + **kwargs: Additional fields to include in the log entry + """ + if not self.enabled or not self.file_handle: + return + + entry = { + "timestamp": datetime.now(timezone.utc).isoformat(), + "session_id": self.session_id, + "level": level, + } + + if operation: + entry["operation"] = operation + if message: + entry["message"] = message + if service: + entry["service"] = service + if context: + entry["context"] = self._sanitize_data(context) + if request: + entry["request"] = self._sanitize_data(request) + if response: + entry["response"] = self._sanitize_data(response) + if duration_ms is not None: + entry["duration_ms"] = duration_ms + if success is not None: + entry["success"] = success + + if error: + entry["error"] = { + "type": type(error).__name__, + "message": str(error), + "traceback": traceback.format_exception(type(error), error, error.__traceback__), + } + + for key, value in kwargs.items(): + if key not in entry: + entry[key] = self._sanitize_data(value) + + try: + self.file_handle.write(json.dumps(entry, default=str) + "\n") + self.file_handle.flush() + except Exception as e: + print(f"Failed to write debug log: {e}", file=sys.stderr) + + def _sanitize_data(self, data: Any) -> Any: + """ + Sanitize data for JSON serialization. + Handles complex objects and removes sensitive information. + """ + if data is None: + return None + + if isinstance(data, (str, int, float, bool)): + return data + + if isinstance(data, (list, tuple)): + return [self._sanitize_data(item) for item in data] + + if isinstance(data, dict): + sanitized = {} + for key, value in data.items(): + key_lower = str(key).lower() + has_prefix = key_lower.startswith("has_") + + is_always_sensitive = not has_prefix and any( + sensitive in key_lower for sensitive in ["password", "token", "secret", "auth", "cookie"] + ) + + is_key_field = ( + "key" in key_lower + and not has_prefix + and not any(safe in key_lower for safe in ["_count", "_id", "_type", "kid", "keys_", "key_found"]) + ) + + should_redact = is_always_sensitive or (is_key_field and not self.log_keys) + + if should_redact: + sanitized[key] = "[REDACTED]" + else: + sanitized[key] = self._sanitize_data(value) + return sanitized + + if isinstance(data, bytes): + try: + return data.hex() + except Exception: + return "[BINARY_DATA]" + + if isinstance(data, Path): + return str(data) + + try: + return str(data) + except Exception: + return f"[{type(data).__name__}]" + + def log_operation_start(self, operation: str, **kwargs) -> str: + """ + Log the start of an operation and return an operation ID. + + Args: + operation: Name of the operation + **kwargs: Additional context + + Returns: + Operation ID that can be used to log the end of the operation + """ + op_id = str(uuid4())[:8] + self.log( + level="DEBUG", + operation=f"{operation}_start", + message=f"Starting operation: {operation}", + operation_id=op_id, + **kwargs, + ) + return op_id + + def log_operation_end( + self, operation: str, operation_id: str, success: bool = True, duration_ms: Optional[float] = None, **kwargs + ): + """ + Log the end of an operation. + + Args: + operation: Name of the operation + operation_id: Operation ID from log_operation_start + success: Whether the operation succeeded + duration_ms: Operation duration in milliseconds + **kwargs: Additional context + """ + self.log( + level="INFO" if success else "ERROR", + operation=f"{operation}_end", + message=f"Finished operation: {operation}", + operation_id=operation_id, + success=success, + duration_ms=duration_ms, + **kwargs, + ) + + def log_service_call(self, method: str, url: str, **kwargs): + """ + Log a service API call. + + Args: + method: HTTP method (GET, POST, etc.) + url: Request URL + **kwargs: Additional request details (headers, body, etc.) + """ + self.log(level="DEBUG", operation="service_call", request={"method": method, "url": url, **kwargs}) + + def log_drm_operation(self, drm_type: str, operation: str, **kwargs): + """ + Log a DRM operation (PSSH extraction, license request, key retrieval). + + Args: + drm_type: DRM type (Widevine, PlayReady, etc.) + operation: DRM operation name + **kwargs: Additional context (PSSH, KIDs, keys, etc.) + """ + self.log( + level="DEBUG", operation=f"drm_{operation}", message=f"{drm_type} {operation}", drm_type=drm_type, **kwargs + ) + + def log_vault_query(self, vault_name: str, operation: str, **kwargs): + """ + Log a vault query operation. + + Args: + vault_name: Name of the vault + operation: Vault operation (get_key, add_key, etc.) + **kwargs: Additional context (KID, key, success, etc.) + """ + self.log( + level="DEBUG", + operation=f"vault_{operation}", + message=f"Vault {vault_name}: {operation}", + vault=vault_name, + **kwargs, + ) + + def log_error(self, operation: str, error: Exception, **kwargs): + """ + Log an error with full context. + + Args: + operation: Operation that failed + error: Exception that occurred + **kwargs: Additional context + """ + self.log( + level="ERROR", + operation=operation, + message=f"Error in {operation}: {str(error)}", + error=error, + success=False, + **kwargs, + ) + + def close(self): + """Close the log file and clean up resources.""" + if self.file_handle: + self.log(level="INFO", operation="session_end", message="Debug logging session ended") + self.file_handle.close() + self.file_handle = None + + +# Global debug logger instance +_debug_logger: Optional[DebugLogger] = None + + +def get_debug_logger() -> Optional[DebugLogger]: + """Get the global debug logger instance.""" + return _debug_logger + + +def init_debug_logger(log_path: Optional[Path] = None, enabled: bool = False, log_keys: bool = False): + """ + Initialize the global debug logger. + + Args: + log_path: Path to the log file + enabled: Whether debug logging is enabled + log_keys: Whether to log decryption keys (for debugging key issues) + """ + global _debug_logger + if _debug_logger: + _debug_logger.close() + _debug_logger = DebugLogger(log_path=log_path, enabled=enabled, log_keys=log_keys) + + +def close_debug_logger(): + """Close the global debug logger.""" + global _debug_logger + if _debug_logger: + _debug_logger.close() + _debug_logger = None + + +__all__ = ( + "DebugLogger", + "get_debug_logger", + "init_debug_logger", + "close_debug_logger", +) diff --git a/unshackle/unshackle-example.yaml b/unshackle/unshackle-example.yaml index 3b00f48..0e45840 100644 --- a/unshackle/unshackle-example.yaml +++ b/unshackle/unshackle-example.yaml @@ -32,6 +32,24 @@ title_cache_enabled: true # Enable/disable title caching globally (default: true title_cache_time: 1800 # Cache duration in seconds (default: 1800 = 30 minutes) title_cache_max_retention: 86400 # Maximum cache retention for fallback when API fails (default: 86400 = 24 hours) +# Debug logging configuration +# Comprehensive JSON-based debug logging for troubleshooting and service development +debug: false # Enable structured JSON debug logging (default: false) + # When enabled with --debug flag or set to true: + # - Creates JSON Lines (.jsonl) log files with complete debugging context + # - Logs: session info, CLI params, service config, CDM details, authentication, + # titles, tracks metadata, DRM operations, vault queries, errors with stack traces + # - File location: logs/unshackle_debug_{service}_{timestamp}.jsonl + # - Also creates text log: logs/unshackle_root_{timestamp}.log + +debug_keys: false # Log decryption keys in debug logs (default: false) + # Set to true to include actual decryption keys in logs + # Useful for debugging key retrieval and decryption issues + # SECURITY NOTE: Passwords, tokens, cookies, and session tokens + # are ALWAYS redacted regardless of this setting + # Only affects: content_key, key fields (the actual CEKs) + # Never affects: kid, keys_count, key_id (metadata is always logged) + # Muxing configuration muxing: set_title: false @@ -239,7 +257,7 @@ headers: # Override default filenames used across unshackle filenames: - log: "unshackle_{name}_{time}.log" + debug_log: "unshackle_debug_{service}_{time}.jsonl" # JSON Lines debug log file config: "config.yaml" root_config: "unshackle.yaml" chapters: "Chapters_{title}_{random}.txt"