From 610c017abe0cff920566e07c3f889ec7eddb5b86 Mon Sep 17 00:00:00 2001 From: rictic Date: Mon, 4 Sep 2023 14:10:33 -0700 Subject: [PATCH 01/15] Add some more "why" info in events This is building up to writing an "explain" logger. --- src/cli.ts | 2 +- src/event.ts | 33 ++++++++ src/logging/default-logger.ts | 24 ++++++ src/logging/quiet/run-tracker.ts | 2 + src/watcher.ts | 129 ++++++++++++++++++++++--------- 5 files changed, 154 insertions(+), 36 deletions(-) diff --git a/src/cli.ts b/src/cli.ts index 80bdf53f3..1a8a0c375 100644 --- a/src/cli.ts +++ b/src/cli.ts @@ -78,7 +78,7 @@ const run = async (options: Options): Promise> => { options.agent, ); process.on('SIGINT', () => { - watcher.abort(); + watcher.abort('SIGINT'); }); await watcher.watch(); return {ok: true, value: undefined}; diff --git a/src/event.ts b/src/event.ts index 8f7aafeef..d03f33cc3 100644 --- a/src/event.ts +++ b/src/event.ts @@ -354,6 +354,8 @@ export type Info = | OutputModified | WatchRunStart | WatchRunEnd + | WatchAborted + | WatchedFileTriggeredRun | ServiceProcessStarted | ServiceReady | ServiceStopped @@ -413,8 +415,13 @@ export interface AnalysisCompleted extends InfoBase { */ export interface WatchRunStart extends InfoBase { detail: 'watch-run-start'; + reason: WatchRunStartReason; } +export type WatchRunStartReason = + | {name: 'initial'} + | {name: 'file-changed'; path: string; operation: FileOperation}; + /** * A watch mode iteration ended. */ @@ -422,6 +429,32 @@ export interface WatchRunEnd extends InfoBase { detail: 'watch-run-end'; } +/** + * We're exiting from watch mode. + */ +export interface WatchAborted extends InfoBase { + detail: 'watch-aborted'; + reason: WatchAbortedReason; +} + +export type WatchAbortedReason = /** We received a CTRL-C signal. */ 'SIGINT'; + +/** + * A file changed that we're watching, and that triggered the next + * watch-run-start. + */ +export interface WatchedFileTriggeredRun extends InfoBase { + detail: 'watched-file-triggered-run'; + path: string; + operation: FileOperation; + /** + * true if we noticed the file was changed while a run was active. + */ + runActive: boolean; +} + +export type FileOperation = 'changed' | 'created' | 'deleted' | 'altered in an unknown way'; + /** * A service process started running. */ diff --git a/src/logging/default-logger.ts b/src/logging/default-logger.ts index d109e1637..024456f92 100644 --- a/src/logging/default-logger.ts +++ b/src/logging/default-logger.ts @@ -265,6 +265,30 @@ export class DefaultLogger implements Logger { console.log(`πŸ‘€${prefix} Watching for file changes`); break; } + case 'watch-aborted': { + switch (event.reason) { + case 'SIGINT': { + console.log(`πŸ›‘${prefix} ctrl-c received, ending watch mode`); + break; + } + default: { + const never: never = event; + console.log( + `πŸ›‘${prefix} Watch aborted for unknown reason: `, + never, + ); + } + } + break; + } + case 'watched-file-triggered-run': { + if (event.runActive) { + console.log(`πŸ”${prefix} File ${JSON.stringify(event.path)} was ${event.operation}, queuing up a new run once this one is finished.`); + } else { + console.log(`πŸ”${prefix} File ${JSON.stringify(event.path)} was ${event.operation}, triggering a new run.`); + } + break; + } case 'cache-info': { console.log(`ℹ️${prefix} ${event.message}`); break; diff --git a/src/logging/quiet/run-tracker.ts b/src/logging/quiet/run-tracker.ts index e39d73b7d..3d2b06a41 100644 --- a/src/logging/quiet/run-tracker.ts +++ b/src/logging/quiet/run-tracker.ts @@ -407,6 +407,8 @@ export class QuietRunLogger implements Disposable { case 'service-ready': case 'watch-run-start': case 'watch-run-end': + case 'watch-aborted': + case 'watched-file-triggered-run': return noChange; case 'locked': { // the script is blocked on starting because something else is diff --git a/src/watcher.ts b/src/watcher.ts index bbd61177e..12dd58857 100644 --- a/src/watcher.ts +++ b/src/watcher.ts @@ -20,6 +20,11 @@ import { import type {Agent} from './cli-options.js'; import type {Fingerprint} from './fingerprint.js'; +import { + FileOperation, + WatchAbortedReason, + WatchRunStartReason, +} from './event.js'; /** * ``` @@ -43,12 +48,12 @@ import type {Fingerprint} from './fingerprint.js'; * ``` */ type WatcherState = - | 'initial' - | 'watching' - | 'debouncing' - | 'running' - | 'queued' - | 'aborted'; + | {name: 'initial'} + | {name: 'watching'} + | {name: 'debouncing'; reason: WatchRunStartReason} + | {name: 'running'; reason: WatchRunStartReason} + | {name: 'queued'; reason: WatchRunStartReason} + | {name: 'aborted'; why: WatchAbortedReason}; function unknownState(state: never) { return new Error(`Unknown watcher state ${String(state)}`); @@ -89,7 +94,7 @@ const DEBOUNCE_MS = 0; */ export class Watcher { /** See {@link WatcherState} */ - #state: WatcherState = 'initial'; + #state: WatcherState = {name: 'initial'}; readonly #rootScript: ScriptReference; readonly #extraArgs: string[] | undefined; @@ -144,7 +149,7 @@ export class Watcher { } watch(): Promise { - void this.#startRun(); + void this.#startRun({name: 'initial'}); return this.#finished.promise; } @@ -163,10 +168,10 @@ export class Watcher { } #onDebounced(): void { - switch (this.#state) { + switch (this.#state.name) { case 'debouncing': { this.#debounceTimeoutId = undefined; - this.#startRun(); + this.#startRun(this.#state.reason); return; } case 'initial': @@ -182,15 +187,16 @@ export class Watcher { } } - #startRun(): void { - switch (this.#state) { + #startRun(reason: WatchRunStartReason): void { + switch (this.#state.name) { case 'initial': case 'debouncing': { - this.#state = 'running'; + this.#state = {name: 'running', reason}; this.#logger.log({ script: this.#rootScript, type: 'info', detail: 'watch-run-start', + reason, }); if (this.#latestRootScriptConfig === undefined) { void this.#analyze(); @@ -221,13 +227,13 @@ export class Watcher { } async #analyze(): Promise { - if (this.#state !== 'running') { + if (this.#state.name !== 'running') { throw unexpectedState(this.#state); } const analyzer = new Analyzer(this.#agent, this.#logger); const result = await analyzer.analyze(this.#rootScript, this.#extraArgs); - if ((this.#state as WatcherState) === 'aborted') { + if ((this.#state as WatcherState).name === 'aborted') { return; } @@ -264,7 +270,7 @@ export class Watcher { } async #execute(script: ScriptConfig): Promise { - if (this.#state !== 'running') { + if (this.#state.name !== 'running') { throw unexpectedState(this.#state); } this.#executor = new Executor( @@ -295,7 +301,7 @@ export class Watcher { type: 'info', detail: 'watch-run-end', }); - switch (this.#state) { + switch (this.#state.name) { case 'queued': { // Note that the debounce time could actually have already elapsed since // the last file change while we were running, but we don't start the @@ -303,12 +309,12 @@ export class Watcher { // interval is also the minimum time between successive runs. This seems // fine and probably good, and is simpler than maintaining a separate // "queued-debouncing" state. - this.#state = 'debouncing'; + this.#state = {name: 'debouncing', reason: this.#state.reason}; void this.#startDebounce(); return; } case 'running': { - this.#state = 'watching'; + this.#state = {name: 'watching'}; return; } case 'aborted': { @@ -326,15 +332,26 @@ export class Watcher { } } - #onConfigFileChanged = (): void => { + #onConfigFileChanged = (operation: FileOperation, path: string): void => { this.#latestRootScriptConfig = undefined; - this.#fileChanged(); + this.#fileChanged(operation, path); }; - #fileChanged = (): void => { - switch (this.#state) { + #fileChanged = (operation: FileOperation, path: string): void => { + switch (this.#state.name) { case 'watching': { - this.#state = 'debouncing'; + this.#logger.log({ + script: this.#rootScript, + type: 'info', + detail: 'watched-file-triggered-run', + path, + operation, + runActive: false, + }); + this.#state = { + name: 'debouncing', + reason: {name: 'file-changed', path, operation}, + }; void this.#startDebounce(); return; } @@ -344,7 +361,18 @@ export class Watcher { return; } case 'running': { - this.#state = 'queued'; + this.#logger.log({ + script: this.#rootScript, + type: 'info', + detail: 'watched-file-triggered-run', + path, + operation, + runActive: true, + }); + this.#state = { + name: 'queued', + reason: {name: 'file-changed', path, operation}, + }; return; } case 'queued': @@ -401,33 +429,39 @@ export class Watcher { } } - abort(): void { + abort(why: WatchAbortedReason): void { + if (this.#state.name === 'aborted') { + return; + } if (this.#executor !== undefined) { this.#executor.abort(); this.#executor = undefined; } - switch (this.#state) { + this.#logger.log({ + script: this.#rootScript, + type: 'info', + detail: 'watch-aborted', + reason: why, + }); + switch (this.#state.name) { case 'debouncing': case 'watching': { - if (this.#state === 'debouncing') { + if (this.#state.name === 'debouncing') { this.#cancelDebounce(); } - this.#state = 'aborted'; + this.#state = {name: 'aborted', why}; this.#closeAllFileWatchers(); this.#finished.resolve(); return; } case 'running': case 'queued': { - this.#state = 'aborted'; + this.#state = {name: 'aborted', why}; this.#closeAllFileWatchers(); // Don't resolve #finished immediately so that we will wait for #analyze // or #execute to finish. return; } - case 'aborted': { - return; - } case 'initial': { throw unexpectedState(this.#state); } @@ -477,7 +511,7 @@ const watchPathsEqual = ( export const makeWatcher = ( patterns: string[], cwd: string, - callback: () => void, + callback: (operation: FileOperation, path: string) => void, ignoreInitial = true, ): FileWatcher => { // TODO(aomarks) chokidar doesn't work exactly like fast-glob, so there are @@ -492,7 +526,32 @@ export const makeWatcher = ( ignoreInitial, }, ); - watcher.on('all', callback); + watcher.on('all', (kind, path) => { + let operation: FileOperation; + switch (kind) { + case 'add': + case 'addDir': { + operation = 'created'; + break; + } + case 'change': { + operation = 'changed'; + break; + } + case 'unlink': + case 'unlinkDir': { + operation = 'deleted'; + break; + } + default: { + const expectNever = (_v: never) => {}; + expectNever(kind); + operation = 'altered in an unknown way'; + } + } + + callback(operation, path); + }); return { patterns, watcher, From 9e21e1ac1d4b888fbee38e4e8eb0e61f57a188ed Mon Sep 17 00:00:00 2001 From: rictic Date: Mon, 4 Sep 2023 14:46:28 -0700 Subject: [PATCH 02/15] Better explain services stopping --- src/event.ts | 15 ++++++++++++++- src/execution/service.ts | 21 ++++++++++++++++----- src/executor.ts | 6 ++++-- src/logging/default-logger.ts | 21 ++++++++++++++++++--- 4 files changed, 52 insertions(+), 11 deletions(-) diff --git a/src/event.ts b/src/event.ts index d03f33cc3..6687adec8 100644 --- a/src/event.ts +++ b/src/event.ts @@ -453,7 +453,11 @@ export interface WatchedFileTriggeredRun extends InfoBase { runActive: boolean; } -export type FileOperation = 'changed' | 'created' | 'deleted' | 'altered in an unknown way'; +export type FileOperation = + | 'changed' + | 'created' + | 'deleted' + | 'altered in an unknown way'; /** * A service process started running. @@ -475,8 +479,17 @@ export interface ServiceReady extends InfoBase { */ export interface ServiceStopped extends InfoBase { detail: 'service-stopped'; + reason: ServiceStoppedReason; + failure: Failure|undefined; } +export type ServiceStoppedReason = + | 'the depgraph changed, service is no longer needed' + | 'the run was aborted' + | 'all consumers of the service are done' + | 'its fingerprint changed, so it needs to restart' + | 'unknown'; + /** * An advisory event about caching. */ diff --git a/src/execution/service.ts b/src/execution/service.ts index 79099bbab..72c84efdd 100644 --- a/src/execution/service.ts +++ b/src/execution/service.ts @@ -14,7 +14,7 @@ import type {ExecutionResult} from './base.js'; import type {Dependency, ServiceScriptConfig} from '../config.js'; import type {Executor} from '../executor.js'; import type {Logger} from '../logging/logger.js'; -import type {Failure} from '../event.js'; +import type {Failure, ServiceStoppedReason} from '../event.js'; import type {Result} from '../error.js'; type ServiceState = @@ -234,6 +234,7 @@ function unexpectedState(state: ServiceState) { */ export class ServiceScriptExecution extends BaseExecutionWithCommand { #state: ServiceState; + readonly config: ServiceScriptConfig; readonly #terminated = new Deferred>(); readonly #isWatchMode: boolean; @@ -246,6 +247,7 @@ export class ServiceScriptExecution extends BaseExecutionWithCommand { + void this.#terminated.promise.then((result) => { + const failure = result.ok ? undefined : result.error; this._logger.log({ script: this._config, type: 'info', detail: 'service-stopped', + reason: this.#stopReason, + failure, }); }); } @@ -359,7 +365,11 @@ export class ServiceScriptExecution extends BaseExecutionWithCommand { - void this.abort(); + void this.abort( + this._config.isPersistent + ? 'the run was aborted' + : 'all consumers of the service are done', + ); }); this.#state = { @@ -489,7 +499,7 @@ export class ServiceScriptExecution extends BaseExecutionWithCommand { + void adoptee.abort('its fingerprint changed, so it needs to restart').then(() => { this.#onAdopteeStopped(); }); return; @@ -978,7 +988,8 @@ export class ServiceScriptExecution extends BaseExecutionWithCommand { + abort(reason: ServiceStoppedReason): Promise { + this.#stopReason = reason; switch (this.#state.id) { case 'started': case 'started-broken': { diff --git a/src/executor.ts b/src/executor.ts index 990b44141..9456beeb7 100644 --- a/src/executor.ts +++ b/src/executor.ts @@ -151,7 +151,7 @@ export class Executor { this.#stopServices.resolve(); if (this.#previousIterationServices !== undefined) { for (const service of this.#previousIterationServices.values()) { - void service.abort(); + void service.abort('the run was aborted'); } } } @@ -178,7 +178,9 @@ export class Executor { const abortPromises = []; for (const [key, service] of this.#previousIterationServices) { if (!currentPersistentServices.has(key)) { - abortPromises.push(service.abort()); + abortPromises.push( + service.abort('the depgraph changed, service is no longer needed'), + ); this.#previousIterationServices.delete(key); } } diff --git a/src/logging/default-logger.ts b/src/logging/default-logger.ts index 024456f92..07035252c 100644 --- a/src/logging/default-logger.ts +++ b/src/logging/default-logger.ts @@ -283,9 +283,17 @@ export class DefaultLogger implements Logger { } case 'watched-file-triggered-run': { if (event.runActive) { - console.log(`πŸ”${prefix} File ${JSON.stringify(event.path)} was ${event.operation}, queuing up a new run once this one is finished.`); + console.log( + `πŸ”${prefix} File ${JSON.stringify(event.path)} was ${ + event.operation + }, queuing up a new run once this one is finished.`, + ); } else { - console.log(`πŸ”${prefix} File ${JSON.stringify(event.path)} was ${event.operation}, triggering a new run.`); + console.log( + `πŸ”${prefix} File ${JSON.stringify(event.path)} was ${ + event.operation + }, triggering a new run.`, + ); } break; } @@ -302,7 +310,14 @@ export class DefaultLogger implements Logger { break; } case 'service-stopped': { - console.log(`⬇️${prefix} Service stopped`); + console.log(`⬇️${prefix} Service stopped because ${event.reason}`); + if (event.failure !== undefined) { + // Use console.group to indent + console.group(); + console.log(`Related failure:`); + this.log(event.failure); + console.groupEnd(); + } break; } case 'analysis-started': From 4c3e3bb78fcd067e9ed8954c251ac6dabea48112 Mon Sep 17 00:00:00 2001 From: rictic Date: Mon, 4 Sep 2023 16:28:03 -0700 Subject: [PATCH 03/15] Track reasons for fingerprint changes --- src/execution/no-command.ts | 4 +- src/execution/service.ts | 20 +-- src/execution/standard.ts | 49 ++++++-- src/fingerprint.ts | 225 ++++++++++++++++++++++++++++++++-- src/logging/explain-logger.ts | 24 ++++ src/logging/watch-logger.ts | 3 +- src/test/gc.test.ts | 4 +- 7 files changed, 296 insertions(+), 33 deletions(-) create mode 100644 src/logging/explain-logger.ts diff --git a/src/execution/no-command.ts b/src/execution/no-command.ts index cc0fd728c..c2bc9d54f 100644 --- a/src/execution/no-command.ts +++ b/src/execution/no-command.ts @@ -19,7 +19,7 @@ export class NoCommandScriptExecution extends BaseExecution { - this.#onAdopteeStopped(); - }); + // deleted the `void` as a deliberate lint warning so I come back and + // include info on + // what changed in the fingerprint + adoptee + .abort('its fingerprint changed, so it needs to restart') + .then(() => { + this.#onAdopteeStopped(); + }); return; } this.#state.deferredFingerprint.resolve({ diff --git a/src/execution/standard.ts b/src/execution/standard.ts index 96dc7d4b3..44192fdac 100644 --- a/src/execution/standard.ts +++ b/src/execution/standard.ts @@ -21,7 +21,12 @@ import type {Result} from '../error.js'; import type {ExecutionResult} from './base.js'; import type {Executor} from '../executor.js'; import type {StandardScriptConfig} from '../config.js'; -import type {FingerprintString} from '../fingerprint.js'; +import type { + ComputeFingerprintResult, + Difference, + FingerprintString, + NotFullyTrackedReason, +} from '../fingerprint.js'; import type {Logger} from '../logging/logger.js'; import type {Cache, CacheHit} from '../caching/cache.js'; import type {Failure, StartCancelled} from '../event.js'; @@ -79,10 +84,11 @@ export class StandardScriptExecution extends BaseExecutionWithCommand { - if (!fingerprint.data.fullyTracked) { - return false; + async #needsToRun( + computeResult: ComputeFingerprintResult, + ): Promise { + if (computeResult.notFullyTrackedReason !== undefined) { + return { + name: 'not-fully-tracked', + reason: computeResult.notFullyTrackedReason, + }; } + const fingerprint = computeResult.fingerprint; const prevFingerprint = await this.#readPreviousFingerprint(); - return prevFingerprint !== undefined && fingerprint.equal(prevFingerprint); + if (prevFingerprint === undefined) { + return {name: 'no-previous-fingerprint'}; + } + const difference = fingerprint.difference(prevFingerprint); + if (difference === undefined) { + return undefined; + } + return { + name: 'fingerprints-differed', + difference, + }; } /** @@ -758,3 +781,11 @@ export class StandardScriptExecution extends BaseExecutionWithCommand, - ): Promise { - let allDependenciesAreFullyTracked = true; + ): Promise { + let notFullyTrackedDep: ScriptReferenceString | undefined = undefined; const filteredDependencyFingerprints: Array< [ScriptReferenceString, FingerprintSha256HexDigest] > = []; @@ -143,7 +148,9 @@ export class Fingerprint { continue; } if (!depFingerprint.data.fullyTracked) { - allDependenciesAreFullyTracked = false; + if (notFullyTrackedDep === undefined) { + notFullyTrackedDep = scriptReferenceToString(dep.config); + } } filteredDependencyFingerprints.push([ scriptReferenceToString(dep.config), @@ -186,19 +193,36 @@ export class Fingerprint { fileHashes = []; } - const fullyTracked = + const notFullyTrackedReason: NotFullyTrackedReason | undefined = (() => { // If any any dependency is not fully tracked, then we can't be either, // because we can't know if there was an undeclared input that this script // depends on. - allDependenciesAreFullyTracked && + if (notFullyTrackedDep !== undefined) { + return { + name: 'dependency not fully tracked', + dependency: notFullyTrackedDep, + }; + } // A no-command script. Doesn't ever do anything itsef, so always fully // tracked. - (script.command === undefined || - // A service. Fully tracked if we know its inputs. Can't produce output. - (script.service !== undefined && script.files !== undefined) || - // A standard script. Fully tracked if we know both its inputs and - // outputs. - (script.files !== undefined && script.output !== undefined)); + if (script.command === undefined) { + return undefined; + } + if (script.files === undefined) { + return {name: 'no input'}; + } + // A service. Fully tracked if we know its inputs. Can't produce output. + if (script.service !== undefined) { + return undefined; + } + // A standard script. Fully tracked if we know both its inputs and + // outputs. + if (script.output === undefined) { + return {name: 'no output'}; + } + return undefined; + })(); + const fullyTracked = notFullyTrackedReason === undefined; const fingerprint = new Fingerprint(); @@ -232,7 +256,7 @@ export class Fingerprint { env: script.env, }; fingerprint.#data = data as FingerprintData; - return fingerprint; + return {fingerprint, notFullyTrackedReason}; } #str?: FingerprintString; @@ -267,4 +291,181 @@ export class Fingerprint { equal(other: Fingerprint): boolean { return this.string === other.string; } + + requiresRebuild(previous: Fingerprint | undefined): boolean { + // If we're not fully tracked, we always need to rebuild. + if (!this.data.fullyTracked) { + return true; + } + // If we don't have a previous fingerprint, we need to rebuild. + if (previous === undefined) { + return true; + } + // Otherwise, we need to rebuild if the fingerprint changed. + return !this.equal(previous); + } + + difference(previous: Fingerprint): Difference | undefined { + // Do a string comparison first, because it's much faster than + // checking field by field; + if (this.equal(previous)) { + return undefined; + } + if (this.data.platform !== previous.data.platform) { + return { + name: 'environment', + field: 'platform', + previous: this.data.platform, + current: previous.data.platform, + }; + } + if (this.data.arch !== previous.data.arch) { + return { + name: 'environment', + field: 'arch', + previous: this.data.arch, + current: previous.data.arch, + }; + } + if (this.data.nodeVersion !== previous.data.nodeVersion) { + return { + name: 'environment', + field: 'nodeVersion', + previous: this.data.nodeVersion, + current: previous.data.nodeVersion, + }; + } + if (this.data.command !== previous.data.command) { + return { + name: 'config', + field: 'command', + previous: this.data.command, + current: previous.data.command, + }; + } + if (this.data.extraArgs.join(' ') !== previous.data.extraArgs.join(' ')) { + return { + name: 'config', + field: 'extraArgs', + previous: this.data.extraArgs, + current: previous.data.extraArgs, + }; + } + if (this.data.clean !== previous.data.clean) { + return { + name: 'config', + field: 'clean', + previous: this.data.clean, + current: previous.data.clean, + }; + } + if (this.data.output.join(' ') !== previous.data.output.join(' ')) { + return { + name: 'config', + field: 'output', + previous: this.data.output, + current: previous.data.output, + }; + } + if ( + this.data.service?.readyWhen.lineMatches !== + previous.data.service?.readyWhen.lineMatches + ) { + return { + name: 'config', + field: 'service', + previous: this.data.service, + current: previous.data.service, + }; + } + if (JSON.stringify(this.data.env) !== JSON.stringify(previous.data.env)) { + return { + name: 'config', + field: 'env', + previous: this.data.env, + current: previous.data.env, + }; + } + const thisFiles = new Set(Object.keys(this.data.files)); + const previousFiles = new Set(Object.keys(previous.data.files)); + for (const path of thisFiles) { + if (!previousFiles.has(path)) { + return {name: 'file added', path}; + } + } + for (const path of previousFiles) { + if (!thisFiles.has(path)) { + return {name: 'file removed', path}; + } + } + for (const path of thisFiles) { + if (this.data.files[path] !== previous.data.files[path]) { + return {name: 'file changed', path}; + } + } + const thisDependencies = new Set( + Object.keys(this.data.dependencies) as ScriptReferenceString[], + ); + const previousDependencies = new Set( + Object.keys(previous.data.dependencies) as ScriptReferenceString[], + ); + for (const dependency of thisDependencies) { + if (!previousDependencies.has(dependency)) { + return { + name: 'dependency changed', + script: dependency, + }; + } + } + for (const dependency of previousDependencies) { + if (!thisDependencies.has(dependency)) { + return { + name: 'dependency removed', + script: dependency, + }; + } + } + for (const dependency of thisDependencies) { + if ( + this.data.dependencies[dependency] !== + previous.data.dependencies[dependency] + ) { + return { + name: 'dependency changed', + script: dependency, + }; + } + } + throw new Error( + `Internal error: fingerprints different but no difference was found.\n current: ${this.string}\n previous: ${previous.string}`, + ); + } } + +export type NotFullyTrackedReason = + | {name: 'no input'} + | {name: 'no output'} + | { + name: 'dependency not fully tracked'; + dependency: ScriptReferenceString; + }; + +export type Difference = + | { + name: 'environment'; + field: 'platform' | 'arch' | 'nodeVersion'; + previous: string; + current: string; + } + | { + name: 'config'; + field: 'command' | 'extraArgs' | 'clean' | 'output' | 'service' | 'env'; + previous: unknown; + current: unknown; + } + | {name: 'file added'; path: string} + | {name: 'file removed'; path: string} + | {name: 'file changed'; path: string} + | {name: 'dependency removed'; script: ScriptReferenceString} + | {name: 'dependency added'; script: ScriptReferenceString} + | {name: 'dependency changed'; script: ScriptReferenceString}; diff --git a/src/logging/explain-logger.ts b/src/logging/explain-logger.ts new file mode 100644 index 000000000..f4fe211b2 --- /dev/null +++ b/src/logging/explain-logger.ts @@ -0,0 +1,24 @@ +/** + * @license + * Copyright 2023 Google LLC + * SPDX-License-Identifier: Apache-2.0 + */ + +import {Event} from '../event.js'; +import {DefaultLogger} from './default-logger.js'; +import {Logger} from './logger.js'; + +export class ExplainLogger extends DefaultLogger { + override log(event: Event): void { + super.log(event); + } + + override printMetrics(): void { + return; + } + + override getWatchLogger(): Logger { + // Don't use watchLogger, we don't want to clear the terminal. + return this; + } +} diff --git a/src/logging/watch-logger.ts b/src/logging/watch-logger.ts index 947f09460..8c0aa97e1 100644 --- a/src/logging/watch-logger.ts +++ b/src/logging/watch-logger.ts @@ -66,7 +66,8 @@ export class WatchLogger implements Logger { case 'watch-run-start': case 'start-cancelled': case 'locked': - case 'analysis-completed': { + case 'analysis-completed': + case 'watched-file-triggered-run': { return false; } } diff --git a/src/test/gc.test.ts b/src/test/gc.test.ts index 4ad5ff06a..ee50fcf44 100644 --- a/src/test/gc.test.ts +++ b/src/test/gc.test.ts @@ -213,7 +213,7 @@ test( } for (const service of previousServices!.values()) { - await service.abort(); + await service.abort('the run was aborted'); } await retryWithGcUntilCallbackDoesNotThrow(() => { @@ -305,7 +305,7 @@ test( } for (const service of previousServices!.values()) { - await service.abort(); + await service.abort('the run was aborted'); } await retryWithGcUntilCallbackDoesNotThrow(() => { From 75c8ddbb5485280f091913c5cfea2cd6836527e7 Mon Sep 17 00:00:00 2001 From: rictic Date: Mon, 4 Sep 2023 18:34:46 -0700 Subject: [PATCH 04/15] Log why a service was stopped in verbose loggers. --- README.md | 2 +- src/cli-options.ts | 8 +- src/event.ts | 13 ++-- src/execution/service.ts | 43 +++++++++-- src/execution/standard.ts | 2 +- src/executor.ts | 4 +- src/fingerprint.ts | 16 ++-- src/logging/default-logger.ts | 141 +++++++++++++++++++++++++++++++++- src/logging/explain-logger.ts | 5 ++ src/test/gc.test.ts | 4 +- src/test/service.test.ts | 42 ++++++---- src/test/util/test-rig.ts | 24 +++++- 12 files changed, 259 insertions(+), 45 deletions(-) diff --git a/README.md b/README.md index 53b621ef8..dbca4ee82 100644 --- a/README.md +++ b/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. ### Service output diff --git a/src/cli-options.ts b/src/cli-options.ts index f465a89d3..ccacc5ad9 100644 --- a/src/cli-options.ts +++ b/src/cli-options.ts @@ -15,6 +15,7 @@ import {unreachable} from './util/unreachable.js'; import {Logger} from './logging/logger.js'; import {QuietCiLogger, QuietLogger} from './logging/quiet-logger.js'; import {DefaultLogger} from './logging/default-logger.js'; +import {ExplainLogger} from './logging/explain-logger.js'; export const packageDir = await (async (): Promise => { // Recent versions of npm set this environment variable that tells us the @@ -197,6 +198,9 @@ export const getOptions = (): Result => { if (str === 'quiet-ci') { return {ok: true, value: new QuietCiLogger(packageRoot)}; } + if (str === 'explain') { + return {ok: true, value: new ExplainLogger(packageRoot)}; + } if (str === 'simple') { return {ok: true, value: new DefaultLogger(packageRoot)}; } @@ -209,7 +213,9 @@ export const getOptions = (): Result => { reason: 'invalid-usage', message: `Expected the WIREIT_LOGGER env variable to be ` + - `"quiet", "simple", or "metrics", got ${JSON.stringify(str)}`, + `"quiet", "quiet-ci", "explain", "simple", or "metrics", got ${JSON.stringify( + str, + )}`, script, type: 'failure', }, diff --git a/src/event.ts b/src/event.ts index 6687adec8..44451f1fb 100644 --- a/src/event.ts +++ b/src/event.ts @@ -12,6 +12,7 @@ import type { ScriptReferenceWithCommand, PackageReference, } from './config.js'; +import {NeedsToRunReason} from './execution/standard.js'; /** * Something that happened during Wireit execution. Includes successes, @@ -480,15 +481,15 @@ export interface ServiceReady extends InfoBase { export interface ServiceStopped extends InfoBase { detail: 'service-stopped'; reason: ServiceStoppedReason; - failure: Failure|undefined; + failure: Failure | undefined; } export type ServiceStoppedReason = - | 'the depgraph changed, service is no longer needed' - | 'the run was aborted' - | 'all consumers of the service are done' - | 'its fingerprint changed, so it needs to restart' - | 'unknown'; + | { name: 'the depgraph changed, service is no longer needed' } + | { name: 'the run was aborted' } + | { name: 'all consumers of the service are done' } + | { name: 'restart'; reason: NeedsToRunReason } + | { name: 'unknown' }; /** * An advisory event about caching. diff --git a/src/execution/service.ts b/src/execution/service.ts index b2a657f51..c8edfd5dd 100644 --- a/src/execution/service.ts +++ b/src/execution/service.ts @@ -16,6 +16,7 @@ import type {Executor} from '../executor.js'; import type {Logger} from '../logging/logger.js'; import type {Failure, ServiceStoppedReason} from '../event.js'; import type {Result} from '../error.js'; +import {NeedsToRunReason} from './standard.js'; type ServiceState = | { @@ -247,7 +248,7 @@ export class ServiceScriptExecution extends BaseExecutionWithCommand { void this.abort( this._config.isPersistent - ? 'the run was aborted' - : 'all consumers of the service are done', + ? {name: 'the run was aborted'} + : {name: 'all consumers of the service are done'}, ); }); @@ -484,15 +485,41 @@ export class ServiceScriptExecution extends BaseExecutionWithCommand { this.#onAdopteeStopped(); }); diff --git a/src/execution/standard.ts b/src/execution/standard.ts index 44192fdac..b053326c9 100644 --- a/src/execution/standard.ts +++ b/src/execution/standard.ts @@ -782,7 +782,7 @@ export class StandardScriptExecution extends BaseExecutionWithCommand { let version: string | undefined; @@ -310,7 +315,139 @@ export class DefaultLogger implements Logger { break; } case 'service-stopped': { - console.log(`⬇️${prefix} Service stopped because ${event.reason}`); + let reason: string; + switch (event.reason.name) { + default: { + const never: never = event.reason; + throw new Error( + `Unknown service stop reason: ${inspect(never)}`, + ); + } + case 'all consumers of the service are done': + case 'the depgraph changed, service is no longer needed': + case 'the run was aborted': + case 'unknown': + reason = event.reason.name; + break; + case 'restart': { + const restartReason = event.reason; + switch (restartReason.reason.name) { + default: { + const never: never = restartReason.reason; + throw new Error( + `Unknown restart reason: ${inspect(never)}`, + ); + } + case 'not-fully-tracked': { + const notFullyTrackedReason = restartReason.reason.reason; + switch (notFullyTrackedReason.name) { + default: { + const never: never = notFullyTrackedReason; + throw new Error( + `Unknown not-fully-tracked reason: ${inspect(never)}`, + ); + } + case 'dependency not fully tracked': { + reason = `the service depends on ${labelForScript( + this.#rootPackageDir, + stringToScriptReference( + notFullyTrackedReason.dependency, + ), + )}`; + break; + } + case 'no files field': { + throw new Error( + 'Internal error: a service is tracked even without a files field', + ); + } + case 'no output field': { + throw new Error( + 'Internal error: a service never has output', + ); + } + } + break; + } + case 'no-previous-fingerprint': { + throw new Error( + 'Internal error: could not find a previous fingerprint, so we restarted the server?', + ); + } + case 'fingerprints-differed': { + const difference = restartReason.reason.difference; + switch (difference.name) { + default: { + const never: never = difference; + throw new Error( + `Unknown not-fully-tracked reason: ${inspect(never)}`, + ); + } + case 'config': { + reason = `config field ${ + difference.field + } changed from ${inspect( + difference.previous, + )} to ${inspect(difference.current)}`; + break; + } + case 'environment': { + reason = `the ${ + difference.field + } of the environment changed from ${inspect( + difference.previous, + )} to ${inspect(difference.current)}`; + break; + } + case 'dependency added': { + reason = `a dependency was added: [${labelForScript( + this.#rootPackageDir, + stringToScriptReference(difference.script), + )}]`; + break; + } + case 'dependency removed': { + reason = `a dependency was removed: [${labelForScript( + this.#rootPackageDir, + stringToScriptReference(difference.script), + )}]`; + break; + } + case 'dependency changed': { + reason = `a dependency changed: [${labelForScript( + this.#rootPackageDir, + stringToScriptReference(difference.script), + )}]`; + break; + } + case 'file added': { + reason = `a file was added: ${pathlib.relative( + this.#rootPackageDir, + difference.path, + )}`; + break; + } + case 'file removed': { + reason = `a file was removed: ${pathlib.relative( + this.#rootPackageDir, + difference.path, + )}`; + break; + } + case 'file changed': { + reason = `a file was changed: ${pathlib.relative( + this.#rootPackageDir, + difference.path, + )}`; + break; + } + } + } + } + break; + } + } + console.log(`⬇️${prefix} Service stopped because ${reason}`); if (event.failure !== undefined) { // Use console.group to indent console.group(); diff --git a/src/logging/explain-logger.ts b/src/logging/explain-logger.ts index f4fe211b2..fd14da667 100644 --- a/src/logging/explain-logger.ts +++ b/src/logging/explain-logger.ts @@ -10,6 +10,11 @@ import {Logger} from './logger.js'; export class ExplainLogger extends DefaultLogger { override log(event: Event): void { + if (event.type === 'output') { + // When explaining, we care about what wireit is doing, not what + // the scripts are doing, so don't log output. + return; + } super.log(event); } diff --git a/src/test/gc.test.ts b/src/test/gc.test.ts index ee50fcf44..b17d74834 100644 --- a/src/test/gc.test.ts +++ b/src/test/gc.test.ts @@ -213,7 +213,7 @@ test( } for (const service of previousServices!.values()) { - await service.abort('the run was aborted'); + await service.abort({name: 'the run was aborted'}); } await retryWithGcUntilCallbackDoesNotThrow(() => { @@ -305,7 +305,7 @@ test( } for (const service of previousServices!.values()) { - await service.abort('the run was aborted'); + await service.abort({name: 'the run was aborted'}); } await retryWithGcUntilCallbackDoesNotThrow(() => { diff --git a/src/test/service.test.ts b/src/test/service.test.ts index 79d0f1c14..5d205cc6e 100644 --- a/src/test/service.test.ts +++ b/src/test/service.test.ts @@ -16,8 +16,8 @@ test.before.each(async (ctx) => { try { ctx.rig = new WireitTestRig(); // Uncomment these lines to debug tests: - // process.env['SHOW_TEST_OUTPUT'] = 'true'; - // ctx.rig.env['WIREIT_DEBUG_LOGGER'] = 'true'; + process.env['SHOW_TEST_OUTPUT'] = 'true'; + ctx.rig.env['WIREIT_DEBUG_LOGGER'] = 'true'; await ctx.rig.setup(); } catch (error) { // Uvu has a bug where it silently ignores failures in before and after, @@ -634,6 +634,7 @@ for (const failureMode of ['continue', 'no-new']) { // v v // service standard timeout(async ({rig}) => { + rig.env.WIREIT_LOGGER = 'simple'; const service = await rig.newCommand(); const standard = await rig.newCommand(); await rig.writeAtomic({ @@ -650,6 +651,7 @@ for (const failureMode of ['continue', 'no-new']) { service: { command: service.command, service: true, + files: [], }, standard: { command: standard.command, @@ -663,21 +665,21 @@ for (const failureMode of ['continue', 'no-new']) { const wireit = rig.exec('npm run entrypoint --watch', { env: {WIREIT_FAILURES: failureMode}, }); - await wireit.waitForLog( - /50% \[1 \/ 2\] \[2 running\] \[1 service\] standard/, - ); + // await wireit.waitForLog( + // /50% \[1 \/ 2\] \[2 running\] \[1 service\] standard/, + // ); const serviceInv = await service.nextInvocation(); const standardInv1 = await standard.nextInvocation(); standardInv1.exit(1); - await wireit.waitForLog(/❌ \[standard\] exited with exit code 1/); - await wireit.waitForLog(/❌ 1 script failed/); + // await wireit.waitForLog(/❌ \[standard\] exited with exit code 1/); + // await wireit.waitForLog(/❌ 1 script failed/); await new Promise((resolve) => setTimeout(resolve, 100)); assert.ok(serviceInv.isRunning); await rig.write('input/standard', '2'); const standardInv2 = await standard.nextInvocation(); standardInv2.exit(0); - await wireit.waitForLog(/βœ… Ran 1 script and skipped 0/); + // await wireit.waitForLog(/βœ… Ran 2 scripts and skipped 0/); await new Promise((resolve) => setTimeout(resolve, 100)); assert.ok(serviceInv.isRunning); @@ -1365,10 +1367,12 @@ test( command: service.command, service: true, dependencies: ['standard'], + files: [], }, standard: { command: standard.command, files: ['input'], + output: [], }, }, }, @@ -1391,6 +1395,9 @@ test( // Introduce an error. Service keeps running but goes into a temporary // "started-broken" state, where it awaits its dependencies being fixed. await rig.write('input', '2'); + await wireit.waitForLog( + /πŸ” \[service\] File "input" was changed, triggering a new run./, + ); await wireit.waitForLog(/\[standard\] Running/); (await standard.nextInvocation()).exit(1); await wireit.waitForLog(/\[standard\] Failed with exit status 1/); @@ -1402,11 +1409,17 @@ test( // Fix the error. Service restarts because the fingerprint of its dependency // has changed. await rig.write('input', '3'); + await wireit.waitForLog( + /πŸ” \[service\] File "input" was changed, triggering a new run./, + ); await wireit.waitForLog(/\[standard\] Running/); (await standard.nextInvocation()).exit(0); await wireit.waitForLog(/\[standard\] Executed successfully/); await service.nextInvocation(); - await wireit.waitForLog(/\[service\] Service stopped/); + await wireit.waitForLog( + /\[service\] Service stopped because a dependency changed: \[standard\]/, + ); + await wireit.waitForLog(/\[service\] Service starting.../); await wireit.waitForLog(/\[service\] Service ready/); await wireit.waitForLog(/\[service\] Watching for file changes/); await new Promise((resolve) => setTimeout(resolve, 50)); @@ -1416,6 +1429,9 @@ test( // Introduce another error. Again the service keeps running as // "started-broken". await rig.write('input', '4'); + await wireit.waitForLog( + /πŸ” \[service\] File "input" was changed, triggering a new run./, + ); await wireit.waitForLog(/\[standard\] Running/); (await standard.nextInvocation()).exit(1); await wireit.waitForLog(/\[standard\] Failed with exit status 1/); @@ -1428,18 +1444,16 @@ test( // restart, because the fingerprint has been restored to what it was before // the failure. await rig.write('input', '3'); - await wireit.waitForLog(/\[standard\] Running/); - (await standard.nextInvocation()).exit(0); - await wireit.waitForLog(/\[standard\] Executed successfully/); + await wireit.waitForLog(/\[standard\] Restored from cache/); await wireit.waitForLog(/\[service\] Watching for file changes/); await new Promise((resolve) => setTimeout(resolve, 50)); assert.equal(service.numInvocations, 2); - assert.equal(standard.numInvocations, 5); + assert.equal(standard.numInvocations, 4); wireit.kill(); await wireit.exit; assert.equal(service.numInvocations, 2); - assert.equal(standard.numInvocations, 5); + assert.equal(standard.numInvocations, 4); }), ); diff --git a/src/test/util/test-rig.ts b/src/test/util/test-rig.ts index 32aaef9c6..34f61cda5 100644 --- a/src/test/util/test-rig.ts +++ b/src/test/util/test-rig.ts @@ -121,6 +121,7 @@ export class WireitTestRig extends FilesystemTestRig { // at the end of the test, and if any are still running then the test // has probably failed from timeout. If the process is hung, we'll // already see that from the timeout. + child.reportStalledLogMatchers(); child.kill({force: true}); await child.exit; } @@ -223,6 +224,7 @@ export type {ExecResult}; * The object returned by {@link WireitTestRig.exec}. */ class ExecResult { + readonly #command: string; readonly #child: ChildProcessWithoutNullStreams; readonly #exited = new Deferred(); #running = true; @@ -236,6 +238,7 @@ class ExecResult { cwd: string, env: Record, ) { + this.#command = command; // Remove any environment variables that start with "npm_", because those // will have been set by the "npm test" or similar command that launched // this test itself, and we want a more pristine simulation of running @@ -347,12 +350,31 @@ class ExecResult { */ waitForLog(matcher: RegExp): Promise { const deferred = new Deferred(); - this.#logMatchers.add({re: matcher, deferred}); + this.#logMatchers.add({ + re: matcher, + deferred, + }); // In case we've already received the log we're watching for this.#checkMatchersAgainstLogs(); return deferred.promise; } + reportStalledLogMatchers() { + if (this.#logMatchers.size === 0) { + return; + } + console.error(`${this.#command} was still waiting to see logs matching:`); + for (const {re} of this.#logMatchers) { + console.error(' ', re); + } + console.error( + `Unconsumed stdout:\n\`\`\`\n${this.#matcherStdout}\n\`\`\`\n`, + ); + console.error( + `Unconsumed stderr:\n\`\`\`\n${this.#matcherStderr}\n\`\`\`\n`, + ); + } + #checkMatchersAgainstLogs() { let stdoutLastIndex = -1; let stderrLastIndex = -1; From 81e826fc2ce3edb4e638f17e01ed1775ff2d7eae Mon Sep 17 00:00:00 2001 From: rictic Date: Mon, 4 Sep 2023 19:25:44 -0700 Subject: [PATCH 05/15] Explain why a running script isn't fresh --- src/event.ts | 23 ++++-- src/execution/standard.ts | 57 +++++++++---- src/logging/default-logger.ts | 24 +++--- src/logging/explain-logger.ts | 146 +++++++++++++++++++++++++++++++++- 4 files changed, 216 insertions(+), 34 deletions(-) diff --git a/src/event.ts b/src/event.ts index 44451f1fb..ae77ae9fb 100644 --- a/src/event.ts +++ b/src/event.ts @@ -374,8 +374,21 @@ interface InfoBase */ export interface ScriptRunning extends InfoBase { detail: 'running'; + notFreshReason: NotFreshReason; } +export type NotFreshReason = + | { + name: 'output manifest outdated'; + reason: OutputManifestOutdatedReason; + } + | NeedsToRunReason; + +export type OutputManifestOutdatedReason = + | 'no previous manifest' + | 'output modified' + | `can't glob output files`; + /** * A script can't run right now because a system-wide lock is being held by * another process. @@ -485,11 +498,11 @@ export interface ServiceStopped extends InfoBase { } export type ServiceStoppedReason = - | { name: 'the depgraph changed, service is no longer needed' } - | { name: 'the run was aborted' } - | { name: 'all consumers of the service are done' } - | { name: 'restart'; reason: NeedsToRunReason } - | { name: 'unknown' }; + | {name: 'the depgraph changed, service is no longer needed'} + | {name: 'the run was aborted'} + | {name: 'all consumers of the service are done'} + | {name: 'restart'; reason: NeedsToRunReason} + | {name: 'unknown'}; /** * An advisory event about caching. diff --git a/src/execution/standard.ts b/src/execution/standard.ts index b053326c9..26d835122 100644 --- a/src/execution/standard.ts +++ b/src/execution/standard.ts @@ -29,7 +29,12 @@ import type { } from '../fingerprint.js'; import type {Logger} from '../logging/logger.js'; import type {Cache, CacheHit} from '../caching/cache.js'; -import type {Failure, StartCancelled} from '../event.js'; +import type { + Failure, + NotFreshReason, + OutputManifestOutdatedReason, + StartCancelled, +} from '../event.js'; import type {AbsoluteEntry} from '../util/glob.js'; import type {FileManifestEntry, FileManifestString} from '../util/manifest.js'; @@ -106,15 +111,27 @@ export class StandardScriptExecution extends BaseExecutionWithCommand { + async #handleNeedsRun( + fingerprint: Fingerprint, + notFreshReason: NotFreshReason, + ): Promise { // Check if we should clean before we delete the fingerprint file, because // we sometimes need to read the previous fingerprint file to determine // this. @@ -381,6 +401,7 @@ export class StandardScriptExecution extends BaseExecutionWithCommand > { this.#ensureState('before-running'); - return (this.#cachedOutputFilesBeforeRunning ??= this.#globOutputFiles()); + const result = await (this.#cachedOutputFilesBeforeRunning ??= + this.#globOutputFiles()); + this.#ensureState('before-running'); + return result; } #cachedOutputFilesBeforeRunning?: Promise< Result @@ -719,21 +743,23 @@ export class StandardScriptExecution extends BaseExecutionWithCommand> { + async #outputManifestOutdatedReason(): Promise< + Result + > { const oldManifestPromise = this.#readPreviousOutputManifest(); const outputFilesBeforeRunning = await this.#globOutputFilesBeforeRunning(); if (!outputFilesBeforeRunning.ok) { return outputFilesBeforeRunning; } if (outputFilesBeforeRunning.value === undefined) { - return {ok: true, value: false}; + return {ok: true, value: `can't glob output files`}; } const newManifest = await this.#computeOutputManifest( outputFilesBeforeRunning.value, ); const oldManifest = await oldManifestPromise; if (oldManifest === undefined) { - return {ok: true, value: false}; + return {ok: true, value: 'no previous manifest'}; } const equal = newManifest === oldManifest; if (!equal) { @@ -742,8 +768,9 @@ export class StandardScriptExecution extends BaseExecutionWithCommand { * Default {@link Logger} which logs to stdout and stderr. */ export class DefaultLogger implements Logger { - readonly #rootPackageDir: string; + protected readonly rootPackageDir: string; readonly #diagnosticPrinter: DiagnosticPrinter; /** @@ -45,13 +45,13 @@ export class DefaultLogger implements Logger { * executed belongs to. */ constructor(rootPackage: string) { - this.#rootPackageDir = rootPackage; - this.#diagnosticPrinter = new DiagnosticPrinter(this.#rootPackageDir); + this.rootPackageDir = rootPackage; + this.#diagnosticPrinter = new DiagnosticPrinter(this.rootPackageDir); } log(event: Event) { const type = event.type; - const label = labelForScript(this.#rootPackageDir, event.script); + const label = labelForScript(this.rootPackageDir, event.script); const prefix = label !== '' ? ` [${label}]` : ''; switch (type) { default: { @@ -182,7 +182,7 @@ export class DefaultLogger implements Logger { case 'dependency-invalid': { console.error( `❌${prefix} Depended, perhaps indirectly, on ${labelForScript( - this.#rootPackageDir, + this.rootPackageDir, event.dependency, )} which could not be validated. Please file a bug at https://github.com/google/wireit/issues/new, mention this message, that you encountered it in wireit version ${getWireitVersion()}, and give information about your package.json files.`, ); @@ -349,7 +349,7 @@ export class DefaultLogger implements Logger { } case 'dependency not fully tracked': { reason = `the service depends on ${labelForScript( - this.#rootPackageDir, + this.rootPackageDir, stringToScriptReference( notFullyTrackedReason.dependency, ), @@ -401,42 +401,42 @@ export class DefaultLogger implements Logger { } case 'dependency added': { reason = `a dependency was added: [${labelForScript( - this.#rootPackageDir, + this.rootPackageDir, stringToScriptReference(difference.script), )}]`; break; } case 'dependency removed': { reason = `a dependency was removed: [${labelForScript( - this.#rootPackageDir, + this.rootPackageDir, stringToScriptReference(difference.script), )}]`; break; } case 'dependency changed': { reason = `a dependency changed: [${labelForScript( - this.#rootPackageDir, + this.rootPackageDir, stringToScriptReference(difference.script), )}]`; break; } case 'file added': { reason = `a file was added: ${pathlib.relative( - this.#rootPackageDir, + this.rootPackageDir, difference.path, )}`; break; } case 'file removed': { reason = `a file was removed: ${pathlib.relative( - this.#rootPackageDir, + this.rootPackageDir, difference.path, )}`; break; } case 'file changed': { reason = `a file was changed: ${pathlib.relative( - this.#rootPackageDir, + this.rootPackageDir, difference.path, )}`; break; diff --git a/src/logging/explain-logger.ts b/src/logging/explain-logger.ts index fd14da667..acdf8a1f7 100644 --- a/src/logging/explain-logger.ts +++ b/src/logging/explain-logger.ts @@ -4,9 +4,18 @@ * SPDX-License-Identifier: Apache-2.0 */ -import {Event} from '../event.js'; -import {DefaultLogger} from './default-logger.js'; +import {inspect} from 'node:util'; +import { + Event, + NotFreshReason, + OutputManifestOutdatedReason, + ScriptRunning, +} from '../event.js'; +import {DefaultLogger, labelForScript} from './default-logger.js'; import {Logger} from './logger.js'; +import {stringToScriptReference} from '../config.js'; +import {Difference, NotFullyTrackedReason} from '../fingerprint.js'; +import * as pathlib from 'node:path'; export class ExplainLogger extends DefaultLogger { override log(event: Event): void { @@ -16,6 +25,139 @@ export class ExplainLogger extends DefaultLogger { return; } super.log(event); + if (event.type === 'info' && event.detail === 'running') { + this.#logRunning(event); + } + } + #logRunning(event: ScriptRunning) { + // const pipeRightTreeChar = '\u251c'; + const downRightTreeChar = '\u2514'; + const notFreshExplanation = this.#explainNotFreshReason(event.notFreshReason); + // console.log(`${pipeRightTreeChar} You asked it to run because ${dependencyExplanation}.`); + console.log(`${downRightTreeChar} It can't be skipped because ${notFreshExplanation}.`); + } + + #explainNotFreshReason(reason: NotFreshReason): string { + switch (reason.name) { + default: { + const never: never = reason; + throw new Error(`Unknown not-fresh reason: ${inspect(never)}`); + } + case 'no-previous-fingerprint': { + return `this looks like the first run (no previous fingerprint found)`; + } + case 'fingerprints-differed': { + return this.#explainFingerprintsDifferedReason(reason.difference); + } + case 'not-fully-tracked': { + return this.#explainNotFullyTrackedReason(reason.reason); + } + case 'output manifest outdated': { + return this.#explainOutputManifestOutdatedReason(reason.reason); + } + } + } + + #explainFingerprintsDifferedReason(difference: Difference): string { + switch (difference.name) { + default: { + const never: never = difference; + throw new Error(`Unknown not-fully-tracked reason: ${inspect(never)}`); + } + case 'config': { + return `the ${ + difference.field + } field in the package.json file changed from ${inspect( + difference.current, + )} to ${inspect(difference.previous)}`; + } + case 'environment': { + return `the ${ + difference.field + } aspect of the runtime environment changed from ${inspect( + difference.current, + )} to ${inspect(difference.previous)}`; + } + case 'file added': { + return `the input file ${pathlib.relative( + this.rootPackageDir, + difference.path, + )} was created`; + } + case 'file removed': { + return `the input file ${pathlib.relative( + this.rootPackageDir, + difference.path, + )} was deleted`; + } + case 'file changed': { + return `the input file ${pathlib.relative( + this.rootPackageDir, + difference.path, + )} was modified`; + } + case 'dependency added': { + return `a dependency on [${labelForScript( + this.rootPackageDir, + stringToScriptReference(difference.script), + )}] was added`; + } + case 'dependency removed': { + return `a dependency on [${labelForScript( + this.rootPackageDir, + stringToScriptReference(difference.script), + )}] was removed`; + } + case 'dependency changed': { + return `out dependency [${labelForScript( + this.rootPackageDir, + stringToScriptReference(difference.script), + )}] was re-run, so we needed to as well`; + } + } + } + + #explainOutputManifestOutdatedReason( + reason: OutputManifestOutdatedReason, + ): string { + switch (reason) { + default: { + const never: never = reason; + throw new Error( + `Unknown output manifest outdated reason: ${inspect(never)}`, + ); + } + case `can't glob output files`: { + return `unable to glob output files`; + } + case 'no previous manifest': { + return `this looks like the first run (no previous output manifest found)`; + } + case 'output modified': { + return `output files were modified since the previous run`; + } + } + } + + #explainNotFullyTrackedReason(reason: NotFullyTrackedReason): string { + switch (reason.name) { + default: { + const never: never = reason; + throw new Error(`Unknown not-fully-tracked reason: ${inspect(never)}`); + } + case 'dependency not fully tracked': { + return `depends on ${labelForScript( + this.rootPackageDir, + stringToScriptReference(reason.dependency), + )} which must always be run`; + } + case 'no files field': { + return `it has no "files" field and so it must always be run`; + } + case 'no output field': { + return `it has no "output" field and so it must always be run`; + } + } } override printMetrics(): void { From aafaf976dc363912d3b8e81e15d4a0d544588b1e Mon Sep 17 00:00:00 2001 From: rictic Date: Mon, 4 Sep 2023 19:51:36 -0700 Subject: [PATCH 06/15] Explain dependency trees too --- src/event.ts | 63 ++++++++++++++++++++++++++++++++++- src/execution/base.ts | 43 ++++++++++++++++++++---- src/execution/service.ts | 16 ++++++--- src/execution/standard.ts | 25 +++++++------- src/executor.ts | 28 +++++++++++----- src/fingerprint.ts | 31 ++--------------- src/logging/explain-logger.ts | 63 +++++++++++++++++++++++++++-------- 7 files changed, 196 insertions(+), 73 deletions(-) diff --git a/src/event.ts b/src/event.ts index ae77ae9fb..06e25dad6 100644 --- a/src/event.ts +++ b/src/event.ts @@ -11,8 +11,8 @@ import type { ScriptReference, ScriptReferenceWithCommand, PackageReference, + ScriptReferenceString, } from './config.js'; -import {NeedsToRunReason} from './execution/standard.js'; /** * Something that happened during Wireit execution. Includes successes, @@ -375,8 +375,12 @@ interface InfoBase export interface ScriptRunning extends InfoBase { detail: 'running'; notFreshReason: NotFreshReason; + executionRequestedReason: ExecutionRequestedReason; } +/** + * Answers the question "Why is this script not fresh?" + */ export type NotFreshReason = | { name: 'output manifest outdated'; @@ -384,11 +388,68 @@ export type NotFreshReason = } | NeedsToRunReason; +/** + * Answers the question "Why does this script need to run?" + */ +export type NeedsToRunReason = + | { + name: 'not-fully-tracked'; + reason: NotFullyTrackedReason; + } + | {name: 'no-previous-fingerprint'} + | {name: 'fingerprints-differed'; difference: FingerprintDifference}; + +/** + * Answers the question "Why is this script's fingerprint not fully tracked?" + */ +export type NotFullyTrackedReason = + | {name: 'no files field'} + | {name: 'no output field'} + | { + name: 'dependency not fully tracked'; + dependency: ScriptReferenceString; + }; + +/** + * Answers the question "Why is this script's fingerprint different from the + * previous one?" + */ +export type FingerprintDifference = + | { + name: 'environment'; + field: 'platform' | 'arch' | 'nodeVersion'; + previous: string; + current: string; + } + | { + name: 'config'; + field: 'command' | 'extraArgs' | 'clean' | 'output' | 'service' | 'env'; + previous: unknown; + current: unknown; + } + | {name: 'file added'; path: string} + | {name: 'file removed'; path: string} + | {name: 'file changed'; path: string} + | {name: 'dependency removed'; script: ScriptReferenceString} + | {name: 'dependency added'; script: ScriptReferenceString} + | {name: 'dependency changed'; script: ScriptReferenceString}; + +/** + * One reason why a script might not be fresh is that we can't be sure that + * its output files are up to date. This can happen if the output manifest + * can't be found, or its output was modified since its last run, or if for + * some reason we can't glob its output files. + */ export type OutputManifestOutdatedReason = | 'no previous manifest' | 'output modified' | `can't glob output files`; +/** + * Answers the question "what requested this script to run?" + */ +export type ExecutionRequestedReason = {path: readonly ScriptReferenceString[]}; + /** * A script can't run right now because a system-wide lock is being held by * another process. diff --git a/src/execution/base.ts b/src/execution/base.ts index 89e14f570..f5e7f086c 100644 --- a/src/execution/base.ts +++ b/src/execution/base.ts @@ -10,9 +10,13 @@ import {Deferred} from '../util/deferred.js'; import type {Result} from '../error.js'; import type {Executor} from '../executor.js'; -import type {Dependency, ScriptConfig} from '../config.js'; +import { + scriptReferenceToString, + type Dependency, + type ScriptConfig, +} from '../config.js'; import type {Logger} from '../logging/logger.js'; -import type {Failure} from '../event.js'; +import type {ExecutionRequestedReason, Failure} from '../event.js'; export type ExecutionResult = Result; @@ -47,13 +51,22 @@ export abstract class BaseExecution { protected readonly _config: T; protected readonly _executor: Executor; protected readonly _logger: Logger; + readonly #executionRequestedReason: ExecutionRequestedReason; + #reasonForChildExecution: ExecutionRequestedReason | undefined = undefined; + #fingerprint?: Promise; - constructor(config: T, executor: Executor, logger: Logger) { + constructor( + config: T, + executor: Executor, + logger: Logger, + executionRequestedReason: ExecutionRequestedReason, + ) { executionConstructorHook?.(this); this._config = config; this._executor = executor; this._logger = logger; + this.#executionRequestedReason = executionRequestedReason; } /** @@ -64,6 +77,18 @@ export abstract class BaseExecution { return (this.#fingerprint ??= this._execute()); } + getReasonForChildExecution(): ExecutionRequestedReason { + if (this.#reasonForChildExecution === undefined) { + this.#reasonForChildExecution = { + path: [ + ...this.#executionRequestedReason.path, + scriptReferenceToString(this._config), + ], + }; + } + return this.#reasonForChildExecution; + } + protected abstract _execute(): Promise; /** @@ -79,7 +104,9 @@ export abstract class BaseExecution { const dependencyResults = await Promise.all( this._config.dependencies.map((dependency) => { - return this._executor.getExecution(dependency.config).execute(); + return this._executor + .getExecution(dependency.config, this.getReasonForChildExecution()) + .execute(); }), ); const results: Array<[Dependency, Fingerprint]> = []; @@ -124,7 +151,9 @@ export abstract class BaseExecutionWithCommand< */ protected readonly _anyServiceTerminated = Promise.race( this._config.services.map( - (service) => this._executor.getExecution(service).terminated, + (service) => + this._executor.getExecution(service, this.getReasonForChildExecution()) + .terminated, ), ); @@ -135,7 +164,9 @@ export abstract class BaseExecutionWithCommand< if (this._config.services.length > 0) { const results = await Promise.all( this._config.services.map((service) => - this._executor.getExecution(service).start(), + this._executor + .getExecution(service, this.getReasonForChildExecution()) + .start(), ), ); const errors: Failure[] = []; diff --git a/src/execution/service.ts b/src/execution/service.ts index c8edfd5dd..4a549d50a 100644 --- a/src/execution/service.ts +++ b/src/execution/service.ts @@ -14,9 +14,13 @@ import type {ExecutionResult} from './base.js'; import type {Dependency, ServiceScriptConfig} from '../config.js'; import type {Executor} from '../executor.js'; import type {Logger} from '../logging/logger.js'; -import type {Failure, ServiceStoppedReason} from '../event.js'; +import type { + ExecutionRequestedReason, + Failure, + NeedsToRunReason, + ServiceStoppedReason, +} from '../event.js'; import type {Result} from '../error.js'; -import {NeedsToRunReason} from './standard.js'; type ServiceState = | { @@ -257,8 +261,9 @@ export class ServiceScriptExecution extends BaseExecutionWithCommand, adoptee: ServiceScriptExecution | undefined, isWatchMode: boolean, + executionRequestedReason: ExecutionRequestedReason, ) { - super(config, executor, logger); + super(config, executor, logger, executionRequestedReason); this.config = config; this.#isWatchMode = isWatchMode; this.#state = { @@ -359,7 +364,10 @@ export class ServiceScriptExecution extends BaseExecutionWithCommand - this._executor.getExecution(consumer).servicesNotNeeded, + this._executor.getExecution( + consumer, + this.getReasonForChildExecution(), + ).servicesNotNeeded, ), ); const abort = this._config.isPersistent diff --git a/src/execution/standard.ts b/src/execution/standard.ts index 26d835122..cd07252a0 100644 --- a/src/execution/standard.ts +++ b/src/execution/standard.ts @@ -23,9 +23,7 @@ import type {Executor} from '../executor.js'; import type {StandardScriptConfig} from '../config.js'; import type { ComputeFingerprintResult, - Difference, FingerprintString, - NotFullyTrackedReason, } from '../fingerprint.js'; import type {Logger} from '../logging/logger.js'; import type {Cache, CacheHit} from '../caching/cache.js'; @@ -33,7 +31,9 @@ import type { Failure, NotFreshReason, OutputManifestOutdatedReason, + ExecutionRequestedReason, StartCancelled, + NeedsToRunReason, } from '../event.js'; import type {AbsoluteEntry} from '../util/glob.js'; import type {FileManifestEntry, FileManifestString} from '../util/manifest.js'; @@ -50,6 +50,7 @@ export class StandardScriptExecution extends BaseExecutionWithCommand { // Check if we should clean before we delete the fingerprint file, because // we sometimes need to read the previous fingerprint file to determine @@ -402,6 +410,7 @@ export class StandardScriptExecution extends BaseExecutionWithCommand(config: T): ConfigToExecution { + getExecution( + config: T, + executionRequestedReason: ExecutionRequestedReason, + ): ConfigToExecution { const key = scriptReferenceToString(config); let execution = this.#executions.get(key); if (execution === undefined) { if (config.command === undefined) { - execution = new NoCommandScriptExecution(config, this, this.#logger); + execution = new NoCommandScriptExecution( + config, + this, + this.#logger, + executionRequestedReason, + ); } else if (config.service !== undefined) { execution = new ServiceScriptExecution( config, @@ -267,6 +277,7 @@ export class Executor { this.#stopServices.promise, this.#previousIterationServices?.get(key), this.#isWatchMode, + executionRequestedReason, ); if (config.isPersistent) { this.#persistentServices.set(key, execution); @@ -280,6 +291,7 @@ export class Executor { this.#workerPool, this.#cache, this.#logger, + executionRequestedReason, ); } this.#executions.set(key, execution); diff --git a/src/fingerprint.ts b/src/fingerprint.ts index e9b7cd5dd..49517c009 100644 --- a/src/fingerprint.ts +++ b/src/fingerprint.ts @@ -14,6 +14,7 @@ import type { ScriptReferenceString, Dependency, } from './config.js'; +import {FingerprintDifference, NotFullyTrackedReason} from './event.js'; /** * All meaningful inputs of a script. Used for determining if a script is fresh, @@ -307,7 +308,7 @@ export class Fingerprint { return !this.equal(previous); } - difference(previous: Fingerprint): Difference | undefined { + difference(previous: Fingerprint): FingerprintDifference | undefined { // Do a string comparison first, because it's much faster than // checking field by field; if (this.equal(previous)) { @@ -443,31 +444,3 @@ export class Fingerprint { ); } } - -export type NotFullyTrackedReason = - | {name: 'no files field'} - | {name: 'no output field'} - | { - name: 'dependency not fully tracked'; - dependency: ScriptReferenceString; - }; - -export type Difference = - | { - name: 'environment'; - field: 'platform' | 'arch' | 'nodeVersion'; - previous: string; - current: string; - } - | { - name: 'config'; - field: 'command' | 'extraArgs' | 'clean' | 'output' | 'service' | 'env'; - previous: unknown; - current: unknown; - } - | {name: 'file added'; path: string} - | {name: 'file removed'; path: string} - | {name: 'file changed'; path: string} - | {name: 'dependency removed'; script: ScriptReferenceString} - | {name: 'dependency added'; script: ScriptReferenceString} - | {name: 'dependency changed'; script: ScriptReferenceString}; diff --git a/src/logging/explain-logger.ts b/src/logging/explain-logger.ts index acdf8a1f7..9b36df450 100644 --- a/src/logging/explain-logger.ts +++ b/src/logging/explain-logger.ts @@ -6,15 +6,17 @@ import {inspect} from 'node:util'; import { + FingerprintDifference, Event, + ExecutionRequestedReason, NotFreshReason, + NotFullyTrackedReason, OutputManifestOutdatedReason, ScriptRunning, } from '../event.js'; import {DefaultLogger, labelForScript} from './default-logger.js'; import {Logger} from './logger.js'; import {stringToScriptReference} from '../config.js'; -import {Difference, NotFullyTrackedReason} from '../fingerprint.js'; import * as pathlib from 'node:path'; export class ExplainLogger extends DefaultLogger { @@ -30,11 +32,43 @@ export class ExplainLogger extends DefaultLogger { } } #logRunning(event: ScriptRunning) { - // const pipeRightTreeChar = '\u251c'; + const pipeRightTreeChar = '\u251c'; const downRightTreeChar = '\u2514'; - const notFreshExplanation = this.#explainNotFreshReason(event.notFreshReason); - // console.log(`${pipeRightTreeChar} You asked it to run because ${dependencyExplanation}.`); - console.log(`${downRightTreeChar} It can't be skipped because ${notFreshExplanation}.`); + const notFreshExplanation = this.#explainNotFreshReason( + event.notFreshReason, + ); + const executionExplanation = this.#explainExecutionRequestedReason( + event.executionRequestedReason, + ); + console.log( + `${pipeRightTreeChar} You asked it to run because ${executionExplanation}.`, + ); + console.log( + `${downRightTreeChar} It can't be skipped because ${notFreshExplanation}.`, + ); + // ? + } + + #explainExecutionRequestedReason(reason: ExecutionRequestedReason): string { + if (reason.path.length === 0) { + return 'it was the root script you asked for'; + } + if (reason.path.length === 1) { + return `it was a direct dependency of the root script [${labelForScript( + this.rootPackageDir, + stringToScriptReference(reason.path[0]!), + )}] you asked for`; + } + const path = reason.path + .map( + (p) => + `[${labelForScript( + this.rootPackageDir, + stringToScriptReference(p), + )}]`, + ) + .join(' -> '); + return `it was a dependency along this path: ${path}`; } #explainNotFreshReason(reason: NotFreshReason): string { @@ -56,16 +90,19 @@ export class ExplainLogger extends DefaultLogger { return this.#explainOutputManifestOutdatedReason(reason.reason); } } + // } - #explainFingerprintsDifferedReason(difference: Difference): string { + #explainFingerprintsDifferedReason( + difference: FingerprintDifference, + ): string { switch (difference.name) { default: { const never: never = difference; throw new Error(`Unknown not-fully-tracked reason: ${inspect(never)}`); } case 'config': { - return `the ${ + return `its ${ difference.field } field in the package.json file changed from ${inspect( difference.current, @@ -79,37 +116,37 @@ export class ExplainLogger extends DefaultLogger { )} to ${inspect(difference.previous)}`; } case 'file added': { - return `the input file ${pathlib.relative( + return `its input file ${pathlib.relative( this.rootPackageDir, difference.path, )} was created`; } case 'file removed': { - return `the input file ${pathlib.relative( + return `its input file ${pathlib.relative( this.rootPackageDir, difference.path, )} was deleted`; } case 'file changed': { - return `the input file ${pathlib.relative( + return `its input file ${pathlib.relative( this.rootPackageDir, difference.path, )} was modified`; } case 'dependency added': { - return `a dependency on [${labelForScript( + return `its dependency on [${labelForScript( this.rootPackageDir, stringToScriptReference(difference.script), )}] was added`; } case 'dependency removed': { - return `a dependency on [${labelForScript( + return `its dependency on [${labelForScript( this.rootPackageDir, stringToScriptReference(difference.script), )}] was removed`; } case 'dependency changed': { - return `out dependency [${labelForScript( + return `its dependency [${labelForScript( this.rootPackageDir, stringToScriptReference(difference.script), )}] was re-run, so we needed to as well`; From 9cbed09f4bc613772d8402264f2cdbb5cdbd4c88 Mon Sep 17 00:00:00 2001 From: rictic Date: Mon, 4 Sep 2023 20:33:31 -0700 Subject: [PATCH 07/15] Use the type system to double check that we got all fingerprint fields --- src/fingerprint.ts | 46 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 46 insertions(+) diff --git a/src/fingerprint.ts b/src/fingerprint.ts index 49517c009..c388cebe1 100644 --- a/src/fingerprint.ts +++ b/src/fingerprint.ts @@ -314,6 +314,15 @@ export class Fingerprint { if (this.equal(previous)) { return undefined; } + + // To be sure that we don't miss any differences, as we check each field + // we remove its type from this union. If we get to the end and there are + // still fields left, then we missed something. + type FingerprintFields = Exclude< + keyof FingerprintData, + '__FingerprintDataBrand__' + >; + type FieldsExcludingPlatform = Exclude; if (this.data.platform !== previous.data.platform) { return { name: 'environment', @@ -322,6 +331,7 @@ export class Fingerprint { current: previous.data.platform, }; } + type FieldsExcludingArch = Exclude; if (this.data.arch !== previous.data.arch) { return { name: 'environment', @@ -330,6 +340,10 @@ export class Fingerprint { current: previous.data.arch, }; } + type FieldsExcludingNodeVersion = Exclude< + FieldsExcludingArch, + 'nodeVersion' + >; if (this.data.nodeVersion !== previous.data.nodeVersion) { return { name: 'environment', @@ -338,6 +352,10 @@ export class Fingerprint { current: previous.data.nodeVersion, }; } + type FieldsExcludingCommand = Exclude< + FieldsExcludingNodeVersion, + 'command' + >; if (this.data.command !== previous.data.command) { return { name: 'config', @@ -346,6 +364,10 @@ export class Fingerprint { current: previous.data.command, }; } + type FieldsExcludingExtraArgs = Exclude< + FieldsExcludingCommand, + 'extraArgs' + >; if (this.data.extraArgs.join(' ') !== previous.data.extraArgs.join(' ')) { return { name: 'config', @@ -354,6 +376,7 @@ export class Fingerprint { current: previous.data.extraArgs, }; } + type FieldsExcludingClean = Exclude; if (this.data.clean !== previous.data.clean) { return { name: 'config', @@ -362,6 +385,7 @@ export class Fingerprint { current: previous.data.clean, }; } + type FieldsExcludingOutput = Exclude; if (this.data.output.join(' ') !== previous.data.output.join(' ')) { return { name: 'config', @@ -370,6 +394,7 @@ export class Fingerprint { current: previous.data.output, }; } + type FieldsExcludingService = Exclude; if ( this.data.service?.readyWhen.lineMatches !== previous.data.service?.readyWhen.lineMatches @@ -381,6 +406,7 @@ export class Fingerprint { current: previous.data.service, }; } + type FieldsExcludingEnv = Exclude; if (JSON.stringify(this.data.env) !== JSON.stringify(previous.data.env)) { return { name: 'config', @@ -389,6 +415,7 @@ export class Fingerprint { current: previous.data.env, }; } + type FieldsExcludingFiles = Exclude; const thisFiles = new Set(Object.keys(this.data.files)); const previousFiles = new Set(Object.keys(previous.data.files)); for (const path of thisFiles) { @@ -406,6 +433,10 @@ export class Fingerprint { return {name: 'file changed', path}; } } + type FieldsExcludingDependencies = Exclude< + FieldsExcludingFiles, + 'dependencies' + >; const thisDependencies = new Set( Object.keys(this.data.dependencies) as ScriptReferenceString[], ); @@ -439,6 +470,21 @@ export class Fingerprint { }; } } + type FieldsExcludingFullyTracked = Exclude< + FieldsExcludingDependencies, + 'fullyTracked' + >; + if (this.data.fullyTracked !== previous.data.fullyTracked) { + // This should never happen, because we already checked that all of + // the other fields are the same. + throw new Error( + `Internal error: fingerprints differed only in the 'fullyTracked' field, which should be impossible.\n current: ${this.string}\n previous: ${previous.string}`, + ); + } + if (false as boolean) { + let remainingFields!: FieldsExcludingFullyTracked; + remainingFields satisfies never; + } throw new Error( `Internal error: fingerprints different but no difference was found.\n current: ${this.string}\n previous: ${previous.string}`, ); From 7bb036d1e892e74d4a7263990c94082266b66b24 Mon Sep 17 00:00:00 2001 From: rictic Date: Mon, 4 Sep 2023 20:49:31 -0700 Subject: [PATCH 08/15] Update CHANGELOG and README --- CHANGELOG.md | 4 ++++ README.md | 16 ++++++++-------- src/logging/explain-logger.ts | 1 - 3 files changed, 12 insertions(+), 9 deletions(-) diff --git a/CHANGELOG.md b/CHANGELOG.md index 6d7151a0f..5a28fca2f 100644 --- a/CHANGELOG.md +++ b/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. + ### Fixed - More reliably handle and report diagnostics for scripts with invalid configurations. Specifically fixed https://github.com/google/wireit/issues/803. diff --git a/README.md b/README.md index dbca4ee82..937f70304 100644 --- a/README.md +++ b/README.md @@ -847,14 +847,14 @@ The following syntaxes can be used in the `wireit.