Python logging with ptb: Same line logged twice but only one handler added

Question

• python: 3.6.6
• python-telegram-bot: 10.0.2

I have this problem: I have defined a python logger with a SMTPHandler, a TimedRotatingFileHandler and a StreamHandler.

The StreamHandler works fine, but when I try to use it from a python-telegram-bot handler, the line is being printed twice on the standard output with two different formats and I can't find out how to avoid one and get the another one (the timed one) to remain.

I have discovered the cause. When adding a ConversationHandler with a CallbackQueryHandler, this message is shown when starting.

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

And then the unwished log line appears every time.

The code is here below as log_config.py . I have added also the sample code for testing my_main_file.py and the current output as a multiline comment.

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 includes several logging calls that use logging.warning instead of the self.logger logger they probably should use, such as 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 and the other module-level logging convenience functions call logging.basicConfig, which adds a handler to the root logger if no handlers on the root logger are present. This handler is the one responsible for the unwanted

INFO:__main__:HELP!

logging output.

The use of logging.warning instead of self.logger.warning should probably be considered a python-telegram-bot bug. I don't see an open issue for it on their issue tracker, so you might want to file a bug report.

In the meantime, or if the python-telegram-bot developers decide the behavior is fine, you can add a null handler to the root logger to prevent basicConfig from adding its own handler. This must be done before the ConversationHandler is created, to preempt the basicConfig:

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