diff --git a/CHANGELOG.md b/CHANGELOG.md index 1c0583c..2112cff 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -90,9 +90,12 @@ All notable changes to this project are documented here. The format follows ### Fixed -- Broad `except Exception: pass` handlers are gone from the database layer, - recorder, worker and clip engine; 46 such handlers remain elsewhere (18 in - the web UI, the rest in storage providers and API clients). +- Broad `except Exception: pass` handlers are gone from the whole code base + (database layer, recorder, worker, clip engine, web UI, storage providers + and API clients). The failures they hid are now caught by class and logged; + fallback values are unchanged. +- A deleted VOD or clip whose file was still on disk opened in the player: + the tombstone check's `abort(404)` was swallowed by its own error handler. - A fresh database no longer logs a bogus `users.role` migration warning. ## [0.1.0] - 2026-11-09 diff --git a/WEBUI/webui.py b/WEBUI/webui.py index ef4c3ff..21d4ea1 100644 --- a/WEBUI/webui.py +++ b/WEBUI/webui.py @@ -3,6 +3,7 @@ import bisect import glob import hashlib +import http.client import ipaddress import json import logging @@ -1721,8 +1722,8 @@ def current_user_bypasses_maintenance() -> bool: username = session.get("username") if username and site_maintenance.is_user_exempt(username, current_user_role()): return True - except Exception: - pass + except (OSError, ValueError) as exc: + logging.warning("Maintenance bypass check failed, treating user as not exempt: %s", exc) return False @@ -2580,16 +2581,16 @@ def list_all_streamer_folders(): folders.add(name) if arch and not is_system_backup_slug(arch): folders.add(arch) - except Exception: - pass + except sqlite3.Error as exc: + logging.warning("Folder list without channel configs (database error): %s", exc) rows = [] profiles = load_profiles() configs = {} try: configs = {c.get("name"): c for c in database.list_channel_configs()} - except Exception: - pass + except sqlite3.Error as exc: + logging.warning("Folder list cannot mark stream channels (database error): %s", exc) for f in sorted(folders, key=lambda s: s.lower()): p_data = profiles.get(f) or {} @@ -2649,6 +2650,13 @@ def list_system_backups(): return sorted(items.values(), key=lambda x: x["mtime"], reverse=True) +def _twitch_gql_user(data): + """The `data.user` object of a Twitch GQL answer, or None for any other shape.""" + inner = data.get("data") if isinstance(data, dict) else None + user = inner.get("user") if isinstance(inner, dict) else None + return user if isinstance(user, dict) and user else None + + def get_twitch_profile_and_banner(channel): query = { "query": """ @@ -2674,11 +2682,12 @@ def get_twitch_profile_and_banner(channel): ) with urllib.request.urlopen(req, timeout=5) as resp: data = json.loads(resp.read().decode('utf-8')) - if data and "data" in data and data["data"].get("user"): - u = data["data"]["user"] - return u.get("profileImageURL"), u.get("bannerImageURL") - except Exception: - pass + except (OSError, ValueError, http.client.HTTPException) as exc: + logging.warning("Twitch profile lookup for %s failed: %s", channel, exc) + return None, None + user = _twitch_gql_user(data) + if user: + return user.get("profileImageURL"), user.get("bannerImageURL") return None, None def get_twitch_profile_image(channel): @@ -2747,12 +2756,14 @@ def get_twitch_user_id(channel): ) with urllib.request.urlopen(req, timeout=5) as resp: data = json.loads(resp.read().decode("utf-8")) - user_id = data.get("data", {}).get("user", {}).get("id") if isinstance(data, dict) else None - if user_id: - TWITCH_USER_ID_CACHE[login] = {"id": str(user_id), "ts": now} - return str(user_id) - except Exception: - pass + except (OSError, ValueError, http.client.HTTPException) as exc: + logging.warning("Twitch user id lookup for %s failed: %s", login, exc) + data = None + user = _twitch_gql_user(data) + user_id = user.get("id") if user else None + if user_id: + TWITCH_USER_ID_CACHE[login] = {"id": str(user_id), "ts": now} + return str(user_id) TWITCH_USER_ID_CACHE[login] = {"id": None, "ts": now} return None @@ -4756,23 +4767,20 @@ def can_view_streamer(streamer): return False candidates = {str(streamer).strip().lower()} - try: - norm = normalize_channel_name(streamer) - if norm: - candidates.add(norm.lower()) - except Exception: - pass + norm = normalize_channel_name(streamer) + if norm: + candidates.add(norm.lower()) try: arch = archive_name_for(streamer) if arch: candidates.add(arch.lower()) - except Exception: - pass + except sqlite3.Error as exc: + logging.warning("Access check for %s without archive name (database error): %s", streamer, exc) try: for s in related_archive_slugs(streamer) or []: candidates.add(str(s).strip().lower()) - except Exception: - pass + except sqlite3.Error as exc: + logging.warning("Access check for %s without archive aliases (database error): %s", streamer, exc) # 1. Check disabled_channels (Folder explicitly shut off / disabled) disabled_set = ctx.get("disabled_channels") or set() @@ -4827,18 +4835,22 @@ def abort_deleted_media(streamer, filename, file_id=None): slugs = set() try: slugs.update(related_archive_slugs(streamer) or []) - except Exception: - pass + except sqlite3.Error as exc: + logging.warning("Tombstone check for %s/%s without aliases (database error): %s", streamer, name, exc) primary = archive_name_for(streamer) or str(streamer or "").strip() if primary: slugs.add(primary) if streamer: slugs.add(str(streamer).strip()) try: - if database.is_deleted_media(filename=name, file_id=file_id, streamers=slugs): - abort(404) - except Exception: - pass + deleted = database.is_deleted_media(filename=name, file_id=file_id, streamers=slugs) + except sqlite3.Error as exc: + # Same outcome as before: without the tombstone table the file + # itself decides (resolve_media_path still 404s a missing file). + logging.warning("Tombstone check for %s/%s failed, serving: %s", streamer, name, exc) + return + if deleted: + abort(404) def visible_streamers(streamers=None): @@ -5776,8 +5788,8 @@ def read_media_sidecar_metadata(media_path): m_w = re.search(r"(?:Neuer Status|Stream-Titel):\s*(.+)$", msg, re.IGNORECASE) if m_w and not title: title = m_w.group(1).strip() - except Exception: - pass + except OSError as exc: + logging.warning("Title from chat log of %s unavailable: %s", media_path, exc) return { "title": clean_metadata_label(title, 180), @@ -6224,8 +6236,8 @@ def resolve_media_path(streamer, filename, route): candidates.append(streamer) try: candidates.extend(related_archive_slugs(streamer)) - except Exception: - pass + except sqlite3.Error as exc: + logging.warning("Media lookup for %s without archive aliases (database error): %s", streamer, exc) seen = set() files_dir = getattr(config, "FILES_DIR", None) or os.path.join(BASE_DIR, "files") for cand in candidates: @@ -7070,8 +7082,8 @@ def delete_video_file(streamer, filename, is_clip): tombstone_slugs = set() try: tombstone_slugs.update(related_archive_slugs(streamer) or []) - except Exception: - pass + except sqlite3.Error as exc: + logging.warning("Tombstone for %s/%s without archive aliases (database error): %s", streamer, filename, exc) primary = archive_name_for(streamer) or str(streamer or "").strip() if primary: tombstone_slugs.add(primary) @@ -7102,8 +7114,8 @@ def delete_video_file(streamer, filename, is_clip): _td, alt_path, alt_lock = thumb_paths(slug, filename) paths_to_clear.add(alt_path) paths_to_clear.add(alt_lock) - except Exception: - pass + except sqlite3.Error as exc: + logging.warning("Thumbnails of %s/%s under alias folders kept (database error): %s", streamer, filename, exc) for path in paths_to_clear: if not path: continue @@ -8947,13 +8959,13 @@ def _vod_access_candidate_slugs(): name = str((item or {}).get("name") or "").strip() if name: found.add(database._normalize_vod_access_slug(name) or name.rstrip("_").lower()) - except Exception: - pass + except (OSError, sqlite3.Error) as exc: + logging.warning("VOD access candidates without archive folders: %s", exc) try: for slug in database.list_vod_access_defaults(): found.add(slug) - except Exception: - pass + except sqlite3.Error as exc: + logging.warning("VOD access candidates without stored defaults: %s", exc) return sorted(s for s in found if s) @@ -11858,8 +11870,8 @@ def _recording_logins_set(): login = twitch_api.normalize_login(conf.get("name")) if login and current_recording_info(login) is not None: logins.add(login) - except Exception: - pass + except (sqlite3.Error, OSError) as exc: + logging.warning("Recording channel list unavailable: %s", exc) return logins @@ -11993,7 +12005,8 @@ def twitch_watch(channel): conf = database.get_channel_config(login) if conf: archive_name = normalize_channel_name(conf.get("archive_name")) or login - except Exception: + except sqlite3.Error as exc: + logging.warning("Live watch %s: channel config unavailable: %s", login, exc) archive_name = "" if not archive_name: try: @@ -12001,8 +12014,8 @@ def twitch_watch(channel): if twitch_api.normalize_login(conf.get("name")) == login: archive_name = normalize_channel_name(conf.get("archive_name")) or login break - except Exception: - pass + except sqlite3.Error as exc: + logging.warning("Live watch %s: channel list unavailable: %s", login, exc) # Default: Twitch embed without account cookies (iframe credentialless ≈ Incognito). # Optional ?proxy=1 for server HLS when embed is blocked or unsupported. diff --git a/core/chat_chunker.py b/core/chat_chunker.py index 7ad5bc9..7ff7788 100644 --- a/core/chat_chunker.py +++ b/core/chat_chunker.py @@ -40,8 +40,8 @@ def ensure_chat_chunks( if os.path.getmtime(meta_path) >= os.path.getmtime(log_path): with open(meta_path, "r", encoding="utf-8") as f: return json.load(f) - except Exception: - pass + except (OSError, ValueError) as exc: + logger.warning("chat chunk cache %s unreadable, rebuilding: %s", meta_path, exc) if not os.path.isfile(log_path) or os.path.getsize(log_path) == 0: return {"ok": False, "error": "Log file not found or empty", "total_chunks": 0} diff --git a/core/live_watch_diag.py b/core/live_watch_diag.py index 79bfbb8..de25d68 100644 --- a/core/live_watch_diag.py +++ b/core/live_watch_diag.py @@ -6,8 +6,10 @@ from __future__ import annotations +import logging import os import re +import sqlite3 import subprocess import time from pathlib import Path @@ -15,6 +17,8 @@ from core import config +logger = logging.getLogger(__name__) + LIVE_HLS_TTL_SEC = int(os.environ.get("LIVE_HLS_TTL_SEC", "24")) LIVE_WATCH_DEMAND_SEC = int(os.environ.get("LIVE_WATCH_DEMAND_SEC", "120")) LIVE_STALL_RESTART_SEC = int(os.environ.get("LIVE_STALL_RESTART_SEC", "12")) @@ -84,8 +88,8 @@ def list_candidate_channels(extra: list[str] | None = None) -> list[str]: found.add(name) if int(conf.get("live") or 0) == 1 and name: found.add(name) - except Exception: - pass + except (sqlite3.Error, ValueError) as exc: + logger.warning("live diag: channel configs unavailable: %s", exc) for name in extra or []: if name: found.add(str(name).strip().lower()) @@ -173,8 +177,8 @@ def diagnose_channel(channel: str, *, logs: int = 30, helix: dict | None = None) if conf: db_live = int(conf.get("live") or 0) db_record = int(conf.get("record") or 0) - except Exception: - pass + except (sqlite3.Error, ValueError) as exc: + logger.warning("live diag %s: channel config unavailable: %s", channel, exc) helix_info = (helix or {}).get(channel) if helix is not None else None if helix_info is None: diff --git a/core/redis_client.py b/core/redis_client.py index 4f8309e..00ffce3 100644 --- a/core/redis_client.py +++ b/core/redis_client.py @@ -126,8 +126,8 @@ def invalidate_dashboard_cache() -> bool: shm_path = "/dev/shm/streamrecorder_dashboard_media.json" if os.path.exists(shm_path): os.remove(shm_path) - except Exception: - pass + except OSError as exc: + logger.warning("dashboard shm cache %s not removed: %s", shm_path, exc) return True diff --git a/core/storage/base.py b/core/storage/base.py index 23ca66f..03f14c6 100644 --- a/core/storage/base.py +++ b/core/storage/base.py @@ -8,15 +8,19 @@ from __future__ import annotations +import logging import mimetypes import os import posixpath import re +import sqlite3 from dataclasses import dataclass from typing import Callable, Iterable, Iterator, Optional from flask_babel import gettext, lazy_gettext +logger = logging.getLogger("storage.base") + class StorageError(RuntimeError): """A provider/configuration error with optional retry semantics.""" @@ -210,10 +214,16 @@ def _config_changed(self) -> None: return try: callback(dict(self.config)) - except Exception: + except (StorageError, sqlite3.Error, OSError, ValueError) as exc: # Token rotation must never make a request fail just because the - # optional persistence callback is unavailable. - pass + # optional persistence callback is unavailable. The rotated token + # stays valid in memory; after a restart the stored one is used, + # which a provider with single-use refresh tokens may reject. + logger.warning( + "%s: rotated credentials not persisted: %s", + self.type_id or "storage", + mask_error(exc), + ) # ------------------------------------------------------------------ # Configuration helpers diff --git a/core/storage/http.py b/core/storage/http.py index c1a4e7d..f9b21a7 100644 --- a/core/storage/http.py +++ b/core/storage/http.py @@ -11,6 +11,7 @@ from typing import Any, Optional import requests +from urllib3.exceptions import HTTPError as Urllib3HTTPError from .base import StorageError @@ -50,6 +51,25 @@ def session() -> requests.Session: return current +def close_quietly(resource, *, provider: str = "") -> None: + """Release a response or stream body whose result is no longer needed. + + Closing only hands the connection back to the pool; the transfer result + is already decided by then. A socket that is already gone (OSError, + including requests' ConnectionError) or a urllib3 protocol error while + draining must therefore not replace the caller's result or exception. + Anything else is a programming error and propagates. + """ + try: + resource.close() + except (OSError, Urllib3HTTPError) as exc: + logger.debug( + "%s: closing HTTP response failed: %s", + provider or "storage", + sanitize_error_text(exc), + ) + + def _retry_after_seconds(response: requests.Response, attempt: int) -> float: raw = (response.headers.get("Retry-After") or "").strip() if raw: @@ -127,10 +147,7 @@ def request( if response.status_code not in statuses or attempt + 1 >= retries: return response delay = _retry_after_seconds(response, attempt) - try: - response.close() - except Exception: - pass + close_quietly(response, provider=provider) time.sleep(delay) raise StorageError( diff --git a/core/storage/providers/dropbox.py b/core/storage/providers/dropbox.py index a3adca0..2054063 100644 --- a/core/storage/providers/dropbox.py +++ b/core/storage/providers/dropbox.py @@ -152,10 +152,7 @@ def _rpc(self, endpoint: str, payload: dict, action: str) -> dict: timeout=(10, 60), ) if response.status_code == 401 and attempt == 0: - try: - response.close() - except Exception: - pass + http.close_quietly(response, provider=self.type_id) self._token(force=True) continue return http.json_response(response, action, provider=self.type_id) @@ -369,10 +366,7 @@ def download_file( os.fsync(handle.fileno()) os.replace(tmp_path, dest_path) finally: - try: - response.close() - except Exception: - pass + http.close_quietly(response, provider=self.type_id) if os.path.exists(tmp_path): try: os.remove(tmp_path) @@ -388,10 +382,7 @@ def open_range(self, remote_path: str, start: int, end: int) -> Iterable[bytes]: try: yield from iter_response_range(response, start, end) finally: - try: - response.close() - except Exception: - pass + http.close_quietly(response, provider=self.type_id) def delete(self, remote_path: str) -> None: try: diff --git a/core/storage/providers/google_drive.py b/core/storage/providers/google_drive.py index 18083e0..586dad4 100644 --- a/core/storage/providers/google_drive.py +++ b/core/storage/providers/google_drive.py @@ -186,10 +186,7 @@ def _api(self, method: str, path: str, **kwargs): kwargs["headers"] = self._headers(**(kwargs.get("headers") or {})) response = http.request(method, url, provider=self.type_id, **kwargs) if response.status_code == 401 and attempt == 0: - try: - response.close() - except Exception: - pass + http.close_quietly(response, provider=self.type_id) self._token(force=True) continue return response @@ -345,10 +342,7 @@ def _upload_empty(self, name: str, parent_id: str, existing_id: str, mime: str) ) if response.status_code != 401 or attempt == 1: break - try: - response.close() - except Exception: - pass + http.close_quietly(response, provider=self.type_id) data = http.json_response(response, "Google-Upload (leer)", provider=self.type_id) return { "remote_id": str(data.get("id") or existing_id or ""), @@ -410,10 +404,7 @@ def upload_file( ) if response.status_code != 401 or attempt == 1: break - try: - response.close() - except Exception: - pass + http.close_quietly(response, provider=self.type_id) http.raise_for_status(response, "Google-Upload starten", provider=self.type_id) location = str(response.headers.get("Location") or "").strip() if not location: @@ -540,10 +531,7 @@ def download_file( os.fsync(handle.fileno()) os.replace(tmp_path, dest_path) finally: - try: - response.close() - except Exception: - pass + http.close_quietly(response, provider=self.type_id) if os.path.exists(tmp_path): try: os.remove(tmp_path) @@ -559,10 +547,7 @@ def open_range(self, remote_path: str, start: int, end: int) -> Iterable[bytes]: try: yield from iter_response_range(response, start, end) finally: - try: - response.close() - except Exception: - pass + http.close_quietly(response, provider=self.type_id) def delete(self, remote_path: str) -> None: remote_path = normalize_remote_path(remote_path) diff --git a/core/storage/providers/onedrive.py b/core/storage/providers/onedrive.py index fda13da..4be197f 100644 --- a/core/storage/providers/onedrive.py +++ b/core/storage/providers/onedrive.py @@ -153,10 +153,7 @@ def _api(self, method: str, url: str, **kwargs): kwargs["headers"] = self._headers(**(kwargs.get("headers") or {})) response = http.request(method, url, provider=self.type_id, **kwargs) if response.status_code == 401 and attempt == 0: - try: - response.close() - except Exception: - pass + http.close_quietly(response, provider=self.type_id) self._token(force=True) continue return response @@ -352,10 +349,7 @@ def download_file( os.fsync(handle.fileno()) os.replace(tmp_path, dest_path) finally: - try: - response.close() - except Exception: - pass + http.close_quietly(response, provider=self.type_id) if os.path.exists(tmp_path): try: os.remove(tmp_path) @@ -371,10 +365,7 @@ def open_range(self, remote_path: str, start: int, end: int) -> Iterable[bytes]: try: yield from iter_response_range(response, start, end) finally: - try: - response.close() - except Exception: - pass + http.close_quietly(response, provider=self.type_id) def delete(self, remote_path: str) -> None: response = self._api("DELETE", self._item_url(remote_path), timeout=(10, 60)) diff --git a/core/storage/providers/s3.py b/core/storage/providers/s3.py index e95dbc7..2752c48 100644 --- a/core/storage/providers/s3.py +++ b/core/storage/providers/s3.py @@ -8,6 +8,7 @@ from flask_babel import gettext, lazy_gettext +from core.storage import http from core.storage.base import ( ProgressCallback, ProviderField, @@ -268,10 +269,7 @@ def open_range(self, remote_path: str, start: int, end: int) -> Iterable[bytes]: break yield chunk finally: - try: - body.close() - except Exception: - pass + http.close_quietly(body, provider=self.type_id) def delete(self, remote_path: str) -> None: key = self._key(remote_path) diff --git a/core/storage/providers/webdav.py b/core/storage/providers/webdav.py index e118012..feee9dc 100644 --- a/core/storage/providers/webdav.py +++ b/core/storage/providers/webdav.py @@ -185,10 +185,7 @@ def download_file( os.fsync(handle.fileno()) os.replace(tmp_path, dest_path) finally: - try: - response.close() - except Exception: - pass + http.close_quietly(response, provider=self.type_id) if os.path.exists(tmp_path): try: os.remove(tmp_path) @@ -209,10 +206,7 @@ def open_range(self, remote_path: str, start: int, end: int) -> Iterable[bytes]: try: yield from iter_response_range(response, start, end) finally: - try: - response.close() - except Exception: - pass + http.close_quietly(response, provider=self.type_id) def delete(self, remote_path: str) -> None: response = self._request("DELETE", self._url(remote_path), timeout=(10, 60), retries=2) diff --git a/core/storage/service.py b/core/storage/service.py index 1207299..e869d24 100644 --- a/core/storage/service.py +++ b/core/storage/service.py @@ -11,6 +11,7 @@ import logging import os import shutil +import sqlite3 import stat import time from typing import Optional @@ -1132,8 +1133,10 @@ def callback(done: int, size: int): state["last_pct"] = pct try: database.update_storage_object(object_id, progress=round(pct, 1)) - except Exception: - pass + except sqlite3.Error as exc: + # Progress is cosmetic and rewritten every two seconds; a busy + # database must not abort the transfer itself. + logger.debug("storage object %s: progress not saved: %s", object_id, exc) return callback @@ -1396,8 +1399,14 @@ def run_restore(payload: dict) -> dict: database.update_storage_object(object_id, last_error=message) try: database.set_storage_provider_error(obj["provider_id"], message) - except Exception: - pass + except sqlite3.Error as db_exc: + # Keep the restore error for the caller; the provider status line + # is only a convenience for the storage page. + logger.warning( + "provider %s: restore error not recorded: %s", + obj["provider_id"], + db_exc, + ) raise diff --git a/core/tube_auth.py b/core/tube_auth.py index eec5512..f101dc6 100644 --- a/core/tube_auth.py +++ b/core/tube_auth.py @@ -8,9 +8,11 @@ from __future__ import annotations +import logging import os import re import secrets +import sqlite3 import string import time from typing import Any @@ -20,6 +22,8 @@ from core import database +logger = logging.getLogger(__name__) + VALID_ROLES = {"admin", "viewer", "user", "member", "live_only"} MEMBER_ROLE = "member" LIVE_ONLY_ROLE = "live_only" @@ -93,7 +97,8 @@ def _expand_access_slugs(raw_slugs) -> set[str]: def list_default_vod_access_slugs() -> list[str]: try: rows = database.list_role_vod_access(MEMBER_ROLE) - except Exception: + except sqlite3.Error as exc: + logger.warning("VOD access defaults unreadable, using seed list: %s", exc) rows = [] if rows: return list(rows) @@ -110,8 +115,8 @@ def effective_vod_access_bases(role: str | None = None) -> list[str]: rows = database.list_role_vod_access(role_key) if rows: return rows - except Exception: - pass + except sqlite3.Error as exc: + logger.warning("VOD access for role %s unreadable, using defaults: %s", role_key, exc) return list_default_vod_access_slugs() diff --git a/core/twitch_api.py b/core/twitch_api.py index 554a443..d640c26 100644 --- a/core/twitch_api.py +++ b/core/twitch_api.py @@ -8,6 +8,7 @@ from __future__ import annotations +import http.client import json import logging import os @@ -236,6 +237,18 @@ def _wait_if_circuit_open(): time.sleep(delay) +def _drain_http_error(exc: urllib.error.HTTPError, path: str) -> None: + """Read and discard an error response body so the socket can close. + + The status code has already decided the outcome; a body that cannot be + read (connection reset, truncated chunk) changes nothing about it. + """ + try: + exc.read() + except (OSError, http.client.HTTPException) as read_exc: + logger.debug("Twitch Helix %s: error body unreadable: %s", path, read_exc) + + def helix_get(path: str, params: list[tuple[str, str]] | dict[str, Any] | None = None) -> dict | None: token = get_app_access_token() if not token or not TWITCH_CLIENT_ID: @@ -280,10 +293,7 @@ def helix_get(path: str, params: list[tuple[str, str]] | dict[str, Any] | None = attempt + 1, max_attempts, ) - try: - exc.read() - except Exception: - pass + _drain_http_error(exc, path) if attempt + 1 < max_attempts: time.sleep(sleep_for + random.uniform(0.0, 0.5)) continue @@ -298,19 +308,13 @@ def helix_get(path: str, params: list[tuple[str, str]] | dict[str, Any] | None = attempt + 1, max_attempts, ) - try: - exc.read() - except Exception: - pass + _drain_http_error(exc, path) if attempt + 1 < max_attempts: time.sleep(sleep_for) continue return None logger.info("Twitch Helix request failed (%s): HTTP %s", path, code) - try: - exc.read() - except Exception: - pass + _drain_http_error(exc, path) return None except Exception as exc: logger.info("Twitch Helix request failed (%s): %s", path, exc) diff --git a/core/twitch_eventsub.py b/core/twitch_eventsub.py index a9a7f00..6515cf3 100644 --- a/core/twitch_eventsub.py +++ b/core/twitch_eventsub.py @@ -8,6 +8,7 @@ import hashlib import hmac +import http.client import json import logging import os @@ -52,11 +53,10 @@ def reload_env() -> None: with _STATE_LOCK: _STATE_CACHE.clear() _STATE_CACHE.update({"by_login": {}, "by_user_id": {}, "updated_at": 0.0}) - try: - from core import redis_client - redis_client.delete_state("sysstate:eventsub_state") - except Exception: - pass + from core import redis_client + + # delete_state() absorbs Redis errors itself and returns False. + redis_client.delete_state("sysstate:eventsub_state") def enabled() -> bool: @@ -224,8 +224,9 @@ def _helix_post(path: str, payload: dict[str, Any]) -> dict | None: detail = "" try: detail = exc.read().decode("utf-8", errors="replace")[:400] - except Exception: - pass + except (OSError, http.client.HTTPException) as read_exc: + # The HTTP status below is the result; the body is only detail. + logger.debug("EventSub Helix POST %s: error body unreadable: %s", path, read_exc) logger.warning("EventSub Helix POST %s failed: HTTP %s %s", path, exc.code, detail) return None except Exception as exc: diff --git a/tests/test_error_handling.py b/tests/test_error_handling.py new file mode 100644 index 0000000..f931cfe --- /dev/null +++ b/tests/test_error_handling.py @@ -0,0 +1,294 @@ +"""Former `except Exception: pass` paths: specific error classes, logged. + +Each test pins two things: the expected failure is still absorbed (the caller +keeps its fallback) and it now leaves a log line behind. +The environment bootstrap (test credentials, temp BASE_DIR, fcntl shim on +Windows) lives in test_recorder_reliability and runs on import. +""" + +from __future__ import annotations + +import io +import json +import os +import sqlite3 +import time +import unittest +import urllib.error +from unittest import mock + +try: + from test_recorder_reliability import IsolatedBaseTest # noqa: F401 +except ImportError: # run as tests.test_error_handling + from tests.test_recorder_reliability import IsolatedBaseTest # noqa: F401 + +from core import config # noqa: E402 +from core import chat_chunker, live_watch_diag, redis_client, tube_auth # noqa: E402 +from core import twitch_api, twitch_eventsub # noqa: E402 +from core.storage import http as storage_http # noqa: E402 +from core.storage.providers import google_drive as google_module # noqa: E402 +from core.storage.providers.google_drive import GoogleDriveProvider # noqa: E402 + + +class StorageResponseCloseTests(unittest.TestCase): + def test_close_failure_is_logged_with_provider(self): + response = mock.Mock() + response.close.side_effect = ConnectionResetError("reset by peer") + with self.assertLogs("storage.http", level="DEBUG") as logs: + storage_http.close_quietly(response, provider="dropbox") + self.assertTrue(any("dropbox" in line and "reset by peer" in line for line in logs.output)) + + def test_unexpected_close_error_is_not_swallowed(self): + response = mock.Mock() + response.close.side_effect = RuntimeError("programming error") + with self.assertRaises(RuntimeError): + storage_http.close_quietly(response, provider="dropbox") + + def test_google_drive_401_retry_survives_a_failing_close(self): + class Unauthorized: + status_code = 401 + reason = "Unauthorized" + text = "denied" + content = b"" + headers = {} + + def json(self): + raise ValueError("not json") + + def close(self): + raise ConnectionResetError("socket gone") + + provider = GoogleDriveProvider({}) + token_calls = [] + provider._token = lambda force=False: token_calls.append(bool(force)) or "token" + requests = [] + + def fake_request(method, url, **kwargs): + requests.append((method, url)) + return Unauthorized() + + with mock.patch.object(google_module.http, "request", fake_request), \ + self.assertLogs("storage.http", level="DEBUG"): + response = provider._api("GET", "/files") + self.assertEqual(response.status_code, 401) + self.assertEqual(len(requests), 2) + self.assertIn(True, token_calls, "the 401 must still force a token refresh") + + +def _http_error_with_broken_body(code): + exc = urllib.error.HTTPError("https://api.twitch.tv/helix/x", code, "err", {}, io.BytesIO(b"")) + exc.read = mock.Mock(side_effect=ConnectionResetError("body lost")) + return exc + + +class TwitchHttpErrorBodyTests(unittest.TestCase): + def setUp(self): + for name, value in (("get_app_access_token", lambda: "app-token"), + ("TWITCH_CLIENT_ID", "client")): + patcher = mock.patch.object(twitch_api, name, value) + patcher.start() + self.addCleanup(patcher.stop) + + def test_helix_get_logs_unreadable_error_body_and_returns_none(self): + with mock.patch.object(twitch_api.urllib.request, "urlopen", + side_effect=_http_error_with_broken_body(404)), self.assertLogs(twitch_api.logger, level="DEBUG") as logs: + self.assertIsNone(twitch_api.helix_get("streams", {"user_login": "x"})) + self.assertTrue(any("body lost" in line for line in logs.output)) + + def test_eventsub_post_logs_unreadable_error_body_and_returns_none(self): + with mock.patch.object(twitch_eventsub.urllib.request, "urlopen", + side_effect=_http_error_with_broken_body(409)), self.assertLogs(twitch_eventsub.logger, level="DEBUG") as logs: + self.assertIsNone(twitch_eventsub._helix_post("eventsub/subscriptions", {})) + self.assertTrue(any("body lost" in line for line in logs.output)) + + +class CoreDatabaseFallbackTests(IsolatedBaseTest): + def test_vod_access_bases_fall_back_to_defaults_and_log(self): + locked = sqlite3.OperationalError("database is locked") + with mock.patch.object(tube_auth.database, "list_role_vod_access", side_effect=locked), self.assertLogs("core.tube_auth", level="WARNING"): + bases = tube_auth.effective_vod_access_bases() + self.assertEqual(bases, sorted(tube_auth._VOD_ACCESS_SEED_BASES)) + + def test_live_diag_candidates_survive_database_error(self): + from core import database + locked = sqlite3.OperationalError("database is locked") + with mock.patch.object(database, "list_channel_configs", side_effect=locked), self.assertLogs("core.live_watch_diag", level="WARNING"): + names = live_watch_diag.list_candidate_channels(extra=["Extra"]) + self.assertIn("extra", names) + + def test_live_diag_channel_report_survives_database_error(self): + from core import database + locked = sqlite3.OperationalError("database is locked") + with mock.patch.object(database, "get_channel_config", side_effect=locked), mock.patch.object(live_watch_diag, "streamlink_counts", return_value={}), mock.patch.object(live_watch_diag, "ffmpeg_hls_pids", return_value={}), self.assertLogs("core.live_watch_diag", level="WARNING"): + report = live_watch_diag.diagnose_channel("chan", helix={"chan": {}}) + self.assertEqual(report["db"], {"live": None, "record": None}) + + +class ChatChunkCacheTests(IsolatedBaseTest): + def test_corrupt_cached_meta_is_logged_and_rebuilt(self): + log_path = self.base / "chan" / "chat_logs" / "vod.jsonl" + log_path.parent.mkdir(parents=True) + log_path.write_text(json.dumps({"t": 1.0, "msg": "hi"}) + "\n", encoding="utf-8") + chunks_dir = chat_chunker.get_chunks_dir(str(self.base), "chan", "vod.mp4") + os.makedirs(chunks_dir) + meta = os.path.join(chunks_dir, "meta.json") + with open(meta, "w", encoding="utf-8") as handle: + handle.write("{truncated") + os.utime(meta, (os.path.getmtime(log_path) + 60,) * 2) + with self.assertLogs("streamvault.chat_chunker", level="WARNING"): + result = chat_chunker.ensure_chat_chunks(str(self.base), "chan", "vod.mp4", str(log_path)) + self.assertTrue(result.get("ok"), result) + with open(meta, encoding="utf-8") as handle: + self.assertEqual(json.load(handle)["total_chunks"], result["total_chunks"]) + + +class RedisDashboardCacheTests(unittest.TestCase): + def test_shm_cache_removal_failure_is_logged(self): + with mock.patch.object(redis_client, "delete_state", return_value=False), mock.patch.object(redis_client, "publish_event", return_value=False), mock.patch.object(redis_client.os.path, "exists", return_value=True), mock.patch.object(redis_client.os, "remove", side_effect=PermissionError("busy")), self.assertLogs("streamvault.redis", level="WARNING"): + self.assertTrue(redis_client.invalidate_dashboard_cache()) + + + +def _admin_client(webui): + webui.app.config.update(TESTING=True) + client = webui.app.test_client() + with client.session_transaction() as sess: + now = time.time() + sess.update(logged_in=True, user_role="admin", username=config.VOD_USER, + login_time=now, last_active=now, _csrf_token="t") + return client + + +class DeletedMediaTombstoneTests(IsolatedBaseTest): + """A tombstoned VOD stays hidden even while its file is still on disk.""" + + def setUp(self): + super().setUp() + from core import database + from WEBUI import webui + self.webui = webui + self.database = database + patcher = mock.patch.object(webui, "BASE_DIR", str(self.base)) + patcher.start() + self.addCleanup(patcher.stop) + webui.ensure_admin_user() + archive = self.base / "streamer" + archive.mkdir() + (archive / "vod.mp4").write_bytes(b"\0" * 32) + + def test_tombstoned_vod_page_is_404(self): + client = _admin_client(self.webui) + self.assertEqual(client.get("/vod/streamer/vod.mp4").status_code, 200) + self.database.upsert_deleted_media("streamer", "vod.mp4", deleted_by="admin") + self.assertEqual(client.get("/vod/streamer/vod.mp4").status_code, 404) + + def test_tombstone_lookup_failure_is_logged_and_page_still_served(self): + client = _admin_client(self.webui) + locked = sqlite3.OperationalError("database is locked") + with mock.patch.object(self.webui.database, "is_deleted_media", side_effect=locked), self.assertLogs(level="WARNING") as logs: + response = client.get("/vod/streamer/vod.mp4") + self.assertEqual(response.status_code, 200) + self.assertTrue(any("database is locked" in line for line in logs.output)) + + + +class WebuiLookupFailureTests(IsolatedBaseTest): + """Web UI lookups that used to swallow every error now log specific ones.""" + + def setUp(self): + super().setUp() + from werkzeug.security import generate_password_hash + + from WEBUI import webui + self.webui = webui + patcher = mock.patch.object(webui, "BASE_DIR", str(self.base)) + patcher.start() + self.addCleanup(patcher.stop) + webui.ensure_admin_user() + webui.save_user("plainviewer", generate_password_hash("Role-Test-Pass-1"), role="viewer") + archive = self.base / "streamer" + archive.mkdir() + (archive / "vod.mp4").write_bytes(b"\0" * 32) + self.locked = sqlite3.OperationalError("database is locked") + + def _viewer_request(self): + ctx = self.webui.app.test_request_context("/") + ctx.push() + self.addCleanup(ctx.pop) + now = time.time() + self.webui.session.update(logged_in=True, user_role="viewer", username="plainviewer", + login_time=now, last_active=now) + + def test_maintenance_bypass_check_failure_is_logged_and_denied(self): + from core import site_maintenance + self._viewer_request() + with mock.patch.object(site_maintenance, "is_user_exempt", side_effect=OSError("state unreadable")), \ + self.assertLogs(level="WARNING") as logs: + self.assertFalse(self.webui.current_user_bypasses_maintenance()) + self.assertTrue(any("state unreadable" in line for line in logs.output)) + + def test_viewer_access_check_survives_channel_lookup_failure(self): + self._viewer_request() + expected = self.webui.can_view_streamer("streamer") + with mock.patch.object(self.webui, "related_archive_slugs", side_effect=self.locked), \ + self.assertLogs(level="WARNING") as logs: + self.assertEqual(self.webui.can_view_streamer("streamer"), expected) + self.assertTrue(any("database is locked" in line for line in logs.output)) + + def test_streamer_folders_survive_channel_config_failure(self): + with mock.patch.object(self.webui.database, "list_channel_configs", side_effect=self.locked), \ + self.assertLogs(level="WARNING"): + rows = self.webui.list_all_streamer_folders() + self.assertIn("streamer", [row["name"] for row in rows]) + + def test_media_path_resolves_when_alias_lookup_fails(self): + with mock.patch.object(self.webui, "related_archive_slugs", side_effect=self.locked), \ + self.assertLogs(level="WARNING"): + resolved = self.webui.resolve_media_path("streamer", "vod.mp4", "vod") + self.assertEqual(os.path.normpath(resolved), os.path.normpath(str(self.base / "streamer" / "vod.mp4"))) + + def test_vod_access_candidates_survive_failures(self): + with mock.patch.object(self.webui, "list_streamers", side_effect=OSError("archive unreadable")), \ + mock.patch.object(self.webui.database, "list_vod_access_defaults", side_effect=self.locked), \ + self.assertLogs(level="WARNING") as logs: + self.assertEqual(self.webui._vod_access_candidate_slugs(), []) + self.assertEqual(len(logs.output), 2) + + def test_recording_logins_survive_database_error(self): + with mock.patch.object(self.webui.database, "list_channel_configs", side_effect=self.locked), \ + self.assertLogs(level="WARNING"): + self.assertEqual(self.webui._recording_logins_set(), set()) + + def test_twitch_profile_lookup_failure_is_logged(self): + offline = urllib.error.URLError("offline") + with mock.patch.object(self.webui.urllib.request, "urlopen", side_effect=offline), \ + self.assertLogs(level="WARNING"): + self.assertEqual(self.webui.get_twitch_profile_and_banner("someone"), (None, None)) + + def test_twitch_profile_unexpected_payload_is_no_profile(self): + response = mock.MagicMock() + response.__enter__.return_value.read.return_value = b'{"data": null}' + with mock.patch.object(self.webui.urllib.request, "urlopen", return_value=response): + self.assertEqual(self.webui.get_twitch_profile_and_banner("someone"), (None, None)) + + def test_twitch_user_id_failure_is_logged_and_cached_as_unknown(self): + self.webui.TWITCH_USER_ID_CACHE.pop("someone", None) + self.addCleanup(self.webui.TWITCH_USER_ID_CACHE.pop, "someone", None) + with mock.patch.object(self.webui.urllib.request, "urlopen", side_effect=TimeoutError("slow")), \ + self.assertLogs(level="WARNING"): + self.assertIsNone(self.webui.get_twitch_user_id("someone")) + self.assertIsNone(self.webui.TWITCH_USER_ID_CACHE["someone"]["id"]) + + def test_delete_still_removes_file_and_writes_tombstone_when_alias_lookup_fails(self): + self._viewer_request() + with mock.patch.object(self.webui, "related_archive_slugs", side_effect=self.locked), \ + self.assertLogs(level="WARNING") as logs: + self.assertTrue(self.webui.delete_video_file("streamer", "vod.mp4", False)) + # media lookup, tombstone aliases, thumbnail aliases + self.assertEqual(sum("database is locked" in line for line in logs.output), 3) + self.assertFalse((self.base / "streamer" / "vod.mp4").exists()) + self.assertTrue(self.webui.database.is_deleted_media(streamer="streamer", filename="vod.mp4")) + + +if __name__ == "__main__": + unittest.main() diff --git a/tests/test_invariants.py b/tests/test_invariants.py index bc444d9..bf5f08f 100644 --- a/tests/test_invariants.py +++ b/tests/test_invariants.py @@ -401,5 +401,143 @@ def test_worker_task_cleanup_logs_close_errors(self): worker.cleanup_old_tasks(force=True) + +class ChannelLockFileTests(IsolatedBaseTest): + """Lock-file bookkeeping: only the holder (or the PID inside) may release.""" + + def setUp(self): + super().setUp() + self.recordings = self.base / "chan" + self.recordings.mkdir() + self.path = recorder.channel_lock_path(str(self.recordings), "chan") + self.addCleanup(recorder.release_held_channel_lock, str(self.recordings), "chan") + + def _content(self): + return Path(self.path).read_text(encoding="utf-8") + + def test_lock_records_the_child_pid_after_spawn(self): + self.assertIsNotNone(recorder.try_acquire_channel_lock(str(self.recordings), "chan", pid=111)) + self.assertEqual(self._content(), "111") + recorder.update_channel_lock_pid(str(self.recordings), 22222, "chan") + self.assertEqual(self._content(), "22222") + + def test_release_for_a_foreign_pid_keeps_the_held_lock(self): + recorder.try_acquire_channel_lock(str(self.recordings), "chan", pid=111) + recorder.release_channel_lock(str(self.recordings), pid=999, source_channel="chan") + self.assertIn(self.path, recorder._CHANNEL_LOCK_FDS) + self.assertTrue(os.path.exists(self.path)) + recorder.release_channel_lock(str(self.recordings), pid=111, source_channel="chan") + self.assertNotIn(self.path, recorder._CHANNEL_LOCK_FDS) + self.assertFalse(os.path.exists(self.path)) + + def test_unheld_lock_file_is_removed_only_for_its_own_pid(self): + Path(self.path).write_text("999", encoding="utf-8") + recorder.release_channel_lock(str(self.recordings), pid=111, source_channel="chan") + self.assertEqual(self._content(), "999") + recorder.release_channel_lock(str(self.recordings), pid=999, source_channel="chan") + self.assertFalse(os.path.exists(self.path)) + + +@unittest.skipUnless(os.name == "posix", "needs real fcntl.flock") +class InstanceLockRealFlockTests(IsolatedBaseTest): + """Invariant: a second recorder instance exits instead of recording twice.""" + + def setUp(self): + super().setUp() + self.lock_file = str(self.base / ".streamrecorder.pid") + for patcher in (mock.patch.object(recorder, "INSTANCE_LOCK_FILE", self.lock_file), + mock.patch.object(recorder, "_INSTANCE_LOCK_FD", None), + mock.patch.object(recorder.atexit, "register")): + patcher.start() + self.addCleanup(patcher.stop) + self.addCleanup(recorder.release_instance_lock) + + def test_second_instance_exits_while_the_first_holds_the_lock(self): + holder = subprocess.Popen([sys.executable, "-c", ChannelLockRealFlockTests.HOLDER, self.lock_file], + stdout=subprocess.PIPE, text=True) + self.addCleanup(lambda: holder.poll() is None and (holder.kill(), holder.wait(timeout=5))) + self.assertEqual(holder.stdout.readline().strip(), "locked") + with self.assertLogs(recorder.logger, level="ERROR"), self.assertRaises(SystemExit) as ctx: + recorder.acquire_instance_lock() + self.assertEqual(ctx.exception.code, 1) + holder.kill() + holder.wait(timeout=5) + recorder.acquire_instance_lock() + self.assertEqual(Path(self.lock_file).read_text(encoding="utf-8"), str(os.getpid())) + recorder.release_instance_lock() + self.assertFalse(os.path.exists(self.lock_file)) + + +def _ignore_sigterm_and_wait(ready): + signal.signal(signal.SIGTERM, signal.SIG_IGN) + ready.set() + time.sleep(30) + + +@unittest.skipUnless(POSIX and hasattr(os, "fork"), "needs fork and POSIX signals") +class StopChannelProcessRealChildTests(unittest.TestCase): + """A channel worker that ignores SIGTERM is killed within the deadline.""" + + def test_worker_ignoring_sigterm_is_killed(self): + import multiprocessing + ctx = multiprocessing.get_context("fork") + ready = ctx.Event() + proc = ctx.Process(target=_ignore_sigterm_and_wait, args=(ready,)) + proc.start() + self.addCleanup(lambda: proc.is_alive() and (proc.kill(), proc.join(5))) + self.assertTrue(ready.wait(10)) + started = time.monotonic() + with self.assertLogs(recorder.logger, level="WARNING"): + recorder.stop_channel_process(proc, "chan", timeout=0.5) + self.assertFalse(proc.is_alive()) + self.assertEqual(proc.exitcode, -signal.SIGKILL) + self.assertLess(time.monotonic() - started, 10) + + +class WorkerVodTaskPathTests(IsolatedBaseTest): + """worker._safe_vod_task_path: remux/thumbnail tasks never leave the archive.""" + + def setUp(self): + super().setUp() + from recorder import worker + self.worker = worker + self.channel = self.base / "streamer" + self.channel.mkdir() + self.vod = self.channel / "vod.mp4" + self.vod.write_bytes(b"\0" * 16) + self.outside = Path(self._tmp.name).parent / f"outside-{os.getpid()}-{id(self)}.mp4" + self.outside.write_bytes(b"secret") + self.addCleanup(self.outside.unlink) + + def test_archive_file_resolves(self): + resolved = self.worker._safe_vod_task_path("streamer", "vod.mp4") + self.assertEqual(os.path.normcase(resolved), os.path.normcase(os.path.realpath(self.vod))) + + def test_traversal_and_non_archive_names_are_rejected(self): + cases = [ + ("streamer", "../" + self.outside.name), + ("streamer", "..\\" + self.outside.name), + ("streamer", str(self.outside)), + ("..", self.outside.name), + ("../streamer", "vod.mp4"), + ("streamer", "missing.mp4"), + ("streamer", "vod.mp4.part"), + ("streamer", "notes.txt"), + ("", "vod.mp4"), + ("streamer", ""), + ] + for streamer, filename in cases: + with self.subTest(streamer=streamer, filename=filename): + self.assertIsNone(self.worker._safe_vod_task_path(streamer, filename)) + + def test_symlink_out_of_the_archive_is_rejected(self): + link = self.channel / "link.mp4" + try: + os.symlink(self.outside, link) + except (OSError, NotImplementedError) as exc: + self.skipTest(f"symlinks unavailable: {exc}") + self.assertIsNone(self.worker._safe_vod_task_path("streamer", "link.mp4")) + + if __name__ == "__main__": unittest.main() diff --git a/tests/test_storage.py b/tests/test_storage.py index a1298d7..b84442a 100644 --- a/tests/test_storage.py +++ b/tests/test_storage.py @@ -15,6 +15,7 @@ import io import json import os +import sqlite3 import stat import tempfile import time @@ -2082,5 +2083,36 @@ def test_storage_admin_error_log_omits_traceback_and_secrets(self): self.assertNotIn("supersecret", str(log_error.call_args)) +class StorageBookkeepingFailureTests(StorageTestBase): + """Database hiccups in side bookkeeping are logged, never fatal.""" + + def test_progress_update_on_locked_database_is_logged(self): + callback = service._progress_callback(1, 100) + locked = sqlite3.OperationalError("database is locked") + with mock.patch.object(service.database, "update_storage_object", side_effect=locked), self.assertLogs("storage.service", level="DEBUG") as logs: + callback(50, 100) + self.assertTrue(any("database is locked" in line for line in logs.output)) + + def test_restore_error_survives_failing_provider_error_bookkeeping(self): + path, obj = RestoreSafetyTests._restore_object(self, b"new", remote_size=3, local=b"older") + fake = RestoreSafetyTests._FakeDownloadProvider(error=StorageError("remote gone")) + locked = sqlite3.OperationalError("database is locked") + with mock.patch.object(service, "build_provider", return_value=fake), mock.patch.object(service.database, "set_storage_provider_error", side_effect=locked), self.assertLogs("storage.service", level="WARNING") as logs: + with self.assertRaises(StorageError) as ctx: + service.run_restore({"object_id": obj["id"]}) + self.assertIn("remote gone", str(ctx.exception)) + self.assertTrue(any("database is locked" in line for line in logs.output)) + self.assertEqual(path.read_bytes(), b"older") + + def test_failing_token_persistence_does_not_fail_the_request(self): + provider = DropboxProvider({}) + provider.set_config_changed_callback( + mock.Mock(side_effect=sqlite3.OperationalError("database is locked")) + ) + with self.assertLogs("storage.base", level="WARNING") as logs: + provider._config_changed() + self.assertTrue(any("dropbox" in line for line in logs.output)) + + if __name__ == "__main__": unittest.main()