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

From: Elijah Newren <newren@gmail.com>
Date: Mar 12, 2020, 16:48 UTC
Message-ID: <CABPp-BEa7pvqgH+EytGPp2AO5nBmEgW0+7HnjK-e3MqrBnthnA@mail.gmail.com>
In-Reply-To: <20200312132032.GD3122@szeder.dev>

On Thu, Mar 12, 2020 at 6:20 AM SZEDER Gábor <szeder.dev@gmail.com> wrote:

Show 35 quoted lines

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

Show 7 quoted lines

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

Show 44 quoted lines

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