[FIXED] Async exception handling works when using ensure_future but not when using run_until_complete

Issue

I am using aiologger for async logging, and have written two functions to override default exception handlers:

from aiologger import Logger as AioLogger
from aiologger.levels import LogLevel
import asyncio

logger = AioLogger.with_default_handlers(name='test', level=LogLevel.NOTSET,
                                         loop=asyncio.get_event_loop())

def excepthook(exc_type, exc_value, exc_traceback):
    print('excepthook called.')
    if issubclass(exc_type, KeyboardInterrupt):
        sys.__excepthook__(exc_type, exc_value, exc_traceback)
        return
    logger.error(f'Uncaught Exception: {exc_type.__name__}')

def asyncio_exception_handler(loop, context):
    print('asyncio_exception_handler called.')
    exception = context.get('exception', None)
    if exception:
        exc_info = (type(exception), exception, exception.__traceback__)
        if issubclass(exception.__class__, KeyboardInterrupt):
            sys.__excepthook__(*exc_info)
            return
        logger.error(f'Uncaught Exception: {exc_info[0].__name__}')
    else:
        logger.error(context['message'])

Then, I overrode the exception handlers with the ones I have provided:

import sys

sys.excepthook = excepthook
asyncio.get_event_loop().set_exception_handler(asyncio_exception_handler)

Finally, I wrote a simple code to test the functionality:

async def main():
    raise RuntimeError('Uncaught Test')

loop = asyncio.get_event_loop()
asyncio.ensure_future(main())
loop.run_forever()

This works as expected, and the output is:

asyncio_exception_handler called.
Uncaught Exception: RuntimeError
^Cexcepthook called.
Traceback (most recent call last):
  File "examples/sample.py", line 110, in <module>
    loop.run_forever()
  File "/usr/lib/python3.8/asyncio/base_events.py", line 570, in run_forever
    self._run_once()
  File "/usr/lib/python3.8/asyncio/base_events.py", line 1823, in _run_once
    event_list = self._selector.select(timeout)
  File "/usr/lib/python3.8/selectors.py", line 468, in select
    fd_event_list = self._selector.poll(timeout, max_ev)
KeyboardInterrupt

(The process remains open after the exception, and I have to send KeyboardInterrupt to terminate it.)

---

However, if I replace asyncio.ensure_future(main()) with loop.run_until_complete(main()), everything goes crazy and the application exits without any logs:

$ python main.py 
excepthook called.
$

The confusing part is, in this case, my excepthook function is executed instead of asyncio_exception_handler. My perception is that somehow using loop.run_until_complete() will treat the code to be non-async, hence calling logger.error() which creates an async task, has no effects.

---

How can I manage to use my exception handlers to log uncaught exceptions when my code is running with loop.run_until_complete()? What is the difference between the two scenarios I have provided? I am not so good with asyncio, and I may have missed some trivial notes here.

Solution

AioLogger is an async logging framework that depends on the event loop to run. When you raise from ensure_future, your event loop is still running until you press Ctrl+C, which is why you see the log. On the other hand, when you use run_until_complete(main()), nothing will run the event loop after run_until_complete raises, so the log message scheduled by excepthook will be dropped.

To fix the issue, you can run something like asyncio.sleep(0.001) after the logger calls in excepthook to ensure that the log messages go through:

def excepthook(exc_type, exc_value, exc_traceback):
    print('excepthook called.')
    if issubclass(exc_type, KeyboardInterrupt):
        sys.__excepthook__(exc_type, exc_value, exc_traceback)
        return
    logger.error(f'Uncaught Exception: {exc_type.__name__}')
    # sleep a bit to give the log a chance to flush
    loop.run_until_complete(asyncio.sleep(0.001))

In general, the asyncio exception handler is meant as a last-resort error reporting, not something you should rely on for your business logic. When you call run_until_complete(), there is no reason to pass the exception to the asyncio exception handler because the exception is propagated to the caller of run_until_complete(), which can just handle it in the usual way. (In your case sys.excepthook is called because the error propagates to top-level.) When you call ensure_future, you get a Future instance (or instance of its Task subclass) that you can either await or call result() or exception() to get the exception. If you do none of that and just allow the future to get destroyed by GC, it will pass the exception to the asyncio handler to log it.

Answered By - user4815162342