Add audit-id to storage traces

Refactor GetAuditIDTruncated to use context instead of request
This commit is contained in:
Artur Żyliński 2022-06-20 17:09:32 +02:00
parent 609db7ed0b
commit b1e12b01b6
7 changed files with 16 additions and 9 deletions

View File

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

View File

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

View File

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

View File

@ -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 // 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 // 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. // 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 return
} }
http.Error(w, "This request caused apiserver to panic. Look in the logs for details.", http.StatusInternalServerError) 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()))
}) })
} }

View File

@ -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 // Log is intended to be called once at the end of your request handler, via defer
func (rl *respLogger) Log() { func (rl *respLogger) Log() {
latency := time.Since(rl.startTime) latency := time.Since(rl.startTime)
auditID := request.GetAuditIDTruncated(rl.req) auditID := request.GetAuditIDTruncated(rl.req.Context())
verb := rl.req.Method verb := rl.req.Method
if requestInfo, ok := request.RequestInfoFrom(rl.req.Context()); ok { if requestInfo, ok := request.RequestInfoFrom(rl.req.Context()); ok {

View File

@ -34,6 +34,7 @@ import (
utilruntime "k8s.io/apimachinery/pkg/util/runtime" utilruntime "k8s.io/apimachinery/pkg/util/runtime"
"k8s.io/apimachinery/pkg/util/wait" "k8s.io/apimachinery/pkg/util/wait"
"k8s.io/apimachinery/pkg/watch" "k8s.io/apimachinery/pkg/watch"
endpointsrequest "k8s.io/apiserver/pkg/endpoints/request"
"k8s.io/apiserver/pkg/features" "k8s.io/apiserver/pkg/features"
"k8s.io/apiserver/pkg/storage" "k8s.io/apiserver/pkg/storage"
"k8s.io/apiserver/pkg/storage/cacher/metrics" "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) 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) defer trace.LogIfLong(500 * time.Millisecond)
if err := c.ready.wait(); err != nil { if err := c.ready.wait(); err != nil {

View File

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