Merge pull request #439 from anthonyho007/improve-loggings

✨ Improve webhook loggings

Author: k8s-ci-robot

pkg/webhook/admission/http.go

@@ -81,6 +81,7 @@ func (wh *Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		wh.writeResponse(w, reviewResponse)
 		return
 	}
+	wh.log.V(1).Info("received request", "UID", req.UID, "kind", req.Kind, "resource", req.Resource)
 
 	// TODO: add panic-recovery for Handle
 	reviewResponse = wh.Handle(r.Context(), req)
@@ -96,5 +97,8 @@ func (wh *Webhook) writeResponse(w io.Writer, response Response) {
 	if err != nil {
 		wh.log.Error(err, "unable to encode the response")
 		wh.writeResponse(w, Errored(http.StatusInternalServerError, err))
+	} else {
+		res := responseAdmissionReview.Response
+		wh.log.V(1).Info("wrote response", "UID", res.UID, "allowed", res.Allowed, "result", res.Result)
 	}
 }

pkg/webhook/admission/http_test.go

@@ -30,6 +30,7 @@ import (
 	"sigs.k8s.io/controller-runtime/pkg/runtime/inject"
 
 	admissionv1beta1 "k8s.io/api/admission/v1beta1"
+	logf "sigs.k8s.io/controller-runtime/pkg/internal/log"
 )
 
 var _ = Describe("Admission Webhooks", func() {
@@ -88,6 +89,7 @@ var _ = Describe("Admission Webhooks", func() {
 			}
 			webhook := &Webhook{
 				Handler: &fakeHandler{},
+				log:     logf.RuntimeLog.WithName("webhook"),
 			}
 
 			expected := []byte(`{"response":{"uid":"","allowed":true,"status":{"metadata":{},"code":200}}}
@@ -111,6 +113,7 @@ var _ = Describe("Admission Webhooks", func() {
 						return Allowed(ctx.Value(key).(string))
 					},
 				},
+				log: logf.RuntimeLog.WithName("webhook"),
 			}
 
 			expected := []byte(fmt.Sprintf(`{"response":{"uid":"","allowed":true,"status":{"metadata":{},"reason":%q,"code":200}}}

pkg/webhook/admission/webhook_test.go

@@ -29,6 +29,7 @@ import (
 	"k8s.io/apimachinery/pkg/runtime"
 	machinerytypes "k8s.io/apimachinery/pkg/types"
 
+	logf "sigs.k8s.io/controller-runtime/pkg/internal/log"
 	"sigs.k8s.io/controller-runtime/pkg/runtime/inject"
 )
 
@@ -45,6 +46,7 @@ var _ = Describe("Admission Webhooks", func() {
 		}
 		webhook := &Webhook{
 			Handler: handler,
+			log:     logf.RuntimeLog.WithName("webhook"),
 		}
 
 		return webhook
@@ -94,6 +96,7 @@ var _ = Describe("Admission Webhooks", func() {
 					},
 				}
 			}),
+			log: logf.RuntimeLog.WithName("webhook"),
 		}
 
 		By("invoking the webhook")
@@ -110,6 +113,7 @@ var _ = Describe("Admission Webhooks", func() {
 			Handler: HandlerFunc(func(ctx context.Context, req Request) Response {
 				return Patched("", jsonpatch.Operation{Operation: "add", Path: "/a", Value: 2}, jsonpatch.Operation{Operation: "replace", Path: "/b", Value: 4})
 			}),
+			log: logf.RuntimeLog.WithName("webhook"),
 		}
 
 		By("invoking the webhook")
@@ -135,6 +139,7 @@ var _ = Describe("Admission Webhooks", func() {
 			handler := &fakeHandler{}
 			webhook := &Webhook{
 				Handler: handler,
+				log:     logf.RuntimeLog.WithName("webhook"),
 			}
 			Expect(setFields(webhook)).To(Succeed())
 			Expect(inject.InjectorInto(setFields, webhook)).To(BeTrue())
@@ -154,6 +159,7 @@ var _ = Describe("Admission Webhooks", func() {
 			handler := &fakeHandler{}
 			webhook := &Webhook{
 				Handler: handler,
+				log:     logf.RuntimeLog.WithName("webhook"),
 			}
 			Expect(setFields(webhook)).To(Succeed())
 			Expect(inject.InjectorInto(setFields, webhook)).To(BeTrue())

pkg/webhook/server.go

@@ -106,6 +106,7 @@ func (s *Server) Register(path string, hook http.Handler) {
 	// TODO(directxman12): call setfields if we've already started the server
 	s.webhooks[path] = hook
 	s.WebhookMux.Handle(path, instrumentedHook(path, hook))
+	log.Info("registering webhook", "path", path)
 }
 
 // instrumentedHook adds some instrumentation on top of the given webhook.
@@ -125,6 +126,8 @@ func (s *Server) Start(stop <-chan struct{}) error {
 	s.defaultingOnce.Do(s.setDefaults)
 
 	baseHookLog := log.WithName("webhooks")
+	baseHookLog.Info("starting webhook server")
+
 	// inject fields here as opposed to in Register so that we're certain to have our setFields
 	// function available.
 	for hookPath, webhook := range s.webhooks {
@@ -164,13 +167,16 @@ func (s *Server) Start(stop <-chan struct{}) error {
 		return err
 	}
 
+	log.Info("serving webhook server", "host", s.Host, "port", s.Port)
+
 	srv := &http.Server{
 		Handler: s.WebhookMux,
 	}
 
 	idleConnsClosed := make(chan struct{})
 	go func() {
 		<-stop
+		log.Info("shutting down webhook server")
 
 		// TODO: use a context with reasonable timeout
 		if err := srv.Shutdown(context.Background()); err != nil {