Log "Retrying block" instead "Retrying None" etc. when there is no called function (#333)

This happens when `Retrying` is used as a context manager.

Author: Martin Kulhavy

tenacity/after.py

@@ -36,11 +36,13 @@ def after_log(
     """After call strategy that logs to some logger the finished attempt."""
 
     def log_it(retry_state: "RetryCallState") -> None:
+        target = "block" if retry_state.fn is None else f"call to '{_utils.get_callback_name(retry_state.fn)}'"
+        verb = "running" if retry_state.fn is None else "calling"
+
         logger.log(
             log_level,
-            f"Finished call to '{_utils.get_callback_name(retry_state.fn)}' "
-            f"after {sec_format % retry_state.seconds_since_start}(s), "
-            f"this was the {_utils.to_ordinal(retry_state.attempt_number)} time calling it.",
+            f"Finished {target} after {sec_format % retry_state.seconds_since_start}(s), "
+            f"this was the {_utils.to_ordinal(retry_state.attempt_number)} time {verb} it.",
         )
 
     return log_it

tenacity/before.py

@@ -32,10 +32,11 @@ def before_log(logger: "logging.Logger", log_level: int) -> typing.Callable[["Re
     """Before call strategy that logs to some logger the attempt."""
 
     def log_it(retry_state: "RetryCallState") -> None:
+        target = "block" if retry_state.fn is None else f"call to '{_utils.get_callback_name(retry_state.fn)}'"
+        verb = "running" if retry_state.fn is None else "calling"
         logger.log(
             log_level,
-            f"Starting call to '{_utils.get_callback_name(retry_state.fn)}', "
-            f"this is the {_utils.to_ordinal(retry_state.attempt_number)} time calling it.",
+            f"Starting {target}, this is the {_utils.to_ordinal(retry_state.attempt_number)} time {verb} it.",
         )
 
     return log_it

tenacity/before_sleep.py

@@ -48,10 +48,10 @@ def log_it(retry_state: "RetryCallState") -> None:
             verb, value = "returned", retry_state.outcome.result()
             local_exc_info = False  # exc_info does not apply when no exception
 
+        target = "block" if retry_state.fn is None else _utils.get_callback_name(retry_state.fn)
         logger.log(
             log_level,
-            f"Retrying {_utils.get_callback_name(retry_state.fn)} "
-            f"in {retry_state.next_action.sleep} seconds as it {verb} {value}.",
+            f"Retrying {target} in {retry_state.next_action.sleep} seconds as it {verb} {value}.",
             exc_info=local_exc_info,
         )
 

tests/test_after.py

@@ -32,7 +32,7 @@ def test_01_default(self):
         )
 
     def test_02_custom_sec_format(self):
-        """Test log formatting with custom int format.."""
+        """Test log formatting with custom int format."""
         log = unittest.mock.MagicMock(spec="logging.Logger.log")
         logger = unittest.mock.MagicMock(spec="logging.Logger", log=log)
 
@@ -48,3 +48,25 @@ def test_02_custom_sec_format(self):
             f"after {sec_format % retry_state.seconds_since_start}(s), "
             f"this was the {_utils.to_ordinal(retry_state.attempt_number)} time calling it.",
         )
+
+    def test_03_no_call_function(self):
+        """Test log formatting when there is no called function.
+
+        E.g. when using as context manager.
+        """
+        log = unittest.mock.MagicMock(spec="logging.Logger.log")
+        logger = unittest.mock.MagicMock(spec="logging.Logger", log=log)
+
+        sec_format = "%0.3f"
+        delay_since_first_attempt = 0.1
+
+        retry_state = test_tenacity.make_retry_state(self.previous_attempt_number, delay_since_first_attempt)
+        retry_state.fn = None
+        fun = after_log(logger=logger, log_level=self.log_level)  # use default sec_format
+        fun(retry_state)
+        log.assert_called_once_with(
+            self.log_level,
+            f"Finished block "
+            f"after {sec_format % retry_state.seconds_since_start}(s), "
+            f"this was the {_utils.to_ordinal(retry_state.attempt_number)} time running it.",
+        )

tests/test_before.py

@@ -28,3 +28,22 @@ def test_01_default(self):
             f"Starting call to '{_utils.get_callback_name(retry_state.fn)}', "
             f"this is the {_utils.to_ordinal(retry_state.attempt_number)} time calling it.",
         )
+
+    def test_02_no_call_function(self):
+        """Test log formatting when there is no called function.
+
+        E.g. when using as context manager.
+        """
+        log = unittest.mock.MagicMock(spec="logging.Logger.log")
+        logger = unittest.mock.MagicMock(spec="logging.Logger", log=log)
+
+        delay_since_first_attempt = 0.1
+
+        retry_state = test_tenacity.make_retry_state(self.previous_attempt_number, delay_since_first_attempt)
+        retry_state.fn = None
+        fun = before_log(logger=logger, log_level=self.log_level)
+        fun(retry_state)
+        log.assert_called_once_with(
+            self.log_level,
+            f"Starting block, this is the {_utils.to_ordinal(retry_state.attempt_number)} time running it.",
+        )

tests/test_before_sleep.py

@@ -61,3 +61,30 @@ def test_02_wrong_return(self):
             f"in {sleep} seconds as it returned {retry_state.outcome.result()}.",
             exc_info=False,
         )
+
+    def test_03_wrong_return_no_call_function(self):
+        """Test log formatting when there is no called function.
+
+        E.g. when using as context manager.
+        """
+        log = unittest.mock.MagicMock(spec="logging.Logger.log")
+        logger = unittest.mock.MagicMock(spec="logging.Logger", log=log)
+
+        delay_since_first_attempt = 0.1
+        sleep = 2
+
+        retry_state = test_tenacity.make_retry_state(self.previous_attempt_number, delay_since_first_attempt)
+        retry_state.fn = None
+        retry_state.next_action = unittest.mock.MagicMock(spec="tenacity.RetryAction", sleep=sleep)
+        retry_state.outcome = unittest.mock.MagicMock(
+            spec="tenacity.Future",
+            failed=False,
+            result=unittest.mock.Mock(return_value="infinity"),
+        )
+        fun = before_sleep_log(logger=logger, log_level=self.log_level)
+        fun(retry_state)
+        log.assert_called_once_with(
+            self.log_level,
+            f"Retrying block in {sleep} seconds as it returned {retry_state.outcome.result()}.",
+            exc_info=False,
+        )

tests/test_tenacity.py

@@ -50,6 +50,10 @@ def _set_delay_since_start(retry_state, delay):
     assert retry_state.seconds_since_start == delay
 
 
+def flaky_function():
+    """Just an empty function to use as the called function."""
+
+
 def make_retry_state(previous_attempt_number, delay_since_first_attempt, last_result=None):
     """Construct RetryCallState for given attempt number & delay.
 
@@ -63,7 +67,7 @@ def make_retry_state(previous_attempt_number, delay_since_first_attempt, last_re
             delay_since_first_attempt=delay_since_first_attempt,
         )
 
-    retry_state = RetryCallState(None, None, (), {})
+    retry_state = RetryCallState(None, flaky_function, (), {})
     retry_state.attempt_number = previous_attempt_number
     if last_result is not None:
         retry_state.outcome = last_result