Merge pull request #104557 from tkashem/optimize-httplog

apiserver: construct logger for httplog only when log level is  3

staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go

@@ -35,6 +35,9 @@ import (
 // StacktracePred returns true if a stacktrace should be logged for this status.
 type StacktracePred func(httpStatus int) (logStacktrace bool)
 
+// ShouldLogRequestPred returns true if logging should be enabled for this request
+type ShouldLogRequestPred func() bool
+
 type logger interface {
 	Addf(format string, data ...interface{})
 }
@@ -89,7 +92,18 @@ func DefaultStacktracePred(status int) bool {
 
 // WithLogging wraps the handler with logging.
 func WithLogging(handler http.Handler, pred StacktracePred) http.Handler {
+	return withLogging(handler, pred, func() bool {
+		return klog.V(3).Enabled()
+	})
+}
+
+func withLogging(handler http.Handler, stackTracePred StacktracePred, shouldLogRequest ShouldLogRequestPred) http.Handler {
 	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+		if !shouldLogRequest() {
+			handler.ServeHTTP(w, req)
+			return
+		}
+
 		ctx := req.Context()
 		if old := respLoggerFromRequest(req); old != nil {
 			panic("multiple WithLogging calls!")
@@ -100,14 +114,12 @@ func WithLogging(handler http.Handler, pred StacktracePred) http.Handler {
 			startTime = receivedTimestamp
 		}
 
-		var rl *respLogger
-		rl, w = newLoggedWithStartTime(req, w, startTime)
-		rl.StacktraceWhen(pred)
+		rl := newLoggedWithStartTime(req, w, startTime)
+		rl.StacktraceWhen(stackTracePred)
 		req = req.WithContext(context.WithValue(ctx, respLoggerContextKey, rl))
+		defer rl.Log()
 
-		if klog.V(3).Enabled() {
-			defer rl.Log()
-		}
+		w = responsewriter.WrapForHTTP1Or2(rl)
 		handler.ServeHTTP(w, req)
 	})
 }
@@ -125,20 +137,18 @@ func respLoggerFromRequest(req *http.Request) *respLogger {
 	return respLoggerFromContext(req.Context())
 }
 
-func newLoggedWithStartTime(req *http.Request, w http.ResponseWriter, startTime time.Time) (*respLogger, http.ResponseWriter) {
+func newLoggedWithStartTime(req *http.Request, w http.ResponseWriter, startTime time.Time) *respLogger {
 	logger := &respLogger{
 		startTime:         startTime,
 		req:               req,
 		w:                 w,
 		logStacktracePred: DefaultStacktracePred,
 	}
-
-	rw := responsewriter.WrapForHTTP1Or2(logger)
-	return logger, rw
+	return logger
 }
 
 // newLogged turns a normal response writer into a logged response writer.
-func newLogged(req *http.Request, w http.ResponseWriter) (*respLogger, http.ResponseWriter) {
+func newLogged(req *http.Request, w http.ResponseWriter) *respLogger {
 	return newLoggedWithStartTime(req, w, time.Now())
 }
 

staging/src/k8s.io/apiserver/pkg/server/httplog/httplog_test.go

@@ -63,9 +63,11 @@ func TestWithLogging(t *testing.T) {
 	if err != nil {
 		t.Errorf("Unexpected error: %v", err)
 	}
+
+	shouldLogRequest := func() bool { return true }
 	var handler http.Handler
 	handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {})
-	handler = WithLogging(WithLogging(handler, DefaultStacktracePred), DefaultStacktracePred)
+	handler = withLogging(withLogging(handler, DefaultStacktracePred, shouldLogRequest), DefaultStacktracePred, shouldLogRequest)
 
 	func() {
 		defer func() {
@@ -79,29 +81,40 @@ func TestWithLogging(t *testing.T) {
 }
 
 func TestLogOf(t *testing.T) {
-	logOfTests := []bool{true, false}
-	for _, makeLogger := range logOfTests {
-		req, err := http.NewRequest("GET", "http://example.com", nil)
-		if err != nil {
-			t.Errorf("Unexpected error: %v", err)
-		}
-		var want string
-		var handler http.Handler
-		handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
-			got := reflect.TypeOf(LogOf(r, w)).String()
-			if want != got {
-				t.Errorf("Expected %v, got %v", want, got)
-			}
-		})
-		if makeLogger {
-			handler = WithLogging(handler, DefaultStacktracePred)
-			want = "*httplog.respLogger"
-		} else {
-			want = "*httplog.passthroughLogger"
-		}
+	tests := []struct {
+		name             string
+		shouldLogRequest bool
+		want             string
+	}{
+		{
+			name:             "request is being logged",
+			shouldLogRequest: true,
+			want:             "*httplog.respLogger",
+		},
+		{
+			name:             "request is not being logged",
+			shouldLogRequest: false,
+			want:             "*httplog.passthroughLogger",
+		},
+	}
 
-		w := httptest.NewRecorder()
-		handler.ServeHTTP(w, req)
+	for _, test := range tests {
+		t.Run(test.name, func(t *testing.T) {
+			req, err := http.NewRequest("GET", "http://example.com", nil)
+			if err != nil {
+				t.Errorf("Unexpected error: %v", err)
+			}
+			var handler http.Handler
+			handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+				got := reflect.TypeOf(LogOf(r, w)).String()
+				if test.want != got {
+					t.Errorf("Expected %v, got %v", test.want, got)
+				}
+			})
+			handler = withLogging(handler, DefaultStacktracePred, func() bool { return test.shouldLogRequest })
+			w := httptest.NewRecorder()
+			handler.ServeHTTP(w, req)
+		})
 	}
 }
 
@@ -136,7 +149,7 @@ func TestLoggedStatus(t *testing.T) {
 	}
 
 	var tw http.ResponseWriter = new(responsewriter.FakeResponseWriter)
-	logger, _ := newLogged(req, tw)
+	logger := newLogged(req, tw)
 	logger.Write(nil)
 
 	if logger.status != http.StatusOK {
@@ -144,7 +157,7 @@ func TestLoggedStatus(t *testing.T) {
 	}
 
 	tw = new(responsewriter.FakeResponseWriter)
-	logger, _ = newLogged(req, tw)
+	logger = newLogged(req, tw)
 	logger.WriteHeader(http.StatusForbidden)
 	logger.Write(nil)
 
@@ -154,46 +167,58 @@ func TestLoggedStatus(t *testing.T) {
 }
 
 func TestRespLoggerWithDecoratedResponseWriter(t *testing.T) {
-	req, err := http.NewRequest("GET", "http://example.com", nil)
-	if err != nil {
-		t.Errorf("unexpected error: %v", err)
+	tests := []struct {
+		name       string
+		r          func() http.ResponseWriter
+		hijackable bool
+	}{
+		{
+			name: "http2",
+			r: func() http.ResponseWriter {
+				return &responsewriter.FakeResponseWriterFlusherCloseNotifier{}
+			},
+			hijackable: false,
+		},
+		{
+			name: "http/1.x",
+			r: func() http.ResponseWriter {
+				return &responsewriter.FakeResponseWriterFlusherCloseNotifierHijacker{}
+			},
+			hijackable: true,
+		},
 	}
 
-	var tw http.ResponseWriter = new(responsewriter.FakeResponseWriter)
-	_, rwGot := newLogged(req, tw)
+	for _, test := range tests {
+		t.Run(test.name, func(t *testing.T) {
+			req, err := http.NewRequest("GET", "http://example.com", nil)
+			if err != nil {
+				t.Errorf("Unexpected error: %v", err)
+			}
 
-	switch v := rwGot.(type) {
-	case *respLogger:
-	default:
-		t.Errorf("Expected respLogger, got %v", reflect.TypeOf(v))
-	}
+			var handler http.Handler
+			handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {
+				switch v := w.(type) {
+				case *respLogger:
+					t.Errorf("Did not expect %v", reflect.TypeOf(v))
+					return
+				default:
+				}
 
-	tw = new(responsewriter.FakeResponseWriterFlusherCloseNotifier)
-	_, rwGot = newLogged(req, tw)
+				//lint:file-ignore SA1019 Keep supporting deprecated http.CloseNotifier
+				if _, ok := w.(http.CloseNotifier); !ok {
+					t.Errorf("Expected the ResponseWriter object to implement http.CloseNotifier")
+				}
+				if _, ok := w.(http.Flusher); !ok {
+					t.Errorf("Expected the ResponseWriter object to implement http.Flusher")
+				}
+				if _, ok := w.(http.Hijacker); test.hijackable != ok {
+					t.Errorf("http.Hijacker does not match, want: %t, got: %t", test.hijackable, ok)
+				}
+			})
 
-	//lint:file-ignore SA1019 Keep supporting deprecated http.CloseNotifier
-	if _, ok := rwGot.(http.CloseNotifier); !ok {
-		t.Errorf("Expected http.ResponseWriter to implement http.CloseNotifier")
-	}
-	if _, ok := rwGot.(http.Flusher); !ok {
-		t.Errorf("Expected the wrapper to implement http.Flusher")
-	}
-	if _, ok := rwGot.(http.Hijacker); ok {
-		t.Errorf("Expected http.ResponseWriter not to implement http.Hijacker")
-	}
-
-	tw = new(responsewriter.FakeResponseWriterFlusherCloseNotifierHijacker)
-	_, rwGot = newLogged(req, tw)
-
-	//lint:file-ignore SA1019 Keep supporting deprecated http.CloseNotifier
-	if _, ok := rwGot.(http.CloseNotifier); !ok {
-		t.Errorf("Expected http.ResponseWriter to implement http.CloseNotifier")
-	}
-	if _, ok := rwGot.(http.Flusher); !ok {
-		t.Errorf("Expected the wrapper to implement http.Flusher")
-	}
-	if _, ok := rwGot.(http.Hijacker); !ok {
-		t.Errorf("Expected http.ResponseWriter to implement http.Hijacker")
+			handler = withLogging(handler, DefaultStacktracePred, func() bool { return true })
+			handler.ServeHTTP(test.r(), req)
+		})
 	}
 }