Did we break receive-pack recently?

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?

On Sat, Aug 4, 2012 at 6:55 PM, Junio C Hamano [off-list ref] 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

On Sun, Aug 5, 2012 at 6:37 PM, Brandon Casey [off-list ref] wrote:

On Sat, Aug 4, 2012 at 6:55 PM, Junio C Hamano [off-list ref] wrote:

quoted

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

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 <redacted>
---
 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

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 <redacted>
---
 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

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 <redacted>
---
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