Selaa lähdekoodia

fix(backup): commit each database category so SQLite's writer is not held (#2656)

The database phase had the same shape the K-profile phase did: _find_
archive, _find_spool, the usage dedupe and _restore_settings are all one
SELECT per row or per key, interleaved with autoflushed INSERTs, inside a
single open write transaction. A few thousand archives plus a full usage
history plausibly passes the 15 s busy_timeout, and every concurrent
writer in the app fails with "database is locked" until it finishes.

Each category now commits before the next starts. The id maps are plain
dicts in memory and the session is expire_on_commit=False, so the
ordering tolerates it.

The cost is that a later failure no longer rolls back an earlier
category, so a tally is recorded only after its category commits and
run_restore reports the categories already on disk instead of an empty
result - the same correction the K-profile split needed.
jmoore-skild 1 kuukausi sitten
vanhempi
sitoutus
fc2dcf76b5
2 muutettua tiedostoa jossa 149 lisäystä ja 27 poistoa
  1. 60 17
      backend/app/services/github_restore.py
  2. 89 10
      backend/tests/unit/test_github_restore.py

+ 60 - 17
backend/app/services/github_restore.py

@@ -740,13 +740,20 @@ class GitHubRestoreService:
                 await db.refresh(log)
                 await db.refresh(log)
                 log_id = log.id
                 log_id = log.id
 
 
+                # Owned here rather than by _apply so the failure path can see
+                # the categories that were already committed when the raise
+                # happened. _apply records a tally only after its category's
+                # commit, so every entry present is on disk.
+                results: dict[str, _CategoryTally] = {}
                 try:
                 try:
                     payload, error = await self._read_categories(config, resolved, categories)
                     payload, error = await self._read_categories(config, resolved, categories)
                     if error:
                     if error:
                         raise RuntimeError(error)
                         raise RuntimeError(error)
 
 
                     settings_keys_written: set[str] = set()
                     settings_keys_written: set[str] = set()
-                    results = await self._apply(db, payload, categories, overwrite_existing, settings_keys_written)
+                    await self._apply(
+                        db, payload, categories, overwrite_existing, settings_keys_written, results=results
+                    )
                     await db.commit()
                     await db.commit()
 
 
                     # After the commit: this reconnects the relay, which is not
                     # After the commit: this reconnects the relay, which is not
@@ -775,17 +782,26 @@ class GitHubRestoreService:
                     }
                     }
 
 
                 except Exception as e:
                 except Exception as e:
-                    # Rolls back whatever is still uncommitted. That is every
-                    # database category unless K-profiles were also selected, in
-                    # which case _apply has already committed them before talking
-                    # to the printers — see the comment there.
+                    # Rolls back the category that was mid-flight. Every category
+                    # already in ``results`` committed as it finished (see
+                    # _apply), so those rows survive this — and reporting an
+                    # empty result over them would tell the user nothing was
+                    # restored while their archives and spools are on disk.
                     logger.exception("Restore failed for config %s ref %s", config_id, resolved)
                     logger.exception("Restore failed for config %s ref %s", config_id, resolved)
                     await db.rollback()
                     await db.rollback()
+                    committed = sum(tally.restored for tally in results.values())
                     log.status = "failed"
                     log.status = "failed"
                     log.completed_at = datetime.now(timezone.utc)
                     log.completed_at = datetime.now(timezone.utc)
+                    log.files_changed = committed
                     log.error_message = str(e)[:1000]
                     log.error_message = str(e)[:1000]
                     await db.commit()
                     await db.commit()
-                    return {"success": False, "message": str(e), "log_id": log_id, "ref": resolved, "results": {}}
+                    return {
+                        "success": False,
+                        "message": str(e),
+                        "log_id": log_id,
+                        "ref": resolved,
+                        "results": {name: tally.as_dict() for name, tally in results.items()},
+                    }
 
 
         finally:
         finally:
             self._running_restore = False
             self._running_restore = False
@@ -836,21 +852,49 @@ class GitHubRestoreService:
         categories: list[RestoreCategory],
         categories: list[RestoreCategory],
         overwrite: bool,
         overwrite: bool,
         settings_keys_written: set[str] | None = None,
         settings_keys_written: set[str] | None = None,
+        results: dict[str, _CategoryTally] | None = None,
     ) -> dict[str, _CategoryTally]:
     ) -> dict[str, _CategoryTally]:
         """Apply categories in dependency order and return per-category tallies.
         """Apply categories in dependency order and return per-category tallies.
 
 
         ``settings_keys_written``, if given, collects the setting keys actually
         ``settings_keys_written``, if given, collects the setting keys actually
         written, for the caller's post-commit side effects (see
         written, for the caller's post-commit side effects (see
         ``_reconfigure_mqtt_relay``).
         ``_reconfigure_mqtt_relay``).
+
+        ``results``, if given, is the caller's own dict rather than a fresh one.
+        Each category is committed before it is recorded there, so on a raise
+        the caller can report exactly what is already on disk — see the
+        per-category commit below.
         """
         """
-        results: dict[str, _CategoryTally] = {}
+        results = {} if results is None else results
         archive_id_map: dict[int, int] = {}
         archive_id_map: dict[int, int] = {}
 
 
+        # Every database category commits before the next one starts, and only
+        # then is its tally recorded. Two reasons:
+        #
+        #  * SQLite has one writer. Each category is a long run of one SELECT per
+        #    row or per key — _find_archive, _find_spool, the usage dedupe,
+        #    _restore_settings — interleaved with autoflushed INSERTs, all inside
+        #    the open write transaction. A few thousand archives plus a full
+        #    usage history plausibly passes the 15 s busy_timeout
+        #    (core/database.py), at which point every concurrent writer in the
+        #    app fails with "database is locked". This is the same hold the
+        #    K-profile phase had, arriving by volume rather than by awaiting a
+        #    sulking printer.
+        #  * The ordering tolerates it: the only cross-category state is
+        #    archive_id_map and spool_id_map, both plain dicts in memory, and
+        #    the session is expire_on_commit=False so nothing reloads.
+        #
+        # The cost is that a later failure no longer rolls back an earlier
+        # category — which is why the tally is recorded after the commit, so
+        # run_restore's failure path reports the rows that really landed instead
+        # of claiming nothing was restored.
+
         # Archives first: spool usage history references archive_id.
         # Archives first: spool usage history references archive_id.
         if RestoreCategory.ARCHIVES in categories:
         if RestoreCategory.ARCHIVES in categories:
             self._progress = "Restoring print archives..."
             self._progress = "Restoring print archives..."
             tally = _CategoryTally()
             tally = _CategoryTally()
             await self._restore_archives(db, payload.get(ARCHIVES_PATH), overwrite, tally, archive_id_map)
             await self._restore_archives(db, payload.get(ARCHIVES_PATH), overwrite, tally, archive_id_map)
+            await db.commit()
             results[RestoreCategory.ARCHIVES.value] = tally
             results[RestoreCategory.ARCHIVES.value] = tally
 
 
         if RestoreCategory.SPOOLS in categories:
         if RestoreCategory.SPOOLS in categories:
@@ -864,6 +908,7 @@ class GitHubRestoreService:
                 tally,
                 tally,
                 archive_id_map,
                 archive_id_map,
             )
             )
+            await db.commit()
             results[RestoreCategory.SPOOLS.value] = tally
             results[RestoreCategory.SPOOLS.value] = tally
 
 
         if RestoreCategory.SETTINGS in categories:
         if RestoreCategory.SETTINGS in categories:
@@ -872,26 +917,24 @@ class GitHubRestoreService:
             await self._restore_settings(
             await self._restore_settings(
                 db, payload.get(SETTINGS_PATH), overwrite, tally, keys_written=settings_keys_written
                 db, payload.get(SETTINGS_PATH), overwrite, tally, keys_written=settings_keys_written
             )
             )
+            await db.commit()
             results[RestoreCategory.SETTINGS.value] = tally
             results[RestoreCategory.SETTINGS.value] = tally
 
 
         # Last, because it leaves the database and publishes over MQTT.
         # Last, because it leaves the database and publishes over MQTT.
         if RestoreCategory.KPROFILES in categories:
         if RestoreCategory.KPROFILES in categories:
-            # Commit the database categories FIRST, and not just for tidiness.
-            # Everything above has already autoflushed its INSERTs, so SQLite is
-            # holding the single write transaction — and _restore_kprofiles then
-            # awaits get_kprofiles per printer per nozzle, which is
-            # timeout=5.0 * max_retries=3, i.e. up to ~15 s each against an
-            # unresponsive printer. busy_timeout is 15 s (core/database.py), so a
-            # farm with a couple of sulking printers would hold the writer past
-            # it and every concurrent writer in the app would fail with
-            # "database is locked".
+            # The database categories are already committed by the loop above,
+            # and that is load-bearing here rather than tidiness:
+            # _restore_kprofiles awaits get_kprofiles per printer per nozzle,
+            # which is timeout=5.0 * max_retries=3, i.e. up to ~15 s each against
+            # an unresponsive printer. Holding SQLite's writer across that would
+            # pass the 15 s busy_timeout on a farm with a couple of sulking
+            # printers.
             #
             #
             # The cost is that a K-profile failure no longer rolls back the
             # The cost is that a K-profile failure no longer rolls back the
             # categories that already succeeded. That is the correct trade
             # categories that already succeeded. That is the correct trade
             # anyway: extrusion_cali_set has left for the printer by then and
             # anyway: extrusion_cali_set has left for the printer by then and
             # cannot be rolled back either, so a rollback would only have made
             # cannot be rolled back either, so a rollback would only have made
             # the database disagree with the hardware.
             # the database disagree with the hardware.
-            await db.commit()
 
 
             self._progress = "Sending K-profiles to printers..."
             self._progress = "Sending K-profiles to printers..."
             tally = _CategoryTally()
             tally = _CategoryTally()

+ 89 - 10
backend/tests/unit/test_github_restore.py

@@ -2802,7 +2802,14 @@ class TestMqttRelayReconfigure:
 
 
 
 
 class TestApplyOrdering:
 class TestApplyOrdering:
-    """_apply must not hold SQLite's write transaction across the MQTT phase."""
+    """_apply must not hold SQLite's single writer any longer than one category.
+
+    Two ways to overrun the 15 s busy_timeout, and the same fix closes both: the
+    K-profile phase awaits an unresponsive printer (3 x 5 s per printer/nozzle),
+    and a database category is one SELECT per row or per key against a few
+    thousand archives plus a full usage history. Every concurrent writer in the
+    app fails with "database is locked" while either runs.
+    """
 
 
     def _recording_service(self, calls: list[str]):
     def _recording_service(self, calls: list[str]):
         service = _service()
         service = _service()
@@ -2816,8 +2823,7 @@ class TestApplyOrdering:
         return service
         return service
 
 
     @pytest.mark.asyncio
     @pytest.mark.asyncio
-    async def test_commits_database_categories_before_talking_to_printers(self):
-        """get_kprofiles is 3 x 5 s per printer/nozzle; busy_timeout is 15 s."""
+    async def test_every_database_category_commits_before_the_next_one_starts(self):
         calls: list[str] = []
         calls: list[str] = []
         service = self._recording_service(calls)
         service = self._recording_service(calls)
         db = MagicMock()
         db = MagicMock()
@@ -2826,24 +2832,60 @@ class TestApplyOrdering:
         await service._apply(
         await service._apply(
             db,
             db,
             {},
             {},
-            [RestoreCategory.ARCHIVES, RestoreCategory.SPOOLS, RestoreCategory.KPROFILES],
+            [RestoreCategory.ARCHIVES, RestoreCategory.SPOOLS, RestoreCategory.SETTINGS],
             False,
             False,
         )
         )
 
 
-        assert calls == ["archives", "spools", "commit", "kprofiles"]
+        assert calls == ["archives", "commit", "spools", "commit", "settings", "commit"]
 
 
     @pytest.mark.asyncio
     @pytest.mark.asyncio
-    async def test_does_not_split_the_transaction_without_kprofiles(self):
-        """A database-only restore stays one transaction, committed by run_restore."""
+    async def test_the_printer_phase_runs_with_no_write_transaction_open(self):
+        """The K-profile phase is last, and everything before it is already committed."""
         calls: list[str] = []
         calls: list[str] = []
         service = self._recording_service(calls)
         service = self._recording_service(calls)
         db = MagicMock()
         db = MagicMock()
         db.commit = AsyncMock(side_effect=lambda: calls.append("commit"))
         db.commit = AsyncMock(side_effect=lambda: calls.append("commit"))
 
 
-        await service._apply(db, {}, [RestoreCategory.ARCHIVES, RestoreCategory.SETTINGS], False)
+        await service._apply(
+            db,
+            {},
+            [RestoreCategory.ARCHIVES, RestoreCategory.SPOOLS, RestoreCategory.KPROFILES],
+            False,
+        )
+
+        assert calls == ["archives", "commit", "spools", "commit", "kprofiles"]
+
+    @pytest.mark.asyncio
+    async def test_a_tally_is_recorded_only_after_its_category_commits(self):
+        """What run_restore's failure path relies on to report honestly.
+
+        A tally present in ``results`` has to mean "these rows are on disk". If
+        the commit raises, the category must not appear — otherwise a failed
+        restore reports rows that rolled back.
+        """
+        service = self._recording_service([])
+        db = MagicMock()
+        db.commit = AsyncMock(side_effect=RuntimeError("database is locked"))
+        results: dict = {}
+
+        with pytest.raises(RuntimeError):
+            await service._apply(db, {}, [RestoreCategory.ARCHIVES], False, results=results)
+
+        assert results == {}
 
 
-        assert calls == ["archives", "settings"]
-        assert db.commit.await_count == 0
+    @pytest.mark.asyncio
+    async def test_the_callers_results_dict_is_populated_in_place(self):
+        """So a raise mid-run still leaves the committed categories visible."""
+        service = self._recording_service([])
+        db = MagicMock()
+        db.commit = AsyncMock()
+        service._restore_spools = AsyncMock(side_effect=RuntimeError("boom"))
+        results: dict = {}
+
+        with pytest.raises(RuntimeError):
+            await service._apply(db, {}, [RestoreCategory.ARCHIVES, RestoreCategory.SPOOLS], False, results=results)
+
+        assert set(results) == {"archives"}, "archives committed before spools ran; the caller must see it"
 
 
 
 
 class TestKprofilePhaseFailure:
 class TestKprofilePhaseFailure:
@@ -2956,6 +2998,43 @@ class TestKprofilePhaseFailure:
         assert (await db_session.execute(select(Settings))).scalars().first() is None
         assert (await db_session.execute(select(Settings))).scalars().first() is None
         relay.configure.assert_not_awaited()
         relay.configure.assert_not_awaited()
 
 
+    @pytest.mark.asyncio
+    async def test_a_later_category_failing_still_reports_the_earlier_one(self, db_session):
+        """The database phase commits per category, so this is now reachable there too.
+
+        Archives land and are committed; settings then raises. Reporting an empty
+        result would be the same false "nothing was restored" the K-profile split
+        already had to fix, over rows that are durable on disk.
+        """
+        service, config_id = await self._configured_service(
+            db_session,
+            {
+                ARCHIVES_PATH: {
+                    "version": "1.0",
+                    "archives": [
+                        {
+                            "id": 1,
+                            "filename": "benchy.3mf",
+                            "content_hash": "hash-later",
+                            "started_at": "2026-03-01 10:00:00",
+                        }
+                    ],
+                },
+                SETTINGS_PATH: dict(self._SETTINGS),
+            },
+        )
+        service._restore_settings = AsyncMock(side_effect=RuntimeError("read failed"))
+
+        with self._session_patch(db_session):
+            result = await service.run_restore(
+                config_id, "a" * 40, [RestoreCategory.ARCHIVES, RestoreCategory.SETTINGS]
+            )
+
+        assert result["success"] is False
+        assert result["results"][RestoreCategory.ARCHIVES.value]["restored"] == 1
+        assert RestoreCategory.SETTINGS.value not in result["results"], "settings rolled back; do not claim it"
+        assert (await db_session.execute(select(PrintArchive))).scalars().first() is not None
+
     @pytest.mark.asyncio
     @pytest.mark.asyncio
     async def test_a_malformed_profiles_value_is_a_skipped_category_not_a_raise(self, db_session, printer_factory):
     async def test_a_malformed_profiles_value_is_a_skipped_category_not_a_raise(self, db_session, printer_factory):
         """Belt-and-braces: the pre-loop count ran ahead of the per-call guards.
         """Belt-and-braces: the pre-loop count ran ahead of the per-call guards.