From a704c6439a9a34045f6d5bde78d5982b11e6d478 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?SZEDER=20G=C3=A1bor?= Date: Thu, 12 Jul 2018 14:22:14 +0200 Subject: [PATCH 1/3] t5541: clean up truncating access log MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Signed-off-by: Junio C Hamano --- 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 d38bf32470..dc08275b7d 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 < Date: Thu, 12 Jul 2018 14:22:15 +0200 Subject: [PATCH 2/3] t/lib-httpd: add the strip_access_log() helper function MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Signed-off-by: Junio C Hamano --- 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 dc08275b7d..3fbe7722ff 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 a51b7e20d3..5f98fa90af 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 ' From e8b3b2e275106c4fae1fb2b5969924a4565615e6 Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?SZEDER=20G=C3=A1bor?= Date: Thu, 12 Jul 2018 14:22:16 +0200 Subject: [PATCH 3/3] t/lib-httpd: avoid occasional failures when checking access.log MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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 Signed-off-by: Junio C Hamano --- 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 3fbe7722ff..918822868e 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 5f98fa90af..f0b03e5190 100755 --- a/t/t5551-http-fetch-smart.sh +++ b/t/t5551-http-fetch-smart.sh @@ -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 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 6a0f240e6d..28c74b80a8 100755 --- a/t/t5561-http-backend.sh +++ b/t/t5561-http-backend.sh @@ -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 - EOF test_expect_success 'server request log matches test results' ' - strip_access_log >act && - test_cmp exp act + check_access_log exp ' stop_httpd