[4/5] t6022, t6046: test expected behavior instead of testing a proxy for it
diff mbox series

Message ID 26d0c34cd1d4a54dab28d0c9c2242336244e8a3c.1582762465.git.gitgitgadget@gmail.com
State New
Headers show
Series
  • Testcase cleanups (merge related)
Related show

Commit Message

Philippe Blain via GitGitGadget Feb. 27, 2020, 12:14 a.m. UTC
From: Elijah Newren <newren@gmail.com>

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.

Signed-off-by: Elijah Newren <newren@gmail.com>
---
 t/t6022-merge-rename.sh                | 15 ++++-
 t/t6046-merge-skip-unneeded-updates.sh | 89 +++++++++++++++++---------
 2 files changed, 70 insertions(+), 34 deletions(-)

Comments

SZEDER Gábor March 12, 2020, 1:20 p.m. UTC | #1
On Thu, Feb 27, 2020 at 12:14:23AM +0000, Elijah Newren via GitGitGadget wrote:
> From: Elijah Newren <newren@gmail.com>
> 
> 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.
> 
> Signed-off-by: Elijah Newren <newren@gmail.com>
> ---
>  t/t6022-merge-rename.sh                | 15 ++++-
>  t/t6046-merge-skip-unneeded-updates.sh | 89 +++++++++++++++++---------
>  2 files changed, 70 insertions(+), 34 deletions(-)
> 
> diff --git a/t/t6022-merge-rename.sh b/t/t6022-merge-rename.sh
> index 6f196aaf276..d97cf48495b 100755
> --- a/t/t6022-merge-rename.sh
> +++ b/t/t6022-merge-rename.sh
> @@ -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

>  	GIT_MERGE_VERBOSITY=3 git merge change >out &&

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

> -	test_i18ngrep "^Skipped B" out &&

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

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

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

>  test_expect_success 'setup for rename + d/f conflicts' '
> diff --git a/t/t6046-merge-skip-unneeded-updates.sh b/t/t6046-merge-skip-unneeded-updates.sh
> index b7e46698321..962030ecdb6 100755
> --- a/t/t6046-merge-skip-unneeded-updates.sh
> +++ b/t/t6046-merge-skip-unneeded-updates.sh
> @@ -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 &&
> -- 
> gitgitgadget
>
Elijah Newren March 12, 2020, 4:48 p.m. UTC | #2
On Thu, Mar 12, 2020 at 6:20 AM SZEDER Gábor <szeder.dev@gmail.com> wrote:
>
> On Thu, Feb 27, 2020 at 12:14:23AM +0000, Elijah Newren via GitGitGadget wrote:
> > From: Elijah Newren <newren@gmail.com>
> >
> > 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.
> >
> > Signed-off-by: Elijah Newren <newren@gmail.com>
> > ---
> >  t/t6022-merge-rename.sh                | 15 ++++-
> >  t/t6046-merge-skip-unneeded-updates.sh | 89 +++++++++++++++++---------
> >  2 files changed, 70 insertions(+), 34 deletions(-)
> >
> > diff --git a/t/t6022-merge-rename.sh b/t/t6022-merge-rename.sh
> > index 6f196aaf276..d97cf48495b 100755
> > --- a/t/t6022-merge-rename.sh
> > +++ b/t/t6022-merge-rename.sh
> > @@ -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

Oh, cool.

> >       GIT_MERGE_VERBOSITY=3 git merge change >out &&
>
> Nit: The output of 'git merge' is still redirected to a file, but ...
>
> > -     test_i18ngrep "^Skipped B" out &&
>
> ... the only command looking at the output is now removed.

Indeed.

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

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.

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

> 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.
Elijah Newren March 12, 2020, 5:35 p.m. UTC | #3
On Thu, Mar 12, 2020 at 9:48 AM Elijah Newren <newren@gmail.com> wrote:
>
> On Thu, Mar 12, 2020 at 6:20 AM SZEDER Gábor <szeder.dev@gmail.com> wrote:
> >
> > On Thu, Feb 27, 2020 at 12:14:23AM +0000, Elijah Newren via GitGitGadget wrote:
> > > From: Elijah Newren <newren@gmail.com>
> > >
> > > 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.
> > >
> > > Signed-off-by: Elijah Newren <newren@gmail.com>
> > > ---
> > >  t/t6022-merge-rename.sh                | 15 ++++-
> > >  t/t6046-merge-skip-unneeded-updates.sh | 89 +++++++++++++++++---------
> > >  2 files changed, 70 insertions(+), 34 deletions(-)
> > >
> > > diff --git a/t/t6022-merge-rename.sh b/t/t6022-merge-rename.sh
> > > index 6f196aaf276..d97cf48495b 100755
> > > --- a/t/t6022-merge-rename.sh
> > > +++ b/t/t6022-merge-rename.sh
> > > @@ -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
>
> Oh, cool.
>
> > >       GIT_MERGE_VERBOSITY=3 git merge change >out &&
> >
> > Nit: The output of 'git merge' is still redirected to a file, but ...
> >
> > > -     test_i18ngrep "^Skipped B" out &&
> >
> > ... the only command looking at the output is now removed.
>
> Indeed.
>
> > > +     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.
> >
> > > +     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
>
> 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.

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?
SZEDER Gábor March 12, 2020, 8:01 p.m. UTC | #4
On Thu, Mar 12, 2020 at 10:35:52AM -0700, Elijah Newren wrote:
> On Thu, Mar 12, 2020 at 9:48 AM Elijah Newren <newren@gmail.com> wrote:
> >
> > On Thu, Mar 12, 2020 at 6:20 AM SZEDER Gábor <szeder.dev@gmail.com> wrote:
> > >
> > > On Thu, Feb 27, 2020 at 12:14:23AM +0000, Elijah Newren via GitGitGadget wrote:
> > > > From: Elijah Newren <newren@gmail.com>
> > > >
> > > > 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.
> > > >
> > > > Signed-off-by: Elijah Newren <newren@gmail.com>
> > > > ---
> > > >  t/t6022-merge-rename.sh                | 15 ++++-
> > > >  t/t6046-merge-skip-unneeded-updates.sh | 89 +++++++++++++++++---------
> > > >  2 files changed, 70 insertions(+), 34 deletions(-)
> > > >
> > > > diff --git a/t/t6022-merge-rename.sh b/t/t6022-merge-rename.sh
> > > > index 6f196aaf276..d97cf48495b 100755
> > > > --- a/t/t6022-merge-rename.sh
> > > > +++ b/t/t6022-merge-rename.sh
> > > > @@ -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
> >
> > Oh, cool.
> >
> > > >       GIT_MERGE_VERBOSITY=3 git merge change >out &&
> > >
> > > Nit: The output of 'git merge' is still redirected to a file, but ...
> > >
> > > > -     test_i18ngrep "^Skipped B" out &&
> > >
> > > ... the only command looking at the output is now removed.
> >
> > Indeed.
> >
> > > > +     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.
> > >
> > > > +     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
> >
> > 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.
> 
> 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.

> 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
SZEDER Gábor March 13, 2020, 5:12 p.m. UTC | #5
On Thu, Feb 27, 2020 at 12:14:23AM +0000, Elijah Newren via GitGitGadget wrote:
> diff --git a/t/t6022-merge-rename.sh b/t/t6022-merge-rename.sh
> index 6f196aaf276..d97cf48495b 100755
> --- a/t/t6022-merge-rename.sh
> +++ b/t/t6022-merge-rename.sh
> @@ -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 ...

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

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

>  	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?
SZEDER Gábor March 13, 2020, 5:17 p.m. UTC | #6
On Thu, Mar 12, 2020 at 09:01:57PM +0100, SZEDER Gábor wrote:
> > > > 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
> > >
> > > 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.
> > 
> > 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.

>   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 :)

> > 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.
Elijah Newren March 13, 2020, 5:18 p.m. UTC | #7
On Fri, Mar 13, 2020 at 10:12 AM SZEDER Gábor <szeder.dev@gmail.com> wrote:
>
> On Thu, Feb 27, 2020 at 12:14:23AM +0000, Elijah Newren via GitGitGadget wrote:
> > diff --git a/t/t6022-merge-rename.sh b/t/t6022-merge-rename.sh
> > index 6f196aaf276..d97cf48495b 100755
> > --- a/t/t6022-merge-rename.sh
> > +++ b/t/t6022-merge-rename.sh
> > @@ -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 ...
>
> >       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.
>
> > +
> >       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 ...
>
> >       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?

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?
SZEDER Gábor March 13, 2020, 5:30 p.m. UTC | #8
On Fri, Mar 13, 2020 at 10:18:29AM -0700, Elijah Newren wrote:
> On Fri, Mar 13, 2020 at 10:12 AM SZEDER Gábor <szeder.dev@gmail.com> wrote:
> >
> > On Thu, Feb 27, 2020 at 12:14:23AM +0000, Elijah Newren via GitGitGadget wrote:
> > > diff --git a/t/t6022-merge-rename.sh b/t/t6022-merge-rename.sh
> > > index 6f196aaf276..d97cf48495b 100755
> > > --- a/t/t6022-merge-rename.sh
> > > +++ b/t/t6022-merge-rename.sh
> > > @@ -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 ...
> >
> > >       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.
> >
> > > +
> > >       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 ...
> >
> > >       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?
> 
> 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.
Elijah Newren March 13, 2020, 5:45 p.m. UTC | #9
On Fri, Mar 13, 2020 at 10:17 AM SZEDER Gábor <szeder.dev@gmail.com> wrote:
>
> On Thu, Mar 12, 2020 at 09:01:57PM +0100, SZEDER Gábor wrote:
> > > > > 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
> > > >
> > > > 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.
> > >
> > > 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.
>
> >   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 :)

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.

> 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.
Elijah Newren March 13, 2020, 6:11 p.m. UTC | #10
On Fri, Mar 13, 2020 at 10:18 AM Elijah Newren <newren@gmail.com> wrote:
>
> On Fri, Mar 13, 2020 at 10:12 AM SZEDER Gábor <szeder.dev@gmail.com> wrote:
> >
> > On Thu, Feb 27, 2020 at 12:14:23AM +0000, Elijah Newren via GitGitGadget wrote:
> > > diff --git a/t/t6022-merge-rename.sh b/t/t6022-merge-rename.sh
> > > index 6f196aaf276..d97cf48495b 100755
> > > --- a/t/t6022-merge-rename.sh
> > > +++ b/t/t6022-merge-rename.sh
> > > @@ -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 ...
> >
> > >       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.
> >
> > > +
> > >       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 ...
> >
> > >       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?
>
> 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.

Patch
diff mbox series

diff --git a/t/t6022-merge-rename.sh b/t/t6022-merge-rename.sh
index 6f196aaf276..d97cf48495b 100755
--- a/t/t6022-merge-rename.sh
+++ b/t/t6022-merge-rename.sh
@@ -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' '
diff --git a/t/t6046-merge-skip-unneeded-updates.sh b/t/t6046-merge-skip-unneeded-updates.sh
index b7e46698321..962030ecdb6 100755
--- a/t/t6046-merge-skip-unneeded-updates.sh
+++ b/t/t6046-merge-skip-unneeded-updates.sh
@@ -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 &&