{"thread":{"id":"49290","subject":"[RFC PATCH 0/5] Fix the racy split index problem","startedAt":"2018-09-06T02:48:21Z","lastAt":"2018-09-10T22:12:40Z","messageCount":20,"participants":["SZEDER Gábor","Ævar Arnfjörð Bjarmason","Junio C Hamano","Duy Nguyen","Paul-Sebastian Ungureanu"],"isPatch":true,"patchVersion":1,"patchTotal":5},"messages":[{"id":"357506","messageId":"20180906024810.8074-1-szeder.dev@gmail.com","threadId":"49290","inReplyTo":null,"subject":"[RFC PATCH 0/5] Fix the racy split index problem","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-09-06T02:48:05Z","receivedAt":"2018-09-06T02:48:21Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"Ever since the split index feature was introduced, refreshing a split\nindex is prone to a variant of the classic racy git problem, which\ncaused occasional failures in several random test scripts when run\nwith 'GIT_TEST_SPLIT_INDEX=yes'.  I won't go into details here, there\nis plenty of text to be read already in the commit messages of patches\n3 and 5.\n\nRFC, because I'm not sure that the fix in patch 5 is the best fix for\nthis issue.  ... and because I usually don't dive this deep into core\nstuff during my Git hacking adventures, so who knows what subtleties I\nmight have missed.\n\n\nSZEDER Gábor (5):\n  t1700-split-index: drop unnecessary 'grep'\n  t0090: disable GIT_TEST_SPLIT_INDEX for the test checking split index\n  split index: add a test to demonstrate the racy split index problem\n  t1700-split-index: date back files to avoid racy situations\n  split-index: smudge and add racily clean cache entries to split index\n\n cache.h                     |   2 +\n read-cache.c                |   2 +-\n split-index.c               |  12 ++-\n t/t0090-cache-tree.sh       |  18 ++--\n t/t1700-split-index.sh      |  51 +++++++-----\n t/t1701-racy-split-index.sh | 162 ++++++++++++++++++++++++++++++++++++\n 6 files changed, 216 insertions(+), 31 deletions(-)\n create mode 100755 t/t1701-racy-split-index.sh\n\n-- \n2.19.0.rc0.188.g56c5ee2db1\n\n"},{"id":"357507","messageId":"20180906024810.8074-2-szeder.dev@gmail.com","threadId":"49290","inReplyTo":"20180906024810.8074-1-szeder.dev@gmail.com","subject":"[PATCH 1/5] t1700-split-index: drop unnecessary 'grep'","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-09-06T02:48:06Z","receivedAt":"2018-09-06T02:48:28Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"The test 'disable split index' in 't1700-split-index.sh' runs the\nfollowing pipeline:\n\n  cmd | grep <pattern> | sed s///\n\nDrop that 'grep' from the pipeline, and let 'sed' take over its\nduties.\n\nSigned-off-by: SZEDER Gábor <szeder.dev@gmail.com>\n---\n t/t1700-split-index.sh | 2 +-\n 1 file changed, 1 insertion(+), 1 deletion(-)\n\ndiff --git a/t/t1700-split-index.sh b/t/t1700-split-index.sh\nindex b3b4d83eaf..be22398a85 100755\n--- a/t/t1700-split-index.sh\n+++ b/t/t1700-split-index.sh\n@@ -57,7 +57,7 @@ test_expect_success 'disable split index' '\n \tEOF\n \ttest_cmp ls-files.expect ls-files.actual &&\n \n-\tBASE=$(test-tool dump-split-index .git/index | grep \"^own\" | sed \"s/own/base/\") &&\n+\tBASE=$(test-tool dump-split-index .git/index | sed -n \"s/^own/base/p\") &&\n \ttest-tool dump-split-index .git/index | sed \"/^own/d\" >actual &&\n \tcat >expect <<-EOF &&\n \tnot a split index\n-- \n2.19.0.rc0.188.g56c5ee2db1\n\n"},{"id":"357508","messageId":"20180906024810.8074-3-szeder.dev@gmail.com","threadId":"49290","inReplyTo":"20180906024810.8074-1-szeder.dev@gmail.com","subject":"[PATCH 2/5] t0090: disable GIT_TEST_SPLIT_INDEX for the test checking split index","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-09-06T02:48:07Z","receivedAt":"2018-09-06T02:48:33Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"The test 'switching trees does not invalidate shared index' in\n't0090-cache-tree.sh' is about verifying the behaviour of the split\nindex feature, therefore it should be in full control of when index\nsplitting is performed, like all the tests in 't1700-split-index.sh'.\n\nUnset GIT_TEST_SPLIT_INDEX for this test to avoid unintended random\nindex splitting.\n\nSigned-off-by: SZEDER Gábor <szeder.dev@gmail.com>\n---\n t/t0090-cache-tree.sh | 18 +++++++++++-------\n 1 file changed, 11 insertions(+), 7 deletions(-)\n\ndiff --git a/t/t0090-cache-tree.sh b/t/t0090-cache-tree.sh\nindex 7de40141ca..65b5152b9b 100755\n--- a/t/t0090-cache-tree.sh\n+++ b/t/t0090-cache-tree.sh\n@@ -242,14 +242,18 @@ test_expect_success 'no phantom error when switching trees' '\n \ttest_must_be_empty errors\n '\n \n+\n test_expect_success 'switching trees does not invalidate shared index' '\n-\tgit update-index --split-index &&\n-\t>split &&\n-\tgit add split &&\n-\ttest-tool dump-split-index .git/index | grep -v ^own >before &&\n-\tgit commit -m \"as-is\" &&\n-\ttest-tool dump-split-index .git/index | grep -v ^own >after &&\n-\ttest_cmp before after\n+\t(\n+\t\tsane_unset GIT_TEST_SPLIT_INDEX &&\n+\t\tgit update-index --split-index &&\n+\t\t>split &&\n+\t\tgit add split &&\n+\t\ttest-tool dump-split-index .git/index | grep -v ^own >before &&\n+\t\tgit commit -m \"as-is\" &&\n+\t\ttest-tool dump-split-index .git/index | grep -v ^own >after &&\n+\t\ttest_cmp before after\n+\t)\n '\n \n test_done\n-- \n2.19.0.rc0.188.g56c5ee2db1\n\n"},{"id":"357509","messageId":"20180906024810.8074-4-szeder.dev@gmail.com","threadId":"49290","inReplyTo":"20180906024810.8074-1-szeder.dev@gmail.com","subject":"[RFC PATCH 3/5] split index: add a test to demonstrate the racy split index problem","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-09-06T02:48:08Z","receivedAt":"2018-09-06T02:48:39Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"Ever since the split index feature was introduced [1], refreshing a\nsplit index is prone to a variant of the classic racy git problem.\nThere are a couple of unrelated tests in the test suite that\noccasionally fail when run with 'GIT_TEST_SPLIT_INDEX=yes', but\n't1700-split-index.sh', the only test script focusing solely on split\nindex, has never noticed this issue, because it only cares about how\nthe index is split under various circumstances and all the different\nways to turn the split index feature on and off.\n\nAdd a dedicated test script 't1701-racy-split-index.sh' to exercise\nthe split index feature in racy situations as well; kind of a\n\"t0010-racy-git.sh for split index\" but with modern style (the tests\ndo everything in &&-chained list of commands in 'test_expect_...'\nblocks, and use 'test_cmp' for more informative output on failure).\n\nThe tests cover the following sequences of index splitting, updating,\nand racy file modifications, with case #3 demonstrating the racy split\nindex problem:\n\n  1. Split the index when the worktree contains a racily clean file:\n\n       echo \"cached content\" >file\n       git update-index --split-index --add file\n       echo \"dirty worktree\" >file    # size stays the same\n\n     This case already works properly.  Even though the cache entry's\n     stat data matches with the file in the worktree, subsequent git\n     commands will notice that the (split) index and the file have the\n     same mtime, and then will go on to check the file's content.\n\n  2. Split the index when it (i.e. the not yet splitted index)\n     contains a racily clean cache entry, i.e. an entry whose cached\n     stat data matches with the corresponding file in the worktree and\n     the cached mtime matches that of the index:\n\n       echo \"cached content\" >file\n       git update-index --add file\n       echo \"dirty worktree\" >file\n       # ... wait ...\n       git update-index --split-index --add other-file\n\n     This case already works properly.  The shared index is written by\n     do_write_index(), i.e. the same function that is responsible for\n     writing \"regular\" and split indexes as well.  This function\n     cleverly notices the racily clean cache entry, and writes the\n     entry to the new shared index with smudged stat data, i.e. file\n     size set to 0.  When subsequent git commands read the index, they\n     will notice that the smudged stat data doesn't match with the\n     file in the worktree, and then go on to check the file's content.\n\n  3. Update the split index when the shared index contains a racily\n     clean cache entry:\n\n       echo \"cached content\" >file\n       git update-index --split-index --add file\n       echo \"dirty worktree\" >file\n       # ... wait ...\n       git update-index --add other-file\n\n     This case fails due to the racy split index problem.  In the\n     second 'git update-index' prepare_to_write_split_index() gathers\n     all cache entries that should be written to the new split index.\n     Alas, this function never looks out for racily clean cache\n     entries, and since the file's stat data in the worktree hasn't\n     changed since the shared index was written, the entry won't be\n     replaced in the new split index.  Consequently, do_write_index()\n     doesn't even get this racily clean cache entry, and can't smudge\n     its stat data.  Subsequent git commands will then see that the\n     index has more recent mtime than the file and that the (not\n     smudged) cached stat data still matches with the file in the\n     worktree, and, ultimately, will erroneously consider the file\n     clean.\n\n  4. Add a racily clean file to an already split index:\n\n       git update-index --split-index\n       echo \"cached content\" >file\n       git update-index --add file\n       echo \"dirty worktree\" >file\n\n     This case already works properly.  After the second 'git\n     update-index' writes the newly added file's cache entry to the\n     new split index, it basically works in the same way as case #1.\n\n  5. Update the split index when it contains a racily clean cache\n     entry:\n\n       git update-index --split-index\n       echo \"cached content\" >file\n       git update-index --add file\n       echo \"dirty worktree\" >file\n       # ... wait ...\n       git update-index --add other-file\n\n     This case already works properly.  Since the second 'git\n     update-index' writes the newly added file's cache entry to the\n     split index, the third 'git update-index's do_write_index() now\n     has a chance to look at this entry, notices its raciness, and\n     writes smudged stat data to the new split index.\n\n[1] In the branch leading to the merge commit v2.1.0-rc0~45 (Merge\n    branch 'nd/split-index', 2014-07-16).\n\nSigned-off-by: SZEDER Gábor <szeder.dev@gmail.com>\n---\n t/t1701-racy-split-index.sh | 164 ++++++++++++++++++++++++++++++++++++\n 1 file changed, 164 insertions(+)\n create mode 100755 t/t1701-racy-split-index.sh\n\ndiff --git a/t/t1701-racy-split-index.sh b/t/t1701-racy-split-index.sh\nnew file mode 100755\nindex 0000000000..c92ba9ce5e\n--- /dev/null\n+++ b/t/t1701-racy-split-index.sh\n@@ -0,0 +1,164 @@\n+#!/bin/sh\n+\n+# This test can give false success if your machine is sufficiently\n+# slow or all trials happened to happen on second boundaries.\n+\n+test_description='racy split index'\n+\n+. ./test-lib.sh\n+\n+test_expect_success 'setup' '\n+\t# Only split the index when the test explicitly says so.\n+\tsane_unset GIT_TEST_SPLIT_INDEX GIT_FSMONITOR_TEST &&\n+\tgit config splitIndex.maxPercentChange 100 &&\n+\n+\techo something >other-file &&\n+\t# No raciness with this file.\n+\ttest-tool chmtime =-20 other-file\n+'\n+\n+check_cached_diff () {\n+\tgit diff-index --patch --cached $EMPTY_TREE racy-file >diff &&\n+\ttail -1 diff >actual &&\n+\techo \"+cached content\" >expect &&\n+\ttest_cmp expect actual\n+}\n+\n+for trial in 0 1 2 3 4\n+do\n+\ttest_expect_success \"split the index when the worktree contains a racily clean file #$trial\" '\n+\t\ttest_when_finished \"rm -f .git/index .git/sharedindex.*\" &&\n+\n+\t\t# The next three commands must be run within the same\n+\t\t# second (so both writes to racy-file result in the same\n+\t\t# mtime) to create the interesting racy situation.\n+\t\techo \"cached content\" >racy-file &&\n+\n+\t\t# Update and split the index.  The cache entry of\n+\t\t# racy-file will be stored in the shared index.\n+\t\tgit update-index --split-index --add racy-file &&\n+\n+\t\t# File size must stay the same.\n+\t\techo \"dirty worktree\" >racy-file &&\n+\n+\t\tcheck_cached_diff\n+\t'\n+done\n+\n+for trial in 0 1 2 3 4\n+do\n+\ttest_expect_success \"split the index when it contains a racily clean cache entry #$trial\" '\n+\t\ttest_when_finished \"rm -f .git/index .git/sharedindex.*\" &&\n+\n+\t\t# The next three commands must be run within the same\n+\t\t# second.\n+\t\techo \"cached content\" >racy-file &&\n+\n+\t\tgit update-index --add racy-file &&\n+\n+\t\t# File size must stay the same.\n+\t\techo \"dirty worktree\" >racy-file &&\n+\n+\t\t# Now wait a bit to ensure that the split index written\n+\t\t# below will get a more recent mtime than racy-file,\n+\t\t# and, consequently, subsequent git commands wont\n+\t\t# consider the entry racily clean.\n+\t\tsleep 1 &&\n+\n+\t\t# Update and split the index when it contains the\n+\t\t# racily clean cache entry of racy-file; the stat data\n+\t\t# in that entry should be smudged, so the file wont\n+\t\t# appear clean for subsequent git commands.\n+\t\tgit update-index --split-index --add other-file &&\n+\n+\t\tcheck_cached_diff\n+\t'\n+done\n+\n+for trial in 0 1 2 3 4\n+do\n+\ttest_expect_failure \"update the split index when the shared index contains a racily clean cache entry #$trial\" '\n+\t\ttest_when_finished \"rm -f .git/index .git/sharedindex.*\" &&\n+\n+\t\t# The next three commands must be run within the same\n+\t\t# second.\n+\t\techo \"cached content\" >racy-file &&\n+\n+\t\t# Update and split the index.  The cache entry of\n+\t\t# racy-file will be stored in the shared index.\n+\t\tgit update-index --split-index --add racy-file &&\n+\n+\t\t# File size must stay the same.\n+\t\techo \"dirty worktree\" >racy-file &&\n+\n+\t\t# Now wait a bit to ensure that the split index written\n+\t\t# below will get a more recent mtime than racy-file.\n+\t\tsleep 1 &&\n+\n+\t\t# Update the split index when the shared index contains\n+\t\t# the racily clean cache entry of racy-file.  A\n+\t\t# corresponding replacement cache entry with smudged\n+\t\t# stat data should be added to the new split index, so\n+\t\t# the file wont appear clean for subsequent git commands.\n+\t\t#\n+\t\t# Alas, such a smudged replacement entry is not added!\n+\t\tgit update-index --add other-file &&\n+\n+\t\tcheck_cached_diff\n+\t'\n+done\n+\n+for trial in 0 1 2 3 4\n+do\n+\ttest_expect_success \"add a racily clean file to an already split index #$trial\" '\n+\t\ttest_when_finished \"rm -f .git/index .git/sharedindex.*\" &&\n+\n+\t\tgit update-index --split-index &&\n+\n+\t\t# The next three commands must be run within the same\n+\t\t# second.\n+\t\techo \"cached content\" >racy-file &&\n+\n+\t\t# Update the split index.  The cache entry of racy-file\n+\t\t# will be stored in the split index.\n+\t\tgit update-index --add racy-file &&\n+\n+\t\t# File size must stay the same.\n+\t\techo \"dirty worktree\" >racy-file &&\n+\n+\t\tcheck_cached_diff\n+\t'\n+done\n+\n+for trial in 0 1 2 3 4\n+do\n+\ttest_expect_success \"update the split index when it contains a racily clean cache entry #$trial\" '\n+\t\ttest_when_finished \"rm -f .git/index .git/sharedindex.*\" &&\n+\n+\t\tgit update-index --split-index &&\n+\n+\t\t# The next three commands must be run within the same\n+\t\t# second.\n+\t\techo \"cached content\" >racy-file &&\n+\n+\t\t# Update the split index.  The cache entry of racy-file\n+\t\t# will be stored in the split index.\n+\t\tgit update-index --add racy-file &&\n+\n+\t\t# File size must stay the same.\n+\t\techo \"dirty worktree\" >racy-file &&\n+\n+\t\t# Now wait a bit to ensure that the split index written\n+\t\t# below will get a more recent mtime than racy-file.\n+\t\tsleep 1 &&\n+\n+\t\t# Update the split index when it contains the racily\n+\t\t# clean cache entry of racy-file; the stat data in that\n+\t\t# entry should be smudged.\n+\t\tgit update-index --add other-file &&\n+\n+\t\tcheck_cached_diff\n+\t'\n+done\n+\n+test_done\n-- \n2.19.0.rc0.188.g56c5ee2db1\n\n"},{"id":"357510","messageId":"20180906024810.8074-5-szeder.dev@gmail.com","threadId":"49290","inReplyTo":"20180906024810.8074-1-szeder.dev@gmail.com","subject":"[RFC PATCH 4/5] t1700-split-index: date back files to avoid racy situations","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-09-06T02:48:09Z","receivedAt":"2018-09-06T02:48:45Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"'t1700-split-index.sh' checks that the index was split correctly under\nvarious circumstances and that all the different ways to turn the\nsplit index feature on and off work correctly.  To do so, most of its\ntests use 'test-tool dump-split-index' to see which files have their\ncache entries in the split index.  All these tests assume that all\ncache entries are written to the shared index (called \"base\"\nthroughout these tests) when a new shared index is created.  This is\nan implementation detail: most git commands (basically all except 'git\nupdate-index') don't care or know at all about split index or whether\na cache entry is stored in the split or shared index.\n\nAs demonstrated in the previous patch, refreshing a split index is\nprone to a variant of the classic racy git issue.  The next patch will\nfix this issue, but while doing so it will also slightly change this\nbehaviour: only cache entries with mtime in the past will be written\nonly to the newly created shared index, but racily clean cache entries\nwill be written to the new split index (with smudged stat data).\n\nWhile this upcoming change won't at all affect any git commands, it\nwill violate the above mentioned assumption of 't1700's tests.  Since\nthese tests create or modify files and create or refresh the split\nindex in rapid succession, there are plenty of racily clean cache\nentries to be dealt with, which will then be written to the new split\nindexes, and, ultimately, will cause several tests in 't1700' to fail.\n\nLet's prepare 't1700-split-index.sh' for this upcoming change and\nmodify its tests to avoid racily clean files by backdating the mtime\nof any file modifications (and since a lot of tests create or modify\nfiles, encapsulate it into a helper function).\n\nSigned-off-by: SZEDER Gábor <szeder.dev@gmail.com>\n---\n t/t1700-split-index.sh | 49 ++++++++++++++++++++++++------------------\n 1 file changed, 28 insertions(+), 21 deletions(-)\n\ndiff --git a/t/t1700-split-index.sh b/t/t1700-split-index.sh\nindex be22398a85..e7beef1e09 100755\n--- a/t/t1700-split-index.sh\n+++ b/t/t1700-split-index.sh\n@@ -8,6 +8,13 @@ test_description='split index mode tests'\n sane_unset GIT_TEST_SPLIT_INDEX\n sane_unset GIT_FSMONITOR_TEST\n \n+# Create a file named as $1 with content read from stdin.\n+# Set the file's mtime to a few seconds in the past to avoid racy situations.\n+create_file () {\n+\tcat >\"$1\" &&\n+\ttest-tool chmtime =-5 \"$1\"\n+}\n+\n test_expect_success 'enable split index' '\n \tgit config splitIndex.maxPercentChange 100 &&\n \tgit update-index --split-index &&\n@@ -31,7 +38,7 @@ test_expect_success 'enable split index' '\n '\n \n test_expect_success 'add one file' '\n-\t: >one &&\n+\tcreate_file one &&\n \tgit update-index --add one &&\n \tgit ls-files --stage >ls-files.actual &&\n \tcat >ls-files.expect <<-EOF &&\n@@ -83,7 +90,7 @@ test_expect_success 'enable split index again, \"one\" now belongs to base index\"'\n '\n \n test_expect_success 'modify original file, base index untouched' '\n-\techo modified >one &&\n+\techo modified |create_file one &&\n \tgit update-index one &&\n \tgit ls-files --stage >ls-files.actual &&\n \tcat >ls-files.expect <<-EOF &&\n@@ -102,7 +109,7 @@ test_expect_success 'modify original file, base index untouched' '\n '\n \n test_expect_success 'add another file, which stays index' '\n-\t: >two &&\n+\tcreate_file two &&\n \tgit update-index --add two &&\n \tgit ls-files --stage >ls-files.actual &&\n \tcat >ls-files.expect <<-EOF &&\n@@ -155,7 +162,7 @@ test_expect_success 'remove file in base index' '\n '\n \n test_expect_success 'add original file back' '\n-\t: >one &&\n+\tcreate_file one &&\n \tgit update-index --add one &&\n \tgit ls-files --stage >ls-files.actual &&\n \tcat >ls-files.expect <<-EOF &&\n@@ -174,7 +181,7 @@ test_expect_success 'add original file back' '\n '\n \n test_expect_success 'add new file' '\n-\t: >two &&\n+\tcreate_file two &&\n \tgit update-index --add two &&\n \tgit ls-files --stage >actual &&\n \tcat >expect <<-EOF &&\n@@ -218,7 +225,7 @@ test_expect_success 'rev-parse --shared-index-path' '\n \n test_expect_success 'set core.splitIndex config variable to true' '\n \tgit config core.splitIndex true &&\n-\t: >three &&\n+\tcreate_file three &&\n \tgit update-index --add three &&\n \tgit ls-files --stage >ls-files.actual &&\n \tcat >ls-files.expect <<-EOF &&\n@@ -253,9 +260,9 @@ test_expect_success 'set core.splitIndex config variable to false' '\n \ttest_cmp expect actual\n '\n \n-test_expect_success 'set core.splitIndex config variable to true' '\n+test_expect_success 'set core.splitIndex config variable back to true' '\n \tgit config core.splitIndex true &&\n-\t: >three &&\n+\tcreate_file three &&\n \tgit update-index --add three &&\n \tBASE=$(test-tool dump-split-index .git/index | grep \"^base\") &&\n \ttest-tool dump-split-index .git/index | sed \"/^own/d\" >actual &&\n@@ -265,7 +272,7 @@ test_expect_success 'set core.splitIndex config variable to true' '\n \tdeletions:\n \tEOF\n \ttest_cmp expect actual &&\n-\t: >four &&\n+\tcreate_file four &&\n \tgit update-index --add four &&\n \ttest-tool dump-split-index .git/index | sed \"/^own/d\" >actual &&\n \tcat >expect <<-EOF &&\n@@ -279,7 +286,7 @@ test_expect_success 'set core.splitIndex config variable to true' '\n \n test_expect_success 'check behavior with splitIndex.maxPercentChange unset' '\n \tgit config --unset splitIndex.maxPercentChange &&\n-\t: >five &&\n+\tcreate_file five &&\n \tgit update-index --add five &&\n \tBASE=$(test-tool dump-split-index .git/index | grep \"^base\") &&\n \ttest-tool dump-split-index .git/index | sed \"/^own/d\" >actual &&\n@@ -289,7 +296,7 @@ test_expect_success 'check behavior with splitIndex.maxPercentChange unset' '\n \tdeletions:\n \tEOF\n \ttest_cmp expect actual &&\n-\t: >six &&\n+\tcreate_file six &&\n \tgit update-index --add six &&\n \ttest-tool dump-split-index .git/index | sed \"/^own/d\" >actual &&\n \tcat >expect <<-EOF &&\n@@ -303,7 +310,7 @@ test_expect_success 'check behavior with splitIndex.maxPercentChange unset' '\n \n test_expect_success 'check splitIndex.maxPercentChange set to 0' '\n \tgit config splitIndex.maxPercentChange 0 &&\n-\t: >seven &&\n+\tcreate_file seven &&\n \tgit update-index --add seven &&\n \tBASE=$(test-tool dump-split-index .git/index | grep \"^base\") &&\n \ttest-tool dump-split-index .git/index | sed \"/^own/d\" >actual &&\n@@ -313,7 +320,7 @@ test_expect_success 'check splitIndex.maxPercentChange set to 0' '\n \tdeletions:\n \tEOF\n \ttest_cmp expect actual &&\n-\t: >eight &&\n+\tcreate_file eight &&\n \tgit update-index --add eight &&\n \tBASE=$(test-tool dump-split-index .git/index | grep \"^base\") &&\n \ttest-tool dump-split-index .git/index | sed \"/^own/d\" >actual &&\n@@ -326,17 +333,17 @@ test_expect_success 'check splitIndex.maxPercentChange set to 0' '\n '\n \n test_expect_success 'shared index files expire after 2 weeks by default' '\n-\t: >ten &&\n+\tcreate_file ten &&\n \tgit update-index --add ten &&\n \ttest $(ls .git/sharedindex.* | wc -l) -gt 2 &&\n \tjust_under_2_weeks_ago=$((5-14*86400)) &&\n \ttest-tool chmtime =$just_under_2_weeks_ago .git/sharedindex.* &&\n-\t: >eleven &&\n+\tcreate_file eleven &&\n \tgit update-index --add eleven &&\n \ttest $(ls .git/sharedindex.* | wc -l) -gt 2 &&\n \tjust_over_2_weeks_ago=$((-1-14*86400)) &&\n \ttest-tool chmtime =$just_over_2_weeks_ago .git/sharedindex.* &&\n-\t: >twelve &&\n+\tcreate_file twelve &&\n \tgit update-index --add twelve &&\n \ttest $(ls .git/sharedindex.* | wc -l) -le 2\n '\n@@ -344,12 +351,12 @@ test_expect_success 'shared index files expire after 2 weeks by default' '\n test_expect_success 'check splitIndex.sharedIndexExpire set to 16 days' '\n \tgit config splitIndex.sharedIndexExpire \"16.days.ago\" &&\n \ttest-tool chmtime =$just_over_2_weeks_ago .git/sharedindex.* &&\n-\t: >thirteen &&\n+\tcreate_file thirteen &&\n \tgit update-index --add thirteen &&\n \ttest $(ls .git/sharedindex.* | wc -l) -gt 2 &&\n \tjust_over_16_days_ago=$((-1-16*86400)) &&\n \ttest-tool chmtime =$just_over_16_days_ago .git/sharedindex.* &&\n-\t: >fourteen &&\n+\tcreate_file fourteen &&\n \tgit update-index --add fourteen &&\n \ttest $(ls .git/sharedindex.* | wc -l) -le 2\n '\n@@ -358,13 +365,13 @@ test_expect_success 'check splitIndex.sharedIndexExpire set to \"never\" and \"now\"\n \tgit config splitIndex.sharedIndexExpire never &&\n \tjust_10_years_ago=$((-365*10*86400)) &&\n \ttest-tool chmtime =$just_10_years_ago .git/sharedindex.* &&\n-\t: >fifteen &&\n+\tcreate_file fifteen &&\n \tgit update-index --add fifteen &&\n \ttest $(ls .git/sharedindex.* | wc -l) -gt 2 &&\n \tgit config splitIndex.sharedIndexExpire now &&\n \tjust_1_second_ago=-1 &&\n \ttest-tool chmtime =$just_1_second_ago .git/sharedindex.* &&\n-\t: >sixteen &&\n+\tcreate_file sixteen &&\n \tgit update-index --add sixteen &&\n \ttest $(ls .git/sharedindex.* | wc -l) -le 2\n '\n@@ -379,7 +386,7 @@ do\n \t\t# Create one new shared index file\n \t\tgit config core.sharedrepository \"$mode\" &&\n \t\tgit config core.splitIndex true &&\n-\t\t: >one &&\n+\t\tcreate_file one &&\n \t\tgit update-index --add one &&\n \t\techo \"$modebits\" >expect &&\n \t\ttest_modebits .git/index >actual &&\n-- \n2.19.0.rc0.188.g56c5ee2db1\n\n"},{"id":"357511","messageId":"20180906024810.8074-6-szeder.dev@gmail.com","threadId":"49290","inReplyTo":"20180906024810.8074-1-szeder.dev@gmail.com","subject":"[RFC PATCH 5/5] split-index: smudge and add racily clean cache entries to split index","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-09-06T02:48:10Z","receivedAt":"2018-09-06T02:48:51Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"Ever since the split index feature was introduced [1], refreshing a\nsplit index is prone to a variant of the classic racy git problem.\n\nConsider the following sequence of commands updating the split index\nwhen the shared index contains a racily clean cache entry, i.e. an\nentry whose cached stat data matches with the corresponding file in\nthe worktree and the cached mtime matches that of the index:\n\n  echo \"cached content\" >file\n  git update-index --split-index --add file\n  echo \"dirty worktree\" >file    # size stays the same!\n  # ... wait ...\n  git update-index --add other-file\n\nNormally, when a non-split index is updated, then do_write_index()\n(the function responsible for writing all kinds of indexes, \"regular\",\nsplit, and shared) recognizes racily clean cache entries, and writes\nthem with smudged stat data, i.e. with file size set to 0.  When\nsubsequent git commands read the index, they will notice that the\nsmudged stat data doesn't match with the file in the worktree, and\nthen go on to check the file's content.\n\nIn the above example, however, in the second 'git update-index'\nprepare_to_write_split_index() gathers all cache entries that should\nbe written to the new split index.  Alas, this function never looks\nout for racily clean cache entries, and since the file's stat data in\nthe worktree hasn't changed since the shared index was written, it\nwon't be replaced in the new split index.  Consequently,\ndo_write_index() doesn't even get this racily clean cache entry, and\ncan't smudge its stat data.  Subsequent git commands will then see\nthat the index has more recent mtime than the file and that the (not\nsmudged) cached stat data still matches with the file in the worktree,\nand, ultimately, will erroneously consider the file clean.\n\nModify prepare_to_write_split_index() to recognize racily clean cache\nentries, and mark them to be added to the split index.  This way\ndo_write_index() will get these racily clean cache entries as well,\nand will then write them with smudged stat data to the new split\nindex.\n\nNote that after this change if the index is split when it contains a\nracily clean cache entry, then a smudged cache entry will be written\nboth to the new shared and to the new split indexes.  This doesn't\naffect regular git commands: as far as they are concerned this is just\nan entry in the split index replacing an outdated entry in the shared\nindex.  It did affect a few tests in 't1700-split-index.sh', though,\nbecause they actually check which entries are stored in the split\nindex; the previous patch made the necessary adjustments.  And racily\nclean cache entries and index splitting are rare enough to not worry\nabout the resulting duplicated smudged cache entries, and the\nadditional complexity required to prevent them is not worth it.\n\nSeveral tests failed occasionally when the test suite was run with\n'GIT_TEST_SPLIT_INDEX=yes'.  Here are those that I managed to trace\nback to this racy split index problem, starting with those failing\nmore frequently, with a link to a failing Travis CI build job for\neach.  The highlighted line shows when the racy file was written,\nwhich is not always in the failing test (but note that those lines are\nin the 'after failure' fold, and your browser might unhelpfully fold\nit up before you could take a good look).\n\n  t3903-stash.sh:\n    https://travis-ci.org/git/git/jobs/385542084#L5858\n\n  t4024-diff-optimize-common.sh:\n    https://travis-ci.org/git/git/jobs/386531969#L3174\n\n  t4015-diff-whitespace.sh:\n    https://travis-ci.org/git/git/jobs/360797600#L8215\n\n  t2200-add-update.sh:\n    https://travis-ci.org/git/git/jobs/382543426#L3051\n\n  t0090-cache-tree:\n    https://travis-ci.org/git/git/jobs/416583010#L3679\n\nThere might be others, e.g. perhaps 't1000-read-tree-m-3way.sh' and\nothers using 'lib-read-tree-m-3way.sh', but I couldn't confirm yet.\n\n[1] In the branch leading to the merge commit v2.1.0-rc0~45 (Merge\n    branch 'nd/split-index', 2014-07-16).\n\nSigned-off-by: SZEDER Gábor <szeder.dev@gmail.com>\n---\n cache.h                     |  2 ++\n read-cache.c                |  2 +-\n split-index.c               | 12 +++++++++++-\n t/t1701-racy-split-index.sh |  4 +---\n 4 files changed, 15 insertions(+), 5 deletions(-)\n\ndiff --git a/cache.h b/cache.h\nindex 4d014541ab..3f419b6c79 100644\n--- a/cache.h\n+++ b/cache.h\n@@ -781,6 +781,8 @@ extern void *read_blob_data_from_index(const struct index_state *, const char *,\n #define CE_MATCH_REFRESH\t\t0x10\n /* don't refresh_fsmonitor state or do stat comparison even if CE_FSMONITOR_VALID is true */\n #define CE_MATCH_IGNORE_FSMONITOR 0X20\n+extern int is_racy_timestamp(const struct index_state *istate,\n+\t\t\t     const struct cache_entry *ce);\n extern int ie_match_stat(struct index_state *, const struct cache_entry *, struct stat *, unsigned int);\n extern int ie_modified(struct index_state *, const struct cache_entry *, struct stat *, unsigned int);\n \ndiff --git a/read-cache.c b/read-cache.c\nindex 7b1354d759..8f644f68b4 100644\n--- a/read-cache.c\n+++ b/read-cache.c\n@@ -337,7 +337,7 @@ static int is_racy_stat(const struct index_state *istate,\n \t\t);\n }\n \n-static int is_racy_timestamp(const struct index_state *istate,\n+int is_racy_timestamp(const struct index_state *istate,\n \t\t\t     const struct cache_entry *ce)\n {\n \treturn (!S_ISGITLINK(ce->ce_mode) &&\ndiff --git a/split-index.c b/split-index.c\nindex 84f067e10d..b4458f31f6 100644\n--- a/split-index.c\n+++ b/split-index.c\n@@ -220,8 +220,18 @@ void prepare_to_write_split_index(struct index_state *istate)\n \t\t\t}\n \t\t\tce->ce_flags |= CE_MATCHED; /* or \"shared\" */\n \t\t\tbase = si->base->cache[ce->index - 1];\n-\t\t\tif (ce == base)\n+\t\t\tif (ce == base) {\n+\t\t\t\t/*\n+\t\t\t\t * Racily clean cache entries must be\n+\t\t\t\t * written to the split index, so the\n+\t\t\t\t * subsequent do_write_index() can smudge\n+\t\t\t\t * their stat data.\n+\t\t\t\t */\n+\t\t\t\tif (!ce_uptodate(ce) &&\n+\t\t\t\t    is_racy_timestamp(istate, ce))\n+\t\t\t\t\tce->ce_flags |= CE_UPDATE_IN_BASE;\n \t\t\t\tcontinue;\n+\t\t\t}\n \t\t\tif (ce->ce_namelen != base->ce_namelen ||\n \t\t\t    strcmp(ce->name, base->name)) {\n \t\t\t\tce->index = 0;\ndiff --git a/t/t1701-racy-split-index.sh b/t/t1701-racy-split-index.sh\nindex c92ba9ce5e..6780d08367 100755\n--- a/t/t1701-racy-split-index.sh\n+++ b/t/t1701-racy-split-index.sh\n@@ -77,7 +77,7 @@ done\n \n for trial in 0 1 2 3 4\n do\n-\ttest_expect_failure \"update the split index when the shared index contains a racily clean cache entry #$trial\" '\n+\ttest_expect_success \"update the split index when the shared index contains a racily clean cache entry #$trial\" '\n \t\ttest_when_finished \"rm -f .git/index .git/sharedindex.*\" &&\n \n \t\t# The next three commands must be run within the same\n@@ -100,8 +100,6 @@ do\n \t\t# corresponding replacement cache entry with smudged\n \t\t# stat data should be added to the new split index, so\n \t\t# the file wont appear clean for subsequent git commands.\n-\t\t#\n-\t\t# Alas, such a smudged replacement entry is not added!\n \t\tgit update-index --add other-file &&\n \n \t\tcheck_cached_diff\n-- \n2.19.0.rc0.188.g56c5ee2db1\n\n"},{"id":"357518","messageId":"871sa7rr30.fsf@evledraar.gmail.com","threadId":"49290","inReplyTo":"20180906024810.8074-5-szeder.dev@gmail.com","subject":"Re: [RFC PATCH 4/5] t1700-split-index: date back files to avoid racy situations","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2018-09-06T08:02:43Z","receivedAt":"2018-09-06T08:02:48Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Thu, Sep 06 2018, SZEDER Gábor wrote:\n\n> +# Create a file named as $1 with content read from stdin.\n> +# Set the file's mtime to a few seconds in the past to avoid racy situations.\n> +create_file () {\n\nNit: Would be easier to read in the future as\ne.g. s/create_file/create_old_file/ or something like that. I.e. so you\ncan see at a glance from the tests themselves what this is doing.\n\n>  test_expect_success 'modify original file, base index untouched' '\n> -\techo modified >one &&\n> +\techo modified |create_file one &&\n\nStyle nit: missing whitespace after \"|\", i.e. should be \"echo modified |\ncreate_file one\".\n"},{"id":"357519","messageId":"87zhwvqcgr.fsf@evledraar.gmail.com","threadId":"49290","inReplyTo":"20180906024810.8074-3-szeder.dev@gmail.com","subject":"Re: [PATCH 2/5] t0090: disable GIT_TEST_SPLIT_INDEX for the test checking split index","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2018-09-06T08:03:48Z","receivedAt":"2018-09-06T08:03:53Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Thu, Sep 06 2018, SZEDER Gábor wrote:\n>  '\n>\n> +\n\n^ stray newline being added here that shouldn't be added.\n"},{"id":"357520","messageId":"20180906091539.GA8805@localhost","threadId":"49290","inReplyTo":"871sa7rr30.fsf@evledraar.gmail.com","subject":"Re: [RFC PATCH 4/5] t1700-split-index: date back files to avoid racy situations","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-09-06T09:15:39Z","receivedAt":"2018-09-06T09:15:48Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Thu, Sep 06, 2018 at 10:02:43AM +0200, Ævar Arnfjörð Bjarmason wrote:\n> \n> On Thu, Sep 06 2018, SZEDER Gábor wrote:\n> \n> > +# Create a file named as $1 with content read from stdin.\n> > +# Set the file's mtime to a few seconds in the past to avoid racy situations.\n> > +create_file () {\n> \n> Nit: Would be easier to read in the future as\n> e.g. s/create_file/create_old_file/ or something like that. I.e. so you\n> can see at a glance from the tests themselves what this is doing.\n\nPerhaps; but then I'm not so sure about 'old', because that's just a\nproperty of the resulting file...  I'm inclined to rename it to\n'create_non_racy_file' to also imply \"why\" this function is used\ninstead of plain old '>file'.\n\n"},{"id":"357521","messageId":"87y3cfq8wa.fsf@evledraar.gmail.com","threadId":"49290","inReplyTo":"20180906091539.GA8805@localhost","subject":"Re: [RFC PATCH 4/5] t1700-split-index: date back files to avoid racy situations","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2018-09-06T09:20:53Z","receivedAt":"2018-09-06T09:20:58Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Thu, Sep 06 2018, SZEDER Gábor wrote:\n\n> On Thu, Sep 06, 2018 at 10:02:43AM +0200, Ævar Arnfjörð Bjarmason wrote:\n>> \n>> On Thu, Sep 06 2018, SZEDER Gábor wrote:\n>> \n>> > +# Create a file named as $1 with content read from stdin.\n>> > +# Set the file's mtime to a few seconds in the past to avoid racy situations.\n>> > +create_file () {\n>> \n>> Nit: Would be easier to read in the future as\n>> e.g. s/create_file/create_old_file/ or something like that. I.e. so you\n>> can see at a glance from the tests themselves what this is doing.\n>\n> Perhaps; but then I'm not so sure about 'old', because that's just a\n> property of the resulting file...  I'm inclined to rename it to\n> 'create_non_racy_file' to also imply \"why\" this function is used\n> instead of plain old '>file'.\n\nYeah, that's much better.\n"},{"id":"357525","messageId":"87woryrkfo.fsf@evledraar.gmail.com","threadId":"49290","inReplyTo":"20180906024810.8074-6-szeder.dev@gmail.com","subject":"Re: [RFC PATCH 5/5] split-index: smudge and add racily clean cache entries to split index","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2018-09-06T10:26:19Z","receivedAt":"2018-09-06T10:26:24Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Thu, Sep 06 2018, SZEDER Gábor wrote:\n\n>   t3903-stash.sh:\n>     https://travis-ci.org/git/git/jobs/385542084#L5858\n>\n>   t4024-diff-optimize-common.sh:\n>     https://travis-ci.org/git/git/jobs/386531969#L3174\n>\n>   t4015-diff-whitespace.sh:\n>     https://travis-ci.org/git/git/jobs/360797600#L8215\n>\n>   t2200-add-update.sh:\n>     https://travis-ci.org/git/git/jobs/382543426#L3051\n>\n>   t0090-cache-tree:\n>     https://travis-ci.org/git/git/jobs/416583010#L3679\n\nNit: That last test name is missing its \".sh\", as I found out when\ncopy/pasting all of these into a terminal :)\n"},{"id":"357526","messageId":"87va7ireuu.fsf@evledraar.gmail.com","threadId":"49290","inReplyTo":"20180906024810.8074-6-szeder.dev@gmail.com","subject":"Re: [RFC PATCH 5/5] split-index: smudge and add racily clean cache entries to split index","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2018-09-06T12:26:49Z","receivedAt":"2018-09-06T12:26:56Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Thu, Sep 06 2018, SZEDER Gábor wrote:\n\n> Ever since the split index feature was introduced [1], refreshing a\n> split index is prone to a variant of the classic racy git problem.\n>\n> Consider the following sequence of commands updating the split index\n> when the shared index contains a racily clean cache entry, i.e. an\n> entry whose cached stat data matches with the corresponding file in\n> the worktree and the cached mtime matches that of the index:\n>\n>   echo \"cached content\" >file\n>   git update-index --split-index --add file\n>   echo \"dirty worktree\" >file    # size stays the same!\n>   # ... wait ...\n>   git update-index --add other-file\n>\n> Normally, when a non-split index is updated, then do_write_index()\n> (the function responsible for writing all kinds of indexes, \"regular\",\n> split, and shared) recognizes racily clean cache entries, and writes\n> them with smudged stat data, i.e. with file size set to 0.  When\n> subsequent git commands read the index, they will notice that the\n> smudged stat data doesn't match with the file in the worktree, and\n> then go on to check the file's content.\n>\n> In the above example, however, in the second 'git update-index'\n> prepare_to_write_split_index() gathers all cache entries that should\n> be written to the new split index.  Alas, this function never looks\n> out for racily clean cache entries, and since the file's stat data in\n> the worktree hasn't changed since the shared index was written, it\n> won't be replaced in the new split index.  Consequently,\n> do_write_index() doesn't even get this racily clean cache entry, and\n> can't smudge its stat data.  Subsequent git commands will then see\n> that the index has more recent mtime than the file and that the (not\n> smudged) cached stat data still matches with the file in the worktree,\n> and, ultimately, will erroneously consider the file clean.\n>\n> Modify prepare_to_write_split_index() to recognize racily clean cache\n> entries, and mark them to be added to the split index.  This way\n> do_write_index() will get these racily clean cache entries as well,\n> and will then write them with smudged stat data to the new split\n> index.\n>\n> Note that after this change if the index is split when it contains a\n> racily clean cache entry, then a smudged cache entry will be written\n> both to the new shared and to the new split indexes.  This doesn't\n> affect regular git commands: as far as they are concerned this is just\n> an entry in the split index replacing an outdated entry in the shared\n> index.  It did affect a few tests in 't1700-split-index.sh', though,\n> because they actually check which entries are stored in the split\n> index; the previous patch made the necessary adjustments.  And racily\n> clean cache entries and index splitting are rare enough to not worry\n> about the resulting duplicated smudged cache entries, and the\n> additional complexity required to prevent them is not worth it.\n>\n> Several tests failed occasionally when the test suite was run with\n> 'GIT_TEST_SPLIT_INDEX=yes'.  Here are those that I managed to trace\n> back to this racy split index problem, starting with those failing\n> more frequently, with a link to a failing Travis CI build job for\n> each.  The highlighted line shows when the racy file was written,\n> which is not always in the failing test (but note that those lines are\n> in the 'after failure' fold, and your browser might unhelpfully fold\n> it up before you could take a good look).\n\nThanks for working on this. When I package up git I run the tests\nunder a few different modes, in the case of split index I've been\ndoing:\n\n    GIT_TEST_SPLIT_INDEX=true GIT_SKIP_TESTS=\"t3903 t4015.77\"\n\nSince those were the ones I spotted failing under that mode, but\nI still had occasional other failures, I don't have a record of\nwhich, maybe some of these other tests you mention, maybe not.\n\nTo test how this this series improves things, I've been running\nthis on a 56 core CentOS 7.5 machine:\n\n    while true; do GIT_TEST_SPLIT_INDEX=yes prove -j$(parallel --number-of-cores) t3903-stash.sh t4024-diff-optimize-common.sh t4015-diff-whitespace.sh t2200-add-update.sh t0090-cache-tree.sh && echo \"OK $(date) $(git describe)\" >>log2 || echo \"FAIL $(date) $(git describe)\" >>log2; done\n\nWhile, in another window to get some load on the machine (these seem to\nfail more under load):\n\n    while true; do prove -j$(parallel --number-of-cores) t[156789]*.sh; done\n\nThe results with this series applied up to 4/5. I.e. without the actual\nfix:\n\n     92 OK v2.19.0-rc2-6-ged839bd155\n      8 FAIL v2.19.0-rc2-6-ged839bd155\n\nI.e. when running this 100 times, I got 8 failures. So 8%.\n\nWith this patch applied:\n\n    389 OK v2.19.0-rc2-5-g05a5a13935\n     11 FAIL v2.19.0-rc2-5-g05a5a13935\n\nThis time I ran the tests 400 times, and got 11 failures, i.e. a\n~2.8% failure rate. I don't have a full account of what stuff\nfailed (this was just scrolling past in my terminal), but most\nwere:\n\n    t0090-cache-tree.sh          (Wstat: 256 Tests: 21 Failed: 3)\n      Failed tests:  10-12\n      Non-zero exit status: 1\n\nI.e. these tests:\n\n    ok 10 - commit --interactive gives cache-tree on partial commit\n    ok 11 - commit in child dir has cache-tree\n    ok 12 - reset --hard gives cache-tree\n\nThen I saw two of these fail, and no other failures:\n\n    t3903-stash.sh               (Wstat: 256 Tests: 90 Failed: 1)\n      Failed test:  55\n      Non-zero exit status: 1\n\nI.e. this:\n\n    ok 55 - stash branch should not drop the stash if the apply fails\n\nI don't have output from those under -x -v. I'm running them in a loop\nnow to try to make them fail like that, no luck yet, maybe one of those\noptions \"fixes\" the race condition, or I'm just unlucky.\n\n[Side note: All of the above is just assuming that running the tests in\n a loop without GIT_TEST_SPLIT_INDEX=yes will work, but I haven't\n actually tested that, but I've never seen one of these transitory\n failures in the past without GIT_TEST_SPLIT_INDEX=yes, so I'm fairly\n sure that works]\n\nSo this definitely seems like an improvement, i.e. the transitory\nfailure rate is much lower now, but it looks like there's still some\nrace condition related to split index left to solve.\n\nHowever, one thing that makes me paranoid is that without your patch I\ndo get failures on t3903-stash.sh, but it's a *different* failure than\nthe (much less likely to happen) failure after your patch. I.e. I've\nonly seen it fail like this before:\n\n    t3903-stash.sh               (Wstat: 256 Tests: 90 Failed: 1)\n      Failed test:  60\n      Non-zero exit status: 1\n\nThat's this test, i.e. #60, not the #55 test that occasionally fails\nafter these patches:\n\n    ok 60 - handle stash specification with spaces\n\nThis series doesn't change t3903-stash.sh at all, so this really is a\ndifferent failure.\n\nYou *do* modify t0090-cache-tree.sh, but the 10-12 tests failing with\nyour patch are earlier in the file than the new test you added, so I\nbelieve that's a new failure as well. It could just be sampling bias /\nbad luck, but I don't have a single failure for t0090-cache-tree.sh\nwithout this patch, and with the patch it's the most common failure.\n"},{"id":"357542","messageId":"20180906151439.GA8016@localhost","threadId":"49290","inReplyTo":"87va7ireuu.fsf@evledraar.gmail.com","subject":"Re: [RFC PATCH 5/5] split-index: smudge and add racily clean cache entries to split index","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-09-06T15:14:39Z","receivedAt":"2018-09-06T15:14:48Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Thu, Sep 06, 2018 at 02:26:49PM +0200, Ævar Arnfjörð Bjarmason wrote:\n> \n> On Thu, Sep 06 2018, SZEDER Gábor wrote:\n> > Several tests failed occasionally when the test suite was run with\n> > 'GIT_TEST_SPLIT_INDEX=yes'.  Here are those that I managed to trace\n> > back to this racy split index problem, starting with those failing\n> > more frequently, with a link to a failing Travis CI build job for\n> > each.  The highlighted line shows when the racy file was written,\n> > which is not always in the failing test (but note that those lines are\n> > in the 'after failure' fold, and your browser might unhelpfully fold\n> > it up before you could take a good look).\n> \n> Thanks for working on this. When I package up git I run the tests\n> under a few different modes, in the case of split index I've been\n> doing:\n> \n>     GIT_TEST_SPLIT_INDEX=true GIT_SKIP_TESTS=\"t3903 t4015.77\"\n\nYeah, I noticed that you mentioned this in an unrelated thread the\nother day, that's why I put you on Cc.  ... and that's why I pulled\nthis series from the backburner and cleaned it up for submission.\n(Gah, most of these commits have an author date back in February...)\n\n> Since those were the ones I spotted failing under that mode, but\n> I still had occasional other failures, I don't have a record of\n> which, maybe some of these other tests you mention, maybe not.\n\nI poked around the Travis CI API, and managed to get the logs of all\nbuild jobs that failed with 'GIT_TEST_SPLIT_INDEX=yes' but succeeded\nwithout it.  Here is the list of failed test scripts, along with how\nmany times they failed:\n\n      1 t0027-auto-crlf.sh\n      1 t0090-cache-tree.sh\n      1 t3404-rebase-interactive.sh\n      1 t5520-pull.sh\n      1 t5573-pull-verify-signatures.sh\n      1 t5608-clone-2gb.sh\n      1 t7406-submodule-update.sh\n      2 t2200-add-update.sh\n      2 t4002-diff-basic.sh\n      2 t5504-fetch-receive-strict.sh\n      3 t0028-working-tree-encoding.sh\n      4 t1000-read-tree-m-3way.sh\n      6 t4015-diff-whitespace.sh\n     10 t4024-diff-optimize-common.sh\n     17 t3030-merge-recursive.sh\n     17 t3402-rebase-merge.sh\n     17 t3501-revert-cherry-pick.sh\n     17 t6022-merge-rename.sh\n     17 t6032-merge-large-rename.sh\n     17 t6034-merge-rename-nocruft.sh\n     17 t6042-merge-rename-corner-cases.sh\n     17 t6043-merge-rename-directories.sh\n     17 t6046-merge-skip-unneeded-updates.sh\n     17 t7003-filter-branch.sh\n     17 t7601-merge-pull-config.sh\n     23 t3903-stash.sh\n\nI doubt that this racy split index problem is responsible for all\nthese failures; e.g. I looked at the failures of a few merge-related\ntest scripts, and these logs show that they tend to fail because of\nmemory corruption, i.e. with 'Aborted (core dumped)' or 'Segmentation\nfault (core dumped)'.\n\n> To test how this this series improves things, I've been running\n> this on a 56 core CentOS 7.5 machine:\n> \n>     while true; do GIT_TEST_SPLIT_INDEX=yes prove -j$(parallel --number-of-cores) t3903-stash.sh t4024-diff-optimize-common.sh t4015-diff-whitespace.sh t2200-add-update.sh t0090-cache-tree.sh && echo \"OK $(date) $(git describe)\" >>log2 || echo \"FAIL $(date) $(git describe)\" >>log2; done\n> \n> While, in another window to get some load on the machine (these seem to\n> fail more under load):\n> \n>     while true; do prove -j$(parallel --number-of-cores) t[156789]*.sh; done\n> \n> The results with this series applied up to 4/5. I.e. without the actual\n> fix:\n> \n>      92 OK v2.19.0-rc2-6-ged839bd155\n>       8 FAIL v2.19.0-rc2-6-ged839bd155\n> \n> I.e. when running this 100 times, I got 8 failures. So 8%.\n\nLucky you ;)\n\nI could only get t3903 to fail on me, but not the others.  That was\nenough to eventually track down and fix the problem (fun! ;), and then\nI looked at the logs of failed git/git Travis CI build jobs to see,\nwhat other failures might have been caused by it.\n\n> With this patch applied:\n> \n>     389 OK v2.19.0-rc2-5-g05a5a13935\n>      11 FAIL v2.19.0-rc2-5-g05a5a13935\n> \n> This time I ran the tests 400 times, and got 11 failures, i.e. a\n> ~2.8% failure rate. I don't have a full account of what stuff\n> failed (this was just scrolling past in my terminal), but most\n> were:\n> \n>     t0090-cache-tree.sh          (Wstat: 256 Tests: 21 Failed: 3)\n>       Failed tests:  10-12\n>       Non-zero exit status: 1\n> \n> I.e. these tests:\n> \n>     ok 10 - commit --interactive gives cache-tree on partial commit\n>     ok 11 - commit in child dir has cache-tree\n>     ok 12 - reset --hard gives cache-tree\n\nBut hey, 't0090 --verbose-log -x -i' just failed on me with the fix\napplied while writing this email, yay!  In its logs I see the\nfollowing errors in all three tests you mention:\n\n  error: index uses ?½þA extension, which we do not understand\n  fatal: index file corrupt\n\nTest 13 then starts with 'rm -f .git/index', and then all is well for\nthe remaining tests.\n\nThere was a recent discussion about a similar error starting at:\n\n  https://public-inbox.org/git/20180901214157.hxlqmbz3fds7hsdl@ltop.local/\n\nand leading to a fix in 6c003d6ffb (reopen_tempfile(): truncate opened\nfile, 2018-09-04).  I certainly hope that not my fix is buggy, but\ncombined with 'GIT_TEST_SPLIT_INDEX=yes' it can occasionally trigger\nthe same error, and Peff's (Cc'd) fix will resolve it as well.\n\nCould you run your stress tests with Peff's fix merged with mine?\nApparetly your setup is much more capable of triggering these issues\nthan mine...\n\n"},{"id":"357543","messageId":"87lg8er6ir.fsf@evledraar.gmail.com","threadId":"49290","inReplyTo":"20180906151439.GA8016@localhost","subject":"Re: [RFC PATCH 5/5] split-index: smudge and add racily clean cache entries to split index","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2018-09-06T15:26:52Z","receivedAt":"2018-09-06T15:26:58Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Thu, Sep 06 2018, SZEDER Gábor wrote:\n\n> On Thu, Sep 06, 2018 at 02:26:49PM +0200, Ævar Arnfjörð Bjarmason wrote:\n>>\n>> On Thu, Sep 06 2018, SZEDER Gábor wrote:\n>> > Several tests failed occasionally when the test suite was run with\n>> > 'GIT_TEST_SPLIT_INDEX=yes'.  Here are those that I managed to trace\n>> > back to this racy split index problem, starting with those failing\n>> > more frequently, with a link to a failing Travis CI build job for\n>> > each.  The highlighted line shows when the racy file was written,\n>> > which is not always in the failing test (but note that those lines are\n>> > in the 'after failure' fold, and your browser might unhelpfully fold\n>> > it up before you could take a good look).\n>>\n>> Thanks for working on this. When I package up git I run the tests\n>> under a few different modes, in the case of split index I've been\n>> doing:\n>>\n>>     GIT_TEST_SPLIT_INDEX=true GIT_SKIP_TESTS=\"t3903 t4015.77\"\n>\n> Yeah, I noticed that you mentioned this in an unrelated thread the\n> other day, that's why I put you on Cc.  ... and that's why I pulled\n> this series from the backburner and cleaned it up for submission.\n> (Gah, most of these commits have an author date back in February...)\n>\n>> Since those were the ones I spotted failing under that mode, but\n>> I still had occasional other failures, I don't have a record of\n>> which, maybe some of these other tests you mention, maybe not.\n>\n> I poked around the Travis CI API, and managed to get the logs of all\n> build jobs that failed with 'GIT_TEST_SPLIT_INDEX=yes' but succeeded\n> without it.  Here is the list of failed test scripts, along with how\n> many times they failed:\n>\n>       1 t0027-auto-crlf.sh\n>       1 t0090-cache-tree.sh\n>       1 t3404-rebase-interactive.sh\n>       1 t5520-pull.sh\n>       1 t5573-pull-verify-signatures.sh\n>       1 t5608-clone-2gb.sh\n>       1 t7406-submodule-update.sh\n>       2 t2200-add-update.sh\n>       2 t4002-diff-basic.sh\n>       2 t5504-fetch-receive-strict.sh\n>       3 t0028-working-tree-encoding.sh\n>       4 t1000-read-tree-m-3way.sh\n>       6 t4015-diff-whitespace.sh\n>      10 t4024-diff-optimize-common.sh\n>      17 t3030-merge-recursive.sh\n>      17 t3402-rebase-merge.sh\n>      17 t3501-revert-cherry-pick.sh\n>      17 t6022-merge-rename.sh\n>      17 t6032-merge-large-rename.sh\n>      17 t6034-merge-rename-nocruft.sh\n>      17 t6042-merge-rename-corner-cases.sh\n>      17 t6043-merge-rename-directories.sh\n>      17 t6046-merge-skip-unneeded-updates.sh\n>      17 t7003-filter-branch.sh\n>      17 t7601-merge-pull-config.sh\n>      23 t3903-stash.sh\n>\n> I doubt that this racy split index problem is responsible for all\n> these failures; e.g. I looked at the failures of a few merge-related\n> test scripts, and these logs show that they tend to fail because of\n> memory corruption, i.e. with 'Aborted (core dumped)' or 'Segmentation\n> fault (core dumped)'.\n>\n>> To test how this this series improves things, I've been running\n>> this on a 56 core CentOS 7.5 machine:\n>>\n>>     while true; do GIT_TEST_SPLIT_INDEX=yes prove -j$(parallel --number-of-cores) t3903-stash.sh t4024-diff-optimize-common.sh t4015-diff-whitespace.sh t2200-add-update.sh t0090-cache-tree.sh && echo \"OK $(date) $(git describe)\" >>log2 || echo \"FAIL $(date) $(git describe)\" >>log2; done\n>>\n>> While, in another window to get some load on the machine (these seem to\n>> fail more under load):\n>>\n>>     while true; do prove -j$(parallel --number-of-cores) t[156789]*.sh; done\n>>\n>> The results with this series applied up to 4/5. I.e. without the actual\n>> fix:\n>>\n>>      92 OK v2.19.0-rc2-6-ged839bd155\n>>       8 FAIL v2.19.0-rc2-6-ged839bd155\n>>\n>> I.e. when running this 100 times, I got 8 failures. So 8%.\n>\n> Lucky you ;)\n>\n> I could only get t3903 to fail on me, but not the others.  That was\n> enough to eventually track down and fix the problem (fun! ;), and then\n> I looked at the logs of failed git/git Travis CI build jobs to see,\n> what other failures might have been caused by it.\n>\n>> With this patch applied:\n>>\n>>     389 OK v2.19.0-rc2-5-g05a5a13935\n>>      11 FAIL v2.19.0-rc2-5-g05a5a13935\n>>\n>> This time I ran the tests 400 times, and got 11 failures, i.e. a\n>> ~2.8% failure rate. I don't have a full account of what stuff\n>> failed (this was just scrolling past in my terminal), but most\n>> were:\n>>\n>>     t0090-cache-tree.sh          (Wstat: 256 Tests: 21 Failed: 3)\n>>       Failed tests:  10-12\n>>       Non-zero exit status: 1\n>>\n>> I.e. these tests:\n>>\n>>     ok 10 - commit --interactive gives cache-tree on partial commit\n>>     ok 11 - commit in child dir has cache-tree\n>>     ok 12 - reset --hard gives cache-tree\n>\n> But hey, 't0090 --verbose-log -x -i' just failed on me with the fix\n> applied while writing this email, yay!  In its logs I see the\n> following errors in all three tests you mention:\n>\n>   error: index uses ?½þA extension, which we do not understand\n>   fatal: index file corrupt\n>\n> Test 13 then starts with 'rm -f .git/index', and then all is well for\n> the remaining tests.\n>\n> There was a recent discussion about a similar error starting at:\n>\n>   https://public-inbox.org/git/20180901214157.hxlqmbz3fds7hsdl@ltop.local/\n>\n> and leading to a fix in 6c003d6ffb (reopen_tempfile(): truncate opened\n> file, 2018-09-04).  I certainly hope that not my fix is buggy, but\n> combined with 'GIT_TEST_SPLIT_INDEX=yes' it can occasionally trigger\n> the same error, and Peff's (Cc'd) fix will resolve it as well.\n>\n> Could you run your stress tests with Peff's fix merged with mine?\n> Apparetly your setup is much more capable of triggering these issues\n> than mine...\n\nI get the same sort of thing on t0090-cache-tree.sh with -v -x,\ni.e. failures due to:\n\n    error: index uses �)�? extension, which we do not understand\n    fatal: index file corrupt\n\nIt turns out that my inability to reproduce that earlier was because I'd\nforgotten to set GIT_TEST_SPLIT_INDEX=yes in the environment for that\nwhile loop, so I wasn't testing the split index at all.\n\nI'm now running the tests in a lop with 6c003d6ffb cherry-picked on\ntop. I'll report back when I have enough data to say if/how it helped.\n"},{"id":"357553","messageId":"87k1nyqzq2.fsf@evledraar.gmail.com","threadId":"49290","inReplyTo":"87lg8er6ir.fsf@evledraar.gmail.com","subject":"Re: [RFC PATCH 5/5] split-index: smudge and add racily clean cache entries to split index","fromName":"Ævar Arnfjörð Bjarmason","fromEmail":"avarab@gmail.com","sentAt":"2018-09-06T17:53:41Z","receivedAt":"2018-09-06T17:53:48Z","isPatch":true,"sender":{"key":"avarab@gmail.com","avatar":"https://avatars.githubusercontent.com/u/45301?v=4"},"body":"\nOn Thu, Sep 06 2018, Ævar Arnfjörð Bjarmason wrote:\n\n> On Thu, Sep 06 2018, SZEDER Gábor wrote:\n>\n>> On Thu, Sep 06, 2018 at 02:26:49PM +0200, Ævar Arnfjörð Bjarmason wrote:\n>>>\n>>> On Thu, Sep 06 2018, SZEDER Gábor wrote:\n>>> > Several tests failed occasionally when the test suite was run with\n>>> > 'GIT_TEST_SPLIT_INDEX=yes'.  Here are those that I managed to trace\n>>> > back to this racy split index problem, starting with those failing\n>>> > more frequently, with a link to a failing Travis CI build job for\n>>> > each.  The highlighted line shows when the racy file was written,\n>>> > which is not always in the failing test (but note that those lines are\n>>> > in the 'after failure' fold, and your browser might unhelpfully fold\n>>> > it up before you could take a good look).\n>>>\n>>> Thanks for working on this. When I package up git I run the tests\n>>> under a few different modes, in the case of split index I've been\n>>> doing:\n>>>\n>>>     GIT_TEST_SPLIT_INDEX=true GIT_SKIP_TESTS=\"t3903 t4015.77\"\n>>\n>> Yeah, I noticed that you mentioned this in an unrelated thread the\n>> other day, that's why I put you on Cc.  ... and that's why I pulled\n>> this series from the backburner and cleaned it up for submission.\n>> (Gah, most of these commits have an author date back in February...)\n>>\n>>> Since those were the ones I spotted failing under that mode, but\n>>> I still had occasional other failures, I don't have a record of\n>>> which, maybe some of these other tests you mention, maybe not.\n>>\n>> I poked around the Travis CI API, and managed to get the logs of all\n>> build jobs that failed with 'GIT_TEST_SPLIT_INDEX=yes' but succeeded\n>> without it.  Here is the list of failed test scripts, along with how\n>> many times they failed:\n>>\n>>       1 t0027-auto-crlf.sh\n>>       1 t0090-cache-tree.sh\n>>       1 t3404-rebase-interactive.sh\n>>       1 t5520-pull.sh\n>>       1 t5573-pull-verify-signatures.sh\n>>       1 t5608-clone-2gb.sh\n>>       1 t7406-submodule-update.sh\n>>       2 t2200-add-update.sh\n>>       2 t4002-diff-basic.sh\n>>       2 t5504-fetch-receive-strict.sh\n>>       3 t0028-working-tree-encoding.sh\n>>       4 t1000-read-tree-m-3way.sh\n>>       6 t4015-diff-whitespace.sh\n>>      10 t4024-diff-optimize-common.sh\n>>      17 t3030-merge-recursive.sh\n>>      17 t3402-rebase-merge.sh\n>>      17 t3501-revert-cherry-pick.sh\n>>      17 t6022-merge-rename.sh\n>>      17 t6032-merge-large-rename.sh\n>>      17 t6034-merge-rename-nocruft.sh\n>>      17 t6042-merge-rename-corner-cases.sh\n>>      17 t6043-merge-rename-directories.sh\n>>      17 t6046-merge-skip-unneeded-updates.sh\n>>      17 t7003-filter-branch.sh\n>>      17 t7601-merge-pull-config.sh\n>>      23 t3903-stash.sh\n>>\n>> I doubt that this racy split index problem is responsible for all\n>> these failures; e.g. I looked at the failures of a few merge-related\n>> test scripts, and these logs show that they tend to fail because of\n>> memory corruption, i.e. with 'Aborted (core dumped)' or 'Segmentation\n>> fault (core dumped)'.\n>>\n>>> To test how this this series improves things, I've been running\n>>> this on a 56 core CentOS 7.5 machine:\n>>>\n>>>     while true; do GIT_TEST_SPLIT_INDEX=yes prove -j$(parallel --number-of-cores) t3903-stash.sh t4024-diff-optimize-common.sh t4015-diff-whitespace.sh t2200-add-update.sh t0090-cache-tree.sh && echo \"OK $(date) $(git describe)\" >>log2 || echo \"FAIL $(date) $(git describe)\" >>log2; done\n>>>\n>>> While, in another window to get some load on the machine (these seem to\n>>> fail more under load):\n>>>\n>>>     while true; do prove -j$(parallel --number-of-cores) t[156789]*.sh; done\n>>>\n>>> The results with this series applied up to 4/5. I.e. without the actual\n>>> fix:\n>>>\n>>>      92 OK v2.19.0-rc2-6-ged839bd155\n>>>       8 FAIL v2.19.0-rc2-6-ged839bd155\n>>>\n>>> I.e. when running this 100 times, I got 8 failures. So 8%.\n>>\n>> Lucky you ;)\n>>\n>> I could only get t3903 to fail on me, but not the others.  That was\n>> enough to eventually track down and fix the problem (fun! ;), and then\n>> I looked at the logs of failed git/git Travis CI build jobs to see,\n>> what other failures might have been caused by it.\n>>\n>>> With this patch applied:\n>>>\n>>>     389 OK v2.19.0-rc2-5-g05a5a13935\n>>>      11 FAIL v2.19.0-rc2-5-g05a5a13935\n>>>\n>>> This time I ran the tests 400 times, and got 11 failures, i.e. a\n>>> ~2.8% failure rate. I don't have a full account of what stuff\n>>> failed (this was just scrolling past in my terminal), but most\n>>> were:\n>>>\n>>>     t0090-cache-tree.sh          (Wstat: 256 Tests: 21 Failed: 3)\n>>>       Failed tests:  10-12\n>>>       Non-zero exit status: 1\n>>>\n>>> I.e. these tests:\n>>>\n>>>     ok 10 - commit --interactive gives cache-tree on partial commit\n>>>     ok 11 - commit in child dir has cache-tree\n>>>     ok 12 - reset --hard gives cache-tree\n>>\n>> But hey, 't0090 --verbose-log -x -i' just failed on me with the fix\n>> applied while writing this email, yay!  In its logs I see the\n>> following errors in all three tests you mention:\n>>\n>>   error: index uses ?½þA extension, which we do not understand\n>>   fatal: index file corrupt\n>>\n>> Test 13 then starts with 'rm -f .git/index', and then all is well for\n>> the remaining tests.\n>>\n>> There was a recent discussion about a similar error starting at:\n>>\n>>   https://public-inbox.org/git/20180901214157.hxlqmbz3fds7hsdl@ltop.local/\n>>\n>> and leading to a fix in 6c003d6ffb (reopen_tempfile(): truncate opened\n>> file, 2018-09-04).  I certainly hope that not my fix is buggy, but\n>> combined with 'GIT_TEST_SPLIT_INDEX=yes' it can occasionally trigger\n>> the same error, and Peff's (Cc'd) fix will resolve it as well.\n>>\n>> Could you run your stress tests with Peff's fix merged with mine?\n>> Apparetly your setup is much more capable of triggering these issues\n>> than mine...\n>\n> I get the same sort of thing on t0090-cache-tree.sh with -v -x,\n> i.e. failures due to:\n>\n>     error: index uses �)�? extension, which we do not understand\n>     fatal: index file corrupt\n>\n> It turns out that my inability to reproduce that earlier was because I'd\n> forgotten to set GIT_TEST_SPLIT_INDEX=yes in the environment for that\n> while loop, so I wasn't testing the split index at all.\n>\n> I'm now running the tests in a lop with 6c003d6ffb cherry-picked on\n> top. I'll report back when I have enough data to say if/how it helped.\n\nI got 436 OK runs with that and 3 failures before I gave up and ctrl+c'd\nit. And the 3 failures were:\n\n    t3903-stash.sh               (Wstat: 256 Tests: 90 Failed: 1)\n      Failed test:  55\n      Non-zero exit status: 1\n\nSo it's back to failing on the same test as before your patches.\n\nI did try merging in \"pu\" to get git-stash in C. There I had 2 failures\nand 135 OK before I gave up. The C version failed tests 5 & 20, so there\nmay be some new regressions in the C version related to this.\n"},{"id":"357585","messageId":"xmqq5zziz5du.fsf@gitster-ct.c.googlers.com","threadId":"49290","inReplyTo":"20180906024810.8074-2-szeder.dev@gmail.com","subject":"Re: [PATCH 1/5] t1700-split-index: drop unnecessary 'grep'","fromName":"Junio C Hamano","fromEmail":"gitster@pobox.com","sentAt":"2018-09-06T21:24:13Z","receivedAt":"2018-09-06T21:24:18Z","isPatch":true,"sender":{"key":"gitster@pobox.com","avatar":"https://avatars.githubusercontent.com/u/54884?v=4"},"body":"SZEDER Gábor <szeder.dev@gmail.com> writes:\n\n> The test 'disable split index' in 't1700-split-index.sh' runs the\n> following pipeline:\n>\n>   cmd | grep <pattern> | sed s///\n>\n> Drop that 'grep' from the pipeline, and let 'sed' take over its\n> duties.\n>\n> Signed-off-by: SZEDER Gábor <szeder.dev@gmail.com>\n> ---\n\nObviously good ;-)  Thanks.\n\n\n>  t/t1700-split-index.sh | 2 +-\n>  1 file changed, 1 insertion(+), 1 deletion(-)\n>\n> diff --git a/t/t1700-split-index.sh b/t/t1700-split-index.sh\n> index b3b4d83eaf..be22398a85 100755\n> --- a/t/t1700-split-index.sh\n> +++ b/t/t1700-split-index.sh\n> @@ -57,7 +57,7 @@ test_expect_success 'disable split index' '\n>  \tEOF\n>  \ttest_cmp ls-files.expect ls-files.actual &&\n>  \n> -\tBASE=$(test-tool dump-split-index .git/index | grep \"^own\" | sed \"s/own/base/\") &&\n> +\tBASE=$(test-tool dump-split-index .git/index | sed -n \"s/^own/base/p\") &&\n>  \ttest-tool dump-split-index .git/index | sed \"/^own/d\" >actual &&\n>  \tcat >expect <<-EOF &&\n>  \tnot a split index\n"},{"id":"357604","messageId":"20180907034942.GA10370@localhost","threadId":"49290","inReplyTo":"87k1nyqzq2.fsf@evledraar.gmail.com","subject":"Re: [RFC PATCH 5/5] split-index: smudge and add racily clean cache entries to split index","fromName":"SZEDER Gábor","fromEmail":"szeder.dev@gmail.com","sentAt":"2018-09-07T03:49:42Z","receivedAt":"2018-09-07T03:49:53Z","isPatch":true,"sender":{"key":"szeder.dev@gmail.com","avatar":"https://avatars.githubusercontent.com/u/116324?v=4"},"body":"On Thu, Sep 06, 2018 at 07:53:41PM +0200, Ævar Arnfjörð Bjarmason wrote:\n> I got 436 OK runs with that and 3 failures before I gave up and ctrl+c'd\n> it. And the 3 failures were:\n> \n>     t3903-stash.sh               (Wstat: 256 Tests: 90 Failed: 1)\n>       Failed test:  55\n>       Non-zero exit status: 1\n> \n> So it's back to failing on the same test as before your patches.\n\nAh, what a pity :)\n\nLuckily, the tests in t3903 are mostly self-contained, and copying\ntest #55 into a dedicated test script still works.  Then running it\nrepeatedly is much faster than running the whole t3903, and failed in\na reasonable amount of time.  I could then eventually narrow it down\nto the diff below, which fails rather reliably, in fact I've yet to\nsee it succeed.  Unfortunately, 'git stash' is rather busy with index\noperations, and I couldn't figure out yet what exactly goes wrong or\nhow to turn it into a proper test.\n\n\ndiff --git a/git-stash.sh b/git-stash.sh\nindex 94793c1a91..04fa2a4f43 100755\n--- a/git-stash.sh\n+++ b/git-stash.sh\n@@ -328,6 +328,7 @@ push_stash () {\n \t\t\tgit diff-index -p --cached --binary HEAD -- \"$@\" |\n \t\t\tgit apply --index -R\n \t\telse\n+\t\t\tGIT_TEST_SPLIT_INDEX=yes \\\n \t\t\tgit reset --hard -q\n \t\tfi\n \n@@ -671,6 +672,7 @@ apply_to_branch () {\n \tset -- --index \"$@\"\n \tassert_stash_like \"$@\"\n \n+\tsleep 1\n \tgit checkout -b $branch $REV^ &&\n \tapply_stash \"$@\" && {\n \t\ttest -z \"$IS_STASH_REF\" || drop_stash \"$@\"\ndiff --git a/read-cache.c b/read-cache.c\nindex 8f644f68b4..9f39f29221 100644\n--- a/read-cache.c\n+++ b/read-cache.c\n@@ -2761,9 +2761,8 @@ int write_locked_index(struct index_state *istate, struct lock_file *lock,\n \t}\n \n \tif (git_env_bool(\"GIT_TEST_SPLIT_INDEX\", 0)) {\n-\t\tint v = si->base_oid.hash[0];\n-\t\tif ((v & 15) < 6)\n-\t\t\tistate->cache_changed |= SPLIT_INDEX_ORDERED;\n+\t\t/* always split, to make it more deterministic */\n+\t\tistate->cache_changed |= SPLIT_INDEX_ORDERED;\n \t}\n \tif (too_many_not_shared_entries(istate))\n \t\tistate->cache_changed |= SPLIT_INDEX_ORDERED;\ndiff --git a/t/t9999-stash-vs-split-index.sh b/t/t9999-stash-vs-split-index.sh\nnew file mode 100755\nindex 0000000000..bc2b7ccf6b\n--- /dev/null\n+++ b/t/t9999-stash-vs-split-index.sh\n@@ -0,0 +1,20 @@\n+test_description='stash vs. split index'\n+\n+. ./test-lib.sh\n+\n+test_expect_success 'stash vs. split index' '\n+\tsane_unset GIT_TEST_SPLIT_INDEX &&\n+\tgit config splitIndex.maxPercentChange 100 &&\n+\n+\techo foo >file &&\n+\tGIT_TEST_SPLIT_INDEX=yes git add file &&\n+\tgit commit -m initial &&\n+\techo bar >file &&\n+\tgit stash &&\n+\techo baz >file &&\n+\ttest_when_finished \"git checkout master\" &&\n+\ttest_must_fail git stash branch new_branch stash@{0} &&\n+\tgit rev-parse stash@{0} --\n+'\n+\n+test_done\n-- \n2.19.0.rc2.140.g09cf9e37c9\n\n"},{"id":"357693","messageId":"CACsJy8DKOvFj-V81HJQ+0Nx9QkeZ9MqrTPWJ4kDvJmbt+E4o_g@mail.gmail.com","threadId":"49290","inReplyTo":"20180906024810.8074-2-szeder.dev@gmail.com","subject":"Re: [PATCH 1/5] t1700-split-index: drop unnecessary 'grep'","fromName":"Duy Nguyen","fromEmail":"pclouds@gmail.com","sentAt":"2018-09-08T13:50:37Z","receivedAt":"2018-09-08T13:51:05Z","isPatch":true,"sender":{"key":"pclouds@gmail.com","avatar":"https://avatars.githubusercontent.com/u/720?v=4"},"body":"On Thu, Sep 6, 2018 at 4:48 AM SZEDER Gábor <szeder.dev@gmail.com> wrote:\n>\n> The test 'disable split index' in 't1700-split-index.sh' runs the\n> following pipeline:\n>\n>   cmd | grep <pattern> | sed s///\n>\n> Drop that 'grep' from the pipeline, and let 'sed' take over its\n> duties.\n\nYears of using sed and I never realized -n could simplify this\npattern. Thank you.\n-- \nDuy\n"},{"id":"357701","messageId":"CACsJy8CAPcD7pHgV-KWb39cFAvL1Yn+89y5znhcOgTG8O57w_A@mail.gmail.com","threadId":"49290","inReplyTo":"20180906024810.8074-6-szeder.dev@gmail.com","subject":"Re: [RFC PATCH 5/5] split-index: smudge and add racily clean cache entries to split index","fromName":"Duy Nguyen","fromEmail":"pclouds@gmail.com","sentAt":"2018-09-08T16:45:46Z","receivedAt":"2018-09-08T16:49:16Z","isPatch":true,"sender":{"key":"pclouds@gmail.com","avatar":"https://avatars.githubusercontent.com/u/720?v=4"},"body":"On Thu, Sep 6, 2018 at 4:48 AM SZEDER Gábor <szeder.dev@gmail.com> wrote:\n>\n> Ever since the split index feature was introduced [1], refreshing a\n> split index is prone to a variant of the classic racy git problem.\n>\n> Consider the following sequence of commands updating the split index\n> when the shared index contains a racily clean cache entry, i.e. an\n> entry whose cached stat data matches with the corresponding file in\n> the worktree and the cached mtime matches that of the index:\n>\n>   echo \"cached content\" >file\n>   git update-index --split-index --add file\n>   echo \"dirty worktree\" >file    # size stays the same!\n>   # ... wait ...\n>   git update-index --add other-file\n>\n> Normally, when a non-split index is updated, then do_write_index()\n> (the function responsible for writing all kinds of indexes, \"regular\",\n> split, and shared) recognizes racily clean cache entries, and writes\n> them with smudged stat data, i.e. with file size set to 0.  When\n> subsequent git commands read the index, they will notice that the\n> smudged stat data doesn't match with the file in the worktree, and\n> then go on to check the file's content.\n>\n> In the above example, however, in the second 'git update-index'\n> prepare_to_write_split_index() gathers all cache entries that should\n> be written to the new split index.  Alas, this function never looks\n> out for racily clean cache entries, and since the file's stat data in\n> the worktree hasn't changed since the shared index was written, it\n> won't be replaced in the new split index.  Consequently,\n> do_write_index() doesn't even get this racily clean cache entry, and\n> can't smudge its stat data.  Subsequent git commands will then see\n> that the index has more recent mtime than the file and that the (not\n> smudged) cached stat data still matches with the file in the worktree,\n> and, ultimately, will erroneously consider the file clean.\n>\n> Modify prepare_to_write_split_index() to recognize racily clean cache\n> entries, and mark them to be added to the split index.  This way\n> do_write_index() will get these racily clean cache entries as well,\n> and will then write them with smudged stat data to the new split\n> index.\n\nAck. I was aware of the first half of of the racy solution but did not\npay attention to this smudging business.\n\nI wonder if untracked cache is also racy like this. It also only has\nhalf the racy solution because I only knew that much. I'll check this\nlater.\n\n> Note that after this change if the index is split when it contains a\n> racily clean cache entry, then a smudged cache entry will be written\n> both to the new shared and to the new split indexes.  This doesn't\n> affect regular git commands: as far as they are concerned this is just\n> an entry in the split index replacing an outdated entry in the shared\n> index.  It did affect a few tests in 't1700-split-index.sh', though,\n> because they actually check which entries are stored in the split\n> index; the previous patch made the necessary adjustments.  And racily\n> clean cache entries and index splitting are rare enough to not worry\n> about the resulting duplicated smudged cache entries, and the\n> additional complexity required to prevent them is not worth it.\n\nYes. If we have to make updates (racy or not) we have to make updates,\nand the version in the shared index becomes obsolete by design.\n-- \nDuy\n"},{"id":"357838","messageId":"c7343fc4-b7ad-6c39-33bb-5b9d50bffb8d@gmail.com","threadId":"49290","inReplyTo":"87k1nyqzq2.fsf@evledraar.gmail.com","subject":"Re: [RFC PATCH 5/5] split-index: smudge and add racily clean cache entries to split index","fromName":"Paul-Sebastian Ungureanu","fromEmail":"ungureanupaulsebastian@gmail.com","sentAt":"2018-09-10T22:12:35Z","receivedAt":"2018-09-10T22:12:40Z","isPatch":true,"sender":{"key":"ungureanupaulsebastian@gmail.com","avatar":"https://avatars.githubusercontent.com/u/24317622?v=4"},"body":"Hello,\n\nOn 06.09.2018 20:53, Ævar Arnfjörð Bjarmason wrote:\n> \n> On Thu, Sep 06 2018, Ævar Arnfjörð Bjarmason wrote:\n> \n>> On Thu, Sep 06 2018, SZEDER Gábor wrote:\n>>\n>>> On Thu, Sep 06, 2018 at 02:26:49PM +0200, Ævar Arnfjörð Bjarmason wrote:\n>>>>\n>>>> On Thu, Sep 06 2018, SZEDER Gábor wrote:\n>>>>> Several tests failed occasionally when the test suite was run with\n>>>>> 'GIT_TEST_SPLIT_INDEX=yes'.  Here are those that I managed to trace\n>>>>> back to this racy split index problem, starting with those failing\n>>>>> more frequently, with a link to a failing Travis CI build job for\n>>>>> each.  The highlighted line shows when the racy file was written,\n>>>>> which is not always in the failing test (but note that those lines are\n>>>>> in the 'after failure' fold, and your browser might unhelpfully fold\n>>>>> it up before you could take a good look).\n>>>>\n>>>> Thanks for working on this. When I package up git I run the tests\n>>>> under a few different modes, in the case of split index I've been\n>>>> doing:\n>>>>\n>>>>      GIT_TEST_SPLIT_INDEX=true GIT_SKIP_TESTS=\"t3903 t4015.77\"\n>>>\n>>> Yeah, I noticed that you mentioned this in an unrelated thread the\n>>> other day, that's why I put you on Cc.  ... and that's why I pulled\n>>> this series from the backburner and cleaned it up for submission.\n>>> (Gah, most of these commits have an author date back in February...)\n>>>\n>>>> Since those were the ones I spotted failing under that mode, but\n>>>> I still had occasional other failures, I don't have a record of\n>>>> which, maybe some of these other tests you mention, maybe not.\n>>>\n>>> I poked around the Travis CI API, and managed to get the logs of all\n>>> build jobs that failed with 'GIT_TEST_SPLIT_INDEX=yes' but succeeded\n>>> without it.  Here is the list of failed test scripts, along with how\n>>> many times they failed:\n>>>\n>>>        1 t0027-auto-crlf.sh\n>>>        1 t0090-cache-tree.sh\n>>>        1 t3404-rebase-interactive.sh\n>>>        1 t5520-pull.sh\n>>>        1 t5573-pull-verify-signatures.sh\n>>>        1 t5608-clone-2gb.sh\n>>>        1 t7406-submodule-update.sh\n>>>        2 t2200-add-update.sh\n>>>        2 t4002-diff-basic.sh\n>>>        2 t5504-fetch-receive-strict.sh\n>>>        3 t0028-working-tree-encoding.sh\n>>>        4 t1000-read-tree-m-3way.sh\n>>>        6 t4015-diff-whitespace.sh\n>>>       10 t4024-diff-optimize-common.sh\n>>>       17 t3030-merge-recursive.sh\n>>>       17 t3402-rebase-merge.sh\n>>>       17 t3501-revert-cherry-pick.sh\n>>>       17 t6022-merge-rename.sh\n>>>       17 t6032-merge-large-rename.sh\n>>>       17 t6034-merge-rename-nocruft.sh\n>>>       17 t6042-merge-rename-corner-cases.sh\n>>>       17 t6043-merge-rename-directories.sh\n>>>       17 t6046-merge-skip-unneeded-updates.sh\n>>>       17 t7003-filter-branch.sh\n>>>       17 t7601-merge-pull-config.sh\n>>>       23 t3903-stash.sh\n>>>\n>>> I doubt that this racy split index problem is responsible for all\n>>> these failures; e.g. I looked at the failures of a few merge-related\n>>> test scripts, and these logs show that they tend to fail because of\n>>> memory corruption, i.e. with 'Aborted (core dumped)' or 'Segmentation\n>>> fault (core dumped)'.\n>>>\n>>>> To test how this this series improves things, I've been running\n>>>> this on a 56 core CentOS 7.5 machine:\n>>>>\n>>>>      while true; do GIT_TEST_SPLIT_INDEX=yes prove -j$(parallel --number-of-cores) t3903-stash.sh t4024-diff-optimize-common.sh t4015-diff-whitespace.sh t2200-add-update.sh t0090-cache-tree.sh && echo \"OK $(date) $(git describe)\" >>log2 || echo \"FAIL $(date) $(git describe)\" >>log2; done\n>>>>\n>>>> While, in another window to get some load on the machine (these seem to\n>>>> fail more under load):\n>>>>\n>>>>      while true; do prove -j$(parallel --number-of-cores) t[156789]*.sh; done\n>>>>\n>>>> The results with this series applied up to 4/5. I.e. without the actual\n>>>> fix:\n>>>>\n>>>>       92 OK v2.19.0-rc2-6-ged839bd155\n>>>>        8 FAIL v2.19.0-rc2-6-ged839bd155\n>>>>\n>>>> I.e. when running this 100 times, I got 8 failures. So 8%.\n>>>\n>>> Lucky you ;)\n>>>\n>>> I could only get t3903 to fail on me, but not the others.  That was\n>>> enough to eventually track down and fix the problem (fun! ;), and then\n>>> I looked at the logs of failed git/git Travis CI build jobs to see,\n>>> what other failures might have been caused by it.\n>>>\n>>>> With this patch applied:\n>>>>\n>>>>      389 OK v2.19.0-rc2-5-g05a5a13935\n>>>>       11 FAIL v2.19.0-rc2-5-g05a5a13935\n>>>>\n>>>> This time I ran the tests 400 times, and got 11 failures, i.e. a\n>>>> ~2.8% failure rate. I don't have a full account of what stuff\n>>>> failed (this was just scrolling past in my terminal), but most\n>>>> were:\n>>>>\n>>>>      t0090-cache-tree.sh          (Wstat: 256 Tests: 21 Failed: 3)\n>>>>        Failed tests:  10-12\n>>>>        Non-zero exit status: 1\n>>>>\n>>>> I.e. these tests:\n>>>>\n>>>>      ok 10 - commit --interactive gives cache-tree on partial commit\n>>>>      ok 11 - commit in child dir has cache-tree\n>>>>      ok 12 - reset --hard gives cache-tree\n>>>\n>>> But hey, 't0090 --verbose-log -x -i' just failed on me with the fix\n>>> applied while writing this email, yay!  In its logs I see the\n>>> following errors in all three tests you mention:\n>>>\n>>>    error: index uses ?½þA extension, which we do not understand\n>>>    fatal: index file corrupt\n>>>\n>>> Test 13 then starts with 'rm -f .git/index', and then all is well for\n>>> the remaining tests.\n>>>\n>>> There was a recent discussion about a similar error starting at:\n>>>\n>>>    https://public-inbox.org/git/20180901214157.hxlqmbz3fds7hsdl@ltop.local/\n>>>\n>>> and leading to a fix in 6c003d6ffb (reopen_tempfile(): truncate opened\n>>> file, 2018-09-04).  I certainly hope that not my fix is buggy, but\n>>> combined with 'GIT_TEST_SPLIT_INDEX=yes' it can occasionally trigger\n>>> the same error, and Peff's (Cc'd) fix will resolve it as well.\n>>>\n>>> Could you run your stress tests with Peff's fix merged with mine?\n>>> Apparetly your setup is much more capable of triggering these issues\n>>> than mine...\n>>\n>> I get the same sort of thing on t0090-cache-tree.sh with -v -x,\n>> i.e. failures due to:\n>>\n>>      error: index uses �)�? extension, which we do not understand\n>>      fatal: index file corrupt\n>>\n>> It turns out that my inability to reproduce that earlier was because I'd\n>> forgotten to set GIT_TEST_SPLIT_INDEX=yes in the environment for that\n>> while loop, so I wasn't testing the split index at all.\n>>\n>> I'm now running the tests in a lop with 6c003d6ffb cherry-picked on\n>> top. I'll report back when I have enough data to say if/how it helped.\n> \n> I got 436 OK runs with that and 3 failures before I gave up and ctrl+c'd\n> it. And the 3 failures were:\n> \n>      t3903-stash.sh               (Wstat: 256 Tests: 90 Failed: 1)\n>        Failed test:  55\n>        Non-zero exit status: 1\n> \n> So it's back to failing on the same test as before your patches.\n> \n> I did try merging in \"pu\" to get git-stash in C. There I had 2 failures\n> and 135 OK before I gave up. The C version failed tests 5 & 20, so there\n> may be some new regressions in the C version related to this.\n> \n\nSorry for late replay. I have been pretty busy these days.\n\nIndeed, test 5 & 20 also causes problems for me. I tried to find the \nroot cause, but, unfortunately, I couldn't.\n\nFor test 5 (`apply does not clobber working directory changes`), it \nseems that `git stash apply` works when it should fail.\n\nWhen test 20 (`stash -k`) fails it acts like `-k` wasn't specified. In \nthe following code path (or Github link below), it seems that `out` is \nnot filled with names of modified files.\n\n\tcp1.git_cmd = 1;\n\targv_array_pushl(&cp1.args, \"ls-files\", \"-z\",\n\t\t\t \"--modified\", \"--\", NULL);\n\tadd_pathspecs(&cp1.args, ps);\n\tif (pipe_command(&cp1, NULL, 0, &out, 0, NULL, 0)) {\n\t\tret = -1;\n\t\tgoto done;\n\t}\n\nGithub link: \nhttps://github.com/ungps/git/blob/git-stash/builtin/stash.c#L1358\n\nI will look more into it tomorrow.\n\nBest,\nPaul\n"}]}