python避坑指南02——logging模块日志重复打印问题

Posted 2020-11-02 滚滚向前滚

目录

[TOC]

一、问题抛出

        python的logging模块是python使用过程中打印日志的利器。我们可以使用logging模块的logger、Handler、formatter对我们的日志进行封装，指定日志输出的路径、格式以及位置。在声明logger的时候可以传一个字符串作为这个logger的标签。一直以为这个logger是以单例对象的设计模式设计的，只要这个标签名是一样的，那么返回的logger就是同一个。在打印日志的时候，想要实现日志分层，定义类如下函数来封装日志打印函数（由于源代码已经修改，用伪代码形式）

def print_log_info(msg):
    # Logger是我定义的一个类，用来封装日志打印的
    logger = Logger(‘INFO‘).getLogger()
    logger.info(msg)

        在测试用例中用到了ddt，将测试用例参数化。关键代码如下：

    @data(*test_datas[‘test_add‘])
    @unpack
    def test_add(self, *args, **kwargs):
        data_path, err_num, test_id, p1, p2, value = args
        result = Test(p1, p2).add()
        try:
            self.assertEqual(result, value, "在{err_num}行用例编号为{test_id}的测试中加法错误，请重新输入" .format(
                err_num = err_num,
                test_id = test_id
            ))
            utils.print_log_info("在{err_num}行用例编号为{test_id}的测试中加法测试成功".format(err_num = err_num,test_id = test_id))
        except AssertionError as err:
            err_str = traceback.format_exc()
            raise err

        执行完测试用例后，发现一条测试用例打印了多条，并且，重复打印次数由1一直增加到n（博主比较懒，这是源代码出现的问题截图）。

二、问题解决

        一开始，一直以为是ddt的bug。但后来直接在外部定义了一个logger，调用这个logger打印日志的时候，发现日志没有重复打印的情况，而当我偶然的情况下，两次声明了同一个logger的情况下，发现日志打印了两次。便开始思考这是不是logging模块本身的问题，由于第一章的代码中，每次打印日志，都需要print_log_info()函数，这个函数每次调用时，都申明了一次logger。每一条测试用例执行完，都需要打印日志，再声明一次logger，那么声明logger的次数就是1累计增加到n，是不是和我们上面重复日志打印的情况类似？所以考虑问题的出现是由重复声明logger造成的。为了验证猜想，对代码做如下修改（源代码太长，粘部分关键代码）。

info_logger = Logger(‘INFO‘).get_logger()
error_logger = Logger(‘ERROR‘).get_logger()

def print_log_info(msg):
    ‘‘‘
    打印测试用例执行的正常信息以及控制台日志
    :param msg:需要打印的信息
    :return:
    ‘‘‘
    # 获取函数调用者的信息
    caller_module, msg_lineno = trace_caller(2)
    edit_msg = ‘[%s] : [%s]     %s‘ % (caller_module, msg_lineno, msg)
    print(edit_msg)
    info_logger.info(edit_msg)

def print_log_error(msg):
    ‘‘‘
    用例出错时，打印错误日志以及控制台输出
    :param msg: 需要打印的信息
    :return:
    ‘‘‘
    edit_msg = msg
    error_logger.error(edit_msg)

测试用例中，与第一章同样的方式调用日志打印的代码，得到日志如下，重复日志的bug已经解决：

[2018-04-30 Monday 12:00:45] [INFO] [MainThread:28980] [src\test\case\testExample.py] : [82]     在3行用例编号为test_add01的测试中加法测试成功
[2018-04-30 Monday 12:00:45] [ERROR] [MainThread:28980] 
文件：data\calculator.xls中测试用例出错
出错用例行：4，用例编号：test_add02
Traceback (most recent call last):
  File "C:\Users\Think\PycharmProjects\InterfaceFrame\src\test\case\testExample.py", line 80, in test_add
    test_id = test_id
  File "C:\Python33\lib\unittest\case.py", line 641, in assertEqual
    assertion_func(first, second, msg=msg)
  File "C:\Python33\lib\unittest\case.py", line 634, in _baseAssertEqual
    raise self.failureException(msg)
AssertionError: 3 != 4 : 在4行用例编号为test_add02的测试中加法错误，请重新输入

[2018-04-30 Monday 12:00:45] [INFO] [MainThread:28980] [src\test\case\testExample.py] : [82]     在5行用例编号为test_add03的测试中加法测试成功
[2018-04-30 Monday 12:00:45] [INFO] [MainThread:28980] [src\test\case\testExample.py] : [82]     在6行用例编号为test_add04的测试中加法测试成功
[2018-04-30 Monday 12:00:45] [INFO] [MainThread:28980] [src\test\case\testExample.py] : [160]     在15行用例编号为test_div01的测试中除法测试成功
[2018-04-30 Monday 12:00:45] [INFO] [MainThread:28980] [src\test\case\testExample.py] : [160]     在16行用例编号为test_div02的测试中除法测试成功
[2018-04-30 Monday 12:00:45] [INFO] [MainThread:28980] [src\test\case\testExample.py] : [160]     在17行用例编号为test_div03的测试中除法测试成功
[2018-04-30 Monday 12:00:45] [INFO] [MainThread:28980] [src\test\case\testExample.py] : [160]     在18行用例编号为test_div04的测试中除法测试成功
[2018-04-30 Monday 12:00:45] [INFO] [MainThread:28980] [src\test\case\testExample.py] : [135]     在11行用例编号为test_multi01的测试中乘法测试成功
[2018-04-30 Monday 12:00:45] [INFO] [MainThread:28980] [src\test\case\testExample.py] : [135]     在12行用例编号为test_multi02的测试中乘法测试成功
[2018-04-30 Monday 12:00:45] [INFO] [MainThread:28980] [src\test\case\testExample.py] : [135]     在13行用例编号为test_multi03的测试中乘法测试成功