Merge pull request #24 from zopefoundation/better-setstate-failure-logging

provide more information when logging setstate failures

src/ZODB/Connection.py

@@ -68,6 +68,12 @@ def resetCaches():
     global global_reset_counter
     global_reset_counter += 1
 
+
+def className(obj):
+    cls = type(obj)
+    return "%s.%s" % (cls.__module__, cls.__name__)
+
+
 @implementer(IConnection,
              ISavepointDataManager,
              IPersistentDataManager,
@@ -853,18 +859,23 @@ class Connection(ExportImport, object):
         oid = obj._p_oid
 
         if self.opened is None:
-            msg = ("Shouldn't load state for %s "
-                   "when the connection is closed" % oid_repr(oid))
-            self._log.error(msg)
-            raise ConnectionStateError(msg)
+            msg = ("Shouldn't load state for %s %s "
+                   "when the connection is closed"
+                   % (className(obj), oid_repr(oid)))
+            try:
+                raise ConnectionStateError(msg)
+            except:
+                self._log.exception(msg)
+                raise
 
         try:
             self._setstate(obj)
         except ConflictError:
             raise
         except:
-            self._log.error("Couldn't load state for %s", oid_repr(oid),
-                            exc_info=sys.exc_info())
+            self._log.exception("Couldn't load state for %s %s",
+                                className(obj), oid_repr(oid),
+                                exc_info=sys.exc_info())
             raise
 
     def _setstate(self, obj):

src/ZODB/tests/testConnection.py

@@ -25,7 +25,7 @@ from ZODB.config import databaseFromString
 from ZODB.utils import p64
 from persistent import Persistent
 from zope.interface.verify import verifyObject
-from zope.testing import renormalizing
+from zope.testing import loggingsupport, renormalizing
 
 checker = renormalizing.RENormalizing([
     # Python 3 bytes add a "b".
@@ -164,6 +164,37 @@ class ConnectionDotAdd(ZODB.tests.util.TestCase):
         self.assertFalse(new_cache is old_cache)
         self.assertTrue(self.datamgr._reader._cache is new_cache)
 
+
+class SetstateErrorLoggingTests(ZODB.tests.util.TestCase):
+
+    def setUp(self):
+        ZODB.tests.util.TestCase.setUp(self)
+        from ZODB.Connection import Connection
+        self.db = db = databaseFromString("<zodb>\n<mappingstorage/>\n</zodb>")
+        self.datamgr = self.db.open()
+        self.object = StubObject()
+        self.datamgr.add(self.object)
+        transaction.commit()
+        self.handler = loggingsupport.InstalledHandler("ZODB")
+
+    def tearDown(self):
+        self.handler.uninstall()
+
+    def test_closed_connection_wont_setstate(self):
+        oid = self.object._p_oid
+        self.object._p_deactivate()
+        self.datamgr.close()
+        self.assertRaises(
+            ZODB.POSException.ConnectionStateError,
+            self.datamgr.setstate, self.object)
+        record, = self.handler.records
+        self.assertEqual(
+            record.msg,
+            "Shouldn't load state for ZODB.tests.testConnection.StubObject"
+            " 0x01 when the connection is closed")
+        self.assert_(record.exc_info)
+
+
 class UserMethodTests(unittest.TestCase):
 
     # add isn't tested here, because there are a bunch of traditional
@@ -1296,6 +1327,7 @@ class StubDatabase:
 
 def test_suite():
     s = unittest.makeSuite(ConnectionDotAdd)
+    s.addTest(unittest.makeSuite(SetstateErrorLoggingTests))
     s.addTest(doctest.DocTestSuite(checker=checker))
     s.addTest(unittest.makeSuite(TestConnectionInterface))
     s.addTest(unittest.makeSuite(EstimatedSizeTests))