在Python中同时记录线程特定和共享日志文件

Question

我想在一个多线程的Python应用程序中实现每个线程都有自己的日志记录功能，使用Python的logging模块。在主模块（创建线程的地方），我给日志记录器的名字加上了一个独特的ID：

mylogger = logging.getLogger(str(someInt) + __name__)

这个模块使用了多个其他模块，这些模块也支持日志记录，但它们的日志记录器初始化方式是这样的：

mylogger = logging.getLogger(__name__)

由于被调用的类看不到调用者的日志记录器，所以调用者的日志是特定于线程的，而被调用者的日志则会根据路径记录到一个全局文件中。

我们该怎么做才能避免在每个其他模块中都传递str(someInt)，而是让它们保持不变，同时仍然能够记录到特定于线程的文件中呢？

Answer 1

根据我的理解，这实际上是Python日志系统中的一个难题。你可以尝试在每次创建新线程的地方找到解决办法，通过日志处理器和过滤器来调整日志控制。但一旦你的代码调用了某个库或代码，这些库自己也想使用线程，这个解决办法就不管用了，至少在这些库的线程记录消息的地方是这样。

我在这里问了一个相关的问题，详细内容可以查看

如何在Python中让不同线程记录到不同的文件？

我还在上面提到的@Vinay Sajip的博客中评论了这个问题。也就是说，依我所见（我可能错了！），他的解决方案并没有解决这里的根本问题。实际上，除非使用一些高级的技巧，比如调用栈追踪之类的，否则没有什么能真正解决线程和日志结合时的这个基本缺陷。即使是多进程包也无法解决这个问题。每个进程仍然绑定在同一个根日志器上（这在我看来有点奇怪和令人担忧）。

如果能够查询一个线程的父线程，那就能真正解决这个问题，但实际上是做不到的。

Answer 2

一个可能的解决办法是替换掉 getLogger：

import logging
old_getlogger= logging.getLogger
def my_getlogger(name):
    return old_getlogger( (str(someInt) if name==__name__ else "") + name)
logging.getLogger= my_getlogger

不过你需要确保 someInt 的值是正确的，这可能会有点难，具体要看你代码的结构。@Marek 提出的使用线程本地存储的建议可能会对你有帮助。

Answer 3

我不推荐为每个线程使用单独的文件。其实你可以把所有线程的信息都放在一个公共的日志文件里，只需要在格式字符串中加上 thread 或 threadName 就可以了。你想要的功能是可以实现的，方法是使用一个 Filter 的子类，具体的做法可以参考这篇文章，虽然它的情况和你提到的有些不同。

Answer 4

虽然我对我所建议的内容不是很有经验，但我会尝试使用线程局部存储。

线程局部存储

这是一个表示线程局部数据的类。线程局部数据是指每个线程都有自己独特的数据。要管理这些线程局部数据，只需创建一个local（或其子类）的实例，并在上面存储属性。这样，不同的线程就会有不同的值。

你可以通过以下方式保存和访问这些变量：

import threading
mydata = threading.local()
mydata.x = 1

我建议在创建线程特定的日志记录器时，将其保存到线程局部变量中，然后在需要时通过线程局部存储再次访问这个日志记录器。

可以看看这些链接，它们帮助我理解了线程局部存储：

• Python中的线程局部存储
• 什么是Python中的“线程局部存储”，我为什么需要它？

Answer 5

这个可以通过 logging.Filter 来实现，下面是一个例子：

import threading
import logging
import logging.config


class ThreadLogFilter(logging.Filter):
    """
    This filter only show log entries for specified thread name
    """

    def __init__(self, thread_name, *args, **kwargs):
        logging.Filter.__init__(self, *args, **kwargs)
        self.thread_name = thread_name

    def filter(self, record):
        return record.threadName == self.thread_name


def start_thread_logging():
    """
    Add a log handler to separate file for current thread
    """
    thread_name = threading.Thread.getName(threading.current_thread())
    log_file = '/tmp/perThreadLogging-{}.log'.format(thread_name)
    log_handler = logging.FileHandler(log_file)

    log_handler.setLevel(logging.DEBUG)

    formatter = logging.Formatter(
        "%(asctime)-15s"
        "| %(threadName)-11s"
        "| %(levelname)-5s"
        "| %(message)s")
    log_handler.setFormatter(formatter)

    log_filter = ThreadLogFilter(thread_name)
    log_handler.addFilter(log_filter)

    logger = logging.getLogger()
    logger.addHandler(log_handler)

    return log_handler


def stop_thread_logging(log_handler):
    # Remove thread log handler from root logger
    logging.getLogger().removeHandler(log_handler)

    # Close the thread log handler so that the lock on log file can be released
    log_handler.close()


def worker():
    thread_log_handler = start_thread_logging()
    logging.info('Info log entry in sub thread.')
    logging.debug('Debug log entry in sub thread.')
    stop_thread_logging(thread_log_handler)


def config_root_logger():
    log_file = '/tmp/perThreadLogging.log'

    formatter = "%(asctime)-15s" \
                "| %(threadName)-11s" \
                "| %(levelname)-5s" \
                "| %(message)s"

    logging.config.dictConfig({
        'version': 1,
        'formatters': {
            'root_formatter': {
                'format': formatter
            }
        },
        'handlers': {
            'console': {
                'level': 'INFO',
                'class': 'logging.StreamHandler',
                'formatter': 'root_formatter'
            },
            'log_file': {
                'class': 'logging.FileHandler',
                'level': 'DEBUG',
                'filename': log_file,
                'formatter': 'root_formatter',
            }
        },
        'loggers': {
            '': {
                'handlers': [
                    'console',
                    'log_file',
                ],
                'level': 'DEBUG',
                'propagate': True
            }
        }
    })


if __name__ == '__main__':
    config_root_logger()

    logging.info('Info log entry in main thread.')
    logging.debug('Debug log entry in main thread.')

    for i in xrange(3):
        t = threading.Thread(target=worker,
                             name='Thread-{}'.format(i),
                             args=[])
        t.start()

控制台输出：

$ python perThreadLoggingSample.py
2019-03-07 10:29:34,318| MainThread | INFO | Info log entry in main thread.
2019-03-07 10:29:34,320| Thread-0   | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,320| Thread-1   | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,320| Thread-2   | INFO | Info log entry in sub thread.
$

查看日志文件：

$ cat /tmp/perThreadLogging.log
2019-03-07 10:29:34,318| MainThread | INFO | Info log entry in main thread.
2019-03-07 10:29:34,319| MainThread | DEBUG| Debug log entry in main thread.
2019-03-07 10:29:34,320| Thread-0   | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,320| Thread-1   | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,321| Thread-0   | DEBUG| Debug log entry in sub thread.
2019-03-07 10:29:34,320| Thread-2   | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,321| Thread-1   | DEBUG| Debug log entry in sub thread.
2019-03-07 10:29:34,321| Thread-2   | DEBUG| Debug log entry in sub thread.
$
$ cat /tmp/perThreadLogging-Thread-0.log
2019-03-07 10:29:34,320| Thread-0   | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,321| Thread-0   | DEBUG| Debug log entry in sub thread.
$
$ cat /tmp/perThreadLogging-Thread-1.log
2019-03-07 10:29:34,320| Thread-1   | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,321| Thread-1   | DEBUG| Debug log entry in sub thread.
$
$ cat /tmp/perThreadLogging-Thread-2.log
2019-03-07 10:29:34,320| Thread-2   | INFO | Info log entry in sub thread.
2019-03-07 10:29:34,321| Thread-2   | DEBUG| Debug log entry in sub thread.
$