diff --git a/tenacity/after.py b/tenacity/after.py index a38eae79..af87c70a 100644 --- a/tenacity/after.py +++ b/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 diff --git a/tenacity/before.py b/tenacity/before.py index 6a95406c..beef0ad3 100644 --- a/tenacity/before.py +++ b/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 diff --git a/tenacity/before_sleep.py b/tenacity/before_sleep.py index 44b9f70e..d8715fc7 100644 --- a/tenacity/before_sleep.py +++ b/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, ) diff --git a/tests/test_after.py b/tests/test_after.py index d98e3095..74b6de96 100644 --- a/tests/test_after.py +++ b/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.", + ) diff --git a/tests/test_before.py b/tests/test_before.py new file mode 100644 index 00000000..54462009 --- /dev/null +++ b/tests/test_before.py @@ -0,0 +1,49 @@ +import logging +import random +import unittest.mock + +from tenacity import before_log +from tenacity import _utils # noqa + +from . import test_tenacity + + +class TestBeforeLogFormat(unittest.TestCase): + def setUp(self) -> None: + self.log_level = random.choice((logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)) + self.previous_attempt_number = random.randint(1, 512) + + def test_01_default(self): + """Test log formatting.""" + 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) + fun = before_log(logger=logger, log_level=self.log_level) + fun(retry_state) + log.assert_called_once_with( + self.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.", + ) + + 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.", + ) diff --git a/tests/test_before_sleep.py b/tests/test_before_sleep.py new file mode 100644 index 00000000..7b4de12e --- /dev/null +++ b/tests/test_before_sleep.py @@ -0,0 +1,90 @@ +import logging +import random +import unittest.mock + +from tenacity import before_sleep_log +from tenacity import _utils # noqa + +from . import test_tenacity + + +class TestBeforeSleepLogFormat(unittest.TestCase): + def setUp(self) -> None: + self.log_level = random.choice((logging.DEBUG, logging.INFO, logging.WARNING, logging.ERROR, logging.CRITICAL)) + self.previous_attempt_number = random.randint(1, 512) + + def test_01_failed(self): + """Test log formatting.""" + 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.next_action = unittest.mock.MagicMock(spec="tenacity.RetryAction", sleep=sleep) + retry_state.outcome = unittest.mock.MagicMock( + spec="tenacity.Future", + failed=True, + exception=unittest.mock.Mock(return_value=FileNotFoundError("Not found")), + ) + fun = before_sleep_log(logger=logger, log_level=self.log_level) + fun(retry_state) + log.assert_called_once_with( + self.log_level, + f"Retrying {_utils.get_callback_name(retry_state.fn)} " + f"in {sleep} seconds as it raised " + f"{retry_state.outcome.exception().__class__.__name__}: {retry_state.outcome.exception()}.", + exc_info=False, + ) + + def test_02_wrong_return(self): + """Test log formatting.""" + 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.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 {_utils.get_callback_name(retry_state.fn)} " + 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, + ) diff --git a/tests/test_tenacity.py b/tests/test_tenacity.py index 2e5febd8..85968ed2 100644 --- a/tests/test_tenacity.py +++ b/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