Did we break receive-pack recently?

Did we break receive-pack recently?

[Junio C Hamano]

I just saw this:

    $ git push ko
    ko: Counting objects: 332, done.
    Delta compression using up to 4 threads.
    Compressing objects: 100% (110/110), done.
    Writing objects: 100% (130/130), 32.27 KiB, done.
    Total 130 (delta 106), reused 21 (delta 20)
    Auto packing the repository for optimum performance.
    fatal: protocol error: bad line length character: Remo
    error: error in sideband demultiplexer
    To ra.kernel.org:/pub/scm/git/git.git
    ...

What is unusual with this push is that it happened to trigger the
auto-gc on the receiving end and the message "Auto packing the
repository..." came back to the pusher just fine, but somebody
nearby seem to have tried to say "Remo"(te---probably) without
properly using the sideband.

Does this ring a bell to anybody?

Re: Did we break receive-pack recently?

[Brandon Casey]

On Sat, Aug 4, 2012 at 6:55 PM, Junio C Hamano <gitster@pobox.com> wrote:
> I just saw this:
>
>     $ git push ko
>     ko: Counting objects: 332, done.
>     Delta compression using up to 4 threads.
>     Compressing objects: 100% (110/110), done.
>     Writing objects: 100% (130/130), 32.27 KiB, done.
>     Total 130 (delta 106), reused 21 (delta 20)
>     Auto packing the repository for optimum performance.
>     fatal: protocol error: bad line length character: Remo
>     error: error in sideband demultiplexer
>     To ra.kernel.org:/pub/scm/git/git.git
>     ...
>
> What is unusual with this push is that it happened to trigger the
> auto-gc on the receiving end and the message "Auto packing the
> repository..." came back to the pusher just fine, but somebody
> nearby seem to have tried to say "Remo"(te---probably) without
> properly using the sideband.

Or perhaps "Remo" is short for "Removing...".

Perhaps this is the source:

   $ grep Remo builtin/prune.c
   printf("Removing stale temporary file %s\n", fullpath);

-Brandon

Re: Did we break receive-pack recently?

[Brandon Casey]

On Sun, Aug 5, 2012 at 6:37 PM, Brandon Casey <drafnel@gmail.com> wrote:
> On Sat, Aug 4, 2012 at 6:55 PM, Junio C Hamano <gitster@pobox.com> wrote:
>> I just saw this:
>>
>>     $ git push ko
>>     ko: Counting objects: 332, done.
>>     Delta compression using up to 4 threads.
>>     Compressing objects: 100% (110/110), done.
>>     Writing objects: 100% (130/130), 32.27 KiB, done.
>>     Total 130 (delta 106), reused 21 (delta 20)
>>     Auto packing the repository for optimum performance.
>>     fatal: protocol error: bad line length character: Remo
>>     error: error in sideband demultiplexer
>>     To ra.kernel.org:/pub/scm/git/git.git
>>     ...
>>
>> What is unusual with this push is that it happened to trigger the
>> auto-gc on the receiving end and the message "Auto packing the
>> repository..." came back to the pusher just fine, but somebody
>> nearby seem to have tried to say "Remo"(te---probably) without
>> properly using the sideband.
>
> Or perhaps "Remo" is short for "Removing...".
>
> Perhaps this is the source:
>
>    $ grep Remo builtin/prune.c
>    printf("Removing stale temporary file %s\n", fullpath);

Verified...

test_path=`pwd` &&
git init test_repo1 &&
( cd test_repo1 &&
  echo D >file.txt &&
  git add . &&
  git commit -m 'Commit something that hashes to 17...' &&
  echo MN >file.txt &&
  git commit -a -m 'Commit something else that hashes to 17...'
) &&
git init --bare test_repo2.git &&
( cd test_repo2.git &&
  git config gc.auto 1 &&
  touch -d '2012-07-01' objects/tmp_test
) &&
( cd test_repo1 &&
  git push "file://$test_path/test_repo2.git" HEAD:refs/heads/master
)

It seems to have been broken since we added 'gc --auto' to receive
pack in 2009 (or maybe since I added that printf to prune.c in 2008
depending on how you look at it :b ).  Apparently it's something not
very likely to be triggered.  Probably because most servers running
git daemon frequently run 'git gc'.  Wonder what k.org's policy is?

I think the original thinking behind writing to stdout
indiscriminately was that removing a temporary object was something
that was considered unusual, so the user should always be informed.
This is unlike removing a stale object, which is something that is
expected during normal usage.  If a stale temporary object is removed,
then it means that some piece of git which should have removed it,
failed to do so.

We could write the message to stderr instead, but I think the full
path to a temporary stale object is not appropriate to communicate to
remote users over the wire.

So, I think it's best just to protect it with 'if (show_only ||
verbose)' like the other informational messages.

Patch forthcoming, hopefully with a test.  Doesn't look like we have
anything testing the auto-gc spawned from receive-pack.  I'll see if I
can come up with something.

-Brandon

[PATCH 1/2] t/t5400: demonstrate breakage caused by informational message from prune

[Brandon Casey]

When receive-pack triggers 'git gc --auto' and 'git prune' is called to
remove a stale temporary object, 'git prune' prints an informational
message to stdout about the file that it will remove.  Since this message
is written to stdout, it is sent back over the transport channel to the git
client which tries to interpret it as part of the pack protocol and then
promptly terminates with a complaint about a protocol error.

Introduce a test which exercises the auto-gc functionality of receive-pack
and demonstrates this breakage.

Signed-off-by: Brandon Casey <drafnel@gmail.com>
---
 t/t5400-send-pack.sh | 35 +++++++++++++++++++++++++++++++++++
 1 file changed, 35 insertions(+)

diff --git a/t/t5400-send-pack.sh b/t/t5400-send-pack.sh
index 0eace37..04a8791 100755
--- a/t/t5400-send-pack.sh
+++ b/t/t5400-send-pack.sh
@@ -145,6 +145,41 @@ test_expect_success 'push --all excludes remote-tracking hierarchy' '
 	)
 '
 
+test_expect_failure 'receive-pack runs auto-gc in remote repo' '
+	rm -rf parent child &&
+	git init parent &&
+	(
+	    # Setup a repo with 2 packs
+	    cd parent &&
+	    echo "Some text" >file.txt &&
+	    git add . &&
+	    git commit -m "Initial commit" &&
+	    git repack -adl &&
+	    echo "Some more text" >>file.txt &&
+	    git commit -a -m "Second commit" &&
+	    git repack
+	) &&
+	cp -a parent child &&
+	(
+	    # Set the child to auto-pack if more than one pack exists
+	    cd child &&
+	    git config gc.autopacklimit 1 &&
+	    git branch test_auto_gc &&
+	    # And create a file that follows the temporary object naming
+	    # convention for the auto-gc to remove
+	    : >.git/objects/tmp_test_object &&
+	    test-chmtime =-1209601 .git/objects/tmp_test_object
+	) &&
+	(
+	    cd parent &&
+	    echo "Even more text" >>file.txt &&
+	    git commit -a -m "Third commit" &&
+	    git send-pack ../child HEAD:refs/heads/test_auto_gc >output 2>&1 &&
+	    grep "Auto packing the repository for optimum performance." output
+	) &&
+	test ! -e child/.git/objects/tmp_test_object
+'
+
 rewound_push_setup() {
 	rm -rf parent child &&
 	mkdir parent &&
-- 
1.7.12.rc1.17.g9a7365c

[PATCH 2/2] prune.c: only print informational message in show_only or verbose mode

[Brandon Casey]

This informational message can cause a problem if 'git prune' is spawned
from an auto-gc during receive-pack.  In this case, the informational
message will be sent back over the wire to the git client and the client
will try to interpret it as part of the pack protocol and will produce an
error.

So let's refrain from producing this message unless show_only or verbose
is enabled.

This fixes the test in t5400.

Signed-off-by: Brandon Casey <drafnel@gmail.com>
---
 builtin/prune.c      | 3 ++-
 t/t5400-send-pack.sh | 2 +-
 2 files changed, 3 insertions(+), 2 deletions(-)

diff --git a/builtin/prune.c b/builtin/prune.c
index b99b635..6cb9944 100644
--- a/builtin/prune.c
+++ b/builtin/prune.c
@@ -25,7 +25,8 @@ static int prune_tmp_object(const char *path, const char *filename)
 		return error("Could not stat '%s'", fullpath);
 	if (st.st_mtime > expire)
 		return 0;
-	printf("Removing stale temporary file %s\n", fullpath);
+	if (show_only || verbose)
+		printf("Removing stale temporary file %s\n", fullpath);
 	if (!show_only)
 		unlink_or_warn(fullpath);
 	return 0;
diff --git a/t/t5400-send-pack.sh b/t/t5400-send-pack.sh
index 04a8791..250c720 100755
--- a/t/t5400-send-pack.sh
+++ b/t/t5400-send-pack.sh
@@ -145,7 +145,7 @@ test_expect_success 'push --all excludes remote-tracking hierarchy' '
 	)
 '
 
-test_expect_failure 'receive-pack runs auto-gc in remote repo' '
+test_expect_success 'receive-pack runs auto-gc in remote repo' '
 	rm -rf parent child &&
 	git init parent &&
 	(
-- 
1.7.12.rc1.17.g9a7365c

Re: [PATCH 2/2] prune.c: only print informational message in show_only or verbose mode

[Junio C Hamano]

Thanks.

This patch may fix the immediate symptom, but I think the right fix
is to correct the way "gc" is invoked by receive-pack, so that
nothing "gc" writes to its standard output can leak to the standard
output of the receive-pack.  After all, receive-pack is the one that
knows that its output is a structured protocol communication channel
and should not be contaminated by random crufts.  Receive-pack is
the one that is responsible to avoid this kind of problem in the
first place.

Once that fix is done, any future changes to "gc" or its subprograms
won't be able to cause the same breakage again.  Which automatically
makes your patch unnecessary.

Something along this line, perhaps.

Note that this chooses to expose what comes out of the standard
output of the subprocess to the standard error to be shown to the
user sitting on the other end.  This is in line with what we do to
all of our hooks (Cf. cd83c74 (Redirect update hook stdout to
stderr., 2006-12-30)).

If we instead want to discard the standard output, we would need to
either extend run_command_v_opt(), or set up our own child_process
and spawn the subprocess using the underlying run_command() API
ourselves.

 builtin/receive-pack.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/builtin/receive-pack.c b/builtin/receive-pack.c
index ee7751a..19bdc66 100644
--- a/builtin/receive-pack.c
+++ b/builtin/receive-pack.c
@@ -979,7 +979,8 @@ int cmd_receive_pack(int argc, const char **argv, const char *prefix)
 			const char *argv_gc_auto[] = {
 				"gc", "--auto", "--quiet", NULL,
 			};
-			run_command_v_opt(argv_gc_auto, RUN_GIT_CMD);
+			int opt = RUN_GIT_CMD | RUN_COMMAND_STDOUT_TO_STDERR;
+			run_command_v_opt(argv_gc_auto, opt);
 		}
 		if (auto_update_server_info)
 			update_server_info(0);
 

Re: [PATCH 2/2] prune.c: only print informational message in show_only or verbose mode

[Junio C Hamano]

Junio C Hamano <gitster@pobox.com> writes:

> Note that this chooses to expose what comes out of the standard
> output of the subprocess to the standard error to be shown to the
> user sitting on the other end.  This is in line with what we do to
> all of our hooks (Cf. cd83c74 (Redirect update hook stdout to
> stderr., 2006-12-30)).

Ok, now a tested patch, on top of your 1/2

-- >8 --
Subject: [PATCH] receive-pack: do not leak output from auto-gc to standard output

The standard output channel of receive-pack is a structured protocol
channel, and subprocesses must never be allowed to leak anything
into it by writing to their standard output.

Use RUN_COMMAND_STDOUT_TO_STDERR option to run_command_v_opt() just
like we do when running hooks to prevent output from "gc" leaking to
the standard output.

Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 builtin/receive-pack.c | 3 ++-
 t/t5400-send-pack.sh   | 2 +-
 2 files changed, 3 insertions(+), 2 deletions(-)

diff --git a/builtin/receive-pack.c b/builtin/receive-pack.c
index 0afb8b2..3f05d97 100644
--- a/builtin/receive-pack.c
+++ b/builtin/receive-pack.c
@@ -977,7 +977,8 @@ int cmd_receive_pack(int argc, const char **argv, const char *prefix)
 			const char *argv_gc_auto[] = {
 				"gc", "--auto", "--quiet", NULL,
 			};
-			run_command_v_opt(argv_gc_auto, RUN_GIT_CMD);
+			int opt = RUN_GIT_CMD | RUN_COMMAND_STDOUT_TO_STDERR;
+			run_command_v_opt(argv_gc_auto, opt);
 		}
 		if (auto_update_server_info)
 			update_server_info(0);
diff --git a/t/t5400-send-pack.sh b/t/t5400-send-pack.sh
index 04a8791..250c720 100755
--- a/t/t5400-send-pack.sh
+++ b/t/t5400-send-pack.sh
@@ -145,7 +145,7 @@ test_expect_success 'push --all excludes remote-tracking hierarchy' '
 	)
 '
 
-test_expect_failure 'receive-pack runs auto-gc in remote repo' '
+test_expect_success 'receive-pack runs auto-gc in remote repo' '
 	rm -rf parent child &&
 	git init parent &&
 	(
-- 
1.7.12.rc1.93.g8914ab8

Re: [PATCH 2/2] prune.c: only print informational message in show_only or verbose mode

[Brandon Casey]

On Mon, Aug 6, 2012 at 10:34 PM, Junio C Hamano <gitster@pobox.com> wrote:
> Junio C Hamano <gitster@pobox.com> writes:
>
> Ok, now a tested patch, on top of your 1/2


On Mon, Aug 6, 2012 at 10:32 PM, Jeff King <peff@peff.net> wrote:
>
> This seems like a band-aid. The real problem is that auto-gc can
> interfere with the pack protocol, which it should not be allowed to do,
> no matter what it produces.
>
> We could fix that root cause with this patch (on top of your 1/2):

Anyone else? :)

Ah, I wasn't aware of that feature of run_command.  Both look obviously correct.

And the comment I made yesterday about leaking the full path to the
remote end can be disregarded, since prune will report the path
relative to the repository base.

Thanks,
-Brandon

Re: [PATCH 2/2] prune.c: only print informational message in show_only or verbose mode

[Jeff King]

On Mon, Aug 06, 2012 at 10:44:07PM -0700, Brandon Casey wrote:

> On Mon, Aug 6, 2012 at 10:32 PM, Jeff King <peff@peff.net> wrote:
> >
> > This seems like a band-aid. The real problem is that auto-gc can
> > interfere with the pack protocol, which it should not be allowed to do,
> > no matter what it produces.
> >
> > We could fix that root cause with this patch (on top of your 1/2):
> 
> Anyone else? :)

Sorry to gang up on you. :)

I still think your 2/2 is worth doing independently, though. It is silly
that git-prune will not mention pruned objects without "-v", but will
mention temporary files. They should be in the same category.

-Peff

Re: [PATCH 2/2] prune.c: only print informational message in show_only or verbose mode

[Brandon Casey]

On Mon, Aug 6, 2012 at 11:03 PM, Jeff King <peff@peff.net> wrote:
> On Mon, Aug 06, 2012 at 10:44:07PM -0700, Brandon Casey wrote:
>> Anyone else? :)
>
> Sorry to gang up on you. :)

Heh. :b

> I still think your 2/2 is worth doing independently, though. It is silly
> that git-prune will not mention pruned objects without "-v", but will
> mention temporary files. They should be in the same category.

As I mentioned in an earlier message, I think the original thinking
was that removing a temporary object should be an unusual occurrence
that indicates a failure of some sort, so you want to inform the user
who may want to investigate (of course the file's gone, so what's to
investigate).  Removing a stale object file on the other hand is just
part of the normal operation.  That is why the former is always
printed out and the latter only when -v is used.

That was the original thinking, but I don't think it matters very
much.  Printing both using the same conditions seems valid.  My commit
message should be scrapped and replaced with something like your
paragraph though..

-Brandon

Re: [PATCH 2/2] prune.c: only print informational message in show_only or verbose mode

[Junio C Hamano]

Brandon Casey <drafnel@gmail.com> writes:

> On Mon, Aug 6, 2012 at 11:03 PM, Jeff King <peff@peff.net> wrote:
>> On Mon, Aug 06, 2012 at 10:44:07PM -0700, Brandon Casey wrote:
>>> Anyone else? :)
>>
>> Sorry to gang up on you. :)
>
> Heh. :b
>
>> I still think your 2/2 is worth doing independently, though. It is silly
>> that git-prune will not mention pruned objects without "-v", but will
>> mention temporary files. They should be in the same category.
>
> As I mentioned in an earlier message, I think the original thinking
> was that removing a temporary object should be an unusual occurrence
> that indicates a failure of some sort, so you want to inform the user
> who may want to investigate (of course the file's gone, so what's to
> investigate).  Removing a stale object file on the other hand is just
> part of the normal operation.  That is why the former is always
> printed out and the latter only when -v is used.

That matches my understanding, modulo "may want to investigate" is
probably more like "may want to be reminded of an earlier repack
that was aborted".

> That was the original thinking, but I don't think it matters very
> much.  Printing both using the same conditions seems valid.

Yeah, I agree that it does not make much difference either way and
both ways of thinking feel equally valid.

Re: [PATCH 2/2] prune.c: only print informational message in show_only or verbose mode

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

> I still think your 2/2 is worth doing independently, though. It is silly
> that git-prune will not mention pruned objects without "-v", but will
> mention temporary files. They should be in the same category.

Ok, so I'll queue it as a separate topic with a different
justification.

-- >8 --
From: Brandon Casey <drafnel@gmail.com>
Date: Mon, 6 Aug 2012 22:01:49 -0700
Subject: [PATCH] prune.c: only print informational message in show_only or verbose mode

"git prune" reports removal of loose object files that are no longer
necessary only under the "-v" option, but unconditionally reports
removal of temporary files that are no longer needed.

The original thinking was that presence of a leftover temporary file
should be an unusual occurrence that may indicate an earlier failure
of some sort, and the user may want to be reminded of it.  Removing
an unnecessary loose object file, on the other hand, is just part of
the normal operation.  That is why the former is always printed out
and the latter only when -v is used.

But neither report is particularly useful.  Hide both of these
behind the "-v" option for consistency.

Signed-off-by: Brandon Casey <drafnel@gmail.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>
---
 builtin/prune.c | 3 ++-
 1 file changed, 2 insertions(+), 1 deletion(-)

diff --git a/builtin/prune.c b/builtin/prune.c
index b99b635..6cb9944 100644
--- a/builtin/prune.c
+++ b/builtin/prune.c
@@ -25,7 +25,8 @@ static int prune_tmp_object(const char *path, const char *filename)
 		return error("Could not stat '%s'", fullpath);
 	if (st.st_mtime > expire)
 		return 0;
-	printf("Removing stale temporary file %s\n", fullpath);
+	if (show_only || verbose)
+		printf("Removing stale temporary file %s\n", fullpath);
 	if (!show_only)
 		unlink_or_warn(fullpath);
 	return 0;
-- 
1.7.12.rc2.53.g9ec2ef6

Re: [PATCH 2/2] prune.c: only print informational message in show_only or verbose mode

[Jeff King]

On Tue, Aug 07, 2012 at 02:44:51PM -0700, Junio C Hamano wrote:

> Ok, so I'll queue it as a separate topic with a different
> justification.
> 
> -- >8 --
> From: Brandon Casey <drafnel@gmail.com>
> Date: Mon, 6 Aug 2012 22:01:49 -0700
> Subject: [PATCH] prune.c: only print informational message in show_only or verbose mode
> 
> "git prune" reports removal of loose object files that are no longer
> necessary only under the "-v" option, but unconditionally reports
> removal of temporary files that are no longer needed.
> 
> The original thinking was that presence of a leftover temporary file

s/presence/the &/

> should be an unusual occurrence that may indicate an earlier failure
> of some sort, and the user may want to be reminded of it.  Removing
> an unnecessary loose object file, on the other hand, is just part of
> the normal operation.  That is why the former is always printed out
> and the latter only when -v is used.
> 
> But neither report is particularly useful.  Hide both of these
> behind the "-v" option for consistency.
> 
> Signed-off-by: Brandon Casey <drafnel@gmail.com>
> Signed-off-by: Junio C Hamano <gitster@pobox.com>
> ---

Looks fine to me.  I think tmpfile removal is also not that interesting
in general. A stale file can happen any time the user aborts an
operation via ^C. But I think your justification is sufficient as-is
(and this topic is not worth spending too much more time on).

-Peff

Re: [PATCH 2/2] prune.c: only print informational message in show_only or verbose mode

[Brandon Casey]

On Tue, Aug 7, 2012 at 2:44 PM, Junio C Hamano <gitster@pobox.com> wrote:
> Jeff King <peff@peff.net> writes:
>
>> I still think your 2/2 is worth doing independently, though. It is silly
>> that git-prune will not mention pruned objects without "-v", but will
>> mention temporary files. They should be in the same category.
>
> Ok, so I'll queue it as a separate topic with a different
> justification.

Looks fine to me.  Thanks.

-Brandon

Re: [PATCH 2/2] prune.c: only print informational message in show_only or verbose mode

[Jeff King]

On Mon, Aug 06, 2012 at 10:01:49PM -0700, Brandon Casey wrote:

> This informational message can cause a problem if 'git prune' is spawned
> from an auto-gc during receive-pack.  In this case, the informational
> message will be sent back over the wire to the git client and the client
> will try to interpret it as part of the pack protocol and will produce an
> error.
> 
> So let's refrain from producing this message unless show_only or verbose
> is enabled.

This seems like a band-aid. The real problem is that auto-gc can
interfere with the pack protocol, which it should not be allowed to do,
no matter what it produces.

We could fix that root cause with this patch (on top of your 1/2):

-- >8 --
Subject: [PATCH] receive-pack: redirect auto-gc stdout to stderr

In some cases, git-gc may produce informational messages to
stdout, rather than stderr. This is bad for receive-pack,
because its stdout (and therefore that of its child) is
connected to a git client and speaking pack protocol.
Instead, let's redirect these messages to stderr to avoid
interference and let the client see them.

Signed-off-by: Jeff King <peff@peff.net>
---
We already do the same thing for all of the hooks we run. With this
change, all sub-processes have their stdout redirected (either to a
pipe, or to stderr) except git-unpack-objects.

Looking at unpack-objects, it should not write anything to stdout under
normal circumstances. However, if it is fed more bytes than the
pack data claims (e.g., extra entries beyond what the header claims), it
will send them to stdout. I've never heard of that happening, but
probably it should go to /dev/null, and/or flag an error.

 builtin/receive-pack.c | 3 ++-
 t/t5400-send-pack.sh   | 2 +-
 2 files changed, 3 insertions(+), 2 deletions(-)

diff --git a/builtin/receive-pack.c b/builtin/receive-pack.c
index 0afb8b2..e0b9f2e 100644
--- a/builtin/receive-pack.c
+++ b/builtin/receive-pack.c
@@ -977,7 +977,8 @@ int cmd_receive_pack(int argc, const char **argv, const char *prefix)
 			const char *argv_gc_auto[] = {
 				"gc", "--auto", "--quiet", NULL,
 			};
-			run_command_v_opt(argv_gc_auto, RUN_GIT_CMD);
+			run_command_v_opt(argv_gc_auto,
+					  RUN_GIT_CMD | RUN_COMMAND_STDOUT_TO_STDERR);
 		}
 		if (auto_update_server_info)
 			update_server_info(0);
diff --git a/t/t5400-send-pack.sh b/t/t5400-send-pack.sh
index 04a8791..250c720 100755
--- a/t/t5400-send-pack.sh
+++ b/t/t5400-send-pack.sh
@@ -145,7 +145,7 @@ test_expect_success 'push --all excludes remote-tracking hierarchy' '
 	)
 '
 
-test_expect_failure 'receive-pack runs auto-gc in remote repo' '
+test_expect_success 'receive-pack runs auto-gc in remote repo' '
 	rm -rf parent child &&
 	git init parent &&
 	(
-- 
1.7.12.rc1.12.g6d3a2d7