{"thread":{"id":"40408","subject":"t5561 failing after make PROFILE=GEN","startedAt":"2015-09-22T23:21:39Z","lastAt":"2015-09-25T15:50:07Z","messageCount":9,"participants":["Stephan Beyer","Jeff King","Junio C Hamano"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"270540","messageId":"5601E283.2030507@gmx.net","threadId":"40408","inReplyTo":null,"subject":"t5561 failing after make PROFILE=GEN","fromName":"Stephan Beyer","fromEmail":"s-beyer@gmx.net","sentAt":"2015-09-22T23:21:39Z","receivedAt":"2015-09-22T23:21:39Z","isPatch":false,"sender":{"key":"s-beyer@gmx.net","avatar":"https://avatars.githubusercontent.com/u/143889?v=4"},"body":"Hi,\n\nI noticed that t5561 fails on my machine when compiling with\n\"make PROFILE=GEN\". Luckily, the reason seems to be the test only,\nnot the tool it is testing.\n\nI tracked it down that far that log_div() (defined in\nt/t5561-http-backend.sh but used in t/t556x_common) appends\nthe given text to the access.log *before* the last GET log entry\nis written.\n\nThe test code does it right (as far as I managed to look over it),\nso this is maybe some odd flushing behavior of the web server?\nOn the other hand, the problem only occurs with PROFILE=GEN\nbut the web server should be independent of the Git compile-time\nconfiguration, right? Looks weird to me but I did not dig deep.\n\nReplacing the log_div() implementation by \"return 0\" and removing\nthe implied output solves the problem without breaking any test\nfunctionality. (For more clarity, the log_div() calls and definitions\nshould be removed.) I refrained from sending this trivial patch\nbecause I am not sure if this is the right way to cope with the issue.\n\nBest\n Stephan\n"},{"id":"270612","messageId":"20150923232443.GA21755@sigill.intra.peff.net","threadId":"40408","inReplyTo":"5601E283.2030507@gmx.net","subject":"Re: t5561 failing after make PROFILE=GEN","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-09-23T23:24:43Z","receivedAt":"2015-09-23T23:24:43Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Sep 23, 2015 at 01:21:39AM +0200, Stephan Beyer wrote:\n\n> I noticed that t5561 fails on my machine when compiling with\n> \"make PROFILE=GEN\". Luckily, the reason seems to be the test only,\n> not the tool it is testing.\n> \n> I tracked it down that far that log_div() (defined in\n> t/t5561-http-backend.sh but used in t/t556x_common) appends\n> the given text to the access.log *before* the last GET log entry\n> is written.\n\nYes, I have run into this before. I _think_ I've also seen it once in a\nnon-profile build. Which would make sense, if it is simply racy but the\nrace usually goes the right way, and something about the profile build\nupsets that.\n\nBut I also can't get it to fail when running t5561 in a loop, so I may\nhave been mistaken (and it fails to consistently with PRORILE=GEN). And\nit does seem to be mostly related to the log-flushing behavior of\napache, and I can't imagine how we would be affecting that.\n\nIt's nothing in the environment; if you have a profile build and run \"cd\nt && ./t5561-*\", it will still fail. So it's something about the build.\nI'd guess it would be that git-http-backend is taking extra time after\nthe session is over to write out the profile data, and that apache\ndelays writing the log entry until it is done.\n\nAha. That seems to be it. If I add\n\ndiff --git a/http-backend.c b/http-backend.c\nindex bac40ef..88610b4 100644\n--- a/http-backend.c\n+++ b/http-backend.c\n@@ -699,5 +699,6 @@ int main(int argc, char **argv)\n \t\t\t\t\t max_request_buffer);\n \n \tcmd->imp(cmd_arg);\n+\tsleep(1);\n \treturn 0;\n }\n\nthen it fails for me even without a profile build.\n\n> Replacing the log_div() implementation by \"return 0\" and removing\n> the implied output solves the problem without breaking any test\n> functionality. (For more clarity, the log_div() calls and definitions\n> should be removed.) I refrained from sending this trivial patch\n> because I am not sure if this is the right way to cope with the issue.\n\nI'd agree that the tests would be OK (albeit a little less readable) if\nwe drop the log_div. My initial worry was that we we were papering over\na real problem, but I don't think we are. Touching the apache logfile\nourselves is inherently racy. We know the _client_ has finished talking\nto the server, but we don't know when the server side of the CGI has\nexited.\n\nAnd this isn't anything to do with git's behavior, but just the test\nscript. So I think dropping the log_div is probably our best bet. We may\nwant to keep the existing \"expected\" file with the \"###\" lines as\ncomments, and then simply strip them out when comparing to the actual\noutput (so the test script remains readable).\n\n-Peff\n"},{"id":"270615","messageId":"1443054017-8312-1-git-send-email-s-beyer@gmx.net","threadId":"40408","inReplyTo":"20150923232443.GA21755@sigill.intra.peff.net","subject":"[PATCH] t5561: get rid of racy appending to logfile","fromName":"Stephan Beyer","fromEmail":"s-beyer@gmx.net","sentAt":"2015-09-24T00:20:17Z","receivedAt":"2015-09-24T00:20:17Z","isPatch":true,"sender":{"key":"s-beyer@gmx.net","avatar":"https://avatars.githubusercontent.com/u/143889?v=4"},"body":"The definition of log_div() appended information to the web server's\nlogfile to make the test more readable. However, it could happen that\nthis information is written before the web server writes its log line\n(this consistently happens with a PROFILE=GEN build), and hence the\ntest failed.\n\nTo get rid of this behavior, the logfile is not touched at all. This\ncommit removes log_div() and its calls. The readability-improving\ninformation is kept in the test but filtered out before comparing\nit to the actual logfile.\n\nSigned-off-by: Stephan Beyer \n---\n t/t5560-http-backend-noserver.sh | 4 ----\n t/t5561-http-backend.sh | 8 +-------\n t/t556x_common | 12 ------------\n 3 files changed, 1 insertion(+), 23 deletions(-)\n\ndiff --git a/t/t5560-http-backend-noserver.sh b/t/t5560-http-backend-noserver.sh\nindex aa73eea..9fafcf1 100755\n--- a/t/t5560-http-backend-noserver.sh\n+++ b/t/t5560-http-backend-noserver.sh\n@@ -44,10 +44,6 @@ POST() {\n \ttest_cmp exp act\n }\n \n-log_div() {\n-\treturn 0\n-}\n-\n . \"$TEST_DIRECTORY\"/t556x_common\n \n expect_aliased() {\ndiff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh\nindex 19afe96..b870410 100755\n--- a/t/t5561-http-backend.sh\n+++ b/t/t5561-http-backend.sh\n@@ -29,15 +29,9 @@ POST() {\n \ttest_cmp exp act\n }\n \n-log_div() {\n-\techo >>\"$HTTPD_ROOT_PATH\"/access.log\n-\techo \"### $1\" >>\"$HTTPD_ROOT_PATH\"/access.log\n-\techo \"###\" >>\"$HTTPD_ROOT_PATH\"/access.log\n-}\n-\n . \"$TEST_DIRECTORY\"/t556x_common\n \n-cat >exp <exp <> I noticed that t5561 fails on my machine when compiling with\n>> \"make PROFILE=GEN\". Luckily, the reason seems to be the test only,\n>> not the tool it is testing.\n>>\n>> I tracked it down that far that log_div() (defined in\n>> t/t5561-http-backend.sh but used in t/t556x_common) appends\n>> the given text to the access.log *before* the last GET log entry\n>> is written.\n> \n> Yes, I have run into this before. I _think_ I've also seen it once in a\n> non-profile build. Which would make sense, if it is simply racy but the\n> race usually goes the right way, and something about the profile build\n> upsets that.\n\nI only checked for profile builds and first tried to bisect the issue,\nwhich went terribly wrong because using older Git commits (unluckily I\ncan't say now how far you should go back in history), the test failed or\nsucceeded randomly. So it always found different (and always unrelated)\ncommits using \"git bisect run\".\nHowever, in the latest versions, it *always* fails for a profile build\n(and *never* for a non-profile build, at least here).\n\nMaybe this needs some more investigation?\n\n> It's nothing in the environment; if you have a profile build and run \"cd\n> t && ./t5561-*\", it will still fail. So it's something about the build.\n> I'd guess it would be that git-http-backend is taking extra time after\n> the session is over to write out the profile data, and that apache\n> delays writing the log entry until it is done.\n> \n> Aha. That seems to be it. If I add\n> \n> diff --git a/http-backend.c b/http-backend.c\n> index bac40ef..88610b4 100644\n> --- a/http-backend.c\n> +++ b/http-backend.c\n> @@ -699,5 +699,6 @@ int main(int argc, char **argv)\n> \t\t\t\t\t max_request_buffer);\n> \n> \tcmd->imp(cmd_arg);\n> +\tsleep(1);\n> \treturn 0;\n> }\n> \n> then it fails for me even without a profile build.\n\nHmm, but why is the profile build of http-backend \"slower\"? (Or am I\ngetting it wrong?)\n\n> Touching the apache logfile ourselves is inherently racy.\n\nIt would not be racy if we started/stopped apache before/after each test\n(and only append to the logfile after each apache shutdown). But that\nwould slow it down a lot.\n\n> And this isn't anything to do with git's behavior, but just the test\n> script. So I think dropping the log_div is probably our best bet. We may\n> want to keep the existing \"expected\" file with the \"###\" lines as\n> comments, and then simply strip them out when comparing to the actual\n> output (so the test script remains readable).\n\nThat's a very good idea. (I just sent a patch with a possible realization.)\n\nStephan\n"},{"id":"270617","messageId":"20150924014135.GA6442@sigill.intra.peff.net","threadId":"40408","inReplyTo":"56034232.6030100@gmx.net","subject":"Re: t5561 failing after make PROFILE=GEN","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-09-24T01:41:35Z","receivedAt":"2015-09-24T01:41:35Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Sep 24, 2015 at 02:22:10AM +0200, Stephan Beyer wrote:\n\n> I only checked for profile builds and first tried to bisect the issue,\n> which went terribly wrong because using older Git commits (unluckily I\n> can't say now how far you should go back in history), the test failed or\n> succeeded randomly. So it always found different (and always unrelated)\n> commits using \"git bisect run\".\n> However, in the latest versions, it *always* fails for a profile build\n> (and *never* for a non-profile build, at least here).\n> \n> Maybe this needs some more investigation?\n\nI don't think so. The tests have always been pretty solid, but I think\nthe profile-build code was broken for a long while.\n\n> Hmm, but why is the profile build of http-backend \"slower\"? (Or am I\n> getting it wrong?)\n\nRemember that there are two phases to the profile build: first we build\nwith profile-recording on, run the tests, and then build the optimized\nversion with the output written during the test-run. And it's this first\nbuild that is failing the tests. I don't know exactly how the\nprofile-recording is implemented, but I imagine that it records counters\nas it runs, and then after we call exit() it dumps the counters to a\nfile.\n\nSo the profile-generation version probably _is_ slower overall, but it\nis really the pause between exit() and the process actually ending that\nis the problem here (because the client thinks we are done and proceeds,\nbut apache is waiting for the CGI to exit).\n\n> > Touching the apache logfile ourselves is inherently racy.\n> \n> It would not be racy if we started/stopped apache before/after each test\n> (and only append to the logfile after each apache shutdown). But that\n> would slow it down a lot.\n\nTrue, though that would be really slow (it may also still be racy; I\ndon't know if Apache would flush out the log if it gets a shutdown\nsignal or not).\n\n> That's a very good idea. (I just sent a patch with a possible realization.)\n\nThanks, I'll give it a look.\n\n-Peff\n"},{"id":"270618","messageId":"20150924014541.GB6442@sigill.intra.peff.net","threadId":"40408","inReplyTo":"1443054017-8312-1-git-send-email-s-beyer@gmx.net","subject":"Re: [PATCH] t5561: get rid of racy appending to logfile","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2015-09-24T01:45:41Z","receivedAt":"2015-09-24T01:45:41Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Sep 24, 2015 at 02:20:17AM +0200, Stephan Beyer wrote:\n\n> The definition of log_div() appended information to the web server's\n> logfile to make the test more readable. However, it could happen that\n> this information is written before the web server writes its log line\n> (this consistently happens with a PROFILE=GEN build), and hence the\n> test failed.\n\nI don't know if you want to add more detail here or not, but I believe\nthe race is based on the amount of time between git-http-backend\nfinishes serving the request, and when the process exits. We run\nlog_div() as soon as the first is done, but Apache waits for the latter\nto flush out the logfile. And PROFILE=GEN lengthens that time.\n\n> To get rid of this behavior, the logfile is not touched at all. This\n> commit removes log_div() and its calls. The readability-improving\n> information is kept in the test but filtered out before comparing\n> it to the actual logfile.\n> \n> Signed-off-by: Stephan Beyer \n> ---\n> t/t5560-http-backend-noserver.sh | 4 ----\n> t/t5561-http-backend.sh | 8 +-------\n> t/t556x_common | 12 ------------\n> 3 files changed, 1 insertion(+), 23 deletions(-)\n\nThis looks good to me.\n\nI'd have written the grep as:\n\n> -cat >exp < +grep -e '^[GP]' >exp <exp <\n---\n Okay Peff, I added the information to the commit message (in my own\n words). Past tense for the situation before the patch, present tense\n for the situation after (hope that's right but should not be too\n important).\n\n I also used your proposed grep line because it is probably more robust.\n\n t/t5560-http-backend-noserver.sh | 4 ----\n t/t5561-http-backend.sh | 8 +-------\n t/t556x_common | 12 ------------\n 3 files changed, 1 insertion(+), 23 deletions(-)\n\ndiff --git a/t/t5560-http-backend-noserver.sh b/t/t5560-http-backend-noserver.sh\nindex aa73eea..9fafcf1 100755\n--- a/t/t5560-http-backend-noserver.sh\n+++ b/t/t5560-http-backend-noserver.sh\n@@ -44,10 +44,6 @@ POST() {\n \ttest_cmp exp act\n }\n \n-log_div() {\n-\treturn 0\n-}\n-\n . \"$TEST_DIRECTORY\"/t556x_common\n \n expect_aliased() {\ndiff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh\nindex 19afe96..73dcb29 100755\n--- a/t/t5561-http-backend.sh\n+++ b/t/t5561-http-backend.sh\n@@ -29,15 +29,9 @@ POST() {\n \ttest_cmp exp act\n }\n \n-log_div() {\n-\techo >>\"$HTTPD_ROOT_PATH\"/access.log\n-\techo \"### $1\" >>\"$HTTPD_ROOT_PATH\"/access.log\n-\techo \"###\" >>\"$HTTPD_ROOT_PATH\"/access.log\n-}\n-\n . \"$TEST_DIRECTORY\"/t556x_common\n \n-cat >exp <exp < The definition of log_div() appended information to the web server's\n> logfile to make the test more readable. However, log_div() was called\n> right after a request is served (which is done by git-http-backend);\n> the web server waits for the git-http-backend process to exit before\n> it writes to the log file. When the duration between serving a request\n> and exiting was long, the log_div() output was written before the last\n> request's log, and the test failed. (This duration could become\n> especially long for PROFILE=GEN builds.)\n> \n> To get rid of this behavior, we should not change the logfile at all.\n> This commit removes log_div() and its calls. The additional information\n> is kept in the test (for readability reasons) but filtered out before\n> comparing it to the actual logfile.\n> \n> Signed-off-by: Stephan Beyer \n> ---\n> Okay Peff, I added the information to the commit message (in my own\n> words). Past tense for the situation before the patch, present tense\n> for the situation after (hope that's right but should not be too\n> important).\n> \n> I also used your proposed grep line because it is probably more robust.\n\nThis all looks good to me. Thanks so much for working on this.\n\n> -cat >exp < +grep '^[^#]' >exp < writes:\n\n> The definition of log_div() appended information to the web server's\n> logfile to make the test more readable. However, log_div() was called\n> right after a request is served (which is done by git-http-backend);\n> the web server waits for the git-http-backend process to exit before\n> it writes to the log file. When the duration between serving a request\n> and exiting was long, the log_div() output was written before the last\n> request's log, and the test failed. (This duration could become\n> especially long for PROFILE=GEN builds.)\n>\n> To get rid of this behavior, we should not change the logfile at all.\n> This commit removes log_div() and its calls. The additional information\n> is kept in the test (for readability reasons) but filtered out before\n> comparing it to the actual logfile.\n>\n> Signed-off-by: Stephan Beyer \n> ---\n> Okay Peff, I added the information to the commit message (in my own\n> words). Past tense for the situation before the patch, present tense\n> for the situation after (hope that's right but should not be too\n> important).\n>\n> I also used your proposed grep line because it is probably more robust.\n\nThanks, both. \n\nI vaguely recall this test mysteriously failing a few times during\nthe past several years for me. Thanks for digging to the bottom of\nthe problem. Both the diagnosis and fix look very sensible.\n"}]}