Log (Watchdog's) Timeouts with duration

... and clean up WatchDog start a little.

If this pattern proves useful we could consider extending it.

Change-Id: Ia85f9321b69bc4114a60c32a7ad082cae7da72b3

2 files changed, 14 insertions, 7 deletions

diff --git a/test/unit/common/test_utils.py b/test/unit/common/test_utils.py
index e477ee85d..300fdb021 100644
--- a/test/unit/common/test_utils.py
+++ b/test/unit/common/test_utils.py
@@ -1144,11 +1144,15 @@ class TestUtils(unittest.TestCase):
             # test eventlet.Timeout
             with ConnectionTimeout(42, 'my error message') \
                     as connection_timeout:
-                log_exception(connection_timeout)
+                now = time.time()
+                connection_timeout.created_at = now - 123.456
+                with mock.patch('swift.common.utils.time.time',
+                                return_value=now):
+                    log_exception(connection_timeout)
                 log_msg = strip_value(sio)
                 self.assertNotIn('Traceback', log_msg)
                 self.assertTrue('ConnectionTimeout' in log_msg)
-                self.assertTrue('(42s)' in log_msg)
+                self.assertTrue('(42s after 123.46s)' in log_msg)
                 self.assertNotIn('my error message', log_msg)
 
             with MessageTimeout(42, 'my error message') as message_timeout:
@@ -8744,13 +8748,16 @@ class TestWatchdog(unittest.TestCase):
         w._evt.send = mock.Mock(side_effect=w._evt.send)
         gth = object()
 
+        now = time.time()
+        timeout_value = 1.0
         with patch('eventlet.greenthread.getcurrent', return_value=gth),\
-                patch('time.time', return_value=10.0):
+                patch('time.time', return_value=now):
             # On first call, _next_expiration is None, it should unblock
             # greenthread that is blocked for ever
-            key = w.start(1.0, Timeout)
+            key = w.start(timeout_value, Timeout)
             self.assertIn(key, w._timeouts)
-            self.assertEqual(w._timeouts[key], (1.0, 11.0, gth, Timeout))
+            self.assertEqual(w._timeouts[key], (
+                timeout_value, now + timeout_value, gth, Timeout, now))
             w._evt.send.assert_called_once()
 
             w.stop(key)
diff --git a/test/unit/proxy/controllers/test_obj.py b/test/unit/proxy/controllers/test_obj.py
index 0b8bf1568..38c40b2db 100644
--- a/test/unit/proxy/controllers/test_obj.py
+++ b/test/unit/proxy/controllers/test_obj.py
@@ -4927,7 +4927,7 @@ class TestECObjController(ECObjectControllerMixin, unittest.TestCase):
         for line in error_lines[:nparity]:
             self.assertIn('retrying', line)
         for line in error_lines[nparity:]:
-            self.assertIn('ChunkReadTimeout (0.01s)', line)
+            self.assertIn('ChunkReadTimeout (0.01s', line)
         for line in self.logger.logger.records['ERROR']:
             self.assertIn(req.headers['x-trans-id'], line)
 
@@ -5012,7 +5012,7 @@ class TestECObjController(ECObjectControllerMixin, unittest.TestCase):
         error_lines = self.logger.get_lines_for_level('error')
         self.assertEqual(ndata, len(error_lines))
         for line in error_lines:
-            self.assertIn('ChunkReadTimeout (0.01s)', line)
+            self.assertIn('ChunkReadTimeout (0.01s', line)
         for line in self.logger.logger.records['ERROR']:
             self.assertIn(req.headers['x-trans-id'], line)