t/lib-httpd: avoid occasional failures when checking access.log
authorSZEDER Gábor <szeder.dev@gmail.com>
Thu, 12 Jul 2018 12:22:16 +0000 (14:22 +0200)
committerJunio C Hamano <gitster@pobox.com>
Thu, 12 Jul 2018 17:40:31 +0000 (10:40 -0700)
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)

    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

Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>
Signed-off-by: Junio C Hamano <gitster@pobox.com>

index b6788fe..7f060ae 100644 (file)
@@ -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
index 3fbe772..9188228 100755 (executable)
@@ -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
 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 \
index 5f98fa9..f0b03e5 100755 (executable)
@@ -98,8 +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
 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)' '
index 6a0f240..28c74b8 100755 (executable)
@@ -123,8 +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 -
 test_expect_success 'server request log matches test results' '
-       strip_access_log >act &&
-       test_cmp exp act
+       check_access_log exp