net/http/httptrace: panic on GotConn #34282

cuonglm · 2019-09-13T08:41:41Z

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

$ go version
go version devel +03f63654c4 Thu Sep 12 21:02:57 2019 +0000 darwin/amd64

Does this issue reproduce with the latest release?

Yes

What operating system and processor architecture are you using (`go env`)?

go env Output

$ go env
GO111MODULE=""
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/cuonglm/Library/Caches/go-build"
GOENV="/Users/cuonglm/Library/Application Support/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GONOPROXY=""
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/cuonglm/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/Users/cuonglm/sources/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/Users/cuonglm/sources/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD=""
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/y4/hs76ltbn7sb66lw_6934kq4m0000gn/T/go-build718378058=/tmp/go-build -gno-record-gcc-switches -fno-common"

What did you do?

package main

import (
	"context"
	"log"
	"net/http"
	"net/http/httptrace"
	"sync"
)

func gotConn(info httptrace.GotConnInfo) {
	_ = info.Conn.RemoteAddr
}

func doGet() {
	ctx := httptrace.WithClientTrace(context.Background(), &httptrace.ClientTrace{
		GotConn: gotConn,
	})

	req, _ := http.NewRequest(http.MethodGet, "https://google.com", nil)
	req = req.WithContext(ctx)

	if _, err := http.DefaultClient.Do(req); err != nil {
		log.Println(err)
	}
}

func main() {
	var wg sync.WaitGroup
	n := 1000
	wg.Add(n)

	for i := 0; i < n; i++ {
		go func() {
			defer wg.Done()
			doGet()
		}()
	}

	wg.Wait()
}

Thanks @tmthrgd for simpler and not racy program.

What did you expect to see?

Run successfully.

What did you see instead?

Panic

panic: runtime error: invalid memory address or nil pointer dereference
[signal SIGSEGV: segmentation violation code=0x1 addr=0x0 pc=0x12ad645]

goroutine 72 [running]:
main.gotConn(0x0, 0x0, 0x1a500101, 0xc0ce52)
	/Users/cuonglm/sources/goissues/34282/trace.go:12 +0x5
net/http.(*Transport).getConn(0x15cc420, 0xc0025eec60, 0x0, 0x135530c, 0x5, 0xc0029f1650, 0xe, 0x0, 0x0, 0x0, ...)
	/Users/cuonglm/sdk/go1.13/src/net/http/transport.go:1210 +0x394
net/http.(*Transport).roundTrip(0x15cc420, 0xc00027e900, 0x0, 0xc00020ab20, 0x100e118)
	/Users/cuonglm/sdk/go1.13/src/net/http/transport.go:522 +0x603
net/http.(*Transport).RoundTrip(0x15cc420, 0xc00027e900, 0x15cc420, 0x0, 0x0)
	/Users/cuonglm/sdk/go1.13/src/net/http/roundtrip.go:17 +0x35
net/http.send(0xc00027e900, 0x13be5a0, 0x15cc420, 0x0, 0x0, 0x0, 0xc000282050, 0x203000, 0x1, 0x0)
	/Users/cuonglm/sdk/go1.13/src/net/http/client.go:250 +0x43a
net/http.(*Client).send(0x15d1200, 0xc00027e900, 0x0, 0x0, 0x0, 0xc000282050, 0x0, 0x1, 0x13479a0)
	/Users/cuonglm/sdk/go1.13/src/net/http/client.go:174 +0xfa
net/http.(*Client).do(0x15d1200, 0xc00027e900, 0x0, 0x0, 0x0)
	/Users/cuonglm/sdk/go1.13/src/net/http/client.go:641 +0x3ce
net/http.(*Client).Do(...)
	/Users/cuonglm/sdk/go1.13/src/net/http/client.go:509
main.main.func1(0xc00001c340, 0x13c3a40, 0xc0000ceab0)
	/Users/cuonglm/sources/goissues/34282/trace.go:31 +0x18c
created by main.main
	/Users/cuonglm/sources/goissues/34282/trace.go:25 +0xeb
exit status 2

The program works in go1.12, panic on go1.13 as well as tip.

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

agnivade · 2019-09-13T08:57:01Z

Want to do a bisect ? 🙂

@bradfitz

tmthrgd · 2019-09-13T09:28:55Z

Here is a simpler reproducer that shows the same crash (Edit: simpler still):

package main

import (
	"context"
	"log"
	"net/http"
	"net/http/httptrace"
	"sync"
)

func gotConn(info httptrace.GotConnInfo) {
	_ = info.Conn.RemoteAddr // info.Conn == nil here
}

func doGet() {
	ctx := httptrace.WithClientTrace(context.Background(), &httptrace.ClientTrace{
		GotConn: gotConn,
	})

	req, _ := http.NewRequest(http.MethodGet, "https://google.com", nil)
	req = req.WithContext(ctx)

	if _, err := http.DefaultClient.Do(req); err != nil {
		log.Println(err)
	}
}

func main() {
	var wg sync.WaitGroup
	n := 1000
	wg.Add(n)

	for i := 0; i < n; i++ {
		go func() {
			defer wg.Done()
			doGet()
		}()
	}

	wg.Wait()
}

cuonglm · 2019-09-13T09:34:33Z

@ALTree The example of @tmthrgd above is not racy and produce the panic.

I updated the issue with that program, thanks @tmthrgd .

ALTree · 2019-09-13T09:38:41Z

In general, it's better not to edit the original message. Now people reading the thread from the start will get confused by our initial discussion about code that doesn't exist any more. I'll mark our messages as outdated to hide them.

tmthrgd · 2019-09-13T09:57:56Z

~~I think the problem might be some kind of race condition in queueForIdleConn around t.idleConn.~~

This is where the call to GotConn with a nil info.Conn is happening:

go/src/net/http/transport.go

Lines 1196 to 1199 in 98aa978

    
           if delivered := t.queueForIdleConn(w); delivered { 
        
           	pc := w.pc 
        
           	if trace != nil && trace.GotConn != nil { 
        
           		trace.GotConn(pc.gotIdleConnTrace(pc.idleAt))

Nothing touches w before queueForIdleConn, which can only ever return true here:

go/src/net/http/transport.go

Line 936 in 98aa978

return delivered

Running the go program above in delve, I'm seeing a persistConn with conn == nil at the call to tryDeliver here:

go/src/net/http/transport.go

Line 916 in 98aa978

delivered = w.tryDeliver(pconn, nil)

cuonglm · 2019-09-13T10:09:45Z

git bisect points to 43b9fcf

tmthrgd · 2019-09-13T10:19:51Z

After 43b9fcf, dialConn can return a persistConn with conn == nil here:

go/src/net/http/transport.go

Line 1535 in 98aa978

    
           return &persistConn{t: t, cacheKey: pconn.cacheKey, alt: next(cm.targetAddr, pconn.conn.(*tls.Conn))}, nil

That persistConn is then being put in t.idleConn by tryPutIdleConn and pulled out by queueForIdleConn.

When there aren't any idle connections available, x/net/http2 calls GotConn itself, see here:

go/src/net/http/transport.go

Lines 1217 to 1221 in 98aa978

    
           // Trace success but only for HTTP/1. 
        
           // HTTP/2 calls trace.GotConn itself. 
        
           if w.pc != nil && w.pc.alt == nil && trace != nil && trace.GotConn != nil { 
        
           	trace.GotConn(httptrace.GotConnInfo{Conn: w.pc.conn, Reused: w.pc.isReused()}) 
        
           }

Is the bug here simply that this call is missing the HTTP/2 specific check?

go/src/net/http/transport.go

Lines 1198 to 1200 in 98aa978

    
           if trace != nil && trace.GotConn != nil { 
        
           	trace.GotConn(pc.gotIdleConnTrace(pc.idleAt)) 
        
           }

cuonglm · 2019-09-13T10:30:07Z

@tmthrgd w.pc.alt == nil guarantees HTTP/1

gopherbot · 2019-09-13T10:45:13Z

Change https://golang.org/cl/195237 mentions this issue: net/http: fix HTTP/2 idle pool tracing

tmthrgd · 2019-09-13T10:48:50Z

CL 195237 fixes the panic, but is missing a test case.

@cuonglm If you're looking for a temporary workaround, either:

http.DefaultTransport.(*http.Transport).DisableKeepAlives = true

or

http.DefaultTransport.(*http.Transport).MaxIdleConnsPerHost = -1

will stop the problematic persistConn from being put in the idle pool

cuonglm · 2019-09-13T12:06:49Z

@gopherbot please consider this for backport 1.13

gopherbot · 2019-09-13T12:06:56Z

Backport issue(s) opened: #34285 (for 1.13).

Remember to create the cherry-pick CL(s) as soon as the patch is submitted to master, according to https://golang.org/wiki/MinorReleases.

cuonglm mentioned this issue Sep 13, 2019

Invalid memory address or nil pointer dereference when running in k8s grafana/k6#1153

Closed

cuonglm changed the title ~~net/http/httptrace: panic on GoConn~~ net/http/httptrace: panic on GotConn Sep 13, 2019

agnivade added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Sep 13, 2019

agnivade added this to the Go1.14 milestone Sep 13, 2019

This comment has been minimized.

Sign in to view

tmthrgd mentioned this issue Sep 13, 2019

net/http: fix HTTP/2 idle pool tracing #34283

Closed

gopherbot mentioned this issue Sep 13, 2019

net/http/httptrace: panic on GotConn [1.13 backport] #34285

Closed

cuonglm mentioned this issue Sep 16, 2019

temporary use go1.12 for Dockerfile grafana/k6#1157

Merged

gopherbot closed this as completed in 582d519 Sep 18, 2019

cuonglm mentioned this issue Sep 26, 2019

Use go1.13 for CI again grafana/k6#1177

Merged

golang locked and limited conversation to collaborators Sep 17, 2020

gopherbot added the FrozenDueToAge label Sep 17, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

net/http/httptrace: panic on GotConn #34282

net/http/httptrace: panic on GotConn #34282

cuonglm commented Sep 13, 2019 •

edited

Loading

agnivade commented Sep 13, 2019

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

tmthrgd commented Sep 13, 2019 •

edited

Loading

cuonglm commented Sep 13, 2019 •

edited

Loading

ALTree commented Sep 13, 2019 •

edited

Loading

tmthrgd commented Sep 13, 2019 •

edited

Loading

cuonglm commented Sep 13, 2019

tmthrgd commented Sep 13, 2019

cuonglm commented Sep 13, 2019

gopherbot commented Sep 13, 2019

tmthrgd commented Sep 13, 2019

cuonglm commented Sep 13, 2019

gopherbot commented Sep 13, 2019

net/http/httptrace: panic on GotConn #34282

net/http/httptrace: panic on GotConn #34282

Comments

cuonglm commented Sep 13, 2019 • edited Loading

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

Does this issue reproduce with the latest release?

What operating system and processor architecture are you using (go env)?

What did you do?

What did you expect to see?

What did you see instead?

agnivade commented Sep 13, 2019

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

This comment has been minimized.

tmthrgd commented Sep 13, 2019 • edited Loading

cuonglm commented Sep 13, 2019 • edited Loading

ALTree commented Sep 13, 2019 • edited Loading

tmthrgd commented Sep 13, 2019 • edited Loading

cuonglm commented Sep 13, 2019

tmthrgd commented Sep 13, 2019

cuonglm commented Sep 13, 2019

gopherbot commented Sep 13, 2019

tmthrgd commented Sep 13, 2019

cuonglm commented Sep 13, 2019

gopherbot commented Sep 13, 2019

cuonglm commented Sep 13, 2019 •

edited

Loading

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

What operating system and processor architecture are you using (`go env`)?

tmthrgd commented Sep 13, 2019 •

edited

Loading

cuonglm commented Sep 13, 2019 •

edited

Loading

ALTree commented Sep 13, 2019 •

edited

Loading

tmthrgd commented Sep 13, 2019 •

edited

Loading