From 9c15d75f23402badbc2930aea7bef0ef4901248c Mon Sep 17 00:00:00 2001 From: Naman Lakhwani Date: Wed, 12 Apr 2023 04:04:43 +0530 Subject: [PATCH] Migrated `pod-security-admission` to contextual logging (#114471) * migrated pod-security-admission to contextual logging Signed-off-by: Naman * updating test files for contextual logging Signed-off-by: Naman * smalll nit Signed-off-by: Naman * doing inline if Signed-off-by: Naman --------- Signed-off-by: Naman --- .../admission/admission.go | 34 +++++++++---------- .../admission/admission_test.go | 7 ++-- .../cmd/webhook/server/server.go | 30 ++++++++-------- 3 files changed, 38 insertions(+), 33 deletions(-) diff --git a/staging/src/k8s.io/pod-security-admission/admission/admission.go b/staging/src/k8s.io/pod-security-admission/admission/admission.go index 7e5749b7a8c..f6a030b4cfe 100644 --- a/staging/src/k8s.io/pod-security-admission/admission/admission.go +++ b/staging/src/k8s.io/pod-security-admission/admission/admission.go @@ -233,12 +233,12 @@ func (a *Admission) ValidateNamespace(ctx context.Context, attrs api.Attributes) } obj, err := attrs.GetObject() if err != nil { - klog.ErrorS(err, "failed to decode object") + klog.FromContext(ctx).Error(err, "failed to decode object") return errorResponse(err, &apierrors.NewBadRequest("failed to decode object").ErrStatus) } namespace, ok := obj.(*corev1.Namespace) if !ok { - klog.InfoS("failed to assert namespace type", "type", reflect.TypeOf(obj)) + klog.FromContext(ctx).Info("failed to assert namespace type", "type", reflect.TypeOf(obj)) return errorResponse(nil, &apierrors.NewBadRequest("failed to decode namespace").ErrStatus) } @@ -263,12 +263,12 @@ func (a *Admission) ValidateNamespace(ctx context.Context, attrs api.Attributes) // if update, check if policy labels changed oldObj, err := attrs.GetOldObject() if err != nil { - klog.ErrorS(err, "failed to decode old object") + klog.FromContext(ctx).Error(err, "failed to decode old object") return errorResponse(err, &apierrors.NewBadRequest("failed to decode old object").ErrStatus) } oldNamespace, ok := oldObj.(*corev1.Namespace) if !ok { - klog.InfoS("failed to assert old namespace type", "type", reflect.TypeOf(oldObj)) + klog.FromContext(ctx).Info("failed to assert old namespace type", "type", reflect.TypeOf(oldObj)) return errorResponse(nil, &apierrors.NewBadRequest("failed to decode old namespace").ErrStatus) } oldPolicy, oldErrs := a.PolicyToEvaluate(oldNamespace.Labels) @@ -345,7 +345,7 @@ func (a *Admission) ValidatePod(ctx context.Context, attrs api.Attributes) *admi // short-circuit on privileged enforce+audit+warn namespaces namespace, err := a.NamespaceGetter.GetNamespace(ctx, attrs.GetNamespace()) if err != nil { - klog.ErrorS(err, "failed to fetch pod namespace", "namespace", attrs.GetNamespace()) + klog.FromContext(ctx).Error(err, "failed to fetch pod namespace", "namespace", attrs.GetNamespace()) a.Metrics.RecordError(true, attrs) return errorResponse(err, &apierrors.NewInternalError(fmt.Errorf("failed to lookup namespace %q", attrs.GetNamespace())).ErrStatus) } @@ -357,26 +357,26 @@ func (a *Admission) ValidatePod(ctx context.Context, attrs api.Attributes) *admi obj, err := attrs.GetObject() if err != nil { - klog.ErrorS(err, "failed to decode object") + klog.FromContext(ctx).Error(err, "failed to decode object") a.Metrics.RecordError(true, attrs) return errorResponse(err, &apierrors.NewBadRequest("failed to decode object").ErrStatus) } pod, ok := obj.(*corev1.Pod) if !ok { - klog.InfoS("failed to assert pod type", "type", reflect.TypeOf(obj)) + klog.FromContext(ctx).Info("failed to assert pod type", "type", reflect.TypeOf(obj)) a.Metrics.RecordError(true, attrs) return errorResponse(nil, &apierrors.NewBadRequest("failed to decode pod").ErrStatus) } if attrs.GetOperation() == admissionv1.Update { oldObj, err := attrs.GetOldObject() if err != nil { - klog.ErrorS(err, "failed to decode old object") + klog.FromContext(ctx).Error(err, "failed to decode old object") a.Metrics.RecordError(true, attrs) return errorResponse(err, &apierrors.NewBadRequest("failed to decode old object").ErrStatus) } oldPod, ok := oldObj.(*corev1.Pod) if !ok { - klog.InfoS("Failed to assert old pod type", "type", reflect.TypeOf(oldObj)) + klog.FromContext(ctx).Info("failed to assert old pod type", "type", reflect.TypeOf(oldObj)) a.Metrics.RecordError(true, attrs) return errorResponse(nil, &apierrors.NewBadRequest("failed to decode old pod").ErrStatus) } @@ -409,7 +409,7 @@ func (a *Admission) ValidatePodController(ctx context.Context, attrs api.Attribu // short-circuit on privileged audit+warn namespaces namespace, err := a.NamespaceGetter.GetNamespace(ctx, attrs.GetNamespace()) if err != nil { - klog.ErrorS(err, "failed to fetch pod namespace", "namespace", attrs.GetNamespace()) + klog.FromContext(ctx).Error(err, "failed to fetch pod namespace", "namespace", attrs.GetNamespace()) a.Metrics.RecordError(true, attrs) response := allowedResponse() response.AuditAnnotations = map[string]string{ @@ -424,7 +424,7 @@ func (a *Admission) ValidatePodController(ctx context.Context, attrs api.Attribu obj, err := attrs.GetObject() if err != nil { - klog.ErrorS(err, "failed to decode object") + klog.FromContext(ctx).Error(err, "failed to decode object") a.Metrics.RecordError(true, attrs) response := allowedResponse() response.AuditAnnotations = map[string]string{ @@ -434,7 +434,7 @@ func (a *Admission) ValidatePodController(ctx context.Context, attrs api.Attribu } podMetadata, podSpec, err := a.PodSpecExtractor.ExtractPodSpec(obj) if err != nil { - klog.ErrorS(err, "failed to extract pod spec") + klog.FromContext(ctx).Error(err, "failed to extract pod spec") a.Metrics.RecordError(true, attrs) response := allowedResponse() response.AuditAnnotations = map[string]string{ @@ -453,6 +453,7 @@ func (a *Admission) ValidatePodController(ctx context.Context, attrs api.Attribu // The enforce policy is only checked if enforce=true. // The returned response may be shared between evaluations and must not be mutated. func (a *Admission) EvaluatePod(ctx context.Context, nsPolicy api.Policy, nsPolicyErr error, podMetadata *metav1.ObjectMeta, podSpec *corev1.PodSpec, attrs api.Attributes, enforce bool) *admissionv1.AdmissionResponse { + logger := klog.FromContext(ctx) // short-circuit on exempt runtimeclass if a.exemptRuntimeClass(podSpec.RuntimeClassName) { a.Metrics.RecordExemption(attrs) @@ -461,14 +462,13 @@ func (a *Admission) EvaluatePod(ctx context.Context, nsPolicy api.Policy, nsPoli auditAnnotations := map[string]string{} if nsPolicyErr != nil { - klog.V(2).InfoS("failed to parse PodSecurity namespace labels", "err", nsPolicyErr) + logger.V(2).Info("failed to parse PodSecurity namespace labels", "err", nsPolicyErr) auditAnnotations["error"] = fmt.Sprintf("Failed to parse policy: %v", nsPolicyErr) a.Metrics.RecordError(false, attrs) } - klogV := klog.V(5) - if klogV.Enabled() { - klogV.InfoS("PodSecurity evaluation", "policy", fmt.Sprintf("%v", nsPolicy), "op", attrs.GetOperation(), "resource", attrs.GetResource(), "namespace", attrs.GetNamespace(), "name", attrs.GetName()) + if klogV := logger.V(5); klogV.Enabled() { + klogV.Info("PodSecurity evaluation", "policy", fmt.Sprintf("%v", nsPolicy), "op", attrs.GetOperation(), "resource", attrs.GetResource(), "namespace", attrs.GetNamespace(), "name", attrs.GetName()) } cachedResults := make(map[api.LevelVersion]policy.AggregateCheckResult) response := allowedResponse() @@ -551,7 +551,7 @@ func (a *Admission) EvaluatePodsInNamespace(ctx context.Context, namespace strin pods, err := a.PodLister.ListPods(ctx, namespace) if err != nil { - klog.ErrorS(err, "failed to list pods", "namespace", namespace) + klog.FromContext(ctx).Error(err, "failed to list pods", "namespace", namespace) return []string{"failed to list pods while checking new PodSecurity enforce level"} } diff --git a/staging/src/k8s.io/pod-security-admission/admission/admission_test.go b/staging/src/k8s.io/pod-security-admission/admission/admission_test.go index 26bf4f3ab01..197923ad3cf 100644 --- a/staging/src/k8s.io/pod-security-admission/admission/admission_test.go +++ b/staging/src/k8s.io/pod-security-admission/admission/admission_test.go @@ -38,6 +38,7 @@ import ( "k8s.io/apimachinery/pkg/runtime/schema" "k8s.io/apimachinery/pkg/types" "k8s.io/apimachinery/pkg/util/uuid" + "k8s.io/klog/v2/ktesting" admissionapi "k8s.io/pod-security-admission/admission/api" "k8s.io/pod-security-admission/admission/api/load" "k8s.io/pod-security-admission/api" @@ -504,6 +505,7 @@ func TestValidateNamespace(t *testing.T) { for _, tc := range testcases { t.Run(tc.name, func(t *testing.T) { + _, ctx := ktesting.NewTestContext(t) newObject := &corev1.Namespace{ ObjectMeta: metav1.ObjectMeta{ Name: "test", @@ -587,7 +589,7 @@ func TestValidateNamespace(t *testing.T) { namespacePodCheckTimeout: time.Second, namespaceMaxPodsToCheck: 4, } - result := a.ValidateNamespace(context.TODO(), attrs) + result := a.ValidateNamespace(ctx, attrs) if result.Allowed != tc.expectAllowed { t.Errorf("expected allowed=%v, got %v", tc.expectAllowed, result.Allowed) } @@ -960,6 +962,7 @@ func TestValidatePodAndController(t *testing.T) { for _, tc := range testCases { t.Run(tc.desc, func(t *testing.T) { + _, ctx := ktesting.NewTestContext(t) if tc.obj != nil { tc.obj.(metav1.ObjectMetaAccessor).GetObjectMeta().SetNamespace(tc.namespace) } @@ -999,7 +1002,7 @@ func TestValidatePodAndController(t *testing.T) { require.NoError(t, a.CompleteConfiguration(), "CompleteConfiguration()") require.NoError(t, a.ValidateConfiguration(), "ValidateConfiguration()") - response := a.Validate(context.TODO(), attrs) + response := a.Validate(ctx, attrs) var expectedEvaluations []MetricsRecord var expectedAuditAnnotationKeys []string diff --git a/staging/src/k8s.io/pod-security-admission/cmd/webhook/server/server.go b/staging/src/k8s.io/pod-security-admission/cmd/webhook/server/server.go index bcd2420a2a0..524602fb281 100644 --- a/staging/src/k8s.io/pod-security-admission/cmd/webhook/server/server.go +++ b/staging/src/k8s.io/pod-security-admission/cmd/webhook/server/server.go @@ -112,6 +112,7 @@ type Server struct { func (s *Server) Start(ctx context.Context) error { s.informerFactory.Start(ctx.Done()) + logger := klog.FromContext(ctx) mux := http.NewServeMux() healthz.InstallHandler(mux, healthz.PingHealthz) @@ -141,11 +142,11 @@ func (s *Server) Start(ctx context.Context) error { } <-listenerStoppedCh - klog.V(1).InfoS("[graceful-termination] HTTP Server has stopped listening") + logger.V(1).Info("[graceful-termination] HTTP Server has stopped listening") // Wait for graceful shutdown. <-shutdownCh - klog.V(1).Info("[graceful-termination] HTTP Server is exiting") + logger.V(1).Info("[graceful-termination] HTTP Server is exiting") return nil } @@ -157,14 +158,15 @@ func (s *Server) HandleValidate(w http.ResponseWriter, r *http.Request) { }) var ( - body []byte - err error - ctx = r.Context() + body []byte + err error + ctx = r.Context() + logger = klog.FromContext(ctx) ) if timeout, ok, err := parseTimeout(r); err != nil { // Ignore an invalid timeout. - klog.V(2).InfoS("Invalid timeout", "error", err) + logger.V(2).Info("Invalid timeout", "error", err) } else if ok { var cancel context.CancelFunc ctx, cancel = context.WithTimeout(ctx, timeout) @@ -173,7 +175,7 @@ func (s *Server) HandleValidate(w http.ResponseWriter, r *http.Request) { if r.Body == nil || r.Body == http.NoBody { err = errors.New("request body is empty") - klog.ErrorS(err, "bad request") + logger.Error(err, "bad request") http.Error(w, err.Error(), http.StatusBadRequest) return } @@ -181,12 +183,12 @@ func (s *Server) HandleValidate(w http.ResponseWriter, r *http.Request) { defer r.Body.Close() limitedReader := &io.LimitedReader{R: r.Body, N: maxRequestSize} if body, err = ioutil.ReadAll(limitedReader); err != nil { - klog.ErrorS(err, "unable to read the body from the incoming request") + logger.Error(err, "unable to read the body from the incoming request") http.Error(w, "unable to read the body from the incoming request", http.StatusBadRequest) return } if limitedReader.N <= 0 { - klog.ErrorS(err, "unable to read the body from the incoming request; limit reached") + logger.Error(err, "unable to read the body from the incoming request; limit reached") http.Error(w, fmt.Sprintf("request entity is too large; limit is %d bytes", maxRequestSize), http.StatusRequestEntityTooLarge) return } @@ -194,7 +196,7 @@ func (s *Server) HandleValidate(w http.ResponseWriter, r *http.Request) { // verify the content type is accurate if contentType := r.Header.Get("Content-Type"); contentType != "application/json" { err = fmt.Errorf("contentType=%s, expected application/json", contentType) - klog.ErrorS(err, "unable to process a request with an unknown content type", "contentType", contentType) + logger.Error(err, "unable to process a request with an unknown content type", "type", contentType) http.Error(w, "unable to process a request with a non-json content type", http.StatusBadRequest) return } @@ -202,21 +204,21 @@ func (s *Server) HandleValidate(w http.ResponseWriter, r *http.Request) { v1AdmissionReviewKind := admissionv1.SchemeGroupVersion.WithKind("AdmissionReview") reviewObject, gvk, err := codecs.UniversalDeserializer().Decode(body, &v1AdmissionReviewKind, nil) if err != nil { - klog.ErrorS(err, "unable to decode the request") + logger.Error(err, "unable to decode the request") http.Error(w, "unable to decode the request", http.StatusBadRequest) return } if *gvk != v1AdmissionReviewKind { - klog.InfoS("Unexpected AdmissionReview kind", "kind", gvk.String()) + logger.Info("Unexpected AdmissionReview kind", "kind", gvk.String()) http.Error(w, fmt.Sprintf("unexpected AdmissionReview kind: %s", gvk.String()), http.StatusBadRequest) return } review, ok := reviewObject.(*admissionv1.AdmissionReview) if !ok { - klog.InfoS("Failed admissionv1.AdmissionReview type assertion") + logger.Info("Failed admissionv1.AdmissionReview type assertion") http.Error(w, "unexpected AdmissionReview type", http.StatusBadRequest) } - klog.V(1).InfoS("received request", "UID", review.Request.UID, "kind", review.Request.Kind, "resource", review.Request.Resource) + logger.V(1).Info("received request", "UID", review.Request.UID, "kind", review.Request.Kind, "resource", review.Request.Resource) attributes := api.RequestAttributes(review.Request, codecs.UniversalDeserializer()) response := s.delegate.Validate(ctx, attributes)