Rework logger and pass *Request pointer in webhook/authentication

Signed-off-by: Vince Prignano <[email protected]>

Author: vincepri

examples/tokenreview/tokenreview.go

@@ -29,7 +29,7 @@ type authenticator struct {
 }
 
 // authenticator admits a request by the token.
-func (a *authenticator) Handle(ctx context.Context, req authentication.Request) authentication.Response {
+func (a *authenticator) Handle(ctx context.Context, req *authentication.Request) authentication.Response {
 	if req.Spec.Token == "invalid" {
 		return authentication.Unauthenticated("invalid is an invalid token", v1.UserInfo{})
 	}

pkg/webhook/admission/webhook_test.go

@@ -31,7 +31,6 @@ import (
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	machinerytypes "k8s.io/apimachinery/pkg/types"
 
-	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"
 )
@@ -59,7 +58,6 @@ var _ = Describe("Admission Webhooks", func() {
 		}
 		webhook := &Webhook{
 			Handler: handler,
-			log:     internallog.RuntimeLog.WithName("webhook"),
 		}
 
 		return webhook
@@ -109,7 +107,6 @@ var _ = Describe("Admission Webhooks", func() {
 					},
 				}
 			}),
-			log: internallog.RuntimeLog.WithName("webhook"),
 		}
 
 		By("invoking the webhook")
@@ -126,7 +123,6 @@ 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: internallog.RuntimeLog.WithName("webhook"),
 		}
 
 		By("invoking the webhook")
@@ -213,7 +209,6 @@ var _ = Describe("Admission Webhooks", func() {
 				webhook := &Webhook{
 					Handler:      handler,
 					RecoverPanic: true,
-					log:          internallog.RuntimeLog.WithName("webhook"),
 				}
 
 				return webhook
@@ -240,7 +235,6 @@ var _ = Describe("Admission Webhooks", func() {
 				}
 				webhook := &Webhook{
 					Handler: handler,
-					log:     internallog.RuntimeLog.WithName("webhook"),
 				}
 
 				return webhook

pkg/webhook/authentication/doc.go

@@ -21,9 +21,3 @@ methods to implement authentication webhook handlers.
 See examples/tokenreview/ for an example of authentication webhooks.
 */
 package authentication
-
-import (
-	logf "sigs.k8s.io/controller-runtime/pkg/internal/log"
-)
-
-var log = logf.RuntimeLog.WithName("authentication")

pkg/webhook/authentication/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")
-		log.Error(err, "bad request")
+		wh.getLogger(nil).Error(err, "bad request")
 		reviewResponse = Errored(err)
 		wh.writeResponse(w, reviewResponse)
 		return
 	}
 
 	defer r.Body.Close()
 	if body, err = io.ReadAll(r.Body); err != nil {
-		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(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)
-		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(err)
 		wh.writeResponse(w, reviewResponse)
 		return
@@ -82,23 +82,23 @@ func (wh *Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	// unregistered type to the v1 GVK, the decoder will coerce a v1beta1 TokenReview to authenticationv1.
 	// The actual TokenReview GVK will be used to write a typed response in case the
 	// webhook config permits multiple versions, otherwise this response will fail.
-	req := Request{}
+	req := new(Request)
 	ar := unversionedTokenReview{}
 	// avoid an extra copy
 	ar.TokenReview = &req.TokenReview
 	ar.SetGroupVersionKind(authenticationv1.SchemeGroupVersion.WithKind("TokenReview"))
 	_, actualTokRevGVK, err := authenticationCodecs.UniversalDeserializer().Decode(body, nil, &ar)
 	if err != nil {
-		log.Error(err, "unable to decode the request")
+		wh.getLogger(req).Error(err, "unable to decode the request")
 		reviewResponse = Errored(err)
 		wh.writeResponse(w, reviewResponse)
 		return
 	}
-	log.V(1).Info("received request", "UID", req.UID, "kind", req.Kind)
+	wh.getLogger(req).V(1).Info("received request", "UID", req.UID, "kind", req.Kind)
 
 	if req.Spec.Token == "" {
 		err = errors.New("token is empty")
-		log.Error(err, "bad request")
+		wh.getLogger(req).Error(err, "bad request")
 		reviewResponse = Errored(err)
 		wh.writeResponse(w, reviewResponse)
 		return
@@ -131,12 +131,12 @@ func (wh *Webhook) writeResponseTyped(w io.Writer, response Response, tokRevGVK
 // writeTokenResponse writes ar to w.
 func (wh *Webhook) writeTokenResponse(w io.Writer, ar authenticationv1.TokenReview) {
 	if err := json.NewEncoder(w).Encode(ar); err != nil {
-		log.Error(err, "unable to encode the response")
+		wh.getLogger(nil).Error(err, "unable to encode the response")
 		wh.writeResponse(w, Errored(err))
 	}
 	res := ar
-	if log.V(1).Enabled() {
-		log.V(1).Info("wrote response", "UID", res.UID, "authenticated", res.Status.Authenticated)
+	if wh.getLogger(nil).V(1).Enabled() {
+		wh.getLogger(nil).V(1).Info("wrote response", "UID", res.UID, "authenticated", res.Status.Authenticated)
 	}
 }
 

pkg/webhook/authentication/http_test.go

@@ -138,7 +138,7 @@ var _ = Describe("Authentication Webhooks", func() {
 			const value = "from-ctx"
 			webhook := &Webhook{
 				Handler: &fakeHandler{
-					fn: func(ctx context.Context, req Request) Response {
+					fn: func(ctx context.Context, req *Request) Response {
 						<-ctx.Done()
 						return Authenticated(ctx.Value(key).(string), authenticationv1.UserInfo{})
 					},
@@ -164,7 +164,7 @@ var _ = Describe("Authentication Webhooks", func() {
 			const key ctxkey = 1
 			webhook := &Webhook{
 				Handler: &fakeHandler{
-					fn: func(ctx context.Context, req Request) Response {
+					fn: func(ctx context.Context, req *Request) Response {
 						return Authenticated(ctx.Value(key).(string), authenticationv1.UserInfo{})
 					},
 				},
@@ -192,10 +192,10 @@ func (nopCloser) Close() error { return nil }
 
 type fakeHandler struct {
 	invoked bool
-	fn      func(context.Context, Request) Response
+	fn      func(context.Context, *Request) Response
 }
 
-func (h *fakeHandler) Handle(ctx context.Context, req Request) Response {
+func (h *fakeHandler) Handle(ctx context.Context, req *Request) Response {
 	h.invoked = true
 	if h.fn != nil {
 		return h.fn(ctx, req)

pkg/webhook/authentication/webhook.go

@@ -20,8 +20,13 @@ import (
 	"context"
 	"errors"
 	"net/http"
+	"sync"
 
+	"github.com/go-logr/logr"
 	authenticationv1 "k8s.io/api/authentication/v1"
+	"k8s.io/klog/v2"
+
+	logf "sigs.k8s.io/controller-runtime/pkg/log"
 )
 
 var (
@@ -46,7 +51,7 @@ type Response struct {
 
 // Complete populates any fields that are yet to be set in
 // the underlying TokenResponse, It mutates the response.
-func (r *Response) Complete(req Request) error {
+func (r *Response) Complete(req *Request) error {
 	r.UID = req.UID
 
 	return nil
@@ -58,16 +63,16 @@ type Handler interface {
 	//
 	// The supplied context is extracted from the received http.Request, allowing wrapping
 	// http.Handlers to inject values into and control cancelation of downstream request processing.
-	Handle(context.Context, Request) Response
+	Handle(context.Context, *Request) Response
 }
 
 // HandlerFunc implements Handler interface using a single function.
-type HandlerFunc func(context.Context, Request) Response
+type HandlerFunc func(context.Context, *Request) Response
 
 var _ Handler = HandlerFunc(nil)
 
 // Handle process the TokenReview by invoking the underlying function.
-func (f HandlerFunc) Handle(ctx context.Context, req Request) Response {
+func (f HandlerFunc) Handle(ctx context.Context, req *Request) Response {
 	return f(ctx, req)
 }
 
@@ -81,15 +86,40 @@ type Webhook struct {
 	// add any additional information such as passing the request path or
 	// headers thus allowing you to read them from within the handler
 	WithContextFunc func(context.Context, *http.Request) context.Context
+
+	setupLogOnce sync.Once
+	log          logr.Logger
 }
 
 // Handle processes TokenReview.
-func (wh *Webhook) Handle(ctx context.Context, req Request) Response {
+func (wh *Webhook) Handle(ctx context.Context, req *Request) Response {
 	resp := wh.Handler.Handle(ctx, req)
 	if err := resp.Complete(req); err != nil {
-		log.Error(err, "unable to encode response")
+		wh.getLogger(req).Error(err, "unable to encode response")
 		return Errored(errUnableToEncodeResponse)
 	}
 
 	return resp
 }
+
+// getLogger constructs a logger from the injected log and LogConstructor.
+func (wh *Webhook) getLogger(req *Request) logr.Logger {
+	wh.setupLogOnce.Do(func() {
+		if wh.log.GetSink() == nil {
+			wh.log = logf.Log.WithName("authentication")
+		}
+	})
+
+	return logConstructor(wh.log, req)
+}
+
+// logConstructor adds some commonly interesting fields to the given logger.
+func logConstructor(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,
+			"user", req.Status.User.Username,
+		)
+	}
+	return base
+}

pkg/webhook/authentication/webhook_test.go

@@ -30,7 +30,7 @@ import (
 var _ = Describe("Authentication Webhooks", func() {
 	allowHandler := func() *Webhook {
 		handler := &fakeHandler{
-			fn: func(ctx context.Context, req Request) Response {
+			fn: func(ctx context.Context, req *Request) Response {
 				return Response{
 					TokenReview: authenticationv1.TokenReview{
 						Status: authenticationv1.TokenReviewStatus{
@@ -52,7 +52,7 @@ var _ = Describe("Authentication Webhooks", func() {
 		webhook := allowHandler()
 
 		By("invoking the webhook")
-		resp := webhook.Handle(context.Background(), Request{})
+		resp := webhook.Handle(context.Background(), &Request{})
 
 		By("checking that it allowed the request")
 		Expect(resp.Status.Authenticated).To(BeTrue())
@@ -63,7 +63,7 @@ var _ = Describe("Authentication Webhooks", func() {
 		webhook := allowHandler()
 
 		By("invoking the webhook")
-		resp := webhook.Handle(context.Background(), Request{TokenReview: authenticationv1.TokenReview{ObjectMeta: metav1.ObjectMeta{UID: "foobar"}}})
+		resp := webhook.Handle(context.Background(), &Request{TokenReview: authenticationv1.TokenReview{ObjectMeta: metav1.ObjectMeta{UID: "foobar"}}})
 
 		By("checking that the response share's the request's UID")
 		Expect(resp.UID).To(Equal(machinerytypes.UID("foobar")))
@@ -74,7 +74,7 @@ var _ = Describe("Authentication Webhooks", func() {
 		webhook := allowHandler()
 
 		By("invoking the webhook")
-		resp := webhook.Handle(context.Background(), Request{})
+		resp := webhook.Handle(context.Background(), &Request{})
 
 		By("checking that the response share's the request's UID")
 		Expect(resp.Status).To(Equal(authenticationv1.TokenReviewStatus{Authenticated: true}))
@@ -83,7 +83,7 @@ var _ = Describe("Authentication Webhooks", func() {
 	It("shouldn't overwrite the status on a response", func() {
 		By("setting up a webhook that sets a status")
 		webhook := &Webhook{
-			Handler: HandlerFunc(func(ctx context.Context, req Request) Response {
+			Handler: HandlerFunc(func(ctx context.Context, req *Request) Response {
 				return Response{
 					TokenReview: authenticationv1.TokenReview{
 						Status: authenticationv1.TokenReviewStatus{
@@ -96,7 +96,7 @@ var _ = Describe("Authentication Webhooks", func() {
 		}
 
 		By("invoking the webhook")
-		resp := webhook.Handle(context.Background(), Request{})
+		resp := webhook.Handle(context.Background(), &Request{})
 
 		By("checking that the message is intact")
 		Expect(resp.Status).NotTo(BeNil())