From 77f7a2341043773df4b7386cc75876125b2aeeb9 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Sat, 30 May 2026 12:08:43 -0400 Subject: [PATCH 1/2] =?UTF-8?q?feat(scheduler):=20order=20due=20sources=20?= =?UTF-8?q?by=20last=5Fchecked=5Fat=20=E2=80=94=20most=20overdue=20first?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit select_due_sources returned rows in undefined order (Postgres-determined, typically PK). At tick rates that outpace download-queue throughput, a freshly-rerun source could keep getting re-queued ahead of one that's still waiting for its first attempt this cycle. Operator-flagged 2026-05-30: > if there are 8 hours before a source is due again and 40 full time > downloads can happen in that period that means that there's a chance > the first one to fire gets back into the download queue before item 41 > has a chance to get downloaded. Added `ORDER BY last_checked_at ASC NULLS FIRST, id` to the due-source SELECT. Never-checked sources go first, then longest-since-checked, then ties broken by id. Combined with Celery's FIFO `download` queue, the oldest-overdue source in each tick now reaches a worker before any fresher one. Test pins the ordering: a NULL-last_checked source, a 4-hour-overdue source, and a 2-min-overdue source come back in that exact order from select_due_sources. Co-Authored-By: Claude Opus 4.7 (1M context) --- backend/app/services/scheduler_service.py | 8 +++++ tests/test_scheduler_service.py | 39 +++++++++++++++++++++++ 2 files changed, 47 insertions(+) diff --git a/backend/app/services/scheduler_service.py b/backend/app/services/scheduler_service.py index 3c42ca1..dd038a4 100644 --- a/backend/app/services/scheduler_service.py +++ b/backend/app/services/scheduler_service.py @@ -116,6 +116,13 @@ async def select_due_sources(session: AsyncSession) -> list[Source]: whose platform is currently in a rate-limit cooldown are excluded — the cooldown is the preventive half of the burst-prevention pair (per-source consecutive_failures backoff handles the offending source itself). + + Ordering: last_checked_at ASC NULLS FIRST, then id. Never-checked + sources go first, then the longest-since-checked, so the most overdue + sources hit Celery's FIFO download queue first. Anti-starvation: if + queue throughput ever falls below the tick rate, a freshly-rerun source + can't keep cutting in line ahead of one that hasn't been checked at all. + Operator-confirmed 2026-05-30. """ rows = (await session.execute( select(Source) @@ -123,6 +130,7 @@ async def select_due_sources(session: AsyncSession) -> list[Source]: .join(Artist, Source.artist_id == Artist.id) .where(Source.enabled.is_(True)) .where(Artist.auto_check.is_(True)) + .order_by(Source.last_checked_at.asc().nulls_first(), Source.id) )).scalars().all() cooldowns = await _platforms_in_cooldown(session) diff --git a/tests/test_scheduler_service.py b/tests/test_scheduler_service.py index 03aab3a..e94c554 100644 --- a/tests/test_scheduler_service.py +++ b/tests/test_scheduler_service.py @@ -233,6 +233,45 @@ async def test_select_ignores_expired_cooldown(db): assert any(s.url == "https://cd-exp" for s in due) +@pytest.mark.asyncio +async def test_select_orders_most_overdue_first_then_id(db): + """Within the due set, sources are ordered by last_checked_at ASC NULLS + FIRST. Combined with Celery FIFO on the download queue, the most-overdue + source in each tick reaches a worker first — preventing the 'a freshly- + rerun source keeps cutting in line ahead of one that's still waiting' + starvation pattern when queue throughput is below the tick population.""" + artist = await _seed_artist(db, interval=60, name="order-test") + now = datetime.now(UTC) + # Newest check — least overdue (but still past its 60s interval). + s_new = Source( + artist_id=artist.id, platform="patreon", url="https://order-new", + enabled=True, consecutive_failures=0, + last_checked_at=now - timedelta(minutes=2), + ) + # Oldest check — most overdue among checked sources. + s_old = Source( + artist_id=artist.id, platform="patreon", url="https://order-old", + enabled=True, consecutive_failures=0, + last_checked_at=now - timedelta(hours=4), + ) + # Never checked — wins the ordering (NULLS FIRST). + s_never = Source( + artist_id=artist.id, platform="patreon", url="https://order-never", + enabled=True, consecutive_failures=0, + ) + db.add_all([s_new, s_old, s_never]) + await db.commit() + + due = await select_due_sources(db) + # Filter to just our test seeds (concurrent tests may add others). + urls = [s.url for s in due if s.url.startswith("https://order-")] + assert urls == [ + "https://order-never", + "https://order-old", + "https://order-new", + ] + + @pytest.mark.asyncio async def test_set_platform_cooldown_upserts(db): """Calling set_platform_cooldown twice on the same platform updates From 99b66aa85f4147e84a7408778b1fdfad1a477109 Mon Sep 17 00:00:00 2001 From: Bryan Van Deusen Date: Sat, 30 May 2026 14:16:54 -0400 Subject: [PATCH 2/2] fix(download): preserve partial output + classify timeouts richer MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Operator-flagged 2026-05-30: "the fail state of timeouts doesn't show anything other than that the task timedout and was cleaned up. I can't tell why it ran over or if it was stuck failed or there was just that much to get." The TimeoutExpired branch was returning a DownloadResult with no stdout, no stderr, no files_downloaded, and a generic "Download timed out after N seconds" message — even though subprocess.TimeoutExpired carries the partial output gallery-dl emitted before being killed. Now: - Capture e.stdout / e.stderr (coerced str if bytes; "" if None). - Count files_downloaded from partial stdout via _count_downloaded_files. - Surface a tail-of-stderr hint in error_message so the UI summary tells the operator at a glance whether it was "lots of content" (high count, clean stderr), "stuck retrying" (any count, 429-spam stderr), or "hung silent" (zero count, "no stderr output"). - Promote error_type to RATE_LIMITED when the partial stderr matches RATE_LIMIT_PATTERNS — gallery-dl spinning on retries through the whole 900s window is the timeout-shaped tail of a real rate limit, and the platform cooldown should kick in for the same reason. Existing test_download_timeout strengthened to also assert empty-partial case stays correctly TIMEOUT-classified with no preserved output. New test_download_timeout_preserves_partial_output_and_classifies covers the rich-partial-output → RATE_LIMITED promotion path. DownloadEvent.metadata already flows stdout/stderr/run_stats from DownloadResult via _phase3_persist — no UI change needed; the existing DownloadDetailModal will surface the captured output automatically once the build redeploys. Co-Authored-By: Claude Opus 4.7 (1M context) --- backend/app/services/gallery_dl.py | 52 +++++++++++++++++++++++++++--- tests/test_gallery_dl_service.py | 48 +++++++++++++++++++++++++++ 2 files changed, 96 insertions(+), 4 deletions(-) diff --git a/backend/app/services/gallery_dl.py b/backend/app/services/gallery_dl.py index 2883bd4..c356908 100644 --- a/backend/app/services/gallery_dl.py +++ b/backend/app/services/gallery_dl.py @@ -641,13 +641,57 @@ class GalleryDLService: started_at=started_at, completed_at=completed_at, ) - except subprocess.TimeoutExpired: + except subprocess.TimeoutExpired as e: duration = time.time() - start_time - log.error("Download timeout for %s/%s after %.1fs", artist_slug, platform, duration) + # subprocess.run(text=True) makes these str if non-None, but the + # caller may have raised TimeoutExpired manually with None or + # bytes (tests do); coerce both cases to str. + partial_stdout = e.stdout or "" + partial_stderr = e.stderr or "" + if isinstance(partial_stdout, bytes): + partial_stdout = partial_stdout.decode("utf-8", "replace") + if isinstance(partial_stderr, bytes): + partial_stderr = partial_stderr.decode("utf-8", "replace") + + files_so_far = self._count_downloaded_files(partial_stdout) + written_so_far = [str(p) for p in self._written_paths(partial_stdout)] + stderr_lines = partial_stderr.strip().splitlines() + tail_hint = stderr_lines[-1] if stderr_lines else "no stderr output" + + # If the partial output already shows a rate-limit pattern, the + # timeout was almost certainly gallery-dl spinning on retries — + # promote to RATE_LIMITED so _update_source_health stamps the + # platform cooldown (same code path as a clean-exit rate limit). + # Otherwise stay TIMEOUT and let the captured stdout/stderr + + # files_so_far tell the operator whether it was "lots of + # content" vs "stuck retrying" vs "hung silent". + combined = (partial_stdout + "\n" + partial_stderr).lower() + if any(p in combined for p in self.RATE_LIMIT_PATTERNS): + error_type = ErrorType.RATE_LIMITED + error_message = ( + f"Rate-limited and never completed within " + f"{source_config.timeout}s ({files_so_far} files written)" + ) + else: + error_type = ErrorType.TIMEOUT + error_message = ( + f"Download timed out after {source_config.timeout}s — " + f"{files_so_far} file(s) written; last stderr: {tail_hint}" + ) + + log.error( + "Download timeout for %s/%s after %.1fs (%d files written, " + "last stderr: %s)", + artist_slug, platform, duration, files_so_far, tail_hint, + ) + return DownloadResult( success=False, url=url, artist_slug=artist_slug, platform=platform, - error_type=ErrorType.TIMEOUT, - error_message=f"Download timed out after {source_config.timeout} seconds", + files_downloaded=files_so_far, + written_paths=written_so_far, + stdout=partial_stdout, stderr=partial_stderr, + return_code=-1, # killed by timeout, no real exit code + error_type=error_type, error_message=error_message, duration_seconds=duration, started_at=started_at, completed_at=datetime.now(UTC).isoformat(), diff --git a/tests/test_gallery_dl_service.py b/tests/test_gallery_dl_service.py index f172643..35d2d04 100644 --- a/tests/test_gallery_dl_service.py +++ b/tests/test_gallery_dl_service.py @@ -91,6 +91,54 @@ async def test_download_timeout(gdl, monkeypatch): ) assert result.success is False assert result.error_type == ErrorType.TIMEOUT + # Empty-partial timeout: no preserved output and zero files. + assert result.stdout == "" + assert result.stderr == "" + assert result.files_downloaded == 0 + + +@pytest.mark.asyncio +async def test_download_timeout_preserves_partial_output_and_classifies(gdl, monkeypatch): + """When gallery-dl is killed by timeout but had emitted partial output, + the DownloadResult preserves stdout/stderr, counts files written so + far, and promotes to RATE_LIMITED if the partial stderr shows a rate- + limit pattern (so the platform cooldown kicks in). Without this, the + operator only sees 'timed out' with no clue whether it was 'lots of + content', 'stuck retrying', or 'hung silent'.""" + import subprocess as sp + + # Simulate gallery-dl writing two files, then spinning on 429s. + partial_stdout = ( + "/tmp/images/alice/file_001.jpg\n" + "/tmp/images/alice/file_002.jpg\n" + ) + partial_stderr = ( + "[urllib3] 429 Too Many Requests; sleeping 60s\n" + "[urllib3] 429 Too Many Requests; sleeping 60s\n" + ) + + def _raise(*a, **k): + raise sp.TimeoutExpired( + cmd="gallery-dl", timeout=900, + output=partial_stdout, stderr=partial_stderr, + ) + + monkeypatch.setattr("backend.app.services.gallery_dl.subprocess.run", _raise) + result = await gdl.download( + url="https://patreon.com/alice", artist_slug="alice", platform="patreon", + source_config=SourceConfig(timeout=900), + ) + assert result.success is False + # Partial output preserved on the DownloadResult — _phase3_persist + # writes them into download_event.metadata so the UI can render them. + assert result.stdout == partial_stdout + assert result.stderr == partial_stderr + # Files counted from partial stdout (lines starting with '/'). + assert result.files_downloaded == 2 + # Rate-limit pattern in partial stderr → promoted to RATE_LIMITED so + # _update_source_health stamps the platform cooldown. + assert result.error_type == ErrorType.RATE_LIMITED + assert "Rate-limited" in result.error_message @pytest.mark.asyncio