Copy request in timeout handler

[Argh4k]

What type of PR is this?

/kind bug

What this PR does / why we need it:

This PR fixes race condition:

• apiserver request time outs
• we run deferred function from withLogging filter where respLogger hold pointer to original Request

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

  Lines 124 to 127 in 88f9728

  	rl := newLoggedWithStartTime(req, w, startTime)
  	rl.StacktraceWhen(stackTracePred)
  	req = req.WithContext(context.WithValue(ctx, respLoggerContextKey, rl))
  	defer rl.Log()

• this function calls CleanVerb that can access header map

  kubernetes/staging/src/k8s.io/apiserver/pkg/endpoints/metrics/metrics.go

  Line 572 in 88f9728

  if verb == "PATCH" && request.Header.Get("Content-Type") == string(types.ApplyPatchType) && utilfeature.DefaultFeatureGate.Enabled(features.ServerSideApply) {

• meanwhile other filters launched in new goroutine by timeout handler can modify this header. For example authentication filter does this.

  kubernetes/staging/src/k8s.io/apiserver/pkg/endpoints/filters/authentication.go

  Line 77 in 88f9728

  req.Header.Del("Authorization")

We can also get to the CleanVerb function by postTimeoutFn() called by timeout handler in case of timeout:

kubernetes/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go

Line 141 in 88f9728

defer postTimeoutFn()

This function looks like this:

kubernetes/staging/src/k8s.io/apiserver/pkg/server/filters/timeout.go

Lines 55 to 57 in 88f9728

	postTimeoutFn := func() {
	metrics.RecordRequestTermination(req, requestInfo, metrics.APIServerComponent, http.StatusGatewayTimeout)
	}

And calls cleanVerb (that internally calls CleanVerb):

kubernetes/staging/src/k8s.io/apiserver/pkg/endpoints/metrics/metrics.go

Line 420 in 88f9728

reportedVerb := cleanVerb(CanonicalVerb(strings.ToUpper(req.Method), scope), getVerbIfWatch(req), req)

Those are spots that I've found, but there might be even more of those.

Test cases added in this pull request when run without fix and with -race flag, crash with race condition detected. In case of TestTimeoutWithLogging passing --args -v=3 is also necessary to force logging.

Which issue(s) this PR fixes:

Fixes #

Fix a race in timeout handler that could lead to kube-apiserver crashes

[k8s-ci-robot]

Welcome @Argh4k!

It looks like this is your first PR to kubernetes/kubernetes 🎉. Please refer to our pull request process documentation to help your PR have a smooth ride to approval.

You will be prompted by a bot to use commands during the review process. Do not be afraid to follow the prompts! It is okay to experiment. Here is the bot commands documentation.

You can also check if kubernetes/kubernetes has its own contribution guidelines.

You may want to refer to our testing guide if you run into trouble with your tests not passing.

If you are having difficulty getting your pull request seen, please follow the recommended escalation practices. Also, for tips and tricks in the contribution process you may want to read the Kubernetes contributor cheat sheet. We want to make sure your contribution gets all the attention it needs!

Thank you, and welcome to Kubernetes. 😃

[k8s-ci-robot]

Hi @Argh4k. Thanks for your PR.

I'm waiting for a kubernetes member to verify that this patch is reasonable to test. If it is, they should reply with /ok-to-test on its own line. Until that is done, I will not automatically test new commits in this PR, but the usual testing commands by org members will still work. Regular contributors should join the org to skip this step.

Once the patch is verified, the new status will be reflected by the ok-to-test label.

I understand the commands that are listed here.

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/test-infra repository.

[Argh4k]

/assign @wojtek-t
/assign @liggitt
/assign @mborsz

[aojea]

/ok-to-test

[mborsz]

/cc @wojtek-t @liggitt
/retest

Please fix gofmt

[mborsz]

Are request headers the only problematic case?

If so, maybe we can shallow copy request and deep clone headers only to save few bytes?

[mborsz]

I think for now we believe only headers are problematic, but I can imagine (e.g. in future) some handler modifying any other field in http.Request.

I think it's reasonable to clone entire object, but I would change the comment to say something like "to avoid races when accessing/modifying http.Request (e.g. request headers)".

[Argh4k]

Yes, I would rather make deep copy of all request metadata. This way we ensure that further changes to filter that precede timeout handler probably won't cause race condition. I think there is very low probability that any filter will touch body of the request, which is not deep copied here.

[mborsz]

One nit.

Otherwise LGTM.

The potential issue with this solution is that it blocks propagation of request's headers changes to filters that are above WithTimeoutForNonLongRunningRequests. It was already possible that the request timed out before the changes were made (which generated this race), but now it happens for all requests.

I tried to skim the code around and I wasn't able to find any practical problem with this now. This may lead to some potential issues in future if e.g. someone implements a filter A that changes request and expect this change to be propagated to another filter B (with WithTimeoutForNonLongRunningRequests in the middle), but:

• It's not clear to me if we will ever need to implement this kind of filters
• It will be easy to catch during testing (no request will have that request change propagated)
• Even without this change, it was possible that we never reach filter B (e.g. due to timeout), so any implementation of filter A that expected request change of B was simply invalid in general case. Now we block such changes which makes this more obvious.

So for me it looks good, but I would like to hear opinion of more senior folks about this change: @wojtek-t @liggitt

[aojea]

I tried to skim the code around and I wasn't able to find any practical problem with this now. This may lead to some potential issues in future if e.g. someone implements a filter A that changes request and expect this change to be propagated to another filter B (with WithTimeoutForNonLongRunningRequests in the middle), but:

what if instead of passing the clone to the handlers we use the clone for the timeout handler instead, and we pass the original request?

[fedebongio]

/assign @tkashem
/triage accepted

[mborsz]

is there a better way to implement timeouts on requests without using goroutines?

The most common way in golang I have seen in other libraries is to simply use a single goroutine and use context cancellation for timeout. There is some discussion around that in #105884 but overall it looks like e.g. Write operation doesn't use context which makes it hard to switch to this approach now: #105884 (comment)

Long term it looks like a way to go, but we will need to either to have a golang's support for Write with context support or workaround it somehow.

[aojea]

Long term it looks like a way to go, but we will need to either to have a golang's support for Write with context support or workaround it somehow.

It seems that all options were explored and this is the least bad option :)
LGTM , can we add a reference to this issue on the comment? there is some good context here for the future
Defer to wojtek and Jordan

[wojtek-t]

Added a release-note - we should cherrypick it once this is merged.

/lgtm
/aprove

[wojtek-t]

/approve

[Argh4k]

/retest

[wojtek-t]

/lgtm
/approve

[k8s-ci-robot]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: Argh4k, wojtek-t

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

The pull request process is described here

Needs approval from an approver in each of these files:

• staging/src/k8s.io/apiserver/OWNERS [wojtek-t]

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

[k8s-triage-robot]

The Kubernetes project has merge-blocking tests that are currently too flaky to consistently pass.

This bot retests PRs for certain kubernetes repos according to the following rules:

• The PR does have any do-not-merge/* labels
• The PR does not have the needs-ok-to-test label
• The PR is mergeable (does not have a needs-rebase label)
• The PR is approved (has cncf-cla: yes, lgtm, approved labels)
• The PR is failing tests required for merge

You can:

• Review the full test history for this PR
• Prevent this bot from retesting with /lgtm cancel or /hold
• Help make our tests less flaky by following our Flaky Tests Guide

/retest