From 68461c164914eade1ddee1d56f819c61db013c9b Mon Sep 17 00:00:00 2001 From: Shahar Naveh <50263213+ShaharNaveh@users.noreply.github.com> Date: Mon, 11 May 2026 18:42:54 +0300 Subject: [PATCH] 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 | 39 +++----- Lib/logging/config.py | 14 ++- Lib/logging/handlers.py | 24 ++++- Lib/test/test_logging.py | 203 +++++++++++++++++++++++++++++++-------- 4 files changed, 210 insertions(+), 70 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 357d127c0..9005f1ef8 100644 --- a/Lib/logging/__init__.py +++ b/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 diff --git a/Lib/logging/config.py b/Lib/logging/config.py index 190b4f922..3d9aa00fa 100644 --- a/Lib/logging/config.py +++ b/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): diff --git a/Lib/logging/handlers.py b/Lib/logging/handlers.py index d3ea06c73..4a07258f8 100644 --- a/Lib/logging/handlers.py +++ b/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. diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index ef52f1477..083934d31 100644 --- a/Lib/test/test_logging.py +++ b/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('')) + self.assertStartsWith(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)