# [PATCH 2/7] trace: stop using write_or_whine_pipe() 20 messages from 2016-08-03 to 2016-08-05. Participants: Jeff King, Junio C Hamano, Christian Couder. Thread: https://gitlist.dev/t/43000 ## Jeff King, 2016-08-03 22:58 Subject: [PATCH 2/7] trace: stop using write_or_whine_pipe() Message-ID: <20160803225800.mwwznno7tiujycgt@sigill.intra.peff.net> URL: https://gitlist.dev/e/20160803225800.mwwznno7tiujycgt%40sigill.intra.peff.net In-Reply-To: <20160803225600.fgm23bdacunmrw44@sigill.intra.peff.net> ``` 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 --- trace.c | 11 ++++++++--- 1 file changed, 8 insertions(+), 3 deletions(-) diff --git a/trace.c b/trace.c index f204a7d..bdbe149 100644 --- a/trace.c +++ b/trace.c @@ -132,18 +132,23 @@ static int prepare_trace_line(const char *file, int line, return 1; } +static void trace_write(struct trace_key *key, const void *buf, unsigned len) +{ + if (write_in_full(get_trace_fd(key), buf, len) < 0) + fprintf(stderr, "%s: write error (%s)\n", err_msg, strerror(errno)); +} + void trace_verbatim(struct trace_key *key, const void *buf, unsigned len) { if (!trace_want(key)) return; - write_or_whine_pipe(get_trace_fd(key), buf, len, err_msg); + trace_write(key, buf, len); } static void print_trace_line(struct trace_key *key, struct strbuf *buf) { strbuf_complete_line(buf); - - write_or_whine_pipe(get_trace_fd(key), buf->buf, buf->len, err_msg); + trace_write(key, buf->buf, buf->len); strbuf_release(buf); } -- 2.9.2.670.g42e63de ``` ## Jeff King, 2016-08-03 22:58 Subject: [PATCH 3/7] trace: use warning() for printing trace errors Message-ID: <20160803225826.hlr273h4cy2hcfyk@sigill.intra.peff.net> URL: https://gitlist.dev/e/20160803225826.hlr273h4cy2hcfyk%40sigill.intra.peff.net In-Reply-To: <20160803225600.fgm23bdacunmrw44@sigill.intra.peff.net> ``` 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 --- trace.c | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/trace.c b/trace.c index bdbe149..6a77e4d 100644 --- a/trace.c +++ b/trace.c @@ -61,9 +61,8 @@ static int get_trace_fd(struct trace_key *key) else if (is_absolute_path(trace)) { int fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666); if (fd == -1) { - fprintf(stderr, - "Could not open '%s' for tracing: %s\n" - "Defaulting to tracing on stderr...\n", + warning("Could not open '%s' for tracing: %s\n" + "Defaulting to tracing on stderr...", trace, strerror(errno)); key->fd = STDERR_FILENO; } else { @@ -71,10 +70,10 @@ static int get_trace_fd(struct trace_key *key) key->need_close = 1; } } else { - fprintf(stderr, "What does '%s' for %s mean?\n" + warning("What does '%s' for %s mean?\n" "If you want to trace into a file, then please set " "%s to an absolute pathname (starting with /).\n" - "Defaulting to tracing on stderr...\n", + "Defaulting to tracing on stderr...", trace, key->key, key->key); key->fd = STDERR_FILENO; } @@ -135,7 +134,7 @@ static int prepare_trace_line(const char *file, int line, static void trace_write(struct trace_key *key, const void *buf, unsigned len) { if (write_in_full(get_trace_fd(key), buf, len) < 0) - fprintf(stderr, "%s: write error (%s)\n", err_msg, strerror(errno)); + warning("%s: write error (%s)", err_msg, strerror(errno)); } void trace_verbatim(struct trace_key *key, const void *buf, unsigned len) -- 2.9.2.670.g42e63de ``` ## Jeff King, 2016-08-03 23:01 Subject: [PATCH 6/7] trace: disable key after write error Message-ID: <20160803230103.daexq233ufrttnmn@sigill.intra.peff.net> URL: https://gitlist.dev/e/20160803230103.daexq233ufrttnmn%40sigill.intra.peff.net In-Reply-To: <20160803225600.fgm23bdacunmrw44@sigill.intra.peff.net> ``` 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 --- trace.c | 1 + 1 file changed, 1 insertion(+) diff --git a/trace.c b/trace.c index 4efb256..083eb98 100644 --- a/trace.c +++ b/trace.c @@ -134,6 +134,7 @@ static void trace_write(struct trace_key *key, const void *buf, unsigned len) normalize_trace_key(&key); warning("unable to write trace for %s: %s", key->key, strerror(errno)); + trace_disable(key); } } -- 2.9.2.670.g42e63de ``` ## Jeff King, 2016-08-03 22:56 Subject: [PATCH 0/7] minor trace fixes and cosmetic improvements Message-ID: <20160803225600.fgm23bdacunmrw44@sigill.intra.peff.net> URL: https://gitlist.dev/e/20160803225600.fgm23bdacunmrw44%40sigill.intra.peff.net In-Reply-To: <20160803213920.jg3eshy57bsldqjh@sigill.intra.peff.net> ``` On Wed, Aug 03, 2016 at 05:39:20PM -0400, Jeff King wrote: > Thinking about (2), I'd go so far as to say that the trace actually > should just be using: > > if (write_in_full(...) < 0) > warning("unable to write trace to ...: %s", strerror(errno)); > > and we should get rid of write_or_whine_pipe entirely. 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 ``` ## Jeff King, 2016-08-03 23:01 Subject: [PATCH 7/7] write_or_die: drop write_or_whine_pipe() Message-ID: <20160803230141.fujy7umrihw2utpu@sigill.intra.peff.net> URL: https://gitlist.dev/e/20160803230141.fujy7umrihw2utpu%40sigill.intra.peff.net In-Reply-To: <20160803225600.fgm23bdacunmrw44@sigill.intra.peff.net> ``` 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 --- cache.h | 1 - write_or_die.c | 12 ------------ 2 files changed, 13 deletions(-) diff --git a/cache.h b/cache.h index b5f76a4..3885911 100644 --- a/cache.h +++ b/cache.h @@ -1740,7 +1740,6 @@ extern int copy_file(const char *dst, const char *src, int mode); extern int copy_file_with_time(const char *dst, const char *src, int mode); extern void write_or_die(int fd, const void *buf, size_t count); -extern int write_or_whine_pipe(int fd, const void *buf, size_t count, const char *msg); extern void fsync_or_die(int fd, const char *); extern ssize_t read_in_full(int fd, void *buf, size_t count); diff --git a/write_or_die.c b/write_or_die.c index 9816879..0734432 100644 --- a/write_or_die.c +++ b/write_or_die.c @@ -82,15 +82,3 @@ void write_or_die(int fd, const void *buf, size_t count) die_errno("write error"); } } - -int write_or_whine_pipe(int fd, const void *buf, size_t count, const char *msg) -{ - if (write_in_full(fd, buf, count) < 0) { - check_pipe(errno); - fprintf(stderr, "%s: write error (%s)\n", - msg, strerror(errno)); - return 0; - } - - return 1; -} -- 2.9.2.670.g42e63de ``` ## Jeff King, 2016-08-03 22:56 Subject: [PATCH 1/7] trace: handle NULL argument in trace_disable() Message-ID: <20160803225657.vdjih5mzvdmilx4d@sigill.intra.peff.net> URL: https://gitlist.dev/e/20160803225657.vdjih5mzvdmilx4d%40sigill.intra.peff.net In-Reply-To: <20160803225600.fgm23bdacunmrw44@sigill.intra.peff.net> ``` 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 --- trace.c | 20 ++++++++++++++++---- 1 file changed, 16 insertions(+), 4 deletions(-) diff --git a/trace.c b/trace.c index 4aeea60..f204a7d 100644 --- a/trace.c +++ b/trace.c @@ -25,15 +25,25 @@ #include "cache.h" #include "quote.h" +/* + * "Normalize" a key argument by converting NULL to our trace_default, + * and otherwise passing through the value. All caller-facing functions + * should normalize their inputs in this way, though most get it + * for free by calling get_trace_fd() (directly or indirectly). + */ +static void normalize_trace_key(struct trace_key **key) +{ + static struct trace_key trace_default = { "GIT_TRACE" }; + if (!*key) + *key = &trace_default; +} + /* Get a trace file descriptor from "key" env variable. */ static int get_trace_fd(struct trace_key *key) { - static struct trace_key trace_default = { "GIT_TRACE" }; const char *trace; - /* use default "GIT_TRACE" if NULL */ - if (!key) - key = &trace_default; + normalize_trace_key(&key); /* don't open twice */ if (key->initialized) @@ -75,6 +85,8 @@ static int get_trace_fd(struct trace_key *key) void trace_disable(struct trace_key *key) { + normalize_trace_key(&key); + if (key->need_close) close(key->fd); key->fd = 0; -- 2.9.2.670.g42e63de ``` ## Jeff King, 2016-08-03 23:04 Subject: Re: [PATCH 0/7] minor trace fixes and cosmetic improvements Message-ID: <20160803230422.vec7mhjo6jfzbpap@sigill.intra.peff.net> URL: https://gitlist.dev/e/20160803230422.vec7mhjo6jfzbpap%40sigill.intra.peff.net In-Reply-To: <20160803225600.fgm23bdacunmrw44@sigill.intra.peff.net> ``` On Wed, Aug 03, 2016 at 06:56:00PM -0400, Jeff King wrote: > On Wed, Aug 03, 2016 at 05:39:20PM -0400, Jeff King wrote: > > > Thinking about (2), I'd go so far as to say that the trace actually > > should just be using: > > > > if (write_in_full(...) < 0) > > warning("unable to write trace to ...: %s", strerror(errno)); > > > > and we should get rid of write_or_whine_pipe entirely. > > 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() 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 ``` ## Jeff King, 2016-08-03 23:00 Subject: [PATCH 4/7] trace: cosmetic fixes for error messages Message-ID: <20160803230022.drw4kcwgheeqn3xr@sigill.intra.peff.net> URL: https://gitlist.dev/e/20160803230022.drw4kcwgheeqn3xr%40sigill.intra.peff.net In-Reply-To: <20160803225600.fgm23bdacunmrw44@sigill.intra.peff.net> ``` 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 --- 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(-) diff --git a/trace.c b/trace.c index 6a77e4d..4d68eb5 100644 --- a/trace.c +++ b/trace.c @@ -61,8 +61,8 @@ static int get_trace_fd(struct trace_key *key) else if (is_absolute_path(trace)) { int fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666); if (fd == -1) { - warning("Could not open '%s' for tracing: %s\n" - "Defaulting to tracing on stderr...", + warning("could not open '%s' for tracing: %s\n" + " Defaulting to tracing on stderr...", trace, strerror(errno)); key->fd = STDERR_FILENO; } else { @@ -70,11 +70,11 @@ static int get_trace_fd(struct trace_key *key) key->need_close = 1; } } else { - warning("What does '%s' for %s mean?\n" - "If you want to trace into a file, then please set " - "%s to an absolute pathname (starting with /).\n" - "Defaulting to tracing on stderr...", - trace, key->key, key->key); + warning("unknown trace value for '%s': %s\n" + " If you want to trace into a file, then please set %s\n" + " to an absolute pathname (starting with /)\n" + " Defaulting to tracing on stderr...", + key->key, trace, key->key); key->fd = STDERR_FILENO; } @@ -93,7 +93,7 @@ void trace_disable(struct trace_key *key) key->need_close = 0; } -static const char err_msg[] = "Could not trace into fd given by " +static const char err_msg[] = "could not trace into fd given by " "GIT_TRACE environment variable"; static int prepare_trace_line(const char *file, int line, -- 2.9.2.670.g42e63de ``` ## Jeff King, 2016-08-03 23:00 Subject: [PATCH 5/7] trace: correct variable name in write() error message Message-ID: <20160803230032.hgbq4kdd6jiwcxb7@sigill.intra.peff.net> URL: https://gitlist.dev/e/20160803230032.hgbq4kdd6jiwcxb7%40sigill.intra.peff.net In-Reply-To: <20160803225600.fgm23bdacunmrw44@sigill.intra.peff.net> ``` 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 --- trace.c | 10 +++++----- 1 file changed, 5 insertions(+), 5 deletions(-) diff --git a/trace.c b/trace.c index 4d68eb5..4efb256 100644 --- a/trace.c +++ b/trace.c @@ -93,9 +93,6 @@ void trace_disable(struct trace_key *key) key->need_close = 0; } -static const char err_msg[] = "could not trace into fd given by " - "GIT_TRACE environment variable"; - static int prepare_trace_line(const char *file, int line, struct trace_key *key, struct strbuf *buf) { @@ -133,8 +130,11 @@ static int prepare_trace_line(const char *file, int line, static void trace_write(struct trace_key *key, const void *buf, unsigned len) { - if (write_in_full(get_trace_fd(key), buf, len) < 0) - warning("%s: write error (%s)", err_msg, strerror(errno)); + if (write_in_full(get_trace_fd(key), buf, len) < 0) { + normalize_trace_key(&key); + warning("unable to write trace for %s: %s", + key->key, strerror(errno)); + } } void trace_verbatim(struct trace_key *key, const void *buf, unsigned len) -- 2.9.2.670.g42e63de ``` ## Junio C Hamano, 2016-08-04 20:41 Subject: Re: [PATCH 3/7] trace: use warning() for printing trace errors Message-ID: URL: https://gitlist.dev/e/xmqqk2fw1d41.fsf%40gitster.mtv.corp.google.com In-Reply-To: <20160803225826.hlr273h4cy2hcfyk@sigill.intra.peff.net> ``` Jeff King writes: > 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!). I think the last bit is about to change; cf. 545f13c0 (usage: add set_warn_routine(), 2016-07-30) on cc/apply-am topic. ``` ## Junio C Hamano, 2016-08-04 20:42 Subject: Re: [PATCH 4/7] trace: cosmetic fixes for error messages Message-ID: URL: https://gitlist.dev/e/xmqqfuqk1d23.fsf%40gitster.mtv.corp.google.com In-Reply-To: <20160803230022.drw4kcwgheeqn3xr@sigill.intra.peff.net> ``` Jeff King writes: > 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). Yes, yes. ``` ## Junio C Hamano, 2016-08-04 20:45 Subject: Re: [PATCH 6/7] trace: disable key after write error Message-ID: URL: https://gitlist.dev/e/xmqq8twc1cx4.fsf%40gitster.mtv.corp.google.com In-Reply-To: <20160803230103.daexq233ufrttnmn@sigill.intra.peff.net> ``` Jeff King writes: > 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. 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. ``` ## Jeff King, 2016-08-04 21:21 Subject: Re: [PATCH 3/7] trace: use warning() for printing trace errors Message-ID: <20160804212157.cn7ecyxcbyf4okd7@sigill.intra.peff.net> URL: https://gitlist.dev/e/20160804212157.cn7ecyxcbyf4okd7%40sigill.intra.peff.net In-Reply-To: ``` On Thu, Aug 04, 2016 at 01:41:02PM -0700, Junio C Hamano wrote: > Jeff King writes: > > > 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!). > > I think the last bit is about to change; cf. 545f13c0 (usage: add > set_warn_routine(), 2016-07-30) on cc/apply-am topic. 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, 2016-08-04 21:22 Subject: Re: [PATCH 6/7] trace: disable key after write error Message-ID: <20160804212244.cilov7i2uelg7lnh@sigill.intra.peff.net> URL: https://gitlist.dev/e/20160804212244.cilov7i2uelg7lnh%40sigill.intra.peff.net In-Reply-To: ``` On Thu, Aug 04, 2016 at 01:45:11PM -0700, Junio C Hamano wrote: > Jeff King writes: > > > 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. > > 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. Yeah, I was tempted to strip that out, too. I'll look into preparing a patch on top. -Peff ``` ## Junio C Hamano, 2016-08-04 21:28 Subject: Re: [PATCH 3/7] trace: use warning() for printing trace errors Message-ID: URL: https://gitlist.dev/e/xmqqy44cz0k6.fsf%40gitster.mtv.corp.google.com In-Reply-To: <20160804212157.cn7ecyxcbyf4okd7@sigill.intra.peff.net> ``` Jeff King writes: > 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. 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. ``` ## Jeff King, 2016-08-05 07:58 Subject: Re: [PATCH 6/7] trace: disable key after write error Message-ID: <20160805075838.zkwoyorvdc4ljn6l@sigill.intra.peff.net> URL: https://gitlist.dev/e/20160805075838.zkwoyorvdc4ljn6l%40sigill.intra.peff.net In-Reply-To: <20160804212244.cilov7i2uelg7lnh@sigill.intra.peff.net> ``` On Thu, Aug 04, 2016 at 05:22:44PM -0400, Jeff King wrote: > On Thu, Aug 04, 2016 at 01:45:11PM -0700, Junio C Hamano wrote: > > > Jeff King writes: > > > > > 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. > > > > 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. > > Yeah, I was tempted to strip that out, too. I'll look into preparing a > patch on top. 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 --- trace.c | 10 ++++------ 1 file changed, 4 insertions(+), 6 deletions(-) diff --git a/trace.c b/trace.c index 083eb98..7508aea 100644 --- a/trace.c +++ b/trace.c @@ -61,10 +61,9 @@ static int get_trace_fd(struct trace_key *key) else if (is_absolute_path(trace)) { int fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666); if (fd == -1) { - warning("could not open '%s' for tracing: %s\n" - " Defaulting to tracing on stderr...", + warning("could not open '%s' for tracing: %s", trace, strerror(errno)); - key->fd = STDERR_FILENO; + trace_disable(key); } else { key->fd = fd; key->need_close = 1; @@ -72,10 +71,9 @@ static int get_trace_fd(struct trace_key *key) } else { warning("unknown trace value for '%s': %s\n" " If you want to trace into a file, then please set %s\n" - " to an absolute pathname (starting with /)\n" - " Defaulting to tracing on stderr...", + " to an absolute pathname (starting with /)", key->key, trace, key->key); - key->fd = STDERR_FILENO; + trace_disable(key); } key->initialized = 1; -- 2.9.2.707.g48ee8b7 ``` ## Jeff King, 2016-08-05 07:56 Subject: Re: [PATCH 3/7] trace: use warning() for printing trace errors Message-ID: <20160805075600.dzt4hfvcdgruo2ef@sigill.intra.peff.net> URL: https://gitlist.dev/e/20160805075600.dzt4hfvcdgruo2ef%40sigill.intra.peff.net In-Reply-To: ``` On Thu, Aug 04, 2016 at 02:28:09PM -0700, Junio C Hamano wrote: > Jeff King writes: > > > 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. > > 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. 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 --- trace.c | 11 +++++------ 1 file changed, 5 insertions(+), 6 deletions(-) diff --git a/trace.c b/trace.c index bdbe149..6a77e4d 100644 --- a/trace.c +++ b/trace.c @@ -61,9 +61,8 @@ static int get_trace_fd(struct trace_key *key) else if (is_absolute_path(trace)) { int fd = open(trace, O_WRONLY | O_APPEND | O_CREAT, 0666); if (fd == -1) { - fprintf(stderr, - "Could not open '%s' for tracing: %s\n" - "Defaulting to tracing on stderr...\n", + warning("Could not open '%s' for tracing: %s\n" + "Defaulting to tracing on stderr...", trace, strerror(errno)); key->fd = STDERR_FILENO; } else { @@ -71,10 +70,10 @@ static int get_trace_fd(struct trace_key *key) key->need_close = 1; } } else { - fprintf(stderr, "What does '%s' for %s mean?\n" + warning("What does '%s' for %s mean?\n" "If you want to trace into a file, then please set " "%s to an absolute pathname (starting with /).\n" - "Defaulting to tracing on stderr...\n", + "Defaulting to tracing on stderr...", trace, key->key, key->key); key->fd = STDERR_FILENO; } @@ -135,7 +134,7 @@ static int prepare_trace_line(const char *file, int line, static void trace_write(struct trace_key *key, const void *buf, unsigned len) { if (write_in_full(get_trace_fd(key), buf, len) < 0) - fprintf(stderr, "%s: write error (%s)\n", err_msg, strerror(errno)); + warning("%s: write error (%s)", err_msg, strerror(errno)); } void trace_verbatim(struct trace_key *key, const void *buf, unsigned len) -- 2.9.2.707.g48ee8b7 ``` ## Jeff King, 2016-08-05 08:00 Subject: Re: [PATCH 4/7] trace: cosmetic fixes for error messages Message-ID: <20160805080016.tne7lvvvaw3viot2@sigill.intra.peff.net> URL: https://gitlist.dev/e/20160805080016.tne7lvvvaw3viot2%40sigill.intra.peff.net In-Reply-To: ``` On Thu, Aug 04, 2016 at 01:42:12PM -0700, Junio C Hamano wrote: > Jeff King writes: > > > 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). > > Yes, yes. 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 ``` ## Christian Couder, 2016-08-05 07:59 Subject: Re: [PATCH 3/7] trace: use warning() for printing trace errors Message-ID: URL: https://gitlist.dev/e/CAP8UFD3hvrrwmnyF0PLreAos62hN_1W4bwYV9toMQ-vQQ6rgog%40mail.gmail.com In-Reply-To: ``` On Thu, Aug 4, 2016 at 11:28 PM, Junio C Hamano wrote: > Jeff King writes: > >> 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. > > 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. Ok, I will reroll soon with Peff's suggested changes. ``` ## Junio C Hamano, 2016-08-05 18:41 Subject: Re: [PATCH 3/7] trace: use warning() for printing trace errors Message-ID: URL: https://gitlist.dev/e/xmqqwpjvvz0x.fsf%40gitster.mtv.corp.google.com In-Reply-To: ``` Christian Couder writes: > On Thu, Aug 4, 2016 at 11:28 PM, Junio C Hamano wrote: >> Jeff King writes: >> >>> 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. >> >> 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. > > Ok, I will reroll soon with Peff's suggested changes. Thanks. ```