net/http: crash in Transport.queueForIdleConn(...) #42810
Comments
xqzhang2015
changed the title
|
This looks like memory corruption. Have you tried running your program under the race detector? See https://blog.golang.org/race-detector . |
|
@davecheney thanks for the info. Will try to test it. BTW, we get another net/http related crash stack trace. panic: close of closed channel
goroutine 27732906 [running]:
panic(0xd52840, 0xfa4110)
/usr/local/go/src/runtime/panic.go:1064 +0x545 fp=0xc00ecd33c0 sp=0xc00ecd32f8 pc=0x43a025
runtime.closechan(0xc00f5ebe00)
/usr/local/go/src/runtime/chan.go:365 +0x25a fp=0xc00ecd3400 sp=0xc00ecd33c0 pc=0x408eda
net/http.(*persistConn).roundTrip(0xc00ea685a0, 0xc01a7c3800, 0xc010707710, 0x0, 0x0)
/usr/local/go/src/net/http/transport.go:2603 +0xb3a fp=0xc00ecd3718 sp=0xc00ecd3400 pc=0x752dda
net/http.(*Transport).roundTrip(0xc000402280, 0xc00e266100, 0x30, 0x7f5be55f9188, 0x150)
/usr/local/go/src/net/http/transport.go:582 +0xa65 fp=0xc00ecd3960 sp=0xc00ecd3718 pc=0x746f65
net/http.(*Transport).RoundTrip(0xc000402280, 0xc00e266100, 0xc000402280, 0x0, 0x0)
/usr/local/go/src/net/http/roundtrip.go:17 +0x35 fp=0xc00ecd3998 sp=0xc00ecd3960 pc=0x72ccb5
net/http.send(0xc00e266100, 0xfb5940, 0xc000402280, 0x0, 0x0, 0x0, 0xc006cb7230, 0x203005, 0x1, 0x0)
/usr/local/go/src/net/http/client.go:252 +0x453 fp=0xc00ecd3b40 sp=0xc00ecd3998 pc=0x6e8b93
net/http.(*Client).send(0xc0000d5230, 0xc00e266100, 0x0, 0x0, 0x0, 0xc006cb7230, 0x0, 0x1, 0x203005)
/usr/local/go/src/net/http/client.go:176 +0xff fp=0xc00ecd3bc0 sp=0xc00ecd3b40 pc=0x6e857f
net/http.(*Client).do(0xc0000d5230, 0xc00e266100, 0x0, 0x0, 0x0)
/usr/local/go/src/net/http/client.go:718 +0x45f fp=0xc00ecd3d98 sp=0xc00ecd3bc0 pc=0x6ea59f
net/http.(*Client).Do(...)
/usr/local/go/src/net/http/client.go:586
|
|
Found one buz code change: 1st time to fully use httptrace strings.Builder
currentTraceTime := time.Now()
trace := &httptrace.ClientTrace{
GetConn: func(hostPort string) {
fmt.Fprintf(&httptrace, "\n\tHttpTrace: |%s %v|", "GetConn", time.Since(currentTraceTime))
currentTraceTime = time.Now()
},
DNSStart: func(dnsInfo httptrace.DNSStartInfo) {
fmt.Fprintf(&httptrace, "%s %v|", "DNSStart", time.Since(currentTraceTime))
currentTraceTime = time.Now()
},
DNSDone: func(dnsInfo httptrace.DNSDoneInfo) {
fmt.Fprintf(&httptrace, "%s %v|", "DNSDone", time.Since(currentTraceTime))
currentTraceTime = time.Now()
},
ConnectStart: func(network, addr string) {
fmt.Fprintf(&httptrace, "%s %v|", "ConnectStart", time.Since(currentTraceTime))
currentTraceTime = time.Now()
},
ConnectDone: func(network, addr string, err error) {
fmt.Fprintf(&httptrace, "%s %v|", "ConnectDone", time.Since(currentTraceTime))
currentTraceTime = time.Now()
},
TLSHandshakeStart: func() {
fmt.Fprintf(&httptrace, "%s %v|", "TLSHandshakeStart", time.Since(currentTraceTime))
currentTraceTime = time.Now()
},
TLSHandshakeDone: func(connState tls.ConnectionState, err error) {
fmt.Fprintf(&httptrace, "%s %v|", "TLSHandshakeDone", time.Since(currentTraceTime))
currentTraceTime = time.Now()
},
GotConn: func(connInfo httptrace.GotConnInfo) {
fmt.Fprintf(&httptrace, "%s %v|", "GotConn", time.Since(currentTraceTime))
r.remoteAddr = util.ExtractIP(connInfo.Conn.RemoteAddr().String())
currentTraceTime = time.Now()
},
WroteRequest: func(wrInfo httptrace.WroteRequestInfo) {
fmt.Fprintf(&httptrace, "%s %v|", "WroteRequest", time.Since(currentTraceTime))
currentTraceTime = time.Now()
},
GotFirstResponseByte: func() {
fmt.Fprintf(&httptrace, "%s %v|", "GotFirstResponseByte", time.Since(currentTraceTime))
},
}
|
odeke-em
changed the title
|
Hi @davecheney Do you have any proposal for the HTTP trace usage? One idea is to lock in each hook. Thanks. |
|
Have a look at how we do it in github.com/davecheney/httpstat |
|
Hi @davecheney, Thanks for the help so much. httpstat seems mainly for a single HTTP request. For PRD usage, the net/http client requests concurrency may be quite high. I noticed one comment "some may be called after the request has completed or failed" for ClientTrace. I have a concern if there is data access racing for the shared variable between ClientTrace hook and the usage after getting the response, like reading or setting remoteAddr by the connInfo.Conn.RemoteAddr() from httptrace.GotConnInfo. // ClientTrace is a set of hooks to run at various stages of an outgoing
// HTTP request. Any particular hook may be nil. Functions may be
// called concurrently from different goroutines and some may be called
// after the request has completed or failed.
//
// ClientTrace currently traces a single HTTP request & response
// during a single round trip and has no hooks that span a series
// of redirected requests.
//
// See https://blog.golang.org/http-tracing for more.
type ClientTrace struct {
|
|
There could be a possibility of data races during the different phases of ClientTrace as the memory ownership and happens before relationships are not (IMO) well defined for that use case. I would proceed cautiously and make heavy use of the race detector to check your work. Also, I should remind you that unlike many projects, the Go project does not use GitHub Issues for general discussion or asking questions. GitHub Issues are used for tracking bugs and proposals only. For asking questions, see:
|
|
Thanks for the reminder and all the help, which is truly impressive. I got such log: TLSHandshakeStart is after GotConn/WroteRequest, which means the variable shared between the trace hook and the usage after got response body may encounter race condition. One approach is to use atomic/mutex for the shared variables. HttpTrace: |GetConn 37.462µs|GotConn 136.729174ms|WroteRequest 44.956µs|TLSHandshakeStart 102.646256ms|TLSHandshakeDone 1.03µs| |
What version of Go are you using (
go version)?Does this issue reproduce with the latest release?
Not sure. Only happened once in our PROD env.
What operating system and processor architecture are you using (
go env)?PROD runtime env, there is no go.
What did you do?
Sending an HTTPS request, and Got crashed.
fatal error: fault [signal SIGSEGV: segmentation violation code=0x80 addr=0x0 pc=0x74f58d] goroutine 40123707 [running]: runtime.throw(0xe8844d, 0x5) /usr/local/go/src/runtime/panic.go:1116 +0x72 fp=0xc00deb3330 sp=0xc00deb3300 pc=0x43a432 runtime.sigpanic() /usr/local/go/src/runtime/signal_unix.go:727 +0x405 fp=0xc00deb3360 sp=0xc00deb3330 pc=0x450be5 net/http.(*persistConn).isBroken(0x7c736d3838313537, 0xc00616f650) /usr/local/go/src/net/http/transport.go:1897 +0x2d fp=0xc00deb3390 sp=0xc00deb3360 pc=0x74f58d net/http.(*Transport).queueForIdleConn(0xc00028c000, 0xc0131f9080, 0xc00cb96a00) /usr/local/go/src/net/http/transport.go:1021 +0x1e5 fp=0xc00deb3478 sp=0xc00deb3390 pc=0x749845 net/http.(*Transport).getConn(0xc00028c000, 0xc00f51dbc0, 0x0, 0xc006086500, 0x5, 0xc00e9184c0, 0x16, 0x0, 0x0, 0x0, ...) /usr/local/go/src/net/http/transport.go:1326 +0x297 fp=0xc00deb3718 sp=0xc00deb3478 pc=0x74b257 net/http.(*Transport).roundTrip(0xc00028c000, 0xc004784200, 0x30, 0x7f7f604ade90, 0x150) /usr/local/go/src/net/http/transport.go:569 +0x77c fp=0xc00deb3960 sp=0xc00deb3718 pc=0x746c7c net/http.(*Transport).RoundTrip(0xc00028c000, 0xc004784200, 0xc00028c000, 0x0, 0x0) /usr/local/go/src/net/http/roundtrip.go:17 +0x35 fp=0xc00deb3998 sp=0xc00deb3960 pc=0x72ccb5 net/http.send(0xc004784200, 0xfb5860, 0xc00028c000, 0x0, 0x0, 0x0, 0xc012b706a0, 0x203001, 0x1, 0x0) /usr/local/go/src/net/http/client.go:252 +0x453 fp=0xc00deb3b40 sp=0xc00deb3998 pc=0x6e8b93 net/http.(*Client).send(0xc000a36750, 0xc004784200, 0x0, 0x0, 0x0, 0xc012b706a0, 0x0, 0x1, 0x203003) /usr/local/go/src/net/http/client.go:176 +0xff fp=0xc00deb3bc0 sp=0xc00deb3b40 pc=0x6e857f net/http.(*Client).do(0xc000a36750, 0xc004784200, 0x0, 0x0, 0x0) /usr/local/go/src/net/http/client.go:718 +0x45f fp=0xc00deb3d98 sp=0xc00deb3bc0 pc=0x6ea59f net/http.(*Client).Do(...) /usr/local/go/src/net/http/client.go:586 (dlv) frame 6 > runtime.raise() /usr/local/go/src/runtime/sys_linux_amd64.s:165 (PC: 0x4749e1) Warning: debugging optimized function Frame 6: /usr/local/go/src/net/http/transport.go:1021 (PC: 749845) (dlv) locals oldTime = time.Time {wall: 0, ext: 0, loc: *time.Location nil} list = []*net/http.persistConn len: 7, cap: 64, [...] stop = false delivered = false pconn = ("*net/http.persistConn")(0x7c736d3838313537) tooOld = false (dlv) p list []*net/http.persistConn len: 7, cap: 64, [ *{ alt: net/http.RoundTripper nil, t: *(unreadable error while reading spliced memory at 0x71655265746f7257: EOF), cacheKey: (*"net/http.connectMethodKey")(0x71655265746f726f), conn: net.Conn nil, tlsState: *(unreadable error while reading spliced memory at 0x71655265746f7257: EOF), br: *(unreadable error while reading spliced memory at 0x71655265746f7257: EOF), bw: *(unreadable error while reading spliced memory at 0x71655265746f7257: EOF), nwrite: (unreadable error while reading spliced memory at 0x71655265746f7257: EOF), reqch: chan net/http.requestAndChan {}, writech: chan net/http.writeRequest {}, closech: chan struct {} {}, isProxy: (unreadable error while reading spliced memory at 0x71655265746f7257: EOF), sawEOF: (unreadable error while reading spliced memory at 0x71655265746f7257: EOF), readLimit: (unreadable error while reading spliced memory at 0x71655265746f7257: EOF), writeErrCh: chan error {}, writeLoopDone: chan struct {} {}, idleAt: (*time.Time)(0x71655265746f730f), idleTimer: *(unreadable error while reading spliced memory at 0x71655265746f7257: EOF), mu: (*sync.Mutex)(0x71655265746f732f), numExpectedResponses: (unreadable error while reading spliced memory at 0x71655265746f7257: EOF), closed: error nil, canceledErr: error nil, broken: (unreadable error while reading spliced memory at 0x71655265746f7257: EOF), reused: (unreadable error while reading spliced memory at 0x71655265746f7257: EOF), mutateHeaderFunc: (unreadable error while reading spliced memory at 0x71655265746f7257: EOF),}, *{ alt: net/http.RoundTripper nil, t: *(unreadable error while reading spliced memory at 0x2e33322074736575: EOF), cacheKey: (*"net/http.connectMethodKey")(0x2e3332207473658d), conn: net.Conn nil, tlsState: *(unreadable error while reading spliced memory at 0x2e33322074736575: EOF), br: *(unreadable error while reading spliced memory at 0x2e33322074736575: EOF), bw: *(unreadable error while reading spliced memory at 0x2e33322074736575: EOF), nwrite: (unreadable error while reading spliced memory at 0x2e33322074736575: EOF), reqch: chan net/http.requestAndChan {}, writech: chan net/http.writeRequest {}, closech: chan struct {} {}, isProxy: (unreadable error while reading spliced memory at 0x2e33322074736575: EOF), sawEOF: (unreadable error while reading spliced memory at 0x2e33322074736575: EOF), readLimit: (unreadable error while reading spliced memory at 0x2e33322074736575: EOF), writeErrCh: chan error {}, writeLoopDone: chan struct {} {}, idleAt: (*time.Time)(0x2e3332207473662d), idleTimer: *(unreadable error while reading spliced memory at 0x2e33322074736575: EOF), mu: (*sync.Mutex)(0x2e3332207473664d), numExpectedResponses: (unreadable error while reading spliced memory at 0x2e33322074736575: EOF), closed: error nil, canceledErr: error nil, broken: (unreadable error while reading spliced memory at 0x2e33322074736575: EOF), reused: (unreadable error while reading spliced memory at 0x2e33322074736575: EOF), mutateHeaderFunc: (unreadable error while reading spliced memory at 0x2e33322074736575: EOF),}, *{ alt: net/http.RoundTripper nil, t: *(unreadable error while reading spliced memory at 0x6f477c73b5c23737: EOF), cacheKey: (*"net/http.connectMethodKey")(0x6f477c73b5c2374f), conn: net.Conn nil, tlsState: *(unreadable error while reading spliced memory at 0x6f477c73b5c23737: EOF), br: *(unreadable error while reading spliced memory at 0x6f477c73b5c23737: EOF), bw: *(unreadable error while reading spliced memory at 0x6f477c73b5c23737: EOF), nwrite: (unreadable error while reading spliced memory at 0x6f477c73b5c23737: EOF), reqch: chan net/http.requestAndChan {}, writech: chan net/http.writeRequest {}, closech: chan struct {} {}, isProxy: (unreadable error while reading spliced memory at 0x6f477c73b5c23737: EOF), sawEOF: (unreadable error while reading spliced memory at 0x6f477c73b5c23737: EOF), readLimit: (unreadable error while reading spliced memory at 0x6f477c73b5c23737: EOF), writeErrCh: chan error {}, writeLoopDone: chan struct {} {}, idleAt: (*time.Time)(0x6f477c73b5c237ef), idleTimer: *(unreadable error while reading spliced memory at 0x6f477c73b5c23737: EOF), mu: (*sync.Mutex)(0x6f477c73b5c2380f), numExpectedResponses: (unreadable error while reading spliced memory at 0x6f477c73b5c23737: EOF), closed: error nil, canceledErr: error nil, broken: (unreadable error while reading spliced memory at 0x6f477c73b5c23737: EOF), reused: (unreadable error while reading spliced memory at 0x6f477c73b5c23737: EOF), mutateHeaderFunc: (unreadable error while reading spliced memory at 0x6f477c73b5c23737: EOF),}, *{ alt: net/http.RoundTripper nil, t: *(unreadable error while reading spliced memory at 0x6552747372694674: EOF), cacheKey: (*"net/http.connectMethodKey")(0x655274737269468c), conn: net.Conn nil, tlsState: *(unreadable error while reading spliced memory at 0x6552747372694674: EOF), br: *(unreadable error while reading spliced memory at 0x6552747372694674: EOF), bw: *(unreadable error while reading spliced memory at 0x6552747372694674: EOF), nwrite: (unreadable error while reading spliced memory at 0x6552747372694674: EOF), reqch: chan net/http.requestAndChan {}, writech: chan net/http.writeRequest {}, closech: chan struct {} {}, isProxy: (unreadable error while reading spliced memory at 0x6552747372694674: EOF), sawEOF: (unreadable error while reading spliced memory at 0x6552747372694674: EOF), readLimit: (unreadable error while reading spliced memory at 0x6552747372694674: EOF), writeErrCh: chan error {}, writeLoopDone: chan struct {} {}, idleAt: (*time.Time)(0x655274737269472c), idleTimer: *(unreadable error while reading spliced memory at 0x6552747372694674: EOF), mu: (*sync.Mutex)(0x655274737269474c), numExpectedResponses: (unreadable error while reading spliced memory at 0x6552747372694674: EOF), closed: error nil, canceledErr: error nil, broken: (unreadable error while reading spliced memory at 0x6552747372694674: EOF), reused: (unreadable error while reading spliced memory at 0x6552747372694674: EOF), mutateHeaderFunc: (unreadable error while reading spliced memory at 0x6552747372694674: EOF),}, *{ alt: net/http.RoundTripper nil, t: *(unreadable error while reading spliced memory at 0x794265736e6f7073: EOF), cacheKey: (*"net/http.connectMethodKey")(0x794265736e6f708b), conn: net.Conn nil, tlsState: *(unreadable error while reading spliced memory at 0x794265736e6f7073: EOF), br: *(unreadable error while reading spliced memory at 0x794265736e6f7073: EOF), bw: *(unreadable error while reading spliced memory at 0x794265736e6f7073: EOF), nwrite: (unreadable error while reading spliced memory at 0x794265736e6f7073: EOF), reqch: chan net/http.requestAndChan {}, writech: chan net/http.writeRequest {}, closech: chan struct {} {}, isProxy: (unreadable error while reading spliced memory at 0x794265736e6f7073: EOF), sawEOF: (unreadable error while reading spliced memory at 0x794265736e6f7073: EOF), readLimit: (unreadable error while reading spliced memory at 0x794265736e6f7073: EOF), writeErrCh: chan error {}, writeLoopDone: chan struct {} {}, idleAt: (*time.Time)(0x794265736e6f712b), idleTimer: *(unreadable error while reading spliced memory at 0x794265736e6f7073: EOF), mu: (*sync.Mutex)(0x794265736e6f714b), numExpectedResponses: (unreadable error while reading spliced memory at 0x794265736e6f7073: EOF), closed: error nil, canceledErr: error nil, broken: (unreadable error while reading spliced memory at 0x794265736e6f7073: EOF), reused: (unreadable error while reading spliced memory at 0x794265736e6f7073: EOF), mutateHeaderFunc: (unreadable error while reading spliced memory at 0x794265736e6f7073: EOF),}, *{ alt: net/http.RoundTripper nil, t: *(unreadable error while reading spliced memory at 0x382e353031206574: EOF), cacheKey: (*"net/http.connectMethodKey")(0x382e35303120658c), conn: net.Conn nil, tlsState: *(unreadable error while reading spliced memory at 0x382e353031206574: EOF), br: *(unreadable error while reading spliced memory at 0x382e353031206574: EOF), bw: *(unreadable error while reading spliced memory at 0x382e353031206574: EOF), nwrite: (unreadable error while reading spliced memory at 0x382e353031206574: EOF), reqch: chan net/http.requestAndChan {}, writech: chan net/http.writeRequest {}, closech: chan struct {} {}, isProxy: (unreadable error while reading spliced memory at 0x382e353031206574: EOF), sawEOF: (unreadable error while reading spliced memory at 0x382e353031206574: EOF), readLimit: (unreadable error while reading spliced memory at 0x382e353031206574: EOF), writeErrCh: chan error {}, writeLoopDone: chan struct {} {}, idleAt: (*time.Time)(0x382e35303120662c), idleTimer: *(unreadable error while reading spliced memory at 0x382e353031206574: EOF), mu: (*sync.Mutex)(0x382e35303120664c), numExpectedResponses: (unreadable error while reading spliced memory at 0x382e353031206574: EOF), closed: error nil, canceledErr: error nil, broken: (unreadable error while reading spliced memory at 0x382e353031206574: EOF), reused: (unreadable error while reading spliced memory at 0x382e353031206574: EOF), mutateHeaderFunc: (unreadable error while reading spliced memory at 0x382e353031206574: EOF),}, *{ alt: net/http.RoundTripper nil, t: *(unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), cacheKey: (*"net/http.connectMethodKey")(0x7c736d383831354f), conn: net.Conn nil, tlsState: *(unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), br: *(unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), bw: *(unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), nwrite: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), reqch: chan net/http.requestAndChan {}, writech: chan net/http.writeRequest {}, closech: chan struct {} {}, isProxy: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), sawEOF: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), readLimit: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), writeErrCh: chan error {}, writeLoopDone: chan struct {} {}, idleAt: (*time.Time)(0x7c736d38383135ef), idleTimer: *(unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), mu: (*sync.Mutex)(0x7c736d383831360f), numExpectedResponses: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), closed: error nil, canceledErr: error nil, broken: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), reused: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), mutateHeaderFunc: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF),}, ] (dlv) p pconn *net/http.persistConn { alt: net/http.RoundTripper nil, t: *(unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), cacheKey: net/http.connectMethodKey {proxy: (unreadable could not read string len error while reading spliced memory at 0x7c736d3838313537: EOF), scheme: (unreadable could not read string len error while reading spliced memory at 0x7c736d3838313537: EOF), addr: (unreadable could not read string len error while reading spliced memory at 0x7c736d3838313537: EOF), onlyH1: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF)}, conn: net.Conn nil, tlsState: *(unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), br: *(unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), bw: *(unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), nwrite: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), reqch: chan net/http.requestAndChan {}, writech: chan net/http.writeRequest {}, closech: chan struct {} {}, isProxy: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), sawEOF: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), readLimit: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), writeErrCh: chan error {}, writeLoopDone: chan struct {} {}, idleAt: time.Time { wall: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), ext: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), loc: *(unreadable error while reading spliced memory at 0x7c736d3838313537: EOF),}, idleTimer: *(unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), mu: sync.Mutex {state: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), sema: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF)}, numExpectedResponses: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), closed: error nil, canceledErr: error nil, broken: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), reused: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF), mutateHeaderFunc: (unreadable error while reading spliced memory at 0x7c736d3838313537: EOF),}What did you expect to see?
Successfully sending out HTTPS request
What did you see instead?
The memory of idle connections list seems corrupted
func (t *Transport) queueForIdleConn(w *wantConn) (delivered bool) { // ... // Look for most recently-used idle connection. if list, ok := t.idleConn[w.key]; ok { stop := false delivered := false for len(list) > 0 && !stop { pconn := list[len(list)-1]The text was updated successfully, but these errors were encountered: