@hundreds-father-404: re:

Starting

messages for test processes

I think that the

EngineAwareParameterType

might work. Set it on the

PythonTestFieldSet

and we can’t rely on the

@rule

that produces that workunit to tell us when it has started, for two reasons: 1) it’s not under the process lock so it doesn’t know that it has actually started, 2) the

@rule

won’t know its own identity when it starts

the @rule won’t know its own identity when it starts

Oh, yeah, I think

EngineAwareParameter

only impacts some things like stacktraces, but not the “Starting” message

the Params probably should be usable in the workunit description via templating, yea. but still have to worry about (1)

This is probably a design smell, but might we want something like?

starting_level=<http://LogLevel.INFO|LogLevel.INFO>,
ending_level=LogLevel.DEBUG,

The

Process

constructor can take

level

or

starting_level

and

ending_level

. If you only do

level

, then it will automatically set the other two.

the bounded commander runner lock is basically in the optimal spot right now, (un)fortunately. if we moved it “higher” so that preparatory rules didn’t even start running until there were slots available, we’d potential block preparatory work from starting, and then only run it under the lock

@hundreds-father-404 we already have a mechanism for altering the level of a workunit while it is running

@hundreds-breakfast-49010: yes, but see the other context in the thread

what's the problem we're trying to solve with

Starting

messages?

did we remove starting messages somehow?

that’s described at the top of the thread

but this is a sticky problem, because only the Process’s workunit(s) know when it is actually running

I think that keeping the log message on the

Process

is correct. The

Process

also has access to the information it needs: the file/target it’s running on Imo, it seems like this is about a need to have the

Process

be INFO at its start, but DEBUG at completion

and the rules above it are also. they only lift their levels as they complete

this sounds like we're trying to use the concept of a workunit's level for something it wasn't intended for

@hundreds-father-404: i think that i agree. i wonder if pushing

EngineAwareReturnType

down far enough would allow us to actually configure completion info for the

Process

?

what information/logic is that? I'm still not sure exactly what change happened

would allow us to actually configure completion info for the Process ?

I don’t think we want this. Right now, streaming of test results is done in

test.py

. When you’re adding a new test implementation, you’ll get it working correctly no matter what. That’s important

we made

Process

workunits DEBUG instead of INFO, and that got rid of the "Starting" message for

Process

workunits?

@hundreds-breakfast-49010: test completion is logged via https://github.com/pantsbuild/pants/blob/f90b9826f064af61556c92e4bbc573861ee0b9fe/src/python/pants/core/goals/test.py#L75 right now

why were they moved to Debug?

To clarify, the reason we moved the

Process

to Debug is that it’s really noisy for us to say

Completed process

and then immediately after stream the result via

test.py

, which uses

EngineAwareReturnType

why's that? that seems like two conceptually-separate messages

@hundreds-father-404: but also, only if it failed, right?

“pants finished executing some process” and “here is the result of a test”

From a user perspective, the implementation detail would be leaking imo. There isn’t any new informtation gained by saying “completed process” and then immediately after “here’s the process output” Taking a step back from the current mechanisms, the user cares about this when

--no-dynamic-ui

is set: * When the test run starts. * When the test run finishes, and what its status + output is, where output depends on the

--test-show-output

option * Not too noisy.

* When the test run finishes, and what its status + output is, where output depends on the 

--test-show-output

 option

yes, but the default is “only on failure”, in which case you get a ton of output, and the extra line is a non-issue i think.

I'm not sure the process bit of it is an implementation detail. users care about when the test run starts because they care about when the test process actually runs

which means they should care about when it stops running too, regardless of outcome

Yes, they do care about this. Strong agreement. But they already get that via

142421.68 [INFO] Completed: Run tests - src/python/pants/util/strutil_test.py:tests succeeded.

It would be confusing to get that and a message saying “Completed: Run tests for src/python/pants/util/strutil_tests.py:tests`. Why are you getting both? They say basically the same thing, but one is less helpful.

the second one is the workunit for the

@rule

right?

so: how do we push down richer information or logic to the Process

so: how do we push down richer information or logic to the Process

Which I don’t think we want from a Plugin API perspective https://pantsbuild.slack.com/archives/C0D7TNJHL/p1601327586055900?thread_ts=1601326361.048700&cid=C0D7TNJHL Perhaps there is a way to make it more automatic though

@hundreds-father-404: so, ignoring the “tests” case for now (remains an open question… i’ll file a ticket), it looks like a lot of processes got moved to Debug at various times

I personally disagree. For example, Protobuf gets run dozens of times and I think it would be really noisy to get every single run. I do think though that the desired behavior changes between CI vs. locally. Locally, where you have a smaller terminal, I’m personally extra sensitive to noisy tools. You also already have the dynamic UI to show what’s going on. But in CI, it is more helpful to get a tasteful amount of logging

For example, Protobuf gets run dozens of times and I think it would be really noisy to get every single run.

only if the files have changed

and that should only be your first run locally

I do think that we need to consider your very first run for Pants, though. Are you going to get 50 lines of logs that you have to parse through?

yes, and then (almost) never again.

Yeah I think my takeaway from this convo is that

--no-dynamic-ui

is more important than I thought. We don’t only want it to toggle the “Starting” message. For many workunits, we also want it to toggle the “Completed” message

yea, i’m unclear on what the strategy for

--no-dynamic-ui

will be (tweaking level vs finding a useful periodic thing that we can dump), but i think that i agree.

The strawman design that’s been floating in my head is to add a new type that allows you to customize how things appear in each context:

{dynamic ui x no_dynamic_ui} x {starting_level x ending_level}

The constructor would be ergonomic, such that you can only set

level=LogLevel.DEBUG

for example and it will do that for everything. Or, you can get fancier if you want tight control, like we want with

test

. What’s holding me back is that logging is already a little tricky to reason about. And it’s really easy for someone to accidentally change something and break things without realizing. This adds lots of permutations But then on the other side of my internal debate, I think it’s crucial we have an excellent UX for every edge case. Even if our code has to be complex to support it, I think that it’s worth it so that

--dynamic-ui

isn’t too noisy, but also

--no-dynamic-ui

is informative enough.

i’m hoping that there is something clearly useful that we can log in the

--no-dynamic-ui

case that aligns the on/off case so that individual nodes don’t have to worry about that.