python - Async exception handling works when using ensure_future but not when using run_until_complete

Question

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.

标签： pythonloggingpython-asyncio

Answer 1

AioLogger是一个依赖事件循环运行的异步日志框架。当您从 引发时ensure_future，您的事件循环仍在运行，直到您按下Ctrl+C，这就是您看到日志的原因。另一方面，当你使用 时run_until_complete(main())，在 raises 之后什么都不会运行事件循环run_until_complete，因此调度的日志消息excepthook将被丢弃。

要解决此问题，您可以asyncio.sleep(0.001)在记录器调用后运行类似的操作，excepthook以确保日志消息通过：

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))

一般来说，asyncio 异常处理程序是作为最后的错误报告，而不是你的业务逻辑应该依赖的东西。当您调用run_until_complete()时，没有理由将异常传递给 asyncio 异常处理程序，因为异常会传播给 的调用者run_until_complete()，后者可以按通常的方式处理它。（在您的情况下sys.excepthook被调用是因为错误传播到顶层。）当您调用时ensure_future，您将获得一个Future实例（或其Task子类的实例），您可以调用或await调用result()或exception()获取异常。如果你什么都不做，只是让未来被 GC 销毁，它会将异常传递给 asyncio 处理程序以记录它。