logging: align to Kubernetes structured logging, add reconcileID

Signed-off-by: Stefan Büringer buringerst@vmware.com

pkg/builder/controller.go

@@ -308,9 +308,8 @@ func (blder *Builder) doController(r reconcile.Reconciler) error {
 	if ctrlOptions.Log.GetSink() == nil {
 		ctrlOptions.Log = blder.mgr.GetLogger()
 	}
-	ctrlOptions.Log = ctrlOptions.Log.WithValues("reconciler group", gvk.Group, "reconciler kind", gvk.Kind)
 
 	// Build the controller and return.
-	blder.ctrl, err = newController(blder.getControllerName(gvk), blder.mgr, ctrlOptions)
+	blder.ctrl, err = newController(blder.getControllerName(gvk), &gvk, blder.mgr, ctrlOptions)
 	return err
 }

pkg/controller/controller.go

@@ -18,10 +18,14 @@ package controller
 
 import (
 	"context"
+	crand "crypto/rand"
+	"encoding/binary"
 	"fmt"
+	"math/rand"
 	"time"
 
 	"github.com/go-logr/logr"
+	"k8s.io/apimachinery/pkg/runtime/schema"
 	"k8s.io/client-go/util/workqueue"
 
 	"sigs.k8s.io/controller-runtime/pkg/handler"
@@ -84,8 +88,8 @@ type Controller interface {
 
 // New returns a new Controller registered with the Manager.  The Manager will ensure that shared Caches have
 // been synced before the Controller is Started.
-func New(name string, mgr manager.Manager, options Options) (Controller, error) {
-	c, err := NewUnmanaged(name, mgr, options)
+func New(name string, gvk *schema.GroupVersionKind, mgr manager.Manager, options Options) (Controller, error) {
+	c, err := NewUnmanaged(name, gvk, mgr, options)
 	if err != nil {
 		return nil, err
 	}
@@ -96,7 +100,7 @@ func New(name string, mgr manager.Manager, options Options) (Controller, error)
 
 // NewUnmanaged returns a new controller without adding it to the manager. The
 // caller is responsible for starting the returned controller.
-func NewUnmanaged(name string, mgr manager.Manager, options Options) (Controller, error) {
+func NewUnmanaged(name string, gvk *schema.GroupVersionKind, mgr manager.Manager, options Options) (Controller, error) {
 	if options.Reconciler == nil {
 		return nil, fmt.Errorf("must specify Reconciler")
 	}
@@ -126,6 +130,19 @@ func NewUnmanaged(name string, mgr manager.Manager, options Options) (Controller
 		return nil, err
 	}
 
+	// Add controller and reconciler group / kind to logger.
+	log := options.Log.WithValues("controller", name)
+	if gvk != nil {
+		log = log.WithValues("reconciler group", gvk.Group, "reconciler kind", gvk.Kind)
+	}
+
+	// Initialize random source, later used to generate reconcileIDs.
+	var rngSeed int64
+	if err := binary.Read(crand.Reader, binary.LittleEndian, &rngSeed); err != nil {
+		return nil, fmt.Errorf("could not read random bytes to seed random source for reconcileID generation: %v", err)
+	}
+	randSource := rand.New(rand.NewSource(rngSeed))
+
 	// Create controller with dependencies set
 	return &controller.Controller{
 		Do: options.Reconciler,
@@ -136,7 +153,9 @@ func NewUnmanaged(name string, mgr manager.Manager, options Options) (Controller
 		CacheSyncTimeout:        options.CacheSyncTimeout,
 		SetFields:               mgr.SetFields,
 		Name:                    name,
-		Log:                     options.Log.WithName("controller").WithName(name).WithValues("controller", name),
+		GVK:                     gvk,
+		Log:                     log,
+		RandSource:              randSource,
 		RecoverPanic:            options.RecoverPanic,
 	}, nil
 }

pkg/internal/controller/controller.go

@@ -18,14 +18,19 @@ package controller
 
 import (
 	"context"
+	"encoding/hex"
 	"errors"
 	"fmt"
+	"math/rand"
+	"strings"
 	"sync"
 	"time"
 
 	"github.com/go-logr/logr"
+	"k8s.io/apimachinery/pkg/runtime/schema"
 	utilruntime "k8s.io/apimachinery/pkg/util/runtime"
 	"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"
@@ -86,6 +91,13 @@ type Controller struct {
 	// Log is used to log messages to users during reconciliation, or for example when a watch is started.
 	Log logr.Logger
 
+	// RandSource is used to generate reconcileIDs for logging.
+	RandSource *rand.Rand
+
+	// GVK is used to create the log key for the object.
+	// If not set, "obj" is used instead.
+	GVK *schema.GroupVersionKind
+
 	// RecoverPanic indicates whether the panic caused by reconcile should be recovered.
 	RecoverPanic bool
 }
@@ -99,7 +111,6 @@ type watchDescription struct {
 
 // Reconcile implements reconcile.Reconciler.
 func (c *Controller) Reconcile(ctx context.Context, req reconcile.Request) (_ reconcile.Result, err error) {
-	log := c.Log.WithValues("name", req.Name, "namespace", req.Namespace)
 	defer func() {
 		if r := recover(); r != nil {
 			if c.RecoverPanic {
@@ -110,11 +121,11 @@ func (c *Controller) Reconcile(ctx context.Context, req reconcile.Request) (_ re
 				return
 			}
 
+			log := logf.FromContext(ctx)
 			log.Info(fmt.Sprintf("Observed a panic in reconciler: %v", r))
 			panic(r)
 		}
 	}()
-	ctx = logf.IntoContext(ctx, log)
 	return c.Do.Reconcile(ctx, req)
 }
 
@@ -295,7 +306,7 @@ func (c *Controller) reconcileHandler(ctx context.Context, obj interface{}) {
 		c.updateMetrics(time.Since(reconcileStartTS))
 	}()
 
-	// Make sure that the the object is a valid request.
+	// Make sure that the object is a valid request.
 	req, ok := obj.(reconcile.Request)
 	if !ok {
 		// As the item in the workqueue is actually invalid, we call
@@ -307,7 +318,24 @@ func (c *Controller) reconcileHandler(ctx context.Context, obj interface{}) {
 		return
 	}
 
-	log := c.Log.WithValues("name", req.Name, "namespace", req.Namespace)
+	// Add object to the logger.
+	var objectLogKey = "obj"
+	if c.GVK != nil {
+		objectLogKey = strings.ToLower(c.GVK.Kind)
+	}
+	log := c.Log.WithValues(objectLogKey, KRef(req.Namespace, req.Name))
+
+	// Add reconcileID to the logger.
+	reconcileID, err := c.generateReconcileID()
+	if err != nil {
+		c.Queue.AddRateLimited(req)
+		ctrlmetrics.ReconcileErrors.WithLabelValues(c.Name).Inc()
+		ctrlmetrics.ReconcileTotal.WithLabelValues(c.Name, labelError).Inc()
+		log.Error(err, "Reconciler error")
+		return
+	}
+
+	log = log.WithValues("reconcileID", reconcileID)
 	ctx = logf.IntoContext(ctx, log)
 
 	// RunInformersAndControllers the syncHandler, passing it the Namespace/Name string of the
@@ -353,3 +381,46 @@ func (c *Controller) InjectFunc(f inject.Func) error {
 func (c *Controller) updateMetrics(reconcileTime time.Duration) {
 	ctrlmetrics.ReconcileTime.WithLabelValues(c.Name).Observe(reconcileTime.Seconds())
 }
+
+// KRef returns ObjectRef from name and namespace
+// Note: This is a copy of the func from klog. It has been copied to avoid
+// introducing a dependency to klog, while still implement logging according
+// to the Kubernetes structured logging KEP.
+func KRef(namespace, name string) ObjectRef {
+	return ObjectRef{
+		Name:      name,
+		Namespace: namespace,
+	}
+}
+
+// ObjectRef references a kubernetes object
+// Note: This is a copy of the struct from klog. It has been copied to avoid
+// introducing a dependency to klog, while still implement logging according
+// to the Kubernetes structured logging KEP.
+type ObjectRef struct {
+	Name      string `json:"name"`
+	Namespace string `json:"namespace,omitempty"`
+}
+
+// MarshalLog ensures that loggers with support for structured output will log
+// as a struct by removing the String method via a custom type.
+func (ref ObjectRef) MarshalLog() interface{} {
+	type or ObjectRef
+	return or(ref)
+}
+
+func (ref ObjectRef) String() string {
+	if ref.Namespace != "" {
+		return fmt.Sprintf("%s/%s", ref.Namespace, ref.Name)
+	}
+	return ref.Name
+}
+
+// generateReconcileID generates a reconcileID for logging.
+func (c *Controller) generateReconcileID() (string, error) {
+	id := [16]byte{}
+	if _, err := c.RandSource.Read(id[:]); err != nil {
+		return "", fmt.Errorf("failed to generate reconcileID: %v", err)
+	}
+	return hex.EncodeToString(id[:]), nil
+}