search

SlyMarbo / spdy

[deprecated] A full-featured SPDY library for the Go language.
BSD 2-Clause "Simplified" License
116 stars 13 forks source link

deadlock when client is used by multiple goroutines #81

Closed jabley closed 9 years ago

jabley commented 9 years ago

Diff below is a test case that reasonably reliably causes the tests to fail for me.

diff --git a/client_test.go b/client_test.go
index a13ca3e..44b9fc6 100644
--- a/client_test.go
+++ b/client_test.go
@@ -11,6 +11,7 @@ import (
    "net/http"
    "net/http/httptest"
    "strings"
+   "sync"
    "testing"

    "github.com/SlyMarbo/spdy"
@@ -55,6 +56,115 @@ func TestClientHead(t *testing.T) {
    }
 }

+func TestClientInGoroutines(t *testing.T) {
+   defer afterTest(t)
+   ts := newServer(robotsTxtHandler)
+   defer ts.Close()
+
+   client := http.DefaultClient
+
+   var wg sync.WaitGroup
+
+   wg.Add(1)
+   go func() {
+       defer wg.Done()
+       r, err := client.Get(ts.URL)
+       var b []byte
+       if err == nil {
+           b, err = pedanticReadAll(r.Body)
+           r.Body.Close()
+       }
+       if err != nil {
+           t.Error(err)
+       } else if s := string(b); !strings.HasPrefix(s, "User-agent:") {
+           t.Errorf("Incorrect page body (did not begin with User-agent): %q", s)
+       }
+   }()
+
+   wg.Add(1)
+   go func() {
+       defer wg.Done()
+       r, err := client.Get(ts.URL)
+       var b []byte
+       if err == nil {
+           b, err = pedanticReadAll(r.Body)
+           r.Body.Close()
+       }
+       if err != nil {
+           t.Error(err)
+       } else if s := string(b); !strings.HasPrefix(s, "User-agent:") {
+           t.Errorf("Incorrect page body (did not begin with User-agent): %q", s)
+       }
+   }()
+
+   wg.Add(1)
+   go func() {
+       defer wg.Done()
+       r, err := client.Get(ts.URL)
+       var b []byte
+       if err == nil {
+           b, err = pedanticReadAll(r.Body)
+           r.Body.Close()
+       }
+       if err != nil {
+           t.Error(err)
+       } else if s := string(b); !strings.HasPrefix(s, "User-agent:") {
+           t.Errorf("Incorrect page body (did not begin with User-agent): %q", s)
+       }
+   }()
+
+   wg.Add(1)
+   go func() {
+       defer wg.Done()
+       r, err := client.Get(ts.URL)
+       var b []byte
+       if err == nil {
+           b, err = pedanticReadAll(r.Body)
+           r.Body.Close()
+       }
+       if err != nil {
+           t.Error(err)
+       } else if s := string(b); !strings.HasPrefix(s, "User-agent:") {
+           t.Errorf("Incorrect page body (did not begin with User-agent): %q", s)
+       }
+   }()
+
+   wg.Add(1)
+   go func() {
+       defer wg.Done()
+       r, err := client.Get(ts.URL)
+       var b []byte
+       if err == nil {
+           b, err = pedanticReadAll(r.Body)
+           r.Body.Close()
+       }
+       if err != nil {
+           t.Error(err)
+       } else if s := string(b); !strings.HasPrefix(s, "User-agent:") {
+           t.Errorf("Incorrect page body (did not begin with User-agent): %q", s)
+       }
+   }()
+
+   wg.Add(1)
+   go func() {
+       defer wg.Done()
+       r, err := client.Get(ts.URL)
+       var b []byte
+       if err == nil {
+           b, err = pedanticReadAll(r.Body)
+           r.Body.Close()
+       }
+       if err != nil {
+           t.Error(err)
+       } else if s := string(b); !strings.HasPrefix(s, "User-agent:") {
+           t.Errorf("Incorrect page body (did not begin with User-agent): %q", s)
+       }
+   }()
+
+   wg.Wait()
+
+}
+
 // FIXME: Fails
 // func TestClientRedirects(t *testing.T) {
 //     defer afterTest(t)

I run go test -v and end up sending SIGQUIT to get a dump of the process.

=== RUN TestExamples
--- PASS: TestExamples (5.43s)
=== RUN TestClient
--- PASS: TestClient (0.02s)
=== RUN TestClientHead
--- PASS: TestClientHead (0.02s)
=== RUN TestClientInGoroutines
2015/03/03 21:32:00 http: TLS handshake error from 127.0.0.1:65001: remote error: bad certificate
2015/03/03 21:32:01 http: TLS handshake error from 127.0.0.1:65002: remote error: bad certificate
SIGQUIT: quit
PC=0x407b3

goroutine 0 [idle]:
runtime.kevent(0x206000000004, 0x0, 0x0, 0x7fff5fbfe9c8, 0x7fff00000040, 0x0, 0x0, 0x0, 0x0, 0x0, ...)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/runtime/sys_darwin_amd64.s:493 +0x23
runtime.netpoll(0x568301, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/runtime/netpoll_kqueue.go:76 +0xcb
findrunnable(0xc208012000)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/runtime/proc.c:1472 +0x485
schedule()
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/runtime/proc.c:1575 +0x151
goexit0(0xc2080019e0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/runtime/proc.c:1717 +0x16e
runtime.mcall(0x33e64)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/runtime/asm_amd64.s:186 +0x5a

goroutine 1 [chan receive]:
testing.RunTests(0x44ee08, 0x564fe0, 0x5, 0x5, 0x1c1109b545e89101)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/testing/testing.go:556 +0xad6
testing.(*M).Run(0xc208044410, 0x56fe80)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/testing/testing.go:485 +0x6c
main.main()
    github.com/SlyMarbo/spdy/_test/_testmain.go:62 +0x1d5

goroutine 36 [semacquire]:
sync.(*Mutex).Lock(0xc208060000)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/sync/mutex.go:66 +0xd3
github.com/SlyMarbo/spdy.(*Transport).RoundTrip(0xc208060000, 0xc20801f450, 0xc20853b140, 0x0, 0x0)
    /Users/jabley/gocode/src/github.com/SlyMarbo/spdy/transport.go:163 +0x1ad
net/http.send(0xc20801f450, 0x62a068, 0xc208060000, 0x17, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:219 +0x4fc
net/http.(*Client).send(0xc20803cc30, 0xc20801f450, 0x17, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:142 +0x15b
net/http.(*Client).doFollowingRedirects(0xc20803cc30, 0xc20801f450, 0x44efa8, 0x0, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:367 +0xb25
net/http.(*Client).Get(0xc20803cc30, 0xc20853b040, 0x17, 0xc20801afc0, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:299 +0xba
github.com/SlyMarbo/spdy_test.func·005()
    /Users/jabley/gocode/src/github.com/SlyMarbo/spdy/client_test.go:119 +0x91
created by github.com/SlyMarbo/spdy_test.TestClientInGoroutines
    /Users/jabley/gocode/src/github.com/SlyMarbo/spdy/client_test.go:130 +0x4bc

goroutine 35 [chan receive]:
github.com/SlyMarbo/spdy.(*Transport).dial(0xc208060000, 0xc208502b60, 0x0, 0x0, 0x0, 0x0)
    /Users/jabley/gocode/src/github.com/SlyMarbo/spdy/transport.go:108 +0x193
github.com/SlyMarbo/spdy.(*Transport).RoundTrip(0xc208060000, 0xc20801f380, 0xc20853b120, 0x0, 0x0)
    /Users/jabley/gocode/src/github.com/SlyMarbo/spdy/transport.go:202 +0x648
net/http.send(0xc20801f380, 0x62a068, 0xc208060000, 0x17, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:219 +0x4fc
net/http.(*Client).send(0xc20803cc30, 0xc20801f380, 0x17, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:142 +0x15b
net/http.(*Client).doFollowingRedirects(0xc20803cc30, 0xc20801f380, 0x44efa8, 0x0, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:367 +0xb25
net/http.(*Client).Get(0xc20803cc30, 0xc20853b040, 0x17, 0x0, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:299 +0xba
github.com/SlyMarbo/spdy_test.func·004()
    /Users/jabley/gocode/src/github.com/SlyMarbo/spdy/client_test.go:103 +0x91
created by github.com/SlyMarbo/spdy_test.TestClientInGoroutines
    /Users/jabley/gocode/src/github.com/SlyMarbo/spdy/client_test.go:114 +0x3d7

goroutine 32 [IO wait]:
net.(*pollDesc).Wait(0xc208444fb0, 0x72, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/fd_poll_runtime.go:84 +0x47
net.(*pollDesc).WaitRead(0xc208444fb0, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/fd_poll_runtime.go:89 +0x43
net.(*netFD).accept(0xc208444f50, 0x0, 0x629a20, 0xc208399448)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/fd_unix.go:419 +0x40b
net.(*TCPListener).AcceptTCP(0xc208046110, 0xc208017e60, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/tcpsock_posix.go:234 +0x4e
net.(*TCPListener).Accept(0xc208046110, 0x0, 0x0, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/tcpsock_posix.go:244 +0x4c
crypto/tls.(*listener).Accept(0xc20853b020, 0x0, 0x0, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/crypto/tls/tls.go:46 +0x6b
net/http/httptest.(*historyListener).Accept(0xc208536a80, 0x0, 0x0, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/httptest/server.go:48 +0x7a
net/http.(*Server).Serve(0xc208449e00, 0x62c5f8, 0xc208536a80, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/server.go:1728 +0x92
created by net/http/httptest.(*Server).StartTLS
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/httptest/server.go:142 +0x887

goroutine 31 [semacquire]:
sync.(*WaitGroup).Wait(0xc20853b080)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/sync/waitgroup.go:132 +0x169
github.com/SlyMarbo/spdy_test.TestClientInGoroutines(0xc2080753b0)
    /Users/jabley/gocode/src/github.com/SlyMarbo/spdy/client_test.go:164 +0x68e
testing.tRunner(0xc2080753b0, 0x565028)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/testing/testing.go:447 +0xbf
created by testing.RunTests
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/testing/testing.go:555 +0xa8b

goroutine 37 [semacquire]:
sync.(*Mutex).Lock(0xc208060000)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/sync/mutex.go:66 +0xd3
github.com/SlyMarbo/spdy.(*Transport).RoundTrip(0xc208060000, 0xc20801f520, 0xc20853b160, 0x0, 0x0)
    /Users/jabley/gocode/src/github.com/SlyMarbo/spdy/transport.go:163 +0x1ad
net/http.send(0xc20801f520, 0x62a068, 0xc208060000, 0x17, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:219 +0x4fc
net/http.(*Client).send(0xc20803cc30, 0xc20801f520, 0x17, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:142 +0x15b
net/http.(*Client).doFollowingRedirects(0xc20803cc30, 0xc20801f520, 0x44efa8, 0x0, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:367 +0xb25
net/http.(*Client).Get(0xc20803cc30, 0xc20853b040, 0x17, 0x0, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:299 +0xba
github.com/SlyMarbo/spdy_test.func·006()
    /Users/jabley/gocode/src/github.com/SlyMarbo/spdy/client_test.go:135 +0x91
created by github.com/SlyMarbo/spdy_test.TestClientInGoroutines
    /Users/jabley/gocode/src/github.com/SlyMarbo/spdy/client_test.go:146 +0x5a1

goroutine 38 [semacquire]:
sync.(*Mutex).Lock(0xc208060000)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/sync/mutex.go:66 +0xd3
github.com/SlyMarbo/spdy.(*Transport).RoundTrip(0xc208060000, 0xc20801f5f0, 0xc20853b180, 0x0, 0x0)
    /Users/jabley/gocode/src/github.com/SlyMarbo/spdy/transport.go:163 +0x1ad
net/http.send(0xc20801f5f0, 0x62a068, 0xc208060000, 0x17, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:219 +0x4fc
net/http.(*Client).send(0xc20803cc30, 0xc20801f5f0, 0x17, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:142 +0x15b
net/http.(*Client).doFollowingRedirects(0xc20803cc30, 0xc20801f5f0, 0x44efa8, 0x0, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:367 +0xb25
net/http.(*Client).Get(0xc20803cc30, 0xc20853b040, 0x17, 0x0, 0x0, 0x0)
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/net/http/client.go:299 +0xba
github.com/SlyMarbo/spdy_test.func·007()
    /Users/jabley/gocode/src/github.com/SlyMarbo/spdy/client_test.go:151 +0x91
created by github.com/SlyMarbo/spdy_test.TestClientInGoroutines
    /Users/jabley/gocode/src/github.com/SlyMarbo/spdy/client_test.go:162 +0x67e

goroutine 49 [syscall, locked to thread]:
runtime.goexit()
    /opt/boxen/homebrew/Cellar/go/1.4.2/libexec/src/runtime/asm_amd64.s:2232 +0x1

rax     0x4
rbx     0x0
rcx     0x7fff5fbfe960
rdx     0x0
rdi     0x4
rsi     0x0
rbp     0x568480
rsp     0x7fff5fbfe960
r8      0x40
r9      0x0
r10     0x7fff5fbfe9c8
r11     0x246
r12     0x432c27e691b4
r13     0x487a762bd0e8
r14     0x13c81a692789ea00
r15     0x10
rip     0x407b3
rflags  0x247
cs      0x7
fs      0x0
gs      0x8390000
exit status 2

The locking in transport.go seems to prevent progress.

SlyMarbo commented 9 years ago

Thanks for the test suggestion, that tracked it down