Inconsistent goal output #13276
Comments
|
A third run again shows no Flake8 output. This include / exclude appears to be ~random: $ ./pants --changed-since=upstream/main fmt lint check test
11:05:00.87 [INFO] Completed: Format with docformatter - Docformatter made no changes.
11:05:00.87 [INFO] Completed: Format with Autoflake - autoflake made no changes.
11:05:00.87 [INFO] Completed: Format with isort - isort made no changes.
11:05:00.87 [INFO] Completed: Format with Black - Black made no changes.
All done! ✨ 🍰 ✨
2 files left unchanged.
✓ Black made no changes.
✓ Docformatter made no changes.
✓ autoflake made no changes.
✓ isort made no changes.
11:05:00.87 [INFO] Completed: Lint with autoflake - autoflake succeeded.
11:05:00.87 [INFO] Completed: Lint with Black - Black succeeded.
All done! ✨ 🍰 ✨
2 files would be left unchanged.
11:05:00.87 [INFO] Completed: Lint with isort - isort succeeded.
11:05:00.87 [INFO] Completed: Lint with docformatter - Docformatter succeeded.
✓ Black succeeded.
✓ Docformatter succeeded.
𐄂 Flake8 failed.
✓ autoflake succeeded.
✓ isort succeeded. |
|
And again after fixing the lint, but this time in mypy: $ ./pants --changed-since=upstream/main fmt lint check test
11:06:56.58 [INFO] Initializing scheduler...
11:06:56.72 [INFO] Scheduler initialized.
11:06:57.99 [INFO] Completed: Format with Autoflake - autoflake made no changes.
11:06:59.51 [INFO] Completed: Format with Black - Black made no changes.
All done! ✨ 🍰 ✨
2 files left unchanged.
11:07:00.72 [INFO] Completed: Format with docformatter - Docformatter made no changes.
11:07:00.80 [INFO] Completed: Format with isort - isort made no changes.
✓ Black made no changes.
✓ Docformatter made no changes.
✓ autoflake made no changes.
✓ isort made no changes.
11:07:00.88 [INFO] Completed: Lint with isort - isort succeeded.
11:07:00.90 [INFO] Completed: Lint with autoflake - autoflake succeeded.
11:07:00.92 [INFO] Completed: Lint with docformatter - Docformatter succeeded.
11:07:01.21 [INFO] Completed: Lint with Black - Black succeeded.
All done! ✨ 🍰 ✨
2 files would be left unchanged.
11:07:02.04 [INFO] Completed: Lint with Flake8 - Flake8 succeeded.
✓ Black succeeded.
✓ Docformatter succeeded.
✓ Flake8 succeeded.
✓ autoflake succeeded.
✓ isort succeeded.
11:07:04.98 [INFO] Completed: Building extra_type_stubs.pex
11:07:06.94 [INFO] Completed: Building mypy.pex from mypy_default_lockfile.txt
11:07:10.08 [INFO] Completed: Installing 3rdparty/python/lockfiles/user_reqs.txt
11:07:10.48 [INFO] Completed: Extracting 13 requirements to build requirements.pex from lockfile.pex: PyYAML<5.5,>=5.4, ansicolors==1.1.8, humbug==0.2.6, ijson==3.1.4, packaging==21.0, pex==2.1.51, pytest<6.3,>=6.2.4, setuptools<5... (120 characters truncated)
11:07:11.03 [INFO] Completed: Building requirements_venv.pex
𐄂 MyPy failed.And again: $ ./pants --changed-since=upstream/main fmt lint check test
11:07:51.56 [INFO] Completed: Format with Black - Black made no changes.
All done! ✨ 🍰 ✨
2 files left unchanged.
11:07:51.56 [INFO] Completed: Format with Autoflake - autoflake made no changes.
11:07:51.56 [INFO] Completed: Format with isort - isort made no changes.
11:07:51.56 [INFO] Completed: Format with docformatter - Docformatter made no changes.
✓ Black made no changes.
✓ Docformatter made no changes.
✓ autoflake made no changes.
✓ isort made no changes.
11:07:51.57 [INFO] Completed: Lint with autoflake - autoflake succeeded.
11:07:51.57 [INFO] Completed: Lint with Black - Black succeeded.
All done! ✨ 🍰 ✨
2 files would be left unchanged.
11:07:51.57 [INFO] Completed: Lint with docformatter - Docformatter succeeded.
11:07:51.57 [INFO] Completed: Lint with isort - isort succeeded.
11:07:51.57 [INFO] Completed: Lint with Flake8 - Flake8 succeeded.
✓ Black succeeded.
✓ Docformatter succeeded.
✓ Flake8 succeeded.
✓ autoflake succeeded.
✓ isort succeeded.
𐄂 MyPy failed.But then fine on a 3rd try: $ ./pants --changed-since=upstream/main fmt lint check test
11:08:21.83 [INFO] Completed: Format with Autoflake - autoflake made no changes.
11:08:21.83 [INFO] Completed: Format with isort - isort made no changes.
11:08:21.83 [INFO] Completed: Format with docformatter - Docformatter made no changes.
11:08:21.83 [INFO] Completed: Format with Black - Black made no changes.
All done! ✨ 🍰 ✨
2 files left unchanged.
✓ Black made no changes.
✓ Docformatter made no changes.
✓ autoflake made no changes.
✓ isort made no changes.
11:08:21.83 [INFO] Completed: Lint with docformatter - Docformatter succeeded.
11:08:21.83 [INFO] Completed: Lint with autoflake - autoflake succeeded.
11:08:21.83 [INFO] Completed: Lint with isort - isort succeeded.
11:08:21.83 [INFO] Completed: Lint with Flake8 - Flake8 succeeded.
11:08:21.83 [INFO] Completed: Lint with Black - Black succeeded.
All done! ✨ 🍰 ✨
2 files would be left unchanged.
✓ Black succeeded.
✓ Docformatter succeeded.
✓ Flake8 succeeded.
✓ autoflake succeeded.
✓ isort succeeded.
11:08:26.33 [ERROR] Completed: Typecheck using MyPy - MyPy failed (exit code 1).
src/python/pants/engine/process_test.py: note: In function "test_find_binary_file_path":
src/python/pants/engine/process_test.py:313:78: error: Argument "search_path"
to "BinaryPathRequest" has incompatible type "List[local]"; expected
"Iterable[str]" [arg-type]
... [BinaryPathRequest(binary_name=binary_name, search_path=search_path)]
^
Found 1 error in 1 file (checked 2 source files)
𐄂 MyPy failed. |
|
And one last time with test - this is very easy to repro apparently: $ ./pants --changed-since=upstream/main fmt lint check test
11:10:10.73 [INFO] Completed: Format with Autoflake - autoflake made no changes.
11:10:11.19 [WARN] Completed: Format with Black - Black made changes.
reformatted src/python/pants/engine/process_test.py
All done! ✨ 🍰 ✨
1 file reformatted, 1 file left unchanged.
11:10:11.30 [INFO] Completed: Format with docformatter - Docformatter made no changes.
11:10:11.36 [INFO] Completed: Format with isort - isort made no changes.
+ Black made changes.
✓ Docformatter made no changes.
✓ autoflake made no changes.
✓ isort made no changes.
11:10:11.37 [INFO] Filesystem changed during run: retrying `Fmt` in 500ms...
11:10:11.95 [INFO] Completed: Lint with isort - isort succeeded.
11:10:11.98 [INFO] Completed: Lint with autoflake - autoflake succeeded.
11:10:12.00 [INFO] Completed: Lint with docformatter - Docformatter succeeded.
11:10:12.08 [INFO] Completed: Lint with Flake8 - Flake8 succeeded.
11:10:12.28 [INFO] Completed: Lint with Black - Black succeeded.
All done! ✨ 🍰 ✨
2 files would be left unchanged.
✓ Black succeeded.
✓ Docformatter succeeded.
✓ Flake8 succeeded.
✓ autoflake succeeded.
✓ isort succeeded.
11:10:16.98 [INFO] Completed: Typecheck using MyPy - MyPy succeeded.
Success: no issues found in 2 source files
✓ MyPy succeeded.
11:10:22.63 [INFO] Completed: Building pytest.pex from 3rdparty/python/lockfiles/pytest.txt
11:10:22.87 [INFO] Completed: Building local_dists.pex
11:10:23.84 [INFO] Completed: Building pytest_runner.pex
𐄂 src/python/pants/engine/process_test.py:tests failed.Fine on 2nd run though: $ ./pants --changed-since=upstream/main fmt lint check test
11:10:40.58 [INFO] Completed: Format with Autoflake - autoflake made no changes.
11:10:40.97 [INFO] Completed: Format with Black - Black made no changes.
All done! ✨ 🍰 ✨
2 files left unchanged.
11:10:40.97 [INFO] Completed: Format with docformatter - Docformatter made no changes.
11:10:40.97 [INFO] Completed: Format with isort - isort made no changes.
✓ Black made no changes.
✓ Docformatter made no changes.
✓ autoflake made no changes.
✓ isort made no changes.
11:10:40.98 [INFO] Completed: Lint with Black - Black succeeded.
All done! ✨ 🍰 ✨
2 files would be left unchanged.
11:10:40.98 [INFO] Completed: Lint with autoflake - autoflake succeeded.
11:10:40.98 [INFO] Completed: Lint with isort - isort succeeded.
11:10:40.98 [INFO] Completed: Lint with docformatter - Docformatter succeeded.
11:10:40.98 [INFO] Completed: Lint with Flake8 - Flake8 succeeded.
✓ Black succeeded.
✓ Docformatter succeeded.
✓ Flake8 succeeded.
✓ autoflake succeeded.
✓ isort succeeded.
11:10:41.04 [INFO] Completed: Typecheck using MyPy - MyPy succeeded.
Success: no issues found in 2 source files
✓ MyPy succeeded.
11:10:42.03 [ERROR] Completed: Run Pytest - src/python/pants/engine/process_test.py:tests failed (exit code 1).
============================= test session starts ==============================
collected 16 items
src/python/pants/engine/process_test.py ...............F [100%]
=================================== FAILURES ===================================
__________________________ test_find_binary_file_path __________________________
rule_runner = RuleRunner(build_root=/tmp/_BUILD_ROOTl3ikv17s)
tmpdir = local('/tmp/pytest-of-jsirois/pytest-1/test_find_binary_file_path0')
def test_find_binary_file_path(rule_runner: RuleRunner, tmpdir: py.path.local) -> None:
binary_name = "mybin"
binary_path_abs = tmpdir / "bin" / binary_name
binary_path_abs.write("", ensure=True)
binary_path_abs.chmod(0o755)
binary_paths = rule_runner.request(
BinaryPaths,
[BinaryPathRequest(binary_name=binary_name, search_path=[binary_path_abs.strpath])],
)
> assert binary_paths.first_path is not None
E AssertionError: assert None is not None
E + where None = BinaryPaths(binary_name='mybin', paths=()).first_path
src/python/pants/engine/process_test.py:315: AssertionError
- generated xml file: /tmp/process-executionHDL5Ut/src.python.pants.engine.process_test.py.tests.xml -
=========================== short test summary info ============================
FAILED src/python/pants/engine/process_test.py::test_find_binary_file_path - ...
========================= 1 failed, 15 passed in 0.75s =========================
𐄂 src/python/pants/engine/process_test.py:tests failed. |
|
This is mildly terrifying. I've never experienced it (or at least noticed it) but getting to the bottom of this seems important. Maybe this manifests more on linux than macos. |
|
I got a new laptop finally and it has 16 cores, etc. This only started happening since the switch to the new laptop which is just ~1 week so it could be smoking out racy stuff better. |
|
Ah, that seems significant. Yes, probably there is a race that your new machine is exposing. Which puts a debugging burden on you alas. |
|
This is probably #11626, but it sounds like you have an excellent environment to reproduce it in. Very interested in getting to the bottom of it. In the first example in the description, the expectation was that the workunit for the |
|
@jsirois : based on the data you reported out-of-band, my best hypothesis is that this is due to these lines: pants/src/rust/engine/ui/src/console_ui.rs Lines 117 to 125 in 6b1d215 These easiest path forward would be for you to confirm in your environment that that is what is happening. To do that, I'd recommend adding something like: diff --git a/src/rust/engine/ui/src/console_ui.rs b/src/rust/engine/ui/src/console_ui.rs
index edec069808..b5d27c2577 100644
--- a/src/rust/engine/ui/src/console_ui.rs
+++ b/src/rust/engine/ui/src/console_ui.rs
@@ -119,7 +119,10 @@ impl ConsoleUI {
while let Ok(stderr) = stderr_receiver.recv() {
match first_bar.upgrade() {
Some(first_bar) => first_bar.println(stderr),
- None => break,
+ None => {
+ logging::debug_log!("repro.log", "Dropped: {:?}", stderr);
+ break;
+ }
}
}
});If that isn't what is happening, then my next guess would be that Regardless though, the solution for either issue will likely be to fix the synchronization of teardown. |
|
Ok, finally got around to this. That is what's happening. Every console ui dropped output run the repro.log gets created and logged to. |
|
Great! I'm not sure what the priority of #13481 will be (and it will likely need the same fix, afaict). Do you want to take a stab at fixing this, or should I? Would likely be after Thanksgiving on my end. |
|
It will also likely be after Thanksgiving on my end. If you remain assigned I'll assume you're on it since in-progress is now gone. Otheriwse, just remove your assignment and then when you or I have time we can re-self-assign. |
As described in #13276 and #11626, a race condition can occur between releasing exclusive access to the Console and the dynamic UI shutting down. In #13276, the issue was triaged to a task accepting output without confirming that the UI was still valid, and then dropping it if the UI was no longer valid. To fix this, replace the extra task and channel (which could not be used "transactionally" to both accept stderr and validate that the UI was still valid), with an anonymous `Mutex` directly around the stderr destination. Fixes #13276 and #11626. [ci skip-build-wheels]
|
@stuhood this appears to fix things, but it also appears to be the case that 2 fixes are in play and I only see one: namely, I never see evidence of a failur to upgrade the weak progress bar in order to log stderr - there is never the expected log::warn fallback / retry you'd expect in that case; so is there a reason you can see that the change would solve the timing in progress bar teardown directly? Or maybe have my odds at seeing this rare event just got alot worse? I tried ~20 times before your change and after getting 2/20 fail before, 0/20 after. The before was using the commit just before your change and the 2/20 was already subjectively much better than the OP where the failure rate was maybe 3/5. |
|
Thanks, you're right that we've fixed one out of two issues. Replied on #14093. |
As described in pantsbuild#13276 and pantsbuild#11626, a race condition can occur between releasing exclusive access to the Console and the dynamic UI shutting down. In pantsbuild#13276, the issue was triaged to a task accepting output without confirming that the UI was still valid, and then dropping it if the UI was no longer valid. To fix this, replace the extra task and channel (which could not be used "transactionally" to both accept stderr and validate that the UI was still valid), with an anonymous `Mutex` directly around the stderr destination. Fixes pantsbuild#13276 and pantsbuild#11626. [ci skip-build-wheels]
…4690) As described in #13276 and #11626, a race condition can occur between releasing exclusive access to the Console and the dynamic UI shutting down. In #13276, the issue was triaged to a task accepting output without confirming that the UI was still valid, and then dropping it if the UI was no longer valid. To fix this, replace the extra task and channel (which could not be used "transactionally" to both accept stderr and validate that the UI was still valid), with an anonymous `Mutex` directly around the stderr destination. Fixes #13276 and #11626. [ci skip-build-wheels]
On Pants main @ 6037e69 I encountered this failure with no information about why Flake8 failed:
I re-ran and found:
So the issue was
src/python/pants/engine/process.py:537:1: W293 blank line contains whitespacebut that was not reported on the 1st run. In the 1st run it's just reported that the flake8.pex was built10:48:11.36 [INFO] Completed: Building flake8.pex from 3rdparty/python/lockfiles/flake8.txt, but not what theCompleted: ...of that pex's execution was.The pantsd.log shows the following for this session:
The text was updated successfully, but these errors were encountered: