Break ties when compliance timestamps collide

Uses the microsecond `EventTime` field on the event when present, or it
tries to use a hexadecimal-encoded nanosecond timestamp which is in the
name of events created by controller-runtime.

Refs:
 - https://github.com/stolostron/backlog/issues/26039

Signed-off-by: Justin Kulikauskas <[email protected]>

Author: JustinKuli

controllers/statussync/policy_status_sync.go

@@ -9,6 +9,7 @@ import (
 	"os"
 	"regexp"
 	"sort"
+	"strconv"
 	"strings"
 
 	corev1 "k8s.io/api/core/v1"
@@ -171,7 +172,7 @@ func (r *PolicyReconciler) Reconcile(ctx context.Context, request reconcile.Requ
 		return reconcile.Result{}, err
 	}
 	// filter events to current policy instance and build map
-	eventForPolicyMap := make(map[string]*[]policiesv1.ComplianceHistory)
+	eventForPolicyMap := make(map[string]*[]historyEvent)
 	// panic if regexp invalid
 	rgx := regexp.MustCompile(`(?i)^policy:\s*([A-Za-z0-9.-]+)\s*\/([A-Za-z0-9.-]+)`)
 	for _, event := range eventList.Items {
@@ -180,14 +181,18 @@ func (r *PolicyReconciler) Reconcile(ctx context.Context, request reconcile.Requ
 		if event.InvolvedObject.Kind == policiesv1.Kind && event.InvolvedObject.APIVersion == policiesv1APIVersion &&
 			event.InvolvedObject.Name == instance.GetName() && reason != "" {
 			templateName := rgx.FindStringSubmatch(event.Reason)[2]
-			eventHistory := policiesv1.ComplianceHistory{
-				LastTimestamp: event.LastTimestamp,
-				Message:       strings.TrimSpace(strings.TrimPrefix(event.Message, "(combined from similar events):")),
-				EventName:     event.GetName(),
+			eventHistory := historyEvent{
+				ComplianceHistory: policiesv1.ComplianceHistory{
+					LastTimestamp: event.LastTimestamp,
+					Message: strings.TrimSpace(strings.TrimPrefix(
+						event.Message, "(combined from similar events):")),
+					EventName: event.GetName(),
+				},
+				eventTime: *event.EventTime.DeepCopy(),
 			}
 
 			if eventForPolicyMap[templateName] == nil {
-				eventForPolicyMap[templateName] = &[]policiesv1.ComplianceHistory{}
+				eventForPolicyMap[templateName] = &[]historyEvent{}
 			}
 
 			templateEvents := append(*eventForPolicyMap[templateName], eventHistory)
@@ -236,7 +241,7 @@ func (r *PolicyReconciler) Reconcile(ctx context.Context, request reconcile.Requ
 			}
 		}
 
-		history := []policiesv1.ComplianceHistory{}
+		history := []historyEvent{}
 		if eventForPolicyMap[tName] != nil {
 			history = *eventForPolicyMap[tName]
 		}
@@ -252,20 +257,55 @@ func (r *PolicyReconciler) Reconcile(ctx context.Context, request reconcile.Requ
 					break
 				}
 			}
-			// doesn't exists, append to history
+			// doesn't exist, append to history
 			if !exists {
-				history = append(history, ech)
+				history = append(history, historyEvent{ComplianceHistory: ech})
 			}
 		}
-		// sort by lasttimestamp
+		// sort by lasttimestamp, break ties with EventTime (if present) or EventName
 		sort.Slice(history, func(i, j int) bool {
-			return history[i].LastTimestamp.Time.After(history[j].LastTimestamp.Time)
+			if history[i].LastTimestamp.Equal(&history[j].LastTimestamp) {
+				if !history[i].eventTime.IsZero() && !history[j].eventTime.IsZero() {
+					reqLogger.V(2).Info("Event timestamp collision, order determined by EventTime",
+						"event1Name", history[i].EventName, "event2Name", history[j].EventName)
+
+					return !history[i].eventTime.Before(&history[j].eventTime)
+				}
+				// Timestamps are the same: attempt to use the event name.
+				// Conventionally (in client-go), the event name has a hexadecimal
+				// nanosecond timestamp as a suffix after a period.
+				iNameParts := strings.Split(history[i].EventName, ".")
+				jNameParts := strings.Split(history[j].EventName, ".")
+				errMsg := "Unable to interpret hexadecimal timestamp in event name, " +
+					"can't guarantee ordering of events in this status"
+
+				iNanos, err := strconv.ParseInt(iNameParts[len(iNameParts)-1], 16, 64)
+				if err != nil {
+					reqLogger.Error(err, errMsg, "eventName", history[i].EventName)
+
+					return false
+				}
+
+				jNanos, err := strconv.ParseInt(jNameParts[len(jNameParts)-1], 16, 64)
+				if err != nil {
+					reqLogger.Error(err, errMsg, "eventName", history[j].EventName)
+
+					return false
+				}
+
+				reqLogger.V(2).Info("Event timestamp collision, order determined by hex timestamp in name",
+					"event1Name", history[i].EventName, "event2Name", history[j].EventName)
+
+				return iNanos > jNanos
+			}
+
+			return !history[i].LastTimestamp.Time.Before(history[j].LastTimestamp.Time)
 		})
 		// remove duplicates
 		newHistory := []policiesv1.ComplianceHistory{}
 
 		for historyIndex := 0; historyIndex < len(history); historyIndex++ {
-			newHistory = append(newHistory, history[historyIndex])
+			newHistory = append(newHistory, history[historyIndex].ComplianceHistory)
 
 			for j := historyIndex; j < len(history); j++ {
 				if history[historyIndex].EventName == history[j].EventName &&
@@ -365,3 +405,8 @@ func (r *PolicyReconciler) Reconcile(ctx context.Context, request reconcile.Requ
 
 	return reconcile.Result{}, nil
 }
+
+type historyEvent struct {
+	policiesv1.ComplianceHistory
+	eventTime metav1.MicroTime
+}

test/e2e/case11_status_ts_collision_test.go

@@ -0,0 +1,226 @@
+// Copyright (c) 2020 Red Hat, Inc.
+// Copyright Contributors to the Open Cluster Management project
+
+package e2e
+
+import (
+	"context"
+	"time"
+
+	. "github.com/onsi/ginkgo/v2"
+	. "github.com/onsi/gomega"
+	corev1 "k8s.io/api/core/v1"
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"open-cluster-management.io/governance-policy-propagator/test/utils"
+)
+
+const (
+	case11PolicyYaml    string = "../resources/case11_ts_collision/case11-policy.yaml"
+	case11PolicyName    string = "default.case11-test-policy"
+	case11Event1        string = "default.case11-test-policy.171a96193d32cf17"
+	case11Event2        string = "default.case11-test-policy.171a96193dea32f4"
+	case11Event3        string = "default.case11-test-policy.171a96193dea32f8"
+	case11Event4        string = "default.case11-test-policy.four.171a96193d32cf17"
+	case11Event5        string = "default.case11-test-policy.five.171a96193d32cf17"
+	case11Event6        string = "default.case11-test-policy.six.171a96193d32cf17"
+	case11hubconfig     string = "--kubeconfig=../../kubeconfig_hub"
+	case11managedconfig string = "--kubeconfig=../../kubeconfig_managed"
+)
+
+func case11Event(name, namespace, message, evtype string, evtime time.Time, includeMS bool) error {
+	event := &corev1.Event{
+		ObjectMeta: metav1.ObjectMeta{
+			Name:              name,
+			Namespace:         namespace,
+			CreationTimestamp: metav1.NewTime(evtime),
+		},
+		InvolvedObject: corev1.ObjectReference{
+			Kind:      "Policy",
+			Namespace: namespace,
+			Name:      "default.case11-test-policy",
+			// UID:        "53719093-857c-4c9b-a1d2-187dfb8c6657",
+			APIVersion: "policy.open-cluster-management.io/v1",
+		},
+		Reason:  "policy: managed/case11-cfg-policy",
+		Message: message,
+		Source: corev1.EventSource{
+			Component: "configuration-policy-controller",
+		},
+		FirstTimestamp: metav1.NewTime(evtime),
+		LastTimestamp:  metav1.NewTime(evtime),
+		Count:          1,
+		Type:           evtype,
+	}
+
+	if includeMS {
+		event.EventTime = metav1.NewMicroTime(evtime)
+
+		// These fields must also be added to satisfy eventsv1.Event validation
+		event.Action = "filler"
+		event.ReportingController = "filler"
+		event.ReportingInstance = "filler"
+	}
+
+	_, err := clientManaged.CoreV1().Events(namespace).Create(
+		context.TODO(),
+		event,
+		metav1.CreateOptions{},
+	)
+
+	return err
+}
+
+func case11cleanup() {
+	out, err := utils.KubectlWithOutput(
+		"delete", "-f", case11PolicyYaml, "-n", clusterNamespaceOnHub, case11hubconfig)
+	if err != nil {
+		Expect(out).Should(ContainSubstring("NotFound"))
+	}
+
+	out, err = utils.KubectlWithOutput(
+		"delete", "-f", case11PolicyYaml, "-n", clusterNamespace, case11managedconfig)
+	if err != nil {
+		Expect(out).Should(ContainSubstring("NotFound"))
+	}
+
+	eventsToDelete := []string{
+		case11Event1,
+		case11Event2,
+		case11Event3,
+		case11Event4,
+		case11Event5,
+		case11Event6,
+	}
+
+	for _, evname := range eventsToDelete {
+		out, err = utils.KubectlWithOutput(
+			"delete", "event", evname, "-n", clusterNamespace, case11managedconfig)
+		if err != nil {
+			Expect(out).Should(ContainSubstring("NotFound"))
+		}
+	}
+}
+
+var _ = Describe("Test event sorting by name when timestamps collide", Ordered, func() {
+	It("Creates the policy and one event, and shows compliant", func() {
+		_, err := utils.KubectlWithOutput(
+			"apply", "-f", case11PolicyYaml, "-n", clusterNamespaceOnHub, case11hubconfig,
+		)
+		Expect(err).Should(BeNil())
+
+		_, err = utils.KubectlWithOutput(
+			"apply", "-f", case11PolicyYaml, "-n", clusterNamespace, case11managedconfig,
+		)
+		Expect(err).Should(BeNil())
+
+		Expect(case11Event(
+			case11Event1,
+			clusterNamespace,
+			"Compliant; notification - this is the oldest event",
+			"Normal",
+			time.Date(2022, 10, 3, 14, 40, 47, 0, time.UTC),
+			false,
+		)).Should(BeNil())
+
+		Eventually(checkCompliance(case11PolicyName), defaultTimeoutSeconds, 1).
+			Should(Equal("Compliant"))
+		Consistently(checkCompliance(case11PolicyName), "15s", 1).
+			Should(Equal("Compliant"))
+	})
+
+	It("Creates a second event with the same timestamp, and shows noncompliant", func() {
+		Expect(case11Event(
+			case11Event2,
+			clusterNamespace,
+			"NonCompliant; violation - a problem sandwich",
+			"Warning",
+			time.Date(2022, 10, 3, 14, 40, 47, 0, time.UTC),
+			false,
+		)).Should(BeNil())
+
+		Eventually(checkCompliance(case11PolicyName), defaultTimeoutSeconds, 1).
+			Should(Equal("NonCompliant"))
+		Consistently(checkCompliance(case11PolicyName), "15s", 1).
+			Should(Equal("NonCompliant"))
+	})
+
+	It("Creates a third with the same timestamp, and shows compliant", func() {
+		Expect(case11Event(
+			case11Event3,
+			clusterNamespace,
+			"Compliant; notification - this should be the most recent",
+			"Normal",
+			time.Date(2022, 10, 3, 14, 40, 47, 0, time.UTC),
+			false,
+		)).Should(BeNil())
+
+		Eventually(checkCompliance(case11PolicyName), defaultTimeoutSeconds, 1).
+			Should(Equal("Compliant"))
+		Consistently(checkCompliance(case11PolicyName), "15s", 1).
+			Should(Equal("Compliant"))
+	})
+
+	AfterAll(case11cleanup)
+})
+
+var _ = Describe("Test event sorting by eventtime when timestamps collide", Ordered, func() {
+	It("Creates the policy and one event, and shows compliant", func() {
+		_, err := utils.KubectlWithOutput(
+			"apply", "-f", case11PolicyYaml, "-n", clusterNamespaceOnHub, case11hubconfig,
+		)
+		Expect(err).Should(BeNil())
+
+		_, err = utils.KubectlWithOutput(
+			"apply", "-f", case11PolicyYaml, "-n", clusterNamespace, case11managedconfig,
+		)
+		Expect(err).Should(BeNil())
+
+		Expect(case11Event(
+			case11Event4,
+			clusterNamespace,
+			"Compliant; notification - this is the oldest event",
+			"Normal",
+			time.Date(2022, 10, 3, 14, 40, 47, 111111, time.UTC),
+			true,
+		)).Should(BeNil())
+
+		Eventually(checkCompliance(case11PolicyName), defaultTimeoutSeconds, 1).
+			Should(Equal("Compliant"))
+		Consistently(checkCompliance(case11PolicyName), "15s", 1).
+			Should(Equal("Compliant"))
+	})
+
+	It("Creates a second event with the same timestamp, and shows noncompliant", func() {
+		Expect(case11Event(
+			case11Event5,
+			clusterNamespace,
+			"NonCompliant; violation - a problem sandwich",
+			"Warning",
+			time.Date(2022, 10, 3, 14, 40, 47, 222222, time.UTC),
+			true,
+		)).Should(BeNil())
+
+		Eventually(checkCompliance(case11PolicyName), defaultTimeoutSeconds, 1).
+			Should(Equal("NonCompliant"))
+		Consistently(checkCompliance(case11PolicyName), "15s", 1).
+			Should(Equal("NonCompliant"))
+	})
+
+	It("Creates a third with the same timestamp, and shows compliant", func() {
+		Expect(case11Event(
+			case11Event6,
+			clusterNamespace,
+			"Compliant; notification - this should be the most recent",
+			"Warning",
+			time.Date(2022, 10, 3, 14, 40, 47, 333333, time.UTC),
+			true,
+		)).Should(BeNil())
+
+		Eventually(checkCompliance(case11PolicyName), defaultTimeoutSeconds, 1).
+			Should(Equal("Compliant"))
+		Consistently(checkCompliance(case11PolicyName), "15s", 1).
+			Should(Equal("Compliant"))
+	})
+
+	AfterAll(case11cleanup)
+})

test/resources/case11_ts_collision/case11-event-five.yaml

@@ -0,0 +1,22 @@
+action: "filler"
+apiVersion: v1
+count: 1
+eventTime: "2022-10-03T14:40:47.222222Z"
+firstTimestamp: "2022-10-03T14:40:47Z"
+involvedObject:
+  apiVersion: policy.open-cluster-management.io/v1
+  kind: Policy
+  name: default.case11-test-policy
+  uid: 53719093-857c-4c9b-a1d2-187dfb8c6657
+kind: Event
+lastTimestamp: "2022-10-03T14:40:47Z"
+message: NonCompliant; violation - a problem sandwich
+metadata:
+  creationTimestamp: "2022-10-03T14:40:47Z"
+  name: default.case11-test-policy.b.171a96193d32cf17
+reason: 'policy: managed/case11-cfg-policy'
+reportingComponent: "filler"
+reportingInstance: "filler"
+source:
+  component: configuration-policy-controller
+type: Warning

test/resources/case11_ts_collision/case11-event-four.yaml

@@ -0,0 +1,22 @@
+action: "filler"
+apiVersion: v1
+count: 1
+eventTime: "2022-10-03T14:40:47.111111Z"
+firstTimestamp: "2022-10-03T14:40:47Z"
+involvedObject:
+  apiVersion: policy.open-cluster-management.io/v1
+  kind: Policy
+  name: default.case11-test-policy
+  uid: 53719093-857c-4c9b-a1d2-187dfb8c6657
+kind: Event
+lastTimestamp: "2022-10-03T14:40:47Z"
+message: Compliant; notification - this is the oldest event
+metadata:
+  creationTimestamp: "2022-10-03T14:40:47Z"
+  name: default.case11-test-policy.a.171a96193d32cf17
+reason: 'policy: managed/case11-cfg-policy'
+reportingComponent: "filler"
+reportingInstance: "filler"
+source:
+  component: configuration-policy-controller
+type: Normal