Flaky `test_nanny` #6764

gjoseph92 · 2022-07-20T20:01:39Z

__________________________________ test_nanny __________________________________
addr = 'tls://127.0.0.1:50252', timeout = 5, deserialize = True
handshake_overrides = None
connection_args = {'extra_conn_args': {}, 'require_encryption': False, 'ssl_context': <ssl.SSLContext object at 0x7fa5723732c0>}
scheme = 'tls', loc = '127.0.0.1:50252'
backend = <distributed.comm.tcp.TLSBackend object at 0x7fa56b7b1af0>
connector = <distributed.comm.tcp.TLSConnector object at 0x7fa572375a30>
comm = None, time_left = <function connect.<locals>.time_left at 0x7fa572396670>
backoff_base = 0.01
asyncdefconnect(
        addr, timeout=None, deserialize=True, handshake_overrides=None, **connection_args
    ):
"""
    Connect to the given address (a URI such as ``tcp://127.0.0.1:1234``)
    and yield a ``Comm`` object.  If the connection attempt fails, it is
    retried until the *timeout* is expired.
    """
if timeout isNone:
            timeout = dask.config.get("distributed.comm.timeouts.connect")
        timeout = parse_timedelta(timeout, default="seconds")
        scheme, loc = parse_address(addr)
        backend = registry.get_backend(scheme)
        connector = backend.get_connector()
        comm = None
        start = time()
deftime_left():
            deadline = start + timeout
returnmax(0, deadline - time())
        backoff_base = 0.01
        attempt = 0
# Prefer multiple small attempts than one long attempt. This should protect
# primarily from DNS race conditions
# gh3104, gh4176, gh4167
        intermediate_cap = timeout / 5
        active_exception = None
while time_left() > 0:
try:
>               comm = await asyncio.wait_for(
                    connector.connect(loc, deserialize=deserialize, **connection_args),
                    timeout=min(intermediate_cap, time_left()),
                )
distributed/comm/core.py:291: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
fut = <Task cancelled name='Task-2226' coro=<BaseTCPConnector.connect() done, defined at /Users/runner/work/distributed/distributed/distributed/comm/tcp.py:443>>
timeout = 0.5918369293212891
asyncdefwait_for(fut, timeout, *, loop=None):
"""Wait for the single Future or coroutine to complete, with timeout.
    Coroutine will be wrapped in Task.
    Returns result of the Future or coroutine.  When a timeout occurs,
    it cancels the task and raises TimeoutError.  To avoid the task
    cancellation, wrap it in shield().
    If the wait is cancelled, the task is also cancelled.
    This function is a coroutine.
    """
if loop isNone:
            loop = events.get_running_loop()
else:
            warnings.warn("The loop argument is deprecated since Python 3.8, "
"and scheduled for removal in Python 3.10.",
DeprecationWarning, stacklevel=2)
if timeout isNone:
returnawait fut
if timeout <= 0:
            fut = ensure_future(fut, loop=loop)
if fut.done():
return fut.result()
await _cancel_and_wait(fut, loop=loop)
try:
                fut.result()
except exceptions.CancelledError as exc:
raise exceptions.TimeoutError() fromexc
else:
raise exceptions.TimeoutError()
        waiter = loop.create_future()
        timeout_handle = loop.call_later(timeout, _release_waiter, waiter)
        cb = functools.partial(_release_waiter, waiter)
        fut = ensure_future(fut, loop=loop)
        fut.add_done_callback(cb)
try:
# wait until the future completes or the timeout
try:
await waiter
except exceptions.CancelledError:
if fut.done():
return fut.result()
else:
                    fut.remove_done_callback(cb)
# We must ensure that the task is not running
# after wait_for() returns.
# See https://bugs.python.org/issue32751
await _cancel_and_wait(fut, loop=loop)
raise
if fut.done():
return fut.result()
else:
                fut.remove_done_callback(cb)
# We must ensure that the task is not running
# after wait_for() returns.
# See https://bugs.python.org/issue32751
await _cancel_and_wait(fut, loop=loop)
>               raise exceptions.TimeoutError()
E               asyncio.exceptions.TimeoutError
../../../miniconda3/envs/dask-distributed/lib/python3.8/asyncio/tasks.py:501: TimeoutError
The above exception was the direct cause of the following exception:
loop = <tornado.platform.asyncio.AsyncIOLoop object at 0x7fa571b7e880>
deftest_nanny(loop):
        port = open_port()
with popen(
            [
"dask-scheduler",
"--no-dashboard",
f"--port={port}",
            ]
            + tls_args
        ) as s:
with popen(
                ["dask-worker", "--no-dashboard", "--nanny", f"tls://127.0.0.1:{port}"]
                + tls_args
            ) as w:
>               with Client(
f"tls://127.0.0.1:{port}", loop=loop, security=tls_security()
                ) as c:
distributed/cli/tests/test_tls_cli.py:58: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
distributed/client.py:940: in __init__
self.start(timeout=timeout)
distributed/client.py:1098: in start
    sync(self.loop, self._start, **kwargs)
distributed/utils.py:405: in sync
raise exc.with_traceback(tb)
distributed/utils.py:378: in f
    result = yield future
../../../miniconda3/envs/dask-distributed/lib/python3.8/site-packages/tornado/gen.py:762: in run
    value = future.result()
distributed/client.py:1178: in _start
awaitself._ensure_connected(timeout=timeout)
distributed/client.py:1241: in _ensure_connected
    comm = await connect(
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
addr = 'tls://127.0.0.1:50252', timeout = 5, deserialize = True
handshake_overrides = None
connection_args = {'extra_conn_args': {}, 'require_encryption': False, 'ssl_context': <ssl.SSLContext object at 0x7fa5723732c0>}
scheme = 'tls', loc = '127.0.0.1:50252'
backend = <distributed.comm.tcp.TLSBackend object at 0x7fa56b7b1af0>
connector = <distributed.comm.tcp.TLSConnector object at 0x7fa572375a30>
comm = None, time_left = <function connect.<locals>.time_left at 0x7fa572396670>
backoff_base = 0.01
asyncdefconnect(
        addr, timeout=None, deserialize=True, handshake_overrides=None, **connection_args
    ):
"""
    Connect to the given address (a URI such as ``tcp://127.0.0.1:1234``)
    and yield a ``Comm`` object.  If the connection attempt fails, it is
    retried until the *timeout* is expired.
    """
if timeout isNone:
            timeout = dask.config.get("distributed.comm.timeouts.connect")
        timeout = parse_timedelta(timeout, default="seconds")
        scheme, loc = parse_address(addr)
        backend = registry.get_backend(scheme)
        connector = backend.get_connector()
        comm = None
        start = time()
deftime_left():
            deadline = start + timeout
returnmax(0, deadline - time())
        backoff_base = 0.01
        attempt = 0
# Prefer multiple small attempts than one long attempt. This should protect
# primarily from DNS race conditions
# gh3104, gh4176, gh4167
        intermediate_cap = timeout / 5
        active_exception = None
while time_left() > 0:
try:
                comm = await asyncio.wait_for(
                    connector.connect(loc, deserialize=deserialize, **connection_args),
                    timeout=min(intermediate_cap, time_left()),
                )
break
except FatalCommClosedError:
raise
# Note: CommClosed inherits from OSError
except (asyncio.TimeoutError, OSError) as exc:
                active_exception = exc
# As descibed above, the intermediate timeout is used to distributed
# initial, bulk connect attempts homogeneously. In particular with
# the jitter upon retries we should not be worred about overloading
# any more DNS servers
                intermediate_cap = timeout
# FullJitter see https://aws.amazon.com/blogs/architecture/exponential-backoff-and-jitter/
                upper_cap = min(time_left(), backoff_base * (2**attempt))
                backoff = random.uniform(0, upper_cap)
                attempt += 1
                logger.debug(
"Could not connect to %s, waiting for %s before retrying", loc, backoff
                )
await asyncio.sleep(backoff)
else:
>           raiseOSError(
f"Timed out trying to connect to {addr} after {timeout} s"
            ) fromactive_exception
E           OSError: Timed out trying to connect to tls://127.0.0.1:50252 after 5 s
distributed/comm/core.py:317: OSError
----------------------------- Captured stderr call -----------------------------
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.24755.632797' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.24791.864042' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.27002.030479' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Couldn't use data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.22881.305886': database disk image is malformed
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.[2006](https://github.com/dask/distributed/runs/7315241408?check_suite_focus=true#step:11:2007)3.304395' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.25316.046512' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.20439.553620' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.28084.586082' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.20240.310419' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Couldn't use data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.27289.596724': database disk image is malformed
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.20839.224158' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.27032.699745' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.27001.853348' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.33035.591657' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.27979.010575' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.32539.546178' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Couldn't use data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.26224.093499': database disk image is malformed
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.22856.514201' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.26804.927287' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.20673.972507' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Couldn't use data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.32233.101067': database disk image is malformed
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.27949.431327' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
/Users/runner/miniconda3/envs/dask-distributed/lib/python3.8/site-packages/coverage/data.py:130: CoverageWarning: Data file '/Users/runner/work/distributed/distributed/.coverage.Mac-1657691297091.local.20241.856082' doesn't seem to be a coverage data file: cannot unpack non-iterable NoneType object
  data._warn(str(exc))
[2022](https://github.com/dask/distributed/runs/7315241408?check_suite_focus=true#step:11:2023)-07-13 06:10:58,689 - distributed.scheduler - INFO - -----------------------------------------------
2022-07-13 06:10:58,712 - distributed.http.proxy - INFO - To route to workers diagnostics web server please install jupyter-server-proxy: python -m pip install jupyter-server-proxy
2022-07-13 06:10:58,721 - distributed.scheduler - INFO - State start
2022-07-13 06:10:58,733 - distributed.scheduler - INFO - -----------------------------------------------
2022-07-13 06:10:58,733 - distributed.scheduler - INFO - Clear task state
2022-07-13 06:10:58,735 - distributed.scheduler - INFO -   Scheduler at:   tls://10.213.2.56:50252
2022-07-13 06:10:58,735 - distributed.scheduler - INFO -   dashboard at:                     :8787
2022-07-13 06:10:58,764 - distributed.nanny - INFO -         Start Nanny at: 'tls://127.0.0.1:50264'
2022-07-13 06:11:00,329 - distributed.worker - INFO -       Start worker at:      tls://127.0.0.1:50267
2022-07-13 06:11:00,330 - distributed.worker - INFO -          Listening to:      tls://127.0.0.1:50267
2022-07-13 06:11:00,330 - distributed.worker - INFO -          dashboard at:            127.0.0.1:50268
2022-07-13 06:11:00,330 - distributed.worker - INFO - Waiting to connect to:      tls://127.0.0.1:50252
2022-07-13 06:11:00,330 - distributed.worker - INFO - -------------------------------------------------
2022-07-13 06:11:00,330 - distributed.worker - INFO -               Threads:                          3
2022-07-13 06:11:00,330 - distributed.worker - INFO -                Memory:                  14.00 GiB
2022-07-13 06:11:00,330 - distributed.worker - INFO -       Local Directory: /var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/dask-worker-space/worker-tpnerrc1
2022-07-13 06:11:00,330 - distributed.worker - INFO - -------------------------------------------------
2022-07-13 06:11:01,002 - distributed.scheduler - INFO - Register worker <WorkerState 'tls://127.0.0.1:50267', status: init, memory: 0, processing: 0>
2022-07-13 06:11:01,713 - distributed._signals - INFO - Received signal SIGINT (2)
2022-07-13 06:11:01,714 - distributed.nanny - INFO - Closing Nanny at 'tls://127.0.0.1:50264'.
2022-07-13 06:11:01,715 - distributed.nanny - INFO - Nanny asking worker to close
2022-07-13 06:11:01,717 - distributed.worker - INFO - Stopping worker at tls://127.0.0.1:50267
2022-07-13 06:11:01,717 - distributed.worker - INFO - Closed worker has not yet started: Status.init
2022-07-13 06:11:01,767 - distributed.scheduler - INFO - Starting worker compute stream, tls://127.0.0.1:50267
2022-07-13 06:11:01,767 - distributed.core - INFO - Starting established connection
2022-07-13 06:11:01,909 - distributed.scheduler - INFO - Remove worker <WorkerState 'tls://127.0.0.1:50267', status: init, memory: 0, processing: 0>
2022-07-13 06:11:01,910 - distributed.core - INFO - Removing comms to tls://127.0.0.1:50267
2022-07-13 06:11:01,910 - distributed.scheduler - INFO - Lost all workers
2022-07-13 06:11:01,936 - distributed.dask_worker - INFO - End worker
2022-07-13 06:11:02,248 - distributed._signals - INFO - Received signal SIGINT (2)
2022-07-13 06:11:02,248 - distributed.scheduler - INFO - Scheduler closing...
2022-07-13 06:11:02,249 - distributed.scheduler - INFO - Scheduler closing all comms
2022-07-13 06:11:02,250 - distributed.scheduler - INFO - Stopped scheduler at 'tls://10.213.2.56:50252'
2022-07-13 06:11:02,251 - distributed.scheduler - INFO - End scheduler

The text was updated successfully, but these errors were encountered:

gjoseph92 added the flaky test Intermittent failures on CI. label Jul 20, 2022

gjoseph92 mentioned this issue Jul 20, 2022

Flaky tests: OSError: Timed out trying to connect to tcp://127.0.0.1:8786 after 5 s #6731

Closed

gjoseph92 mentioned this issue Aug 3, 2022

Only set 5s connect timeout in gen_cluster tests #6822

Merged

1 task

fjetter closed this as completed in #6822 Aug 5, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Flaky `test_nanny` #6764

Flaky `test_nanny` #6764

gjoseph92 commented Jul 20, 2022

Flaky test_nanny #6764

Flaky test_nanny #6764

Comments

gjoseph92 commented Jul 20, 2022

Flaky `test_nanny` #6764

Flaky `test_nanny` #6764