SVN: ZODB/trunk/src/ - If a ZEO client process was restarted while invalidating a ZEO cache

Log message for revision 114645:
  - If a ZEO client process was restarted while invalidating a ZEO cache
    entry, the cache could be left in a stage when there is data marked
    current that should be invalidated, leading to persistent conflict
    errors.
  
  - Invalidations of object records in ZEO caches, where the
    invalidation transaction ids matched the cached transaction ids
    should have been ignored.
  
  - Corrupted or invalid cache files prevented ZEO clients from
    starting. Now, bad cache files are moved aside.
  

Changed:
  U   ZODB/trunk/src/CHANGES.txt
  U   ZODB/trunk/src/ZEO/cache.py
  U   ZODB/trunk/src/ZEO/tests/test_cache.py

-=-
Modified: ZODB/trunk/src/CHANGES.txt
===================================================================
--- ZODB/trunk/src/CHANGES.txt	2010-07-12 15:40:24 UTC (rev 114644)
+++ ZODB/trunk/src/CHANGES.txt	2010-07-12 18:44:09 UTC (rev 114645)
@@ -33,6 +33,18 @@
   The ZEO cache trace statistics and simulation scripts have been
   given more descriptive names and moved to the ZEO scripts package.
 
+- If a ZEO client process was restarted while invalidating a ZEO cache
+  entry, the cache could be left in a stage when there is data marked
+  current that should be invalidated, leading to persistent conflict
+  errors.
+
+- Corrupted or invalid cache files prevented ZEO clients from
+  starting. Now, bad cache files are moved aside.
+
+- Invalidations of object records in ZEO caches, where the
+  invalidation transaction ids matched the cached transaction ids
+  should have been ignored.
+
 3.10.0b1 (2010-05-18)
 =====================
 

Modified: ZODB/trunk/src/ZEO/cache.py
===================================================================
--- ZODB/trunk/src/ZEO/cache.py	2010-07-12 15:40:24 UTC (rev 114644)
+++ ZODB/trunk/src/ZEO/cache.py	2010-07-12 18:44:09 UTC (rev 114645)
@@ -207,7 +207,24 @@
             self.f.write(magic+z64)
             logger.info("created temporary cache file %r", self.f.name)
 
-        self._initfile(fsize)
+        try:
+            self._initfile(fsize)
+        except:
+            if not path:
+                raise # unrecoverable temp file error :(
+            badpath = path+'.bad'
+            if os.path.exists(badpath):
+                logger.critical(
+                    'Removing bad cache file: %r (prev bad exists).',
+                    path, exc_info=1)
+                os.remove(path)
+            else:
+                logger.critical('Moving bad cache file to %r.',
+                                badpath, exc_info=1)
+                os.rename(path, badpath)
+            self.f = open(path, 'wb+')
+            self.f.write(magic+z64)
+            self._initfile(ZEC_HEADER_SIZE)
 
         # Statistics:  _n_adds, _n_added_bytes,
         #              _n_evicts, _n_evicted_bytes,
@@ -675,6 +692,9 @@
             self._trace(0x1E, oid, tid)
             self._len -= 1
         else:
+            if tid == saved_tid:
+                logger.warning("Ignoring invalidation with same tid as current")
+                return
             self.f.seek(ofs+21)
             self.f.write(tid)
             self._set_noncurrent(oid, saved_tid, ofs)

Modified: ZODB/trunk/src/ZEO/tests/test_cache.py
===================================================================
--- ZODB/trunk/src/ZEO/tests/test_cache.py	2010-07-12 15:40:24 UTC (rev 114644)
+++ ZODB/trunk/src/ZEO/tests/test_cache.py	2010-07-12 18:44:09 UTC (rev 114645)
@@ -490,13 +490,7 @@
 >>> cache.close()
 """
 
-def bad_magic_number():
-    r"""
->>> open('cache', 'w').write("Hi world!")
->>> try: cache = ZEO.cache.ClientCache('cache', 1000)
-... except Exception, v: print v
-unexpected magic number: 'Hi w'
-"""
+# def bad_magic_number(): See rename_bad_cache_file
 
 def cache_trace_analysis():
     r"""
@@ -1025,6 +1019,74 @@
 
 """
 
+def invalidations_with_current_tid_dont_wreck_cache():
+    """
+    >>> cache = ZEO.cache.ClientCache('cache', 1000)
+    >>> cache.store(p64(1), p64(1), None, 'data')
+    >>> import logging, sys
+    >>> handler = logging.StreamHandler(sys.stdout)
+    >>> logging.getLogger().addHandler(handler)
+    >>> old_level = logging.getLogger().getEffectiveLevel()
+    >>> logging.getLogger().setLevel(logging.WARNING)
+    >>> cache.invalidate(p64(1), p64(1))
+    Ignoring invalidation with same tid as current
+    >>> cache.close()
+    >>> cache = ZEO.cache.ClientCache('cache', 1000)
+    >>> cache.close()
+    >>> logging.getLogger().removeHandler(handler)
+    >>> logging.getLogger().setLevel(old_level)
+    """
+
+def rename_bad_cache_file():
+    """
+An attempt to open a bad cache file will cause it to be dropped and recreated.
+
+    >>> open('cache', 'w').write('x'*100)
+    >>> import logging, sys
+    >>> handler = logging.StreamHandler(sys.stdout)
+    >>> logging.getLogger().addHandler(handler)
+    >>> old_level = logging.getLogger().getEffectiveLevel()
+    >>> logging.getLogger().setLevel(logging.WARNING)
+
+    >>> cache = ZEO.cache.ClientCache('cache', 1000) # doctest: +ELLIPSIS
+    Moving bad cache file to 'cache.bad'.
+    Traceback (most recent call last):
+    ...
+    ValueError: unexpected magic number: 'xxxx'
+
+    >>> cache.store(p64(1), p64(1), None, 'data')
+    >>> cache.close()
+    >>> f = open('cache')
+    >>> f.seek(0, 2)
+    >>> f.tell()
+    1000
+    >>> f.close()
+
+    >>> open('cache', 'w').write('x'*200)
+    >>> cache = ZEO.cache.ClientCache('cache', 1000) # doctest: +ELLIPSIS
+    Removing bad cache file: 'cache' (prev bad exists).
+    Traceback (most recent call last):
+    ...
+    ValueError: unexpected magic number: 'xxxx'
+
+    >>> cache.store(p64(1), p64(1), None, 'data')
+    >>> cache.close()
+    >>> f = open('cache')
+    >>> f.seek(0, 2)
+    >>> f.tell()
+    1000
+    >>> f.close()
+
+    >>> f = open('cache.bad')
+    >>> f.seek(0, 2)
+    >>> f.tell()
+    100
+    >>> f.close()
+
+    >>> logging.getLogger().removeHandler(handler)
+    >>> logging.getLogger().setLevel(old_level)
+    """
+
 def test_suite():
     suite = unittest.TestSuite()
     suite.addTest(unittest.makeSuite(CacheTests))