[New-bugs-announce] [issue34999] Different behavior of copied loggers in 3.7

[sebix]

New submission from sebix <sebix+bugs.python.org at sebix.at>:

For the unittests of project I mock the function returning the logger. The code to tests can re-initialize the logger because of updated configuration (It's a deamon), so it needs to do that correctly and I test if it works. By mocking the function returning I can always control the loggers's and parameters and always return a copy of the same logger. This worked until 3.6 but does no longer work in 3.7 (I tested 3.7.1rc2).
Why do I copy it? Because if the tested program sets (for example) a different log level, that would affect my "master copy".

I created a minimal example splitted into two files, the code to test and the test itself.

The tested code:

------
def log(log_level):
    pass


class Bot(object):
    def __init__(self):
        self.logger = None
        self.__init_logger(logging_level='INFO')
        self.logger.info('Initialized')
        self.logger.handlers = []  # remove all existing handlers
        self.__init_logger(logging_level='DEBUG')
        self.logger.debug('test')
        self.logger.info("Bot stopped.")

    def __init_logger(self, logging_level):
        self.logger = log(log_level=logging_level)
-----

And the test:
-----
import copy
import io
import logging
import unittest.mock as mock

from intelmq.bot import Bot


bot_id = 'test-bot'
log_stream = io.StringIO()

logger = logging.getLogger(bot_id)
logger.setLevel("INFO")
console_formatter = logging.Formatter('%(levelname)s - %(message)s')
console_handler = logging.StreamHandler(log_stream)
console_handler.setFormatter(console_formatter)
logger.addHandler(console_handler)


def mocked_log(log_level):
    # Return a copy as the bot may modify the logger and we should always return the intial logger
    logger_new = copy.copy(logger)
    logger_new.setLevel(log_level)
    return logger_new


with mock.patch('intelmq.bot.log', mocked_log):
    bot = Bot()
loglines_buffer = log_stream.getvalue()
loglines = loglines_buffer.splitlines()
print(loglines_buffer)

print("INFO - Initialized" in loglines[0])
print('DEBUG - test' in loglines_buffer)
print("INFO - Bot stopped." in loglines[-1])
-----
Adapt the import of the "Bot" if you try to run it.

In Python 3.4-3.6 it gives:

-----
INFO - Initialized
DEBUG - test
INFO - Bot stopped.

True
True
True
-----

And in Python 3.7:
-------
INFO - Initialized

True
False
False
-------

The minimal code is also here: https://github.com/wagner-certat/intelmq/tree/minimal-1269

----------
components: Library (Lib)
messages: 327838
nosy: sebix
priority: normal
severity: normal
status: open
title: Different behavior of copied loggers in 3.7
versions: Python 3.7

_______________________________________
Python tracker <report at bugs.python.org>
<https://bugs.python.org/issue34999>
_______________________________________