Skip to content
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.

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

Fix httplog not logging watch duration #125626

Open
wants to merge 1 commit into
base: master
Choose a base branch
from

Conversation

linxiulei
Copy link
Contributor

What type of PR is this?

/kind bug

What this PR does / why we need it:

Which issue(s) this PR fixes:

Fixes #125614

Special notes for your reviewer:

Does this PR introduce a user-facing change?

NONE

@k8s-ci-robot
Copy link
Contributor

Skipping CI for Draft Pull Request.
If you want CI signal for your change, please convert it to an actual PR.
You can still manually trigger a test run with /test all

@k8s-ci-robot k8s-ci-robot added release-note-none Denotes a PR that doesn't merit a release note. do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. kind/bug Categorizes issue or PR as related to a bug. cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. needs-priority Indicates a PR lacks a `priority/foo` label and requires one. labels Jun 21, 2024
@linxiulei linxiulei changed the title Fix routine log Fix httplog not logging watch duration Jun 21, 2024
@k8s-ci-robot k8s-ci-robot added area/apiserver sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. and removed do-not-merge/needs-sig Indicates an issue or PR lacks a `sig/foo` label and requires one. labels Jun 21, 2024
@linxiulei linxiulei marked this pull request as ready for review June 21, 2024 10:08
@k8s-ci-robot k8s-ci-robot removed the do-not-merge/work-in-progress Indicates that a PR should not merge because it is a work in progress. label Jun 21, 2024
@k8s-ci-robot k8s-ci-robot added area/kubelet sig/cloud-provider Categorizes an issue or PR as relevant to SIG Cloud Provider. sig/node Categorizes an issue or PR as relevant to SIG Node. sig/scheduling Categorizes an issue or PR as relevant to SIG Scheduling. labels Jun 21, 2024
@linxiulei linxiulei force-pushed the fix_routine_log branch 2 times, most recently from c20be53 to 5e6d4f5 Compare June 21, 2024 11:37
@jpbetz
Copy link
Contributor

jpbetz commented Jun 25, 2024

/triage accepted
/assign @siyuanfoundation

@k8s-ci-robot k8s-ci-robot added the triage/accepted Indicates an issue or PR is ready to be actively worked on. label Jun 25, 2024
@k8s-ci-robot k8s-ci-robot removed the needs-triage Indicates an issue or PR lacks a `triage/foo` label and requires one. label Jun 25, 2024
@@ -283,7 +283,7 @@ func buildHandlerChain(handler http.Handler, authn authenticator.Request, authz
handler = genericapifilters.WithAuthentication(handler, authn, failedHandler, nil, nil)
handler = genericapifilters.WithRequestInfo(handler, requestInfoResolver)
handler = genericapifilters.WithCacheControl(handler)
handler = genericfilters.WithHTTPLogging(handler)
handler = genericfilters.WithHTTPLogging(handler, func(_ context.Context, f func()) { f() })
Copy link
Member

Choose a reason for hiding this comment

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

This is very hard to think about what's happening.

Why can't we just do the following:

  • change withLogging to do more-or-less exactly what's ListResource is doing [check if TaskFrom is non-nil and if so append to it]
  • not change anything else...

Copy link
Contributor Author

Choose a reason for hiding this comment

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

change withLogging to do more-or-less exactly what's ListResource is doing [check if TaskFrom is non-nil and if so append to it]

Actually my first attempt was like that. But it caused cycle import if we call TaskFrom in httplog. Let me try if I can work this around.

Copy link
Contributor Author

Choose a reason for hiding this comment

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

Not sure if it's an overkill to move routine filter in a separate directory to tackle the cycle import issue. But it should be what you suggested.

@wojtek-t wojtek-t self-assigned this Jun 26, 2024
@k8s-ci-robot k8s-ci-robot added the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Jun 26, 2024
@k8s-ci-robot k8s-ci-robot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. labels Jun 26, 2024
@k8s-ci-robot
Copy link
Contributor

[APPROVALNOTIFIER] This PR is NOT APPROVED

This pull-request has been approved by: linxiulei
Once this PR has been reviewed and has the lgtm label, please ask for approval from wojtek-t. For more information see the Kubernetes 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:

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

@linxiulei
Copy link
Contributor Author

/retest


w = responsewriter.WrapForHTTP1Or2(rl)
handler.ServeHTTP(w, req)

if routine.AppendTask(ctx, &routine.Task{Func: rl.Log}) {
logInRoutine = true
Copy link
Contributor

Choose a reason for hiding this comment

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

can you explain a bit what would happen when logInRoutine = true?

Copy link
Contributor Author

Choose a reason for hiding this comment

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

We added a feature to run the watch serving in a separate goroutine to free stack memory allocated by Golang runtime (#120902). This code determines if it is the case and run the rl.log() at the end of the aforementioned goroutine.

I also added comment to explain that a bit. Thanks!

@linxiulei
Copy link
Contributor Author

/retest

@@ -125,10 +126,21 @@ func withLogging(handler http.Handler, stackTracePred StacktracePred, shouldLogR
rl := newLoggedWithStartTime(req, w, startTime)
rl.StacktraceWhen(stackTracePred)
req = req.WithContext(context.WithValue(ctx, respLoggerContextKey, rl))
defer rl.Log()
logInRoutine := false
Copy link
Member

Choose a reason for hiding this comment

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

nit: I would switch to sth like;

var logFunc func()
logFunc = rl.Log
defer func() {
  if logFunc != nil {
    logFunc()
  }
}()


w = responsewriter.WrapForHTTP1Or2(rl)
handler.ServeHTTP(w, req)

// log after the task is executed in the separate routine
// there is a task created in handler.ServeHTTP()
Copy link
Member

Choose a reason for hiding this comment

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

Let's put more context into this comment - I don't think it clarifies enough for people not familiar with it.

// We need to ensure that the request is logged after it is processed.
// In case the request is executed in a separate goroutine (created via
// WithRoutine handler in the handler chain), we want the logging to
// happen in that goroutine too, so we append it to the task.


// log after the task is executed in the separate routine
// there is a task created in handler.ServeHTTP()
if routine.AppendTask(ctx, &routine.Task{Func: rl.Log}) {
Copy link
Member

Choose a reason for hiding this comment

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

Hmm - when calling AppendTask, the main function is not yet set, right?
So won't it be overwritten later anyway?

I would like to see test output to see we actually fixed the problem.

@@ -35,6 +35,20 @@ func WithTask(parent context.Context, t *Task) context.Context {
return request.WithValue(parent, taskKey, t)
}

// AppendTask appends a task executed after completion of existing task.
// It is a no-op if there is no existing task.
func AppendTask(ctx context.Context, t *Task) bool {
Copy link
Member

Choose a reason for hiding this comment

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

This deserves some unit test.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
area/apiserver area/kubelet cncf-cla: yes Indicates the PR's author has signed the CNCF CLA. kind/bug Categorizes issue or PR as related to a bug. needs-priority Indicates a PR lacks a `priority/foo` label and requires one. release-note-none Denotes a PR that doesn't merit a release note. sig/api-machinery Categorizes an issue or PR as relevant to SIG API Machinery. sig/cloud-provider Categorizes an issue or PR as relevant to SIG Cloud Provider. sig/node Categorizes an issue or PR as relevant to SIG Node. sig/scheduling Categorizes an issue or PR as relevant to SIG Scheduling. size/L Denotes a PR that changes 100-499 lines, ignoring generated files. triage/accepted Indicates an issue or PR is ready to be actively worked on.
Projects
Status: Needs Reviewer
Development

Successfully merging this pull request may close these issues.

kube-apiserver logs watch requests before they end in 1.30
5 participants