net/http: Server still handling new connections after Close (or Shutdown) returns

[c1728p9]

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

$ go version
go version go1.13.4 linux/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="/home/russ/.cache/go-build"
GOENV="/home/russ/.config/go/env"
GOEXE=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="linux"
GONOPROXY=""
GONOSUMDB=""
GOOS="linux"
GOPATH="/home/russ/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/go"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/go/pkg/tool/linux_amd64"
GCCGO="gccgo"
AR="ar"
CC="gcc"
CXX="g++"
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 -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build697515286=/tmp/go-build -gno-record-gcc-switches"

What did you do?

In a loop I create a server with a unique ID, send requests to it and then close the server:

1. Start listening on socket
2. Start Server with a unique ID in a separate go routine
3. Make requests, check server ID against expected and wait for them to complete
4. Close and wait for the server to finish
5. Go back to step 1

Test which reproduces this issue:

package main

import (
	"fmt"
	"io/ioutil"
	"net"
	"net/http"
	"os"
	"strconv"
	"sync"
)

func main() {
	fmt.Println("Starting test")
	for i := 0; i < 10000; i++ {
		fmt.Println("Loop", i)

		// Start the server
		client := &http.Client{}
		closeAndWait := RunServer(i)

		// Run parellel requests and wait for them to finish
		ParallelRequets(client, i)

		// Close the server and wait for Serve to return
		closeAndWait()
	}
	fmt.Println("Test Pass")
}

func ParallelRequets(client *http.Client, expected int) {
	var wait sync.WaitGroup
	for minor := 0; minor < 2; minor++ {
		wait.Add(1)
		go func() {
			defer wait.Done()
			resp, err := client.Get("http://127.0.0.1:8081")
			if err != nil {
				fmt.Println("Get error!", err)
				return
			}
			defer resp.Body.Close()

			data, err := ioutil.ReadAll(resp.Body)
			actual, err := strconv.Atoi(string(data))

			if expected != actual {
				fmt.Printf("Mismatch! expected %v got %v\n", expected, actual)
				os.Exit(-1)
			}

		}()
	}
	wait.Wait()
}

func RunServer(major int) func() {
	fmt.Println("Starting", major)

	handler := http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		fmt.Fprintf(w, "%v", major)
	})
	server := http.Server{Handler: handler}
	listener, err := net.Listen("tcp", ":8081")
	if err != nil {
		panic("Listen error!")
	}
	done := make(chan bool, 1)

	go func() {
		err := server.Serve(listener)
		if err != http.ErrServerClosed {
			fmt.Println("Unexpected server error", err)
		}
		done <- true
	}()

	return func() {
		server.Close()
		<-done
		fmt.Println("Terminated", major)
	}
}

What did you expect to see?

Get requests always return the ID of the currently running server.

$ go run .
Starting test
Loop 0
Starting 0
Terminated 0
Loop 1
Starting 1
Terminated 1
...
Loop 9999
Starting 9999
Terminated 9999
Test Pass

What did you see instead?

Get requests intermittently return the ID of the previously running server. This occurs even though the call to Serve has completed and the server has been closed.

$ go run .
Starting test
Loop 0
Starting 0
Terminated 0
Loop 1
Starting 1
Terminated 1
...
Starting 795
Terminated 795
Loop 796
Starting 796
Terminated 796
Loop 797
Starting 797
Mismatch! expected 797 got 796
exit status 255

Other Notes

I noticed this problem when some of the integration tests I was running were spuriously failing if the same port was used multiple times. I narrowed it down to the server not actually being closed after Close or Shutdown returns so I created this issue.

[toothrot]

I can reproduce this reliably locally, but I have to increase the number of parallel requests to 10. After some more investigation, it does look like the handler is indeed invoked after we called server.Close(). I'm not an expert on internal/poll/fd_unix.go, so it's hard for me to say if this is a bug, or if TCP file descriptors just aren't expected to be synchronously closed.

I cannot reproduce this with net.Listen / Accept on my own, so I wonder if it is related to our retry semantics when accepting a connection in a http server.

I'm stumped. /cc @bradfitz

[AlexanderYastrebov]

I believe it might be caused by #48642 for which I've created a fix https://golang.org/cl/353714

I can reproduce on stock go installation also increasing parallel requests to 10 and I can not reproduce on the fix branch build.

To avoid Get error! Get "http://127.0.0.1:8081": dial tcp 127.0.0.1:8081: connect: cannot assign requested address due to paraller requests increase I've changed client to talk over multiple localhost IPs:

            ip := net.IP([]byte{127, 0, 0, byte(expected%255) + 1})
            resp, err := client.Get(fmt.Sprintf("http://%s:8081", ip))

I have also removed i < 10000 to verify it does not fail on the fix branch beyond 10k attempts.

[AlexanderYastrebov]

#48642 was fixed