Mutation: log applied mutations (#1140)

* Improve mutation logging

Signed-off-by: mmirecki <mmirecki@redhat.com>

* Add String function to mutators

Signed-off-by: mmirecki <mmirecki@redhat.com>

* Set mutation log flag name to log-mutations

Signed-off-by: mmirecki <mmirecki@redhat.com>

* Update dummyMutator to latest Mutator interface

Signed-off-by: mmirecki <mmirecki@redhat.com>

* Fix lint issue

Signed-off-by: Max Smythe <smythe@google.com>

Co-authored-by: Max Smythe <smythe@google.com>

pkg/logging/logging.go

@@ -19,5 +19,6 @@ const (
 	ResourceNamespace    = "resource_namespace"
 	ResourceName         = "resource_name"
 	RequestUsername      = "request_username"
+	MutationApplied      = "mutation_applied"
 	DebugLevel           = 2 // r.log.Debug(foo) == r.log.V(logging.DebugLevel).Info(foo)
 )

pkg/mutation/assign_mutator.go

@@ -43,7 +43,7 @@ func (m *AssignMutator) Matches(obj runtime.Object, ns *corev1.Namespace) bool {
 	return matches
 }
 
-func (m *AssignMutator) Mutate(obj *unstructured.Unstructured) error {
+func (m *AssignMutator) Mutate(obj *unstructured.Unstructured) (bool, error) {
 	return mutate(m, m.tester, m.testValue, obj)
 }
 
@@ -135,6 +135,10 @@ func (m *AssignMutator) DeepCopy() types.Mutator {
 	return res
 }
 
+func (m *AssignMutator) String() string {
+	return fmt.Sprintf("%s/%s/%s:%d", m.id.Kind, m.id.Namespace, m.id.Name, m.assign.GetGeneration())
+}
+
 // MutatorForAssign returns an AssignMutator built from
 // the given assign instance.
 func MutatorForAssign(assign *mutationsv1alpha1.Assign) (*AssignMutator, error) {

pkg/mutation/assign_mutator_test.go

@@ -717,7 +717,7 @@ func TestPathTests(t *testing.T) {
 		t.Run(test.name, func(t *testing.T) {
 			mutator := newAssignMutator(test.cfg)
 			obj := newFoo(test.spec)
-			err := mutator.Mutate(obj)
+			_, err := mutator.Mutate(obj)
 			if err != nil {
 				t.Fatalf("failed mutation: %s", err)
 			}
@@ -1432,7 +1432,7 @@ func TestValueTests(t *testing.T) {
 		t.Run(test.name, func(t *testing.T) {
 			mutator := newAssignMutator(test.cfg)
 			obj := newFoo(test.spec)
-			err := mutator.Mutate(obj)
+			_, err := mutator.Mutate(obj)
 			if err != nil {
 				t.Fatalf("failed mutation: %s", err)
 			}

pkg/mutation/assignmeta_mutator.go

@@ -56,12 +56,12 @@ func (m *AssignMetadataMutator) Matches(obj runtime.Object, ns *corev1.Namespace
 	return matches
 }
 
-func (m *AssignMetadataMutator) Mutate(obj *unstructured.Unstructured) error {
+func (m *AssignMetadataMutator) Mutate(obj *unstructured.Unstructured) (bool, error) {
 	t, err := tester.New([]tester.Test{
 		{SubPath: m.Path(), Condition: tester.MustNotExist},
 	})
 	if err != nil {
-		return err
+		return false, err
 	}
 	return mutate(m, t, nil, obj)
 }
@@ -113,6 +113,10 @@ func (m *AssignMetadataMutator) Value() (interface{}, error) {
 	}
 }
 
+func (m *AssignMetadataMutator) String() string {
+	return fmt.Sprintf("%s/%s/%s:%d", m.id.Kind, m.id.Namespace, m.id.Name, m.assignMetadata.GetGeneration())
+}
+
 // MutatorForAssignMetadata builds an AssignMetadataMutator from the given AssignMetadata object.
 func MutatorForAssignMetadata(assignMeta *mutationsv1alpha1.AssignMetadata) (*AssignMetadataMutator, error) {
 	path, err := parser.Parse(assignMeta.Spec.Location)

pkg/mutation/dummy_mutator.go

@@ -50,11 +50,15 @@ func (d *dummyMutator) Matches(obj runtime.Object, ns *corev1.Namespace) bool {
 	return matches
 }
 
-func (d *dummyMutator) Mutate(obj *unstructured.Unstructured) error {
+func (d *dummyMutator) Mutate(obj *unstructured.Unstructured) (bool, error) {
 	t, _ := path.New(nil)
 	return mutate(d, t, func(_ interface{}, _ bool) bool { return true }, obj)
 }
 
+func (d *dummyMutator) String() string {
+	return ""
+}
+
 func newDummyMutator(name, path string, value interface{}) *dummyMutator {
 	p, err := parser.Parse(path)
 	if err != nil {

pkg/mutation/mutation.go

@@ -15,15 +15,19 @@ package mutation
 import (
 	"flag"
 
+	"github.com/open-policy-agent/gatekeeper/pkg/logging"
 	logf "sigs.k8s.io/controller-runtime/pkg/log"
 )
 
 // MutationEnabled indicates if the mutation feature is enabled
 var (
-	MutationEnabled *bool
-	log             = logf.Log.WithName("mutation")
+	MutationEnabled        *bool
+	MutationLoggingEnabled *bool
+	log                    = logf.Log.WithName("mutation").WithValues(logging.Process, "mutation")
 )
 
 func init() {
 	MutationEnabled = flag.Bool("enable-mutation", false, "(alpha) Enable the mutation feature")
+	MutationLoggingEnabled = flag.Bool("log-mutations", false, "(alpha) Enable detailed logging of mutation events")
+
 }

pkg/mutation/mutation_function.go

@@ -10,16 +10,16 @@ import (
 	"k8s.io/apimachinery/pkg/apis/meta/v1/unstructured"
 )
 
-func mutate(mutator types.Mutator, tester *path.Tester, valueTest func(interface{}, bool) bool, obj *unstructured.Unstructured) error {
+func mutate(mutator types.Mutator, tester *path.Tester, valueTest func(interface{}, bool) bool, obj *unstructured.Unstructured) (bool, error) {
 	s := &mutatorState{mutator: mutator, tester: tester, valueTest: valueTest}
 	if len(mutator.Path().Nodes) == 0 {
-		return fmt.Errorf("mutator %v has an empty target location", mutator.ID())
+		return false, fmt.Errorf("mutator %v has an empty target location", mutator.ID())
 	}
 	if obj == nil {
-		return errors.New("attempting to mutate a nil object")
+		return false, errors.New("attempting to mutate a nil object")
 	}
-	_, _, err := s.mutateInternal(obj.Object, 0)
-	return err
+	mutated, _, err := s.mutateInternal(obj.Object, 0)
+	return mutated, err
 }
 
 type mutatorState struct {

pkg/mutation/mutation_function_test.go

@@ -377,7 +377,7 @@ func testAssignMetadataMutation(
 }
 
 func testMutation(mutator types.Mutator, unstructured *unstructured.Unstructured, testFunc func(*unstructured.Unstructured), t *testing.T) error {
-	err := mutator.Mutate(unstructured)
+	_, err := mutator.Mutate(unstructured)
 	if err != nil {
 		return err
 	}

pkg/mutation/schema/schema_test.go

@@ -27,7 +27,7 @@ type mockMutator struct {
 
 func (m *mockMutator) Matches(obj runtime.Object, ns *corev1.Namespace) bool { return false }
 
-func (m *mockMutator) Mutate(obj *unstructured.Unstructured) error { return nil }
+func (m *mockMutator) Mutate(obj *unstructured.Unstructured) (bool, error) { return false, nil }
 
 func (m *mockMutator) Value() (interface{}, error) { return nil, nil }
 
@@ -40,6 +40,10 @@ func (m *mockMutator) HasDiff(other types.Mutator) bool {
 	return !reflect.DeepEqual(m, other)
 }
 
+func (m *mockMutator) String() string {
+	return ""
+}
+
 func deepCopyBindings(bindings []Binding) []Binding {
 	cpy := []Binding{}
 	for _, b := range bindings {

pkg/mutation/system.go

@@ -3,9 +3,11 @@ package mutation
 import (
 	"fmt"
 	"sort"
+	"strings"
 	"sync"
 
 	"github.com/google/go-cmp/cmp"
+	"github.com/open-policy-agent/gatekeeper/pkg/logging"
 	"github.com/open-policy-agent/gatekeeper/pkg/mutation/schema"
 	"github.com/open-policy-agent/gatekeeper/pkg/mutation/types"
 	"github.com/pkg/errors"
@@ -83,11 +85,17 @@ func (s *System) Mutate(obj *unstructured.Unstructured, ns *corev1.Namespace) (b
 	original := obj.DeepCopy()
 	maxIterations := len(s.orderedMutators) + 1
 
+	allAppliedMutations := [][]types.Mutator{}
+
 	for i := 0; i < maxIterations; i++ {
+		appliedMutations := []types.Mutator{}
 		old := obj.DeepCopy()
 		for _, m := range s.orderedMutators {
 			if m.Matches(obj, ns) {
-				err := m.Mutate(obj)
+				mutated, err := m.Mutate(obj)
+				if mutated && *MutationLoggingEnabled {
+					appliedMutations = append(appliedMutations, m)
+				}
 				if err != nil {
 					return false, errors.Wrapf(err, "mutation %v failed for %s %s %s %s", m.ID(), obj.GroupVersionKind().Group, obj.GroupVersionKind().Kind, obj.GetNamespace(), obj.GetName())
 				}
@@ -98,14 +106,51 @@ func (s *System) Mutate(obj *unstructured.Unstructured, ns *corev1.Namespace) (b
 				return false, nil
 			}
 			if cmp.Equal(original, obj) {
+				if *MutationLoggingEnabled {
+					logAppliedMutations("Oscillating mutation.", original, allAppliedMutations)
+				}
 				return false, fmt.Errorf("oscillating mutation for %s %s %s %s", obj.GroupVersionKind().Group, obj.GroupVersionKind().Kind, obj.GetNamespace(), obj.GetName())
 			}
+			if *MutationLoggingEnabled {
+				logAppliedMutations("Mutation applied", original, allAppliedMutations)
+			}
 			return true, nil
 		}
+		if *MutationLoggingEnabled {
+			allAppliedMutations = append(allAppliedMutations, appliedMutations)
+		}
+	}
+	if *MutationLoggingEnabled {
+		logAppliedMutations("Mutation not converging", original, allAppliedMutations)
 	}
 	return false, fmt.Errorf("mutation not converging for %s %s %s %s", obj.GroupVersionKind().Group, obj.GroupVersionKind().Kind, obj.GetNamespace(), obj.GetName())
 }
 
+func logAppliedMutations(message string, obj *unstructured.Unstructured, allAppliedMutations [][]types.Mutator) {
+	iterations := []interface{}{}
+	for i, appliedMutations := range allAppliedMutations {
+		if len(appliedMutations) == 0 {
+			continue
+		}
+		var appliedMutationsText []string
+		for _, mutator := range appliedMutations {
+			appliedMutationsText = append(appliedMutationsText, mutator.String())
+		}
+		iterations = append(iterations, fmt.Sprintf("iteration_%d", i), strings.Join(appliedMutationsText, ", "))
+	}
+	if len(iterations) > 0 {
+		logDetails := []interface{}{}
+		logDetails = append(logDetails, logging.EventType, logging.MutationApplied)
+		logDetails = append(logDetails, logging.ResourceGroup, obj.GroupVersionKind().Group)
+		logDetails = append(logDetails, logging.ResourceKind, obj.GroupVersionKind().Kind)
+		logDetails = append(logDetails, logging.ResourceAPIVersion, obj.GroupVersionKind().Version)
+		logDetails = append(logDetails, logging.ResourceNamespace, obj.GetNamespace())
+		logDetails = append(logDetails, logging.ResourceName, obj.GetName())
+		logDetails = append(logDetails, iterations...)
+		log.Info(message, logDetails...)
+	}
+}
+
 // Remove removes the mutator from the mutation system
 func (s *System) Remove(id types.ID) error {
 	s.mux.Lock()

pkg/mutation/system_test.go

@@ -29,14 +29,14 @@ func (m *MockMutator) Matches(obj runtime.Object, ns *corev1.Namespace) bool {
 	return true // always matches
 }
 
-func (m *MockMutator) Mutate(obj *unstructured.Unstructured) error {
+func (m *MockMutator) Mutate(obj *unstructured.Unstructured) (bool, error) {
 	m.MutationCount++
 	if m.Labels == nil {
-		return nil
+		return false, nil
 	}
 	accessor, err := meta.Accessor(obj)
 	if err != nil {
-		return err
+		return false, err
 	}
 
 	current := accessor.GetLabels()
@@ -52,7 +52,7 @@ func (m *MockMutator) Mutate(obj *unstructured.Unstructured) error {
 	}
 	accessor.SetLabels(current)
 
-	return nil
+	return true, nil
 }
 
 func (m *MockMutator) ID() types.ID {
@@ -94,6 +94,10 @@ func (m *MockMutator) DeepCopy() types.Mutator {
 	return res
 }
 
+func (m *MockMutator) String() string {
+	return ""
+}
+
 var mutators = []types.Mutator{
 	&MockMutator{Mocked: types.ID{Group: "bbb", Kind: "aaa", Namespace: "aaa", Name: "aaa"}},
 	&MockMutator{Mocked: types.ID{Group: "aaa", Kind: "bbb", Namespace: "ccc", Name: "ddd"}},

pkg/mutation/types/mutator.go

@@ -24,7 +24,7 @@ type Mutator interface {
 	// Matches tells if the given object is eligible for this mutation.
 	Matches(obj runtime.Object, ns *corev1.Namespace) bool
 	// Mutate applies the mutation to the given object
-	Mutate(obj *unstructured.Unstructured) error
+	Mutate(obj *unstructured.Unstructured) (bool, error)
 	// ID returns the id of the current mutator.
 	ID() ID
 	// Has diff tells if the mutator has meaningful differences
@@ -34,6 +34,7 @@ type Mutator interface {
 	DeepCopy() Mutator
 	Value() (interface{}, error)
 	Path() *parser.Path
+	String() string
 }
 
 // MakeID builds an ID object for the given object