Skip to content

Commit b3fb0ad

Browse files
mihowclaude
andcommitted
feat(jobs): reconcile async jobs stuck on NATS-lost images
When NATS exhausts max_deliver=2 (per #1234) for a message whose processing kept failing non-retriably, JetStream stops redelivering but keeps the message in the consumer's num_ack_pending indefinitely. Redis still tracks the image id in pending_images:{process,results}. The job sits at <100% progress until check_stale_jobs REVOKEs it at 10 min, wiping all the legitimately processed work alongside the lost images. Adds mark_lost_images_failed() — a new sub-check wired into jobs_health_check ahead of check_stale_jobs. For each running async_api job whose updated_at is older than STALLED_JOBS_MAX_MINUTES and whose Redis pending sets still hold ids, SREMs those ids from pending, SADDs them to failed_images, and runs _update_job_progress for both stages. The existing completion logic (FAILURE_THRESHOLD = 0.5) then decides SUCCESS vs FAILURE on accurate per-image counts instead of REVOKE-ing the whole job. Design decisions: * Idle-threshold signal is Job.updated_at, not NATS consumer counters. JetStream does not clear num_ack_pending when max_deliver is hit — guarding on num_ack_pending > 0 would block the exact production case this is meant to reconcile. Verified empirically with chaos_monkey exhaust_max_deliver (next commit) against a live NATS JetStream. * get_consumer_state() is still called per candidate, but only to log current counters in the diagnostic appended to progress.errors. The reconcile decision itself does not read them. * Runs BEFORE _run_stale_jobs_check so a reconcilable job lands in its natural completion state instead of being REVOKEd. Tests: * 8 TransactionTestCase cases in TestMarkLostImagesFailed covering the main job-2421 shape, the mixed-failure path, the >50% FAILURE threshold, the idle-threshold guard, and two cases (num_pending > 0, num_ack_pending > 0) that now reconcile because the idle cutoff is the load-bearing signal — previously (in earlier revisions of this branch) those were guarded noops. Co-Authored-By: Claude <noreply@anthropic.com>
1 parent 7abd7bc commit b3fb0ad

3 files changed

Lines changed: 513 additions & 1 deletion

File tree

ami/jobs/tasks.py

Lines changed: 212 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -13,7 +13,7 @@
1313

1414
from ami.main.checks.schemas import IntegrityCheckResult
1515
from ami.ml.orchestration.async_job_state import AsyncJobStateManager
16-
from ami.ml.orchestration.nats_queue import TaskQueueManager
16+
from ami.ml.orchestration.nats_queue import ConsumerState, TaskQueueManager
1717
from ami.ml.schemas import PipelineResultsError, PipelineResultsResponse
1818
from ami.tasks import default_soft_time_limit, default_time_limit
1919
from config import celery_app
@@ -533,6 +533,190 @@ def _update_job_progress(
533533
cleanup_async_job_if_needed(job)
534534

535535

536+
def mark_lost_images_failed(minutes: int | None = None, dry_run: bool = False) -> list[dict]:
537+
"""Reconcile running async_api jobs that have been idle past the cutoff
538+
while Redis still tracks images as pending.
539+
540+
**Decision signals** (all must hold):
541+
542+
1. :attr:`Job.updated_at` older than ``minutes`` — every successful result
543+
save bumps ``updated_at``, so 10+ minutes of silence means no batch has
544+
landed. ADC has stopped processing this job, for any reason.
545+
2. Redis ``job:{id}:pending_images:{process,results}`` still has ids —
546+
there is real work left to reconcile.
547+
3. NATS consumer exists (``get_consumer_state`` returns not-None) — the
548+
job is a live async_api job we own state for.
549+
550+
No NATS-counter-based guards. Empirically, JetStream keeps messages in
551+
``num_ack_pending`` even after ``max_deliver`` is hit and the messages are
552+
dropped from delivery; those counters are not reliable signals of whether
553+
the queue is still making progress. Time-based staleness + "Redis still
554+
has work" are the signals that matter.
555+
556+
**Why this is safe:**
557+
558+
- Late NATS deliveries are idempotent: ``save_results`` dedupes on
559+
``(detection, source_image)``, SREM on already-removed ids is a no-op
560+
with ``newly_removed == 0`` gating counter accumulation (see
561+
``processing-lifecycle.md`` §2), and ``_update_job_progress`` clamps
562+
percentage with ``max()``. A late result arriving post-reconcile saves
563+
its detections and its SREM/SADD is a no-op.
564+
- Runs BEFORE :func:`check_stale_jobs` in :func:`jobs_health_check` so
565+
a job the reconciler can unstick lands in its natural completion state
566+
(SUCCESS or FAILURE via :data:`FAILURE_THRESHOLD`) rather than being
567+
REVOKEd and losing legitimate successful work.
568+
569+
``get_consumer_state`` is still called per candidate, but only so the
570+
current ``num_redelivered`` can be logged in the diagnostic — operators
571+
get a one-glance signal distinguishing "max_deliver exhausted" from
572+
"never delivered" after the fact.
573+
574+
Returns a list of per-job result dicts (``job_id``, ``lost_count``,
575+
``action``) mirroring :func:`check_stale_jobs` for consistency in
576+
operator logs.
577+
"""
578+
from ami.jobs.models import Job, JobDispatchMode, JobState
579+
580+
if minutes is None:
581+
minutes = Job.STALLED_JOBS_MAX_MINUTES
582+
583+
cutoff = datetime.datetime.now() - datetime.timedelta(minutes=minutes)
584+
candidate_pks = list(
585+
Job.objects.filter(
586+
status__in=JobState.running_states(),
587+
dispatch_mode=JobDispatchMode.ASYNC_API,
588+
updated_at__lt=cutoff,
589+
).values_list("pk", flat=True)
590+
)
591+
if not candidate_pks:
592+
return []
593+
594+
async def _fetch_states() -> dict[int, ConsumerState | None]:
595+
states: dict[int, ConsumerState | None] = {}
596+
async with TaskQueueManager() as manager:
597+
for pk in candidate_pks:
598+
try:
599+
states[pk] = await manager.get_consumer_state(pk)
600+
except Exception:
601+
# get_consumer_state already swallows per-consumer errors
602+
# and returns None, but a truly unexpected failure (e.g.
603+
# connection reset mid-loop) should not blow up the whole
604+
# reconciler tick — mark this pk as "skip" and continue.
605+
logger.exception("mark_lost_images_failed: consumer_state failed for job %s", pk)
606+
states[pk] = None
607+
return states
608+
609+
try:
610+
consumer_states = async_to_sync(_fetch_states)()
611+
except Exception:
612+
logger.exception("mark_lost_images_failed: failed to open NATS connection")
613+
return []
614+
615+
results: list[dict] = []
616+
for pk in candidate_pks:
617+
state = consumer_states.get(pk)
618+
if state is None:
619+
# Consumer missing: either cleanup already fired or we have no
620+
# NATS-level record. Either way, reconciling without a consumer
621+
# means we can't verify the state is ours — skip.
622+
continue
623+
624+
state_manager = AsyncJobStateManager(pk)
625+
lost_ids = state_manager.get_pending_image_ids()
626+
if not lost_ids:
627+
continue
628+
629+
if dry_run:
630+
results.append({"job_id": pk, "lost_count": len(lost_ids), "action": "dry-run"})
631+
continue
632+
633+
try:
634+
_reconcile_lost_images(pk, lost_ids, state)
635+
except Exception:
636+
logger.exception("mark_lost_images_failed: failed reconciling job %s", pk)
637+
results.append({"job_id": pk, "lost_count": len(lost_ids), "action": "error"})
638+
continue
639+
640+
results.append({"job_id": pk, "lost_count": len(lost_ids), "action": "marked_failed"})
641+
642+
return results
643+
644+
645+
def _reconcile_lost_images(job_id: int, lost_ids: set[str], consumer_state: ConsumerState) -> None:
646+
"""Mark *lost_ids* as failed in Redis and push progress to 100% in both stages.
647+
648+
Mirrors the SREM+SADD+progress-update sequence that
649+
:func:`process_nats_pipeline_result` runs on every result, so the stage
650+
transitions land in the same shape the rest of the pipeline expects. The
651+
completion decision (SUCCESS vs FAILURE) reuses :data:`FAILURE_THRESHOLD`
652+
so a job losing >50% of its images still falls through to FAILURE.
653+
"""
654+
from ami.jobs.models import Job, JobState
655+
656+
state_manager = AsyncJobStateManager(job_id)
657+
658+
# Stage "process": SREM from pending_images:process and SADD to failed_images.
659+
process_progress = state_manager.update_state(lost_ids, stage="process", failed_image_ids=lost_ids)
660+
# Stage "results": SREM from pending_images:results. failed_image_ids
661+
# already covered by the previous call (SADD is idempotent anyway).
662+
results_progress = state_manager.update_state(lost_ids, stage="results")
663+
664+
if not process_progress or not results_progress:
665+
logger.warning(
666+
"mark_lost_images_failed: job %s state disappeared mid-reconcile; " "leaving it for check_stale_jobs",
667+
job_id,
668+
)
669+
return
670+
671+
complete_state = JobState.SUCCESS
672+
if process_progress.total > 0 and (process_progress.failed / process_progress.total) > FAILURE_THRESHOLD:
673+
complete_state = JobState.FAILURE
674+
675+
_update_job_progress(
676+
job_id,
677+
"process",
678+
process_progress.percentage,
679+
complete_state=complete_state,
680+
processed=process_progress.processed,
681+
remaining=process_progress.remaining,
682+
failed=process_progress.failed,
683+
)
684+
# Results-stage counters are accumulated inside _update_job_progress, so
685+
# passing zeros here preserves whatever save_results already counted on
686+
# the non-lost branch. We do NOT have detections/classifications for the
687+
# lost images — by definition we never got their results.
688+
_update_job_progress(
689+
job_id,
690+
"results",
691+
results_progress.percentage,
692+
complete_state=complete_state,
693+
detections=0,
694+
classifications=0,
695+
captures=0,
696+
)
697+
698+
diagnostic = (
699+
f"jobs_health_check: marked {len(lost_ids)} image(s) as failed "
700+
f"(job idle past cutoff; NATS consumer "
701+
f"num_pending={consumer_state.num_pending} "
702+
f"num_ack_pending={consumer_state.num_ack_pending} "
703+
f"num_redelivered={consumer_state.num_redelivered}). "
704+
f"IDs: {sorted(lost_ids)}"
705+
)
706+
707+
# Append the diagnostic to ``progress.errors`` so the reason is visible in
708+
# the UI alongside the now-accurate ``failed`` count. ``select_for_update``
709+
# mirrors :func:`_fail_job` — the row may still be touched concurrently by
710+
# a late ``process_nats_pipeline_result`` retry.
711+
with transaction.atomic():
712+
job = Job.objects.select_for_update().get(pk=job_id)
713+
if diagnostic not in job.progress.errors:
714+
job.progress.errors.append(diagnostic)
715+
job.save(update_fields=["progress"])
716+
717+
job.logger.warning(diagnostic)
718+
719+
536720
def check_stale_jobs(minutes: int | None = None, dry_run: bool = False) -> list[dict]:
537721
"""
538722
Find jobs stuck in a running state past the cutoff and revoke them.
@@ -665,11 +849,33 @@ class JobsHealthCheckResult:
665849
Add a new field here when adding a sub-check to the umbrella.
666850
"""
667851

852+
lost_images: IntegrityCheckResult
668853
stale_jobs: IntegrityCheckResult
669854
running_job_snapshots: IntegrityCheckResult
670855
zombie_streams: IntegrityCheckResult
671856

672857

858+
def _run_mark_lost_images_failed_check() -> IntegrityCheckResult:
859+
"""Mark NATS-lost pending images as failed so their jobs can finalize.
860+
861+
Runs BEFORE ``_run_stale_jobs_check`` in :func:`jobs_health_check` — a job
862+
the reconciler can unstick should land in its natural completion state
863+
rather than being REVOKED. Jobs the reconciler can't help (e.g. consumer
864+
missing, num_redelivered=0, no pending ids) fall through to
865+
``check_stale_jobs`` unchanged.
866+
"""
867+
results = mark_lost_images_failed()
868+
fixed = sum(1 for r in results if r["action"] == "marked_failed")
869+
unfixable = sum(1 for r in results if r["action"] == "error")
870+
logger.info(
871+
"lost_images check: %d candidate(s), %d marked failed, %d error(s)",
872+
len(results),
873+
fixed,
874+
unfixable,
875+
)
876+
return IntegrityCheckResult(checked=len(results), fixed=fixed, unfixable=unfixable)
877+
878+
673879
def _run_stale_jobs_check() -> IntegrityCheckResult:
674880
"""Reconcile jobs stuck in running states past Job.STALLED_JOBS_MAX_MINUTES."""
675881
results = check_stale_jobs()
@@ -884,7 +1090,12 @@ def jobs_health_check() -> dict:
8841090
:class:`JobsHealthCheckResult` so celery's default JSON backend can store
8851091
it; add new sub-checks by extending that dataclass and calling them here.
8861092
"""
1093+
# Order matters: the ``lost_images`` reconciler runs BEFORE ``stale_jobs``
1094+
# so that jobs whose only remaining problem is NATS-dropped pending ids
1095+
# land in SUCCESS/FAILURE via _update_job_progress rather than REVOKE.
1096+
# Jobs the reconciler can't help still fall through to check_stale_jobs.
8871097
result = JobsHealthCheckResult(
1098+
lost_images=_safe_run_sub_check("lost_images", _run_mark_lost_images_failed_check),
8881099
stale_jobs=_safe_run_sub_check("stale_jobs", _run_stale_jobs_check),
8891100
running_job_snapshots=_safe_run_sub_check("running_job_snapshots", _run_running_job_snapshot_check),
8901101
zombie_streams=_safe_run_sub_check("zombie_streams", _run_zombie_streams_check),

ami/jobs/tests/test_periodic_beat_tasks.py

Lines changed: 6 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -41,6 +41,10 @@ def _stub_manager(self, mock_manager_cls) -> AsyncMock:
4141
instance.populate_redelivered_counts = AsyncMock(return_value=None)
4242
instance.delete_consumer = AsyncMock(return_value=True)
4343
instance.delete_stream = AsyncMock(return_value=True)
44+
# Lost-images sub-check default: no consumer state available (e.g. no
45+
# async_api stale jobs). Individual tests override when exercising the
46+
# reconciler path.
47+
instance.get_consumer_state = AsyncMock(return_value=None)
4448
return instance
4549

4650
def test_reports_both_sub_check_results(self, mock_manager_cls, _mock_cleanup):
@@ -53,6 +57,7 @@ def test_reports_both_sub_check_results(self, mock_manager_cls, _mock_cleanup):
5357
self.assertEqual(
5458
result,
5559
{
60+
"lost_images": _empty_check_dict(),
5661
"stale_jobs": {"checked": 2, "fixed": 2, "unfixable": 0},
5762
"running_job_snapshots": _empty_check_dict(),
5863
"zombie_streams": _empty_check_dict(),
@@ -67,6 +72,7 @@ def test_idle_deployment_returns_all_zeros(self, mock_manager_cls, _mock_cleanup
6772
self.assertEqual(
6873
jobs_health_check(),
6974
{
75+
"lost_images": _empty_check_dict(),
7076
"stale_jobs": _empty_check_dict(),
7177
"running_job_snapshots": _empty_check_dict(),
7278
"zombie_streams": _empty_check_dict(),

0 commit comments

Comments
 (0)