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/httputil: ReverseProxy gives "context canceled" message when client disappears #20071

Open
aronatkins opened this issue Apr 21, 2017 · 6 comments

Comments

Projects
None yet
6 participants
@aronatkins
Copy link

commented Apr 21, 2017

When clients prematurely abandon a proxied HTTP request, there is no identified cause other than "context canceled".

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

go version go1.8.1 darwin/amd64

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

GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/aron/go"
GORACE=""
GOROOT="/usr/local/go"
GOTOOLDIR="/usr/local/go/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -fdebug-prefix-map=/var/folders/ts/s940qvdj5vj1czr9qh07fvtw0000gn/T/go-build063338539=/tmp/go-build -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

What did you do?

package main

import (
	"fmt"
	"log"
	"net"
	"net/http"
	"net/http/httptest"
	"net/http/httputil"
	"net/url"
	"time"
)

func main() {
	backend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		log.Printf("backend: %s", r.URL)
		w.Write([]byte("This is unexpected!"))
	}))
	defer backend.Close()

	backendURL, err := url.Parse(backend.URL)
	if err != nil {
		log.Fatalf("could not parse backend url %s: %s", backend.URL, err)
	}

	director := func(req *http.Request) {
		req.URL = &url.URL{}
		req.URL.Scheme = "http"
		req.URL.Host = backendURL.Host
		req.Host = ""
	}
	pxy := &httputil.ReverseProxy{Director: director}

	frontend := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
		log.Printf("proxying: %s", r.URL)
		pxy.ServeHTTP(w, r)
	}))
	defer frontend.Close()

	frontendURL, err := url.Parse(frontend.URL)
	if err != nil {
		log.Fatalf("could not parse frontend url %s: %s", frontend.URL, err)
	}

	conn, err := net.DialTimeout("tcp", frontendURL.Host, 5*time.Second)
	if err != nil {
		log.Fatalf("could not dial: %s: %s", frontendURL.Host, err)
	}
	conn.Write([]byte("GET / HTTP/1.1\n"))
	conn.Write([]byte(fmt.Sprintf("Host: %s\n", frontendURL.Host)))
	conn.Write([]byte("\n"))
	//_, err = io.Copy(os.Stdout, conn)
	err = conn.Close()
	if err != nil {
		log.Fatalf("could not close: %s: %s", frontendURL.Host, err)
	}
	// without this, the "http: proxy error: context canceled" message might not appear.
	time.Sleep(2 * time.Second)
}

What did you expect to see?

Not entirely sure the right amount of transparency, but it would have been helpful to have something indicating that the client has closed the connection or otherwise gone away.

What did you see instead?

2017/04/21 15:30:07 proxying: /
2017/04/21 15:30:07 http: proxy error: context canceled

I believe the context is canceled by the following code from ReverseProxy.ServeHTTP:

	ctx := req.Context()
	if cn, ok := rw.(http.CloseNotifier); ok {
		var cancel context.CancelFunc
		ctx, cancel = context.WithCancel(ctx)
		defer cancel()
		notifyChan := cn.CloseNotify()
		go func() {
			select {
			case <-notifyChan:
				cancel()
			case <-ctx.Done():
			}
		}()
	}
@matipan

This comment has been minimized.

Copy link

commented Apr 22, 2017

Hi!
It's true that the context canceled message is not very descriptive, but I don't think we need much more. In the ServeHTTP method of ReverseProxy, it's quite clear that the context will only be canceled when the http.CloseNotifier detects that the underlying connection has gone away.

I think, but I'm not sure, that it would be very easy to add a log specifying that the client has gone away:

case <-notifyChan:
        p.logf("connection closed by client") // or "client went away" or something like that
        cancel()

But I still believe it's not necessary.

What do you think?

@aronatkins

This comment has been minimized.

Copy link
Author

commented Apr 24, 2017

@matipan That may indeed be the case. I do not know all the ways the http.ResponseWriter may be prematurely closed. There have been several other similar issues related to error reporting in the reverse proxy; #18838 is one example.

@kovetskiy

This comment has been minimized.

Copy link

commented Feb 2, 2018

@matipan that's definitely not clear why context is canceled. I have chain of 3 proxy servers, and middle server was returning "context canceled". It's not really obvious message.
"connection unexpectedly closed by client" would be much much better.

@andybons

This comment has been minimized.

Copy link
Member

commented Apr 11, 2018

@andybons andybons added this to the Unplanned milestone Apr 11, 2018

@HaraldNordgren

This comment has been minimized.

Copy link
Member

commented Dec 22, 2018

Is there any way to silence the message? I'm seeing the pretty frequently and starting to realize that it's probably not harmful -- albeit pretty annoying to see in the logs daily.

@djui

This comment has been minimized.

Copy link

commented Dec 22, 2018

I believe https://golang.org/src/net/http/httputil/reverseproxy.go#L234 will report that error since the latest Go minor's versions, one can influence the error logger, trying to match on these context errors.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.