- A 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.

src/ZEO/cache.py

@@ -292,11 +292,15 @@ class ClientCache(object):
         noncurrent_for_oid[u64(tid)] = ofs
 
     def _del_noncurrent(self, oid, tid):
-        noncurrent_for_oid = self.noncurrent[u64(oid)]
-        del noncurrent_for_oid[u64(tid)]
-        if not noncurrent_for_oid:
-            del self.noncurrent[u64(oid)]
+        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
         self._n_evicts = self._n_evicted_bytes = 0

src/ZEO/tests/test_cache.py

@@ -313,6 +313,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)
+    """
     )
 
 def test_suite():