Refactor logging during plugin discovery, using tmt's logging

Instead of `fmf.utils.Logging`, using a dedicated bootstrap logger when
imported in `cli.py`. That should give us some tree-like, nested log
messages to illustrate different sources, plus we get the behavior &
implementation the tmt uses.

bin/tmt

@@ -1,9 +1,16 @@
 #!/usr/bin/python
 
-import tmt.cli
-import tmt.utils
-
 try:
+    # Cover imports with try/except, to handle errors raised while importing
+    # tmt packages. Some may perform actions in import-time, and may raise
+    # exceptions.
+
+    # Import utils first, before CLI gets a chance to spawn a logger. Without
+    # tmt.utils, we would not be able to intercept the exception below.
+    import tmt.utils
+
+    import tmt.cli  # isort: skip
+
     tmt.cli.main()
 
 # Basic error message for general errors

docs/conf.py

@@ -17,6 +17,7 @@
 from unittest.mock import Mock as MagicMock
 
 import tmt.plugins
+import tmt.utils
 from tmt.utils import Path
 
 try:
@@ -254,11 +255,14 @@ def __getattr__(cls, name: str) -> 'Mock':
 MOCK_MODULES = ['testcloud', 'testcloud.image', 'testcloud.instance']
 sys.modules.update((mod_name, Mock()) for mod_name in MOCK_MODULES)
 
+# We will need a logger...
+logger = tmt.Logger.create()
+
 # Explore available *export* plugins - do not import other plugins, we don't need them.
-tmt.plugins._explore_export_directory()
+tmt.plugins.explore_export_package(logger)
 
 # Generate stories
-tree = tmt.Tree(logger=tmt.Logger.create(), path=Path.cwd())
+tree = tmt.Tree(logger=logger, path=Path.cwd())
 
 areas = {
     '/stories/docs': 'Documentation',

tests/core/env/test.sh

@@ -9,9 +9,9 @@ rlJournalStart
     rlPhaseEnd
 
     rlPhaseStartTest "Check the TMT_DEBUG variable"
-        rlRun -s "TMT_DEBUG=3 tmt plan show 2>&1 >/dev/null"
+        rlRun -s "TMT_DEBUG=3 tmt plan show"
         rlAssertGrep "Using the 'DiscoverFmf' plugin" $rlRun_LOG
-        rlRun -s "TMT_DEBUG=weird tmt plan show 2>&1 >/dev/null" 2
+        rlRun -s "TMT_DEBUG=weird tmt plan show" 1
         rlAssertGrep "Invalid debug level" $rlRun_LOG
     rlPhaseEnd
 

tests/unit/test_schemas.py

@@ -67,7 +67,7 @@ def _iter_stories_in_tree(tree):
 
 
 def validate_node(tree, node, schema, label, name):
-    errors = tmt.utils.validate_fmf_node(node, schema)
+    errors = tmt.utils.validate_fmf_node(node, schema, LOGGER)
 
     if errors:
         print(f"""A node in tree loaded from {str(_tree_path(tree))} failed validation

tests/unit/test_utils.py

@@ -869,24 +869,31 @@ def check():
         wait(Common(logger=root_logger), check, datetime.timedelta(seconds=1))
 
 
-def test_import_member():
-    klass = tmt.plugins.import_member('tmt.steps.discover', 'Discover')
+def test_import_member(root_logger):
+    klass = tmt.plugins.import_member(
+        module_name='tmt.steps.discover', member_name='Discover', logger=root_logger)
 
     assert klass is tmt.steps.discover.Discover
 
 
-def test_import_member_no_such_module():
+def test_import_member_no_such_module(root_logger):
     with pytest.raises(
             tmt.utils.GeneralError,
             match=r"Failed to import module 'tmt\.steps\.nope_does_not_exist'."):
-        tmt.plugins.import_member('tmt.steps.nope_does_not_exist', 'Discover')
+        tmt.plugins.import_member(
+            module_name='tmt.steps.nope_does_not_exist',
+            member_name='Discover',
+            logger=root_logger)
 
 
-def test_import_member_no_such_class():
+def test_import_member_no_such_class(root_logger):
     with pytest.raises(
             tmt.utils.GeneralError,
             match=r"No such member 'NopeDoesNotExist' in module 'tmt\.steps\.discover'."):
-        tmt.plugins.import_member('tmt.steps.discover', 'NopeDoesNotExist')
+        tmt.plugins.import_member(
+            module_name='tmt.steps.discover',
+            member_name='NopeDoesNotExist',
+            logger=root_logger)
 
 
 def test_common_base_inheritance(root_logger):

tmt/base.py

@@ -23,6 +23,7 @@
 import tmt.export
 import tmt.identifier
 import tmt.log
+import tmt.plugins
 import tmt.steps
 import tmt.steps.discover
 import tmt.steps.execute
@@ -1583,7 +1584,7 @@ def lint(self) -> bool:
         self.ls()
 
         # Explore all available plugins
-        tmt.plugins.explore()
+        tmt.plugins.explore(self._logger)
 
         invalid_keys = self.lint_keys(
             list(self.step_names(enabled=True, disabled=True)) +
@@ -2010,7 +2011,9 @@ def grow(
 
         import tmt.plugins
 
-        tmt.plugins.explore()
+        logger = logger or tmt.log.Logger.create()
+
+        tmt.plugins.explore(logger)
 
         return Tree(
             path=path,

tmt/cli.py

@@ -32,7 +32,7 @@
     import tmt.steps.execute
 
 # Explore available plugins (need to detect all supported methods first)
-tmt.plugins.explore()
+tmt.plugins.explore(tmt.log.Logger.get_bootstrap_logger())
 
 # ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
 #  Click Context Object Container

tmt/plugins/__init__.py

@@ -6,21 +6,18 @@
 import os
 import pkgutil
 import sys
-from typing import Any, Generator, Optional
+from typing import Any, Generator, List, Optional, Tuple
 
 if sys.version_info < (3, 9):
     from importlib_metadata import entry_points
 else:
     from importlib.metadata import entry_points
 
-import fmf
-
 import tmt
+from tmt.log import Logger
 from tmt.steps import STEPS
 from tmt.utils import Path
 
-log = fmf.utils.Logging('tmt').logger
-
 # Two possibilities to load additional plugins:
 # entry_points (setup_tools)
 ENTRY_POINT_NAME = 'tmt.plugin'
@@ -31,88 +28,155 @@
 _TMT_ROOT = Path(tmt.__file__).resolve().parent
 
 
-def _explore_steps_directories(root: Path = _TMT_ROOT) -> None:
-    """ Check all tmt steps for native plugins """
+def discover(path: Path) -> Generator[str, None, None]:
+    """ Discover available plugins for given paths """
+    for _, name, package in pkgutil.iter_modules([str(path)]):
+        if not package:
+            yield name
+
 
-    for step in STEPS:
-        for module in discover(root / 'steps' / step):
-            import_(f'tmt.steps.{step}.{module}')
+#
+# Explore available sources, and load all plugins found. Possible sources are:
+#
+# * tmt's own packages (_explore_packages)
+#    - tmt.steps.*
+#    - tmt.export
+#    - tmt.plugins
+#
+# * directories (_explore_directories)
+#    - directories listed in TMT_PLUGINS envvar
+#
+# * packaging entry points (_explore_entry_points)
+#    - tmt.plugin
+#
 
+# A list of tmt (sub)packages that may contain plugins. For each package, we
+# track the package name and its path relative to tmt package sources.
+#
+# If you think of adding new package with plugins tmt should load on start,
+# this is the place.
+_DISCOVER_PACKAGES: List[Tuple[str, Path]] = [
+    (f'tmt.steps.{step}', Path('steps') / step)
+    for step in STEPS
+    ] + [
+    ('tmt.plugins', Path('plugins')),
+    ('tmt.export', Path('export'))
+    ]
 
-def _explore_plugins_directory(root: Path = _TMT_ROOT) -> None:
-    """ Check for possible plugins in the 'plugins' directory """
 
-    for module in discover(root / 'plugins'):
-        import_(f'tmt.plugins.{module}')
+def _explore_package(package: str, path: Path, logger: Logger) -> None:
+    """ Import plugins from a given Python package """
 
+    logger.debug(f"Import plugins from the '{package}' package.")
+    logger = logger.descend()
 
-def _explore_export_directory(root: Path = _TMT_ROOT) -> None:
-    """ Check for possible plugins in the 'export' directory """
+    for module in discover(path):
+        import_(module=f'{package}.{module}', logger=logger)
 
-    for module in discover(root / 'export'):
-        import_(f'tmt.export.{module}')
 
+def _explore_directory(path: Path, logger: Logger) -> None:
+    """ Import plugins dropped into a directory """
 
-def _explore_custom_directories() -> None:
-    """ Check environment variable for user plugins """
+    logger.debug(f"Import plugins from the '{path}' directory.")
+    logger = logger.descend()
 
-    try:
-        paths = [
-            Path(os.path.expandvars(path)).expanduser().resolve()
-            for path in os.environ[ENVIRONMENT_NAME].split(os.pathsep)]
-    except KeyError:
-        log.debug(f'No custom plugin locations detected in {ENVIRONMENT_NAME}.')
-        paths = []
-    for path in paths:
-        for module in discover(path):
-            if str(path) not in sys.path:
-                sys.path.insert(0, str(path))
-            import_(module, path)
+    _path = str(path)
 
+    for module in discover(path):
+        if _path not in sys.path:
+            sys.path.insert(0, _path)
 
-def _explore_plugins_directories() -> None:
-    _explore_steps_directories()
-    _explore_plugins_directory()
-    _explore_export_directory()
-    _explore_custom_directories()
+        import_(module=module, path=path, logger=logger)
 
 
-def _explore_entry_points() -> None:
-    """ Import by entry_points """
+def _explore_custom_directories(logger: Logger) -> None:
+    """ Import plugins from directories listed in ``TMT_PLUGINS`` envvar """
+
+    logger.debug('Import plugins from custom directories.')
+    logger = logger.descend()
+
+    if not os.environ.get(ENVIRONMENT_NAME):
+        logger.debug(
+            f"No custom directories found in the '{ENVIRONMENT_NAME}' environment variable.")
+        return
+
+    for _path in os.environ[ENVIRONMENT_NAME].split(os.pathsep):
+        _explore_directory(
+            Path(os.path.expandvars(os.path.expanduser(_path))).resolve(),
+            logger)
+
+
+def _explore_entry_point(entry_point: str, logger: Logger) -> None:
+    """ Import all plugins hooked to an entry points """
+
+    logger.debug(f"Import plugins from the '{entry_point}' entry point.")
+    logger = logger.descend()
 
     try:
-        for found in entry_points()[ENTRY_POINT_NAME]:
-            log.debug(f'Loading plugin "{found.name}" ({found.value}).')
+        for found in entry_points()[entry_point]:
+            logger.debug(f"Loading plugin '{found.name}' ({found.value}).")
             found.load()
+
     except KeyError:
-        log.debug(f'No custom plugins detected for "{ENTRY_POINT_NAME}".')
+        logger.debug(f"No plugins detected for the '{entry_point}' entry point.")
+
+
+def _explore_packages(logger: Logger) -> None:
+    """ Import all plugins bundled into tmt package """
 
+    logger.debug('Import plugins from tmt packages.')
 
-def explore() -> None:
-    """ Explore all available plugins """
+    for name, path in _DISCOVER_PACKAGES:
+        _explore_package(name, _TMT_ROOT / path, logger.descend())
 
-    _explore_plugins_directories()
-    _explore_entry_points()
 
+def _explore_directories(logger: Logger) -> None:
+    """ Import all plugins from various directories """
 
-def import_(module: str, path: Optional[Path] = None) -> None:
+    logger.debug('Import plugins from custom directories.')
+
+    _explore_custom_directories(logger.descend())
+
+
+def _explore_entry_points(logger: Logger) -> None:
+    """ Import all plugins hooked to entry points """
+
+    logger.debug('Import plugins from entry points.')
+
+    _explore_entry_point(ENTRY_POINT_NAME, logger.descend())
+
+
+def explore(logger: Logger) -> None:
+    """ Explore all available plugin locations """
+
+    _explore_packages(logger)
+    _explore_directories(logger)
+    _explore_entry_points(logger)
+
+
+def import_(*, module: str, path: Optional[Path] = None, logger: Logger) -> None:
     """ Attempt to import requested module """
+
+    if module in sys.modules:
+        logger.debug(f"Module '{module}' already imported.")
+        return
+
     try:
         importlib.import_module(module)
-        log.debug(f"Successfully imported the '{module}' module.")
+        logger.debug(f"Successfully imported the '{module}' module.")
     except (ImportError, SystemExit) as error:
         # setup.py when executed during import raises SystemExit
         raise SystemExit(
             f"Failed to import the '{module}' module" +
-            (f" from '{path}'." if path else ".") + f"\n({error})")
+            (f" from '{path}'." if path else ".")) from error
 
 
-def import_member(module_name: str, member_name: str) -> Any:
+def import_member(*, module_name: str, member_name: str, logger: Logger) -> Any:
     """ Import member from given module, handle errors nicely """
     # Make sure the module is imported. It probably is, but really,
     # make sure of it.
     try:
-        import_(module_name)
+        import_(module=module_name, logger=logger)
     except SystemExit as exc:
         raise tmt.utils.GeneralError(f"Failed to import module '{module_name}'.") from exc
 
@@ -128,8 +192,9 @@ def import_member(module_name: str, member_name: str) -> Any:
     return getattr(module, member_name)
 
 
-def discover(path: Path) -> Generator[str, None, None]:
-    """ Discover available plugins for given paths """
-    for _, name, package in pkgutil.iter_modules([str(path)]):
-        if not package:
-            yield name
+# Small helper for one specific package - export plugins are needed when
+# generating docs.
+def explore_export_package(logger: Logger) -> None:
+    """ Import all plugins bundled into tmt.export package """
+
+    _explore_package('tmt.export', _TMT_ROOT / 'export', logger.descend())

tmt/steps/__init__.py

@@ -367,7 +367,8 @@ def load(self) -> None:
             self.debug('Successfully loaded step data.', level=2)
 
             self.data = [
-                StepData.unserialize(raw_datum) for raw_datum in raw_step_data['data']
+                StepData.unserialize(raw_datum, self._logger)
+                for raw_datum in raw_step_data['data']
                 ]
             self.status(raw_step_data['status'])
         except tmt.utils.GeneralError: