net/http/httputil: ReverseProxy gives "context canceled" message when client disappears

[aronatkins]

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]

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]

@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]

@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]

@bradfitz

[HaraldNordgren]

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]

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.

[sergodeeva]

Hi @HaraldNordgren did you find a way to silence this error? I am trying to silence it, as my logs are all polluted with this error.

Update: i think i found it. Can do something like this:

proxy := &httputil.ReverseProxy{
	Director: director,
	ErrorHandler: func(http.ResponseWriter, *http.Request, error) {
		// handle error
	},
}

[aronatkins]

@sergodeeva - we do something like the following, which logs for errors that are not cancels and always returns http.StatusBadGateway. This replaces the ReverseProxy#defaultErrorHandler implementation with one that conditionally logs. This version doesn't make use of the ReverseProxy#ErrorLog, but you can certainly alter how logging is performed.

// noContextCancelationErrors suppresses logging of "context canceled" errors while still
// logging other types of errors.
func noContextCancelationErrors(rw http.ResponseWriter, req *http.Request, err error) {
	if err != context.Canceled {
		log.Printf("http: proxy error: %v", err)
	}
	rw.WriteHeader(http.StatusBadGateway)
}

proxy := &httputil.ReverseProxy{
	// ...
	ErrorHandler: noContextCancelationErrors,
}

[Haegi]

One simple non-breaking way to indicate the reason would be to use context.WithCancelCause(...). Did you consider this option?
#64465