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

["SZEDER Gábor" <szeder.dev@gmail.com>]

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