Skip to content

Commit

Permalink
Improved error reporting for unexpected output file deletion (#1270)
Browse files Browse the repository at this point in the history 
## Background

Before and after execution of a script, wireit globs and stats the output files in order to remember them across runs. If some process is simultaneously writing to the same output files out-of-band, it is possible for an output file to be deleted in the small amount of time between globbing it and stat'ing it.

Before this PR, this situation was not detected, and just resulted in an unknown exception, which we log as an "Internal error".

## Main change

After this PR, this situation is specifically detected, and we give a more useful error:

```
[foo] Output file "./some/file.js" was deleted unexpectedly. Is another process writing to the same location?
```

## Other changes

- When an unhandled exception occurs, we now report it with the name of the specific script that failed, instead of with the top-level entry-point script (by catching unknown exceptions on individual script executions, instead of only at the very top-level as before).

- Added a test for the similar case where an *input* file is deleted during fingerprinting, and tweaked the error message to suggest that another process might be the cause.

- Clarified the default logger vs the simple logger in the README and class names (the default changed from simple to quiet recently, but the README and class names were not quite in sync).

- Document the `WIREIT_DEBUG_LOG_FILE` variable.
  • Loading branch information
@aomarks
aomarks authored Jan 28, 2025
1 parent 2948121 commit b671bc9
Show file tree
Hide file tree
Showing 15 changed files with 255 additions and 54 deletions.
6 changes: 6 additions & 0 deletions CHANGELOG.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -13,6 +13,12 @@ Versioning](https://semver.org/spec/v2.0.0.html).
- Fix a bug that may have resulted in Wireit attempting to open too many files
at once (no known reports).

- When an unexpected error occurs, the specific script that failed is now
reported by the logger, instead of the less-useful entry-point script.

- When an output file is deleted during output manifest generation, a more
useful error message is reported instead of an unexpected error.

## [0.14.9] - 2024-09-03

### Added
Expand Down
21 changes: 11 additions & 10 deletions README.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -877,16 +877,17 @@ The following syntaxes can be used in the `wireit.<script>.dependencies` array:

The following environment variables affect the behavior of Wireit:

| Variable | Description |
| ----------------------- | ---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
| `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/v2`](#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> |
| `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_LOGGER` | How to present progress and results on the command line.<br><br>Options:<br><ul><li>`quiet` (default): 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` (default when env.CI or !stdout.isTTY): like `quiet` but optimized for non-interactive environments, like GitHub Actions runners.</li></ul> |
| `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_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_WATCH_STRATEGY` | How Wireit determines when a file has changed which warrants a new watch iteration.<br><br>Options:<br><ul><li>`event` (default): Register OS file system watcher callbacks (using [chokidar](https://github.com/paulmillr/chokidar)).</li><li>`poll`: Poll the filesystem every `WIREIT_WATCH_POLL_MS` milliseconds. Less responsive and worse performance than `event`, but a good fallback for when `event` does not work well or at all (e.g. filesystems that don't support filesystem events, or performance and memory problems with large file trees).</li></ul> |
| `WIREIT_WATCH_POLL_MS` | When `WIREIT_WATCH_STRATEGY` is `poll`, how many milliseconds to wait between each filesystem poll. Defaults to `500`. |
| `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`. |
| Variable | Description |
| ----------------------- | ----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------- |
| `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/v2`](#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> |
| `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_LOGGER` | How to present progress and results on the command line.<br><br>Options:<br><ul><li>`quiet` (default for normal execution): 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.</li><li>`quiet-ci` (default when `env.CI` or `!stdout.isTTY`): like `quiet` but optimized for non-interactive environments, like GitHub Actions runners.</li><li>`simple`: 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></ul> |
| `WIREIT_DEBUG_LOG_FILE` | Path to a file which will receive detailed event logging. |
| `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_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_WATCH_STRATEGY` | How Wireit determines when a file has changed which warrants a new watch iteration.<br><br>Options:<br><ul><li>`event` (default): Register OS file system watcher callbacks (using [chokidar](https://github.com/paulmillr/chokidar)).</li><li>`poll`: Poll the filesystem every `WIREIT_WATCH_POLL_MS` milliseconds. Less responsive and worse performance than `event`, but a good fallback for when `event` does not work well or at all (e.g. filesystems that don't support filesystem events, or performance and memory problems with large file trees).</li></ul> |
| `WIREIT_WATCH_POLL_MS` | When `WIREIT_WATCH_STRATEGY` is `poll`, how many milliseconds to wait between each filesystem poll. Defaults to `500`. |
| `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`. |

### Glob patterns

Expand Down
4 changes: 2 additions & 2 deletions src/cli-options.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,7 @@ import * as pathlib from 'path';
import {ScriptReference} from './config.js';
import {Result} from './error.js';
import {FailureMode} from './executor.js';
import {DefaultLogger} from './logging/default-logger.js';
import {SimpleLogger} from './logging/simple-logger.js';
import {Console, Logger} from './logging/logger.js';
import {MetricsLogger} from './logging/metrics-logger.js';
import {QuietCiLogger, QuietLogger} from './logging/quiet-logger.js';
Expand Down Expand Up @@ -204,7 +204,7 @@ export const getOptions = async (): Promise<Result<Options>> => {
return {ok: true, value: new QuietCiLogger(packageRoot, console)};
}
if (str === 'simple') {
return {ok: true, value: new DefaultLogger(packageRoot, console)};
return {ok: true, value: new SimpleLogger(packageRoot, console)};
}
if (str === 'metrics') {
return {ok: true, value: new MetricsLogger(packageRoot, console)};
Expand Down
4 changes: 2 additions & 2 deletions src/cli.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -9,7 +9,7 @@ import {getOptions, Options, packageDir} from './cli-options.js';
import {Result} from './error.js';
import {Failure} from './event.js';
import {Executor} from './executor.js';
import {DefaultLogger} from './logging/default-logger.js';
import {SimpleLogger} from './logging/simple-logger.js';
import {Console} from './logging/logger.js';
import {unreachable} from './util/unreachable.js';
import {WorkerPool} from './util/worker-pool.js';
Expand Down Expand Up @@ -118,7 +118,7 @@ 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.
const console = new Console(process.stderr, process.stderr);
const logger = new DefaultLogger(packageDir ?? process.cwd(), console);
const logger = new SimpleLogger(packageDir ?? process.cwd(), console);
logger.log(optionsResult.error);
process.exit(1);
}
Expand Down
22 changes: 17 additions & 5 deletions src/event.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -101,7 +101,8 @@ export type Failure =
| ServiceExitedUnexpectedly
| DependencyServiceExitedUnexpectedly
| Aborted
| FilesDeletedDuringFingerprinting;
| InputFileDeletedUnexpectedly
| OutputFileDeletedUnexpectedly;

interface ErrorBase<T extends PackageReference = ScriptReference>
extends EventBase<T> {
Expand Down Expand Up @@ -283,11 +284,22 @@ export interface Aborted extends ErrorBase {
}

/**
* A file was deleting after globbing but before fingerprinting and
* was unable to be read.
* One or more input files were deleted very unexpectedly, e.g. between globbing
* and fingerprinting, indicating that an out-of-band process is modifying the
* same input location.
*/
export interface FilesDeletedDuringFingerprinting extends ErrorBase {
reason: 'files-deleted-during-fingerprinting';
export interface InputFileDeletedUnexpectedly extends ErrorBase {
reason: 'input-file-deleted-unexpectedly';
filePaths: string[];
}

/**
* One or more output files were deleted very unexpectedly, e.g. between
* globbing and generating an output manifest, indicating that an out-of-band
* process is modifying the same output location.
*/
export interface OutputFileDeletedUnexpectedly extends ErrorBase {
reason: 'output-file-deleted-unexpectedly';
filePaths: string[];
}

Expand Down
10 changes: 7 additions & 3 deletions src/execution/base.ts
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,7 +8,7 @@ import {shuffle} from '../util/shuffle.js';
import {Fingerprint} from '../fingerprint.js';
import {Deferred} from '../util/deferred.js';

import type {Result} from '../error.js';
import {convertExceptionToFailure, type Result} from '../error.js';
import type {Executor} from '../executor.js';
import type {Dependency, ScriptConfig} from '../config.js';
import type {Logger} from '../logging/logger.js';
Expand Down Expand Up @@ -60,8 +60,12 @@ export abstract class BaseExecution<T extends ScriptConfig> {
* Execute this script and return its fingerprint. Cached, so safe to call
* multiple times.
*/
execute(): Promise<ExecutionResult> {
return (this.#fingerprint ??= this._execute());
async execute(): Promise<ExecutionResult> {
try {
return await (this.#fingerprint ??= this._execute());
} catch (error) {
return convertExceptionToFailure(error, this._config);
}
}

protected abstract _execute(): Promise<ExecutionResult>;
Expand Down
Loading

0 comments on commit b671bc9

Please sign in to comment.