Sleeping updates the loop's current time always. (#1228)

* Sleeping updates the loop's current time always.

That had been disabled for libuv, but now that we run timers in our own code that's not a concern anymore.

Fixes #1227.

* Try Python 3.5.5 because of the weird Illegal Instruction crash we suddenly see with 3.5.4

* Increase the value; test_sendall_timeout was often failing to actually timeout.

* Really python3.5

CHANGES.rst

@@ -7,7 +7,10 @@
 1.3.3 (unreleased)
 ==================
 
-- Nothing changed yet.
+- :func:`gevent.sleep` updates the loop's notion of the current time
+  before sleeping so that sleep duration corresponds more closely to
+  elapsed (wall clock) time. :class:`gevent.Timeout` does the same.
+  Reported by champax and FoP in :issue:`1227`.
 
 
 1.3.2.post0 (2018-05-30)

Makefile

@@ -129,7 +129,7 @@ BUILD_RUNTIMES?=$(PWD)/.runtimes
 PY278=$(BUILD_RUNTIMES)/snakepit/python2.7.8
 PY27=$(BUILD_RUNTIMES)/snakepit/python2.7.14
 PY34=$(BUILD_RUNTIMES)/snakepit/python3.4.7
-PY35=$(BUILD_RUNTIMES)/snakepit/python3.5.4
+PY35=$(BUILD_RUNTIMES)/snakepit/python3.5.5
 PY36=$(BUILD_RUNTIMES)/snakepit/python3.6.4
 PY37=$(BUILD_RUNTIMES)/snakepit/python3.7.0b4
 PYPY=$(BUILD_RUNTIMES)/snakepit/pypy5100
@@ -191,7 +191,7 @@ test-py34: $(PY34)
 	PYTHON=python3.4.7 PATH=$(BUILD_RUNTIMES)/versions/python3.4.7/bin:$(PATH) make develop basictest
 
 test-py35: $(PY35)
-	PYTHON=python3.5.4 PATH=$(BUILD_RUNTIMES)/versions/python3.5.4/bin:$(PATH) make develop basictest
+	PYTHON=python3.5.5 PATH=$(BUILD_RUNTIMES)/versions/python3.5.5/bin:$(PATH) make develop basictest
 
 test-py36: $(PY36)
 	PYTHON=python3.6.4 PATH=$(BUILD_RUNTIMES)/versions/python3.6.4/bin:$(PATH) make develop allbackendtest

scripts/install.sh

@@ -102,7 +102,7 @@ for var in "$@"; do
       install 3.4.7 python3.4.7
       ;;
     3.5)
-      install 3.5.4 python3.5.4
+      install 3.5.5 python3.5.5
       ;;
     3.6)
       install 3.6.4 python3.6.4

src/gevent/_config.py

@@ -230,7 +230,7 @@ class ImportableSetting(object):
         if '.' not in path:
             raise ImportError("Cannot import %r. "
                               "Required format: [path/][package.]module.class. "
-                              "Or choice from %r"
+                              "Or choose from %r"
                               % (path, list(self.shortname_map)))
 
         if '/' in path:

src/gevent/_ffi/watcher.py

@@ -514,7 +514,7 @@ class TimerMixin(object):
 
             # 1.3 changed the default for this to False *unless* the loop is
             # running a callback; see libuv for details. Note that
-            # starting Timeout objects internally still sets this to true.
+            # starting Timeout objects still sets this to true.
 
             self.loop.update_now()
         super(TimerMixin, self).start(callback, *args)

src/gevent/hub.py

@@ -152,6 +152,10 @@ def sleep(seconds=0, ref=True):
         waiter.get()
     else:
         with loop.timer(seconds, ref=ref) as t:
+            # Sleeping is expected to be an "absolute" measure with
+            # respect to time.time(), not a relative measure, so it's
+            # important to update the loop's notion of now before we start
+            loop.update_now()
             hub.wait(t)
 
 

src/gevent/timeout.py

@@ -232,7 +232,9 @@ class Timeout(BaseException):
             # regular timeout with user-provided exception
             throws = self.exception
 
-        self.timer.start(getcurrent().throw, throws)
+        # Make sure the timer updates the current time so that we don't
+        # expire prematurely.
+        self.timer.start(getcurrent().throw, throws, update=True)
 
     @classmethod
     def start_new(cls, timeout=None, exception=None, ref=True, _one_shot=False):

src/greentest/test__api_timeout.py

@@ -24,61 +24,125 @@ import greentest
 import weakref
 import time
 import gc
-from gevent import sleep, Timeout
-DELAY = 0.04
+
+from gevent import sleep
+from gevent import Timeout
+from gevent import get_hub
+
+
+from greentest.timing import SMALL_TICK as DELAY
 
 
 class Error(Exception):
     pass
 
 
+class _UpdateNowProxy(object):
+
+    update_now_calls = 0
+
+    def __init__(self, loop):
+        self.loop = loop
+
+    def __getattr__(self, name):
+        return getattr(self.loop, name)
+
+    def update_now(self):
+        self.update_now_calls += 1
+        self.loop.update_now()
+
+class _UpdateNowWithTimerProxy(_UpdateNowProxy):
+
+    def timer(self, *_args, **_kwargs):
+        return _Timer(self)
+
+class _Timer(object):
+
+    pending = False
+    active = False
+
+    def __init__(self, loop):
+        self.loop = loop
+
+    def start(self, *_args, **kwargs):
+        if kwargs.get("update"):
+            self.loop.update_now()
+        self.pending = self.active = True
+
+    def stop(self):
+        self.active = self.pending = False
+
+    def close(self):
+        "Does nothing"
+
+
 class Test(greentest.TestCase):
 
+    def test_timeout_calls_update_now(self):
+        hub = get_hub()
+        loop = hub.loop
+        proxy = _UpdateNowWithTimerProxy(loop)
+        hub.loop = proxy
+
+        try:
+            with Timeout(DELAY * 2) as t:
+                self.assertTrue(t.pending)
+        finally:
+            hub.loop = loop
+
+        self.assertEqual(1, proxy.update_now_calls)
+
+    def test_sleep_calls_update_now(self):
+        hub = get_hub()
+        loop = hub.loop
+        proxy = _UpdateNowProxy(loop)
+        hub.loop = proxy
+        try:
+            sleep(0.01)
+        finally:
+            hub.loop = loop
+
+        self.assertEqual(1, proxy.update_now_calls)
+
+
     @greentest.skipOnAppVeyor("Timing is flaky, especially under Py 3.4/64-bit")
     def test_api(self):
         # Nothing happens if with-block finishes before the timeout expires
         t = Timeout(DELAY * 2)
-        assert not t.pending, repr(t)
+        self.assertFalse(t.pending, t)
         with t:
-            assert t.pending, repr(t)
+            self.assertTrue(t.pending, t)
             sleep(DELAY)
         # check if timer was actually cancelled
-        assert not t.pending, repr(t)
+        self.assertFalse(t.pending, t)
         sleep(DELAY * 2)
 
         # An exception will be raised if it's not
-        try:
+        with self.assertRaises(Timeout) as exc:
             with Timeout(DELAY) as t:
                 sleep(DELAY * 10)
-        except Timeout as ex:
-            assert ex is t, (ex, t)
-        else:
-            raise AssertionError('must raise Timeout')
+
+        self.assertIs(exc.exception, t)
 
         # You can customize the exception raised:
-        try:
+        with self.assertRaises(IOError):
             with Timeout(DELAY, IOError("Operation takes way too long")):
                 sleep(DELAY * 10)
-        except IOError as ex:
-            assert str(ex) == "Operation takes way too long", repr(ex)
 
         # Providing classes instead of values should be possible too:
-        try:
+        with self.assertRaises(ValueError):
             with Timeout(DELAY, ValueError):
                 sleep(DELAY * 10)
-        except ValueError:
-            pass
+
 
         try:
             1 / 0
-        except:
-            try:
+        except ZeroDivisionError:
+            with self.assertRaises(ZeroDivisionError):
                 with Timeout(DELAY, sys.exc_info()[0]):
                     sleep(DELAY * 10)
                     raise AssertionError('should not get there')
                 raise AssertionError('should not get there')
-            except ZeroDivisionError:
-                pass
         else:
             raise AssertionError('should not get there')
 
@@ -107,7 +171,8 @@ class Test(greentest.TestCase):
             sleep(DELAY)
         del err
         gc.collect()
-        assert not err_ref(), repr(err_ref())
+        self.assertFalse(err_ref(), err_ref)
+
 
     def test_nested_timeout(self):
         with Timeout(DELAY, False):
@@ -117,23 +182,25 @@ class Test(greentest.TestCase):
 
         with Timeout(DELAY) as t1:
             with Timeout(DELAY * 20) as t2:
-                try:
+                with self.assertRaises(Timeout) as exc:
                     sleep(DELAY * 30)
-                except Timeout as ex:
-                    assert ex is t1, (ex, t1)
-                assert not t1.pending, t1
-                assert t2.pending, t2
-            assert not t2.pending, t2
+                self.assertIs(exc.exception, t1)
+
+                self.assertFalse(t1.pending, t1)
+                self.assertTrue(t2.pending, t2)
+
+            self.assertFalse(t2.pending)
 
         with Timeout(DELAY * 20) as t1:
             with Timeout(DELAY) as t2:
-                try:
+                with self.assertRaises(Timeout) as exc:
                     sleep(DELAY * 30)
-                except Timeout as ex:
-                    assert ex is t2, (ex, t2)
-                assert t1.pending, t1
-                assert not t2.pending, t2
-        assert not t1.pending, t1
+                self.assertIs(exc.exception, t2)
+
+                self.assertTrue(t1.pending, t1)
+                self.assertFalse(t2.pending, t2)
+
+        self.assertFalse(t1.pending)
 
 
 if __name__ == '__main__':

src/greentest/test__socket.py

 from gevent import monkey; monkey.patch_all()
+
 import sys
 import os
 import array
@@ -200,32 +201,36 @@ class TestTCP(greentest.TestCase):
         client.close()
         client_sock[0][0].close()
 
-    # On Windows send() accepts whatever is thrown at it
-    if sys.platform != 'win32':
-
-        _test_sendall_timeout_check_time = True
-        # Travis-CI container infrastructure is configured with
-        # large socket buffers, at least 2MB, as-of Jun 3, 2015,
-        # so we must be sure to send more data than that.
-        _test_sendall_data = b'hello' * 1000000
-
-        def test_sendall_timeout(self):
-            client_sock = []
-            acceptor = Thread(target=lambda: client_sock.append(self.listener.accept()))
-            client = self.create_connection()
-            time.sleep(0.1)
-            assert client_sock
-            client.settimeout(0.1)
-            start = time.time()
-            try:
-                self.assertRaises(self.TIMEOUT_ERROR, client.sendall, self._test_sendall_data)
-                if self._test_sendall_timeout_check_time:
-                    took = time.time() - start
-                    assert 0.09 <= took <= 0.2, took
-            finally:
-                acceptor.join()
-                client.close()
-                client_sock[0][0].close()
+    # Subclasses can disable  this
+    _test_sendall_timeout_check_time = True
+
+    # Travis-CI container infrastructure is configured with
+    # large socket buffers, at least 2MB, as-of Jun 3, 2015,
+    # so we must be sure to send more data than that.
+    # In 2018, this needs to be increased *again* as a smaller value was
+    # still often being sent.
+    _test_sendall_data = b'hello' * 100000000
+
+    # This doesn't make much sense...why are we really skipping this?
+    @greentest.skipOnWindows("On Windows send() accepts whatever is thrown at it")
+    def test_sendall_timeout(self):
+        client_sock = []
+        acceptor = Thread(target=lambda: client_sock.append(self.listener.accept()))
+        client = self.create_connection()
+        time.sleep(0.1)
+        assert client_sock
+        client.settimeout(0.1)
+        start = time.time()
+        try:
+            with self.assertRaises(self.TIMEOUT_ERROR):
+                client.sendall(self._test_sendall_data)
+            if self._test_sendall_timeout_check_time:
+                took = time.time() - start
+                self.assertTimeWithinRange(took, 0.09, 0.2)
+        finally:
+            acceptor.join()
+            client.close()
+            client_sock[0][0].close()
 
     def test_makefile(self):
         def accept_once():

src/greentest/test__ssl.py

 from gevent import monkey; monkey.patch_all()
 import os
-import sys
+
 import socket
 import greentest
 # Be careful not to have TestTCP as a bare attribute in this module,
@@ -31,43 +31,42 @@ class TestSSL(test__socket.TestTCP):
     def create_connection(self, *args, **kwargs):
         return ssl.wrap_socket(super(TestSSL, self).create_connection(*args, **kwargs))
 
-    if not sys.platform.startswith('win32'):
-
-        # The SSL library can take a long time to buffer the large amount of data we're trying
-        # to send, so we can't compare to the timeout values
-        _test_sendall_timeout_check_time = False
-
-        # The SSL layer has extra buffering, so test_sendall needs
-        # to send a very large amount to make it timeout
-        _test_sendall_data = data_sent = b'hello' * 100000000
-
-        def test_ssl_sendall_timeout0(self):
-            # Issue #317: SSL_WRITE_PENDING in some corner cases
-
-            server_sock = []
-            acceptor = test__socket.Thread(target=lambda: server_sock.append(self.listener.accept()))
-            client = self.create_connection()
-            client.setblocking(False)
-            try:
-                # Python 3 raises ssl.SSLWantWriteError; Python 2 simply *hangs*
-                # on non-blocking sockets because it's a simple loop around
-                # send(). Python 2.6 doesn't have SSLWantWriteError
-                expected = getattr(ssl, 'SSLWantWriteError', ssl.SSLError)
-                with self.assertRaises(expected):
-                    client.sendall(self._test_sendall_data)
-            finally:
-                acceptor.join()
-                client.close()
-                server_sock[0][0].close()
-
-    elif greentest.LIBUV:
-
-        def test_fullduplex(self):
-            try:
-                super(TestSSL, self).test_fullduplex()
-            except LoopExit:
+    # The SSL library can take a long time to buffer the large amount of data we're trying
+    # to send, so we can't compare to the timeout values
+    _test_sendall_timeout_check_time = False
+
+    # The SSL layer has extra buffering, so test_sendall needs
+    # to send a very large amount to make it timeout
+    _test_sendall_data = data_sent = b'hello' * 100000000
+
+    @greentest.skipOnWindows("Not clear why we're skipping")
+    def test_ssl_sendall_timeout0(self):
+        # Issue #317: SSL_WRITE_PENDING in some corner cases
+
+        server_sock = []
+        acceptor = test__socket.Thread(target=lambda: server_sock.append(self.listener.accept()))
+        client = self.create_connection()
+        client.setblocking(False)
+        try:
+            # Python 3 raises ssl.SSLWantWriteError; Python 2 simply *hangs*
+            # on non-blocking sockets because it's a simple loop around
+            # send(). Python 2.6 doesn't have SSLWantWriteError
+            expected = getattr(ssl, 'SSLWantWriteError', ssl.SSLError)
+            with self.assertRaises(expected):
+                client.sendall(self._test_sendall_data)
+        finally:
+            acceptor.join()
+            client.close()
+            server_sock[0][0].close()
+
+    def test_fullduplex(self):
+        try:
+            super(TestSSL, self).test_fullduplex()
+        except LoopExit:
+            if greentest.LIBUV and greentest.WIN:
                 # XXX: Unable to duplicate locally
                 raise unittest.SkipTest("libuv on Windows sometimes raises LoopExit")
+            raise
 
 
     @greentest.ignores_leakcheck