Separate user and machine output #1175

autoantwort · 2023-08-31T13:13:20Z

Fixes microsoft/vcpkg#33444, microsoft/vcpkg#30180 and microsoft/vcpkg#34805

I also noticed that when using depend-info and some warnings are destroying the output

BillyONeal · 2023-09-01T20:19:50Z

The current "everything goes to stdout" behavior is intended, not a bug. /cc @ras0219-msft

autoantwort · 2023-09-03T21:32:05Z

At least for the commands where it destroys the format of the output it should go to stderr :)

ras0219-msft · 2023-10-06T19:27:58Z

First, I want to agree with the problem statement that when we are issuing structured machine output, we should separate all "user messages" into stderr. Note though, this is not just when we use Color::warning or Color::error!

For example, take --x-json. The only print that we should send to stdout is the single, final write of the serialized json object (ignoring the case of streaming). Every other print statement in the entire program is a user message.

Indeed, the vcpkg codebase emits user-facing messages 99% of the time and machine structured output only in very specific circumstances. Off the top of my head:

--x-json
depend-info (inc. --dgml)
fetch
x-download (Maybe? I think the only structured output of x-download is the error code)

For the vast majority of commands, all output is user-facing output and none is considered "machine readable".

As an aside, we must note the downside of splitting output streams: you lose synchronization. For example, if we emit I'm going to load file: abc to stdout (because it's not an "error" message) and then error: file not found to stderr (because it's an "error"), you would lose synchronization between the two. This implies that all non-machine output should go to the same channel.

One way to do this would be to simply make stderr the default print channel for the entire tool (since 99% of our print calls are non-machine-readable). Then, the handful of commands above would explicitly print to stdout with their machine-readable output.

However, this makes interacting with most of the vcpkg tool more painful than it needs to be; in most cases, we intentionally would print nothing to stdout. I'm not sure what others experiences are, but I'm regularly annoyed by typing curl | less or curl | tee foo.log and then remembering that I have to curl 2>&1 | less after the pipeline fails to do what I want.

Therefore, I think the most reasonable path forward for flags such as --x-json is to switch the "default" pipe from stdout to stderr when those flags are passed. Then, those commands can explicitly issue their machine-readable calls to stdout.

I could see some future argument that says the default pipe should always be stderr, but I'd need to discuss that more.

autoantwort · 2023-10-12T13:53:01Z

Therefore, I think the most reasonable path forward for flags such as --x-json is to switch the "default" pipe from stdout to stderr when those flags are passed. Then, those commands can explicitly issue their machine-readable calls to stdout.

👍 The only downside is that this is challenging to implement the nice way, at least I have not found one. The "problem" is that there are a lot of prints before the "command selection" is done. So we have to decide which "default" pipe should be used before the normal command selection is done. I will push a solution but maybe someone has a better idea 😅

An simpler to implement solution would be to output the machine readable output to stderr, but that can also be non intuitive, but a message that says you have to redirect stderr could help.

…rint machine readable output to stdout

autoantwort · 2023-10-12T14:29:05Z

src/vcpkg/vcpkgcmdarguments.cpp

+            if (*command == "depend-info")
+            {
+                bool found = false;
+                for (const auto& arg : args.forwardable_arguments)
+                {
+                    if (found)
+                    {
+                        const auto value = Strings::ascii_to_lowercase(arg);
+                        use_stderr = value == "dot" || value == "mermaid" || value == "dgml";
+                        break;
+                    }
+                    if (Strings::case_insensitive_ascii_starts_with(arg, "--format"))
+                    {
+                        if (arg.length() > 9)
+                        {
+                            const auto value = Strings::ascii_to_lowercase(StringView(arg).substr(9));
+                            use_stderr = value == "dot" || value == "mermaid" || value == "dgml";
+                            break;
+                        }
+                        found = true;
+                    }
+                }
+            }
        }

-        args.forwardable_arguments = args.parser.get_remaining_args();
+        if (use_stderr)
+        {
+            msg::set_default_output_stream(OutputStream::StdErr);
+        }


The ugly hack is here. But this now also works with vcpkg depend-info 'pcl[core,visualization]' --forMat=dOt --debug > test.dot

BillyONeal · 2023-10-21T01:40:38Z

src/vcpkg/vcpkgcmdarguments.cpp

@@ -388,16 +388,44 @@ namespace vcpkg
        if (const auto p = args.debug_env.get()) args.debug = *p;

        auto maybe_command = args.parser.extract_first_command_like_arg_lowercase();
+        args.forwardable_arguments = args.parser.get_remaining_args();
+        bool use_stderr = Util::contains(args.forwardable_arguments, "--x-json");


Instead of hard coding stuff like this, can we add a field to CommandMetadata that controls the setting?

Alternately, can we just do it at the top of the command function in question instead?

The problem then it is too late. There are Debug print statements before a command is selected.

For example here:

vcpkg-tool/src/vcpkg.cpp

Lines 279 to 292 in e658895

VcpkgCmdArguments args = VcpkgCmdArguments::create_from_command_line(real_filesystem, argc, argv);

if (const auto p = args.debug.get()) Debug::g_debugging = *p;

args.imbue_from_environment();

VcpkgCmdArguments::imbue_or_apply_process_recursion(args);

if (const auto p = args.debug_env.get(); p && *p)

{

msg::write_unlocalized_text_to_stdout(Color::none,

"[DEBUG] The following environment variables are currently set:\n" +

get_environment_variables() + '\n');

}

else if (Debug::g_debugging)

{

Debug::println("To include the environment variables in debug output, pass --debug-env");

}

After line 283 we already have to know it output should go to stderr or stdout

But one could argue that we don't care if debug output breaks things

I would like to resolve those as 'debug output always goes to stderr' and 'console parse failures always go to stderr' on the grounds that neither of those types of output should apply to the edge cases @ras0219-msft enumerated above; I'm asking around and will keep you posted.

BillyONeal · 2023-10-21T01:42:30Z

I could see some future argument that says the default pipe should always be stderr, but I'd need to discuss that more.

I think it would be good if console parse errors go directly to stderr too. In that case we generally don't expect the program to continue so synchronization issues and concerns about accidentally causing pipelines to fail should not be concerns.

BillyONeal · 2023-10-25T00:01:45Z

@AugP @vicroms @JavierMatosD @data-queue @ras0219-msft and I discussed this today and agreed with the following outcomes:

We disagree with @BillyONeal 's proposal to send all debug output to stderr, but we agree that we don't mind if it is written inconsistently.
We agree with @BillyONeal 's proposal that all console parse failure messages should go to stderr in order to avoid the 'parse time machine' problem.

Do you mind if I morally take over this PR and make those changes?

autoantwort · 2023-10-25T00:03:44Z

Do you mind if I morally take over this PR and make those changes?

No you can do that :)

…s-to-stderr # Conflicts: # src/vcpkg/commands.build.cpp # src/vcpkg/commands.ci-verify-versions.cpp # src/vcpkg/paragraphs.cpp

…ding to solve a time machine problem. Audit all commands which say 'x-json' and assign their output to stdout or stderr as appropriate.

BillyONeal · 2023-11-28T02:02:07Z

@autoantwort Can you confirm you are happy with the changes I just pushed?

autoantwort · 2023-11-28T22:20:39Z

Seems that something is not working:

Maybe we also need e2e tests

autoantwort · 2023-11-28T22:22:43Z

@BillyONeal Maybe this warning also must go to stderr by default

autoantwort · 2023-11-28T22:26:54Z

Also

BillyONeal · 2023-11-29T02:42:23Z

@BillyONeal Maybe this warning also must go to stderr by default

I agree.

Also

Hmmm I thought I got that one? Let me check again...

BillyONeal · 2023-11-29T03:58:10Z

Ah the sendmetrics one is in vcpkg.cpp rather than vcpkgcmdarguments.cpp

BillyONeal · 2023-11-29T05:03:53Z

OK please check again

autoantwort · 2023-11-29T12:19:49Z

I don't know if we want to support that, but

autoantwort · 2023-11-29T12:24:03Z

src/vcpkg/commands.z-preregister-telemetry.cpp

+            msg::write_unlocalized_text_to_stderr(
+                Color::warning,
+                LocalizedString::from_raw(WarningPrefix).append(msgVcpkgSendMetricsButDisabled).append_raw('\n'));


Maybe
stderr_sink.println_warnin

Suggested change

msg::write_unlocalized_text_to_stderr(

Color::warning,

LocalizedString::from_raw(WarningPrefix).append(msgVcpkgSendMetricsButDisabled).append_raw('\n'));

stderr_sink.println_warning(msgVcpkgSendMetricsButDisabled);

I don't want to introduce use of the sinks where the polymorphism is not needed right now but I could see an argument in the future that all console output should be polymorphic like this. (But that seems way outside the scope of this PR)

…s-to-stderr # Conflicts: # src/vcpkg/commands.owns.cpp

BillyONeal · 2023-12-11T19:01:44Z

Thanks!

Make it possible to redirect output to stderr. depend-info now only p…

149b1bc

…rint machine readable output to stdout

autoantwort force-pushed the feature/warning-errors-to-stderr branch from 2d92048 to 149b1bc Compare October 12, 2023 14:27

autoantwort commented Oct 12, 2023

View reviewed changes

autoantwort changed the title ~~Print warnings and errors on stderr~~ Separate user and machine output Oct 12, 2023

BillyONeal reviewed Oct 21, 2023

View reviewed changes

autoantwort mentioned this pull request Oct 30, 2023

Request: write WaitingToTakeFilesystemLock output for vcpkg-tool to stderr not stdout microsoft/vcpkg#34805

Closed

BillyONeal added 2 commits November 27, 2023 16:30

Merge remote-tracking branch 'origin/main' into feature/warning-error…

e8b7b4c

…s-to-stderr # Conflicts: # src/vcpkg/commands.build.cpp # src/vcpkg/commands.ci-verify-versions.cpp # src/vcpkg/paragraphs.cpp

Explicitly write console parse messages always to stderr to avoid nee…

bb92b6b

…ding to solve a time machine problem. Audit all commands which say 'x-json' and assign their output to stdout or stderr as appropriate.

BillyONeal approved these changes Nov 28, 2023

View reviewed changes

Changed several more prerun errors to go to stderr.

ff369af

autoantwort commented Nov 29, 2023

View reviewed changes

BillyONeal added 2 commits December 5, 2023 13:21

Merge remote-tracking branch 'origin/main' into feature/warning-error…

a0e08e6

…s-to-stderr # Conflicts: # src/vcpkg/commands.owns.cpp

Redirect filesystem lock message to stderr.

05ef8de

BillyONeal merged commit c1b70fb into microsoft:main Dec 11, 2023
5 checks passed

autoantwort deleted the feature/warning-errors-to-stderr branch December 11, 2023 19:03

BillyONeal mentioned this pull request Dec 20, 2023

Don't format options table like errors #1306

Merged

SunBlack mentioned this pull request Jan 5, 2024

[vcpkg] Passing --dgml should suppress warnings (on stdout) microsoft/vcpkg#30180

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Separate user and machine output #1175

Separate user and machine output #1175

autoantwort commented Aug 31, 2023 •

edited

Loading

BillyONeal commented Sep 1, 2023

autoantwort commented Sep 3, 2023 •

edited

Loading

ras0219-msft commented Oct 6, 2023 •

edited

Loading

autoantwort commented Oct 12, 2023 •

edited

Loading

autoantwort Oct 12, 2023

BillyONeal Oct 21, 2023

autoantwort Oct 21, 2023

autoantwort Oct 21, 2023

autoantwort Oct 21, 2023

BillyONeal Oct 23, 2023

BillyONeal commented Oct 21, 2023

BillyONeal commented Oct 25, 2023

autoantwort commented Oct 25, 2023

BillyONeal commented Nov 28, 2023

autoantwort commented Nov 28, 2023

autoantwort commented Nov 28, 2023

autoantwort commented Nov 28, 2023

BillyONeal commented Nov 29, 2023

BillyONeal commented Nov 29, 2023

BillyONeal commented Nov 29, 2023

autoantwort commented Nov 29, 2023

autoantwort Nov 29, 2023

BillyONeal Dec 5, 2023

BillyONeal commented Dec 11, 2023

	VcpkgCmdArguments args = VcpkgCmdArguments::create_from_command_line(real_filesystem, argc, argv);
	if (const auto p = args.debug.get()) Debug::g_debugging = *p;
	args.imbue_from_environment();
	VcpkgCmdArguments::imbue_or_apply_process_recursion(args);
	if (const auto p = args.debug_env.get(); p && *p)
	{
	msg::write_unlocalized_text_to_stdout(Color::none,
	"[DEBUG] The following environment variables are currently set:\n" +
	get_environment_variables() + '\n');
	}
	else if (Debug::g_debugging)
	{
	Debug::println("To include the environment variables in debug output, pass --debug-env");
	}

Separate user and machine output #1175

Separate user and machine output #1175

Conversation

autoantwort commented Aug 31, 2023 • edited Loading

BillyONeal commented Sep 1, 2023

autoantwort commented Sep 3, 2023 • edited Loading

ras0219-msft commented Oct 6, 2023 • edited Loading

autoantwort commented Oct 12, 2023 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

BillyONeal commented Oct 21, 2023

BillyONeal commented Oct 25, 2023

autoantwort commented Oct 25, 2023

BillyONeal commented Nov 28, 2023

autoantwort commented Nov 28, 2023

autoantwort commented Nov 28, 2023

autoantwort commented Nov 28, 2023

BillyONeal commented Nov 29, 2023

BillyONeal commented Nov 29, 2023

BillyONeal commented Nov 29, 2023

autoantwort commented Nov 29, 2023

Choose a reason for hiding this comment

Choose a reason for hiding this comment

BillyONeal commented Dec 11, 2023

autoantwort commented Aug 31, 2023 •

edited

Loading

autoantwort commented Sep 3, 2023 •

edited

Loading

ras0219-msft commented Oct 6, 2023 •

edited

Loading

autoantwort commented Oct 12, 2023 •

edited

Loading