diff --git a/changelog/66927.fixed.md b/changelog/66927.fixed.md new file mode 100644 index 000000000000..f3295b6357ef --- /dev/null +++ b/changelog/66927.fixed.md @@ -0,0 +1 @@ +Prevent `KeyError` raised by module `__virtual__()` during loader initialization from being logged as an error; log it at debug level instead. diff --git a/salt/loader/lazy.py b/salt/loader/lazy.py index 677371f6734a..7820c16e191f 100644 --- a/salt/loader/lazy.py +++ b/salt/loader/lazy.py @@ -1281,6 +1281,15 @@ def _process_virtual(self, mod, module_name, virtual_func="__virtual__"): end, module_name ) log.warning(msg) + + except KeyError as exc: + error_reason = ( + "Missing loader context while processing __virtual__ " + "for {}: {}".format(mod.__name__, exc) + ) + log.debug(error_reason, exc_info=exc) + virtual = None + except Exception as exc: # pylint: disable=broad-except error_reason = ( "Exception raised when processing __virtual__ function" diff --git a/tests/unit/test_loader.py b/tests/unit/test_loader.py index b7266c59effe..6a65a04019e6 100644 --- a/tests/unit/test_loader.py +++ b/tests/unit/test_loader.py @@ -28,6 +28,7 @@ from tests.support.mock import MagicMock, patch from tests.support.runtests import RUNTIME_VARS from tests.support.unit import TestCase +from tests.support.helpers import dedent log = logging.getLogger(__name__) @@ -1794,3 +1795,83 @@ def test_lazyloader_pyx_modules(self): loader = self.__init_loader() assert ".pyx" not in loader.suffix_map assert ".pyx" not in loader.suffix_order + + +class LazyLoaderVirtualExceptionLoggingTest(TestCase): + """ + Ensure _process_virtual logs KeyError as debug and other exceptions as error. + """ + + def setUp(self): + self.opts = salt.config.minion_config(None) + self.opts["grains"] = salt.loader.grains(self.opts) + + self.utils = salt.loader.utils(copy.deepcopy(self.opts)) + self.proxy = salt.loader.proxy(self.opts) + self.funcs = salt.loader.minion_mods( + self.opts, utils=self.utils, proxy=self.proxy + ) + + self.module_dir = tempfile.mkdtemp(dir=RUNTIME_VARS.TMP) + self.addCleanup(shutil.rmtree, self.module_dir, ignore_errors=True) + + def _make_loader(self, module_code): + path = os.path.join(self.module_dir, "badmod.py") + + with salt.utils.files.fopen(path, "w") as fh: + fh.write(salt.utils.stringutils.to_str(module_code)) + + return salt.loader.LazyLoader( + [self.module_dir], + copy.deepcopy(self.opts), + pack={ + "__utils__": self.utils, + "__salt__": self.funcs, + "__proxy__": self.proxy, + }, + tag="module", + ) + + def test_keyerror_is_debug_not_error(self): + module = dedent( + """ + def __virtual__(): + raise KeyError("boom") + + def run(): + return True + """ + ) + + loader = self._make_loader(module) + + with patch.object(salt.loader.lazy.log, "error") as mock_error, patch.object( + salt.loader.lazy.log, "debug" + ) as mock_debug: + + _ = "badmod.run" in loader + + mock_error.assert_not_called() + self.assertTrue(mock_debug.called) + + def test_other_exception_is_error(self): + module = dedent( + """ + def __virtual__(): + raise ValueError("boom") + + def run(): + return True + """ + ) + + loader = self._make_loader(module) + + with patch.object(salt.loader.lazy.log, "error") as mock_error, patch.object( + salt.loader.lazy.log, "debug" + ) as mock_debug: + + _ = "badmod.run" in loader + + mock_error.assert_called() + mock_debug.assert_not_called()