[rush] rush build error logs no longer include stdout

[relm923]

Summary

rush build error logs no longer include STDOUT since 5.124.4.

Repro steps

Using https://github.com/microsoft/rush-example

1. Add TS error in package
2. rush build
3. Review generated logs

Expected result: (v5.124.4)

==[ FAILURE: 1 operation ]=====================================================

--[ FAILURE: my-toolchain ]----------------------------------[ 0.77 seconds ]--

Invoking: rimraf ./lib/ && tsc 
src/startCommand.ts(9,1): error TS2552: Cannot find name 'consoleX'. Did you mean 'console'?


Operations failed.

rush build (0.79 seconds)

Actual result: (since v5.124.4)

==[ FAILURE: 1 operation ]=====================================================

--[ FAILURE: my-toolchain ]----------------------------------[ 0.76 seconds ]--

Returned error code: 2


Operations failed.

rush build (0.77 seconds)

Details

Potentially introduced by https://github.com/microsoft/rushstack/pull/4717

Zulip Thread

Standard questions

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

Question	Answer
@microsoft/rush globally installed version?
rushVersion from rush.json?	5.124.4 vs 5.124.5
useWorkspaces from rush.json?	true
Operating system?	Mac
Would you consider contributing a PR?	Yes
Node.js version (node -v)?	20.11.0

[iclanton]

@dmichon-msft, would you mind taking a look at this?

[dmichon-msft]

StdioSummarizer will automatically discard stdout if there is any content to stderr. I think the solution to this may well be that we should abandon that behavior and instead do as BuildXL does, i.e. if the operation fails, dump the entire log.

The change in my PR was to handle issues where operations were failing and not logging anything.

[relm923]

@dmichon-msft Makes sense but the current implementation is particularly painful for build commands using tsc as all error messages are thrown away.

Thoughts on either reverting your change or prioritizing a forward fix?

[relm923]

What the options here? The current version is very painful when there are TS build errors

[jessekrubin]

I second @relm923 it is extremely painful. Can kinda get away with using the -v but then I have a bazillion things to scroll through...

[jessekrubin]

@dmichon-msft What is the rational behind throwing away the stdout log on stderr? Why wouldn't ALL the stdout/stderr be collected and displayed when there is an error? I cannot imagine a scenario where I would not want both logs.

AFAIK many many many build tools write to stdout when exiting with nonzero codes.

EDIT/PS: This makes it difficult to use rush without using something like heft that steps in and redirects/collects the logs. I/you/one REALLY should not have to buy into using heft or some other tool to use rush. It makes it difficult to migrate non-heft packages into a rush repo. In many cases for smaller libraries my build script is just tsc -b && eslint <ARGS>.

[UberMouse]

+1 on this

[octogonz]

After chatting with @dmichon-msft , I'm suggesting the following:

• Quickly fix the immediate issue: If it will take some time to figure out the best possible design, perhaps we should temporarily revert the design change that is causing frustration, or at least provide a way to opt-in (or opt-out).  
• Show full details: Whether or not a summary is shown, we could print full logs for projects that had errors/warnings.  As long as this extra output precedes the summary, I don't see any downside to including it (i.e. no need for such a change to be optional).  
• Improve or remove the summarizer (TBD): Personally I still think it can be beneficial to show a summary, for example: if someone sends me a URL for a CI job where 3 projects failed, and I'm trying to read it on my phone (where it is very difficult to scroll through a log), it can be really handy to have a quick synopsis of the likely error messages. But the algorithm is a heuristic, and sometimes it's wrong. Ideally we should improve the algorithm so that the excerpt is more likely to contain the actual error message, and so that the surrounding text is more explicit to avoid accidentally misleading the user when the error isn't captured accurately.

[octogonz]

For reference, our understanding of the regression:

1. The summarizer normally shows the last few lines of STDERR (excluding STDOUT entirely), unless there is no STDERR, in which case it instead shows the last few lines of STDOUT.
2. In this repro, the task would normally fail with all error info going to STDOUT
3. ...and therefore the summarizer chooses to excerpt from STDOUT
4. But https://github.com/microsoft/rushstack/pull/4717 made a change so that Rush itself now writes to STDERR
5. ...which caused the summarizer to instead show STDERR only, and now STDOUT is not shown at all.

[octogonz]

@dmichon-msft has made a quick fix: https://github.com/microsoft/rushstack/pull/4984 🙏

This PR basically acknowledges that "any change is going to break people." Rush's summarizer is an arbitrary heuristic that is somewhat "unstable" (i.e. printing one character to STDERR causes STDOUT to get lost), which people have had years to adjust to. So I think we should be mindful about changing it, even if those changes seem like improvements.

Next steps after David's PR:

• Another PR to include full STDERR+STDOUT for any failing projects (printed above the summary)

• Another PR to improve the heuristic, with an "opt-in" switch to accommodate anyone who prefers the old summarizer semantics. I'm thinking we can aim for significant improvements, e.g. maybe we can use VS Code problem matchers instead of merely looking for STDERR outputs.

[jessekrubin]

When will this be published?

[jessekrubin]

@octogonz could the changes related to this issue also affect why chaining rushx uno && rushx dos within a package's build script also gives no helpful information?