- (beta 8) An ZEO cache internal data structure can get out of sync

  with the data in a way that prevents data from being loaded into the
  cache. We don't yet know why, but added an exception handler to
  prevent this error from being fatal.

NEWS.txt

@@ -4,7 +4,12 @@ Whats new in ZODB 3.8.1
 
 Bugs Fixed:
 
-- (unreleased) Fixed setup.py use of setuptools vs distutils, so .c and .h
+- (beta 8) An ZEO cache internal data structure can get out of sync
+  with the data in a way that prevents data from being loaded into the
+  cache. We don't yet know why, but added an exception handler to
+  prevent this error from being fatal.
+
+- (beta 8) Fixed setup.py use of setuptools vs distutils, so .c and .h
   files are included in the bdist_egg.
 
 - (beta 7) Fixed a bug, introduced in an earlier beta, that allowed

src/ZEO/cache.py

@@ -295,10 +295,14 @@ class ClientCache(object):
         noncurrent_for_oid[u64(tid)] = ofs
 
     def _del_noncurrent(self, oid, tid):
+        try:
             noncurrent_for_oid = self.noncurrent[u64(oid)]
             del noncurrent_for_oid[u64(tid)]
             if not noncurrent_for_oid:
                 del self.noncurrent[u64(oid)]
+        except KeyError:
+            logger.error("Couldn't find non-current %r", (oid, tid))
+
             
     def clearStats(self):
         self._n_adds = self._n_added_bytes = 0

src/ZEO/tests/test_cache.py

@@ -301,6 +301,37 @@ __test__ = dict(
     >>> cache.close()
     
     """,
+
+    broken_non_current =
+    r"""
+
+    In production, we saw a situation where an _del_noncurrent raused
+    a key error when trying to free space, causing the cache to become
+    unusable.  I can't see why this would occur, but added a logging
+    exception handler so, in the future, we'll still see cases in the
+    log, but will ignore the error and keep going.
+    
+    >>> import ZEO.cache, ZODB.utils, logging, sys
+    >>> logger = logging.getLogger('ZEO.cache')
+    >>> logger.setLevel(logging.ERROR)
+    >>> handler = logging.StreamHandler(sys.stdout)
+    >>> logger.addHandler(handler)
+    >>> cache = ZEO.cache.ClientCache('cache', 1000)
+    >>> cache.store(ZODB.utils.p64(1), '', ZODB.utils.p64(1), None, '0')
+    >>> cache.invalidate(ZODB.utils.p64(1), '', ZODB.utils.p64(2))
+    >>> cache._del_noncurrent(ZODB.utils.p64(1), ZODB.utils.p64(2))
+    ... # doctest: +NORMALIZE_WHITESPACE
+    Couldn't find non-current
+    ('\x00\x00\x00\x00\x00\x00\x00\x01', '\x00\x00\x00\x00\x00\x00\x00\x02')
+    >>> cache._del_noncurrent(ZODB.utils.p64(1), ZODB.utils.p64(1))
+    >>> cache._del_noncurrent(ZODB.utils.p64(1), ZODB.utils.p64(1)) # 
+    ... # doctest: +NORMALIZE_WHITESPACE
+    Couldn't find non-current
+    ('\x00\x00\x00\x00\x00\x00\x00\x01', '\x00\x00\x00\x00\x00\x00\x00\x01')
+
+    >>> logger.setLevel(logging.NOTSET)
+    >>> logger.removeHandler(handler)
+    """
     )