From: Stephan Beyer <hidden> Date: 2016-06-15 23:06:39
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
From: Jeff King <hidden> Date: 2016-06-15 23:06:40
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
@@ -699,5 +699,6 @@ int main(int argc, char **argv)max_request_buffer);cmd->imp(cmd_arg);+sleep(1);return0;}
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
From: Stephan Beyer <hidden> Date: 2016-06-15 23:06:40
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 <redacted>
---
t/t5560-http-backend-noserver.sh | 4 ----
t/t5561-http-backend.sh | 8 +-------
t/t556x_common | 12 ------------
3 files changed, 1 insertion(+), 23 deletions(-)
From: Stephan Beyer <hidden> Date: 2016-06-15 23:06:40
Hi,
On 09/24/2015 01:24 AM, Jeff King wrote:
quoted
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?
quoted hunk
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
@@ -699,5 +699,6 @@ int main(int argc, char **argv)max_request_buffer);cmd->imp(cmd_arg);+sleep(1);return0;}
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
From: Jeff King <hidden> Date: 2016-06-15 23:06:40
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).
quoted
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.)
From: Jeff King <hidden> Date: 2016-06-15 23:06:40
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 <redacted>
---
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
From: Stephan Beyer <hidden> Date: 2016-06-15 23:06:40
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 <redacted>
---
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(-)
From: Jeff King <hidden> Date: 2016-06-15 23:06:40
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 <redacted>
---
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