https://pantsbuild.org/ logo
Join Slack
Powered by
Hey, with the recent logging of workunits change, ...
# development
h
Hey, with the recent logging of workunits change, I pitched to Greg that I think we definitely want the feature, but that we want it disabled by default. The typical Pants run is small, like “format these 2 files” or “run a single test”. Logging makes those runs feel heavier and noisier than they really are; Pants is no longer an elegant wrapper around Pytest and Black. There are times where the logging is helpful, like CI or running test over 100 targets. Or, when the dynamic UI is disabled. But for your Typical Pants Run™, I don’t think we want it on.
This is a lot of noise:
Copy code
▶ ./v2 --changed-since=HEAD fmt
20:30:55:734 [INFO] Completed: Run Black on 2 targets: src/python/pants/backend/python/dependency_inference, src/python/pants/backend/python/dependency_inference:tests.
20:30:55:736 [INFO] Completed: Format using Black
20:30:56:417 [INFO] Completed: Run Docformatter on 2 targets: src/python/pants/backend/python/dependency_inference, src/python/pants/backend/python/dependency_inference:tests.
20:30:56:418 [INFO] Completed: Format Python docstrings with docformatter
20:30:57:160 [INFO] Completed: Run isort on 2 targets: src/python/pants/backend/python/dependency_inference, src/python/pants/backend/python/dependency_inference:tests.
20:30:57:162 [INFO] Completed: Format using isort
𐄂 Black made changes.
reformatted src/python/pants/backend/python/dependency_inference/import_parser_test.py
All done! :sparkles: :cake: :sparkles:
1 file reformatted, 2 files left unchanged.


✓ Docformatter made no changes.

𐄂 isort made changes.
Fixing src/python/pants/backend/python/dependency_inference/import_parser.py

20:30:57:174 [INFO] Completed: `fmt` goal
I know that we can tune it, but I don’t think any of these log messages are particularly informative. The goal only took me 3 seconds to run, and now I have ~30 lines to read to make sense of the results.
w
most of those are named rules rather than processes. so fixing that part would halve it.
i do think that we want this enabled by default, but i think that a lot more stuff should be at debug.
if you move these to debug:
Copy code
20:30:55:736 [INFO] Completed: Format using Black
20:30:56:418 [INFO] Completed: Format Python docstrings with docformatter
20:30:57:162 [INFO] Completed: Format using isort
20:30:57:174 [INFO] Completed: `fmt` goal
(…which we should do anyway because they don’t add anything over the processes underneath them)
h
so fixing that part would halve it.
Agreed, but even fixing this, for this run that only takes 3 seconds, I don’t think any of the log messages are pulling their weight. And I suspect that’ll be the case for most local runs It would be neat if I could say 
--verbose
to turn it on. Or if 
--no-dynamic-ui
turned it on, perhaps.
w
…you get:
Copy code
▶ ./v2 --changed-since=HEAD fmt
20:30:55:734 [INFO] Completed: Run Black on 2 targets: src/python/pants/backend/python/dependency_inference, src/python/pants/backend/python/dependency_inference:tests.
20:30:56:417 [INFO] Completed: Run Docformatter on 2 targets: src/python/pants/backend/python/dependency_inference, src/python/pants/backend/python/dependency_inference:tests.
20:30:57:160 [INFO] Completed: Run isort on 2 targets: src/python/pants/backend/python/dependency_inference, src/python/pants/backend/python/dependency_inference:tests.
𐄂 Black made changes.
reformatted src/python/pants/backend/python/dependency_inference/import_parser_test.py
All done! :sparkles: :cake: :sparkles:
1 file reformatted, 2 files left unchanged.
✓ Docformatter made no changes.
𐄂 isort made changes.
Fixing src/python/pants/backend/python/dependency_inference/import_parser.py
ie three lines for three processes.
but the other reason why we shouldn’t turn this off, is that it’s looking like this is how we should provide “streaming” completion of results
h
Better, but still noisy. The dynamic UI just showed me that the process completed. And in 1 second, I’m going to get that exact same information expressed in a different way with the final output
w
@hundreds-father-404: the rendering that we do in the consule rule at the end should mostly go away in favor of streaming workunit completion
👍 1
h
The ideal here would be streaming the results real-time. Don’t log that “Run black on 2 targets” finished. Just give me back that result real time
w
(…of stdio for failing workunits)
right, that’s what’s been proposed.
h
Okay, glad to hear. Are we aiming to get that in by 1.30?
w
greg is working on attaching stdio to workunits right now in https://github.com/pantsbuild/pants/pull/9906
Are we aiming to get that in by 1.30
i can’t speak for @hundreds-breakfast-49010 or @happy-kitchen-89482, but if that’s “about three weeks”, then it seems reasonable to me
h
yeah I'm pretty close to being done with the stdio/stderr on workunits work, and I'm working on it literally right now
so that should be ready for a review hopefully by the end of the day today
h
Okay, cool. Thank you both 🙂
w
for 
lint
and 
test
(as discussed on the doc you had about this), i think that the completion and logs will be rendered in a streaming fashion by workunits, and one line per runner/target with pass/fail will be rendered by the console rule
h
Will it be possible to stream the test results without prefixing them with 
[INFO]
?
w
if we want to switch to using color to differentiate the levels, then maybe… test failures would be 
[ERROR]
, for example
h
Okay, not a huge deal. But a fundamental level, it will always be logging, right? Because only the goal rule can have exclusive access to the console?
w
right.
i think so.
i don’t really see a future where we have “zero” logging… there will always be some. and given that, it needs to mix well with other things being streamed.
gotta head to an appointment. back at 3:30
👋 1
h
@hundreds-father-404 yeah this is something I've been wondering about in light of these changes
currently we are using the logging framework to print those workunit lines
and the logging formatting puts that timestamp, the level in brackets, and then the message
and this is fine for actual logs, but I feel like what we're doing with workunits is now "actual program output" and not just informational logs
h
Exactly. That’s my concern
h
@fast-nail-55400 this is possibly relevant for the sorts of logging you would like to do
it's easy enough to change the log formatting to not print [INFO] or whatever. but then we need to decide, what is an actual log that we do want to print with that formatting, and what's non-log ordinary pants output?
h
Maybe we could introduce a kwarg to 
<http://log.info|log.info>
that allows us to disable that prefix info? I think we still won’t be able to use the console to output, but if we could turn off the formatting in some situtations and keep it for others, problem solved
w
We can totally overhaul the logging format .. it's completely configurable.
❤️ 1
h
possibly. and what tom was interested in doing was switching to the 
slog
rust crate so he could do structured logging in rust
which might also give us that configurability
in rust
so, does that mean that we want to mix non-log-formatted messages from workunits above the swim lanes, intermixed with actual log-formatted messages from log strings?
w
@hundreds-father-404: disabling the prefix would look strange next to other things with it enabled, imo. Would be better to make it more compact in general
But also, keep in mind the multi line won't have the prefix on trailing lines.
f
I’m interested in debug/trace level stuff for the structured logging. My thoughts on regular output, which probably overlaps heavily with what you all have already considered. I would refine the notion of what we are trying to communicate to the user. In my view, we are communicating that we broke apart the high-level request (test these targets) into discrete tasks to perform and that we are making progress on completing those units of work. Above the swim-lane should be the names of completed work units as they complete, the swim lane should start with an “aggregate line” with the X out of Y tasks remaining and total time (e.g. like Bazel) and then the swim lanes. Any other logs intended to be viewed by a Pants developer should be squelched in the normal case.
if you look at the Docker BuildKit mode of 
docker build
, I like that output. If there are 14 steps, it will print all 14 and then run through them and colorize them as it executes them.
the “Starting tests” lines are less useful in my mind then just printing the completions and a summary of success/failure, bonus points for colorizing it
an aggregate line above the swim-lanes will let a user know work is coming up (as they watch completed task count increase)
thus no need to tell them something started
which gets confusing since the completion lines are not grouped together with the start line any way
also can we not show idle swim-lanes?
👍 1
just show swim-lanes for tasks actually executing
👍 1
(again I find Bazel gets this right)
if I’m running one test target and have 8 cores so 7 empty swim lanes doesn’t convey much information to me
👍 1
I do like the emoji on the swim lane though
w
We don't render things starting when the UI is enabled: only completing
In general, workunits are already structured logging
Re: idle swim lanes: yea, we should be choosing that number dynamically, because the hardcoded size right now isn't accurate in the context of remoting, and it's not really possible for it to be without knowing the capacity of your cluster from the client.
👍 1
h
incidentally I updated https://github.com/pantsbuild/pants/pull/9927 which is possibly relevant to this discussion
that's the display timestamps in localtime rather than UTC PR
@fast-nail-55400 the number of swim lanes is right now hard coded ot be the same as the number of cpu cores on your local machine, which I don't like. the number of workunits happening simultaneously isn't obviously related to the number of cpu cores, and even less so in the context of remoting
that's something we should definitely change
f
@witty-crayon-22786: we do render starting:
Copy code
vagrant@vagrant:/src/toolchain$ ./tc test src/python/toolchain/infosite::
21:24:51:970 [INFO] Starting tests: src/python/toolchain/infosite:tests
⠋ 14.03s Building requirements.pex with 24 requirements: Django==3.0.6, ansicolors==1.1.8, beautifulsoup4==4.
“Starting tests”
w
@fast-nail-55400: only if --no-dynamic-ui
Which will be the case in CI, where we don't have a tty
f
swim-lanes is dynamic UI, correct? and the command I ran showed swim lanes (you can see the swim-lane emoji in what I pasted)
w
This is on master: the logging you're looking at is gone on master
f
ah
w
And when it is present it's more accurate =)
(ish: see the top of this thread: more tuning to do)
Open in Slack
PreviousNext
Powered by