Repository: sindresorhus/execa (js)

Issue:
Verbose mode
## Problem

Projects with many processes or with complex process orchestration (parallel runs, deep/grand-child processes, etc.) can be hard to debug. This is a common pain point in terms of developer experience when working with processes.

This is mostly a problem when executing processes programmatically. In an interactive shell, users run commands one-by-one, can see the history of previous commands by scrolling up, and can see each command being input.

Also, some users of the new `$` API might expect opting in to a shell-like experience in that regard.

## Prior art

A common solution to this problem is to add a verbose mode. Examples include:
  - `bash -x` or `bash -v`
  - `zx` [`verbose` option](https://github.com/google/zx/#verbose)
  - Many build tools like `gulp` print each command being executed

## Solution

Add a `verbose` boolean option to Execa. When `true`, each command is printed before being executed: 
  - `"$ "` would be prepended
  - The command would be escaped like [`escapedCommand`](https://github.com/sindresorhus/execa#escapedcommand) using the [already existing quoting logic](https://github.com/sindresorhus/execa/blob/eae327cc0a49f61b17f699b9199c7953e1497c1a/lib/command.js#L12)

### Default value

Verbosity is mostly meant for debugging, i.e. it should be `false` by default. For example, `zx` currently defaults it `true` but is actually [reverting to `false`](https://github.com/google/zx/issues/569) in their next major release.

### stderr

The verbose mode prints to `stderr`, to separate from the command's normal output (`stdout`), which might be piped to another process or stream.

### NODE_DEBUG

When executing many commands and nesting them, it might be helpful to use an environment variable to set the verbose mode. We could use the core Node.js method [`debuglog()`](https://nodejs.org/api/util.html#utildebuglogsection-callback) for this purpose. Users would then use the `NODE_DEBUG=execa` environment variable.

### Errors

We can expect process failures to throw an exception which would either crash the process then logged, or be handled then logged. Therefore, we do not need to do anything there.

If the [`reject` option](https://github.com/sindresorhus/execa/blob/main/readme.md#reject) is `true`, the user indicates that process failure might be expected. In that case, we would let users print any information they want for debugging.

### Durations

Knowing how long a process took is useful for debugging. Many tools do this, e.g. Gulp.

However, it also comes with some cons. It might unnecessarily too verbose, by adding an additional line for every successful command. Also, when running commands in parallel, it might be hard to know which command ended without labeling or numbering them.

One potential solution would be to timestamp each command as they start, instead of printing their duration as they end. For example, instead of prepending `$ ` to each command, prepending `[HH:mm:ss.sss] `. Printing the date and timezone might not be useful for that purpose, i.e. could be left out.

### Colors

We might want (or not?) using colors. If we do, would the `FORCE_COLOR` environment variable be enough, or would this require a separate `colors` boolean option?

### Stdout/stderr

The verbose mode would not print stdout and stderr to avoid printing it twice. This is because `execa()` cannot know whether the user will `childProcess.stdout.pipe(process.stdout)` after execution. The same applies to failed commands.

Also, this makes the verbose mode more concise, yet still helpful. 

---

While this issue is detailed, the implementation could be rather small, and with a limited API surface (one boolean option), while still significantly improving debugging child processes.

What do you think @sindresorhus?

Pull request:
Add "verbose" option
Fixes #524.

This adds a `verbose` boolean option. It defaults to `false`, unless the [`NODE_DEBUG=execa` environment variable](https://nodejs.org/api/util.html#debuglogenabled) is set. When enabled, it prints any command before executing it. It also prints a timestamp.

The "problem" and "prior art" sections in #524 give some background on why this feature might be a good addition.

For example, the following script:

```js
import {$} from 'execa'

await $`echo one`
await $`echo two`
```

Would print:

```
$ node example.js

$ NODE_DEBUG=execa node example.js
[22:44:57.723] echo one
[22:44:57.731] echo two
```

While the following:

```js
import {$} from 'execa'

const $$ = $({ stdio: 'inherit' })

await $$`echo one`
await $$`echo two`
```

Would print:

```
$ node example.js
one
two

$ NODE_DEBUG=execa node example.js
[22:47:52.056] echo one
one
[22:47:52.060] echo two
two
```

This can also be enabled for individual commands with:

```js
await $({ verbose: true })`echo one`
```

This feature works with any other Execa method too.

```js
await execa('echo', ['one'], { verbose: true })
```

The PR's code and tests are done, but I haven't added the types, type tests nor readme documentation. I'd like to first confirm the overall idea and design make sense to you @sindresorhus. :)

Patch:
diff --git a/index.d.ts b/index.d.ts
index b5a681a..83c1727 100644
--- a/index.d.ts
+++ b/index.d.ts
@@ -244,6 +244,15 @@ export type CommonOptions<EncodingType> = {
 	@default true
 	*/
 	readonly windowsHide?: boolean;
+
+	/**
+	Print each command on `stderr` before executing it.
+
+	This can also be enabled by setting the `NODE_DEBUG=execa` environment variable in the current process.
+
+	@default false
+	*/
+	readonly verbose?: boolean;
 };
 
 export type Options<EncodingType = string> = {
diff --git a/index.js b/index.js
index bd49574..5c6ac50 100644
--- a/index.js
+++ b/index.js
@@ -12,6 +12,7 @@ import {spawnedKill, spawnedCancel, setupTimeout, validateTimeout, setExitHandle
 import {handleInput, getSpawnedResult, makeAllStream, validateInputSync} from './lib/stream.js';
 import {mergePromise, getSpawnedPromise} from './lib/promise.js';
 import {joinCommand, parseCommand, parseTemplates, getEscapedCommand} from './lib/command.js';
+import {logCommand, verboseDefault} from './lib/verbose.js';
 
 const DEFAULT_MAX_BUFFER = 1000 * 1000 * 100;
 
@@ -44,6 +45,7 @@ const handleArguments = (file, args, options = {}) => {
 		cleanup: true,
 		all: false,
 		windowsHide: true,
+		verbose: verboseDefault,
 		...options,
 	};
 
@@ -76,6 +78,7 @@ export function execa(file, args, options) {
 	const parsed = handleArguments(file, args, options);
 	const command = joinCommand(file, args);
 	const escapedCommand = getEscapedCommand(file, args);
+	logCommand(escapedCommand, parsed.options);
 
 	validateTimeout(parsed.options);
 
@@ -165,6 +168,7 @@ export function execaSync(file, args, options) {
 	const parsed = handleArguments(file, args, options);
 	const command = joinCommand(file, args);
 	const escapedCommand = getEscapedCommand(file, args);
+	logCommand(escapedCommand, parsed.options);
 
 	validateInputSync(parsed.options);
 
diff --git a/lib/verbose.js b/lib/verbose.js
new file mode 100644
index 0000000..5f5490e
--- /dev/null
+++ b/lib/verbose.js
@@ -0,0 +1,19 @@
+import {debuglog} from 'node:util';
+import process from 'node:process';
+
+export const verboseDefault = debuglog('execa').enabled;
+
+const padField = (field, padding) => String(field).padStart(padding, '0');
+
+const getTimestamp = () => {
+	const date = new Date();
+	return `${padField(date.getHours(), 2)}:${padField(date.getMinutes(), 2)}:${padField(date.getSeconds(), 2)}.${padField(date.getMilliseconds(), 3)}`;
+};
+
+export const logCommand = (escapedCommand, {verbose}) => {
+	if (!verbose) {
+		return;
+	}
+
+	process.stderr.write(`[${getTimestamp()}] ${escapedCommand}\n`);
+};
diff --git a/readme.md b/readme.md
index 09bfe67..69aa9ea 100644
--- a/readme.md
+++ b/readme.md
@@ -101,6 +101,20 @@ $({stdio: 'inherit'}).sync`echo ${unicorns} rainbows`;
 //=> 'unicorns rainbows'
 ```
 
+#### Verbose mode
+
+```sh
+> node file.js
+unicorns
+rainbows
+
+> NODE_DEBUG=execa node file.js
+[16:50:03.305] echo unicorns
+unicorns
+[16:50:03.308] echo rainbows
+rainbows
+```
+
 ### Pipe the child process stdout to the parent
 
 ```js
@@ -652,6 +666,15 @@ Default: `true`
 
 On Windows, do not create a new console window. Please note this also prevents `CTRL-C` [from working](https://github.com/nodejs/node/issues/29837) on Windows.
 
+#### verbose
+
+Type: `boolean`\
+Default: `false`
+
+[Print each command](#verbose-mode) on `stderr` before executing it.
+
+This can also be enabled by setting the `NODE_DEBUG=execa` environment variable in the current process.
+
 #### nodePath *(For `.node()` only)*
 
 Type: `string`\


Test patch:
diff --git a/index.test-d.ts b/index.test-d.ts
index a2a6d21..17b383f 100644
--- a/index.test-d.ts
+++ b/index.test-d.ts
@@ -150,6 +150,7 @@ execa('unicorns', {killSignal: 9});
 execa('unicorns', {signal: new AbortController().signal});
 execa('unicorns', {windowsVerbatimArguments: true});
 execa('unicorns', {windowsHide: false});
+execa('unicorns', {verbose: false});
 /* eslint-enable @typescript-eslint/no-floating-promises */
 execa('unicorns').kill();
 execa('unicorns').kill('SIGKILL');
diff --git a/test/fixtures/nested.js b/test/fixtures/nested.js
new file mode 100755
index 0000000..5e329af
--- /dev/null
+++ b/test/fixtures/nested.js
@@ -0,0 +1,7 @@
+#!/usr/bin/env node
+import process from 'node:process';
+import {execa} from '../../index.js';
+
+const [options, file, ...args] = process.argv.slice(2);
+const nestedOptions = {stdio: 'inherit', ...JSON.parse(options)};
+await execa(file, args, nestedOptions);
diff --git a/test/fixtures/verbose-script.js b/test/fixtures/verbose-script.js
new file mode 100755
index 0000000..c242074
--- /dev/null
+++ b/test/fixtures/verbose-script.js
@@ -0,0 +1,6 @@
+#!/usr/bin/env node
+import {$} from '../../index.js';
+
+const $$ = $({stdio: 'inherit'});
+await $$`node -p "one"`;
+await $$`node -p "two"`;
diff --git a/test/verbose.js b/test/verbose.js
new file mode 100644
index 0000000..fa0a605
--- /dev/null
+++ b/test/verbose.js
@@ -0,0 +1,35 @@
+import test from 'ava';
+import {execa} from '../index.js';
+import {setFixtureDir} from './helpers/fixtures-dir.js';
+
+setFixtureDir();
+
+const normalizeTimestamp = output => output.replace(/\d/g, '0');
+const testTimestamp = '[00:00:00.000]';
+
+test('Prints command when "verbose" is true', async t => {
+	const {stdout, stderr, all} = await execa('nested.js', [JSON.stringify({verbose: true}), 'noop.js', 'test'], {all: true});
+	t.is(stdout, 'test');
+	t.is(normalizeTimestamp(stderr), `${testTimestamp} noop.js test`);
+	t.is(normalizeTimestamp(all), `${testTimestamp} noop.js test\ntest`);
+});
+
+test('Prints command with NODE_DEBUG=execa', async t => {
+	const {stdout, stderr, all} = await execa('nested.js', [JSON.stringify({}), 'noop.js', 'test'], {all: true, env: {NODE_DEBUG: 'execa'}});
+	t.is(stdout, 'test');
+	t.is(normalizeTimestamp(stderr), `${testTimestamp} noop.js test`);
+	t.is(normalizeTimestamp(all), `${testTimestamp} noop.js test\ntest`);
+});
+
+test('Escape verbose command', async t => {
+	const {stderr} = await execa('nested.js', [JSON.stringify({verbose: true}), 'noop.js', 'one two', '"'], {all: true});
+	t.true(stderr.endsWith('"one two" "\\""'));
+});
+
+test('Verbose option works with inherit', async t => {
+	const {all} = await execa('verbose-script.js', {all: true, env: {NODE_DEBUG: 'execa'}});
+	t.is(normalizeTimestamp(all), `${testTimestamp} node -p "\\"one\\""
+one
+${testTimestamp} node -p "\\"two\\""
+two`);
+});