Python多模块日志记录

Question

我有很多模块，里面大量使用了Python的日志功能。当我像Python文档中那样把这些模块导入到主模块里并尝试运行时，却没有看到任何日志输出。有人知道这是怎么回事吗？

日志功能是在下面导入的public模块中调用的（这段代码太长，无法在这里展示）。下面的代码是整个程序运行的地方，并且在这里初始化了日志功能：

import logging
from bottle import run, debug
import public

logging.basicConfig(level=logging.DEBUG)

if __name__ == '__main__':
   logging.info('Started')
   debug(mode=True)
   run(host='localhost', port = 8080, reloader=True)
   logging.info('Finished')

Answer 1

编辑 1：

下面的内容是基于对提问者代码的误解（来自评论）和我自己的错误假设。因此，这些内容是不正确的。

你提供的代码至少有一个错误。debug(mode=True) 错了，原因有两个：

1. 它是自我调用的，你定义的方法并不存在。
2. mode=True 是一个赋值操作，不是用来判断是否相等。

以下是去掉了其他模块和代码后，可以正常运行并记录日志的代码：

import logging

mode = False

logging.basicConfig(level=logging.DEBUG)
logging.info('Started')
logging.debug(mode is True)
# ... other code ...
logging.info('Finished')

从命令行运行：

$ python my_logger.py
INFO:root:Started
DEBUG:root:False
INFO:root:Finished

Answer 2

#!/usr/bin/env python
# -*- coding: utf-8 -*-

import logging
import logging.handlers
from logging.config import dictConfig

logger = logging.getLogger(__name__)

DEFAULT_LOGGING = {
    'version': 1,
    'disable_existing_loggers': False,
}
def configure_logging(logfile_path):
    """
    Initialize logging defaults for Project.

    :param logfile_path: logfile used to the logfile
    :type logfile_path: string

    This function does:

    - Assign INFO and DEBUG level to logger file handler and console handler

    """
    dictConfig(DEFAULT_LOGGING)

    default_formatter = logging.Formatter(
        "[%(asctime)s] [%(levelname)s] [%(name)s] [%(funcName)s():%(lineno)s] [PID:%(process)d TID:%(thread)d] %(message)s",
        "%d/%m/%Y %H:%M:%S")

    file_handler = logging.handlers.RotatingFileHandler(logfile_path, maxBytes=10485760,backupCount=300, encoding='utf-8')
    file_handler.setLevel(logging.INFO)

    console_handler = logging.StreamHandler()
    console_handler.setLevel(logging.DEBUG)

    file_handler.setFormatter(default_formatter)
    console_handler.setFormatter(default_formatter)

    logging.root.setLevel(logging.DEBUG)
    logging.root.addHandler(file_handler)
    logging.root.addHandler(console_handler)



[31/10/2015 22:00:33] [DEBUG] [yourmodulename] [yourfunction_name():9] [PID:61314 TID:140735248744448] this is logger infomation from hello module

我在我的项目中试过这段代码。在主程序中运行 configure_loggint(logpath)。

你可以使用

#!/usr/bin/env python
# -*- coding: utf-8 -*-

import logging

logger = logging.getLogger(__name__)

def hello():
    logger.debug("this is logger infomation from hello module")

Answer 3

你的问题可能是因为 import public 这行代码在调用 logging.debug(...) 或类似的函数。接下来发生的事情是这样的：

1. 你执行了 import public。这会引发一个副作用，比如调用了 logging.debug，这会自动调用 basicConfig，然后给根日志记录器添加一个 StreamHandler，但不会改变日志级别。
2. 然后你调用 basicConfig，但是因为根日志记录器已经有了一个处理器，所以这次调用没有任何效果（文档中有说明）。
3. 由于默认的日志级别是 WARNING，所以你的 info 和 debug 调用不会产生任何输出。

你真的应该避免在导入时产生副作用：例如，你对 basicConfig 的调用应该放在 if __name__ == '__main__' 这个条件语句里。下面是这个 public.py 文件：

import logging

def main():
    logging.debug('Hello from public')

还有这个 main.py 文件：

import logging
from bottle import run, debug
import public

def main():
    logging.basicConfig(level=logging.DEBUG)
    logging.info('Started')
    debug(mode=True)
    public.main()
    run(host='localhost', port = 8080, reloader=True)
    logging.info('Finished')

if __name__ == '__main__':
    main()

你会得到以下输出：

$ python main.py
INFO:root:Started
DEBUG:root:Hello from public
INFO:root:Started
DEBUG:root:Hello from public
Bottle server starting up (using WSGIRefServer())...
Listening on http://localhost:8080/
Hit Ctrl-C to quit.

^CINFO:root:Finished
$ Shutdown...
INFO:root:Finished

你会发现，Bottle 实际上是在一个单独的进程中重新运行脚本，这就是消息重复的原因。你可以通过使用一个格式字符串来显示进程 ID 来说明这一点：如果你使用

logging.basicConfig(level=logging.DEBUG,
                    format='%(process)s %(levelname)s %(message)s')

那么你会得到类似这样的输出：

$ python main.py
13839 INFO Started
13839 DEBUG Hello from public
13840 INFO Started
13840 DEBUG Hello from public
Bottle server starting up (using WSGIRefServer())...
Listening on http://localhost:8080/
Hit Ctrl-C to quit.

^C13839 INFO Finished
$ Shutdown...
13840 INFO Finished

注意，如果你在 public.py 中添加一个会产生副作用的语句，比如：

logging.debug('Side-effect from public')

在模块级别，那么你根本不会得到任何日志输出：

$ python main.py
Bottle server starting up (using WSGIRefServer())...
Listening on http://localhost:8080/
Hit Ctrl-C to quit.

^C$ Shutdown...

这似乎证实了上面的分析。