Skip to contentSkip to conversation

Testcase cleanups (merge related)

PATCH In review Elijah Newren via GitGitGadget 3 participants 16 messages Feb 27, 2020 – Mar 13, 2020

lore
Share & tools
lore
#0 lore raw

cover Testcase cleanups (merge related)

This series has a few testcase cleanups, and a new testcase. In more detail:

* The first three patches are just various forms of testcase modernization
* The fourth patch updates some tests to check intended behavior instead of a proxy thereof
* The fifth patch adds a new simple testcase that there is no other merge/rebase/cherry-pick test for in our testsuite, just for added defensiveness.

As a side note: t60[01]* is used by rev-list, and then t60[234].sh is kinda taken by merge-recursive except that t6030 and t6041 are for bisect and t6040 for remote tracking stuff. Because t60[234].sh got filled up, rev-list spilled over to t61[01]* as well. It's all kind of a mess. I'm curious if moving the merge stuff over to t64* would make sense, since that'd keep the merge stuff together, and would also free up space for rev-list, bisect, remote-tracking and whatnot. Would that just be too much churn?

Elijah Newren (5):
t602[1236], t6034: modernize test formatting
t6020, t6022, t6035: update merge tests to use test helper functions
t3035: prefer test_must_fail to bash negation for git commands t6022, t6046: test expected behavior instead of testing a proxy for it
t6020: new test with interleaved lexicographic ordering of directories

 t/t3035-merge-sparse.sh                |   4 +-
 t/t6020-merge-df.sh                    |  55 ++-
 t/t6021-merge-criss-cross.sh           | 135 +++---
 t/t6022-merge-rename.sh                | 382 +++++++++--------
 t/t6023-merge-file.sh                  | 568 +++++++++++++------------
 t/t6026-merge-attr.sh                  |  46 +-
 t/t6034-merge-rename-nocruft.sh        | 122 +++---
 t/t6035-merge-dir-to-symlink.sh        |  28 +-
 t/t6046-merge-skip-unneeded-updates.sh |  89 ++--
 9 files changed, 752 insertions(+), 677 deletions(-)

base-commit: 2d2118b814c11f509e1aa76cb07110f7231668dc
Published-As: https://github.com/gitgitgadget/git/releases/tag/pr-git-716%2Fnewren%2Ftestcase-cleanups-v1
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-git-716/newren/testcase-cleanups-v1
Pull-Request: https://github.com/git/git/pull/716

Signature · 1 line
gitgitgadget
#3 lore raw

PATCH 3/5 t3035: prefer test_must_fail to bash negation for git commands

From: Elijah Newren <[email protected]>

---
 t/t3035-merge-sparse.sh | 4 ++--
 1 file changed, 2 insertions(+), 2 deletions(-)
t/t3035-merge-sparse.sh +2 -2
index c4b4a94324a..74562e12356 100755
@@ -28,7 +28,7 @@ test_expect_success 'setup' '
 	git config core.sparseCheckout true &&
 	echo "/checked-out" >.git/info/sparse-checkout &&
 	git reset --hard &&
-	! git merge theirs
+	test_must_fail git merge theirs
 '
 
 test_expect_success 'reset --hard works after the conflict' '
@@ -42,7 +42,7 @@ test_expect_success 'is reset properly' '
 '
 
 test_expect_success 'setup: conflict back' '
-	! git merge theirs
+	test_must_fail git merge theirs
 '
 
 test_expect_success 'Merge abort works after the conflict' '
Signature · 1 line
gitgitgadget
#2 lore raw

PATCH 2/5 t6020, t6022, t6035: update merge tests to use test helper functions

In reply to Elijah Newren via GitGitGadget

From: Elijah Newren <[email protected]>

Make use of test_path_is_file, test_write_lines, and similar helpers in these old test files.

---
 t/t6020-merge-df.sh             | 12 ++++----
 t/t6022-merge-rename.sh         | 54 ++++++++++++++++-----------------
 t/t6035-merge-dir-to-symlink.sh | 28 ++++++++---------
 3 files changed, 47 insertions(+), 47 deletions(-)
t/t6020-merge-df.sh +6 -6
index 46b506b3b7b..cf662068da1 100755
@@ -83,9 +83,9 @@ test_expect_success 'modify/delete + directory/file conflict' '
 	test 4 -eq $(git ls-files -u | wc -l) &&
 	test 1 -eq $(git ls-files -o | wc -l) &&
 
-	test -f letters/file &&
-	test -f letters.txt &&
-	test -f letters~modify
+	test_path_is_file letters/file &&
+	test_path_is_file letters.txt &&
+	test_path_is_file letters~modify
 '
 
 test_expect_success 'modify/delete + directory/file conflict; other way' '
@@ -99,9 +99,9 @@ test_expect_success 'modify/delete + directory/file conflict; other way' '
 	test 4 -eq $(git ls-files -u | wc -l) &&
 	test 1 -eq $(git ls-files -o | wc -l) &&
 
-	test -f letters/file &&
-	test -f letters.txt &&
-	test -f letters~HEAD
+	test_path_is_file letters/file &&
+	test_path_is_file letters.txt &&
+	test_path_is_file letters~HEAD
 '
 
 test_done
t/t6022-merge-rename.sh +27 -27

120 lines not on this page · raw message

t/t6035-merge-dir-to-symlink.sh +14 -14
index 9324ea44162..2eddcc7664e 100755
@@ -31,19 +31,19 @@ test_expect_success 'a/b-2/c/d is kept when clobbering symlink b' '
 	git rm --cached a/b &&
 	git commit -m "untracked symlink remains" &&
 	git checkout -f start^0 &&
-	test -f a/b-2/c/d
+	test_path_is_file a/b-2/c/d
 '
 
 test_expect_success 'checkout should not have deleted a/b-2/c/d' '
 	git checkout HEAD^0 &&
 	git reset --hard master &&
 	 git checkout start^0 &&
-	 test -f a/b-2/c/d
+	 test_path_is_file a/b-2/c/d
 '
 
 test_expect_success 'setup for merge test' '
 	git reset --hard &&
-	test -f a/b-2/c/d &&
+	test_path_is_file a/b-2/c/d &&
 	echo x > a/x &&
 	git add a/x &&
 	git commit -m x &&
@@ -54,7 +54,7 @@ test_expect_success 'Handle D/F conflict, do not lose a/b-2/c/d in merge (resolv
 	git reset --hard &&
 	git checkout baseline^0 &&
 	git merge -s resolve master &&
-	test -f a/b-2/c/d
+	test_path_is_file a/b-2/c/d
 '
 
 test_expect_success SYMLINKS 'a/b was resolved as symlink' '
@@ -65,7 +65,7 @@ test_expect_success 'Handle D/F conflict, do not lose a/b-2/c/d in merge (recurs
 	git reset --hard &&
 	git checkout baseline^0 &&
 	git merge -s recursive master &&
-	test -f a/b-2/c/d
+	test_path_is_file a/b-2/c/d
 '
 
 test_expect_success SYMLINKS 'a/b was resolved as symlink' '
@@ -76,7 +76,7 @@ test_expect_success 'Handle F/D conflict, do not lose a/b-2/c/d in merge (resolv
 	git reset --hard &&
 	git checkout master^0 &&
 	git merge -s resolve baseline^0 &&
-	test -f a/b-2/c/d
+	test_path_is_file a/b-2/c/d
 '
 
 test_expect_success SYMLINKS 'a/b was resolved as symlink' '
@@ -87,7 +87,7 @@ test_expect_success 'Handle F/D conflict, do not lose a/b-2/c/d in merge (recurs
 	git reset --hard &&
 	git checkout master^0 &&
 	git merge -s recursive baseline^0 &&
-	test -f a/b-2/c/d
+	test_path_is_file a/b-2/c/d
 '
 
 test_expect_success SYMLINKS 'a/b was resolved as symlink' '
@@ -99,8 +99,8 @@ test_expect_failure 'do not lose untracked in merge (resolve)' '
 	git checkout baseline^0 &&
 	>a/b/c/e &&
 	test_must_fail git merge -s resolve master &&
-	test -f a/b/c/e &&
-	test -f a/b-2/c/d
+	test_path_is_file a/b/c/e &&
+	test_path_is_file a/b-2/c/d
 '
 
 test_expect_success 'do not lose untracked in merge (recursive)' '
@@ -108,8 +108,8 @@ test_expect_success 'do not lose untracked in merge (recursive)' '
 	git checkout baseline^0 &&
 	>a/b/c/e &&
 	test_must_fail git merge -s recursive master &&
-	test -f a/b/c/e &&
-	test -f a/b-2/c/d
+	test_path_is_file a/b/c/e &&
+	test_path_is_file a/b-2/c/d
 '
 
 test_expect_success 'do not lose modifications in merge (resolve)' '
@@ -140,7 +140,7 @@ test_expect_success 'merge should not have D/F conflicts (resolve)' '
 	git reset --hard &&
 	git checkout baseline^0 &&
 	git merge -s resolve test2 &&
-	test -f a/b/c/d
+	test_path_is_file a/b/c/d
 '
 
 test_expect_success SYMLINKS 'a/b-2 was resolved as symlink' '
@@ -151,7 +151,7 @@ test_expect_success 'merge should not have D/F conflicts (recursive)' '
 	git reset --hard &&
 	git checkout baseline^0 &&
 	git merge -s recursive test2 &&
-	test -f a/b/c/d
+	test_path_is_file a/b/c/d
 '
 
 test_expect_success SYMLINKS 'a/b-2 was resolved as symlink' '
@@ -162,7 +162,7 @@ test_expect_success 'merge should not have F/D conflicts (recursive)' '
 	git reset --hard &&
 	git checkout -b foo test2 &&
 	git merge -s recursive baseline^0 &&
-	test -f a/b/c/d
+	test_path_is_file a/b/c/d
 '
 
 test_expect_success SYMLINKS 'a/b-2 was resolved as symlink' '
Signature · 1 line
gitgitgadget
#1 lore raw

PATCH 1/5 t602[1236], t6034: modernize test formatting

In reply to Elijah Newren via GitGitGadget

From: Elijah Newren <[email protected]>

Indent code, and include it inside test_expect* blocks.

---
 t/t6021-merge-criss-cross.sh    | 135 +++-----
 t/t6022-merge-rename.sh         | 315 +++++++++---------
 t/t6023-merge-file.sh           | 568 +++++++++++++++++---------------
 t/t6026-merge-attr.sh           |  46 +--
 t/t6034-merge-rename-nocruft.sh | 122 ++++---
 5 files changed, 591 insertions(+), 595 deletions(-)
t/t6021-merge-criss-cross.sh +53 -82
index d254e020b6d..9d5e992878f 100755
@@ -10,87 +10,58 @@
 test_description='Test criss-cross merge'
 . ./test-lib.sh
 
-test_expect_success 'prepare repository' \
-'echo "1
-2
-3
-4
-5
-6
-7
-8
-9" > file &&
-git add file &&
-git commit -m "Initial commit" file &&
-git branch A &&
-git branch B &&
-git checkout A &&
-echo "1
-2
-3
-4
-5
-6
-7
-8 changed in B8, branch A
-9" > file &&
-git commit -m "B8" file &&
-git checkout B &&
-echo "1
-2
-3 changed in C3, branch B
-4
-5
-6
-7
-8
-9
-" > file &&
-git commit -m "C3" file &&
-git branch C3 &&
-git merge -m "pre E3 merge" A &&
-echo "1
-2
-3 changed in E3, branch B. New file size
-4
-5
-6
-7
-8 changed in B8, branch A
-9
-" > file &&
-git commit -m "E3" file &&
-git checkout A &&
-git merge -m "pre D8 merge" C3 &&
-echo "1
-2
-3 changed in C3, branch B
-4
-5
-6
-7
-8 changed in D8, branch A. New file size 2
-9" > file &&
-git commit -m D8 file'
-
-test_expect_success 'Criss-cross merge' 'git merge -m "final merge" B'
-
-cat > file-expect <<EOF
-1
-2
-3 changed in E3, branch B. New file size
-4
-5
-6
-7
-8 changed in D8, branch A. New file size 2
-9
-EOF
-
-test_expect_success 'Criss-cross merge result' 'cmp file file-expect'
-
-test_expect_success 'Criss-cross merge fails (-s resolve)' \
-'git reset --hard A^ &&
-test_must_fail git merge -s resolve -m "final merge" B'
+test_expect_success 'prepare repository' '
+	test_write_lines 1 2 3 4 5 6 7 8 9 >file &&
+	git add file &&
+	git commit -m "Initial commit" file &&
+
+	git branch A &&
+	git branch B &&
+	git checkout A &&
+
+	test_write_lines 1 2 3 4 5 6 7 "8 changed in B8, branch A" 9 >file &&
+	git commit -m "B8" file &&
+	git checkout B &&
+
+	test_write_lines 1 2 "3 changed in C3, branch B" 4 5 6 7 8 9 >file &&
+	git commit -m "C3" file &&
+	git branch C3 &&
+
+	git merge -m "pre E3 merge" A &&
+
+	test_write_lines 1 2 "3 changed in E3, branch B. New file size" 4 5 6 7 "8 changed in B8, branch A" 9 >file &&
+	git commit -m "E3" file &&
+
+	git checkout A &&
+	git merge -m "pre D8 merge" C3 &&
+	test_write_lines 1 2 "3 changed in C3, branch B" 4 5 6 7 "8 changed in D8, branch A. New file size 2" 9 >file &&
+
+	git commit -m D8 file
+'
+
+test_expect_success 'Criss-cross merge' '
+	git merge -m "final merge" B
+'
+
+test_expect_success 'Criss-cross merge result' '
+	cat <<-\EOF >file-expect &&
+	1
+	2
+	3 changed in E3, branch B. New file size
+	4
+	5
+	6
+	7
+	8 changed in D8, branch A. New file size 2
+	9
+	EOF
+
+	test_cmp file-expect file
+'
+
+test_expect_success 'Criss-cross merge fails (-s resolve)' '
+	git reset --hard A^ &&
+	test_must_fail git merge -s resolve -m "final merge" B
+'
 
 test_done
t/t6022-merge-rename.sh +157 -158

373 lines not on this page · raw message

t/t6023-merge-file.sh +298 -270

634 lines not on this page · raw message

t/t6026-merge-attr.sh +23 -23

58 lines not on this page · raw message

t/t6034-merge-rename-nocruft.sh +60 -62

142 lines not on this page · raw message

Signature · 1 line
gitgitgadget
#15 lore raw

PATCH 5/5 t6020: new test with interleaved lexicographic ordering of directories

In reply to Elijah Newren via GitGitGadget

From: Elijah Newren <[email protected]>

If a repository has two files:

    foo/bar/baz
    foo/bar-2/baz
then a simple lexicographic ordering of files and directories shows
    ...
    foo/bar
    foo/bar-2
    foo/bar/baz
    ...

and the appearance of foo/bar-2 between foo/bar and foo/bar/baz can trip up some codepaths. Add a test to catch such cases.

t6020 might be a slight misfit since this testcase does not test any kind of file/directory conflict. However, it is similar in spirit to some tests (4-6) already in t6020 that check cases where a *file* sorted between a directory and the files underneath that directory. This testcase differs in that now there is a *directory* that sorts in the middle.

Although merge-recursive currently has no problems with this simple testcase, I discovered that it's very possible to accidentally mess it up. Further, we have no other merge or cherry-pick or rebase testcases in the entire testsuite that cover such a case, so I felt like it would be a worthwhile addition to the testsuite.

---
 t/t6020-merge-df.sh | 43 +++++++++++++++++++++++++++++++++++++++++++
 1 file changed, 43 insertions(+)
t/t6020-merge-df.sh +43 -0
index cf662068da1..400a4cd1392 100755
@@ -104,4 +104,47 @@ test_expect_success 'modify/delete + directory/file conflict; other way' '
 	test_path_is_file letters~HEAD
 '
 
+test_expect_success 'Simple merge in repo with interesting pathnames' '
+	# Simple lexicographic ordering of files and directories would be:
+	#     foo
+	#     foo/bar
+	#     foo/bar-2
+	#     foo/bar/baz
+	#     foo/bar-2/baz
+	# The fact that foo/bar-2 appears between foo/bar and foo/bar/baz
+	# can trip up some codepaths, and is the point of this test.
+	test_create_repo name-ordering &&
+	(
+		cd name-ordering &&
+
+		mkdir -p foo/bar &&
+		mkdir -p foo/bar-2 &&
+		>foo/bar/baz &&
+		>foo/bar-2/baz &&
+		git add . &&
+		git commit -m initial &&
+
+		git branch main &&
+		git branch other &&
+
+		git checkout other &&
+		echo other >foo/bar-2/baz &&
+		git add -u &&
+		git commit -m other &&
+
+		git checkout main &&
+		echo main >foo/bar/baz &&
+		git add -u &&
+		git commit -m main &&
+
+		git merge other &&
+		git ls-files -s >out &&
+		test_line_count = 2 out &&
+		git rev-parse :0:foo/bar/baz :0:foo/bar-2/baz >actual &&
+		git rev-parse HEAD~1:foo/bar/baz other:foo/bar-2/baz >expect &&
+		test_cmp expect actual
+	)
+
+'
+
 test_done
Signature · 1 line
gitgitgadget
#4 lore raw

PATCH 4/5 t6022, t6046: test expected behavior instead of testing a proxy for it

In reply to Elijah Newren via GitGitGadget

From: Elijah Newren <[email protected]>

In t6022, we were testing for file being overwritten (or not) based on an output message instead of checking for the file being overwritten. Since we can check for the file being overwritten via mtime updates, check that instead.

In t6046, we were largely checking for both the expected behavior and a proxy for it, which is unnecessary. The calls to test-tool also were a bit cryptic. Make them a little clearer.

---
 t/t6022-merge-rename.sh                | 15 ++++-
 t/t6046-merge-skip-unneeded-updates.sh | 89 +++++++++++++++++---------
 2 files changed, 70 insertions(+), 34 deletions(-)
t/t6022-merge-rename.sh +13 -2
index 6f196aaf276..d97cf48495b 100755
@@ -242,12 +242,23 @@ test_expect_success 'merge of identical changes in a renamed file' '
 	rm -f A M N &&
 	git reset --hard &&
 	git checkout change+rename &&
+
+	test-tool chmtime =31337 B &&
+	test-tool chmtime --get B >old-mtime &&
 	GIT_MERGE_VERBOSITY=3 git merge change >out &&
-	test_i18ngrep "^Skipped B" out &&
+
+	test-tool chmtime --get B >new-mtime &&
+	test_cmp old-mtime new-mtime &&
+
 	git reset --hard HEAD^ &&
 	git checkout change &&
+
+	test-tool chmtime =-1 M &&
+	test-tool chmtime --get M >old-mtime &&
 	GIT_MERGE_VERBOSITY=3 git merge change+rename >out &&
-	test_i18ngrep ! "^Skipped B" out
+
+	test-tool chmtime --get B >new-mtime &&
+	test $(cat old-mtime) -lt $(cat new-mtime)
 '
 
 test_expect_success 'setup for rename + d/f conflicts' '
t/t6046-merge-skip-unneeded-updates.sh +57 -32

215 lines not on this page · raw message

Signature · 1 line
gitgitgadget
#5 lore raw

Re: [PATCH 4/5] t6022, t6046: test expected behavior instead of testing a proxy for it

Quoted 22 lines · Elijah Newren via GitGitGadget

From: Elijah Newren <[email protected]>

In t6022, we were testing for file being overwritten (or not) based on an output message instead of checking for the file being overwritten. Since we can check for the file being overwritten via mtime updates, check that instead.

In t6046, we were largely checking for both the expected behavior and a proxy for it, which is unnecessary. The calls to test-tool also were a bit cryptic. Make them a little clearer.

---
 t/t6022-merge-rename.sh                | 15 ++++-
 t/t6046-merge-skip-unneeded-updates.sh | 89 +++++++++++++++++---------
 2 files changed, 70 insertions(+), 34 deletions(-)
t/t6022-merge-rename.sh +0 -0
index 6f196aaf276..d97cf48495b 100755

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 247

Quoted 6 lines
t/t6022-merge-rename.sh +3 -0
@@ -242,12 +242,23 @@ test_expect_success 'merge of identical changes in a renamed file' '
 	rm -f A M N &&
 	git reset --hard &&
 	git checkout change+rename &&
+
+	test-tool chmtime =31337 B &&
+	test-tool chmtime --get B >old-mtime &&

Nit: I think it's possible to change the mtime and print it in a single invocation with:

  test-tool chmtime --get =1234 file

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 248

Quoted 1 line
t/t6022-merge-rename.sh +0 -0
 	GIT_MERGE_VERBOSITY=3 git merge change >out &&

Nit: The output of 'git merge' is still redirected to a file, but ...

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 246

Quoted 1 line
t/t6022-merge-rename.sh +0 -1
-	test_i18ngrep "^Skipped B" out &&

... the only command looking at the output is now removed.

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 250

Quoted 10 lines
t/t6022-merge-rename.sh +6 -1
+	test-tool chmtime --get B >new-mtime &&
+	test_cmp old-mtime new-mtime &&
+
 	git reset --hard HEAD^ &&
 	git checkout change &&
+
+	test-tool chmtime =-1 M &&
+	test-tool chmtime --get M >old-mtime &&
 	GIT_MERGE_VERBOSITY=3 git merge change+rename >out &&
-	test_i18ngrep ! "^Skipped B" out

Likewise.

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 259

Quoted 2 lines
t/t6022-merge-rename.sh +2 -0
+	test-tool chmtime --get B >new-mtime &&
+	test $(cat old-mtime) -lt $(cat new-mtime)

I saw this test fail today in one of my custom CI builds:

+git checkout change
Switched to branch 'change'
+test-tool chmtime =-1 M
+test-tool chmtime --get M +GIT_MERGE_VERBOSITY=3 git merge change+rename +test-tool chmtime --get B
+cat old-mtime
+cat new-mtime
+test 1583967731 -lt 1583967731
error: last command exited with $?=1
not ok 12 - merge of identical changes in a renamed file

The contents of 'out', i.e. the output of the 'git merge' command before the failure is:

Auto-merging B
Merge made by the 'recursive' strategy.

   A => B | 0
   1 file changed, 0 insertions(+), 0 deletions(-)

rename A => B (100%)

This is a rare failure, this is the first time I saw it, and to make things worse, this one time it happened on big-endian and with all the GIT_TEST_* knobs enabled.

https://travis-ci.org/github/szeder/git-cooking-topics-for-travis-ci/jobs/661294571#L4020

I've been running './t6022-merge-rename.sh --stress -r 1,12' both with and without all the GIT_TEST_* knobs for a few hundred repetitions, but couldn't trigger the failure yet...

I wonder whether comparing the mtimes with '-le' instead of '-lt' is acceptable in this test case, but don't have enough insight to form an opinion. Note that this patch added a few similar mtime comparisons to t6046 below, and they might be prone to the same issue as well.

Quoted 236 lines
t/t6022-merge-rename.sh +0 -0
 test_expect_success 'setup for rename + d/f conflicts' '
t/t6046-merge-skip-unneeded-updates.sh +57 -32
index b7e46698321..962030ecdb6 100755
@@ -71,16 +71,16 @@ test_expect_success '1a-L: Modify(A)/Modify(B), change on B subset of A' '
 
 		git checkout A^0 &&
 
-		test-tool chmtime =31337 b &&
-		test-tool chmtime -v +0 b >expected-mtime &&
+		test-tool chmtime =-1 b &&
+		test-tool chmtime --get b >old-mtime &&
 
 		GIT_MERGE_VERBOSITY=3 git merge -s recursive B^0 >out 2>err &&
 
-		test_i18ngrep "Skipped b" out &&
 		test_must_be_empty err &&
 
-		test-tool chmtime -v +0 b >actual-mtime &&
-		test_cmp expected-mtime actual-mtime &&
+		# Make sure b was NOT updated
+		test-tool chmtime --get b >new-mtime &&
+		test_cmp old-mtime new-mtime &&
 
 		git ls-files -s >index_files &&
 		test_line_count = 1 index_files &&
@@ -102,9 +102,14 @@ 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 &&
 		GIT_MERGE_VERBOSITY=3 git merge -s recursive A^0 >out 2>err &&
 
-		test_i18ngrep "Auto-merging b" out &&
+		# Make sure b WAS updated
+		test-tool chmtime --get b >new-mtime &&
+		test $(cat old-mtime) -lt $(cat new-mtime) &&
+
 		test_must_be_empty err &&
 
 		git ls-files -s >index_files &&
@@ -165,10 +170,10 @@ test_expect_success '2a-L: Modify/rename, merge into modify side' '
 
 		git checkout A^0 &&
 
+		test_path_is_missing c &&
 		GIT_MERGE_VERBOSITY=3 git merge -s recursive B^0 >out 2>err &&
 
-		test_i18ngrep ! "Skipped c" out &&
-		test_must_be_empty err &&
+		test_path_is_file c &&
 
 		git ls-files -s >index_files &&
 		test_line_count = 1 index_files &&
@@ -193,9 +198,14 @@ 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 &&
 		GIT_MERGE_VERBOSITY=3 git merge -s recursive A^0 >out 2>err &&
 
-		test_i18ngrep ! "Skipped c" out &&
+		# Make sure c WAS updated
+		test-tool chmtime --get c >new-mtime &&
+		test $(cat old-mtime) -lt $(cat new-mtime) &&
+
 		test_must_be_empty err &&
 
 		git ls-files -s >index_files &&
@@ -256,16 +266,15 @@ test_expect_success '2b-L: Rename+Mod(A)/Mod(B), B mods subset of A' '
 
 		git checkout A^0 &&
 
-		test-tool chmtime =31337 c &&
-		test-tool chmtime -v +0 c >expected-mtime &&
-
+		test-tool chmtime =-1 c &&
+		test-tool chmtime --get c >old-mtime &&
 		GIT_MERGE_VERBOSITY=3 git merge -s recursive B^0 >out 2>err &&
 
-		test_i18ngrep "Skipped c" out &&
 		test_must_be_empty err &&
 
-		test-tool chmtime -v +0 c >actual-mtime &&
-		test_cmp expected-mtime actual-mtime &&
+		# Make sure c WAS updated
+		test-tool chmtime --get c >new-mtime &&
+		test_cmp old-mtime new-mtime &&
 
 		git ls-files -s >index_files &&
 		test_line_count = 1 index_files &&
@@ -290,9 +299,12 @@ test_expect_success '2b-R: Rename+Mod(A)/Mod(B), B mods subset of A' '
 
 		git checkout B^0 &&
 
+		test_path_is_missing c &&
 		GIT_MERGE_VERBOSITY=3 git merge -s recursive A^0 >out 2>err &&
 
-		test_i18ngrep "Auto-merging c" out &&
+		# Make sure c now present (and thus was updated)
+		test_path_is_file c &&
+
 		test_must_be_empty err &&
 
 		git ls-files -s >index_files &&
@@ -361,13 +373,18 @@ 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 &&
 		GIT_MERGE_VERBOSITY=3 &&
 		export GIT_MERGE_VERBOSITY &&
 		test_must_fail git merge -s recursive B^0 >out 2>err &&
 
 		test_i18ngrep "CONFLICT (rename/add): Rename b->c" out &&
-		test_i18ngrep ! "Skipped c" out &&
-		test_must_be_empty err
+		test_must_be_empty err &&
+
+		# Make sure c WAS updated
+		test-tool chmtime --get c >new-mtime &&
+		test $(cat old-mtime) -lt $(cat new-mtime)
 
 		# FIXME: rename/add conflicts are horribly broken right now;
 		# when I get back to my patch series fixing it and
@@ -460,11 +477,13 @@ test_expect_success '3a-L: bq_1->foo/bq_2 on A, foo/->bar/ on B' '
 
 		git checkout A^0 &&
 
+		test_path_is_missing bar/bq &&
 		GIT_MERGE_VERBOSITY=3 git -c merge.directoryRenames=true merge -s recursive B^0 >out 2>err &&
 
-		test_i18ngrep ! "Skipped bar/bq" out &&
 		test_must_be_empty err &&
 
+		test_path_is_file bar/bq &&
+
 		git ls-files -s >index_files &&
 		test_line_count = 2 index_files &&
 
@@ -488,11 +507,13 @@ test_expect_success '3a-R: bq_1->foo/bq_2 on A, foo/->bar/ on B' '
 
 		git checkout B^0 &&
 
+		test_path_is_missing bar/bq &&
 		GIT_MERGE_VERBOSITY=3 git -c merge.directoryRenames=true merge -s recursive A^0 >out 2>err &&
 
-		test_i18ngrep ! "Skipped bar/bq" out &&
 		test_must_be_empty err &&
 
+		test_path_is_file bar/bq &&
+
 		git ls-files -s >index_files &&
 		test_line_count = 2 index_files &&
 
@@ -552,11 +573,13 @@ test_expect_success '3b-L: bq_1->foo/bq_2 on A, foo/->bar/ on B' '
 
 		git checkout A^0 &&
 
+		test_path_is_missing bar/bq &&
 		GIT_MERGE_VERBOSITY=3 git -c merge.directoryRenames=true merge -s recursive B^0 >out 2>err &&
 
-		test_i18ngrep ! "Skipped bar/bq" out &&
 		test_must_be_empty err &&
 
+		test_path_is_file bar/bq &&
+
 		git ls-files -s >index_files &&
 		test_line_count = 2 index_files &&
 
@@ -580,11 +603,13 @@ test_expect_success '3b-R: bq_1->foo/bq_2 on A, foo/->bar/ on B' '
 
 		git checkout B^0 &&
 
+		test_path_is_missing bar/bq &&
 		GIT_MERGE_VERBOSITY=3 git -c merge.directoryRenames=true merge -s recursive A^0 >out 2>err &&
 
-		test_i18ngrep ! "Skipped bar/bq" out &&
 		test_must_be_empty err &&
 
+		test_path_is_file bar/bq &&
+
 		git ls-files -s >index_files &&
 		test_line_count = 2 index_files &&
 
@@ -654,16 +679,16 @@ 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 =31337 b &&
-		test-tool chmtime -v +0 b >expected-mtime &&
+		test-tool chmtime =-1 b &&
+		test-tool chmtime --get b >old-mtime &&
 
 		GIT_MERGE_VERBOSITY=3 git merge -s recursive B^0 >out 2>err &&
 
-		test_i18ngrep "Skipped b" out &&
 		test_must_be_empty err &&
 
-		test-tool chmtime -v +0 b >actual-mtime &&
-		test_cmp expected-mtime actual-mtime &&
+		# Make sure b was NOT updated
+		test-tool chmtime --get b >new-mtime &&
+		test_cmp old-mtime new-mtime &&
 
 		git ls-files -s >index_files &&
 		test_line_count = 1 index_files &&
@@ -722,16 +747,16 @@ 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 =31337 c &&
-		test-tool chmtime -v +0 c >expected-mtime &&
+		test-tool chmtime =-1 c &&
+		test-tool chmtime --get c >old-mtime &&
 
 		GIT_MERGE_VERBOSITY=3 git merge -s recursive B^0 >out 2>err &&
 
-		test_i18ngrep "Skipped c" out &&
 		test_must_be_empty err &&
 
-		test-tool chmtime -v +0 c >actual-mtime &&
-		test_cmp expected-mtime actual-mtime &&
+		# Make sure c was NOT updated
+		test-tool chmtime --get c >new-mtime &&
+		test_cmp old-mtime new-mtime &&
 
 		git ls-files -s >index_files &&
 		test_line_count = 1 index_files &&
Signature · 1 line
gitgitgadget
#6 lore raw

Re: [PATCH 4/5] t6022, t6046: test expected behavior instead of testing a proxy for it

Quoted 34 lines · SZEDER Gábor
Quoted 22 lines · Elijah Newren via GitGitGadget

From: Elijah Newren <[email protected]>

In t6022, we were testing for file being overwritten (or not) based on an output message instead of checking for the file being overwritten. Since we can check for the file being overwritten via mtime updates, check that instead.

In t6046, we were largely checking for both the expected behavior and a proxy for it, which is unnecessary. The calls to test-tool also were a bit cryptic. Make them a little clearer.

---
 t/t6022-merge-rename.sh                | 15 ++++-
 t/t6046-merge-skip-unneeded-updates.sh | 89 +++++++++++++++++---------
 2 files changed, 70 insertions(+), 34 deletions(-)
t/t6022-merge-rename.sh +0 -0
index 6f196aaf276..d97cf48495b 100755

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 247

Quoted 6 lines
t/t6022-merge-rename.sh +3 -0
@@ -242,12 +242,23 @@ test_expect_success 'merge of identical changes in a renamed file' '
      rm -f A M N &&
      git reset --hard &&
      git checkout change+rename &&
+
+     test-tool chmtime =31337 B &&
+     test-tool chmtime --get B >old-mtime &&

Nit: I think it's possible to change the mtime and print it in a single invocation with:

Quoted 1 line
  test-tool chmtime --get =1234 file

Oh, cool.

Quoted 7 lines

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 248

Quoted 1 line
t/t6022-merge-rename.sh +0 -0
      GIT_MERGE_VERBOSITY=3 git merge change >out &&

Nit: The output of 'git merge' is still redirected to a file, but ...

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 246

Quoted 1 line
t/t6022-merge-rename.sh +0 -1
-     test_i18ngrep "^Skipped B" out &&

... the only command looking at the output is now removed.

Indeed.

Quoted 37 lines

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 250

Quoted 10 lines
t/t6022-merge-rename.sh +6 -1
+     test-tool chmtime --get B >new-mtime &&
+     test_cmp old-mtime new-mtime &&
+
      git reset --hard HEAD^ &&
      git checkout change &&
+
+     test-tool chmtime =-1 M &&
+     test-tool chmtime --get M >old-mtime &&
      GIT_MERGE_VERBOSITY=3 git merge change+rename >out &&
-     test_i18ngrep ! "^Skipped B" out

Likewise.

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 259

Quoted 2 lines
t/t6022-merge-rename.sh +2 -0
+     test-tool chmtime --get B >new-mtime &&
+     test $(cat old-mtime) -lt $(cat new-mtime)

I saw this test fail today in one of my custom CI builds:

+git checkout change
Switched to branch 'change'
+test-tool chmtime =-1 M
+test-tool chmtime --get M +GIT_MERGE_VERBOSITY=3 git merge change+rename +test-tool chmtime --get B
+cat old-mtime
+cat new-mtime
+test 1583967731 -lt 1583967731
error: last command exited with $?=1
not ok 12 - merge of identical changes in a renamed file

The contents of 'out', i.e. the output of the 'git merge' command before the failure is:

Auto-merging B
Merge made by the 'recursive' strategy.

   A => B | 0
   1 file changed, 0 insertions(+), 0 deletions(-)
Quoted 7 lines

rename A => B (100%)

This is a rare failure, this is the first time I saw it, and to make things worse, this one time it happened on big-endian and with all the GIT_TEST_* knobs enabled.

https://travis-ci.org/github/szeder/git-cooking-topics-for-travis-ci/jobs/661294571#L4020

This is very troubling. The workflow is basically:
- Manually set the mtime to a file to something old (I happened to
pick 1 second before now, but picking something from 1970 would have been fine too).
- Run a merge which is known to need to overwrite the file. Your
output ("Auto-merging B") suggests that we should have been in such a case.
- Verify that the file was actually updated as expected. Since the
OS is supposed to update the mtime when it writes the file, it should have set it to something recent, i.e. something *different* than what it had before.

So, now I'm left wondering how the mtime possibly could have been not updated. Maybe the file wasn't actually written? (But if so, why didn't other people see the failure? Or your stress runs not see it?)
Or maybe it was written but all file contents and metadata were
delayed in writing to disk such that a subsequent command still sees the old file?? Or maybe it was written but the mtime update was delayed and the test was able to check it in that intermediate state??? Or perhaps the mtime check before the merge raced with the setting of the mtime backwards and got the mtime before it was rewound????

I don't have a plausible scenario under which any of these should be possible; I'm at a loss.

Quoted 3 lines

I've been running './t6022-merge-rename.sh --stress -r 1,12' both with and without all the GIT_TEST_* knobs for a few hundred repetitions, but couldn't trigger the failure yet...

I'm not sure if that makes me feel better or worse.

Quoted 4 lines

I wonder whether comparing the mtimes with '-le' instead of '-lt' is acceptable in this test case, but don't have enough insight to form an opinion. Note that this patch added a few similar mtime comparisons to t6046 below, and they might be prone to the same issue as well.

-le would not be acceptable; if we were to do that we may as well throw away the test. The test exists to check that the file contents were actually written, which I was assuming could be verified by an mtime update of what otherwise used to be an "old" file.

#7 lore raw

Re: [PATCH 4/5] t6022, t6046: test expected behavior instead of testing a proxy for it

Quoted 118 lines · Elijah Newren
Quoted 34 lines · SZEDER Gábor
Quoted 22 lines · Elijah Newren via GitGitGadget

From: Elijah Newren <[email protected]>

In t6022, we were testing for file being overwritten (or not) based on an output message instead of checking for the file being overwritten. Since we can check for the file being overwritten via mtime updates, check that instead.

In t6046, we were largely checking for both the expected behavior and a proxy for it, which is unnecessary. The calls to test-tool also were a bit cryptic. Make them a little clearer.

---
 t/t6022-merge-rename.sh                | 15 ++++-
 t/t6046-merge-skip-unneeded-updates.sh | 89 +++++++++++++++++---------
 2 files changed, 70 insertions(+), 34 deletions(-)
t/t6022-merge-rename.sh +0 -0
index 6f196aaf276..d97cf48495b 100755

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 247

Quoted 6 lines
t/t6022-merge-rename.sh +3 -0
@@ -242,12 +242,23 @@ test_expect_success 'merge of identical changes in a renamed file' '
      rm -f A M N &&
      git reset --hard &&
      git checkout change+rename &&
+
+     test-tool chmtime =31337 B &&
+     test-tool chmtime --get B >old-mtime &&

Nit: I think it's possible to change the mtime and print it in a single invocation with:

Quoted 1 line
  test-tool chmtime --get =1234 file

Oh, cool.

Quoted 7 lines

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 248

Quoted 1 line
t/t6022-merge-rename.sh +0 -0
      GIT_MERGE_VERBOSITY=3 git merge change >out &&

Nit: The output of 'git merge' is still redirected to a file, but ...

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 246

Quoted 1 line
t/t6022-merge-rename.sh +0 -1
-     test_i18ngrep "^Skipped B" out &&

... the only command looking at the output is now removed.

Indeed.

Quoted 37 lines

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 250

Quoted 10 lines
t/t6022-merge-rename.sh +6 -1
+     test-tool chmtime --get B >new-mtime &&
+     test_cmp old-mtime new-mtime &&
+
      git reset --hard HEAD^ &&
      git checkout change &&
+
+     test-tool chmtime =-1 M &&
+     test-tool chmtime --get M >old-mtime &&
      GIT_MERGE_VERBOSITY=3 git merge change+rename >out &&
-     test_i18ngrep ! "^Skipped B" out

Likewise.

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 259

Quoted 2 lines
t/t6022-merge-rename.sh +2 -0
+     test-tool chmtime --get B >new-mtime &&
+     test $(cat old-mtime) -lt $(cat new-mtime)

I saw this test fail today in one of my custom CI builds:

+git checkout change
Switched to branch 'change'
+test-tool chmtime =-1 M
+test-tool chmtime --get M +GIT_MERGE_VERBOSITY=3 git merge change+rename +test-tool chmtime --get B
+cat old-mtime
+cat new-mtime
+test 1583967731 -lt 1583967731
error: last command exited with $?=1
not ok 12 - merge of identical changes in a renamed file

The contents of 'out', i.e. the output of the 'git merge' command before the failure is:

Auto-merging B
Merge made by the 'recursive' strategy.

   A => B | 0
   1 file changed, 0 insertions(+), 0 deletions(-)
Quoted 7 lines

rename A => B (100%)

This is a rare failure, this is the first time I saw it, and to make things worse, this one time it happened on big-endian and with all the GIT_TEST_* knobs enabled.

https://travis-ci.org/github/szeder/git-cooking-topics-for-travis-ci/jobs/661294571#L4020

This is very troubling. The workflow is basically:
- Manually set the mtime to a file to something old (I happened to
pick 1 second before now, but picking something from 1970 would have been fine too).
- Run a merge which is known to need to overwrite the file. Your
output ("Auto-merging B") suggests that we should have been in such a case.
- Verify that the file was actually updated as expected. Since the
OS is supposed to update the mtime when it writes the file, it should have set it to something recent, i.e. something *different* than what it had before.

So, now I'm left wondering how the mtime possibly could have been not updated. Maybe the file wasn't actually written? (But if so, why didn't other people see the failure? Or your stress runs not see it?)
Or maybe it was written but all file contents and metadata were
delayed in writing to disk such that a subsequent command still sees the old file?? Or maybe it was written but the mtime update was delayed and the test was able to check it in that intermediate state??? Or perhaps the mtime check before the merge raced with the setting of the mtime backwards and got the mtime before it was rewound????

Quoted 2 lines

I don't have a plausible scenario under which any of these should be possible; I'm at a loss.

Hmm. Maybe leap seconds, or clock updates via ntp at an unfortunate time? Perhaps just setting the "old" time to something more than one second in the past would avoid this?

Anyone have a clue if this is a useful guess or not?

#8 lore raw

Re: [PATCH 4/5] t6022, t6046: test expected behavior instead of testing a proxy for it

Quoted 119 lines · Elijah Newren
Quoted 118 lines · Elijah Newren
Quoted 34 lines · SZEDER Gábor
Quoted 22 lines · Elijah Newren via GitGitGadget

From: Elijah Newren <[email protected]>

In t6022, we were testing for file being overwritten (or not) based on an output message instead of checking for the file being overwritten. Since we can check for the file being overwritten via mtime updates, check that instead.

In t6046, we were largely checking for both the expected behavior and a proxy for it, which is unnecessary. The calls to test-tool also were a bit cryptic. Make them a little clearer.

---
 t/t6022-merge-rename.sh                | 15 ++++-
 t/t6046-merge-skip-unneeded-updates.sh | 89 +++++++++++++++++---------
 2 files changed, 70 insertions(+), 34 deletions(-)
t/t6022-merge-rename.sh +0 -0
index 6f196aaf276..d97cf48495b 100755

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 247

Quoted 6 lines
t/t6022-merge-rename.sh +3 -0
@@ -242,12 +242,23 @@ test_expect_success 'merge of identical changes in a renamed file' '
      rm -f A M N &&
      git reset --hard &&
      git checkout change+rename &&
+
+     test-tool chmtime =31337 B &&
+     test-tool chmtime --get B >old-mtime &&

Nit: I think it's possible to change the mtime and print it in a single invocation with:

Quoted 1 line
  test-tool chmtime --get =1234 file

Oh, cool.

Quoted 7 lines

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 248

Quoted 1 line
t/t6022-merge-rename.sh +0 -0
      GIT_MERGE_VERBOSITY=3 git merge change >out &&

Nit: The output of 'git merge' is still redirected to a file, but ...

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 246

Quoted 1 line
t/t6022-merge-rename.sh +0 -1
-     test_i18ngrep "^Skipped B" out &&

... the only command looking at the output is now removed.

Indeed.

Quoted 37 lines

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 250

Quoted 10 lines
t/t6022-merge-rename.sh +6 -1
+     test-tool chmtime --get B >new-mtime &&
+     test_cmp old-mtime new-mtime &&
+
      git reset --hard HEAD^ &&
      git checkout change &&
+
+     test-tool chmtime =-1 M &&
+     test-tool chmtime --get M >old-mtime &&
      GIT_MERGE_VERBOSITY=3 git merge change+rename >out &&
-     test_i18ngrep ! "^Skipped B" out

Likewise.

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 259

Quoted 2 lines
t/t6022-merge-rename.sh +2 -0
+     test-tool chmtime --get B >new-mtime &&
+     test $(cat old-mtime) -lt $(cat new-mtime)

I saw this test fail today in one of my custom CI builds:

+git checkout change
Switched to branch 'change'
+test-tool chmtime =-1 M
+test-tool chmtime --get M +GIT_MERGE_VERBOSITY=3 git merge change+rename +test-tool chmtime --get B
+cat old-mtime
+cat new-mtime
+test 1583967731 -lt 1583967731
error: last command exited with $?=1
not ok 12 - merge of identical changes in a renamed file

The contents of 'out', i.e. the output of the 'git merge' command before the failure is:

Auto-merging B
Merge made by the 'recursive' strategy.

   A => B | 0
   1 file changed, 0 insertions(+), 0 deletions(-)
Quoted 7 lines

rename A => B (100%)

This is a rare failure, this is the first time I saw it, and to make things worse, this one time it happened on big-endian and with all the GIT_TEST_* knobs enabled.

https://travis-ci.org/github/szeder/git-cooking-topics-for-travis-ci/jobs/661294571#L4020

This is very troubling. The workflow is basically:
- Manually set the mtime to a file to something old (I happened to
pick 1 second before now, but picking something from 1970 would have been fine too).
- Run a merge which is known to need to overwrite the file. Your
output ("Auto-merging B") suggests that we should have been in such a case.
- Verify that the file was actually updated as expected. Since the
OS is supposed to update the mtime when it writes the file, it should have set it to something recent, i.e. something *different* than what it had before.

So, now I'm left wondering how the mtime possibly could have been not updated. Maybe the file wasn't actually written? (But if so, why didn't other people see the failure? Or your stress runs not see it?)
Or maybe it was written but all file contents and metadata were
delayed in writing to disk such that a subsequent command still sees the old file?? Or maybe it was written but the mtime update was delayed and the test was able to check it in that intermediate state??? Or perhaps the mtime check before the merge raced with the setting of the mtime backwards and got the mtime before it was rewound????

Quoted 5 lines
Quoted 2 lines

I don't have a plausible scenario under which any of these should be possible; I'm at a loss.

Hmm. Maybe leap seconds, or clock updates via ntp at an unfortunate time?

I'm now fairly confident that 'git merge' is OK, and suspect that it's an issue with Travis CI's s390x environment (multi-architecture support is an alpha-stage feature).

I kicked off a build that only runs 't6022 --stress -r 1,12', and it failed with the same error on s390x fairly quickly, but haven't failed in any of our "standard" CI jobs until the jobs timeouted.

https://travis-ci.org/github/szeder/git/jobs/661647673#L2084

Then I kicked off a build to run the test below with --stress:

  test_expect_success 'test' '
  	touch file &&
  	old=$(test-tool chmtime --get =-1 file) &&
  	touch file &&
  	new=$(test-tool chmtime --get file) &&
  	test $old -lt $new
  '

This failed fairly quickly with the same error on s390x as well.

https://travis-ci.org/github/szeder/git/jobs/661654844#L1275

So I think 'git merge' should be okay, because the failure could be triggered without it as well.

Quoted 4 lines

Perhaps just setting the "old" time to something more than one second in the past would avoid this?

Anyone have a clue if this is a useful guess or not?

I kicked off a build where I set an older timestamp ('=-10' instead of '=-1'), to see what happens, but the s390x job in that build just doesn't want to start... (alpha feature? :) Anyway, the job's output should eventually be available here, will try to check back tomorrow:

https://travis-ci.org/github/szeder/git/jobs/661657781

#11 lore raw

Re: [PATCH 4/5] t6022, t6046: test expected behavior instead of testing a proxy for it

In reply to Elijah Newren via GitGitGadget

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 247

Quoted 11 lines · Elijah Newren via GitGitGadget
t/t6022-merge-rename.sh +3 -0
index 6f196aaf276..d97cf48495b 100755
@@ -242,12 +242,23 @@ test_expect_success 'merge of identical changes in a renamed file' '
 	rm -f A M N &&
 	git reset --hard &&
 	git checkout change+rename &&
+
+	test-tool chmtime =31337 B &&
+	test-tool chmtime --get B >old-mtime &&

Here you compare the mtime of 'B' before ...

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 251

Quoted 5 lines
t/t6022-merge-rename.sh +3 -1
 	GIT_MERGE_VERBOSITY=3 git merge change >out &&
-	test_i18ngrep "^Skipped B" out &&
+
+	test-tool chmtime --get B >new-mtime &&
+	test_cmp old-mtime new-mtime &&

... and after the merge.

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 257

Quoted 6 lines
t/t6022-merge-rename.sh +4 -0
+
 	git reset --hard HEAD^ &&
 	git checkout change &&
+
+	test-tool chmtime =-1 M &&
+	test-tool chmtime --get M >old-mtime &&

Here, however, you compare the mtime of 'M' before the merge ...

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 261

Quoted 5 lines
t/t6022-merge-rename.sh +3 -1
 	GIT_MERGE_VERBOSITY=3 git merge change+rename >out &&
-	test_i18ngrep ! "^Skipped B" out
+
+	test-tool chmtime --get B >new-mtime &&
+	test $(cat old-mtime) -lt $(cat new-mtime)

... with the mtime of 'B' after the merge, i.e. the mtimes of two different files.

Is that right?

#9 lore raw

Re: [PATCH 4/5] t6022, t6046: test expected behavior instead of testing a proxy for it

In reply to SZEDER Gábor
Quoted 55 lines · SZEDER Gábor
Quoted 55 lines
Quoted 54 lines
Quoted 21 lines

I saw this test fail today in one of my custom CI builds:

+git checkout change
Switched to branch 'change'
+test-tool chmtime =-1 M
+test-tool chmtime --get M +GIT_MERGE_VERBOSITY=3 git merge change+rename +test-tool chmtime --get B
+cat old-mtime
+cat new-mtime
+test 1583967731 -lt 1583967731
error: last command exited with $?=1
not ok 12 - merge of identical changes in a renamed file

The contents of 'out', i.e. the output of the 'git merge' command before the failure is:

Auto-merging B
Merge made by the 'recursive' strategy.

   A => B | 0
   1 file changed, 0 insertions(+), 0 deletions(-)
Quoted 7 lines

rename A => B (100%)

This is a rare failure, this is the first time I saw it, and to make things worse, this one time it happened on big-endian and with all the GIT_TEST_* knobs enabled.

https://travis-ci.org/github/szeder/git-cooking-topics-for-travis-ci/jobs/661294571#L4020

This is very troubling. The workflow is basically:
- Manually set the mtime to a file to something old (I happened to
pick 1 second before now, but picking something from 1970 would have been fine too).
- Run a merge which is known to need to overwrite the file. Your
output ("Auto-merging B") suggests that we should have been in such a case.
- Verify that the file was actually updated as expected. Since the
OS is supposed to update the mtime when it writes the file, it should have set it to something recent, i.e. something *different* than what it had before.

So, now I'm left wondering how the mtime possibly could have been not updated. Maybe the file wasn't actually written? (But if so, why didn't other people see the failure? Or your stress runs not see it?)
Or maybe it was written but all file contents and metadata were
delayed in writing to disk such that a subsequent command still sees the old file?? Or maybe it was written but the mtime update was delayed and the test was able to check it in that intermediate state??? Or perhaps the mtime check before the merge raced with the setting of the mtime backwards and got the mtime before it was rewound????

I don't have a plausible scenario under which any of these should be possible; I'm at a loss.

Quoted 6 lines
Quoted 2 lines

Hmm. Maybe leap seconds, or clock updates via ntp at an unfortunate time?

I'm now fairly confident that 'git merge' is OK, and suspect that it's an issue with Travis CI's s390x environment (multi-architecture support is an alpha-stage feature).

I could finally reproduce the issue on my own machine, so apparently it's not an issue in Travis CI's multi-arch environments.

Quoted 7 lines
  test_expect_success 'test' '
  	touch file &&
  	old=$(test-tool chmtime --get =-1 file) &&
  	touch file &&
  	new=$(test-tool chmtime --get file) &&
  	test $old -lt $new
  '

I wanted to report the issue to Travis CI, and in order to do so I turned the above test case into a script that doesn't at all depend on out test framework and 'test-tool' but uses only coreutils commands (with a whole lot of GNUisms...):

cat >timestamp.sh <<-\EOF
#!/bin/sh

set -ex

  i=0
  while true
  do
  	printf "$i\r"
  	i=$((i + 1))
  
  	# set a file's mtime to one second ago
  	now=$(date "+%s.%N")
  	one_sec_ago=$(date -d "@$((${now%.*} - 1))" "+%Y%m%d%H%M%S")
  	touch -t ${one_sec_ago%??}.${one_sec_ago#????????????} file
  	# save its actual mtime
  	old=$(date -r file "+%s.%N")
  	# set its mtime to now
  	touch file
  	# the current the mtime should be different, but sometimes it isn't
  	new=$(date -r file "+%s.%N")
  	test "${old%.*}" != "${new%.*}"
  done
  EOF
  chmod u+x timestamp.sh
  ./timestamp.sh 2>out
  echo
  tail -n11 out

And this script usually fails after a few hundred iterations on my machine:

308
+ date +%s.%N
+ now=1584118408.002458987
+ date -d @1584118407 +%Y%m%d%H%M%S
+ one_sec_ago=20200313175327
+ touch -t 202003131753.27 file
+ date -r file +%s.%N
+ old=1584118407.000000000
+ touch file
+ date -r file +%s.%N
+ new=1584118407.997464837
+ test 1584118407 != 1584118407

Note that the mtime update at the end of the iteration results in an mtime that is _before_ the current time at the beginning of the iteration. Well, I'm puzzled :)

Quoted 2 lines
Quoted 2 lines

Perhaps just setting the "old" time to something more than one second in the past would avoid this?

Yes, setting the old timestamp 2 seconds in the past seems to be sufficient, at least I haven't seen it fail in a few 100k repetitions.

#12 lore raw

Re: [PATCH 4/5] t6022, t6046: test expected behavior instead of testing a proxy for it

In reply to SZEDER Gábor
Quoted 39 lines · SZEDER Gábor

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 247

Quoted 11 lines · Elijah Newren via GitGitGadget
t/t6022-merge-rename.sh +3 -0
index 6f196aaf276..d97cf48495b 100755
@@ -242,12 +242,23 @@ test_expect_success 'merge of identical changes in a renamed file' '
      rm -f A M N &&
      git reset --hard &&
      git checkout change+rename &&
+
+     test-tool chmtime =31337 B &&
+     test-tool chmtime --get B >old-mtime &&

Here you compare the mtime of 'B' before ...

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 251

Quoted 5 lines
t/t6022-merge-rename.sh +3 -1
      GIT_MERGE_VERBOSITY=3 git merge change >out &&
-     test_i18ngrep "^Skipped B" out &&
+
+     test-tool chmtime --get B >new-mtime &&
+     test_cmp old-mtime new-mtime &&

... and after the merge.

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 257

Quoted 6 lines
t/t6022-merge-rename.sh +4 -0
+
      git reset --hard HEAD^ &&
      git checkout change &&
+
+     test-tool chmtime =-1 M &&
+     test-tool chmtime --get M >old-mtime &&

Here, however, you compare the mtime of 'M' before the merge ...

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 261

Quoted 5 lines
t/t6022-merge-rename.sh +3 -1
      GIT_MERGE_VERBOSITY=3 git merge change+rename >out &&
-     test_i18ngrep ! "^Skipped B" out
+
+     test-tool chmtime --get B >new-mtime &&
+     test $(cat old-mtime) -lt $(cat new-mtime)
Quoted 4 lines

... with the mtime of 'B' after the merge, i.e. the mtimes of two different files.

Is that right?

No, sounds like a copy-and-paste-and-forget-to-update bug. Thanks for spotting it. Since you found it, do you want to submit a patch with the fix?

#13 lore raw

Re: [PATCH 4/5] t6022, t6046: test expected behavior instead of testing a proxy for it

Quoted 40 lines · Elijah Newren
Quoted 39 lines · SZEDER Gábor

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 247

Quoted 11 lines · Elijah Newren via GitGitGadget
t/t6022-merge-rename.sh +3 -0
index 6f196aaf276..d97cf48495b 100755
@@ -242,12 +242,23 @@ test_expect_success 'merge of identical changes in a renamed file' '
      rm -f A M N &&
      git reset --hard &&
      git checkout change+rename &&
+
+     test-tool chmtime =31337 B &&
+     test-tool chmtime --get B >old-mtime &&

Here you compare the mtime of 'B' before ...

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 251

Quoted 5 lines
t/t6022-merge-rename.sh +3 -1
      GIT_MERGE_VERBOSITY=3 git merge change >out &&
-     test_i18ngrep "^Skipped B" out &&
+
+     test-tool chmtime --get B >new-mtime &&
+     test_cmp old-mtime new-mtime &&

... and after the merge.

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 257

Quoted 6 lines
t/t6022-merge-rename.sh +4 -0
+
      git reset --hard HEAD^ &&
      git checkout change &&
+
+     test-tool chmtime =-1 M &&
+     test-tool chmtime --get M >old-mtime &&

Here, however, you compare the mtime of 'M' before the merge ...

Quoted 5 lines
t/t6022-merge-rename.sh +3 -1
      GIT_MERGE_VERBOSITY=3 git merge change+rename >out &&
-     test_i18ngrep ! "^Skipped B" out
+
+     test-tool chmtime --get B >new-mtime &&
+     test $(cat old-mtime) -lt $(cat new-mtime)
Quoted 8 lines
Quoted 4 lines

... with the mtime of 'B' after the merge, i.e. the mtimes of two different files.

Is that right?

No, sounds like a copy-and-paste-and-forget-to-update bug. Thanks for spotting it. Since you found it, do you want to submit a patch with the fix?

No :) There is no file 'B' in branch 'change', so I think the fix requires your expertise to make sure that the test checks what it was supposed to check.

#10 lore raw

Re: [PATCH 4/5] t6022, t6046: test expected behavior instead of testing a proxy for it

In reply to SZEDER Gábor
Quoted 125 lines · SZEDER Gábor
Quoted 55 lines · SZEDER Gábor
Quoted 55 lines
Quoted 54 lines
Quoted 21 lines

I saw this test fail today in one of my custom CI builds:

+git checkout change
Switched to branch 'change'
+test-tool chmtime =-1 M
+test-tool chmtime --get M +GIT_MERGE_VERBOSITY=3 git merge change+rename +test-tool chmtime --get B
+cat old-mtime
+cat new-mtime
+test 1583967731 -lt 1583967731
error: last command exited with $?=1
not ok 12 - merge of identical changes in a renamed file

The contents of 'out', i.e. the output of the 'git merge' command before the failure is:

Auto-merging B
Merge made by the 'recursive' strategy.

   A => B | 0
   1 file changed, 0 insertions(+), 0 deletions(-)
Quoted 7 lines

rename A => B (100%)

This is a rare failure, this is the first time I saw it, and to make things worse, this one time it happened on big-endian and with all the GIT_TEST_* knobs enabled.

https://travis-ci.org/github/szeder/git-cooking-topics-for-travis-ci/jobs/661294571#L4020

This is very troubling. The workflow is basically:
- Manually set the mtime to a file to something old (I happened to
pick 1 second before now, but picking something from 1970 would have been fine too).
- Run a merge which is known to need to overwrite the file. Your
output ("Auto-merging B") suggests that we should have been in such a case.
- Verify that the file was actually updated as expected. Since the
OS is supposed to update the mtime when it writes the file, it should have set it to something recent, i.e. something *different* than what it had before.

So, now I'm left wondering how the mtime possibly could have been not updated. Maybe the file wasn't actually written? (But if so, why didn't other people see the failure? Or your stress runs not see it?)
Or maybe it was written but all file contents and metadata were
delayed in writing to disk such that a subsequent command still sees the old file?? Or maybe it was written but the mtime update was delayed and the test was able to check it in that intermediate state??? Or perhaps the mtime check before the merge raced with the setting of the mtime backwards and got the mtime before it was rewound????

I don't have a plausible scenario under which any of these should be possible; I'm at a loss.

Quoted 6 lines
Quoted 2 lines

Hmm. Maybe leap seconds, or clock updates via ntp at an unfortunate time?

I'm now fairly confident that 'git merge' is OK, and suspect that it's an issue with Travis CI's s390x environment (multi-architecture support is an alpha-stage feature).

I could finally reproduce the issue on my own machine, so apparently it's not an issue in Travis CI's multi-arch environments.

Quoted 7 lines
  test_expect_success 'test' '
      touch file &&
      old=$(test-tool chmtime --get =-1 file) &&
      touch file &&
      new=$(test-tool chmtime --get file) &&
      test $old -lt $new
  '

I wanted to report the issue to Travis CI, and in order to do so I turned the above test case into a script that doesn't at all depend on out test framework and 'test-tool' but uses only coreutils commands (with a whole lot of GNUisms...):

cat >timestamp.sh <<-\EOF
#!/bin/sh

set -ex

  i=0
  while true
  do
        printf "$i\r"
        i=$((i + 1))
        # set a file's mtime to one second ago
        now=$(date "+%s.%N")
        one_sec_ago=$(date -d "@$((${now%.*} - 1))" "+%Y%m%d%H%M%S")
        touch -t ${one_sec_ago%??}.${one_sec_ago#????????????} file
        # save its actual mtime
        old=$(date -r file "+%s.%N")
        # set its mtime to now
        touch file
        # the current the mtime should be different, but sometimes it isn't
        new=$(date -r file "+%s.%N")
        test "${old%.*}" != "${new%.*}"
  done
  EOF
  chmod u+x timestamp.sh
  ./timestamp.sh 2>out
  echo
  tail -n11 out

And this script usually fails after a few hundred iterations on my machine:

308
+ date +%s.%N
+ now=1584118408.002458987
+ date -d @1584118407 +%Y%m%d%H%M%S
+ one_sec_ago=20200313175327
+ touch -t 202003131753.27 file
+ date -r file +%s.%N
+ old=1584118407.000000000
+ touch file
+ date -r file +%s.%N
+ new=1584118407.997464837
+ test 1584118407 != 1584118407

Quoted 3 lines

Note that the mtime update at the end of the iteration results in an mtime that is _before_ the current time at the beginning of the iteration. Well, I'm puzzled :)

Interesting...

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.
'''

also, from https://apenwarr.ca/log/20181113 says:

'''
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, perhaps instead of setting the file mtime relative to the current clock (and truncated to the nearest integer), we need to set the file mtime relative to its recorded mtime.

Quoted 2 lines

Yes, setting the old timestamp 2 seconds in the past seems to be sufficient, at least I haven't seen it fail in a few 100k repetitions.

Or yeah, we could just use bigger numbers, but given that wall clock and file-system clock are apparently different, I like the idea of setting them relative to the mtimes that existed before. Looks like test-tool chmtime supports that too, so I'll cook up a patch.

#14 lore raw

Re: [PATCH 4/5] t6022, t6046: test expected behavior instead of testing a proxy for it

In reply to Elijah Newren
Quoted 41 lines · Elijah Newren
Quoted 39 lines · SZEDER Gábor

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 247

Quoted 11 lines · Elijah Newren via GitGitGadget
t/t6022-merge-rename.sh +3 -0
index 6f196aaf276..d97cf48495b 100755
@@ -242,12 +242,23 @@ test_expect_success 'merge of identical changes in a renamed file' '
      rm -f A M N &&
      git reset --hard &&
      git checkout change+rename &&
+
+     test-tool chmtime =31337 B &&
+     test-tool chmtime --get B >old-mtime &&

Here you compare the mtime of 'B' before ...

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 251

Quoted 5 lines
t/t6022-merge-rename.sh +3 -1
      GIT_MERGE_VERBOSITY=3 git merge change >out &&
-     test_i18ngrep "^Skipped B" out &&
+
+     test-tool chmtime --get B >new-mtime &&
+     test_cmp old-mtime new-mtime &&

... and after the merge.

t/t6022-merge-rename.sh test_expect_success 'merge of identical changes in a renamed file' ' · line 257

Quoted 6 lines
t/t6022-merge-rename.sh +4 -0
+
      git reset --hard HEAD^ &&
      git checkout change &&
+
+     test-tool chmtime =-1 M &&
+     test-tool chmtime --get M >old-mtime &&

Here, however, you compare the mtime of 'M' before the merge ...

Quoted 5 lines
t/t6022-merge-rename.sh +3 -1
      GIT_MERGE_VERBOSITY=3 git merge change+rename >out &&
-     test_i18ngrep ! "^Skipped B" out
+
+     test-tool chmtime --get B >new-mtime &&
+     test $(cat old-mtime) -lt $(cat new-mtime)
Quoted 8 lines
Quoted 4 lines

... with the mtime of 'B' after the merge, i.e. the mtimes of two different files.

Is that right?

No, sounds like a copy-and-paste-and-forget-to-update bug. Thanks for spotting it. Since you found it, do you want to submit a patch with the fix?

Actually, it wasn't wrong. Definitely needs some comments explaining the weird construct, though.