From da90a424b53261057c480115176d9e22d23d81cd Mon Sep 17 00:00:00 2001 From: dencoded <33698537+dencoded@users.noreply.github.com> Date: Tue, 27 Nov 2018 21:31:08 -0500 Subject: [PATCH 1/4] analytics RecordHit fixed --- handler_success.go | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) diff --git a/handler_success.go b/handler_success.go index 6a2f2f3e4ac..94e7be9900b 100644 --- a/handler_success.go +++ b/handler_success.go @@ -4,13 +4,14 @@ import ( "bytes" "encoding/base64" "io" + "io/ioutil" "net/http" "runtime/pprof" "strconv" "strings" "time" - cache "github.com/pmylund/go-cache" + "github.com/pmylund/go-cache" "github.com/TykTechnologies/tyk/request" @@ -151,10 +152,18 @@ func (s *SuccessHandler) RecordHit(r *http.Request, timing int64, code int, resp // mw_redis_cache instead? is there a reason not // to include that in the analytics? if responseCopy != nil { + // Make a copy of response body as Response.Write resets underlying buffer to 0 len + responseCopyBodyBuffer := new(bytes.Buffer) + recordBodyBuffer := new(bytes.Buffer) + io.Copy(responseCopyBodyBuffer, responseCopy.Body) // this resets responseCopy.Body buffer to 0 len + *recordBodyBuffer = *responseCopyBodyBuffer + responseCopy.Body = ioutil.NopCloser(recordBodyBuffer) // fix responseCopy.Body buffer after io.Copy // Get the wire format representation var wireFormatRes bytes.Buffer - responseCopy.Write(&wireFormatRes) + responseCopy.Write(&wireFormatRes) // this resets responseCopy.Body buffer to 0 len again rawResponse = base64.StdEncoding.EncodeToString(wireFormatRes.Bytes()) + // fix Body to be read again + responseCopy.Body = ioutil.NopCloser(responseCopyBodyBuffer) // fix responseCopy.Body buffer after responseCopy.Write } } From 0fcdfcfcdbcee5cf116365ae0687ca943db2c42c Mon Sep 17 00:00:00 2001 From: Leonid Bugaev Date: Wed, 28 Nov 2018 18:27:19 +0300 Subject: [PATCH 2/4] Add tests for analytics with cache --- gateway_test.go | 95 +++++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 95 insertions(+) diff --git a/gateway_test.go b/gateway_test.go index 4b53a89e2fb..355c3a65d7a 100644 --- a/gateway_test.go +++ b/gateway_test.go @@ -646,6 +646,101 @@ func TestAnalytics(t *testing.T) { t.Error("Analytics record do not match", record) } }) + + t.Run("Detailed analytics", func(t *testing.T) { + defer resetTestConfig() + globalConf := config.Global() + globalConf.AnalyticsConfig.EnableDetailedRecording = true + config.SetGlobal(globalConf) + + buildAndLoadAPI(func(spec *APISpec) { + spec.UseKeylessAccess = false + spec.Proxy.ListenPath = "/" + }) + + key := createSession() + + authHeaders := map[string]string{ + "authorization": key, + } + + ts.Run(t, test.TestCase{ + Path: "/", Headers: authHeaders, Code: 200, + }) + + // let records to to be sent + time.Sleep(recordsBufferFlushInterval + 50) + + results := analytics.Store.GetAndDeleteSet(analyticsKeyName) + if len(results) != 1 { + t.Error("Should return 1 record: ", len(results)) + } + + var record AnalyticsRecord + msgpack.Unmarshal(results[0].([]byte), &record) + if record.ResponseCode != 200 { + t.Error("Analytics record do not match", record) + } + + if record.RawRequest == "" { + t.Error("Detailed request info not found", record) + } + + if record.RawResponse == "" { + t.Error("Detailed response info not found", record) + } + }) + + t.Run("Detailed analytics with cache", func(t *testing.T) { + defer resetTestConfig() + globalConf := config.Global() + globalConf.AnalyticsConfig.EnableDetailedRecording = true + config.SetGlobal(globalConf) + + buildAndLoadAPI(func(spec *APISpec) { + spec.UseKeylessAccess = false + spec.Proxy.ListenPath = "/" + spec.CacheOptions = apidef.CacheOptions{ + CacheTimeout: 120, + EnableCache: true, + CacheAllSafeRequests: true, + } + }) + + key := createSession() + + authHeaders := map[string]string{ + "authorization": key, + } + + ts.Run(t, []test.TestCase{ + {Path: "/", Headers: authHeaders, Code: 200}, + {Path: "/", Headers: authHeaders, Code: 200}, + }...) + + // let records to to be sent + time.Sleep(recordsBufferFlushInterval + 50) + + results := analytics.Store.GetAndDeleteSet(analyticsKeyName) + if len(results) != 2 { + t.Error("Should return 1 record: ", len(results)) + } + + // Take second cached request + var record AnalyticsRecord + msgpack.Unmarshal(results[1].([]byte), &record) + if record.ResponseCode != 200 { + t.Error("Analytics record do not match", record) + } + + if record.RawRequest == "" { + t.Error("Detailed request info not found", record) + } + + if record.RawResponse == "" { + t.Error("Detailed response info not found", record) + } + }) } func TestListener(t *testing.T) { From 6bde723762552d0e189d7d30e27ac2534667d860 Mon Sep 17 00:00:00 2001 From: dencoded <33698537+dencoded@users.noreply.github.com> Date: Wed, 28 Nov 2018 11:48:18 -0500 Subject: [PATCH 3/4] Revert "analytics RecordHit fixed" This reverts commit da90a424b53261057c480115176d9e22d23d81cd. --- handler_success.go | 13 ++----------- 1 file changed, 2 insertions(+), 11 deletions(-) diff --git a/handler_success.go b/handler_success.go index 94e7be9900b..6a2f2f3e4ac 100644 --- a/handler_success.go +++ b/handler_success.go @@ -4,14 +4,13 @@ import ( "bytes" "encoding/base64" "io" - "io/ioutil" "net/http" "runtime/pprof" "strconv" "strings" "time" - "github.com/pmylund/go-cache" + cache "github.com/pmylund/go-cache" "github.com/TykTechnologies/tyk/request" @@ -152,18 +151,10 @@ func (s *SuccessHandler) RecordHit(r *http.Request, timing int64, code int, resp // mw_redis_cache instead? is there a reason not // to include that in the analytics? if responseCopy != nil { - // Make a copy of response body as Response.Write resets underlying buffer to 0 len - responseCopyBodyBuffer := new(bytes.Buffer) - recordBodyBuffer := new(bytes.Buffer) - io.Copy(responseCopyBodyBuffer, responseCopy.Body) // this resets responseCopy.Body buffer to 0 len - *recordBodyBuffer = *responseCopyBodyBuffer - responseCopy.Body = ioutil.NopCloser(recordBodyBuffer) // fix responseCopy.Body buffer after io.Copy // Get the wire format representation var wireFormatRes bytes.Buffer - responseCopy.Write(&wireFormatRes) // this resets responseCopy.Body buffer to 0 len again + responseCopy.Write(&wireFormatRes) rawResponse = base64.StdEncoding.EncodeToString(wireFormatRes.Bytes()) - // fix Body to be read again - responseCopy.Body = ioutil.NopCloser(responseCopyBodyBuffer) // fix responseCopy.Body buffer after responseCopy.Write } } From 86487a22cd94346d98678eb5591a313618457edd Mon Sep 17 00:00:00 2001 From: dencoded <33698537+dencoded@users.noreply.github.com> Date: Wed, 28 Nov 2018 12:41:21 -0500 Subject: [PATCH 4/4] convert Body to our custom nopCloser in ServeHTTPForCache as well, record RawResponse for cache hits --- mw_redis_cache.go | 3 ++- reverse_proxy.go | 11 ++++++----- 2 files changed, 8 insertions(+), 6 deletions(-) diff --git a/mw_redis_cache.go b/mw_redis_cache.go index 3c6fcb375a3..7a4d8ad89dc 100644 --- a/mw_redis_cache.go +++ b/mw_redis_cache.go @@ -231,6 +231,7 @@ func (m *RedisCacheMiddleware) ProcessRequest(w http.ResponseWriter, r *http.Req if err != nil { log.Error("Could not create response object: ", err) } + nopCloseResponseBody(newRes) defer newRes.Body.Close() for _, h := range hopHeaders { @@ -263,7 +264,7 @@ func (m *RedisCacheMiddleware) ProcessRequest(w http.ResponseWriter, r *http.Req // Record analytics if !m.Spec.DoNotTrack { - go m.sh.RecordHit(r, 0, newRes.StatusCode, nil) + go m.sh.RecordHit(r, 0, newRes.StatusCode, newRes) } // Stop any further execution diff --git a/reverse_proxy.go b/reverse_proxy.go index 18431c06db2..65ec309e33a 100644 --- a/reverse_proxy.go +++ b/reverse_proxy.go @@ -371,7 +371,11 @@ func (p *ReverseProxy) ServeHTTP(rw http.ResponseWriter, req *http.Request) *htt } func (p *ReverseProxy) ServeHTTPForCache(rw http.ResponseWriter, req *http.Request) *http.Response { - return p.WrappedServeHTTP(rw, req, true) + resp := p.WrappedServeHTTP(rw, req, true) + + nopCloseResponseBody(resp) + + return resp } func (p *ReverseProxy) CheckHardTimeoutEnforced(spec *APISpec, req *http.Request) (bool, int) { @@ -890,11 +894,8 @@ func (n nopCloser) Read(p []byte) (int, error) { return num, err } -// Close is a no-op Close plus moves position to the start just in case +// Close is a no-op Close func (n nopCloser) Close() error { - // seek to the start if body ever called to be closed - n.Seek(0, io.SeekStart) - return nil }