[PATCH 2/2] vreportf: avoid intermediate buffer

From: Jeff King <peff@peff.net>
Date: Aug 11, 2015, 18:13 UTC
Message-ID: <20150811181359.GB18002@sigill.intra.peff.net>
In-Reply-To: <20150811180524.GB15521@sigill.intra.peff.net>

When we call "die(fmt, args...)", we end up in vreportf with two pieces of information:

  1. The prefix "fatal: "

  2. The original fmt and va_list of args.

We format item (2) into a temporary buffer, and then fprintf the prefix and the temporary buffer, along with a newline. This has the unfortunate side effect of truncating any error messages that are longer than 4096 bytes.

Instead, let's use separate calls for the prefix and newline, letting us hand the item (2) directly to vfprintf. This is essentially undoing d048a96 (print warning/error/fatal messages in one shot, 2007-11-09), which tried to have the whole output end up in a single `write` call.

But we can address this instead by explicitly requesting line-buffering for the output handle, and by making sure that the buffer is empty before we start (so that outputting the prefix does not cause a flush due to hitting the buffer limit).

We may still break the output into two writes if the content is larger than our buffer, but there's not much we can do there; depending on the stdio implementation, that might have happened even with a single fprintf call.

Signed-off-by: Jeff King <peff@peff.net>
---
I am not 100% sure on the last statement. On my system, it seems that:

  fprintf(stderr, "%s%s\n", prefix, msg);

will generally result in a single write when stderr is unbuffered (i.e., it's default state). Which feels very magical, since it clearly must be preparing the output in a single buffer to feed to write, and the contents of prefix and msg may easily exceed BUFSIZ. It looks like glibc internally uses an 8K buffer to generate "unbuffered" content. E.g., if I do:

  strace -o /dev/fd/3 -e write \
  git --no-pager log --$(perl -e 'print "a" x 4096') \
  3>&2 2>/dev/null

I get:

  write(2, "fatal: unrecognized argument: --"..., 4129) = 4129

and if I bump the 4096 to 16384, I get:

  write(2, "fatal: unrecognized argument: --"..., 8192) = 8192
  write(2, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"..., 8192) = 8192
  write(2, "aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa"..., 33) = 33

So that's kind of weird. I suspect other stdio implementations may behave differently, and AFAIK the standard is quiet on the subject (so it would be OK for an implementation to output the prefix, the msg, and the newline in separate writes, no matter their length).

 usage.c | 15 ++++++++++++---
 1 file changed, 12 insertions(+), 3 deletions(-)

diff --git a/usage.c b/usage.c
index e4fa6d2..82ff131 100644
--- a/usage.c
+++ b/usage.c
@@ -7,13 +7,21 @@
 #include "cache.h"
 
 static FILE *error_handle;
+static int tweaked_error_buffering;
 
 void vreportf(const char *prefix, const char *err, va_list params)
 {
-	char msg[4096];
 	FILE *fh = error_handle ? error_handle : stderr;
-	vsnprintf(msg, sizeof(msg), err, params);
-	fprintf(fh, "%s%s\n", prefix, msg);
+
+	fflush(fh);
+	if (!tweaked_error_buffering) {
+		setvbuf(fh, NULL, _IOLBF, 0);
+		tweaked_error_buffering = 1;
+	}
+
+	fputs(prefix, fh);
+	vfprintf(fh, err, params);
+	fputc('\n', fh);
 }
 
 static NORETURN void usage_builtin(const char *err, va_list params)
@@ -70,6 +78,7 @@ void set_die_is_recursing_routine(int (*routine)(void))
 void set_error_handle(FILE *fh)
 {
 	error_handle = fh;
+	tweaked_error_buffering = 0;
 }
 
 void NORETURN usagef(const char *err, ...)

-- 
2.5.0.417.g2db689c