From 4e6cc0c401bd6c9e47b324fc2df99e3bd679da33 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Pablo=20Su=C3=A1rez=20Hern=C3=A1ndez?= Date: Wed, 22 Jan 2020 08:19:55 +0000 Subject: [PATCH] Prevent logging deadlock on salt-api subprocesses (bsc#1159284) --- salt/_logging/impl.py | 127 +++++++++++++++------------------- salt/client/ssh/__init__.py | 12 +++- salt/client/ssh/client.py | 21 +++--- salt/client/ssh/wrapper/cp.py | 10 +-- salt/loader.py | 2 +- salt/utils/lazy.py | 10 +-- 6 files changed, 85 insertions(+), 97 deletions(-) diff --git a/salt/_logging/impl.py b/salt/_logging/impl.py index 5a6292b445..2f15bf0025 100644 --- a/salt/_logging/impl.py +++ b/salt/_logging/impl.py @@ -1,4 +1,3 @@ -# -*- coding: utf-8 -*- """ salt._logging.impl ~~~~~~~~~~~~~~~~~~ @@ -6,15 +5,12 @@ Salt's logging implementation classes/functionality """ -# Import python libs -from __future__ import absolute_import, print_function, unicode_literals import logging import re import sys import types -# Import 3rd-party libs import salt.ext.six as six # Let's define these custom logging levels before importing the salt._logging.mixins @@ -23,8 +19,8 @@ PROFILE = logging.PROFILE = 15 TRACE = logging.TRACE = 5 GARBAGE = logging.GARBAGE = 1 QUIET = logging.QUIET = 1000 +DEBUG = logging.DEBUG = 10 -# Import Salt libs from salt._logging.handlers import StreamHandler # isort:skip # from salt._logging.handlers import SysLogHandler # isort:skip @@ -52,7 +48,7 @@ LOG_LEVELS = { "warning": logging.WARNING, } -LOG_VALUES_TO_LEVELS = dict((v, k) for (k, v) in LOG_LEVELS.items()) +LOG_VALUES_TO_LEVELS = {v: k for (k, v) in LOG_LEVELS.items()} LOG_COLORS = { "levels": { @@ -96,9 +92,7 @@ LOG_COLORS = { } # Make a list of log level names sorted by log level -SORTED_LEVEL_NAMES = [ - l[0] for l in sorted(six.iteritems(LOG_LEVELS), key=lambda x: x[1]) -] +SORTED_LEVEL_NAMES = [l[0] for l in sorted(LOG_LEVELS.items(), key=lambda x: x[1])] MODNAME_PATTERN = re.compile(r"(?P%%\(name\)(?:\-(?P[\d]+))?s)") @@ -168,8 +162,7 @@ def set_log_record_factory(factory): Set the logging log record factory """ get_log_record_factory.__factory__ = factory - if not six.PY2: - logging.setLogRecordFactory(factory) + logging.setLogRecordFactory(factory) set_log_record_factory(SaltLogRecord) @@ -180,7 +173,7 @@ LOGGING_LOGGER_CLASS = logging.getLoggerClass() class SaltLoggingClass( - six.with_metaclass(LoggingMixinMeta, LOGGING_LOGGER_CLASS, NewStyleClassMixin) + LOGGING_LOGGER_CLASS, NewStyleClassMixin, metaclass=LoggingMixinMeta ): def __new__(cls, *args): """ @@ -194,13 +187,11 @@ class SaltLoggingClass( logging.getLogger(__name__) """ - instance = super(SaltLoggingClass, cls).__new__(cls) + instance = super().__new__(cls) - try: - max_logger_length = len( - max(list(logging.Logger.manager.loggerDict), key=len) - ) - for handler in logging.root.handlers: + max_logger_length = len(max(list(logging.Logger.manager.loggerDict), key=len)) + for handler in logging.root.handlers: + try: if handler in ( LOGGING_NULL_HANDLER, LOGGING_STORE_HANDLER, @@ -221,18 +212,15 @@ class SaltLoggingClass( match = MODNAME_PATTERN.search(fmt) if not match: # Not matched. Release handler and return. - handler.release() return instance if "digits" not in match.groupdict(): # No digits group. Release handler and return. - handler.release() return instance digits = match.group("digits") if not digits or not (digits and digits.isdigit()): # No valid digits. Release handler and return. - handler.release() return instance if int(digits) < max_logger_length: @@ -243,9 +231,14 @@ class SaltLoggingClass( ) handler.setFormatter(formatter) handler.release() - except ValueError: - # There are no registered loggers yet - pass + except ValueError: + # There are no registered loggers yet + pass + finally: + try: + handler.release() + except: + pass return instance def _log( @@ -279,7 +272,7 @@ class SaltLoggingClass( "Only one of 'exc_info' and 'exc_info_on_loglevel' is " "permitted" ) if exc_info_on_loglevel is not None: - if isinstance(exc_info_on_loglevel, six.string_types): + if isinstance(exc_info_on_loglevel, str): exc_info_on_loglevel = LOG_LEVELS.get( exc_info_on_loglevel, logging.ERROR ) @@ -295,31 +288,37 @@ class SaltLoggingClass( else: extra["exc_info_on_loglevel"] = exc_info_on_loglevel - if sys.version_info < (3,): - LOGGING_LOGGER_CLASS._log( - self, level, msg, args, exc_info=exc_info, extra=extra - ) - elif sys.version_info < (3, 8): - LOGGING_LOGGER_CLASS._log( - self, - level, - msg, - args, - exc_info=exc_info, - extra=extra, - stack_info=stack_info, - ) - else: - LOGGING_LOGGER_CLASS._log( - self, - level, - msg, - args, - exc_info=exc_info, - extra=extra, - stack_info=stack_info, - stacklevel=stacklevel, - ) + try: + logging._acquireLock() + if sys.version_info < (3,): + LOGGING_LOGGER_CLASS._log( + self, level, msg, args, exc_info=exc_info, extra=extra + ) + elif sys.version_info < (3, 8): + LOGGING_LOGGER_CLASS._log( + self, + level, + msg, + args, + exc_info=exc_info, + extra=extra, + stack_info=stack_info, + ) + else: + LOGGING_LOGGER_CLASS._log( + self, + level, + msg, + args, + exc_info=exc_info, + extra=extra, + stack_info=stack_info, + stacklevel=stacklevel, + ) + except: + pass + finally: + logging._releaseLock() def makeRecord( self, @@ -357,7 +356,7 @@ class SaltLoggingClass( except NameError: salt_system_encoding = "utf-8" - if isinstance(msg, six.string_types) and not isinstance(msg, six.text_type): + if isinstance(msg, str) and not isinstance(msg, str): try: _msg = msg.decode(salt_system_encoding, "replace") except UnicodeDecodeError: @@ -367,9 +366,7 @@ class SaltLoggingClass( _args = [] for item in args: - if isinstance(item, six.string_types) and not isinstance( - item, six.text_type - ): + if isinstance(item, str) and not isinstance(item, str): try: _args.append(item.decode(salt_system_encoding, "replace")) except UnicodeDecodeError: @@ -378,24 +375,9 @@ class SaltLoggingClass( _args.append(item) _args = tuple(_args) - if six.PY2: - # Recreate what's done for Py >= 3.5 - _log_record_factory = get_log_record_factory() - logrecord = _log_record_factory( - name, level, fn, lno, _msg, _args, exc_info, func - ) - - if extra is not None: - for key in extra: - if (key in ["message", "asctime"]) or (key in logrecord.__dict__): - raise KeyError( - "Attempt to overwrite '{}' in LogRecord".format(key) - ) - logrecord.__dict__[key] = extra[key] - else: - logrecord = LOGGING_LOGGER_CLASS.makeRecord( - self, name, level, fn, lno, _msg, _args, exc_info, func, sinfo - ) + logrecord = LOGGING_LOGGER_CLASS.makeRecord( + self, name, level, fn, lno, _msg, _args, exc_info, func, sinfo + ) if exc_info_on_loglevel is not None: # Let's add some custom attributes to the LogRecord class in order @@ -419,6 +401,7 @@ if logging.getLoggerClass() is not SaltLoggingClass: logging.addLevelName(PROFILE, "PROFILE") logging.addLevelName(TRACE, "TRACE") logging.addLevelName(GARBAGE, "GARBAGE") + logging.addLevelName(DEBUG, "DEBUG") # ----- REMOVE ON REFACTORING COMPLETE --------------------------------------------------------------------------> if not logging.root.handlers: diff --git a/salt/client/ssh/__init__.py b/salt/client/ssh/__init__.py index ef9eb0c07e..6570fba5b1 100644 --- a/salt/client/ssh/__init__.py +++ b/salt/client/ssh/__init__.py @@ -532,7 +532,9 @@ class SSH: **target ) ret = {"id": single.id} + logging._acquireLock() stdout, stderr, retcode = single.run() + logging._releaseLock() # This job is done, yield try: data = salt.utils.json.find_json(stdout) @@ -600,8 +602,14 @@ class SSH: self.targets[host], mine, ) - routine = Process(target=self.handle_routine, args=args) - routine.start() + try: + logging._acquireLock() + routine = Process(target=self.handle_routine, args=args) + routine.start() + except: + pass + finally: + logging._releaseLock() running[host] = {"thread": routine} continue ret = {} diff --git a/salt/client/ssh/client.py b/salt/client/ssh/client.py index 55436366cf..d2dbdeb00e 100644 --- a/salt/client/ssh/client.py +++ b/salt/client/ssh/client.py @@ -1,14 +1,10 @@ -# -*- coding: utf-8 -*- - -# Import Python libs -from __future__ import absolute_import, print_function, unicode_literals - import copy import logging +import multiprocessing import os import random +import time -# Import Salt libs import salt.config import salt.syspaths as syspaths import salt.utils.args @@ -16,8 +12,10 @@ from salt.exceptions import SaltClientError # Temporary log = logging.getLogger(__name__) +_LOCK = multiprocessing.Lock() -class SSHClient(object): + +class SSHClient: """ Create a client object for executing routines via the salt-ssh backend @@ -60,7 +58,11 @@ class SSHClient(object): opts["selected_target_option"] = tgt_type opts["tgt"] = tgt opts["arg"] = arg - return salt.client.ssh.SSH(opts) + _LOCK.acquire() + ret = salt.client.ssh.SSH(opts) + time.sleep(0.01) + _LOCK.release() + return ret def cmd_iter( self, @@ -80,8 +82,7 @@ class SSHClient(object): .. versionadded:: 2015.5.0 """ ssh = self._prep_ssh(tgt, fun, arg, timeout, tgt_type, kwarg, **kwargs) - for ret in ssh.run_iter(jid=kwargs.get("jid", None)): - yield ret + yield from ssh.run_iter(jid=kwargs.get("jid", None)) def cmd( self, tgt, fun, arg=(), timeout=None, tgt_type="glob", kwarg=None, **kwargs diff --git a/salt/client/ssh/wrapper/cp.py b/salt/client/ssh/wrapper/cp.py index e369d8475f..eb37ae971b 100644 --- a/salt/client/ssh/wrapper/cp.py +++ b/salt/client/ssh/wrapper/cp.py @@ -1,15 +1,11 @@ -# -*- coding: utf-8 -*- """ Wrap the cp module allowing for managed ssh file transfers """ -# Import Python libs -from __future__ import absolute_import, print_function -import logging import os -# Import salt libs import salt.client.ssh +import salt.log.setup as logging import salt.utils.files import salt.utils.stringutils import salt.utils.templates @@ -107,7 +103,7 @@ def _render_filenames(path, dest, saltenv, template): if template not in salt.utils.templates.TEMPLATE_REGISTRY: raise CommandExecutionError( "Attempted to render file paths with unavailable engine " - "{0}".format(template) + "{}".format(template) ) kwargs = {} @@ -133,7 +129,7 @@ def _render_filenames(path, dest, saltenv, template): if not data["result"]: # Failed to render the template raise CommandExecutionError( - "Failed to render file path with error: {0}".format(data["data"]) + "Failed to render file path with error: {}".format(data["data"]) ) else: return data["data"] diff --git a/salt/loader.py b/salt/loader.py index 9a9c11b401..cfcd18f6f3 100644 --- a/salt/loader.py +++ b/salt/loader.py @@ -8,7 +8,6 @@ import functools import importlib.machinery # pylint: disable=no-name-in-module,import-error import importlib.util # pylint: disable=no-name-in-module,import-error import inspect -import logging import os import re import sys @@ -23,6 +22,7 @@ from zipimport import zipimporter import salt.config import salt.defaults.events import salt.defaults.exitcodes +import salt.log.setup as logging import salt.syspaths import salt.utils.args import salt.utils.context diff --git a/salt/utils/lazy.py b/salt/utils/lazy.py index 8fc538164a..c828dd2c32 100644 --- a/salt/utils/lazy.py +++ b/salt/utils/lazy.py @@ -1,15 +1,13 @@ -# -*- coding: utf-8 -*- """ Lazily-evaluated data structures, primarily used by Salt's loader """ -# Import Python Libs -from __future__ import absolute_import, unicode_literals -import logging +import time from collections.abc import MutableMapping import salt.exceptions +import salt.log.setup as logging log = logging.getLogger(__name__) @@ -81,7 +79,7 @@ class LazyDict(MutableMapping): Override this to return a more meaningfull error message if possible """ - return "'{0}' is not available.".format(function_name) + return "'{}' is not available.".format(function_name) def __setitem__(self, key, val): self._dict[key] = val @@ -100,11 +98,13 @@ class LazyDict(MutableMapping): # load the item if self._load(key): log.debug("LazyLoaded %s", key) + time.sleep(0.0001) return self._dict[key] else: log.debug( "Could not LazyLoad %s: %s", key, self.missing_fun_string(key) ) + time.sleep(0.0001) raise KeyError(key) else: return self._dict[key] -- 2.29.2