Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Open
c1728p9 opened this issue Dec 11, 2019 · 3 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@c1728p9
Copy link

c1728p9 commented Dec 11, 2019

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.

@c1728p9 c1728p9 changed the title net/http: Server still handling connections after Close (or Shutdown) returns net/http: Server still handling new connections after Close (or Shutdown) returns Dec 11, 2019
@toothrot toothrot added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Dec 13, 2019
@toothrot toothrot added this to the Backlog milestone Dec 13, 2019
@toothrot
Copy link
Contributor

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
Copy link
Contributor

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
Copy link
Contributor

#48642 was fixed

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Development

No branches or pull requests

3 participants