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

[jmuchemb]

I submitted zopefoundation/ZODB#291 to fix a similar issue (zopefoundation/ZODB#290) but one of the scripts written by @navytux still fails with ZEO5, when each worker thread has its own connection to the ZEO server. I was also unable to reproduce this issue with NEO, so I think it is a different bug, which is in ZEO5.

The script is https://gist.github.com/jmuchemb/b082dadd28c8a6a55c68e510b49873fd

@jamadden Can you try it with RelStorage ?

[jamadden]

I ran the script with two different RelStorage backends and didn't see the AssertionError after several minutes. I also tried gevent instead of native threads, because that can change timings, and also saw no AssertionError.

[jmuchemb]

(I edited the issue description because it's not only about Connection.open())

I think there's a race condition between Client.loadBefore and Client.invalidateTransaction. That's what the cache trace shows:

                   loads    hits  inv(h)  writes hitrate
Jan 21 20:26:41 00 '' 0000000000000000 0000000000000000 -
Jan 21 20:26-26       0       0       0       0     n/a
Jan 21 20:26:41 ==================== Restart ====================
Jan 21 20:26:41 20                0 0000000000000000 0000000000000000 -
Jan 21 20:26:41 24                0 0000000000000000 03d5510eaf3e4145 -
Jan 21 20:26:41 52                0 03d5510eaf3e4144 0000000000000000 - 122
Jan 21 20:26:41 22                0 03d5510eaf3e4144 0000000000000000 - 122
Jan 21 20:26:41 22                0 03d5510eaf3e4144 0000000000000000 - 122
# Load obj1
Jan 21 20:26:41 20                1 0000000000000000 0000000000000000 -
Jan 21 20:26:41 24                1 0000000000000000 03d5510eaf3e4145 -
Jan 21 20:26:41 52                1 03d5510eaf3e4144 0000000000000000 - 32
# Load obj2
Jan 21 20:26:41 20                2 0000000000000000 0000000000000000 -
Jan 21 20:26:41 24                2 0000000000000000 03d5510eaf3e4145 -
# Waiting from obj2 to be loaded from server.
# Process invalidations from a recently committed transactions.
Jan 21 20:26:41 1c                1 03d5510eaf7847cc 0000000000000000 -
Jan 21 20:26:41 10                2 03d5510eaf7847cc 0000000000000000 -
# obj2 received from server: end_tid is wrong.
Jan 21 20:26:41 52                2 03d5510eaf3e4144 0000000000000000 - 32
[...]
        Count Code Function (action)
            1  00  _setup_trace (initialization)
            1  10  invalidate (miss)
            1  1c  invalidate (hit, saving non-current)
            4  20  load (miss)
            3  22  load (hit)
            4  24  load (non-current, miss)
            4  52  store (current, non-version)

By looking at more the client code, I have 2 hypothesis:

• the IO thread does not process packets in the same order they were received, in which case there would be many other race conditions
• there's a race condition at the server side

Note that ClientCache.loadBefore may call ClientCache.load and on cache miss, it results in 2 cache traces. But ClientCache.loadBefore is also called from both ClientStorage.loadBefore and Client.load_before_threadsafe: if I hadn't commented the former during my tests, there would be up to 4 cache traces before loading from the server.

[jmuchemb]

Same issue with Python 3.7 so it wouldn't be a bug in trollius.

Here is a new test:

Jan 22 16:42:00 24                1 0000000000000000 03d555ce02153934 -
Jan 22 16:42:00 10                1 03d555ce023c9211 0000000000000000 -
Jan 22 16:42:00 10                2 03d555ce023c9211 0000000000000000 -
Jan 22 16:42:00 52                1 03d555ce02153933 0000000000000000 - 37

And at server side, I have logs showing the following events (processed in the same thread):

1. loadBefore(oid=1) completed for the failing client, with end_tid=None
2. ZEOStorage._invalidate called for 03d555ce023c9211

At this level, for this run, the server worked as expected, and somewhere else the 2 messages to the client were swapped.

I stop here for now. I have enough evidence that my ZODB PR can be merged, and we're still far from using ZEO5 in our company.

While working on this issue, cache traces show something that seems to be another ZEO5 bug: I find 062cbec suspicious because it does not handle the case where several oids conflict. Or maybe this commit can simply be reverted.

[navytux]

Here is original cleaned test program that exposes this bug: https://lab.nexedi.com/kirr/wendelin.core/blob/ecd0e7f0/zloadrace5.py

Let me quote its description for completness:

---- 8< ----
Program zloadrace5.py demonstrates concurrency bug in ZODB5/ZEO5 that leads to data corruption.

The bug was not fully analyzed, but offhand it looks like ZEO5 does not properly synchronize on-client loads with invalidations which lead to stale live cache in ZODB connection and corrupt data provided by ZODB to application similarly to zopefoundation/ZODB#290.

The program simulates eight clients: every client once in a while modifies two integer objects preserving invariant that their values stay equal. At every iteration each client also verifies the invariant with access to one of the objects always going through loading from the database. This way if live cache becomes stale the bug is observed as invariant breakage.

Here is example failure:

$ ./zloadrace5.py     
No handlers could be found for logger "ZEO.asyncio.server"     
Traceback (most recent call last):     
  File "./zloadrace5.py", line 139, in <module>     
    main()     
  File "</home/kirr/src/tools/py/decorator/src/decorator.pyc:decorator-gen-1>", line 2, in main
  File "/home/kirr/src/tools/go/pygolang/golang/__init__.py", line 100, in _     
    return f(*argv, **kw)     
  File "./zloadrace5.py", line 123, in main     
    wg.wait()     
  File "golang/_sync.pyx", line 198, in golang._sync.PyWorkGroup.wait     
    pyerr_reraise(pyerr)     
  File "golang/_sync.pyx", line 178, in golang._sync.PyWorkGroup.go.pyrunf     
    f(pywg._pyctx, *argv, **kw)     
  File "</home/kirr/src/tools/py/decorator/src/decorator.pyc:decorator-gen-3>", line 2, in T  
  File "/home/kirr/src/tools/go/pygolang/golang/__init__.py", line 100, in _     
    return f(*argv, **kw)     
  File "./zloadrace5.py", line 112, in T     
    t1()     
  File "</home/kirr/src/tools/py/decorator/src/decorator.pyc:decorator-gen-8>", line 2, in t1 
  File "/home/kirr/src/tools/go/pygolang/golang/__init__.py", line 100, in _     
    return f(*argv, **kw)     
  File "./zloadrace5.py", line 94, in t1     
    raise AssertionError("T%s: obj1.i (%d)  !=  obj2.i (%d)" % (name, i1, i2))     
AssertionError: T7: obj1.i (1)  !=  obj2.i (0)     

---

NOTE ZODB4/ZEO4 do not expose this load vs invalidation race because there the issue was specially cared about. Here is relevant part of Connection._setstate() on ZODB4:

https://github.com/zopefoundation/ZODB/blob/4.4.5-4-g7a1a49111/src/ZODB/Connection.py#L949-L964

Basically it is

1. check if oid was already invalidated and, if yes, load from storage with before=._txn_time i.e. transaction ID of first invalidated transaction this connection received after its transaction begin;
2. if oid was not invalidated - call zstor.load(oid) with before=None - i.e. load latest data for that oid;
3. check again after load whether oid was invalidated, and if yes - reload data again with before=._txn_time.

One can suppose that there can be a race window in that a new transaction was committed before load in 2, but corresponding invalidation messages were not yet sent by server, or not yet processed on client. If any of that were true, it would result in breakage of Isolation property so that in-progress
transaction would observe changes from transactions going simultaneously to it.

After some analysis it looks like it should not be the case:

ZEO4 server explicitly guarantees that it does not mix processing load requests inside tpc_finish + send invalidations. This way if load is processed after new commit, load reply is guaranteed to come to client after invalidation message. This was explicitly fixed by 71eb1456 (search for callAsyncNoPoll there) and later again by 94f275c3.

HOWEVER

ZODB5 shifts MVCC handling into storage layer and this way there is no 1-2-3 from the above in Connection.setstate(). ZEO5 server was also significantly reworked compared to ZEO4 and it looks like that rework reintroduced some concurrency bugs that lead to corrupt data.
---- 8< ----

/cc @jimfulton

P.S. I would also correct the subject of this issue from "Date corruption ..." to "Data corrpution ..." as date corruption is something different and more innocent.

[jmuchemb]

I found some time to look at further. By dumping packets between the client and the server, I could find that they're properly ordered, which means that the bug is on the client side. So I had less code to read and found that the bug is in Protocol.message_received (ZEO.asyncio.client):

• server notifications like invalidations are processed immediately
• replies are just set to the related future object: some futures process callbacks immediately (special Fut class in ZEO), other don't (e.g. asyncio.Future), and it's asyncio.Future in the case of loadBefore

The consequence is that the load_before callback (which stores the result in the cache) is called after that the next received message is processed. At the same time, I found that in case of concurrent loads of the same oid/serial, the result could be saved several times into the cache: maybe not buggy but not ideal for performance.

What I suggest is to do like for other RPCs, except that Fut is too simple in that only 1 callback can be added. Here is a patch that fixes the issue (without regression in the test suite):

--- a/src/ZEO/asyncio/client.py
+++ b/src/ZEO/asyncio/client.py
@@ -252,10 +252,19 @@ def load_before(self, oid, tid):
         message_id = (oid, tid)
         future = self.futures.get(message_id)
         if future is None:
-            future = asyncio.Future(loop=self.loop)
+            future = FutureManyImmediateCallbacks()
             self.futures[message_id] = future
             self._write(
                 self.encode(message_id, False, 'loadBefore', (oid, tid)))
+            @future.add_done_callback
+            def _(future):
+                try:
+                    data = future.result()
+                except Exception:
+                    return
+                if data:
+                    data, start, end = data
+                    self.client.cache.store(oid, start, end, data)
         return future
 
     # Methods called by the server.
@@ -608,9 +617,6 @@ def load_before_threadsafe(self, future, wait_ready, oid, tid):
                 future.set_exception(exc)
             else:
                 future.set_result(data)
-                if data:
-                    data, start, end = data
-                    self.cache.store(oid, start, end, data)
         elif wait_ready:
             self._when_ready(
                 self.load_before_threadsafe, future, wait_ready, oid, tid)
@@ -908,3 +914,21 @@ def result(self):
             raise self.exc
         else:
             return self._result
+
+class FutureManyImmediateCallbacks(Fut):
+
+    def __init__(self):
+        self.cb = []
+
+    def add_done_callback(self, cb):
+        self.cb.append(cb)
+
+    def set_exception(self, exc):
+        self.exc = exc
+        for cb in self.cb:
+            cb(self)
+
+    def set_result(self, result):
+        self._result = result
+        for cb in self.cb:
+            cb(self)

Not sure it's useful to keep an optimized class (Fut) for the case there can only be one callback. Or we should rename Fut.

[navytux]

For the reference: I've backported how ZODB.Connection implements MVCC from ZODB5 to ZODB4 and my crash test works correctly with that ZODB4 version and ZEO4:

https://lab.nexedi.com/nexedi/ZODB/merge_requests/1

The bug definitely looks to be indeed in ZEO5.

[navytux]

Something really wrong is going on with ZEO5.

In addition to the test program provided in this issue, where there are 8 simultaneous workers each of which opens its own storage-level connection, I've tried to run the test program from zopefoundation/ZODB#290 with minimal edit to use ZEO instead of MappingStorage, and it fails too.

In that test program there is only one storage-level connection and two simultaneous users that are using that single storage-level connection. In other words there are no external invalidations involved at all.

https://lab.nexedi.com/kirr/wendelin.core/blob/e2dc8651/lib/tests/testprog/zopenrace.py#L102-203

Here is how it fails:

.../wendelin.core$ WENDELIN_CORE_TEST_DB="<zeo>" py.test -vs -k openrace lib/tests/test_zodb.py
============================== test session starts ==============================
platform linux2 -- Python 2.7.18, pytest-4.6.11, py-1.9.0, pluggy-0.13.1 -- /home/kirr/src/wendelin/venv/z-dev/bin/python2
cachedir: .pytest_cache
rootdir: /home/kirr/src/wendelin/wendelin.core
collected 8 items / 6 deselected / 2 selected

lib/tests/test_zodb.py::test_zodb_zopenrace_basic OK
PASSED
lib/tests/test_zodb.py::test_zodb_zopenrace FAILED

=================================== FAILURES ====================================
______________________________ test_zodb_zopenrace ______________________________

    def test_zodb_zopenrace():
        # exercises ZODB.Connection + particular storage implementation
>       zopenrace.main()

lib/tests/test_zodb.py:382:
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
<decorator-gen-2>:2: in main
    ???
../../tools/go/pygolang/golang/__init__.py:103: in _
    return f(*argv, **kw)
lib/tests/testprog/zopenrace.py:115: in main
    test(zstor)
<decorator-gen-3>:2: in test
    ???
../../tools/go/pygolang/golang/__init__.py:103: in _
    return f(*argv, **kw)
lib/tests/testprog/zopenrace.py:201: in test
    wg.wait()
golang/_sync.pyx:246: in golang._sync.PyWorkGroup.wait
    ???
golang/_sync.pyx:226: in golang._sync.PyWorkGroup.go.pyrunf
    ???
lib/tests/testprog/zopenrace.py:165: in T1
    t1()
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _

    def t1():
        transaction.begin()
        zconn = db.open()

        root = zconn.root()
        obj1 = root['obj1']
        obj2 = root['obj2']

        # obj1 - reload it from zstor
        # obj2 - get it from zconn cache
        obj1._p_invalidate()

        # both objects must have the same values
        i1 = obj1.i
        i2 = obj2.i
        if i1 != i2:
>           raise AssertionError("T1: obj1.i (%d)  !=  obj2.i (%d)" % (i1, i2))
E           AssertionError: T1: obj1.i (16)  !=  obj2.i (15)

lib/tests/testprog/zopenrace.py:156: AssertionError

P.S. Suggested patch from #155 (comment) does not help here - both issues stay unfixed even though it fixes original problem, it does not help to fix zopefoundation/ZODB#290 with ZEO5.

P.P.S. ZEO 5.2.2-1-g3d90ed42, ZODB 5.6.0-18-g75c703fcf

[navytux]

P.S. Suggested patch from #155 (comment) does not help - both issues stay unfixed.

Correction. The original problem from this issue is fixed. The problem from zopefoundation/ZODB#290 stays unfixed. Appologize for providing misleading information in the first place.

[navytux]

P.S. Suggested patch from #155 (comment) does not help - both issues stay unfixed.

Correction. The original problem from this issue is fixed. The problem from zopefoundation/ZODB#290 stays unfixed. Appologize for providing misleading information in the first place.

Filed #155 (comment) as #166 since this seems to be a different problem.

[navytux]

A PR with fix based on @jmuchemb analysis and initial patch is here: #169.