{"thread":{"id":"48709","subject":"[RFC PATCH 0/4] Fix occasional test failures in http tests","startedAt":"2018-06-14T12:31:20Z","lastAt":"2018-07-12T15:56:06Z","messageCount":26,"participants":["SZEDER Gábor","Junio C Hamano","Jeff King"],"isPatch":true,"patchVersion":1,"patchTotal":4},"messages":[{"id":"350146","messageId":"20180614123107.11608-1-szeder.dev@gmail.com","threadId":"48709","inReplyTo":null,"subject":"[RFC PATCH 0/4] Fix occasional test failures in http tests","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-06-14T12:31:03Z","receivedAt":"2018-06-14T12:31:20Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"'t5561-http-backend.sh' is prone to occasional failures; luckily it's\nnot 'git-http-backend's fault, but the test script is a bit racy. I\nwon't go into the details here, patch 4/4's commit message discusses\nit at length. 4/4 also fixes this issue, but I'm not particularly\nhappy with that fix, the note attached to that patch explains why,\nalong with possible alternatives, hence the RFC.\n\nEven if we settle for a different fix, I think the first two patches\nare worthy cleanups on their own right.\n\nSZEDER Gábor (4):\n t5541: avoid empty line when truncating access log\n t/lib-httpd: add the strip_access_log() helper function\n t/lib-httpd: add minor and patch version to $HTTPD_VERSION\n t/lib-httpd: sort log based on timestamp to avoid occasional failure\n\n t/lib-httpd.sh | 24 ++++++++++++++++++++++--\n t/lib-httpd/apache.conf | 5 +++++\n t/t5541-http-push-smart.sh | 17 +++--------------\n t/t5551-http-fetch-smart.sh | 7 +------\n t/t5561-http-backend.sh | 7 +------\n 5 files changed, 32 insertions(+), 28 deletions(-)\n\n-- \n2.18.0.rc0.207.ga6211da864\n\n"},{"id":"350147","messageId":"20180614123107.11608-2-szeder.dev@gmail.com","threadId":"48709","inReplyTo":"20180614123107.11608-1-szeder.dev@gmail.com","subject":"[PATCH 1/4] t5541: avoid empty line when truncating access log","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-06-14T12:31:04Z","receivedAt":"2018-06-14T12:31:24Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"The second test of 't5541-http-push-smart.sh', 'no empty path\ncomponents' truncates Apache's access log by running\n\n echo >.../access.log\n\nwhich doesn't leave an empty file behind, like a proper truncation\nwould, but a file with a lone newline in it. Consequently, a later\ntest checking the log's contents must consider this improper\ntruncation and include an empty line in the expected content.\n\nThere is no need for that newline at all, so drop the 'echo' from the\ntruncation and adjust the expected content accordingly.\n\nSigned-off-by: SZEDER Gábor \n---\n\n t/t5541-http-push-smart.sh | 3 +--\n 1 file changed, 1 insertion(+), 2 deletions(-)\n\ndiff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh\nindex 21340e89c9..c961db814d 100755\n--- a/t/t5541-http-push-smart.sh\n+++ b/t/t5541-http-push-smart.sh\n@@ -54,7 +54,7 @@ test_expect_success 'no empty path components' '\n \t# service\" test which reads the log too.\n \t#\n \t# We do this before the actual comparison to ensure the log is cleared.\n-\techo > \"$HTTPD_ROOT_PATH\"/access.log &&\n+\t>\"$HTTPD_ROOT_PATH\"/access.log &&\n \n \ttest_cmp exp act\n '\n@@ -124,7 +124,6 @@ test_expect_success 'rejected update prints status' '\n rm -f \"$HTTPD_DOCUMENT_ROOT_PATH/test_repo.git/hooks/update\"\n \n cat >exp <\n---\n t/lib-httpd.sh | 9 +++++++++\n t/t5541-http-push-smart.sh | 14 ++------------\n t/t5551-http-fetch-smart.sh | 7 +------\n t/t5561-http-backend.sh | 7 +------\n 4 files changed, 13 insertions(+), 24 deletions(-)\n\ndiff --git a/t/lib-httpd.sh b/t/lib-httpd.sh\nindex 435a37465a..b6788fea57 100644\n--- a/t/lib-httpd.sh\n+++ b/t/lib-httpd.sh\n@@ -287,3 +287,12 @@ expect_askpass() {\n \ttest_cmp \"$TRASH_DIRECTORY/askpass-expect\" \\\n \t\t \"$TRASH_DIRECTORY/askpass-query\"\n }\n+\n+strip_access_log() {\n+\tsed -e \"\n+\t\ts/^.* \\\"//\n+\t\ts/\\\"//\n+\t\ts/ [1-9][0-9]*\\$//\n+\t\ts/^GET /GET /\n+\t\" \"$HTTPD_ROOT_PATH\"/access.log\n+}\ndiff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh\nindex c961db814d..a1385800fa 100755\n--- a/t/t5541-http-push-smart.sh\n+++ b/t/t5541-http-push-smart.sh\n@@ -43,12 +43,7 @@ test_expect_success 'no empty path components' '\n \tcd \"$ROOT_PATH\" &&\n \tgit clone $HTTPD_URL/smart/test_repo.git/ test_repo_clone &&\n \n-\tsed -e \"\n-\t\ts/^.* \\\"//\n-\t\ts/\\\"//\n-\t\ts/ [1-9][0-9]*\\$//\n-\t\ts/^GET /GET /\n-\t\" >act <\"$HTTPD_ROOT_PATH\"/access.log &&\n+\tstrip_access_log >act &&\n \n \t# Clear the log, so that it does not affect the \"used receive-pack\n \t# service\" test which reads the log too.\n@@ -137,12 +132,7 @@ GET /smart/test_repo.git/info/refs?service=git-receive-pack HTTP/1.1 200\n POST /smart/test_repo.git/git-receive-pack HTTP/1.1 200\n EOF\n test_expect_success 'used receive-pack service' '\n-\tsed -e \"\n-\t\ts/^.* \\\"//\n-\t\ts/\\\"//\n-\t\ts/ [1-9][0-9]*\\$//\n-\t\ts/^GET /GET /\n-\t\" >act <\"$HTTPD_ROOT_PATH\"/access.log &&\n+\tstrip_access_log >act &&\n \ttest_cmp exp act\n '\n \ndiff --git a/t/t5551-http-fetch-smart.sh b/t/t5551-http-fetch-smart.sh\nindex f5721b4a59..82a4fb5e16 100755\n--- a/t/t5551-http-fetch-smart.sh\n+++ b/t/t5551-http-fetch-smart.sh\n@@ -98,12 +98,7 @@ GET /smart/repo.git/info/refs?service=git-upload-pack HTTP/1.1 200\n POST /smart/repo.git/git-upload-pack HTTP/1.1 200\n EOF\n test_expect_success 'used upload-pack service' '\n-\tsed -e \"\n-\t\ts/^.* \\\"//\n-\t\ts/\\\"//\n-\t\ts/ [1-9][0-9]*\\$//\n-\t\ts/^GET /GET /\n-\t\" >act <\"$HTTPD_ROOT_PATH\"/access.log &&\n+\tstrip_access_log >act &&\n \ttest_cmp exp act\n '\n \ndiff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh\nindex 90e0d6f0fe..6a0f240e6d 100755\n--- a/t/t5561-http-backend.sh\n+++ b/t/t5561-http-backend.sh\n@@ -123,12 +123,7 @@ GET /smart/repo.git/info/refs?service=git-receive-pack HTTP/1.1 403 -\n POST /smart/repo.git/git-receive-pack HTTP/1.1 403 -\n EOF\n test_expect_success 'server request log matches test results' '\n-\tsed -e \"\n-\t\ts/^.* \\\"//\n-\t\ts/\\\"//\n-\t\ts/ [1-9][0-9]*\\$//\n-\t\ts/^GET /GET /\n-\t\" >act <\"$HTTPD_ROOT_PATH\"/access.log &&\n+\tstrip_access_log >act &&\n \ttest_cmp exp act\n '\n \n-- \n2.18.0.rc0.207.ga6211da864\n\n"},{"id":"350149","messageId":"20180614123107.11608-4-szeder.dev@gmail.com","threadId":"48709","inReplyTo":"20180614123107.11608-1-szeder.dev@gmail.com","subject":"[PATCH 3/4] t/lib-httpd: add minor and patch version to $HTTPD_VERSION","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-06-14T12:31:06Z","receivedAt":"2018-06-14T12:31:35Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"To fix an occasional test failure, the next patch will rely on an\nApache log format specifier that was introduced in version 2.2.30.\nConsequently, 't/lib-httpd.sh' must be able to decide whether the\nApache version used for testing is equal or newer than that version to\nbe able to act accordingly when processing the webserver's access log.\n\n$HTTPD_VERSION currently only contains Apache's major version, so\nchange how Apache's version string is parsed to store the minor and\npatch versions as well. Furthermore, update the only condition\nlooking at $HTTPD_VERSION to deal with the full version.\n\nSigned-off-by: SZEDER Gábor \n---\n t/lib-httpd.sh | 4 ++--\n 1 file changed, 2 insertions(+), 2 deletions(-)\n\ndiff --git a/t/lib-httpd.sh b/t/lib-httpd.sh\nindex b6788fea57..5915625631 100644\n--- a/t/lib-httpd.sh\n+++ b/t/lib-httpd.sh\n@@ -99,13 +99,13 @@ then\n fi\n \n HTTPD_VERSION=$($LIB_HTTPD_PATH -v | \\\n-\tsed -n 's/^Server version: Apache\\/\\([0-9]*\\)\\..*$/\\1/p; q')\n+\tsed -n 's/^Server version: Apache\\/\\([0-9]*\\.[0-9]*\\.[0-9]*\\).*$/\\1/p; q')\n \n if test -n \"$HTTPD_VERSION\"\n then\n \tif test -z \"$LIB_HTTPD_MODULE_PATH\"\n \tthen\n-\t\tif ! test $HTTPD_VERSION -ge 2\n+\t\tif ! test ${HTTPD_VERSION%%.*} -ge 2\n \t\tthen\n \t\t\ttest_skip_or_die $GIT_TEST_HTTPD \\\n \t\t\t\t\"at least Apache version 2 is required\"\n-- \n2.18.0.rc0.207.ga6211da864\n\n"},{"id":"350150","messageId":"20180614123107.11608-5-szeder.dev@gmail.com","threadId":"48709","inReplyTo":"20180614123107.11608-1-szeder.dev@gmail.com","subject":"[RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-06-14T12:31:07Z","receivedAt":"2018-06-14T12:31:43Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"The last test of 't5561-http-backend.sh', 'server request log matches\ntest results' may fail occasionally, because the order of entries in\nApache's access log doesn't match the order of requests sent in the\nprevious tests, although all the right requests are there. I saw it\nfail on Travis CI five times in the span of about half a year, when\nthe order of two subsequent requests was flipped, and could trigger\nthe failure with a modified Git. However, I was unable to trigger it\nwith stock Git on my machine. Three tests in\n't5541-http-push-smart.sh' and 't5551-http-fetch-smart.sh' check\nrequests in the log the same way, so they might be prone to a similar\noccasional failure as well.\n\nWhen a test sends a HTTP request, it can continue execution after\n'git-http-backend' fulfilled that request, but Apache writes the\ncorresponding access log entry only after 'git-http-backend' exited.\nSome time inevitably passes between fulfilling the request and writing\nthe log entry, and, under unfavourable circumstances, enough time\nmight pass for the subsequent request to be sent and fulfilled, and\nthen Apache writes access log entries racily.\n\nThis effect can be exacerbated by adding a bit of variable delay after\nthe request is fulfilled but before 'git-http-backend' exits, e.g.\nlike this:\n\n diff --git a/http-backend.c b/http-backend.c\n index f3dc218b2..bbf4c125b 100644\n --- a/http-backend.c\n +++ b/http-backend.c\n @@ -709,5 +709,7 @@ int cmd_main(int argc, const char **argv)\n \t\t\t\t\t max_request_buffer);\n\n \tcmd->imp(&hdr, cmd_arg);\n +\tif (getpid() % 2)\n +\t\tsleep(1);\n \treturn 0;\n }\n\nThis delay considerably increases the chances of log entries being\nwritten out of order, and in turn makes t5561's last test fail almost\nevery time. Alas, it doesn't seem to be enough to trigger a similar\nfailure in t5541 and t5551.\n\nNow, by default the timestamp of a log entry marks the beginning of\nthe request processing, not when the log entry gets written. Since\nour requests are sent sequentially, sorting the log entries based on\ntheir timestamps would ensure that their order corresponds to the\norder of our requests.\n\nTherefore, change Apache's log format to use microseconds since epoch\nas timestamps, the finest resolution Apache has to offer. This will:\n\n - give enough resolution to make reasonably sure that no two\n requests have the same timestamp; the default timestamp format has\n only one second resolution, which is not nearly enough.\n\n - make the timestamps sortable; the default timestamp format looks\n like \"[31/Jan/2018:16:33:52 +0000]\", which would trip sorting if\n the test script happens to run over month boundaries.\n\nModify the strip_access_log() helper function, used by all potentially\naffected tests, to sort the access log entries based on their\ntimestamp before stripping the uninteresting bits from the entries.\n\nUnfortunately, this \"microseconds since epoch\" is an extended time\nformat specifier which was only introduced in Apache 2.2.30 [1], and\nstandard strftime() doesn't have any format specifiers with\nmicrosecond or finer precision, so we can't use the above solution\nwith Apache versions older than 2.2.30. However, since Apache 2.2 is\nno longer maintained anyway, it's not that big a deal to leave test\nruns with those old versions prone to this occasional failure. So use\nmicrosecond timestamps and sort access log entries only if the test is\nrun with an Apache version supporting it; otherwise stick to the\ndefault timestamp format and leave the order of access log entries\nunchanged.\n\n[1] http://httpd.apache.org/docs/2.2/mod/mod_log_config.html\n\nSigned-off-by: SZEDER Gábor \n---\n\nNotes:\n The log of the latest of this test failures:\n \n https://travis-ci.org/szeder/git-cooking-topics-for-travis-ci/jobs/391499735#L3130\n \n I don't really like the fix in this patch. I think an unfortunate\n clock skew during the test run could mess up the sorting added in this\n patch and cause test failure. Or if DST or even a leap second happen\n while the test is running. Do we care? Anyway, this occasional test\n failure apparently happens more often than DST and leap seconds\n combined.\n Furthermore, in the future we might have computers fast enough to\n fulfill more than one test requests in a single microsecond; but I\n guess by that time we'll have higher resolution time formats as well.\n \n An alternative I considered was that we could decide that the order of\n requests in the access log is not important as long as all the right\n requests are there. This would inherently eliminate the raciness\n issue, but if something were to go wrong, then it would become rather\n hard to find out e.g. which request from which test has gone missing,\n especially considering that several requests are sent in more than one\n test. We could address this by truncating the access log at the\n beginning and checking its contents at the end of each test sending\n requests. Unfortunately, this would raise additional difficulties,\n because all requests in t5561 come from tests included from\n 't556x-common', i.e. from tests shared with\n 't5560-http-backend-noserver.sh', which as its name suggests doesn't\n run Apache and doesn't have an access log at all.\n \n Another alternative is to simply accept that these tests are racy, and\n that the resulting test failures are rare enough that it isn't worth\n the complexity of the workaround, but adding a comment to the affected\n tests warning about the raciness is sufficient. (But I wrote this\n when I first saw and tracked down this failure; since then I observed\n it four more times... :)\n \n --\n \n Apache doesn't maintain 2.2 anymore; the final maintenance release\n 2.2.34 was released in July 2017, almost a year ago. OTOH, our\n 't/lib-httpd/apache.conf' contains a couple of IfVersion directives\n dealing with versions <2.4, and one even with <2.1. How much do we\n actually care about these unmaintained Apache versions, and how much\n of this is just bitrotting?\n\n t/lib-httpd.sh | 13 ++++++++++++-\n t/lib-httpd/apache.conf | 5 +++++\n 2 files changed, 17 insertions(+), 1 deletion(-)\n\ndiff --git a/t/lib-httpd.sh b/t/lib-httpd.sh\nindex 5915625631..1a7fe67141 100644\n--- a/t/lib-httpd.sh\n+++ b/t/lib-httpd.sh\n@@ -289,10 +289,21 @@ expect_askpass() {\n }\n \n strip_access_log() {\n+\tcase \"$HTTPD_VERSION\" in\n+\t2.[01].*|2.2.[0-9]|2.2.[12][0-9])\n+\t\t# Apache versions < 2.2.30 didn't have any log timestamp\n+\t\t# format with microseconds precision, so don't attempt to\n+\t\t# sort the access log when testing with such old versions.\n+\t\tcat \"$HTTPD_ROOT_PATH\"/access.log\n+\t\t;;\n+\t*)\n+\t\tsort -n -k 4,4 \"$HTTPD_ROOT_PATH\"/access.log\n+\t\t;;\n+\tesac | \\\n \tsed -e \"\n \t\ts/^.* \\\"//\n \t\ts/\\\"//\n \t\ts/ [1-9][0-9]*\\$//\n \t\ts/^GET /GET /\n-\t\" \"$HTTPD_ROOT_PATH\"/access.log\n+\t\"\n }\ndiff --git a/t/lib-httpd/apache.conf b/t/lib-httpd/apache.conf\nindex 724d9ae462..8d6da6bdb2 100644\n--- a/t/lib-httpd/apache.conf\n+++ b/t/lib-httpd/apache.conf\n@@ -1,7 +1,12 @@\n ServerName dummy\n PidFile httpd.pid\n DocumentRoot www\n+= 2.2.30>\n+LogFormat \"%h %l %u %{usec}t \\\"%r\\\" %>s %b\" common\n+\n+\n LogFormat \"%h %l %u %t \\\"%r\\\" %>s %b\" common\n+\n CustomLog access.log common\n ErrorLog error.log\n \n-- \n2.18.0.rc0.207.ga6211da864\n\n"},{"id":"350161","messageId":"CAM0VKjkfLiEoTOfkC=jXx5TVmbbVvHRDB6KEPinW6Gb98p0vgA@mail.gmail.com","threadId":"48709","inReplyTo":"20180614123107.11608-5-szeder.dev@gmail.com","subject":"Re: [RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-06-14T16:39:39Z","receivedAt":"2018-06-14T16:39:44Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Thu, Jun 14, 2018 at 2:31 PM, SZEDER Gábor wrote:\n\n> When a test sends a HTTP request, it can continue execution after\n> 'git-http-backend' fulfilled that request, but Apache writes the\n> corresponding access log entry only after 'git-http-backend' exited.\n> Some time inevitably passes between fulfilling the request and writing\n> the log entry, and, under unfavourable circumstances, enough time\n> might pass for the subsequent request to be sent and fulfilled, and\n> then Apache writes access log entries racily.\n>\n> This effect can be exacerbated by adding a bit of variable delay after\n> the request is fulfilled but before 'git-http-backend' exits, e.g.\n> like this:\n>\n> diff --git a/http-backend.c b/http-backend.c\n> index f3dc218b2..bbf4c125b 100644\n> --- a/http-backend.c\n> +++ b/http-backend.c\n> @@ -709,5 +709,7 @@ int cmd_main(int argc, const char **argv)\n> max_request_buffer);\n>\n> cmd->imp(&hdr, cmd_arg);\n> + if (getpid() % 2)\n> + sleep(1);\n> return 0;\n> }\n>\n> This delay considerably increases the chances of log entries being\n> written out of order, and in turn makes t5561's last test fail almost\n> every time. Alas, it doesn't seem to be enough to trigger a similar\n> failure in t5541 and t5551.\n\nA bit of addendum here:\n\nThere are basically two \"kinds\" of requests:\n\n 1. requests asking for regular files, e.g.:\n\n GET /smart/repo.git/HEAD HTTP/1.1 200\n GET /smart/repo.git/info/refs HTTP/1.1 200\n GET /smart/repo.git/objects/info/packs HTTP/1.1 200\n\n 2. requests asking for 'git-receive-pack' or 'git-upload-pack',\n e.g.:\n\n GET /smart/repo.git/info/refs?service=git-receive-pack HTTP/1.1 200\n POST /smart/repo.git/git-receive-pack HTTP/1.1 200 -\n\nThis artificial variable delay shuffles only the access log entries\nwritten for the first kind of requests, but doesn't appear to have any\neffect on the order of log entries written for the second kind of\nrequests.\n\nt5561 sends both kinds of requests, so this variable delay is\nsufficient to make the test fail most of the time.\n\nt5541 and t5551, however, send only requests of the second kind, so\nthat's why this variable delay can't trigger a similar failure in\nthese test scripts.\n\nI haven't investigated any further what else would be necessary to\ntrigger a failure in t5541 and t5551.\n"},{"id":"350162","messageId":"xmqqvaal47dl.fsf@gitster-ct.c.googlers.com","threadId":"48709","inReplyTo":"20180614123107.11608-1-szeder.dev@gmail.com","subject":"Re: [RFC PATCH 0/4] Fix occasional test failures in http tests","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2018-06-14T17:15:18Z","receivedAt":"2018-06-14T17:15:25Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"SZEDER Gábor writes:\n\n> 't5561-http-backend.sh' is prone to occasional failures; luckily it's\n> not 'git-http-backend's fault, but the test script is a bit racy. I\n> won't go into the details here, patch 4/4's commit message discusses\n> it at length. 4/4 also fixes this issue, but I'm not particularly\n> happy with that fix, the note attached to that patch explains why,\n> along with possible alternatives, hence the RFC.\n\nInteresting.\n\n> Even if we settle for a different fix, I think the first two patches\n> are worthy cleanups on their own right.\n\nYeah, the first two are unquestionally good. \n\nThe sed expression of the second one could use sq around (instead of\ndq) to lose hard-to-read backslash quoting from there, but it\nprobably is OK to keep the second one a pure \"refactoring\" patch,\nand leave it to a separate \"further cleanup\" patch to make such a\nchange.\n\n> SZEDER Gábor (4):\n> t5541: avoid empty line when truncating access log\n> t/lib-httpd: add the strip_access_log() helper function\n> t/lib-httpd: add minor and patch version to $HTTPD_VERSION\n> t/lib-httpd: sort log based on timestamp to avoid occasional failure\n>\n> t/lib-httpd.sh | 24 ++++++++++++++++++++++--\n> t/lib-httpd/apache.conf | 5 +++++\n> t/t5541-http-push-smart.sh | 17 +++--------------\n> t/t5551-http-fetch-smart.sh | 7 +------\n> t/t5561-http-backend.sh | 7 +------\n> 5 files changed, 32 insertions(+), 28 deletions(-)\n"},{"id":"350175","messageId":"20180614175325.GA14935@sigill.intra.peff.net","threadId":"48709","inReplyTo":"20180614123107.11608-5-szeder.dev@gmail.com","subject":"Re: [RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-06-14T17:53:26Z","receivedAt":"2018-06-14T17:53:31Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Jun 14, 2018 at 02:31:07PM +0200, SZEDER Gábor wrote:\n\n> The last test of 't5561-http-backend.sh', 'server request log matches\n> test results' may fail occasionally, because the order of entries in\n> Apache's access log doesn't match the order of requests sent in the\n> previous tests, although all the right requests are there. I saw it\n> fail on Travis CI five times in the span of about half a year, when\n> the order of two subsequent requests was flipped, and could trigger\n> the failure with a modified Git. However, I was unable to trigger it\n> with stock Git on my machine. Three tests in\n> 't5541-http-push-smart.sh' and 't5551-http-fetch-smart.sh' check\n> requests in the log the same way, so they might be prone to a similar\n> occasional failure as well.\n\nI've occasionally run into these failures on my local box, too. I'm\nhappy somebody is looking into it (I have before, but eventually threw\nup my hands in disgust).\n\n> Now, by default the timestamp of a log entry marks the beginning of\n> the request processing, not when the log entry gets written. Since\n> our requests are sent sequentially, sorting the log entries based on\n> their timestamps would ensure that their order corresponds to the\n> order of our requests.\n\nThat's a reasonably clever solution. One thing I wonder, though: are we\nalways guaranteed that the log entries are written _at all_ before we\nlook at them?\n\nI.e., could we have a situation where we make a request, the client\nfinishes, and then we look at the logs, but nothing has been written by\napache yet?\n\n> I don't really like the fix in this patch. I think an unfortunate\n> clock skew during the test run could mess up the sorting added in this\n> patch and cause test failure. Or if DST or even a leap second happen\n> while the test is running. Do we care? Anyway, this occasional test\n> failure apparently happens more often than DST and leap seconds\n> combined.\n\nWe could probably eliminate DST issues by consistently using UTC for the\ntimestamps. Leap seconds are probably infrequent enough not to worry\nabout. More likely is something like clock adjustment due to ntp. Those\nadjustments are usually small enough not to matter, but if we're talking\nmicroseconds, it could trigger.\n\n> An alternative I considered was that we could decide that the order of\n> requests in the access log is not important as long as all the right\n> requests are there. This would inherently eliminate the raciness\n> issue, but if something were to go wrong, then it would become rather\n> hard to find out e.g. which request from which test has gone missing,\n> especially considering that several requests are sent in more than one\n> test. We could address this by truncating the access log at the\n> beginning and checking its contents at the end of each test sending\n> requests. Unfortunately, this would raise additional difficulties,\n> because all requests in t5561 come from tests included from\n> 't556x-common', i.e. from tests shared with\n> 't5560-http-backend-noserver.sh', which as its name suggests doesn't\n> run Apache and doesn't have an access log at all.\n\nWhat if the test script provides the in-order expectation, but we check\nonly the unordered version (by sorting both actual and expected output\non the fly)? That would give us a more relaxed check most of the time,\nbut somebody digging in to a failure could run the ordered diff (or we\ncould even show it automatically on failure instead of just using\ntest_cmp).\n\n> Another alternative is to simply accept that these tests are racy, and\n> that the resulting test failures are rare enough that it isn't worth\n> the complexity of the workaround, but adding a comment to the affected\n> tests warning about the raciness is sufficient. (But I wrote this\n> when I first saw and tracked down this failure; since then I observed\n> it four more times... :)\n\nIt's definitely bugged me. I'd be happy to see some solution. I've been\nclose to suggesting that reading apache logs is simply not robust, and\nwe should focus our tests on the git-visible state changes (e.g., seeing\nsuccessful requests, updated refs, etc).\n\nA side effect of that is that it would become a lot easier to support\nother webservers in our test scripts (though that may still be a fool's\nerrand just due to the amount of custom config we seem to carry).\n\n> Apache doesn't maintain 2.2 anymore; the final maintenance release\n> 2.2.34 was released in July 2017, almost a year ago. OTOH, our\n> 't/lib-httpd/apache.conf' contains a couple of IfVersion directives\n> dealing with versions <2.4, and one even with <2.1. How much do we\n> actually care about these unmaintained Apache versions, and how much\n> of this is just bitrotting?\n\nI strongly suspect bitrotting. It looks like most of the \"< 2.4\"\ndirectives are from 5 years ago (when Debian switched to 2.4 by\ndefault), so even long-term stable systems would generally have it by\nnow (though I'm sure there's probably some RHEL version without it).\n\n-Peff\n"},{"id":"350177","messageId":"20180614175650.GA15544@sigill.intra.peff.net","threadId":"48709","inReplyTo":"20180614123107.11608-1-szeder.dev@gmail.com","subject":"Re: [RFC PATCH 0/4] Fix occasional test failures in http tests","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-06-14T17:56:51Z","receivedAt":"2018-06-14T17:56:55Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Jun 14, 2018 at 02:31:03PM +0200, SZEDER Gábor wrote:\n\n> 't5561-http-backend.sh' is prone to occasional failures; luckily it's\n> not 'git-http-backend's fault, but the test script is a bit racy. I\n> won't go into the details here, patch 4/4's commit message discusses\n> it at length. 4/4 also fixes this issue, but I'm not particularly\n> happy with that fix, the note attached to that patch explains why,\n> along with possible alternatives, hence the RFC.\n> \n> Even if we settle for a different fix, I think the first two patches\n> are worthy cleanups on their own right.\n\nYes, the first two look like improvements on their own (and I left more\ndetailed comments on the final one). Thanks for tackling this!\n\n-Peff\n"},{"id":"350181","messageId":"xmqqefh94420.fsf@gitster-ct.c.googlers.com","threadId":"48709","inReplyTo":"20180614175325.GA14935@sigill.intra.peff.net","subject":"Re: [RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2018-06-14T18:27:03Z","receivedAt":"2018-06-14T18:27:08Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"Jeff King writes:\n\n>> Another alternative is to simply accept that these tests are racy, and\n>> that the resulting test failures are rare enough that it isn't worth\n>> the complexity of the workaround, but adding a comment to the affected\n>> tests warning about the raciness is sufficient. (But I wrote this\n>> when I first saw and tracked down this failure; since then I observed\n>> it four more times... :)\n>\n> It's definitely bugged me. I'd be happy to see some solution. I've been\n> close to suggesting that reading apache logs is simply not robust, and\n> we should focus our tests on the git-visible state changes (e.g., seeing\n> successful requests, updated refs, etc).\n\nHmph, that certainly is \"checking only the things that matter\",\nwhich is desirable.\n\n> A side effect of that is that it would become a lot easier to support\n> other webservers in our test scripts (though that may still be a fool's\n> errand just due to the amount of custom config we seem to carry).\n"},{"id":"350233","messageId":"20180615060020.GA8367@sigill.intra.peff.net","threadId":"48709","inReplyTo":"xmqqefh94420.fsf@gitster-ct.c.googlers.com","subject":"Re: [RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-06-15T06:00:20Z","receivedAt":"2018-06-15T06:00:25Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Jun 14, 2018 at 11:27:03AM -0700, Junio C Hamano wrote:\n\n> Jeff King writes:\n> \n> >> Another alternative is to simply accept that these tests are racy, and\n> >> that the resulting test failures are rare enough that it isn't worth\n> >> the complexity of the workaround, but adding a comment to the affected\n> >> tests warning about the raciness is sufficient. (But I wrote this\n> >> when I first saw and tracked down this failure; since then I observed\n> >> it four more times... :)\n> >\n> > It's definitely bugged me. I'd be happy to see some solution. I've been\n> > close to suggesting that reading apache logs is simply not robust, and\n> > we should focus our tests on the git-visible state changes (e.g., seeing\n> > successful requests, updated refs, etc).\n> \n> Hmph, that certainly is \"checking only the things that matter\",\n> which is desirable.\n\nThe existing tests that look at the apache logs are very white-box, and\ncome from Shawn's original smart-http series. I suspect it was as much\nabout sanity-checking the implementation then as it was about protecting\nagainst regressions.\n\nSo it's possible that these tests have simply outlived their usefulness.\n\nOTOH, they might catch non-functional problems, like if we started\nsending redundant requests. But then, they are not very comprehensive,\nas they only cover a few basic situations (so for example, for a while\nwe were sending extra auth-related requests, but I don't think these\ntests detected that).\n\n-Peff\n"},{"id":"352237","messageId":"CAM0VKjmXoOaYFrkNJzNp_wgzReaXSZHiDCtJRADX0RRG123wPw@mail.gmail.com","threadId":"48709","inReplyTo":"20180614175325.GA14935@sigill.intra.peff.net","subject":"Re: [RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-07-11T12:53:23Z","receivedAt":"2018-07-11T12:53:38Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Thu, Jun 14, 2018 at 7:53 PM Jeff King wrote:\n>\n> On Thu, Jun 14, 2018 at 02:31:07PM +0200, SZEDER Gábor wrote:\n>\n> > The last test of 't5561-http-backend.sh', 'server request log matches\n> > test results' may fail occasionally, because the order of entries in\n> > Apache's access log doesn't match the order of requests sent in the\n> > previous tests, although all the right requests are there.\n\n> I've occasionally run into these failures on my local box, too. I'm\n> happy somebody is looking into it (I have before, but eventually threw\n> up my hands in disgust).\n\nHeh, well, I found it to be one of the more entertaining debugging\nsessions... ;)\nI'm glad that somebody else saw it, too, and outside of Travis CI.\n\n> > Now, by default the timestamp of a log entry marks the beginning of\n> > the request processing, not when the log entry gets written. Since\n> > our requests are sent sequentially, sorting the log entries based on\n> > their timestamps would ensure that their order corresponds to the\n> > order of our requests.\n>\n> That's a reasonably clever solution. One thing I wonder, though: are we\n> always guaranteed that the log entries are written _at all_ before we\n> look at them?\n>\n> I.e., could we have a situation where we make a request, the client\n> finishes, and then we look at the logs, but nothing has been written by\n> apache yet?\n\nThat's possible, I suppose. Highly improbable, but possible. Or the\nlog entries can be written only partially by the time we look at them.\n\nFWIW, Apache has the 'BufferedLogs' directive, which \"causes\nmod_log_config to store several log entries in memory and write them\ntogether to disk, rather than writing them after each request.\" It\nvery sensibly defaults to off, and our test config doesn't set it.\n\nI would think that stopping Apache should flush the logs, but I don't\nknow whether 'stop_httpd' blocks until the web server is indeed\nstopped, or it's all async. Perhaps a SIGHUP would suffice to flush\nthe logs, but that's definitely async. Also note that while t5561\nchecks the access log at the end of the script, t5541 and t5551 do\ncheck the logs in the middle of the script, so we would have to stop\nApache and then start again.\n\nAnyway, I would prefer not to do anything about it just yet, because\nI'm curious :) and I'd like to see whether this actually happens in\npractice.\n\n\n> > I don't really like the fix in this patch. I think an unfortunate\n> > clock skew during the test run could mess up the sorting added in this\n> > patch and cause test failure. Or if DST or even a leap second happen\n> > while the test is running. Do we care? Anyway, this occasional test\n> > failure apparently happens more often than DST and leap seconds\n> > combined.\n>\n> We could probably eliminate DST issues by consistently using UTC for the\n> timestamps. Leap seconds are probably infrequent enough not to worry\n> about. More likely is something like clock adjustment due to ntp. Those\n> adjustments are usually small enough not to matter, but if we're talking\n> microseconds, it could trigger.\n\nOk, so admittedly I haven't quite thought through all these potential\nclock-related issues that I mentioned.\n\nSetting back the clock at the end of DST is not an issue, because\nApache uses the timezone it finds set in the environment, and our test\nenvironment does set UTC, so as far as the tests and Apache's log\ntimestamps are concerned there is no such thing as DST.\nLeap seconds don't go back in time, they are only added to compensate\nfor Earth's slowing rotation, so that's not an issue, either.\nAnd I think NTP is supposed to be clever enough to not set back the\nclock recklessly, but only advance it slower.\n\nOf course, someone can still set back the clock manually while these\ntests run, but I would put that in the \"If it hurts, don't do it\" box.\n\n\nHowever, having said all this, ...\n\n> What if the test script provides the in-order expectation, but we check\n> only the unordered version (by sorting both actual and expected output\n> on the fly)? That would give us a more relaxed check most of the time,\n> but somebody digging in to a failure could run the ordered diff (or we\n> could even show it automatically on failure instead of just using\n> test_cmp).\n\nthis is the fix I'll go for in v2.\n"},{"id":"352238","messageId":"20180711125647.16512-1-szeder.dev@gmail.com","threadId":"48709","inReplyTo":"20180614123107.11608-1-szeder.dev@gmail.com","subject":"[PATCH v2 0/3] Fix occasional test failures in http tests","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-07-11T12:56:44Z","receivedAt":"2018-07-11T12:56:57Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"'t5561-http-backend.sh' is prone to occasional failures; luckily it's\nnot 'git-http-backend's fault, but the test script is a bit racy. I\nwon't go into the details here, patch 3/3's commit message discusses\nit at length.\n\nv1 is here; it haven't been picked up by Junio:\n\n https://public-inbox.org/git/20180614123107.11608-1-szeder.dev@gmail.com/T/#u\n\nThe first two patches are identical to those in v1, and the last patch\nimplements a different and simpler fix than in v1, following Peff's\nsuggestion. The third patch was dropped, because it's not necessary for\nthis simpler fix.\n\n\nSZEDER Gábor (3):\n t5541: avoid empty line when truncating access log\n t/lib-httpd: add the strip_access_log() helper function\n t/lib-httpd: avoid occasional failures when checking access.log\n\n t/lib-httpd.sh | 21 +++++++++++++++++++++\n t/t5541-http-push-smart.sh | 24 +++++-------------------\n t/t5551-http-fetch-smart.sh | 8 +-------\n t/t5561-http-backend.sh | 8 +-------\n 4 files changed, 28 insertions(+), 33 deletions(-)\n\n-- \n2.18.0.273.g57f1ecce9c\n\n"},{"id":"352239","messageId":"20180711125647.16512-2-szeder.dev@gmail.com","threadId":"48709","inReplyTo":"20180711125647.16512-1-szeder.dev@gmail.com","subject":"[PATCH v2 1/3] t5541: avoid empty line when truncating access log","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-07-11T12:56:45Z","receivedAt":"2018-07-11T12:57:02Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"The second test of 't5541-http-push-smart.sh', 'no empty path\ncomponents' truncates Apache's access log by running\n\n echo >.../access.log\n\nwhich doesn't leave an empty file behind, like a proper truncation\nwould, but a file with a lone newline in it. Consequently, a later\ntest checking the log's contents must consider this improper\ntruncation and include an empty line in the expected content.\n\nThere is no need for that newline at all, so drop the 'echo' from the\ntruncation and adjust the expected content accordingly.\n\nSigned-off-by: SZEDER Gábor \n---\n t/t5541-http-push-smart.sh | 3 +--\n 1 file changed, 1 insertion(+), 2 deletions(-)\n\ndiff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh\nindex a2af693068..d623cbad97 100755\n--- a/t/t5541-http-push-smart.sh\n+++ b/t/t5541-http-push-smart.sh\n@@ -54,7 +54,7 @@ test_expect_success 'no empty path components' '\n \t# service\" test which reads the log too.\n \t#\n \t# We do this before the actual comparison to ensure the log is cleared.\n-\techo > \"$HTTPD_ROOT_PATH\"/access.log &&\n+\t>\"$HTTPD_ROOT_PATH\"/access.log &&\n \n \ttest_cmp exp act\n '\n@@ -124,7 +124,6 @@ test_expect_success 'rejected update prints status' '\n rm -f \"$HTTPD_DOCUMENT_ROOT_PATH/test_repo.git/hooks/update\"\n \n cat >exp <\n---\n t/lib-httpd.sh | 9 +++++++++\n t/t5541-http-push-smart.sh | 14 ++------------\n t/t5551-http-fetch-smart.sh | 7 +------\n t/t5561-http-backend.sh | 7 +------\n 4 files changed, 13 insertions(+), 24 deletions(-)\n\ndiff --git a/t/lib-httpd.sh b/t/lib-httpd.sh\nindex 435a37465a..b6788fea57 100644\n--- a/t/lib-httpd.sh\n+++ b/t/lib-httpd.sh\n@@ -287,3 +287,12 @@ expect_askpass() {\n \ttest_cmp \"$TRASH_DIRECTORY/askpass-expect\" \\\n \t\t \"$TRASH_DIRECTORY/askpass-query\"\n }\n+\n+strip_access_log() {\n+\tsed -e \"\n+\t\ts/^.* \\\"//\n+\t\ts/\\\"//\n+\t\ts/ [1-9][0-9]*\\$//\n+\t\ts/^GET /GET /\n+\t\" \"$HTTPD_ROOT_PATH\"/access.log\n+}\ndiff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh\nindex d623cbad97..6cd986797d 100755\n--- a/t/t5541-http-push-smart.sh\n+++ b/t/t5541-http-push-smart.sh\n@@ -43,12 +43,7 @@ test_expect_success 'no empty path components' '\n \tcd \"$ROOT_PATH\" &&\n \tgit clone $HTTPD_URL/smart/test_repo.git/ test_repo_clone &&\n \n-\tsed -e \"\n-\t\ts/^.* \\\"//\n-\t\ts/\\\"//\n-\t\ts/ [1-9][0-9]*\\$//\n-\t\ts/^GET /GET /\n-\t\" >act <\"$HTTPD_ROOT_PATH\"/access.log &&\n+\tstrip_access_log >act &&\n \n \t# Clear the log, so that it does not affect the \"used receive-pack\n \t# service\" test which reads the log too.\n@@ -137,12 +132,7 @@ GET /smart/test_repo.git/info/refs?service=git-receive-pack HTTP/1.1 200\n POST /smart/test_repo.git/git-receive-pack HTTP/1.1 200\n EOF\n test_expect_success 'used receive-pack service' '\n-\tsed -e \"\n-\t\ts/^.* \\\"//\n-\t\ts/\\\"//\n-\t\ts/ [1-9][0-9]*\\$//\n-\t\ts/^GET /GET /\n-\t\" >act <\"$HTTPD_ROOT_PATH\"/access.log &&\n+\tstrip_access_log >act &&\n \ttest_cmp exp act\n '\n \ndiff --git a/t/t5551-http-fetch-smart.sh b/t/t5551-http-fetch-smart.sh\nindex 913089b144..c8b6ec493b 100755\n--- a/t/t5551-http-fetch-smart.sh\n+++ b/t/t5551-http-fetch-smart.sh\n@@ -103,12 +103,7 @@ GET /smart/repo.git/info/refs?service=git-upload-pack HTTP/1.1 200\n POST /smart/repo.git/git-upload-pack HTTP/1.1 200\n EOF\n test_expect_success 'used upload-pack service' '\n-\tsed -e \"\n-\t\ts/^.* \\\"//\n-\t\ts/\\\"//\n-\t\ts/ [1-9][0-9]*\\$//\n-\t\ts/^GET /GET /\n-\t\" >act <\"$HTTPD_ROOT_PATH\"/access.log &&\n+\tstrip_access_log >act &&\n \ttest_cmp exp act\n '\n \ndiff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh\nindex 84a955770a..4248b5a06d 100755\n--- a/t/t5561-http-backend.sh\n+++ b/t/t5561-http-backend.sh\n@@ -129,12 +129,7 @@ GET /smart/repo.git/info/refs?service=git-receive-pack HTTP/1.1 403 -\n POST /smart/repo.git/git-receive-pack HTTP/1.1 403 -\n EOF\n test_expect_success 'server request log matches test results' '\n-\tsed -e \"\n-\t\ts/^.* \\\"//\n-\t\ts/\\\"//\n-\t\ts/ [1-9][0-9]*\\$//\n-\t\ts/^GET /GET /\n-\t\" >act <\"$HTTPD_ROOT_PATH\"/access.log &&\n+\tstrip_access_log >act &&\n \ttest_cmp exp act\n '\n \n-- \n2.18.0.273.g57f1ecce9c\n\n"},{"id":"352241","messageId":"20180711125647.16512-4-szeder.dev@gmail.com","threadId":"48709","inReplyTo":"20180711125647.16512-1-szeder.dev@gmail.com","subject":"[PATCH v2 3/3] t/lib-httpd: avoid occasional failures when checking access.log","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-07-11T12:56:47Z","receivedAt":"2018-07-11T12:57:12Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"The last test of 't5561-http-backend.sh', 'server request log matches\ntest results' may fail occasionally, because the order of entries in\nApache's access log doesn't match the order of requests sent in the\nprevious tests, although all the right requests are there. I saw it\nfail on Travis CI five times in the span of about half a year, when\nthe order of two subsequent requests was flipped, and could trigger\nthe failure with a modified Git. However, I was unable to trigger it\nwith stock Git on my machine. Three tests in\n't5541-http-push-smart.sh' and 't5551-http-fetch-smart.sh' check\nrequests in the log the same way, so they might be prone to a similar\noccasional failure as well.\n\nWhen a test sends a HTTP request, it can continue execution after\n'git-http-backend' fulfilled that request, but Apache writes the\ncorresponding access log entry only after 'git-http-backend' exited.\nSome time inevitably passes between fulfilling the request and writing\nthe log entry, and, under unfavourable circumstances, enough time\nmight pass for the subsequent request to be sent and fulfilled by a\ndifferent Apache thread or process, and then Apache writes access log\nentries racily.\n\nThis effect can be exacerbated by adding a bit of variable delay after\nthe request is fulfilled but before 'git-http-backend' exits, e.g.\nlike this:\n\n diff --git a/http-backend.c b/http-backend.c\n index f3dc218b2..bbf4c125b 100644\n --- a/http-backend.c\n +++ b/http-backend.c\n @@ -709,5 +709,7 @@ int cmd_main(int argc, const char **argv)\n \t\t\t\t\t max_request_buffer);\n\n \tcmd->imp(&hdr, cmd_arg);\n +\tif (getpid() % 2)\n +\t\tsleep(1);\n \treturn 0;\n }\n\nThis delay considerably increases the chances of log entries being\nwritten out of order, and in turn makes t5561's last test fail almost\nevery time. Alas, it doesn't seem to be enough to trigger a similar\nfailure in t5541 and t5551.\n\nSo, since we can't just rely on the order of access log entries always\ncorresponding the order of requests, make checking the access log more\ndeterministic by sorting (simply lexicographically) both the stripped\naccess log entries and the expected entries before the comparison with\n'test_cmp'. This way the order of log entries won't matter and\noccasional out-of-order entries won't trigger a test failure, but the\ncomparison will still notice any unexpected or missing log entries.\n\nOTOH, this sorting will make it harder to identify from which test an\nunexpected log entry came from or which test's request went missing.\nTherefore, in case of an error include the comparison of the unsorted\nlog enries in the test output as well.\n\nAnd since all this should be performed in four tests in three test\nscripts, put this into a new helper function 'check_access_log' in\n't/lib-httpd.sh'.\n\nSigned-off-by: SZEDER Gábor \n---\n t/lib-httpd.sh | 12 ++++++++++++\n t/t5541-http-push-smart.sh | 13 +++++--------\n t/t5551-http-fetch-smart.sh | 3 +--\n t/t5561-http-backend.sh | 3 +--\n 4 files changed, 19 insertions(+), 12 deletions(-)\n\ndiff --git a/t/lib-httpd.sh b/t/lib-httpd.sh\nindex b6788fea57..7f060aebd0 100644\n--- a/t/lib-httpd.sh\n+++ b/t/lib-httpd.sh\n@@ -296,3 +296,15 @@ strip_access_log() {\n \t\ts/^GET /GET /\n \t\" \"$HTTPD_ROOT_PATH\"/access.log\n }\n+\n+# Requires one argument: the name of a file containing the expected stripped\n+# access log entries.\n+check_access_log() {\n+\tsort \"$1\" >\"$1\".sorted &&\n+\tstrip_access_log >access.log.stripped &&\n+\tsort access.log.stripped >access.log.sorted &&\n+\tif ! test_cmp \"$1\".sorted access.log.sorted\n+\tthen\n+\t\ttest_cmp \"$1\" access.log.stripped\n+\tfi\n+}\ndiff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh\nindex 6cd986797d..a481e3989a 100755\n--- a/t/t5541-http-push-smart.sh\n+++ b/t/t5541-http-push-smart.sh\n@@ -43,15 +43,13 @@ test_expect_success 'no empty path components' '\n \tcd \"$ROOT_PATH\" &&\n \tgit clone $HTTPD_URL/smart/test_repo.git/ test_repo_clone &&\n \n-\tstrip_access_log >act &&\n+\tcheck_access_log exp\n+'\n \n+test_expect_success 'clear access log' '\n \t# Clear the log, so that it does not affect the \"used receive-pack\n \t# service\" test which reads the log too.\n-\t#\n-\t# We do this before the actual comparison to ensure the log is cleared.\n-\t>\"$HTTPD_ROOT_PATH\"/access.log &&\n-\n-\ttest_cmp exp act\n+\t>\"$HTTPD_ROOT_PATH\"/access.log\n '\n \n test_expect_success 'clone remote repository' '\n@@ -132,8 +130,7 @@ GET /smart/test_repo.git/info/refs?service=git-receive-pack HTTP/1.1 200\n POST /smart/test_repo.git/git-receive-pack HTTP/1.1 200\n EOF\n test_expect_success 'used receive-pack service' '\n-\tstrip_access_log >act &&\n-\ttest_cmp exp act\n+\tcheck_access_log exp\n '\n \n test_http_push_nonff \"$HTTPD_DOCUMENT_ROOT_PATH\"/test_repo.git \\\ndiff --git a/t/t5551-http-fetch-smart.sh b/t/t5551-http-fetch-smart.sh\nindex c8b6ec493b..3aab44bdcb 100755\n--- a/t/t5551-http-fetch-smart.sh\n+++ b/t/t5551-http-fetch-smart.sh\n@@ -103,8 +103,7 @@ GET /smart/repo.git/info/refs?service=git-upload-pack HTTP/1.1 200\n POST /smart/repo.git/git-upload-pack HTTP/1.1 200\n EOF\n test_expect_success 'used upload-pack service' '\n-\tstrip_access_log >act &&\n-\ttest_cmp exp act\n+\tcheck_access_log exp\n '\n \n test_expect_success 'follow redirects (301)' '\ndiff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh\nindex 4248b5a06d..1c49054595 100755\n--- a/t/t5561-http-backend.sh\n+++ b/t/t5561-http-backend.sh\n@@ -129,8 +129,7 @@ GET /smart/repo.git/info/refs?service=git-receive-pack HTTP/1.1 403 -\n POST /smart/repo.git/git-receive-pack HTTP/1.1 403 -\n EOF\n test_expect_success 'server request log matches test results' '\n-\tstrip_access_log >act &&\n-\ttest_cmp exp act\n+\tcheck_access_log exp\n '\n \n stop_httpd\n-- \n2.18.0.273.g57f1ecce9c\n\n"},{"id":"352251","messageId":"20180711144555.GA15269@sigill.intra.peff.net","threadId":"48709","inReplyTo":"CAM0VKjmXoOaYFrkNJzNp_wgzReaXSZHiDCtJRADX0RRG123wPw@mail.gmail.com","subject":"Re: [RFC PATCH 4/4] t/lib-httpd: sort log based on timestamp to avoid occasional failure","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-07-11T14:45:55Z","receivedAt":"2018-07-11T14:45:59Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Jul 11, 2018 at 02:53:23PM +0200, SZEDER Gábor wrote:\n\n> > I.e., could we have a situation where we make a request, the client\n> > finishes, and then we look at the logs, but nothing has been written by\n> > apache yet?\n> \n> That's possible, I suppose. Highly improbable, but possible. Or the\n> log entries can be written only partially by the time we look at them.\n\nDigging into earlier cases I had seen on my local box, my impression was\nthat this was the problem I was seeing (not reordering). But it's\nentirely possible that I was confused by reordering. I've been trying to\nreproduce, but after 5 minutes of t5561 running in a tight loop under\nhigh load, I haven't gotten a single failure.\n\n> Anyway, I would prefer not to do anything about it just yet, because\n> I'm curious :) and I'd like to see whether this actually happens in\n> practice.\n\nI can't reproduce for now, so I'm happy either way. :)\n\n> > What if the test script provides the in-order expectation, but we check\n> > only the unordered version (by sorting both actual and expected output\n> > on the fly)? That would give us a more relaxed check most of the time,\n> > but somebody digging in to a failure could run the ordered diff (or we\n> > could even show it automatically on failure instead of just using\n> > test_cmp).\n> \n> this is the fix I'll go for in v2.\n\nGreat. That seems much simpler to reason about. I'll take a look.\n\n-Peff\n"},{"id":"352252","messageId":"20180711145730.GB15269@sigill.intra.peff.net","threadId":"48709","inReplyTo":"20180711125647.16512-4-szeder.dev@gmail.com","subject":"Re: [PATCH v2 3/3] t/lib-httpd: avoid occasional failures when checking access.log","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-07-11T14:57:31Z","receivedAt":"2018-07-11T14:57:34Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Jul 11, 2018 at 02:56:47PM +0200, SZEDER Gábor wrote:\n\n> +# Requires one argument: the name of a file containing the expected stripped\n> +# access log entries.\n> +check_access_log() {\n> +\tsort \"$1\" >\"$1\".sorted &&\n> +\tstrip_access_log >access.log.stripped &&\n> +\tsort access.log.stripped >access.log.sorted &&\n> +\tif ! test_cmp \"$1\".sorted access.log.sorted\n> +\tthen\n> +\t\ttest_cmp \"$1\" access.log.stripped\n> +\tfi\n> +}\n\nThis will generate output showing both the unsorted and sorted\ndifferences. Do we want to suppress the sorted ones (e.g., by just using\n\"cmp\" directly)? I guess it doesn't matter unless there is an actual\ntest failure, but I just wonder if it would be confusing to see both.\n\n> diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh\n> index 6cd986797d..a481e3989a 100755\n> --- a/t/t5541-http-push-smart.sh\n> +++ b/t/t5541-http-push-smart.sh\n> @@ -43,15 +43,13 @@ test_expect_success 'no empty path components' '\n> \tcd \"$ROOT_PATH\" &&\n> \tgit clone $HTTPD_URL/smart/test_repo.git/ test_repo_clone &&\n> \n> -\tstrip_access_log >act &&\n> +\tcheck_access_log exp\n> +'\n> \n> +test_expect_success 'clear access log' '\n> \t# Clear the log, so that it does not affect the \"used receive-pack\n> \t# service\" test which reads the log too.\n> -\t#\n> -\t# We do this before the actual comparison to ensure the log is cleared.\n> -\t>\"$HTTPD_ROOT_PATH\"/access.log &&\n> -\n> -\ttest_cmp exp act\n> +\t>\"$HTTPD_ROOT_PATH\"/access.log\n> '\n\nThis took some head-scratching, mostly because of the original comment.\nI thought the \"before\" here was referring to a timing issue (maybe\nbecause we're talking about timing ;) ).\n\nBut it is really \"make sure that a failed test here does not prevent us\nfrom doing this cleanup\". So the original really should have just\ndropped that comment and added a test_when_finished. Bumping it into a\nseparate test as you have here accomplishes the same thing.\n\n-Peff\n"},{"id":"352253","messageId":"20180711145845.GC15269@sigill.intra.peff.net","threadId":"48709","inReplyTo":"20180711125647.16512-1-szeder.dev@gmail.com","subject":"Re: [PATCH v2 0/3] Fix occasional test failures in http tests","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-07-11T14:58:45Z","receivedAt":"2018-07-11T14:58:48Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Jul 11, 2018 at 02:56:44PM +0200, SZEDER Gábor wrote:\n\n> 't5561-http-backend.sh' is prone to occasional failures; luckily it's\n> not 'git-http-backend's fault, but the test script is a bit racy. I\n> won't go into the details here, patch 3/3's commit message discusses\n> it at length.\n> \n> v1 is here; it haven't been picked up by Junio:\n> \n> https://public-inbox.org/git/20180614123107.11608-1-szeder.dev@gmail.com/T/#u\n> \n> The first two patches are identical to those in v1, and the last patch\n> implements a different and simpler fix than in v1, following Peff's\n> suggestion. The third patch was dropped, because it's not necessary for\n> this simpler fix.\n\nThe first two look obviously correct as before. I picked a few minor\nnits in the third one. But if your response is \"no, I prefer it the way\nI wrote it\", then I am perfectly happy seeing it applied as-is.\n\nThanks for finishing this up.\n\n-Peff\n"},{"id":"352276","messageId":"CAM0VKjm8V58w=2+Zx+ykrfmOmNDOtPY5HeuFy+mWm_H40UrF1A@mail.gmail.com","threadId":"48709","inReplyTo":"20180711145730.GB15269@sigill.intra.peff.net","subject":"Re: [PATCH v2 3/3] t/lib-httpd: avoid occasional failures when checking access.log","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-07-11T17:26:19Z","receivedAt":"2018-07-11T17:26:35Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Wed, Jul 11, 2018 at 4:57 PM Jeff King wrote:\n>\n> On Wed, Jul 11, 2018 at 02:56:47PM +0200, SZEDER Gábor wrote:\n>\n> > +# Requires one argument: the name of a file containing the expected stripped\n> > +# access log entries.\n> > +check_access_log() {\n> > + sort \"$1\" >\"$1\".sorted &&\n> > + strip_access_log >access.log.stripped &&\n> > + sort access.log.stripped >access.log.sorted &&\n> > + if ! test_cmp \"$1\".sorted access.log.sorted\n> > + then\n> > + test_cmp \"$1\" access.log.stripped\n> > + fi\n> > +}\n>\n> This will generate output showing both the unsorted and sorted\n> differences. Do we want to suppress the sorted ones (e.g., by just using\n> \"cmp\" directly)? I guess it doesn't matter unless there is an actual\n> test failure, but I just wonder if it would be confusing to see both.\n\nI have no opinion about this, at all. I tried it both ways back then,\nand didn't find one any better than the other, so I just chose the\nsimpler-shorter one, i.e. no 2>/dev/null redirection in the condition.\n\n> > diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh\n> > index 6cd986797d..a481e3989a 100755\n> > --- a/t/t5541-http-push-smart.sh\n> > +++ b/t/t5541-http-push-smart.sh\n> > @@ -43,15 +43,13 @@ test_expect_success 'no empty path components' '\n> > cd \"$ROOT_PATH\" &&\n> > git clone $HTTPD_URL/smart/test_repo.git/ test_repo_clone &&\n> >\n> > - strip_access_log >act &&\n> > + check_access_log exp\n> > +'\n> >\n> > +test_expect_success 'clear access log' '\n> > # Clear the log, so that it does not affect the \"used receive-pack\n> > # service\" test which reads the log too.\n> > - #\n> > - # We do this before the actual comparison to ensure the log is cleared.\n> > - >\"$HTTPD_ROOT_PATH\"/access.log &&\n> > -\n> > - test_cmp exp act\n> > + >\"$HTTPD_ROOT_PATH\"/access.log\n> > '\n>\n> This took some head-scratching, mostly because of the original comment.\n> I thought the \"before\" here was referring to a timing issue (maybe\n> because we're talking about timing ;) ).\n\nHeh, I had to do some head-scratching now as well... That's what I\nget for updating the patch, and then waiting almost a month to finish\nit up and update the commit message.\n\n> But it is really \"make sure that a failed test here does not prevent us\n> from doing this cleanup\". So the original really should have just\n> dropped that comment and added a test_when_finished. Bumping it into a\n> separate test as you have here accomplishes the same thing.\n\nAfter taking a step back, I think this would fit better into the first\npatch, wouldn't it?\nI will send v3 shortly.\n"},{"id":"352278","messageId":"20180711173513.GA24949@sigill.intra.peff.net","threadId":"48709","inReplyTo":"CAM0VKjm8V58w=2+Zx+ykrfmOmNDOtPY5HeuFy+mWm_H40UrF1A@mail.gmail.com","subject":"Re: [PATCH v2 3/3] t/lib-httpd: avoid occasional failures when checking access.log","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-07-11T17:35:13Z","receivedAt":"2018-07-11T17:35:16Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Wed, Jul 11, 2018 at 07:26:19PM +0200, SZEDER Gábor wrote:\n\n> > But it is really \"make sure that a failed test here does not prevent us\n> > from doing this cleanup\". So the original really should have just\n> > dropped that comment and added a test_when_finished. Bumping it into a\n> > separate test as you have here accomplishes the same thing.\n> \n> After taking a step back, I think this would fit better into the first\n> patch, wouldn't it?\n> I will send v3 shortly.\n\nYeah, I agree it would be even nicer to clean it up there.\n\n-Peff\n"},{"id":"352325","messageId":"20180712122216.12691-1-szeder.dev@gmail.com","threadId":"48709","inReplyTo":"20180711125647.16512-1-szeder.dev@gmail.com","subject":"[PATCH v3 0/3] Fix occasional test failures in http tests","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-07-12T12:22:13Z","receivedAt":"2018-07-12T12:22:26Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"To recap: 't5561-http-backend.sh' is prone to occasional failures;\nluckily it's not 'git-http-backend's fault, but the test script is a\nbit racy; patch 3/3's commit message discusses the details at length.\n\nChanges since v2:\n\n - Use 'test_when_finished' to clear the access log in the first\n patch. (and necessary adjustments to the subsequent patches\n because of conflicts)\n \nInterdiff included below. (I wanted to include range-diff, but it\ndidn't make any sense)\n\n\nSZEDER Gábor (3):\n t5541: clean up truncating access log\n t/lib-httpd: add the strip_access_log() helper function\n t/lib-httpd: avoid occasional failures when checking access.log\n\n t/lib-httpd.sh | 21 +++++++++++++++++++++\n t/t5541-http-push-smart.sh | 28 ++++++----------------------\n t/t5551-http-fetch-smart.sh | 8 +-------\n t/t5561-http-backend.sh | 8 +-------\n 4 files changed, 29 insertions(+), 36 deletions(-)\n\n-- \n2.18.0.305.g66e9e0a543\n\ndiff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh\nindex a481e3989a..a9836e4af0 100755\n--- a/t/t5541-http-push-smart.sh\n+++ b/t/t5541-http-push-smart.sh\n@@ -38,6 +38,10 @@ GET /smart/test_repo.git/info/refs?service=git-upload-pack HTTP/1.1 200\n POST /smart/test_repo.git/git-upload-pack HTTP/1.1 200\n EOF\n test_expect_success 'no empty path components' '\n+\t# Clear the log, so that it does not affect the \"used receive-pack\n+\t# service\" test which reads the log too.\n+\ttest_when_finished \">\\\"$HTTPD_ROOT_PATH\\\"/access.log\" &&\n+\n \t# In the URL, add a trailing slash, and see if git appends yet another\n \t# slash.\n \tcd \"$ROOT_PATH\" &&\n@@ -46,12 +50,6 @@ test_expect_success 'no empty path components' '\n \tcheck_access_log exp\n '\n \n-test_expect_success 'clear access log' '\n-\t# Clear the log, so that it does not affect the \"used receive-pack\n-\t# service\" test which reads the log too.\n-\t>\"$HTTPD_ROOT_PATH\"/access.log\n-'\n-\n test_expect_success 'clone remote repository' '\n \trm -rf test_repo_clone &&\n \tgit clone $HTTPD_URL/smart/test_repo.git test_repo_clone &&\n"},{"id":"352326","messageId":"20180712122216.12691-2-szeder.dev@gmail.com","threadId":"48709","inReplyTo":"20180712122216.12691-1-szeder.dev@gmail.com","subject":"[PATCH v3 1/3] t5541: clean up truncating access log","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-07-12T12:22:14Z","receivedAt":"2018-07-12T12:22:28Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"In the second test of 't5541-http-push-smart.sh', 'no empty path\ncomponents' we truncate Apache's access log by running:\n\n echo >.../access.log\n\nThere are two issues with this approach:\n\n - This doesn't leave an empty file behind, like a proper truncation\n would, but a file with a lone newline in it. Consequently, a\n later test checking the log's contents must consider this improper\n truncation and include an empty line in the expected content.\n\n - This truncation is done in the middle of the test, because,\n quoting the in-code comment, \"we do this [truncation] before the\n actual comparison to ensure the log is cleared\" even when\n subsequent 'test_cmp' fails. Alas, this is not quite robust\n enough, as it is conceivable that 'git clone' fails after already\n having sent a request, in which case the access log would not be\n truncated and would leave stray log entries behind.\n\nSince there is no need for that newline at all, drop the 'echo' from\nthe truncation and adjust the expected content accordingly.\nFurthermore, make sure that the truncation is performed no matter\nwhether and how 'git clone' fails unexpectedly by specifying it as a\n'test_when_finished' command.\n\nSigned-off-by: SZEDER Gábor \n---\n t/t5541-http-push-smart.sh | 12 ++++--------\n 1 file changed, 4 insertions(+), 8 deletions(-)\n\ndiff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh\nindex a2af693068..5c9ca19401 100755\n--- a/t/t5541-http-push-smart.sh\n+++ b/t/t5541-http-push-smart.sh\n@@ -38,6 +38,10 @@ GET /smart/test_repo.git/info/refs?service=git-upload-pack HTTP/1.1 200\n POST /smart/test_repo.git/git-upload-pack HTTP/1.1 200\n EOF\n test_expect_success 'no empty path components' '\n+\t# Clear the log, so that it does not affect the \"used receive-pack\n+\t# service\" test which reads the log too.\n+\ttest_when_finished \">\\\"$HTTPD_ROOT_PATH\\\"/access.log\" &&\n+\n \t# In the URL, add a trailing slash, and see if git appends yet another\n \t# slash.\n \tcd \"$ROOT_PATH\" &&\n@@ -49,13 +53,6 @@ test_expect_success 'no empty path components' '\n \t\ts/ [1-9][0-9]*\\$//\n \t\ts/^GET /GET /\n \t\" >act <\"$HTTPD_ROOT_PATH\"/access.log &&\n-\n-\t# Clear the log, so that it does not affect the \"used receive-pack\n-\t# service\" test which reads the log too.\n-\t#\n-\t# We do this before the actual comparison to ensure the log is cleared.\n-\techo > \"$HTTPD_ROOT_PATH\"/access.log &&\n-\n \ttest_cmp exp act\n '\n \n@@ -124,7 +121,6 @@ test_expect_success 'rejected update prints status' '\n rm -f \"$HTTPD_DOCUMENT_ROOT_PATH/test_repo.git/hooks/update\"\n \n cat >exp <\n---\n t/lib-httpd.sh | 9 +++++++++\n t/t5541-http-push-smart.sh | 14 ++------------\n t/t5551-http-fetch-smart.sh | 7 +------\n t/t5561-http-backend.sh | 7 +------\n 4 files changed, 13 insertions(+), 24 deletions(-)\n\ndiff --git a/t/lib-httpd.sh b/t/lib-httpd.sh\nindex 435a37465a..b6788fea57 100644\n--- a/t/lib-httpd.sh\n+++ b/t/lib-httpd.sh\n@@ -287,3 +287,12 @@ expect_askpass() {\n \ttest_cmp \"$TRASH_DIRECTORY/askpass-expect\" \\\n \t\t \"$TRASH_DIRECTORY/askpass-query\"\n }\n+\n+strip_access_log() {\n+\tsed -e \"\n+\t\ts/^.* \\\"//\n+\t\ts/\\\"//\n+\t\ts/ [1-9][0-9]*\\$//\n+\t\ts/^GET /GET /\n+\t\" \"$HTTPD_ROOT_PATH\"/access.log\n+}\ndiff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh\nindex 5c9ca19401..83390f80cc 100755\n--- a/t/t5541-http-push-smart.sh\n+++ b/t/t5541-http-push-smart.sh\n@@ -47,12 +47,7 @@ test_expect_success 'no empty path components' '\n \tcd \"$ROOT_PATH\" &&\n \tgit clone $HTTPD_URL/smart/test_repo.git/ test_repo_clone &&\n \n-\tsed -e \"\n-\t\ts/^.* \\\"//\n-\t\ts/\\\"//\n-\t\ts/ [1-9][0-9]*\\$//\n-\t\ts/^GET /GET /\n-\t\" >act <\"$HTTPD_ROOT_PATH\"/access.log &&\n+\tstrip_access_log >act &&\n \ttest_cmp exp act\n '\n \n@@ -134,12 +129,7 @@ GET /smart/test_repo.git/info/refs?service=git-receive-pack HTTP/1.1 200\n POST /smart/test_repo.git/git-receive-pack HTTP/1.1 200\n EOF\n test_expect_success 'used receive-pack service' '\n-\tsed -e \"\n-\t\ts/^.* \\\"//\n-\t\ts/\\\"//\n-\t\ts/ [1-9][0-9]*\\$//\n-\t\ts/^GET /GET /\n-\t\" >act <\"$HTTPD_ROOT_PATH\"/access.log &&\n+\tstrip_access_log >act &&\n \ttest_cmp exp act\n '\n \ndiff --git a/t/t5551-http-fetch-smart.sh b/t/t5551-http-fetch-smart.sh\nindex 913089b144..c8b6ec493b 100755\n--- a/t/t5551-http-fetch-smart.sh\n+++ b/t/t5551-http-fetch-smart.sh\n@@ -103,12 +103,7 @@ GET /smart/repo.git/info/refs?service=git-upload-pack HTTP/1.1 200\n POST /smart/repo.git/git-upload-pack HTTP/1.1 200\n EOF\n test_expect_success 'used upload-pack service' '\n-\tsed -e \"\n-\t\ts/^.* \\\"//\n-\t\ts/\\\"//\n-\t\ts/ [1-9][0-9]*\\$//\n-\t\ts/^GET /GET /\n-\t\" >act <\"$HTTPD_ROOT_PATH\"/access.log &&\n+\tstrip_access_log >act &&\n \ttest_cmp exp act\n '\n \ndiff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh\nindex 84a955770a..4248b5a06d 100755\n--- a/t/t5561-http-backend.sh\n+++ b/t/t5561-http-backend.sh\n@@ -129,12 +129,7 @@ GET /smart/repo.git/info/refs?service=git-receive-pack HTTP/1.1 403 -\n POST /smart/repo.git/git-receive-pack HTTP/1.1 403 -\n EOF\n test_expect_success 'server request log matches test results' '\n-\tsed -e \"\n-\t\ts/^.* \\\"//\n-\t\ts/\\\"//\n-\t\ts/ [1-9][0-9]*\\$//\n-\t\ts/^GET /GET /\n-\t\" >act <\"$HTTPD_ROOT_PATH\"/access.log &&\n+\tstrip_access_log >act &&\n \ttest_cmp exp act\n '\n \n-- \n2.18.0.305.g66e9e0a543\n\n"},{"id":"352328","messageId":"20180712122216.12691-4-szeder.dev@gmail.com","threadId":"48709","inReplyTo":"20180712122216.12691-1-szeder.dev@gmail.com","subject":"[PATCH v3 3/3] t/lib-httpd: avoid occasional failures when checking access.log","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-07-12T12:22:16Z","receivedAt":"2018-07-12T12:22:31Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"The last test of 't5561-http-backend.sh', 'server request log matches\ntest results' may fail occasionally, because the order of entries in\nApache's access log doesn't match the order of requests sent in the\nprevious tests, although all the right requests are there. I saw it\nfail on Travis CI five times in the span of about half a year, when\nthe order of two subsequent requests was flipped, and could trigger\nthe failure with a modified Git. However, I was unable to trigger it\nwith stock Git on my machine. Three tests in\n't5541-http-push-smart.sh' and 't5551-http-fetch-smart.sh' check\nrequests in the log the same way, so they might be prone to a similar\noccasional failure as well.\n\nWhen a test sends a HTTP request, it can continue execution after\n'git-http-backend' fulfilled that request, but Apache writes the\ncorresponding access log entry only after 'git-http-backend' exited.\nSome time inevitably passes between fulfilling the request and writing\nthe log entry, and, under unfavourable circumstances, enough time\nmight pass for the subsequent request to be sent and fulfilled by a\ndifferent Apache thread or process, and then Apache writes access log\nentries racily.\n\nThis effect can be exacerbated by adding a bit of variable delay after\nthe request is fulfilled but before 'git-http-backend' exits, e.g.\nlike this:\n\n diff --git a/http-backend.c b/http-backend.c\n index f3dc218b2..bbf4c125b 100644\n --- a/http-backend.c\n +++ b/http-backend.c\n @@ -709,5 +709,7 @@ int cmd_main(int argc, const char **argv)\n \t\t\t\t\t max_request_buffer);\n\n \tcmd->imp(&hdr, cmd_arg);\n +\tif (getpid() % 2)\n +\t\tsleep(1);\n \treturn 0;\n }\n\nThis delay considerably increases the chances of log entries being\nwritten out of order, and in turn makes t5561's last test fail almost\nevery time. Alas, it doesn't seem to be enough to trigger a similar\nfailure in t5541 and t5551.\n\nSo, since we can't just rely on the order of access log entries always\ncorresponding the order of requests, make checking the access log more\ndeterministic by sorting (simply lexicographically) both the stripped\naccess log entries and the expected entries before the comparison with\n'test_cmp'. This way the order of log entries won't matter and\noccasional out-of-order entries won't trigger a test failure, but the\ncomparison will still notice any unexpected or missing log entries.\n\nOTOH, this sorting will make it harder to identify from which test an\nunexpected log entry came from or which test's request went missing.\nTherefore, in case of an error include the comparison of the unsorted\nlog enries in the test output as well.\n\nAnd since all this should be performed in four tests in three test\nscripts, put this into a new helper function 'check_access_log' in\n't/lib-httpd.sh'.\n\nSigned-off-by: SZEDER Gábor \n---\n t/lib-httpd.sh | 12 ++++++++++++\n t/t5541-http-push-smart.sh | 6 ++----\n t/t5551-http-fetch-smart.sh | 3 +--\n t/t5561-http-backend.sh | 3 +--\n 4 files changed, 16 insertions(+), 8 deletions(-)\n\ndiff --git a/t/lib-httpd.sh b/t/lib-httpd.sh\nindex b6788fea57..7f060aebd0 100644\n--- a/t/lib-httpd.sh\n+++ b/t/lib-httpd.sh\n@@ -296,3 +296,15 @@ strip_access_log() {\n \t\ts/^GET /GET /\n \t\" \"$HTTPD_ROOT_PATH\"/access.log\n }\n+\n+# Requires one argument: the name of a file containing the expected stripped\n+# access log entries.\n+check_access_log() {\n+\tsort \"$1\" >\"$1\".sorted &&\n+\tstrip_access_log >access.log.stripped &&\n+\tsort access.log.stripped >access.log.sorted &&\n+\tif ! test_cmp \"$1\".sorted access.log.sorted\n+\tthen\n+\t\ttest_cmp \"$1\" access.log.stripped\n+\tfi\n+}\ndiff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh\nindex 83390f80cc..a9836e4af0 100755\n--- a/t/t5541-http-push-smart.sh\n+++ b/t/t5541-http-push-smart.sh\n@@ -47,8 +47,7 @@ test_expect_success 'no empty path components' '\n \tcd \"$ROOT_PATH\" &&\n \tgit clone $HTTPD_URL/smart/test_repo.git/ test_repo_clone &&\n \n-\tstrip_access_log >act &&\n-\ttest_cmp exp act\n+\tcheck_access_log exp\n '\n \n test_expect_success 'clone remote repository' '\n@@ -129,8 +128,7 @@ GET /smart/test_repo.git/info/refs?service=git-receive-pack HTTP/1.1 200\n POST /smart/test_repo.git/git-receive-pack HTTP/1.1 200\n EOF\n test_expect_success 'used receive-pack service' '\n-\tstrip_access_log >act &&\n-\ttest_cmp exp act\n+\tcheck_access_log exp\n '\n \n test_http_push_nonff \"$HTTPD_DOCUMENT_ROOT_PATH\"/test_repo.git \\\ndiff --git a/t/t5551-http-fetch-smart.sh b/t/t5551-http-fetch-smart.sh\nindex c8b6ec493b..3aab44bdcb 100755\n--- a/t/t5551-http-fetch-smart.sh\n+++ b/t/t5551-http-fetch-smart.sh\n@@ -103,8 +103,7 @@ GET /smart/repo.git/info/refs?service=git-upload-pack HTTP/1.1 200\n POST /smart/repo.git/git-upload-pack HTTP/1.1 200\n EOF\n test_expect_success 'used upload-pack service' '\n-\tstrip_access_log >act &&\n-\ttest_cmp exp act\n+\tcheck_access_log exp\n '\n \n test_expect_success 'follow redirects (301)' '\ndiff --git a/t/t5561-http-backend.sh b/t/t5561-http-backend.sh\nindex 4248b5a06d..1c49054595 100755\n--- a/t/t5561-http-backend.sh\n+++ b/t/t5561-http-backend.sh\n@@ -129,8 +129,7 @@ GET /smart/repo.git/info/refs?service=git-receive-pack HTTP/1.1 403 -\n POST /smart/repo.git/git-receive-pack HTTP/1.1 403 -\n EOF\n test_expect_success 'server request log matches test results' '\n-\tstrip_access_log >act &&\n-\ttest_cmp exp act\n+\tcheck_access_log exp\n '\n \n stop_httpd\n-- \n2.18.0.305.g66e9e0a543\n\n"},{"id":"352355","messageId":"20180712155602.GA8889@sigill.intra.peff.net","threadId":"48709","inReplyTo":"20180712122216.12691-2-szeder.dev@gmail.com","subject":"Re: [PATCH v3 1/3] t5541: clean up truncating access log","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2018-07-12T15:56:03Z","receivedAt":"2018-07-12T15:56:06Z","isPatch":true,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Jul 12, 2018 at 02:22:14PM +0200, SZEDER Gábor wrote:\n\n> diff --git a/t/t5541-http-push-smart.sh b/t/t5541-http-push-smart.sh\n> index a2af693068..5c9ca19401 100755\n> --- a/t/t5541-http-push-smart.sh\n> +++ b/t/t5541-http-push-smart.sh\n> @@ -38,6 +38,10 @@ GET /smart/test_repo.git/info/refs?service=git-upload-pack HTTP/1.1 200\n> POST /smart/test_repo.git/git-upload-pack HTTP/1.1 200\n> EOF\n> test_expect_success 'no empty path components' '\n> +\t# Clear the log, so that it does not affect the \"used receive-pack\n> +\t# service\" test which reads the log too.\n> +\ttest_when_finished \">\\\"$HTTPD_ROOT_PATH\\\"/access.log\" &&\n\nI think you want to escape the $ here, too, so the eval sees the\nvariable and not its expanded value.\n\nOther than that, this iteration looks good (and patch 3 is much easier\nto read).\n\n-Peff\n"}]}