Merge pull request #192 from zopefoundation/tpc_vote+abort_fixes#156

tpc_vote/abort + log message enhancements

CHANGES.rst

@@ -4,11 +4,27 @@ Changelog
 5.3.1 (unreleased)
 ------------------
 
+- Add ``ConflictError`` to the list of unlogged server exceptions
+  (the client/its application should determine whether it wants
+  them logged).
+
+  Prevent ``no current transaction: tpc_abort()`` server log entries.
+  The storage API allows ``tpc_abort`` to be called with an
+  invalid transaction (the call should be ignored in this case)
+  and the server's ``tpc_vote`` relies on this.
+
+  Change the server's log message label for request exceptions
+  from ``Bad request ...`` to ``... raised exception:``,
+  hinting towards a server rather than client problem.
+
+  See `issue 156 <https://github.com/zopefoundation/ZEO/issues/156>`_.
+
+
 
 5.3.0 (2022-03-24)
 ------------------
 
-- Remove tests for the `asyncio/mtacceptor` module, it appears unused
+- Remove tests for the ``asyncio/mtacceptor`` module, it appears unused
   and presents a maintenance burden. The module will be removed in
   ZEO version 6.
 

src/ZEO/StorageServer.py

@@ -182,6 +182,9 @@ class ZEOStorage(object):
             raise ReadOnlyError()
         if self.transaction is None:
             caller = sys._getframe().f_back.f_code.co_name
+            # ``tpc_abort`` is allowed to be called with invalid transaction
+            # ``vote`` relies on this
+            if caller != "tpc_abort":
                 self.log("no current transaction: %s()" % caller,
                          level=logging.WARNING)
             if exc is not None:
@@ -190,6 +193,8 @@ class ZEOStorage(object):
                 return 0
         if self.transaction.id != tid:
             caller = sys._getframe().f_back.f_code.co_name
+            # ``tpc_abort`` is allowed to be called with invalid transaction
+            if caller != "tpc_abort":
                 self.log("%s(%s) invalid; current transaction = %s" %
                          (caller, repr(tid), repr(self.transaction.id)),
                          logging.WARNING)

src/ZEO/asyncio/client.py

@@ -131,7 +131,7 @@ class Protocol(base.Protocol):
                 logger.info("Connection to %r cancelled", self.addr)
             elif future.exception() is not None:
                 logger.info("Connection to %r failed, %s",
-                            (self.addr, future.exception()))
+                            self.addr, future.exception())
             else: return
             # keep trying
             if not self.closed:

src/ZEO/asyncio/server.py

@@ -24,6 +24,8 @@ class ServerProtocol(base.Protocol):
 
     unlogged_exception_types = (
         ZODB.POSException.POSKeyError,
+        ZODB.POSException.ConflictError,
+        ZODB.POSException.ReadConflictError,
         )
 
     def __init__(self, loop, addr, zeo_storage, msgpack):
@@ -104,7 +106,8 @@ class ServerProtocol(base.Protocol):
         except Exception as exc:
             if not isinstance(exc, self.unlogged_exception_types):
                 logger.exception(
-                    "Bad %srequest, %r", 'async ' if async_ else '', name)
+                    "%s`%r` raised exception:",
+                    'async ' if async_ else '', name)
             if async_:
                 return self.close() # No way to recover/cry for help
             else:
@@ -163,6 +166,7 @@ class Delay(object):
     """
 
     msgid = protocol = sent = None
+    unlogged_exception_types = ServerProtocol.unlogged_exception_types
 
     def set_sender(self, msgid, protocol):
         self.msgid = msgid
@@ -175,6 +179,7 @@ class Delay(object):
 
     def error(self, exc_info):
         self.sent = 'error'
+        if exc_info[0] not in self.unlogged_exception_types:
             logger.error("Error raised in delayed method", exc_info=exc_info)
         if self.protocol:
             self.protocol.send_error(self.msgid, exc_info[1])

src/ZEO/tests/testZEO2.py

@@ -92,9 +92,6 @@ client will be restarted.  It will get a conflict error, that is
 raised to the client:
 
     >>> zs1.tpc_abort('0') # doctest: +ELLIPSIS
-    Error raised in delayed method
-    Traceback (most recent call last):
-    ...ConflictError: ...
     error 1 database conflict error ...
 
 The transaction is aborted by the server: