Add unit tests for progress tracking and remove fullpath from reporting

pkg/volume/volume_linux.go

@@ -23,6 +23,7 @@ import (
 	"context"
 	"fmt"
 	"path/filepath"
+	"strings"
 	"syscall"
 
 	"os"
@@ -39,8 +40,14 @@ const (
 	rwMask   = os.FileMode(0660)
 	roMask   = os.FileMode(0440)
 	execMask = os.FileMode(0110)
+)
 
-	progressReportDuration = 60 * time.Second
+var (
+	// function that will be used for changing file permissions on linux
+	// mainly stored here as a variable so as it can replaced in tests
+	filePermissionChangeFunc = changeFilePermission
+	progressReportDuration   = 60 * time.Second
+	firstEventReportDuration = 30 * time.Second
 )
 
 // NewVolumeOwnership returns an interface that can be used to recursively change volume permissions and ownership
@@ -75,7 +82,7 @@ func (vo *VolumeOwnership) ChangePermissions() error {
 	ctx, cancel := context.WithCancel(context.Background())
 	defer cancel()
 
-	timer := time.AfterFunc(30*time.Second, func() {
+	timer := time.AfterFunc(firstEventReportDuration, func() {
 		vo.initiateProgressMonitor(ctx)
 	})
 	defer timer.Stop()
@@ -96,7 +103,7 @@ func (vo *VolumeOwnership) changePermissionsRecursively() error {
 			return err
 		}
 		vo.fileCounter.Add(1)
-		return changeFilePermission(path, vo.fsGroup, vo.mounter.GetAttributes().ReadOnly, info)
+		return filePermissionChangeFunc(path, vo.fsGroup, vo.mounter.GetAttributes().ReadOnly, info)
 	})
 
 	if vo.completionCallback != nil {
@@ -108,7 +115,8 @@ func (vo *VolumeOwnership) changePermissionsRecursively() error {
 }
 
 func (vo *VolumeOwnership) monitorProgress(ctx context.Context) {
-	msg := fmt.Sprintf("Setting volume ownership for %s is taking longer than expected, consider using OnRootMismatch - https://kubernetes.io/docs/tasks/configure-pod-container/security-context/#configure-volume-permission-and-ownership-change-policy-for-pods", vo.dir)
+	dirName := getDirnameToReport(vo.dir, string(vo.pod.UID))
+	msg := fmt.Sprintf("Setting volume ownership for %s is taking longer than expected, consider using OnRootMismatch - https://kubernetes.io/docs/tasks/configure-pod-container/security-context/#configure-volume-permission-and-ownership-change-policy-for-pods", dirName)
 	vo.recorder.Event(vo.pod, v1.EventTypeWarning, events.VolumePermissionChangeInProgress, msg)
 	ticker := time.NewTicker(progressReportDuration)
 	defer ticker.Stop()
@@ -122,8 +130,18 @@ func (vo *VolumeOwnership) monitorProgress(ctx context.Context) {
 	}
 }
 
+// report everything after podUID in dir string, including podUID
+func getDirnameToReport(dir, podUID string) string {
+	podUIDIndex := strings.Index(dir, podUID)
+	if podUIDIndex == -1 {
+		return dir
+	}
+	return dir[podUIDIndex:]
+}
+
 func (vo *VolumeOwnership) logWarning() {
-	msg := fmt.Sprintf("Setting volume ownership for %s, processed %d files.", vo.dir, vo.fileCounter.Load())
+	dirName := getDirnameToReport(vo.dir, string(vo.pod.UID))
+	msg := fmt.Sprintf("Setting volume ownership for %s, processed %d files.", dirName, vo.fileCounter.Load())
 	klog.Warning(msg)
 	vo.recorder.Event(vo.pod, v1.EventTypeWarning, events.VolumePermissionChangeInProgress, msg)
 }

pkg/volume/volume_linux_test.go

@@ -25,8 +25,11 @@ import (
 	"path/filepath"
 	"syscall"
 	"testing"
+	"time"
 
 	v1 "k8s.io/api/core/v1"
+	metav1 "k8s.io/apimachinery/pkg/apis/meta/v1"
+	"k8s.io/client-go/tools/record"
 	utiltesting "k8s.io/client-go/util/testing"
 )
 
@@ -286,6 +289,7 @@ func TestSetVolumeOwnershipMode(t *testing.T) {
 			}
 
 			defer os.RemoveAll(tmpDir)
+
 			info, err := os.Lstat(tmpDir)
 			if err != nil {
 				t.Fatalf("error reading permission of tmpdir: %v", err)
@@ -296,7 +300,7 @@ func TestSetVolumeOwnershipMode(t *testing.T) {
 				t.Fatalf("error reading permission stats for tmpdir: %s", tmpDir)
 			}
 
-			var expectedGid int64 = int64(stat.Gid)
+			var expectedGid = int64(stat.Gid)
 			err = test.setupFunc(tmpDir)
 			if err != nil {
 				t.Errorf("for %s error running setup with: %v", test.description, err)
@@ -316,6 +320,130 @@ func TestSetVolumeOwnershipMode(t *testing.T) {
 	}
 }
 
+func TestProgressTracking(t *testing.T) {
+	alwaysApplyPolicy := v1.FSGroupChangeAlways
+	var expectedGID int64 = 9999
+	var permissionSleepDuration = 5 * time.Millisecond
+	// how often to report the events
+	progressReportDuration = 200 * time.Millisecond
+	firstEventReportDuration = 50 * time.Millisecond
+
+	filePermissionChangeFunc = func(filename string, fsGroup *int64, _ bool, _ os.FileInfo) error {
+		t.Logf("Calling file permission change for %s with gid %d", filename, *fsGroup)
+		time.Sleep(permissionSleepDuration)
+		return nil
+	}
+	pod := &v1.Pod{
+		ObjectMeta: metav1.ObjectMeta{
+			Name: "pod1",
+			UID:  "pod1uid",
+		},
+		Spec: v1.PodSpec{
+			Volumes: []v1.Volume{
+				{
+					Name: "volume-name",
+					VolumeSource: v1.VolumeSource{
+						GCEPersistentDisk: &v1.GCEPersistentDiskVolumeSource{
+							PDName: "fake-device1",
+						},
+					},
+				},
+			},
+		},
+	}
+
+	tests := []struct {
+		name                             string
+		filePermissionChangeTimeDuration time.Duration
+		totalWaitTime                    time.Duration
+		currentPod                       *v1.Pod
+		expectedEvents                   []string
+	}{
+		{
+			name:                             "When permission change finishes quickly, no events should be logged",
+			filePermissionChangeTimeDuration: 30 * time.Millisecond,
+			totalWaitTime:                    1 * time.Second,
+			currentPod:                       pod,
+			expectedEvents:                   []string{},
+		},
+		{
+			name:                             "When no pod is specified, no events should be logged",
+			filePermissionChangeTimeDuration: 300 * time.Millisecond,
+			totalWaitTime:                    1 * time.Second,
+			currentPod:                       nil,
+			expectedEvents:                   []string{},
+		},
+		{
+			name:                             "When permission change takes loo long and pod is specified",
+			filePermissionChangeTimeDuration: 300 * time.Millisecond,
+			totalWaitTime:                    1 * time.Second,
+			currentPod:                       pod,
+			expectedEvents: []string{
+				"Warning VolumePermissionChangeInProgress Setting volume ownership for pod1uid/volumes/faketype is taking longer than expected, consider using OnRootMismatch - https://kubernetes.io/docs/tasks/configure-pod-container/security-context/#configure-volume-permission-and-ownership-change-policy-for-pods",
+				"Warning VolumePermissionChangeInProgress Setting volume ownership for pod1uid/volumes/faketype, processed 1 files.",
+			},
+		},
+	}
+
+	for i := range tests {
+		tc := tests[i]
+		t.Run(tc.name, func(t *testing.T) {
+			tmpDir, err := utiltesting.MkTmpdir("volume_linux_ownership")
+			if err != nil {
+				t.Fatalf("error creating temp dir: %v", err)
+			}
+			podUID := "placeholder"
+			if tc.currentPod != nil {
+				podUID = string(tc.currentPod.UID)
+			}
+			volumePath := filepath.Join(tmpDir, podUID, "volumes", "faketype")
+			err = os.MkdirAll(volumePath, 0770)
+			if err != nil {
+				t.Fatalf("error creating volumePath %s: %v", volumePath, err)
+			}
+			defer func() {
+				err := os.RemoveAll(tmpDir)
+				if err != nil {
+					t.Fatalf("error removing tmpDir %s: %v", tmpDir, err)
+				}
+			}()
+
+			mounter := &localFakeMounter{path: "FAKE_DIR_DOESNT_EXIST"} // SetVolumeOwnership() must rely on tmpDir
+
+			fakeRecorder := record.NewFakeRecorder(100)
+			recordedEvents := []string{}
+
+			// Set how long file permission change takes
+			permissionSleepDuration = tc.filePermissionChangeTimeDuration
+
+			ownershipChanger := NewVolumeOwnership(mounter, volumePath, &expectedGID, &alwaysApplyPolicy, nil)
+			if tc.currentPod != nil {
+				ownershipChanger.AddProgressNotifier(tc.currentPod, fakeRecorder)
+			}
+			err = ownershipChanger.ChangePermissions()
+			if err != nil {
+				t.Errorf("unexpected error: %+v", err)
+			}
+			time.Sleep(tc.totalWaitTime)
+			actualEventCount := len(fakeRecorder.Events)
+			if len(tc.expectedEvents) == 0 && actualEventCount != len(tc.expectedEvents) {
+				t.Errorf("expected 0 events got %d", actualEventCount)
+			}
+
+			for range actualEventCount {
+				event := <-fakeRecorder.Events
+				recordedEvents = append(recordedEvents, event)
+			}
+
+			for i, event := range tc.expectedEvents {
+				if event != recordedEvents[i] {
+					t.Errorf("expected event %d to be %s, got: %s", i, event, recordedEvents[i])
+				}
+			}
+		})
+	}
+}
+
 // verifyDirectoryPermission checks if given path has directory permissions
 // that is expected by k8s. If returns true if it does otherwise false
 func verifyDirectoryPermission(path string, readonly bool) bool {