patchusage: try harder to format very long error messages

We use a fixed-size buffer of 4096 bytes to format die() and error() messages. We explicitly avoided using a strbuf or other fanciness here, because we want to make sure that we report the message even in the face of malloc() failure (after all, we might even be dying due to a malloc call).

In most cases, this buffer is long enough to show any reasonable message. However, if you are experimenting with _unreasonable_ things (e.g., filenames approaching 4096 bytes), the messages can be truncated, making them confusing. E.g., seeing:

  error: cannot stat 'aaaaaaaaaaaaaaaaaaaaaa

is much less useful than:

  error: cannot stat 'aaaaaaaaaaaaaaaaaaaaaaa/foo': File too long

(these are truncated for the sake of readability; obviously real examples are much longer. Just imagine many lines full of "a"'s).

This patch teaches vreportf and vwritef to at least try using a dynamically sized buffer before falling back to the fixed-size buffer. For most long errors (which are typically reporting problems with syscalls on long filenames), this means we'll generally see the full message. And in case that fails, we still print the truncated message, but with a note that it was truncated.

Note that die_errno does not need the same treatment for its fixed-size buffers, as they are a combination of:

  - our fixed-size string constants, without placeholders
    expanded (so a literal "cannot stat '%s'", without %s
    expanded to arbitrary data)

  - the results of strerror(errno)

both of which should be predictably small.

Signed-off-by: Jeff King <peff@peff.net>
---
So this solution tries to change vreportf and vwritef as little as
possible, and ends up slightly complex as a result. But reading
vreportf's:

  vsnprintf(msg, sizeof(msg), err, params);
  fprintf(stderr, "%s%s\n", prefix, msg);

I had to wonder why this wasn't just:

  fputs(prefix, stderr);
  vfprintf(stderr, err, params);

In fact, we used to do this, but changed it in d048a96 (print warning/error/fatal messages in one shot, 2007-11-09). I'm not sure of the reasoning there, though. I would expect stdio to generally write that as a single shot already, assuming:

  - there isn't anything in the stderr buffer already (i.e., we do not
    need to flush somewhere in the middle)

  - our prefix does not have a newline (which it doesn't; it is
    "error:", "fatal:", etc).

IOW, I wonder if it would be enough to simply fflush(stderr) before and after to make sure we keep the buffer clear. I also wonder if this is even enough as-is; if the resulting message is larger than stdio's buffer size, I'd expect it to come through across several writes anyway.

As for vwritef, it exists solely to work over write(), _and_ it doesn't get the "one-shot" thing right (which is probably OK, as we use it only when exec fails). But we could probably teach run-command to fdopen(), and get rid of it entirely (in favor of teaching vreportf to take a FILE* handle instead of assuming stderr).

So I dunno. I think the solution here works fine, but maybe we should be taking the opportunity to simplify.

 usage.c | 72 +++++++++++++++++++++++++++++++++++++++++++++++++++++++++--------
 1 file changed, 64 insertions(+), 8 deletions(-)

On Tue, Aug 11, 2015 at 9:17 AM, Jeff King <peff@peff.net> wrote:

Would it make sense to allocate memory in the early startup phase for a possible error message? So instead of putting 4kb on the stack we'd just have an unused 16kb on the heap.

On Tue, Aug 11, 2015 at 09:28:34AM -0700, Stefan Beller wrote:

Isn't that just punting on the problem? Now your 16kb filename will get truncated messages (in general we cannot even work with such files, but it is nice if the error message telling us so is readable).

If stack space is the problem, we can just put 16kb in BSS. But I think we really do want something that grows to the appropriate size. Or we need to start being more clever about our truncation. E.g., printing:

  error: unable to stat 'aaaaaaaaa[...]aaaaaa/foo': File too long

where the "[...]" is literally what we would print. The trouble with that approach is that it is hard to intercept large strings without re-implementing all of stdio's formatting.

-Peff

Jeff King <peff@peff.net> writes:

Yes, that was the rationale behind the "we use a fixed-buffer and try not to allocate in this codepath", I think.

Sounds like a plan ;-)

The patch looks very sensible.

On Tue, Aug 11, 2015 at 09:34:31AM -0700, Junio C Hamano wrote:

So here's an alternative series that does this, along with the single-fprintf thing I mentioned. The first patch is actually orthogonal to the second; we would probably want it whichever path we choose to fix vreportf's truncation (I'd just have to rebase the earlier patch on top of it if we go that route).

  [1/2]: vreportf: report to arbitrary filehandles
  [2/2]: vreportf: avoid intermediate buffer

-Peff

The vreportf function always goes to stderr, but run-command wants child errors to go to the parent's original stderr. To solve this, commit a5487dd duplicates the stderr fd and installs die and error handlers to direct the output appropriately (which later turned into the vwritef function). This has two downsides, though:

  - we make multiple calls to write(), which contradicts the
    "write at once" logic from d048a96 (print
    warning/error/fatal messages in one shot, 2007-11-09).

  - the custom handlers basically duplicate the normal
    handlers.  They're only a few lines of code, but we
    should not have to repeat the magic "exit(128)", for
    example.

We can solve the first by using fdopen() on the duplicated descriptor. We can't pass this to vreportf, but we could introduce a new vreportf_to to handle it.

However, to fix the second problem, we instead introduce a new "set_error_handle" function, which lets the normal vreportf calls output to a handle besides stderr. Thus we can get rid of our custom handlers entirely, and just ask the regular handlers to output to our new descriptor.

And as vwritef has no more callers, it can just go away.

Signed-off-by: Jeff King <peff@peff.net>
---
 git-compat-util.h |  2 +-
 run-command.c     | 17 ++---------------
 usage.c           | 22 +++++++++-------------
 3 files changed, 12 insertions(+), 29 deletions(-)

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(-)