before_sleep_log: Add an exc_info option to include exception traceba…

…cks (#227)

* before_sleep_log: More specific tests to show how log messages look

* before_sleep_log: Add an exc_info option to include exception tracebacks

* fixup! before_sleep_log: Add an exc_info option to include exception tracebacks

Fix pep8 failures.

* fixup! before_sleep_log: Add an exc_info option to include exception tracebacks

* Add release note.

releasenotes/notes/before_sleep_log-improvements-d8149274dfb37d7c.yaml

@@ -0,0 +1,3 @@
+---
+features:
+  - Add an ``exc_info`` option to the ``before_sleep_log()`` strategy.

tenacity/before_sleep.py

@@ -15,23 +15,32 @@
 # limitations under the License.
 
 from tenacity import _utils
+from tenacity.compat import get_exc_info_from_future
 
 
 def before_sleep_nothing(retry_state):
     """Before call strategy that does nothing."""
 
 
-def before_sleep_log(logger, log_level):
+def before_sleep_log(logger, log_level, exc_info=False):
     """Before call strategy that logs to some logger the attempt."""
     def log_it(retry_state):
         if retry_state.outcome.failed:
-            verb, value = 'raised', retry_state.outcome.exception()
+            ex = retry_state.outcome.exception()
+            verb, value = 'raised', '%s: %s' % (type(ex).__name__, ex)
+
+            if exc_info:
+                local_exc_info = get_exc_info_from_future(retry_state.outcome)
+            else:
+                local_exc_info = False
         else:
             verb, value = 'returned', retry_state.outcome.result()
+            local_exc_info = False  # exc_info does not apply when no exception
 
         logger.log(log_level,
                    "Retrying %s in %s seconds as it %s %s.",
                    _utils.get_callback_name(retry_state.fn),
                    getattr(retry_state.next_action, 'sleep'),
-                   verb, value)
+                   verb, value,
+                   exc_info=local_exc_info)
     return log_it

tenacity/compat.py

@@ -299,3 +299,24 @@ def wrapped_retry_error_callback(retry_state):
             'retry_error_callback', fn, stacklevel=4)
         return fn(retry_state.outcome)
     return wrapped_retry_error_callback
+
+
+def get_exc_info_from_future(future):
+    """
+    Get an exc_info value from a Future.
+
+    Given a a Future instance, retrieve an exc_info value suitable for passing
+    in as the exc_info parameter to logging.Logger.log() and related methods.
+
+    On Python 2, this will be a (type, value, traceback) triple.
+    On Python 3, this will be an exception instance (with embedded traceback).
+
+    If there was no exception, None is returned on both versions of Python.
+    """
+    if six.PY3:
+        return future.exception()
+    else:
+        ex, tb = future.exception_info()
+        if ex is None:
+            return None
+        return type(ex), ex, tb

tenacity/tests/test_tenacity.py

@@ -14,6 +14,8 @@
 # See the License for the specific language governing permissions and
 # limitations under the License.
 import logging
+import os
+import re
 import sys
 import time
 import typing
@@ -1157,20 +1159,52 @@ def test_before_sleep_log_raises(self):
         finally:
             logger.removeHandler(handler)
 
-        etalon_re = r'Retrying .* in 0\.01 seconds as it raised .*\.'
+        etalon_re = (r"^Retrying .* in 0\.01 seconds as it raised "
+                     r"(IO|OS)Error: Hi there, I'm an IOError\.$")
         self.assertEqual(len(handler.records), 2)
-        self.assertRegexpMatches(handler.records[0].getMessage(), etalon_re)
-        self.assertRegexpMatches(handler.records[1].getMessage(), etalon_re)
+        fmt = logging.Formatter().format
+        self.assertRegexpMatches(fmt(handler.records[0]), etalon_re)
+        self.assertRegexpMatches(fmt(handler.records[1]), etalon_re)
 
-    def test_before_sleep_log_returns(self):
+    def test_before_sleep_log_raises_with_exc_info(self):
+        thing = NoIOErrorAfterCount(2)
+        logger = logging.getLogger(self.id())
+        logger.propagate = False
+        logger.setLevel(logging.INFO)
+        handler = CapturingHandler()
+        logger.addHandler(handler)
+        try:
+            _before_sleep = tenacity.before_sleep_log(logger,
+                                                      logging.INFO,
+                                                      exc_info=True)
+            retrying = Retrying(wait=tenacity.wait_fixed(0.01),
+                                stop=tenacity.stop_after_attempt(3),
+                                before_sleep=_before_sleep)
+            retrying.call(thing.go)
+        finally:
+            logger.removeHandler(handler)
+
+        etalon_re = re.compile(r"^Retrying .* in 0\.01 seconds as it raised "
+                               r"(IO|OS)Error: Hi there, I'm an IOError\.{0}"
+                               r"Traceback \(most recent call last\):{0}"
+                               r".*$".format(os.linesep),
+                               flags=re.MULTILINE)
+        self.assertEqual(len(handler.records), 2)
+        fmt = logging.Formatter().format
+        self.assertRegexpMatches(fmt(handler.records[0]), etalon_re)
+        self.assertRegexpMatches(fmt(handler.records[1]), etalon_re)
+
+    def test_before_sleep_log_returns(self, exc_info=False):
         thing = NoneReturnUntilAfterCount(2)
         logger = logging.getLogger(self.id())
         logger.propagate = False
         logger.setLevel(logging.INFO)
         handler = CapturingHandler()
         logger.addHandler(handler)
         try:
-            _before_sleep = tenacity.before_sleep_log(logger, logging.INFO)
+            _before_sleep = tenacity.before_sleep_log(logger,
+                                                      logging.INFO,
+                                                      exc_info=exc_info)
             _retry = tenacity.retry_if_result(lambda result: result is None)
             retrying = Retrying(wait=tenacity.wait_fixed(0.01),
                                 stop=tenacity.stop_after_attempt(3),
@@ -1179,10 +1213,14 @@ def test_before_sleep_log_returns(self):
         finally:
             logger.removeHandler(handler)
 
+        etalon_re = r'^Retrying .* in 0\.01 seconds as it returned None\.$'
         self.assertEqual(len(handler.records), 2)
-        etalon_re = r'Retrying .* in 0\.01 seconds as it returned None'
-        self.assertRegexpMatches(handler.records[0].getMessage(), etalon_re)
-        self.assertRegexpMatches(handler.records[1].getMessage(), etalon_re)
+        fmt = logging.Formatter().format
+        self.assertRegexpMatches(fmt(handler.records[0]), etalon_re)
+        self.assertRegexpMatches(fmt(handler.records[1]), etalon_re)
+
+    def test_before_sleep_log_returns_with_exc_info(self):
+        self.test_before_sleep_log_returns(exc_info=True)
 
 
 class TestReraiseExceptions(unittest.TestCase):