Add audit-id to storage traces

Refactor GetAuditIDTruncated to use context instead of request

Kubernetes-commit: b1e12b01b6c578da3eb593805b48e9d4a69efe54

pkg/endpoints/handlers/helpers.go

@@ -83,7 +83,7 @@ type lazyAuditID struct {
 
 func (lazy *lazyAuditID) String() string {
 	if lazy.req != nil {
-		return request.GetAuditIDTruncated(lazy.req)
+		return request.GetAuditIDTruncated(lazy.req.Context())
 	}
 
 	return "unknown"

pkg/endpoints/handlers/responsewriters/writers.go

@@ -88,6 +88,7 @@ func StreamObject(statusCode int, gv schema.GroupVersion, s runtime.NegotiatedSe
 // a client and the feature gate for APIResponseCompression is enabled.
 func SerializeObject(mediaType string, encoder runtime.Encoder, hw http.ResponseWriter, req *http.Request, statusCode int, object runtime.Object) {
 	trace := utiltrace.New("SerializeObject",
+		utiltrace.Field{"audit-id", request.GetAuditIDTruncated(req.Context())},
 		utiltrace.Field{"method", req.Method},
 		utiltrace.Field{"url", req.URL.Path},
 		utiltrace.Field{"protocol", req.Proto},

pkg/endpoints/request/auditid.go

@@ -18,7 +18,6 @@ package request
 
 import (
 	"context"
-	"net/http"
 
 	"k8s.io/apimachinery/pkg/types"
 )
@@ -45,12 +44,12 @@ func AuditIDFrom(ctx context.Context) (types.UID, bool) {
 	return auditID, ok
 }
 
-// GetAuditIDTruncated returns the audit ID (truncated) associated with a request.
+// GetAuditIDTruncated returns the audit ID (truncated) from the request context.
 // If the length of the Audit-ID value exceeds the limit, we truncate it to keep
 // the first N (maxAuditIDLength) characters.
 // This is intended to be used in logging only.
-func GetAuditIDTruncated(req *http.Request) string {
-	auditID, ok := AuditIDFrom(req.Context())
+func GetAuditIDTruncated(ctx context.Context) string {
+	auditID, ok := AuditIDFrom(ctx)
 	if !ok {
 		return ""
 	}

pkg/server/filters/wrap.go

@@ -50,11 +50,11 @@ func WithPanicRecovery(handler http.Handler, resolver request.RequestInfoResolve
 			// This call can have different handlers, but the default chain rate limits. Call it after the metrics are updated
 			// in case the rate limit delays it.  If you outrun the rate for this one timed out requests, something has gone
 			// seriously wrong with your server, but generally having a logging signal for timeouts is useful.
-			runtime.HandleError(fmt.Errorf("timeout or abort while handling: method=%v URI=%q audit-ID=%q", req.Method, req.RequestURI, request.GetAuditIDTruncated(req)))
+			runtime.HandleError(fmt.Errorf("timeout or abort while handling: method=%v URI=%q audit-ID=%q", req.Method, req.RequestURI, request.GetAuditIDTruncated(req.Context())))
 			return
 		}
 		http.Error(w, "This request caused apiserver to panic. Look in the logs for details.", http.StatusInternalServerError)
-		klog.ErrorS(nil, "apiserver panic'd", "method", req.Method, "URI", req.RequestURI, "audit-ID", request.GetAuditIDTruncated(req))
+		klog.ErrorS(nil, "apiserver panic'd", "method", req.Method, "URI", req.RequestURI, "audit-ID", request.GetAuditIDTruncated(req.Context()))
 	})
 }
 

pkg/server/httplog/httplog.go

@@ -239,7 +239,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() {
 	latency := time.Since(rl.startTime)
-	auditID := request.GetAuditIDTruncated(rl.req)
+	auditID := request.GetAuditIDTruncated(rl.req.Context())
 
 	verb := rl.req.Method
 	if requestInfo, ok := request.RequestInfoFrom(rl.req.Context()); ok {

pkg/storage/cacher/cacher.go

@@ -34,6 +34,7 @@ import (
 	utilruntime "k8s.io/apimachinery/pkg/util/runtime"
 	"k8s.io/apimachinery/pkg/util/wait"
 	"k8s.io/apimachinery/pkg/watch"
+	endpointsrequest "k8s.io/apiserver/pkg/endpoints/request"
 	"k8s.io/apiserver/pkg/features"
 	"k8s.io/apiserver/pkg/storage"
 	"k8s.io/apiserver/pkg/storage/cacher/metrics"
@@ -645,7 +646,9 @@ func (c *Cacher) GetList(ctx context.Context, key string, opts storage.ListOptio
 		return c.storage.GetList(ctx, key, opts, listObj)
 	}
 
-	trace := utiltrace.New("cacher list", utiltrace.Field{Key: "type", Value: c.objectType.String()})
+	trace := utiltrace.New("cacher list",
+		utiltrace.Field{"audit-id", endpointsrequest.GetAuditIDTruncated(ctx)},
+		utiltrace.Field{Key: "type", Value: c.objectType.String()})
 	defer trace.LogIfLong(500 * time.Millisecond)
 
 	if err := c.ready.wait(); err != nil {

pkg/storage/etcd3/store.go

@@ -37,6 +37,7 @@ import (
 	"k8s.io/apimachinery/pkg/conversion"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/watch"
+	endpointsrequest "k8s.io/apiserver/pkg/endpoints/request"
 	"k8s.io/apiserver/pkg/features"
 	"k8s.io/apiserver/pkg/storage"
 	"k8s.io/apiserver/pkg/storage/etcd3/metrics"
@@ -152,6 +153,7 @@ func (s *store) Get(ctx context.Context, key string, opts storage.GetOptions, ou
 // Create implements storage.Interface.Create.
 func (s *store) Create(ctx context.Context, key string, obj, out runtime.Object, ttl uint64) error {
 	trace := utiltrace.New("Create etcd3",
+		utiltrace.Field{"audit-id", endpointsrequest.GetAuditIDTruncated(ctx)},
 		utiltrace.Field{"key", key},
 		utiltrace.Field{"type", getTypeName(obj)},
 	)
@@ -329,6 +331,7 @@ func (s *store) GuaranteedUpdate(
 	ctx context.Context, key string, destination runtime.Object, ignoreNotFound bool,
 	preconditions *storage.Preconditions, tryUpdate storage.UpdateFunc, cachedExistingObject runtime.Object) error {
 	trace := utiltrace.New("GuaranteedUpdate etcd3",
+		utiltrace.Field{"audit-id", endpointsrequest.GetAuditIDTruncated(ctx)},
 		utiltrace.Field{"key", key},
 		utiltrace.Field{"type", getTypeName(destination)})
 	defer trace.LogIfLong(500 * time.Millisecond)
@@ -524,6 +527,7 @@ func (s *store) GetList(ctx context.Context, key string, opts storage.ListOption
 	match := opts.ResourceVersionMatch
 	pred := opts.Predicate
 	trace := utiltrace.New(fmt.Sprintf("List(recursive=%v) etcd3", recursive),
+		utiltrace.Field{"audit-id", endpointsrequest.GetAuditIDTruncated(ctx)},
 		utiltrace.Field{"key", key},
 		utiltrace.Field{"resourceVersion", resourceVersion},
 		utiltrace.Field{"resourceVersionMatch", match},