mvccadapter: check if the last TID changed without invalidation

[jmuchemb]

Since commit b5895a5, a ZEO test fails as follows:

File "src/ZEO/tests/drop_cache_rather_than_verify.txt", line 114, in drop_cache_rather_than_verify.txt
Failed example:
    conn.root()[1].x
Expected:
    6
Got:
    1

Earlier in the test, the ZEO server is restarted and then another client commits. When disconnected, the first client does not receive invalidations anymore and the connection gets stuck in the past until there's a new commit after it reconnected. It was possible to make the test pass with the following patch:

--- a/src/ZEO/ClientStorage.py
+++ b/src/ZEO/ClientStorage.py
@@ -357,6 +357,7 @@ def notify_connected(self, conn, info):
 
         # invalidate our db cache
         if self._db is not None:
+            self._db.invalidate(self.lastTransaction(), ())
             self._db.invalidateCache()
 
         logger.info("%s %s to storage: %s",

Other implementations like NEO are probably affected the same way.

Rather than changing interfaces in a backward-incompatible way, this commit revert to the original behaviour, and all the changes that were done in existing tests are reverted.

[jmuchemb]

This is a follow-up of #291.

I submit this PR because it solves an issue that has to be fixed quickly.

However, this is extra code that's useless most of the time so I prefer we change the interface, which may require a major version bump.

[jmuchemb]

I'll merge on Friday.

[jamadden]

Can we get CI green, please?

[jamadden]

I think I understand what's going on here and I think this looks OK, at least in isolation, once tests go green.

It needs a good change note (I think there's already something about #290 in there, so maybe just an updated change note mentioning this PR?).

[jmuchemb]

Can we get CI green, please?

Oops. Now fixed, with:

--- a/src/ZODB/tests/testmvcc.py
+++ b/src/ZODB/tests/testmvcc.py
@@ -87,10 +87,10 @@
 
 >>> cn._storage._start == p64(u64(st.lastTransaction()) + 1)
 True
->>> cn.db()._mvcc_storage.invalidate(100, dict.fromkeys([1, 2]))
+>>> cn.db()._mvcc_storage.invalidate(p64(100), dict.fromkeys([1, 2]))
 >>> cn._storage._start == p64(u64(st.lastTransaction()) + 1)
 True
->>> cn.db()._mvcc_storage.invalidate(200, dict.fromkeys([1, 2]))
+>>> cn.db()._mvcc_storage.invalidate(p64(200), dict.fromkeys([1, 2]))
 >>> cn._storage._start == p64(u64(st.lastTransaction()) + 1)
 True
 

I also needed #310 to be merged.

[jamadden]

Awesome!

[navytux]

@jmuchemb, @jamadden isn't the above true only if storage, upon receiving invalidation messages from server, first notifies DB.invalidate() and only after updates zstor.last_tid? For the reference this is indeed true for ZEO4:

https://github.com/zopefoundation/ZEO/blob/47d3fbe8cbf24cad91b183483df069ef20708874/src/ZEO/ClientStorage.py#L1473-L1482

but not true for NEO:

https://lab.nexedi.com/nexedi/neoppod/blob/fc58c089/neo/client/handlers/master.py#L109-124

If zstor.last_tid is updated first before zstor sends invalidations to DB (to MVCCAdapter here), what could happen is:

• poll_invalidations calls zstor.lastTransaction -> gets just committed tid;
• poll invalidations proceeds and could retrieve ._invalidations before zstor could actually update them with invalidation data corresponding to tid;
• tid, and incomplete set of objects to invalidate is returned.

I.e. it will be a data corruption, because objects might remain stale in live cache with similar data corruption scenario as demonstrated in #290.

P.S. I could not quickly see which way ZEO5 implements. Maybe it is something different, or actually related to zopefoundation/ZEO#155.

P.P.S RelStorage is unaffected as it implements IMVCCStorage natively.

[jmuchemb]

There's indeed a problem between this MR & NEO :(

For ZEO4, the 2 operations are wrapped around the same lock so the order does not matter.

For ZEO5, it's first DB.invalidate() then lastTransaction() updated.

So I have to answer 2 questions:

1. Is ZEO5 behaviour enough ?
2. If it is, can I do the same in NEO ?

zopefoundation/ZEO#155 is unrelated.

[navytux]

@jmuchemb, thanks for feedback.

Yes, I believe if we change DB.invalidate() call to always happen before zstor.last_tid update that would be enough. If we go this way this change also requires corresponding change in IStorage interface definiton. Something like below:

--- a/src/ZODB/interfaces.py
+++ b/src/ZODB/interfaces.py
@@ -685,6 +685,15 @@ def isReadOnly():
     def lastTransaction():
         """Return the id of the last committed transaction.
 
+        Returned tid is ID of last committed transaction as observed from
+        some time _before_ lastTransaction call returns. In particular for
+        client-sever case, lastTransaction can return cached view of storage
+        that was learned some time ago.
+
+        It is guaranteed that for all IStorageWrappers, that wrap the storage,
+        invalidation notifications have been completed for transactions
+        with ID ≤ returned tid.
+
         If no transactions have been committed, return a string of 8
         null (0) characters.
         """

---

EDIT: corrected to "... some time before lastTransaction call was madereturns." due to @jmuchemb notice.

[jmuchemb]

Indeed, I found no way to cause any bug if lastTransaction() is updated just after invalidations are notified. I feared issues because NEO also uses lastTransaction() internally: note however it must do it before releasing its cache lock, otherwise "load current" fails on ZODB<5.

Updating lastTransaction() at the right moment also matters for "internal" invalidations: I mean that it must be done just after calling the tpc_finish callback.

https://lab.nexedi.com/nexedi/neoppod/commit/5870c5d79f68dce00267f3ae9c4e12d56d19dede should make NEO work with this MR. It includes tests for the 4 cases.

[navytux]

@jmuchemb, thanks for feedback and adapting things on NEO side. I see about the need to update app.last_tid while still under app._cache_lock - as app._cache and app.last_tid need to be kept coherent on NEO side internally.

Updating lastTransaction() at the right moment also matters for "internal" invalidations: I mean that it must be done just after calling the tpc_finish callback.

Yes, thanks for pointing this out. There app.last_tid has to be also set while still under app._cache_lock and after call to app._cache.invalidate(). As you say this matters for "load current" on ZODB<5. I thus suggest the following amendment for ZODB4 version of proposed IStorage.lastTransaction interface change (ZODB4 specifics in bold):

def lastTransaction():
"""Return the id of the last committed transaction.

Returned tid is ID of last committed transaction as observed from
some time before lastTransaction call returns. In particular for
client-sever case, lastTransaction can return cached view of storage
that was learned some time ago.

It is guaranteed that for all IStorageWrappers, that wrap the storage,
invalidation notifications have been completed for transactions
with ID ≤ returned tid.

It is guaranteed that after lastTransaction returns, "current" view of
the storage as observed by load() is ≥ returned tid.

If no transactions have been committed, return a string of 8
null (0) characters.

I believe it is very important we don't just fixup NEO and merge this patch without fixing IStorage interface. There are application-level cases that rely on exactly the same guarantees that MVCCAdapter needs here and got wrong in the first version of this patch. Also it has to be clear for all other potential storages and their authors - just from reading the interfaces - which semantic must be provided.

I created the following pull-requests to adjust the IStorage interface:

#313
#314

/cc @jamadden, @vpelletier, @arnaud-fontaine, @jwolf083, @klawlf82, @gidzit, @jimfulton

---

EDIT: corrected to "... some time before lastTransaction call was madereturns." due to @jmuchemb notice.

[jmuchemb]

I believe it is very important we don't just fixup NEO and merge this patch without fixing IStorage interface.

Yes. First, I wanted to be sure this MR is correct.

as observed from some time before lastTransaction call was made.

Strictly speaking, it's wrong because the value that lastTransaction reads could be updated between the call to lastTransaction start and the instruction that actually reads the value in question.

I suggest the following change:

--- a/src/ZODB/interfaces.py
+++ b/src/ZODB/interfaces.py
@@ -685,6 +685,14 @@ def isReadOnly():
     def lastTransaction():
         """Return the id of the last committed transaction.
 
+        For proper MVCC operation, the return value is the id of the last
+        transaction for which invalidation notifications are completed.
+
+        In particular for client-server implementations, lastTransaction
+        should return a cached value (rather than querying the server).
+        A preliminary call to sync() can be done to get the actual last
+        TID at the wanted time.
+
         If no transactions have been committed, return a string of 8
         null (0) characters.
         """

[navytux]

@jmuchemb, thanks for feedback.

Strictly speaking, it's wrong ...

You are right, thanks for noticing it. It was a thinko on my side that I copied from ZODB/go. The correction is to require "as observed from some time before lastTransaction call was madereturns." I've amended ZODB/go and my two pull requests accordingly.

I suggest the following change:

I prefer my version, but am ok if ZODB/interfaces.py is updated with your text, or any other text that clearly documents required semantic.

[d-maurer]

The change has caused a problem with ZEO: "zopefoundation/ZEO#166". The reason is obvious: ZEO does not yet fulfill the requirement that lastTransaction is updated after connection cache invalidation processing.

In "zopefoundation/ZEO#167" I tried to change this but failed: the (ZODB) check_tid_ordering_w_commit tests are now failing. This test uses the tpc_finish callback used by mvccadapter for invalidation processing to ensure that lastTransaction is called at this time. As lastTransaction now changes after invalidation processing, the test sees a value which is deemed too old.

@jmuchemb Do you have an idea how this problem might be fixed?

[jmuchemb]

In "zopefoundation/ZEO#167" I tried to change this but failed: the (ZODB) check_tid_ordering_w_commit tests are now failing. This test uses the tpc_finish callback used by mvccadapter for invalidation processing to ensure that lastTransaction is called at this time. As lastTransaction now changes after invalidation processing, the test sees a value which is deemed too old.

@jmuchemb Do you have an idea how this problem might be fixed?

check_tid_ordering_w_commit was fixed in #316 but no new release of ZODB since then.

[d-maurer]

Julien Muchembled wrote at 2021-4-8 07:00 -0700:

> In "[zopefoundation/ZEO#167](zopefoundation/ZEO#167)" I tried to change this but failed: the (ZODB) `check_tid_ordering_w_commit` tests are now failing. This test uses the `tpc_finish` callback used by `mvccadapter` for invalidation processing to ensure that `lastTransaction` is called at this time. As `lastTransaction` now changes after invalidation processing, the test sees a value which is deemed too old. > > @jmuchemb Do you have an idea how this problem might be fixed? `check_tid_ordering_w_commit` was fixed in zopefoundation/ZODB#316 but no new release of ZODB since then.

The `check_tid_ordering_w_commit` tests fail (for ZEO#167) even with the current ZODB master (which contains `ZODB#316`). This does not surprise me: the test samples `lastTransaction` at the precise place where during normal operations `MVCCAdapterInstance` would process invalidations. As (with ZODB>=5.6) `lastTransaction` must change after invalidation processing, it has not yet changed at this time and the test must fail. I believe that the original problem should be resolved in a different way: Let `MVCCAdapterInstance` override `lastTransaction` to return its `_ltid` (which is the tid of the last processed invalidation) and call the base `lastTransaction` if this is still invalid. There could still be a race condition - but only for newly created `MVCCAdapterInstance`s or after reconnections. I hope that this could be handle in `poll_invalidations`. I will explore that approach.

[jmuchemb]

You're not clear about where the bug would be. And if the code of ZODB is correct, I prefer not to complicate just to make the test pass. I don't understand what you suggest to do in MVCCAdapterInstance because check_tid_ordering_w_commit works directly with storages.

Note that check_tid_ordering_w_commit passes with NEO. The difference between NEO & ZEO is about the cache lock:

• NEO: the lock is outside the cache instance and the caller must acquire it before accessing the cache
• ZEO: the lock is inside the cache instance and cache methods lock internally

In NEO, we can then do several operations without releasing the lock. And in particular, as you can see within tpc_finish, the callback call & the last_tid update are done with the same acquired lock. The test starts with a load and NEO also acquires the cache lock for that: it means that when the load is processed, the last_tid is guaranteed to be updated (NEO needed that with ZODB<5).

For ZEO, I tried the following change (on top of zopefoundation/ZEO#167):

--- a/src/ZEO/asyncio/client.py
+++ b/src/ZEO/asyncio/client.py
@@ -661,6 +661,7 @@ def tpc_finish_threadsafe(self, future, wait_ready, tid, updates, f):
                 self.protocol.close()
                 self.disconnected(self.protocol)
             else:
+              with cache._lock:
                 # typically performs connection cache invalidations
                 f(tid)
                 # ZODB>=5.6.0 requires that ``LastTid``

and the test passes.

But what I said about ZODB is also true for ZEO: if ZEO is already correct about how it locks the cache, then we should rather change the test.

[d-maurer]

Julien Muchembled wrote at 2021-4-9 11:09 -0700:

You're not clear about where the bug would be. And if the code of ZODB is correct, I prefer not to complicate just to make the test pass. I don't understand what you suggest to do in `MVCCAdapterInstance` because `check_tid_ordering_w_commit` works directly with storages.

`MVCCAdapterInstance` puts the invalidations associated with `tpc_finish` into the callback to the storage's `tpc_finish`. The storage interface now (ZODB>=5.6) requests that `lastTransaction` changes **after** invalidation processing. For `ClientStorage`, this implies that `cache.setLastTID` (the source of `lastTransaction`) must be called after the callback call. In the `check_tid_ordering_w_commit`, this same callback is used to coordinate `lastTransaction` sampling. Therefore, it necessarily gets the wrong `lastTransaction`: the one before the `tpc_finish` not the one set up by `tpc_finish`. Do you now see the problem? If `lastTransaction` must change after invalidation processing, `check_tid_ordering_w_commit` cannot see the correct `lastTransaction` value because it monitors this value at the place where during normal operations the invalidation takes place.

Note that `check_tid_ordering_w_commit` passes with NEO. The difference between NEO & ZEO is about the cache lock: - NEO: the lock is outside the cache instance and the caller must acquire it before accessing the cache

I perfectly understand why the test fails with `ZEO`. I do not understand why it succeeds with any storage which is used via `MVCCAdapter`. Or more precisely: if the test succeeds, the storage would need to change `lastTransaction` **before** invalidation processing -- contrary to the new requirement of ZODB>=5.6.

... For ZEO, I tried the following change (on top of zopefoundation/ZEO#167): ```diff --- a/src/ZEO/asyncio/client.py +++ b/src/ZEO/asyncio/client.py @@ -661,6 +661,7 @@ def tpc_finish_threadsafe(self, future, wait_ready, tid, updates, f): self.protocol.close() self.disconnected(self.protocol) else: + with cache._lock: # typically performs connection cache invalidations f(tid) # ZODB>=5.6.0 requires that ``LastTid`` ``` and the test passes.

Really surprising: how can the test pass when the test setup tries hard to ensure that `lastTransaction` is sampled during the `f(tid)` call and `setLastTID` (which provides the value for `lastTransaction`) is called only thereafter?

But what I said about ZODB is also true for ZEO: if ZEO is already correct about how it locks the cache, then we should rather change the test.

As I read the test, it depends on the fact that `lastTransaction` changes before invalidation processing -- at least for all storages which are used with `MVCCAdapter` -- contrary to the new (ZODB>=5.6) ordering requirement.

[navytux]

@d-maurer, I quickly checked, and while I might be missing something, to me it looks like there should not be the problem you describe with check_tid_ordering_w_commit: there both commit (that calls storage.tpc_finish with callback to sample new tid) and load (that samples new serial and lastTransaction) are run in their own threads in parallel. The logic here is that while tpc_finish callback is run - it is holding a kind of "storage lock". This way thread that calls lastTransaction must be blocked to wait for the tpc_finish thread to first release that lock. And after the storage lock is released tpc_finish is complete and so the notion of last tid is already updated too.

ZODB/src/ZODB/tests/BasicStorage.py

Lines 321 to 379 in dad7780

	to_join = []
	def run_in_thread(func):
	t = threading.Thread(target=func)
	t.setDaemon(True)
	t.start()
	to_join.append(t)
	started = threading.Event()
	finish = threading.Event()
	@run_in_thread
	def commit():
	def callback(tid):
	started.set()
	tids.append(tid)
	finish.wait()
	self._storage.tpc_finish(t, callback)
	results = {}
	started.wait()
	attempts = []
	attempts_cond = utils.Condition()
	def update_attempts():
	with attempts_cond:
	attempts.append(1)
	attempts_cond.notifyAll()
	@run_in_thread
	def load():
	update_attempts()
	results['load'] = utils.load_current(self._storage, ZERO)[1]
	results['lastTransaction'] = self._storage.lastTransaction()
	expected_attempts = 1
	if hasattr(self._storage, 'getTid'):
	expected_attempts += 1
	@run_in_thread
	def getTid():
	update_attempts()
	results['getTid'] = self._storage.getTid(ZERO)
	if hasattr(self._storage, 'lastInvalidations'):
	expected_attempts += 1
	@run_in_thread
	def lastInvalidations():
	update_attempts()
	invals = self._storage.lastInvalidations(1)
	if invals:
	results['lastInvalidations'] = invals[0][0]
	with attempts_cond:
	while len(attempts) < expected_attempts:
	attempts_cond.wait()
	time.sleep(.01) # for good measure :)
	finish.set()

Existing storages already confirm to the requiredment to first call the tpc_finish callback, and only after that to set the last tid. And they indeed do so from under holding the "storage lock". Here are some examples:

BaseStorage:

ZODB/src/ZODB/BaseStorage.py

Lines 230 to 246 in dad7780

	def tpc_finish(self, transaction, f=None):
	# It's important that the storage calls the function we pass
	# while it still has its lock. We don't want another thread
	# to be able to read any updated data until we've had a chance
	# to send an invalidation message to all of the other
	# connections!
	with self._lock:
	if transaction is not self._transaction:
	raise POSException.StorageTransactionError(
	"tpc_finish called with wrong transaction")
	try:
	if f is not None:
	f(self._tid)
	u, d, e = self._ude
	self._finish(self._tid, u, d, e)
	self._clear_temp()

FileStorage:

ZODB/src/ZODB/FileStorage/FileStorage.py

Lines 810 to 821 in dad7780

	def tpc_finish(self, transaction, f=None):
	with self._files.write_lock():
	with self._lock:
	if transaction is not self._transaction:
	raise StorageTransactionError(
	"tpc_finish called with wrong transaction")
	try:
	tid = self._tid
	if f is not None:
	f(tid)
	self._finish(tid, *self._ude)
	self._clear_temp()

MappingStorage

ZODB/src/ZODB/MappingStorage.py

Lines 286 to 321 in dad7780

	self._commit_lock.acquire()
	with self._lock:
	self._transaction = transaction
	self._tdata = {}
	if tid is None:
	if self._transactions:
	old_tid = self._transactions.maxKey()
	else:
	old_tid = None
	tid = ZODB.utils.newTid(old_tid)
	self._tid = tid
	# ZODB.interfaces.IStorage
	@ZODB.utils.locked(opened)
	def tpc_finish(self, transaction, func = lambda tid: None):
	if (transaction is not self._transaction):
	raise ZODB.POSException.StorageTransactionError(
	"tpc_finish called with wrong transaction")
	tid = self._tid
	func(tid)
	tdata = self._tdata
	for oid in tdata:
	tid_data = self._data.get(oid)
	if tid_data is None:
	tid_data = BTrees.OOBTree.OOBucket()
	self._data[oid] = tid_data
	tid_data[tid] = tdata[oid]
	self._ltid = tid
	self._transactions[tid] = TransactionRecord(tid, transaction, tdata)
	self._transaction = None
	del self._tdata
	self._commit_lock.release()

NEO:

https://lab.nexedi.com/nexedi/neoppod/blob/de0feb4e/neo/client/handlers/master.py#L69-86

Doing last tid update from under lock (and retrieving last tid with also taking the lock) is likely what @jimfulton was talking about "some locking strategy" in c3091e2.

Does that help? Did I missed something?

Thanks again for your work on to bring ZEO5 into a better shape,
Kirill

[d-maurer]

Kirill Smelkov wrote at 2021-4-13 10:48 -0700: ***@***.***, I quickly checked, and while I might be missing something, to me it looks like there should not be the problem you describe with `check_tid_ordering_w_commit`: there both `commit` (that calls storage.tpc_finish with callback to sample new tid) and `load` (that samples new serial and `lastTransaction`) are run in their own threads in parallel. The logic here is that while tpc_finish callback is run - it is holding a kind of "storage lock". This way thread that calls lastTransaction must be blocked to wait for the tpc_finish thread to first release that lock. And after the storage lock is released tpc_finish is complete and so the notion of last tid is already updated too. I am convinced: I have misread the test that `finish` is set (and therefore `tpc_finish` can complete) after the sampling threads have run; but in fact, `finish` is set after all sampling threads are started. The "storage" lock (not visible by looking at the test only) apparently prevents the sampling threads to complete before `tpc_finish` ends. But for ZEO5, `ClientStorage` seems to lack such a lock.

... Does that help? Did I missed something?

It does. We still need to find a way to implement the lock for `ClientStorage` in ZEO5. There, the test fails when I move the `setLastTID` call after the callback.

[navytux]

Thanks, @d-maurer.