testing: Delay in test causes timeouts in tests that follow it.

[eZanmoto]

1 go version: go version go1.4.2 linux/amd64

2
OS: Linux Mint 16
uname -a: Linux mint 3.11.0-12-generic #19-Ubuntu SMP Wed Oct 9 16:20:46 UTC 2013 x86_64 x86_64 x86_64 GNU/Linux

3 Ran go test with the following test file:

package p

import (
    "net"
    "testing"
    "time"
)

func Test1(t *testing.T) {
    testTunnelWithinSecond(t, time.Millisecond)
}

func Test2(t *testing.T) {
    testTunnelWithinSecond(t, time.Millisecond)
}

func Test3(t *testing.T) {
    testTunnelWithinSecond(t, 0)
}

func Test4(t *testing.T) {
    testTunnelWithinSecond(t, time.Millisecond)
}

func Test5(t *testing.T) {
    testTunnelWithinSecond(t, time.Millisecond)
}

func testTunnelWithinSecond(t *testing.T, timeout time.Duration) {
    ch := make(chan struct{}, 1)

    go func() {
        in, err := pipeConn()
        if err != nil {
            t.Fatalf("Unexpected error: %v", err)
        }

        for err == nil {
            in[1].SetReadDeadline(time.Now().Add(timeout))
            _, err = in[1].Read(make([]byte, 0))
            if e, ok := err.(net.Error); ok && e.Timeout() {
                err = nil
                continue
            }
        }

        close(ch)
    }()

    select {
    case <-time.After(time.Millisecond):
        t.Fatalf("Test timed out")
    case <-ch:
    }
}

// `pipeConn` returns a pair of `net.Conn`s that are connected to each other.
func pipeConn() ([2]net.Conn, error) {
    errs := make(chan error, 1)
    ports := make(chan int, 1)
    conns := make(chan net.Conn, 1)

    go func() {
        ln, err := net.ListenTCP("tcp4", &net.TCPAddr{IP: localhost})
        if err != nil {
            errs <- err
        } else {
            ports <- ln.Addr().(*net.TCPAddr).Port

            conn, err := ln.Accept()
            conns <- conn
            errs <- err
        }
    }()

    select {
    case err := <-errs:
        return [2]net.Conn{nil, nil}, err
    case port := <-ports:
        conn, _ := net.DialTCP(
            "tcp4",
            nil,
            &net.TCPAddr{IP: localhost, Port: port},
        )
        return [2]net.Conn{conn, <-conns}, <-errs
    }
}

var localhost = net.IPv4(127, 0, 0, 1)

4 I expected all tests to pass except for Test3, which I expected to fail with "Test timed out".

5 Test1 and Test2 always passed, but Test4 and Test5 intermittently (but with high probability) failed with "Test timed out". The following script was run to break down the frequency of failures:

import collections
import pprint
import re
import subprocess

output = collections.defaultdict(int)
for i in xrange(100):
    try:
        subprocess.check_output(["go", "test"])
    except subprocess.CalledProcessError, e:
        output[re.sub("0\.\d*s", "", e.output)] += 1

for k, v in output.items():
    print "%d%%" % v
    print '\t' + k.replace('\n', '\n\t')

The above script gave the following results on a sample run, providing preliminary evidence to the presence of cross-contamination of tests.

18%
    --- FAIL: Test3 ()
        tunnel_test.go:52: Test timed out
    --- FAIL: Test4 ()
        tunnel_test.go:52: Test timed out
    FAIL
    exit status 1
    FAIL    bitbucket.com/ezanmoto/repogate/lab 

69%
    --- FAIL: Test3 ()
        tunnel_test.go:52: Test timed out
    --- FAIL: Test4 ()
        tunnel_test.go:52: Test timed out
    --- FAIL: Test5 ()
        tunnel_test.go:52: Test timed out
    FAIL
    exit status 1
    FAIL    bitbucket.com/ezanmoto/repogate/lab 

1%
    --- FAIL: Test3 ()
        tunnel_test.go:52: Test timed out
    FAIL
    exit status 1
    FAIL    bitbucket.com/ezanmoto/repogate/lab 

12%
    --- FAIL: Test3 ()
        tunnel_test.go:52: Test timed out
    --- FAIL: Test5 ()
        tunnel_test.go:52: Test timed out
    FAIL
    exit status 1
    FAIL    bitbucket.com/ezanmoto/repogate/lab 

[minux]

Test3 created a goroutine that is effective busy looping. This affects the pipeConn function, which also relies on scheduling a newly created goroutine to run before it can return. Because your timeout covers both pipeConn call and the real read loop, after Test3 creates the busy looping goroutine, pipeConn calls in Test4 and Test5 might not be able to return within your timeout. You should tear up the goroutine created during tests even if the test fails. I don't see what we can do to fix the behavior.