logging 重複打日誌

Jayden5發表於2021-01-25

正確使用姿勢

import logging

import config

LOG_LEVEL = "INFO"
LOG_FORMAT = "%(asctime)s %(name)s %(levelname)s %(message)s"

def get_logger(name, level=LOG_LEVEL, log_format=LOG_FORMAT):
    """
    :param name: looger 例項的名字
    :param level: logger 日誌級別
    :param log_format: logger 的輸出`格式
    :return:
    """
    # 強制要求傳入 name
    logger = logging.getLogger(name)
    # 如果已經例項過一個相同名字的 logger，則不用再追加 handler
    if not logger.handlers:
        logger.setLevel(level=level)
        formatter = logging.Formatter(log_format)
        sh = logging.StreamHandler()
        sh.setFormatter(formatter)
        logger.addHandler(sh)
    return logger

官方文件有關介紹

Note that Loggers should NEVER be instantiated directly, but always through the module-level function logging.getLogger(name). Multiple calls to getLogger() with the same name will always return a reference to the same Logger object.

Logger物件一般不會直接例項化得到，而是通過模組級別的函式logging.getLogger(name)得到。以相同的名稱多次呼叫getLogger()將永遠返回相同Logger物件的引用。

If you attach a handler to a logger and one or more of its ancestors, it may emit the same record multiple times. In general, you should not need to attach a handler to more than one logger - if you just attach it to the appropriate logger which is highest in the logger hierarchy, then it will see all events logged by all descendant loggers, provided that their propagate setting is left set to True. A common scenario is to attach handlers only to the root logger, and to let propagation take care of the rest.

注如果你新增一個handler到logger和 它的一個或多個祖先中，它可能多次列印相同的記錄。一般來說，你不應該需要將一個handler新增給多個logger - 如果你只將它新增到合適的logger而它是logger層次中最高的，那麼它將看到所有子logger記錄的事件，只要它們的propagate設定保留為True。一個常見的場景是將handlers附加給根logger，然後讓propagation負責剩下的事情。

先看下面這段程式碼會發生什麼？

先看原始碼裡有關日誌輸出的地方

def callHandlers(self, record):
    """
    Pass a record to all relevant handlers.

    Loop through all handlers for this logger and its parents in the
    logger hierarchy. If no handler was found, output a one-off error
    message to sys.stderr. Stop searching up the hierarchy whenever a
    logger with the "propagate" attribute set to zero is found - that
    will be the last logger whose handlers are called.
    """
    c = self
    found = 0
    while c:
        for hdlr in c.handlers:
            found = found + 1
            if record.levelno >= hdlr.level:
                hdlr.handle(record)
        if not c.propagate:
            c = None    #break out
        else:
           # 將 parent 屬性重新賦值給自己
            c = c.parent

如果，c 是一個 self 例項，先查詢裡面的 c.handlers，當前 logger 例項有多少個 handlers 會 flush多少次日誌；而 c.propagate 預設為 TRUE，所以當遍歷當前 例項的 handles，還會尋找其parent的handles，依次遍歷。

因此，出現多次列印日誌的可能

  • 當前 logger 例項有多個 handlers。出現這種情況，是因為在建立 logger 例項，即 logging.getLogger(name) 時，相同的名稱多次呼叫getLogger()，這時候會返回相同Logger物件的引用，然而每次呼叫getLogger()後都新增一個 handlers，此時同一個 logger 例項就有多個 handlers。

  • 父類有 handlers。出現這種情況，一般是因為引用了 root logger ，並且給 root logger 新增了 StreamHandlers。

1. logger 例項有多個 handles - 相同的名稱多次呼叫getLogger()

錯誤示範：

def log(name=None):
    ch = logging.StreamHandler()
    ch.setLevel(logging.INFO)

    formatter = logging.Formatter("%(asctime)s,%(name)s,%(levelname)s,%(message)s")

    logger = logging.getLogger(name)
    logger.setLevel(logging.INFO)

    ch.setFormatter(formatter)
    logger.addHandler(ch)
    return logger

log('test').info('log')
log('test').info('test')

輸出

2020-01-10 14:21:50,222,test,INFO,log
2020-01-10 14:21:50,222,test,INFO,test
2020-01-10 14:21:50,222,test,INFO,test

原因是 log(‘test’).info(‘log’) 會建立一個 logger 的例項，並且新增一個 handlers，此時只有一個handlers，因此只列印一次。log(‘test’).info(‘test’) 則不會再建立一個新的 logger 例項，而是引用了之前建立的物件，並且又新增了一個 handlers，此時這個例項就有2個 handlers，因此會輸出兩次同一條日誌

正確做法：

LOG_LEVEL = "INFO"
LOG_FORMAT = "%(asctime)s %(name)s %(levelname)s %(message)s"
def get_logger(name, level=LOG_LEVEL, log_format=LOG_FORMAT):
    """
    :param name: looger 例項的名字
    :param level: logger 日誌級別
    :param log_format: logger 的輸出`格式
    :return:
    """
    # 強制要求傳入 name
    logger = logging.getLogger(name)
    # 如果已經例項過一個相同名字的 logger，則不用再追加 handler
    if not logger.handlers:
        logger.setLevel(level=level)
        formatter = logging.Formatter(log_format)
        sh = logging.StreamHandler()
        sh.setFormatter(formatter)
        logger.addHandler(sh)
    return logger

2. 呼叫 getLogger() 時 沒有賦值 name

錯誤例項

def log(name=None):
    ch = logging.StreamHandler()
    ch.setLevel(logging.INFO)

    formatter = logging.Formatter("%(asctime)s,%(name)s,%(levelname)s,%(message)s")

    logger = logging.getLogger(name)
    logger.setLevel(logging.INFO)

    ch.setFormatter(formatter)
    logger.addHandler(ch)
    return logger

log().info('log')
log('test').info('test')

輸出

2020-01-10 14:29:50,920,root,INFO,log
2020-01-10 14:29:50,920,test,INFO,test
2020-01-10 14:29:50,920,test,INFO,test

相應原始碼

root = RootLogger(WARNING)
Logger.root = root
Logger.manager = Manager(Logger.root)
...
...

def getLogger(name=None):
    """
    Return a logger with the specified name, creating it if necessary.

    If no name is specified, return the root logger.
    """
    if name:
        return Logger.manager.getLogger(name)
    # 如果在 getLogger 時沒有賦值 name，會返回 root物件
    else:
        return root

如果在 getLogger 時沒有賦值 name，會返回 root物件，而 root 是 RootLogger的例項。在getLogger後又新增了一個 handler，此時，root 這個 logger例項，就會有一個handler了（預設是沒有的），因此當logger例項找到父級時，其父級也有有一個 handler，因此會再輸出多一次相同的日誌。

3. import logging 或者使用了 logging.basicConfig(kwargs)

先看下面這個測試案例

import logging
logging.error('hello')

輸出

ERROR:root:hello

從原始碼分析

def error(msg, *args, **kwargs):
    """
    Log a message with severity 'ERROR' on the root logger. If the logger has
    no handlers, call basicConfig() to add a console handler with a pre-defined
    format.
    """
    if len(root.handlers) == 0:
        basicConfig()
    root.error(msg, *args, **kwargs)

調式可以發現，root 是一個 RootLogger的物件，且 root.handlers 是一個空的列表，那麼根據上面的原始碼，接下來就會呼叫 basicConfig()方法。

root

那麼可以理解為

import logging == import logging; logging.basicConfig()

測試

import logging

log_format = "[%(asctime)s] %(filename)s %(funcName)s line:%(lineno)d [%(levelname)s]%(message)s"
logging.basicConfig(level=logging.INFO, format=log_format)


def log(name=None):
    ch = logging.StreamHandler()
    ch.setLevel(logging.INFO)

    formatter = logging.Formatter("%(asctime)s,%(name)s,%(levelname)s,%(message)s")

    logger = logging.getLogger(name)
    logger.setLevel(logging.INFO)

    ch.setFormatter(formatter)
    logger.addHandler(ch)
    return logger

log('test').info('test')

輸出

2020-01-10 14:32:36,817,test,INFO,test
[2020-01-10 14:32:36,817] __init__.py <module> line:26 [INFO]test

先看原始碼

def basicConfig(**kwargs):
    _acquireLock()
    try:
        if len(root.handlers) == 0:
            handlers = kwargs.pop("handlers", None)
            if handlers is None:
                if "stream" in kwargs and "filename" in kwargs:
                    raise ValueError("'stream' and 'filename' should not be "
                                     "specified together")
            else:
                if "stream" in kwargs or "filename" in kwargs:
                    raise ValueError("'stream' or 'filename' should not be "
                                     "specified together with 'handlers'")
            if handlers is None:
                filename = kwargs.pop("filename", None)
                mode = kwargs.pop("filemode", 'a')
                # 如果賦值了 filename，則建立 FileHandler
                if filename:
                    h = FileHandler(filename, mode)
                # 否則預設建立 StreamHandler
                else:
                    stream = kwargs.pop("stream", None)
                    h = StreamHandler(stream)
                handlers = [h]
            dfs = kwargs.pop("datefmt", None)
            style = kwargs.pop("style", '%')
            if style not in _STYLES:
                raise ValueError('Style must be one of: %s' % ','.join(
                                 _STYLES.keys()))
            fs = kwargs.pop("format", _STYLES[style][1])
            fmt = Formatter(fs, dfs, style)
            for h in handlers:
                if h.formatter is None:
                    h.setFormatter(fmt)
                # 加入到 root 
                root.addHandler(h)
            level = kwargs.pop("level", None)
            if level is not None:
                root.setLevel(level)
            if kwargs:
                keys = ', '.join(kwargs.keys())
                raise ValueError('Unrecognised argument(s): %s' % keys)
    finally:
        _releaseLock()

如上，如果 basicConfig 有賦值引數 filename，則會建立一個 filehandler，將日誌輸入到檔案上，否則預設建立一個StreamHandler,並且會新增一個 name=None的 handler 到 rootLogger 上，此時情況又變成了類似第二種，root 這個 logger例項帶有一個handler。

總結

  1. basicConfig是 logging的所有頂級配置，如果在這裡配置了，其後面宣告的 logging.getLogger(name) 都可能會受到影響。最好不要隨便使用 basicConfig 來輸入 streamhandler，即使用 basicConfig 一般是用於輸出到檔案上。

  2. 使用 logging.getLogger(name) 時，一定要賦值 name，且 name 不應該相同，如果不知道怎麼命名，可以 logging.getLogger(_name_) 或者 logginggetLogger(_file_)

  3. 如果怕萬一使用了相同的name，可以在建立下，先判斷有沒有相同 name的 logger例項存在，如果有，則不新增 Handler，如第一點的正確做法

  4. 其實 如果設定 Logger.propagate = False（預設為TRUE），日誌訊息就不會傳遞給祖先 loggers 的 handlers。如果它為真，記錄到該 logger 的事件除了傳遞給該 logger 的 handler 之外，也被傳遞給上游（祖先）logger的 handler。資訊將直接傳遞給祖先 logger 的 handler - 不會考慮祖先 logger 的級別和 filter。但感覺最好不要這樣處理

本作品採用《CC 協議》，轉載必須註明作者和本文連結

相關文章