Python日志记录在导入模块中的记录器的包装脚本中创建处理程序

Question

我正在编写一个API(python 2.7.x)，我有一个工作脚本，它自己不做任何事情，但可以被各种更高级别的脚本包裹(即一个从csv提供工作数据，一个从dB等提供工作数据)。当前任务要求我：

1. 将INFO+日志记录到控制台
2. 将某一组INFO+事件记录到.csv文件中
3. 将所有事件记录到不同的.log文件中

我已经将代码提炼为以下示例：

# SuperExample.py
import logging
import SubExample

def main():
logging.basicConfig(level=logging.INFO)
verbose_log = 'debug.log'
data_log = 'data.csv'
format_string = '%(asctime)s::%(name)s::%(levelname)s::%(message)s'
formatter = logging.Formatter(format_string)
# verbose log is a typical event log used for debugging
verbose = logging.FileHandler(verbose_log, mode='w')
verbose.setLevel(logging.DEBUG)
verbose.setFormatter(formatter)
SubExample.logger.addHandler(verbose)
# data log will eventually have a different formatter and a filter in
# order to get a narrow set of events, formatted for post-processing ease
data = logging.FileHandler(data_log, mode='w')
data.setLevel(logging.INFO)
data.setFormatter(formatter)
SubExample.logger.addHandler(data)
logging.info('Started')
SubExample.do_something()
logging.info('Finished')
if __name__ == '__main__':
main()

和

# SubExample.py
import logging
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)

def do_something():
logger.debug('hey look I am doing something!')
logger.debug('now I am doing something else!!')
logger.info('this is my result!!!')

它在我的文件中提供了我想要的东西，但在我的控制台中提供了这个：

INFO:root:Started
DEBUG:SubExample:hey look I am doing something!
DEBUG:SubExample:now I am doing something else!!
INFO:SubExample:this is my result!!!
INFO:root:Finished

我读过关于日志模块及其最佳实践的文章，但很少有示例代码能像库所描述的那样工作。所以，我的第一个问题是：这是一种基本上理智的方法吗？实际上，我还没有看到其他人从包装脚本将处理程序附加到下标记录器，但它似乎可以实现我想要的功能。

我的第二个问题是，为什么DEBUG语句会进入控制台？我认为logging.basicConfig(level=logging.INFO)应该防止这种情况发生？

Answer 1

在SuperExample.py文件中，我删除了basicConfig步骤，改为执行以下操作：

# SuperExample.py
import logging
import SubExample
def main():
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
console = logging.StreamHandler()
console.setLevel(logging.INFO)
logger.addHandler(console)
...
...
logger.info('Started')
...
logger.info('Finished')

在SubExample.py文件中：

# SubExample.py
import logging
logger = logging.getLogger(__name__)
logger.setLevel(logging.DEBUG)
console = logging.StreamHandler()
console.setLevel(logging.INFO)
logger.addHandler(console)
def do_something():
....

其余代码与您的代码相同。当我运行SuperExample.py时，这是输出：

test_project ~$ python SuperExample.py
Started
this is my result!!!
Finished

debug.log文件包含以下内容：

2017-10-25 16:18:08,292::SubExample::DEBUG::hey look I am doing something!
2017-10-25 16:18:08,292::SubExample::DEBUG::now I am doing something else!!
2017-10-25 16:18:08,292::SubExample::INFO::this is my result!!!

data.csv文件包含以下内容：

2017-10-25 16:18:08,292::SubExample::INFO::this is my result!!!

因此，似乎正确的方法是在每个模块的记录器中添加一个StreamHandler，并将其级别设置为您希望从那里记录到控制台的级别。此外，无论何时执行logging.getLogger()，都必须设置记录器的级别，以便从处理程序中获得预期的行为。