Python logging模塊日誌存儲位置踩坑

問題描述

項目過程當中寫了一個小模塊，設計到了日誌存儲的問題，結果發現了個小問題。

代碼結構以下：

db.py
run.py

其中db.py是操做數據庫抽象出來的一個類，run.py是業務邏輯代碼。兩個文件中都有使用Python自帶的logging模塊，來記錄日誌。其中前者將日誌存入到db_xxx.log下，後者存入run_xxx.log下。

二者logging相關代碼爲：

# db.py
import logging
import time

dt = time.time()
logging.basicConfig(filename='db_' + str(dt) + '.log', level=logging.INFO)


# run.py
import logging
import time

dt = time.time()
logging.basicConfig(filename='run_' + str(dt) + '.log', level=logging.INFO)

同時，在run.py中會調用db.py的函數，例如：

# db.py

class DB():
        def __init__(self):
                xxxx
        
        def select(self):
                logging.info('log from db.py')

# run.py

from db import DB

if __name__ == '__main__':
        db = DB()
        db.select()
        
        logging.info('log from run.py')

實際運行起來，發現全部的日誌都只會存在 db_xxx.log 中，同時並不會產生 run_xxx.log 文件。

排錯

猜想

依照上面的結果，猜想run.py文件中，引入的db.py中也有logging的設置，但只會有一個生效。

驗證 1

寫兩個py文件first.py和second.py，在second中引用first的函數，看最終日誌的輸出文件名及順序。

內容分別爲：

# first.py

import logging

class TEST():
    def __init__(self, log_type, dt):
        dt = str(dt)
        logging.basicConfig(filename='./log/' + log_type + '_' + dt + '.txt', level=logging.INFO)

    def test_log(self):
        logging.info('log from first.py')


# second.py

from first import TEST
import time

dt = time.time()

import logging
logging.basicConfig(filename='./log/' + 'second.txt', level=logging.INFO)
logging.info('log from second')


test = TEST('db', dt)
test.test_log()


# 結果

➜  log_dir_test python second.py
➜  log_dir_test ls log
second.txt
➜  log_dir_test cat log/second.txt
INFO:root:log from second
INFO:root:log from first.py

能夠看到，文件名爲 second.txt，即採用了 second.py 的logging設置。同時，日誌輸出的順序也是先輸出 second 再是 first。

驗證 2

此時嘗試將second.py的語句順序作一個調整，調整爲下面：

# second.py

from first import TEST
import time

dt = time.time()
test = TEST('db', dt)
test.test_log()

import logging
logging.basicConfig(filename='./log/' + 'second.txt', level=logging.INFO)
logging.info('log from second')

# result

➜  log_dir_test cat log/db_1561088221.83.txt
INFO:root:log from first.py
INFO:root:log from second

能夠看到結果存儲到了 db_xxx.txt 中，即採用了 first.py 的logging設置。

驗證 3

再對second.py作調整：

# second.py

from first import TEST
import time

dt = time.time()
test = TEST('db', dt)

import logging
logging.basicConfig(filename='./log/' + 'second.txt', level=logging.INFO)
logging.info('log from second')

test.test_log()

# result

➜  log_dir_test cat log/db_1561088393.36.txt
INFO:root:log from second
INFO:root:log from first.py

採用了first.py的設置

驗證 4

繼續調整second.py：

# second.py

from first import TEST
import time
import logging
logging.basicConfig(filename='./log/' + 'second.txt', level=logging.INFO)

dt = time.time()
test = TEST('db', dt)

logging.info('log from second')

test.test_log()


# result

➜  log_dir_test cat log/second.txt
INFO:root:log from second
INFO:root:log from first.py

採用了 second.py 的設置

共性

能夠發現，兩個文件的logging設置，在second.py的順序，影響了second.py的logging設置。即：

• 當 first.py 的logging設置在前的時候，採用first.py的設置
• 反正，採用second.py的設置
• 只採用其中一個設置

解釋

起初以爲奇怪，如今想一想仍是比較容易理解的。

假如 second.py 中已經設置了logging，後面引用了first.py的函數，first.py中又設置了logging。若此時又採用 first.py的設置，那後續若是second.py中又使用了logging.xxx怎麼辦？也就是說，Python會以爲混亂，不知所措……

解決辦法

若是仍是想達到 db.py 操做都存儲到 db 相關目錄下，run日誌存儲到run目錄下怎麼辦？彷佛沒太好的解決辦法；不優雅的處理方式，能夠採用文件操做……比方說使用with open(xx) as f去操做，這樣的話，比較繁瑣。

更好的辦法是什麼？就是如今Python的這種機制。即 run.py 相關日誌都存儲到 run 目錄下，即便調用了 db.py 的函數，日誌也存儲到 run 目錄下。這樣能夠保證 run.py 的日誌是全的，且時間順序是正確的，減小了排錯的成本。