From e93836d9b35f5ec231da91807f00dab3d1a28fd9 Mon Sep 17 00:00:00 2001 From: Maciej Borsz Date: Tue, 12 Jan 2021 09:45:43 +0100 Subject: [PATCH] Add trace to SerializeObject --- .../endpoints/handlers/responsewriters/BUILD | 1 + .../handlers/responsewriters/errors_test.go | 3 +- .../handlers/responsewriters/writers.go | 25 ++++++ .../handlers/responsewriters/writers_test.go | 87 ++++++++++++------- 4 files changed, 84 insertions(+), 32 deletions(-) diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/BUILD b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/BUILD index 90427ce85d8..86356415235 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/BUILD +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/BUILD @@ -57,6 +57,7 @@ go_library( "//staging/src/k8s.io/apiserver/pkg/util/feature:go_default_library", "//staging/src/k8s.io/apiserver/pkg/util/flushwriter:go_default_library", "//staging/src/k8s.io/apiserver/pkg/util/wsstream:go_default_library", + "//vendor/k8s.io/utils/trace:go_default_library", ], ) diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/errors_test.go b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/errors_test.go index 457a5553290..4645a5f5701 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/errors_test.go +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/errors_test.go @@ -20,6 +20,7 @@ import ( "errors" "net/http" "net/http/httptest" + "net/url" "testing" "k8s.io/apimachinery/pkg/runtime" @@ -77,7 +78,7 @@ func TestForbidden(t *testing.T) { observer := httptest.NewRecorder() scheme := runtime.NewScheme() negotiatedSerializer := serializer.NewCodecFactory(scheme).WithoutConversion() - Forbidden(request.NewDefaultContext(), test.attributes, observer, &http.Request{}, test.reason, negotiatedSerializer) + Forbidden(request.NewDefaultContext(), test.attributes, observer, &http.Request{URL: &url.URL{Path: "/path"}}, test.reason, negotiatedSerializer) result := string(observer.Body.Bytes()) if result != test.expected { t.Errorf("Forbidden response body(%#v...)\n expected: %v\ngot: %v", test.attributes, test.expected, result) diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go index 65cb389e517..21adc12e297 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers.go @@ -26,6 +26,7 @@ import ( "strconv" "strings" "sync" + "time" "k8s.io/apiserver/pkg/features" @@ -40,6 +41,7 @@ import ( utilfeature "k8s.io/apiserver/pkg/util/feature" "k8s.io/apiserver/pkg/util/flushwriter" "k8s.io/apiserver/pkg/util/wsstream" + utiltrace "k8s.io/utils/trace" ) // StreamObject performs input stream negotiation from a ResourceStreamer and writes that to the response. @@ -86,11 +88,20 @@ func StreamObject(statusCode int, gv schema.GroupVersion, s runtime.NegotiatedSe // The context is optional and can be nil. This method will perform optional content compression if requested by // a client and the feature gate for APIResponseCompression is enabled. func SerializeObject(mediaType string, encoder runtime.Encoder, hw http.ResponseWriter, req *http.Request, statusCode int, object runtime.Object) { + trace := utiltrace.New("SerializeObject", + utiltrace.Field{"method", req.Method}, + utiltrace.Field{"url", req.URL.Path}, + utiltrace.Field{"protocol", req.Proto}, + utiltrace.Field{"mediaType", mediaType}, + utiltrace.Field{"encoder", encoder.Identifier()}) + defer trace.LogIfLong(5 * time.Second) + w := &deferredResponseWriter{ mediaType: mediaType, statusCode: statusCode, contentEncoding: negotiateContentEncoding(req), hw: hw, + trace: trace, } err := encoder.Encode(object, w) @@ -177,9 +188,23 @@ type deferredResponseWriter struct { hasWritten bool hw http.ResponseWriter w io.Writer + + trace *utiltrace.Trace } func (w *deferredResponseWriter) Write(p []byte) (n int, err error) { + if w.trace != nil { + // This Step usually wraps in-memory object serialization. + w.trace.Step("About to start writing response", utiltrace.Field{"size", len(p)}) + + firstWrite := !w.hasWritten + defer func() { + w.trace.Step("Write call finished", + utiltrace.Field{"writer", fmt.Sprintf("%T", w.w)}, + utiltrace.Field{"size", len(p)}, + utiltrace.Field{"firstWrite", firstWrite}) + }() + } if w.hasWritten { return w.w.Write(p) } diff --git a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers_test.go b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers_test.go index ace0f0a7096..3b2b4097024 100644 --- a/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers_test.go +++ b/staging/src/k8s.io/apiserver/pkg/endpoints/handlers/responsewriters/writers_test.go @@ -26,6 +26,7 @@ import ( "io/ioutil" "net/http" "net/http/httptest" + "net/url" "reflect" "testing" @@ -62,9 +63,12 @@ func TestSerializeObjectParallel(t *testing.T) { compressionEnabled: true, out: largePayload, mediaType: "application/json", - req: &http.Request{Header: http.Header{ - "Accept-Encoding": []string{"gzip"}, - }}, + req: &http.Request{ + Header: http.Header{ + "Accept-Encoding": []string{"gzip"}, + }, + URL: &url.URL{Path: "/path"}, + }, wantCode: http.StatusOK, wantHeaders: http.Header{ "Content-Type": []string{"application/json"}, @@ -130,7 +134,7 @@ func TestSerializeObject(t *testing.T) { { name: "serialize object", out: smallPayload, - req: &http.Request{Header: http.Header{}}, + req: &http.Request{Header: http.Header{}, URL: &url.URL{Path: "/path"}}, wantCode: http.StatusOK, wantHeaders: http.Header{"Content-Type": []string{""}}, wantBody: smallPayload, @@ -140,7 +144,7 @@ func TestSerializeObject(t *testing.T) { name: "return content type", out: smallPayload, mediaType: "application/json", - req: &http.Request{Header: http.Header{}}, + req: &http.Request{Header: http.Header{}, URL: &url.URL{Path: "/path"}}, wantCode: http.StatusOK, wantHeaders: http.Header{"Content-Type": []string{"application/json"}}, wantBody: smallPayload, @@ -151,7 +155,7 @@ func TestSerializeObject(t *testing.T) { statusCode: http.StatusBadRequest, out: smallPayload, mediaType: "application/json", - req: &http.Request{Header: http.Header{}}, + req: &http.Request{Header: http.Header{}, URL: &url.URL{Path: "/path"}}, wantCode: http.StatusBadRequest, wantHeaders: http.Header{"Content-Type": []string{"application/json"}}, wantBody: smallPayload, @@ -162,7 +166,7 @@ func TestSerializeObject(t *testing.T) { out: smallPayload, outErrs: []error{fmt.Errorf("bad")}, mediaType: "application/json", - req: &http.Request{Header: http.Header{}}, + req: &http.Request{Header: http.Header{}, URL: &url.URL{Path: "/path"}}, wantCode: http.StatusInternalServerError, wantHeaders: http.Header{"Content-Type": []string{"application/json"}}, wantBody: smallPayload, @@ -173,7 +177,7 @@ func TestSerializeObject(t *testing.T) { out: smallPayload, outErrs: []error{fmt.Errorf("bad"), fmt.Errorf("bad2")}, mediaType: "application/json", - req: &http.Request{Header: http.Header{}}, + req: &http.Request{Header: http.Header{}, URL: &url.URL{Path: "/path"}}, wantCode: http.StatusInternalServerError, wantHeaders: http.Header{"Content-Type": []string{"text/plain"}}, wantBody: []byte(": bad"), @@ -184,7 +188,7 @@ func TestSerializeObject(t *testing.T) { out: smallPayload, outErrs: []error{kerrors.NewNotFound(schema.GroupResource{}, "test"), fmt.Errorf("bad2")}, mediaType: "application/json", - req: &http.Request{Header: http.Header{}}, + req: &http.Request{Header: http.Header{}, URL: &url.URL{Path: "/path"}}, statusCode: http.StatusOK, wantCode: http.StatusNotFound, wantHeaders: http.Header{"Content-Type": []string{"text/plain"}}, @@ -196,7 +200,7 @@ func TestSerializeObject(t *testing.T) { out: smallPayload, outErrs: []error{kerrors.NewNotFound(schema.GroupResource{}, "test"), fmt.Errorf("bad2")}, mediaType: "application/json", - req: &http.Request{Header: http.Header{}}, + req: &http.Request{Header: http.Header{}, URL: &url.URL{Path: "/path"}}, statusCode: http.StatusNotAcceptable, wantCode: http.StatusNotAcceptable, wantHeaders: http.Header{"Content-Type": []string{"text/plain"}}, @@ -207,9 +211,12 @@ func TestSerializeObject(t *testing.T) { name: "compression requires feature gate", out: largePayload, mediaType: "application/json", - req: &http.Request{Header: http.Header{ - "Accept-Encoding": []string{"gzip"}, - }}, + req: &http.Request{ + Header: http.Header{ + "Accept-Encoding": []string{"gzip"}, + }, + URL: &url.URL{Path: "/path"}, + }, wantCode: http.StatusOK, wantHeaders: http.Header{"Content-Type": []string{"application/json"}}, wantBody: largePayload, @@ -220,9 +227,12 @@ func TestSerializeObject(t *testing.T) { compressionEnabled: true, out: largePayload, mediaType: "application/json", - req: &http.Request{Header: http.Header{ - "Accept-Encoding": []string{"gzip"}, - }}, + req: &http.Request{ + Header: http.Header{ + "Accept-Encoding": []string{"gzip"}, + }, + URL: &url.URL{Path: "/path"}, + }, wantCode: http.StatusOK, wantHeaders: http.Header{ "Content-Type": []string{"application/json"}, @@ -237,9 +247,12 @@ func TestSerializeObject(t *testing.T) { compressionEnabled: true, out: smallPayload, mediaType: "application/json", - req: &http.Request{Header: http.Header{ - "Accept-Encoding": []string{"gzip"}, - }}, + req: &http.Request{ + Header: http.Header{ + "Accept-Encoding": []string{"gzip"}, + }, + URL: &url.URL{Path: "/path"}, + }, wantCode: http.StatusOK, wantHeaders: http.Header{ "Content-Type": []string{"application/json"}, @@ -252,9 +265,12 @@ func TestSerializeObject(t *testing.T) { compressionEnabled: true, out: largePayload, mediaType: "application/json", - req: &http.Request{Header: http.Header{ - "Accept-Encoding": []string{"deflate, , gzip,"}, - }}, + req: &http.Request{ + Header: http.Header{ + "Accept-Encoding": []string{"deflate, , gzip,"}, + }, + URL: &url.URL{Path: "/path"}, + }, wantCode: http.StatusOK, wantHeaders: http.Header{ "Content-Type": []string{"application/json"}, @@ -269,9 +285,12 @@ func TestSerializeObject(t *testing.T) { compressionEnabled: true, out: largePayload, mediaType: "application/json", - req: &http.Request{Header: http.Header{ - "Accept-Encoding": []string{"deflate"}, - }}, + req: &http.Request{ + Header: http.Header{ + "Accept-Encoding": []string{"deflate"}, + }, + URL: &url.URL{Path: "/path"}, + }, wantCode: http.StatusOK, wantHeaders: http.Header{ "Content-Type": []string{"application/json"}, @@ -284,9 +303,12 @@ func TestSerializeObject(t *testing.T) { compressionEnabled: true, out: largePayload, mediaType: "application/json", - req: &http.Request{Header: http.Header{ - "Accept-Encoding": []string{", , other, nothing, what, "}, - }}, + req: &http.Request{ + Header: http.Header{ + "Accept-Encoding": []string{", , other, nothing, what, "}, + }, + URL: &url.URL{Path: "/path"}, + }, wantCode: http.StatusOK, wantHeaders: http.Header{ "Content-Type": []string{"application/json"}, @@ -301,9 +323,12 @@ func TestSerializeObject(t *testing.T) { out: smallPayload, outErrs: []error{fmt.Errorf(string(largePayload)), fmt.Errorf("bad2")}, mediaType: "application/json", - req: &http.Request{Header: http.Header{ - "Accept-Encoding": []string{"gzip"}, - }}, + req: &http.Request{ + Header: http.Header{ + "Accept-Encoding": []string{"gzip"}, + }, + URL: &url.URL{Path: "/path"}, + }, wantCode: http.StatusInternalServerError, wantHeaders: http.Header{ "Content-Type": []string{"text/plain"},