salt/prevent-logging-deadlock-on-salt-api-subprocesses-bs.patch

From 4e6cc0c401bd6c9e47b324fc2df99e3bd679da33 Mon Sep 17 00:00:00 2001
From: =?UTF-8?q?Pablo=20Su=C3=A1rez=20Hern=C3=A1ndez?=
 <psuarezhernandez@suse.com>
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>%%\(name\)(?:\-(?P<digits>[\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