Truncate (to a configurable limit) very large lock errors. Fixes #511.

Author: jamadden

CHANGES.rst

@@ -5,7 +5,10 @@
 4.1.1 (unreleased)
 ==================
 
-- Nothing changed yet.
+- Make certain lock-related errors in very large transactions no
+  longer produce huge (unusable) error messages when logged or
+  printed. Now such messages are truncated. Previously, they were
+  allowed to grow without bounds. See :issue:`511`
 
 
 4.1.0 (2024-10-11)

src/relstorage/adapters/locker.py

@@ -254,9 +254,10 @@ def _modify_commit_lock_kind(self, kind, exc): # pylint:disable=unused-argument
         return kind
 
     def reraise_commit_lock_error(self, cursor, lock_stmt, kind):
-        v = sys.exc_info()[1]
-        kind = self._modify_commit_lock_kind(kind, v)
-        if self.driver.exception_is_deadlock(v):
+        _current_exc_type, current_exc, current_tb = sys.exc_info()
+
+        kind = self._modify_commit_lock_kind(kind, current_exc)
+        if self.driver.exception_is_deadlock(current_exc):
             kind = getattr(kind, 'DEADLOCK_VARIANT', UnableToLockRowsDeadlockError)
 
         try:
@@ -270,13 +271,15 @@ def reraise_commit_lock_error(self, cursor, lock_stmt, kind):
             logger.debug("Failed to acquire commit lock:\n%s", debug_info)
 
         message = "Acquiring a lock during commit failed: %s%s" % (
-            sys.exc_info()[1],
+            current_exc,
             '\n' + debug_info if debug_info else '(No debug info.)'
         )
         val = kind(message)
-        val.__relstorage_cause__ = v
-        del v
-        raise val.with_traceback(sys.exc_info()[2])
+        val.__relstorage_cause__ = current_exc
+        try:
+            raise val.with_traceback(current_tb) from current_exc
+        finally:
+            del current_exc, current_tb
 
     # MySQL allows aggregates in the top level to use FOR UPDATE,
     # but PostgreSQL does not, so we have to use the second form.
@@ -342,6 +345,8 @@ def _get_commit_lock_debug_info(self, cursor, was_failure=False):
         that will be added to the exception message when a commit lock cannot
         be acquired. For example, it might list other connections that
         have conflicting locks.
+
+        :rtype: str
         """
         return ''
 

src/relstorage/storage/tpc/__init__.py

@@ -133,8 +133,8 @@ def local_client(self):
     def store_connection(self):
         conn = self._storage._store_connection_pool.borrow()
         # Report on the connection we will use.
-        # https://github.com/zodb/relstorage/issues/460
-        logger.info("Using store connection %s", conn)
+        #  https://github.com/zodb/relstorage/issues/460
+        logger.debug("Using store connection %s", conn)
         return conn
 
     @store_connection.aborter

src/relstorage/storage/tpc/temporary_storage.py

@@ -155,6 +155,10 @@ def __repr__(self):
         )
 
     def __str__(self):
+        """
+        The string of this object can get very, very long, if the transaction
+        modifies a lot of objects.
+        """
         base = repr(self)
         if not self:
             return base

src/relstorage/storage/tpc/tests/test_vote.py

@@ -3,12 +3,9 @@
 Tests for vote.py.
 
 """
-from __future__ import absolute_import
-from __future__ import division
-from __future__ import print_function
-
 
 import unittest
+from unittest.mock import patch as Patch
 
 from hamcrest import assert_that
 from nti.testing.matchers import verifiably_provides
@@ -227,7 +224,7 @@ def _callFUT(self, ex, state, required_tids):
         add_details_to_lock_error(ex, state, required_tids)
         return ex
 
-    def _check(self, kind):
+    def _check(self, kind, truncated=False):
         ex = kind('MESSAGE')
         storage = MockStorage()
         storage.keep_history = False # pylint:disable=attribute-defined-outside-init
@@ -237,9 +234,9 @@ def _check(self, kind):
         self._callFUT(ex, state, {1: 1})
         s = str(ex)
         self.assertIn('readCurrent {oid: tid}', s)
-        self.assertIn('{1: 1}', s)
-        self.assertIn('Previous TID', s)
-        self.assertIn('42', s)
+        self.assertIn('{1: 1}' if not truncated else '{...', s)
+        self.assertIn('Previous TID' if not truncated else '<...', s)
+        self.assertIn('42' if not truncated else '', s)
         self.assertIn('MESSAGE', s)
 
     def test_add_details_to_UnableToAcquireCommitLockError(self):
@@ -250,6 +247,12 @@ def test_add_details_to_UnableToLockRowsToModifyError(self):
         from relstorage.adapters.interfaces import UnableToLockRowsToModifyError
         self._check(UnableToLockRowsToModifyError)
 
+    def test_add_truncated_details_to_UnableToLockRowsToModifyError(self):
+        from relstorage.adapters.interfaces import UnableToLockRowsToModifyError
+        from .. import vote
+        with Patch.object(vote, 'DETAIL_TRUNCATION_LEN', new=1):
+            self._check(UnableToLockRowsToModifyError, truncated=True)
+
     def test_add_details_to_UnableToLockRowsToReadCurrentError(self):
         from relstorage.adapters.interfaces import UnableToLockRowsToReadCurrentError
         self._check(UnableToLockRowsToReadCurrentError)

src/relstorage/storage/tpc/vote.py

@@ -18,11 +18,9 @@
 temporary objects to the database, and moving them to their final locations,
 live here.
 """
-from __future__ import absolute_import
-from __future__ import print_function
 
 import time
-from logging import DEBUG
+import logging
 
 from zope.interface import implementer
 
@@ -37,6 +35,7 @@
 from relstorage._util import do_log_duration_info
 from relstorage._util import TRACE
 from relstorage._util import METRIC_SAMPLE_RATE
+from relstorage._util import get_positive_integer_from_environ
 from relstorage.options import COMMIT_EXIT_CRITICAL_SECTION_EARLY
 from relstorage.adapters.interfaces import UnableToAcquireLockError
 from ..interfaces import VoteReadConflictError
@@ -46,9 +45,9 @@
 from . import AbstractTPCStateDatabaseAvailable
 from .finish import Finish
 
-LOG_LEVEL_TID = DEBUG
+LOG_LEVEL_TID = logging.DEBUG
 
-logger = __import__('logging').getLogger(__name__)
+logger = logging.getLogger(__name__)
 perf_logger = logger.getChild('timing')
 
 class DatabaseLockedForTid(object):
@@ -663,14 +662,36 @@ def loadSerial(self, oid, serial):
         assert bytes8_to_int64(serial) == tid
         return state
 
+#: The maximum number of characters to allow in each portion
+#: of lock detail errors.
+DETAIL_TRUNCATION_LEN = get_positive_integer_from_environ(
+    'RS_LOCK_ERROR_MAX_LEN',
+    # 2k seems a reasonable default. If you are actually getting
+    # truncated, then chances are the transaction is much larger
+    # than that
+    2048,
+    logger=logger
+)
+
 def add_details_to_lock_error(ex, shared_state, required_tids):
     # type: (Exception, SharedState, required_tids)
+
+    obj_msg = str(shared_state.temp_storage) if shared_state.has_temp_data() else 'None'
+    tid_msg = str(dict(required_tids)) # May be a BTree, which has no useful str/repr
+
+    obj_msg = (obj_msg[:DETAIL_TRUNCATION_LEN] + '...'
+               if len(obj_msg) > DETAIL_TRUNCATION_LEN
+               else obj_msg)
+    tid_msg = (tid_msg[:DETAIL_TRUNCATION_LEN] + '...'
+               if len(tid_msg) > DETAIL_TRUNCATION_LEN
+               else tid_msg)
+
     message = '\n'.join((
-            'Stored Objects',
-            str(shared_state.temp_storage) if shared_state.has_temp_data() else 'None',
-            'readCurrent {oid: tid}',
-            str(dict(required_tids)) # May be a BTree, which has no
-        ))
+        'Stored Objects',
+        obj_msg,
+        'readCurrent {oid: tid}',
+        tid_msg,
+    ))
 
     if hasattr(ex, 'message'):
         # A ConflictError subclass *or* we're on Python 2.