Finalise grade syncs left stuck in_progress

docs/grade-sync-completion-race.md

@@ -0,0 +1,121 @@
+# Grade sync can stick in `in_progress` forever
+
+A `GradingSync` can be left permanently in `in_progress`, which then blocks **every** further
+grade sync for that assignment. Recovery currently requires a human with an SSM session.
+
+Observed once in production on 2026-08-16 (CA region, assignment 9253) — one stuck row against
+150 `finished` and 52 `failed`, so it is rare but not theoretical. Operational recovery is in
+the playbook: `docs/support-howtos/unblocking-a-stuck-grade-sync.md`.
+
+## Impact
+
+`create_grading_sync` refuses to start a new sync while a non-terminal one exists
+(`lms/views/dashboard/api/grading.py:52`, `lms/services/auto_grading.py:18` matching
+`["scheduled", "in_progress"]`):
+
+```python
+if self.auto_grading_service.get_in_progress_sync(assignment):
+    self.request.response.status_int = 400
+    return {"message": "There's already an auto-grade sync in progress"}
+```
+
+So a stuck row is not cosmetic. The instructor sees the sync hang, and every retry returns
+`400`. There is no timeout, no reaper and no UI affordance to clear it — the assignment's grade
+sync is dead until someone intervenes manually.
+
+## Root cause: the completion task can observe a pre-commit snapshot
+
+`sync_grade` runs entirely inside `with request.tm:` (`lms/tasks/grading.py:41`), so its write
+to `grading_sync_grade.success` is not visible to other transactions until that block exits.
+
+But the completion task is scheduled **inside** that same transaction, with a one-second
+countdown (`lms/tasks/grading.py:67` and `:74`, via `_schedule_sync_grades_complete` at `:108`):
+
+```python
+grading_sync_grade.success = False
+grading_sync_grade.error_details = {"exception": str(err)}
+_schedule_sync_grades_complete(grading_sync.id, countdown=1)   # sent to broker immediately
+LOG.exception("Syncing grade back to LMS failed")
+return
+```
+
+`apply_async` reaches the broker straight away, not on commit. If the transaction takes longer
+than the countdown to commit, `sync_grades_complete` runs against a snapshot where that grade
+is still `success IS NULL`, its `~exists(... success.is_(None))` check
+(`lms/tasks/grading.py:90`) evaluates to "not complete", it sets nothing
+(`:105`), and it exits **successfully**. Nothing ever re-checks.
+
+This is a transactional-outbox problem: a delayed message enqueued inside a transaction, with a
+delay shorter than the commit latency.
+
+### Production timeline
+
+```
+21:59:39,468  GradingSync 203 created (12 grades)
+21:59:39,821 → 21:59:41,112   11 completion tasks run and correctly do nothing
+                              (grade 12 still in flight)
+
+              grade 12 → 403 Forbidden from brightspace.brocku.ca
+21:59:50,153  sync_grade retry: "Retry in 11s"
+22:00:01,587  final failure → success=False set in session,
+                _schedule_sync_grades_complete(countdown=1)
+22:00:02,575  sync_grades_complete SUCCEEDED           ← ran here
+22:00:02,944  sync_grade SUCCEEDED — success=False COMMITS here
+              (nothing runs again; row stays in_progress)
+```
+
+**The finaliser completed 369 ms before the commit it needed to see.**
+
+### Why it is rare
+
+On the happy path a whole sync commits in ~1.2 s and the one-second countdown is comfortably
+enough. The race needs a grade that fails *after* exhausting its retries: `max_retries=2` with
+`retry_backoff=10` (`lms/tasks/grading.py:33-36`) adds ~11 s, which pushes the scheduling call
+to just before a comparatively slow commit. That is why it took 203 syncs to surface — and why
+it will keep surfacing whenever an institution's LMS starts rejecting grade posts.
+
+## Contributing factors
+
+**`sync_grades_complete` has no retry policy.** It is a bare `@app.task()`
+(`lms/tasks/grading.py:77`), unlike `sync_grade` which has `autoretry_for=(Exception,)`. Any
+transient failure in the finaliser is terminal, and produces the same stuck state by a
+different route.
+
+**Nothing reconciles stale rows.** The design assumes the last completing grade always
+successfully triggers a finaliser that sees a complete picture. There is no fallback if that
+single trigger is lost, mistimed, or errors.
+
+## Fixes
+
+**3 is implemented** — `sweep_stale_grading_syncs` in `lms/tasks/grading.py`, scheduled every
+15 minutes from `h-periodic` (`h_periodic/lms_beat.py`). 1 and 2 remain worthwhile follow-ups:
+the reaper guarantees *recovery*, it does not reduce how often the race fires.
+
+In increasing order of robustness — 3 is the one that actually closes the hole.
+
+1. **Schedule after commit.** Register the `apply_async` on the transaction's commit hook
+   rather than calling it inline, so the message is only sent once the write is durable.
+   Removes this specific race, but still assumes the message is never lost.
+
+2. **Make the finaliser self-healing.** Give `sync_grades_complete` a retry policy, and have it
+   re-schedule itself when it finds the sync incomplete but recently updated. Converts "lost
+   trigger" into "delayed trigger".
+
+3. **Add a periodic reaper.** A scheduled task that finalises `scheduled` / `in_progress` syncs
+   older than N minutes, using the same completion logic. This fixes the race, the missing
+   retry policy, and any future lost task in one move — and it is the difference between a
+   system that self-heals and one that needs an engineer with production access.
+
+Note that `GradingSync` carries a partial unique index — `ix__grading_sync_assignment_status_unique`
+on `assignment_id` where `status IN ('scheduled', 'in_progress')` — so at most one non-terminal
+sync per assignment is possible, and `get_in_progress_sync`'s `.one_or_none()` is safe. It also
+means a stuck row blocks at two layers: the view returns 400, and the database would reject a
+second row anyway.
+
+## Reproducing
+
+Make `sync_grade`'s final failure path commit slowly — e.g. hold the transaction open past the
+countdown — while a completion task is already in flight. The sync will be left in
+`in_progress` with every `grading_sync_grade.success` populated, which is the signature to
+assert on: **all grades terminal, parent non-terminal**. That invariant violation is also a
+cheap thing to alert on in production.

lms/tasks/grading.py

@@ -1,14 +1,22 @@
 import logging
-from datetime import UTC
+from datetime import UTC, datetime, timedelta
 
-from sqlalchemy import exists, select
+from sqlalchemy import exists, select, update
 
 from lms.models import GradingSync, GradingSyncGrade
 from lms.services.lti_grading.factory import service_factory
 from lms.tasks.celery import app
 
 LOG = logging.getLogger(__name__)
 
+STALE_GRADING_SYNC_TIMEOUT = timedelta(minutes=15)
+"""How long a GradingSync may stay non-terminal before we finalise it ourselves.
+
+A sync normally completes in about a second. The worst legitimate case is a grade
+exhausting its retries, which `max_retries=2` and `retry_backoff=10` bound to well
+under a minute. Fifteen minutes is a wide margin over that.
+"""
+
 
 @app.task()
 def sync_grades():
@@ -105,6 +113,69 @@ def sync_grades_complete(*, grading_sync_id):
                 grading_sync.status = "failed" if is_failed else "finished"
 
 
+@app.task()
+def sweep_stale_grading_syncs():
+    """Finalise GradingSyncs that have been left in a non-terminal state.
+
+    A GradingSync only reaches `finished`/`failed` when a `sync_grades_complete`
+    task observes every one of its grades as complete. That relies on a single
+    delayed message arriving *after* the last grade commits. If it is lost, or
+    fires before the commit it needed to see, nothing ever re-checks and the sync
+    stays `in_progress` forever.
+
+    That matters because a non-terminal sync blocks all further grade syncing for
+    its assignment - `create_grading_sync` rejects new syncs with a 400, and a
+    partial unique index enforces the same rule in the database. So one lost
+    message takes out grade syncing for that assignment permanently, until a human
+    intervenes.
+
+    This task closes that hole: anything left non-terminal past
+    STALE_GRADING_SYNC_TIMEOUT gets finalised. Grades still incomplete by then are
+    marked failed - their task is not coming back - so the sync can reach a
+    terminal state and the assignment is usable again.
+    """
+    cutoff = datetime.now(UTC).replace(tzinfo=None) - STALE_GRADING_SYNC_TIMEOUT
+
+    with app.request_context() as request:  # noqa: SIM117
+        with request.tm:
+            stale_ids = list(
+                request.db.scalars(
+                    select(GradingSync.id).where(
+                        GradingSync.status.in_(["scheduled", "in_progress"]),
+                        GradingSync.updated < cutoff,
+                    )
+                )
+            )
+
+            for grading_sync_id in stale_ids:
+                abandoned = request.db.execute(
+                    update(GradingSyncGrade)
+                    .where(
+                        GradingSyncGrade.grading_sync_id == grading_sync_id,
+                        GradingSyncGrade.success.is_(None),
+                    )
+                    .values(
+                        success=False,
+                        error_details={
+                            "exception": "Timed out: the grade sync task never completed"
+                        },
+                    )
+                ).rowcount
+
+                LOG.warning(
+                    "Finalising stale GradingSync %s (%s grades never completed)",
+                    grading_sync_id,
+                    abandoned,
+                )
+
+    # Dispatch only after the transaction above has committed. Scheduling work
+    # from inside a transaction is precisely the bug this task exists to clean up
+    # after: the consumer can otherwise run against a snapshot that predates the
+    # commit it needs to see.
+    for grading_sync_id in stale_ids:
+        sync_grades_complete.delay(grading_sync_id=grading_sync_id)
+
+
 def _schedule_sync_grades_complete(grading_sync_id: int, countdown: int):
     sync_grades_complete.apply_async(
         (), {"grading_sync_id": grading_sync_id}, countdown=countdown

tests/unit/lms/tasks/grading_test.py

@@ -1,10 +1,17 @@
 from contextlib import contextmanager
-from datetime import UTC
+from datetime import UTC, datetime, timedelta
 from unittest.mock import call
 
 import pytest
-
-from lms.tasks.grading import sync_grade, sync_grades, sync_grades_complete
+from sqlalchemy import update
+
+from lms.models import GradingSync
+from lms.tasks.grading import (
+    sweep_stale_grading_syncs,
+    sync_grade,
+    sync_grades,
+    sync_grades_complete,
+)
 from tests import factories
 
 
@@ -84,19 +91,102 @@ def test_sync_grade_last_retry(
     @pytest.mark.parametrize(
         "success_values,status",
         [
-            ((None, None), "in_progress"),
-            ((None, False), "in_progress"),
-            ((None, True), "in_progress"),
+            # Not every grade has completed, so the status is left alone.
+            ((None, None), "scheduled"),
+            ((None, False), "scheduled"),
+            ((None, True), "scheduled"),
+            # All grades complete: failed if any failed, otherwise finished.
             ((True, True), "finished"),
             ((False, True), "failed"),
         ],
     )
-    def test_syn_grades_complete(self, grading_sync, success_values, status):
+    def test_sync_grades_complete(self, grading_sync, success_values, status):
         grading_sync.grades[0].success, grading_sync.grades[1].success = success_values
 
         sync_grades_complete(grading_sync_id=grading_sync.id)
 
+        assert grading_sync.status == status
+
+    def test_sweep_stale_grading_syncs(
+        self, db_session, grading_sync, sync_grades_complete
+    ):
+        """A sync whose grades all completed, but which never got finalised.
+
+        This is the production failure: `sync_grades_complete` ran against a
+        snapshot taken before the last grade committed, saw work outstanding, and
+        exited without setting a terminal status. Nothing re-checks, so the sync -
+        and therefore grade syncing for the whole assignment - is stuck forever.
+        """
+        grading_sync.status = "in_progress"
+        grading_sync.grades[0].success = True
+        grading_sync.grades[1].success = False
+        self.set_updated(db_session, grading_sync, minutes_ago=60)
+
+        sweep_stale_grading_syncs()
+
+        sync_grades_complete.delay.assert_called_once_with(
+            grading_sync_id=grading_sync.id
+        )
+
+    def test_sweep_stale_grading_syncs_fails_abandoned_grades(
+        self, db_session, grading_sync, sync_grades_complete
+    ):
+        """A grade whose task was lost never completes, so we mark it failed.
+
+        Without this the sync could never reach a terminal state and the
+        assignment would stay blocked.
+        """
+        grading_sync.status = "in_progress"
+        grading_sync.grades[0].success = True
+        grading_sync.grades[1].success = None
+        self.set_updated(db_session, grading_sync, minutes_ago=60)
+
+        sweep_stale_grading_syncs()
+        db_session.expire_all()
+
+        assert grading_sync.grades[0].success is True, "completed grades are untouched"
+        assert grading_sync.grades[1].success is False
+        assert "Timed out" in grading_sync.grades[1].error_details["exception"]
+        sync_grades_complete.delay.assert_called_once_with(
+            grading_sync_id=grading_sync.id
+        )
+
+    def test_sweep_stale_grading_syncs_ignores_recent_ones(
+        self, db_session, grading_sync, sync_grades_complete
+    ):
+        """A sync still within the timeout may legitimately be retrying."""
+        grading_sync.status = "in_progress"
+        self.set_updated(db_session, grading_sync, minutes_ago=1)
+
+        sweep_stale_grading_syncs()
+        db_session.expire_all()
+
+        sync_grades_complete.delay.assert_not_called()
+        assert grading_sync.grades[0].success is None, "grades are not touched"
+
+    @pytest.mark.parametrize("status", ["finished", "failed"])
+    def test_sweep_stale_grading_syncs_ignores_terminal_ones(
+        self, db_session, grading_sync, sync_grades_complete, status
+    ):
         grading_sync.status = status
+        self.set_updated(db_session, grading_sync, minutes_ago=60)
+
+        sweep_stale_grading_syncs()
+
+        sync_grades_complete.delay.assert_not_called()
+
+    @staticmethod
+    def set_updated(db_session, grading_sync, minutes_ago):
+        """Backdate `updated`, bypassing the column's onupdate default."""
+        db_session.flush()
+        db_session.execute(
+            update(GradingSync)
+            .where(GradingSync.id == grading_sync.id)
+            .values(
+                updated=datetime.now(UTC).replace(tzinfo=None)
+                - timedelta(minutes=minutes_ago)
+            )
+        )
 
     @pytest.fixture
     def assignment(self, lti_v13_application_instance):