Coroutine sink exceptions are not caught

[gdmoore]

It appears that if you use a coroutine as a sink and it has an unhandled exception, even with catch=True specified in add(), the exception is not caught, and you will get a Task exception was never retrieved error on stderr from asyncio: https://docs.python.org/3/library/asyncio-dev.html#detect-never-retrieved-exceptions

import asyncio
from loguru import logger

async def sink(msg):
  raise Exception("oh no")

async def main():
  logger.add(sink, catch=True)
  logger.info("hello world")

asyncio.run(main())

2020-03-23 12:31:58.236 | INFO | main:main:3 - hello world
Task exception was never retrieved
future: <Task finished name='Task-2' coro=<sink() done, defined at :1> exception=Exception('oh no')>
Traceback (most recent call last):
File "", line 2, in sink
Exception: oh no

[Delgan]

Hey @gdmoore, thanks for the bug report!

The first thing, I think, it that you should await logger.complete() before the end of your main() function to ensure all logging tasks are finished. If you do so, you will see the Exception being effectively raised without the warning message. Which leads to another problem: this exception is not caught, even if caught=True. I need to fix it, probably by wrapping logger.complete() internally.

[gdmoore]

Sorry, made that mistake when minimizing it for the bug report. In my actual app I am awaiting before my app shuts down.

Here's a better example which runs for 5 seconds, doing the same as above, and finishing with a logger.complete():

import asyncio
from loguru import logger

async def sink(msg):
  raise Exception("oh no")

async def main():
  logger.add(sink, catch=True)
  for i in range(0,5):
    logger.info("hello world")
    await asyncio.sleep(1)
  await logger.complete()

asyncio.run(main())

here's the output I get:

2020-03-24 17:41:38.163 | INFO     | __main__:main:4 - hello world
Task exception was never retrieved
future: <Task finished name='Task-2' coro=<sink() done, defined at <stdin>:1> exception=Exception('oh no')>
Traceback (most recent call last):
  File "<stdin>", line 2, in sink
Exception: oh no
2020-03-24 17:41:39.166 | INFO     | __main__:main:4 - hello world
Task exception was never retrieved
future: <Task finished name='Task-3' coro=<sink() done, defined at <stdin>:1> exception=Exception('oh no')>
Traceback (most recent call last):
  File "<stdin>", line 2, in sink
Exception: oh no

... etc, 5 times total.

Each call to my sink which raises an exception never has the exception retrieved, even if the program ultimately finishes with a call to logger.complete().

It seems like the Future returned by the sink coroutine isn't being held onto by loguru when it invokes all of the sinks. Or if it is, doing it in logger.complete() at program termination won't be enough, since in a long-running program you may not hit logger.complete() for a long time.

[Delgan]

Thanks for the update! So it's going to be a little more complicated than I thought... 😬

Loguru manages coroutines similarly to asyncio.ensure_future(). It creates a Task and add it to a weakset. Once the task ends, it's automatically removed from the weakset. However, if an error occurred, the task is removed without the exception being handled, by anyone hence the warning. I'm not sure yet how to fix that, I will probably need to find a way to avoid failed tasks to be removed and keep them in memory until logger.complete() is called.

[gdmoore]

I don't think the approach with logger.complete will work broadly.

If I have a long-running program with a sink that sometimes fails, you'll be storing all the failures in memory for weeks or months, and I won't get any notification that there were failures until the program is shutting down. I think this would be surprising behaviour.

I think logger.complete is really only good for ensuring no in-flight logging tasks get dropped on the floor when exiting, not for this kind of bookkeeping.

I think you need to do something like the following. If anyone passes a coroutine to add(), whenever you invoke their sink, add the Task to a list. In a separate thread, wait on these Tasks to finish, and if they raise, (depending on catch), immediately react by either re-raising in the logger or dumping to stderr. If catch=True you could just dump to stderr immediately in this Task watcher thread.

If catch=False, you would need to have a message pump between the thread checking for Task failures in order to notify the logger that there were failures. I'm not sure when in this case the user could poll to find out an exception happened in a reasonable way. (I'm not very experienced with asyncio, but perhaps someone with more experience can provide guidance?)

[Delgan]

Yes, you are right. I realized later that it was not a good solution to store pending tasks.

However, I'd rather not use a thread to fix this. What about Task.add_done_callback()? If the completed task contains an exception, I could print it to stderr if catch=True and otherwise re-raise it. The error will not be propagated to the main thread as it's raised from within the event loop but I'm not sure there is much I can do about that.

[gdmoore]

A thread is definitely an ugly solution. That looks a lot better.

You're right about propagation. I was kind of thinking of it in terms of the unhandled exception being raised to the call site (eg the person who called logger.info(...) and had the sink fail) but that doesn't make sense.

Printing in the done callback if catch=True sounds right, and re-raising it will allow someone who has registered an exception handler with loop.set_exception_handler() to catch it, which I think is the correct way.

logger.complete() should still exist for blocking until all active sinks are finished.

[Delgan]

Great, so we agree on how this should behave. 👍

I'm a little worried about the callback overhead but I don't see any other simple solution.

[Delgan]

Fixed in next version. :)