EngineAware rules should possibly log when starting when --no-dynamic-ui

[Eric-Arellano]

We do this currently with Process, but not with rules that return an EngineAware type.

▶ ./pants test src/python/pants/core/goals/{fmt,test}_test.py --no-dynamic-ui
09:35:11 [INFO] Starting: Run Pytest for src/python/pants/core/goals/test_test.py
09:35:11 [INFO] Starting: Run Pytest for src/python/pants/core/goals/fmt_test.py
09:35:15 [INFO] Completed: Run Pytest for src/python/pants/core/goals/fmt_test.py
09:35:15 [INFO] Completed: Run Pytest - tests succeeded: src/python/pants/core/goals/fmt_test.py
09:35:15 [INFO] Completed: Run Pytest for src/python/pants/core/goals/test_test.py
09:35:15 [INFO] Completed: Run Pytest - tests succeeded: src/python/pants/core/goals/test_test.py

We say "Completed: Run Pytest - tests succeeded" but do not say "Starting Run Pytest".

Note that this requires the below diff:

diff --git a/src/python/pants/core/goals/test.py b/src/python/pants/core/goals/test.py
index 057d6503c..7c1feb47e 100644
--- a/src/python/pants/core/goals/test.py
+++ b/src/python/pants/core/goals/test.py
@@ -88,7 +88,7 @@ class TestResult(EngineAware):
     def level(self):
         if self.status == Status.FAILURE:
             return LogLevel.ERROR
-        return None
+        return LogLevel.INFO
 
     def message(self):
         result = "succeeded" if self.status == Status.SUCCESS else "failed"

It's not clear what the log message should be, though. We won't yet have access to the return type, e.g. the TestResult, so it will be difficult to output any dynamic information. It's important that we would be able to say "Starting test for address :foo". This may require introducing a new mechanism.

[stuhood]

We do this currently with Process, but not with rules that return an EngineAware type.

IIRC, whether something is logged as it starts is dependent on its level. You can set the level of a @rule in the decorator:

@rule(level=LogLevel.INFO)

...would do it.

[Eric-Arellano]

Ah, that would solve half the problem. But the log wouldn't be very helpful because it would be missing any dynamic information. We'd get a bunch of "Run Pytest", which looks repetitive.

I can't find the issue about allowing the @rule annotation to access dynamic info? I think we'd need to solve that to completely solve this problem.

[stuhood]

#7907 is the dynamic info issue.

[stuhood]

@Eric-Arellano : Is this still desirable?

[Eric-Arellano]

I think it could be useful in CI to debug where hangs are happening. You can see which tests have have a started message but are missing a finished message

Re how to make the starting message useful, I think the solution is to use EngineAwareParameter to make the message dynamic

[stuhood]

We've begun including EngineAwareParameter info in a few places, yea. The challenge with embedding it in @rule(desc="...") is that it's challenging to know what a @rule's parameters will be. But we could have a single generic placeholder that @rules could use, without knowing what they were going to get?

[Eric-Arellano]

Or should we do something like unconditionally add - {param} to the end? Iirc we do that elsewhere. (Not sure how that would work if you have >1 param)

I think I much prefer a template language though, like desc="Start pytest for {field_set}", where the name is the name of the argument to the rule.

And then EngineAwareReturnType can override the desc, as before.

[stuhood]

I think I much prefer a template language though, like desc="Start pytest for {field_set}", where the name is the name of the argument to the rule.

The Node starts running before the arguments to the @rule have been determined: they're the first thing requested in the Node body.

pants/src/rust/engine/src/nodes.rs

Lines 1171 to 1191 in 5798377

	let params = self.params;
	let deps = {
	// While waiting for dependencies, mark ourselves blocking.
	let _blocking_token = workunit.blocking();
	let edges = &context
	.core
	.rule_graph
	.edges_for_inner(&self.entry)
	.expect("edges for task exist.");
	future::try_join_all(
	self
	.task
	.clause
	.into_iter()
	.map(|type_id| {
	Select::new_from_edges(params.clone(), type_id, edges).run(context.clone())
	})
	.collect::<Vec<_>>(),
	)
	.await?
	};

That will change a bit in #11269, but if anything it will go further in the current direction: we won't even create the Node until all of its arguments are ready.

[Eric-Arellano]

Okay, so sounds like a non-starter to include EngineAwareParamater in the Start message, right? If so, then we should definitely close this issue.

It'd be great if we could make it dynamic not just for this issue (--no-dynamic-ui), but also for --dynamic-ui. For example, we had a user you and I were helping this week with slow performance and it wasn't clear in setup pytest which target it was for - the process hadn't run yet with the dynamic info.

[stuhood]

Okay, so sounds like a non-starter to include EngineAwareParamater in the Start message, right? If so, then we should definitely close this issue.

No: we could still include the params right now. But if we'd rather wait until #11269, we could actually template in the arguments.

Although I said above "moves further in the current direction", the situation currently is that we indicate that a @rule has started even while its input arguments are being computed. I've only pondered how the graph will change after #11269, but we will essentially only blame a @rule for things that it awaits, and everything else would get blamed to the caller. That might actually be better from the perspective of understanding where time is being spent... unclear.

But for the purposes of this ticket, I suppose that #11269 will be a net benefit... and so maybe it makes sense to wait for it, and then implement templating.

[stuhood]

Or should we do something like unconditionally add - {param} to the end? Iirc we do that elsewhere. (Not sure how that would work if you have >1 param)

So: this is definitely a thing that we can do if we want to. Sorry that I missed this comment earlier.

The experience would likely be fairly good, assuming that EngineAwareParameter is used on the most relevant types, and avoided for others.

[Eric-Arellano]

cool i think it would be excellent polish! make the dynamic UI more useful and less like things are duplicating

[stuhood]

FWIW: Doing this would involve editing this bit of code to append the EngineAwareParameter::debug_hint of any engine_aware_params to the user_facing_name:

pants/src/rust/engine/src/nodes.rs

Lines 1393 to 1400 in 902d3ac

	desc = self.user_facing_name(),
	user_metadata = {
	let gil = Python::acquire_gil();
	let py = gil.python();
	Self::engine_aware_params(context.clone(), py, &params)
	.flat_map(|val| EngineAwareParameter::metadata((*val).as_ref(py)))
	.collect()
	},

It's a bit tricky due to the macro though, because the computation of those fields is lazy, and only happens if the workunit is actually enabled. Keeping it lazy is probably the highest priority, so probably easiest to just call Self::engine_aware_params inside of user_facing_name.

[stuhood]

#15769 sketches this for one use case, and it seemingly works really well.

[stuhood]

#17119 included EngineAwareParameters in @rule workunit descriptions in all cases, so some of the discussion on here is now stale.

But one thing that is unfortunately not stale, and is probably reason-enough to close this is that when the @rule code starts is not actually useful: all of the test-running @rules will start ~immediately, since there is no concurrency bound on them. You'd have to log the beginning of the actual underlying Process instead, which we currently have marked Debug, in favor of the logging from the @rule.