diff --git a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go index 299d543b1ea34..70e71c4b283f2 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go +++ b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go @@ -67,7 +67,6 @@ type respLogger struct { addedInfo strings.Builder addedKeyValuePairs []interface{} startTime time.Time - isTerminating bool captureErrorOutput bool @@ -75,7 +74,8 @@ type respLogger struct { userAgent string w http.ResponseWriter - logStacktracePred StacktracePred + logStacktracePred StacktracePred + shouldLogRequestPred func(ctx context.Context) bool } var _ http.ResponseWriter = &respLogger{} @@ -102,19 +102,24 @@ const withLoggingLevel = 3 // WithLogging wraps the handler with logging. func WithLogging(handler http.Handler, pred StacktracePred, isTerminatingFn func() bool) http.Handler { - return withLogging(handler, pred, func() bool { - return klog.V(withLoggingLevel).Enabled() - }, isTerminatingFn) + return withLogging(handler, pred, func(ctx context.Context) bool { + isTerminating := false + if isTerminatingFn != nil { + isTerminating = isTerminatingFn() + } + logger := klog.FromContext(ctx) + return logger.V(withLoggingLevel).Enabled() || (isTerminating && logger.V(1).Enabled()) + }) } -func withLogging(handler http.Handler, stackTracePred StacktracePred, shouldLogRequest ShouldLogRequestPred, isTerminatingFn func() bool) http.Handler { +func withLogging(handler http.Handler, stackTracePred StacktracePred, shouldLogRequest func(context.Context) bool) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { - if !shouldLogRequest() { + ctx := req.Context() + if !shouldLogRequest(ctx) { handler.ServeHTTP(w, req) return } - ctx := req.Context() if old := respLoggerFromRequest(req); old != nil { panic("multiple WithLogging calls!") } @@ -123,24 +128,19 @@ func withLogging(handler http.Handler, stackTracePred StacktracePred, shouldLogR startTime = receivedTimestamp } - isTerminating := false - if isTerminatingFn != nil { - isTerminating = isTerminatingFn() - } - rl := newLoggedWithStartTime(req, w, startTime).StacktraceWhen(stackTracePred).IsTerminating(isTerminating) + rl := newLoggedWithStartTime(req, w, startTime).StacktraceWhen(stackTracePred).ShouldLogRequest(shouldLogRequest) req = req.WithContext(context.WithValue(ctx, respLoggerContextKey, rl)) var logFunc func() - logFunc = rl.Log + logFunc = func() { + rl.Log(ctx) + } defer func() { if logFunc != nil { logFunc() } }() - if klog.V(3).Enabled() || (rl.isTerminating && klog.V(1).Enabled()) { - defer rl.Log() - } w = responsewriter.WrapForHTTP1Or2(rl) handler.ServeHTTP(w, req) @@ -149,7 +149,7 @@ func withLogging(handler http.Handler, stackTracePred StacktracePred, shouldLogR // WithRoutine handler in the handler chain (i.e. above handler.ServeHTTP() // would return request is completely responsed), we want the logging to // happen in that goroutine too, so we append it to the task. - if routine.AppendTask(ctx, &routine.Task{Func: rl.Log}) { + if routine.AppendTask(ctx, &routine.Task{Func: logFunc}) { logFunc = nil } }) @@ -211,9 +211,9 @@ func (rl *respLogger) StacktraceWhen(pred StacktracePred) *respLogger { return rl } -// IsTerminating informs the logger that the server is terminating. -func (rl *respLogger) IsTerminating(is bool) *respLogger { - rl.isTerminating = is +// ShouldLogRequest can be used to set a custom logging condition for Log. +func (rl *respLogger) ShouldLogRequest(shouldLogRequestPred func(context.Context) bool) *respLogger { + rl.shouldLogRequestPred = shouldLogRequestPred return rl } @@ -268,7 +268,7 @@ func SetStacktracePredicate(ctx context.Context, pred StacktracePred) { } // Log is intended to be called once at the end of your request handler, via defer -func (rl *respLogger) Log() { +func (rl *respLogger) Log(ctx context.Context) { latency := time.Since(rl.startTime) auditID := audit.GetAuditIDTruncated(rl.req.Context()) verb := metrics.NormalizedVerb(rl.req) @@ -304,7 +304,14 @@ func (rl *respLogger) Log() { } } - klog.V(withLoggingLevel).InfoSDepth(1, "HTTP", keysAndValues...) + logger := klog.FromContext(ctx) + shouldLogRequest := logger.V(withLoggingLevel).Enabled() + if rl.shouldLogRequestPred != nil { + shouldLogRequest = rl.shouldLogRequestPred(ctx) + } + if shouldLogRequest { + logger.WithCallDepth(1).Info("HTTP", keysAndValues...) + } } // Header implements http.ResponseWriter. diff --git a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog_test.go b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog_test.go index 61b83c8c975eb..150e45063e261 100644 --- a/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog_test.go +++ b/staging/src/k8s.io/apiserver/pkg/server/httplog/httplog_test.go @@ -17,12 +17,15 @@ limitations under the License. package httplog import ( + "context" "net/http" "net/http/httptest" "reflect" "testing" "k8s.io/apiserver/pkg/endpoints/responsewriter" + "k8s.io/klog/v2" + "k8s.io/klog/v2/ktesting" ) func TestDefaultStacktracePred(t *testing.T) { @@ -64,10 +67,10 @@ func TestWithLogging(t *testing.T) { t.Errorf("Unexpected error: %v", err) } - shouldLogRequest := func() bool { return true } + shouldLogRequest := func(_ context.Context) bool { return true } var handler http.Handler handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {}) - handler = withLogging(withLogging(handler, DefaultStacktracePred, shouldLogRequest, nil), DefaultStacktracePred, shouldLogRequest, nil) + handler = withLogging(withLogging(handler, DefaultStacktracePred, shouldLogRequest), DefaultStacktracePred, shouldLogRequest) func() { defer func() { @@ -80,6 +83,78 @@ func TestWithLogging(t *testing.T) { }() } +func TestWithLogging_PredicateFunctions(t *testing.T) { + tests := []struct { + name string + loggerVerbosity int + isTerminating bool + expectedLogCount int + }{ + { + name: "should not log request on verbosity 1", + loggerVerbosity: 1, + expectedLogCount: 0, + }, + { + name: "should log request on verbosity 1 when terminating", + loggerVerbosity: 1, + isTerminating: true, + expectedLogCount: 1, + }, + { + name: "should not log request on verbosity 2", + loggerVerbosity: 2, + expectedLogCount: 0, + }, + { + name: "should log request on verbosity 2 when terminating", + loggerVerbosity: 2, + isTerminating: true, + expectedLogCount: 1, + }, + { + name: "should log request on verbosity 3", + loggerVerbosity: 3, + expectedLogCount: 1, + }, + } + + for _, test := range tests { + t.Run(test.name, func(t *testing.T) { + var handler http.Handler + handler = http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) {}) + handler = WithLogging(handler, DefaultStacktracePred, func() bool { + return test.isTerminating + }) + + var b ktesting.BufferTL + logger := ktesting.NewLogger(&b, ktesting.NewConfig( + ktesting.BufferLogs(true), + ktesting.Verbosity(test.loggerVerbosity), + )) + + ctx := klog.NewContext(context.Background(), logger) + r, err := http.NewRequestWithContext(ctx, "GET", "http://example.com", nil) + if err != nil { + t.Fatalf("Unexpected error: %v", err) + } + + w := httptest.NewRecorder() + handler.ServeHTTP(w, r) + + testingLogger, ok := logger.GetSink().(ktesting.Underlier) + if !ok { + t.Fatal("Failed to cast logger sink to ktesting.Underlier") + } + + data := testingLogger.GetBuffer().Data() + if len(data) != test.expectedLogCount { + t.Errorf("Log entry count expected=%d, got=%d", test.expectedLogCount, len(data)) + } + }) + } +} + func TestLogOf(t *testing.T) { tests := []struct { name string @@ -111,7 +186,7 @@ func TestLogOf(t *testing.T) { t.Errorf("Expected %v, got %v", test.want, got) } }) - handler = withLogging(handler, DefaultStacktracePred, func() bool { return test.shouldLogRequest }, nil) + handler = withLogging(handler, DefaultStacktracePred, func(_ context.Context) bool { return test.shouldLogRequest }) w := httptest.NewRecorder() handler.ServeHTTP(w, req) }) @@ -216,7 +291,7 @@ func TestRespLoggerWithDecoratedResponseWriter(t *testing.T) { } }) - handler = withLogging(handler, DefaultStacktracePred, func() bool { return true }, nil) + handler = withLogging(handler, DefaultStacktracePred, func(_ context.Context) bool { return true }) handler.ServeHTTP(test.r(), req) }) }