[fix] Adapt to setuptools>=65.6.0 logging on root

INFO logs from setuptools which were previously not emitted because
setuptool's ad-hoc legacy logger defaulted to WARNING and above may
now be emitted because setuptools now logs to the root logger, thus
the global root logger's level configuration applied.

This caused undesired 'root: <some setuptools info>' messages to be
emitted and caused many tests to fail due to unexpected outputs.

src/zc/buildout/buildout.py

@@ -1275,21 +1275,33 @@ class Buildout(DictMixin):
                     timeout)
 
     def _setup_logging(self):
-        root_logger = logging.getLogger()
-        self._logger = logging.getLogger('zc.buildout')
-        handler = logging.StreamHandler(sys.stdout)
+        # Note that setuptols >= 65.6.0 emits INFO logs directly to the root.
+
         log_format = self['buildout']['log-format']
-        if not log_format:
-            # No format specified. Use different formatter for buildout
-            # and other modules, showing logger name except for buildout
-            log_format = '%(name)s: %(message)s'
-            buildout_handler = logging.StreamHandler(sys.stdout)
-            buildout_handler.setFormatter(logging.Formatter('%(message)s'))
-            self._logger.propagate = False
-            self._logger.addHandler(buildout_handler)
-
-        handler.setFormatter(logging.Formatter(log_format))
-        root_logger.addHandler(handler)
+        generic_log_format = log_format or '%(name)s: %(message)s'
+        buildout_log_format = log_format or '%(message)s'
+
+        root_logger = logging.getLogger()
+        self._logger = buildout_logger = logging.getLogger('zc.buildout')
+
+        # root-specific WARNING handler because setuptools>=65.6.0 logs to root
+        root_handler = logging.StreamHandler(sys.stdout)
+        root_handler.setLevel(logging.WARNING)
+        root_handler.addFilter(lambda record: record.name == 'root')
+        root_handler.setFormatter(logging.Formatter(generic_log_format))
+        root_logger.addHandler(root_handler)
+
+        # generic handler for third-party logs
+        generic_handler = logging.StreamHandler(sys.stdout)
+        generic_handler.addFilter(lambda record: record.name != 'root')
+        generic_handler.setFormatter(logging.Formatter(generic_log_format))
+        root_logger.addHandler(generic_handler)
+
+        # buildout handler for buildout logs
+        buildout_handler = logging.StreamHandler(sys.stdout)
+        buildout_handler.setFormatter(logging.Formatter(buildout_log_format))
+        buildout_logger.propagate = False
+        buildout_logger.addHandler(buildout_handler)
 
         level = self['buildout']['log-level']
         if level in ('DEBUG', 'INFO', 'WARNING', 'ERROR', 'CRITICAL'):

src/zc/buildout/testing.py

@@ -615,6 +615,8 @@ normalize_open_in_generated_script = (
 
 not_found = (re.compile(r'Not found: [^\n]+/(\w|\.)+/\r?\n'), '')
 
+root_logger_messages = (re.compile(r'^(root: )+', re.MULTILINE), '')
+
 python27_warning = (re.compile(r'DEPRECATION: Python 2.7 reached the end of its '
     'life on January 1st, 2020. Please upgrade your Python as Python 2.7 is no '
     'longer maintained. A future version of pip will drop support for Python '

src/zc/buildout/tests/test_all.py

@@ -3937,6 +3937,7 @@ def test_suite():
                     zc.buildout.testing.normalize_script,
                     zc.buildout.testing.normalize_egg_py,
                     zc.buildout.testing.not_found,
+                    zc.buildout.testing.root_logger_messages,
                     zc.buildout.testing.adding_find_link,
                     zc.buildout.testing.python27_warning,
                     zc.buildout.testing.python27_warning_2,
@@ -3988,6 +3989,7 @@ def test_suite():
                zc.buildout.testing.normalize_script,
                zc.buildout.testing.normalize_egg_py,
                zc.buildout.testing.not_found,
+               zc.buildout.testing.root_logger_messages,
                zc.buildout.testing.adding_find_link,
                zc.buildout.testing.easyinstall_deprecated,
                zc.buildout.testing.setuptools_deprecated,
@@ -4030,6 +4032,7 @@ def test_suite():
                 zc.buildout.testing.normalize_endings,
                 zc.buildout.testing.normalize_exception_type_for_python_2_and_3,
                 zc.buildout.testing.not_found,
+                zc.buildout.testing.root_logger_messages,
                 zc.buildout.testing.adding_find_link,
                 zc.buildout.testing.easyinstall_deprecated,
                 zc.buildout.testing.setuptools_deprecated,
@@ -4057,6 +4060,7 @@ def test_suite():
                 zc.buildout.testing.normalize_script,
                 zc.buildout.testing.normalize_egg_py,
                 zc.buildout.testing.not_found,
+                zc.buildout.testing.root_logger_messages,
                 zc.buildout.testing.adding_find_link,
                 zc.buildout.testing.easyinstall_deprecated,
                 zc.buildout.testing.setuptools_deprecated,
@@ -4093,6 +4097,7 @@ def test_suite():
                 zc.buildout.testing.normalize_open_in_generated_script,
                 zc.buildout.testing.adding_find_link,
                 zc.buildout.testing.not_found,
+                zc.buildout.testing.root_logger_messages,
                 zc.buildout.testing.python27_warning,
                 zc.buildout.testing.python27_warning_2,
                 zc.buildout.testing.easyinstall_deprecated,
@@ -4122,6 +4127,7 @@ def test_suite():
             checker=renormalizing.RENormalizing([
               zc.buildout.testing.normalize_exception_type_for_python_2_and_3,
               zc.buildout.testing.not_found,
+              zc.buildout.testing.root_logger_messages,
               zc.buildout.testing.adding_find_link,
               zc.buildout.testing.easyinstall_deprecated,
               zc.buildout.testing.setuptools_deprecated,
@@ -4146,6 +4152,7 @@ def test_suite():
                 zc.buildout.testing.normalize_egg_py,
                 zc.buildout.testing.normalize___pycache__,
                 zc.buildout.testing.not_found,
+                zc.buildout.testing.root_logger_messages,
                 zc.buildout.testing.normalize_exception_type_for_python_2_and_3,
                 zc.buildout.testing.adding_find_link,
                 zc.buildout.testing.python27_warning,
@@ -4204,6 +4211,7 @@ def test_suite():
                zc.buildout.testing.normalize_script,
                zc.buildout.testing.normalize_egg_py,
                zc.buildout.testing.not_found,
+               zc.buildout.testing.root_logger_messages,
                zc.buildout.testing.adding_find_link,
                zc.buildout.testing.easyinstall_deprecated,
                zc.buildout.testing.setuptools_deprecated,
@@ -4294,6 +4302,7 @@ def test_suite():
                zc.buildout.testing.normalize_endings,
                zc.buildout.testing.normalize_script,
                zc.buildout.testing.not_found,
+               zc.buildout.testing.root_logger_messages,
                normalize_bang,
                zc.buildout.testing.adding_find_link,
                (re.compile('Downloading.*setuptools.*egg\n'), ''),

src/zc/buildout/tests/test_extras.py

@@ -74,6 +74,7 @@ def test_suite():
             zc.buildout.testing.normalize_egg_py,
             zc.buildout.testing.normalize___pycache__,
             zc.buildout.testing.not_found,
+            zc.buildout.testing.root_logger_messages,
             zc.buildout.testing.normalize_exception_type_for_python_2_and_3,
             zc.buildout.testing.adding_find_link,
             zc.buildout.testing.python27_warning,

src/zc/buildout/tests/test_increment.py

@@ -402,6 +402,7 @@ def test_suite():
             zc.buildout.testing.normalize_egg_py,
             zc.buildout.testing.normalize___pycache__,
             zc.buildout.testing.not_found,
+            zc.buildout.testing.root_logger_messages,
             zc.buildout.testing.normalize_exception_type_for_python_2_and_3,
             zc.buildout.testing.adding_find_link,
             zc.buildout.testing.python27_warning,

src/zc/buildout/tests/testing_bugfix.txt

@@ -4,9 +4,9 @@ Bug fixes in zc.buildout.testing
 Logging handler which did not get deleted
 -----------------------------------------
 
-The buildout testing set up runs a buildout which adds a
+The buildout testing set up runs a buildout which adds two
 ``logging.StreamHandler`` to the root logger. But tear down did not
-remove it. This can disturb other tests of packages reusing
+remove them. This can disturb other tests of packages reusing
 zc.buildout.testing.
 
 The handlers before calling set up are:
@@ -16,19 +16,19 @@ The handlers before calling set up are:
     >>> logging.getLogger().handlers # doctest: +ELLIPSIS
     [<...NullHandler...>]
 
-After calling it, a ``logging.StreamHandler`` was added:
+After calling it, two ``logging.StreamHandler`` were added:
 
     >>> import zc.buildout.testing
     >>> import doctest
     >>> test = doctest.DocTestParser().get_doctest(
     ...     '>>> x', {}, 'foo', 'foo.py', 0)
     >>> zc.buildout.testing.buildoutSetUp(test)
-    >>> len(logging.getLogger().handlers) == count + 1
+    >>> len(logging.getLogger().handlers) == count + 2
     True
     >>> logging.getLogger().handlers # doctest: +ELLIPSIS +NORMALIZE_WHITESPACE
-    [<...NullHandler...StreamHandler...>]
+    [<...NullHandler...StreamHandler...StreamHandler...>]
 
-But tear down removes the new logging handler:
+But tear down removes the new logging handlers:
 
     >>> zc.buildout.testing.buildoutTearDown(test)
     >>> len(logging.getLogger().handlers) == count

zc.recipe.egg_/src/zc/recipe/egg/tests.py

@@ -49,6 +49,7 @@ def test_suite():
                zc.buildout.tests.normalize_bang,
                zc.buildout.tests.normalize_S,
                zc.buildout.testing.not_found,
+               zc.buildout.testing.root_logger_messages,
                zc.buildout.testing.python27_warning,
                zc.buildout.testing.python27_warning_2,
                zc.buildout.testing.easyinstall_deprecated,
@@ -71,6 +72,7 @@ def test_suite():
                zc.buildout.testing.normalize_path,
                zc.buildout.testing.normalize_endings,
                zc.buildout.testing.not_found,
+               zc.buildout.testing.root_logger_messages,
                zc.buildout.testing.python27_warning,
                zc.buildout.testing.python27_warning_2,
                zc.buildout.testing.easyinstall_deprecated,
@@ -98,6 +100,7 @@ def test_suite():
                zc.buildout.testing.normalize_path,
                zc.buildout.testing.normalize_endings,
                zc.buildout.testing.not_found,
+               zc.buildout.testing.root_logger_messages,
                ])
             ),
         doctest.DocFileSuite(
@@ -112,6 +115,7 @@ def test_suite():
                zc.buildout.tests.normalize_bang,
                zc.buildout.tests.normalize_S,
                zc.buildout.testing.not_found,
+               zc.buildout.testing.root_logger_messages,
                zc.buildout.testing.easy_install_deprecated,
                (re.compile(r'[d-]  zc.buildout(-\S+)?[.]egg(-link)?'),
                 'zc.buildout.egg'),
@@ -131,6 +135,7 @@ def test_suite():
                     zc.buildout.testing.normalize_path,
                     zc.buildout.testing.normalize_endings,
                     zc.buildout.testing.not_found,
+                    zc.buildout.testing.root_logger_messages,
                     zc.buildout.testing.python27_warning,
                     zc.buildout.testing.python27_warning_2,
                     zc.buildout.testing.easyinstall_deprecated,