日志记录模块示例代码每次调用重复消息 n 次

Question

我对 Python 的日志模块的输出感到惊讶。我写了 Python.org 的 How-To for Logging。当我运行示例代码时，有很多（令人困惑的）重复。

StreamHandler 复制日志消息，每次我用魔法 %run

重新加载 iPython 中的文件一个

In [4]: %run main.py
2018-05-11 2127:33 - WARNING - 3. This is a warning, yous!
2018-05-11 2127:33 - ERROR - 4. Here is an error
2018-05-11 2127:33 - CRITICAL - 5. This is f-ing critical!
[...]
In [7]: %run main.py
2018-05-11 2127:38 - WARNING - 3. This is a warning, yous!
2018-05-11 2127:38 - WARNING - 3. This is a warning, yous!
2018-05-11 2127:38 - WARNING - 3. This is a warning, yous!
2018-05-11 2127:38 - ERROR - 4. Here is an error
2018-05-11 2127:38 - ERROR - 4. Here is an error
2018-05-11 2127:38 - ERROR - 4. Here is an error
2018-05-11 2127:38 - CRITICAL - 5. This is f-ing critical!
2018-05-11 2127:38 - CRITICAL - 5. This is f-ing critical!
2018-05-11 2127:38 - CRITICAL - 5. This is f-ing critical!

我添加了一个 FileHandler：

fh = logging.FileHandler("app.log")
fh.setLevel(logging.DEBUG)
fh.setFormatter(formatter)
logger.addHandler(fh)

这也重复：

xtian@spaceghost> cat app.log
2018-05-11 2159:24 - WARNING - 3. This is a warning!
2018-05-11 2159:24 - ERROR - 4. This is an error
2018-05-11 2159:24 - CRITICAL - 5. This is fucking critical!
[...]
2018-05-11 2201:00 - WARNING - 3. This is a warning, yous!
2018-05-11 2201:00 - WARNING - 3. This is a warning, yous!
2018-05-11 2201:00 - WARNING - 3. This is a warning, yous!
2018-05-11 2201:00 - ERROR - 4. Here is an error.
2018-05-11 2201:00 - ERROR - 4. Here is an error.
2018-05-11 2201:00 - ERROR - 4. Here is an error.
2018-05-11 2201:00 - CRITICAL - 5. This is f-ing critical!
2018-05-11 2201:00 - CRITICAL - 5. This is f-ing critical!
2018-05-11 2201:00 - CRITICAL - 5. This is f-ing critical!

我也遵循了的建议，并在消息调用之前添加了这些行：

# propagation fix
logger.propagate = False

结果是一样的

设置为post，我看到一个类似的问题：

What could cause the logging module to log a record multiple times?

但所有这些调试都是针对 OP 的原始自定义代码。我的问题是示例代码，我希望它能更好地警告或解释正在发生的事情。

文档说，

Note. If you attach a handler to a logger and one or more of its ancestors, it may emit the same record multiple times. In general, you should not need to attach a handler to more than one logger - if you just attach it to the appropriate logger which is highest in the logger hierarchy, then it will see all events logged by all descendant loggers, provided that their propagate setting is left set to True. A common scenario is to attach handlers only to the root logger, and to let propagation take care of the rest.

你可以看完整的测试文件main.pyhere看看我有没有'more than one logger'.

import logging

# Root Logger
logger = logging.getLogger(__name__)

# Console handler
ch = logging.StreamHandler()
ch.setLevel(logging.WARNING)

# Formatter
formatter = logging.Formatter(fmt='%(asctime)s - %(levelname)s - %(message)s' , datefmt='%Y-%m-%d %H%M:%S', style='%')

# Add formatter to Console handler ch
ch.setFormatter(formatter)

# Add ch to logger
logger.addHandler(ch)

# Text File handler
fh = logging.FileHandler("app.log")
fh.setLevel(logging.DEBUG)
fh.setFormatter(formatter)
logger.addHandler(fh)

# propagation fix
logger.propagate = False

# Example Application code
logger.debug("1. This is a debug message.")
logger.info("2. This is an info message.")
logger.warning('3. This is a warning!')
logger.error('4. This is an error')
logger.critical("5. This is fucking critical!")

Answer 1

每次执行%run main.py时，logging.getLogger(__name__)返回的logger都是同一个logger。但是

ch = logging.StreamHandler()

每次实例化一个新的StreamHandler，然后添加到logger:

logger.addHandler(ch)

因此，在 %run main.py 的后续运行中，logger 有多个处理程序附加到它，每个处理程序都会发出一条记录。

In [5]: %run main.py
2018-05-11 2251:17 - WARNING - 3. This is a warning!
2018-05-11 2251:17 - ERROR - 4. This is an error
2018-05-11 2251:17 - CRITICAL - 5. This is fucking critical!

In [6]: logger
Out[6]: <logging.Logger at 0x7f5d0152fe10>

第一次%run main.py是运行，两个处理程序附加到logger:

In [7]: logger.handlers
Out[12]: 
[<logging.StreamHandler at 0x7f5d0152fdd8>,
 <logging.FileHandler at 0x7f5d014c40f0>]

In [13]: %run main.py
2018-05-11 2251:44 - WARNING - 3. This is a warning!
2018-05-11 2251:44 - WARNING - 3. This is a warning!
2018-05-11 2251:44 - ERROR - 4. This is an error
2018-05-11 2251:44 - ERROR - 4. This is an error
2018-05-11 2251:44 - CRITICAL - 5. This is fucking critical!
2018-05-11 2251:44 - CRITICAL - 5. This is fucking critical!

第二次，现在有四个处理程序：

In [14]: logger.handlers
Out[14]: 
[<logging.StreamHandler at 0x7f5d0152fdd8>,
 <logging.FileHandler at 0x7f5d014c40f0>,
 <logging.StreamHandler at 0x7f5d014c4668>,
 <logging.FileHandler at 0x7f5d014c4550>]

In [15]: logger
Out[15]: <logging.Logger at 0x7f5d0152fe10>

为防止重复，您可以在 %run 次调用之间调用 logger.removeHandler：

In [29]: for handler in logger.handlers: logger.removeHandler(handler)

In [30]: %run main.py
2018-05-11 2257:30 - WARNING - 3. This is a warning!
2018-05-11 2257:30 - ERROR - 4. This is an error
2018-05-11 2257:30 - CRITICAL - 5. This is fucking critical!

或者，修改 main.py 以便每次调用 %run 时都不会附加新的处理程序。例如，您可以使用 logging.config.dictConfig:

设置 logger

import logging
import logging.config

# Modified using  as a template
logging_config = { 
    'version': 1,
    'formatters': { 
        'standard': { 
            'format': '%(asctime)s - %(levelname)s - %(message)s'
        },
    },
    'handlers': { 
        'stream': { 
            'level': 'INFO',
            'formatter': 'standard',
            'class': 'logging.StreamHandler',
        },
        'file': { 
            'level': 'DEBUG',
            'formatter': 'standard',
            'class': 'logging.FileHandler',
            'filename': 'app.log'
        },
    },
    'loggers': { 
        __name__: { 
            'handlers': ['stream', 'file'],
            'level': 'WARN',
            'propagate': False
        },
    } 
}
logging.config.dictConfig(logging_config)
logger = logging.getLogger(__name__)

# Example Application code
logger.debug("1. This is a debug message.")
logger.info("2. This is an info message.")
logger.warning('3. This is a warning!')
logger.error('4. This is an error')
logger.critical("5. This is fucking critical!")

使用此代码，%run main.py 每次发出相同的输出。

日志记录模块示例代码每次调用重复消息 n 次

Logging module sample code repeats messages n-times-each call

python

logging

ipython