Skip to content

OCPBUGS-43994: UPSTREAM: <carry>: kube-apiserver: Only log each HTTP request once #2451

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Open
wants to merge 2 commits into
base: master
Choose a base branch
from
Open

OCPBUGS-43994: UPSTREAM: <carry>: kube-apiserver: Only log each HTTP request once #2451

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
2 commits
Select commit Hold shift + click to select a range
c068b2f
UPSTREAM: <carry>: kube-apiserver: Only log each HTTP request once
tchap Sep 8, 2025
3981cdc
Use shouldLogRequest predicate in Log as well
tchap Sep 29, 2025
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
53 changes: 30 additions & 23 deletions staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -67,15 +67,15 @@ type respLogger struct {
addedInfo strings.Builder
addedKeyValuePairs []interface{}
startTime time.Time
isTerminating bool

captureErrorOutput bool

req *http.Request
userAgent string
w http.ResponseWriter

logStacktracePred StacktracePred
logStacktracePred StacktracePred
shouldLogRequestPred func(ctx context.Context) bool
}

var _ http.ResponseWriter = &respLogger{}
Expand All @@ -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 {
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

wait, why so many changes in this file ? should we simply remove the code we discussed previously ?

isTerminating := false
if isTerminatingFn != nil {
isTerminating = isTerminatingFn()
}
logger := klog.FromContext(ctx)
return logger.V(withLoggingLevel).Enabled() || (isTerminating && logger.V(1).Enabled())
})
Copy link
Author

@tchap tchap Sep 23, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@p0lyn0mial I ended up refactoring the logic and private interfaces a bit, but the overall approach is not exactly bullet-proof.

There is now a single predicate function that merges previous shouldLogRequest and isTerminatingFn. This means withLogging is now much more clear and simple.

I added tests and use contextual logging internally that is handy for testing.

The issue really is that when you check respLogger.Log, it contains anyway klog.V(withLoggingLevel), but isTerminating flag is not passed there, so I am afraid the current implementation contains a bug anyway and isTerminating is pretty much ignored. So what I did was to check all the conditions initially here and remove .V call from .Log. This makes all the tests pass just fine.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Another approach would be to keep the isTerminating field in the logger and repeat the terminating check in Log as well...

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I need to check but if rl.isTerminating is/was unused then maybe we can drop the entire patch. Assuming our issue was:

if klog.V(3).Enabled() || (rl.isTerminating && klog.V(1).Enabled()) {...}

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This isTerminatingFunc is actually set up and passed to this machinery in https://github.com/openshift/kubernetes/blob/master/staging/src/k8s.io/apiserver/pkg/server/config.go#L1155

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yeah, I think that the patch was introduced in b052cde

But given that shouldLogRequest is always true when the loglevel is 3 (hardcoded value) and the fact that rl.isTerminating is unused beyond httplog what is the point of the original patch/pr ?

If we were to drop it, I think there would be no change in the behavior. am I right?

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Otherwise we can just drop the original patch, which would mean no logging when terminating. Which is not happening right now anyway, but the question is whether we want to drop the intent.

I think the patch is very old. I think that the purpose was to find requests during server termination - not a feature users were using.

I think that we could simply drop the patch and test manually that when loglevel is 3 there are no duplicates during server shutdown.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I did push one last commit, but I guess the plan is to close this and also remove the original carry this is fixing then?

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think so, given that the behaviour will not change after removing the PR, right?. Unless there are some other parts that depend on the original PR.

Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I don't think anything depends on it, I've reverted the commit just to test it.

Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

could you also test manually that httplog logs requests when appropriate loglevel is set and there are no duplicates ?

you can also open a new PR so that we get a signal from the CI.

}

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!")
}
Expand All @@ -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()
Copy link

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

so, previously, the request was first logged here

}
}()

if klog.V(3).Enabled() || (rl.isTerminating && klog.V(1).Enabled()) {
defer rl.Log()
}
w = responsewriter.WrapForHTTP1Or2(rl)
handler.ServeHTTP(w, req)

Expand All @@ -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
}
})
Expand Down Expand Up @@ -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
}

Expand Down Expand Up @@ -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) {
Copy link
Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

There is a change of interface, but it doesn't seem to be really used publicly as this is an unexported object.

latency := time.Since(rl.startTime)
auditID := audit.GetAuditIDTruncated(rl.req.Context())
verb := metrics.NormalizedVerb(rl.req)
Expand Down Expand Up @@ -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.
Expand Down
83 changes: 79 additions & 4 deletions staging/src/k8s.io/apiserver/pkg/server/httplog/httplog_test.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down Expand Up @@ -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() {
Expand All @@ -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
Expand Down Expand Up @@ -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)
})
Expand Down Expand Up @@ -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)
})
}
Expand Down