一般当我们启动多线程的时候,各个多线程的日志会打印到同一个日志文件。但是这样就会产生一个问题,当程序出现异常需要进行日志排查的时候,会发现各个线程的日志各种交叉混乱打印到了一起,导致难以区分甚至根本无法区分,特别是线程数开得比较多的时候,这时候想要进行日志追踪和排查就很困难了。

我原本想的是给不同的线程传递不同的前缀,在日志打印时将这些前缀加到对应线程日志前边,但是这样操作虽然可行,但是有点略显复杂。

后面发现还有更简单的办法。原来 logging 早已想到了这种困扰,可以直接在日志输出的 format 格式里添加 [%(threadName)s],自动将对应线程的线程名打印到日志里。比如设置打印格式为:

[%(asctime)s,%(msecs)d][%(threadName)s][%(module)s][%(levelname)s] %(lineno)d - %(message)s

日志常规打印

import os
import random
import threading
import logging
import time
from logging import handlers

os.makedirs("./logs", exist_ok=True)


def _logging(**kwargs):
    level = kwargs.pop('level', logging.DEBUG)
    filename = kwargs.pop('filename', 'default.log')
    datefmt = kwargs.pop('datefmt', '%Y-%m-%d %H:%M:%S')
    format = kwargs.pop('format', '[%(asctime)s,%(msecs)d][%(module)s][%(levelname)s] %(lineno)d - %(message)s')
    log = logging.getLogger(filename)
    format_str = logging.Formatter(format, datefmt)

    th = handlers.TimedRotatingFileHandler(filename=filename, when='MIDNIGHT', backupCount=5, encoding="utf-8")
    th.setFormatter(format_str)
    th.setLevel(level)

    log.addHandler(th)
    log.setLevel(level)
    return log


logger = _logging(filename="./logs/test.log")


def run():
    logger.info("start run task")
    sleep_second = random.randint(1, 5)
    logger.info(f"sleep {sleep_second}s")
    time.sleep(sleep_second)
    logger.info("end run task")


if __name__ == '__main__':
    logger.info("start main thread")
    thread_list = []
    for i in range(3):
        t = threading.Thread(target=run)
        thread_list.append(t)

    for t in thread_list:
        t.daemon = True
        t.start()

    for t in thread_list:
        t.join()

    logger.info("end main thread")
[2025-09-28 10:46:36,748][logger][INFO] 40 - start main thread
[2025-09-28 10:46:36,749][logger][INFO] 32 - start run task
[2025-09-28 10:46:36,749][logger][INFO] 34 - sleep 5s
[2025-09-28 10:46:36,749][logger][INFO] 32 - start run task
[2025-09-28 10:46:36,749][logger][INFO] 34 - sleep 5s
[2025-09-28 10:46:36,750][logger][INFO] 32 - start run task
[2025-09-28 10:46:36,750][logger][INFO] 34 - sleep 2s
[2025-09-28 10:46:38,751][logger][INFO] 36 - end run task
[2025-09-28 10:46:41,750][logger][INFO] 36 - end run task
[2025-09-28 10:46:41,752][logger][INFO] 36 - end run task
[2025-09-28 10:46:41,752][logger][INFO] 53 - end main thread

日志区分打印

import os
import random
import threading
import logging
import time
from logging import handlers

os.makedirs("./logs", exist_ok=True)


def _logging(**kwargs):
    level = kwargs.pop('level', logging.DEBUG)
    filename = kwargs.pop('filename', 'default.log')
    datefmt = kwargs.pop('datefmt', '%Y-%m-%d %H:%M:%S')
    format = kwargs.pop('format', '[%(asctime)s,%(msecs)d][%(threadName)s][%(module)s][%(levelname)s] %(lineno)d - %(message)s')
    log = logging.getLogger(filename)
    format_str = logging.Formatter(format, datefmt)

    th = handlers.TimedRotatingFileHandler(filename=filename, when='MIDNIGHT', backupCount=5, encoding="utf-8")
    th.setFormatter(format_str)
    th.setLevel(level)

    log.addHandler(th)
    log.setLevel(level)
    return log


logger = _logging(filename="./logs/test.log")


def run():
    logger.info("start run task")
    sleep_second = random.randint(1, 5)
    logger.info(f"sleep {sleep_second}s")
    time.sleep(sleep_second)
    logger.info("end run task")


if __name__ == '__main__':
    logger.info("start main thread")
    thread_list = []
    for i in range(3):
        t = threading.Thread(target=run)
        thread_list.append(t)

    for t in thread_list:
        t.daemon = True
        t.start()

    for t in thread_list:
        t.join()

    logger.info("end main thread")
[2025-09-28 10:50:45,289][MainThread][logger][INFO] 40 - start main thread
[2025-09-28 10:50:45,289][Thread-1 (run)][logger][INFO] 32 - start run task
[2025-09-28 10:50:45,289][Thread-1 (run)][logger][INFO] 34 - sleep 4s
[2025-09-28 10:50:45,290][Thread-2 (run)][logger][INFO] 32 - start run task
[2025-09-28 10:50:45,290][Thread-2 (run)][logger][INFO] 34 - sleep 3s
[2025-09-28 10:50:45,290][Thread-3 (run)][logger][INFO] 32 - start run task
[2025-09-28 10:50:45,290][Thread-3 (run)][logger][INFO] 34 - sleep 2s
[2025-09-28 10:50:47,292][Thread-3 (run)][logger][INFO] 36 - end run task
[2025-09-28 10:50:48,291][Thread-2 (run)][logger][INFO] 36 - end run task
[2025-09-28 10:50:49,291][Thread-1 (run)][logger][INFO] 36 - end run task
[2025-09-28 10:50:49,291][MainThread][logger][INFO] 53 - end main thread

可以看到,添加格式 [%(threadName)s] 后,日志里就自动将对应的线程名打印出来了,这时候,再对多线程里出现的问题进行日志追踪就容易多了。

Logo

Agent 垂直技术社区,欢迎活跃、内容共建。

更多推荐