us icon indicating copy to clipboard operation
us copied to clipboard

TestCompatibility takes more than 10min and panics

Open jkawamoto opened this issue 3 years ago • 4 comments

I'm not sure if there is a bug or just the test needs a long time, but go test panics on the master branch (3e9f269) with this output:

=== RUN   TestCompatibility
panic: test timed out after 10m0s

goroutine 259 [running]:
testing.(*M).startAlarm.func1()
        /usr/local/go/src/testing/testing.go:1618 +0x11f
created by time.goFunc
        /usr/local/go/src/time/sleep.go:167 +0x52

goroutine 1 [chan receive, 9 minutes]:
testing.(*T).Run(0xc000102780, 0x817a3f, 0x11, 0x82a0c0, 0x1)
        /usr/local/go/src/testing/testing.go:1169 +0x5f4
testing.runTests.func1(0xc000102780)
        /usr/local/go/src/testing/testing.go:1439 +0xa7
testing.tRunner(0xc000102780, 0xc000191ce0)
        /usr/local/go/src/testing/testing.go:1123 +0x203
testing.runTests(0xc000140380, 0xa2e240, 0x4, 0x4, 0xbffbd8d621f6198b, 0x8bb30767bc, 0xa349a0, 0xc000139220)
        /usr/local/go/src/testing/testing.go:1437 +0x613
testing.(*M).Run(0xc0001a2080, 0x0)
        /usr/local/go/src/testing/testing.go:1345 +0x3b4
main.main()
        _testmain.go:57 +0x237

goroutine 234 [IO wait, 9 minutes]:
internal/poll.runtime_pollWait(0x7f09f4220f48, 0x72, 0x872380)
        /usr/local/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc0001a2018, 0x72, 0x872300, 0x9e45b0, 0x0)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0xe6
internal/poll.(*pollDesc).waitRead(...)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc0001a2000, 0xc000234000, 0x26, 0x5a0, 0x0, 0x0, 0x0)
        /usr/local/go/src/internal/poll/fd_unix.go:159 +0x23f
net.(*netFD).Read(0xc0001a2000, 0xc000234000, 0x26, 0x5a0, 0xc000133568, 0x4e56fe, 0x0)
        /usr/local/go/src/net/fd_posix.go:55 +0x66
net.(*conn).Read(0xc000128018, 0xc000234000, 0x26, 0x5a0, 0x5a0, 0xc0001336c0, 0x6520ca)
        /usr/local/go/src/net/net.go:182 +0xec
io.ReadAtLeast(0x871c40, 0xc000128018, 0xc000234000, 0x26, 0x5a0, 0x26, 0x0, 0x57a, 0xc000234032)
        /usr/local/go/src/io/io.go:314 +0x9d
io.ReadFull(...)
        /usr/local/go/src/io/io.go:333
lukechampine.com/us/renterhost/mux.readEncryptedFrame(0x871c40, 0xc000128018, 0xc000234000, 0x5a0, 0x5a0, 0x5a0, 0x8758e0, 0xc00015a2a0, 0x5a0, 0x8758e0, ...)
        /data/renterhost/mux/encryption.go:73 +0x99
lukechampine.com/us/renterhost/mux.initiateSettingsHandshake(0x876cc0, 0xc000128018, 0x5a0, 0xa, 0x1176592e000, 0x8758e0, 0xc00015a2a0, 0x0, 0x0, 0x0, ...)
        /data/renterhost/mux/frame.go:130 +0x5b0
lukechampine.com/us/renterhost/mux.Dial(0x876cc0, 0xc000128018, 0xc000294640, 0x20, 0x20, 0xc000128018, 0x0, 0x0)
        /data/renterhost/mux/mux.go:287 +0x36b
lukechampine.com/us/renterhost/mux.TestCompatibility(0xc000082c00)
        /data/renterhost/mux/mux_test.go:344 +0x4c5
testing.tRunner(0xc000082c00, 0x82a0c0)
        /usr/local/go/src/testing/testing.go:1123 +0x203
created by testing.(*T).Run
        /usr/local/go/src/testing/testing.go:1168 +0x5bc

goroutine 235 [IO wait, 9 minutes]:
internal/poll.runtime_pollWait(0x7f09f4221030, 0x72, 0x872380)
        /usr/local/go/src/runtime/netpoll.go:222 +0x55
internal/poll.(*pollDesc).wait(0xc0001a2118, 0x72, 0x872300, 0x9e45b0, 0x0)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:87 +0xe6
internal/poll.(*pollDesc).waitRead(...)
        /usr/local/go/src/internal/poll/fd_poll_runtime.go:92
internal/poll.(*FD).Read(0xc0001a2100, 0xc000234b7a, 0x14, 0x14, 0x0, 0x0, 0x0)
        /usr/local/go/src/internal/poll/fd_unix.go:159 +0x23f
net.(*netFD).Read(0xc0001a2100, 0xc000234b7a, 0x14, 0x14, 0x57a, 0x0, 0x0)
        /usr/local/go/src/net/fd_posix.go:55 +0x66
net.(*conn).Read(0xc0003b0008, 0xc000234b7a, 0x14, 0x14, 0x57a, 0x0, 0x0)
        /usr/local/go/src/net/net.go:182 +0xec
io.ReadAtLeast(0x871c40, 0xc0003b0008, 0xc000234600, 0x58e, 0x58e, 0x58e, 0xa, 0xa, 0x0)
        /usr/local/go/src/io/io.go:314 +0x9d
io.ReadFull(...)
        /usr/local/go/src/io/io.go:333
gitlab.com/NebulousLabs/siamux/mux.readFrame(0x871c40, 0xc0003b0008, 0x8758e0, 0xc000294760, 0x5b400003908, 0x3530333150, 0x0, 0x0, 0x0, 0x0, ...)
        /go/pkg/mod/gitlab.com/!nebulous!labs/[email protected]/mux/frame.go:256 +0x6c5
gitlab.com/NebulousLabs/siamux/mux.(*Mux).managedReadFrame(0xc000168000, 0xe8a468a62b65b571, 0x0, 0x0, 0x0, 0x0, 0x0, 0xda7e35454b26c86a, 0x697d1518feed0d62)
        /go/pkg/mod/gitlab.com/!nebulous!labs/[email protected]/mux/proto.go:328 +0x1d0
gitlab.com/NebulousLabs/siamux/mux.(*Mux).initUpdateSettingsServer(0xc000168000, 0x0, 0x0)
        /go/pkg/mod/gitlab.com/!nebulous!labs/[email protected]/mux/proto.go:223 +0x56
gitlab.com/NebulousLabs/siamux/mux.(*Mux).initServer(0xc000168000, 0xc000126010, 0x876cc0)
        /go/pkg/mod/gitlab.com/!nebulous!labs/[email protected]/mux/proto.go:92 +0xa8
gitlab.com/NebulousLabs/siamux/mux.NewServerMux(0x8757a0, 0xc000126010, 0x876cc0, 0xc0003b0008, 0xda7e35454b26c86a, 0x697d1518feed0d62, 0x11235b5d0257d379, 0xb6286c8d5ed67937, 0xda7f0c089d7726c9, 0xe6c4774eab11d481, ...)
        /go/pkg/mod/gitlab.com/!nebulous!labs/[email protected]/mux/mux.go:287 +0x2ec
lukechampine.com/us/renterhost/mux.TestCompatibility.func1.1(0x875120, 0xc000140060, 0xc000294640, 0xc0003ae080, 0x0, 0x0)
        /data/renterhost/mux/mux_test.go:318 +0x245
lukechampine.com/us/renterhost/mux.TestCompatibility.func1(0xc000066060, 0x875120, 0xc000140060, 0xc000294640, 0xc0003ae080)
        /data/renterhost/mux/mux_test.go:336 +0x5b
created by lukechampine.com/us/renterhost/mux.TestCompatibility
        /data/renterhost/mux/mux_test.go:311 +0x30d

goroutine 277 [select, 9 minutes]:
gitlab.com/NebulousLabs/siamux/mux.(*Mux).threadedPruneClosedStreams(0xc000168000)
        /go/pkg/mod/gitlab.com/!nebulous!labs/[email protected]/mux/mux.go:335 +0x27b
gitlab.com/NebulousLabs/siamux/mux.newMux.func3(0xc000168000)
        /go/pkg/mod/gitlab.com/!nebulous!labs/[email protected]/mux/mux.go:229 +0x39
created by gitlab.com/NebulousLabs/siamux/mux.newMux
        /go/pkg/mod/gitlab.com/!nebulous!labs/[email protected]/mux/mux.go:228 +0x7b9

goroutine 276 [select, 9 minutes]:
gitlab.com/NebulousLabs/siamux/mux.(*Mux).threadedHandleMaxTimeoutCallback(0xc000168000)
        /go/pkg/mod/gitlab.com/!nebulous!labs/[email protected]/mux/keepalive.go:52 +0x2c9
gitlab.com/NebulousLabs/siamux/mux.newMux.func2(0xc000168000)
        /go/pkg/mod/gitlab.com/!nebulous!labs/[email protected]/mux/mux.go:223 +0x39
created by gitlab.com/NebulousLabs/siamux/mux.newMux
        /go/pkg/mod/gitlab.com/!nebulous!labs/[email protected]/mux/mux.go:222 +0x77a

goroutine 278 [chan receive, 9 minutes]:
gitlab.com/NebulousLabs/siamux/mux.newMux.func4(0x875760, 0xc00012c100, 0xc000168000)
        /go/pkg/mod/gitlab.com/!nebulous!labs/[email protected]/mux/mux.go:235 +0x5a
created by gitlab.com/NebulousLabs/siamux/mux.newMux
        /go/pkg/mod/gitlab.com/!nebulous!labs/[email protected]/mux/mux.go:234 +0x80f
FAIL    lukechampine.com/us/renterhost/mux      600.047s

jkawamoto avatar Jan 25 '21 16:01 jkawamoto

Interesting. It looks like mux has already written the settings frame and is stuck waiting for a response, while siamux thinks it has not received the settings frame and is also stuck waiting for it to arrive.

I haven't been able to reproduce this locally. Is it repeatable? What go test command are you using?

lukechampine avatar Jan 26 '21 04:01 lukechampine

I run go test -v -race ./... at the root of the repository on Linux, while I don't get this error on mac.

jkawamoto avatar Jan 26 '21 05:01 jkawamoto

Hmm, still not able to reproduce this on either of my Linux machines. :/

lukechampine avatar Jan 26 '21 23:01 lukechampine

I think you can reproduce this error with this command: docker run -v $(pwd):/data golang sh -c "cd /data && go test -v -race ./..."

jkawamoto avatar Jan 27 '21 00:01 jkawamoto