[rush] Rush prints too much preamble on rush build

elliot-nelson commented 1 year ago

Summary

Today, after running rush build, I see 24 lines of output before an actual build operation starts.

❯ rush build --to-except .
Found configuration in /Users/enelson/dev/acme/rush.json

Rush Multi-Project Build Tool 5.82.1 - https://rushjs.io
Node.js version is 16.15.0 (LTS)

Found configuration in /Users/enelson/dev/acme/rush.json

Trying to acquire lock for pnpm-6.7.1
Acquired lock for pnpm-6.7.1
Found pnpm version 6.7.1 in /Users/enelson/.rush/node-v16.15.0/pnpm-6.7.1

Symlinking "/Users/enelson/dev/acme/common/temp/pnpm-local"
  --> "/Users/enelson/.rush/node-v16.15.0/pnpm-6.7.1"
Acquiring lock for "common/autoinstallers/rush-plugins" folder...
Autoinstaller folder is already up to date

Starting "rush build"

Analyzing repo state... DONE (0.41 seconds)

Executing a maximum of 8 simultaneous processes...

==[ @acme/node-rig (build) ]=======================================[ 1 of 13 ]==
"@acme/node-rig (build)" did not define any work.

I think that there should be fewer lines of output for the general developer. This ticket covers some suggested change to the output logic to make that happen.

Details

I'm open to pushback on many of these, but in my opinion:

Developers don't need to know Found configuration in /Users/enelson/dev/acme/rush.json (especially not twice).
Developers don't need "Analyzing repo state".
The middle block (from "Trying to acquire lock" to "Autoinstaller folder") is because we have rush plugins for this monorepo. I think that these operations should be hidden unless you are running a small subset of operations (the update- and init-autoinstaller commands, basically).
The order of operations in the middle block also highlights a potential inefficiency... the goal is to check whether the autoinstaller folder is up to date, but in order to do that, we need to make sure we have the right version of pnpm; however, we are running this from inside a running rush command... maybe we can indicate that we know the right version of pnpm is already available, and can skip right to the up-to-date check).

These changes would result in 8 lines before a build operation is printed, which feels much more reasonable.

❯ rush build --to-except .

Rush Multi-Project Build Tool 5.82.1 - https://rushjs.io
Node.js version is 16.15.0 (LTS)

Starting "rush build"

Executing a maximum of 8 simultaneous processes...

==[ @acme/node-rig (build) ]=======================================[ 1 of 13 ]==
"@acme/node-rig (build)" did not define any work.

(The rest of the output doesn't need to be discarded; I think it can be piped to --verbose.)

Standard questions

Please answer these questions to help us investigate your issue more quickly:

Question	Answer
`@microsoft/rush` globally installed version?	5.82.1
`rushVersion` from rush.json?	5.82.1
`useWorkspaces` from rush.json?	yes
Operating system?	mac
Would you consider contributing a PR?	yes
Node.js version (`node -v`)?	16

iclanton commented 1 year ago

I definitely agree that too much gets printed before any "useful" logging information happens.

The only thing I disagree with removing from non-verbose output is "Analyzing repo state" because in a large repo that might look like Rush is frozen without running any build operations.

@elliot-nelson - It'd be great if you could put this together!

dmichon-msft commented 1 year ago

For reference, that "Analyzing repo state" section typically takes 2.2 seconds on my developer machine for the main repository I work in, which is a non-trivial amount of time.

The command doesn't know you've run rush install with the current asked for version of pnpm unless we have a state file to tell us that, and even then, we need to ensure we handle (even if just by throwing an intelligible error) if you just randomly go and delete the $HOME/.rush folder before running the command.

Frankly you don't normally need to know the version of Rush or Node, either, though it helps with bug reports.

FYI this already works, but isn't the default:

PS D:\rushstack\build-tests\heft-webpack5-everything-test> rush --quiet build --only .    
Analyzing repo state... DONE (0.48 seconds)

Executing a maximum of 7 simultaneous processes...

==[ heft-webpack5-everything-test (build) ]========================[ 1 of 1 ]==
"heft-webpack5-everything-test (build)" completed successfully in 6.68 seconds.

==[ SUCCESS: 1 operation ]=====================================================

These operations completed successfully:
  heft-webpack5-everything-test (build)    6.68 seconds

rush build (7.25 seconds)

The --quiet parameter can nonetheless be combined with --verbose:

rush --quiet build --only . --verbose
Analyzing repo state... DONE (0.45 seconds)

Selected 1 operation:
  heft-webpack5-everything-test (build)

Executing a maximum of 7 simultaneous processes...

==[ heft-webpack5-everything-test (build) ]========================[ 1 of 1 ]==

This project does not define the caching behavior of the "_phase:build" command, so caching has been disabled.
Invoking: heft build --clean
Using local Heft from D:\rushstack\build-tests\heft-webpack5-everything-test\node_modules\@rushstack\heft

Project build folder is "D:\rushstack\build-tests\heft-webpack5-everything-test"
Starting build
 ---- Clean started ---- 
[delete-globs] Deleted 0 files and 4 folders
 ---- Clean finished (20ms) ----
 ---- Pre-compile started ---- 
 ---- Pre-compile finished (0ms) ----
 ---- Compile started ----
[copy-static-assets] Copied 4 files and linked 0 files in 31ms
[typescript] Using TypeScript version 4.8.4
[eslint] Using ESLint version 8.7.0
[tslint] Using TSLint version 5.20.1
 ---- Compile finished (4446ms) ---- 
 ---- Bundle started ---- 
[webpack] Using Webpack version 5.68.0
Shutting down minifier worker pool
Module minification: 0 Deduped, 5 Processed
 ---- Bundle finished (1102ms) ---- 
 ---- Post-build started ----
 ---- Post-build finished (2ms) ---- 
-------------------- Finished (6.598s) --------------------
Project: heft-webpack5-everything-test@1.0.0
Heft version: 0.48.8
Node version: v14.20.0
"heft-webpack5-everything-test (build)" completed successfully in 6.76 seconds.

==[ SUCCESS: 1 operation ]=====================================================

These operations completed successfully:
  heft-webpack5-everything-test (build)    6.77 seconds

rush build (7.31 seconds)

Perhaps we could provide an environment variable that equates to the --quiet parameter?

Buri commented 1 year ago

Either environment variable or, preferably, a config option, so it can be set on repository level.

dbartholomae commented 1 year ago

I ran into this problem in practice today: I'm writing a GitHub action that uses rush list to identify which projects are touched by the PR. But if I invoke node ./common/scripts/install-run-rush.js list on CI, most of the output is the preamble which I need to manually remove before being able to programmatically parse the actual result.

dbartholomae commented 1 year ago

Happy to help with a PR for a quiet parameter if there is interest

elliot-nelson commented 1 year ago

Does node ./common/scripts/install-run-rush.js --quiet list work for you? I believe we are using that today in our workflows.

Although if it existed, I certainly wouldn't mind this instead:

 - runs: node ./common/scripts/install-run-rush.js list
   env:
     RUSH_QUIET: 1

dbartholomae commented 1 year ago

This still gives me a header of

The rush.json configuration requests Rush version 5.90.2

Invoking "rush --quiet list --impacted-by git:origin/main"
----------------------------------------------------------

Maybe this should be an additional issue for adding a silent flag? Not sure - what happened to the good old UNIX times when CLIs just outputted the actual output on standard out 😄

elliot-nelson commented 1 year ago

Ohhh ok -- I am on Rush v5.88.0, I wonder if this was recently regressed.

We might need to add a new explicit test to make sure "--quiet" stays consistent.

EDIT: Actually, even on latest I am not seeing this issue! Is there anything else funky about your setup?

If you recently upgraded to Rush v5.90.2, is it possible you haven't run "rush update" yet (which would overwrite your common/scripts scripts).

dbartholomae commented 1 year ago

Thanks, that was it! I had installed the new version just to test this. No it is working :)

microsoft / rushstack