[RFC PATCH 0/4] Fix occasional test failures in http tests

[RFC PATCH 0/4] Fix occasional test failures in http tests

[SZEDER Gábor]

't5561-http-backend.sh' is prone to occasional failures; luckily it's
not 'git-http-backend's fault, but the test script is a bit racy.  I
won't go into the details here, patch 4/4's commit message discusses
it at length.  4/4 also fixes this issue, but I'm not particularly
happy with that fix, the note attached to that patch explains why,
along with possible alternatives, hence the RFC.

Even if we settle for a different fix, I think the first two patches
are worthy cleanups on their own right.

SZEDER Gábor (4):
  t5541: avoid empty line when truncating access log
  t/lib-httpd: add the strip_access_log() helper function
  t/lib-httpd: add minor and patch version to $HTTPD_VERSION
  t/lib-httpd: sort log based on timestamp to avoid occasional failure

 t/lib-httpd.sh              | 24 ++++++++++++++++++++++--
 t/lib-httpd/apache.conf     |  5 +++++
 t/t5541-http-push-smart.sh  | 17 +++--------------
 t/t5551-http-fetch-smart.sh |  7 +------
 t/t5561-http-backend.sh     |  7 +------
 5 files changed, 32 insertions(+), 28 deletions(-)

-- 
2.18.0.rc0.207.ga6211da864

[PATCH 1/4] t5541: avoid empty line when truncating access log

[SZEDER Gábor]

The second test of 't5541-http-push-smart.sh', 'no empty path
components' truncates Apache's access log by running

  echo >.../access.log

which doesn't leave an empty file behind, like a proper truncation
would, but a file with a lone newline in it.  Consequently, a later
test checking the log's contents must consider this improper
truncation and include an empty line in the expected content.

There is no need for that newline at all, so drop the 'echo' from the
truncation and adjust the expected content accordingly.

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---

 t/t5541-http-push-smart.sh | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)

diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh
index 21340e89c9..c961db814d 100755
--- a/t/t5541-http-push-smart.sh
+++ b/t/t5541-http-push-smart.sh
@@ -54,7 +54,7 @@ test_expect_success 'no empty path components' '
 	# service" test which reads the log too.
 	#
 	# We do this before the actual comparison to ensure the log is cleared.
-	echo > "$HTTPD_ROOT_PATH"/access.log &&
+	>"$HTTPD_ROOT_PATH"/access.log &&
 
 	test_cmp exp act
 '
@@ -124,7 +124,6 @@ test_expect_success 'rejected update prints status' '
 rm -f "$HTTPD_DOCUMENT_ROOT_PATH/test_repo.git/hooks/update"
 
 cat >exp <<EOF
-
 GET  /smart/test_repo.git/info/refs?service=git-upload-pack HTTP/1.1 200
 POST /smart/test_repo.git/git-upload-pack HTTP/1.1 200
 GET  /smart/test_repo.git/info/refs?service=git-receive-pack HTTP/1.1 200
-- 
2.18.0.rc0.207.ga6211da864

[PATCH 2/4] t/lib-httpd: add the strip_access_log() helper function

[SZEDER Gábor]

Four tests in three httpd-related test scripts check the contents of
Apache's 'access.log', and they all do so by running 'sed' with the
exact same script consisting of four s/// commands to strip
uninteresting log fields and to vertically align the requested URLs.

Extract this into a common helper function 'strip_access_log' in
'lib-httpd.sh', and use it in all of those tests.

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---
 t/lib-httpd.sh              |  9 +++++++++
 t/t5541-http-push-smart.sh  | 14 ++------------
 t/t5551-http-fetch-smart.sh |  7 +------
 t/t5561-http-backend.sh     |  7 +------
 4 files changed, 13 insertions(+), 24 deletions(-)

diff --git a/t/lib-httpd.sh b/t/lib-httpd.sh
index 435a37465a..b6788fea57 100644
--- a/t/lib-httpd.sh
+++ b/t/lib-httpd.sh
@@ -287,3 +287,12 @@ expect_askpass() {
 	test_cmp "$TRASH_DIRECTORY/askpass-expect" \
 		 "$TRASH_DIRECTORY/askpass-query"
 }
+
+strip_access_log() {
+	sed -e "
+		s/^.* \"//
+		s/\"//
+		s/ [1-9][0-9]*\$//
+		s/^GET /GET  /
+	" "$HTTPD_ROOT_PATH"/access.log
+}
diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh
index c961db814d..a1385800fa 100755
--- a/t/t5541-http-push-smart.sh
+++ b/t/t5541-http-push-smart.sh
@@ -43,12 +43,7 @@ test_expect_success 'no empty path components' '
 	cd "$ROOT_PATH" &&
 	git clone $HTTPD_URL/smart/test_repo.git/ test_repo_clone &&
 
-	sed -e "
-		s/^.* \"//
-		s/\"//
-		s/ [1-9][0-9]*\$//
-		s/^GET /GET  /
-	" >act <"$HTTPD_ROOT_PATH"/access.log &&
+	strip_access_log >act &&
 
 	# Clear the log, so that it does not affect the "used receive-pack
 	# service" test which reads the log too.
@@ -137,12 +132,7 @@ GET  /smart/test_repo.git/info/refs?service=git-receive-pack HTTP/1.1 200
 POST /smart/test_repo.git/git-receive-pack HTTP/1.1 200
 EOF
 test_expect_success 'used receive-pack service' '
-	sed -e "
-		s/^.* \"//
-		s/\"//
-		s/ [1-9][0-9]*\$//
-		s/^GET /GET  /
-	" >act <"$HTTPD_ROOT_PATH"/access.log &&
+	strip_access_log >act &&
 	test_cmp exp act
 '
 
diff --git a/t/t5551-http-fetch-smart.sh b/t/t5551-http-fetch-smart.sh
index f5721b4a59..82a4fb5e16 100755
--- a/t/t5551-http-fetch-smart.sh
+++ b/t/t5551-http-fetch-smart.sh
@@ -98,12 +98,7 @@ GET  /smart/repo.git/info/refs?service=git-upload-pack HTTP/1.1 200
 POST /smart/repo.git/git-upload-pack HTTP/1.1 200
 EOF
 test_expect_success 'used upload-pack service' '
-	sed -e "
-		s/^.* \"//
-		s/\"//
-		s/ [1-9][0-9]*\$//
-		s/^GET /GET  /
-	" >act <"$HTTPD_ROOT_PATH"/access.log &&
+	strip_access_log >act &&
 	test_cmp exp act
 '
 
diff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh
index 90e0d6f0fe..6a0f240e6d 100755
--- a/t/t5561-http-backend.sh
+++ b/t/t5561-http-backend.sh
@@ -123,12 +123,7 @@ GET  /smart/repo.git/info/refs?service=git-receive-pack HTTP/1.1 403 -
 POST /smart/repo.git/git-receive-pack HTTP/1.1 403 -
 EOF
 test_expect_success 'server request log matches test results' '
-	sed -e "
-		s/^.* \"//
-		s/\"//
-		s/ [1-9][0-9]*\$//
-		s/^GET /GET  /
-	" >act <"$HTTPD_ROOT_PATH"/access.log &&
+	strip_access_log >act &&
 	test_cmp exp act
 '
 
-- 
2.18.0.rc0.207.ga6211da864

[PATCH 3/4] t/lib-httpd: add minor and patch version to $HTTPD_VERSION

[SZEDER Gábor]

To fix an occasional test failure, the next patch will rely on an
Apache log format specifier that was introduced in version 2.2.30.
Consequently, 't/lib-httpd.sh' must be able to decide whether the
Apache version used for testing is equal or newer than that version to
be able to act accordingly when processing the webserver's access log.

$HTTPD_VERSION currently only contains Apache's major version, so
change how Apache's version string is parsed to store the minor and
patch versions as well.  Furthermore, update the only condition
looking at $HTTPD_VERSION to deal with the full version.

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---
 t/lib-httpd.sh | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)

diff --git a/t/lib-httpd.sh b/t/lib-httpd.sh
index b6788fea57..5915625631 100644
--- a/t/lib-httpd.sh
+++ b/t/lib-httpd.sh
@@ -99,13 +99,13 @@ then
 fi
 
 HTTPD_VERSION=$($LIB_HTTPD_PATH -v | \
-	sed -n 's/^Server version: Apache\/\([0-9]*\)\..*$/\1/p; q')
+	sed -n 's/^Server version: Apache\/\([0-9]*\.[0-9]*\.[0-9]*\).*$/\1/p; q')
 
 if test -n "$HTTPD_VERSION"
 then
 	if test -z "$LIB_HTTPD_MODULE_PATH"
 	then
-		if ! test $HTTPD_VERSION -ge 2
+		if ! test ${HTTPD_VERSION%%.*} -ge 2
 		then
 			test_skip_or_die $GIT_TEST_HTTPD \
 				"at least Apache version 2 is required"
-- 
2.18.0.rc0.207.ga6211da864

[RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure

[SZEDER Gábor]

The last test of 't5561-http-backend.sh', 'server request log matches
test results' may fail occasionally, because the order of entries in
Apache's access log doesn't match the order of requests sent in the
previous tests, although all the right requests are there.  I saw it
fail on Travis CI five times in the span of about half a year, when
the order of two subsequent requests was flipped, and could trigger
the failure with a modified Git.  However, I was unable to trigger it
with stock Git on my machine.  Three tests in
't5541-http-push-smart.sh' and 't5551-http-fetch-smart.sh' check
requests in the log the same way, so they might be prone to a similar
occasional failure as well.

When a test sends a HTTP request, it can continue execution after
'git-http-backend' fulfilled that request, but Apache writes the
corresponding access log entry only after 'git-http-backend' exited.
Some time inevitably passes between fulfilling the request and writing
the log entry, and, under unfavourable circumstances, enough time
might pass for the subsequent request to be sent and fulfilled, and
then Apache writes access log entries racily.

This effect can be exacerbated by adding a bit of variable delay after
the request is fulfilled but before 'git-http-backend' exits, e.g.
like this:

  diff --git a/http-backend.c b/http-backend.c
  index f3dc218b2..bbf4c125b 100644
  --- a/http-backend.c
  +++ b/http-backend.c
  @@ -709,5 +709,7 @@ int cmd_main(int argc, const char **argv)
   					   max_request_buffer);

   	cmd->imp(&hdr, cmd_arg);
  +	if (getpid() % 2)
  +		sleep(1);
   	return 0;
   }

This delay considerably increases the chances of log entries being
written out of order, and in turn makes t5561's last test fail almost
every time.  Alas, it doesn't seem to be enough to trigger a similar
failure in t5541 and t5551.

Now, by default the timestamp of a log entry marks the beginning of
the request processing, not when the log entry gets written.  Since
our requests are sent sequentially, sorting the log entries based on
their timestamps would ensure that their order corresponds to the
order of our requests.

Therefore, change Apache's log format to use microseconds since epoch
as timestamps, the finest resolution Apache has to offer.  This will:

  - give enough resolution to make reasonably sure that no two
    requests have the same timestamp; the default timestamp format has
    only one second resolution, which is not nearly enough.

  - make the timestamps sortable; the default timestamp format looks
    like "[31/Jan/2018:16:33:52 +0000]", which would trip sorting if
    the test script happens to run over month boundaries.

Modify the strip_access_log() helper function, used by all potentially
affected tests, to sort the access log entries based on their
timestamp before stripping the uninteresting bits from the entries.

Unfortunately, this "microseconds since epoch" is an extended time
format specifier which was only introduced in Apache 2.2.30 [1], and
standard strftime() doesn't have any format specifiers with
microsecond or finer precision, so we can't use the above solution
with Apache versions older than 2.2.30.  However, since Apache 2.2 is
no longer maintained anyway, it's not that big a deal to leave test
runs with those old versions prone to this occasional failure.  So use
microsecond timestamps and sort access log entries only if the test is
run with an Apache version supporting it; otherwise stick to the
default timestamp format and leave the order of access log entries
unchanged.

[1] http://httpd.apache.org/docs/2.2/mod/mod_log_config.html

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---

Notes:
    The log of the latest of this test failures:
    
      https://travis-ci.org/szeder/git-cooking-topics-for-travis-ci/jobs/391499735#L3130
    
    I don't really like the fix in this patch.  I think an unfortunate
    clock skew during the test run could mess up the sorting added in this
    patch and cause test failure.  Or if DST or even a leap second happen
    while the test is running.  Do we care?  Anyway, this occasional test
    failure apparently happens more often than DST and leap seconds
    combined.
    Furthermore, in the future we might have computers fast enough to
    fulfill more than one test requests in a single microsecond; but I
    guess by that time we'll have higher resolution time formats as well.
    
    An alternative I considered was that we could decide that the order of
    requests in the access log is not important as long as all the right
    requests are there.  This would inherently eliminate the raciness
    issue, but if something were to go wrong, then it would become rather
    hard to find out e.g. which request from which test has gone missing,
    especially considering that several requests are sent in more than one
    test.  We could address this by truncating the access log at the
    beginning and checking its contents at the end of each test sending
    requests.  Unfortunately, this would raise additional difficulties,
    because all requests in t5561 come from tests included from
    't556x-common', i.e. from tests shared with
    't5560-http-backend-noserver.sh', which as its name suggests doesn't
    run Apache and doesn't have an access log at all.
    
    Another alternative is to simply accept that these tests are racy, and
    that the resulting test failures are rare enough that it isn't worth
    the complexity of the workaround, but adding a comment to the affected
    tests warning about the raciness is sufficient.  (But I wrote this
    when I first saw and tracked down this failure; since then I observed
    it four more times... :)
    
    --
    
    Apache doesn't maintain 2.2 anymore; the final maintenance release
    2.2.34 was released in July 2017, almost a year ago.  OTOH, our
    't/lib-httpd/apache.conf' contains a couple of IfVersion directives
    dealing with versions <2.4, and one even with <2.1.  How much do we
    actually care about these unmaintained Apache versions, and how much
    of this is just bitrotting?

 t/lib-httpd.sh          | 13 ++++++++++++-
 t/lib-httpd/apache.conf |  5 +++++
 2 files changed, 17 insertions(+), 1 deletion(-)

diff --git a/t/lib-httpd.sh b/t/lib-httpd.sh
index 5915625631..1a7fe67141 100644
--- a/t/lib-httpd.sh
+++ b/t/lib-httpd.sh
@@ -289,10 +289,21 @@ expect_askpass() {
 }
 
 strip_access_log() {
+	case "$HTTPD_VERSION" in
+	2.[01].*|2.2.[0-9]|2.2.[12][0-9])
+		# Apache versions < 2.2.30 didn't have any log timestamp
+		# format with microseconds precision, so don't attempt to
+		# sort the access log when testing with such old versions.
+		cat "$HTTPD_ROOT_PATH"/access.log
+		;;
+	*)
+		sort -n -k 4,4 "$HTTPD_ROOT_PATH"/access.log
+		;;
+	esac | \
 	sed -e "
 		s/^.* \"//
 		s/\"//
 		s/ [1-9][0-9]*\$//
 		s/^GET /GET  /
-	" "$HTTPD_ROOT_PATH"/access.log
+	"
 }
diff --git a/t/lib-httpd/apache.conf b/t/lib-httpd/apache.conf
index 724d9ae462..8d6da6bdb2 100644
--- a/t/lib-httpd/apache.conf
+++ b/t/lib-httpd/apache.conf
@@ -1,7 +1,12 @@
 ServerName dummy
 PidFile httpd.pid
 DocumentRoot www
+<IfVersion >= 2.2.30>
+LogFormat "%h %l %u %{usec}t \"%r\" %>s %b" common
+</IfVersion>
+<IfVersion < 2.2.30>
 LogFormat "%h %l %u %t \"%r\" %>s %b" common
+</IfVersion>
 CustomLog access.log common
 ErrorLog error.log
 <IfModule !mod_log_config.c>
-- 
2.18.0.rc0.207.ga6211da864

Re: [RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure

[SZEDER Gábor]

On Thu, Jun 14, 2018 at 2:31 PM, SZEDER Gábor <szeder.dev@gmail.com> wrote:

> When a test sends a HTTP request, it can continue execution after
> 'git-http-backend' fulfilled that request, but Apache writes the
> corresponding access log entry only after 'git-http-backend' exited.
> Some time inevitably passes between fulfilling the request and writing
> the log entry, and, under unfavourable circumstances, enough time
> might pass for the subsequent request to be sent and fulfilled, and
> then Apache writes access log entries racily.
>
> This effect can be exacerbated by adding a bit of variable delay after
> the request is fulfilled but before 'git-http-backend' exits, e.g.
> like this:
>
>   diff --git a/http-backend.c b/http-backend.c
>   index f3dc218b2..bbf4c125b 100644
>   --- a/http-backend.c
>   +++ b/http-backend.c
>   @@ -709,5 +709,7 @@ int cmd_main(int argc, const char **argv)
>                                            max_request_buffer);
>
>         cmd->imp(&hdr, cmd_arg);
>   +     if (getpid() % 2)
>   +             sleep(1);
>         return 0;
>    }
>
> This delay considerably increases the chances of log entries being
> written out of order, and in turn makes t5561's last test fail almost
> every time.  Alas, it doesn't seem to be enough to trigger a similar
> failure in t5541 and t5551.

A bit of addendum here:

There are basically two "kinds" of requests:

  1. requests asking for regular files, e.g.:

     GET  /smart/repo.git/HEAD HTTP/1.1 200
     GET  /smart/repo.git/info/refs HTTP/1.1 200
     GET  /smart/repo.git/objects/info/packs HTTP/1.1 200

  2. requests asking for 'git-receive-pack' or 'git-upload-pack',
     e.g.:

     GET  /smart/repo.git/info/refs?service=git-receive-pack HTTP/1.1 200
     POST /smart/repo.git/git-receive-pack HTTP/1.1 200 -

This artificial variable delay shuffles only the access log entries
written for the first kind of requests, but doesn't appear to have any
effect on the order of log entries written for the second kind of
requests.

t5561 sends both kinds of requests, so this variable delay is
sufficient to make the test fail most of the time.

t5541 and t5551, however, send only requests of the second kind, so
that's why this variable delay can't trigger a similar failure in
these test scripts.

I haven't investigated any further what else would be necessary to
trigger a failure in t5541 and t5551.

Re: [RFC PATCH 0/4] Fix occasional test failures in http tests

[Junio C Hamano]

SZEDER Gábor <szeder.dev@gmail.com> writes:

> 't5561-http-backend.sh' is prone to occasional failures; luckily it's
> not 'git-http-backend's fault, but the test script is a bit racy.  I
> won't go into the details here, patch 4/4's commit message discusses
> it at length.  4/4 also fixes this issue, but I'm not particularly
> happy with that fix, the note attached to that patch explains why,
> along with possible alternatives, hence the RFC.

Interesting.

> Even if we settle for a different fix, I think the first two patches
> are worthy cleanups on their own right.

Yeah, the first two are unquestionally good.  

The sed expression of the second one could use sq around (instead of
dq) to lose hard-to-read backslash quoting from there, but it
probably is OK to keep the second one a pure "refactoring" patch,
and leave it to a separate "further cleanup" patch to make such a
change.

> SZEDER Gábor (4):
>   t5541: avoid empty line when truncating access log
>   t/lib-httpd: add the strip_access_log() helper function
>   t/lib-httpd: add minor and patch version to $HTTPD_VERSION
>   t/lib-httpd: sort log based on timestamp to avoid occasional failure
>
>  t/lib-httpd.sh              | 24 ++++++++++++++++++++++--
>  t/lib-httpd/apache.conf     |  5 +++++
>  t/t5541-http-push-smart.sh  | 17 +++--------------
>  t/t5551-http-fetch-smart.sh |  7 +------
>  t/t5561-http-backend.sh     |  7 +------
>  5 files changed, 32 insertions(+), 28 deletions(-)

Re: [RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure

[Jeff King]

On Thu, Jun 14, 2018 at 02:31:07PM +0200, SZEDER Gábor wrote:

> The last test of 't5561-http-backend.sh', 'server request log matches
> test results' may fail occasionally, because the order of entries in
> Apache's access log doesn't match the order of requests sent in the
> previous tests, although all the right requests are there.  I saw it
> fail on Travis CI five times in the span of about half a year, when
> the order of two subsequent requests was flipped, and could trigger
> the failure with a modified Git.  However, I was unable to trigger it
> with stock Git on my machine.  Three tests in
> 't5541-http-push-smart.sh' and 't5551-http-fetch-smart.sh' check
> requests in the log the same way, so they might be prone to a similar
> occasional failure as well.

I've occasionally run into these failures on my local box, too. I'm
happy somebody is looking into it (I have before, but eventually threw
up my hands in disgust).

> Now, by default the timestamp of a log entry marks the beginning of
> the request processing, not when the log entry gets written.  Since
> our requests are sent sequentially, sorting the log entries based on
> their timestamps would ensure that their order corresponds to the
> order of our requests.

That's a reasonably clever solution. One thing I wonder, though: are we
always guaranteed that the log entries are written _at all_ before we
look at them?

I.e., could we have a situation where we make a request, the client
finishes, and then we look at the logs, but nothing has been written by
apache yet?

>     I don't really like the fix in this patch.  I think an unfortunate
>     clock skew during the test run could mess up the sorting added in this
>     patch and cause test failure.  Or if DST or even a leap second happen
>     while the test is running.  Do we care?  Anyway, this occasional test
>     failure apparently happens more often than DST and leap seconds
>     combined.

We could probably eliminate DST issues by consistently using UTC for the
timestamps. Leap seconds are probably infrequent enough not to worry
about. More likely is something like clock adjustment due to ntp. Those
adjustments are usually small enough not to matter, but if we're talking
microseconds, it could trigger.

>     An alternative I considered was that we could decide that the order of
>     requests in the access log is not important as long as all the right
>     requests are there. This would inherently eliminate the raciness
>     issue, but if something were to go wrong, then it would become rather
>     hard to find out e.g. which request from which test has gone missing,
>     especially considering that several requests are sent in more than one
>     test.  We could address this by truncating the access log at the
>     beginning and checking its contents at the end of each test sending
>     requests.  Unfortunately, this would raise additional difficulties,
>     because all requests in t5561 come from tests included from
>     't556x-common', i.e. from tests shared with
>     't5560-http-backend-noserver.sh', which as its name suggests doesn't
>     run Apache and doesn't have an access log at all.

What if the test script provides the in-order expectation, but we check
only the unordered version (by sorting both actual and expected output
on the fly)? That would give us a more relaxed check most of the time,
but somebody digging in to a failure could run the ordered diff (or we
could even show it automatically on failure instead of just using
test_cmp).

>     Another alternative is to simply accept that these tests are racy, and
>     that the resulting test failures are rare enough that it isn't worth
>     the complexity of the workaround, but adding a comment to the affected
>     tests warning about the raciness is sufficient.  (But I wrote this
>     when I first saw and tracked down this failure; since then I observed
>     it four more times... :)

It's definitely bugged me. I'd be happy to see some solution. I've been
close to suggesting that reading apache logs is simply not robust, and
we should focus our tests on the git-visible state changes (e.g., seeing
successful requests, updated refs, etc).

A side effect of that is that it would become a lot easier to support
other webservers in our test scripts (though that may still be a fool's
errand just due to the amount of custom config we seem to carry).

>     Apache doesn't maintain 2.2 anymore; the final maintenance release
>     2.2.34 was released in July 2017, almost a year ago.  OTOH, our
>     't/lib-httpd/apache.conf' contains a couple of IfVersion directives
>     dealing with versions <2.4, and one even with <2.1.  How much do we
>     actually care about these unmaintained Apache versions, and how much
>     of this is just bitrotting?

I strongly suspect bitrotting. It looks like most of the "< 2.4"
directives are from 5 years ago (when Debian switched to 2.4 by
default), so even long-term stable systems would generally have it by
now (though I'm sure there's probably some RHEL version without it).

-Peff

Re: [RFC PATCH 0/4] Fix occasional test failures in http tests

[Jeff King]

On Thu, Jun 14, 2018 at 02:31:03PM +0200, SZEDER Gábor wrote:

> 't5561-http-backend.sh' is prone to occasional failures; luckily it's
> not 'git-http-backend's fault, but the test script is a bit racy.  I
> won't go into the details here, patch 4/4's commit message discusses
> it at length.  4/4 also fixes this issue, but I'm not particularly
> happy with that fix, the note attached to that patch explains why,
> along with possible alternatives, hence the RFC.
> 
> Even if we settle for a different fix, I think the first two patches
> are worthy cleanups on their own right.

Yes, the first two look like improvements on their own (and I left more
detailed comments on the final one). Thanks for tackling this!

-Peff

Re: [RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure

[Junio C Hamano]

Jeff King <peff@peff.net> writes:

>>     Another alternative is to simply accept that these tests are racy, and
>>     that the resulting test failures are rare enough that it isn't worth
>>     the complexity of the workaround, but adding a comment to the affected
>>     tests warning about the raciness is sufficient.  (But I wrote this
>>     when I first saw and tracked down this failure; since then I observed
>>     it four more times... :)
>
> It's definitely bugged me. I'd be happy to see some solution. I've been
> close to suggesting that reading apache logs is simply not robust, and
> we should focus our tests on the git-visible state changes (e.g., seeing
> successful requests, updated refs, etc).

Hmph, that certainly is "checking only the things that matter",
which is desirable.

> A side effect of that is that it would become a lot easier to support
> other webservers in our test scripts (though that may still be a fool's
> errand just due to the amount of custom config we seem to carry).

Re: [RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure

[Jeff King]

On Thu, Jun 14, 2018 at 11:27:03AM -0700, Junio C Hamano wrote:

> Jeff King <peff@peff.net> writes:
> 
> >>     Another alternative is to simply accept that these tests are racy, and
> >>     that the resulting test failures are rare enough that it isn't worth
> >>     the complexity of the workaround, but adding a comment to the affected
> >>     tests warning about the raciness is sufficient.  (But I wrote this
> >>     when I first saw and tracked down this failure; since then I observed
> >>     it four more times... :)
> >
> > It's definitely bugged me. I'd be happy to see some solution. I've been
> > close to suggesting that reading apache logs is simply not robust, and
> > we should focus our tests on the git-visible state changes (e.g., seeing
> > successful requests, updated refs, etc).
> 
> Hmph, that certainly is "checking only the things that matter",
> which is desirable.

The existing tests that look at the apache logs are very white-box, and
come from Shawn's original smart-http series. I suspect it was as much
about sanity-checking the implementation then as it was about protecting
against regressions.

So it's possible that these tests have simply outlived their usefulness.

OTOH, they might catch non-functional problems, like if we started
sending redundant requests. But then, they are not very comprehensive,
as they only cover a few basic situations (so for example, for a while
we were sending extra auth-related requests, but I don't think these
tests detected that).

-Peff

Re: [RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure

[SZEDER Gábor]

On Thu, Jun 14, 2018 at 7:53 PM Jeff King <peff@peff.net> wrote:
>
> On Thu, Jun 14, 2018 at 02:31:07PM +0200, SZEDER Gábor wrote:
>
> > The last test of 't5561-http-backend.sh', 'server request log matches
> > test results' may fail occasionally, because the order of entries in
> > Apache's access log doesn't match the order of requests sent in the
> > previous tests, although all the right requests are there.

> I've occasionally run into these failures on my local box, too. I'm
> happy somebody is looking into it (I have before, but eventually threw
> up my hands in disgust).

Heh, well, I found it to be one of the more entertaining debugging
sessions... ;)
I'm glad that somebody else saw it, too, and outside of Travis CI.

> > Now, by default the timestamp of a log entry marks the beginning of
> > the request processing, not when the log entry gets written.  Since
> > our requests are sent sequentially, sorting the log entries based on
> > their timestamps would ensure that their order corresponds to the
> > order of our requests.
>
> That's a reasonably clever solution. One thing I wonder, though: are we
> always guaranteed that the log entries are written _at all_ before we
> look at them?
>
> I.e., could we have a situation where we make a request, the client
> finishes, and then we look at the logs, but nothing has been written by
> apache yet?

That's possible, I suppose.  Highly improbable, but possible.  Or the
log entries can be written only partially by the time we look at them.

FWIW, Apache has the 'BufferedLogs' directive, which "causes
mod_log_config to store several log entries in memory and write them
together to disk, rather than writing them after each request."  It
very sensibly defaults to off, and our test config doesn't set it.

I would think that stopping Apache should flush the logs, but I don't
know whether 'stop_httpd' blocks until the web server is indeed
stopped, or it's all async.  Perhaps a SIGHUP would suffice to flush
the logs, but that's definitely async.  Also note that while t5561
checks the access log at the end of the script, t5541 and t5551 do
check the logs in the middle of the script, so we would have to stop
Apache and then start again.

Anyway, I would prefer not to do anything about it just yet, because
I'm curious :) and I'd like to see whether this actually happens in
practice.


> >     I don't really like the fix in this patch.  I think an unfortunate
> >     clock skew during the test run could mess up the sorting added in this
> >     patch and cause test failure.  Or if DST or even a leap second happen
> >     while the test is running.  Do we care?  Anyway, this occasional test
> >     failure apparently happens more often than DST and leap seconds
> >     combined.
>
> We could probably eliminate DST issues by consistently using UTC for the
> timestamps. Leap seconds are probably infrequent enough not to worry
> about. More likely is something like clock adjustment due to ntp. Those
> adjustments are usually small enough not to matter, but if we're talking
> microseconds, it could trigger.

Ok, so admittedly I haven't quite thought through all these potential
clock-related issues that I mentioned.

Setting back the clock at the end of DST is not an issue, because
Apache uses the timezone it finds set in the environment, and our test
environment does set UTC, so as far as the tests and Apache's log
timestamps are concerned there is no such thing as DST.
Leap seconds don't go back in time, they are only added to compensate
for Earth's slowing rotation, so that's not an issue, either.
And I think NTP is supposed to be clever enough to not set back the
clock recklessly, but only advance it slower.

Of course, someone can still set back the clock manually while these
tests run, but I would put that in the "If it hurts, don't do it" box.


However, having said all this, ...

> What if the test script provides the in-order expectation, but we check
> only the unordered version (by sorting both actual and expected output
> on the fly)? That would give us a more relaxed check most of the time,
> but somebody digging in to a failure could run the ordered diff (or we
> could even show it automatically on failure instead of just using
> test_cmp).

this is the fix I'll go for in v2.

[PATCH v2 0/3] Fix occasional test failures in http tests

[SZEDER Gábor]

't5561-http-backend.sh' is prone to occasional failures; luckily it's
not 'git-http-backend's fault, but the test script is a bit racy.  I
won't go into the details here, patch 3/3's commit message discusses
it at length.

v1 is here; it haven't been picked up by Junio:

  https://public-inbox.org/git/20180614123107.11608-1-szeder.dev@gmail.com/T/#u

The first two patches are identical to those in v1, and the last patch
implements a different and simpler fix than in v1, following Peff's
suggestion.  The third patch was dropped, because it's not necessary for
this simpler fix.


SZEDER Gábor (3):
  t5541: avoid empty line when truncating access log
  t/lib-httpd: add the strip_access_log() helper function
  t/lib-httpd: avoid occasional failures when checking access.log

 t/lib-httpd.sh              | 21 +++++++++++++++++++++
 t/t5541-http-push-smart.sh  | 24 +++++-------------------
 t/t5551-http-fetch-smart.sh |  8 +-------
 t/t5561-http-backend.sh     |  8 +-------
 4 files changed, 28 insertions(+), 33 deletions(-)

-- 
2.18.0.273.g57f1ecce9c

[PATCH v2 1/3] t5541: avoid empty line when truncating access log

[SZEDER Gábor]

The second test of 't5541-http-push-smart.sh', 'no empty path
components' truncates Apache's access log by running

  echo >.../access.log

which doesn't leave an empty file behind, like a proper truncation
would, but a file with a lone newline in it.  Consequently, a later
test checking the log's contents must consider this improper
truncation and include an empty line in the expected content.

There is no need for that newline at all, so drop the 'echo' from the
truncation and adjust the expected content accordingly.

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---
 t/t5541-http-push-smart.sh | 3 +--
 1 file changed, 1 insertion(+), 2 deletions(-)

diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh
index a2af693068..d623cbad97 100755
--- a/t/t5541-http-push-smart.sh
+++ b/t/t5541-http-push-smart.sh
@@ -54,7 +54,7 @@ test_expect_success 'no empty path components' '
 	# service" test which reads the log too.
 	#
 	# We do this before the actual comparison to ensure the log is cleared.
-	echo > "$HTTPD_ROOT_PATH"/access.log &&
+	>"$HTTPD_ROOT_PATH"/access.log &&
 
 	test_cmp exp act
 '
@@ -124,7 +124,6 @@ test_expect_success 'rejected update prints status' '
 rm -f "$HTTPD_DOCUMENT_ROOT_PATH/test_repo.git/hooks/update"
 
 cat >exp <<EOF
-
 GET  /smart/test_repo.git/info/refs?service=git-upload-pack HTTP/1.1 200
 POST /smart/test_repo.git/git-upload-pack HTTP/1.1 200
 GET  /smart/test_repo.git/info/refs?service=git-receive-pack HTTP/1.1 200
-- 
2.18.0.273.g57f1ecce9c

[PATCH v2 2/3] t/lib-httpd: add the strip_access_log() helper function

[SZEDER Gábor]

Four tests in three httpd-related test scripts check the contents of
Apache's 'access.log', and they all do so by running 'sed' with the
exact same script consisting of four s/// commands to strip
uninteresting log fields and to vertically align the requested URLs.

Extract this into a common helper function 'strip_access_log' in
'lib-httpd.sh', and use it in all of those tests.

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---
 t/lib-httpd.sh              |  9 +++++++++
 t/t5541-http-push-smart.sh  | 14 ++------------
 t/t5551-http-fetch-smart.sh |  7 +------
 t/t5561-http-backend.sh     |  7 +------
 4 files changed, 13 insertions(+), 24 deletions(-)

diff --git a/t/lib-httpd.sh b/t/lib-httpd.sh
index 435a37465a..b6788fea57 100644
--- a/t/lib-httpd.sh
+++ b/t/lib-httpd.sh
@@ -287,3 +287,12 @@ expect_askpass() {
 	test_cmp "$TRASH_DIRECTORY/askpass-expect" \
 		 "$TRASH_DIRECTORY/askpass-query"
 }
+
+strip_access_log() {
+	sed -e "
+		s/^.* \"//
+		s/\"//
+		s/ [1-9][0-9]*\$//
+		s/^GET /GET  /
+	" "$HTTPD_ROOT_PATH"/access.log
+}
diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh
index d623cbad97..6cd986797d 100755
--- a/t/t5541-http-push-smart.sh
+++ b/t/t5541-http-push-smart.sh
@@ -43,12 +43,7 @@ test_expect_success 'no empty path components' '
 	cd "$ROOT_PATH" &&
 	git clone $HTTPD_URL/smart/test_repo.git/ test_repo_clone &&
 
-	sed -e "
-		s/^.* \"//
-		s/\"//
-		s/ [1-9][0-9]*\$//
-		s/^GET /GET  /
-	" >act <"$HTTPD_ROOT_PATH"/access.log &&
+	strip_access_log >act &&
 
 	# Clear the log, so that it does not affect the "used receive-pack
 	# service" test which reads the log too.
@@ -137,12 +132,7 @@ GET  /smart/test_repo.git/info/refs?service=git-receive-pack HTTP/1.1 200
 POST /smart/test_repo.git/git-receive-pack HTTP/1.1 200
 EOF
 test_expect_success 'used receive-pack service' '
-	sed -e "
-		s/^.* \"//
-		s/\"//
-		s/ [1-9][0-9]*\$//
-		s/^GET /GET  /
-	" >act <"$HTTPD_ROOT_PATH"/access.log &&
+	strip_access_log >act &&
 	test_cmp exp act
 '
 
diff --git a/t/t5551-http-fetch-smart.sh b/t/t5551-http-fetch-smart.sh
index 913089b144..c8b6ec493b 100755
--- a/t/t5551-http-fetch-smart.sh
+++ b/t/t5551-http-fetch-smart.sh
@@ -103,12 +103,7 @@ GET  /smart/repo.git/info/refs?service=git-upload-pack HTTP/1.1 200
 POST /smart/repo.git/git-upload-pack HTTP/1.1 200
 EOF
 test_expect_success 'used upload-pack service' '
-	sed -e "
-		s/^.* \"//
-		s/\"//
-		s/ [1-9][0-9]*\$//
-		s/^GET /GET  /
-	" >act <"$HTTPD_ROOT_PATH"/access.log &&
+	strip_access_log >act &&
 	test_cmp exp act
 '
 
diff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh
index 84a955770a..4248b5a06d 100755
--- a/t/t5561-http-backend.sh
+++ b/t/t5561-http-backend.sh
@@ -129,12 +129,7 @@ GET  /smart/repo.git/info/refs?service=git-receive-pack HTTP/1.1 403 -
 POST /smart/repo.git/git-receive-pack HTTP/1.1 403 -
 EOF
 test_expect_success 'server request log matches test results' '
-	sed -e "
-		s/^.* \"//
-		s/\"//
-		s/ [1-9][0-9]*\$//
-		s/^GET /GET  /
-	" >act <"$HTTPD_ROOT_PATH"/access.log &&
+	strip_access_log >act &&
 	test_cmp exp act
 '
 
-- 
2.18.0.273.g57f1ecce9c

[PATCH v2 3/3] t/lib-httpd: avoid occasional failures when checking access.log

[SZEDER Gábor]

The last test of 't5561-http-backend.sh', 'server request log matches
test results' may fail occasionally, because the order of entries in
Apache's access log doesn't match the order of requests sent in the
previous tests, although all the right requests are there.  I saw it
fail on Travis CI five times in the span of about half a year, when
the order of two subsequent requests was flipped, and could trigger
the failure with a modified Git.  However, I was unable to trigger it
with stock Git on my machine.  Three tests in
't5541-http-push-smart.sh' and 't5551-http-fetch-smart.sh' check
requests in the log the same way, so they might be prone to a similar
occasional failure as well.

When a test sends a HTTP request, it can continue execution after
'git-http-backend' fulfilled that request, but Apache writes the
corresponding access log entry only after 'git-http-backend' exited.
Some time inevitably passes between fulfilling the request and writing
the log entry, and, under unfavourable circumstances, enough time
might pass for the subsequent request to be sent and fulfilled by a
different Apache thread or process, and then Apache writes access log
entries racily.

This effect can be exacerbated by adding a bit of variable delay after
the request is fulfilled but before 'git-http-backend' exits, e.g.
like this:

  diff --git a/http-backend.c b/http-backend.c
  index f3dc218b2..bbf4c125b 100644
  --- a/http-backend.c
  +++ b/http-backend.c
  @@ -709,5 +709,7 @@ int cmd_main(int argc, const char **argv)
   					   max_request_buffer);

   	cmd->imp(&hdr, cmd_arg);
  +	if (getpid() % 2)
  +		sleep(1);
   	return 0;
   }

This delay considerably increases the chances of log entries being
written out of order, and in turn makes t5561's last test fail almost
every time.  Alas, it doesn't seem to be enough to trigger a similar
failure in t5541 and t5551.

So, since we can't just rely on the order of access log entries always
corresponding the order of requests, make checking the access log more
deterministic by sorting (simply lexicographically) both the stripped
access log entries and the expected entries before the comparison with
'test_cmp'.  This way the order of log entries won't matter and
occasional out-of-order entries won't trigger a test failure, but the
comparison will still notice any unexpected or missing log entries.

OTOH, this sorting will make it harder to identify from which test an
unexpected log entry came from or which test's request went missing.
Therefore, in case of an error include the comparison of the unsorted
log enries in the test output as well.

And since all this should be performed in four tests in three test
scripts, put this into a new helper function 'check_access_log' in
't/lib-httpd.sh'.

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---
 t/lib-httpd.sh              | 12 ++++++++++++
 t/t5541-http-push-smart.sh  | 13 +++++--------
 t/t5551-http-fetch-smart.sh |  3 +--
 t/t5561-http-backend.sh     |  3 +--
 4 files changed, 19 insertions(+), 12 deletions(-)

diff --git a/t/lib-httpd.sh b/t/lib-httpd.sh
index b6788fea57..7f060aebd0 100644
--- a/t/lib-httpd.sh
+++ b/t/lib-httpd.sh
@@ -296,3 +296,15 @@ strip_access_log() {
 		s/^GET /GET  /
 	" "$HTTPD_ROOT_PATH"/access.log
 }
+
+# Requires one argument: the name of a file containing the expected stripped
+# access log entries.
+check_access_log() {
+	sort "$1" >"$1".sorted &&
+	strip_access_log >access.log.stripped &&
+	sort access.log.stripped >access.log.sorted &&
+	if ! test_cmp "$1".sorted access.log.sorted
+	then
+		test_cmp "$1" access.log.stripped
+	fi
+}
diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh
index 6cd986797d..a481e3989a 100755
--- a/t/t5541-http-push-smart.sh
+++ b/t/t5541-http-push-smart.sh
@@ -43,15 +43,13 @@ test_expect_success 'no empty path components' '
 	cd "$ROOT_PATH" &&
 	git clone $HTTPD_URL/smart/test_repo.git/ test_repo_clone &&
 
-	strip_access_log >act &&
+	check_access_log exp
+'
 
+test_expect_success 'clear access log' '
 	# Clear the log, so that it does not affect the "used receive-pack
 	# service" test which reads the log too.
-	#
-	# We do this before the actual comparison to ensure the log is cleared.
-	>"$HTTPD_ROOT_PATH"/access.log &&
-
-	test_cmp exp act
+	>"$HTTPD_ROOT_PATH"/access.log
 '
 
 test_expect_success 'clone remote repository' '
@@ -132,8 +130,7 @@ GET  /smart/test_repo.git/info/refs?service=git-receive-pack HTTP/1.1 200
 POST /smart/test_repo.git/git-receive-pack HTTP/1.1 200
 EOF
 test_expect_success 'used receive-pack service' '
-	strip_access_log >act &&
-	test_cmp exp act
+	check_access_log exp
 '
 
 test_http_push_nonff "$HTTPD_DOCUMENT_ROOT_PATH"/test_repo.git \
diff --git a/t/t5551-http-fetch-smart.sh b/t/t5551-http-fetch-smart.sh
index c8b6ec493b..3aab44bdcb 100755
--- a/t/t5551-http-fetch-smart.sh
+++ b/t/t5551-http-fetch-smart.sh
@@ -103,8 +103,7 @@ GET  /smart/repo.git/info/refs?service=git-upload-pack HTTP/1.1 200
 POST /smart/repo.git/git-upload-pack HTTP/1.1 200
 EOF
 test_expect_success 'used upload-pack service' '
-	strip_access_log >act &&
-	test_cmp exp act
+	check_access_log exp
 '
 
 test_expect_success 'follow redirects (301)' '
diff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh
index 4248b5a06d..1c49054595 100755
--- a/t/t5561-http-backend.sh
+++ b/t/t5561-http-backend.sh
@@ -129,8 +129,7 @@ GET  /smart/repo.git/info/refs?service=git-receive-pack HTTP/1.1 403 -
 POST /smart/repo.git/git-receive-pack HTTP/1.1 403 -
 EOF
 test_expect_success 'server request log matches test results' '
-	strip_access_log >act &&
-	test_cmp exp act
+	check_access_log exp
 '
 
 stop_httpd
-- 
2.18.0.273.g57f1ecce9c

Re: [RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure

[Jeff King]

On Wed, Jul 11, 2018 at 02:53:23PM +0200, SZEDER Gábor wrote:

> > I.e., could we have a situation where we make a request, the client
> > finishes, and then we look at the logs, but nothing has been written by
> > apache yet?
> 
> That's possible, I suppose.  Highly improbable, but possible.  Or the
> log entries can be written only partially by the time we look at them.

Digging into earlier cases I had seen on my local box, my impression was
that this was the problem I was seeing (not reordering). But it's
entirely possible that I was confused by reordering. I've been trying to
reproduce, but after 5 minutes of t5561 running in a tight loop under
high load, I haven't gotten a single failure.

> Anyway, I would prefer not to do anything about it just yet, because
> I'm curious :) and I'd like to see whether this actually happens in
> practice.

I can't reproduce for now, so I'm happy either way. :)

> > What if the test script provides the in-order expectation, but we check
> > only the unordered version (by sorting both actual and expected output
> > on the fly)? That would give us a more relaxed check most of the time,
> > but somebody digging in to a failure could run the ordered diff (or we
> > could even show it automatically on failure instead of just using
> > test_cmp).
> 
> this is the fix I'll go for in v2.

Great. That seems much simpler to reason about. I'll take a look.

-Peff

Re: [PATCH v2 3/3] t/lib-httpd: avoid occasional failures when checking access.log

[Jeff King]

On Wed, Jul 11, 2018 at 02:56:47PM +0200, SZEDER Gábor wrote:

> +# Requires one argument: the name of a file containing the expected stripped
> +# access log entries.
> +check_access_log() {
> +	sort "$1" >"$1".sorted &&
> +	strip_access_log >access.log.stripped &&
> +	sort access.log.stripped >access.log.sorted &&
> +	if ! test_cmp "$1".sorted access.log.sorted
> +	then
> +		test_cmp "$1" access.log.stripped
> +	fi
> +}

This will generate output showing both the unsorted and sorted
differences. Do we want to suppress the sorted ones (e.g., by just using
"cmp" directly)? I guess it doesn't matter unless there is an actual
test failure, but I just wonder if it would be confusing to see both.

> diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh
> index 6cd986797d..a481e3989a 100755
> --- a/t/t5541-http-push-smart.sh
> +++ b/t/t5541-http-push-smart.sh
> @@ -43,15 +43,13 @@ test_expect_success 'no empty path components' '
>  	cd "$ROOT_PATH" &&
>  	git clone $HTTPD_URL/smart/test_repo.git/ test_repo_clone &&
>  
> -	strip_access_log >act &&
> +	check_access_log exp
> +'
>  
> +test_expect_success 'clear access log' '
>  	# Clear the log, so that it does not affect the "used receive-pack
>  	# service" test which reads the log too.
> -	#
> -	# We do this before the actual comparison to ensure the log is cleared.
> -	>"$HTTPD_ROOT_PATH"/access.log &&
> -
> -	test_cmp exp act
> +	>"$HTTPD_ROOT_PATH"/access.log
>  '

This took some head-scratching, mostly because of the original comment.
I thought the "before" here was referring to a timing issue (maybe
because we're talking about timing ;) ).

But it is really "make sure that a failed test here does not prevent us
from doing this cleanup". So the original really should have just
dropped that comment and added a test_when_finished. Bumping it into a
separate test as you have here accomplishes the same thing.

-Peff

Re: [PATCH v2 0/3] Fix occasional test failures in http tests

[Jeff King]

On Wed, Jul 11, 2018 at 02:56:44PM +0200, SZEDER Gábor wrote:

> 't5561-http-backend.sh' is prone to occasional failures; luckily it's
> not 'git-http-backend's fault, but the test script is a bit racy.  I
> won't go into the details here, patch 3/3's commit message discusses
> it at length.
> 
> v1 is here; it haven't been picked up by Junio:
> 
>   https://public-inbox.org/git/20180614123107.11608-1-szeder.dev@gmail.com/T/#u
> 
> The first two patches are identical to those in v1, and the last patch
> implements a different and simpler fix than in v1, following Peff's
> suggestion.  The third patch was dropped, because it's not necessary for
> this simpler fix.

The first two look obviously correct as before. I picked a few minor
nits in the third one. But if your response is "no, I prefer it the way
I wrote it", then I am perfectly happy seeing it applied as-is.

Thanks for finishing this up.

-Peff

Re: [PATCH v2 3/3] t/lib-httpd: avoid occasional failures when checking access.log

[SZEDER Gábor]

On Wed, Jul 11, 2018 at 4:57 PM Jeff King <peff@peff.net> wrote:
>
> On Wed, Jul 11, 2018 at 02:56:47PM +0200, SZEDER Gábor wrote:
>
> > +# Requires one argument: the name of a file containing the expected stripped
> > +# access log entries.
> > +check_access_log() {
> > +     sort "$1" >"$1".sorted &&
> > +     strip_access_log >access.log.stripped &&
> > +     sort access.log.stripped >access.log.sorted &&
> > +     if ! test_cmp "$1".sorted access.log.sorted
> > +     then
> > +             test_cmp "$1" access.log.stripped
> > +     fi
> > +}
>
> This will generate output showing both the unsorted and sorted
> differences. Do we want to suppress the sorted ones (e.g., by just using
> "cmp" directly)? I guess it doesn't matter unless there is an actual
> test failure, but I just wonder if it would be confusing to see both.

I have no opinion about this, at all.  I tried it both ways back then,
and didn't find one any better than the other, so I just chose the
simpler-shorter one, i.e. no 2>/dev/null redirection in the condition.

> > diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh
> > index 6cd986797d..a481e3989a 100755
> > --- a/t/t5541-http-push-smart.sh
> > +++ b/t/t5541-http-push-smart.sh
> > @@ -43,15 +43,13 @@ test_expect_success 'no empty path components' '
> >       cd "$ROOT_PATH" &&
> >       git clone $HTTPD_URL/smart/test_repo.git/ test_repo_clone &&
> >
> > -     strip_access_log >act &&
> > +     check_access_log exp
> > +'
> >
> > +test_expect_success 'clear access log' '
> >       # Clear the log, so that it does not affect the "used receive-pack
> >       # service" test which reads the log too.
> > -     #
> > -     # We do this before the actual comparison to ensure the log is cleared.
> > -     >"$HTTPD_ROOT_PATH"/access.log &&
> > -
> > -     test_cmp exp act
> > +     >"$HTTPD_ROOT_PATH"/access.log
> >  '
>
> This took some head-scratching, mostly because of the original comment.
> I thought the "before" here was referring to a timing issue (maybe
> because we're talking about timing ;) ).

Heh, I had to do some head-scratching now as well...  That's what I
get for updating the patch, and then waiting almost a month to finish
it up and update the commit message.

> But it is really "make sure that a failed test here does not prevent us
> from doing this cleanup". So the original really should have just
> dropped that comment and added a test_when_finished. Bumping it into a
> separate test as you have here accomplishes the same thing.

After taking a step back, I think this would fit better into the first
patch, wouldn't it?
I will send v3 shortly.

Re: [PATCH v2 3/3] t/lib-httpd: avoid occasional failures when checking access.log

[Jeff King]

On Wed, Jul 11, 2018 at 07:26:19PM +0200, SZEDER Gábor wrote:

> > But it is really "make sure that a failed test here does not prevent us
> > from doing this cleanup". So the original really should have just
> > dropped that comment and added a test_when_finished. Bumping it into a
> > separate test as you have here accomplishes the same thing.
> 
> After taking a step back, I think this would fit better into the first
> patch, wouldn't it?
> I will send v3 shortly.

Yeah, I agree it would be even nicer to clean it up there.

-Peff

[PATCH v3 0/3] Fix occasional test failures in http tests

[SZEDER Gábor]

To recap: 't5561-http-backend.sh' is prone to occasional failures;
luckily it's not 'git-http-backend's fault, but the test script is a
bit racy; patch 3/3's commit message discusses the details at length.

Changes since v2:

  - Use 'test_when_finished' to clear the access log in the first
    patch.  (and necessary adjustments to the subsequent patches
    because of conflicts)
  
Interdiff included below.  (I wanted to include range-diff, but it
didn't make any sense)


SZEDER Gábor (3):
  t5541: clean up truncating access log
  t/lib-httpd: add the strip_access_log() helper function
  t/lib-httpd: avoid occasional failures when checking access.log

 t/lib-httpd.sh              | 21 +++++++++++++++++++++
 t/t5541-http-push-smart.sh  | 28 ++++++----------------------
 t/t5551-http-fetch-smart.sh |  8 +-------
 t/t5561-http-backend.sh     |  8 +-------
 4 files changed, 29 insertions(+), 36 deletions(-)

-- 
2.18.0.305.g66e9e0a543

diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh
index a481e3989a..a9836e4af0 100755
--- a/t/t5541-http-push-smart.sh
+++ b/t/t5541-http-push-smart.sh
@@ -38,6 +38,10 @@ GET  /smart/test_repo.git/info/refs?service=git-upload-pack HTTP/1.1 200
 POST /smart/test_repo.git/git-upload-pack HTTP/1.1 200
 EOF
 test_expect_success 'no empty path components' '
+	# Clear the log, so that it does not affect the "used receive-pack
+	# service" test which reads the log too.
+	test_when_finished ">\"$HTTPD_ROOT_PATH\"/access.log" &&
+
 	# In the URL, add a trailing slash, and see if git appends yet another
 	# slash.
 	cd "$ROOT_PATH" &&
@@ -46,12 +50,6 @@ test_expect_success 'no empty path components' '
 	check_access_log exp
 '
 
-test_expect_success 'clear access log' '
-	# Clear the log, so that it does not affect the "used receive-pack
-	# service" test which reads the log too.
-	>"$HTTPD_ROOT_PATH"/access.log
-'
-
 test_expect_success 'clone remote repository' '
 	rm -rf test_repo_clone &&
 	git clone $HTTPD_URL/smart/test_repo.git test_repo_clone &&

[PATCH v3 1/3] t5541: clean up truncating access log

[SZEDER Gábor]

In the second test of 't5541-http-push-smart.sh', 'no empty path
components' we truncate Apache's access log by running:

  echo >.../access.log

There are two issues with this approach:

  - This doesn't leave an empty file behind, like a proper truncation
    would, but a file with a lone newline in it.  Consequently, a
    later test checking the log's contents must consider this improper
    truncation and include an empty line in the expected content.

  - This truncation is done in the middle of the test, because,
    quoting the in-code comment, "we do this [truncation] before the
    actual comparison to ensure the log is cleared" even when
    subsequent 'test_cmp' fails.  Alas, this is not quite robust
    enough, as it is conceivable that 'git clone' fails after already
    having sent a request, in which case the access log would not be
    truncated and would leave stray log entries behind.

Since there is no need for that newline at all, drop the 'echo' from
the truncation and adjust the expected content accordingly.
Furthermore, make sure that the truncation is performed no matter
whether and how 'git clone' fails unexpectedly by specifying it as a
'test_when_finished' command.

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---
 t/t5541-http-push-smart.sh | 12 ++++--------
 1 file changed, 4 insertions(+), 8 deletions(-)

diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh
index a2af693068..5c9ca19401 100755
--- a/t/t5541-http-push-smart.sh
+++ b/t/t5541-http-push-smart.sh
@@ -38,6 +38,10 @@ GET  /smart/test_repo.git/info/refs?service=git-upload-pack HTTP/1.1 200
 POST /smart/test_repo.git/git-upload-pack HTTP/1.1 200
 EOF
 test_expect_success 'no empty path components' '
+	# Clear the log, so that it does not affect the "used receive-pack
+	# service" test which reads the log too.
+	test_when_finished ">\"$HTTPD_ROOT_PATH\"/access.log" &&
+
 	# In the URL, add a trailing slash, and see if git appends yet another
 	# slash.
 	cd "$ROOT_PATH" &&
@@ -49,13 +53,6 @@ test_expect_success 'no empty path components' '
 		s/ [1-9][0-9]*\$//
 		s/^GET /GET  /
 	" >act <"$HTTPD_ROOT_PATH"/access.log &&
-
-	# Clear the log, so that it does not affect the "used receive-pack
-	# service" test which reads the log too.
-	#
-	# We do this before the actual comparison to ensure the log is cleared.
-	echo > "$HTTPD_ROOT_PATH"/access.log &&
-
 	test_cmp exp act
 '
 
@@ -124,7 +121,6 @@ test_expect_success 'rejected update prints status' '
 rm -f "$HTTPD_DOCUMENT_ROOT_PATH/test_repo.git/hooks/update"
 
 cat >exp <<EOF
-
 GET  /smart/test_repo.git/info/refs?service=git-upload-pack HTTP/1.1 200
 POST /smart/test_repo.git/git-upload-pack HTTP/1.1 200
 GET  /smart/test_repo.git/info/refs?service=git-receive-pack HTTP/1.1 200
-- 
2.18.0.305.g66e9e0a543

[PATCH v3 2/3] t/lib-httpd: add the strip_access_log() helper function

[SZEDER Gábor]

Four tests in three httpd-related test scripts check the contents of
Apache's 'access.log', and they all do so by running 'sed' with the
exact same script consisting of four s/// commands to strip
uninteresting log fields and to vertically align the requested URLs.

Extract this into a common helper function 'strip_access_log' in
'lib-httpd.sh', and use it in all of those tests.

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---
 t/lib-httpd.sh              |  9 +++++++++
 t/t5541-http-push-smart.sh  | 14 ++------------
 t/t5551-http-fetch-smart.sh |  7 +------
 t/t5561-http-backend.sh     |  7 +------
 4 files changed, 13 insertions(+), 24 deletions(-)

diff --git a/t/lib-httpd.sh b/t/lib-httpd.sh
index 435a37465a..b6788fea57 100644
--- a/t/lib-httpd.sh
+++ b/t/lib-httpd.sh
@@ -287,3 +287,12 @@ expect_askpass() {
 	test_cmp "$TRASH_DIRECTORY/askpass-expect" \
 		 "$TRASH_DIRECTORY/askpass-query"
 }
+
+strip_access_log() {
+	sed -e "
+		s/^.* \"//
+		s/\"//
+		s/ [1-9][0-9]*\$//
+		s/^GET /GET  /
+	" "$HTTPD_ROOT_PATH"/access.log
+}
diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh
index 5c9ca19401..83390f80cc 100755
--- a/t/t5541-http-push-smart.sh
+++ b/t/t5541-http-push-smart.sh
@@ -47,12 +47,7 @@ test_expect_success 'no empty path components' '
 	cd "$ROOT_PATH" &&
 	git clone $HTTPD_URL/smart/test_repo.git/ test_repo_clone &&
 
-	sed -e "
-		s/^.* \"//
-		s/\"//
-		s/ [1-9][0-9]*\$//
-		s/^GET /GET  /
-	" >act <"$HTTPD_ROOT_PATH"/access.log &&
+	strip_access_log >act &&
 	test_cmp exp act
 '
 
@@ -134,12 +129,7 @@ GET  /smart/test_repo.git/info/refs?service=git-receive-pack HTTP/1.1 200
 POST /smart/test_repo.git/git-receive-pack HTTP/1.1 200
 EOF
 test_expect_success 'used receive-pack service' '
-	sed -e "
-		s/^.* \"//
-		s/\"//
-		s/ [1-9][0-9]*\$//
-		s/^GET /GET  /
-	" >act <"$HTTPD_ROOT_PATH"/access.log &&
+	strip_access_log >act &&
 	test_cmp exp act
 '
 
diff --git a/t/t5551-http-fetch-smart.sh b/t/t5551-http-fetch-smart.sh
index 913089b144..c8b6ec493b 100755
--- a/t/t5551-http-fetch-smart.sh
+++ b/t/t5551-http-fetch-smart.sh
@@ -103,12 +103,7 @@ GET  /smart/repo.git/info/refs?service=git-upload-pack HTTP/1.1 200
 POST /smart/repo.git/git-upload-pack HTTP/1.1 200
 EOF
 test_expect_success 'used upload-pack service' '
-	sed -e "
-		s/^.* \"//
-		s/\"//
-		s/ [1-9][0-9]*\$//
-		s/^GET /GET  /
-	" >act <"$HTTPD_ROOT_PATH"/access.log &&
+	strip_access_log >act &&
 	test_cmp exp act
 '
 
diff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh
index 84a955770a..4248b5a06d 100755
--- a/t/t5561-http-backend.sh
+++ b/t/t5561-http-backend.sh
@@ -129,12 +129,7 @@ GET  /smart/repo.git/info/refs?service=git-receive-pack HTTP/1.1 403 -
 POST /smart/repo.git/git-receive-pack HTTP/1.1 403 -
 EOF
 test_expect_success 'server request log matches test results' '
-	sed -e "
-		s/^.* \"//
-		s/\"//
-		s/ [1-9][0-9]*\$//
-		s/^GET /GET  /
-	" >act <"$HTTPD_ROOT_PATH"/access.log &&
+	strip_access_log >act &&
 	test_cmp exp act
 '
 
-- 
2.18.0.305.g66e9e0a543

[PATCH v3 3/3] t/lib-httpd: avoid occasional failures when checking access.log

[SZEDER Gábor]

The last test of 't5561-http-backend.sh', 'server request log matches
test results' may fail occasionally, because the order of entries in
Apache's access log doesn't match the order of requests sent in the
previous tests, although all the right requests are there.  I saw it
fail on Travis CI five times in the span of about half a year, when
the order of two subsequent requests was flipped, and could trigger
the failure with a modified Git.  However, I was unable to trigger it
with stock Git on my machine.  Three tests in
't5541-http-push-smart.sh' and 't5551-http-fetch-smart.sh' check
requests in the log the same way, so they might be prone to a similar
occasional failure as well.

When a test sends a HTTP request, it can continue execution after
'git-http-backend' fulfilled that request, but Apache writes the
corresponding access log entry only after 'git-http-backend' exited.
Some time inevitably passes between fulfilling the request and writing
the log entry, and, under unfavourable circumstances, enough time
might pass for the subsequent request to be sent and fulfilled by a
different Apache thread or process, and then Apache writes access log
entries racily.

This effect can be exacerbated by adding a bit of variable delay after
the request is fulfilled but before 'git-http-backend' exits, e.g.
like this:

  diff --git a/http-backend.c b/http-backend.c
  index f3dc218b2..bbf4c125b 100644
  --- a/http-backend.c
  +++ b/http-backend.c
  @@ -709,5 +709,7 @@ int cmd_main(int argc, const char **argv)
   					   max_request_buffer);

   	cmd->imp(&hdr, cmd_arg);
  +	if (getpid() % 2)
  +		sleep(1);
   	return 0;
   }

This delay considerably increases the chances of log entries being
written out of order, and in turn makes t5561's last test fail almost
every time.  Alas, it doesn't seem to be enough to trigger a similar
failure in t5541 and t5551.

So, since we can't just rely on the order of access log entries always
corresponding the order of requests, make checking the access log more
deterministic by sorting (simply lexicographically) both the stripped
access log entries and the expected entries before the comparison with
'test_cmp'.  This way the order of log entries won't matter and
occasional out-of-order entries won't trigger a test failure, but the
comparison will still notice any unexpected or missing log entries.

OTOH, this sorting will make it harder to identify from which test an
unexpected log entry came from or which test's request went missing.
Therefore, in case of an error include the comparison of the unsorted
log enries in the test output as well.

And since all this should be performed in four tests in three test
scripts, put this into a new helper function 'check_access_log' in
't/lib-httpd.sh'.

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
---
 t/lib-httpd.sh              | 12 ++++++++++++
 t/t5541-http-push-smart.sh  |  6 ++----
 t/t5551-http-fetch-smart.sh |  3 +--
 t/t5561-http-backend.sh     |  3 +--
 4 files changed, 16 insertions(+), 8 deletions(-)

diff --git a/t/lib-httpd.sh b/t/lib-httpd.sh
index b6788fea57..7f060aebd0 100644
--- a/t/lib-httpd.sh
+++ b/t/lib-httpd.sh
@@ -296,3 +296,15 @@ strip_access_log() {
 		s/^GET /GET  /
 	" "$HTTPD_ROOT_PATH"/access.log
 }
+
+# Requires one argument: the name of a file containing the expected stripped
+# access log entries.
+check_access_log() {
+	sort "$1" >"$1".sorted &&
+	strip_access_log >access.log.stripped &&
+	sort access.log.stripped >access.log.sorted &&
+	if ! test_cmp "$1".sorted access.log.sorted
+	then
+		test_cmp "$1" access.log.stripped
+	fi
+}
diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh
index 83390f80cc..a9836e4af0 100755
--- a/t/t5541-http-push-smart.sh
+++ b/t/t5541-http-push-smart.sh
@@ -47,8 +47,7 @@ test_expect_success 'no empty path components' '
 	cd "$ROOT_PATH" &&
 	git clone $HTTPD_URL/smart/test_repo.git/ test_repo_clone &&
 
-	strip_access_log >act &&
-	test_cmp exp act
+	check_access_log exp
 '
 
 test_expect_success 'clone remote repository' '
@@ -129,8 +128,7 @@ GET  /smart/test_repo.git/info/refs?service=git-receive-pack HTTP/1.1 200
 POST /smart/test_repo.git/git-receive-pack HTTP/1.1 200
 EOF
 test_expect_success 'used receive-pack service' '
-	strip_access_log >act &&
-	test_cmp exp act
+	check_access_log exp
 '
 
 test_http_push_nonff "$HTTPD_DOCUMENT_ROOT_PATH"/test_repo.git \
diff --git a/t/t5551-http-fetch-smart.sh b/t/t5551-http-fetch-smart.sh
index c8b6ec493b..3aab44bdcb 100755
--- a/t/t5551-http-fetch-smart.sh
+++ b/t/t5551-http-fetch-smart.sh
@@ -103,8 +103,7 @@ GET  /smart/repo.git/info/refs?service=git-upload-pack HTTP/1.1 200
 POST /smart/repo.git/git-upload-pack HTTP/1.1 200
 EOF
 test_expect_success 'used upload-pack service' '
-	strip_access_log >act &&
-	test_cmp exp act
+	check_access_log exp
 '
 
 test_expect_success 'follow redirects (301)' '
diff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh
index 4248b5a06d..1c49054595 100755
--- a/t/t5561-http-backend.sh
+++ b/t/t5561-http-backend.sh
@@ -129,8 +129,7 @@ GET  /smart/repo.git/info/refs?service=git-receive-pack HTTP/1.1 403 -
 POST /smart/repo.git/git-receive-pack HTTP/1.1 403 -
 EOF
 test_expect_success 'server request log matches test results' '
-	strip_access_log >act &&
-	test_cmp exp act
+	check_access_log exp
 '
 
 stop_httpd
-- 
2.18.0.305.g66e9e0a543

Re: [PATCH v3 1/3] t5541: clean up truncating access log

[Jeff King]

On Thu, Jul 12, 2018 at 02:22:14PM +0200, SZEDER Gábor wrote:

> diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh
> index a2af693068..5c9ca19401 100755
> --- a/t/t5541-http-push-smart.sh
> +++ b/t/t5541-http-push-smart.sh
> @@ -38,6 +38,10 @@ GET  /smart/test_repo.git/info/refs?service=git-upload-pack HTTP/1.1 200
>  POST /smart/test_repo.git/git-upload-pack HTTP/1.1 200
>  EOF
>  test_expect_success 'no empty path components' '
> +	# Clear the log, so that it does not affect the "used receive-pack
> +	# service" test which reads the log too.
> +	test_when_finished ">\"$HTTPD_ROOT_PATH\"/access.log" &&

I think you want to escape the $ here, too, so the eval sees the
variable and not its expanded value.

Other than that, this iteration looks good (and patch 3 is much easier
to read).

-Peff