Merge pull request #88936 from jpbetz/http-trace

Add nested tracing and endpoint filter tracing to apiserver

Kubernetes-commit: 240a72b5c0aed6eb96b0c27cf0a82a9124eb57fe

Godeps/Godeps.json

@@ -672,11 +672,11 @@
 		},
 		{
 			"ImportPath": "k8s.io/apimachinery",
-			"Rev": "8e7d6bb9bd6d"
+			"Rev": "cc2fa4f57325"
 		},
 		{
 			"ImportPath": "k8s.io/client-go",
-			"Rev": "505a1f443178"
+			"Rev": "319dbfd0ed29"
 		},
 		{
 			"ImportPath": "k8s.io/component-base",

go.mod

@@ -42,8 +42,8 @@ require (
 	gopkg.in/square/go-jose.v2 v2.2.2
 	gopkg.in/yaml.v2 v2.2.8
 	k8s.io/api v0.0.0-20200713130235-be360156aa6a
-	k8s.io/apimachinery v0.0.0-20200713125709-8e7d6bb9bd6d
+	k8s.io/apimachinery v0.0.0-20200713125710-cc2fa4f57325
-	k8s.io/client-go v0.0.0-20200713130841-505a1f443178
+	k8s.io/client-go v0.0.0-20200713130842-319dbfd0ed29
 	k8s.io/component-base v0.0.0-20200713132432-e98e6e533eb1
 	k8s.io/klog/v2 v2.2.0
 	k8s.io/kube-openapi v0.0.0-20200427153329-656914f816f9
@@ -55,7 +55,7 @@ require (
 
 replace (
 	k8s.io/api => k8s.io/api v0.0.0-20200713130235-be360156aa6a
-	k8s.io/apimachinery => k8s.io/apimachinery v0.0.0-20200713125709-8e7d6bb9bd6d
+	k8s.io/apimachinery => k8s.io/apimachinery v0.0.0-20200713125710-cc2fa4f57325
-	k8s.io/client-go => k8s.io/client-go v0.0.0-20200713130841-505a1f443178
+	k8s.io/client-go => k8s.io/client-go v0.0.0-20200713130842-319dbfd0ed29
 	k8s.io/component-base => k8s.io/component-base v0.0.0-20200713132432-e98e6e533eb1
 )

go.sum

@@ -506,8 +506,8 @@ honnef.co/go/tools v0.0.0-20190418001031-e561f6794a2a/go.mod h1:rf3lG4BRIbNafJWh
 honnef.co/go/tools v0.0.0-20190523083050-ea95bdfd59fc/go.mod h1:rf3lG4BRIbNafJWhAfAdb/ePZxsR/4RtNHQocxwk9r4=
 honnef.co/go/tools v0.0.1-2019.2.3/go.mod h1:a3bituU0lyd329TUQxRnasdCoJDkEUEAqEt0JzvZhAg=
 k8s.io/api v0.0.0-20200713130235-be360156aa6a/go.mod h1:7a4Es5f8qLSh2S2PUf3gP8NdtZFhLKve7TRsSopUcwU=
-k8s.io/apimachinery v0.0.0-20200713125709-8e7d6bb9bd6d/go.mod h1:eHbWZVMaaewmYBAUuRYnAmTTMtDhvpPNZuh8/6Yl7v0=
+k8s.io/apimachinery v0.0.0-20200713125710-cc2fa4f57325/go.mod h1:eHbWZVMaaewmYBAUuRYnAmTTMtDhvpPNZuh8/6Yl7v0=
-k8s.io/client-go v0.0.0-20200713130841-505a1f443178/go.mod h1:4DeUSdsqcLMsCjohGuc0/AzpQDCDYsgjd7oq0vlmFQY=
+k8s.io/client-go v0.0.0-20200713130842-319dbfd0ed29/go.mod h1:4DeUSdsqcLMsCjohGuc0/AzpQDCDYsgjd7oq0vlmFQY=
 k8s.io/component-base v0.0.0-20200713132432-e98e6e533eb1/go.mod h1:vP8oeTBkmx6vS0b48FQ1masOyJvdltkTeuaV28yaF8k=
 k8s.io/gengo v0.0.0-20200413195148-3a45101e95ac/go.mod h1:ezvh/TsK7cY6rbqRK0oQQ8IAqLxYwwyPxAX1Pzy0ii0=
 k8s.io/klog/v2 v2.0.0/go.mod h1:PBfzABfn139FHAV07az/IF9Wp1bkk3vpT2XSJ76fSDE=

pkg/admission/plugin/webhook/mutating/dispatcher.go

@@ -42,6 +42,7 @@ import (
 	"k8s.io/apiserver/pkg/admission/plugin/webhook/generic"
 	webhookrequest "k8s.io/apiserver/pkg/admission/plugin/webhook/request"
 	auditinternal "k8s.io/apiserver/pkg/apis/audit"
+	genericapirequest "k8s.io/apiserver/pkg/endpoints/request"
 	webhookutil "k8s.io/apiserver/pkg/util/webhook"
 	"k8s.io/apiserver/pkg/warning"
 	utiltrace "k8s.io/utils/trace"
@@ -221,7 +222,7 @@ func (a *mutatingDispatcher) callAttrMutatingHook(ctx context.Context, h *admiss
 	if err != nil {
 		return false, &webhookutil.ErrCallingWebhook{WebhookName: h.Name, Reason: err}
 	}
-	trace := utiltrace.New("Call mutating webhook",
+	ctx, trace := genericapirequest.WithTrace(ctx, "Call mutating webhook",
 		utiltrace.Field{"configuration", configurationName},
 		utiltrace.Field{"webhook", h.Name},
 		utiltrace.Field{"resource", attr.GetResource()},

pkg/admission/plugin/webhook/validating/dispatcher.go

@@ -32,6 +32,7 @@ import (
 	webhookerrors "k8s.io/apiserver/pkg/admission/plugin/webhook/errors"
 	"k8s.io/apiserver/pkg/admission/plugin/webhook/generic"
 	webhookrequest "k8s.io/apiserver/pkg/admission/plugin/webhook/request"
+	genericapirequest "k8s.io/apiserver/pkg/endpoints/request"
 	webhookutil "k8s.io/apiserver/pkg/util/webhook"
 	"k8s.io/apiserver/pkg/warning"
 	"k8s.io/klog/v2"
@@ -181,7 +182,7 @@ func (d *validatingDispatcher) callHook(ctx context.Context, h *v1.ValidatingWeb
 	if err != nil {
 		return &webhookutil.ErrCallingWebhook{WebhookName: h.Name, Reason: err}
 	}
-	trace := utiltrace.New("Call validating webhook",
+	ctx, trace := genericapirequest.WithTrace(ctx, "Call validating webhook",
 		utiltrace.Field{"configuration", invocation.Webhook.GetConfigurationName()},
 		utiltrace.Field{"webhook", h.Name},
 		utiltrace.Field{"resource", attr.GetResource()},

pkg/endpoints/filters/authentication.go

@@ -47,6 +47,7 @@ func WithAuthentication(handler http.Handler, auth authenticator.Request, failed
 			req = req.WithContext(authenticator.WithAudiences(req.Context(), apiAuds))
 		}
 		resp, ok, err := auth.AuthenticateRequest(req)
+		traceFilterStep(req.Context(), "Authenticate check done")
 		defer recordAuthMetrics(resp, ok, err, apiAuds, authenticationStart)
 		if err != nil || !ok {
 			if err != nil {

pkg/endpoints/filters/authorization.go

@@ -57,6 +57,7 @@ func WithAuthorization(handler http.Handler, a authorizer.Authorizer, s runtime.
 			return
 		}
 		authorized, reason, err := a.Authorize(ctx, attributes)
+		traceFilterStep(ctx, "Authorize check done")
 		// an authorizer like RBAC could encounter evaluation errors and still allow the request, so authorizer decision is checked before error here.
 		if authorized == authorizer.DecisionAllow {
 			audit.LogAnnotation(ae, decisionAnnotationKey, decisionAllow)

pkg/endpoints/filters/impersonation.go

@@ -110,6 +110,7 @@ func WithImpersonation(handler http.Handler, a authorizer.Authorizer, s runtime.
 			}
 
 			decision, reason, err := a.Authorize(ctx, actingAsAttributes)
+			traceFilterStep(ctx, "Impersonation authorize check done")
 			if err != nil || decision != authorizer.DecisionAllow {
 				klog.V(4).Infof("Forbidden: %#v, Reason: %s, Error: %v", req.RequestURI, reason, err)
 				responsewriters.Forbidden(ctx, actingAsAttributes, w, req, reason, s)
@@ -144,7 +145,6 @@ func WithImpersonation(handler http.Handler, a authorizer.Authorizer, s runtime.
 				req.Header.Del(headerName)
 			}
 		}
-
 		handler.ServeHTTP(w, req)
 	})
 }

pkg/endpoints/filters/trace.go

@@ -0,0 +1,69 @@
+/*
+Copyright 2020 The Kubernetes Authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package filters
+
+import (
+	"context"
+	"net/http"
+	"time"
+
+	utiltrace "k8s.io/utils/trace"
+
+	"k8s.io/apiserver/pkg/endpoints/internal"
+	genericapirequest "k8s.io/apiserver/pkg/endpoints/request"
+)
+
+// WithTrace decorates a http.Handler with tracing for all the non-long running
+// requests coming to the server.
+func WithTrace(handler http.Handler, longRunningCheck genericapirequest.LongRunningRequestCheck) http.Handler {
+	return http.HandlerFunc(func(w http.ResponseWriter, req *http.Request) {
+		ri, ok := genericapirequest.RequestInfoFrom(req.Context())
+		isLongRunning := false
+		if longRunningCheck != nil {
+			if ok && longRunningCheck(req, ri) {
+				isLongRunning = true
+			}
+		}
+
+		if isLongRunning {
+			handler.ServeHTTP(w, req)
+			return
+		}
+		ctx, trace := genericapirequest.WithTrace(req.Context(), "HTTP Request",
+			utiltrace.Field{Key: "method", Value: req.Method},
+			utiltrace.Field{Key: "url", Value: req.URL.Path},
+			utiltrace.Field{Key: "verb", Value: ri.Verb},
+			utiltrace.Field{Key: "name", Value: ri.Name},
+			utiltrace.Field{Key: "resource", Value: ri.Resource},
+			utiltrace.Field{Key: "subresource", Value: ri.Subresource},
+			utiltrace.Field{Key: "namespace", Value: ri.Namespace},
+			utiltrace.Field{Key: "api-group", Value: ri.APIGroup},
+			utiltrace.Field{Key: "api-version", Value: ri.APIVersion},
+			utiltrace.Field{Key: "user-agent", Value: &internal.LazyTruncatedUserAgent{req}},
+			utiltrace.Field{Key: "client", Value: &internal.LazyClientIP{req}})
+		req = req.Clone(ctx)
+		// Set trace as root trace in context for nested tracing
+		defer trace.LogIfLong(30 * time.Second)
+		handler.ServeHTTP(w, req)
+	})
+}
+
+func traceFilterStep(ctx context.Context, msg string, field ...utiltrace.Field) {
+	if trace, ok := genericapirequest.TraceFrom(ctx); ok {
+		trace.Step(msg, field...)
+	}
+}

pkg/endpoints/handlers/create.go

@@ -33,9 +33,11 @@ import (
 	"k8s.io/apimachinery/pkg/apis/meta/v1/validation"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/runtime/schema"
+
 	"k8s.io/apiserver/pkg/admission"
 	"k8s.io/apiserver/pkg/audit"
 	"k8s.io/apiserver/pkg/endpoints/handlers/negotiation"
+	"k8s.io/apiserver/pkg/endpoints/internal"
 	"k8s.io/apiserver/pkg/endpoints/request"
 	"k8s.io/apiserver/pkg/features"
 	"k8s.io/apiserver/pkg/registry/rest"
@@ -47,7 +49,7 @@ import (
 func createHandler(r rest.NamedCreater, scope *RequestScope, admit admission.Interface, includeName bool) http.HandlerFunc {
 	return func(w http.ResponseWriter, req *http.Request) {
 		// For performance tracking purposes.
-		trace := utiltrace.New("Create", utiltrace.Field{Key: "url", Value: req.URL.Path}, utiltrace.Field{Key: "user-agent", Value: &lazyTruncatedUserAgent{req}}, utiltrace.Field{Key: "client", Value: &lazyClientIP{req}})
+		req, trace := requestWithTrace(req, "Create", utiltrace.Field{Key: "url", Value: req.URL.Path}, utiltrace.Field{Key: "user-agent", Value: &internal.LazyTruncatedUserAgent{req}}, utiltrace.Field{Key: "client", Value: &internal.LazyClientIP{req}})
 		defer trace.LogIfLong(500 * time.Millisecond)
 
 		if isDryRun(req.URL) && !utilfeature.DefaultFeatureGate.Enabled(features.DryRun) {

pkg/endpoints/handlers/delete.go

@@ -30,9 +30,11 @@ import (
 	"k8s.io/apimachinery/pkg/apis/meta/v1/validation"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/runtime/schema"
+
 	"k8s.io/apiserver/pkg/admission"
 	"k8s.io/apiserver/pkg/audit"
 	"k8s.io/apiserver/pkg/endpoints/handlers/negotiation"
+	"k8s.io/apiserver/pkg/endpoints/internal"
 	"k8s.io/apiserver/pkg/endpoints/request"
 	"k8s.io/apiserver/pkg/features"
 	"k8s.io/apiserver/pkg/registry/rest"
@@ -46,7 +48,7 @@ import (
 func DeleteResource(r rest.GracefulDeleter, allowsOptions bool, scope *RequestScope, admit admission.Interface) http.HandlerFunc {
 	return func(w http.ResponseWriter, req *http.Request) {
 		// For performance tracking purposes.
-		trace := utiltrace.New("Delete", utiltrace.Field{Key: "url", Value: req.URL.Path}, utiltrace.Field{Key: "user-agent", Value: &lazyTruncatedUserAgent{req}}, utiltrace.Field{Key: "client", Value: &lazyClientIP{req}})
+		req, trace := requestWithTrace(req, "Delete", utiltrace.Field{Key: "url", Value: req.URL.Path}, utiltrace.Field{Key: "user-agent", Value: &internal.LazyTruncatedUserAgent{req}}, utiltrace.Field{Key: "client", Value: &internal.LazyClientIP{req}})
 		defer trace.LogIfLong(500 * time.Millisecond)
 
 		if isDryRun(req.URL) && !utilfeature.DefaultFeatureGate.Enabled(features.DryRun) {
@@ -164,7 +166,7 @@ func DeleteResource(r rest.GracefulDeleter, allowsOptions bool, scope *RequestSc
 // DeleteCollection returns a function that will handle a collection deletion
 func DeleteCollection(r rest.CollectionDeleter, checkBody bool, scope *RequestScope, admit admission.Interface) http.HandlerFunc {
 	return func(w http.ResponseWriter, req *http.Request) {
-		trace := utiltrace.New("Delete", utiltrace.Field{"url", req.URL.Path})
+		req, trace := requestWithTrace(req, "Delete", utiltrace.Field{"url", req.URL.Path})
 		defer trace.LogIfLong(500 * time.Millisecond)
 
 		if isDryRun(req.URL) && !utilfeature.DefaultFeatureGate.Enabled(features.DryRun) {

pkg/endpoints/handlers/get.go

@@ -36,7 +36,9 @@ import (
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/fields"
 	"k8s.io/apimachinery/pkg/runtime"
+
 	"k8s.io/apiserver/pkg/endpoints/handlers/negotiation"
+	"k8s.io/apiserver/pkg/endpoints/internal"
 	"k8s.io/apiserver/pkg/endpoints/metrics"
 	"k8s.io/apiserver/pkg/endpoints/request"
 	"k8s.io/apiserver/pkg/registry/rest"
@@ -51,7 +53,7 @@ type getterFunc func(ctx context.Context, name string, req *http.Request, trace
 // passed-in getterFunc to perform the actual get.
 func getResourceHandler(scope *RequestScope, getter getterFunc) http.HandlerFunc {
 	return func(w http.ResponseWriter, req *http.Request) {
-		trace := utiltrace.New("Get", utiltrace.Field{Key: "url", Value: req.URL.Path}, utiltrace.Field{Key: "user-agent", Value: &lazyTruncatedUserAgent{req}}, utiltrace.Field{Key: "client", Value: &lazyClientIP{req}})
+		req, trace := requestWithTrace(req, "Get", utiltrace.Field{Key: "url", Value: req.URL.Path}, utiltrace.Field{Key: "user-agent", Value: &internal.LazyTruncatedUserAgent{req}}, utiltrace.Field{Key: "client", Value: &internal.LazyClientIP{req}})
 		defer trace.LogIfLong(500 * time.Millisecond)
 
 		namespace, name, err := scope.Namer.Name(req)
@@ -168,7 +170,7 @@ func getRequestOptions(req *http.Request, scope *RequestScope, into runtime.Obje
 func ListResource(r rest.Lister, rw rest.Watcher, scope *RequestScope, forceWatch bool, minRequestTimeout time.Duration) http.HandlerFunc {
 	return func(w http.ResponseWriter, req *http.Request) {
 		// For performance tracking purposes.
-		trace := utiltrace.New("List", utiltrace.Field{Key: "url", Value: req.URL.Path}, utiltrace.Field{Key: "user-agent", Value: &lazyTruncatedUserAgent{req}}, utiltrace.Field{Key: "client", Value: &lazyClientIP{req}})
+		req, trace := requestWithTrace(req, "List", utiltrace.Field{Key: "url", Value: req.URL.Path}, utiltrace.Field{Key: "user-agent", Value: &internal.LazyTruncatedUserAgent{req}}, utiltrace.Field{Key: "client", Value: &internal.LazyClientIP{req}})
 
 		namespace, err := scope.Namer.Namespace(req)
 		if err != nil {

pkg/endpoints/handlers/patch.go

@@ -38,18 +38,20 @@ import (
 	"k8s.io/apimachinery/pkg/util/sets"
 	"k8s.io/apimachinery/pkg/util/strategicpatch"
 	"k8s.io/apimachinery/pkg/util/validation/field"
+	"sigs.k8s.io/yaml"
+
 	"k8s.io/apiserver/pkg/admission"
 	"k8s.io/apiserver/pkg/audit"
 	"k8s.io/apiserver/pkg/authorization/authorizer"
 	"k8s.io/apiserver/pkg/endpoints/handlers/fieldmanager"
 	"k8s.io/apiserver/pkg/endpoints/handlers/negotiation"
+	"k8s.io/apiserver/pkg/endpoints/internal"
 	"k8s.io/apiserver/pkg/endpoints/request"
 	"k8s.io/apiserver/pkg/features"
 	"k8s.io/apiserver/pkg/registry/rest"
 	"k8s.io/apiserver/pkg/util/dryrun"
 	utilfeature "k8s.io/apiserver/pkg/util/feature"
 	utiltrace "k8s.io/utils/trace"
-	"sigs.k8s.io/yaml"
 )
 
 const (
@@ -61,7 +63,7 @@ const (
 func PatchResource(r rest.Patcher, scope *RequestScope, admit admission.Interface, patchTypes []string) http.HandlerFunc {
 	return func(w http.ResponseWriter, req *http.Request) {
 		// For performance tracking purposes.
-		trace := utiltrace.New("Patch", utiltrace.Field{Key: "url", Value: req.URL.Path}, utiltrace.Field{Key: "user-agent", Value: &lazyTruncatedUserAgent{req}}, utiltrace.Field{Key: "client", Value: &lazyClientIP{req}})
+		req, trace := requestWithTrace(req, "Patch", utiltrace.Field{Key: "url", Value: req.URL.Path}, utiltrace.Field{Key: "user-agent", Value: &internal.LazyTruncatedUserAgent{req}}, utiltrace.Field{Key: "client", Value: &internal.LazyClientIP{req}})
 		defer trace.LogIfLong(500 * time.Millisecond)
 
 		if isDryRun(req.URL) && !utilfeature.DefaultFeatureGate.Enabled(features.DryRun) {

pkg/endpoints/handlers/rest.go

@@ -47,6 +47,7 @@ import (
 	"k8s.io/apiserver/pkg/registry/rest"
 	utilfeature "k8s.io/apiserver/pkg/util/feature"
 	"k8s.io/klog/v2"
+	utiltrace "k8s.io/utils/trace"
 )
 
 // RequestScope encapsulates common fields across all RESTful handler methods.
@@ -445,3 +446,10 @@ func isTooLargeError(err error) bool {
 	}
 	return false
 }
+
+// requestWithTrace returns a new trace using the provided msg and fields, nested within any trace already in the
+//context of the provided req. Also returns a request with the new trace in the context.
+func requestWithTrace(req *http.Request, msg string, fields ...utiltrace.Field) (*http.Request, *utiltrace.Trace) {
+	ctx, trace := request.WithTrace(req.Context(), msg, fields...)
+	return req.Clone(ctx), trace
+}

pkg/endpoints/handlers/update.go

@@ -30,10 +30,12 @@ import (
 	"k8s.io/apimachinery/pkg/apis/meta/v1/validation"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/runtime/schema"
+
 	"k8s.io/apiserver/pkg/admission"
 	"k8s.io/apiserver/pkg/audit"
 	"k8s.io/apiserver/pkg/authorization/authorizer"
 	"k8s.io/apiserver/pkg/endpoints/handlers/negotiation"
+	"k8s.io/apiserver/pkg/endpoints/internal"
 	"k8s.io/apiserver/pkg/endpoints/request"
 	"k8s.io/apiserver/pkg/features"
 	"k8s.io/apiserver/pkg/registry/rest"
@@ -46,7 +48,7 @@ import (
 func UpdateResource(r rest.Updater, scope *RequestScope, admit admission.Interface) http.HandlerFunc {
 	return func(w http.ResponseWriter, req *http.Request) {
 		// For performance tracking purposes.
-		trace := utiltrace.New("Update", utiltrace.Field{Key: "url", Value: req.URL.Path}, utiltrace.Field{Key: "user-agent", Value: &lazyTruncatedUserAgent{req}}, utiltrace.Field{Key: "client", Value: &lazyClientIP{req}})
+		req, trace := requestWithTrace(req, "Update", utiltrace.Field{Key: "url", Value: req.URL.Path}, utiltrace.Field{Key: "user-agent", Value: &internal.LazyTruncatedUserAgent{req}}, utiltrace.Field{Key: "client", Value: &internal.LazyClientIP{req}})
 		defer trace.LogIfLong(500 * time.Millisecond)
 
 		if isDryRun(req.URL) && !utilfeature.DefaultFeatureGate.Enabled(features.DryRun) {

pkg/endpoints/internal/helpers.go

@@ -14,7 +14,7 @@ See the License for the specific language governing permissions and
 limitations under the License.
 */
 
-package handlers
+package internal
 
 import (
 	"net/http"
@@ -27,16 +27,16 @@ const (
 	userAgentTruncateSuffix = "...TRUNCATED"
 )
 
-// lazyTruncatedUserAgent implements String() string and it will
+// LazyTruncatedUserAgent implements String() string and it will
 // return user-agent which may be truncated.
-type lazyTruncatedUserAgent struct {
+type LazyTruncatedUserAgent struct {
-	req *http.Request
+	Req *http.Request
 }
 
-func (lazy *lazyTruncatedUserAgent) String() string {
+func (lazy *LazyTruncatedUserAgent) String() string {
 	ua := "unknown"
-	if lazy.req != nil {
+	if lazy.Req != nil {
-		ua = utilnet.GetHTTPClient(lazy.req)
+		ua = utilnet.GetHTTPClient(lazy.Req)
 		if len(ua) > maxUserAgentLength {
 			ua = ua[:maxUserAgentLength] + userAgentTruncateSuffix
 		}
@@ -46,13 +46,13 @@ func (lazy *lazyTruncatedUserAgent) String() string {
 
 // LazyClientIP implements String() string and it will
 // calls GetClientIP() lazily only when required.
-type lazyClientIP struct {
+type LazyClientIP struct {
-	req *http.Request
+	Req *http.Request
 }
 
-func (lazy *lazyClientIP) String() string {
+func (lazy *LazyClientIP) String() string {
-	if lazy.req != nil {
+	if lazy.Req != nil {
-		if ip := utilnet.GetClientIP(lazy.req); ip != nil {
+		if ip := utilnet.GetClientIP(lazy.Req); ip != nil {
 			return ip.String()
 		}
 	}

pkg/endpoints/internal/helpers_test.go

@@ -14,13 +14,14 @@ See the License for the specific language governing permissions and
 limitations under the License.
 */
 
-package handlers
+package internal
 
 import (
 	"fmt"
-	"github.com/stretchr/testify/assert"
 	"net/http"
 	"testing"
+
+	"github.com/stretchr/testify/assert"
 )
 
 func TestLazyTruncatedUserAgent(t *testing.T) {
@@ -29,7 +30,7 @@ func TestLazyTruncatedUserAgent(t *testing.T) {
 
 	ua := "short-agent"
 	req.Header.Set("User-Agent", ua)
-	uaNotTruncated := &lazyTruncatedUserAgent{req}
+	uaNotTruncated := &LazyTruncatedUserAgent{req}
 	assert.Equal(t, ua, fmt.Sprintf("%v", uaNotTruncated))
 
 	ua = ""
@@ -37,10 +38,10 @@ func TestLazyTruncatedUserAgent(t *testing.T) {
 		ua = ua + "a"
 	}
 	req.Header.Set("User-Agent", ua)
-	uaTruncated := &lazyTruncatedUserAgent{req}
+	uaTruncated := &LazyTruncatedUserAgent{req}
 	assert.NotEqual(t, ua, fmt.Sprintf("%v", uaTruncated))
 
-	usUnknown := &lazyTruncatedUserAgent{}
+	usUnknown := &LazyTruncatedUserAgent{}
 	assert.Equal(t, "unknown", fmt.Sprintf("%v", usUnknown))
 }
 
@@ -51,9 +52,9 @@ func TestLazyClientIP(t *testing.T) {
 	ip := "127.0.0.1"
 	req.Header.Set("X-Forwarded-For", ip)
 
-	clientIPWithReq := &lazyClientIP{req}
+	clientIPWithReq := &LazyClientIP{req}
 	assert.Equal(t, ip, fmt.Sprintf("%v", clientIPWithReq))
 
-	clientIPWithoutReq := &lazyClientIP{}
+	clientIPWithoutReq := &LazyClientIP{}
 	assert.Equal(t, "unknown", fmt.Sprintf("%v", clientIPWithoutReq))
 }

pkg/endpoints/request/context.go

@@ -22,6 +22,7 @@ import (
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apiserver/pkg/apis/audit"
 	"k8s.io/apiserver/pkg/authentication/user"
+	utiltrace "k8s.io/utils/trace"
 )
 
 // The key type is unexported to prevent collisions
@@ -39,6 +40,9 @@ const (
 
 	// audiencesKey is the context key for request audiences.
 	audiencesKey
+
+	// traceKey is the context key for nested tracing.
+	traceKey
 )
 
 // NewContext instantiates a base context object for request flows.
@@ -94,3 +98,17 @@ func AuditEventFrom(ctx context.Context) *audit.Event {
 	ev, _ := ctx.Value(auditKey).(*audit.Event)
 	return ev
 }
+
+// TraceFrom returns the value of the trace key on the ctx
+func TraceFrom(ctx context.Context) (*utiltrace.Trace, bool) {
+	trace, ok := ctx.Value(traceKey).(*utiltrace.Trace)
+	return trace, ok
+}
+
+// WithTrace returns a new trace using the provided msg and fields, nested within any trace already in the
+// provided context. Also returns a context containing the new trace
+func WithTrace(ctx context.Context, msg string, fields ...utiltrace.Field) (context.Context, *utiltrace.Trace) {
+	parent, _ := TraceFrom(ctx) // ignore ok since Nest can be called with a nil receiver to create root traces
+	trace := parent.Nest(msg, fields...)
+	return context.WithValue(ctx, traceKey, trace), trace
+}

pkg/server/config.go

@@ -682,6 +682,7 @@ func DefaultBuildHandlerChain(apiHandler http.Handler, c *Config) http.Handler {
 	handler = genericfilters.WithCORS(handler, c.CorsAllowedOriginList, nil, nil, nil, "true")
 	handler = genericfilters.WithTimeoutForNonLongRunningRequests(handler, c.LongRunningFunc, c.RequestTimeout)
 	handler = genericfilters.WithWaitGroup(handler, c.LongRunningFunc, c.HandlerChainWaitGroup)
+	handler = genericapifilters.WithTrace(handler, c.LongRunningFunc)
 	handler = genericapifilters.WithRequestInfo(handler, c.RequestInfoResolver)
 	if c.SecureServing != nil && !c.SecureServing.DisableHTTP2 && c.GoawayChance > 0 {
 		handler = genericfilters.WithProbabilisticGoaway(handler, c.GoawayChance)

pkg/storage/cacher/cacher.go

@@ -35,6 +35,7 @@ import (
 	utilruntime "k8s.io/apimachinery/pkg/util/runtime"
 	"k8s.io/apimachinery/pkg/util/wait"
 	"k8s.io/apimachinery/pkg/watch"
+	genericapirequest "k8s.io/apiserver/pkg/endpoints/request"
 	"k8s.io/apiserver/pkg/features"
 	"k8s.io/apiserver/pkg/storage"
 	utilfeature "k8s.io/apiserver/pkg/util/feature"
@@ -604,7 +605,7 @@ func (c *Cacher) GetToList(ctx context.Context, key string, opts storage.ListOpt
 		return c.storage.GetToList(ctx, key, opts, listObj)
 	}
 
-	trace := utiltrace.New("cacher list", utiltrace.Field{"type", c.objectType.String()})
+	ctx, trace := genericapirequest.WithTrace(ctx, "cacher list", utiltrace.Field{"type", c.objectType.String()})
 	defer trace.LogIfLong(500 * time.Millisecond)
 
 	c.ready.wait()
@@ -678,7 +679,7 @@ func (c *Cacher) List(ctx context.Context, key string, opts storage.ListOptions,
 		return c.storage.List(ctx, key, opts, listObj)
 	}
 
-	trace := utiltrace.New("cacher list", utiltrace.Field{"type", c.objectType.String()})
+	ctx, trace := genericapirequest.WithTrace(ctx, "cacher list", utiltrace.Field{"type", c.objectType.String()})
 	defer trace.LogIfLong(500 * time.Millisecond)
 
 	c.ready.wait()

pkg/storage/etcd3/store.go

@@ -38,6 +38,7 @@ import (
 	"k8s.io/apimachinery/pkg/conversion"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/watch"
+	genericapirequest "k8s.io/apiserver/pkg/endpoints/request"
 	"k8s.io/apiserver/pkg/features"
 	"k8s.io/apiserver/pkg/storage"
 	"k8s.io/apiserver/pkg/storage/etcd3/metrics"
@@ -239,7 +240,7 @@ func (s *store) conditionalDelete(ctx context.Context, key string, out runtime.O
 func (s *store) GuaranteedUpdate(
 	ctx context.Context, key string, out runtime.Object, ignoreNotFound bool,
 	preconditions *storage.Preconditions, tryUpdate storage.UpdateFunc, suggestion ...runtime.Object) error {
-	trace := utiltrace.New("GuaranteedUpdate etcd3", utiltrace.Field{"type", getTypeName(out)})
+	ctx, trace := genericapirequest.WithTrace(ctx, "GuaranteedUpdate etcd3", utiltrace.Field{"type", getTypeName(out)})
 	defer trace.LogIfLong(500 * time.Millisecond)
 
 	v, err := conversion.EnforcePtr(out)
@@ -382,7 +383,7 @@ func (s *store) GetToList(ctx context.Context, key string, listOpts storage.List
 	resourceVersion := listOpts.ResourceVersion
 	match := listOpts.ResourceVersionMatch
 	pred := listOpts.Predicate
-	trace := utiltrace.New("GetToList etcd3",
+	ctx, trace := genericapirequest.WithTrace(ctx, "GetToList etcd3",
 		utiltrace.Field{"key", key},
 		utiltrace.Field{"resourceVersion", resourceVersion},
 		utiltrace.Field{"resourceVersionMatch", match},
@@ -526,7 +527,7 @@ func (s *store) List(ctx context.Context, key string, opts storage.ListOptions,
 	resourceVersion := opts.ResourceVersion
 	match := opts.ResourceVersionMatch
 	pred := opts.Predicate
-	trace := utiltrace.New("List etcd3",
+	ctx, trace := genericapirequest.WithTrace(ctx, "List etcd3",
 		utiltrace.Field{"key", key},
 		utiltrace.Field{"resourceVersion", resourceVersion},
 		utiltrace.Field{"resourceVersionMatch", match},