python - 日志记录中标准输出捕获的最大递归深度

Question

我的记录器配置如下:

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

import logging
import logging.handlers
import sys
import os
import re


class MaskFormatter(logging.Formatter):
    def __init__(self, fmt, masks):
        logging.Formatter.__init__(self, fmt)
        self.masks = masks

    def format(self, record):
        result = logging.Formatter.format(self, record)
        if result is not None:
            result = self.masks.sub("*" * 25, result)
        return result


class LoggerWriter:
    def __init__(self, level):
        # self.level is really like using log.debug(message)
        # at least in my case
        self.level = level

    def write(self, message):
        # if statement reduces the amount of newlines that are
        # printed to the logger
        if message != '\n':
            self.level("stdout: " + message)

    def flush(self):
        # create a flush method so things can be flushed when
        # the system wants to. Not sure if simply 'printing'
        # sys.stderr is the correct way to do it, but it seemed
        # to work properly for me.
        self.level("stderr: " + sys.stderr)


VERBOSE = 5

log = logging.getLogger("my_logger")

logging.getLogger("requests").setLevel(logging.WARNING)
logging.getLogger("selenium").setLevel(logging.INFO)

logging.addLevelName(5, "VERBOSE")

masks_compile = re.compile('|'.join(map(re.escape, ["some_pass_1", "some_pass_2"])))

c_formatter = MaskFormatter('%(message)s', masks_compile)
f_formatter = MaskFormatter('%(asctime)s %(name)s %(levelname)s: \t %(message)s', masks_compile)

f_handler = logging.handlers.RotatingFileHandler(os.path.join(os.path.expanduser("~"), "tests.log"), mode='a', maxBytes=3000000, backupCount=10)
f_handler.setFormatter(f_formatter)
f_handler.setLevel(logging.DEBUG)

c_handler = logging.StreamHandler(sys.stdout)
c_handler.setFormatter(c_formatter)
c_handler.setLevel(int(os.environ.get("logging_level", "5")))

log.addHandler(c_handler)
log.addHandler(f_handler)
log.setLevel(int(os.environ.get("logging_level", "5")))


sys.stdout = LoggerWriter(log.debug)
sys.stderr = LoggerWriter(log.warning)

注意我正在捕获标准输出和标准错误。

我在 Jenkins 上运行时随机遇到的问题是，在记录简单消息时，记录器进入最大递归。测试失败的方式不同，但每个测试都在“self.level("stdout: "+ message)"

行中进入这样的递归

堆栈跟踪之一:

  File "C:\Python27\lib\unittest\case.py", line 384, in doCleanups
        function(*args, **kwargs)
  File "C:\jenkins\workspace\PLC_Tests_Core_Functionalities_Win7_64b_Nightly\automation\tests\ds_setup.py", line 191, in failedReset
        log.info("Test failed, will reinstall DS and set subscribed to initial ones")
  File "C:\Python27\lib\logging\__init__.py", line 1160, in info
        self._log(INFO, msg, args, **kwargs)
  File "C:\Python27\lib\logging\__init__.py", line 1279, in _log
        self.handle(record)
  File "C:\Python27\lib\logging\__init__.py", line 1289, in handle
        self.callHandlers(record)
  File "C:\Python27\lib\logging\__init__.py", line 1329, in callHandlers
        hdlr.handle(record)
  File "C:\Python27\lib\logging\__init__.py", line 757, in handle
        self.emit(record)
  File "C:\Python27\lib\logging\handlers.py", line 82, in emit
        self.handleError(record)
  File "C:\Python27\lib\logging\__init__.py", line 810, in handleError
        None, sys.stderr)
  File "C:\Python27\lib\traceback.py", line 124, in print_exception
        _print(file, 'Traceback (most recent call last):')
  File "C:\Python27\lib\traceback.py", line 13, in _print
        file.write(str+terminator)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)
  File "C:\jenkins\workspace\PLC_Tests_Core_Functionalities_Win7_64b_Nightly\automation\pages\log.py", line 36, in write
        self.level("stdout: " + message)
  File "C:\Python27\lib\logging\__init__.py", line 1172, in warning
        self._log(WARNING, msg, args, **kwargs)
  File "C:\Python27\lib\logging\__init__.py", line 1279, in _log
        self.handle(record)
  File "C:\Python27\lib\logging\__init__.py", line 1289, in handle
        self.callHandlers(record)
  File "C:\Python27\lib\logging\__init__.py", line 1329, in callHandlers
        hdlr.handle(record)
  File "C:\Python27\lib\logging\__init__.py", line 757, in handle
        self.emit(record)
  File "C:\Python27\lib\logging\handlers.py", line 82, in emit
        self.handleError(record)
  File "C:\Python27\lib\logging\__init__.py", line 810, in handleError
        None, sys.stderr)
  File "C:\Python27\lib\traceback.py", line 124, in print_exception
        _print(file, 'Traceback (most recent call last):')
  File "C:\Python27\lib\traceback.py", line 13, in _print
        file.write(str+terminator)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)
  File "C:\jenkins\workspace\PLC_Tests_Core_Functionalities_Win7_64b_Nightly\automation\pages\log.py", line 36, in write
        self.level("stdout: " + message)
  File "C:\Python27\lib\logging\__init__.py", line 1172, in warning
        self._log(WARNING, msg, args, **kwargs)
  File "C:\Python27\lib\logging\__init__.py", line 1279, in _log
        self.handle(record)
  File "C:\Python27\lib\logging\__init__.py", line 1289, in handle
        self.callHandlers(record)
  File "C:\Python27\lib\logging\__init__.py", line 1329, in callHandlers
        hdlr.handle(record)
  File "C:\Python27\lib\logging\__init__.py", line 757, in handle
        self.emit(record)
  File "C:\Python27\lib\logging\handlers.py", line 82, in emit
        self.handleError(record)
  File "C:\Python27\lib\logging\__init__.py", line 810, in handleError
        None, sys.stderr)
  File "C:\Python27\lib\traceback.py", line 124, in print_exception
        _print(file, 'Traceback (most recent call last):')
  File "C:\Python27\lib\traceback.py", line 13, in _print
        file.write(str+terminator)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)
  File "C:\Python27\lib\site-packages\nose\plugins\xunit.py", line 129, in write
        s.write(data)

我运行测试:

nosetests -v -s --with-xunit --xunit-file=path/to/xml path/to/tests --with-allure --logdir=path/to/output

Answer 1

我预计问题来自于尝试从同一流 (stdout) 读取和写入。所以我假设您的意图是捕获应用程序创建的所有 stdout/stderr 消息(例如从 3rd 方模块进行日志记录)。在这种情况下，最好将所有记录器配置为将消息传播到父记录器，并添加一个根记录器以您选择的方式记录数据。

如果日志结构比较复杂，我推荐使用logging_tree发现:

import logging_tree
import nose
logging_tree.printout()
...

所以我们得到了记录器o<--"nose" 级别 NOTSET 所以继承级别 WARNING

import logging
logging.getLogger("nose").propagate = True
logging.getLogger().addHandler(<Your handler>)
logging.getLogger().setLevel(logging.DEBUG)

现在任何时候 Nose 记录任何东西，也会收到这条消息。我推荐Python Advanced Logging Tutorial ，在处理大型项目时会很有帮助。