Retry for filesystem changes more quickly, indefinitely, and with logging #10139

stuhood · 2020-06-23T19:44:51Z

Problem

As described in #10081, there are a few different concerns around retrying nodes when the filesystem changes:

whether we have retried enough times
whether we've made it clear to the user that we're retrying
whether we retry immediately upon change, or only after something has completed

Solution

To address each of the above points, we retry:

indefinitely
with logging
immediately upon invalidation of nodes by:
- removing the Running::dirty flag, and moving a Running node to NotStarted to trigger invalidation
- "aborting"/dropping ongoing work for a canceled attempt using futures::Abortable

Additionally, improve the Display and user_facing_name implementations for Node to allow for better log messages from the Graph.

Result

A message like:

12:39:52.93 [INFO] Completed: Building requirements.pex
15:21:58.95 [INFO] Filesystem changed during run: retrying `Test` in 500ms...
15:21:58.96 [INFO] Filesystem changed during run: retrying `@rule coordinator_of_tests((OptionsBootstrapper(args=['--no-v1', '--v2', '--no-process-execution-use-local-cache', 'test', 'tests/python/pants_test/util:'], env={'PANTS_DEV': '1'}, config=ChainedConfig(['/Users/stuhood/src/pants/pants.toml', '/Users/stuhood/.pants.rc'])), WrappedTestFieldSet(field_set=PythonTestFieldSet(address=Address(tests/python/pants_test/util, argutil), origin=SiblingAddresses(directory='tests/python/pants_test/util'), sources=<class 'pants.backend.python.target_types.PythonTestsSources'>(alias='sources', sanitized_raw_value=('test_argutil.py',), default=('test_*.py', '*_test.py', 'tests.py', 'conftest.py')), timeout=pants.backend.python.target_types.PythonTestsTimeout(alias='timeout', value=None, default=None), coverage=pants.backend.python.target_types.PythonCoverage(alias='coverage', value=('pants.util.argutil',), default=None)))))` in 500ms...
12:39:57.17 [INFO] Completed: Building requirements.pex with 1 requirement: dataclasses==0.6

...is rendered immediately when a file that a test depends on is invalidated.

Fixes #10081.

stuhood · 2020-06-23T20:12:40Z

The commits are useful to review independently, but the first two overlap a little bit. Thanks!

Eric-Arellano

Awesome!

Eric-Arellano · 2020-06-23T21:58:34Z

src/rust/engine/graph/src/tests.rs


-  let delay_for_root = Duration::from_millis(2000);
+  let delay_for_mid = Duration::from_millis(2000);


The middle of three.

Oh, maybe say middle. I spent a solid minute trying to figure out what mid could be an acronym for.

Eric-Arellano · 2020-06-23T22:01:21Z

tests/python/pants_test/pantsd/test_pantsd_integration.py

@@ -22,6 +22,7 @@
 def launch_file_toucher(f):
    """Launch a loop to touch the given file, and return a function to call to stop and join it."""
    if not os.path.isfile(f):
+


Not sure if this was intentional.

Guess which file I was smoke testing with, heh.

Eric-Arellano · 2020-06-23T22:02:16Z

src/rust/engine/graph/src/lib.rs

+              inner.unsafe_entry_for_id(entry_id).node().clone()
+            };
+            info!(
+              "Filesystem changed during run: retrying `{}` in {:?}...",


To reduce the risk of truncation:

Suggested change

"Filesystem changed during run: retrying `{}` in {:?}...",

"Filesystem changed: retrying `{}` in {:?}...",

I'm wondering if it would be worth rewording so that the time appears before the node description also. I'm concerned some nodes may be really long.

I think it's important to mention "during run", because as you said, this is independent from --loop... also, I want to send the signal that this is tied specifically to the thing that is re-running (it is: if a file unrelated to the thing that was running is changed, you won't see this).

Regarding truncation: these messages are not truncated. Perhaps they should be, but.

Okay, fair. Thanks

Eric-Arellano · 2020-06-23T22:05:00Z

src/rust/engine/src/nodes.rs

      NodeKey::MultiPlatformExecuteProcess(mp_epr) => mp_epr.0.user_facing_name(),
      NodeKey::DigestFile(DigestFile(File { path, .. })) => {
        Some(format!("Fingerprinting: {}", path.display()))
      }
-      NodeKey::DownloadedFile(..) => None,
+      NodeKey::DownloadedFile(ref d) => Some(format!("Downloading: {}", d.0)),


Thanks for improving these. They look great.

Eric-Arellano · 2020-06-23T22:05:33Z

src/rust/engine/src/nodes.rs

@@ -1040,14 +1040,16 @@ impl NodeKey {
  fn user_facing_name(&self) -> Option<String> {
    match self {
      NodeKey::Task(ref task) => task.task.display_info.desc.as_ref().map(|s| s.to_owned()),
-      NodeKey::Snapshot(_) => Some(format!("{}", self)),
+      NodeKey::Snapshot(ref s) => Some(format!("Snapshotting: {}", s.0)),


Snapshotting might not mean much to non-Pants devs. I can't think of a better name though. More something to consider medium term.

The content of the PathGlobs object should help... it reads as Snapshotting: PathGlobs(globs=['thing.py'], ..)

Speaking of which, the PathGlobs help is very verbose. In a followup, I think it'd be great if it only showed PathGlobs(['foo', '!ignore']) and not the other fields.

stuhood · 2020-06-23T22:27:11Z

Note: unfortunately, rendering just the Node::user_facing_name as the Display of a Node ran afoul of #7907, by breaking the cycle detection tests. They (rightly) confirm that we actually render the name of the cyclic target, which @rule(desc=..) cannot do currently. See the updated example in the description.

# Delete this line to force CI to run the JVM tests. [ci skip-jvm-tests]

[ci skip-jvm-tests]

…ying. # Delete this line to force CI to run the JVM tests. [ci skip-jvm-tests]

[ci skip-jvm-tests]

# Delete this line to force CI to run the JVM tests. [ci skip-jvm-tests]

…0139.

… post pantsbuild#10139.

…ging (pantsbuild#10139) As described in pantsbuild#10081, there are a few different concerns around retrying nodes when the filesystem changes: 1. whether we have retried enough times 2. whether we've made it clear to the user that we're retrying 3. whether we retry immediately upon change, or only after something has completed To address each of the above points, we retry: 1. indefinitely 2. with logging 3. immediately upon invalidation of nodes by: * removing the `Running::dirty` flag, and moving a `Running` node to `NotStarted` to trigger invalidation * "aborting"/dropping ongoing work for a canceled attempt using `futures::Abortable` Additionally, improve the `Display` and `user_facing_name` implementations for `Node` to allow for better log messages from the `Graph`. A message like: ``` 12:39:52.93 [INFO] Completed: Building requirements.pex 15:21:58.95 [INFO] Filesystem changed during run: retrying `Test` in 500ms... 15:21:58.96 [INFO] Filesystem changed during run: retrying `@rule coordinator_of_tests((OptionsBootstrapper(args=['--no-v1', '--v2', '--no-process-execution-use-local-cache', 'test', 'tests/python/pants_test/util:'], env={'PANTS_DEV': '1'}, config=ChainedConfig(['/Users/stuhood/src/pants/pants.toml', '/Users/stuhood/.pants.rc'])), WrappedTestFieldSet(field_set=PythonTestFieldSet(address=Address(tests/python/pants_test/util, argutil), origin=SiblingAddresses(directory='tests/python/pants_test/util'), sources=<class 'pants.backend.python.target_types.PythonTestsSources'>(alias='sources', sanitized_raw_value=('test_argutil.py',), default=('test_*.py', '*_test.py', 'tests.py', 'conftest.py')), timeout=pants.backend.python.target_types.PythonTestsTimeout(alias='timeout', value=None, default=None), coverage=pants.backend.python.target_types.PythonCoverage(alias='coverage', value=('pants.util.argutil',), default=None)))))` in 500ms... 12:39:57.17 [INFO] Completed: Building requirements.pex with 1 requirement: dataclasses==0.6 ``` ...is rendered immediately when a file that a test depends on is invalidated. Fixes pantsbuild#10081.

stuhood requested review from hrfuller, Eric-Arellano and gshuflin June 23, 2020 20:11

stuhood marked this pull request as ready for review June 23, 2020 20:12

Eric-Arellano approved these changes Jun 23, 2020

View reviewed changes

stuhood force-pushed the stuhood/faster-indefinite-retry branch from 948257e to 495299c Compare June 23, 2020 22:22

Eric-Arellano approved these changes Jun 23, 2020

View reviewed changes

stuhood added 5 commits June 23, 2020 17:57

Immediately cancel Running nodes when dirtied.

8624c61

# Delete this line to force CI to run the JVM tests. [ci skip-jvm-tests]

Abort nodes when cleared/dirtied while running.

9f95431

[ci skip-jvm-tests]

Infinitely retry nodes, but log each retry and then amount we're dela…

f2aa667

…ying. # Delete this line to force CI to run the JVM tests. [ci skip-jvm-tests]

Improve Display and user_facing_name for Node.

9a491cd

[ci skip-jvm-tests]

Review feedback

8fe1bae

# Delete this line to force CI to run the JVM tests. [ci skip-jvm-tests]

stuhood force-pushed the stuhood/faster-indefinite-retry branch from 495299c to 8fe1bae Compare June 24, 2020 00:57

stuhood merged commit 5a059c3 into pantsbuild:master Jun 24, 2020

stuhood deleted the stuhood/faster-indefinite-retry branch June 24, 2020 02:21

stuhood added a commit to stuhood/pants that referenced this pull request Jul 1, 2020

WIP: Fixup docstrings regarding dirty running nodes post pantsbuild#1…

c7d1711

…0139.

stuhood added a commit to stuhood/pants that referenced this pull request Jul 1, 2020

Remove stale docstrings and lock acquisitions re: dirty running nodes…

55009ca

… post pantsbuild#10139.

stuhood added a commit to stuhood/pants that referenced this pull request Jul 9, 2020

Remove stale docstrings and lock acquisitions re: dirty running nodes…

6e2bbc3

… post pantsbuild#10139.

stuhood added a commit to stuhood/pants that referenced this pull request Jul 16, 2020

Remove stale docstrings and lock acquisitions re: dirty running nodes…

b44fc97

… post pantsbuild#10139.

stuhood mentioned this pull request Aug 18, 2020

Workunits not completed when nodes canceled due to filesystem changes #10650

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Retry for filesystem changes more quickly, indefinitely, and with logging #10139

Retry for filesystem changes more quickly, indefinitely, and with logging #10139

stuhood commented Jun 23, 2020 •

edited

stuhood commented Jun 23, 2020 •

edited

Eric-Arellano left a comment

Eric-Arellano Jun 23, 2020

stuhood Jun 23, 2020

Eric-Arellano Jun 23, 2020

Eric-Arellano Jun 23, 2020

stuhood Jun 23, 2020

Eric-Arellano Jun 23, 2020

Eric-Arellano Jun 23, 2020

stuhood Jun 23, 2020

Eric-Arellano Jun 23, 2020

Eric-Arellano Jun 23, 2020

Eric-Arellano Jun 23, 2020

stuhood Jun 23, 2020

Eric-Arellano Jun 23, 2020

stuhood commented Jun 23, 2020 •

edited


		let delay_for_root = Duration::from_millis(2000);
		let delay_for_mid = Duration::from_millis(2000);

	"Filesystem changed during run: retrying `{}` in {:?}...",
	"Filesystem changed: retrying `{}` in {:?}...",

Retry for filesystem changes more quickly, indefinitely, and with logging #10139

Retry for filesystem changes more quickly, indefinitely, and with logging #10139

Conversation

stuhood commented Jun 23, 2020 • edited

Problem

Solution

Result

stuhood commented Jun 23, 2020 • edited

Eric-Arellano left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

stuhood commented Jun 23, 2020 • edited

stuhood commented Jun 23, 2020 •

edited

stuhood commented Jun 23, 2020 •

edited

stuhood commented Jun 23, 2020 •

edited