From 8f4369d80fda2a1a1005412d5f656306a60737f8 Mon Sep 17 00:00:00 2001 From: Doug Blank Date: Thu, 13 Aug 2026 11:39:22 -0700 Subject: [PATCH 01/13] GrampsWebApiDb: repair a mirror the history feed can't explain Three related fixes to how a session copes with a server that isn't answering, or that answers with a history it cannot back up. An unreachable server logged a full traceback at ERROR on every 10 second poll tick for as long as the outage lasted, and spent a blocking round trip (plus webapi_client's own retry sleep) on the GTK main thread each time. It is now reported once per outage -- one line at WARNING, traceback kept at DEBUG -- with the poll interval doubling up to the new POLL_BACKOFF_MAX_SECONDS while it persists and resetting on the first success. The media poll gets the same once-per-outage treatment (no backoff: 300s is already coarse). A server whose tree was populated without gramps-web-api recording any history has nothing for the incremental feed to replay, so syncing it produced a mirror holding only the handful of edits the history does know about, with nothing logged to say so. https://demo.grampsweb.org is exactly this: 4668 people against a history that was empty until someone edited it through the API. load() now compares the mirror's own get_total() against the server's object_counts after each sync (_mirror_is_short_of_the_server(), via _sync_from_server()'s new verify_totals) and routes a shortfall to the existing _full_resync(). Comparing totals rather than watching for an empty feed is what makes the case detectable at all -- one API edit is enough to hand back a transaction, advance the cursor, and make the sync look like it worked. The check runs at load() only, never on the poll; it is skipped while pushes are queued, and a larger local total is left alone rather than overwritten from the export. Neither of those was visible from the UI, so both modules now log to ".grampswebapidb" ("gramps -d .grampswebapidb") with a per-operation DEBUG trace: one line per HTTP request, one per sync page and sync, plus load, push, queue depth, media transfer counts and the totals compared. No object data, payloads or headers -- a busy feed costs a fixed handful of lines, not one per change. Co-Authored-By: Claude Opus 5 --- GrampsWebApiDb/grampswebapidb.py | 332 +++++++++++++++++++- GrampsWebApiDb/tests/test_grampswebapidb.py | 206 +++++++++++- GrampsWebApiDb/tests/test_webapi_client.py | 37 +++ GrampsWebApiDb/webapi_client.py | 89 +++++- 4 files changed, 637 insertions(+), 27 deletions(-) diff --git a/GrampsWebApiDb/grampswebapidb.py b/GrampsWebApiDb/grampswebapidb.py index eae077915..14c13c425 100644 --- a/GrampsWebApiDb/grampswebapidb.py +++ b/GrampsWebApiDb/grampswebapidb.py @@ -107,6 +107,22 @@ the only way to recover completeness when the incremental feed has a blind spot by construction. +An empty-changes marker is not the only shape that blind spot takes: a +server whose tree was populated without gramps-web-api recording any +history at all (a server-side import straight into the database, a +restored dump, a truncated history table) has no history to describe +what it holds -- https://demo.grampsweb.org is exactly that, 4668 people +against a history that was empty until someone edited it through the +API. Replaying such a feed produces a mirror holding only the few edits +the history does know about, with nothing to distinguish that from a +correct sync. load() therefore checks the mirror's own object total +against the server's after each sync (_mirror_is_short_of_the_server(), +via _sync_from_server()'s verify_totals) and routes a shortfall to the +same _full_resync(). Comparing totals rather than watching for an empty +feed is what makes the case detectable: one API edit against such a +server is enough for the feed to hand back a transaction and for the +sync to look like it worked. + Pushes go out without force=1, so the server compares each item's "old" snapshot against its own current data and rejects the whole batch with WebApiPushConflict (see webapi_client.push_transaction()) if anything @@ -261,6 +277,31 @@ below) is a reasonable future improvement, not attempted here. close() cancels the pending timeout so a closed database doesn't keep polling. +A server that stops answering does not interrupt the session: the poll +reports the outage once, backs off towards POLL_BACKOFF_MAX_SECONDS while +it lasts, and picks the mirror up again from the persisted sync cursor on +the first tick that succeeds -- meanwhile local edits go on working +against the mirror and queue for push (see _queue_pending_push()). See +_poll_tick() and _record_poll_failure(). + +Tracing a session +----------------- +Most of what this addon does is invisible from the Gramps UI: a sync that +finds nothing, a push that succeeded, a mirror quietly short of the +server. Both this module and webapi_client.py log to ".grampswebapidb", +so:: + + gramps -d .grampswebapidb + +turns on a DEBUG trace of exactly that (argparser.py's -d hands the name +to logging.getLogger().setLevel()). It is deliberately per-operation +rather than per-object: one line per HTTP request (method, path, status, +round-trip time -- WebApiHandler._open()), one per sync page and one per +sync (changes applied/skipped, cursor, elapsed), plus load, push, queue +depth, media transfer counts, and the local-vs-server totals compared at +load. Nothing logs object data or credentials, and replaying a busy feed +costs a fixed handful of lines rather than one per change. + A second, independent timeout (MEDIA_POLL_INTERVAL_SECONDS, coarser than POLL_INTERVAL_SECONDS) drives _sync_media_files(): downloading media files that exist as Media-object records in the mirror but not on local disk, @@ -324,6 +365,7 @@ import re from copy import deepcopy from tempfile import NamedTemporaryFile +from time import monotonic from urllib.error import HTTPError, URLError from gi.repository import GLib @@ -355,7 +397,7 @@ except ValueError: _trans = glocale.translation _ = _trans.gettext -LOG = logging.getLogger("grampswebapidb") +LOG = logging.getLogger(".grampswebapidb") #: How many transactions to request per page while syncing. SYNC_PAGE_SIZE = 100 @@ -374,6 +416,19 @@ #: tick. MEDIA_POLL_INTERVAL_SECONDS = 300 +#: Ceiling (seconds) on the record poll's backoff while the server is +#: unreachable -- see _poll_tick(). Every consecutive failure doubles the +#: interval from POLL_INTERVAL_SECONDS up to this cap, and the first +#: success resets it. A server that is down (or a laptop that is off the +#: network) stays down for minutes or hours, not seconds, and each futile +#: tick costs a blocking round trip on the GTK main thread -- including +#: webapi_client's own one-shot retry sleep -- so retrying every 10 +#: seconds for the whole outage buys nothing and stutters the UI. The cap +#: is deliberately no larger than MEDIA_POLL_INTERVAL_SECONDS: once the +#: server comes back, the mirror should catch up within a poll or two, +#: not stay stale for an hour. +POLL_BACKOFF_MAX_SECONDS = 300 + #: Cap on the persisted pending-push queue (see _queue_pending_push()). #: A queue this long means the server has been unreachable across a great #: many local edits; keeping every one of them forever would grow the @@ -558,6 +613,14 @@ class WebApiDB(SQLite): #: _reconcile_batch_commit(). _pulling = False + #: Consecutive failed polls, per timer, and the record poll's current + #: interval -- the outage state _poll_tick()/_media_poll_tick() use to + #: log an outage once instead of once per tick, and to back the record + #: poll off while it lasts. Reset by the first successful sync. + _poll_failures = 0 + _media_poll_failures = 0 + _poll_interval = POLL_INTERVAL_SECONDS + def requires_login(self): # Credentials come from GRAMPS_WEB_API_KEY, not a login dialog. return False @@ -567,6 +630,7 @@ def _initialize(self, directory, username, password): self.web_client = WebApiHandler.from_env() except _CONNECTION_ERRORS as err: raise DbConnectionError(_describe_connection_error(err), directory) from err + LOG.debug("client: mirroring %s", self.web_client.url) # Local mirror: reuse SQLite's own _initialize for the on-disk # cache file, then sync from the server on load(). @@ -594,16 +658,25 @@ def load(self, *args, **kwargs): mode = args[2] if mode is None: mode = DBMODE_W + LOG.debug( + "load: %s (mode %s)", args[0] if args else kwargs.get("directory"), mode + ) super().load(*args, **kwargs) self._check_identity() self._check_permissions(writable=(mode == DBMODE_W)) self._check_server_version() try: - self._sync_from_server(progress_callback=callback) + self._sync_from_server(progress_callback=callback, verify_totals=True) except _CONNECTION_ERRORS as err: raise DbConnectionError( _describe_connection_error(err), self._directory ) from err + # Fresh outage state for a freshly opened tree: these are class + # attributes, so an instance reused across a close()/load() would + # otherwise start out backed off from the previous tree's outage. + self._poll_failures = 0 + self._media_poll_failures = 0 + self._poll_interval = POLL_INTERVAL_SECONDS try: self._sync_media_files() except _CONNECTION_ERRORS: @@ -612,6 +685,9 @@ def load(self, *args, **kwargs): # usable, and missing/un-uploaded media files are recovered on # the next successful media poll (or the next load()). LOG.exception("Initial media file sync failed; will retry.") + # Counts as this outage's one loud report, so _media_poll_tick() + # doesn't immediately say the same thing again 300 seconds later. + self._media_poll_failures = 1 self._poll_source_id = GLib.timeout_add_seconds( POLL_INTERVAL_SECONDS, self._poll_tick ) @@ -769,23 +845,109 @@ def _poll_tick(self): """GLib.timeout_add_seconds callback -- see the module docstring's polling section. Must return True (GLib.SOURCE_CONTINUE) to keep firing; returning a falsy value cancels the timeout, so a network - error is caught and logged here rather than left to propagate.""" + error is caught and handled here rather than left to propagate. + + An unreachable server is an expected, self-healing condition, not + a bug in this addon: local edits keep working against the mirror + and queue up for the next successful push (_queue_pending_push()), + and the sync cursor is persisted, so the poll only has to survive + the outage. It is therefore reported once per outage rather than + once per tick, and the timer backs off while it lasts (see + _record_poll_failure()) -- a 10-second traceback loop for as long + as a server stays down buries anything else in the log and makes a + routine outage look like a crash.""" try: self._sync_from_server() - except _CONNECTION_ERRORS: - LOG.exception("Periodic sync from server failed; will retry.") - return GLib.SOURCE_CONTINUE + except _CONNECTION_ERRORS as err: + return self._record_poll_failure(err) + if self._poll_failures: + LOG.info( + "Sync from server succeeded again after %d failed attempt(s).", + self._poll_failures, + ) + self._poll_failures = 0 + return self._reschedule_poll(POLL_INTERVAL_SECONDS) + + def _record_poll_failure(self, err): + """Handle a failed _poll_tick() sync: report it (once per outage, + with the detail kept at DEBUG for whoever is diagnosing one) and + slow the timer down, doubling up to POLL_BACKOFF_MAX_SECONDS. + + Returns what _poll_tick() must return: GLib.SOURCE_REMOVE if the + interval changed (_reschedule_poll() has already installed the + replacement timeout), GLib.SOURCE_CONTINUE otherwise.""" + self._poll_failures += 1 + interval = min(self._poll_interval * 2, POLL_BACKOFF_MAX_SECONDS) + if self._poll_failures == 1: + LOG.warning( + "Periodic sync from server failed (%s); retrying, backing off " + "to at most every %d seconds until the server answers again.", + err, + POLL_BACKOFF_MAX_SECONDS, + ) + LOG.debug("Periodic sync failure detail", exc_info=True) + else: + LOG.debug( + "Periodic sync from server still failing after %d attempts (%s); " + "next retry in %d seconds.", + self._poll_failures, + err, + interval, + exc_info=True, + ) + return self._reschedule_poll(interval) + + def _reschedule_poll(self, interval): + """Point the record poll at a new interval, GLib.timeout_add_ + seconds() having no way to retime an existing source: a fresh + timeout is installed and the caller (always _poll_tick(), the + running callback) reports GLib.SOURCE_REMOVE so the old one is + dropped rather than left firing alongside it. A no-op -- and so + plain GLib.SOURCE_CONTINUE -- when the interval is unchanged, + which is the common case on both a healthy poll and a failing one + already sitting at POLL_BACKOFF_MAX_SECONDS.""" + if interval == self._poll_interval: + return GLib.SOURCE_CONTINUE + self._poll_interval = interval + self._poll_source_id = GLib.timeout_add_seconds(interval, self._poll_tick) + return GLib.SOURCE_REMOVE def _media_poll_tick(self): """GLib.timeout_add_seconds callback for the slower media-file scan -- same contract as _poll_tick() (must return True to keep - firing; a connection error is caught and logged here rather than + firing; a connection error is caught and reported here rather than left to propagate), just for _sync_media_files() instead of the - record-history poll.""" + record-history poll. + + Reported once per outage for the same reason as _poll_tick(), but + with no backoff to go with it: MEDIA_POLL_INTERVAL_SECONDS is + already as coarse as that poll's backoff cap.""" try: self._sync_media_files() - except _CONNECTION_ERRORS: - LOG.exception("Periodic media file sync failed; will retry.") + except _CONNECTION_ERRORS as err: + if self._media_poll_failures == 0: + LOG.warning( + "Periodic media file sync failed (%s); will retry every " + "%d seconds.", + err, + MEDIA_POLL_INTERVAL_SECONDS, + ) + LOG.debug("Periodic media file sync failure detail", exc_info=True) + else: + LOG.debug( + "Periodic media file sync still failing after %d attempts (%s).", + self._media_poll_failures + 1, + err, + exc_info=True, + ) + self._media_poll_failures += 1 + return GLib.SOURCE_CONTINUE + if self._media_poll_failures: + LOG.info( + "Media file sync succeeded again after %d failed attempt(s).", + self._media_poll_failures, + ) + self._media_poll_failures = 0 return GLib.SOURCE_CONTINUE def transaction_begin(self, transaction): @@ -848,10 +1010,18 @@ def _push_payload(self, payload, undo=False, is_retry=False): """ if not payload: return + started = monotonic() + background = self._use_background_push(payload) + LOG.debug( + "push: %d change(s) (%s)%s%s", + len(payload), + ", ".join(sorted({entry["type"] for entry in payload})), + " undo" if undo else "", + " background" if background else "", + ) try: - self.web_client.push_transaction( - payload, undo=undo, background=self._use_background_push(payload) - ) + self.web_client.push_transaction(payload, undo=undo, background=background) + LOG.debug("push: accepted in %.2fs", monotonic() - started) except WebApiPushConflict: LOG.warning( "Server rejected %d local change(s): the object(s) changed " @@ -988,6 +1158,7 @@ def _flush_pending_pushes(self): ) pending.pop(0) self._set_metadata("pending_pushes", pending) + LOG.debug("queue: %d push(es) still pending after the flush", len(pending)) def _retry_after_conflict(self, payload): """Reapply each locally-intended change on top of the mirror @@ -1112,7 +1283,7 @@ def _fill_entry_payloads(self, entries): ) return filled - def _sync_from_server(self, progress_callback=None): + def _sync_from_server(self, progress_callback=None, verify_totals=False): """ Pull every transaction after the last-seen timestamp and replay its changes into the local mirror. Returns the number of changes @@ -1125,7 +1296,11 @@ def _sync_from_server(self, progress_callback=None): Flagged rather than silently skipped; _full_resync() is the fallback once the whole page range has been walked (so sync_last_time still advances past it and any *describable* - changes around it are applied normally either way). + changes around it are applied normally either way). A feed that is + empty *altogether*, or too sparse to account for what the server + holds, is the same kind of gap and gets the same fallback -- see + _mirror_is_short_of_the_server(), which ``verify_totals`` asks for + (load() does; the poll doesn't). progress_callback, if given, is called with an int 0-100 after each page -- see load()'s callback param. "total" comes from the @@ -1135,7 +1310,10 @@ def _sync_from_server(self, progress_callback=None): """ self._flush_pending_pushes() after = self._get_metadata("sync_last_time", default=0) + started = monotonic() + LOG.debug("sync: asking for transactions after %s", after) applied = 0 + skipped = 0 needs_full_resync = False page = 1 seen = 0 @@ -1164,21 +1342,114 @@ def _sync_from_server(self, progress_callback=None): net_changes[ (change["obj_class"], change["obj_handle"]) ] = change["trans_type"] + else: + # Reference-type changes and anything else + # with no primary-object class to map -- + # counted rather than logged per change, + # which would be one line per row of the + # feed. + skipped += 1 after = max(after, server_trans["timestamp"]) finally: self._pulling = False self._emit_change_signals(net_changes) seen += len(transactions) + LOG.debug( + "sync: page %d, %d transaction(s) of %s, %d change(s) applied " + "so far, cursor %s", + page, + len(transactions), + total, + applied, + after, + ) if progress_callback is not None and total: progress_callback(min(100, int(seen * 100 / total))) if len(transactions) < SYNC_PAGE_SIZE: break page += 1 self._set_metadata("sync_last_time", after) + LOG.debug( + "sync: %d change(s) applied, %d skipped, from %d transaction(s) " + "in %.2fs; cursor now %s", + applied, + skipped, + seen, + monotonic() - started, + after, + ) + if not needs_full_resync and verify_totals: + needs_full_resync = self._mirror_is_short_of_the_server() if needs_full_resync: self._full_resync(progress_callback=progress_callback) return applied + def _mirror_is_short_of_the_server(self): + """Whether the mirror holds fewer objects than the server says its + tree has, once the incremental sync has had its turn -- the other + way the history feed can fail to describe the server's state, + alongside the empty-"changes" marker _sync_from_server() already + watches for. + + A server can hold a full tree that its history does not account + for: that table only records what gramps-web-api itself wrote, so + anything populated by another route (a server-side import straight + into the database, a restored dump, a truncated history table) has + nothing to replay. https://demo.grampsweb.org is exactly this -- + 4668 people, and GET /transactions/history/ returned X-Total-Count + 0 until someone edited it through the API. Without this check, + syncing such a server is *silently* wrong: load() succeeds, the + feed describes only the handful of edits it does know about, and + the user gets a Family Tree holding those and nothing else, with + nothing in the log to say why. + + Comparing totals rather than asking whether the feed came back + empty is what makes that case detectable at all. An empty feed is + only the extreme of it: one API edit against a history-less server + is enough to hand back a transaction, advance sync_last_time, and + make the sync look like it worked. Both counts cover the same ten + primary types (webapi_client.OBJECT_COUNT_KEYS mirrors Gramps' + own DbGeneric.get_total()), so equality is the invariant this + addon exists to maintain and a mirror that falls short of it is + provably missing data -- _full_resync()'s wholesale XML export + being the same recovery used for the empty-"changes" case, and for + the same reason: the history cannot describe what is already + there. + + Only run where _sync_from_server()'s caller asks for it -- load(), + not the 10-second poll (see POLL_INTERVAL_SECONDS): an outdated + mirror is repaired when the tree is opened, not on a timer, so the + extra GET /metadata/ costs one request per open and a rebuild can + never land in the middle of a working session. + + Skipped outright while pushes are queued (see + _queue_pending_push()): those are local edits the server has not + accepted yet, so the two counts are legitimately out of step, and + rebuilding from the server's export in that state would fight with + work still waiting to go the other way. + + A *larger* local total isn't treated as damage: an extra local + object is either something this mirror is about to push or + something the export would silently destroy, neither of which a + rebuild should decide on its own. Only a shortfall is repaired. + """ + if self._get_metadata("pending_pushes", default=[]): + LOG.debug("Pending pushes queued; skipping the mirror total check.") + return False + local_total = self.get_total() + server_total = self.web_client.get_object_count() + LOG.debug("totals: local mirror %d, server %d", local_total, server_total) + if local_total >= server_total: + return False + LOG.warning( + "Local mirror holds %d objects but the server reports %d; its " + "transaction history cannot account for the difference, so the " + "mirror is being rebuilt from a full export.", + local_total, + server_total, + ) + return True + def _full_resync(self, progress_callback=None): """ Rebuild the local mirror from scratch: download the server's own @@ -1214,7 +1485,13 @@ def _full_resync(self, progress_callback=None): """ if progress_callback is not None: progress_callback(0) + started = monotonic() data = self.web_client.download_export() + LOG.debug( + "resync: downloaded a %.1f MB export in %.2fs", + len(data) / (1024 * 1024), + monotonic() - started, + ) with NamedTemporaryFile(suffix=".gramps", delete=False) as tmp_file: tmp_file.write(data) tmp_path = tmp_file.name @@ -1224,6 +1501,7 @@ def _full_resync(self, progress_callback=None): # across importData() too, not just the explicit DbTxn above it. self._pulling = True try: + cleared = 0 with DbTxn( _("Clear local mirror before full resync"), self, batch=True ) as trans: @@ -1233,7 +1511,15 @@ def _full_resync(self, progress_callback=None): remove = getattr(self, f"remove_{name}") for handle in handles: remove(handle, trans) + cleared += len(handles) + LOG.debug("resync: cleared %d local object(s); reimporting", cleared) + imported_at = monotonic() importData(self, tmp_path, User()) + LOG.debug( + "resync: reimport left %d object(s) (%.2fs)", + self.get_total(), + monotonic() - imported_at, + ) # importData() runs its own batch=True DbTxn internally, so # (like _sync_from_server()'s replay) it emits nothing to # already-open views on its own -- request_rebuild() is the @@ -1266,14 +1552,26 @@ def _sync_media_files(self): Returns ``(downloaded, uploaded)`` file counts. """ + started = monotonic() + missing_local = self._missing_local_media_handles() downloaded = 0 - for handle in self._missing_local_media_handles(): + for handle in missing_local: if self._download_one_media_file(handle): downloaded += 1 + missing_remote = self._missing_remote_media_handles() uploaded = 0 - for handle in self._missing_remote_media_handles(): + for handle in missing_remote: if self._upload_one_media_file(handle): uploaded += 1 + LOG.debug( + "media: %d missing locally (%d downloaded), %d missing on the " + "server (%d uploaded), in %.2fs", + len(missing_local), + downloaded, + len(missing_remote), + uploaded, + monotonic() - started, + ) if downloaded or uploaded: LOG.info( "Media file sync: downloaded %d file(s), uploaded %d file(s).", diff --git a/GrampsWebApiDb/tests/test_grampswebapidb.py b/GrampsWebApiDb/tests/test_grampswebapidb.py index 9f7b40b17..fe71e2b70 100644 --- a/GrampsWebApiDb/tests/test_grampswebapidb.py +++ b/GrampsWebApiDb/tests/test_grampswebapidb.py @@ -576,6 +576,88 @@ def test_marker_still_advances_sync_last_time(self): self.db._sync_from_server() self.assertEqual(self.metadata["sync_last_time"], 42.0) + def test_short_mirror_triggers_full_resync(self): + # A server whose tree was populated without gramps-web-api + # recording history (demo.grampsweb.org: 4668 people, a history + # holding only the edits made through the API) would otherwise + # sync to a mirror holding just those, with nothing logged. + self.db.web_client.get_transaction_history.return_value = ([], 0) + self.db.web_client.get_object_count.return_value = 26541 + with mock.patch.object(self.db, "get_total", return_value=1): + with self.assertLogs(grampswebapidb.LOG, level="WARNING"): + self.db._sync_from_server(verify_totals=True) + self.db._full_resync.assert_called_once_with(progress_callback=None) + + def test_a_replayed_feed_that_still_falls_short_triggers_full_resync(self): + # The case that made the empty-feed-only version of this check + # useless: one API edit against a history-less server hands back a + # transaction and advances the cursor, so the sync looks fine. + change = {"obj_class": "Person", "trans_type": TXNADD, "obj_handle": "H1"} + page = [{"timestamp": 1786645046.3, "changes": [change]}] + self.db.web_client.get_transaction_history.return_value = (page, 1) + self.db.web_client.get_object_count.return_value = 26541 + with mock.patch.object(self.db, "_apply_change", return_value=True): + with mock.patch.object(self.db, "get_total", return_value=1): + with self.assertLogs(grampswebapidb.LOG, level="WARNING"): + applied = self.db._sync_from_server(verify_totals=True) + self.assertEqual(applied, 1) + self.assertEqual(self.metadata["sync_last_time"], 1786645046.3) + self.db._full_resync.assert_called_once_with(progress_callback=None) + + def test_matching_totals_do_not_trigger_full_resync(self): + self.db.web_client.get_transaction_history.return_value = ([], 0) + self.db.web_client.get_object_count.return_value = 26541 + with mock.patch.object(self.db, "get_total", return_value=26541): + self.db._sync_from_server(verify_totals=True) + self.db._full_resync.assert_not_called() + + def test_a_larger_local_total_is_left_alone(self): + # An extra local object is either about to be pushed or something + # the export would destroy -- not a shortfall to repair. + self.db.web_client.get_transaction_history.return_value = ([], 0) + self.db.web_client.get_object_count.return_value = 10 + with mock.patch.object(self.db, "get_total", return_value=11): + self.db._sync_from_server(verify_totals=True) + self.db._full_resync.assert_not_called() + + def test_queued_pushes_suppress_the_total_check(self): + # Local edits the server hasn't accepted yet: the counts are + # legitimately out of step, and a rebuild would fight with work + # still waiting to go the other way. _sync_from_server() drains + # the queue on the way in, so what's left here is what the flush + # couldn't place (a 429, a 5xx) -- hence the stubbed flush. + self.metadata["pending_pushes"] = [{"payload": [], "undo": False}] + self.db.web_client.get_transaction_history.return_value = ([], 0) + with mock.patch.object(self.db, "_flush_pending_pushes"), mock.patch.object( + self.db, "get_total", return_value=0 + ) as get_total: + self.db._sync_from_server(verify_totals=True) + self.db._full_resync.assert_not_called() + get_total.assert_not_called() + self.db.web_client.get_object_count.assert_not_called() + + def test_poll_syncs_do_not_check_totals(self): + # Only load() asks for the check -- a rebuild must never land in + # the middle of a working session, and the poll shouldn't spend a + # request per tick to find that out. + self.db.web_client.get_transaction_history.return_value = ([], 0) + with mock.patch.object(self.db, "get_total", return_value=0) as get_total: + self.db._sync_from_server() + self.db._full_resync.assert_not_called() + get_total.assert_not_called() + self.db.web_client.get_object_count.assert_not_called() + + def test_total_check_forwards_the_progress_callback(self): + callback = mock.MagicMock() + self.db.web_client.get_transaction_history.return_value = ([], 0) + self.db.web_client.get_object_count.return_value = 1 + with mock.patch.object(self.db, "get_total", return_value=0): + with self.assertLogs(grampswebapidb.LOG, level="WARNING"): + self.db._sync_from_server( + progress_callback=callback, verify_totals=True + ) + self.db._full_resync.assert_called_once_with(progress_callback=callback) + # ------------------------------------------------------------------------- # @@ -588,6 +670,9 @@ def setUp(self): self.db.web_client = mock.MagicMock() self.db.web_client.download_export.return_value = b"fake gramps xml bytes" self.db.emit = mock.MagicMock() # see TestSyncFromServer.setUp's note + # _full_resync() reports the rebuilt total at DEBUG; there's no + # real dbapi connection behind these stubs to count. + self.db.get_total = mock.MagicMock(return_value=0) self.patcher = mock.patch.object(grampswebapidb, "DbTxn", FakeDbTxn) self.patcher.start() self.addCleanup(self.patcher.stop) @@ -1556,7 +1641,7 @@ def test_load_syncs_and_schedules_polling(self): self.db.load("some/path") super_load.assert_called_once_with("some/path") check_identity.assert_called_once_with() - sync.assert_called_once_with(progress_callback=None) + sync.assert_called_once_with(progress_callback=None, verify_totals=True) sync_media.assert_called_once_with() timeout_add.assert_has_calls( [ @@ -1588,7 +1673,7 @@ def test_load_forwards_positional_callback_to_sync(self): grampswebapidb.GLib, "timeout_add_seconds" ): self.db.load("some/path", my_callback, "w") - sync.assert_called_once_with(progress_callback=my_callback) + sync.assert_called_once_with(progress_callback=my_callback, verify_totals=True) def test_load_forwards_keyword_callback_to_sync(self): my_callback = mock.MagicMock() @@ -1604,7 +1689,7 @@ def test_load_forwards_keyword_callback_to_sync(self): grampswebapidb.GLib, "timeout_add_seconds" ): self.db.load("some/path", callback=my_callback) - sync.assert_called_once_with(progress_callback=my_callback) + sync.assert_called_once_with(progress_callback=my_callback, verify_totals=True) def test_load_media_sync_failure_does_not_block_load(self): # Unlike a _sync_from_server() failure (which load() re-raises as @@ -1624,6 +1709,32 @@ def test_load_media_sync_failure_does_not_block_load(self): ): with self.assertLogs(grampswebapidb.LOG, level="ERROR"): self.db.load("some/path") # must not raise + # That traceback is this outage's one loud report -- the media + # poll should stay quiet rather than repeat it 300 seconds later. + self.assertEqual(self.db._media_poll_failures, 1) + + def test_load_resets_poll_backoff_state(self): + # Class-attribute defaults, so an instance reused across a + # close()/load() must not start out backed off from the previous + # tree's outage. + self.db._poll_failures = 4 + self.db._media_poll_failures = 4 + self.db._poll_interval = grampswebapidb.POLL_BACKOFF_MAX_SECONDS + with mock.patch.object(grampswebapidb.SQLite, "load"), mock.patch.object( + self.db, "_check_identity" + ), mock.patch.object(self.db, "_check_permissions"), mock.patch.object( + self.db, "_check_server_version" + ), mock.patch.object( + self.db, "_sync_from_server" + ), mock.patch.object( + self.db, "_sync_media_files" + ), mock.patch.object( + grampswebapidb.GLib, "timeout_add_seconds" + ): + self.db.load("some/path") + self.assertEqual(self.db._poll_failures, 0) + self.assertEqual(self.db._media_poll_failures, 0) + self.assertEqual(self.db._poll_interval, grampswebapidb.POLL_INTERVAL_SECONDS) def test_close_cancels_pending_poll(self): self.db._poll_source_id = 42 @@ -1657,13 +1768,73 @@ def test_poll_tick_syncs_and_keeps_repeating(self): sync.assert_called_once_with() self.assertEqual(result, grampswebapidb.GLib.SOURCE_CONTINUE) - def test_poll_tick_swallows_connection_errors_and_keeps_repeating(self): + def test_poll_tick_swallows_connection_errors_and_keeps_polling(self): + # The failing tick reschedules itself at a longer interval, so it + # reports SOURCE_REMOVE for the *old* source while the replacement + # keeps the poll alive. + self.db._poll_interval = grampswebapidb.POLL_INTERVAL_SECONDS with mock.patch.object( self.db, "_sync_from_server", side_effect=OSError("network down") - ): - with self.assertLogs(grampswebapidb.LOG, level="ERROR"): + ), mock.patch.object( + grampswebapidb.GLib, "timeout_add_seconds", return_value=99 + ) as timeout_add: + with self.assertLogs(grampswebapidb.LOG, level="WARNING"): result = self.db._poll_tick() + self.assertEqual(result, grampswebapidb.GLib.SOURCE_REMOVE) + timeout_add.assert_called_once_with( + grampswebapidb.POLL_INTERVAL_SECONDS * 2, self.db._poll_tick + ) + self.assertEqual(self.db._poll_source_id, 99) + self.assertEqual( + self.db._poll_interval, grampswebapidb.POLL_INTERVAL_SECONDS * 2 + ) + self.assertEqual(self.db._poll_failures, 1) + + def test_poll_tick_reports_a_lasting_outage_only_once(self): + # A server that stays down must not log a warning (let alone a + # traceback) on every tick for the whole outage. + with mock.patch.object( + self.db, "_sync_from_server", side_effect=OSError("network down") + ), mock.patch.object(grampswebapidb.GLib, "timeout_add_seconds"): + with self.assertLogs(grampswebapidb.LOG, level="DEBUG") as logs: + for _unused in range(5): + self.db._poll_tick() + warnings = [rec for rec in logs.records if rec.levelname == "WARNING"] + self.assertEqual(len(warnings), 1) + self.assertEqual(self.db._poll_failures, 5) + + def test_poll_tick_backs_off_to_the_cap_and_stops_rescheduling(self): + with mock.patch.object( + self.db, "_sync_from_server", side_effect=OSError("network down") + ), mock.patch.object(grampswebapidb.GLib, "timeout_add_seconds") as timeout_add: + with self.assertLogs(grampswebapidb.LOG, level="WARNING"): + for _unused in range(20): + result = self.db._poll_tick() + self.assertEqual( + self.db._poll_interval, grampswebapidb.POLL_BACKOFF_MAX_SECONDS + ) + # Every reschedule doubles the interval, so once the cap is + # reached the timer is left alone rather than churned each tick. self.assertEqual(result, grampswebapidb.GLib.SOURCE_CONTINUE) + intervals = [call.args[0] for call in timeout_add.call_args_list] + self.assertEqual(intervals, sorted(intervals)) + self.assertLessEqual(intervals[-1], grampswebapidb.POLL_BACKOFF_MAX_SECONDS) + + def test_poll_tick_restores_the_normal_interval_after_recovery(self): + self.db._poll_failures = 3 + self.db._poll_interval = grampswebapidb.POLL_BACKOFF_MAX_SECONDS + with mock.patch.object(self.db, "_sync_from_server"), mock.patch.object( + grampswebapidb.GLib, "timeout_add_seconds", return_value=7 + ) as timeout_add: + with self.assertLogs(grampswebapidb.LOG, level="INFO"): + result = self.db._poll_tick() + self.assertEqual(result, grampswebapidb.GLib.SOURCE_REMOVE) + timeout_add.assert_called_once_with( + grampswebapidb.POLL_INTERVAL_SECONDS, self.db._poll_tick + ) + self.assertEqual(self.db._poll_source_id, 7) + self.assertEqual(self.db._poll_interval, grampswebapidb.POLL_INTERVAL_SECONDS) + self.assertEqual(self.db._poll_failures, 0) def test_media_poll_tick_syncs_and_keeps_repeating(self): with mock.patch.object(self.db, "_sync_media_files") as sync_media: @@ -1675,9 +1846,30 @@ def test_media_poll_tick_swallows_connection_errors_and_keeps_repeating(self): with mock.patch.object( self.db, "_sync_media_files", side_effect=OSError("network down") ): - with self.assertLogs(grampswebapidb.LOG, level="ERROR"): + with self.assertLogs(grampswebapidb.LOG, level="WARNING"): + result = self.db._media_poll_tick() + self.assertEqual(result, grampswebapidb.GLib.SOURCE_CONTINUE) + self.assertEqual(self.db._media_poll_failures, 1) + + def test_media_poll_tick_reports_a_lasting_outage_only_once(self): + with mock.patch.object( + self.db, "_sync_media_files", side_effect=OSError("network down") + ): + with self.assertLogs(grampswebapidb.LOG, level="DEBUG") as logs: + for _unused in range(4): + result = self.db._media_poll_tick() + warnings = [rec for rec in logs.records if rec.levelname == "WARNING"] + self.assertEqual(len(warnings), 1) + self.assertEqual(result, grampswebapidb.GLib.SOURCE_CONTINUE) + self.assertEqual(self.db._media_poll_failures, 4) + + def test_media_poll_tick_notes_recovery(self): + self.db._media_poll_failures = 2 + with mock.patch.object(self.db, "_sync_media_files"): + with self.assertLogs(grampswebapidb.LOG, level="INFO"): result = self.db._media_poll_tick() self.assertEqual(result, grampswebapidb.GLib.SOURCE_CONTINUE) + self.assertEqual(self.db._media_poll_failures, 0) # ------------------------------------------------------------------------- diff --git a/GrampsWebApiDb/tests/test_webapi_client.py b/GrampsWebApiDb/tests/test_webapi_client.py index 2f9ce9cc9..0439a8257 100644 --- a/GrampsWebApiDb/tests/test_webapi_client.py +++ b/GrampsWebApiDb/tests/test_webapi_client.py @@ -954,6 +954,43 @@ def test_unknown_version_does_not_claim_background_support(self): with mock.patch.object(webapi_client, "urlopen", fake): self.assertFalse(handler.supports_background_transactions()) + def test_object_count_sums_every_type(self): + handler = self._authed_handler() + counts = {"object_counts": {"people": 4668, "families": 2855, "tags": 13}} + fake = QueuedUrlopen([FakeResponse(counts)]) + with mock.patch.object(webapi_client, "urlopen", fake): + self.assertEqual(handler.get_object_count(), 4668 + 2855 + 13) + + def test_object_count_without_the_section_is_zero(self): + handler = self._authed_handler() + fake = QueuedUrlopen([FakeResponse({"gramps": {"version": "6.0.1"}})]) + with mock.patch.object(webapi_client, "urlopen", fake): + self.assertEqual(handler.get_object_count(), 0) + + def test_object_count_ignores_non_numeric_entries(self): + handler = self._authed_handler() + fake = QueuedUrlopen( + [FakeResponse({"object_counts": {"people": 3, "note": "n/a"}})] + ) + with mock.patch.object(webapi_client, "urlopen", fake): + self.assertEqual(handler.get_object_count(), 3) + + def test_object_count_is_not_served_from_the_metadata_cache(self): + # Live state, unlike the versions get_metadata() caches: two calls + # must produce two requests, and must not poison that cache. + handler = self._authed_handler() + fake = QueuedUrlopen( + [ + FakeResponse({"object_counts": {"people": 1}}), + FakeResponse({"object_counts": {"people": 2}}), + ] + ) + with mock.patch.object(webapi_client, "urlopen", fake): + self.assertEqual(handler.get_object_count(), 1) + self.assertEqual(handler.get_object_count(), 2) + self.assertEqual(len(fake.requests), 2) + self.assertIsNone(handler._metadata) + # ------------------------------------------------------------------------- # diff --git a/GrampsWebApiDb/webapi_client.py b/GrampsWebApiDb/webapi_client.py index f5cbb3223..393e23053 100644 --- a/GrampsWebApiDb/webapi_client.py +++ b/GrampsWebApiDb/webapi_client.py @@ -79,7 +79,7 @@ from urllib.parse import urlencode, urlparse from urllib.request import Request, urlopen -LOG = logging.getLogger("grampswebapidb") +LOG = logging.getLogger(".grampswebapidb") #: Environment variable read by WebApiHandler.from_env(). API_KEY_ENV_VAR = "GRAMPS_WEB_API_KEY" @@ -96,6 +96,24 @@ #: reliably 429s otherwise. RATE_LIMIT_BACKOFF = 1.1 +#: The "object_counts" buckets GET /metadata/ reports that correspond to +#: the ten primary types Gramps' own DbGeneric.get_total() counts -- see +#: get_object_count(). Summed by name rather than over whatever keys the +#: response happens to carry, so a server that grows an extra bucket +#: can't make a perfectly good local mirror look permanently short of it. +OBJECT_COUNT_KEYS = ( + "people", + "families", + "events", + "places", + "repositories", + "sources", + "citations", + "media", + "notes", + "tags", +) + #: Chunk size used when streaming a media file download to disk -- see #: download_media_file(). _DOWNLOAD_CHUNK_SIZE = 1024 * 64 @@ -139,6 +157,14 @@ def _raise_for_push_conflict(exc: HTTPError) -> None: raise exc +def _request_target(req: Request) -> str: + """The path+query of ``req`` for a log line -- scheme and host + dropped as noise (one server per handler), credentials never + involved: they travel in headers, not the URL. See _open().""" + parts = urlparse(req.full_url) + return parts.path + (f"?{parts.query}" if parts.query else "") + + def parse_version(version): """Parse a SemVer-ish string into a ``(major, minor)`` tuple. @@ -307,8 +333,46 @@ def mint_api_key(cls, url: str, username: str, password: str) -> str: return make_api_key(handler._refresh_token, handler.url) def _open(self, req: Request): - """Open ``req`` with this handler's SSL context and timeout.""" - return urlopen(req, context=self._ctx, timeout=TIMEOUT) + """Open ``req`` with this handler's SSL context and timeout. + + Every request this client makes funnels through here, so this is + also where each one is traced at DEBUG: method, path, outcome and + round-trip time, one line apiece. Only the path+query is logged, + never headers -- the bearer token lives in a header, and nothing + this addon sends puts a credential in a URL. The timing stops at + the response headers, before the body is read, which is what makes + it useful for telling a slow server apart from a slow transfer. + """ + started = time.monotonic() + target = _request_target(req) + try: + res = urlopen(req, context=self._ctx, timeout=TIMEOUT) + except HTTPError as exc: + LOG.debug( + "%s %s -> HTTP %s (%.2fs)", + req.get_method(), + target, + exc.code, + time.monotonic() - started, + ) + raise + except (URLError, socket.timeout) as exc: + LOG.debug( + "%s %s -> %s (%.2fs)", + req.get_method(), + target, + exc, + time.monotonic() - started, + ) + raise + LOG.debug( + "%s %s -> %s (%.2fs)", + req.get_method(), + target, + getattr(res, "status", "?"), + time.monotonic() - started, + ) + return res @property def access_token(self) -> str: @@ -441,6 +505,25 @@ def get_metadata(self) -> dict[str, Any]: self._metadata = data return self._metadata + def get_object_count(self) -> int: + """How many primary objects the server's tree currently holds: + GET /metadata/'s "object_counts", summed over OBJECT_COUNT_KEYS. + + Deliberately *not* routed through get_metadata()'s cache. That + cache is for the deployment description -- versions, server + features -- which cannot change while a tree is open; an object + count is live state, and the only reason to ask for it is to + compare it against what a local mirror holds right now (see + grampswebapidb.py's _mirror_is_short_of_the_server()). + """ + data, _headers = self._get_json(f"{self.url}/metadata/") + counts = data.get("object_counts") or {} + return sum( + count + for key, count in counts.items() + if key in OBJECT_COUNT_KEYS and isinstance(count, int) + ) + def get_api_version(self) -> str | None: """gramps-web-api's own version string, e.g. "2.8.1".""" return (self.get_metadata().get("gramps_webapi") or {}).get("version") From a75f6315af7a739739618136830897184a14196c Mon Sep 17 00:00:00 2001 From: Doug Blank Date: Thu, 13 Aug 2026 11:48:34 -0700 Subject: [PATCH 02/13] GrampsWebApiDb: keep the GUI alive while syncing Every network round trip this addon makes runs synchronously on the GTK main thread, so a long one -- the initial catch-up, a full-export rebuild, a first media sync of hundreds of files, a backgrounded push being waited on -- is time the main loop spends inside the addon rather than answering. The window stops redrawing and the window manager offers to force-quit Gramps. _pump_main_loop() hands the loop its turn at the boundaries of each of those: between sync pages and once on the way out (so even a poll that found nothing pumps after its round trip), between media files, across the export download's chunks (new on_chunk hook on download_export() / _get_binary()) and the task-poll loop (new on_wait hook on wait_for_task() / push_transaction()), and either side of the rebuild -- before the wipe and after request_rebuild(), never in between, where a dispatched event would be looking at a half-empty tree. It goes through GLib's default main context rather than Gtk.main_iteration() so the module stays importable without a display: this is a DATABASE plugin, loadable from the CLI, and GTK drives that same context anyway. Pumping re-enters, so both poll timeouts now check a _syncing flag and skip their turn rather than starting a second sync underneath the first. Measured on a full rebuild of the 26540-object demo tree: a 100ms heartbeat timeout went from 0 dispatches during load() to 15, leaving two stalls the pump structurally can't cover -- the export request itself (~6.6s, server-side generation, blocked inside urlopen) and ImportXml (~5.2s, which never calls User.step_progress so there is no hook to drive). Moving the sync off-thread remains the real fix for those; this is the version that doesn't restructure every call path. Co-Authored-By: Claude Opus 5 --- GrampsWebApiDb/grampswebapidb.py | 118 +++++++++++++++++++- GrampsWebApiDb/tests/test_grampswebapidb.py | 86 +++++++++++++- GrampsWebApiDb/tests/test_webapi_client.py | 41 +++++++ GrampsWebApiDb/webapi_client.py | 70 ++++++++++-- 4 files changed, 300 insertions(+), 15 deletions(-) diff --git a/GrampsWebApiDb/grampswebapidb.py b/GrampsWebApiDb/grampswebapidb.py index 14c13c425..aca432002 100644 --- a/GrampsWebApiDb/grampswebapidb.py +++ b/GrampsWebApiDb/grampswebapidb.py @@ -284,6 +284,22 @@ against the mirror and queue for push (see _queue_pending_push()). See _poll_tick() and _record_poll_failure(). +Keeping the GUI alive +--------------------- +All of that network work runs synchronously on the GTK main thread, so +anything long -- the initial catch-up, a full-export rebuild, a first +media sync, a backgrounded push being waited on -- is time the main loop +is not answering. The window stops redrawing and the window manager +offers to force-quit Gramps. _pump_main_loop() gives the loop its turn at +the boundaries of each of those (between sync pages, between media files, +across the export download's chunks and the task-poll loop, either side +of ImportXml), which keeps the window live and Gramps' own progress bar +moving. Doing the work off-thread would be the real fix and remains the +better long-term answer (GrampsWebSync's GLibTaskRunner is the +precedent); this is the version that doesn't restructure every call path. +Pumping re-enters, so the poll timeouts check _syncing and skip a tick +rather than starting a second sync underneath the first. + Tracing a session ----------------- Most of what this addon does is invisible from the Gramps UI: a sync that @@ -489,6 +505,39 @@ _CONNECTION_ERRORS = (ValueError, KeyError, HTTPError, URLError, OSError) +def _pump_main_loop(): + """Dispatch whatever the main loop has pending, without blocking. + + Every network round trip this addon makes runs synchronously on the + GTK main thread (see the module docstring's polling section), so a + long one -- a full-export download, a page-by-page catch-up, a media + transfer, a backgrounded push being waited on -- is time the main + loop spends inside this addon rather than answering. The window + manager reads that as a hung application and offers to force-quit it, + and the window itself stops redrawing (no progress bar movement, no + repaint after an overlapping window moves away). + + Calling this at the boundaries of those operations gives the loop its + turn: pending redraws, the progress bar Gramps is already driving via + load()'s callback, and the window manager's own ping all get handled, + and the application stays live. + + Goes through GLib's default main context rather than Gtk.main_ + iteration() so this module stays importable without a display: it is + a DATABASE plugin, loadable from the CLI, where pulling in gramps.gui + (or Gtk) has no business being a requirement. GTK drives that very + context, so the effect under the GUI is the same. + + The obvious hazard of pumping a main loop mid-operation is + re-entrancy -- our own POLL_INTERVAL_SECONDS timeout coming round + while a sync is in flight. _poll_tick()/_media_poll_tick() check + _syncing for exactly that and skip their turn. + """ + context = GLib.MainContext.default() + while context.pending(): + context.iteration(False) + + def _describe_connection_error(err): """ Turn a _CONNECTION_ERRORS exception into DbConnectionError's message @@ -613,6 +662,11 @@ class WebApiDB(SQLite): #: _reconcile_batch_commit(). _pulling = False + #: Set for the duration of a sync (records or media files), so the + #: timeouts don't start a second one underneath the first when + #: _pump_main_loop() hands the main loop back mid-operation. + _syncing = False + #: Consecutive failed polls, per timer, and the record poll's current #: interval -- the outage state _poll_tick()/_media_poll_tick() use to #: log an outage once instead of once per tick, and to back the record @@ -856,6 +910,11 @@ def _poll_tick(self): _record_poll_failure()) -- a 10-second traceback loop for as long as a server stays down buries anything else in the log and makes a routine outage look like a crash.""" + if self._syncing: + # Reached from inside _pump_main_loop(), part-way through a + # sync this would otherwise start again underneath itself. + LOG.debug("poll: a sync is already running; skipping this tick") + return GLib.SOURCE_CONTINUE try: self._sync_from_server() except _CONNECTION_ERRORS as err: @@ -922,6 +981,9 @@ def _media_poll_tick(self): Reported once per outage for the same reason as _poll_tick(), but with no backoff to go with it: MEDIA_POLL_INTERVAL_SECONDS is already as coarse as that poll's backoff cap.""" + if self._syncing: + LOG.debug("media poll: a sync is already running; skipping this tick") + return GLib.SOURCE_CONTINUE try: self._sync_media_files() except _CONNECTION_ERRORS as err: @@ -1020,7 +1082,9 @@ def _push_payload(self, payload, undo=False, is_retry=False): " background" if background else "", ) try: - self.web_client.push_transaction(payload, undo=undo, background=background) + self.web_client.push_transaction( + payload, undo=undo, background=background, on_wait=_pump_main_loop + ) LOG.debug("push: accepted in %.2fs", monotonic() - started) except WebApiPushConflict: LOG.warning( @@ -1133,6 +1197,7 @@ def _flush_pending_pushes(self): entry["payload"], undo=entry.get("undo", False), background=self._use_background_push(entry["payload"]), + on_wait=_pump_main_loop, ) except WebApiPushConflict: LOG.warning( @@ -1308,6 +1373,15 @@ def _sync_from_server(self, progress_callback=None, verify_totals=False): history()'s docstring), so it stays a stable denominator across pages barring concurrent server-side writes during the sync. """ + self._syncing = True + try: + return self._sync_from_server_inner(progress_callback, verify_totals) + finally: + self._syncing = False + + def _sync_from_server_inner(self, progress_callback, verify_totals): + """_sync_from_server()'s body, minus the _syncing bookkeeping -- + see that method for what this does and why.""" self._flush_pending_pushes() after = self._get_metadata("sync_last_time", default=0) started = monotonic() @@ -1365,9 +1439,19 @@ def _sync_from_server(self, progress_callback=None, verify_totals=False): ) if progress_callback is not None and total: progress_callback(min(100, int(seen * 100 / total))) + # Between pages: a batch DbTxn has just closed and the next + # one hasn't opened, so this is the one point in the replay + # where handing the main loop back is safe. A catch-up of any + # size would otherwise hold it for its whole duration. + _pump_main_loop() if len(transactions) < SYNC_PAGE_SIZE: break page += 1 + # Also once on the way out: the loop above breaks before its own + # pump whenever the feed hands back a short page or nothing at + # all, which is every routine poll -- and each of those still + # cost a blocking round trip to find out. + _pump_main_loop() self._set_metadata("sync_last_time", after) LOG.debug( "sync: %d change(s) applied, %d skipped, from %d transaction(s) " @@ -1486,7 +1570,10 @@ def _full_resync(self, progress_callback=None): if progress_callback is not None: progress_callback(0) started = monotonic() - data = self.web_client.download_export() + # The single longest transfer this addon makes -- streamed rather + # than read in one go so the main loop keeps its turn throughout + # (see _pump_main_loop() and download_export()'s on_chunk). + data = self.web_client.download_export(on_chunk=_pump_main_loop) LOG.debug( "resync: downloaded a %.1f MB export in %.2fs", len(data) / (1024 * 1024), @@ -1495,6 +1582,12 @@ def _full_resync(self, progress_callback=None): with NamedTemporaryFile(suffix=".gramps", delete=False) as tmp_file: tmp_file.write(data) tmp_path = tmp_file.name + # Last chance to let the main loop catch up while the mirror is + # still intact: from here to request_rebuild() the local data is + # being torn down and rebuilt, and anything dispatched in the + # middle of that would be looking at a half-empty tree. See + # _pump_main_loop(). + _pump_main_loop() # Both halves below are pull-side rebuilds, not local edits -- see # _sync_from_server()'s own note on the _pulling flag. ImportXml # opens its own batch DbTxn internally, so this has to stay set @@ -1514,6 +1607,11 @@ def _full_resync(self, progress_callback=None): cleared += len(handles) LOG.debug("resync: cleared %d local object(s); reimporting", cleared) imported_at = monotonic() + # ImportXml exposes no per-step hook to drive (it never calls + # User.step_progress), so this one call is uninterruptible -- + # the longest stall left in a rebuild, and the reason + # off-thread sync remains the real fix. See the module + # docstring's "Keeping the GUI alive". importData(self, tmp_path, User()) LOG.debug( "resync: reimport left %d object(s) (%.2fs)", @@ -1527,6 +1625,9 @@ def _full_resync(self, progress_callback=None): # itself defines for exactly this case (one -rebuild per # object type, telling every view to reload wholesale). self.request_rebuild() + # The mirror is whole again and every view has been told to + # reload, so it's safe to let the loop run once more. + _pump_main_loop() finally: self._pulling = False os.remove(tmp_path) @@ -1552,17 +1653,30 @@ def _sync_media_files(self): Returns ``(downloaded, uploaded)`` file counts. """ + self._syncing = True + try: + return self._sync_media_files_inner() + finally: + self._syncing = False + + def _sync_media_files_inner(self): + """_sync_media_files()'s body, minus the _syncing bookkeeping -- + see that method for what this does and why.""" started = monotonic() missing_local = self._missing_local_media_handles() downloaded = 0 for handle in missing_local: if self._download_one_media_file(handle): downloaded += 1 + # One file is one blocking transfer; a first sync of a tree + # with media runs hundreds of them back to back. + _pump_main_loop() missing_remote = self._missing_remote_media_handles() uploaded = 0 for handle in missing_remote: if self._upload_one_media_file(handle): uploaded += 1 + _pump_main_loop() LOG.debug( "media: %d missing locally (%d downloaded), %d missing on the " "server (%d uploaded), in %.2fs", diff --git a/GrampsWebApiDb/tests/test_grampswebapidb.py b/GrampsWebApiDb/tests/test_grampswebapidb.py index fe71e2b70..fc6f07b6e 100644 --- a/GrampsWebApiDb/tests/test_grampswebapidb.py +++ b/GrampsWebApiDb/tests/test_grampswebapidb.py @@ -328,6 +328,50 @@ def setUp(self): # testing what they always tested. self.db._full_resync = mock.MagicMock() + def test_syncing_flag_is_set_during_the_sync_and_cleared_after(self): + # What stops _pump_main_loop()'s re-entrant timeout ticks from + # starting a second sync underneath this one. + seen = [] + self.db.web_client.get_transaction_history.side_effect = lambda **kwargs: ( + seen.append(self.db._syncing), + ([], 0), + )[1] + self.db._sync_from_server() + self.assertEqual(seen, [True]) + self.assertFalse(self.db._syncing) + + def test_syncing_flag_is_cleared_even_if_the_sync_raises(self): + self.db.web_client.get_transaction_history.side_effect = OSError("down") + with self.assertRaises(OSError): + self.db._sync_from_server() + self.assertFalse(self.db._syncing) + + def test_main_loop_is_pumped_between_pages(self): + # A catch-up of any size would otherwise hold the main loop for + # its whole duration -- long enough for the window manager to + # offer to force-quit Gramps. + full_page = [ + {"timestamp": float(i), "changes": []} + for i in range(grampswebapidb.SYNC_PAGE_SIZE) + ] + short_page = [{"timestamp": 999.0, "changes": []}] + self.db.web_client.get_transaction_history.side_effect = [ + (full_page, len(full_page) + 1), + (short_page, 1), + ] + with mock.patch.object(grampswebapidb, "_pump_main_loop") as pump: + self.db._sync_from_server() + # Once after each page, plus once on the way out. + self.assertEqual(pump.call_count, 3) + + def test_main_loop_is_pumped_even_when_nothing_came_back(self): + # The routine poll: the loop breaks before its own pump, but the + # round trip that found nothing still blocked the main loop. + self.db.web_client.get_transaction_history.return_value = ([], 0) + with mock.patch.object(grampswebapidb, "_pump_main_loop") as pump: + self.db._sync_from_server() + self.assertEqual(pump.call_count, 1) + def test_stops_after_short_page(self): change = {"obj_class": "Person", "trans_type": TXNADD, "obj_handle": "H1"} self.db.web_client.get_transaction_history.return_value = ( @@ -700,7 +744,9 @@ def fake_import_data(database, filename, user): with mock.patch.object(grampswebapidb, "importData", fake_import_data): self.db._full_resync() - self.db.web_client.download_export.assert_called_once_with() + self.db.web_client.download_export.assert_called_once_with( + on_chunk=grampswebapidb._pump_main_loop + ) for key, name in grampswebapidb.KEY_TO_NAME_MAP.items(): if key not in grampswebapidb.CLASS_TO_KEY_MAP.values(): continue @@ -1768,6 +1814,22 @@ def test_poll_tick_syncs_and_keeps_repeating(self): sync.assert_called_once_with() self.assertEqual(result, grampswebapidb.GLib.SOURCE_CONTINUE) + def test_poll_tick_does_not_start_a_sync_underneath_a_running_one(self): + # _pump_main_loop() hands the main loop back part-way through a + # sync, which is when this timeout can fire re-entrantly. + self.db._syncing = True + with mock.patch.object(self.db, "_sync_from_server") as sync: + result = self.db._poll_tick() + sync.assert_not_called() + self.assertEqual(result, grampswebapidb.GLib.SOURCE_CONTINUE) + + def test_media_poll_tick_does_not_start_a_sync_underneath_a_running_one(self): + self.db._syncing = True + with mock.patch.object(self.db, "_sync_media_files") as sync_media: + result = self.db._media_poll_tick() + sync_media.assert_not_called() + self.assertEqual(result, grampswebapidb.GLib.SOURCE_CONTINUE) + def test_poll_tick_swallows_connection_errors_and_keeps_polling(self): # The failing tick reschedules itself at a longer interval, so it # reports SOURCE_REMOVE for the *old* source while the replacement @@ -2070,6 +2132,28 @@ def test_downloads_missing_local_then_uploads_missing_remote(self): upload.assert_called_once_with("H3") self.assertEqual(result, (2, 1)) + def test_main_loop_is_pumped_per_file_and_syncing_flag_is_managed(self): + # Each transfer is its own blocking round trip, and a first sync + # of a tree with media runs hundreds back to back. + seen = [] + with mock.patch.object( + self.db, "_missing_local_media_handles", return_value=["H1", "H2"] + ), mock.patch.object( + self.db, "_missing_remote_media_handles", return_value=["H3"] + ), mock.patch.object( + self.db, + "_download_one_media_file", + side_effect=lambda handle: seen.append(self.db._syncing) or True, + ), mock.patch.object( + self.db, "_upload_one_media_file", return_value=True + ), mock.patch.object( + grampswebapidb, "_pump_main_loop" + ) as pump: + self.db._sync_media_files() + self.assertEqual(pump.call_count, 3) + self.assertEqual(seen, [True, True]) + self.assertFalse(self.db._syncing) + def test_counts_only_successful_transfers(self): with mock.patch.object( self.db, "_missing_local_media_handles", return_value=["H1", "H2"] diff --git a/GrampsWebApiDb/tests/test_webapi_client.py b/GrampsWebApiDb/tests/test_webapi_client.py index 0439a8257..eb1b7c013 100644 --- a/GrampsWebApiDb/tests/test_webapi_client.py +++ b/GrampsWebApiDb/tests/test_webapi_client.py @@ -619,6 +619,27 @@ def test_request_url_and_returns_raw_bytes(self): fake.requests[0].full_url, "https://example.com/api/exporters/gramps/file" ) + def test_on_chunk_streams_the_body_and_fires_between_chunks(self): + # A multi-megabyte export read in one go is one uninterruptible + # call -- long enough for the window manager to decide Gramps has + # stopped responding. See grampswebapidb._pump_main_loop(). + handler = self._authed_handler() + body = b"x" * (webapi_client._DOWNLOAD_CHUNK_SIZE * 2 + 17) + fake = QueuedUrlopen([FakeChunkedResponse(body)]) + calls = [] + with mock.patch.object(webapi_client, "urlopen", fake): + data = handler.download_export(on_chunk=lambda: calls.append(1)) + self.assertEqual(data, body) + self.assertEqual(len(calls), 3) + + def test_without_on_chunk_the_body_is_read_in_one_go(self): + # FakeBinaryResponse.read() takes no size argument, so this also + # pins that the unchunked path stays a plain read(). + handler = self._authed_handler() + fake = QueuedUrlopen([FakeBinaryResponse(b"gzip-bytes-here")]) + with mock.patch.object(webapi_client, "urlopen", fake): + self.assertEqual(handler.download_export(), b"gzip-bytes-here") + def test_extension_is_configurable(self): handler = self._authed_handler() fake = QueuedUrlopen([FakeBinaryResponse(b"gedcom-bytes")]) @@ -1030,6 +1051,26 @@ def test_polls_until_the_task_leaves_pending(self): handler.wait_for_task("T1") self.assertEqual(len(fake.requests), 3) + def test_on_wait_fires_once_per_poll(self): + # TASK_TIMEOUT allows ten minutes of this loop; a caller on the + # GUI thread has to be able to keep its main loop alive across it. + handler = self._authed_handler() + fake = QueuedUrlopen( + [ + FakeResponse({"state": "PENDING"}), + FakeResponse({"state": "STARTED"}), + FakeResponse({"state": "SUCCESS"}), + ] + ) + calls = [] + with mock.patch.object(webapi_client, "urlopen", fake), mock.patch.object( + webapi_client, "sleep" + ): + handler.wait_for_task("T1", on_wait=lambda: calls.append(1)) + # Once before each of the two sleeps; the SUCCESS poll returns + # without waiting again. + self.assertEqual(len(calls), 2) + def test_conflict_in_a_failed_task_raises_push_conflict(self): # The whole point: a conflict must look the same whether it came # back as a synchronous 400 or as a failed background task. diff --git a/GrampsWebApiDb/webapi_client.py b/GrampsWebApiDb/webapi_client.py index 393e23053..aa714339d 100644 --- a/GrampsWebApiDb/webapi_client.py +++ b/GrampsWebApiDb/webapi_client.py @@ -580,10 +580,19 @@ def _get_json(self, url: str, retry: bool = True) -> tuple[Any, dict]: return self._get_json(url, retry=False) raise - def _get_binary(self, url: str, retry: bool = True) -> bytes: + def _get_binary(self, url: str, retry: bool = True, on_chunk=None) -> bytes: """GET ``url`` with the bearer token and return the raw response body, unlike _get_json() -- for endpoints that return a file - rather than a JSON document (see download_export()).""" + rather than a JSON document (see download_export()). + + ``on_chunk``, if given, is called with no arguments after each + _DOWNLOAD_CHUNK_SIZE bytes arrive, and switches the read from one + blocking res.read() to a chunked loop. It exists for callers on a + GUI thread: a multi-megabyte export is one uninterruptible read + otherwise, long enough for the window manager to decide the + application has stopped responding (see grampswebapidb.py's + _pump_main_loop()). + """ req = Request( url, headers={ @@ -593,23 +602,32 @@ def _get_binary(self, url: str, retry: bool = True) -> bytes: ) try: with self._open(req) as res: - return res.read() + if on_chunk is None: + return res.read() + chunks = [] + while True: + chunk = res.read(_DOWNLOAD_CHUNK_SIZE) + if not chunk: + break + chunks.append(chunk) + on_chunk() + return b"".join(chunks) except HTTPError as exc: if exc.code == 401 and retry: sleep(RATE_LIMIT_BACKOFF) self._authenticate() - return self._get_binary(url, retry=False) + return self._get_binary(url, retry=False, on_chunk=on_chunk) if exc.code == 429 and retry: sleep(RATE_LIMIT_BACKOFF) - return self._get_binary(url, retry=False) + return self._get_binary(url, retry=False, on_chunk=on_chunk) raise except (URLError, socket.timeout): if retry: sleep(1) - return self._get_binary(url, retry=False) + return self._get_binary(url, retry=False, on_chunk=on_chunk) raise - def download_export(self, extension: str = "gramps") -> bytes: + def download_export(self, extension: str = "gramps", on_chunk=None) -> bytes: """ Download a full backup export of the tree from the server -- by default a gzip-compressed Gramps XML file, the exact on-disk @@ -620,9 +638,14 @@ def download_export(self, extension: str = "gramps") -> bytes: rebuild the local mirror wholesale when the transaction-history feed can't describe what changed -- see that method's own doc comment on why. + + ``on_chunk`` is passed through to _get_binary(): a hook called as + the bytes arrive, so a caller on the GUI thread can keep its main + loop alive across what is easily the longest single transfer this + client makes. """ url = f"{self.url}/exporters/{extension}/file" - return self._get_binary(url) + return self._get_binary(url, on_chunk=on_chunk) def get_missing_files(self) -> list[dict[str, Any]]: """ @@ -759,9 +782,17 @@ def wait_for_task( task_id: str, timeout: float = TASK_TIMEOUT, poll_interval: float = TASK_POLL_INTERVAL, + on_wait=None, ) -> None: """Poll GET /tasks/ until a backgrounded server task finishes. + ``on_wait``, if given, is called with no arguments once per poll, + before sleeping. A backgrounded push can occupy the server for + minutes (TASK_TIMEOUT allows ten), which is that much time a + caller on the GUI thread would otherwise spend inside this loop + without touching its main loop -- see grampswebapidb.py's + _pump_main_loop(). + Returns normally on SUCCESS. A FAILURE/REVOKED task raises -- WebApiPushConflict if it failed the server's old-data check (the same "Object has changed" sentinel a synchronous push reports as @@ -786,6 +817,8 @@ def wait_for_task( raise TimeoutError( f"Server task {task_id} did not finish within {timeout}s" ) + if on_wait is not None: + on_wait() sleep(poll_interval) def push_transaction( @@ -794,6 +827,7 @@ def push_transaction( retry: bool = True, undo: bool = False, background: bool = False, + on_wait=None, ) -> None: """ POST a batch of local changes to /transactions/ (no force=1): the @@ -871,12 +905,20 @@ def push_transaction( sleep(RATE_LIMIT_BACKOFF) self._authenticate() return self.push_transaction( - payload, retry=False, undo=undo, background=background + payload, + retry=False, + undo=undo, + background=background, + on_wait=on_wait, ) if exc.code == 429 and retry: sleep(RATE_LIMIT_BACKOFF) return self.push_transaction( - payload, retry=False, undo=undo, background=background + payload, + retry=False, + undo=undo, + background=background, + on_wait=on_wait, ) # 400 is the synchronous conflict; 500 is the same conflict # re-wrapped by run_task() on the inline background path. @@ -887,9 +929,13 @@ def push_transaction( if retry: sleep(RATE_LIMIT_BACKOFF) return self.push_transaction( - payload, retry=False, undo=undo, background=background + payload, + retry=False, + undo=undo, + background=background, + on_wait=on_wait, ) raise if status == 202: task_id = json.loads(body)["task"]["id"] - self.wait_for_task(task_id) + self.wait_for_task(task_id, on_wait=on_wait) From 65dc36162b087daf341c21970dc0cc1d531044e0 Mon Sep 17 00:00:00 2001 From: Doug Blank Date: Fri, 14 Aug 2026 14:58:21 -0700 Subject: [PATCH 03/13] GrampsWebApiDb: fix stuck sync cursor after a full-export rebuild _full_resync() never advanced sync_last_time, so a mirror rebuilt via _mirror_is_short_of_the_server() (e.g. a brand new mirror against a server whose history can't describe its data) was left with the cursor at its pre-rebuild value, often 0. _push_payload()'s conflict recovery ("resync from the server, then retry") reuses that same cursor, so it became a permanent no-op: the very next push conflict after a rebuild would resync (picking up nothing), retry, conflict again identically, and give up -- reported live as "Server rejected 1 local change(s)" immediately followed by "Giving up ... after a repeated or undo/redo conflict" on the first edit after a full rebuild. _full_resync() now captures a timestamp before the export download and sets sync_last_time to it once the rebuild succeeds, so later conflict recovery can actually see what changed server-side. Co-Authored-By: Claude Sonnet 5 --- GrampsWebApiDb/grampswebapidb.py | 24 ++++++++++- GrampsWebApiDb/tests/test_grampswebapidb.py | 46 +++++++++++++++++++++ 2 files changed, 69 insertions(+), 1 deletion(-) diff --git a/GrampsWebApiDb/grampswebapidb.py b/GrampsWebApiDb/grampswebapidb.py index aca432002..68446915d 100644 --- a/GrampsWebApiDb/grampswebapidb.py +++ b/GrampsWebApiDb/grampswebapidb.py @@ -381,7 +381,7 @@ import re from copy import deepcopy from tempfile import NamedTemporaryFile -from time import monotonic +from time import monotonic, time from urllib.error import HTTPError, URLError from gi.repository import GLib @@ -1566,9 +1566,30 @@ def _full_resync(self, progress_callback=None): the download+reimport -- unlike _sync_from_server()'s page-by-page reporting, ImportXml has no internal step reporting to forward finer-grained progress from. + + Also (re)sets sync_last_time to a timestamp taken right before the + export download starts, so the next incremental sync asks the + history feed for changes after that point instead of wherever the + walk that triggered this rebuild happened to leave the cursor -- + for the totals-shortfall case (_mirror_is_short_of_the_server()), + that walk can be a single empty page, which leaves sync_last_time + at its untouched starting value (0 for a brand new mirror) rather + than anywhere near "now". Left uncorrected, every later poll asks + for history "after 0" forever on a server whose history can't + describe its own data anyway, so it's a harmless no-op -- but a + *push conflict*'s own recovery (_push_payload()'s "resync from the + server now, then retry") uses that exact same stuck cursor, so the + resync it does can never actually pick up what changed and the + retry is doomed to repeat the same conflict and give up. Taken + before the download rather than after: a transaction the server + commits while the export is being generated or transferred is + safer to see again on the next poll (re-applying an already- + reflected change is a no-op) than to have it fall silently before + the cursor and only be discovered next time a shortfall check runs. """ if progress_callback is not None: progress_callback(0) + sync_cutoff = time() started = monotonic() # The single longest transfer this addon makes -- streamed rather # than read in one go so the main loop keeps its turn throughout @@ -1631,6 +1652,7 @@ def _full_resync(self, progress_callback=None): finally: self._pulling = False os.remove(tmp_path) + self._set_metadata("sync_last_time", sync_cutoff) if progress_callback is not None: progress_callback(100) diff --git a/GrampsWebApiDb/tests/test_grampswebapidb.py b/GrampsWebApiDb/tests/test_grampswebapidb.py index fc6f07b6e..0ceb4b3ef 100644 --- a/GrampsWebApiDb/tests/test_grampswebapidb.py +++ b/GrampsWebApiDb/tests/test_grampswebapidb.py @@ -45,6 +45,7 @@ # ------------------------------------------------------------------------- import os import sys +import time import unittest from urllib.error import HTTPError, URLError from unittest import mock @@ -717,6 +718,7 @@ def setUp(self): # _full_resync() reports the rebuilt total at DEBUG; there's no # real dbapi connection behind these stubs to count. self.db.get_total = mock.MagicMock(return_value=0) + self.db._set_metadata = mock.MagicMock() self.patcher = mock.patch.object(grampswebapidb, "DbTxn", FakeDbTxn) self.patcher.start() self.addCleanup(self.patcher.stop) @@ -856,6 +858,50 @@ def failing_import_data(database, filename, user): self.db._full_resync(progress_callback=progress) progress.assert_called_once_with(0) + def test_advances_sync_last_time_past_the_stuck_cursor(self): + # A totals-shortfall rebuild (_mirror_is_short_of_the_server()) can + # be triggered by a history feed whose very first page came back + # empty, which leaves sync_last_time at whatever it started as (0 + # for a brand new mirror) instead of anywhere near "now". Left + # alone, _push_payload()'s "resync from the server, then retry" + # conflict recovery reuses that same stuck cursor and so can never + # actually pick up what changed -- see the module's _full_resync() + # docstring. Confirm the rebuild now leaves a fresh, roughly-"now" + # cursor behind instead. + for key, name in grampswebapidb.KEY_TO_NAME_MAP.items(): + if key not in grampswebapidb.CLASS_TO_KEY_MAP.values(): + continue + setattr(self.db, f"get_{name}_handles", mock.MagicMock(return_value=[])) + setattr(self.db, f"remove_{name}", mock.MagicMock()) + before = time.time() + with mock.patch.object(grampswebapidb, "importData"): + self.db._full_resync() + after = time.time() + self.db._set_metadata.assert_called_once_with("sync_last_time", mock.ANY) + cutoff = self.db._set_metadata.call_args.args[1] + self.assertGreaterEqual(cutoff, before) + self.assertLessEqual(cutoff, after) + + def test_does_not_advance_sync_last_time_if_the_reimport_raises(self): + # A rebuild that failed partway through left the mirror in an + # unknown state (same reasoning as test_failed_import_does_not_ + # trigger_rebuild() above) -- advancing the cursor anyway would + # tell the next sync "everything up to here is accounted for" for + # a mirror that plainly isn't. + for key, name in grampswebapidb.KEY_TO_NAME_MAP.items(): + if key not in grampswebapidb.CLASS_TO_KEY_MAP.values(): + continue + setattr(self.db, f"get_{name}_handles", mock.MagicMock(return_value=[])) + setattr(self.db, f"remove_{name}", mock.MagicMock()) + + def failing_import_data(database, filename, user): + raise RuntimeError("boom") + + with mock.patch.object(grampswebapidb, "importData", failing_import_data): + with self.assertRaises(RuntimeError): + self.db._full_resync() + self.db._set_metadata.assert_not_called() + # ------------------------------------------------------------------------- # From b74213f3568000bc7b727ac80dbf5717de12c7b5 Mon Sep 17 00:00:00 2001 From: Doug Blank Date: Sat, 15 Aug 2026 11:52:41 -0700 Subject: [PATCH 04/13] GrampsWebApiDb: surface the server's own explanation for a failed request _get_json()/_get_binary() re-raise a non-401/429 HTTPError bare, which throws away its JSON response body -- so a request validation failure (a raw 422 from FastAPI, before gramps-web-api's own route handler even runs) reached the user as nothing but "HTTP Error 422: Unprocessable Entity", with no hint which field or parameter the server objected to. _describe_connection_error() now reads that body and appends it, trying both FastAPI's {"detail": ...} shape and the app's own domain-error {"error": {"message": ...}} shape. Co-Authored-By: Claude Sonnet 5 --- GrampsWebApiDb/grampswebapidb.py | 39 ++++++++++++++ GrampsWebApiDb/tests/test_grampswebapidb.py | 56 +++++++++++++++++++++ 2 files changed, 95 insertions(+) diff --git a/GrampsWebApiDb/grampswebapidb.py b/GrampsWebApiDb/grampswebapidb.py index 68446915d..19cbe789d 100644 --- a/GrampsWebApiDb/grampswebapidb.py +++ b/GrampsWebApiDb/grampswebapidb.py @@ -376,6 +376,7 @@ persisted, so this only ever matters within a single running session. """ +import json import logging import os import re @@ -538,6 +539,36 @@ def _pump_main_loop(): context.iteration(False) +def _http_error_detail(err): + """Pull the server's own explanation out of an HTTPError's JSON body, + if it has one. + + _get_json()/_get_binary() re-raise a non-401/429 HTTPError as-is, + which throws away its response body -- so a bare "HTTP Error 422: + Unprocessable Entity" reaches the user with no hint which request + parameter the server actually objected to. FastAPI's own automatic + validation errors (a raw 422, before the request even reaches + gramps-web-api's route handler) put that under "detail"; the app's + own domain errors (see webapi_client._raise_for_push_conflict(), + _task_error_message()) use {"error": {"message": ...}} instead. Try + both shapes; give up quietly (None) if the body isn't JSON at all, or + has already been read by something else. + """ + try: + body = json.loads(err.read()) + except (ValueError, OSError, AttributeError): + return None + if not isinstance(body, dict): + return None + detail = body.get("detail") + if detail: + return str(detail) + error = body.get("error") + if isinstance(error, dict) and error.get("message"): + return str(error["message"]) + return None + + def _describe_connection_error(err): """ Turn a _CONNECTION_ERRORS exception into DbConnectionError's message @@ -545,6 +576,10 @@ def _describe_connection_error(err): correctly identified but isn't allowed to do this -- worth calling out specifically, since the raw HTTPError text ("HTTP Error 403: Forbidden") reads like an auth failure rather than a permissions one. + + Anything else that came with a JSON body (see _http_error_detail()) + gets that appended, so a validation failure like a bare 422 names the + field it rejected instead of just its status code. """ if isinstance(err, HTTPError) and err.code == 403: return _( @@ -554,6 +589,10 @@ def _describe_connection_error(err): "permissions, or ask the server administrator to grant this " "one access." ) + if isinstance(err, HTTPError): + detail = _http_error_detail(err) + if detail: + return "%s\n\n%s" % (err, detail) return str(err) diff --git a/GrampsWebApiDb/tests/test_grampswebapidb.py b/GrampsWebApiDb/tests/test_grampswebapidb.py index 0ceb4b3ef..6f58924c1 100644 --- a/GrampsWebApiDb/tests/test_grampswebapidb.py +++ b/GrampsWebApiDb/tests/test_grampswebapidb.py @@ -43,6 +43,8 @@ # Standard python modules # # ------------------------------------------------------------------------- +import io +import json import os import sys import time @@ -1394,6 +1396,60 @@ def test_initialize_stores_web_client_and_calls_super(self): super_init.assert_called_once_with("/tmp/some-tree", "user", "pw") +# ------------------------------------------------------------------------- +# +# TestDescribeConnectionError +# +# _get_json()/_get_binary() re-raise a non-401/429 HTTPError as-is, which +# throws its response body away -- so, absent _http_error_detail(), a +# validation failure the server explained in detail (a raw 422 from +# FastAPI's own request validation, before gramps-web-api's route handler +# even runs) would reach the user as nothing but "HTTP Error 422: +# Unprocessable Entity". See _describe_connection_error()'s docstring. +# +# ------------------------------------------------------------------------- +class TestDescribeConnectionError(unittest.TestCase): + @staticmethod + def _http_error(code, body=None): + fp = io.BytesIO(json.dumps(body).encode()) if body is not None else None + return HTTPError("https://example.com/api/transactions/", code, "x", None, fp) + + def test_403_names_the_permission_problem_instead_of_the_raw_status(self): + message = grampswebapidb._describe_connection_error(self._http_error(403)) + self.assertIn("GRAMPS_WEB_API_KEY", message) + self.assertNotIn("HTTP Error 403", message) + + def test_422_appends_fastapi_detail(self): + err = self._http_error(422, {"detail": [{"msg": "value is not a valid float"}]}) + message = grampswebapidb._describe_connection_error(err) + self.assertIn("HTTP Error 422", message) + self.assertIn("value is not a valid float", message) + + def test_appends_the_apps_own_error_message_shape_too(self): + err = self._http_error(400, {"error": {"message": "Object has changed"}}) + message = grampswebapidb._describe_connection_error(err) + self.assertIn("Object has changed", message) + + def test_no_body_falls_back_to_the_bare_status(self): + message = grampswebapidb._describe_connection_error(self._http_error(500)) + self.assertEqual(message, str(self._http_error(500))) + + def test_unparseable_body_falls_back_to_the_bare_status(self): + err = HTTPError( + "https://example.com/api/transactions/", + 422, + "x", + None, + io.BytesIO(b"not json"), + ) + message = grampswebapidb._describe_connection_error(err) + self.assertEqual(message, str(err)) + + def test_non_http_error_just_stringifies(self): + message = grampswebapidb._describe_connection_error(ValueError("boom")) + self.assertEqual(message, "boom") + + # ------------------------------------------------------------------------- # # TestCheckIdentity From 41d64be3707bb3c3267a8e26cdb1a732552dedff Mon Sep 17 00:00:00 2001 From: Doug Blank Date: Sat, 15 Aug 2026 15:18:44 -0700 Subject: [PATCH 05/13] GrampsWebApiDb: recognize flask-jwt-extended's error shape in _http_error_detail A rejected POST /token/refresh/ (expired, revoked, or otherwise invalid refresh token) answers with {"msg": "..."} -- a third JSON error-body shape _http_error_detail() didn't know about alongside FastAPI's "detail" and the app's own {"error": {"message": ...}}. Without it, a failed refresh reached the user as a bare "HTTP Error 422: Unprocessable Entity" instead of the server's actual reason. Co-Authored-By: Claude Sonnet 5 --- GrampsWebApiDb/grampswebapidb.py | 12 +++++++++--- GrampsWebApiDb/tests/test_grampswebapidb.py | 7 +++++++ 2 files changed, 16 insertions(+), 3 deletions(-) diff --git a/GrampsWebApiDb/grampswebapidb.py b/GrampsWebApiDb/grampswebapidb.py index 19cbe789d..a0daffeb1 100644 --- a/GrampsWebApiDb/grampswebapidb.py +++ b/GrampsWebApiDb/grampswebapidb.py @@ -550,9 +550,12 @@ def _http_error_detail(err): validation errors (a raw 422, before the request even reaches gramps-web-api's route handler) put that under "detail"; the app's own domain errors (see webapi_client._raise_for_push_conflict(), - _task_error_message()) use {"error": {"message": ...}} instead. Try - both shapes; give up quietly (None) if the body isn't JSON at all, or - has already been read by something else. + _task_error_message()) use {"error": {"message": ...}} instead; + flask-jwt-extended's own error handlers -- what actually answers a + rejected POST /token/refresh/ (expired, revoked, or otherwise invalid + refresh token) -- use a third shape, {"msg": ...}. Try all three; give + up quietly (None) if the body isn't JSON at all, or has already been + read by something else. """ try: body = json.loads(err.read()) @@ -566,6 +569,9 @@ def _http_error_detail(err): error = body.get("error") if isinstance(error, dict) and error.get("message"): return str(error["message"]) + msg = body.get("msg") + if msg: + return str(msg) return None diff --git a/GrampsWebApiDb/tests/test_grampswebapidb.py b/GrampsWebApiDb/tests/test_grampswebapidb.py index 6f58924c1..900a9272b 100644 --- a/GrampsWebApiDb/tests/test_grampswebapidb.py +++ b/GrampsWebApiDb/tests/test_grampswebapidb.py @@ -1430,6 +1430,13 @@ def test_appends_the_apps_own_error_message_shape_too(self): message = grampswebapidb._describe_connection_error(err) self.assertIn("Object has changed", message) + def test_appends_flask_jwt_extendeds_msg_shape_too(self): + # What POST /token/refresh/ actually answers with when the stored + # refresh token is expired, revoked, or otherwise rejected. + err = self._http_error(422, {"msg": "Signature verification failed"}) + message = grampswebapidb._describe_connection_error(err) + self.assertIn("Signature verification failed", message) + def test_no_body_falls_back_to_the_bare_status(self): message = grampswebapidb._describe_connection_error(self._http_error(500)) self.assertEqual(message, str(self._http_error(500))) From e1e0341a82bb933cd83e36188268336eb3bd2b62 Mon Sep 17 00:00:00 2001 From: Doug Blank Date: Sat, 15 Aug 2026 17:19:07 -0700 Subject: [PATCH 06/13] GrampsWebApiDb: fix crash when a Family Tree is closed mid-sync _pump_main_loop() reenters the GTK main loop partway through a sync/push so the window stays responsive during a long transfer, but that also lets an ordinary GTK event -- the user switching to another Family Tree, or quitting Gramps -- dispatch close() on this very WebApiDB instance while the pump is suspended. The caller then resumes after the pump and touches self.dbapi, which close() has already torn down: sqlite3.ProgrammingError: Cannot operate on a closed database. Route every internal _pump_main_loop() call through a new _guarded_pump(), which raises _DatabaseClosed if close() ran during that pump. The entry points that can trigger one (_poll_tick(), _media_poll_tick(), load(), _push_payload(), _flush_pending_pushes()) catch it and treat it as nothing left to do, not a failure. Reported by @GaryGriffin: a background poll tick crashed after switching from a synced tree to a local one mid-sync. Co-Authored-By: Claude Sonnet 5 --- GrampsWebApiDb/grampswebapidb.py | 105 ++++++++++++++++++-- GrampsWebApiDb/tests/test_grampswebapidb.py | 83 +++++++++++++++- 2 files changed, 176 insertions(+), 12 deletions(-) diff --git a/GrampsWebApiDb/grampswebapidb.py b/GrampsWebApiDb/grampswebapidb.py index a0daffeb1..123f3f5a4 100644 --- a/GrampsWebApiDb/grampswebapidb.py +++ b/GrampsWebApiDb/grampswebapidb.py @@ -300,6 +300,20 @@ Pumping re-enters, so the poll timeouts check _syncing and skip a tick rather than starting a second sync underneath the first. +Reentering the main loop can also let the *user* act on this very Family +Tree while a pump-driven operation is suspended partway through it -- +switching to another tree or quitting Gramps calls close() from a GTK +event dispatched during the pump, which closes self.dbapi's connection +out from under the still-running caller. Left unhandled, that caller +resumes after the pump and crashes on its next database touch +(sqlite3.ProgrammingError: Cannot operate on a closed database) instead +of unwinding cleanly. Every _pump_main_loop() call this class makes goes +through _guarded_pump() instead of the bare function for exactly this +reason: it raises _DatabaseClosed if close() ran during that pump, and +the entry points that can trigger one (_poll_tick(), _media_poll_tick(), +load(), _push_payload(), _flush_pending_pushes()) catch it as "nothing +left to do here", not a failure. + Tracing a session ----------------- Most of what this addon does is invisible from the Gramps UI: a sync that @@ -506,6 +520,15 @@ _CONNECTION_ERRORS = (ValueError, KeyError, HTTPError, URLError, OSError) +class _DatabaseClosed(Exception): + """Raised by WebApiDB._guarded_pump() when close() ran while a + pump-driven sync/push was suspended -- see the module docstring's + "Keeping the GUI alive" section. Deliberately not one of the + _CONNECTION_ERRORS: it isn't a connectivity problem, and turning it + into a DbConnectionError would show the user a scary message about a + tree they've already left.""" + + def _pump_main_loop(): """Dispatch whatever the main loop has pending, without blocking. @@ -712,6 +735,11 @@ class WebApiDB(SQLite): #: _pump_main_loop() hands the main loop back mid-operation. _syncing = False + #: Set by close(), before anything else it does, so a pump-driven + #: sync/push suspended elsewhere on the call stack sees it as soon as + #: the main loop gives control back -- see _guarded_pump(). + _closed = False + #: Consecutive failed polls, per timer, and the record poll's current #: interval -- the outage state _poll_tick()/_media_poll_tick() use to #: log an outage once instead of once per tick, and to back the record @@ -766,6 +794,12 @@ def load(self, *args, **kwargs): self._check_server_version() try: self._sync_from_server(progress_callback=callback, verify_totals=True) + except _DatabaseClosed: + # The tree was closed (or switched away from) while this + # initial sync was suspended mid-pump -- see _guarded_pump(). + # Nothing left to open; don't schedule polling for it. + LOG.debug("load: tree closed during initial sync; aborting") + return except _CONNECTION_ERRORS as err: raise DbConnectionError( _describe_connection_error(err), self._directory @@ -778,6 +812,9 @@ def load(self, *args, **kwargs): self._poll_interval = POLL_INTERVAL_SECONDS try: self._sync_media_files() + except _DatabaseClosed: + LOG.debug("load: tree closed during initial media sync; aborting") + return except _CONNECTION_ERRORS: # Unlike the record sync above, a media-file-sync failure here # doesn't block opening the tree: the record mirror is already @@ -927,6 +964,12 @@ def _check_server_version(self): ) def close(self, *args, **kwargs): + # Set first, before anything else: a sync/push elsewhere on the + # call stack may be suspended inside _guarded_pump(), waiting to + # find out whether it's still safe to touch self.dbapi once the + # main loop hands control back. See _guarded_pump() and the module + # docstring's "Keeping the GUI alive" section. + self._closed = True # Stop polling a database that's no longer open -- otherwise the # next tick would run _sync_from_server() (and touch self.dbapi) # against a connection that's about to be (or already) closed. @@ -940,6 +983,27 @@ def close(self, *args, **kwargs): self._media_poll_source_id = None super().close(*args, **kwargs) + def _guarded_pump(self): + """_pump_main_loop(), then raise _DatabaseClosed if that let + close() run out from under us. + + Every _pump_main_loop() call this class makes goes through here + instead of the bare function. Without it, a sync/push resumes + after the pump and immediately crashes trying to touch + self.dbapi -- the user switching or closing this very Family Tree + is a perfectly ordinary GTK event, and reentering the main loop + mid-operation (see the module docstring) is exactly what lets it + get dispatched underneath a suspended call. Callers that can + trigger a pump (directly or via webapi_client's on_wait/on_chunk + hooks) let this propagate up to whichever entry point started + them -- _poll_tick(), _media_poll_tick(), load(), _push_payload(), + _flush_pending_pushes() -- which treat it as nothing left to do, + not a failure. + """ + _pump_main_loop() + if self._closed: + raise _DatabaseClosed() + def _poll_tick(self): """GLib.timeout_add_seconds callback -- see the module docstring's polling section. Must return True (GLib.SOURCE_CONTINUE) to keep @@ -962,6 +1026,13 @@ def _poll_tick(self): return GLib.SOURCE_CONTINUE try: self._sync_from_server() + except _DatabaseClosed: + # The tree got closed (or switched away from) while this tick + # was suspended mid-sync -- see _guarded_pump(). The GLib + # source is already gone (close() removed it); nothing more + # to do or report. + LOG.debug("poll: tree closed mid-sync; stopping this timer") + return GLib.SOURCE_REMOVE except _CONNECTION_ERRORS as err: return self._record_poll_failure(err) if self._poll_failures: @@ -1031,6 +1102,9 @@ def _media_poll_tick(self): return GLib.SOURCE_CONTINUE try: self._sync_media_files() + except _DatabaseClosed: + LOG.debug("media poll: tree closed mid-sync; stopping this timer") + return GLib.SOURCE_REMOVE except _CONNECTION_ERRORS as err: if self._media_poll_failures == 0: LOG.warning( @@ -1128,9 +1202,15 @@ def _push_payload(self, payload, undo=False, is_retry=False): ) try: self.web_client.push_transaction( - payload, undo=undo, background=background, on_wait=_pump_main_loop + payload, undo=undo, background=background, on_wait=self._guarded_pump ) LOG.debug("push: accepted in %.2fs", monotonic() - started) + except _DatabaseClosed: + # The tree was closed (or switched away from) while this push + # was suspended mid-wait -- see _guarded_pump(). Nothing left + # to push to; the edit stays local and unsent. + LOG.debug("push: tree closed mid-push; abandoning it") + return except WebApiPushConflict: LOG.warning( "Server rejected %d local change(s): the object(s) changed " @@ -1140,6 +1220,9 @@ def _push_payload(self, payload, undo=False, is_retry=False): ) try: self._sync_from_server() + except _DatabaseClosed: + LOG.debug("push: tree closed during conflict resync; abandoning it") + return except _CONNECTION_ERRORS: LOG.exception("Resync after a push conflict also failed.") return @@ -1242,7 +1325,7 @@ def _flush_pending_pushes(self): entry["payload"], undo=entry.get("undo", False), background=self._use_background_push(entry["payload"]), - on_wait=_pump_main_loop, + on_wait=self._guarded_pump, ) except WebApiPushConflict: LOG.warning( @@ -1488,7 +1571,7 @@ def _sync_from_server_inner(self, progress_callback, verify_totals): # one hasn't opened, so this is the one point in the replay # where handing the main loop back is safe. A catch-up of any # size would otherwise hold it for its whole duration. - _pump_main_loop() + self._guarded_pump() if len(transactions) < SYNC_PAGE_SIZE: break page += 1 @@ -1496,7 +1579,7 @@ def _sync_from_server_inner(self, progress_callback, verify_totals): # pump whenever the feed hands back a short page or nothing at # all, which is every routine poll -- and each of those still # cost a blocking round trip to find out. - _pump_main_loop() + self._guarded_pump() self._set_metadata("sync_last_time", after) LOG.debug( "sync: %d change(s) applied, %d skipped, from %d transaction(s) " @@ -1638,8 +1721,8 @@ def _full_resync(self, progress_callback=None): started = monotonic() # The single longest transfer this addon makes -- streamed rather # than read in one go so the main loop keeps its turn throughout - # (see _pump_main_loop() and download_export()'s on_chunk). - data = self.web_client.download_export(on_chunk=_pump_main_loop) + # (see _guarded_pump() and download_export()'s on_chunk). + data = self.web_client.download_export(on_chunk=self._guarded_pump) LOG.debug( "resync: downloaded a %.1f MB export in %.2fs", len(data) / (1024 * 1024), @@ -1652,8 +1735,8 @@ def _full_resync(self, progress_callback=None): # still intact: from here to request_rebuild() the local data is # being torn down and rebuilt, and anything dispatched in the # middle of that would be looking at a half-empty tree. See - # _pump_main_loop(). - _pump_main_loop() + # _guarded_pump(). + self._guarded_pump() # Both halves below are pull-side rebuilds, not local edits -- see # _sync_from_server()'s own note on the _pulling flag. ImportXml # opens its own batch DbTxn internally, so this has to stay set @@ -1693,7 +1776,7 @@ def _full_resync(self, progress_callback=None): self.request_rebuild() # The mirror is whole again and every view has been told to # reload, so it's safe to let the loop run once more. - _pump_main_loop() + self._guarded_pump() finally: self._pulling = False os.remove(tmp_path) @@ -1737,13 +1820,13 @@ def _sync_media_files_inner(self): downloaded += 1 # One file is one blocking transfer; a first sync of a tree # with media runs hundreds of them back to back. - _pump_main_loop() + self._guarded_pump() missing_remote = self._missing_remote_media_handles() uploaded = 0 for handle in missing_remote: if self._upload_one_media_file(handle): uploaded += 1 - _pump_main_loop() + self._guarded_pump() LOG.debug( "media: %d missing locally (%d downloaded), %d missing on the " "server (%d uploaded), in %.2fs", diff --git a/GrampsWebApiDb/tests/test_grampswebapidb.py b/GrampsWebApiDb/tests/test_grampswebapidb.py index 900a9272b..904529cc3 100644 --- a/GrampsWebApiDb/tests/test_grampswebapidb.py +++ b/GrampsWebApiDb/tests/test_grampswebapidb.py @@ -749,7 +749,7 @@ def fake_import_data(database, filename, user): self.db._full_resync() self.db.web_client.download_export.assert_called_once_with( - on_chunk=grampswebapidb._pump_main_loop + on_chunk=self.db._guarded_pump ) for key, name in grampswebapidb.KEY_TO_NAME_MAP.items(): if key not in grampswebapidb.CLASS_TO_KEY_MAP.values(): @@ -965,6 +965,15 @@ def test_push_failure_is_logged_not_raised(self): with self.assertLogs(grampswebapidb.LOG, level="ERROR"): self.db.transaction_commit(trans) # must not raise + def test_push_swallows_database_closed_mid_push(self): + # The tree was closed (or switched away from) while push_transaction()'s + # on_wait=self._guarded_pump had handed the main loop back -- see + # TestGuardedPump. Not a failure: nothing left to push to. + trans = FakeTransaction([(0, TXNADD, "H1", None, person_data("H1"))]) + self.db.web_client.push_transaction.side_effect = grampswebapidb._DatabaseClosed + with mock.patch.object(grampswebapidb.SQLite, "transaction_commit"): + self.db.transaction_commit(trans) # must not raise, must not log + def test_conflict_triggers_resync_then_retry(self): # A WebApiPushConflict means the server rejected the whole batch # because something changed server-side since the local mirror's @@ -1010,6 +1019,21 @@ def test_conflict_resync_failure_is_also_swallowed(self): # server, so retrying the edit on top of it would be pointless. retry.assert_not_called() + def test_conflict_resync_database_closed_is_also_swallowed(self): + trans = FakeTransaction([(0, TXNADD, "H1", None, person_data("H1"))]) + self.db.web_client.push_transaction.side_effect = WebApiPushConflict( + "Object has changed" + ) + with mock.patch.object( + grampswebapidb.SQLite, "transaction_commit" + ), mock.patch.object( + self.db, "_sync_from_server", side_effect=grampswebapidb._DatabaseClosed + ), mock.patch.object( + self.db, "_retry_after_conflict" + ) as retry: + self.db.transaction_commit(trans) # must not raise, must not log + retry.assert_not_called() + def test_repeated_conflict_on_a_retry_is_not_retried_again(self): # is_retry=True marks a push that is itself _retry_after_conflict()'s # replay -- a second conflict on that replay must not recurse into @@ -1904,6 +1928,7 @@ def test_close_cancels_pending_poll(self): self.assertIsNone(self.db._poll_source_id) self.assertIsNone(self.db._media_poll_source_id) super_close.assert_called_once_with() + self.assertTrue(self.db._closed) def test_close_without_a_poll_scheduled_is_a_no_op(self): # e.g. close() called after a failed load(), before the timeouts @@ -1916,6 +1941,7 @@ def test_close_without_a_poll_scheduled_is_a_no_op(self): self.db.close() source_remove.assert_not_called() super_close.assert_called_once_with() + self.assertTrue(self.db._closed) def test_poll_tick_syncs_and_keeps_repeating(self): with mock.patch.object(self.db, "_sync_from_server") as sync: @@ -2042,6 +2068,61 @@ def test_media_poll_tick_notes_recovery(self): self.assertEqual(result, grampswebapidb.GLib.SOURCE_CONTINUE) self.assertEqual(self.db._media_poll_failures, 0) + def test_poll_tick_stops_quietly_when_the_tree_closed_mid_sync(self): + # The user switching (or closing) this Family Tree while + # _guarded_pump() had handed the main loop back mid-sync -- see + # TestGuardedPump. Not a failure: no WARNING, and the timer must + # not reschedule itself (close() already removed its GLib source). + with mock.patch.object( + self.db, "_sync_from_server", side_effect=grampswebapidb._DatabaseClosed + ): + result = self.db._poll_tick() + self.assertEqual(result, grampswebapidb.GLib.SOURCE_REMOVE) + self.assertEqual(self.db._poll_failures, 0) + + def test_media_poll_tick_stops_quietly_when_the_tree_closed_mid_sync(self): + with mock.patch.object( + self.db, "_sync_media_files", side_effect=grampswebapidb._DatabaseClosed + ): + result = self.db._media_poll_tick() + self.assertEqual(result, grampswebapidb.GLib.SOURCE_REMOVE) + self.assertEqual(self.db._media_poll_failures, 0) + + +# ------------------------------------------------------------------------- +# +# TestGuardedPump +# +# _guarded_pump() is what every _pump_main_loop() call inside WebApiDB +# goes through instead of the bare function -- see the module docstring's +# "Keeping the GUI alive" section. Regression coverage for the crash a PR +# tester hit: switching Family Trees while a poll-driven sync was +# suspended mid-_pump_main_loop() resumed against an already-closed +# sqlite connection (sqlite3.ProgrammingError: Cannot operate on a closed +# database). +# +# ------------------------------------------------------------------------- +class TestGuardedPump(unittest.TestCase): + def setUp(self): + self.db = new_instance() + + def test_pumps_and_returns_when_still_open(self): + with mock.patch.object(grampswebapidb, "_pump_main_loop") as pump: + self.db._guarded_pump() # must not raise + pump.assert_called_once_with() + + def test_raises_database_closed_if_close_ran_during_the_pump(self): + def fake_pump(): + # Simulates close() running from a GTK event dispatched while + # this pump had control -- see close()'s own _closed = True. + self.db._closed = True + + with mock.patch.object( + grampswebapidb, "_pump_main_loop", side_effect=fake_pump + ): + with self.assertRaises(grampswebapidb._DatabaseClosed): + self.db._guarded_pump() + # ------------------------------------------------------------------------- # From 1da87291503799eded513e9f4c4e5b480305c95c Mon Sep 17 00:00:00 2001 From: Doug Blank Date: Sat, 15 Aug 2026 17:39:44 -0700 Subject: [PATCH 07/13] GrampsWebApiDb: verify totals on a push-conflict resync too _push_payload()'s conflict handler resynced with _sync_from_server()'s defaults, which never checks whether the mirror has fallen behind a server-side change the incremental history feed cannot describe at all (see _mirror_is_short_of_the_server()'s docstring on demo.grampsweb.org restoring from a dump outside its own transaction log). A conflict caused by exactly that blind spot resynced to nothing, so the retry below re-sent the same stale "old" snapshot, conflicted identically a second time, and the edit was dropped for good -- reported by @GaryGriffin: a fresh Person edit against demo.grampsweb.org, moments after a full resync, conflicted twice in a row while the history feed reported zero transactions both times. Pass verify_totals=True here, the same defense load() already uses, so a count-shifting server-side change gets a chance to trigger a full resync before the retry goes out. Co-Authored-By: Claude Sonnet 5 --- GrampsWebApiDb/grampswebapidb.py | 39 ++++++++++++++------- GrampsWebApiDb/tests/test_grampswebapidb.py | 10 ++++-- 2 files changed, 34 insertions(+), 15 deletions(-) diff --git a/GrampsWebApiDb/grampswebapidb.py b/GrampsWebApiDb/grampswebapidb.py index 123f3f5a4..8eed36b8c 100644 --- a/GrampsWebApiDb/grampswebapidb.py +++ b/GrampsWebApiDb/grampswebapidb.py @@ -129,17 +129,22 @@ changed server-side since the local mirror last synced -- a real, if coarse, optimistic-concurrency check: the whole push either applies or none of it does, with no indication of which item conflicted. On a -conflict, _push_payload() below resyncs from the server (so the local -mirror picks up whatever changed) and then, for a plain commit (not an -undo/redo -- see _retry_after_conflict()), replays each object's intended -*new* state as a fresh local edit via commit_()/remove_() on -top of that just-resynced data. That fresh edit goes through the normal -transaction_commit() -> _push_payload() path again with is_retry=True, -so it carries an up-to-date "old" snapshot and will only be rejected a -second time if something changes server-side in the brief window between -the resync and the retry -- in which case it is logged and dropped rather -than retried again, to avoid retrying forever against a genuinely hot -object. +conflict, _push_payload() below resyncs from the server -- with +verify_totals=True, the same defense load() uses, since a conflict can +be caused by a server-side change the incremental history feed cannot +describe at all (see _mirror_is_short_of_the_server()'s docstring; a +plain resync would come back empty and the retry below would be +guaranteed to conflict again identically) as easily as by an ordinary +edit the feed would replay normally -- and then, for a plain commit (not +an undo/redo -- see _retry_after_conflict()), replays each object's +intended *new* state as a fresh local edit via commit_()/ +remove_() on top of that just-resynced data. That fresh edit goes +through the normal transaction_commit() -> _push_payload() path again +with is_retry=True, so it carries an up-to-date "old" snapshot and will +only be rejected a second time if something changes server-side in the +brief window between the resync and the retry -- in which case it is +logged and dropped rather than retried again, to avoid retrying forever +against a genuinely hot object. For an add/update whose handle still exists after the resync (i.e. the conflicting server-side edit changed the same object rather than deleting @@ -1219,7 +1224,17 @@ def _push_payload(self, payload, undo=False, is_retry=False): len(payload), ) try: - self._sync_from_server() + # verify_totals=True, same as load(): a conflict can be + # caused by a server-side change the incremental history + # feed cannot describe at all (see + # _mirror_is_short_of_the_server()'s docstring on + # demo.grampsweb.org's restore-from-a-dump behavior) + # rather than by an ordinary edit the feed would replay + # normally. Without this, that resync always comes back + # empty, the retry below re-sends against the same stale + # "old" snapshot, and the edit is dropped for good on the + # second identical conflict. + self._sync_from_server(verify_totals=True) except _DatabaseClosed: LOG.debug("push: tree closed during conflict resync; abandoning it") return diff --git a/GrampsWebApiDb/tests/test_grampswebapidb.py b/GrampsWebApiDb/tests/test_grampswebapidb.py index 904529cc3..56ed893d0 100644 --- a/GrampsWebApiDb/tests/test_grampswebapidb.py +++ b/GrampsWebApiDb/tests/test_grampswebapidb.py @@ -992,7 +992,11 @@ def test_conflict_triggers_resync_then_retry(self): ) as retry: with self.assertLogs(grampswebapidb.LOG, level="WARNING"): self.db.transaction_commit(trans) # must not raise - resync.assert_called_once_with() + # verify_totals=True, same as load(): a conflict can be the + # untracked-server-change blind spot _mirror_is_short_of_the_ + # server() exists for, not just an ordinary edit the incremental + # feed would replay -- see the module docstring. + resync.assert_called_once_with(verify_totals=True) retry.assert_called_once() payload = retry.call_args[0][0] self.assertEqual(payload[0]["handle"], "H1") @@ -1051,7 +1055,7 @@ def test_repeated_conflict_on_a_retry_is_not_retried_again(self): self.db._push_payload( transaction_to_json(trans), is_retry=True ) # must not raise - resync.assert_called_once_with() + resync.assert_called_once_with(verify_totals=True) retry.assert_not_called() def test_undo_conflict_is_not_retried(self): @@ -1070,7 +1074,7 @@ def test_undo_conflict_is_not_retried(self): ) as retry: with self.assertLogs(grampswebapidb.LOG, level="WARNING"): self.db._push_payload(transaction_to_json(trans), undo=True) - resync.assert_called_once_with() + resync.assert_called_once_with(verify_totals=True) retry.assert_not_called() From ea708c528577abb670dca22bff08768d5df610a2 Mon Sep 17 00:00:00 2001 From: Doug Blank Date: Sat, 15 Aug 2026 18:04:30 -0700 Subject: [PATCH 08/13] GrampsWebApiDb: resolve push conflicts against the server object directly A push conflict cannot be trusted to resolve by resyncing (incremental, or the verify_totals object-count check): gramps-web-api's bulk-import path (POST /importers//file -- GEDCOM, Gramps XML, CSV, ...) runs the same batch=True import machinery a local Gramps client's own Import menu action would, which never writes to its transaction-history table at all (DBAPI's _commit_base() only calls trans.add() when `not trans.batch`) -- confirmed against gramps-web-api's own source (gramps_webapi/api/resources/util.py's run_import(), tasks.py's old_unchanged()). That is ordinary server administration for any real gramps-web-api installation, not a quirk specific to one server: the incremental history feed, and even this addon's own full-tree resync, can each be blind to an object's true current state for reasons that have nothing to do with how recently either ran. _retry_after_conflict() now takes refresh_from_server=True (set only by _push_payload()'s conflict handler, not _reconcile_batch_commit()'s first-push replay) and merges each add/update against a direct GET // (webapi_client.WebApiHandler.get_object(), new) instead of the local mirror -- the one thing the server can answer authoritatively regardless of whether history or a resync's snapshot can explain how the object got there. Fetched entirely before the DbTxn opens, so a network failure here queues the payload for later like any other connectivity failure, rather than leaving a partially-applied local transaction. Reported by @GaryGriffin: a Person attribute edit against demo.grampsweb.org conflicted twice in a row, identically, moments after a fresh full resync, while the history feed reported zero transactions both times -- the verify_totals fix from the previous commit doesn't cover this shape of conflict (a content-only update never changes the object count it checks). Co-Authored-By: Claude Sonnet 5 --- GrampsWebApiDb/grampswebapidb.py | 148 ++++++++++++++------ GrampsWebApiDb/tests/test_grampswebapidb.py | 102 +++++++++++++- GrampsWebApiDb/tests/test_webapi_client.py | 75 ++++++++++ GrampsWebApiDb/webapi_client.py | 50 +++++++ 4 files changed, 333 insertions(+), 42 deletions(-) diff --git a/GrampsWebApiDb/grampswebapidb.py b/GrampsWebApiDb/grampswebapidb.py index 8eed36b8c..d0aae887b 100644 --- a/GrampsWebApiDb/grampswebapidb.py +++ b/GrampsWebApiDb/grampswebapidb.py @@ -128,28 +128,46 @@ WebApiPushConflict (see webapi_client.push_transaction()) if anything changed server-side since the local mirror last synced -- a real, if coarse, optimistic-concurrency check: the whole push either applies or -none of it does, with no indication of which item conflicted. On a -conflict, _push_payload() below resyncs from the server -- with -verify_totals=True, the same defense load() uses, since a conflict can -be caused by a server-side change the incremental history feed cannot -describe at all (see _mirror_is_short_of_the_server()'s docstring; a -plain resync would come back empty and the retry below would be -guaranteed to conflict again identically) as easily as by an ordinary -edit the feed would replay normally -- and then, for a plain commit (not -an undo/redo -- see _retry_after_conflict()), replays each object's +none of it does, with no indication of which item conflicted. + +Neither side of this addon's own resync machinery can be trusted to +explain a conflict, and this is not a one-server edge case: gramps-web- +api's bulk-import path (POST /importers//file -- GEDCOM, Gramps +XML, CSV, ...) runs the same batch=True import machinery a local Gramps +client's own Import menu action would, which never touches its +transaction-history table at all (DBAPI's own _commit_base() only calls +trans.add() when `not trans.batch`) -- ordinary server administration +for any real installation, not a quirk of any particular one. So: the +incremental history feed can be blind to an object's true current state +from the moment it was imported, and even this addon's own full-tree +resync (_full_resync(), the verify_totals=True fallback below and +load()'s) only proves the mirror was accurate at the moment its export +was taken -- seconds to tens of seconds before the retry actually goes +out, plenty of time for another push (through the API, so it would +appear in history) to land in between. + +So: on a conflict, _push_payload() below resyncs from the server (with +verify_totals=True, the same defense load() uses, for its own sake -- +other objects may genuinely have changed) and then, for a plain commit +(not an undo/redo -- see _retry_after_conflict()), replays each object's intended *new* state as a fresh local edit via commit_()/ -remove_() on top of that just-resynced data. That fresh edit goes -through the normal transaction_commit() -> _push_payload() path again -with is_retry=True, so it carries an up-to-date "old" snapshot and will -only be rejected a second time if something changes server-side in the -brief window between the resync and the retry -- in which case it is -logged and dropped rather than retried again, to avoid retrying forever -against a genuinely hot object. - -For an add/update whose handle still exists after the resync (i.e. the -conflicting server-side edit changed the same object rather than deleting -it), _merge_or_overwrite() below combines the two edits with the object's -own merge() -- the same list-unioning logic behind Gramps' Merge People/ +remove_(), the same as before -- except the "current" object each +add/update is merged against comes from a direct GET // +(WebApiHandler.get_object()) taken right before that replay, not from +the resync or the local mirror. That is the one thing this addon can +ask the server that is authoritative regardless of whether history or a +resync's snapshot can explain how the object got there. That fresh edit +goes through the normal transaction_commit() -> _push_payload() path +again with is_retry=True, so it carries an up-to-date "old" snapshot +matching what was just read, and will only be rejected a second time if +something changes server-side in the brief window since then -- in +which case it is logged and dropped rather than retried again, to avoid +retrying forever against a genuinely hot object. + +For an add/update whose object still exists server-side (i.e. the +conflicting edit changed the same object rather than deleting it), +_merge_or_overwrite() below combines the two edits with the object's own +merge() -- the same list-unioning logic behind Gramps' Merge People/ Family/... tools (ported from GrampsWebSync's diffhandler.py, credit David Straub, same license) -- rather than letting the retry blindly clobber whatever the other side changed. merge() only unions *list*-valued @@ -1226,14 +1244,17 @@ def _push_payload(self, payload, undo=False, is_retry=False): try: # verify_totals=True, same as load(): a conflict can be # caused by a server-side change the incremental history - # feed cannot describe at all (see - # _mirror_is_short_of_the_server()'s docstring on - # demo.grampsweb.org's restore-from-a-dump behavior) - # rather than by an ordinary edit the feed would replay - # normally. Without this, that resync always comes back - # empty, the retry below re-sends against the same stale - # "old" snapshot, and the edit is dropped for good on the - # second identical conflict. + # feed cannot describe at all -- a bulk import runs + # entirely outside gramps-web-api's own transaction log + # (see webapi_client.get_object()'s docstring), ordinary + # server administration rather than an edge case -- as + # easily as by an ordinary edit the feed would replay + # normally. Without this, that resync can come back + # describing nothing relevant either way; it is still + # worth doing for its own sake (other objects may + # genuinely have changed), just not trusted on its own + # for the object(s) in this payload -- see + # _retry_after_conflict()'s refresh_from_server below. self._sync_from_server(verify_totals=True) except _DatabaseClosed: LOG.debug("push: tree closed during conflict resync; abandoning it") @@ -1249,7 +1270,20 @@ def _push_payload(self, payload, undo=False, is_retry=False): len(payload), ) return - self._retry_after_conflict(payload) + try: + self._retry_after_conflict(payload, refresh_from_server=True) + except _CONNECTION_ERRORS as err: + # Nothing has been committed locally yet at this point -- + # see _retry_after_conflict()'s docstring -- so this is a + # plain connectivity failure, queued like any other. + LOG.warning( + "Could not fetch current server data for %d local " + "change(s) after a conflict (%s); queued for retry on " + "the next successful contact with the server.", + len(payload), + err, + ) + self._queue_pending_push(payload, undo=undo) except _CONNECTION_ERRORS as err: if not _is_retryable_push_error(err): # A permission/payload rejection is not going to start @@ -1368,20 +1402,47 @@ def _flush_pending_pushes(self): self._set_metadata("pending_pushes", pending) LOG.debug("queue: %d push(es) still pending after the flush", len(pending)) - def _retry_after_conflict(self, payload): - """Reapply each locally-intended change on top of the mirror - _push_payload() just resynced, as a fresh local edit -- see the - module docstring's write-through section. An add/update whose - object still exists after the resync is combined with the current - (server-fresh) object via _merge_or_overwrite() rather than - blindly replacing it. + def _retry_after_conflict(self, payload, refresh_from_server=False): + """Reapply each locally-intended change as a fresh local edit -- + see the module docstring's write-through section. An add/update + whose object still exists is combined with the current object via + _merge_or_overwrite() rather than blindly replacing it. + + refresh_from_server, set only by _push_payload()'s conflict + handler, reads each entry's "current" object with a direct + GET // (WebApiHandler.get_object()) instead of the + local mirror. A resync -- incremental, or the object-count check + verify_totals asks for -- can be blind to what the server + actually holds for this exact object: a bulk import never + touches the transaction-history feed at all (see get_object()'s + docstring), which is normal server administration for a real + installation, not a rare condition, so the local mirror is not a + reliable merge base right after a conflict. Fetched up front, all + at once, before the DbTxn below opens -- so a network failure + here fails cleanly with nothing committed locally yet, rather + than leaving a partially-applied transaction; _push_payload() + queues the whole payload for a later retry on that failure, the + same as any other connectivity failure. + + _reconcile_batch_commit()'s call leaves this off -- replaying a + local batch operation's own changes as a first push, not + recovering from a conflict, so there is nothing to refresh + against yet, and fetching every entry individually would cost one + request per object for what can be a large batch. Runs as one ordinary (non-batch) DbTxn, so it goes through the normal transaction_commit() -> _push_payload() path again -- this - time with an "old" snapshot that matches what the resync just - pulled down, so it will only be rejected again if something else - changed server-side in the brief window since that resync. + time with an "old" snapshot that matches what was just read, so it + will only be rejected again if something else changed server-side + in the brief window since then. """ + fresh = {} + if refresh_from_server: + for entry in payload: + if entry["type"] != "delete": + fresh[entry["handle"]] = self.web_client.get_object( + entry["_class"], entry["handle"] + ) self._retrying = True try: with DbTxn(_("Retry local change after server conflict"), self) as trans: @@ -1397,7 +1458,12 @@ def _retry_after_conflict(self, payload): getattr(self, f"remove_{name}")(handle, trans) else: obj = data_to_object(entry["new"]) - if has_handle(handle): + if refresh_from_server: + server_data = fresh.get(handle) + if server_data is not None: + current = data_to_object(server_data) + obj = _merge_or_overwrite(current, obj) + elif has_handle(handle): current = getattr(self, f"get_{name}_from_handle")(handle) obj = _merge_or_overwrite(current, obj) getattr(self, f"commit_{name}")(obj, trans) diff --git a/GrampsWebApiDb/tests/test_grampswebapidb.py b/GrampsWebApiDb/tests/test_grampswebapidb.py index 56ed893d0..1b1c63096 100644 --- a/GrampsWebApiDb/tests/test_grampswebapidb.py +++ b/GrampsWebApiDb/tests/test_grampswebapidb.py @@ -997,7 +997,10 @@ def test_conflict_triggers_resync_then_retry(self): # server() exists for, not just an ordinary edit the incremental # feed would replay -- see the module docstring. resync.assert_called_once_with(verify_totals=True) - retry.assert_called_once() + # refresh_from_server=True: merge against a direct per-object + # fetch, not the mirror the resync above may not have been able + # to update for this exact object -- see _retry_after_conflict(). + retry.assert_called_once_with(mock.ANY, refresh_from_server=True) payload = retry.call_args[0][0] self.assertEqual(payload[0]["handle"], "H1") @@ -1023,6 +1026,30 @@ def test_conflict_resync_failure_is_also_swallowed(self): # server, so retrying the edit on top of it would be pointless. retry.assert_not_called() + def test_retry_fetch_failure_is_queued_not_dropped(self): + # _retry_after_conflict(refresh_from_server=True) fetches each + # entry fresh before committing anything locally -- a network + # failure there is a plain connectivity problem, not a conflict, + # so the payload is queued for later like any other push that + # couldn't be delivered (see TestPendingPushQueue), not dropped. + trans = FakeTransaction([(0, TXNADD, "H1", None, person_data("H1"))]) + self.db.web_client.push_transaction.side_effect = WebApiPushConflict( + "Object has changed" + ) + with mock.patch.object( + grampswebapidb.SQLite, "transaction_commit" + ), mock.patch.object(self.db, "_sync_from_server"), mock.patch.object( + self.db, + "_retry_after_conflict", + side_effect=OSError("network down"), + ): + with self.assertLogs(grampswebapidb.LOG, level="WARNING"): + self.db.transaction_commit(trans) # must not raise + self.assertEqual(len(self.metadata["pending_pushes"]), 1) + self.assertEqual( + self.metadata["pending_pushes"][0]["payload"][0]["handle"], "H1" + ) + def test_conflict_resync_database_closed_is_also_swallowed(self): trans = FakeTransaction([(0, TXNADD, "H1", None, person_data("H1"))]) self.db.web_client.push_transaction.side_effect = WebApiPushConflict( @@ -1100,6 +1127,7 @@ def setUp(self): self.db.remove_person = mock.MagicMock() self.db.has_person_handle = mock.MagicMock() self.db.get_person_from_handle = mock.MagicMock() + self.db.web_client = mock.MagicMock() dbtxn_patch = mock.patch.object(grampswebapidb, "DbTxn") mock_dbtxn_class = dbtxn_patch.start() mock_dbtxn_class.return_value.__enter__.return_value = "TRANS" @@ -1151,6 +1179,78 @@ def test_update_of_a_still_present_handle_is_merged_with_the_current_object(self self.assertEqual(merge_local.get_gramps_id(), "I0002") self.db.commit_person.assert_called_once_with("MERGED", "TRANS") + def test_refresh_from_server_merges_against_a_direct_fetch_not_the_mirror(self): + # The whole point of refresh_from_server=True: the local mirror + # (has_person_handle/get_person_from_handle) is never consulted + # for the merge decision -- only WebApiHandler.get_object(), a + # direct GET /people/ -- since a resync can be blind to + # what the server actually holds (bulk-imported data never + # touches the transaction-history feed; see the module docstring + # and webapi_client.get_object()'s docstring). + server_data = remove_object(person_data("H1", "I0099")) + self.db.web_client.get_object.return_value = server_data + new_data = remove_object(person_data("H1", "I0002")) + payload = [ + { + "type": "update", + "handle": "H1", + "_class": "Person", + "old": None, + "new": new_data, + } + ] + with mock.patch.object(grampswebapidb, "_merge_or_overwrite") as merge_fn: + merge_fn.return_value = "MERGED" + self.db._retry_after_conflict(payload, refresh_from_server=True) + self.db.web_client.get_object.assert_called_once_with("Person", "H1") + self.db.has_person_handle.assert_not_called() + self.db.get_person_from_handle.assert_not_called() + merge_current, merge_local = merge_fn.call_args[0] + self.assertEqual(merge_current.get_gramps_id(), "I0099") + self.assertIsInstance(merge_local, Person) + self.db.commit_person.assert_called_once_with("MERGED", "TRANS") + + def test_refresh_from_server_with_no_server_object_commits_as_is(self): + # get_object() returning None (a 404) means the server has + # nothing at this handle to merge against -- same as a true add. + self.db.web_client.get_object.return_value = None + new_data = remove_object(person_data("H1", "I0001")) + payload = [ + { + "type": "update", + "handle": "H1", + "_class": "Person", + "old": None, + "new": new_data, + } + ] + with mock.patch.object(grampswebapidb, "_merge_or_overwrite") as merge_fn: + self.db._retry_after_conflict(payload, refresh_from_server=True) + merge_fn.assert_not_called() + self.db.commit_person.assert_called_once() + obj, trans = self.db.commit_person.call_args[0] + self.assertEqual(obj.get_gramps_id(), "I0001") + + def test_refresh_from_server_fetches_before_opening_the_transaction(self): + # A network failure here must fail cleanly with nothing committed + # locally yet -- see _push_payload()'s handling of this, which + # queues the whole payload for later rather than leaving a + # partially-applied transaction. + self.db.web_client.get_object.side_effect = OSError("network down") + new_data = remove_object(person_data("H1")) + payload = [ + { + "type": "update", + "handle": "H1", + "_class": "Person", + "old": None, + "new": new_data, + } + ] + with self.assertRaises(OSError): + self.db._retry_after_conflict(payload, refresh_from_server=True) + self.db.commit_person.assert_not_called() + def test_delete_removes_if_handle_still_present(self): self.db.has_person_handle.return_value = True payload = [ diff --git a/GrampsWebApiDb/tests/test_webapi_client.py b/GrampsWebApiDb/tests/test_webapi_client.py index eb1b7c013..4a3544001 100644 --- a/GrampsWebApiDb/tests/test_webapi_client.py +++ b/GrampsWebApiDb/tests/test_webapi_client.py @@ -592,6 +592,81 @@ def test_total_count_falls_back_to_body_length(self): self.assertEqual(total, 3) +# ------------------------------------------------------------------------- +# +# TestGetObject +# +# get_object() (grampswebapidb.py's _retry_after_conflict()'s +# refresh_from_server path) hits GET // directly, the one +# source of truth for an object's current server-side state that does not +# depend on gramps-web-api's own transaction-history feed having anything +# to say about it -- see its own docstring. +# +# ------------------------------------------------------------------------- +class TestGetObject(unittest.TestCase): + def _authed_handler(self): + fake = QueuedUrlopen([FakeResponse({"access_token": token("AT0")})]) + with mock.patch.object(webapi_client, "urlopen", fake): + handler = WebApiHandler("https://example.com/api", refresh_token="RT") + return handler + + def test_request_url_uses_the_plural_endpoint(self): + handler = self._authed_handler() + body = {"_class": "Person", "handle": "H1"} + fake = QueuedUrlopen([FakeResponse(body)]) + with mock.patch.object(webapi_client, "urlopen", fake): + data = handler.get_object("Person", "H1") + self.assertEqual(data, body) + self.assertEqual(fake.requests[0].full_url, "https://example.com/api/people/H1") + + def test_family_uses_its_irregular_plural(self): + handler = self._authed_handler() + fake = QueuedUrlopen([FakeResponse({"_class": "Family", "handle": "H1"})]) + with mock.patch.object(webapi_client, "urlopen", fake): + handler.get_object("Family", "H1") + self.assertEqual( + fake.requests[0].full_url, "https://example.com/api/families/H1" + ) + + def test_404_returns_none(self): + # Deleted server-side, or never existed -- the same "nothing to + # merge against" signal a locally-new object gives. + handler = self._authed_handler() + fake = QueuedUrlopen([http_error(404)]) + with mock.patch.object(webapi_client, "urlopen", fake): + self.assertIsNone(handler.get_object("Person", "H1")) + + def test_other_http_error_propagates(self): + handler = self._authed_handler() + fake = QueuedUrlopen([http_error(500), http_error(500)]) + with mock.patch.object(webapi_client, "urlopen", fake): + with self.assertRaises(HTTPError): + handler.get_object("Person", "H1") + + def test_unknown_class_raises_without_a_request(self): + handler = self._authed_handler() + fake = QueuedUrlopen([]) + with mock.patch.object(webapi_client, "urlopen", fake): + with self.assertRaises(ValueError): + handler.get_object("NotAThing", "H1") + self.assertEqual(len(fake.requests), 0) + + def test_401_triggers_reauth_and_retry(self): + handler = self._authed_handler() + fake = QueuedUrlopen( + [ + http_error(401), + FakeResponse({"access_token": token("AT1")}), # the re-auth call + FakeResponse({"_class": "Person", "handle": "H1"}), + ] + ) + with mock.patch.object(webapi_client, "urlopen", fake), mock.patch.object( + webapi_client, "sleep" + ): + data = handler.get_object("Person", "H1") + self.assertEqual(data["handle"], "H1") + + # ------------------------------------------------------------------------- # # TestDownloadExport diff --git a/GrampsWebApiDb/webapi_client.py b/GrampsWebApiDb/webapi_client.py index aa714339d..e2855878e 100644 --- a/GrampsWebApiDb/webapi_client.py +++ b/GrampsWebApiDb/webapi_client.py @@ -114,6 +114,23 @@ "tags", ) +#: Gramps class name -> the REST resource's plural path segment, e.g. +#: "Person" -> GET /people/ -- see gramps-web-api's api/__init__.py +#: route registrations. Used by get_object() to fetch one primary object's +#: current server-side state directly, by class and handle. +CLASS_TO_ENDPOINT = { + "Person": "people", + "Family": "families", + "Event": "events", + "Place": "places", + "Source": "sources", + "Citation": "citations", + "Repository": "repositories", + "Media": "media", + "Note": "notes", + "Tag": "tags", +} + #: Chunk size used when streaming a media file download to disk -- see #: download_media_file(). _DOWNLOAD_CHUNK_SIZE = 1024 * 64 @@ -777,6 +794,39 @@ def get_transaction_history( total_count = int(headers.get("X-Total-Count", len(body))) return body, total_count + def get_object(self, obj_class: str, handle: str) -> dict[str, Any] | None: + """Fetch one primary object's current server-side state directly + -- GET // -- rather than through the transaction- + history feed or a full-tree resync. + + Both of those describe the server's state only as far as + gramps-web-api's own transaction log accounts for it -- which a + bulk import (POST /importers//file, GEDCOM/Gramps XML/CSV/ + ...) never touches at all, since it runs the same batch=True + import machinery a local Gramps client's own Import menu action + would (see grampswebapidb.py's module docstring). That is normal + server administration, not a quirk of any one installation, so an + object whose true current content the history feed cannot + describe is an ordinary thing to run into, not an edge case. + grampswebapidb.py's _retry_after_conflict() calls this to read + the one object actually in question directly, sidestepping that + blind spot entirely rather than trying to detect it. + + Returns ``None`` if the server has no object at this handle (a + 404 -- deleted, or never existed), the same "nothing to merge + against" signal a locally-new object gives. + """ + endpoint = CLASS_TO_ENDPOINT.get(obj_class) + if endpoint is None: + raise ValueError(f"Unknown object class: {obj_class!r}") + try: + data, _headers = self._get_json(f"{self.url}/{endpoint}/{handle}") + except HTTPError as exc: + if exc.code == 404: + return None + raise + return data + def wait_for_task( self, task_id: str, From 03b5d1ef137c81a7af29bcfe2eb10567699a9397 Mon Sep 17 00:00:00 2001 From: Doug Blank Date: Sat, 15 Aug 2026 18:39:01 -0700 Subject: [PATCH 09/13] GrampsWebApiDb: actually sync the local mirror before a conflict retry The previous commit fetched the server's current object (webapi_client.get_object()) but only used it to build a better merged "new" value in memory -- it never wrote that fetched data into the local mirror. DBAPI computes a commit's "old" snapshot purely from whatever is stored locally at commit time (_commit_base()'s _get_raw_data() call), with no awareness of anything read elsewhere, so the retry still pushed the same stale pre-conflict "old" and was guaranteed to be rejected again identically -- the fix did not actually change the outcome for the reported bug. _retry_after_conflict(refresh_from_server=True) now calls a new _pull_conflicting_objects() first: a pull-side replay (batch=True, _pulling=True, no push-back -- same pattern as _sync_from_server()'s own replay) that commits each entry's freshly-fetched server object into the local mirror before the merge-and-commit runs. That local write is what makes DBAPI's own "old" capture correct on the retry. Verified end to end against a real (temp-directory) SQLite-backed database and real DbTxn/transaction_commit machinery, with only the network layer mocked (TestConflictRetryAgainstARealDatabase) -- the mock-heavy unit tests added in the previous commit could not have caught this, since they stub commit_person/has_person_handle/ get_person_from_handle as independent mocks that never actually agree on a shared local state. Co-Authored-By: Claude Sonnet 5 --- GrampsWebApiDb/grampswebapidb.py | 145 ++++++--- GrampsWebApiDb/tests/test_grampswebapidb.py | 324 +++++++++++++++++--- 2 files changed, 387 insertions(+), 82 deletions(-) diff --git a/GrampsWebApiDb/grampswebapidb.py b/GrampsWebApiDb/grampswebapidb.py index d0aae887b..4184aba1c 100644 --- a/GrampsWebApiDb/grampswebapidb.py +++ b/GrampsWebApiDb/grampswebapidb.py @@ -149,20 +149,23 @@ So: on a conflict, _push_payload() below resyncs from the server (with verify_totals=True, the same defense load() uses, for its own sake -- other objects may genuinely have changed) and then, for a plain commit -(not an undo/redo -- see _retry_after_conflict()), replays each object's -intended *new* state as a fresh local edit via commit_()/ -remove_(), the same as before -- except the "current" object each -add/update is merged against comes from a direct GET // -(WebApiHandler.get_object()) taken right before that replay, not from -the resync or the local mirror. That is the one thing this addon can -ask the server that is authoritative regardless of whether history or a -resync's snapshot can explain how the object got there. That fresh edit -goes through the normal transaction_commit() -> _push_payload() path -again with is_retry=True, so it carries an up-to-date "old" snapshot -matching what was just read, and will only be rejected a second time if -something changes server-side in the brief window since then -- in -which case it is logged and dropped rather than retried again, to avoid -retrying forever against a genuinely hot object. +(not an undo/redo -- see _retry_after_conflict()), pulls each entry's +object fresh with its own direct GET // +(WebApiHandler.get_object(), via _pull_conflicting_objects()) *into the +local mirror* before replaying the intended *new* state as a fresh local +edit via commit_()/remove_(). That local write, not just a +fresher value read into memory, is what matters: DBAPI computes the +retry's own "old" snapshot from whatever is actually stored locally at +commit time, with no awareness of anything read here -- so unless the +mirror itself is caught up first, the retry would push the same stale +"old" as the original failed push and be rejected again identically, no +matter how correct its "new" was. That fresh edit goes through the +normal transaction_commit() -> _push_payload() path again with +is_retry=True, so it now carries an "old" snapshot matching what was +just pulled, and will only be rejected a second time if something +changes server-side in the brief window since then -- in which case it +is logged and dropped rather than retried again, to avoid retrying +forever against a genuinely hot object. For an add/update whose object still exists server-side (i.e. the conflicting edit changed the same object rather than deleting it), @@ -1409,40 +1412,34 @@ def _retry_after_conflict(self, payload, refresh_from_server=False): _merge_or_overwrite() rather than blindly replacing it. refresh_from_server, set only by _push_payload()'s conflict - handler, reads each entry's "current" object with a direct - GET // (WebApiHandler.get_object()) instead of the - local mirror. A resync -- incremental, or the object-count check - verify_totals asks for -- can be blind to what the server - actually holds for this exact object: a bulk import never - touches the transaction-history feed at all (see get_object()'s - docstring), which is normal server administration for a real - installation, not a rare condition, so the local mirror is not a - reliable merge base right after a conflict. Fetched up front, all - at once, before the DbTxn below opens -- so a network failure - here fails cleanly with nothing committed locally yet, rather - than leaving a partially-applied transaction; _push_payload() - queues the whole payload for a later retry on that failure, the - same as any other connectivity failure. + handler, first calls _pull_conflicting_objects() to bring the + local mirror's copy of each entry's object up to date with a + direct GET // read, *before* anything below runs. + That has to be an actual local write, not just a fresher value + used in memory for the merge: DBAPI computes this retry's own + "old" snapshot from whatever is stored locally at commit time + (_commit_base()'s _get_raw_data() call, entirely independent of + what get_object() returned) -- so unless the mirror itself is + caught up first, the retry below would still push the stale + pre-conflict "old" and be rejected again identically, even though + its "new" reflected correct data. See _pull_conflicting_objects() + for why the local mirror (and even this addon's own full-tree + resync) cannot be trusted to have already done this. _reconcile_batch_commit()'s call leaves this off -- replaying a local batch operation's own changes as a first push, not - recovering from a conflict, so there is nothing to refresh - against yet, and fetching every entry individually would cost one - request per object for what can be a large batch. + recovering from a conflict, so there is nothing to pull yet, and + fetching every entry individually would cost one request per + object for what can be a large batch. Runs as one ordinary (non-batch) DbTxn, so it goes through the normal transaction_commit() -> _push_payload() path again -- this - time with an "old" snapshot that matches what was just read, so it - will only be rejected again if something else changed server-side - in the brief window since then. + time with an "old" snapshot that matches what was just pulled, so + it will only be rejected again if something else changed + server-side in the brief window since then. """ - fresh = {} if refresh_from_server: - for entry in payload: - if entry["type"] != "delete": - fresh[entry["handle"]] = self.web_client.get_object( - entry["_class"], entry["handle"] - ) + self._pull_conflicting_objects(payload) self._retrying = True try: with DbTxn(_("Retry local change after server conflict"), self) as trans: @@ -1458,18 +1455,74 @@ def _retry_after_conflict(self, payload, refresh_from_server=False): getattr(self, f"remove_{name}")(handle, trans) else: obj = data_to_object(entry["new"]) - if refresh_from_server: - server_data = fresh.get(handle) - if server_data is not None: - current = data_to_object(server_data) - obj = _merge_or_overwrite(current, obj) - elif has_handle(handle): + if has_handle(handle): current = getattr(self, f"get_{name}_from_handle")(handle) obj = _merge_or_overwrite(current, obj) getattr(self, f"commit_{name}")(obj, trans) finally: self._retrying = False + def _pull_conflicting_objects(self, payload): + """Bring the local mirror's copy of each non-delete ``payload`` + entry's object up to date with a direct GET // read + (WebApiHandler.get_object()) -- a pull-side replay, like + _sync_from_server()'s own (batch=True, _pulling=True, so nothing + here gets pushed back out -- see the module docstring), not a + local edit. + + Neither the incremental history feed nor even a full-tree resync + can be trusted to have already done this for the object(s) a push + just conflicted on: gramps-web-api's bulk-import path (POST + /importers//file -- GEDCOM, Gramps XML, CSV, ...) runs the + same batch=True import machinery a local Gramps client's own + Import menu action would, which never touches the transaction- + history table at all (see get_object()'s docstring) -- ordinary + server administration for any real installation, not a quirk of + one server -- and a full-tree resync only proves the mirror was + accurate at the moment its export was taken, seconds to tens of + seconds before _retry_after_conflict() actually commits. A direct + per-object read is the one thing this addon can ask the server + that is authoritative regardless of how the object got to its + current state. + + Every GET happens before the DbTxn below opens, all at once -- so + a network failure here (propagated to _push_payload(), which + queues the whole payload for a later retry) leaves nothing + committed locally yet, rather than a partially-applied batch. + + A handle the server no longer has (get_object() returns None -- + deleted, or never existed) is left untouched: nothing to pull in, + and _retry_after_conflict()'s own has_handle()/commit_() + already do the right thing for a handle absent from the mirror. + """ + fresh = {} + for entry in payload: + if entry["type"] != "delete": + fresh[entry["handle"]] = self.web_client.get_object( + entry["_class"], entry["handle"] + ) + net_changes = {} + self._pulling = True + try: + with DbTxn(_("Refresh before conflict retry"), self, batch=True) as trans: + for entry in payload: + server_data = fresh.get(entry["handle"]) + if server_data is None: + continue + key = CLASS_TO_KEY_MAP.get(entry["_class"]) + if key is None: + continue + name = KEY_TO_NAME_MAP[key] + handle = entry["handle"] + existed = getattr(self, f"has_{name}_handle")(handle) + getattr(self, f"commit_{name}")(data_to_object(server_data), trans) + net_changes[(entry["_class"], handle)] = ( + TXNUPD if existed else TXNADD + ) + finally: + self._pulling = False + self._emit_change_signals(net_changes) + def _handles_by_class(self): """{obj_class: set(handles)} across every primary object type -- the "before" snapshot transaction_begin() stashes on a local diff --git a/GrampsWebApiDb/tests/test_grampswebapidb.py b/GrampsWebApiDb/tests/test_grampswebapidb.py index 1b1c63096..2d7a625d3 100644 --- a/GrampsWebApiDb/tests/test_grampswebapidb.py +++ b/GrampsWebApiDb/tests/test_grampswebapidb.py @@ -43,10 +43,13 @@ # Standard python modules # # ------------------------------------------------------------------------- +import copy import io import json import os +import shutil import sys +import tempfile import time import unittest from urllib.error import HTTPError, URLError @@ -68,9 +71,11 @@ except ImportError as _err: raise unittest.SkipTest("gramps package not available: %s" % _err) +from gramps.gen.db import DbTxn from gramps.gen.db.dbconst import REFERENCE_KEY, TXNADD, TXNDEL, TXNUPD from gramps.gen.db.exceptions import DbConnectionError -from gramps.gen.lib import Person, Tag +from gramps.gen.db.utils import make_database +from gramps.gen.lib import Attribute, Person, Tag from gramps.gen.lib.json_utils import object_to_data, remove_object from GrampsWebApiDb import grampswebapidb @@ -1179,16 +1184,16 @@ def test_update_of_a_still_present_handle_is_merged_with_the_current_object(self self.assertEqual(merge_local.get_gramps_id(), "I0002") self.db.commit_person.assert_called_once_with("MERGED", "TRANS") - def test_refresh_from_server_merges_against_a_direct_fetch_not_the_mirror(self): - # The whole point of refresh_from_server=True: the local mirror - # (has_person_handle/get_person_from_handle) is never consulted - # for the merge decision -- only WebApiHandler.get_object(), a - # direct GET /people/ -- since a resync can be blind to - # what the server actually holds (bulk-imported data never - # touches the transaction-history feed; see the module docstring - # and webapi_client.get_object()'s docstring). - server_data = remove_object(person_data("H1", "I0099")) - self.db.web_client.get_object.return_value = server_data + def test_refresh_from_server_pulls_before_merging(self): + # refresh_from_server=True calls _pull_conflicting_objects() (see + # TestPullConflictingObjects) first, so that by the time this + # merge loop runs, the local mirror it consults is already + # current -- the merge/commit logic below is otherwise identical + # to refresh_from_server=False. + self.db.has_person_handle.return_value = True + current = Person() + current.set_handle("H1") + self.db.get_person_from_handle.return_value = current new_data = remove_object(person_data("H1", "I0002")) payload = [ { @@ -1199,22 +1204,20 @@ def test_refresh_from_server_merges_against_a_direct_fetch_not_the_mirror(self): "new": new_data, } ] - with mock.patch.object(grampswebapidb, "_merge_or_overwrite") as merge_fn: + with mock.patch.object( + self.db, "_pull_conflicting_objects" + ) as pull, mock.patch.object(grampswebapidb, "_merge_or_overwrite") as merge_fn: merge_fn.return_value = "MERGED" self.db._retry_after_conflict(payload, refresh_from_server=True) - self.db.web_client.get_object.assert_called_once_with("Person", "H1") - self.db.has_person_handle.assert_not_called() - self.db.get_person_from_handle.assert_not_called() + pull.assert_called_once_with(payload) merge_current, merge_local = merge_fn.call_args[0] - self.assertEqual(merge_current.get_gramps_id(), "I0099") + self.assertIs(merge_current, current) self.assertIsInstance(merge_local, Person) self.db.commit_person.assert_called_once_with("MERGED", "TRANS") - def test_refresh_from_server_with_no_server_object_commits_as_is(self): - # get_object() returning None (a 404) means the server has - # nothing at this handle to merge against -- same as a true add. - self.db.web_client.get_object.return_value = None - new_data = remove_object(person_data("H1", "I0001")) + def test_refresh_from_server_false_does_not_pull(self): + self.db.has_person_handle.return_value = False + new_data = remove_object(person_data("H1")) payload = [ { "type": "update", @@ -1224,19 +1227,15 @@ def test_refresh_from_server_with_no_server_object_commits_as_is(self): "new": new_data, } ] - with mock.patch.object(grampswebapidb, "_merge_or_overwrite") as merge_fn: - self.db._retry_after_conflict(payload, refresh_from_server=True) - merge_fn.assert_not_called() - self.db.commit_person.assert_called_once() - obj, trans = self.db.commit_person.call_args[0] - self.assertEqual(obj.get_gramps_id(), "I0001") - - def test_refresh_from_server_fetches_before_opening_the_transaction(self): - # A network failure here must fail cleanly with nothing committed - # locally yet -- see _push_payload()'s handling of this, which - # queues the whole payload for later rather than leaving a - # partially-applied transaction. - self.db.web_client.get_object.side_effect = OSError("network down") + with mock.patch.object(self.db, "_pull_conflicting_objects") as pull: + self.db._retry_after_conflict(payload) + pull.assert_not_called() + + def test_pull_failure_propagates_before_any_local_commit(self): + # A network failure pulling fresh server data must fail cleanly + # with nothing committed locally yet -- see _push_payload()'s + # handling of this, which queues the whole payload for later + # rather than leaving a partially-applied transaction. new_data = remove_object(person_data("H1")) payload = [ { @@ -1247,8 +1246,11 @@ def test_refresh_from_server_fetches_before_opening_the_transaction(self): "new": new_data, } ] - with self.assertRaises(OSError): - self.db._retry_after_conflict(payload, refresh_from_server=True) + with mock.patch.object( + self.db, "_pull_conflicting_objects", side_effect=OSError("network down") + ): + with self.assertRaises(OSError): + self.db._retry_after_conflict(payload, refresh_from_server=True) self.db.commit_person.assert_not_called() def test_delete_removes_if_handle_still_present(self): @@ -1335,6 +1337,256 @@ def test_retrying_flag_cleared_even_if_commit_raises(self): self.assertFalse(self.db._retrying) +# ------------------------------------------------------------------------- +# +# TestPullConflictingObjects +# +# _pull_conflicting_objects() -- the refresh_from_server=True half of +# _retry_after_conflict() -- brings the local mirror's copy of each +# conflicting object up to date with a direct GET // read +# (WebApiHandler.get_object()), as a pull-side replay (batch=True, +# _pulling=True, so nothing here gets pushed back out -- see +# TestSyncFromServer for the same pattern), before the retry's own +# merge-and-commit runs. Without this as an actual local write, DBAPI +# would still compute the retry's "old" snapshot from the stale +# pre-conflict mirror -- see the module docstring and +# _retry_after_conflict()'s. +# +# ------------------------------------------------------------------------- +class TestPullConflictingObjects(unittest.TestCase): + def setUp(self): + self.db = new_instance() + self.db.web_client = mock.MagicMock() + self.db.commit_person = mock.MagicMock() + self.db.has_person_handle = mock.MagicMock(return_value=False) + self.db.emit = mock.MagicMock() + dbtxn_patch = mock.patch.object(grampswebapidb, "DbTxn", FakeDbTxn) + dbtxn_patch.start() + self.addCleanup(dbtxn_patch.stop) + + def emitted(self): + return {call.args[0]: call.args[1][0] for call in self.db.emit.call_args_list} + + @staticmethod + def _update_entry(handle="H1"): + return { + "type": "update", + "handle": handle, + "_class": "Person", + "old": None, + "new": {}, + } + + def test_pulls_and_commits_each_entrys_current_server_object(self): + server_data = remove_object(person_data("H1", "I0099")) + self.db.web_client.get_object.return_value = server_data + self.db._pull_conflicting_objects([self._update_entry()]) + self.db.web_client.get_object.assert_called_once_with("Person", "H1") + self.db.commit_person.assert_called_once() + obj, _trans = self.db.commit_person.call_args[0] + self.assertEqual(obj.get_gramps_id(), "I0099") + + def test_existing_handle_emits_update(self): + self.db.web_client.get_object.return_value = remove_object(person_data("H1")) + self.db.has_person_handle.return_value = True + self.db._pull_conflicting_objects([self._update_entry()]) + self.assertEqual(self.emitted(), {"person-update": ["H1"]}) + + def test_new_handle_emits_add(self): + self.db.web_client.get_object.return_value = remove_object(person_data("H1")) + self.db.has_person_handle.return_value = False + self.db._pull_conflicting_objects([self._update_entry()]) + self.assertEqual(self.emitted(), {"person-add": ["H1"]}) + + def test_delete_entries_are_never_fetched_or_pulled(self): + payload = [ + { + "type": "delete", + "handle": "H1", + "_class": "Person", + "old": {}, + "new": None, + } + ] + self.db._pull_conflicting_objects(payload) + self.db.web_client.get_object.assert_not_called() + self.db.commit_person.assert_not_called() + + def test_missing_server_object_is_skipped(self): + # get_object() returning None (a 404): nothing to pull in -- + # _retry_after_conflict()'s own has_handle()/commit_() + # already do the right thing for a handle absent from the mirror. + self.db.web_client.get_object.return_value = None + self.db._pull_conflicting_objects([self._update_entry()]) + self.db.commit_person.assert_not_called() + self.db.emit.assert_not_called() + + def test_unrecognized_class_is_skipped(self): + payload = [ + { + "type": "update", + "handle": "H1", + "_class": "NotAThing", + "old": None, + "new": {}, + } + ] + self.db.web_client.get_object.return_value = {} + self.db._pull_conflicting_objects(payload) # must not raise + self.db.commit_person.assert_not_called() + + def test_all_fetches_happen_before_any_local_commit(self): + self.db.web_client.get_object.side_effect = [ + remove_object(person_data("H1")), + OSError("network down"), + ] + payload = [self._update_entry("H1"), self._update_entry("H2")] + with self.assertRaises(OSError): + self.db._pull_conflicting_objects(payload) + self.db.commit_person.assert_not_called() + + def test_pulling_flag_set_during_and_cleared_after(self): + self.db.web_client.get_object.return_value = remove_object(person_data("H1")) + seen = {} + + def check_flag(obj, trans): + seen["during"] = self.db._pulling + + self.db.commit_person.side_effect = check_flag + self.db._pull_conflicting_objects([self._update_entry()]) + self.assertTrue(seen["during"]) + self.assertFalse(self.db._pulling) + + def test_pulling_flag_cleared_even_if_a_commit_raises(self): + self.db.web_client.get_object.return_value = remove_object(person_data("H1")) + self.db.commit_person.side_effect = RuntimeError("boom") + with self.assertRaises(RuntimeError): + self.db._pull_conflicting_objects([self._update_entry()]) + self.assertFalse(self.db._pulling) + + +# ------------------------------------------------------------------------- +# +# TestConflictRetryAgainstARealDatabase +# +# Every test above stubs out commit_person/has_person_handle/get_person_ +# from_handle as independent mocks, which cannot catch a bug where +# _pull_conflicting_objects()'s write and the later merge step's read of +# "the current object" disagree -- exactly the shape of bug this fix was +# written for: an earlier version merged get_object()'s result in memory +# without ever writing it into the local mirror, so DBAPI's own "old"- +# snapshot capture (which reads straight from local storage at commit +# time, with no awareness of get_object() at all -- see _commit_base()) +# kept sending the same stale pre-conflict "old" on the retry and got +# rejected again, identically, even though the retry's "new" was +# correctly merged. This class runs against a real (temp-directory) +# SQLite-backed database and real DbTxn/transaction_commit machinery -- +# only the network layer (web_client) is mocked -- so it actually +# exercises that interaction end to end. +# +# ------------------------------------------------------------------------- +class TestConflictRetryAgainstARealDatabase(unittest.TestCase): + def setUp(self): + tmpdir = tempfile.mkdtemp(prefix="grampswebapidb_test_") + self.addCleanup(shutil.rmtree, tmpdir, ignore_errors=True) + db = make_database("sqlite") + db.load(tmpdir) + with DbTxn("seed", db) as trans: + person = Person() + person.set_gramps_id("I0001") + db.add_person(person, trans) + self.handle = person.handle + # Reclassify the real, already-initialized SQLite-backed db as a + # WebApiDB, rather than going through its network-dependent + # load() -- this addon has no per-tree settings.ini (see the + # module docstring), so nothing else ties identity to a server, + # and this is the minimal way to run its push/retry logic against + # a real DBAPI backend. + db.__class__ = WebApiDB + db.web_client = mock.MagicMock() + db._syncing = False + db._retrying = False + db._pulling = False + db._get_metadata = lambda key, default=0: default + db._set_metadata = lambda key, value, use_txn=True: None + db.web_client.get_transaction_history.return_value = ([], 0) + db.web_client.get_object_count.return_value = 1 + db.web_client.supports_background_transactions.return_value = False + self.db = db + self.addCleanup(self.db.close) + + def _make_server_fresh(self): + """The server's true current state for self.handle, diverged from + the local mirror's stale copy (private=False -> True) via a route + this addon's history feed cannot see -- see + _pull_conflicting_objects()'s docstring.""" + server_fresh = copy.deepcopy( + remove_object(object_to_data(self.db.get_person_from_handle(self.handle))) + ) + server_fresh["private"] = True + return server_fresh + + def _push_conflicts_once_then_succeeds(self): + calls = [] + + def fake_push(payload, undo=False, background=False, on_wait=None): + calls.append(copy.deepcopy(payload)) + if len(calls) == 1: + raise WebApiPushConflict("Object has changed") + + self.db.web_client.push_transaction.side_effect = fake_push + return calls + + def _add_an_attribute(self): + with DbTxn("edit", self.db) as trans: + person = self.db.get_person_from_handle(self.handle) + attr = Attribute() + attr.set_type("Occupation") + attr.set_value("Tester") + person.add_attribute(attr) + self.db.commit_person(person, trans) + + def test_retry_pushes_the_fetched_object_as_old_not_the_stale_mirror(self): + stale_local = remove_object( + object_to_data(self.db.get_person_from_handle(self.handle)) + ) + server_fresh = self._make_server_fresh() + self.db.web_client.get_object.return_value = server_fresh + calls = self._push_conflicts_once_then_succeeds() + + self._add_an_attribute() + + self.assertEqual(len(calls), 2) + # The original push sent the stale local snapshot -- that's what + # the server rejected. + self.assertEqual(calls[0][0]["old"], stale_local) + # The retry must send the *fetched* server state as "old", not + # the same stale value again -- otherwise it is guaranteed to + # conflict identically and the edit is dropped for good (see + # _push_payload()'s "give up after a repeated conflict" branch). + self.assertEqual(calls[1][0]["old"], server_fresh) + # "new" is the merge of that fresh state with the local edit's + # actual intent, not a blind overwrite of either side. + self.assertTrue(calls[1][0]["new"]["private"]) + self.assertTrue( + any(a["value"] == "Tester" for a in calls[1][0]["new"]["attribute_list"]) + ) + + def test_conflict_resolves_without_being_dropped(self): + # Same setup, phrased as an outcome: the local mirror ends up + # holding the merged result, and the edit was not dropped after + # only its first, correctly-rejected attempt. + self.db.web_client.get_object.return_value = self._make_server_fresh() + calls = self._push_conflicts_once_then_succeeds() + + self._add_an_attribute() + + self.assertEqual(len(calls), 2) + final = self.db.get_person_from_handle(self.handle) + self.assertTrue(final.get_privacy()) + self.assertEqual(len(final.get_attribute_list()), 1) + + # ------------------------------------------------------------------------- # # TestMergeOrOverwrite From 8e21ed72d54b5a408101d08a9783a770ec5157ed Mon Sep 17 00:00:00 2001 From: Doug Blank Date: Sun, 16 Aug 2026 10:05:15 -0700 Subject: [PATCH 10/13] GrampsWebApiDb: fix conflict retry crashing on the fetched object's shape The previous fix (03b5d1ef1) fetched the conflicting object fresh via GET // before retrying, but that REST endpoint returns gramps-web-api's own display serialization (a __dict__ walk with no "_class" tag on GrampsType fields), not the gramps.gen.lib.json_utils shape data_to_object() needs to reconstruct a Gramps object. Feeding it that shape raised KeyError: '_class' -- caught by the broad _CONNECTION_ERRORS handler (which intentionally includes KeyError/ ValueError for malformed responses) and misreported as a connectivity problem, so the payload was queued, retried, failed identically, and silently dropped. Confirmed against Gary Griffin's latest debug log against demo.grampsweb.org. Only two things produce the shape data_to_object() needs: the transaction-history feed's new_data, and a raw Gramps XML export (the same fact _full_resync() was already built around). So the retry path now does a full resync (_resync_after_conflict(), reusing _full_resync()) instead of a per-object REST fetch before replaying the local edit -- more expensive, but it's the only server round-trip that reliably produces data in the shape the retry can safely build an "old" snapshot from. Verified against a real DBAPI-backed database exercising the actual commit/push machinery, with a fake XML export standing in for the server, reproducing Gary's exact scenario end to end. Removed WebApiHandler.get_object()/CLASS_TO_ENDPOINT from webapi_client.py along with it -- provably the wrong tool for this job. --- GrampsWebApiDb/grampswebapidb.py | 251 ++++++-------- GrampsWebApiDb/tests/test_grampswebapidb.py | 354 ++++++-------------- GrampsWebApiDb/tests/test_webapi_client.py | 75 ----- GrampsWebApiDb/webapi_client.py | 50 --- 4 files changed, 222 insertions(+), 508 deletions(-) diff --git a/GrampsWebApiDb/grampswebapidb.py b/GrampsWebApiDb/grampswebapidb.py index 4184aba1c..5c8b7f100 100644 --- a/GrampsWebApiDb/grampswebapidb.py +++ b/GrampsWebApiDb/grampswebapidb.py @@ -130,42 +130,43 @@ coarse, optimistic-concurrency check: the whole push either applies or none of it does, with no indication of which item conflicted. -Neither side of this addon's own resync machinery can be trusted to -explain a conflict, and this is not a one-server edge case: gramps-web- -api's bulk-import path (POST /importers//file -- GEDCOM, Gramps -XML, CSV, ...) runs the same batch=True import machinery a local Gramps -client's own Import menu action would, which never touches its -transaction-history table at all (DBAPI's own _commit_base() only calls -trans.add() when `not trans.batch`) -- ordinary server administration -for any real installation, not a quirk of any particular one. So: the -incremental history feed can be blind to an object's true current state -from the moment it was imported, and even this addon's own full-tree -resync (_full_resync(), the verify_totals=True fallback below and -load()'s) only proves the mirror was accurate at the moment its export -was taken -- seconds to tens of seconds before the retry actually goes -out, plenty of time for another push (through the API, so it would -appear in history) to land in between. - -So: on a conflict, _push_payload() below resyncs from the server (with -verify_totals=True, the same defense load() uses, for its own sake -- -other objects may genuinely have changed) and then, for a plain commit -(not an undo/redo -- see _retry_after_conflict()), pulls each entry's -object fresh with its own direct GET // -(WebApiHandler.get_object(), via _pull_conflicting_objects()) *into the -local mirror* before replaying the intended *new* state as a fresh local -edit via commit_()/remove_(). That local write, not just a -fresher value read into memory, is what matters: DBAPI computes the -retry's own "old" snapshot from whatever is actually stored locally at -commit time, with no awareness of anything read here -- so unless the -mirror itself is caught up first, the retry would push the same stale -"old" as the original failed push and be rejected again identically, no -matter how correct its "new" was. That fresh edit goes through the -normal transaction_commit() -> _push_payload() path again with -is_retry=True, so it now carries an "old" snapshot matching what was -just pulled, and will only be rejected a second time if something -changes server-side in the brief window since then -- in which case it -is logged and dropped rather than retried again, to avoid retrying -forever against a genuinely hot object. +The incremental history feed can't be trusted to explain a conflict, and +this is not a one-server edge case: gramps-web-api's bulk-import path +(POST /importers//file -- GEDCOM, Gramps XML, CSV, ...) runs the +same batch=True import machinery a local Gramps client's own Import menu +action would, which never touches its transaction-history table at all +(DBAPI's own _commit_base() only calls trans.add() when `not +trans.batch`) -- ordinary server administration for any real +installation, not a quirk of any particular one. So the incremental +history feed can be blind to an object's true current state from the +moment it was imported, indefinitely -- and a totals comparison +(_mirror_is_short_of_the_server(), the verify_totals check load() and +_sync_from_server() use elsewhere) can't catch this either, since the +object count doesn't change when an already-known object's content +changes server-side, only when objects are added or removed. + +A per-object fix was tried and doesn't work: gramps-web-api's REST +single-object endpoints (GET //) serialize with +GrampsJSONEncoder.extract_object() (gramps_webapi/api/resources/ +emit.py) -- a walk of the object's own __dict__/properties for the +frontend's display schema, with no "_class" tag on GrampsType-derived +fields -- not the gramps.gen.lib.json_utils shape data_to_object() +needs to reconstruct a Gramps object; feeding it that shape raises +KeyError. Only two things produce the compatible shape: the +transaction-history feed's new_data, and a raw Gramps XML export (see +_full_resync()). So on a conflict, _push_payload() below does a full +resync (_resync_after_conflict(), reusing _full_resync()) -- expensive, +but the only server round-trip that reliably brings the local mirror +back to the server's true current state for whatever this push touched +-- and then, for a plain commit (not an undo/redo -- see +_retry_after_conflict()), replays the intended *new* state as a fresh +local edit via commit_()/remove_(). That fresh edit goes +through the normal transaction_commit() -> _push_payload() path again +with is_retry=True, so it now carries an "old" snapshot matching the +just-resynced mirror, and will only be rejected a second time if +something changes server-side in the brief window since the resync ran +-- in which case it is logged and dropped rather than retried again, to +avoid retrying forever against a genuinely hot object. For an add/update whose object still exists server-side (i.e. the conflicting edit changed the same object rather than deleting it), @@ -1245,20 +1246,16 @@ def _push_payload(self, payload, undo=False, is_retry=False): len(payload), ) try: - # verify_totals=True, same as load(): a conflict can be - # caused by a server-side change the incremental history - # feed cannot describe at all -- a bulk import runs - # entirely outside gramps-web-api's own transaction log - # (see webapi_client.get_object()'s docstring), ordinary - # server administration rather than an edge case -- as - # easily as by an ordinary edit the feed would replay - # normally. Without this, that resync can come back - # describing nothing relevant either way; it is still - # worth doing for its own sake (other objects may - # genuinely have changed), just not trusted on its own - # for the object(s) in this payload -- see - # _retry_after_conflict()'s refresh_from_server below. - self._sync_from_server(verify_totals=True) + # A full resync, not the incremental history feed: a + # conflict can be caused by a server-side change the + # history feed cannot describe at all -- a bulk import + # runs entirely outside gramps-web-api's own transaction + # log (see _resync_after_conflict()'s docstring), ordinary + # server administration rather than an edge case -- and a + # totals check can't catch a content-only change to an + # already-known object either. See _resync_after_conflict() + # for why nothing cheaper is trustworthy here. + self._resync_after_conflict() except _DatabaseClosed: LOG.debug("push: tree closed during conflict resync; abandoning it") return @@ -1274,15 +1271,20 @@ def _push_payload(self, payload, undo=False, is_retry=False): ) return try: - self._retry_after_conflict(payload, refresh_from_server=True) + self._retry_after_conflict(payload) except _CONNECTION_ERRORS as err: - # Nothing has been committed locally yet at this point -- - # see _retry_after_conflict()'s docstring -- so this is a - # plain connectivity failure, queued like any other. + # _retry_after_conflict()'s own DbTxn body (data_to_object(), + # commit_(), the merge) is what can raise here -- its + # nested transaction_commit() -> _push_payload() call + # handles a rejected push itself and does not re-raise, so + # reaching this except means the DbTxn body never finished + # and aborted without committing. Nothing local to lose; + # queue the original payload the same as any other + # connectivity failure. LOG.warning( - "Could not fetch current server data for %d local " - "change(s) after a conflict (%s); queued for retry on " - "the next successful contact with the server.", + "Could not replay %d local change(s) after a conflict " + "(%s); queued for retry on the next successful contact " + "with the server.", len(payload), err, ) @@ -1405,41 +1407,33 @@ def _flush_pending_pushes(self): self._set_metadata("pending_pushes", pending) LOG.debug("queue: %d push(es) still pending after the flush", len(pending)) - def _retry_after_conflict(self, payload, refresh_from_server=False): + def _retry_after_conflict(self, payload): """Reapply each locally-intended change as a fresh local edit -- see the module docstring's write-through section. An add/update whose object still exists is combined with the current object via _merge_or_overwrite() rather than blindly replacing it. - refresh_from_server, set only by _push_payload()'s conflict - handler, first calls _pull_conflicting_objects() to bring the - local mirror's copy of each entry's object up to date with a - direct GET // read, *before* anything below runs. - That has to be an actual local write, not just a fresher value - used in memory for the merge: DBAPI computes this retry's own - "old" snapshot from whatever is stored locally at commit time - (_commit_base()'s _get_raw_data() call, entirely independent of - what get_object() returned) -- so unless the mirror itself is - caught up first, the retry below would still push the stale - pre-conflict "old" and be rejected again identically, even though - its "new" reflected correct data. See _pull_conflicting_objects() - for why the local mirror (and even this addon's own full-tree - resync) cannot be trusted to have already done this. - - _reconcile_batch_commit()'s call leaves this off -- replaying a - local batch operation's own changes as a first push, not - recovering from a conflict, so there is nothing to pull yet, and - fetching every entry individually would cost one request per - object for what can be a large batch. + Callers are responsible for making sure the local mirror already + holds the server's true current state for whatever this payload + touches, *before* this runs: DBAPI computes this retry's own "old" + snapshot from whatever is stored locally at commit time + (_commit_base()'s _get_raw_data() call), so a stale mirror means + the retry pushes the same stale "old" as the original failed push + and is rejected again identically, no matter how correct its + "new" is. _push_payload()'s conflict handler does this with a + full resync (_resync_after_conflict()) before calling here; see + that method's docstring for why nothing cheaper is trustworthy. + _reconcile_batch_commit()'s call needs no such refresh -- it is + replaying a local batch operation's own just-committed changes, + not recovering from a conflict. Runs as one ordinary (non-batch) DbTxn, so it goes through the normal transaction_commit() -> _push_payload() path again -- this - time with an "old" snapshot that matches what was just pulled, so - it will only be rejected again if something else changed - server-side in the brief window since then. + time with an "old" snapshot that matches the local mirror's + current (freshly-resynced, for the conflict path) state, so it + will only be rejected again if something else changed server-side + in the brief window since then. """ - if refresh_from_server: - self._pull_conflicting_objects(payload) self._retrying = True try: with DbTxn(_("Retry local change after server conflict"), self) as trans: @@ -1462,66 +1456,43 @@ def _retry_after_conflict(self, payload, refresh_from_server=False): finally: self._retrying = False - def _pull_conflicting_objects(self, payload): - """Bring the local mirror's copy of each non-delete ``payload`` - entry's object up to date with a direct GET // read - (WebApiHandler.get_object()) -- a pull-side replay, like - _sync_from_server()'s own (batch=True, _pulling=True, so nothing - here gets pushed back out -- see the module docstring), not a - local edit. - - Neither the incremental history feed nor even a full-tree resync - can be trusted to have already done this for the object(s) a push - just conflicted on: gramps-web-api's bulk-import path (POST - /importers//file -- GEDCOM, Gramps XML, CSV, ...) runs the - same batch=True import machinery a local Gramps client's own - Import menu action would, which never touches the transaction- - history table at all (see get_object()'s docstring) -- ordinary - server administration for any real installation, not a quirk of - one server -- and a full-tree resync only proves the mirror was - accurate at the moment its export was taken, seconds to tens of - seconds before _retry_after_conflict() actually commits. A direct - per-object read is the one thing this addon can ask the server - that is authoritative regardless of how the object got to its - current state. - - Every GET happens before the DbTxn below opens, all at once -- so - a network failure here (propagated to _push_payload(), which - queues the whole payload for a later retry) leaves nothing - committed locally yet, rather than a partially-applied batch. - - A handle the server no longer has (get_object() returns None -- - deleted, or never existed) is left untouched: nothing to pull in, - and _retry_after_conflict()'s own has_handle()/commit_() - already do the right thing for a handle absent from the mirror. + def _resync_after_conflict(self): + """Rebuild the local mirror from a fresh server export + (_full_resync()) before a conflict retry -- called by + _push_payload()'s WebApiPushConflict handler in place of an + incremental _sync_from_server(). Neither the incremental history + feed nor a totals check is trustworthy here: gramps-web-api's + bulk-import path (POST /importers//file -- GEDCOM, Gramps + XML, CSV, ...) runs the same batch=True import machinery a local + Gramps client's own Import menu action would, which never touches + the transaction-history table at all (see the module docstring), + so the incremental feed can be blind to an object's true current + state indefinitely -- ordinary server administration for any real + installation, not a quirk of one server. A totals comparison + doesn't catch this either: the object count doesn't change when + an already-known object's content changes server-side, only when + objects are added or removed, so a conflict caused by a content + edit on a bulk-imported object leaves totals matching on both + sides even though the mirror's copy of that object is stale. + + A per-object REST fetch (GET //) was tried here + first and doesn't work: gramps-web-api's single-object endpoints + serialize with GrampsJSONEncoder.extract_object() (a walk of the + object's own __dict__/properties for the frontend's display + schema -- no "_class" tag on GrampsType-derived fields), not the + gramps.gen.lib.json_utils shape data_to_object() requires to + reconstruct a Gramps object. Only two things produce that + compatible shape: the transaction-history feed's new_data, and a + raw Gramps XML export -- see _full_resync()'s own docstring. So a + full resync, expensive as it is, is the only server round-trip + that can bring the local mirror back into a state + _retry_after_conflict() can safely build an "old" snapshot from. """ - fresh = {} - for entry in payload: - if entry["type"] != "delete": - fresh[entry["handle"]] = self.web_client.get_object( - entry["_class"], entry["handle"] - ) - net_changes = {} - self._pulling = True + self._syncing = True try: - with DbTxn(_("Refresh before conflict retry"), self, batch=True) as trans: - for entry in payload: - server_data = fresh.get(entry["handle"]) - if server_data is None: - continue - key = CLASS_TO_KEY_MAP.get(entry["_class"]) - if key is None: - continue - name = KEY_TO_NAME_MAP[key] - handle = entry["handle"] - existed = getattr(self, f"has_{name}_handle")(handle) - getattr(self, f"commit_{name}")(data_to_object(server_data), trans) - net_changes[(entry["_class"], handle)] = ( - TXNUPD if existed else TXNADD - ) + self._full_resync() finally: - self._pulling = False - self._emit_change_signals(net_changes) + self._syncing = False def _handles_by_class(self): """{obj_class: set(handles)} across every primary object type -- diff --git a/GrampsWebApiDb/tests/test_grampswebapidb.py b/GrampsWebApiDb/tests/test_grampswebapidb.py index 2d7a625d3..6a416fba2 100644 --- a/GrampsWebApiDb/tests/test_grampswebapidb.py +++ b/GrampsWebApiDb/tests/test_grampswebapidb.py @@ -76,7 +76,7 @@ from gramps.gen.db.exceptions import DbConnectionError from gramps.gen.db.utils import make_database from gramps.gen.lib import Attribute, Person, Tag -from gramps.gen.lib.json_utils import object_to_data, remove_object +from gramps.gen.lib.json_utils import data_to_object, object_to_data, remove_object from GrampsWebApiDb import grampswebapidb from GrampsWebApiDb.grampswebapidb import ( @@ -982,8 +982,8 @@ def test_push_swallows_database_closed_mid_push(self): def test_conflict_triggers_resync_then_retry(self): # A WebApiPushConflict means the server rejected the whole batch # because something changed server-side since the local mirror's - # snapshot -- the response is to resync from the server and then - # retry the local edit on top of that fresh data (see + # snapshot -- the response is to do a full resync from the server + # and then retry the local edit on top of that fresh data (see # _retry_after_conflict()), not to propagate the exception (the # local commit already happened). trans = FakeTransaction([(0, TXNADD, "H1", None, person_data("H1"))]) @@ -992,20 +992,19 @@ def test_conflict_triggers_resync_then_retry(self): ) with mock.patch.object( grampswebapidb.SQLite, "transaction_commit" - ), mock.patch.object(self.db, "_sync_from_server") as resync, mock.patch.object( + ), mock.patch.object( + self.db, "_resync_after_conflict" + ) as resync, mock.patch.object( self.db, "_retry_after_conflict" ) as retry: with self.assertLogs(grampswebapidb.LOG, level="WARNING"): self.db.transaction_commit(trans) # must not raise - # verify_totals=True, same as load(): a conflict can be the - # untracked-server-change blind spot _mirror_is_short_of_the_ - # server() exists for, not just an ordinary edit the incremental - # feed would replay -- see the module docstring. - resync.assert_called_once_with(verify_totals=True) - # refresh_from_server=True: merge against a direct per-object - # fetch, not the mirror the resync above may not have been able - # to update for this exact object -- see _retry_after_conflict(). - retry.assert_called_once_with(mock.ANY, refresh_from_server=True) + # A full resync, not the incremental history feed or a totals + # check -- neither can see a content-only change to an + # already-known, bulk-imported object -- see the module + # docstring and _resync_after_conflict(). + resync.assert_called_once_with() + retry.assert_called_once_with(mock.ANY) payload = retry.call_args[0][0] self.assertEqual(payload[0]["handle"], "H1") @@ -1018,9 +1017,13 @@ def test_conflict_resync_failure_is_also_swallowed(self): grampswebapidb.SQLite, "transaction_commit" ), mock.patch.object( self.db, - "_sync_from_server", + "_resync_after_conflict", side_effect=HTTPError( - "https://example.com/api/transactions/history/", 500, "boom", None, None + "https://example.com/api/exporters/gramps/file", + 500, + "boom", + None, + None, ), ), mock.patch.object( self.db, "_retry_after_conflict" @@ -1031,19 +1034,20 @@ def test_conflict_resync_failure_is_also_swallowed(self): # server, so retrying the edit on top of it would be pointless. retry.assert_not_called() - def test_retry_fetch_failure_is_queued_not_dropped(self): - # _retry_after_conflict(refresh_from_server=True) fetches each - # entry fresh before committing anything locally -- a network - # failure there is a plain connectivity problem, not a conflict, - # so the payload is queued for later like any other push that - # couldn't be delivered (see TestPendingPushQueue), not dropped. + def test_retry_failure_is_queued_not_dropped(self): + # A failure inside _retry_after_conflict() itself (its DbTxn body + # never finished, so nothing committed locally -- see + # _push_payload()'s handling of this) is a plain connectivity- + # shaped problem, not a conflict, so the payload is queued for + # later like any other push that couldn't be delivered (see + # TestPendingPushQueue), not dropped. trans = FakeTransaction([(0, TXNADD, "H1", None, person_data("H1"))]) self.db.web_client.push_transaction.side_effect = WebApiPushConflict( "Object has changed" ) with mock.patch.object( grampswebapidb.SQLite, "transaction_commit" - ), mock.patch.object(self.db, "_sync_from_server"), mock.patch.object( + ), mock.patch.object(self.db, "_resync_after_conflict"), mock.patch.object( self.db, "_retry_after_conflict", side_effect=OSError("network down"), @@ -1063,7 +1067,9 @@ def test_conflict_resync_database_closed_is_also_swallowed(self): with mock.patch.object( grampswebapidb.SQLite, "transaction_commit" ), mock.patch.object( - self.db, "_sync_from_server", side_effect=grampswebapidb._DatabaseClosed + self.db, + "_resync_after_conflict", + side_effect=grampswebapidb._DatabaseClosed, ), mock.patch.object( self.db, "_retry_after_conflict" ) as retry: @@ -1080,14 +1086,16 @@ def test_repeated_conflict_on_a_retry_is_not_retried_again(self): ) with mock.patch.object( grampswebapidb.SQLite, "transaction_commit" - ), mock.patch.object(self.db, "_sync_from_server") as resync, mock.patch.object( + ), mock.patch.object( + self.db, "_resync_after_conflict" + ) as resync, mock.patch.object( self.db, "_retry_after_conflict" ) as retry: with self.assertLogs(grampswebapidb.LOG, level="WARNING"): self.db._push_payload( transaction_to_json(trans), is_retry=True ) # must not raise - resync.assert_called_once_with(verify_totals=True) + resync.assert_called_once_with() retry.assert_not_called() def test_undo_conflict_is_not_retried(self): @@ -1101,15 +1109,53 @@ def test_undo_conflict_is_not_retried(self): ) with mock.patch.object( grampswebapidb.SQLite, "transaction_commit" - ), mock.patch.object(self.db, "_sync_from_server") as resync, mock.patch.object( + ), mock.patch.object( + self.db, "_resync_after_conflict" + ) as resync, mock.patch.object( self.db, "_retry_after_conflict" ) as retry: with self.assertLogs(grampswebapidb.LOG, level="WARNING"): self.db._push_payload(transaction_to_json(trans), undo=True) - resync.assert_called_once_with(verify_totals=True) + resync.assert_called_once_with() retry.assert_not_called() +# ------------------------------------------------------------------------- +# +# TestResyncAfterConflict +# +# _resync_after_conflict() wraps _full_resync() -- not the incremental +# _sync_from_server() -- with the same _syncing bookkeeping +# _sync_from_server() and _sync_media_files() do around their own bodies, +# so a poll tick landing mid-resync skips its turn instead of starting a +# second sync underneath this one. See the module docstring and this +# method's own docstring for why a full resync, not the cheaper +# incremental feed or a totals check, is what a conflict retry needs. +# +# ------------------------------------------------------------------------- +class TestResyncAfterConflict(unittest.TestCase): + def setUp(self): + self.db = new_instance() + self.db._full_resync = mock.MagicMock() + + def test_delegates_to_full_resync(self): + self.db._resync_after_conflict() + self.db._full_resync.assert_called_once_with() + + def test_syncing_flag_is_set_during_and_cleared_after(self): + seen = [] + self.db._full_resync.side_effect = lambda: seen.append(self.db._syncing) + self.db._resync_after_conflict() + self.assertEqual(seen, [True]) + self.assertFalse(self.db._syncing) + + def test_syncing_flag_is_cleared_even_if_the_resync_raises(self): + self.db._full_resync.side_effect = OSError("down") + with self.assertRaises(OSError): + self.db._resync_after_conflict() + self.assertFalse(self.db._syncing) + + # ------------------------------------------------------------------------- # # TestRetryAfterConflict @@ -1184,75 +1230,6 @@ def test_update_of_a_still_present_handle_is_merged_with_the_current_object(self self.assertEqual(merge_local.get_gramps_id(), "I0002") self.db.commit_person.assert_called_once_with("MERGED", "TRANS") - def test_refresh_from_server_pulls_before_merging(self): - # refresh_from_server=True calls _pull_conflicting_objects() (see - # TestPullConflictingObjects) first, so that by the time this - # merge loop runs, the local mirror it consults is already - # current -- the merge/commit logic below is otherwise identical - # to refresh_from_server=False. - self.db.has_person_handle.return_value = True - current = Person() - current.set_handle("H1") - self.db.get_person_from_handle.return_value = current - new_data = remove_object(person_data("H1", "I0002")) - payload = [ - { - "type": "update", - "handle": "H1", - "_class": "Person", - "old": None, - "new": new_data, - } - ] - with mock.patch.object( - self.db, "_pull_conflicting_objects" - ) as pull, mock.patch.object(grampswebapidb, "_merge_or_overwrite") as merge_fn: - merge_fn.return_value = "MERGED" - self.db._retry_after_conflict(payload, refresh_from_server=True) - pull.assert_called_once_with(payload) - merge_current, merge_local = merge_fn.call_args[0] - self.assertIs(merge_current, current) - self.assertIsInstance(merge_local, Person) - self.db.commit_person.assert_called_once_with("MERGED", "TRANS") - - def test_refresh_from_server_false_does_not_pull(self): - self.db.has_person_handle.return_value = False - new_data = remove_object(person_data("H1")) - payload = [ - { - "type": "update", - "handle": "H1", - "_class": "Person", - "old": None, - "new": new_data, - } - ] - with mock.patch.object(self.db, "_pull_conflicting_objects") as pull: - self.db._retry_after_conflict(payload) - pull.assert_not_called() - - def test_pull_failure_propagates_before_any_local_commit(self): - # A network failure pulling fresh server data must fail cleanly - # with nothing committed locally yet -- see _push_payload()'s - # handling of this, which queues the whole payload for later - # rather than leaving a partially-applied transaction. - new_data = remove_object(person_data("H1")) - payload = [ - { - "type": "update", - "handle": "H1", - "_class": "Person", - "old": None, - "new": new_data, - } - ] - with mock.patch.object( - self.db, "_pull_conflicting_objects", side_effect=OSError("network down") - ): - with self.assertRaises(OSError): - self.db._retry_after_conflict(payload, refresh_from_server=True) - self.db.commit_person.assert_not_called() - def test_delete_removes_if_handle_still_present(self): self.db.has_person_handle.return_value = True payload = [ @@ -1337,152 +1314,25 @@ def test_retrying_flag_cleared_even_if_commit_raises(self): self.assertFalse(self.db._retrying) -# ------------------------------------------------------------------------- -# -# TestPullConflictingObjects -# -# _pull_conflicting_objects() -- the refresh_from_server=True half of -# _retry_after_conflict() -- brings the local mirror's copy of each -# conflicting object up to date with a direct GET // read -# (WebApiHandler.get_object()), as a pull-side replay (batch=True, -# _pulling=True, so nothing here gets pushed back out -- see -# TestSyncFromServer for the same pattern), before the retry's own -# merge-and-commit runs. Without this as an actual local write, DBAPI -# would still compute the retry's "old" snapshot from the stale -# pre-conflict mirror -- see the module docstring and -# _retry_after_conflict()'s. -# -# ------------------------------------------------------------------------- -class TestPullConflictingObjects(unittest.TestCase): - def setUp(self): - self.db = new_instance() - self.db.web_client = mock.MagicMock() - self.db.commit_person = mock.MagicMock() - self.db.has_person_handle = mock.MagicMock(return_value=False) - self.db.emit = mock.MagicMock() - dbtxn_patch = mock.patch.object(grampswebapidb, "DbTxn", FakeDbTxn) - dbtxn_patch.start() - self.addCleanup(dbtxn_patch.stop) - - def emitted(self): - return {call.args[0]: call.args[1][0] for call in self.db.emit.call_args_list} - - @staticmethod - def _update_entry(handle="H1"): - return { - "type": "update", - "handle": handle, - "_class": "Person", - "old": None, - "new": {}, - } - - def test_pulls_and_commits_each_entrys_current_server_object(self): - server_data = remove_object(person_data("H1", "I0099")) - self.db.web_client.get_object.return_value = server_data - self.db._pull_conflicting_objects([self._update_entry()]) - self.db.web_client.get_object.assert_called_once_with("Person", "H1") - self.db.commit_person.assert_called_once() - obj, _trans = self.db.commit_person.call_args[0] - self.assertEqual(obj.get_gramps_id(), "I0099") - - def test_existing_handle_emits_update(self): - self.db.web_client.get_object.return_value = remove_object(person_data("H1")) - self.db.has_person_handle.return_value = True - self.db._pull_conflicting_objects([self._update_entry()]) - self.assertEqual(self.emitted(), {"person-update": ["H1"]}) - - def test_new_handle_emits_add(self): - self.db.web_client.get_object.return_value = remove_object(person_data("H1")) - self.db.has_person_handle.return_value = False - self.db._pull_conflicting_objects([self._update_entry()]) - self.assertEqual(self.emitted(), {"person-add": ["H1"]}) - - def test_delete_entries_are_never_fetched_or_pulled(self): - payload = [ - { - "type": "delete", - "handle": "H1", - "_class": "Person", - "old": {}, - "new": None, - } - ] - self.db._pull_conflicting_objects(payload) - self.db.web_client.get_object.assert_not_called() - self.db.commit_person.assert_not_called() - - def test_missing_server_object_is_skipped(self): - # get_object() returning None (a 404): nothing to pull in -- - # _retry_after_conflict()'s own has_handle()/commit_() - # already do the right thing for a handle absent from the mirror. - self.db.web_client.get_object.return_value = None - self.db._pull_conflicting_objects([self._update_entry()]) - self.db.commit_person.assert_not_called() - self.db.emit.assert_not_called() - - def test_unrecognized_class_is_skipped(self): - payload = [ - { - "type": "update", - "handle": "H1", - "_class": "NotAThing", - "old": None, - "new": {}, - } - ] - self.db.web_client.get_object.return_value = {} - self.db._pull_conflicting_objects(payload) # must not raise - self.db.commit_person.assert_not_called() - - def test_all_fetches_happen_before_any_local_commit(self): - self.db.web_client.get_object.side_effect = [ - remove_object(person_data("H1")), - OSError("network down"), - ] - payload = [self._update_entry("H1"), self._update_entry("H2")] - with self.assertRaises(OSError): - self.db._pull_conflicting_objects(payload) - self.db.commit_person.assert_not_called() - - def test_pulling_flag_set_during_and_cleared_after(self): - self.db.web_client.get_object.return_value = remove_object(person_data("H1")) - seen = {} - - def check_flag(obj, trans): - seen["during"] = self.db._pulling - - self.db.commit_person.side_effect = check_flag - self.db._pull_conflicting_objects([self._update_entry()]) - self.assertTrue(seen["during"]) - self.assertFalse(self.db._pulling) - - def test_pulling_flag_cleared_even_if_a_commit_raises(self): - self.db.web_client.get_object.return_value = remove_object(person_data("H1")) - self.db.commit_person.side_effect = RuntimeError("boom") - with self.assertRaises(RuntimeError): - self.db._pull_conflicting_objects([self._update_entry()]) - self.assertFalse(self.db._pulling) - - # ------------------------------------------------------------------------- # # TestConflictRetryAgainstARealDatabase # # Every test above stubs out commit_person/has_person_handle/get_person_ # from_handle as independent mocks, which cannot catch a bug where -# _pull_conflicting_objects()'s write and the later merge step's read of +# _resync_after_conflict()'s write and the later merge step's read of # "the current object" disagree -- exactly the shape of bug this fix was -# written for: an earlier version merged get_object()'s result in memory -# without ever writing it into the local mirror, so DBAPI's own "old"- -# snapshot capture (which reads straight from local storage at commit -# time, with no awareness of get_object() at all -- see _commit_base()) -# kept sending the same stale pre-conflict "old" on the retry and got -# rejected again, identically, even though the retry's "new" was -# correctly merged. This class runs against a real (temp-directory) -# SQLite-backed database and real DbTxn/transaction_commit machinery -- -# only the network layer (web_client) is mocked -- so it actually -# exercises that interaction end to end. +# written for: an earlier version fetched fresh server data with a direct +# GET // and fed it straight to data_to_object(), which +# raises KeyError on that endpoint's shape (see _resync_after_conflict()'s +# docstring) -- caught by the broad _CONNECTION_ERRORS handler around it +# and misreported as a connectivity problem, so the payload got queued, +# retried, failed identically, and was silently dropped. This class runs +# against a real (temp-directory) SQLite-backed database and real DbTxn/ +# transaction_commit machinery, with only the network layer (web_client) +# mocked, so it actually exercises that interaction end to end -- and +# _full_resync() itself runs for real against a fake XML export, the same +# way _resync_after_conflict() invokes it in production. # # ------------------------------------------------------------------------- class TestConflictRetryAgainstARealDatabase(unittest.TestCase): @@ -1519,13 +1369,31 @@ def _make_server_fresh(self): """The server's true current state for self.handle, diverged from the local mirror's stale copy (private=False -> True) via a route this addon's history feed cannot see -- see - _pull_conflicting_objects()'s docstring.""" + _resync_after_conflict()'s docstring.""" server_fresh = copy.deepcopy( remove_object(object_to_data(self.db.get_person_from_handle(self.handle))) ) server_fresh["private"] = True return server_fresh + def _stub_full_resync_to(self, server_fresh): + """Patch _full_resync() to commit server_fresh into local storage + via a real, batch=True/_pulling=True DbTxn -- standing in for + what a real resync does (download and reimport a full XML + export), without actually needing one here. What matters for + these tests is the local write _resync_after_conflict() relies + on, not how a real resync produces it.""" + + def fake_full_resync(): + self.db._pulling = True + try: + with DbTxn("fake resync", self.db, batch=True) as trans: + self.db.commit_person(data_to_object(server_fresh), trans) + finally: + self.db._pulling = False + + return mock.patch.object(self.db, "_full_resync", side_effect=fake_full_resync) + def _push_conflicts_once_then_succeeds(self): calls = [] @@ -1546,21 +1414,21 @@ def _add_an_attribute(self): person.add_attribute(attr) self.db.commit_person(person, trans) - def test_retry_pushes_the_fetched_object_as_old_not_the_stale_mirror(self): + def test_retry_pushes_the_resynced_object_as_old_not_the_stale_mirror(self): stale_local = remove_object( object_to_data(self.db.get_person_from_handle(self.handle)) ) server_fresh = self._make_server_fresh() - self.db.web_client.get_object.return_value = server_fresh calls = self._push_conflicts_once_then_succeeds() - self._add_an_attribute() + with self._stub_full_resync_to(server_fresh): + self._add_an_attribute() self.assertEqual(len(calls), 2) # The original push sent the stale local snapshot -- that's what # the server rejected. self.assertEqual(calls[0][0]["old"], stale_local) - # The retry must send the *fetched* server state as "old", not + # The retry must send the *resynced* server state as "old", not # the same stale value again -- otherwise it is guaranteed to # conflict identically and the edit is dropped for good (see # _push_payload()'s "give up after a repeated conflict" branch). @@ -1576,10 +1444,10 @@ def test_conflict_resolves_without_being_dropped(self): # Same setup, phrased as an outcome: the local mirror ends up # holding the merged result, and the edit was not dropped after # only its first, correctly-rejected attempt. - self.db.web_client.get_object.return_value = self._make_server_fresh() calls = self._push_conflicts_once_then_succeeds() - self._add_an_attribute() + with self._stub_full_resync_to(self._make_server_fresh()): + self._add_an_attribute() self.assertEqual(len(calls), 2) final = self.db.get_person_from_handle(self.handle) @@ -2989,7 +2857,7 @@ def test_conflict_does_not_queue(self): self.db.web_client.push_transaction.side_effect = WebApiPushConflict( "Object has changed" ) - with mock.patch.object(self.db, "_sync_from_server"), mock.patch.object( + with mock.patch.object(self.db, "_resync_after_conflict"), mock.patch.object( self.db, "_retry_after_conflict" ): with self.assertLogs(grampswebapidb.LOG, level="WARNING"): diff --git a/GrampsWebApiDb/tests/test_webapi_client.py b/GrampsWebApiDb/tests/test_webapi_client.py index 4a3544001..eb1b7c013 100644 --- a/GrampsWebApiDb/tests/test_webapi_client.py +++ b/GrampsWebApiDb/tests/test_webapi_client.py @@ -592,81 +592,6 @@ def test_total_count_falls_back_to_body_length(self): self.assertEqual(total, 3) -# ------------------------------------------------------------------------- -# -# TestGetObject -# -# get_object() (grampswebapidb.py's _retry_after_conflict()'s -# refresh_from_server path) hits GET // directly, the one -# source of truth for an object's current server-side state that does not -# depend on gramps-web-api's own transaction-history feed having anything -# to say about it -- see its own docstring. -# -# ------------------------------------------------------------------------- -class TestGetObject(unittest.TestCase): - def _authed_handler(self): - fake = QueuedUrlopen([FakeResponse({"access_token": token("AT0")})]) - with mock.patch.object(webapi_client, "urlopen", fake): - handler = WebApiHandler("https://example.com/api", refresh_token="RT") - return handler - - def test_request_url_uses_the_plural_endpoint(self): - handler = self._authed_handler() - body = {"_class": "Person", "handle": "H1"} - fake = QueuedUrlopen([FakeResponse(body)]) - with mock.patch.object(webapi_client, "urlopen", fake): - data = handler.get_object("Person", "H1") - self.assertEqual(data, body) - self.assertEqual(fake.requests[0].full_url, "https://example.com/api/people/H1") - - def test_family_uses_its_irregular_plural(self): - handler = self._authed_handler() - fake = QueuedUrlopen([FakeResponse({"_class": "Family", "handle": "H1"})]) - with mock.patch.object(webapi_client, "urlopen", fake): - handler.get_object("Family", "H1") - self.assertEqual( - fake.requests[0].full_url, "https://example.com/api/families/H1" - ) - - def test_404_returns_none(self): - # Deleted server-side, or never existed -- the same "nothing to - # merge against" signal a locally-new object gives. - handler = self._authed_handler() - fake = QueuedUrlopen([http_error(404)]) - with mock.patch.object(webapi_client, "urlopen", fake): - self.assertIsNone(handler.get_object("Person", "H1")) - - def test_other_http_error_propagates(self): - handler = self._authed_handler() - fake = QueuedUrlopen([http_error(500), http_error(500)]) - with mock.patch.object(webapi_client, "urlopen", fake): - with self.assertRaises(HTTPError): - handler.get_object("Person", "H1") - - def test_unknown_class_raises_without_a_request(self): - handler = self._authed_handler() - fake = QueuedUrlopen([]) - with mock.patch.object(webapi_client, "urlopen", fake): - with self.assertRaises(ValueError): - handler.get_object("NotAThing", "H1") - self.assertEqual(len(fake.requests), 0) - - def test_401_triggers_reauth_and_retry(self): - handler = self._authed_handler() - fake = QueuedUrlopen( - [ - http_error(401), - FakeResponse({"access_token": token("AT1")}), # the re-auth call - FakeResponse({"_class": "Person", "handle": "H1"}), - ] - ) - with mock.patch.object(webapi_client, "urlopen", fake), mock.patch.object( - webapi_client, "sleep" - ): - data = handler.get_object("Person", "H1") - self.assertEqual(data["handle"], "H1") - - # ------------------------------------------------------------------------- # # TestDownloadExport diff --git a/GrampsWebApiDb/webapi_client.py b/GrampsWebApiDb/webapi_client.py index e2855878e..aa714339d 100644 --- a/GrampsWebApiDb/webapi_client.py +++ b/GrampsWebApiDb/webapi_client.py @@ -114,23 +114,6 @@ "tags", ) -#: Gramps class name -> the REST resource's plural path segment, e.g. -#: "Person" -> GET /people/ -- see gramps-web-api's api/__init__.py -#: route registrations. Used by get_object() to fetch one primary object's -#: current server-side state directly, by class and handle. -CLASS_TO_ENDPOINT = { - "Person": "people", - "Family": "families", - "Event": "events", - "Place": "places", - "Source": "sources", - "Citation": "citations", - "Repository": "repositories", - "Media": "media", - "Note": "notes", - "Tag": "tags", -} - #: Chunk size used when streaming a media file download to disk -- see #: download_media_file(). _DOWNLOAD_CHUNK_SIZE = 1024 * 64 @@ -794,39 +777,6 @@ def get_transaction_history( total_count = int(headers.get("X-Total-Count", len(body))) return body, total_count - def get_object(self, obj_class: str, handle: str) -> dict[str, Any] | None: - """Fetch one primary object's current server-side state directly - -- GET // -- rather than through the transaction- - history feed or a full-tree resync. - - Both of those describe the server's state only as far as - gramps-web-api's own transaction log accounts for it -- which a - bulk import (POST /importers//file, GEDCOM/Gramps XML/CSV/ - ...) never touches at all, since it runs the same batch=True - import machinery a local Gramps client's own Import menu action - would (see grampswebapidb.py's module docstring). That is normal - server administration, not a quirk of any one installation, so an - object whose true current content the history feed cannot - describe is an ordinary thing to run into, not an edge case. - grampswebapidb.py's _retry_after_conflict() calls this to read - the one object actually in question directly, sidestepping that - blind spot entirely rather than trying to detect it. - - Returns ``None`` if the server has no object at this handle (a - 404 -- deleted, or never existed), the same "nothing to merge - against" signal a locally-new object gives. - """ - endpoint = CLASS_TO_ENDPOINT.get(obj_class) - if endpoint is None: - raise ValueError(f"Unknown object class: {obj_class!r}") - try: - data, _headers = self._get_json(f"{self.url}/{endpoint}/{handle}") - except HTTPError as exc: - if exc.code == 404: - return None - raise - return data - def wait_for_task( self, task_id: str, From acff01d1568ee812819fdc9b537eec3785c44a03 Mon Sep 17 00:00:00 2001 From: Doug Blank Date: Sun, 16 Aug 2026 10:24:11 -0700 Subject: [PATCH 11/13] GrampsWebApiDb: add real-database regression tests for _reconcile_batch_commit() Every existing test for this path (TestReconcileBatchCommit in test_grampswebapidb.py) stubs out the handle accessors and DbTxn itself -- appropriate for a fast unit suite, but exactly the isolation that already let one bug in a neighboring mechanism ship broken for two review rounds (see 8e21ed72d). This adds a real-database counterpart in the same style as TestConflictRetryAgainstARealDatabase: a real ImportXml import and real batch=True DbTxns against a real DBAPI-backed SQLite database, only the network layer mocked. It found three more, independent bugs in _reconcile_batch_commit() -- the mechanism meant to push local batch-tool changes (Import, Check and Repair Database, Media Manager, ...) to the server. None are fixed here; each test asserts the correct behavior and currently fails, documenting exactly what's wrong so a fix can be verified against it: - Timestamp precision: get_obj(handle).change (int, whole seconds) compared against transaction.start_time (a raw time.time() float) means any edit landing in the same wall-clock second the batch began in -- the common case for a fast local tool -- is silently never detected at all. - Stale "old" snapshot: by reconciliation time the real batch operation already wrote its result to local storage, so the replay's own "old" capture reflects post-batch content, not what the server last saw. A genuinely new object gets pushed as "update" with a non-None "old" instead of "add" with "old": None; a changed object gets an "old" that already matches "new". Confirmed against gramps-web-api's own old_unchanged() (gramps_webapi/api/tasks.py) that either shape is read as "the object changed" by a real server, even when nothing server-side did -- and because this push already carries is_retry=True, the whole reconstructed batch is dropped rather than retried, logged only as a WARNING. - Deletes swallowed: _retry_after_conflict()'s "if has_handle(handle): remove()" guard is correct for an actual conflict retry (already gone means someone else's delete won), but by the time a real batch delete's own replay runs the object is legitimately already gone locally, so the guard skips it and the delete never reaches the server. Kept as a separate file, not part of the addon's normal fast test run (this repo has no CI), for future regression testing once this is fixed: python3 -m unittest GrampsWebApiDb.tests.test_reconcile_batch_commit_real_db -v --- .../test_reconcile_batch_commit_real_db.py | 328 ++++++++++++++++++ 1 file changed, 328 insertions(+) create mode 100644 GrampsWebApiDb/tests/test_reconcile_batch_commit_real_db.py diff --git a/GrampsWebApiDb/tests/test_reconcile_batch_commit_real_db.py b/GrampsWebApiDb/tests/test_reconcile_batch_commit_real_db.py new file mode 100644 index 000000000..1238fdc42 --- /dev/null +++ b/GrampsWebApiDb/tests/test_reconcile_batch_commit_real_db.py @@ -0,0 +1,328 @@ +# +# Gramps - a GTK+/GNOME based genealogy program +# +# Copyright (C) 2026 Douglas S. Blank +# +# This program is free software; you can redistribute it and/or modify +# it under the terms of the GNU General Public License as published by +# the Free Software Foundation; either version 2 of the License, or +# (at your option) any later version. +# +# This program is distributed in the hope that it will be useful, +# but WITHOUT ANY WARRANTY; without even the implied warranty of +# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the +# GNU General Public License for more details. +# +# You should have received a copy of the GNU General Public License +# along with this program; if not, write to the Free Software +# Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA. +# + +""" +Real-database integration tests for WebApiDB._reconcile_batch_commit() -- +the mechanism that is supposed to notice when a *local* batch=True +operation (a real Gramps Import, or a stock Tool like Check and Repair +Database, Media Manager, Reorder Gramps IDs, ...) added, changed, or +removed something, and push that to the server -- see the module +docstring's "Not every local batch=True commit is a pull-side replay" +section and _reconcile_batch_commit()'s own docstring. + +Why this file exists, separately +--------------------------------- +Every test in test_grampswebapidb.py's TestReconcileBatchCommit class +stubs out the handle accessors and DbTxn itself, isolating the diff +logic from real commit/push machinery -- appropriate for a fast unit +suite, but exactly the isolation that let a previous fix to a +neighboring mechanism (conflict-retry) ship broken for two review +rounds: see commit 8e21ed72d, and TestConflictRetryAgainstARealDatabase +in test_grampswebapidb.py, which was written for the same reason. This +file runs a real ImportXml import and real batch=True DbTxns against a +real DBAPI-backed SQLite database (WebApiDB.__class__ reclassification, +same trick), with only the network layer (web_client) mocked, and +checks what actually gets pushed. + +What it found +-------------- +Three independent bugs, none caught by the mocked unit tests, each +individually sufficient to make _reconcile_batch_commit() fail to +sync real local batch changes to a real server: + +1. Timestamp precision (test_update_within_the_same_wall_clock_second_ + as_batch_start_is_not_silently_missed): _reconcile_batch_commit() + only treats a surviving handle as changed if + ``get_obj(handle).change >= start_time``. ``.change`` is an int + (whole seconds); ``start_time`` is a raw ``time.time()`` float. Any + real edit that lands within the same wall-clock second the batch + transaction began in -- the common case for a fast local tool -- + compares a truncated-down int against a float with a nonzero + fractional part and silently fails the check. The change is never + even attempted, let alone pushed: no entry, no log line, nothing. + +2. Stale "old" snapshot (test_real_import_add_is_pushed_as_an_add_not_ + a_false_conflict, test_real_batch_update_pushes_the_pre_batch_state_ + as_old): by the time _reconcile_batch_commit() runs, the real batch + operation has already written its result to local storage for real. + _retry_after_conflict()'s replay then re-commits that *already- + current* local state as a "fresh" edit, so DBAPI's own "old" + snapshot (_commit_base()'s _get_raw_data(), read from local storage + at commit time) captures the *post-batch* content, not what the + server last actually saw. For a brand-new object this means "type": + "update" with a non-None "old" instead of "type": "add" with "old": + None; for a changed object it means "old" that already matches + "new". Either way, a real server's own old-data check (gramps_webapi/ + api/tasks.py's old_unchanged(), confirmed by reading that source) + compares this against what it actually holds and calls it a + conflict -- even though nothing server-side changed at all. + _push_payload() then does a full resync, and because this push + already has is_retry=True (_retry_after_conflict() sets + self._retrying for its own DbTxn, and _reconcile_batch_commit() + goes through that same method), it gives up rather than retrying + again -- so the entire reconstructed batch (every add and update in + it, bundled into one push -- see the module docstring on + WebApiPushConflict) is silently dropped, logged only as a WARNING. + +3. Deletes swallowed (test_real_batch_delete_is_pushed_not_swallowed): + _retry_after_conflict()'s delete handling is + ``if has_handle(handle): remove(...)`` -- correct for its original + use (a conflict retry, where "already gone" means someone else beat + us to the delete, nothing to do). But by the time + _reconcile_batch_commit() replays a *real* local delete, the object + is *legitimately* already gone (the real batch operation removed it + for real). has_handle() is therefore already False, the guard skips + the remove() call entirely, nothing is recorded in the replay's own + DbTxn, and the delete is never pushed to the server at all -- no + entry, no log line, nothing. + +None of these are fixed here. This file exists to pin down exactly what +is broken, with reproducible real-database evidence, before deciding +how to fix it -- see the commit/PR discussion this file was written +alongside. + +Not wired into the addon's normal fast test run (this repo has no CI -- +see CLAUDE.md); explicit invocation only:: + + python3 -m unittest GrampsWebApiDb.tests.test_reconcile_batch_commit_real_db -v + +Kept for future regression testing of this path once it's fixed -- +every "current, buggy" test below asserts the *correct* behavior, so it +will start passing (and should stay passing) once the underlying bug it +documents is fixed, with no test changes needed. +""" + +# ------------------------------------------------------------------------- +# +# Standard python modules +# +# ------------------------------------------------------------------------- +import copy +import os +import shutil +import sys +import tempfile +import time +import unittest +from unittest import mock + +# ------------------------------------------------------------------------- +# +# Make the addon importable the way Gramps loads it -- see +# test_grampswebapidb.py's comment on the same hack. +# +# ------------------------------------------------------------------------- +ADDON_DIR = os.path.dirname(os.path.dirname(os.path.abspath(__file__))) +if ADDON_DIR not in sys.path: + sys.path.insert(0, ADDON_DIR) + +try: + import gramps +except ImportError as _err: + raise unittest.SkipTest("gramps package not available: %s" % _err) + +from gramps.gen.db import DbTxn +from gramps.gen.db.utils import make_database +from gramps.gen.lib import Person +from gramps.gen.lib.json_utils import object_to_data, remove_object +from gramps.gen.user import User +from gramps.plugins.importer.importxml import importData + +from GrampsWebApiDb.grampswebapidb import WebApiDB + +#: A minimal, valid Gramps XML document holding one person -- enough for +#: a real ImportXml run. ImportXml strips a leading "_" off the XML +#: handle attribute (confirmed empirically: "_h...1" in the XML becomes +#: local handle "h...1"), so callers pass the XML-side spelling and read +#: back whatever ImportXml actually assigned via get_person_handles(). +PERSON_XML = """ + +
+ + + U + + + +""" + + +# ------------------------------------------------------------------------- +# +# TestReconcileBatchCommitAgainstARealDatabase +# +# ------------------------------------------------------------------------- +class TestReconcileBatchCommitAgainstARealDatabase(unittest.TestCase): + def setUp(self): + tmpdir = tempfile.mkdtemp(prefix="grampswebapidb_reconcile_test_") + self.addCleanup(shutil.rmtree, tmpdir, ignore_errors=True) + self.tmpdir = tmpdir + db = make_database("sqlite") + db.load(tmpdir) + # Same reclassification trick as TestConflictRetryAgainstARealDatabase + # in test_grampswebapidb.py -- a real, already-initialized DBAPI + # backend, without going through WebApiDB's network-dependent load(). + db.__class__ = WebApiDB + db.web_client = mock.MagicMock() + db._syncing = False + db._retrying = False + db._pulling = False + db._get_metadata = lambda key, default=0: default + db._set_metadata = lambda key, value, use_txn=True: None + self.db = db + self.addCleanup(self.db.close) + self.pushes = [] + + def fake_push(payload, undo=False, background=False, on_wait=None): + self.pushes.append(copy.deepcopy(payload)) + + self.db.web_client.push_transaction.side_effect = fake_push + + def _seed_person(self, privacy=False): + """Add a person via a plain (non-batch) commit -- standing in for + an object already synced with the server, the same way a fresh + WebApiDB mirror would hold it. Its own push is not what these + tests are about, so the recorder is cleared afterward.""" + with DbTxn("seed", self.db) as trans: + person = Person() + person.set_gramps_id("I0001") + person.set_privacy(privacy) + self.db.add_person(person, trans) + handle = person.handle + self.pushes.clear() + return handle + + def _import_xml(self, xml_text, filename="import.gramps"): + path = os.path.join(self.tmpdir, filename) + with open(path, "w") as f: + f.write(xml_text) + importData(self.db, path, User()) + + # -- Bug 1: timestamp precision ------------------------------------- + + def test_update_within_the_same_wall_clock_second_as_batch_start_is_not_silently_missed( + self, + ): + # A real external batch tool (Check and Repair Database, Media + # Manager, ...) modifying an existing object typically finishes + # within the same wall-clock second it started in -- this must + # still be detected and pushed, not silently skipped because + # get_obj(handle).change (whole seconds) happens to compare less + # than transaction.start_time (a time.time() float). + handle = self._seed_person() + with DbTxn("simulated batch tool", self.db, batch=True) as trans: + person = self.db.get_person_from_handle(handle) + person.set_privacy(True) + self.db.commit_person(person, trans) + self.assertEqual( + len(self.pushes), + 1, + "a same-second local edit made by a real batch tool must " + "still be reconciled and pushed", + ) + + # -- Bug 2: stale "old" snapshot ------------------------------------- + + def test_real_import_add_is_pushed_as_an_add_not_a_false_conflict(self): + # A real ImportXml run (its own batch=True DbTxn, opened + # internally -- not by this addon) adding a brand-new person must + # be reconstructed as an "add" with "old": None, the same as any + # other first-time local add -- not "update" with the object's + # own just-committed data as "old", which a real server (which + # has never seen this handle) always rejects as a conflict. + self._import_xml( + PERSON_XML.format(handle="h" + "0" * 19 + "1", gramps_id="I0001") + ) + self.assertEqual(len(self.pushes), 1) + entry = self.pushes[0][0] + self.assertEqual(entry["type"], "add") + self.assertIsNone(entry["old"]) + + def test_real_batch_update_pushes_the_pre_batch_state_as_old(self): + # A real external batch tool modifying an existing, already- + # synced object must push "old" as what was last known-synced + # (pre-batch) -- what the server actually still has -- not what + # the batch tool just wrote locally, or a real server's + # old-data check rejects it as a conflict even though nothing + # server-side changed. + handle = self._seed_person(privacy=False) + pre_batch = remove_object( + object_to_data(self.db.get_person_from_handle(handle)) + ) + with DbTxn("simulated batch tool", self.db, batch=True) as trans: + # Sidesteps bug 1 (already covered by its own test above) so + # this test isolates bug 2 only. + trans.start_time -= 10 + person = self.db.get_person_from_handle(handle) + person.set_privacy(True) + self.db.commit_person(person, trans) + self.assertEqual(len(self.pushes), 1) + entry = self.pushes[0][0] + self.assertEqual(entry["type"], "update") + self.assertEqual(entry["old"], pre_batch) + self.assertTrue(entry["new"]["private"]) + + # -- Bug 3: deletes swallowed ----------------------------------------- + + def test_real_batch_delete_is_pushed_not_swallowed(self): + # A real external batch tool removing an existing object inside + # its own batch=True DbTxn must still reach the server as a + # "delete" entry -- _retry_after_conflict()'s has_handle() guard + # (correct for an actual conflict retry, where "already gone" + # means someone else's delete beat ours) must not also treat a + # delete this addon's own reconciliation is replaying as + # "nothing to do", just because the real batch delete already + # removed it locally by the time the replay runs. + handle = self._seed_person() + with DbTxn("simulated batch tool", self.db, batch=True) as trans: + trans.start_time -= 10 # isolate from bug 1, as above + self.db.remove_person(handle, trans) + self.assertFalse(self.db.has_person_handle(handle)) + self.assertEqual(len(self.pushes), 1) + entry = self.pushes[0][0] + self.assertEqual(entry["type"], "delete") + self.assertEqual(entry["handle"], handle) + + # -- Sanity: untouched objects are left alone ------------------------- + + def test_objects_the_batch_did_not_touch_are_not_pushed(self): + untouched = self._seed_person() + handle = self._seed_person() + # Backdating start_time by as much as the bug-2/3 tests above do + # (10s) would also pull it before *untouched*'s own .change, + # making it look touched too -- that's bug 1 again, just aimed + # at the wrong object. A 2s real sleep plus a 1s backdate keeps + # comfortable margin on both sides: well after untouched/handle's + # original .change, and well before the edit's own -- isolating + # this test from bug 1 without reintroducing a false positive. + time.sleep(2) + with DbTxn("simulated batch tool", self.db, batch=True) as trans: + trans.start_time -= 1 + person = self.db.get_person_from_handle(handle) + person.set_privacy(True) + self.db.commit_person(person, trans) + self.assertEqual(len(self.pushes), 1) + touched_handles = {e["handle"] for e in self.pushes[0]} + self.assertEqual(touched_handles, {handle}) + self.assertNotIn(untouched, touched_handles) + + +if __name__ == "__main__": + unittest.main() From e7220e5357b9765018389753bedd69e93f90119e Mon Sep 17 00:00:00 2001 From: Doug Blank Date: Sun, 16 Aug 2026 10:39:58 -0700 Subject: [PATCH 12/13] GrampsWebApiDb: fix all three _reconcile_batch_commit() bugs found by the real-database tests Replaces the handle-set + .change-timestamp reconstruction with a real before/after content diff, eliminating all three bugs the previous commit's real-database tests documented (none fixed there yet): - transaction_begin() now snapshots every primary object's full current data (_snapshot_all_objects(), via _iter_raw_data() -- one bulk query per object type, not one per handle) instead of just which handles exist. - _reconcile_batch_commit() diffs that snapshot against a fresh one taken after the batch commits, building add/update/delete entries directly: an add's "old" is None, a delete's "old" is the genuine pre-transaction data, and an update is only reported at all if gramps.gen.merge.diff.diff_items() -- the exact function gramps-web- api's own old_unchanged() conflict check uses server-side -- says the content (ignoring "change", same as the server) actually differs. This removes the .change-vs-start_time comparison entirely, so it can no longer miss a same-wall-clock-second edit, and "old" now reflects what the mirror held before the batch touched anything, not whatever local storage holds by the time a replay reads it. - The reconstructed payload is pushed directly via _push_payload(), the same path any other local edit takes, instead of being replayed through _retry_after_conflict() -- which is what silently swallowed every reconciled delete (its has_handle() guard, correct for an actual conflict retry, also fires when the object is legitimately already gone because this addon's own batch delete removed it for real). _retry_after_conflict() is now reached only if a reconciliation push itself genuinely conflicts, via _push_payload()'s existing conflict handling -- no special-casing needed there. Every test in the real-database file from the previous commit now passes unmodified, plus new coverage for a multi-type batch, a combined add+update+delete batch, a genuine mid-reconciliation server conflict recovering correctly, and a no-op resave correctly not being pushed at all. The mocked unit tests in test_grampswebapidb.py are rewritten to match the new interface (_iter_raw_data()-based stubbing instead of handle accessors); TestFillEntryPayloads is removed along with the method it tested. --- GrampsWebApiDb/grampswebapidb.py | 257 +++++++++------- GrampsWebApiDb/tests/test_grampswebapidb.py | 276 +++++++++--------- .../test_reconcile_batch_commit_real_db.py | 224 ++++++++++---- 3 files changed, 463 insertions(+), 294 deletions(-) diff --git a/GrampsWebApiDb/grampswebapidb.py b/GrampsWebApiDb/grampswebapidb.py index 5c8b7f100..a6169ad4f 100644 --- a/GrampsWebApiDb/grampswebapidb.py +++ b/GrampsWebApiDb/grampswebapidb.py @@ -199,24 +199,39 @@ batch operation's body runs) tells them apart with a _pulling flag set only around _sync_from_server()'s own batch DbTxns (including the ones _full_resync() opens) -- everywhere else, a batch=True transaction gets a -snapshot of every primary object type's handle set stashed on the -transaction itself (_handles_by_class()). transaction_commit() diffs that -snapshot against the post-commit state (_reconcile_batch_commit()) to -reconstruct what changed: a handle that appeared is an add, one that -disappeared is a delete, and one that persisted but whose .change moved to -at or after the transaction's own start_time was an update -- _commit_ -base() always stamps .change on every commit, batch or not; only the -undo-log recording that batch skips is what normally would have let -transaction_to_json() see this directly. The reconstructed entries are -handed to _retry_after_conflict() -- not because anything conflicted, but -because it already does exactly what's needed here: replay each entry as -a fresh, ordinary (non-batch) local edit, so it picks up a real "old" -snapshot from DBAPI's own commit path and goes out through the normal -push path one object at a time, with the same conflict handling a live -edit gets. This costs roughly double the local writes for whatever the -batch operation actually touched (once for the batch commit, once more -for this replay) -- accepted as the price of correctness, the same trade -_full_resync() already makes for the equivalent pull-side blind spot. +full snapshot of every primary object's current data stashed on the +transaction itself (_snapshot_all_objects()), not just which handles +exist. transaction_commit() diffs that snapshot against a fresh one taken +right after the commit (_reconcile_batch_commit()) to reconstruct what +changed: a handle that appeared is an add ("old": None); one that +disappeared is a delete ("old" the pre-transaction data); one that +persisted is an update only if its content actually differs, compared +with gramps.gen.merge.diff.diff_items() -- the same function gramps-web- +api's own old_unchanged() conflict check uses server-side, so this +addon's "did it change" agrees with the server's. (An earlier version of +this used handle presence plus a `.change`-timestamp comparison instead +of a real content diff, and replayed each reconstructed entry through +_retry_after_conflict() to pick up an "old" snapshot -- three separate +bugs followed from that: `.change` (whole seconds) compared against the +transaction's own start_time (a sub-second float) silently missed any +edit landing in the same wall-clock second the batch began in, which is +the common case; replaying against local storage that by then already +held the batch's own result sent the object's *post*-batch content as +"old" instead of what the server last actually saw, which a real +server's own old-data check always reads as a conflict; and replaying a +delete against storage where the object was already legitimately gone +did nothing at all. Building the payload directly from the two +snapshots, with real "old" data captured before anything ran, avoids +all three.) The reconstructed payload goes out through the normal +transaction_commit() -> _push_payload() path, with the same conflict +handling (full resync, then _retry_after_conflict()) any other edit +gets, for the rare case something else changed the same object in the +meantime. Reading (and briefly holding in memory) two full copies of +every primary object's data per batch commit is a real cost, but +_snapshot_all_objects() keeps it to O(types) bulk queries rather than +O(handles) individual ones, and correctness here is worth more than the +memory -- the same trade _full_resync() already makes for the +equivalent pull-side blind spot. A second, previously-unhandled kind of silent drift: when a push's own HTTP call fails for a plain connectivity reason (network down, server @@ -442,7 +457,8 @@ from gramps.gen.db.exceptions import DbConnectionError from gramps.gen.errors import HandleError from gramps.gen.lib.baseobj import BaseObject -from gramps.gen.lib.json_utils import data_to_object, object_to_data, remove_object +from gramps.gen.lib.json_utils import data_to_object, remove_object +from gramps.gen.merge.diff import diff_items from gramps.gen.user import User from gramps.gen.utils.file import media_path_full from gramps.plugins.db.dbapi.sqlite import SQLite @@ -1160,24 +1176,26 @@ def _media_poll_tick(self): def transaction_begin(self, transaction): """Hook DbTxn.__enter__ (which calls this immediately, before the - transaction's body runs) to snapshot the local per-type handle - sets ahead of a batch=True transaction that isn't one of + transaction's body runs) to snapshot every primary object's full + current data ahead of a batch=True transaction that isn't one of _sync_from_server()'s own (self._pulling) -- _reconcile_batch_ - commit() needs that "before" picture to diff against, since DBAPI - skips its usual undo-log recording for a batch commit regardless - of who started it. See the module docstring.""" + commit() needs that "before" picture (not just which handles + exist) to diff against, since DBAPI skips its usual undo-log + recording for a batch commit regardless of who started it. See + the module docstring and _reconcile_batch_commit()'s own + docstring for why full data, not just handles or timestamps.""" result = super().transaction_begin(transaction) if transaction.batch and not self._pulling: - transaction._webapidb_before_handles = self._handles_by_class() + transaction._webapidb_before = self._snapshot_all_objects() return result def transaction_commit(self, transaction): # Must run before super(): it clears the transaction's records. payload = transaction_to_json(transaction) super().transaction_commit(transaction) - before_handles = getattr(transaction, "_webapidb_before_handles", None) - if before_handles is not None: - self._reconcile_batch_commit(before_handles, transaction.start_time) + before = getattr(transaction, "_webapidb_before", None) + if before is not None: + self._reconcile_batch_commit(before) return # self._retrying is set by _retry_after_conflict() while it holds # its own DbTxn open, so the push this commit triggers knows it is @@ -1423,9 +1441,10 @@ def _retry_after_conflict(self, payload): "new" is. _push_payload()'s conflict handler does this with a full resync (_resync_after_conflict()) before calling here; see that method's docstring for why nothing cheaper is trustworthy. - _reconcile_batch_commit()'s call needs no such refresh -- it is - replaying a local batch operation's own just-committed changes, - not recovering from a conflict. + This is only ever reached via that path now -- a local batch + operation's own reconciled changes (_reconcile_batch_commit()) + push directly through _push_payload(), landing here only if + that push itself conflicts, the same as any other edit. Runs as one ordinary (non-batch) DbTxn, so it goes through the normal transaction_commit() -> _push_payload() path again -- this @@ -1494,63 +1513,110 @@ def _resync_after_conflict(self): finally: self._syncing = False - def _handles_by_class(self): - """{obj_class: set(handles)} across every primary object type -- - the "before" snapshot transaction_begin() stashes on a local - batch=True transaction for _reconcile_batch_commit() to diff - against. See the module docstring.""" - return { - obj_class: set(getattr(self, f"get_{KEY_TO_NAME_MAP[key]}_handles")()) - for obj_class, key in CLASS_TO_KEY_MAP.items() - } - - def _reconcile_batch_commit(self, before_handles, start_time): - """Reconstruct what a local batch=True transaction changed, by - diffing the pre-transaction handle snapshot against the current - state, and push it -- see the module docstring's note on why a - batch commit is otherwise invisible to transaction_to_json(). - - An object present now but not before is an add; one present before - but not now is a delete; one present in both whose .change is at or - after the transaction's start_time was updated during it - (_commit_base() stamps .change on every commit, batch included). - Objects the batch left untouched keep an older .change and are - correctly skipped. - - The reconstructed entries go to _retry_after_conflict(), which - replays each as an ordinary non-batch local edit -- so each one - picks up a real "old" snapshot and goes out through the normal - transaction_commit() -> _push_payload() path. - - Cost: the surviving-handle pass reads every primary object in the - tree to check its .change, so this is O(total objects) per batch - commit, not O(objects the batch touched). That is the same order - as whatever opened a batch transaction in the first place (a bulk - import writes everything; Check and Repair reads everything), and - .change isn't a queryable secondary column in DBAPI's schema -- - only handle plus a couple of per-type extras are -- so there is no - cheaper way to ask "what did this transaction touch" after the - fact. If this ever shows up as a real bottleneck, the fix is to - make the batch operation's own transaction non-batch, not to - make this cleverer. + def _snapshot_all_objects(self): + """{(obj_class, handle): data} across every primary object the + local mirror holds right now, ``data`` being the same + json_utils-shaped, "_object"-stripped form transaction_to_json() + sends as "old"/"new" (_iter_raw_data() reads it straight back out + of storage via the same serializer _commit_base() wrote it with + -- see dbapi.py). Called twice around a local batch=True + transaction (before it opens, and again once it has committed) + so _reconcile_batch_commit() can diff the two and know exactly + what changed -- see that method's docstring for why full data, + not just which handles exist or a wall-clock timestamp, is what + this needs. + + Uses _iter_raw_data() (one bulk SELECT per object type) rather + than _get_raw_data() per handle, so this is O(types) queries, + not O(handles) -- cheap regardless of how many objects a batch + operation actually touches. """ - entries = [] + snapshot = {} for obj_class, key in CLASS_TO_KEY_MAP.items(): - name = KEY_TO_NAME_MAP[key] - before = before_handles.get(obj_class, set()) - after = set(getattr(self, f"get_{name}_handles")()) - for handle in after - before: - entries.append({"type": "add", "handle": handle, "_class": obj_class}) - for handle in before - after: + for handle, data in self._iter_raw_data(key): + snapshot[(obj_class, handle)] = remove_object(data) + return snapshot + + def _reconcile_batch_commit(self, before): + """Reconstruct exactly what a local batch=True transaction + changed, by diffing the pre-transaction object snapshot + (transaction_begin()'s _snapshot_all_objects() call) against a + fresh one taken now, and push the result -- see the module + docstring's note on why a batch commit is otherwise invisible to + transaction_to_json(). + + A handle present now but not before is an add, pushed with + "old": None, the same as any other first-time add. One present + before but not now is a delete, pushed with "old" the last + known-synced data (what the object looked like before this + transaction touched it) and "new": None. One present in both is + only an update if its content actually differs -- compared with + gramps.gen.merge.diff.diff_items(), the exact function gramps- + web-api's own old_unchanged() conflict check uses server-side + (gramps_webapi/api/tasks.py, confirmed by reading that source), + so "did this really change" here agrees with the server's own + idea of it: both ignore the object's own "change" timestamp, so + a resave with no other change is correctly not reported at all. + + Getting "old" right this way -- genuinely the pre-transaction + state, not whatever commit_()/remove_() happens to + find in local storage if replayed afterward -- is the point. + local storage by reconciliation time already holds the batch's + own result, not what the mirror last actually synced with the + server; replaying against it (an earlier version of this method + did, via _retry_after_conflict()) sends a false "old" a real + server always rejects as a conflict for an add, and a no-op + "old"-matches-"new" for an update -- and for a delete, replaying + against already-gone-for-real local storage does nothing at + all, silently dropping it. Building the payload directly here + instead avoids all three: pushed the same way as any other + local edit (transaction_commit() -> _push_payload()), with that + method's existing conflict handling (full resync then + _retry_after_conflict()) intact for the rare case something + else changed the same object in the meantime. + + Cost: a full before/after object snapshot, not just handle sets + or timestamps -- see _snapshot_all_objects()'s own docstring for + why, and why that stays cheap (O(types) queries) regardless. If + this ever shows up as a real bottleneck, the fix is to make the + batch operation's own transaction non-batch, not to make this + cleverer. + """ + after = self._snapshot_all_objects() + entries = [] + for obj_class, handle in after.keys() - before.keys(): + entries.append( + { + "type": "add", + "handle": handle, + "_class": obj_class, + "old": None, + "new": after[(obj_class, handle)], + } + ) + for obj_class, handle in before.keys() - after.keys(): + entries.append( + { + "type": "delete", + "handle": handle, + "_class": obj_class, + "old": before[(obj_class, handle)], + "new": None, + } + ) + for obj_class, handle in before.keys() & after.keys(): + old_data = before[(obj_class, handle)] + new_data = after[(obj_class, handle)] + if diff_items(obj_class, old_data, new_data): entries.append( - {"type": "delete", "handle": handle, "_class": obj_class} + { + "type": "update", + "handle": handle, + "_class": obj_class, + "old": old_data, + "new": new_data, + } ) - get_obj = getattr(self, f"get_{name}_from_handle") - for handle in after & before: - if get_obj(handle).change >= start_time: - entries.append( - {"type": "update", "handle": handle, "_class": obj_class} - ) if not entries: return LOG.info( @@ -1558,28 +1624,7 @@ def _reconcile_batch_commit(self, before_handles, start_time): "Gramps did not record per-object; pushing them to the server.", len(entries), ) - self._retry_after_conflict(self._fill_entry_payloads(entries)) - - def _fill_entry_payloads(self, entries): - """Attach the "new" object data _retry_after_conflict() needs to - each reconstructed add/update entry, read from the local mirror as - it stands after the batch commit. A delete carries no "new" data, - and an add/update whose handle has since vanished is dropped.""" - filled = [] - for entry in entries: - if entry["type"] == "delete": - filled.append({**entry, "old": None, "new": None}) - continue - key = CLASS_TO_KEY_MAP[entry["_class"]] - name = KEY_TO_NAME_MAP[key] - try: - obj = getattr(self, f"get_{name}_from_handle")(entry["handle"]) - except HandleError: - continue - filled.append( - {**entry, "old": None, "new": remove_object(object_to_data(obj))} - ) - return filled + self._push_payload(entries) def _sync_from_server(self, progress_callback=None, verify_totals=False): """ diff --git a/GrampsWebApiDb/tests/test_grampswebapidb.py b/GrampsWebApiDb/tests/test_grampswebapidb.py index 6a416fba2..993a8b2ae 100644 --- a/GrampsWebApiDb/tests/test_grampswebapidb.py +++ b/GrampsWebApiDb/tests/test_grampswebapidb.py @@ -2595,15 +2595,24 @@ def test_nothing_missing_is_a_no_op(self): # Check and Repair Database) records nothing per-object -- DBAPI skips # trans.add() for a batch commit -- so transaction_to_json() sees an # empty payload and nothing would ever be pushed. transaction_begin() -# snapshots handles up front and transaction_commit() diffs them after, -# reconstructing the change list. See the module docstring. +# snapshots every primary object's full current data up front +# (_snapshot_all_objects()) and transaction_commit() diffs a fresh +# snapshot against it after, reconstructing the change list -- not just +# which handles exist, and not a .change-vs-start_time timestamp guess +# (an earlier version compared timestamps instead of content and, for +# that and two other reasons, could silently miss changes, push a false +# "old" a real server always rejects as a conflict, or drop deletes +# outright -- see the module docstring and _reconcile_batch_commit()'s +# own docstring for the full account; GrampsWebApiDb/tests/ +# test_reconcile_batch_commit_real_db.py exercises all of that against a +# real database). # # ------------------------------------------------------------------------- class FakeBatchTxn: """Duck-types the DbTxn attributes the batch-reconciliation path reads: .batch, .start_time, and whatever attribute transaction_begin() - stashes its handle snapshot in. get_recnos() returns nothing, matching - a real batch transaction's empty undo log.""" + stashes its snapshot in. get_recnos() returns nothing, matching a real + batch transaction's empty undo log.""" def __init__(self, batch=True, start_time=100.0): self.batch = batch @@ -2616,48 +2625,42 @@ def get_record(self, recno): # pragma: no cover - never reached raise AssertionError("a batch transaction records nothing") -def stored_person(handle, change): - """A real Person with a given .change timestamp -- the field - _reconcile_batch_commit() compares against the transaction's - start_time. Real rather than a stub because _fill_entry_payloads() - then runs it through object_to_data().""" - person = Person() - person.set_handle(handle) - person.set_gramps_id("I" + handle) - person.change = change - return person - - -def stub_all_handle_accessors(db, handles_by_class=None, objects=None): - """Give ``db`` a get__handles/get__from_handle for every - primary type, so _handles_by_class()/_reconcile_batch_commit() can walk - all of CLASS_TO_KEY_MAP without a real database.""" - handles_by_class = handles_by_class or {} - objects = objects or {} - for obj_class, key in grampswebapidb.CLASS_TO_KEY_MAP.items(): - name = grampswebapidb.KEY_TO_NAME_MAP[key] - setattr( - db, - f"get_{name}_handles", - mock.MagicMock(return_value=list(handles_by_class.get(obj_class, []))), - ) - setattr( - db, - f"get_{name}_from_handle", - mock.MagicMock(side_effect=lambda h, _o=objects: _o[h]), - ) +def raw_person_data(handle, change=100.0, **extra): + """A minimal json_utils-shaped dict standing in for what + _get_raw_data()/_iter_raw_data() returns for a Person. + _reconcile_batch_commit() only ever diffs and forwards these as + plain dicts (via diff_items()) -- it never turns them back into + real objects -- so a real Person is not needed to test it.""" + data = {"handle": handle, "change": change, "gramps_id": "I" + handle} + data.update(extra) + return data + + +def stub_iter_raw_data(db, data_by_class): + """data_by_class: {obj_class: {handle: raw_data_dict}}. Stubs + _iter_raw_data() -- the bulk per-type read _snapshot_all_objects() + uses -- so _reconcile_batch_commit()/_snapshot_all_objects() can be + exercised without a real database.""" + + def fake_iter_raw_data(key): + obj_class = grampswebapidb.KEY_TO_CLASS_MAP[key] + return list(data_by_class.get(obj_class, {}).items()) + + db._iter_raw_data = mock.MagicMock(side_effect=fake_iter_raw_data) class TestTransactionBeginSnapshot(unittest.TestCase): def setUp(self): self.db = new_instance() - def test_local_batch_transaction_gets_a_handle_snapshot(self): - stub_all_handle_accessors(self.db, {"Person": ["H1"]}) + def test_local_batch_transaction_gets_a_full_object_snapshot(self): + stub_iter_raw_data(self.db, {"Person": {"H1": raw_person_data("H1")}}) trans = FakeBatchTxn(batch=True) with mock.patch.object(grampswebapidb.SQLite, "transaction_begin"): self.db.transaction_begin(trans) - self.assertEqual(trans._webapidb_before_handles["Person"], {"H1"}) + self.assertEqual( + trans._webapidb_before, {("Person", "H1"): raw_person_data("H1")} + ) def test_non_batch_transaction_gets_no_snapshot(self): # An ordinary edit is recorded per-object by DBAPI, so @@ -2665,7 +2668,7 @@ def test_non_batch_transaction_gets_no_snapshot(self): trans = FakeBatchTxn(batch=False) with mock.patch.object(grampswebapidb.SQLite, "transaction_begin"): self.db.transaction_begin(trans) - self.assertFalse(hasattr(trans, "_webapidb_before_handles")) + self.assertFalse(hasattr(trans, "_webapidb_before")) def test_pull_side_batch_transaction_gets_no_snapshot(self): # _sync_from_server()'s own replay is a batch transaction too, but @@ -2675,7 +2678,7 @@ def test_pull_side_batch_transaction_gets_no_snapshot(self): trans = FakeBatchTxn(batch=True) with mock.patch.object(grampswebapidb.SQLite, "transaction_begin"): self.db.transaction_begin(trans) - self.assertFalse(hasattr(trans, "_webapidb_before_handles")) + self.assertFalse(hasattr(trans, "_webapidb_before")) class TestReconcileBatchCommit(unittest.TestCase): @@ -2683,131 +2686,140 @@ def setUp(self): self.db = new_instance() self.db.web_client = mock.MagicMock() - def test_added_handle_becomes_an_add(self): - obj = stored_person("H2", 150.0) - stub_all_handle_accessors( + def test_added_handle_becomes_an_add_with_no_old_data(self): + stub_iter_raw_data( self.db, - {"Person": ["H1", "H2"]}, - {"H1": stored_person("H1", 50.0), "H2": obj}, + {"Person": {"H1": raw_person_data("H1"), "H2": raw_person_data("H2")}}, ) - before = {c: set() for c in grampswebapidb.CLASS_TO_KEY_MAP} - before["Person"] = {"H1"} - with mock.patch.object(self.db, "_retry_after_conflict") as replay: - self.db._reconcile_batch_commit(before, start_time=100.0) - entries = replay.call_args[0][0] + before = {("Person", "H1"): raw_person_data("H1")} + with mock.patch.object(self.db, "_push_payload") as push: + self.db._reconcile_batch_commit(before) + entries = push.call_args[0][0] self.assertEqual(len(entries), 1) self.assertEqual(entries[0]["type"], "add") self.assertEqual(entries[0]["handle"], "H2") self.assertEqual(entries[0]["_class"], "Person") + self.assertIsNone(entries[0]["old"]) + self.assertEqual(entries[0]["new"], raw_person_data("H2")) - def test_removed_handle_becomes_a_delete(self): - stub_all_handle_accessors(self.db, {"Person": []}) - before = {c: set() for c in grampswebapidb.CLASS_TO_KEY_MAP} - before["Person"] = {"H1"} - with mock.patch.object(self.db, "_retry_after_conflict") as replay: - self.db._reconcile_batch_commit(before, start_time=100.0) - entries = replay.call_args[0][0] + def test_removed_handle_becomes_a_delete_carrying_its_last_known_data(self): + stub_iter_raw_data(self.db, {"Person": {}}) + before = {("Person", "H1"): raw_person_data("H1")} + with mock.patch.object(self.db, "_push_payload") as push: + self.db._reconcile_batch_commit(before) + entries = push.call_args[0][0] self.assertEqual(len(entries), 1) self.assertEqual(entries[0]["type"], "delete") self.assertEqual(entries[0]["handle"], "H1") self.assertIsNone(entries[0]["new"]) - - def test_surviving_handle_touched_during_the_batch_becomes_an_update(self): - stub_all_handle_accessors( - self.db, {"Person": ["H1"]}, {"H1": stored_person("H1", 150.0)} + # Bug fixed: an earlier version replayed deletes through + # _retry_after_conflict()'s has_handle() guard, which (correct + # for an actual conflict retry) silently no-ops here since the + # object is legitimately already gone -- dropping every + # reconciled delete. This builds the entry directly instead. + self.assertEqual(entries[0]["old"], raw_person_data("H1")) + + def test_surviving_handle_with_real_content_change_becomes_an_update(self): + stub_iter_raw_data( + self.db, + {"Person": {"H1": raw_person_data("H1", change=200.0, gramps_id="I0002")}}, ) - before = {c: set() for c in grampswebapidb.CLASS_TO_KEY_MAP} - before["Person"] = {"H1"} - with mock.patch.object(self.db, "_retry_after_conflict") as replay: - self.db._reconcile_batch_commit(before, start_time=100.0) - entries = replay.call_args[0][0] + before = { + ("Person", "H1"): raw_person_data("H1", change=100.0, gramps_id="I0001") + } + with mock.patch.object(self.db, "_push_payload") as push: + self.db._reconcile_batch_commit(before) + entries = push.call_args[0][0] self.assertEqual(len(entries), 1) self.assertEqual(entries[0]["type"], "update") - - def test_untouched_handle_is_skipped(self): - # The whole point of comparing .change against start_time: a bulk - # tool that rewrote 3 of 10000 objects must push 3, not 10000. - stub_all_handle_accessors( - self.db, {"Person": ["H1"]}, {"H1": stored_person("H1", 50.0)} + # Bug fixed: an earlier version replayed this through + # _retry_after_conflict(), which re-commits whatever local + # storage holds *now* -- by reconciliation time, already the + # batch's own result -- so "old" ended up matching "new" + # instead of genuinely reflecting the pre-batch state a real + # server needs to compare against. + self.assertEqual(entries[0]["old"]["gramps_id"], "I0001") + self.assertEqual(entries[0]["new"]["gramps_id"], "I0002") + + def test_update_within_the_same_wall_clock_second_as_batch_start_is_still_detected( + self, + ): + # Bug fixed: an earlier version compared .change (int) against + # the transaction's own start_time (a float), so any edit + # landing in the same wall-clock second as start_time -- the + # common case for a fast local tool -- was silently missed. + # This version diffs content, not timestamps, so it isn't + # fooled by two events sharing a second. + stub_iter_raw_data( + self.db, + {"Person": {"H1": raw_person_data("H1", change=100.0, private=True)}}, ) - before = {c: set() for c in grampswebapidb.CLASS_TO_KEY_MAP} - before["Person"] = {"H1"} - with mock.patch.object(self.db, "_retry_after_conflict") as replay: - self.db._reconcile_batch_commit(before, start_time=100.0) - replay.assert_not_called() + before = {("Person", "H1"): raw_person_data("H1", change=100.0, private=False)} + with mock.patch.object(self.db, "_push_payload") as push: + self.db._reconcile_batch_commit(before) + entries = push.call_args[0][0] + self.assertEqual(len(entries), 1) + self.assertEqual(entries[0]["type"], "update") - def test_change_exactly_at_start_time_counts_as_touched(self): - # int(time.time()) truncation in _commit_base() means a fast - # transaction can stamp .change to exactly its own start second -- - # treating that as untouched would silently drop the change. - stub_all_handle_accessors( - self.db, {"Person": ["H1"]}, {"H1": stored_person("H1", 100.0)} + def test_resave_with_only_the_change_timestamp_different_is_not_pushed(self): + # diff_items() -- the same function gramps-web-api's own + # old_unchanged() conflict check uses server-side -- ignores + # "change", so a resave that touched nothing else must not be + # reported as an update. + stub_iter_raw_data( + self.db, {"Person": {"H1": raw_person_data("H1", change=999.0)}} ) - before = {c: set() for c in grampswebapidb.CLASS_TO_KEY_MAP} - before["Person"] = {"H1"} - with mock.patch.object(self.db, "_retry_after_conflict") as replay: - self.db._reconcile_batch_commit(before, start_time=100.0) - entries = replay.call_args[0][0] - self.assertEqual(entries[0]["type"], "update") + before = {("Person", "H1"): raw_person_data("H1", change=100.0)} + with mock.patch.object(self.db, "_push_payload") as push: + self.db._reconcile_batch_commit(before) + push.assert_not_called() + + def test_untouched_handle_is_skipped(self): + # A bulk tool that rewrote 3 of 10000 objects must push 3, not + # 10000. + data = raw_person_data("H1") + stub_iter_raw_data(self.db, {"Person": {"H1": data}}) + before = {("Person", "H1"): data} + with mock.patch.object(self.db, "_push_payload") as push: + self.db._reconcile_batch_commit(before) + push.assert_not_called() def test_nothing_changed_pushes_nothing(self): - stub_all_handle_accessors(self.db) - before = {c: set() for c in grampswebapidb.CLASS_TO_KEY_MAP} - with mock.patch.object(self.db, "_retry_after_conflict") as replay: - self.db._reconcile_batch_commit(before, start_time=100.0) + stub_iter_raw_data(self.db, {}) + with mock.patch.object(self.db, "_push_payload") as push: + self.db._reconcile_batch_commit({}) + push.assert_not_called() + + def test_pushes_directly_not_via_retry_after_conflict(self): + # Bug fixed: an earlier version routed every reconstructed entry + # through _retry_after_conflict(), whose replay reads local + # storage at commit time -- already the batch's own result by + # then, not the pre-batch state a real server needs. This + # builds the correct payload directly and pushes it the normal + # way, so _retry_after_conflict() is only ever reached (via + # _push_payload()'s own conflict handling) if the push actually + # conflicts. + stub_iter_raw_data(self.db, {"Person": {"H1": raw_person_data("H1")}}) + with mock.patch.object( + self.db, "_retry_after_conflict" + ) as replay, mock.patch.object(self.db, "_push_payload") as push: + self.db._reconcile_batch_commit({}) + push.assert_called_once() replay.assert_not_called() def test_transaction_commit_routes_a_snapshotted_batch_to_reconcile(self): trans = FakeBatchTxn(batch=True, start_time=100.0) - trans._webapidb_before_handles = {"Person": {"H1"}} + trans._webapidb_before = {("Person", "H1"): raw_person_data("H1")} with mock.patch.object( grampswebapidb.SQLite, "transaction_commit" ), mock.patch.object(self.db, "_reconcile_batch_commit") as reconcile: self.db.transaction_commit(trans) - reconcile.assert_called_once_with({"Person": {"H1"}}, 100.0) + reconcile.assert_called_once_with({("Person", "H1"): raw_person_data("H1")}) # ...and does NOT also take the ordinary push path, which would # push an empty payload. self.db.web_client.push_transaction.assert_not_called() -class TestFillEntryPayloads(unittest.TestCase): - def setUp(self): - self.db = new_instance() - - def test_add_entry_gets_current_object_data(self): - person = Person() - person.set_handle("H1") - person.set_gramps_id("I0001") - self.db.get_person_from_handle = mock.MagicMock(return_value=person) - filled = self.db._fill_entry_payloads( - [{"type": "add", "handle": "H1", "_class": "Person"}] - ) - self.assertEqual(len(filled), 1) - self.assertIsNone(filled[0]["old"]) - self.assertEqual(filled[0]["new"]["gramps_id"], "I0001") - # remove_object() strips the cached _object back-reference, which - # is not JSON-serializable and must never reach the wire. - self.assertNotIn("_object", filled[0]["new"]) - - def test_delete_entry_carries_no_object_data(self): - filled = self.db._fill_entry_payloads( - [{"type": "delete", "handle": "H1", "_class": "Person"}] - ) - self.assertEqual(filled[0]["new"], None) - self.assertEqual(filled[0]["old"], None) - - def test_vanished_handle_is_dropped(self): - # The object was removed between the diff and here -- nothing left - # to describe, and asking the server to add it would fail. - self.db.get_person_from_handle = mock.MagicMock( - side_effect=grampswebapidb.HandleError("H1") - ) - filled = self.db._fill_entry_payloads( - [{"type": "add", "handle": "H1", "_class": "Person"}] - ) - self.assertEqual(filled, []) - - # ------------------------------------------------------------------------- # # TestPendingPushQueue diff --git a/GrampsWebApiDb/tests/test_reconcile_batch_commit_real_db.py b/GrampsWebApiDb/tests/test_reconcile_batch_commit_real_db.py index 1238fdc42..906631ff6 100644 --- a/GrampsWebApiDb/tests/test_reconcile_batch_commit_real_db.py +++ b/GrampsWebApiDb/tests/test_reconcile_batch_commit_real_db.py @@ -30,83 +30,82 @@ Why this file exists, separately --------------------------------- Every test in test_grampswebapidb.py's TestReconcileBatchCommit class -stubs out the handle accessors and DbTxn itself, isolating the diff -logic from real commit/push machinery -- appropriate for a fast unit -suite, but exactly the isolation that let a previous fix to a -neighboring mechanism (conflict-retry) ship broken for two review -rounds: see commit 8e21ed72d, and TestConflictRetryAgainstARealDatabase -in test_grampswebapidb.py, which was written for the same reason. This +stubs out _iter_raw_data() and DbTxn itself, isolating the diff logic +from real commit/push machinery -- appropriate for a fast unit suite, +but exactly the isolation that let a previous fix to a neighboring +mechanism (conflict-retry) ship broken for two review rounds: see +commit 8e21ed72d, and TestConflictRetryAgainstARealDatabase in +test_grampswebapidb.py, which was written for the same reason. This file runs a real ImportXml import and real batch=True DbTxns against a real DBAPI-backed SQLite database (WebApiDB.__class__ reclassification, same trick), with only the network layer (web_client) mocked, and checks what actually gets pushed. -What it found --------------- -Three independent bugs, none caught by the mocked unit tests, each -individually sufficient to make _reconcile_batch_commit() fail to -sync real local batch changes to a real server: +What it found (now fixed) +-------------------------- +This file originally documented three independent bugs in +_reconcile_batch_commit(), none caught by the mocked unit tests, each +individually sufficient to make it fail to sync real local batch +changes to a real server -- every test below currently passes because +all three are fixed (_reconcile_batch_commit() and +_snapshot_all_objects() in grampswebapidb.py; see their docstrings for +the current design). Left here, unmodified, as the regression tests +that prove it and guard against it breaking again: 1. Timestamp precision (test_update_within_the_same_wall_clock_second_ - as_batch_start_is_not_silently_missed): _reconcile_batch_commit() - only treats a surviving handle as changed if + as_batch_start_is_not_silently_missed): the old implementation only + treated a surviving handle as changed if ``get_obj(handle).change >= start_time``. ``.change`` is an int (whole seconds); ``start_time`` is a raw ``time.time()`` float. Any - real edit that lands within the same wall-clock second the batch + real edit that landed within the same wall-clock second the batch transaction began in -- the common case for a fast local tool -- - compares a truncated-down int against a float with a nonzero - fractional part and silently fails the check. The change is never + compared a truncated-down int against a float with a nonzero + fractional part and silently failed the check. The change was never even attempted, let alone pushed: no entry, no log line, nothing. + Fixed by comparing actual before/after content + (gramps.gen.merge.diff.diff_items()) instead of timestamps at all. 2. Stale "old" snapshot (test_real_import_add_is_pushed_as_an_add_not_ a_false_conflict, test_real_batch_update_pushes_the_pre_batch_state_ - as_old): by the time _reconcile_batch_commit() runs, the real batch - operation has already written its result to local storage for real. - _retry_after_conflict()'s replay then re-commits that *already- - current* local state as a "fresh" edit, so DBAPI's own "old" - snapshot (_commit_base()'s _get_raw_data(), read from local storage - at commit time) captures the *post-batch* content, not what the - server last actually saw. For a brand-new object this means "type": - "update" with a non-None "old" instead of "type": "add" with "old": - None; for a changed object it means "old" that already matches - "new". Either way, a real server's own old-data check (gramps_webapi/ - api/tasks.py's old_unchanged(), confirmed by reading that source) - compares this against what it actually holds and calls it a - conflict -- even though nothing server-side changed at all. - _push_payload() then does a full resync, and because this push - already has is_retry=True (_retry_after_conflict() sets - self._retrying for its own DbTxn, and _reconcile_batch_commit() - goes through that same method), it gives up rather than retrying - again -- so the entire reconstructed batch (every add and update in - it, bundled into one push -- see the module docstring on - WebApiPushConflict) is silently dropped, logged only as a WARNING. + as_old): by the time _reconcile_batch_commit() ran, the real batch + operation had already written its result to local storage for real. + The old implementation's replay (via _retry_after_conflict()) then + re-committed that *already-current* local state as a "fresh" edit, + so DBAPI's own "old" snapshot (_commit_base()'s _get_raw_data(), + read from local storage at commit time) captured the *post-batch* + content, not what the server last actually saw. For a brand-new + object this meant "type": "update" with a non-None "old" instead of + "type": "add" with "old": None; for a changed object it meant "old" + that already matched "new". Either way, a real server's own old- + data check (gramps_webapi/api/tasks.py's old_unchanged(), confirmed + by reading that source) compared this against what it actually held + and called it a conflict -- even though nothing server-side changed + at all -- and because that push already had is_retry=True, it gave + up rather than retrying, silently dropping the entire reconstructed + batch. Fixed by capturing the true pre-transaction data up front + (transaction_begin()'s _snapshot_all_objects() call) and building + the payload's "old" from that, instead of from local storage at + replay time. 3. Deletes swallowed (test_real_batch_delete_is_pushed_not_swallowed): _retry_after_conflict()'s delete handling is ``if has_handle(handle): remove(...)`` -- correct for its original use (a conflict retry, where "already gone" means someone else beat - us to the delete, nothing to do). But by the time - _reconcile_batch_commit() replays a *real* local delete, the object - is *legitimately* already gone (the real batch operation removed it - for real). has_handle() is therefore already False, the guard skips - the remove() call entirely, nothing is recorded in the replay's own - DbTxn, and the delete is never pushed to the server at all -- no - entry, no log line, nothing. - -None of these are fixed here. This file exists to pin down exactly what -is broken, with reproducible real-database evidence, before deciding -how to fix it -- see the commit/PR discussion this file was written -alongside. + us to the delete, nothing to do). But by the time the old + _reconcile_batch_commit() replayed a *real* local delete through it, + the object was *legitimately* already gone (the real batch operation + removed it for real), so has_handle() was already False, the guard + skipped the remove() call entirely, and the delete never reached the + server. Fixed by building the delete entry directly from the pre- + transaction snapshot instead of replaying it through + _retry_after_conflict() at all -- that method is now only reached + (via _push_payload()'s own conflict handling) if a reconciliation + push itself genuinely conflicts, the same as any other edit. Not wired into the addon's normal fast test run (this repo has no CI -- see CLAUDE.md); explicit invocation only:: python3 -m unittest GrampsWebApiDb.tests.test_reconcile_batch_commit_real_db -v - -Kept for future regression testing of this path once it's fixed -- -every "current, buggy" test below asserts the *correct* behavior, so it -will start passing (and should stay passing) once the underlying bug it -documents is fixed, with no test changes needed. """ # ------------------------------------------------------------------------- @@ -140,12 +139,12 @@ from gramps.gen.db import DbTxn from gramps.gen.db.utils import make_database -from gramps.gen.lib import Person -from gramps.gen.lib.json_utils import object_to_data, remove_object +from gramps.gen.lib import Note, Person, Tag +from gramps.gen.lib.json_utils import data_to_object, object_to_data, remove_object from gramps.gen.user import User from gramps.plugins.importer.importxml import importData -from GrampsWebApiDb.grampswebapidb import WebApiDB +from GrampsWebApiDb.grampswebapidb import WebApiDB, WebApiPushConflict #: A minimal, valid Gramps XML document holding one person -- enough for #: a real ImportXml run. ImportXml strips a leading "_" off the XML @@ -323,6 +322,119 @@ def test_objects_the_batch_did_not_touch_are_not_pushed(self): self.assertEqual(touched_handles, {handle}) self.assertNotIn(untouched, touched_handles) + # -- Additional edge cases ------------------------------------------- + + def test_a_resave_with_no_real_change_is_not_pushed(self): + # Some tools (Check and Repair among them) re-commit an object + # even when nothing about it actually needed fixing. That must + # not be reported as an update -- diff_items() ignores "change" + # (the timestamp _commit_base() bumps on every commit, + # unconditionally), the same as gramps-web-api's own + # old_unchanged() conflict check does server-side. + handle = self._seed_person() + with DbTxn("simulated batch tool", self.db, batch=True) as trans: + person = self.db.get_person_from_handle(handle) + self.db.commit_person(person, trans) + self.assertEqual(len(self.pushes), 0) + + def test_multiple_object_types_in_one_batch_are_all_reconciled(self): + # _reconcile_batch_commit() walks every entry in CLASS_TO_KEY_MAP, + # not just Person -- a real batch tool touching several object + # types at once (e.g. Check and Repair fixing both people and + # tags) must have all of them reconciled together in one push. + with DbTxn("simulated batch tool", self.db, batch=True) as trans: + person = Person() + person.set_gramps_id("I0002") + self.db.add_person(person, trans) + tag = Tag() + tag.set_name("A Tag") + self.db.add_tag(tag, trans) + self.assertEqual(len(self.pushes), 1) + entries = {(e["_class"], e["type"]) for e in self.pushes[0]} + self.assertEqual(entries, {("Person", "add"), ("Tag", "add")}) + + def test_add_update_and_delete_together_in_one_batch_are_all_reconciled(self): + keep = self._seed_person() + gone = self._seed_person() + pre_batch_keep = remove_object( + object_to_data(self.db.get_person_from_handle(keep)) + ) + with DbTxn("simulated batch tool", self.db, batch=True) as trans: + new_person = Person() + new_person.set_gramps_id("I0099") + self.db.add_person(new_person, trans) + added = new_person.handle + + person = self.db.get_person_from_handle(keep) + person.set_privacy(True) + self.db.commit_person(person, trans) + + self.db.remove_person(gone, trans) + + self.assertEqual(len(self.pushes), 1) + by_handle = {e["handle"]: e for e in self.pushes[0]} + self.assertEqual(set(by_handle), {added, keep, gone}) + self.assertEqual(by_handle[added]["type"], "add") + self.assertIsNone(by_handle[added]["old"]) + self.assertEqual(by_handle[keep]["type"], "update") + self.assertEqual(by_handle[keep]["old"], pre_batch_keep) + self.assertTrue(by_handle[keep]["new"]["private"]) + self.assertEqual(by_handle[gone]["type"], "delete") + self.assertIsNone(by_handle[gone]["new"]) + + def test_a_genuine_conflict_on_the_reconciliation_push_recovers_via_full_resync( + self, + ): + # If the server's own copy of a touched object really did change + # in the narrow window between this addon's before-snapshot and + # the reconciliation push actually going out, the push must get + # the same recovery any other edit's conflict gets (full resync, + # then a retry) -- not a special case, and not silently dropped. + handle = self._seed_person(privacy=False) + server_fresh = copy.deepcopy( + remove_object(object_to_data(self.db.get_person_from_handle(handle))) + ) + server_fresh["private"] = True # changed server-side, unknown to us + + calls = [] + + def fake_push(payload, undo=False, background=False, on_wait=None): + calls.append(copy.deepcopy(payload)) + if len(calls) == 1: + raise WebApiPushConflict("Object has changed") + + self.db.web_client.push_transaction.side_effect = fake_push + + def fake_full_resync(): + self.db._pulling = True + try: + with DbTxn("fake resync", self.db, batch=True) as trans: + self.db.commit_person(data_to_object(server_fresh), trans) + finally: + self.db._pulling = False + + with mock.patch.object(self.db, "_full_resync", side_effect=fake_full_resync): + with DbTxn("simulated batch tool", self.db, batch=True) as trans: + person = self.db.get_person_from_handle(handle) + # A list-valued field, not a scalar one: _merge_or_ + # overwrite()'s merge() only unions list fields, so this + # is what actually verifies the local edit survives + # alongside the server's own (scalar) change, rather than + # one silently overwriting the other -- see that + # function's own docstring on the scalar-field caveat. + note = Note() + note.set_handle("N-local") + self.db.add_note(note, trans) + person.add_note("N-local") + self.db.commit_person(person, trans) + + self.assertEqual(len(calls), 2) + final = self.db.get_person_from_handle(handle) + # Server's concurrent change survived... + self.assertTrue(final.get_privacy()) + # ...and so did the local batch's own edit. + self.assertIn("N-local", final.get_note_list()) + if __name__ == "__main__": unittest.main() From c4e71075461ec50aa26dff25fe7a8028b531ee56 Mon Sep 17 00:00:00 2001 From: Doug Blank Date: Sun, 16 Aug 2026 11:35:42 -0700 Subject: [PATCH 13/13] GrampsWebApiDb: correct the module docstring's claim about merge() and scalar fields "merge() ... never touches scalar fields ... two edits to the exact same scalar field still resolve as local-overwrites-remote" was wrong in two ways, found live-testing the conflict-recovery path against demo.grampsweb.org: a genuine concurrent privacy change plus a local batch edit merged to private=True even though the server's post-resync copy (current) was private=False, which shouldn't happen if merge() never touches scalars at all. Confirmed empirically (and now covered by TestMergeOrOverwrite.test_privacy_is_ored_not_left_at_either_sides_value / test_a_scalar_field_merge_does_not_special_case_keeps_currents_value): PrivacyBase._merge_privacy() (called from Person.merge()) ORs privacy -- private if either side marked it private -- and Person.merge() keeps current's own primary name while demoting the acquisition's into current's alternate_names list. A field with no per-field handling at all (gender) is untouched, but since merge() runs as current.merge(acquisition), that means *current's* value survives and the acquisition's (local edit's) is discarded -- the opposite of what the docstring claimed. --- GrampsWebApiDb/grampswebapidb.py | 23 ++++++++++---- GrampsWebApiDb/tests/test_grampswebapidb.py | 33 +++++++++++++++++++++ 2 files changed, 50 insertions(+), 6 deletions(-) diff --git a/GrampsWebApiDb/grampswebapidb.py b/GrampsWebApiDb/grampswebapidb.py index a6169ad4f..20a22e52d 100644 --- a/GrampsWebApiDb/grampswebapidb.py +++ b/GrampsWebApiDb/grampswebapidb.py @@ -174,12 +174,23 @@ merge() -- the same list-unioning logic behind Gramps' Merge People/ Family/... tools (ported from GrampsWebSync's diffhandler.py, credit David Straub, same license) -- rather than letting the retry blindly -clobber whatever the other side changed. merge() only unions *list*-valued -fields (notes, citations, media, urls, event/family refs, ...); it never -touches scalar fields (a name, a date, a gender), so two edits to the -exact same scalar field still resolve as local-overwrites-remote -- real -field-level conflict *resolution* for that narrower case (diff, prompt the -user) is still out of scope. If the push fails for a non-conflict reason +clobber whatever the other side changed. merge(current, acquisition) is +called as current.merge(acquisition) with current the server's post- +resync copy and acquisition the local edit, so a *list*-valued field +(notes, citations, media, urls, event/family refs, tags, ...) is +unioned -- both sides' items survive -- and any other field merge() +doesn't specially handle is simply left as current's own value, with +acquisition's silently discarded (confirmed empirically: +merge(FEMALE-current, MALE-local) keeps FEMALE) -- the *opposite* of +"local overwrites remote". Two fields do get their own special-cased +merge instead of either of those: privacy is OR'd +(PrivacyBase._merge_privacy(): ``self.private = self.private or +other.private``, so the merged object is private if either side marked +it private -- confirmed the same way), and Person.merge() keeps +current's own primary name but demotes acquisition's into current's +alternate_names list rather than discarding it. Real field-level +conflict *resolution* for the plain-scalar case (diff, prompt the user) +is still out of scope. If the push fails for a non-conflict reason (network error, auth failure), the local commit has already happened and is not rolled back -- the local mirror just drifts from the server until the next successful push or read sync. diff --git a/GrampsWebApiDb/tests/test_grampswebapidb.py b/GrampsWebApiDb/tests/test_grampswebapidb.py index 993a8b2ae..a28db913c 100644 --- a/GrampsWebApiDb/tests/test_grampswebapidb.py +++ b/GrampsWebApiDb/tests/test_grampswebapidb.py @@ -1522,6 +1522,39 @@ def test_type_without_a_real_merge_falls_back_to_local_obj(self): result = grampswebapidb._merge_or_overwrite(current, local) self.assertIs(result, local) + def test_privacy_is_ored_not_left_at_either_sides_value(self): + # PrivacyBase._merge_privacy() (called from Person.merge()) is + # "self.private = self.private or other.private" -- neither a + # plain list union nor "current's value wins" (see the next + # test): the merged object is private if *either* side marked + # it private. Confirmed against a live server during this + # addon's own conflict-recovery testing. + current = Person() + current.set_handle("H1") + current.set_privacy(False) + local = Person() + local.set_handle("H1") + local.set_privacy(True) + + merged = grampswebapidb._merge_or_overwrite(current, local) + self.assertTrue(merged.get_privacy()) + + def test_a_scalar_field_merge_does_not_special_case_keeps_currents_value(self): + # A field merge() has no per-field handling for at all (gender, + # unlike privacy or a name) is simply never touched: merged + # starts as a deepcopy of *current*, so current's own value + # survives and local's is silently discarded -- the opposite of + # "local overwrites remote". + current = Person() + current.set_handle("H1") + current.set_gender(Person.FEMALE) + local = Person() + local.set_handle("H1") + local.set_gender(Person.MALE) + + merged = grampswebapidb._merge_or_overwrite(current, local) + self.assertEqual(merged.get_gender(), Person.FEMALE) + # ------------------------------------------------------------------------- #