在Python中使用根日志记录器还是命名日志记录器更好？

Question

我正在尝试找出在Python中跨多个模块使用日志记录的最佳实践。我在这里看到了一些信息：http://docs.python.org/2/howto/logging#logging-from-multiple-modules，它讲述了如何使用根日志记录器在多个模块中记录日志。不过，正如链接所指出的那样，你无法知道消息来自应用程序的哪个部分，因为它们都显示为“root”。

在我看来，有两个选择（假设我的模块不在包结构中，而只是同一个文件夹中的一堆模块）：

1) 像示例中那样使用根日志记录器，但更改日志格式以包含文件名：

# myapp.py
import logging
import mylib

def main():
    logging.basicConfig(format='%(asctime)s %(filename)s %(levelname)s: %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p', level=logging.INFO)  #filename='myapp.log', 
    logging.info('Started')
    mylib.do_something()
    logging.info('Finished')

if __name__ == '__main__':
    main()

#mylib.py
import logging

def do_something():
    logging.info('Do something')




In [4]: import myapp

In [5]: myapp.main()
03/06/2014 12:22:07 PM myapp.py INFO: Started
03/06/2014 12:22:07 PM mylib.py INFO: Do something
03/06/2014 12:22:07 PM myapp.py INFO: Finished

2) 在主应用程序中使用根日志记录器，但在子模块中使用命名日志记录器，并在日志格式中使用“name”而不是“filename”：

# myapp.py
import logging
import mylib

def main():
    #logging.basicConfig(format='%(asctime)s %(filename)s %(levelname)s: %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p', level=logging.INFO)  #filename='myapp.log', 
    logging.basicConfig(format='%(asctime)s %(name)s %(levelname)s: %(message)s', datefmt='%m/%d/%Y %I:%M:%S %p', level=logging.INFO)  #filename='myapp.log', 
    logging.info('Started')
    mylib.do_something()
    logging.info('Finished')

if __name__ == '__main__':
    main()

#mylib.py
import logging

def do_something():
    #logging.info('Do something')
    logger = logging.getLogger(__name__)
    logger.info('Do something')



In [3]: import myapp

In [4]: myapp.main()
03/06/2014 12:27:29 PM root INFO: Started
03/06/2014 12:27:29 PM mylib INFO: Do something
03/06/2014 12:27:29 PM root INFO: Finished

Answer 1

Vinay Sajip（负责日志模块的维护者）在这里给出了一个建议，这个建议和你提到的第二个选项有点像，不过你可以在任何地方使用一个命名的日志记录器，包括在我的应用程序（myapp）里：

import logging
import mylib
logger = logging.getLogger(__name__)

def main():
    logging.basicConfig(format='%(asctime)s %(module)s %(levelname)s: %(message)s',
                        datefmt='%m/%d/%Y %I:%M:%S %p', level=logging.INFO)  
    logger.info('Started')
    mylib.do_something()
    logger.info('Finished')

if __name__ == '__main__':
    main()

这样做的结果是：

03/06/2014 12:59:25 PM myapp INFO: Started
03/06/2014 12:59:25 PM mylib INFO: Do something
03/06/2014 12:59:25 PM myapp INFO: Finished

注意，如果你用 %(module)s 代替 %(name)s，那么你会得到 myapp，而之前你得到的是 root、myapp.py 或者 __main__。

这种一致性——总是使用 logger——在 myapp 有时作为脚本调用，有时作为模块导入时，可能特别有用。