pex_test.py can timeout/hang

[stuhood]

pex_test.py occasionally takes much longer than its (recently increased) 10 minute timeout. Example: https://github.com/pantsbuild/pants/actions/runs/3087423728/jobs/5001705069

In at least two of the runs that I've seen, it seems to have timed out relatively early in its run, suggesting that it might actually be hanging in some cases, rather than just running slowly:

 16:15:19.60 [ERROR] Completed: Run Pytest - src/python/pants/backend/python/util_rules/pex_test.py:tests failed (exit code -15).
============================= test session starts ==============================
collecting ... collected 27 items

src/python/pants/backend/python/util_rules/pex_test.py::test_pex_execution[True-Pex] PASSED [  3%]
src/python/pants/backend/python/util_rules/pex_test.py::test_pex_execution[True-VenvPex] PASSED [  7%]
src/python/pants/backend/python/util_rules/pex_test.py::test_pex_execution[False-Pex] PASSED [ 11%]
src/python/pants/backend/python/util_rules/pex_test.py::test_pex_execution[False-VenvPex] PASSED [ 14%]
src/python/pants/backend/python/util_rules/pex_test.py::test_pex_environment[Pex] PASSED [ 18%]
src/python/pants/backend/python/util_rules/pex_test.py::test_pex_environment[VenvPex] PASSED [ 22%]
src/python/pants/backend/python/util_rules/pex_test.py::test_pex_working_directory[Pex] PASSED [ 25%]
src/python/pants/backend/python/util_rules/pex_test.py::test_pex_working_directory[VenvPex] PASSED [ 29%]
src/python/pants/backend/python/util_rules/pex_test.py::test_resolves_dependencies PASSED [ 33%]
src/python/pants/backend/python/util_rules/pex_test.py::test_requirement_constraints PASSED [ 37%]
src/python/pants/backend/python/util_rules/pex_test.py::test_lockfiles 


Exceeded timeout of 600.0 seconds when executing local process: Run Pytest for src/python/pants/backend/python/util_rules/pex_test.py:tests

[benjyw]

Yeah, pretty sure it's hanging, not slow, because running it locally takes just a couple of minutes.

[stuhood]

Drafted here: #16928 ... will land if it doesn't hit some other timeout in the same file instead.

[stuhood]

It doesn't look like that was it:

17:28:54.85 [ERROR] Completed: Run Pytest - src/python/pants/backend/python/util_rules/pex_test.py:tests failed (exit code -15).
============================= test session starts ==============================
collecting ... collected 27 items

src/python/pants/backend/python/util_rules/pex_test.py::test_pex_execution[True-Pex] PASSED [  3%]
src/python/pants/backend/python/util_rules/pex_test.py::test_pex_execution[True-VenvPex] PASSED [  7%]
src/python/pants/backend/python/util_rules/pex_test.py::test_pex_execution[False-Pex] PASSED [ 11%]
src/python/pants/backend/python/util_rules/pex_test.py::test_pex_execution[False-VenvPex] PASSED [ 14%]
src/python/pants/backend/python/util_rules/pex_test.py::test_pex_environment[Pex] PASSED [ 18%]
src/python/pants/backend/python/util_rules/pex_test.py::test_pex_environment[VenvPex] PASSED [ 22%]
src/python/pants/backend/python/util_rules/pex_test.py::test_pex_working_directory[Pex] PASSED [ 25%]
src/python/pants/backend/python/util_rules/pex_test.py::test_pex_working_directory[VenvPex] PASSED [ 29%]
src/python/pants/backend/python/util_rules/pex_test.py::test_resolves_dependencies PASSED [ 33%]
src/python/pants/backend/python/util_rules/pex_test.py::test_requirement_constraints PASSED [ 37%]
src/python/pants/backend/python/util_rules/pex_test.py::test_lockfiles ERROR [ 40%]
src/python/pants/backend/python/util_rules/pex_test.py::test_entry_point PASSED [ 44%]
src/python/pants/backend/python/util_rules/pex_test.py::test_interpreter_constraints 


Exceeded timeout of 600.0 seconds when executing local process: Run Pytest for src/python/pants/backend/python/util_rules/pex_test.py:tests

[Eric-Arellano]

If you haven't tried yet, running with --debug locally may be instructive

[stuhood]

If you haven't tried yet, running with --debug locally may be instructive

Doesn't repro locally... finishes in a minute or two. But I haven't yet tried to repro without caches.

[kaos]

I repro this locally, and in #16910

https://pantsbuild.slack.com/archives/C0D7TNJHL/p1663758370882199?thread_ts=1662998340.585589&channel=C0D7TNJHL&message_ts=1663758370.882199

[stuhood]

I repro this locally, and in #16910

https://pantsbuild.slack.com/archives/C0D7TNJHL/p1663758370882199?thread_ts=1662998340.585589&channel=C0D7TNJHL&message_ts=1663758370.882199

Ooh: if you repro locally, I'm very curious what you're seeing in stack traces via py-spy, both in the test process, and in the child process(es) if any.

[stuhood]

Fixed by #16939: thanks @tdyas!