From 394ed67e28cadb1f8935a0a2731c34bac4cf4036 Mon Sep 17 00:00:00 2001
From: imSp4rky <george+slight@slight.me>
Date: Tue, 9 Jun 2026 22:12:05 -0600
Subject: [PATCH] feat(logging): expand debug-logging coverage, add primitives,
 redaction & tests

Instrument the full download pipeline in the structured JSONL debug logger and make adding logging to new features a one-liner.

Coverage:
- DRM license request/response, content keys (incl. remote-CDM seam) and decrypt timing across Widevine/PlayReady/ClearKey
- DASH/HLS/ISM manifest fetch + parse milestones (HLS.to_tracks also covers the m3u8_parser path used by iTunes/ATV-style services)
- Per-backend vault get/add via the Vaults manager, track selection, subtitle conversion, repackage, normalize_vui, and full mkvmerge mux (command, duration, output size, warnings)
- All external tooling (ffmpeg, ffprobe, mkvmerge, mkvpropedit, dovi_tool, SubtitleEdit, ccextractor) via a unified `tool_run` op, centralised in run_step/ffprobe + log_tool_run

DX:
- Add log_event() / timed_operation() primitives (no-op when disabled); retrofit ~91 guard/timing blocks onto them
- Fix message= collision in log_drm_operation/log_vault_query/log_service_call that raised TypeError on the live decrypt path

Redaction (redact_all = redact_text -> redact_url -> redact_path):
- Collapse content/CDN/api URLs to `redacted[.ext]`
- Strip local path prefixes (install root -> <unshackle>, venv -> <venv>, home -> ~)
- Apply to every logged string so shared logs leak no URLs, paths or usernames
- Drop per-request service_call logging (manifest parse is the request seam)
---
 docs/debug-logging.md                     |  76 ++++
 tests/core/test_debug_logging.py          | 338 +++++++++++++++++
 unshackle/commands/dl.py                  | 265 +++++++-------
 unshackle/core/drm/clearkey.py            |  16 +
 unshackle/core/drm/playready.py           |  55 ++-
 unshackle/core/drm/widevine.py            |  59 ++-
 unshackle/core/manifests/dash.py          | 131 ++++---
 unshackle/core/manifests/hls.py           | 113 +++---
 unshackle/core/manifests/ism.py           | 128 ++++---
 unshackle/core/proxies/gluetun.py         | 421 ++++++++++------------
 unshackle/core/tracks/dv_fixup.py         |  31 +-
 unshackle/core/tracks/hybrid.py           | 362 +++++++++----------
 unshackle/core/tracks/subtitle.py         |  45 ++-
 unshackle/core/tracks/subtitle_convert.py |  11 +
 unshackle/core/tracks/track.py            |  21 +-
 unshackle/core/tracks/tracks.py           | 119 +++---
 unshackle/core/tracks/video.py            |  46 ++-
 unshackle/core/utilities.py               |  90 ++++-
 unshackle/core/utils/bitrate.py           |   9 +
 unshackle/core/utils/dovi.py              |  10 +-
 unshackle/core/utils/redact.py            |  86 +++++
 unshackle/core/utils/subprocess.py        |  79 +++-
 unshackle/core/utils/tags.py              |  11 +
 unshackle/core/vaults.py                  |  34 +-
 24 files changed, 1763 insertions(+), 793 deletions(-)
 create mode 100644 docs/debug-logging.md
 create mode 100644 tests/core/test_debug_logging.py

diff --git a/docs/debug-logging.md b/docs/debug-logging.md
new file mode 100644
index 0000000..b8b6279
--- /dev/null
+++ b/docs/debug-logging.md
@@ -0,0 +1,76 @@
+# Structured debug logging
+
+unshackle emits structured JSON Lines (JSONL) when `-d`/`--debug` (a **global** flag, before the
+subcommand: `unshackle -d dl ...`) or `config.debug` is set. Output lands at
+`config.directories.logs / unshackle_debug_<service>_<time>.jsonl`. The logger is built for
+**developers troubleshooting pipeline flow** — maximum signal, minimum noise — not end users.
+
+## Adding logging to a new feature
+
+Use the two primitives from `unshackle.core.utilities`. Both are **no-ops when debug logging is
+disabled**, so they are always safe to call unguarded — no `if debug_logger:` needed.
+
+```python
+from unshackle.core.utilities import log_event, timed_operation
+
+# One-shot event:
+log_event("myfeature_done", message="Did the thing", context={"count": n})
+
+# Time a block (logs once at the end with duration_ms; ERROR + exception if it raises):
+with timed_operation("myfeature_run", context={"input": str(path)}):
+    do_the_work()
+```
+
+That's it. Do **not** write `if dl := get_debug_logger(): dl.log(...)` in new code — `log_event`
+replaces that boilerplate.
+
+### External tools (ffmpeg, mkvmerge, dovi_tool, …)
+
+Route binary calls through the helpers in `unshackle.core.utils.subprocess`:
+
+- `run_step(args, *, label=..., output=...)` — runs a CLI step and **auto-logs** a `tool_run`
+  entry (label, tool, returncode, duration). Prefer this for new tool calls.
+- `ffprobe(uri)` — auto-logs its `tool_run`.
+- `log_tool_run(label, tool, returncode, *, duration_ms=..., **ctx)` — for a direct
+  `subprocess.run` you can't route through `run_step`; call it right after the process returns.
+
+## Conventions
+
+- **Operation names**: `<area>_<event>` lowercase, e.g. `manifest_dash_parse`, `drm_decrypt`,
+  `mux_complete`, `vault_get_key`, `tool_run`. Names are plain inline strings (no central registry).
+- **Levels = the flow skeleton.** One **INFO** milestone per stage (a dev runs
+  `jq 'select(.level=="INFO")'` to read the end-to-end flow); internals at **DEBUG**; failures at
+  **ERROR**. Keep INFO sparse.
+- **Every entry carries a one-sentence `message`** that reads on its own; structured data
+  (`context`, `duration_ms`, counts, ids) lives in fields, not prose.
+- **No raw dumps.** Counts, ids, sizes, and `safe_display_url(url)` only — never a full `Tracks`,
+  MPD/manifest body, or response payload.
+- **Secrets, URLs & paths.** Every logged string passes through `redact_all` =
+  `redact_text` (mask password/token/secret/auth/cookie keys + URL userinfo/secret query params)
+  → `redact_url` (collapse any http(s) URL to `redacted[.ext]`, hiding CDN/content/manifest/api
+  locations while keeping the extension, e.g. `redacted.mpd`) → `redact_path` (strip local base
+  dirs: install root → `<unshackle>`, venv → `<venv>`, home → `~`). `key` fields are also redacted
+  unless `config.debug_keys`. Pass user data via `context=`/`request=`/kwargs so it is sanitized.
+  Net effect: a shared JSONL leaks no account URLs, machine paths, or usernames.
+- **Service calls are intentionally not logged** (no per-request POST/GET to services). Manifest
+  parsing (`manifest_*_parse`) is the seam for request-level visibility.
+
+## Reading the output
+
+```bash
+# Flow skeleton (one line per milestone):
+jq -r 'select(.level=="INFO") | "\(.operation)\t\(.message)"' unshackle/logs/unshackle_debug_*.jsonl
+
+# Everything for one correlated operation:
+jq 'select(.operation_id=="abc12345")' <log>
+```
+
+## Primitives reference
+
+| Symbol | Module | Purpose |
+|---|---|---|
+| `log_event(op, *, level, message, **ctx)` | `core.utilities` | one-shot structured entry |
+| `timed_operation(op, *, level, message, **ctx)` | `core.utilities` | context manager; logs once at end with `duration_ms` (ERROR on raise) |
+| `DebugLogger.log_drm_operation / log_vault_query / log_service_call` | `core.utilities` | typed convenience wrappers (accept `message=`/`level=` overrides) |
+| `run_step` / `ffprobe` / `log_tool_run` | `core.utils.subprocess` | external-tool `tool_run` logging |
+| `get_debug_logger()` | `core.utilities` | low-level accessor (rarely needed directly) |
diff --git a/tests/core/test_debug_logging.py b/tests/core/test_debug_logging.py
new file mode 100644
index 0000000..2e68a38
--- /dev/null
+++ b/tests/core/test_debug_logging.py
@@ -0,0 +1,338 @@
+"""Unit tests for the structured debug logger: JSONL output, secret redaction / key gating,
+the log_event / timed_operation primitives, the convenience-helper message override (regression
+for the hardcoded-message TypeError footgun), and tool_run logging."""
+
+from __future__ import annotations
+
+import json
+from pathlib import Path
+
+import pytest
+
+from unshackle.core.utilities import (close_debug_logger, get_debug_logger, init_debug_logger, log_event,
+                                      timed_operation)
+from unshackle.core.utils.redact import redact_all, redact_path, redact_text, redact_url, safe_display_url
+from unshackle.core.utils.subprocess import log_tool_run
+
+pytestmark = pytest.mark.unit
+
+
+def read_entries(path: Path) -> list[dict]:
+    """Parse a JSONL debug log into a list of dicts (proves every line is valid JSON)."""
+    return [json.loads(line) for line in path.read_text(encoding="utf-8").splitlines() if line.strip()]
+
+
+def find(entries: list[dict], operation: str) -> dict:
+    matches = [e for e in entries if e.get("operation") == operation]
+    assert matches, f"no entry with operation={operation!r} (have {[e.get('operation') for e in entries]})"
+    return matches[0]
+
+
+@pytest.fixture
+def debug_log(tmp_path: Path):
+    """Enabled debug logger writing to a temp JSONL file; torn down after each test."""
+    path = tmp_path / "debug.jsonl"
+    init_debug_logger(log_path=path, enabled=True)
+    yield path
+    close_debug_logger()
+
+
+@pytest.fixture
+def debug_log_with_keys(tmp_path: Path):
+    """Enabled debug logger with log_keys=True (mirrors config.debug_keys)."""
+    path = tmp_path / "debug_keys.jsonl"
+    init_debug_logger(log_path=path, enabled=True, log_keys=True)
+    yield path
+    close_debug_logger()
+
+
+# ---------- JSONL output shape ----------
+
+
+def test_every_line_is_valid_json_with_required_fields(debug_log: Path):
+    log_event("sample_event", message="hi", context={"a": 1})
+    close_debug_logger()  # flush session_end
+    entries = read_entries(debug_log)
+    assert entries, "expected at least one JSONL entry"
+    for e in entries:
+        assert {"timestamp", "session_id", "level", "operation"} <= e.keys()
+    assert {"session_start", "session_end"} <= {e["operation"] for e in entries}
+
+
+def test_session_id_is_stable_across_entries(debug_log: Path):
+    log_event("a")
+    log_event("b")
+    close_debug_logger()
+    ids = {e["session_id"] for e in read_entries(debug_log)}
+    assert len(ids) == 1
+
+
+# ---------- log_event ----------
+
+
+def test_log_event_emits_with_level_message_and_context(debug_log: Path):
+    log_event("feature_done", level="INFO", message="did it", context={"count": 3})
+    e = find(read_entries(debug_log), "feature_done")
+    assert e["level"] == "INFO"
+    assert e["message"] == "did it"
+    assert e["context"] == {"count": 3}
+
+
+def test_log_event_noop_when_disabled():
+    close_debug_logger()
+    assert get_debug_logger() is None
+    log_event("should_not_explode", message="no logger")  # must not raise
+
+
+# ---------- timed_operation ----------
+
+
+def test_timed_operation_logs_success_and_duration(debug_log: Path):
+    with timed_operation("work", level="INFO", context={"k": "v"}):
+        pass
+    e = find(read_entries(debug_log), "work")
+    assert e["level"] == "INFO"
+    assert e["success"] is True
+    assert isinstance(e["duration_ms"], (int, float))
+    assert e["context"] == {"k": "v"}
+
+
+def test_timed_operation_logs_error_and_reraises(debug_log: Path):
+    with pytest.raises(ValueError, match="boom"):
+        with timed_operation("work_fail"):
+            raise ValueError("boom")
+    e = find(read_entries(debug_log), "work_fail")
+    assert e["level"] == "ERROR"
+    assert e["success"] is False
+    assert "duration_ms" in e
+    assert e["error"]["type"] == "ValueError"
+
+
+def test_timed_operation_noop_when_disabled():
+    close_debug_logger()
+    with timed_operation("disabled_block"):  # must not raise, must still run body
+        value = 1 + 1
+    assert value == 2
+
+
+# ---------- secret redaction / key gating ----------
+
+
+def test_sanitize_redacts_sensitive_key_names(debug_log: Path):
+    dl = get_debug_logger()
+    cleaned = dl.sanitize_data(
+        {
+            "password": "hunter2",
+            "token": "abc",
+            "auth": "bearer x",
+            "cookie": "sess=1",
+            "secret": "s",
+            "has_password": True,  # has_ prefix stays
+            "quality": "1080p",  # non-secret stays
+        }
+    )
+    assert cleaned["password"] == "[REDACTED]"
+    assert cleaned["token"] == "[REDACTED]"
+    assert cleaned["auth"] == "[REDACTED]"
+    assert cleaned["cookie"] == "[REDACTED]"
+    assert cleaned["secret"] == "[REDACTED]"
+    assert cleaned["has_password"] is True
+    assert cleaned["quality"] == "1080p"
+
+
+def test_sanitize_gates_key_fields_unless_log_keys(debug_log: Path):
+    dl = get_debug_logger()  # log_keys=False
+    cleaned = dl.sanitize_data({"content_key": "deadbeef", "kid": "00112233", "key_found": True, "key_count": 2})
+    assert cleaned["content_key"] == "[REDACTED]"  # redacted when log_keys False
+    assert cleaned["kid"] == "00112233"  # kid whitelisted
+    assert cleaned["key_found"] is True  # key_found whitelisted
+    assert cleaned["key_count"] == 2  # _count whitelisted
+
+
+def test_sanitize_keeps_keys_when_log_keys_enabled(debug_log_with_keys: Path):
+    dl = get_debug_logger()  # log_keys=True
+    cleaned = dl.sanitize_data({"content_key": "deadbeef"})
+    assert cleaned["content_key"] == "deadbeef"
+
+
+def test_sanitize_masks_query_param_secrets_in_nonurl_string(debug_log: Path):
+    dl = get_debug_logger()
+    cleaned = dl.sanitize_data({"blob": "creds token=abc password=hunter2"})
+    assert "token=***" in cleaned["blob"]
+    assert "password=***" in cleaned["blob"]
+    assert "hunter2" not in cleaned["blob"]
+
+
+def test_sanitize_collapses_urls(debug_log: Path):
+    dl = get_debug_logger()
+    cleaned = dl.sanitize_data(
+        {
+            "segment": "https://cdn.example.net/a/b/x_audio_144.mp4?token=abc",
+            "manifest": "https://cdn.example.net/v/manifest.mpd",
+            "proxy": "http://bob:secret@proxy.example:8080/x",
+        }
+    )
+    assert cleaned["segment"] == "redacted.mp4"  # extension kept, host/path/query gone
+    assert cleaned["manifest"] == "redacted.mpd"
+    assert cleaned["proxy"] == "redacted"  # userinfo + host never reaches disk
+
+
+def test_logged_content_url_is_collapsed_on_disk(debug_log: Path):
+    log_event(
+        "downloader_start",
+        context={"first_url": "https://user:pw@cdn.example.net/seg_144.mp4?api_key=zzz"},
+    )
+    close_debug_logger()
+    raw = debug_log.read_text(encoding="utf-8")
+    assert "cdn.example.net" not in raw
+    assert "user:pw" not in raw
+    assert "api_key=zzz" not in raw
+    assert "redacted.mp4" in raw
+
+
+# ---------- redact.py helpers ----------
+
+
+@pytest.mark.parametrize(
+    ("text", "expected"),
+    [
+        ("https://u:p@h/x", "https://***@h/x"),
+        ("https://h/x?token=abc&q=1", "https://h/x?token=***&q=1"),
+        ("https://h/x?password=p", "https://h/x?password=***"),
+        ("nothing secret here", "nothing secret here"),
+    ],
+)
+def test_redact_text(text: str, expected: str):
+    assert redact_text(text) == expected
+
+
+def test_redact_text_masks_known_secrets_longest_first():
+    out = redact_text("a=foobar b=foo", secrets=["foo", "foobar"])
+    assert "foobar" not in out
+    assert out == "a=*** b=***"
+
+
+def test_safe_display_url_strips_userinfo_and_query():
+    assert safe_display_url("https://u:p@host:8080/a/b?token=x&y=2") == "https://host:8080/a/b"
+
+
+# ---------- redact_url ----------
+
+
+@pytest.mark.parametrize(
+    ("url", "expected"),
+    [
+        ("https://cdn.x/a/seg_144.mp4?t=1", "redacted.mp4"),
+        ("https://cdn.x/v/manifest.mpd", "redacted.mpd"),
+        ("https://cdn.x/v/playlist.m3u8", "redacted.m3u8"),
+        ("http://u:p@cdn.x/seg.m4s", "redacted.m4s"),
+        ("https://api.example/auth/token", "redacted"),  # no extension
+    ],
+)
+def test_redact_url_collapses_to_redacted_ext(url: str, expected: str):
+    assert redact_url(url) == expected
+
+
+def test_redact_url_leaves_nonurl_untouched():
+    assert redact_url("just some text, no url") == "just some text, no url"
+
+
+def test_redact_url_handles_url_embedded_in_text():
+    assert redact_url("got https://cdn.x/a.mp4 ok") == "got redacted.mp4 ok"
+
+
+# ---------- redact_path ----------
+
+
+def test_redact_path_strips_install_root():
+    # redact.py resolves the project/install root as the <unshackle> anchor.
+    from unshackle.core.utils import redact as redact_mod
+
+    root = str(Path(redact_mod.__file__).resolve().parents[3])
+    assert redact_path(f"{root}/temp/Audio.mp4") == "<unshackle>/temp/Audio.mp4"
+
+
+def test_redact_path_strips_home_dir():
+    home = str(Path.home())
+    assert redact_path(f"{home}/elsewhere/x").startswith("~/")
+
+
+def test_redact_path_leaves_relative_paths_untouched():
+    assert redact_path("temp/Audio.mp4") == "temp/Audio.mp4"
+
+
+# ---------- redact_all + output_dir integration ----------
+
+
+def test_redact_all_composes_secrets_urls_and_paths():
+    root = str(Path(__import__("unshackle.core.utils.redact", fromlist=["x"]).__file__).resolve().parents[3])
+    out = redact_all(f"dl https://u:p@cdn.x/seg.mp4?token=t into {root}/temp")
+    assert "cdn.x" not in out
+    assert "redacted.mp4" in out
+    assert "<unshackle>/temp" in out
+
+
+def test_logged_output_dir_is_path_redacted(debug_log: Path):
+    root = str(Path(__import__("unshackle.core.utils.redact", fromlist=["x"]).__file__).resolve().parents[3])
+    log_event("downloader_start", context={"output_dir": f"{root}/temp", "filename": "Audio_3eeab4ed.mp4"})
+    e = find(read_entries(debug_log), "downloader_start")
+    assert e["context"]["output_dir"] == "<unshackle>/temp"
+    assert e["context"]["filename"] == "Audio_3eeab4ed.mp4"  # bare filename untouched
+
+
+# ---------- convenience-helper message override (footgun regression) ----------
+
+
+def test_log_drm_operation_accepts_message_and_level_override(debug_log: Path):
+    dl = get_debug_logger()
+    # Previously raised: TypeError: log() got multiple values for keyword argument 'message'
+    dl.log_drm_operation("Widevine", "license_request", level="INFO", message="custom msg", kid="abc")
+    e = find(read_entries(debug_log), "drm_license_request")
+    assert e["message"] == "custom msg"
+    assert e["level"] == "INFO"
+    assert e["drm_type"] == "Widevine"
+
+
+def test_log_drm_operation_default_message(debug_log: Path):
+    get_debug_logger().log_drm_operation("PlayReady", "license_response")
+    e = find(read_entries(debug_log), "drm_license_response")
+    assert e["message"] == "PlayReady license_response"
+
+
+def test_log_vault_query_accepts_message_override(debug_log: Path):
+    get_debug_logger().log_vault_query("local", "get_key", message="hit", key_found=True)
+    e = find(read_entries(debug_log), "vault_get_key")
+    assert e["message"] == "hit"
+    assert e["vault"] == "local"
+
+
+def test_log_service_call_accepts_message_override(debug_log: Path):
+    get_debug_logger().log_service_call("POST", "https://api.example/x", message="license", status=200)
+    e = find(read_entries(debug_log), "service_call")
+    assert e["message"] == "license"
+    assert e["request"]["method"] == "POST"
+    assert e["request"]["status"] == 200
+
+
+# ---------- tool_run ----------
+
+
+def test_log_tool_run_success_is_debug(debug_log: Path):
+    log_tool_run("ffmpeg concat", "ffmpeg", 0, duration_ms=12.3, segments=5)
+    e = find(read_entries(debug_log), "tool_run")
+    assert e["level"] == "DEBUG"
+    assert e["context"]["tool"] == "ffmpeg"
+    assert e["context"]["returncode"] == 0
+    assert e["context"]["segments"] == 5
+
+
+def test_log_tool_run_failure_is_error(debug_log: Path):
+    log_tool_run("mkvpropedit tags", "mkvpropedit", 2)
+    e = find(read_entries(debug_log), "tool_run")
+    assert e["level"] == "ERROR"
+    assert "failed" in e["message"]
+
+
+def test_log_tool_run_noop_when_disabled():
+    close_debug_logger()
+    log_tool_run("ffmpeg", "ffmpeg", 0)  # must not raise
diff --git a/unshackle/commands/dl.py b/unshackle/commands/dl.py
index 60efd97..7745469 100644
--- a/unshackle/commands/dl.py
+++ b/unshackle/commands/dl.py
@@ -59,8 +59,8 @@ from unshackle.core.tracks.attachment import Attachment
 from unshackle.core.tracks.dv_fixup import apply_dv_fixup
 from unshackle.core.tracks.hybrid import Hybrid
 from unshackle.core.utilities import (find_font_with_fallbacks, find_missing_langs, get_debug_logger,
-                                      get_system_fonts, init_debug_logger, is_close_match, suggest_font_packages,
-                                      time_elapsed_since)
+                                      get_system_fonts, init_debug_logger, is_close_match, log_event,
+                                      suggest_font_packages, time_elapsed_since)
 from unshackle.core.utils import tags
 from unshackle.core.utils.bitrate import apply_real_bitrates
 from unshackle.core.utils.click_types import (AUDIO_CODEC_LIST, LANGUAGE_RANGE, QUALITY_LIST, SEASON_RANGE,
@@ -861,18 +861,17 @@ 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:
-                            # log key names only -- the full config carries service certificates,
-                            # device fingerprints and endpoints that bloat the log and may be sensitive
-                            self.debug_logger.log(
-                                level="DEBUG",
-                                operation="load_service_config",
-                                service=self.service,
-                                context={
-                                    "config_path": str(service_config_path),
-                                    "config_keys": sorted(self.service_config or []),
-                                },
-                            )
+                        # log key names only -- the full config carries service certificates,
+                        # device fingerprints and endpoints that bloat the log and may be sensitive
+                        log_event(
+                            "load_service_config",
+                            level="DEBUG",
+                            service=self.service,
+                            context={
+                                "config_path": str(service_config_path),
+                                "config_keys": sorted(self.service_config or []),
+                            },
+                        )
                 except KeyError:
                     pass
             merge_dict(config.services.get(self.service), self.service_config)
@@ -915,13 +914,12 @@ class dl:
         if cdm_only:
             self.vaults = Vaults(self.vault_service)
             self.log.info("CDM-only mode: Skipping vault loading")
-            if self.debug_logger:
-                self.debug_logger.log(
-                    level="INFO",
-                    operation="vault_loading_skipped",
-                    service=self.service,
-                    context={"reason": "cdm_only flag set"},
-                )
+            log_event(
+                "vault_loading_skipped",
+                level="INFO",
+                service=self.service,
+                context={"reason": "cdm_only flag set"},
+            )
         else:
             with console.status("Loading Key Vaults...", spinner="dots"):
                 self.vaults = Vaults(self.vault_service)
@@ -1009,9 +1007,9 @@ class dl:
                         "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}
+                if cdm_info:
+                    log_event(
+                        "load_cdm", level="INFO", service=self.service, context={"cdm": cdm_info}
                     )
 
         self.proxy_providers = []
@@ -1257,17 +1255,16 @@ 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"),
-                },
-            )
+        log_event(
+            "drm_mode_config",
+            level="DEBUG",
+            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 Remote Service..." if self.is_remote else "Authenticating with Service...",
@@ -1279,17 +1276,16 @@ class dl:
                 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,
-                            },
-                        )
+                    log_event(
+                        "authenticate",
+                        level="INFO",
+                        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(
@@ -1304,14 +1300,13 @@ class dl:
                 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,
-                        )
+                    log_event(
+                        "get_titles",
+                        level="ERROR",
+                        service=self.service,
+                        message="No titles returned from service",
+                        success=False,
+                    )
                     sys.exit(1)
             except Exception as e:
                 if self.debug_logger:
@@ -2241,6 +2236,25 @@ class dl:
 
             selected_tracks, tracks_progress_callables = title.tracks.tree(add_progress=True)
 
+            log_event(
+                "track_select",
+                level="INFO",
+                message=(
+                    f"Selected {len(title.tracks.videos)} video, {len(title.tracks.audio)} audio, "
+                    f"{len(title.tracks.subtitles)} subtitle track(s)"
+                ),
+                context={
+                    "videos": [
+                        f"{v.codec} {v.range} {v.height}p {v.bitrate}bps {v.language}" for v in title.tracks.videos
+                    ],
+                    "audio": [
+                        f"{a.codec} {a.language} {getattr(a, 'channels', None)}ch {a.bitrate}bps"
+                        for a in title.tracks.audio
+                    ],
+                    "subtitles": [f"{s.codec} {s.language}" for s in title.tracks.subtitles],
+                },
+            )
+
             if progress_sink is not None:
                 from unshackle.core.api.progress import build_job_progress_callables
 
@@ -2346,14 +2360,13 @@ class dl:
 
             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)},
-                    )
+                log_event(
+                    "download_tracks",
+                    level="WARNING",
+                    service=self.service,
+                    message="Download cancelled by user",
+                    context={"title": str(title)},
+                )
                 return
             except Exception as e:  # noqa
                 # Reported and swallowed (no re-raise) so the CLI exits cleanly; flag it so the
@@ -2986,6 +2999,16 @@ class dl:
             drm_name = {"widevine": "Widevine", "playready": "PlayReady"}.get(
                 server_drm_type or "", drm.__class__.__name__
             )
+            log_event(
+                "drm_content_keys",
+                level="INFO",
+                message=f"Server CDM resolved {len(drm.content_keys)} {drm_name} content key(s)",
+                service=self.service,
+                drm_type=drm_name,
+                key_count=len(drm.content_keys),
+                keys=[{"kid": k.hex, "key": v} for k, v in drm.content_keys.items()],
+                remote=True,
+            )
             with self.DRM_TABLE_LOCK:
                 pssh_str = ""
                 expected_class = "PlayReady" if server_drm_type == "playready" else "Widevine"
@@ -3088,18 +3111,17 @@ class dl:
                         label = f"[text2]{kid.hex}:{cached_key}{is_track_kid} from cache"
                         if not any(f"{kid.hex}:{cached_key}" in x.label for x in cek_tree.children):
                             cek_tree.add(label)
-                        if self.debug_logger:
-                            self.debug_logger.log(
-                                level="INFO",
-                                operation="license_cache_hit",
-                                service=self.service,
-                                context={
-                                    "kid": kid.hex,
-                                    "content_key": cached_key,
-                                    "track": str(track),
-                                    "drm_type": "Widevine",
-                                },
-                            )
+                        log_event(
+                            "license_cache_hit",
+                            level="INFO",
+                            service=self.service,
+                            context={
+                                "kid": kid.hex,
+                                "content_key": cached_key,
+                                "track": str(track),
+                                "drm_type": "Widevine",
+                            },
+                        )
                         continue
 
                     if not cdm_only:
@@ -3129,14 +3151,13 @@ 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(
-                                    level="ERROR",
-                                    operation="vault_key_not_found",
-                                    service=self.service,
-                                    message=msg,
-                                    context={"kid": kid.hex, "track": str(track)},
-                                )
+                            log_event(
+                                "vault_key_not_found",
+                                level="ERROR",
+                                service=self.service,
+                                message=msg,
+                                context={"kid": kid.hex, "track": str(track)},
+                            )
                             raise Widevine.Exceptions.CEKNotFound(msg)
                         else:
                             need_license = True
@@ -3150,17 +3171,16 @@ 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],
-                            },
-                        )
+                    log_event(
+                        "get_license",
+                        level="INFO",
+                        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":
@@ -3187,17 +3207,16 @@ class dl:
                                 )
                             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()],
-                            },
-                        )
+                    log_event(
+                        "license_keys_retrieved",
+                        level="INFO",
+                        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:
@@ -3289,18 +3308,17 @@ class dl:
                         label = f"[text2]{kid.hex}:{cached_key}{is_track_kid} from cache"
                         if not any(f"{kid.hex}:{cached_key}" in x.label for x in cek_tree.children):
                             cek_tree.add(label)
-                        if self.debug_logger:
-                            self.debug_logger.log(
-                                level="INFO",
-                                operation="license_cache_hit",
-                                service=self.service,
-                                context={
-                                    "kid": kid.hex,
-                                    "content_key": cached_key,
-                                    "track": str(track),
-                                    "drm_type": "PlayReady",
-                                },
-                            )
+                        log_event(
+                            "license_cache_hit",
+                            level="INFO",
+                            service=self.service,
+                            context={
+                                "kid": kid.hex,
+                                "content_key": cached_key,
+                                "track": str(track),
+                                "drm_type": "PlayReady",
+                            },
+                        )
                         continue
 
                     if not cdm_only:
@@ -3331,14 +3349,13 @@ 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(
-                                    level="ERROR",
-                                    operation="vault_key_not_found",
-                                    service=self.service,
-                                    message=msg,
-                                    context={"kid": kid.hex, "track": str(track), "drm_type": "PlayReady"},
-                                )
+                            log_event(
+                                "vault_key_not_found",
+                                level="ERROR",
+                                service=self.service,
+                                message=msg,
+                                context={"kid": kid.hex, "track": str(track), "drm_type": "PlayReady"},
+                            )
                             raise PlayReady.Exceptions.CEKNotFound(msg)
                         else:
                             need_license = True
diff --git a/unshackle/core/drm/clearkey.py b/unshackle/core/drm/clearkey.py
index c1c93e4..f22aa90 100644
--- a/unshackle/core/drm/clearkey.py
+++ b/unshackle/core/drm/clearkey.py
@@ -12,6 +12,7 @@ from m3u8.model import Key
 from requests import Session
 
 from unshackle.core.session import RnetSession
+from unshackle.core.utilities import log_event
 
 
 class ClearKey:
@@ -44,6 +45,14 @@ class ClearKey:
         if not path or not path.exists():
             raise ValueError("Tried to decrypt a file that does not exist.")
 
+        log_event(
+            "drm_decrypt",
+            level="DEBUG",
+            message=f"Decrypting {path.name} with AES-CBC",
+            drm_type="ClearKey",
+            file=path.name,
+        )
+
         decrypted = AES.new(self.key, AES.MODE_CBC, self.iv).decrypt(path.read_bytes())
 
         try:
@@ -94,6 +103,13 @@ class ClearKey:
             key = data
         else:
             url = urljoin(m3u_key.base_uri, m3u_key.uri)
+            log_event(
+                "drm_key_fetch",
+                level="DEBUG",
+                message="Fetching ClearKey from M3U key URI",
+                drm_type="ClearKey",
+                request={"url": url},
+            )
             res = session.get(url)
             res.raise_for_status()
             if not res.content:
diff --git a/unshackle/core/drm/playready.py b/unshackle/core/drm/playready.py
index 5328ddf..bfcfb8e 100644
--- a/unshackle/core/drm/playready.py
+++ b/unshackle/core/drm/playready.py
@@ -4,6 +4,7 @@ import base64
 import shutil
 import subprocess
 import textwrap
+import time
 from pathlib import Path
 from typing import Any, Callable, Optional, Union
 from uuid import UUID
@@ -20,7 +21,7 @@ from unshackle.core import binaries
 from unshackle.core.config import config
 from unshackle.core.console import console
 from unshackle.core.constants import AnyTrack
-from unshackle.core.utilities import get_boxes
+from unshackle.core.utilities import get_boxes, log_event
 from unshackle.core.utils.subprocess import ffprobe
 
 
@@ -307,6 +308,14 @@ class PlayReady:
 
             if challenge:
                 try:
+                    log_event(
+                        "drm_license_request",
+                        level="DEBUG",
+                        message="Requesting PlayReady license",
+                        drm_type="PlayReady",
+                        challenge_size=len(challenge),
+                        kid_count=len(self.kids),
+                    )
                     try:
                         license_res = licence(challenge=challenge, pssh_b64=self.pssh_b64)
                     except TypeError:
@@ -323,11 +332,28 @@ class PlayReady:
                             pass
 
                     cdm.parse_license(session_id, license_str)
+                    log_event(
+                        "drm_license_response",
+                        level="DEBUG",
+                        message="Parsed PlayReady license",
+                        drm_type="PlayReady",
+                        response_size=len(license_str),
+                    )
                 except Exception:
                     raise
 
             keys = self._extract_keys_from_cdm(cdm, session_id)
             self.content_keys.update(keys)
+
+            if keys:
+                log_event(
+                    "drm_content_keys",
+                    level="INFO",
+                    message=f"Recovered {len(keys)} PlayReady content key(s) from CDM",
+                    drm_type="PlayReady",
+                    key_count=len(keys),
+                    keys=[{"kid": k.hex if hasattr(k, "hex") else str(k), "key": v} for k, v in keys.items()],
+                )
         finally:
             cdm.close(session_id)
 
@@ -351,11 +377,34 @@ class PlayReady:
             raise ValueError("Tried to decrypt a file that does not exist.")
 
         decrypter = str(getattr(config, "decryption", "")).lower()
+        tool = "mp4decrypt" if decrypter == "mp4decrypt" else "shaka-packager"
 
+        log_event(
+            "drm_decrypt",
+            level="DEBUG",
+            message=f"Decrypting {path.name} with {tool}",
+            drm_type="PlayReady",
+            tool=tool,
+            file=path.name,
+            key_count=len(self.content_keys),
+        )
+
+        decrypt_start = time.monotonic()
         if decrypter == "mp4decrypt":
-            return self._decrypt_with_mp4decrypt(path)
+            self._decrypt_with_mp4decrypt(path)
         else:
-            return self._decrypt_with_shaka_packager(path)
+            self._decrypt_with_shaka_packager(path)
+
+        log_event(
+            "drm_decrypt_complete",
+            level="DEBUG",
+            message=f"Decrypted {path.name} with {tool}",
+            drm_type="PlayReady",
+            tool=tool,
+            file=path.name,
+            duration_ms=round((time.monotonic() - decrypt_start) * 1000, 1),
+            output_size=path.stat().st_size if path.exists() else 0,
+        )
 
     def _decrypt_with_mp4decrypt(self, path: Path) -> None:
         """Decrypt using mp4decrypt"""
diff --git a/unshackle/core/drm/widevine.py b/unshackle/core/drm/widevine.py
index 250b05a..b48a930 100644
--- a/unshackle/core/drm/widevine.py
+++ b/unshackle/core/drm/widevine.py
@@ -4,6 +4,7 @@ import base64
 import shutil
 import subprocess
 import textwrap
+import time
 from pathlib import Path
 from typing import Any, Callable, Optional, Union
 from uuid import UUID
@@ -20,7 +21,7 @@ from unshackle.core import binaries
 from unshackle.core.config import config
 from unshackle.core.console import console
 from unshackle.core.constants import AnyTrack
-from unshackle.core.utilities import get_boxes
+from unshackle.core.utilities import get_boxes, log_event
 from unshackle.core.utils.subprocess import ffprobe
 
 
@@ -216,13 +217,42 @@ class Widevine:
                 if hasattr(cdm, "has_cached_keys") and cdm.has_cached_keys(session_id):
                     pass
                 else:
+                    log_event(
+                        "drm_license_request",
+                        level="DEBUG",
+                        message=f"Requesting Widevine license for KID {kid.hex}",
+                        drm_type="Widevine",
+                        kid=kid.hex,
+                        challenge_size=len(challenge),
+                        kid_count=len(self.kids),
+                    )
                     try:
                         license_res = licence(challenge=challenge, pssh=self.pssh)
                     except TypeError:
                         license_res = licence(challenge=challenge)
                     cdm.parse_license(session_id, license_res)
+                    log_event(
+                        "drm_license_response",
+                        level="DEBUG",
+                        message=f"Parsed Widevine license for KID {kid.hex}",
+                        drm_type="Widevine",
+                        kid=kid.hex,
+                        response_size=len(license_res) if license_res else 0,
+                    )
 
                 self.content_keys = {key.kid: key.key.hex() for key in cdm.get_keys(session_id, "CONTENT")}
+
+                if self.content_keys:
+                    log_event(
+                        "drm_content_keys",
+                        level="INFO",
+                        message=f"Recovered {len(self.content_keys)} Widevine content key(s)",
+                        drm_type="Widevine",
+                        kid=kid.hex,
+                        key_count=len(self.content_keys),
+                        keys=[{"kid": k.hex, "key": v} for k, v in self.content_keys.items()],
+                    )
+
                 if not self.content_keys:
                     raise Widevine.Exceptions.EmptyLicense("No Content Keys were within the License")
 
@@ -287,11 +317,34 @@ class Widevine:
             raise ValueError("Tried to decrypt a file that does not exist.")
 
         decrypter = str(getattr(config, "decryption", "")).lower()
+        tool = "mp4decrypt" if decrypter == "mp4decrypt" else "shaka-packager"
 
+        log_event(
+            "drm_decrypt",
+            level="DEBUG",
+            message=f"Decrypting {path.name} with {tool}",
+            drm_type="Widevine",
+            tool=tool,
+            file=path.name,
+            key_count=len(self.content_keys),
+        )
+
+        decrypt_start = time.monotonic()
         if decrypter == "mp4decrypt":
-            return self._decrypt_with_mp4decrypt(path)
+            self._decrypt_with_mp4decrypt(path)
         else:
-            return self._decrypt_with_shaka_packager(path)
+            self._decrypt_with_shaka_packager(path)
+
+        log_event(
+            "drm_decrypt_complete",
+            level="DEBUG",
+            message=f"Decrypted {path.name} with {tool}",
+            drm_type="Widevine",
+            tool=tool,
+            file=path.name,
+            duration_ms=round((time.monotonic() - decrypt_start) * 1000, 1),
+            output_size=path.stat().st_size if path.exists() else 0,
+        )
 
     def _decrypt_with_mp4decrypt(self, path: Path) -> None:
         """Decrypt using mp4decrypt"""
diff --git a/unshackle/core/manifests/dash.py b/unshackle/core/manifests/dash.py
index 0890cce..8c60bbf 100644
--- a/unshackle/core/manifests/dash.py
+++ b/unshackle/core/manifests/dash.py
@@ -29,7 +29,8 @@ from unshackle.core.drm import DRM_T, PlayReady, Widevine
 from unshackle.core.events import events
 from unshackle.core.session import RnetSession
 from unshackle.core.tracks import Audio, Subtitle, Tracks, Video
-from unshackle.core.utilities import get_debug_logger, is_close_match, try_ensure_utf8
+from unshackle.core.utilities import is_close_match, log_event, try_ensure_utf8
+from unshackle.core.utils.redact import safe_display_url
 from unshackle.core.utils.xml import load_xml
 
 
@@ -67,6 +68,13 @@ class DASH:
         if not res.ok:
             raise requests.ConnectionError("Failed to request the MPD document.", response=res)
 
+        log_event(
+            "manifest_dash_fetch",
+            level="DEBUG",
+            message=f"Fetched DASH manifest ({len(res.text)} bytes)",
+            context={"url": safe_display_url(url), "size": len(res.text)},
+        )
+
         return DASH.from_text(res.text, url)
 
     @classmethod
@@ -248,6 +256,22 @@ class DASH:
             break
 
         tracks.manifest_url = self.url
+
+        log_event(
+            "manifest_dash_parse",
+            level="INFO",
+            message=(
+                f"Parsed DASH manifest: {len(tracks.videos)} video, "
+                f"{len(tracks.audio)} audio, {len(tracks.subtitles)} subtitle track(s)"
+            ),
+            context={
+                "videos": len(tracks.videos),
+                "audio": len(tracks.audio),
+                "subtitles": len(tracks.subtitles),
+                "ranges": sorted({str(v.range) for v in tracks.videos}),
+                "vcodecs": sorted({str(v.codec) for v in tracks.videos}),
+            },
+        )
         return tracks
 
     @staticmethod
@@ -444,22 +468,20 @@ class DASH:
             session=session,
         )
 
-        debug_logger = get_debug_logger()
-        if debug_logger:
-            debug_logger.log(
-                level="DEBUG",
-                operation="manifest_dash_download_start",
-                message="Starting DASH manifest download",
-                context={
-                    "track_id": getattr(track, "id", None),
-                    "track_type": track.__class__.__name__,
-                    "total_segments": len(segments),
-                    "has_drm": bool(track.drm),
-                    "drm_types": [drm.__class__.__name__ for drm in (track.drm or [])],
-                    "save_path": str(save_path),
-                    "has_init_data": bool(init_data),
-                },
-            )
+        log_event(
+            "manifest_dash_download_start",
+            level="DEBUG",
+            message="Starting DASH manifest download",
+            context={
+                "track_id": getattr(track, "id", None),
+                "track_type": track.__class__.__name__,
+                "total_segments": len(segments),
+                "has_drm": bool(track.drm),
+                "drm_types": [drm.__class__.__name__ for drm in (track.drm or [])],
+                "save_path": str(save_path),
+                "has_init_data": bool(init_data),
+            },
+        )
 
         for status_update in downloader(**downloader_args):
             file_downloaded = status_update.get("file_downloaded")
@@ -474,19 +496,18 @@ class DASH:
         # Verify output directory exists and contains files
         if not save_dir.exists():
             error_msg = f"Output directory does not exist: {save_dir}"
-            if debug_logger:
-                debug_logger.log(
-                    level="ERROR",
-                    operation="manifest_dash_download_output_missing",
-                    message=error_msg,
-                    context={
-                        "track_id": getattr(track, "id", None),
-                        "track_type": track.__class__.__name__,
-                        "save_dir": str(save_dir),
-                        "save_path": str(save_path),
-                        "downloader": "requests",
-                    },
-                )
+            log_event(
+                "manifest_dash_download_output_missing",
+                level="ERROR",
+                message=error_msg,
+                context={
+                    "track_id": getattr(track, "id", None),
+                    "track_type": track.__class__.__name__,
+                    "save_dir": str(save_dir),
+                    "save_path": str(save_path),
+                    "downloader": "requests",
+                },
+            )
             raise FileNotFoundError(error_msg)
 
         for control_file in save_dir.glob("*.!dev"):
@@ -494,39 +515,37 @@ class DASH:
 
         segments_to_merge = [x for x in sorted(save_dir.iterdir()) if x.is_file()]
 
-        if debug_logger:
-            debug_logger.log(
-                level="DEBUG",
-                operation="manifest_dash_download_complete",
-                message="DASH download complete, preparing to merge",
+        log_event(
+            "manifest_dash_download_complete",
+            level="DEBUG",
+            message="DASH download complete, preparing to merge",
+            context={
+                "track_id": getattr(track, "id", None),
+                "track_type": track.__class__.__name__,
+                "save_dir": str(save_dir),
+                "save_dir_exists": save_dir.exists(),
+                "segments_found": len(segments_to_merge),
+                "segment_files": [f.name for f in segments_to_merge[:10]],  # Limit to first 10
+                "downloader": "requests",
+            },
+        )
+
+        if not segments_to_merge:
+            error_msg = f"No segment files found in output directory: {save_dir}"
+            # List all contents of the directory for debugging
+            all_contents = list(save_dir.iterdir()) if save_dir.exists() else []
+            log_event(
+                "manifest_dash_download_no_segments",
+                level="ERROR",
+                message=error_msg,
                 context={
                     "track_id": getattr(track, "id", None),
                     "track_type": track.__class__.__name__,
                     "save_dir": str(save_dir),
-                    "save_dir_exists": save_dir.exists(),
-                    "segments_found": len(segments_to_merge),
-                    "segment_files": [f.name for f in segments_to_merge[:10]],  # Limit to first 10
+                    "directory_contents": [str(p) for p in all_contents],
                     "downloader": "requests",
                 },
             )
-
-        if not segments_to_merge:
-            error_msg = f"No segment files found in output directory: {save_dir}"
-            if debug_logger:
-                # List all contents of the directory for debugging
-                all_contents = list(save_dir.iterdir()) if save_dir.exists() else []
-                debug_logger.log(
-                    level="ERROR",
-                    operation="manifest_dash_download_no_segments",
-                    message=error_msg,
-                    context={
-                        "track_id": getattr(track, "id", None),
-                        "track_type": track.__class__.__name__,
-                        "save_dir": str(save_dir),
-                        "directory_contents": [str(p) for p in all_contents],
-                        "downloader": "requests",
-                    },
-                )
             raise FileNotFoundError(error_msg)
 
         with open(save_path, "wb") as f:
diff --git a/unshackle/core/manifests/hls.py b/unshackle/core/manifests/hls.py
index 343e26a..0b08b45 100644
--- a/unshackle/core/manifests/hls.py
+++ b/unshackle/core/manifests/hls.py
@@ -9,6 +9,7 @@ import re
 import shutil
 import subprocess
 import sys
+import time
 from functools import partial
 from pathlib import Path
 from typing import Any, Callable, Optional, Union
@@ -33,7 +34,9 @@ from unshackle.core.drm import DRM_T, ClearKey, MonaLisa, PlayReady, Widevine
 from unshackle.core.events import events
 from unshackle.core.session import RnetResponse, RnetSession
 from unshackle.core.tracks import Audio, Subtitle, Tracks, Video
-from unshackle.core.utilities import get_debug_logger, get_extension, is_close_match, try_ensure_utf8
+from unshackle.core.utilities import get_extension, is_close_match, log_event, try_ensure_utf8
+from unshackle.core.utils.redact import safe_display_url
+from unshackle.core.utils.subprocess import log_tool_run
 
 
 class HLS:
@@ -86,6 +89,13 @@ class HLS:
 
         master = m3u8.loads(content, uri=url)
 
+        log_event(
+            "manifest_hls_fetch",
+            level="DEBUG",
+            message=f"Fetched HLS manifest ({len(content)} bytes)",
+            context={"url": safe_display_url(url), "size": len(content)},
+        )
+
         return cls(master, session, url=url, raw_text=content)
 
     @classmethod
@@ -313,6 +323,22 @@ class HLS:
 
         if self.url:
             tracks.manifest_url = self.url
+
+        log_event(
+            "manifest_hls_parse",
+            level="INFO",
+            message=(
+                f"Parsed HLS manifest: {len(tracks.videos)} video, "
+                f"{len(tracks.audio)} audio, {len(tracks.subtitles)} subtitle track(s)"
+            ),
+            context={
+                "videos": len(tracks.videos),
+                "audio": len(tracks.audio),
+                "subtitles": len(tracks.subtitles),
+                "ranges": sorted({str(v.range) for v in tracks.videos}),
+                "vcodecs": sorted({str(v.codec) for v in tracks.videos}),
+            },
+        )
         return tracks
 
     @staticmethod
@@ -656,21 +682,19 @@ class HLS:
             session=session,
         )
 
-        debug_logger = get_debug_logger()
-        if debug_logger:
-            debug_logger.log(
-                level="DEBUG",
-                operation="manifest_hls_download_start",
-                message="Starting HLS manifest download",
-                context={
-                    "track_id": getattr(track, "id", None),
-                    "track_type": track.__class__.__name__,
-                    "total_segments": total_segments,
-                    "has_drm": bool(session_drm),
-                    "drm_type": session_drm.__class__.__name__ if session_drm else None,
-                    "save_path": str(save_path),
-                },
-            )
+        log_event(
+            "manifest_hls_download_start",
+            level="DEBUG",
+            message="Starting HLS manifest download",
+            context={
+                "track_id": getattr(track, "id", None),
+                "track_type": track.__class__.__name__,
+                "total_segments": total_segments,
+                "has_drm": bool(session_drm),
+                "drm_type": session_drm.__class__.__name__ if session_drm else None,
+                "save_path": str(save_path),
+            },
+        )
 
         for status_update in downloader(**downloader_args):
             file_downloaded = status_update.get("file_downloaded")
@@ -939,39 +963,37 @@ class HLS:
         # finally merge all the discontinuity save files together to the final path
         segments_to_merge = find_segments_recursively(save_dir)
 
-        if debug_logger:
-            debug_logger.log(
-                level="DEBUG",
-                operation="manifest_hls_download_complete",
-                message="HLS download complete, preparing to merge",
+        log_event(
+            "manifest_hls_download_complete",
+            level="DEBUG",
+            message="HLS download complete, preparing to merge",
+            context={
+                "track_id": getattr(track, "id", None),
+                "track_type": track.__class__.__name__,
+                "save_dir": str(save_dir),
+                "save_dir_exists": save_dir.exists(),
+                "segments_found": len(segments_to_merge),
+                "segment_files": [f.name for f in segments_to_merge[:10]],  # Limit to first 10
+                "downloader": "requests",
+            },
+        )
+
+        if not segments_to_merge:
+            error_msg = f"No segment files found in output directory: {save_dir}"
+            all_contents = list(save_dir.iterdir()) if save_dir.exists() else []
+            log_event(
+                "manifest_hls_download_no_segments",
+                level="ERROR",
+                message=error_msg,
                 context={
                     "track_id": getattr(track, "id", None),
                     "track_type": track.__class__.__name__,
                     "save_dir": str(save_dir),
                     "save_dir_exists": save_dir.exists(),
-                    "segments_found": len(segments_to_merge),
-                    "segment_files": [f.name for f in segments_to_merge[:10]],  # Limit to first 10
+                    "directory_contents": [str(p) for p in all_contents],
                     "downloader": "requests",
                 },
             )
-
-        if not segments_to_merge:
-            error_msg = f"No segment files found in output directory: {save_dir}"
-            if debug_logger:
-                all_contents = list(save_dir.iterdir()) if save_dir.exists() else []
-                debug_logger.log(
-                    level="ERROR",
-                    operation="manifest_hls_download_no_segments",
-                    message=error_msg,
-                    context={
-                        "track_id": getattr(track, "id", None),
-                        "track_type": track.__class__.__name__,
-                        "save_dir": str(save_dir),
-                        "save_dir_exists": save_dir.exists(),
-                        "directory_contents": [str(p) for p in all_contents],
-                        "downloader": "requests",
-                    },
-                )
             raise FileNotFoundError(error_msg)
 
         if len(segments_to_merge) == 1:
@@ -1039,6 +1061,7 @@ class HLS:
                 demuxer_file = save_path.parent / f"ffmpeg_concat_demuxer_{save_path.stem}.txt"
                 demuxer_file.write_text("\n".join([f"file '{segment.absolute()}'" for segment in segments]))
 
+                concat_start = time.monotonic()
                 subprocess.check_call(
                     [
                         binaries.FFMPEG,
@@ -1061,6 +1084,14 @@ class HLS:
                 )
                 demuxer_file.unlink(missing_ok=True)
                 cleanup_segments_and_dirs()
+                log_tool_run(
+                    "ffmpeg concat segments",
+                    "ffmpeg",
+                    0,
+                    duration_ms=round((time.monotonic() - concat_start) * 1000, 1),
+                    segments=len(segments),
+                    output_size=save_path.stat().st_size if save_path.exists() else 0,
+                )
                 return save_path.stat().st_size
 
             except (subprocess.CalledProcessError, subprocess.TimeoutExpired, OSError) as e:
diff --git a/unshackle/core/manifests/ism.py b/unshackle/core/manifests/ism.py
index b1fe991..61d9378 100644
--- a/unshackle/core/manifests/ism.py
+++ b/unshackle/core/manifests/ism.py
@@ -20,7 +20,8 @@ from unshackle.core.drm import DRM_T, PlayReady, Widevine
 from unshackle.core.events import events
 from unshackle.core.session import RnetSession
 from unshackle.core.tracks import Audio, Subtitle, Track, Tracks, Video
-from unshackle.core.utilities import get_debug_logger, try_ensure_utf8
+from unshackle.core.utilities import log_event, try_ensure_utf8
+from unshackle.core.utils.redact import safe_display_url
 from unshackle.core.utils.xml import load_xml
 
 
@@ -45,6 +46,12 @@ class ISM:
         if res.url != url:
             url = res.url
         res.raise_for_status()
+        log_event(
+            "manifest_ism_fetch",
+            level="DEBUG",
+            message=f"Fetched ISM manifest ({len(res.content)} bytes)",
+            context={"url": safe_display_url(url), "size": len(res.content)},
+        )
         return cls(load_xml(res.content), url)
 
     @classmethod
@@ -220,6 +227,22 @@ class ISM:
                         )
                     )
         tracks.manifest_url = self.url
+
+        log_event(
+            "manifest_ism_parse",
+            level="INFO",
+            message=(
+                f"Parsed ISM manifest: {len(tracks.videos)} video, "
+                f"{len(tracks.audio)} audio, {len(tracks.subtitles)} subtitle track(s)"
+            ),
+            context={
+                "videos": len(tracks.videos),
+                "audio": len(tracks.audio),
+                "subtitles": len(tracks.subtitles),
+                "ranges": sorted({str(v.range) for v in tracks.videos}),
+                "vcodecs": sorted({str(v.codec) for v in tracks.videos}),
+            },
+        )
         return tracks
 
     @staticmethod
@@ -280,22 +303,20 @@ class ISM:
             session=session,
         )
 
-        debug_logger = get_debug_logger()
-        if debug_logger:
-            debug_logger.log(
-                level="DEBUG",
-                operation="manifest_ism_download_start",
-                message="Starting ISM manifest download",
-                context={
-                    "track_id": getattr(track, "id", None),
-                    "track_type": track.__class__.__name__,
-                    "total_segments": len(segments),
-                    "downloader": "requests",
-                    "has_drm": bool(session_drm),
-                    "drm_type": session_drm.__class__.__name__ if session_drm else None,
-                    "save_path": str(save_path),
-                },
-            )
+        log_event(
+            "manifest_ism_download_start",
+            level="DEBUG",
+            message="Starting ISM manifest download",
+            context={
+                "track_id": getattr(track, "id", None),
+                "track_type": track.__class__.__name__,
+                "total_segments": len(segments),
+                "downloader": "requests",
+                "has_drm": bool(session_drm),
+                "drm_type": session_drm.__class__.__name__ if session_drm else None,
+                "save_path": str(save_path),
+            },
+        )
 
         for status_update in downloader(**downloader_args):
             file_downloaded = status_update.get("file_downloaded")
@@ -310,19 +331,18 @@ class ISM:
         # Verify output directory exists and contains files
         if not save_dir.exists():
             error_msg = f"Output directory does not exist: {save_dir}"
-            if debug_logger:
-                debug_logger.log(
-                    level="ERROR",
-                    operation="manifest_ism_download_output_missing",
-                    message=error_msg,
-                    context={
-                        "track_id": getattr(track, "id", None),
-                        "track_type": track.__class__.__name__,
-                        "save_dir": str(save_dir),
-                        "save_path": str(save_path),
-                        "downloader": "requests",
-                    },
-                )
+            log_event(
+                "manifest_ism_download_output_missing",
+                level="ERROR",
+                message=error_msg,
+                context={
+                    "track_id": getattr(track, "id", None),
+                    "track_type": track.__class__.__name__,
+                    "save_dir": str(save_dir),
+                    "save_path": str(save_path),
+                    "downloader": "requests",
+                },
+            )
             raise FileNotFoundError(error_msg)
 
         for control_file in save_dir.glob("*.!dev"):
@@ -330,38 +350,36 @@ class ISM:
 
         segments_to_merge = [x for x in sorted(save_dir.iterdir()) if x.is_file()]
 
-        if debug_logger:
-            debug_logger.log(
-                level="DEBUG",
-                operation="manifest_ism_download_complete",
-                message="ISM download complete, preparing to merge",
+        log_event(
+            "manifest_ism_download_complete",
+            level="DEBUG",
+            message="ISM download complete, preparing to merge",
+            context={
+                "track_id": getattr(track, "id", None),
+                "track_type": track.__class__.__name__,
+                "save_dir": str(save_dir),
+                "save_dir_exists": save_dir.exists(),
+                "segments_found": len(segments_to_merge),
+                "segment_files": [f.name for f in segments_to_merge[:10]],  # Limit to first 10
+                "downloader": "requests",
+            },
+        )
+
+        if not segments_to_merge:
+            error_msg = f"No segment files found in output directory: {save_dir}"
+            all_contents = list(save_dir.iterdir()) if save_dir.exists() else []
+            log_event(
+                "manifest_ism_download_no_segments",
+                level="ERROR",
+                message=error_msg,
                 context={
                     "track_id": getattr(track, "id", None),
                     "track_type": track.__class__.__name__,
                     "save_dir": str(save_dir),
-                    "save_dir_exists": save_dir.exists(),
-                    "segments_found": len(segments_to_merge),
-                    "segment_files": [f.name for f in segments_to_merge[:10]],  # Limit to first 10
+                    "directory_contents": [str(p) for p in all_contents],
                     "downloader": "requests",
                 },
             )
-
-        if not segments_to_merge:
-            error_msg = f"No segment files found in output directory: {save_dir}"
-            if debug_logger:
-                all_contents = list(save_dir.iterdir()) if save_dir.exists() else []
-                debug_logger.log(
-                    level="ERROR",
-                    operation="manifest_ism_download_no_segments",
-                    message=error_msg,
-                    context={
-                        "track_id": getattr(track, "id", None),
-                        "track_type": track.__class__.__name__,
-                        "save_dir": str(save_dir),
-                        "directory_contents": [str(p) for p in all_contents],
-                        "downloader": "requests",
-                    },
-                )
             raise FileNotFoundError(error_msg)
 
         with open(save_path, "wb") as f:
diff --git a/unshackle/core/proxies/gluetun.py b/unshackle/core/proxies/gluetun.py
index fceeb04..5dc40b0 100644
--- a/unshackle/core/proxies/gluetun.py
+++ b/unshackle/core/proxies/gluetun.py
@@ -13,7 +13,7 @@ import requests
 
 from unshackle.core import binaries
 from unshackle.core.proxies.proxy import Proxy
-from unshackle.core.utilities import get_country_code, get_country_name, get_debug_logger
+from unshackle.core.utilities import get_country_code, get_country_name, get_debug_logger, log_event
 from unshackle.core.utils.ip_info import get_ip_info
 
 # Global registry for cleanup on exit
@@ -223,20 +223,18 @@ class Gluetun(Proxy):
             _gluetun_instances.append(self)
 
         # Log initialization
-        debug_logger = get_debug_logger()
-        if debug_logger:
-            debug_logger.log(
-                level="INFO",
-                operation="gluetun_init",
-                message=f"Gluetun proxy provider initialized with {len(self.providers)} provider(s)",
-                context={
-                    "providers": list(self.providers.keys()),
-                    "base_port": base_port,
-                    "auto_cleanup": auto_cleanup,
-                    "verify_ip": verify_ip,
-                    "container_prefix": container_prefix,
-                },
-            )
+        log_event(
+            "gluetun_init",
+            level="INFO",
+            message=f"Gluetun proxy provider initialized with {len(self.providers)} provider(s)",
+            context={
+                "providers": list(self.providers.keys()),
+                "base_port": base_port,
+                "auto_cleanup": auto_cleanup,
+                "verify_ip": verify_ip,
+                "container_prefix": container_prefix,
+            },
+        )
 
     def __repr__(self) -> str:
         provider_count = len(self.providers)
@@ -269,24 +267,21 @@ class Gluetun(Proxy):
         query_key = f"{provider_name}:{region}"
         container_name = f"{self.container_prefix}-{provider_name}-{region}"
 
-        debug_logger = get_debug_logger()
-
         # Check if container already exists (in memory OR in Docker)
         # This handles multiple concurrent Unshackle sessions
         if query_key in self.active_containers:
             container = self.active_containers[query_key]
             if self._is_container_running(container["container_name"]):
-                if debug_logger:
-                    debug_logger.log(
-                        level="DEBUG",
-                        operation="gluetun_container_reuse",
-                        message=f"Reusing existing container (in-memory): {query_key}",
-                        context={
-                            "query_key": query_key,
-                            "container_name": container["container_name"],
-                            "port": container["port"],
-                        },
-                    )
+                log_event(
+                    "gluetun_container_reuse",
+                    level="DEBUG",
+                    message=f"Reusing existing container (in-memory): {query_key}",
+                    context={
+                        "query_key": query_key,
+                        "container_name": container["container_name"],
+                        "port": container["port"],
+                    },
+                )
                 # Re-verify if needed
                 if self.verify_ip:
                     self._verify_container(query_key)
@@ -297,17 +292,16 @@ class Gluetun(Proxy):
             if existing_info:
                 # Container exists in Docker, reuse it
                 self.active_containers[query_key] = existing_info
-                if debug_logger:
-                    debug_logger.log(
-                        level="INFO",
-                        operation="gluetun_container_reuse_docker",
-                        message=f"Reusing existing Docker container: {query_key}",
-                        context={
-                            "query_key": query_key,
-                            "container_name": container_name,
-                            "port": existing_info["port"],
-                        },
-                    )
+                log_event(
+                    "gluetun_container_reuse_docker",
+                    level="INFO",
+                    message=f"Reusing existing Docker container: {query_key}",
+                    context={
+                        "query_key": query_key,
+                        "container_name": container_name,
+                        "port": existing_info["port"],
+                    },
+                )
                 # Re-verify if needed
                 if self.verify_ip:
                     self._verify_container(query_key)
@@ -411,13 +405,12 @@ class Gluetun(Proxy):
 
     def cleanup(self):
         """Stop and remove all managed Gluetun containers."""
-        debug_logger = get_debug_logger()
         container_count = len(self.active_containers)
 
-        if container_count > 0 and debug_logger:
-            debug_logger.log(
+        if container_count > 0:
+            log_event(
+                "gluetun_cleanup_start",
                 level="DEBUG",
-                operation="gluetun_cleanup_start",
                 message=f"Cleaning up {container_count} Gluetun container(s)",
                 context={
                     "container_count": container_count,
@@ -429,23 +422,22 @@ class Gluetun(Proxy):
             container_name = container_info["container_name"]
             self._remove_container(container_name)
 
-            if debug_logger:
-                debug_logger.log(
-                    level="DEBUG",
-                    operation="gluetun_container_removed",
-                    message=f"Removed Gluetun container: {container_name}",
-                    context={
-                        "query_key": query_key,
-                        "container_name": container_name,
-                    },
-                )
+            log_event(
+                "gluetun_container_removed",
+                level="DEBUG",
+                message=f"Removed Gluetun container: {container_name}",
+                context={
+                    "query_key": query_key,
+                    "container_name": container_name,
+                },
+            )
 
         self.active_containers.clear()
 
-        if container_count > 0 and debug_logger:
-            debug_logger.log(
+        if container_count > 0:
+            log_event(
+                "gluetun_cleanup_complete",
                 level="INFO",
-                operation="gluetun_cleanup_complete",
                 message=f"Cleanup complete: removed {container_count} container(s)",
                 context={"container_count": container_count},
                 success=True,
@@ -654,34 +646,31 @@ class Gluetun(Proxy):
         hostname: Optional[str] = None,
     ):
         """Create and start a Gluetun Docker container."""
-        debug_logger = get_debug_logger()
         start_time = time.time()
 
-        if debug_logger:
-            debug_logger.log(
-                level="DEBUG",
-                operation="gluetun_container_create_start",
-                message=f"Creating Gluetun container: {container_name}",
-                context={
-                    "container_name": container_name,
-                    "port": port,
-                    "provider": provider_name,
-                    "country": country,
-                    "city": city,
-                    "hostname": hostname,
-                },
-            )
+        log_event(
+            "gluetun_container_create_start",
+            level="DEBUG",
+            message=f"Creating Gluetun container: {container_name}",
+            context={
+                "container_name": container_name,
+                "port": port,
+                "provider": provider_name,
+                "country": country,
+                "city": city,
+                "hostname": hostname,
+            },
+        )
 
         # Ensure the Gluetun image is available (pulls if needed)
         gluetun_image = "qmcgaw/gluetun:latest"
         if not self._ensure_image_available(gluetun_image):
-            if debug_logger:
-                debug_logger.log(
-                    level="ERROR",
-                    operation="gluetun_image_pull_failed",
-                    message=f"Failed to pull Docker image: {gluetun_image}",
-                    success=False,
-                )
+            log_event(
+                "gluetun_image_pull_failed",
+                level="ERROR",
+                message=f"Failed to pull Docker image: {gluetun_image}",
+                success=False,
+            )
             raise RuntimeError(f"Failed to ensure Gluetun Docker image '{gluetun_image}' is available")
 
         vpn_type = provider_config.get("vpn_type", "wireguard").lower()
@@ -752,7 +741,7 @@ class Gluetun(Proxy):
         env_vars.update(extra_env)
 
         # Debug log environment variables (redact sensitive values)
-        if debug_logger:
+        if debug_logger := get_debug_logger():
             redact_markers = ("KEY", "PASSWORD", "PASS", "TOKEN", "SECRET", "USER")
             safe_env = {k: ("***" if any(m in k for m in redact_markers) else v) for k, v in env_vars.items()}
             debug_logger.log(
@@ -821,54 +810,50 @@ class Gluetun(Proxy):
                     errors="replace",
                 )
             except subprocess.TimeoutExpired:
-                if debug_logger:
-                    debug_logger.log(
-                        level="ERROR",
-                        operation="gluetun_container_create_timeout",
-                        message=f"Docker run timed out for {container_name}",
-                        context={"container_name": container_name},
-                        success=False,
-                        duration_ms=(time.time() - start_time) * 1000,
-                    )
+                log_event(
+                    "gluetun_container_create_timeout",
+                    level="ERROR",
+                    message=f"Docker run timed out for {container_name}",
+                    context={"container_name": container_name},
+                    success=False,
+                    duration_ms=(time.time() - start_time) * 1000,
+                )
                 raise RuntimeError("Docker run command timed out")
 
             if result.returncode != 0:
                 error_msg = result.stderr or "unknown error"
-                if debug_logger:
-                    debug_logger.log(
-                        level="ERROR",
-                        operation="gluetun_container_create_failed",
-                        message=f"Docker run failed for {container_name}",
-                        context={
-                            "container_name": container_name,
-                            "return_code": result.returncode,
-                            "stderr": error_msg,
-                        },
-                        success=False,
-                        duration_ms=(time.time() - start_time) * 1000,
-                    )
+                log_event(
+                    "gluetun_container_create_failed",
+                    level="ERROR",
+                    message=f"Docker run failed for {container_name}",
+                    context={
+                        "container_name": container_name,
+                        "return_code": result.returncode,
+                        "stderr": error_msg,
+                    },
+                    success=False,
+                    duration_ms=(time.time() - start_time) * 1000,
+                )
                 raise RuntimeError(f"Docker run failed: {error_msg}")
 
             # Log successful container creation
-            if debug_logger:
-                duration_ms = (time.time() - start_time) * 1000
-                debug_logger.log(
-                    level="INFO",
-                    operation="gluetun_container_created",
-                    message=f"Gluetun container created: {container_name}",
-                    context={
-                        "container_name": container_name,
-                        "port": port,
-                        "provider": provider_name,
-                        "vpn_type": vpn_type,
-                        "country": country,
-                        "city": city,
-                        "hostname": hostname,
-                        "container_id": result.stdout.strip()[:12] if result.stdout else None,
-                    },
-                    success=True,
-                    duration_ms=duration_ms,
-                )
+            log_event(
+                "gluetun_container_created",
+                level="INFO",
+                message=f"Gluetun container created: {container_name}",
+                context={
+                    "container_name": container_name,
+                    "port": port,
+                    "provider": provider_name,
+                    "vpn_type": vpn_type,
+                    "country": country,
+                    "city": city,
+                    "hostname": hostname,
+                    "container_id": result.stdout.strip()[:12] if result.stdout else None,
+                },
+                success=True,
+                duration_ms=(time.time() - start_time) * 1000,
+            )
         finally:
             if env_file_path:
                 # Best-effort "secure delete": overwrite then unlink (not guaranteed on all filesystems).
@@ -1011,17 +996,15 @@ class Gluetun(Proxy):
         Returns:
             True if container is ready, False if it failed or timed out
         """
-        debug_logger = get_debug_logger()
         start_time = time.time()
         last_error = None
 
-        if debug_logger:
-            debug_logger.log(
-                level="DEBUG",
-                operation="gluetun_container_wait_start",
-                message=f"Waiting for container to be ready: {container_name}",
-                context={"container_name": container_name, "timeout": timeout},
-            )
+        log_event(
+            "gluetun_container_wait_start",
+            level="DEBUG",
+            message=f"Waiting for container to be ready: {container_name}",
+            context={"container_name": container_name, "timeout": timeout},
+        )
 
         while time.time() - start_time < timeout:
             try:
@@ -1059,19 +1042,18 @@ class Gluetun(Proxy):
                         # Give a brief moment for the proxy to fully initialize
                         time.sleep(1)
                         duration_ms = (time.time() - start_time) * 1000
-                        if debug_logger:
-                            debug_logger.log(
-                                level="INFO",
-                                operation="gluetun_container_ready",
-                                message=f"Gluetun container is ready: {container_name}",
-                                context={
-                                    "container_name": container_name,
-                                    "proxy_ready": proxy_ready,
-                                    "vpn_ready": vpn_ready,
-                                },
-                                success=True,
-                                duration_ms=duration_ms,
-                            )
+                        log_event(
+                            "gluetun_container_ready",
+                            level="INFO",
+                            message=f"Gluetun container is ready: {container_name}",
+                            context={
+                                "container_name": container_name,
+                                "proxy_ready": proxy_ready,
+                                "vpn_ready": vpn_ready,
+                            },
+                            success=True,
+                            duration_ms=duration_ms,
+                        )
                         return True
 
                     # Check for fatal errors that indicate VPN connection failure
@@ -1106,19 +1088,18 @@ class Gluetun(Proxy):
 
         # Log timeout/failure
         duration_ms = (time.time() - start_time) * 1000
-        if debug_logger:
-            debug_logger.log(
-                level="ERROR",
-                operation="gluetun_container_wait_timeout",
-                message=f"Gluetun container failed to become ready: {container_name}",
-                context={
-                    "container_name": container_name,
-                    "timeout": timeout,
-                    "last_error": last_error,
-                },
-                success=False,
-                duration_ms=duration_ms,
-            )
+        log_event(
+            "gluetun_container_wait_timeout",
+            level="ERROR",
+            message=f"Gluetun container failed to become ready: {container_name}",
+            context={
+                "container_name": container_name,
+                "timeout": timeout,
+                "last_error": last_error,
+            },
+            success=False,
+            duration_ms=duration_ms,
+        )
         return False
 
     def _get_container_exit_info(self, container_name: str) -> Optional[dict]:
@@ -1170,7 +1151,6 @@ class Gluetun(Proxy):
         Raises:
             RuntimeError: If verification fails after all retries
         """
-        debug_logger = get_debug_logger()
         start_time = time.time()
 
         if query_key not in self.active_containers:
@@ -1180,18 +1160,17 @@ class Gluetun(Proxy):
         proxy_url = self._build_proxy_uri(container["port"])
         expected_country = container.get("country", "").upper()
 
-        if debug_logger:
-            debug_logger.log(
-                level="DEBUG",
-                operation="gluetun_verify_start",
-                message=f"Verifying VPN IP for: {query_key}",
-                context={
-                    "query_key": query_key,
-                    "container_name": container.get("container_name"),
-                    "expected_country": expected_country,
-                    "max_retries": max_retries,
-                },
-            )
+        log_event(
+            "gluetun_verify_start",
+            level="DEBUG",
+            message=f"Verifying VPN IP for: {query_key}",
+            context={
+                "query_key": query_key,
+                "container_name": container.get("container_name"),
+                "expected_country": expected_country,
+                "max_retries": max_retries,
+            },
+        )
 
         last_error = None
 
@@ -1219,22 +1198,21 @@ class Gluetun(Proxy):
 
                             if actual_country != expected_code:
                                 duration_ms = (time.time() - start_time) * 1000
-                                if debug_logger:
-                                    debug_logger.log(
-                                        level="ERROR",
-                                        operation="gluetun_verify_mismatch",
-                                        message=f"Region mismatch for {query_key}",
-                                        context={
-                                            "query_key": query_key,
-                                            "expected_country": expected_code,
-                                            "actual_country": actual_country,
-                                            "ip": ip_info.get("ip"),
-                                            "city": ip_info.get("city"),
-                                            "org": ip_info.get("org"),
-                                        },
-                                        success=False,
-                                        duration_ms=duration_ms,
-                                    )
+                                log_event(
+                                    "gluetun_verify_mismatch",
+                                    level="ERROR",
+                                    message=f"Region mismatch for {query_key}",
+                                    context={
+                                        "query_key": query_key,
+                                        "expected_country": expected_code,
+                                        "actual_country": actual_country,
+                                        "ip": ip_info.get("ip"),
+                                        "city": ip_info.get("city"),
+                                        "org": ip_info.get("org"),
+                                    },
+                                    success=False,
+                                    duration_ms=duration_ms,
+                                )
                                 raise RuntimeError(
                                     f"Region mismatch for {container['provider']}:{container['region']}: "
                                     f"Expected '{expected_code}' but got '{actual_country}' "
@@ -1249,22 +1227,21 @@ class Gluetun(Proxy):
                             self.active_containers[query_key]["ip_org"] = ip_info.get("org")
 
                         duration_ms = (time.time() - start_time) * 1000
-                        if debug_logger:
-                            debug_logger.log(
-                                level="INFO",
-                                operation="gluetun_verify_success",
-                                message=f"VPN IP verified for: {query_key}",
-                                context={
-                                    "query_key": query_key,
-                                    "ip": ip_info.get("ip"),
-                                    "country": actual_country,
-                                    "city": ip_info.get("city"),
-                                    "org": ip_info.get("org"),
-                                    "attempts": attempt + 1,
-                                },
-                                success=True,
-                                duration_ms=duration_ms,
-                            )
+                        log_event(
+                            "gluetun_verify_success",
+                            level="INFO",
+                            message=f"VPN IP verified for: {query_key}",
+                            context={
+                                "query_key": query_key,
+                                "ip": ip_info.get("ip"),
+                                "country": actual_country,
+                                "city": ip_info.get("city"),
+                                "org": ip_info.get("org"),
+                                "attempts": attempt + 1,
+                            },
+                            success=True,
+                            duration_ms=duration_ms,
+                        )
                         return
 
                     # ip_info was None, retry
@@ -1274,17 +1251,16 @@ class Gluetun(Proxy):
                     raise  # Re-raise region mismatch errors immediately
                 except Exception as e:
                     last_error = str(e)
-                    if debug_logger:
-                        debug_logger.log(
-                            level="DEBUG",
-                            operation="gluetun_verify_retry",
-                            message=f"Verification attempt {attempt + 1} failed, retrying",
-                            context={
-                                "query_key": query_key,
-                                "attempt": attempt + 1,
-                                "error": last_error,
-                            },
-                        )
+                    log_event(
+                        "gluetun_verify_retry",
+                        level="DEBUG",
+                        message=f"Verification attempt {attempt + 1} failed, retrying",
+                        context={
+                            "query_key": query_key,
+                            "attempt": attempt + 1,
+                            "error": last_error,
+                        },
+                    )
 
                 # Wait before retry (exponential backoff)
                 if attempt < max_retries - 1:
@@ -1298,19 +1274,18 @@ class Gluetun(Proxy):
 
         # All retries exhausted
         duration_ms = (time.time() - start_time) * 1000
-        if debug_logger:
-            debug_logger.log(
-                level="ERROR",
-                operation="gluetun_verify_failed",
-                message=f"VPN verification failed after {max_retries} attempts",
-                context={
-                    "query_key": query_key,
-                    "max_retries": max_retries,
-                    "last_error": last_error,
-                },
-                success=False,
-                duration_ms=duration_ms,
-            )
+        log_event(
+            "gluetun_verify_failed",
+            level="ERROR",
+            message=f"VPN verification failed after {max_retries} attempts",
+            context={
+                "query_key": query_key,
+                "max_retries": max_retries,
+                "last_error": last_error,
+            },
+            success=False,
+            duration_ms=duration_ms,
+        )
         raise RuntimeError(
             f"Failed to verify VPN IP for {container['provider']}:{container['region']} "
             f"after {max_retries} attempts. Last error: {last_error}"
diff --git a/unshackle/core/tracks/dv_fixup.py b/unshackle/core/tracks/dv_fixup.py
index 3e8f9ff..a7744b4 100644
--- a/unshackle/core/tracks/dv_fixup.py
+++ b/unshackle/core/tracks/dv_fixup.py
@@ -22,7 +22,7 @@ from rich.rule import Rule
 from unshackle.core.binaries import FFMPEG, DoviTool
 from unshackle.core.config import config
 from unshackle.core.console import console
-from unshackle.core.utilities import get_debug_logger
+from unshackle.core.utilities import log_event
 from unshackle.core.utils import dovi
 from unshackle.core.utils.subprocess import run_step
 
@@ -35,7 +35,6 @@ class DVFixup:
 
     def __init__(self, video: "Video") -> None:
         self.log = logging.getLogger("dv-fixup")
-        self.debug_logger = get_debug_logger()
         self.video = video
 
         if not DoviTool:
@@ -74,13 +73,12 @@ class DVFixup:
             dovi.inject_rpu(raw_hevc, rpu, fixed_hevc, status="Re-injecting DV RPU with proper signaling...")
         except Exception as e:
             self.log.warning(f"DV fixup failed ({e}); muxing source as-is.")
-            if self.debug_logger:
-                self.debug_logger.log(
-                    level="WARNING",
-                    operation="dv_fixup",
-                    message="DV fixup failed; falling back to source",
-                    context={"error": str(e), "source": str(source)},
-                )
+            log_event(
+                "dv_fixup",
+                level="WARNING",
+                message="DV fixup failed; falling back to source",
+                context={"error": str(e), "source": str(source)},
+            )
             for leftover in (raw_hevc, rpu, fixed_hevc):
                 leftover.unlink(missing_ok=True)
             return source
@@ -89,14 +87,13 @@ class DVFixup:
             leftover.unlink(missing_ok=True)
 
         self.log.info("✓ DV signaling restored")
-        if self.debug_logger:
-            self.debug_logger.log(
-                level="INFO",
-                operation="dv_fixup",
-                message="DV fixup complete",
-                context={"source": str(source), "output": str(fixed_hevc)},
-                success=True,
-            )
+        log_event(
+            "dv_fixup",
+            level="INFO",
+            message="DV fixup complete",
+            context={"source": str(source), "output": str(fixed_hevc)},
+            success=True,
+        )
         return fixed_hevc
 
 
diff --git a/unshackle/core/tracks/hybrid.py b/unshackle/core/tracks/hybrid.py
index 3632d45..3f67121 100644
--- a/unshackle/core/tracks/hybrid.py
+++ b/unshackle/core/tracks/hybrid.py
@@ -14,7 +14,7 @@ from rich.rule import Rule
 from unshackle.core.binaries import FFMPEG, FFProbe, HDR10PlusTool
 from unshackle.core.config import config
 from unshackle.core.console import console
-from unshackle.core.utilities import get_debug_logger
+from unshackle.core.utilities import log_event
 from unshackle.core.utils import dovi
 from unshackle.core.utils.subprocess import run_step
 
@@ -22,7 +22,6 @@ from unshackle.core.utils.subprocess import run_step
 class Hybrid:
     def __init__(self, videos, source) -> None:
         self.log = logging.getLogger("hybrid")
-        self.debug_logger = get_debug_logger()
 
         """
             Takes the Dolby Vision and HDR10(+) streams out of the VideoTracks.
@@ -48,18 +47,17 @@ class Hybrid:
 
         console.print(Padding(Rule(f"[rule.text]HDR10+DV Hybrid ({self.resolution})"), (1, 2)))
 
-        if self.debug_logger:
-            self.debug_logger.log(
-                level="DEBUG",
-                operation="hybrid_init",
-                message="Starting HDR10+DV hybrid processing",
-                context={
-                    "source": source,
-                    "resolution": self.resolution,
-                    "video_count": len(videos),
-                    "video_ranges": [str(v.range) for v in videos],
-                },
-            )
+        log_event(
+            "hybrid_init",
+            level="DEBUG",
+            message="Starting HDR10+DV hybrid processing",
+            context={
+                "source": source,
+                "resolution": self.resolution,
+                "video_count": len(videos),
+                "video_ranges": [str(v.range) for v in videos],
+            },
+        )
 
         for video in self.videos:
             if not video.path or not os.path.exists(video.path):
@@ -122,19 +120,18 @@ class Hybrid:
 
         self.injecting()
 
-        if self.debug_logger:
-            self.debug_logger.log(
-                level="INFO",
-                operation="hybrid_complete",
-                message="Injection Completed",
-                context={
-                    "hdr_type": self.hdr_type,
-                    "resolution": self.resolution,
-                    "hdr10plus_to_dv": self.hdr10plus_to_dv,
-                    "rpu_file": self.rpu_file,
-                    "output_file": self.hevc_file,
-                },
-            )
+        log_event(
+            "hybrid_complete",
+            level="INFO",
+            message="Injection Completed",
+            context={
+                "hdr_type": self.hdr_type,
+                "resolution": self.resolution,
+                "hdr10plus_to_dv": self.hdr10plus_to_dv,
+                "rpu_file": self.rpu_file,
+                "output_file": self.hevc_file,
+            },
+        )
         self.log.info("✓ Injection Completed")
         if self.source == ("itunes" or "appletvplus"):
             Path.unlink(config.directories.temp / "hdr10.mkv")
@@ -156,24 +153,22 @@ class Hybrid:
                 label=f"ffmpeg extract {type_}",
             )
         except RuntimeError as e:
-            if self.debug_logger:
-                self.debug_logger.log(
-                    level="ERROR",
-                    operation="hybrid_extract_stream",
-                    message=f"Failed extracting {type_} stream",
-                    context={"type": type_, "input": str(save_path), "output": str(output), "error": str(e)},
-                )
+            log_event(
+                "hybrid_extract_stream",
+                level="ERROR",
+                message=f"Failed extracting {type_} stream",
+                context={"type": type_, "input": str(save_path), "output": str(output), "error": str(e)},
+            )
             self.log.error(f"x Failed extracting {type_} stream")
             sys.exit(1)
 
-        if self.debug_logger:
-            self.debug_logger.log(
-                level="DEBUG",
-                operation="hybrid_extract_stream",
-                message=f"Extracted {type_} stream",
-                context={"type": type_, "input": str(save_path), "output": str(output)},
-                success=True,
-            )
+        log_event(
+            "hybrid_extract_stream",
+            level="DEBUG",
+            message=f"Extracted {type_} stream",
+            context={"type": type_, "input": str(save_path), "output": str(output)},
+            success=True,
+        )
 
     def extract_rpu(self, video, untouched=False):
         if os.path.isfile(config.directories.temp / "RPU.bin") or os.path.isfile(
@@ -190,13 +185,12 @@ class Hybrid:
             dovi.extract_rpu(dv_stream, rpu_path, mode=None if untouched else 3, status=spinner)
         except RuntimeError as e:
             stderr_text = str(e)
-            if self.debug_logger:
-                self.debug_logger.log(
-                    level="ERROR",
-                    operation="hybrid_extract_rpu",
-                    message=f"Failed extracting{' untouched ' if untouched else ' '}RPU",
-                    context={"untouched": untouched, "error": stderr_text},
-                )
+            log_event(
+                "hybrid_extract_rpu",
+                level="ERROR",
+                message=f"Failed extracting{' untouched ' if untouched else ' '}RPU",
+                context={"untouched": untouched, "error": stderr_text},
+            )
             if "MAX_PQ_LUMINANCE" in stderr_text:
                 self.extract_rpu(video, untouched=True)
                 return
@@ -204,14 +198,13 @@ class Hybrid:
                 raise ValueError("Dolby Vision VideoTrack seems to be corrupt")
             raise ValueError(f"Failed extracting{' untouched ' if untouched else ' '}RPU from Dolby Vision stream")
 
-        if self.debug_logger:
-            self.debug_logger.log(
-                level="DEBUG",
-                operation="hybrid_extract_rpu",
-                message=f"Extracted{' untouched ' if untouched else ' '}RPU from Dolby Vision stream",
-                context={"untouched": untouched, "output": f"{rpu_name}.bin"},
-                success=True,
-            )
+        log_event(
+            "hybrid_extract_rpu",
+            level="DEBUG",
+            message=f"Extracted{' untouched ' if untouched else ' '}RPU from Dolby Vision stream",
+            context={"untouched": untouched, "output": f"{rpu_name}.bin"},
+            success=True,
+        )
 
     def level_5(self, input_video):
         """Generate Level 5 active area metadata via crop detection on the HDR10 stream.
@@ -235,13 +228,12 @@ class Hybrid:
             )
 
             if result_duration.returncode != 0:
-                if self.debug_logger:
-                    self.debug_logger.log(
-                        level="WARNING",
-                        operation="hybrid_level5",
-                        message="Could not probe video duration",
-                        context={"returncode": result_duration.returncode, "stderr": (result_duration.stderr or "")},
-                    )
+                log_event(
+                    "hybrid_level5",
+                    level="WARNING",
+                    message="Could not probe video duration",
+                    context={"returncode": result_duration.returncode, "stderr": (result_duration.stderr or "")},
+                )
                 self.log.warning("Could not probe video duration, skipping L5 crop detection")
                 return
 
@@ -268,13 +260,12 @@ class Hybrid:
             )
 
             if result_streams.returncode != 0:
-                if self.debug_logger:
-                    self.debug_logger.log(
-                        level="WARNING",
-                        operation="hybrid_level5",
-                        message="Could not probe video resolution",
-                        context={"returncode": result_streams.returncode, "stderr": (result_streams.stderr or "")},
-                    )
+                log_event(
+                    "hybrid_level5",
+                    level="WARNING",
+                    message="Could not probe video resolution",
+                    context={"returncode": result_streams.returncode, "stderr": (result_streams.stderr or "")},
+                )
                 self.log.warning("Could not probe video resolution, skipping L5 crop detection")
                 return
 
@@ -327,13 +318,12 @@ class Hybrid:
                     crop_results.append((left, top, right, bottom))
 
         if not crop_results:
-            if self.debug_logger:
-                self.debug_logger.log(
-                    level="WARNING",
-                    operation="hybrid_level5",
-                    message="No crop data detected, skipping L5",
-                    context={"samples": len(random_times)},
-                )
+            log_event(
+                "hybrid_level5",
+                level="WARNING",
+                message="No crop data detected, skipping L5",
+                context={"samples": len(random_times)},
+            )
             self.log.warning("No crop data detected, skipping L5")
             return
 
@@ -365,26 +355,24 @@ class Hybrid:
                 label="dovi_tool editor (L5)",
             )
         except RuntimeError as e:
-            if self.debug_logger:
-                self.debug_logger.log(
-                    level="ERROR",
-                    operation="hybrid_level5",
-                    message="Failed editing RPU Level 5 values",
-                    context={"error": str(e)},
-                )
+            log_event(
+                "hybrid_level5",
+                level="ERROR",
+                message="Failed editing RPU Level 5 values",
+                context={"error": str(e)},
+            )
             raise ValueError("Failed editing RPU Level 5 values")
 
-        if self.debug_logger:
-            self.debug_logger.log(
-                level="DEBUG",
-                operation="hybrid_level5",
-                message="Edited RPU Level 5 active area",
-                context={
-                    "crop": {"left": left, "right": right, "top": top, "bottom": bottom},
-                    "samples": len(crop_results),
-                },
-                success=True,
-            )
+        log_event(
+            "hybrid_level5",
+            level="DEBUG",
+            message="Edited RPU Level 5 active area",
+            context={
+                "crop": {"left": left, "right": right, "top": top, "bottom": bottom},
+                "samples": len(crop_results),
+            },
+            success=True,
+        )
         self.rpu_file = "RPU_L5.bin"
 
     @staticmethod
@@ -412,13 +400,12 @@ class Hybrid:
             with console.status("Reading RPU luminance metadata...", spinner="dots"):
                 info_text = dovi.info_summary(config.directories.temp / self.rpu_file)
         except RuntimeError as e:
-            if self.debug_logger:
-                self.debug_logger.log(
-                    level="ERROR",
-                    operation="hybrid_level6",
-                    message="Failed reading RPU metadata for Level 6 values",
-                    context={"error": str(e)},
-                )
+            log_event(
+                "hybrid_level6",
+                level="ERROR",
+                message="Failed reading RPU metadata for Level 6 values",
+                context={"error": str(e)},
+            )
             raise ValueError("Failed reading RPU metadata for Level 6 values")
 
         max_cll = None
@@ -455,13 +442,12 @@ class Hybrid:
         max_mdl, min_mdl, max_cll, max_fall = self.sanitize_l6(max_mdl, min_mdl, max_cll, max_fall)
 
         if any(v is None for v in (max_cll, max_fall, max_mdl, min_mdl)):
-            if self.debug_logger:
-                self.debug_logger.log(
-                    level="ERROR",
-                    operation="hybrid_level6",
-                    message="Could not extract Level 6 luminance data from RPU",
-                    context={"max_cll": max_cll, "max_fall": max_fall, "max_mdl": max_mdl, "min_mdl": min_mdl},
-                )
+            log_event(
+                "hybrid_level6",
+                level="ERROR",
+                message="Could not extract Level 6 luminance data from RPU",
+                context={"max_cll": max_cll, "max_fall": max_fall, "max_mdl": max_mdl, "min_mdl": min_mdl},
+            )
             raise ValueError("Could not extract Level 6 luminance data from RPU")
 
         level6_data = {
@@ -488,28 +474,26 @@ class Hybrid:
                 label="dovi_tool editor (L6)",
             )
         except RuntimeError as e:
-            if self.debug_logger:
-                self.debug_logger.log(
-                    level="ERROR",
-                    operation="hybrid_level6",
-                    message="Failed editing RPU Level 6 values",
-                    context={"error": str(e)},
-                )
+            log_event(
+                "hybrid_level6",
+                level="ERROR",
+                message="Failed editing RPU Level 6 values",
+                context={"error": str(e)},
+            )
             raise ValueError("Failed editing RPU Level 6 values")
 
-        if self.debug_logger:
-            self.debug_logger.log(
-                level="DEBUG",
-                operation="hybrid_level6",
-                message="Edited RPU Level 6 luminance values",
-                context={
-                    "max_cll": max_cll,
-                    "max_fall": max_fall,
-                    "max_mdl": max_mdl,
-                    "min_mdl": min_mdl,
-                },
-                success=True,
-            )
+        log_event(
+            "hybrid_level6",
+            level="DEBUG",
+            message="Edited RPU Level 6 luminance values",
+            context={
+                "max_cll": max_cll,
+                "max_fall": max_fall,
+                "max_mdl": max_mdl,
+                "min_mdl": min_mdl,
+            },
+            success=True,
+        )
         self.rpu_file = "RPU_L6.bin"
 
     def injecting(self):
@@ -525,28 +509,26 @@ class Hybrid:
                 label="dovi_tool inject-rpu",
             )
         except RuntimeError as e:
-            if self.debug_logger:
-                self.debug_logger.log(
-                    level="ERROR",
-                    operation="hybrid_inject_rpu",
-                    message="Failed injecting Dolby Vision metadata into HDR10 stream",
-                    context={"error": str(e)},
-                )
+            log_event(
+                "hybrid_inject_rpu",
+                level="ERROR",
+                message="Failed injecting Dolby Vision metadata into HDR10 stream",
+                context={"error": str(e)},
+            )
             raise ValueError("Failed injecting Dolby Vision metadata into HDR10 stream")
 
-        if self.debug_logger:
-            self.debug_logger.log(
-                level="DEBUG",
-                operation="hybrid_inject_rpu",
-                message=f"Injected Dolby Vision metadata into {self.hdr_type} stream",
-                context={
-                    "hdr_type": self.hdr_type,
-                    "rpu_file": self.rpu_file,
-                    "output": self.hevc_file,
-                    "drop_hdr10plus": self.hdr10plus_to_dv,
-                },
-                success=True,
-            )
+        log_event(
+            "hybrid_inject_rpu",
+            level="DEBUG",
+            message=f"Injected Dolby Vision metadata into {self.hdr_type} stream",
+            context={
+                "hdr_type": self.hdr_type,
+                "rpu_file": self.rpu_file,
+                "output": self.hevc_file,
+                "drop_hdr10plus": self.hdr10plus_to_dv,
+            },
+            success=True,
+        )
 
     def extract_hdr10plus(self, _video):
         """Extract HDR10+ metadata from the video stream"""
@@ -570,34 +552,31 @@ class Hybrid:
                 label="hdr10plus_tool extract",
             )
         except RuntimeError as e:
-            if self.debug_logger:
-                self.debug_logger.log(
-                    level="ERROR",
-                    operation="hybrid_extract_hdr10plus",
-                    message="Failed extracting HDR10+ metadata",
-                    context={"error": str(e)},
-                )
+            log_event(
+                "hybrid_extract_hdr10plus",
+                level="ERROR",
+                message="Failed extracting HDR10+ metadata",
+                context={"error": str(e)},
+            )
             raise ValueError("Failed extracting HDR10+ metadata")
 
         file_size = os.path.getsize(config.directories.temp / self.hdr10plus_file)
         if file_size == 0:
-            if self.debug_logger:
-                self.debug_logger.log(
-                    level="ERROR",
-                    operation="hybrid_extract_hdr10plus",
-                    message="No HDR10+ metadata found in the stream",
-                    context={"file_size": 0},
-                )
+            log_event(
+                "hybrid_extract_hdr10plus",
+                level="ERROR",
+                message="No HDR10+ metadata found in the stream",
+                context={"file_size": 0},
+            )
             raise ValueError("No HDR10+ metadata found in the stream")
 
-        if self.debug_logger:
-            self.debug_logger.log(
-                level="DEBUG",
-                operation="hybrid_extract_hdr10plus",
-                message="Extracted HDR10+ metadata",
-                context={"output": self.hdr10plus_file, "file_size": file_size},
-                success=True,
-            )
+        log_event(
+            "hybrid_extract_hdr10plus",
+            level="DEBUG",
+            message="Extracted HDR10+ metadata",
+            context={"output": self.hdr10plus_file, "file_size": file_size},
+            success=True,
+        )
 
     def _probe_hdr_metadata(self):
         """Extract mastering display and content light level metadata from the HDR10 stream via ffprobe.
@@ -649,13 +628,12 @@ class Hybrid:
             except (json.JSONDecodeError, KeyError, ValueError, ZeroDivisionError):
                 pass
 
-        if self.debug_logger:
-            self.debug_logger.log(
-                level="DEBUG",
-                operation="hybrid_probe_hdr_metadata",
-                message="Probed HDR metadata from source stream",
-                context={"max_mdl": max_mdl, "min_mdl": min_mdl, "max_cll": max_cll, "max_fall": max_fall},
-            )
+        log_event(
+            "hybrid_probe_hdr_metadata",
+            level="DEBUG",
+            message="Probed HDR metadata from source stream",
+            context={"max_mdl": max_mdl, "min_mdl": min_mdl, "max_cll": max_cll, "max_fall": max_fall},
+        )
 
         return max_mdl, min_mdl, max_cll, max_fall
 
@@ -692,22 +670,20 @@ class Hybrid:
                 label="dovi_tool generate",
             )
         except RuntimeError as e:
-            if self.debug_logger:
-                self.debug_logger.log(
-                    level="ERROR",
-                    operation="hybrid_convert_hdr10plus",
-                    message="Failed converting HDR10+ to Dolby Vision",
-                    context={"error": str(e)},
-                )
+            log_event(
+                "hybrid_convert_hdr10plus",
+                level="ERROR",
+                message="Failed converting HDR10+ to Dolby Vision",
+                context={"error": str(e)},
+            )
             raise ValueError("Failed converting HDR10+ to Dolby Vision")
 
-        if self.debug_logger:
-            self.debug_logger.log(
-                level="DEBUG",
-                operation="hybrid_convert_hdr10plus",
-                message="Converted HDR10+ metadata to Dolby Vision Profile 8",
-                success=True,
-            )
+        log_event(
+            "hybrid_convert_hdr10plus",
+            level="DEBUG",
+            message="Converted HDR10+ metadata to Dolby Vision Profile 8",
+            success=True,
+        )
 
         # Clean up temporary files
         Path.unlink(config.directories.temp / "extra.json")
diff --git a/unshackle/core/tracks/subtitle.py b/unshackle/core/tracks/subtitle.py
index 4a5ccd0..8130779 100644
--- a/unshackle/core/tracks/subtitle.py
+++ b/unshackle/core/tracks/subtitle.py
@@ -3,6 +3,7 @@ from __future__ import annotations
 import logging
 import re
 import subprocess
+import time
 from collections import defaultdict
 from enum import Enum
 from functools import partial
@@ -22,7 +23,8 @@ from subtitle_filter import Subtitles
 from unshackle.core import binaries
 from unshackle.core.config import config
 from unshackle.core.tracks.track import Track
-from unshackle.core.utilities import try_ensure_utf8
+from unshackle.core.utilities import get_debug_logger, log_event, try_ensure_utf8
+from unshackle.core.utils.subprocess import log_tool_run
 from unshackle.core.utils.webvtt import merge_segmented_webvtt
 
 # silence srt library INFO logging
@@ -622,7 +624,30 @@ class Subtitle(Track):
             config.subtitle.get("conversion_method") or getattr(self, "preferred_conversion_method", None) or "auto"
         )
         pin = None if method == "auto" else method
-        return run_conversion(self, codec, pin=pin, forced=forced)
+
+        dl = get_debug_logger()
+        if not dl:
+            return run_conversion(self, codec, pin=pin, forced=forced)
+
+        start = time.monotonic()
+        try:
+            result = run_conversion(self, codec, pin=pin, forced=forced)
+        except Exception as e:
+            dl.log_error(
+                "subtitle_convert",
+                e,
+                context={"from": str(self.codec), "to": str(codec), "method": method, "forced": forced},
+            )
+            raise
+        log_event(
+            "subtitle_convert",
+            level="INFO",
+            message=f"Converted subtitle {self.codec} -> {codec}",
+            context={"from": str(self.codec), "to": str(codec), "method": method, "forced": forced},
+            duration_ms=round((time.monotonic() - start) * 1000, 1),
+            success=True,
+        )
+        return result
 
     @staticmethod
     def extract_fonts(text: str) -> set[str]:
@@ -1036,6 +1061,7 @@ class Subtitle(Track):
             from unshackle.core.tracks.subtitle_convert import SUBTITLE_EDIT_FORMATS, subtitleedit_args
 
             output_format = SUBTITLE_EDIT_FORMATS.get(self.codec, self.codec.name.lower())
+            se_start = time.monotonic()
             subprocess.run(
                 subtitleedit_args(
                     binaries.SubtitleEdit, self.path, output_format, output_folder=self.path.parent, remove_hi=True
@@ -1044,6 +1070,13 @@ class Subtitle(Track):
                 stdout=subprocess.DEVNULL,
                 stderr=subprocess.DEVNULL,
             )
+            log_tool_run(
+                "SubtitleEdit strip SDH",
+                "SubtitleEdit",
+                0,
+                duration_ms=round((time.monotonic() - se_start) * 1000, 1),
+                format=output_format,
+            )
         else:
             if config.subtitle.get("convert_before_strip", True) and self.codec != Subtitle.Codec.SubRip:
                 self.path = self.convert(Subtitle.Codec.SubRip)
@@ -1088,6 +1121,7 @@ class Subtitle(Track):
 
         output_format = SUBTITLE_EDIT_FORMATS.get(self.codec, self.codec.name.lower())
 
+        se_start = time.monotonic()
         subprocess.run(
             subtitleedit_args(
                 binaries.SubtitleEdit, self.path, output_format, output_folder=self.path.parent, reverse_rtl=True
@@ -1096,6 +1130,13 @@ class Subtitle(Track):
             stdout=subprocess.DEVNULL,
             stderr=subprocess.DEVNULL,
         )
+        log_tool_run(
+            "SubtitleEdit reverse RTL",
+            "SubtitleEdit",
+            0,
+            duration_ms=round((time.monotonic() - se_start) * 1000, 1),
+            format=output_format,
+        )
 
 
 __all__ = ("Subtitle",)
diff --git a/unshackle/core/tracks/subtitle_convert.py b/unshackle/core/tracks/subtitle_convert.py
index 71f2273..3e9f1b7 100644
--- a/unshackle/core/tracks/subtitle_convert.py
+++ b/unshackle/core/tracks/subtitle_convert.py
@@ -16,6 +16,7 @@ from __future__ import annotations
 
 import logging
 import subprocess
+import time
 from pathlib import Path
 from typing import Optional, Protocol
 
@@ -25,6 +26,7 @@ from subby import CommonIssuesFixer, SAMIConverter, WebVTTConverter, WVTTConvert
 
 from unshackle.core import binaries
 from unshackle.core.tracks.subtitle import Subtitle
+from unshackle.core.utils.subprocess import log_tool_run
 
 log = logging.getLogger("subtitle")
 
@@ -146,7 +148,16 @@ class SubtitleEditBackend:
             output_folder=out.parent,
             convert_colors=(target == Codec.SubRip),
         )
+        se_start = time.monotonic()
         subprocess.run(args, check=True, stdout=subprocess.DEVNULL, stderr=subprocess.DEVNULL)
+        log_tool_run(
+            "SubtitleEdit convert",
+            "SubtitleEdit",
+            0,
+            duration_ms=round((time.monotonic() - se_start) * 1000, 1),
+            source=str(source),
+            target=str(target),
+        )
         # SE5 names the output <input-stem>.<format-ext>, which may differ from our target
         # suffix (e.g. timedtext1.0 -> .ttml). Normalise it onto `out`.
         if not out.exists():
diff --git a/unshackle/core/tracks/track.py b/unshackle/core/tracks/track.py
index daa1d9b..657f30e 100644
--- a/unshackle/core/tracks/track.py
+++ b/unshackle/core/tracks/track.py
@@ -24,7 +24,7 @@ from unshackle.core.downloaders import requests
 from unshackle.core.drm import DRM_T, PlayReady, Widevine
 from unshackle.core.events import events
 from unshackle.core.session import RnetSession
-from unshackle.core.utilities import get_boxes, try_ensure_utf8
+from unshackle.core.utilities import get_boxes, log_event, try_ensure_utf8
 from unshackle.core.utils.subprocess import ffprobe
 
 
@@ -766,6 +766,13 @@ class Track:
                 stderr=subprocess.PIPE,
             )
 
+        log_event(
+            "repackage",
+            level="DEBUG",
+            message=f"Repackaging {self.__class__.__name__} {original_path.name} with ffmpeg",
+            context={"track_type": self.__class__.__name__, "id": self.id, "file": original_path.name},
+        )
+
         try:
             _ffmpeg()
         except subprocess.CalledProcessError as e:
@@ -778,5 +785,17 @@ class Track:
         original_path.unlink()
         self.path = output_path
 
+        log_event(
+            "repackage_complete",
+            level="DEBUG",
+            message=f"Repackaged {self.__class__.__name__} -> {output_path.name}",
+            context={
+                "track_type": self.__class__.__name__,
+                "id": self.id,
+                "output": output_path.name,
+                "output_size": output_path.stat().st_size if output_path.exists() else 0,
+            },
+        )
+
 
 __all__ = ("Track",)
diff --git a/unshackle/core/tracks/tracks.py b/unshackle/core/tracks/tracks.py
index 5ed58d9..7907cd8 100644
--- a/unshackle/core/tracks/tracks.py
+++ b/unshackle/core/tracks/tracks.py
@@ -2,6 +2,7 @@ from __future__ import annotations
 
 import logging
 import subprocess
+import time
 from functools import partial
 from pathlib import Path
 from typing import Callable, Iterator, Optional, Sequence, Union
@@ -22,7 +23,7 @@ from unshackle.core.tracks.chapters import Chapter, Chapters
 from unshackle.core.tracks.subtitle import Subtitle
 from unshackle.core.tracks.track import Track
 from unshackle.core.tracks.video import Video
-from unshackle.core.utilities import get_debug_logger, is_close_match, sanitize_filename
+from unshackle.core.utilities import is_close_match, log_event, sanitize_filename
 from unshackle.core.utils.collections import as_list, flatten
 
 
@@ -662,69 +663,83 @@ class Tracks:
         if not output_path:
             raise ValueError("No tracks provided, at least one track must be provided.")
 
-        debug_logger = get_debug_logger()
-        if debug_logger:
-            debug_logger.log(
-                level="DEBUG",
-                operation="mux_start",
-                message="Starting mkvmerge muxing",
-                context={
-                    "title": title,
-                    "output_path": str(output_path),
-                    "video_count": len(self.videos),
-                    "audio_count": len(self.audio),
-                    "subtitle_count": len(self.subtitles),
-                    "attachment_count": len(self.attachments),
-                    "has_chapters": bool(self.chapters),
-                    "video_tracks": [
-                        {"id": v.id, "codec": getattr(v, "codec", None), "language": str(v.language)}
-                        for v in self.videos
-                    ],
-                    "audio_tracks": [
-                        {"id": a.id, "codec": getattr(a, "codec", None), "language": str(a.language)}
-                        for a in self.audio
-                    ],
-                    "subtitle_tracks": [
-                        {"id": s.id, "codec": getattr(s, "codec", None), "language": str(s.language)}
-                        for s in self.subtitles
-                    ],
-                },
-            )
+        full_command = [*cl, "--output", str(output_path), "--gui-mode"]
+
+        log_event(
+            "mux_start",
+            level="INFO",
+            message=(f"Muxing {len(self.videos)}V/{len(self.audio)}A/{len(self.subtitles)}S " f"-> {output_path.name}"),
+            context={
+                "title": title,
+                "output_path": str(output_path),
+                "muxer": str(binaries.MKVToolNix),
+                "command": full_command,
+                "video_count": len(self.videos),
+                "audio_count": len(self.audio),
+                "subtitle_count": len(self.subtitles),
+                "attachment_count": len(self.attachments),
+                "has_chapters": bool(self.chapters),
+                "video_tracks": [
+                    {"id": v.id, "codec": getattr(v, "codec", None), "language": str(v.language)} for v in self.videos
+                ],
+                "audio_tracks": [
+                    {"id": a.id, "codec": getattr(a, "codec", None), "language": str(a.language)} for a in self.audio
+                ],
+                "subtitle_tracks": [
+                    {"id": s.id, "codec": getattr(s, "codec", None), "language": str(s.language)}
+                    for s in self.subtitles
+                ],
+            },
+        )
 
         # let potential failures go to caller, caller should handle
         try:
             errors = []
-            p = subprocess.Popen([*cl, "--output", str(output_path), "--gui-mode"], text=True, stdout=subprocess.PIPE)
+            warnings = []
+            mux_start_time = time.monotonic()
+            p = subprocess.Popen(full_command, text=True, stdout=subprocess.PIPE)
             for line in iter(p.stdout.readline, ""):
                 if line.startswith("#GUI#error") or line.startswith("#GUI#warning"):
                     errors.append(line)
+                    if line.startswith("#GUI#warning"):
+                        warnings.append(line.strip())
                 if "progress" in line:
                     progress(total=100, completed=int(line.strip()[14:-1]))
 
             returncode = p.wait()
+            mux_duration_ms = round((time.monotonic() - mux_start_time) * 1000, 1)
+            output_size = output_path.stat().st_size if output_path and output_path.exists() else 0
 
-            if debug_logger:
-                if returncode != 0 or errors:
-                    debug_logger.log(
-                        level="ERROR",
-                        operation="mux_failed",
-                        message=f"mkvmerge exited with code {returncode}",
-                        context={
-                            "returncode": returncode,
-                            "output_path": str(output_path),
-                            "errors": errors,
-                        },
-                    )
-                else:
-                    debug_logger.log(
-                        level="DEBUG",
-                        operation="mux_complete",
-                        message="mkvmerge muxing completed successfully",
-                        context={
-                            "output_path": str(output_path),
-                            "output_exists": output_path.exists() if output_path else False,
-                        },
-                    )
+            if returncode != 0 or errors:
+                log_event(
+                    "mux_failed",
+                    level="ERROR",
+                    message=f"mkvmerge exited with code {returncode}",
+                    context={
+                        "returncode": returncode,
+                        "output_path": str(output_path),
+                        "errors": errors,
+                        "warnings": warnings,
+                        "duration_ms": mux_duration_ms,
+                    },
+                )
+            else:
+                log_event(
+                    "mux_complete",
+                    level="INFO",
+                    message=(
+                        f"Muxed {output_path.name} ({output_size} bytes) in {mux_duration_ms}ms"
+                        + (f" with {len(warnings)} warning(s)" if warnings else "")
+                    ),
+                    context={
+                        "output_path": str(output_path),
+                        "output_exists": output_path.exists() if output_path else False,
+                        "output_size": output_size,
+                        "duration_ms": mux_duration_ms,
+                        "returncode": returncode,
+                        "warnings": warnings,
+                    },
+                )
 
             return output_path, returncode, errors
         finally:
diff --git a/unshackle/core/tracks/video.py b/unshackle/core/tracks/video.py
index 71ed529..6f68039 100644
--- a/unshackle/core/tracks/video.py
+++ b/unshackle/core/tracks/video.py
@@ -4,6 +4,7 @@ import logging
 import math
 import re
 import subprocess
+import time
 from enum import Enum
 from pathlib import Path
 from typing import Any, Optional, Union
@@ -14,7 +15,8 @@ from unshackle.core import binaries
 from unshackle.core.config import config
 from unshackle.core.tracks.subtitle import Subtitle
 from unshackle.core.tracks.track import Track
-from unshackle.core.utilities import FPS, get_boxes
+from unshackle.core.utilities import FPS, get_boxes, log_event
+from unshackle.core.utils.subprocess import log_tool_run
 
 
 class Video(Track):
@@ -379,6 +381,7 @@ class Video(Track):
         original_path = self.path
         output_path = original_path.with_stem(f"{original_path.stem}_{['limited', 'full'][range_]}_range")
 
+        range_start = time.monotonic()
         subprocess.run(
             [
                 binaries.FFMPEG,
@@ -395,6 +398,14 @@ class Video(Track):
             ],
             check=True,
         )
+        log_tool_run(
+            "ffmpeg change range",
+            "ffmpeg",
+            0,
+            duration_ms=round((time.monotonic() - range_start) * 1000, 1),
+            codec=str(self.codec),
+            full_range=bool(range_),
+        )
 
         self.path = output_path
         original_path.unlink()
@@ -458,6 +469,18 @@ class Video(Track):
 
         self.path = output_path
         original_path.unlink()
+
+        log_event(
+            "normalize_vui",
+            level="DEBUG",
+            message=f"Rewrote {self.codec} VUI colour metadata to match {self.range}",
+            context={
+                "codec": str(self.codec),
+                "range": str(self.range),
+                "vui": {"primaries": primaries, "transfer": transfer, "matrix": matrix},
+                "id": self.id,
+            },
+        )
         return True
 
     def ccextractor(
@@ -473,6 +496,7 @@ class Video(Track):
         out_path = Path(out_path)
 
         def _run_ccextractor() -> bool:
+            cc_start = time.monotonic()
             try:
                 subprocess.run(
                     [binaries.CCExtractor, "-trim", "-nobom", "-noru", "-ru1", "-o", out_path, self.path],
@@ -482,8 +506,21 @@ class Video(Track):
                 )
             except subprocess.CalledProcessError as e:
                 out_path.unlink(missing_ok=True)
+                log_tool_run(
+                    "ccextractor",
+                    "ccextractor",
+                    e.returncode,
+                    duration_ms=round((time.monotonic() - cc_start) * 1000, 1),
+                )
                 if e.returncode != 10:  # 10 = No captions found
                     raise
+                return out_path.exists()
+            log_tool_run(
+                "ccextractor",
+                "ccextractor",
+                0,
+                duration_ms=round((time.monotonic() - cc_start) * 1000, 1),
+            )
             return out_path.exists()
 
         # Try on the original file first (preserves container-level CC data like c608 boxes),
@@ -578,6 +615,7 @@ class Video(Track):
 
         original_path = self.path
         cleaned_path = original_path.with_suffix(f".cleaned{original_path.suffix}")
+        eia_start = time.monotonic()
         subprocess.run(
             [
                 binaries.FFMPEG,
@@ -598,6 +636,12 @@ class Video(Track):
             ],
             check=True,
         )
+        log_tool_run(
+            "ffmpeg remove EIA-CC",
+            "ffmpeg",
+            0,
+            duration_ms=round((time.monotonic() - eia_start) * 1000, 1),
+        )
 
         log.info(" + Removed")
 
diff --git a/unshackle/core/utilities.py b/unshackle/core/utilities.py
index 55c6b9f..572bfd0 100644
--- a/unshackle/core/utilities.py
+++ b/unshackle/core/utilities.py
@@ -30,7 +30,7 @@ from unidecode import unidecode
 
 from unshackle.core.config import config
 from unshackle.core.constants import LANGUAGE_EXACT_DISTANCE, LANGUAGE_MAX_DISTANCE
-from unshackle.core.utils.redact import redact_text
+from unshackle.core.utils.redact import redact_all
 
 """
 Utility functions for the unshackle media archival tool.
@@ -837,7 +837,7 @@ class DebugLogger:
         if operation:
             entry["operation"] = operation
         if message:
-            entry["message"] = redact_text(message)
+            entry["message"] = redact_all(message)
         if service:
             entry["service"] = service
         if context:
@@ -854,9 +854,9 @@ class DebugLogger:
         if error:
             entry["error"] = {
                 "type": type(error).__name__,
-                "message": redact_text(str(error)),
+                "message": redact_all(str(error)),
                 "traceback": [
-                    redact_text(line) for line in traceback.format_exception(type(error), error, error.__traceback__)
+                    redact_all(line) for line in traceback.format_exception(type(error), error, error.__traceback__)
                 ],
             }
 
@@ -879,9 +879,8 @@ class DebugLogger:
             return None
 
         if isinstance(data, str):
-            # mask URL userinfo and secret-bearing query params that key-based
-            # redaction can't catch (e.g. a proxy URL inside a non-sensitive field)
-            return redact_text(data)
+            # mask secrets, collapse content/CDN URLs, and strip local path prefixes
+            return redact_all(data)
 
         if isinstance(data, (int, float, bool)):
             return data
@@ -920,7 +919,7 @@ class DebugLogger:
                 return "[BINARY_DATA]"
 
         if isinstance(data, Path):
-            return str(data)
+            return redact_all(str(data))
 
         try:
             return str(data)
@@ -980,7 +979,9 @@ class DebugLogger:
             url: Request URL
             **kwargs: Additional request details (headers, body, etc.)
         """
-        self.log(level="DEBUG", operation="service_call", request={"method": method, "url": url, **kwargs})
+        message = kwargs.pop("message", "")
+        level = kwargs.pop("level", "DEBUG")
+        self.log(level=level, operation="service_call", message=message, request={"method": method, "url": url, **kwargs})
 
     def log_drm_operation(self, drm_type: str, operation: str, **kwargs):
         """
@@ -989,11 +990,11 @@ class DebugLogger:
         Args:
             drm_type: DRM type (Widevine, PlayReady, etc.)
             operation: DRM operation name
-            **kwargs: Additional context (PSSH, KIDs, keys, etc.)
+            **kwargs: Additional context. Pass ``message=``/``level=`` to override the defaults.
         """
-        self.log(
-            level="DEBUG", operation=f"drm_{operation}", message=f"{drm_type} {operation}", drm_type=drm_type, **kwargs
-        )
+        message = kwargs.pop("message", None) or f"{drm_type} {operation}"
+        level = kwargs.pop("level", "DEBUG")
+        self.log(level=level, operation=f"drm_{operation}", message=message, drm_type=drm_type, **kwargs)
 
     def log_vault_query(self, vault_name: str, operation: str, **kwargs):
         """
@@ -1002,12 +1003,14 @@ class DebugLogger:
         Args:
             vault_name: Name of the vault
             operation: Vault operation (get_key, add_key, etc.)
-            **kwargs: Additional context (KID, key, success, etc.)
+            **kwargs: Additional context. Pass ``message=``/``level=`` to override the defaults.
         """
+        message = kwargs.pop("message", None) or f"Vault {vault_name}: {operation}"
+        level = kwargs.pop("level", "DEBUG")
         self.log(
-            level="DEBUG",
+            level=level,
             operation=f"vault_{operation}",
-            message=f"Vault {vault_name}: {operation}",
+            message=message,
             vault=vault_name,
             **kwargs,
         )
@@ -1047,6 +1050,59 @@ def get_debug_logger() -> Optional[DebugLogger]:
     return _debug_logger
 
 
+def log_event(operation: str, *, level: str = "DEBUG", message: str = "", **kwargs: Any) -> None:
+    """Emit a single structured debug-log entry. No-op when debug logging is disabled.
+
+    The canonical one-shot logging primitive — replaces the
+    ``if dl := get_debug_logger(): dl.log(...)`` guard boilerplate. To add logging to a new
+    feature, call ``log_event("my_feature_event", message="...", context={...})``.
+    """
+    dl = _debug_logger
+    if dl:
+        dl.log(level=level, operation=operation, message=message, **kwargs)
+
+
+@contextlib.contextmanager
+def timed_operation(operation: str, *, level: str = "DEBUG", message: str = "", **kwargs: Any):
+    """Time a block and log ``operation`` once it finishes, with ``duration_ms``.
+
+    Logs at ``level`` with ``success=True`` on normal exit, or at ERROR with the exception and
+    ``success=False`` if the block raises (then re-raises). No-op when debug logging is disabled,
+    so it is always safe to wrap a block in it.
+
+    Example::
+
+        with timed_operation("mux", context={"output": str(path)}):
+            run_mkvmerge(...)
+    """
+    dl = _debug_logger
+    if not dl:
+        yield
+        return
+    start = time.monotonic()
+    try:
+        yield
+    except Exception as e:
+        dl.log(
+            level="ERROR",
+            operation=operation,
+            message=message or f"{operation} failed",
+            error=e,
+            success=False,
+            duration_ms=round((time.monotonic() - start) * 1000, 1),
+            **kwargs,
+        )
+        raise
+    dl.log(
+        level=level,
+        operation=operation,
+        message=message,
+        success=True,
+        duration_ms=round((time.monotonic() - start) * 1000, 1),
+        **kwargs,
+    )
+
+
 def init_debug_logger(log_path: Optional[Path] = None, enabled: bool = False, log_keys: bool = False):
     """
     Initialize the global debug logger.
@@ -1075,4 +1131,6 @@ __all__ = (
     "get_debug_logger",
     "init_debug_logger",
     "close_debug_logger",
+    "log_event",
+    "timed_operation",
 )
diff --git a/unshackle/core/utils/bitrate.py b/unshackle/core/utils/bitrate.py
index 501b211..d6a41e4 100644
--- a/unshackle/core/utils/bitrate.py
+++ b/unshackle/core/utils/bitrate.py
@@ -3,6 +3,7 @@ from __future__ import annotations
 import json
 import logging
 import subprocess
+import time
 from collections import OrderedDict, defaultdict
 from concurrent.futures import ThreadPoolExecutor
 from dataclasses import dataclass
@@ -13,6 +14,7 @@ from requests import Session
 
 from unshackle.core.binaries import FFProbe
 from unshackle.core.session import RnetSession
+from unshackle.core.utils.subprocess import log_tool_run
 
 if TYPE_CHECKING:
     from unshackle.core.tracks import Track
@@ -421,6 +423,7 @@ def probe_bytes_duration(data: Optional[bytes], log: logging.Logger) -> Optional
         return None
     ffprobe_bin = str(FFProbe) if FFProbe else "ffprobe"
     try:
+        probe_start = time.monotonic()
         result = subprocess.run(
             [ffprobe_bin, "-v", "error", "-show_entries", "format=duration:stream=duration", "-of", "json", "pipe:"],
             input=data,
@@ -428,6 +431,12 @@ def probe_bytes_duration(data: Optional[bytes], log: logging.Logger) -> Optional
             stderr=subprocess.PIPE,
             timeout=60,
         )
+        log_tool_run(
+            "ffprobe duration probe",
+            "ffprobe",
+            result.returncode,
+            duration_ms=round((time.monotonic() - probe_start) * 1000, 1),
+        )
         info = json.loads(result.stdout or b"{}")
         candidates = [info.get("format", {}).get("duration")]
         candidates += [s.get("duration") for s in info.get("streams", [])]
diff --git a/unshackle/core/utils/dovi.py b/unshackle/core/utils/dovi.py
index 190e599..3bd002e 100644
--- a/unshackle/core/utils/dovi.py
+++ b/unshackle/core/utils/dovi.py
@@ -13,11 +13,12 @@ re-implement subprocess plumbing per call site. Each wrapper:
 from __future__ import annotations
 
 import subprocess
+import time
 from pathlib import Path
 from typing import Optional
 
 from unshackle.core import binaries
-from unshackle.core.utils.subprocess import run_step
+from unshackle.core.utils.subprocess import log_tool_run, run_step
 
 
 def _require_dovi_tool() -> str:
@@ -82,7 +83,14 @@ def editor(
 def info_summary(rpu: Path) -> str:
     """Return the textual summary (`dovi_tool info -i ... -s`) for an RPU file."""
     tool = _require_dovi_tool()
+    info_start = time.monotonic()
     p = subprocess.run([tool, "info", "-i", str(rpu), "-s"], capture_output=True, text=True)
+    log_tool_run(
+        "dovi_tool info",
+        "dovi_tool",
+        p.returncode,
+        duration_ms=round((time.monotonic() - info_start) * 1000, 1),
+    )
     if p.returncode != 0:
         raise RuntimeError(f"dovi_tool info failed: {(p.stderr or '')[-400:]}")
     return p.stdout
diff --git a/unshackle/core/utils/redact.py b/unshackle/core/utils/redact.py
index ebb04da..28ac7fa 100644
--- a/unshackle/core/utils/redact.py
+++ b/unshackle/core/utils/redact.py
@@ -3,6 +3,8 @@
 from __future__ import annotations
 
 import re
+import sys
+from pathlib import Path
 from typing import Iterable, Optional
 from urllib.parse import urlsplit, urlunsplit
 
@@ -37,3 +39,87 @@ def safe_display_url(url: str) -> str:
     if parts.port:
         netloc += f":{parts.port}"
     return urlunsplit((parts.scheme, netloc, parts.path, "", ""))
+
+
+def _path_bases() -> list[tuple[str, str]]:
+    """Local base directories to strip from logged paths, longest-first.
+
+    Anchors everything left of the unshackle install/root (and the venv / home dir) so an
+    absolute path like ``/home/me/Projects/unshackle-live/temp`` logs as ``<unshackle>/temp``,
+    hiding the username and machine layout on both Linux and Windows.
+    """
+    candidates: list[tuple[str, str]] = []
+    try:
+        # redact.py lives at <root>/unshackle/core/utils/redact.py -> parents[3] == project/install root
+        candidates.append((str(Path(__file__).resolve().parents[3]), "<unshackle>"))
+    except Exception:
+        pass
+    for raw in (getattr(sys, "prefix", ""), getattr(sys, "base_prefix", "")):
+        if raw:
+            candidates.append((str(Path(raw)), "<venv>"))
+    try:
+        candidates.append((str(Path.home()), "~"))
+    except Exception:
+        pass
+
+    bases: list[tuple[str, str]] = []
+    seen: set[str] = set()
+    for base, token in candidates:
+        # cover both separator conventions (a path may be logged with / even on Windows)
+        for variant in (base, base.replace("\\", "/"), base.replace("/", "\\")):
+            if variant and variant not in seen:
+                seen.add(variant)
+                bases.append((variant, token))
+    bases.sort(key=lambda item: len(item[0]), reverse=True)
+    return bases
+
+
+_PATH_BASES = _path_bases()
+
+
+def redact_path(text: Optional[str]) -> Optional[str]:
+    """Replace local base-directory prefixes (install root, venv, home) in ``text`` with tokens.
+
+    Idempotent and cheap; only touches strings that actually contain a known base dir, so URLs
+    and relative paths pass through unchanged.
+    """
+    if not isinstance(text, str) or not text:
+        return text
+    for base, token in _PATH_BASES:
+        if base in text:
+            text = text.replace(base, token)
+    return text
+
+
+# any http(s) URL embedded in free text (content/manifest/segment/api locations)
+URL_RE = re.compile(r"https?://[^\s\"'<>\\]+", re.IGNORECASE)
+# a plausible file extension to preserve (e.g. .mpd, .m3u8, .mp4, .m4s, .vtt)
+_EXT_RE = re.compile(r"^\.[A-Za-z0-9]{1,5}$")
+
+
+def _collapse_url(match: "re.Match[str]") -> str:
+    url = match.group(0)
+    try:
+        suffix = Path(urlsplit(url).path).suffix
+    except Exception:
+        suffix = ""
+    if not _EXT_RE.match(suffix):
+        suffix = ""
+    return f"redacted{suffix}"
+
+
+def redact_url(text: Optional[str]) -> Optional[str]:
+    """Collapse every http(s) URL in ``text`` to ``redacted[.ext]``.
+
+    Hides content/CDN/manifest/segment/api locations (host + path + query) from shareable debug
+    logs while keeping the file extension so the manifest/segment type stays visible
+    (e.g. ``redacted.mpd``). Non-URL strings pass through unchanged.
+    """
+    if not isinstance(text, str) or not text:
+        return text
+    return URL_RE.sub(_collapse_url, text)
+
+
+def redact_all(text: Optional[str]) -> Optional[str]:
+    """Full redaction for logged strings: secrets, then URLs, then local path prefixes."""
+    return redact_path(redact_url(redact_text(text)))
diff --git a/unshackle/core/utils/subprocess.py b/unshackle/core/utils/subprocess.py
index 89cae9f..4189dc6 100644
--- a/unshackle/core/utils/subprocess.py
+++ b/unshackle/core/utils/subprocess.py
@@ -1,10 +1,43 @@
 import json
 import subprocess
+import time
 from pathlib import Path
 from typing import Optional, Sequence, Union
 
 from unshackle.core import binaries
 from unshackle.core.console import console
+from unshackle.core.utilities import get_debug_logger
+
+
+def log_tool_run(
+    label: str,
+    tool: Optional[str],
+    returncode: Optional[int],
+    *,
+    duration_ms: Optional[float] = None,
+    **context: object,
+) -> None:
+    """Emit a structured ``tool_run`` debug-log entry for an external tool invocation.
+
+    Central helper so every binary call (ffmpeg, mkvpropedit, dovi_tool, etc.) logs the
+    same shape. No-op when debug logging is disabled.
+    """
+    dl = get_debug_logger()
+    if not dl:
+        return
+    failed = bool(returncode)
+    dl.log(
+        level="ERROR" if failed else "DEBUG",
+        operation="tool_run",
+        message=f"{label} {'failed' if failed else 'ok'}",
+        context={
+            "label": label,
+            "tool": tool,
+            "returncode": returncode,
+            "duration_ms": duration_ms,
+            **context,
+        },
+    )
 
 
 def ffprobe(uri: Union[bytes, Path]) -> dict:
@@ -19,11 +52,33 @@ def ffprobe(uri: Union[bytes, Path]) -> dict:
         )
     elif isinstance(uri, bytes):
         args.append("pipe:")
+
+    dl = get_debug_logger()
+    start = time.monotonic()
     try:
         ff = subprocess.run(args, input=uri if isinstance(uri, bytes) else None, check=True, capture_output=True)
     except subprocess.CalledProcessError:
+        if dl:
+            dl.log(
+                level="DEBUG",
+                operation="tool_run",
+                message="ffprobe failed",
+                context={"tool": "ffprobe", "duration_ms": round((time.monotonic() - start) * 1000, 1)},
+            )
         return {}
-    return json.loads(ff.stdout.decode("utf8"))
+    result = json.loads(ff.stdout.decode("utf8"))
+    if dl:
+        dl.log(
+            level="DEBUG",
+            operation="tool_run",
+            message=f"ffprobe found {len(result.get('streams', []))} stream(s)",
+            context={
+                "tool": "ffprobe",
+                "streams": len(result.get("streams", [])),
+                "duration_ms": round((time.monotonic() - start) * 1000, 1),
+            },
+        )
+    return result
 
 
 def run_step(
@@ -42,6 +97,7 @@ def run_step(
         output.unlink(missing_ok=True)
 
     str_args = [str(a) for a in args]
+    start = time.monotonic()
     if status:
         with console.status(status, spinner="dots"):
             p = subprocess.run(str_args, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
@@ -50,7 +106,26 @@ def run_step(
 
     stderr = p.stderr or b""
     bad_output = output is not None and (not output.exists() or output.stat().st_size == 0)
-    if p.returncode or bad_output:
+    failed = bool(p.returncode or bad_output)
+
+    if dl := get_debug_logger():
+        dl.log(
+            level="ERROR" if failed else "DEBUG",
+            operation="tool_run",
+            message=f"{label} {'failed' if failed else 'ok'}",
+            context={
+                "label": label,
+                "tool": Path(str_args[0]).name if str_args else None,
+                "arg_count": len(str_args),
+                "returncode": p.returncode,
+                "duration_ms": round((time.monotonic() - start) * 1000, 1),
+                "output": str(output) if output else None,
+                "output_size": output.stat().st_size if output and output.exists() else 0,
+                "bad_output": bad_output,
+            },
+        )
+
+    if failed:
         if output is not None:
             output.unlink(missing_ok=True)
         raise RuntimeError(f"{label} failed: {stderr.decode(errors='replace')[-400:]}")
diff --git a/unshackle/core/utils/tags.py b/unshackle/core/utils/tags.py
index 86db1c1..d756f80 100644
--- a/unshackle/core/utils/tags.py
+++ b/unshackle/core/utils/tags.py
@@ -3,6 +3,7 @@ from __future__ import annotations
 import logging
 import subprocess
 import tempfile
+import time
 from pathlib import Path
 from typing import Optional
 from xml.sax.saxutils import escape
@@ -14,6 +15,7 @@ from unshackle.core.providers import (ExternalIds, MetadataResult, enrich_ids, f
 from unshackle.core.titles.episode import Episode
 from unshackle.core.titles.movie import Movie
 from unshackle.core.titles.title import Title
+from unshackle.core.utils.subprocess import log_tool_run
 
 log = logging.getLogger("TAGS")
 
@@ -33,12 +35,21 @@ def apply_tags(path: Path, tags: dict[str, str]) -> None:
         f.write("\n".join(xml_lines))
         tmp_path = Path(f.name)
     try:
+        tag_start = time.monotonic()
         result = subprocess.run(
             [str(binaries.Mkvpropedit), str(path), "--tags", f"global:{tmp_path}"],
             check=False,
             capture_output=True,
             text=True,
         )
+        log_tool_run(
+            "mkvpropedit tags",
+            "mkvpropedit",
+            result.returncode,
+            duration_ms=round((time.monotonic() - tag_start) * 1000, 1),
+            file=Path(path).name,
+            tag_count=len(tags),
+        )
         if result.returncode != 0:
             log.warning("mkvpropedit failed (exit %d): %s", result.returncode, result.stderr.strip())
         else:
diff --git a/unshackle/core/vaults.py b/unshackle/core/vaults.py
index 00c2728..3db74ec 100644
--- a/unshackle/core/vaults.py
+++ b/unshackle/core/vaults.py
@@ -1,9 +1,10 @@
 import logging
+import time
 from typing import Any, Iterator, Optional, Union
 from uuid import UUID
 
 from unshackle.core.config import config
-from unshackle.core.utilities import import_module_by_path
+from unshackle.core.utilities import get_debug_logger, import_module_by_path
 from unshackle.core.vault import Vault
 
 log = logging.getLogger(__name__)
@@ -50,29 +51,56 @@ class Vaults:
 
     def get_key(self, kid: Union[UUID, str]) -> tuple[Optional[str], Optional[Vault]]:
         """Get Key from the first Vault it can by KID (Key ID) and Service."""
+        dl = get_debug_logger()
         for vault in self.vaults:
+            start = time.monotonic()
             try:
                 key = vault.get_key(kid, self.service)
             except (PermissionError, NotImplementedError):
                 continue
             except Exception as e:
                 log.warning(f"Failed to get key from Vault '{vault.name}': {e}")
+                if dl:
+                    dl.log_vault_query(
+                        vault.name,
+                        "get_key",
+                        kid=str(kid),
+                        reachable=False,
+                        error=e,
+                        duration_ms=round((time.monotonic() - start) * 1000, 1),
+                    )
                 continue
-            if key and key.count("0") != len(key):
+            found = bool(key and key.count("0") != len(key))
+            if dl:
+                dl.log_vault_query(
+                    vault.name,
+                    "get_key",
+                    kid=str(kid),
+                    key_found=found,
+                    reachable=True,
+                    duration_ms=round((time.monotonic() - start) * 1000, 1),
+                )
+            if found:
                 return key, vault
         return None, None
 
     def add_key(self, kid: Union[UUID, str], key: str, excluding: Optional[Vault] = None) -> int:
         """Add a KID:KEY to all Vaults, optionally with an exclusion."""
+        dl = get_debug_logger()
         success = 0
         for vault in self.vaults:
             if vault != excluding and not vault.no_push:
                 try:
-                    success += vault.add_key(self.service, kid, key)
+                    added = vault.add_key(self.service, kid, key)
+                    success += added
+                    if dl:
+                        dl.log_vault_query(vault.name, "add_key", kid=str(kid), success=bool(added))
                 except (PermissionError, NotImplementedError):
                     pass
                 except Exception as e:
                     log.warning(f"Failed to add key to Vault '{vault.name}': {e}")
+                    if dl:
+                        dl.log_vault_query(vault.name, "add_key", kid=str(kid), success=False, error=e)
         return success
 
     def add_keys(self, kid_keys: dict[Union[UUID, str], str]) -> int: