From 02a51e3712d9355b337056809ed8412b568f4864 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 29 Sep 2025 14:30:07 +0200 Subject: [PATCH 1/2] DRA ResourceSlice tracker: explain test a bit better, fix -run Instead of creating a new test case, the permutation is passed down. This enables adding the event numbers to the log output, which is useful to understand better which output belongs to which input: === RUN TestListPatchedResourceSlices/update-patch/2_3_0_1 tracker.go:396: I0929 14:28:40.032318] event #1: ResourceSlice add slice="s1" tracker.go:581: I0929 14:28:40.032404] event #1: syncing ResourceSlice resourceslice="s1" tracker.go:659: I0929 14:28:40.032446] event #1: ResourceSlice synced resourceslice="s1" change="add" tracker.go:396: I0929 14:28:40.032502] event #2: ResourceSlice add slice="s2" tracker.go:581: I0929 14:28:40.032536] event #2: syncing ResourceSlice resourceslice="s2" tracker.go:659: I0929 14:28:40.032568] event #2: ResourceSlice synced resourceslice="s2" change="add" tracker.go:463: I0929 14:28:40.032609] event #0/#0: DeviceTaintRule add patch="rule" tracker.go:581: I0929 14:28:40.032639] event #0/#0: syncing ResourceSlice resourceslice="s1" tracker.go:703: I0929 14:28:40.032675] event #0/#0: processing DeviceTaintRule resourceslice="s1" deviceTaintRule="rule" tracker.go:807: I0929 14:28:40.032712] event #0/#0: applying matching DeviceTaintRule resourceslice="s1" deviceTaintRule="rule" device="driver1.example.com/pool-1/device-1" tracker.go:868: I0929 14:28:40.032780] event #0/#0: Assigned new taint ID, no matching taint resourceslice="s1" deviceTaintRule="rule" device="driver1.example.com/pool-1/device-1" taintID=0 taint="example.com/taint=tainted:NoExecute" tracker.go:654: I0929 14:28:40.033023] event #0/#0: ResourceSlice synced resourceslice="s1" change="update" diff=< @@ -23,7 +23,32 @@ "BindingConditions": null, "BindingFailureConditions": null, "AllowMultipleAllocations": null, - "Taints": null + "Taints": [ + { + "Rule": { + "metadata": { + "name": "rule" + }, + "spec": { + "deviceSelector": { + "pool": "pool-1" + }, + "taint": { + "key": "example.com/taint", + "value": "tainted", + "effect": "NoExecute", + "timeAdded": "2006-01-02T15:04:05Z" + } + }, + "status": {} + }, + "ID": 1, + "key": "example.com/taint", + "value": "tainted", + "effect": "NoExecute", + "timeAdded": "2006-01-02T15:04:05Z" + } + ] } ], "Taints": null, > tracker.go:482: I0929 14:28:40.033224] event #0/#1: DeviceTaintRule update patch="rule" diff=< @@ -4,7 +4,7 @@ }, "spec": { "deviceSelector": { - "pool": "pool-1" + "pool": "pool-2" }, "taint": { "key": "example.com/taint", > tracker.go:581: I0929 14:28:40.033285] event #0/#1: syncing ResourceSlice resourceslice="s1" tracker.go:703: I0929 14:28:40.033319] event #0/#1: processing DeviceTaintRule resourceslice="s1" deviceTaintRule="rule" tracker.go:654: I0929 14:28:40.033478] event #0/#1: ResourceSlice synced resourceslice="s1" change="update" diff=< @@ -23,32 +23,7 @@ "BindingConditions": null, "BindingFailureConditions": null, "AllowMultipleAllocations": null, - "Taints": [ - { - "Rule": { - "metadata": { - "name": "rule" - }, - "spec": { - "deviceSelector": { - "pool": "pool-1" - }, - "taint": { - "key": "example.com/taint", - "value": "tainted", - "effect": "NoExecute", - "timeAdded": "2006-01-02T15:04:05Z" - } - }, - "status": {} - }, - "ID": 1, - "key": "example.com/taint", - "value": "tainted", - "effect": "NoExecute", - "timeAdded": "2006-01-02T15:04:05Z" - } - ] + "Taints": null } ], "Taints": null, > tracker.go:581: I0929 14:28:40.033601] event #0/#1: syncing ResourceSlice resourceslice="s2" tracker.go:703: I0929 14:28:40.033633] event #0/#1: processing DeviceTaintRule resourceslice="s2" deviceTaintRule="rule" ... Disabling event checking only worked when actually running all sub-tests. When selectively running only one permutation with -run, the boolean variable was wrong: $ go test -run='.*/^update-patch$' ./staging/src/k8s.io/dynamic-resource-allocation/resourceslice/tracker/ ok k8s.io/dynamic-resource-allocation/resourceslice/tracker $ go test -run='.*/^update-patch$/3_2_0_1' ./staging/src/k8s.io/dynamic-resource-allocation/resourceslice/tracker/ --- FAIL: TestListPatchedResourceSlices (0.01s) --- FAIL: TestListPatchedResourceSlices/update-patch (0.00s) --- FAIL: TestListPatchedResourceSlices/update-patch/3_2_0_1 (0.00s) tracker_test.go:762: Error Trace: /nvme/gopath/src/k8s.io/kubernetes/staging/src/k8s.io/dynamic-resource-allocation/resourceslice/tracker/tracker_test.go:762 /nvme/gopath/src/k8s.io/kubernetes/staging/src/k8s.io/dynamic-resource-allocation/resourceslice/tracker/tracker_test.go:856 Error: Not equal: expected: []tracker.handlerEvent{tracker.handlerEvent{event:"add", oldObj:(*api.ResourceSlice)(nil), newObj:(*api.ResourceSlice)(0xc000301d40)}, tracker.handlerEvent{event:"add", oldObj:(*api.ResourceSlice)(nil), newObj:(*api.ResourceSlice)(0xc000346000)}} actual : []tracker.handlerEvent{tracker.handlerEvent{event:"add", oldObj:(*api.ResourceSlice)(nil), newObj:(*api.ResourceSlice)(0xc0001f9ba0)}, tracker.handlerEvent{event:"add", oldObj:(*api.ResourceSlice)(nil), newObj:(*api.ResourceSlice)(0xc000301d40)}, tracker.handlerEvent{event:"update", oldObj:(*api.ResourceSlice)(0xc000301d40), newObj:(*api.ResourceSlice)(0xc0003dba00)}, tracker.handlerEvent{event:"update", oldObj:(*api.ResourceSlice)(0xc0003dba00), newObj:(*api.ResourceSlice)(0xc000301d40)}, tracker.handlerEvent{event:"update", oldObj:(*api.ResourceSlice)(0xc0001f9ba0), newObj:(*api.ResourceSlice)(0xc0003dbba0)}} Now permutations are detected automatically based on the indices. While at it, documentation gets moved around a bit to make reading test cases easier without going to the implementation. --- .../resourceslice/tracker/tracker_test.go | 127 +++++++++++------- 1 file changed, 80 insertions(+), 47 deletions(-) diff --git a/staging/src/k8s.io/dynamic-resource-allocation/resourceslice/tracker/tracker_test.go b/staging/src/k8s.io/dynamic-resource-allocation/resourceslice/tracker/tracker_test.go index 5726320eec3..0e2c13c3b34 100644 --- a/staging/src/k8s.io/dynamic-resource-allocation/resourceslice/tracker/tracker_test.go +++ b/staging/src/k8s.io/dynamic-resource-allocation/resourceslice/tracker/tracker_test.go @@ -67,17 +67,35 @@ func update[T any](oldObj, newObj *T) [2]*T { return [2]*T{oldObj, newObj} } -func runInputEvents(tCtx *testContext, events []any) { - for _, event := range events { - switch event := event.(type) { - case []any: - for _, event := range event { - applyEventPair(tCtx, event) +func runInputEvents(tCtx *testContext, events []any, permutation []int) { + for _, i := range permutation { + event, name := lookupEvent(events, i) + stepCtx := tCtx.withLoggerName(fmt.Sprintf("event #%s", name)) + applyEventPair(stepCtx, event) + } +} + +// lookupEvent is the opposite of flatten: it takes an index +// after flattening and maps it back to the event in the original +// event hierarchy. To do so, it descends into the second level where necessary. +func lookupEvent(events []any, index int) (any, string) { + numEvents := 0 + for i := range events { + if e, ok := events[i].([]any); ok { + for j := range e { + if numEvents == index { + return e[j], fmt.Sprintf("%d/%d", i, j) + } + numEvents++ } - default: - applyEventPair(tCtx, event) + } else { + if numEvents == index { + return events[i], fmt.Sprintf("%d", i) + } + numEvents++ } } + panic(fmt.Sprintf("invalid event index #%d", index)) } func applyEventPair(tCtx *testContext, event any) { @@ -140,6 +158,18 @@ type testContext struct { *fake.Clientset } +func (t *testContext) withLoggerName(name string) *testContext { + logger := klog.FromContext(t.Context) + logger = klog.LoggerWithName(logger, name) + t = &testContext{ + T: t.T, + Context: klog.NewContext(t.Context, logger), + Tracker: t.Tracker, + Clientset: t.Clientset, + } + return t +} + var ( now, _ = time.Parse(time.RFC3339, "2006-01-02T15:04:05Z") driver1 = "driver1.example.com" @@ -335,6 +365,11 @@ func TestListPatchedResourceSlices(t *testing.T) { // the order in those nested lists is preserved. events []any expectedPatchedSlices []*resourceapi.ResourceSlice + // The exact events that are emitted for a sequence of events is + // highly dependent on the order in which those events are received. + // We punt on determining a set of validation criteria for every + // possible sequence and only check them against the first + // permutation: the order in which the events are defined. expectedHandlerEvents []handlerEvent expectEvents func(t *assert.CollectT, events *v1.EventList) expectUnhandledErrors func(t *testing.T, errs []error) @@ -643,7 +678,15 @@ func TestListPatchedResourceSlices(t *testing.T) { } } - testHandlers := func(tCtx *testContext, test test, testExpectedEmittedEvents bool) { + testHandlers := func(tCtx *testContext, test test, permutation []int) { + isPermutated := false + for i, j := range permutation { + if i != j { + isPermutated = true + break + } + } + var handlerEvents []handlerEvent handler := cache.ResourceEventHandlerFuncs{ AddFunc: func(obj interface{}) { @@ -663,9 +706,9 @@ func TestListPatchedResourceSlices(t *testing.T) { unhandledErrors = append(unhandledErrors, err) } - runInputEvents(tCtx, test.events) + runInputEvents(tCtx, test.events, permutation) - if testExpectedEmittedEvents { + if !isPermutated { assert.Equal(tCtx, test.expectedHandlerEvents, handlerEvents) } @@ -709,60 +752,47 @@ func TestListPatchedResourceSlices(t *testing.T) { for name, tc := range tests { t.Run(name, func(t *testing.T) { - // The exact events that are emitted for a sequence of events is - // highly dependent on the order in which those events are received. - // We punt on determining a set of validation criteria for every - // possible sequence and only check them against the first - // permutation: the order in which the events are defined. - testExpectedEmittedEvents := true - - numEvents := len(tc.events) - if numEvents <= 1 { - // No permutations. - tContext := setup(t) - testHandlers(tContext, tc, testExpectedEmittedEvents) - return - } - - // flatten does one level of flattening of events. It also returns - // another slice of pairs of indices representing ranges which were - // flattened. - flatten := func(events []any) ([]any, [][2]int) { - var ret []any + // flatten does one level of flattening of events, counting all events. + // It also returns a slice of pairs of indices representing ranges which were + // flattened (= came from the second level) and which therefore must + // remain in that order. + flatten := func(events []any) (int, [][2]int) { + numEvents := 0 var ranges [][2]int for _, e := range events { switch e := e.(type) { case []any: - ranges = append(ranges, [2]int{len(ret), len(ret) + len(e)}) - ret = append(ret, e...) + ranges = append(ranges, [2]int{numEvents, numEvents + len(e)}) + numEvents += len(e) default: - ret = append(ret, e) + numEvents++ } } - return ret, ranges + return numEvents, ranges } + numEvents, constraints := flatten(tc.events) - var constraints [][2]int - tc.events, constraints = flatten(tc.events) - numEvents = len(tc.events) + if len(tc.events) <= 1 { + // No permutations possible. + var permutation []int + for i := 0; i < numEvents; i++ { + permutation = append(permutation, i) + } + tContext := setup(t) + testHandlers(tContext, tc, permutation) + return + } permutation := make([]int, numEvents) var permutate func(depth int) permutate = func(depth int) { if depth >= numEvents { // Define a sub-test which runs the current permutation of events. - events := make([]any, numEvents) - for i := range numEvents { - events[i] = tc.events[permutation[i]] - } - tc := tc - tc.events = events name := strings.Trim(fmt.Sprintf("%v", permutation), "[]") t.Run(name, func(t *testing.T) { tContext := setup(t) - testHandlers(tContext, tc, testExpectedEmittedEvents) - - testExpectedEmittedEvents = false + // No need to clone the slice, we don't run in parallel. + testHandlers(tContext, tc, permutation) }) return } @@ -778,10 +808,13 @@ func TestListPatchedResourceSlices(t *testing.T) { } for j := i + 1; j < constraint[1]; j++ { if slices.Contains(permutation[0:depth], j) { + // Invalid permutation, would change order + // of sub-events. continue nexti } } } + // Pick it for the current position in permutation, // continue with next position. permutation[depth] = i From c36c927d189213b315b4b117551ac2b4fa641e62 Mon Sep 17 00:00:00 2001 From: Patrick Ohly Date: Mon, 29 Sep 2025 17:36:03 +0200 Subject: [PATCH 2/2] DRA ResourceSlice: nicer log output UniqueString rendered as {} in JSON/YAML, which isn't useful... Providing a MarshalJSON which dumps the string is better. This enables full object dumps in the ResourceSlice tracker. While at it: - Consistently log the object content at level 6. - Use past tense in log messages (recommended style). - Rename "patch" -> "rule". --- .../api/uniquestring.go | 6 ++++ .../resourceslice/tracker/tracker.go | 36 +++++++++++-------- 2 files changed, 28 insertions(+), 14 deletions(-) diff --git a/staging/src/k8s.io/dynamic-resource-allocation/api/uniquestring.go b/staging/src/k8s.io/dynamic-resource-allocation/api/uniquestring.go index 34d413743ac..a95e6aaaa2d 100644 --- a/staging/src/k8s.io/dynamic-resource-allocation/api/uniquestring.go +++ b/staging/src/k8s.io/dynamic-resource-allocation/api/uniquestring.go @@ -17,6 +17,7 @@ limitations under the License. package api import ( + "encoding/json" "unique" ) @@ -35,6 +36,11 @@ func (us UniqueString) String() string { return unique.Handle[string](us).Value() } +// MarshalJSON is primarily useful for pretty-printing as JSON or YAML. +func (us UniqueString) MarshalJSON() ([]byte, error) { + return json.Marshal(us.String()) +} + // MakeUniqueString constructs a new unique string. func MakeUniqueString(str string) UniqueString { return UniqueString(unique.Make(str)) diff --git a/staging/src/k8s.io/dynamic-resource-allocation/resourceslice/tracker/tracker.go b/staging/src/k8s.io/dynamic-resource-allocation/resourceslice/tracker/tracker.go index 62938d807f3..b27b3d0392c 100644 --- a/staging/src/k8s.io/dynamic-resource-allocation/resourceslice/tracker/tracker.go +++ b/staging/src/k8s.io/dynamic-resource-allocation/resourceslice/tracker/tracker.go @@ -387,7 +387,11 @@ func (t *Tracker) resourceSliceAdd(ctx context.Context) func(obj any) { if !ok { return } - logger.V(5).Info("ResourceSlice add", "slice", klog.KObj(slice)) + if loggerV := logger.V(6); loggerV.Enabled() { + loggerV.Info("ResourceSlice added", "slice", klog.Format(slice)) + } else { + logger.V(5).Info("ResourceSlice added", "slice", klog.KObj(slice)) + } t.syncSlice(ctx, slice.Name, true) } } @@ -406,9 +410,9 @@ func (t *Tracker) resourceSliceUpdate(ctx context.Context) func(oldObj, newObj a if loggerV := logger.V(6); loggerV.Enabled() { // While debugging, one needs a full dump of the objects for context *and* // a diff because otherwise small changes would be hard to spot. - loggerV.Info("ResourceSlice update", "slice", klog.Format(oldSlice), "oldSlice", klog.Format(newSlice), "diff", diff.Diff(oldSlice, newSlice)) + loggerV.Info("ResourceSlice updated", "diff", diff.Diff(oldSlice, newSlice), "slice", klog.Format(newSlice)) } else { - logger.V(5).Info("ResourceSlice update", "slice", klog.KObj(newSlice)) + logger.V(5).Info("ResourceSlice updated", "slice", klog.KObj(newSlice)) } t.syncSlice(ctx, newSlice.Name, true) } @@ -424,7 +428,7 @@ func (t *Tracker) resourceSliceDelete(ctx context.Context) func(obj any) { if !ok { return } - logger.V(5).Info("ResourceSlice delete", "slice", klog.KObj(slice)) + logger.V(5).Info("ResourceSlice deleted", "slice", klog.KObj(slice)) t.syncSlice(ctx, slice.Name, true) } } @@ -432,12 +436,16 @@ func (t *Tracker) resourceSliceDelete(ctx context.Context) func(obj any) { func (t *Tracker) deviceTaintAdd(ctx context.Context) func(obj any) { logger := klog.FromContext(ctx) return func(obj any) { - patch, ok := obj.(*resourcealphaapi.DeviceTaintRule) + rule, ok := obj.(*resourcealphaapi.DeviceTaintRule) if !ok { return } - logger.V(5).Info("DeviceTaintRule add", "patch", klog.KObj(patch)) - for _, sliceName := range t.sliceNamesForPatch(ctx, patch) { + if loggerV := logger.V(6); loggerV.Enabled() { + loggerV.Info("DeviceTaintRule added", "deviceTaintRule", klog.Format(rule)) + } else { + logger.V(5).Info("DeviceTaintRule added", "deviceTaintRule", klog.KObj(rule)) + } + for _, sliceName := range t.sliceNamesForPatch(ctx, rule) { t.syncSlice(ctx, sliceName, false) } } @@ -446,26 +454,26 @@ func (t *Tracker) deviceTaintAdd(ctx context.Context) func(obj any) { func (t *Tracker) deviceTaintUpdate(ctx context.Context) func(oldObj, newObj any) { logger := klog.FromContext(ctx) return func(oldObj, newObj any) { - oldPatch, ok := oldObj.(*resourcealphaapi.DeviceTaintRule) + oldRule, ok := oldObj.(*resourcealphaapi.DeviceTaintRule) if !ok { return } - newPatch, ok := newObj.(*resourcealphaapi.DeviceTaintRule) + newRule, ok := newObj.(*resourcealphaapi.DeviceTaintRule) if !ok { return } if loggerV := logger.V(6); loggerV.Enabled() { - loggerV.Info("DeviceTaintRule update", "patch", klog.KObj(newPatch), "diff", diff.Diff(oldPatch, newPatch)) + loggerV.Info("DeviceTaintRule updated", "diff", diff.Diff(oldRule, newRule), "deviceTaintRule", klog.KObj(newRule)) } else { - logger.V(5).Info("DeviceTaintRule update", "patch", klog.KObj(newPatch)) + logger.V(5).Info("DeviceTaintRule updated", "deviceTaintRule", klog.KObj(newRule)) } // Slices that matched the old patch may need to be updated, in // case they no longer match the new patch and need to have the // patch's changes reverted. slicesToSync := sets.New[string]() - slicesToSync.Insert(t.sliceNamesForPatch(ctx, oldPatch)...) - slicesToSync.Insert(t.sliceNamesForPatch(ctx, newPatch)...) + slicesToSync.Insert(t.sliceNamesForPatch(ctx, oldRule)...) + slicesToSync.Insert(t.sliceNamesForPatch(ctx, newRule)...) for _, sliceName := range slicesToSync.UnsortedList() { t.syncSlice(ctx, sliceName, false) } @@ -482,7 +490,7 @@ func (t *Tracker) deviceTaintDelete(ctx context.Context) func(obj any) { if !ok { return } - logger.V(5).Info("DeviceTaintRule delete", "patch", klog.KObj(patch)) + logger.V(5).Info("DeviceTaintRule deleted", "patch", klog.KObj(patch)) for _, sliceName := range t.sliceNamesForPatch(ctx, patch) { t.syncSlice(ctx, sliceName, false) }