Repository: zopefoundation/ZEO (language: python)

Issue:
Client does not retry failed connections
In my development environment, I use a script to run a zeo server and a flask application configured as a zeo client. The connection between the client and the server is done with a unix socket.
Depending on the runs, the server may or may not be ready before the client is. With ZEO 5.4.0, when the client is ready first, it prints the following error message, and does not retry to connect:

```
2023-03-10 09:34:34,836:INFO:ZEO.asyncio.client:Connection to '/path/to/zeo.sock' failed, [Errno 2] No such file or directory
```

With ZEO 5.3.0 the client would have tried several times until the connection succeeds, which was very convenient in such situations.

I suggest implementing a timeout or a try again mechanism for client connection. What do you think?
Client does not retry failed connections
In my development environment, I use a script to run a zeo server and a flask application configured as a zeo client. The connection between the client and the server is done with a unix socket.
Depending on the runs, the server may or may not be ready before the client is. With ZEO 5.4.0, when the client is ready first, it prints the following error message, and does not retry to connect:

```
2023-03-10 09:34:34,836:INFO:ZEO.asyncio.client:Connection to '/path/to/zeo.sock' failed, [Errno 2] No such file or directory
```

With ZEO 5.3.0 the client would have tried several times until the connection succeeds, which was very convenient in such situations.

I suggest implementing a timeout or a try again mechanism for client connection. What do you think?
Client does not retry failed connections
In my development environment, I use a script to run a zeo server and a flask application configured as a zeo client. The connection between the client and the server is done with a unix socket.
Depending on the runs, the server may or may not be ready before the client is. With ZEO 5.4.0, when the client is ready first, it prints the following error message, and does not retry to connect:

```
2023-03-10 09:34:34,836:INFO:ZEO.asyncio.client:Connection to '/path/to/zeo.sock' failed, [Errno 2] No such file or directory
```

With ZEO 5.3.0 the client would have tried several times until the connection succeeds, which was very convenient in such situations.

I suggest implementing a timeout or a try again mechanism for client connection. What do you think?


Discussion / hints:
Éloi Rivard wrote at 2023-3-10 00:42 -0800:
>In my development environment, I use a script to run a zeo server and a flask application configured as a zeo client. The connection between the client and the server is done with a unix socket.
>Depending on the runs, the server may or may not be ready before the client is. With ZEO 5.4.0 , when the client is ready first, it prints the following error message, and does not retry:
>
>```
>2023-03-10 09:34:34,836:INFO:ZEO.asyncio.client:Connection to '/path/to/zeo.sock' failed, [Errno 2] No such file or directory
>```
>
>Until ZEO 5.3.0 the client would have tried several times until the connection succeeds, which was very convenient in such situations.
>
>I suggest implementing a timeout or a try again mechanism for client connection. What do you think?

This functionality should still be there.

The code is in `ZEO.asycio.client.Protocol.connect` and
reads:
```python
	...
	cr = lambda: self.loop.create_unix_connection(...)
	...
	@coroutine
        def connect():
            while not self.closed:
                try:
                    yield cr()
                    return
                except asyncio.CancelledError:
                    logger.info("Connection to %r cancelled", self.addr)
                    raise
                except Exception as exc:
                    logger.info("Connection to %r failed, %s",
                                self.addr, exc)
                yield asyncio.sleep(self.connect_poll + local_random.random())
                logger.info("retry connecting %r", self.addr)
        self._connecting = Task(connect(), self.loop)
```

This means: if `create_unix_connection` raises an exception
different from `CancelledError`, then `Connection failed` is
logged, then the coroutine waits between 1 (`== self.connect_poll`)
and 2 seconds, then logs `retry connecting` and tries `create_unix_connection`
again.

You might try debugging the code above to find out why
you do not see the reconnection trial.

If it really does not work, you might contact @navytux.
Likely, it would mean that the `asyncio.sleep` does not finish
or the coroutine execution has a problem.
@navitux implemented the `coroutine` executor (behind the `Task`).



Thank you for your answer. The error seems to be around `yield asyncio.sleep`, as the *retry connecting* message is never shown.

Actually, if I wait long enough, I get this error message:

```python
2023-03-10 15:24:55,758:INFO:ZEO.ClientStorage:/path/to/zeo.sock ClientStorage (pid=156361) created RW/normal for storage: '1'
2023-03-10 15:24:55,765:INFO:ZEO.cache:created temporary cache file 4
2023-03-10 15:24:55,769:INFO:ZEO.asyncio.client:Connection to '/path/to/zeo.sock' failed, [Errno 2] No such file or directory
Traceback (most recent call last):
  File "/path/to/bin/flask", line 8, in <module>
    sys.exit(main())
  File "/path/to/flask/cli.py", line 1050, in main
    cli.main()
  File "/path/to/click/core.py", line 1055, in main
    rv = self.invoke(ctx)
  File "/path/to/click/core.py", line 1657, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/path/to/click/core.py", line 1404, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/path/to/click/core.py", line 760, in invoke
    return __callback(*args, **kwargs)
  File "/path/to/click/decorators.py", line 84, in new_func
    return ctx.invoke(f, obj, *args, **kwargs)
  File "/path/to/click/core.py", line 760, in invoke
    return __callback(*args, **kwargs)
  File "/path/to/flask/cli.py", line 911, in run_command
    raise e from None
  File "/path/to/flask/cli.py", line 897, in run_command
    app = info.load_app()
  File "/path/to/flask/cli.py", line 308, in load_app
    app = locate_app(import_name, name)
  File "/path/to/flask/cli.py", line 235, in locate_app
    return find_best_app(module)
  File "/path/to/flask/cli.py", line 63, in find_best_app
    app = app_factory()
  File "/path/to/web/__init__.py", line 215, in create_app
    setup_database(app)
  File "/path/to/web/__init__.py", line 197, in setup_database
    sheraf.Database.get_or_create(uri=app.config["DB_URI"])
  File "/path/to/sheraf/databases.py", line 372, in get_or_create
    return Database(**kwargs)
  File "/path/to/sheraf/databases.py", line 118, in __init__
    self.reset(storage, uri)
  File "/path/to/sheraf/databases.py", line 152, in reset
    self.storage = storage_factory()
  File "/path/to/zodburi/resolvers.py", line 160, in factory
    return ClientStorage(*args, **kw)
  File "/path/to/ZEO/ClientStorage.py", line 353, in __init__
    self._wait()
  File "/path/to/ZEO/asyncio/client.py", line 1001, in wait
    return self.io_call(
  File "/path/to/ZEO/asyncio/client.py", line 868, in io_call
    return future.result() if wait else future
  File "/path/to/ZEO/asyncio/futures.py", line 224, in result
    return Future.result(self)
  File "/path/to/ZEO/asyncio/futures.py", line 75, in result
    raise self._result
  File "/path/to/ZEO/asyncio/futures.py", line 267, in step
    result = self.coro.throw(await_result)
  File "/path/to/ZEO/asyncio/client.py", line 706, in await_operational_co
    raise ClientDisconnected("timed out waiting for connection")
ZEO.Exceptions.ClientDisconnected: timed out waiting for connection
2023-03-10 15:34:55,902:ERROR:asyncio:AsyncTask exception was never retrieved
future: <ZEO.asyncio.futures.AsyncTask object at 0x7f777695ea40>
Traceback (most recent call last):
  File "/path/to/ZEO/asyncio/futures.py", line 267, in step
    result = self.coro.throw(await_result)
  File "/path/to/ZEO/asyncio/client.py", line 170, in connect
    yield asyncio.sleep(sleep_n)
  File "/path/to/ZEO/asyncio/futures.py", line 253, in step
    await_result = awaiting.result()
  File "/path/to/ZEO/asyncio/futures.py", line 75, in result
    raise self._result
  File "/path/to/ZEO/asyncio/futures.py", line 265, in step
    result = self.coro.send(await_result)
  File "/usr/lib/python3.10/asyncio/tasks.py", line 599, in sleep
    loop = events.get_running_loop()
RuntimeError: no running event loop
make: *** [Makefile:15: run-web] Error 1
```
Installing the `uvloop` package solves the situation.
Éloi Rivard wrote at 2023-3-10 07:30 -0800:
> ...
>Thank you for your answer. The error seems to be around `yield asyncio.sleep`, as the *retry connecting* message is never shown.

You might want to learn how long the sleep should be.
Usually, it would be between 1 and 2 seconds.
>
>Actually, if I wait long enough, I get this error message:
>
>```python
> ...
>  File "/path/to/ZEO/asyncio/client.py", line 706, in await_operational_co
>    raise ClientDisconnected("timed out waiting for connection")
>ZEO.Exceptions.ClientDisconnected: timed out waiting for connection
>2023-03-10 15:34:55,902:ERROR:asyncio:AsyncTask exception was never retrieved

This is the normal 30 s connection timeout.
The `sleep` time should be significantly shorter.

>future: <ZEO.asyncio.futures.AsyncTask object at 0x7f777695ea40>
>Traceback (most recent call last):
> ...
>    loop = events.get_running_loop()
>RuntimeError: no running event loop

Once the connection timeout occurred, the client is closed.
Part of this process is cancelling the connection process
and shutting down the loop.
Apparently, the loop is shut down before the cancelation is finished.
This causes the observed exception.

I agree with you that something does not work as expected with
the `sleep`.
At your place, I would try to find out how long the sleep should be
(e.g. by modifying the code and logging the sleep time).
If the sleep takes significantly longer that this time,
I would contact @navytux.
If the sleep time is much higher than the expected 1 to 2 seconds,
something went wrong with the parameter passing or the
`local_random` behaves strangely.

Éloi Rivard wrote at 2023-3-10 07:39 -0800:
>Installing the `uvloop` package solves the situation.

`uvloop` causes different timeing behavior. Therefore,
your observations may be different.
However, there should be no significant difference
regarding the `sleep`.
Therefore, I expect that the problem you have observed earlier
still exists, and just happens to not yet be observed.

> At your place, I would try to find out how long the sleep should be (e.g. by modifying the code and logging the sleep time). If the sleep takes significantly longer that this time, I would contact @navytux.

Logging tells me that the value passed to sleep is as expected between 1 and 2. However the sleep appears to happen 30 seconds (or `wait_timeout` seconds if it is set), and then the `ClientDisconnected` exception is raised.
Forcing the sleep value to 1 or 2 seconds does not change the behavior.

The `uvloop` installation is just a workaround I use for the moment, but I though it worth mentioning it :)
> However the sleep appears to happen 30 seconds (or `wait_timeout` seconds if it is set), and then the `ClientDisconnected` exception is raised.

This means that the `sleep` does not work.

@navytux Potentially, `sleep` uses a task feature not supported by our special `Task` implementation; or the coroutine executor does something wrong with the `Future` used by `sleep`. Would you analyze the problem?

@azmeuk Would you tell us which Python version you are using?
Yup. Python 3.10.9
@azmeuk 
I have tried to reproduce the problem with the following (simplified) script
```python
from _thread import start_new_thread
from time import time, sleep
from ZEO.asyncio.client import Task, coroutine, asyncio

@coroutine
def test_sleep():
  global F
  F = asyncio.Future()
  try: yield F
  except Exception: print("Exception")
  s = time()
  yield asyncio.sleep(1)
  print(time() - s)

def t():
  global loop
  loop = asyncio.new_event_loop()
  asyncio.set_event_loop(loop)
  loop.run_forever()

start_new_thread(t, ())
sleep(0.1)

def create_task():
  global T
  T = Task(test_sleep())

loop.call_soon_threadsafe(create_task)
sleep(0.1)
loop.call_soon_threadsafe(F.set_exception, ValueError())
sleep(2)
```
It emulates the `connect` coroutine by coroutine `test_sleep`. The failing connection establishment is emulated by a future which gets an exception set.
I could not observe a `sleep` failure (with Python 3.10.3).

Would you run the script in your environment (without `uvloop`)?
If `sleep` has a problem, the last output is `Exception`; otherwise, additional output (a number near 1) follows.

The following even simpler script emulates the situation more faithfully:
```python
from _thread import start_new_thread
from time import time, sleep
from ZEO.asyncio.client import Task, coroutine, asyncio

@coroutine
def test_sleep():
  try: yield loop.create_unix_connection(asyncio.Protocol, "u.sock")
  except Exception as e: print(e.__class__, e)
  s = time()
  yield asyncio.sleep(1)
  print(time() - s)

def t():
  global loop
  loop = asyncio.new_event_loop()
  asyncio.set_event_loop(loop)
  loop.run_forever()

start_new_thread(t, ())
sleep(0.1)

def create_task():
  global T
  T = Task(test_sleep())

loop.call_soon_threadsafe(create_task)
sleep(2)
```

In my env, I cannot see a `sleep` problem: the script ends with the output of a number near 1.
Here are the output of your scripts:

```
Exception
1.0012478828430176
```

```
<class 'FileNotFoundError'> [Errno 2] No such file or directory
1.0012452602386475
```

In both cases, nothing hangs, and the script execution is quick.
Éloi Rivard wrote at 2023-3-13 02:40 -0700:
> ...
>In both cases, nothing hangs, and the script execution is quick.

I have looked at the `sleep` implementation.
It is essentially a `loop.call_later` where the callback
sets the future's result and thereby terminates the sleeping.

The connection timeout uses a similar approach, based, too, on
`loop.call_later`. You have observed that this timeout works.
Therefore, it is extremely strange that `sleep` has problems.

Hello @azmeuk, thanks for reporting.
Hello @d-maurer, thanks for your help and for pinging me.

I've looked at this problem a bit this morning. Here is why it happens:

The `connect` coroutine starts to be executed before `loop.run_forever` is called. That's why `asyncio.sleep()` raises "no running event loop". here is how that happens:

with the following debug patch:

```diff
--- a/src/ZEO/asyncio/client.py
+++ b/src/ZEO/asyncio/client.py
@@ -145,6 +145,9 @@ def pop_futures(self):
         return futures
 
     def connect(self):
+        trace('connect')
+        import traceback as tb; tb.print_stack()
+        trace()
         if isinstance(self.addr, tuple):
             host, port = self.addr
             cr = lambda: self.loop.create_connection(  # noqa: E731
@@ -156,6 +159,9 @@ def connect(self):
 
         @coroutine
         def connect():
+            trace('coro connect')
+            import traceback as tb; tb.print_stack()
+            trace('running loop:', asyncio.events.get_running_loop())
             while not self.closed:
                 try:
                     yield cr()
@@ -1035,9 +1041,14 @@ def run_io_thread(self):
         try:
             loop = self.loop if self.loop is not None else new_event_loop()
             asyncio.set_event_loop(loop)
+            trace('>>> setup_delegation')
             self.setup_delegation(loop)
+            trace('<<< setup_delegation')
             loop.call_soon(self.started.set)
+            import time; time.sleep(3)
+            trace('>>> loop.run_forever')
             loop_run_forever(loop)
+            trace('<<< loop.run_forever')
         except Exception as exc:
             logger.exception("Client thread")
             self.exception = exc
@@ -1088,3 +1099,8 @@ def cancel_task(task):
     if sys.version_info < (3,9):
         task.add_done_callback(
             lambda future: future.cancelled() or future.exception())
+
+
+import sys
+def trace(*argv):
+    print(*argv, file=sys.stderr, flush=True)
```

and the following test progam

```py
#!/usr/bin/env python

import logging
logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(levelname)s - %(message)s')

import ZEO
print('AAA')
zcli = ZEO.client('/path/to/zeo.sock')
print('BBB')
```

the output is like this:

```
(py3.venv) kirr@deca:~/src/wendelin/z/ZEO$ ../ZEO5/x.py 2>&1 
AAA
2023-03-14 07:21:01,569 - INFO - /path/to/zeo.sock ClientStorage (pid=49949) created RW/normal for storage: '1'
2023-03-14 07:21:01,569 - INFO - created temporary cache file 3
2023-03-14 07:21:01,570 - DEBUG - Using selector: EpollSelector
>>> setup_delegation
2023-03-14 07:21:01,570 - DEBUG - disconnected <ZEO.asyncio.client.ClientIO object at 0x7f03c50077c0> None
2023-03-14 07:21:01,570 - DEBUG - try_connecting <ZEO.asyncio.client.ClientIO object at 0x7f03c50077c0>
connect
  File "/usr/lib/python3.9/threading.py", line 912, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.9/threading.py", line 954, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.9/threading.py", line 892, in run
    self._target(*self._args, **self._kwargs)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 1045, in run_io_thread
    self.setup_delegation(loop)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 861, in setup_delegation
    self.client = client = ClientIO(loop, *self.__args, **self.__kwargs)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 477, in __init__
    self.disconnected(None)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 537, in disconnected
    self.try_connecting()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 549, in try_connecting
    self.protocols = [
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 550, in <listcomp>
    Protocol(self.loop, addr, self,
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 93, in __init__
    self.connect()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 149, in connect
    import traceback as tb; tb.print_stack()

coro connect
  File "/usr/lib/python3.9/threading.py", line 912, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.9/threading.py", line 954, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.9/threading.py", line 892, in run
    self._target(*self._args, **self._kwargs)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 1045, in run_io_thread
    self.setup_delegation(loop)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 861, in setup_delegation
    self.client = client = ClientIO(loop, *self.__args, **self.__kwargs)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 477, in __init__
    self.disconnected(None)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 537, in disconnected
    self.try_connecting()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 549, in try_connecting
    self.protocols = [
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 550, in <listcomp>
    Protocol(self.loop, addr, self,
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 93, in __init__
    self.connect()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 178, in connect
    self._connecting = Task(connect(), self.loop)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/futures.py", line 390, in __init__
    self.executor.step()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/futures.py", line 271, in step
    result = self.coro.send(await_result)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 163, in connect
    import traceback as tb; tb.print_stack()
<<< setup_delegation


>>> loop.run_forever
...
```

which shows that `connect` coroutine indeed starts to be executing immediately by `self._connecting = Task(connect(), self.loop)` because that Task is our task with immediate callback invocations. In other words here we try to run asyncio code outside of a running loop and that's why it breaks.

The fix should be something like this:

```diff
diff --git a/src/ZEO/asyncio/client.py b/src/ZEO/asyncio/client.py
index 34e85cf9..768b04ee 100644
--- a/src/ZEO/asyncio/client.py
+++ b/src/ZEO/asyncio/client.py
@@ -1041,10 +1041,13 @@ def run_io_thread(self):
         try:
             loop = self.loop if self.loop is not None else new_event_loop()
             asyncio.set_event_loop(loop)
-            trace('>>> setup_delegation')
-            self.setup_delegation(loop)
-            trace('<<< setup_delegation')
-            loop.call_soon(self.started.set)
+            # setup_delegation triggers to execute coroutines - we need to call it from under running loop
+            def _():
+                trace('>>> setup_delegation')
+                self.setup_delegation(loop)
+                trace('<<< setup_delegation')
+                self.started.set()
+            loop.call_soon(_)
             import time; time.sleep(3)
             trace('>>> loop.run_forever')
             loop_run_forever(loop)
```

which is similar in style to d27a2cd1.

@d-maurer, if you agree with my analysis I will try to do a proper patch later, hopefully today.

For the reference: we do not have this problem on master, because there we changed `._connecting` to be native asyncio task instead of our own in 63429391 + e3b8658d, and that has the side effect of not running connect coroutine immediately and instead scheduling it to be run when the loop is run. Still I would consider to apply my fix to master as well because it is potentially safer to do async-related activity from under already setup running loop.

Hope that helps a bit,
Kirill
Thank your @navytux for you investigation. Indeed the master branch seems to not have this issue, and your patch fixes it on 5.4.0.
Thanks, @azmeuk. I followed-up with https://github.com/zopefoundation/ZEO/pull/227.
Éloi Rivard wrote at 2023-3-10 00:42 -0800:
>In my development environment, I use a script to run a zeo server and a flask application configured as a zeo client. The connection between the client and the server is done with a unix socket.
>Depending on the runs, the server may or may not be ready before the client is. With ZEO 5.4.0 , when the client is ready first, it prints the following error message, and does not retry:
>
>```
>2023-03-10 09:34:34,836:INFO:ZEO.asyncio.client:Connection to '/path/to/zeo.sock' failed, [Errno 2] No such file or directory
>```
>
>Until ZEO 5.3.0 the client would have tried several times until the connection succeeds, which was very convenient in such situations.
>
>I suggest implementing a timeout or a try again mechanism for client connection. What do you think?

This functionality should still be there.

The code is in `ZEO.asycio.client.Protocol.connect` and
reads:
```python
	...
	cr = lambda: self.loop.create_unix_connection(...)
	...
	@coroutine
        def connect():
            while not self.closed:
                try:
                    yield cr()
                    return
                except asyncio.CancelledError:
                    logger.info("Connection to %r cancelled", self.addr)
                    raise
                except Exception as exc:
                    logger.info("Connection to %r failed, %s",
                                self.addr, exc)
                yield asyncio.sleep(self.connect_poll + local_random.random())
                logger.info("retry connecting %r", self.addr)
        self._connecting = Task(connect(), self.loop)
```

This means: if `create_unix_connection` raises an exception
different from `CancelledError`, then `Connection failed` is
logged, then the coroutine waits between 1 (`== self.connect_poll`)
and 2 seconds, then logs `retry connecting` and tries `create_unix_connection`
again.

You might try debugging the code above to find out why
you do not see the reconnection trial.

If it really does not work, you might contact @navytux.
Likely, it would mean that the `asyncio.sleep` does not finish
or the coroutine execution has a problem.
@navitux implemented the `coroutine` executor (behind the `Task`).



Thank you for your answer. The error seems to be around `yield asyncio.sleep`, as the *retry connecting* message is never shown.

Actually, if I wait long enough, I get this error message:

```python
2023-03-10 15:24:55,758:INFO:ZEO.ClientStorage:/path/to/zeo.sock ClientStorage (pid=156361) created RW/normal for storage: '1'
2023-03-10 15:24:55,765:INFO:ZEO.cache:created temporary cache file 4
2023-03-10 15:24:55,769:INFO:ZEO.asyncio.client:Connection to '/path/to/zeo.sock' failed, [Errno 2] No such file or directory
Traceback (most recent call last):
  File "/path/to/bin/flask", line 8, in <module>
    sys.exit(main())
  File "/path/to/flask/cli.py", line 1050, in main
    cli.main()
  File "/path/to/click/core.py", line 1055, in main
    rv = self.invoke(ctx)
  File "/path/to/click/core.py", line 1657, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/path/to/click/core.py", line 1404, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/path/to/click/core.py", line 760, in invoke
    return __callback(*args, **kwargs)
  File "/path/to/click/decorators.py", line 84, in new_func
    return ctx.invoke(f, obj, *args, **kwargs)
  File "/path/to/click/core.py", line 760, in invoke
    return __callback(*args, **kwargs)
  File "/path/to/flask/cli.py", line 911, in run_command
    raise e from None
  File "/path/to/flask/cli.py", line 897, in run_command
    app = info.load_app()
  File "/path/to/flask/cli.py", line 308, in load_app
    app = locate_app(import_name, name)
  File "/path/to/flask/cli.py", line 235, in locate_app
    return find_best_app(module)
  File "/path/to/flask/cli.py", line 63, in find_best_app
    app = app_factory()
  File "/path/to/web/__init__.py", line 215, in create_app
    setup_database(app)
  File "/path/to/web/__init__.py", line 197, in setup_database
    sheraf.Database.get_or_create(uri=app.config["DB_URI"])
  File "/path/to/sheraf/databases.py", line 372, in get_or_create
    return Database(**kwargs)
  File "/path/to/sheraf/databases.py", line 118, in __init__
    self.reset(storage, uri)
  File "/path/to/sheraf/databases.py", line 152, in reset
    self.storage = storage_factory()
  File "/path/to/zodburi/resolvers.py", line 160, in factory
    return ClientStorage(*args, **kw)
  File "/path/to/ZEO/ClientStorage.py", line 353, in __init__
    self._wait()
  File "/path/to/ZEO/asyncio/client.py", line 1001, in wait
    return self.io_call(
  File "/path/to/ZEO/asyncio/client.py", line 868, in io_call
    return future.result() if wait else future
  File "/path/to/ZEO/asyncio/futures.py", line 224, in result
    return Future.result(self)
  File "/path/to/ZEO/asyncio/futures.py", line 75, in result
    raise self._result
  File "/path/to/ZEO/asyncio/futures.py", line 267, in step
    result = self.coro.throw(await_result)
  File "/path/to/ZEO/asyncio/client.py", line 706, in await_operational_co
    raise ClientDisconnected("timed out waiting for connection")
ZEO.Exceptions.ClientDisconnected: timed out waiting for connection
2023-03-10 15:34:55,902:ERROR:asyncio:AsyncTask exception was never retrieved
future: <ZEO.asyncio.futures.AsyncTask object at 0x7f777695ea40>
Traceback (most recent call last):
  File "/path/to/ZEO/asyncio/futures.py", line 267, in step
    result = self.coro.throw(await_result)
  File "/path/to/ZEO/asyncio/client.py", line 170, in connect
    yield asyncio.sleep(sleep_n)
  File "/path/to/ZEO/asyncio/futures.py", line 253, in step
    await_result = awaiting.result()
  File "/path/to/ZEO/asyncio/futures.py", line 75, in result
    raise self._result
  File "/path/to/ZEO/asyncio/futures.py", line 265, in step
    result = self.coro.send(await_result)
  File "/usr/lib/python3.10/asyncio/tasks.py", line 599, in sleep
    loop = events.get_running_loop()
RuntimeError: no running event loop
make: *** [Makefile:15: run-web] Error 1
```
Installing the `uvloop` package solves the situation.
Éloi Rivard wrote at 2023-3-10 07:30 -0800:
> ...
>Thank you for your answer. The error seems to be around `yield asyncio.sleep`, as the *retry connecting* message is never shown.

You might want to learn how long the sleep should be.
Usually, it would be between 1 and 2 seconds.
>
>Actually, if I wait long enough, I get this error message:
>
>```python
> ...
>  File "/path/to/ZEO/asyncio/client.py", line 706, in await_operational_co
>    raise ClientDisconnected("timed out waiting for connection")
>ZEO.Exceptions.ClientDisconnected: timed out waiting for connection
>2023-03-10 15:34:55,902:ERROR:asyncio:AsyncTask exception was never retrieved

This is the normal 30 s connection timeout.
The `sleep` time should be significantly shorter.

>future: <ZEO.asyncio.futures.AsyncTask object at 0x7f777695ea40>
>Traceback (most recent call last):
> ...
>    loop = events.get_running_loop()
>RuntimeError: no running event loop

Once the connection timeout occurred, the client is closed.
Part of this process is cancelling the connection process
and shutting down the loop.
Apparently, the loop is shut down before the cancelation is finished.
This causes the observed exception.

I agree with you that something does not work as expected with
the `sleep`.
At your place, I would try to find out how long the sleep should be
(e.g. by modifying the code and logging the sleep time).
If the sleep takes significantly longer that this time,
I would contact @navytux.
If the sleep time is much higher than the expected 1 to 2 seconds,
something went wrong with the parameter passing or the
`local_random` behaves strangely.

Éloi Rivard wrote at 2023-3-10 07:39 -0800:
>Installing the `uvloop` package solves the situation.

`uvloop` causes different timeing behavior. Therefore,
your observations may be different.
However, there should be no significant difference
regarding the `sleep`.
Therefore, I expect that the problem you have observed earlier
still exists, and just happens to not yet be observed.

> At your place, I would try to find out how long the sleep should be (e.g. by modifying the code and logging the sleep time). If the sleep takes significantly longer that this time, I would contact @navytux.

Logging tells me that the value passed to sleep is as expected between 1 and 2. However the sleep appears to happen 30 seconds (or `wait_timeout` seconds if it is set), and then the `ClientDisconnected` exception is raised.
Forcing the sleep value to 1 or 2 seconds does not change the behavior.

The `uvloop` installation is just a workaround I use for the moment, but I though it worth mentioning it :)
> However the sleep appears to happen 30 seconds (or `wait_timeout` seconds if it is set), and then the `ClientDisconnected` exception is raised.

This means that the `sleep` does not work.

@navytux Potentially, `sleep` uses a task feature not supported by our special `Task` implementation; or the coroutine executor does something wrong with the `Future` used by `sleep`. Would you analyze the problem?

@azmeuk Would you tell us which Python version you are using?
Yup. Python 3.10.9
@azmeuk 
I have tried to reproduce the problem with the following (simplified) script
```python
from _thread import start_new_thread
from time import time, sleep
from ZEO.asyncio.client import Task, coroutine, asyncio

@coroutine
def test_sleep():
  global F
  F = asyncio.Future()
  try: yield F
  except Exception: print("Exception")
  s = time()
  yield asyncio.sleep(1)
  print(time() - s)

def t():
  global loop
  loop = asyncio.new_event_loop()
  asyncio.set_event_loop(loop)
  loop.run_forever()

start_new_thread(t, ())
sleep(0.1)

def create_task():
  global T
  T = Task(test_sleep())

loop.call_soon_threadsafe(create_task)
sleep(0.1)
loop.call_soon_threadsafe(F.set_exception, ValueError())
sleep(2)
```
It emulates the `connect` coroutine by coroutine `test_sleep`. The failing connection establishment is emulated by a future which gets an exception set.
I could not observe a `sleep` failure (with Python 3.10.3).

Would you run the script in your environment (without `uvloop`)?
If `sleep` has a problem, the last output is `Exception`; otherwise, additional output (a number near 1) follows.

The following even simpler script emulates the situation more faithfully:
```python
from _thread import start_new_thread
from time import time, sleep
from ZEO.asyncio.client import Task, coroutine, asyncio

@coroutine
def test_sleep():
  try: yield loop.create_unix_connection(asyncio.Protocol, "u.sock")
  except Exception as e: print(e.__class__, e)
  s = time()
  yield asyncio.sleep(1)
  print(time() - s)

def t():
  global loop
  loop = asyncio.new_event_loop()
  asyncio.set_event_loop(loop)
  loop.run_forever()

start_new_thread(t, ())
sleep(0.1)

def create_task():
  global T
  T = Task(test_sleep())

loop.call_soon_threadsafe(create_task)
sleep(2)
```

In my env, I cannot see a `sleep` problem: the script ends with the output of a number near 1.
Here are the output of your scripts:

```
Exception
1.0012478828430176
```

```
<class 'FileNotFoundError'> [Errno 2] No such file or directory
1.0012452602386475
```

In both cases, nothing hangs, and the script execution is quick.
Éloi Rivard wrote at 2023-3-13 02:40 -0700:
> ...
>In both cases, nothing hangs, and the script execution is quick.

I have looked at the `sleep` implementation.
It is essentially a `loop.call_later` where the callback
sets the future's result and thereby terminates the sleeping.

The connection timeout uses a similar approach, based, too, on
`loop.call_later`. You have observed that this timeout works.
Therefore, it is extremely strange that `sleep` has problems.

Hello @azmeuk, thanks for reporting.
Hello @d-maurer, thanks for your help and for pinging me.

I've looked at this problem a bit this morning. Here is why it happens:

The `connect` coroutine starts to be executed before `loop.run_forever` is called. That's why `asyncio.sleep()` raises "no running event loop". here is how that happens:

with the following debug patch:

```diff
--- a/src/ZEO/asyncio/client.py
+++ b/src/ZEO/asyncio/client.py
@@ -145,6 +145,9 @@ def pop_futures(self):
         return futures
 
     def connect(self):
+        trace('connect')
+        import traceback as tb; tb.print_stack()
+        trace()
         if isinstance(self.addr, tuple):
             host, port = self.addr
             cr = lambda: self.loop.create_connection(  # noqa: E731
@@ -156,6 +159,9 @@ def connect(self):
 
         @coroutine
         def connect():
+            trace('coro connect')
+            import traceback as tb; tb.print_stack()
+            trace('running loop:', asyncio.events.get_running_loop())
             while not self.closed:
                 try:
                     yield cr()
@@ -1035,9 +1041,14 @@ def run_io_thread(self):
         try:
             loop = self.loop if self.loop is not None else new_event_loop()
             asyncio.set_event_loop(loop)
+            trace('>>> setup_delegation')
             self.setup_delegation(loop)
+            trace('<<< setup_delegation')
             loop.call_soon(self.started.set)
+            import time; time.sleep(3)
+            trace('>>> loop.run_forever')
             loop_run_forever(loop)
+            trace('<<< loop.run_forever')
         except Exception as exc:
             logger.exception("Client thread")
             self.exception = exc
@@ -1088,3 +1099,8 @@ def cancel_task(task):
     if sys.version_info < (3,9):
         task.add_done_callback(
             lambda future: future.cancelled() or future.exception())
+
+
+import sys
+def trace(*argv):
+    print(*argv, file=sys.stderr, flush=True)
```

and the following test progam

```py
#!/usr/bin/env python

import logging
logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(levelname)s - %(message)s')

import ZEO
print('AAA')
zcli = ZEO.client('/path/to/zeo.sock')
print('BBB')
```

the output is like this:

```
(py3.venv) kirr@deca:~/src/wendelin/z/ZEO$ ../ZEO5/x.py 2>&1 
AAA
2023-03-14 07:21:01,569 - INFO - /path/to/zeo.sock ClientStorage (pid=49949) created RW/normal for storage: '1'
2023-03-14 07:21:01,569 - INFO - created temporary cache file 3
2023-03-14 07:21:01,570 - DEBUG - Using selector: EpollSelector
>>> setup_delegation
2023-03-14 07:21:01,570 - DEBUG - disconnected <ZEO.asyncio.client.ClientIO object at 0x7f03c50077c0> None
2023-03-14 07:21:01,570 - DEBUG - try_connecting <ZEO.asyncio.client.ClientIO object at 0x7f03c50077c0>
connect
  File "/usr/lib/python3.9/threading.py", line 912, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.9/threading.py", line 954, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.9/threading.py", line 892, in run
    self._target(*self._args, **self._kwargs)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 1045, in run_io_thread
    self.setup_delegation(loop)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 861, in setup_delegation
    self.client = client = ClientIO(loop, *self.__args, **self.__kwargs)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 477, in __init__
    self.disconnected(None)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 537, in disconnected
    self.try_connecting()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 549, in try_connecting
    self.protocols = [
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 550, in <listcomp>
    Protocol(self.loop, addr, self,
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 93, in __init__
    self.connect()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 149, in connect
    import traceback as tb; tb.print_stack()

coro connect
  File "/usr/lib/python3.9/threading.py", line 912, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.9/threading.py", line 954, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.9/threading.py", line 892, in run
    self._target(*self._args, **self._kwargs)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 1045, in run_io_thread
    self.setup_delegation(loop)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 861, in setup_delegation
    self.client = client = ClientIO(loop, *self.__args, **self.__kwargs)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 477, in __init__
    self.disconnected(None)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 537, in disconnected
    self.try_connecting()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 549, in try_connecting
    self.protocols = [
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 550, in <listcomp>
    Protocol(self.loop, addr, self,
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 93, in __init__
    self.connect()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 178, in connect
    self._connecting = Task(connect(), self.loop)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/futures.py", line 390, in __init__
    self.executor.step()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/futures.py", line 271, in step
    result = self.coro.send(await_result)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 163, in connect
    import traceback as tb; tb.print_stack()
<<< setup_delegation


>>> loop.run_forever
...
```

which shows that `connect` coroutine indeed starts to be executing immediately by `self._connecting = Task(connect(), self.loop)` because that Task is our task with immediate callback invocations. In other words here we try to run asyncio code outside of a running loop and that's why it breaks.

The fix should be something like this:

```diff
diff --git a/src/ZEO/asyncio/client.py b/src/ZEO/asyncio/client.py
index 34e85cf9..768b04ee 100644
--- a/src/ZEO/asyncio/client.py
+++ b/src/ZEO/asyncio/client.py
@@ -1041,10 +1041,13 @@ def run_io_thread(self):
         try:
             loop = self.loop if self.loop is not None else new_event_loop()
             asyncio.set_event_loop(loop)
-            trace('>>> setup_delegation')
-            self.setup_delegation(loop)
-            trace('<<< setup_delegation')
-            loop.call_soon(self.started.set)
+            # setup_delegation triggers to execute coroutines - we need to call it from under running loop
+            def _():
+                trace('>>> setup_delegation')
+                self.setup_delegation(loop)
+                trace('<<< setup_delegation')
+                self.started.set()
+            loop.call_soon(_)
             import time; time.sleep(3)
             trace('>>> loop.run_forever')
             loop_run_forever(loop)
```

which is similar in style to d27a2cd1.

@d-maurer, if you agree with my analysis I will try to do a proper patch later, hopefully today.

For the reference: we do not have this problem on master, because there we changed `._connecting` to be native asyncio task instead of our own in 63429391 + e3b8658d, and that has the side effect of not running connect coroutine immediately and instead scheduling it to be run when the loop is run. Still I would consider to apply my fix to master as well because it is potentially safer to do async-related activity from under already setup running loop.

Hope that helps a bit,
Kirill
Thank your @navytux for you investigation. Indeed the master branch seems to not have this issue, and your patch fixes it on 5.4.0.
Thanks, @azmeuk. I followed-up with https://github.com/zopefoundation/ZEO/pull/227.
Éloi Rivard wrote at 2023-3-10 00:42 -0800:
>In my development environment, I use a script to run a zeo server and a flask application configured as a zeo client. The connection between the client and the server is done with a unix socket.
>Depending on the runs, the server may or may not be ready before the client is. With ZEO 5.4.0 , when the client is ready first, it prints the following error message, and does not retry:
>
>```
>2023-03-10 09:34:34,836:INFO:ZEO.asyncio.client:Connection to '/path/to/zeo.sock' failed, [Errno 2] No such file or directory
>```
>
>Until ZEO 5.3.0 the client would have tried several times until the connection succeeds, which was very convenient in such situations.
>
>I suggest implementing a timeout or a try again mechanism for client connection. What do you think?

This functionality should still be there.

The code is in `ZEO.asycio.client.Protocol.connect` and
reads:
```python
	...
	cr = lambda: self.loop.create_unix_connection(...)
	...
	@coroutine
        def connect():
            while not self.closed:
                try:
                    yield cr()
                    return
                except asyncio.CancelledError:
                    logger.info("Connection to %r cancelled", self.addr)
                    raise
                except Exception as exc:
                    logger.info("Connection to %r failed, %s",
                                self.addr, exc)
                yield asyncio.sleep(self.connect_poll + local_random.random())
                logger.info("retry connecting %r", self.addr)
        self._connecting = Task(connect(), self.loop)
```

This means: if `create_unix_connection` raises an exception
different from `CancelledError`, then `Connection failed` is
logged, then the coroutine waits between 1 (`== self.connect_poll`)
and 2 seconds, then logs `retry connecting` and tries `create_unix_connection`
again.

You might try debugging the code above to find out why
you do not see the reconnection trial.

If it really does not work, you might contact @navytux.
Likely, it would mean that the `asyncio.sleep` does not finish
or the coroutine execution has a problem.
@navitux implemented the `coroutine` executor (behind the `Task`).



Thank you for your answer. The error seems to be around `yield asyncio.sleep`, as the *retry connecting* message is never shown.

Actually, if I wait long enough, I get this error message:

```python
2023-03-10 15:24:55,758:INFO:ZEO.ClientStorage:/path/to/zeo.sock ClientStorage (pid=156361) created RW/normal for storage: '1'
2023-03-10 15:24:55,765:INFO:ZEO.cache:created temporary cache file 4
2023-03-10 15:24:55,769:INFO:ZEO.asyncio.client:Connection to '/path/to/zeo.sock' failed, [Errno 2] No such file or directory
Traceback (most recent call last):
  File "/path/to/bin/flask", line 8, in <module>
    sys.exit(main())
  File "/path/to/flask/cli.py", line 1050, in main
    cli.main()
  File "/path/to/click/core.py", line 1055, in main
    rv = self.invoke(ctx)
  File "/path/to/click/core.py", line 1657, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "/path/to/click/core.py", line 1404, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/path/to/click/core.py", line 760, in invoke
    return __callback(*args, **kwargs)
  File "/path/to/click/decorators.py", line 84, in new_func
    return ctx.invoke(f, obj, *args, **kwargs)
  File "/path/to/click/core.py", line 760, in invoke
    return __callback(*args, **kwargs)
  File "/path/to/flask/cli.py", line 911, in run_command
    raise e from None
  File "/path/to/flask/cli.py", line 897, in run_command
    app = info.load_app()
  File "/path/to/flask/cli.py", line 308, in load_app
    app = locate_app(import_name, name)
  File "/path/to/flask/cli.py", line 235, in locate_app
    return find_best_app(module)
  File "/path/to/flask/cli.py", line 63, in find_best_app
    app = app_factory()
  File "/path/to/web/__init__.py", line 215, in create_app
    setup_database(app)
  File "/path/to/web/__init__.py", line 197, in setup_database
    sheraf.Database.get_or_create(uri=app.config["DB_URI"])
  File "/path/to/sheraf/databases.py", line 372, in get_or_create
    return Database(**kwargs)
  File "/path/to/sheraf/databases.py", line 118, in __init__
    self.reset(storage, uri)
  File "/path/to/sheraf/databases.py", line 152, in reset
    self.storage = storage_factory()
  File "/path/to/zodburi/resolvers.py", line 160, in factory
    return ClientStorage(*args, **kw)
  File "/path/to/ZEO/ClientStorage.py", line 353, in __init__
    self._wait()
  File "/path/to/ZEO/asyncio/client.py", line 1001, in wait
    return self.io_call(
  File "/path/to/ZEO/asyncio/client.py", line 868, in io_call
    return future.result() if wait else future
  File "/path/to/ZEO/asyncio/futures.py", line 224, in result
    return Future.result(self)
  File "/path/to/ZEO/asyncio/futures.py", line 75, in result
    raise self._result
  File "/path/to/ZEO/asyncio/futures.py", line 267, in step
    result = self.coro.throw(await_result)
  File "/path/to/ZEO/asyncio/client.py", line 706, in await_operational_co
    raise ClientDisconnected("timed out waiting for connection")
ZEO.Exceptions.ClientDisconnected: timed out waiting for connection
2023-03-10 15:34:55,902:ERROR:asyncio:AsyncTask exception was never retrieved
future: <ZEO.asyncio.futures.AsyncTask object at 0x7f777695ea40>
Traceback (most recent call last):
  File "/path/to/ZEO/asyncio/futures.py", line 267, in step
    result = self.coro.throw(await_result)
  File "/path/to/ZEO/asyncio/client.py", line 170, in connect
    yield asyncio.sleep(sleep_n)
  File "/path/to/ZEO/asyncio/futures.py", line 253, in step
    await_result = awaiting.result()
  File "/path/to/ZEO/asyncio/futures.py", line 75, in result
    raise self._result
  File "/path/to/ZEO/asyncio/futures.py", line 265, in step
    result = self.coro.send(await_result)
  File "/usr/lib/python3.10/asyncio/tasks.py", line 599, in sleep
    loop = events.get_running_loop()
RuntimeError: no running event loop
make: *** [Makefile:15: run-web] Error 1
```
Installing the `uvloop` package solves the situation.
Éloi Rivard wrote at 2023-3-10 07:30 -0800:
> ...
>Thank you for your answer. The error seems to be around `yield asyncio.sleep`, as the *retry connecting* message is never shown.

You might want to learn how long the sleep should be.
Usually, it would be between 1 and 2 seconds.
>
>Actually, if I wait long enough, I get this error message:
>
>```python
> ...
>  File "/path/to/ZEO/asyncio/client.py", line 706, in await_operational_co
>    raise ClientDisconnected("timed out waiting for connection")
>ZEO.Exceptions.ClientDisconnected: timed out waiting for connection
>2023-03-10 15:34:55,902:ERROR:asyncio:AsyncTask exception was never retrieved

This is the normal 30 s connection timeout.
The `sleep` time should be significantly shorter.

>future: <ZEO.asyncio.futures.AsyncTask object at 0x7f777695ea40>
>Traceback (most recent call last):
> ...
>    loop = events.get_running_loop()
>RuntimeError: no running event loop

Once the connection timeout occurred, the client is closed.
Part of this process is cancelling the connection process
and shutting down the loop.
Apparently, the loop is shut down before the cancelation is finished.
This causes the observed exception.

I agree with you that something does not work as expected with
the `sleep`.
At your place, I would try to find out how long the sleep should be
(e.g. by modifying the code and logging the sleep time).
If the sleep takes significantly longer that this time,
I would contact @navytux.
If the sleep time is much higher than the expected 1 to 2 seconds,
something went wrong with the parameter passing or the
`local_random` behaves strangely.

Éloi Rivard wrote at 2023-3-10 07:39 -0800:
>Installing the `uvloop` package solves the situation.

`uvloop` causes different timeing behavior. Therefore,
your observations may be different.
However, there should be no significant difference
regarding the `sleep`.
Therefore, I expect that the problem you have observed earlier
still exists, and just happens to not yet be observed.

> At your place, I would try to find out how long the sleep should be (e.g. by modifying the code and logging the sleep time). If the sleep takes significantly longer that this time, I would contact @navytux.

Logging tells me that the value passed to sleep is as expected between 1 and 2. However the sleep appears to happen 30 seconds (or `wait_timeout` seconds if it is set), and then the `ClientDisconnected` exception is raised.
Forcing the sleep value to 1 or 2 seconds does not change the behavior.

The `uvloop` installation is just a workaround I use for the moment, but I though it worth mentioning it :)
> However the sleep appears to happen 30 seconds (or `wait_timeout` seconds if it is set), and then the `ClientDisconnected` exception is raised.

This means that the `sleep` does not work.

@navytux Potentially, `sleep` uses a task feature not supported by our special `Task` implementation; or the coroutine executor does something wrong with the `Future` used by `sleep`. Would you analyze the problem?

@azmeuk Would you tell us which Python version you are using?
Yup. Python 3.10.9
@azmeuk 
I have tried to reproduce the problem with the following (simplified) script
```python
from _thread import start_new_thread
from time import time, sleep
from ZEO.asyncio.client import Task, coroutine, asyncio

@coroutine
def test_sleep():
  global F
  F = asyncio.Future()
  try: yield F
  except Exception: print("Exception")
  s = time()
  yield asyncio.sleep(1)
  print(time() - s)

def t():
  global loop
  loop = asyncio.new_event_loop()
  asyncio.set_event_loop(loop)
  loop.run_forever()

start_new_thread(t, ())
sleep(0.1)

def create_task():
  global T
  T = Task(test_sleep())

loop.call_soon_threadsafe(create_task)
sleep(0.1)
loop.call_soon_threadsafe(F.set_exception, ValueError())
sleep(2)
```
It emulates the `connect` coroutine by coroutine `test_sleep`. The failing connection establishment is emulated by a future which gets an exception set.
I could not observe a `sleep` failure (with Python 3.10.3).

Would you run the script in your environment (without `uvloop`)?
If `sleep` has a problem, the last output is `Exception`; otherwise, additional output (a number near 1) follows.

The following even simpler script emulates the situation more faithfully:
```python
from _thread import start_new_thread
from time import time, sleep
from ZEO.asyncio.client import Task, coroutine, asyncio

@coroutine
def test_sleep():
  try: yield loop.create_unix_connection(asyncio.Protocol, "u.sock")
  except Exception as e: print(e.__class__, e)
  s = time()
  yield asyncio.sleep(1)
  print(time() - s)

def t():
  global loop
  loop = asyncio.new_event_loop()
  asyncio.set_event_loop(loop)
  loop.run_forever()

start_new_thread(t, ())
sleep(0.1)

def create_task():
  global T
  T = Task(test_sleep())

loop.call_soon_threadsafe(create_task)
sleep(2)
```

In my env, I cannot see a `sleep` problem: the script ends with the output of a number near 1.
Here are the output of your scripts:

```
Exception
1.0012478828430176
```

```
<class 'FileNotFoundError'> [Errno 2] No such file or directory
1.0012452602386475
```

In both cases, nothing hangs, and the script execution is quick.
Éloi Rivard wrote at 2023-3-13 02:40 -0700:
> ...
>In both cases, nothing hangs, and the script execution is quick.

I have looked at the `sleep` implementation.
It is essentially a `loop.call_later` where the callback
sets the future's result and thereby terminates the sleeping.

The connection timeout uses a similar approach, based, too, on
`loop.call_later`. You have observed that this timeout works.
Therefore, it is extremely strange that `sleep` has problems.

Hello @azmeuk, thanks for reporting.
Hello @d-maurer, thanks for your help and for pinging me.

I've looked at this problem a bit this morning. Here is why it happens:

The `connect` coroutine starts to be executed before `loop.run_forever` is called. That's why `asyncio.sleep()` raises "no running event loop". here is how that happens:

with the following debug patch:

```diff
--- a/src/ZEO/asyncio/client.py
+++ b/src/ZEO/asyncio/client.py
@@ -145,6 +145,9 @@ def pop_futures(self):
         return futures
 
     def connect(self):
+        trace('connect')
+        import traceback as tb; tb.print_stack()
+        trace()
         if isinstance(self.addr, tuple):
             host, port = self.addr
             cr = lambda: self.loop.create_connection(  # noqa: E731
@@ -156,6 +159,9 @@ def connect(self):
 
         @coroutine
         def connect():
+            trace('coro connect')
+            import traceback as tb; tb.print_stack()
+            trace('running loop:', asyncio.events.get_running_loop())
             while not self.closed:
                 try:
                     yield cr()
@@ -1035,9 +1041,14 @@ def run_io_thread(self):
         try:
             loop = self.loop if self.loop is not None else new_event_loop()
             asyncio.set_event_loop(loop)
+            trace('>>> setup_delegation')
             self.setup_delegation(loop)
+            trace('<<< setup_delegation')
             loop.call_soon(self.started.set)
+            import time; time.sleep(3)
+            trace('>>> loop.run_forever')
             loop_run_forever(loop)
+            trace('<<< loop.run_forever')
         except Exception as exc:
             logger.exception("Client thread")
             self.exception = exc
@@ -1088,3 +1099,8 @@ def cancel_task(task):
     if sys.version_info < (3,9):
         task.add_done_callback(
             lambda future: future.cancelled() or future.exception())
+
+
+import sys
+def trace(*argv):
+    print(*argv, file=sys.stderr, flush=True)
```

and the following test progam

```py
#!/usr/bin/env python

import logging
logging.basicConfig(level=logging.DEBUG, format='%(asctime)s - %(levelname)s - %(message)s')

import ZEO
print('AAA')
zcli = ZEO.client('/path/to/zeo.sock')
print('BBB')
```

the output is like this:

```
(py3.venv) kirr@deca:~/src/wendelin/z/ZEO$ ../ZEO5/x.py 2>&1 
AAA
2023-03-14 07:21:01,569 - INFO - /path/to/zeo.sock ClientStorage (pid=49949) created RW/normal for storage: '1'
2023-03-14 07:21:01,569 - INFO - created temporary cache file 3
2023-03-14 07:21:01,570 - DEBUG - Using selector: EpollSelector
>>> setup_delegation
2023-03-14 07:21:01,570 - DEBUG - disconnected <ZEO.asyncio.client.ClientIO object at 0x7f03c50077c0> None
2023-03-14 07:21:01,570 - DEBUG - try_connecting <ZEO.asyncio.client.ClientIO object at 0x7f03c50077c0>
connect
  File "/usr/lib/python3.9/threading.py", line 912, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.9/threading.py", line 954, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.9/threading.py", line 892, in run
    self._target(*self._args, **self._kwargs)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 1045, in run_io_thread
    self.setup_delegation(loop)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 861, in setup_delegation
    self.client = client = ClientIO(loop, *self.__args, **self.__kwargs)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 477, in __init__
    self.disconnected(None)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 537, in disconnected
    self.try_connecting()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 549, in try_connecting
    self.protocols = [
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 550, in <listcomp>
    Protocol(self.loop, addr, self,
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 93, in __init__
    self.connect()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 149, in connect
    import traceback as tb; tb.print_stack()

coro connect
  File "/usr/lib/python3.9/threading.py", line 912, in _bootstrap
    self._bootstrap_inner()
  File "/usr/lib/python3.9/threading.py", line 954, in _bootstrap_inner
    self.run()
  File "/usr/lib/python3.9/threading.py", line 892, in run
    self._target(*self._args, **self._kwargs)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 1045, in run_io_thread
    self.setup_delegation(loop)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 861, in setup_delegation
    self.client = client = ClientIO(loop, *self.__args, **self.__kwargs)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 477, in __init__
    self.disconnected(None)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 537, in disconnected
    self.try_connecting()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 549, in try_connecting
    self.protocols = [
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 550, in <listcomp>
    Protocol(self.loop, addr, self,
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 93, in __init__
    self.connect()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 178, in connect
    self._connecting = Task(connect(), self.loop)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/futures.py", line 390, in __init__
    self.executor.step()
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/futures.py", line 271, in step
    result = self.coro.send(await_result)
  File "/home/kirr/src/wendelin/z/ZEO/src/ZEO/asyncio/client.py", line 163, in connect
    import traceback as tb; tb.print_stack()
<<< setup_delegation


>>> loop.run_forever
...
```

which shows that `connect` coroutine indeed starts to be executing immediately by `self._connecting = Task(connect(), self.loop)` because that Task is our task with immediate callback invocations. In other words here we try to run asyncio code outside of a running loop and that's why it breaks.

The fix should be something like this:

```diff
diff --git a/src/ZEO/asyncio/client.py b/src/ZEO/asyncio/client.py
index 34e85cf9..768b04ee 100644
--- a/src/ZEO/asyncio/client.py
+++ b/src/ZEO/asyncio/client.py
@@ -1041,10 +1041,13 @@ def run_io_thread(self):
         try:
             loop = self.loop if self.loop is not None else new_event_loop()
             asyncio.set_event_loop(loop)
-            trace('>>> setup_delegation')
-            self.setup_delegation(loop)
-            trace('<<< setup_delegation')
-            loop.call_soon(self.started.set)
+            # setup_delegation triggers to execute coroutines - we need to call it from under running loop
+            def _():
+                trace('>>> setup_delegation')
+                self.setup_delegation(loop)
+                trace('<<< setup_delegation')
+                self.started.set()
+            loop.call_soon(_)
             import time; time.sleep(3)
             trace('>>> loop.run_forever')
             loop_run_forever(loop)
```

which is similar in style to d27a2cd1.

@d-maurer, if you agree with my analysis I will try to do a proper patch later, hopefully today.

For the reference: we do not have this problem on master, because there we changed `._connecting` to be native asyncio task instead of our own in 63429391 + e3b8658d, and that has the side effect of not running connect coroutine immediately and instead scheduling it to be run when the loop is run. Still I would consider to apply my fix to master as well because it is potentially safer to do async-related activity from under already setup running loop.

Hope that helps a bit,
Kirill
Thank your @navytux for you investigation. Indeed the master branch seems to not have this issue, and your patch fixes it on 5.4.0.
Thanks, @azmeuk. I followed-up with https://github.com/zopefoundation/ZEO/pull/227.

Fix patch:
diff --git a/CHANGES.rst b/CHANGES.rst
index ed167197..9429b8b6 100644
--- a/CHANGES.rst
+++ b/CHANGES.rst
@@ -4,6 +4,13 @@ Changelog
 5.4.1 (unreleased)
 ------------------
 
+- Fix `#226 <https://github.com/zopefoundation/ZEO/issues/226>`_
+  using an ``asyncio.Task`` (rather than a proprietary,
+  specially ZEO optimized task) for the connection process.
+  This is advisable because the connection process is not
+  implemented by ZEO but by foreign code which may
+  have problems with the limitations of ZEO tasks.
+
 
 5.4.0 (2023-01-18)
 ------------------
diff --git a/src/ZEO/asyncio/client.py b/src/ZEO/asyncio/client.py
index 0a90160d..a5689458 100644
--- a/src/ZEO/asyncio/client.py
+++ b/src/ZEO/asyncio/client.py
@@ -42,6 +42,11 @@
 from .futures import Future, AsyncTask as Task, \
      coroutine, return_, run_coroutine_threadsafe, switch_thread
 
+if sys.version_info[0] == 2:
+    from .connectco_2 import connect_coroutine
+else:
+    from .connectco_3 import connect_coroutine
+
 logger = logging.getLogger(__name__)
 
 Fallback = object()
@@ -154,22 +159,12 @@ def connect(self):
             cr = lambda: self.loop.create_unix_connection(  # noqa: E731
                 self.protocol_factory, self.addr, ssl=self.ssl)
 
-        @coroutine
-        def connect():
-            while not self.closed:
-                try:
-                    yield cr()
-                    return
-                except asyncio.CancelledError:
-                    logger.info("Connection to %r cancelled", self.addr)
-                    raise
-                except Exception as exc:
-                    logger.info("Connection to %r failed, %s",
-                                self.addr, exc)
-                yield asyncio.sleep(self.connect_poll + local_random.random())
-                logger.info("retry connecting %r", self.addr)
-
-        self._connecting = Task(connect(), self.loop)
+        # Usually, we use our optimized but feature limited tasks
+        # to run coroutines. Here we use a standard task
+        # because we do not know which task features the connect
+        # coroutine needs.
+        self._connecting = self.loop.create_task(
+            connect_coroutine(cr, self, logger, local_random.random))
 
     def connection_made(self, transport):
         logger.debug('connection_made %s', self)
diff --git a/src/ZEO/asyncio/connectco_2.py b/src/ZEO/asyncio/connectco_2.py
new file mode 100644
index 00000000..01d1f04e
--- /dev/null
+++ b/src/ZEO/asyncio/connectco_2.py
@@ -0,0 +1,19 @@
+"""Python 2 implementation for ``connect_coroutine``."""
+
+from .compat import asyncio
+
+@asyncio.coroutine
+def connect_coroutine(cr, self, logger, random):
+    while not self.closed:
+        try:
+            yield cr()
+            return
+        except asyncio.CancelledError:
+            logger.info("Connection to %r cancelled", self.addr)
+            raise
+        except Exception as exc:
+            logger.info("Connection to %r failed, %s",
+                        self.addr, exc)
+        yield asyncio.sleep(self.connect_poll + random())
+        logger.info("retry connecting %r", self.addr)
+
diff --git a/src/ZEO/asyncio/connectco_3.py b/src/ZEO/asyncio/connectco_3.py
new file mode 100644
index 00000000..7c9273dd
--- /dev/null
+++ b/src/ZEO/asyncio/connectco_3.py
@@ -0,0 +1,17 @@
+"""Python 3 implementation for ``connect_coroutine``."""
+
+from .compat import asyncio
+
+async def connect_coroutine(cr, self, logger, random):
+    while not self.closed:
+        try:
+            return await cr()
+        except asyncio.CancelledError:
+            logger.info("Connection to %r cancelled", self.addr)
+            raise
+        except Exception as exc:
+            logger.info("Connection to %r failed, %s",
+                        self.addr, exc)
+        await asyncio.sleep(self.connect_poll + random())
+        logger.info("retry connecting %r", self.addr)
+


Test patch:
diff --git a/src/ZEO/asyncio/tests.py b/src/ZEO/asyncio/tests.py
index c09fce76..b100f5cf 100644
--- a/src/ZEO/asyncio/tests.py
+++ b/src/ZEO/asyncio/tests.py
@@ -153,8 +153,10 @@ def start(self,
         cache = MemoryCache()
         # We can also provide an event loop.  We'll use a testing loop
         # so we don't have to actually make any network connection.
-        self.loop = loop = FaithfulLoop(
-            addrs if loop_addrs is None else loop_addrs)
+        if self.loop is None:
+            self.loop = FaithfulLoop(
+                addrs if loop_addrs is None else loop_addrs)
+        loop = self.loop
         ClientThread.__init__(self,
                               addrs, wrapper, cache, 'TEST',
                               read_only, timeout=1)
@@ -505,6 +507,21 @@ def test_cache_way_behind(self):
         self.assertFalse(cache)
         wrapper.invalidateCache.assert_called_with()
 
+    def test_reconnect_trial(self):
+        """test for "https://github.com/zopefoundation/ZEO/issues/226"."""
+        # we use a unix connection (to be in line with #226)
+        addrs = ["__nonexisting_unix_socket__"]
+        loop = self.loop = FaithfulLoop(addrs)
+        # we override the loop's ``create_unix_connection`` to let it
+        # fail immediately
+        loop.create_unix_connection = lambda *args: 1/0
+        wrapper, cache, loop, client, protocol, transport = self.start(
+            addrs, ())
+
+        # The failed connection is attempted in the future:
+        delay, func, args, handle = loop.later.pop(0)
+        self.assertTrue(1 <= delay <= 2)
+
     def test_multiple_addresses(self):
         # We can pass multiple addresses to client constructor
         addrs = [('1.2.3.4', 8200), ('2.2.3.4', 8200)]