https://pantsbuild.org/ logo
#pex
Title
# pex
w

witty-crayon-22786

03/18/2020, 12:50 AM
more followup on the pex 2.0 upgrade: verbosity
we have a small handful (luckily!) of errors that reduce to things like:
Copy code
Exception message: Failed to resolve compatible distributions:
1: pendulum==1.4.4 requires tzlocal<2.0.0.0,>=1.5.0.0 but tzlocal 2.0.0 was resolved
PEX_VERBOSE seems to be filtered out of the environment, and
-ldebug
does not seem to be propagated through
having typed this out, i believe that we probably had something in place to propagate
-ldebug
through as a pex verbosity level
that might have been lost in the upgrade.
i will look at how to restore it in v1.
hm. this is challenging, i think. because the PEX Env continues to be a global static, and
Copy code
File ".pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/python/pex_build_util.py", line 188, in _resolve_multi
    max_parallel_jobs=python_setup.resolver_jobs,
  File ".pex/installed_wheels/30c1b4c3cda65f3686f402d62ee6f52ac0358408/pex-2.1.6-py2.py3-none-any.whl/pex/resolver.py", line 802, in resolve_multi
    return list(resolve_request.resolve_distributions(ignore_errors=ignore_errors))
  File ".pex/installed_wheels/30c1b4c3cda65f3686f402d62ee6f52ac0358408/pex-2.1.6-py2.py3-none-any.whl/pex/resolver.py", line 578, in resolve_distributions
    self._check_resolve(resolved_distributions)
  File ".pex/installed_wheels/30c1b4c3cda65f3686f402d62ee6f52ac0358408/pex-2.1.6-py2.py3-none-any.whl/pex/resolver.py", line 618, in _check_resolve
    for index, failure in enumerate(unsatisfied))
doesn't appear to allow for propagating in debug info.
...but. perhaps the fact that it is a global static actually allows for good bad behavior here? mutating it based on pants' own settings?
e

enough-analyst-54434

03/18/2020, 2:44 AM
There should be 0 changes to PEX_VERBOSE propagation in Pex or Pants. If you can sharpen up your question, perhaps I can help.
w

witty-crayon-22786

03/18/2020, 2:45 AM
-ldebug
used to trigger verbose pex behavior, but now it does not.
(for v1)
e

enough-analyst-54434

03/18/2020, 2:59 AM
OK. Do you happen to notice or know if this is for building pexes or running pexes or both?
w

witty-crayon-22786

03/18/2020, 3:00 AM
the exception above comes while resolving, which would be build time.
e

enough-analyst-54434

03/18/2020, 3:03 AM
OK - so probably pants.backend.python.tasks.resolve_requirements_task_base.ResolveRequirementsTaskBase
w

witty-crayon-22786

03/18/2020, 3:03 AM
Copy code
Exception caught: (pex.resolver.Unsatisfiable)
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/bin/daemon_pants_runner.py", line 278, in run
    runner.run()
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/bin/local_pants_runner.py", line 293, in run
    self._run()
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/bin/local_pants_runner.py", line 389, in _run
    goal_runner_result = self._maybe_run_v1()
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/bin/local_pants_runner.py", line 330, in _maybe_run_v1
    self._exiter,
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/bin/goal_runner.py", line 230, in run
    return self._run_goals()
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/bin/goal_runner.py", line 201, in _run_goals
    result = self._execute_engine()
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/bin/goal_runner.py", line 189, in _execute_engine
    result = engine.execute(self._context, self._goals)
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/engine/legacy_engine.py", line 21, in execute
    self.attempt(context, goals)
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/engine/round_engine.py", line 252, in attempt
    goal_executor.attempt(explain)
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/engine/round_engine.py", line 50, in attempt
    task.execute()
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/backend/python/tasks/resolve_requirements.py", line 29, in execute
    pex = self.resolve_requirements(interpreter, self.context.targets(has_python_requirements))
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/backend/python/tasks/resolve_requirements_task_base.py", line 96, in resolve_requirements
    pex_builder.add_requirement_libs_from(req_libs, platforms=platforms)
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/python/pex_build_util.py", line 135, in add_requirement_libs_from
    self.add_resolved_requirements(reqs, platforms=platforms)
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/python/pex_build_util.py", line 161, in add_resolved_requirements
    for resolved_dist in self.resolve_distributions(reqs, platforms=platforms):
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/python/pex_build_util.py", line 152, in resolve_distributions
    return self._resolve_multi(deduped_reqs, platforms=platforms, find_links=find_links)
  File "/Users/stuhood/.pex/installed_wheels/ed508aff6910eb46ab1cfd7310d8ed6f117e9d0d/pantsbuild.pants-1.26.0rc1+git3f37dd50-cp36-abi3-macosx_10_11_x86_64.whl/pants/python/pex_build_util.py", line 188, in _resolve_multi
    max_parallel_jobs=python_setup.resolver_jobs,
  File "/Users/stuhood/.pex/installed_wheels/30c1b4c3cda65f3686f402d62ee6f52ac0358408/pex-2.1.6-py2.py3-none-any.whl/pex/resolver.py", line 802, in resolve_multi
    return list(resolve_request.resolve_distributions(ignore_errors=ignore_errors))
  File "/Users/stuhood/.pex/installed_wheels/30c1b4c3cda65f3686f402d62ee6f52ac0358408/pex-2.1.6-py2.py3-none-any.whl/pex/resolver.py", line 578, in resolve_distributions
    self._check_resolve(resolved_distributions)
  File "/Users/stuhood/.pex/installed_wheels/30c1b4c3cda65f3686f402d62ee6f52ac0358408/pex-2.1.6-py2.py3-none-any.whl/pex/resolver.py", line 618, in _check_resolve
    for index, failure in enumerate(unsatisfied))
apologies. yes. full stack is:
this is the
1.26.x
branch
i might have gotten ahead of myself by referencing PEX_VERBOSE and
-ldebug
... the better question is probably just: "what should a user do when they see
Copy code
Exception message: Failed to resolve compatible distributions:
1: pendulum==1.4.4 requires tzlocal<2.0.0.0,>=1.5.0.0 but tzlocal 2.0.0 was resolved
" ... based on the past, i was expecting
-ldebug
to render additional info
e

enough-analyst-54434

03/18/2020, 3:07 AM
OK - it definitely helps to get that straight. 0 python v1 tasks use "debug" (-ldebug) as a trigger to do anything before or after.
w

witty-crayon-22786

03/18/2020, 3:09 AM
hm. so... hm.
oooh. so, perhaps the python log level used to apply?
because the pex resolver was using python logging?
e

enough-analyst-54434

03/18/2020, 3:11 AM
1st, on the above - know that Pex used to silently pick an invalid winner. This represents a real incompatibility you've had all along. 2nd, this is all the info pip gives. 3rd, but pex can do better: ... I thought I had an issue filed on this but I don't. I have a several months old hack at supplying better info, namely which deps require what. I'll file that issue after I poke about a bit and link back here. This is also needed by Toolchain.
w

witty-crayon-22786

03/18/2020, 3:12 AM
would it be reasonable to propagate the log level through to pip here: https://github.com/pantsbuild/pex/blob/a07954a1bce1cf0c023c67f36e4e37f078eb23ba/pex/pip.py#L68-L74 ?
re: incompatibility: i definitely believe it. am glad that we don't have more.
e

enough-analyst-54434

03/18/2020, 3:15 AM
I'm confused by your link. That link highlights where Pex already propagates PEX_VERBOSE to pip. Do you mean would it be reasonable to wire up -ldebug in pants to setup PEX_VERBOSE when we run the Pex builder?
w

witty-crayon-22786

03/18/2020, 3:15 AM
so, here is my theory.
1. pex uses (used?) python logging, so
-ldebug
caused it to be more verbose, including during resolution time
e

enough-analyst-54434

03/18/2020, 3:16 AM
nack
It uses a custom Tracer object and stderr
Instead of guessing at the debug canards, what do you want? A better message about what needs what is a pex change. Turning on full pip logging is exporting PEX_VERBOSE=9
There is nothing else there.
w

witty-crayon-22786

03/18/2020, 3:18 AM
exporting
PEX_VERBOSE
when running pants as a pex gets stripped by the outer invoke of pex
e

enough-analyst-54434

03/18/2020, 3:19 AM
aha - that's a much much better description
ok, just a sec
w

witty-crayon-22786

03/18/2020, 3:20 AM
but
-ldebug
used to result in resolver debug output from pex
and that always felt cleaner anyway since it was explicit
e

enough-analyst-54434

03/18/2020, 3:20 AM
That I don't believe.
PEX_VERBOSE stripping is believeable
On the ldebug, you have the same tools I do - search for '"debug"' plumbing in a task, that doesn't exist as a delta in the Pex upgrade.
(All -ldebug plumbing tasks have a line that does == "debug")
w

witty-crayon-22786

03/18/2020, 3:24 AM
...ahh. it looks like this logging was just in
pex_build_util
:
Copy code
20:23:25 00:08   [binary]
20:23:25 00:08     [py]
                   Invalidated 1 target.
                   cache for PythonBinary(BuildFileAddress(src/python/pants/util/BUILD, s3_log_aggregator)) is invalid, rebuilding
                   No customized shebang found for s3_log_aggregator
                     Dumping sources: PythonBinary(BuildFileAddress(src/python/pants/util/BUILD, s3_log_aggregator))
                     Dumping requirement: PythonRequirement(s3-log-parse==0.1.1)03:23:25 [DEBUG] urllib3.util.retry:pid=4001: Converted retries value: 5 -> Retry(total=5, connect=None, read=None, redirect=None, status=None)
03:23:25 [DEBUG] urllib3.util.retry:pid=4001: Converted retries value: 5 -> Retry(total=5, connect=None, read=None, redirect=None, status=None)

                     Dumping distribution: .../s3_log_parse-0.1.1-py3-none-any.whl
                     Dumping distribution: .../pytz-2019.1-py2.py3-none-any.whl
                     Dumping requirement: PythonRequirement(setuptools==40.6.3)03:23:26 [DEBUG] urllib3.util.retry:pid=4001: Converted retries value: 5 -> Retry(total=5, connect=None, read=None, redirect=None, status=None)

                     Dumping distribution: .../setuptools-40.6.3-py2.py3-none-any.whl
                   created .pants.d/binary/py/9f3432780b5f/src.python.pants.util.s3_log_aggregator/current/s3_log_aggregator.pex
                   created pex dist/s3_log_aggregator.pex
(with
-ldebug
on
1.25.x
)
e

enough-analyst-54434

03/18/2020, 3:27 AM
OK - thats pants logging not pex logging right?
w

witty-crayon-22786

03/18/2020, 3:27 AM
correct, so i was wrong about that.
e

enough-analyst-54434

03/18/2020, 3:27 AM
OK - good
e

enough-analyst-54434

03/18/2020, 3:27 AM
So, back to the error message. Pex prints that out after analyzing the results of pip's resolve. It can do better. I'm working on that this week
To figure out the issue right now though, you can do ... gimme a sec for some command line tricks
w

witty-crayon-22786

03/18/2020, 3:30 AM
(thanks a ton)
e

enough-analyst-54434

03/18/2020, 3:35 AM
OK, I think you need to get the pex command being run or at least the list of requirements passed to it. If you can get that, then: 1. pex -o investigate.pex --ignore-errors [requirements]
Working on 2, but you can confirm 1 gets you a pex.
2.
zipinfo -1 investigate.pex | grep METADATA | while read md; do echo "Requirements for $md: " && unzip -qc investigate.pex $md | grep Requires-Dist | grep tzlocal; done
That will show you which dists in the pex have what requirements for tzlocal leading the resolve to have no (proper) solution.
w

witty-crayon-22786

03/18/2020, 3:42 AM
ok: seeing if i can do that from within
pex_build_utils
, since the
ignore_errors
flag is exposed.
e

enough-analyst-54434

03/18/2020, 3:43 AM
OK. That check is basically what the improved Pex error message will derive from. That same info.
w

witty-crayon-22786

03/18/2020, 3:49 AM
passing
resolve_multi(.., ignore_errors=True)
does appear to skip validating the resolve, which allows the test to start and fail. working on adapting your command for the extracted pex under
.pants.d
e

enough-analyst-54434

03/18/2020, 3:51 AM
Excellent.
w

witty-crayon-22786

03/18/2020, 3:54 AM
requires a
clean-all
, but
find .pants.d -name METADATA | while read md; do echo "Requirements for $md: " && cat $md | grep Requires-Dist | grep tzlocal; done
appears to work... reports about 5 or 6 declarations of tzlocal out of 265!
so, this is workable: thanks a lot John.
this will unblock us to fix these errors before the better debug output. we should probably still target your fix at 1.26.x
e

enough-analyst-54434

03/18/2020, 3:58 AM
OK, great. I'll include a cherry-pick label and Tweeps for review on the Pex change and Pants upgrade change.
w

witty-crayon-22786

03/18/2020, 3:59 AM
awesome. have a great night, and thanks again!