Re: [PATCH v3 01/10] built-in add -i/-p: treat SIGPIPE as EOF

From: Johannes Schindelin <Johannes.Schindelin@gmx.de>
To: "SZEDER Gábor" <szeder.dev@gmail.com>
Cc: Johannes Schindelin via GitGitGadget <gitgitgadget@gmail.com>,
	git@vger.kernel.org, Jeff King <peff@peff.net>
Subject: Re: [PATCH v3 01/10] built-in add -i/-p: treat SIGPIPE as EOF
Date: Tue, 14 Jan 2020 13:47:43 +0100 (CET)	[thread overview]
Message-ID: <nycvar.QRO.7.76.6.2001141301310.46@tvgsbejvaqbjf.bet> (raw)
In-Reply-To: <20200113170417.GK32750@szeder.dev>

[-- Attachment #1: Type: text/plain, Size: 8829 bytes --]

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@gmx.de>
> >
> > 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