Merge pull request #2162 from xiaoweim/add_expander_stage_logging

feat: add optional logging for expander stages

experiments/compositions/composition/internal/controller/expander_reconciler.go

@@ -174,13 +174,20 @@ func (r *ExpanderReconciler) Reconcile(ctx context.Context, req ctrl.Request) (c
 			logger.Error(err, "unable to update Plan status")
 		}
 	}()
+	expanderDebugLogsEnabled := false
+	_, exist := inputcr.GetAnnotations()["composition-expander-debug-logs"]
+	if exist {
+		expanderDebugLogsEnabled = true
+		logger.Info("annotation'composition-expander-debug-logs' is turned on.")
+	}
+	logger.Info("annotation'composition-expander-debug-logs' is turned off.")
 
 	// ------------------- EVALUATION SECTION -----------------------
 	stagesEvaluated := []string{}
 	values := map[string]interface{}{}
 	planUpdated := false
 	waitRequested := false
-	for _, expander := range compositionCR.Spec.Expanders {
+	for i, expander := range compositionCR.Spec.Expanders {
 		logger = loggerCR.WithName(expander.Name).WithName("Expand")
 
 		uri, ev, reason, err := r.getExpanderValue(ctx, expander.Version, expander.Type)
@@ -193,14 +200,17 @@ func (r *ExpanderReconciler) Reconcile(ctx context.Context, req ctrl.Request) (c
 
 		logger.Info("Got valid expander uri", "uri", uri)
 
+		if expanderDebugLogsEnabled {
+			r.Recorder.Event(&inputcr, "Normal", fmt.Sprintf("Running expander stage %d: %s", i, expander.Name), expanderDebugLog(&inputcr))
+		}
 		if ev.Spec.Type == compositionv1alpha1.ExpanderTypeJob {
 			reason, err := r.runJob(ctx, logger, &inputcr, expander.Name, planNN.Name, uri, ev.Spec.ImageRegistry)
 			if err != nil {
 				newStatus.AppendErrorCondition(expander.Name, err.Error(), reason)
 				return ctrl.Result{}, err
 			}
 		} else {
-			newValues, updated, reason, err := r.evaluateAndSavePlan(ctx, logger, &inputcr, values, expander, planNN, ev, uri)
+			newValues, updated, reason, err := r.evaluateAndSavePlan(ctx, logger, &inputcr, values, expander, planNN, ev, uri, expanderDebugLogsEnabled)
 			_, iswaitErr := err.(*EvaluateWaitError)
 			if iswaitErr {
 				newStatus.AppendWaitingCondition(expander.Name, err.Error(), reason)
@@ -222,6 +232,9 @@ func (r *ExpanderReconciler) Reconcile(ctx context.Context, req ctrl.Request) (c
 		newStatus.ClearCondition(compositionv1alpha1.Ready)
 		message := fmt.Sprintf("Evaluated stages: %s", strings.Join(stagesEvaluated, ", "))
 		newStatus.AppendCondition(compositionv1alpha1.Ready, metav1.ConditionFalse, message, "EvaluationPending")
+		if expanderDebugLogsEnabled {
+			r.Recorder.Event(&inputcr, "Normal", fmt.Sprintf("Evaluated expander stage %d: %s", i, expander.Name), expanderDebugLog(&inputcr))
+		}
 	}
 
 	// ------------------- APPLIER SECTION -----------------------
@@ -329,6 +342,14 @@ func (r *ExpanderReconciler) Reconcile(ctx context.Context, req ctrl.Request) (c
 		newStatus.ClearCondition(compositionv1alpha1.Ready)
 		message := fmt.Sprintf("Evaluated stages: %s \n Applied stages: %s", strings.Join(stagesEvaluated, ", "), strings.Join(stagesApplied, ", "))
 		newStatus.AppendCondition(compositionv1alpha1.Ready, metav1.ConditionFalse, message, "PendingStages")
+
+		if expanderDebugLogsEnabled {
+			r.Recorder.Event(&inputcr, "Normal", fmt.Sprintf("Finished expander stage %d: %s", index, expander), expanderDebugLog(&inputcr)+fmt.Sprintf("---resource count: %d", applier.Count()))
+			for i, resourceStatus := range newStatus.Stages[expander].LastApplied {
+				logger.Info("Resource %d, Resource name: %s, resource namespace: %s, resource gvk: %s %s %s, resource status: %s",
+					i, resourceStatus.Name, resourceStatus.Namespace, resourceStatus.Group, resourceStatus.Version, resourceStatus.Kind, resourceStatus.Health)
+			}
+		}
 	}
 
 	// Inject plan.Ready Condition with list of expanders
@@ -418,7 +439,7 @@ func (r *ExpanderReconciler) runJob(ctx context.Context, logger logr.Logger,
 
 func (r *ExpanderReconciler) evaluateAndSavePlan(ctx context.Context, logger logr.Logger,
 	cr *unstructured.Unstructured, values map[string]interface{}, expander compositionv1alpha1.Expander,
-	planNN types.NamespacedName, ev *compositionv1alpha1.ExpanderVersion, grpcService string) (map[string]interface{}, bool, string, error) {
+	planNN types.NamespacedName, ev *compositionv1alpha1.ExpanderVersion, grpcService string, expanderDebugLogEnabled bool) (map[string]interface{}, bool, string, error) {
 	// Set up a connection to the server.
 	updated := false
 
@@ -493,16 +514,18 @@ func (r *ExpanderReconciler) evaluateAndSavePlan(ctx context.Context, logger log
 		logger.Error(err, "failed to marshall Getter Values")
 		return values, updated, "MarshallValuesFailed", err
 	}
-
+	evaluateRequest := &pb.EvaluateRequest{
+		Config:   configBytes,
+		Context:  contextBytes,
+		Facade:   facadeBytes,
+		Resource: r.InputGVR.Resource,
+		Value:    valuesBytes,
+	}
 	expanderClient := pb.NewExpanderClient(conn)
-	result, err := expanderClient.Evaluate(ctx,
-		&pb.EvaluateRequest{
-			Config:   configBytes,
-			Context:  contextBytes,
-			Facade:   facadeBytes,
-			Resource: r.InputGVR.Resource,
-			Value:    valuesBytes,
-		})
+	if expanderDebugLogEnabled {
+		logger.Info(expanderDebugLog(cr) + fmt.Sprintf("---sending expander request: %v", evaluateRequest))
+	}
+	result, err := expanderClient.Evaluate(ctx, evaluateRequest)
 	if err != nil {
 		logger.Error(err, "expander.Evaluate() Failed", "expander", expander.Name)
 		return values, updated, "EvaluateError", err
@@ -517,6 +540,10 @@ func (r *ExpanderReconciler) evaluateAndSavePlan(ctx context.Context, logger log
 		err = fmt.Errorf("Evaluate Failed: %s", result.Error.Message)
 		return values, updated, "EvaluateStatusFailed", err
 	}
+	if expanderDebugLogEnabled {
+		logger.Info(expanderDebugLog(cr) + fmt.Sprintf("---sent expander request: %v, received results: %v", evaluateRequest, result))
+		r.Recorder.Event(cr, "Normal", fmt.Sprintf("Expander stage %s evaluation completed", expander.Name), expanderDebugLog(cr)+fmt.Sprintf("---request: %v, result: %v", evaluateRequest, result))
+	}
 
 	// Write to Plan object
 	// Re-read the Plan CR to load the expanded manifests
@@ -589,6 +616,11 @@ func (r *ExpanderReconciler) evaluateAndSavePlan(ctx context.Context, logger log
 	return values, updated, "", nil
 }
 
+func expanderDebugLog(cr *unstructured.Unstructured) string {
+	// TODO(@xiaoweim): add the UID in the future if possible
+	return fmt.Sprintf("expanderDebugLog---%s/%s/%s---version: %d", cr.GetKind(), cr.GetNamespace(), cr.GetName(), cr.GetGeneration())
+}
+
 func (r *ExpanderReconciler) enqueueAllFromGVK(ctx context.Context, _ client.Object) []reconcile.Request {
 	logger := log.FromContext(ctx)
 	logger.Info("Got notification of changed CRD")

experiments/compositions/composition/tests/data/TestSimpleCompositionExpanderLoggingEnabled/input.yaml

@@ -0,0 +1,161 @@
+# Copyright 2024 Google LLC
+#
+# 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.
+
+
+apiVersion: apiextensions.k8s.io/v1
+kind: CustomResourceDefinition
+metadata:
+  name: pconfigs.facade.foocorp.com
+spec:
+  group: facade.foocorp.com
+  names:
+    kind: PConfig
+    listKind: PConfigList
+    plural: pconfigs
+    singular: pconfig
+  scope: Namespaced
+  versions:
+  - name: v1alpha1
+    schema:
+      openAPIV3Schema:
+        description: Schema for the pconfig
+        properties:
+          apiVersion:
+            description: api-version of api
+            type: string
+          kind:
+            description: gvk Kind
+            type: string
+          metadata:
+            type: object
+          spec:
+            description: PConfig spec
+            properties:
+              project:
+                type: string
+            required:
+            - project
+            type: object
+          status:
+            description: PConfig status
+            type: object
+        type: object
+    served: true
+    storage: true
+    subresources:
+      status: {}
+---
+apiVersion: rbac.authorization.k8s.io/v1
+kind: ClusterRole
+metadata:
+  name: composition-facade-foocorp
+rules:
+- apiGroups:
+  - facade.foocorp.com
+  resources:
+  - '*'
+  verbs:
+  - get
+  - list
+  - patch
+  - update
+  - watch
+  - create
+  - delete
+- apiGroups:
+  - facade.foocorp.com
+  resources:
+  - "*/status"
+  verbs:
+  - get
+  - update
+- apiGroups: ["*"]
+  resources: ["*"]
+  verbs: ["*"]
+---
+apiVersion: rbac.authorization.k8s.io/v1
+kind: ClusterRoleBinding
+metadata:
+  name: composition-facade-foocorp
+roleRef:
+  apiGroup: rbac.authorization.k8s.io
+  kind: ClusterRole
+  name: composition-facade-foocorp
+subjects:
+- kind: ServiceAccount
+  name: composition-controller-manager
+  namespace: composition-system
+---
+apiVersion: composition.google.com/v1alpha1
+kind: GetterConfiguration
+metadata:
+  name: projectvalues
+  namespace: default
+spec:
+  valuesFrom:
+  - name: commondata
+    resourceRef:
+      group: ""
+      version: v1
+      kind: ConfigMap
+      resource: configmaps
+      name: common-config
+    fieldRef:
+    - path: ".data"
+      as: data
+---
+apiVersion: composition.google.com/v1alpha1
+kind: Composition
+metadata:
+  name: projectconfigmap
+  namespace: default
+spec:
+  inputAPIGroup: pconfigs.facade.foocorp.com
+  expanders:
+  - type: jinja2
+    version: v0.0.1
+    name: common
+    template: |
+      apiVersion: v1
+      kind: ConfigMap
+      metadata:
+        name: common-config
+        namespace: {{ pconfigs.metadata.namespace }}
+        labels:
+          createdby: "composition-namespaceconfigmap"
+      data:
+        key1: value1
+---
+apiVersion: v1
+kind: Namespace
+metadata:
+  name: team-a
+---
+apiVersion: composition.google.com/v1alpha1
+kind: Context
+metadata:
+  name: context
+  namespace: team-a
+spec:
+  project: proj-a
+---
+apiVersion: facade.foocorp.com/v1alpha1
+kind: PConfig
+metadata:
+  name: team-a-config
+  namespace: team-a
+  annotations:
+    composition-expander-debug-logs: "true"
+spec:
+  project: proj-a

experiments/compositions/composition/tests/data/TestSimpleCompositionExpanderLoggingEnabled/output.yaml

@@ -0,0 +1,23 @@
+# Copyright 2024 Google LLC
+#
+# 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.
+
+apiVersion: v1
+kind: ConfigMap
+metadata:
+  name: common-config
+  namespace: team-a
+  labels:
+   createdby: "composition-namespaceconfigmap"
+data:
+  key1: value1

experiments/compositions/composition/tests/testcases/simple_test.go

@@ -393,3 +393,14 @@ func TestSimpleExpanderVersionInvalid(t *testing.T) {
 	condition = utils.GetErrorCondition("VersionNotFound", "")
 	s.C.MustHaveCondition(plan, condition, scenario.CompositionReconcileTimeout)
 }
+
+func TestSimpleCompositionExpanderLoggingEnabled(t *testing.T) {
+	s := scenario.NewBasic(t)
+	defer s.Cleanup()
+	s.Setup()
+
+	plan := utils.GetPlanObj("team-a", "pconfigs-team-a-config")
+	condition := utils.GetWaitingCondition("EvaluateStatusWait", "")
+	s.C.MustNotHaveCondition(plan, condition, 3*scenario.CompositionReconcileTimeout)
+	s.VerifyOutputExists()
+}