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 的日志是全的，且时间顺序是正确的，减少了排错的成本。