Repository: envoyproxy/gateway

Issue:
FAIL: TestPermissionCache
--- FAIL: TestPermissionCache (0.13s)
    --- FAIL: TestPermissionCache/Cached_permission_should_be_removed_after_expiry (0.01s)


https://github.com/envoyproxy/gateway/actions/runs/15037684372/job/42262351384


cc @zhaohuabing 

Hints from issue comments:

Solution patch:
diff --git a/internal/wasm/premissioncache.go b/internal/wasm/premissioncache.go
index 053b3880c..e680574ad 100644
--- a/internal/wasm/premissioncache.go
+++ b/internal/wasm/premissioncache.go
@@ -71,9 +71,6 @@ type permissionCache struct {
 
 	cache  map[string]*permissionCacheEntry
 	logger logging.Logger
-
-	// For tests
-	triggerChan chan struct{}
 }
 
 // permissionCacheEntry is an entry in the permission cache.
@@ -128,7 +125,6 @@ func newPermissionCache(options permissionCacheOptions, logger logging.Logger) *
 		cache:                  make(map[string]*permissionCacheEntry),
 		permissionCacheOptions: options,
 		logger:                 logger,
-		triggerChan:            make(chan struct{}),
 	}
 }
 
@@ -148,11 +144,48 @@ func (p *permissionCache) Start(ctx context.Context) {
 		defer ticker.Stop()
 		for {
 			select {
-			// explicitly trigger a check for tests
-			case <-p.triggerChan:
-				p.checkPermissions(ctx)
 			case <-ticker.C:
-				p.checkPermissions(ctx)
+				func() {
+					p.Lock()
+					defer p.Unlock()
+					for _, e := range p.cache {
+						if e.isCacheExpired(p.cacheExpiry) {
+							p.logger.Info("removing permission cache entry", "image", e.image.String())
+							delete(p.cache, e.key())
+							continue
+						}
+						if e.isPermissionExpired(p.permissionExpiry) {
+							const retryAttempts = 3
+							const retryDelay = 1 * time.Second
+							p.logger.Info("rechecking permission for image", "image", e.image.String())
+							err := retry.Do(
+								func() error {
+									err := p.checkAndUpdatePermission(ctx, e)
+									if err != nil && isRetriableError(err) {
+										p.logger.Error(
+											err,
+											"failed to check permission for image, will retry again",
+											"image",
+											e.image.String())
+										return err
+									}
+									return nil
+								},
+								retry.Attempts(retryAttempts),
+								retry.DelayType(retry.BackOffDelay),
+								retry.Delay(retryDelay),
+								retry.Context(ctx),
+							)
+							if err != nil {
+								p.logger.Error(
+									err,
+									fmt.Sprintf("failed to recheck permission for image after %d attempts", retryAttempts),
+									"image",
+									e.image.String())
+							}
+						}
+					}
+				}()
 			case <-ctx.Done():
 				return
 			}
@@ -160,48 +193,6 @@ func (p *permissionCache) Start(ctx context.Context) {
 	}()
 }
 
-func (p *permissionCache) checkPermissions(ctx context.Context) {
-	p.Lock()
-	defer p.Unlock()
-	for _, e := range p.cache {
-		if e.isCacheExpired(p.cacheExpiry) {
-			p.logger.Info("removing permission cache entry", "image", e.image.String())
-			delete(p.cache, e.key())
-			continue
-		}
-		if e.isPermissionExpired(p.permissionExpiry) {
-			const retryAttempts = 3
-			const retryDelay = 1 * time.Second
-			p.logger.Info("rechecking permission for image", "image", e.image.String())
-			err := retry.Do(
-				func() error {
-					err := p.checkAndUpdatePermission(ctx, e)
-					if err != nil && isRetriableError(err) {
-						p.logger.Error(
-							err,
-							"failed to check permission for image, will retry again",
-							"image",
-							e.image.String())
-						return err
-					}
-					return nil
-				},
-				retry.Attempts(retryAttempts),
-				retry.DelayType(retry.BackOffDelay),
-				retry.Delay(retryDelay),
-				retry.Context(ctx),
-			)
-			if err != nil {
-				p.logger.Error(
-					err,
-					fmt.Sprintf("failed to recheck permission for image after %d attempts", retryAttempts),
-					"image",
-					e.image.String())
-			}
-		}
-	}
-}
-
 // isRetriableError checks if the error is retriable.
 // If the error is a permission error, it's not retriable. For example, 401 and 403 HTTP status code.
 func isRetriableError(err error) bool {



Test patch:
diff --git a/internal/wasm/premissioncache_test.go b/internal/wasm/premissioncache_test.go
index 9cc7bb10c..a6231fe59 100644
--- a/internal/wasm/premissioncache_test.go
+++ b/internal/wasm/premissioncache_test.go
@@ -65,193 +65,270 @@ func TestPermissionCache(t *testing.T) {
 	latestImage, _ := url.Parse(ociURLWithLatestTag)
 	secret := []byte("")
 
-	t.Run("Cached permission should be updated", func(t *testing.T) {
-		lock.Lock()
-		failPermissionCheck = false
-		lock.Unlock()
-
-		ctx := context.Background()
-		defer ctx.Done()
-		cache, entry := setupTestPermissionCache(
-			permissionCacheOptions{
-				checkInterval:    1 * time.Nanosecond,
-				permissionExpiry: 10 * time.Nanosecond,
-			},
-			image,
-			latestImage,
-			secret)
-		cache.Start(ctx)
-
-		lastAccessTime := entry.lastAccess
-		lastCheckTime := entry.lastCheck
-
-		cache.triggerChan <- struct{}{}
-		time.Sleep(1 * time.Millisecond)
-		allowed, err := cache.IsAllowed(context.Background(), image, secret, true)
-		require.True(
-			t,
-			allowed,
-			"permission should be rechecked and allowed after permission expired")
-		require.NoError(
-			t,
-			err,
-			"permission should be rechecked and allowed after permission expired")
-
-		entry, ok := cache.getForTest(entry.key())
-		require.True(t, ok, "cache entry should exist")
-		require.True(t, entry.lastAccess.After(lastAccessTime), "last access time should be updated")
-		require.True(t, entry.lastCheck.After(lastCheckTime), "last check time should be updated")
+	t.Run("Cached permission should be updated after expiry", func(t *testing.T) {
+		require.Eventually(t, func() bool {
+			lock.Lock()
+			failPermissionCheck = false
+			lock.Unlock()
+
+			ctx := context.Background()
+			defer ctx.Done()
+			cache, entry := setupTestPermissionCache(
+				permissionCacheOptions{
+					checkInterval:    1 * time.Nanosecond,
+					permissionExpiry: 10 * time.Nanosecond,
+				},
+				image,
+				latestImage,
+				secret)
+			cache.Start(ctx)
+
+			lastAccessTime := entry.lastAccess
+			lastCheckTime := entry.lastCheck
+
+			// Wait for the cache to expire
+			time.Sleep(10 * time.Millisecond)
+			allowed, err := cache.IsAllowed(context.Background(), image, secret, true)
+			if err != nil {
+				t.Logf("permission rechecked should not return error: %v", err)
+				return false
+			}
+			if !allowed {
+				t.Log("ppermission should be rechecked and allowed after permission expired")
+				return false
+			}
+			entry, ok := cache.getForTest(entry.key())
+			if !ok {
+				t.Log("cache entry should exist")
+				return false
+			}
+			// Verify the cached image permission is rechecked
+			if !entry.lastAccess.After(lastAccessTime) {
+				t.Log("last access time should be updated")
+				return false
+			}
+			if !entry.lastCheck.After(lastCheckTime) {
+				t.Log("last check time should be updated")
+				return false
+			}
+			return true
+		}, time.Second*5, time.Millisecond*20)
 	})
 
 	t.Run("Cached permission failed after recheck", func(t *testing.T) {
-		lock.Lock()
-		failPermissionCheck = true
-		lock.Unlock()
-
-		ctx := context.Background()
-		defer ctx.Done()
-		cache, entry := setupTestPermissionCache(
-			permissionCacheOptions{
-				checkInterval:    1 * time.Nanosecond,
-				permissionExpiry: 10 * time.Nanosecond,
-			},
-			image,
-			latestImage,
-			secret)
-		cache.Start(ctx)
-
-		lastAccessTime := entry.lastAccess
-		lastCheckTime := entry.lastCheck
-
-		cache.triggerChan <- struct{}{}
-		time.Sleep(1 * time.Millisecond)
-		allowed, err := cache.IsAllowed(context.Background(), image, secret, true)
-		require.False(t, isRetriableError(err), "permission check error should not be retriable")
-		require.False(
-			t,
-			allowed,
-			"permission should be rechecked and denied after permission expired and secret is invalid")
-		require.Error(
-			t,
-			err,
-			"permission should be rechecked and denied after permission expired and secret is invalid")
-
-		entry, ok := cache.getForTest(entry.key())
-		require.True(t, ok, "cache entry should exist")
-		require.True(t, entry.lastAccess.After(lastAccessTime), "last access time should be updated")
-		require.True(t, entry.lastCheck.After(lastCheckTime), "last check time should be updated")
+		require.Eventually(t, func() bool {
+			lock.Lock()
+			failPermissionCheck = true
+			lock.Unlock()
+
+			ctx := context.Background()
+			defer ctx.Done()
+			cache, entry := setupTestPermissionCache(
+				permissionCacheOptions{
+					checkInterval:    1 * time.Nanosecond,
+					permissionExpiry: 10 * time.Nanosecond,
+				},
+				image,
+				latestImage,
+				secret)
+			cache.Start(ctx)
+
+			lastAccessTime := entry.lastAccess
+			lastCheckTime := entry.lastCheck
+
+			// Wait for the cache to expire
+			time.Sleep(10 * time.Millisecond)
+			allowed, err := cache.IsAllowed(context.Background(), image, secret, true)
+			if err == nil {
+				t.Log("permission rechecked should return error if failed permission check")
+				return false
+			}
+			if isRetriableError(err) {
+				t.Logf("permission check error should not be retriable: %v", err)
+				return false
+			}
+			if allowed {
+				t.Log("permission should be rechecked and denied after permission expired and secret is invalid")
+				return false
+			}
+			entry, ok := cache.getForTest(entry.key())
+			if !ok {
+				t.Log("cache entry should exist")
+				return false
+			}
+			if !entry.lastAccess.After(lastAccessTime) {
+				t.Log("last access time should be updated")
+				return false
+			}
+			if !entry.lastCheck.After(lastCheckTime) {
+				t.Log("last check time should be updated")
+				return false
+			}
+			return true
+		}, time.Second*5, time.Millisecond*20)
 	})
 
 	t.Run("Cached permission should be removed after expiry", func(t *testing.T) {
-		lock.Lock()
-		failPermissionCheck = false
-		lock.Unlock()
-
-		ctx := context.Background()
-		defer ctx.Done()
-		cache, entry := setupTestPermissionCache(
-			permissionCacheOptions{
-				checkInterval: 1 * time.Nanosecond,
-				cacheExpiry:   10 * time.Nanosecond,
-			},
-			image,
-			latestImage,
-			secret)
-		cache.Start(ctx)
-
-		lastAccessTime := entry.lastAccess
-		lastCheckTime := entry.lastCheck
-
-		cache.triggerChan <- struct{}{}
-		time.Sleep(1 * time.Millisecond)
-		key := entry.key()
-		entry, ok := cache.getForTest(key)
-		require.False(t, ok, "cache entry should be removed after expiry")
-		allowed, err := cache.IsAllowed(context.Background(), image, secret, true)
-		require.True(t,
-			allowed,
-			"permission should be rechecked and allowed after cache removed")
-		require.NoError(t,
-			err,
-			"permission should be rechecked and allowed after cache removed")
-		entry, ok = cache.getForTest(key)
-		require.True(t, ok, "expired entry should be added after recheck")
-		require.True(t, entry.lastAccess.After(lastAccessTime), "last access time should be updated")
-		require.True(t, entry.lastCheck.After(lastCheckTime), "last check time should be updated")
+		require.Eventually(t, func() bool {
+			lock.Lock()
+			failPermissionCheck = false
+			lock.Unlock()
+
+			ctx := context.Background()
+			defer ctx.Done()
+			cache, entry := setupTestPermissionCache(
+				permissionCacheOptions{
+					checkInterval: 1 * time.Nanosecond,
+					cacheExpiry:   10 * time.Nanosecond,
+				},
+				image,
+				latestImage,
+				secret)
+			cache.Start(ctx)
+
+			lastAccessTime := entry.lastAccess
+			lastCheckTime := entry.lastCheck
+
+			// Wait for the cache to expire
+			time.Sleep(10 * time.Millisecond)
+			key := entry.key()
+			entry, ok := cache.getForTest(key)
+			if ok {
+				t.Log("cache entry should be removed after expiry")
+				return false
+			}
+			allowed, err := cache.IsAllowed(context.Background(), image, secret, true)
+			if err != nil {
+				t.Logf("permission rechecked should not return error: %v", err)
+				return false
+			}
+			if !allowed {
+				t.Log("permission should be rechecked and allowed after cache removed")
+				return false
+			}
+			entry, ok = cache.getForTest(key)
+			if !ok {
+				t.Log("expired entry should be added after recheck")
+				return false
+			}
+			if !entry.lastAccess.After(lastAccessTime) {
+				t.Log("last access time should be updated")
+				return false
+			}
+			if !entry.lastCheck.After(lastCheckTime) {
+				t.Log("last check time should be updated")
+				return false
+			}
+			return true
+		}, time.Second*5, time.Millisecond*20)
 	})
 
 	t.Run("Non-exist permission should be checked and cached after first access for allowed permission", func(t *testing.T) {
-		lock.Lock()
-		failPermissionCheck = false
-		lock.Unlock()
-
-		ctx := context.Background()
-		defer ctx.Done()
-		cache, entry := setupTestPermissionCache(
-			permissionCacheOptions{
-				checkInterval: 1 * time.Nanosecond,
-			},
-			image,
-			latestImage,
-			secret)
-		key := entry.key()
-		// remove the cache entry
-		cache.deleteForTest(key)
-		cache.Start(ctx)
-
-		_, ok := cache.getForTest(key)
-		require.False(t, ok, "cache entry should not exist before access")
-
-		now := time.Now()
-		allowed, err := cache.IsAllowed(context.Background(), image, secret, true)
-		require.True(t,
-			allowed,
-			"non-exist permission should be checked and allowed at first access")
-		require.NoError(t,
-			err,
-			"non-exist permission should be checked and allowed at first access")
-
-		entry, ok = cache.getForTest(key)
-		require.True(t, ok, "non-exist permission should be added to the cache after first access ")
-		require.True(t, entry.lastAccess.After(now), "last access time should be updated after first access")
-		require.True(t, entry.lastCheck.After(now), "last check time should be updated after first access")
+		require.Eventually(t, func() bool {
+			lock.Lock()
+			failPermissionCheck = false
+			lock.Unlock()
+
+			ctx := context.Background()
+			defer ctx.Done()
+			cache, entry := setupTestPermissionCache(
+				permissionCacheOptions{
+					checkInterval: 1 * time.Nanosecond,
+				},
+				image,
+				latestImage,
+				secret)
+			key := entry.key()
+			// remove the cache entry
+			cache.deleteForTest(key)
+			cache.Start(ctx)
+
+			_, ok := cache.getForTest(key)
+			if ok {
+				t.Log("cache entry should not exist before access")
+				return false
+			}
+
+			now := time.Now()
+			allowed, err := cache.IsAllowed(context.Background(), image, secret, true)
+			if err != nil {
+				t.Logf("permission check should not return error: %v", err)
+				return false
+			}
+			if !allowed {
+				t.Log("non-exist permission should be checked and allowed at first access")
+				return false
+			}
+
+			entry, ok = cache.getForTest(key)
+			if !ok {
+				t.Log("non-exist permission should be added to the cache after first access")
+				return false
+			}
+			if !entry.lastAccess.After(now) {
+				t.Log("last access time should be updated after first access")
+				return false
+			}
+			if !entry.lastCheck.After(now) {
+				t.Log("last check time should be updated after first access")
+				return false
+			}
+			return true
+		}, time.Second*5, time.Millisecond*20)
 	})
 
 	t.Run("Non-exist permission should be checked and cached after first access for denied permission", func(t *testing.T) {
-		lock.Lock()
-		failPermissionCheck = true
-		lock.Unlock()
-
-		ctx := context.Background()
-		defer ctx.Done()
-		cache, entry := setupTestPermissionCache(
-			permissionCacheOptions{
-				checkInterval: 1 * time.Nanosecond,
-			},
-			image,
-			latestImage,
-			secret)
-		key := entry.key()
-		// remove the cache entry
-		cache.deleteForTest(key)
-		cache.Start(ctx)
-
-		_, ok := cache.getForTest(key)
-		require.False(t, ok, "cache entry should not exist before access")
-
-		now := time.Now()
-		allowed, err := cache.IsAllowed(context.Background(), image, secret, true)
-		require.False(t,
-			allowed,
-			"non-exist permission should be checked and denied at first access if secret is invalid")
-		require.Error(t,
-			err,
-			"non-exist permission should be checked and denied at first access if secret is invalid")
-
-		entry, ok = cache.getForTest(key)
-		require.True(t, ok, "non-exist permission should be added to the cache after first access ")
-		require.True(t, entry.lastAccess.After(now), "last access time should be updated after first access")
-		require.True(t, entry.lastCheck.After(now), "last check time should be updated after first access")
+		require.Eventually(t, func() bool {
+			lock.Lock()
+			failPermissionCheck = true
+			lock.Unlock()
+
+			ctx := context.Background()
+			defer ctx.Done()
+			cache, entry := setupTestPermissionCache(
+				permissionCacheOptions{
+					checkInterval: 1 * time.Nanosecond,
+				},
+				image,
+				latestImage,
+				secret)
+			key := entry.key()
+			// remove the cache entry
+			cache.deleteForTest(key)
+			cache.Start(ctx)
+
+			_, ok := cache.getForTest(key)
+			if ok {
+				t.Log("cache entry should not exist before access")
+				return false
+			}
+
+			now := time.Now()
+			allowed, err := cache.IsAllowed(context.Background(), image, secret, true)
+			if err == nil {
+				t.Logf("non-exist permission should be checked and denied at first access if secret is invalid")
+				return false
+			}
+			if allowed {
+				t.Log("non-exist permission should be checked and denied at first access if secret is invalid")
+				return false
+			}
+
+			entry, ok = cache.getForTest(key)
+			if !ok {
+				t.Log("non-exist permission should be added to the cache after first access")
+				return false
+			}
+			if !entry.lastAccess.After(now) {
+				t.Log("last access time should be updated after first access")
+				return false
+			}
+			if !entry.lastCheck.After(now) {
+				t.Log("last check time should be updated after first access")
+				return false
+			}
+			return true
+		}, time.Second*5, time.Millisecond*20)
 	})
 }