如果启用文件日志记录,协程中的异常不会显示

Exception in coroutine not shown if enable file logging

我将我的问题最小化为下一个:

logger.conf:

###################################
[loggers]
keys=root
[logger_root]
level=DEBUG
handlers=handlerScreen,handlerFile

###################################
[handlers]
keys=handlerScreen,handlerFile
[handler_handlerScreen]
class=StreamHandler
level=DEBUG
formatter=formScreen
args=(sys.stderr,)
[handler_handlerFile]
class=FileHandler
level=INFO
formatter=formFile
args=('%(log_file)s', 'a')

###################################
[formatters]
keys=formScreen,formFile
[formatter_formScreen]
format=%(asctime)s %(message)s
datefmt=%Y-%m-%d %H:%M:%S
[formatter_formFile]
format=%(asctime)s %(filename)-21s[line:%(lineno)-3d] %(levelname)s %(message)s
datefmt=%Y-%m-%d %H:%M:%S

fc.py:

import asyncio
import logging.config

logging.config.fileConfig("logger.conf", defaults=dict(log_file="run.log"))

async def fun():
    print("1")
    1/0
    print("2")

async def action():
    asyncio.create_task(fun())
    print("do other tasks at once")
    await asyncio.sleep(5)

asyncio.run(action())

执行:

$ python3 fc.py
do other tasks at once
1

问题:

你可以看到 1/0 没有在屏幕上打印任何错误,但是 2 没有被打印,所以我猜异常已经发生了,只是我在屏幕上看不到任何东西,为什么会这样?

我试过什么?

  1. 禁用文件记录:

    import asyncio
    import logging.config
    
    # Disable file logging
    # logging.config.fileConfig("logger.conf", defaults=dict(log_file="run.log"))
    
    async def fun():
        print("1")
        1/0
        print("2")
    
    async def action():
        asyncio.create_task(fun())
        print("do other tasks at once")
        await asyncio.sleep(5)
    
    asyncio.run(action())
    

    然后 运行 如下:

    $ python3 fc.py
    do other tasks at once
    1
    Task exception was never retrieved
    future: <Task finished name='Task-2' coro=<fun() done, defined at fc.py:6> 
    exception=ZeroDivisionError('division by zero')>
    Traceback (most recent call last):
      File "fc.py", line 9, in fun
        1/0
    ZeroDivisionError: division by zero
    
  2. 添加try...except:

    import asyncio
    import logging.config
    
    logging.config.fileConfig("logger.conf", defaults=dict(log_file="run.log"))
    
    async def fun():
        print("1")
        try:
            1/0
        except Exception as e:
            print(e)
        print("2")
    
    async def action():
        asyncio.create_task(fun())
        print("do other tasks at once")
        await asyncio.sleep(5)
    
    asyncio.run(action())
    

    那么,运行如下:

    $ python3 fc.py
    do other tasks at once
    1
    division by zero
    2
    

那么,如何在不禁用文件日志记录的情况下显示错误,同时又不使用显式 try...catch?如果我能知道为什么会出现这种情况就更好了。

注意:await asyncio.create_task(fun()) 不是我需要的。在我的场景中,我等不及 fun 完成然后执行下一步操作。如果重要的话,我使用 Python 3.8.10

查了asyncio的出处,发现原因:asyncio也用logging打印异常:

asyncio/log.py:

import logging
logger = logging.getLogger(__package__)

asyncio/base_events.py:

def default_exception_handler(self, context):
    """Default exception handler.

    This is called when an exception occurs and no exception
    handler is set, and can be called by a custom exception
    handler that wants to defer to the default behavior.

    ......
    """
    ......
    logger.error('\n'.join(log_lines), exc_info=exc_info)

因此,asyncio 定义了一个名为“asyncio”的记录器 (__package__)。但是,在我的 logger.conf 中,我只是用 keys=root 定义了一个记录器,这就是错误没有显示在屏幕上的原因。

所以,将 logger.conf 更改为 next 可以工作,尽管我不知道如何让 logger.conf 默认处理所有 logger 而无需明确指定它们:

##################################
[loggers]
keys=root,asyncio
[logger_root]
level=DEBUG
handlers=handlerScreen,handlerFile
[logger_asyncio]
level=DEBUG
qualname=asyncio
handlers=handlerScreen,handlerFile