From eb15f772aa7aa6c9553bb4f24c709e941e6f3413 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 | 80 +++++++++++++++++++---------------- salt/client/ssh/__init__.py | 12 +++++- salt/client/ssh/client.py | 9 +++- salt/client/ssh/wrapper/cp.py | 2 +- salt/loader.py | 6 +-- salt/utils/lazy.py | 10 ++--- 6 files changed, 71 insertions(+), 48 deletions(-) diff --git a/salt/_logging/impl.py b/salt/_logging/impl.py index afb0027eeb..ad46c10e01 100644 --- a/salt/_logging/impl.py +++ b/salt/_logging/impl.py @@ -15,6 +15,7 @@ PROFILE = logging.PROFILE = 15 TRACE = logging.TRACE = 5 GARBAGE = logging.GARBAGE = 1 QUIET = logging.QUIET = 1000 +DEBUG = logging.DEBUG = 10 from salt._logging.handlers import StreamHandler # isort:skip @@ -182,11 +183,9 @@ class SaltLoggingClass( """ 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, @@ -207,18 +206,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: @@ -229,9 +225,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( @@ -281,31 +282,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, @@ -395,6 +402,7 @@ if logging.getLoggerClass() is not SaltLoggingClass: logging.addLevelName(PROFILE, "PROFILE") logging.addLevelName(TRACE, "TRACE") logging.addLevelName(GARBAGE, "GARBAGE") + logging.addLevelName(DEBUG, "DEBUG") if pip_log_module is not None: # Let's make newer versions of pip work by patching SaltLoggingClass to # add a verbose method which is what pip expects diff --git a/salt/client/ssh/__init__.py b/salt/client/ssh/__init__.py index 01fb5e9a30..a4a74aa2c2 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 ef4287463b..037aea779c 100644 --- a/salt/client/ssh/client.py +++ b/salt/client/ssh/client.py @@ -1,7 +1,9 @@ import copy import logging +import multiprocessing import os import random +import time import salt.config import salt.syspaths @@ -10,6 +12,7 @@ from salt.exceptions import SaltClientError log = logging.getLogger(__name__) +_LOCK = multiprocessing.Lock() class SSHClient: """ @@ -124,7 +127,11 @@ class SSHClient: 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, diff --git a/salt/client/ssh/wrapper/cp.py b/salt/client/ssh/wrapper/cp.py index 020dadfa35..af7d4f73f4 100644 --- a/salt/client/ssh/wrapper/cp.py +++ b/salt/client/ssh/wrapper/cp.py @@ -2,10 +2,10 @@ Wrap the cp module allowing for managed ssh file transfers """ -import logging import os import salt.client.ssh +import salt.log.setup as logging import salt.utils.files import salt.utils.stringutils import salt.utils.templates diff --git a/salt/loader.py b/salt/loader.py index 491768a028..cdcec70262 100644 --- a/salt/loader.py +++ b/salt/loader.py @@ -10,7 +10,6 @@ import importlib 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 @@ -27,6 +26,7 @@ import salt.config import salt.defaults.events import salt.defaults.exitcodes import salt.loader_context +import salt.log.setup as logging import salt.syspaths import salt.utils.args import salt.utils.context @@ -2195,7 +2195,7 @@ class LazyLoader(salt.utils.lazy.LazyDict): mod.__name__, exc ) ) - log.error(error_reason, exc_info_on_loglevel=logging.DEBUG) + log.error(error_reason, exc_info_on_loglevel=logging.logging.DEBUG) virtual = None # Get the module's virtual name virtualname = getattr(mod, "__virtualname__", virtual) @@ -2341,5 +2341,5 @@ def catch_entry_points_exception(entry_point): entry_point_details.name, entry_point_details.version, exc, - exc_info_on_loglevel=logging.DEBUG, + exc_info_on_loglevel=logging.logging.DEBUG, ) 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.33.0