bvandeusen
407de18ff6
Operator-flagged 2026-05-28: tag_and_embed on image 6288 (an mp4) was
marked failed by recover_stalled_task_runs at the 5-min sweep tick
while still legitimately running. The error_type='RecoverySweep' /
"no completion signal received within 5 min" message was misleading
— the worker was busy, not stuck.
Root cause is two interacting limits, both undersized for video work:
tag_and_embed: soft_time_limit=300, time_limit=420
(sized for the image branch, ≈2 GPU ops)
recovery sweep: STUCK_THRESHOLD_MINUTES = 5 across all queues
The video branch samples 10 frames via ffmpeg, then runs tagger +
embedder on EACH frame — ~20 GPU ops vs 2 for an image. A loaded
ml-worker can take 5-10 min on a long video, which trips both
limits well before the task naturally finishes.
**Two-part fix**
1. `tag_and_embed` time limits bumped to soft=900 (15 min) / time=1200
(20 min). Sized for the video path's worst case; image runs return
in seconds and don't care.
2. New `QUEUE_STUCK_THRESHOLD_MINUTES` override dict in maintenance.py.
Queues with legitimately-long-running tasks (currently just `ml` at
25 min — 5-min buffer past the new hard kill) get their own
threshold; queues not in the dict use the default 5 min. The sweep
now issues one UPDATE per distinct threshold value, with
`queue.notin_(override_queues)` on the default pass so each row is
touched at most once.
Tests:
- _make_task_run helper accepts `queue=` (defaults to "default") so
existing tests use the default-threshold path.
- New test `test_recover_stalled_task_runs_ml_queue_uses_longer_threshold`
pins both directions: a 10-min-old ml row survives (fresh by 25-min
override), a 30-min-old ml row gets flagged.
After deploy, operator's mp4 ML jobs run to completion without
spurious RecoverySweep failures.
404 lines
13 KiB
Python
404 lines
13 KiB
Python
"""Unit tests for the maintenance tasks. Eager-mode Celery so the task
|
|
function runs synchronously inside the same DB transaction as the test.
|
|
"""
|
|
|
|
from datetime import UTC, datetime, timedelta
|
|
|
|
import pytest
|
|
|
|
from backend.app.celery_app import celery
|
|
from backend.app.models import ImportBatch, ImportTask
|
|
|
|
pytestmark = pytest.mark.integration
|
|
|
|
|
|
@pytest.fixture(autouse=True)
|
|
def eager():
|
|
celery.conf.task_always_eager = True
|
|
yield
|
|
celery.conf.task_always_eager = False
|
|
|
|
|
|
def _make_batch(session) -> int:
|
|
batch = ImportBatch(triggered_by="manual", source_path="/import", scan_mode="quick")
|
|
session.add(batch)
|
|
session.flush()
|
|
return batch.id
|
|
|
|
|
|
def test_recover_interrupted_only_old(db_sync, monkeypatch):
|
|
batch_id = _make_batch(db_sync)
|
|
now = datetime.now(UTC)
|
|
|
|
# "Fresh" must sit comfortably under whatever STUCK_THRESHOLD_MINUTES
|
|
# currently is (5 min as of 2026-05-24, tightened from 30); 30
|
|
# seconds is well below any reasonable threshold. "Stale" stays at
|
|
# 2 hours so the test remains valid if the threshold ever moves
|
|
# back up.
|
|
fresh = ImportTask(
|
|
batch_id=batch_id, source_path="/import/a.jpg", task_type="media",
|
|
status="processing", started_at=now - timedelta(seconds=30),
|
|
)
|
|
stale = ImportTask(
|
|
batch_id=batch_id, source_path="/import/b.jpg", task_type="media",
|
|
status="processing", started_at=now - timedelta(hours=2),
|
|
)
|
|
db_sync.add_all([fresh, stale])
|
|
db_sync.commit()
|
|
|
|
# Isolate the recover task: under eager Celery, the real
|
|
# import_media_file.delay() would run inline against the nonexistent
|
|
# /import/b.jpg and flip the just-requeued row 'queued' -> 'skipped'.
|
|
from backend.app.tasks import import_file
|
|
|
|
dispatched: list[int] = []
|
|
monkeypatch.setattr(
|
|
import_file.import_media_file, "delay", dispatched.append
|
|
)
|
|
|
|
from backend.app.tasks.maintenance import recover_interrupted_tasks
|
|
recovered = recover_interrupted_tasks.apply().get()
|
|
assert recovered == 1
|
|
|
|
db_sync.refresh(fresh)
|
|
db_sync.refresh(stale)
|
|
assert fresh.status == "processing"
|
|
assert stale.status == "queued"
|
|
assert stale.started_at is None
|
|
assert dispatched == [stale.id]
|
|
|
|
|
|
def test_recover_interrupted_sweeps_pending_orphans_to_failed(db_sync, monkeypatch):
|
|
"""A scan that creates ImportTask rows but crashes before the second
|
|
pass (transition to 'queued' + .delay()) leaves rows orphaned at
|
|
status='pending'. The sweep flips them to 'failed' so the operator
|
|
can drain via /api/import/retry-failed without thundering-herding.
|
|
Banked 2026-05-25 after operator hit 5490 stuck pending rows.
|
|
"""
|
|
from backend.app.tasks import import_file
|
|
monkeypatch.setattr(import_file.import_media_file, "delay", lambda *_: None)
|
|
|
|
batch_id = _make_batch(db_sync)
|
|
now = datetime.now(UTC)
|
|
|
|
fresh_pending = ImportTask(
|
|
batch_id=batch_id, source_path="/import/fresh.jpg", task_type="media",
|
|
status="pending",
|
|
)
|
|
db_sync.add(fresh_pending)
|
|
db_sync.flush()
|
|
# created_at defaults to now() server-side; fresh row stays untouched.
|
|
|
|
# Two stale rows simulating the orphan pile: one 'pending', one
|
|
# 'queued' (scanner crashed AFTER transitioning some rows but
|
|
# before all). Both should sweep.
|
|
stale_pending = ImportTask(
|
|
batch_id=batch_id, source_path="/import/stale1.jpg", task_type="media",
|
|
status="pending",
|
|
)
|
|
stale_queued = ImportTask(
|
|
batch_id=batch_id, source_path="/import/stale2.jpg", task_type="media",
|
|
status="queued",
|
|
)
|
|
db_sync.add_all([stale_pending, stale_queued])
|
|
db_sync.flush()
|
|
# Backdate created_at past the orphan cutoff (30 min).
|
|
from sqlalchemy import update as _upd
|
|
db_sync.execute(
|
|
_upd(ImportTask)
|
|
.where(ImportTask.id.in_([stale_pending.id, stale_queued.id]))
|
|
.values(created_at=now - timedelta(hours=2))
|
|
)
|
|
db_sync.commit()
|
|
|
|
from backend.app.tasks.maintenance import recover_interrupted_tasks
|
|
touched = recover_interrupted_tasks.apply().get()
|
|
assert touched == 2
|
|
|
|
db_sync.refresh(fresh_pending)
|
|
db_sync.refresh(stale_pending)
|
|
db_sync.refresh(stale_queued)
|
|
assert fresh_pending.status == "pending" # fresh row untouched
|
|
assert stale_pending.status == "failed"
|
|
assert stale_queued.status == "failed"
|
|
assert "orphan" in (stale_pending.error or "")
|
|
|
|
|
|
def test_recover_interrupted_handles_both_stuck_and_orphans(db_sync, monkeypatch):
|
|
"""One sweep tick handles both 'processing' crashes AND
|
|
'pending'/'queued' orphans in a single pass."""
|
|
from backend.app.tasks import import_file
|
|
dispatched: list[int] = []
|
|
monkeypatch.setattr(
|
|
import_file.import_media_file, "delay", dispatched.append
|
|
)
|
|
|
|
batch_id = _make_batch(db_sync)
|
|
now = datetime.now(UTC)
|
|
|
|
stuck = ImportTask(
|
|
batch_id=batch_id, source_path="/import/stuck.jpg", task_type="media",
|
|
status="processing", started_at=now - timedelta(hours=2),
|
|
)
|
|
orphan = ImportTask(
|
|
batch_id=batch_id, source_path="/import/orphan.jpg", task_type="media",
|
|
status="pending",
|
|
)
|
|
db_sync.add_all([stuck, orphan])
|
|
db_sync.flush()
|
|
from sqlalchemy import update as _upd
|
|
db_sync.execute(
|
|
_upd(ImportTask).where(ImportTask.id == orphan.id)
|
|
.values(created_at=now - timedelta(hours=2))
|
|
)
|
|
db_sync.commit()
|
|
|
|
from backend.app.tasks.maintenance import recover_interrupted_tasks
|
|
touched = recover_interrupted_tasks.apply().get()
|
|
assert touched == 2
|
|
|
|
db_sync.refresh(stuck)
|
|
db_sync.refresh(orphan)
|
|
assert stuck.status == "queued"
|
|
assert orphan.status == "failed"
|
|
assert dispatched == [stuck.id] # stuck rows re-enqueue; orphans don't
|
|
|
|
|
|
def test_cleanup_old_deletes_finished_old(db_sync):
|
|
batch_id = _make_batch(db_sync)
|
|
now = datetime.now(UTC)
|
|
|
|
old_complete = ImportTask(
|
|
batch_id=batch_id, source_path="/import/a.jpg", task_type="media",
|
|
status="complete", finished_at=now - timedelta(days=10),
|
|
)
|
|
recent_complete = ImportTask(
|
|
batch_id=batch_id, source_path="/import/b.jpg", task_type="media",
|
|
status="complete", finished_at=now - timedelta(days=2),
|
|
)
|
|
old_pending = ImportTask(
|
|
batch_id=batch_id, source_path="/import/c.jpg", task_type="media",
|
|
status="pending",
|
|
)
|
|
db_sync.add_all([old_complete, recent_complete, old_pending])
|
|
db_sync.commit()
|
|
|
|
from backend.app.tasks.maintenance import cleanup_old_tasks
|
|
deleted = cleanup_old_tasks.apply().get()
|
|
assert deleted == 1
|
|
|
|
remaining = {t.source_path for t in db_sync.query(ImportTask).all()}
|
|
assert remaining == {"/import/b.jpg", "/import/c.jpg"}
|
|
|
|
|
|
# --- FC-3i: task_run sweep + retention -----------------------------
|
|
|
|
|
|
def _make_task_run(db_sync, *, status, started_at, finished_at=None,
|
|
error_type=None, queue="default"):
|
|
from backend.app.models import TaskRun
|
|
row = TaskRun(
|
|
celery_task_id="x",
|
|
queue=queue,
|
|
task_name="backend.app.tasks.fake.t",
|
|
target_id=1,
|
|
started_at=started_at,
|
|
finished_at=finished_at,
|
|
duration_ms=1000 if finished_at else None,
|
|
status=status,
|
|
error_type=error_type,
|
|
error_message="x" if status in ("error", "timeout") else None,
|
|
)
|
|
db_sync.add(row)
|
|
db_sync.flush()
|
|
return row.id
|
|
|
|
|
|
def test_recover_stalled_task_runs_flips_old_running_to_error(db_sync):
|
|
from sqlalchemy import select
|
|
|
|
from backend.app.models import TaskRun
|
|
from backend.app.tasks.maintenance import recover_stalled_task_runs
|
|
|
|
now = datetime.now(UTC)
|
|
stale_id = _make_task_run(
|
|
db_sync, status="running", started_at=now - timedelta(minutes=10),
|
|
)
|
|
db_sync.commit()
|
|
|
|
recovered = recover_stalled_task_runs.apply().get()
|
|
assert recovered == 1
|
|
|
|
db_sync.expire_all()
|
|
status = db_sync.execute(
|
|
select(TaskRun.status).where(TaskRun.id == stale_id)
|
|
).scalar_one()
|
|
error_type = db_sync.execute(
|
|
select(TaskRun.error_type).where(TaskRun.id == stale_id)
|
|
).scalar_one()
|
|
assert status == "error"
|
|
assert error_type == "RecoverySweep"
|
|
|
|
|
|
def test_recover_stalled_task_runs_skips_fresh_running(db_sync):
|
|
from sqlalchemy import select
|
|
|
|
from backend.app.models import TaskRun
|
|
from backend.app.tasks.maintenance import recover_stalled_task_runs
|
|
|
|
now = datetime.now(UTC)
|
|
fresh_id = _make_task_run(
|
|
db_sync, status="running", started_at=now - timedelta(seconds=30),
|
|
)
|
|
db_sync.commit()
|
|
|
|
recovered = recover_stalled_task_runs.apply().get()
|
|
assert recovered == 0
|
|
|
|
|
|
def test_recover_stalled_task_runs_ml_queue_uses_longer_threshold(db_sync):
|
|
"""ml-queue tasks (tag_and_embed video branch) legitimately run
|
|
past the default 5-min threshold. The sweep must NOT flag an
|
|
ml-queue task that's only been running 10 min — the override
|
|
threshold (25 min via QUEUE_STUCK_THRESHOLD_MINUTES) protects
|
|
in-flight video tagging. Operator-flagged 2026-05-28 after
|
|
image 6288 (mp4) was marked failed at the 5-min tick mid-run."""
|
|
from sqlalchemy import select
|
|
|
|
from backend.app.models import TaskRun
|
|
from backend.app.tasks.maintenance import recover_stalled_task_runs
|
|
|
|
now = datetime.now(UTC)
|
|
# 10-min-old ml-queue row: stale by the default 5-min rule but
|
|
# fresh by the 25-min ml override. Must survive the sweep.
|
|
ml_fresh_id = _make_task_run(
|
|
db_sync, status="running", queue="ml",
|
|
started_at=now - timedelta(minutes=10),
|
|
)
|
|
# 30-min-old ml-queue row: past even the ml override. Must be
|
|
# flagged.
|
|
ml_stale_id = _make_task_run(
|
|
db_sync, status="running", queue="ml",
|
|
started_at=now - timedelta(minutes=30),
|
|
)
|
|
db_sync.commit()
|
|
|
|
recovered = recover_stalled_task_runs.apply().get()
|
|
assert recovered == 1
|
|
|
|
db_sync.expire_all()
|
|
ml_fresh_status = db_sync.execute(
|
|
select(TaskRun.status).where(TaskRun.id == ml_fresh_id)
|
|
).scalar_one()
|
|
ml_stale_status = db_sync.execute(
|
|
select(TaskRun.status).where(TaskRun.id == ml_stale_id)
|
|
).scalar_one()
|
|
assert ml_fresh_status == "running"
|
|
assert ml_stale_status == "error"
|
|
|
|
db_sync.expire_all()
|
|
status = db_sync.execute(
|
|
select(TaskRun.status).where(TaskRun.id == fresh_id)
|
|
).scalar_one()
|
|
assert status == "running"
|
|
|
|
|
|
def test_prune_task_runs_deletes_ok_older_than_24h(db_sync):
|
|
from sqlalchemy import select
|
|
|
|
from backend.app.models import TaskRun
|
|
from backend.app.tasks.maintenance import prune_task_runs
|
|
|
|
now = datetime.now(UTC)
|
|
old_id = _make_task_run(
|
|
db_sync, status="ok",
|
|
started_at=now - timedelta(hours=30),
|
|
finished_at=now - timedelta(hours=29),
|
|
)
|
|
recent_id = _make_task_run(
|
|
db_sync, status="ok",
|
|
started_at=now - timedelta(hours=2),
|
|
finished_at=now - timedelta(hours=1),
|
|
)
|
|
db_sync.commit()
|
|
|
|
result = prune_task_runs.apply().get()
|
|
assert result["ok_deleted"] == 1
|
|
|
|
db_sync.expire_all()
|
|
surviving_ids = set(db_sync.execute(
|
|
select(TaskRun.id).where(TaskRun.id.in_([old_id, recent_id]))
|
|
).scalars().all())
|
|
assert surviving_ids == {recent_id}
|
|
|
|
|
|
def test_prune_task_runs_deletes_failures_older_than_7d(db_sync):
|
|
from sqlalchemy import select
|
|
|
|
from backend.app.models import TaskRun
|
|
from backend.app.tasks.maintenance import prune_task_runs
|
|
|
|
now = datetime.now(UTC)
|
|
old_id = _make_task_run(
|
|
db_sync, status="error", error_type="OldError",
|
|
started_at=now - timedelta(days=10),
|
|
finished_at=now - timedelta(days=9),
|
|
)
|
|
db_sync.commit()
|
|
|
|
result = prune_task_runs.apply().get()
|
|
assert result["failures_deleted"] >= 1
|
|
|
|
db_sync.expire_all()
|
|
surviving = db_sync.execute(
|
|
select(TaskRun.id).where(TaskRun.id == old_id)
|
|
).scalar_one_or_none()
|
|
assert surviving is None
|
|
|
|
|
|
def test_prune_task_runs_keeps_recent_failures(db_sync):
|
|
from sqlalchemy import select
|
|
|
|
from backend.app.models import TaskRun
|
|
from backend.app.tasks.maintenance import prune_task_runs
|
|
|
|
now = datetime.now(UTC)
|
|
recent_id = _make_task_run(
|
|
db_sync, status="error", error_type="RecentError",
|
|
started_at=now - timedelta(days=6),
|
|
finished_at=now - timedelta(days=5),
|
|
)
|
|
db_sync.commit()
|
|
|
|
prune_task_runs.apply().get()
|
|
|
|
db_sync.expire_all()
|
|
surviving = db_sync.execute(
|
|
select(TaskRun.id).where(TaskRun.id == recent_id)
|
|
).scalar_one_or_none()
|
|
assert surviving == recent_id
|
|
|
|
|
|
def test_prune_task_runs_never_deletes_running(db_sync):
|
|
"""Even a 30-day-old running row stays — recovery sweep is the
|
|
mechanism that flips them; prune doesn't touch in-flight."""
|
|
from sqlalchemy import select
|
|
|
|
from backend.app.models import TaskRun
|
|
from backend.app.tasks.maintenance import prune_task_runs
|
|
|
|
now = datetime.now(UTC)
|
|
ancient_id = _make_task_run(
|
|
db_sync, status="running",
|
|
started_at=now - timedelta(days=30),
|
|
)
|
|
db_sync.commit()
|
|
|
|
prune_task_runs.apply().get()
|
|
|
|
db_sync.expire_all()
|
|
surviving = db_sync.execute(
|
|
select(TaskRun.id).where(TaskRun.id == ancient_id)
|
|
).scalar_one_or_none()
|
|
assert surviving == ancient_id
|