diff --git a/pkg/endpoints/filterlatency/filterlatency.go b/pkg/endpoints/filterlatency/filterlatency.go index d42e18233..07880e5e2 100644 --- a/pkg/endpoints/filterlatency/filterlatency.go +++ b/pkg/endpoints/filterlatency/filterlatency.go @@ -24,6 +24,8 @@ import ( utilclock "k8s.io/apimachinery/pkg/util/clock" "k8s.io/apiserver/pkg/endpoints/metrics" apirequest "k8s.io/apiserver/pkg/endpoints/request" + "k8s.io/apiserver/pkg/server/httplog" + "k8s.io/klog/v2" ) type requestFilterRecordKeyType int @@ -31,6 +33,8 @@ type requestFilterRecordKeyType int // requestFilterRecordKey is the context key for a request filter record struct. const requestFilterRecordKey requestFilterRecordKeyType = iota +const minFilterLatencyToLog = 100 * time.Millisecond + type requestFilterRecord struct { name string startedTimestamp time.Time @@ -57,7 +61,11 @@ func TrackStarted(handler http.Handler, name string) http.Handler { // it updates the corresponding metric with the filter latency duration. func TrackCompleted(handler http.Handler) http.Handler { return trackCompleted(handler, utilclock.RealClock{}, func(ctx context.Context, fr *requestFilterRecord, completedAt time.Time) { - metrics.RecordFilterLatency(ctx, fr.name, completedAt.Sub(fr.startedTimestamp)) + latency := completedAt.Sub(fr.startedTimestamp) + metrics.RecordFilterLatency(ctx, fr.name, latency) + if klog.V(3).Enabled() && latency > minFilterLatencyToLog { + httplog.AddInfof(ctx, "%s=%s", fr.name, latency.String()) + } }) } diff --git a/pkg/server/httplog/httplog.go b/pkg/server/httplog/httplog.go index 92b9b1285..78f9fcd3b 100644 --- a/pkg/server/httplog/httplog.go +++ b/pkg/server/httplog/httplog.go @@ -23,6 +23,7 @@ import ( "net" "net/http" "runtime" + "strings" "time" "k8s.io/apiserver/pkg/endpoints/request" @@ -52,7 +53,7 @@ type respLogger struct { statusRecorded bool status int statusStack string - addedInfo string + addedInfo strings.Builder startTime time.Time captureErrorOutput bool @@ -83,7 +84,7 @@ func DefaultStacktracePred(status int) bool { func WithLogging(handler http.Handler, pred StacktracePred) http.Handler { return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) { ctx := req.Context() - if old := respLoggerFromContext(req); old != nil { + if old := respLoggerFromRequest(req); old != nil { panic("multiple WithLogging calls!") } @@ -103,8 +104,7 @@ func WithLogging(handler http.Handler, pred StacktracePred) http.Handler { } // respLoggerFromContext returns the respLogger or nil. -func respLoggerFromContext(req *http.Request) *respLogger { - ctx := req.Context() +func respLoggerFromContext(ctx context.Context) *respLogger { val := ctx.Value(respLoggerContextKey) if rl, ok := val.(*respLogger); ok { return rl @@ -112,6 +112,10 @@ func respLoggerFromContext(req *http.Request) *respLogger { return nil } +func respLoggerFromRequest(req *http.Request) *respLogger { + return respLoggerFromContext(req.Context()) +} + func newLoggedWithStartTime(req *http.Request, w http.ResponseWriter, startTime time.Time) *respLogger { return &respLogger{ startTime: startTime, @@ -130,7 +134,7 @@ func newLogged(req *http.Request, w http.ResponseWriter) *respLogger { // then a passthroughLogger will be created which will log to stdout immediately // when Addf is called. func LogOf(req *http.Request, w http.ResponseWriter) logger { - if rl := respLoggerFromContext(req); rl != nil { + if rl := respLoggerFromRequest(req); rl != nil { return rl } return &passthroughLogger{} @@ -138,7 +142,7 @@ func LogOf(req *http.Request, w http.ResponseWriter) logger { // Unlogged returns the original ResponseWriter, or w if it is not our inserted logger. func Unlogged(req *http.Request, w http.ResponseWriter) http.ResponseWriter { - if rl := respLoggerFromContext(req); rl != nil { + if rl := respLoggerFromRequest(req); rl != nil { return rl.w } return w @@ -166,7 +170,14 @@ func StatusIsNot(statuses ...int) StacktracePred { // Addf adds additional data to be logged with this request. func (rl *respLogger) Addf(format string, data ...interface{}) { - rl.addedInfo += "\n" + fmt.Sprintf(format, data...) + rl.addedInfo.WriteString("\n") + rl.addedInfo.WriteString(fmt.Sprintf(format, data...)) +} + +func AddInfof(ctx context.Context, format string, data ...interface{}) { + if rl := respLoggerFromContext(ctx); rl != nil { + rl.Addf(format, data...) + } } func (rl *respLogger) LogArgs() []interface{} { @@ -196,8 +207,9 @@ func (rl *respLogger) LogArgs() []interface{} { args = append(args, "statusStack", rl.statusStack) } - if len(rl.addedInfo) > 0 { - args = append(args, "addedInfo", rl.addedInfo) + info := rl.addedInfo.String() + if len(info) > 0 { + args = append(args, "addedInfo", info) } return args }