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 prefix output #975

Open
wants to merge 3 commits into
base: main
Choose a base branch
from
Open

Add prefix output #975

Show file tree
Hide file tree
Changes from 2 commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
f065cfc
add prefix in logger
sirenkovladd Nov 20, 2023
9f7e577
add readme
sirenkovladd Nov 20, 2023
a8612cd
Update README.md
sirenkovladd Jan 5, 2024
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
1 change: 1 addition & 0 deletions README.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -855,6 +855,7 @@ The following environment variables affect the behavior of Wireit:
| `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` (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_LOGGER_PREFIX` | Prefix each stdout and stderr line from the script|
sirenkovladd marked this conversation as resolved.
Show resolved Hide resolved

### Glob patterns

Expand Down
17 changes: 14 additions & 3 deletions src/logging/default-logger.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,7 @@
import * as pathlib from 'path';
import {unreachable} from '../util/unreachable.js';

import type {Event} from '../event.js';
import type {Event, Stderr, Stdout} from '../event.js';
import type {Logger, Console} from './logger.js';
import {type PackageReference, type ScriptReference} from '../config.js';
import {DiagnosticPrinter} from '../error.js';
Expand Down Expand Up @@ -42,6 +42,8 @@ export class DefaultLogger implements Logger {
readonly console: Console;
readonly #diagnosticPrinter: DiagnosticPrinter;

private outputWrite: typeof DefaultLogger.prototype.outputWriteDebug;

/**
* @param rootPackage The npm package directory that the root script being
* executed belongs to.
Expand All @@ -50,6 +52,15 @@ export class DefaultLogger implements Logger {
this.#rootPackageDir = rootPackage;
this.#diagnosticPrinter = new DiagnosticPrinter(this.#rootPackageDir);
this.console = ourConsole;
this.outputWrite = process.env['WIREIT_LOGGER_PREFIX'] ? this.outputWriteDebug : this.outputWriteDefault;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Let's put this logic on our Console class as a new method that takes an output event and writes it out to the proper underlying stream, using the presence / absence of the env variable to determine whether to use the prefix. That way the implementation lives in a single place.

}

private outputWriteDefault(this: void, stream: NodeJS.WritableStream, event: Stdout | Stderr) {
stream.write(event.data);
}

private outputWriteDebug(this: void, stream: NodeJS.WritableStream, event: Stdout | Stderr, label: string) {
stream.write(event.data.toString().split('\n').map(line => line.trim() ? `[${label}] ${line}` : line).join('\n'));
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This isn't quite right, because output events don't have to map cleanly onto lines. For example, you could have a program that logs "abc" with a pause between each letter. What we want to log here is:

[scriptname] abc

But as you've written this, I believe wireit would log:

[scriptname] a
[scriptname] b
[scriptname] c

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It doesn't seem to work in the current version
https://stackblitz.com/edit/stackblitz-starters-eweown

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah, that looks like a bug as well

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yes indeed, but even if it worked (I can send a PR after the discussion), what should be output in the example I posted

I see two possible options, or output what is sent

daefbq
decfq
q
deafq
dbefcq

or save the line until I get a transition to a new line (which is, of course, a bad option, since the user needs an answer immediately, and not waiting for the end of the line)

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I see what you mean. Looking into it our options a bit:

  1. We could implement a full TUI and render a separate window for each server, each with its own scrollback. I'd like to explore this for Wireit anyways longer term, as this would let us do some other interesting things at the UI level. However, that'd involve bringing in at least one sizeable new dependency, and likely a lot of additional code. Not in scope for a small change, and potentially not even something we're willing to maintain as part of Wireit.
  2. We could use ANSI escape codes to update previous lines. In theory, this would be ideal, letting us have multiple servers all writing at the same time without stepping on each others' lines, and the complexity and overhead would be manageable (just need to track newlines written, and characters written per line), but unfortunately ANSI control is based on window position, not terminal output position. So you can only modify lines that are up to N lines back in the scrollback, where N is the height of the user's terminal window.
  3. We could remember whether the previously write was by a server and didn't end in a newline, and if so, only create a newline if the next write is by something other than that server. This seems like a good trade off of correctness vs complexity.

With strategy 3, the output of your example would be:

[process1] a
[process2] de
[process1] b
[process2] fq
[process2] d
[process1] c
[process2] ef
[process1] q
<... and so on>

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is super necessary feature for complex service dependency chains. And it looks like this PR has stalled due to the complexity of correctly handling this relatively rare scenario. Couldn't we just add a caveat in the documentation for the env variable letting users know about the effect that would have on their log output? For dev tools, the correctness requirements are often less stringent. For example, the wildly popular npm-run-all package has a printLabels option that actually stops colorizing output. See https://github.com/mysticatea/npm-run-all/blob/master/docs/npm-run-all.md#known-limitations.

I think this feature is too important to delay for this reason.

}

log(event: Event) {
Expand Down Expand Up @@ -222,11 +233,11 @@ export class DefaultLogger implements Logger {
// TODO(aomarks) More advanced handling of output streams so that
// output isn't simply interweaved.
case 'stdout': {
this.console.stdout.write(event.data);
this.outputWrite(this.console.stdout, event, label);
break;
}
case 'stderr': {
this.console.stderr.write(event.data);
this.outputWrite(this.console.stderr, event, label);
break;
}
}
Expand Down
11 changes: 9 additions & 2 deletions src/logging/quiet/run-tracker.ts
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -600,6 +600,13 @@ export class QuietRunLogger implements Disposable {
return state.hasBufferedOutput;
}

private outputWrite = process.env['WIREIT_LOGGER_PREFIX'] ? (stream: NodeJS.WritableStream, output: Output) => {
const label = labelForScript(this.#rootPackage, output.script);
stream.write(output.data.toString().split('\n').map(line => line.trim() ? `[${label}] ${line}` : line).join('\n'));
} : (stream: NodeJS.WritableStream, output: Output) => {
stream.write(output.data);
}

#handleOutput(event: Output): StatusLineResult {
const key = scriptReferenceToString(event.script);
const state = this.#running.get(key);
Expand All @@ -618,9 +625,9 @@ export class QuietRunLogger implements Disposable {
// eslint-disable-next-line @typescript-eslint/no-unused-vars
using _pause = this.#statusLineWriter.clearUntilDisposed();
if (event.stream === 'stdout') {
process.stdout.write(event.data);
this.outputWrite(process.stdout, event);
} else {
process.stderr.write(event.data);
this.outputWrite(process.stderr, event);
}
return noChange;
}
Expand Down