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 · 9 comments
Labels
NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one.
Milestone

Comments

@aronatkins
Copy link

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

matipan 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
Copy link
Author

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

@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
Copy link
Member

@bradfitz

@andybons andybons added the NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. label Apr 11, 2018
@andybons andybons added this to the Unplanned milestone Apr 11, 2018
@HaraldNordgren
Copy link
Member

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

djui 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.

@sergodeeva
Copy link

sergodeeva commented Sep 24, 2021

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

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

Haegi commented Mar 26, 2024

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

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

8 participants