net/http/httputil: ReverseProxy no longer uses io.ReaderFrom/WriterTo

[Zariel]

Before go 1.8 httputil.ReverseProxy would use io.CopyBuffer which would use io.ReaderFrom or io.WriterTo if possible to avoid allocation. In fixing #16659 it removed using io.CopyBuffer and implements its own without the optimisations of io.CopyBuffer to add an extra log.

Please answer these questions before submitting your issue. Thanks!

What did you do?

https://play.golang.org/p/4GjT-hwI3t

What did you expect to see?

WriteTo

What did you see instead?

Read

System details

go version go1.9 darwin/amd64
GOARCH="amd64"
GOBIN=""
GOEXE=""
GOHOSTARCH="amd64"
GOHOSTOS="darwin"
GOOS="darwin"
GOPATH="/Users/chris/dev/go"
GORACE=""
GOROOT="/usr/local/opt/go/libexec"
GOTOOLDIR="/usr/local/opt/go/libexec/pkg/tool/darwin_amd64"
GCCGO="gccgo"
CC="clang"
GOGCCFLAGS="-fPIC -m64 -pthread -fno-caret-diagnostics -Qunused-arguments -fmessage-length=0 -gno-record-gcc-switches -fno-common"
CXX="clang++"
CGO_ENABLED="1"
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.9 darwin/amd64
GOROOT/bin/go tool compile -V: compile version go1.9
uname -v: Darwin Kernel Version 15.3.0: Thu Dec 10 18:40:58 PST 2015; root:xnu-3248.30.4~1/RELEASE_X86_64
ProductName:	Mac OS X
ProductVersion:	10.11.3
BuildVersion:	15D21
lldb --version: lldb-340.4.110.1
gdb --version: GNU gdb (GDB) 8.0

[Zariel]

I suggest either reverting to calling io.CopyBuffer and logging the error returned from that or adding the interface checks to copyResponse. The former makes more sense to me as would also log write errors which adds more symmetry. I have a patch available if its an acceptable change.

[tomwans]

The former makes more sense to me as would also log write errors which adds more symmetry.

Looking at the CL that introduced this, it seems that the intent was to log only read errors: https://go-review.googlesource.com/c/go/+/30692/5/src/net/http/httputil/reverseproxy.go#264. That is why io.CopyBuffer was copied in. Whatever solution we use here should probably retain that property.

[gopherbot]

Change https://golang.org/cl/65690 mentions this issue: net/http/httputil: respect WriterTo and ReadFrom by using io.CopyBuffer

[tombergan]

I'm not sure how to resolve this without breaking #16659 or making errors spammy, which @bradfitz objected to. The issue: when WriteTo/ReadFrom returns an error, it's impossible to know if the error came from reading from src or writing to dst. That detail is hidden inside the WriteTo/ReadFrom implementation. Options are:

1. Leave the code as-is (don't support WriteTo/ReadFrom).
2. Add WriteTo/ReadFrom and log all errors from those methods, possibly making logs spammy.
3. Add WriteTo/ReadFrom but don't log any errors from those methods, possibly breaking net/http/httputil: ReverseProxy does not log errors during CopyBuffer #16659.

My inclination is to go with option 1. I don't believe that WriteTo or ReadFrom can use sendfile because resp.Body is never a simple file descriptor (not even when the incoming response is HTTP/1 without chunked encoding). At best WriteTo/ReadFrom might provide slightly more optimal buffering. I would want to see evidence of improved performance from WriteTo/ReadFrom over Read/Write before actually moving forward.

/cc @fraenkel, @Zariel

[fraenkel]

@tombergan Its more or less how we ended up with the current implementation. Since the http package doesn't provide any optimized ReadFrom/WriteTo, I would be ok with option 3.

[tombergan]

Actually, net/http's ResponseWriter implements ReaderFrom, so I think option 3 would break #16659.

To clarify: the WaitinfForInfo state is waiting for some justification that WriteTo/ReadFrom provide an actual (measurable) performance gain.

[gopherbot]

Timed out in state WaitingForInfo. Closing.

(I am just a bot, though. Please speak up if this is a mistake or you have the requested information.)

[Zariel]

Now that #10948 has landed Go's ReverseProxy will not be able to use splice due to #16659

[jameshartig]

Now that we have splice being used it's unfortunate that it's not used in ReverseProxy. I vote for using io.CopyBuffer here so there isn't a need to consistantly keep copying functionality over and any future improvements in the io package will benefit the ReverseProxy.

We currently log over 16,000 "http: proxy error: context canceled" errors per hour but I haven't seen any of the "read error" logs. Now that we have ErrorHandler if a user wants to filter out specific spammy errors (like the one above) they can do so in their own ErrorHandler.

@fraenkel, what are your thoughts?

[fraenkel]

@fastest963 I understand that you have never seen the issue but the reason why the code was changed was because we did. It was far too common to have downstream clients disappear and have no knowledge in the proxy as to who was at fault.
We can't just switch to io.Copy or io.CopyBuffer because we now lose this detail.

Do you have any data that shows using splice provides value? Which is what @tombergan was asking for above.

[jameshartig]

@fraenkel I was saying that if you added your own ErrorHandler you'd be able to capture both writing and reading errors and handle them however you like. You can ignore write errors and log reader errors. So it sounds like 2 is the best option since by default it will log all errors but you can handle it however you like if you want.

[fraenkel]

@fastest963 That is the problem, you cannot distinguish between read and write errors, its all errors. In #21814 (comment), the point was to ignore write errors. If I could have done that without splitting CopyBuffer apart I would have.
If you can tell me how to detect read errors and ignore write errors, we can easily fix this.

[jameshartig]

@fraenkel I would argue that you might want to care about some write errors. I don't know the history of why you only care about read errors but you could do something like:

func(err error) {
  if nerr, ok := err.(*net.OpError); ok && nerr.Op == "write" {
    return
  }
  // do some logging of err
}

What I'm proposing (#2 in @tombergan's comment) is that using io.CopyBuffer would end up logging all errors but if that is too noisy for you (which was @bradfitz's concern) then you can just define your own ErrorHandler method and ignore whatever errors are too noisy. We're already logging 10s of thousands of errors right now and I can't imagine that adding write errors to that would be an order of magnitude more. We already need to add filtering for context canceled errors so we'll just add whatever other ones come up that are too annoying for us. But I'd rather the default be to log more than less especially since you can always define your own handler to customize it.

Additionally, I have not tested splice yet but the fact that ReverseProxy has its own "gimped" copy of io.CopyBuffer just means it's going to get further and further behind on any improvements, bugfixes, changes, etc made to the io package method. It seems better to have it use the io package so any changes made to CopyBuffer don't need to be remembered to be copied over to the httputil package.

[fraenkel]

I did add a benchmark to see what the improvement might be. Here are the results based on fixed size responses of 100, 1000 and 8000 bytes. But as expected there is no way to detect read errors.
So the question is whether there is value in offering a way to enable a potentially more optimal path where you will lose on read errors. Just so you are aware, on any short read, you will get no logged error. The error returned from the io.CopyBuffer() is "unexpected EOF" as a string. That gets dropped in the ReverseProxy.ServeHTTP.

name         old time/op    new time/op    delta
ServeHTTP-8     117µs ± 0%     111µs ± 1%   -5.60%  (p=0.000 n=10+10)

name         old alloc/op   new alloc/op   delta
ServeHTTP-8    43.1kB ± 0%    10.6kB ± 0%  -75.27%  (p=0.000 n=9+9)

name         old allocs/op  new allocs/op  delta
ServeHTTP-8       133 ± 0%       133 ± 0%     ~     (all equal)

name         old time/op    new time/op    delta
ServeHTTP-8     120µs ± 1%     113µs ± 1%   -5.59%  (p=0.000 n=10+10)

name         old alloc/op   new alloc/op   delta
ServeHTTP-8    45.5kB ± 0%    13.2kB ± 0%  -70.91%  (p=0.000 n=10+9)

name         old allocs/op  new allocs/op  delta
ServeHTTP-8       134 ± 1%       134 ± 0%     ~     (p=0.211 n=10+10)

name         old time/op    new time/op    delta
ServeHTTP-8     145µs ± 1%     139µs ± 1%   -3.94%  (p=0.000 n=10+10)
name         old alloc/op   new alloc/op   delta
ServeHTTP-8    81.7kB ± 0%    51.0kB ± 0%  -37.55%  (p=0.000 n=9+10)
name         old allocs/op  new allocs/op  delta
ServeHTTP-8       144 ± 0%       144 ± 0%     ~     (all equal)

[jameshartig]

@fraenkel thanks for the benchmarks those definitely are useful for context. What do you mean by:

The error returned from the io.CopyBuffer() is "unexpected EOF" as a string.

It has to be an error type, right? Can you print out the type? Is it a *net.OpError?

When you say:

Just so you are aware, on any short read, you will get no logged error.

What was the change you made? Did you take the error and call getErrorHandler if there was an error from copyResponse?

[fraenkel]

@fastest963 You are correct, I forgot to call logf. But here is the actual error that comes back from io.CopyBuffer, &errors.errorString{s:"unexpected EOF"}. Is that a read or write error?

[jameshartig]

@fraenkel looks like that's an io.ErrUnexpectedEOF which I would assume is from a read. The docs:

EOF is the error returned by Read when no more input is available. Functions should return EOF only to signal a graceful end of input. If the EOF occurs unexpectedly in a structured data stream, the appropriate error is either ErrUnexpectedEOF or some other error giving more detail.

Though I'm not sure how you got that considering:

func (c *TCPConn) ReadFrom(r io.Reader) (int64, error) {
	if !c.ok() {
		return 0, syscall.EINVAL
	}
	n, err := c.readFrom(r)
	if err != nil && err != io.EOF {
		err = &OpError{Op: "readfrom", Net: c.fd.net, Source: c.fd.laddr, Addr: c.fd.raddr, Err: err}
	}
	return n, err
}

If the error is not io.EOF it wraps it in net.OpError so idk where that ErrUnexpectedEOF is coming from.

[fraenkel]

Digging a bit deeper. Splice will never be used in reverseproxy. Splice requires a TCP conn on both sides which never happens. At best you see ReadFrom or WriteTo come into play which is what is happening. Again this is part of the issue, there are 3 possible paths, all which provide different results.
Using io.CopyBuffer, content is transferring between a *http.response and *http.bodyEOFSignal.
The error comes from transfer.go:823