[v3,1/1] vreportf(): avoid relying on stdio buffering
diff mbox series

Message ID fce0894ee46f737322551b51edf5cd2a53413a50.1572379280.git.gitgitgadget@gmail.com
State New
Headers show
Series
  • Fix t5516 flakiness in Visual Studio builds
Related show

Commit Message

Johannes Schindelin via GitGitGadget Oct. 29, 2019, 8:01 p.m. UTC
From: Johannes Schindelin <johannes.schindelin@gmx.de>

The MSVC runtime behavior differs from glibc's with respect to
`fprintf(stderr, ...)` in that the former writes out the message
character by character.

In t5516, this leads to a funny problem where a `git fetch` process as
well as the `git upload-pack` process spawned by it _both_ call `die()`
at the same time. The output can look like this:

	fatal: git uploadfata-lp: raemcokte :error:  upload-pnot our arcef k6: n4ot our ea4cr1e3f 36d45ea94fca1398e86a771eda009872d63adb28598f6a9
	8e86a771eda009872d6ab2886

Let's avoid this predicament altogether by rendering the entire message,
including the prefix and the trailing newline, into the buffer we
already have (and which is still fixed size) and then write it out via
`write_in_full()`.

We still clip the message to at most 4095 characters.

The history of `vreportf()` with regard to this issue includes the
following commits:

d048a96e (2007-11-09) - 'char msg[256]' is introduced to avoid interleaving
389d1767 (2009-03-25) - Buffer size increased to 1024 to avoid truncation
625a860c (2009-11-22) - Buffer size increased to 4096 to avoid truncation
f4c3edc0 (2015-08-11) - Buffer removed to avoid truncation
b5a9e435 (2017-01-11) - Reverts f4c3edc0 to be able to replace control
                        chars before sending to stderr
9ac13ec9 (2006-10-11) - Another attempt to solve interleaving.
                        This is seemingly related to d048a96e.
137a0d0e (2007-11-19) - Addresses out-of-order for display()
34df8aba (2009-03-10) - Switches xwrite() to fprintf() in recv_sideband()
                        to support UTF-8 emulation
eac14f89 (2012-01-14) - Removes the need for fprintf() for UTF-8 emulation,
                        so it's safe to use xwrite() again
5e5be9e2 (2016-06-28) - recv_sideband() uses xwrite() again

Note that we print nothing if the `vsnprintf()` call failed to render
the error message; There is little we can do in that case, and it should
not happen anyway.

Also please note that we `fflush(stderr)` here to help when running in a
Git Bash on Windows: in this case, `stderr` is not actually truly
unbuffered, and needs the extra help.

Helped-by: Jeff King <peff@peff.net>
Helped-by: Alexandr Miloslavskiy <alexandr.miloslavskiy@syntevo.com>
Helped-by: SZEDER Gábor <szeder.dev@gmail.com>
Helped-by: Junio C Hamano <gitster@pobox.com>
Signed-off-by: Johannes Schindelin <johannes.schindelin@gmx.de>
---
 usage.c | 15 +++++++++++----
 1 file changed, 11 insertions(+), 4 deletions(-)

Comments

Jeff King Oct. 29, 2019, 8:32 p.m. UTC | #1
On Tue, Oct 29, 2019 at 08:01:20PM +0000, Johannes Schindelin via GitGitGadget wrote:

> diff --git a/usage.c b/usage.c
> index 2fdb20086b..471efb2de9 100644
> --- a/usage.c
> +++ b/usage.c
> @@ -9,14 +9,21 @@
>  void vreportf(const char *prefix, const char *err, va_list params)
>  {
>  	char msg[4096];
> -	char *p;
> +	size_t off = strlcpy(msg, prefix, sizeof(msg));
> +	char *p, *pend = msg + sizeof(msg);
>  
> -	vsnprintf(msg, sizeof(msg), err, params);
> -	for (p = msg; *p; p++) {
> +	p = off < pend - msg ? msg + off : pend - 1;
> +	if (vsnprintf(p, pend - p, err, params) < 0)
> +		*p = '\0'; /* vsnprintf() failed, clip at prefix */
> +
> +	for (; p != pend - 1 && *p; p++) {
>  		if (iscntrl(*p) && *p != '\t' && *p != '\n')
>  			*p = '?';
>  	}

This version looks OK to me. Some bikeshedding:

  - I suspect it may be more readable to just stick to offsets instead
    of pointers, since that's what strlcpy() and vsnprintf() give us.

  - I don't think "p == pend - 1" can ever trigger, since either
    vsnprintf() or we will have just written a NUL.

  - Do we need to contend with vsnprintf() return a negative value in
    general in our codebase? We already BUG() on it elsewhere. Yes, that
    BUG() would try to write via this code path, but it implies to me
    that we've already dealt with any such broken vsnprintf()
    implementations (via compat/snprintf.c).

If you're sick of bikeshedding, though, I can live without any of those
being addressed.

> +	*(p++) = '\n'; /* we no longer need a NUL */
> +	fflush(stderr);
> +	write_in_full(2, msg, p - msg);

One non-bikeshed question: would fprintf() on some platforms have sent
"\r\n", which is no longer happening with our write()? Do we need to
care about that?

-Peff
Junio C Hamano Oct. 30, 2019, 2:01 a.m. UTC | #2
"Johannes Schindelin via GitGitGadget" <gitgitgadget@gmail.com>
writes:

> Subject: Re: [PATCH v3 1/1] vreportf(): avoid relying on stdio buffering

perfect ;-)

> Let's avoid this predicament altogether by rendering the entire message,
> including the prefix and the trailing newline, into the buffer we
> already have (and which is still fixed size) and then write it out via
> `write_in_full()`.
>
> We still clip the message to at most 4095 characters.

Good.

> Also please note that we `fflush(stderr)` here to help when running in a
> Git Bash on Windows: in this case, `stderr` is not actually truly
> unbuffered, and needs the extra help.

I do not think you have to single out Windows in this case; if we
are writing directly to file descriptor #2, as long as there have
been something written by the process to the standard error stream
before our caller called us, we must flush it to make sure what
we are going to write out will come after, no matter what platform
we are on.

    The process may have written to the standard error stream and
    there may be something left in the buffer kept in the stdio
    layer.  Call fflush(stderr) before writing the message we
    prepare in this function.

or something along that line would be sufficient.

> diff --git a/usage.c b/usage.c
> index 2fdb20086b..471efb2de9 100644
> --- a/usage.c
> +++ b/usage.c
> @@ -9,14 +9,21 @@
>  void vreportf(const char *prefix, const char *err, va_list params)
>  {
>  	char msg[4096];
> -	char *p;
> +	size_t off = strlcpy(msg, prefix, sizeof(msg));
> +	char *p, *pend = msg + sizeof(msg);
>  
> -	vsnprintf(msg, sizeof(msg), err, params);
> -	for (p = msg; *p; p++) {
> +	p = off < pend - msg ? msg + off : pend - 1;
> +	if (vsnprintf(p, pend - p, err, params) < 0)
> +		*p = '\0'; /* vsnprintf() failed, clip at prefix */
> +
> +	for (; p != pend - 1 && *p; p++) {

It may make the result much simpler to start with something like:

	size_t prefix_len = strlen(prefix);

	if (sizeof(msg) <= prefix_len) {
 		fprintf(stderr, "BUG!!! too long a prefix '%s'\n", prefix);
		abort();
	}
	memcpy(msg, prefix, prefix_len);
	p = msg + prefix_len;

as we agreed that we won't have prefix that will fill or overflow
msg[] based on your earlier reading of the callers like BUG-fl.
That way, we probably may be able to even lose the pend pointer and
arithmetic around it.

>  		if (iscntrl(*p) && *p != '\t' && *p != '\n')
>  			*p = '?';
>  	}

Thanks.  With this flow it is crystal clear that the prefix is shown
as-is, while the payload is sanitized.

> -	fprintf(stderr, "%s%s\n", prefix, msg);
> +
> +	*(p++) = '\n'; /* we no longer need a NUL */
> +	fflush(stderr);
> +	write_in_full(2, msg, p - msg);
>  }
>  
>  static NORETURN void usage_builtin(const char *err, va_list params)
Johannes Schindelin Oct. 30, 2019, 8:54 a.m. UTC | #3
Hi Peff,

On Tue, 29 Oct 2019, Jeff King wrote:

> On Tue, Oct 29, 2019 at 08:01:20PM +0000, Johannes Schindelin via GitGitGadget wrote:
>
> > diff --git a/usage.c b/usage.c
> > index 2fdb20086b..471efb2de9 100644
> > --- a/usage.c
> > +++ b/usage.c
> > @@ -9,14 +9,21 @@
> >  void vreportf(const char *prefix, const char *err, va_list params)
> >  {
> >  	char msg[4096];
> > -	char *p;
> > +	size_t off = strlcpy(msg, prefix, sizeof(msg));
> > +	char *p, *pend = msg + sizeof(msg);
> >
> > -	vsnprintf(msg, sizeof(msg), err, params);
> > -	for (p = msg; *p; p++) {
> > +	p = off < pend - msg ? msg + off : pend - 1;
> > +	if (vsnprintf(p, pend - p, err, params) < 0)
> > +		*p = '\0'; /* vsnprintf() failed, clip at prefix */
> > +
> > +	for (; p != pend - 1 && *p; p++) {
> >  		if (iscntrl(*p) && *p != '\t' && *p != '\n')
> >  			*p = '?';
> >  	}
>
> This version looks OK to me. Some bikeshedding:
>
>   - I suspect it may be more readable to just stick to offsets instead
>     of pointers, since that's what strlcpy() and vsnprintf() give us.

An earlier (unsent) iteration did exactly that, but it was quite a bit
more unreadable because of the required arithmetics with `sizeof(msg)`.

>   - I don't think "p == pend - 1" can ever trigger, since either
>     vsnprintf() or we will have just written a NUL.

You are right, but I wanted to make extra sure that this code is robust
even (or: especially) in the presence of buggy libc functions.

It's not even expensive, I don't think.

>   - Do we need to contend with vsnprintf() return a negative value in
>     general in our codebase? We already BUG() on it elsewhere. Yes, that
>     BUG() would try to write via this code path, but it implies to me
>     that we've already dealt with any such broken vsnprintf()
>     implementations (via compat/snprintf.c).

It is true that the test suite bails out with a `BUG()` when
`vsnprintf()` is broken. But I figured that we want to be safe rather
than sorry. Besides, I have no full picture about what potential reasons
could make `vsnprintf()` return a negative value: for what I know, an
invalid format string could trigger that. And I _really_ want this code
path to be as robust as I can make it.

> If you're sick of bikeshedding, though, I can live without any of those
> being addressed.

Oh, that's okay, and I would not even call it bikeshedding, I think you
raised valid concerns.

> > +	*(p++) = '\n'; /* we no longer need a NUL */
> > +	fflush(stderr);
> > +	write_in_full(2, msg, p - msg);
>
> One non-bikeshed question: would fprintf() on some platforms have sent
> "\r\n", which is no longer happening with our write()? Do we need to
> care about that?

I am not aware of any platform where `fprintf()` would automatically
transform `\n` to `\r\n`. Not unless the `FILE *` in question has been
opened with the `t` flag. And I am rather certain that `stderr` is not
opened with that flag. And if it was, I would force it off in Git for
Windows.

Thanks,
Dscho
Johannes Schindelin Oct. 30, 2019, 9:13 a.m. UTC | #4
Hi Junio,

On Wed, 30 Oct 2019, Junio C Hamano wrote:

> "Johannes Schindelin via GitGitGadget" <gitgitgadget@gmail.com>
> writes:
>
> > Also please note that we `fflush(stderr)` here to help when running in a
> > Git Bash on Windows: in this case, `stderr` is not actually truly
> > unbuffered, and needs the extra help.
>
> I do not think you have to single out Windows in this case; if we
> are writing directly to file descriptor #2, as long as there have
> been something written by the process to the standard error stream
> before our caller called us, we must flush it to make sure what
> we are going to write out will come after, no matter what platform
> we are on.
>
>     The process may have written to the standard error stream and
>     there may be something left in the buffer kept in the stdio
>     layer.  Call fflush(stderr) before writing the message we
>     prepare in this function.
>
> or something along that line would be sufficient.

I replaced the paragraph with a slightly edited version of this. Thanks.

> > diff --git a/usage.c b/usage.c
> > index 2fdb20086b..471efb2de9 100644
> > --- a/usage.c
> > +++ b/usage.c
> > @@ -9,14 +9,21 @@
> >  void vreportf(const char *prefix, const char *err, va_list params)
> >  {
> >  	char msg[4096];
> > -	char *p;
> > +	size_t off = strlcpy(msg, prefix, sizeof(msg));
> > +	char *p, *pend = msg + sizeof(msg);
> >
> > -	vsnprintf(msg, sizeof(msg), err, params);
> > -	for (p = msg; *p; p++) {
> > +	p = off < pend - msg ? msg + off : pend - 1;
> > +	if (vsnprintf(p, pend - p, err, params) < 0)
> > +		*p = '\0'; /* vsnprintf() failed, clip at prefix */
> > +
> > +	for (; p != pend - 1 && *p; p++) {
>
> It may make the result much simpler to start with something like:
>
> 	size_t prefix_len = strlen(prefix);
>
> 	if (sizeof(msg) <= prefix_len) {
>  		fprintf(stderr, "BUG!!! too long a prefix '%s'\n", prefix);
> 		abort();
> 	}
> 	memcpy(msg, prefix, prefix_len);
> 	p = msg + prefix_len;
>
> as we agreed that we won't have prefix that will fill or overflow
> msg[] based on your earlier reading of the callers like BUG-fl.

Makes sense. I was a bit blinded by my endeavor to keep the diffstat
small.

> That way, we probably may be able to even lose the pend pointer and
> arithmetic around it.

I tried this, and it still looks more obvious to me with `pend`.

> >  		if (iscntrl(*p) && *p != '\t' && *p != '\n')
> >  			*p = '?';
> >  	}
>
> Thanks.  With this flow it is crystal clear that the prefix is shown
> as-is, while the payload is sanitized.

Yes ;-)

Thanks,
Dscho

> > -	fprintf(stderr, "%s%s\n", prefix, msg);
> > +
> > +	*(p++) = '\n'; /* we no longer need a NUL */
> > +	fflush(stderr);
> > +	write_in_full(2, msg, p - msg);
> >  }
> >
> >  static NORETURN void usage_builtin(const char *err, va_list params)
>
>
Jeff King Oct. 31, 2019, 6:24 a.m. UTC | #5
On Wed, Oct 30, 2019 at 09:54:52AM +0100, Johannes Schindelin wrote:

> > One non-bikeshed question: would fprintf() on some platforms have sent
> > "\r\n", which is no longer happening with our write()? Do we need to
> > care about that?
> 
> I am not aware of any platform where `fprintf()` would automatically
> transform `\n` to `\r\n`. Not unless the `FILE *` in question has been
> opened with the `t` flag. And I am rather certain that `stderr` is not
> opened with that flag. And if it was, I would force it off in Git for
> Windows.

OK, thanks. You guessed the platform I was thinking of. :)

Another more far-fetched one: IIRC our stdio wrappers on Windows do some
magic to convert ANSI color codes into actual terminal codes. Could that
be a problem here? I think we'd kill off any color codes in the actual
message due to the control-code replacement. In theory the prefix could
have them. I don't think any code does now, but the PUSH_COLOR_ERROR
stuff in builtin/push.c is getting close. I wouldn't be surprised for
that to eventually get folded into error().

-Peff
Johannes Schindelin Oct. 31, 2019, 10:26 a.m. UTC | #6
Hi Peff,

On Thu, 31 Oct 2019, Jeff King wrote:

> On Wed, Oct 30, 2019 at 09:54:52AM +0100, Johannes Schindelin wrote:
>
> > > One non-bikeshed question: would fprintf() on some platforms have sent
> > > "\r\n", which is no longer happening with our write()? Do we need to
> > > care about that?
> >
> > I am not aware of any platform where `fprintf()` would automatically
> > transform `\n` to `\r\n`. Not unless the `FILE *` in question has been
> > opened with the `t` flag. And I am rather certain that `stderr` is not
> > opened with that flag. And if it was, I would force it off in Git for
> > Windows.
>
> OK, thanks. You guessed the platform I was thinking of. :)
>
> Another more far-fetched one: IIRC our stdio wrappers on Windows do some
> magic to convert ANSI color codes into actual terminal codes. Could that
> be a problem here? I think we'd kill off any color codes in the actual
> message due to the control-code replacement. In theory the prefix could
> have them. I don't think any code does now, but the PUSH_COLOR_ERROR
> stuff in builtin/push.c is getting close. I wouldn't be surprised for
> that to eventually get folded into error().

A valid concern!

As per eac14f8909d (Win32: Thread-safe windows console output,
2012-01-14), `write()` _implicitly_ gets the ANSI emulation of
`winansi.c`.

So I think we're good.

Thanks for thinking of all kinds of angles,
Dscho
Jeff King Oct. 31, 2019, 3:48 p.m. UTC | #7
On Thu, Oct 31, 2019 at 11:26:30AM +0100, Johannes Schindelin wrote:

> > Another more far-fetched one: IIRC our stdio wrappers on Windows do some
> > magic to convert ANSI color codes into actual terminal codes. Could that
> > be a problem here? I think we'd kill off any color codes in the actual
> > message due to the control-code replacement. In theory the prefix could
> > have them. I don't think any code does now, but the PUSH_COLOR_ERROR
> > stuff in builtin/push.c is getting close. I wouldn't be surprised for
> > that to eventually get folded into error().
> 
> A valid concern!
> 
> As per eac14f8909d (Win32: Thread-safe windows console output,
> 2012-01-14), `write()` _implicitly_ gets the ANSI emulation of
> `winansi.c`.
> 
> So I think we're good.
> 
> Thanks for thinking of all kinds of angles,

Good. Thanks for humoring my wild speculation. :)

I remember being confused by this not too long ago, so I did a quick dig
in the archive. And indeed, there was a confusing comment which caught
me in 2016, and which you removed back then (via 3d0a83382f26). I even
reviewed the patch. Maybe this time I will remember the outcome!

-Peff
Johannes Schindelin Nov. 1, 2019, 6:41 p.m. UTC | #8
Hi,

On Thu, 31 Oct 2019, Jeff King wrote:

> On Thu, Oct 31, 2019 at 11:26:30AM +0100, Johannes Schindelin wrote:
>
> > > Another more far-fetched one: IIRC our stdio wrappers on Windows do some
> > > magic to convert ANSI color codes into actual terminal codes. Could that
> > > be a problem here? I think we'd kill off any color codes in the actual
> > > message due to the control-code replacement. In theory the prefix could
> > > have them. I don't think any code does now, but the PUSH_COLOR_ERROR
> > > stuff in builtin/push.c is getting close. I wouldn't be surprised for
> > > that to eventually get folded into error().
> >
> > A valid concern!
> >
> > As per eac14f8909d (Win32: Thread-safe windows console output,
> > 2012-01-14), `write()` _implicitly_ gets the ANSI emulation of
> > `winansi.c`.
> >
> > So I think we're good.
> >
> > Thanks for thinking of all kinds of angles,
>
> Good. Thanks for humoring my wild speculation. :)

Of course!

> I remember being confused by this not too long ago, so I did a quick dig
> in the archive. And indeed, there was a confusing comment which caught
> me in 2016, and which you removed back then (via 3d0a83382f26). I even
> reviewed the patch. Maybe this time I will remember the outcome!

Heh, I won't fault you because I totally forgot about it myself.

Ciao,
Dscho

Patch
diff mbox series

diff --git a/usage.c b/usage.c
index 2fdb20086b..471efb2de9 100644
--- a/usage.c
+++ b/usage.c
@@ -9,14 +9,21 @@ 
 void vreportf(const char *prefix, const char *err, va_list params)
 {
 	char msg[4096];
-	char *p;
+	size_t off = strlcpy(msg, prefix, sizeof(msg));
+	char *p, *pend = msg + sizeof(msg);
 
-	vsnprintf(msg, sizeof(msg), err, params);
-	for (p = msg; *p; p++) {
+	p = off < pend - msg ? msg + off : pend - 1;
+	if (vsnprintf(p, pend - p, err, params) < 0)
+		*p = '\0'; /* vsnprintf() failed, clip at prefix */
+
+	for (; p != pend - 1 && *p; p++) {
 		if (iscntrl(*p) && *p != '\t' && *p != '\n')
 			*p = '?';
 	}
-	fprintf(stderr, "%s%s\n", prefix, msg);
+
+	*(p++) = '\n'; /* we no longer need a NUL */
+	fflush(stderr);
+	write_in_full(2, msg, p - msg);
 }
 
 static NORETURN void usage_builtin(const char *err, va_list params)