✨ Pass webhook logger to handler via context (#1972)

* ✨ Pass webhook logger to handler via context

* Add namespace and name field

* Allow configuring LogConstructor in webhook builder

Author: timebertt

examples/builtins/mutatingwebhook.go

@@ -22,7 +22,9 @@ import (
 	"net/http"
 
 	corev1 "k8s.io/api/core/v1"
+
 	"sigs.k8s.io/controller-runtime/pkg/client"
+	logf "sigs.k8s.io/controller-runtime/pkg/log"
 	"sigs.k8s.io/controller-runtime/pkg/webhook/admission"
 )
 
@@ -36,8 +38,10 @@ type podAnnotator struct {
 
 // podAnnotator adds an annotation to every incoming pods.
 func (a *podAnnotator) Handle(ctx context.Context, req admission.Request) admission.Response {
-	pod := &corev1.Pod{}
+	// set up a convenient log object so we don't have to type request over and over again
+	log := logf.FromContext(ctx)
 
+	pod := &corev1.Pod{}
 	err := a.decoder.Decode(req, pod)
 	if err != nil {
 		return admission.Errored(http.StatusBadRequest, err)
@@ -52,6 +56,7 @@ func (a *podAnnotator) Handle(ctx context.Context, req admission.Request) admiss
 	if err != nil {
 		return admission.Errored(http.StatusInternalServerError, err)
 	}
+	log.Info("Annotating Pod")
 
 	return admission.PatchResponseFromRaw(req.Object.Raw, marshaledPod)
 }

examples/builtins/validatingwebhook.go

@@ -22,7 +22,9 @@ import (
 	"net/http"
 
 	corev1 "k8s.io/api/core/v1"
+
 	"sigs.k8s.io/controller-runtime/pkg/client"
+	logf "sigs.k8s.io/controller-runtime/pkg/log"
 	"sigs.k8s.io/controller-runtime/pkg/webhook/admission"
 )
 
@@ -36,13 +38,17 @@ type podValidator struct {
 
 // podValidator admits a pod if a specific annotation exists.
 func (v *podValidator) Handle(ctx context.Context, req admission.Request) admission.Response {
-	pod := &corev1.Pod{}
+	// set up a convenient log object so we don't have to type request over and over again
+	log := logf.FromContext(ctx)
 
+	pod := &corev1.Pod{}
 	err := v.decoder.Decode(req, pod)
 	if err != nil {
 		return admission.Errored(http.StatusBadRequest, err)
 	}
 
+	log.Info("Validating Pod")
+
 	key := "example-mutating-admission-webhook"
 	anno, found := pod.Annotations[key]
 	if !found {

pkg/builder/webhook.go

@@ -22,9 +22,12 @@ import (
 	"net/url"
 	"strings"
 
+	"github.com/go-logr/logr"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/runtime/schema"
 	"k8s.io/client-go/rest"
+	"k8s.io/klog/v2"
+
 	"sigs.k8s.io/controller-runtime/pkg/client/apiutil"
 	"sigs.k8s.io/controller-runtime/pkg/manager"
 	"sigs.k8s.io/controller-runtime/pkg/webhook/admission"
@@ -33,13 +36,14 @@ import (
 
 // WebhookBuilder builds a Webhook.
 type WebhookBuilder struct {
-	apiType       runtime.Object
-	withDefaulter admission.CustomDefaulter
-	withValidator admission.CustomValidator
-	gvk           schema.GroupVersionKind
-	mgr           manager.Manager
-	config        *rest.Config
-	recoverPanic  bool
+	apiType        runtime.Object
+	withDefaulter  admission.CustomDefaulter
+	withValidator  admission.CustomValidator
+	gvk            schema.GroupVersionKind
+	mgr            manager.Manager
+	config         *rest.Config
+	recoverPanic   bool
+	logConstructor func(base logr.Logger, req *admission.Request) logr.Logger
 }
 
 // WebhookManagedBy allows inform its manager.Manager.
@@ -69,6 +73,12 @@ func (blder *WebhookBuilder) WithValidator(validator admission.CustomValidator)
 	return blder
 }
 
+// WithLogConstructor overrides the webhook's LogConstructor.
+func (blder *WebhookBuilder) WithLogConstructor(logConstructor func(base logr.Logger, req *admission.Request) logr.Logger) *WebhookBuilder {
+	blder.logConstructor = logConstructor
+	return blder
+}
+
 // RecoverPanic indicates whether the panic caused by webhook should be recovered.
 func (blder *WebhookBuilder) RecoverPanic() *WebhookBuilder {
 	blder.recoverPanic = true
@@ -80,6 +90,9 @@ func (blder *WebhookBuilder) Complete() error {
 	// Set the Config
 	blder.loadRestConfig()
 
+	// Configure the default LogConstructor
+	blder.setLogConstructor()
+
 	// Set the Webhook if needed
 	return blder.registerWebhooks()
 }
@@ -90,6 +103,25 @@ func (blder *WebhookBuilder) loadRestConfig() {
 	}
 }
 
+func (blder *WebhookBuilder) setLogConstructor() {
+	if blder.logConstructor == nil {
+		blder.logConstructor = func(base logr.Logger, req *admission.Request) logr.Logger {
+			log := base.WithValues(
+				"webhookGroup", blder.gvk.Group,
+				"webhookKind", blder.gvk.Kind,
+			)
+			if req != nil {
+				return log.WithValues(
+					blder.gvk.Kind, klog.KRef(req.Namespace, req.Name),
+					"namespace", req.Namespace, "name", req.Name,
+					"resource", req.Resource, "user", req.UserInfo.Username,
+				)
+			}
+			return log
+		}
+	}
+}
+
 func (blder *WebhookBuilder) registerWebhooks() error {
 	typ, err := blder.getType()
 	if err != nil {
@@ -116,6 +148,7 @@ func (blder *WebhookBuilder) registerWebhooks() error {
 func (blder *WebhookBuilder) registerDefaultingWebhook() {
 	mwh := blder.getDefaultingWebhook()
 	if mwh != nil {
+		mwh.LogConstructor = blder.logConstructor
 		path := generateMutatePath(blder.gvk)
 
 		// Checking if the path is already registered.
@@ -145,6 +178,7 @@ func (blder *WebhookBuilder) getDefaultingWebhook() *admission.Webhook {
 func (blder *WebhookBuilder) registerValidatingWebhook() {
 	vwh := blder.getValidatingWebhook()
 	if vwh != nil {
+		vwh.LogConstructor = blder.logConstructor
 		path := generateValidatePath(blder.gvk)
 
 		// Checking if the path is already registered.

pkg/builder/webhook_test.go

@@ -20,18 +20,23 @@ import (
 	"context"
 	"errors"
 	"fmt"
+	"io"
 	"net/http"
 	"net/http/httptest"
 	"os"
 	"strings"
 
+	"github.com/go-logr/logr"
 	. "github.com/onsi/ginkgo/v2"
 	. "github.com/onsi/gomega"
+	"github.com/onsi/gomega/gbytes"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/runtime/schema"
 
 	"sigs.k8s.io/controller-runtime/pkg/controller"
+	logf "sigs.k8s.io/controller-runtime/pkg/log"
+	"sigs.k8s.io/controller-runtime/pkg/log/zap"
 	"sigs.k8s.io/controller-runtime/pkg/manager"
 	"sigs.k8s.io/controller-runtime/pkg/scheme"
 	"sigs.k8s.io/controller-runtime/pkg/webhook/admission"
@@ -49,11 +54,17 @@ var _ = Describe("webhook", func() {
 })
 
 func runTests(admissionReviewVersion string) {
-	var stop chan struct{}
+	var (
+		stop          chan struct{}
+		logBuffer     *gbytes.Buffer
+		testingLogger logr.Logger
+	)
 
 	BeforeEach(func() {
 		stop = make(chan struct{})
 		newController = controller.New
+		logBuffer = gbytes.NewBuffer()
+		testingLogger = zap.New(zap.JSONEncoder(), zap.WriteTo(io.MultiWriter(logBuffer, GinkgoWriter)))
 	})
 
 	AfterEach(func() {
@@ -214,6 +225,9 @@ func runTests(admissionReviewVersion string) {
 		err = WebhookManagedBy(m).
 			WithDefaulter(&TestCustomDefaulter{}).
 			For(&TestDefaulter{}).
+			WithLogConstructor(func(base logr.Logger, req *admission.Request) logr.Logger {
+				return admission.DefaultLogConstructor(testingLogger, req)
+			}).
 			Complete()
 		ExpectWithOffset(1, err).NotTo(HaveOccurred())
 		svr := m.GetWebhookServer()
@@ -225,16 +239,17 @@ func runTests(admissionReviewVersion string) {
   "request":{
     "uid":"07e52e8d-4513-11e9-a716-42010a800270",
     "kind":{
-      "group":"",
+      "group":"foo.test.org",
       "version":"v1",
       "kind":"TestDefaulter"
     },
     "resource":{
-      "group":"",
+      "group":"foo.test.org",
       "version":"v1",
       "resource":"testdefaulter"
     },
     "namespace":"default",
+    "name":"foo",
     "operation":"CREATE",
     "object":{
       "replica":1
@@ -263,6 +278,7 @@ func runTests(admissionReviewVersion string) {
 		ExpectWithOffset(1, w.Body).To(ContainSubstring(`"allowed":true`))
 		ExpectWithOffset(1, w.Body).To(ContainSubstring(`"patch":`))
 		ExpectWithOffset(1, w.Body).To(ContainSubstring(`"code":200`))
+		EventuallyWithOffset(1, logBuffer).Should(gbytes.Say(`"msg":"Defaulting object","object":{"name":"foo","namespace":"default"},"namespace":"default","name":"foo","resource":{"group":"foo.test.org","version":"v1","resource":"testdefaulter"},"user":"","requestID":"07e52e8d-4513-11e9-a716-42010a800270"`))
 
 		By("sending a request to a validating webhook path that doesn't exist")
 		path = generateValidatePath(testDefaulterGVK)
@@ -431,6 +447,9 @@ func runTests(admissionReviewVersion string) {
 		err = WebhookManagedBy(m).
 			WithValidator(&TestCustomValidator{}).
 			For(&TestValidator{}).
+			WithLogConstructor(func(base logr.Logger, req *admission.Request) logr.Logger {
+				return admission.DefaultLogConstructor(testingLogger, req)
+			}).
 			Complete()
 		ExpectWithOffset(1, err).NotTo(HaveOccurred())
 		svr := m.GetWebhookServer()
@@ -442,16 +461,17 @@ func runTests(admissionReviewVersion string) {
   "request":{
     "uid":"07e52e8d-4513-11e9-a716-42010a800270",
     "kind":{
-      "group":"",
+      "group":"foo.test.org",
       "version":"v1",
-      "kind":"TestValidator"
+      "kind":"TestDefaulter"
     },
     "resource":{
-      "group":"",
+      "group":"foo.test.org",
       "version":"v1",
-      "resource":"testvalidator"
+      "resource":"testdefaulter"
     },
     "namespace":"default",
+    "name":"foo",
     "operation":"UPDATE",
     "object":{
       "replica":1
@@ -491,6 +511,7 @@ func runTests(admissionReviewVersion string) {
 		By("sanity checking the response contains reasonable field")
 		ExpectWithOffset(1, w.Body).To(ContainSubstring(`"allowed":false`))
 		ExpectWithOffset(1, w.Body).To(ContainSubstring(`"code":403`))
+		EventuallyWithOffset(1, logBuffer).Should(gbytes.Say(`"msg":"Validating object","object":{"name":"foo","namespace":"default"},"namespace":"default","name":"foo","resource":{"group":"foo.test.org","version":"v1","resource":"testdefaulter"},"user":"","requestID":"07e52e8d-4513-11e9-a716-42010a800270"`))
 	})
 
 	It("should scaffold defaulting and validating webhooks if the type implements both Defaulter and Validator interfaces", func() {
@@ -845,6 +866,7 @@ func (dv *TestDefaultValidator) ValidateDelete() error {
 type TestCustomDefaulter struct{}
 
 func (*TestCustomDefaulter) Default(ctx context.Context, obj runtime.Object) error {
+	logf.FromContext(ctx).Info("Defaulting object")
 	req, err := admission.RequestFromContext(ctx)
 	if err != nil {
 		return fmt.Errorf("expected admission.Request in ctx: %w", err)
@@ -867,6 +889,7 @@ var _ admission.CustomDefaulter = &TestCustomDefaulter{}
 type TestCustomValidator struct{}
 
 func (*TestCustomValidator) ValidateCreate(ctx context.Context, obj runtime.Object) error {
+	logf.FromContext(ctx).Info("Validating object")
 	req, err := admission.RequestFromContext(ctx)
 	if err != nil {
 		return fmt.Errorf("expected admission.Request in ctx: %w", err)
@@ -883,6 +906,7 @@ func (*TestCustomValidator) ValidateCreate(ctx context.Context, obj runtime.Obje
 }
 
 func (*TestCustomValidator) ValidateUpdate(ctx context.Context, oldObj, newObj runtime.Object) error {
+	logf.FromContext(ctx).Info("Validating object")
 	req, err := admission.RequestFromContext(ctx)
 	if err != nil {
 		return fmt.Errorf("expected admission.Request in ctx: %w", err)
@@ -903,6 +927,7 @@ func (*TestCustomValidator) ValidateUpdate(ctx context.Context, oldObj, newObj r
 }
 
 func (*TestCustomValidator) ValidateDelete(ctx context.Context, obj runtime.Object) error {
+	logf.FromContext(ctx).Info("Validating object")
 	req, err := admission.RequestFromContext(ctx)
 	if err != nil {
 		return fmt.Errorf("expected admission.Request in ctx: %w", err)

pkg/webhook/admission/defaulter_test.go

@@ -10,13 +10,16 @@ import (
 	admissionv1 "k8s.io/api/admission/v1"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/apimachinery/pkg/runtime/schema"
+
+	"sigs.k8s.io/controller-runtime/pkg/runtime/inject"
 )
 
 var _ = Describe("Defaulter Handler", func() {
 
 	It("should return ok if received delete verb in defaulter handler", func() {
 		obj := &TestDefaulter{}
 		handler := DefaultingWebhookFor(obj)
+		Expect(inject.LoggerInto(log, handler)).To(BeTrue())
 
 		resp := handler.Handle(context.TODO(), Request{
 			AdmissionRequest: admissionv1.AdmissionRequest{

pkg/webhook/admission/http.go

@@ -52,15 +52,15 @@ func (wh *Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	var reviewResponse Response
 	if r.Body == nil {
 		err = errors.New("request body is empty")
-		wh.log.Error(err, "bad request")
+		wh.getLogger(nil).Error(err, "bad request")
 		reviewResponse = Errored(http.StatusBadRequest, err)
 		wh.writeResponse(w, reviewResponse)
 		return
 	}
 
 	defer r.Body.Close()
 	if body, err = io.ReadAll(r.Body); err != nil {
-		wh.log.Error(err, "unable to read the body from the incoming request")
+		wh.getLogger(nil).Error(err, "unable to read the body from the incoming request")
 		reviewResponse = Errored(http.StatusBadRequest, err)
 		wh.writeResponse(w, reviewResponse)
 		return
@@ -69,7 +69,7 @@ func (wh *Webhook) ServeHTTP(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)
-		wh.log.Error(err, "unable to process a request with an unknown content type", "content type", contentType)
+		wh.getLogger(nil).Error(err, "unable to process a request with an unknown content type", "content type", contentType)
 		reviewResponse = Errored(http.StatusBadRequest, err)
 		wh.writeResponse(w, reviewResponse)
 		return
@@ -88,12 +88,12 @@ func (wh *Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	ar.SetGroupVersionKind(v1.SchemeGroupVersion.WithKind("AdmissionReview"))
 	_, actualAdmRevGVK, err := admissionCodecs.UniversalDeserializer().Decode(body, nil, &ar)
 	if err != nil {
-		wh.log.Error(err, "unable to decode the request")
+		wh.getLogger(nil).Error(err, "unable to decode the request")
 		reviewResponse = Errored(http.StatusBadRequest, err)
 		wh.writeResponse(w, reviewResponse)
 		return
 	}
-	wh.log.V(1).Info("received request", "UID", req.UID, "kind", req.Kind, "resource", req.Resource)
+	wh.getLogger(nil).V(1).Info("received request", "UID", req.UID, "kind", req.Kind, "resource", req.Resource)
 
 	reviewResponse = wh.Handle(ctx, req)
 	wh.writeResponseTyped(w, reviewResponse, actualAdmRevGVK)
@@ -124,19 +124,19 @@ func (wh *Webhook) writeResponseTyped(w io.Writer, response Response, admRevGVK
 // writeAdmissionResponse writes ar to w.
 func (wh *Webhook) writeAdmissionResponse(w io.Writer, ar v1.AdmissionReview) {
 	if err := json.NewEncoder(w).Encode(ar); err != nil {
-		wh.log.Error(err, "unable to encode and write the response")
+		wh.getLogger(nil).Error(err, "unable to encode and write the response")
 		// Since the `ar v1.AdmissionReview` is a clear and legal object,
 		// it should not have problem to be marshalled into bytes.
 		// The error here is probably caused by the abnormal HTTP connection,
 		// e.g., broken pipe, so we can only write the error response once,
 		// to avoid endless circular calling.
 		serverError := Errored(http.StatusInternalServerError, err)
 		if err = json.NewEncoder(w).Encode(v1.AdmissionReview{Response: &serverError.AdmissionResponse}); err != nil {
-			wh.log.Error(err, "still unable to encode and write the InternalServerError response")
+			wh.getLogger(nil).Error(err, "still unable to encode and write the InternalServerError response")
 		}
 	} else {
 		res := ar.Response
-		if log := wh.log; log.V(1).Enabled() {
+		if log := wh.getLogger(nil); log.V(1).Enabled() {
 			if res.Result != nil {
 				log = log.WithValues("code", res.Result.Code, "reason", res.Result.Reason, "message", res.Result.Message)
 			}