Re: t5561 failing after make PROFILE=GEN

[Jeff King <peff@peff.net>]

On Wed, Sep 23, 2015 at 01:21:39AM +0200, Stephan Beyer wrote:

> I noticed that t5561 fails on my machine when compiling with
> "make PROFILE=GEN". Luckily, the reason seems to be the test only,
> not the tool it is testing.
> 
> I tracked it down that far that log_div() (defined in
> t/t5561-http-backend.sh but used in t/t556x_common) appends
> the given text to the access.log *before* the last GET log entry
> is written.

Yes, I have run into this before. I _think_ I've also seen it once in a
non-profile build. Which would make sense, if it is simply racy but the
race usually goes the right way, and something about the profile build
upsets that.

But I also can't get it to fail when running t5561 in a loop, so I may
have been mistaken (and it fails to consistently with PRORILE=GEN). And
it does seem to be mostly related to the log-flushing behavior of
apache, and I can't imagine how we would be affecting that.

It's nothing in the environment; if you have a profile build and run "cd
t && ./t5561-*", it will still fail. So it's something about the build.
I'd guess it would be that git-http-backend is taking extra time after
the session is over to write out the profile data, and that apache
delays writing the log entry until it is done.

Aha. That seems to be it. If I add

diff --git a/http-backend.c b/http-backend.c
index bac40ef..88610b4 100644
--- a/http-backend.c
+++ b/http-backend.c
@@ -699,5 +699,6 @@ int main(int argc, char **argv)
 					   max_request_buffer);
 
 	cmd->imp(cmd_arg);
+	sleep(1);
 	return 0;
 }

then it fails for me even without a profile build.

> Replacing the log_div() implementation by "return 0" and removing
> the implied output solves the problem without breaking any test
> functionality. (For more clarity, the log_div() calls and definitions
> should be removed.) I refrained from sending this trivial patch
> because I am not sure if this is the right way to cope with the issue.

I'd agree that the tests would be OK (albeit a little less readable) if
we drop the log_div. My initial worry was that we we were papering over
a real problem, but I don't think we are. Touching the apache logfile
ourselves is inherently racy. We know the _client_ has finished talking
to the server, but we don't know when the server side of the CGI has
exited.

And this isn't anything to do with git's behavior, but just the test
script. So I think dropping the log_div is probably our best bet. We may
want to keep the existing "expected" file with the "###" lines as
comments, and then simply strip them out when comparing to the actual
output (so the test script remains readable).

-Peff