From d4a1690601de76e6e1478020b326ae982f558179 Mon Sep 17 00:00:00 2001 From: Tim Ebert Date: Fri, 20 Jan 2023 17:48:16 +0100 Subject: [PATCH] =?UTF-8?q?=E2=9C=A8=20Pass=20webhook=20logger=20to=20hand?= =?UTF-8?q?ler=20via=20context=20(#1972)?= MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit * ✨ Pass webhook logger to handler via context * Add namespace and name field * Allow configuring LogConstructor in webhook builder --- examples/builtins/mutatingwebhook.go | 7 +- examples/builtins/validatingwebhook.go | 8 +- pkg/builder/webhook.go | 48 ++++++++++-- pkg/builder/webhook_test.go | 39 ++++++++-- pkg/webhook/admission/defaulter_test.go | 3 + pkg/webhook/admission/http.go | 16 ++-- pkg/webhook/admission/webhook.go | 40 +++++++++- pkg/webhook/admission/webhook_test.go | 99 ++++++++++++++++++++++--- 8 files changed, 222 insertions(+), 38 deletions(-) diff --git a/examples/builtins/mutatingwebhook.go b/examples/builtins/mutatingwebhook.go index a4f4eee508..823b620877 100644 --- a/examples/builtins/mutatingwebhook.go +++ b/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) } diff --git a/examples/builtins/validatingwebhook.go b/examples/builtins/validatingwebhook.go index 57bc526574..00b3e94417 100644 --- a/examples/builtins/validatingwebhook.go +++ b/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 { diff --git a/pkg/builder/webhook.go b/pkg/builder/webhook.go index 534e6d64cd..05bb3e2ee9 100644 --- a/pkg/builder/webhook.go +++ b/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. diff --git a/pkg/builder/webhook_test.go b/pkg/builder/webhook_test.go index 3d5f4f1d9a..41d15f1bb4 100644 --- a/pkg/builder/webhook_test.go +++ b/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) diff --git a/pkg/webhook/admission/defaulter_test.go b/pkg/webhook/admission/defaulter_test.go index e9e41f5420..63635c8456 100644 --- a/pkg/webhook/admission/defaulter_test.go +++ b/pkg/webhook/admission/defaulter_test.go @@ -10,6 +10,8 @@ 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() { @@ -17,6 +19,7 @@ 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{ diff --git a/pkg/webhook/admission/http.go b/pkg/webhook/admission/http.go index 750b58708b..c3b7a5cc61 100644 --- a/pkg/webhook/admission/http.go +++ b/pkg/webhook/admission/http.go @@ -52,7 +52,7 @@ 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 @@ -60,7 +60,7 @@ func (wh *Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) { 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,7 +124,7 @@ 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, @@ -132,11 +132,11 @@ func (wh *Webhook) writeAdmissionResponse(w io.Writer, ar v1.AdmissionReview) { // 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) } diff --git a/pkg/webhook/admission/webhook.go b/pkg/webhook/admission/webhook.go index d10b97dddb..dcff043db6 100644 --- a/pkg/webhook/admission/webhook.go +++ b/pkg/webhook/admission/webhook.go @@ -23,15 +23,17 @@ import ( "net/http" "github.com/go-logr/logr" - jsonpatch "gomodules.xyz/jsonpatch/v2" + "gomodules.xyz/jsonpatch/v2" admissionv1 "k8s.io/api/admission/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/runtime" "k8s.io/apimachinery/pkg/util/json" utilruntime "k8s.io/apimachinery/pkg/util/runtime" "k8s.io/client-go/kubernetes/scheme" + "k8s.io/klog/v2" - logf "sigs.k8s.io/controller-runtime/pkg/internal/log" + internallog "sigs.k8s.io/controller-runtime/pkg/internal/log" + logf "sigs.k8s.io/controller-runtime/pkg/log" "sigs.k8s.io/controller-runtime/pkg/runtime/inject" "sigs.k8s.io/controller-runtime/pkg/webhook/internal/metrics" ) @@ -131,6 +133,12 @@ type Webhook struct { // headers thus allowing you to read them from within the handler WithContextFunc func(context.Context, *http.Request) context.Context + // LogConstructor is used to construct a logger for logging messages during webhook calls + // based on the given base logger (which might carry more values like the webhook's path). + // Note: LogConstructor has to be able to handle nil requests as we are also using it + // outside the context of requests. + LogConstructor func(base logr.Logger, req *Request) logr.Logger + // decoder is constructed on receiving a scheme and passed down to then handler decoder *Decoder @@ -166,15 +174,39 @@ func (wh *Webhook) Handle(ctx context.Context, req Request) (response Response) }() } + reqLog := wh.getLogger(&req) + reqLog = reqLog.WithValues("requestID", req.UID) + ctx = logf.IntoContext(ctx, reqLog) + resp := wh.Handler.Handle(ctx, req) if err := resp.Complete(req); err != nil { - wh.log.Error(err, "unable to encode response") + reqLog.Error(err, "unable to encode response") return Errored(http.StatusInternalServerError, errUnableToEncodeResponse) } return resp } +// getLogger constructs a logger from the injected log and LogConstructor. +func (wh *Webhook) getLogger(req *Request) logr.Logger { + logConstructor := wh.LogConstructor + if logConstructor == nil { + logConstructor = DefaultLogConstructor + } + return logConstructor(wh.log, req) +} + +// DefaultLogConstructor adds some commonly interesting fields to the given logger. +func DefaultLogConstructor(base logr.Logger, req *Request) logr.Logger { + if req != nil { + return base.WithValues("object", klog.KRef(req.Namespace, req.Name), + "namespace", req.Namespace, "name", req.Name, + "resource", req.Resource, "user", req.UserInfo.Username, + ) + } + return base +} + // InjectScheme injects a scheme into the webhook, in order to construct a Decoder. func (wh *Webhook) InjectScheme(s *runtime.Scheme) error { // TODO(directxman12): we should have a better way to pass this down @@ -267,7 +299,7 @@ func StandaloneWebhook(hook *Webhook, opts StandaloneOptions) (http.Handler, err } if opts.Logger.GetSink() == nil { - opts.Logger = logf.RuntimeLog.WithName("webhook") + opts.Logger = internallog.RuntimeLog.WithName("webhook") } hook.log = opts.Logger diff --git a/pkg/webhook/admission/webhook_test.go b/pkg/webhook/admission/webhook_test.go index 0868969dd4..6c140d4728 100644 --- a/pkg/webhook/admission/webhook_test.go +++ b/pkg/webhook/admission/webhook_test.go @@ -18,22 +18,37 @@ package admission import ( "context" + "io" "net/http" + "github.com/go-logr/logr" . "github.com/onsi/ginkgo/v2" . "github.com/onsi/gomega" - - jsonpatch "gomodules.xyz/jsonpatch/v2" + "github.com/onsi/gomega/gbytes" + "gomodules.xyz/jsonpatch/v2" admissionv1 "k8s.io/api/admission/v1" + authenticationv1 "k8s.io/api/authentication/v1" metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/runtime" machinerytypes "k8s.io/apimachinery/pkg/types" - logf "sigs.k8s.io/controller-runtime/pkg/internal/log" + internallog "sigs.k8s.io/controller-runtime/pkg/internal/log" + logf "sigs.k8s.io/controller-runtime/pkg/log" + "sigs.k8s.io/controller-runtime/pkg/log/zap" "sigs.k8s.io/controller-runtime/pkg/runtime/inject" ) var _ = Describe("Admission Webhooks", func() { + var ( + logBuffer *gbytes.Buffer + testLogger logr.Logger + ) + + BeforeEach(func() { + logBuffer = gbytes.NewBuffer() + testLogger = zap.New(zap.JSONEncoder(), zap.WriteTo(io.MultiWriter(logBuffer, GinkgoWriter))) + }) + allowHandler := func() *Webhook { handler := &fakeHandler{ fn: func(ctx context.Context, req Request) Response { @@ -46,7 +61,7 @@ var _ = Describe("Admission Webhooks", func() { } webhook := &Webhook{ Handler: handler, - log: logf.RuntimeLog.WithName("webhook"), + log: internallog.RuntimeLog.WithName("webhook"), } return webhook @@ -96,7 +111,7 @@ var _ = Describe("Admission Webhooks", func() { }, } }), - log: logf.RuntimeLog.WithName("webhook"), + log: internallog.RuntimeLog.WithName("webhook"), } By("invoking the webhook") @@ -113,7 +128,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"), + log: internallog.RuntimeLog.WithName("webhook"), } By("invoking the webhook") @@ -125,6 +140,70 @@ var _ = Describe("Admission Webhooks", func() { Expect(resp.Patch).To(Equal([]byte(`[{"op":"add","path":"/a","value":2},{"op":"replace","path":"/b","value":4}]`))) }) + It("should pass a request logger via the context", func() { + By("setting up a webhook that uses the request logger") + webhook := &Webhook{ + Handler: HandlerFunc(func(ctx context.Context, req Request) Response { + logf.FromContext(ctx).Info("Received request") + + return Response{ + AdmissionResponse: admissionv1.AdmissionResponse{ + Allowed: true, + }, + } + }), + log: testLogger, + } + + By("invoking the webhook") + resp := webhook.Handle(context.Background(), Request{AdmissionRequest: admissionv1.AdmissionRequest{ + UID: "test123", + Name: "foo", + Namespace: "bar", + Resource: metav1.GroupVersionResource{ + Group: "apps", + Version: "v1", + Resource: "deployments", + }, + UserInfo: authenticationv1.UserInfo{ + Username: "tim", + }, + }}) + Expect(resp.Allowed).To(BeTrue()) + + By("checking that the log message contains the request fields") + Eventually(logBuffer).Should(gbytes.Say(`"msg":"Received request","object":{"name":"foo","namespace":"bar"},"namespace":"bar","name":"foo","resource":{"group":"apps","version":"v1","resource":"deployments"},"user":"tim","requestID":"test123"}`)) + }) + + It("should pass a request logger created by LogConstructor via the context", func() { + By("setting up a webhook that uses the request logger") + webhook := &Webhook{ + Handler: HandlerFunc(func(ctx context.Context, req Request) Response { + logf.FromContext(ctx).Info("Received request") + + return Response{ + AdmissionResponse: admissionv1.AdmissionResponse{ + Allowed: true, + }, + } + }), + LogConstructor: func(base logr.Logger, req *Request) logr.Logger { + return base.WithValues("operation", req.Operation) + }, + log: testLogger, + } + + By("invoking the webhook") + resp := webhook.Handle(context.Background(), Request{AdmissionRequest: admissionv1.AdmissionRequest{ + UID: "test123", + Operation: admissionv1.Create, + }}) + Expect(resp.Allowed).To(BeTrue()) + + By("checking that the log message contains the request fields") + Eventually(logBuffer).Should(gbytes.Say(`"msg":"Received request","operation":"CREATE","requestID":"test123"}`)) + }) + Describe("dependency injection", func() { It("should set dependencies passed in on the handler", func() { By("setting up a webhook and injecting it with a injection func that injects a string") @@ -139,7 +218,7 @@ var _ = Describe("Admission Webhooks", func() { handler := &fakeHandler{} webhook := &Webhook{ Handler: handler, - log: logf.RuntimeLog.WithName("webhook"), + log: internallog.RuntimeLog.WithName("webhook"), } Expect(setFields(webhook)).To(Succeed()) Expect(inject.InjectorInto(setFields, webhook)).To(BeTrue()) @@ -159,7 +238,7 @@ var _ = Describe("Admission Webhooks", func() { handler := &fakeHandler{} webhook := &Webhook{ Handler: handler, - log: logf.RuntimeLog.WithName("webhook"), + log: internallog.RuntimeLog.WithName("webhook"), } Expect(setFields(webhook)).To(Succeed()) Expect(inject.InjectorInto(setFields, webhook)).To(BeTrue()) @@ -204,7 +283,7 @@ var _ = Describe("Admission Webhooks", func() { webhook := &Webhook{ Handler: handler, RecoverPanic: true, - log: logf.RuntimeLog.WithName("webhook"), + log: internallog.RuntimeLog.WithName("webhook"), } return webhook @@ -231,7 +310,7 @@ var _ = Describe("Admission Webhooks", func() { } webhook := &Webhook{ Handler: handler, - log: logf.RuntimeLog.WithName("webhook"), + log: internallog.RuntimeLog.WithName("webhook"), } return webhook