Traceback from trac.mimeview.pygments when wheel is installed

[Ryan J Ollos]

I've installed Trac with pip, which defaults to installing a wheel.

$pip --version
pip 7.1.2 from /Users/rjollos/Documents/Workspace/trac-dev/next-ticket/pve/lib/python2.7/site-packages (python 2.7)
$pip install ../trac-1.0-stable/
Processing /Users/rjollos/Documents/Workspace/trac-dev/trac-1.0-stable
Requirement already satisfied (use --upgrade to upgrade): setuptools>=0.6b1 in ./pve/lib/python2.7/site-packages (from Trac==1.0.10.dev0)
Collecting Genshi>=0.6 (from Trac==1.0.10.dev0)
Building wheels for collected packages: Trac
  Running setup.py bdist_wheel for Trac
  Stored in directory: /Users/rjollos/Library/Caches/pip/wheels/3f/60/12/c10dd2a8966cbc743d8922432155940b4a67ddc617edfedd51
Successfully built Trac
Installing collected packages: Genshi, Trac
Successfully installed Genshi-0.7 Trac-1.0.10.dev0

Now there is a traceback when Trac is started:

14:38:59 Trac[loader] ERROR: Skipping "trac.mimeview.pygments = trac.mimeview.pygments [pygments]": 
Traceback (most recent call last):
  File "/Users/rjollos/Documents/Workspace/trac-dev/pve1/lib/python2.7/site-packages/trac/loader.py", line 68, in _load_eggs
    entry.load(require=True)
  File "/Users/rjollos/Documents/Workspace/trac-dev/pve1/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2355, in load
    return self.resolve()
  File "/Users/rjollos/Documents/Workspace/trac-dev/pve1/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2361, in resolve
    module = __import__(self.module_name, fromlist=['__name__'], level=0)
  File "/Users/rjollos/Documents/Workspace/trac-dev/pve1/lib/python2.7/site-packages/trac/mimeview/pygments.py", line 16, in <module>
    import pygments
ImportError: No module named pygments

When installed with --no-use-wheel there is no traceback:

15:54:42 Trac[loader] DEBUG: Skipping "trac.mimeview.pygments = trac.mimeview.pygments [pygments]": ("DistributionNotFound: The 'Pygments>=0.6' distribution was not found and is required by the application" not found)

It seems we are encountering a ​reported issue with setuptools. I get the same results seen in that ticket.

When a wheel is installed:

>>> import pkg_resources
>>> d = pkg_resources.get_distribution('trac')
>>> d.requires(d.extras)
[Requirement.parse('Genshi>=0.6'), Requirement.parse('setuptools>=0.6b1')]

When installed with --no-use-wheel:

>>> import pkg_resources
>>> d = pkg_resources.get_distribution('trac')
>>> d.requires(d.extras)
[Requirement.parse('setuptools>=0.6b1'), Requirement.parse('Genshi>=0.6'), Requirement.parse('ConfigObj'), Requirement.parse('SilverCity>=0.9.4'), Requirement.parse('Babel>=0.9.5'), Requirement.parse('docutils>=0.3.9'), Requirement.parse('textile>=2.0'), Requirement.parse('Pygments>=0.6')]

The following is a workaround:

setup.py

@@ -105 +105 @@
     extras_require = {
         'Babel': ['Babel>=0.9.5'],
         'ConfigObj': ['ConfigObj'],
-        'Pygments': ['Pygments>=0.6'],
+        'pygments': ['Pygments>=0.6'],
         'reST': ['docutils>=0.3.9'],
         'SilverCity': ['SilverCity>=0.9.4'],
         'Textile': ['textile>=2.0'],
@@ -125 +125 @@
         trac.db.postgres = trac.db.postgres_backend
         trac.db.sqlite = trac.db.sqlite_backend
         trac.mimeview.patch = trac.mimeview.patch
-        trac.mimeview.pygments = trac.mimeview.pygments[Pygments]
+        trac.mimeview.pygments = trac.mimeview.pygments[pygments]
         trac.mimeview.rst = trac.mimeview.rst[reST]
         trac.mimeview.txtl = trac.mimeview.txtl[Textile]
         trac.prefs = trac.prefs.web_ui

To work around the issue for all extra dependencies we should consider using lowercase identifiers in extras_require: tags/trac-1.0.9/setup.py@:106-111#L105​.

See also #11877.

[Ryan J Ollos]

Replying to rjollos:

To work around the issue for all extra dependencies we should consider using lowercase identifiers in extras_require: tags/trac-1.0.9/setup.py@:106-111#L105​.

I'll go ahead and make this change in a few days if there's no feedback.

[Ryan J Ollos]

We may want to address the casing issue for TracSpamFilter as well: plugins/1.0/spam-filter/setup.py@14379:55-56#L36​.

[Ryan J Ollos]

Replying to rjollos:

We may want to address the casing issue for TracSpamFilter as well: plugins/1.0/spam-filter/setup.py@14379:55-56#L36​.

Addressed in [14387].

[Ryan J Ollos]

Committed to 1.0-stable in [14388], merged to trunk in [14389].

See also #12290.

[Ryan J Ollos]

Another issue that I just started seeing today, in a Debian 8.5 Virtual environment with Python 2.7.9, pip 8.1.2 and setuptools 23.1.0:

2016-06-28 20:41:01,853 Trac[loader] ERROR: Skipping "trac.mimeview.txtl = trac.mimeview.txtl [textile]": 
Traceback (most recent call last):
  File "/var/www/bugs.jquery.com/private/pve/local/lib/python2.7/site-packages/trac/loader.py", line 68, in _load_eggs
    entry.load(require=True)
  File "/var/www/bugs.jquery.com/private/pve/local/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2229, in load
    return self.resolve()
  File "/var/www/bugs.jquery.com/private/pve/local/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2235, in resolve
    module = __import__(self.module_name, fromlist=['__name__'], level=0)
  File "/var/www/bugs.jquery.com/private/pve/local/lib/python2.7/site-packages/trac/mimeview/txtl.py", line 21, in <module>
    import textile
ImportError: No module named textile

textile isn't installed in the virtual environment, and Trac shouldn't be trying to load the module due to the missing dependency. I cannot reproduce on OSX with Python 2.7.11.

[Jun Omae]

It seems that behaviour has changed since setuptools 20.8.0. I think that is a setuptools issue….

Maybe relative issues:

• ​20.5.0+ breaks existing setup.py files - UndefinedEnvironmentName · Issue #523 · pypa/setuptools
• ​With the version 20.7.0 he call extra in the environment · Issue #544 · pypa/setuptools

setuptools <= 20.4

13:47:06 Trac[loader] DEBUG: Skipping "trac.mimeview.pygments = trac.mimeview.pygments [pygments]": ("DistributionNotFound: The 'Pygments>=0.6; extra == "pygments"' distribution was not found and is required by the application" not found)

setuptools >= 20.6.6

13:44:54 Trac[loader] ERROR: Skipping "trac.mimeview.pygments = trac.mimeview.pygments [pygments]":
Traceback (most recent call last):
  File "/dev/shm/t12282/local/lib/python2.7/site-packages/trac/loader.py", line 68, in _load_eggs
    entry.load(require=True)
  File "/dev/shm/t12282/local/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2228, in load
    self.require(*args, **kwargs)
  File "/dev/shm/t12282/local/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2245, in require
    items = working_set.resolve(reqs, env, installer)
  File "/dev/shm/t12282/local/lib/python2.7/site-packages/pkg_resources/__init__.py", line 808, in resolve
    if not req_extras.markers_pass(req):
  File "/dev/shm/t12282/local/lib/python2.7/site-packages/pkg_resources/__init__.py", line 993, in markers_pass
    return not req.marker or any(extra_evals) or req.marker.evaluate()
  File "/dev/shm/t12282/local/lib/python2.7/site-packages/pkg_resources/_vendor/packaging/markers.py", line 278, in evaluate
    return _evaluate_markers(self._markers, current_environment)
  File "/dev/shm/t12282/local/lib/python2.7/site-packages/pkg_resources/_vendor/packaging/markers.py", line 203, in _evaluate_markers
    lhs_value = _get_env(environment, lhs.value)
  File "/dev/shm/t12282/local/lib/python2.7/site-packages/pkg_resources/_vendor/packaging/markers.py", line 185, in _get_env
    "{0!r} does not exist in evaluation environment.".format(name)
UndefinedEnvironmentName: 'extra' does not exist in evaluation environment.

setuptools >= 20.8.1

13:45:41 Trac[loader] ERROR: Skipping "trac.mimeview.pygments = trac.mimeview.pygments [pygments]":
Traceback (most recent call last):
  File "/dev/shm/t12282/local/lib/python2.7/site-packages/trac/loader.py", line 68, in _load_eggs
    entry.load(require=True)
  File "/dev/shm/t12282/local/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2229, in load
    return self.resolve()
  File "/dev/shm/t12282/local/lib/python2.7/site-packages/pkg_resources/__init__.py", line 2235, in resolve
    module = __import__(self.module_name, fromlist=['__name__'], level=0)
  File "/dev/shm/t12282/local/lib/python2.7/site-packages/trac/mimeview/pygments.py", line 16, in <module>
    import pygments
ImportError: No module named pygments

[Jun Omae]

According to ​setuptools documentation:

Load the entry point, returning the advertised Python object, or raise ImportError if it cannot be obtained. If require is a true value, then require(env, installer) is called before attempting the import.

The raising ImportError is by design. Also, the documentation has been added on 14 Aug 2005. See ​Added docs for main !EntryPoint APIs, and cleaned up the API itself a … · pypa/setuptools@53cf2db.

I think we should avoid logging the trace back if the error is ImportErrors in _load_eggs().

trac/loader.py

@@ -54 +54 @@
                               item, ue)
             elif isinstance(e, UnknownExtra):
                 env.log.error('Skipping "%s": (unknown extra "%s")', item, ue)
+            elif isinstance(e, ImportError):
+                env.log.error('Skipping "%s": (%s)', item, ue)
             else:
                 env.log.error('Skipping "%s": %s', item,
                               exception_to_unicode(e, traceback=True))

[Jun Omae]

Replying to Jun Omae:

It seems that behaviour has changed since setuptools 20.8.0. I think that is a setuptools issue….

I've filed it. See ​https://github.com/pypa/setuptools/issues/759.

[Ryan J Ollos]

Thanks for investigating. One interesting thing is that the traceback is only seen when installing a wheel. When installing an egg:

$pip install 1.0-stable/
Processing ./1.0-stable
Requirement already satisfied (use --upgrade to upgrade): setuptools>=0.6b1 in ./pve/lib/python2.7/site-packages (from Trac==1.0.13.dev0)
Requirement already satisfied (use --upgrade to upgrade): Genshi>=0.6 in ./pve/lib/python2.7/site-packages (from Trac==1.0.13.dev0)
Installing collected packages: Trac
  Running setup.py install for Trac ... done
Successfully installed Trac-1.0.13.dev0
$
$ls pve/lib/python2.7/site-packages
Genshi-0.7.dist-info            pkg_resources
Trac-1.0.13.dev0-py2.7.egg-info setuptools
easy_install.py                 setuptools-26.0.0.dist-info
easy_install.pyc                trac
genshi                          tracopt
pip                             wheel
pip-8.1.2.dist-info             wheel-0.29.0.dist-info

The log message in this case is:

14:35:56 Trac[loader] DEBUG: Skipping "trac.mimeview.pygments = trac.mimeview.pygments [pygments]": ("DistributionNotFound: The 'Pygments>=0.6' distribution was not found and is required by the application" not found)

With the comment:9 patch, I get:

14:41:17 Trac[loader] ERROR: Skipping "trac.mimeview.pygments = trac.mimeview.pygments [pygments]": (ImportError: No module named pygments)

So I just wonder if that should be debug-level logging rather than error-level logging.

[Jun Omae]

Replying to Ryan J Ollos:

Thanks for investigating. One interesting thing is that the traceback is only seen when installing a wheel. When installing an egg:

Interested. The same here. DistributionNotFound is raised when Trac is installed with *.egg-info. ImportError is raised when Trac is installed with *.dist-info.

So I just wonder if that should be debug-level logging rather than error-level logging.

I consider it should be ERROR or WARNING. Otherwise, a user would be unable to notice issues if a Trac plugin has any issues.

I agree DEBUG level if the error is ResolutionError and its subclass (e.g. DistributionNotFound). For ImportError, it should be ERROR or WARNING because installed Trac plugin might have something wrong.

[Ryan J Ollos]

Replying to Jun Omae:

I agree DEBUG level if the error is ResolutionError and its subclass (e.g. DistributionNotFound). For ImportError, it should be ERROR or WARNING because installed Trac plugin might have something wrong.

Okay, that makes sense if the ImportError would not be raised for the case of the package not found, were setuptools to not have the defect introduced in 20.8.1.

I created #12566 for documenting changes.

[Jun Omae]

Replying to Jun Omae:

Replying to Jun Omae:

It seems that behaviour has changed since setuptools 20.8.0. I think that is a setuptools issue….

I've filed it. See ​https://github.com/pypa/setuptools/issues/759.

Added comment to the issue in github.

Extra requirements in entry points works fine with any version of setuptools if Trac is installed with .egg-info. However, the extra requirements doesn't work if Trac is installed with .dist-info since setuptools 20.8.1.

[Ryan J Ollos]

See also #12989.