Merge pull request #470 from fabiolb/issue-460-gzip-and-access-log

Issue #460: Fix access logging when gzip is enabled

proxy/http_handler.go

@@ -24,20 +24,6 @@ func newHTTPProxy(target *url.URL, tr http.RoundTripper, flush time.Duration) ht
 			}
 		},
 		FlushInterval: flush,
-		Transport:     &transport{tr, nil, nil},
+		Transport:     tr,
 	}
 }
-
-// transport executes the roundtrip and captures the response. It is not
-// safe for multiple or concurrent use since it only captures a single
-// response.
-type transport struct {
-	http.RoundTripper
-	resp *http.Response
-	err  error
-}
-
-func (t *transport) RoundTrip(r *http.Request) (*http.Response, error) {
-	t.resp, t.err = t.RoundTripper.RoundTrip(r)
-	return t.resp, t.err
-}

proxy/http_integration_test.go

@@ -14,6 +14,7 @@ import (
 	"os"
 	"regexp"
 	"sort"
+	"strconv"
 	"strings"
 	"testing"
 	"time"
@@ -306,6 +307,24 @@ func TestRedirect(t *testing.T) {
 }
 
 func TestProxyLogOutput(t *testing.T) {
+	t.Run("uncompressed response", func(t *testing.T) {
+		testProxyLogOutput(t, 73, config.Proxy{})
+	})
+	t.Run("compression enabled but no match", func(t *testing.T) {
+		testProxyLogOutput(t, 73, config.Proxy{
+			GZIPContentTypes: regexp.MustCompile(`^$`),
+		})
+	})
+	t.Run("compression enabled and active", func(t *testing.T) {
+		testProxyLogOutput(t, 28, config.Proxy{
+			GZIPContentTypes: regexp.MustCompile(`.*`),
+		})
+	})
+}
+
+func testProxyLogOutput(t *testing.T, bodySize int, cfg config.Proxy) {
+	t.Helper()
+
 	// build a format string from all log fields and one header field
 	fields := []string{"header.X-Foo:$header.X-Foo"}
 	for _, k := range logger.Fields {
@@ -322,13 +341,14 @@ func TestProxyLogOutput(t *testing.T) {
 
 	// create an upstream server
 	server := httptest.NewServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-		fmt.Fprint(w, "foo")
+		fmt.Fprint(w, "foooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooooo")
 	}))
 	defer server.Close()
 
 	// create a proxy handler with mocked time
 	tm := time.Date(2016, 1, 1, 0, 0, 0, 12345678, time.UTC)
 	proxyHandler := &HTTPProxy{
+		Config: cfg,
 		Time: func() time.Time {
 			defer func() { tm = tm.Add(1111111111 * time.Nanosecond) }()
 			return tm
@@ -379,7 +399,7 @@ func TestProxyLogOutput(t *testing.T) {
 		"request_scheme:http",
 		"request_uri:/foo?x=y",
 		"request_url:http://example.com/foo?x=y",
-		"response_body_size:3",
+		"response_body_size:" + strconv.Itoa(bodySize),
 		"response_status:200",
 		"response_time_ms:1.111",
 		"response_time_ns:1.111111111",

proxy/http_proxy.go

@@ -1,11 +1,12 @@
 package proxy
 
 import (
+	"bufio"
 	"crypto/tls"
+	"errors"
 	"io"
 	"net"
 	"net/http"
-	"net/http/httputil"
 	"net/url"
 	"strconv"
 	"strings"
@@ -181,7 +182,8 @@ func (p *HTTPProxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	}
 
 	start := timeNow()
-	h.ServeHTTP(w, r)
+	rw := &responseWriter{w: w}
+	h.ServeHTTP(rw, r)
 	end := timeNow()
 	dur := end.Sub(start)
 
@@ -191,28 +193,22 @@ func (p *HTTPProxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	if t.Timer != nil {
 		t.Timer.Update(dur)
 	}
-
-	// get response and update metrics
-	rp, ok := h.(*httputil.ReverseProxy)
-	if !ok {
-		return
-	}
-	rpt, ok := rp.Transport.(*transport)
-	if !ok {
-		return
-	}
-	if rpt.resp == nil {
+	if rw.code <= 0 {
 		return
 	}
-	metrics.DefaultRegistry.GetTimer(key(rpt.resp.StatusCode)).Update(dur)
+
+	metrics.DefaultRegistry.GetTimer(key(rw.code)).Update(dur)
 
 	// write access log
 	if p.Logger != nil {
 		p.Logger.Log(&logger.Event{
-			Start:           start,
-			End:             end,
-			Request:         r,
-			Response:        rpt.resp,
+			Start:   start,
+			End:     end,
+			Request: r,
+			Response: &http.Response{
+				StatusCode:    rw.code,
+				ContentLength: int64(rw.size),
+			},
 			RequestURL:      requestURL,
 			UpstreamAddr:    targetURL.Host,
 			UpstreamService: t.Service,
@@ -226,3 +222,36 @@ func key(code int) string {
 	b = strconv.AppendInt(b, int64(code), 10)
 	return string(b)
 }
+
+// responseWriter wraps an http.ResponseWriter to capture the status code and
+// the size of the response. It also implements http.Hijacker to forward
+// hijacking the connection to the wrapped writer if supported.
+type responseWriter struct {
+	w    http.ResponseWriter
+	code int
+	size int
+}
+
+func (rw *responseWriter) Header() http.Header {
+	return rw.w.Header()
+}
+
+func (rw *responseWriter) Write(b []byte) (int, error) {
+	n, err := rw.w.Write(b)
+	rw.size += n
+	return n, err
+}
+
+func (rw *responseWriter) WriteHeader(statusCode int) {
+	rw.w.WriteHeader(statusCode)
+	rw.code = statusCode
+}
+
+var errNoHijacker = errors.New("not a hijacker")
+
+func (rw *responseWriter) Hijack() (net.Conn, *bufio.ReadWriter, error) {
+	if hj, ok := rw.w.(http.Hijacker); ok {
+		return hj.Hijack()
+	}
+	return nil, nil, errNoHijacker
+}