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 <gitster@pobox.com> wrote:

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 <drafnel@gmail.com> wrote:

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 <drafnel@gmail.com>
---
 t/t5400-send-pack.sh | 35 +++++++++++++++++++++++++++++++++++
 1 file changed, 35 insertions(+)

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(-)

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(-)

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

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(-)

On Mon, Aug 6, 2012 at 10:34 PM, Junio C Hamano <gitster@pobox.com> wrote:

On Mon, Aug 6, 2012 at 10:32 PM, Jeff King <peff@peff.net> wrote:

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

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

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

On Mon, Aug 6, 2012 at 11:03 PM, Jeff King <peff@peff.net> wrote:

Heh. :b

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

Brandon Casey <drafnel@gmail.com> writes:

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".

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

Jeff King <peff@peff.net> writes:

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(-)

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

s/presence/the &/

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

On Tue, Aug 7, 2012 at 2:44 PM, Junio C Hamano <gitster@pobox.com> wrote:

Looks fine to me.  Thanks.

-Brandon

On Mon, Aug 06, 2012 at 10:01:49PM -0700, Brandon Casey 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):

-- >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(-)