threads / discuss / 10938

t9106 failure, bisect weirdness

Subject: t9106 failure, bisect weirdness

## tl;dr

7 messages between Nov 19, 2007 and Nov 21, 2007.

replies: 6people: 3as markdown or json

carbonated beverage· Nov 19, 2007, 23:06 UTC · lore
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

Christian Couder· Nov 20, 2007, 04:52 UTC · re: carbonated beverage · lore

Re: t9106 failure, bisect weirdness

Le mardi 20 novembre 2007, carbonated beverage a écrit : [...]

Show 40 quoted lines
> 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.

carbonated beverage· Nov 20, 2007, 06:13 UTC · re: Christian Couder · lore

Re: t9106 failure, bisect weirdness

> 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

Christian Couder· Nov 21, 2007, 04:08 UTC · re: carbonated beverage · lore

Re: t9106 failure, bisect weirdness

Le mardi 20 novembre 2007, carbonated beverage a écrit :
Show 15 quoted lines
> > 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.

Show 11 quoted lines
> 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.

carbonated beverage· Nov 21, 2007, 04:56 UTC · re: Christian Couder · lore

Re: t9106 failure, bisect weirdness

> 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
Eric Wong· Nov 21, 2007, 09:10 UTC · re: carbonated beverage · lore

Re: t9106 failure, bisect weirdness

Hi, thanks for the heads up, Christian
carbonated beverage <ramune@net-ronin.org> wrote:
Show 23 quoted lines
> > 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
carbonated beverage· Nov 21, 2007, 09:57 UTC · re: Eric Wong · lore

Re: t9106 failure, bisect weirdness

> 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

← back to recent threads