Pip-tools: No handlers could be found for logger "pip.vcs.git"

[cancan101]

Looks like logging is not totally set up. I get this when pip-compile wit VCS links:

No handlers could be found for logger "pip.vcs.git"

[ryanhiebert]

FWIW, this issue came up for me about the same time that I added a -e requirement to a github repository (starting with git+git://).

[vphilippon]

Has this been since in recent releases?

Note to contributors: Try to reproduce by causing a failure with a git repo on pip's side.

[ryanhiebert]

I'm still seeing this message each time I run my upgrade script.

[vphilippon]

@ryanhiebert Could you give me your upgrade script, as well as a requirements.in to reproduce?

[ryanhiebert]

I may have been mis-remembering what I was seeing. I can't confirm the bug myself ATM.

[vphilippon]

Alright, closing this for now. If anyone comes up with this again, we'll reopen.

[koleror]

Hi, I add the issue myself running pip-compile with git urls indeed.
The format of the github urls is: -e git+ssh://[email protected]/<user>/<repo>.git@<tag>#egg=<egg>, if it can help?

Also, I get No handlers could be found for logger "pip.req.req_install"

[amanagr]

Did anyone figure this out? @cancan101 ??

[atugushev]

Hello @koleror,

Hi, I add the issue myself running pip-compile with git urls indeed.
The format of the github urls is: -e git+ssh://[email protected]/<user>/<repo>.git@<tag>#egg=<egg>, if it can help?

Also, I get No handlers could be found for logger "pip.req.req_install"

I cannot reproduce it locally. Is this issue still on, @koleror?

echo "-e git+ssh://[email protected]/jazzband/pip-tools.git@master#egg=pip-tools" | pip-compile - -vo- > /dev/null
Using indexes:
  https://pypi.org/simple

                          ROUND 1
Current constraints:
  pip-tools from git+ssh://****@github.com/jazzband/pip-tools.git@master#egg=pip-tools (from -r /var/folders/4x/rz_w89dx1z3bydfd6qpdjn_h0000gn/T/tmpflyl5zxs (line 1))

Finding the best candidates:
  found candidate -e git+ssh://[email protected]/jazzband/pip-tools.git@master#egg=pip-tools (constraint was <any>)

Finding secondary dependencies:

New dependencies found in this round:
  adding ['click', '>=6', '[]']
  adding ['six', '', '[]']
Removed dependencies in this round:
------------------------------------------------------------
Result of round 1: not stable

                          ROUND 2
Current constraints:
  click>=6 (from pip-tools->-r /var/folders/4x/rz_w89dx1z3bydfd6qpdjn_h0000gn/T/tmpflyl5zxs (line 1))
  pip-tools from git+ssh://****@github.com/jazzband/pip-tools.git@master#egg=pip-tools (from -r /var/folders/4x/rz_w89dx1z3bydfd6qpdjn_h0000gn/T/tmpflyl5zxs (line 1))
  six (from pip-tools->-r /var/folders/4x/rz_w89dx1z3bydfd6qpdjn_h0000gn/T/tmpflyl5zxs (line 1))

Finding the best candidates:
  found candidate click==7.0 (constraint was >=6)
  found candidate -e git+ssh://[email protected]/jazzband/pip-tools.git@master#egg=pip-tools (constraint was <any>)
  found candidate six==1.12.0 (constraint was <any>)

Finding secondary dependencies:
  click==7.0                requires -
  six==1.12.0               requires -
------------------------------------------------------------
Result of round 2: stable, done

#
# This file is autogenerated by pip-compile
# To update, run:
#
#    pip-compile --output-file=- -
#
-e git+ssh://[email protected]/jazzband/pip-tools.git@master#egg=pip-tools
click==7.0
six==1.12.0

[antonagestam]

I am still seeing this with (pip-compile --version: pip-compile, version 4.2.0)

[antonagestam]

Actually I am seeing a slightly different error:

No handlers could be found for logger "pip._internal.vcs.git"
Traceback (most recent call last):
  File "/Users/anton/.pyenv/versions/dn-campaign/bin/pip-compile", line 8, in <module>
    sys.exit(cli())
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/click/core.py", line 764, in __call__
    return self.main(*args, **kwargs)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/click/core.py", line 717, in main
    rv = self.invoke(ctx)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/click/core.py", line 956, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/click/core.py", line 555, in invoke
    return callback(*args, **kwargs)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/click/decorators.py", line 17, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/piptools/scripts/compile.py", line 358, in cli
    results = resolver.resolve(max_rounds=max_rounds)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/piptools/resolver.py", line 168, in resolve
    has_changed, best_matches = self._resolve_one_round()
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/piptools/resolver.py", line 263, in _resolve_one_round
    their_constraints.extend(self._iter_dependencies(best_match))
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/piptools/resolver.py", line 339, in _iter_dependencies
    for dependency in self.repository.get_dependencies(ireq):
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/piptools/repositories/pypi.py", line 272, in get_dependencies
    download_dir, ireq, wheel_cache
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/piptools/repositories/pypi.py", line 231, in resolve_reqs
    results = resolver._resolve_one(reqset, ireq)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/legacy_resolve.py", line 365, in _resolve_one
    abstract_dist = self._get_abstract_dist_for(req_to_install)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/legacy_resolve.py", line 295, in _get_abstract_dist_for
    req, self.require_hashes, self.use_user_site, self.finder,
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/operations/prepare.py", line 258, in prepare_editable_requirement
    req, self.req_tracker, finder, self.build_isolation,
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/operations/prepare.py", line 49, in _get_prepared_distribution
    abstract_dist.prepare_distribution_metadata(finder, build_isolation)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/distributions/source/legacy.py", line 39, in prepare_distribution_metadata
    self.req.prepare_metadata()
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/req/req_install.py", line 563, in prepare_metadata
    self.metadata_directory = metadata_generator(self)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/operations/generate_metadata.py", line 124, in _generate_metadata_legacy
    command_desc='python setup.py egg_info',
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/utils/subprocess.py", line 242, in call_subprocess
    raise InstallationError(exc_msg)
pip._internal.exceptions.InstallationError: Command errored out with exit status 1: python setup.py egg_info Check the logs for full command output.

And also this:

No handlers could be found for logger "pip.subprocessor"
Traceback (most recent call last):
  File "/Users/anton/.pyenv/versions/dn-campaign/bin/pip-compile", line 8, in <module>
    sys.exit(cli())
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/click/core.py", line 764, in __call__
    return self.main(*args, **kwargs)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/click/core.py", line 717, in main
    rv = self.invoke(ctx)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/click/core.py", line 956, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/click/core.py", line 555, in invoke
    return callback(*args, **kwargs)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/click/decorators.py", line 17, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/piptools/scripts/compile.py", line 358, in cli
    results = resolver.resolve(max_rounds=max_rounds)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/piptools/resolver.py", line 168, in resolve
    has_changed, best_matches = self._resolve_one_round()
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/piptools/resolver.py", line 263, in _resolve_one_round
    their_constraints.extend(self._iter_dependencies(best_match))
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/piptools/resolver.py", line 339, in _iter_dependencies
    for dependency in self.repository.get_dependencies(ireq):
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/piptools/repositories/pypi.py", line 272, in get_dependencies
    download_dir, ireq, wheel_cache
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/piptools/repositories/pypi.py", line 231, in resolve_reqs
    results = resolver._resolve_one(reqset, ireq)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/legacy_resolve.py", line 365, in _resolve_one
    abstract_dist = self._get_abstract_dist_for(req_to_install)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/legacy_resolve.py", line 295, in _get_abstract_dist_for
    req, self.require_hashes, self.use_user_site, self.finder,
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/operations/prepare.py", line 258, in prepare_editable_requirement
    req, self.req_tracker, finder, self.build_isolation,
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/operations/prepare.py", line 49, in _get_prepared_distribution
    abstract_dist.prepare_distribution_metadata(finder, build_isolation)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/distributions/source/legacy.py", line 39, in prepare_distribution_metadata
    self.req.prepare_metadata()
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/req/req_install.py", line 563, in prepare_metadata
    self.metadata_directory = metadata_generator(self)
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/operations/generate_metadata.py", line 124, in _generate_metadata_legacy
    command_desc='python setup.py egg_info',
  File "/Users/anton/.pyenv/versions/2.7.16/envs/dn-campaign/lib/python2.7/site-packages/pip/_internal/utils/subprocess.py", line 242, in call_subprocess
    raise InstallationError(exc_msg)
pip._internal.exceptions.InstallationError: Command errored out with exit status 1: python setup.py egg_info Check the logs for full command output.

[atugushev]

@antonagestam could you paste requirements.in? I'll check.

[palfrey]

I've got the pip.subprocessor variant with the following requirements.in

Cohen >= 0.7.4

# For https://github.com/lobocv/eventdispatcher/commit/b238ee18fa511c54090c21c7801564edd0dd95ef#diff-3e88a25682c0094a8dfc3cabbaa05dcb to fix clock issue
# The < 1.9.5 is because of https://github.com/lobocv/eventdispatcher/issues/2
eventdispatcher >= 1.9.0,<1.9.5

pip-tools

axiom
tagpy
netifaces
twisted

# Because last release is very broken. See https://github.com/inducer/tagpy/issues/5
-e git+https://github.com/inducer/tagpy.git#egg=tagpy

Like the one from https://github.com/palfrey/parochial currently, but with the Twisted version lockdown removed. Incidentally, it works with twisted < 15 and every value up to < 19 but not < 20 so might have something to do with Twisted 19.x?

[vphilippon]

I think I've finally figured this one out.
Due to how we import pip internals, the builtin logging module configuration is never properly done.

It should be pretty straightforward to fix, and help give a bit more details from pip logger when we hit some odd failure cases. I'll open up a MR soon.

[atugushev]

@vphilippon cool! Thanks for the fix!

@antonagestam @palfrey could you please test the #1035 whether it fixes your issue? Coud be installed via:

$ pip install -e 'git+https://github.com/vphilippon/pip-tools.git@configure-builtin-logging-module#egg=pip-tools'

[palfrey]

So it's still not fully working, but we've got a more interesting error message :)

ERROR:pip.subprocessor:Command errored out with exit status 1:
 command: /Users/palfrey/src/parochial/ENV/bin/python2.7 -c 'import sys, setuptools, tokenize; sys.argv[0] = '"'"'/var/folders/hs/z7c0cksd5nz80mjhc2qncx900000gn/T/tmp9IbOujbuild/twisted/setup.py'"'"'; __file__='"'"'/var/folders/hs/z7c0cksd5nz80mjhc2qncx900000gn/T/tmp9IbOujbuild/twisted/setup.py'"'"';f=getattr(tokenize, '"'"'open'"'"', open)(__file__);code=f.read().replace('"'"'\r\n'"'"', '"'"'\n'"'"');f.close();exec(compile(code, __file__, '"'"'exec'"'"'))' egg_info --egg-base /var/folders/hs/z7c0cksd5nz80mjhc2qncx900000gn/T/tmp9IbOujbuild/twisted/pip-egg-info
     cwd: /var/folders/hs/z7c0cksd5nz80mjhc2qncx900000gn/T/tmp9IbOujbuild/twisted/
Complete output (12 lines):
no previously-included directories found matching '.travis'
no previously-included directories found matching 'tests'
warning: no previously-included files found matching 'examplesetup.py'
no previously-included directories found matching 'src/exampleproj'
no previously-included directories found matching 'src/incremental/newsfragments'

Installed /private/var/folders/hs/z7c0cksd5nz80mjhc2qncx900000gn/T/tmp9IbOujbuild/twisted/.eggs/incremental-17.5.0-py2.7.egg
/usr/local/Cellar/python@2/2.7.17_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/distutils/dist.py:267: UserWarning: Unknown distribution option: 'long_description_content_type'
  warnings.warn(msg)
/usr/local/Cellar/python@2/2.7.17_1/Frameworks/Python.framework/Versions/2.7/lib/python2.7/distutils/dist.py:267: UserWarning: Unknown distribution option: 'project_urls'
  warnings.warn(msg)
error in Twisted setup command: 'extras_require' must be a dictionary whose values are strings or lists of strings containing valid project/version requirement specifiers.
----------------------------------------
Traceback (most recent call last):
  File "/Users/palfrey/src/parochial/ENV/bin/pip-compile", line 9, in <module>
    load_entry_point('pip-tools==1.10.0rc2.dev488+gcde47c0', 'console_scripts', 'pip-compile')()
  File "/Users/palfrey/src/parochial/ENV/lib/python2.7/site-packages/click/core.py", line 764, in __call__
    return self.main(*args, **kwargs)
  File "/Users/palfrey/src/parochial/ENV/lib/python2.7/site-packages/click/core.py", line 717, in main
    rv = self.invoke(ctx)
  File "/Users/palfrey/src/parochial/ENV/lib/python2.7/site-packages/click/core.py", line 956, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/Users/palfrey/src/parochial/ENV/lib/python2.7/site-packages/click/core.py", line 555, in invoke
    return callback(*args, **kwargs)
  File "/Users/palfrey/src/parochial/ENV/lib/python2.7/site-packages/click/decorators.py", line 17, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/Users/palfrey/src/parochial/ENV/src/pip-tools/piptools/scripts/compile.py", line 380, in cli
    results = resolver.resolve(max_rounds=max_rounds)
  File "/Users/palfrey/src/parochial/ENV/src/pip-tools/piptools/resolver.py", line 165, in resolve
    has_changed, best_matches = self._resolve_one_round()
  File "/Users/palfrey/src/parochial/ENV/src/pip-tools/piptools/resolver.py", line 260, in _resolve_one_round
    their_constraints.extend(self._iter_dependencies(best_match))
  File "/Users/palfrey/src/parochial/ENV/src/pip-tools/piptools/resolver.py", line 355, in _iter_dependencies
    dependencies = self.repository.get_dependencies(ireq)
  File "/Users/palfrey/src/parochial/ENV/src/pip-tools/piptools/repositories/local.py", line 70, in get_dependencies
    return self.repository.get_dependencies(ireq)
  File "/Users/palfrey/src/parochial/ENV/src/pip-tools/piptools/repositories/pypi.py", line 292, in get_dependencies
    download_dir, ireq, wheel_cache
  File "/Users/palfrey/src/parochial/ENV/src/pip-tools/piptools/repositories/pypi.py", line 249, in resolve_reqs
    results = resolver._resolve_one(reqset, ireq)
  File "/Users/palfrey/src/parochial/ENV/lib/python2.7/site-packages/pip/_internal/legacy_resolve.py", line 365, in _resolve_one
    abstract_dist = self._get_abstract_dist_for(req_to_install)
  File "/Users/palfrey/src/parochial/ENV/lib/python2.7/site-packages/pip/_internal/legacy_resolve.py", line 313, in _get_abstract_dist_for
    req, self.session, self.finder, self.require_hashes
  File "/Users/palfrey/src/parochial/ENV/lib/python2.7/site-packages/pip/_internal/operations/prepare.py", line 224, in prepare_linked_requirement
    req, self.req_tracker, finder, self.build_isolation,
  File "/Users/palfrey/src/parochial/ENV/lib/python2.7/site-packages/pip/_internal/operations/prepare.py", line 49, in _get_prepared_distribution
    abstract_dist.prepare_distribution_metadata(finder, build_isolation)
  File "/Users/palfrey/src/parochial/ENV/lib/python2.7/site-packages/pip/_internal/distributions/source/legacy.py", line 39, in prepare_distribution_metadata
    self.req.prepare_metadata()
  File "/Users/palfrey/src/parochial/ENV/lib/python2.7/site-packages/pip/_internal/req/req_install.py", line 563, in prepare_metadata
    self.metadata_directory = metadata_generator(self)
  File "/Users/palfrey/src/parochial/ENV/lib/python2.7/site-packages/pip/_internal/operations/generate_metadata.py", line 124, in _generate_metadata_legacy
    command_desc='python setup.py egg_info',
  File "/Users/palfrey/src/parochial/ENV/lib/python2.7/site-packages/pip/_internal/utils/subprocess.py", line 242, in call_subprocess
    raise InstallationError(exc_msg)
pip._internal.exceptions.InstallationError: Command errored out with exit status 1: python setup.py egg_info Check the logs for full command output.

Note that doing pip install twisted==19.7.0 --no-binary :all: (the --no-binary is there because the default is a wheel which also works) works fine

[vphilippon]

@palfrey Alright! My fix was just to fix the logger part, and get a better message, not fix the actual underlying issue it was failing to report :). So this is a good sign.

For this case, with the output, it seems there's something odd with the twisted package extras_require. I'd (naively?) expect this to be easily reproducible, but it isn't.
That's a specific issue that we can track with its own ticket. It deserves it :).

A good-ish title to identify it:
"error in Twisted setup command: 'extras_require' must be a dictionary whose values are strings or lists of strings containing valid project/version requirement specifiers."

[palfrey]

So, it turns out it's got nothing to do with Twisted at all, but setuptools. My virtualenv had setuptools 18.2 installed, which exhibited this bug, but upgrading to latest (44.0.0) fixed the problem.