net: tcpproxy test hangs under Go tip (due to splice), works on Go 1.10 #25985

bradfitz · 2018-06-20T21:24:50Z

https://github.com/google/tcpproxy at git rev dbc151467 has test hangs at Go tip (rev f3f7bd5) but works fine with Go 1.10.

Sometimes it even passes at Go tip, but with -count=20 I've never seen it pass more than a couple times before hanging:

dev:tcpproxy $ GOROOT=$HOME/go1.10 go test -v -run=PROXYOut -count=20 github.com/google/tcpproxy
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
PASS
ok      github.com/google/tcpproxy      0.016s

But with Go tip:

dev:tcpproxy $ GOROOT=$HOME/go go test -v -run=PROXYOut -count=20
=== RUN   TestProxyPROXYOut
--- PASS: TestProxyPROXYOut (0.00s)
=== RUN   TestProxyPROXYOut
....
(hangs)

If I send it SIGQUIT:

^\SIGQUIT: quit
PC=0x45dba1 m=0 sigcode=128

goroutine 0 [idle]:
runtime.futex(0x916360, 0x80, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x7ffc41051530, 0x40bf92, ...)
        /home/bradfitz/go/src/runtime/sys_linux_amd64.s:531 +0x21
runtime.futexsleep(0x916360, 0x0, 0xffffffffffffffff)
        /home/bradfitz/go/src/runtime/os_linux.go:46 +0x4b
runtime.notesleep(0x916360)
        /home/bradfitz/go/src/runtime/lock_futex.go:151 +0xa2
runtime.stopm()
        /home/bradfitz/go/src/runtime/proc.go:2013 +0xe3
runtime.findrunnable(0xc00002cf00, 0x0)
        /home/bradfitz/go/src/runtime/proc.go:2484 +0x4dc
runtime.schedule()
        /home/bradfitz/go/src/runtime/proc.go:2610 +0x13a
runtime.park_m(0xc000001980)
        /home/bradfitz/go/src/runtime/proc.go:2673 +0xae
runtime.mcall(0x0)
        /home/bradfitz/go/src/runtime/asm_amd64.s:299 +0x5b

goroutine 1 [chan receive]:
testing.(*T).Run(0xc000142300, 0x6f75a1, 0x11, 0x708718, 0x477401)
        /home/bradfitz/go/src/testing/testing.go:879 +0x37a
testing.runTests.func1(0xc000142200)
        /home/bradfitz/go/src/testing/testing.go:1119 +0x78
testing.tRunner(0xc000142200, 0xc0000afe08)
        /home/bradfitz/go/src/testing/testing.go:827 +0xbf
testing.runTests(0xc00012c260, 0x910280, 0x9, 0x9, 0x40d22f)
        /home/bradfitz/go/src/testing/testing.go:1117 +0x2a2
testing.(*M).Run(0xc000130000, 0x0)
        /home/bradfitz/go/src/testing/testing.go:1034 +0x165
main.main()
        _testmain.go:58 +0x13d

goroutine 13 [IO wait]:
internal/poll.runtime_pollWait(0x7f47b1a60af0, 0x72, 0xc000059b88)
        /home/bradfitz/go/src/runtime/netpoll.go:173 +0x66
internal/poll.(*pollDesc).wait(0xc000186018, 0x72, 0xffffffffffffff00, 0x73fbe0, 0x8de450)
        /home/bradfitz/go/src/internal/poll/fd_poll_runtime.go:85 +0x9a
internal/poll.(*pollDesc).waitRead(0xc000186018, 0xc00018c000, 0x5d1, 0x5d1)
        /home/bradfitz/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Read(0xc000186000, 0xc00018c02f, 0x5d1, 0x5d1, 0x0, 0x0, 0x0)
        /home/bradfitz/go/src/internal/poll/fd_unix.go:163 +0x179
net.(*netFD).Read(0xc000186000, 0xc00018c02f, 0x5d1, 0x5d1, 0x3, 0x0, 0x0)
        /home/bradfitz/go/src/net/fd_unix.go:203 +0x4f
net.(*conn).Read(0xc000180008, 0xc00018c02f, 0x5d1, 0x5d1, 0x0, 0x0, 0x0)
        /home/bradfitz/go/src/net/net.go:176 +0x68
bytes.(*Buffer).ReadFrom(0xc000188000, 0x73f040, 0xc000180008, 0xc000059d60, 0x59c0b8, 0xc000186000)
        /home/bradfitz/go/src/bytes/buffer.go:206 +0xb4
io/ioutil.readAll(0x73f040, 0xc000180008, 0x200, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/bradfitz/go/src/io/ioutil/ioutil.go:36 +0xb5
io/ioutil.ReadAll(0x73f040, 0xc000180008, 0xc000180008, 0x73f040, 0xc000180008, 0x0, 0x0)
        /home/bradfitz/go/src/io/ioutil/ioutil.go:45 +0x3e
github.com/google/tcpproxy.TestProxyPROXYOut(0xc000142300)
        /home/bradfitz/src/github.com/google/tcpproxy/tcpproxy_test.go:316 +0x529
testing.tRunner(0xc000142300, 0x708718)
        /home/bradfitz/go/src/testing/testing.go:827 +0xbf
created by testing.(*T).Run
        /home/bradfitz/go/src/testing/testing.go:878 +0x353

goroutine 15 [chan receive]:
github.com/google/tcpproxy.(*Proxy).awaitFirstError(0xc000010a00, 0xc0000704e0)
        /home/bradfitz/src/github.com/google/tcpproxy/tcpproxy.go:210 +0x3d
created by github.com/google/tcpproxy.(*Proxy).Start
        /home/bradfitz/src/github.com/google/tcpproxy/tcpproxy.go:205 +0x3e7

goroutine 14 [IO wait]:
internal/poll.runtime_pollWait(0x7f47b1a60f00, 0x72, 0x0)
        /home/bradfitz/go/src/runtime/netpoll.go:173 +0x66
internal/poll.(*pollDesc).wait(0xc000130398, 0x72, 0xc000148000, 0x0, 0x0)
        /home/bradfitz/go/src/internal/poll/fd_poll_runtime.go:85 +0x9a
internal/poll.(*pollDesc).waitRead(0xc000130398, 0xffffffffffffff00, 0x0, 0x0)
        /home/bradfitz/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.(*FD).Accept(0xc000130380, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0)
        /home/bradfitz/go/src/internal/poll/fd_unix.go:378 +0x1a0
net.(*netFD).accept(0xc000130380, 0xc00000e080, 0x0, 0x0)
        /home/bradfitz/go/src/net/fd_unix.go:239 +0x42
net.(*TCPListener).accept(0xc00000e070, 0xc000048748, 0xc000048750, 0x38)
        /home/bradfitz/go/src/net/tcpsock_posix.go:139 +0x2e
net.(*TCPListener).Accept(0xc00000e070, 0x7086d8, 0xc000010a00, 0x742ae0, 0xc00000e080)
        /home/bradfitz/go/src/net/tcpsock.go:260 +0x47
github.com/google/tcpproxy.(*Proxy).serveListener(0xc000010a00, 0xc0000704e0, 0x7416a0, 0xc00000e070, 0xc00005cf30, 0x1, 0x1)
        /home/bradfitz/src/github.com/google/tcpproxy/tcpproxy.go:216 +0x8d
created by github.com/google/tcpproxy.(*Proxy).Start
        /home/bradfitz/src/github.com/google/tcpproxy/tcpproxy.go:203 +0x20f

goroutine 16 [semacquire]:
internal/poll.runtime_Semacquire(0xc0001305a8)
        /home/bradfitz/go/src/runtime/sema.go:61 +0x39
internal/poll.(*FD).Close(0xc000130580, 0xc000130580, 0x0)
        /home/bradfitz/go/src/internal/poll/fd_unix.go:106 +0xde
net.(*netFD).Close(0xc000130580, 0xc000156000, 0x742af8)
        /home/bradfitz/go/src/net/fd_unix.go:185 +0x4f
net.(*conn).Close(0xc00000e080, 0x0, 0x0)
        /home/bradfitz/go/src/net/net.go:200 +0x4a
github.com/google/tcpproxy.(*DialProxy).HandleConn(0xc000010a40, 0x742ae0, 0xc00000e080)
        /home/bradfitz/src/github.com/google/tcpproxy/tcpproxy.go:388 +0x405
github.com/google/tcpproxy.(*Proxy).serveConn(0xc000010a00, 0x742ae0, 0xc00000e080, 0xc00005cf30, 0x1, 0x1, 0x1)
        /home/bradfitz/src/github.com/google/tcpproxy/tcpproxy.go:239 +0x2df
created by github.com/google/tcpproxy.(*Proxy).serveListener
        /home/bradfitz/src/github.com/google/tcpproxy/tcpproxy.go:221 +0x76

goroutine 35 [IO wait]:
internal/poll.runtime_pollWait(0x7f47b1a60d60, 0x72, 0x6)
        /home/bradfitz/go/src/runtime/netpoll.go:173 +0x66
internal/poll.(*pollDesc).wait(0xc000130698, 0x72, 0xffffffffffffff00, 0x73fbe0, 0x8de450)
        /home/bradfitz/go/src/internal/poll/fd_poll_runtime.go:85 +0x9a
internal/poll.(*pollDesc).waitRead(0xc000130698, 0x0, 0x400000, 0x2)
        /home/bradfitz/go/src/internal/poll/fd_poll_runtime.go:90 +0x3d
internal/poll.spliceDrain(0xd, 0xc000130680, 0x400000, 0x0, 0x0, 0x0)
        /home/bradfitz/go/src/internal/poll/splice_linux.go:92 +0x99
internal/poll.Splice(0xc000130580, 0xc000130680, 0x4000000000000000, 0x0, 0xc000049500, 0x0, 0x0, 0x0, 0x0)
        /home/bradfitz/go/src/internal/poll/splice_linux.go:57 +0x215
net.splice(0xc000130580, 0x73f040, 0xc00000e088, 0xc000156000, 0x4, 0xc000049648, 0x406c7c)
        /home/bradfitz/go/src/net/splice_linux.go:30 +0xa8
net.(*TCPConn).readFrom(0xc00000e080, 0x73f040, 0xc00000e088, 0xc000049680, 0x40b63d, 0x6a84a0)
        /home/bradfitz/go/src/net/tcpsock_posix.go:48 +0x46
net.(*TCPConn).ReadFrom(0xc00000e080, 0x73f040, 0xc00000e088, 0x7f47b1a61100, 0xc00000e080, 0x456e01)
        /home/bradfitz/go/src/net/tcpsock.go:103 +0x5d
io.copyBuffer(0x73f060, 0xc00000e080, 0x73f040, 0xc00000e088, 0x0, 0x0, 0x0, 0x1, 0x1000000000001, 0x1)
        /home/bradfitz/go/src/io/io.go:388 +0x303
io.Copy(0x73f060, 0xc00000e080, 0x73f040, 0xc00000e088, 0xc000088720, 0x0, 0x1)
        /home/bradfitz/go/src/io/io.go:364 +0x5a
github.com/google/tcpproxy.proxyCopy(0xc000070600, 0x73f060, 0xc00000e080, 0x73f040, 0xc00000e088)
        /home/bradfitz/src/github.com/google/tcpproxy/tcpproxy.go:428 +0x49
created by github.com/google/tcpproxy.(*DialProxy).HandleConn
        /home/bradfitz/src/github.com/google/tcpproxy/tcpproxy.go:385 +0x338

rax    0xca
rbx    0x916220
rcx    0x45dba3
rdx    0x0
rdi    0x916360
rsi    0x80
rbp    0x7ffc410514f8
rsp    0x7ffc410514b0
r8     0x0
r9     0x0
r10    0x0
r11    0x286
r12    0x8
r13    0x33
r14    0x73a9a0
r15    0x0
rip    0x45dba1
rflags 0x286
cs     0x33
fs     0x0
gs     0x0
exit status 2
FAIL    github.com/google/tcpproxy      18.931s

If I disable the splice support (f2316c2) in Go 1.11 (with just an added return statement at the top of splice_linux.go's func splice), then it works again.

/cc @acln0 @danderson

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

bradfitz · 2018-06-20T21:38:24Z

This Close blocking is suspicious:

goroutine 18 [semacquire]:
internal/poll.runtime_Semacquire(0xc00014e028)
        /home/bradfitz/go/src/runtime/sema.go:61 +0x39
internal/poll.(*FD).Close(0xc00014e000, 0xc00014e000, 0x0)
        /home/bradfitz/go/src/internal/poll/fd_unix.go:106 +0xde
net.(*netFD).Close(0xc00014e000, 0xc000156000, 0x742dd8)
        /home/bradfitz/go/src/net/fd_unix.go:185 +0x4f
net.(*conn).Close(0xc000152000, 0x0, 0x0)
        /home/bradfitz/go/src/net/net.go:200 +0x4a
github.com/google/tcpproxy.(*DialProxy).HandleConn(0xc000010940, 0x742dc0, 0xc000152000)
        /home/bradfitz/src/github.com/google/tcpproxy/tcpproxy.go:399 +0x696
github.com/google/tcpproxy.(*Proxy).serveConn(0xc000010900, 0x742dc0, 0xc000152000, 0xc00005cd90, 0x1, 0x1, 0x5b2ac90b)
        /home/bradfitz/src/github.com/google/tcpproxy/tcpproxy.go:239 +0x2df
created by github.com/google/tcpproxy.(*Proxy).serveListener
        /home/bradfitz/src/github.com/google/tcpproxy/tcpproxy.go:221 +0x76

Not sure the root cause yet. See golang/go#25985.

acln0 · 2018-06-20T21:56:52Z

Investigating.

bradfitz · 2018-06-20T22:01:41Z

Note that we just worked around it with inetaf/tcpproxy@7f81f77 so if you try to reproduce, use the commit just before that.

acln0 · 2018-06-20T22:05:53Z

I can reproduce it. It hangs in exactly the same way on my machine.

acln0 · 2018-06-20T23:42:50Z

It seems like moving this defer to the top of HandleConn fixes the hang in the test, but it is still unclear why the hang was happening in the first place. Perhaps this is a clue. Still investigating.

EDIT: the following test, adapted from the https://github.com/google/tcpproxy code, seems to reproduce the issue reliably from within package net.

func TestSpliceIssue25985(t *testing.T) {
	front, err := newLocalListener("tcp")
	if err != nil {
		t.Fatal(err)
	}
	defer front.Close()
	back, err := newLocalListener("tcp")
	if err != nil {
		t.Fatal(err)
	}
	defer back.Close()

	proxy := func() error {
		src, err := front.Accept()
		if err != nil {
			return err
		}
		dst, err := Dial("tcp", back.Addr().String())
		if err != nil {
			return err
		}
		defer dst.Close()
		defer src.Close()
		errc := make(chan error, 1)
		go func() {
			_, err := io.Copy(src, dst)
			errc <- err
		}()
		go func() {
			_, err := io.Copy(dst, src)
			errc <- err
		}()
		return <-errc
	}

	proxyErrc := make(chan error, 1)
	go func() { proxyErrc <- proxy() }()

	toFront, err := Dial("tcp", front.Addr().String())
	if err != nil {
		t.Fatal(err)
	}

	io.WriteString(toFront, "foo")
	toFront.Close()

	fromProxy, err := back.Accept()
	if err != nil {
		t.Fatal(err)
	}
	defer fromProxy.Close()

	_, err = ioutil.ReadAll(fromProxy)
	if err != nil {
		t.Fatal(err)
	}

	<-proxyErrc
}

This test seems to reinforce the aforementioned observation about changing the order of the deferred Close calls. Furthermore, it exhibits very similar behavior to the original reported issue, including the blocking Close.

EDIT 2: I believe I've figured it out. I think it has to do with the way poll.Splice holds locks. Still not 100% sure the solution is the correct one, but I'll send a CL shortly. Sorry for the trouble.

gopherbot · 2018-06-21T17:28:54Z

Change https://golang.org/cl/120317 mentions this issue: internal/poll: use more fine-grained locking in Splice

bradfitz added NeedsFix The path to resolution is known, but the work has not been done. release-blocker labels Jun 20, 2018

bradfitz added this to the Go1.11 milestone Jun 20, 2018

bradfitz assigned ianlancetaylor Jun 20, 2018

bradfitz added a commit to inetaf/tcpproxy that referenced this issue Jun 20, 2018

Work around deadlock with Go tip (at Go rev f3f7bd5)

7f81f77

Not sure the root cause yet. See golang/go#25985.

gopherbot closed this as completed in 24fb2e0 Jun 21, 2018

golang locked and limited conversation to collaborators Jun 21, 2019

gopherbot added the FrozenDueToAge label Jun 21, 2019

rsc unassigned ianlancetaylor Jun 23, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

net: tcpproxy test hangs under Go tip (due to splice), works on Go 1.10 #25985

net: tcpproxy test hangs under Go tip (due to splice), works on Go 1.10 #25985

bradfitz commented Jun 20, 2018

bradfitz commented Jun 20, 2018

acln0 commented Jun 20, 2018

bradfitz commented Jun 20, 2018

acln0 commented Jun 20, 2018

acln0 commented Jun 20, 2018 •

edited

Loading

gopherbot commented Jun 21, 2018

net: tcpproxy test hangs under Go tip (due to splice), works on Go 1.10 #25985

net: tcpproxy test hangs under Go tip (due to splice), works on Go 1.10 #25985

Comments

bradfitz commented Jun 20, 2018

bradfitz commented Jun 20, 2018

acln0 commented Jun 20, 2018

bradfitz commented Jun 20, 2018

acln0 commented Jun 20, 2018

acln0 commented Jun 20, 2018 • edited Loading

gopherbot commented Jun 21, 2018

acln0 commented Jun 20, 2018 •

edited

Loading