Add per-webhook logging

This gives each webhook a log, so that serving errors can be tied to a
particuluar webhook.

Author: DirectXMan12

example/main.go

@@ -88,8 +88,8 @@ func main() {
 	}
 
 	entryLog.Info("registering webhooks to the webhook server")
-	hookServer.Register("/mutate-pods", webhook.Admission{Handler: &podAnnotator{}})
-	hookServer.Register("/validate-pods", webhook.Admission{Handler: &podValidator{}})
+	hookServer.Register("/mutate-pods", &webhook.Admission{Handler: &podAnnotator{}})
+	hookServer.Register("/validate-pods", &webhook.Admission{Handler: &podValidator{}})
 
 	entryLog.Info("starting manager")
 	if err := mgr.Start(signals.SetupSignalHandler()); err != nil {

pkg/runtime/inject/inject.go

@@ -17,9 +17,11 @@ limitations under the License.
 package inject
 
 import (
+	"github.com/go-logr/logr"
 	"k8s.io/apimachinery/pkg/api/meta"
 	"k8s.io/apimachinery/pkg/runtime"
 	"k8s.io/client-go/rest"
+
 	"sigs.k8s.io/controller-runtime/pkg/cache"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 )
@@ -129,3 +131,18 @@ func InjectorInto(f Func, i interface{}) (bool, error) {
 	}
 	return false, nil
 }
+
+// Logger is used to inject Loggers into components that need them
+// and don't otherwise have opinions.
+type Logger interface {
+	InjectLogger(l logr.Logger) error
+}
+
+// LoggerInto will set the logger on the given object if it implements inject.Logger,
+// returning true if a InjectLogger was called, and false otherwise.
+func LoggerInto(l logr.Logger, i interface{}) (bool, error) {
+	if injectable, wantsLogger := i.(Logger); wantsLogger {
+		return true, injectable.InjectLogger(l)
+	}
+	return false, nil
+}

pkg/webhook/admission/http.go

@@ -41,21 +41,21 @@ func init() {
 
 var _ http.Handler = &Webhook{}
 
-func (wh Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) {
+func (wh *Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	var body []byte
 	var err error
 
 	var reviewResponse Response
 	if r.Body != nil {
 		if body, err = ioutil.ReadAll(r.Body); err != nil {
-			log.Error(err, "unable to read the body from the incoming request")
+			wh.log.Error(err, "unable to read the body from the incoming request")
 			reviewResponse = Errored(http.StatusBadRequest, err)
 			wh.writeResponse(w, reviewResponse)
 			return
 		}
 	} else {
 		err = errors.New("request body is empty")
-		log.Error(err, "bad request")
+		wh.log.Error(err, "bad request")
 		reviewResponse = Errored(http.StatusBadRequest, err)
 		wh.writeResponse(w, reviewResponse)
 		return
@@ -65,7 +65,7 @@ func (wh Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 	contentType := r.Header.Get("Content-Type")
 	if 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.log.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
@@ -77,7 +77,7 @@ func (wh Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		Request: &req.AdmissionRequest,
 	}
 	if _, _, err := admissionCodecs.UniversalDeserializer().Decode(body, nil, &ar); err != nil {
-		log.Error(err, "unable to decode the request")
+		wh.log.Error(err, "unable to decode the request")
 		reviewResponse = Errored(http.StatusBadRequest, err)
 		wh.writeResponse(w, reviewResponse)
 		return
@@ -95,7 +95,7 @@ func (wh *Webhook) writeResponse(w io.Writer, response Response) {
 	}
 	err := encoder.Encode(responseAdmissionReview)
 	if err != nil {
-		log.Error(err, "unable to encode the response")
+		wh.log.Error(err, "unable to encode the response")
 		wh.writeResponse(w, Errored(http.StatusInternalServerError, err))
 	}
 }

pkg/webhook/admission/http_test.go

@@ -26,21 +26,25 @@ import (
 	. "github.com/onsi/ginkgo"
 	. "github.com/onsi/gomega"
 
+	"sigs.k8s.io/controller-runtime/pkg/runtime/inject"
+
 	admissionv1beta1 "k8s.io/api/admission/v1beta1"
 )
 
 var _ = Describe("Admission Webhooks", func() {
 
 	Describe("HTTP Handler", func() {
 		var respRecorder *httptest.ResponseRecorder
+		webhook := &Webhook{
+			Handler: nil,
+		}
 		BeforeEach(func() {
 			respRecorder = &httptest.ResponseRecorder{
 				Body: bytes.NewBuffer(nil),
 			}
+			_, err := inject.LoggerInto(log.WithName("test-webhook"), webhook)
+			Expect(err).NotTo(HaveOccurred())
 		})
-		webhook := &Webhook{
-			Handler: nil,
-		}
 
 		It("should return bad-request when given an empty body", func() {
 			req := &http.Request{Body: nil}

pkg/webhook/admission/webhook.go

@@ -22,6 +22,7 @@ import (
 	"net/http"
 
 	"github.com/appscode/jsonpatch"
+	"github.com/go-logr/logr"
 	admissionv1beta1 "k8s.io/api/admission/v1beta1"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/runtime"
@@ -110,8 +111,16 @@ type Webhook struct {
 	// and potentially patches to apply to the handler.
 	Handler Handler
 
-	// scheme is used to construct the Decoder
+	// decoder is constructed on receiving a scheme and passed down to then handler
 	decoder *Decoder
+
+	log logr.Logger
+}
+
+// InjectLogger gets a handle to a logging instance, hopefully with more info about this particular webhook.
+func (w *Webhook) InjectLogger(l logr.Logger) error {
+	w.log = l
+	return nil
 }
 
 // Handle processes AdmissionRequest.
@@ -121,7 +130,7 @@ type Webhook struct {
 func (w *Webhook) Handle(ctx context.Context, req Request) Response {
 	resp := w.Handler.Handle(ctx, req)
 	if err := resp.Complete(req); err != nil {
-		log.Error(err, "unable to encode response")
+		w.log.Error(err, "unable to encode response")
 		return Errored(http.StatusInternalServerError, errUnableToEncodeResponse)
 	}
 

pkg/webhook/server.go

@@ -111,12 +111,20 @@ func instrumentedHook(path string, hookRaw http.Handler) http.Handler {
 func (s *Server) Start(stop <-chan struct{}) error {
 	s.defaultingOnce.Do(s.setDefaults)
 
+	baseHookLog := log.WithName("webhooks")
 	// inject fields here as opposed to in Register so that we're certain to have our setFields
 	// function available.
-	for _, webhook := range s.webhooks {
+	for hookPath, webhook := range s.webhooks {
 		if err := s.setFields(webhook); err != nil {
 			return err
 		}
+
+		// NB(directxman12): we don't propagate this further by wrapping setFields because it's
+		// unclear if this is how we want to deal with log propagation.  In this specific instance,
+		// we want to be able to pass a logger to webhooks because they don't know their own path.
+		if _, err := inject.LoggerInto(baseHookLog.WithValues("webhook", hookPath), webhook); err != nil {
+			return err
+		}
 	}
 
 	// TODO: watch the cert dir. Reload the cert if it changes