Merge pull request #6 from dbsystel/develop

Improvements for logging

pkg/webhook/facade/api.go

@@ -5,6 +5,8 @@ import (
 	"fmt"
 	"reflect"
 
+	"k8s.io/apimachinery/pkg/types"
+
 	v1 "k8s.io/api/admission/v1"
 	"k8s.io/api/admission/v1beta1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -50,8 +52,10 @@ type AdmissionRequest interface {
 	Object() *runtime.RawExtension
 	// OldObject returns the runtime.RawExtension representing the request old object
 	OldObject() *runtime.RawExtension
-	// Resource returns the metav1.GroupVersionResource for the request object
-	Resource() metav1.GroupVersionResource
+	// ResourceKind returns the metav1.GroupVersionResource for the request object
+	ResourceKind() metav1.GroupVersionResource
+	// ResourceId returns the namespaced name of the requested resource
+	ResourceID() types.NamespacedName
 	// Namespace returns the name of the namespace which is source to this request
 	Namespace() string
 }

pkg/webhook/facade/v1_admission_review.go

@@ -4,6 +4,8 @@ package facade
 import (
 	"encoding/json"
 
+	"k8s.io/apimachinery/pkg/types"
+
 	"github.com/pkg/errors"
 	v1 "k8s.io/api/admission/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -58,6 +60,10 @@ type v1AdmissionReviewRequest struct {
 	target *v1.AdmissionRequest
 }
 
+func (v *v1AdmissionReviewRequest) ResourceID() types.NamespacedName {
+	return types.NamespacedName{Namespace: v.target.Namespace, Name: v.target.Name}
+}
+
 func (v *v1AdmissionReviewRequest) Namespace() string {
 	return v.target.Namespace
 }
@@ -74,7 +80,7 @@ func (v *v1AdmissionReviewRequest) OldObject() *runtime.RawExtension {
 	return &v.target.OldObject
 }
 
-func (v *v1AdmissionReviewRequest) Resource() metav1.GroupVersionResource {
+func (v *v1AdmissionReviewRequest) ResourceKind() metav1.GroupVersionResource {
 	return v.target.Resource
 }
 

pkg/webhook/facade/v1_admission_review_test.go

@@ -9,6 +9,7 @@ import (
 	. "github.com/onsi/gomega"
 	v1 "k8s.io/api/admission/v1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/apimachinery/pkg/types"
 )
 
 var _ = Describe("v1AdmissionReview test", func() {
@@ -35,7 +36,11 @@ var _ = Describe("v1AdmissionReview test", func() {
 		Expect(sut.Request().Kind()).To(BeEquivalentTo(expected.Kind))
 		Expect(sut.Request().Object()).To(BeEquivalentTo(&expected.Object))
 		Expect(sut.Request().OldObject()).To(BeEquivalentTo(&expected.OldObject))
-		Expect(sut.Request().Resource()).To(BeEquivalentTo(expected.Resource))
+		Expect(sut.Request().ResourceKind()).To(BeEquivalentTo(expected.Resource))
+		Expect(sut.Request().ResourceID()).To(BeEquivalentTo(types.NamespacedName{
+			Namespace: admission_test.V1ValidPod().Request.Namespace,
+			Name:      admission_test.V1ValidPod().Request.Name,
+		}))
 		Expect(sut.Request().Namespace()).To(BeEquivalentTo(expected.Namespace))
 		Expect(sut.Response().ResponseType()).To(Equal(facade.AdmissionError))
 	})

pkg/webhook/facade/v1beta1_admission_review.go

@@ -4,6 +4,8 @@ package facade
 import (
 	"encoding/json"
 
+	"k8s.io/apimachinery/pkg/types"
+
 	"github.com/pkg/errors"
 	"k8s.io/api/admission/v1beta1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
@@ -58,6 +60,10 @@ type v1beta1AdmissionReviewRequest struct {
 	target *v1beta1.AdmissionRequest
 }
 
+func (v *v1beta1AdmissionReviewRequest) ResourceID() types.NamespacedName {
+	return types.NamespacedName{Namespace: v.target.Namespace, Name: v.target.Name}
+}
+
 func (v *v1beta1AdmissionReviewRequest) Namespace() string {
 	return v.target.Namespace
 }
@@ -74,7 +80,7 @@ func (v *v1beta1AdmissionReviewRequest) OldObject() *runtime.RawExtension {
 	return &v.target.OldObject
 }
 
-func (v *v1beta1AdmissionReviewRequest) Resource() metav1.GroupVersionResource {
+func (v *v1beta1AdmissionReviewRequest) ResourceKind() metav1.GroupVersionResource {
 	return v.target.Resource
 }
 

pkg/webhook/facade/v1beta1_admission_review_test.go

@@ -9,6 +9,7 @@ import (
 	. "github.com/onsi/gomega"
 	"k8s.io/api/admission/v1beta1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/apimachinery/pkg/types"
 )
 
 var _ = Describe("v1beta1AdmissionReview test", func() {
@@ -35,7 +36,11 @@ var _ = Describe("v1beta1AdmissionReview test", func() {
 		Expect(sut.Request().Kind()).To(BeEquivalentTo(expected.Kind))
 		Expect(sut.Request().Object()).To(BeEquivalentTo(&expected.Object))
 		Expect(sut.Request().OldObject()).To(BeEquivalentTo(&expected.OldObject))
-		Expect(sut.Request().Resource()).To(BeEquivalentTo(expected.Resource))
+		Expect(sut.Request().ResourceKind()).To(BeEquivalentTo(expected.Resource))
+		Expect(sut.Request().ResourceID()).To(BeEquivalentTo(types.NamespacedName{
+			Namespace: admission_test.V1ValidPod().Request.Namespace,
+			Name:      admission_test.V1ValidPod().Request.Name,
+		}))
 		Expect(sut.Request().Namespace()).To(BeEquivalentTo(expected.Namespace))
 		Expect(sut.Response().ResponseType()).To(Equal(facade.AdmissionError))
 	})

pkg/webhook/handler/api.go

@@ -25,7 +25,7 @@ const (
 type AdmissionReview interface {
 	// HandleReview handles the facade.AdmissionReview using the logr.Logger
 	HandleReview(logger logr.Logger, review facade.AdmissionReview) error
-	// Type returns the Type to identify the web hook
+	// HandlerType returns the Type to identify the web hook
 	HandlerType() Type
 }
 

pkg/webhook/handler/mutator.go

@@ -25,16 +25,16 @@ func (m *mutatorImpl) HandlerType() Type {
 func (m *mutatorImpl) HandleReview(logger logr.Logger, review facade.AdmissionReview) error {
 	request := review.Request()
 
-	verboseLogger := logger.V(1)
-	verboseLogger.Info("mutation hook start", "resource", request.Resource())
+	verboseLogger := logger.V(1).WithValues("kind", request.ResourceKind(), "id", request.ResourceID())
+	verboseLogger.Info("mutation hook start")
 	if err := m.unmarshaller.HandleReview(logger, review); err != nil {
 		return errors.Wrap(err, "unable to handle request object")
 	}
 
 	object, oldObject := request.Object().Object, request.OldObject().Object
 
 	if object == nil && oldObject == nil {
-		logger.Info("mutation hook skipped, object type not registered", "resource", request.Resource())
+		logger.Info("mutation hook skipped, object type not registered")
 		return nil
 	}
 
@@ -47,11 +47,11 @@ func (m *mutatorImpl) HandleReview(logger logr.Logger, review facade.AdmissionRe
 	review.Response().Allow()
 
 	if len(patchBytes) > 0 {
-		logger.Info("admission review was patched", "resource", request.Resource(), "patch", string(patchBytes))
+		logger.Info("admission review was patched", "patch", string(patchBytes))
 		review.Response().PatchJSON(patchBytes)
 	}
 
-	verboseLogger.Info("mutation hook complete", "resource", request.Resource())
+	verboseLogger.Info("mutation hook complete")
 	return nil
 }
 

pkg/webhook/handler/validator.go

@@ -26,16 +26,16 @@ func (v *validatorImpl) HandlerType() Type {
 
 func (v *validatorImpl) HandleReview(logger logr.Logger, review facade.AdmissionReview) error {
 	request := review.Request()
-	verboseLogger := logger.V(1)
-	verboseLogger.Info("validation hook start", "resource", request.Resource())
+	verboseLogger := logger.V(1).WithValues("kind", request.ResourceKind(), "id", request.ResourceID())
+	verboseLogger.Info("validation hook start")
 	if err := v.unmarshaller.HandleReview(logger, review); err != nil {
 		return errors.Wrap(err, "unable to handle request object")
 	}
 
 	object, oldObject := request.Object().Object, request.OldObject().Object
 
 	if object == nil {
-		logger.Info("validation hook skipped, object type not registered", "resource", request.Resource())
+		logger.Info("validation hook skipped, object type not registered")
 		return nil
 	}
 
@@ -46,15 +46,15 @@ func (v *validatorImpl) HandleReview(logger logr.Logger, review facade.Admission
 	}
 	// Handle valid status
 	if len(failures) == 0 {
-		verboseLogger.Info("validation hook allowed the request", "resource", request.Resource())
+		verboseLogger.Info("validation hook allowed the request")
 		review.Response().Allow()
 		return nil
 	}
 	// Convert the fail into a status
 	status := v.convertFailuresToStatus(object, failures)
-	logger.Info("validation hook denied the request", "resource", request.Resource())
+	logger.Info("validation hook denied the request")
 	review.Response().Deny(status)
-	verboseLogger.Info("validation hook complete", "resource", request.Resource())
+	verboseLogger.Info("validation hook complete")
 	return nil
 }
 

pkg/webhook/server.go

@@ -53,29 +53,37 @@ func (s *Server) AddMutator(mutators ...mutation.Mutator) error {
 func (s *Server) HandleAdmissionReview(path string, admRevHandler handler.AdmissionReview, summary metering.Summary) {
 	// Add a handler function
 	s.HandleExt(path, func(writer httpext.ResponseWriter, request *httpext.Request) {
+		logger := request.Logger().V(1).WithValues("path", path, "handler", admRevHandler.HandlerType())
+		logger.Info("reading admission review")
 		review := s.readAdmissionReview(writer, request)
 		if review == nil {
+			logger.Info("no review provided")
 			return
 		}
 
 		// Ensure we meter a handled request
 		finishMetering := s.startMetering(summary, review, writer)
 		defer finishMetering()
 
+		logger.Info("handling review")
 		// Delegate the review to the admRevHandler
 		if err := admRevHandler.HandleReview(request.Logger(), review); err != nil {
 			writer.HandleInternalError(errors.Wrap(err, "review handler failed"))
 			return
 		}
 
+		logger.Info("removing request part of review and sending response")
+
 		// Clear out the request
 		review.ClearRequest()
-
 		// Send the response
 		bytes, err := review.Marshal()
 		if err != nil {
+			logger.Error(err, "response could not be marshalled")
 			writer.HandleInternalError(errors.Wrap(err, "response review cannot be marshaled"))
+			return
 		}
+		logger.Info("sending response", "size", len(bytes))
 		writer.SendJSONBytes(http.StatusOK, bytes)
 	})
 }