"error downloading required artifacts" is misleading when the artifact is already in the cache

[cburroughs]

Trying to debug a problem with pants 2.16.0rc0 where an M1 mac user would get:

14:26:02.33 [ERROR] 1 Exception encountered:

Engine traceback:
  in `run` goal

ProcessExecutionFailure: Process 'Building 1 requirement for src.py.eq.feast_features/feast-cli.pex from the 3rdparty/py/dags.lock resolve: feast[aws,snowflake]==0.25.0' failed with exit code 1.
stdout:

stderr:
There was 1 error downloading required artifacts:
1. feast 0.25 from https://files.pythonhosted.org/packages/fc/58/7dee70ba96b0dd79d15a9378a3d327ae5930d34a21f23479391f93e898e4/feast-0.25.0.tar.gz
    hint: See above for details.

Lead to adding adding a bunch of -vvvv to the __run.sh script. This suggests the actual problem is:

Collecting https://files.pythonhosted.org/packages/fc/58/7dee70ba96b0dd79d15a9378a3d327ae5930d34a21f23479391f93e898e4/feast-0.25.0.tar.gz
  Using cached feast-0.25.0.tar.gz (3.4 MB)
  Installing build dependencies: started
  Installing build dependencies: finished with status 'done'
  Getting requirements to build wheel: started
  Getting requirements to build wheel: finished with status 'done'
  Installing backend dependencies: started
  Installing backend dependencies: finished with status 'done'
  Preparing metadata (pyproject.toml): started
  Preparing metadata (pyproject.toml): finished with status 'error'

Which turns out to be a real problem with this package and M1 Mac, but that's not the direction the original error message was pointing.

Fuller log: https://gist.github.com/cburroughs/56b625630743b864a42fb0363854e389

[jsirois]

@cburroughs since Pex does provide -v for exactly this reason, would you be satisfied if Pants ran Pex that way, suppressing output on success, but dumping the -vs log on failure? Or are you wanting Pex to learn Pip / all the various ways the packages it builds can fail, parse that set of errors and produce a higher level error message?

[cburroughs]

would you be satisfied if Pants ran Pex that way, suppressing output on success, but dumping the -vs log on failure?

I think that would have been enough to point the person (new to pants and pex) who go the error in a helpful direction, instead of trying to curl or looking for dns problems.

[jsirois]

Ok. So, just to make sure I'm not giving you the runaround, if I move / create a new issue over in Pants to do this then that is agreeable to you @cburroughs?

[cburroughs]

I think what you suggested from pants is the better and more general improvement.

But on a pendantic note in pex land, I do still think "error downloading required artifacts" as a message should be reserved for actual errors downloading

[aviau]

I just finished a long debugging session where we were debugging networking problems to realize pex wasn't downloading at all...

[jsirois]

@aviau, are you too a Pants user or a direct Pex user? As a direct Pex user you have easier access to debug logs (-v (up to 9 times) or --preserve-pip-download-log, which is where the failure to build error (which is presumably your error - you don't provide details) would show up.

[aviau]

Yeah I am a pants user, I could get the logs via PANTS_PEX_VERBOSITY=9, but the "error downloading required artifacts" really pointed us in the wrong direction. We had just installed a pip proxy so we were certain that this was related to our pip proxy, but it turned out to be an installation issue.

[jsirois]

Ok. As @cburroughs said here:

But on a pendantic note in pex land, I do still think "error downloading required artifacts" as a message should be reserved for actual errors downloading

However, from Pex's perspective the error did in fact occur downloading. It just finished calling pip download ... on a bunch of artifacts and Pip's error message was hint: See above for details.. As such, the following is the current error message Pex composes:

1: There was 1 error downloading required artifacts:
2: 1. feast 0.25 from https://files.pythonhosted.org/packages/fc/58/7dee70ba96b0dd79d15a9378a3d327ae5930d34a21f23479391f93e898e4/feast-0.25.0.tar.gz
3:    hint: See above for details.

Lines 1 and 2 are from Pex, line 3 is the error message from Pip.

For Pex to do better it would have to dissect the verbose Pip logs to divine if the error was a download error (network error), or a metadata generation error (the case that caught you both up). As you might guess, this is likely non-trivial given the varietly of failure cases and the variety of Pip versions Pex supports. With two reports though I can look at at least covering the metadata generation case. Perhaps I can surface those without too-gross hacks.

As an aside, I also just noticed the issue title:

"error downloading required artifacts" is misleading when the artifact is already in the cache

The following lines in the OP, which I think is where the title comes from, are also Pip log lines. In other words, this is Pip's cache, not Pex's; so Pex is unaware:

Collecting https://files.pythonhosted.org/packages/fc/58/7dee70ba96b0dd79d15a9378a3d327ae5930d34a21f23479391f93e898e4/feast-0.25.0.tar.gz
  Using cached feast-0.25.0.tar.gz (3.4 MB)

Hopefully it's clear there is a theme here. Pex switched from a bespoke resolver to Pip in the 1.x -> 2.x transition (with the aim of leveraging the community standard resolver to reduce bugs and match closer to user expectations). As such, Pex tries to stay out of resolving and hand off to Pip. This obviously comes at a price of only having as good messaging as Pip itself unless Pex decides to re-wade into resolution details and be a back-seat driver to Pip. I do think some back seat driving may be warranted in these common confusing cases if possible, but for full transparency on what's really going on here.

[DLukeNelson]

What about something like a prefix on those lines? Something like:

1: [pex] There was 1 error downloading required artifacts:
2: [pex] 1. feast 0.25 from https://files.pythonhosted.org/packages/fc/58/7dee70ba96b0dd79d15a9378a3d327ae5930d34a21f23479391f93e898e4/feast-0.25.0.tar.gz
3: [pip]   hint: See above for details.

would immediately have made it clear to me that I needed to get into the pip logs, instead of assuming that what came above (the list of requirements, and some warnings about forcibly re-creating .lck files, in my case) was the information I was told to "See above"

[jsirois]

@DLukeNelson that mostly makes sense. You're seeing things through Pants eyes though; so the [pex] stuff is redundant from the Pex layer. With Pex verbose logging turned on Pex log lines are prefixed with pex: but Pex end-user output (which is output whether or not logging is enables), is of course, not. The upshot is this:

1. Latest Pip:

   :; python -mpex --pip-version latest --lock lock.json -ofeast.pex
   There was 1 error downloading required artifacts:
   1. feast 0.25 from https://files.pythonhosted.org/packages/fc/58/7dee70ba96b0dd79d15a9378a3d327ae5930d34a21f23479391f93e898e4/feast-0.25.0.tar.gz
       pip:   error: subprocess-exited-with-error
       pip:
       pip:   × Preparing metadata (pyproject.toml) did not run successfully.
       pip:   │ exit code: 1
       pip:   ╰─> See above for output.
       pip:
       pip:   note: This error originates from a subprocess, and is likely not a problem with pip.
       pip: error: metadata-generation-failed
       pip:
       pip: × Encountered error while generating package metadata.
       pip: ╰─> See above for output.
       pip:
       pip: note: This is an issue with the package mentioned above, not pip.
       pip: hint: See above for details.
   

2. Vendored Pip (oldest supported by Pex):

   :; python -mpex --pip-version vendored --lock lock.json -ofeast.pex
   There was 1 error downloading required artifacts:
   1. feast 0.25 from https://files.pythonhosted.org/packages/fc/58/7dee70ba96b0dd79d15a9378a3d327ae5930d34a21f23479391f93e898e4/feast-0.25.0.tar.gz
       pip:   error: subprocess-exited-with-error
       pip:
       pip:   × Preparing metadata (pyproject.toml) did not run successfully.
       pip:   │ exit code: 1
       pip:   ╰─> [3 lines of output]
       pip:       /home/jsirois/.pex/pip/23.0.1/pip_cache/.tmp/pip-build-env-htqx4b9g/overlay/lib/python3.11/site-packages/setuptools_scm/_integration/setuptools.py:92: UserWarning: version of feast already set
       pip:         warnings.warn(f"version of {dist_name} already set")
       pip:       error in feast setup command: 'extras_require' must be a dictionary whose values are strings or lists of strings containing valid project/version requirement specifiers.
       pip:       [end of output]
       pip:
       pip:   note: This error originates from a subprocess, and is likely not a problem with pip.
       pip: error: metadata-generation-failed
       pip:
       pip: × Encountered error while generating package metadata.
       pip: ╰─> from https://files.pythonhosted.org/packages/fc/58/7dee70ba96b0dd79d15a9378a3d327ae5930d34a21f23479391f93e898e4/feast-0.25.0.tar.gz
       pip:
       pip: note: This is an issue with the package mentioned above, not pip.
       pip: hint: See above for details.
   

Still not great, since Pip buries the real error here in its own subprocess, but I think the best I can reasonably do. Also its worth noting Pip output is slightly worse with latest Pip here.

So now Pex points a finger. If Pants wants to point fingers at a higher layer, then this could all come out:

:; python -mpex --pip-version latest --lock lock.json -ofeast.pex
[pex] There was 1 error downloading required artifacts:
[pex] 1. feast 0.25 from https://files.pythonhosted.org/packages/fc/58/7dee70ba96b0dd79d15a9378a3d327ae5930d34a21f23479391f93e898e4/feast-0.25.0.tar.gz
[pex]     pip:   error: subprocess-exited-with-error
[pex]     pip:
[pex]     pip:   × Preparing metadata (pyproject.toml) did not run successfully.
[pex]     pip:   │ exit code: 1
[pex]     pip:   ╰─> See above for output.
[pex]     pip:
[pex]     pip:   note: This error originates from a subprocess, and is likely not a problem with pip.
[pex]     pip: error: metadata-generation-failed
[pex]     pip:
[pex]     pip: × Encountered error while generating package metadata.
[pex]     pip: ╰─> See above for output.
[pex]     pip:
[pex]     pip: note: This is an issue with the package mentioned above, not pip.
[pex]     pip: hint: See above for details.

I.E. Pants slaps its own context on where an error came from from its, higher layer, perspective. For all Pants knows, There is only Pex going on here and no Pip at all.

[jsirois]

Ok, the better download error messages are now available in v2.13.0.