Merge 5780196 into 4374c44

CHANGES.rst

@@ -6,7 +6,8 @@
 3.1.1 (unreleased)
 ==================
 
-- Nothing changed yet.
+- Fix logging of long duration commits. See `issue 44
+  <https://github.com/NextThought/nti.transactions/issues/44>`_.
 
 
 3.1.0 (2019-11-29)

setup.py

@@ -9,6 +9,7 @@
 }
 
 TESTS_REQUIRE = [
+    'coverage',
     'fudge',
     'nti.testing',
     'pylint',

src/nti/transactions/loop.py

@@ -59,7 +59,7 @@ def exc_clear():
 
 logger = getLogger(__name__)
 
-def _do_commit(tx, description, long_commit_duration,
+def _do_commit(tx, long_commit_duration,
                retries, sleep_time,
                _logger=logger,
                _DEBUG=DEBUG,
@@ -76,8 +76,8 @@ def _do_commit(tx, description, long_commit_duration,
         if _logger.isEnabledFor(level):
             _logger.log(
                 level,
-                "Committed transaction description=%s, duration=%s, retries=%s, sleep_time=%s",
-                description, duration, retries, sleep_time
+                "Committed transaction description=%r, duration=%s, retries=%s, sleep_time=%s",
+                tx.description, duration, retries, sleep_time
             )
     except TypeError:
         # Translate this into something meaningful
@@ -114,6 +114,14 @@ class TransactionLoop(object):
     commit is vetoed by :meth:`should_abort_due_to_no_side_effects` or
     :meth:`should_veto_commit` is never retried.
 
+    Aborting or committing the transaction will set these :mod:`perfmetrics`
+    timers:
+
+    transaction.commit
+        Time taken to commit the transaction. Sampled.
+    transaction.abort
+        Time taken to abort the transaction. Sampled.
+
     Running the loop will increment these :mod:`perfmetrics` counters
     (new in 3.1):
 
@@ -215,7 +223,7 @@ def __init__(
             long_commit_duration=None, # type: float
     ):
         """
-        :keyword float sleep: Sets the :attr:`initial_retry_delay`.
+        :keyword float sleep: Sets the :attr:`sleep`.
         :keyword int retries: If given, the number of times a transaction will be
             retried. Note that this is one less than the total number of
             :attr:`attempts`
@@ -528,7 +536,12 @@ def __loop(self, txm, note, stats, args, kwargs):
                     stats('transaction.doomed' if tx.isDoomed() else 'transaction.vetoed')
                     raise self.AbortAndReturn(result, "doomed or vetoed")
 
-                _do_commit(tx, note, attempt_number, sleep_time, self.long_commit_duration)
+                _do_commit(
+                    tx,
+                    self.long_commit_duration,
+                    attempt_number,
+                    sleep_time,
+                )
                 stats('transaction.successful')
                 if attempt_number:
                     stats('transaction.retry', self.attempts - 1 - attempts_remaining)

src/nti/transactions/pyramid_tween.py

@@ -151,10 +151,6 @@ class TransactionTween(TransactionLoop):
     and :func:`is_error_retryable` can be used to influence handler behaviour.
     """
 
-    # TODO: Take the number of attempts, sleep delay,
-    # delay backoff time/multiplier, long_commit_duration and
-    # side_effect_free as config params. Maybe model on pyramid_tm?
-
     def prep_for_retry(self, attempts_remaining, tx, request): # pylint:disable=arguments-differ
         """
         Prepares the request for possible retries.

src/nti/transactions/tests/test_loop.py

@@ -5,6 +5,7 @@
 
 # pylint:disable=too-many-public-methods
 
+import logging
 import sys
 import unittest
 
@@ -49,13 +50,17 @@
 
 
 class TestCommit(unittest.TestCase):
-    class RaisingCommit(object):
-        def __init__(self, t=Exception):
+    class Transaction(object):
+        description = u''
+        def __init__(self, t=None):
             self.t = t
 
         def nti_commit(self):
             if self.t:
-                raise self.t
+                raise self.t # (Python2, old pylint)  pylint:disable=raising-bad-type
+
+    def RaisingCommit(self, t=Exception):
+        return self.Transaction(t)
 
     def test_commit_raises_type_error_raises_commit_failed(self):
         assert_that(calling(_do_commit)
@@ -74,7 +79,7 @@ def test_commit_raises_type_error_raises_commit_failed_good_message(self):
                     raises(CommitFailedError, "A custom message"))
 
 
-    @fudge.patch('nti.transactions.transactions.logger.exception')
+    @fudge.patch('nti.transactions.loop.logger.exception')
     def test_commit_raises_assertion_error(self, fake_logger):
         fake_logger.expects_call()
 
@@ -84,7 +89,7 @@ def test_commit_raises_assertion_error(self, fake_logger):
                     ),
                     raises(AssertionError))
 
-    @fudge.patch('nti.transactions.transactions.logger.exception')
+    @fudge.patch('nti.transactions.loop.logger.exception')
     def test_commit_raises_value_error(self, fake_logger):
         fake_logger.expects_call()
 
@@ -95,7 +100,7 @@ def test_commit_raises_value_error(self, fake_logger):
                     ),
                     raises(ValueError))
 
-    @fudge.patch('nti.transactions.transactions.logger.exception')
+    @fudge.patch('nti.transactions.loop.logger.exception')
     def test_commit_raises_custom_error(self, fake_logger):
         fake_logger.expects_call()
 
@@ -115,14 +120,39 @@ class MyException(Exception):
     @fudge.patch('nti.transactions.loop.logger.log')
     def test_commit_clean_but_long(self, fake_logger):
         fake_logger.expects_call()
-        _do_commit(self.RaisingCommit(None), '', -1, 0, 0)
+        _do_commit(self.RaisingCommit(None), -1, 0, 0)
+
+
+    @fudge.patch('nti.transactions.loop.logger.isEnabledFor',
+                 'nti.transactions.loop.logger.log')
+    def test_commit_duration_logging_short(self, fake_is_enabled, fake_log):
+        fake_is_enabled.expects_call().returns(True).with_args(logging.DEBUG)
+        fake_log.expects_call()
+        _do_commit(self.Transaction(), 6, 0, 0)
+
+    @fudge.patch('nti.transactions.loop.logger.isEnabledFor',
+                 'nti.transactions.loop.logger.log')
+    def test_commit_duration_logging_long(self, fake_is_enabled, fake_log):
+        fake_is_enabled.expects_call().returns(True).with_args(logging.WARNING)
+        fake_log.expects_call()
+        fake_perf_counter = fudge.Fake(
+        ).expects_call(
+        ).returns(
+            0
+        ).next_call(
+        ).returns(
+            10
+        )
+        _do_commit(self.Transaction(), 6, 0, 0, _perf_counter=fake_perf_counter)
+
 
 class TrueStatsDClient(FakeStatsDClient):
     # https://github.com/zodb/perfmetrics/issues/23
     def __bool__(self):
         return True
     __nonzero__ = __bool__
 
+
 class TestLoop(unittest.TestCase):
 
     def setUp(self):
@@ -140,8 +170,21 @@ def tearDown(self):
         statsd_client_stack.pop()
         zope.event.subscribers.remove(self.events.append)
 
-    def test_trivial(self):
-        result = TransactionLoop(lambda a: a, retries=1, long_commit_duration=1, sleep=1)(1)
+    @fudge.patch('nti.transactions.loop._do_commit')
+    def test_trivial(self, fake_commit):
+        class Any(object):
+            def __eq__(self, other):
+                return True
+
+        loop = TransactionLoop(lambda a: a, retries=1, long_commit_duration=1, sleep=1)
+        fake_commit.expects_call().with_args(
+            Any(), # transaction
+            loop.long_commit_duration,
+            0, # attempt number / retries
+            0 # sleep_time
+        )
+
+        result = loop(1)
         assert_that(result, is_(1))
         # May or may not get a transaction.commit stat first, depending on random
         assert_that(self.statsd_client.packets, has_length(greater_than_or_equal_to(1)))
@@ -389,13 +432,15 @@ def should_veto_commit(self, result, *args, **kwargs):
                     has_items(
                         is_counter(name='transaction.vetoed', value=1)))
 
-    @fudge.patch('transaction._manager.TransactionManager.begin')
-    def test_abort_systemexit(self, fake_begin):
+    @fudge.patch('transaction._manager.TransactionManager.begin',
+                 'sys.stderr')
+    def test_abort_systemexit(self, fake_begin, fake_stderr):
         fake_tx = fudge.Fake()
         fake_tx.expects('abort').raises(ValueError)
         fake_tx.provides('isDoomed').returns(False)
 
         fake_begin.expects_call().returns(fake_tx)
+        fake_stderr.provides('write')
 
         def handler():
             raise SystemExit()