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

tchap · 2025-09-08T12:05:15Z

What type of PR is this?

/kind bug

What this PR does / why we need it:

kube-apiserver now logs each HTTP request twice since there is an extra logging call when finishing the request. This duplicity is now removed.

Which issue(s) this PR fixes:

N/A

Special notes for your reviewer:

N/A

Does this PR introduce a user-facing change?

NONE

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

N/A

openshift-ci-robot · 2025-09-08T12:05:22Z

@tchap: This pull request references Jira Issue OCPBUGS-43994, which is invalid:

expected the bug to target the "4.21.0" version, but no target version was set

Comment /jira refresh to re-evaluate validity if changes to the Jira bug are made, or edit the title of this pull request to link to a different bug.

The bug has been updated to refer to the pull request using the external bug tracker.

In response to this:

What type of PR is this?

/kind bug

What this PR does / why we need it:

kube-apiserver now logs each HTTP request twice since there is an extra logging call when finishing the request. This duplicity is now removed.

Which issue(s) this PR fixes:

N/A

Special notes for your reviewer:

N/A

Does this PR introduce a user-facing change?
NONE
Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

N/A

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the openshift-eng/jira-lifecycle-plugin repository.

openshift-ci-robot · 2025-09-08T12:05:26Z

@tchap: the contents of this pull request could not be automatically validated.

The following commits could not be validated and must be approved by a top-level approver:

10c8973|UPSTREAM: : kube-apiserver: Only log each HTTP request once: does not specify an upstream backport in the commit message

Comment /validate-backports to re-evaluate validity of the upstream PRs, for example when they are merged upstream.

tchap · 2025-09-08T12:06:04Z

/jira refresh

openshift-ci-robot · 2025-09-08T12:06:13Z

@tchap: This pull request references Jira Issue OCPBUGS-43994, which is valid. The bug has been moved to the POST state.

3 validation(s) were run on this bug

bug is open, matching expected state (open)
bug target version (4.21.0) matches configured target version for branch (4.21.0)
bug is in the state New, which is one of the valid states (NEW, ASSIGNED, POST)

Requesting review from QA contact:
/cc @wangke19

In response to this:

/jira refresh

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the openshift-eng/jira-lifecycle-plugin repository.

openshift-ci · 2025-09-08T12:08:07Z

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: tchap
Once this PR has been reviewed and has the lgtm label, please assign jerpeter1 for approval. For more information see the Code Review Process.

The full list of commands accepted by this bot can be found here.

Needs approval from an approver in each of these files:

DOWNSTREAM_OWNERS

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment

tchap · 2025-09-09T08:42:59Z

/retest

tchap · 2025-09-09T15:49:27Z

/retest

tchap · 2025-09-10T13:52:02Z

/retest

tchap · 2025-09-22T14:22:17Z

/retest

p0lyn0mial · 2025-09-22T14:46:38Z

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

+		}
 		defer func() {
 			if logFunc != nil {
 				logFunc()


so, previously, the request was first logged here

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

p0lyn0mial · 2025-09-23T08:42:23Z

@tchap please also find the pr that introduced this change and let's add a description to the commit pointing to the original pr with which the new changes should be squashed during the next rebase.

tchap · 2025-09-23T08:46:44Z

@p0lyn0mial Is this any kind of standardized process documented anywhere, or should I just add a generic comment?

p0lyn0mial · 2025-09-23T08:48:40Z

@p0lyn0mial Is this any kind of standardized process documented anywhere, or should I just add a generic comment?

@bertinatto ^^

bertinatto · 2025-09-23T10:00:19Z

@p0lyn0mial Is this any kind of standardized process documented anywhere, or should I just add a generic comment?

@bertinatto ^^

We don't have a standarized process, but historically we either:

use the same commit title as the original commit that introduced the change;
or we add a (squash) to the commit title plus the original commit in the description (personally, I prefer this one).

That way, the person doing the rebase will easily notice that the carry patch can/should be squashed.

kube-apiserver now logs each HTTP request twice since there is an extra logging call when finishing the request. This duplicity is now removed.

openshift-ci-robot · 2025-09-23T10:48:41Z

@tchap: the contents of this pull request could not be automatically validated.

The following commits could not be validated and must be approved by a top-level approver:

c068b2f|UPSTREAM: : kube-apiserver: Only log each HTTP request once: does not specify an upstream backport in the commit message

Comment /validate-backports to re-evaluate validity of the upstream PRs, for example when they are merged upstream.

p0lyn0mial · 2025-09-23T10:55:21Z

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

-	return withLogging(handler, pred, func() bool {
-		return klog.V(withLoggingLevel).Enabled()
-	}, isTerminatingFn)
+	return withLogging(handler, pred, func(ctx context.Context) bool {


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

tchap · 2025-09-23T10:58:44Z

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

+		}
+		logger := klog.FromContext(ctx)
+		return logger.V(withLoggingLevel).Enabled() || (isTerminating && logger.V(1).Enabled())
+	})


@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.

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

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()) {...}

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

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?

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.

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?

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.

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

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.

tchap · 2025-09-23T11:01:14Z

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


 // 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) {


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

tchap · 2025-09-24T10:14:34Z

/retest

tchap · 2025-09-25T08:29:17Z

/retest

tchap · 2025-09-26T08:12:46Z

/retest

openshift-ci-robot · 2025-09-29T09:56:29Z

@tchap: the contents of this pull request could not be automatically validated.

The following commits could not be validated and must be approved by a top-level approver:

3981cdc|Use shouldLogRequest predicate in Log as well: does not specify an upstream backport in the commit message
c068b2f|UPSTREAM: : kube-apiserver: Only log each HTTP request once: does not specify an upstream backport in the commit message

Comment /validate-backports to re-evaluate validity of the upstream PRs, for example when they are merged upstream.

openshift-ci · 2025-09-29T17:05:25Z

@tchap: The following tests failed, say /retest to rerun all failed tests or /retest-required to rerun all mandatory failed tests:

Test name	Commit	Details	Required	Rerun command
ci/prow/e2e-aws-ovn-runc	`3981cdc`	link	true	`/test e2e-aws-ovn-runc`
ci/prow/e2e-aws-ovn-fips	`3981cdc`	link	true	`/test e2e-aws-ovn-fips`
ci/prow/k8s-e2e-conformance-aws	`3981cdc`	link	true	`/test k8s-e2e-conformance-aws`
ci/prow/e2e-aws-csi	`3981cdc`	link	false	`/test e2e-aws-csi`
ci/prow/verify-commits	`3981cdc`	link	true	`/test verify-commits`
ci/prow/e2e-aws-crun-wasm	`3981cdc`	link	true	`/test e2e-aws-crun-wasm`
ci/prow/k8s-e2e-aws-ovn-serial	`3981cdc`	link	false	`/test k8s-e2e-aws-ovn-serial`
ci/prow/e2e-aws-ovn-cgroupsv2	`3981cdc`	link	true	`/test e2e-aws-ovn-cgroupsv2`
ci/prow/e2e-aws-ovn-techpreview-serial	`3981cdc`	link	false	`/test e2e-aws-ovn-techpreview-serial`
ci/prow/e2e-aws-ovn-techpreview	`3981cdc`	link	false	`/test e2e-aws-ovn-techpreview`
ci/prow/e2e-agnostic-ovn-cmd	`3981cdc`	link	false	`/test e2e-agnostic-ovn-cmd`
ci/prow/okd-scos-e2e-aws-ovn	`3981cdc`	link	false	`/test okd-scos-e2e-aws-ovn`
ci/prow/e2e-aws-ovn-serial	`3981cdc`	link	true	`/test e2e-aws-ovn-serial`
ci/prow/e2e-aws-ovn-crun	`3981cdc`	link	true	`/test e2e-aws-ovn-crun`

Full PR test history. Your PR dashboard.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes-sigs/prow repository. I understand the commands that are listed here.

openshift-ci bot added the kind/bug Categorizes issue or PR as related to a bug. label Sep 8, 2025

openshift-ci-robot added jira/valid-bug Indicates that a referenced Jira bug is valid for the branch this PR is targeting. and removed jira/invalid-bug Indicates that a referenced Jira bug is invalid for the branch this PR is targeting. labels Sep 8, 2025

openshift-ci bot requested review from wangke19, jerpeter1 and p0lyn0mial September 8, 2025 12:06

openshift-ci bot added the vendor-update Touching vendor dir or related files label Sep 8, 2025

p0lyn0mial reviewed Sep 22, 2025

View reviewed changes

p0lyn0mial reviewed Sep 23, 2025

View reviewed changes

staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go Show resolved Hide resolved

staging/src/k8s.io/apiserver/pkg/server/httplog/httplog.go Show resolved Hide resolved

UPSTREAM: <carry>: kube-apiserver: Only log each HTTP request once

c068b2f

kube-apiserver now logs each HTTP request twice since there is an extra logging call when finishing the request. This duplicity is now removed.

tchap force-pushed the httplog-only-once branch from 10c8973 to c068b2f Compare September 23, 2025 10:48

p0lyn0mial reviewed Sep 23, 2025

View reviewed changes

tchap commented Sep 23, 2025

View reviewed changes

Use shouldLogRequest predicate in Log as well

3981cdc

openshift-ci-robot mentioned this pull request Oct 1, 2025

OCPBUGS-43994: UPSTREAM: <carry>: kube-apiserver: wire through isTerminating into handler chain #2477

Merged

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

Are you sure you want to change the base?

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

Uh oh!

Conversation

tchap commented Sep 8, 2025

What type of PR is this?

What this PR does / why we need it:

Which issue(s) this PR fixes:

Special notes for your reviewer:

Does this PR introduce a user-facing change?

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

Uh oh!

openshift-ci-robot commented Sep 8, 2025

What type of PR is this?

What this PR does / why we need it:

Which issue(s) this PR fixes:

Special notes for your reviewer:

Does this PR introduce a user-facing change?

Additional documentation e.g., KEPs (Kubernetes Enhancement Proposals), usage docs, etc.:

Uh oh!

openshift-ci-robot commented Sep 8, 2025

Uh oh!

tchap commented Sep 8, 2025

Uh oh!

openshift-ci-robot commented Sep 8, 2025

Uh oh!

openshift-ci bot commented Sep 8, 2025

Uh oh!

tchap commented Sep 9, 2025

Uh oh!

tchap commented Sep 9, 2025

Uh oh!

tchap commented Sep 10, 2025

Uh oh!

tchap commented Sep 22, 2025

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

p0lyn0mial commented Sep 23, 2025

Uh oh!

tchap commented Sep 23, 2025

Uh oh!

p0lyn0mial commented Sep 23, 2025

Uh oh!

bertinatto commented Sep 23, 2025

Uh oh!

openshift-ci-robot commented Sep 23, 2025

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tchap Sep 23, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

tchap commented Sep 24, 2025

Uh oh!

tchap Sep 23, 2025 •

edited

Loading