From 783cc7b16a2733df27383bf2e525ff10d9bbdb61 Mon Sep 17 00:00:00 2001 From: Irit Katriel Date: Mon, 5 Oct 2020 15:20:06 +0100 Subject: [PATCH 1/4] bpo-41898: Fix bug where assertLogs doesn't correctly filter messages by level --- Lib/unittest/_log.py | 1 + Lib/unittest/test/test_case.py | 12 ++++++++++++ 2 files changed, 13 insertions(+) diff --git a/Lib/unittest/_log.py b/Lib/unittest/_log.py index 961c448a7fb356..94868e5bb95eb3 100644 --- a/Lib/unittest/_log.py +++ b/Lib/unittest/_log.py @@ -47,6 +47,7 @@ def __enter__(self): logger = self.logger = logging.getLogger(self.logger_name) formatter = logging.Formatter(self.LOGGING_FORMAT) handler = _CapturingHandler() + handler.setLevel(self.level) handler.setFormatter(formatter) self.watcher = handler.watcher self.old_handlers = logger.handlers[:] diff --git a/Lib/unittest/test/test_case.py b/Lib/unittest/test/test_case.py index 0e416967a30861..b8aca92a8ebe9f 100644 --- a/Lib/unittest/test/test_case.py +++ b/Lib/unittest/test/test_case.py @@ -1673,6 +1673,18 @@ def testAssertLogsFailureLevelTooHigh(self): with self.assertLogs(level='WARNING'): log_foo.info("1") + def testAssertLogsFailureLevelTooHigh_FilterInRootLogger(self): + # Failure due to level too high - message propagated to root + with self.assertNoStderr(): + oldLevel = log_foo.level + log_foo.setLevel(logging.INFO) + try: + with self.assertRaises(self.failureException): + with self.assertLogs(level='WARNING'): + log_foo.info("1") + finally: + log_foo.setLevel(oldLevel) + def testAssertLogsFailureMismatchingLogger(self): # Failure due to mismatching logger (and the logged message is # passed through) From 35d016ba11c1ec2c57e3575c16df3ba6f76dc9b1 Mon Sep 17 00:00:00 2001 From: Irit Katriel Date: Wed, 7 Oct 2020 00:03:01 +0100 Subject: [PATCH 2/4] revert fix in unittest, and fix in logging. Two previous tests (test_config7_ok, test_config_8a_ok) are still failing --- Lib/logging/__init__.py | 15 +++++++++------ Lib/test/test_logging.py | 34 +++++++++++++++++++++++++++++++--- Lib/unittest/_log.py | 1 - 3 files changed, 40 insertions(+), 10 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 787cb4eefa1061..9f6bfd2a3d2c07 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -1662,14 +1662,17 @@ def callHandlers(self, record): c = self found = 0 while c: - for hdlr in c.handlers: - found = found + 1 - if record.levelno >= hdlr.level: - hdlr.handle(record) - if not c.propagate: + if not c.isEnabledFor(record.levelno): c = None #break out else: - c = c.parent + for hdlr in c.handlers: + found = found + 1 + if record.levelno >= hdlr.level: + hdlr.handle(record) + if not c.propagate: + c = None #break out + else: + c = c.parent if (found == 0): if lastResort: if record.levelno >= lastResort.level: diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 4cd8c7e25daa93..b726832c152105 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -331,6 +331,28 @@ def test_regression_29220(self): self.assertEqual(logging.getLevelName(logging.NOTSET), 'NOTSET') self.assertEqual(logging.getLevelName('NOTSET'), logging.NOTSET) + def test_issue_41943(self): + """See issue #41943 for more information.""" + m = self.next_message + ROOT = logging.getLogger() + self.addCleanup(ROOT.setLevel, ROOT.level) + ROOT.setLevel(logging.WARNING) + CHILD = logging.getLogger("CHILD") + self.addCleanup(CHILD.setLevel, CHILD.level) + CHILD.setLevel(logging.INFO) + + # This should log. + CHILD.warning(m()) + + # These should not log. + CHILD.debug(m()) + CHILD.info(m()) + + self.assert_log_lines([ + ('CHILD', 'WARNING', '1'), + ]) + + class BasicFilterTest(BaseTest): """Test the bundled Filter class.""" @@ -2073,14 +2095,20 @@ def test_persistent_loggers(self): # if visible references are destroyed. self.root_logger.setLevel(logging.INFO) foo = logging.getLogger("foo") - self._watch_for_survival(foo) + foo_stream = io.StringIO() + foo_hdlr = logging.StreamHandler(foo_stream) + foo_hdlr.setFormatter(logging.Formatter(self.log_format)) + foo.addHandler(foo_hdlr) + + self._watch_for_survival(foo, foo_hdlr) foo.setLevel(logging.DEBUG) self.root_logger.debug(self.next_message()) foo.debug(self.next_message()) self.assert_log_lines([ ('foo', 'DEBUG', '2'), - ]) + ], stream=foo.handlers[0].stream) del foo + del foo_hdlr # foo has survived. self._assertTruesurvival() # foo has retained its settings. @@ -2089,7 +2117,7 @@ def test_persistent_loggers(self): self.assert_log_lines([ ('foo', 'DEBUG', '2'), ('foo', 'DEBUG', '3'), - ]) + ], stream=bar.handlers[0].stream) class EncodingTest(BaseTest): diff --git a/Lib/unittest/_log.py b/Lib/unittest/_log.py index 94868e5bb95eb3..961c448a7fb356 100644 --- a/Lib/unittest/_log.py +++ b/Lib/unittest/_log.py @@ -47,7 +47,6 @@ def __enter__(self): logger = self.logger = logging.getLogger(self.logger_name) formatter = logging.Formatter(self.LOGGING_FORMAT) handler = _CapturingHandler() - handler.setLevel(self.level) handler.setFormatter(formatter) self.watcher = handler.watcher self.old_handlers = logger.handlers[:] From 9638eea7159e7a505fa9d3040769e44b7c48102d Mon Sep 17 00:00:00 2001 From: Irit Katriel Date: Wed, 7 Oct 2020 18:42:25 +0100 Subject: [PATCH 3/4] Revert "revert fix in unittest, and fix in logging. Two previous tests (test_config7_ok, test_config_8a_ok) are still failing" This reverts commit 35d016ba11c1ec2c57e3575c16df3ba6f76dc9b1. --- Lib/logging/__init__.py | 15 ++++++--------- Lib/test/test_logging.py | 34 +++------------------------------- Lib/unittest/_log.py | 1 + 3 files changed, 10 insertions(+), 40 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 9f6bfd2a3d2c07..787cb4eefa1061 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -1662,17 +1662,14 @@ def callHandlers(self, record): c = self found = 0 while c: - if not c.isEnabledFor(record.levelno): + for hdlr in c.handlers: + found = found + 1 + if record.levelno >= hdlr.level: + hdlr.handle(record) + if not c.propagate: c = None #break out else: - for hdlr in c.handlers: - found = found + 1 - if record.levelno >= hdlr.level: - hdlr.handle(record) - if not c.propagate: - c = None #break out - else: - c = c.parent + c = c.parent if (found == 0): if lastResort: if record.levelno >= lastResort.level: diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index b726832c152105..4cd8c7e25daa93 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -331,28 +331,6 @@ def test_regression_29220(self): self.assertEqual(logging.getLevelName(logging.NOTSET), 'NOTSET') self.assertEqual(logging.getLevelName('NOTSET'), logging.NOTSET) - def test_issue_41943(self): - """See issue #41943 for more information.""" - m = self.next_message - ROOT = logging.getLogger() - self.addCleanup(ROOT.setLevel, ROOT.level) - ROOT.setLevel(logging.WARNING) - CHILD = logging.getLogger("CHILD") - self.addCleanup(CHILD.setLevel, CHILD.level) - CHILD.setLevel(logging.INFO) - - # This should log. - CHILD.warning(m()) - - # These should not log. - CHILD.debug(m()) - CHILD.info(m()) - - self.assert_log_lines([ - ('CHILD', 'WARNING', '1'), - ]) - - class BasicFilterTest(BaseTest): """Test the bundled Filter class.""" @@ -2095,20 +2073,14 @@ def test_persistent_loggers(self): # if visible references are destroyed. self.root_logger.setLevel(logging.INFO) foo = logging.getLogger("foo") - foo_stream = io.StringIO() - foo_hdlr = logging.StreamHandler(foo_stream) - foo_hdlr.setFormatter(logging.Formatter(self.log_format)) - foo.addHandler(foo_hdlr) - - self._watch_for_survival(foo, foo_hdlr) + self._watch_for_survival(foo) foo.setLevel(logging.DEBUG) self.root_logger.debug(self.next_message()) foo.debug(self.next_message()) self.assert_log_lines([ ('foo', 'DEBUG', '2'), - ], stream=foo.handlers[0].stream) + ]) del foo - del foo_hdlr # foo has survived. self._assertTruesurvival() # foo has retained its settings. @@ -2117,7 +2089,7 @@ def test_persistent_loggers(self): self.assert_log_lines([ ('foo', 'DEBUG', '2'), ('foo', 'DEBUG', '3'), - ], stream=bar.handlers[0].stream) + ]) class EncodingTest(BaseTest): diff --git a/Lib/unittest/_log.py b/Lib/unittest/_log.py index 961c448a7fb356..94868e5bb95eb3 100644 --- a/Lib/unittest/_log.py +++ b/Lib/unittest/_log.py @@ -47,6 +47,7 @@ def __enter__(self): logger = self.logger = logging.getLogger(self.logger_name) formatter = logging.Formatter(self.LOGGING_FORMAT) handler = _CapturingHandler() + handler.setLevel(self.level) handler.setFormatter(formatter) self.watcher = handler.watcher self.old_handlers = logger.handlers[:] From e4f169edaa4fb482430b12f13b519772dccd5391 Mon Sep 17 00:00:00 2001 From: "blurb-it[bot]" <43283697+blurb-it[bot]@users.noreply.github.com> Date: Wed, 7 Oct 2020 18:36:05 +0000 Subject: [PATCH 4/4] =?UTF-8?q?=F0=9F=93=9C=F0=9F=A4=96=20Added=20by=20blu?= =?UTF-8?q?rb=5Fit.?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit --- .../NEWS.d/next/Library/2020-10-07-18-36-03.bpo-41943.Pt55fT.rst | 1 + 1 file changed, 1 insertion(+) create mode 100644 Misc/NEWS.d/next/Library/2020-10-07-18-36-03.bpo-41943.Pt55fT.rst diff --git a/Misc/NEWS.d/next/Library/2020-10-07-18-36-03.bpo-41943.Pt55fT.rst b/Misc/NEWS.d/next/Library/2020-10-07-18-36-03.bpo-41943.Pt55fT.rst new file mode 100644 index 00000000000000..3a7874d25aef06 --- /dev/null +++ b/Misc/NEWS.d/next/Library/2020-10-07-18-36-03.bpo-41943.Pt55fT.rst @@ -0,0 +1 @@ +Fix bug where TestCase.assertLogs doesn't correctly filter messages by level. \ No newline at end of file