t5561 failing after make PROFILE=GEN

t5561 failing after make PROFILE=GEN

[Stephan Beyer]

Hi,

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.

The test code does it right (as far as I managed to look over it),
so this is maybe some odd flushing behavior of the web server?
On the other hand, the problem only occurs with PROFILE=GEN
but the web server should be independent of the Git compile-time
configuration, right? Looks weird to me but I did not dig deep.

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.

Best
  Stephan

Re: t5561 failing after make PROFILE=GEN

[Jeff King]

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

[PATCH] t5561: get rid of racy appending to logfile

[Stephan Beyer]

The definition of log_div() appended information to the web server's
logfile to make the test more readable. However, it could happen that
this information is written before the web server writes its log line
(this consistently happens with a PROFILE=GEN build), and hence the
test failed.

To get rid of this behavior, the logfile is not touched at all. This
commit removes log_div() and its calls. The readability-improving
information is kept in the test but filtered out before comparing
it to the actual logfile.

Signed-off-by: Stephan Beyer <s-beyer@gmx.net>
---
 t/t5560-http-backend-noserver.sh |  4 ----
 t/t5561-http-backend.sh          |  8 +-------
 t/t556x_common                   | 12 ------------
 3 files changed, 1 insertion(+), 23 deletions(-)

diff --git a/t/t5560-http-backend-noserver.sh b/t/t5560-http-backend-noserver.sh
index aa73eea..9fafcf1 100755
--- a/t/t5560-http-backend-noserver.sh
+++ b/t/t5560-http-backend-noserver.sh
@@ -44,10 +44,6 @@ POST() {
 	test_cmp exp act
 }
 
-log_div() {
-	return 0
-}
-
 . "$TEST_DIRECTORY"/t556x_common
 
 expect_aliased() {
diff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh
index 19afe96..b870410 100755
--- a/t/t5561-http-backend.sh
+++ b/t/t5561-http-backend.sh
@@ -29,15 +29,9 @@ POST() {
 	test_cmp exp act
 }
 
-log_div() {
-	echo >>"$HTTPD_ROOT_PATH"/access.log
-	echo "###  $1" >>"$HTTPD_ROOT_PATH"/access.log
-	echo "###" >>"$HTTPD_ROOT_PATH"/access.log
-}
-
 . "$TEST_DIRECTORY"/t556x_common
 
-cat >exp <<EOF
+grep -e '^[GP]' >exp <<EOF
 
 ###  refs/heads/master
 ###
diff --git a/t/t556x_common b/t/t556x_common
index 82926cf..359fcfe 100755
--- a/t/t556x_common
+++ b/t/t556x_common
@@ -52,21 +52,17 @@ get_static_files() {
 SMART=smart
 GIT_HTTP_EXPORT_ALL=1 && export GIT_HTTP_EXPORT_ALL
 test_expect_success 'direct refs/heads/master not found' '
-	log_div "refs/heads/master" &&
 	GET refs/heads/master "404 Not Found"
 '
 test_expect_success 'static file is ok' '
-	log_div "getanyfile default" &&
 	get_static_files "200 OK"
 '
 SMART=smart_noexport
 unset GIT_HTTP_EXPORT_ALL
 test_expect_success 'no export by default' '
-	log_div "no git-daemon-export-ok" &&
 	get_static_files "404 Not Found"
 '
 test_expect_success 'export if git-daemon-export-ok' '
-	log_div "git-daemon-export-ok" &&
         (cd "$HTTPD_DOCUMENT_ROOT_PATH/repo.git" &&
 	 touch git-daemon-export-ok
 	) &&
@@ -75,47 +71,39 @@ test_expect_success 'export if git-daemon-export-ok' '
 SMART=smart
 GIT_HTTP_EXPORT_ALL=1 && export GIT_HTTP_EXPORT_ALL
 test_expect_success 'static file if http.getanyfile true is ok' '
-	log_div "getanyfile true" &&
 	config http.getanyfile true &&
 	get_static_files "200 OK"
 '
 test_expect_success 'static file if http.getanyfile false fails' '
-	log_div "getanyfile false" &&
 	config http.getanyfile false &&
 	get_static_files "403 Forbidden"
 '
 
 test_expect_success 'http.uploadpack default enabled' '
-	log_div "uploadpack default" &&
 	GET info/refs?service=git-upload-pack "200 OK"  &&
 	POST git-upload-pack 0000 "200 OK"
 '
 test_expect_success 'http.uploadpack true' '
-	log_div "uploadpack true" &&
 	config http.uploadpack true &&
 	GET info/refs?service=git-upload-pack "200 OK" &&
 	POST git-upload-pack 0000 "200 OK"
 '
 test_expect_success 'http.uploadpack false' '
-	log_div "uploadpack false" &&
 	config http.uploadpack false &&
 	GET info/refs?service=git-upload-pack "403 Forbidden" &&
 	POST git-upload-pack 0000 "403 Forbidden"
 '
 
 test_expect_success 'http.receivepack default disabled' '
-	log_div "receivepack default" &&
 	GET info/refs?service=git-receive-pack "403 Forbidden"  &&
 	POST git-receive-pack 0000 "403 Forbidden"
 '
 test_expect_success 'http.receivepack true' '
-	log_div "receivepack true" &&
 	config http.receivepack true &&
 	GET info/refs?service=git-receive-pack "200 OK" &&
 	POST git-receive-pack 0000 "200 OK"
 '
 test_expect_success 'http.receivepack false' '
-	log_div "receivepack false" &&
 	config http.receivepack false &&
 	GET info/refs?service=git-receive-pack "403 Forbidden" &&
 	POST git-receive-pack 0000 "403 Forbidden"
-- 
2.6.0.rc3.dirty

Re: [PATCH] t5561: get rid of racy appending to logfile

[Jeff King]

On Thu, Sep 24, 2015 at 02:20:17AM +0200, Stephan Beyer wrote:

> The definition of log_div() appended information to the web server's
> logfile to make the test more readable. However, it could happen that
> this information is written before the web server writes its log line
> (this consistently happens with a PROFILE=GEN build), and hence the
> test failed.

I don't know if you want to add more detail here or not, but I believe
the race is based on the amount of time between git-http-backend
finishes serving the request, and when the process exits. We run
log_div() as soon as the first is done, but Apache waits for the latter
to flush out the logfile. And PROFILE=GEN lengthens that time.

> To get rid of this behavior, the logfile is not touched at all. This
> commit removes log_div() and its calls. The readability-improving
> information is kept in the test but filtered out before comparing
> it to the actual logfile.
> 
> Signed-off-by: Stephan Beyer <s-beyer@gmx.net>
> ---
>  t/t5560-http-backend-noserver.sh |  4 ----
>  t/t5561-http-backend.sh          |  8 +-------
>  t/t556x_common                   | 12 ------------
>  3 files changed, 1 insertion(+), 23 deletions(-)

This looks good to me.

I'd have written the grep as:

> -cat >exp <<EOF
> +grep -e '^[GP]' >exp <<EOF

grep '^[^#]' >exp <<EOF

to exclude blank lines and comments, but I doubt it matters in practice
(I cannot imagine any line except GET or POST here).

-Peff

[PATCH] t5561: get rid of racy appending to logfile

[Stephan Beyer]

The definition of log_div() appended information to the web server's
logfile to make the test more readable. However, log_div() was called
right after a request is served (which is done by git-http-backend);
the web server waits for the git-http-backend process to exit before
it writes to the log file. When the duration between serving a request
and exiting was long, the log_div() output was written before the last
request's log, and the test failed. (This duration could become
especially long for PROFILE=GEN builds.)

To get rid of this behavior, we should not change the logfile at all.
This commit removes log_div() and its calls. The additional information
is kept in the test (for readability reasons) but filtered out before
comparing it to the actual logfile.

Signed-off-by: Stephan Beyer <s-beyer@gmx.net>
---
 Okay Peff, I added the information to the commit message (in my own
 words). Past tense for the situation before the patch, present tense
 for the situation after (hope that's right but should not be too
 important).

 I also used your proposed grep line because it is probably more robust.

 t/t5560-http-backend-noserver.sh |  4 ----
 t/t5561-http-backend.sh          |  8 +-------
 t/t556x_common                   | 12 ------------
 3 files changed, 1 insertion(+), 23 deletions(-)

diff --git a/t/t5560-http-backend-noserver.sh b/t/t5560-http-backend-noserver.sh
index aa73eea..9fafcf1 100755
--- a/t/t5560-http-backend-noserver.sh
+++ b/t/t5560-http-backend-noserver.sh
@@ -44,10 +44,6 @@ POST() {
 	test_cmp exp act
 }
 
-log_div() {
-	return 0
-}
-
 . "$TEST_DIRECTORY"/t556x_common
 
 expect_aliased() {
diff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh
index 19afe96..73dcb29 100755
--- a/t/t5561-http-backend.sh
+++ b/t/t5561-http-backend.sh
@@ -29,15 +29,9 @@ POST() {
 	test_cmp exp act
 }
 
-log_div() {
-	echo >>"$HTTPD_ROOT_PATH"/access.log
-	echo "###  $1" >>"$HTTPD_ROOT_PATH"/access.log
-	echo "###" >>"$HTTPD_ROOT_PATH"/access.log
-}
-
 . "$TEST_DIRECTORY"/t556x_common
 
-cat >exp <<EOF
+grep '^[^#]' >exp <<EOF
 
 ###  refs/heads/master
 ###
diff --git a/t/t556x_common b/t/t556x_common
index 82926cf..359fcfe 100755
--- a/t/t556x_common
+++ b/t/t556x_common
@@ -52,21 +52,17 @@ get_static_files() {
 SMART=smart
 GIT_HTTP_EXPORT_ALL=1 && export GIT_HTTP_EXPORT_ALL
 test_expect_success 'direct refs/heads/master not found' '
-	log_div "refs/heads/master" &&
 	GET refs/heads/master "404 Not Found"
 '
 test_expect_success 'static file is ok' '
-	log_div "getanyfile default" &&
 	get_static_files "200 OK"
 '
 SMART=smart_noexport
 unset GIT_HTTP_EXPORT_ALL
 test_expect_success 'no export by default' '
-	log_div "no git-daemon-export-ok" &&
 	get_static_files "404 Not Found"
 '
 test_expect_success 'export if git-daemon-export-ok' '
-	log_div "git-daemon-export-ok" &&
         (cd "$HTTPD_DOCUMENT_ROOT_PATH/repo.git" &&
 	 touch git-daemon-export-ok
 	) &&
@@ -75,47 +71,39 @@ test_expect_success 'export if git-daemon-export-ok' '
 SMART=smart
 GIT_HTTP_EXPORT_ALL=1 && export GIT_HTTP_EXPORT_ALL
 test_expect_success 'static file if http.getanyfile true is ok' '
-	log_div "getanyfile true" &&
 	config http.getanyfile true &&
 	get_static_files "200 OK"
 '
 test_expect_success 'static file if http.getanyfile false fails' '
-	log_div "getanyfile false" &&
 	config http.getanyfile false &&
 	get_static_files "403 Forbidden"
 '
 
 test_expect_success 'http.uploadpack default enabled' '
-	log_div "uploadpack default" &&
 	GET info/refs?service=git-upload-pack "200 OK"  &&
 	POST git-upload-pack 0000 "200 OK"
 '
 test_expect_success 'http.uploadpack true' '
-	log_div "uploadpack true" &&
 	config http.uploadpack true &&
 	GET info/refs?service=git-upload-pack "200 OK" &&
 	POST git-upload-pack 0000 "200 OK"
 '
 test_expect_success 'http.uploadpack false' '
-	log_div "uploadpack false" &&
 	config http.uploadpack false &&
 	GET info/refs?service=git-upload-pack "403 Forbidden" &&
 	POST git-upload-pack 0000 "403 Forbidden"
 '
 
 test_expect_success 'http.receivepack default disabled' '
-	log_div "receivepack default" &&
 	GET info/refs?service=git-receive-pack "403 Forbidden"  &&
 	POST git-receive-pack 0000 "403 Forbidden"
 '
 test_expect_success 'http.receivepack true' '
-	log_div "receivepack true" &&
 	config http.receivepack true &&
 	GET info/refs?service=git-receive-pack "200 OK" &&
 	POST git-receive-pack 0000 "200 OK"
 '
 test_expect_success 'http.receivepack false' '
-	log_div "receivepack false" &&
 	config http.receivepack false &&
 	GET info/refs?service=git-receive-pack "403 Forbidden" &&
 	POST git-receive-pack 0000 "403 Forbidden"
-- 
2.6.0.rc3.dirty

Re: [PATCH] t5561: get rid of racy appending to logfile

[Jeff King]

On Thu, Sep 24, 2015 at 08:12:22PM +0200, Stephan Beyer wrote:

> The definition of log_div() appended information to the web server's
> logfile to make the test more readable. However, log_div() was called
> right after a request is served (which is done by git-http-backend);
> the web server waits for the git-http-backend process to exit before
> it writes to the log file. When the duration between serving a request
> and exiting was long, the log_div() output was written before the last
> request's log, and the test failed. (This duration could become
> especially long for PROFILE=GEN builds.)
> 
> To get rid of this behavior, we should not change the logfile at all.
> This commit removes log_div() and its calls. The additional information
> is kept in the test (for readability reasons) but filtered out before
> comparing it to the actual logfile.
> 
> Signed-off-by: Stephan Beyer <s-beyer@gmx.net>
> ---
>  Okay Peff, I added the information to the commit message (in my own
>  words). Past tense for the situation before the patch, present tense
>  for the situation after (hope that's right but should not be too
>  important).
> 
>  I also used your proposed grep line because it is probably more robust.

This all looks good to me. Thanks so much for working on this.

> -cat >exp <<EOF
> +grep '^[^#]' >exp <<EOF

One quick note for others who are reviewing: this violates our usual
advice to use "<<-\EOF" for here-docs, but I think it's best as-is.

We can't use "\" here because we _do_ want interpolation. The reason to
use "<<-" is to match indentation with the rest of the test block. This
particular content is outside a test block, which is something we
typically avoid. But in this case, the expected content is essentially
the whole of the script, and I think it reads a little more easily
outside.

So I don't think there is anything to change, but I wanted to point out
my thought process so other reviewers don't end up repeating it.

-Peff

Re: [PATCH] t5561: get rid of racy appending to logfile

[Junio C Hamano]

Stephan Beyer <s-beyer@gmx.net> writes:

> The definition of log_div() appended information to the web server's
> logfile to make the test more readable. However, log_div() was called
> right after a request is served (which is done by git-http-backend);
> the web server waits for the git-http-backend process to exit before
> it writes to the log file. When the duration between serving a request
> and exiting was long, the log_div() output was written before the last
> request's log, and the test failed. (This duration could become
> especially long for PROFILE=GEN builds.)
>
> To get rid of this behavior, we should not change the logfile at all.
> This commit removes log_div() and its calls. The additional information
> is kept in the test (for readability reasons) but filtered out before
> comparing it to the actual logfile.
>
> Signed-off-by: Stephan Beyer <s-beyer@gmx.net>
> ---
>  Okay Peff, I added the information to the commit message (in my own
>  words). Past tense for the situation before the patch, present tense
>  for the situation after (hope that's right but should not be too
>  important).
>
>  I also used your proposed grep line because it is probably more robust.

Thanks, both.  

I vaguely recall this test mysteriously failing a few times during
the past several years for me.  Thanks for digging to the bottom of
the problem.  Both the diagnosis and fix look very sensible.

Re: t5561 failing after make PROFILE=GEN

[Stephan Beyer]

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

Re: t5561 failing after make PROFILE=GEN

[Jeff King]

On Thu, Sep 24, 2015 at 02:22:10AM +0200, Stephan Beyer wrote:

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

I don't think so. The tests have always been pretty solid, but I think
the profile-build code was broken for a long while.

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

Remember that there are two phases to the profile build: first we build
with profile-recording on, run the tests, and then build the optimized
version with the output written during the test-run. And it's this first
build that is failing the tests. I don't know exactly how the
profile-recording is implemented, but I imagine that it records counters
as it runs, and then after we call exit() it dumps the counters to a
file.

So the profile-generation version probably _is_ slower overall, but it
is really the pause between exit() and the process actually ending that
is the problem here (because the client thinks we are done and proceeds,
but apache is waiting for the CGI to exit).

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

True, though that would be really slow (it may also still be racy; I
don't know if Apache would flush out the log if it gets a shutdown
signal or not).

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

Thanks, I'll give it a look.

-Peff