x/net/ipv4: flaky on Windows #17655

bradfitz · 2016-10-28T21:52:30Z

Trybots on the x/net repo sometimes flake on Windows:

https://storage.googleapis.com/go-build-log/1bd39e79/windows-amd64-gce_2c5af62a.log

ok      golang.org/x/net/bpf    0.064s
ok      golang.org/x/net/context    0.186s
ok      golang.org/x/net/context/ctxhttp    0.166s
?       golang.org/x/net/dict   [no test files]
ok      golang.org/x/net/html   0.298s
ok      golang.org/x/net/html/atom  0.045s
ok      golang.org/x/net/html/charset   0.135s
ok      golang.org/x/net/http2  10.806s
?       golang.org/x/net/http2/h2i  [no test files]
ok      golang.org/x/net/http2/hpack    0.059s
ok      golang.org/x/net/icmp   0.177s
ok      golang.org/x/net/idna   0.044s
?       golang.org/x/net/internal/iana  [no test files]
ok      golang.org/x/net/internal/netreflect    0.037s
?       golang.org/x/net/internal/nettest   [no test files]
ok      golang.org/x/net/internal/timeseries    0.041s
FAIL
FAIL    golang.org/x/net/ipv4   0.059s
ok      golang.org/x/net/ipv6   0.039s
ok      golang.org/x/net/lex/httplex    0.046s
ok      golang.org/x/net/netutil    1.024s
ok      golang.org/x/net/proxy  0.080s
ok      golang.org/x/net/publicsuffix   0.190s
ok      golang.org/x/net/trace  0.120s
ok      golang.org/x/net/webdav 0.180s
ok      golang.org/x/net/webdav/internal/xml    0.079s
ok      golang.org/x/net/websocket  0.115s
ok      golang.org/x/net/xsrftoken  0.031s

But why?

That failure doesn't say much.

/cc @mikioh

The text was updated successfully, but these errors were encountered:

mikioh · 2016-10-28T22:36:05Z

If the branch is Go 1.6 or below, it's probably because of some leaked goroutine in test cases. The testing package of Go 1.7 or above can capture such flakiness. If it happens with tip, have no clue, but we can guess that the failure happens at an intersection between testee packages and testing package.

bradfitz · 2016-10-28T22:44:10Z

It's tip.

mikioh · 2016-11-16T08:51:55Z

Just took a look at testing package and I now feel like this is not an issue of ipv4 package. The interesting FAIL followed by FAIL golang.org/x/net/ipv4 0.059s lines mean that the running test process is killed by an observer; in this case a Windows kernel, though, I have no clue on the root cause.

bradfitz · 2016-12-02T01:27:23Z

@aclements, is this something your tool can grep for?

I'm wondering if it's happening enough to worry about.

aclements · 2016-12-02T01:41:25Z

Unfortunately I don't have the logs for the x repos.

bradfitz · 2016-12-06T17:28:45Z

@alexbrainman, are you able to reproduce this flake?

alexbrainman · 2016-12-07T02:41:07Z

are you able to reproduce this flake?

No I cannot. But I can see different error:

c:\dev\src\golang.org\x\net>go version
go version devel +94a4485 Tue Dec 6 22:33:48 2016 +0000 windows/amd64

c:\dev\src\golang.org\x\net>go get -u ./...

c:\dev\src\golang.org\x\net>go test -short ./...
ok      golang.org/x/net/bpf    0.066s
ok      golang.org/x/net/context        0.138s
ok      golang.org/x/net/context/ctxhttp        0.195s
?       golang.org/x/net/dict   [no test files]
ok      golang.org/x/net/html   0.122s
ok      golang.org/x/net/html/atom      0.058s
ok      golang.org/x/net/html/charset   0.051s
ok      golang.org/x/net/http2  9.439s
?       golang.org/x/net/http2/h2i      [no test files]
ok      golang.org/x/net/http2/hpack    0.075s
ok      golang.org/x/net/icmp   0.039s
ok      golang.org/x/net/idna   0.030s
?       golang.org/x/net/internal/iana  [no test files]
ok      golang.org/x/net/internal/netreflect    0.036s
?       golang.org/x/net/internal/nettest       [no test files]
ok      golang.org/x/net/internal/timeseries    0.031s
--- FAIL: TestRawConnMulticastSocketOptions (0.00s)
        multicastsockopt_test.go:88: operation not supported
--- FAIL: TestRawConnUnicastSocketOptions (0.00s)
        unicastsockopt_test.go:101: operation not supported
FAIL
FAIL    golang.org/x/net/ipv4   0.065s
ok      golang.org/x/net/ipv6   0.040s
ok      golang.org/x/net/lex/httplex    0.046s
ok      golang.org/x/net/nettest        0.436s
ok      golang.org/x/net/netutil        1.071s
ok      golang.org/x/net/proxy  0.056s
ok      golang.org/x/net/publicsuffix   0.178s
ok      golang.org/x/net/trace  0.110s
ok      golang.org/x/net/webdav 0.206s
ok      golang.org/x/net/webdav/internal/xml    0.051s
ok      golang.org/x/net/websocket      0.090s
ok      golang.org/x/net/xsrftoken      0.029s

c:\dev\src\golang.org\x\net>

this is running on Windows 7.

Alex

bradfitz · 2016-12-07T06:37:05Z

You want to send a CL to t.Skip those if they get an "operation not supported" error?

bradfitz · 2016-12-07T17:27:34Z

I can reproduce this with gomote.

$ gomote create windows-amd64-gce
$ export MOTE=user-bradfitz-windows-amd64-gce-0
$ gomote push $MOTE
$ gomote run $MOTE go/src/make.bat
$ tar -C ~/src/ -zc golang.org/x/net | gomote puttar -dir=gopath/src $MOTE
$ gomote run -e 'GOPATH=c:/workdir/gopath' $MOTE go/bin/go test -v -run=. -count=500 golang.org/x/net/ipv4  | tee log.txt

See the attached log.txt, which is a mystery: it has no FAIL mentions, except the end.

And the there's no Exit call in the program, and there's no panic anywhere, and no log.Fatal I can see, no Main, .... I'm not sure where it's failing yet.

bradfitz · 2016-12-07T17:36:08Z

@mikioh,

Just took a look at testing package and I now feel like this is not an issue of ipv4 package. The interesting FAIL followed by FAIL golang.org/x/net/ipv4 0.059s lines mean that the running test process is killed by an observer; in this case a Windows kernel, though, I have no clue on the root cause.

Why do you think that?

Maybe there's something in the net or syscall or runtime package that's crashing? Except then we'd expect some sort of stack trace, I assume.

Is there something like strace for Windows, @alexbrainman? If so, probably not a CLI tool, huh?

bradfitz · 2016-12-07T17:37:21Z

Update:

If I add:

func TestMain(m *testing.M) {
        fmt.Println("starting test")
        flag.Parse()
        v := m.Run()
        fmt.Println("test Run complete =", v)
        os.Exit(v)
}

Then it fails like:

=== RUN   TestRawConnUnicastSocketOptions
--- SKIP: TestRawConnUnicastSocketOptions (0.00s)
        unicastsockopt_test.go:86: no access to raw socket allowed on windows
FAIL
test Run complete = 1
exit status 1
FAIL    golang.org/x/net/ipv4   4.642s
Error running run: exit status 1

So it's not just getting killed by the kernel. The Go test does indeed intend to fail itself. But why?

bradfitz · 2016-12-07T17:54:11Z

And verified that stderr isn't being lost:

        unicastsockopt_test.go:86: no access to raw socket allowed on windows
FAIL
stdout test Run complete = 1
stderr test Run complete = 1
exit status 1
FAIL    golang.org/x/net/ipv4   4.904s

bradfitz · 2016-12-07T20:45:54Z

I suspected it was test failures in goroutines, so I audited all 4 in the ipv4 tests. All four looked fine. Modifying the testing package to log a stack on failure, I found:

TEST FAIL:  goroutine 18877 [running]:
testing.(*common).Fail(0xc042923dc0)
        C:/workdir/go/src/testing/testing.go:468 +0xec
testing.(*common).Fail(0xc0428b70a0)
        C:/workdir/go/src/testing/testing.go:458 +0x259
testing.(*common).Error(0xc0428b70a0, 0xc042787fa0, 0x1, 0x1)
        C:/workdir/go/src/testing/testing.go:534 +0x76
golang.org/x/net/ipv4_test.acceptor(0xc0428b70a0, 0x689de0, 0xc04204e1b0, 0xc0426a5440)
        c:/workdir/gopath/src/golang.org/x/net/ipv4/mocktransponder_test.go:17 +0xcd
created by golang.org/x/net/ipv4_test.TestConnUnicastSocketOptions
        c:/workdir/gopath/src/golang.org/x/net/ipv4/unicastsockopt_test.go:34 +0x1a6

But that test looks fine:

        done := make(chan bool)                                                        
        go acceptor(t, ln, done)                                                       
                                                                                       
        c, err := net.Dial("tcp4", ln.Addr().String())                                 
        if err != nil {                                                                
                t.Fatal(err)                                                           
        }                                                                              
        defer c.Close()                                                                
                                                                                       
        testUnicastSocketOptions(t, ipv4.NewConn(c))                                   
                                                                                       
        <-done

Where acceptor (which is only used once, and is in a separate file all by itself) is just:

func acceptor(t *testing.T, ln net.Listener, done chan<- bool) {  
        defer func() { done <- true }()  
  
        c, err := ln.Accept()  
        if err != nil {  
                t.Error(err)  
                return  
        }  
        c.Close()  
}

It's an unbuffered channel, so I'm not sure why that synchronization isn't sufficient to make the message log something.

bradfitz · 2016-12-07T20:56:53Z

Well, https://go-review.googlesource.com/34021 fixes the flakes, but I'm not sure why.

gopherbot · 2016-12-07T21:01:18Z

CL https://golang.org/cl/34021 mentions this issue.

alexbrainman · 2016-12-07T23:30:43Z

Is there something like strace for Windows, @alexbrainman? If so, probably not a CLI tool, huh?

I am not sure what you want. I have used https://technet.microsoft.com/en-us/sysinternals/processmonitor.aspx in old days. Also mksyscall._windows.go has -trace flag.

Alex

bradfitz added this to the Go1.8 milestone Oct 28, 2016

bradfitz assigned mikioh Oct 28, 2016

quentinmit added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Nov 7, 2016

mikioh removed their assignment Nov 16, 2016

bradfitz self-assigned this Dec 7, 2016

gopherbot closed this as completed in golang/net@944c58e Dec 7, 2016

golang locked and limited conversation to collaborators Dec 7, 2017

gopherbot added the FrozenDueToAge label Dec 7, 2017

rsc unassigned bradfitz Jun 23, 2022

x/net/ipv4: flaky on Windows #17655

x/net/ipv4: flaky on Windows #17655

bradfitz commented Oct 28, 2016

mikioh commented Oct 28, 2016

bradfitz commented Oct 28, 2016

mikioh commented Nov 16, 2016

bradfitz commented Dec 2, 2016

aclements commented Dec 2, 2016

bradfitz commented Dec 6, 2016

alexbrainman commented Dec 7, 2016

bradfitz commented Dec 7, 2016

bradfitz commented Dec 7, 2016

bradfitz commented Dec 7, 2016

bradfitz commented Dec 7, 2016

bradfitz commented Dec 7, 2016

bradfitz commented Dec 7, 2016

bradfitz commented Dec 7, 2016

gopherbot commented Dec 7, 2016

alexbrainman commented Dec 7, 2016

x/net/ipv4: flaky on Windows #17655

x/net/ipv4: flaky on Windows #17655

Comments

bradfitz commented Oct 28, 2016

mikioh commented Oct 28, 2016

bradfitz commented Oct 28, 2016

mikioh commented Nov 16, 2016

bradfitz commented Dec 2, 2016

aclements commented Dec 2, 2016

bradfitz commented Dec 6, 2016

alexbrainman commented Dec 7, 2016

bradfitz commented Dec 7, 2016

bradfitz commented Dec 7, 2016

bradfitz commented Dec 7, 2016

bradfitz commented Dec 7, 2016

bradfitz commented Dec 7, 2016

bradfitz commented Dec 7, 2016

bradfitz commented Dec 7, 2016

gopherbot commented Dec 7, 2016

alexbrainman commented Dec 7, 2016