From e0aac4fb8087f1fda1d65d883381e9a98c7f282d Mon Sep 17 00:00:00 2001 From: John Sirois Date: Sun, 28 Jul 2024 16:13:57 -0700 Subject: [PATCH] Add more context for Job errors. (#2479) This makes several error paths that manifest when creating locks and PEXes present better error details. Several changes support this: 1. Jobs can now have a context label which is used, when set, to prefix all job error output. This should help root cause the problem; i.e.: is it fundamentally Pex or is it Pip or is it a problem with a bad package? 2. When a Pip download errors, we now show all STDERR output instead of just the last line whenever the last line contains "See above for details", which Pip emits to indicate an error buried deeper in the logs. 3. A new log analyzer is added to all Pip downloads that knows how to spot sdist build errors and surface their details. 4. A fail-safe is added to the Pip download log scraper to just report the full Pip log content when no better analysis was found. Fixes #2113 --- pex/build_system/pep_517.py | 8 +- pex/dist_metadata.py | 34 +++- pex/interpreter.py | 40 ---- pex/jobs.py | 22 ++- pex/pip/dependencies/requires.py | 2 +- pex/pip/log_analyzer.py | 28 ++- pex/pip/tool.py | 132 ++++++++----- pex/resolve/downloads.py | 7 +- pex/resolve/lock_resolver.py | 2 +- testing/__init__.py | 3 +- .../cli/commands/test_issue_1801.py | 33 ---- tests/integration/cli/commands/test_lock.py | 62 +++--- .../cli/commands/test_lock_resolve_auth.py | 2 +- .../test_lock_update_issues_2332_2334.py | 6 +- tests/integration/test_integration.py | 36 ++-- tests/integration/test_issue_2113.py | 181 ++++++++++++++++++ tests/integration/test_pep_427.py | 5 +- tests/pip/test_log_analyzer.py | 155 +++++++++++++++ tests/test_dist_metadata.py | 7 +- tests/test_jobs.py | 15 +- tests/tools/commands/test_repository.py | 3 +- tox.ini | 3 + 22 files changed, 580 insertions(+), 206 deletions(-) create mode 100644 tests/integration/test_issue_2113.py create mode 100644 tests/pip/test_log_analyzer.py diff --git a/pex/build_system/pep_517.py b/pex/build_system/pep_517.py index b085f47b2..f7d87ef93 100644 --- a/pex/build_system/pep_517.py +++ b/pex/build_system/pep_517.py @@ -186,7 +186,13 @@ def _invoke_build_hook( stderr=subprocess.PIPE, ) return SpawnedJob.file( - Job(command=args, process=process), + Job( + command=args, + process=process, + context="PEP-517:{hook_method} at {project_directory}".format( + hook_method=hook_method, project_directory=project_directory + ), + ), output_file=fp.name, result_func=lambda file_content: json.loads(file_content.decode("utf-8")), ) diff --git a/pex/dist_metadata.py b/pex/dist_metadata.py index 84621edbc..daee47054 100644 --- a/pex/dist_metadata.py +++ b/pex/dist_metadata.py @@ -651,22 +651,40 @@ def requires_dists(location): ) +# Frozen exception types don't work under 3.11+ where the `__traceback__` attribute can be set +# after construction in some cases. +@attr.s class RequirementParseError(Exception): """Indicates and invalid requirement string. See PEP-508: https://www.python.org/dev/peps/pep-0508 """ + error = attr.ib() # type: Any + source = attr.ib(default=None) # type: Optional[str] + + def __str__(self): + # type: () -> str + if not self.source: + return str(self.error) + return "Failed to parse a requirement of {source}: {err}".format( + err=self.error, source=self.source + ) + @attr.s(frozen=True) class Constraint(object): @classmethod - def parse(cls, constraint): - # type: (Text) -> Constraint + def parse( + cls, + constraint, # type: Text + source=None, # type: Optional[str] + ): + # type: (...) -> Constraint try: return cls.from_packaging_requirement(PackagingRequirement(constraint)) except InvalidRequirement as e: - raise RequirementParseError(str(e)) + raise RequirementParseError(str(e), source=source) @classmethod def from_packaging_requirement(cls, requirement): @@ -777,12 +795,16 @@ def as_requirement(self): @attr.s(frozen=True) class Requirement(Constraint): @classmethod - def parse(cls, requirement): - # type: (Text) -> Requirement + def parse( + cls, + requirement, # type: Text + source=None, # type: Optional[str] + ): + # type: (...) -> Requirement try: return cls.from_packaging_requirement(PackagingRequirement(requirement)) except InvalidRequirement as e: - raise RequirementParseError(str(e)) + raise RequirementParseError(str(e), source=source) @classmethod def from_packaging_requirement(cls, requirement): diff --git a/pex/interpreter.py b/pex/interpreter.py index 395358d38..bb483e8b0 100644 --- a/pex/interpreter.py +++ b/pex/interpreter.py @@ -46,7 +46,6 @@ Mapping, MutableMapping, Optional, - Sequence, Text, Tuple, Union, @@ -1566,45 +1565,6 @@ def __repr__(self): ) -def spawn_python_job( - args, # type: Iterable[str] - env=None, # type: Optional[Mapping[str, str]] - interpreter=None, # type: Optional[PythonInterpreter] - expose=None, # type: Optional[Sequence[str]] - pythonpath=None, # type: Optional[Iterable[str]] - **subprocess_kwargs # type: Any -): - # type: (...) -> Job - """Spawns a python job. - - :param args: The arguments to pass to the python interpreter. - :param env: The environment to spawn the python interpreter process in. Defaults to the ambient - environment. - :param interpreter: The interpreter to use to spawn the python job. Defaults to the current - interpreter. - :param expose: The names of any vendored distributions to expose to the spawned python process. - These will be appended to `pythonpath` if passed. - :param pythonpath: The PYTHONPATH to expose to the spawned python process. These will be - pre-pended to the `expose` path if passed. - :param subprocess_kwargs: Any additional :class:`subprocess.Popen` kwargs to pass through. - :returns: A job handle to the spawned python process. - """ - pythonpath = list(pythonpath or ()) - subprocess_env = dict(env or os.environ) - if expose: - # In order to expose vendored distributions with their un-vendored import paths in-tact, we - # need to set `__PEX_UNVENDORED__`. See: vendor.__main__.ImportRewriter._modify_import. - subprocess_env["__PEX_UNVENDORED__"] = ",".join(expose) - - pythonpath.extend(third_party.expose(expose, interpreter=interpreter)) - - interpreter = interpreter or PythonInterpreter.get() - cmd, process = interpreter.open_process( - args=args, pythonpath=pythonpath, env=subprocess_env, **subprocess_kwargs - ) - return Job(command=cmd, process=process) - - # See the "Test results from various systems" table here: # https://www.in-ulm.de/~mascheck/various/shebang/#length MAX_SHEBANG_LENGTH = 512 if sys.platform == "darwin" else 128 diff --git a/pex/jobs.py b/pex/jobs.py index ab3bbc320..bae04ccc6 100644 --- a/pex/jobs.py +++ b/pex/jobs.py @@ -63,19 +63,33 @@ def __init__( exitcode, # type: int stderr, # type: Optional[Text] message, # type: str + context=None, # type: Optional[str] ): # type: (...) -> None - super(Job.Error, self).__init__(message) + super(Job.Error, self).__init__( + "{ctx}: {msg}".format(ctx=context, msg=message) if context else message + ) self.pid = pid self.command = command self.exitcode = exitcode self.stderr = stderr + self._context = context + + def contextualized_stderr(self): + # type: () -> Iterator[Text] + if self.stderr: + for line in self.stderr.splitlines(): + if not self._context: + yield line + else: + yield "{ctx}: {line}".format(ctx=self._context, line=line) def __init__( self, command, # type: Iterable[str] process, # type: subprocess.Popen finalizer=None, # type: Optional[Callable[[int], None]] + context=None, # type: Optional[str] ): # type: (...) -> None """ @@ -84,10 +98,13 @@ def __init__( :param finalizer: An optional cleanup function to call exactly once with the process return code when the underlying process terminates in the course of calling this job's public methods. + :param context: An optional context labeling the job that will be used to decorate error + information. """ self._command = tuple(command) self._process = process self._finalizer = finalizer + self._context = context def wait(self): # type: () -> None @@ -153,6 +170,7 @@ def create_error( exitcode=self._process.returncode, stderr=err, message=msg, + context=self._context, ) def _finalize_job(self): @@ -407,7 +425,7 @@ def job_error_message( pid=job_error.pid, command=" ".join(job_error.command), exitcode=job_error.exitcode, - stderr=job_error.stderr, + stderr="\n".join(job_error.contextualized_stderr()), ) @abstractmethod diff --git a/pex/pip/dependencies/requires.py b/pex/pip/dependencies/requires.py index 8938ac564..ef3c0d293 100644 --- a/pex/pip/dependencies/requires.py +++ b/pex/pip/dependencies/requires.py @@ -22,7 +22,7 @@ def requires(self, *args, **kwargs): modified_requires = [] orig = orig_requires(self, *args, **kwargs) for req in orig: - requirement = PexRequirement.parse(str(req)) + requirement = PexRequirement.parse(str(req), source=repr(self)) excluded_by = dependency_configuration.excluded_by(requirement) if excluded_by: logger.debug( diff --git a/pex/pip/log_analyzer.py b/pex/pip/log_analyzer.py index a30d2654b..a2701c2cb 100644 --- a/pex/pip/log_analyzer.py +++ b/pex/pip/log_analyzer.py @@ -7,6 +7,7 @@ import subprocess from abc import abstractmethod +from pex.common import safe_delete from pex.jobs import Job from pex.typing import TYPE_CHECKING, Generic @@ -81,7 +82,7 @@ def __init__( self._log = log self._log_analyzers = list(log_analyzers) self._preserve_log = preserve_log - super(LogScrapeJob, self).__init__(command, process, finalizer=finalizer) + super(LogScrapeJob, self).__init__(command, process, finalizer=finalizer, context="pip") def _check_returncode(self, stderr=None): # type: (Optional[bytes]) -> None @@ -90,6 +91,7 @@ def _check_returncode(self, stderr=None): for analyzer in self._log_analyzers if analyzer.should_collect(self._process.returncode) ] + analyzed_stderr = b"" # type: bytes if activated_analyzers: collected = [] # A process may fail so early that there is no log file to analyze. @@ -100,7 +102,7 @@ def _check_returncode(self, stderr=None): for line in fp: if not activated_analyzers: break - for index, analyzer in enumerate(activated_analyzers): + for index, analyzer in tuple(enumerate(activated_analyzers)): result = analyzer.analyze(line) if isinstance(result.data, ErrorMessage): collected.append(result.data) @@ -110,7 +112,21 @@ def _check_returncode(self, stderr=None): break for analyzer in activated_analyzers: analyzer.analysis_completed() - if not self._preserve_log: - os.unlink(self._log) - stderr = (stderr or b"") + "".join(collected).encode("utf-8") - super(LogScrapeJob, self)._check_returncode(stderr=stderr) + if collected: + analyzed_stderr = "".join(collected).encode("utf-8") + + # Fall back to displaying the Pip logs in full if we have no stderr output or analysis. It's + # likely overwhelming, but better than silence and useful for debugging. + if ( + not stderr + and not analyzed_stderr + and self._process.returncode != 0 + and os.path.isfile(self._log) + ): + with open(self._log, "rb") as fp: + analyzed_stderr = fp.read() + + if not self._preserve_log: + safe_delete(self._log) + + super(LogScrapeJob, self)._check_returncode(stderr=(stderr or b"") + analyzed_stderr) diff --git a/pex/pip/tool.py b/pex/pip/tool.py index 1bb7273e3..a407a94b9 100644 --- a/pex/pip/tool.py +++ b/pex/pip/tool.py @@ -50,6 +50,7 @@ Iterator, List, Mapping, + Match, Optional, Sequence, Tuple, @@ -233,6 +234,42 @@ def analyze(self, line): return self.Continue() +@attr.s +class _PexIssue2113Analyzer(ErrorAnalyzer): + # Improves obscure error output described in: https://github.com/pex-tool/pex/issues/2113 + + _strip = attr.ib(default=0, init=False) # type: Optional[int] + _command = attr.ib(default=None, init=False) # type: Optional[str] + _command_output = attr.ib(factory=list, init=False) # type: List[str] + _command_errored = attr.ib(default=None, init=False) # type: Optional[Match] + + def analyze(self, line): + # type: (str) -> ErrorAnalysis + + if self._command_errored: + return self.Complete() + + match = re.match(r"^(?P\S+)\s+Running command (?P.*)$", line) + if match: + self._strip = len(match.group("timestamp")) + self._command = match.group("command") + del self._command_output[:] + self._command_output.append(line[self._strip :]) + return self.Continue() + + if self._command: + self._command_errored = re.match( + r"^\S+\s+ERROR:.*{command}".format(command=re.escape(self._command)), line + ) + if self._command_errored: + return self.Continue( + ErrorMessage("".join(self._command_output + [line[self._strip :]])) + ) + self._command_output.append(line[self._strip :]) + + return self.Continue() + + @attr.s(frozen=True) class PipVenv(object): venv_dir = attr.ib() # type: str @@ -414,7 +451,7 @@ def _spawn_pip_isolated_job( extra_env=extra_env, **popen_kwargs ) - return Job(command=command, process=process, finalizer=finalizer) + return Job(command=command, process=process, finalizer=finalizer, context="pip") @staticmethod def _iter_build_configuration_options(build_configuration): @@ -540,57 +577,53 @@ def spawn_download_distributions( ): log_analyzers.append(_Issue9420Analyzer()) - log = None + # Most versions of Pip hide useful information when a metadata build command fails; this + # analyzer brings that build failure information to the fore. + log_analyzers.append(_PexIssue2113Analyzer()) + popen_kwargs = {} finalizer = None - if log_analyzers: - prefix = "pex-pip-log." - log = os.path.join( - mkdtemp(prefix=prefix) if preserve_log else safe_mkdtemp(prefix=prefix), "pip.log" - ) - if preserve_log: - TRACER.log( - "Preserving `pip download` log at {log_path}".format(log_path=log), - V=ENV.PEX_VERBOSE, - ) - - download_cmd = ["--log", log] + download_cmd - # N.B.: The `pip -q download ...` command is quiet but - # `pip -q --log log.txt download ...` leaks download progress bars to stdout. We work - # around this by sending stdout to the bit bucket. - popen_kwargs["stdout"] = open(os.devnull, "wb") - - if ENV.PEX_VERBOSE > 0: - tailer = Tailer.tail( - path=log, - output=get_stderr_bytes_buffer(), - filters=( - re.compile( - r"^.*(pip is looking at multiple versions of [^\s+] to determine " - r"which version is compatible with other requirements\. This could " - r"take a while\.).*$" - ), - re.compile( - r"^.*(This is taking longer than usual. You might need to provide " - r"the dependency resolver with stricter constraints to reduce " - r"runtime\. If you want to abort this run, you can press " - r"Ctrl \+ C to do so\. To improve how pip performs, tell us what " - r"happened here: https://pip\.pypa\.io/surveys/backtracking).*$" - ), - ), - ) - - def finalizer(_): - # type: (int) -> None - tailer.stop() - elif preserve_log: + prefix = "pex-pip-log." + log = os.path.join( + mkdtemp(prefix=prefix) if preserve_log else safe_mkdtemp(prefix=prefix), "pip.log" + ) + if preserve_log: TRACER.log( - "The `pip download` log is not being utilized, to see more `pip download` " - "details, re-run with more Pex verbosity (more `-v`s).", + "Preserving `pip download` log at {log_path}".format(log_path=log), V=ENV.PEX_VERBOSE, ) + download_cmd = ["--log", log] + download_cmd + # N.B.: The `pip -q download ...` command is quiet but + # `pip -q --log log.txt download ...` leaks download progress bars to stdout. We work + # around this by sending stdout to the bit bucket. + popen_kwargs["stdout"] = open(os.devnull, "wb") + + if ENV.PEX_VERBOSE > 0: + tailer = Tailer.tail( + path=log, + output=get_stderr_bytes_buffer(), + filters=( + re.compile( + r"^.*(pip is looking at multiple versions of [^\s+] to determine " + r"which version is compatible with other requirements\. This could " + r"take a while\.).*$" + ), + re.compile( + r"^.*(This is taking longer than usual. You might need to provide " + r"the dependency resolver with stricter constraints to reduce " + r"runtime\. If you want to abort this run, you can press " + r"Ctrl \+ C to do so\. To improve how pip performs, tell us what " + r"happened here: https://pip\.pypa\.io/surveys/backtracking).*$" + ), + ), + ) + + def finalizer(_): + # type: (int) -> None + tailer.stop() + command, process = self._spawn_pip_isolated( download_cmd, package_index_configuration=package_index_configuration, @@ -599,12 +632,9 @@ def finalizer(_): extra_env=extra_env, **popen_kwargs ) - if log: - return LogScrapeJob( - command, process, log, log_analyzers, preserve_log=preserve_log, finalizer=finalizer - ) - else: - return Job(command, process) + return LogScrapeJob( + command, process, log, log_analyzers, preserve_log=preserve_log, finalizer=finalizer + ) def _ensure_wheel_installed(self, package_index_configuration=None): # type: (Optional[PackageIndexConfiguration]) -> None diff --git a/pex/resolve/downloads.py b/pex/resolve/downloads.py index edf8b2085..92e07b7ff 100644 --- a/pex/resolve/downloads.py +++ b/pex/resolve/downloads.py @@ -186,6 +186,11 @@ def download( try: self._download(url=artifact.url, download_dir=dest_dir).wait() except Job.Error as e: - return Error((e.stderr or str(e)).splitlines()[-1]) + error_lines = list(e.contextualized_stderr()) or str(e).splitlines() + return Error( + os.linesep.join(error_lines) + if "See above for details" in error_lines[-1] + else error_lines[-1] + ) hashing.file_hash(dest_file, digest) return artifact.filename diff --git a/pex/resolve/lock_resolver.py b/pex/resolve/lock_resolver.py index f84bce95b..91e2aa28c 100644 --- a/pex/resolve/lock_resolver.py +++ b/pex/resolve/lock_resolver.py @@ -400,7 +400,7 @@ def resolve_from_lock( index=index, pin=downloadable_artifact.pin, url=downloadable_artifact.artifact.url.download_url, - error=error, + error="\n ".join(str(error).splitlines()), ) for index, (downloadable_artifact, error) in enumerate( download_errors.items(), start=1 diff --git a/testing/__init__.py b/testing/__init__.py index e020a9bb9..7ab8580da 100644 --- a/testing/__init__.py +++ b/testing/__init__.py @@ -29,7 +29,6 @@ from pex.pex_info import PexInfo from pex.pip.installation import get_pip from pex.resolve.configured_resolver import ConfiguredResolver -from pex.resolve.resolver_configuration import PipConfiguration from pex.typing import TYPE_CHECKING from pex.util import named_temporary_file from pex.venv.virtualenv import InstallationChoice, Virtualenv @@ -211,7 +210,7 @@ def bdist(self): # type: () -> str get_pip( interpreter=self._interpreter, - resolver=ConfiguredResolver(pip_configuration=PipConfiguration()), + resolver=ConfiguredResolver.default(), ).spawn_build_wheels( distributions=[self._source_dir], wheel_dir=self._wheel_dir, diff --git a/tests/integration/cli/commands/test_issue_1801.py b/tests/integration/cli/commands/test_issue_1801.py index de548fe53..e4f63d365 100644 --- a/tests/integration/cli/commands/test_issue_1801.py +++ b/tests/integration/cli/commands/test_issue_1801.py @@ -4,12 +4,7 @@ import os.path import re -import pytest -from colors import green - from pex.resolve.lockfile import json_codec -from pex.resolve.resolver_configuration import ResolverVersion -from testing import run_pex_command from testing.cli import run_pex3 @@ -63,31 +58,3 @@ def test_preserve_pip_download_log(): assert artifact.url.download_url.endswith(expected_url_suffix) assert expected_algorithm == artifact.fingerprint.algorithm assert expected_hash == artifact.fingerprint.hash - - -@pytest.mark.skipif( - ResolverVersion.default() is ResolverVersion.PIP_2020, - reason=( - "The PIP_2020 resolver triggers download analysis in normal resolves but this test is " - "concerned with the case when there is no analysis to be performed." - ), -) -def test_preserve_pip_download_log_none(): - # type: () -> None - - result = run_pex_command( - args=[ - "ansicolors==1.1.8", - "--preserve-pip-download-log", - "--", - "-c", - "import colors; print(colors.green('42'))", - ], - quiet=True, - ) - result.assert_success() - assert green("42") == result.output.strip() - assert ( - "pex: The `pip download` log is not being utilized, to see more `pip download` details, " - "re-run with more Pex verbosity (more `-v`s).\n" - ) in result.error, result.error diff --git a/tests/integration/cli/commands/test_lock.py b/tests/integration/cli/commands/test_lock.py index cb57fa3a7..78f95d97f 100644 --- a/tests/integration/cli/commands/test_lock.py +++ b/tests/integration/cli/commands/test_lock.py @@ -883,33 +883,31 @@ def test_update_targeted_impossible( pip_version = json_codec.load(lock_file_path).pip_version if pip_version == PipVersion.v20_3_4_patched: expected_lines = [ - "ERROR: Could not find a version that satisfies the requirement urllib3<1.27,>=1.21.1 " - "(from requests)", - "ERROR: No matching distribution found for urllib3<1.27,>=1.21.1", - "", + "pip: ERROR: Could not find a version that satisfies the requirement " + "urllib3<1.27,>=1.21.1 (from requests)", + "pip: ERROR: No matching distribution found for urllib3<1.27,>=1.21.1", ] else: expected_lines = [ - "ERROR: Cannot install requests==2.26.0 because these package versions have " + "pip: ERROR: Cannot install requests==2.26.0 because these package versions have " "conflicting dependencies.", - "ERROR: ResolutionImpossible: for help visit " + "pip: ERROR: ResolutionImpossible: for help visit " "https://pip.pypa.io/en/latest/topics/dependency-resolution/" "#dealing-with-dependency-conflicts", - " ", - " The conflict is caused by:", - " requests 2.26.0 depends on urllib3<1.27 and >=1.21.1", - " The user requested (constraint) urllib3<1.16", - " ", - " To fix this you could try to:", - " 1. loosen the range of package versions you've specified", - " 2. remove package versions to allow {pip_to} attempt to solve the dependency " + "pip: ", + "pip: The conflict is caused by:", + "pip: requests 2.26.0 depends on urllib3<1.27 and >=1.21.1", + "pip: The user requested (constraint) urllib3<1.16", + "pip: ", + "pip: To fix this you could try to:", + "pip: 1. loosen the range of package versions you've specified", + "pip: 2. remove package versions to allow {pip_to} attempt to solve the dependency " "conflict".format( pip_to="pip" if pip_version.version < PipVersion.v24_1.version else "pip to" ), - "", ] assert expected_lines == error_lines[12:], os.linesep.join( - difflib.unified_diff(os.linesep.join(expected_lines), os.linesep.join(error_lines[12:])) + difflib.unified_diff(expected_lines, error_lines[12:]) ) # The pip legacy resolver, though is not strict and will let us get away with this. @@ -984,34 +982,32 @@ def test_update_add_impossible( pip_version = json_codec.load(lock_file_path).pip_version if pip_version == PipVersion.v20_3_4_patched: expected_lines = [ - "ERROR: Could not find a version that satisfies the requirement certifi<2017.4.17 " + "pip: ERROR: Could not find a version that satisfies the requirement certifi<2017.4.17 " "(from conflicting-certifi-requirement)", - "ERROR: No matching distribution found for certifi<2017.4.17", - "", + "pip: ERROR: No matching distribution found for certifi<2017.4.17", ] else: expected_lines = [ - "ERROR: Cannot install conflicting-certifi-requirement==1.2.3 and requests==2.26.0 " - "because these package versions have conflicting dependencies.", - "ERROR: ResolutionImpossible: for help visit " + "pip: ERROR: Cannot install conflicting-certifi-requirement==1.2.3 and " + "requests==2.26.0 because these package versions have conflicting dependencies.", + "pip: ERROR: ResolutionImpossible: for help visit " "https://pip.pypa.io/en/latest/topics/dependency-resolution/" "#dealing-with-dependency-conflicts", - " ", - " The conflict is caused by:", - " requests 2.26.0 depends on certifi>=2017.4.17", - " conflicting-certifi-requirement 1.2.3 depends on certifi<2017.4.17", - " The user requested (constraint) certifi==2021.5.30", - " ", - " To fix this you could try to:", - " 1. loosen the range of package versions you've specified", - " 2. remove package versions to allow {pip_to} attempt to solve the dependency " + "pip: ", + "pip: The conflict is caused by:", + "pip: requests 2.26.0 depends on certifi>=2017.4.17", + "pip: conflicting-certifi-requirement 1.2.3 depends on certifi<2017.4.17", + "pip: The user requested (constraint) certifi==2021.5.30", + "pip: ", + "pip: To fix this you could try to:", + "pip: 1. loosen the range of package versions you've specified", + "pip: 2. remove package versions to allow {pip_to} attempt to solve the dependency " "conflict".format( pip_to="pip" if pip_version.version < PipVersion.v24_1.version else "pip to" ), - "", ] assert expected_lines == error_lines[13:], os.linesep.join( - difflib.unified_diff(os.linesep.join(expected_lines), os.linesep.join(error_lines[12:])) + difflib.unified_diff(expected_lines, error_lines[12:]) ) # The pip legacy resolver, though is not strict and will let us get away with this. diff --git a/tests/integration/cli/commands/test_lock_resolve_auth.py b/tests/integration/cli/commands/test_lock_resolve_auth.py index 327aec8ad..71b848bda 100644 --- a/tests/integration/cli/commands/test_lock_resolve_auth.py +++ b/tests/integration/cli/commands/test_lock_resolve_auth.py @@ -168,7 +168,7 @@ def assert_unauthorized( assert ( "There was 1 error downloading required artifacts:\n" "1. ansicolors 1.1.8 from {repo_url}/ansicolors-1.1.8-py2.py3-none-any.whl\n" - " ERROR: Could not install requirement ansicolors==1.1.8 from " + " pip: ERROR: Could not install requirement ansicolors==1.1.8 from " "{repo_url}/ansicolors-1.1.8-py2.py3-none-any.whl because of HTTP error 401 Client Error: " "Unauthorized for url: {repo_url}/ansicolors-1.1.8-py2.py3-none-any.whl for URL " "{repo_url}/ansicolors-1.1.8-py2.py3-none-any.whl".format( diff --git a/tests/integration/cli/commands/test_lock_update_issues_2332_2334.py b/tests/integration/cli/commands/test_lock_update_issues_2332_2334.py index 2635f03cf..e5e31a8b0 100644 --- a/tests/integration/cli/commands/test_lock_update_issues_2332_2334.py +++ b/tests/integration/cli/commands/test_lock_update_issues_2332_2334.py @@ -290,9 +290,9 @@ def test_lock_update_conflict( else re.escape( dedent( """\ - The conflict is caused by: - The user requested proj-b==1.* - The user requested (constraint) proj-b>=2 + pip: The conflict is caused by: + pip: The user requested proj-b==1.* + pip: The user requested (constraint) proj-b>=2 """ ) ) diff --git a/tests/integration/test_integration.py b/tests/integration/test_integration.py index 15372960e..dce25e855 100644 --- a/tests/integration/test_integration.py +++ b/tests/integration/test_integration.py @@ -1753,24 +1753,24 @@ def test_pip_issues_9420_workaround(): assert normalized_stderr.startswith( dedent( """\ - ERROR: Cannot install colorama==0.4.1 and isort[colors]==5.7.0 because these package versions have conflicting dependencies. - ERROR: ResolutionImpossible: for help visit https://pip.pypa.io/ + pip: ERROR: Cannot install colorama==0.4.1 and isort[colors]==5.7.0 because these package versions have conflicting dependencies. + pip: ERROR: ResolutionImpossible: for help visit https://pip.pypa.io/ """ ).strip() ), normalized_stderr assert normalized_stderr.endswith( dedent( """\ - The conflict is caused by: - The user requested colorama==0.4.1 - isort[colors] 5.7.0 depends on colorama<0.5.0 and >=0.4.3; extra == "colors" - - To fix this you could try to: - 1. loosen the range of package versions you've specified - 2. remove package versions to allow pip to attempt to solve the dependency conflict + pip: The conflict is caused by: + pip: The user requested colorama==0.4.1 + pip: isort[colors] 5.7.0 depends on colorama<0.5.0 and >=0.4.3; extra == "colors" + pip: + pip: To fix this you could try to: + pip: 1. loosen the range of package versions you've specified + pip: 2. remove package versions to allow pip to attempt to solve the dependency conflict """ ).strip() - ) + ), normalized_stderr @pytest.mark.skipif( @@ -1970,30 +1970,30 @@ def test_require_hashes(tmpdir): re.sub(r"\s+", " ", line.strip()): index for index, line in enumerate(as_constraints_result.error.splitlines()) } - index = error_lines["Expected sha512 worse"] + index = error_lines["pip: Expected sha512 worse"] assert ( index + 1 == error_lines[ - "Got ca602ae6dd925648c8ff87ef00bcef2d0ebebf1090b44e8dd43b75403f07db50269e5078f709cbce8e" - "7cfaedaf1b754d02dda08b6970b6a157cbf4c31ebc16a7" + "pip: Got ca602ae6dd925648c8ff87ef00bcef2d0ebebf1090b44e8dd43b75403f07db50269e5078f709c" + "bce8e7cfaedaf1b754d02dda08b6970b6a157cbf4c31ebc16a7" ] ) - index = error_lines["Expected sha384 bad"] + index = error_lines["pip: Expected sha384 bad"] assert ( index + 1 == error_lines[ - "Got 64ec6b63f74b7bdf161a9b38fabf59c0a691ba9ed325f0864fea984e0deabe648cbd12d619d3989b64" - "24488349df3b30" + "pip: Got 64ec6b63f74b7bdf161a9b38fabf59c0a691ba9ed325f0864fea984e0deabe648cbd12d619d39" + "89b6424488349df3b30" ] ) index = error_lines[ - "Expected sha256 2f4da4594db7e1e110a944bb1b551fdf4e6c136ad42e4234131391e21eb5b0d0" + "pip: Expected sha256 2f4da4594db7e1e110a944bb1b551fdf4e6c136ad42e4234131391e21eb5b0d0" ] assert ( index + 1 - == error_lines["Got 2f4da4594db7e1e110a944bb1b551fdf4e6c136ad42e4234131391e21eb5b0df"] + == error_lines["pip: Got 2f4da4594db7e1e110a944bb1b551fdf4e6c136ad42e4234131391e21eb5b0df"] ) diff --git a/tests/integration/test_issue_2113.py b/tests/integration/test_issue_2113.py new file mode 100644 index 000000000..39010adf8 --- /dev/null +++ b/tests/integration/test_issue_2113.py @@ -0,0 +1,181 @@ +# Copyright 2024 Pex project contributors. +# Licensed under the Apache License, Version 2.0 (see LICENSE). + +from __future__ import absolute_import + +import os.path +import re +from textwrap import dedent + +import pytest + +from pex import targets +from pex.build_system import pep_517 +from pex.common import safe_open +from pex.resolve.configured_resolver import ConfiguredResolver +from pex.result import try_ +from pex.typing import TYPE_CHECKING +from testing import PY_VER, IntegResults, run_pex_command +from testing.cli import run_pex3 + +if TYPE_CHECKING: + from typing import Any + + +@pytest.fixture +def feast_simulator_project(tmpdir): + # type: (Any) -> str + project_dir = os.path.join(str(tmpdir), "feast-simulator") + with safe_open(os.path.join(project_dir, "setup.py"), "w") as fp: + fp.write( + dedent( + """\ + from setuptools import setup + + + setup( + name="feast-simulator", + version="0.1.0", + install_requires=["ansicolors<1.1.9,>=1.0.*"] + ) + """ + ) + ) + return project_dir + + +skip_if_setuptools_too_old = pytest.mark.skipif( + PY_VER < (3, 7), + reason=( + "The setuptools / packaging compatible with Python<3.7 does not fail to process the bad " + "metadata used in this test." + ), +) + + +def assert_local_project_build_failure_message(result): + # type: (IntegResults) -> None + result.assert_failure( + expected_error_re=( + r".*" + r"^\s*pip:.*(?:{cause_distribution_hint_one}|{cause_distribution_hint_two}).*" + r"(?:{reason_one}|{reason_two}).*$" + r".*" + r"^\s*pip:.*{requirement}$" + r".*" + ).format( + # N.B.: We have two versions of cause and reason to account for permutations of Pip, + # setuptools and package resources messages which all intermix here. + cause_distribution_hint_one=re.escape( + "Failed to parse a requirement of feast-simulator 0.1.0" + ), + cause_distribution_hint_two=re.escape("error in feast-simulator setup command:"), + reason_one=re.escape( + "'install_requires' must be a string or list of strings containing valid " + "project/version requirement specifiers" + ), + reason_two=re.escape(".* suffix can only be used with `==` or `!=` operators"), + requirement=re.escape("ansicolors<1.1.9,>=1.0.*"), + ), + re_flags=re.DOTALL | re.MULTILINE, + ) + + +@skip_if_setuptools_too_old +def test_metadata_gen_from_local_project_failure_lock( + tmpdir, # type: Any + feast_simulator_project, # type: str +): + # type: (...) -> None + assert_local_project_build_failure_message( + run_pex3("lock", "create", feast_simulator_project, "-o", os.path.join(str(tmpdir), "lock")) + ) + + +@skip_if_setuptools_too_old +def test_metadata_gen_from_local_project_failure_build_pex( + tmpdir, # type: Any + feast_simulator_project, # type: str +): + # type: (...) -> None + assert_local_project_build_failure_message( + run_pex_command( + args=[feast_simulator_project, "-o", (os.path.join(str(tmpdir), "pex"))], quiet=True + ) + ) + + +@pytest.fixture +def feast_simulator_sdist( + tmpdir, # type: Any + feast_simulator_project, # type: str +): + # type: (...) -> str + with safe_open(os.path.join(feast_simulator_project, "pyproject.toml"), "w") as fp: + fp.write( + dedent( + """\ + [build-system] + build-backend = "setuptools.build_meta" + + # N.B.: We need an older setuptools to be able to build an sdist containing bad + # metadata. With setuptools 67.0.0, packaging 23.0 is vendored with strict + # requirement parsing that leads to setuptools refusing to build the sdist at all. + # See: https://setuptools.pypa.io/en/stable/history.html#v67-0-0 + requires = ["setuptools<67"] + """ + ) + ) + + return str( + try_( + pep_517.build_sdist( + project_directory=feast_simulator_project, + dist_dir=os.path.join(str(tmpdir), "build"), + target=targets.current(), + resolver=ConfiguredResolver.default(), + ) + ) + ) + + +def assert_dist_build_failure_message(result): + # type: (IntegResults) -> None + result.assert_failure( + expected_error_re=( + r".*" + r"^\s*pip:.*{cause_distribution_hint}.*$" + r".*" + r"^\s*pip:.*{reason}$" + r".*" + r"^\s*pip:.*{requirement}$" + r".*" + ).format( + cause_distribution_hint=re.escape("feast_simulator-0.1.0.dist-info"), + reason=re.escape(".* suffix can only be used with `==` or `!=` operators"), + requirement=re.escape("ansicolors<1.1.9,>=1.0.*"), + ), + re_flags=re.DOTALL | re.MULTILINE, + ) + + +@skip_if_setuptools_too_old +def test_metadata_gen_from_dist_failure_lock( + tmpdir, # type: Any + feast_simulator_sdist, # type: str +): + # type: (...) -> None + lock = os.path.join(str(tmpdir), "lock") + assert_dist_build_failure_message(run_pex3("lock", "create", feast_simulator_sdist, "-o", lock)) + + +@skip_if_setuptools_too_old +def test_metadata_gen_from_dist_failure_build_pex( + tmpdir, # type: Any + feast_simulator_sdist, # type: str +): + # type: (...) -> None + pex = os.path.join(str(tmpdir), "pex") + assert_dist_build_failure_message( + run_pex_command(args=[feast_simulator_sdist, "-o", pex], quiet=True) + ) diff --git a/tests/integration/test_pep_427.py b/tests/integration/test_pep_427.py index 92b423b0f..b984717a0 100644 --- a/tests/integration/test_pep_427.py +++ b/tests/integration/test_pep_427.py @@ -10,6 +10,7 @@ from pex.common import is_exe, safe_open from pex.pep_427 import install_wheel_interpreter from pex.pip.installation import get_pip +from pex.resolve.configured_resolver import ConfiguredResolver from pex.typing import TYPE_CHECKING from pex.venv.virtualenv import InstallationChoice, Virtualenv from testing import WheelBuilder, make_env @@ -27,12 +28,12 @@ def test_install_wheel_interpreter(tmpdir): assert not os.path.exists(cowsay_script) download_dir = os.path.join(str(tmpdir), "downloads") - get_pip().spawn_download_distributions( + get_pip(resolver=ConfiguredResolver.default()).spawn_download_distributions( download_dir=download_dir, requirements=["cowsay==5.0"] ).wait() wheel_dir = os.path.join(str(tmpdir), "wheels") - get_pip().spawn_build_wheels( + get_pip(resolver=ConfiguredResolver.default()).spawn_build_wheels( distributions=glob(os.path.join(download_dir, "*.tar.gz")), wheel_dir=wheel_dir ).wait() wheels = glob(os.path.join(wheel_dir, "*.whl")) diff --git a/tests/pip/test_log_analyzer.py b/tests/pip/test_log_analyzer.py new file mode 100644 index 000000000..03ac31305 --- /dev/null +++ b/tests/pip/test_log_analyzer.py @@ -0,0 +1,155 @@ +# Copyright 2024 Pex project contributors. +# Licensed under the Apache License, Version 2.0 (see LICENSE). + +from __future__ import absolute_import + +import os.path +import subprocess +from textwrap import dedent + +import pytest + +from pex.common import chmod_plus_x +from pex.jobs import Job +from pex.pip.log_analyzer import ErrorAnalyzer, ErrorMessage, LogAnalyzer, LogScrapeJob +from pex.typing import TYPE_CHECKING + +if TYPE_CHECKING: + from typing import Any, Optional + + import attr # vendor:skip +else: + from pex.third_party import attr + + +class NoopErrorAnalyzer(ErrorAnalyzer): + def analyze(self, line): + return self.Complete() + + +@attr.s +class FirstLineErrorAnalyzer(ErrorAnalyzer): + _error_message = attr.ib(default=None, init=False) # type: Optional[ErrorMessage] + + def analyze(self, line): + if self._error_message: + return self.Complete() + self._error_message = ErrorMessage(line) + return self.Continue(self._error_message) + + +@pytest.fixture +def log(tmpdir): + # type: (Any) -> str + + log = os.path.join(str(tmpdir), "pip.log") + with open(log, "w") as fp: + fp.write( + dedent( + """\ + Multi-line log output. + Line 2. + Key insight! + Line 4. + Last line. + """ + ) + ) + return log + + +@pytest.fixture +def script(tmpdir): + # type: (Any) -> str + + script = os.path.join(str(tmpdir), "exe.sh") + with open(script, "w") as fp: + fp.write( + dedent( + """\ + #!/bin/sh + + exit 42 + """ + ) + ) + chmod_plus_x(script) + return script + + +def assert_job_failure( + log, # type: str + script, # type: str + *log_analyzers # type: LogAnalyzer +): + # type: (...) -> str + + process = subprocess.Popen(args=[script]) + process.wait() + + finalized = [] + with pytest.raises(Job.Error) as exc_info: + LogScrapeJob( + command=[script], + process=process, + log=log, + log_analyzers=log_analyzers, + preserve_log=False, + finalizer=lambda code: finalized.append(code), + ).wait() + assert not os.path.exists(log) + assert [42] == finalized + return str(exc_info.value) + + +def test_errored_log_scrape_job_with_analysis( + tmpdir, # type: Any + log, # type: str + script, # type: str +): + # type: (...) -> None + + error_msg = assert_job_failure(log, script, NoopErrorAnalyzer(), FirstLineErrorAnalyzer()) + assert ( + "pip: Executing {script} failed with 42\n" + "STDERR:\n" + "Multi-line log output.\n".format(script=script) + ) == error_msg + + +def test_errored_log_scrape_job_with_no_analysis( + tmpdir, # type: Any + log, # type: str + script, # type: str +): + # type: (...) -> None + + error_msg = assert_job_failure(log, script, NoopErrorAnalyzer()) + assert ( + "pip: Executing {script} failed with 42\n" + "STDERR:\n" + "Multi-line log output.\n" + "Line 2.\n" + "Key insight!\n" + "Line 4.\n" + "Last line.\n".format(script=script) + ) == error_msg + + +def test_errored_log_scrape_job_with_no_analyzers( + tmpdir, # type: Any + log, # type: str + script, # type: str +): + # type: (...) -> None + + error_msg = assert_job_failure(log, script) + assert ( + "pip: Executing {script} failed with 42\n" + "STDERR:\n" + "Multi-line log output.\n" + "Line 2.\n" + "Key insight!\n" + "Line 4.\n" + "Last line.\n".format(script=script) + ) == error_msg diff --git a/tests/test_dist_metadata.py b/tests/test_dist_metadata.py index 2ad1fbcb7..4297e8150 100644 --- a/tests/test_dist_metadata.py +++ b/tests/test_dist_metadata.py @@ -28,6 +28,7 @@ from pex.pep_503 import ProjectName from pex.pex_warnings import PEXWarning from pex.pip.installation import get_pip +from pex.resolve.configured_resolver import ConfiguredResolver from pex.resolve.resolver_configuration import BuildConfiguration from pex.third_party.packaging.specifiers import SpecifierSet from pex.typing import TYPE_CHECKING @@ -59,7 +60,7 @@ def downloaded_sdist(requirement): # type: (str) -> Iterator[str] with temporary_dir() as td: download_dir = os.path.join(td, "download") - get_pip().spawn_download_distributions( + get_pip(resolver=ConfiguredResolver.default()).spawn_download_distributions( download_dir=download_dir, requirements=[requirement], transitive=False, @@ -103,7 +104,9 @@ def pip_tgz_sdist(): def pip_wheel(pip_tgz_sdist): # type: (str) -> Iterator[str] with temporary_dir() as wheel_dir: - get_pip().spawn_build_wheels([pip_tgz_sdist], wheel_dir=wheel_dir).wait() + get_pip(resolver=ConfiguredResolver.default()).spawn_build_wheels( + [pip_tgz_sdist], wheel_dir=wheel_dir + ).wait() wheels = os.listdir(wheel_dir) assert len(wheels) == 1, "Expected 1 wheel to be built for {}.".format(pip_tgz_sdist) wheel = os.path.join(wheel_dir, wheels[0]) diff --git a/tests/test_jobs.py b/tests/test_jobs.py index c10cb2103..7c460aaa8 100644 --- a/tests/test_jobs.py +++ b/tests/test_jobs.py @@ -1,6 +1,8 @@ # Copyright 2019 Pex project contributors. # Licensed under the Apache License, Version 2.0 (see LICENSE). +from __future__ import absolute_import + import json import os import subprocess @@ -8,12 +10,12 @@ import pytest -from pex.interpreter import spawn_python_job +from pex.interpreter import PythonInterpreter from pex.jobs import _ABSOLUTE_MAX_JOBS, DEFAULT_MAX_JOBS, Job, SpawnedJob, _sanitize_max_jobs from pex.typing import TYPE_CHECKING, cast if TYPE_CHECKING: - from typing import Any, Dict + from typing import Any, Dict, Iterable def test_sanitize_max_jobs_none(): @@ -40,6 +42,15 @@ def test_sanitize_max_jobs_too_large(): assert _ABSOLUTE_MAX_JOBS == _sanitize_max_jobs(_ABSOLUTE_MAX_JOBS + 5) +def spawn_python_job( + args, # type: Iterable[str] + **subprocess_kwargs # type: Any +): + # type: (...) -> Job + cmd, process = PythonInterpreter.get().open_process(args=args, **subprocess_kwargs) + return Job(command=cmd, process=process) + + def create_error_job(exit_code): # type: (int) -> Job return spawn_python_job(args=["-c", "import sys; sys.exit({})".format(exit_code)]) diff --git a/tests/tools/commands/test_repository.py b/tests/tools/commands/test_repository.py index 4a4b2629a..a164fd9a7 100644 --- a/tests/tools/commands/test_repository.py +++ b/tests/tools/commands/test_repository.py @@ -17,6 +17,7 @@ from pex.dist_metadata import Distribution, Requirement from pex.pip.installation import get_pip from pex.pip.version import PipVersion +from pex.resolve.configured_resolver import ConfiguredResolver from pex.resolve.resolver_configuration import BuildConfiguration from pex.third_party.packaging.specifiers import SpecifierSet from pex.typing import TYPE_CHECKING @@ -218,7 +219,7 @@ def test_extract_lifecycle(pex, pex_tools_env, tmpdir): # Since we'll be locking down indexes to just find-links, we need to include the wheel .whl # needed by vendored Pip. vendored_pip_dists_dir = os.path.join(str(tmpdir), "vendored-pip-dists") - get_pip().spawn_download_distributions( + get_pip(resolver=ConfiguredResolver.default()).spawn_download_distributions( download_dir=vendored_pip_dists_dir, requirements=[PipVersion.VENDORED.wheel_requirement], build_configuration=BuildConfiguration.create(allow_builds=False), diff --git a/tox.ini b/tox.ini index 4664152f6..b318170ae 100644 --- a/tox.ini +++ b/tox.ini @@ -137,6 +137,9 @@ commands = [testenv:{typecheck,check}] deps = + # We keep this compatible with Python 2.7 for the 2.7 type check. + pytest==4.6.11 + # This version should track the version in pex/vendor/__init__.py. attrs @ git+https://github.com/python-attrs/attrs@947bfb542104209a587280701d8cb389c813459d httpx==0.23.0