chore: Refactor operator logs (apache#4586)

- Reduce amount of informational log events by using Debug level on events like "Reconciling ...", "Invoking action ..." - Use Debug level for each "Reconciling ..." log event - Use new "Initializing ..." Info level log event when a resource is initializing (used in metrics tests to verify metrics) - Log error details on state transition to Phase "Error" for resources Integration, Build, KameletBinding and Pipe
christophd · Jul 20, 2023 · 42791ff · 42791ff
1 parent 2d0935d
commit 42791ff
Show file tree

Hide file tree

Showing 20 changed files with 83 additions and 27 deletions.
diff --git a/e2e/commonwithcustominstall/operator_metrics_test.go b/e2e/commonwithcustominstall/operator_metrics_test.go
@@ -61,7 +61,7 @@ func TestMetrics(t *testing.T) {
 	WithNewTestNamespace(t, func(ns string) {
 		name := "java"
 		operatorID := "camel-k-metrics"
-		Expect(KamelInstallWithID(operatorID, ns).Execute()).To(Succeed())
+		Expect(KamelInstallWithID(operatorID, ns, "--log-level", "debug").Execute()).To(Succeed())
 		Expect(KamelRunWithID(operatorID, ns, "files/Java.java",
 			"-t", "prometheus.enabled=true",
 			"-t", "prometheus.pod-monitor=false",
@@ -104,7 +104,7 @@ func TestMetrics(t *testing.T) {
 			err = NewLogWalker(&logs).
 				AddStep(MatchFields(IgnoreExtras, Fields{
 					"LoggerName":  Equal("camel-k.controller.build"),
-					"Message":     Equal("state transition"),
+					"Message":     Equal("State transition"),
 					"PhaseFrom":   Equal(string(v1.BuildPhaseScheduling)),
 					"PhaseTo":     Equal(string(v1.BuildPhasePending)),
 					"RequestName": Equal(build.Name),
@@ -115,7 +115,7 @@ func TestMetrics(t *testing.T) {
 				}), LogEntryNoop).
 				AddStep(MatchFields(IgnoreExtras, Fields{
 					"LoggerName":  Equal("camel-k.controller.build"),
-					"Message":     Equal("state transition"),
+					"Message":     Equal("State transition"),
 					"PhaseFrom":   Equal(string(v1.BuildPhaseRunning)),
 					"PhaseTo":     Equal(string(v1.BuildPhaseSucceeded)),
 					"RequestName": Equal(build.Name),
@@ -422,7 +422,7 @@ func TestMetrics(t *testing.T) {
 			err = NewLogWalker(&logs).
 				AddStep(MatchFields(IgnoreExtras, Fields{
 					"LoggerName":  Equal("camel-k.controller.build"),
-					"Message":     Equal("state transition"),
+					"Message":     Equal("State transition"),
 					"PhaseFrom":   Equal(string(v1.BuildPhaseScheduling)),
 					"PhaseTo":     Equal(string(v1.BuildPhasePending)),
 					"RequestName": Equal(build.Name),

diff --git a/pkg/controller/build/build_controller.go b/pkg/controller/build/build_controller.go
@@ -107,7 +107,7 @@ type reconcileBuild struct {
 // Result.Requeue is true, otherwise upon completion it will remove the work from the queue.
 func (r *reconcileBuild) Reconcile(ctx context.Context, request reconcile.Request) (reconcile.Result, error) {
 	rlog := Log.WithValues("request-namespace", request.Namespace, "request-name", request.Name)
-	rlog.Info("Reconciling Build")
+	rlog.Debug("Reconciling Build")
 
 	// Make sure the operator is allowed to act on namespace
 	if ok, err := platform.IsOperatorAllowedOnNamespace(ctx, r.client, request.Namespace); err != nil {
@@ -176,7 +176,7 @@ func (r *reconcileBuild) Reconcile(ctx context.Context, request reconcile.Reques
 		a.InjectRecorder(r.recorder)
 
 		if a.CanHandle(target) {
-			targetLog.Infof("Invoking action %s", a.Name())
+			targetLog.Debugf("Invoking action %s", a.Name())
 
 			newTarget, err := a.Handle(ctx, target)
 			if err != nil {
@@ -192,10 +192,23 @@ func (r *reconcileBuild) Reconcile(ctx context.Context, request reconcile.Reques
 
 				if newTarget.Status.Phase != instance.Status.Phase {
 					targetLog.Info(
-						"state transition",
+						"State transition",
 						"phase-from", instance.Status.Phase,
 						"phase-to", newTarget.Status.Phase,
 					)
+
+					if newTarget.Status.Phase == v1.BuildPhaseError || newTarget.Status.Phase == v1.BuildPhaseFailed {
+						reason := string(newTarget.Status.Phase)
+
+						if newTarget.Status.Failure != nil {
+							reason = newTarget.Status.Failure.Reason
+						}
+
+						targetLog.Info(
+							"Build error",
+							"reason", reason,
+							"error-message", newTarget.Status.Error)
+					}
 				}
 
 				target = newTarget

diff --git a/pkg/controller/build/initialize_pod.go b/pkg/controller/build/initialize_pod.go
@@ -49,6 +49,8 @@ func (action *initializePodAction) CanHandle(build *v1.Build) bool {
 
 // Handle handles the builds.
 func (action *initializePodAction) Handle(ctx context.Context, build *v1.Build) (*v1.Build, error) {
+	action.L.Info("Initializing Build")
+
 	if err := deleteBuilderPod(ctx, action.client, build); err != nil {
 		return nil, fmt.Errorf("cannot delete build pod: %w", err)
 	}

diff --git a/pkg/controller/build/initialize_routine.go b/pkg/controller/build/initialize_routine.go
@@ -43,6 +43,8 @@ func (action *initializeRoutineAction) CanHandle(build *v1.Build) bool {
 
 // Handle handles the builds.
 func (action *initializeRoutineAction) Handle(ctx context.Context, build *v1.Build) (*v1.Build, error) {
+	action.L.Info("Initializing Build")
+
 	build.Status.Phase = v1.BuildPhaseScheduling
 
 	return build, nil

diff --git a/pkg/controller/build/monitor_routine.go b/pkg/controller/build/monitor_routine.go
@@ -211,7 +211,7 @@ func (action *monitorRoutineAction) updateBuildStatus(ctx context.Context, build
 		return err
 	}
 	if target.Status.Phase != build.Status.Phase {
-		action.L.Info("state transition", "phase-from", build.Status.Phase, "phase-to", target.Status.Phase)
+		action.L.Info("State transition", "phase-from", build.Status.Phase, "phase-to", target.Status.Phase)
 	}
 	event.NotifyBuildUpdated(ctx, action.client, action.recorder, build, target)
 	build.Status = target.Status

diff --git a/pkg/controller/build/schedule.go b/pkg/controller/build/schedule.go
@@ -102,7 +102,7 @@ func (action *scheduleAction) patchBuildStatus(ctx context.Context, build *v1.Bu
 	}
 
 	if target.Status.Phase != build.Status.Phase {
-		action.L.Info("state transition", "phase-from", build.Status.Phase, "phase-to", target.Status.Phase)
+		action.L.Info("State transition", "phase-from", build.Status.Phase, "phase-to", target.Status.Phase)
 	}
 	event.NotifyBuildUpdated(ctx, action.client, action.recorder, build, target)
 

diff --git a/pkg/controller/catalog/catalog_controller.go b/pkg/controller/catalog/catalog_controller.go
@@ -112,7 +112,7 @@ type reconcileCatalog struct {
 // Result.Requeue is true, otherwise upon completion it will remove the work from the queue.
 func (r *reconcileCatalog) Reconcile(ctx context.Context, request reconcile.Request) (reconcile.Result, error) {
 	rlog := Log.WithValues("request-namespace", request.Namespace, "request-name", request.Name)
-	rlog.Info("Reconciling CamelCatalog")
+	rlog.Debug("Reconciling CamelCatalog")
 
 	// Make sure the operator is allowed to act on namespace
 	if ok, err := platform.IsOperatorAllowedOnNamespace(ctx, r.client, request.Namespace); err != nil {
@@ -185,7 +185,7 @@ func (r *reconcileCatalog) Reconcile(ctx context.Context, request reconcile.Requ
 
 			if targetPhase != phaseFrom {
 				targetLog.Info(
-					"state transition",
+					"State transition",
 					"phase-from", phaseFrom,
 					"phase-to", target.Status.Phase,
 				)

diff --git a/pkg/controller/catalog/initialize.go b/pkg/controller/catalog/initialize.go
@@ -76,6 +76,8 @@ func (action *initializeAction) CanHandle(catalog *v1.CamelCatalog) bool {
 }
 
 func (action *initializeAction) Handle(ctx context.Context, catalog *v1.CamelCatalog) (*v1.CamelCatalog, error) {
+	action.L.Info("Initializing CamelCatalog")
+
 	platform, err := platformutil.GetOrFindLocal(ctx, action.client, catalog.Namespace)
 
 	if err != nil {

diff --git a/pkg/controller/integration/initialize.go b/pkg/controller/integration/initialize.go
@@ -51,6 +51,8 @@ func (action *initializeAction) CanHandle(integration *v1.Integration) bool {
 
 // Handle handles the integrations.
 func (action *initializeAction) Handle(ctx context.Context, integration *v1.Integration) (*v1.Integration, error) {
+	action.L.Info("Initializing Integration")
+
 	if _, err := trait.Apply(ctx, action.client, integration, nil); err != nil {
 		integration.Status.Phase = v1.IntegrationPhaseError
 		integration.SetReadyCondition(corev1.ConditionFalse,

diff --git a/pkg/controller/integration/integration_controller.go b/pkg/controller/integration/integration_controller.go
@@ -309,7 +309,7 @@ type reconcileIntegration struct {
 // Result.Requeue is true, otherwise upon completion it will remove the work from the queue.
 func (r *reconcileIntegration) Reconcile(ctx context.Context, request reconcile.Request) (reconcile.Result, error) {
 	rlog := Log.WithValues("request-namespace", request.Namespace, "request-name", request.Name)
-	rlog.Info("Reconciling Integration")
+	rlog.Debug("Reconciling Integration")
 
 	// Make sure the operator is allowed to act on namespace
 	if ok, err := platform.IsOperatorAllowedOnNamespace(ctx, r.client, request.Namespace); err != nil {
@@ -354,7 +354,7 @@ func (r *reconcileIntegration) Reconcile(ctx context.Context, request reconcile.
 		a.InjectLogger(targetLog)
 
 		if a.CanHandle(target) {
-			targetLog.Infof("Invoking action %s", a.Name())
+			targetLog.Debugf("Invoking action %s", a.Name())
 
 			newTarget, err := a.Handle(ctx, target)
 			if err != nil {
@@ -398,10 +398,19 @@ func (r *reconcileIntegration) update(ctx context.Context, base *v1.Integration,
 
 	if target.Status.Phase != base.Status.Phase {
 		log.Info(
-			"state transition",
+			"State transition",
 			"phase-from", base.Status.Phase,
 			"phase-to", target.Status.Phase,
 		)
+
+		if target.Status.Phase == v1.IntegrationPhaseError {
+			if cond := target.Status.GetCondition(v1.IntegrationConditionReady); cond != nil && cond.Status == corev1.ConditionFalse {
+				log.Info(
+					"Integration error",
+					"reason", cond.GetReason(),
+					"error-message", cond.GetMessage())
+			}
+		}
 	}
 
 	return nil

diff --git a/pkg/controller/integrationkit/initialize.go b/pkg/controller/integrationkit/initialize.go
@@ -53,6 +53,7 @@ func (action *initializeAction) Handle(ctx context.Context, kit *v1.IntegrationK
 		return nil, err
 	}
 
+	action.L.Info("Initializing IntegrationKit")
 	kit.Status.Version = defaults.Version
 
 	if kit.Spec.Image == "" {

diff --git a/pkg/controller/integrationkit/integrationkit_controller.go b/pkg/controller/integrationkit/integrationkit_controller.go
@@ -193,7 +193,7 @@ type reconcileIntegrationKit struct {
 // Result.Requeue is true, otherwise upon completion it will remove the work from the queue.
 func (r *reconcileIntegrationKit) Reconcile(ctx context.Context, request reconcile.Request) (reconcile.Result, error) {
 	rlog := Log.WithValues("request-namespace", request.Namespace, "request-name", request.Name)
-	rlog.Info("Reconciling IntegrationKit")
+	rlog.Debug("Reconciling IntegrationKit")
 
 	// Make sure the operator is allowed to act on namespace
 	if ok, err := platform.IsOperatorAllowedOnNamespace(ctx, r.client, request.Namespace); err != nil {
@@ -291,7 +291,7 @@ func (r *reconcileIntegrationKit) Reconcile(ctx context.Context, request reconci
 
 				if targetPhase != instance.Status.Phase {
 					targetLog.Info(
-						"state transition",
+						"State transition",
 						"phase-from", instance.Status.Phase,
 						"phase-to", targetPhase,
 					)

diff --git a/pkg/controller/integrationplatform/initialize.go b/pkg/controller/integrationplatform/initialize.go
@@ -66,6 +66,7 @@ func (action *initializeAction) Handle(ctx context.Context, platform *v1.Integra
 		return nil, nil
 	}
 
+	action.L.Info("Initializing IntegrationPlatform")
 	if err = platformutil.ConfigureDefaults(ctx, action.client, platform, true); err != nil {
 		return nil, err
 	}

diff --git a/pkg/controller/integrationplatform/integrationplatform_controller.go b/pkg/controller/integrationplatform/integrationplatform_controller.go
@@ -121,7 +121,7 @@ type reconcileIntegrationPlatform struct {
 // Result.Requeue is true, otherwise upon completion it will remove the work from the queue.
 func (r *reconcileIntegrationPlatform) Reconcile(ctx context.Context, request reconcile.Request) (reconcile.Result, error) {
 	rlog := Log.WithValues("request-namespace", request.Namespace, "request-name", request.Name)
-	rlog.Info("Reconciling IntegrationPlatform")
+	rlog.Debug("Reconciling IntegrationPlatform")
 
 	// Make sure the operator is allowed to act on namespace
 	if ok, err := platform.IsOperatorAllowedOnNamespace(ctx, r.client, request.Namespace); err != nil {
@@ -193,7 +193,7 @@ func (r *reconcileIntegrationPlatform) Reconcile(ctx context.Context, request re
 
 				if targetPhase != phaseFrom {
 					targetLog.Info(
-						"state transition",
+						"State transition",
 						"phase-from", phaseFrom,
 						"phase-to", target.Status.Phase,
 					)

diff --git a/pkg/controller/kamelet/initialize.go b/pkg/controller/kamelet/initialize.go
@@ -42,5 +42,7 @@ func (action *initializeAction) CanHandle(kamelet *v1.Kamelet) bool {
 }
 
 func (action *initializeAction) Handle(ctx context.Context, kamelet *v1.Kamelet) (*v1.Kamelet, error) {
+	action.L.Info("Initializing Kamelet")
+
 	return kameletutils.Initialize(kamelet)
 }
diff --git a/pkg/controller/kamelet/kamelet_controller.go b/pkg/controller/kamelet/kamelet_controller.go
@@ -113,7 +113,7 @@ type reconcileKamelet struct {
 // Result.Requeue is true, otherwise upon completion it will remove the work from the queue.
 func (r *reconcileKamelet) Reconcile(ctx context.Context, request reconcile.Request) (reconcile.Result, error) {
 	rlog := Log.WithValues("request-namespace", request.Namespace, "request-name", request.Name)
-	rlog.Info("Reconciling Kamelet")
+	rlog.Debug("Reconciling Kamelet")
 
 	// Make sure the operator is allowed to act on namespace
 	if ok, err := platform.IsOperatorAllowedOnNamespace(ctx, r.client, request.Namespace); err != nil {
@@ -164,7 +164,7 @@ func (r *reconcileKamelet) Reconcile(ctx context.Context, request reconcile.Requ
 			continue
 		}
 
-		targetLog.Infof("Invoking action %s", a.Name())
+		targetLog.Debugf("Invoking action %s", a.Name())
 
 		phaseFrom := target.Status.Phase
 
@@ -186,7 +186,7 @@ func (r *reconcileKamelet) Reconcile(ctx context.Context, request reconcile.Requ
 
 			if targetPhase != phaseFrom {
 				targetLog.Info(
-					"state transition",
+					"State transition",
 					"phase-from", phaseFrom,
 					"phase-to", target.Status.Phase,
 				)

diff --git a/pkg/controller/kameletbinding/initialize.go b/pkg/controller/kameletbinding/initialize.go
@@ -52,6 +52,8 @@ func (action *initializeAction) CanHandle(binding *v1alpha1.KameletBinding) bool
 }
 
 func (action *initializeAction) Handle(ctx context.Context, binding *v1alpha1.KameletBinding) (*v1alpha1.KameletBinding, error) {
+	action.L.Info("Initializing KameletBinding")
+
 	it, err := CreateIntegrationFor(ctx, action.client, binding)
 	if err != nil {
 		binding.Status.Phase = v1alpha1.KameletBindingPhaseError

diff --git a/pkg/controller/kameletbinding/kameletbinding_controller.go b/pkg/controller/kameletbinding/kameletbinding_controller.go
@@ -143,7 +143,7 @@ type ReconcileKameletBinding struct {
 // Result.Requeue is true, otherwise upon completion it will remove the work from the queue.
 func (r *ReconcileKameletBinding) Reconcile(ctx context.Context, request reconcile.Request) (reconcile.Result, error) {
 	rlog := Log.WithValues("request-namespace", request.Namespace, "request-name", request.Name)
-	rlog.Info("Reconciling KameletBinding")
+	rlog.Debug("Reconciling KameletBinding")
 
 	// Make sure the operator is allowed to act on namespace
 	if ok, err := platform.IsOperatorAllowedOnNamespace(ctx, r.client, request.Namespace); err != nil {
@@ -190,7 +190,7 @@ func (r *ReconcileKameletBinding) Reconcile(ctx context.Context, request reconci
 		a.InjectLogger(targetLog)
 
 		if a.CanHandle(target) {
-			targetLog.Infof("Invoking action %s", a.Name())
+			targetLog.Debugf("Invoking action %s", a.Name())
 
 			target, err = a.Handle(ctx, target)
 			if err != nil {
@@ -229,10 +229,19 @@ func (r *ReconcileKameletBinding) update(ctx context.Context, base *v1alpha1.Kam
 
 	if target.Status.Phase != base.Status.Phase {
 		log.Info(
-			"state transition",
+			"State transition",
 			"phase-from", base.Status.Phase,
 			"phase-to", target.Status.Phase,
 		)
+
+		if target.Status.Phase == v1alpha1.KameletBindingPhaseError {
+			if cond := target.Status.GetCondition(v1alpha1.KameletBindingIntegrationConditionError); cond != nil {
+				log.Info(
+					"Integration error",
+					"reason", cond.GetReason(),
+					"error-message", cond.GetMessage())
+			}
+		}
 	}
 
 	return nil

diff --git a/pkg/controller/pipe/initialize.go b/pkg/controller/pipe/initialize.go
@@ -52,6 +52,8 @@ func (action *initializeAction) CanHandle(binding *v1.Pipe) bool {
 }
 
 func (action *initializeAction) Handle(ctx context.Context, binding *v1.Pipe) (*v1.Pipe, error) {
+	action.L.Info("Initializing Pipe")
+
 	it, err := CreateIntegrationFor(ctx, action.client, binding)
 	if err != nil {
 		binding.Status.Phase = v1.PipePhaseError

diff --git a/pkg/controller/pipe/pipe_controller.go b/pkg/controller/pipe/pipe_controller.go
@@ -143,7 +143,7 @@ type ReconcilePipe struct {
 // Result.Requeue is true, otherwise upon completion it will remove the work from the queue.
 func (r *ReconcilePipe) Reconcile(ctx context.Context, request reconcile.Request) (reconcile.Result, error) {
 	rlog := Log.WithValues("request-namespace", request.Namespace, "request-name", request.Name)
-	rlog.Info("Reconciling Pipe")
+	rlog.Debug("Reconciling Pipe")
 
 	// Make sure the operator is allowed to act on namespace
 	if ok, err := platform.IsOperatorAllowedOnNamespace(ctx, r.client, request.Namespace); err != nil {
@@ -190,7 +190,7 @@ func (r *ReconcilePipe) Reconcile(ctx context.Context, request reconcile.Request
 		a.InjectLogger(targetLog)
 
 		if a.CanHandle(target) {
-			targetLog.Infof("Invoking action %s", a.Name())
+			targetLog.Debugf("Invoking action %s", a.Name())
 
 			target, err = a.Handle(ctx, target)
 			if err != nil {
@@ -229,10 +229,19 @@ func (r *ReconcilePipe) update(ctx context.Context, base *v1.Pipe, target *v1.Pi
 
 	if target.Status.Phase != base.Status.Phase {
 		log.Info(
-			"state transition",
+			"State transition",
 			"phase-from", base.Status.Phase,
 			"phase-to", target.Status.Phase,
 		)
+
+		if target.Status.Phase == v1.PipePhaseError {
+			if cond := target.Status.GetCondition(v1.PipeIntegrationConditionError); cond != nil {
+				log.Info(
+					"Integration error",
+					"reason", cond.GetReason(),
+					"error-message", cond.GetMessage())
+			}
+		}
 	}
 
 	return nil