PackageRevision stuck when created right after Repository Ready

[nagygergo]

Issue

When packagerevision is created right after porch is reporting the repository is ready, the PackageRevision is reporting a failure, and never recovers from it.

Steps to reproduce

~ stress -p 1 -count 30 -timeout 30m ./experiments/e2e/standalone/cache_gap.test -test.run=TestCacheGap -test.v
5s: 3 runs so far, 0 failures, 1 active
10s: 6 runs so far, 0 failures, 1 active
15s: 6 runs so far, 0 failures, 1 active
    cache_gap_test.go:190: Ready condition: status=False reason=Failed message=create draft: repository cache-gap-237488:exp-race-test:: not found
    cache_gap_test.go:199: === BUG REPRODUCED ===
    cache_gap_test.go:211: BUG CONFIRMED: Package still Failed. No retry. Error was swallowed.
--- FAIL: TestCacheGap (10.54s)
FAIL
20s: 8 runs so far, 1 failures (12.50%), 1 active
25s: 8 runs so far, 1 failures (12.50%), 1 active
30s: 8 runs so far, 1 failures (12.50%), 1 active
    cache_gap_test.go:190: Ready condition: status=False reason=Failed message=create draft: repository cache-gap-637773:exp-race-test:: not found
    cache_gap_test.go:199: === BUG REPRODUCED ===
    cache_gap_test.go:211: BUG CONFIRMED: Package still Failed. No retry. Error was swallowed.
--- FAIL: TestCacheGap (10.54s)
FAIL
35s: 9 runs so far, 2 failures (22.22%), 1 active
40s: 9 runs so far, 2 failures (22.22%), 1 active
    cache_gap_test.go:190: Ready condition: status=False reason=Failed message=create draft: repository cache-gap-311242:exp-race-test:: not found
    cache_gap_test.go:199: === BUG REPRODUCED ===
    cache_gap_test.go:211: BUG CONFIRMED: Package still Failed. No retry. Error was swallowed.
--- FAIL: TestCacheGap (10.56s)
FAIL
45s: 12 runs so far, 3 failures (25.00%), 1 active
50s: 14 runs so far, 3 failures (21.43%), 1 active
55s: 14 runs so far, 3 failures (21.43%), 1 active
    cache_gap_test.go:190: Ready condition: status=False reason=Failed message=create draft: repository cache-gap-831101:exp-race-test:: not found
    cache_gap_test.go:199: === BUG REPRODUCED ===
    cache_gap_test.go:211: BUG CONFIRMED: Package still Failed. No retry. Error was swallowed.
--- FAIL: TestCacheGap (10.77s)
FAIL
1m0s: 16 runs so far, 4 failures (25.00%), 1 active
1m5s: 18 runs so far, 4 failures (22.22%), 1 active
1m10s: 18 runs so far, 4 failures (22.22%), 1 active
    cache_gap_test.go:190: Ready condition: status=False reason=Failed message=create draft: repository cache-gap-248849:exp-race-test:: not found
    cache_gap_test.go:199: === BUG REPRODUCED ===
    cache_gap_test.go:211: BUG CONFIRMED: Package still Failed. No retry. Error was swallowed.
--- FAIL: TestCacheGap (10.81s)
FAIL
1m15s: 20 runs so far, 5 failures (25.00%), 1 active
1m20s: 22 runs so far, 5 failures (22.73%), 1 active
1m25s: 22 runs so far, 5 failures (22.73%), 1 active
    cache_gap_test.go:190: Ready condition: status=False reason=Failed message=create draft: repository cache-gap-773963:exp-race-test:: not found
    cache_gap_test.go:199: === BUG REPRODUCED ===
    cache_gap_test.go:211: BUG CONFIRMED: Package still Failed. No retry. Error was swallowed.
--- FAIL: TestCacheGap (10.77s)
FAIL
1m30s: 24 runs so far, 6 failures (25.00%), 1 active
1m35s: 26 runs so far, 6 failures (23.08%), 1 active
1m40s: 26 runs so far, 6 failures (23.08%), 1 active
    cache_gap_test.go:190: Ready condition: status=False reason=Failed message=create draft: repository cache-gap-315957:exp-race-test:: not found
    cache_gap_test.go:199: === BUG REPRODUCED ===
    cache_gap_test.go:211: BUG CONFIRMED: Package still Failed. No retry. Error was swallowed.
--- FAIL: TestCacheGap (10.53s)
FAIL
1m45s: 29 runs so far, 7 failures (24.14%), 1 active
1m46s: 30 runs total, 7 failures (23.33%)

Testcase to reproduce

// TestCacheGap reproduces the bug where a PackageRevision created immediately
// after a Repository becomes Ready gets permanently stuck in Failed state
// because the PR controller's ContentCache hasn't opened the repository yet.
//
// Steps:
//  1. Create a fresh namespace
//  2. Register a repository and wait for Ready=True
//  3. Immediately create a PackageRevision
//  4. Observe: the package permanently fails with "repository not found"
//     and never retries
//
// Expected behavior: The package should eventually succeed (retry until cache ready).
// Actual behavior: The package is stuck in Failed forever.
func TestCacheGap(t *testing.T) {
	ctx := context.Background()
	scheme := runtime.NewScheme()
	porchv1alpha2.AddToScheme(scheme)
	configapi.AddToScheme(scheme)
	corev1.AddToScheme(scheme)

	cfg, err := config.GetConfig()
	if err != nil {
		t.Fatalf("no kubeconfig: %v", err)
	}
	c, err := client.New(cfg, client.Options{Scheme: scheme})
	if err != nil {
		t.Fatalf("client: %v", err)
	}

	// Unique namespace per run
	ns := fmt.Sprintf("cache-gap-%d", time.Now().UnixNano()%1_000_000)
	repoName := "exp-race-test"
	giteaLBIP := discoverGiteaIP(t, c)

	// Ensure gitea repo exists
	ensureGiteaRepo(giteaLBIP, repoName)

	// Cleanup
	t.Cleanup(func() {
		var prList porchv1alpha2.PackageRevisionList
		if err := c.List(ctx, &prList, client.InNamespace(ns)); err == nil {
			for i := range prList.Items {
				prList.Items[i].Finalizers = nil
				c.Update(ctx, &prList.Items[i])
			}
		}
		var repoList configapi.RepositoryList
		if err := c.List(ctx, &repoList, client.InNamespace(ns)); err == nil {
			for i := range repoList.Items {
				repoList.Items[i].Finalizers = nil
				c.Update(ctx, &repoList.Items[i])
			}
		}
		c.Delete(ctx, &corev1.Namespace{ObjectMeta: metav1.ObjectMeta{Name: ns}})
	})

	// Step 1: Create namespace
	t.Logf("Creating namespace %s", ns)
	if err := c.Create(ctx, &corev1.Namespace{ObjectMeta: metav1.ObjectMeta{Name: ns}}); err != nil {
		t.Fatalf("create ns: %v", err)
	}

	// Step 2: Register repo and wait for Ready
	t.Log("Creating secret + repository")
	c.Create(ctx, &corev1.Secret{
		ObjectMeta: metav1.ObjectMeta{Name: repoName + "-auth", Namespace: ns},
		Immutable:  ptr.To(true),
		Data:       map[string][]byte{"username": []byte("porch"), "password": []byte("secret")},
		Type:       corev1.SecretTypeBasicAuth,
	})
	if err := c.Create(ctx, &configapi.Repository{
		ObjectMeta: metav1.ObjectMeta{
			Name: repoName, Namespace: ns,
			Annotations: map[string]string{"porch.kpt.dev/v1alpha2-migration": "true"},
		},
		Spec: configapi.RepositorySpec{
			Type: configapi.RepositoryTypeGit,
			Git: &configapi.GitRepository{
				Repo:      fmt.Sprintf("http://gitea.gitea.svc.cluster.local:3000/porch/%s.git", repoName),
				Branch:    "main",
				SecretRef: configapi.SecretRef{Name: repoName + "-auth"},
			},
		},
	}); err != nil {
		t.Fatalf("create repo: %v", err)
	}

	if !pollUntil(t, 2*time.Minute, 200*time.Millisecond, func() bool {
		repo := &configapi.Repository{}
		if err := c.Get(ctx, client.ObjectKey{Namespace: ns, Name: repoName}, repo); err != nil {
			return false
		}
		for _, cond := range repo.Status.Conditions {
			if cond.Type == configapi.RepositoryReady && cond.Status == metav1.ConditionTrue {
				return true
			}
		}
		return false
	}) {
		t.Fatal("repo never became Ready")
	}
	t.Log("Repo is Ready")

	// Step 3: Immediately create package (no delay!)
	pkgName := fmt.Sprintf("gap-%d", time.Now().UnixNano()%100000)
	prName := fmt.Sprintf("%s.%s.v1", repoName, pkgName)
	t.Logf("Creating package %s immediately after repo Ready", prName)

	if err := c.Create(ctx, &porchv1alpha2.PackageRevision{
		ObjectMeta: metav1.ObjectMeta{Name: prName, Namespace: ns},
		Spec: porchv1alpha2.PackageRevisionSpec{
			PackageName: pkgName, RepositoryName: repoName,
			WorkspaceName: "v1", Lifecycle: porchv1alpha2.PackageRevisionLifecycleDraft,
			Source: &porchv1alpha2.PackageSource{
				Init: &porchv1alpha2.PackageInitSpec{Description: "cache gap reproducer"},
			},
		},
	}); err != nil {
		t.Fatalf("create PR: %v", err)
	}

	// Step 4: Poll until terminal state (Ready=True or Failed)
	var pr porchv1alpha2.PackageRevision
	terminal := pollUntil(t, 2*time.Minute, 200*time.Millisecond, func() bool {
		if err := c.Get(ctx, client.ObjectKey{Namespace: ns, Name: prName}, &pr); err != nil {
			return false
		}
		for _, cond := range pr.Status.Conditions {
			if cond.Type == porchv1alpha2.ConditionReady {
				if cond.Status == metav1.ConditionTrue {
					return true
				}
				if cond.Status == metav1.ConditionFalse && cond.Reason == porchv1alpha2.ReasonFailed {
					return true
				}
			}
		}
		return false
	})
	if !terminal {
		t.Fatal("Timed out waiting for terminal Ready condition")
	}

	// Step 5: Evaluate result
	for _, cond := range pr.Status.Conditions {
		if cond.Type != porchv1alpha2.ConditionReady {
			continue
		}
		t.Logf("Ready condition: status=%s reason=%s message=%s", cond.Status, cond.Reason, cond.Message)

		if cond.Status == metav1.ConditionTrue {
			t.Log("Package became Ready — cache was warm in time. Bug did not trigger this run.")
			return
		}

		if cond.Reason == porchv1alpha2.ReasonFailed && strings.Contains(cond.Message, "not found") {
			t.Log("")
			t.Log("=== BUG REPRODUCED ===")
			t.Log("Package is permanently stuck in Failed state.")
			t.Log("The PR controller's ContentCache hasn't opened the repository")
			t.Log("despite the Repository reporting Ready=True.")
			t.Log("The error is never retried — the package will never recover.")
			t.Log("")

			// Confirm no retry after 10s
			time.Sleep(10 * time.Second)
			c.Get(ctx, client.ObjectKey{Namespace: ns, Name: prName}, &pr)
			for _, c2 := range pr.Status.Conditions {
				if c2.Type == porchv1alpha2.ConditionReady && c2.Status == metav1.ConditionFalse {
					t.Fatal("BUG CONFIRMED: Package still Failed. No retry. Error was swallowed.")
				}
			}
		}
	}
}

// pollUntil polls condition at interval until it returns true or timeout expires.
func pollUntil(t *testing.T, timeout, interval time.Duration, condition func() bool) bool {
	t.Helper()
	deadline := time.Now().Add(timeout)
	for time.Now().Before(deadline) {
		if condition() {
			return true
		}
		time.Sleep(interval)
	}
	return false
}

func discoverGiteaIP(t *testing.T, c client.Client) string {
	t.Helper()
	if ip := os.Getenv("GITEA_LB_IP"); ip != "" {
		return ip
	}
	svc := &corev1.Service{}
	if err := c.Get(context.Background(), client.ObjectKey{Namespace: "gitea", Name: "gitea-lb"}, svc); err == nil {
		if len(svc.Status.LoadBalancer.Ingress) > 0 {
			if ip := svc.Status.LoadBalancer.Ingress[0].IP; ip != "" {
				return ip
			}
		}
	}
	return "172.18.255.200"
}

func ensureGiteaRepo(giteaLBIP, name string) {
	url := fmt.Sprintf("http://%s:3000/api/v1/user/repos", giteaLBIP)
	req, _ := http.NewRequest("POST", url, strings.NewReader(fmt.Sprintf(`{"name":"%s","auto_init":true}`, name)))
	req.SetBasicAuth("porch", "secret")
	req.Header.Set("Content-Type", "application/json")
	http.DefaultClient.Do(req)
}