enable timespan

Dockers/self-hosted-iptv/README.md

@@ -28,6 +28,8 @@ docker run -d --name iptv -p 8080:8080 \
 ```
 When using TMDB metadata, mount `/data` read-write (as above) so the app can store and reuse metadata in `/data/tmdb_cache/`. Use `-v /path/to/data:/data:ro` only if you do not use TMDB.
 
+**EPG timespan:** Set `EPG_TIMESPAN` to control how far ahead the guide is generated (default `14d`). Examples: `2d`, `7d`, `48h`. The randomized schedule is refreshed after (timespan − 3 hours) so a new block of content is ready before the current one ends. Example: `-e EPG_TIMESPAN=2d` gives 2 days of EPG and a new schedule every 45 hours.
+
 **Optional – EPG metadata (Dutch) from TMDB:**  
 To show series titles, episode names, and descriptions in the TV guide in **Dutch**, set a [TMDB API key](https://www.themoviedb.org/settings/api) (free after sign-up):
 
@@ -38,18 +40,20 @@ Series are matched by folder name (e.g. `series/W817` → search "W817"); episod
 - **Persistent cache:** Fetched metadata is stored under `/data/tmdb_cache/` (series search, series details, episode, episode credits). When generating the EPG, the app checks this cache first and only calls TMDB for missing entries. Mount `/data` read-write (omit `:ro`) so the cache can be written.
 - **Rate limit:** TMDB allows 40 requests per 10 seconds. The app enforces this limit when calling the API; if the cache is warm, few or no requests are made during EPG generation.
 
+**Logging:** Set `LOG_LEVEL=DEBUG` (e.g. in your `docker run` with `-e LOG_LEVEL=DEBUG`) to see where time is spent: schedule building (including ffprobe per video), EPG per-channel programme count and duration, and TMDB cache hits (memory/disk) vs API requests and rate-limit waits.
+
 3. In your IPTV client or **Plex DVR**, add:
    - **Playlist URL:** `http://<host>:8080/playlist.m3u`
    - **EPG (XMLTV) URL:** `http://<host>:8080/epg.xml`  
    Plex will show programme titles and times for each channel.
 
-Each channel in the M3U points to a **continuous live stream** (`/live/<id>`): FFmpeg concatenates the channel’s randomized videos into one MPEG-TS stream and loops it. The **schedule** (and EPG) is built from video durations (via ffprobe) so start/stop times match what’s actually playing. The same order is cached for 24h so the EPG and live stream stay in sync.
+Each channel in the M3U points to a **continuous live stream** (`/live/<id>`): FFmpeg concatenates the channel’s randomized videos into one MPEG-TS stream and loops it. The **schedule** (and EPG) is built from video durations (via ffprobe) so start/stop times match what’s actually playing. The schedule is cached for (timespan − 3 h) so the EPG and live stream stay in sync and a new span is ready in time.
 
 ## Endpoints
 
 - `GET /` — simple web index with playlist and EPG links
 - `GET /playlist.m3u` — master M3U for Plex DVR (one live stream URL per channel)
-- `GET /epg.xml` or `GET /xmltv.xml` — XMLTV EPG (14 days, UTC)
+- `GET /epg.xml` or `GET /xmltv.xml` — XMLTV EPG (duration set by `EPG_TIMESPAN`, UTC)
 - `GET /live/<channel_id>` — continuous MPEG-TS stream for that channel (for tuning/recording)
 - `GET /channel/<id>/playlist.m3u` — single channel M3U (list of individual video URLs)
 - `GET /stream?path=movies/...` or `path=series/...` — stream a single video file

Dockers/self-hosted-iptv/main.py

@@ -5,6 +5,7 @@ with randomized order so the same show never appears twice in a row.
 """
 
 import json
+import logging
 import os
 import random
 import re
@@ -22,12 +23,48 @@ from http.server import HTTPServer, BaseHTTPRequestHandler
 from urllib.parse import urlparse, parse_qs, unquote, urlencode
 import mimetypes
 
-# Per-channel schedule cache: channel_id -> (paths, durations). TTL 24h so EPG and live stay in sync.
+logger = logging.getLogger(__name__)
+
+# Per-channel schedule cache: channel_id -> (paths, durations). TTL = (timespan - 3h) so a new span is ready before the current one ends.
 _schedule_cache: dict[str, tuple[list[Path], list[float], float]] = {}
-SCHEDULE_CACHE_TTL_SEC = 24 * 3600
+# Parsed from EPG_TIMESPAN (e.g. "2d", "14d", "48h"). Default 14d. Schedule refreshes after (timespan - 3h).
-EPG_DAYS = 14
+EPG_TIMESPAN_DAYS = 14.0
+EPG_TIMESPAN_SEC = 14.0 * 24 * 3600
+SCHEDULE_CACHE_TTL_SEC = (14 * 24 - 3) * 3600  # 14d - 3h
 DEFAULT_DURATION_SEC = 3600
 
+
+def _parse_epg_timespan(value: str) -> tuple[float, float]:
+    """Parse EPG_TIMESPAN env (e.g. '2d', '14d', '48h'). Returns (days, seconds). Default (14, 14*24*3600) on error."""
+    value = (value or "").strip().lower()
+    if not value:
+        return 14.0, 14.0 * 24 * 3600
+    m = re.match(r"^(\d+(?:\.\d+)?)\s*([dh])?$", value)
+    if not m:
+        return 14.0, 14.0 * 24 * 3600
+    num = float(m.group(1))
+    unit = (m.group(2) or "d")
+    if unit == "h":
+        days = num / 24.0
+    else:
+        days = num
+    sec = days * 24 * 3600
+    return days, sec
+
+
+def _init_epg_timespan() -> None:
+    """Load EPG_TIMESPAN from env and set EPG_* and SCHEDULE_CACHE_TTL_SEC."""
+    global EPG_TIMESPAN_DAYS, EPG_TIMESPAN_SEC, SCHEDULE_CACHE_TTL_SEC
+    days, sec = _parse_epg_timespan(os.environ.get("EPG_TIMESPAN", ""))
+    EPG_TIMESPAN_DAYS = days
+    EPG_TIMESPAN_SEC = sec
+    # New schedule is generated after (timespan - 3 hours); minimum 1 hour TTL
+    schedule_ttl = sec - 3 * 3600
+    SCHEDULE_CACHE_TTL_SEC = max(3600, schedule_ttl)
+
+
+_init_epg_timespan()
+
 MOVIES_ROOT = Path("/movies")
 SERIES_ROOT = Path("/series")
 DATA_ROOT = Path("/data")
@@ -131,6 +168,7 @@ def build_channel_path_list(path_keys: list[str]) -> list[Path]:
 
 def get_duration(path: Path) -> float:
     """Return duration in seconds via ffprobe. Uses DEFAULT_DURATION_SEC on failure."""
+    t0 = time.monotonic()
     try:
         out = subprocess.run(
             [
@@ -145,9 +183,11 @@ def get_duration(path: Path) -> float:
             timeout=30,
         )
         if out.returncode == 0 and out.stdout.strip():
-            return float(out.stdout.strip())
+            d = float(out.stdout.strip())
-    except (subprocess.TimeoutExpired, ValueError, FileNotFoundError):
+            logger.debug("ffprobe %s -> %.0fs in %.2fs", path.name, d, time.monotonic() - t0)
-        pass
+            return d
+    except (subprocess.TimeoutExpired, ValueError, FileNotFoundError) as e:
+        logger.debug("ffprobe %s failed: %s", path.name, e)
     return DEFAULT_DURATION_SEC
 
 
@@ -160,7 +200,10 @@ def get_or_build_schedule(channel_id: str) -> tuple[list[Path], list[float]] | N
     if channel_id in _schedule_cache:
         paths, durations, ts = _schedule_cache[channel_id]
         if now - ts < SCHEDULE_CACHE_TTL_SEC:
+            logger.debug("schedule cache hit for channel %s (%s videos)", channel_id, len(paths))
             return paths, durations
+    logger.info("Building schedule for channel %s ...", channel_id)
+    t0 = time.monotonic()
     channels = get_channels()
     channel = next((c for c in channels if c.get("id") == channel_id), None)
     if not channel:
@@ -169,7 +212,9 @@ def get_or_build_schedule(channel_id: str) -> tuple[list[Path], list[float]] | N
     if not paths:
         return None
     durations = [get_duration(p) for p in paths]
+    elapsed = time.monotonic() - t0
     _schedule_cache[channel_id] = (paths, durations, now)
+    logger.info("Schedule for channel %s built in %.1fs (%s videos)", channel_id, elapsed, len(paths))
     return paths, durations
 
 
@@ -311,6 +356,7 @@ def _tmdb_wait_rate_limit() -> None:
                 break
             wait = TMDB_RATE_LIMIT_WINDOW_SEC - (now - _tmdb_request_times[0])
             if wait > 0:
+                logger.debug("TMDB rate limit: waiting %.1fs (%s/40 in window)", wait, len(_tmdb_request_times))
                 time.sleep(min(0.5, wait))
 
 
@@ -331,12 +377,14 @@ def _tmdb_request(path: str, params: dict | None = None) -> dict | None:
         q.update(params)
     url = f"{TMDB_API_BASE}{path}?{urlencode(q)}"
     req = urllib.request.Request(url)
+    logger.debug("TMDB request: %s", path)
     try:
         with urllib.request.urlopen(req, timeout=15) as resp:
             data = json.load(resp)
             _tmdb_record_request()
             return data
-    except (urllib.error.HTTPError, urllib.error.URLError, OSError, json.JSONDecodeError):
+    except (urllib.error.HTTPError, urllib.error.URLError, OSError, json.JSONDecodeError) as e:
+        logger.debug("TMDB request failed %s: %s", path, e)
         return None
 
 
@@ -346,6 +394,7 @@ def _tmdb_search_series(name: str) -> tuple[int, str] | None:
     if name in _tmdb_series_cache:
         sid, sname, ts = _tmdb_series_cache[name]
         if now - ts < TMDB_CACHE_TTL_SEC:
+            logger.debug("TMDB series_search %s: memory hit -> %s", name, sid)
             return (sid, sname)
     key = _tmdb_sanitize_key(name)
     cached = _tmdb_read_disk_cache("series_search", key)
@@ -353,7 +402,9 @@ def _tmdb_search_series(name: str) -> tuple[int, str] | None:
         sid, sname = cached.get("series_id"), cached.get("series_name_nl")
         if sid is not None and sname is not None:
             _tmdb_series_cache[name] = (int(sid), sname, now)
+            logger.debug("TMDB series_search %s: disk hit -> %s", name, sid)
             return (int(sid), sname)
+    logger.debug("TMDB series_search %s: API request", name)
     data = _tmdb_request("/search/tv", {"query": name})
     if not data:
         return None
@@ -376,12 +427,15 @@ def _tmdb_get_series_details(series_id: int) -> dict | None:
     if series_id in _tmdb_series_details_cache:
         details, ts = _tmdb_series_details_cache[series_id]
         if now - ts < TMDB_CACHE_TTL_SEC:
+            logger.debug("TMDB series_details %s: memory hit", series_id)
             return details
     key = str(series_id)
     cached = _tmdb_read_disk_cache("series_details", key)
     if cached is not None:
         _tmdb_series_details_cache[series_id] = (cached, now)
+        logger.debug("TMDB series_details %s: disk hit", series_id)
         return cached
+    logger.debug("TMDB series_details %s: API request", series_id)
     data = _tmdb_request(f"/tv/{series_id}")
     if not data:
         return None
@@ -401,12 +455,15 @@ def _tmdb_get_episode(series_id: int, season: int, episode: int) -> dict | None:
     if key_tuple in _tmdb_episode_cache:
         meta, ts = _tmdb_episode_cache[key_tuple]
         if now - ts < TMDB_CACHE_TTL_SEC:
+            logger.debug("TMDB episode %s s%s e%s: memory hit", series_id, season, episode)
             return meta
     key = f"{series_id}_{season}_{episode}"
     cached = _tmdb_read_disk_cache("episode", key)
     if cached is not None:
         _tmdb_episode_cache[key_tuple] = (cached, now)
+        logger.debug("TMDB episode %s s%s e%s: disk hit", series_id, season, episode)
         return cached
+    logger.debug("TMDB episode %s s%s e%s: API request", series_id, season, episode)
     data = _tmdb_request(f"/tv/{series_id}/season/{season}/episode/{episode}")
     if not data:
         return None
@@ -426,12 +483,15 @@ def _tmdb_get_episode_credits(series_id: int, season: int, episode: int) -> dict
     if key_tuple in _tmdb_episode_credits_cache:
         cred, ts = _tmdb_episode_credits_cache[key_tuple]
         if now - ts < TMDB_CACHE_TTL_SEC:
+            logger.debug("TMDB episode_credits %s s%s e%s: memory hit", series_id, season, episode)
             return cred
     key = f"{series_id}_{season}_{episode}"
     cached = _tmdb_read_disk_cache("episode_credits", key)
     if cached is not None:
         _tmdb_episode_credits_cache[key_tuple] = (cached, now)
+        logger.debug("TMDB episode_credits %s s%s e%s: disk hit", series_id, season, episode)
         return cached
+    logger.debug("TMDB episode_credits %s s%s e%s: API request", series_id, season, episode)
     data = _tmdb_request(f"/tv/{series_id}/season/{season}/episode/{episode}/credits")
     if not data:
         return None
@@ -518,15 +578,17 @@ def get_episode_metadata(programme_name: str, path: Path) -> dict | None:
 def build_epg_xml() -> str:
     """
     Build XMLTV EPG for all channels. Schedule repeats from midnight UTC (same
-    epoch as live stream). Programmes generated for EPG_DAYS. Uses cached schedule.
+    epoch as live stream). Programmes generated for EPG_TIMESPAN_DAYS. Uses cached schedule.
     """
+    epg_start = time.monotonic()
     channels = get_channels()
     if not channels:
         return '<?xml version="1.0" encoding="UTF-8"?>\n<tv></tv>'
 
+    logger.info("EPG build started (%s channels)", len(channels))
     now = datetime.now(timezone.utc)
     epoch = _schedule_epoch_utc()
-    end_epoch = epoch + timedelta(days=EPG_DAYS)
+    end_epoch = epoch + timedelta(days=EPG_TIMESPAN_DAYS)
 
     root = ET.Element("tv")
     root.set("source-info-name", "self-hosted-iptv")
@@ -538,10 +600,13 @@ def build_epg_xml() -> str:
         chan_el = ET.SubElement(root, "channel", id=cid)
         ET.SubElement(chan_el, "display-name").text = name
 
+    total_programmes = 0
     for ch in channels:
         cid = ch.get("id", ch.get("name", ""))
+        ch_start = time.monotonic()
         schedule = get_or_build_schedule(cid)
         if not schedule:
+            logger.debug("EPG channel %s: no schedule", cid)
             continue
         paths, durations = schedule
         cycle_duration_sec = sum(durations)
@@ -552,6 +617,7 @@ def build_epg_xml() -> str:
         for d in durations[:-1]:
             offsets_sec.append(offsets_sec[-1] + d)
 
+        channel_programmes = 0
         cycle_start = epoch
         while cycle_start < end_epoch:
             for i, (path, dur) in enumerate(zip(paths, durations)):
@@ -561,6 +627,7 @@ def build_epg_xml() -> str:
                     continue
                 if start_dt >= end_epoch:
                     break
+                channel_programmes += 1
                 prog = ET.SubElement(root, "programme",
                     start=_format_xmltv_time(start_dt),
                     stop=_format_xmltv_time(stop_dt),
@@ -606,7 +673,13 @@ def build_epg_xml() -> str:
                         ET.SubElement(prog, "episode-num", system="onscreen").text = f"S{s:02d}E{e:02d}"
             cycle_start += cycle_delta
 
+        ch_elapsed = time.monotonic() - ch_start
+        total_programmes += channel_programmes
+        logger.info("EPG channel %s: %s programmes in %.1fs", cid, channel_programmes, ch_elapsed)
+
     ET.indent(root, space="  ")
+    epg_elapsed = time.monotonic() - epg_start
+    logger.info("EPG build finished in %.1fs (%s programmes total)", epg_elapsed, total_programmes)
     return '<?xml version="1.0" encoding="UTF-8"?>\n' + ET.tostring(root, encoding="unicode", default_namespace=None)
 
 
@@ -845,8 +918,19 @@ class IPTVHandler(BaseHTTPRequestHandler):
 
 
 def main():
+    log_level = getattr(logging, os.environ.get("LOG_LEVEL", "INFO").upper(), logging.INFO)
+    logging.basicConfig(
+        level=log_level,
+        format="%(asctime)s [%(levelname)s] %(name)s: %(message)s",
+        datefmt="%Y-%m-%d %H:%M:%S",
+    )
     if not CHANNELS_FILE.exists():
         print(f"Warning: {CHANNELS_FILE} not found. Create it from data/channels.json.example")
+    logger.info(
+        "EPG timespan: %s days, schedule refresh after: %.1f h",
+        EPG_TIMESPAN_DAYS,
+        SCHEDULE_CACHE_TTL_SEC / 3600,
+    )
     port = 8080
     server = HTTPServer(("0.0.0.0", port), IPTVHandler)
     print(f"Serving at http://0.0.0.0:{port}/  (playlist: http://<host>:{port}/playlist.m3u)")