net/http: Error when setting idleConnectionTimeout

[khushijain21]

Go version

1.21

Output of go env in your module/workspace:

GO111MODULE=''
GOARCH='arm64'
GOBIN=''
GOCACHE='/Users/khushijain/Library/Caches/go-build'
GOENV='/Users/khushijain/Library/Application Support/go/env'
GOEXE=''
GOEXPERIMENT=''
GOFLAGS=''
GOHOSTARCH='arm64'
GOHOSTOS='darwin'
GOINSECURE=''
GOMODCACHE='/Users/khushijain/go/pkg/mod'
GONOPROXY=''
GONOSUMDB=''
GOOS='darwin'
GOPATH='/Users/khushijain/go'
GOPRIVATE=''
GOPROXY='https://proxy.golang.org,direct'
GOROOT='/opt/homebrew/Cellar/go/1.23.1/libexec'
GOSUMDB='sum.golang.org'
GOTMPDIR=''
GOTOOLCHAIN='local'
GOTOOLDIR='/opt/homebrew/Cellar/go/1.23.1/libexec/pkg/tool/darwin_arm64'
GOVCS=''
GOVERSION='go1.23.1'
GODEBUG=''
GOTELEMETRY='local'
GOTELEMETRYDIR='/Users/khushijain/Library/Application Support/go/telemetry'
GCCGO='gccgo'
GOARM64='v8.0'
AR='ar'
CC='cc'
CXX='c++'
CGO_ENABLED='1'
GOMOD='/Users/khushijain/Documents/elastic-agent-libs/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/cv/_38x0gd965v0156jwblb9x6h0000gn/T/go-build243205887=/tmp/go-build -gno-record-gcc-switches -fno-common'

What did you do?

If you set IdleConnectionTImeout timeout on http.Transport to 2s. And send two separate requests with 5 seconds delay between them with custom logging dialer which logs an error received during read and write operations on net.Conn

We receive a use of closed connection error on sending the second request. The error is from the read method on net.Conn. It seems like it was trying to reuse the first connection which was closed due to timeout. We expected Go to internally handle not reusing old connections

How to reproduce

// Set up a test HTTP server
	server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		fmt.Fprintln(w, `{"status": "ok"}`)
	}))
	defer server.Close()

	logger := logp.NewLogger("test")
	// Set IdleConnTimeout to 2 seconds and a custom dialer
	transport := &http.Transport{
		IdleConnTimeout: 2 * time.Second,
		// uses our implementation of custom dialer
		DialContext: LoggingDialer(NetDialer(10*time.Second), logger).DialContext,
	}

	client := &http.Client{
		Transport: transport,
	}

	// First request to the test server
	resp, err := client.Get(server.URL) //nolint:noctx // It is a test
	require.NoError(t, err, "first request failed")
	_, _ = io.ReadAll(resp.Body)
	resp.Body.Close()

	// Wait for a duration longer than IdleConnTimeout
	waitTime := 6 * time.Second
	time.Sleep(waitTime)

	// Second request to the test server after idle timeout
	resp, err = client.Get(server.URL) //nolint:noctx // It is a test
	require.NoError(t, err, "second request failed")
	_, _ = io.ReadAll(resp.Body)
	resp.Body.Close()

What did you see happen?

use of closed network connection

What did you expect to see?

We expected a new connection would be used to read from the buffer. Instead it reuses an old connection that has already been closed due to timeout

[gabyhelp]

Related Issues

• net/http: setting IdleConnTimeout to a low value on http.Transport is causing non-deterministic tls handshake failures #33891
• net/http: IdleConnTimeout is invalid for HTTP/2 #69205
• x/net/http2: raciness in stream close prevents closing of failed connections, blocking subsequent requests #59690
• net/http: dial should not be canceled if an idle connection is reused #66442 (closed)
• net/http: client closes persistent connections when context deadline is exceeded without reuse #45559
• net/http: TCP connection is not closed after http client makes a https request via a http proxy server which doesn't response #28012 (closed)
• net/http: Connection to HTTP/2 site with IdleConnTimeout hangs #34387 (closed)
• net/http: transport closes healthy connections when pool limit is reached #42650
• net/http: zombie connection leaked after Server.IdleTimeout #51614 (closed)
• net/http: Errors from persistConn.readLoop not returned to client still writing a request #62447

_{(Emoji vote if this was helpful or unhelpful; more detailed feedback welcome in this discussion.)}

[seankhliao]

If I remove your custom dialer (you haven't given an implementation for it), the test passes. That leads me to believe the error is in your dialer implementation and not in net/http.

[khushijain21]

The custom dialer does nothing but log an error if any. Here is the implementation

type loggingConn struct {
	net.Conn
	logger *logp.Logger
}

func LoggingDialer(d Dialer, logger *logp.Logger) Dialer {
	return DialerFunc(func(ctx context.Context, network, addr string) (net.Conn, error) {
		logger := logger.With("network.transport", network, "server.address", addr)
		c, err := d.DialContext(ctx, network, addr)
		if err != nil {
			logger.Errorf("Error dialing %v", err)
			return nil, err
		}

		logger.Debugf("Completed dialing successfully")
		return &loggingConn{c, logger}, nil
	})
}

func (l *loggingConn) Read(b []byte) (int, error) {
	n, err := l.Conn.Read(b)
	if err != nil && !errors.Is(err, io.EOF) {
		l.logger.Debugf("Error reading from connection: %v", err)
	}
	return n, err
}

func (l *loggingConn) Write(b []byte) (int, error) {
	n, err := l.Conn.Write(b)
	if err != nil && !errors.Is(err, io.EOF) {
		l.logger.Debugf("Error writing to connection: %v", err)
	}
	return n, err
}

[khushijain21]

@seankhliao any other info required?

[seankhliao]

It doesn't look reproducible elsewhere?

[khushijain21]

I have not come across any other scenario

[seankhliao]

I've tested it on both a Mac and Linux, neither can reproduce the issue. If no one else can, then it's on you to investigate/give us enough detail to identify a root cause.

[khushijain21]

I see why you may not have been able to - the logger attempts to send it on the logger. Apologies - I had edited the code to print on console

func (l *loggingConn) Read(b []byte) (int, error) {
	n, err := l.Conn.Read(b)
	if err != nil && !errors.Is(err, io.EOF) {
		fmt.Printf("Error reading from connection: %v", err). // using fmt.Printf here
	}
	return n, err
}

func (l *loggingConn) Write(b []byte) (int, error) {
	n, err := l.Conn.Write(b)
	if err != nil && !errors.Is(err, io.EOF) {
		fmt.Printf(("Error writing to connection: %v", err) // using fmt.Printf here
	}
	return n, err
}

This should show you the error on console now. Let me know if you are still not able to reproduce it

[seankhliao]

can you please have a complete test case that we can just download and run?

[khushijain21]

package testing

import (
	"context"
	"errors"
	"fmt"
	"io"
	"net"
	"net/http"
	"testing"
	"time"
)

func TestMain(t *testing.T) {
	transport12 := &http.Transport{
		IdleConnTimeout: 2 * time.Second, // Close idle connections after 2 seconds
		DialContext:     LoggingDialer(&net.Dialer{Timeout: 10 * time.Second}).DialContext,
	}

	client := &http.Client{
		Transport: transport12,
	}

	// Make a request to an endpoint that accepts multiple connections
	url := "https://httpbin.org/get"

	// Perform the first request
	fmt.Println("Sending first request")
	resp, err := client.Get(url)
	if err != nil {
		fmt.Println("Error:", err)
		return
	}
	_, _ = io.ReadAll(resp.Body)
	resp.Body.Close()
	fmt.Println("First request completed")

	// Wait for a duration longer than IdleConnTimeout
	fmt.Printf("Waiting for 6 seconds (IdleConnTimeout is 5 seconds)...\n")
	time.Sleep(6 * time.Second)

	// Perform another request after the idle timeout
	fmt.Println("Sending second request")
	resp, err = client.Get(url)
	if err != nil {
		fmt.Println("Error:", err)
		return
	}
	body, _ := io.ReadAll(resp.Body)
	resp.Body.Close()
	fmt.Println("Second request completed with response:", string(body))

}

type loggingConn struct {
	net.Conn
}
type Dialer interface {
	Dial(network, address string) (net.Conn, error)
	DialContext(ctx context.Context, network, address string) (net.Conn, error)
}

func (d DialerFunc) Dial(network, address string) (net.Conn, error) {
	return d(context.Background(), network, address)
}

func (d DialerFunc) DialContext(ctx context.Context, network, address string) (net.Conn, error) {
	return d(ctx, network, address)
}

type DialerFunc func(ctx context.Context, network, address string) (net.Conn, error)

func LoggingDialer(d Dialer) Dialer {
	return DialerFunc(func(ctx context.Context, network, addr string) (net.Conn, error) {

		c, err := d.DialContext(ctx, network, addr)
		if err != nil {
			fmt.Printf("Error dialing %v", err)
			return nil, err
		}

		fmt.Printf("Completed dialing successfully")
		return &loggingConn{c}, nil
	})
}

func (l *loggingConn) Read(b []byte) (int, error) {
	n, err := l.Conn.Read(b)
	if err != nil && !errors.Is(err, io.EOF) {
		fmt.Printf("Error reading from connection: %v", err)
	}
	return n, err
}

func (l *loggingConn) Write(b []byte) (int, error) {
	n, err := l.Conn.Write(b)
	if err != nil && !errors.Is(err, io.EOF) {
		fmt.Printf("Error writing to connection: %v", err)
	}
	return n, err
}

and the o/p on my console

Sending first request
Completed dialing successfullyFirst request completed
Waiting for 6 seconds (IdleConnTimeout is 5 seconds)...
Error reading from connection: read tcp 192.168.29.243:60951->98.84.71.227:443: use of closed network connectionSending second request
Completed dialing successfullySecond request completed with response: {
  "args": {},
  "headers": {
    "Accept-Encoding": "gzip",
    "Host": "httpbin.org",
    "User-Agent": "Go-http-client/1.1",
    "X-Amzn-Trace-Id": "Root=1-673c928e-6ca58a7c0a789fb01eda2c6d"
  },
  "origin": "49.37.241.173",
  "url": "https://httpbin.org/get"
}