Trace the execution of a reconciler hierarchy

Introduces a Tracer interface that can be provided to the Reconciler and
Webhook handler implementations when they are defined. Each provided
SubReconciler is instrumented to enter a new frame when it's Reconcile
method is called and exit upon return.

Two implementations are provided out of the box.  DiscardTracer ignores
all calls.  LogrTracer logs as each frame enters and exits, capturing
the elapsed time.

Custom SubReconcilers and other aspects of the call stack can be
instrumented:

    import "reconciler.io/runtime/trace"

    ...

    trace.Enter(ctx, "MEANINGFUL NAME")
    defer trace.Exit(ctx)

Signed-off-by: Scott Andrews <scott@andrews.me>

reconcilers/aggregate.go

@@ -35,6 +35,7 @@ import (
 	"reconciler.io/runtime/duck"
 	"reconciler.io/runtime/internal"
 	rtime "reconciler.io/runtime/time"
+	"reconciler.io/runtime/trace"
 	"reconciler.io/runtime/tracker"
 )
 
@@ -104,6 +105,11 @@ type AggregateReconciler[Type client.Object] struct {
 	// +optional
 	Sanitize func(resource Type) interface{}
 
+	// Trace the execution of each request using this tracer.
+	//
+	// +optional
+	Trace trace.Tracer
+
 	Config Config
 
 	// stamp manages the lifecycle of the aggregated resource.
@@ -215,15 +221,18 @@ func (r *AggregateReconciler[T]) Reconcile(ctx context.Context, req Request) (Re
 		return Result{}, nil
 	}
 
-	ctx = WithStash(ctx)
-
 	c := r.Config
 
 	log := logr.FromContextOrDiscard(ctx).
 		WithName(r.Name).
 		WithValues("resourceType", gvk(c, r.Type))
 	ctx = logr.NewContext(ctx, log)
 
+	ctx = trace.StashTracer(ctx, r.Trace)
+	trace.Enter(ctx, r.Name)
+	defer trace.Exit(ctx)
+
+	ctx = WithStash(ctx)
 	ctx = rtime.StashNow(ctx, time.Now())
 	ctx = StashRequest(ctx, req)
 	ctx = StashConfig(ctx, c)

reconcilers/cast.go

@@ -24,6 +24,7 @@ import (
 	"sync"
 
 	"k8s.io/apimachinery/pkg/util/errors"
+	"reconciler.io/runtime/trace"
 
 	"github.com/go-logr/logr"
 	"k8s.io/apimachinery/pkg/api/equality"
@@ -105,11 +106,6 @@ func (r *CastResource[T, CT]) validate(ctx context.Context) error {
 func (r *CastResource[T, CT]) Reconcile(ctx context.Context, resource T) (Result, error) {
 	r.init()
 
-	if r.noop {
-		// cast the type rather than convert the object
-		return r.Reconciler.Reconcile(ctx, client.Object(resource).(CT))
-	}
-
 	var nilCT CT
 	emptyCT := newEmpty(nilCT).(CT)
 
@@ -118,6 +114,14 @@ func (r *CastResource[T, CT]) Reconcile(ctx context.Context, resource T) (Result
 		WithValues("castResourceType", typeName(emptyCT))
 	ctx = logr.NewContext(ctx, log)
 
+	trace.Enter(ctx, r.Name)
+	defer trace.Exit(ctx)
+
+	if r.noop {
+		// cast the type rather than convert the object
+		return r.Reconciler.Reconcile(ctx, client.Object(resource).(CT))
+	}
+
 	ctx, castResource, err := r.cast(ctx, resource)
 	if err != nil {
 		return Result{}, err

reconcilers/child.go

@@ -32,6 +32,7 @@ import (
 	"sigs.k8s.io/controller-runtime/pkg/client"
 
 	"reconciler.io/runtime/internal"
+	"reconciler.io/runtime/trace"
 )
 
 var (
@@ -276,6 +277,9 @@ func (r *ChildReconciler[T, CT, CLT]) Reconcile(ctx context.Context, resource T)
 		WithValues("childType", gvk(c, r.ChildType))
 	ctx = logr.NewContext(ctx, log)
 
+	trace.Enter(ctx, r.Name)
+	defer trace.Exit(ctx)
+
 	child, err := r.reconcile(ctx, resource)
 	if resource.GetDeletionTimestamp() != nil {
 		return Result{}, err

reconcilers/childset.go

@@ -26,6 +26,7 @@ import (
 	utilerrors "k8s.io/apimachinery/pkg/util/errors"
 	"k8s.io/apimachinery/pkg/util/sets"
 	"reconciler.io/runtime/internal"
+	"reconciler.io/runtime/trace"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/builder"
 	"sigs.k8s.io/controller-runtime/pkg/client"
@@ -294,6 +295,9 @@ func (r *ChildSetReconciler[T, CT, CLT]) Reconcile(ctx context.Context, resource
 		WithName(r.Name)
 	ctx = logr.NewContext(ctx, log)
 
+	trace.Enter(ctx, r.Name)
+	defer trace.Exit(ctx)
+
 	knownChildren, err := r.knownChildren(ctx, resource)
 	if err != nil {
 		return Result{}, err

reconcilers/finalizer.go

@@ -23,6 +23,7 @@ import (
 
 	"github.com/go-logr/logr"
 	corev1 "k8s.io/api/core/v1"
+	"reconciler.io/runtime/trace"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/builder"
 	"sigs.k8s.io/controller-runtime/pkg/client"
@@ -92,6 +93,9 @@ func (r *WithFinalizer[T]) Reconcile(ctx context.Context, resource T) (Result, e
 		WithName(r.Name)
 	ctx = logr.NewContext(ctx, log)
 
+	trace.Enter(ctx, r.Name)
+	defer trace.Exit(ctx)
+
 	if resource.GetDeletionTimestamp() == nil {
 		if err := AddFinalizer(ctx, resource, r.Finalizer); err != nil {
 			return Result{}, err

reconcilers/flow.go

@@ -23,6 +23,7 @@ import (
 
 	"github.com/go-logr/logr"
 	"k8s.io/utils/pointer"
+	"reconciler.io/runtime/trace"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/builder"
 	"sigs.k8s.io/controller-runtime/pkg/client"
@@ -125,6 +126,9 @@ func (r *IfThen[T]) Reconcile(ctx context.Context, resource T) (Result, error) {
 		WithName(r.Name)
 	ctx = logr.NewContext(ctx, log)
 
+	trace.Enter(ctx, r.Name)
+	defer trace.Exit(ctx)
+
 	if r.If(ctx, resource) {
 		return r.Then.Reconcile(ctx, resource)
 	} else if r.Else != nil {
@@ -256,6 +260,9 @@ func (r *While[T]) Reconcile(ctx context.Context, resource T) (Result, error) {
 		WithName(r.Name)
 	ctx = logr.NewContext(ctx, log)
 
+	trace.Enter(ctx, r.Name)
+	defer trace.Exit(ctx)
+
 	aggregateResult := Result{}
 	for i := 0; true; i++ {
 		if *r.MaxIterations != 0 && i >= *r.MaxIterations {
@@ -387,6 +394,9 @@ func (r *TryCatch[T]) Reconcile(ctx context.Context, resource T) (Result, error)
 		WithName(r.Name)
 	ctx = logr.NewContext(ctx, log)
 
+	trace.Enter(ctx, r.Name)
+	defer trace.Exit(ctx)
+
 	result, err := r.Try.Reconcile(ctx, resource)
 	if r.Catch != nil {
 		result, err = r.Catch(ctx, resource, result, err)
@@ -474,6 +484,9 @@ func (r *OverrideSetup[T]) Reconcile(ctx context.Context, resource T) (Result, e
 		WithName(r.Name)
 	ctx = logr.NewContext(ctx, log)
 
+	trace.Enter(ctx, r.Name)
+	defer trace.Exit(ctx)
+
 	if r.Reconciler == nil {
 		return Result{}, nil
 	}

reconcilers/resource.go

@@ -41,6 +41,7 @@ import (
 	"reconciler.io/runtime/duck"
 	"reconciler.io/runtime/internal"
 	rtime "reconciler.io/runtime/time"
+	"reconciler.io/runtime/trace"
 )
 
 var (
@@ -83,6 +84,11 @@ type ResourceReconciler[Type client.Object] struct {
 	// returned.
 	Reconciler SubReconciler[Type]
 
+	// Trace the execution of each request using this tracer.
+	//
+	// +optional
+	Trace trace.Tracer
+
 	Config Config
 
 	lazyInit sync.Once
@@ -193,15 +199,18 @@ func (r *ResourceReconciler[T]) validate(ctx context.Context) error {
 func (r *ResourceReconciler[T]) Reconcile(ctx context.Context, req Request) (Result, error) {
 	r.init()
 
-	ctx = WithStash(ctx)
-
 	c := r.Config
 
 	log := logr.FromContextOrDiscard(ctx).
 		WithName(r.Name).
 		WithValues("resourceType", gvk(c, r.Type))
 	ctx = logr.NewContext(ctx, log)
 
+	ctx = trace.StashTracer(ctx, r.Trace)
+	trace.Enter(ctx, r.Name)
+	defer trace.Exit(ctx)
+
+	ctx = WithStash(ctx)
 	ctx = rtime.StashNow(ctx, time.Now())
 	ctx = StashRequest(ctx, req)
 	ctx = StashConfig(ctx, c)

reconcilers/sequence.go

@@ -21,6 +21,7 @@ import (
 	"fmt"
 
 	"github.com/go-logr/logr"
+	"reconciler.io/runtime/trace"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/builder"
 	"sigs.k8s.io/controller-runtime/pkg/client"
@@ -49,6 +50,9 @@ func (r Sequence[T]) SetupWithManager(ctx context.Context, mgr ctrl.Manager, bld
 }
 
 func (r Sequence[T]) Reconcile(ctx context.Context, resource T) (Result, error) {
+	trace.Enter(ctx, "Sequence")
+	defer trace.Exit(ctx)
+
 	aggregateResult := Result{}
 	for i, reconciler := range r {
 		log := logr.FromContextOrDiscard(ctx).

reconcilers/sync.go

@@ -22,6 +22,7 @@ import (
 	"fmt"
 
 	"github.com/go-logr/logr"
+	"reconciler.io/runtime/trace"
 	ctrl "sigs.k8s.io/controller-runtime"
 	"sigs.k8s.io/controller-runtime/pkg/builder"
 	"sigs.k8s.io/controller-runtime/pkg/client"
@@ -124,6 +125,9 @@ func (r *SyncReconciler[T]) Reconcile(ctx context.Context, resource T) (Result,
 		WithName(r.Name)
 	ctx = logr.NewContext(ctx, log)
 
+	trace.Enter(ctx, r.Name)
+	defer trace.Exit(ctx)
+
 	result := Result{}
 
 	if resource.GetDeletionTimestamp() == nil || r.SyncDuringFinalization {

reconcilers/webhook.go

@@ -31,12 +31,14 @@ import (
 	"k8s.io/apimachinery/pkg/api/equality"
 	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
 	"k8s.io/apimachinery/pkg/types"
-	"reconciler.io/runtime/internal"
-	rtime "reconciler.io/runtime/time"
 	"sigs.k8s.io/controller-runtime/pkg/client"
 	crlog "sigs.k8s.io/controller-runtime/pkg/log"
 	"sigs.k8s.io/controller-runtime/pkg/webhook"
 	"sigs.k8s.io/controller-runtime/pkg/webhook/admission"
+
+	"reconciler.io/runtime/internal"
+	rtime "reconciler.io/runtime/time"
+	"reconciler.io/runtime/trace"
 )
 
 // AdmissionWebhookAdapter allows using sub reconcilers to process admission webhooks. The full
@@ -74,6 +76,11 @@ type AdmissionWebhookAdapter[Type client.Object] struct {
 	// Typically, Reconciler is a Sequence of multiple SubReconcilers.
 	Reconciler SubReconciler[Type]
 
+	// Trace the execution of each request using this tracer.
+	//
+	// +optional
+	Trace trace.Tracer
+
 	Config Config
 
 	lazyInit sync.Once
@@ -130,6 +137,10 @@ func (r *AdmissionWebhookAdapter[T]) Handle(ctx context.Context, req admission.R
 		)
 	ctx = logr.NewContext(ctx, log)
 
+	ctx = trace.StashTracer(ctx, r.Trace)
+	trace.Enter(ctx, r.Name)
+	defer trace.Exit(ctx)
+
 	resp := &admission.Response{
 		AdmissionResponse: admissionv1.AdmissionResponse{
 			UID: req.UID,

trace/discard.go

@@ -0,0 +1,30 @@
+/*
+Copyright 2024 the original author or authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package trace
+
+import (
+	"context"
+)
+
+var (
+	_ Tracer = (*discardTracer)(nil)
+)
+
+type discardTracer struct{}
+
+func (d *discardTracer) Enter(ctx context.Context, name string) {}
+func (d *discardTracer) Exit(ctx context.Context)               {}

trace/interface.go

@@ -0,0 +1,29 @@
+/*
+Copyright 2024 the original author or authors.
+
+Licensed under the Apache License, Version 2.0 (the "License");
+you may not use this file except in compliance with the License.
+You may obtain a copy of the License at
+
+    http://www.apache.org/licenses/LICENSE-2.0
+
+Unless required by applicable law or agreed to in writing, software
+distributed under the License is distributed on an "AS IS" BASIS,
+WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+See the License for the specific language governing permissions and
+limitations under the License.
+*/
+
+package trace
+
+import (
+	"context"
+)
+
+// Tracer observes the execution of a reconciler hierarchy.
+type Tracer interface {
+	// Enter opens a new frame.
+	Enter(ctx context.Context, name string)
+	// Exit closes the most recently entered open frame.
+	Exit(ctx context.Context)
+}