Subject: [PATCH v2] t6022, t6046: fix flaky files-are-updated checks

From: "Elijah Newren via GitGitGadget" <[email-masked]>
Date: Fri, 13 Mar 2020 20:03:02 +0000

From: Elijah Newren <[email-masked]>

Several tests wanted to verify that files were actually modified by a
merge, which it would do by checking that the mtime was updated.  In
order to avoid problems with the merge completing so fast that the mtime
at the beginning and end of the operation was the same, these tests
would first set the mtime of a file to something "old".  This "old"
value was usually determined as current system clock minus one second,
truncated to the nearest integer.  Unfortunately, it appears the system
clock and filesystem clock are different and comparing across the two
runs into race problems resulting in flaky tests.

>From https://stackoverflow.com/questions/14392975/timestamp-accuracy-on-ext4-sub-millsecond:

    date will call the gettimeofday system call which will always return
    the most accurate time available based on the cached kernel time,
    adjusted by the CPU cycle time if available to give nanosecond
    resolution. The timestamps stored in the file system however, are
    only based on the cached kernel time. ie The time calculated at the
    last timer interrupt.

and from https://apenwarr.ca/log/20181113:

    Does mtime get set to >= the current time?

    No, this depends on clock granularity. For example, gettimeofday()
    can return times in microseconds on my system, but ext4 rounds
    timestamps down to the previous ~10ms (but not exactly 10ms)
    increment, with the surprising result that a newly-created file is
    almost always created in the past:

      $ python -c "
      import os, time
      t0 = time.time()
      open('testfile', 'w').close()
      print os.stat('testfile').st_mtime - t0
      "

      -0.00234484672546

So, instead of trying to compare across what are effectively two
different clocks, just avoid using the system clock.  Any new updates to
files have to give an mtime at least as big as what is already in the
file, so we could define "old" as one second before the mtime found in
the file before the merge starts.  But, to avoid problems with leap
seconds, ntp updates, filesystems that only provide two second
resolution, and other such weirdness, let's just pick an hour before the
mtime found in the file before the merge starts.

Also, clarify in one test where we check the mtime of different files
that it really was intentional.  I totally forgot the reasons for that
and assumed it was a bug when asked.

Reported-by: SZEDER Gábor <[email-masked]>
Signed-off-by: Elijah Newren <[email-masked]>
---
    t6022, t6046: fix flaky files-are-updated checks
    
    Who knew that the system clock and the filesystem clock were apparently
    different things, causing mtime comparisons to be flaky?
    
    Definitely not me. Fix the flaky tests that SZEDER reported and helped
    track down the cause of.

Published-As: https://github.com/gitgitgadget/git/releases/tag/pr-git-725%2Fnewren%2Ftest-cleanup-more-v2
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-git-725/newren/test-cleanup-more-v2
Pull-Request: https://github.com/git/git/pull/725

Range-diff vs v1:

 1:  dfe1f66112b ! 1:  6f603695093 t6022, t6046: fix flaky files-are-updated checks
     @@ -43,8 +43,11 @@
          So, instead of trying to compare across what are effectively two
          different clocks, just avoid using the system clock.  Any new updates to
          files have to give an mtime at least as big as what is already in the
     -    file, so define "old" as one second before the mtime found in the file
     -    before the merge starts.
     +    file, so we could define "old" as one second before the mtime found in
     +    the file before the merge starts.  But, to avoid problems with leap
     +    seconds, ntp updates, filesystems that only provide two second
     +    resolution, and other such weirdness, let's just pick an hour before the
     +    mtime found in the file before the merge starts.
      
          Also, clarify in one test where we check the mtime of different files
          that it really was intentional.  I totally forgot the reasons for that
     @@ -62,7 +65,7 @@
       
      -	test-tool chmtime =31337 B &&
      -	test-tool chmtime --get B >old-mtime &&
     -+	test-tool chmtime --get -1 B >old-mtime &&
     ++	test-tool chmtime --get -3600 B >old-mtime &&
       	GIT_MERGE_VERBOSITY=3 git merge change >out &&
       
       	test-tool chmtime --get B >new-mtime &&
     @@ -74,7 +77,7 @@
      -	test-tool chmtime --get M >old-mtime &&
      +	# A will be renamed to B; we check mtimes and file presence
      +	test_path_is_missing B &&
     -+	test-tool chmtime --get -1 A >old-mtime &&
     ++	test-tool chmtime --get -3600 A >old-mtime &&
       	GIT_MERGE_VERBOSITY=3 git merge change+rename >out &&
       
      +	test_path_is_missing A &&
     @@ -86,7 +89,7 @@
       test_expect_success 'avoid unnecessary update, normal rename' '
       	git checkout -q avoid-unnecessary-update-1^0 &&
      -	test-tool chmtime --get =1000000000 rename >expect &&
     -+	test-tool chmtime --get -1 rename >expect &&
     ++	test-tool chmtime --get -3600 rename >expect &&
       	git merge merge-branch-1 &&
       	test-tool chmtime --get rename >actual &&
       	test_cmp expect actual # "rename" should have stayed intact
     @@ -95,7 +98,7 @@
       test_expect_success 'avoid unnecessary update, with D/F conflict' '
       	git checkout -q avoid-unnecessary-update-2^0 &&
      -	test-tool chmtime --get =1000000000 df >expect &&
     -+	test-tool chmtime --get -1 df >expect &&
     ++	test-tool chmtime --get -3600 df >expect &&
       	git merge merge-branch-2 &&
       	test-tool chmtime --get df >actual &&
       	test_cmp expect actual # "df" should have stayed intact
     @@ -104,7 +107,7 @@
       test_expect_success 'avoid unnecessary update, dir->(file,nothing)' '
       	git checkout -q master^0 &&
      -	test-tool chmtime --get =1000000000 df >expect &&
     -+	test-tool chmtime --get -1 df >expect &&
     ++	test-tool chmtime --get -3600 df >expect &&
       	git merge side &&
       	test-tool chmtime --get df >actual &&
       	test_cmp expect actual # "df" should have stayed intact
     @@ -113,7 +116,7 @@
       test_expect_success 'avoid unnecessary update, modify/delete' '
       	git checkout -q master^0 &&
      -	test-tool chmtime --get =1000000000 file >expect &&
     -+	test-tool chmtime --get -1 file >expect &&
     ++	test-tool chmtime --get -3600 file >expect &&
       	test_must_fail git merge side &&
       	test-tool chmtime --get file >actual &&
       	test_cmp expect actual # "file" should have stayed intact
     @@ -122,7 +125,7 @@
       test_expect_success 'avoid unnecessary update, rename/add-dest' '
       	git checkout -q master^0 &&
      -	test-tool chmtime --get =1000000000 newfile >expect &&
     -+	test-tool chmtime --get -1 newfile >expect &&
     ++	test-tool chmtime --get -3600 newfile >expect &&
       	git merge side &&
       	test-tool chmtime --get newfile >actual &&
       	test_cmp expect actual # "file" should have stayed intact
     @@ -136,7 +139,7 @@
       
      -		test-tool chmtime =-1 b &&
      -		test-tool chmtime --get b >old-mtime &&
     -+		test-tool chmtime --get -1 b >old-mtime &&
     ++		test-tool chmtime --get -3600 b >old-mtime &&
       
       		GIT_MERGE_VERBOSITY=3 git merge -s recursive B^0 >out 2>err &&
       
     @@ -146,7 +149,7 @@
       
      -		test-tool chmtime =-1 b &&
      -		test-tool chmtime --get b >old-mtime &&
     -+		test-tool chmtime --get -1 b >old-mtime &&
     ++		test-tool chmtime --get -3600 b >old-mtime &&
       		GIT_MERGE_VERBOSITY=3 git merge -s recursive A^0 >out 2>err &&
       
       		# Make sure b WAS updated
     @@ -156,7 +159,7 @@
       
      -		test-tool chmtime =-1 c &&
      -		test-tool chmtime --get c >old-mtime &&
     -+		test-tool chmtime --get -1 c >old-mtime &&
     ++		test-tool chmtime --get -3600 c >old-mtime &&
       		GIT_MERGE_VERBOSITY=3 git merge -s recursive A^0 >out 2>err &&
       
       		# Make sure c WAS updated
     @@ -166,7 +169,7 @@
       
      -		test-tool chmtime =-1 c &&
      -		test-tool chmtime --get c >old-mtime &&
     -+		test-tool chmtime --get -1 c >old-mtime &&
     ++		test-tool chmtime --get -3600 c >old-mtime &&
       		GIT_MERGE_VERBOSITY=3 git merge -s recursive B^0 >out 2>err &&
       
       		test_must_be_empty err &&
     @@ -176,7 +179,7 @@
       
      -		test-tool chmtime =-1 c &&
      -		test-tool chmtime --get c >old-mtime &&
     -+		test-tool chmtime --get -1 c >old-mtime &&
     ++		test-tool chmtime --get -3600 c >old-mtime &&
       		GIT_MERGE_VERBOSITY=3 &&
       		export GIT_MERGE_VERBOSITY &&
       		test_must_fail git merge -s recursive B^0 >out 2>err &&
     @@ -186,7 +189,7 @@
       
      -		test-tool chmtime =-1 b &&
      -		test-tool chmtime --get b >old-mtime &&
     -+		test-tool chmtime --get -1 b >old-mtime &&
     ++		test-tool chmtime --get -3600 b >old-mtime &&
       
       		GIT_MERGE_VERBOSITY=3 git merge -s recursive B^0 >out 2>err &&
       
     @@ -196,7 +199,7 @@
       
      -		test-tool chmtime =-1 c &&
      -		test-tool chmtime --get c >old-mtime &&
     -+		test-tool chmtime --get -1 c >old-mtime &&
     ++		test-tool chmtime --get -3600 c >old-mtime &&
       
       		GIT_MERGE_VERBOSITY=3 git merge -s recursive B^0 >out 2>err &&

 t/t6022-merge-rename.sh                | 19 ++++++++++---------
 t/t6046-merge-skip-unneeded-updates.sh | 21 +++++++--------------
 2 files changed, 17 insertions(+), 23 deletions(-)

diff --git a/t/t6022-merge-rename.sh b/t/t6022-merge-rename.sh
index d97cf48495b..bbbba3dcbf0 100755
--- a/t/t6022-merge-rename.sh
+++ b/t/t6022-merge-rename.sh
@@ -243,8 +243,7 @@ test_expect_success 'merge of identical changes in a renamed file' '
 	git reset --hard &&
 	git checkout change+rename &&
 
-	test-tool chmtime =31337 B &&
-	test-tool chmtime --get B >old-mtime &&
+	test-tool chmtime --get -3600 B >old-mtime &&
 	GIT_MERGE_VERBOSITY=3 git merge change >out &&
 
 	test-tool chmtime --get B >new-mtime &&
@@ -253,10 +252,12 @@ test_expect_success 'merge of identical changes in a renamed file' '
 	git reset --hard HEAD^ &&
 	git checkout change &&
 
-	test-tool chmtime =-1 M &&
-	test-tool chmtime --get M >old-mtime &&
+	# A will be renamed to B; we check mtimes and file presence
+	test_path_is_missing B &&
+	test-tool chmtime --get -3600 A >old-mtime &&
 	GIT_MERGE_VERBOSITY=3 git merge change+rename >out &&
 
+	test_path_is_missing A &&
 	test-tool chmtime --get B >new-mtime &&
 	test $(cat old-mtime) -lt $(cat new-mtime)
 '
@@ -645,7 +646,7 @@ test_expect_success 'setup avoid unnecessary update, normal rename' '
 
 test_expect_success 'avoid unnecessary update, normal rename' '
 	git checkout -q avoid-unnecessary-update-1^0 &&
-	test-tool chmtime --get =1000000000 rename >expect &&
+	test-tool chmtime --get -3600 rename >expect &&
 	git merge merge-branch-1 &&
 	test-tool chmtime --get rename >actual &&
 	test_cmp expect actual # "rename" should have stayed intact
@@ -677,7 +678,7 @@ test_expect_success 'setup to test avoiding unnecessary update, with D/F conflic
 
 test_expect_success 'avoid unnecessary update, with D/F conflict' '
 	git checkout -q avoid-unnecessary-update-2^0 &&
-	test-tool chmtime --get =1000000000 df >expect &&
+	test-tool chmtime --get -3600 df >expect &&
 	git merge merge-branch-2 &&
 	test-tool chmtime --get df >actual &&
 	test_cmp expect actual # "df" should have stayed intact
@@ -708,7 +709,7 @@ test_expect_success 'setup avoid unnecessary update, dir->(file,nothing)' '
 
 test_expect_success 'avoid unnecessary update, dir->(file,nothing)' '
 	git checkout -q master^0 &&
-	test-tool chmtime --get =1000000000 df >expect &&
+	test-tool chmtime --get -3600 df >expect &&
 	git merge side &&
 	test-tool chmtime --get df >actual &&
 	test_cmp expect actual # "df" should have stayed intact
@@ -737,7 +738,7 @@ test_expect_success 'setup avoid unnecessary update, modify/delete' '
 
 test_expect_success 'avoid unnecessary update, modify/delete' '
 	git checkout -q master^0 &&
-	test-tool chmtime --get =1000000000 file >expect &&
+	test-tool chmtime --get -3600 file >expect &&
 	test_must_fail git merge side &&
 	test-tool chmtime --get file >actual &&
 	test_cmp expect actual # "file" should have stayed intact
@@ -765,7 +766,7 @@ test_expect_success 'setup avoid unnecessary update, rename/add-dest' '
 
 test_expect_success 'avoid unnecessary update, rename/add-dest' '
 	git checkout -q master^0 &&
-	test-tool chmtime --get =1000000000 newfile >expect &&
+	test-tool chmtime --get -3600 newfile >expect &&
 	git merge side &&
 	test-tool chmtime --get newfile >actual &&
 	test_cmp expect actual # "file" should have stayed intact
diff --git a/t/t6046-merge-skip-unneeded-updates.sh b/t/t6046-merge-skip-unneeded-updates.sh
index 962030ecdb6..1ddc9e6626b 100755
--- a/t/t6046-merge-skip-unneeded-updates.sh
+++ b/t/t6046-merge-skip-unneeded-updates.sh
@@ -71,8 +71,7 @@ test_expect_success '1a-L: Modify(A)/Modify(B), change on B subset of A' '
 
 		git checkout A^0 &&
 
-		test-tool chmtime =-1 b &&
-		test-tool chmtime --get b >old-mtime &&
+		test-tool chmtime --get -3600 b >old-mtime &&
 
 		GIT_MERGE_VERBOSITY=3 git merge -s recursive B^0 >out 2>err &&
 
@@ -102,8 +101,7 @@ test_expect_success '1a-R: Modify(A)/Modify(B), change on B subset of A' '
 
 		git checkout B^0 &&
 
-		test-tool chmtime =-1 b &&
-		test-tool chmtime --get b >old-mtime &&
+		test-tool chmtime --get -3600 b >old-mtime &&
 		GIT_MERGE_VERBOSITY=3 git merge -s recursive A^0 >out 2>err &&
 
 		# Make sure b WAS updated
@@ -198,8 +196,7 @@ test_expect_success '2a-R: Modify/rename, merge into rename side' '
 
 		git checkout B^0 &&
 
-		test-tool chmtime =-1 c &&
-		test-tool chmtime --get c >old-mtime &&
+		test-tool chmtime --get -3600 c >old-mtime &&
 		GIT_MERGE_VERBOSITY=3 git merge -s recursive A^0 >out 2>err &&
 
 		# Make sure c WAS updated
@@ -266,8 +263,7 @@ test_expect_success '2b-L: Rename+Mod(A)/Mod(B), B mods subset of A' '
 
 		git checkout A^0 &&
 
-		test-tool chmtime =-1 c &&
-		test-tool chmtime --get c >old-mtime &&
+		test-tool chmtime --get -3600 c >old-mtime &&
 		GIT_MERGE_VERBOSITY=3 git merge -s recursive B^0 >out 2>err &&
 
 		test_must_be_empty err &&
@@ -373,8 +369,7 @@ test_expect_success '2c: Modify b & add c VS rename b->c' '
 
 		git checkout A^0 &&
 
-		test-tool chmtime =-1 c &&
-		test-tool chmtime --get c >old-mtime &&
+		test-tool chmtime --get -3600 c >old-mtime &&
 		GIT_MERGE_VERBOSITY=3 &&
 		export GIT_MERGE_VERBOSITY &&
 		test_must_fail git merge -s recursive B^0 >out 2>err &&
@@ -679,8 +674,7 @@ test_expect_failure '4a: Change on A, change on B subset of A, dirty mods presen
 		git checkout A^0 &&
 		echo "File rewritten" >b &&
 
-		test-tool chmtime =-1 b &&
-		test-tool chmtime --get b >old-mtime &&
+		test-tool chmtime --get -3600 b >old-mtime &&
 
 		GIT_MERGE_VERBOSITY=3 git merge -s recursive B^0 >out 2>err &&
 
@@ -747,8 +741,7 @@ test_expect_success '4b: Rename+Mod(A)/Mod(B), change on B subset of A, dirty mo
 		git checkout A^0 &&
 		echo "File rewritten" >c &&
 
-		test-tool chmtime =-1 c &&
-		test-tool chmtime --get c >old-mtime &&
+		test-tool chmtime --get -3600 c >old-mtime &&
 
 		GIT_MERGE_VERBOSITY=3 git merge -s recursive B^0 >out 2>err &&

base-commit: 30e9940356dc67959877f4b2417da33ebdefbb79
-- 
gitgitgadget