每次异步函数调用创建一个新的日志记录器，是个好主意吗？

Question

在编写Python asyncio程序时，通常会有一个异步函数，其中有许多并发运行的调用。我想在这个函数中添加一些日志记录，但来自不同调用的日志输出将交错在一起，使其难以跟踪。 我目前的解决方案是以某种方式为每个调用创建一个唯一的名称，并每次记录该名称，如下所示：

async def make_request(args):
    logger = logging.getLogger('myscript.request')
    log_name = unique_name()
    logger.debug('[%s] making request with args %r', log_name, args)
    response = await request(args)
    logger.debug('[%s] response: %r', log_name, response)

然而，每次记录日志时都必须输入log_name，这很快会让人感到疲劳。为了节省这些击键，我想出了一个不同的解决方案，为每次调用创建一个具有唯一名称的新记录器：

async def make_request(args):
    logger = logging.getLogger(f'myscript.request.{unique_name()}')
    logger.debug('making request with args %r', args)
    response = await request(args)
    logger.debug('response: %r', response)

这种方法有什么缺点吗？我唯一能想到的是创建一个新的日志记录器可能会很昂贵，但实际上情况是否如此？还有其他我没有看到的问题吗？

- twisteroid ambassador

---

根据我的经验，你应该只有一个日志记录器。为了识别哪个任务发送了哪个消息，你需要将这些信息写入日志中。这样，通过查看日志文件中的一行，你就可以看到这条消息是由哪个任务写入的。 - Duck Dodgers

@JoeyMallone 为什么只使用一个记录器？拥有太多记录器的缺点是什么？ - twisteroid ambassador

我说，首先是基于经验。我曾经使用实时系统并行运行数十个任务。任何单个设备上始终只有一个记录器正在运行。我期望那些实施这些系统的人知道他们在做什么。此外，我还看到过在日志文件中记录任务名称的相同方法。但是，抛开我的模拟程序设计方法不谈，我认为，为每个进程提供一个记录器首先是不可扩展的，其次，当每个记录器被分离时，如何记录这些进程的交互？在单个记录器中，更容易看到是谁在什么时候调用了什么。 - Duck Dodgers

使用相同的记录器的一个很大的优点是，您可以配置它一次并重复使用该配置，而不需要每次调用函数时都需要配置新的记录器。 - dirn

使用Python的logging模块，"loggers"和"handlers"之间有一个分离。大多数配置都附加到处理程序上，例如格式化和输出。记录器是分层的，因此如果我将处理程序附加到记录器"myscript.request"，则记录在任何记录器"myscript.request.*"中的消息都将由处理程序处理。因此，在这种情况下，配置实际上并不是一个问题。 - twisteroid ambassador

Answer 1

除了可能创建记录器的代价之外，另一个缺点是您创建的记录器将永远与唯一名称相关联并且永远不会被销毁，因此您实际上拥有内存泄漏。这在文档中明确承诺：

“使用相同名称多次调用 getLogger（）将始终返回对同一 Logger 对象的引用。”

我建议您勇敢地创建具有所需功能的助手。基于 Brad Solomon 的答案，包装器可能如下所示（未经测试）：

import itertools, weakref, logging

logging.basicConfig(format='%(asctime)-15s %(task_name)s %(message)s')

class TaskLogger:
    _next_id = itertools.count().__next__
    _task_ids = weakref.WeakKeyDictionary()

    def __init__(self):
        self._logger = logging.getLogger('myscript.request')

    def _task_name(self):
        task = asyncio.current_task()
        if task not in self._task_ids:
            self._task_ids[task] = self._next_id()
        return f'task-{self._task_ids[task]}'

    def debug(self, *args, **kwargs):
        self._logger.debug(*args, task_name=self._task_name(), **kwargs)

    # the same for info, etc.

logger = TaskLogger()

- user4815162342

---

这是一个很好的观点，虽然我想象垃圾回收会从内存中删除过期的记录器？ - twisteroid ambassador

@twisteroidambassador，这不会发生，这正是我的观点。GC不能收集过期的记录器，因为它无法证明您稍后不会调用getLogger('myscript.request')，并期望（根据文档）获得先前配置的记录器对象。 - user4815162342

Answer 2

不要创建新的记录器，可以考虑利用日志消息中的自定义属性，通过extra参数进行操作：

例如：

FORMAT = '%(asctime)-15s %(unique_name)s %(message)s'
# [Configure/format loggers & handlers]

在协程内部调用记录调试级别的消息，看起来会像这样：

logger.debug('making request with args %r', args, extra={'unique_name': unique_name())

请注意：如果您正在进行大量请求，unique_name()可能会变得很昂贵。在使用多进程创建并发时，一种常见的模式是通过os.getpid()记录调用进程的ID。对于asyncio，也许一个非常粗略的近亲就是当前Task的某个标识符，您可以通过asyncio.current_task()获取到它。每个任务都有一个_name属性，它应该是唯一的，因为它调用了递增的_task_name_counter()函数：

class Task(futures._PyFuture): # Inherit Python Task implementation
    def __init__(self, coro, *, loop=None, name=None):
    # ...
        if name is None:
            self._name = f'Task-{_task_name_counter()}'
        else:
            self._name = str(name)

- Brad Solomon

---

"extra" 很酷，但是有了这样的格式化器，我必须在每个日志调用中传递额外的字典，即使是在有趣的函数之外。文档确实说：“虽然这可能很烦人，但此功能旨在用于特殊情况，例如多线程服务器，在其中相同的代码在许多上下文中执行，并且出现的有趣条件取决于此上下文……在这种情况下，很可能会使用特定的处理程序与专门的格式化程序”，因此此功能基本上是为此案例设计的，但仍然很烦人。 - twisteroid ambassador

@twisteroidambassador，您可以使用 LoggerAdapter 来避免每次传递 extra。在创建适配器实例时，将 extra 值传递给它即可 - https://docs.python.org/3/howto/logging-cookbook.html#adding-contextual-information-to-your-logging-output - Vinay Sajip

Answer 3

我正在寻找从多个异步任务记录日志的相似解决方案。 如上所述，无法确定哪行日志来自哪个任务。

以下是我对此问题的解决方案。 如果有缺点或更好的方法，请让我知道。

import asyncio
import logging

log_format = '%(levelname).1s,%(thread)s,%(name)s,%(lineno)d: %(message)s'
logging.basicConfig(format=log_format, level=logging.NOTSET)
log = logging.getLogger()


class MyStreamHandler(logging.StreamHandler):
    def __init__(self):
        super().__init__()

    def emit(self, record: logging.LogRecord) -> None:
        try:
            task = asyncio.current_task(asyncio.get_running_loop())
            if task is not None:
                record.__setattr__("thread", f"{record.thread}[{task.get_name()}]")
        except RuntimeError:
            pass
        super().emit(record)


handler = MyStreamHandler()
handler.setFormatter(logging.Formatter(log_format))
log.handlers = []
log.addHandler(handler)


def synchronous():
    log.debug("I'm synchronous")


async def asynchronous():
    log.debug("I'm a debug")
    log.warning("I'm a warning")
    log.error("I'm an error")


async def main():
    loop = asyncio.get_event_loop()

    tasks = []
    for i in range(5):
        tasks.append(asynchronous())

    await asyncio.gather(*tasks)

synchronous()
asyncio.run(main())

示例输出：

D,6052,root,30: I'm synchronous
D,6052,asyncio,623: Using proactor: IocpProactor
D,6052[Task-2],root,34: I'm a debug
W,6052[Task-2],root,35: I'm a warning
E,6052[Task-2],root,36: I'm an error
D,6052[Task-3],root,34: I'm a debug
W,6052[Task-3],root,35: I'm a warning
E,6052[Task-3],root,36: I'm an error
D,6052[Task-4],root,34: I'm a debug
W,6052[Task-4],root,35: I'm a warning
E,6052[Task-4],root,36: I'm an error
D,6052[Task-5],root,34: I'm a debug
W,6052[Task-5],root,35: I'm a warning
E,6052[Task-5],root,36: I'm an error
D,6052[Task-6],root,34: I'm a debug
W,6052[Task-6],root,35: I'm a warning
E,6052[Task-6],root,36: I'm an error

- Sinan Cetinkaya

Answer 4

为了给这个旧问题提供一些解决方案，在遵循Vinay Sajip有关LoggerAdapter的评论之后，我实际上在文档中找到了我想要的东西。引用文档中的内容：

If you need a different method, e.g. if you want to prepend or append the contextual information to the message string, you just need to subclass LoggerAdapter and override process() to do what you need. Here is a simple example:

class CustomAdapter(logging.LoggerAdapter):
    """
    This example adapter expects the passed in dict-like object to have a
    'connid' key, whose value in brackets is prepended to the log message.
    """
    def process(self, msg, kwargs):
        return '[%s] %s' % (self.extra['connid'], msg), kwargs

which you can use like this:

logger = logging.getLogger(__name__)
adapter = CustomAdapter(logger, {'connid': some_conn_id})

Then any events that you log to the adapter will have the value of some_conn_id prepended to the log messages.

- twisteroid ambassador