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

Jump to bottom

net/http: Reader.Read called after receiving EOF #50155

Closed
samutamm opened this issue Dec 14, 2021 · 3 comments
Closed

net/http: Reader.Read called after receiving EOF #50155

samutamm opened this issue Dec 14, 2021 · 3 comments
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone
Backlog

Comments

@samutamm
Copy link

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

$ go version
go version go1.17.2 darwin/amd64

Does this issue reproduce with the latest release?

What operating system and processor architecture are you using (go env)?

go env Output
$ go env
GO111MODULE="on"
GOARCH="amd64"
GOBIN=""
GOCACHE="/Users/samutamm/Library/Caches/go-build"
GOENV="/Users/samutamm/Library/Application Support/go/env"
GOEXE=""
GOEXPERIMENT=""
GOFLAGS=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOINSECURE=""
GOMODCACHE="/Users/samutamm/go/pkg/mod"
GONOPROXY="on"
GONOSUMDB=""
GOOS="darwin"
GOPATH="/Users/samutamm/go"
GOPRIVATE=""
GOPROXY="https://proxy.golang.org,direct"
GOROOT="/usr/local/Cellar/go/1.17.2/libexec"
GOSUMDB="sum.golang.org"
GOTMPDIR=""
GOTOOLDIR="/usr/local/Cellar/go/1.17.2/libexec/pkg/tool/darwin_amd64"
GOVCS=""
GOVERSION="go1.17.2"
GCCGO="gccgo"
AR="ar"
CC="clang"
CXX="clang++"
CGO_ENABLED="1"
GOMOD="/dev/null"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"
PKG_CONFIG="pkg-config"
GOROOT/bin/go version: go version go1.17.2 darwin/amd64
GOROOT/bin/go tool compile -V: compile version go1.17.2
uname -v: Darwin Kernel Version 21.1.0: Wed Oct 13 17:33:23 PDT 2021; root:xnu-8019.41.5~1/RELEASE_X86_64
ProductName:	macOS
ProductVersion:	12.0.1
BuildVersion:	21A559
lldb --version: lldb-1300.0.32.4
Swift version 5.5.1-dev

What did you do?

I have very simple Reader that has a channel and Read function:

type MyReader struct {
	ch chan bool
}
func (mr *MyReader) Read(p []byte) (n int, err error) {
	fmt.Printf("my reader read\n")
	close(mr.ch)
	return 0, io.EOF
}

The Read function returns 0, io.EOF to indicate that the reader has reached to the end of the file and should not be called again.
I use MyReader as HTTP request body, like in the complete example below, and I send 1000000 such a requests to a simple web server.

package main

import (
	"fmt"
	"io"
	"net/http"
	"sync"
	"time"

	"math/rand"
)

type MyReader struct {
	ch chan bool
}

func (mr *MyReader) Read(p []byte) (n int, err error) {
	fmt.Printf("my reader read\n")
	close(mr.ch)
	return 0, io.EOF // tell callers that reached EOF
}

func NewMyReader() io.Reader {
	return &MyReader{ch: make(chan bool)}
}

func checkStart(w http.ResponseWriter, r *http.Request) {
}

func getServer(addr string) *http.Server {
	mux := http.NewServeMux()
	mux.HandleFunc("/", checkStart)
	server := &http.Server{
		Addr:    addr,
		Handler: mux,
	}
	go func() {
		err := server.ListenAndServe()
		if err != nil {
			panic(err)
		}
	}()

	started := false
	for i := 0; i < 10; i++ {
		req, err := http.NewRequest(http.MethodGet, "http://"+addr, nil)
		if err != nil {
			panic(err)
		}
		_, err = http.DefaultClient.Do(req)
		if err == nil {
			started = true
			break
		}
		time.Sleep(50 * time.Millisecond)
	}
	if !started {
		fmt.Printf("server not started\n")
	}
	return server
}

func main() {
	server := getServer("127.0.0.1:8080")
	defer server.Close()

	wg := sync.WaitGroup{}
	for i := 0; i < 1000000; i++ {
		wg.Add(1)
		time.Sleep(time.Duration(10 + rand.Intn(100)) * time.Microsecond) // sleep 10 - 110 ms between queries
		go func(i int) {
			defer wg.Done()
			req, err := http.NewRequest(http.MethodGet, "http://127.0.0.1:8080", NewMyReader())
			if err != nil {
				return
			}
			fmt.Printf("%v\n", i)
			resp, err := http.DefaultClient.Do(req)
			if err != nil {
				return
			}
			resp.Body.Close()
		}(i)
	}
	wg.Wait()
}

I execute the code above on command line

go run main.go

and I get an panic: close of closed channel quite consistently. The error is not thrown every time but about one out of three runs.
I noticed that if the sleep between the request is fixed to some value, the error is thrown much less frequently. But with random sleep interval between 10-110 microseconds, the error is easier to reproduce.

What did you expect to see?

I expect that the Read function would not be called after the MyReader has returned (0, io.EOF). I noticed that some of the Reader implementations (like this one) use sync.Mutex and boolean flags to return early from Read call when EOF had been seen first time.

However, it seems like a bug that most of the time the first io.EOF is enough to liberate the Reader from reading, but sometimes there are still Read calls after (0, io.EOF) has been returned.

What did you see instead?

After running the program few times, I see following stack trace:

...
my reader read
509670
my reader read
my reader read
panic: close of closed channel

goroutine 1460930 [running]:
main.(*MyReader).Read(0xc0005ea268, {0x1, 0xc0008adab8, 0x12010cf})
	/Users/samutamm/sandbox/performance_test/main.go:19 +0x52
net/http.(*readTrackingBody).Read(0x0, {0xc000862000, 0xc0008adb00, 0x104a512})
	/usr/local/Cellar/go/1.17.2/libexec/src/net/http/transport.go:634 +0x2a
io.(*multiReader).Read(0xc0005f4120, {0xc000862000, 0x8000, 0x8000})
	/usr/local/Cellar/go/1.17.2/libexec/src/io/multi.go:26 +0x9b
io.copyBuffer({0x9a9c008, 0xc0002cc270}, {0x12ded00, 0xc0005f4120}, {0x0, 0x0, 0x0})
	/usr/local/Cellar/go/1.17.2/libexec/src/io/io.go:423 +0x1b2
io.Copy(...)
	/usr/local/Cellar/go/1.17.2/libexec/src/io/io.go:382
net/http.(*transferWriter).doBodyCopy(0xc0000baaa0, {0x9a9c008, 0xc0002cc270}, {0x12ded00, 0xc0005f4120})
	/usr/local/Cellar/go/1.17.2/libexec/src/net/http/transfer.go:410 +0x4d
net/http.(*transferWriter).writeBody(0xc0000baaa0, {0x12deb60, 0xc0001ca200})
	/usr/local/Cellar/go/1.17.2/libexec/src/net/http/transfer.go:357 +0x225
net/http.(*Request).write(0xc0004c1100, {0x12deb60, 0xc0001ca200}, 0x0, 0xc000717200, 0x0)
	/usr/local/Cellar/go/1.17.2/libexec/src/net/http/request.go:698 +0xb4e
net/http.(*persistConn).writeLoop(0xc0005c85a0)
	/usr/local/Cellar/go/1.17.2/libexec/src/net/http/transport.go:2389 +0x189
created by net/http.(*Transport).dialConn
	/usr/local/Cellar/go/1.17.2/libexec/src/net/http/transport.go:1748 +0x1e65
exit status 2
@cherrymui cherrymui changed the title net/http/transfer.go calls Reader.Read after receiving EOF error net/http: Reader.Read called after receiving EOF Dec 14, 2021
@cherrymui cherrymui added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Dec 14, 2021
@cherrymui cherrymui added this to the Backlog milestone Dec 14, 2021
@cherrymui
Copy link
Member

It's unclear to me if a Read method can be called after returning EOF. I cannot find it documented one way or another.

cc @neild

@seankhliao
Copy link
Member

Looks like it's transferWriter probing to determine if it should send a chunked request:

===== read 1 =====
goroutine 3110925 [running]:
runtime/debug.Stack()
	/home/arccy/sdk/gotip/src/runtime/debug/stack.go:24 +0x65
main.(*MyReader).Read(0xc000643d20, {0xc001ae2480?, 0x0?, 0xc001305040?})
	/home/arccy/tmp/testrepo-722/main.go:28 +0x154
net/http.(*readTrackingBody).Read(0x0?, {0xc001e2c166?, 0x0?, 0xc00137d8c0?})
	/home/arccy/sdk/gotip/src/net/http/transport.go:634 +0x2a
net/http.(*transferWriter).probeRequestBody.func1({0x71ec60, 0xc000fbe240})
	/home/arccy/sdk/gotip/src/net/http/transfer.go:210 +0x5a
created by net/http.(*transferWriter).probeRequestBody
	/home/arccy/sdk/gotip/src/net/http/transfer.go:207 +0x12d

===== read 2 =====
goroutine 3111055 [running]:
runtime/debug.Stack()
	/home/arccy/sdk/gotip/src/runtime/debug/stack.go:24 +0x65
main.(*MyReader).Read(0xc000643d20, {0x7f6b764a4f01?, 0xc00150eac8?, 0x624a2f?})
	/home/arccy/tmp/testrepo-722/main.go:25 +0xf9
net/http.(*readTrackingBody).Read(0x0?, {0xc000116000?, 0xc00150eb10?, 0x44ac72?})
	/home/arccy/sdk/gotip/src/net/http/transport.go:634 +0x2a
io.(*multiReader).Read(0xc001bde918, {0xc000116000, 0x8000, 0x8000})
	/home/arccy/sdk/gotip/src/io/multi.go:26 +0x9b
io.copyBuffer({0x7f6b4c5b7018, 0xc0002427d0}, {0x71e920, 0xc001bde918}, {0x0, 0x0, 0x0})
	/home/arccy/sdk/gotip/src/io/io.go:426 +0x1b2
io.Copy(...)
	/home/arccy/sdk/gotip/src/io/io.go:385
net/http.(*transferWriter).doBodyCopy(0xc000f94500, {0x7f6b4c5b7018?, 0xc0002427d0?}, {0x71e920?, 0xc001bde918?})
	/home/arccy/sdk/gotip/src/net/http/transfer.go:411 +0x4d
net/http.(*transferWriter).writeBody(0xc000f94500, {0x71e780, 0xc0003e2800})
	/home/arccy/sdk/gotip/src/net/http/transfer.go:358 +0x21a
net/http.(*Request).write(0xc000f99100, {0x71e780, 0xc0003e2800}, 0x0, 0xc000f8ebd0, 0x0)
	/home/arccy/sdk/gotip/src/net/http/request.go:698 +0xb46
net/http.(*persistConn).writeLoop(0xc000ba26c0)
	/home/arccy/sdk/gotip/src/net/http/transport.go:2389 +0x185
created by net/http.(*Transport).dialConn
	/home/arccy/sdk/gotip/src/net/http/transport.go:1748 +0x1791

@ianlancetaylor
Copy link
Contributor

The io.Reader interface does not require its users to stop calling Read after a call to Read returns io.EOF. And common implementations of Read, such as the one for os.File, work fine if called after a return of io.EOF. Moreover, the io.Reader documentaiton is clear that a Read method that returns a non-zero number of bytes read along with io.EOF must expect to be called again even though it already returned io.EOF. Therefore, I think that every Read method must assume in general that it can be called again after it returns io.EOF (at which point it should presumably return io.EOF again).

I'm going to close this because I don't think there is anything to change in the Go library.

@samutamm samutamm mentioned this issue Dec 14, 2021
Closed
@golang golang locked and limited conversation to collaborators Dec 14, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Projects
None yet
Milestone
Backlog
Development

No branches or pull requests
5 participants
@ianlancetaylor @samutamm @gopherbot @seankhliao @cherrymui