fix(download): salvage soft-time-limit kills + fix timeout ladder
Backfill downloads stranded with empty logs + a generic "stranded by recovery sweep" error. Root cause: the backfill gallery-dl subprocess timeout (1170s) exceeded download_source's Celery soft_time_limit (900s), so SoftTimeLimitExceeded preempted subprocess.TimeoutExpired. The TimeoutExpired path (which captures partial stdout/stderr and finalizes the event) never ran, the event was left 'running', and phase 3 never decremented backfill_runs_remaining — so the source re-ran and re-stranded every tick (Anduo #39912). Two layers: 1. Raise download_source limits (soft 900→1350, hard 1200→1500) so both subprocess budgets (870 tick / 1170 backfill) sit below the soft limit with phase-3 persist headroom. Promote to module constants and guard the invariant with a test. 2. Catch SoftTimeLimitExceeded in download_source and finalize the in-flight event with a real reason, mirror phase-3 source-health, and decrement backfill so a chronically-slow source self-heals to tick mode. The existing celery_signals handler only covered TaskRun, not DownloadEvent — that was the gap. Updates stale 900/1200 references in gallery_dl.py + maintenance.py. Co-Authored-By: Claude Opus 4.8 (1M context) <noreply@anthropic.com>
This commit is contained in:
@@ -59,29 +59,33 @@ TICK_SKIP_VALUE = "exit:20"
|
||||
# Source.backfill_runs_remaining > 0 selects this mode; the longer
|
||||
# timeout below absorbs creators with thousands of posts.
|
||||
#
|
||||
# 30 seconds shy of Celery's hard `time_limit=1200` on download_source
|
||||
# (tasks/download.py:33). subprocess.run MUST raise TimeoutExpired
|
||||
# before Celery SIGKILLs the worker — same rationale as the tick
|
||||
# default at line 74. The audit (2026-06-02) caught this at 1800,
|
||||
# guaranteeing SIGKILL on any backfill that ran to its subprocess
|
||||
# budget: stdout/stderr lost, backfill_runs_remaining never
|
||||
# decrements, recovery sweep stamps generic "stranded" 30 min later.
|
||||
# Recreates the exact Knuxy #38275 failure mode the tick 870s default
|
||||
# was added to prevent. backfill_runs_remaining=3 still gives ~58
|
||||
# minutes of cumulative walk across three runs for prolific creators.
|
||||
# Sits below download_source's Celery soft_time_limit
|
||||
# (DOWNLOAD_SOFT_TIME_LIMIT=1350, tasks/download.py) with ~180s of
|
||||
# headroom for phase-3 persist. subprocess.run MUST raise TimeoutExpired
|
||||
# before Celery raises SoftTimeLimitExceeded — that exception path
|
||||
# captures partial stdout/stderr and finalizes the event; the soft-limit
|
||||
# path (until the 2026-06-03 fix) did not. Audit history: 1800 guaranteed
|
||||
# SIGKILL against the old hard limit (Knuxy #38275); 1170 was then sized
|
||||
# "30s shy of the hard limit (1200)" but still EXCEEDED the soft limit
|
||||
# (900), so SoftTimeLimitExceeded preempted TimeoutExpired and every
|
||||
# backfill stranded empty (Anduo #39912). Raising the Celery soft/hard
|
||||
# limits to 1350/1500 (tasks/download.py) is what made 1170 safe.
|
||||
# backfill_runs_remaining=3 still gives ~58 minutes of cumulative walk
|
||||
# across three runs for prolific creators.
|
||||
BACKFILL_SKIP_VALUE = True
|
||||
BACKFILL_TIMEOUT_SECONDS = 1170
|
||||
|
||||
|
||||
# 30 seconds shy of download_source's Celery soft_time_limit (900s, see
|
||||
# tasks/download.py:32). subprocess.run MUST raise TimeoutExpired before
|
||||
# Celery raises SoftTimeLimitExceeded — otherwise Celery wins the race,
|
||||
# SIGKILLs the worker, in-memory stdout/stderr is lost, and the
|
||||
# DownloadEvent ends up empty-logged with "stranded by recovery sweep"
|
||||
# 18 minutes later (operator-flagged 2026-05-31, Knuxy event #38275).
|
||||
# The 30s buffer absorbs scheduler jitter / GC pauses without making
|
||||
# legitimately-long-running syncs timeout-friendlier. Per-source bumps
|
||||
# still live in source.config_overrides for legitimately long syncs.
|
||||
# Sits well below download_source's Celery soft_time_limit
|
||||
# (DOWNLOAD_SOFT_TIME_LIMIT=1350, tasks/download.py). subprocess.run MUST
|
||||
# raise TimeoutExpired before Celery raises SoftTimeLimitExceeded —
|
||||
# otherwise Celery wins the race, SIGKILLs the worker, in-memory
|
||||
# stdout/stderr is lost, and the DownloadEvent ends up empty-logged with
|
||||
# "stranded by recovery sweep" (operator-flagged 2026-05-31, Knuxy event
|
||||
# #38275; recurred in backfill mode as Anduo #39912). Per-source bumps
|
||||
# still live in source.config_overrides for legitimately long syncs —
|
||||
# keep any override below the soft limit, or the soft-limit salvage path
|
||||
# in tasks/download.py (_finalize_soft_limited) is the only safety net.
|
||||
_DEFAULT_GDL_TIMEOUT_SECONDS = 870
|
||||
|
||||
|
||||
|
||||
@@ -1,12 +1,17 @@
|
||||
"""download_source Celery task — runs DownloadService for one source."""
|
||||
|
||||
import asyncio
|
||||
import logging
|
||||
from datetime import UTC, datetime
|
||||
from pathlib import Path
|
||||
|
||||
from celery.exceptions import SoftTimeLimitExceeded
|
||||
from sqlalchemy import select
|
||||
from sqlalchemy.exc import DBAPIError, OperationalError
|
||||
from sqlalchemy.orm import Session as SyncSession
|
||||
|
||||
from ..celery_app import celery
|
||||
from ..models import ImportSettings
|
||||
from ..models import DownloadEvent, ImportSettings, Source
|
||||
from ..services.credential_crypto import CredentialCrypto
|
||||
from ..services.credential_service import CredentialService
|
||||
from ..services.download_service import DownloadService
|
||||
@@ -16,9 +21,79 @@ from ..services.thumbnailer import Thumbnailer
|
||||
from ._async_session import async_session_factory
|
||||
from .import_file import _sync_session_factory
|
||||
|
||||
log = logging.getLogger(__name__)
|
||||
|
||||
IMAGES_ROOT = Path("/images")
|
||||
_KEY_PATH = IMAGES_ROOT / "secrets" / "credential_key.b64"
|
||||
|
||||
# Celery time budget for one download_source run. The ceiling that
|
||||
# governs *clean* teardown is the SOFT limit: it raises a catchable
|
||||
# SoftTimeLimitExceeded in-process, whereas the HARD limit SIGKILLs the
|
||||
# worker (no chance to finalize). Both gallery-dl subprocess budgets
|
||||
# (gallery_dl.py: _DEFAULT_GDL_TIMEOUT_SECONDS=870 tick,
|
||||
# BACKFILL_TIMEOUT_SECONDS=1170 backfill) MUST sit below the soft limit
|
||||
# so subprocess.run raises its own TimeoutExpired first — that path
|
||||
# captures partial stdout/stderr and finalizes the DownloadEvent. soft is
|
||||
# max-subprocess (1170) + ~180s phase-3 persist headroom; hard is soft +
|
||||
# 150s SIGKILL backstop. Audit 2026-06-03 (Anduo #39912): the old
|
||||
# soft=900 sat BELOW the 1170 backfill budget, so SoftTimeLimitExceeded
|
||||
# preempted TimeoutExpired and the event stranded empty. The recovery
|
||||
# sweep's DOWNLOAD_STALL_THRESHOLD_MINUTES (30 min) still trails the new
|
||||
# 25-min hard kill by 5 min, so it stays a true backstop. Invariant
|
||||
# guarded by test_timeout_ladder_keeps_subprocess_budgets_under_soft_limit.
|
||||
DOWNLOAD_SOFT_TIME_LIMIT = 1350
|
||||
DOWNLOAD_HARD_TIME_LIMIT = 1500
|
||||
|
||||
|
||||
def _finalize_soft_limited(session: SyncSession, source_id: int) -> None:
|
||||
"""Defense in depth for the soft-time-limit kill path.
|
||||
|
||||
A SoftTimeLimitExceeded unwinds download_source before phase 3 can
|
||||
finalize the DownloadEvent, leaving it 'running' until the recovery
|
||||
sweep stamps a context-free "stranded" error 30 min later — AND
|
||||
leaving backfill_runs_remaining undecremented so the source re-runs
|
||||
and re-strands every tick (Anduo #39912, 2026-06-03). Flip the
|
||||
in-flight event to error with a real reason, mirror phase 3's
|
||||
source-health write, and decrement any backfill budget so a
|
||||
chronically-slow source self-heals back to tick mode.
|
||||
|
||||
The caller owns the commit. All mutations are gated on actually
|
||||
finding a running event, so a benign late soft-limit (phase 3 already
|
||||
committed) is a no-op.
|
||||
"""
|
||||
now = datetime.now(UTC)
|
||||
ev = session.execute(
|
||||
select(DownloadEvent)
|
||||
.where(DownloadEvent.source_id == source_id)
|
||||
.where(DownloadEvent.status == "running")
|
||||
.order_by(DownloadEvent.id.desc())
|
||||
.limit(1)
|
||||
).scalar_one_or_none()
|
||||
if ev is None:
|
||||
return
|
||||
ev.status = "error"
|
||||
ev.finished_at = now
|
||||
ev.error = (
|
||||
f"killed by Celery soft time limit ({DOWNLOAD_SOFT_TIME_LIMIT}s) "
|
||||
"before the gallery-dl subprocess returned — the run exceeded its "
|
||||
"budget and its stdout/stderr were lost with the worker thread. "
|
||||
"If this recurs, the source is too large for one run; the backfill "
|
||||
"budget was decremented so the next tick walks less."
|
||||
)
|
||||
ev.metadata_ = {
|
||||
**(ev.metadata_ or {}),
|
||||
"error_type": "timeout",
|
||||
"soft_time_limited": True,
|
||||
}
|
||||
src = session.get(Source, source_id)
|
||||
if src is not None:
|
||||
src.consecutive_failures = (src.consecutive_failures or 0) + 1
|
||||
src.last_error = "soft time limit exceeded"
|
||||
src.error_type = "timeout"
|
||||
src.last_checked_at = now
|
||||
if (src.backfill_runs_remaining or 0) > 0:
|
||||
src.backfill_runs_remaining = max(0, src.backfill_runs_remaining - 1)
|
||||
|
||||
|
||||
@celery.task(
|
||||
name="backend.app.tasks.download.download_source",
|
||||
@@ -29,8 +104,8 @@ _KEY_PATH = IMAGES_ROOT / "secrets" / "credential_key.b64"
|
||||
retry_backoff_max=120,
|
||||
retry_jitter=True,
|
||||
max_retries=3,
|
||||
soft_time_limit=900,
|
||||
time_limit=1200,
|
||||
soft_time_limit=DOWNLOAD_SOFT_TIME_LIMIT,
|
||||
time_limit=DOWNLOAD_HARD_TIME_LIMIT,
|
||||
)
|
||||
def download_source(self, source_id: int) -> int:
|
||||
"""Returns the DownloadEvent.id."""
|
||||
@@ -73,4 +148,19 @@ def download_source(self, source_id: int) -> int:
|
||||
finally:
|
||||
await async_engine.dispose()
|
||||
|
||||
return asyncio.run(_run())
|
||||
try:
|
||||
return asyncio.run(_run())
|
||||
except SoftTimeLimitExceeded:
|
||||
# phase 3 never ran — salvage the in-flight event so the operator
|
||||
# sees a real reason instead of the recovery sweep's generic
|
||||
# "stranded" 30 min later (Anduo #39912). Best-effort: a failure
|
||||
# here must not mask the timeout. Re-raise so Celery + the
|
||||
# task_run signal handler still record the kill.
|
||||
try:
|
||||
SyncFactory = _sync_session_factory()
|
||||
with SyncFactory() as session:
|
||||
_finalize_soft_limited(session, source_id)
|
||||
session.commit()
|
||||
except Exception: # noqa: BLE001 — cleanup must not swallow the kill
|
||||
log.exception("soft-limit finalize failed for source %s", source_id)
|
||||
raise
|
||||
|
||||
@@ -46,9 +46,12 @@ MAX_RECOVERY_ATTEMPTS = 3
|
||||
ORPHAN_PENDING_THRESHOLD_MINUTES = 30
|
||||
|
||||
# DownloadEvent (pending|running) recovery threshold. download_source has
|
||||
# time_limit=1200s (20 min); 30 min is 10 min past that, so a legitimately-
|
||||
# running task is never killed by the sweep. Operator-confirmed 2026-05-29
|
||||
# after 43 sources stranded at "last check never" by the in-flight guard.
|
||||
# time_limit=1500s (25 min, DOWNLOAD_HARD_TIME_LIMIT); 30 min is 5 min past
|
||||
# that, so a legitimately-running task is hard-killed before the sweep ever
|
||||
# touches it — the sweep only catches events whose worker died without
|
||||
# finalizing. Operator-confirmed 2026-05-29 after 43 sources stranded at
|
||||
# "last check never" by the in-flight guard; budget bumped 2026-06-03 with
|
||||
# the soft/hard limit raise (Anduo #39912).
|
||||
DOWNLOAD_STALL_THRESHOLD_MINUTES = 30
|
||||
|
||||
OLD_TASK_DAYS = 7
|
||||
@@ -535,7 +538,7 @@ def recover_stalled_download_events() -> int:
|
||||
tasks.scan._tick_due_sources_async) inserts DownloadEvent(status='pending')
|
||||
and fires download_source.delay(). If that task dies before finalizing the
|
||||
event — worker OOM/SIGKILL, lost task, or a gallery-dl that didn't unwind
|
||||
on the 1200s hard time_limit — the event stays in-flight forever. The next
|
||||
on the 1500s hard time_limit — the event stays in-flight forever. The next
|
||||
tick then skips that source because of the in-flight guard (scan.py:168)
|
||||
and Source.last_checked_at never updates; the operator sees "last check
|
||||
never" in the Subscriptions health column, permanently.
|
||||
|
||||
Reference in New Issue
Block a user