t3424: new rebase testcase documenting a stat-dirty-like failure

From: Elijah Newren <[email protected]>

A user discovered a case where they had a stack of 20 simple commits to rebase, and the rebase would succeed in picking the first commit and then error out with a pair of "Could not execute the todo command" and "Your local changes to the following files would be overwritten by merge" messages.

Their steps actually made use of the -i flag, but I switched it over to -m to make it simpler to trigger the bug. With that flag, it bisects back to commit 68aa495b590d (rebase: implement --merge via the interactive machinery, 2018-12-11), but that's misleading. If you change the -m flag to --keep-empty, then the problem persists and will bisect back to 356ee4659bb5 (sequencer: try to commit without forking 'git commit', 2017-11-24)

After playing with the testcase for a bit, I discovered that added --exec "sleep 1" to the command line makes the rebase succeed, making me suspect there is some kind of discard and reloading of caches that lead us to believe that something is stat dirty, but I didn't succeed in digging any further than that.

Signed-off-by Elijah Newren <[email protected]>

---
t3424: new rebase testcase documenting a stat-dirty-like failure

A user discovered a case where they had a stack of 20 simple commits to rebase, and the rebase would succeed in picking the first commit and then error out with a pair of "Could not execute the todo command" and "Your local changes to the following files would be overwritten by merge" messages.

Their steps actually made use of the -i flag, but I switched it over to -m to make it simpler to trigger the bug. With that flag, it bisects back to commit 68aa495b590d (rebase: implement --merge via the interactive machinery, 2018-12-11), but that's misleading. If you change the -m flag to --keep-empty, then the problem persists and will bisect back to 356ee4659bb5 (sequencer: try to commit without forking 'git commit', 2017-11-24)

After playing with the testcase for a bit, I discovered that added --exec "sleep 1" to the command line makes the rebase succeed, making me suspect there is some kind of discard and reloading of caches that lead us to believe that something is stat dirty, but I didn't succeed in digging any further than that.

Published-As: https://github.com/gitgitgadget/git/releases/tag/pr-git-712%2Fnewren%2Fdocument-rebase-failure-v1
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-git-712/newren/document-rebase-failure-v1
Pull-Request: https://github.com/git/git/pull/712

 t/t3424-rebase-across-mode-change.sh | 52 ++++++++++++++++++++++++++++
 1 file changed, 52 insertions(+)
 create mode 100755 t/t3424-rebase-across-mode-change.sh

t/t3424-rebase-across-mode-change.sh new file +52 -0

new file mode 100755
index 00000000000..4d2eb1dd7c6
@@ -0,0 +1,52 @@
+#!/bin/sh
+
+test_description='git rebase across mode change'
+
+. ./test-lib.sh
+
+test_expect_success 'setup' '
+       rm -rf ../stupid &&
+       git init ../stupid &&
+       cd ../stupid &&
+       mkdir DS &&
+       >DS/whatever &&
+       git add DS &&
+       git commit -m base &&
+
+       git branch side1 &&
+       git branch side2 &&
+
+       git checkout side1 &&
+       git rm -rf DS &&
+       ln -s unrelated DS &&
+       git add DS &&
+       git commit -m side1 &&
+
+       git checkout side2 &&
+       >unrelated &&
+       git add unrelated &&
+       git commit -m commit1 &&
+
+       echo >>unrelated &&
+       git commit -am commit2
+'
+
+test_expect_success 'rebase changes with the apply backend' '
+       test_when_finished "git rebase --abort || true" &&
+       git checkout -b apply-backend side2 &&
+       git rebase side1
+'
+
+test_expect_failure 'rebase changes with the merge backend' '
+       test_when_finished "git rebase --abort || true" &&
+       git checkout -b merge-backend side2 &&
+       git rebase -m side1
+'
+
+test_expect_success 'rebase changes with the merge backend with a delay' '
+       test_when_finished "git rebase --abort || true" &&
+       git checkout -b merge-delay-backend side2 &&
+       git rebase -m --exec "sleep 1" side1
+'
+
+test_done

base-commit: e68e29171cc2d6968902e0654b5687fbe1ccb903 --
gitgitgadget

I forgot to add some cc's in GitGitGadget before submitting; adding now...

Quoted 22 lines · Elijah Newren via GitGitGadget

From: Elijah Newren <[email protected]>

A user discovered a case where they had a stack of 20 simple commits to rebase, and the rebase would succeed in picking the first commit and then error out with a pair of "Could not execute the todo command" and "Your local changes to the following files would be overwritten by merge" messages.

Their steps actually made use of the -i flag, but I switched it over to -m to make it simpler to trigger the bug. With that flag, it bisects back to commit 68aa495b590d (rebase: implement --merge via the interactive machinery, 2018-12-11), but that's misleading. If you change the -m flag to --keep-empty, then the problem persists and will bisect back to 356ee4659bb5 (sequencer: try to commit without forking 'git commit', 2017-11-24)

After playing with the testcase for a bit, I discovered that added --exec "sleep 1" to the command line makes the rebase succeed, making me suspect there is some kind of discard and reloading of caches that lead us to believe that something is stat dirty, but I didn't succeed in digging any further than that.

Quoted 32 lines

Signed-off-by Elijah Newren <[email protected]>

---
t3424: new rebase testcase documenting a stat-dirty-like failure

A user discovered a case where they had a stack of 20 simple commits to rebase, and the rebase would succeed in picking the first commit and then error out with a pair of "Could not execute the todo command" and "Your local changes to the following files would be overwritten by merge" messages.

Their steps actually made use of the -i flag, but I switched it over to -m to make it simpler to trigger the bug. With that flag, it bisects back to commit 68aa495b590d (rebase: implement --merge via the interactive machinery, 2018-12-11), but that's misleading. If you change the -m flag to --keep-empty, then the problem persists and will bisect back to 356ee4659bb5 (sequencer: try to commit without forking 'git commit', 2017-11-24)

After playing with the testcase for a bit, I discovered that added --exec "sleep 1" to the command line makes the rebase succeed, making me suspect there is some kind of discard and reloading of caches that lead us to believe that something is stat dirty, but I didn't succeed in digging any further than that.

Published-As: https://github.com/gitgitgadget/git/releases/tag/pr-git-712%2Fnewren%2Fdocument-rebase-failure-v1
Fetch-It-Via: git fetch https://github.com/gitgitgadget/git pr-git-712/newren/document-rebase-failure-v1
Pull-Request: https://github.com/git/git/pull/712

  t/t3424-rebase-across-mode-change.sh | 52 ++++++++++++++++++++++++++++
  1 file changed, 52 insertions(+)

create mode 100755 t/t3424-rebase-across-mode-change.sh

Quoted 6 lines

t/t3424-rebase-across-mode-change.sh new file +0 -0

new file mode 100755
index 00000000000..4d2eb1dd7c6

t/t3424-rebase-across-mode-change.sh line 10

Quoted 10 lines

t/t3424-rebase-across-mode-change.sh new file +10 -0

@@ -0,0 +1,52 @@
+#!/bin/sh
+
+test_description='git rebase across mode change'
+
+. ./test-lib.sh
+
+test_expect_success 'setup' '
+       rm -rf ../stupid &&
+       git init ../stupid &&
+       cd ../stupid &&

Quoted 46 lines

t/t3424-rebase-across-mode-change.sh new file +42 -0

+       mkdir DS &&
+       >DS/whatever &&
+       git add DS &&
+       git commit -m base &&
+
+       git branch side1 &&
+       git branch side2 &&
+
+       git checkout side1 &&
+       git rm -rf DS &&
+       ln -s unrelated DS &&
+       git add DS &&
+       git commit -m side1 &&
+
+       git checkout side2 &&
+       >unrelated &&
+       git add unrelated &&
+       git commit -m commit1 &&
+
+       echo >>unrelated &&
+       git commit -am commit2
+'
+
+test_expect_success 'rebase changes with the apply backend' '
+       test_when_finished "git rebase --abort || true" &&
+       git checkout -b apply-backend side2 &&
+       git rebase side1
+'
+
+test_expect_failure 'rebase changes with the merge backend' '
+       test_when_finished "git rebase --abort || true" &&
+       git checkout -b merge-backend side2 &&
+       git rebase -m side1
+'
+
+test_expect_success 'rebase changes with the merge backend with a delay' '
+       test_when_finished "git rebase --abort || true" &&
+       git checkout -b merge-delay-backend side2 &&
+       git rebase -m --exec "sleep 1" side1
+'
+
+test_done

base-commit: e68e29171cc2d6968902e0654b5687fbe1ccb903 --
gitgitgadget

Hi Elijah

Quoted 26 lines · Elijah Newren

I forgot to add some cc's in GitGitGadget before submitting; adding now...

Quoted 22 lines · Elijah Newren via GitGitGadget

From: Elijah Newren <[email protected]>

A user discovered a case where they had a stack of 20 simple commits to rebase, and the rebase would succeed in picking the first commit and then error out with a pair of "Could not execute the todo command" and "Your local changes to the following files would be overwritten by merge" messages.

Their steps actually made use of the -i flag, but I switched it over to -m to make it simpler to trigger the bug. With that flag, it bisects back to commit 68aa495b590d (rebase: implement --merge via the interactive machinery, 2018-12-11), but that's misleading. If you change the -m flag to --keep-empty, then the problem persists and will bisect back to 356ee4659bb5 (sequencer: try to commit without forking 'git commit', 2017-11-24)

After playing with the testcase for a bit, I discovered that added --exec "sleep 1" to the command line makes the rebase succeed, making me suspect there is some kind of discard and reloading of caches that lead us to believe that something is stat dirty, but I didn't succeed in digging any further than that.

Intriguing - it's strange that it errors out picking commit2, not commit1 I'll try and have a look at it. There seem to be some leftover bits at the start of the test that want removing see below

Quoted 4 lines

t/t3424-rebase-across-mode-change.sh line 10

Quoted 4 lines

t/t3424-rebase-across-mode-change.sh new file +4 -0

+test_expect_success 'setup' '
+       rm -rf ../stupid &&
+       git init ../stupid &&
+       cd ../stupid &&

I think these 3 lines must be left over from you trying this out before making it a test

Quoted 25 lines · Phillip Wood

Hi Elijah

Quoted 21 lines · Elijah Newren

I forgot to add some cc's in GitGitGadget before submitting; adding now...

Quoted 17 lines · Elijah Newren via GitGitGadget

From: Elijah Newren <[email protected]>

A user discovered a case where they had a stack of 20 simple commits to rebase, and the rebase would succeed in picking the first commit and then error out with a pair of "Could not execute the todo command" and "Your local changes to the following files would be overwritten by merge" messages.

Their steps actually made use of the -i flag, but I switched it over to -m to make it simpler to trigger the bug. With that flag, it bisects back to commit 68aa495b590d (rebase: implement --merge via the interactive machinery, 2018-12-11), but that's misleading. If you change the -m flag to --keep-empty, then the problem persists and will bisect back to 356ee4659bb5 (sequencer: try to commit without forking 'git commit', 2017-11-24)

Quoted 5 lines

Quoted 5 lines

Quoted 5 lines

After playing with the testcase for a bit, I discovered that added --exec "sleep 1" to the command line makes the rebase succeed, making me suspect there is some kind of discard and reloading of caches that lead us to believe that something is stat dirty, but I didn't succeed in digging any further than that.

Quoted 3 lines

Intriguing - it's strange that it errors out picking commit2, not commit1 I'll try and have a look at it. There seem to be some leftover bits at the start of the test that want removing see below

I know, right? It's kinda weird.

Quoted 7 lines

Quoted 4 lines

t/t3424-rebase-across-mode-change.sh line 10

Quoted 4 lines

t/t3424-rebase-across-mode-change.sh new file +4 -0

+test_expect_success 'setup' '
+       rm -rf ../stupid &&
+       git init ../stupid &&
+       cd ../stupid &&

I think these 3 lines must be left over from you trying this out before making it a test

Whoops, yes you are exactly right. I'll remove them.

Hi Elijah

Quoted 26 lines · Elijah Newren

Quoted 25 lines · Phillip Wood

Hi Elijah

Quoted 21 lines · Elijah Newren

I forgot to add some cc's in GitGitGadget before submitting; adding now...

Quoted 17 lines · Elijah Newren via GitGitGadget

From: Elijah Newren <[email protected]>

A user discovered a case where they had a stack of 20 simple commits to rebase, and the rebase would succeed in picking the first commit and then error out with a pair of "Could not execute the todo command" and "Your local changes to the following files would be overwritten by merge" messages.

Their steps actually made use of the -i flag, but I switched it over to -m to make it simpler to trigger the bug. With that flag, it bisects back to commit 68aa495b590d (rebase: implement --merge via the interactive machinery, 2018-12-11), but that's misleading. If you change the -m flag to --keep-empty, then the problem persists and will bisect back to 356ee4659bb5 (sequencer: try to commit without forking 'git commit', 2017-11-24)

Quoted 5 lines

Quoted 5 lines

Quoted 5 lines

Quoted 5 lines

After playing with the testcase for a bit, I discovered that added --exec "sleep 1" to the command line makes the rebase succeed, making me suspect there is some kind of discard and reloading of caches that lead us to believe that something is stat dirty, but I didn't succeed in digging any further than that.

I think --exec true would be better as it makes it clear that it's not a timing issue. I've changed do_recursive_merge() to print the mtime and mode of "DS" before and after the merge which gives

HEAD is now at abd8fe3 side1
Rebasing (1/2) # picking commit1
DS mtime, mode before merge 1582109854, 120000
DS mtime, mode after merge 0, 120000
Rebasing (2/2) # picking commit2
DS mtime, mode before merge 0, 120000
error: Your local changes to the following files would be overwritten by merge:
DS

So it looks like the problem is that when we pick commit1 we don't update the index entry for DS properly in merge_trees()

Best Wishes

Phillip

Quoted 17 lines

I think --exec true would be better as it makes it clear that it's not a timing issue. I've changed do_recursive_merge() to print the mtime and mode of "DS" before and after the merge which gives

HEAD is now at abd8fe3 side1
Rebasing (1/2) # picking commit1
DS mtime, mode before merge 1582109854, 120000
DS mtime, mode after merge 0, 120000
Rebasing (2/2) # picking commit2
DS mtime, mode before merge 0, 120000
error: Your local changes to the following files would be overwritten by merge:
DS

So it looks like the problem is that when we pick commit1 we don't update the index entry for DS properly in merge_trees()

Quoted 3 lines

Best Wishes

Phillip

Oh, indeed, so this was my bug. Thanks for jumping in and investigating; I probably should have found that lead but I just didn't. Anyway, with your extra information I dug around for a bit and I think I found the fix. I'll post it soon.

Hi Phillip,

Quoted 14 lines

HEAD is now at abd8fe3 side1
Rebasing (1/2) # picking commit1
DS mtime, mode before merge 1582109854, 120000
DS mtime, mode after merge 0, 120000
Rebasing (2/2) # picking commit2
DS mtime, mode before merge 0, 120000
error: Your local changes to the following files would be overwritten by merge:
DS

So it looks like the problem is that when we pick commit1 we don't update the index entry for DS properly in merge_trees()

Quoted 3 lines

Best Wishes

Phillip

Oh, indeed, so this was my bug. Thanks for jumping in and investigating; I probably should have found that lead but I just didn't. Anyway, with your extra information I dug around for a bit and I think I found the fix. I'll post it soon.

t/t3424-rebase-across-mode-change.sh new file +11 -0

new file mode 100755
index 00000000000..4d2eb1dd7c6
@@ -0,0 +1,52 @@
+#!/bin/sh
+
+test_description='git rebase across mode change'
+
+. ./test-lib.sh
+
+test_expect_success 'setup' '
+	rm -rf ../stupid &&
+	git init ../stupid &&
+	cd ../stupid &&
+	mkdir DS &&

t/t3424-rebase-across-mode-change.sh new file +31 -0

+	git add DS &&
+	git commit -m side1 &&
+
+	git checkout side2 &&
+	>unrelated &&
+	git add unrelated &&
+	git commit -m commit1 &&
+
+	echo >>unrelated &&
+	git commit -am commit2
+'
+
+test_expect_success 'rebase changes with the apply backend' '
+	test_when_finished "git rebase --abort || true" &&
+	git checkout -b apply-backend side2 &&
+	git rebase side1
+'
+
+test_expect_failure 'rebase changes with the merge backend' '
+	test_when_finished "git rebase --abort || true" &&
+	git checkout -b merge-backend side2 &&
+	git rebase -m side1
+'
+
+test_expect_success 'rebase changes with the merge backend with a delay' '
+	test_when_finished "git rebase --abort || true" &&
+	git checkout -b merge-delay-backend side2 &&
+	git rebase -m --exec "sleep 1" side1
+'
+
+test_done

base-commit: e68e29171cc2d6968902e0654b5687fbe1ccb903 --
gitgitgadget

Hi Elijah,

I am awfully short on time these days, so just a very quick observation:

Quoted 23 lines · Elijah Newren via GitGitGadget

t/t3424-rebase-across-mode-change.sh new file +17 -0

new file mode 100755
index 00000000000..4d2eb1dd7c6
@@ -0,0 +1,52 @@
+#!/bin/sh
+
+test_description='git rebase across mode change'
+
+. ./test-lib.sh
+
+test_expect_success 'setup' '
+     rm -rf ../stupid &&
+     git init ../stupid &&
+     cd ../stupid &&
+     mkdir DS &&
+     >DS/whatever &&
+     git add DS &&
+     git commit -m base &&
+
+     git branch side1 &&
+     git branch side2 &&

t/t3424-rebase-across-mode-change.sh line 21

Quoted 4 lines

t/t3424-rebase-across-mode-change.sh new file +4 -0

+
+     git checkout side1 &&
+     git rm -rf DS &&
+     ln -s unrelated DS &&

This requires symbolic links. Therefore it won't work on Windows, and will at least need the SYMLINKS prereq. Maybe there is a way, though, to change the test so it does not require a symbolic link here?

 t/t3424-rebase-across-mode-change.sh | 48 ++++++++++++++++++++++++++++

Quoted 1 line · Elijah Newren via GitGitGadget

 t/t3424-rebase-across-mode-change.sh | 48 ++++++++++++++++++++++++++++

t3424 is already taken by en/rebase-backend topic that has been cooking for some time by now. It seems 342? are all taken and the next available may be t3433 perhaps (please double check with 'pu')?

From: Elijah Newren <[email protected]>

If we need to delete a higher stage entry in the index to place the file at stage 0, then we'll lose that file's stat information. In such situations we may still be able to detect that the file on disk is the version we want (as noted by our comment in the code:
/* do not overwrite file if already present */
), but we do still need to update the mtime since we are creating a new cache_entry for that file. Update the logic used to determine whether we refresh a file's mtime.

Signed-off-by Elijah Newren <[email protected]>

---
 merge-recursive.c                    | 7 +++++--
 t/t3433-rebase-across-mode-change.sh | 2 +-
 2 files changed, 6 insertions(+), 3 deletions(-)

merge-recursive.c +0 -0

index aee1769a7ac..e6f943c5ccc 100644
@@ -998,10 +998,13 @@ static int update_file_flags(struct merge_options *opt,
 		free(buf);

merge-recursive.c +1 -0

+	}
 	return ret;
 }
 

t/t3433-rebase-across-mode-change.sh +1 -1

index f11fc35c3ee..05df964670f 100755
@@ -33,7 +33,7 @@ test_expect_success 'rebase changes with the apply backend' '
 	git rebase side1
 '
 
-test_expect_failure 'rebase changes with the merge backend' '
+test_expect_success 'rebase changes with the merge backend' '
 	test_when_finished "git rebase --abort || true" &&
 	git checkout -b merge-backend side2 &&
 	git rebase -m side1

Quoted 23 lines · Elijah Newren via GitGitGadget

From: Elijah Newren <[email protected]>

If we need to delete a higher stage entry in the index to place the file at stage 0, then we'll lose that file's stat information. In such situations we may still be able to detect that the file on disk is the version we want (as noted by our comment in the code:
/* do not overwrite file if already present */
), but we do still need to update the mtime since we are creating a new cache_entry for that file. Update the logic used to determine whether we refresh a file's mtime.

Signed-off-by Elijah Newren <[email protected]>

---
 merge-recursive.c                    | 7 +++++--
 t/t3433-rebase-across-mode-change.sh | 2 +-
 2 files changed, 6 insertions(+), 3 deletions(-)

merge-recursive.c +0 -0

index aee1769a7ac..e6f943c5ccc 100644
@@ -998,10 +998,13 @@ static int update_file_flags(struct merge_options *opt,
              free(buf);

merge-recursive.c static int update_file_flags(struct merge_options *opt, · line 1006

Quoted 10 lines

merge-recursive.c +4 -2

      }
 update_index:
-     if (!ret && update_cache)
-             if (add_cacheinfo(opt, contents, path, 0, update_wd,
+     if (!ret && update_cache) {
+             int refresh = (!opt->priv->call_depth &&
+                            contents->mode != S_IFGITLINK);
+             if (add_cacheinfo(opt, contents, path, 0, refresh,
                                ADD_CACHE_OK_TO_ADD))
                      return -1;

Hmph, !.call_depth would avoid resetting update_wd to 0, so the only difference this patch makes is when the caller of this helper passed (update_wd == 0) during the outermost merge. We did not tell add_cacheinfo() to refresh, and refresh_cache_entry() was not called. But the new code forces refresh to happen for normal entries. The proposed log message explains that a refresh is needed for a new cache entry, but if I am reading the code correctly, this function is called with !update_wd from two places, one of which is the "Adding %s" /* do not overwrite ... */ the log message mentions.

But the other one? When both sides added identically, we do have an up-to-date result on our side already, so shouldn't we avoid forcing update_wd in that case?

I do not think passing refresh==1 in that case will produce an incorrect result, but doesn't it force an unnecessary refreshing?

Puzzled.

Quoted 10 lines

Hmph, !.call_depth would avoid resetting update_wd to 0, so the only difference this patch makes is when the caller of this helper passed (update_wd == 0) during the outermost merge. We did not tell add_cacheinfo() to refresh, and refresh_cache_entry() was not called. But the new code forces refresh to happen for normal entries. The proposed log message explains that a refresh is needed for a new cache entry, but if I am reading the code correctly, this function is called with !update_wd from two places, one of which is the "Adding %s" /* do not overwrite ... */ the log message mentions.

Quoted 3 lines

But the other one? When both sides added identically, we do have an up-to-date result on our side already, so shouldn't we avoid forcing update_wd in that case?

This change doesn't force update_wd (write out a new file, also implies refreshing is needed), this only forces refreshing (check stat-related fields of existing file).

Quoted 3 lines

I do not think passing refresh==1 in that case will produce an incorrect result, but doesn't it force an unnecessary refreshing?

Quoted 1 line

Puzzled.

It does force a refreshing, and it is a necessary one based on merge-recursive's design. You can verify by putting an "exit 1" right
...
So, this was a bug all along for BOTH cases, we just didn't notice before.