Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

net/http: crash in Transport.queueForIdleConn(...) #42810

Closed
xqzhang2015 opened this issue Nov 24, 2020 · 8 comments
Closed

net/http: crash in Transport.queueForIdleConn(...) #42810

xqzhang2015 opened this issue Nov 24, 2020 · 8 comments
Labels
FrozenDueToAge

Comments

@xqzhang2015
Copy link

What version of Go are you using (go version)?

go1.15.3

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.

$ uname -a
Linux ashads097.fwmrm.net 3.10.0-514.el7.x86_64 #1 SMP Tue Nov 22 16:42:41 UTC 2016 x86_64 x86_64 x86_64 GNU/Linux

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]
@xqzhang2015 xqzhang2015 changed the title Go net/http crash Transport.queueForIdleConn(...) Go net/http crash in Transport.queueForIdleConn(...) Nov 24, 2020
@davecheney
Copy link
Contributor

This looks like memory corruption. Have you tried running your program under the race detector? See https://blog.golang.org/race-detector .

@xqzhang2015
Copy link
Author

@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

@xqzhang2015
Copy link
Author

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 odeke-em changed the title Go net/http crash in Transport.queueForIdleConn(...) net/http: crash in Transport.queueForIdleConn(...) Nov 25, 2020
@xqzhang2015
Copy link
Author

Hi @davecheney
Actually, there is racing for shared variables(like currentTraceTime, strings.Builder) among different HTTP trace hooks(or callbacks).

Do you have any proposal for the HTTP trace usage? One idea is to lock in each hook.

Thanks.

@davecheney
Copy link
Contributor

Have a look at how we do it in github.com/davecheney/httpstat

@xqzhang2015
Copy link
Author

xqzhang2015 commented Nov 25, 2020 •
edited

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 {

@davecheney
Copy link
Contributor

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:

@xqzhang2015
Copy link
Author

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|

@golang golang locked and limited conversation to collaborators Dec 1, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
3 participants
@davecheney @gopherbot @xqzhang2015