Re: t5561 failing after make PROFILE=GEN

[Stephan Beyer <s-beyer@gmx.net>]

Hi,

On 09/24/2015 01:24 AM, Jeff King 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.

I only checked for profile builds and first tried to bisect the issue,
which went terribly wrong because using older Git commits (unluckily I
can't say now how far you should go back in history), the test failed or
succeeded randomly. So it always found different (and always unrelated)
commits using "git bisect run".
However, in the latest versions, it *always* fails for a profile build
(and *never* for a non-profile build, at least here).

Maybe this needs some more investigation?

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

Hmm, but why is the profile build of http-backend "slower"? (Or am I
getting it wrong?)

> Touching the apache logfile ourselves is inherently racy.

It would not be racy if we started/stopped apache before/after each test
(and only append to the logfile after each apache shutdown). But that
would slow it down a lot.

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

That's a very good idea. (I just sent a patch with a possible realization.)

Stephan