From a7f548520e4ee871ad8aeb354ecfa1a324c8ca19 Mon Sep 17 00:00:00 2001
From: Alexey Stepanov <penguinolog@users.noreply.github.com>
Date: Mon, 12 Jul 2021 11:34:42 +0200
Subject: [PATCH] Fix after_log logger format (#317)

Co-authored-by: akgnah <1024@setq.me>

Co-authored-by: akgnah <1024@setq.me>
---
 .../notes/after_log-50f4d73b24ce9203.yaml     |  3 ++
 tenacity/after.py                             |  4 +-
 tests/test_after.py                           | 50 +++++++++++++++++++
 3 files changed, 55 insertions(+), 2 deletions(-)
 create mode 100644 releasenotes/notes/after_log-50f4d73b24ce9203.yaml
 create mode 100644 tests/test_after.py

diff --git a/releasenotes/notes/after_log-50f4d73b24ce9203.yaml b/releasenotes/notes/after_log-50f4d73b24ce9203.yaml
new file mode 100644
index 00000000..b8023e11
--- /dev/null
+++ b/releasenotes/notes/after_log-50f4d73b24ce9203.yaml
@@ -0,0 +1,3 @@
+---
+fixes:
+  - "Fix after_log logger format: function name was used with delay formatting."
diff --git a/tenacity/after.py b/tenacity/after.py
index 9dc55726..a38eae79 100644
--- a/tenacity/after.py
+++ b/tenacity/after.py
@@ -36,10 +36,10 @@ def after_log(
     """After call strategy that logs to some logger the finished attempt."""
 
     def log_it(retry_state: "RetryCallState") -> None:
-        sec = sec_format % _utils.get_callback_name(retry_state.fn)
         logger.log(
             log_level,
-            f"Finished call to '{sec}' after {retry_state.seconds_since_start}(s), "
+            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.",
         )
 
diff --git a/tests/test_after.py b/tests/test_after.py
new file mode 100644
index 00000000..d98e3095
--- /dev/null
+++ b/tests/test_after.py
@@ -0,0 +1,50 @@
+import logging
+import random
+import unittest.mock
+
+from tenacity import after_log
+from tenacity import _utils  # noqa
+
+from . import test_tenacity
+
+
+class TestAfterLogFormat(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)
+
+        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)
+        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 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.",
+        )
+
+    def test_02_custom_sec_format(self):
+        """Test log formatting with custom int format.."""
+        log = unittest.mock.MagicMock(spec="logging.Logger.log")
+        logger = unittest.mock.MagicMock(spec="logging.Logger", log=log)
+
+        sec_format = "%.1f"
+        delay_since_first_attempt = 0.1
+
+        retry_state = test_tenacity.make_retry_state(self.previous_attempt_number, delay_since_first_attempt)
+        fun = after_log(logger=logger, log_level=self.log_level, sec_format=sec_format)
+        fun(retry_state)
+        log.assert_called_once_with(
+            self.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.",
+        )