Merge pull request #2419 from sbueringer/pr-add-reconcile-logs

🌱 Add logs around Reconcile call, change webhook logs to log level 5

pkg/internal/controller/controller.go

@@ -28,6 +28,7 @@ import (
 	utilruntime "k8s.io/apimachinery/pkg/util/runtime"
 	"k8s.io/apimachinery/pkg/util/uuid"
 	"k8s.io/client-go/util/workqueue"
+
 	"sigs.k8s.io/controller-runtime/pkg/handler"
 	ctrlmetrics "sigs.k8s.io/controller-runtime/pkg/internal/controller/metrics"
 	logf "sigs.k8s.io/controller-runtime/pkg/log"
@@ -311,6 +312,7 @@ func (c *Controller) reconcileHandler(ctx context.Context, obj interface{}) {
 
 	// RunInformersAndControllers the syncHandler, passing it the Namespace/Name string of the
 	// resource to be synced.
+	log.V(5).Info("Reconciling")
 	result, err := c.Reconcile(ctx, req)
 	switch {
 	case err != nil:
@@ -323,6 +325,7 @@ func (c *Controller) reconcileHandler(ctx context.Context, obj interface{}) {
 		ctrlmetrics.ReconcileTotal.WithLabelValues(c.Name, labelError).Inc()
 		log.Error(err, "Reconciler error")
 	case result.RequeueAfter > 0:
+		log.V(5).Info(fmt.Sprintf("Reconcile done, requeueing after %s", result.RequeueAfter))
 		// The result.RequeueAfter request will be lost, if it is returned
 		// along with a non-nil error. But this is intended as
 		// We need to drive to stable reconcile loops before queuing due
@@ -331,9 +334,11 @@ func (c *Controller) reconcileHandler(ctx context.Context, obj interface{}) {
 		c.Queue.AddAfter(req, result.RequeueAfter)
 		ctrlmetrics.ReconcileTotal.WithLabelValues(c.Name, labelRequeueAfter).Inc()
 	case result.Requeue:
+		log.V(5).Info("Reconcile done, requeueing")
 		c.Queue.AddRateLimited(req)
 		ctrlmetrics.ReconcileTotal.WithLabelValues(c.Name, labelRequeue).Inc()
 	default:
+		log.V(5).Info("Reconcile successful")
 		// Finally, if no error occurs we Forget this item so it does not
 		// get queued again until another change happens.
 		c.Queue.Forget(obj)

pkg/webhook/admission/http.go

@@ -93,7 +93,7 @@ func (wh *Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		wh.writeResponse(w, reviewResponse)
 		return
 	}
-	wh.getLogger(&req).V(4).Info("received request")
+	wh.getLogger(&req).V(5).Info("received request")
 
 	reviewResponse = wh.Handle(ctx, req)
 	wh.writeResponseTyped(w, reviewResponse, actualAdmRevGVK)
@@ -136,11 +136,11 @@ func (wh *Webhook) writeAdmissionResponse(w io.Writer, ar v1.AdmissionReview) {
 		}
 	} else {
 		res := ar.Response
-		if log := wh.getLogger(nil); log.V(4).Enabled() {
+		if log := wh.getLogger(nil); log.V(5).Enabled() {
 			if res.Result != nil {
 				log = log.WithValues("code", res.Result.Code, "reason", res.Result.Reason, "message", res.Result.Message)
 			}
-			log.V(4).Info("wrote response", "requestID", res.UID, "allowed", res.Allowed)
+			log.V(5).Info("wrote response", "requestID", res.UID, "allowed", res.Allowed)
 		}
 	}
 }

pkg/webhook/authentication/http.go

@@ -94,7 +94,7 @@ func (wh *Webhook) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 		wh.writeResponse(w, reviewResponse)
 		return
 	}
-	wh.getLogger(&req).V(4).Info("received request")
+	wh.getLogger(&req).V(5).Info("received request")
 
 	if req.Spec.Token == "" {
 		err = errors.New("token is empty")
@@ -135,7 +135,7 @@ func (wh *Webhook) writeTokenResponse(w io.Writer, ar authenticationv1.TokenRevi
 		wh.writeResponse(w, Errored(err))
 	}
 	res := ar
-	wh.getLogger(nil).V(4).Info("wrote response", "requestID", res.UID, "authenticated", res.Status.Authenticated)
+	wh.getLogger(nil).V(5).Info("wrote response", "requestID", res.UID, "authenticated", res.Status.Authenticated)
 }
 
 // unversionedTokenReview is used to decode both v1 and v1beta1 TokenReview types.