[RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Eric Sunshine]

The order in which the stdout and stderr streams are flushed is not
guaranteed to be the same across platforms or `libc` implementations.
This lack of determinism can lead to anomalous and potentially confusing
output if normal (stdout) output is flushed after error (stderr) output.
For instance, the following output which clearly indicates a failure due
to a fatal error:

    % git worktree add ../foo bar
    Preparing worktree (checking out 'bar')
    fatal: 'bar' is already checked out at '.../wherever'

has been reported[1] on Microsoft Windows to appear as:

    % git worktree add ../foo bar
    fatal: 'bar' is already checked out at '.../wherever'
    Preparing worktree (checking out 'bar')

which may confuse the reader into thinking that the command somehow
recovered and ran to completion despite the error.

Rather than attempting to address this issue on a case by case basis,
address it by making vreportf() -- which is the heart of error-reporting
functions die(), error(), warn(), etc. -- flush stdout before emitting
the error message to stderr.

[1]: https://lore.kernel.org/git/CA+34VNLj6VB1kCkA=MfM7TZR+6HgqNi5-UaziAoCXacSVkch4A@mail.gmail.com/T/

Signed-off-by: Eric Sunshine <sunshine@sunshineco.com>
---

This is RFC because I naturally worry about potential fallout from
making a change to such a core function. I can't think of any case that
it wouldn't be advantageous to flush stdout before stderr, so this
change _seems_ safe, however, it may be that I'm just not imaginative
enough, hence my hesitancy.

 usage.c | 1 +
 1 file changed, 1 insertion(+)

diff --git a/usage.c b/usage.c
index c7d233b0de..0fc7640b25 100644
--- a/usage.c
+++ b/usage.c
@@ -27,6 +27,7 @@ void vreportf(const char *prefix, const char *err, va_list params)
 	}
 
 	*(p++) = '\n'; /* we no longer need a NUL */
+	fflush(stdout);
 	fflush(stderr);
 	write_in_full(2, msg, p - msg);
 }
-- 
2.34.1.75.gabe6bb3905

Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Junio C Hamano]

Eric Sunshine <sunshine@sunshineco.com> writes:

> This is RFC because I naturally worry about potential fallout from
> making a change to such a core function. I can't think of any case that
> it wouldn't be advantageous to flush stdout before stderr, so this
> change _seems_ safe, however, it may be that I'm just not imaginative
> enough, hence my hesitancy.

If stdout and stderr are both going to the same place (e.g. the
user's terminal), this would probably is an improvement, but if the
standard output is going to a pipe talking to another process, which
may care when the output is flushed, this may hurt.

But as long as the calling code is using stdio, it cannot precisely
control when the buffered contents are flushed anyway, so as long as
the caller has working standard output, this may be OK.

Hits from "git grep -l vreportf" includes http-backend.c; where is
its standard output connected, and can it have some unflushed stuff
in its standard output buffer, I wonder?

>  usage.c | 1 +
>  1 file changed, 1 insertion(+)
>
> diff --git a/usage.c b/usage.c
> index c7d233b0de..0fc7640b25 100644
> --- a/usage.c
> +++ b/usage.c
> @@ -27,6 +27,7 @@ void vreportf(const char *prefix, const char *err, va_list params)
>  	}
>  
>  	*(p++) = '\n'; /* we no longer need a NUL */
> +	fflush(stdout);
>  	fflush(stderr);
>  	write_in_full(2, msg, p - msg);
>  }

Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Jeff King]

On Mon, Nov 29, 2021 at 09:13:10PM -0800, Junio C Hamano wrote:

> Eric Sunshine <sunshine@sunshineco.com> writes:
> 
> > This is RFC because I naturally worry about potential fallout from
> > making a change to such a core function. I can't think of any case that
> > it wouldn't be advantageous to flush stdout before stderr, so this
> > change _seems_ safe, however, it may be that I'm just not imaginative
> > enough, hence my hesitancy.
> 
> If stdout and stderr are both going to the same place (e.g. the
> user's terminal), this would probably is an improvement, but if the
> standard output is going to a pipe talking to another process, which
> may care when the output is flushed, this may hurt.
> 
> But as long as the calling code is using stdio, it cannot precisely
> control when the buffered contents are flushed anyway, so as long as
> the caller has working standard output, this may be OK.

Yeah, I think this logic applies to the "happy" case. Any caller which
is depending on the time of flush is already racily buggy.

What I wonder about is the error case. What can happen if flushing
fails? There are two interesting cases I can think of:

  - flushing causes an error (which is quite likely, as we may
    vreportf() because of an error on stdout). We should be OK, as we do
    not care about the return value here, nor eventually checking
    ferror(stdout). We may overwrite errno, but at this point in
    vreportf(), we are committed to whatever error we're going to show
    (and obviously the stderr flush below could cause the same issues).

  - flushing causes us to block. This implies our stdout is connected to
    a pipe or socket, and the other side is not expecting to read. A
    plausible case here is a client sending us a big input which we find
    to be bogus (maybe index-pack checking an incoming pack). We call
    die() to complain about the input, but the client is still writing.
    In the current code, we'd write out our error and then exit; the
    client would get SIGPIPE or a write() error and abort. But with a
    flush here, we could block writing back to the client, and now we're
    in a deadlock; they are trying to write to us but we are no longer
    reading, and we are blocked trying to get out a little bit of
    irrelevant stdout data.

    I _think_ we're probably OK here. The scenario above means that the
    caller is already doing asynchronous I/O via stdio and is subject to
    deadlock. Because the segment of buffer we try to flush here _could_
    have been flushed already under the hood, which would have caused
    the same blocking. A careful caller might be using select() or
    similar to decide when it is OK to write, but I find it highly
    unlikely they'd be using stdio in that case.

Of the two, the deadlock case worries me more, just because it would be
quiet subtle and racy. As I said, I think we may be OK, but my reasoning
there is pretty hand-wavy.

-Peff

Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Jeff King]

On Tue, Nov 30, 2021 at 02:14:25AM -0500, Jeff King wrote:

>   - flushing causes us to block. This implies our stdout is connected to
>     a pipe or socket, and the other side is not expecting to read. A
>     plausible case here is a client sending us a big input which we find
>     to be bogus (maybe index-pack checking an incoming pack). We call
>     die() to complain about the input, but the client is still writing.
>     In the current code, we'd write out our error and then exit; the
>     client would get SIGPIPE or a write() error and abort. But with a
>     flush here, we could block writing back to the client, and now we're
>     in a deadlock; they are trying to write to us but we are no longer
>     reading, and we are blocked trying to get out a little bit of
>     irrelevant stdout data.
> 
>     I _think_ we're probably OK here. The scenario above means that the
>     caller is already doing asynchronous I/O via stdio and is subject to
>     deadlock. Because the segment of buffer we try to flush here _could_
>     have been flushed already under the hood, which would have caused
>     the same blocking. A careful caller might be using select() or
>     similar to decide when it is OK to write, but I find it highly
>     unlikely they'd be using stdio in that case.
> 
> Of the two, the deadlock case worries me more, just because it would be
> quiet subtle and racy. As I said, I think we may be OK, but my reasoning
> there is pretty hand-wavy.

Thinking on this a bit more: I guess as soon as we exit libc would call
the equivalent of fflush(NULL) anyway, and try that same flush. So in a
sense this is just ordering a bit differently, and not introducing any
new problems. (Unless libc is clever enough to avoid blocking, but that
doesn't seem like something we could or should rely on in general).

-Peff

Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Ævar Arnfjörð Bjarmason]

On Tue, Nov 30 2021, Jeff King wrote:

> On Tue, Nov 30, 2021 at 02:14:25AM -0500, Jeff King wrote:
>
>>   - flushing causes us to block. This implies our stdout is connected to
>>     a pipe or socket, and the other side is not expecting to read. A
>>     plausible case here is a client sending us a big input which we find
>>     to be bogus (maybe index-pack checking an incoming pack). We call
>>     die() to complain about the input, but the client is still writing.
>>     In the current code, we'd write out our error and then exit; the
>>     client would get SIGPIPE or a write() error and abort. But with a
>>     flush here, we could block writing back to the client, and now we're
>>     in a deadlock; they are trying to write to us but we are no longer
>>     reading, and we are blocked trying to get out a little bit of
>>     irrelevant stdout data.
>> 
>>     I _think_ we're probably OK here. The scenario above means that the
>>     caller is already doing asynchronous I/O via stdio and is subject to
>>     deadlock. Because the segment of buffer we try to flush here _could_
>>     have been flushed already under the hood, which would have caused
>>     the same blocking. A careful caller might be using select() or
>>     similar to decide when it is OK to write, but I find it highly
>>     unlikely they'd be using stdio in that case.
>> 
>> Of the two, the deadlock case worries me more, just because it would be
>> quiet subtle and racy. As I said, I think we may be OK, but my reasoning
>> there is pretty hand-wavy.
>
> Thinking on this a bit more: I guess as soon as we exit libc would call
> the equivalent of fflush(NULL) anyway, and try that same flush. So in a
> sense this is just ordering a bit differently, and not introducing any
> new problems. (Unless libc is clever enough to avoid blocking, but that
> doesn't seem like something we could or should rely on in general).

I think this change is probably OK too, but let's not forget about
warning() and error(). I.e. we are not always on a path to a fatal error
with vreportf(), that's just with die(), usage() and BUG().

So e.g. the warning you added recently (and we ejected before v2.34.0)
about encodings in "git log" would behave differently with this
change.

I think probably for the better, but we should also consider those
cases.

Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Jeff King]

On Tue, Nov 30, 2021 at 04:10:37PM +0100, Ævar Arnfjörð Bjarmason wrote:

> 
> On Tue, Nov 30 2021, Jeff King wrote:
> 
> > On Tue, Nov 30, 2021 at 02:14:25AM -0500, Jeff King wrote:
> >
> >>   - flushing causes us to block. This implies our stdout is connected to
> >>     a pipe or socket, and the other side is not expecting to read. A
> >>     plausible case here is a client sending us a big input which we find
> >>     to be bogus (maybe index-pack checking an incoming pack). We call
> >>     die() to complain about the input, but the client is still writing.
> >>     In the current code, we'd write out our error and then exit; the
> >>     client would get SIGPIPE or a write() error and abort. But with a
> >>     flush here, we could block writing back to the client, and now we're
> >>     in a deadlock; they are trying to write to us but we are no longer
> >>     reading, and we are blocked trying to get out a little bit of
> >>     irrelevant stdout data.
> >> 
> >>     I _think_ we're probably OK here. The scenario above means that the
> >>     caller is already doing asynchronous I/O via stdio and is subject to
> >>     deadlock. Because the segment of buffer we try to flush here _could_
> >>     have been flushed already under the hood, which would have caused
> >>     the same blocking. A careful caller might be using select() or
> >>     similar to decide when it is OK to write, but I find it highly
> >>     unlikely they'd be using stdio in that case.
> >> 
> >> Of the two, the deadlock case worries me more, just because it would be
> >> quiet subtle and racy. As I said, I think we may be OK, but my reasoning
> >> there is pretty hand-wavy.
> >
> > Thinking on this a bit more: I guess as soon as we exit libc would call
> > the equivalent of fflush(NULL) anyway, and try that same flush. So in a
> > sense this is just ordering a bit differently, and not introducing any
> > new problems. (Unless libc is clever enough to avoid blocking, but that
> > doesn't seem like something we could or should rely on in general).
> 
> I think this change is probably OK too, but let's not forget about
> warning() and error(). I.e. we are not always on a path to a fatal error
> with vreportf(), that's just with die(), usage() and BUG().

My gut feeling is that warning() and error() would encounter a subset of
the problems that die() would. Because die() is actually changing the
program state in a much more drastic way (by exiting), whereas error and
warning would continue and eventually flush anyway. They might care more
about things like errno being touched if they continue on, but they
already must assume that vreportf() can affect errno (because of the
existing flush and write on stderr).

Likewise BUG() is an interesting one. It doesn't call exit(), but
instead abort(). So unlike die(), it doesn't actually flush, and the "we
would fflush(NULL) on exit anyway" caveat above does not apply.

I still suspect that any caller doing async I/O on stdio like this is
already flaky, though. It could have decided to flush and blocked during
any write.

-Peff

Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Eric Sunshine]

On Tue, Nov 30, 2021 at 2:14 AM Jeff King <peff@peff.net> wrote:
>   - flushing causes us to block. This implies our stdout is connected to
>     a pipe or socket, and the other side is not expecting to read. A
>     plausible case here is a client sending us a big input which we find
>     to be bogus (maybe index-pack checking an incoming pack). We call
>     die() to complain about the input, but the client is still writing.
>     In the current code, we'd write out our error and then exit; the
>     client would get SIGPIPE or a write() error and abort. But with a
>     flush here, we could block writing back to the client, and now we're
>     in a deadlock; they are trying to write to us but we are no longer
>     reading, and we are blocked trying to get out a little bit of
>     irrelevant stdout data.
>
> Of the two, the deadlock case worries me more, just because it would be
> quiet subtle and racy. As I said, I think we may be OK, but my reasoning
> there is pretty hand-wavy.

Flushing stdout only if it is attached to a terminal:

    if (isatty(1))
        fflush(stdout);

should address this potential-deadlock concern, I think(?). It's
rather ugly, though, and entering the realm of
too-much-special-casing; it feels like it has the potential of heading
down a rabbit hole where we find more cases which need to be handled
specially.

Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Jeff King]

On Mon, Nov 29, 2021 at 11:39:46PM -0500, Eric Sunshine wrote:

> The order in which the stdout and stderr streams are flushed is not
> guaranteed to be the same across platforms or `libc` implementations.
> This lack of determinism can lead to anomalous and potentially confusing
> output if normal (stdout) output is flushed after error (stderr) output.
> For instance, the following output which clearly indicates a failure due
> to a fatal error:
> 
>     % git worktree add ../foo bar
>     Preparing worktree (checking out 'bar')
>     fatal: 'bar' is already checked out at '.../wherever'
> 
> has been reported[1] on Microsoft Windows to appear as:
> 
>     % git worktree add ../foo bar
>     fatal: 'bar' is already checked out at '.../wherever'
>     Preparing worktree (checking out 'bar')
> 
> which may confuse the reader into thinking that the command somehow
> recovered and ran to completion despite the error.
> 
> Rather than attempting to address this issue on a case by case basis,
> address it by making vreportf() -- which is the heart of error-reporting
> functions die(), error(), warn(), etc. -- flush stdout before emitting
> the error message to stderr.

I left some thoughts on whether this flush is safe elsewhere in the
thread. But for this particular case, two things occur to me:

  - shouldn't status messages like this go to stderr anyway? I know some
    people follow the "unless it is an error, it should not to go
    stderr" philosophy. But I think in general our approach in Git is
    more "if it is the main output of the program, it goes to stdout; if
    it is chatter or progress for the user, it goes to stderr".

  - the reason it works consistently on glibc is that stdout to a
    terminal is line buffered by default, so the "preparing" line is
    flushed immediately. If that isn't the case on Windows, should we
    consider calling setlinebuf() preemptively when isatty(1)?

    That only covers most cases, of course (both to a terminal, or
    separated stdout/stderr). Even on Linux, if you do:

      git worktree add ../foo bar >out 2>&1

    you'll get the stderr result before stdout. That implies again to me
    that this kind of message really ought to be part of the stderr
    stream.

-Peff

Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Eric Sunshine]

On Tue, Nov 30, 2021 at 2:21 AM Jeff King <peff@peff.net> wrote:
> On Mon, Nov 29, 2021 at 11:39:46PM -0500, Eric Sunshine wrote:
> > Rather than attempting to address this issue on a case by case basis,
> > address it by making vreportf() -- which is the heart of error-reporting
> > functions die(), error(), warn(), etc. -- flush stdout before emitting
> > the error message to stderr.
>
> I left some thoughts on whether this flush is safe elsewhere in the
> thread. But for this particular case, two things occur to me:
>
>   - shouldn't status messages like this go to stderr anyway? I know some
>     people follow the "unless it is an error, it should not to go
>     stderr" philosophy. But I think in general our approach in Git is
>     more "if it is the main output of the program, it goes to stdout; if
>     it is chatter or progress for the user, it goes to stderr".

I considered this as well and agree that it would be a nicer localized
fix, but...

(1) I don't think the practice is documented anywhere, so people --
including me when I wrote builtin/worktree.c -- might not know about
it. Indeed, we don't seem to be entirely consistent about doing it
this way. Randomly picking submodule-helper.c, for instance, I see
status-like messages going to stdout:

    printf(_("Entering '%s'\n"), displaypath);
    printf(_("Synchronizing submodule url for '%s'\n"), ...);

    if (...)
        format = _("Cleared directory '%s'\n");
    else
        format = _("Could not remove submodule work tree '%s'\n");
    printf(format, displaypath);

(2) With git-worktree being four or five years old, for
backward-compatibility concerns, I worry that "that ship has sailed",
where 'that' is the freedom to relocate those status-like messages
from stdout to stderr. I don't want to break tooling which exists
around git-worktree.

I'd be happy to be wrong on the second point -- indeed, git-worktree
is still marked "experimental" in the man-page, but that may not mean
anything this late in the game -- and submit a patch which places
git-worktree's status-like messages on stderr instead of stdout.
Thoughts?

>   - the reason it works consistently on glibc is that stdout to a
>     terminal is line buffered by default, so the "preparing" line is
>     flushed immediately. If that isn't the case on Windows, should we
>     consider calling setlinebuf() preemptively when isatty(1)?

I'll let the Windows experts chime in on this (Dscho?). For all I
know, that might introduce a bad performance regression on that
platform under whatever terminal-like or pseudo-tty-like emulation
they are using.

Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Eric Sunshine]

On Tue, Nov 30, 2021 at 9:05 AM Eric Sunshine <sunshine@sunshineco.com> wrote:
> (2) With git-worktree being four or five years old, for
> backward-compatibility concerns, I worry that "that ship has sailed",
> where 'that' is the freedom to relocate those status-like messages
> from stdout to stderr. I don't want to break tooling which exists
> around git-worktree.
>
> I'd be happy to be wrong on the second point -- indeed, git-worktree
> is still marked "experimental" in the man-page, but that may not mean
> anything this late in the game -- and submit a patch which places
> git-worktree's status-like messages on stderr instead of stdout.
> Thoughts?

If that ship has indeed sailed, then perhaps the best and safest thing
to do is admit that git-worktree is an outlier in terms of sending
status-like messages to stdout, and just sprinkle the necessary
fflush(stdout) around in builtin/worktree.c and live with that
localized ugliness. Thoughts?

"breaking" command output message parsing (was: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output)

[Ævar Arnfjörð Bjarmason]

On Tue, Nov 30 2021, Eric Sunshine wrote:

> On Tue, Nov 30, 2021 at 9:05 AM Eric Sunshine <sunshine@sunshineco.com> wrote:
>> (2) With git-worktree being four or five years old, for
>> backward-compatibility concerns, I worry that "that ship has sailed",
>> where 'that' is the freedom to relocate those status-like messages
>> from stdout to stderr. I don't want to break tooling which exists
>> around git-worktree.
>>
>> I'd be happy to be wrong on the second point -- indeed, git-worktree
>> is still marked "experimental" in the man-page, but that may not mean
>> anything this late in the game -- and submit a patch which places
>> git-worktree's status-like messages on stderr instead of stdout.
>> Thoughts?
>
> If that ship has indeed sailed, then perhaps the best and safest thing
> to do is admit that git-worktree is an outlier in terms of sending
> status-like messages to stdout, and just sprinkle the necessary
> fflush(stdout) around in builtin/worktree.c and live with that
> localized ugliness. Thoughts?

I really don't think that ship has sailed at all. We're at full liberty
to change these error messages, and have even done so for some plumbing
in the past (being sensitive to what sort of messages, sometimes they
are important).

See e.g. my 9144ba4cf52 (remote: add meaningful exit code on
missing/existing, 2020-10-27), that was a case where we knew about a
in-the-wild parser of the output, and git-remote is in the (I suppose
"pseudo-plumbing?") "Ancillary Commands" category.

I think the one grey area here is as in 9144ba4cf52 where we'd expect
people to reasonably script around these commands, and parsing the
output was the only way to accomplish something reasonable. E.g. in that
case automation around adding remotes & the handling of failure
scenarios. The case of [1] for "git pull" is another potential recent
one. I.e. someone grepping "Everything up-to-date".

From some brief skimming of the worktree.c code that doesn't seem to
apply, i.e. it's just chattyness.

I doubt anyone cares if it's blathering about "preparing a worktree" or
whatever, it just matters if "git worktree add" and the like fail with
non-zero, but perhaps there's cases of conflated states, as in that case
of "git remote" and "git pull".

1. https://lore.kernel.org/git/211130.86a6hleo84.gmgdl@evledraar.gmail.com/

Re: "breaking" command output message parsing (was: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output)

[Eric Sunshine]

On Wed, Dec 1, 2021 at 8:59 AM Ævar Arnfjörð Bjarmason <avarab@gmail.com> wrote:
> On Tue, Nov 30 2021, Eric Sunshine wrote:
> > On Tue, Nov 30, 2021 at 9:05 AM Eric Sunshine <sunshine@sunshineco.com> wrote:
> >> (2) With git-worktree being four or five years old, for
> >> backward-compatibility concerns, I worry that "that ship has sailed",
> >> where 'that' is the freedom to relocate those status-like messages
> >> from stdout to stderr. I don't want to break tooling which exists
> >> around git-worktree.
> >>
> >> I'd be happy to be wrong on the second point -- indeed, git-worktree
> >> is still marked "experimental" in the man-page, but that may not mean
> >> anything this late in the game -- and submit a patch which places
> >> git-worktree's status-like messages on stderr instead of stdout.
> >> Thoughts?
> >
> > If that ship has indeed sailed, then perhaps the best and safest thing
> > to do is admit that git-worktree is an outlier in terms of sending
> > status-like messages to stdout, and just sprinkle the necessary
> > fflush(stdout) around in builtin/worktree.c and live with that
> > localized ugliness. Thoughts?
>
> I really don't think that ship has sailed at all. We're at full liberty
> to change these error messages, and have even done so for some plumbing
> in the past (being sensitive to what sort of messages, sometimes they
> are important).

Just to be clear for other readers, I wasn't talking about changing
error messages but rather changing the destination of the "chatty"
messages from stdout to stderr. (I think you probably understand that
even though you typed "error message" above.)

> From some brief skimming of the worktree.c code that doesn't seem to
> apply, i.e. it's just chattyness.
>
> I doubt anyone cares if it's blathering about "preparing a worktree" or
> whatever, it just matters if "git worktree add" and the like fail with
> non-zero, but perhaps there's cases of conflated states, as in that case
> of "git remote" and "git pull".

Peff had already managed to allay my worries about that ship having
sailed[1], so that I decided[2] to drop the RFC patch and resubmit as
a patch which moves the git-worktree "chatty" messages from stdout to
stderr. Nevertheless, it's nice to hear an independent confirmation
about that ship.

[1]: https://lore.kernel.org/git/YaaN0pibKWgjcVk3@coredump.intra.peff.net/
[2]: https://lore.kernel.org/git/CAPig+cT+YfgBG3Aqszp+y7iy_megboECZy3NkMqUjBj7=Z661A@mail.gmail.com/

Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Jeff King]

On Tue, Nov 30, 2021 at 09:05:54AM -0500, Eric Sunshine wrote:

> >   - shouldn't status messages like this go to stderr anyway? I know some
> >     people follow the "unless it is an error, it should not to go
> >     stderr" philosophy. But I think in general our approach in Git is
> >     more "if it is the main output of the program, it goes to stdout; if
> >     it is chatter or progress for the user, it goes to stderr".
> 
> I considered this as well and agree that it would be a nicer localized
> fix, but...
> 
> (1) I don't think the practice is documented anywhere, so people --
> including me when I wrote builtin/worktree.c -- might not know about
> it. Indeed, we don't seem to be entirely consistent about doing it
> this way. Randomly picking submodule-helper.c, for instance, I see
> status-like messages going to stdout:
> 
>     printf(_("Entering '%s'\n"), displaypath);
>     printf(_("Synchronizing submodule url for '%s'\n"), ...);
> 
>     if (...)
>         format = _("Cleared directory '%s'\n");
>     else
>         format = _("Could not remove submodule work tree '%s'\n");
>     printf(format, displaypath);

Yeah, we've definitely not been consistent here. There's no silver
bullet for this aside from vigilance during review, but probably laying
out guidelines could help.

Here's a past discussion (that actually goes the other way: somebody
complaining that stderr should be on stdout!) where I laid out my mental
model:

  https://lore.kernel.org/git/20110907215716.GJ13364@sigill.intra.peff.net/

> (2) With git-worktree being four or five years old, for
> backward-compatibility concerns, I worry that "that ship has sailed",
> where 'that' is the freedom to relocate those status-like messages
> from stdout to stderr. I don't want to break tooling which exists
> around git-worktree.

IMHO it would be OK to change these. They are, after all, marked for
translation, so they're not reliably machine-readable anyway. It's
possible that some script could not be parsing them, but just trying to
redirect them. Or even keying on content in stderr as a sign of an error
(as tcl likes to do). But I don't think that's a guarantee we want to be
bound by.

See 68b939b2f0 (clone: send diagnostic messages to stderr, 2013-09-18)
for a similar case in the past.

> I'd be happy to be wrong on the second point -- indeed, git-worktree
> is still marked "experimental" in the man-page, but that may not mean
> anything this late in the game -- and submit a patch which places
> git-worktree's status-like messages on stderr instead of stdout.
> Thoughts?

I'm in favor. :)

-Peff

Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Eric Sunshine]

On Tue, Nov 30, 2021 at 3:47 PM Jeff King <peff@peff.net> wrote:
> On Tue, Nov 30, 2021 at 09:05:54AM -0500, Eric Sunshine wrote:
> > (1) I don't think the practice is documented anywhere, so people --
> > including me when I wrote builtin/worktree.c -- might not know about
> > it. Indeed, we don't seem to be entirely consistent about doing it
> > this way. Randomly picking submodule-helper.c, for instance, I see
> > status-like messages going to stdout:
>
> Yeah, we've definitely not been consistent here. There's no silver
> bullet for this aside from vigilance during review, but probably laying
> out guidelines could help.
>
> Here's a past discussion (that actually goes the other way: somebody
> complaining that stderr should be on stdout!) where I laid out my mental
> model:
>
>   https://lore.kernel.org/git/20110907215716.GJ13364@sigill.intra.peff.net/

Thanks for the reference. I'll take a stab at adding a blurb about
this to CodingGuidelines.

> > (2) With git-worktree being four or five years old, for
> > backward-compatibility concerns, I worry that "that ship has sailed",
> > where 'that' is the freedom to relocate those status-like messages
> > from stdout to stderr. I don't want to break tooling which exists
> > around git-worktree.
>
> IMHO it would be OK to change these. They are, after all, marked for
> translation, so they're not reliably machine-readable anyway. It's
> possible that some script could not be parsing them, but just trying to
> redirect them. Or even keying on content in stderr as a sign of an error
> (as tcl likes to do). But I don't think that's a guarantee we want to be
> bound by.

That's a good point about them being marked for translation. It also
reminds me that we made some reasonably significant changes to this
exact message in 2c27002a0a (worktree: improve message when creating a
new worktree, 2018-04-24), and we didn't hear any complaints, let
alone complaints about tool breakage.

> See 68b939b2f0 (clone: send diagnostic messages to stderr, 2013-09-18)
> for a similar case in the past.

Nice. This and the above make me feel much more comfortable with the
idea of changing git-worktree to send these sorts of messages to
stderr rather than stdout.

> > I'd be happy to be wrong on the second point -- indeed, git-worktree
> > is still marked "experimental" in the man-page, but that may not mean
> > anything this late in the game -- and submit a patch which places
> > git-worktree's status-like messages on stderr instead of stdout.
> > Thoughts?
>
> I'm in favor. :)

Thanks. I'll drop this RFC patch and resubmit with a patch which just
fixes git-worktree to be chatty on stderr instead of stdout.

Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Eric Sunshine]

On Tue, Nov 30, 2021 at 9:36 PM Eric Sunshine <sunshine@sunshineco.com> wrote:
> On Tue, Nov 30, 2021 at 3:47 PM Jeff King <peff@peff.net> wrote:
> > On Tue, Nov 30, 2021 at 09:05:54AM -0500, Eric Sunshine wrote:
> > > (1) I don't think the practice is documented anywhere, so people --
> > > including me when I wrote builtin/worktree.c -- might not know about
> > > it. Indeed, we don't seem to be entirely consistent about doing it
> > > this way. Randomly picking submodule-helper.c, for instance, I see
> > > status-like messages going to stdout:
> >
> > Yeah, we've definitely not been consistent here. There's no silver
> > bullet for this aside from vigilance during review, but probably laying
> > out guidelines could help.
>
> Thanks for the reference. I'll take a stab at adding a blurb about
> this to CodingGuidelines.

I just posted a patch which updates CodingGuidelines to talk a bit about this:
https://lore.kernel.org/git/20211201053214.2902-1-sunshine@sunshineco.com/

Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Ævar Arnfjörð Bjarmason]

On Tue, Nov 30 2021, Jeff King wrote:

> On Tue, Nov 30, 2021 at 09:05:54AM -0500, Eric Sunshine wrote:
>
>> >   - shouldn't status messages like this go to stderr anyway? I know some
>> >     people follow the "unless it is an error, it should not to go
>> >     stderr" philosophy. But I think in general our approach in Git is
>> >     more "if it is the main output of the program, it goes to stdout; if
>> >     it is chatter or progress for the user, it goes to stderr".
>> 
>> I considered this as well and agree that it would be a nicer localized
>> fix, but...
>> 
>> (1) I don't think the practice is documented anywhere, so people --
>> including me when I wrote builtin/worktree.c -- might not know about
>> it. Indeed, we don't seem to be entirely consistent about doing it
>> this way. Randomly picking submodule-helper.c, for instance, I see
>> status-like messages going to stdout:
>> 
>>     printf(_("Entering '%s'\n"), displaypath);
>>     printf(_("Synchronizing submodule url for '%s'\n"), ...);
>> 
>>     if (...)
>>         format = _("Cleared directory '%s'\n");
>>     else
>>         format = _("Could not remove submodule work tree '%s'\n");
>>     printf(format, displaypath);
>
> Yeah, we've definitely not been consistent here. There's no silver
> bullet for this aside from vigilance during review, but probably laying
> out guidelines could help.
>
> Here's a past discussion (that actually goes the other way: somebody
> complaining that stderr should be on stdout!) where I laid out my mental
> model:
>
>   https://lore.kernel.org/git/20110907215716.GJ13364@sigill.intra.peff.net/

...and a third way (which git doesn't conform to at all), which is that
std*err* is really what we should be using for errors only.

You shouldn't write anything that isn't an error there, or at least
that's what I've seen some software in the wild assume.

I've run into occasional problems with git over the years because it
writes to stderr routinely for non-errors, which flies in the face
assumptions made by various third-party software that assumes the
"that's for errors" model of the world.

E.g. look at the (very useful) "chronic" utility, which is in
"moreutils" in Debian. From its manpage:

   -e  Stderr triggering. Triggers output when stderr output length is non-zero.
       Without -e chronic needs non-zero return value to trigger output.

       In this mode, chronic's return value will be 2 if the command's
       return value is 0 but the command printed to stderr.

Right now I'm failing to recall what, but I remember dealing with that
behavior from git in some other contexts.

Re: [RFC PATCH] vreportf: ensure sensible ordering of normal and error output

[Junio C Hamano]

Ævar Arnfjörð Bjarmason <avarab@gmail.com> writes:

>> Here's a past discussion (that actually goes the other way: somebody
>> complaining that stderr should be on stdout!) where I laid out my mental
>> model:
>>
>>   https://lore.kernel.org/git/20110907215716.GJ13364@sigill.intra.peff.net/
>
> ...and a third way (which git doesn't conform to at all), which is that
> std*err* is really what we should be using for errors only.
>
> You shouldn't write anything that isn't an error there, or at least
> that's what I've seen some software in the wild assume.

That is already covered in the old thread Peff cited (not in the
message from Peff, but you can find what others said on the topic
back then from that page).  We saw programs that declare any output
to standard error by programs they spawn indicates an error, instead
of checking the exit status of the programs they spawn, which would
of course break when they try to drive git.