client: Fix cache corruption on loadBefore and prefetch #169

navytux · 2021-04-14T17:35:53Z

Currently loadBefore and prefetch spawn async protocol.load_before task,
and, after waking up on its completion, populate the cache with received
data. But in between the time when protocol.load_before handler is run
and the time when protocol.load_before caller wakes up, there is a
window in which event loop might be running some other code, including
the code that handles invalidateTransaction messages from the server.

This means that cache updates and cache invalidations can be processed on
the client not in the order that server sent it. And such difference in
the order can lead to data corruption if e.g server sent

<- loadBefore oid serial=tid1 next_serial=None
<- invalidateTransaction tid2 oid

and client processed it as

invalidateTransaction tid2 oid
cache.store(oid, tid1, next_serial=None)

because here the end effect is that invalidation for oid@tid2 is not
applied to the cache.

The fix is simple: perform cache updates right after loadBefore reply is
received.

Fixes: #155

The fix is based on analysis and initial patch by @jmuchemb:

#155 (comment)

For tests, similarly to zopefoundation/ZODB#345,
I wanted to include a general test for this issue into ZODB, so that all
storages - not just ZEO - are exercised for this race scenario. However
in ZODB test infrastructure there is currently no established general
way to open several client storage connections to one storage server.
This way the test for this issue currently lives in wendelin.core
repository (and exercises both NEO and ZEO there):

~~https://lab.nexedi.com/nexedi/wendelin.core/commit/c37a989d~~

I understand there is a room for improvement. For the reference, my
original ZEO-specific data corruption reproducer is here:

#155 (comment)
https://lab.nexedi.com/kirr/wendelin.core/blob/ecd0e7f0/zloadrace5.py

EDIT: this fix now has corresponding test that should be coming in via #170 and zopefoundation/ZODB#345.

/cc @d-maurer, @jamadden, @dataflake, @jimfulton

navytux · 2021-04-14T18:04:07Z

CI:

py36 failed with:

    Exception ignored in <bound method BaseEventLoop.__del__ of <_UnixSelectorEventLoop running=False closed=False debug=False>>
    Traceback (most recent call last)
      File "/opt/python/3.6.7/lib/python3.6/asyncio/base_events.py", line , in __del__
        self.close()
      File "/opt/python/3.6.7/lib/python3.6/asyncio/unix_events.py", line , in close
        super().close()
      File "/opt/python/3.6.7/lib/python3.6/asyncio/selector_events.py", line , in close
        self._close_self_pipe()
      File "/opt/python/3.6.7/lib/python3.6/asyncio/selector_events.py", line , in _close_self_pipe
        self._remove_reader(self._ssock.fileno())
      File "/opt/python/3.6.7/lib/python3.6/asyncio/selector_events.py", line , in _remove_reader
        key = self._selector.get_key(fd)
      File "/opt/python/3.6.7/lib/python3.6/selectors.py", line , in get_key
        return mapping[fileobj]
      File "/opt/python/3.6.7/lib/python3.6/selectors.py", line , in __getitem__
        fd = self._selector._fileobj_lookup(fileobj)
      File "/opt/python/3.6.7/lib/python3.6/selectors.py", line , in _fileobj_lookup
        return _fileobj_to_fd(fileobj)
      File "/opt/python/3.6.7/lib/python3.6/selectors.py", line , in _fileobj_to_fd
        raise ValueError("Invalid file descriptor {}".format(fd))
    ValueError Invalid file descriptor -1
    <BLANKLINE>

uvloop failed with

RuntimeError: uvloop requires Python 3.7 or greater
An error occurred when trying to install /tmp/tmph6b7orkdget_dist/uvloop-0.15.2.tar.gz. Look above this message for any errors that were output by easy_install.
While:
  Installing test.
  Getting distribution for 'uvloop>=0.5.1'.

I believe both failures are unrelated to my patch.

The other 12 jobs passed ok.

jmuchemb · 2021-04-14T22:18:55Z

src/ZEO/asyncio/client.py

    """

+    cbv = None


Isn't Fut() usually followed by a call to add_done_callback ?

Then I'd replace with:

def __init__(self): self.cbv = []

remove the if self.cbv is None: clause in add_done_callback, and the if self.cbv: lines in set_*.

Good idea. Thanks for the advice.

jmuchemb · 2021-04-14T22:22:33Z

src/ZEO/asyncio/client.py

-            if data:
-                data, start, end = data
-                self.cache.store(oid, start, end, data)
+            yield self.protocol.load_before(oid, tid)


Oh I missed that, thanks.

Is is tested ? I'm not asking about the race, but maybe not doing this change would break prefetch. Or would it just become dead code (i.e. data always false) ?

You are welcome, and yes - prefetech is tested:

ZEO/src/ZEO/tests/testZEO.py

Lines 1071 to 1113 in 3d90ed4

def test_prefetch(self):

"""The client storage prefetch method pre-fetches from the server

>>> count = 999

>>> import ZEO

>>> addr, stop = start_server()

>>> conn = ZEO.connection(addr)

>>> root = conn.root()

>>> cls = root.__class__

>>> for i in range(count):

... root[i] = cls()

>>> conn.transaction_manager.commit()

>>> oids = [root[i]._p_oid for i in range(count)]

>>> conn.close()

>>> conn = ZEO.connection(addr)

>>> storage = conn.db().storage

>>> len(storage._cache) <= 1

True

>>> storage.prefetch(oids, conn._storage._start)

The prefetch returns before the cache is filled:

>>> len(storage._cache) < count

True

But it is filled eventually:

>>> from zope.testing.wait import wait

>>> wait(lambda : len(storage._cache) > count)

>>> loads = storage.server_status()['loads']

Now if we reload the data, it will be satisfied from the cache:

>>> for oid in oids:

... _ = conn._storage.load(oid)

>>> storage.server_status()['loads'] == loads

True

>>> conn.close()

"""

What is removed is just a duplicate of cache update that is now living in protocol.load_before. It seems to be it would not be a bug to leave cache.store here because it would only store into the cache what was just stored into the cache by protocol.load_before itself. The wakup here seems to be immediate after switching load_before from asyncio.Future to Fut, so there is seemingly no race window with invalidations. At least I could not make a data corruption with reintroducing this block back and injecting prefetches into my zloadrace.

Anyway, since prefech is just semantically "call loadBefore, but do not wait for it to complete", and load_before_threadsafe - that is serving loadBefore now is not doing cache update and delegates cache update to protocol.load_before, this change should be correct.

Correct Fut implemntation according to review feedback: zopefoundation#169 (comment)

navytux · 2021-04-15T16:42:39Z

Patch updated with Fut changes suggested by @jmuchemb.

navytux · 2021-04-15T16:56:22Z

( CI failure is just with uvloop "RuntimeError: uvloop requires Python 3.7 or greater" and unrelated to my patch )

…neric _new_storage_client() This allows ZODB tests to recognize ZEO as client-server storage and so make "load vs external invalidate" test added in zopefoundation/ZODB#345 to reproduce data corruption problem reported at zopefoundation#155. For the reference: that problem should be fixed by zopefoundation#169. We drop # It's hard to find the actual address. # The rpc mgr addr attribute is a list. Each element in the # list is a socket domain (AF_INET, AF_UNIX, etc.) and an # address. note because at the time it was added (81f586c) it came with addr = self._storage._rpc_mgr.addr[0][1] but nowdays after 0386718 getting to server address is just by ClientStorage._addr.

@d-maurer

For ZEO this data corruption bug was reported at zopefoundation/ZEO#155 and fixed at zopefoundation/ZEO#169. Without that fix the failure shows e.g. as follows when running ZEO test suite: Failure in test check_race_load_vs_external_invalidate (ZEO.tests.testZEO.BlobAdaptedFileStorageTests) Traceback (most recent call last): File "/usr/lib/python2.7/unittest/case.py", line 329, in run testMethod() File "/home/kirr/src/wendelin/z/ZODB/src/ZODB/tests/BasicStorage.py", line 621, in check_race_load_vs_external_invalidate self.fail([_ for _ in failure if _]) File "/usr/lib/python2.7/unittest/case.py", line 410, in fail raise self.failureException(msg) AssertionError: ['T1: obj1.value (7) != obj2.value (8)'] Even if added test is somewhat similar to check_race_loadopen_vs_local_invalidate, it is added anew without trying to unify code. The reason here is that the probability to catch load vs external invalidation race is significantly reduced when there are only 1 modify and 1 verify workers. The unification with preserving both tests semantic would make test for "load vs local invalidate" harder to follow. Sometimes a little copying is better than trying to unify too much. For the test to work, test infrastructure is amended with ._new_storage_client() method that complements ._storage attribute: client-server storages like ZEO, NEO and RelStorage allow several storage clients to be connected to single storage server. For client-server storages test subclasses should implement _new_storage_client to return new storage client that is connected to the same storage server self._storage is connected to. For ZEO ._new_storage_client() is added by zopefoundation/ZEO#170 Other client-server storages can follow to implement ._new_storage_client() and this way automatically activate this "load vs external invalidation" test when their testsuite is run. Contrary to test for "load vs local invalidate" N is set to lower value (100), because with 8 workers the bug is usually reproduced at not-so-high iteration number (5-10-20). /cc @d-maurer, @jamadden, @jmuchemb

navytux · 2021-04-16T17:10:08Z

This fix now comes with corresponding test: see zopefoundation/ZODB#345 (comment) and #170.

d-maurer

The proposed fix lets the Travis tests for #167 (which formerly reliably revealed a race condition problem) succeed. Thus, it apparently resolves at least that problem.

I suggest to add a change log entry to document the fix.

d-maurer · 2021-04-20T06:44:08Z

See "24f4bb7" to resolve the uvloop Travis problem.

navytux · 2021-04-20T11:16:45Z

Thanks, @d-maurer. I've added the changelog entry as you suggests. Note, that this fix now has correposponding test that should be coming in via #170 and zopefoundation/ZODB#345.

If ok, let's merge all this bits.

navytux · 2021-04-20T11:17:11Z

(and good to have that uvloop problem now fixed)

navytux · 2021-04-20T11:26:15Z

CI is ok modulo uvloop. But uvloop fix is coming in separately. (@d-maurer, btw, maybe it makes sense to cherry-pick your "fix uvloop" patch to master without waiting for #167 to be merged first.)

d-maurer · 2021-04-20T12:40:48Z

Kirill Smelkov wrote at 2021-4-20 04:26 -0700:

CI is ok modulo uvloop. But uvloop fix is coming in separately. ***@***.***, btw, maybe it makes sense to cherry-pick your "fix uvloop" patch to master without waiting for #167 to be merged first.)

I would not mind.

navytux · 2021-04-20T14:55:51Z

I would not mind.

Thanks, @d-maurer. I've applied your uvloop-fix patch to master: 707316c4.

@d-maurer

…neric _new_storage_client() (#170) This allows ZODB tests to recognize ZEO as client-server storage and so make "load vs external invalidate" test added in zopefoundation/ZODB#345 to reproduce data corruption problem reported at #155. For the reference: that problem should be fixed by #169. We drop # It's hard to find the actual address. # The rpc mgr addr attribute is a list. Each element in the # list is a socket domain (AF_INET, AF_UNIX, etc.) and an # address. note because at the time it was added (81f586c) it came with addr = self._storage._rpc_mgr.addr[0][1] but nowdays after 0386718 getting to server address is just by ClientStorage._addr. /reviewed-on #170 /reviewed-by @d-maurer

@jmuchemb

Currently loadBefore and prefetch spawn async protocol.load_before task, and, after waking up on its completion, populate the cache with received data. But in between the time when protocol.load_before handler is run and the time when protocol.load_before caller wakes up, there is a window in which event loop might be running some other code, including the code that handles invalidateTransaction messages from the server. This means that cache updates and cache invalidations can be processed on the client not in the order that server sent it. And such difference in the order can lead to data corruption if e.g server sent <- loadBefore oid serial=tid1 next_serial=None <- invalidateTransaction tid2 oid and client processed it as invalidateTransaction tid2 oid cache.store(oid, tid1, next_serial=None) because here the end effect is that invalidation for oid@tid2 is not applied to the cache. The fix is simple: perform cache updates right after loadBefore reply is received. Fixes: zopefoundation#155 The fix is based on analysis and initial patch by @jmuchemb: zopefoundation#155 (comment) A tests corresponding to the fix is coming coming through zopefoundation#170 and zopefoundation/ZODB#345 For the reference, my original ZEO-specific data corruption reproducer is here: zopefoundation#155 (comment) https://lab.nexedi.com/kirr/wendelin.core/blob/ecd0e7f0/zloadrace5.py /cc @jamadden, @dataflake, @jimfulton /reviewed-by @jmuchemb, @d-maurer /reviewed-on zopefoundation#169

navytux · 2021-04-20T17:50:16Z

patches rebased onto master to get uvloop fix;
patches squashed into one to update commit message with properly referring to where corresponding test is coming.

navytux · 2021-04-20T18:38:19Z

I believe it's time to merge this fix.

@d-maurer

For ZEO this data corruption bug was reported at zopefoundation/ZEO#155 and fixed at zopefoundation/ZEO#169. Without that fix the failure shows e.g. as follows when running ZEO test suite: Failure in test check_race_load_vs_external_invalidate (ZEO.tests.testZEO.BlobAdaptedFileStorageTests) Traceback (most recent call last): File "/usr/lib/python2.7/unittest/case.py", line 329, in run testMethod() File "/home/kirr/src/wendelin/z/ZODB/src/ZODB/tests/BasicStorage.py", line 621, in check_race_load_vs_external_invalidate self.fail([_ for _ in failure if _]) File "/usr/lib/python2.7/unittest/case.py", line 410, in fail raise self.failureException(msg) AssertionError: ['T1: obj1.value (7) != obj2.value (8)'] Even if added test is somewhat similar to check_race_loadopen_vs_local_invalidate, it is added anew without trying to unify code. The reason here is that the probability to catch load vs external invalidation race is significantly reduced when there are only 1 modify and 1 verify workers. The unification with preserving both tests semantic would make test for "load vs local invalidate" harder to follow. Sometimes a little copying is better than trying to unify too much. For the test to work, test infrastructure is amended with ._new_storage_client() method that complements ._storage attribute: client-server storages like ZEO, NEO and RelStorage allow several storage clients to be connected to single storage server. For client-server storages test subclasses should implement _new_storage_client to return new storage client that is connected to the same storage server self._storage is connected to. For ZEO ._new_storage_client() is added by zopefoundation/ZEO#170 Other client-server storages can follow to implement ._new_storage_client() and this way automatically activate this "load vs external invalidation" test when their testsuite is run. Contrary to test for "load vs local invalidate" N is set to lower value (100), because with 8 workers the bug is usually reproduced at not-so-high iteration number (5-10-20). /cc @d-maurer, @jamadden, @jmuchemb /reviewed-on zopefoundation#345

@d-maurer

For ZEO this data corruption bug was reported at zopefoundation/ZEO#155 and fixed at zopefoundation/ZEO#169. Without that fix the failure shows e.g. as follows when running ZEO test suite: Failure in test check_race_load_vs_external_invalidate (ZEO.tests.testZEO.BlobAdaptedFileStorageTests) Traceback (most recent call last): File "/usr/lib/python2.7/unittest/case.py", line 329, in run testMethod() File "/home/kirr/src/wendelin/z/ZODB/src/ZODB/tests/BasicStorage.py", line 621, in check_race_load_vs_external_invalidate self.fail([_ for _ in failure if _]) File "/usr/lib/python2.7/unittest/case.py", line 410, in fail raise self.failureException(msg) AssertionError: ['T1: obj1.value (7) != obj2.value (8)'] Even if added test is somewhat similar to check_race_loadopen_vs_local_invalidate, it is added anew without trying to unify code. The reason here is that the probability to catch load vs external invalidation race is significantly reduced when there are only 1 modify and 1 verify workers. The unification with preserving both tests semantic would make test for "load vs local invalidate" harder to follow. Sometimes a little copying is better than trying to unify too much. For the test to work, test infrastructure is amended with ._new_storage_client() method that complements ._storage attribute: client-server storages like ZEO, NEO and RelStorage allow several storage clients to be connected to single storage server. For client-server storages test subclasses should implement _new_storage_client to return new storage client that is connected to the same storage server self._storage is connected to. For ZEO ._new_storage_client() is added by zopefoundation/ZEO#170 Other client-server storages can follow to implement ._new_storage_client() and this way automatically activate this "load vs external invalidation" test when their testsuite is run. Contrary to test for "load vs local invalidate" N is set to lower value (100), because with 8 workers the bug is usually reproduced at not-so-high iteration number (5-10-20). /cc @d-maurer, @jamadden, @jmuchemb /reviewed-on #345

navytux · 2021-08-09T09:17:32Z

This patch fixes data corruption. It was merged to master almost 4 months ago. Can we please make a new ZEO release to get this fix available out of the box?

Thanks beforehand,
Kirill

/cc @jamadden, @icemac, @dataflake, @jugmac00

dataflake · 2021-08-09T11:57:51Z

I'll create a release

navytux · 2021-08-09T12:22:35Z

Thanks, @dataflake.

dataflake · 2021-08-09T12:23:52Z

ZEO 5.2.4 is now published

dataflake · 2021-08-09T12:24:20Z

oops, 5.2.3 I meant

navytux · 2021-08-09T13:34:27Z

@dataflake, thanks again. I appreciate your help.

navytux mentioned this pull request Apr 14, 2021

Data corruption due to race condition with external invalidations (ZEO5 regression) #155

Closed

jmuchemb reviewed Apr 14, 2021

View reviewed changes

navytux added a commit to navytux/ZEO that referenced this pull request Apr 15, 2021

fixup! client: Fix cache corruption on loadBefore and prefetch

fccd3b7

Correct Fut implemntation according to review feedback: zopefoundation#169 (comment)

navytux mentioned this pull request Apr 16, 2021

tests: Factor "Open another ClientStorage to the same server" into generic _new_storage_client() #170

Merged

navytux mentioned this pull request Apr 16, 2021

tests: Add test for open vs invalidation race zopefoundation/ZODB#345

Merged

navytux mentioned this pull request Apr 16, 2021

move setLastTID call after connection cache invalidation processing #167

Closed

d-maurer approved these changes Apr 20, 2021

View reviewed changes

navytux force-pushed the x/fix-155 branch from 0b317b4 to 2694ca8 Compare April 20, 2021 17:49

navytux merged commit e277ba0 into zopefoundation:master Apr 20, 2021

navytux deleted the x/fix-155 branch April 20, 2021 18:40

navytux mentioned this pull request Aug 3, 2022

Fix lint tests. #207

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

client: Fix cache corruption on loadBefore and prefetch #169

client: Fix cache corruption on loadBefore and prefetch #169

navytux commented Apr 14, 2021 •

edited

Loading

navytux commented Apr 14, 2021

jmuchemb Apr 14, 2021

navytux Apr 15, 2021

jmuchemb Apr 14, 2021

navytux Apr 15, 2021

navytux commented Apr 15, 2021

navytux commented Apr 15, 2021

navytux commented Apr 16, 2021

d-maurer left a comment

d-maurer commented Apr 20, 2021

navytux commented Apr 20, 2021

navytux commented Apr 20, 2021

navytux commented Apr 20, 2021

d-maurer commented Apr 20, 2021 via email

navytux commented Apr 20, 2021

navytux commented Apr 20, 2021

navytux commented Apr 20, 2021

navytux commented Aug 9, 2021

dataflake commented Aug 9, 2021

navytux commented Aug 9, 2021

dataflake commented Aug 9, 2021

dataflake commented Aug 9, 2021

navytux commented Aug 9, 2021

	def test_prefetch(self):
	"""The client storage prefetch method pre-fetches from the server

	>>> count = 999

	>>> import ZEO
	>>> addr, stop = start_server()
	>>> conn = ZEO.connection(addr)
	>>> root = conn.root()
	>>> cls = root.__class__
	>>> for i in range(count):
	... root[i] = cls()
	>>> conn.transaction_manager.commit()
	>>> oids = [root[i]._p_oid for i in range(count)]
	>>> conn.close()
	>>> conn = ZEO.connection(addr)
	>>> storage = conn.db().storage
	>>> len(storage._cache) <= 1
	True
	>>> storage.prefetch(oids, conn._storage._start)

	The prefetch returns before the cache is filled:

	>>> len(storage._cache) < count
	True

	But it is filled eventually:

	>>> from zope.testing.wait import wait
	>>> wait(lambda : len(storage._cache) > count)

	>>> loads = storage.server_status()['loads']

	Now if we reload the data, it will be satisfied from the cache:

	>>> for oid in oids:
	... _ = conn._storage.load(oid)

	>>> storage.server_status()['loads'] == loads
	True

	>>> conn.close()
	"""

client: Fix cache corruption on loadBefore and prefetch #169

client: Fix cache corruption on loadBefore and prefetch #169

Conversation

navytux commented Apr 14, 2021 • edited Loading

navytux commented Apr 14, 2021

jmuchemb Apr 14, 2021

Choose a reason for hiding this comment

navytux Apr 15, 2021

Choose a reason for hiding this comment

jmuchemb Apr 14, 2021

Choose a reason for hiding this comment

navytux Apr 15, 2021

Choose a reason for hiding this comment

navytux commented Apr 15, 2021

navytux commented Apr 15, 2021

navytux commented Apr 16, 2021

d-maurer left a comment

Choose a reason for hiding this comment

d-maurer commented Apr 20, 2021

navytux commented Apr 20, 2021

navytux commented Apr 20, 2021

navytux commented Apr 20, 2021

d-maurer commented Apr 20, 2021 via email

navytux commented Apr 20, 2021

navytux commented Apr 20, 2021

navytux commented Apr 20, 2021

navytux commented Aug 9, 2021

dataflake commented Aug 9, 2021

navytux commented Aug 9, 2021

dataflake commented Aug 9, 2021

dataflake commented Aug 9, 2021

navytux commented Aug 9, 2021

navytux commented Apr 14, 2021 •

edited

Loading