https://pantsbuild.org/ logo
Powered by
h

hundreds-father-404

06/01/2020, 8:38 PM
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

witty-crayon-22786

06/01/2020, 8:42 PM
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

hundreds-father-404

06/01/2020, 8:45 PM
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

witty-crayon-22786

06/01/2020, 8:45 PM
…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

hundreds-father-404

06/01/2020, 8:46 PM
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

witty-crayon-22786

06/01/2020, 8:46 PM
@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

hundreds-father-404

06/01/2020, 8:46 PM
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

witty-crayon-22786

06/01/2020, 8:46 PM
(…of stdio for failing workunits)
right, that’s what’s been proposed.
h

hundreds-father-404

06/01/2020, 8:48 PM
Okay, glad to hear. Are we aiming to get that in by 1.30?
w

witty-crayon-22786

06/01/2020, 8:48 PM
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

hundreds-breakfast-49010

06/01/2020, 8:49 PM
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

hundreds-father-404

06/01/2020, 8:52 PM
Okay, cool. Thank you both 🙂
w

witty-crayon-22786

06/01/2020, 8:53 PM
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

hundreds-father-404

06/01/2020, 8:54 PM
Will it be possible to stream the test results without prefixing them with 
[INFO]
?
w

witty-crayon-22786

06/01/2020, 8:55 PM
if we want to switch to using color to differentiate the levels, then maybe… test failures would be 
[ERROR]
, for example
h

hundreds-father-404

06/01/2020, 8:56 PM
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

witty-crayon-22786

06/01/2020, 8:56 PM
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-breakfast-49010

06/01/2020, 9:01 PM
@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

hundreds-father-404

06/01/2020, 9:02 PM
Exactly. That’s my concern
h

hundreds-breakfast-49010

06/01/2020, 9:02 PM
@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

hundreds-father-404

06/01/2020, 9:02 PM
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

witty-crayon-22786

06/01/2020, 9:03 PM
We can totally overhaul the logging format .. it's completely configurable.
❤️ 1
h

hundreds-breakfast-49010

06/01/2020, 9:03 PM
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

witty-crayon-22786

06/01/2020, 9:04 PM
@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

fast-nail-55400

06/01/2020, 9:08 PM
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

witty-crayon-22786

06/01/2020, 9:17 PM
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

hundreds-breakfast-49010

06/01/2020, 9:20 PM
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

fast-nail-55400

06/01/2020, 9:25 PM
@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

witty-crayon-22786

06/01/2020, 9:25 PM
@fast-nail-55400: only if --no-dynamic-ui
Which will be the case in CI, where we don't have a tty
f

fast-nail-55400

06/01/2020, 9:26 PM
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

witty-crayon-22786

06/01/2020, 9:27 PM
This is on master: the logging you're looking at is gone on master
f

fast-nail-55400

06/01/2020, 9:27 PM
ah
w

witty-crayon-22786

06/01/2020, 9:27 PM
And when it is present it's more accurate =)
(ish: see the top of this thread: more tuning to do)
Powered by