[PATCH] update-ref: fix streaming of status updates

[PATCH] update-ref: fix streaming of status updates

[Patrick Steinhardt]

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

When executing git-update-ref(1) with the `--stdin` flag, then the user
can queue updates and, since e48cf33b61 (update-ref: implement
interactive transaction handling, 2020-04-02), interactively drive the
transaction's state via a set of transactional verbs. This interactivity
is somewhat broken though: while the caller can use these verbs to drive
the transaction's state, the status messages which confirm that a verb
has been processed is not flushed. The caller may thus be left hanging
waiting for the acknowledgement.

Fix the bug by flushing stdout after writing the status update. Add a
test which catches this bug.

Signed-off-by: Patrick Steinhardt <ps@pks.im>
---
 builtin/update-ref.c  | 14 ++++++++++----
 t/t1400-update-ref.sh | 32 ++++++++++++++++++++++++++++++++
 2 files changed, 42 insertions(+), 4 deletions(-)

diff --git a/builtin/update-ref.c b/builtin/update-ref.c
index 6029a80544..a84e7b47a2 100644
--- a/builtin/update-ref.c
+++ b/builtin/update-ref.c
@@ -302,6 +302,12 @@ static void parse_cmd_verify(struct ref_transaction *transaction,
 	strbuf_release(&err);
 }
 
+static void report_ok(const char *command)
+{
+	fprintf(stdout, "%s: ok\n", command);
+	fflush(stdout);
+}
+
 static void parse_cmd_option(struct ref_transaction *transaction,
 			     const char *next, const char *end)
 {
@@ -317,7 +323,7 @@ static void parse_cmd_start(struct ref_transaction *transaction,
 {
 	if (*next != line_termination)
 		die("start: extra input: %s", next);
-	puts("start: ok");
+	report_ok("start");
 }
 
 static void parse_cmd_prepare(struct ref_transaction *transaction,
@@ -328,7 +334,7 @@ static void parse_cmd_prepare(struct ref_transaction *transaction,
 		die("prepare: extra input: %s", next);
 	if (ref_transaction_prepare(transaction, &error))
 		die("prepare: %s", error.buf);
-	puts("prepare: ok");
+	report_ok("prepare");
 }
 
 static void parse_cmd_abort(struct ref_transaction *transaction,
@@ -339,7 +345,7 @@ static void parse_cmd_abort(struct ref_transaction *transaction,
 		die("abort: extra input: %s", next);
 	if (ref_transaction_abort(transaction, &error))
 		die("abort: %s", error.buf);
-	puts("abort: ok");
+	report_ok("abort");
 }
 
 static void parse_cmd_commit(struct ref_transaction *transaction,
@@ -350,7 +356,7 @@ static void parse_cmd_commit(struct ref_transaction *transaction,
 		die("commit: extra input: %s", next);
 	if (ref_transaction_commit(transaction, &error))
 		die("commit: %s", error.buf);
-	puts("commit: ok");
+	report_ok("commit");
 	ref_transaction_free(transaction);
 }
 
diff --git a/t/t1400-update-ref.sh b/t/t1400-update-ref.sh
index 4506cd435b..1e754e258f 100755
--- a/t/t1400-update-ref.sh
+++ b/t/t1400-update-ref.sh
@@ -1598,6 +1598,38 @@ test_expect_success 'transaction cannot restart ongoing transaction' '
 	test_must_fail git show-ref --verify refs/heads/restart
 '
 
+test_expect_success PIPE 'transaction flushes status updates' '
+	mkfifo in out &&
+	(git update-ref --stdin <in >out &) &&
+
+	exec 9>in &&
+	test_when_finished "exec 9>&-" &&
+
+	echo "start" >&9 &&
+	echo "start: ok" >expected &&
+	read line <out &&
+	echo "$line" >actual &&
+	test_cmp expected actual &&
+
+	echo "create refs/heads/flush $A" >&9 &&
+
+	echo prepare >&9 &&
+	echo "prepare: ok" >expected &&
+	read line <out &&
+	echo "$line" >actual &&
+	test_cmp expected actual &&
+
+	# This must now fail given that we have locked the ref.
+	test_must_fail git update-ref refs/heads/flush $B 2>stderr &&
+	grep "fatal: update_ref failed for ref ${SQ}refs/heads/flush${SQ}: cannot lock ref" stderr &&
+
+	echo commit >&9 &&
+	echo "commit: ok" >expected &&
+	read line <out &&
+	echo "$line" >actual &&
+	test_cmp expected actual
+'
+
 test_expect_success 'directory not created deleting packed ref' '
 	git branch d1/d2/r1 HEAD &&
 	git pack-refs --all &&
-- 
2.33.0


[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]

Re: [PATCH] update-ref: fix streaming of status updates

[Junio C Hamano]

Patrick Steinhardt <ps@pks.im> writes:

> When executing git-update-ref(1) with the `--stdin` flag, then the user
> can queue updates and, since e48cf33b61 (update-ref: implement
> interactive transaction handling, 2020-04-02), interactively drive the
> transaction's state via a set of transactional verbs. This interactivity
> is somewhat broken though: while the caller can use these verbs to drive
> the transaction's state, the status messages which confirm that a verb
> has been processed is not flushed. The caller may thus be left hanging
> waiting for the acknowledgement.
>
> Fix the bug by flushing stdout after writing the status update. Add a
> test which catches this bug.

Nobody hit by this for more than a year is interesting.

Will queue.  Thanks.

>
> Signed-off-by: Patrick Steinhardt <ps@pks.im>
> ---
>  builtin/update-ref.c  | 14 ++++++++++----
>  t/t1400-update-ref.sh | 32 ++++++++++++++++++++++++++++++++
>  2 files changed, 42 insertions(+), 4 deletions(-)
>
> diff --git a/builtin/update-ref.c b/builtin/update-ref.c
> index 6029a80544..a84e7b47a2 100644
> --- a/builtin/update-ref.c
> +++ b/builtin/update-ref.c
> @@ -302,6 +302,12 @@ static void parse_cmd_verify(struct ref_transaction *transaction,
>  	strbuf_release(&err);
>  }
>  
> +static void report_ok(const char *command)
> +{
> +	fprintf(stdout, "%s: ok\n", command);
> +	fflush(stdout);
> +}
> +
>  static void parse_cmd_option(struct ref_transaction *transaction,
>  			     const char *next, const char *end)
>  {
> @@ -317,7 +323,7 @@ static void parse_cmd_start(struct ref_transaction *transaction,
>  {
>  	if (*next != line_termination)
>  		die("start: extra input: %s", next);
> -	puts("start: ok");
> +	report_ok("start");
>  }
>  
>  static void parse_cmd_prepare(struct ref_transaction *transaction,
> @@ -328,7 +334,7 @@ static void parse_cmd_prepare(struct ref_transaction *transaction,
>  		die("prepare: extra input: %s", next);
>  	if (ref_transaction_prepare(transaction, &error))
>  		die("prepare: %s", error.buf);
> -	puts("prepare: ok");
> +	report_ok("prepare");
>  }
>  
>  static void parse_cmd_abort(struct ref_transaction *transaction,
> @@ -339,7 +345,7 @@ static void parse_cmd_abort(struct ref_transaction *transaction,
>  		die("abort: extra input: %s", next);
>  	if (ref_transaction_abort(transaction, &error))
>  		die("abort: %s", error.buf);
> -	puts("abort: ok");
> +	report_ok("abort");
>  }
>  
>  static void parse_cmd_commit(struct ref_transaction *transaction,
> @@ -350,7 +356,7 @@ static void parse_cmd_commit(struct ref_transaction *transaction,
>  		die("commit: extra input: %s", next);
>  	if (ref_transaction_commit(transaction, &error))
>  		die("commit: %s", error.buf);
> -	puts("commit: ok");
> +	report_ok("commit");
>  	ref_transaction_free(transaction);
>  }
>  
> diff --git a/t/t1400-update-ref.sh b/t/t1400-update-ref.sh
> index 4506cd435b..1e754e258f 100755
> --- a/t/t1400-update-ref.sh
> +++ b/t/t1400-update-ref.sh
> @@ -1598,6 +1598,38 @@ test_expect_success 'transaction cannot restart ongoing transaction' '
>  	test_must_fail git show-ref --verify refs/heads/restart
>  '
>  
> +test_expect_success PIPE 'transaction flushes status updates' '
> +	mkfifo in out &&
> +	(git update-ref --stdin <in >out &) &&
> +
> +	exec 9>in &&
> +	test_when_finished "exec 9>&-" &&
> +
> +	echo "start" >&9 &&
> +	echo "start: ok" >expected &&
> +	read line <out &&
> +	echo "$line" >actual &&
> +	test_cmp expected actual &&
> +
> +	echo "create refs/heads/flush $A" >&9 &&
> +
> +	echo prepare >&9 &&
> +	echo "prepare: ok" >expected &&
> +	read line <out &&
> +	echo "$line" >actual &&
> +	test_cmp expected actual &&
> +
> +	# This must now fail given that we have locked the ref.
> +	test_must_fail git update-ref refs/heads/flush $B 2>stderr &&
> +	grep "fatal: update_ref failed for ref ${SQ}refs/heads/flush${SQ}: cannot lock ref" stderr &&
> +
> +	echo commit >&9 &&
> +	echo "commit: ok" >expected &&
> +	read line <out &&
> +	echo "$line" >actual &&
> +	test_cmp expected actual
> +'
> +
>  test_expect_success 'directory not created deleting packed ref' '
>  	git branch d1/d2/r1 HEAD &&
>  	git pack-refs --all &&

Re: [PATCH] update-ref: fix streaming of status updates

[Jeff King]

> diff --git a/t/t1400-update-ref.sh b/t/t1400-update-ref.sh
> index 4506cd435b..1e754e258f 100755
> --- a/t/t1400-update-ref.sh
> +++ b/t/t1400-update-ref.sh
> @@ -1598,6 +1598,38 @@ test_expect_success 'transaction cannot restart ongoing transaction' '
>  	test_must_fail git show-ref --verify refs/heads/restart
>  '
>  
> +test_expect_success PIPE 'transaction flushes status updates' '
> +	mkfifo in out &&
> +	(git update-ref --stdin <in >out &) &&
> +
> +	exec 9>in &&
> +	test_when_finished "exec 9>&-" &&
> +
> +	echo "start" >&9 &&
> +	echo "start: ok" >expected &&
> +	read line <out &&
> +	echo "$line" >actual &&
> +	test_cmp expected actual &&
> +
> +	echo "create refs/heads/flush $A" >&9 &&
> +
> +	echo prepare >&9 &&
> +	echo "prepare: ok" >expected &&
> +	read line <out &&
> +	echo "$line" >actual &&
> +	test_cmp expected actual &&

I think this test may be racy. I saw a strange failure from it in CI:

  https://github.com/peff/git/runs/3605506649?check_suite_focus=true#step:5:6734

I can't reproduce the problem locally with "--stress", but the failure
there is on macOS (and likewise, a nearby run failed with a timeout just
for macOS, which could be caused by a racy deadlock).

I'm guessing the problem may be the continued opening and closing of
"out" by the read calls from the shell. The update-ref process may get
SIGPIPE as a result, depending on the write timing.

The solution is to use open a descriptor for "out" like we do for "in",
and then read from that. See 4783e7ea83 (t0008: avoid SIGPIPE race
condition on fifo, 2013-07-12) for some prior art.

-Peff

[PATCH] t1400: avoid SIGPIPE race condition on fifo

[Jeff King]

On Wed, Sep 15, 2021 at 01:13:25PM -0400, Jeff King wrote:

> I think this test may be racy. I saw a strange failure from it in CI:
> 
>   https://github.com/peff/git/runs/3605506649?check_suite_focus=true#step:5:6734
> 
> I can't reproduce the problem locally with "--stress", but the failure
> there is on macOS (and likewise, a nearby run failed with a timeout just
> for macOS, which could be caused by a racy deadlock).

Ah, I just wasn't trying hard enough. Using --run=1,190 lets it run a
lot more tightly, and I got a failure pretty quickly. Here's the fix (on
top of ps/update-ref-batch-flush).

-- >8 --
Subject: [PATCH] t1400: avoid SIGPIPE race condition on fifo

t1400.190 sometimes fails or even hangs because of the way it uses
fifos. Our goal is to interactively read and write lines from
update-ref, so we have two fifos, in and out. We open a descriptor
connected to "in" and redirect output to that, so that update-ref does
not see EOF as it would if we opened and closed it for each "echo" call.

But we don't do the same for the output. This leads to a race where our
"read response <out" has not yet opened the fifo, but update-ref tries
to write to it and gets SIGPIPE. This can result in the test failing, or
worse, hanging as we wait forever for somebody to write to the pipe.

This is the same proble we fixed in 4783e7ea83 (t0008: avoid SIGPIPE
race condition on fifo, 2013-07-12), and we can fix it the same way, by
opening a second long-running descriptor.

Before this patch, running:

  ./t1400-update-ref.sh --run=1,190 --stress

failed or hung within a few dozen iterations. After it, I ran it for
several hundred without problems.

Signed-off-by: Jeff King <peff@peff.net>
---
 t/t1400-update-ref.sh | 8 +++++---
 1 file changed, 5 insertions(+), 3 deletions(-)

diff --git a/t/t1400-update-ref.sh b/t/t1400-update-ref.sh
index 1e754e258f..0d4f73acaa 100755
--- a/t/t1400-update-ref.sh
+++ b/t/t1400-update-ref.sh
@@ -1603,19 +1603,21 @@ test_expect_success PIPE 'transaction flushes status updates' '
 	(git update-ref --stdin <in >out &) &&
 
 	exec 9>in &&
+	exec 8<out &&
 	test_when_finished "exec 9>&-" &&
+	test_when_finished "exec 8<&-" &&
 
 	echo "start" >&9 &&
 	echo "start: ok" >expected &&
-	read line <out &&
+	read line <&8 &&
 	echo "$line" >actual &&
 	test_cmp expected actual &&
 
 	echo "create refs/heads/flush $A" >&9 &&
 
 	echo prepare >&9 &&
 	echo "prepare: ok" >expected &&
-	read line <out &&
+	read line <&8 &&
 	echo "$line" >actual &&
 	test_cmp expected actual &&
 
@@ -1625,7 +1627,7 @@ test_expect_success PIPE 'transaction flushes status updates' '
 
 	echo commit >&9 &&
 	echo "commit: ok" >expected &&
-	read line <out &&
+	read line <&8 &&
 	echo "$line" >actual &&
 	test_cmp expected actual
 '
-- 
2.33.0.917.g33ebf6a5f6

Re: [PATCH] t1400: avoid SIGPIPE race condition on fifo

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> On Wed, Sep 15, 2021 at 01:13:25PM -0400, Jeff King wrote:
>
>> I think this test may be racy. I saw a strange failure from it in CI:
>> 
>>   https://github.com/peff/git/runs/3605506649?check_suite_focus=true#step:5:6734
>> 
>> I can't reproduce the problem locally with "--stress", but the failure
>> there is on macOS (and likewise, a nearby run failed with a timeout just
>> for macOS, which could be caused by a racy deadlock).
>
> Ah, I just wasn't trying hard enough. Using --run=1,190 lets it run a
> lot more tightly, and I got a failure pretty quickly. Here's the fix (on
> top of ps/update-ref-batch-flush).
>
> -- >8 --
> Subject: [PATCH] t1400: avoid SIGPIPE race condition on fifo
>
> t1400.190 sometimes fails or even hangs because of the way it uses
> fifos. Our goal is to interactively read and write lines from
> update-ref, so we have two fifos, in and out. We open a descriptor
> connected to "in" and redirect output to that, so that update-ref does
> not see EOF as it would if we opened and closed it for each "echo" call.

Thanks.  I think I see the same breakage in last night's pushout of
'seen'.

Will queue.

Re: [PATCH] t1400: avoid SIGPIPE race condition on fifo

[Patrick Steinhardt]

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

On Wed, Sep 15, 2021 at 01:24:52PM -0400, Jeff King wrote:
> On Wed, Sep 15, 2021 at 01:13:25PM -0400, Jeff King wrote:
> 
> > I think this test may be racy. I saw a strange failure from it in CI:
> > 
> >   https://github.com/peff/git/runs/3605506649?check_suite_focus=true#step:5:6734
> > 
> > I can't reproduce the problem locally with "--stress", but the failure
> > there is on macOS (and likewise, a nearby run failed with a timeout just
> > for macOS, which could be caused by a racy deadlock).
> 
> Ah, I just wasn't trying hard enough. Using --run=1,190 lets it run a
> lot more tightly, and I got a failure pretty quickly. Here's the fix (on
> top of ps/update-ref-batch-flush).
> 
> -- >8 --
> Subject: [PATCH] t1400: avoid SIGPIPE race condition on fifo
> 
> t1400.190 sometimes fails or even hangs because of the way it uses
> fifos. Our goal is to interactively read and write lines from
> update-ref, so we have two fifos, in and out. We open a descriptor
> connected to "in" and redirect output to that, so that update-ref does
> not see EOF as it would if we opened and closed it for each "echo" call.
> 
> But we don't do the same for the output. This leads to a race where our
> "read response <out" has not yet opened the fifo, but update-ref tries
> to write to it and gets SIGPIPE. This can result in the test failing, or
> worse, hanging as we wait forever for somebody to write to the pipe.
> 
> This is the same proble we fixed in 4783e7ea83 (t0008: avoid SIGPIPE

Type: "proble" -> "problem".

> race condition on fifo, 2013-07-12), and we can fix it the same way, by
> opening a second long-running descriptor.
> 
> Before this patch, running:
> 
>   ./t1400-update-ref.sh --run=1,190 --stress
> 
> failed or hung within a few dozen iterations. After it, I ran it for
> several hundred without problems.
> 
> Signed-off-by: Jeff King <peff@peff.net>
> ---
>  t/t1400-update-ref.sh | 8 +++++---
>  1 file changed, 5 insertions(+), 3 deletions(-)
> 
> diff --git a/t/t1400-update-ref.sh b/t/t1400-update-ref.sh
> index 1e754e258f..0d4f73acaa 100755
> --- a/t/t1400-update-ref.sh
> +++ b/t/t1400-update-ref.sh
> @@ -1603,19 +1603,21 @@ test_expect_success PIPE 'transaction flushes status updates' '
>  	(git update-ref --stdin <in >out &) &&
>  
>  	exec 9>in &&
> +	exec 8<out &&
>  	test_when_finished "exec 9>&-" &&
> +	test_when_finished "exec 8<&-" &&
>  
>  	echo "start" >&9 &&
>  	echo "start: ok" >expected &&
> -	read line <out &&
> +	read line <&8 &&
>  	echo "$line" >actual &&
>  	test_cmp expected actual &&
>  
>  	echo "create refs/heads/flush $A" >&9 &&
>  
>  	echo prepare >&9 &&
>  	echo "prepare: ok" >expected &&
> -	read line <out &&
> +	read line <&8 &&
>  	echo "$line" >actual &&
>  	test_cmp expected actual &&
>  
> @@ -1625,7 +1627,7 @@ test_expect_success PIPE 'transaction flushes status updates' '
>  
>  	echo commit >&9 &&
>  	echo "commit: ok" >expected &&
> -	read line <out &&
> +	read line <&8 &&
>  	echo "$line" >actual &&
>  	test_cmp expected actual
>  '
> -- 
> 2.33.0.917.g33ebf6a5f6
> 

Thanks a lot for digging and fixing my test. The patch looks good to me.

Patrick

[-- Attachment #2: signature.asc --]
[-- Type: application/pgp-signature, Size: 833 bytes --]