Merge pull request #97953 from mborsz/deflog

Add trace to SerializeObject

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",
     ],
 )
 

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)

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)
 	}

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"},