Intermittent testing failures

[mrocklin]

Some tests fail very infrequently. Lets maintain a list here:

• distributed/cli/tests/test_dask_worker.py::test_local_directory
• distributed/tests/test_ipython.py::test_start_ipython_scheduler (windows)
• distributed/deploy/tests/test_local.py::test_silent_startup appveyor

[mrocklin]

__________________________ test_worker_death_timeout ___________________________
    def test_func():
        with pristine_loop() as loop:
            cor = gen.coroutine(func)
            try:
>               loop.run_sync(cor, timeout=timeout)
distributed/utils_test.py:438: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
../../../miniconda/envs/test-environment/lib/python3.4/site-packages/tornado/ioloop.py:457: in run_sync
    return future_cell[0].result()
../../../miniconda/envs/test-environment/lib/python3.4/site-packages/tornado/concurrent.py:237: in result
    raise_exc_info(self._exc_info)
<string>:3: in raise_exc_info
    ???
../../../miniconda/envs/test-environment/lib/python3.4/site-packages/tornado/gen.py:1021: in run
    yielded = self.gen.throw(*exc_info)
distributed/tests/test_worker.py:660: in test_worker_death_timeout
    yield w._start()
../../../miniconda/envs/test-environment/lib/python3.4/site-packages/tornado/gen.py:1015: in run
    value = future.result()
../../../miniconda/envs/test-environment/lib/python3.4/site-packages/tornado/concurrent.py:237: in result
    raise_exc_info(self._exc_info)
<string>:3: in raise_exc_info
    ???
../../../miniconda/envs/test-environment/lib/python3.4/site-packages/tornado/gen.py:1021: in run
    yielded = self.gen.throw(*exc_info)
distributed/worker.py:268: in _start
    yield self._register_with_scheduler()
../../../miniconda/envs/test-environment/lib/python3.4/site-packages/tornado/gen.py:1015: in run
    value = future.result()
../../../miniconda/envs/test-environment/lib/python3.4/site-packages/tornado/concurrent.py:237: in result
    raise_exc_info(self._exc_info)
<string>:3: in raise_exc_info
    ???
../../../miniconda/envs/test-environment/lib/python3.4/site-packages/tornado/gen.py:1024: in run
    yielded = self.gen.send(value)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
self = <Worker: tcp://127.0.0.1:35785, running, stored: 0, running: 0/2, ready: 0, comm: 0, waiting: 0>
    @gen.coroutine
    def _register_with_scheduler(self):
        self.heartbeat_callback.stop()
        start = time()
        while True:
            if self.death_timeout and time() > start + self.death_timeout:
                yield self._close(timeout=1)
                return
            if self.status in ('closed', 'closing'):
                raise gen.Return
            try:
                future = self.scheduler.register(
                        ncores=self.ncores, address=self.address,
                        keys=list(self.data),
                        name=self.name,
                        nbytes=self.nbytes,
                        now=time(),
                        host_info=self.host_health(),
                        services=self.service_ports,
                        memory_limit=self.memory_limit,
                        local_directory=self.local_dir,
                        resources=self.total_resources)
                if self.death_timeout:
                    diff = self.death_timeout - (time() - start)
                    future = gen.with_timeout(timedelta(seconds=diff), future,
                                              io_loop=self.loop)
                resp = yield future
                self.status = 'running'
                break
            except EnvironmentError:
                logger.debug("Unable to register with scheduler.  Waiting")
                yield gen.sleep(0.1)
            except gen.TimeoutError:
                pass
        if resp != 'OK':
>           raise ValueError(resp)
E           ValueError: {'local_directory': '/tmp/worker-yw29rxv9', 'address': 'tcp://127.0.0.1:35785', 'name': 'tcp://127.0.0.1:35785', 'nbytes': {}, 'keys': [], 'now': 1490630984.8787775, 'memory_limit': 4706014003.0, 'resources': {}, 'services': {}, 'ncores': 2, 'reply': True, 'host_info': {'memory': 7843356672, 'disk-read': 0, 'memory_percent': 24.0, 'time': 1490630984.8787794, 'network-send': 0, 'disk-write': 0, 'cpu': 100.0, 'network-recv': 0}, 'op': 'register'}

[mrocklin]

No rush on this, but @pitrou this is probably due to recent work on the concurrent.futures compatible executor.

=================================== FAILURES ===================================
________________________________ test_shutdown _________________________________
loop = <tornado.platform.epoll.EPollIOLoop object at 0x7f41c0385e90>
    def test_shutdown(loop):
        with cluster() as (s, [a, b]):
            with Client(s['address'], loop=loop) as c:
                # shutdown(wait=True) waits for pending tasks to finish
                e = c.get_executor()
                fut = e.submit(time.sleep, 1.0)
                t1 = time.time()
                e.shutdown()
                dt = time.time() - t1
>               assert 0.5 <= dt <= 2.0
E               assert 0.5 <= 0.0022339820861816406
distributed/tests/test_client_executor.py:213: AssertionError
============================== 3 tests deselected ==============================

[mrocklin]

Nevermind on the test_shutdown error. That was a genuine error in my code.

[mrocklin]

================================== FAILURES ===================================
_____________________________ test_server_listen ______________________________
Traceback (most recent call last):
  File "C:\projects\distributed\distributed\utils_test.py", line 438, in test_func
    loop.run_sync(cor, timeout=timeout)
  File "C:\Miniconda35-x64\envs\testenv\lib\site-packages\tornado\ioloop.py", line 457, in run_sync
    return future_cell[0].result()
  File "C:\Miniconda35-x64\envs\testenv\lib\site-packages\tornado\concurrent.py", line 237, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 3, in raise_exc_info
  File "C:\Miniconda35-x64\envs\testenv\lib\site-packages\tornado\gen.py", line 285, in wrapper
    yielded = next(result)
  File "C:\projects\distributed\distributed\tests\test_core.py", line 113, in test_server_listen
    with listen_on(Server, 8882) as server:
  File "C:\Miniconda35-x64\envs\testenv\lib\contextlib.py", line 59, in __enter__
    return next(self.gen)
  File "C:\projects\distributed\distributed\tests\test_core.py", line 105, in listen_on
    server.listen(*args)
  File "C:\projects\distributed\distributed\core.py", line 198, in listen
    self.listener.start()
  File "C:\projects\distributed\distributed\comm\tcp.py", line 245, in start
    self.tcp_server.listen(self.port, self.ip)
  File "C:\Miniconda35-x64\envs\testenv\lib\site-packages\tornado\tcpserver.py", line 126, in listen
    sockets = bind_sockets(port, address=address)
  File "C:\Miniconda35-x64\envs\testenv\lib\site-packages\tornado\netutil.py", line 194, in bind_sockets
    sock.bind(sockaddr)
OSError: [WinError 10048] Only one usage of each socket address (protocol/network address/port) is normally permitted
============================= 2 tests deselected ==============================

@pitrou does this mean anything to you?

[mrocklin]

I guess maybe 8882 was already taken randomly?

[pitrou]

I guess maybe 8882 was already taken randomly?

That sounds possible. I'm not sure how Windows allocates ephemeral port numbers.

[mrocklin]

@pitrou I am somewhat confused by the error in #966 (comment) which continues to pop up from time to time. We send a request to the Scheduler.add_worker function, which only returns either 'OK' or 'name taken'. And yet somehow we get back a response that is very much like what we sent. Can you think of any reason why this might be the case?

[pitrou]

No, I can't imagine what is happening. We seem to be getting back exactly what was sent (the "reply" key in the dict is added by send_recv).
Do you know of way to reproduce?

[pitrou]

One thing I don't understand: test_worker_death_timeout shouldn't be able to contact the scheduler as none has been started. Perhaps ('127.0.0.1', 38848) can randomly correspond to an open port on the system?

[pitrou]

The following might make the test more reliable (ditto for test_nanny_death_timeout):

diff --git a/distributed/tests/test_worker.py b/distributed/tests/test_worker.py
index 0524417..fae6d8a 100644
--- a/distributed/tests/test_worker.py
+++ b/distributed/tests/test_worker.py
@@ -654,9 +654,10 @@ def test_hold_onto_dependents(c, s, a, b):
 
 
 @slow
-@gen_test()
-def test_worker_death_timeout():
-    w = Worker('127.0.0.1', 38848, death_timeout=1)
+@gen_cluster(client=False, ncores=[])
+def test_worker_death_timeout(s):
+    yield s.close()  # close scheduler address
+    w = Worker(s.address, death_timeout=1)
     yield w._start()
 
     yield gen.sleep(3)

[pitrou]

It seems test_bokeh_port_zero might be flaky as well: https://travis-ci.org/dask/distributed/jobs/230841681#L1514

_____________________________ test_bokeh_port_zero _____________________________

loop = <zmq.eventloop.ioloop.ZMQIOLoop object at 0x7f96a443db00>

    def test_bokeh_port_zero(loop):
        pytest.importorskip('bokeh')
        with tmpfile() as fn:
            with popen(['dask-scheduler',
                        '--bokeh-port', '0']) as proc:
                count = 0
                while count < 1:
                    line = proc.stderr.readline()
                    if b'bokeh' in line.lower() or b'web' in line.lower():
                        count += 1
>                       assert b':0' not in line

distributed/cli/tests/test_dask_scheduler.py:254: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
../../../miniconda/envs/test-environment/lib/python3.4/contextlib.py:66: in __exit__
    next(self.gen)
distributed/utils_test.py:600: in popen
    terminate_process(proc)
distributed/utils_test.py:574: in terminate_process
    proc.wait(10)
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 

self = <subprocess.Popen object at 0x7f96a445feb8>, timeout = 10
endtime = 270.472086438

    def wait(self, timeout=None, endtime=None):
        """Wait for child process to terminate.  Returns returncode
                attribute."""
        if self.returncode is not None:
            return self.returncode
    
        # endtime is preferred to timeout.  timeout is only used for
        # printing.
        if endtime is not None or timeout is not None:
            if endtime is None:
                endtime = _time() + timeout
            elif timeout is None:
                timeout = self._remaining_time(endtime)
    
        if endtime is not None:
            # Enter a busy loop if we have a timeout.  This busy loop was
            # cribbed from Lib/threading.py in Thread.wait() at r71065.
            delay = 0.0005 # 500 us -> initial delay of 1 ms
            while True:
                if self._waitpid_lock.acquire(False):
                    try:
                        if self.returncode is not None:
                            break  # Another thread waited.
                        (pid, sts) = self._try_wait(os.WNOHANG)
                        assert pid == self.pid or pid == 0
                        if pid == self.pid:
                            self._handle_exitstatus(sts)
                            break
                    finally:
                        self._waitpid_lock.release()
                remaining = self._remaining_time(endtime)
                if remaining <= 0:
>                   raise TimeoutExpired(self.args, timeout)
E                   subprocess.TimeoutExpired: Command '['dask-scheduler', '--bokeh-port', '0']' timed out after 10 seconds

../../../miniconda/envs/test-environment/lib/python3.4/subprocess.py:1561: TimeoutExpired

[mrocklin]

This failed on windows

================================== FAILURES ===================================
_________________________ test_nanny_process_failure __________________________
Traceback (most recent call last):
  File "C:\projects\distributed\distributed\utils_test.py", line 547, in test_func
    return loop.run_sync(lambda: cor(*args), timeout=timeout)
  File "C:\Miniconda35-x64\envs\testenv\lib\site-packages\tornado\ioloop.py", line 457, in run_sync
    return future_cell[0].result()
  File "C:\Miniconda35-x64\envs\testenv\lib\site-packages\tornado\concurrent.py", line 237, in result
    raise_exc_info(self._exc_info)
  File "<string>", line 3, in raise_exc_info
  File "C:\Miniconda35-x64\envs\testenv\lib\site-packages\tornado\gen.py", line 1024, in run
    yielded = self.gen.send(value)
  File "C:\projects\distributed\distributed\tests\test_nanny.py", line 99, in test_nanny_process_failure
    assert n.worker_address != original_address  # most likely
AssertionError: assert 'tcp://127.0.0.1:10305' != 'tcp://127.0.0.1:10305'
 +  where 'tcp://127.0.0.1:10305' = <Nanny: tcp://127.0.0.1:10305, threads: 2>.worker_address
---------------------------- Captured stderr call -----------------------------