Add a new "explain" logger #863

rictic · 2023-09-05T03:56:30Z

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

This is building up to writing an "explain" logger.

aomarks

Looks great! Some pretty minor comments.

aomarks · 2023-09-05T14:38:41Z

src/cli-options.ts

@@ -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)};


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

aomarks · 2023-09-05T14:39:26Z

README.md

@@ -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.


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

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.

aomarks · 2023-09-05T14:46:55Z

src/fingerprint.ts

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


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

src/fingerprint.ts

aomarks · 2023-09-05T14:49:21Z

src/fingerprint.ts

@@ -267,4 +294,186 @@ export class Fingerprint {
  equal(other: Fingerprint): boolean {
    return this.string === other.string;
  }
+
+  difference(previous: Fingerprint): FingerprintDifference | undefined {


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

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

aomarks · 2023-09-05T14:52:18Z

src/fingerprint.ts

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


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?

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

aomarks · 2023-09-05T14:54:32Z

CHANGELOG.md

@@ -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.


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?

aomarks · 2023-09-05T15:04:18Z

src/test/service.test.ts

    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);


Why did the numInvocations change? 🤔

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.

aomarks · 2023-09-05T15:08:05Z

src/logging/explain-logger.ts

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


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)

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

aomarks · 2023-09-05T15:08:38Z

src/logging/explain-logger.ts

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


What's this comment?

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

aomarks · 2023-09-11T17:32:50Z

src/test/gc.test.ts

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


1 GC not enough?

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.

🤷

This test behaves the same with and without this change.

rictic added 5 commits September 4, 2023 20:52

Add some more "why" info in events

610c017

This is building up to writing an "explain" logger.

Better explain services stopping

9e21e1a

Track reasons for fingerprint changes

4c3e3bb

Log why a service was stopped in verbose loggers.

75c8ddb

Explain why a running script isn't fresh

81e826f

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

rictic added 5 commits September 4, 2023 21:54

Explain dependency trees too

aafaf97

Use the type system to double check that we got all fingerprint fields

9cbed09

Update CHANGELOG and README

7bb036d

Lint

42b48c0

Improve clarity a bit more.

fcba1f8

rictic force-pushed the explain-mode branch from 89340b1 to fcba1f8 Compare September 5, 2023 04:55

aomarks approved these changes Sep 5, 2023

View reviewed changes

rictic and others added 3 commits September 5, 2023 10:20

Address some review comments

cfd0391

Format

0a7a85a

Unify behavior of persistent services and the 'files' field.

4b8a11d

aomarks approved these changes Sep 11, 2023

View reviewed changes

rictic added 2 commits September 11, 2023 18:50

Add a test of a caching consumer of an ephemeral service with files

ea5bff9

This test behaves the same with and without this change.

Improved and clarified service caching test

ba68974

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add a new "explain" logger #863

Add a new "explain" logger #863

rictic commented Sep 5, 2023

aomarks left a comment

aomarks Sep 5, 2023

rictic Sep 5, 2023

aomarks Sep 5, 2023

rictic Sep 10, 2023

aomarks Sep 5, 2023

rictic Sep 5, 2023

aomarks Sep 5, 2023

rictic Sep 5, 2023

aomarks Sep 5, 2023

rictic Sep 5, 2023

aomarks Sep 5, 2023

rictic Sep 10, 2023

aomarks Sep 5, 2023

rictic Sep 5, 2023

aomarks Sep 5, 2023

rictic Sep 5, 2023

aomarks Sep 5, 2023

rictic Sep 5, 2023

aomarks Sep 11, 2023

rictic Sep 12, 2023

Add a new "explain" logger #863

Are you sure you want to change the base?

Add a new "explain" logger #863

Conversation

rictic commented Sep 5, 2023

aomarks 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

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

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