diff --git a/scripts/check-session.py b/scripts/check-session.py new file mode 100755 index 0000000..8f09030 --- /dev/null +++ b/scripts/check-session.py @@ -0,0 +1,70 @@ +#!/usr/bin/env python3 +""" +Preflight for gdl-cron.sh: is there a usable Instagram login in the cookie jar gdl reads? + +gdl-sync.py runs gallery-dl with `--cookies-from-browser chrome:`, so what matters +is not what the interactive Chrome window LOOKS like (an open tab keeps showing its logged-in +UI long after the session died -- found 2026-10-14, stories had been empty for a week) but +whether the profile's cookie DB holds a `sessionid`. This reads the same DB, the same way. + +Never prints cookie values -- only the name, expiry, and a verdict. + +Exit 0 logged in (a non-expired sessionid exists) +Exit 1 logged out / unreadable -- the caller must not scrape +""" +import datetime as dt +import os +import shutil +import sqlite3 +import sys +import tempfile +import time +from pathlib import Path + +PROFILE = Path(os.environ.get("GDL_COOKIE_PROFILE", + str(Path.home() / ".config/google-chrome-devtools"))) +WARN_DAYS = 7 + + +def main() -> int: + src = PROFILE / "Default" / "Cookies" + if not src.exists(): + print(f"no cookie DB at {src} -- Chrome profile missing?") + return 1 + with tempfile.TemporaryDirectory() as tmp: + # Copy first: Chrome holds the live DB open, and a copy keeps this read-only. + for suffix in ("", "-journal", "-wal", "-shm"): + f = Path(str(src) + suffix) + if f.exists(): + shutil.copy2(f, Path(tmp) / f.name) + try: + con = sqlite3.connect(str(Path(tmp) / "Cookies")) + rows = con.execute( + "SELECT expires_utc, has_expires FROM cookies " + "WHERE host_key LIKE '%instagram.com' AND name = 'sessionid'").fetchall() + except sqlite3.Error as exc: + print(f"cannot read cookie DB: {exc}") + return 1 + if not rows: + print("NOT LOGGED IN: no Instagram sessionid in the Chrome profile " + f"{PROFILE}. Log in to Instagram in that Chrome window (the open tab can " + "look logged in while stale -- reload it), then re-run.") + return 1 + expires, has_expires = rows[0] + if has_expires: + exp = dt.datetime.fromtimestamp(expires / 1_000_000 - 11644473600, dt.timezone.utc) + left = (exp.timestamp() - time.time()) / 86400 + if left <= 0: + print(f"NOT LOGGED IN: the Instagram sessionid expired {exp:%Y-%m-%d}.") + return 1 + note = f"expires {exp:%Y-%m-%d}" + if left < WARN_DAYS: + note += f" (WARNING: only {left:.1f} days left)" + print(f"session ok: sessionid present, {note}") + else: + print("session ok: sessionid present (session cookie, no expiry)") + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/scripts/gdl-cron.sh b/scripts/gdl-cron.sh index 20dc081..f1219c9 100755 --- a/scripts/gdl-cron.sh +++ b/scripts/gdl-cron.sh @@ -66,6 +66,24 @@ mkdir -p "$GDL_HOME/logs" [ -n "$HC_URL" ] && curl -fsS -m 10 --retry 3 -o /dev/null "$HC_URL/start" || true +# Preflight: refuse to scrape logged out. gdl reads the Chrome profile's cookie DB, and the +# session in it can die silently -- from 2026-10-07 every stories run fetched "No results" +# for all six profiles and still exited 0, so nothing alerted and a week of stories (which +# cannot be backfilled) was lost. An open Chrome tab keeps showing its logged-in UI after +# that, so only the cookie DB tells the truth. Exit 76 turns the Healthchecks check red. +SESSION_CHECK="$GDL_HOME/check-session.py" +if [ -x "$SESSION_CHECK" ]; then + if ! SESSION_MSG=$("$SESSION_CHECK" 2>&1); then + echo "=== $MODE run $(date -Is) ===" | tee -a "$LOG" + echo "ABORT (no requests sent): $SESSION_MSG" | tee -a "$LOG" >&2 + echo "=== exit 76 at $(date -Is) ===" | tee -a "$LOG" + [ -n "$HC_URL" ] && curl -fsS -m 10 --retry 3 --data-binary "@$LOG" \ + -o /dev/null "$HC_URL/76" || true + exit 76 + fi + echo "preflight: $SESSION_MSG" | tee -a "$LOG" +fi + # Staging is wiped every run ON PURPOSE. What we already hold is decided by the # skip-archive (--download-archive), never by which files happen to be sitting # in staging, so starting empty is correct -- and it keeps the publish rsync @@ -111,6 +129,16 @@ if [ "$MODE" = "stories" ] && grep -q "sources : 0 to sync" "$RUNOUT"; then [ "$status" -eq 0 ] && status=75 fi +# Every stories source empty for several days running = a session Instagram stopped +# honouring while the cookie is still in the jar (the preflight cannot see that). Stories-only: +# other modes legitimately return few items per source. See stories-streak.py. +if [ "$MODE" = "stories" ] && [ "$status" -eq 0 ] && [ -x "$GDL_HOME/stories-streak.py" ]; then + if ! STREAK_MSG=$("$GDL_HOME/stories-streak.py" "$RUNOUT" "$GDL_HOME/stories-empty-streak" 2>&1); then + echo "WARNING: $STREAK_MSG" | tee -a "$LOG" >&2 + status=77 + fi +fi + echo "=== exit $status at $(date -Is) ===" | tee -a "$LOG" # The log becomes the ping body -- healthchecks.io keeps the last ping's body diff --git a/scripts/gdl-sync.py b/scripts/gdl-sync.py index 67f633c..28c73ff 100755 --- a/scripts/gdl-sync.py +++ b/scripts/gdl-sync.py @@ -94,6 +94,7 @@ import re import shutil import subprocess import sys +import threading import time from dataclasses import dataclass, field from pathlib import Path @@ -460,6 +461,71 @@ def build_config(rate: str, sleep_request: list[float], # Planning and execution # -------------------------------------------------------------------------- +def _fmt_elapsed(sec: float) -> str: + sec = int(sec) + h, rest = divmod(sec, 3600) + m, s = divmod(rest, 60) + return f"{h}h{m:02d}m" if h else (f"{m}m{s:02d}s" if m else f"{s}s") + + +def _count_new(root: Path, since: float) -> tuple[int, str | None]: + """Media files under `root` written since `since`, and the newest one's name.""" + n, newest, newest_t = 0, None, 0.0 + for d, _dirs, files in os.walk(root): + for f in files: + if f.endswith((".txt", ".json", ".part")): + continue + try: + mt = os.stat(os.path.join(d, f)).st_mtime + except OSError: + continue + if mt >= since: + n += 1 + if mt > newest_t: + newest, newest_t = f, mt + return n, newest + + +class Heartbeat: + """ + Prints a progress line every `every` seconds while a quiet step runs. + + A healthy run looks hung otherwise: pacing is 12-20s between requests, the + generated config sets `output: null` (no per-file lines), and the live + listing probe captures gallery-dl output until it finishes. With `watch` + set, the line also reports how many files have landed there so far. + """ + + def __init__(self, label: str, watch: Path | None = None, every: float = 60.0): + self.label, self.watch, self.every = label, watch, every + self._stop = threading.Event() + self._thread = threading.Thread(target=self._run, daemon=True) + self.t0 = time.time() + + def _run(self) -> None: + while not self._stop.wait(self.every): + msg = f" ... {self.label}: {_fmt_elapsed(time.time() - self.t0)} elapsed" + if self.watch is not None: + n, newest = _count_new(self.watch, self.t0) + msg += f", {n} new file(s) so far" + if newest: + msg += f" (latest: {newest})" + print(msg, flush=True) + + def __enter__(self) -> "Heartbeat": + self.t0 = time.time() + self._thread.start() + return self + + def __exit__(self, *exc) -> None: + self._stop.set() + self._thread.join() + + @property + def elapsed(self) -> float: + return time.time() - self.t0 + + def gdl_command(src: Source, staging: Path, config: Path, cookies: str, archive_db: Path | None) -> list[str]: cmd = [ @@ -1003,8 +1069,9 @@ def main() -> int: 0.0 if args.force else args.probe_ttl) failures = 0 - for prof, src, seed in plan: - print(f"==> {prof.user} / {src.kind}") + for n_src, (prof, src, seed) in enumerate(plan, 1): + print(f"==> [{n_src}/{len(plan)}] {prof.user} / {src.kind} " + f"({dt.datetime.now().strftime('%H:%M:%S')})") stage_dir = args.staging / (src.directory or ".") stage_dir.mkdir(parents=True, exist_ok=True) @@ -1016,7 +1083,10 @@ def main() -> int: try: live = probes.get(src.url, now_ts) if live is None: - live = probe_live(src, config_path, args.cookies) + print(" listing live items (metadata only; quiet until done)...") + with Heartbeat("listing") as hb: + live = probe_live(src, config_path, args.cookies) + print(f" listed {len(live)} item(s) in {_fmt_elapsed(hb.elapsed)}") probes.put(src.url, live, stamp) probes.save() else: @@ -1034,12 +1104,16 @@ def main() -> int: cmd = gdl_command(src, args.staging, config_path, args.cookies, args.archive_db) - result = subprocess.run(cmd) + with Heartbeat("fetching", watch=stage_dir) as hb: + result = subprocess.run(cmd) + n_new, _ = _count_new(stage_dir, hb.t0) if result.returncode != 0: failures += 1 # Keep going: one private or renamed profile must not abort the run. - print(f" FAILED (exit {result.returncode})", file=sys.stderr) + print(f" FAILED (exit {result.returncode}) after " + f"{_fmt_elapsed(hb.elapsed)}", file=sys.stderr) else: + print(f" done in {_fmt_elapsed(hb.elapsed)}, {n_new} new file(s)") # Recorded even for an empty fetch: the request was still spent. state.mark_fetched(src.url, stamp) state.save() diff --git a/scripts/stories-streak.py b/scripts/stories-streak.py new file mode 100755 index 0000000..e48f898 --- /dev/null +++ b/scripts/stories-streak.py @@ -0,0 +1,57 @@ +#!/usr/bin/env python3 +""" +Detect a silently dead Instagram session from a stories run's output. + +A dead session (killed server-side while the sessionid is still in the cookie jar, so +check-session.py passes) shows up as every fetched stories source returning +"No results" -- the daily run still exits 0. From 2026-10-07 all six profiles came back +empty every day and nothing alerted. One all-empty day is normal (nobody posted a story); +several in a row across ALL sources is not. + +Usage: stories-streak.py [state file] +Counts at most one day per calendar date (manual re-runs don't inflate it). Prints a message +and exits 1 once the streak reaches GDL_EMPTY_STREAK_FAIL days (default 3); exits 0 otherwise. +Runs that fetched nothing (all skipped / no sources) leave the streak untouched. +""" +import datetime as dt +import os +import re +import sys +from pathlib import Path + +THRESHOLD = int(os.environ.get("GDL_EMPTY_STREAK_FAIL", "3")) + + +def main() -> int: + out = Path(sys.argv[1]).read_text(errors="replace") + state = Path(sys.argv[2] if len(sys.argv) > 2 + else Path.home() / "gdl" / "stories-empty-streak") + m = re.search(r"sources\s*:\s*(\d+) to sync", out) + to_sync = int(m.group(1)) if m else 0 + if to_sync == 0: + return 0 # nothing fetched: no evidence either way + empty = len(re.findall(r"No results for \S*/stories/", out)) + today = dt.date.today().isoformat() + last_date, streak = "", 0 + try: + last_date, s = state.read_text().split() + streak = int(s) + except (OSError, ValueError): + pass + if empty >= to_sync: # every fetched source came back empty + if last_date != today: + streak += 1 + else: + streak = 0 + state.write_text(f"{today} {streak}\n") + if streak >= THRESHOLD: + print(f"SESSION LIKELY DEAD: stories came back empty for ALL {to_sync} profile(s) on " + f"{streak} consecutive day(s). The cookie is present but Instagram is probably " + "no longer honouring it -- log in again in the Chrome window (reload the tab to " + "check) and re-run.") + return 1 + return 0 + + +if __name__ == "__main__": + sys.exit(main()) diff --git a/scripts/systemd/gdl-sync@.service b/scripts/systemd/gdl-sync@.service index 829b0c4..ef9ca3f 100644 --- a/scripts/systemd/gdl-sync@.service +++ b/scripts/systemd/gdl-sync@.service @@ -8,7 +8,7 @@ Wants=network-online.target [Service] Type=oneshot -ExecStart=%h/gdl/gdl-cron.sh %i +ExecStart=%h/gdl/run-%i.sh # A sync has no deadline and the pacing is deliberately slow; a full sweep can # run for hours. Never let systemd kill one midway -- a half-published run is # the one state the publish step is designed to avoid. diff --git a/scripts/test_gdl_sync.py b/scripts/test_gdl_sync.py index 9b1ccb6..6f0e8b8 100644 --- a/scripts/test_gdl_sync.py +++ b/scripts/test_gdl_sync.py @@ -343,5 +343,43 @@ class PostUrlsFile(unittest.TestCase): ]) +class ProgressOutput(unittest.TestCase): + """The heartbeat that stops a healthy paced run (12-20s between requests, no per-file + output) from looking hung.""" + + def test_elapsed_formatting(self): + self.assertEqual(gdl._fmt_elapsed(5), "5s") + self.assertEqual(gdl._fmt_elapsed(125), "2m05s") + self.assertEqual(gdl._fmt_elapsed(7300), "2h01m") + + def test_count_new_counts_media_written_since_and_ignores_sidecars(self): + with tempfile.TemporaryDirectory() as d: + root = Path(d) + (root / "sub").mkdir() + old = root / "old.jpg" + old.write_text("x") + import os + os.utime(old, (1, 1)) # long before `since` + (root / "sub" / "new.jpg").write_text("x") + (root / "sub" / "new.mp4").write_text("x") + for sidecar in ("new.txt", "new.json", "half.jpg.part"): + (root / "sub" / sidecar).write_text("x") + n, newest = gdl._count_new(root, since=1000) + self.assertEqual(n, 2) + self.assertIn(newest, ("new.jpg", "new.mp4")) + + def test_heartbeat_prints_while_running_and_stops_cleanly(self): + with tempfile.TemporaryDirectory() as d: + with mock.patch("builtins.print") as pr: + with gdl.Heartbeat("fetching", watch=Path(d), every=0.05) as hb: + (Path(d) / "a.jpg").write_text("x") + import time + time.sleep(0.2) + lines = [str(c.args[0]) for c in pr.call_args_list] + self.assertTrue(any("fetching" in s and "new file(s) so far" in s for s in lines)) + self.assertFalse(hb._thread.is_alive()) + self.assertGreater(hb.elapsed, 0.1) + + if __name__ == "__main__": unittest.main(verbosity=2) diff --git a/scripts/test_session_guards.py b/scripts/test_session_guards.py new file mode 100644 index 0000000..af7a3fa --- /dev/null +++ b/scripts/test_session_guards.py @@ -0,0 +1,160 @@ +""" +Tests for the two guards that stop a dead Instagram session going unnoticed: + + check-session.py preflight: is there a usable `sessionid` in the Chrome cookie DB? + stories-streak.py postflight: did every stories source come back empty for days running? + +Both are run as subprocesses (the way gdl-cron.sh runs them); neither touches the network. + + python3 -I -m unittest scripts/test_session_guards.py +""" +import datetime as dt +import os +import sqlite3 +import subprocess +import sys +import tempfile +import time +import unittest +from pathlib import Path + +HERE = Path(__file__).resolve().parent +CHROME_EPOCH = 11644473600 # seconds between 1601-01-01 and 1970-01-01 + + +def run(script, *args, env=None): + e = {**os.environ, **(env or {})} + return subprocess.run([sys.executable, str(HERE / script), *args], + capture_output=True, text=True, env=e) + + +class CheckSession(unittest.TestCase): + def profile(self, rows): + """A fake Chrome profile whose cookie DB holds `rows` = [(host, name, expires_unix|None)].""" + tmp = tempfile.TemporaryDirectory() + self.addCleanup(tmp.cleanup) + d = Path(tmp.name) / "Default" + d.mkdir() + con = sqlite3.connect(d / "Cookies") + con.execute("CREATE TABLE cookies (host_key TEXT, name TEXT, expires_utc INTEGER, has_expires INTEGER)") + for host, name, exp in rows: + con.execute("INSERT INTO cookies VALUES (?,?,?,?)", + (host, name, 0 if exp is None else (exp + CHROME_EPOCH) * 1_000_000, + 0 if exp is None else 1)) + con.commit() + con.close() + return tmp.name + + def check(self, rows): + return run("check-session.py", env={"GDL_COOKIE_PROFILE": self.profile(rows)}) + + def test_valid_sessionid_passes(self): + r = self.check([(".instagram.com", "sessionid", time.time() + 200 * 86400)]) + self.assertEqual(r.returncode, 0, r.stdout) + self.assertIn("session ok", r.stdout) + self.assertNotIn("WARNING", r.stdout) + + def test_missing_sessionid_fails_even_with_other_instagram_cookies(self): + # What the real failure looked like: csrftoken/ds_user_id/mid linger after logout. + r = self.check([(".instagram.com", "csrftoken", time.time() + 86400), + (".instagram.com", "ds_user_id", time.time() + 86400), + (".instagram.com", "mid", time.time() + 86400)]) + self.assertEqual(r.returncode, 1) + self.assertIn("NOT LOGGED IN", r.stdout) + + def test_expired_sessionid_fails(self): + r = self.check([(".instagram.com", "sessionid", time.time() - 86400)]) + self.assertEqual(r.returncode, 1) + self.assertIn("expired", r.stdout) + + def test_near_expiry_warns_but_passes(self): + r = self.check([(".instagram.com", "sessionid", time.time() + 3 * 86400)]) + self.assertEqual(r.returncode, 0) + self.assertIn("WARNING", r.stdout) + + def test_session_cookie_without_expiry_passes(self): + r = self.check([(".instagram.com", "sessionid", None)]) + self.assertEqual(r.returncode, 0) + + def test_other_sites_sessionid_does_not_count(self): + r = self.check([(".example.com", "sessionid", time.time() + 86400)]) + self.assertEqual(r.returncode, 1) + + def test_missing_profile_fails_loudly(self): + r = run("check-session.py", env={"GDL_COOKIE_PROFILE": "/nonexistent/profile"}) + self.assertEqual(r.returncode, 1) + self.assertIn("no cookie DB", r.stdout) + + def test_never_prints_cookie_values(self): + # The fake DB has no value column at all; the script must not need one. + r = self.check([(".instagram.com", "sessionid", time.time() + 90 * 86400)]) + self.assertNotIn("sessionid=", r.stdout + r.stderr) + + +class StoriesStreak(unittest.TestCase): + def setUp(self): + tmp = tempfile.TemporaryDirectory() + self.addCleanup(tmp.cleanup) + self.dir = Path(tmp.name) + self.state = self.dir / "streak" + self.today = dt.date.today().isoformat() + self.yesterday = (dt.date.today() - dt.timedelta(days=1)).isoformat() + + def out(self, to_sync, empty, skipped=0): + lines = [f"sources : {to_sync} to sync, {skipped} skipped"] + lines += [f"[instagram][info] No results for https://www.instagram.com/stories/user{i}/" + for i in range(empty)] + p = self.dir / "run.out" + p.write_text("\n".join(lines) + "\n") + return p + + def streak(self, to_sync, empty, skipped=0): + return run("stories-streak.py", str(self.out(to_sync, empty, skipped)), str(self.state)) + + def stored(self): + return self.state.read_text().split() + + def test_all_empty_for_three_days_fails(self): + self.state.write_text(f"{self.yesterday} 2\n") + r = self.streak(6, 6) + self.assertEqual(r.returncode, 1) + self.assertIn("SESSION LIKELY DEAD", r.stdout) + self.assertEqual(self.stored(), [self.today, "3"]) + + def test_first_empty_day_is_quiet(self): + r = self.streak(6, 6) + self.assertEqual(r.returncode, 0) + self.assertEqual(self.stored(), [self.today, "1"]) + + def test_same_day_rerun_does_not_inflate_the_streak(self): + self.state.write_text(f"{self.today} 2\n") + r = self.streak(6, 6) + self.assertEqual(r.returncode, 0) + self.assertEqual(self.stored(), [self.today, "2"]) + + def test_any_story_resets_the_streak(self): + self.state.write_text(f"{self.yesterday} 2\n") + r = self.streak(6, 5) # one profile had a story + self.assertEqual(r.returncode, 0) + self.assertEqual(self.stored(), [self.today, "0"]) + + def test_run_that_fetched_nothing_leaves_state_alone(self): + self.state.write_text(f"{self.yesterday} 2\n") + r = self.streak(0, 0, skipped=6) + self.assertEqual(r.returncode, 0) + self.assertEqual(self.stored(), [self.yesterday, "2"]) + + def test_threshold_is_configurable(self): + r = run("stories-streak.py", str(self.out(6, 6)), str(self.state), + env={"GDL_EMPTY_STREAK_FAIL": "1"}) + self.assertEqual(r.returncode, 1) + + def test_corrupt_state_file_is_treated_as_no_history(self): + self.state.write_text("garbage\n") + r = self.streak(6, 6) + self.assertEqual(r.returncode, 0) + self.assertEqual(self.stored(), [self.today, "1"]) + + +if __name__ == "__main__": + unittest.main()