RHOAIENG-13916: chore(odh-notebook-controller/tests): introduce oTel-based testing (#570)

Author: jiridanek

components/odh-notebook-controller/controllers/notebook_webhook.go

@@ -19,14 +19,19 @@ import (
 	"context"
 	"encoding/json"
 	"fmt"
-	configv1 "github.com/openshift/api/config/v1"
 	"net/http"
 	"sort"
 	"strings"
+	"sync"
+
+	"go.opentelemetry.io/otel"
+	"go.opentelemetry.io/otel/attribute"
+	"go.opentelemetry.io/otel/trace"
 
 	"github.com/go-logr/logr"
 	nbv1 "github.com/kubeflow/kubeflow/components/notebook-controller/api/v1"
 	"github.com/kubeflow/kubeflow/components/notebook-controller/pkg/culler"
+	configv1 "github.com/openshift/api/config/v1"
 	admissionv1 "k8s.io/api/admission/v1"
 	corev1 "k8s.io/api/core/v1"
 	"k8s.io/apimachinery/pkg/api/equality"
@@ -57,6 +62,12 @@ type NotebookWebhook struct {
 
 var proxyEnvVars = make(map[string]string, 3)
 
+// https://github.com/open-telemetry/opentelemetry-go/pull/1674#issuecomment-793558199
+// https://github.com/open-telemetry/opentelemetry-go/issues/4291#issuecomment-1629797725
+var getWebhookTracer func() trace.Tracer = sync.OnceValue(func() trace.Tracer {
+	return otel.GetTracerProvider().Tracer("opendatahub.io/kubeflow/components/odh-notebook-controller/controllers/notebook_webhook.go")
+})
+
 // InjectReconciliationLock injects the kubeflow notebook controller culling
 // stop annotation to explicitly start the notebook pod when the ODH notebook
 // controller finishes the reconciliation. Otherwise, a race condition may happen
@@ -264,6 +275,15 @@ func (w *NotebookWebhook) Handle(ctx context.Context, req admission.Request) adm
 	log := w.Log.WithValues("notebook", req.Name, "namespace", req.Namespace)
 	ctx = logr.NewContext(ctx, log)
 
+	// Initialize OpenTelemetry tracer.
+	// This is a noop in production code and is (so far) only used for testing.
+	ctx, span := getWebhookTracer().Start(ctx, "handleFunc", trace.WithNewRoot(), trace.WithAttributes(
+		attribute.String("notebook", req.Name),
+		attribute.String("namespace", req.Namespace),
+		attribute.String("operation", string(req.Operation)),
+	))
+	defer span.End()
+
 	notebook := &nbv1.Notebook{}
 
 	err := w.Decoder.Decode(req, notebook)
@@ -350,6 +370,9 @@ func (w *NotebookWebhook) maybeRestartRunningNotebook(ctx context.Context, req a
 	var err error
 	log := logr.FromContextOrDiscard(ctx)
 
+	ctx, span := getWebhookTracer().Start(ctx, "maybeRestartRunningNotebook")
+	defer span.End()
+
 	// Notebook that was just created can be updated
 	if req.Operation == admissionv1.Create {
 		log.Info("Not blocking update, notebook is being newly created")
@@ -625,6 +648,8 @@ func InjectCertConfig(notebook *nbv1.Notebook, configMapName string) error {
 // Otherwise, it checks the last-image-selection annotation to find the image stream and fetches the image from status.dockerImageReference,
 // assigning it to the container.image value.
 func SetContainerImageFromRegistry(ctx context.Context, config *rest.Config, notebook *nbv1.Notebook, log logr.Logger, namespace string) error {
+	span := trace.SpanFromContext(ctx)
+
 	// Create a dynamic client
 	dynamicClient, err := dynamic.NewForConfig(config)
 	if err != nil {
@@ -717,6 +742,7 @@ func SetContainerImageFromRegistry(ctx context.Context, config *rest.Config, not
 						}
 					}
 					if !imagestreamFound {
+						span.AddEvent("imagestream-not-found")
 						log.Error(nil, "ImageStream not found in main controller namespace, or the ImageStream is present but does not contain a dockerImageReference for the specified tag",
 							"imageSelected", imageSelected[0], "tag", imageSelected[1], "namespace", namespace)
 					}

components/odh-notebook-controller/controllers/notebook_webhook_test.go

@@ -18,6 +18,7 @@ package controllers
 import (
 	"context"
 	"fmt"
+
 	nbv1 "github.com/kubeflow/kubeflow/components/notebook-controller/api/v1"
 	corev1 "k8s.io/api/core/v1"
 	apierrs "k8s.io/apimachinery/pkg/api/errors"
@@ -53,7 +54,9 @@ var _ = Describe("The Openshift Notebook webhook", func() {
 			// currently we expect that Notebook CR is always created,
 			// and when unable to resolve imagestream, image: is left alone
 			expectedImage string
-			// todo(jdanek): also consider Observing for the log message, https://www.youtube.com/watch?v=prLRI3VEVq4
+			// see https://www.youtube.com/watch?v=prLRI3VEVq4 for Observability Driven Development intro
+			expectedEvents   []string
+			unexpectedEvents []string
 		}{
 			{
 				name: "ImageStream with all that is needful",
@@ -109,6 +112,9 @@ var _ = Describe("The Openshift Notebook webhook", func() {
 					},
 				},
 				expectedImage: "quay.io/modh/odh-generic-data-science-notebook@sha256:76e6af79c601a323f75a58e7005de0beac66b8cccc3d2b67efb6d11d85f0cfa1",
+				unexpectedEvents: []string{
+					"imagestream-not-found",
+				},
 			},
 			{
 				name: "ImageStream with a tag without items (RHOAIENG-13916)",
@@ -158,23 +164,47 @@ var _ = Describe("The Openshift Notebook webhook", func() {
 				},
 				// there is no update to the Notebook
 				expectedImage: ":some-tag",
+				expectedEvents: []string{
+					"imagestream-not-found",
+				},
 			},
 		}
 
+		BeforeEach(func() {
+			Expect(tracings.TraceProvider.ForceFlush(context.Background())).To(Succeed())
+			tracings.SpanExporter.Reset()
+		})
+
 		for _, testCase := range testCases {
-			testCase := testCase // create a copy to get correct capture in the `It` closure, https://go.dev/blog/loopvar-preview
-			It(fmt.Sprintf("Should create a Notebook resource successfully: %s", testCase.name), func() {
-				By("Creating a Notebook resource successfully")
-				Expect(cli.Create(ctx, testCase.imageStream, &client.CreateOptions{})).To(Succeed())
-				// if our webhook panics, then cli.Create will err
-				Expect(cli.Create(ctx, testCase.notebook, &client.CreateOptions{})).To(Succeed())
+			Context(fmt.Sprintf("The Notebook webhook test case: %s", testCase.name), func() {
+				It("Should create a Notebook resource successfully", func() {
+					By("Creating a Notebook resource successfully")
+					Expect(cli.Create(ctx, testCase.imageStream, &client.CreateOptions{})).To(Succeed())
+					// if our webhook panics, then cli.Create will err
+					Expect(cli.Create(ctx, testCase.notebook, &client.CreateOptions{})).To(Succeed())
 
-				By("Checking that the webhook modified the notebook CR with the expected image")
-				Expect(testCase.notebook.Spec.Template.Spec.Containers[0].Image).To(Equal(testCase.expectedImage))
+					By("Checking that the webhook modified the notebook CR with the expected image")
+					Expect(testCase.notebook.Spec.Template.Spec.Containers[0].Image).To(Equal(testCase.expectedImage))
 
-				By("Deleting the created resources")
-				Expect(cli.Delete(ctx, testCase.notebook, &client.DeleteOptions{})).To(Succeed())
-				Expect(cli.Delete(ctx, testCase.imageStream, &client.DeleteOptions{})).To(Succeed())
+					By("Checking telemetry events")
+					Expect(tracings.TraceProvider.ForceFlush(context.Background())).To(Succeed())
+					spans := tracings.SpanExporter.GetSpans()
+					events := make([]string, 0)
+					for _, span := range spans {
+						for _, event := range span.Events {
+							events = append(events, event.Name)
+						}
+					}
+					Expect(events).To(ContainElements(testCase.expectedEvents))
+					for _, unexpectedEvent := range testCase.unexpectedEvents {
+						Expect(events).ToNot(ContainElement(unexpectedEvent))
+					}
+				})
+				AfterEach(func() {
+					By("Deleting the created resources")
+					Expect(cli.Delete(ctx, testCase.notebook, &client.DeleteOptions{})).To(Succeed())
+					Expect(cli.Delete(ctx, testCase.imageStream, &client.DeleteOptions{})).To(Succeed())
+				})
 			})
 		}
 	})

components/odh-notebook-controller/controllers/opentelemetry_test.go

@@ -0,0 +1,131 @@
+package controllers
+
+import (
+	"context"
+	"errors"
+	"testing"
+
+	"github.com/stretchr/testify/assert"
+
+	"go.opentelemetry.io/otel"
+	"go.opentelemetry.io/otel/propagation"
+	"go.opentelemetry.io/otel/sdk/trace"
+	"go.opentelemetry.io/otel/sdk/trace/tracetest"
+)
+
+var tracings struct {
+	SpanExporter  *tracetest.InMemoryExporter
+	TraceProvider *trace.TracerProvider
+}
+
+// context examples
+// https://github.com/go-logr/logr/pull/27
+
+// setupOTelSDK bootstraps the OpenTelemetry pipeline.
+// If it does not return an error, make sure to call shutdown for proper cleanup.
+func setupOTelSDK(ctx context.Context) (shutdown func(context.Context) error, err error) {
+	var shutdownFuncs []func(context.Context) error
+
+	// shutdown() calls cleanup functions registered via shutdownFuncs.
+	// The errors from the calls are joined.
+	// Each registered cleanup will be invoked once.
+	shutdown = func(ctx context.Context) error {
+		var err error
+		for _, fn := range shutdownFuncs {
+			err = errors.Join(err, fn(ctx))
+		}
+		shutdownFuncs = nil
+		return err
+	}
+
+	// handleErr calls shutdown for cleanup and makes sure that all errors are returned.
+	handleErr := func(inErr error) {
+		err = errors.Join(inErr, shutdown(ctx))
+	}
+
+	// Set up propagator.
+	prop := newPropagator()
+	otel.SetTextMapPropagator(prop)
+
+	// Set up trace provider.
+	tracerProvider, err := newTraceProvider()
+	if err != nil {
+		handleErr(err)
+		return
+	}
+	shutdownFuncs = append(shutdownFuncs, tracerProvider.Shutdown)
+	otel.SetTracerProvider(tracerProvider)
+
+	return
+}
+
+func newPropagator() propagation.TextMapPropagator {
+	return propagation.NewCompositeTextMapPropagator(
+		propagation.TraceContext{},
+		propagation.Baggage{},
+	)
+}
+
+func newTraceProvider() (*trace.TracerProvider, error) {
+	tracings.SpanExporter = tracetest.NewInMemoryExporter()
+
+	tracings.TraceProvider = trace.NewTracerProvider(
+		trace.WithBatcher(tracings.SpanExporter),
+	)
+
+	return tracings.TraceProvider, nil
+}
+
+// Example tests to show how to work with oTel
+
+const name = "opendatahub.io/kubeflow/components/odh-notebook-controller/controllers/opentelemetry_test.go"
+
+var (
+	tracer = otel.Tracer(name)
+)
+
+func TestHelloOTel(t *testing.T) {
+	// Set up OpenTelemetry.
+	otelShutdown, err := setupOTelSDK(ctx)
+	if err != nil {
+		return
+	}
+	// Handle shutdown properly so nothing leaks.
+	defer func() {
+		err = errors.Join(err, otelShutdown(context.Background()))
+	}()
+
+	func() {
+		_, span := tracer.Start(context.Background(), "roll")
+		//defer span.End()
+		span.AddEvent("do_stuff")
+		span.End()
+	}()
+
+	assert.Nil(t, tracings.TraceProvider.ForceFlush(context.Background()))
+	spans := tracings.SpanExporter.GetSpans()
+	assert.Len(t, spans, 1)
+}
+
+// TestOpenTelemetryInMemoryExporterReadout demonstrates accessing spans from test code.
+// Code is copied from https://github.com/open-telemetry/opentelemetry-go/issues/2080
+func TestOpenTelemetryInMemoryExporterReadout(t *testing.T) {
+	ctx := context.Background()
+
+	exp := tracetest.NewInMemoryExporter()
+
+	tp := trace.NewTracerProvider(
+		trace.WithBatcher(exp),
+	)
+
+	tracer := tp.Tracer("tracer")
+
+	_, span := tracer.Start(ctx, "span")
+	span.End()
+
+	err := tp.ForceFlush(ctx)
+	assert.NoError(t, err)
+
+	// Expect well-defined behavior due to calling ForceFlush
+	assert.Len(t, exp.GetSpans(), 1)
+}

components/odh-notebook-controller/controllers/suite_test.go

@@ -18,27 +18,29 @@ import (
 	"context"
 	"crypto/tls"
 	"fmt"
-	"k8s.io/utils/ptr"
 	"net"
 	"os"
 	"path/filepath"
 	"testing"
 	"time"
 
-	v1 "k8s.io/api/core/v1"
-	netv1 "k8s.io/api/networking/v1"
-	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	. "github.com/onsi/ginkgo"
+	. "github.com/onsi/gomega"
+
+	"go.opentelemetry.io/otel"
 
 	"go.uber.org/zap/zapcore"
 	"k8s.io/apimachinery/pkg/runtime"
 	utilruntime "k8s.io/apimachinery/pkg/util/runtime"
+	"k8s.io/utils/ptr"
 	ctrl "sigs.k8s.io/controller-runtime"
 
 	nbv1 "github.com/kubeflow/kubeflow/components/notebook-controller/api/v1"
-
-	. "github.com/onsi/ginkgo"
-	. "github.com/onsi/gomega"
 	routev1 "github.com/openshift/api/route/v1"
+	v1 "k8s.io/api/core/v1"
+	netv1 "k8s.io/api/networking/v1"
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+
 	clientgoscheme "k8s.io/client-go/kubernetes/scheme"
 	"k8s.io/client-go/rest"
 	"sigs.k8s.io/controller-runtime/pkg/client"
@@ -63,6 +65,7 @@ var (
 
 	ctx            context.Context
 	cancel         context.CancelFunc
+	otelShutdown   func(context.Context) error
 	managerStopped = make(chan struct{})
 
 	testNamespaces = []string{}
@@ -80,6 +83,7 @@ func TestAPIs(t *testing.T) {
 }
 
 var _ = BeforeSuite(func() {
+	var err error
 	ctx, cancel = context.WithCancel(context.Background())
 
 	// Initialize logger
@@ -89,6 +93,12 @@ var _ = BeforeSuite(func() {
 	}
 	logf.SetLogger(zap.New(zap.WriteTo(GinkgoWriter), zap.UseFlagOptions(&opts)))
 
+	// initialize tracer
+	// Set up OpenTelemetry.
+	otelShutdown, err = setupOTelSDK(ctx)
+	Expect(err).ToNot(HaveOccurred())
+	tracer = otel.Tracer("odh-notebook-controller/controllers/suite_test.go")
+
 	// Initialize test environment:
 	// https://pkg.go.dev/sigs.k8s.io/controller-runtime/pkg/envtest#Environment.Start
 	By("Bootstrapping test environment")
@@ -120,7 +130,6 @@ var _ = BeforeSuite(func() {
 		GinkgoT().Logf("DEBUG_WRITE_AUDITLOG environment variable was not provided")
 	}
 
-	var err error
 	cfg, err = envTest.Start()
 	Expect(err).NotTo(HaveOccurred())
 	Expect(cfg).NotTo(BeNil())
@@ -240,4 +249,7 @@ var _ = AfterSuite(func() {
 	// TODO: Stop cert controller-runtime.certwatcher before manager
 	err := envTest.Stop()
 	Expect(err).NotTo(HaveOccurred())
+
+	err = otelShutdown(context.Background())
+	Expect(err).NotTo(HaveOccurred())
 })