Skip to content

CI failing with test_submit_after_failed_worker_async #6311

New issue
New issue
Closed
#8032
Closed
CI failing with test_submit_after_failed_worker_async#6311
#8032
Labels
flaky testIntermittent failures on CI.

Description

@jakirkham
jakirkham
opened on May 10, 2022

Seeing a CI failure with test_submit_after_failed_worker_async.

Activity

  1. jakirkham
    added
    flaky testIntermittent failures on CI.
    on May 10, 2022

  2. gjoseph92 commented on Jun 9, 2022

    @gjoseph92
    gjoseph92
    on Jun 9, 2022
    Collaborator

    A more recent traceback from https://github.com/dask/distributed/runs/6621019362?check_suite_focus=true#step:11:1368

    ____________________ test_submit_after_failed_worker_async _____________________
cls = <class '_pytest.runner.CallInfo'>
func = <function call_runtest_hook.<locals>.<lambda> at 0x13f4bc040>
when = 'call'
reraise = (<class '_pytest.outcomes.Exit'>, <class 'KeyboardInterrupt'>)
@classmethod
deffrom_call(
cls,
        func: "Callable[[], TResult]",
        when: "Literal['collect', 'setup', 'call', 'teardown']",
        reraise: Optional[
            Union[Type[BaseException], Tuple[Type[BaseException], ...]]
        ] = None,
    ) -> "CallInfo[TResult]":
"""Call func, wrapping the result in a CallInfo.
    :param func:
        The function to call. Called without arguments.
    :param when:
        The phase in which the function is called.
    :param reraise:
        Exception or exceptions that shall propagate if raised by the
        function, instead of being wrapped in the CallInfo.
    """
        excinfo = None
        start = timing.time()
        precise_start = timing.perf_counter()
try:
>           result: Optional[TResult] = func()
../../../miniconda3/envs/dask-distributed/lib/python3.10/site-packages/_pytest/runner.py:338: 
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
../../../miniconda3/envs/dask-distributed/lib/python3.10/site-packages/_pytest/runner.py:259: in <lambda>
lambda: ihook(item=item, **kwds), when=when, reraise=reraise
../../../miniconda3/envs/dask-distributed/lib/python3.10/site-packages/pluggy/_hooks.py:265: in __call__
returnself._hookexec(self.name, self.get_hookimpls(), kwargs, firstresult)
../../../miniconda3/envs/dask-distributed/lib/python3.10/site-packages/pluggy/_manager.py:80: in _hookexec
returnself._inner_hookexec(hook_name, methods, kwargs, firstresult)
../../../miniconda3/envs/dask-distributed/lib/python3.10/site-packages/_pytest/unraisableexception.py:88: in pytest_runtest_call
yield from unraisable_exception_runtest_hook()
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ 
defunraisable_exception_runtest_hook() -> Generator[None, None, None]:
with catch_unraisable_exception() as cm:
yield
if cm.unraisable:
if cm.unraisable.err_msg isnotNone:
                    err_msg = cm.unraisable.err_msg
else:
                    err_msg = "Exception ignored in"
                msg = f"{err_msg}: {cm.unraisable.object!r}\n\n"
                msg += "".join(
                    traceback.format_exception(
                        cm.unraisable.exc_type,
                        cm.unraisable.exc_value,
                        cm.unraisable.exc_traceback,
                    )
                )
>               warnings.warn(pytest.PytestUnraisableExceptionWarning(msg))
E               pytest.PytestUnraisableExceptionWarning: Exception ignored in: <_io.FileIO [closed]>
E               
E               Traceback (most recent call last):
E                 File "/Users/runner/work/distributed/distributed/distributed/utils_test.py", line 1141, in coro
E                   gc.collect()
E               ResourceWarning: unclosed file <_io.BufferedReader name=26>
../../../miniconda3/envs/dask-distributed/lib/python3.10/site-packages/_pytest/unraisableexception.py:78: PytestUnraisableExceptionWarning
----------------------------- Captured stderr call -----------------------------
2022-05-27 06:19:51,868 - distributed.scheduler - INFO - State start
2022-05-27 06:19:51,871 - distributed.scheduler - INFO - Clear task state
2022-05-27 06:19:51,872 - distributed.scheduler - INFO -   Scheduler at:     tcp://127.0.0.1:56527
2022-05-27 06:19:51,872 - distributed.scheduler - INFO -   dashboard at:           127.0.0.1:56526
2022-05-27 06:19:51,884 - distributed.worker - INFO -       Start worker at:      tcp://127.0.0.1:56528
2022-05-27 06:19:51,884 - distributed.worker - INFO -          Listening to:      tcp://127.0.0.1:56528
2022-05-27 06:19:51,885 - distributed.worker - INFO -          dashboard at:            127.0.0.1:56529
2022-05-27 06:19:51,885 - distributed.worker - INFO - Waiting to connect to:      tcp://127.0.0.1:56527
2022-05-27 06:19:51,885 - distributed.worker - INFO - -------------------------------------------------
2022-05-27 06:19:51,885 - distributed.worker - INFO -               Threads:                          1
2022-05-27 06:19:51,885 - distributed.worker - INFO -                Memory:                  14.00 GiB
2022-05-27 06:19:51,885 - distributed.worker - INFO -       Local Directory: /var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/tmpqs_op4a3/dask-worker-space/worker-qrg8801h
2022-05-27 06:19:51,886 - distributed.worker - INFO - -------------------------------------------------
2022-05-27 06:19:51,887 - distributed.worker - INFO -       Start worker at:      tcp://127.0.0.1:56530
2022-05-27 06:19:51,887 - distributed.worker - INFO -          Listening to:      tcp://127.0.0.1:56530
2022-05-27 06:19:51,887 - distributed.worker - INFO -          dashboard at:            127.0.0.1:56531
2022-05-27 06:19:51,887 - distributed.worker - INFO - Waiting to connect to:      tcp://127.0.0.1:56527
2022-05-27 06:19:51,887 - distributed.worker - INFO - -------------------------------------------------
2022-05-27 06:19:51,888 - distributed.worker - INFO -               Threads:                          2
2022-05-27 06:19:51,888 - distributed.worker - INFO -                Memory:                  14.00 GiB
2022-05-27 06:19:51,888 - distributed.worker - INFO -       Local Directory: /var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/tmpqs_op4a3/dask-worker-space/worker-4bil5nqv
2022-05-27 06:19:51,888 - distributed.worker - INFO - -------------------------------------------------
2022-05-27 06:19:51,898 - distributed.scheduler - INFO - Register worker <WorkerState 'tcp://127.0.0.1:56528', name: 0, status: init, memory: 0, processing: 0>
2022-05-27 06:19:51,899 - distributed.scheduler - INFO - Starting worker compute stream, tcp://127.0.0.1:56528
2022-05-27 06:19:51,899 - distributed.core - INFO - Starting established connection
2022-05-27 06:19:51,900 - distributed.scheduler - INFO - Register worker <WorkerState 'tcp://127.0.0.1:56530', name: 1, status: init, memory: 0, processing: 0>
2022-05-27 06:19:51,901 - distributed.scheduler - INFO - Starting worker compute stream, tcp://127.0.0.1:56530
2022-05-27 06:19:51,901 - distributed.core - INFO - Starting established connection
2022-05-27 06:19:51,901 - distributed.worker - INFO -         Registered to:      tcp://127.0.0.1:56527
2022-05-27 06:19:51,901 - distributed.worker - INFO - -------------------------------------------------
2022-05-27 06:19:51,902 - distributed.worker - INFO -         Registered to:      tcp://127.0.0.1:56527
2022-05-27 06:19:51,903 - distributed.worker - INFO - -------------------------------------------------
2022-05-27 06:19:51,903 - distributed.core - INFO - Starting established connection
2022-05-27 06:19:51,903 - distributed.core - INFO - Starting established connection
2022-05-27 06:19:51,931 - distributed.scheduler - INFO - Receive client connection: Client-0499aa98-dd85-11ec-9af1-005056aba833
2022-05-27 06:19:51,932 - distributed.core - INFO - Starting established connection
2022-05-27 06:19:51,942 - distributed.nanny - INFO -         Start Nanny at: 'tcp://127.0.0.1:56536'
2022-05-27 06:19:53,926 - distributed.worker - INFO -       Start worker at:      tcp://127.0.0.1:56541
2022-05-27 06:19:53,926 - distributed.worker - INFO -          Listening to:      tcp://127.0.0.1:56541
2022-05-27 06:19:53,926 - distributed.worker - INFO -          dashboard at:            127.0.0.1:56542
2022-05-27 06:19:53,926 - distributed.worker - INFO - Waiting to connect to:      tcp://127.0.0.1:56527
2022-05-27 06:19:53,926 - distributed.worker - INFO - -------------------------------------------------
2022-05-27 06:19:53,926 - distributed.worker - INFO -               Threads:                          2
2022-05-27 06:19:53,926 - distributed.worker - INFO -                Memory:                   9.33 GiB
2022-05-27 06:19:53,926 - distributed.worker - INFO -       Local Directory: /var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/tmpqs_op4a3/dask-worker-space/worker-828ryjvx
2022-05-27 06:19:53,927 - distributed.worker - INFO - -------------------------------------------------
2022-05-27 06:19:54,756 - distributed.scheduler - INFO - Register worker <WorkerState 'tcp://127.0.0.1:56541', status: init, memory: 0, processing: 0>
2022-05-27 06:19:54,757 - distributed.scheduler - INFO - Starting worker compute stream, tcp://127.0.0.1:56541
2022-05-27 06:19:54,758 - distributed.core - INFO - Starting established connection
2022-05-27 06:19:54,758 - distributed.worker - INFO -         Registered to:      tcp://127.0.0.1:56527
2022-05-27 06:19:54,758 - distributed.worker - INFO - -------------------------------------------------
2022-05-27 06:19:54,760 - distributed.core - INFO - Starting established connection
2022-05-27 06:19:55,242 - distributed.nanny - INFO - Nanny asking worker to close
2022-05-27 06:19:55,244 - distributed.worker - INFO - Stopping worker at tcp://127.0.0.1:56541
2022-05-27 06:19:55,246 - distributed.worker - INFO - Connection to scheduler broken. Closing without reporting.  Status: Status.closing
2022-05-27 06:19:55,247 - distributed.scheduler - INFO - Remove worker <WorkerState 'tcp://127.0.0.1:56541', status: closing, memory: 3, processing: 0>
2022-05-27 06:19:55,247 - distributed.core - INFO - Removing comms to tcp://127.0.0.1:56541
2022-05-27 06:19:55,508 - distributed.nanny - WARNING - Restarting worker
2022-05-27 06:19:57,479 - distributed.worker - INFO -       Start worker at:      tcp://127.0.0.1:56558
2022-05-27 06:19:57,479 - distributed.worker - INFO -          Listening to:      tcp://127.0.0.1:56558
2022-05-27 06:19:57,479 - distributed.worker - INFO -          dashboard at:            127.0.0.1:56559
2022-05-27 06:19:57,480 - distributed.worker - INFO - Waiting to connect to:      tcp://127.0.0.1:56527
2022-05-27 06:19:57,480 - distributed.worker - INFO - -------------------------------------------------
2022-05-27 06:19:57,480 - distributed.worker - INFO -               Threads:                          2
2022-05-27 06:19:57,480 - distributed.worker - INFO -                Memory:                   9.33 GiB
2022-05-27 06:19:57,480 - distributed.worker - INFO -       Local Directory: /var/folders/24/8k48jl6d249_n_qfxwsl6xvm0000gn/T/tmpqs_op4a3/dask-worker-space/worker-fo9bzbxy
2022-05-27 06:19:57,480 - distributed.worker - INFO - -------------------------------------------------
2022-05-27 06:19:58,265 - distributed.scheduler - INFO - Register worker <WorkerState 'tcp://127.0.0.1:56558', status: init, memory: 0, processing: 0>
2022-05-27 06:19:58,267 - distributed.scheduler - INFO - Starting worker compute stream, tcp://127.0.0.1:56558
2022-05-27 06:19:58,267 - distributed.core - INFO - Starting established connection
2022-05-27 06:19:58,268 - distributed.worker - INFO -         Registered to:      tcp://127.0.0.1:56527
2022-05-27 06:19:58,268 - distributed.worker - INFO - -------------------------------------------------
2022-05-27 06:19:58,270 - distributed.core - INFO - Starting established connection
2022-05-27 06:20:00,251 - distributed.worker - ERROR - Worker stream died during communication: tcp://127.0.0.1:56541
ConnectionRefusedError: [Errno 61] Connection refused
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/Users/runner/work/distributed/distributed/distributed/comm/core.py", line 289, in connect
    comm = await asyncio.wait_for(
  File "/Users/runner/miniconda3/envs/dask-distributed/lib/python3.10/asyncio/tasks.py", line 445, in wait_for
    return fut.result()
  File "/Users/runner/work/distributed/distributed/distributed/comm/tcp.py", line 451, in connect
    convert_stream_closed_error(self, e)
  File "/Users/runner/work/distributed/distributed/distributed/comm/tcp.py", line 148, in convert_stream_closed_error
    raise CommClosedError(f"in {obj}: {exc.__class__.__name__}: {exc}") from exc
distributed.comm.core.CommClosedError: in <distributed.comm.tcp.TCPConnector object at 0x13ff10df0>: ConnectionRefusedError: [Errno 61] Connection refused
The above exception was the direct cause of the following exception:
Traceback (most recent call last):
  File "/Users/runner/work/distributed/distributed/distributed/worker.py", line 3277, in gather_dep
    response = await get_data_from_worker(
  File "/Users/runner/work/distributed/distributed/distributed/worker.py", line 4593, in get_data_from_worker
    return await retry_operation(_get_data, operation="get_data_from_worker")
  File "/Users/runner/work/distributed/distributed/distributed/utils_comm.py", line 381, in retry_operation
    return await retry(
  File "/Users/runner/work/distributed/distributed/distributed/utils_comm.py", line 366, in retry
    return await coro()
  File "/Users/runner/work/distributed/distributed/distributed/worker.py", line 4570, in _get_data
    comm = await rpc.connect(worker)
  File "/Users/runner/work/distributed/distributed/distributed/core.py", line 1193, in connect
    return await connect_attempt
  File "/Users/runner/work/distributed/distributed/distributed/core.py", line 1129, in _connect
    comm = await connect(
  File "/Users/runner/work/distributed/distributed/distributed/comm/core.py", line 315, in connect
    raise OSError(
OSError: Timed out trying to connect to tcp://127.0.0.1:56541 after 5 s
2022-05-27 06:20:00,280 - distributed.nanny - INFO - Closing Nanny at 'tcp://127.0.0.1:56536'.
2022-05-27 06:20:00,281 - distributed.nanny - INFO - Nanny asking worker to close
2022-05-27 06:20:00,284 - distributed.worker - INFO - Stopping worker at tcp://127.0.0.1:56558
2022-05-27 06:20:00,287 - distributed.worker - INFO - Connection to scheduler broken. Closing without reporting.  Status: Status.closing
2022-05-27 06:20:00,288 - distributed.scheduler - INFO - Remove worker <WorkerState 'tcp://127.0.0.1:56558', status: closing, memory: 0, processing: 0>
2022-05-27 06:20:00,288 - distributed.core - INFO - Removing comms to tcp://127.0.0.1:56558
2022-05-27 06:20:00,590 - distributed.scheduler - INFO - Remove client Client-0499aa98-dd85-11ec-9af1-005056aba833
2022-05-27 06:20:00,591 - distributed.scheduler - INFO - Remove client Client-0499aa98-dd85-11ec-9af1-005056aba833
2022-05-27 06:20:00,591 - distributed.scheduler - INFO - Close client connection: Client-0499aa98-dd85-11ec-9af1-005056aba833
2022-05-27 06:20:00,593 - distributed.worker - INFO - Stopping worker at tcp://127.0.0.1:56528
2022-05-27 06:20:00,594 - distributed.worker - INFO - Stopping worker at tcp://127.0.0.1:56530
2022-05-27 06:20:00,598 - distributed.scheduler - INFO - Remove worker <WorkerState 'tcp://127.0.0.1:56528', name: 0, status: closing, memory: 0, processing: 0>
2022-05-27 06:20:00,598 - distributed.core - INFO - Removing comms to tcp://127.0.0.1:56528
2022-05-27 06:20:00,599 - distributed.scheduler - INFO - Remove worker <WorkerState 'tcp://127.0.0.1:56530', name: 1, status: closing, memory: 0, processing: 0>
2022-05-27 06:20:00,599 - distributed.core - INFO - Removing comms to tcp://127.0.0.1:56530
2022-05-27 06:20:00,599 - distributed.scheduler - INFO - Lost all workers
2022-05-27 06:20:00,599 - distributed.worker - INFO - Connection to scheduler broken. Closing without reporting.  Status: Status.closing
2022-05-27 06:20:00,600 - distributed.worker - INFO - Connection to scheduler broken. Closing without reporting.  Status: Status.closing
2022-05-27 06:20:00,605 - distributed.scheduler - INFO - Scheduler closing...
2022-05-27 06:20:00,606 - distributed.scheduler - INFO - Scheduler closing all comms
2022-05-27 06:20:00,768 - distributed.utils_perf - WARNING - full garbage collections took 31% CPU time recently (threshold: 10%)

  3. graingert commented on Nov 24, 2022

    @graingert
    graingert
    on Nov 24, 2022
    Member

    from #7249

    2022-11-24 13:12:20,027 - distributed.nanny - ERROR - Error in Nanny killing Worker subprocess
Traceback (most recent call last):
  File "d:\a\distributed\distributed\distributed\nanny.py", line 603, in close
    await self.kill(timeout=timeout, reason=reason)
  File "d:\a\distributed\distributed\distributed\nanny.py", line 388, in kill
    await self.process.kill(reason=reason, timeout=0.8 * (deadline - time()))
  File "d:\a\distributed\distributed\distributed\nanny.py", line 826, in kill
    await process.join(wait_timeout)
  File "d:\a\distributed\distributed\distributed\process.py", line 311, in join
    assert self._state.pid is not None, "can only join a started process"
AssertionError: can only join a started process

  4. fjetter commented on Dec 1, 2022

    @fjetter
    fjetter
    on Dec 1, 2022
    Member

    85562a0 fixes the problem mentioned in #6311 (comment)

    which is a race condition between starting and killing the WorkerProcess concurrently.

    I believe there are still other issues with this test but can't tell for sure. Locally I can trigger a couple of timeouts due to the 500ms connect timeout configured

  5. mrocklin commented on Dec 20, 2022

    @mrocklin
    mrocklin
    on Dec 20, 2022
    Member

    I just ran into this (and it appears to be quite common). It appears that the commit @fjetter mentions above was never merged in. Is there a story here?

  6. fjetter
    closed this as completedin #8032on Aug 3, 2023
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Metadata

Metadata

Assignees

No one assigned

    Labels

    flaky testIntermittent failures on CI.

    Type

    No type

    Projects

    No projects

      Milestone

      No milestone

      Relationships

      None yet

      Development

      No branches or pull requests

      Issue actions