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

[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>
Acked-by: Jeff King <peff@peff.net>
---

 SubmittingPatches says that when there is consensus the patch has to
 be resent to Junio and cc'ed to the list. Here it is (although I
 don't know if there is consensus, but, hey, it's a rather trivial patch,
 so it should be okay).
 See http://git.661346.n2.nabble.com/t5561-failing-after-make-PROFILE-GEN-td7640150.html
 for the original thread.
 Compared to the last version, I only added the Acked-by line.

 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

[Junio C Hamano]

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

>  SubmittingPatches says that when there is consensus the patch has to
>  be resent to Junio and cc'ed to the list. Here it is (although I
>  don't know if there is consensus, but, hey, it's a rather trivial patch,
>  so it should be okay).

Yup.

The patch text matches exactly what I already queued with
Reviewed-by from Peff earlier, which is good.  

Thanks.

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.