淺析python日誌重複輸出問題

#淺析python日誌重複輸出問題

問題起源：

​ 在學習了python的函數式編程後，又接觸到了logging這樣一個強大的日誌模塊。爲了減小重複代碼，應該很多同窗和我同樣便火燒眉毛的寫了一個本身的日誌函數，好比下面這樣：

import logging


# 這裏爲了便於理解，簡單的展現了一個輸出到屏幕的日誌函數
def my_log():
    logger = logging.getLogger('mysql.log')

    ch = logging.StreamHandler()
    ch.setLevel(logging.ERROR)
    fmt = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
    ch.setFormatter(fmt)
    logger.addHandler(ch)

    return logger


my_log().error('run one')
my_log().error('run two')
my_log().error('run three')

函數寫好了，看起來彷佛也沒有問題，咱們來運行一下！

結果以下：

2018-06-21 13:06:37,569 - mysql.log - ERROR - run one 2018-06-21 13:06:37,569 - mysql.log - ERROR - run two 2018-06-21 13:06:37,569 - mysql.log - ERROR - run two 2018-06-21 13:06:37,569 - mysql.log - ERROR - run three 2018-06-21 13:06:37,569 - mysql.log - ERROR - run three 2018-06-21 13:06:37,569 - mysql.log - ERROR - run three

日誌竟然重複輸出了，且數量遞增。

---

問題解析

• 實際上logger = logging.getLogger('mysql.log')在執行時，沒有每次生成一個新的logger，而是先檢查內存中是否存在一個叫作‘mysql.log’的logger對象，存在則取出，不存在則新建。

• 實例化的logger對象具備‘handlers’這樣一個屬性來存儲 Handler，代碼演示以下：

import logging


def my_log():
	logger = logging.getLogger('mysql.log')
	# 每次被調用後打印出logger的handlers列表
	print(logger.handlers)

	ch = logging.StreamHandler()
	ch.setLevel(logging.ERROR)
	fmt = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
	ch.setFormatter(fmt)

	logger.addHandler(ch)

	return logger


my_log().error('run one')
my_log().error('run two')
my_log().error('run three')

運行結果：

[] 2018-06-21 13:26:14,059 - mysql.log - ERROR - run one [<StreamHandler <stderr> (ERROR)>] 2018-06-21 13:26:14,060 - mysql.log - ERROR - run two 2018-06-21 13:26:14,060 - mysql.log - ERROR - run two [<StreamHandler <stderr> (ERROR)>, <StreamHandler <stderr> (ERROR)>] 2018-06-21 13:26:14,060 - mysql.log - ERROR - run three 2018-06-21 13:26:14,060 - mysql.log - ERROR - run three 2018-06-21 13:26:14,060 - mysql.log - ERROR - run three

1. logger.handlers最初是一個空列表，執行‘logger.addHandler(ch)’添加一個‘StreamHandler’，輸出一條日誌
2. 在第二次被調用時，logger.handlers已經存在一個‘StreamHandler’，再次執行‘logger.addHandler(ch)’就會再次添加一個‘StreamHandler’，此時的logger有兩個‘StreamHandler’，輸出兩條重複的日誌
3. 在第三次被調用時，logger.handlers已經存在兩個‘StreamHandler’，再次執行‘logger.addHandler(ch)’就會再次添加一個，此時的logger有三個‘StreamHandler’，輸出三條重複的日誌

解決辦法

1.更名換姓

import logging


# 爲日誌函數添加一個name，每次調用時傳入不一樣的日誌名
def my_log(name):
    logger = logging.getLogger(name)

    ch = logging.StreamHandler()
    ch.setLevel(logging.ERROR)
    fmt = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
    ch.setFormatter(fmt)
    logger.addHandler(ch)

    return logger


my_log('log1').error('run one')
my_log('log2').error('run two')
my_log('log3').error('run three')

運行結果：

2018-06-21 13:40:51,685 - log1 - ERROR - run one 2018-06-21 13:40:51,685 - log2 - ERROR - run two 2018-06-21 13:40:51,685 - log3 - ERROR - run three

2.及時清理（logger.handlers.clear）

import logging


def my_log():
    logger = logging.getLogger('mysql.log')
    # 每次被調用後，清空已經存在handler
    logger.handlers.clear()

    ch = logging.StreamHandler()
    ch.setLevel(logging.ERROR)
    fmt = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
    ch.setFormatter(fmt)

    logger.addHandler(ch)

    return logger


my_log().error('run one')
my_log().error('run two')
my_log().error('run three')

ps：removeHandler方法（兼容性較差）

# 這種寫法下的可使用removeHandler方法(logger.handlers.clear也可使用在這種寫法的函數內)
import logging


def my_log(msg):
    logger = logging.getLogger('mysql.log')

    ch = logging.StreamHandler()
    ch.setLevel(logging.ERROR)
    fmt = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
    ch.setFormatter(fmt)

    logger.addHandler(ch)
    logger.error(msg)
    
    # 在使用完ch後從移除Handler
    logger.removeHandler(ch)


my_log('run one')
my_log('run two')
my_log('run three')

###3.用前判斷

import logging


def my_log():
    logger = logging.getLogger('mysql.log')
    # 判斷logger是否已經添加過handler，是則直接返回logger對象，不然執行handler設定以及addHandler(ch)
    if not logger.handlers:
        ch = logging.StreamHandler()
        ch.setLevel(logging.ERROR)
        fmt = logging.Formatter('%(asctime)s - %(name)s - %(levelname)s - %(message)s')
        ch.setFormatter(fmt)

        logger.addHandler(ch)

    return logger


my_log().error('run one')
my_log().error('run two')
my_log().error('run three')

總結

​ 第一次遇到日誌重複輸出問題，那時尚未學習到面向對象編程的內容，當時並無真正理解logging模塊。學習完面向對象編程後，回過頭來再思考這些問題有了豁然開朗的感受。

​ 好比起初對logging.getLogger的實際原理不是很理解，在學習了面向對象編程中的hasattr、getattr、setattr這樣一些方法後就恍然大悟了。因此諸君若是如今仍是對logging模塊不太理解，不妨先不糾結於這些細節，繼續學下去。

​ 知識面擴充後，曾經的一些難題天然就會迎刃而解：）

---

參考內容：

luffycity : https://www.luffycity.com/home

The Python Standard Library

huilan_same ：https://blog.csdn.net/huilan_same/article/details/51858817