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@xxxxxxxxx> wrote: > > > > On Thu, Mar 12, 2020 at 6:20 AM SZEDER Gábor <szeder.dev@xxxxxxxxx> wrote: > > > > > > On Thu, Feb 27, 2020 at 12:14:23AM +0000, Elijah Newren via GitGitGadget wrote: > > > > From: Elijah Newren <newren@xxxxxxxxx> > > > > > > > > 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@xxxxxxxxx> > > > > --- > > > > 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
