t9106 failure, bisect weirdness

t9106 failure, bisect weirdness

[carbonated beverage]

Hi all,

Just checked out v1.5.3.6 from git, built it on a Debian/stable i386 box,
and got a failure in one of the test suites:

*** t9106-git-svn-dcommit-clobber-series.sh ***
*   ok 1: initialize repo
*   ok 2: (supposedly) non-conflicting change from SVN
*   ok 3: some unrelated changes to git
* FAIL 4: change file but in unrelated area

                test x"`sed -n -e 4p < file`" = x4 &&
                test x"`sed -n -e 7p < file`" = x7 &&
                perl -i -p -e 's/^4$/4444/' file &&
                perl -i -p -e 's/^7$/7777/' file &&
                test x"`sed -n -e 4p < file`" = x4444 &&
                test x"`sed -n -e 7p < file`" = x7777 &&
                git commit -m '4 => 4444, 7 => 7777' file &&
                git svn dcommit &&
                svn up tmp &&
                cd tmp &&
                        test x"`sed -n -e 4p < file`" = x4444 &&
                        test x"`sed -n -e 7p < file`" = x7777 &&
                        test x"`sed -n -e 58p < file`" = x5588 &&
                        test x"`sed -n -e 61p < file`" = x6611

*   ok 5: attempt to dcommit with a dirty index
* failed 1 among 5 test(s)
make[1]: *** [t9106-git-svn-dcommit-clobber-series.sh] Error 1
make[1]: Leaving directory `/home/ramune/src/git/git/t'
make: *** [test] Error 2
ramune/lycaeum:git:

Bisecting gives me:

fb159580a1628947f0a088e24cfe6fe4c81d99d0 is first bad commit
commit fb159580a1628947f0a088e24cfe6fe4c81d99d0
Author: Eric Wong <normalperson@yhbt.net>
Date:   Mon Nov 5 03:21:48 2007 -0800

    git-svn: t9114: verify merge commit message in test

    It's possible that we end up with an incorrect commit message
    in this test after making changes to fix the clobber bug
    in dcommit.

    Signed-off-by: Eric Wong <normalperson@yhbt.net>
    Signed-off-by: Junio C Hamano <gitster@pobox.com>

:040000 040000 1c4f3776c031f9531869e736b661a0559fab5ff6 4f4c5ecd6c79f7e9732b554e2f8dd536a8a8f2a6 M      t

Which seems odd -- the previous commit (marked good, because make test didn't
fail) was the one that modified t9106-git-svn-dcommit-clobber-series.sh.

I tried running the test manually and noticed something weird as well:

ramune/lycaeum:t: sh t9106-git-svn-dcommit-clobber-series.sh
*   ok 1: initialize repo
*   ok 2: (supposedly) non-conflicting change from SVN
*   ok 3: some unrelated changes to git
*   ok 4: change file but in unrelated area
* passed all 4 test(s)
ramune/lycaeum:t:
ramune/lycaeum:t: pwd
/home/ramune/src/git/git/t
ramune/lycaeum:t:
ramune/lycaeum:t: sh t9106-git-svn-dcommit-clobber-series.sh
*   ok 1: initialize repo
*   ok 2: (supposedly) non-conflicting change from SVN
*   ok 3: some unrelated changes to git
* FAIL 4: change file but in unrelated area

                test x"`sed -n -e 4p < file`" = x4 &&
                test x"`sed -n -e 7p < file`" = x7 &&
                perl -i -p -e 's/^4$/4444/' file &&
                perl -i -p -e 's/^7$/7777/' file &&
                test x"`sed -n -e 4p < file`" = x4444 &&
                test x"`sed -n -e 7p < file`" = x7777 &&
                git commit -m '4 => 4444, 7 => 7777' file &&
                git svn dcommit &&
                svn up tmp &&
                cd tmp &&
                        test x"`sed -n -e 4p < file`" = x4444 &&
                        test x"`sed -n -e 7p < file`" = x7777 &&
                        test x"`sed -n -e 58p < file`" = x5588 &&
                        test x"`sed -n -e 61p < file`" = x6611

* failed 1 among 4 test(s)

So it succeeds once, then fails.

/bin/sh is dash 0.5.3-7 from Debian.

Any additional information needed?

-- DN
Daniel

Re: t9106 failure, bisect weirdness

[Christian Couder]

Le mardi 20 novembre 2007, carbonated beverage a écrit :
[...]
> I tried running the test manually and noticed something weird as well:
>
> ramune/lycaeum:t: sh t9106-git-svn-dcommit-clobber-series.sh
> *   ok 1: initialize repo
> *   ok 2: (supposedly) non-conflicting change from SVN
> *   ok 3: some unrelated changes to git
> *   ok 4: change file but in unrelated area
> * passed all 4 test(s)
> ramune/lycaeum:t:
> ramune/lycaeum:t: pwd
> /home/ramune/src/git/git/t
> ramune/lycaeum:t:
> ramune/lycaeum:t: sh t9106-git-svn-dcommit-clobber-series.sh
> *   ok 1: initialize repo
> *   ok 2: (supposedly) non-conflicting change from SVN
> *   ok 3: some unrelated changes to git
> * FAIL 4: change file but in unrelated area
>
>                 test x"`sed -n -e 4p < file`" = x4 &&
>                 test x"`sed -n -e 7p < file`" = x7 &&
>                 perl -i -p -e 's/^4$/4444/' file &&
>                 perl -i -p -e 's/^7$/7777/' file &&
>                 test x"`sed -n -e 4p < file`" = x4444 &&
>                 test x"`sed -n -e 7p < file`" = x7777 &&
>                 git commit -m '4 => 4444, 7 => 7777' file &&
>                 git svn dcommit &&
>                 svn up tmp &&
>                 cd tmp &&
>                         test x"`sed -n -e 4p < file`" = x4444 &&
>                         test x"`sed -n -e 7p < file`" = x7777 &&
>                         test x"`sed -n -e 58p < file`" = x5588 &&
>                         test x"`sed -n -e 61p < file`" = x6611
>
> * failed 1 among 4 test(s)
>
> So it succeeds once, then fails.
>
> /bin/sh is dash 0.5.3-7 from Debian.
>
> Any additional information needed?

Could you try running the test twice when you bisect ?
This way bisecting should give you the real first bad commit. 

Could you also try to find the line that fails in the 4th test ?
For example you could replace all the trailing "&&" in this test with a new 
line that contains "echo $?".

Thanks in advance,
Christian.

Re: t9106 failure, bisect weirdness

[carbonated beverage]

> Could you try running the test twice when you bisect ?
> This way bisecting should give you the real first bad commit. 

I re-ran it several times, and also manually -- there were times it'd
succeed 6 times in a row before failing.  Weird.

Finally, the bisect came down to:

  ramune/lycaeum:git: git bisect good
  c74d9acf20ba0c69bbd67c5b0bb3bd3c2349cebe is first bad commit
  commit c74d9acf20ba0c69bbd67c5b0bb3bd3c2349cebe
  Author: Eric Wong <normalperson@yhbt.net>
  Date:   Mon Nov 5 03:21:47 2007 -0800
  
      git-svn: fix dcommit clobbering when committing a series of diffs

Modifying the failing t9106-git-svn-dcommit-clobber-series.sh test to
add touch statements as so:

  test x\"\`sed -n -e 4p < file\`\" = x4444 && touch '/tmp/eleven' &&
  test x\"\`sed -n -e 7p < file\`\" = x7777 && touch '/tmp/twelve' &&
  test x\"\`sed -n -e 58p < file\`\" = x5588 && touch '/tmp/thirteen' &&
  test x\"\`sed -n -e 61p < file\`\" = x6611

Line 52 was the culprit:

  test x\"\`sed -n -e 58p < file\`\" = x5588 &&

-- DN
Daniel

Re: t9106 failure, bisect weirdness

[Christian Couder]

Le mardi 20 novembre 2007, carbonated beverage a écrit :
> > Could you try running the test twice when you bisect ?
> > This way bisecting should give you the real first bad commit.
>
> I re-ran it several times, and also manually -- there were times it'd
> succeed 6 times in a row before failing.  Weird.
>
> Finally, the bisect came down to:
>
>   ramune/lycaeum:git: git bisect good
>   c74d9acf20ba0c69bbd67c5b0bb3bd3c2349cebe is first bad commit
>   commit c74d9acf20ba0c69bbd67c5b0bb3bd3c2349cebe
>   Author: Eric Wong <normalperson@yhbt.net>
>   Date:   Mon Nov 5 03:21:47 2007 -0800
>
>       git-svn: fix dcommit clobbering when committing a series of diffs

Thanks for having done that. Unfortunately I don't know this part of the 
code, so I cc'ed Eric.

> Modifying the failing t9106-git-svn-dcommit-clobber-series.sh test to
> add touch statements as so:
>
>   test x\"\`sed -n -e 4p < file\`\" = x4444 && touch '/tmp/eleven' &&
>   test x\"\`sed -n -e 7p < file\`\" = x7777 && touch '/tmp/twelve' &&
>   test x\"\`sed -n -e 58p < file\`\" = x5588 && touch '/tmp/thirteen' &&
>   test x\"\`sed -n -e 61p < file\`\" = x6611
>
> Line 52 was the culprit:
>
>   test x\"\`sed -n -e 58p < file\`\" = x5588 &&

Ok thanks for doing that too.
Could you also look at the "file" when the test succeed and when it does not 
and send us both versions and a diff between them (if it's not too big).

Thanks in advance,
Christian.

Re: t9106 failure, bisect weirdness

[carbonated beverage]

> Ok thanks for doing that too.
> Could you also look at the "file" when the test succeed and when it does not 
> and send us both versions and a diff between them (if it's not too big).

Size-wise, they're tiny -- though there's a lot of lines.

The diff:

ramune/lycaeum:t: diff -u works.t fails.t 
--- works.t     2007-11-20 21:54:29.000000000 -0700
+++ fails.t     2007-11-20 21:54:39.000000000 -0700
@@ -55,9 +55,9 @@
 55
 56
 57
-5588
+58
 59
 60
-6611
+61
 62
 63

And the full (working) file:

1
2
3
4444
5
6
7777
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
5588
59
60
6611
62
63

Re: t9106 failure, bisect weirdness

[Eric Wong]

Hi, thanks for the heads up, Christian

carbonated beverage <ramune@net-ronin.org> wrote:
> > Ok thanks for doing that too.
> > Could you also look at the "file" when the test succeed and when it does not 
> > and send us both versions and a diff between them (if it's not too big).
> 
> Size-wise, they're tiny -- though there's a lot of lines.
> 
> The diff:
> 
> ramune/lycaeum:t: diff -u works.t fails.t 
> --- works.t     2007-11-20 21:54:29.000000000 -0700
> +++ fails.t     2007-11-20 21:54:39.000000000 -0700
> @@ -55,9 +55,9 @@
>  55
>  56
>  57
> -5588
> +58
>  59
>  60
> -6611
> +61
>  62
>  63

Ah, these changes should've been made on the svn side.  But I'm betting
a race condition appears on faster computers (which we've seen before in
other tests).

I can't reproduce it at all on any of my boxes, but does the following
one-liner fix it consistently?

Thanks,

From: Eric Wong <normalperson@yhbt.net>
Date: Wed, 21 Nov 2007 00:57:33 -0800
Subject: [PATCH] t9106: fix a race condition that caused svn to miss modifications

carbonated beverage noticed this test was occasionally failing.

Signed-off-by: Eric Wong <normalperson@yhbt.net>
---
 t/t9106-git-svn-dcommit-clobber-series.sh |    1 +
 1 files changed, 1 insertions(+), 0 deletions(-)

diff --git a/t/t9106-git-svn-dcommit-clobber-series.sh b/t/t9106-git-svn-dcommit-clobber-series.sh
index d59acc8..7452546 100755
--- a/t/t9106-git-svn-dcommit-clobber-series.sh
+++ b/t/t9106-git-svn-dcommit-clobber-series.sh
@@ -22,6 +22,7 @@ test_expect_success '(supposedly) non-conflicting change from SVN' "
 	cd tmp &&
 		perl -i -p -e 's/^58\$/5588/' file &&
 		perl -i -p -e 's/^61\$/6611/' file &&
+		poke file &&
 		test x\"\`sed -n -e 58p < file\`\" = x5588 &&
 		test x\"\`sed -n -e 61p < file\`\" = x6611 &&
 		svn commit -m '58 => 5588, 61 => 6611' &&
-- 
Eric Wong

Re: t9106 failure, bisect weirdness

[carbonated beverage]

> I can't reproduce it at all on any of my boxes, but does the following
> one-liner fix it consistently?

FYI, it's a Core 2 Duo @ 2GHz (Thinkpad Z61t).

Yup, I ran the test in a loop, and it went through 15 iterations without
failure.  This patch works for me.

Thanks!

-- DN
Daniel