x/net/http2: data race in Transport.newClientConn() when connection idle timeout is too low

[cinchurge]

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/[email protected]/http2/transport.go:1108 +0xc4
  golang.org/x/net/http2.(*ClientConn).onIdleTimeout()
      /Users/echung/go-code/pkg/mod/golang.org/x/[email protected]/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/[email protected]/http2/transport.go:864 +0x1048
  golang.org/x/net/http2.(*Transport).dialClientConn()
      /Users/echung/go-code/pkg/mod/golang.org/x/[email protected]/http2/transport.go:739 +0xdc
  golang.org/x/net/http2.(*dialCall).dial()
      /Users/echung/go-code/pkg/mod/golang.org/x/[email protected]/http2/client_conn_pool.go:141 +0x7c
  golang.org/x/net/http2.(*clientConnPool).getStartDialLocked.gowrap1()
      /Users/echung/go-code/pkg/mod/golang.org/x/[email protected]/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/[email protected]/http2/client_conn_pool.go:134 +0x34c
  golang.org/x/net/http2.(*clientConnPool).getClientConn()
      /Users/echung/go-code/pkg/mod/golang.org/x/[email protected]/http2/client_conn_pool.go:95 +0x200
  golang.org/x/net/http2.(*clientConnPool).GetClientConn()
      /Users/echung/go-code/pkg/mod/golang.org/x/[email protected]/http2/client_conn_pool.go:55 +0x44
  golang.org/x/net/http2.(*Transport).RoundTripOpt()
      /Users/echung/go-code/pkg/mod/golang.org/x/[email protected]/http2/transport.go:610 +0x620
  golang.org/x/net/http2.(*Transport).RoundTrip()
      /Users/echung/go-code/pkg/mod/golang.org/x/[email protected]/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
FAIL

What did you expect to see?

No race detected.

[gopherbot]

Change https://go.dev/cl/578115 mentions this issue: http2: set up the handler of closing idle connection after its initialization