Client spews errors in JupyterLab during `compute`

[gjoseph92]

In recent versions of distributed, during a compute, tons of errors sometimes start spewing out in JupyterLab like this:

I've heard other people complain about this too.

For searchability, here are some of the logs:

Details

tornado.application - ERROR - Exception in callback functools.partial(<bound method IOLoop._discard_future_result of <zmq.eventloop.ioloop.ZMQIOLoop object at 0x1334d13d0>>, <Task finished name='Task-337' coro=<Cluster._sync_cluster_info() done, defined at /Users/gabe/dev/distributed/distributed/deploy/cluster.py:104> exception=OSError('Timed out trying to connect to tls://54.212.201.147:8786 after 5 s')>)
Traceback (most recent call last):
  File "/Users/gabe/dev/distributed/distributed/comm/tcp.py", line 398, in connect
    stream = await self.client.connect(
  File "/Users/gabe/dev/dask-playground/env/lib/python3.9/site-packages/tornado/tcpclient.py", line 288, in connect
    stream = await stream.start_tls(
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/gabe/.pyenv/versions/3.9.1/lib/python3.9/asyncio/tasks.py", line 489, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/gabe/dev/distributed/distributed/comm/core.py", line 284, in connect
    comm = await asyncio.wait_for(
  File "/Users/gabe/.pyenv/versions/3.9.1/lib/python3.9/asyncio/tasks.py", line 491, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/gabe/dev/dask-playground/env/lib/python3.9/site-packages/tornado/ioloop.py", line 741, in _run_callback
    ret = callback()
  File "/Users/gabe/dev/dask-playground/env/lib/python3.9/site-packages/tornado/ioloop.py", line 765, in _discard_future_result
    future.result()
  File "/Users/gabe/dev/distributed/distributed/deploy/cluster.py", line 105, in _sync_cluster_info
    await self.scheduler_comm.set_metadata(
  File "/Users/gabe/dev/distributed/distributed/core.py", line 785, in send_recv_from_rpc
    comm = await self.live_comm()
  File "/Users/gabe/dev/distributed/distributed/core.py", line 742, in live_comm
    comm = await connect(
  File "/Users/gabe/dev/distributed/distributed/comm/core.py", line 308, in connect
    raise OSError(
OSError: Timed out trying to connect to tls://54.212.201.147:8786 after 5 s
tornado.application - ERROR - Exception in callback functools.partial(<bound method IOLoop._discard_future_result of <zmq.eventloop.ioloop.ZMQIOLoop object at 0x1334d13d0>>, <Task finished name='Task-340' coro=<Cluster._sync_cluster_info() done, defined at /Users/gabe/dev/distributed/distributed/deploy/cluster.py:104> exception=OSError('Timed out trying to connect to tls://54.212.201.147:8786 after 5 s')>)
Traceback (most recent call last):
  File "/Users/gabe/dev/distributed/distributed/comm/tcp.py", line 398, in connect
    stream = await self.client.connect(
  File "/Users/gabe/dev/dask-playground/env/lib/python3.9/site-packages/tornado/tcpclient.py", line 288, in connect
    stream = await stream.start_tls(
asyncio.exceptions.CancelledError

During handling of the above exception, another exception occurred:

Traceback (most recent call last):
  File "/Users/gabe/.pyenv/versions/3.9.1/lib/python3.9/asyncio/tasks.py", line 489, in wait_for
    fut.result()
asyncio.exceptions.CancelledError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/gabe/dev/distributed/distributed/comm/core.py", line 284, in connect
    comm = await asyncio.wait_for(
  File "/Users/gabe/.pyenv/versions/3.9.1/lib/python3.9/asyncio/tasks.py", line 491, in wait_for
    raise exceptions.TimeoutError() from exc
asyncio.exceptions.TimeoutError

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/Users/gabe/dev/dask-playground/env/lib/python3.9/site-packages/tornado/ioloop.py", line 741, in _run_callback
    ret = callback()
  File "/Users/gabe/dev/dask-playground/env/lib/python3.9/site-packages/tornado/ioloop.py", line 765, in _discard_future_result
    future.result()
  File "/Users/gabe/dev/distributed/distributed/deploy/cluster.py", line 105, in _sync_cluster_info
    await self.scheduler_comm.set_metadata(
  File "/Users/gabe/dev/distributed/distributed/core.py", line 785, in send_recv_from_rpc
    comm = await self.live_comm()
  File "/Users/gabe/dev/distributed/distributed/core.py", line 742, in live_comm
    comm = await connect(
  File "/Users/gabe/dev/distributed/distributed/comm/core.py", line 308, in connect
    raise OSError(
OSError: Timed out trying to connect to tls://54.212.201.147:8786 after 5 s
tornado.application - ERROR - Exception in callback functools.partial(<bound method IOLoop._discard_future_result of <zmq.eventloop.ioloop.ZMQIOLoop object at 0x1334d13d0>>, <Task finished name='Task-349' coro=<Cluster._sync_cluster_info() done, defined at /Users/gabe/dev/distributed/distributed/deploy/cluster.py:104> exception=OSError('Timed out trying to connect to tls://54.212.201.147:8786 after 5 s')>)
Traceback (most recent call last):
  File "/Users/gabe/dev/distributed/distributed/comm/tcp.py", line 398, in connect
    stream = await self.client.connect(
  File "/Users/gabe/dev/dask-playground/env/lib/python3.9/site-packages/tornado/tcpclient.py", line 288, in connect
    stream = await stream.start_tls(
asyncio.exceptions.CancelledError

From reading the traceback, it appears to be unhandled exceptions in the new cluster<->scheduler synced dict from #5033. I'd guess that when the scheduler gets overwhelmed from any of the myriad of things that can block its event loop, something breaks. I'm not sure why it stays broken and the comm doesn't reconnect, but after one failure it seems you'll get this message once per second.

1. There should be error handling in the cluster info syncing; at a minimum, any error here should be handled and logged, but not allowed to propagate up
2. Why is this error happening, and why does it not seem to recover?

cc @jacobtomlinson

[jrbourbeau]

Thanks for reporting @gjoseph92. Do you have a code example other can use to reproduce those errors?

[ian-r-rose]

Is this specific to JupyterLab, or does the same thing happen in an IPython terminal or regular Python session?

[ncclementi]

@jrbourbeau I've seen this happening too, but the same code that spills the error, then it runs fine, and so far I couldn't narrow down a code example to reproduce.

@ian-r-rose I saw it on pure notebooks but I'm assuming this is similar to JupyterLab.

[ntabris]

We've been seeing this OSError: Timed out a lot from the _sync_cluster_info periodic callback when Coiled cluster is (i) slow to start, (ii) slow to stopped or stopped without client knowing, or (iii) just too busy to respond.

One easy way to reproduce is to kill scheduler without the python client knowing.

I'm not familiar with what the sync is needed for, but I agree that it makes sense to handle the timeouts when they occur there. Simplest option is to silently catch, maybe like this: main...ntabris:main

Another option would be to add optional callback to rpc class, and if this callback is given, then call it when there's timeout rather than throwing OSError. This would allow user (e.g., coiled) to decide what to do with timeout... for instance, check cluster health if there's another way to do that (as there is for coiled).

[ian-r-rose]

@ian-r-rose I saw it on pure notebooks but I'm assuming this is similar to JupyterLab.

Right, my question is: does this issue have anything to do with which Python interface people are using (pure interpreter, notebook, whatever)? It seems like the answer is no.

[jrbourbeau]

One easy way to reproduce is to kill scheduler without the python client knowing

Thanks for pointing that out @ntabris. Here's a concrete snippet which one can use to trigger the errors (note that you'll need to wait a few seconds before the errors start appearing):

from distributed import LocalCluster, Client

cluster = LocalCluster()
client = Client(cluster)

async def foo(dask_scheduler):
    await dask_scheduler.close()
    
client.run_on_scheduler(foo)

does this issue have anything to do with which Python interface people are using (pure interpreter, notebook, whatever)? It seems like the answer is no.

I can confirm this happens in JupyterLab, IPython, and a plain Python session

FWIW @jcrist mentioned he's looking into this issue

[gjoseph92]

Thanks for finding a reproducer @jrbourbeau! Very helpful.