Merge pull request #5545 from tk0miya/refactor_loading_extensions

Refactor loading extensions

CHANGES

@@ -21,6 +21,7 @@ Deprecated
 
 * The ``suffix`` argument of ``env.doc2path()`` is deprecated.
 * The string style ``base`` argument of ``env.doc2path()`` is deprecated.
+* ``sphinx.application.Sphinx._setting_up_extension``
 * ``sphinx.ext.doctest.doctest_encode()``
 * ``sphinx.testing.util.remove_unicode_literal()``
 * ``sphinx.util.get_matching_docs()`` is deprecated

doc/extdev/index.rst

@@ -153,6 +153,11 @@ The following is a list of deprecated interfaces.
      - 4.0
      - ``os.walk()``
 
+   * - ``sphinx.application.Sphinx._setting_up_extension``
+     - 2.0
+     - 3.0
+     - N/A
+
    * - :rst:dir:`highlightlang`
      - 1.8
      - 4.0

doc/extdev/logging.rst

@@ -62,3 +62,5 @@ Logging API
 .. autofunction:: pending_logging()
 
 .. autofunction:: pending_warnings()
+
+.. autofunction:: prefixed_warnings()

sphinx/application.py

@@ -44,6 +44,7 @@ from sphinx.util.build_phase import BuildPhase
 from sphinx.util.console import bold  # type: ignore
 from sphinx.util.docutils import directive_helper
 from sphinx.util.i18n import find_catalog_source_files
+from sphinx.util.logging import prefixed_warnings
 from sphinx.util.osutil import abspath, ensuredir, relpath
 from sphinx.util.tags import Tags
 
@@ -135,7 +136,6 @@ class Sphinx:
         self.phase = BuildPhase.INITIALIZATION
         self.verbosity = verbosity
         self.extensions = {}                    # type: Dict[unicode, Extension]
-        self._setting_up_extension = ['?']      # type: List[unicode]
         self.builder = None                     # type: Builder
         self.env = None                         # type: BuildEnvironment
         self.project = None                     # type: Project
@@ -237,15 +237,16 @@ class Sphinx:
 
         # the config file itself can be an extension
         if self.config.setup:
-            self._setting_up_extension = ['conf.py']
+            prefix = __('while setting up extension %s:') % "conf.py"
-            if callable(self.config.setup):
+            with prefixed_warnings(prefix):
-                self.config.setup(self)
+                if callable(self.config.setup):
-            else:
+                    self.config.setup(self)
-                raise ConfigError(
+                else:
-                    __("'setup' as currently defined in conf.py isn't a Python callable. "
+                    raise ConfigError(
-                       "Please modify its definition to make it a callable function. This is "
+                        __("'setup' as currently defined in conf.py isn't a Python callable. "
-                       "needed for conf.py to behave as a Sphinx extension.")
+                           "Please modify its definition to make it a callable function. "
-                )
+                           "This is needed for conf.py to behave as a Sphinx extension.")
+                    )
 
         # now that we know all config values, collect them from conf.py
         self.config.init_values()
@@ -555,10 +556,9 @@ class Sphinx:
         """
         logger.debug('[app] adding node: %r', (node, kwds))
         if not override and docutils.is_node_registered(node):
-            logger.warning(__('while setting up extension %s: node class %r is '
+            logger.warning(__('node class %r is already registered, '
-                              'already registered, its visitors will be overridden'),
+                              'its visitors will be overridden'),
-                           self._setting_up_extension, node.__name__,
+                           node.__name__, type='app', subtype='add_node')
-                           type='app', subtype='add_node')
         docutils.register_node(node)
         self.registry.add_translation_handlers(node, **kwds)
 
@@ -653,10 +653,8 @@ class Sphinx:
         logger.debug('[app] adding directive: %r',
                      (name, obj, content, arguments, options))
         if name in directives._directives and not override:
-            logger.warning(__('while setting up extension %s: directive %r is '
+            logger.warning(__('directive %r is already registered, it will be overridden'),
-                              'already registered, it will be overridden'),
+                           name, type='app', subtype='add_directive')
-                           self._setting_up_extension[-1], name,
-                           type='app', subtype='add_directive')
 
         if not isclass(obj) or not issubclass(obj, Directive):
             directive = directive_helper(obj, content, arguments, **options)
@@ -678,10 +676,8 @@ class Sphinx:
         """
         logger.debug('[app] adding role: %r', (name, role))
         if name in roles._roles and not override:
-            logger.warning(__('while setting up extension %s: role %r is '
+            logger.warning(__('role %r is already registered, it will be overridden'),
-                              'already registered, it will be overridden'),
+                           name, type='app', subtype='add_role')
-                           self._setting_up_extension[-1], name,
-                           type='app', subtype='add_role')
         roles.register_local_role(name, role)
 
     def add_generic_role(self, name, nodeclass, override=False):
@@ -699,10 +695,8 @@ class Sphinx:
         # ``register_canonical_role``.
         logger.debug('[app] adding generic role: %r', (name, nodeclass))
         if name in roles._roles and not override:
-            logger.warning(__('while setting up extension %s: role %r is '
+            logger.warning(__('role %r is already registered, it will be overridden'),
-                              'already registered, it will be overridden'),
+                           name, type='app', subtype='add_generic_role')
-                           self._setting_up_extension[-1], name,
-                           type='app', subtype='add_generic_role')
         role = roles.GenericRole(name, nodeclass)
         roles.register_local_role(name, role)
 
@@ -1210,6 +1204,13 @@ class Sphinx:
 
         return True
 
+    @property
+    def _setting_up_extension(self):
+        # type: () -> List[unicode]
+        warnings.warn('app._setting_up_extension is deprecated.',
+                      RemovedInSphinx30Warning)
+        return ['?']
+
 
 class TemplateBridge:
     """

sphinx/registry.py

@@ -28,6 +28,7 @@ from sphinx.parsers import Parser as SphinxParser
 from sphinx.roles import XRefRole
 from sphinx.util import logging
 from sphinx.util.docutils import directive_helper
+from sphinx.util.logging import prefixed_warnings
 
 if False:
     # For type annotation
@@ -465,39 +466,38 @@ class SphinxComponentRegistry:
             return
 
         # update loading context
-        app._setting_up_extension.append(extname)
+        prefix = __('while setting up extension %s:') % extname
-
+        with prefixed_warnings(prefix):
-        try:
-            mod = __import__(extname, None, None, ['setup'])
-        except ImportError as err:
-            logger.verbose(__('Original exception:\n') + traceback.format_exc())
-            raise ExtensionError(__('Could not import extension %s') % extname, err)
-
-        if not hasattr(mod, 'setup'):
-            logger.warning(__('extension %r has no setup() function; is it really '
-                              'a Sphinx extension module?'), extname)
-            metadata = {}  # type: Dict[unicode, Any]
-        else:
             try:
-                metadata = mod.setup(app)
+                mod = __import__(extname, None, None, ['setup'])
-            except VersionRequirementError as err:
+            except ImportError as err:
-                # add the extension name to the version required
+                logger.verbose(__('Original exception:\n') + traceback.format_exc())
-                raise VersionRequirementError(
+                raise ExtensionError(__('Could not import extension %s') % extname, err)
-                    __('The %s extension used by this project needs at least '
-                       'Sphinx v%s; it therefore cannot be built with this '
-                       'version.') % (extname, err)
-                )
 
-        if metadata is None:
+            if not hasattr(mod, 'setup'):
-            metadata = {}
+                logger.warning(__('extension %r has no setup() function; is it really '
-        elif not isinstance(metadata, dict):
+                                  'a Sphinx extension module?'), extname)
-            logger.warning(__('extension %r returned an unsupported object from '
+                metadata = {}  # type: Dict[unicode, Any]
-                              'its setup() function; it should return None or a '
+            else:
-                              'metadata dictionary'), extname)
+                try:
-            metadata = {}
+                    metadata = mod.setup(app)
+                except VersionRequirementError as err:
+                    # add the extension name to the version required
+                    raise VersionRequirementError(
+                        __('The %s extension used by this project needs at least '
+                           'Sphinx v%s; it therefore cannot be built with this '
+                           'version.') % (extname, err)
+                    )
 
-        app.extensions[extname] = Extension(extname, mod, **metadata)
+            if metadata is None:
-        app._setting_up_extension.pop()
+                metadata = {}
+            elif not isinstance(metadata, dict):
+                logger.warning(__('extension %r returned an unsupported object from '
+                                  'its setup() function; it should return None or a '
+                                  'metadata dictionary'), extname)
+                metadata = {}
+
+            app.extensions[extname] = Extension(extname, mod, **metadata)
 
     def get_envversion(self, app):
         # type: (Sphinx) -> Dict[unicode, unicode]

sphinx/util/logging.py

@@ -287,6 +287,53 @@ def skip_warningiserror(skip=True):
                 handler.removeFilter(disabler)
 
 
+@contextmanager
+def prefixed_warnings(prefix):
+    # type: (unicode) -> Generator
+    """Prepend prefix to all records for a while.
+
+    For example::
+
+        >>> with prefixed_warnings("prefix:"):
+        >>>     logger.warning('Warning message!')  # => prefix: Warning message!
+
+    .. versionadded:: 2.0
+    """
+    logger = logging.getLogger(NAMESPACE)
+    warning_handler = None
+    for handler in logger.handlers:
+        if isinstance(handler, WarningStreamHandler):
+            warning_handler = handler
+            break
+    else:
+        # warning stream not found
+        yield
+        return
+
+    prefix_filter = None
+    for _filter in warning_handler.filters:
+        if isinstance(_filter, MessagePrefixFilter):
+            prefix_filter = _filter
+            break
+
+    if prefix_filter:
+        # already prefixed
+        try:
+            previous = prefix_filter.prefix
+            prefix_filter.prefix = prefix
+            yield
+        finally:
+            prefix_filter.prefix = previous
+    else:
+        # not prefixed yet
+        try:
+            prefix_filter = MessagePrefixFilter(prefix)
+            warning_handler.addFilter(prefix_filter)
+            yield
+        finally:
+            warning_handler.removeFilter(prefix_filter)
+
+
 class LogCollector:
     def __init__(self):
         # type: () -> None
@@ -395,6 +442,21 @@ class DisableWarningIsErrorFilter(logging.Filter):
         return True
 
 
+class MessagePrefixFilter(logging.Filter):
+    """Prepend prefix to all records."""
+
+    def __init__(self, prefix):
+        # type: (unicode) -> None
+        self.prefix = prefix
+        super(MessagePrefixFilter, self).__init__()
+
+    def filter(self, record):
+        # type: (logging.LogRecord) -> bool
+        if self.prefix:
+            record.msg = self.prefix + ' ' + record.msg  # type: ignore
+        return True
+
+
 class SphinxLogRecordTranslator(logging.Filter):
     """Converts a log record to one Sphinx expects
 

tests/test_application.py

@@ -48,7 +48,8 @@ def test_emit_with_nonascii_name_node(app, status, warning):
 
 def test_extensions(app, status, warning):
     app.setup_extension('shutil')
-    assert strip_escseq(warning.getvalue()).startswith("WARNING: extension 'shutil'")
+    warning = strip_escseq(warning.getvalue())
+    assert "extension 'shutil' has no setup() function" in warning
 
 
 def test_extension_in_blacklist(app, status, warning):

tests/test_util_logging.py

@@ -20,7 +20,7 @@ from sphinx.errors import SphinxWarning
 from sphinx.testing.util import strip_escseq
 from sphinx.util import logging
 from sphinx.util.console import colorize
-from sphinx.util.logging import is_suppressed_warning
+from sphinx.util.logging import is_suppressed_warning, prefixed_warnings
 from sphinx.util.parallel import ParallelTasks
 
 
@@ -330,3 +330,22 @@ def test_skip_warningiserror(app, status, warning):
         with logging.pending_warnings():
             with logging.skip_warningiserror(False):
                 logger.warning('message')
+
+
+def test_prefixed_warnings(app, status, warning):
+    logging.setup(app, status, warning)
+    logger = logging.getLogger(__name__)
+
+    logger.warning('message1')
+    with prefixed_warnings('PREFIX:'):
+        logger.warning('message2')
+        with prefixed_warnings('Another PREFIX:'):
+            logger.warning('message3')
+        logger.warning('message4')
+    logger.warning('message5')
+
+    assert 'WARNING: message1' in warning.getvalue()
+    assert 'WARNING: PREFIX: message2' in warning.getvalue()
+    assert 'WARNING: Another PREFIX: message3' in warning.getvalue()
+    assert 'WARNING: PREFIX: message4' in warning.getvalue()
+    assert 'WARNING: message5' in warning.getvalue()