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.

Sign up for GitHub

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

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
15 commits
Select commit Hold shift + click to select a range
610c017
Add some more "why" info in events
rictic Sep 4, 2023
9e21e1a
Better explain services stopping
rictic Sep 4, 2023
4c3e3bb
Track reasons for fingerprint changes
rictic Sep 4, 2023
75c8ddb
Log why a service was stopped in verbose loggers.
rictic Sep 5, 2023
81e826f
Explain why a running script isn't fresh
rictic Sep 5, 2023
aafaf97
Explain dependency trees too
rictic Sep 5, 2023
9cbed09
Use the type system to double check that we got all fingerprint fields
rictic Sep 5, 2023
7bb036d
Update CHANGELOG and README
rictic Sep 5, 2023
42b48c0
Lint
rictic Sep 5, 2023
fcba1f8
Improve clarity a bit more.
rictic Sep 5, 2023
cfd0391
Address some review comments
rictic Sep 5, 2023
0a7a85a
Format
rictic Sep 5, 2023
4b8a11d
Unify behavior of persistent services and the 'files' field.
rictic Sep 10, 2023
ea5bff9
Add a test of a caching consumer of an ephemeral service with files
rictic Sep 5, 2023
ba68974
Improved and clarified service caching test
rictic Sep 5, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
10 changes: 10 additions & 0 deletions CHANGELOG.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -10,6 +10,16 @@ Versioning](https://semver.org/spec/v2.0.0.html).

## [Unreleased]

### Changed

- When running in watch mode, a persistent service will now restart on each run if it does not have a `files` field in its config. This makes persistent services better match the behavior of standard scripts and ephemeral services.

### 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


- Added more "why" explanations to the `simple` and `metrics` loggers as well, including why a service was restarted, and what file change triggered a new run in watch mode.

### Fixed

- More reliably handle and report diagnostics for scripts with invalid configurations. Specifically fixed https://github.com/google/wireit/issues/803.
Expand Down
16 changes: 8 additions & 8 deletions README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -847,14 +847,14 @@ The following syntaxes can be used in the `wireit.<script>.dependencies` array:

The following environment variables affect the behavior of Wireit:

| Variable | Description |
| ----------------------- | --------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
| `WIREIT_FAILURES` | [How to handle script failures](#failures-and-errors).<br><br>Options:<br><ul><li>[`no-new`](#failures-and-errors) (default): Allow running scripts to finish, but don't start new ones.</li><li>[`continue`](#continue): Allow running scripts to continue, and start new ones unless any of their dependencies failed.</li><li>[`kill`](#kill): Immediately kill running scripts, and don't start new ones.</li></ul> |
| `WIREIT_PARALLEL` | [Maximum number of scripts to run at one time](#parallelism).<br><br>Defaults to 2×logical CPU cores.<br><br>Must be a positive integer or `infinity`. |
| `WIREIT_CACHE` | [Caching mode](#caching).<br><br>Defaults to `local` unless `CI` is `true`, in which case defaults to `none`.<br><br>Automatically set to `github` by the [`google/wireit@setup-github-actions-caching/v1`](#github-actions-caching) action.<br><br>Options:<ul><li>[`local`](#local-caching): Cache to local disk.</li><li>[`github`](#github-actions-caching): Cache to GitHub Actions.</li><li>`none`: Disable caching.</li></ul> |
| `CI` | Affects the default value of `WIREIT_CACHE`.<br><br>Automatically set to `true` by [GitHub Actions](https://docs.github.com/en/actions/learn-github-actions/environment-variables#default-environment-variables) and most other CI (continuous integration) services.<br><br>Must be exactly `true`. If unset or any other value, interpreted as `false`. |
| `WIREIT_MAX_OPEN_FILES` | Limits the number of file descriptors Wireit will have open concurrently. Prevents resource exhaustion when checking large numbers of cached files. Set to a lower number if you hit file descriptor limits. |
| `WIREIT_LOGGER` | How to present progress and results on the command line.<br><br>Options:<br><ul><li>`quiet`: writes a single dynamically updating line summarizing progress. Only passes along stdout and stderr from commands if there's a failure, or if the command is a service. The planned new default, please try it out.</li><li>`simple` (default): A verbose logger that presents clear information about the work that Wireit is doing.</li><li>`metrics`: Like `simple`, but also presents a summary table of results once a command is finished.</li><li>`quiet-ci`: like `quiet` but optimized for non-interactive environments, like GitHub Actions runners.</li></ul> |
| Variable | Description |
| ----------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
| `WIREIT_FAILURES` | [How to handle script failures](#failures-and-errors).<br><br>Options:<br><ul><li>[`no-new`](#failures-and-errors) (default): Allow running scripts to finish, but don't start new ones.</li><li>[`continue`](#continue): Allow running scripts to continue, and start new ones unless any of their dependencies failed.</li><li>[`kill`](#kill): Immediately kill running scripts, and don't start new ones.</li></ul> |
| `WIREIT_PARALLEL` | [Maximum number of scripts to run at one time](#parallelism).<br><br>Defaults to 2×logical CPU cores.<br><br>Must be a positive integer or `infinity`. |
| `WIREIT_CACHE` | [Caching mode](#caching).<br><br>Defaults to `local` unless `CI` is `true`, in which case defaults to `none`.<br><br>Automatically set to `github` by the [`google/wireit@setup-github-actions-caching/v1`](#github-actions-caching) action.<br><br>Options:<ul><li>[`local`](#local-caching): Cache to local disk.</li><li>[`github`](#github-actions-caching): Cache to GitHub Actions.</li><li>`none`: Disable caching.</li></ul> |
| `CI` | Affects the default value of `WIREIT_CACHE`.<br><br>Automatically set to `true` by [GitHub Actions](https://docs.github.com/en/actions/learn-github-actions/environment-variables#default-environment-variables) and most other CI (continuous integration) services.<br><br>Must be exactly `true`. If unset or any other value, interpreted as `false`. |
| `WIREIT_MAX_OPEN_FILES` | Limits the number of file descriptors Wireit will have open concurrently. Prevents resource exhaustion when checking large numbers of cached files. Set to a lower number if you hit file descriptor limits. |
| `WIREIT_LOGGER` | How to present progress and results on the command line.<br><br>Options:<br><ul><li>`quiet`: writes a single dynamically updating line summarizing progress. Only passes along stdout and stderr from commands if there's a failure, or if the command is a service. The planned new default, please try it out.</li><li>`simple` (default): A verbose logger that presents clear information about the work that Wireit is doing.</li><li>`metrics`: Like `simple`, but also presents a summary table of results once a command is finished.</li><li>`quiet-ci`: like `quiet` but optimized for non-interactive environments, like GitHub Actions runners.</li><li>`explain`: includes detailed information about why each script was run, and does not emit any stdout or stderr from scripts. Useful for debugging your wireit configs.</li></ul> |

### Glob patterns

Expand Down
12 changes: 9 additions & 3 deletions src/cli-options.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -58,7 +58,7 @@ export interface Options {
logger: Logger;
}

export const getOptions = (): Result<Options> => {
export const getOptions = async (): Promise<Result<Options>> => {
// This environment variable is set by npm, yarn, and pnpm, and tells us which
// script is running.
const scriptName = process.env.npm_lifecycle_event;
Expand Down Expand Up @@ -185,7 +185,7 @@ export const getOptions = (): Result<Options> => {

const agent = getNpmUserAgent();

const loggerResult = ((): Result<Logger> => {
const loggerResult = await (async (): Promise<Result<Logger>> => {
const packageRoot = packageDir ?? process.cwd();
const str = process.env['WIREIT_LOGGER'];
if (!str) {
Expand All @@ -197,6 +197,10 @@ export const getOptions = (): Result<Options> => {
if (str === 'quiet-ci') {
return {ok: true, value: new QuietCiLogger(packageRoot)};
}
if (str === 'explain') {
const {ExplainLogger} = await import('./logging/explain-logger.js');
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!

}
if (str === 'simple') {
return {ok: true, value: new DefaultLogger(packageRoot)};
}
Expand All @@ -209,7 +213,9 @@ export const getOptions = (): Result<Options> => {
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',
},
Expand Down
4 changes: 2 additions & 2 deletions src/cli.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -78,7 +78,7 @@ const run = async (options: Options): Promise<Result<void, Failure[]>> => {
options.agent,
);
process.on('SIGINT', () => {
watcher.abort();
watcher.abort('SIGINT');
});
await watcher.watch();
return {ok: true, value: undefined};
Expand Down Expand Up @@ -116,7 +116,7 @@ const run = async (options: Options): Promise<Result<void, Failure[]>> => {
}
};

const optionsResult = getOptions();
const optionsResult = await getOptions();
if (!optionsResult.ok) {
// if we can't figure out our options, we can't figure out what logger
// we should use here, so just use the default logger.
Expand Down
121 changes: 121 additions & 0 deletions src/event.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,7 @@ import type {
ScriptReference,
ScriptReferenceWithCommand,
PackageReference,
ScriptReferenceString,
} from './config.js';

/**
Expand Down Expand Up @@ -354,6 +355,8 @@ export type Info =
| OutputModified
| WatchRunStart
| WatchRunEnd
| WatchAborted
| WatchedFileTriggeredRun
| ServiceProcessStarted
| ServiceReady
| ServiceStopped
Expand All @@ -371,8 +374,82 @@ interface InfoBase<T extends PackageReference = ScriptReference>
*/
export interface ScriptRunning extends InfoBase<ScriptReferenceWithCommand> {
detail: 'running';
notFreshReason: NotFreshReason;
executionRequestedReason: ExecutionRequestedReason;
}

/**
* Answers the question "Why is this script not fresh?"
*/
export type NotFreshReason =
| {
name: 'output manifest outdated';
reason: OutputManifestOutdatedReason;
}
| 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.
Expand Down Expand Up @@ -413,15 +490,50 @@ 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.
*/
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.
*/
Expand All @@ -442,8 +554,17 @@ export interface ServiceReady extends InfoBase {
*/
export interface ServiceStopped extends InfoBase {
detail: 'service-stopped';
reason: ServiceStoppedReason;
failure: Failure | undefined;
}

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'};

/**
* An advisory event about caching.
*/
Expand Down
Loading