https://pantsbuild.org/ logo
Join Slack
Powered by
more followup on the pex 2.0 upgrade: verbosity
# pex
w
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
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
-ldebug
used to trigger verbose pex behavior, but now it does not.
(for v1)
e
OK. Do you happen to notice or know if this is for building pexes or running pexes or both?
w
the exception above comes while resolving, which would be build time.
e
OK - so probably pants.backend.python.tasks.resolve_requirements_task_base.ResolveRequirementsTaskBase
w
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
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
hm. so... hm.
oooh. so, perhaps the python log level used to apply?
because the pex resolver was using python logging?
e
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
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
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
so, here is my theory.
1. pex uses (used?) python logging, so 
-ldebug
caused it to be more verbose, including during resolution time
e
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
exporting 
PEX_VERBOSE
when running pants as a pex gets stripped by the outer invoke of pex
e
aha - that's a much much better description
ok, just a sec
w
but 
-ldebug
used to result in resolver debug output from pex
and that always felt cleaner anyway since it was explicit
e
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
...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
OK - thats pants logging not pex logging right?
w
correct, so i was wrong about that.
e
OK - good
w
e
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
(thanks a ton)
e
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
ok: seeing if i can do that from within 
pex_build_utils
, since the 
ignore_errors
flag is exposed.
e
OK. That check is basically what the improved Pex error message will derive from. That same info.
w
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
Excellent.
w
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
OK, great. I'll include a cherry-pick label and Tweeps for review on the Pex change and Pants upgrade change.
w
awesome. have a great night, and thanks again!
Open in Slack
PreviousNext
Powered by