From 61439e9b07635e89494bb91c662a8b466b5aca69 Mon Sep 17 00:00:00 2001 From: ShaharNaveh <50263213+ShaharNaveh@users.noreply.github.com> Date: Sat, 19 Jul 2025 14:13:08 +0200 Subject: [PATCH 1/5] Update logging from 3.13.5 --- Lib/logging/__init__.py | 234 +++++++++++----------- Lib/logging/config.py | 63 +++--- Lib/logging/handlers.py | 131 +++++++------ Lib/test/test_logging.py | 409 +++++++++++++++++++++++++++++---------- 4 files changed, 514 insertions(+), 323 deletions(-) diff --git a/Lib/logging/__init__.py b/Lib/logging/__init__.py index 28df075dcd6..357d127c090 100644 --- a/Lib/logging/__init__.py +++ b/Lib/logging/__init__.py @@ -56,7 +56,7 @@ # #_startTime is used as the base when calculating the relative time of events # -_startTime = time.time() +_startTime = time.time_ns() # #raiseExceptions is used to see if exceptions during handling should be @@ -159,12 +159,9 @@ def addLevelName(level, levelName): This is used when converting levels to text during message formatting. """ - _acquireLock() - try: #unlikely to cause an exception, but you never know... + with _lock: _levelToName[level] = levelName _nameToLevel[levelName] = level - finally: - _releaseLock() if hasattr(sys, "_getframe"): currentframe = lambda: sys._getframe(1) @@ -201,7 +198,7 @@ def _is_internal_frame(frame): """Signal whether the frame is a CPython or logging module internal.""" filename = os.path.normcase(frame.f_code.co_filename) return filename == _srcfile or ( - "importlib" in filename and "_bootstrap" in filename + "importlib" in filename and "_bootstrap" in filename ) @@ -231,21 +228,27 @@ def _checkLevel(level): # _lock = threading.RLock() -def _acquireLock(): +def _prepareFork(): """ - Acquire the module-level lock for serializing access to shared data. + Prepare to fork a new child process by acquiring the module-level lock. - This should be released with _releaseLock(). + This should be used in conjunction with _afterFork(). """ - if _lock: + # Wrap the lock acquisition in a try-except to prevent the lock from being + # abandoned in the event of an asynchronous exception. See gh-106238. + try: _lock.acquire() + except BaseException: + _lock.release() + raise -def _releaseLock(): +def _afterFork(): """ - Release the module-level lock acquired by calling _acquireLock(). + After a new child process has been forked, release the module-level lock. + + This should be used in conjunction with _prepareFork(). """ - if _lock: - _lock.release() + _lock.release() # Prevent a held logging lock from blocking a child from logging. @@ -260,23 +263,20 @@ def _register_at_fork_reinit_lock(instance): _at_fork_reinit_lock_weakset = weakref.WeakSet() def _register_at_fork_reinit_lock(instance): - _acquireLock() - try: + with _lock: _at_fork_reinit_lock_weakset.add(instance) - finally: - _releaseLock() def _after_at_fork_child_reinit_locks(): for handler in _at_fork_reinit_lock_weakset: handler._at_fork_reinit() - # _acquireLock() was called in the parent before forking. + # _prepareFork() was called in the parent before forking. # The lock is reinitialized to unlocked state. _lock._at_fork_reinit() - os.register_at_fork(before=_acquireLock, + os.register_at_fork(before=_prepareFork, after_in_child=_after_at_fork_child_reinit_locks, - after_in_parent=_releaseLock) + after_in_parent=_afterFork) #--------------------------------------------------------------------------- @@ -300,7 +300,7 @@ def __init__(self, name, level, pathname, lineno, """ Initialize a logging record with interesting information. """ - ct = time.time() + ct = time.time_ns() self.name = name self.msg = msg # @@ -322,7 +322,7 @@ def __init__(self, name, level, pathname, lineno, # Thus, while not removing the isinstance check, it does now look # for collections.abc.Mapping rather than, as before, dict. if (args and len(args) == 1 and isinstance(args[0], collections.abc.Mapping) - and args[0]): + and args[0]): args = args[0] self.args = args self.levelname = getLevelName(level) @@ -339,9 +339,17 @@ def __init__(self, name, level, pathname, lineno, self.stack_info = sinfo self.lineno = lineno self.funcName = func - self.created = ct - self.msecs = int((ct - int(ct)) * 1000) + 0.0 # see gh-89047 - self.relativeCreated = (self.created - _startTime) * 1000 + self.created = ct / 1e9 # ns to float seconds + # Get the number of whole milliseconds (0-999) in the fractional part of seconds. + # Eg: 1_677_903_920_999_998_503 ns --> 999_998_503 ns--> 999 ms + # Convert to float by adding 0.0 for historical reasons. See gh-89047 + self.msecs = (ct % 1_000_000_000) // 1_000_000 + 0.0 + if self.msecs == 999.0 and int(self.created) != ct // 1_000_000_000: + # ns -> sec conversion can round up, e.g: + # 1_677_903_920_999_999_900 ns --> 1_677_903_921.0 sec + self.msecs = 0.0 + + self.relativeCreated = (ct - _startTime) / 1e6 if logThreads: self.thread = threading.get_ident() self.threadName = threading.current_thread().name @@ -378,7 +386,7 @@ def __init__(self, name, level, pathname, lineno, def __repr__(self): return ''%(self.name, self.levelno, - self.pathname, self.lineno, self.msg) + self.pathname, self.lineno, self.msg) def getMessage(self): """ @@ -572,7 +580,7 @@ class Formatter(object): %(lineno)d Source line number where the logging call was issued (if available) %(funcName)s Function name - %(created)f Time when the LogRecord was created (time.time() + %(created)f Time when the LogRecord was created (time.time_ns() / 1e9 return value) %(asctime)s Textual time when the LogRecord was created %(msecs)d Millisecond portion of the creation time @@ -583,6 +591,7 @@ class Formatter(object): %(threadName)s Thread name (if available) %(taskName)s Task name (if available) %(process)d Process ID (if available) + %(processName)s Process name (if available) %(message)s The result of record.getMessage(), computed just as the record is emitted """ @@ -608,7 +617,7 @@ def __init__(self, fmt=None, datefmt=None, style='%', validate=True, *, """ if style not in _STYLES: raise ValueError('Style must be one of: %s' % ','.join( - _STYLES.keys())) + _STYLES.keys())) self._style = _STYLES[style][0](fmt, defaults=defaults) if validate: self._style.validate() @@ -658,7 +667,7 @@ def formatException(self, ei): # See issues #9427, #1553375. Commented out for now. #if getattr(self, 'fullstack', False): # traceback.print_stack(tb.tb_frame.f_back, file=sio) - traceback.print_exception(ei[0], ei[1], tb, None, sio) + traceback.print_exception(ei[0], ei[1], tb, limit=None, file=sio) s = sio.getvalue() sio.close() if s[-1:] == "\n": @@ -879,25 +888,20 @@ def _removeHandlerRef(wr): # set to None. It can also be called from another thread. So we need to # pre-emptively grab the necessary globals and check if they're None, # to prevent race conditions and failures during interpreter shutdown. - acquire, release, handlers = _acquireLock, _releaseLock, _handlerList - if acquire and release and handlers: - acquire() - try: - handlers.remove(wr) - except ValueError: - pass - finally: - release() + handlers, lock = _handlerList, _lock + if lock and handlers: + with lock: + try: + handlers.remove(wr) + except ValueError: + pass def _addHandlerRef(handler): """ Add a handler to the internal cleanup list using a weak reference. """ - _acquireLock() - try: + with _lock: _handlerList.append(weakref.ref(handler, _removeHandlerRef)) - finally: - _releaseLock() def getHandlerByName(name): @@ -912,8 +916,7 @@ def getHandlerNames(): """ Return all known handler names as an immutable set. """ - result = set(_handlers.keys()) - return frozenset(result) + return frozenset(_handlers) class Handler(Filterer): @@ -943,15 +946,12 @@ def get_name(self): return self._name def set_name(self, name): - _acquireLock() - try: + with _lock: if self._name in _handlers: del _handlers[self._name] self._name = name if name: _handlers[name] = self - finally: - _releaseLock() name = property(get_name, set_name) @@ -1023,11 +1023,8 @@ def handle(self, record): if isinstance(rv, LogRecord): record = rv if rv: - self.acquire() - try: + with self.lock: self.emit(record) - finally: - self.release() return rv def setFormatter(self, fmt): @@ -1055,13 +1052,10 @@ def close(self): methods. """ #get the module data lock, as we're updating a shared structure. - _acquireLock() - try: #unlikely to raise an exception, but you never know... + with _lock: self._closed = True if self._name and self._name in _handlers: del _handlers[self._name] - finally: - _releaseLock() def handleError(self, record): """ @@ -1076,14 +1070,14 @@ def handleError(self, record): The record which was being processed is passed in to this method. """ if raiseExceptions and sys.stderr: # see issue 13807 - t, v, tb = sys.exc_info() + exc = sys.exception() try: sys.stderr.write('--- Logging error ---\n') - traceback.print_exception(t, v, tb, None, sys.stderr) + traceback.print_exception(exc, limit=None, file=sys.stderr) sys.stderr.write('Call stack:\n') # Walk the stack frame up until we're out of logging, # so as to print the calling context. - frame = tb.tb_frame + frame = exc.__traceback__.tb_frame while (frame and os.path.dirname(frame.f_code.co_filename) == __path__[0]): frame = frame.f_back @@ -1092,7 +1086,7 @@ def handleError(self, record): else: # couldn't find the right stack frame, for some reason sys.stderr.write('Logged from file %s, line %s\n' % ( - record.filename, record.lineno)) + record.filename, record.lineno)) # Issue 18671: output logging message and arguments try: sys.stderr.write('Message: %r\n' @@ -1104,11 +1098,11 @@ def handleError(self, record): sys.stderr.write('Unable to print the message and arguments' ' - possible formatting error.\nUse the' ' traceback above to help find the error.\n' - ) + ) except OSError: #pragma: no cover pass # see issue 5971 finally: - del t, v, tb + del exc def __repr__(self): level = getLevelName(self.level) @@ -1138,12 +1132,9 @@ def flush(self): """ Flushes the stream. """ - self.acquire() - try: + with self.lock: if self.stream and hasattr(self.stream, "flush"): self.stream.flush() - finally: - self.release() def emit(self, record): """ @@ -1179,12 +1170,9 @@ def setStream(self, stream): result = None else: result = self.stream - self.acquire() - try: + with self.lock: self.flush() self.stream = stream - finally: - self.release() return result def __repr__(self): @@ -1234,8 +1222,7 @@ def close(self): """ Closes the stream. """ - self.acquire() - try: + with self.lock: try: if self.stream: try: @@ -1251,8 +1238,6 @@ def close(self): # Also see Issue #42378: we also rely on # self._closed being set to True there StreamHandler.close(self) - finally: - self.release() def _open(self): """ @@ -1388,8 +1373,7 @@ def getLogger(self, name): rv = None if not isinstance(name, str): raise TypeError('A logger name must be a string') - _acquireLock() - try: + with _lock: if name in self.loggerDict: rv = self.loggerDict[name] if isinstance(rv, PlaceHolder): @@ -1404,8 +1388,6 @@ def getLogger(self, name): rv.manager = self self.loggerDict[name] = rv self._fixupParents(rv) - finally: - _releaseLock() return rv def setLoggerClass(self, klass): @@ -1468,12 +1450,11 @@ def _clear_cache(self): Called when level changes are made """ - _acquireLock() - for logger in self.loggerDict.values(): - if isinstance(logger, Logger): - logger._cache.clear() - self.root._cache.clear() - _releaseLock() + with _lock: + for logger in self.loggerDict.values(): + if isinstance(logger, Logger): + logger._cache.clear() + self.root._cache.clear() #--------------------------------------------------------------------------- # Logger classes and functions @@ -1494,6 +1475,8 @@ 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. @@ -1552,7 +1535,7 @@ def warning(self, msg, *args, **kwargs): def warn(self, msg, *args, **kwargs): warnings.warn("The 'warn' method is deprecated, " - "use 'warning' instead", DeprecationWarning, 2) + "use 'warning' instead", DeprecationWarning, 2) self.warning(msg, *args, **kwargs) def error(self, msg, *args, **kwargs): @@ -1649,7 +1632,7 @@ def makeRecord(self, name, level, fn, lno, msg, args, exc_info, specialized LogRecords. """ rv = _logRecordFactory(name, level, fn, lno, msg, args, exc_info, func, - sinfo) + sinfo) if extra is not None: for key in extra: if (key in ["message", "asctime"]) or (key in rv.__dict__): @@ -1690,36 +1673,35 @@ def handle(self, record): This method is used for unpickled records received from a socket, as well as those created locally. Logger-level filtering is applied. """ - if self.disabled: - return - maybe_record = self.filter(record) - if not maybe_record: + if self._is_disabled(): return - if isinstance(maybe_record, LogRecord): - record = maybe_record - self.callHandlers(record) + + 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 def addHandler(self, hdlr): """ Add the specified handler to this logger. """ - _acquireLock() - try: + with _lock: if not (hdlr in self.handlers): self.handlers.append(hdlr) - finally: - _releaseLock() def removeHandler(self, hdlr): """ Remove the specified handler from this logger. """ - _acquireLock() - try: + with _lock: if hdlr in self.handlers: self.handlers.remove(hdlr) - finally: - _releaseLock() def hasHandlers(self): """ @@ -1791,22 +1773,19 @@ def isEnabledFor(self, level): """ Is this logger enabled for level 'level'? """ - if self.disabled: + if self._is_disabled(): return False try: return self._cache[level] except KeyError: - _acquireLock() - try: + with _lock: if self.manager.disable >= level: is_enabled = self._cache[level] = False else: is_enabled = self._cache[level] = ( - level >= self.getEffectiveLevel() + level >= self.getEffectiveLevel() ) - finally: - _releaseLock() return is_enabled def getChild(self, suffix): @@ -1836,16 +1815,18 @@ def _hierlevel(logger): return 1 + logger.name.count('.') d = self.manager.loggerDict - _acquireLock() - try: + with _lock: # exclude PlaceHolders - the last check is to ensure that lower-level # descendants aren't returned - if there are placeholders, a logger's # parent field might point to a grandparent or ancestor thereof. return set(item for item in d.values() if isinstance(item, Logger) and item.parent is self and _hierlevel(item) == 1 + _hierlevel(item.parent)) - finally: - _releaseLock() + + 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()) @@ -1881,7 +1862,7 @@ class LoggerAdapter(object): information in logging output. """ - def __init__(self, logger, extra=None): + 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 @@ -1891,9 +1872,20 @@ def __init__(self, logger, extra=None): following example: adapter = LoggerAdapter(someLogger, dict(p1=v1, p2="v2")) + + By default, LoggerAdapter objects will drop the "extra" argument + passed on the individual log calls to use its own instead. + + Initializing it with merge_extra=True will instead merge both + maps when logging, the individual call extra taking precedence + over the LoggerAdapter instance extra + + .. versionchanged:: 3.13 + The *merge_extra* argument was added. """ self.logger = logger self.extra = extra + self.merge_extra = merge_extra def process(self, msg, kwargs): """ @@ -1905,7 +1897,10 @@ def process(self, msg, kwargs): Normally, you'll only need to override this one method in a LoggerAdapter subclass for your specific needs. """ - kwargs["extra"] = self.extra + if self.merge_extra and "extra" in kwargs: + kwargs["extra"] = {**self.extra, **kwargs["extra"]} + else: + kwargs["extra"] = self.extra return msg, kwargs # @@ -1931,7 +1926,7 @@ def warning(self, msg, *args, **kwargs): def warn(self, msg, *args, **kwargs): warnings.warn("The 'warn' method is deprecated, " - "use 'warning' instead", DeprecationWarning, 2) + "use 'warning' instead", DeprecationWarning, 2) self.warning(msg, *args, **kwargs) def error(self, msg, *args, **kwargs): @@ -2088,8 +2083,7 @@ def basicConfig(**kwargs): """ # Add thread safety in case someone mistakenly calls # basicConfig() from multiple threads - _acquireLock() - try: + with _lock: force = kwargs.pop('force', False) encoding = kwargs.pop('encoding', None) errors = kwargs.pop('errors', 'backslashreplace') @@ -2125,7 +2119,7 @@ def basicConfig(**kwargs): style = kwargs.pop("style", '%') if style not in _STYLES: raise ValueError('Style must be one of: %s' % ','.join( - _STYLES.keys())) + _STYLES.keys())) fs = kwargs.pop("format", _STYLES[style][1]) fmt = Formatter(fs, dfs, style) for h in handlers: @@ -2138,8 +2132,6 @@ def basicConfig(**kwargs): if kwargs: keys = ', '.join(kwargs.keys()) raise ValueError('Unrecognised argument(s): %s' % keys) - finally: - _releaseLock() #--------------------------------------------------------------------------- # Utility functions at module level. @@ -2202,7 +2194,7 @@ def warning(msg, *args, **kwargs): def warn(msg, *args, **kwargs): warnings.warn("The 'warn' function is deprecated, " - "use 'warning' instead", DeprecationWarning, 2) + "use 'warning' instead", DeprecationWarning, 2) warning(msg, *args, **kwargs) def info(msg, *args, **kwargs): diff --git a/Lib/logging/config.py b/Lib/logging/config.py index ef04a35168d..190b4f92259 100644 --- a/Lib/logging/config.py +++ b/Lib/logging/config.py @@ -83,15 +83,12 @@ def fileConfig(fname, defaults=None, disable_existing_loggers=True, encoding=Non formatters = _create_formatters(cp) # critical section - logging._acquireLock() - try: + with logging._lock: _clearExistingHandlers() # Handlers add themselves to logging._handlers handlers = _install_handlers(cp, formatters) _install_loggers(cp, handlers, disable_existing_loggers) - finally: - logging._releaseLock() def _resolve(name): @@ -314,7 +311,7 @@ def convert_with_key(self, key, value, replace=True): if replace: self[key] = result if type(result) in (ConvertingDict, ConvertingList, - ConvertingTuple): + ConvertingTuple): result.parent = self result.key = key return result @@ -323,7 +320,7 @@ def convert(self, value): result = self.configurator.convert(value) if value is not result: if type(result) in (ConvertingDict, ConvertingList, - ConvertingTuple): + ConvertingTuple): result.parent = self return result @@ -378,7 +375,7 @@ class BaseConfigurator(object): WORD_PATTERN = re.compile(r'^\s*(\w+)\s*') DOT_PATTERN = re.compile(r'^\.\s*(\w+)\s*') - INDEX_PATTERN = re.compile(r'^\[\s*(\w+)\s*\]\s*') + INDEX_PATTERN = re.compile(r'^\[([^\[\]]*)\]\s*') DIGIT_PATTERN = re.compile(r'^\d+$') value_converters = { @@ -464,8 +461,8 @@ def convert(self, value): elif not isinstance(value, ConvertingList) and isinstance(value, list): value = ConvertingList(value) value.configurator = self - elif not isinstance(value, ConvertingTuple) and \ - isinstance(value, tuple) and not hasattr(value, '_fields'): + elif not isinstance(value, ConvertingTuple) and\ + isinstance(value, tuple) and not hasattr(value, '_fields'): value = ConvertingTuple(value) value.configurator = self elif isinstance(value, str): # str for py3k @@ -543,8 +540,7 @@ def configure(self): raise ValueError("Unsupported version: %s" % config['version']) incremental = config.pop('incremental', False) EMPTY_DICT = {} - logging._acquireLock() - try: + with logging._lock: if incremental: handlers = config.get('handlers', EMPTY_DICT) for name in handlers: @@ -585,7 +581,7 @@ def configure(self): for name in formatters: try: formatters[name] = self.configure_formatter( - formatters[name]) + formatters[name]) except Exception as e: raise ValueError('Unable to configure ' 'formatter %r' % name) from e @@ -688,8 +684,6 @@ def configure(self): except Exception as e: raise ValueError('Unable to configure root ' 'logger') from e - finally: - logging._releaseLock() def configure_formatter(self, config): """Configure a formatter from a dictionary.""" @@ -700,10 +694,9 @@ def configure_formatter(self, config): except TypeError as te: if "'format'" not in str(te): raise - #Name of parameter changed from fmt to format. - #Retry with old name. - #This is so that code can be used with older Python versions - #(e.g. by Django) + # logging.Formatter and its subclasses expect the `fmt` + # parameter instead of `format`. Retry passing configuration + # with `fmt`. config['fmt'] = config.pop('format') config['()'] = factory result = self.configure_custom(config) @@ -812,7 +805,7 @@ def configure_handler(self, config): elif issubclass(klass, logging.handlers.QueueHandler): # Another special case for handler which refers to other handlers # if 'handlers' not in config: - # raise ValueError('No handlers specified for a QueueHandler') + # raise ValueError('No handlers specified for a QueueHandler') if 'queue' in config: qspec = config['queue'] @@ -836,8 +829,8 @@ def configure_handler(self, config): else: if isinstance(lspec, str): listener = self.resolve(lspec) - if isinstance(listener, type) and \ - not issubclass(listener, logging.handlers.QueueListener): + if isinstance(listener, type) and\ + not issubclass(listener, logging.handlers.QueueListener): raise TypeError('Invalid listener specifier %r' % lspec) elif isinstance(lspec, dict): if '()' not in lspec: @@ -861,11 +854,11 @@ def configure_handler(self, config): except Exception as e: raise ValueError('Unable to set required handler %r' % hn) from e config['handlers'] = hlist - elif issubclass(klass, logging.handlers.SMTPHandler) and \ - 'mailhost' in config: + elif issubclass(klass, logging.handlers.SMTPHandler) and\ + 'mailhost' in config: config['mailhost'] = self.as_tuple(config['mailhost']) - elif issubclass(klass, logging.handlers.SysLogHandler) and \ - 'address' in config: + elif issubclass(klass, logging.handlers.SysLogHandler) and\ + 'address' in config: config['address'] = self.as_tuple(config['address']) if issubclass(klass, logging.handlers.QueueHandler): factory = functools.partial(self._configure_queue_handler, klass) @@ -1018,9 +1011,8 @@ class ConfigSocketReceiver(ThreadingTCPServer): def __init__(self, host='localhost', port=DEFAULT_LOGGING_CONFIG_PORT, handler=None, ready=None, verify=None): ThreadingTCPServer.__init__(self, (host, port), handler) - logging._acquireLock() - self.abort = 0 - logging._releaseLock() + with logging._lock: + self.abort = 0 self.timeout = 1 self.ready = ready self.verify = verify @@ -1034,9 +1026,8 @@ def serve_until_stopped(self): self.timeout) if rd: self.handle_request() - logging._acquireLock() - abort = self.abort - logging._releaseLock() + with logging._lock: + abort = self.abort self.server_close() class Server(threading.Thread): @@ -1057,9 +1048,8 @@ def run(self): self.port = server.server_address[1] self.ready.set() global _listener - logging._acquireLock() - _listener = server - logging._releaseLock() + with logging._lock: + _listener = server server.serve_until_stopped() return Server(ConfigSocketReceiver, ConfigStreamHandler, port, verify) @@ -1069,10 +1059,7 @@ def stopListening(): Stop the listening server which was created with a call to listen(). """ global _listener - logging._acquireLock() - try: + with logging._lock: if _listener: _listener.abort = 1 _listener = None - finally: - logging._releaseLock() diff --git a/Lib/logging/handlers.py b/Lib/logging/handlers.py index bf42ea11037..d3ea06c731e 100644 --- a/Lib/logging/handlers.py +++ b/Lib/logging/handlers.py @@ -23,11 +23,17 @@ To use, simply 'import logging.handlers' and log away! """ -import io, logging, socket, os, pickle, struct, time, re -from stat import ST_DEV, ST_INO, ST_MTIME +import copy +import io +import logging +import os +import pickle import queue +import re +import socket +import struct import threading -import copy +import time # # Some constants... @@ -272,7 +278,7 @@ def __init__(self, filename, when='h', interval=1, backupCount=0, # path object (see Issue #27493), but self.baseFilename will be a string filename = self.baseFilename if os.path.exists(filename): - t = os.stat(filename)[ST_MTIME] + t = int(os.stat(filename).st_mtime) else: t = int(time.time()) self.rolloverAt = self.computeRollover(t) @@ -304,10 +310,10 @@ def computeRollover(self, currentTime): rotate_ts = _MIDNIGHT else: rotate_ts = ((self.atTime.hour * 60 + self.atTime.minute)*60 + - self.atTime.second) + self.atTime.second) r = rotate_ts - ((currentHour * 60 + currentMinute) * 60 + - currentSecond) + currentSecond) if r <= 0: # Rotate time is before the current time (for example when # self.rotateAt is 13:45 and it now 14:15), rotation is @@ -465,8 +471,7 @@ class WatchedFileHandler(logging.FileHandler): This handler is not appropriate for use under Windows, because under Windows open files cannot be moved or renamed - logging opens the files with exclusive locks - and so there is no need - for such a handler. Furthermore, ST_INO is not supported under - Windows; stat always returns zero for this value. + for such a handler. This handler is based on a suggestion and patch by Chad J. Schroeder. @@ -482,9 +487,11 @@ def __init__(self, filename, mode='a', encoding=None, delay=False, self._statstream() def _statstream(self): - if self.stream: - sres = os.fstat(self.stream.fileno()) - self.dev, self.ino = sres[ST_DEV], sres[ST_INO] + if self.stream is None: + return + sres = os.fstat(self.stream.fileno()) + self.dev = sres.st_dev + self.ino = sres.st_ino def reopenIfNeeded(self): """ @@ -494,6 +501,9 @@ def reopenIfNeeded(self): has, close the old stream and reopen the file to get the current stream. """ + if self.stream is None: + return + # Reduce the chance of race conditions by stat'ing by path only # once and then fstat'ing our new fd if we opened a new log stream. # See issue #14632: Thanks to John Mulligan for the problem report @@ -501,18 +511,23 @@ def reopenIfNeeded(self): try: # stat the file by path, checking for existence sres = os.stat(self.baseFilename) + + # compare file system stat with that of our stream file handle + reopen = (sres.st_dev != self.dev or sres.st_ino != self.ino) except FileNotFoundError: - sres = None - # compare file system stat with that of our stream file handle - if not sres or sres[ST_DEV] != self.dev or sres[ST_INO] != self.ino: - if self.stream is not None: - # we have an open file handle, clean it up - self.stream.flush() - self.stream.close() - self.stream = None # See Issue #21742: _open () might fail. - # open a new file handle and get new stat info from that fd - self.stream = self._open() - self._statstream() + reopen = True + + if not reopen: + return + + # we have an open file handle, clean it up + self.stream.flush() + self.stream.close() + self.stream = None # See Issue #21742: _open () might fail. + + # open a new file handle and get new stat info from that fd + self.stream = self._open() + self._statstream() def emit(self, record): """ @@ -682,15 +697,12 @@ def close(self): """ Closes the socket. """ - self.acquire() - try: + with self.lock: sock = self.sock if sock: self.sock = None sock.close() logging.Handler.close(self) - finally: - self.release() class DatagramHandler(SocketHandler): """ @@ -803,7 +815,7 @@ class SysLogHandler(logging.Handler): "panic": LOG_EMERG, # DEPRECATED "warn": LOG_WARNING, # DEPRECATED "warning": LOG_WARNING, - } + } facility_names = { "auth": LOG_AUTH, @@ -830,7 +842,7 @@ class SysLogHandler(logging.Handler): "local5": LOG_LOCAL5, "local6": LOG_LOCAL6, "local7": LOG_LOCAL7, - } + } # Originally added to work around GH-43683. Unnecessary since GH-50043 but kept # for backwards compatibility. @@ -950,15 +962,12 @@ def close(self): """ Closes the socket. """ - self.acquire() - try: + with self.lock: sock = self.socket if sock: self.socket = None sock.close() logging.Handler.close(self) - finally: - self.release() def mapPriority(self, levelName): """ @@ -1031,7 +1040,8 @@ def __init__(self, mailhost, fromaddr, toaddrs, subject, only be used when authentication credentials are supplied. The tuple will be either an empty tuple, or a single-value tuple with the name of a keyfile, or a 2-value tuple with the names of the keyfile and - certificate file. (This tuple is passed to the `starttls` method). + certificate file. (This tuple is passed to the + `ssl.SSLContext.load_cert_chain` method). A timeout in seconds can be specified for the SMTP connection (the default is one second). """ @@ -1084,8 +1094,23 @@ def emit(self, record): msg.set_content(self.format(record)) if self.username: if self.secure is not None: + import ssl + + try: + keyfile = self.secure[0] + except IndexError: + keyfile = None + + try: + certfile = self.secure[1] + except IndexError: + certfile = None + + context = ssl._create_stdlib_context( + certfile=certfile, keyfile=keyfile + ) smtp.ehlo() - smtp.starttls(*self.secure) + smtp.starttls(context=context) smtp.ehlo() smtp.login(self.username, self.password) smtp.send_message(msg) @@ -1132,10 +1157,10 @@ def __init__(self, appname, dllname=None, logtype="Application"): logging.WARNING : win32evtlog.EVENTLOG_WARNING_TYPE, logging.ERROR : win32evtlog.EVENTLOG_ERROR_TYPE, logging.CRITICAL: win32evtlog.EVENTLOG_ERROR_TYPE, - } + } except ImportError: - print("The Python Win32 extensions for NT (service, event " \ - "logging) appear not to be available.") + print("The Python Win32 extensions for NT (service, event "\ + "logging) appear not to be available.") self._welu = None def getMessageID(self, record): @@ -1330,11 +1355,8 @@ def flush(self): This version just zaps the buffer to empty. """ - self.acquire() - try: + with self.lock: self.buffer.clear() - finally: - self.release() def close(self): """ @@ -1378,17 +1400,14 @@ def shouldFlush(self, record): Check for buffer full or a record at the flushLevel or higher. """ return (len(self.buffer) >= self.capacity) or \ - (record.levelno >= self.flushLevel) + (record.levelno >= self.flushLevel) def setTarget(self, target): """ Set the target handler for this handler. """ - self.acquire() - try: + with self.lock: self.target = target - finally: - self.release() def flush(self): """ @@ -1398,14 +1417,11 @@ def flush(self): The record buffer is only cleared if a target has been set. """ - self.acquire() - try: + with self.lock: if self.target: for record in self.buffer: self.target.handle(record) self.buffer.clear() - finally: - self.release() def close(self): """ @@ -1416,12 +1432,9 @@ def close(self): if self.flushOnClose: self.flush() finally: - self.acquire() - try: + with self.lock: self.target = None BufferingHandler.close(self) - finally: - self.release() class QueueHandler(logging.Handler): @@ -1532,6 +1545,9 @@ def start(self): This starts up a background thread to monitor the queue for LogRecords to process. """ + if self._thread is not None: + raise RuntimeError("Listener already started") + self._thread = t = threading.Thread(target=self._monitor) t.daemon = True t.start() @@ -1603,6 +1619,7 @@ def stop(self): Note that if you don't call this before your application exits, there may be some records still left on the queue, which won't be processed. """ - self.enqueue_sentinel() - self._thread.join() - self._thread = None + if self._thread: # see gh-114706 - allow calling this more than once + self.enqueue_sentinel() + self._thread.join() + self._thread = None diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 370685f1c63..84ca91ad4f7 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -100,8 +100,7 @@ def setUp(self): self._threading_key = threading_helper.threading_setup() logger_dict = logging.getLogger().manager.loggerDict - logging._acquireLock() - try: + with logging._lock: self.saved_handlers = logging._handlers.copy() self.saved_handler_list = logging._handlerList[:] self.saved_loggers = saved_loggers = logger_dict.copy() @@ -111,8 +110,6 @@ def setUp(self): for name in saved_loggers: logger_states[name] = getattr(saved_loggers[name], 'disabled', None) - finally: - logging._releaseLock() # Set two unused loggers self.logger1 = logging.getLogger("\xab\xd7\xbb") @@ -146,8 +143,7 @@ def tearDown(self): self.root_logger.removeHandler(h) h.close() self.root_logger.setLevel(self.original_logging_level) - logging._acquireLock() - try: + with logging._lock: logging._levelToName.clear() logging._levelToName.update(self.saved_level_to_name) logging._nameToLevel.clear() @@ -164,8 +160,6 @@ def tearDown(self): for name in self.logger_states: if logger_states[name] is not None: self.saved_loggers[name].disabled = logger_states[name] - finally: - logging._releaseLock() self.doCleanups() threading_helper.threading_cleanup(*self._threading_key) @@ -182,7 +176,7 @@ def assert_log_lines(self, expected_values, stream=None, pat=None): match = pat.search(actual) if not match: self.fail("Log line does not match expected pattern:\n" + - actual) + actual) self.assertEqual(tuple(match.groups()), expected) s = stream.read() if s: @@ -588,7 +582,7 @@ def test_specific_filters(self): ('Effusive', '17'), ('Terse', '18'), ('Silent', '20'), - ]) + ]) finally: if specific_filter: self.root_logger.removeFilter(specific_filter) @@ -613,7 +607,7 @@ def test_name(self): def test_builtin_handlers(self): # We can't actually *use* too many handlers in the tests, # but we can try instantiating them with various options - if sys.platform in ('linux', 'darwin'): + if sys.platform in ('linux', 'android', 'darwin'): for existing in (True, False): fn = make_temp_file() if not existing: @@ -673,11 +667,11 @@ def test_pathlike_objects(self): os.unlink(fn) pfn = os_helper.FakePath(fn) cases = ( - (logging.FileHandler, (pfn, 'w')), - (logging.handlers.RotatingFileHandler, (pfn, 'a')), - (logging.handlers.TimedRotatingFileHandler, (pfn, 'h')), - ) - if sys.platform in ('linux', 'darwin'): + (logging.FileHandler, (pfn, 'w')), + (logging.handlers.RotatingFileHandler, (pfn, 'a')), + (logging.handlers.TimedRotatingFileHandler, (pfn, 'h')), + ) + if sys.platform in ('linux', 'android', 'darwin'): cases += ((logging.handlers.WatchedFileHandler, (pfn, 'w')),) for cls, args in cases: h = cls(*args, encoding="utf-8") @@ -751,11 +745,8 @@ def __init__(self): stream=open('/dev/null', 'wt', encoding='utf-8')) def emit(self, record): - self.sub_handler.acquire() - try: + with self.sub_handler.lock: self.sub_handler.emit(record) - finally: - self.sub_handler.release() self.assertEqual(len(logging._handlers), 0) refed_h = _OurHandler() @@ -771,33 +762,26 @@ def emit(self, record): fork_happened__release_locks_and_end_thread = threading.Event() def lock_holder_thread_fn(): - logging._acquireLock() - try: - refed_h.acquire() - try: - # Tell the main thread to do the fork. - locks_held__ready_to_fork.set() - - # If the deadlock bug exists, the fork will happen - # without dealing with the locks we hold, deadlocking - # the child. - - # Wait for a successful fork or an unreasonable amount of - # time before releasing our locks. To avoid a timing based - # test we'd need communication from os.fork() as to when it - # has actually happened. Given this is a regression test - # for a fixed issue, potentially less reliably detecting - # regression via timing is acceptable for simplicity. - # The test will always take at least this long. :( - fork_happened__release_locks_and_end_thread.wait(0.5) - finally: - refed_h.release() - finally: - logging._releaseLock() + with logging._lock, refed_h.lock: + # Tell the main thread to do the fork. + locks_held__ready_to_fork.set() + + # If the deadlock bug exists, the fork will happen + # without dealing with the locks we hold, deadlocking + # the child. + + # Wait for a successful fork or an unreasonable amount of + # time before releasing our locks. To avoid a timing based + # test we'd need communication from os.fork() as to when it + # has actually happened. Given this is a regression test + # for a fixed issue, potentially less reliably detecting + # regression via timing is acceptable for simplicity. + # The test will always take at least this long. :( + fork_happened__release_locks_and_end_thread.wait(0.5) lock_holder_thread = threading.Thread( - target=lock_holder_thread_fn, - name='test_post_fork_child_no_deadlock lock holder') + target=lock_holder_thread_fn, + name='test_post_fork_child_no_deadlock lock holder') lock_holder_thread.start() locks_held__ready_to_fork.wait() @@ -1131,8 +1115,6 @@ class SMTPHandlerTest(BaseTest): # bpo-14314, bpo-19665, bpo-34092: don't wait forever TIMEOUT = support.LONG_TIMEOUT - # TODO: RUSTPYTHON - @unittest.skip(reason="Hangs RustPython") def test_basic(self): sockmap = {} server = TestSMTPServer((socket_helper.HOST, 0), self.process_message, 0.001, @@ -1657,7 +1639,7 @@ def test_config4_ok(self): logging.exception("just testing") sys.stdout.seek(0) self.assertEqual(output.getvalue(), - "ERROR:root:just testing\nGot a [RuntimeError]\n") + "ERROR:root:just testing\nGot a [RuntimeError]\n") # Original logger output is empty self.assert_log_lines([]) @@ -2170,8 +2152,6 @@ def handle_request(self, request): request.end_headers() self.handled.set() - # TODO: RUSTPYTHON - @unittest.skip("RUSTPYTHON") def test_output(self): # The log message sent to the HTTPHandler is properly received. logger = logging.getLogger("http") @@ -2195,7 +2175,7 @@ def test_output(self): sslctx = None context = None self.server = server = TestHTTPServer(addr, self.handle_request, - 0.01, sslctx=sslctx) + 0.01, sslctx=sslctx) server.start() server.ready.wait() host = 'localhost:%d' % server.server_port @@ -2212,7 +2192,8 @@ def test_output(self): self.handled.clear() msg = "sp\xe4m" logger.error(msg) - self.handled.wait() + handled = self.handled.wait(support.SHORT_TIMEOUT) + self.assertTrue(handled, "HTTP request timed out") self.assertEqual(self.log_data.path, '/frob') self.assertEqual(self.command, method) if method == 'GET': @@ -2253,7 +2234,7 @@ def _assertTruesurvival(self): dead.append(repr_) if dead: self.fail("%d objects should have survived " - "but have been destroyed: %s" % (len(dead), ", ".join(dead))) + "but have been destroyed: %s" % (len(dead), ", ".join(dead))) def test_persistent_loggers(self): # Logger objects are persistent and retain their configuration, even @@ -2351,7 +2332,7 @@ def test_warnings(self): s = a_file.getvalue() a_file.close() self.assertEqual(s, - "dummy.py:42: UserWarning: Explicit\n Dummy line\n") + "dummy.py:42: UserWarning: Explicit\n Dummy line\n") def test_warnings_no_handlers(self): with warnings.catch_warnings(): @@ -2632,7 +2613,7 @@ class ConfigDictTest(BaseTest): }, 'root' : { 'level' : 'NOTSET', - 'handlers' : ['hand1'], + 'handlers' : ['hand1'], }, } @@ -2666,7 +2647,7 @@ class ConfigDictTest(BaseTest): }, 'root' : { 'level' : 'NOTSET', - 'handlers' : ['hand1'], + 'handlers' : ['hand1'], }, } @@ -3277,7 +3258,7 @@ def format(self, record): 'h1' : { 'class': 'logging.FileHandler', }, - # key is before depended on handlers to test that deferred config works + # key is before depended on handlers to test that deferred config works 'ah' : { 'class': 'logging.handlers.QueueHandler', 'handlers': ['h1'] @@ -3355,7 +3336,7 @@ def test_config4_ok(self): logging.exception("just testing") sys.stdout.seek(0) self.assertEqual(output.getvalue(), - "ERROR:root:just testing\nGot a [RuntimeError]\n") + "ERROR:root:just testing\nGot a [RuntimeError]\n") # Original logger output is empty self.assert_log_lines([]) @@ -3370,7 +3351,7 @@ def test_config4a_ok(self): logging.exception("just testing") sys.stdout.seek(0) self.assertEqual(output.getvalue(), - "ERROR:root:just testing\nGot a [RuntimeError]\n") + "ERROR:root:just testing\nGot a [RuntimeError]\n") # Original logger output is empty self.assert_log_lines([]) @@ -3770,7 +3751,28 @@ def test_baseconfig(self): d = { 'atuple': (1, 2, 3), 'alist': ['a', 'b', 'c'], - 'adict': {'d': 'e', 'f': 3 }, + 'adict': { + 'd': 'e', 'f': 3 , + 'alpha numeric 1 with spaces' : 5, + 'alpha numeric 1 %( - © ©ß¯' : 9, + 'alpha numeric ] 1 with spaces' : 15, + 'alpha ]] numeric 1 %( - © ©ß¯]' : 19, + ' alpha [ numeric 1 %( - © ©ß¯] ' : 11, + ' alpha ' : 32, + '' : 10, + 'nest4' : { + 'd': 'e', 'f': 3 , + 'alpha numeric 1 with spaces' : 5, + 'alpha numeric 1 %( - © ©ß¯' : 9, + '' : 10, + 'somelist' : ('g', ('h', 'i'), 'j'), + 'somedict' : { + 'a' : 1, + 'a with 1 and space' : 3, + 'a with ( and space' : 4, + } + } + }, 'nest1': ('g', ('h', 'i'), 'j'), 'nest2': ['k', ['l', 'm'], 'n'], 'nest3': ['o', 'cfg://alist', 'p'], @@ -3782,11 +3784,36 @@ def test_baseconfig(self): self.assertEqual(bc.convert('cfg://nest2[1][1]'), 'm') self.assertEqual(bc.convert('cfg://adict.d'), 'e') self.assertEqual(bc.convert('cfg://adict[f]'), 3) + self.assertEqual(bc.convert('cfg://adict[alpha numeric 1 with spaces]'), 5) + self.assertEqual(bc.convert('cfg://adict[alpha numeric 1 %( - © ©ß¯]'), 9) + self.assertEqual(bc.convert('cfg://adict[]'), 10) + self.assertEqual(bc.convert('cfg://adict.nest4.d'), 'e') + self.assertEqual(bc.convert('cfg://adict.nest4[d]'), 'e') + self.assertEqual(bc.convert('cfg://adict[nest4].d'), 'e') + self.assertEqual(bc.convert('cfg://adict[nest4][f]'), 3) + self.assertEqual(bc.convert('cfg://adict[nest4][alpha numeric 1 with spaces]'), 5) + self.assertEqual(bc.convert('cfg://adict[nest4][alpha numeric 1 %( - © ©ß¯]'), 9) + self.assertEqual(bc.convert('cfg://adict[nest4][]'), 10) + self.assertEqual(bc.convert('cfg://adict[nest4][somelist][0]'), 'g') + self.assertEqual(bc.convert('cfg://adict[nest4][somelist][1][0]'), 'h') + self.assertEqual(bc.convert('cfg://adict[nest4][somelist][1][1]'), 'i') + self.assertEqual(bc.convert('cfg://adict[nest4][somelist][2]'), 'j') + self.assertEqual(bc.convert('cfg://adict[nest4].somedict.a'), 1) + self.assertEqual(bc.convert('cfg://adict[nest4].somedict[a]'), 1) + self.assertEqual(bc.convert('cfg://adict[nest4].somedict[a with 1 and space]'), 3) + self.assertEqual(bc.convert('cfg://adict[nest4].somedict[a with ( and space]'), 4) + self.assertEqual(bc.convert('cfg://adict.nest4.somelist[1][1]'), 'i') + self.assertEqual(bc.convert('cfg://adict.nest4.somelist[2]'), 'j') + self.assertEqual(bc.convert('cfg://adict.nest4.somedict.a'), 1) + self.assertEqual(bc.convert('cfg://adict.nest4.somedict[a]'), 1) v = bc.convert('cfg://nest3') self.assertEqual(v.pop(1), ['a', 'b', 'c']) self.assertRaises(KeyError, bc.convert, 'cfg://nosuch') self.assertRaises(ValueError, bc.convert, 'cfg://!') self.assertRaises(KeyError, bc.convert, 'cfg://adict[2]') + self.assertRaises(KeyError, bc.convert, 'cfg://adict[alpha numeric ] 1 with spaces]') + self.assertRaises(ValueError, bc.convert, 'cfg://adict[ alpha ]] numeric 1 %( - © ©ß¯] ]') + self.assertRaises(ValueError, bc.convert, 'cfg://adict[ alpha [ numeric 1 %( - © ©ß¯] ]') def test_namedtuple(self): # see bpo-39142 @@ -3992,7 +4019,7 @@ def test_config_reject_simple_queue_handler_multiprocessing_context(self): @skip_if_tsan_fork @support.requires_subprocess() @unittest.skipUnless(support.Py_DEBUG, "requires a debug build for testing" - "assertions in multiprocessing") + " assertions in multiprocessing") def test_config_queue_handler_multiprocessing_context(self): # regression test for gh-121723 if support.MS_WINDOWS: @@ -4029,8 +4056,7 @@ def _mpinit_issue121723(qspec, message_to_log): # log a message (this creates a record put in the queue) logging.getLogger().info(message_to_log) - # TODO: RustPython - @unittest.expectedFailure + @skip_if_tsan_fork @support.requires_subprocess() def test_multiprocessing_queues(self): # See gh-119819 @@ -4089,8 +4115,6 @@ def test_90195(self): # Logger should be enabled, since explicitly mentioned self.assertFalse(logger.disabled) - # TODO: RustPython - @unittest.expectedFailure def test_111615(self): # See gh-111615 import_helper.import_module('_multiprocessing') # see gh-113692 @@ -4139,6 +4163,89 @@ def __init__(self, *args, **kwargs): handler = logging.getHandlerByName('custom') self.assertEqual(handler.custom_kwargs, custom_kwargs) + # See gh-91555 and gh-90321 + @support.requires_subprocess() + def test_deadlock_in_queue(self): + queue = multiprocessing.Queue() + handler = logging.handlers.QueueHandler(queue) + logger = multiprocessing.get_logger() + level = logger.level + try: + logger.setLevel(logging.DEBUG) + logger.addHandler(handler) + logger.debug("deadlock") + finally: + logger.setLevel(level) + logger.removeHandler(handler) + + def test_recursion_in_custom_handler(self): + class BadHandler(logging.Handler): + def __init__(self): + super().__init__() + def emit(self, record): + logger.debug("recurse") + logger = logging.getLogger("test_recursion_in_custom_handler") + logger.addHandler(BadHandler()) + logger.setLevel(logging.DEBUG) + logger.debug("boom") + + @threading_helper.requires_working_threading() + def test_thread_supression_noninterference(self): + lock = threading.Lock() + logger = logging.getLogger("test_thread_supression_noninterference") + + # Block on the first call, allow others through + # + # NOTE: We need to bypass the base class's lock, otherwise that will + # block multiple calls to the same handler itself. + class BlockOnceHandler(TestHandler): + def __init__(self, barrier): + super().__init__(support.Matcher()) + self.barrier = barrier + + def createLock(self): + self.lock = None + + def handle(self, record): + self.emit(record) + + def emit(self, record): + if self.barrier: + barrier = self.barrier + self.barrier = None + barrier.wait() + with lock: + pass + super().emit(record) + logger.info("blow up if not supressed") + + barrier = threading.Barrier(2) + handler = BlockOnceHandler(barrier) + logger.addHandler(handler) + logger.setLevel(logging.DEBUG) + + t1 = threading.Thread(target=logger.debug, args=("1",)) + with lock: + + # Ensure first thread is blocked in the handler, hence supressing logging... + t1.start() + barrier.wait() + + # ...but the second thread should still be able to log... + t2 = threading.Thread(target=logger.debug, args=("2",)) + t2.start() + t2.join(timeout=3) + + self.assertEqual(len(handler.buffer), 1) + self.assertTrue(handler.matches(levelno=logging.DEBUG, message='2')) + + # The first thread should still be blocked here + self.assertTrue(t1.is_alive()) + + # Now the lock has been released the first thread should complete + t1.join() + self.assertEqual(len(handler.buffer), 2) + self.assertTrue(handler.matches(levelno=logging.DEBUG, message='1')) class ManagerTest(BaseTest): def test_manager_loggerclass(self): @@ -4208,7 +4315,7 @@ def filter(self, record): t = type(record) if t is not self.cls: msg = 'Unexpected LogRecord type %s, expected %s' % (t, - self.cls) + self.cls) raise TypeError(msg) return True @@ -4228,7 +4335,7 @@ def test_logrecord_class(self): logging.setLogRecordFactory(DerivedLogRecord) self.root_logger.error(self.next_message()) self.assert_log_lines([ - ('root', 'ERROR', '2'), + ('root', 'ERROR', '2'), ]) @@ -4276,8 +4383,6 @@ def test_formatting(self): self.assertEqual(formatted_msg, log_record.msg) self.assertEqual(formatted_msg, log_record.message) - @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'), - 'logging.handlers.QueueListener required for this test') def test_queue_listener(self): handler = TestHandler(support.Matcher()) listener = logging.handlers.QueueListener(self.queue, handler) @@ -4288,6 +4393,7 @@ def test_queue_listener(self): self.que_logger.critical(self.next_message()) finally: listener.stop() + listener.stop() # gh-114706 - ensure no crash if called again self.assertTrue(handler.matches(levelno=logging.WARNING, message='1')) self.assertTrue(handler.matches(levelno=logging.ERROR, message='2')) self.assertTrue(handler.matches(levelno=logging.CRITICAL, message='3')) @@ -4311,8 +4417,18 @@ def test_queue_listener(self): self.assertTrue(handler.matches(levelno=logging.CRITICAL, message='6')) handler.close() - @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'), - 'logging.handlers.QueueListener required for this test') + # 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) + 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). listener = logging.handlers.QueueListener(self.queue, self.root_hdlr) @@ -4327,8 +4443,6 @@ def test_queue_listener_with_StreamHandler(self): self.assertEqual(self.stream.getvalue().strip().count('Traceback'), 1) self.assertEqual(self.stream.getvalue().strip().count('Stack'), 1) - @unittest.skipUnless(hasattr(logging.handlers, 'QueueListener'), - 'logging.handlers.QueueListener required for this test') def test_queue_listener_with_multiple_handlers(self): # Test that queue handler format doesn't affect other handler formats (bpo-35726). self.que_hdlr.setFormatter(self.root_formatter) @@ -4344,6 +4458,7 @@ def test_queue_listener_with_multiple_handlers(self): import multiprocessing from unittest.mock import patch + @skip_if_tsan_fork @threading_helper.requires_working_threading() class QueueListenerTest(BaseTest): """ @@ -4427,8 +4542,8 @@ def test_no_messages_in_queue_after_stop(self): expected = [[], [logging.handlers.QueueListener._sentinel]] self.assertIn(items, expected, 'Found unexpected messages in queue: %s' % ( - [m.msg if isinstance(m, logging.LogRecord) - else m for m in items])) + [m.msg if isinstance(m, logging.LogRecord) + else m for m in items])) def test_calls_task_done_after_stop(self): # Issue 36813: Make sure queue.join does not deadlock. @@ -4538,8 +4653,6 @@ def test_dollars(self): f = logging.Formatter('${asctime}--', style='$') self.assertTrue(f.usesTime()) - # TODO: RustPython - @unittest.expectedFailure def test_format_validate(self): # Check correct formatting # Percentage style @@ -4713,8 +4826,6 @@ def test_defaults_parameter(self): def test_invalid_style(self): self.assertRaises(ValueError, logging.Formatter, None, None, 'x') - # TODO: RustPython - @unittest.expectedFailure def test_time(self): r = self.get_record() dt = datetime.datetime(1993, 4, 21, 8, 3, 0, 0, utc) @@ -4729,8 +4840,6 @@ def test_time(self): f.format(r) self.assertEqual(r.asctime, '1993-04-21 08:03:00,123') - # TODO: RustPython - @unittest.expectedFailure def test_default_msec_format_none(self): class NoMsecFormatter(logging.Formatter): default_msec_format = None @@ -4751,6 +4860,77 @@ def test_issue_89047(self): s = f.format(r) self.assertNotIn('.1000', s) + def test_msecs_has_no_floating_point_precision_loss(self): + # See issue gh-102402 + tests = ( + # time_ns is approx. 2023-03-04 04:25:20 UTC + # (time_ns, expected_msecs_value) + (1_677_902_297_100_000_000, 100.0), # exactly 100ms + (1_677_903_920_999_998_503, 999.0), # check truncating doesn't round + (1_677_903_920_000_998_503, 0.0), # check truncating doesn't round + (1_677_903_920_999_999_900, 0.0), # check rounding up + ) + for ns, want in tests: + with patch('time.time_ns') as patched_ns: + patched_ns.return_value = ns + record = logging.makeLogRecord({'msg': 'test'}) + with self.subTest(ns): + self.assertEqual(record.msecs, want) + self.assertEqual(record.created, ns / 1e9) + self.assertAlmostEqual(record.created - int(record.created), + record.msecs / 1e3, + delta=1e-3) + + def test_relativeCreated_has_higher_precision(self): + # See issue gh-102402. + # Run the code in the subprocess, because the time module should + # be patched before the first import of the logging package. + # Temporary unloading and re-importing the logging package has + # side effects (including registering the atexit callback and + # references leak). + start_ns = 1_677_903_920_000_998_503 # approx. 2023-03-04 04:25:20 UTC + offsets_ns = (200, 500, 12_354, 99_999, 1_677_903_456_999_123_456) + code = textwrap.dedent(f""" + start_ns = {start_ns!r} + offsets_ns = {offsets_ns!r} + start_monotonic_ns = start_ns - 1 + + import time + # Only time.time_ns needs to be patched for the current + # implementation, but patch also other functions to make + # the test less implementation depending. + old_time_ns = time.time_ns + old_time = time.time + old_monotonic_ns = time.monotonic_ns + old_monotonic = time.monotonic + time_ns_result = start_ns + time.time_ns = lambda: time_ns_result + time.time = lambda: time.time_ns()/1e9 + time.monotonic_ns = lambda: time_ns_result - start_monotonic_ns + time.monotonic = lambda: time.monotonic_ns()/1e9 + try: + import logging + + for offset_ns in offsets_ns: + # mock for log record creation + time_ns_result = start_ns + offset_ns + record = logging.makeLogRecord({{'msg': 'test'}}) + print(record.created, record.relativeCreated) + finally: + time.time_ns = old_time_ns + time.time = old_time + time.monotonic_ns = old_monotonic_ns + time.monotonic = old_monotonic + """) + rc, out, err = assert_python_ok("-c", code) + out = out.decode() + for offset_ns, line in zip(offsets_ns, out.splitlines(), strict=True): + with self.subTest(offset_ns=offset_ns): + created, relativeCreated = map(float, line.split()) + self.assertAlmostEqual(created, (start_ns + offset_ns) / 1e9, places=6) + # After PR gh-102412, precision (places) increases from 3 to 7 + self.assertAlmostEqual(relativeCreated, offset_ns / 1e6, places=7) + class TestBufferingFormatter(logging.BufferingFormatter): def formatHeader(self, records): @@ -4795,9 +4975,9 @@ def test_formatting(self): self.assertTrue(r.exc_text.endswith('\nRuntimeError: ' 'deliberate mistake')) self.assertTrue(r.stack_info.startswith('Stack (most recent ' - 'call last):\n')) + 'call last):\n')) self.assertTrue(r.stack_info.endswith('logging.exception(\'failed\', ' - 'stack_info=True)')) + 'stack_info=True)')) class LastResortTest(BaseTest): @@ -5061,8 +5241,6 @@ def __init__(self, name='MyLogger', level=logging.NOTSET): h.close() logging.setLoggerClass(logging.Logger) - # TODO: RustPython - @unittest.expectedFailure def test_logging_at_shutdown(self): # bpo-20037: Doing text I/O late at interpreter shutdown must not crash code = textwrap.dedent(""" @@ -5082,8 +5260,6 @@ def __del__(self): self.assertIn("exception in __del__", err) self.assertIn("ValueError: some error", err) - # TODO: RustPython - @unittest.expectedFailure def test_logging_at_shutdown_open(self): # bpo-26789: FileHandler keeps a reference to the builtin open() # function to be able to open or reopen the file during Python @@ -5175,7 +5351,7 @@ def _extract_logrecord_process_name(key, logMultiprocessing, conn=None): results = {'processName' : name, 'r1.processName': r1.processName, 'r2.processName': r2.processName, - } + } finally: logging.logMultiprocessing = prev_logMultiprocessing if conn: @@ -5183,6 +5359,7 @@ def _extract_logrecord_process_name(key, logMultiprocessing, conn=None): else: return results + @skip_if_tsan_fork def test_multiprocessing(self): support.skip_if_broken_multiprocessing_synchronize() multiprocessing_imported = 'multiprocessing' in sys.modules @@ -5333,7 +5510,7 @@ def test_strformatstyle(self): logging.error("Log an error") sys.stdout.seek(0) self.assertEqual(output.getvalue().strip(), - "ERROR:root:Log an error") + "ERROR:root:Log an error") def test_stringtemplatestyle(self): with support.captured_stdout() as output: @@ -5341,7 +5518,7 @@ def test_stringtemplatestyle(self): logging.error("Log an error") sys.stdout.seek(0) self.assertEqual(output.getvalue().strip(), - "ERROR:root:Log an error") + "ERROR:root:Log an error") def test_filename(self): @@ -5418,11 +5595,11 @@ def test_incompatible(self): handlers = [logging.StreamHandler()] stream = sys.stderr assertRaises(ValueError, logging.basicConfig, filename='test.log', - stream=stream) + stream=stream) assertRaises(ValueError, logging.basicConfig, filename='test.log', - handlers=handlers) + handlers=handlers) assertRaises(ValueError, logging.basicConfig, stream=stream, - handlers=handlers) + handlers=handlers) # Issue 23207: test for invalid kwargs assertRaises(ValueError, logging.basicConfig, loglevel=logging.INFO) # Should pop both filename and filemode even if filename is None @@ -5803,6 +5980,30 @@ def test_extra_not_merged_by_default(self): record = self.recording.records[0] self.assertFalse(hasattr(record, 'foo')) + def test_extra_merged(self): + self.adapter = logging.LoggerAdapter(logger=self.logger, + extra={'foo': '1'}, + merge_extra=True) + + 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.assertEqual(record.foo, '1') + self.assertEqual(record.bar, '2') + + def test_extra_merged_log_call_has_precedence(self): + self.adapter = logging.LoggerAdapter(logger=self.logger, + extra={'foo': '1'}, + merge_extra=True) + + 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.assertEqual(record.foo, '2') + class PrefixAdapter(logging.LoggerAdapter): prefix = 'Adapter' @@ -6112,14 +6313,14 @@ def test_should_not_rollover(self): # If maxBytes is zero rollover never occurs rh = logging.handlers.RotatingFileHandler( - self.fn, encoding="utf-8", maxBytes=0) + self.fn, encoding="utf-8", maxBytes=0) self.assertFalse(rh.shouldRollover(None)) rh.close() with open(self.fn, 'wb') as f: f.write(b'\n') rh = logging.handlers.RotatingFileHandler( - self.fn, encoding="utf-8", maxBytes=0) + self.fn, encoding="utf-8", maxBytes=0) self.assertFalse(rh.shouldRollover(None)) rh.close() @@ -6129,7 +6330,7 @@ def test_should_not_rollover_non_file(self): # We set maxBytes to 1 so that rollover would normally happen, except # for the check for regular files rh = logging.handlers.RotatingFileHandler( - os.devnull, encoding="utf-8", maxBytes=1) + os.devnull, encoding="utf-8", maxBytes=1) self.assertFalse(rh.shouldRollover(self.next_rec())) rh.close() @@ -6259,13 +6460,11 @@ def rotator(source, dest): rh.close() class TimedRotatingFileHandlerTest(BaseFileTest): - # TODO: RUSTPYTHON - @unittest.skip("OS dependent bug") @unittest.skipIf(support.is_wasi, "WASI does not have /dev/null.") def test_should_not_rollover(self): # See bpo-45401. Should only ever rollover regular files fh = logging.handlers.TimedRotatingFileHandler( - os.devnull, 'S', encoding="utf-8", backupCount=1) + os.devnull, 'S', encoding="utf-8", backupCount=1) time.sleep(1.1) # a little over a second ... r = logging.makeLogRecord({'msg': 'testing - device file'}) self.assertFalse(fh.shouldRollover(r)) @@ -6274,7 +6473,7 @@ def test_should_not_rollover(self): # other test methods added below def test_rollover(self): fh = logging.handlers.TimedRotatingFileHandler( - self.fn, 'S', encoding="utf-8", backupCount=1) + self.fn, 'S', encoding="utf-8", backupCount=1) fmt = logging.Formatter('%(asctime)s %(message)s') fh.setFormatter(fmt) r1 = logging.makeLogRecord({'msg': 'testing - initial'}) @@ -6314,8 +6513,6 @@ def test_rollover(self): print(tf.read()) self.assertTrue(found, msg=msg) - # TODO: RustPython - @unittest.skip("OS dependent bug") def test_rollover_at_midnight(self, weekly=False): os_helper.unlink(self.fn) now = datetime.datetime.now() @@ -6359,8 +6556,6 @@ def test_rollover_at_midnight(self, weekly=False): for i, line in enumerate(f): self.assertIn(f'testing1 {i}', line) - # TODO: RustPython - @unittest.skip("OS dependent bug") def test_rollover_at_weekday(self): self.test_rollover_at_midnight(weekly=True) @@ -6944,7 +7139,7 @@ def secs(**kw): ('MIDNIGHT', 60 * 60 * 24), # current time (epoch start) is a Thursday, W0 means Monday ('W0', secs(days=4, hours=24)), - ): + ): for interval in 1, 3: def test_compute_rollover(self, when=when, interval=interval, exp=exp): rh = logging.handlers.TimedRotatingFileHandler( @@ -6970,8 +7165,8 @@ def test_compute_rollover(self, when=when, interval=interval, exp=exp): currentSecond = t[5] # r is the number of seconds left between now and midnight r = logging.handlers._MIDNIGHT - ((currentHour * 60 + - currentMinute) * 60 + - currentSecond) + currentMinute) * 60 + + currentSecond) result = currentTime + r print('t: %s (%s)' % (t, rh.utc), file=sys.stderr) print('currentHour: %s' % currentHour, file=sys.stderr) From b4b8dd3f664a5e548510c85914e88dd838a0d1ac Mon Sep 17 00:00:00 2001 From: ShaharNaveh <50263213+ShaharNaveh@users.noreply.github.com> Date: Sat, 19 Jul 2025 14:24:20 +0200 Subject: [PATCH 2/5] Mark failing tests --- Lib/test/test_logging.py | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 84ca91ad4f7..7fd3fbbbe1b 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -1115,6 +1115,8 @@ class SMTPHandlerTest(BaseTest): # bpo-14314, bpo-19665, bpo-34092: don't wait forever TIMEOUT = support.LONG_TIMEOUT + # TODO: RUSTPYTHON + @unittest.skip(reason="RUSTPYTHON hangs") def test_basic(self): sockmap = {} server = TestSMTPServer((socket_helper.HOST, 0), self.process_message, 0.001, @@ -4056,6 +4058,8 @@ def _mpinit_issue121723(qspec, message_to_log): # log a message (this creates a record put in the queue) logging.getLogger().info(message_to_log) + # TODO: RUSTPYTHON; ImportError: cannot import name 'SemLock' + @unittest.expectedFailure @skip_if_tsan_fork @support.requires_subprocess() def test_multiprocessing_queues(self): @@ -4115,6 +4119,8 @@ def test_90195(self): # Logger should be enabled, since explicitly mentioned self.assertFalse(logger.disabled) + # TODO: RUSTPYTHON; ImportError: cannot import name 'SemLock' + @unittest.expectedFailure def test_111615(self): # See gh-111615 import_helper.import_module('_multiprocessing') # see gh-113692 @@ -4163,6 +4169,8 @@ def __init__(self, *args, **kwargs): handler = logging.getHandlerByName('custom') self.assertEqual(handler.custom_kwargs, custom_kwargs) + # TODO: RUSTPYTHON; ImportError: cannot import name 'SemLock' + @unittest.expectedFailure # See gh-91555 and gh-90321 @support.requires_subprocess() def test_deadlock_in_queue(self): @@ -4653,6 +4661,8 @@ def test_dollars(self): f = logging.Formatter('${asctime}--', style='$') self.assertTrue(f.usesTime()) + # TODO: RUSTPYTHON; ValueError: Unexpected error parsing format string + @unittest.expectedFailure def test_format_validate(self): # Check correct formatting # Percentage style @@ -4826,6 +4836,8 @@ def test_defaults_parameter(self): def test_invalid_style(self): self.assertRaises(ValueError, logging.Formatter, None, None, 'x') + # TODO: RUSTPYTHON; AttributeError: 'struct_time' object has no attribute 'tm_gmtoff' + @unittest.expectedFailure def test_time(self): r = self.get_record() dt = datetime.datetime(1993, 4, 21, 8, 3, 0, 0, utc) @@ -4840,6 +4852,8 @@ def test_time(self): f.format(r) self.assertEqual(r.asctime, '1993-04-21 08:03:00,123') + # TODO: RUSTPYTHON; AttributeError: 'struct_time' object has no attribute 'tm_gmtoff' + @unittest.expectedFailure def test_default_msec_format_none(self): class NoMsecFormatter(logging.Formatter): default_msec_format = None @@ -5241,6 +5255,8 @@ def __init__(self, name='MyLogger', level=logging.NOTSET): h.close() logging.setLoggerClass(logging.Logger) + # TODO: RUSTPYTHON + @unittest.expectedFailure def test_logging_at_shutdown(self): # bpo-20037: Doing text I/O late at interpreter shutdown must not crash code = textwrap.dedent(""" @@ -5260,6 +5276,8 @@ def __del__(self): self.assertIn("exception in __del__", err) self.assertIn("ValueError: some error", err) + # TODO: RUSTPYTHON + @unittest.expectedFailure def test_logging_at_shutdown_open(self): # bpo-26789: FileHandler keeps a reference to the builtin open() # function to be able to open or reopen the file during Python From 9d7765eccf003eca7acd5bacafcf83a84479e0ba Mon Sep 17 00:00:00 2001 From: ShaharNaveh <50263213+ShaharNaveh@users.noreply.github.com> Date: Sat, 19 Jul 2025 16:36:44 +0200 Subject: [PATCH 3/5] Mark some failing windows tests --- Lib/test/test_logging.py | 4 ++++ 1 file changed, 4 insertions(+) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 7fd3fbbbe1b..7b0c86edb87 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -6531,6 +6531,8 @@ def test_rollover(self): print(tf.read()) self.assertTrue(found, msg=msg) + # TODO: RUSTPYTHON + @unittest.expectedFailureIfWindows("TODO: RUSTPYTHON") def test_rollover_at_midnight(self, weekly=False): os_helper.unlink(self.fn) now = datetime.datetime.now() @@ -6574,6 +6576,8 @@ def test_rollover_at_midnight(self, weekly=False): for i, line in enumerate(f): self.assertIn(f'testing1 {i}', line) + # TODO: RUSTPYTHON + @unittest.expectedFailureIfWindows("TODO: RUSTPYTHON") def test_rollover_at_weekday(self): self.test_rollover_at_midnight(weekly=True) From 4da9b27d0896f42b73d38b31f7299639f08e70a6 Mon Sep 17 00:00:00 2001 From: ShaharNaveh <50263213+ShaharNaveh@users.noreply.github.com> Date: Sat, 19 Jul 2025 16:43:19 +0200 Subject: [PATCH 4/5] Skip flaky test --- Lib/test/test_logging.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 7b0c86edb87..186f67ec97f 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -2154,6 +2154,8 @@ def handle_request(self, request): request.end_headers() self.handled.set() + # TODO: RUSTPYTHON + @unittest.skip("TODO: RUSTPYTHON; flaky test") def test_output(self): # The log message sent to the HTTPHandler is properly received. logger = logging.getLogger("http") From 673618eed3d39b0599f9cae0ef10acc6e6dc54c9 Mon Sep 17 00:00:00 2001 From: ShaharNaveh <50263213+ShaharNaveh@users.noreply.github.com> Date: Sat, 19 Jul 2025 18:06:34 +0200 Subject: [PATCH 5/5] Mark more failing tests --- Lib/test/test_logging.py | 2 ++ 1 file changed, 2 insertions(+) diff --git a/Lib/test/test_logging.py b/Lib/test/test_logging.py index 186f67ec97f..0039d34b5ef 100644 --- a/Lib/test/test_logging.py +++ b/Lib/test/test_logging.py @@ -6480,6 +6480,8 @@ def rotator(source, dest): rh.close() class TimedRotatingFileHandlerTest(BaseFileTest): + # TODO: RUSTPYTHON + @unittest.expectedFailureIfWindows("TODO: RUSTPYTHON") @unittest.skipIf(support.is_wasi, "WASI does not have /dev/null.") def test_should_not_rollover(self): # See bpo-45401. Should only ever rollover regular files