带有线程错误行为的python记录器

Question

我使用python2.7将一些包含在线程调用中的消息登录到文件中。然而，我没有让消息1次，而是日志发生了3次。嗯，我设定了一个范围等于5，然而，消息发生了15次。

以下是代码：

import sys
import logging
import threading  
import logging.handlers
import time 
import os 

ETT="TVAR 1"
objectname="TVAR 2"
URLFORLOG="TVAR 3"

def setup_custom_logger(name):
    fileLogName='visualreclogfile.log'
    #formatter = logging.Formatter(fmt='%(asctime)s - %(levelname)s - %(module)s - %(message)s')
    formatter = logging.Formatter(fmt='%(asctime)s - %(levelname)s - %(message)s')

    handlerCH = logging.StreamHandler()
    handlerCH.setFormatter(formatter)

    handlerFILE = logging.handlers.RotatingFileHandler(fileLogName, maxBytes=(1048576*5), backupCount=7)
    handlerFILE.setFormatter(formatter)


    logger = logging.getLogger(name)
    logger.setLevel(logging.INFO)

    logger.addHandler(handlerCH)
    logger.addHandler(handlerFILE)

    return logger

def LoggingFileForELK(MessageToBeLogged):
    logger = setup_custom_logger('root')
    logger.info(MessageToBeLogged)


def mainFunction():
    Messages=("*** CONTENT LOGGING *** OBJECT UUID : %s WITH NAME KEY : %s HAS URL : %s ") %(ETT,objectname,URLFORLOG)
    MessageToBeLogged=str(Messages)
    LoggingFileForELK(MessageToBeLogged)





threads = []
for i in range(5):
    t = threading.Thread(target=mainFunction)
    threads.append(t)
    t.start()
    time.sleep(0.5)
for  t in threads:
    t.join()

以下是我的研究结果：

2017-04-22 12:36:59,010 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3
2017-04-22 12:36:59,512 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3
2017-04-22 12:36:59,512 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3
2017-04-22 12:37:00,018 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3
2017-04-22 12:37:00,018 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3
2017-04-22 12:37:00,018 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3
2017-04-22 12:37:00,520 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3
2017-04-22 12:37:00,520 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3
2017-04-22 12:37:00,520 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3
2017-04-22 12:37:00,520 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3
2017-04-22 12:37:01,022 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3
2017-04-22 12:37:01,022 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3
2017-04-22 12:37:01,022 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3
2017-04-22 12:37:01,022 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3
2017-04-22 12:37:01,022 - INFO - *** CONTENT LOGGING *** OBJECT UUID : TVAR 1 WITH NAME KEY : TVAR 2 HAS URL : TVAR 3

我看了这个堆叠溢出的thread，但这里没有回答。

我看不出错误的代码..。

Answer 1

这种重复的事情实际上与threading无关，而是与生成线程并与每个线程一起运行mainFunction的for loop有关。在每次迭代时，当您认为您正在创建一个新的记录器对象时，实际上您只是引用同一个记录器对象，因为您提供的是相同的记录器名称(在本例中是“root”)。但是，在每次迭代时，您也要向这个记录器对象添加更多的处理程序。因此，在迭代i = 0中，您有一个记录器对象、一个文件处理程序和一个流处理程序。但是，当您进入迭代i = 1时，现在仍然有一个记录器对象，但是有两个文件处理程序(指向同一个文件)和两个流处理程序。这意味着，到迭代i = 1结束时，您已经将3行添加到文件中，3行打印到标准流中。按照这个递增逻辑，到第5次迭代结束时，您将得到1个记录器对象、5个文件处理程序和5个流处理程序。本质上，这就是文件中和标准流中重复行后面的内容。

修复方法是重新定义setup_custom_logger函数，以便只在记录器对象不存在时生成新的处理程序。基本上，您必须有某种形式的容器(在本例中是字典)来跟踪您创建的记录器及其处理程序。如果使用已经存在的记录器名称调用setup_custom_logger，则该函数将只返回现有的记录器；但否则它将生成一个新的记录器及其处理程序。

我已经修改了您的脚本以添加修补程序：

import sys
import logging
import threading
import logging.handlers
import time
import os

ETT="TVAR 1"
objectname="TVAR 2"
URLFORLOG="TVAR 3"

# container to keep track of loggers
loggers = {}

def setup_custom_logger(name):
    global loggers
    # return existing logger if it exists
    if name in loggers:
        return loggers.get(name)
    else:   # else, create a new logger with handlers
        fileLogName='visualreclogfile.log'
        #formatter = logging.Formatter(fmt='%(asctime)s - %(levelname)s - %(module)s - %(message)s')
        formatter = logging.Formatter(fmt='%(asctime)s - %(levelname)s - %(message)s')

        handlerCH = logging.StreamHandler()
        handlerCH.setFormatter(formatter)

        handlerFILE = logging.handlers.RotatingFileHandler(fileLogName, maxBytes=(1048576*5), backupCount=7)
        handlerFILE.setFormatter(formatter)


        logger = logging.getLogger(name)
        logger.setLevel(logging.INFO)

        logger.addHandler(handlerCH)
        logger.addHandler(handlerFILE)
        loggers[name] = logger
        return logger

def LoggingFileForELK(MessageToBeLogged):
    logger = setup_custom_logger('root')
    logger.info(MessageToBeLogged)


def mainFunction():
    Messages=("*** CONTENT LOGGING *** OBJECT UUID : %s WITH NAME KEY : %s HAS URL : %s ") %(ETT,objectname,URLFORLOG)
    MessageToBeLogged=str(Messages)
    LoggingFileForELK(MessageToBeLogged)




threads = []
for i in range(5):
    t = threading.Thread(target=mainFunction)
    t.start()
    threads.append(t)
    time.sleep(0.1)
for  t in threads:
    t.join()

编辑：

这是记录器及其句柄的正常行为。即使没有线程，只要您引用相同的记录器并向其添加处理程序，它的行为也将是相同的。这里的问题是for loop，而不是threading进程。如果从脚本中删除threading部件，仍然会得到重复的行。例如，以下内容将返回与原始线程版本相同的行数：

import sys
import logging
import threading
import logging.handlers
import time
import os

ETT="TVAR 1"
objectname="TVAR 2"
URLFORLOG="TVAR 3"

def setup_custom_logger(name):
    fileLogName='visualreclogfile.log'
    #formatter = logging.Formatter(fmt='%(asctime)s - %(levelname)s - %(module)s - %(message)s')
    formatter = logging.Formatter(fmt='%(asctime)s - %(levelname)s - %(message)s')

    handlerCH = logging.StreamHandler()
    handlerCH.setFormatter(formatter)

    handlerFILE = logging.handlers.RotatingFileHandler(fileLogName, maxBytes=(1048576*5), backupCount=7)
    handlerFILE.setFormatter(formatter)


    logger = logging.getLogger(name)
    logger.setLevel(logging.INFO)

    logger.addHandler(handlerCH)
    logger.addHandler(handlerFILE)

    return logger

def LoggingFileForELK(MessageToBeLogged):
    logger = setup_custom_logger('root')
    logger.info(MessageToBeLogged)


def mainFunction():
    Messages=("*** CONTENT LOGGING *** OBJECT UUID : %s WITH NAME KEY : %s HAS URL : %s ") %(ETT,objectname,URLFORLOG)
    MessageToBeLogged=str(Messages)
    LoggingFileForELK(MessageToBeLogged)




for i in range(5):
    mainFunction()

这表明，导致日志处理不正常的不是(线程)，而是在每次迭代时向记录器对象添加新处理程序的过程，而不是。底线是：logging在很大程度上是线程感知的，并且可以与任何线程应用程序正常工作，只要不复制不必要的处理程序。我对其他比logging模块做得更好的东西并不熟悉，但是可能会有更好的事情发生。我只是不知道有什么。

我希望这能帮到你。