From 21fcf2e773cd78e7ab7fba5840808e490e92911f 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 --- examples/builtins/main.go | 3 +- pkg/builder/controller.go | 3 +- pkg/builder/controller_test.go | 24 +++--- pkg/controller/controller.go | 27 ++++++- pkg/controller/controller_integration_test.go | 4 +- pkg/controller/controller_test.go | 14 ++-- pkg/controller/example_test.go | 9 ++- pkg/internal/controller/controller.go | 79 ++++++++++++++++++- .../recorder/recorder_integration_test.go | 3 +- 9 files changed, 130 insertions(+), 36 deletions(-) diff --git a/examples/builtins/main.go b/examples/builtins/main.go index ff1f0dfa3b..78465f7f5a 100644 --- a/examples/builtins/main.go +++ b/examples/builtins/main.go @@ -22,6 +22,7 @@ import ( appsv1 "k8s.io/api/apps/v1" corev1 "k8s.io/api/core/v1" _ "k8s.io/client-go/plugin/pkg/client/auth/gcp" + "sigs.k8s.io/controller-runtime/pkg/client/config" "sigs.k8s.io/controller-runtime/pkg/controller" "sigs.k8s.io/controller-runtime/pkg/handler" @@ -50,7 +51,7 @@ func main() { // Setup a new controller to reconcile ReplicaSets entryLog.Info("Setting up controller") - c, err := controller.New("foo-controller", mgr, controller.Options{ + c, err := controller.New("foo-controller", nil, mgr, controller.Options{ Reconciler: &reconcileReplicaSet{client: mgr.GetClient()}, }) if err != nil { 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/builder/controller_test.go b/pkg/builder/controller_test.go index 5513bc997e..9105f60a73 100644 --- a/pkg/builder/controller_test.go +++ b/pkg/builder/controller_test.go @@ -143,7 +143,7 @@ var _ = Describe("application", func() { }) It("should return an error if it cannot create the controller", func() { - newController = func(name string, mgr manager.Manager, options controller.Options) ( + newController = func(name string, gvk *schema.GroupVersionKind, mgr manager.Manager, options controller.Options) ( controller.Controller, error) { return nil, fmt.Errorf("expected error") } @@ -163,10 +163,10 @@ var _ = Describe("application", func() { It("should override max concurrent reconcilers during creation of controller", func() { const maxConcurrentReconciles = 5 - newController = func(name string, mgr manager.Manager, options controller.Options) ( + newController = func(name string, gvk *schema.GroupVersionKind, mgr manager.Manager, options controller.Options) ( controller.Controller, error) { if options.MaxConcurrentReconciles == maxConcurrentReconciles { - return controller.New(name, mgr, options) + return controller.New(name, gvk, mgr, options) } return nil, fmt.Errorf("max concurrent reconcilers expected %d but found %d", maxConcurrentReconciles, options.MaxConcurrentReconciles) } @@ -186,10 +186,10 @@ var _ = Describe("application", func() { It("should override max concurrent reconcilers during creation of controller, when using", func() { const maxConcurrentReconciles = 10 - newController = func(name string, mgr manager.Manager, options controller.Options) ( + newController = func(name string, gvk *schema.GroupVersionKind, mgr manager.Manager, options controller.Options) ( controller.Controller, error) { if options.MaxConcurrentReconciles == maxConcurrentReconciles { - return controller.New(name, mgr, options) + return controller.New(name, gvk, mgr, options) } return nil, fmt.Errorf("max concurrent reconcilers expected %d but found %d", maxConcurrentReconciles, options.MaxConcurrentReconciles) } @@ -214,9 +214,9 @@ var _ = Describe("application", func() { It("should override rate limiter during creation of controller", func() { rateLimiter := workqueue.DefaultItemBasedRateLimiter() - newController = func(name string, mgr manager.Manager, options controller.Options) (controller.Controller, error) { + newController = func(name string, gvk *schema.GroupVersionKind, mgr manager.Manager, options controller.Options) (controller.Controller, error) { if options.RateLimiter == rateLimiter { - return controller.New(name, mgr, options) + return controller.New(name, gvk, mgr, options) } return nil, fmt.Errorf("rate limiter expected %T but found %T", rateLimiter, options.RateLimiter) } @@ -237,9 +237,9 @@ var _ = Describe("application", func() { It("should override logger during creation of controller", func() { logger := &testLogger{} - newController = func(name string, mgr manager.Manager, options controller.Options) (controller.Controller, error) { + newController = func(name string, gvk *schema.GroupVersionKind, mgr manager.Manager, options controller.Options) (controller.Controller, error) { if options.Log.GetSink() == logger { - return controller.New(name, mgr, options) + return controller.New(name, gvk, mgr, options) } return nil, fmt.Errorf("logger expected %T but found %T", logger, options.Log) } @@ -258,11 +258,11 @@ var _ = Describe("application", func() { }) It("should prefer reconciler from options during creation of controller", func() { - newController = func(name string, mgr manager.Manager, options controller.Options) (controller.Controller, error) { + newController = func(name string, gvk *schema.GroupVersionKind, mgr manager.Manager, options controller.Options) (controller.Controller, error) { if options.Reconciler != (typedNoop{}) { - return nil, fmt.Errorf("Custom reconciler expected %T but found %T", typedNoop{}, options.Reconciler) + return nil, fmt.Errorf("custom reconciler expected %T but found %T", typedNoop{}, options.Reconciler) } - return controller.New(name, mgr, options) + return controller.New(name, gvk, mgr, options) } By("creating a controller manager") diff --git a/pkg/controller/controller.go b/pkg/controller/controller.go index 02a806da24..8e647be556 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)) //nolint:gosec // math/rand is enough, we don't need crypto/rand. + // 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/controller/controller_integration_test.go b/pkg/controller/controller_integration_test.go index 9f347b0032..886137328c 100644 --- a/pkg/controller/controller_integration_test.go +++ b/pkg/controller/controller_integration_test.go @@ -24,6 +24,7 @@ import ( metav1 "k8s.io/apimachinery/pkg/apis/meta/v1" "k8s.io/apimachinery/pkg/runtime/schema" "k8s.io/apimachinery/pkg/types" + "sigs.k8s.io/controller-runtime/pkg/cache" "sigs.k8s.io/controller-runtime/pkg/controller" "sigs.k8s.io/controller-runtime/pkg/controller/controllertest" @@ -33,6 +34,7 @@ import ( . "github.com/onsi/ginkgo" . "github.com/onsi/gomega" + "sigs.k8s.io/controller-runtime/pkg/manager" ) @@ -54,7 +56,7 @@ var _ = Describe("controller", func() { Expect(err).NotTo(HaveOccurred()) By("Creating the Controller") - instance, err := controller.New("foo-controller", cm, controller.Options{ + instance, err := controller.New("foo-controller", nil, cm, controller.Options{ Reconciler: reconcile.Func( func(_ context.Context, request reconcile.Request) (reconcile.Result, error) { reconciled <- request diff --git a/pkg/controller/controller_test.go b/pkg/controller/controller_test.go index d3e8419a16..ce70c282bf 100644 --- a/pkg/controller/controller_test.go +++ b/pkg/controller/controller_test.go @@ -45,7 +45,7 @@ var _ = Describe("controller.Controller", func() { It("should return an error if Name is not Specified", func() { m, err := manager.New(cfg, manager.Options{}) Expect(err).NotTo(HaveOccurred()) - c, err := controller.New("", m, controller.Options{Reconciler: rec}) + c, err := controller.New("", nil, m, controller.Options{Reconciler: rec}) Expect(c).To(BeNil()) Expect(err.Error()).To(ContainSubstring("must specify Name for Controller")) }) @@ -54,7 +54,7 @@ var _ = Describe("controller.Controller", func() { m, err := manager.New(cfg, manager.Options{}) Expect(err).NotTo(HaveOccurred()) - c, err := controller.New("foo", m, controller.Options{}) + c, err := controller.New("foo", nil, m, controller.Options{}) Expect(c).To(BeNil()) Expect(err.Error()).To(ContainSubstring("must specify Reconciler")) }) @@ -63,7 +63,7 @@ var _ = Describe("controller.Controller", func() { m, err := manager.New(cfg, manager.Options{}) Expect(err).NotTo(HaveOccurred()) - c, err := controller.New("foo", m, controller.Options{Reconciler: &failRec{}}) + c, err := controller.New("foo", nil, m, controller.Options{Reconciler: &failRec{}}) Expect(c).To(BeNil()) Expect(err).To(HaveOccurred()) Expect(err.Error()).To(ContainSubstring("expected error")) @@ -73,11 +73,11 @@ var _ = Describe("controller.Controller", func() { m, err := manager.New(cfg, manager.Options{}) Expect(err).NotTo(HaveOccurred()) - c1, err := controller.New("c1", m, controller.Options{Reconciler: rec}) + c1, err := controller.New("c1", nil, m, controller.Options{Reconciler: rec}) Expect(err).NotTo(HaveOccurred()) Expect(c1).ToNot(BeNil()) - c2, err := controller.New("c2", m, controller.Options{Reconciler: rec}) + c2, err := controller.New("c2", nil, m, controller.Options{Reconciler: rec}) Expect(err).NotTo(HaveOccurred()) Expect(c2).ToNot(BeNil()) }) @@ -107,7 +107,7 @@ var _ = Describe("controller.Controller", func() { m, err := manager.New(cfg, manager.Options{}) Expect(err).NotTo(HaveOccurred()) - c, err := controller.New("new-controller", m, controller.Options{Reconciler: rec}) + c, err := controller.New("new-controller", nil, m, controller.Options{Reconciler: rec}) Expect(c.Watch(watch, &handler.EnqueueRequestForObject{})).To(Succeed()) Expect(err).NotTo(HaveOccurred()) @@ -134,7 +134,7 @@ var _ = Describe("controller.Controller", func() { m, err := manager.New(cfg, manager.Options{}) Expect(err).NotTo(HaveOccurred()) - _, err = controller.New("new-controller", m, controller.Options{Reconciler: rec}) + _, err = controller.New("new-controller", nil, m, controller.Options{Reconciler: rec}) Expect(err).NotTo(HaveOccurred()) // force-close keep-alive connections. These'll time anyway (after diff --git a/pkg/controller/example_test.go b/pkg/controller/example_test.go index 3d8e399703..cf8a540fef 100644 --- a/pkg/controller/example_test.go +++ b/pkg/controller/example_test.go @@ -23,6 +23,7 @@ import ( corev1 "k8s.io/api/core/v1" "k8s.io/apimachinery/pkg/apis/meta/v1/unstructured" "k8s.io/apimachinery/pkg/runtime/schema" + "sigs.k8s.io/controller-runtime/pkg/controller" "sigs.k8s.io/controller-runtime/pkg/handler" logf "sigs.k8s.io/controller-runtime/pkg/log" @@ -41,7 +42,7 @@ var ( // This example creates a new Controller named "pod-controller" with a no-op reconcile function. The // manager.Manager will be used to Start the Controller, and will provide it a shared Cache and Client. func ExampleNew() { - _, err := controller.New("pod-controller", mgr, controller.Options{ + _, err := controller.New("pod-controller", nil, mgr, controller.Options{ Reconciler: reconcile.Func(func(context.Context, reconcile.Request) (reconcile.Result, error) { // Your business logic to implement the API by creating, updating, deleting objects goes here. return reconcile.Result{}, nil @@ -59,7 +60,7 @@ func ExampleController() { // Create a new Controller that will call the provided Reconciler function in response // to events. - c, err := controller.New("pod-controller", mgr, controller.Options{ + c, err := controller.New("pod-controller", nil, mgr, controller.Options{ Reconciler: reconcile.Func(func(context.Context, reconcile.Request) (reconcile.Result, error) { // Your business logic to implement the API by creating, updating, deleting objects goes here. return reconcile.Result{}, nil @@ -90,7 +91,7 @@ func ExampleController_unstructured() { // Create a new Controller that will call the provided Reconciler function in response // to events. - c, err := controller.New("pod-controller", mgr, controller.Options{ + c, err := controller.New("pod-controller", nil, mgr, controller.Options{ Reconciler: reconcile.Func(func(context.Context, reconcile.Request) (reconcile.Result, error) { // Your business logic to implement the API by creating, updating, deleting objects goes here. return reconcile.Result{}, nil @@ -129,7 +130,7 @@ func ExampleNewUnmanaged() { // Configure creates a new controller but does not add it to the supplied // manager. - c, err := controller.NewUnmanaged("pod-controller", mgr, controller.Options{ + c, err := controller.NewUnmanaged("pod-controller", nil, mgr, controller.Options{ Reconciler: reconcile.Func(func(context.Context, reconcile.Request) (reconcile.Result, error) { return reconcile.Result{}, 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 +} diff --git a/pkg/internal/recorder/recorder_integration_test.go b/pkg/internal/recorder/recorder_integration_test.go index 5bafaabf5a..a1e7bd6570 100644 --- a/pkg/internal/recorder/recorder_integration_test.go +++ b/pkg/internal/recorder/recorder_integration_test.go @@ -25,6 +25,7 @@ import ( "k8s.io/apimachinery/pkg/watch" "k8s.io/client-go/kubernetes/scheme" ref "k8s.io/client-go/tools/reference" + "sigs.k8s.io/controller-runtime/pkg/controller" "sigs.k8s.io/controller-runtime/pkg/handler" "sigs.k8s.io/controller-runtime/pkg/manager" @@ -44,7 +45,7 @@ var _ = Describe("recorder", func() { By("Creating the Controller") recorder := cm.GetEventRecorderFor("test-recorder") - instance, err := controller.New("foo-controller", cm, controller.Options{ + instance, err := controller.New("foo-controller", nil, cm, controller.Options{ Reconciler: reconcile.Func( func(ctx context.Context, request reconcile.Request) (reconcile.Result, error) { dp, err := clientset.AppsV1().Deployments(request.Namespace).Get(ctx, request.Name, metav1.GetOptions{})