feat: LoggingLogMetric - use updateTime to avoid spurious updates

generation/observedGeneration tells us if the KRM side has changed; updateTime tells us if the GCP side has changed. Note we still have a spurious update after the first creation because of setting spec.resourceID
gemmahou · May 15, 2024 · 6f66df1 · 6f66df1
1 parent 7e7db49
commit 6f66df1
Show file tree

Hide file tree

Showing 4 changed files with 110 additions and 169 deletions.
diff --git a/apis/resources/logging/v1beta1/logmetric_types.go b/apis/resources/logging/v1beta1/logmetric_types.go
@@ -208,7 +208,7 @@ type LoggingLogMetricStatus struct {
 	Conditions []v1alpha1.Condition `json:"conditions,omitempty"`
 	/* Output only. The creation timestamp of the metric. This field may not be present for older metrics. */
 	// +optional
-	CreateTime *metav1.Time `json:"createTime,omitempty"`
+	CreateTime *metav1.MicroTime `json:"createTime,omitempty"`
 
 	// +optional
 	MetricDescriptor *LogmetricMetricDescriptorStatus `json:"metricDescriptor,omitempty"`
@@ -219,7 +219,7 @@ type LoggingLogMetricStatus struct {
 
 	/* Output only. The last update timestamp of the metric. This field may not be present for older metrics. */
 	// +optional
-	UpdateTime *metav1.Time `json:"updateTime,omitempty"`
+	UpdateTime *metav1.MicroTime `json:"updateTime,omitempty"`
 }
 
 // +genclient

diff --git a/pkg/controller/direct/logging/logmetric_controller.go b/pkg/controller/direct/logging/logmetric_controller.go
@@ -200,22 +200,20 @@ func (a *logMetricAdapter) Create(ctx context.Context, u *unstructured.Unstructu
 func logMetricStatusToKRM(in *api.LogMetric, out *krm.LoggingLogMetricStatus) error {
 	out.CreateTime = nil
 	if in.CreateTime != "" {
-		parsed, err := time.Parse(time.RFC3339, in.CreateTime)
+		mt, err := convertToMicrotime(in.CreateTime)
 		if err != nil {
 			return fmt.Errorf("cannot parse createTime %q: %w", in.CreateTime, err)
 		}
-		mt := metav1.NewTime(parsed.UTC())
-		out.CreateTime = &mt
+		out.CreateTime = mt
 	}
 
 	out.UpdateTime = nil
 	if in.UpdateTime != "" {
-		parsed, err := time.Parse(time.RFC3339, in.UpdateTime)
+		mt, err := convertToMicrotime(in.UpdateTime)
 		if err != nil {
 			return fmt.Errorf("cannot parse updateTime %q: %w", in.UpdateTime, err)
 		}
-		mt := metav1.NewTime(parsed.UTC())
-		out.UpdateTime = &mt
+		out.UpdateTime = mt
 	}
 
 	out.MetricDescriptor = convertAPItoKRM_MetricDescriptorStatus(in.MetricDescriptor)
@@ -224,66 +222,124 @@ func logMetricStatusToKRM(in *api.LogMetric, out *krm.LoggingLogMetricStatus) er
 }
 
 func (a *logMetricAdapter) Update(ctx context.Context, u *unstructured.Unstructured) error {
-	update := new(api.LogMetric)
-	*update = *a.actual
-
-	if ValueOf(a.desired.Spec.Description) != a.actual.Description {
-		update.Description = ValueOf(a.desired.Spec.Description)
-	}
-	if ValueOf(a.desired.Spec.Disabled) != a.actual.Disabled {
-		update.Disabled = ValueOf(a.desired.Spec.Disabled)
-	}
-	if a.desired.Spec.Filter != a.actual.Filter {
-		// todo acpana: revisit UX, err out if filter of desired is empty
-		if a.desired.Spec.Filter != "" {
-			update.Filter = a.desired.Spec.Filter
-		} else {
-			// filter is a REQUIRED field
-			update.Filter = a.actual.Filter
+	latest := a.actual
+
+	if a.hasChanges(ctx, u) {
+		update := new(api.LogMetric)
+		*update = *a.actual
+
+		if ValueOf(a.desired.Spec.Description) != a.actual.Description {
+			update.Description = ValueOf(a.desired.Spec.Description)
+		}
+		if ValueOf(a.desired.Spec.Disabled) != a.actual.Disabled {
+			update.Disabled = ValueOf(a.desired.Spec.Disabled)
+		}
+		if a.desired.Spec.Filter != a.actual.Filter {
+			// todo acpana: revisit UX, err out if filter of desired is empty
+			if a.desired.Spec.Filter != "" {
+				update.Filter = a.desired.Spec.Filter
+			} else {
+				// filter is a REQUIRED field
+				update.Filter = a.actual.Filter
+			}
+		}
+		if !compareMetricDescriptors(a.desired.Spec.MetricDescriptor, a.actual.MetricDescriptor) {
+			update.MetricDescriptor = convertKCCtoAPIForMetricDescriptor(a.desired.Spec.MetricDescriptor)
 		}
-	}
-	if !compareMetricDescriptors(a.desired.Spec.MetricDescriptor, a.actual.MetricDescriptor) {
-		update.MetricDescriptor = convertKCCtoAPIForMetricDescriptor(a.desired.Spec.MetricDescriptor)
-	}
 
-	if !reflect.DeepEqual(a.desired.Spec.LabelExtractors, a.actual.LabelExtractors) {
-		update.LabelExtractors = a.desired.Spec.LabelExtractors
-	}
+		if !reflect.DeepEqual(a.desired.Spec.LabelExtractors, a.actual.LabelExtractors) {
+			update.LabelExtractors = a.desired.Spec.LabelExtractors
+		}
 
-	if !compareBucketOptions(a.desired.Spec.BucketOptions, a.actual.BucketOptions) {
-		update.BucketOptions = convertKCCtoAPIForBucketOptions(a.desired.Spec.BucketOptions)
-	}
+		if !compareBucketOptions(a.desired.Spec.BucketOptions, a.actual.BucketOptions) {
+			update.BucketOptions = convertKCCtoAPIForBucketOptions(a.desired.Spec.BucketOptions)
+		}
 
-	if ValueOf(a.desired.Spec.ValueExtractor) != a.actual.ValueExtractor {
-		update.ValueExtractor = ValueOf(a.desired.Spec.ValueExtractor)
-	}
-	if a.desired.Spec.LoggingLogBucketRef != nil && a.desired.Spec.LoggingLogBucketRef.External != a.actual.BucketName {
-		update.BucketName = a.desired.Spec.LoggingLogBucketRef.External
-	}
+		if ValueOf(a.desired.Spec.ValueExtractor) != a.actual.ValueExtractor {
+			update.ValueExtractor = ValueOf(a.desired.Spec.ValueExtractor)
+		}
+		if a.desired.Spec.LoggingLogBucketRef != nil && a.desired.Spec.LoggingLogBucketRef.External != a.actual.BucketName {
+			update.BucketName = a.desired.Spec.LoggingLogBucketRef.External
+		}
 
-	// DANGER: this is an upsert; it will create the LogMetric if it doesn't exists
-	// but this behavior is consistent with the DCL backed behavior we provide for this resource.
-	// todo acpana: look for / switch to a better method and/or use etags etc
-	actualUpdate, err := a.logMetricClient.Update(a.fullyQualifiedName(), update).Context(ctx).Do()
-	if err != nil {
-		return fmt.Errorf("logMetric update failed: %w", err)
+		// DANGER: this is an upsert; it will create the LogMetric if it doesn't exists
+		// but this behavior is consistent with the DCL backed behavior we provide for this resource.
+		// todo acpana: look for / switch to a better method and/or use etags etc
+		updated, err := a.logMetricClient.Update(a.fullyQualifiedName(), update).Context(ctx).Do()
+		if err != nil {
+			return fmt.Errorf("logMetric update failed: %w", err)
+		}
+		latest = updated
 	}
 
 	status := &krm.LoggingLogMetricStatus{}
-	if err := logMetricStatusToKRM(actualUpdate, status); err != nil {
+	if err := logMetricStatusToKRM(latest, status); err != nil {
 		return err
 	}
 
 	// actualUpdate may not contain the description for the metric descriptor.
-	if update.Description != "" {
+	if latest.Description != "" {
 		if status.MetricDescriptor != nil {
-			status.MetricDescriptor.Description = &update.Description
+			status.MetricDescriptor.Description = &latest.Description
 		}
 	}
 
 	return setStatus(u, status)
 }
 
+func (a *logMetricAdapter) hasChanges(ctx context.Context, u *unstructured.Unstructured) bool {
+	log := klog.FromContext(ctx)
+
+	if u.GetGeneration() != getObservedGeneration(u) {
+		log.Info("generation does not match", "generation", u.GetGeneration(), "observedGeneration", getObservedGeneration(u))
+		return true
+	}
+
+	gcpUpdateTime := a.actual.UpdateTime
+	if gcpUpdateTime == "" {
+		log.Info("updateTime is not set in GCP")
+		return true
+	}
+	gcpUpdateTimestamp, err := convertToMicrotime(gcpUpdateTime)
+	if err != nil {
+		log.Error(err, "gcp updateTime cannot be parsed", "updateTime", gcpUpdateTime)
+		return true
+	}
+
+	obj := &krm.LoggingLogMetric{}
+	if err := runtime.DefaultUnstructuredConverter.FromUnstructured(u.Object, &obj); err != nil {
+		log.Error(err, "error converting from unstructured")
+		return true
+	}
+	if obj.Status.UpdateTime == nil {
+		log.Info("status.updateTime is not set")
+		return true
+	}
+
+	if gcpUpdateTimestamp.Equal(obj.Status.UpdateTime) {
+		log.Info("status.updateTime matches gcp updateTime", "status.updateTime", obj.Status.UpdateTime.UTC(), "gcpUpdateTime", gcpUpdateTimestamp.UTC())
+		return false
+	}
+
+	log.Info("status.updateTime does not match gcp updateTime", "status.updateTime", obj.Status.UpdateTime.UTC(), "gcpUpdateTime", gcpUpdateTimestamp.UTC())
+	return true
+}
+
+func convertToMicrotime(s string) (*metav1.MicroTime, error) {
+	if s == "" {
+		return nil, nil
+	}
+	t, err := time.Parse(time.RFC3339Nano, s)
+	if err != nil {
+		return nil, fmt.Errorf("parsing time %q: %w", s, err)
+	}
+	t = t.UTC()
+	// Resolution is microsecond
+	t = t.Round(time.Microsecond)
+	v := metav1.NewMicroTime(t)
+	return &v, nil
+}
+
 func (a *logMetricAdapter) fullyQualifiedName() string {
 	return MakeFQN(a.projectID, a.resourceID)
 }

diff --git a/pkg/controller/direct/logging/utils.go b/pkg/controller/direct/logging/utils.go
@@ -76,6 +76,11 @@ func setStatus(u *unstructured.Unstructured, typedStatus any) error {
 	return nil
 }
 
+func getObservedGeneration(u *unstructured.Unstructured) int64 {
+	v, _, _ := unstructured.NestedInt64(u.Object, "status", "observedGeneration")
+	return v
+}
+
 // todo acpana: end common things
 
 // todo acpana: house these somewhere else

diff --git a/tests/e2e/testdata/scenarios/direct/llm_lazy_reconcile/_http01.log b/tests/e2e/testdata/scenarios/direct/llm_lazy_reconcile/_http01.log
@@ -37,66 +37,6 @@ X-Xss-Protection: 0
 
 ---
 
-PUT https://logging.googleapis.com/v2/projects/${projectId}/metrics/lazyreconcile-${uniqueId}?alt=json&prettyPrint=false
-Content-Type: application/json
-User-Agent: google-api-go-client/0.5
-X-Goog-Api-Client: gl-go/1.22.3 gdcl/0.177.0
-
-{
-  "bucketOptions": {
-    "explicitBuckets": {
-      "bounds": [
-        2.5,
-        5
-      ]
-    }
-  },
-  "createTime": "2024-04-01T12:34:56.123456Z",
-  "filter": "resource.type=gae_app AND severity\u003e=ERROR",
-  "metricDescriptor": {
-    "metricKind": "DELTA",
-    "valueType": "DISTRIBUTION"
-  },
-  "name": "lazyreconcile-${uniqueId}",
-  "updateTime": "2024-04-01T12:34:56.123456Z",
-  "valueExtractor": "EXTRACT(jsonPayload.response)"
-}
-
-200 OK
-Cache-Control: private
-Content-Type: application/json; charset=UTF-8
-Server: ESF
-Vary: Origin
-Vary: X-Origin
-Vary: Referer
-X-Content-Type-Options: nosniff
-X-Frame-Options: SAMEORIGIN
-X-Xss-Protection: 0
-
-{
-  "bucketOptions": {
-    "explicitBuckets": {
-      "bounds": [
-        2.5,
-        5
-      ]
-    }
-  },
-  "createTime": "2024-04-01T12:34:56.123456Z",
-  "filter": "resource.type=gae_app AND severity\u003e=ERROR",
-  "metricDescriptor": {
-    "metricKind": "DELTA",
-    "name": "projects/${projectId}/metricDescriptors/logging.googleapis.com/user/lazyreconcile-${uniqueId}",
-    "type": "logging.googleapis.com/user/lazyreconcile-${uniqueId}",
-    "valueType": "DISTRIBUTION"
-  },
-  "name": "lazyreconcile-${uniqueId}",
-  "updateTime": "2024-04-01T12:34:56.123456Z",
-  "valueExtractor": "EXTRACT(jsonPayload.response)"
-}
-
----
-
 GET https://logging.googleapis.com/v2/projects/${projectId}/metrics/lazyreconcile-${uniqueId}?alt=json&prettyPrint=false
 User-Agent: google-api-go-client/0.5
 X-Goog-Api-Client: gl-go/1.22.3 gdcl/0.177.0
@@ -112,66 +52,6 @@ X-Content-Type-Options: nosniff
 X-Frame-Options: SAMEORIGIN
 X-Xss-Protection: 0
 
-{
-  "bucketOptions": {
-    "explicitBuckets": {
-      "bounds": [
-        2.5,
-        5
-      ]
-    }
-  },
-  "createTime": "2024-04-01T12:34:56.123456Z",
-  "filter": "resource.type=gae_app AND severity\u003e=ERROR",
-  "metricDescriptor": {
-    "metricKind": "DELTA",
-    "name": "projects/${projectId}/metricDescriptors/logging.googleapis.com/user/lazyreconcile-${uniqueId}",
-    "type": "logging.googleapis.com/user/lazyreconcile-${uniqueId}",
-    "valueType": "DISTRIBUTION"
-  },
-  "name": "lazyreconcile-${uniqueId}",
-  "updateTime": "2024-04-01T12:34:56.123456Z",
-  "valueExtractor": "EXTRACT(jsonPayload.response)"
-}
-
----
-
-PUT https://logging.googleapis.com/v2/projects/${projectId}/metrics/lazyreconcile-${uniqueId}?alt=json&prettyPrint=false
-Content-Type: application/json
-User-Agent: google-api-go-client/0.5
-X-Goog-Api-Client: gl-go/1.22.3 gdcl/0.177.0
-
-{
-  "bucketOptions": {
-    "explicitBuckets": {
-      "bounds": [
-        2.5,
-        5
-      ]
-    }
-  },
-  "createTime": "2024-04-01T12:34:56.123456Z",
-  "filter": "resource.type=gae_app AND severity\u003e=ERROR",
-  "metricDescriptor": {
-    "metricKind": "DELTA",
-    "valueType": "DISTRIBUTION"
-  },
-  "name": "lazyreconcile-${uniqueId}",
-  "updateTime": "2024-04-01T12:34:56.123456Z",
-  "valueExtractor": "EXTRACT(jsonPayload.response)"
-}
-
-200 OK
-Cache-Control: private
-Content-Type: application/json; charset=UTF-8
-Server: ESF
-Vary: Origin
-Vary: X-Origin
-Vary: Referer
-X-Content-Type-Options: nosniff
-X-Frame-Options: SAMEORIGIN
-X-Xss-Protection: 0
-
 {
   "bucketOptions": {
     "explicitBuckets": {