pip-compile's logs omit diagnostic messages from pip's subprocess error logging, when e.g. psycopg2 processing fails due to missing system (non-pip-managed) tools #1583

cgeorgelee · 2022-02-16T05:09:19Z

When I use psycopg2 in my requirements.in file then pip-compile fails and throw an exception and does not generate a requirements.txt file. I am using venv but that should not cause a problem.

# ------- Example requirements.in file which does not compile ------------
psycopg2

# ------- Example requirements.in file which DOES compile ------------
Django<4.0

Environment Versions

OS Type: Amazon Linux 2 (amzn2-ami-hvm-2.0.20210427.0-x86_64-gp2)
Python version: Python 3.7.10
pip version: pip 22.0.3 from /mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/pip (python 3.7)
pip-tools version: pip-compile, version 6.5.1

The currently installed packages in this venv are:

$ pip list
Package            Version
------------------ -------
click              8.0.3
importlib-metadata 4.11.1
pep517             0.12.0
pip                22.0.3
pip-tools          6.5.1
setuptools         47.1.0
tomli              2.0.1
typing_extensions  4.1.1
wheel              0.37.1
zipp               3.7.0

Steps to replicate

Create an Amazon Linux 2 box and install pip-tools

pip install --upgrade pip
pip install pip-tools

Create the requirements.in file as shown above
Compile that file

$ pip-compile --output-file requirements.txt requirements.in --upgrade

Expected result

An output file in requirements.txt

Actual result

It fails with:

$ pip-compile --output-file requirements.txt requirements.in --upgrade

ERROR:pip.subprocessor:[present-diagnostic] python setup.py egg_info exited with 1
Traceback (most recent call last):
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/pip/_internal/operations/build/metadata_legacy.py", line 68, in generate_metadata
    spinner=spinner,
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/pip/_internal/utils/subprocess.py", line 224, in call_subprocess
    raise error
pip._internal.exceptions.InstallationSubprocessError: python setup.py egg_info exited with 1

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/mnt/xvdb/views/mysrc/myenv/bin/pip-compile", line 8, in <module>
    sys.exit(cli())
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/click/core.py", line 1128, in __call__
    return self.main(*args, **kwargs)
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/click/core.py", line 1053, in main
    rv = self.invoke(ctx)
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/click/core.py", line 1395, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/click/core.py", line 754, in invoke
    return __callback(*args, **kwargs)
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/click/decorators.py", line 26, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/piptools/scripts/compile.py", line 466, in cli
    results = resolver.resolve(max_rounds=max_rounds)
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/piptools/resolver.py", line 175, in resolve
    has_changed, best_matches = self._resolve_one_round()
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/piptools/resolver.py", line 319, in _resolve_one_round
    their_constraints.extend(self._iter_dependencies(best_match))
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/piptools/resolver.py", line 428, in _iter_dependencies
    dependencies = self.repository.get_dependencies(ireq)
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/piptools/repositories/pypi.py", line 239, in get_dependencies
    download_dir, ireq, wheel_cache
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/piptools/repositories/pypi.py", line 201, in resolve_reqs
    results = resolver._resolve_one(reqset, ireq)
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/pip/_internal/resolution/legacy/resolver.py", line 379, in _resolve_one
    dist = self._get_dist_for(req_to_install)
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/pip/_internal/resolution/legacy/resolver.py", line 332, in _get_dist_for
    dist = self.preparer.prepare_linked_requirement(req)
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/pip/_internal/operations/prepare.py", line 487, in prepare_linked_requirement
    return self._prepare_linked_requirement(req, parallel_builds)
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/pip/_internal/operations/prepare.py", line 560, in _prepare_linked_requirement
    self.build_isolation,
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/pip/_internal/operations/prepare.py", line 58, in _get_prepared_distribution
    abstract_dist.prepare_distribution_metadata(finder, build_isolation)
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/pip/_internal/distributions/sdist.py", line 47, in prepare_distribution_metadata
    self.req.prepare_metadata()
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/pip/_internal/req/req_install.py", line 533, in prepare_metadata
    details=details,
  File "/mnt/xvdb/views/mysrc/myenv/lib64/python3.7/site-packages/pip/_internal/operations/build/metadata_legacy.py", line 71, in generate_metadata
    raise MetadataGenerationFailed(package_details=details) from error
pip._internal.exceptions.MetadataGenerationFailed: metadata generation failed

The text was updated successfully, but these errors were encountered:

AndydeCleyre · 2022-02-16T06:46:49Z

So trying pip install psycopg2 reveals more: it needs pg_config executable on the system to build, but they mention you can alternatively opt to use the psycopg2-binary package.

I think this is just going to come down to installing some things pyscopg2 needs for its build environment to work properly, like postgresql-devel and gcc and whatever else they write in their docs. Then try installing directly for a clue as to what's still missing, if anything. Or use their binary package.

cgeorgelee · 2022-02-16T20:53:07Z

The error message threw me. I used your recommendation and used the psycopg2-binary in requirements.in file and it worked. Thank you!

confuzeus · 2022-02-22T12:50:58Z

Since psycopg2-binary isn't suitable for production, this issue can be solved by installing the postgresql development headers. On Debian based distros, it's called libpq-dev.

dwt · 2022-03-17T09:39:40Z

I would really like this reopened with the goal to provide a better error message. Anything that hints at the true root of the problem would be really helpful.

AndydeCleyre · 2022-03-17T17:16:07Z

@dwt

Thanks! Let me see how the error presents and where pip-tools fits in:

Setting up:

$ podman run -it --rm docker://amazonlinux
# yum install -y python3
# python3 -m venv venv
# . ./venv/bin/activate
# pip install -U pip pip-tools

Checking current pip-tools messages:

# pip-compile - -o - <<<psycopg2

big output

ERROR:pip.subprocessor:[present-diagnostic] python setup.py egg_info exited with 1
Traceback (most recent call last):
  File "/venv/lib64/python3.7/site-packages/pip/_internal/operations/build/metadata_legacy.py", line 68, in generate_metadata
    spinner=spinner,
  File "/venv/lib64/python3.7/site-packages/pip/_internal/utils/subprocess.py", line 224, in call_subprocess
    raise error
pip._internal.exceptions.InstallationSubprocessError: python setup.py egg_info exited with 1

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/venv/bin/pip-compile", line 8, in <module>
    sys.exit(cli())
  File "/venv/lib64/python3.7/site-packages/click/core.py", line 1128, in __call__
    return self.main(*args, **kwargs)
  File "/venv/lib64/python3.7/site-packages/click/core.py", line 1053, in main
    rv = self.invoke(ctx)
  File "/venv/lib64/python3.7/site-packages/click/core.py", line 1395, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/venv/lib64/python3.7/site-packages/click/core.py", line 754, in invoke
    return __callback(*args, **kwargs)
  File "/venv/lib64/python3.7/site-packages/click/decorators.py", line 26, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/venv/lib64/python3.7/site-packages/piptools/scripts/compile.py", line 466, in cli
    results = resolver.resolve(max_rounds=max_rounds)
  File "/venv/lib64/python3.7/site-packages/piptools/resolver.py", line 175, in resolve
    has_changed, best_matches = self._resolve_one_round()
  File "/venv/lib64/python3.7/site-packages/piptools/resolver.py", line 319, in _resolve_one_round
    their_constraints.extend(self._iter_dependencies(best_match))
  File "/venv/lib64/python3.7/site-packages/piptools/resolver.py", line 428, in _iter_dependencies
    dependencies = self.repository.get_dependencies(ireq)
  File "/venv/lib64/python3.7/site-packages/piptools/repositories/pypi.py", line 239, in get_dependencies
    download_dir, ireq, wheel_cache
  File "/venv/lib64/python3.7/site-packages/piptools/repositories/pypi.py", line 201, in resolve_reqs
    results = resolver._resolve_one(reqset, ireq)
  File "/venv/lib64/python3.7/site-packages/pip/_internal/resolution/legacy/resolver.py", line 379, in _resolve_one
    dist = self._get_dist_for(req_to_install)
  File "/venv/lib64/python3.7/site-packages/pip/_internal/resolution/legacy/resolver.py", line 332, in _get_dist_for
    dist = self.preparer.prepare_linked_requirement(req)
  File "/venv/lib64/python3.7/site-packages/pip/_internal/operations/prepare.py", line 487, in prepare_linked_requirement
    return self._prepare_linked_requirement(req, parallel_builds)
  File "/venv/lib64/python3.7/site-packages/pip/_internal/operations/prepare.py", line 560, in _prepare_linked_requirement
    self.build_isolation,
  File "/venv/lib64/python3.7/site-packages/pip/_internal/operations/prepare.py", line 58, in _get_prepared_distribution
    abstract_dist.prepare_distribution_metadata(finder, build_isolation)
  File "/venv/lib64/python3.7/site-packages/pip/_internal/distributions/sdist.py", line 47, in prepare_distribution_metadata
    self.req.prepare_metadata()
  File "/venv/lib64/python3.7/site-packages/pip/_internal/req/req_install.py", line 533, in prepare_metadata
    details=details,
  File "/venv/lib64/python3.7/site-packages/pip/_internal/operations/build/metadata_legacy.py", line 71, in generate_metadata
    raise MetadataGenerationFailed(package_details=details) from error
pip._internal.exceptions.MetadataGenerationFailed: metadata generation failed

The highlights from above:

pip._internal.exceptions.InstallationSubprocessError: python setup.py egg_info exited with 1
pip._internal.exceptions.MetadataGenerationFailed: metadata generation failed

Those are what led me to try with plain pip, but let's see if we get any good details with verbosity turned up:

# pip-compile -vvv - -o - <<<psycopg2

big output

Using indexes:
  https://pypi.org/simple

                          ROUND 1
Current constraints:
  psycopg2 (from -r -)

Finding the best candidates:
  found candidate psycopg2==2.9.3 (constraint was <any>)

Finding secondary dependencies:
  psycopg2==2.9.3 not in cache, need to check index
ERROR:pip.subprocessor:[present-diagnostic] python setup.py egg_info exited with 1
Traceback (most recent call last):
  File "/venv/lib64/python3.7/site-packages/pip/_internal/operations/build/metadata_legacy.py", line 68, in generate_metadata
    spinner=spinner,
  File "/venv/lib64/python3.7/site-packages/pip/_internal/utils/subprocess.py", line 224, in call_subprocess
    raise error
pip._internal.exceptions.InstallationSubprocessError: python setup.py egg_info exited with 1

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/venv/bin/pip-compile", line 8, in <module>
    sys.exit(cli())
  File "/venv/lib64/python3.7/site-packages/click/core.py", line 1128, in __call__
    return self.main(*args, **kwargs)
  File "/venv/lib64/python3.7/site-packages/click/core.py", line 1053, in main
    rv = self.invoke(ctx)
  File "/venv/lib64/python3.7/site-packages/click/core.py", line 1395, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "/venv/lib64/python3.7/site-packages/click/core.py", line 754, in invoke
    return __callback(*args, **kwargs)
  File "/venv/lib64/python3.7/site-packages/click/decorators.py", line 26, in new_func
    return f(get_current_context(), *args, **kwargs)
  File "/venv/lib64/python3.7/site-packages/piptools/scripts/compile.py", line 466, in cli
    results = resolver.resolve(max_rounds=max_rounds)
  File "/venv/lib64/python3.7/site-packages/piptools/resolver.py", line 175, in resolve
    has_changed, best_matches = self._resolve_one_round()
  File "/venv/lib64/python3.7/site-packages/piptools/resolver.py", line 319, in _resolve_one_round
    their_constraints.extend(self._iter_dependencies(best_match))
  File "/venv/lib64/python3.7/site-packages/piptools/resolver.py", line 428, in _iter_dependencies
    dependencies = self.repository.get_dependencies(ireq)
  File "/venv/lib64/python3.7/site-packages/piptools/repositories/pypi.py", line 239, in get_dependencies
    download_dir, ireq, wheel_cache
  File "/venv/lib64/python3.7/site-packages/piptools/repositories/pypi.py", line 201, in resolve_reqs
    results = resolver._resolve_one(reqset, ireq)
  File "/venv/lib64/python3.7/site-packages/pip/_internal/resolution/legacy/resolver.py", line 379, in _resolve_one
    dist = self._get_dist_for(req_to_install)
  File "/venv/lib64/python3.7/site-packages/pip/_internal/resolution/legacy/resolver.py", line 332, in _get_dist_for
    dist = self.preparer.prepare_linked_requirement(req)
  File "/venv/lib64/python3.7/site-packages/pip/_internal/operations/prepare.py", line 487, in prepare_linked_requirement
    return self._prepare_linked_requirement(req, parallel_builds)
  File "/venv/lib64/python3.7/site-packages/pip/_internal/operations/prepare.py", line 560, in _prepare_linked_requirement
    self.build_isolation,
  File "/venv/lib64/python3.7/site-packages/pip/_internal/operations/prepare.py", line 58, in _get_prepared_distribution
    abstract_dist.prepare_distribution_metadata(finder, build_isolation)
  File "/venv/lib64/python3.7/site-packages/pip/_internal/distributions/sdist.py", line 47, in prepare_distribution_metadata
    self.req.prepare_metadata()
  File "/venv/lib64/python3.7/site-packages/pip/_internal/req/req_install.py", line 533, in prepare_metadata
    details=details,
  File "/venv/lib64/python3.7/site-packages/pip/_internal/operations/build/metadata_legacy.py", line 71, in generate_metadata
    raise MetadataGenerationFailed(package_details=details) from error
pip._internal.exceptions.MetadataGenerationFailed: metadata generation failed

The improvement here is just making clear that the problem occurs when trying to do some installation operation with psycopg2 specifically. This is good info, but still lacks the details we ultimately need.

And what do we get with pip directly?

# pip install psycopg2

big output

Collecting psycopg2
  Using cached psycopg2-2.9.3.tar.gz (380 kB)
  Preparing metadata (setup.py) ... error
  error: subprocess-exited-with-error

  × python setup.py egg_info did not run successfully.
  │ exit code: 1
  ╰─> [23 lines of output]
      running egg_info
      creating /tmp/pip-pip-egg-info-1p0ko9rt/psycopg2.egg-info
      writing /tmp/pip-pip-egg-info-1p0ko9rt/psycopg2.egg-info/PKG-INFO
      writing dependency_links to /tmp/pip-pip-egg-info-1p0ko9rt/psycopg2.egg-info/dependency_links.txt
      writing top-level names to /tmp/pip-pip-egg-info-1p0ko9rt/psycopg2.egg-info/top_level.txt
      writing manifest file '/tmp/pip-pip-egg-info-1p0ko9rt/psycopg2.egg-info/SOURCES.txt'

      Error: pg_config executable not found.

      pg_config is required to build psycopg2 from source.  Please add the directory
      containing pg_config to the $PATH or specify the full executable path with the
      option:

          python setup.py build_ext --pg-config /path/to/pg_config build ...

      or with the pg_config option in 'setup.cfg'.

      If you prefer to avoid building psycopg2 from source, please install the PyPI
      'psycopg2-binary' package instead.

      For further information please check the 'doc/src/install.rst' file (also at
      <https://www.psycopg.org/docs/install.html>).

      [end of output]

  note: This error originates from a subprocess, and is likely not a problem with pip.
error: metadata-generation-failed

× Encountered error while generating package metadata.
╰─> See above for output.

note: This is an issue with the package mentioned above, not pip.
hint: See above for details.

Well that's much clearer, with a lot of explanation.

OK. Maybe we can get more of that message into our own logs, at least with -vvv. I'll try to have a look.

AndydeCleyre · 2022-03-17T20:03:26Z

I think the content we want (mentioning pg_config) is not included in the pip-raised exception, so we can't just catch, log, and re-raise it.

It looks like it happens at pip/_internal/operations/build/metadata_legacy.py when calling call_subprocess, and from there it is included as far as the InstallationSubprocessError:

passed to the exception's __init__ as output_lines
stored as exception attribute output_prompt
passed up to a parent exception class via super as context

The exception is then passed (pip-internally) to subprocess_logger.error.

OK, and I see subprocess_logger = getLogger("pip.subprocessor").

When using pip directly, this goes through pip's internal RichPipStreamHandler(RichHandler)'s emit method, which uses some logic to display the diagnostic error. I think when used by pip-compile, this method is not used, so I will try to follow it.

AndydeCleyre · 2022-03-17T20:26:10Z

I've found that we can get that output, at least with newer versions of pip, by using our old _setup_logging always, basically what #1565 was doing.

At this point I've got to tag out and ask for insight from anyone who's worked on the logging changes. Anything to add at this time?

Pinging: @nicoa @davisagli @hugovk @di

di · 2022-03-17T21:40:54Z

See the comment here about why it was recommended to skip _setup_logging for newer pip versions. IIRC this seemed to be correct based on my testing for #1567.

davisagli · 2022-03-17T21:47:13Z

I can take another look at this tomorrow. Complete guess, but maybe some difference between handling pip’s stdout and stderr? David

…

On Mar 17, 2022, at 5:41 PM, Dustin Ingram ***@***.***> wrote: See the comment here about why it was recommended to skip _setup_logging for newer pip versions. IIRC this seemed to be correct based on my testing for #1567. — Reply to this email directly, view it on GitHub, or unsubscribe. You are receiving this because you were mentioned.

davisagli · 2022-03-18T19:59:45Z

It looks like pip-tools probably needs the following changes:

Remove the conditional at https://github.com/jazzband/pip-tools/blob/master/piptools/repositories/pypi.py#L107 -- we still need to call pip's setup_logging function to put in place the RichPipStreamHandler which formats the [present-diagnostic] messages nicely.
Add the same conditional before https://github.com/jazzband/pip-tools/blob/master/piptools/repositories/pypi.py#L454 (and around the remainder of the _setup_logging method). It's necessary to initialize pip's logging, but with pip > 22 it appears to no longer be necessary to explicitly connect it to pip-tools' LogContext.stream (which is really stderr)
Do something to avoid also logging a traceback for the MetadataGenerationFailed exception.

davisagli · 2022-03-18T20:02:57Z

Btw as an easier way to reproduce this I created setup.py containing 1/0 (to provoke a ZeroDivisionError), req.in containing -e ., and then ran pip-compile req.in.

This comment was marked as outdated.

Sign in to view

cgeorgelee closed this as completed Feb 16, 2022

AndydeCleyre reopened this Mar 17, 2022

AndydeCleyre changed the title ~~pip-compile fails with MetadataGenerationFailed when psycopg2 is in requirements.in~~ pip-compile obscures pip's helpful mesages when psycopg2 processing fails due to missing system (non-pip-managed) tools Mar 17, 2022

atugushev added logging Related to log or console output bug Something is not working labels Apr 6, 2022

AndydeCleyre mentioned this issue Nov 15, 2022

pip-compile error #1544

Closed

atugushev mentioned this issue Nov 15, 2022

Mysterious error with optional dependencies in pyproject.toml #1711

Closed

pradyunsg mentioned this issue Nov 22, 2022

Backend subprocess exited when trying to invoke get_requires_for_build_wheel pypa/flit#610

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

pip-compile's logs omit diagnostic messages from pip's subprocess error logging, when e.g. psycopg2 processing fails due to missing system (non-pip-managed) tools #1583

pip-compile's logs omit diagnostic messages from pip's subprocess error logging, when e.g. psycopg2 processing fails due to missing system (non-pip-managed) tools #1583

cgeorgelee commented Feb 16, 2022 •

edited

Loading

This comment was marked as outdated.

This comment was marked as outdated.

AndydeCleyre commented Feb 16, 2022 •

edited

Loading

cgeorgelee commented Feb 16, 2022 •

edited

Loading

confuzeus commented Feb 22, 2022

dwt commented Mar 17, 2022

AndydeCleyre commented Mar 17, 2022

AndydeCleyre commented Mar 17, 2022

AndydeCleyre commented Mar 17, 2022

di commented Mar 17, 2022

davisagli commented Mar 17, 2022 via email

davisagli commented Mar 18, 2022

davisagli commented Mar 18, 2022

pip-compile's logs omit diagnostic messages from pip's subprocess error logging, when e.g. psycopg2 processing fails due to missing system (non-pip-managed) tools #1583

pip-compile's logs omit diagnostic messages from pip's subprocess error logging, when e.g. psycopg2 processing fails due to missing system (non-pip-managed) tools #1583

Comments

cgeorgelee commented Feb 16, 2022 • edited Loading

Environment Versions

Steps to replicate

Expected result

Actual result

This comment was marked as outdated.

This comment was marked as outdated.

AndydeCleyre commented Feb 16, 2022 • edited Loading

cgeorgelee commented Feb 16, 2022 • edited Loading

confuzeus commented Feb 22, 2022

dwt commented Mar 17, 2022

AndydeCleyre commented Mar 17, 2022

AndydeCleyre commented Mar 17, 2022

AndydeCleyre commented Mar 17, 2022

di commented Mar 17, 2022

davisagli commented Mar 17, 2022 via email

davisagli commented Mar 18, 2022

davisagli commented Mar 18, 2022

cgeorgelee commented Feb 16, 2022 •

edited

Loading

AndydeCleyre commented Feb 16, 2022 •

edited

Loading

cgeorgelee commented Feb 16, 2022 •

edited

Loading