From 293ae58d321b790b83f2608e2f7ef9d172140e26 Mon Sep 17 00:00:00 2001 From: Frank Schroeder Date: Sun, 18 Mar 2018 23:53:37 +0100 Subject: [PATCH] Issue #460: Fix access logging when gzip is enabled The code that captured the content length and the status code for the access logger depended on the http.Handler to be of a certain type. Wrapping the handler in a gzip handler broke this silently. This fix removes that dependency and instead wraps the response writer directly to capture the values required for access logging. Fixes #460 --- proxy/http_handler.go | 16 +-------- proxy/http_integration_test.go | 24 +++++++++++-- proxy/http_proxy.go | 65 ++++++++++++++++++++++++---------- 3 files changed, 70 insertions(+), 35 deletions(-) diff --git a/proxy/http_handler.go b/proxy/http_handler.go index 18281eecd..cfde275eb 100644 --- a/proxy/http_handler.go +++ b/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 -} diff --git a/proxy/http_integration_test.go b/proxy/http_integration_test.go index 1a0870306..b9f1776c5 100644 --- a/proxy/http_integration_test.go +++ b/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", diff --git a/proxy/http_proxy.go b/proxy/http_proxy.go index 0898d7afe..52287c87d 100644 --- a/proxy/http_proxy.go +++ b/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" @@ -182,7 +183,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) @@ -192,28 +194,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, @@ -227,3 +223,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 +}