python 记录器的线程行为异常

标签 python logging python-multithreading

我正在使用 python 2.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

我查看了这个 stackoverflow thread但这里没有答案。

我看不到错误的零件代码...

最佳答案

这个重复的东西其实和threading没有任何关系，而是与此相关的一切 for loop生成线程并运行 mainFunction与每个线程。在每次迭代中，当您认为正在创建新的记录器对象时，实际上您只是引用相同的记录器对象，因为您提供了相同的记录器名称(在本例中为“root”)。但您还在每次迭代时向此记录器对象添加更多处理程序。所以在迭代 i = 0 ，您有 1 个记录器对象、1 个文件处理程序和 1 个流处理程序。但是当你点击迭代i = 1时，您现在仍然有 1 个记录器对象，但有 2 个文件处理程序(指向同一个文件)和 2 个流处理程序。这意味着在迭代结束时 i = 1 ，您已将 3 行添加到文件中，并将 3 行打印到标准流中。按照这个递增逻辑，到第五次迭代结束时，您将得到 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 做得更好的东西。模块，但可能还有更多的东西。我只是不知道。

我希望这会有所帮助。

关于python 记录器的线程行为异常，我们在Stack Overflow上找到一个类似的问题： https://stackoverflow.com/questions/43558829/

上一篇：python - 使用 PyPDF2 合并两个 pdf 文件时出错

下一篇：python - 如何在 jinja2 中打印一行字典？

相关文章：

java - 在 Apache 服务器中维护日志文件

python - Python中是否有参数锁定机制？

python - 如何在Python中的特定时间间隔后运行一个方法？

python - 跨线程更新观察者模式(非阻塞)

Python单元测试: Assertion Error issue

javascript - 如何使用点符号将 console.log 方法添加到 JavaScript 中的数组和对象原型(prototype)？

python - numpy ValueError 形状未对齐

java - Log4j2 - 找到配置，但无法正常工作

python - 跨数据框列应用 'or' 条件- Pandas

python - 将 RSA 解密函数从 Golang 翻译成 Python

©2024 IT工具网  联系我们