From 2266c83c7e175481f4052ac967e5431e61d2bd27 Mon Sep 17 00:00:00 2001 From: Stefan Bueringer Date: Fri, 4 Mar 2022 16:08:31 +0100 Subject: [PATCH] logging: align to Kubernetes structured logging, add reconcileID MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Signed-off-by: Stefan Büringer buringerst@vmware.com --- pkg/builder/controller.go | 3 +- pkg/controller/controller.go | 27 +++++++-- pkg/internal/controller/controller.go | 79 +++++++++++++++++++++++++-- 3 files changed, 99 insertions(+), 10 deletions(-) diff --git a/pkg/builder/controller.go b/pkg/builder/controller.go index 9a74d6ec9a..5a1f7546aa 100644 --- a/pkg/builder/controller.go +++ b/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 } diff --git a/pkg/controller/controller.go b/pkg/controller/controller.go index 02a806da24..a3aa4d501a 100644 --- a/pkg/controller/controller.go +++ b/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 } diff --git a/pkg/internal/controller/controller.go b/pkg/internal/controller/controller.go index 615b6476e1..e51ce9b93b 100644 --- a/pkg/internal/controller/controller.go +++ b/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 +}