Hi Gábor,
On Mon, 13 Jan 2020, SZEDER Gábor wrote:
> On Mon, Jan 13, 2020 at 08:29:22AM +0000, Johannes Schindelin via GitGitGadget wrote:
> > From: Johannes Schindelin <johannes.schindelin@xxxxxx>
> >
> > As noticed by Gábor Szeder, if we want to run `git add -p` with
> > redirected input through `test_must_fail` in the test suite, we must
> > expect that a SIGPIPE can happen due to `stdin` coming to its end.
>
> I don't think this issue is related to the redirected input: I
> modified that flaky test to send "unlimited" data to 'git add's stdin,
> i.e.:
>
> /usr/bin/yes | test_must_fail force_color git add -p
>
> and the test with --stress still failed with SIGPIPE all the same and
> just as fast.
>
> After looking into it, the issue seems to be sending data to the
> broken diffFilter process.
Ouch. Thank you for investigating. For my education, how did you debug
this? I could not find a way to identify *what* caused that SIGPIPE...
> So in that test the diff is "filtered" through 'echo too-short', which
> exits real fast, and doesn't read its standard input at all (well, apart
> from e.g. the usual kernel buffering that might happen on a pipe between
> the two processes). Making sure that the diffFilter process reads all
> the data before exiting, i.e. changing it to:
>
> test_config interactive.diffFilter "cat >/dev/null ; echo too-short" &&
>
> made the test reliable, with over 2000 --stress repetitions, and that
> with only a single "y" on 'git add's stdin.
Ah, my diff filter simply ignores the `stdin`... That's easy enough to
fix, and since real-world diff filters probably won't just blatantly
ignore the input, I think it is legitimate to change the test.
> Now, merely tweaking the test is clearly insufficient, because we not
> only want the test to be realiable, but we want 'git add' to die
> gracefully when users out there mess up their configuration.
I think it is sufficient to tweak the test, but I agree that a better
error message might be good when users out there mess up their
configuration.
> Ignoring SIGPIPE can surely accomplish that, but I'm not sure about
> the scope. I mean your patch seems to ignore SIGPIPE basically for
> almost the whole 'git add -(i|p)' process, but perhaps it should be
> limited only to the surroundings of the pipe_command() call running
> the diffFilter, and be done as part of the next patch adding the 'if
> (diff_filter)' block.
Right. Very heavy-handed, and probably inviting unwanted side effects.
> Furthermore, I'm worried that by simply ignoring SIGPIPE we might just
> ignore a more fundamental issue in pipe_command(): shouldn't that
> function be smart enough not to write() to a fd that has no one on the
> other side to read it in the first place?!
>
> So, when the diffFilter process exits unexpectedly early, then the
> poll() call in pipe_command() -> pump_io() -> pump_io_round() returns
> with success and usually sets 'revents' for the child process' stdin
> to 12 (i.e. 'POLLOUT | POLLERR'; gah, how I hate unnamed constants :).
> Unfortunately, at that point we don't take any special action on
> POLLERR, but call xwrite() to try to write to the dead fd anyway,
> which then promptly triggers SIGPIPE. (This is what usually happens
> when stepping through the statements of those functions in a debugger,
> and the diffFilter process has all the time in the world to exit.)
>
> We could handle POLLERR with a patch like this:
>
> --- >8 ---
>
> Subject: run-command: handle POLLERR in pump_io_round() to reduce risk of SIGPIPE
>
> diff --git a/run-command.c b/run-command.c
> index 3449db319b..57093f0acc 100644
> --- a/run-command.c
> +++ b/run-command.c
> @@ -1416,25 +1416,31 @@ static int pump_io_round(struct io_pump *slots, int nr, struct pollfd *pfd)
> if (poll(pfd, pollsize, -1) < 0) {
> if (errno == EINTR)
> return 1;
> die_errno("poll failed");
> }
>
> for (i = 0; i < nr; i++) {
> struct io_pump *io = &slots[i];
>
> if (io->fd < 0)
> continue;
>
> - if (!(io->pfd->revents & (POLLOUT|POLLIN|POLLHUP|POLLERR|POLLNVAL)))
> + if (io->pfd->revents & POLLERR) {
> + io->error = ECONNRESET; /* What should we report to the caller? */
> + close(io->fd);
> + io->fd = -1;
> + continue;
> + }
> + if (!(io->pfd->revents & (POLLOUT|POLLIN|POLLHUP|POLLNVAL)))
> continue;
>
> if (io->type == POLLOUT) {
> ssize_t len = xwrite(io->fd,
> io->u.out.buf, io->u.out.len);
> if (len < 0) {
> io->error = errno;
> close(io->fd);
> io->fd = -1;
> } else {
> io->u.out.buf += len;
> io->u.out.len -= len;
>
> --- >8 ---
>
> Unfortunately #1, this changes the error 'git add -p' dies with from:
>
> error: mismatched output from interactive.diffFilter
>
> to:
>
> error: failed to run 'echo too-short'
>
> It might affect other commands as well, but FWIW the test suite
> doesn't catch any.
Hmm. My first impression is that the error message could be a bit better,
but that it is probably a good thing to have. It would have helped _me_
understand the issue at hand.
> Unfortunately #2, the above patch doesn't completely eliminates the
> SIGPIPE, but only (greatly) reduces its probability. It is possible
> that:
>
> - poll() returns with success and indicating a writable fd without
> any error, i.e. 'revents = 4'.
>
> - the bogus diffFilter exits, closing its stdin.
>
> - 'git add' attempts to xwrite() to the now closed fd, and triggers
> a SIGPIPE right away.
>
> This happens much rarer, 'GIT_TEST_ADD_I_USE_BUILTIN=1
> ./t3701-add-interactive.sh -r 39,49 --stress-jobs=<4*nr-of-cores>
> --stress' tends to take over 200 repetitions. The patch below
> reproduces it fairly reliably by adding two strategically-placed
> sleep()s, with a bit of extra debug output:
>
> --- >8 ---
>
> diff --git a/add-patch.c b/add-patch.c
> index d8dafa8168..0fd017bbd3 100644
> --- a/add-patch.c
> +++ b/add-patch.c
> @@ -421,6 +421,7 @@ static int parse_diff(struct add_p_state *s, const struct pathspec *ps)
> filter_cp.git_cmd = 0;
> filter_cp.use_shell = 1;
> strbuf_reset(&s->buf);
> + fprintf(stderr, "about to run diffFilter\n");
> if (pipe_command(&filter_cp,
> colored->buf, colored->len,
> &s->buf, colored->len,
> diff --git a/run-command.c b/run-command.c
> index 57093f0acc..49ae88a922 100644
> --- a/run-command.c
> +++ b/run-command.c
> @@ -1419,6 +1419,7 @@ static int pump_io_round(struct io_pump *slots, int nr, struct pollfd *pfd)
> die_errno("poll failed");
> }
>
> + sleep(2);
> for (i = 0; i < nr; i++) {
> struct io_pump *io = &slots[i];
>
> @@ -1435,8 +1436,11 @@ static int pump_io_round(struct io_pump *slots, int nr, struct pollfd *pfd)
> continue;
>
> if (io->type == POLLOUT) {
> - ssize_t len = xwrite(io->fd,
> + ssize_t len;
> + fprintf(stderr, "attempting to xwrite() %lu bytes to a fd with revents flags 0x%hx\n", io->u.out.len, io->pfd->revents);
> + len = xwrite(io->fd,
> io->u.out.buf, io->u.out.len);
> + fprintf(stderr, "after xwrite()\n");
> if (len < 0) {
> io->error = errno;
> close(io->fd);
> diff --git a/t/t3701-add-interactive.sh b/t/t3701-add-interactive.sh
> index 12ee321707..acffc9af37 100755
> --- a/t/t3701-add-interactive.sh
> +++ b/t/t3701-add-interactive.sh
> @@ -561,7 +561,7 @@ test_expect_success 'detect bogus diffFilter output' '
> git reset --hard &&
>
> echo content >test &&
> - test_config interactive.diffFilter "echo too-short" &&
> + test_config interactive.diffFilter "sleep 1 ; echo too-short" &&
> printf y >y &&
> test_must_fail force_color git add -p <y
> '
>
> --- >8 ---
>
> and 'GIT_TEST_ADD_I_USE_BUILTIN=1 ./t3701-add-interactive.sh -r 39,49'
> fails with:
>
> + test_must_fail force_color git add -p
> about to run diffFilter
> attempting to xwrite() 224 bytes to a fd with revents flags 0x4
> test_must_fail: died by signal 13: force_color git add -p
>
> I don't understand why we get SIGPIPE right away instead of some error
> that we can act upon (ECONNRESET?).
Isn't it buffered?
In any case, I would take the above-mentioned patch, even if it makes it
"only" less likely to hit `SIGPIPE`.
> FWIW, it fails the same way not only on my box, but on Travis CI's Linux
> and OSX images as well.
>
> https://travis-ci.org/szeder/git/jobs/636446843#L2937
>
>
> Cc'ing Peff for all things SIGPIPE :) who also happens to be the
> author of both pipe_command() and that now flaky test.
I'll go with Peff's suggestion to use `sed 1d` instead of `echo
too-short`.
Thanks,
Dscho
