patch, 7 partstrace: stop using write_or_whine_pipe()

On Wed, Aug 03, 2016 at 05:39:20PM -0400, Jeff King wrote:

I started to write a patch to do that, but it turns out the trace code is full of bugs (and opportunities for cosmetic improvements).

Here's what I came up with.

  [1/7]: trace: handle NULL argument in trace_disable()
  [2/7]: trace: stop using write_or_whine_pipe()
  [3/7]: trace: use warning() for printing trace errors
  [4/7]: trace: cosmetic fixes for error messages
  [5/7]: trace: correct variable name in write() error message
  [6/7]: trace: disable key after write error
  [7/7]: write_or_die: drop write_or_whine_pipe()

-Peff

The write_or_whine_pipe function does two things:

  1. it checks for EPIPE and converts it into a signal death

  2. it prints a message to stderr on error

The first thing does not help us, and actively hurts. Generally we would simply die from SIGPIPE in this case, unless somebody has taken the time to ignore SIGPIPE for the whole process. And if they _did_ do that, it seems rather silly for the trace code, which otherwise takes pains to continue even in the face of errors (e.g., by not using write_or_die!), to take down the whole process for one specific type of error.

Nor does the second thing help us; it just makes it harder to write our error message, because we have to feed bits of it as an argument to write_or_whine_pipe(). Translators never get to see the full message, and it's hard for us to customize it.

Let's switch to just using write_in_full() and writing our own error string. For now, the error is identical to what write_or_whine_pipe() would say, but now that it's more under our control, we can improve it in future patches.

Signed-off-by: Jeff King <peff@peff.net>
---
 trace.c | 11 ++++++++---
 1 file changed, 8 insertions(+), 3 deletions(-)

Right now we just fprintf() straight to stderr, which can make the output hard to distinguish. It would be helpful to give it one of our usual prefixes like "error:", "warning:", etc.

It doesn't make sense to use error() here, as the trace code is "optional" debugging code. If something goes wrong, we should warn the user, but saying "error" implies the actual git operation had a problem. So warning() is the only sane choice.

Note that this does end up calling warn_routine() to do the formatting. So in theory, somebody who tries to trace from their warn_routine() could cause a loop. But nobody does this, and in fact nobody in the history of git has ever replaced the default warn_builtin (there isn't even a set_warn_routine function!).

Signed-off-by: Jeff King <peff@peff.net>
---
 trace.c | 11 +++++------
 1 file changed, 5 insertions(+), 6 deletions(-)

Jeff King <peff@peff.net> writes:

I think the last bit is about to change; cf. 545f13c0 (usage: add set_warn_routine(), 2016-07-30) on cc/apply-am topic.

On Thu, Aug 04, 2016 at 01:41:02PM -0700, Junio C Hamano wrote:

Thanks, I meant to check this series against "pu" to make sure there are no new callers for write_or_whine_pipe(), but forgot to.

It looks like that same topic does add one new caller, and switches the "fprintf" inside it to use warning().

IMHO the call added by 19a73ac (builtin/apply: make try_create_file() return -1 on error, 2016-07-30) should just be a regular:

  if (write_in_full(...) < 0)
        error(...);

We don't care about the weird pipe handling there (we know we're writing to a file we just created), and the way the error message is passed in just makes things weird. Plus it seems more like an error() than a warning (e.g., we call error() immediately below when close() fails!). But 8fab3c6 (write_or_die: use warning() instead of fprintf(stderr, ...), 2016-07-30) makes it an unconditional warning (that commit, btw, has a bug in that it retains the trailing newline of the message, even though warning() will add one itself).

So I'd suggest that series drop the call write_or_whine_pipe() and drop 8fab3c6 entirely.

I wondered if that would then let us drop set_warn_routine(), but it looks like there are other warning() calls it cares about. So that would invalidate the last paragraph here, though I still think converting the trace errors to warning() is a reasonable thing to do.

-Peff

Jeff King <peff@peff.net> writes:

Yes. That is why tonight's pushout will have this series in 'jch' (that is a point on a linear history between 'master' and 'pu') and tentatively ejects cc/apply-am topic out of 'pu', expecting it to be rerolled.

Thanks.

On Thu, Aug 04, 2016 at 02:28:09PM -0700, Junio C Hamano wrote:

Here's a replacement patch 3. Same code, but it clarifies the warn_routine situation in the commit message.

-- >8 --
Subject: [PATCH] trace: use warning() for printing trace errors

Right now we just fprintf() straight to stderr, which can make the output hard to distinguish. It would be helpful to give it one of our usual prefixes like "error:", "warning:", etc.

It doesn't make sense to use error() here, as the trace code is "optional" debugging code. If something goes wrong, we should warn the user, but saying "error" implies the actual git operation had a problem. So warning() is the only sane choice.

Note that this does end up calling warn_routine() to do the formatting. This is probably a good thing, since they are clearly trying to hook messages before they make it to stderr. However, it also means that in theory somebody who tries to trace from their warn_routine() could cause a loop. This seems rather unlikely in practice (we've never even overridden the default warn_builtin routine before, and recent discussions to do so would just install a noop routine).

Signed-off-by: Jeff King <peff@peff.net>
---
 trace.c | 11 +++++------
 1 file changed, 5 insertions(+), 6 deletions(-)

On Thu, Aug 4, 2016 at 11:28 PM, Junio C Hamano <gitster@pobox.com> wrote:

Ok, I will reroll soon with Peff's suggested changes.

Christian Couder <christian.couder@gmail.com> writes:

Thanks.

If we get a write error writing to a trace descriptor, the error isn't likely to go away if we keep writing. Instead, you'll just get the same error over and over. E.g., try:

  GIT_TRACE_PACKET=42 git ls-remote >/dev/null

You don't really need to see:

  warning: unable to write trace for GIT_TRACE_PACKET: Bad file descriptor

hundreds of times. We could fallback to tracing to stderr, as we do in the error code-path for open(), but there's not much point. If the user fed us a bogus descriptor, they're probably better off fixing their invocation. And if they didn't, and we saw a transient error (e.g., ENOSPC writing to a file), it probably doesn't help anybody to have half of the trace in a file, and half on stderr.

Signed-off-by: Jeff King <peff@peff.net>
---
 trace.c | 1 +
 1 file changed, 1 insertion(+)

Jeff King <peff@peff.net> writes:

Yes, I think I like this better than "we cannot open the named file, so let's trace into standard error stream" that is done in the code in the context of [3/7]. We should do the same over there.

On Thu, Aug 04, 2016 at 01:45:11PM -0700, Junio C Hamano wrote:

Yeah, I was tempted to strip that out, too. I'll look into preparing a patch on top.

-Peff

On Thu, Aug 04, 2016 at 05:22:44PM -0400, Jeff King wrote:

Here's a patch that can go on the tip of jk/trace-fixup.

-- >8 --
Subject: [PATCH] trace: do not fall back to stderr

If the trace code cannot open a specified file, or does not understand the contents of the GIT_TRACE variable, it falls back to printing trace output to stderr.

This is an attempt to be helpful, but in practice it just ends up annoying. The user was trying to get the output to go somewhere else, so spewing it to stderr does not really accomplish that. And as it's intended for debugging, they can presumably re-run the command with their error corrected.

So instead of falling back, this patch disables bogus trace keys for the rest of the program, just as we do for write errors. We can drop the "Defaulting to..." part of the error message entirely; after seeing "cannot open '/foo'", the user can assume that tracing is skipped.

Signed-off-by: Jeff King <peff@peff.net>
---
 trace.c | 10 ++++------
 1 file changed, 4 insertions(+), 6 deletions(-)

This function has no callers, and is not likely to gain any because it's confusing to use.

It unconditionally complains to stderr, but _doesn't_ die. Yet any caller which wants a "gentle" write would generally want to suppress the error message, because presumably they're going to write a better one, and/or try the operation again.

And the check_pipe() call leads to confusing behaviors. It means we die for EPIPE, but not for other errors, which is confusing and pointless.

On top of all that, it has unusual error return semantics, which makes it easy for callers to get it wrong.

Let's drop the function, and if somebody ever needs to resurrect something like it, they can fix these warts.

Signed-off-by: Jeff King <peff@peff.net>
---
 cache.h        |  1 -
 write_or_die.c | 12 ------------
 2 files changed, 13 deletions(-)

All of the trace functions treat a NULL key as a synonym for the default GIT_TRACE key. Except for trace_disable(), which will segfault.

Fortunately, this can't cause any bugs, as the function has no callers. But rather than drop it, let's fix the bug, as I plan to add a caller.

Signed-off-by: Jeff King <peff@peff.net>
---
 trace.c | 20 ++++++++++++++++----
 1 file changed, 16 insertions(+), 4 deletions(-)

On Wed, Aug 03, 2016 at 06:56:00PM -0400, Jeff King wrote:

Oops, I meant to detach this from the parent thread, but apparently I am incompetent at editing email headers.

This really is totally orthogonal to your series (except that you should obviously not use write_or_whine_pipe(), but that is the case whether I rip it out or not :) ).

-Peff

The error messages for the trace code are often multi-line; the first line gets a nice "warning:", but the rest are left-aligned. Let's give them an indentation to make sure they stand out as a unit.

While we're here, let's also downcase the first letter of each error (our usual style), and break up a long line of advice (since we're already using multiple lines, one more doesn't hurt).

We also replace "What does 'foo' for GIT_TRACE mean?". While cute, it's probably a good idea to give more context, and follow our usual styles. So it's now "unknown trace value for 'GIT_TRACE': foo".

Signed-off-by: Jeff King <peff@peff.net>
---
I went with an indent the size of "warning: ", because that string does
not actually get translated (it seems like it probably should, though).

I think it would be nicer to still to print:

 warning: first line
 warning: second line

etc. We do that for "advice:", but not the rest of the vreportf functions. It might be nice to do that, but we'd have to go back to printing into a buffer (since we can't break up the incoming format string that we feed to fprintf).

 trace.c | 16 ++++++++--------
 1 file changed, 8 insertions(+), 8 deletions(-)

Jeff King <peff@peff.net> writes:

Yes, yes.

On Thu, Aug 04, 2016 at 01:42:12PM -0700, Junio C Hamano wrote:

Actually, I guess in this case we could easily do:

   warning("something");
   warning("something else");

etc (the lines are fairly stand-alone, so I don't think it runs afoul of the usual translator-lego problem; not to mention that these aren't actually translated). I don't really care that much between that and the indented output, but if there's a preference, I'm happy to re-roll with that.

-Peff

Our error message for write() always mentions GIT_TRACE, even though we may be writing for a different variable entirely. It's also not quite accurate to say "fd given by GIT_TRACE environment variable", as we may hit this error based on a filename the user put in the variable (we do complain and switch to stderr if the file cannot be opened, but it's still possible to hit a write() error on the descriptor later).

So let's fix those things, and switch to our more usual "unable to do X: Y" format for the error.

Signed-off-by: Jeff King <peff@peff.net>
---
 trace.c | 10 +++++-----
 1 file changed, 5 insertions(+), 5 deletions(-)