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

3 files changed, 28 insertions, 20 deletions

diff --git a/swift/common/utils/__init__.py b/swift/common/utils/__init__.py
index 16dc58807..e5291199e 100644
--- a/swift/common/utils/__init__.py
+++ b/swift/common/utils/__init__.py
@@ -1611,8 +1611,10 @@ class LogAdapter(logging.LoggerAdapter, object):
             emsg = '%s: %s' % (exc.__class__.__name__, exc.line)
         elif isinstance(exc, eventlet.Timeout):
             emsg = exc.__class__.__name__
-            if hasattr(exc, 'seconds'):
-                emsg += ' (%ss)' % exc.seconds
+            detail = '%ss' % exc.seconds
+            if hasattr(exc, 'created_at'):
+                detail += ' after %0.2fs' % (time.time() - exc.created_at)
+            emsg += ' (%s)' % detail
             if isinstance(exc, swift.common.exceptions.MessageTimeout):
                 if exc.msg:
                     emsg += ' %s' % exc.msg
@@ -6176,14 +6178,15 @@ class Watchdog(object):
 
         :param timeout: duration before the timeout expires
         :param exc: exception to throw when the timeout expire, must inherit
-                    from eventlet.timeouts.Timeout
+                    from eventlet.Timeout
         :param timeout_at: allow to force the expiration timestamp
         :return: id of the scheduled timeout, needed to cancel it
         """
+        now = time.time()
         if not timeout_at:
-            timeout_at = time.time() + timeout
+            timeout_at = now + timeout
         gth = eventlet.greenthread.getcurrent()
-        timeout_definition = (timeout, timeout_at, gth, exc)
+        timeout_definition = (timeout, timeout_at, gth, exc, now)
         key = id(timeout_definition)
         self._timeouts[key] = timeout_definition
 
@@ -6206,8 +6209,7 @@ class Watchdog(object):
         :param key: timeout id, as returned by start()
         """
         try:
-            if key in self._timeouts:
-                del(self._timeouts[key])
+            del(self._timeouts[key])
         except KeyError:
             pass
 
@@ -6227,15 +6229,14 @@ class Watchdog(object):
         self._next_expiration = None
         if self._evt.ready():
             self._evt.reset()
-        for k, (timeout, timeout_at, gth, exc) in list(self._timeouts.items()):
+        for k, (timeout, timeout_at, gth, exc,
+                created_at) in list(self._timeouts.items()):
             if timeout_at <= now:
-                try:
-                    if k in self._timeouts:
-                        del(self._timeouts[k])
-                except KeyError:
-                    pass
+                self.stop(k)
                 e = exc()
+                # set this after __init__ to keep it off the eventlet scheduler
                 e.seconds = timeout
+                e.created_at = created_at
                 eventlet.hubs.get_hub().schedule_call_global(0, gth.throw, e)
             else:
                 if (self._next_expiration is None
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)