[rush] Replay logs for warnings and errors as well #4668

aramissennyeydd · 2024-04-29T20:15:09Z

Summary

Replays logs through the hook context's runWithTerminalAsync to hook into the stdio summarization functionality. This allows the report at the end of execution to be the same across machines.

Operations with 2 second durations were executed on the agent, those with <.5 seconds were restored from the build cache from the cobuild.

Before:

Agent 1

==[ SUCCESS WITH WARNINGS: 7 operations ]======================================

--[ WARNING: b (build) ]-------------------------------------[ 2.10 seconds ]--

done b

--[ WARNING: c (build) ]-------------------------------------[ 2.10 seconds ]--

done 

--[ WARNING: d (build) ]-------------------------------------[ 2.10 seconds ]--

done 

--[ WARNING: a (build) ]-------------------------------------[ 0.01 seconds ]--


--[ WARNING: e (build) ]-------------------------------------[ 2.09 seconds ]--

done 

--[ WARNING: f (build) ]-------------------------------------[ 2.13 seconds ]--

done f

--[ WARNING: g (build) ]-------------------------------------[ 2.14 seconds ]--

done g


Operations succeeded with warnings.

rush cobuild (16.95 seconds)

Agent 2

==[ SUCCESS WITH WARNINGS: 7 operations ]======================================

--[ WARNING: b (build) ]-------------------------------------[ 0.02 seconds ]--


--[ WARNING: c (build) ]-------------------------------------[ 0.01 seconds ]--


--[ WARNING: d (build) ]-------------------------------------[ 0.01 seconds ]--


--[ WARNING: a (build) ]-------------------------------------[ 2.10 seconds ]--

done a

--[ WARNING: e (build) ]-------------------------------------[ 0.02 seconds ]--


--[ WARNING: f (build) ]-------------------------------------[ 2.14 seconds ]--

done f

--[ WARNING: g (build) ]-------------------------------------[ 2.13 seconds ]--

done g


Operations succeeded with warnings.

rush cobuild (20.71 seconds)

After:

Agent 1

==[ SUCCESS WITH WARNINGS: 7 operations ]======================================

--[ WARNING: b (build) ]-------------------------------------[ 0.01 seconds ]--

done b

--[ WARNING: c (build) ]-------------------------------------[ 0.01 seconds ]--

done 

--[ WARNING: d (build) ]-------------------------------------[ 0.01 seconds ]--

done 

--[ WARNING: a (build) ]-------------------------------------[ 2.09 seconds ]--

done a

--[ WARNING: e (build) ]-------------------------------------[ 0.01 seconds ]--

done 

--[ WARNING: f (build) ]-------------------------------------[ 2.14 seconds ]--

done f

--[ WARNING: g (build) ]-------------------------------------[ 2.14 seconds ]--

done g


Operations succeeded with warnings.

Agent 2


==[ SUCCESS WITH WARNINGS: 7 operations ]======================================

--[ WARNING: b (build) ]-------------------------------------[ 2.09 seconds ]--

done b

--[ WARNING: c (build) ]-------------------------------------[ 2.08 seconds ]--

done 

--[ WARNING: d (build) ]-------------------------------------[ 2.09 seconds ]--

done 

--[ WARNING: a (build) ]-------------------------------------[ 0.01 seconds ]--

done a

--[ WARNING: e (build) ]-------------------------------------[ 2.09 seconds ]--

done 

--[ WARNING: f (build) ]-------------------------------------[ 2.14 seconds ]--

done f

--[ WARNING: g (build) ]-------------------------------------[ 2.14 seconds ]--

done g


Operations succeeded with warnings.

rush cobuild (16.92 seconds)

Details

This stores the log chunks into a JSON file, that is a direct write of the ITerminalChunk type. This is then restored while the build cache is being restored to the terminal with the correct severity following the ShellOperationPlugin logging semantics.

{
  "chunks": [
    {
      "kind": "O",
      "text": "Invoking: node ../build.js b \n"
    },
    {
      "kind": "O",
      "text": "start b\n"
    },
    {
      "kind": "E",
      "text": "done b\n",
    }
  ]
}

How it was tested

Tested against the repo cobuild sandbox with build caching enabled. Both restoring from the original build cache and cobuild cache work as expected and display the output above.

Impacted documentation

libraries/rush-lib/src/logic/operations/OperationMetadataManager.ts

libraries/rush-lib/src/logic/operations/LogChunksWritable.ts

libraries/rush-lib/src/logic/operations/schemas/log-chunk.schema.json

libraries/rush-lib/src/logic/operations/OperationMetadataManager.ts

libraries/rush-lib/src/logic/operations/LogChunksWritable.ts

common/changes/@microsoft/rush/sennyeya-log-replays_2024-04-29-20-05.json

.gitignore

iclanton

This overall looks good to me, but it'd be good for @octogonz to review this too, as he originally wrote a lot of the streaming logs stuff.

build-tests/rush-redis-cobuild-plugin-integration-test/sandbox/repo/.gitignore

common/config/rush/browser-approved-packages.json

libraries/rush-lib/src/logic/operations/OperationMetadataManager.ts

common/reviews/api/rush-lib.api.md

libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts

libraries/rush-lib/src/logic/operations/LogChunksWritable.ts

octogonz · 2024-05-06T18:59:19Z

libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts

@@ -197,6 +198,14 @@ export class OperationExecutionRecord implements IOperationRunnerContext {
 `${associatedPhase.logFilenameIdentifier}${logFileSuffix}`
 )
 : undefined;
+ const logChunksWritable: LogChunksWritable | undefined =
+ associatedPhase && associatedProject


It is unclear why associatedPhase && associatedProject should be the criteria to determine whether we use LogChunksWritable to save chunks or not. Perhaps associatedPhase && associatedProject is only true when cobuilds are enabled? This code needs a comment explanation or a more intuitive criteria.

For example, if I want to test this PR to inspect the `${logFileBaseName}.chunks.jsonl` output, from looking at the code it's not obvious what I would need to do to cause associatedPhase && associatedProject to become true. Enable cobuilds?

I'm also unclear why these are nullable in the first place, they should both be defined when an operation is created with the PhasedOperationPlugin. Cobuilds are not a requirement. The && check is also part of the projectLogWritable above.

@dmichon-msft do you know the answer?

The reason these were not required when added to the interface is that I had other plugins that created operations in the graph that were not strictly related to any phase or any operation. For example I had a custom pnpm installer that added operations to the Rush graph, and those installation steps were associated with external dependencies, not Rush projects.

In current usage we can make them be required (or make them required properties of an optional subobject that also contains all the various things that depend on their presence if we want to maintain that degree of compatibility with fewer checks).

libraries/rush-lib/src/logic/operations/LogChunksWritable.ts

libraries/rush-lib/src/logic/operations/OperationMetadataManager.ts

… chunk separations

…-20-05.json Co-authored-by: Ian Clanton-Thuon <[email protected]>

…/repo/.gitignore Co-authored-by: Ian Clanton-Thuon <[email protected]>

Signed-off-by: Aramis Sennyey <[email protected]>

…er.ts Co-authored-by: Ian Clanton-Thuon <[email protected]>

libraries/rush-lib/src/logic/operations/ProjectLogWritable.ts

libraries/rush-lib/src/logic/operations/CacheableOperationPlugin.ts

libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts

dmichon-msft · 2024-05-14T03:47:25Z

libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts

@@ -197,6 +198,14 @@ export class OperationExecutionRecord implements IOperationRunnerContext {
 `${associatedPhase.logFilenameIdentifier}${logFileSuffix}`
 )
 : undefined;
+ const logChunksWritable: LogChunksWritable | undefined =
+ associatedPhase && associatedProject


The reason these were not required when added to the interface is that I had other plugins that created operations in the graph that were not strictly related to any phase or any operation. For example I had a custom pnpm installer that added operations to the Rush graph, and those installation steps were associated with external dependencies, not Rush projects.

In current usage we can make them be required (or make them required properties of an optional subobject that also contains all the various things that depend on their presence if we want to maintain that degree of compatibility with fewer checks).

aramissennyeydd · 2024-05-16T02:28:59Z

@octogonz @dmichon-msft This is ready for re-review when you get a chance!

dmichon-msft · 2024-05-23T00:58:34Z

libraries/rush-lib/src/logic/operations/OperationMetadataManager.ts

+ if (await FileSystem.existsAsync(this._logChunksPath)) {
+ const rawLogChunks: string = await FileSystem.readFileAsync(this._logChunksPath);


It's safer and faster to try/catch the await FileSystem.readFileAsync call and handle the FileSystem.isNotExistError(err) case. Existence checking files before reading them is well-documented as an error-prone antipattern. Yes, I know that there are many places in the rushstack repo where we do that, but we don't need to add more of them.

dmichon-msft · 2024-05-23T01:01:22Z

libraries/rush-lib/src/logic/operations/ProjectLogWritable.ts

+ if (this._enableChunkedOutput) {
+ if (!this._chunkWriter) {
+ this._chunkWriter = FileWriter.open(this.logChunksPath);
+ }
+ this._chunkWriter.write(JSON.stringify(chunk) + '\n');
+ }


I don't like creating files inside of the write callback. I'd rather pay the tax of creating this file up front and then letting it be empty.

Also, there's a handler for this._logWriter being closed; we should have the same for this._chunkWriter for the same reason.

iclanton

How painful would it be to add a unit test for the chunked file format?

iclanton · 2024-05-23T02:49:54Z

libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts

 ? new ProjectLogWritable(
 associatedProject,
 this.collatedWriter.terminal,
- `${associatedPhase.logFilenameIdentifier}${logFileSuffix}`
+ `${associatedPhase.logFilenameIdentifier}${logFileSuffix}`,
+ true
 )


With this many arguments, consider making this an options object with named properties.

iclanton · 2024-05-23T02:52:26Z

@aramissennyeydd - Looks good overall. Once you just address @dmichon-msft's comments we can get this in.

aramissennyeydd requested review from iclanton, octogonz, apostolisms, D4N14L and dmichon-msft as code owners April 29, 2024 20:15

dmichon-msft reviewed Apr 29, 2024

View reviewed changes

libraries/rush-lib/src/logic/operations/OperationMetadataManager.ts Outdated Show resolved Hide resolved

iclanton reviewed Apr 30, 2024

View reviewed changes

aramissennyeydd requested a review from patmill as a code owner May 2, 2024 16:23

aramissennyeydd requested a review from iclanton May 3, 2024 19:32

iclanton reviewed May 6, 2024

View reviewed changes

octogonz reviewed May 6, 2024

View reviewed changes

common/reviews/api/rush-lib.api.md Show resolved Hide resolved

octogonz reviewed May 6, 2024

View reviewed changes

libraries/rush-lib/src/logic/operations/OperationExecutionRecord.ts Outdated Show resolved Hide resolved

octogonz reviewed May 6, 2024

View reviewed changes

libraries/rush-lib/src/logic/operations/LogChunksWritable.ts Outdated Show resolved Hide resolved

octogonz reviewed May 6, 2024

View reviewed changes

libraries/rush-lib/src/logic/operations/LogChunksWritable.ts Outdated Show resolved Hide resolved

aramissennyeydd force-pushed the sennyeya/log-replays branch 2 times, most recently from fccbf98 to 82b0c1d Compare May 7, 2024 14:56

aramissennyeydd requested a review from octogonz May 7, 2024 15:57

iclanton reviewed May 10, 2024

View reviewed changes

libraries/rush-lib/src/logic/operations/OperationMetadataManager.ts Outdated Show resolved Hide resolved

aramissennyeydd and others added 11 commits May 10, 2024 08:26

fix: replay logs for warnings and errors as well

fc79a18

remove console.log

3da7a34

add changeset

64be994

small rework

b8a8d3c

fix linting issues

a6619b2

create a new terminal writer that outputs to a json files that stores…

f200c55

… chunk separations

fix linting errors

c2c4ee1

add comment

4f822fe

Update common/changes/@microsoft/rush/sennyeya-log-replays_2024-04-29…

8452cfe

…-20-05.json Co-authored-by: Ian Clanton-Thuon <[email protected]>

remove schema check and extract log file name forming

d65408d

update how we're saving the file

e1ad58b

aramissennyeydd and others added 10 commits May 10, 2024 08:26

remove top level gitignore

eb83a8d

remove unnecessary gitignore changes

f785673

update to a jsonl format

11a29ee

rework to use async stream pipeline

e20d7af

Update build-tests/rush-redis-cobuild-plugin-integration-test/sandbox…

8333906

…/repo/.gitignore Co-authored-by: Ian Clanton-Thuon <[email protected]>

address PR feedback

e481c31

remove external dep

2bd0393

Signed-off-by: Aramis Sennyey <[email protected]>

fix linting and remove debug log

ad2a9c0

fix repo state

58b43ac

Update libraries/rush-lib/src/logic/operations/OperationMetadataManag…

a8a6f93

…er.ts Co-authored-by: Ian Clanton-Thuon <[email protected]>

aramissennyeydd force-pushed the sennyeya/log-replays branch from 85d9903 to a8a6f93 Compare May 10, 2024 12:31

octogonz changed the title ~~fix: replay logs for warnings and errors as well~~ [rush] Replay logs for warnings and errors as well May 14, 2024

dmichon-msft reviewed May 14, 2024

View reviewed changes

aramissennyeydd added 5 commits May 14, 2024 05:59

address PR feedback; move chunk writing to project log writable.

cf60b6b

fix comment

69bf9c2

remove optional comment

7bbc670

don't log cache output

fbdc6e7

adjust to .rush folder

bee686c

dmichon-msft reviewed May 23, 2024

View reviewed changes

iclanton reviewed May 23, 2024

View reviewed changes

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[rush] Replay logs for warnings and errors as well #4668

[rush] Replay logs for warnings and errors as well #4668

aramissennyeydd commented Apr 29, 2024 •

edited

iclanton left a comment

octogonz May 6, 2024

octogonz May 6, 2024

aramissennyeydd May 7, 2024

octogonz May 10, 2024

dmichon-msft May 14, 2024

dmichon-msft May 14, 2024

aramissennyeydd commented May 16, 2024

dmichon-msft May 23, 2024

dmichon-msft May 23, 2024

dmichon-msft May 23, 2024

iclanton left a comment

iclanton May 23, 2024

iclanton commented May 23, 2024

		if (await FileSystem.existsAsync(this._logChunksPath)) {
		const rawLogChunks: string = await FileSystem.readFileAsync(this._logChunksPath);

[rush] Replay logs for warnings and errors as well #4668

Are you sure you want to change the base?

[rush] Replay logs for warnings and errors as well #4668

Conversation

aramissennyeydd commented Apr 29, 2024 • edited

Summary

Before:

Agent 1

Agent 2

After:

Agent 1

Agent 2

Details

How it was tested

Impacted documentation

iclanton left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

aramissennyeydd commented May 16, 2024

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

iclanton left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

iclanton commented May 23, 2024

aramissennyeydd commented Apr 29, 2024 •

edited