具有多个模块的 Python 日志记录

Question

我有各种模块，我在其中大量使用 Python 日志记录。当我将它们导入到 Python 文档中的主模块并尝试运行它时，我没有从日志记录中获得任何输出。有人知道发生了什么吗？

Logging是在下面导入的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

您的问题可能是由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...

这似乎证实了上述分析。

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

我已经在我的项目中尝试过这段代码。在 main 中运行 configure_logint(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

编辑 1：

以下内容基于对 OP 代码的误解（来自评论）和我的错误假设。因此，它是无效的。

您提供的代码至少有一个错误。 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