Update logging to 3.14.4 (#7820)

* Update `test_logging.py` to 3.14.4

* Update `logging` to 3.14.4  /

Lib/logging/__init__.py

@@ -1475,8 +1475,6 @@ class Logger(Filterer):
     level, and "input.csv", "input.xls" and "input.gnu" for the sub-levels.
     There is no arbitrary limit to the depth of nesting.
     """
-    _tls = threading.local()
-
     def __init__(self, name, level=NOTSET):
         """
         Initialize the logger with a name and an optional level.
@@ -1673,19 +1671,14 @@ class Logger(Filterer):
         This method is used for unpickled records received from a socket, as
         well as those created locally. Logger-level filtering is applied.
         """
-        if self._is_disabled():
+        if self.disabled:
             return
-
-        self._tls.in_progress = True
-        try:
-            maybe_record = self.filter(record)
-            if not maybe_record:
-                return
-            if isinstance(maybe_record, LogRecord):
-                record = maybe_record
-            self.callHandlers(record)
-        finally:
-            self._tls.in_progress = False
+        maybe_record = self.filter(record)
+        if not maybe_record:
+            return
+        if isinstance(maybe_record, LogRecord):
+            record = maybe_record
+        self.callHandlers(record)
 
     def addHandler(self, hdlr):
         """
@@ -1773,7 +1766,7 @@ class Logger(Filterer):
         """
         Is this logger enabled for level 'level'?
         """
-        if self._is_disabled():
+        if self.disabled:
             return False
 
         try:
@@ -1823,11 +1816,6 @@ class Logger(Filterer):
                        if isinstance(item, Logger) and item.parent is self and
                        _hierlevel(item) == 1 + _hierlevel(item.parent))
 
-    def _is_disabled(self):
-        # We need to use getattr as it will only be set the first time a log
-        # message is recorded on any given thread
-        return self.disabled or getattr(self._tls, 'in_progress', False)
-
     def __repr__(self):
         level = getLevelName(self.getEffectiveLevel())
         return '<%s %s (%s)>' % (self.__class__.__name__, self.name, level)
@@ -1864,9 +1852,9 @@ class LoggerAdapter(object):
 
     def __init__(self, logger, extra=None, merge_extra=False):
         """
-        Initialize the adapter with a logger and a dict-like object which
-        provides contextual information. This constructor signature allows
-        easy stacking of LoggerAdapters, if so desired.
+        Initialize the adapter with a logger and an optional dict-like object
+        which provides contextual information. This constructor signature
+        allows easy stacking of LoggerAdapters, if so desired.
 
         You can effectively pass keyword arguments as shown in the
         following example:
@@ -1897,8 +1885,9 @@ class LoggerAdapter(object):
         Normally, you'll only need to override this one method in a
         LoggerAdapter subclass for your specific needs.
         """
-        if self.merge_extra and "extra" in kwargs:
-            kwargs["extra"] = {**self.extra, **kwargs["extra"]}
+        if self.merge_extra and kwargs.get("extra") is not None:
+            if self.extra is not None:
+                kwargs["extra"] = {**self.extra, **kwargs["extra"]}
         else:
             kwargs["extra"] = self.extra
         return msg, kwargs

Lib/logging/config.py

@@ -865,6 +865,8 @@ class DictConfigurator(BaseConfigurator):
             else:
                 factory = klass
         kwargs = {k: config[k] for k in config if (k != '.' and valid_ident(k))}
+        # When deprecation ends for using the 'strm' parameter, remove the
+        # "except TypeError ..."
         try:
             result = factory(**kwargs)
         except TypeError as te:
@@ -876,6 +878,15 @@ class DictConfigurator(BaseConfigurator):
             #(e.g. by Django)
             kwargs['strm'] = kwargs.pop('stream')
             result = factory(**kwargs)
+
+            import warnings
+            warnings.warn(
+                "Support for custom logging handlers with the 'strm' argument "
+                "is deprecated and scheduled for removal in Python 3.16. "
+                "Define handlers with the 'stream' argument instead.",
+                DeprecationWarning,
+                stacklevel=2,
+            )
         if formatter:
             result.setFormatter(formatter)
         if level is not None:
@@ -1006,7 +1017,8 @@ def listen(port=DEFAULT_LOGGING_CONFIG_PORT, verify=None):
         A simple TCP socket-based logging config receiver.
         """
 
-        allow_reuse_address = 1
+        allow_reuse_address = True
+        allow_reuse_port = False
 
         def __init__(self, host='localhost', port=DEFAULT_LOGGING_CONFIG_PORT,
                      handler=None, ready=None, verify=None):

Lib/logging/handlers.py

@@ -196,7 +196,11 @@ class RotatingFileHandler(BaseRotatingHandler):
         if self.stream is None:                 # delay was set...
             self.stream = self._open()
         if self.maxBytes > 0:                   # are we rolling over?
-            pos = self.stream.tell()
+            try:
+                pos = self.stream.tell()
+            except io.UnsupportedOperation:
+                # gh-143237: Never rollover a named pipe.
+                return False
             if not pos:
                 # gh-116263: Never rollover an empty file
                 return False
@@ -855,7 +859,7 @@ class SysLogHandler(logging.Handler):
     }
 
     def __init__(self, address=('localhost', SYSLOG_UDP_PORT),
-                 facility=LOG_USER, socktype=None):
+                 facility=LOG_USER, socktype=None, timeout=None):
         """
         Initialize a handler.
 
@@ -872,6 +876,7 @@ class SysLogHandler(logging.Handler):
         self.address = address
         self.facility = facility
         self.socktype = socktype
+        self.timeout = timeout
         self.socket = None
         self.createSocket()
 
@@ -933,6 +938,8 @@ class SysLogHandler(logging.Handler):
                 err = sock = None
                 try:
                     sock = socket.socket(af, socktype, proto)
+                    if self.timeout:
+                        sock.settimeout(self.timeout)
                     if socktype == socket.SOCK_STREAM:
                         sock.connect(sa)
                     break
@@ -1529,6 +1536,19 @@ class QueueListener(object):
         self._thread = None
         self.respect_handler_level = respect_handler_level
 
+    def __enter__(self):
+        """
+        For use as a context manager. Starts the listener.
+        """
+        self.start()
+        return self
+
+    def __exit__(self, *args):
+        """
+        For use as a context manager. Stops the listener.
+        """
+        self.stop()
+
     def dequeue(self, block):
         """
         Dequeue a record and return it, optionally blocking.

Lib/test/test_logging.py

@@ -22,8 +22,10 @@ import logging
 import logging.handlers
 import logging.config
 
+
 import codecs
 import configparser
+import contextlib
 import copy
 import datetime
 import pathlib
@@ -680,9 +682,6 @@ class HandlerTest(BaseTest):
             os.unlink(fn)
 
     @unittest.skipIf(os.name == 'nt', 'WatchedFileHandler not appropriate for Windows.')
-    @unittest.skipIf(
-        support.is_emscripten, "Emscripten cannot fstat unlinked files."
-    )
     @threading_helper.requires_working_threading()
     @support.requires_resource('walltime')
     def test_race(self):
@@ -732,11 +731,11 @@ class HandlerTest(BaseTest):
     # based on os.fork existing because that is what users and this test use.
     # This helps ensure that when fork exists (the important concept) that the
     # register_at_fork mechanism is also present and used.
+    @unittest.skip("TODO: RUSTPYTHON; Flaky")
     @support.requires_fork()
     @threading_helper.requires_working_threading()
     @skip_if_asan_fork
     @skip_if_tsan_fork
-    @unittest.skip("TODO: RUSTPYTHON; Flaky")
     def test_post_fork_child_no_deadlock(self):
         """Ensure child logging locks are not held; bpo-6721 & bpo-36533."""
         class _OurHandler(logging.Handler):
@@ -1039,6 +1038,7 @@ class TestTCPServer(ControlMixin, ThreadingTCPServer):
     """
 
     allow_reuse_address = True
+    allow_reuse_port = False
 
     def __init__(self, addr, handler, poll_interval=0.5,
                  bind_and_activate=True):
@@ -1137,7 +1137,7 @@ class SMTPHandlerTest(BaseTest):
         self.assertEqual(mailfrom, 'me')
         self.assertEqual(rcpttos, ['you'])
         self.assertIn('\nSubject: Log\n', data)
-        self.assertTrue(data.endswith('\n\nHello \u2713'))
+        self.assertEndsWith(data, '\n\nHello \u2713')
         h.close()
 
     def process_message(self, *args):
@@ -2098,6 +2098,18 @@ class SysLogHandlerTest(BaseTest):
         self.handled.wait(support.LONG_TIMEOUT)
         self.assertEqual(self.log_output, b'<11>sp\xc3\xa4m\x00')
 
+    @patch('socket.socket')
+    def test_tcp_timeout(self, mock_socket):
+        instance_mock_sock = mock_socket.return_value
+        instance_mock_sock.connect.side_effect = socket.timeout
+
+        with self.assertRaises(socket.timeout):
+            logging.handlers.SysLogHandler(address=('localhost', 514),
+                                           socktype=socket.SOCK_STREAM,
+                                           timeout=1)
+
+        instance_mock_sock.close.assert_called()
+
 @unittest.skipUnless(hasattr(socket, "AF_UNIX"), "Unix sockets required")
 class UnixSysLogHandlerTest(SysLogHandlerTest):
 
@@ -3271,6 +3283,37 @@ class ConfigDictTest(BaseTest):
         }
     }
 
+    # Remove when deprecation ends.
+    class DeprecatedStrmHandler(logging.StreamHandler):
+        def __init__(self, strm=None):
+            super().__init__(stream=strm)
+
+    config_custom_handler_with_deprecated_strm_arg = {
+        "version": 1,
+        "formatters": {
+            "form1": {
+                "format": "%(levelname)s ++ %(message)s",
+            },
+        },
+        "handlers": {
+            "hand1": {
+                "class": DeprecatedStrmHandler,
+                "formatter": "form1",
+                "level": "NOTSET",
+                "stream": "ext://sys.stdout",
+            },
+        },
+        "loggers": {
+            "compiler.parser": {
+                "level": "DEBUG",
+                "handlers": ["hand1"],
+            },
+        },
+        "root": {
+            "level": "WARNING",
+        },
+    }
+
     def apply_config(self, conf):
         logging.config.dictConfig(conf)
 
@@ -3360,6 +3403,15 @@ class ConfigDictTest(BaseTest):
         self.test_config1_ok(config=self.config5)
         self.check_handler('hand1', CustomHandler)
 
+    def test_deprecation_warning_custom_handler_with_strm_arg(self):
+        msg = (
+            "Support for custom logging handlers with the 'strm' argument "
+            "is deprecated and scheduled for removal in Python 3.16. "
+            "Define handlers with the 'stream' argument instead."
+        )
+        with self.assertWarnsRegex(DeprecationWarning, msg):
+            self.test_config1_ok(config=self.config_custom_handler_with_deprecated_strm_arg)
+
     def test_config6_failure(self):
         self.assertRaises(Exception, self.apply_config, self.config6)
 
@@ -3527,7 +3579,7 @@ class ConfigDictTest(BaseTest):
             self.assertEqual(h.foo, 'bar')
             self.assertEqual(h.terminator, '!\n')
             logging.warning('Exclamation')
-            self.assertTrue(output.getvalue().endswith('Exclamation!\n'))
+            self.assertEndsWith(output.getvalue(), 'Exclamation!\n')
 
     def test_config15_ok(self):
 
@@ -4057,9 +4109,8 @@ class ConfigDictTest(BaseTest):
         # log a message (this creates a record put in the queue)
         logging.getLogger().info(message_to_log)
 
-    @unittest.skip('TODO: RUSTPYTHON, flaky EOFError')
-    # TODO: RUSTPYTHON - SemLock not implemented on Windows
-    @unittest.expectedFailureIfWindows("TODO: RUSTPYTHON")
+    @unittest.skip("TODO: RUSTPYTHON; flaky EOFError")
+    @unittest.expectedFailureIfWindows("TODO: RUSTPYTHON; SemLock not implemented on Windows")
     @skip_if_tsan_fork
     @support.requires_subprocess()
     def test_multiprocessing_queues(self):
@@ -4287,7 +4338,7 @@ class QueueHandlerTest(BaseTest):
         msg = self.next_message()
         self.que_logger.warning(msg)
         data = self.queue.get_nowait()
-        self.assertTrue(isinstance(data, logging.LogRecord))
+        self.assertIsInstance(data, logging.LogRecord)
         self.assertEqual(data.name, self.que_logger.name)
         self.assertEqual((data.msg, data.args), (msg, None))
 
@@ -4338,17 +4389,27 @@ class QueueHandlerTest(BaseTest):
         self.assertTrue(handler.matches(levelno=logging.CRITICAL, message='6'))
         handler.close()
 
+    def test_queue_listener_context_manager(self):
+        handler = TestHandler(support.Matcher())
+        with logging.handlers.QueueListener(self.queue, handler) as listener:
+            self.assertIsInstance(listener, logging.handlers.QueueListener)
+            self.assertIsNotNone(listener._thread)
+        self.assertIsNone(listener._thread)
+
         # doesn't hurt to call stop() more than once.
         listener.stop()
         self.assertIsNone(listener._thread)
 
     def test_queue_listener_multi_start(self):
         handler = TestHandler(support.Matcher())
-        listener = logging.handlers.QueueListener(self.queue, handler)
+        with logging.handlers.QueueListener(self.queue, handler) as listener:
+            self.assertRaises(RuntimeError, listener.start)
+
+        with listener:
+            self.assertRaises(RuntimeError, listener.start)
+
         listener.start()
-        self.assertRaises(RuntimeError, listener.start)
         listener.stop()
-        self.assertIsNone(listener._thread)
 
     def test_queue_listener_with_StreamHandler(self):
         # Test that traceback and stack-info only appends once (bpo-34334, bpo-46755).
@@ -4574,7 +4635,7 @@ class FormatterTest(unittest.TestCase, AssertErrorMessage):
         f = logging.Formatter('${asctime}--', style='$')
         self.assertTrue(f.usesTime())
 
-    @unittest.expectedFailure # TODO: RUSTPYTHON; ValueError: Unexpected error parsing format string
+    @unittest.expectedFailure  # TODO: RUSTPYTHON; ValueError: Unexpected error parsing format string
     def test_format_validate(self):
         # Check correct formatting
         # Percentage style
@@ -4887,19 +4948,19 @@ class ExceptionTest(BaseTest):
         r.addHandler(h)
         try:
             raise RuntimeError('deliberate mistake')
-        except:
+        except RuntimeError:
             logging.exception('failed', stack_info=True)
         r.removeHandler(h)
         h.close()
         r = h.records[0]
-        self.assertTrue(r.exc_text.startswith('Traceback (most recent '
-                                              'call last):\n'))
-        self.assertTrue(r.exc_text.endswith('\nRuntimeError: '
-                                            'deliberate mistake'))
-        self.assertTrue(r.stack_info.startswith('Stack (most recent '
-                                              'call last):\n'))
-        self.assertTrue(r.stack_info.endswith('logging.exception(\'failed\', '
-                                            'stack_info=True)'))
+        self.assertStartsWith(r.exc_text,
+                'Traceback (most recent call last):\n')
+        self.assertEndsWith(r.exc_text,
+                '\nRuntimeError: deliberate mistake')
+        self.assertStartsWith(r.stack_info,
+                'Stack (most recent call last):\n')
+        self.assertEndsWith(r.stack_info,
+                "logging.exception('failed', stack_info=True)")
 
 
 class LastResortTest(BaseTest):
@@ -5242,8 +5303,8 @@ class LogRecordTest(BaseTest):
     def test_str_rep(self):
         r = logging.makeLogRecord({})
         s = str(r)
-        self.assertTrue(s.startswith('<LogRecord: '))
-        self.assertTrue(s.endswith('>'))
+        self.assertStartsWith(s, '<LogRecord: ')
+        self.assertEndsWith(s, '>')
 
     def test_dict_arg(self):
         h = RecordingHandler()
@@ -5365,7 +5426,7 @@ class LogRecordTest(BaseTest):
                 logging.logAsyncioTasks = False
                 runner.run(make_record(self.assertIsNone))
         finally:
-            asyncio.set_event_loop_policy(None)
+            asyncio.events._set_event_loop_policy(None)
 
     @support.requires_working_socket()
     def test_taskName_without_asyncio_imported(self):
@@ -5377,7 +5438,7 @@ class LogRecordTest(BaseTest):
                 logging.logAsyncioTasks = False
                 runner.run(make_record(self.assertIsNone))
         finally:
-            asyncio.set_event_loop_policy(None)
+            asyncio.events._set_event_loop_policy(None)
 
 
 class BasicConfigTest(unittest.TestCase):
@@ -5681,7 +5742,7 @@ class BasicConfigTest(unittest.TestCase):
                 data = f.read().strip()
             self.assertRegex(data, r'Task-\d+ - hello world')
         finally:
-            asyncio.set_event_loop_policy(None)
+            asyncio.events._set_event_loop_policy(None)
             if handler:
                 handler.close()
 
@@ -5744,7 +5805,7 @@ class LoggerAdapterTest(unittest.TestCase):
 
         self.addCleanup(cleanup)
         self.addCleanup(logging.shutdown)
-        self.adapter = logging.LoggerAdapter(logger=self.logger, extra=None)
+        self.adapter = logging.LoggerAdapter(logger=self.logger)
 
     def test_exception(self):
         msg = 'testing exception: %r'
@@ -5893,14 +5954,14 @@ class LoggerAdapterTest(unittest.TestCase):
         self.adapter.critical('foo should be here')
         self.assertEqual(len(self.recording.records), 1)
         record = self.recording.records[0]
-        self.assertTrue(hasattr(record, 'foo'))
+        self.assertHasAttr(record, 'foo')
         self.assertEqual(record.foo, '1')
 
     def test_extra_not_merged_by_default(self):
         self.adapter.critical('foo should NOT be here', extra={'foo': 'nope'})
         self.assertEqual(len(self.recording.records), 1)
         record = self.recording.records[0]
-        self.assertFalse(hasattr(record, 'foo'))
+        self.assertNotHasAttr(record, 'foo')
 
     def test_extra_merged(self):
         self.adapter = logging.LoggerAdapter(logger=self.logger,
@@ -5910,11 +5971,23 @@ class LoggerAdapterTest(unittest.TestCase):
         self.adapter.critical('foo and bar should be here', extra={'bar': '2'})
         self.assertEqual(len(self.recording.records), 1)
         record = self.recording.records[0]
-        self.assertTrue(hasattr(record, 'foo'))
-        self.assertTrue(hasattr(record, 'bar'))
+        self.assertHasAttr(record, 'foo')
+        self.assertHasAttr(record, 'bar')
         self.assertEqual(record.foo, '1')
         self.assertEqual(record.bar, '2')
 
+        self.adapter.critical('no extra')  # should not fail
+        self.assertEqual(len(self.recording.records), 2)
+        record = self.recording.records[-1]
+        self.assertEqual(record.foo, '1')
+        self.assertNotHasAttr(record, 'bar')
+
+        self.adapter.critical('none extra', extra=None)  # should not fail
+        self.assertEqual(len(self.recording.records), 3)
+        record = self.recording.records[-1]
+        self.assertEqual(record.foo, '1')
+        self.assertNotHasAttr(record, 'bar')
+
     def test_extra_merged_log_call_has_precedence(self):
         self.adapter = logging.LoggerAdapter(logger=self.logger,
                                              extra={'foo': '1'},
@@ -5923,9 +5996,28 @@ class LoggerAdapterTest(unittest.TestCase):
         self.adapter.critical('foo shall be min', extra={'foo': '2'})
         self.assertEqual(len(self.recording.records), 1)
         record = self.recording.records[0]
-        self.assertTrue(hasattr(record, 'foo'))
+        self.assertHasAttr(record, 'foo')
         self.assertEqual(record.foo, '2')
 
+    def test_extra_merged_without_extra(self):
+        self.adapter = logging.LoggerAdapter(logger=self.logger,
+                                             merge_extra=True)
+
+        self.adapter.critical('foo should be here', extra={'foo': '1'})
+        self.assertEqual(len(self.recording.records), 1)
+        record = self.recording.records[-1]
+        self.assertEqual(record.foo, '1')
+
+        self.adapter.critical('no extra')  # should not fail
+        self.assertEqual(len(self.recording.records), 2)
+        record = self.recording.records[-1]
+        self.assertNotHasAttr(record, 'foo')
+
+        self.adapter.critical('none extra', extra=None)  # should not fail
+        self.assertEqual(len(self.recording.records), 3)
+        record = self.recording.records[-1]
+        self.assertNotHasAttr(record, 'foo')
+
 
 class PrefixAdapter(logging.LoggerAdapter):
     prefix = 'Adapter'
@@ -6256,6 +6348,32 @@ class RotatingFileHandlerTest(BaseFileTest):
         self.assertFalse(rh.shouldRollover(self.next_rec()))
         rh.close()
 
+    @unittest.skipUnless(hasattr(os, "mkfifo"), 'requires os.mkfifo()')
+    def test_should_not_rollover_named_pipe(self):
+        # gh-143237 - test with non-seekable special file (named pipe)
+        filename = os_helper.TESTFN
+        self.addCleanup(os_helper.unlink, filename)
+        try:
+            os.mkfifo(filename)
+        except PermissionError as e:
+            self.skipTest('os.mkfifo(): %s' % e)
+
+        data = 'not read'
+        def other_side():
+            nonlocal data
+            with open(filename, 'rb') as f:
+                data = f.read()
+
+        thread = threading.Thread(target=other_side)
+        with threading_helper.start_threads([thread]):
+            rh = logging.handlers.RotatingFileHandler(
+                    filename, encoding="utf-8", maxBytes=1)
+            with contextlib.closing(rh):
+                m = self.next_rec()
+                self.assertFalse(rh.shouldRollover(m))
+                rh.emit(m)
+        self.assertEqual(data.decode(), m.msg + os.linesep)
+
     def test_should_rollover(self):
         with open(self.fn, 'wb') as f:
             f.write(b'\n')
@@ -6637,18 +6755,19 @@ class TimedRotatingFileHandlerTest(BaseFileTest):
                 p = '%s.log.' % prefix
                 for c in candidates:
                     d, fn = os.path.split(c)
-                    self.assertTrue(fn.startswith(p))
+                    self.assertStartsWith(fn, p)
             elif prefix.startswith('d.e'):
                 for c in candidates:
                     d, fn = os.path.split(c)
-                    self.assertTrue(fn.endswith('.log'), fn)
-                    self.assertTrue(fn.startswith(prefix + '.') and
-                                    fn[len(prefix) + 2].isdigit())
+                    self.assertEndsWith(fn, '.log')
+                    self.assertStartsWith(fn, prefix + '.')
+                    self.assertTrue(fn[len(prefix) + 2].isdigit())
             elif prefix == 'g':
                 for c in candidates:
                     d, fn = os.path.split(c)
-                    self.assertTrue(fn.endswith('.oldlog'))
-                    self.assertTrue(fn.startswith('g') and fn[1].isdigit())
+                    self.assertEndsWith(fn, '.oldlog')
+                    self.assertStartsWith(fn, 'g')
+                    self.assertTrue(fn[1].isdigit())
 
     def test_compute_files_to_delete_same_filename_different_extensions(self):
         # See GH-93205 for background
@@ -6683,10 +6802,10 @@ class TimedRotatingFileHandlerTest(BaseFileTest):
             rotator = rotators[i]
             candidates = rotator.getFilesToDelete()
             self.assertEqual(len(candidates), n_files - backupCount, candidates)
-            matcher = re.compile(r"^\d{4}-\d{2}-\d{2}_\d{2}-\d{2}-\d{2}\Z")
+            matcher = re.compile(r"^\d{4}-\d{2}-\d{2}_\d{2}-\d{2}-\d{2}\z")
             for c in candidates:
                 d, fn = os.path.split(c)
-                self.assertTrue(fn.startswith(prefix+'.'))
+                self.assertStartsWith(fn, prefix+'.')
                 suffix = fn[(len(prefix)+1):]
                 self.assertRegex(suffix, matcher)