Coroutine never yielded from even though it's wrapped in a task AND is actually called

[Florian Rüchel]

Hi everyone,

I currently have a problem I cannot figure out. My code is running perfectly fine, but when using "PYTHONASYNCIODEBUG=1" it reports that a function was never yielded from per instance of that class I have. The problem is I cannot create an example that replicates the issue and the application is fairly large so maybe someone can give a hint on where I might go looking. The function in question is a method of a connection class. The class manages a TCP connection that has to send an init and a disconnect request. It is the disconnect method that is reported as never yielded from. I have log entries that prove that this function was actually run and I have tried wrapping it in asyncio.Task and asyncio.async and I also had a wrapping coroutine that was called and an explicit "yield from connection.disconnect()" statement.

In all three cases the proper log entries were written and the server got the disconnect request, so I know it was properly executed. Now I am wondering if I have a bug in my application that is hidden somewhere between the layers that is repsonsible for this message. Or is it possible to trigger this error message even though the function was properly called?

I'd also like to note that this is the only method where this happens, all other methods on all other classes are never reported as problematic.I have checked the method against others but I cannot find any difference at all: They are called with yield from or as tasks, they all use other coroutines (the connect and disconnect method actually both use yield from self.talk(...)) and they are all properly decorated.

I'm sorry I cannot provide any code examples, but since I am unable to replicate the issue in a small sample, I fear I need further guidance on where to look for the issue.

Many thanks in advance and Regards,

Florian

[Guido van Rossum]

To be sure, the error message is 'Coroutine %r defined at %s:%s was never yielded from' right? This comes from asyncio/tasks.py and the most likely cause is that somewhere you write

    foo()

instead of

    yield from foo()

It's really unfortunate that you can't post your code, because I'm sure that one look at it (or a few looks ;-) would tell me what's going on. Can you at least post the traceback? Which exact Python and asyncio version are you using? Is it happening at the end of the program or while the loop is still running?

--
--Guido van Rossum (python.org/~guido)

[Florian Rüchel]

I can post the code, I just thought it might be too much. However, I'll just post the relevant section. Contrary to multithreaded programming here most of the times the local section is enough (I love asyncio :))

Anyways here is the main function:

try:

    self.event_loop.run_forever()

except KeyboardInterrupt:

    exit_main_loop()

finally:

    print("Running shutdown cleanup")

    collector.cancel()

    @asyncio.coroutine

    def shutdown():

        yield from self.connection_pool.close()

    self.event_loop.run_until_complete(shutdown())

    self.event_loop.close()

And the close method:

@asyncio.coroutine

def close(self):

    try:

        if self.returned_connections:

            msg = ("Not all connections were returned: %s"

                   % self.returned_connections)

            log.error(msg)

            raise ValueError(msg)

    finally:

        conn_tasks = [asyncio.Task(conn.disconnect())

                      for conn in self.all_connections]

        done, pending = yield from asyncio.wait(conn_tasks, timeout=5)

        assert not pending

Relevant is the finally part: I wrap each connection in a task and wait for them together. Removing the timeout did not help (I didn't expect it would, no exception is raised).

Per existing connection (up to 10) a message is produced:

2014-03-27 23:11:58,143 ERROR[asyncio] Coroutine 'disconnect' defined at /path/to/library/connection.py:109 was never yielded from

I have made sure that the amount of logging messages matches exactly the number of connections created (by counting the logging messages inside connection's __init__ function). In a very simple case there was only one connection, so only one error entry and only one log entry for a created connection.

Hope this additional information helps uncover the issue. Thanks for the response.

[Guido van Rossum]

Looks to me like you're never asking for the result of those Futures you're passing to asyncio.wait(). It waits until the Futures are complete, but it doesn't inspect whether they have errors. You need something like

for task in done:

    if task.exception(): ...log it...

[Florian Rüchel]

I modified the code a little, so I make sure it is done and has no exception:

def done(fut):

    print("Future is done")

for task in conn_tasks:

    task.add_done_callback(done)

done, pending = yield from asyncio.wait(conn_tasks, timeout=5)

assert not pending

for task in done:

    assert task.exception() is None

    assert task.result() is None

This executes cleanly, without throwing an exception and prints "Future is done" for each connection.

[Guido van Rossum]

So does this solve your problem or not? You didn't say...

[Florian Rüchel]

Oh sorry... No it didn't solve my problem. The assertions all pass and the error messages remain. I also added logging as you recommended, but it only shows that the exception is None.

[Guido van Rossum]

Try calling fut.exception() inside the done() callback.

[Florian Rüchel]

I tried it and it yields the same result: The assertion passes, the exception is None and the error is still being logged.

def done(fut):

    print("Done")

    assert fut.exception() is None

The "Done" part is printed as before.

[Guido van Rossum]

I'm out of ideas, sorry. Perhaps the code in the __del__ method is wrong and the generator can be in the state that triggers the error message after it has run. Perhaps one of your asserts triggers but it itself is silenced by a similar issue. (Hm, I would definitely check that hypothesis -- use an explicit print or logging call on the condition the assert checks, especially the "assert not pending" one.)

[Florian Rüchel]

Thank you! It was never the code I posted, but some very old leftover __del__ method. This way "disonnect" would be called twice and the second (implict, __del__) one caused the error message. After deleting the __del__ part entirely everything works like a charm. Damn implicit code :)

Thank you very much for your help, it would have taken me ages to consider the __del__ method.

[Guido van Rossum]

Heh, I meant a different __del__ method,  but glad you found it!