[issue34999] Different behavior of copied loggers in 3.7

[Serhiy Storchaka]

Serhiy Storchaka  added the comment:

This is a consequence of implementing pickling for loggers in issue30520.

It would be surprising if pickling/unpickling and deep copying preserve 
identity, but shallow copying creates a new object.

--
nosy: +serhiy.storchaka

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34999] Different behavior of copied loggers in 3.7

[Vinay Sajip]

Vinay Sajip  added the comment:

This doesn't appear to be inherently a logging problem - it seems to be a 
change in how copy.copy() is working. If you update mocked_log to insert some 
statements showing the id of the loggers involved in the copy:

def mocked_log(log_level):
# Return a copy as the bot may modify the logger and we should always 
return the intial logger
print('copying   %x' % id(logger))
assert logger.handlers
logger_new = copy.copy(logger)
logger_new.setLevel(log_level)
print('copied to %x' % id(logger_new))
return logger_new

Then under Python3.6 you get something like

copying   7f2682b3a780
copied to 7f268145bc50
copying   7f2682b3a780
copied to 7f268145bcf8
INFO - Initialized
DEBUG - test
INFO - Bot stopped.

Note the different ids of the copy source and target, and that the assertion 
failure isn't triggered. Under 3.7, you get

copying   7f7084171b38
copied to 7f7084171b38
copying   7f7084171b38
Traceback (most recent call last):
  File "test.py", line 31, in 
bot = Bot()
  File "/home/vinay/projects/scratch/python/34999/bot.py", line 12, in __init__
self.__init_logger(logging_level='DEBUG')
  File "/home/vinay/projects/scratch/python/34999/bot.py", line 17, in 
__init_logger
self.logger = log(log_level=logging_level)
  File "test.py", line 23, in mocked_log
assert logger.handlers
AssertionError

So - copy.copy() hasn't actually made a copy of the logger, it's returned the 
original. I'm not sure why this is.

--

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34999] Different behavior of copied loggers in 3.7

[Ned Deily]

Change by Ned Deily :


--
nosy: +vinay.sajip

___
Python tracker 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com

[issue34999] Different behavior of copied loggers in 3.7

[sebix]

New submission from sebix :

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 

___
___
Python-bugs-list mailing list
Unsubscribe: 
https://mail.python.org/mailman/options/python-bugs-list/archive%40mail-archive.com