使用 ptb : Same line logged twice but only one handler added 进行 Python 日志记录

Question

• python :3.6.6
• python-电报机器人:10.0.2

我有这个问题:我定义了一个带有 SMTPHandler、TimedRotatingFileHandler 和 StreamHandler 的 python 记录器。

StreamHandler 工作正常，但是当我尝试从 python-telegram-bot 处理程序使用它时，该行以两种不同的格式在标准输出上打印两次，我无法找到如何避免一个和让另一个(定时的)留下来。

我已经找到原因了。添加带有 CallbackQueryHandler 的 ConversationHandler 时，此消息会在启动时显示。

WARNING:root:If 'per_message=False', 'CallbackQueryHandler' will not be tracked for every message.

然后每次都会出现不需要的日志行。

下面的代码是 log_config.py 。我还添加了用于测试 my_main_file.py 的示例代码和作为多行注释的当前输出。

config/log_config.py:

import os

import logging
from logging import Formatter

from datetime import datetime


VERSION_NUM = '1.2.0'
LOG_MSG_FORMAT = '%(asctime)s - ({0}) %(levelname)s - %(name)s - %(message)s'
LOGFILE_PATH = os.path.join(os.path.dirname(os.path.dirname(__file__)),
                            'log',
                            'alfred.log')
logging.getLogger('telegram').setLevel(logging.WARNING)
logging.getLogger('chardet.charsetprober').setLevel(logging.WARNING)


def my_timezone_time(*args):
    # I simplified this line, because it's irrelevant
    return datetime.now().timetuple()


handlers = []


#
# ... different handlers added
#


# last handler to add, this one works just as I want

ch = logging.StreamHandler()
formatter = Formatter(LOG_MSG_FORMAT.format(VERSION_NUM))
formatter.converter = my_timezone_time
ch.setFormatter(formatter)
ch.setLevel(logging.INFO)
handlers.append(ch)


def getLogger(name):
    """
    Returns a logger for the file. Works fine but when used,
       it always outputs the same line with the last handler 
       and also with an unknown handler not added by me 
       (must be some default instance)
    :param name: the file name
    :return: a logger
    """
    logger = logging.getLogger(name)
    logger.setLevel(logging.DEBUG)
    for h in handlers:
        logger.addHandler(h)

    return logger

my_main_file.py:

#!/usr/bin/python3
from telegram.ext import (Updater, CommandHandler, ConversationHandler,
                          run_async, CallbackQueryHandler)
from config.log_config import getLogger

# Enable logging
logger = getLogger(__name__)

updater = Updater('......')  # Replace with your bot token

# ************************** HANDLERS
# Define a few command handlers. These usually take the two arguments bot and
# update. Error handlers also receive the raised TelegramError object in error.


@run_async
def show_help(bot, update):
    logger.info('HELP!')


def error_handler(bot, update, error):
    logger.warning('La actualización "%s" causó el error "%s"', update, error)


def dumb_handler(bot, update, user_data):
    return ConversationHandler.END


def main():
    """Start the bot."""
    # Create the EventHandler and pass it your bot's token.
    global updater

    # Get the dispatcher to register handlers
    dp = updater.dispatcher

    # on different commands - answer in Telegram
    dp.add_handler(CommandHandler('help', show_help))

    # Add conversation handler with the states
    # The telegram conversation handler needs a handler_list with functions
    # so it can execute desired code in each state/step

    conv_handler = ConversationHandler(
        entry_points=[CommandHandler('irrelevant', dumb_handler,
                                     pass_user_data=True)
                      ],
        states={
            0: [CallbackQueryHandler(dumb_handler, pass_user_data=True)],
        },
        fallbacks=[],
    )
    dp.add_handler(conv_handler)

    # log all errors
    dp.add_error_handler(error_handler)

    updater.start_polling()
    updater.idle()


if __name__ == '__main__':
    main()

"""
OUTPUT when used /help from the bot chat
(First is my wished output, second is the line I want to avoid)
------

2018-11-08 16:41:51,115 - (1.2.0) INFO - __main__ - HELP!
INFO:__main__:HELP!
"""

Answer 1

telegram.ext.ConversationHandler 包括几个使用 logging.warning 而不是他们可能应该使用的 self.logger 记录器的记录调用，例如this call :

for handler in all_handlers:
    if isinstance(handler, CallbackQueryHandler):
        logging.warning("If 'per_message=False', 'CallbackQueryHandler' will not be "
                        "tracked for every message.")

logging.warning 和其他模块级日志记录便利函数调用 logging.basicConfig ，如果根记录器上没有处理程序，它会向根记录器添加一个处理程序。该处理程序负责处理不需要的内容

INFO:__main__:HELP!

记录输出。

使用 logging.warning 而不是 self.logger.warning 应该被认为是一个 python-telegram-bot 错误。我在他们的 issue tracker 上没有看到它的未解决问题，因此您可能想要提交错误报告。

与此同时，或者如果 python-telegram-bot 开发人员认为行为正常，您可以向根记录器添加一个空处理程序以防止 basicConfig 添加自己的处理程序。这必须在创建 ConversationHandler 之前完成，以抢占 basicConfig:

logging.getLogger().addHandler(logging.NullHandler())