x/net/http2: data race in Transport.newClientConn() when connection idle timeout is too low #66763
Description
Go version
1.22.2
Output of go env in your module/workspace:
GO111MODULE=''
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/echung/Library/Caches/go-build'
GOENV='/Users/echung/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/echung/go-code/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/echung/go-code'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/opt/homebrew/Cellar/go/1.22.2/libexec'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='auto'
GOTOOLDIR='/opt/homebrew/Cellar/go/1.22.2/libexec/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.22.2'
GCCGO='gccgo'
AR='ar'
CC='cc'
CXX='c++'
CGO_ENABLED='1'
GOMOD='/Users/echung/go-code/http2idleconntest/go.mod'
GOWORK=''
CGO_CFLAGS='-O2 -g'
CGO_CPPFLAGS=''
CGO_CXXFLAGS='-O2 -g'
CGO_FFLAGS='-O2 -g'
CGO_LDFLAGS='-O2 -g'
PKG_CONFIG='pkg-config'
GOGCCFLAGS='-fPIC -arch arm64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -ffile-prefix-map=/var/folders/f6/d0y5wpkn14gb644rbckvn_dr0000gn/T/go-build46174965=/tmp/go-build -gno-record-gcc-switches -fno-common'What did you do?
Test code:
package idleconn_test
import (
"context"
"crypto/tls"
"net"
"net/http"
"net/http/httptest"
"testing"
"time"
"golang.org/x/net/http2"
"golang.org/x/net/http2/h2c"
)
func TestHTTP2IdleConnTimeout(t *testing.T) {
server := httptest.NewServer(
h2c.NewHandler(
http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {}),
&http2.Server{},
),
)
defer server.Close()
client := http.Client{
Transport: &http2.Transport{
AllowHTTP: true,
DialTLSContext: func(ctx context.Context, network, addr string, cfg *tls.Config) (net.Conn, error) {
var d net.Dialer
return d.DialContext(ctx, network, addr)
},
IdleConnTimeout: time.Millisecond,
},
}
for range 1000 {
go func() {
_, _ = client.Get(server.URL)
}()
}
}Run it via
go test . -race -count 10000 -v -failfast
What did you see happen?
The above trips the race detector due to ClientConn.idleTimer firing while the client connection is still being constructed. The race happens in ClientConn.closeIfIdle() when it tries to read from ClientConn.nextStreamID while it's being updated in
if t.AllowHTTP {
cc.nextStreamID = 3
}Output of the test with race detection enabled:
$ go test . -race -count 10000 -v -failfast
=== RUN TestHTTP2IdleConnTimeout
==================
WARNING: DATA RACE
Read at 0x00c0002c69b0 by goroutine 760:
golang.org/x/net/http2.(*ClientConn).closeIfIdle()
/Users/echung/go-code/pkg/mod/golang.org/x/net@v0.24.0/http2/transport.go:1108 +0xc4
golang.org/x/net/http2.(*ClientConn).onIdleTimeout()
/Users/echung/go-code/pkg/mod/golang.org/x/net@v0.24.0/http2/transport.go:1080 +0x34
golang.org/x/net/http2.(*ClientConn).onIdleTimeout-fm()
<autogenerated>:1 +0x20
Previous write at 0x00c0002c69b0 by goroutine 508:
golang.org/x/net/http2.(*Transport).newClientConn()
/Users/echung/go-code/pkg/mod/golang.org/x/net@v0.24.0/http2/transport.go:864 +0x1048
golang.org/x/net/http2.(*Transport).dialClientConn()
/Users/echung/go-code/pkg/mod/golang.org/x/net@v0.24.0/http2/transport.go:739 +0xdc
golang.org/x/net/http2.(*dialCall).dial()
/Users/echung/go-code/pkg/mod/golang.org/x/net@v0.24.0/http2/client_conn_pool.go:141 +0x7c
golang.org/x/net/http2.(*clientConnPool).getStartDialLocked.gowrap1()
/Users/echung/go-code/pkg/mod/golang.org/x/net@v0.24.0/http2/client_conn_pool.go:134 +0x64
Goroutine 760 (running) created at:
time.goFunc()
/opt/homebrew/Cellar/go/1.22.2/libexec/src/time/sleep.go:177 +0x40
Goroutine 508 (running) created at:
golang.org/x/net/http2.(*clientConnPool).getStartDialLocked()
/Users/echung/go-code/pkg/mod/golang.org/x/net@v0.24.0/http2/client_conn_pool.go:134 +0x34c
golang.org/x/net/http2.(*clientConnPool).getClientConn()
/Users/echung/go-code/pkg/mod/golang.org/x/net@v0.24.0/http2/client_conn_pool.go:95 +0x200
golang.org/x/net/http2.(*clientConnPool).GetClientConn()
/Users/echung/go-code/pkg/mod/golang.org/x/net@v0.24.0/http2/client_conn_pool.go:55 +0x44
golang.org/x/net/http2.(*Transport).RoundTripOpt()
/Users/echung/go-code/pkg/mod/golang.org/x/net@v0.24.0/http2/transport.go:610 +0x620
golang.org/x/net/http2.(*Transport).RoundTrip()
/Users/echung/go-code/pkg/mod/golang.org/x/net@v0.24.0/http2/transport.go:575 +0x34
net/http.send()
/opt/homebrew/Cellar/go/1.22.2/libexec/src/net/http/client.go:259 +0x6ec
net/http.(*Client).send()
/opt/homebrew/Cellar/go/1.22.2/libexec/src/net/http/client.go:180 +0x100
net/http.(*Client).do()
/opt/homebrew/Cellar/go/1.22.2/libexec/src/net/http/client.go:724 +0xc60
net/http.(*Client).Do()
/opt/homebrew/Cellar/go/1.22.2/libexec/src/net/http/client.go:590 +0x90
net/http.(*Client).Get()
/opt/homebrew/Cellar/go/1.22.2/libexec/src/net/http/client.go:487 +0xa0
http2idleconntest_test.TestHTTP2IdleConnTimeout.func3()
/Users/echung/go-code/http2idleconntest/idleconn_test.go:38 +0x58
==================
testing.go:1398: race detected during execution of test
--- FAIL: TestHTTP2IdleConnTimeout (0.01s)
FAIL
FAIL http2idleconntest 0.427s
FAILWhat did you expect to see?
No race detected.