Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add a new "explain" logger #863

Open
wants to merge 15 commits into
base: main
Choose a base branch
from
Open

Add a new "explain" logger #863

wants to merge 15 commits into from

Conversation

rictic
Copy link
Member

@rictic rictic commented Sep 5, 2023

A somewhat different design, but intended to address the use case brought up in #806 and that we've frequently needed ourselves.

@rictic rictic marked this pull request as ready for review September 5, 2023 04:53
Copy link
Member

@aomarks aomarks left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looks great! Some pretty minor comments.

@@ -197,6 +198,9 @@ export const getOptions = (): Result<Options> => {
if (str === 'quiet-ci') {
return {ok: true, value: new QuietCiLogger(packageRoot)};
}
if (str === 'explain') {
return {ok: true, value: new ExplainLogger(packageRoot)};
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

WDYT about dynamic importing the explain logger here? It should be a rare import.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

+1!

README.md Outdated
@@ -554,7 +554,7 @@ the given regular expression.

In watch mode, a service will be restarted whenever one of its input files or
dependencies change, except for dependencies with
[`cascade`](#execution-cascade) set to `false`.
[`cascade`](#execution-cascade) set to `false`. Unlike standard scripts, `wireit` assumes that a service doesn't depend on any files unless you tell it otherwise by defining a `files` array.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Is this definitely true? I can't remember if it's intentional or not, do you think it's the right behavior?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Looked into it some more, and this seems like an oversight. It's better for services to have explicit "files", and the correct thing to do if that's not there is to restart on each new run. Updated.

if (script.files === undefined) {
return {name: 'no files field'};
}
// A standard script. Fully tracked if we know both its inputs and
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should this comment be just above (above if (script.files === undefined) {) ?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, yes!

src/fingerprint.ts Show resolved Hide resolved
@@ -267,4 +294,186 @@ export class Fingerprint {
equal(other: Fingerprint): boolean {
return this.string === other.string;
}

difference(previous: Fingerprint): FingerprintDifference | undefined {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nit, would other be a better name than previous (more general -- previous implies a certain relationship between the two fingerprints)?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

previous is the intended relationship here, and in both cases where it's currently called the other fingerprint is the called the previous fingerprint

this relationship is also represented in the FingerprintDifference data structure (though I just noticed that I was created a lot of these values backwards, erp!)

by being specific we can give clearer messages when we log

>;
type FieldsExcludingPlatform = Exclude<FingerprintFields, 'platform'>;
if (this.data.platform !== previous.data.platform) {
return {
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There could be multiple fields that are different. WDYT about collecting all fields that differ and returning an array, instead of returning just the first one?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is true across basically all of the "why" logging we do in this PR, and my thinking was that giving only the first cause of an action strikes the right balance of clarity and performance.

Maybe it would be better though to collect together things of like kind? Like, all of the environment changes into one change record, all of the config changes into one change record, etc.

Added a TODO

@@ -10,6 +10,10 @@ Versioning](https://semver.org/spec/v2.0.0.html).

## [Unreleased]

### Added

- Added a new logger for debugging your Wireit configs. Set `WIREIT_LOGGER=explain` to see detailed information about why each script is run, as well as the normal `simple` logs, without any stdout or stderr of scripts.
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It seems like a little more information is also added to the default logger in this PR (and I think simple logger, since it delegates to default sometimes?). Mention that too in a separate line?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Done

await wireit.waitForLog(/\[service\] Watching for file changes/);
await new Promise((resolve) => setTimeout(resolve, 50));
assert.equal(service.numInvocations, 2);
assert.equal(service.numInvocations, 3);
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why did the numInvocations change? 🤔

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good call! Investigated more, and I think it's because of a bug in wireit, that this test was testing, and that this change fixes. The relevant change is that I made services care about whether their dependencies are fully tracked when deciding whether they need to restart. If a dependency ran, and it's not cascade: false, and it's not fully tracked, then the service must restart, because the service's boot up might depend on an untracked output of the dependency.

In more detail:

[standard] wasn't cacheable (i.e. wasn't fully tracked) as originally written because it didn't have an output field. As a result, when we write 3 to standard's input file again, it needs to run again, and because of that [service] needs to restart, because [service] might consume some output of [standard] th was emitted differently this time.

However this test is trying to test cases where [service] doesn't need to restart, i.e. when after a failure of [standard] we can revert it back to its previous version. That requires that [standard] have an output field, and then its final run is just a restore from cache.

}
}
#logRunning(event: ScriptRunning) {
const pipeRightTreeChar = '\u251c';
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

WDYT about just putting the character directly inline instead of having this variable? (That way we can see more easily whether it's the right one in the source)

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, yes, of course, that's much better

console.log(
`${downRightTreeChar} It can't be skipped because ${notFreshExplanation}.`,
);
// ?
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

What's this comment?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah, I was futzing about with making changes to trigger re-builds and looking at the output lol

@@ -74,6 +74,7 @@ async function retryWithGcUntilCallbackDoesNotThrow(
cb: () => void,
): Promise<void> {
for (const wait of [0, 10, 100, 500, 1000]) {
collectGarbage();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

1 GC not enough?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Surprisingly, it often isn't. When doing memory leak tests in Lit we found that memory is often not freed unless you call gc twice in a row.

🤷

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants