{"thread":{"id":"24577","subject":"[RFH] Spurious failures of t0025.[34]","startedAt":"2010-07-29T21:40:01Z","lastAt":"2010-08-05T22:01:28Z","messageCount":4,"participants":["Thomas Rast","Jeff King"],"isPatch":false,"patchVersion":null,"patchTotal":null},"messages":[{"id":"146736","messageId":"201007292340.01836.trast@student.ethz.ch","threadId":"24577","inReplyTo":null,"subject":"[RFH] Spurious failures of t0025.[34]","fromName":"Thomas Rast","fromEmail":"trast@student.ethz.ch","sentAt":"2010-07-29T21:40:01Z","receivedAt":"2010-07-29T21:40:01Z","isPatch":false,"sender":{"key":"tr@thomasrast.ch","avatar":"https://avatars.githubusercontent.com/u/153510?v=4"},"body":"Hi *\n\nI have another hard-to-explain test failure under --valgrind.  I hope\nit's not yet another bug buried deep in valgrind itself...\n\nDoing the following on current next (v1.7.2.1-230-g75e8ac1) stops\nafter a number of iterations, usually within 5 minutes:\n\n  while GIT_SKIP_TESTS=\"t0025.[5-9] t0025.??\" \\\n      ./t0025-crlf-auto.sh --valgrind --root=/dev/shm --tee -i\n  do\n    :\n  done\n\nI can reproduce this both on the machine I use for valgrinding, and my\nwork laptop, and they're quite different:\n\n  openSuSE 11.3, 2.6.34, gcc 4.5.0, glibc 2.11.2\n  RHEL 5.4, 2.6.18, gcc 4.1.2, glibc 2.5\n\nI ordinarily run a bleeding edge valgrind on both (calls itself\n3.6.0SVN) because of the env handling bug from last month, but I also\ntried with valgrind 3.5.0 on the RHEL box, same problem.\n\nIt seems random whether it stops at test 3 or 4, but #4 seems more\nfrequent.  These tests read\n\n  test_expect_success 'crlf=true causes a CRLF file to be normalized' '\n\n          # Backwards compatibility check\n          rm -f .gitattributes tmp one two three &&\n          echo \"two crlf\" > .gitattributes &&\n          git read-tree --reset -u HEAD &&\n\n          # Note, \"normalized\" means that git will normalize it if added\n          has_cr two &&\n          twodiff=`git diff two` &&\n          test -n \"$twodiff\"\n  '\n\n  test_expect_success 'text=true causes a CRLF file to be normalized' '\n\n          rm -f .gitattributes tmp one two three &&\n          echo \"two text\" > .gitattributes &&\n          git read-tree --reset -u HEAD &&\n\n          # Note, \"normalized\" means that git will normalize it if added\n          has_cr two &&\n          twodiff=`git diff two` &&\n          test -n \"$twodiff\"\n  '\n\nI tried patching them in this way:\n\n---- 8< ----\ndiff --git i/t/t0025-crlf-auto.sh w/t/t0025-crlf-auto.sh\nindex f5f67a6..d7424c9 100755\n--- i/t/t0025-crlf-auto.sh\n+++ w/t/t0025-crlf-auto.sh\n@@ -48,8 +48,7 @@ test_expect_success 'crlf=true causes a CRLF file to be normalized' '\n \n \t# Note, \"normalized\" means that git will normalize it if added\n \thas_cr two &&\n-\ttwodiff=`git diff two` &&\n-\ttest -n \"$twodiff\"\n+\ttest_must_fail git diff --exit-code two\n '\n \n test_expect_success 'text=true causes a CRLF file to be normalized' '\n@@ -60,8 +59,7 @@ test_expect_success 'text=true causes a CRLF file to be normalized' '\n \n \t# Note, \"normalized\" means that git will normalize it if added\n \thas_cr two &&\n-\ttwodiff=`git diff two` &&\n-\ttest -n \"$twodiff\"\n+\ttest_must_fail git diff --exit-code two\n '\n \n test_expect_success 'eol=crlf gives a normalized file CRLFs with autocrlf=false' '\n---- >8 ----\n\nUnless I'm too tired, these should be equivalent.  I gained no extra\ninformation by doing so; it just stops at a random iteration with an\nempty diff.  Maybe it shifts the weight slightly towards #3 failing,\nbut that could just as well be the placebo effect, I have not done any\nstatistics.  It looks like\n\n  expecting success: \n\n          rm -f .gitattributes tmp one two three &&\n          echo \"two text\" > .gitattributes &&\n          git read-tree --reset -u HEAD &&\n\n          # Note, \"normalized\" means that git will normalize it if added\n          has_cr two &&\n          xxd two &&\n          test_must_fail git diff --exit-code two\n\n  0000000: 490d 0a61 6d0d 0a76 6572 790d 0a76 6572  I..am..very..ver\n  0000010: 790d 0a66 696e 650d 0a74 6861 6e6b 0d0a  y..fine..thank..\n  0000020: 796f 750d 0a                             you..\n  not ok - 4 text=true causes a CRLF file to be normalized\n  #\n  #\n  #               rm -f .gitattributes tmp one two three &&\n  #               echo \"two text\" > .gitattributes &&\n  #               git read-tree --reset -u HEAD &&\n  #\n  #               # Note, \"normalized\" means that git will normalize it if added\n  #               has_cr two &&\n  #               xxd two &&\n  #               test_must_fail git diff --exit-code two\n  #\n\nI.e., nothing out of the ordinary except that the diff is empty.\n\nSo... does anyone have any ideas what to test next?  Or what might\ncause this?\n\n-- \nThomas Rast\ntrast@{inf,student}.ethz.ch\n"},{"id":"146789","messageId":"20100730182532.GB18544@coredump.intra.peff.net","threadId":"24577","inReplyTo":"201007292340.01836.trast@student.ethz.ch","subject":"Re: [RFH] Spurious failures of t0025.[34]","fromName":"Jeff King","fromEmail":"peff@peff.net","sentAt":"2010-07-30T18:25:33Z","receivedAt":"2010-07-30T18:25:33Z","isPatch":false,"sender":{"key":"peff@peff.net","avatar":"https://avatars.githubusercontent.com/u/45925?v=4"},"body":"On Thu, Jul 29, 2010 at 11:40:01PM +0200, Thomas Rast wrote:\n\n> Doing the following on current next (v1.7.2.1-230-g75e8ac1) stops\n> after a number of iterations, usually within 5 minutes:\n> \n>   while GIT_SKIP_TESTS=\"t0025.[5-9] t0025.??\" \\\n>       ./t0025-crlf-auto.sh --valgrind --root=/dev/shm --tee -i\n>   do\n>     :\n>   done\n\nI was able to reproduce after many iterations on my debian unstable box,\ntoo.\n\nWhat's odd to me is that valgrind reports no error. Which implies to me\nthat it is actually a race condition that is being triggered by how slow\nvalgrind makes us run, but not an actual memory error.\n\n> I tried patching them in this way:\n> \n> ---- 8< ----\n> diff --git i/t/t0025-crlf-auto.sh w/t/t0025-crlf-auto.sh\n> index f5f67a6..d7424c9 100755\n> --- i/t/t0025-crlf-auto.sh\n> +++ w/t/t0025-crlf-auto.sh\n> @@ -48,8 +48,7 @@ test_expect_success 'crlf=true causes a CRLF file to be normalized' '\n>  \n>  \t# Note, \"normalized\" means that git will normalize it if added\n>  \thas_cr two &&\n> -\ttwodiff=`git diff two` &&\n> -\ttest -n \"$twodiff\"\n> +\ttest_must_fail git diff --exit-code two\n\nI also tried doing instead:\n\n  test -n \"$twodiff\" || bash -i\n\nwhich dumped me with a shell in the \"broken\" state. The interesting\nthing is that I can then repeatably run \"git diff two\" and get an empty\ndiff.  So I don't think the error or race condition is in the run of\n\"git diff\" itself, but rather what happened above (presumably the in\nthe read-tree step).\n\n> So... does anyone have any ideas what to test next?  Or what might\n> cause this?\n\nSorry, I am also at a loss, but maybe those hints can help point you in\nthe right direction. The next step for me would be to try running just\nthe read-tree bit in a loop to see if you can get anomalous results.\n\n-Peff\n"},{"id":"146807","messageId":"201007310047.46206.trast@student.ethz.ch","threadId":"24577","inReplyTo":"20100730182532.GB18544@coredump.intra.peff.net","subject":"Re: [RFH] Spurious failures of t0025.[34]","fromName":"Thomas Rast","fromEmail":"trast@student.ethz.ch","sentAt":"2010-07-30T22:47:45Z","receivedAt":"2010-07-30T22:47:45Z","isPatch":false,"sender":{"key":"tr@thomasrast.ch","avatar":"https://avatars.githubusercontent.com/u/153510?v=4"},"body":"Jeff King wrote:\n> which dumped me with a shell in the \"broken\" state. The interesting\n> thing is that I can then repeatably run \"git diff two\" and get an empty\n> diff.  So I don't think the error or race condition is in the run of\n> \"git diff\" itself, but rather what happened above (presumably the in\n> the read-tree step).\n\nThis, and Jonathan's observation about git-apply, finally got me\nsomewhere.  The issue is that the index file has a timestamp different\nfrom the saved mtimes of the file itself.  This can be provoked\ndeterministically by the patch below, even without valgrind; valgrind\nmerely makes it much more likely to happen by slowing down\ngit-read-tree.\n\nNow I don't know what the next step in the chain is.  Who's the\nresident expert on index raciness?  Does git-diff then reindex the\nfile, and in doing so, change the index entry?\n\n\ndiff --git i/t/t0025-crlf-auto.sh w/t/t0025-crlf-auto.sh\nindex f5f67a6..7a9cd3a 100755\n--- i/t/t0025-crlf-auto.sh\n+++ w/t/t0025-crlf-auto.sh\n@@ -46,6 +46,8 @@ test_expect_success 'crlf=true causes a CRLF file to be normalized' '\n \techo \"two crlf\" > .gitattributes &&\n \tgit read-tree --reset -u HEAD &&\n \n+\ttest-chmtime +1 .git/index &&\n+\n \t# Note, \"normalized\" means that git will normalize it if added\n \thas_cr two &&\n \ttwodiff=`git diff two` &&\n@@ -58,6 +60,8 @@ test_expect_success 'text=true causes a CRLF file to be normalized' '\n \techo \"two text\" > .gitattributes &&\n \tgit read-tree --reset -u HEAD &&\n \n+\ttest-chmtime +1 .git/index &&\n+\n \t# Note, \"normalized\" means that git will normalize it if added\n \thas_cr two &&\n \ttwodiff=`git diff two` &&\n\n-- \nThomas Rast\ntrast@{inf,student}.ethz.ch\n"},{"id":"147258","messageId":"201008060001.28734.trast@student.ethz.ch","threadId":"24577","inReplyTo":"201007310047.46206.trast@student.ethz.ch","subject":"Re: [RFH] Spurious failures of t0025.[34]","fromName":"Thomas Rast","fromEmail":"trast@student.ethz.ch","sentAt":"2010-08-05T22:01:28Z","receivedAt":"2010-08-05T22:01:28Z","isPatch":false,"sender":{"key":"tr@thomasrast.ch","avatar":"https://avatars.githubusercontent.com/u/153510?v=4"},"body":"Thomas Rast wrote:\n> Jeff King wrote:\n> > which dumped me with a shell in the \"broken\" state. The interesting\n> > thing is that I can then repeatably run \"git diff two\" and get an empty\n> > diff.  So I don't think the error or race condition is in the run of\n> > \"git diff\" itself, but rather what happened above (presumably the in\n> > the read-tree step).\n>\n> This, and Jonathan's observation about git-apply, finally got me\n> somewhere.  The issue is that the index file has a timestamp different\n> from the saved mtimes of the file itself.  This can be provoked\n> deterministically by the patch below, even without valgrind; valgrind\n> merely makes it much more likely to happen by slowing down\n> git-read-tree.\n>\n> Now I don't know what the next step in the chain is.  Who's the\n> resident expert on index raciness?  Does git-diff then reindex the\n> file, and in doing so, change the index entry?\n\nI did some experiments using ls-files --debug and xxd, and I'm tempted\nto blame it on the \"impossible\" state of the index that results.  The\ndump below was made by inserting 'false' into the crlf=true test as in\n\n---- 8< ----\ndiff --git i/t/t0025-crlf-auto.sh w/t/t0025-crlf-auto.sh\nindex f5f67a6..f2c2c58 100755\n--- i/t/t0025-crlf-auto.sh\n+++ w/t/t0025-crlf-auto.sh\n@@ -46,6 +46,8 @@ test_expect_success 'crlf=true causes a CRLF file to be normalized' '\n \techo \"two crlf\" > .gitattributes &&\n \tgit read-tree --reset -u HEAD &&\n\n+\tfalse &&\n+\n \t# Note, \"normalized\" means that git will normalize it if added\n \thas_cr two &&\n \ttwodiff=`git diff two` &&\n---- >8 ----\n\nand then using the test with -i.  I even disabled __git_ps1 to be sure\nthat nothing touches the repo under my nose.\n\nAt first, all instances I can get at have the CRLF:\n\n  $ git ls-files -s --debug two\n  100644 44fc21c05337594f3e788f058aec8e2f127bb0d7 0       two\n    ctime: 1280668935:778139933\n    mtime: 1280668935:778139933\n    dev: 2054     ino: 5111895\n    uid: 1000     gid: 100\n    size: 37      flags: 3\n  $ xxd two\n  0000000: 490d 0a61 6d0d 0a76 6572 790d 0a76 6572  I..am..very..ver\n  0000010: 790d 0a66 696e 650d 0a74 6861 6e6b 0d0a  y..fine..thank..\n  0000020: 796f 750d 0a                             you..\n  $ git cat-file blob :two | xxd\n  0000000: 490d 0a61 6d0d 0a76 6572 790d 0a76 6572  I..am..very..ver\n  0000010: 790d 0a66 696e 650d 0a74 6861 6e6b 0d0a  y..fine..thank..\n  0000020: 796f 750d 0a                             you..\n  $ git cat-file blob 44fc21c053 | xxd\n  0000000: 490d 0a61 6d0d 0a76 6572 790d 0a76 6572  I..am..very..ver\n  0000010: 790d 0a66 696e 650d 0a74 6861 6e6b 0d0a  y..fine..thank..\n  0000020: 796f 750d 0a                             you..\n\nThis persists even if I remove the file from the worktree and then\nrestore it:\n\n  $ rm two\n  $ git checkout -- two\n  $ git ls-files -s --debug two\n  100644 44fc21c05337594f3e788f058aec8e2f127bb0d7 0       two\n    ctime: 1280669420:849395853\n    mtime: 1280669420:849395853\n    dev: 2054     ino: 5111895\n    uid: 1000     gid: 100\n    size: 37      flags: 3\n  $ git cat-file blob :two | xxd\n  0000000: 490d 0a61 6d0d 0a76 6572 790d 0a76 6572  I..am..very..ver\n  0000010: 790d 0a66 696e 650d 0a74 6861 6e6b 0d0a  y..fine..thank..\n  0000020: 796f 750d 0a                             you..\n\nBut doing it the other way gives a different object in the index:\n\n  $ git rm --cached two\n  rm 'two'\n  $ git add two\n  warning: CRLF will be replaced by LF in two.\n  The file will have its original line endings in your working directory.\n  $ git ls-files -s --debug two\n  100644 666dbf4b28512a26b262e0c9934c3378061cc353 0       two\n    ctime: 1280669420:849395853\n    mtime: 1280669420:849395853\n    dev: 2054     ino: 5111895\n    uid: 1000     gid: 100\n    size: 37      flags: 3\n\nAnd indeed, while the worktree version still has CRLF, the indexed\nversion has only LFs.\n\n  $ xxd two\n  0000000: 490d 0a61 6d0d 0a76 6572 790d 0a76 6572  I..am..very..ver\n  0000010: 790d 0a66 696e 650d 0a74 6861 6e6b 0d0a  y..fine..thank..\n  0000020: 796f 750d 0a                             you..\n  $ git cat-file blob :two | xxd\n  0000000: 490a 616d 0a76 6572 790a 7665 7279 0a66  I.am.very.very.f\n  0000010: 696e 650a 7468 616e 6b0a 796f 750a       ine.thank.you.\n\nAgain nuking from the worktree and restoring from the repository\nfinally gives LFs everywhere.\n\n  $ rm two\n  $ git checkout -- two\n  $ git ls-files -s --debug two\n  100644 666dbf4b28512a26b262e0c9934c3378061cc353 0       two\n    ctime: 1280669504:819361409\n    mtime: 1280669504:819361409\n    dev: 2054     ino: 5111895\n    uid: 1000     gid: 100\n    size: 30      flags: 3\n\n  $ xxd two\n  0000000: 490a 616d 0a76 6572 790a 7665 7279 0a66  I.am.very.very.f\n  0000010: 696e 650a 7468 616e 6b0a 796f 750a       ine.thank.you.\n\n\nSo revisiting the text above\n\n> The issue is that the index file has a timestamp different from the\n> saved mtimes of the file itself.\n>\n> Now I don't know what the next step in the chain is.  Who's the\n> resident expert on index raciness?  Does git-diff then reindex the\n> file, and in doing so, change the index entry?\n\nand having looked at Documentation/technical/racy-git.txt again, my\ncurrent working theory is:\n\n* racy-git defines a file as racily clean if index and stat data agree\n  but also the mtimes of index and file agree, so that we cannot be\n  sure if the file was edited between saving the index and the next\n  tick.\n\n* Therefore, 'two' in the test is racily clean most of the time, but\n  not racy (whether it's clean is probably the main point) when I'm\n  hitting the failure.\n\n* A racily clean file must be inspected again to see whether it is\n  actually clean.  Therefore, git-diff in a \"good\" run will load the\n  worktree copy, convert it to LF, load the index copy, and find that\n  they are different.\n\n* However in a \"bad\" run, the index does not have to be \"doubted\".\n  Apparently it somehow states that the file is still clean, whereas\n  it is not.\n\nSo I think git-read-tree needs to somehow indicate that the file is\nnot clean, even though it actually just wrote out a copy of the blob\nto the worktree.\n\n--\nThomas Rast\ntrast@{inf,student}.ethz.ch\n"}]}